From 5401354f2ef1e7531fef3cb624dc4aa8e9f03cc1 Mon Sep 17 00:00:00 2001 From: Abimael Martell Date: Wed, 18 Feb 2026 10:34:32 -0800 Subject: [PATCH] add logging --- AGENTS.md | 26 ++++++---- Cargo.toml | 20 +------- README.md | 34 ++++++++++--- src/bin/detect_pdf.rs | 1 + src/bin/pdf2md.rs | 1 + src/extractor/content_stream.rs | 2 + src/extractor/fonts.rs | 52 ++++++++++++++++++++ src/extractor/layout.rs | 55 ++++++++++++++++++++- src/extractor/mod.rs | 25 ++++++++++ src/markdown/analysis.rs | 87 ++++++++++++++++++++++++++++++--- src/tables/detect_heuristic.rs | 8 +++ src/tounicode.rs | 13 +++++ 12 files changed, 281 insertions(+), 43 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 059b73d..490a86c 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -47,15 +47,6 @@ src/ bin/ pdf2md.rs — CLI: PDF → Markdown detect_pdf.rs — CLI: detect PDF type - debug_spaces.rs — Debug: dump text items with x/y/width per page - dump_ops.rs — Debug: dump raw PDF content stream operators - debug_ygaps.rs — Debug: Y-gap analysis between lines - debug_fonts.rs — Debug: font information - debug_ligatures.rs — Debug: ligature expansion - debug_order.rs — Debug: reading order - debug_pages.rs — Debug: page-level info - detection_report.rs — Batch detection report on PDF directory - profile_stages.rs — Performance profiling of pipeline stages ``` ## Data Flow @@ -120,6 +111,23 @@ cargo fmt --check # Format check cargo run --release --bin pdf2md -- # Smoke test ``` +## Debugging with RUST_LOG + +All debug output uses structured logging via the `log` crate. Set `RUST_LOG` to control output: + +```bash +RUST_LOG=pdf_inspector::extractor::content_stream=trace # raw PDF operators +RUST_LOG=pdf_inspector::extractor::fonts=debug # font metadata + encodings +RUST_LOG=pdf_inspector::tounicode=debug # CMap parsing +RUST_LOG=pdf_inspector::extractor=debug # text items per page +RUST_LOG=pdf_inspector::extractor::layout=debug # columns, reading order +RUST_LOG=pdf_inspector::markdown::analysis=debug # Y-gaps, paragraph threshold +RUST_LOG=pdf_inspector::tables=debug # table detection +RUST_LOG=pdf_inspector=debug # everything +``` + +Example: `RUST_LOG=pdf_inspector::extractor::fonts=debug cargo run --bin pdf2md -- file.pdf > /dev/null` + ## Common Tasks | Task | Where to Edit | diff --git a/Cargo.toml b/Cargo.toml index 5f63730..6d4490c 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -23,6 +23,7 @@ rayon = "1.10" # Logging log = "0.4" +env_logger = "0.11" # Text processing regex = "1.10" @@ -43,22 +44,3 @@ name = "detect-pdf" path = "src/bin/detect_pdf.rs" -[[bin]] -name = "debug_ygaps" -path = "src/bin/debug_ygaps.rs" - -[[bin]] -name = "debug_pages" -path = "src/bin/debug_pages.rs" - -[[bin]] -name = "debug_fonts" -path = "src/bin/debug_fonts.rs" - -[[bin]] -name = "dump_ops" -path = "src/bin/dump_ops.rs" - -[[bin]] -name = "debug_spaces" -path = "src/bin/debug_spaces.rs" diff --git a/README.md b/README.md index c52c03e..48efe48 100644 --- a/README.md +++ b/README.md @@ -150,7 +150,7 @@ src/ extractor/ — Text extraction pipeline tables/ — Table detection and formatting markdown/ — Markdown conversion and structure detection - bin/ — CLI tools and debug utilities + bin/ — CLI tools (pdf2md, detect_pdf) ``` ## How classification works @@ -226,14 +226,34 @@ The converter handles: | Drop caps | Large initial letters merged with following text | | Dot leaders | TOC-style dots collapsed to " ... " | -## Debug tools +## Debugging with RUST_LOG + +Structured logging via `RUST_LOG` replaces the former debug binaries. Set the environment variable to control which sections emit debug output on stderr: ```bash -cargo run --bin debug_spaces -- file.pdf # Text items with x/y/width per page -cargo run --bin dump_ops -- file.pdf # Raw PDF content stream operators -cargo run --bin debug_ygaps -- file.pdf # Y-gap analysis between lines -cargo run --bin debug_fonts -- file.pdf # Font information -cargo run --bin debug_order -- file.pdf # Reading order visualization +# Raw PDF content stream operators (replaces dump_ops) +RUST_LOG=pdf_inspector::extractor::content_stream=trace cargo run --bin pdf2md -- file.pdf > /dev/null + +# Font metadata, encodings, ligatures (replaces debug_fonts / debug_ligatures) +RUST_LOG=pdf_inspector::extractor::fonts=debug cargo run --bin pdf2md -- file.pdf > /dev/null + +# ToUnicode CMap parsing +RUST_LOG=pdf_inspector::tounicode=debug cargo run --bin pdf2md -- file.pdf > /dev/null + +# Text items per page with x/y/width (replaces debug_spaces / debug_pages) +RUST_LOG=pdf_inspector::extractor=debug cargo run --bin pdf2md -- file.pdf > /dev/null + +# Column detection and reading order (replaces debug_order) +RUST_LOG=pdf_inspector::extractor::layout=debug cargo run --bin pdf2md -- file.pdf > /dev/null + +# Y-gap analysis and paragraph thresholds (replaces debug_ygaps) +RUST_LOG=pdf_inspector::markdown::analysis=debug cargo run --bin pdf2md -- file.pdf > /dev/null + +# Table detection +RUST_LOG=pdf_inspector::tables=debug cargo run --bin pdf2md -- file.pdf > /dev/null + +# Everything +RUST_LOG=pdf_inspector=debug cargo run --bin pdf2md -- file.pdf > /dev/null ``` ## Use case: smart PDF routing diff --git a/src/bin/detect_pdf.rs b/src/bin/detect_pdf.rs index 1294970..811e721 100644 --- a/src/bin/detect_pdf.rs +++ b/src/bin/detect_pdf.rs @@ -6,6 +6,7 @@ use std::process; use std::time::Instant; fn main() { + env_logger::init(); let args: Vec = env::args().collect(); if args.len() < 2 { diff --git a/src/bin/pdf2md.rs b/src/bin/pdf2md.rs index a4294b2..b2b2dfa 100644 --- a/src/bin/pdf2md.rs +++ b/src/bin/pdf2md.rs @@ -43,6 +43,7 @@ fn parse_page_spec(spec: &str) -> Result, String> { } fn main() { + env_logger::init(); let args: Vec = env::args().collect(); if args.len() < 2 { diff --git a/src/extractor/content_stream.rs b/src/extractor/content_stream.rs index 312412e..24015cb 100644 --- a/src/extractor/content_stream.rs +++ b/src/extractor/content_stream.rs @@ -9,6 +9,7 @@ use crate::text_utils::{ use crate::tounicode::FontCMaps; use crate::types::{ItemType, PdfRect, TextItem}; use crate::PdfError; +use log::trace; use lopdf::{Document, Encoding, Object, ObjectId}; use std::collections::HashMap; @@ -100,6 +101,7 @@ pub(crate) fn extract_page_text_items( let mut actual_text_start_tm: Option<[f32; 6]> = None; // text matrix at BDC entry for op in &content.operations { + trace!("{} {:?}", op.operator, op.operands); match op.operator.as_str() { "q" => { // Save graphics state diff --git a/src/extractor/fonts.rs b/src/extractor/fonts.rs index 8255864..53e7ed5 100644 --- a/src/extractor/fonts.rs +++ b/src/extractor/fonts.rs @@ -3,6 +3,7 @@ use crate::glyph_names::glyph_to_char; use crate::tounicode::FontCMaps; use crate::types::{FontEncodingMap, FontWidthInfo, PageFontEncodings, PageFontWidths}; +use log::debug; use lopdf::{Document, Encoding, Object}; use std::collections::HashMap; @@ -42,6 +43,37 @@ pub(crate) fn build_font_widths( for (font_name, font_dict) in fonts { let resource_name = String::from_utf8_lossy(font_name).to_string(); + + let subtype = font_dict + .get(b"Subtype") + .ok() + .and_then(|o| o.as_name().ok()) + .map(|n| String::from_utf8_lossy(n).to_string()) + .unwrap_or_default(); + let base_font = font_dict + .get(b"BaseFont") + .ok() + .and_then(|o| o.as_name().ok()) + .map(|n| String::from_utf8_lossy(n).to_string()) + .unwrap_or_default(); + let has_tounicode = font_dict.get(b"ToUnicode").is_ok(); + let has_descendants = font_dict.get(b"DescendantFonts").is_ok(); + let encoding_str = font_dict + .get(b"Encoding") + .ok() + .map(|o| match o { + Object::Name(n) => String::from_utf8_lossy(n).to_string(), + Object::Reference(_) => "ref(dict)".to_string(), + Object::Dictionary(_) => "dict".to_string(), + _ => format!("{:?}", o), + }) + .unwrap_or_else(|| "none".to_string()); + + debug!( + "font {:<10} sub={:<12} base={:<45} toUni={:<6} enc={:<20} cid={}", + resource_name, subtype, base_font, has_tounicode, encoding_str, has_descendants + ); + if let Some(info) = parse_font_widths(doc, font_dict) { widths.insert(resource_name, info); } @@ -452,6 +484,7 @@ pub(crate) fn parse_encoding_dictionary( let mut encoding_map = FontEncodingMap::new(); let mut current_code: u8 = 0; + let mut ligature_count = 0u32; for item in diff_array { match item { @@ -462,6 +495,17 @@ pub(crate) fn parse_encoding_dictionary( Object::Name(name) => { // Map current code to glyph name -> Unicode let glyph_name = String::from_utf8_lossy(&name).to_string(); + if glyph_name == "fi" + || glyph_name == "fl" + || glyph_name == "ffi" + || glyph_name == "ffl" + { + debug!( + " Differences: code=0x{:02X} glyph={:?} (ligature)", + current_code, glyph_name + ); + ligature_count += 1; + } if let Some(ch) = glyph_to_char(&glyph_name) { encoding_map.insert(current_code, ch); } @@ -471,6 +515,14 @@ pub(crate) fn parse_encoding_dictionary( } } + if ligature_count > 0 { + debug!( + " Differences: {} total entries, {} ligatures", + encoding_map.len(), + ligature_count + ); + } + if encoding_map.is_empty() { None } else { diff --git a/src/extractor/layout.rs b/src/extractor/layout.rs index 832b7ac..a1be8eb 100644 --- a/src/extractor/layout.rs +++ b/src/extractor/layout.rs @@ -2,6 +2,7 @@ use crate::text_utils::{effective_width, sort_line_items}; use crate::types::{TextItem, TextLine}; +use log::debug; /// Represents a column region on a page #[derive(Debug, Clone)] @@ -170,6 +171,16 @@ pub(crate) fn detect_columns(items: &[TextItem], page: u32) -> Vec return vec![ColumnRegion { x_min, x_max }]; } + debug!( + "page {}: {} columns detected (boundaries: {:?})", + page, + valid_valleys.len() + 1, + valid_valleys + .iter() + .map(|(s, e)| x_min + ((*s + *e) as f32 / 2.0) * BIN_WIDTH) + .collect::>() + ); + // Limit to at most 3 gutters (4 columns) — keep the widest if more found if valid_valleys.len() > 3 { valid_valleys.sort_by(|a, b| { @@ -401,6 +412,39 @@ pub fn group_into_lines(items: Vec) -> Vec { col_buckets[best_col].push(item.clone()); } + debug!( + "page {}: {} columns, {} spanning items", + page, + columns.len(), + spanning_items.len() + ); + for (ci, col) in columns.iter().enumerate() { + debug!( + " col {}: x=[{:.0}..{:.0}] {} items", + ci, + col.x_min, + col.x_max, + col_buckets[ci].len() + ); + } + if log::log_enabled!(log::Level::Trace) { + for (ci, bucket) in col_buckets.iter().enumerate() { + for item in bucket { + log::trace!( + " col {} <- x={:7.1} y={:7.1} {:?}", + ci, + item.x, + item.y, + if item.text.len() > 60 { + &item.text[..60] + } else { + &item.text + } + ); + } + } + } + let mut per_column_lines: Vec> = Vec::new(); for col_items in col_buckets { let lines = group_single_column(col_items); @@ -410,7 +454,14 @@ pub fn group_into_lines(items: Vec) -> Vec { // Process spanning items as their own group let spanning_lines = group_single_column(spanning_items); - if is_newspaper_layout(&per_column_lines) { + let is_newspaper = is_newspaper_layout(&per_column_lines); + debug!( + "page {}: layout={}", + page, + if is_newspaper { "newspaper" } else { "tabular" } + ); + + if is_newspaper { // Newspaper: columns are independent text flows. // 1. Split each column into its densest cluster (core) and stragglers // 2. Use core columns to determine the above/below threshold @@ -631,5 +682,7 @@ fn group_single_column(items: Vec) -> Vec { sort_line_items(&mut line.items); } + debug!("group_single_column: {} lines", lines.len()); + lines } diff --git a/src/extractor/mod.rs b/src/extractor/mod.rs index c109245..7d54566 100644 --- a/src/extractor/mod.rs +++ b/src/extractor/mod.rs @@ -12,6 +12,7 @@ use crate::text_utils::is_rtl_text; use crate::tounicode::FontCMaps; use crate::types::{PdfRect, TextItem}; use crate::PdfError; +use log::debug; use lopdf::{Document, Object, ObjectId}; use std::collections::{HashMap, HashSet}; use std::path::Path; @@ -145,6 +146,30 @@ fn extract_positioned_text_from_doc( } } let (items, rects) = extract_page_text_items(doc, page_id, *page_num, font_cmaps)?; + debug!( + "page {}: {} text items, {} rects", + page_num, + items.len(), + rects.len() + ); + if log::log_enabled!(log::Level::Trace) { + for item in &items { + log::trace!( + " p={} x={:7.1} y={:7.1} w={:7.1} fs={:5.1} font={:6} {:?}", + page_num, + item.x, + item.y, + item.width, + item.font_size, + item.font, + if item.text.len() > 80 { + &item.text[..80] + } else { + &item.text + } + ); + } + } all_items.extend(items); all_rects.extend(rects); diff --git a/src/markdown/analysis.rs b/src/markdown/analysis.rs index 0eea028..e060075 100644 --- a/src/markdown/analysis.rs +++ b/src/markdown/analysis.rs @@ -3,6 +3,7 @@ use std::collections::HashMap; use crate::types::{TextItem, TextLine}; +use log::debug; /// Font statistics for a document pub(crate) struct FontStats { @@ -118,13 +119,85 @@ pub(crate) fn compute_paragraph_threshold(lines: &[TextLine], base_size: f32) -> let median = gaps[gaps.len() / 2]; - // The paragraph threshold should be larger than the typical line spacing. - // Use 1.3x the median gap. This means: - // - Single-spaced (median ~14pt for 12pt font): threshold = 18.2pt - // - Double-spaced (median ~28pt for 12pt font): threshold = 36.4pt - // Also ensure it's at least base_size * 1.5 to avoid false paragraph breaks - // in tightly-spaced documents. - (median * 1.3).max(base_size * 1.5) + let threshold = (median * 1.3).max(base_size * 1.5); + + debug!( + "paragraph_threshold: base_size={:.1} median_gap={:.1} threshold={:.1} ({} gaps sampled)", + base_size, + median, + threshold, + gaps.len() + ); + + if log::log_enabled!(log::Level::Debug) { + // Gap histogram + let buckets: &[f32] = &[0.0, 0.5, 1.0, 1.2, 1.5, 1.8, 2.0, 2.5, 3.0, 5.0, 10.0]; + for i in 0..buckets.len() - 1 { + let count = gaps + .iter() + .filter(|&&g| { + let r = g / base_size; + r >= buckets[i] && r < buckets[i + 1] + }) + .count(); + if count > 0 { + debug!( + " gap_ratio {:.1}-{:.1}: {}", + buckets[i], + buckets[i + 1], + count + ); + } + } + let over = gaps.iter().filter(|&&g| g / base_size >= 10.0).count(); + if over > 0 { + debug!(" gap_ratio 10.0+: {}", over); + } + } + + // Per-line detail: Y position, gap, ratio, bold, text preview, paragraph marker + if log::log_enabled!(log::Level::Trace) { + let mut prev: Option<(u32, f32)> = None; + for line in lines { + let font_size = line.items.first().map(|i| i.font_size).unwrap_or(0.0); + let is_bold = line.items.first().map(|i| i.is_bold).unwrap_or(false); + let text = line.text(); + let display: String = text.chars().take(80).collect(); + + let (gap_str, ratio_str, marker) = if let Some((pp, py)) = prev { + if pp == line.page { + let gap = py - line.y; + let ratio = gap / base_size; + let is_para = gap > threshold; + ( + format!("{:8.1}", gap), + format!("{:8.2}", ratio), + if is_para { " <>" } else { "" }, + ) + } else { + (" ---".to_string(), " ---".to_string(), "") + } + } else { + (" ---".to_string(), " ---".to_string(), "") + }; + + log::trace!( + " p={} y={:8.1} gap={} ratio={} fs={:5.1} {} {}{}", + line.page, + line.y, + gap_str, + ratio_str, + font_size, + if is_bold { "B" } else { " " }, + display, + marker + ); + + prev = Some((line.page, line.y)); + } + } + + threshold } /// Discover distinct heading font-size tiers in the document. diff --git a/src/tables/detect_heuristic.rs b/src/tables/detect_heuristic.rs index 2b09a02..fc4336d 100644 --- a/src/tables/detect_heuristic.rs +++ b/src/tables/detect_heuristic.rs @@ -2,6 +2,7 @@ use crate::text_utils::is_rtl_text; use crate::types::TextItem; +use log::debug; use super::financial::try_split_financial_item; use super::grid::{ @@ -578,6 +579,13 @@ fn detect_table_in_region(items: &[(usize, &TextItem)], mode: TableDetectionMode return None; } + debug!( + "table detected: {} rows x {} cols, {} items", + rows.len(), + columns.len(), + item_indices.len() + ); + Some(Table { columns, rows, diff --git a/src/tounicode.rs b/src/tounicode.rs index 1a8056c..03daecc 100644 --- a/src/tounicode.rs +++ b/src/tounicode.rs @@ -3,6 +3,7 @@ //! This module parses ToUnicode CMaps to convert CID-encoded text to Unicode. use flate2::read::ZlibDecoder; +use log::debug; use std::collections::HashMap; use std::io::Read; @@ -599,6 +600,18 @@ impl FontCMaps { // Copy the by_obj map let by_obj_num = cmaps_by_obj; + for (name, cmap) in &by_name { + if !name.contains('_') || name.ends_with(|c: char| c.is_ascii_digit()) { + debug!( + "CMap font={:30} code_byte_length={} char_map={} ranges={}", + name, + cmap.code_byte_length, + cmap.char_map.len(), + cmap.ranges.len() + ); + } + } + FontCMaps { by_name, by_obj_num,