diff --git a/docs/logging-strategy.md b/docs/logging-strategy.md new file mode 100644 index 000000000..b2c2a327c --- /dev/null +++ b/docs/logging-strategy.md @@ -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.