anodizer_core/log.rs
1//! Thin structured logging helper for anodizer stages.
2//!
3//! Provides level-gated output to stderr, with consistent `[stage] message`
4//! formatting. Keeps stdout clean for machine-parseable output (e.g. `anodizer tag`).
5//!
6//! # Verbosity levels
7//!
8//! - **quiet**: errors only (for CI where only failures matter)
9//! - **default**: status messages (stage start/complete, key actions)
10//! - **verbose**: detail (command output, env vars, file paths)
11//! - **debug**: everything (HTTP request/response, template contexts, resolved config)
12//!
13//! # Secret redaction
14//!
15//! Every `StageLogger` carries an optional env-pairs list that drives the
16//! redaction policy applied inside [`StageLogger::check_output`]. Callers
17//! that go through [`crate::context::Context::logger`] inherit the merged
18//! `{process env, config env}` pairs automatically; manual constructors
19//! (`StageLogger::new`) start with no env and can be enriched via
20//! [`StageLogger::with_env`]. Stderr / stdout interpolated into log lines
21//! or `bail!` messages is therefore redacted without callers having to
22//! remember to scrub at every site.
23
24use std::sync::Arc;
25#[cfg(feature = "test-helpers")]
26use std::sync::Mutex;
27use std::sync::atomic::{AtomicUsize, Ordering};
28
29use colored::Colorize;
30
31/// Process-global section nesting depth. Drives the 2-space-per-level
32/// indentation applied to every stderr log line so output produced
33/// inside a [`StageLogger::group`] sits visually beneath its header.
34///
35/// A single atomic (rather than per-logger state) is correct because the
36/// release pipeline drives one stderr stream and no `group()` is ever
37/// opened from a worker thread — sections bracket whole stages on the
38/// main thread, while a stage's interior parallelism (e.g. `build`
39/// spawning per-target threads) emits *inside* an already-open section.
40/// The depth is therefore a property of "where the main thread is in the
41/// run", not of any individual logger clone or worker.
42static SECTION_DEPTH: AtomicUsize = AtomicUsize::new(0);
43
44/// Width of the right-aligned verb column in [`StageLogger::step`],
45/// matching Cargo's ` Compiling foo` look (3 leading spaces + 9-char
46/// verb = a 12-column gutter before the message).
47const VERB_COLUMN: usize = 12;
48
49/// Map a pipeline stage name to its Cargo-style header verb (present
50/// participle, right-aligned into the [`VERB_COLUMN`] gutter). Drives
51/// [`StageLogger::group`]'s local header so a section opens with
52/// ` Building build` / ` Publishing publish` instead of a bare bullet,
53/// matching `cargo`'s ` Compiling foo` look.
54///
55/// Falls back to a capitalized "Running" for any stage without a bespoke
56/// verb, so a newly-added stage still renders in the system vocabulary
57/// without a code change here.
58pub fn stage_verb(stage: &str) -> &'static str {
59 match stage {
60 "setup" => "Preparing",
61 "build" => "Building",
62 "upx" => "Compressing",
63 "appbundle" => "Bundling",
64 "dmg" | "msi" | "nsis" | "pkg" | "srpm" | "nfpm" | "makeself" => "Packaging",
65 "notarize" => "Notarizing",
66 "changelog" => "Changelog",
67 "archive" => "Archiving",
68 "source" => "Archiving",
69 "snapcraft" | "flatpak" => "Packaging",
70 "sbom" => "Cataloging",
71 "templatefiles" => "Templating",
72 "checksum" => "Checksumming",
73 "sign" | "docker-sign" => "Signing",
74 "before-publish" => "Preparing",
75 "release" => "Releasing",
76 "docker" => "Building",
77 "publish" | "blob" | "snapcraft-publish" => "Publishing",
78 "announce" => "Announcing",
79 "publisher-summary" => "Summary",
80 "finalize" => "Finalizing",
81 "prepare" => "Preparing",
82 _ => "Running",
83 }
84}
85
86/// Render the themed `Warning:` line for `msg`, including the current
87/// section indent. The single source of truth for the warning palette
88/// and label, shared by [`StageLogger::warn`] and the CLI's tracing
89/// formatter so a library-side `warn!` looks identical to a logger warn
90/// (one output authority). The `[stage]` tag is the caller's
91/// responsibility — loggerless library warns have no stage to name.
92pub fn render_warning(msg: &str) -> String {
93 format!("{}{} {}", indent(), "Warning:".yellow().bold(), msg)
94}
95
96/// Render the themed `Error:` line for `msg`, including the current
97/// section indent. Companion to [`render_warning`]; shared so the error
98/// palette/label lives in exactly one place.
99pub fn render_error(msg: &str) -> String {
100 format!("{}{} {}", indent(), "Error:".red().bold(), msg)
101}
102
103/// Render the themed `Note:` line for `msg`, including the current
104/// section indent. The third (and final) status label in the vocabulary
105/// — informational lines that are neither warnings nor errors (host-target
106/// selection, auto-snapshot activation). Bold-green to read as a benign
107/// status, distinct from the yellow `Warning:` and red `Error:`. Shared
108/// so the `Note:` palette/label lives in exactly one place rather than
109/// being open-coded per call site.
110pub fn render_note(msg: &str) -> String {
111 format!("{}{} {}", indent(), "Note:".green().bold(), msg)
112}
113
114/// `true` when running under GitHub Actions, where `::group::` /
115/// `::endgroup::` workflow commands render collapsible log sections.
116fn in_github_actions() -> bool {
117 std::env::var("GITHUB_ACTIONS").as_deref() == Ok("true")
118}
119
120/// Current indentation prefix (2 spaces per open section). Empty at the
121/// top level. Suppressed under GitHub Actions, where `::group::` already
122/// supplies the visual nesting and a leading-space prefix would only add
123/// noise to the collapsed view.
124///
125/// Exposed so the CLI's loggerless `tracing` warning formatter can apply
126/// the same indent a library warn fired mid-stage would otherwise lack,
127/// keeping it aligned with the surrounding `[stage]` lines.
128pub fn indent() -> String {
129 if in_github_actions() {
130 return String::new();
131 }
132 " ".repeat(SECTION_DEPTH.load(Ordering::Relaxed))
133}
134
135/// RAII guard returned by [`StageLogger::group`]. Closes the section
136/// (emits `::endgroup::` under Actions, decrements the local indent
137/// depth) when dropped, so a stage's output is always balanced even if
138/// the stage bails early with `?`.
139#[must_use = "dropping the guard immediately ends the section"]
140pub struct SectionGuard {
141 _private: (),
142}
143
144impl Drop for SectionGuard {
145 fn drop(&mut self) {
146 if in_github_actions() {
147 eprintln!("::endgroup::");
148 } else {
149 SECTION_DEPTH.fetch_sub(1, Ordering::Relaxed);
150 }
151 }
152}
153
154/// Level of a log line captured by a [`LogCapture`]. Mirrors the
155/// [`StageLogger`] methods that produce each level.
156///
157/// Gated behind the `test-helpers` Cargo feature — production binaries
158/// do not link the capture infrastructure.
159#[cfg(feature = "test-helpers")]
160#[derive(Debug, Clone, Copy, PartialEq, Eq)]
161pub enum LogLevel {
162 Error,
163 Warn,
164 Status,
165 Verbose,
166 Debug,
167}
168
169/// In-memory sink that records every log line a [`StageLogger`] emits.
170///
171/// Cheap clone (`Arc<Mutex<Vec<…>>>` underneath) — pass the same handle to
172/// every logger derived from a [`crate::context::Context`] and read aggregated
173/// counts back via the accessor methods. Intended for tests that need to
174/// assert "publisher emitted ≥N status lines" — calls still write to stderr
175/// so test output stays debuggable.
176///
177/// Gated behind the `test-helpers` Cargo feature.
178#[cfg(feature = "test-helpers")]
179#[derive(Clone, Default)]
180pub struct LogCapture {
181 inner: Arc<Mutex<Vec<(LogLevel, String)>>>,
182}
183
184#[cfg(feature = "test-helpers")]
185impl LogCapture {
186 /// Construct a fresh empty capture sink.
187 pub fn new() -> Self {
188 Self::default()
189 }
190
191 /// Append a log line to the capture vec. Called from the
192 /// [`StageLogger`] methods when a capture is attached.
193 pub(crate) fn record(&self, level: LogLevel, msg: impl Into<String>) {
194 if let Ok(mut guard) = self.inner.lock() {
195 guard.push((level, msg.into()));
196 }
197 }
198
199 /// Number of [`LogLevel::Status`] lines recorded.
200 pub fn status_count(&self) -> usize {
201 self.count(LogLevel::Status)
202 }
203
204 /// Number of [`LogLevel::Warn`] lines recorded.
205 pub fn warn_count(&self) -> usize {
206 self.count(LogLevel::Warn)
207 }
208
209 /// Number of [`LogLevel::Error`] lines recorded.
210 pub fn error_count(&self) -> usize {
211 self.count(LogLevel::Error)
212 }
213
214 /// Total count across all levels (useful sanity check).
215 pub fn total_count(&self) -> usize {
216 self.inner.lock().map(|g| g.len()).unwrap_or(0)
217 }
218
219 fn count(&self, level: LogLevel) -> usize {
220 self.inner
221 .lock()
222 .map(|g| g.iter().filter(|(l, _)| *l == level).count())
223 .unwrap_or(0)
224 }
225
226 /// Snapshot of every recorded line in insertion order.
227 pub fn all_messages(&self) -> Vec<(LogLevel, String)> {
228 self.inner.lock().map(|g| g.clone()).unwrap_or_default()
229 }
230
231 /// Snapshot of every [`LogLevel::Warn`] message in insertion order.
232 ///
233 /// Convenience accessor for tests that care only about warns — strips
234 /// the level tuple [`all_messages`] returns so callers can write
235 /// `cap.warn_messages().iter().any(|m| m.contains("..."))` without
236 /// the per-call filter+map boilerplate.
237 ///
238 /// [`all_messages`]: Self::all_messages
239 pub fn warn_messages(&self) -> Vec<String> {
240 self.inner
241 .lock()
242 .map(|g| {
243 g.iter()
244 .filter(|(lvl, _)| *lvl == LogLevel::Warn)
245 .map(|(_, m)| m.clone())
246 .collect()
247 })
248 .unwrap_or_default()
249 }
250}
251
252/// Verbosity level, derived from CLI flags.
253#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Default)]
254pub enum Verbosity {
255 Quiet,
256 #[default]
257 Normal,
258 Verbose,
259 Debug,
260}
261
262impl Verbosity {
263 /// Derive verbosity from CLI flag combination.
264 /// `--quiet` overrides `--verbose`; `--debug` overrides everything.
265 pub fn from_flags(quiet: bool, verbose: bool, debug: bool) -> Self {
266 if debug {
267 Verbosity::Debug
268 } else if quiet {
269 Verbosity::Quiet
270 } else if verbose {
271 Verbosity::Verbose
272 } else {
273 Verbosity::Normal
274 }
275 }
276}
277
278/// Stage logger: wraps a stage name, verbosity level, and an optional
279/// env-pairs list used for secret redaction.
280///
281/// All output goes to stderr. Create one per stage via [`StageLogger::new`].
282/// Prefer `Context::logger("name")` over `StageLogger::new` when a
283/// `Context` is in scope, because it carries the env automatically.
284///
285/// ```rust,ignore
286/// let log = ctx.logger("build"); // env pre-populated
287/// let log = StageLogger::new("build", verbosity) // no env yet
288/// .with_env(env_pairs); // attach env for redact
289/// log.status("compiling for x86_64-unknown-linux-gnu");
290/// log.verbose(&format!("RUSTFLAGS={}", flags));
291/// log.debug(&format!("full env: {:?}", env));
292/// ```
293#[derive(Clone)]
294pub struct StageLogger {
295 stage: &'static str,
296 verbosity: Verbosity,
297 /// Env-pairs used to redact subprocess output and bail messages. The
298 /// inner vec is shared via `Arc` so cloning a logger does not copy the
299 /// env every time. `None` means redaction is a no-op (matches the
300 /// behaviour before this field existed).
301 env: Option<Arc<Vec<(String, String)>>>,
302 /// Optional in-memory capture sink. When present, every log method also
303 /// appends to the capture vec (after the stderr write). `None` means
304 /// the logger only writes to stderr (production default).
305 ///
306 /// Gated behind the `test-helpers` Cargo feature — production binaries
307 /// do not carry the field, so no per-log-call `is_none()` check fires.
308 #[cfg(feature = "test-helpers")]
309 capture: Option<LogCapture>,
310}
311
312impl StageLogger {
313 pub fn new(stage: &'static str, verbosity: Verbosity) -> Self {
314 Self {
315 stage,
316 verbosity,
317 env: None,
318 #[cfg(feature = "test-helpers")]
319 capture: None,
320 }
321 }
322
323 /// Construct a logger backed by an in-memory [`LogCapture`] alongside the
324 /// usual stderr writes. Returns the logger plus a clone of the capture
325 /// handle so the test can read counts back after the SUT runs.
326 ///
327 /// Intended exclusively for tests — production code uses
328 /// [`StageLogger::new`] or [`crate::context::Context::logger`].
329 ///
330 /// Gated behind the `test-helpers` Cargo feature.
331 #[cfg(feature = "test-helpers")]
332 pub fn with_capture(stage: &'static str, verbosity: Verbosity) -> (Self, LogCapture) {
333 let capture = LogCapture::new();
334 let logger = Self {
335 stage,
336 verbosity,
337 env: None,
338 capture: Some(capture.clone()),
339 };
340 (logger, capture)
341 }
342
343 /// Attach an existing [`LogCapture`] to this logger. Useful when the
344 /// capture is owned by a [`crate::context::Context`] and every derived
345 /// logger should append to the same vec.
346 ///
347 /// Gated behind the `test-helpers` Cargo feature.
348 #[cfg(feature = "test-helpers")]
349 pub fn with_capture_handle(mut self, capture: LogCapture) -> Self {
350 self.capture = Some(capture);
351 self
352 }
353
354 /// Attach an env-pairs list to drive secret redaction inside
355 /// [`StageLogger::check_output`] and [`StageLogger::redact`]. The list
356 /// is shared via `Arc`, so passing the same vec to many loggers does
357 /// not duplicate the underlying storage.
358 pub fn with_env(mut self, env: Vec<(String, String)>) -> Self {
359 self.env = Some(Arc::new(env));
360 self
361 }
362
363 /// Derive a clone of this logger tagged for a different `stage`, keeping
364 /// verbosity, the (Arc-shared) redaction env, and any capture sink.
365 ///
366 /// The pipeline driver owns one `[release]`-tagged logger but brackets
367 /// sub-sections (`setup`, `finalize`, `publisher-summary`) with their own
368 /// `group()`. Body lines emitted inside such a section must carry the
369 /// *section's* tag, not `[release]`, or the output reads
370 /// `[release] wrote …` underneath `::group::finalize`. Retagging once at
371 /// the section boundary lets every helper called within the section emit
372 /// under the correct tag without threading an explicit `stage` argument
373 /// through each call.
374 pub fn with_stage(&self, stage: &'static str) -> Self {
375 Self {
376 stage,
377 verbosity: self.verbosity,
378 env: self.env.clone(),
379 #[cfg(feature = "test-helpers")]
380 capture: self.capture.clone(),
381 }
382 }
383
384 /// Redact secret values from `s` using this logger's attached env.
385 ///
386 /// When no env has been attached (the default for `StageLogger::new`),
387 /// returns the input unchanged. Combines `redact::string` (for
388 /// known-secret env values) with `redact::redact_url_credentials`
389 /// (for inline `https://<user>:<pass>@host` URL credentials that may
390 /// not match any exported env-var value).
391 pub fn redact(&self, s: &str) -> String {
392 let credential_stripped = crate::redact::redact_url_credentials(s);
393 match self.env.as_deref() {
394 Some(env) => crate::redact::string(&credential_stripped, env),
395 None => credential_stripped,
396 }
397 }
398
399 /// Dimmed `[stage] ` tag prefix (bracketed stage name, dimmed, plus a
400 /// trailing space). The single source of truth for the per-line tag so
401 /// every render method (`error`/`warn`/`status`/`verbose`/`debug`)
402 /// produces a byte-identical prefix — same palette, brackets, spacing.
403 fn tag_prefix(stage: &str) -> String {
404 format!("{} ", format!("[{stage}]").dimmed())
405 }
406
407 /// Error message — always shown (even in quiet mode).
408 ///
409 /// Delegates to [`Self::error_as`] under this logger's own stage tag so
410 /// there is a single error render path (one source of truth for the
411 /// label / indent / `[stage]` formatting).
412 pub fn error(&self, msg: &str) {
413 self.error_as(self.stage, msg);
414 }
415
416 /// Error message rendered under an explicit `stage` tag rather than this
417 /// logger's own [`Self::stage`]. Companion to [`Self::status_as`] for the
418 /// pipeline driver, which owns a single `[release]`-tagged logger but
419 /// opens a `group()` per stage: a stage-failure line emitted from that
420 /// driver must carry the failing stage's tag (so the error inside
421 /// `::group::build` reads `[build]`, not `[release]`). Identical
422 /// formatting to [`Self::error`] otherwise.
423 pub fn error_as(&self, stage: &str, msg: &str) {
424 let tagged = format!("{}{}", Self::tag_prefix(stage), msg);
425 eprintln!("{}", render_error(&tagged));
426 #[cfg(feature = "test-helpers")]
427 if let Some(cap) = &self.capture {
428 cap.record(LogLevel::Error, msg);
429 }
430 }
431
432 /// Warning message — shown at Normal and above.
433 pub fn warn(&self, msg: &str) {
434 if self.verbosity >= Verbosity::Normal {
435 let tagged = format!("{}{}", Self::tag_prefix(self.stage), msg);
436 eprintln!("{}", render_warning(&tagged));
437 }
438 #[cfg(feature = "test-helpers")]
439 if let Some(cap) = &self.capture {
440 cap.record(LogLevel::Warn, msg);
441 }
442 }
443
444 /// Status message — shown at Normal and above. This is the default level
445 /// for key actions (stage start, completion, skips, dry-run notes).
446 ///
447 /// Delegates to [`Self::status_as`] under this logger's own stage tag so
448 /// there is a single status render path (one source of truth for the
449 /// blank-line / indent / `[stage]` formatting).
450 pub fn status(&self, msg: &str) {
451 self.status_as(self.stage, msg);
452 }
453
454 /// Status message rendered under an explicit `stage` tag rather than
455 /// this logger's own [`Self::stage`]. The pipeline driver owns a single
456 /// `[release]`-tagged logger but opens a `group()` per stage; a skip /
457 /// no-binary note emitted from that driver must carry the *current*
458 /// stage's tag (so a note inside `::group::publish` reads `[publish]`,
459 /// not `[release]`). Identical formatting to [`Self::status`] otherwise.
460 pub fn status_as(&self, stage: &str, msg: &str) {
461 if self.verbosity >= Verbosity::Normal {
462 // Preserve fully-blank spacer lines exactly (no prefix and no
463 // indent), so callers using `status("")` for vertical rhythm
464 // keep a clean blank line even inside a group. An indented
465 // "blank" line (trailing spaces only) would render as visible
466 // whitespace and break the rhythm the caller asked for.
467 if msg.is_empty() {
468 eprintln!();
469 } else {
470 eprintln!("{}{}{}", indent(), Self::tag_prefix(stage), msg);
471 }
472 }
473 #[cfg(feature = "test-helpers")]
474 if let Some(cap) = &self.capture {
475 cap.record(LogLevel::Status, msg);
476 }
477 }
478
479 /// Cargo-style status line: a capitalized, right-aligned, bold-green
480 /// `verb` in a fixed-width gutter followed by `msg`
481 /// (` Building build`, ` Signing sign`). Shown at Normal and
482 /// above. Use for section/stage headers where there is a natural
483 /// verb; plain key-action lines stay on [`StageLogger::status`].
484 pub fn step(&self, verb: &str, msg: &str) {
485 if self.verbosity >= Verbosity::Normal {
486 eprintln!(
487 "{}{} {}",
488 indent(),
489 format!("{verb:>VERB_COLUMN$}").green().bold(),
490 msg
491 );
492 }
493 #[cfg(feature = "test-helpers")]
494 if let Some(cap) = &self.capture {
495 cap.record(LogLevel::Status, msg);
496 }
497 }
498
499 /// Open a log section titled `title`.
500 ///
501 /// Under GitHub Actions emits a `::group::<title>` workflow command
502 /// (rendered as a collapsible block); the returned [`SectionGuard`]
503 /// emits the matching `::endgroup::` on drop. Locally emits a
504 /// Cargo-style header — a bold-green right-aligned verb (derived from
505 /// the stage name via [`stage_verb`]) in the [`VERB_COLUMN`] gutter
506 /// followed by the title (` Building build`) — and indents every
507 /// subsequent log line two spaces until the guard drops. Sections
508 /// nest.
509 ///
510 /// ```rust,ignore
511 /// let _section = log.group("build"); // Building build
512 /// log.status("compiling x86_64-unknown-linux-gnu"); // indented beneath
513 /// // section closes here as `_section` drops
514 /// ```
515 #[must_use = "the section stays open only while the guard is alive"]
516 pub fn group(&self, title: &str) -> SectionGuard {
517 if self.verbosity >= Verbosity::Normal {
518 if in_github_actions() {
519 eprintln!("::group::{title}");
520 } else {
521 self.step(stage_verb(title), title);
522 SECTION_DEPTH.fetch_add(1, Ordering::Relaxed);
523 }
524 } else if in_github_actions() {
525 // Keep group markers balanced even in quiet mode so the
526 // Actions UI never shows an unterminated section.
527 eprintln!("::group::{title}");
528 } else {
529 SECTION_DEPTH.fetch_add(1, Ordering::Relaxed);
530 }
531 SectionGuard { _private: () }
532 }
533
534 /// Open a log section *without* emitting the Cargo-style verb header.
535 ///
536 /// Companion to [`Self::group`] for stages the pipeline skips: a skipped
537 /// stage has nothing to announce in the present-participle voice
538 /// (`Announcing announce` followed by `[announce] skipped` reads as a
539 /// contradiction), so the driver opens the section silently and emits a
540 /// single neutral `Skipped …` line itself. The `::group::`/`::endgroup::`
541 /// pair (and the local indent depth) is still balanced so the Actions UI
542 /// shows one collapsible block per stage exactly as [`Self::group`] does.
543 #[must_use = "the section stays open only while the guard is alive"]
544 pub fn group_silent(&self, title: &str) -> SectionGuard {
545 if in_github_actions() {
546 // Always emit the marker (even in quiet mode) so the Actions UI
547 // never shows an unterminated section.
548 eprintln!("::group::{title}");
549 } else {
550 SECTION_DEPTH.fetch_add(1, Ordering::Relaxed);
551 }
552 SectionGuard { _private: () }
553 }
554
555 /// Detail message — shown only at Verbose and above.
556 /// Use for: command output on success, env vars, file paths, template vars.
557 pub fn verbose(&self, msg: &str) {
558 if self.verbosity >= Verbosity::Verbose {
559 eprintln!("{}{}{}", indent(), Self::tag_prefix(self.stage), msg);
560 }
561 #[cfg(feature = "test-helpers")]
562 if let Some(cap) = &self.capture {
563 cap.record(LogLevel::Verbose, msg);
564 }
565 }
566
567 /// Debug message — shown only at Debug level.
568 /// Use for: HTTP request/response details, full template contexts, resolved config.
569 pub fn debug(&self, msg: &str) {
570 if self.verbosity >= Verbosity::Debug {
571 eprintln!(
572 "{}{}{}",
573 indent(),
574 Self::tag_prefix(self.stage),
575 msg.dimmed()
576 );
577 }
578 #[cfg(feature = "test-helpers")]
579 if let Some(cap) = &self.capture {
580 cap.record(LogLevel::Debug, msg);
581 }
582 }
583
584 /// Return the current verbosity level.
585 pub fn verbosity(&self) -> Verbosity {
586 self.verbosity
587 }
588
589 /// Check if verbose output is enabled.
590 pub fn is_verbose(&self) -> bool {
591 self.verbosity >= Verbosity::Verbose
592 }
593
594 /// Check if debug output is enabled.
595 pub fn is_debug(&self) -> bool {
596 self.verbosity >= Verbosity::Debug
597 }
598
599 /// Check command output, log stderr/stdout on failure, and bail with context.
600 /// On success, log stdout at verbose level. Returns `Ok(output)` on success.
601 ///
602 /// Stderr and stdout are passed through [`StageLogger::redact`] before
603 /// they reach the log sink, so any secret env-var values present in the
604 /// subprocess output are replaced with `$KEY_NAME` (and inline
605 /// `https://<user>:<pass>@host` URL credentials are scrubbed) without
606 /// callers having to remember to redact at each call site. Mirrors
607 /// a safe-stderr pattern at every subprocess
608 /// boundary.
609 pub fn check_output(
610 &self,
611 output: std::process::Output,
612 label: &str,
613 ) -> anyhow::Result<std::process::Output> {
614 let (stderr_line, stdout_line) = self.format_output_lines(&output, label);
615 if !output.status.success() {
616 if let Some(line) = stderr_line {
617 self.error(&line);
618 }
619 if let Some(line) = stdout_line {
620 self.error(&line);
621 }
622 // Embed a (truncated, redacted) stderr tail in the bubbled
623 // error so operators reading the final anyhow chain see
624 // something more actionable than just an exit code. The
625 // separately-emitted `log.error` lines above remain the
626 // primary surface; this is defense in depth for callers
627 // that propagate the error past the StageLogger context.
628 let stderr_raw = String::from_utf8_lossy(&output.stderr);
629 let stderr_tail = if stderr_raw.is_empty() {
630 String::from("<no stderr>")
631 } else {
632 let redacted = self.redact(&stderr_raw);
633 let trimmed = redacted.trim();
634 // Cap at 2 KiB to keep error chains scannable.
635 const MAX: usize = 2048;
636 if trimmed.len() > MAX {
637 let cut = trimmed
638 .char_indices()
639 .nth(MAX)
640 .map(|(i, _)| i)
641 .unwrap_or(MAX);
642 format!("{}…", &trimmed[..cut])
643 } else {
644 trimmed.to_string()
645 }
646 };
647 anyhow::bail!(
648 "{} failed with exit code: {}; stderr: {}",
649 label,
650 output.status.code().unwrap_or(-1),
651 stderr_tail
652 );
653 }
654 if self.is_verbose()
655 && let Some(line) = stdout_line
656 {
657 self.verbose(&line);
658 }
659 Ok(output)
660 }
661
662 /// Compose the redacted stderr / stdout log lines that
663 /// [`StageLogger::check_output`] would emit for `output`. Returned as
664 /// `(stderr_line, stdout_line)` where each `Option` is `Some` only when
665 /// the corresponding stream had any content. Exposed via
666 /// `pub(crate)` so the redaction logic can be unit-tested without
667 /// having to capture stderr (`eprintln!` cannot be intercepted from
668 /// the same process portably).
669 pub(crate) fn format_output_lines(
670 &self,
671 output: &std::process::Output,
672 label: &str,
673 ) -> (Option<String>, Option<String>) {
674 let stderr_raw = String::from_utf8_lossy(&output.stderr);
675 let stderr_line = if stderr_raw.is_empty() {
676 None
677 } else {
678 let stderr = self.redact(&stderr_raw);
679 let prefix = if output.status.success() {
680 "output"
681 } else {
682 "stderr"
683 };
684 // Failure messages format stderr separately from stdout (under
685 // the "stderr" label); success uses one "output" label for
686 // stdout only.
687 if output.status.success() {
688 // success path: stderr is never surfaced through check_output
689 None
690 } else {
691 Some(format!("{label} {prefix}:\n{stderr}"))
692 }
693 };
694 let stdout_raw = String::from_utf8_lossy(&output.stdout);
695 let stdout_line = if stdout_raw.is_empty() {
696 None
697 } else {
698 let stdout = self.redact(&stdout_raw);
699 let prefix = if output.status.success() {
700 "output"
701 } else {
702 "stdout"
703 };
704 Some(format!("{label} {prefix}:\n{stdout}"))
705 };
706 (stderr_line, stdout_line)
707 }
708}
709
710#[cfg(test)]
711mod tests {
712 use super::*;
713
714 /// Serializes the section-depth tests: `SECTION_DEPTH` is a
715 /// process-global atomic, so two grouping tests running on parallel
716 /// threads would observe each other's increments.
717 static SECTION_TEST_LOCK: Mutex<()> = Mutex::new(());
718
719 #[test]
720 fn test_group_guard_balances_depth_locally() {
721 // GITHUB_ACTIONS must be unset so the local (indent-depth) path
722 // runs rather than the `::group::` emit path.
723 let _guard = SECTION_TEST_LOCK.lock().unwrap();
724 // SAFETY: single-threaded under SECTION_TEST_LOCK; no other
725 // thread reads GITHUB_ACTIONS while this test holds the lock.
726 unsafe {
727 std::env::remove_var("GITHUB_ACTIONS");
728 }
729 let log = StageLogger::new("build", Verbosity::Normal);
730 let start = SECTION_DEPTH.load(Ordering::Relaxed);
731 {
732 let _outer = log.group("build");
733 assert_eq!(SECTION_DEPTH.load(Ordering::Relaxed), start + 1);
734 {
735 let _inner = log.group("sign");
736 assert_eq!(SECTION_DEPTH.load(Ordering::Relaxed), start + 2);
737 }
738 assert_eq!(SECTION_DEPTH.load(Ordering::Relaxed), start + 1);
739 }
740 assert_eq!(SECTION_DEPTH.load(Ordering::Relaxed), start);
741 }
742
743 #[test]
744 fn test_group_quiet_still_tracks_local_depth() {
745 // Even at Quiet verbosity the local indent depth must stay
746 // balanced so any status lines that DO print (errors) indent
747 // correctly and the guard's decrement has a matching increment.
748 let _guard = SECTION_TEST_LOCK.lock().unwrap();
749 // SAFETY: single-threaded under SECTION_TEST_LOCK.
750 unsafe {
751 std::env::remove_var("GITHUB_ACTIONS");
752 }
753 let log = StageLogger::new("build", Verbosity::Quiet);
754 let start = SECTION_DEPTH.load(Ordering::Relaxed);
755 {
756 let _s = log.group("build");
757 assert_eq!(SECTION_DEPTH.load(Ordering::Relaxed), start + 1);
758 }
759 assert_eq!(SECTION_DEPTH.load(Ordering::Relaxed), start);
760 }
761
762 #[test]
763 fn test_indent_suppressed_under_github_actions() {
764 let _guard = SECTION_TEST_LOCK.lock().unwrap();
765 // SAFETY: single-threaded under SECTION_TEST_LOCK.
766 unsafe {
767 std::env::set_var("GITHUB_ACTIONS", "true");
768 }
769 // Under Actions, indent() returns empty regardless of any
770 // residual depth, because `::group::` supplies the nesting.
771 assert_eq!(indent(), "");
772 assert!(in_github_actions());
773 // SAFETY: single-threaded under SECTION_TEST_LOCK.
774 unsafe {
775 std::env::remove_var("GITHUB_ACTIONS");
776 }
777 assert!(!in_github_actions());
778 }
779
780 #[test]
781 fn test_verbosity_from_flags_default() {
782 assert_eq!(
783 Verbosity::from_flags(false, false, false),
784 Verbosity::Normal
785 );
786 }
787
788 #[test]
789 fn test_verbosity_from_flags_quiet() {
790 assert_eq!(Verbosity::from_flags(true, false, false), Verbosity::Quiet);
791 }
792
793 #[test]
794 fn test_verbosity_from_flags_verbose() {
795 assert_eq!(
796 Verbosity::from_flags(false, true, false),
797 Verbosity::Verbose
798 );
799 }
800
801 #[test]
802 fn test_verbosity_from_flags_debug() {
803 assert_eq!(Verbosity::from_flags(false, false, true), Verbosity::Debug);
804 }
805
806 #[test]
807 fn test_verbosity_from_flags_debug_wins_over_verbose() {
808 assert_eq!(Verbosity::from_flags(false, true, true), Verbosity::Debug);
809 }
810
811 #[test]
812 fn test_verbosity_from_flags_debug_wins_over_quiet() {
813 assert_eq!(Verbosity::from_flags(true, false, true), Verbosity::Debug);
814 }
815
816 #[test]
817 fn test_verbosity_from_flags_quiet_overrides_verbose() {
818 assert_eq!(Verbosity::from_flags(true, true, false), Verbosity::Quiet);
819 }
820
821 #[test]
822 fn test_verbosity_ordering() {
823 assert!(Verbosity::Quiet < Verbosity::Normal);
824 assert!(Verbosity::Normal < Verbosity::Verbose);
825 assert!(Verbosity::Verbose < Verbosity::Debug);
826 }
827
828 #[test]
829 fn test_stage_logger_is_verbose() {
830 let log = StageLogger::new("test", Verbosity::Verbose);
831 assert!(log.is_verbose());
832 assert!(!log.is_debug());
833 }
834
835 #[test]
836 fn test_stage_logger_is_debug() {
837 let log = StageLogger::new("test", Verbosity::Debug);
838 assert!(log.is_verbose());
839 assert!(log.is_debug());
840 }
841
842 #[test]
843 fn test_stage_logger_normal_not_verbose() {
844 let log = StageLogger::new("test", Verbosity::Normal);
845 assert!(!log.is_verbose());
846 assert!(!log.is_debug());
847 }
848
849 #[test]
850 fn test_default_verbosity_is_normal() {
851 assert_eq!(Verbosity::default(), Verbosity::Normal);
852 }
853
854 // -----------------------------------------------------------------
855 // Redaction inside check_output
856 // -----------------------------------------------------------------
857
858 #[cfg(unix)]
859 fn fake_output(stdout: &[u8], stderr: &[u8], code: i32) -> std::process::Output {
860 use std::os::unix::process::ExitStatusExt;
861 std::process::Output {
862 status: std::process::ExitStatus::from_raw(code << 8),
863 stdout: stdout.to_vec(),
864 stderr: stderr.to_vec(),
865 }
866 }
867
868 #[test]
869 fn test_redact_uses_attached_env() {
870 // A logger built via `with_env` must scrub configured secrets.
871 let log = StageLogger::new("test", Verbosity::Normal).with_env(vec![(
872 "GITHUB_TOKEN".to_string(),
873 "ghp_real_secret_token".to_string(),
874 )]);
875 let out = log.redact("auth header: ghp_real_secret_token");
876 assert_eq!(out, "auth header: $GITHUB_TOKEN");
877 assert!(!out.contains("ghp_real_secret_token"));
878 }
879
880 #[test]
881 fn test_redact_without_env_only_scrubs_inline_urls() {
882 // A logger constructed without `with_env` still scrubs inline URL
883 // credentials, even if the bare token is not in env (the env-pair
884 // list is empty).
885 let log = StageLogger::new("test", Verbosity::Normal);
886 let out = log.redact("fetched from https://user:tok@example.com/path");
887 assert_eq!(out, "fetched from https://<redacted>@example.com/path");
888 }
889
890 #[test]
891 fn test_redact_combines_env_and_url_credentials() {
892 let log = StageLogger::new("test", Verbosity::Normal)
893 .with_env(vec![("API_TOKEN".to_string(), "ghp_tok123".to_string())]);
894 // Both the env-value token AND the inline URL credential should be
895 // scrubbed in a single call.
896 let out = log.redact("remote: https://ghp_tok123@github.com/x/y");
897 // URL credential strip runs first, so the `ghp_tok123` between
898 // `://` and `@` becomes `<redacted>`. The path / host text never
899 // contains `ghp_tok123`, so the env-value pass is a no-op here.
900 assert_eq!(out, "remote: https://<redacted>@github.com/x/y");
901 assert!(!out.contains("ghp_tok123"));
902 }
903
904 #[cfg(unix)]
905 #[test]
906 fn test_check_output_redacts_stderr_on_failure() {
907 // Stderr from a failing subprocess must be redacted before
908 // the logger surfaces it, so secrets present in `output.stderr`
909 // never reach the eprintln sink (or any future log appender).
910 let log = StageLogger::new("test", Verbosity::Normal).with_env(vec![(
911 "REGISTRY_PASSWORD".to_string(),
912 "supersecret_pw_123".to_string(),
913 )]);
914 let output = fake_output(
915 b"",
916 b"docker login failed: invalid password 'supersecret_pw_123'",
917 1,
918 );
919 let (stderr_line, _) = log.format_output_lines(&output, "docker login");
920 let line = stderr_line.expect("stderr should be present on failure");
921 assert!(
922 !line.contains("supersecret_pw_123"),
923 "stderr must be redacted: {line}"
924 );
925 assert!(line.contains("$REGISTRY_PASSWORD"));
926 }
927
928 #[cfg(unix)]
929 #[test]
930 fn test_check_output_redacts_stdout_on_failure() {
931 // Stdout on the failure path must be redacted alongside
932 // stderr. Some tools dump credentials onto stdout (e.g. helm
933 // login prints a warning to stdout, not stderr).
934 let log = StageLogger::new("test", Verbosity::Normal).with_env(vec![(
935 "DOCKER_PASSWORD".to_string(),
936 "tok_dckr_abc".to_string(),
937 )]);
938 let output = fake_output(b"echoed config: DOCKER_PASSWORD=tok_dckr_abc\n", b"", 2);
939 let (_, stdout_line) = log.format_output_lines(&output, "docker");
940 let line = stdout_line.expect("stdout should be present on failure");
941 assert!(!line.contains("tok_dckr_abc"));
942 assert!(line.contains("$DOCKER_PASSWORD"));
943 }
944
945 #[cfg(unix)]
946 #[test]
947 fn test_check_output_redacts_stdout_on_verbose_success() {
948 // At verbose level, successful subprocess stdout is logged
949 // too; it must also be redacted.
950 let log = StageLogger::new("test", Verbosity::Verbose).with_env(vec![(
951 "MY_API_KEY".to_string(),
952 "key-abcdef-123".to_string(),
953 )]);
954 let output = fake_output(b"echo: key-abcdef-123 OK\n", b"", 0);
955 let (_, stdout_line) = log.format_output_lines(&output, "echo");
956 let line = stdout_line.expect("stdout should be present on success");
957 assert!(!line.contains("key-abcdef-123"));
958 assert!(line.contains("$MY_API_KEY"));
959 }
960
961 #[cfg(unix)]
962 #[test]
963 fn test_check_output_strips_inline_url_credentials_without_env() {
964 // A logger built without env still strips URL credentials,
965 // so even when the user did not export a matching env var, an
966 // inline `https://<user>:<pw>@host` in stderr is scrubbed.
967 let log = StageLogger::new("test", Verbosity::Normal);
968 let output = fake_output(
969 b"",
970 b"fatal: cannot read https://user:p4ssw0rd@example.com/repo.git\n",
971 128,
972 );
973 let (stderr_line, _) = log.format_output_lines(&output, "git fetch");
974 let line = stderr_line.expect("stderr should be present on failure");
975 assert!(
976 !line.contains("p4ssw0rd"),
977 "userinfo must be redacted: {line}"
978 );
979 assert!(line.contains("<redacted>@example.com"));
980 }
981
982 #[cfg(unix)]
983 #[test]
984 fn test_check_output_bail_message_excludes_raw_secret() {
985 // The bail message embeds the (truncated, redacted) stderr tail
986 // so an operator reading the bubbled anyhow chain sees something
987 // more actionable than the bare exit code. That redaction must
988 // still strip env-resolved secrets — otherwise the new tail
989 // would leak whatever stderr the subprocess emitted.
990 let log = StageLogger::new("test", Verbosity::Normal).with_env(vec![(
991 "AUTH_TOKEN".to_string(),
992 "secret_zzz_yyy".to_string(),
993 )]);
994 let output = fake_output(b"", b"401 Unauthorized: secret_zzz_yyy\n", 1);
995 let err = log
996 .check_output(output, "curl")
997 .expect_err("non-zero exit should bail");
998 let msg = format!("{err:#}");
999 assert!(
1000 !msg.contains("secret_zzz_yyy"),
1001 "bail message leaks secret: {msg}"
1002 );
1003 assert!(
1004 msg.contains("stderr:") && msg.contains("401 Unauthorized"),
1005 "bail message should embed redacted stderr tail: {msg}"
1006 );
1007 }
1008
1009 #[cfg(unix)]
1010 #[test]
1011 fn test_check_output_bail_includes_no_stderr_marker_when_empty() {
1012 // Subprocess failed with empty stderr — the bail still wants
1013 // SOMETHING after `stderr:` so a grep on operator logs sees a
1014 // deterministic marker rather than blank text.
1015 let log = StageLogger::new("test", Verbosity::Normal);
1016 let output = fake_output(b"", b"", 7);
1017 let err = log
1018 .check_output(output, "tool")
1019 .expect_err("non-zero exit should bail");
1020 let msg = format!("{err:#}");
1021 assert!(
1022 msg.contains("stderr: <no stderr>"),
1023 "expected explicit <no stderr> marker: {msg}"
1024 );
1025 }
1026
1027 #[cfg(unix)]
1028 #[test]
1029 fn test_check_output_bail_truncates_long_stderr() {
1030 // Stderr larger than the 2 KiB cap is truncated with an ellipsis
1031 // so the operator's error chain remains scannable.
1032 let log = StageLogger::new("test", Verbosity::Normal);
1033 // 3 KiB of stderr.
1034 let big = vec![b'x'; 3072];
1035 let output = fake_output(b"", &big, 1);
1036 let err = log
1037 .check_output(output, "tool")
1038 .expect_err("non-zero exit should bail");
1039 let msg = format!("{err:#}");
1040 assert!(
1041 msg.ends_with('…'),
1042 "expected ellipsis on truncated stderr: {msg}"
1043 );
1044 // Truncation must keep the surface manageable — well under
1045 // 3 KiB of raw stderr should make it into the bail.
1046 assert!(
1047 msg.len() < 2500,
1048 "bail message too long: {} bytes",
1049 msg.len()
1050 );
1051 }
1052
1053 #[test]
1054 fn test_with_env_is_arc_shared() {
1055 // Cloning a logger should share the env vec via Arc, not deep-copy.
1056 // Verified by pointer equality on the inner Vec backing the Arc.
1057 let env = vec![("K".to_string(), "v_long_enough_to_be_a_token".to_string())];
1058 let a = StageLogger::new("a", Verbosity::Normal).with_env(env);
1059 let b = a.clone();
1060 let pa: *const Vec<(String, String)> = a.env.as_ref().unwrap().as_ref();
1061 let pb: *const Vec<(String, String)> = b.env.as_ref().unwrap().as_ref();
1062 assert_eq!(pa, pb);
1063 }
1064
1065 #[test]
1066 fn test_retag_helpers_emit_under_explicit_stage() {
1067 // `with_stage` rebinds the rendered tag to the section name, while
1068 // `status`/`error` (post-delegation) and the `*_as` variants honour
1069 // the requested stage. The dimmed `tag_prefix` is the byte source for
1070 // every render path, so asserting on it pins the rendered `[stage]`.
1071 let log = StageLogger::new("release", Verbosity::Normal);
1072
1073 // Plain accessors render under the logger's own stage.
1074 assert!(StageLogger::tag_prefix(log.stage).contains("[release]"));
1075
1076 // `with_stage` rebinds the stage the body lines render under.
1077 let finalize = log.with_stage("finalize");
1078 assert_eq!(finalize.stage, "finalize");
1079 assert!(StageLogger::tag_prefix(finalize.stage).contains("[finalize]"));
1080
1081 // The `*_as` variants render under the explicit stage argument.
1082 assert!(StageLogger::tag_prefix("blob").contains("[blob]"));
1083
1084 // The tag carries a single trailing space (after any ANSI reset) so
1085 // the prefix concatenates byte-identically with the message.
1086 assert!(StageLogger::tag_prefix("setup").ends_with(' '));
1087 }
1088
1089 #[test]
1090 fn test_retag_helpers_record_under_shared_capture() {
1091 // The retagged clone shares the capture sink, and the plain
1092 // delegations still record at the right level — locking the plumbing
1093 // independent of the rendered tag (which the capture does not store).
1094 let (log, cap) = StageLogger::with_capture("release", Verbosity::Normal);
1095
1096 log.with_stage("finalize").status("x");
1097 log.error_as("blob", "y");
1098 log.status("own-status");
1099 log.error("own-error");
1100
1101 assert_eq!(
1102 cap.all_messages(),
1103 vec![
1104 (LogLevel::Status, "x".to_string()),
1105 (LogLevel::Error, "y".to_string()),
1106 (LogLevel::Status, "own-status".to_string()),
1107 (LogLevel::Error, "own-error".to_string()),
1108 ]
1109 );
1110 }
1111}