Files
cleveragents-core/docs/adr/ADR-025-observability-and-logging.md
freemo c2db74ba81
CI / lint (push) Successful in 15s
CI / build (push) Successful in 16s
CI / quality (push) Successful in 20s
CI / security (push) Successful in 35s
CI / typecheck (push) Successful in 42s
CI / benchmark-regression (push) Has been skipped
CI / unit_tests (push) Successful in 2m38s
CI / integration_tests (push) Successful in 3m11s
CI / docker (push) Successful in 39s
CI / coverage (push) Successful in 4m58s
CI / benchmark-publish (push) Successful in 17m32s
Docs: Restyled ADR pages
2026-03-10 12:38:35 -04:00

164 lines
9.2 KiB
Markdown

---
adr_number: 25
title: Observability and Logging
status_history:
- - '2026-02-16'
- Proposed
- Jeffrey Phillips Freeman
- - '2026-02-16'
- Accepted
- Jeffrey Phillips Freeman
tier: 4
authors:
- Jeffrey Phillips Freeman
superseded_by: null
related_adrs:
- number: 1
title: Layered Architecture
relationship: Logging is a cross-cutting concern handled through the event bus in the Application Layer
- number: 5
title: Technical Stack
relationship: structlog is the chosen structured logging library
- number: 24
title: Configuration System
relationship: Log verbosity levels are controlled through the configuration system and CLI flags
acceptance:
votes_for:
- voter: Jeffrey Phillips Freeman <Jeffrey.Freeman@CleverThis.com>
comment: Structured JSON logging with context binding gives us the observability needed for debugging LLM-driven workflows
votes_against: []
abstentions: []
---
## Context
CleverAgents orchestrates complex, multi-step AI workflows involving LLM calls, tool invocations, plan hierarchies, and concurrent execution. When something goes wrong — a plan fails, a tool produces unexpected output, an LLM makes a bad decision — the operator needs to trace the chain of events, understand the context, and identify the root cause. Traditional unstructured logging is insufficient for correlating events across plan hierarchies, actor invocations, and tool calls.
## Decision Drivers
- Multi-step AI workflows (LLM calls, tool invocations, plan hierarchies, concurrent execution) require correlated tracing across nested scopes to diagnose failures
- Log events must carry contextual identifiers (plan_id, actor_name, decision_id, tool_name) for structured querying and filtering
- Log output must not contaminate structured command output on stdout; logs and results must flow through separate streams
- LLM-specific observability (token usage, latency, cost) is needed but must remain optional and not create a hard dependency
- Default verbosity must be minimal (FATAL-only) with intuitive CLI-flag escalation for debugging
## Decision
CleverAgents uses **structlog** (>= 24.4.0) for structured JSON logging with context binding. Every log event carries contextual identifiers (`plan_id`, `decision_id`, `actor_name`, `tool_name`) that enable correlation across the plan lifecycle. Optional **LangSmith** integration provides LLM-specific observability (tracing, token usage, latency, cost).
## Design
### Structured Logging with structlog
structlog provides:
- **JSON-structured output**: Every log event is a JSON object with a consistent schema, enabling log aggregation, filtering, and analysis with standard tools.
- **Context binding**: Contextual key-value pairs are bound to the logger and automatically included in every subsequent log event. Plan execution binds `plan_id`, `decision_id`, `actor_name`, and `tool_name` at the appropriate scope.
- **Processor pipeline**: Log events flow through a configurable processor chain (timestamp injection, level filtering, context enrichment, output formatting).
### Context Binding Pattern
```
plan_lifecycle.start → bind(plan_id=...)
strategize → bind(actor_name="local/strategy-actor")
decision_made → bind(decision_id=...)
execute → bind(actor_name="local/execution-actor")
tool_invoked → bind(tool_name="local/edit-file")
tool_completed → unbind(tool_name)
apply → bind(phase="apply")
apply_completed
```
Each nested scope adds its identifiers to the bound context. Log events at any depth carry the full context chain, enabling queries like "show all events for plan X, decision Y, tool Z."
### Log Levels
| Level | Default Behavior | `-v` Flag |
|-------|-----------------|-----------|
| `FATAL` | Always shown | (default) |
| `ERROR` | Suppressed by default | `-v` |
| `WARN` | Suppressed by default | `-vv` |
| `INFO` | Suppressed by default | `-vvv` |
| `DEBUG` | Suppressed by default | `-vvvv` |
| `TRACE` | Suppressed by default | `-vvvvv` |
The default log level is `FATAL` — only fatal errors produce log output. The `-v` flag (repeatable up to 5 times) raises the effective verbosity for a single invocation.
### Log Output Destinations
- **File output**: Log files written to `core.log.dir` (default: `<data-dir>/logs`). Controlled by `core.log.file-enabled` (default: `true`). Retention: `core.log.retention-days` (default: 30).
- **Terminal output**: Controlled by `core.log.terminal` (`auto`, `always`, `never`). In `auto` mode, terminal output is shown only when `-v` is used. Terminal log output goes to `core.log.terminal-stream` (default: `stderr`) to keep logs separate from command output on stdout.
### Domain Events
The event-driven architecture (ADR-001) emits structured domain events through the event bus:
- `PlanCreated`, `PhaseChanged`, `DecisionMade`, `ToolInvoked`, `ApplyCompleted`, `CorrectionRequested`.
- Events flow through RxPY reactive streams for real-time processing.
- Events are captured by the structured logging pipeline for persistence.
- Events enable decoupled observability without tight coupling between components.
### LangSmith Integration (Optional)
LangSmith provides LLM-specific observability:
- **Tracing**: Full trace of LLM calls including prompts, completions, tool calls, and intermediate steps.
- **Token usage**: Per-call and aggregate token consumption tracking.
- **Latency**: Per-call and end-to-end latency measurement.
- **Cost**: Estimated cost per call and per plan based on provider pricing.
Configuration: `CLEVERAGENTS_LANGSMITH_*` environment variables, which sync to `LANGCHAIN_TRACING_V2`. LangSmith is entirely optional — the system functions fully without it.
### Metrics Collection
The `MetricsCollector` in the Application Layer aggregates:
- Plan execution counts and durations.
- Tool invocation counts, success/failure rates, and latencies.
- LLM call counts, token usage, and estimated costs.
- Context assembly metrics (strategy execution times, budget utilization, cache hit rates).
Metrics are exposed through structured log events and are available for performance benchmarking via ASV.
## Constraints
- All log events must be structured JSON. Unstructured string messages are prohibited.
- Context binding must include at minimum `plan_id` and `actor_name` for events within plan execution. `decision_id` and `tool_name` must be included when available.
- Terminal log output must go to stderr (or the configured stream), never to stdout, to avoid contaminating structured command output.
- LangSmith integration must be optional — the system must function identically (except for LLM-specific tracing) without LangSmith configured.
- Log file retention must be enforced automatically. Logs older than `core.log.retention-days` must be purged.
- Provider API keys and other secrets must never appear in log output.
## Consequences
### Positive
- Structured JSON logging enables powerful querying and correlation across complex plan hierarchies.
- Context binding automatically enriches events with identifiers, reducing the need for manual log annotation.
- The `-v` flag convention provides intuitive verbosity control without configuration file changes.
- Separate log and command output streams enable clean scripting with `--format json` while retaining debug log access.
- LangSmith integration provides deep LLM-specific insights without custom instrumentation.
### Negative
- Structured JSON logs are less human-readable than traditional text logs when viewed directly.
- Context binding adds overhead to every log call (maintaining the bound context dictionary).
- The six log levels with a default of FATAL may hide important information from users who do not know about the `-v` flag.
### Risks
- High-volume log events during concurrent plan execution could impact performance or fill disk storage.
- LangSmith dependency on an external service introduces a potential single point of failure for LLM tracing.
- Secret leakage in log output is a persistent risk that requires ongoing vigilance.
## Alternatives Considered
**Python stdlib logging** — Supports structured logging via formatters but lacks structlog's first-class context binding, processor pipeline, and JSON output capabilities. Would require significant custom code to achieve equivalent functionality.
**OpenTelemetry for tracing** — A more general-purpose observability framework, but adds significant complexity. LangSmith provides LLM-specific tracing that is more targeted to CleverAgents' needs. OpenTelemetry could be added later as a complementary integration.
## Compliance
- **Structured output tests**: Tests verify that all log events are valid JSON with the expected schema fields.
- **Context binding tests**: Tests verify that `plan_id`, `actor_name`, `decision_id`, and `tool_name` are correctly bound and unbound at the appropriate scopes.
- **Secret masking tests**: Tests verify that provider API keys and authentication tokens never appear in log output.
- **Stderr separation tests**: Tests verify that log output goes to stderr and does not appear in stdout regardless of verbosity level.
- **Retention tests**: Tests verify that log file cleanup correctly removes files older than the configured retention period.
- **LangSmith opt-in tests**: Tests verify that the system functions correctly without LangSmith configured and that enabling LangSmith produces the expected traces.