feat: add structured logging system for agent debugging

[cabana8471-arch]

Summary

Add a comprehensive structured logging system that saves logs to SQLite at {project_dir}/.autocoder/logs.db for debugging agent issues.

• Add structured_logging.py: SQLite-based logging with WAL mode for better concurrency
• Add test_structured_logging.py: 28 unit tests covering all functionality
• Integrate logging in agent.py, parallel_orchestrator.py, autonomous_agent_demo.py, client.py

Features

• WAL mode for concurrent access by parallel agents (prevents "database is locked")
• Query API with filtering by level, agent_id, feature_id, tool_name
• Full-text search in messages
• Export to JSON, JSONL, CSV formats
• Automatic cleanup of old entries
• Thread-safe concurrent writes

Logged Events

Component	Events
agent.py	Session start/complete, tool use, blocked commands, errors, rate limits
parallel_orchestrator.py	Agent spawn/complete, failures, retry exhaustion
autonomous_agent_demo.py	Script entry, interruptions, fatal errors
client.py	Settings file creation, API overrides, client configuration

Access Logs

# SQLite direct access
sqlite3 {project}/.autocoder/logs.db "SELECT * FROM logs ORDER BY timestamp DESC LIMIT 10"

# Query errors only
sqlite3 {project}/.autocoder/logs.db "SELECT * FROM logs WHERE level='error'"

# API (existing endpoint, now has data)
curl http://localhost:8000/api/logs/{project_name}

Test Plan

• Run python -m pytest test_structured_logging.py -v (28 tests pass)
• Verify WAL mode: sqlite3 logs.db "PRAGMA journal_mode" returns wal
• Test with parallel agents to verify no database locking
• Verify logs are queryable via API endpoint

🤖 Generated with Claude Code

Summary by CodeRabbit

• New Features

  • Persistent, project-scoped structured JSON logging with per-agent/session context, lifecycle and rate-limit events, query/export tools, and console output; integrated into demo, orchestrator, client, and agent flows.
  • New debug logger for capturing persistent debug traces and orchestrator state.

• Bug Fixes

  • Improved error, interruption and status reporting across agent and orchestrator flows for clearer failure context.

• Tests

  • Comprehensive tests for logging, querying, exports, concurrency, and retention/cleanup.

_{✏️ Tip: You can customize this high-level summary in your review settings.}

[coderabbitai]

Warning

Rate limit exceeded

@cabana8471-arch has exceeded the limit for the number of commits that can be reviewed per hour. Please wait 17 minutes and 49 seconds before requesting another review.

⌛ How to resolve this issue?

After the wait time has elapsed, a review can be triggered using the @coderabbitai review command as a PR comment. Alternatively, push new commits to this PR.

We recommend that you space out your commits to avoid hitting the rate limit.

🚦 How do rate limits work?

CodeRabbit enforces hourly rate limits for each developer per organization.

Our paid plans have higher rate limits than the trial, open-source and free plans. In all cases, we re-allow further reviews after a brief timeout.

Please see our FAQ for further information.

📝 Walkthrough

Walkthrough

Adds a new SQLite-backed structured logging subsystem and integrates per-agent loggers throughout the autonomous runtime, client creation, orchestrator, and demo; includes query/export tooling, unit tests, and threads the logger through session lifecycle, error paths, and rate-limit events.

Changes

Cohort / File(s)	Summary
Structured Logging Framework structured_logging.py	New module: StructuredLogEntry, StructuredLogHandler (SQLite WAL persistence, thread-safe, max_entries eviction), StructuredLogger (per-project, optional console), LogQuery (filter/search/timeline/stats/export), and factories get_logger, get_log_query.
Logging Tests test_structured_logging.py	New comprehensive tests for serialization, DB/WAL init, multi-level logging with extras, query filters/paging/timeline/stats, export (json/jsonl/csv), concurrency/thread-safety, and max_entries eviction.
Agent Session Instrumentation agent.py	run_agent_session signature adds optional logger; per-agent logger created in run_autonomous_agent; logger passed through sessions; structured logs added for session start/completion, tool usage, security/tool errors, rate-limit decisions, and final summaries; client identity handling adjusted to compute client_agent_id.
Demo Entrypoint Instrumentation autonomous_agent_demo.py	Imports get_logger, initializes project-scoped logger in main(), logs script start (input/resolved paths, args), and records KeyboardInterrupts and fatal exceptions via structured logs.
Client Initialization Instrumentation client.py	create_client obtains a logger and emits structured logs for writing security settings, API overrides configuration, and client creation metadata (model, yolo_mode, agent_id/is_alternative_api, max_turns).
Orchestrator Instrumentation & Debug Logger parallel_orchestrator.py	Adds DebugLogger (thread-safe, file-based) and per-instance self._logger via get_logger; logs orchestrator init, spawn successes/failures, agent completions (status, return_code, pid), retries/exhaustion, and loop errors; retains existing control flow.
Minor Imports / Organization agent.py, client.py, parallel_orchestrator.py	Added/adjusted os imports and reordered initialization to create loggers earlier; inserted additional logger.debug/info calls around tool usage and responses.

