Skip to main content

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