diff --git a/experiments/run_experiment.py b/experiments/run_experiment.py index dab6f6f..46b5363 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..88f5043 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 @@ -283,7 +284,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 +299,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 +351,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 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..55dbd52 100644 --- a/tests/approaches/test_llm_genplan_approach.py +++ b/tests/approaches/test_llm_genplan_approach.py @@ -296,6 +296,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() 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.