Sequence Diagram

sequenceDiagram
    participant Demo as Demo / Orchestrator
    participant Agent as Agent Runner
    participant Client as Client
    participant Logger as StructuredLogger
    participant Handler as StructuredLogHandler
    participant DB as SQLite DB
    participant Query as LogQuery

    Demo->>Logger: info(startup, project_dir, args)
    Demo->>Agent: start_autonomous_run(project_dir, agent_type, logger)
    Agent->>Logger: info(session_start, agent_id, feature_id)
    Agent->>Client: create_client(client_agent_id, ...)
    Client->>Logger: info(client_created, model, agent_id)
    Agent->>Logger: info(tool_invocation, tool_name, feature_id)
    Logger->>Handler: emit(LogRecord)
    Handler->>DB: INSERT log entry (WAL, eviction)
    DB-->>Handler: commit
    Agent->>Logger: error(session_error, error_type, message)
    Demo->>Query: export_logs(filters)
    Query->>DB: SELECT ... (filters/paging)
    DB-->>Query: rows
    Query-->>Demo: exported_results

Loading

Estimated code review effort

🎯 4 (Complex) | ⏱️ ~60 minutes

Poem

🐰 I hop through WAL and JSON light,

I log each start, each tool, each fight,
Threads hum softly, entries stay,
Agents chatter, errors play,
A rabbit cheers: "Keep logs in sight!"

🚥 Pre-merge checks | ✅ 3

✅ Passed checks (3 passed)

Check name	Status	Explanation
Description Check	✅ Passed	Check skipped - CodeRabbit’s high-level summary is enabled.
Title check	✅ Passed	The pull request title 'feat: add structured logging system for agent debugging' accurately and concisely summarizes the main change—introduction of a new SQLite-backed structured logging system integrated throughout the codebase.
Docstring Coverage	✅ Passed	Docstring coverage is 92.41% which is sufficient. The required threshold is 80.00%.

_{✏️ Tip: You can configure your own custom pre-merge checks in the settings.}

✨ Finishing touches

🧪 Generate unit tests (beta)

• Create PR with unit tests
• Post copyable unit tests in a comment

---

Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

• X
• Mastodon
• Reddit
• LinkedIn

_{Comment @coderabbitai help to get the list of available commands and usage tips.}

[coderabbitai]

Actionable comments posted: 3

🤖 Fix all issues with AI agents

In `@structured_logging.py`:
- Around line 436-439: Replace the two uses of datetime.utcnow() that set
default ranges for since/until with timezone-aware calls: use
datetime.now(timezone.utc) - timedelta(hours=24) for since and
datetime.now(timezone.utc) for until; update or ensure the module imports
timezone from datetime (consistent with the rest of the file) so these
assignments in the block that sets defaults for since and until become
timezone-aware and match the existing pattern used elsewhere (see the existing
usage at line 147).
- Around line 360-362: The LIKE pattern uses the raw search string which allows
% and _ to act as wildcards; escape those characters before building the
parameter and include an ESCAPE clause in the SQL. Locate the query-building
branch that appends "message LIKE ?" and the params.append(f"%{search}%") (the
code handling the search variable), replace the raw insertion with an escaped
version (e.g., replace "%" and "_" with escaped forms and also escape your
escape char), append the escaped pattern wrapped with % to params, and update
the SQL fragment to use "message LIKE ? ESCAPE '\\'" so the DB treats the escape
sequences literally.

