From f536bf24045e5d085058b86efcf524bb1fe2cc64 Mon Sep 17 00:00:00 2001 From: Bryan Helmkamp Date: Wed, 6 May 2026 15:31:25 -0400 Subject: [PATCH] feat(cli): polish foreground TTY logs Add a compact formatter for interactive foreground stdout while preserving the plain tracing format for piped output and file logs. --- docs/internal/logging-strategy.md | 2 +- ...6-05-06-polished-foreground-tty-logging.md | 74 ++++ lib/crates/fabro-cli/src/logging.rs | 375 +++++++++++++++++- 3 files changed, 444 insertions(+), 7 deletions(-) create mode 100644 docs/superpowers/plans/2026-05-06-polished-foreground-tty-logging.md diff --git a/docs/internal/logging-strategy.md b/docs/internal/logging-strategy.md index bc122e598..63f6f8f54 100644 --- a/docs/internal/logging-strategy.md +++ b/docs/internal/logging-strategy.md @@ -1,6 +1,6 @@ # Fabro Logging Strategy -Fabro uses the `tracing` crate for structured logging. CLI logs write to `~/.fabro/logs/cli.YYYY-MM-DD.log`, rotated daily by `tracing-appender`; logs older than 7 days are cleaned up on startup. Daemonized server starts write one main log at `/logs/server.log` by default. Foreground server starts (`fabro server start --foreground` and `fabro server restart --foreground`) stream server logs to stdout by default when `[server.logging].destination` is absent. Set `[server.logging].destination = "file"` to force file logging, or `FABRO_LOG_DESTINATION=stdout` to force stdout where compatible. Default install-generated `settings.toml` intentionally omits `[server.logging].destination` so foreground mode can use its stdout default. +Fabro uses the `tracing` crate for structured logging. CLI logs write to `~/.fabro/logs/cli.YYYY-MM-DD.log`, rotated daily by `tracing-appender`; logs older than 7 days are cleaned up on startup. Daemonized server starts write one main log at `/logs/server.log` by default. Foreground server starts (`fabro server start --foreground` and `fabro server restart --foreground`) stream server logs to stdout by default when `[server.logging].destination` is absent. Interactive foreground stdout uses a compact colored one-line format with local date-bearing timestamps (`YYYY-MM-DD HH:MM:SS.mmm`); piped stdout and file logs keep the plain tracing format with ANSI disabled. Set `[server.logging].destination = "file"` to force file logging, or `FABRO_LOG_DESTINATION=stdout` to force stdout where compatible. Default install-generated `settings.toml` intentionally omits `[server.logging].destination` so foreground mode can use its stdout default. Each worker also writes its tracing events to the run-scoped log at `/runtime/server.log`. This per-run file is worker tracing only: parent-side scheduling/cancel/delete events stay in the main server log, and unstructured worker stderr is still drained by the parent into `/logs/server.log`. diff --git a/docs/superpowers/plans/2026-05-06-polished-foreground-tty-logging.md b/docs/superpowers/plans/2026-05-06-polished-foreground-tty-logging.md new file mode 100644 index 000000000..483577ba8 --- /dev/null +++ b/docs/superpowers/plans/2026-05-06-polished-foreground-tty-logging.md @@ -0,0 +1,74 @@ +# Polished Foreground TTY Logging Implementation Plan + +> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking. + +**Goal:** Improve interactive foreground server stdout logs with a compact, colored, one-line TTY format that keeps date-bearing timestamps. + +**Architecture:** Keep the existing logging sink selection and file logging behavior unchanged. Add an internal TTY-only tracing formatter in `fabro-cli` and select it only for stdout server logs when stdout is an interactive terminal. + +**Tech Stack:** Rust, `tracing`, `tracing-subscriber`, `console`, Fabro CLI/server logging. + +--- + +## Summary + +Add a custom one-line TTY formatter for `fabro server start --foreground` when logs go to stdout and stdout is a terminal. File logs, piped stdout, CI captures, and per-run worker log files keep the current plain tracing format. The TTY timestamp must keep the calendar date. + +## Key Changes + +- Add an internal `TtyLogFormat` in `lib/crates/fabro-cli/src/logging.rs` for stdout logging only. +- Use `std::io::stdout().is_terminal()` to choose TTY formatting; use `console::colors_enabled()` only to decide whether ANSI color is emitted. +- Format TTY logs as: + + ```text + 2026-05-06 14:12:04.184 INFO API server started bind=/tmp/fabro.sock + 2026-05-06 14:12:13.044 WARN LLM request failed, retrying provider=openai attempt=2 error="rate limited" + 2026-05-06 14:12:21.337 ERROR Worker process exited unexpectedly run=run_abc123 pid=41822 + 2026-05-06 14:12:22.008 DEBUG fabro_server::server Spawning worker run=run_abc123 mode=start + ``` + +- Use local wall-clock timestamps formatted as `YYYY-MM-DD HH:MM:SS.mmm`. +- Color TTY output as: timestamp dim, `INFO` green, `WARN` yellow, `ERROR` bold red, `DEBUG` cyan/dim, `TRACE` dim, debug target dim, fields dim. +- Extract tracing `message` as the main message, render all other event fields as `key=value`, and preserve fields rather than hiding diagnostics. +- Hide the target for `INFO`, `WARN`, and `ERROR`; show a dim target for `DEBUG` and `TRACE`. +- Keep file logs on the existing `fmt::layer().with_target(true).with_ansi(false)` behavior. +- Use the TTY formatter for worker stdout only when worker logs are routed to inherited stdout; keep worker per-run `runtime/server.log` plain. + +## Interfaces + +- Public CLI/API/config: no changes. +- Existing `[server.logging].destination` and `FABRO_LOG_DESTINATION` precedence remains unchanged. +- Observable stdout format changes only for interactive foreground server stdout. +- Update `docs/internal/logging-strategy.md` to state that foreground TTY stdout uses compact colored formatting with date-bearing timestamps, while file and piped logs remain plain. + +## Implementation Checklist + +- [x] Add a small field visitor in `logging.rs` that captures the `message` field separately and stores all other fields in stable insertion order. +- [x] Add `TtyLogFormat` implementing `tracing_subscriber::fmt::FormatEvent` for the compact one-line format. +- [x] Factor logging initialization so server stdout can choose between the new TTY formatter and the existing plain formatter without changing file sinks. +- [x] Apply the same stdout-vs-file split to worker logging: TTY formatter for server stdout layer only, plain formatter for per-run file layer. +- [x] Keep all file appenders using `BufferedFileAppender` and ANSI disabled. +- [x] Update the logging strategy doc with the new foreground TTY behavior. + +## Test Plan + +- Add unit tests in `logging.rs` for `TtyLogFormat`: + - timestamp includes a `YYYY-MM-DD` date. + - `INFO` hides target, includes message, and includes fields. + - `DEBUG` includes target. + - color-enabled output contains ANSI sequences. + - color-disabled output contains no ANSI sequences. +- Add or adjust integration coverage in `server_start.rs`: + - Existing piped `foreground_start_writes_tracing_to_stdout_by_default` remains plain and keeps passing. + - Existing file-destination test proves `/logs/server.log` stays uncolored and truncation behavior is unchanged. +- Run: + - `cargo nextest run -p fabro-cli foreground_start_writes_tracing_to_stdout_by_default` + - `cargo nextest run -p fabro-cli foreground_start_with_file_destination_writes_tracing_to_storage_server_log` + - `cargo nextest run -p fabro-cli logging` + - `cargo +nightly-2026-04-14 fmt --check --all` + +## Assumptions + +- TTY formatting is a presentation-only improvement, not a new configuration surface. +- Piped stdout remains stable to avoid breaking scripts and existing tests. +- One-line logs are preferred over multiline pretty output because server logs can interleave parent and worker events. diff --git a/lib/crates/fabro-cli/src/logging.rs b/lib/crates/fabro-cli/src/logging.rs index 1aa0d9a78..9184e6aae 100644 --- a/lib/crates/fabro-cli/src/logging.rs +++ b/lib/crates/fabro-cli/src/logging.rs @@ -2,14 +2,22 @@ clippy::disallowed_methods, reason = "CLI logging setup: sync directory scan during startup" )] +use std::fmt::Write as _; +use std::io::IsTerminal; use std::path::{Path, PathBuf}; use anyhow::{Context, Result}; +use console::Style; use fabro_static::EnvVars; use fabro_util::run_log::BufferedFileAppender; +use tracing::field::{Field, Visit}; +use tracing::{Event, Level, Subscriber}; use tracing_appender::rolling; +use tracing_subscriber::fmt::FmtContext; +use tracing_subscriber::fmt::format::{FormatEvent, FormatFields, Writer}; use tracing_subscriber::fmt::writer::MakeWriter; use tracing_subscriber::layer::SubscriberExt; +use tracing_subscriber::registry::LookupSpan; use tracing_subscriber::util::SubscriberInitExt; use tracing_subscriber::{EnvFilter, fmt}; @@ -72,7 +80,7 @@ pub(crate) fn init_tracing( InternalLogSink::Server { log: LogSink::Stdout, } => { - init_subscriber(filter, std::io::stdout); + init_stdout_subscriber(filter, std::io::stdout); } InternalLogSink::Worker { server_log: LogSink::File(server_log_path), @@ -88,17 +96,166 @@ pub(crate) fn init_tracing( server_log: LogSink::Stdout, per_run_log_path, } => { - init_worker_subscriber( - filter, - std::io::stdout, - open_buffered_appender(per_run_log_path)?, - ); + let per_run_appender = open_buffered_appender(per_run_log_path)?; + init_worker_stdout_subscriber(filter, std::io::stdout, per_run_appender); } } Ok(()) } +#[derive(Clone, Copy, Debug)] +struct TtyLogFormat { + ansi: bool, +} + +impl TtyLogFormat { + fn new(ansi: bool) -> Self { + Self { ansi } + } +} + +impl FormatEvent for TtyLogFormat +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, +{ + fn format_event( + &self, + _ctx: &FmtContext<'_, S, N>, + mut writer: Writer<'_>, + event: &Event<'_>, + ) -> std::fmt::Result { + const MESSAGE_WIDTH: usize = 42; + + let metadata = event.metadata(); + let mut fields = EventFieldVisitor::default(); + event.record(&mut fields); + + let timestamp = chrono::Local::now().format("%Y-%m-%d %H:%M:%S%.3f"); + write!( + writer, + "{} {} ", + self.dim(timestamp), + self.level(*metadata.level()) + )?; + + if should_show_target(*metadata.level()) { + write!(writer, "{} ", self.dim(metadata.target()))?; + } + + let message = fields.message.as_deref().unwrap_or_default(); + if !message.is_empty() { + write!(writer, "{message}")?; + } + + let formatted_fields = fields.format_fields(); + if !formatted_fields.is_empty() { + if !message.is_empty() { + let padding = MESSAGE_WIDTH.saturating_sub(message.len()) + 2; + writer.write_str(&" ".repeat(padding))?; + } + + write!(writer, "{}", self.dim(formatted_fields))?; + } + + writeln!(writer) + } +} + +impl TtyLogFormat { + fn level(self, level: Level) -> String { + let padded = format!("{level:<5}"); + let style = match level { + Level::ERROR => Style::new().red().bold(), + Level::WARN => Style::new().yellow(), + Level::INFO => Style::new().green(), + Level::DEBUG => Style::new().cyan().dim(), + Level::TRACE => Style::new().dim(), + } + .force_styling(self.ansi); + + format!("{}", style.apply_to(padded)) + } + + fn dim(self, value: impl std::fmt::Display) -> String { + format!( + "{}", + Style::new().dim().force_styling(self.ansi).apply_to(value) + ) + } +} + +#[derive(Default)] +struct EventFieldVisitor { + message: Option, + fields: Vec<(String, String)>, +} + +impl EventFieldVisitor { + fn record_value(&mut self, field: &Field, value: String) { + if field.name() == "message" { + self.message = Some(value); + return; + } + + self.fields.push((field.name().to_string(), value)); + } + + fn format_fields(&self) -> String { + let mut output = String::new(); + for (index, (name, value)) in self.fields.iter().enumerate() { + if index > 0 { + output.push(' '); + } + let _ = write!(output, "{name}={value}"); + } + output + } +} + +impl Visit for EventFieldVisitor { + fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) { + self.record_value(field, format!("{value:?}")); + } + + fn record_str(&mut self, field: &Field, value: &str) { + if field.name() == "message" { + self.record_value(field, value.to_string()); + } else { + self.record_value(field, format!("{value:?}")); + } + } + + fn record_i64(&mut self, field: &Field, value: i64) { + self.record_value(field, value.to_string()); + } + + fn record_u64(&mut self, field: &Field, value: u64) { + self.record_value(field, value.to_string()); + } + + fn record_i128(&mut self, field: &Field, value: i128) { + self.record_value(field, value.to_string()); + } + + fn record_u128(&mut self, field: &Field, value: u128) { + self.record_value(field, value.to_string()); + } + + fn record_bool(&mut self, field: &Field, value: bool) { + self.record_value(field, value.to_string()); + } + + fn record_error(&mut self, field: &Field, value: &(dyn std::error::Error + 'static)) { + self.record_value(field, value.to_string()); + } +} + +fn should_show_target(level: Level) -> bool { + matches!(level, Level::DEBUG | Level::TRACE) +} + fn cleanup_old_logs(log_dir: &Path, prefix: &str, max_age_days: u32) { let cutoff = chrono::Utc::now().date_naive() - chrono::Duration::days(i64::from(max_age_days)); let Ok(entries) = std::fs::read_dir(log_dir) else { @@ -146,6 +303,27 @@ where .init(); } +fn init_stdout_subscriber(filter: EnvFilter, stdout_writer: W) +where + W: for<'writer> MakeWriter<'writer> + Send + Sync + 'static, +{ + if !std::io::stdout().is_terminal() { + init_subscriber(filter, stdout_writer); + return; + } + + let ansi = console::colors_enabled(); + tracing_subscriber::registry() + .with(filter) + .with( + fmt::layer() + .with_writer(stdout_writer) + .with_ansi(ansi) + .event_format(TtyLogFormat::new(ansi)), + ) + .init(); +} + fn init_worker_subscriber( filter: EnvFilter, server_writer: ServerWriter, @@ -171,7 +349,192 @@ fn init_worker_subscriber( .init(); } +fn init_worker_stdout_subscriber( + filter: EnvFilter, + server_writer: ServerWriter, + run_writer: RunWriter, +) where + ServerWriter: for<'writer> MakeWriter<'writer> + Send + Sync + 'static, + RunWriter: for<'writer> MakeWriter<'writer> + Send + Sync + 'static, +{ + if !std::io::stdout().is_terminal() { + init_worker_subscriber(filter, server_writer, run_writer); + return; + } + + let ansi = console::colors_enabled(); + tracing_subscriber::registry() + .with(filter) + .with( + fmt::layer() + .with_writer(server_writer) + .with_ansi(ansi) + .event_format(TtyLogFormat::new(ansi)), + ) + .with( + fmt::layer() + .with_writer(run_writer) + .with_target(true) + .with_ansi(false), + ) + .init(); +} + fn open_buffered_appender(path: &Path) -> Result { BufferedFileAppender::open(path) .with_context(|| format!("Failed to open log file: {}", path.display())) } + +#[cfg(test)] +mod tests { + use std::sync::{Arc, Mutex}; + use std::{fmt as std_fmt, io}; + + use tracing::subscriber; + use tracing_subscriber::fmt::MakeWriter; + use tracing_subscriber::prelude::*; + use tracing_subscriber::{fmt as tracing_fmt, registry}; + + use super::TtyLogFormat; + + #[test] + fn tty_format_timestamp_includes_calendar_date() { + let output = render_tty_event(false, || { + tracing::info!("API server started"); + }); + + assert!( + output.starts_with_timestamp(), + "expected date-bearing timestamp at start, got: {output:?}" + ); + } + + #[test] + fn tty_format_info_hides_target_and_preserves_message_and_fields() { + let output = render_tty_event(false, || { + tracing::info!( + target: "fabro_server::server", + bind = %"/tmp/fabro.sock", + "API server started" + ); + }); + + assert!(output.contains("INFO")); + assert!(output.contains("API server started")); + assert!(output.contains("bind=/tmp/fabro.sock")); + assert!( + !output.contains("fabro_server::server"), + "INFO output should hide the target, got: {output:?}" + ); + } + + #[test] + fn tty_format_debug_includes_target() { + let output = render_tty_event(false, || { + tracing::debug!( + target: "fabro_server::server", + run = %"run_abc123", + "Spawning worker" + ); + }); + + assert!(output.contains("DEBUG")); + assert!(output.contains("fabro_server::server")); + assert!(output.contains("Spawning worker")); + assert!(output.contains("run=run_abc123")); + } + + #[test] + fn tty_format_with_color_contains_ansi_sequences() { + let output = render_tty_event(true, || { + tracing::warn!(attempt = 2, "LLM request failed, retrying"); + }); + + assert!( + output.contains("\x1b["), + "color-enabled output should contain ANSI sequences, got: {output:?}" + ); + } + + #[test] + fn tty_format_without_color_contains_no_ansi_sequences() { + let output = render_tty_event(false, || { + tracing::error!(error = %"rate limited", "Request failed"); + }); + + assert!( + !output.contains("\x1b["), + "color-disabled output should be plain, got: {output:?}" + ); + } + + fn render_tty_event(ansi: bool, emit: impl FnOnce()) -> String { + let output = CapturedTrace::default(); + let subscriber = registry().with( + tracing_fmt::layer() + .with_writer(output.clone()) + .event_format(TtyLogFormat::new(ansi)), + ); + + subscriber::with_default(subscriber, emit); + + output.captured_output() + } + + trait TimestampAssertion { + fn starts_with_timestamp(&self) -> bool; + } + + impl TimestampAssertion for str { + fn starts_with_timestamp(&self) -> bool { + let Some(timestamp) = self.get(..23) else { + return false; + }; + + chrono::NaiveDateTime::parse_from_str(timestamp, "%Y-%m-%d %H:%M:%S%.3f").is_ok() + } + } + + #[derive(Clone, Default)] + struct CapturedTrace { + buffer: Arc>>, + } + + impl CapturedTrace { + fn captured_output(&self) -> String { + let buffer = self.buffer.lock().unwrap(); + String::from_utf8(buffer.clone()).unwrap() + } + } + + impl<'writer> MakeWriter<'writer> for CapturedTrace { + type Writer = CapturedTraceWriter; + + fn make_writer(&'writer self) -> Self::Writer { + CapturedTraceWriter { + buffer: Arc::clone(&self.buffer), + } + } + } + + struct CapturedTraceWriter { + buffer: Arc>>, + } + + impl io::Write for CapturedTraceWriter { + fn write(&mut self, bytes: &[u8]) -> io::Result { + self.buffer.lock().unwrap().extend_from_slice(bytes); + Ok(bytes.len()) + } + + fn flush(&mut self) -> io::Result<()> { + Ok(()) + } + } + + impl std_fmt::Debug for CapturedTraceWriter { + fn fmt(&self, formatter: &mut std_fmt::Formatter<'_>) -> std_fmt::Result { + formatter.debug_struct("CapturedTraceWriter").finish() + } + } +}