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