feat: add structured logging system for agent debugging

agent.py

@@ -7,6 +7,7 @@
 
 import asyncio
 import io
+import os
 import re
 import sys
 from datetime import datetime, timedelta
@@ -16,6 +17,8 @@
 
 from claude_agent_sdk import ClaudeSDKClient
 
+from structured_logging import get_logger
+
 # Fix Windows console encoding for Unicode characters (emoji, etc.)
 # Without this, print() crashes when Claude outputs emoji like ✅
 if sys.platform == "win32":
@@ -40,6 +43,7 @@ async def run_agent_session(
     client: ClaudeSDKClient,
     message: str,
     project_dir: Path,
+    logger=None,
 ) -> tuple[str, str]:
     """
     Run a single agent session using Claude Agent SDK.
@@ -48,13 +52,16 @@ async def run_agent_session(
         client: Claude SDK client
         message: The prompt to send
         project_dir: Project directory path
+        logger: Optional structured logger for this session
 
     Returns:
         (status, response_text) where status is:
         - "continue" if agent should continue working
         - "error" if an error occurred
     """
     print("Sending prompt to Claude Agent SDK...\n")
+    if logger:
+        logger.info("Starting agent session", prompt_length=len(message))
 
     try:
         # Send the query
@@ -81,6 +88,8 @@ async def run_agent_session(
                                 print(f"   Input: {input_str[:200]}...", flush=True)
                             else:
                                 print(f"   Input: {input_str}", flush=True)
+                        if logger:
+                            logger.debug("Tool used", tool_name=block.name, input_size=len(str(getattr(block, "input", ""))))
 
             # Handle UserMessage (tool results)
             elif msg_type == "UserMessage" and hasattr(msg, "content"):
@@ -94,20 +103,29 @@ async def run_agent_session(
                         # Check if command was blocked by security hook
                         if "blocked" in str(result_content).lower():
                             print(f"   [BLOCKED] {result_content}", flush=True)
+                            if logger:
+                                logger.error("Security: command blocked", content=str(result_content)[:200])
                         elif is_error:
                             # Show errors (truncated)
                             error_str = str(result_content)[:500]
                             print(f"   [Error] {error_str}", flush=True)
+                            if logger:
+                                logger.error("Tool execution error", error=error_str[:200])
                         else:
                             # Tool succeeded - just show brief confirmation
                             print("   [Done]", flush=True)
 
         print("\n" + "-" * 70 + "\n")
+        if logger:
+            logger.info("Agent session completed", response_length=len(response_text))
         return "continue", response_text
 
     except Exception as e:
-        print(f"Error during agent session: {e}")
-        return "error", str(e)
+        error_str = str(e)
+        print(f"Error during agent session: {error_str}")
+        if logger:
+            logger.error("Agent session error", error_type=type(e).__name__, message=error_str[:200])
+        return "error", error_str
 
 
 async def run_autonomous_agent(
@@ -131,6 +149,27 @@ async def run_autonomous_agent(
         agent_type: Type of agent: "initializer", "coding", "testing", or None (auto-detect)
         testing_feature_id: For testing agents, the pre-claimed feature ID to test
     """
+    # Initialize structured logger for this agent session
+    # Agent ID format: "initializer", "coding-<feature_id>", "testing-<pid>"
+    if agent_type == "testing":
+        agent_id = f"testing-{os.getpid()}"
+    elif feature_id:
+        agent_id = f"coding-{feature_id}"
+    elif agent_type == "initializer":
+        agent_id = "initializer"
+    else:
+        agent_id = "coding-main"
+
+    logger = get_logger(project_dir, agent_id=agent_id, console_output=False)
+    logger.info(
+        "Autonomous agent started",
+        agent_type=agent_type or "auto-detect",
+        model=model,
+        yolo_mode=yolo_mode,
+        max_iterations=max_iterations,
+        feature_id=feature_id,
+    )
+
     print("\n" + "=" * 70)
     print("  AUTONOMOUS CODING AGENT")
     print("=" * 70)
@@ -192,6 +231,7 @@ async def run_autonomous_agent(
         if not is_initializer and iteration == 1:
             passing, in_progress, total = count_passing_tests(project_dir)
             if total > 0 and passing == total:
+                logger.info("Project complete on startup", passing=passing, total=total)
                 print("\n" + "=" * 70)
                 print("  ALL FEATURES ALREADY COMPLETE!")
                 print("=" * 70)
@@ -208,15 +248,14 @@ async def run_autonomous_agent(
         print_session_header(iteration, is_initializer)
 
         # Create client (fresh context)
-        # Pass agent_id for browser isolation in multi-agent scenarios
-        import os
+        # Pass client_agent_id for browser isolation in multi-agent scenarios
         if agent_type == "testing":
-            agent_id = f"testing-{os.getpid()}"  # Unique ID for testing agents
+            client_agent_id = f"testing-{os.getpid()}"  # Unique ID for testing agents
         elif feature_id:
-            agent_id = f"feature-{feature_id}"
+            client_agent_id = f"feature-{feature_id}"
         else:
-            agent_id = None
-        client = create_client(project_dir, model, yolo_mode=yolo_mode, agent_id=agent_id)
+            client_agent_id = None
+        client = create_client(project_dir, model, yolo_mode=yolo_mode, agent_id=client_agent_id)
 
         # Choose prompt based on agent type
         if agent_type == "initializer":
@@ -234,9 +273,10 @@ async def run_autonomous_agent(
         # Wrap in try/except to handle MCP server startup failures gracefully
         try:
             async with client:
-                status, response = await run_agent_session(client, prompt, project_dir)
+                status, response = await run_agent_session(client, prompt, project_dir, logger=logger)
         except Exception as e:
             print(f"Client/MCP server error: {e}")
+            logger.error("Client/MCP server error", error_type=type(e).__name__, message=str(e)[:200])
             # Don't crash - return error status so the loop can retry
             status, response = "error", str(e)
 
@@ -255,6 +295,7 @@ async def run_autonomous_agent(
 
             if "limit reached" in response.lower():
                 print("Claude Agent SDK indicated limit reached.")
+                logger.warn("Rate limit signal in response")
 
                 # Try to parse reset time from response
                 match = re.search(
@@ -329,6 +370,7 @@ async def run_autonomous_agent(
         elif status == "error":
             print("\nSession encountered an error")
             print("Will retry with a fresh session...")
+            logger.error("Session error, retrying", delay_seconds=AUTO_CONTINUE_DELAY_SECONDS)
             await asyncio.sleep(AUTO_CONTINUE_DELAY_SECONDS)
 
         # Small delay between sessions
@@ -337,6 +379,14 @@ async def run_autonomous_agent(
             await asyncio.sleep(1)
 
     # Final summary
+    passing, in_progress, total = count_passing_tests(project_dir)
+    logger.info(
+        "Agent session complete",
+        iterations=iteration,
+        passing=passing,
+        in_progress=in_progress,
+        total=total,
+    )
     print("\n" + "=" * 70)
     print("  SESSION COMPLETE")
     print("=" * 70)

autonomous_agent_demo.py

@@ -46,6 +46,7 @@
 
 from agent import run_autonomous_agent
 from registry import DEFAULT_MODEL, get_project_path
+from structured_logging import get_logger
 
 
 def parse_args() -> argparse.Namespace:
@@ -193,6 +194,17 @@ def main() -> None:
             print("Use an absolute path or register the project first.")
             return
 
+    # Initialize logger now that project_dir is resolved
+    logger = get_logger(project_dir, agent_id="entry-point", console_output=False)
+    logger.info(
+        "Script started",
+        input_path=project_dir_input,
+        resolved_path=str(project_dir),
+        agent_type=args.agent_type,
+        concurrency=args.concurrency,
+        yolo_mode=args.yolo,
+    )
+
     try:
         if args.agent_type:
             # Subprocess mode - spawned by orchestrator for a specific role
@@ -228,8 +240,10 @@ def main() -> None:
     except KeyboardInterrupt:
         print("\n\nInterrupted by user")
         print("To resume, run the same command again")
+        logger.info("Interrupted by user")
     except Exception as e:
         print(f"\nFatal error: {e}")
+        logger.error("Fatal error", error_type=type(e).__name__, message=str(e)[:200])
         raise
 
 

client.py

@@ -16,6 +16,7 @@
 from dotenv import load_dotenv
 
 from security import bash_security_hook
+from structured_logging import get_logger
 
 # Load environment variables from .env file if present
 load_dotenv()
@@ -179,6 +180,9 @@ def create_client(
     Note: Authentication is handled by start.bat/start.sh before this runs.
     The Claude SDK auto-detects credentials from the Claude CLI configuration
     """
+    # Initialize logger for client configuration events
+    logger = get_logger(project_dir, agent_id="client", console_output=False)
+
     # Build allowed tools list based on mode
     # In YOLO mode, exclude Playwright tools for faster prototyping
     allowed_tools = [*BUILTIN_TOOLS, *FEATURE_MCP_TOOLS]
@@ -225,6 +229,7 @@ def create_client(
     with open(settings_file, "w") as f:
         json.dump(security_settings, f, indent=2)
 
+    logger.info("Settings file written", file_path=str(settings_file))
     print(f"Created security settings at {settings_file}")
     print("   - Sandbox enabled (OS-level bash isolation)")
     print(f"   - Filesystem restricted to: {project_dir.resolve()}")
@@ -300,6 +305,7 @@ def create_client(
 
     if sdk_env:
         print(f"   - API overrides: {', '.join(sdk_env.keys())}")
+        logger.info("API overrides configured", is_ollama=is_ollama, overrides=list(sdk_env.keys()))
         if is_ollama:
             print("   - Ollama Mode: Using local models")
         elif "ANTHROPIC_BASE_URL" in sdk_env:
@@ -352,6 +358,16 @@ async def pre_compact_hook(
         # }
         return SyncHookJSONOutput()
 
+    # Log client creation
+    logger.info(
+        "Client created",
+        model=model,
+        yolo_mode=yolo_mode,
+        agent_id=agent_id,
+        is_alternative_api=is_alternative_api,
+        max_turns=1000,
+    )
+
     return ClaudeSDKClient(
         options=ClaudeAgentOptions(
             model=model,

parallel_orchestrator.py

@@ -31,6 +31,7 @@
 from api.dependency_resolver import are_dependencies_satisfied, compute_scheduling_scores
 from progress import has_features
 from server.utils.process_utils import kill_process_tree
+from structured_logging import get_logger
 
 # Root directory of autocoder (where this script and autonomous_agent_demo.py live)
 AUTOCODER_ROOT = Path(__file__).parent.resolve()
@@ -192,6 +193,16 @@ def __init__(
         # Database session for this orchestrator
         self._engine, self._session_maker = create_database(project_dir)
 
+        # Structured logger for persistent logs (saved to {project_dir}/.autocoder/logs.db)
+        # Uses console_output=False since orchestrator already has its own print statements
+        self._logger = get_logger(project_dir, agent_id="orchestrator", console_output=False)
+        self._logger.info(
+            "Orchestrator initialized",
+            max_concurrency=self.max_concurrency,
+            yolo_mode=yolo_mode,
+            testing_agent_ratio=testing_agent_ratio,
+        )
+
     def get_session(self):
         """Get a new database session."""
         return self._session_maker()
@@ -514,6 +525,7 @@ def _spawn_coding_agent(self, feature_id: int) -> tuple[bool, str]:
             )
         except Exception as e:
             # Reset in_progress on failure
+            self._logger.error("Spawn coding agent failed", feature_id=feature_id, error=str(e)[:200])
             session = self.get_session()
             try:
                 feature = session.query(Feature).filter(Feature.id == feature_id).first()
@@ -539,6 +551,7 @@ def _spawn_coding_agent(self, feature_id: int) -> tuple[bool, str]:
             self.on_status(feature_id, "running")
 
         print(f"Started coding agent for feature #{feature_id}", flush=True)
+        self._logger.info("Spawned coding agent", feature_id=feature_id, pid=proc.pid)
         return True, f"Started feature {feature_id}"
 
     def _spawn_testing_agent(self) -> tuple[bool, str]:
@@ -788,9 +801,11 @@ def _on_agent_complete(
             return
 
         # Coding agent completion
+        agent_status = "success" if return_code == 0 else "failed"
         debug_log.log("COMPLETE", f"Coding agent for feature #{feature_id} finished",
             return_code=return_code,
-            status="success" if return_code == 0 else "failed")
+            status=agent_status)
+        self._logger.info("Coding agent completed", feature_id=feature_id, status=agent_status, return_code=return_code)
 
         with self._lock:
             self.running_coding_agents.pop(feature_id, None)
@@ -826,6 +841,7 @@ def _on_agent_complete(
                 print(f"Feature #{feature_id} has failed {failure_count} times, will not retry", flush=True)
                 debug_log.log("COMPLETE", f"Feature #{feature_id} exceeded max retries",
                     failure_count=failure_count)
+                self._logger.warn("Feature exceeded max retries", feature_id=feature_id, failure_count=failure_count)
 
         status = "completed" if return_code == 0 else "failed"
         if self.on_status:
@@ -1102,6 +1118,7 @@ async def run_loop(self):
 
             except Exception as e:
                 print(f"Orchestrator error: {e}", flush=True)
+                self._logger.error("Orchestrator loop error", error_type=type(e).__name__, message=str(e)[:200])
                 await self._wait_for_agent_completion()
 
         # Wait for remaining agents to complete