diff --git a/experiments/run_experiment.py b/experiments/run_experiment.py index f3bab66..69b9ef4 100644 --- a/experiments/run_experiment.py +++ b/experiments/run_experiment.py @@ -231,9 +231,13 @@ def _main(cfg: DictConfig) -> float: ) # Evaluate on held-out episodes. + logger.info( + "Training complete; starting %d held-out evaluation episodes", num_eval + ) render = cfg.render_videos per_episode: list[dict[str, Any]] = [] for i, s in enumerate(eval_seeds): + logger.info("Evaluating episode %d/%d", i + 1, num_eval) count = eval_counts[i] if eval_counts is not None else None episode_max_steps = ( env.max_steps_for_count(count) @@ -272,6 +276,13 @@ def _main(cfg: DictConfig) -> float: ) continue per_episode.append(episode_result) + logger.info( + "Episode %d/%d: solved=%s, steps=%s", + i + 1, + num_eval, + episode_result["solved"], + episode_result["num_steps"], + ) if frames: video_dir = output_dir / "videos" video_dir.mkdir(exist_ok=True) diff --git a/src/robocode/approaches/genplan_driver.py b/src/robocode/approaches/genplan_driver.py index 70329a4..f711b2e 100644 --- a/src/robocode/approaches/genplan_driver.py +++ b/src/robocode/approaches/genplan_driver.py @@ -10,6 +10,7 @@ from __future__ import annotations import json +import logging from pathlib import Path from typing import Any @@ -25,6 +26,14 @@ def main() -> None: """Reconstruct the approach from the sandbox config and run its train loop.""" + logging.basicConfig( + level=logging.INFO, + format="%(asctime)s %(levelname)s %(name)s: %(message)s", + handlers=[ + logging.StreamHandler(), + logging.FileHandler(_SANDBOX / "genplan.log", encoding="utf-8"), + ], + ) cfg = json.loads((_SANDBOX / "genplan_config.json").read_text(encoding="utf-8")) env_cfg = OmegaConf.create(cfg["environment"]) env = hydra.utils.instantiate(env_cfg) @@ -58,7 +67,21 @@ def main() -> None: approach = LLMGenPlanApproach( *args, max_debug_attempts=cfg["max_debug_attempts"], **common ) - approach.train() + logging.getLogger(__name__).info( + "Starting %s replicate %s; budget=$%s; training tasks=%s", + cfg.get("approach", "genplan"), + cfg["seed"], + cfg["max_budget_usd"], + cfg["num_train_tasks"], + ) + try: + approach.train() + except Exception: + logging.getLogger(__name__).exception("GenPlan training failed") + raise + logging.getLogger(__name__).info( + "Training finished; returning policy for evaluation" + ) # The host approach reads these back; the container is the only place the # accumulated API cost and generation count exist. (_SANDBOX / "cost.json").write_text( diff --git a/src/robocode/approaches/llm_genplan_approach.py b/src/robocode/approaches/llm_genplan_approach.py index 40192ac..cdabb3b 100644 --- a/src/robocode/approaches/llm_genplan_approach.py +++ b/src/robocode/approaches/llm_genplan_approach.py @@ -14,6 +14,7 @@ import json import logging import re +import time from collections.abc import Callable from pathlib import Path from typing import Any, TypeVar, cast @@ -162,8 +163,7 @@ def _build_initial_messages( "role": "user", "content": ( f"{context}\n\nThere is a simple strategy for solving " - "all instances of this environment without using " - f"search. {interface_spec}" + f"all instances of this environment. {interface_spec}" ), } ) @@ -283,7 +283,12 @@ def _debug_loop( if t == 0: self._assert_loop_bounded() + logger.info("Validating impl%d on %d training tasks", t, len(seeds)) + started = time.monotonic() failure = self._validate(approach_path, seeds) + logger.info( + "Validation impl%d finished in %.1fs", t, time.monotonic() - started + ) if failure is None: logger.info( "All %d training tasks solved at attempt %d", @@ -293,8 +298,19 @@ def _debug_loop( self.num_generations = t + 1 return logger.info("Attempt %d failed (%s)", t, failure["error_type"]) + (sandbox_dir / f"impl{t}_feedback.json").write_text( + json.dumps(failure, indent=2), encoding="utf-8" + ) + logger.info("Feedback: %s", failure["feedback"].splitlines()[0]) t += 1 if not self._within_budget(t): + logger.info( + "Refinement stopped at budget/attempt limit: %d generations; " + "reported cost=%s, budget=%s", + t, + self.total_cost_usd, + self._max_budget_usd, + ) break messages.append( {"role": "user", "content": f"{failure['feedback']}\nFix the code."} @@ -334,11 +350,34 @@ def _exchange( def _complete(self, messages: list[dict[str, str]], sandbox: Path, tag: str) -> str: assert self._client is not None - result: LLMResponse = self._client.complete(messages) + (sandbox / f"{tag}_prompt.txt").write_text( + messages[-1]["content"], encoding="utf-8" + ) + logger.info( + "Requesting %s; reported cost=%s, budget=%s", + tag, + self.total_cost_usd, + self._max_budget_usd, + ) + started = time.monotonic() + try: + result: LLMResponse = self._client.complete(messages) + except Exception as exc: + (sandbox / f"{tag}_error.txt").write_text(str(exc), encoding="utf-8") + logger.exception( + "Request %s failed after %.1fs", tag, time.monotonic() - started + ) + raise if result.cost_usd is not None: self.total_cost_usd = (self.total_cost_usd or 0.0) + result.cost_usd - (sandbox / f"{tag}_prompt.txt").write_text(messages[-1]["content"]) (sandbox / f"{tag}_response.txt").write_text(result.text) + logger.info( + "Received %s in %.1fs; call cost=%s, total cost=%s", + tag, + time.monotonic() - started, + result.cost_usd, + self.total_cost_usd, + ) return result.text # -------------------------------------------------------------- validation @@ -392,10 +431,11 @@ def _gather_env_source(env: gymnasium.Env) -> str: """Best-effort bundle of the env's local source (robocode + kinder).""" files: list[Path] = [] for obj, package in _source_targets(env): - source_file = inspect.getsourcefile(type(obj)) + cls = obj if inspect.isclass(obj) else type(obj) + source_file = inspect.getsourcefile(cls) assert source_file is not None src = Path(source_file) - root = src.parents[len(type(obj).__module__.split(".")) - 1] + root = src.parents[len(cls.__module__.split(".")) - 1] files.extend(collect_local_deps(src, root, package)) seen: set[Path] = set() blocks: list[str] = [] @@ -413,6 +453,13 @@ def _source_targets(env: gymnasium.Env) -> list[tuple[Any, str]]: underlying = getattr(env, "_kinder_env", None) if underlying is not None: targets.append((underlying, type(underlying).__module__.split(".")[0])) + # VariableObjectCountEnv loads its backend dynamically, so following the + # wrapper's imports cannot discover the actual environment implementation. + # Inspect the loaded class without constructing or resetting a backend (and + # without exposing held-out counts or evaluation states). + env_cls = getattr(env, "_env_cls", None) + if env_cls is not None: + targets.append((env_cls, env_cls.__module__.split(".")[0])) return targets diff --git a/src/robocode/prompts.py b/src/robocode/prompts.py index f4760ea..004a847 100644 --- a/src/robocode/prompts.py +++ b/src/robocode/prompts.py @@ -760,8 +760,8 @@ def genplan_interface_spec(object_centric: bool = False) -> str: GENPLAN_SUMMARY_PROMPT = "Write a short summary of this environment in words." GENPLAN_STRATEGY_PROMPT = ( - "There is a simple strategy for solving all instances of this environment " - "without using search. What is that strategy?" + "There is a simple strategy for solving all instances of this environment. " + "What is that strategy?" ) diff --git a/src/robocode/utils/llm/cli_client.py b/src/robocode/utils/llm/cli_client.py index 58dc447..c968962 100644 --- a/src/robocode/utils/llm/cli_client.py +++ b/src/robocode/utils/llm/cli_client.py @@ -61,15 +61,22 @@ def complete(self, messages: list[dict[str, str]]) -> LLMResponse: ) ) # Prompt via stdin, not argv: it can exceed the OS per-arg limit (128KB). - result = subprocess.run( - args, - env=env, - input=prompt, - capture_output=True, - text=True, - check=True, - timeout=self._timeout_s, - ) + try: + result = subprocess.run( + args, + env=env, + input=prompt, + capture_output=True, + text=True, + check=True, + timeout=self._timeout_s, + ) + except subprocess.CalledProcessError as exc: + raise RuntimeError( + f"Claude exited with status {exc.returncode}.\n" + f"stdout: {exc.stdout or '(empty)'}\n" + f"stderr: {exc.stderr or '(empty)'}" + ) from exc data = json.loads(result.stdout) return LLMResponse(text=data["result"], cost_usd=data.get("total_cost_usd")) diff --git a/tests/approaches/test_llm_genplan_approach.py b/tests/approaches/test_llm_genplan_approach.py index 6135964..fc0cc9a 100644 --- a/tests/approaches/test_llm_genplan_approach.py +++ b/tests/approaches/test_llm_genplan_approach.py @@ -1,20 +1,25 @@ """Tests for llm_genplan_approach.py.""" +import inspect import json +from pathlib import Path import hydra import numpy as np import pytest from gymnasium import Env from gymnasium.spaces import Box +from kinder.envs.dynamic2d.base_env import ObjectCentricDynamic2DRobotEnv from omegaconf import DictConfig, OmegaConf from relational_structs import Type from relational_structs.spaces import ObjectCentricStateSpace from robocode.approaches.llm_genplan_approach import ( LLMGenPlanApproach, + _gather_env_source, _parse_python_code, ) +from robocode.environments.variable_object_count_env import VariableObjectCountEnv from robocode.utils.llm import LLMResponse, create_llm_client @@ -296,6 +301,36 @@ def test_debug_loop_fixes_broken_policy(tmp_path): assert terminated +def test_genplan_logs_progress_and_saves_feedback(tmp_path, caplog): + """Generation, validation, cost and failure feedback remain inspectable.""" + caplog.set_level("INFO") + approach = _make_approach(_ToyEnv(), _FakeClient([_BROKEN, _FIXED]), tmp_path) + approach.train() + assert "Requesting impl0" in caplog.text + assert "Received impl0" in caplog.text + assert "Validating impl0" in caplog.text + assert "All 2 training tasks solved" in caplog.text + assert "total cost=0.02" in caplog.text + feedback = json.loads((tmp_path / "sandbox/impl0_feedback.json").read_text()) + assert feedback["error_type"] == "not-solved" + + +def test_genplan_saves_failed_request(tmp_path, monkeypatch, caplog): + """A failing completion leaves the attempted prompt and error on disk.""" + client = _FakeClient([]) + + def fail(messages): + assert (tmp_path / "sandbox/impl0_prompt.txt").exists() + raise RuntimeError("session limit reached") + + monkeypatch.setattr(client, "complete", fail) + approach = _make_approach(_ToyEnv(), client, tmp_path) + with pytest.raises(RuntimeError, match="session limit reached"): + approach.train() + assert "Request impl0 failed" in caplog.text + assert (tmp_path / "sandbox/impl0_error.txt").read_text() == "session limit reached" + + def test_docker_cost_readback(tmp_path, monkeypatch): """With use_docker, the cost written by the container is read back.""" env = _ToyEnv() @@ -432,3 +467,37 @@ def test_first_attempt_runs_even_if_cot_exhausts_budget(tmp_path): assert ( "class GeneratedApproach" in (tmp_path / "sandbox" / "approach.py").read_text() ) + + +@pytest.mark.parametrize( + "module_name, class_name", + [ + ("dyn_obstruction2d", "DynObstruction2DEnv"), + ("dyn_pushpullhook2d", "DynPushPullHook2DEnv"), + ], +) +def test_generalized_source_includes_underlying_mechanics(module_name, class_name): + """Source text includes the dynamic backend and its physics/goal dependencies.""" + env = VariableObjectCountEnv( + constant_object_env_path=f"kinder.envs.dynamic2d.{module_name}:{class_name}", + count_kwarg="num_obstructions", + count_object_prefix="obstruction", + design_counts=[0, 1], + eval_counts=[0, 1, 2], + ) + try: + source = _gather_env_source(env) + backend_cls = hydra.utils.get_class( + f"kinder.envs.dynamic2d.{module_name}.{class_name}" + ) + # Check entire files, not names that might merely appear in wrapper text. + for cls in ( + VariableObjectCountEnv, + backend_cls, + ObjectCentricDynamic2DRobotEnv, + ): + path = inspect.getsourcefile(cls) + assert path is not None + assert Path(path).read_text(encoding="utf-8") in source + finally: + env.close() diff --git a/tests/utils/test_llm.py b/tests/utils/test_llm.py index d34e8b9..1595931 100644 --- a/tests/utils/test_llm.py +++ b/tests/utils/test_llm.py @@ -56,6 +56,20 @@ def fake_run(args, **kwargs): assert reply.cost_usd == 0.01 +def test_cli_failure_exposes_diagnostics(monkeypatch): + """Captured CLI errors include the actual reason rather than only exit 1.""" + + def fail(args, **kwargs): + raise subprocess.CalledProcessError( + 1, args, output="Session limit reached", stderr="resets 4:50am (UTC)" + ) + + monkeypatch.setattr(subprocess, "run", fail) + with pytest.raises(RuntimeError, match="Session limit reached") as error: + ClaudeCLIClient(DictConfig({"model": "test"})).complete([]) + assert "resets 4:50am" in str(error.value) + + def _create_mcp_tool(sandbox_dir: Path) -> str: """Write the Docker MCP server/config and return its secret test token.""" # A harmless tool returns a token the model cannot know without invoking it.