fabro/docs/logging-strategy.md

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.

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.

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.

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.

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.

// 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:

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:

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:

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:

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:

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.