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(¬e[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(¬e));
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}