In `@test_structured_logging.py`:
- Around line 151-159: The test_log_warn currently asserts the presence of
"warning" in the logged message which is fragile; instead, change the assertion
to verify the log entry's level field. After calling logger.warn("Test warning")
and retrieving logs via get_log_query(...).query(level="warning"), assert that
logs[0]["level"] == "warning" (or use self.assertEqual on logs[0]["level"],
"warning") so the test validates log level rather than message content; keep
references to test_log_warn, logger.warn, get_log_query, and query.query when
locating and updating the assertion.

🧹 Nitpick comments (3)

test_structured_logging.py (1)

385-422: Thread safety test may be flaky on fast machines.

The test_concurrent_read_write test has a race condition where the writer thread could complete before the reader thread has a chance to read any results. On a fast machine or under load, read_results could be empty if the writer finishes and sets write_done before the reader enters its loop.

Consider adding a small synchronization to ensure the reader starts before the writer completes:

     def test_concurrent_read_write(self):
         """Test that reads and writes can happen concurrently."""
         logger = get_logger(self.project_dir, agent_id="writer", console_output=False)
         query = get_log_query(self.project_dir)

         # Pre-populate some logs
         for i in range(10):
             logger.info(f"Initial log {i}")

         read_results = []
         write_done = threading.Event()
+        reader_started = threading.Event()

         def writer():
+            reader_started.wait(timeout=5)  # Wait for reader to start
             for i in range(50):
                 logger.info(f"Concurrent log {i}")
             write_done.set()

         def reader():
+            reader_started.set()
             while not write_done.is_set():
                 count = query.count()
                 read_results.append(count)

structured_logging.py (1)

157-194: Connection-per-emit pattern is safe but inefficient.

Opening and closing a SQLite connection on every emit() call introduces overhead. For high-volume logging, this could become a performance bottleneck. However, this is a reasonable trade-off for simplicity and thread safety with WAL mode.

If performance becomes an issue in the future, consider connection pooling or a dedicated writer thread with a queue.

autonomous_agent_demo.py (1)

240-246: Consider logging at error level for fatal errors.

The fatal error is logged with logger.error() which is correct, but the message truncation to 200 characters may lose important context for debugging complex errors.

For fatal errors that terminate the script, consider logging the full traceback:

     except Exception as e:
         print(f"\nFatal error: {e}")
-        logger.error("Fatal error", error_type=type(e).__name__, message=str(e)[:200])
+        import traceback
+        logger.error("Fatal error", error_type=type(e).__name__, message=str(e)[:500], traceback=traceback.format_exc()[:1000])
         raise

[coderabbitai]

Actionable comments posted: 1

🤖 Fix all issues with AI agents

In `@structured_logging.py`:
- Around line 360-365: The search branch escapes LIKE wildcards into
escaped_search and appends the param, but the SQL fragment in conditions
("message LIKE ?") lacks an ESCAPE clause so SQLite won't treat backslashes as
escape characters; update the condition to include an explicit ESCAPE clause
(e.g., "message LIKE ? ESCAPE '\\'") when adding to conditions, keep using
escaped_search for params, and ensure the chosen escape character in the ESCAPE
clause matches the character used in escaped_search.

🧹 Nitpick comments (1)

structured_logging.py (1)

540-548: Consider handling empty logs case for CSV export.

When logs is empty, the code correctly skips CSV creation (due to if logs:), but this leaves no file created. This is consistent with other formats, but consider creating an empty file with just headers for CSV consistency with tools that expect a file to exist.

Optional: Create CSV with headers even when empty

         elif format == "csv":
             import csv

-            if logs:
-                with open(output_path, "w", newline="") as f:
+            with open(output_path, "w", newline="") as f:
+                fieldnames = ["id", "timestamp", "level", "message", "agent_id", "feature_id", "tool_name", "duration_ms", "extra"]
+                if logs:
+                    fieldnames = logs[0].keys()
                     writer = csv.DictWriter(f, fieldnames=logs[0].keys())
-                    writer.writeheader()
+                writer.writeheader()
+                if logs:
                     writer.writerows(logs)

[coderabbitai]

Actionable comments posted: 2

🤖 Fix all issues with AI agents

