dev: add logging

CHANGELOG.md

@@ -7,6 +7,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [Unreleased]
 
+- feat: add `--verbose` and `--debug-log` diagnostics; install a `log` implementation so resvg/usvg warnings are no longer discarded (#78)
+
 ## [0.9.0] - 2026-01-15
 
 - feat: auto-populate changelog and add shellcheck CI (#19)

Cargo.toml

@@ -16,6 +16,9 @@ name = "mdriver"
 path = "src/main.rs"
 
 [dependencies]
+# Installs a logger for the `log` diagnostics emitted by usvg/resvg/fontdb/ureq,
+# which are otherwise discarded. See src/logging.rs.
+log = "0.4.33"
 two-face = "0.5.1"
 syntect = { version = "5.3.0", default-features = false, features = ["default-syntaxes", "default-themes", "regex-fancy", "parsing", "html", "dump-load", "dump-create"] }
 ureq = "3.3.0"

README.md

@@ -100,10 +100,49 @@ mdriver --images kitty document.md
 # Control color output (auto, always, never)
 mdriver --color=always README.md | less -R
 
+# Report rendering problems (missing fonts, skipped SVG content) to stderr
+mdriver --verbose --images kitty diagram.md
+
+# Capture full diagnostics to a file for a bug report
+mdriver --debug-log /tmp/mdriver.log --images kitty diagram.md
+
 # Show help
 mdriver --help
 ```
 
+## Diagnostics
+
+By default mdriver is silent: when it cannot render something it falls back
+quietly, showing alt text for a broken image or a syntax-highlighted code block
+for a Mermaid diagram it could not draw.
+
+That is the right default for everyday use, but it makes some failures hard to
+diagnose. The worst case is a diagram that renders as a *plausible* image with
+content missing — for example shapes drawn with every label dropped because no
+font matched. Two flags turn on reporting:
+
+```bash
+# Warnings to stderr
+mdriver --verbose --images kitty diagram.md
+
+# Everything to a file, including HTTP and TLS activity
+mdriver --debug-log /tmp/mdriver.log --images kitty diagram.md
+```
+
+`--verbose` (or `-v`) reports warnings from mdriver and from the SVG renderer it
+uses, such as skipped SVG elements, unresolvable fonts, and image or Mermaid
+fallbacks. `--debug-log <FILE>` writes every message, timestamped and truncating
+the file each run; it is more detail than is usually useful, but it is what you
+want attached to a bug report. Both can be used together.
+
+Diagnostics only ever go to stderr or the log file, never to stdout, so neither
+flag changes rendered output. Piping and redirection are unaffected:
+
+```bash
+mdriver --verbose --color=always README.md > out.txt   # warnings still on terminal
+mdriver --verbose --color=always README.md 2>/dev/null # warnings discarded
+```
+
 ## Syntax Highlighting Themes
 
 mdriver uses the [syntect](https://github.com/trishume/syntect) library for syntax highlighting, supporting 100+ languages with customizable color themes.

src/lib.rs

@@ -3,12 +3,15 @@ use std::sync::LazyLock;
 use std::time::Duration;
 
 use htmlentity::entity::{decode as decode_html_entity_bytes, ICodedDataTrait};
+use log::{debug, warn};
 use syntect::easy::HighlightLines;
 use syntect::parsing::SyntaxSet;
 use syntect::util::as_24_bit_terminal_escaped;
 use two_face::theme::{EmbeddedLazyThemeSet, EmbeddedThemeName};
 use unicode_width::UnicodeWidthStr;
 
+pub mod logging;
+
 // Static theme set using two-face's extended themes
 static THEME_SET: LazyLock<EmbeddedLazyThemeSet> = LazyLock::new(two_face::theme::extra);
 
@@ -296,8 +299,15 @@ impl StreamingParser {
 
         // Collect results
         for (url, result) in rx {
-            if let Ok(data) = result {
-                self.image_cache.insert(url, data);
+            match result {
+                Ok(data) => {
+                    self.image_cache.insert(url, data);
+                }
+                // Not fatal: load_image_data retries this URL on demand, and
+                // render_image falls back to alt text. Worth a line either way,
+                // since a prefetch failure usually means every later attempt
+                // fails too.
+                Err(e) => warn!("image: prefetch of {url} failed: {e}"),
             }
         }
     }
@@ -1525,9 +1535,15 @@ impl StreamingParser {
         for line in lines {
             // Add newline for proper syntax highlighting state management
             let line_with_newline = format!("{}\n", line);
-            let ranges = highlighter
-                .highlight_line(&line_with_newline, &self.syntax_set)
-                .unwrap_or_default();
+            let ranges = match highlighter.highlight_line(&line_with_newline, &self.syntax_set) {
+                Ok(ranges) => ranges,
+                Err(e) => {
+                    // Losing highlighting on one line is survivable, but the line
+                    // then renders unstyled with no indication why.
+                    warn!("highlight: {language}: {e}; line rendered without highlighting");
+                    Vec::new()
+                }
+            };
             let highlighted = as_24_bit_terminal_escaped(&ranges[..], false);
             // Remove the trailing newline from highlighted output
             let highlighted = highlighted.trim_end_matches('\n').to_string();
@@ -1572,15 +1588,39 @@ impl StreamingParser {
 
         let svg_string = match rx.recv_timeout(MERMAID_RENDER_TIMEOUT) {
             Ok(Ok(Some(svg))) => svg,
-            _ => return None, // Timeout, render error, or no diagram detected
+            // Each of these degrades to a plain code block, which looks deliberate.
+            // Say which one it was, or the user has no way to tell a syntax error
+            // from a slow diagram.
+            Ok(Ok(None)) => {
+                debug!("mermaid: no diagram detected in fenced block; rendering as code");
+                return None;
+            }
+            Ok(Err(e)) => {
+                warn!("mermaid: render failed: {e}; rendering as code block");
+                return None;
+            }
+            Err(std::sync::mpsc::RecvTimeoutError::Timeout) => {
+                warn!(
+                    "mermaid: render exceeded {:?} timeout; rendering as code block",
+                    MERMAID_RENDER_TIMEOUT
+                );
+                return None;
+            }
+            Err(std::sync::mpsc::RecvTimeoutError::Disconnected) => {
+                warn!("mermaid: render thread died; rendering as code block");
+                return None;
+            }
         };
 
         let svg_bytes = svg_string.as_bytes();
 
         // Use the existing SVG→raster→kitty pipeline
         match self.process_image(svg_bytes) {
             Ok(kitty_output) => Some(format!("{}\n", kitty_output)),
-            Err(_) => None,
+            Err(e) => {
+                warn!("mermaid: rasterizing rendered SVG failed: {e}; rendering as code block");
+                None
+            }
         }
     }
 
@@ -2538,10 +2578,16 @@ impl StreamingParser {
                         // Process and render
                         match self.process_image(&data) {
                             Ok(kitty_output) => kitty_output,
-                            Err(_) => alt.to_string(), // Fallback to alt text
+                            Err(e) => {
+                                warn!("image: decoding {src} failed: {e}; showing alt text");
+                                alt.to_string()
+                            }
                         }
                     }
-                    Err(_) => alt.to_string(), // Fallback to alt text
+                    Err(e) => {
+                        warn!("image: loading {src} failed: {e}; showing alt text");
+                        alt.to_string()
+                    }
                 }
             }
         }
@@ -2747,13 +2793,17 @@ impl StreamingParser {
 
         let mut fontdb = fontdb::Database::new();
         if let Some(path) = &emoji_path {
-            let _ = fontdb.load_font_file(path);
+            if let Err(e) = fontdb.load_font_file(path) {
+                warn!("svg: loading emoji font {}: {e}", path.display());
+            }
         } else {
+            // Once per process, not once per diagram: a document with many
+            // diagrams would otherwise repeat this for each one.
             use std::sync::atomic::{AtomicBool, Ordering};
             static WARNED: AtomicBool = AtomicBool::new(false);
             if !WARNED.swap(true, Ordering::Relaxed) {
-                eprintln!(
-                    "mdriver: warning: no emoji font found; \
+                warn!(
+                    "svg: no emoji font found; \
                      emoji in SVG/Mermaid diagrams may render incorrectly"
                 );
             }

src/logging.rs

@@ -0,0 +1,166 @@
+//! Minimal `log` implementation for mdriver.
+//!
+//! mdriver's dependencies emit diagnostics through the `log` crate, but a `log`
+//! call is a no-op until a logger is installed. Without one, every message is
+//! discarded — most importantly the ~60 `warn!` sites in `usvg` that fire when it
+//! skips SVG content it cannot render. Those warnings are the difference between
+//! "this Mermaid diagram lost all its labels for an unknown reason" and a one-line
+//! explanation, so we install a logger and let the user turn it on.
+//!
+//! Sources of `log` output we consume today:
+//!
+//! - `usvg` / `resvg`: skipped SVG elements, unresolvable fonts, invalid filters
+//! - `fontdb`: font loading failures
+//! - `ureq` / `ureq-proto` / `rustls`: HTTP and TLS activity when fetching URLs
+//! - mdriver itself: rendering fallbacks that would otherwise be invisible
+//!
+//! Two independent sinks, either or both of which may be enabled:
+//!
+//! - stderr, at `WARN`, via `--verbose`
+//! - a file, at `TRACE`, via `--debug-log <FILE>`
+//!
+//! Deliberately not `env_logger`: it pulls in a regex-based filter that is far
+//! more machinery than two fixed levels need.
+//!
+//! Diagnostics never touch stdout. stdout carries the ANSI stream and terminal
+//! image payloads, and interleaving log lines with a kitty escape sequence would
+//! corrupt the image.
+
+use std::fs::File;
+use std::io::{self, Write};
+use std::path::Path;
+use std::sync::Mutex;
+use std::time::Instant;
+
+/// Level for the stderr sink when `--verbose` is given.
+///
+/// `WARN` rather than `INFO` because the interesting messages (content skipped,
+/// font unresolved) are warnings, while `INFO` and below is mostly HTTP and TLS
+/// chatter from ureq that has nothing to do with rendering.
+const VERBOSE_LEVEL: log::LevelFilter = log::LevelFilter::Warn;
+
+/// Level for the `--debug-log` file sink. A file is not competing with the
+/// user's terminal, so capture everything for bug reports.
+const DEBUG_FILE_LEVEL: log::LevelFilter = log::LevelFilter::Trace;
+
+struct Logger {
+    /// Enabled by `--verbose`. Writes at [`VERBOSE_LEVEL`].
+    stderr: bool,
+    /// Enabled by `--debug-log`. Writes at [`DEBUG_FILE_LEVEL`].
+    ///
+    /// A `Mutex` because `log::Log` requires `Sync` and mdriver renders Mermaid
+    /// on a worker thread, so records genuinely arrive from more than one thread.
+    file: Option<Mutex<File>>,
+    /// Process start, used to stamp file records with elapsed time. Cheaper than
+    /// taking on a date/time dependency for what is only ever read relative to
+    /// other lines in the same run.
+    start: Instant,
+}
+
+impl log::Log for Logger {
+    fn enabled(&self, metadata: &log::Metadata) -> bool {
+        let level = metadata.level();
+        (self.stderr && level <= VERBOSE_LEVEL)
+            || (self.file.is_some() && level <= DEBUG_FILE_LEVEL)
+    }
+
+    fn log(&self, record: &log::Record) {
+        let level = record.level();
+
+        if self.stderr && level <= VERBOSE_LEVEL {
+            // Dependency targets (`usvg::tree`) identify where a warning came from and
+            // are worth showing. Our own target is always `mdriver`, which would just
+            // repeat the prefix, so drop it.
+            let target = record.target();
+            let origin = if target == env!("CARGO_PKG_NAME") {
+                String::new()
+            } else {
+                format!("{target}: ")
+            };
+            // Ignore write errors: stderr may be closed, and failing to report a
+            // warning must never take down a render.
+            let _ = writeln!(
+                io::stderr(),
+                "mdriver: {}: {origin}{}",
+                level.as_str().to_lowercase(),
+                record.args()
+            );
+        }
+
+        if level <= DEBUG_FILE_LEVEL {
+            if let Some(file) = &self.file {
+                // A poisoned lock means another thread panicked mid-write. The
+                // file may have a torn line, but dropping all later records is
+                // worse than continuing, so recover the guard either way.
+                let mut file = match file.lock() {
+                    Ok(guard) => guard,
+                    Err(poisoned) => poisoned.into_inner(),
+                };
+                let elapsed = self.start.elapsed().as_millis();
+                let _ = writeln!(
+                    file,
+                    "[+{:>6}ms {:<5} {}] {}",
+                    elapsed,
+                    level.as_str(),
+                    record.target(),
+                    record.args()
+                );
+                // Flush per record. Debug logs are most valuable when the run
+                // ends badly, which is exactly when buffered tail lines are lost.
+                let _ = file.flush();
+            }
+        }
+    }
+
+    fn flush(&self) {
+        if let Some(file) = &self.file {
+            let mut file = match file.lock() {
+                Ok(guard) => guard,
+                Err(poisoned) => poisoned.into_inner(),
+            };
+            let _ = file.flush();
+        }
+    }
+}
+
+/// Install the global logger.
+///
+/// `verbose` sends warnings to stderr; `debug_log` sends everything to that
+/// path, truncating it. Both may be enabled at once. With neither, no logger is
+/// installed at all, so `log` calls stay at their default no-op cost and mdriver
+/// remains silent — usvg's benign-but-frequent warnings (`Fallback from X to Y.`
+/// fires routinely for emoji) should not appear unless asked for.
+///
+/// Returns an error only if `debug_log` cannot be opened, which is worth
+/// reporting: the user explicitly asked for a log at that path.
+pub fn init(verbose: bool, debug_log: Option<&Path>) -> io::Result<()> {
+    let file = match debug_log {
+        Some(path) => Some(File::create(path)?),
+        None => None,
+    };
+
+    if !verbose && file.is_none() {
+        return Ok(());
+    }
+
+    let max = if file.is_some() {
+        DEBUG_FILE_LEVEL
+    } else {
+        VERBOSE_LEVEL
+    };
+
+    let logger = Logger {
+        stderr: verbose,
+        file: file.map(Mutex::new),
+        start: Instant::now(),
+    };
+
+    // set_boxed_logger only fails if a logger is already installed, which can
+    // only happen if init is called twice. Nothing to report, and no reason to
+    // fail the run.
+    if log::set_boxed_logger(Box::new(logger)).is_ok() {
+        log::set_max_level(max);
+    }
+
+    Ok(())
+}