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.
This commit is contained in:
Bryan Helmkamp 2026-05-06 15:31:25 -04:00
parent ce481ca154
commit f536bf2404
No known key found for this signature in database
3 changed files with 444 additions and 7 deletions

View file

@ -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 `<storage>/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 `<storage>/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 `<scratch>/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 `<storage>/logs/server.log`.

View file

@ -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 `<storage>/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.

View file

@ -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<S, N> FormatEvent<S, N> 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<String>,
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<W>(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<ServerWriter, RunWriter>(
filter: EnvFilter,
server_writer: ServerWriter,
@ -171,7 +349,192 @@ fn init_worker_subscriber<ServerWriter, RunWriter>(
.init();
}
fn init_worker_stdout_subscriber<ServerWriter, RunWriter>(
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> {
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<Mutex<Vec<u8>>>,
}
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<Mutex<Vec<u8>>>,
}
impl io::Write for CapturedTraceWriter {
fn write(&mut self, bytes: &[u8]) -> io::Result<usize> {
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()
}
}
}