anodizer_core/log.rs
1//! Thin structured logging helper for anodizer stages.
2//!
3//! Provides level-gated output to stderr in a single unified style ("format
4//! B"). Keeps stdout clean for machine-parseable output (e.g. `anodizer tag`).
5//!
6//! # Output style
7//!
8//! Two visual registers, one source of truth — never hand-format a stage line:
9//!
10//! ```text
11//! Checking determinism ← SECTION HEADER (group / step)
12//! • targets aarch64-… ← META key/value row (kv)
13//! • stages build, sign ← META key/value row (kv)
14//! • runs 2 ← META key/value row (kv)
15//! Building binaries ← SECTION HEADER
16//! • compiling x86_64-… ← DETAIL / info line (detail / status)
17//! ✓ x86_64-… 1.2 MiB ← SUCCESS line (success)
18//! ✗ aarch64-… build failed ← FAILURE line (failure)
19//! ```
20//!
21//! Body lines belonging to a [`StageLogger::group`] section additionally
22//! carry the section's 2-space nesting indent, so a header's own detail
23//! rows sit one level beneath it (the indents in the sketch above are
24//! relative, not absolute columns).
25//!
26//! - **Section headers** ([`StageLogger::step`] / [`StageLogger::group`]) put a
27//! bold-green present-participle verb (the leading word of the stage's
28//! [`stage_header`] phrase) right-aligned in a fixed 12-column gutter, then
29//! one space, then the message. ONLY verbs live in this gutter — never a
30//! lowercase key.
31//! - **Body lines** ([`StageLogger::detail`] / [`success`] / [`failure`], plus
32//! the retargeted [`StageLogger::status`]) sit at a 3-space body indent under
33//! their header, prefixed by a marker — `•` info (cyan), `✓` success (green),
34//! `✗` failure (red) — one space, then the text.
35//! - **Key/value rows** ([`StageLogger::kv`]) are `•` detail lines whose
36//! lowercase dimmed key is padded so the values align within a group.
37//! - **Status labels** (`Warning` / `Error` / `Note`, via
38//! [`render_warning`] / [`render_error`] / [`render_note`]) render the label
39//! right-aligned in the same verb gutter as a section header (no colon), so
40//! their messages align with the header messages above them.
41//!
42//! [`success`]: StageLogger::success
43//! [`failure`]: StageLogger::failure
44//!
45//! # Verbosity levels
46//!
47//! - **quiet**: errors only (for CI where only failures matter)
48//! - **default**: status messages (stage start/complete, key actions)
49//! - **verbose**: detail (command output, env vars, file paths)
50//! - **debug**: everything (HTTP request/response, template contexts, resolved config)
51//!
52//! # Secret redaction
53//!
54//! Every `StageLogger` carries an optional env-pairs list that drives the
55//! redaction policy applied inside [`StageLogger::check_output`]. Callers
56//! that go through [`crate::context::Context::logger`] inherit the merged
57//! `{process env, config env}` pairs automatically; manual constructors
58//! (`StageLogger::new`) start with no env and can be enriched via
59//! [`StageLogger::with_env`]. Stderr / stdout interpolated into log lines
60//! or `bail!` messages is therefore redacted without callers having to
61//! remember to scrub at every site.
62
63use std::sync::Arc;
64use std::sync::Mutex;
65use std::sync::OnceLock;
66use std::sync::atomic::{AtomicUsize, Ordering};
67
68use colored::Colorize;
69
70/// Process-global section nesting depth. Drives the 2-space-per-level
71/// indentation applied to every stderr log line so output produced
72/// inside a [`StageLogger::group`] sits visually beneath its header.
73///
74/// A single atomic (rather than per-logger state) is correct because the
75/// release pipeline drives one stderr stream and no `group()` is ever
76/// opened from a worker thread — sections bracket whole stages on the
77/// main thread, while a stage's interior parallelism (e.g. `build`
78/// spawning per-target threads) emits *inside* an already-open section.
79/// The depth is therefore a property of "where the main thread is in the
80/// run", not of any individual logger clone or worker.
81static SECTION_DEPTH: AtomicUsize = AtomicUsize::new(0);
82
83/// Env var carrying a parent `anodizer` process's visual nesting depth.
84///
85/// The determinism harness spawns child `anodizer release` subprocesses
86/// whose stderr is inherited, so the child's lines interleave directly
87/// into the parent's stream. Without an inherited base depth the child's
88/// section headers would render flush-left, visually escaping the
89/// parent's open section. The parent exports its depth here; the child
90/// reads it once (see [`base_depth`]) and offsets every indent by it.
91pub const LOG_DEPTH_ENV: &str = "ANODIZER_LOG_DEPTH";
92
93/// Base nesting depth inherited from a parent process via
94/// [`LOG_DEPTH_ENV`], parsed once on first use. Zero when the var is
95/// absent or unparseable (a standalone process indents from column 0).
96static BASE_DEPTH: OnceLock<usize> = OnceLock::new();
97
98/// Parse the inherited base depth from a raw [`LOG_DEPTH_ENV`] value.
99/// Lenient by design: a missing or malformed value degrades to 0 (the
100/// standalone-process default) rather than failing — indentation is
101/// presentation, never worth aborting a release over.
102fn parse_base_depth(raw: Option<&str>) -> usize {
103 raw.and_then(|v| v.trim().parse().ok()).unwrap_or(0)
104}
105
106/// The process's inherited base depth (see [`LOG_DEPTH_ENV`]).
107fn base_depth() -> usize {
108 *BASE_DEPTH.get_or_init(|| parse_base_depth(std::env::var(LOG_DEPTH_ENV).ok().as_deref()))
109}
110
111/// Current absolute nesting depth: the inherited base plus every open
112/// section. This is the value [`indent`] renders and the value a parent
113/// exports (offset for the child's nesting) when spawning a subprocess
114/// whose stderr joins this process's stream.
115pub fn current_depth() -> usize {
116 base_depth() + SECTION_DEPTH.load(Ordering::Relaxed)
117}
118
119/// A section header that has been opened ([`StageLogger::group`]) but not yet
120/// printed. The header line is deferred until the section actually emits a
121/// body line, so a stage that does nothing prints nothing at all (matching
122/// GoReleaser, which only prints a section header once the section has output).
123struct PendingHeader {
124 /// Section depth captured at open time. The header renders at *this* depth,
125 /// not the current global depth, so a nested section's deferred header is
126 /// still indented to its own level when flushed alongside its ancestors.
127 depth: usize,
128 /// Right-aligned bold-green verb (the leading word of the stage's
129 /// [`stage_header`] phrase).
130 verb: String,
131 /// The remaining words of the phrase, printed after the verb (empty for a
132 /// single-word phrase, which renders a bare gutter verb).
133 msg: String,
134 /// Whether this header has already been printed. A flushed entry stays on
135 /// the stack (so the LIFO pop in [`SectionGuard::drop`] removes the right
136 /// one) but is never reprinted.
137 flushed: bool,
138}
139
140/// Stack of section headers awaiting their first body line. Pushed by
141/// [`StageLogger::group`], drained by [`flush_pending`] when a real line is
142/// about to print, and popped (LIFO) by [`SectionGuard::drop`].
143///
144/// A `Mutex` (not a thread-local) because sections are opened on the main
145/// thread like [`SECTION_DEPTH`], but body lines may flush from a stage's
146/// worker threads (e.g. `build` spawning per-target threads). The lock
147/// serializes the flush state transition: each header's `flushed` flag flips
148/// under the lock, so a header prints exactly once — never lost, never
149/// duplicated. Header-before-body ordering holds because every emit method
150/// calls [`flush_pending`] then writes its body line with no early return
151/// between. It does not serialize body-line-vs-body-line ordering across
152/// workers — two `build` threads may print their body lines in either order
153/// under a just-flushed header, matching build's existing unordered parallel
154/// output.
155static PENDING: Mutex<Vec<PendingHeader>> = Mutex::new(Vec::new());
156
157/// Print every still-unflushed pending section header, in ancestor-first
158/// (bottom-to-top) order, then mark each flushed.
159///
160/// Called immediately before any method actually writes a visible body line,
161/// so the deferred headers appear above their first line in correct nesting
162/// order. A header renders at its own stored [`PendingHeader::depth`] — the
163/// 2-space-per-level indent, the right-aligned bold-green verb in the
164/// [`VERB_COLUMN`] gutter, then (if non-empty) one space and the message.
165///
166/// No-op when nothing is pending (the common case once a section has already
167/// emitted its first line), so the per-body-line cost is one uncontended lock.
168fn flush_pending() {
169 // Recover a poisoned guard rather than bailing: pending headers are pure
170 // presentation state, and silently muting every section header for the
171 // rest of the run on one panic-mid-format is worse than reusing it.
172 let mut pending = PENDING.lock().unwrap_or_else(|e| e.into_inner());
173 for entry in pending.iter_mut() {
174 if entry.flushed {
175 continue;
176 }
177 eprintln!("{}", render_header(entry.depth, &entry.verb, &entry.msg));
178 entry.flushed = true;
179 }
180}
181
182/// Render a section/stage header line at `depth`: the 2-space-per-level
183/// nesting indent, a bold-green verb right-aligned in the [`VERB_COLUMN`]
184/// gutter, then (only for a non-empty `msg`) a single space and the message.
185///
186/// The single source of truth shared by both header-emitting paths — the
187/// deferred section header in [`flush_pending`] and the direct
188/// [`StageLogger::step`] — so interleaved headers and steps land in
189/// byte-identical columns for the same depth. A single-word phrase (empty
190/// `msg`) renders the bare gutter verb with no trailing space, so headers
191/// never carry stray whitespace.
192fn render_header(depth: usize, verb: &str, msg: &str) -> String {
193 render_gutter(&" ".repeat(depth), verb, |s| s.green().bold(), msg)
194}
195
196/// Render one gutter line: `label` right-aligned in the [`VERB_COLUMN`] gutter
197/// (painted by `paint`) after `prefix`, then a space and `msg` — or, when `msg`
198/// is empty, the bare painted label with no trailing space. The single column
199/// system shared by section headers and the Warning/Error/Note status labels,
200/// so a status label's message lands in the same column as a header's.
201fn render_gutter(
202 prefix: &str,
203 label: &str,
204 paint: impl Fn(String) -> colored::ColoredString,
205 msg: &str,
206) -> String {
207 let label = paint(format!("{label:>VERB_COLUMN$}"));
208 if msg.is_empty() {
209 format!("{prefix}{label}")
210 } else {
211 format!("{prefix}{label} {msg}")
212 }
213}
214
215/// Width of the right-aligned verb column in [`StageLogger::step`],
216/// matching Cargo's ` Compiling foo` look (3 leading spaces + 9-char
217/// verb = a 12-column gutter before the message).
218const VERB_COLUMN: usize = 12;
219
220/// Indent (after any section nesting) of a body line — a [`StageLogger::detail`]
221/// / [`success`] / [`failure`] / [`kv`] row, or a status label. Three spaces
222/// place the marker column one stop in from the section header's text, so body
223/// lines read as subordinate to the header above them.
224///
225/// [`success`]: StageLogger::success
226/// [`failure`]: StageLogger::failure
227/// [`kv`]: StageLogger::kv
228const BODY_INDENT: &str = " ";
229
230/// Marker for an info / detail body line (`•`). Rendered cyan.
231const MARKER_DETAIL: &str = "•";
232
233/// Marker for a success body line (`✓`). Rendered green.
234const MARKER_SUCCESS: &str = "✓";
235
236/// Marker for a failure body line (`✗`). Rendered red.
237const MARKER_FAILURE: &str = "✗";
238
239/// Map a pipeline stage name to its full Cargo-style header phrase
240/// (`"Building binaries"`, `"Signing artifacts"`, `"Publishing"`). Drives
241/// [`StageLogger::group`]'s deferred header: the leading verb is right-aligned
242/// into the [`VERB_COLUMN`] gutter (bold-green, matching `cargo`'s
243/// ` Compiling foo` look), and the remaining words form the message that
244/// follows. A single-word phrase (`"Publishing"`) renders just the gutter
245/// verb with no trailing message.
246///
247/// The phrase is a *readable description* of the work, not an echo of the
248/// stage name — `group("build")` reads ` Building binaries`, not
249/// ` Building build`. This keeps the continuous log scannable: a reader
250/// sees what each section does, not the internal stage identifier.
251///
252/// Falls back to `"Running <stage>"` for any stage without a bespoke
253/// phrase, so a newly-added stage still renders in the system vocabulary
254/// (` Running myfancystage`) without a code change here.
255pub fn stage_header(stage: &str) -> &'static str {
256 match stage {
257 "setup" => "Preparing release",
258 "build" => "Building binaries",
259 "archive" => "Creating archives",
260 "checksum" => "Computing checksums",
261 "sbom" => "Cataloging dependencies",
262 "templatefiles" => "Rendering templates",
263 "changelog" => "Generating changelog",
264 "attest" => "Generating attestations",
265 "binary-sign" => "Signing binaries",
266 "sign" => "Signing artifacts",
267 "docker" => "Building images",
268 "docker-sign" => "Signing images",
269 "upx" => "Compressing binaries",
270 "nfpm" => "Building packages",
271 "snapcraft" => "Building snap",
272 "flatpak" => "Building Flatpak",
273 "msi" => "Building MSI",
274 "nsis" => "Building installer",
275 "dmg" => "Building DMG",
276 "pkg" => "Building pkg",
277 "notarize" => "Notarizing app",
278 "makeself" => "Building installer",
279 "srpm" => "Building source RPM",
280 "appbundle" => "Building app bundle",
281 "appimage" => "Building AppImage",
282 "universal" => "Merging binaries",
283 "source" => "Archiving source",
284 "release" => "Creating release",
285 "before-publish" => "Preparing publishers",
286 "emission-validate" => "Validating output",
287 "publish" => "Publishing",
288 "blob" => "Uploading blobs",
289 "snapcraft-publish" => "Publishing snap",
290 "announce" => "Announcing release",
291 "verify-release" => "Verifying release",
292 "publisher-summary" => "Summary",
293 "check-determinism" => "Checking determinism",
294 "finalize" => "Finalizing",
295 "prepare" => "Preparing",
296 _ => "Running",
297 }
298}
299
300/// Render the themed `Warning` line for `msg`: the label right-aligned in the
301/// gutter (bold-yellow, no colon) at the current section indent, so it reads as
302/// a peer of the section verbs and its message aligns with theirs. The single
303/// source of truth for the warning palette and label, shared by
304/// [`StageLogger::warn`] and the CLI's tracing formatter so a library-side
305/// `warn!` looks identical to a logger warn (one output authority).
306pub fn render_warning(msg: &str) -> String {
307 render_gutter(&indent(), "Warning", |s| s.yellow().bold(), msg)
308}
309
310/// Render the themed `Error` line for `msg` — gutter-aligned bold-red label,
311/// companion to [`render_warning`]; shared so the error palette/label lives in
312/// exactly one place.
313pub fn render_error(msg: &str) -> String {
314 render_gutter(&indent(), "Error", |s| s.red().bold(), msg)
315}
316
317/// Render the themed `Note` line for `msg`: gutter-aligned bold-green label.
318/// The third status label — informational lines that are neither warnings nor
319/// errors (host-target selection, auto-snapshot activation). The bold-green
320/// deliberately matches the section-verb palette (not yellow/red): a note is a
321/// neutral peer of the section headers, not an alert. Shared so the `Note`
322/// palette/label lives in exactly one place rather than being open-coded per
323/// call site.
324pub fn render_note(msg: &str) -> String {
325 render_gutter(&indent(), "Note", |s| s.green().bold(), msg)
326}
327
328/// Current indentation prefix (2 spaces per open section). Empty at the
329/// top level. Applied identically everywhere — including under GitHub
330/// Actions, where the indentation (not a collapsible `::group::` block) is
331/// what conveys section nesting, matching the continuous single-stream log
332/// GoReleaser emits.
333///
334/// Exposed so the CLI's loggerless `tracing` warning formatter can apply
335/// the same indent a library warn fired mid-stage would otherwise lack,
336/// keeping it aligned with the surrounding body lines.
337pub fn indent() -> String {
338 " ".repeat(current_depth())
339}
340
341/// RAII guard returned by [`indent_one_level`]. Removes the extra indent
342/// level when dropped.
343#[must_use = "dropping the guard immediately removes the extra indent"]
344pub struct IndentGuard {
345 _private: (),
346}
347
348impl Drop for IndentGuard {
349 fn drop(&mut self) {
350 SECTION_DEPTH.fetch_sub(1, Ordering::Relaxed);
351 }
352}
353
354/// Deepen the body indent by one level WITHOUT opening a section header.
355///
356/// For rows that must align with the body bullets of sibling sections
357/// while no section is open — e.g. the pipeline's consolidated
358/// `skipped a, b, c` row, which prints between stage sections (the
359/// previous stage's guard has already dropped) but should sit at the
360/// same column as those sections' own `•` lines instead of two columns
361/// to their left. Unlike [`StageLogger::group`] this pushes no pending
362/// header, so nothing extra ever prints.
363pub fn indent_one_level() -> IndentGuard {
364 SECTION_DEPTH.fetch_add(1, Ordering::Relaxed);
365 IndentGuard { _private: () }
366}
367
368/// RAII guard returned by [`StageLogger::group`]. Closes the section
369/// (decrements the indent depth) when dropped, so a stage's body
370/// indentation is always balanced even if the stage bails early with `?`.
371#[must_use = "dropping the guard immediately ends the section"]
372pub struct SectionGuard {
373 _private: (),
374}
375
376impl Drop for SectionGuard {
377 fn drop(&mut self) {
378 // Take the PENDING lock BEFORE decrementing the depth: a
379 // flush_pending observer on another thread serializes on this
380 // lock, so it sees the depth decrement and the pop as one
381 // transition instead of a window where the depth is already
382 // lowered but the section's pending header is still queued.
383 let mut pending = PENDING.lock().unwrap_or_else(|e| e.into_inner());
384 SECTION_DEPTH.fetch_sub(1, Ordering::Relaxed);
385 // Remove this section's pending entry (LIFO matches nesting). An
386 // unflushed entry means the section emitted no body line — a no-op
387 // stage — so dropping it without printing is exactly the desired
388 // "no-op stages print nothing" behavior.
389 pending.pop();
390 }
391}
392
393/// Level of a log line captured by a [`LogCapture`]. Mirrors the
394/// [`StageLogger`] methods that produce each level.
395///
396/// Gated behind the `test-helpers` Cargo feature — production binaries
397/// do not link the capture infrastructure.
398#[cfg(feature = "test-helpers")]
399#[derive(Debug, Clone, Copy, PartialEq, Eq)]
400pub enum LogLevel {
401 Error,
402 Warn,
403 Status,
404 Verbose,
405 Debug,
406}
407
408/// In-memory sink that records every log line a [`StageLogger`] emits.
409///
410/// Cheap clone (`Arc<Mutex<Vec<…>>>` underneath) — pass the same handle to
411/// every logger derived from a [`crate::context::Context`] and read aggregated
412/// counts back via the accessor methods. Intended for tests that need to
413/// assert "publisher emitted ≥N status lines" — calls still write to stderr
414/// so test output stays debuggable.
415///
416/// Gated behind the `test-helpers` Cargo feature.
417#[cfg(feature = "test-helpers")]
418#[derive(Clone, Default)]
419pub struct LogCapture {
420 inner: Arc<Mutex<Vec<(LogLevel, String)>>>,
421}
422
423#[cfg(feature = "test-helpers")]
424impl LogCapture {
425 /// Construct a fresh empty capture sink.
426 pub fn new() -> Self {
427 Self::default()
428 }
429
430 /// Append a log line to the capture vec. Called from the
431 /// [`StageLogger`] methods when a capture is attached.
432 pub(crate) fn record(&self, level: LogLevel, msg: impl Into<String>) {
433 if let Ok(mut guard) = self.inner.lock() {
434 guard.push((level, msg.into()));
435 }
436 }
437
438 /// Number of [`LogLevel::Status`] lines recorded.
439 pub fn status_count(&self) -> usize {
440 self.count(LogLevel::Status)
441 }
442
443 /// Number of [`LogLevel::Debug`] lines recorded.
444 pub fn debug_count(&self) -> usize {
445 self.count(LogLevel::Debug)
446 }
447
448 /// Number of [`LogLevel::Verbose`] lines recorded.
449 pub fn verbose_count(&self) -> usize {
450 self.count(LogLevel::Verbose)
451 }
452
453 /// Number of [`LogLevel::Warn`] lines recorded.
454 pub fn warn_count(&self) -> usize {
455 self.count(LogLevel::Warn)
456 }
457
458 /// Number of [`LogLevel::Error`] lines recorded.
459 pub fn error_count(&self) -> usize {
460 self.count(LogLevel::Error)
461 }
462
463 /// Total count across all levels (useful sanity check).
464 pub fn total_count(&self) -> usize {
465 self.inner.lock().map(|g| g.len()).unwrap_or(0)
466 }
467
468 fn count(&self, level: LogLevel) -> usize {
469 self.inner
470 .lock()
471 .map(|g| g.iter().filter(|(l, _)| *l == level).count())
472 .unwrap_or(0)
473 }
474
475 /// Snapshot of every recorded line in insertion order.
476 pub fn all_messages(&self) -> Vec<(LogLevel, String)> {
477 self.inner.lock().map(|g| g.clone()).unwrap_or_default()
478 }
479
480 /// Snapshot of every [`LogLevel::Warn`] message in insertion order.
481 ///
482 /// Convenience accessor for tests that care only about warns — strips
483 /// the level tuple [`all_messages`] returns so callers can write
484 /// `cap.warn_messages().iter().any(|m| m.contains("..."))` without
485 /// the per-call filter+map boilerplate.
486 ///
487 /// [`all_messages`]: Self::all_messages
488 pub fn warn_messages(&self) -> Vec<String> {
489 self.inner
490 .lock()
491 .map(|g| {
492 g.iter()
493 .filter(|(lvl, _)| *lvl == LogLevel::Warn)
494 .map(|(_, m)| m.clone())
495 .collect()
496 })
497 .unwrap_or_default()
498 }
499}
500
501/// Verbosity level, derived from CLI flags.
502#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Default)]
503pub enum Verbosity {
504 Quiet,
505 #[default]
506 Normal,
507 Verbose,
508 Debug,
509}
510
511impl Verbosity {
512 /// Derive verbosity from CLI flag combination.
513 /// `--quiet` overrides `--verbose`; `--debug` overrides everything.
514 pub fn from_flags(quiet: bool, verbose: bool, debug: bool) -> Self {
515 if debug {
516 Verbosity::Debug
517 } else if quiet {
518 Verbosity::Quiet
519 } else if verbose {
520 Verbosity::Verbose
521 } else {
522 Verbosity::Normal
523 }
524 }
525}
526
527/// Stage logger: wraps a stage name, verbosity level, and an optional
528/// env-pairs list used for secret redaction.
529///
530/// All output goes to stderr. Create one per stage via [`StageLogger::new`].
531/// Prefer `Context::logger("name")` over `StageLogger::new` when a
532/// `Context` is in scope, because it carries the env automatically.
533///
534/// ```rust,ignore
535/// let log = ctx.logger("build"); // env pre-populated
536/// let log = StageLogger::new("build", verbosity) // no env yet
537/// .with_env(env_pairs); // attach env for redact
538/// log.status("compiling for x86_64-unknown-linux-gnu");
539/// log.verbose(&format!("RUSTFLAGS={}", flags));
540/// log.debug(&format!("full env = {:?}", env));
541/// ```
542#[derive(Clone)]
543pub struct StageLogger {
544 /// The logger's stage identity. No longer printed (the per-line
545 /// `[stage]` tag was dropped for the unified body style — section
546 /// headers name the stage instead), but retained as the constructor
547 /// contract: callers build a logger per stage via [`Self::new`] /
548 /// [`crate::context::Context::logger`] and retag sub-sections via
549 /// [`Self::with_stage`]. Kept so those entry points keep a stable
550 /// signature.
551 #[allow(dead_code)]
552 stage: &'static str,
553 verbosity: Verbosity,
554 /// Env-pairs used to redact subprocess output and bail messages. The
555 /// inner vec is shared via `Arc` so cloning a logger does not copy the
556 /// env every time. `None` means redaction is a no-op (matches the
557 /// behaviour before this field existed).
558 env: Option<Arc<Vec<(String, String)>>>,
559 /// Optional in-memory capture sink. When present, every log method also
560 /// appends to the capture vec (after the stderr write). `None` means
561 /// the logger only writes to stderr (production default).
562 ///
563 /// Gated behind the `test-helpers` Cargo feature — production binaries
564 /// do not carry the field, so no per-log-call `is_none()` check fires.
565 #[cfg(feature = "test-helpers")]
566 capture: Option<LogCapture>,
567}
568
569impl StageLogger {
570 pub fn new(stage: &'static str, verbosity: Verbosity) -> Self {
571 Self {
572 stage,
573 verbosity,
574 env: None,
575 #[cfg(feature = "test-helpers")]
576 capture: None,
577 }
578 }
579
580 /// Construct a logger backed by an in-memory [`LogCapture`] alongside the
581 /// usual stderr writes. Returns the logger plus a clone of the capture
582 /// handle so the test can read counts back after the SUT runs.
583 ///
584 /// Intended exclusively for tests — production code uses
585 /// [`StageLogger::new`] or [`crate::context::Context::logger`].
586 ///
587 /// Gated behind the `test-helpers` Cargo feature.
588 #[cfg(feature = "test-helpers")]
589 pub fn with_capture(stage: &'static str, verbosity: Verbosity) -> (Self, LogCapture) {
590 let capture = LogCapture::new();
591 let logger = Self {
592 stage,
593 verbosity,
594 env: None,
595 capture: Some(capture.clone()),
596 };
597 (logger, capture)
598 }
599
600 /// Attach an existing [`LogCapture`] to this logger. Useful when the
601 /// capture is owned by a [`crate::context::Context`] and every derived
602 /// logger should append to the same vec.
603 ///
604 /// Gated behind the `test-helpers` Cargo feature.
605 #[cfg(feature = "test-helpers")]
606 pub fn with_capture_handle(mut self, capture: LogCapture) -> Self {
607 self.capture = Some(capture);
608 self
609 }
610
611 /// Attach an env-pairs list to drive secret redaction inside
612 /// [`StageLogger::check_output`] and [`StageLogger::redact`]. The list
613 /// is shared via `Arc`, so passing the same vec to many loggers does
614 /// not duplicate the underlying storage.
615 pub fn with_env(mut self, env: Vec<(String, String)>) -> Self {
616 self.env = Some(Arc::new(env));
617 self
618 }
619
620 /// Derive a clone of this logger tagged for a different `stage`, keeping
621 /// verbosity, the (Arc-shared) redaction env, and any capture sink.
622 ///
623 /// The pipeline driver owns one `[release]`-tagged logger but brackets
624 /// sub-sections (`setup`, `finalize`, `publisher-summary`) with their own
625 /// `group()`. Body lines emitted inside such a section must carry the
626 /// *section's* tag, not `[release]`, or the output reads
627 /// `[release] wrote …` underneath `::group::finalize`. Retagging once at
628 /// the section boundary lets every helper called within the section emit
629 /// under the correct tag without threading an explicit `stage` argument
630 /// through each call.
631 pub fn with_stage(&self, stage: &'static str) -> Self {
632 Self {
633 stage,
634 verbosity: self.verbosity,
635 env: self.env.clone(),
636 #[cfg(feature = "test-helpers")]
637 capture: self.capture.clone(),
638 }
639 }
640
641 /// Redact secret values from `s` using this logger's attached env.
642 ///
643 /// When no env has been attached (the default for `StageLogger::new`),
644 /// returns the input unchanged. Combines `redact::string` (for
645 /// known-secret env values) with `redact::redact_url_credentials`
646 /// (for inline `https://<user>:<pass>@host` URL credentials that may
647 /// not match any exported env-var value).
648 pub fn redact(&self, s: &str) -> String {
649 match self.env.as_deref() {
650 Some(env) => crate::redact::with_env(s, env),
651 None => crate::redact::redact_url_credentials(s),
652 }
653 }
654
655 /// Render a body line: the current section indent, the 3-space body
656 /// indent, a colored `marker`, one space, then `text`. The single source
657 /// of truth for the `•` / `✓` / `✗` body register so every marker line
658 /// aligns byte-identically under its section header.
659 fn render_body(marker: &str, text: &str) -> String {
660 format!("{}{}{} {}", indent(), BODY_INDENT, marker, text)
661 }
662
663 /// Error message — always shown (even in quiet mode). Renders the
664 /// `Error` status label gutter-aligned beneath the current section.
665 pub fn error(&self, msg: &str) {
666 flush_pending();
667 eprintln!("{}", render_error(msg));
668 #[cfg(feature = "test-helpers")]
669 if let Some(cap) = &self.capture {
670 cap.record(LogLevel::Error, msg);
671 }
672 }
673
674 /// Warning message — shown at Normal and above. Renders the `Warning`
675 /// status label gutter-aligned beneath the current section.
676 pub fn warn(&self, msg: &str) {
677 if self.verbosity >= Verbosity::Normal {
678 flush_pending();
679 eprintln!("{}", render_warning(msg));
680 }
681 #[cfg(feature = "test-helpers")]
682 if let Some(cap) = &self.capture {
683 cap.record(LogLevel::Warn, msg);
684 }
685 }
686
687 /// Status message — shown at Normal and above. This is the default level
688 /// for key actions (stage start, completion, skips, dry-run notes).
689 ///
690 /// Renders as a `•` detail body line beneath the current section. An
691 /// empty `msg` is preserved as a bare blank spacer line (no marker, no
692 /// indent) so callers using `status("")` for vertical rhythm keep a
693 /// clean blank even inside a group. For an explicit register, prefer
694 /// [`Self::detail`] / [`Self::success`] / [`Self::failure`].
695 pub fn status(&self, msg: &str) {
696 if self.verbosity >= Verbosity::Normal {
697 if msg.is_empty() {
698 // A marker on a "blank" line would render as a stray bullet;
699 // emit a truly empty line to preserve the caller's rhythm.
700 // A blank spacer is NOT a real body line, so it does not flush
701 // pending headers (a no-op section must stay invisible).
702 eprintln!();
703 } else {
704 flush_pending();
705 eprintln!(
706 "{}",
707 Self::render_body(&MARKER_DETAIL.cyan().to_string(), msg)
708 );
709 }
710 }
711 #[cfg(feature = "test-helpers")]
712 if let Some(cap) = &self.capture {
713 cap.record(LogLevel::Status, msg);
714 }
715 }
716
717 /// Info / detail body line — a cyan `•` marker, then `msg`, at the body
718 /// indent beneath the current section. Shown at Normal and above. The
719 /// explicit-register sibling of [`Self::status`] for callers that want to
720 /// name the `•` style directly.
721 pub fn detail(&self, msg: &str) {
722 if self.verbosity >= Verbosity::Normal {
723 flush_pending();
724 eprintln!(
725 "{}",
726 Self::render_body(&MARKER_DETAIL.cyan().to_string(), msg)
727 );
728 }
729 #[cfg(feature = "test-helpers")]
730 if let Some(cap) = &self.capture {
731 cap.record(LogLevel::Status, msg);
732 }
733 }
734
735 /// Success body line — a green `✓` marker, then `msg`, at the body indent
736 /// beneath the current section. Shown at Normal and above. Use for a
737 /// completed unit of work (`✓ x86_64-… 1.2 MiB`, `✓ signed 6 artifacts`).
738 pub fn success(&self, msg: &str) {
739 if self.verbosity >= Verbosity::Normal {
740 flush_pending();
741 eprintln!(
742 "{}",
743 Self::render_body(&MARKER_SUCCESS.green().to_string(), msg)
744 );
745 }
746 #[cfg(feature = "test-helpers")]
747 if let Some(cap) = &self.capture {
748 cap.record(LogLevel::Status, msg);
749 }
750 }
751
752 /// Failure body line — a red `✗` marker, then `msg`, at the body indent
753 /// beneath the current section. Shown at Normal and above. Use for a
754 /// failed unit of work that is reported inline (the run continues or the
755 /// error is surfaced separately via [`Self::error`]).
756 pub fn failure(&self, msg: &str) {
757 if self.verbosity >= Verbosity::Normal {
758 flush_pending();
759 eprintln!(
760 "{}",
761 Self::render_body(&MARKER_FAILURE.red().to_string(), msg)
762 );
763 }
764 #[cfg(feature = "test-helpers")]
765 if let Some(cap) = &self.capture {
766 cap.record(LogLevel::Status, msg);
767 }
768 }
769
770 /// Key/value meta row — a `•` detail line whose lowercase dimmed `key` is
771 /// left-padded to `key_width` so the values line up within a group, then
772 /// the `value`. Shown at Normal and above.
773 ///
774 /// Lowercase keys must never sit in the verb gutter (that column is for
775 /// bold capitalized verbs only), so meta rows render in the body
776 /// register. Callers that emit several rows pass the width of their
777 /// widest key as `key_width` so the values share a column:
778 ///
779 /// ```rust,ignore
780 /// let w = ["targets", "stages", "runs"].iter().map(|k| k.len()).max().unwrap();
781 /// log.kv("targets", "aarch64-pc-windows-msvc", w);
782 /// log.kv("stages", "build, source, sign", w);
783 /// log.kv("runs", "2", w);
784 /// // • targets aarch64-pc-windows-msvc
785 /// // • stages build, source, sign
786 /// // • runs 2
787 /// ```
788 pub fn kv(&self, key: &str, value: &str, key_width: usize) {
789 if self.verbosity >= Verbosity::Normal {
790 // Pad the PLAIN key to width before coloring — padding the
791 // already-dimmed string would count the ANSI escape bytes toward
792 // the field width and misalign the value column. Two spaces after
793 // the padded key give a readable gutter without a separator glyph.
794 let padded = format!("{key:<key_width$}");
795 let row = format!("{} {}", padded.dimmed(), value);
796 flush_pending();
797 eprintln!(
798 "{}",
799 Self::render_body(&MARKER_DETAIL.cyan().to_string(), &row)
800 );
801 }
802 #[cfg(feature = "test-helpers")]
803 if let Some(cap) = &self.capture {
804 cap.record(LogLevel::Status, format!("{key} = {value}"));
805 }
806 }
807
808 /// Cargo-style status line: a capitalized, right-aligned, bold-green
809 /// `verb` in a fixed-width gutter followed by `msg`
810 /// (` Building binaries`, ` Signing artifacts`). Shown at Normal and
811 /// above. Use for section/stage headers where there is a natural
812 /// verb; plain key-action lines stay on [`StageLogger::status`].
813 pub fn step(&self, verb: &str, msg: &str) {
814 if self.verbosity >= Verbosity::Normal {
815 eprintln!("{}", render_header(current_depth(), verb, msg));
816 }
817 #[cfg(feature = "test-helpers")]
818 if let Some(cap) = &self.capture {
819 cap.record(LogLevel::Status, msg);
820 }
821 }
822
823 /// Open a log section for stage `title`.
824 ///
825 /// The Cargo-style header (derived from [`stage_header`]: the phrase's
826 /// leading verb bold-green and right-aligned in the [`VERB_COLUMN`]
827 /// gutter, then one space and the remaining words — ` Building binaries`,
828 /// ` Publishing` for a single-word phrase) is *deferred*: it prints only
829 /// when this section emits its first real body line, matching GoReleaser
830 /// (a section header appears only once the section has output). A stage
831 /// that does nothing therefore prints no header at all — no bare
832 /// `Verifying release` over an empty body. The header renders identically
833 /// everywhere — locally and under GitHub Actions — because anodizer streams
834 /// one continuous log; the body indentation (not a collapsible `::group::`
835 /// block) conveys nesting. Every subsequent log line is indented two spaces
836 /// until the guard drops. Sections nest.
837 ///
838 /// ```rust,ignore
839 /// let _section = log.group("build"); // header pending…
840 /// log.status("compiling x86_64-unknown-linux-gnu"); // Building binaries
841 /// // • compiling …
842 /// // section closes here as `_section` drops
843 /// ```
844 #[must_use = "the section stays open only while the guard is alive"]
845 pub fn group(&self, title: &str) -> SectionGuard {
846 // Defer the header: push it onto the pending stack at the CURRENT depth
847 // (before incrementing) and print it only when this section actually
848 // emits a body line via `flush_pending`. A stage that does nothing
849 // therefore prints no header at all.
850 let (verb, msg) = self.split_header(title);
851 let mut pending = PENDING.lock().unwrap_or_else(|e| e.into_inner());
852 pending.push(PendingHeader {
853 depth: current_depth(),
854 verb: verb.to_string(),
855 msg: msg.to_string(),
856 flushed: false,
857 });
858 // Track depth even at Quiet verbosity so any line that DOES print
859 // (errors) indents correctly and the guard's decrement is balanced.
860 SECTION_DEPTH.fetch_add(1, Ordering::Relaxed);
861 SectionGuard { _private: () }
862 }
863
864 /// Split a stage's [`stage_header`] phrase into the `(verb, message)`
865 /// pair [`Self::group`] feeds to [`Self::step`]. The verb is everything
866 /// up to the first space; the message is the remainder (empty for a
867 /// single-word phrase, which renders as a bare gutter verb). An unknown
868 /// stage (default `"Running"`) takes the stage name itself as the
869 /// message, so it reads ` Running myfancystage`.
870 fn split_header<'a>(&self, title: &'a str) -> (&'a str, &'a str) {
871 let phrase = stage_header(title);
872 match phrase.split_once(' ') {
873 Some((verb, rest)) => (verb, rest),
874 // Single-word phrase: the default "Running" echoes the stage name
875 // as its object; any other single word renders verb-only.
876 None if phrase == "Running" => (phrase, title),
877 None => (phrase, ""),
878 }
879 }
880
881 /// Detail message — shown only at Verbose and above. Renders as a `•`
882 /// detail body line beneath the current section.
883 /// Use for: command output on success, env vars, file paths, template vars.
884 pub fn verbose(&self, msg: &str) {
885 if self.verbosity >= Verbosity::Verbose {
886 flush_pending();
887 eprintln!(
888 "{}",
889 Self::render_body(&MARKER_DETAIL.cyan().to_string(), msg)
890 );
891 }
892 #[cfg(feature = "test-helpers")]
893 if let Some(cap) = &self.capture {
894 cap.record(LogLevel::Verbose, msg);
895 }
896 }
897
898 /// Debug message — shown only at Debug level. Renders as a dimmed `•`
899 /// detail body line beneath the current section.
900 /// Use for: HTTP request/response details, full template contexts, resolved config.
901 pub fn debug(&self, msg: &str) {
902 if self.verbosity >= Verbosity::Debug {
903 flush_pending();
904 eprintln!(
905 "{}",
906 Self::render_body(
907 &MARKER_DETAIL.dimmed().to_string(),
908 &msg.dimmed().to_string()
909 )
910 );
911 }
912 #[cfg(feature = "test-helpers")]
913 if let Some(cap) = &self.capture {
914 cap.record(LogLevel::Debug, msg);
915 }
916 }
917
918 /// Emit a per-crate "no `<publisher>` config block" skip line at the
919 /// verbosity the operator asked for.
920 ///
921 /// These lines fire once per non-applicable crate in workspace mode (every
922 /// PR-based publisher visits every selected crate and skips the ones whose
923 /// config lacks its block), so at default verbosity they would bury the
924 /// real output under hundreds of lines of pure no-op noise. They are routed
925 /// to [`Self::debug`] (invisible at default and `--verbose`, visible at
926 /// `--debug`) unless `show` is set — `--show-skipped`, the diagnostic
927 /// escape hatch for "why didn't publisher X run for crate Y?" — in which
928 /// case they surface at [`Self::status`] like any other key action.
929 pub fn skip_line(&self, show: bool, msg: &str) {
930 if show {
931 self.status(msg);
932 } else {
933 self.debug(msg);
934 }
935 }
936
937 /// Return the current verbosity level.
938 pub fn verbosity(&self) -> Verbosity {
939 self.verbosity
940 }
941
942 /// Snapshot this logger's redaction env-pairs (empty when none is
943 /// attached). Lets a caller construct a sibling logger at a different
944 /// verbosity while preserving the same secret-redaction policy — e.g. the
945 /// blob KMS path, which runs its encrypt subprocesses through a
946 /// Normal-verbosity clone so ciphertext is never teed live, yet must keep
947 /// the original logger's redaction coverage.
948 pub fn redaction_env(&self) -> Vec<(String, String)> {
949 self.env.as_deref().cloned().unwrap_or_default()
950 }
951
952 /// Check if verbose output is enabled.
953 pub fn is_verbose(&self) -> bool {
954 self.verbosity >= Verbosity::Verbose
955 }
956
957 /// Check if debug output is enabled.
958 pub fn is_debug(&self) -> bool {
959 self.verbosity >= Verbosity::Debug
960 }
961
962 /// Tee a single line of a child process's standard output to this
963 /// process's STDERR, unmodified except for secret redaction.
964 ///
965 /// Used by the verbose live-stream in [`crate::run::run_checked`]: long
966 /// tools (cargo, snapcraft, nix-build) show progress as they run. Unlike
967 /// the marker-prefixed body register ([`Self::verbose`]), the line is
968 /// written *raw* — no `•` marker, no section indent — so the streamed
969 /// output looks exactly as the tool produced it, matching a tee.
970 ///
971 /// The tee goes to **stderr**, not stdout: anodizer's stdout is a
972 /// machine-readable data channel (GHA step outputs like `new_tag=…`, plus
973 /// json/changelog/metadata payloads), and a hook's child stdout teed onto
974 /// stdout would corrupt it. Progress UX belongs on stderr with every other
975 /// human/log line. Recorded into any attached [`LogCapture`] at
976 /// [`LogLevel::Verbose`] so tests can assert the stream surfaced.
977 ///
978 /// `line` must be a single line with its trailing newline already
979 /// stripped (the caller's line reader does this); the newline is added
980 /// here by `eprintln!`.
981 pub fn stream_child_stdout(&self, line: &str) {
982 self.stream_child_line(line, false);
983 }
984
985 /// Tee a single line of a child process's standard error to this
986 /// process's stderr, unmodified except for secret redaction. The stderr
987 /// companion to [`Self::stream_child_stdout`]; recorded at
988 /// [`LogLevel::Error`] so the verbose-failure double-emit guard is
989 /// observable in tests.
990 pub fn stream_child_stderr(&self, line: &str) {
991 self.stream_child_line(line, true);
992 }
993
994 /// Shared body of [`stream_child_stdout`](Self::stream_child_stdout) and
995 /// [`stream_child_stderr`](Self::stream_child_stderr): flush any deferred
996 /// section header, write the redacted line to stderr, and record it.
997 /// Both child streams tee to stderr (see
998 /// [`stream_child_stdout`](Self::stream_child_stdout)); the methods differ
999 /// only in which capture level the line is recorded under
1000 /// (`from_stderr` selects [`LogLevel::Error`] vs [`LogLevel::Verbose`]),
1001 /// so the write lives here once.
1002 ///
1003 /// `flush_pending()` runs first so a streamed line never prints *above* its
1004 /// deferred section header — the same header-before-body ordering every
1005 /// other body-line emitter (`verbose` / `status` / `error` / `debug`)
1006 /// upholds.
1007 fn stream_child_line(&self, line: &str, from_stderr: bool) {
1008 let redacted = self.redact(line);
1009 flush_pending();
1010 eprintln!("{redacted}");
1011 #[cfg(feature = "test-helpers")]
1012 if let Some(cap) = &self.capture {
1013 let level = if from_stderr {
1014 LogLevel::Error
1015 } else {
1016 LogLevel::Verbose
1017 };
1018 cap.record(level, redacted);
1019 }
1020 #[cfg(not(feature = "test-helpers"))]
1021 let _ = from_stderr;
1022 }
1023
1024 /// Check command output, log stderr/stdout on failure, and bail with context.
1025 /// On success, log stdout at verbose level. Returns `Ok(output)` on success.
1026 ///
1027 /// Stderr and stdout are passed through [`StageLogger::redact`] before
1028 /// they reach the log sink, so any secret env-var values present in the
1029 /// subprocess output are replaced with `$KEY_NAME` (and inline
1030 /// `https://<user>:<pass>@host` URL credentials are scrubbed) without
1031 /// callers having to remember to redact at each call site. Mirrors
1032 /// a safe-stderr pattern at every subprocess
1033 /// boundary.
1034 pub fn check_output(
1035 &self,
1036 output: std::process::Output,
1037 label: &str,
1038 ) -> anyhow::Result<std::process::Output> {
1039 self.check_output_inner(output, label, false)
1040 }
1041
1042 /// Like [`StageLogger::check_output`], but for callers that already
1043 /// streamed the child's stdout/stderr live (the verbose tee in
1044 /// [`crate::run::run_checked`]). Suppresses the stderr/stdout re-emit
1045 /// — both on the success-verbose path and the failure path — so output
1046 /// that was teed line-by-line is not printed a second time. The
1047 /// `bail!` embed (tail-truncated, redacted stderr in the error chain)
1048 /// is preserved unchanged, so error-chain consumers still see context.
1049 pub fn check_output_streamed(
1050 &self,
1051 output: std::process::Output,
1052 label: &str,
1053 ) -> anyhow::Result<std::process::Output> {
1054 self.check_output_inner(output, label, true)
1055 }
1056
1057 /// Shared body of [`check_output`](Self::check_output) and
1058 /// [`check_output_streamed`](Self::check_output_streamed).
1059 ///
1060 /// `already_streamed` suppresses the stderr/stdout log re-emit (the
1061 /// caller's live tee already wrote those lines), but never the `bail!`
1062 /// embed: an error chain propagated past the logger still carries the
1063 /// redacted, truncated stderr tail regardless of streaming.
1064 fn check_output_inner(
1065 &self,
1066 output: std::process::Output,
1067 label: &str,
1068 already_streamed: bool,
1069 ) -> anyhow::Result<std::process::Output> {
1070 let (stderr_line, stdout_line) = self.format_output_lines(&output, label);
1071 if !output.status.success() {
1072 if !already_streamed {
1073 if let Some(line) = stderr_line {
1074 self.error(&line);
1075 }
1076 if let Some(line) = stdout_line {
1077 self.error(&line);
1078 }
1079 }
1080 // Embed a (truncated, redacted) stderr tail in the bubbled
1081 // error so operators reading the final anyhow chain see
1082 // something more actionable than just an exit code. The
1083 // separately-emitted `log.error` lines above remain the
1084 // primary surface; this is defense in depth for callers
1085 // that propagate the error past the StageLogger context.
1086 let stderr_raw = String::from_utf8_lossy(&output.stderr);
1087 let stderr_tail = if stderr_raw.is_empty() {
1088 String::from("<no stderr>")
1089 } else {
1090 // Strip the child's terminal color codes BEFORE redaction and
1091 // truncation: this tail is bubbled up the anyhow chain and ends
1092 // up in non-terminal sinks (failure-notification emails, the
1093 // on_error hook's $ANODIZER_ERROR, JSON run summaries) where raw
1094 // ANSI renders as garbage around every styled token. Color is
1095 // forced on for child processes so the live CI log stays
1096 // colorized; the persisted error must not inherit it. Stripping
1097 // first also makes the byte cap below count visible content, not
1098 // escape bytes.
1099 let stripped = strip_ansi(&stderr_raw);
1100 let redacted = self.redact(&stripped);
1101 let trimmed = redacted.trim();
1102 // Cap at 2 KiB to keep error chains scannable.
1103 const MAX: usize = 2048;
1104 if trimmed.len() > MAX {
1105 let cut = trimmed
1106 .char_indices()
1107 .nth(MAX)
1108 .map(|(i, _)| i)
1109 .unwrap_or(MAX);
1110 format!("{}…", &trimmed[..cut])
1111 } else {
1112 trimmed.to_string()
1113 }
1114 };
1115 anyhow::bail!(
1116 "{} failed with exit code: {}; stderr: {}",
1117 label,
1118 output.status.code().unwrap_or(-1),
1119 stderr_tail
1120 );
1121 }
1122 if !already_streamed
1123 && self.is_verbose()
1124 && let Some(line) = stdout_line
1125 {
1126 self.verbose(&line);
1127 }
1128 Ok(output)
1129 }
1130
1131 /// Compose the redacted stderr / stdout log lines that
1132 /// [`StageLogger::check_output`] would emit for `output`. Returned as
1133 /// `(stderr_line, stdout_line)` where each `Option` is `Some` only when
1134 /// the corresponding stream had any content. Exposed via
1135 /// `pub(crate)` so the redaction logic can be unit-tested without
1136 /// having to capture stderr (`eprintln!` cannot be intercepted from
1137 /// the same process portably).
1138 pub(crate) fn format_output_lines(
1139 &self,
1140 output: &std::process::Output,
1141 label: &str,
1142 ) -> (Option<String>, Option<String>) {
1143 let stderr_raw = String::from_utf8_lossy(&output.stderr);
1144 let stderr_line = if stderr_raw.is_empty() {
1145 None
1146 } else {
1147 let stderr = self.redact(&stderr_raw);
1148 let prefix = if output.status.success() {
1149 "output"
1150 } else {
1151 "stderr"
1152 };
1153 // Failure messages format stderr separately from stdout (under
1154 // the "stderr" label); success uses one "output" label for
1155 // stdout only.
1156 if output.status.success() {
1157 // success path: stderr is never surfaced through check_output
1158 None
1159 } else {
1160 Some(format!("{label} {prefix}:\n{stderr}"))
1161 }
1162 };
1163 let stdout_raw = String::from_utf8_lossy(&output.stdout);
1164 let stdout_line = if stdout_raw.is_empty() {
1165 None
1166 } else {
1167 let stdout = self.redact(&stdout_raw);
1168 let prefix = if output.status.success() {
1169 "output"
1170 } else {
1171 "stdout"
1172 };
1173 Some(format!("{label} {prefix}:\n{stdout}"))
1174 };
1175 (stderr_line, stdout_line)
1176 }
1177}
1178
1179/// Strip ANSI CSI escape sequences (SGR color codes, cursor moves) from `s`.
1180///
1181/// Captured subprocess output (cargo, gpg, …) carries terminal color codes
1182/// when color is forced for the live CI log. Those bytes must never leak into
1183/// a propagated error message that reaches a non-terminal sink — a failure
1184/// email, the `on_error` hook's `$ANODIZER_ERROR`, a JSON run summary — where
1185/// they render as garbage around every styled token.
1186pub(crate) fn strip_ansi(s: &str) -> String {
1187 let mut out = String::with_capacity(s.len());
1188 let mut chars = s.chars();
1189 while let Some(c) = chars.next() {
1190 if c == '\u{1b}' {
1191 // Only a CSI introducer (`ESC [`) starts a parameterized sequence
1192 // we must consume to its final byte (0x40–0x7E); any other escape
1193 // form (a lone ESC, a two-char sequence) drops just the introducer.
1194 if chars.next() == Some('[') {
1195 for ec in chars.by_ref() {
1196 if ('\u{40}'..='\u{7e}').contains(&ec) {
1197 break;
1198 }
1199 }
1200 }
1201 } else {
1202 out.push(c);
1203 }
1204 }
1205 out
1206}
1207
1208#[cfg(test)]
1209mod tests {
1210 use super::*;
1211
1212 /// Serializes the section-depth tests: `SECTION_DEPTH` is a
1213 /// process-global atomic, so two grouping tests running on parallel
1214 /// threads would observe each other's increments.
1215 static SECTION_TEST_LOCK: Mutex<()> = Mutex::new(());
1216
1217 #[test]
1218 fn test_group_guard_balances_depth_locally() {
1219 // `group()` increments depth on open and the guard decrements on
1220 // drop, so nested sections always balance back to the start depth.
1221 let _guard = SECTION_TEST_LOCK.lock().unwrap();
1222 let log = StageLogger::new("build", Verbosity::Normal);
1223 let start = SECTION_DEPTH.load(Ordering::Relaxed);
1224 {
1225 let _outer = log.group("build");
1226 assert_eq!(SECTION_DEPTH.load(Ordering::Relaxed), start + 1);
1227 {
1228 let _inner = log.group("sign");
1229 assert_eq!(SECTION_DEPTH.load(Ordering::Relaxed), start + 2);
1230 }
1231 assert_eq!(SECTION_DEPTH.load(Ordering::Relaxed), start + 1);
1232 }
1233 assert_eq!(SECTION_DEPTH.load(Ordering::Relaxed), start);
1234 }
1235
1236 #[test]
1237 fn test_group_quiet_still_tracks_local_depth() {
1238 // Even at Quiet verbosity the indent depth must stay balanced so
1239 // any status lines that DO print (errors) indent correctly and the
1240 // guard's decrement has a matching increment.
1241 let _guard = SECTION_TEST_LOCK.lock().unwrap();
1242 let log = StageLogger::new("build", Verbosity::Quiet);
1243 let start = SECTION_DEPTH.load(Ordering::Relaxed);
1244 {
1245 let _s = log.group("build");
1246 assert_eq!(SECTION_DEPTH.load(Ordering::Relaxed), start + 1);
1247 }
1248 assert_eq!(SECTION_DEPTH.load(Ordering::Relaxed), start);
1249 }
1250
1251 #[test]
1252 fn test_group_with_body_flushes_header_once() {
1253 // A section that emits a real body line flushes its deferred header:
1254 // the pending entry is marked `flushed` exactly once and stays at its
1255 // own depth. (`flush_pending` writes the header to stderr; we assert
1256 // the state transition rather than capture the uncapturable eprintln.)
1257 let _guard = SECTION_TEST_LOCK.lock().unwrap();
1258 let log = StageLogger::new("build", Verbosity::Normal);
1259 {
1260 let _section = log.group("build");
1261 // Header is pending, not yet printed.
1262 assert!(!PENDING.lock().unwrap().last().unwrap().flushed);
1263 log.status("compiling x86_64-unknown-linux-gnu");
1264 // The body line flushed the header.
1265 let pending = PENDING.lock().unwrap();
1266 let entry = pending.last().unwrap();
1267 assert!(entry.flushed, "body line must flush the header");
1268 assert_eq!(entry.verb, "Building");
1269 assert_eq!(entry.msg, "binaries");
1270 }
1271 // Guard drop popped the (flushed) entry.
1272 assert!(PENDING.lock().unwrap().is_empty());
1273 }
1274
1275 #[test]
1276 fn test_noop_group_prints_no_header() {
1277 // A section that emits NOTHING leaves its pending entry unflushed, and
1278 // the guard drop pops it without ever printing — a no-op stage shows
1279 // no bare header (the GoReleaser behavior). A blank `status("")` spacer
1280 // is NOT a real body line, so it does not flush either.
1281 let _guard = SECTION_TEST_LOCK.lock().unwrap();
1282 let log = StageLogger::new("verify-release", Verbosity::Normal);
1283 {
1284 let _section = log.group("verify-release");
1285 log.status(""); // blank spacer — must not flush
1286 assert!(
1287 !PENDING.lock().unwrap().last().unwrap().flushed,
1288 "a no-op section's header must stay unflushed"
1289 );
1290 }
1291 assert!(PENDING.lock().unwrap().is_empty());
1292 }
1293
1294 #[test]
1295 fn test_nested_groups_flush_in_ancestor_order() {
1296 // A body line in a nested section flushes BOTH the ancestor and the
1297 // nested header (each at its own stored depth), so the deferred
1298 // headers appear in correct order above the first line.
1299 let _guard = SECTION_TEST_LOCK.lock().unwrap();
1300 let log = StageLogger::new("publish", Verbosity::Normal);
1301 let start = SECTION_DEPTH.load(Ordering::Relaxed);
1302 {
1303 let _outer = log.group("publish");
1304 {
1305 let _inner = log.group("blob");
1306 log.status("uploading blob");
1307 let pending = PENDING.lock().unwrap();
1308 assert_eq!(pending.len(), 2);
1309 assert!(pending[0].flushed, "ancestor header must flush");
1310 assert!(pending[1].flushed, "nested header must flush");
1311 assert_eq!(pending[0].depth, start);
1312 assert_eq!(pending[1].depth, start + 1);
1313 }
1314 }
1315 assert!(PENDING.lock().unwrap().is_empty());
1316 }
1317
1318 /// Run `f` with the process stderr fd (2) redirected to a temp file, then
1319 /// restore it and return everything that reached fd 2 as a string, or
1320 /// `None` if `eprintln!` output is being intercepted before fd 2.
1321 ///
1322 /// `eprintln!` writes through libtest's macro path, which — under a plain
1323 /// in-process `cargo test` — diverts output to a thread-local capture sink
1324 /// BEFORE it reaches fd 2, so an fd swap observes nothing. Under
1325 /// `cargo nextest` (the CI test runner) each test is its own process with a
1326 /// real stderr pipe, so the swap captures the true bytes. A sentinel probe
1327 /// distinguishes the two: if the sentinel does not survive the round-trip,
1328 /// fd 2 is not the real emit target and the caller must fall back.
1329 ///
1330 /// `f` must emit its header as the FIRST line it writes — callers slice the
1331 /// header off with `.lines().next()`, which is only correct because the
1332 /// caller's `group()` defers the header and `flush_pending` writes it ahead
1333 /// of any body line. A change that made `f` emit anything before its header
1334 /// would silently grab the wrong line.
1335 ///
1336 /// Unix-only. The fd-2 swap is process-global across the WHOLE
1337 /// `anodizer-core` test binary, so callers carry the crate-wide unnamed
1338 /// `#[serial_test::serial]` key (the convention in
1339 /// [`crate::test_helpers`]) to mutually exclude against every other
1340 /// env/cwd/fd-mutating test; `SECTION_TEST_LOCK` only orders the in-file
1341 /// `PENDING`/`SECTION_DEPTH` state these callers also touch.
1342 #[cfg(unix)]
1343 fn capture_stderr(f: impl FnOnce()) -> Option<String> {
1344 use std::io::{Read, Seek, SeekFrom, Write};
1345 use std::os::unix::io::AsRawFd;
1346
1347 /// Restores fd 2 from the saved dup on EVERY exit path, including a
1348 /// panic in `f` or the probe between the swap and the read. Without
1349 /// this, an unwind would leave fd 2 pointed at the dropped tempfile, so
1350 /// every later test's panic/`eprintln!` diagnostics in this shared
1351 /// process would write to a dangling fd and vanish.
1352 struct StderrRestore(libc::c_int);
1353 impl Drop for StderrRestore {
1354 fn drop(&mut self) {
1355 // SAFETY: self.0 is the dup of the original stderr taken before
1356 // the swap; restoring it on every exit path (including unwind)
1357 // guarantees fd 2 is never left dangling at the tempfile.
1358 unsafe {
1359 libc::dup2(self.0, libc::STDERR_FILENO);
1360 libc::close(self.0);
1361 }
1362 }
1363 }
1364
1365 let mut file = tempfile::tempfile().expect("tempfile for stderr capture");
1366 std::io::stderr().flush().ok();
1367 // SAFETY: dup/dup2 on the live stderr fd; the saved fd is owned by the
1368 // StderrRestore guard below, which restores fd 2 and closes the dup on
1369 // every exit path (panic-safe). The whole swap is serialized by the
1370 // caller's crate-wide `#[serial]` key.
1371 let saved = unsafe { libc::dup(libc::STDERR_FILENO) };
1372 assert!(saved >= 0, "dup(stderr) failed");
1373 unsafe {
1374 assert!(
1375 libc::dup2(file.as_raw_fd(), libc::STDERR_FILENO) >= 0,
1376 "dup2(tempfile, stderr) failed"
1377 );
1378 }
1379 // Owns `saved` from here on; its Drop restores fd 2 even if `f` panics.
1380 let _restore = StderrRestore(saved);
1381
1382 const SENTINEL: &str = "__anodizer_capture_probe__";
1383 eprintln!("{SENTINEL}");
1384 f();
1385 std::io::stderr().flush().ok();
1386
1387 file.seek(SeekFrom::Start(0)).expect("rewind capture file");
1388 let mut out = String::new();
1389 file.read_to_string(&mut out).expect("read capture file");
1390 // The sentinel survives only when fd 2 is the real emit target (nextest
1391 // / `--nocapture`); under in-process `cargo test` libtest swallowed it
1392 // (and `f`'s output), so the fd capture cannot prove anything.
1393 let body = out.strip_prefix(SENTINEL)?.trim_start_matches('\n');
1394 Some(body.to_string())
1395 }
1396
1397 #[test]
1398 #[cfg(unix)]
1399 #[serial_test::serial]
1400 fn test_header_paths_emit_identical_bytes() {
1401 // Regression guard for the v0.9.1 drift where stage headers rendered
1402 // with 2/3/4/5 leading spaces depending on which path printed them.
1403 //
1404 // This drives the TWO REAL emitting paths — the deferred-section header
1405 // in `flush_pending` and the direct `step` — and asserts they write
1406 // byte-identical headers at the same depth. It compares ACTUAL stderr
1407 // bytes (not `render_header`'s return value), so it FAILS the moment
1408 // either path open-codes its own indent/spacing instead of delegating
1409 // to `render_header`. Under `cargo nextest` (the CI gate) the fd capture
1410 // sees real output; under a bare in-process `cargo test` libtest
1411 // intercepts `eprintln!` and `capture_stderr` returns None, so the body
1412 // falls back to re-checking the shared helper rather than failing
1413 // spuriously. The crate-wide `#[serial]` key keeps every other
1414 // env/fd-mutating test out of the fd-swapped capture; SECTION_TEST_LOCK
1415 // only orders the in-file PENDING/SECTION_DEPTH state.
1416 let _guard = SECTION_TEST_LOCK.lock().unwrap();
1417 let log = StageLogger::new("sign", Verbosity::Normal);
1418 // Absolute depth both paths must render at (includes any inherited base
1419 // from ANODIZER_LOG_DEPTH, so the anchor below shifts with it).
1420 let depth = current_depth();
1421
1422 // flush_pending path: open a section (pending header pushed at `depth`),
1423 // then a body line triggers `flush_pending`, which prints the header.
1424 // The header is the FIRST captured line; the body line follows it.
1425 let flushed = capture_stderr(|| {
1426 let _section = log.group("sign");
1427 assert_eq!(
1428 PENDING.lock().unwrap().last().unwrap().depth,
1429 depth,
1430 "pending header must sit at the pre-increment depth"
1431 );
1432 log.status("byte-equality probe"); // forces flush_pending
1433 });
1434 assert!(
1435 PENDING.lock().unwrap().is_empty(),
1436 "guard must pop the entry"
1437 );
1438
1439 // step path: the section is closed, so `current_depth()` is back to
1440 // `depth` — the same depth the pending header rendered at. `step` emits
1441 // exactly the header line, nothing else.
1442 assert_eq!(current_depth(), depth, "depth must return to start");
1443 let stepped = capture_stderr(|| log.step("Signing", "artifacts"));
1444
1445 let prefix = " ".repeat(depth);
1446 let expected = format!("{prefix}{:>VERB_COLUMN$} artifacts", "Signing");
1447
1448 match (flushed, stepped) {
1449 (Some(flushed), Some(stepped)) => {
1450 let flush_header = strip_ansi(
1451 flushed
1452 .lines()
1453 .next()
1454 .expect("flush_pending must emit a header line"),
1455 );
1456 let step_header = strip_ansi(stepped.trim_end_matches('\n'));
1457 // The whole point: both REAL paths produce the same header
1458 // bytes. If a future edit makes one open-code a different
1459 // indent, these diverge and the test fails.
1460 assert_eq!(
1461 flush_header, step_header,
1462 "flush_pending and step must emit byte-identical headers \
1463 (flush={flush_header:?} step={step_header:?})"
1464 );
1465 // Anchor the shared bytes so a regression that drifts BOTH paths
1466 // in lockstep (still equal to each other) is also caught.
1467 assert_eq!(
1468 step_header, expected,
1469 "header must be indent + gutter verb + space + message"
1470 );
1471 }
1472 // In-process `cargo test`: BOTH swaps were intercepted, so the real
1473 // paths are unobservable here. Re-assert the shared helper so the
1474 // test is not a silent no-op; nextest exercises the real bytes.
1475 (None, None) => {
1476 assert_eq!(
1477 strip_ansi(&render_header(depth, "Signing", "artifacts")),
1478 expected
1479 );
1480 }
1481 // The sentinel survived one swap but not the other — a real capture
1482 // anomaly (a flaky/half-redirected environment), not the documented
1483 // all-or-nothing fallback. Surface it loudly instead of silently
1484 // running the weaker check.
1485 (flushed, stepped) => panic!(
1486 "inconsistent stderr capture: flush={} step={}",
1487 flushed.is_some(),
1488 stepped.is_some()
1489 ),
1490 }
1491 }
1492
1493 #[test]
1494 #[cfg(unix)]
1495 #[serial_test::serial]
1496 fn test_single_word_header_emits_no_trailing_space() {
1497 // A single-word phrase (empty message) renders the bare gutter verb
1498 // with NO trailing space on the REAL `step` path — a stray space here
1499 // would leave invisible whitespace at the end of every `Publishing`
1500 // header line. Drives `step` directly and inspects the emitted bytes.
1501 let _guard = SECTION_TEST_LOCK.lock().unwrap();
1502 let log = StageLogger::new("publish", Verbosity::Normal);
1503 let depth = current_depth();
1504 let prefix = " ".repeat(depth);
1505
1506 match capture_stderr(|| log.step("Publishing", "")) {
1507 Some(stepped) => {
1508 let header = strip_ansi(stepped.trim_end_matches('\n'));
1509 assert_eq!(header, format!("{prefix}{:>VERB_COLUMN$}", "Publishing"));
1510 assert!(
1511 !header.ends_with(' '),
1512 "single-word header must not carry a trailing space: {header:?}"
1513 );
1514 }
1515 // In-process `cargo test` intercepts `eprintln!`; re-assert the
1516 // shared helper so the invariant still has a floor under nextest.
1517 None => {
1518 let header = strip_ansi(&render_header(depth, "Publishing", ""));
1519 assert_eq!(header, format!("{prefix}{:>VERB_COLUMN$}", "Publishing"));
1520 assert!(!header.ends_with(' '));
1521 }
1522 }
1523 }
1524
1525 #[test]
1526 fn test_status_labels_gutter_aligned_without_colon() {
1527 // Regression guard: Warning/Error/Note must render as right-aligned
1528 // gutter labels with NO trailing colon, and their message must land in
1529 // the same column as a section header's message (both follow the
1530 // VERB_COLUMN gutter + one space). The old format open-coded
1531 // "Warning:" at BODY_INDENT, which faked Cargo alignment with an
1532 // anti-Cargo colon.
1533 let header = strip_ansi(&render_header(0, "Building", "binaries"));
1534 let header_msg_col = header.find("binaries");
1535 for (rendered, label, msg) in [
1536 (render_warning("oops"), "Warning", "oops"),
1537 (render_error("boom"), "Error", "boom"),
1538 (render_note("fyi"), "Note", "fyi"),
1539 ] {
1540 let line = strip_ansi(&rendered);
1541 assert!(
1542 !line.contains(':'),
1543 "status label must not carry a colon: {line:?}"
1544 );
1545 // Label lines go through the SAME gutter renderer as section
1546 // headers: stripped of color, a Warning/Error/Note line is
1547 // byte-identical to a header whose verb is that label. Deriving the
1548 // expectation from `render_header` (not a hand-written format)
1549 // proves the shared renderer rather than re-stating its shape.
1550 assert_eq!(line, strip_ansi(&render_header(0, label, msg)));
1551 // Column-invariance across differing label widths: every label's
1552 // message lands in the same column as the "Building" header's,
1553 // regardless of how long the verb is.
1554 assert_eq!(
1555 line.find(msg),
1556 header_msg_col,
1557 "status-label message must align with the header message column"
1558 );
1559 }
1560 }
1561
1562 #[test]
1563 #[cfg(unix)]
1564 #[serial_test::serial]
1565 fn test_capture_stderr_restores_fd_on_panic() {
1566 // The fd-restore must run on the unwind path: a panic inside `f`
1567 // (the asserts in the real callers are a reachable panic path) must
1568 // not leave fd 2 dangling at the dropped tempfile, which would make
1569 // every later test's stderr vanish in the shared process.
1570 let _guard = SECTION_TEST_LOCK.lock().unwrap();
1571 let panicked = std::panic::catch_unwind(std::panic::AssertUnwindSafe(|| {
1572 capture_stderr(|| panic!("boom inside capture"));
1573 }));
1574 assert!(panicked.is_err(), "the injected panic must propagate");
1575
1576 // fd 2 is usable again: a fresh capture round-trips its sentinel. (Under
1577 // in-process `cargo test` the sentinel is swallowed and the result is
1578 // None — still a successful, non-dangling write; only a leaked fd 2
1579 // would corrupt this follow-up capture.)
1580 let after = capture_stderr(|| eprintln!("after panic"));
1581 if let Some(body) = after {
1582 assert!(
1583 body.contains("after panic"),
1584 "stderr must work after a mid-capture panic: {body:?}"
1585 );
1586 }
1587 }
1588
1589 #[test]
1590 fn test_indent_reflects_section_depth() {
1591 // Indentation tracks the open-section depth (2 spaces per level)
1592 // identically everywhere — anodizer streams one continuous log, so
1593 // indentation (not a collapsible `::group::` block) conveys nesting.
1594 let _guard = SECTION_TEST_LOCK.lock().unwrap();
1595 let log = StageLogger::new("build", Verbosity::Normal);
1596 // Relative to the inherited base so an exported ANODIZER_LOG_DEPTH
1597 // in the test environment shifts every expectation uniformly.
1598 let base = " ".repeat(base_depth());
1599 assert_eq!(indent(), base);
1600 {
1601 let _outer = log.group("build");
1602 assert_eq!(indent(), format!("{base} "));
1603 {
1604 let _inner = log.group("sign");
1605 assert_eq!(indent(), format!("{base} "));
1606 }
1607 assert_eq!(indent(), format!("{base} "));
1608 }
1609 assert_eq!(indent(), base);
1610 }
1611
1612 #[test]
1613 fn test_indent_one_level_adds_depth_without_pending_header() {
1614 // The header-less guard must deepen the indent (so the row aligns
1615 // with sibling sections' body bullets) without registering a
1616 // pending header that a later body line could spuriously flush.
1617 let _guard = SECTION_TEST_LOCK.lock().unwrap();
1618 let start = SECTION_DEPTH.load(Ordering::Relaxed);
1619 let pending_before = PENDING.lock().unwrap().len();
1620 {
1621 let _indent = indent_one_level();
1622 assert_eq!(SECTION_DEPTH.load(Ordering::Relaxed), start + 1);
1623 assert_eq!(
1624 PENDING.lock().unwrap().len(),
1625 pending_before,
1626 "indent_one_level must not push a pending header"
1627 );
1628 assert_eq!(indent(), " ".repeat(current_depth()));
1629 }
1630 assert_eq!(SECTION_DEPTH.load(Ordering::Relaxed), start);
1631 }
1632
1633 #[test]
1634 fn test_parse_base_depth_accepts_valid_and_degrades_invalid() {
1635 // A subprocess child inherits a numeric depth; anything else
1636 // (absent, junk, negative) degrades to the standalone default 0 —
1637 // indentation must never abort a run.
1638 assert_eq!(parse_base_depth(Some("3")), 3);
1639 assert_eq!(parse_base_depth(Some(" 2 ")), 2);
1640 assert_eq!(parse_base_depth(Some("0")), 0);
1641 assert_eq!(parse_base_depth(Some("-1")), 0);
1642 assert_eq!(parse_base_depth(Some("abc")), 0);
1643 assert_eq!(parse_base_depth(Some("")), 0);
1644 assert_eq!(parse_base_depth(None), 0);
1645 }
1646
1647 #[test]
1648 fn test_current_depth_tracks_sections() {
1649 // `current_depth` = inherited base (0 in tests — the env var is
1650 // not set under cargo test) + open sections; it is the value a
1651 // parent exports to children via LOG_DEPTH_ENV.
1652 let _guard = SECTION_TEST_LOCK.lock().unwrap();
1653 let log = StageLogger::new("build", Verbosity::Normal);
1654 let start = current_depth();
1655 {
1656 let _outer = log.group("build");
1657 assert_eq!(current_depth(), start + 1);
1658 }
1659 assert_eq!(current_depth(), start);
1660 }
1661
1662 #[test]
1663 fn test_stage_header_splits_into_verb_and_message() {
1664 // A multi-word phrase splits on the FIRST space: the verb feeds the
1665 // right-aligned gutter, the remainder is the section message.
1666 let log = StageLogger::new("build", Verbosity::Normal);
1667 assert_eq!(log.split_header("build"), ("Building", "binaries"));
1668 assert_eq!(log.split_header("sign"), ("Signing", "artifacts"));
1669 assert_eq!(log.split_header("source"), ("Archiving", "source"));
1670 }
1671
1672 #[test]
1673 fn test_stage_header_single_word_renders_verb_only() {
1674 // A known single-word phrase ("Publishing") renders just the gutter
1675 // verb with an empty message — no stage-name echo.
1676 let log = StageLogger::new("publish", Verbosity::Normal);
1677 assert_eq!(log.split_header("publish"), ("Publishing", ""));
1678 }
1679
1680 #[test]
1681 fn test_stage_header_unknown_stage_uses_running_plus_name() {
1682 // An unknown stage falls back to "Running" + the stage name, so it
1683 // still renders in the system vocabulary (` Running myfancystage`).
1684 let log = StageLogger::new("x", Verbosity::Normal);
1685 assert_eq!(
1686 log.split_header("myfancystage"),
1687 ("Running", "myfancystage")
1688 );
1689 }
1690
1691 #[test]
1692 fn test_verbosity_from_flags_default() {
1693 assert_eq!(
1694 Verbosity::from_flags(false, false, false),
1695 Verbosity::Normal
1696 );
1697 }
1698
1699 #[test]
1700 fn test_verbosity_from_flags_quiet() {
1701 assert_eq!(Verbosity::from_flags(true, false, false), Verbosity::Quiet);
1702 }
1703
1704 #[test]
1705 fn test_verbosity_from_flags_verbose() {
1706 assert_eq!(
1707 Verbosity::from_flags(false, true, false),
1708 Verbosity::Verbose
1709 );
1710 }
1711
1712 #[test]
1713 fn test_verbosity_from_flags_debug() {
1714 assert_eq!(Verbosity::from_flags(false, false, true), Verbosity::Debug);
1715 }
1716
1717 #[test]
1718 fn test_verbosity_from_flags_debug_wins_over_verbose() {
1719 assert_eq!(Verbosity::from_flags(false, true, true), Verbosity::Debug);
1720 }
1721
1722 #[test]
1723 fn test_verbosity_from_flags_debug_wins_over_quiet() {
1724 assert_eq!(Verbosity::from_flags(true, false, true), Verbosity::Debug);
1725 }
1726
1727 #[test]
1728 fn test_verbosity_from_flags_quiet_overrides_verbose() {
1729 assert_eq!(Verbosity::from_flags(true, true, false), Verbosity::Quiet);
1730 }
1731
1732 #[test]
1733 fn test_verbosity_ordering() {
1734 assert!(Verbosity::Quiet < Verbosity::Normal);
1735 assert!(Verbosity::Normal < Verbosity::Verbose);
1736 assert!(Verbosity::Verbose < Verbosity::Debug);
1737 }
1738
1739 #[test]
1740 fn test_stage_logger_is_verbose() {
1741 let log = StageLogger::new("test", Verbosity::Verbose);
1742 assert!(log.is_verbose());
1743 assert!(!log.is_debug());
1744 }
1745
1746 #[test]
1747 fn test_stage_logger_is_debug() {
1748 let log = StageLogger::new("test", Verbosity::Debug);
1749 assert!(log.is_verbose());
1750 assert!(log.is_debug());
1751 }
1752
1753 #[test]
1754 fn test_stage_logger_normal_not_verbose() {
1755 let log = StageLogger::new("test", Verbosity::Normal);
1756 assert!(!log.is_verbose());
1757 assert!(!log.is_debug());
1758 }
1759
1760 #[test]
1761 fn test_default_verbosity_is_normal() {
1762 assert_eq!(Verbosity::default(), Verbosity::Normal);
1763 }
1764
1765 // -----------------------------------------------------------------
1766 // Redaction inside check_output
1767 // -----------------------------------------------------------------
1768
1769 #[cfg(unix)]
1770 fn fake_output(stdout: &[u8], stderr: &[u8], code: i32) -> std::process::Output {
1771 use std::os::unix::process::ExitStatusExt;
1772 std::process::Output {
1773 status: std::process::ExitStatus::from_raw(code << 8),
1774 stdout: stdout.to_vec(),
1775 stderr: stderr.to_vec(),
1776 }
1777 }
1778
1779 #[test]
1780 fn test_redact_uses_attached_env() {
1781 // A logger built via `with_env` must scrub configured secrets.
1782 let log = StageLogger::new("test", Verbosity::Normal).with_env(vec![(
1783 "GITHUB_TOKEN".to_string(),
1784 "ghp_real_secret_token".to_string(),
1785 )]);
1786 let out = log.redact("auth header: ghp_real_secret_token");
1787 assert_eq!(out, "auth header: $GITHUB_TOKEN");
1788 assert!(!out.contains("ghp_real_secret_token"));
1789 }
1790
1791 #[test]
1792 fn test_redact_without_env_only_scrubs_inline_urls() {
1793 // A logger constructed without `with_env` still scrubs inline URL
1794 // credentials, even if the bare token is not in env (the env-pair
1795 // list is empty).
1796 let log = StageLogger::new("test", Verbosity::Normal);
1797 let out = log.redact("fetched from https://user:tok@example.com/path");
1798 assert_eq!(out, "fetched from https://<redacted>@example.com/path");
1799 }
1800
1801 #[test]
1802 fn test_redact_combines_env_and_url_credentials() {
1803 let log = StageLogger::new("test", Verbosity::Normal)
1804 .with_env(vec![("API_TOKEN".to_string(), "ghp_tok123".to_string())]);
1805 // Both the env-value token AND the inline URL credential should be
1806 // scrubbed in a single call.
1807 let out = log.redact("remote: https://ghp_tok123@github.com/x/y");
1808 // URL credential strip runs first, so the `ghp_tok123` between
1809 // `://` and `@` becomes `<redacted>`. The path / host text never
1810 // contains `ghp_tok123`, so the env-value pass is a no-op here.
1811 assert_eq!(out, "remote: https://<redacted>@github.com/x/y");
1812 assert!(!out.contains("ghp_tok123"));
1813 }
1814
1815 #[cfg(unix)]
1816 #[test]
1817 fn test_check_output_redacts_stderr_on_failure() {
1818 // Stderr from a failing subprocess must be redacted before
1819 // the logger surfaces it, so secrets present in `output.stderr`
1820 // never reach the eprintln sink (or any future log appender).
1821 let log = StageLogger::new("test", Verbosity::Normal).with_env(vec![(
1822 "REGISTRY_PASSWORD".to_string(),
1823 "supersecret_pw_123".to_string(),
1824 )]);
1825 let output = fake_output(
1826 b"",
1827 b"docker login failed: invalid password 'supersecret_pw_123'",
1828 1,
1829 );
1830 let (stderr_line, _) = log.format_output_lines(&output, "docker login");
1831 let line = stderr_line.expect("stderr should be present on failure");
1832 assert!(
1833 !line.contains("supersecret_pw_123"),
1834 "stderr must be redacted: {line}"
1835 );
1836 assert!(line.contains("$REGISTRY_PASSWORD"));
1837 }
1838
1839 #[cfg(unix)]
1840 #[test]
1841 fn test_check_output_redacts_stdout_on_failure() {
1842 // Stdout on the failure path must be redacted alongside
1843 // stderr. Some tools dump credentials onto stdout (e.g. helm
1844 // login prints a warning to stdout, not stderr).
1845 let log = StageLogger::new("test", Verbosity::Normal).with_env(vec![(
1846 "DOCKER_PASSWORD".to_string(),
1847 "tok_dckr_abc".to_string(),
1848 )]);
1849 let output = fake_output(b"echoed config: DOCKER_PASSWORD=tok_dckr_abc\n", b"", 2);
1850 let (_, stdout_line) = log.format_output_lines(&output, "docker");
1851 let line = stdout_line.expect("stdout should be present on failure");
1852 assert!(!line.contains("tok_dckr_abc"));
1853 assert!(line.contains("$DOCKER_PASSWORD"));
1854 }
1855
1856 #[cfg(unix)]
1857 #[test]
1858 fn test_check_output_redacts_stdout_on_verbose_success() {
1859 // At verbose level, successful subprocess stdout is logged
1860 // too; it must also be redacted.
1861 let log = StageLogger::new("test", Verbosity::Verbose).with_env(vec![(
1862 "MY_API_KEY".to_string(),
1863 "key-abcdef-123".to_string(),
1864 )]);
1865 let output = fake_output(b"echo: key-abcdef-123 OK\n", b"", 0);
1866 let (_, stdout_line) = log.format_output_lines(&output, "echo");
1867 let line = stdout_line.expect("stdout should be present on success");
1868 assert!(!line.contains("key-abcdef-123"));
1869 assert!(line.contains("$MY_API_KEY"));
1870 }
1871
1872 #[cfg(unix)]
1873 #[test]
1874 fn test_check_output_strips_inline_url_credentials_without_env() {
1875 // A logger built without env still strips URL credentials,
1876 // so even when the user did not export a matching env var, an
1877 // inline `https://<user>:<pw>@host` in stderr is scrubbed.
1878 let log = StageLogger::new("test", Verbosity::Normal);
1879 let output = fake_output(
1880 b"",
1881 b"fatal: cannot read https://user:p4ssw0rd@example.com/repo.git\n",
1882 128,
1883 );
1884 let (stderr_line, _) = log.format_output_lines(&output, "git fetch");
1885 let line = stderr_line.expect("stderr should be present on failure");
1886 assert!(
1887 !line.contains("p4ssw0rd"),
1888 "userinfo must be redacted: {line}"
1889 );
1890 assert!(line.contains("<redacted>@example.com"));
1891 }
1892
1893 #[cfg(unix)]
1894 #[test]
1895 fn test_check_output_bail_message_excludes_raw_secret() {
1896 // The bail message embeds the (truncated, redacted) stderr tail
1897 // so an operator reading the bubbled anyhow chain sees something
1898 // more actionable than the bare exit code. That redaction must
1899 // still strip env-resolved secrets — otherwise the new tail
1900 // would leak whatever stderr the subprocess emitted.
1901 let log = StageLogger::new("test", Verbosity::Normal).with_env(vec![(
1902 "AUTH_TOKEN".to_string(),
1903 "secret_zzz_yyy".to_string(),
1904 )]);
1905 let output = fake_output(b"", b"401 Unauthorized: secret_zzz_yyy\n", 1);
1906 let err = log
1907 .check_output(output, "curl")
1908 .expect_err("non-zero exit should bail");
1909 let msg = format!("{err:#}");
1910 assert!(
1911 !msg.contains("secret_zzz_yyy"),
1912 "bail message leaks secret: {msg}"
1913 );
1914 assert!(
1915 msg.contains("stderr:") && msg.contains("401 Unauthorized"),
1916 "bail message should embed redacted stderr tail: {msg}"
1917 );
1918 }
1919
1920 #[cfg(unix)]
1921 #[test]
1922 fn test_check_output_bail_message_strips_ansi_color_codes() {
1923 // Color is forced on for child processes so the live CI log stays
1924 // colorized; cargo (and friends) then emit SGR escapes around versions,
1925 // paths, and numbers. The bubbled tail flows into failure-notification
1926 // emails and the on_error hook's $ANODIZER_ERROR, which render raw ANSI
1927 // as garbage — so the persisted error must carry plain text only.
1928 let log = StageLogger::new("test", Verbosity::Normal);
1929 // cargo-shaped colorized stderr: bold version, dimmed path, red error.
1930 let colorized =
1931 b"\x1b[1mPackaging\x1b[0m foo \x1b[2mv\x1b[1m0.11.3\x1b[0m\n\x1b[31merror\x1b[0m: exit \x1b[33m101\x1b[0m\n";
1932 let output = fake_output(b"", colorized, 101);
1933 let err = log
1934 .check_output(output, "cargo publish")
1935 .expect_err("non-zero exit should bail");
1936 let msg = format!("{err:#}");
1937 assert!(
1938 !msg.contains('\u{1b}'),
1939 "bail message must contain no ANSI escape bytes: {msg:?}"
1940 );
1941 assert!(
1942 msg.contains("Packaging") && msg.contains("0.11.3") && msg.contains("101"),
1943 "plain-text content must survive ANSI stripping: {msg}"
1944 );
1945 }
1946
1947 #[cfg(unix)]
1948 #[test]
1949 fn test_check_output_bail_includes_no_stderr_marker_when_empty() {
1950 // Subprocess failed with empty stderr — the bail still wants
1951 // SOMETHING after `stderr:` so a grep on operator logs sees a
1952 // deterministic marker rather than blank text.
1953 let log = StageLogger::new("test", Verbosity::Normal);
1954 let output = fake_output(b"", b"", 7);
1955 let err = log
1956 .check_output(output, "tool")
1957 .expect_err("non-zero exit should bail");
1958 let msg = format!("{err:#}");
1959 assert!(
1960 msg.contains("stderr: <no stderr>"),
1961 "expected explicit <no stderr> marker: {msg}"
1962 );
1963 }
1964
1965 #[cfg(unix)]
1966 #[test]
1967 fn test_check_output_bail_truncates_long_stderr() {
1968 // Stderr larger than the 2 KiB cap is truncated with an ellipsis
1969 // so the operator's error chain remains scannable.
1970 let log = StageLogger::new("test", Verbosity::Normal);
1971 // 3 KiB of stderr.
1972 let big = vec![b'x'; 3072];
1973 let output = fake_output(b"", &big, 1);
1974 let err = log
1975 .check_output(output, "tool")
1976 .expect_err("non-zero exit should bail");
1977 let msg = format!("{err:#}");
1978 assert!(
1979 msg.ends_with('…'),
1980 "expected ellipsis on truncated stderr: {msg}"
1981 );
1982 // Truncation must keep the surface manageable — well under
1983 // 3 KiB of raw stderr should make it into the bail.
1984 assert!(
1985 msg.len() < 2500,
1986 "bail message too long: {} bytes",
1987 msg.len()
1988 );
1989 }
1990
1991 #[test]
1992 fn test_with_env_is_arc_shared() {
1993 // Cloning a logger should share the env vec via Arc, not deep-copy.
1994 // Verified by pointer equality on the inner Vec backing the Arc.
1995 let env = vec![("K".to_string(), "v_long_enough_to_be_a_token".to_string())];
1996 let a = StageLogger::new("a", Verbosity::Normal).with_env(env);
1997 let b = a.clone();
1998 let pa: *const Vec<(String, String)> = a.env.as_ref().unwrap().as_ref();
1999 let pb: *const Vec<(String, String)> = b.env.as_ref().unwrap().as_ref();
2000 assert_eq!(pa, pb);
2001 }
2002
2003 #[test]
2004 fn test_with_stage_rebinds_stage_field() {
2005 // The per-line `[stage]` tag is gone from rendered output, but
2006 // `with_stage` still rebinds the `stage` field a logger carries (it
2007 // drives redaction env inheritance, not line formatting now).
2008 let log = StageLogger::new("release", Verbosity::Normal);
2009 assert_eq!(log.stage, "release");
2010 assert_eq!(log.with_stage("finalize").stage, "finalize");
2011 }
2012
2013 #[test]
2014 fn test_body_markers_render_at_body_indent() {
2015 // Body lines sit at the 3-space body indent (top level: no section
2016 // nesting) behind a colored marker glyph. ANSI codes are stripped
2017 // for the assertion so the test pins the visible shape, not palette.
2018 let _guard = SECTION_TEST_LOCK.lock().unwrap();
2019 let strip = |s: String| {
2020 // Drop CSI sequences so the assertion is palette-independent.
2021 let mut out = String::new();
2022 let mut chars = s.chars().peekable();
2023 while let Some(c) = chars.next() {
2024 if c == '\u{1b}' {
2025 for n in chars.by_ref() {
2026 if n == 'm' {
2027 break;
2028 }
2029 }
2030 } else {
2031 out.push(c);
2032 }
2033 }
2034 out
2035 };
2036 // Relative to the live indent so an exported ANODIZER_LOG_DEPTH
2037 // (or a section left open by a parallel test) cannot skew the
2038 // absolute column.
2039 let prefix = indent();
2040 assert_eq!(
2041 strip(StageLogger::render_body(MARKER_DETAIL, "x")),
2042 format!("{prefix} • x")
2043 );
2044 assert_eq!(
2045 strip(StageLogger::render_body(MARKER_SUCCESS, "ok")),
2046 format!("{prefix} ✓ ok")
2047 );
2048 assert_eq!(
2049 strip(StageLogger::render_body(MARKER_FAILURE, "bad")),
2050 format!("{prefix} ✗ bad")
2051 );
2052 }
2053
2054 #[test]
2055 fn test_kv_pads_plain_key_so_values_align() {
2056 // The padded key width counts the PLAIN key, not the ANSI-dimmed
2057 // bytes, so a short key and a long key share the same value column.
2058 // Emitting a body line drains the process-global PENDING stack via
2059 // `flush_pending`, so serialize against the section-depth tests that
2060 // assert on that stack.
2061 let _guard = SECTION_TEST_LOCK.lock().unwrap_or_else(|e| e.into_inner());
2062 let (log, cap) = StageLogger::with_capture("check", Verbosity::Normal);
2063 let w = ["targets", "runs"].iter().map(|k| k.len()).max().unwrap();
2064 log.kv("targets", "aarch64", w);
2065 log.kv("runs", "2", w);
2066 // The capture stores a normalized `key = value` form regardless of
2067 // the rendered padding/palette.
2068 assert_eq!(
2069 cap.all_messages(),
2070 vec![
2071 (LogLevel::Status, "targets = aarch64".to_string()),
2072 (LogLevel::Status, "runs = 2".to_string()),
2073 ]
2074 );
2075 }
2076
2077 #[test]
2078 fn test_retag_helpers_record_under_shared_capture() {
2079 // The retagged clone shares the capture sink, and the plain
2080 // delegations still record at the right level — locking the plumbing
2081 // independent of the rendered tag (which the capture does not store).
2082 // Emitting body lines drains the global PENDING stack via
2083 // `flush_pending`; serialize against the section-depth tests.
2084 let _guard = SECTION_TEST_LOCK.lock().unwrap_or_else(|e| e.into_inner());
2085 let (log, cap) = StageLogger::with_capture("release", Verbosity::Normal);
2086
2087 log.with_stage("finalize").status("x");
2088 log.error("y");
2089 log.status("own-status");
2090 log.error("own-error");
2091
2092 assert_eq!(
2093 cap.all_messages(),
2094 vec![
2095 (LogLevel::Status, "x".to_string()),
2096 (LogLevel::Error, "y".to_string()),
2097 (LogLevel::Status, "own-status".to_string()),
2098 (LogLevel::Error, "own-error".to_string()),
2099 ]
2100 );
2101 }
2102
2103 #[test]
2104 fn skip_line_records_debug_when_not_shown() {
2105 // The default (show=false) routes a per-crate "no config block" skip to
2106 // debug() so it stays invisible at Normal/Verbose and only surfaces at
2107 // --debug — the fix for the 300+-line workspace skip-noise problem.
2108 // skip_line emits a body line that drains the global PENDING stack;
2109 // serialize against the section-depth tests.
2110 let _guard = SECTION_TEST_LOCK.lock().unwrap_or_else(|e| e.into_inner());
2111 let (log, cap) = StageLogger::with_capture("homebrew", Verbosity::Normal);
2112 log.skip_line(
2113 false,
2114 "skipped homebrew for crate 'demo' — no homebrew config block",
2115 );
2116 assert_eq!(cap.debug_count(), 1);
2117 assert_eq!(cap.status_count(), 0);
2118 assert_eq!(
2119 cap.all_messages(),
2120 vec![(
2121 LogLevel::Debug,
2122 "skipped homebrew for crate 'demo' — no homebrew config block".to_string()
2123 )]
2124 );
2125 }
2126
2127 #[test]
2128 fn skip_line_records_status_when_shown() {
2129 // --show-skipped (show=true) forces the skip line back to status so the
2130 // operator can diagnose why a publisher didn't run for a given crate.
2131 // skip_line emits a body line that drains the global PENDING stack;
2132 // serialize against the section-depth tests.
2133 let _guard = SECTION_TEST_LOCK.lock().unwrap_or_else(|e| e.into_inner());
2134 let (log, cap) = StageLogger::with_capture("homebrew", Verbosity::Normal);
2135 log.skip_line(
2136 true,
2137 "skipped homebrew for crate 'demo' — no homebrew config block",
2138 );
2139 assert_eq!(cap.status_count(), 1);
2140 assert_eq!(cap.debug_count(), 0);
2141 }
2142}