Log GenPlan progress and preserve failure diagnostics

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)

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(

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

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"))
 

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()

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.