Skip to main content

latexml_core/util/
logger.rs

1use std::{
2  cell::RefCell,
3  sync::atomic::{AtomicBool, AtomicUsize, Ordering},
4};
5
6use log::{Level, LevelFilter, Metadata, Record, SetLoggerError, max_level};
7
8// ANSI SGR escape sequences (drop-in replacement for the
9// unmaintained `ansi_term` crate; bytes match `ansi_term::Colour::*.paint(...)`).
10const ANSI_RESET: &str = "\x1b[0m";
11const ANSI_GREEN: &str = "\x1b[32m";
12const ANSI_YELLOW: &str = "\x1b[33m";
13const ANSI_RED: &str = "\x1b[31m";
14const ANSI_WHITE: &str = "\x1b[37m";
15
16fn paint(color: &str, text: &str) -> String { format!("{color}{text}{ANSI_RESET}") }
17
18/// Whether to emit ANSI color escapes on stderr. Colors are a convenience for
19/// an interactive terminal ONLY; when stderr is redirected to a file or pipe
20/// (the canvas/auto-upgrade path: `cortex_worker ... > log.txt 2>&1`) they are
21/// noise that breaks line-anchored error parsing — a naive `grep '^Error:'`
22/// matches `\x1b[31mError:` ZERO times and silently reports "0 errors" on a
23/// failed paper (the false-negative that masked real Rust-only regressions; see
24/// CLAUDE.md "canvas signal integrity"). So: colorize iff stderr is a TTY and
25/// `NO_COLOR` is unset. Cached once — stderr's terminal-ness can't change
26/// mid-process. Note the captured LOG_BUFFER (`.latexml.log`) is already
27/// ANSI-stripped independently; this makes the *redirected stderr* match it.
28fn stderr_use_color() -> bool {
29  use std::{io::IsTerminal, sync::OnceLock};
30  static USE_COLOR: OnceLock<bool> = OnceLock::new();
31  *USE_COLOR
32    .get_or_init(|| std::io::stderr().is_terminal() && std::env::var_os("NO_COLOR").is_none())
33}
34
35/// The STDERR verbosity gate, decoupled from the log-file floor.
36///
37/// Perl LaTeXML separates the two: the log file (`$LOG`) receives every message
38/// while it is open, but STDERR prints only when `$USE_STDERR && $VERBOSITY >= 0`
39/// (`Common/Error.pm` `_printline`). `--quiet` lowers THIS (to `Warn`) without
40/// lowering what the log keeps — so `(Loading …)` progress notes and `Info:`
41/// records still reach `.latexml.log`, which is what BookML's makefile dependency
42/// tracking reads (issue #763). `--verbose`/`--debug` raise it (to `Debug`).
43///
44/// Stored as the `LevelFilter` discriminant (`Off`=0 … `Trace`=5). Process-global
45/// like `max_level`: one shared stderr descriptor across `cortex_worker`'s pool.
46static STDERR_LEVEL: AtomicUsize = AtomicUsize::new(LevelFilter::Info as usize);
47
48/// The current STDERR verbosity (see [`STDERR_LEVEL`]).
49fn stderr_level() -> LevelFilter {
50  match STDERR_LEVEL.load(Ordering::Relaxed) {
51    0 => LevelFilter::Off,
52    1 => LevelFilter::Error,
53    2 => LevelFilter::Warn,
54    3 => LevelFilter::Info,
55    4 => LevelFilter::Debug,
56    _ => LevelFilter::Trace,
57  }
58}
59
60/// Does the current STDERR verbosity admit a record of `level`? `Error`/`Fatal`
61/// are handled unconditionally by the caller (the project's deliberate
62/// always-emit-errors divergence); this governs the verbosity-gated levels.
63pub fn stderr_admits(level: Level) -> bool { level.to_level_filter() <= stderr_level() }
64
65/// Whether STDERR currently shows `Info`-level progress notes — Perl
66/// `$VERBOSITY >= 0`. The `Note!`/`NoteSTDERR!` macros gate their STDERR echo on
67/// this, decoupled from the log-file floor so `--quiet` silences the console note
68/// while the log keeps it (issue #763).
69pub fn stderr_shows_info() -> bool { stderr_admits(Level::Info) }
70
71struct LatexmlLogger;
72static LOGGER: LatexmlLogger = LatexmlLogger;
73
74/// Thread-local log capture buffer. When enabled, log messages are
75/// appended here (without ANSI colors) in addition to stderr.
76#[thread_local]
77static LOG_BUFFER: RefCell<Option<String>> = RefCell::new(None);
78
79/// Does stderr currently sit at the start of a line?
80///
81/// A diagnostic record must begin on a fresh line so CorTeX's line-anchored
82/// parser (`^Error:`/`^Warning:`/`^Info:`) matches and the record never glues
83/// onto an in-flight progress note like `(Loading "foo.sty"… )`, which is
84/// written WITHOUT a trailing newline. That guarantee used to be bought with an
85/// unconditional leading `\n` on every record — which emits a BLANK line
86/// whenever stderr was already at line start, i.e. almost always.
87///
88/// Measured on the 131 MB witness: **1,440,571 of 3,142,509 captured stderr
89/// lines (45.8%) were blank**, matching the record count almost exactly. The
90/// `LOG_BUFFER` path never had this bug — it tests `ends_with('\n')` — so the
91/// on-disk `.latexml.log` and the captured stderr disagreed on line count.
92///
93/// Tracking line-start state reproduces the guarantee at half the bytes.
94///
95/// **Process-global, not `#[thread_local]`, and mutated under the stderr lock.**
96/// stderr is one shared descriptor: `cortex_worker --pool-size N` runs N
97/// conversion threads in one process, and `logger::capture` exists precisely to
98/// run conversions on worker threads. A per-thread flag would let thread A skip
99/// its leading newline believing the cursor is at line start while thread B had
100/// left it mid-line — gluing a record onto B's output, where CorTeX's
101/// `^Error:`/`^Warning:` anchor then misses it entirely. That is a silent
102/// error-count loss, the exact failure this project's signal-integrity rule
103/// forbids (false negatives hide regressions). The unconditional leading `\n`
104/// was robust to that by construction, so the replacement has to be too:
105/// check-write-set happens as one critical section holding the stderr lock.
106static STDERR_AT_LINE_START: AtomicBool = AtomicBool::new(true);
107
108/// Tell the logger that stderr is back at line start. For the `Note!` /
109/// `NoteLog!` macros, which write to stderr directly via `println_stderr!`
110/// rather than through `log::Log` — without this the next diagnostic record
111/// could emit a spurious leading newline.
112pub fn mark_stderr_at_line_start() { STDERR_AT_LINE_START.store(true, Ordering::Release); }
113
114/// Start capturing log output into the buffer (Perl: bind_log).
115pub fn bind_log() { *LOG_BUFFER.borrow_mut() = Some(String::new()); }
116
117/// Flush and return the captured log output, stopping capture (Perl: flush_log).
118pub fn flush_log() -> String { LOG_BUFFER.borrow_mut().take().unwrap_or_default() }
119
120/// Append a progress note to the captured log (`.latexml.log`) only — the LOG
121/// half of Perl `Note`/`NoteLog` (`Common/Error.pm`: `print $LOG _freshline($LOG),
122/// strip_ansi($message), "\n" if $LOG`). ANSI is stripped and the note lands on
123/// its own fresh line with a single trailing newline, so CorTeX's line-anchored
124/// parser and the `.latexml.log` stay clean (mirrors the diagnostic-record
125/// freshline path below). No-op when no buffer is bound or output is suppressed —
126/// unlike a `log::info!` record it is NOT gated on the stderr verbosity, because
127/// the log is the verbose record (Perl writes it regardless of `$VERBOSITY`).
128pub fn note_to_log(msg: &str) {
129  if crate::common::error::is_log_output_suppressed() {
130    return;
131  }
132  if let Ok(mut buf) = LOG_BUFFER.try_borrow_mut()
133    && let Some(ref mut log) = *buf
134  {
135    let clean = strip_ansi(msg);
136    if !log.is_empty() && !log.ends_with('\n') {
137      log.push('\n');
138    }
139    log.push_str(&clean);
140    if !log.ends_with('\n') {
141      log.push('\n');
142    }
143  }
144}
145
146/// Diagnostics captured from a worker thread by [`capture`], for the main thread
147/// to fold back in via [`replay_captured`]. Carries both the already-formatted
148/// log text AND the `REPORT` count deltas — `LOG_BUFFER` and `REPORT` are BOTH
149/// `#[thread_local]`, so forwarding only the text would still leave
150/// `status_code` blind to a worker's failures.
151pub struct CapturedDiagnostics {
152  pub log:    String,
153  pub counts: crate::common::error::ReportCounts,
154}
155
156/// Run `f` on the CURRENT (worker) thread with diagnostic capture. Binds a fresh
157/// thread-local log buffer for the duration so any `Error!`/`Warn!`/`Info!` `f`
158/// emits (directly or deep inside a conversion helper) is recorded instead of
159/// lost, and snapshots the worker's `REPORT` counters afterward. The returned
160/// [`CapturedDiagnostics`] is replayed on the main thread by [`replay_captured`]
161/// after the worker is joined, so the messages reach the bound `cortex.log` and
162/// the failures register in `status_code`.
163///
164/// Assumes the worker thread has no pre-bound buffer (the spawned post-processing
165/// pool threads start clean); it does not save/restore a prior binding.
166///
167/// INVARIANTS (unenforced by types; guard the fleet's canonical signal):
168/// - one `capture` per thread lifetime — `bind_log()` CLOBBERS any pre-bound
169///   buffer, and `snapshot_report_counts` does not reset, so reusing capture
170///   on a pooled thread would drop earlier text and double-merge counts;
171/// - callers must `replay_captured` the result on the MAIN thread exactly
172///   once (a panicking worker never returns, losing its pre-panic capture —
173///   the real-time stderr echo retains it, and the caller's worker_panicked
174///   Error keeps status from reading clean).
175pub fn capture<R>(f: impl FnOnce() -> R) -> (R, CapturedDiagnostics) {
176  debug_assert!(
177    LOG_BUFFER
178      .try_borrow()
179      .map(|b| b.is_none())
180      .unwrap_or(false),
181    "logger::capture on a thread with a pre-bound buffer — pooled-thread reuse?"
182  );
183  bind_log();
184  let result = f();
185  let log = flush_log();
186  let counts = crate::common::error::snapshot_report_counts();
187  (result, CapturedDiagnostics { log, counts })
188}
189
190/// Fold worker-thread diagnostics (from [`capture`]) into the main thread: append
191/// the captured log text to the bound `LOG_BUFFER` and merge the count deltas
192/// into the main `REPORT`. Call on the MAIN thread, in a deterministic order
193/// (e.g. worker/job order), after the workers join. The worker already echoed
194/// each line to the shared stderr fd in real time, so this does NOT re-print to
195/// stderr — it only repairs the captured log + status tally.
196pub fn replay_captured(d: CapturedDiagnostics) {
197  debug_assert!(
198    LOG_BUFFER.try_borrow().is_ok(),
199    "replay_captured: LOG_BUFFER contended — captured text would be dropped"
200  );
201  if !d.log.is_empty()
202    && let Ok(mut buf) = LOG_BUFFER.try_borrow_mut()
203    && let Some(ref mut log) = *buf
204  {
205    // The captured text is already per-record newline-terminated; just make
206    // sure it starts on a fresh line so it can't glue onto an in-flight note.
207    if !log.is_empty() && !log.ends_with('\n') {
208      log.push('\n');
209    }
210    log.push_str(&d.log);
211  }
212  crate::common::error::merge_report_counts(d.counts);
213}
214
215/// Strip ANSI escape sequences from a string for log file output.
216fn strip_ansi(s: &str) -> String {
217  // Match ESC[ ... m sequences
218  let mut result = String::with_capacity(s.len());
219  let mut in_escape = false;
220  for c in s.chars() {
221    if in_escape {
222      if c == 'm' {
223        in_escape = false;
224      }
225    } else if c == '\x1b' {
226      in_escape = true;
227    } else {
228      result.push(c);
229    }
230  }
231  result
232}
233
234/// Append a progress note to the capture buffer as INLINE flowing text — the
235/// faithful Perl LaTeXML / tex.web terminal-progress format. `note_begin`
236/// carries a leading '\n' so each stage opens on a fresh line; `note_end`
237/// (` )`) and `note_progress` (`[1][2]…`, `N formulae …`) append inline so a
238/// load's closing paren and the page markers stay on the SAME line as their
239/// opener, and nested closes chain (`… 0.00 sec) 0.05 sec)`). A leading '\n'
240/// is collapsed against an existing trailing '\n' (or buffer start) so we never
241/// emit a blank line. Replaces the old unconditional `push('\n')` per note,
242/// which put every `)` on its own line and doubled newlines into blank lines
243/// (the reported `.latexml.log` noise on corpora.latexml.rs).
244fn append_note(buf: &mut String, note: &str) {
245  if note.starts_with('\n') && (buf.is_empty() || buf.ends_with('\n')) {
246    buf.push_str(&note[1..]);
247  } else {
248    buf.push_str(note);
249  }
250}
251
252/// prints a single line to STDERR
253#[macro_export]
254macro_rules! println_stderr(
255    ($($arg:tt)*) => ({
256      use std::io::Write;
257      match writeln!(&mut ::std::io::stderr(), $($arg)* ) {
258        Ok(_) => {},
259        Err(x) => panic!("Unable to write to stderr: {}", x),
260      }
261    })
262);
263
264/// prints a to STDERR without a line break
265#[macro_export]
266macro_rules! print_stderr(
267    ($($arg:tt)*) => ({
268      use std::io::Write;
269      match write!(&mut ::std::io::stderr(), $($arg)* ) {
270        Ok(_) => {},
271        Err(x) => panic!("Unable to write to stderr: {}", x),
272      }
273    })
274);
275
276impl log::Log for LatexmlLogger {
277  fn enabled(&self, metadata: &Metadata) -> bool { metadata.level() <= max_level() }
278
279  fn log(&self, record: &Record) {
280    if self.enabled(record.metadata()) {
281      let record_target = record.target();
282      let details = record.args();
283      if record_target == "note" {
284        let note = details.to_string();
285        // A note (e.g. `(Loading foo.sty… )`) is a live progress indicator — but when a capture
286        // buffer is active it must ALSO land there so it reaches the flushed `cortex.log` and
287        // CorTeX's `loaded_file` parser, which anchors on `^(Loading …`. `append_note` keeps it
288        // INLINE (Perl-faithful: `(Loading X… )` on one line, `[1][2]…` chained) while preserving
289        // the `^(Loading` anchor — every `note_begin` carries a leading '\n', so each load still
290        // opens at line start. The following `Info:/Warning:` record re-asserts its own line break
291        // (see the diagnostic-record path below), so the note can't glue onto its anchor.
292        if let Ok(mut buf) = LOG_BUFFER.try_borrow_mut()
293          && let Some(ref mut log) = *buf
294        {
295          append_note(log, &strip_ansi(&note));
296        }
297        // The LOG append above is the log-file record (Perl `$LOG` write, always).
298        // The STDERR echo is the live console indicator and is gated on the
299        // decoupled verbosity: `--quiet` silences the note here while the log
300        // still keeps it (issue #763; Perl `ProgressSpinup` gates STDERR on
301        // `$VERBOSITY >= 0`). Write and publish the cursor state under ONE stderr
302        // lock, so a concurrent diagnostic record cannot observe a stale flag.
303        if stderr_admits(record.level()) {
304          use std::io::Write;
305          let mut err = std::io::stderr().lock();
306          let _ = err.write_all(note.as_bytes());
307          let _ = err.flush();
308          // A note carries no trailing newline of its own unless its text ends
309          // in one (`note_begin` opens with a leading '\n'), so record where it
310          // left the cursor for the next diagnostic record.
311          STDERR_AT_LINE_START.store(note.ends_with('\n'), Ordering::Release);
312        }
313        return;
314      }
315      let category_object = if record_target.is_empty() {
316        "" // "unknown:unknown" ???
317      } else {
318        record_target
319      };
320      // Following the reporting syntax at: https://math.nist.gov/~BMiller/LaTeXML/manual/errorcodes/
321      // The severity word is the FULL Perl LaTeXML token (Info/Warning/Error/Fatal) — consumers
322      // (CorTeX's log parser, the --server LSP) key on it, so it must match Perl exactly. In
323      // particular WARN must serialize as `Warning` (not the abbreviated `Warn`): CorTeX maps an
324      // unrecognized severity to Info, so `Warn:` silently misfiled every warning (see
325      // LaTeXML/lib/LaTeXML/Common/Error.pm: `"Warning:" . $category . …`).
326      let severity = if category_object.starts_with("Fatal:") {
327        ""
328      } else {
329        match record.level() {
330          Level::Info => "Info",
331          Level::Warn => "Warning",
332          Level::Error => "Error",
333          Level::Debug => "Debug",
334          Level::Trace => "Trace",
335        }
336      };
337
338      // Tally every printed diagnostic record that was NOT emitted by a
339      // counting macro (those count at raise time, even under output
340      // suppression — the MAX_ERRORS cap depends on that). This is the
341      // lossless half of the tally contract: any `Warning:`/`Error:` line
342      // this backend prints from a raw `log::warn!`/`log::error!` call now
343      // registers in `REPORT`, so the final "Conversion complete: N
344      // warnings" agrees with what a reader greps from the log. Witness:
345      // the 131 MB witness logged 12,105 `Warning:` lines (12,103 of them
346      // the math parser's raw `log_math_warn!`) and reported "2 warnings".
347      {
348        use crate::common::error::{LogStatus, note_status_from_logger};
349        let status = if category_object.starts_with("Fatal:") {
350          Some(LogStatus::Fatal)
351        } else {
352          match record.level() {
353            Level::Warn => Some(LogStatus::Warning),
354            Level::Error => Some(LogStatus::Error),
355            Level::Info => Some(LogStatus::Info),
356            Level::Debug => Some(LogStatus::Debug),
357            // No Trace counter exists; Trace records stay uncounted.
358            Level::Trace => None,
359          }
360        };
361        if let Some(status) = status {
362          note_status_from_logger(status);
363        }
364      }
365      let message = if severity.is_empty() {
366        s!("{} ", category_object)
367      } else {
368        s!("{}:{} ", severity, category_object)
369      };
370      let painted_message = match record.level() {
371        Level::Info => message,
372        Level::Warn => paint(ANSI_YELLOW, &message),
373        Level::Error => paint(ANSI_RED, &message),
374        Level::Debug => paint(ANSI_GREEN, &message),
375        _ => paint(ANSI_WHITE, &message),
376      } + &details.to_string();
377
378      // Capture to log buffer if active (strip ANSI for clean log text).
379      // A diagnostic record (Info/Warning/Error/Fatal) must start on a fresh
380      // line so CorTeX's line-anchored parser (^Error:/^Warning:/^Info:)
381      // matches and the record never glues onto an in-flight progress note
382      // (notes no longer force a trailing newline — see append_note).
383      if let Ok(mut buf) = LOG_BUFFER.try_borrow_mut()
384        && let Some(ref mut log) = *buf
385      {
386        if !log.is_empty() && !log.ends_with('\n') {
387          log.push('\n');
388        }
389        log.push_str(&strip_ansi(&painted_message));
390        // Exactly one trailing newline — a multi-detail message (e.g.
391        // `Info:…loaded …\n\tat …\n\tIn …`) already ends with '\n', so an
392        // unconditional push would double it into a blank line before the next
393        // `(Loading …` note.
394        if !log.ends_with('\n') {
395          log.push('\n');
396        }
397      }
398
399      // Use `\n` (not `\r`) to guarantee each log line starts on a fresh
400      // line in both TTY and file output. The previous `\r` prefix made
401      // log lines visually overlay any in-flight progress indicator like
402      // `(Loading "foo.sty" definitions... )` — convenient in a terminal
403      // but produced `(...)<CR>Error:...` byte sequences in log files,
404      // breaking line-anchored counts in canvas harnesses
405      // (`grep -cE '^...Error:'` silently returned 0 even when errors
406      // were present). Trade-off: progress indicators in a TTY no longer
407      // get overwritten, but they were not really self-erasing anyway
408      // (they always emitted ` )` to close their parens), so the visual
409      // change is small.
410      // Colorize for an interactive terminal only; when stderr is redirected
411      // to a file/pipe, emit the ANSI-stripped text so on-disk logs stay
412      // grep-clean (matches the captured `.latexml.log` buffer above).
413      // Break onto a fresh line ONLY when a note left the cursor mid-line —
414      // an unconditional leading '\n' was 45.8% of the witness's log (see
415      // STDERR_AT_LINE_START). One critical section: read the flag, write, and
416      // republish it while holding the stderr lock, so the "record starts at
417      // line start" guarantee survives concurrent loggers.
418      //
419      // The LOG_BUFFER append above is the log-file record (Perl `$LOG`, always,
420      // subject only to the Info floor). The STDERR echo is gated on the decoupled
421      // console verbosity so `--quiet` reduces the console without touching the log
422      // (issue #763) — EXCEPT `Error`/`Fatal`, which always reach STDERR (the
423      // project's deliberate always-emit-errors divergence, since cortex aggregates
424      // success rates from `Error:`/`Fatal:` lines). `Error` is the lowest `Level`
425      // value and Fatal records are emitted at `Level::Error`, so `<= Error`
426      // captures both.
427      let to_stderr = record.level() <= Level::Error || stderr_admits(record.level());
428      if to_stderr {
429        use std::io::Write;
430        let text = if stderr_use_color() {
431          painted_message
432        } else {
433          strip_ansi(&painted_message)
434        };
435        let mut err = std::io::stderr().lock();
436        if !STDERR_AT_LINE_START.load(Ordering::Acquire) {
437          let _ = err.write_all(b"\n");
438        }
439        let _ = err.write_all(text.as_bytes());
440        let _ = err.write_all(b"\n");
441        let _ = err.flush();
442        STDERR_AT_LINE_START.store(true, Ordering::Release);
443      }
444    }
445  }
446
447  fn flush(&self) {}
448}
449
450/// initialize the logger at a given STDERR verbosity `level`
451///
452/// `level` is the **console** verbosity (`--quiet` ⇒ `Warn`, default ⇒ `Info`,
453/// `--verbose`/`--debug` ⇒ `Debug`). Perl decouples this from the log-file floor:
454/// the `.latexml.log` keeps a minimum of `Info` regardless of `--quiet`, while
455/// STDERR follows `level` (`Common/Error.pm` `_printline`; issue #763). So the
456/// global `log` `max_level` is set to the MORE verbose of `level` and `Info` (the
457/// floor), admitting to `LatexmlLogger::log` everything the log needs; the STDERR
458/// echo is then gated separately on the `STDERR_LEVEL` atomic.
459///
460/// Returns the underlying `SetLoggerError` if another `log` global logger
461/// is already installed (e.g. an embedder set up `tracing-log` first).
462/// Callers can decide whether to ignore that — the in-process `bind_log` /
463/// `flush_log` buffers are independent of the `log` crate sink and keep
464/// working either way.
465pub fn init(level: LevelFilter) -> Result<(), SetLoggerError> {
466  // Global config (STDERR gate + log-file floor) is set unconditionally — it must
467  // reflect the requested verbosity even if the logger was already installed (a
468  // second `init` in-process returns `Err` from `set_logger`, which callers `.ok()`).
469  STDERR_LEVEL.store(level as usize, Ordering::Relaxed);
470  log::set_max_level(level.max(LevelFilter::Info));
471  log::set_logger(&LOGGER)
472}
473
474#[cfg(test)]
475mod tests {
476  use super::*;
477
478  #[test]
479  fn append_note_inline_and_no_blank_lines() {
480    // note_begin opens a fresh line; note_end / note_progress stay inline.
481    let mut b = String::new();
482    append_note(&mut b, "\n(Loading keyval.sty..."); // note_begin (buffer empty: no leading blank)
483    append_note(&mut b, " )"); // note_end inline
484    assert_eq!(b, "(Loading keyval.sty... )");
485    append_note(&mut b, "\n(Loading graphics.sty..."); // mid-line: keep the break
486    append_note(&mut b, " )");
487    assert_eq!(b, "(Loading keyval.sty... )\n(Loading graphics.sty... )");
488    // page markers chain inline
489    append_note(&mut b, "\n410 formulae ...");
490    append_note(&mut b, "[1]");
491    append_note(&mut b, "[2]");
492    assert!(b.ends_with("410 formulae ...[1][2]"));
493    // a leading '\n' note after a buffer already at line-start collapses (no blank line)
494    let mut c = String::from("Info:foo\n");
495    append_note(&mut c, "\n(Building...");
496    assert_eq!(c, "Info:foo\n(Building...");
497  }
498
499  /// The lossless-tally contract (user directive 2026-08-02): every printed
500  /// diagnostic record counts exactly once, whether it came from a counting
501  /// macro (raise-time count, logger skips) or a raw `log::warn!`-family call
502  /// (logger counts). Defect this pins: the 131 MB witness logged 12,105
503  /// `Warning:` lines — 12,103 from the math parser's raw `log_math_warn!` —
504  /// and the final verdict said "2 warnings".
505  ///
506  /// One test, not several: the global logger and the thread-local `REPORT`
507  /// are both process/thread state, and cargo runs sibling `#[test]`s on
508  /// separate threads — but a SINGLE test body sees one thread and one
509  /// deterministic sequence.
510  #[test]
511  fn raw_log_records_count_and_macro_records_do_not_double_count() {
512    use crate::common::error::{
513      LogStatus, get_status, initialize_report, macro_diag_guard, note_status,
514      note_status_from_logger,
515    };
516    // Another test may have installed the logger already; counting rides
517    // note_status_from_logger either way, so drive it exactly as
518    // `LatexmlLogger::log` does rather than through the global sink.
519    initialize_report();
520
521    // Raw record: the logger's tally path counts it.
522    note_status_from_logger(LogStatus::Warning);
523    assert_eq!(get_status(LogStatus::Warning), 1, "raw warning must count");
524
525    // Macro-emitted record: raise-time count happens under the guard, and
526    // the logger's observation of the same record must be a no-op.
527    {
528      let _g = macro_diag_guard();
529      note_status(LogStatus::Warning, None); // what the macro does
530      note_status_from_logger(LogStatus::Warning); // what the logger then sees
531    }
532    assert_eq!(
533      get_status(LogStatus::Warning),
534      2,
535      "a macro warning counts once, not twice"
536    );
537
538    // Nested guards (Error! escalating into Fatal!) keep the marker set.
539    {
540      let _outer = macro_diag_guard();
541      {
542        let _inner = macro_diag_guard();
543      }
544      note_status_from_logger(LogStatus::Error);
545    }
546    assert_eq!(
547      get_status(LogStatus::Error),
548      0,
549      "the logger stays muted for the whole macro emission, even after a \
550       nested guard drops"
551    );
552
553    // Raw error and a raw Fatal-target record (log_fatal's shape when some
554    // future caller bypasses it): the error counts, the fatal latches.
555    note_status_from_logger(LogStatus::Error);
556    note_status_from_logger(LogStatus::Fatal);
557    assert_eq!(get_status(LogStatus::Error), 1);
558    assert_eq!(get_status(LogStatus::Fatal), 1, "raw fatal latches sticky");
559    initialize_report();
560  }
561
562  /// Suppression semantics (user decision 2026-08-03): Debug/Info/Warning
563  /// records are muted under suppression, but Error and Fatal EMIT
564  /// UNCONDITIONALLY — cortex-class frameworks aggregate success rates from
565  /// `Error:`/`Fatal:` lines, and a suppressed error would vanish from that
566  /// measurement while still counting locally. Counts accrue either way.
567  #[test]
568  fn suppression_never_mutes_error_or_fatal() {
569    use crate::common::error::{
570      LogStatus, emit_record, get_status, initialize_report, set_suppress_log_output,
571    };
572    initialize_report();
573    let _ = log::set_logger(&LOGGER); // ok if another test installed it
574    log::set_max_level(LevelFilter::Warn);
575    let prev = set_suppress_log_output(true);
576
577    bind_log();
578    emit_record(LogStatus::Warning, "quiet:warn", "muted warning");
579    emit_record(LogStatus::Error, "loud:error", "unmutable error");
580    emit_record(LogStatus::Fatal, "Fatal:loud:fatal ", "unmutable fatal");
581    let captured = flush_log();
582
583    set_suppress_log_output(prev);
584    assert!(
585      !captured.contains("muted warning"),
586      "suppression must mute Warning records, captured:\n{captured}"
587    );
588    assert!(
589      captured.contains("Error:loud:error unmutable error"),
590      "Error must emit under suppression, captured:\n{captured}"
591    );
592    // (Fatal targets carry their own trailing space, so the formatter's
593    // separator makes it two — match the pieces, not the join.)
594    assert!(
595      captured.contains("Fatal:loud:fatal") && captured.contains("unmutable fatal"),
596      "Fatal must emit under suppression, captured:\n{captured}"
597    );
598    // Counts accrue regardless of emission.
599    assert_eq!(get_status(LogStatus::Warning), 1);
600    assert_eq!(get_status(LogStatus::Error), 1);
601    assert_eq!(get_status(LogStatus::Fatal), 1);
602    initialize_report();
603  }
604
605  #[test]
606  fn strip_ansi_removes_color_codes() {
607    // ESC [ ... m should vanish; other content preserved.
608    let red = "\x1b[31mhello\x1b[0m";
609    assert_eq!(strip_ansi(red), "hello");
610  }
611
612  #[test]
613  fn strip_ansi_noop_on_plain() {
614    assert_eq!(strip_ansi("plain text"), "plain text");
615    assert_eq!(strip_ansi(""), "");
616  }
617
618  #[test]
619  fn strip_ansi_multiple_sequences() {
620    let s = "\x1b[31merror:\x1b[0m \x1b[33mwarning\x1b[0m";
621    assert_eq!(strip_ansi(s), "error: warning");
622  }
623
624  #[test]
625  fn strip_ansi_preserves_unicode() {
626    let s = "\x1b[31mαβγ\x1b[0m";
627    assert_eq!(strip_ansi(s), "αβγ");
628  }
629
630  #[test]
631  fn strip_ansi_handles_incomplete_escape() {
632    // Unterminated ESC[ sequence — we should not hang.
633    // Current impl: scan until 'm' is found. If never found, consumes
634    // the rest of the input. Document that behavior.
635    let s = "\x1b[1;31m hello";
636    // The scan consumes characters until 'm' is found → the 'm' in the
637    // escape closes, then " hello" remains.
638    assert_eq!(strip_ansi(s), " hello");
639  }
640
641  #[test]
642  fn bind_log_and_flush_log_roundtrip() {
643    // Before bind_log, flush_log returns empty.
644    // After bind_log, the buffer is active but empty until a log
645    // message arrives. Since we can't easily exercise the Log impl
646    // without initializing a global logger, just verify the
647    // capture-buffer lifecycle primitives.
648    let before = flush_log();
649    assert!(before.is_empty(), "no active buffer → empty flush");
650
651    bind_log();
652    let after = flush_log();
653    assert!(
654      after.is_empty(),
655      "empty buffer is still empty after bind/flush with no log traffic"
656    );
657  }
658}