From 047387cb17637761655a6bc5b6b05d7f56a5cc68 Mon Sep 17 00:00:00 2001 From: David Saroka Date: Fri, 21 Aug 2026 16:57:41 +0000 Subject: [PATCH] fix: keep ANSI out of span-field caches, release 1.0.1 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Found during the NSE API's adoption smoke run, not by the test suite: the per-request span's fields (`http_request{method=…}`) arrived in the log file and the colourless console wrapped in italic/dim escape codes, with colour configured off on every sink. The sinks set the ANSI flag on the event format only. Span fields never go through the event format: the *layer's* flag — defaulting on — decides how they are rendered into the cache that every event then prints verbatim. The flag is now set on the layer for all four text shapes. The file sinks also get their own cache (a distinct field-formatter type). Span-field caches are shared per formatter type, so a coloured console beside a text file used to decide what the file printed — the reason services turned console colour off to protect their files. With a separate slot the file always caches plain and the console is free to colour its own. Both regressions are pinned by tests confirmed to fail against 1.0.0. Verified: 273 tests all-features, 0 failures; clippy -D warnings clean. --- CHANGELOG.md | 19 ++++++++ Cargo.toml | 2 +- src/logging/sinks.rs | 67 +++++++++++++++++++++++----- tests/stream_a_file_format.rs | 82 ++++++++++++++++++++++++++++++++++- 4 files changed, 158 insertions(+), 12 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 1996ff3..b19e044 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,25 @@ All notable changes to this project are documented here. The format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). +## [1.0.1] — 2026-08-21 + +### Fixed + +- Span fields no longer carry ANSI escape codes into files or colourless + consoles. The escape codes were coming from span-field *caching*: the + layer's own ANSI flag — which defaulted on — decides how a span's fields are + rendered into the cache every event then prints verbatim, and the sinks only + ever set the flag on the event format. Found live: a web service's + per-request span (`http_request{method=…}`) arrived in its log file wrapped + in italic/dim codes with colour configured off everywhere. + + The file sinks also get their own cache now (a distinct field-formatter + type), so a *coloured* console beside a text file cannot bleed escape codes + into it either — previously the two shared one cache and whichever layer + formatted a span first decided what the other printed, which is why services + had to switch console colour off to protect their files. Both regressions + are pinned by tests that fail against the previous release. + ## [1.0.0] — 2026-08-21 The stability release. From here, a breaking change to anything public is a diff --git a/Cargo.toml b/Cargo.toml index d43605e..500cc8f 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "stratify" -version = "1.0.0" +version = "1.0.1" edition = "2021" rust-version = "1.88.0" description = "Layered configuration and structured logging for Rust services: pluggable sources, priority merging, typed access, and a tracing facade" diff --git a/src/logging/sinks.rs b/src/logging/sinks.rs index 4098d99..c14a47d 100644 --- a/src/logging/sinks.rs +++ b/src/logging/sinks.rs @@ -36,6 +36,29 @@ impl Sink { } } +/// `DefaultFields` under a different type, so file sinks get their own span +/// cache. +/// +/// `tracing-subscriber` formats a span's fields once per *field-formatter +/// type* and caches the result in the span's extensions. With every text sink +/// on `DefaultFields`, they all share one cache, so whichever layer touches a +/// span first decides — with its own ANSI setting — what every other layer +/// prints for that span. That is how a coloured console used to write escape +/// codes into the log file. A distinct type is a distinct cache slot: file +/// sinks always cache plain, and the console is free to colour its own. +#[derive(Default)] +pub(super) struct PlainFields(fmt::format::DefaultFields); + +impl<'writer> fmt::FormatFields<'writer> for PlainFields { + fn format_fields( + &self, + writer: fmt::format::Writer<'writer>, + fields: R, + ) -> std::fmt::Result { + self.0.format_fields(writer, fields) + } +} + /// The console sink, using the built-in layout. /// /// Returns nothing when a caller-supplied formatter is in play; that case is @@ -66,6 +89,11 @@ where layer: Some( fmt::layer() .with_writer(writer.clone()) + // On the *layer*, not only the format: the layer's flag is + // what controls how span fields are cached into the span's + // extensions, and the cached string is printed verbatim by + // every event that closes over the span. + .with_ansi(config.use_color) .event_format(WithGlobals { inner: built_in, prefix: globals.to_string(), @@ -96,6 +124,9 @@ where layer: Some( fmt::layer() .with_writer(writer.clone()) + // Plain span cache: a custom formatter styles its own line, + // and the `SpanScope` it receives is rendered from this cache. + .with_ansi(false) .event_format(WithGlobals { inner: BoxedFormat(format), prefix: globals.to_string(), @@ -209,11 +240,20 @@ where .with_target(true) .with_timer(Timestamp(config.timestamp)); - Some(fmt::layer().with_writer(writer).event_format(WithGlobals { - inner: built_in, - prefix: globals.to_string(), - redact: redact.to_vec(), - })) + Some( + fmt::layer() + .with_writer(writer) + // `PlainFields` gives this sink its own span cache, and the layer + // flag keeps that cache free of escape codes, so a coloured + // console beside this file cannot bleed ANSI into it. + .fmt_fields(PlainFields::default()) + .with_ansi(false) + .event_format(WithGlobals { + inner: built_in, + prefix: globals.to_string(), + redact: redact.to_vec(), + }), + ) } /// The file sink in plain text, using a caller-supplied formatter. @@ -236,11 +276,18 @@ where return None; } let format = format?; - Some(fmt::layer().with_writer(writer).event_format(WithGlobals { - inner: BoxedFormat(format), - prefix: globals.to_string(), - redact: redact.to_vec(), - })) + Some( + fmt::layer() + .with_writer(writer) + // Same reasoning as `file_text`: own cache, kept plain. + .fmt_fields(PlainFields::default()) + .with_ansi(false) + .event_format(WithGlobals { + inner: BoxedFormat(format), + prefix: globals.to_string(), + redact: redact.to_vec(), + }), + ) } /// Reproduce a per-sink filter, or one that admits everything. diff --git a/tests/stream_a_file_format.rs b/tests/stream_a_file_format.rs index 9ba08ad..cc7af82 100644 --- a/tests/stream_a_file_format.rs +++ b/tests/stream_a_file_format.rs @@ -9,7 +9,7 @@ use std::fs; use std::path::PathBuf; -use stratify::logging::{FileConfig, FileFormat}; +use stratify::logging::{ConsoleConfig, FileConfig, FileFormat}; use tracing::subscriber::with_default; fn scratch(label: &str) -> PathBuf { @@ -131,3 +131,83 @@ fn json_format_is_still_available_explicitly() { let _ = fs::remove_dir_all(&dir); } + +#[test] +fn span_fields_in_the_file_carry_no_ansi_even_with_color_off_everywhere() { + // Arrange: every sink colourless — the configuration a service captured + // into Log Analytics runs. Span fields used to arrive with italic/dim + // escape codes anyway, because the *layer's* ANSI flag, not the event + // format's, decides how span fields are cached, and it defaulted on. + let dir = std::env::temp_dir().join(format!("lk-ansi-off-{}", std::process::id())); + let _ = fs::remove_dir_all(&dir); + let (subscriber, handle) = stratify::logging::builder() + .with_filter(stratify::logging::EnvFilter::new("info")) + .console(ConsoleConfig::default().with_color(false)) + .file(FileConfig::new(dir.to_string_lossy().to_string()).with_format(FileFormat::Text)) + .build() + .expect("builds"); + + // Act: the event fires inside a span carrying fields, which is what the + // per-request middleware of a web service produces on every line. + with_default(subscriber, || { + let span = tracing::info_span!("http_request", method = "GET", path = "/health"); + let _entered = span.enter(); + tracing::info!(latency = 3, "finished"); + }); + handle.flush(); + drop(handle); + + // Assert + let entry = fs::read_dir(&dir) + .expect("directory") + .filter_map(Result::ok) + .next() + .expect("a log file"); + let body = fs::read_to_string(entry.path()).expect("readable"); + let _ = fs::remove_dir_all(&dir); + + assert!(body.contains("http_request"), "the span renders: {body}"); + assert!( + !body.contains('\u{1b}'), + "no escape codes anywhere in the file: {body:?}" + ); +} + +#[test] +fn a_colored_console_cannot_bleed_ansi_into_the_file() { + // Arrange: console colour *on*, beside a text file. These used to share + // one span-field cache, so whichever layer formatted a span first decided + // what the other printed — the reason services had to turn console colour + // off to protect their files. The file sink now has its own cache. + let dir = std::env::temp_dir().join(format!("lk-ansi-bleed-{}", std::process::id())); + let _ = fs::remove_dir_all(&dir); + let (subscriber, handle) = stratify::logging::builder() + .with_filter(stratify::logging::EnvFilter::new("info")) + .console(ConsoleConfig::default().with_color(true)) + .file(FileConfig::new(dir.to_string_lossy().to_string()).with_format(FileFormat::Text)) + .build() + .expect("builds"); + + // Act + with_default(subscriber, || { + let span = tracing::info_span!("http_request", method = "GET"); + let _entered = span.enter(); + tracing::info!("finished"); + }); + handle.flush(); + drop(handle); + + // Assert + let entry = fs::read_dir(&dir) + .expect("directory") + .filter_map(Result::ok) + .next() + .expect("a log file"); + let body = fs::read_to_string(entry.path()).expect("readable"); + let _ = fs::remove_dir_all(&dir); + + assert!( + !body.contains('\u{1b}'), + "console colour must stay out of the file: {body:?}" + ); +}