In `@structured_logging.py`:
- Around line 147-149: The timestamp normalization is inconsistent: log records
use .isoformat().replace("+00:00", "Z") but the since/until range values use
plain .isoformat(), causing mismatches; update all timestamp generation sites in
structured_logging.py (the log record formatting block shown and the two other
occurrences around the range filter logic) to produce UTC Zulu timestamps
consistently — e.g., replace .isoformat() with either
.isoformat().replace("+00:00", "Z") or .strftime("%Y-%m-%dT%H:%M:%SZ") so that
the log formatter (where timestamp=datetime.now(timezone.utc)... in the
record-building code) and the functions that build since/until range filters
produce identical "Z" suffixed timestamps.
- Around line 35-36: LogLevel currently defines "warn" but persisted entries use
record.levelname.lower() which yields "warning", causing query(level="warn") to
miss matches; update the code paths that persist/serialize log levels (where
record.levelname.lower() is used) to normalize "warning" → "warn" before
storing, or alternatively expand the LogLevel Literal to include "warning" and
adjust query handling; ensure normalization is applied in the functions that
create stored entries and in any level comparison logic (e.g., the query
function) so filters using "warn" match stored records.

🧹 Nitpick comments (1)

structured_logging.py (1)

96-140: Use context managers for SQLite connections to avoid leaks on exceptions.

If an insert or JSON serialization fails after the connection opens, the connection is never closed. Wrap connections with with sqlite3.connect(...) as conn: so they always close.

♻️ Suggested refactor

-            conn = sqlite3.connect(self.db_path)
-            cursor = conn.cursor()
+            with sqlite3.connect(self.db_path) as conn:
+                cursor = conn.cursor()
@@
-            conn.commit()
-            conn.close()
+                conn.commit()
@@
-                conn = sqlite3.connect(self.db_path)
-                cursor = conn.cursor()
+                with sqlite3.connect(self.db_path) as conn:
+                    cursor = conn.cursor()
@@
-                conn.commit()
-                conn.close()
+                    conn.commit()

Also applies to: 157-194

[coderabbitai]

Actionable comments posted: 1

🤖 Fix all issues with AI agents

In `@structured_logging.py`:
- Around line 489-491: In get_agent_stats(), the timestamp pushed to params uses
since.isoformat() which can omit the required "Z" suffix; convert since to UTC
and format it with a trailing "Z" before appending to params (e.g., ensure since
is timezone-aware via since.astimezone(datetime.timezone.utc) and produce an ISO
string with 'Z' by replacing '+00:00' with 'Z' or using strftime), then replace
the existing since.isoformat() usage in the where_clause / params handling so
the stored timestamp is normalized with the "Z" suffix.

🧹 Nitpick comments (4)

test_structured_logging.py (2)

82-86: Consider moving repeated shutil import to module level.

The import shutil statement is repeated in every tearDown method across 6 test classes. Moving it to the module-level imports would be cleaner.

Suggested improvement

 import json
 import sqlite3
+import shutil
 import tempfile
 import threading

Then remove the import shutil from each tearDown method.

Also applies to: 121-124, 213-216, 303-306, 361-364, 435-438

---

440-466: Test may be timing-sensitive due to cleanup occurring per-insert.

The cleanup logic in StructuredLogHandler.emit() deletes old entries after each insert when count exceeds max_entries. With max_entries=10 and 20 writes, the final count should be exactly 10 (not "at most 10"). Consider using assertEqual for a stricter assertion.

Suggested stricter assertion

         # Should have at most max_entries
-        self.assertLessEqual(count, 10)
+        self.assertEqual(count, 10)

structured_logging.py (2)

182-194: Cleanup query runs on every insert, consider batching or threshold.

The cleanup logic executes SELECT COUNT(*) and potentially a DELETE on every single log insertion. Under high-throughput logging, this adds overhead. Consider running cleanup less frequently (e.g., every N inserts or when count exceeds max_entries * 1.1).

Example optimization

# Add instance counter
self._insert_count = 0
self._cleanup_interval = 100  # Check every 100 inserts

# In emit(), after INSERT:
self._insert_count += 1
if self._insert_count >= self._cleanup_interval:
    self._insert_count = 0
    cursor.execute("SELECT COUNT(*) FROM logs")
    # ... cleanup logic

---

305-309: Database connections not using context managers.

The LogQuery methods open connections with _connect() and close them manually with conn.close(). If an exception occurs between connect and close, the connection could leak. Consider using context managers consistently.

