soma_observability/
logging.rs

1//! Dual-output logging — console (colored) + file (JSON).
2//!
3//! # CUSTOMIZE: Why dual logging?
4//!
5//! Two simultaneous log destinations serve different audiences:
6//!
7//! | Destination | Format     | Audience              | Purpose                    |
8//! |-------------|------------|-----------------------|----------------------------|
9//! | stderr      | Pretty     | Developer / operator  | Human-readable, colorized  |
10//! | File        | JSON lines | Log aggregator / AI   | Machine-parseable, indexed |
11//!
12//! The console output is optimized for human scanning: compact timestamps,
13//! semantic colors, noise suppression. The file output preserves all fields
14//! for programmatic analysis (grep, jq, log aggregators, AI agents).
15//!
16//! # CUSTOMIZE: Usage in main.rs
17//!
18//! Replace the existing `tracing_subscriber` setup in `main.rs` with:
19//!
20//! ```rust,ignore
21//! use soma::logging;
22//!
23//! let data_dir = config.data_dir(); // e.g. ~/.soma
24//! logging::init(&data_dir, "example")?;
25//! ```
26//!
27//! In stdio mode, suppress all logs to avoid polluting the MCP JSON stream:
28//!
29//! ```rust,ignore
30//! if stdio_mode {
31//!     // Don't call logging::init() — tracing stays at warn level on stderr only
32//!     tracing_subscriber::fmt()
33//!         .with_env_filter(EnvFilter::new("warn"))
34//!         .with_writer(std::io::stderr)
35//!         .init();
36//! } else {
37//!     logging::init(&data_dir, "example")?;
38//! }
39//! ```
40//!
41//! # CUSTOMIZE: Log file location
42//!
43//! Logs are written to `{data_dir}/logs/{service}.log`.
44//! For the example service this resolves to `~/.soma/logs/example.log`.
45//!
46//! The file is truncated (not rotated) when it exceeds 10MB. This keeps
47//! disk usage predictable and eliminates the complexity of log rotation.
48//! For production deployments that need persistent logs, configure a log
49//! aggregator (e.g. Loki, Datadog, CloudWatch) to ship from stderr instead.
50
51pub mod aurora;
52pub mod formatter;
53
54use std::io::IsTerminal;
55use std::path::Path;
56
57use anyhow::{Context, Result};
58use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt, EnvFilter};
59
60use formatter::AuroraFormatter;
61
62/// Initialise dual logging: pretty console (stderr) + JSON file.
63///
64/// # Arguments
65///
66/// - `data_dir` — service data directory (e.g. `~/.soma`). Logs go into
67///   `{data_dir}/logs/{service_name}.log`.
68/// - `service_name` — used as the log file name (e.g. `"example"`).
69///
70/// # Errors
71///
72/// Returns an error if the log directory cannot be created or the log file
73/// cannot be opened for writing.
74///
75/// # CUSTOMIZE: EnvFilter precedence
76///
77/// Log levels are controlled by `RUST_LOG`. If unset, defaults to `"info"`.
78/// Examples:
79/// - `RUST_LOG=debug` — show all debug logs
80/// - `RUST_LOG=info,rmcp=warn` — info level, suppress rmcp crate noise
81/// - `RUST_LOG=soma=trace` — trace this crate only
82///
83/// Both the console and file writers share the same `EnvFilter`, so they
84/// always emit the same set of events.
85pub fn init(data_dir: &Path, service_name: &str) -> Result<()> {
86    let log_dir = data_dir.join("logs");
87    std::fs::create_dir_all(&log_dir)
88        .with_context(|| format!("failed to create log directory: {}", log_dir.display()))?;
89
90    let log_path = log_dir.join(format!("{service_name}.log"));
91
92    // Truncate the log file if it has grown past the 10MB cap.
93    // See `truncate_log_if_needed()` for rationale.
94    truncate_log_if_needed(&log_path)?;
95
96    // Open the log file for appending (creates it if it doesn't exist).
97    let log_file = std::fs::OpenOptions::new()
98        .create(true)
99        .append(true)
100        .open(&log_path)
101        .with_context(|| format!("failed to open log file: {}", log_path.display()))?;
102
103    let console_ansi = should_colorize();
104
105    // CUSTOMIZE: Subscriber stack
106    //
107    // The stack is built as:
108    //   registry()          — the base subscriber that stores span data
109    //     .with(env_filter) — shared level filter for ALL layers
110    //     .with(console)    — pretty, colored stderr output
111    //     .with(file)       — JSON lines file output
112    //
113    // Both layers share the same filter. To give them independent filters,
114    // see `tracing_subscriber::layer::Filtered`.
115    tracing_subscriber::registry()
116        .with(EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info")))
117        .with(
118            // Console layer: pretty, colored, human-readable
119            //
120            // CUSTOMIZE: Console layer configuration
121            // - `with_ansi(console_ansi)` — enables ANSI codes only when stderr is a TTY
122            //   or FORCE_COLOR is set. The AuroraFormatter reads `writer.has_ansi_escapes()`
123            //   to conditionally apply colors.
124            // - `with_writer(std::io::stderr)` — logs go to stderr, not stdout.
125            //   stdout is reserved for CLI output and MCP JSON streams.
126            // - `.event_format(AuroraFormatter)` — our custom formatter (see formatter.rs)
127            tracing_subscriber::fmt::layer()
128                .with_ansi(console_ansi)
129                .with_writer(std::io::stderr)
130                .event_format(AuroraFormatter),
131        )
132        .with(
133            // File layer: structured JSON, machine-readable
134            //
135            // CUSTOMIZE: File layer configuration
136            // - `.json()` — emit one JSON object per log line (NDJSON format)
137            // - `.with_ansi(false)` — never emit ANSI codes to the file
138            // - `.with_writer(log_file)` — write to the log file we opened above
139            //
140            // JSON format example:
141            // {"timestamp":"2026-05-13T14:32:01.123Z","level":"INFO","fields":{"message":"starting","bind":"0.0.0.0:3000"}}
142            tracing_subscriber::fmt::layer()
143                .json()
144                .with_ansi(false)
145                .with_writer(log_file),
146        )
147        .init();
148
149    tracing::debug!(
150        log_file = %log_path.display(),
151        ansi = console_ansi,
152        "logging initialised"
153    );
154
155    Ok(())
156}
157
158// ── Log file rotation ─────────────────────────────────────────────────────────
159
160/// Maximum log file size in bytes before truncation.
161///
162/// # CUSTOMIZE: Why 10MB?
163///
164/// 10MB is large enough to contain several hours of busy server logs at INFO
165/// level, but small enough that disk pressure is never a concern. The file is
166/// truncated (not rotated), so disk usage is bounded at exactly one file.
167///
168/// If you need longer retention, configure log shipping to an external system
169/// (Loki, Datadog, etc.) and keep this cap. The file is for local debugging.
170const LOG_FILE_MAX_BYTES: u64 = 10 * 1024 * 1024; // 10 MiB
171
172/// Truncate the log file to zero if it exceeds [`LOG_FILE_MAX_BYTES`].
173///
174/// # CUSTOMIZE: Truncation vs rotation
175///
176/// Traditional log rotation creates `service.log.1`, `service.log.2`, etc.
177/// We truncate instead because:
178/// 1. Simpler — no need to manage multiple files or `logrotate` config
179/// 2. Predictable — disk usage is always ≤ 10MB, never grows unboundedly
180/// 3. Safe for agents — agents reading the log file always find a single file
181///
182/// When the file is truncated, the server logs a WARN message so the operator
183/// knows why the log history starts from the current process.
184fn truncate_log_if_needed(path: &std::path::PathBuf) -> Result<()> {
185    if !path.exists() {
186        return Ok(());
187    }
188
189    let size = path
190        .metadata()
191        .with_context(|| format!("failed to stat log file: {}", path.display()))?
192        .len();
193
194    if size >= LOG_FILE_MAX_BYTES {
195        std::fs::write(path, b"")
196            .with_context(|| format!("failed to truncate log file: {}", path.display()))?;
197        // Note: we can't use tracing here (subscriber not yet initialised).
198        // Write to stderr directly so the truncation event is never lost.
199        eprintln!(
200            "WARN  log file exceeded {LOG_FILE_MAX_BYTES} bytes — truncated: {}",
201            path.display()
202        );
203    }
204
205    Ok(())
206}
207
208// ── Colorization detection ────────────────────────────────────────────────────
209
210/// Determine whether console log output should include ANSI color codes.
211///
212/// Priority order (highest to lowest):
213///
214/// 1. `NO_COLOR` env var set → **no color** (<https://no-color.org/> convention)
215/// 2. `FORCE_COLOR` env var set → **force color** (useful in Docker/CI)
216/// 3. `stderr` is a TTY → **color** (interactive terminal)
217/// 4. `stderr` is not a TTY → **no color** (piped/redirected)
218///
219/// # CUSTOMIZE: Docker containers
220///
221/// Docker containers often do NOT have a TTY attached to stderr, which would
222/// disable color by rule 4. But `docker compose logs` renders ANSI codes
223/// correctly, so operators benefit from colors.
224///
225/// Set `FORCE_COLOR=1` in your `docker-compose.yml` or Dockerfile:
226/// ```yaml
227/// environment:
228///   FORCE_COLOR: "1"
229/// ```
230///
231/// # CUSTOMIZE: CI/CD pipelines
232///
233/// Most CI systems (GitHub Actions, GitLab CI) support ANSI codes.
234/// Set `FORCE_COLOR=1` in your CI environment variables to enable color logs.
235pub fn should_colorize() -> bool {
236    // NO_COLOR takes precedence over everything (https://no-color.org)
237    if std::env::var_os("NO_COLOR").is_some() {
238        return false;
239    }
240
241    // FORCE_COLOR overrides TTY detection (for Docker, CI, etc.)
242    if std::env::var_os("FORCE_COLOR").is_some() {
243        return true;
244    }
245
246    // Fall back to TTY detection
247    std::io::stderr().is_terminal()
248}
249
250#[cfg(test)]
251#[path = "logging_tests.rs"]
252mod tests;
soma_observability/logging.rs

soma_observability/
logging.rs
