mirror of
https://github.com/fabro-sh/fabro.git
synced 2026-10-10 03:30:59 +00:00
Add logging strategy document
Defines structured logging conventions for the team: level guidelines (INFO for production, DEBUG for on-demand investigation), structured field patterns, and per-crate examples. Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
This commit is contained in:
Bryan Helmkamp
parent
716400ac06
commit
303c78e584
1 changed files with 167 additions and 0 deletions
167
docs/logging-strategy.md
Normal file
167
docs/logging-strategy.md
Normal file
|
|
@ -0,0 +1,167 @@
|
|||
# Arc Logging Strategy
|
||||
|
||||
Arc uses the `tracing` crate for structured, file-based logging. Logs write to `~/.arc/logs/YYYY-MM-DD.log`, controlled by the `ARC_LOG` env var (default: `info`). Logs are for **developers debugging issues after the fact** — they are not user-facing output.
|
||||
|
||||
Production runs at INFO level. INFO should be low-volume and high-signal — the summary of what happened. When something goes wrong, developers enable `ARC_LOG=debug` to get the full picture. DEBUG can be as verbose as needed since it's only turned on temporarily.
|
||||
|
||||
## When to Log
|
||||
|
||||
**Log at INFO (always on in production):**
|
||||
|
||||
- Lifecycle boundaries of top-level operations — session started/completed, pipeline started/completed, server ready
|
||||
- Failures and warnings — every error/warn path, with enough context to diagnose the cause
|
||||
- Keep it sparse: a typical agent session should produce ~5-10 INFO lines
|
||||
|
||||
**Log at DEBUG (enabled on-demand for investigation):**
|
||||
|
||||
- Individual steps within an operation — each LLM request, each tool call, each pipeline node
|
||||
- External interactions with detail — request parameters, response metadata, token counts
|
||||
- Decision points — why a code path was taken (retry triggered, fallback used, config value resolved)
|
||||
- State changes and intermediate results — config resolution, parsing outcomes
|
||||
|
||||
**Do not log:**
|
||||
|
||||
- Hot loops or per-token streaming events (use DEBUG only if truly needed for diagnosis)
|
||||
- Data that belongs in user-facing output (`eprintln!` for CLI feedback, not tracing)
|
||||
- Redundant information already captured by a parent event (if you logged "starting X", you don't need to log every sub-step at the same level)
|
||||
- Secrets, API keys, or auth tokens — even at DEBUG level
|
||||
|
||||
## Log Levels
|
||||
|
||||
### ERROR — Something failed and the operation cannot continue
|
||||
|
||||
The current operation is aborting. A human reviewing logs should investigate every ERROR.
|
||||
|
||||
```rust
|
||||
error!(server = %name, error = %err, "MCP server failed to start");
|
||||
error!(provider = %provider, status = %status, "LLM request failed after all retries");
|
||||
```
|
||||
|
||||
### WARN — Something unexpected happened but execution continues
|
||||
|
||||
Degraded behavior, fallback paths, or conditions that might indicate a problem.
|
||||
|
||||
```rust
|
||||
warn!(server = %name, "MCP server disconnected, removing tools");
|
||||
warn!(attempt = attempt, max = max_retries, error = %err, "LLM request failed, retrying");
|
||||
```
|
||||
|
||||
### INFO — The production log level
|
||||
|
||||
INFO is always on. It should tell you **what** happened at a high level: which operations started, which completed, and key outcomes. Think of INFO as the audit trail — enough to answer "what did the system do?" but not so much that it creates noise. A typical agent session should produce a handful of INFO lines, not hundreds.
|
||||
|
||||
```rust
|
||||
info!(model = %model, "Starting agent session");
|
||||
info!(server = %name, tools = tool_count, "MCP server ready");
|
||||
info!(pipeline = %name, "Pipeline complete");
|
||||
info!(turns = turn_count, tool_calls = tool_call_count, "Agent session complete");
|
||||
```
|
||||
|
||||
### DEBUG — Turn this on when something goes wrong
|
||||
|
||||
DEBUG is off in production by default. Enable it with `ARC_LOG=debug` to investigate a specific issue. DEBUG events provide the **how** and **why**: request/response details, intermediate state, config resolution, individual steps within a larger operation. DEBUG can be verbose — that's fine, since it's only enabled temporarily.
|
||||
|
||||
```rust
|
||||
debug!(model = %model, messages = msg_count, tools = tool_count, "Sending LLM request");
|
||||
debug!(provider = %provider, input_tokens = input, output_tokens = output, "LLM response received");
|
||||
debug!(tool = %name, duration_ms = elapsed, "Tool call complete");
|
||||
debug!(path = %path.display(), "Loading workflow file");
|
||||
debug!(env_var = "ANTHROPIC_API_KEY", "API key resolved from environment");
|
||||
```
|
||||
|
||||
## How to Write a Log Event
|
||||
|
||||
### Message: describe what happened
|
||||
|
||||
The message string is a short, human-readable description. Use sentence fragments starting with a verb or noun. No variable interpolation in the message — put variable data in structured fields.
|
||||
|
||||
```rust
|
||||
// Good — message is a fixed string, data is in fields
|
||||
info!(server = %name, tools = tool_count, "MCP server ready");
|
||||
|
||||
// Bad — variable data interpolated into message string
|
||||
info!("MCP server '{}' ready with {} tools", name, tool_count);
|
||||
```
|
||||
|
||||
Fixed message strings make logs grepable and let tooling aggregate events by message.
|
||||
|
||||
### Fields: attach structured context
|
||||
|
||||
Fields are key-value pairs that make events queryable. Include enough context that the event is useful on its own without reading surrounding log lines.
|
||||
|
||||
**Field naming:**
|
||||
- Use `snake_case` for field names
|
||||
- Use consistent names across the codebase (see table below)
|
||||
- Keep names short but unambiguous
|
||||
|
||||
**Common field names:**
|
||||
|
||||
| Field | Used for |
|
||||
|-------|----------|
|
||||
| `model` | LLM model identifier |
|
||||
| `provider` | LLM provider name (anthropic, openai, gemini) |
|
||||
| `server` | MCP server name |
|
||||
| `tool` | Tool name being called |
|
||||
| `turn` | Agent turn number |
|
||||
| `attempt` | Retry attempt number |
|
||||
| `error` | Error value on failure |
|
||||
| `path` | File system path |
|
||||
| `duration_ms` | Elapsed time in milliseconds |
|
||||
| `input_tokens` | Token count for LLM input |
|
||||
| `output_tokens` | Token count for LLM output |
|
||||
|
||||
**Field format specifiers:**
|
||||
- `%` (Display) for user-readable values: `server = %name`, `error = %err`, `path = %path.display()`
|
||||
- `?` (Debug) for internal/enum values: `level = ?params.level`, `status = ?response.status`
|
||||
- No specifier for primitives: `tools = tool_count`, `attempt = 3`
|
||||
|
||||
### Examples by crate
|
||||
|
||||
**arc-agent:**
|
||||
```rust
|
||||
info!(model = %model, "Starting agent session");
|
||||
info!(turns = turn_count, tool_calls = total_calls, "Agent session complete");
|
||||
debug!(turn = turn_number, "Starting agent turn");
|
||||
debug!(tool = %name, "Executing tool call");
|
||||
debug!(tool = %name, duration_ms = elapsed, "Tool call complete");
|
||||
warn!(tool = %name, error = %err, "Tool execution failed");
|
||||
```
|
||||
|
||||
**arc-llm:**
|
||||
```rust
|
||||
debug!(provider = %provider, model = %model, messages = count, "Sending LLM request");
|
||||
debug!(provider = %provider, model = %model, input_tokens = input, output_tokens = output, "LLM response received");
|
||||
warn!(provider = %provider, attempt = n, error = %err, "Request failed, retrying");
|
||||
error!(provider = %provider, error = %err, "Request failed after all retries");
|
||||
```
|
||||
|
||||
**arc-workflows:**
|
||||
```rust
|
||||
info!(pipeline = %name, "Starting pipeline execution");
|
||||
info!(pipeline = %name, nodes = count, "Pipeline complete");
|
||||
debug!(node = %id, handler = %handler_type, "Executing pipeline node");
|
||||
debug!(node = %id, duration_ms = elapsed, "Pipeline node complete");
|
||||
```
|
||||
|
||||
**arc-mcp:**
|
||||
```rust
|
||||
info!(server = %name, tools = tool_count, "MCP server ready");
|
||||
debug!(server = %name, transport = %transport_type, "Connecting to MCP server");
|
||||
error!(server = %name, error = %err, "MCP server failed to start");
|
||||
```
|
||||
|
||||
## Cross-Package Guidelines
|
||||
|
||||
Every crate that does meaningful work should emit tracing events. The `tracing` dependency is workspace-level — add it to any crate's `Cargo.toml` with:
|
||||
|
||||
```toml
|
||||
tracing.workspace = true
|
||||
```
|
||||
|
||||
The subscriber is initialized once in `arc-cli`. Library crates (`arc-agent`, `arc-llm`, etc.) only emit events — they never configure the subscriber. This means:
|
||||
|
||||
- Library crates import `tracing::{info, debug, warn, error}` and call the macros
|
||||
- The events go nowhere in unit tests (this is fine — tests verify behavior, not log output)
|
||||
- The events are captured by whatever subscriber the binary sets up
|
||||
|
||||
When adding tracing to a new crate, start with the boundaries: INFO for the start/end of top-level operations, DEBUG for the individual steps within them. When in doubt about the level, use DEBUG — it's easy to promote something to INFO later, but hard to demote a noisy INFO event without breaking someone's log monitoring.
|
||||
Loading…
Add table
Reference in a new issue