Example refactor for query()

-        conn = self._connect()
-        cursor = conn.cursor()
-        # ... query logic ...
-        cursor.execute(query, params)
-        rows = cursor.fetchall()
-        conn.close()
-        return [dict(row) for row in rows]
+        with self._connect() as conn:
+            cursor = conn.cursor()
+            # ... query logic ...
+            cursor.execute(query, params)
+            rows = cursor.fetchall()
+            return [dict(row) for row in rows]

Also applies to: 340-341, 392-393, 405-406, 426-427, 441-442, 466-467, 484-485, 511-512

[coderabbitai]

Actionable comments posted: 2

🤖 Fix all issues with AI agents

In `@structured_logging.py`:
- Around line 30-53: Several type hints use unparameterized dict/list; update
them to explicit generics (e.g., change StructuredLogEntry.extra: dict ->
dict[str, Any], the to_dict return type: dict -> dict[str, Any], and similarly
replace any unparameterized list/dict occurrences elsewhere in this file) and
add Any to the typing imports; ensure all function signatures and return
annotations (including the other spots using plain dict/list) use concrete
element types or Any where appropriate to satisfy Python 3.11+ typing best
practices.
- Around line 376-385: The timestamp formatting currently uses naive
isoformat.replace("+00:00","Z") which fails for naive or non-UTC datetimes;
create a helper _format_ts(dt) that ensures dt is timezone-aware, converts it to
UTC, and returns an ISO string with a trailing Z, then replace direct isoformat
calls in query, count, get_timeline, and get_agent_stats to use
_format_ts(since)/_format_ts(until) so all filters normalize to UTC before being
appended to params.

🧹 Nitpick comments (1)

test_structured_logging.py (1)

400-403: Avoid a tight spin in the reader loop.

The reader loop can busy‑spin and burn CPU. Consider a tiny sleep to reduce test flakiness on slower CI.

🛠️ Example tweak

+import time
@@
         def reader():
             while not write_done.is_set():
                 count = query.count()
                 read_results.append(count)
+                time.sleep(0.01)

[coderabbitai]

Actionable comments posted: 2

🤖 Fix all issues with AI agents

In `@structured_logging.py`:
- Around line 53-56: The function that formats datetimes currently only converts
timezone-aware datetimes to UTC (using dt.astimezone(timezone.utc)) but leaves
naive datetimes without tzinfo so dt.isoformat() lacks the "Z" suffix; update
the logic handling dt (the local variable passed into the formatter) to treat
naive datetimes as UTC by assigning timezone.utc (e.g., set tzinfo=timezone.utc
or call dt.replace(tzinfo=timezone.utc) before isoformat), then continue
converting/normalizing timezone-aware datetimes to UTC and return a string that
replaces "+00:00" with "Z" as before so naive inputs get the "Z" suffix as
documented.
- Around line 389-393: The LIKE-escape logic in the search branch fails to
escape backslashes, so strings containing "\" are misinterpreted; update the
escape sequence order in the block that builds escaped_search (used with
conditions, params) to first replace "\" with "\\" and then escape "%" and "_"
(i.e., escape backslashes before escaping wildcards) so the final params.append
uses a correctly escaped pattern for SQLite with ESCAPE '\' in the query.

🧹 Nitpick comments (2)

structured_logging.py (2)

254-256: Consider moving hashlib import to module level.

The hashlib import inside __init__ works but deviates from the standard pattern of placing imports at the top of the file. Since hashlib is a lightweight stdlib module with no side effects, moving it to the module-level imports would improve readability.

📝 Suggested change

 import json
 import logging
 import sqlite3
 import threading
+import hashlib
 from dataclasses import dataclass, field

Then remove line 254.

---

569-575: Parameter format shadows built-in function.

Using format as a parameter name shadows Python's built-in format() function. While not a runtime issue here, it can cause confusion and lint warnings.

📝 Suggested change

     def export_logs(
         self,
         output_path: Path,
-        format: Literal["json", "jsonl", "csv"] = "jsonl",
+        output_format: Literal["json", "jsonl", "csv"] = "jsonl",
         batch_size: int = 1000,
         **filters,
     ) -> int:

Update usages of format to output_format within the method body (lines 595, 609, 615).