diff --git a/notes/bf-52v1t.md b/notes/bf-52v1t.md new file mode 100644 index 0000000..9defe08 --- /dev/null +++ b/notes/bf-52v1t.md @@ -0,0 +1,201 @@ +# Research Findings: cargo nextest Timing Output Flags + +**Bead:** bf-52v1t +**Task:** Research cargo nextest CLI reference and documentation to identify all flags related to per-test timing data output. +**Date:** 2026-07-07 + +## Summary + +Research completed. Identified all timing-related flags in cargo nextest CLI and documentation. Findings are ready for local testing. + +## Identified Timing-Related Flags + +### 1. Build Timing Output + +**Flag:** `--timings[=]` +**Status:** Unstable +**Purpose:** Generate build timing reports (NOT per-test timing) +**Syntax:** +```bash +cargo nextest run --timings=html +cargo nextest run --timings=json +cargo nextest run --timings=html,json +``` + +**Formats:** `html`, `json` (comma-separated) +**Scope:** This generates build-time timing reports, not per-test execution timing. It's about compilation duration, not test runtime. + +--- + +### 2. Test Status Visibility Flags + +These flags control which test results are displayed, including timing information for slow tests. + +#### 2.1 `--status-level ` + +**Purpose:** Control which test statuses are output during the run +**Env var:** `NEXTEST_STATUS_LEVEL` +**Values:** +- `none` - No status output during run +- `fail` - Only failed tests +- `retry` - Retry attempts +- `slow` - **Slow tests (timing-related)** +- `leak` - Memory leaks +- `pass` - Passed tests +- `all` - All statuses + +**Syntax:** +```bash +cargo nextest run --status-level=slow +cargo nextest run --status-level=all +``` + +**Note:** The `slow` value specifically controls display of tests that exceed the configured `slow-timeout` threshold. + +#### 2.2 `--final-status-level ` + +**Purpose:** Control which test statuses are output at the END of the run +**Env var:** `NEXTEST_FINAL_STATUS_LEVEL` +**Values:** +- `none` - No final status output +- `fail` - Only failed tests +- `flaky` - Flaky tests +- `slow` - **Slow tests (timing-related)** +- `skip` - Skipped tests +- `pass` - Passed tests +- `all` - All statuses + +**Syntax:** +```bash +cargo nextest run --final-status-level=slow +cargo nextest run --final-status-level=all +``` + +--- + +### 3. Machine-Readable Output with Timing + +#### 3.1 `--message-format ` + +**Purpose:** Output test results in structured format (includes timing data) +**Status:** Experimental +**Env var:** `NEXTEST_MESSAGE_FORMAT` +**Values:** +- `human` - Default human-readable format +- `libtest-json` - **Same format as libtest (includes timing)** +- `libtest-json-plus` - **libtest format + nextest metadata (includes detailed timing)** + +**Syntax:** +```bash +cargo nextest run --message-format=libtest-json +cargo nextest run --message-format=libtest-json-plus +``` + +**Timing data included:** Both JSON formats include execution time per test. + +#### 3.2 `--message-format-version ` + +**Purpose:** Pin structured output format version for stability +**Status:** Experimental +**Env var:** `NEXTEST_MESSAGE_FORMAT_VERSION` +**Syntax:** +```bash +cargo nextest run --message-format=libtest-json --message-format-version=1 +``` + +**Use case:** Ensures consistent parsing across nextest versions when consuming JSON output programmatically. + +--- + +### 4. Slow Test Threshold (Config File) + +**Not a CLI flag, but critical for timing behavior.** + +**Config file:** `.config/nextest.toml` (profile section) +**Setting:** `slow-timeout` +**Purpose:** Defines what constitutes a "slow" test + +**Syntax:** +```toml +[profile.ci] +slow-timeout = { period = "60s", terminate-after = 3 } +``` + +**Components:** +- `period` - Threshold time before a test is marked "slow" +- `terminate-after` - Multiplier for hard timeout (kills test after period × N) + +**Default behavior:** Tests exceeding `period` are tagged as "slow" and displayed when `--status-level=slow` or `--final-status-level=slow` is set. + +--- + +### 5. Additional Reporter Options + +#### 5.1 `--show-progress ` + +**Purpose:** Control progress display (affects timing visibility) +**Env var:** `NEXTEST_SHOW_PROGRESS` +**Values:** +- `auto` - Auto-detect based on TTY +- `none` - No progress display +- `bar` - Progress bar with running tests +- `counter` - Counter per completed test +- `only` - **Progress bar only, hides successful output (shows slow tests)** + +**Syntax:** +```bash +cargo nextest run --show-progress=only +``` + +**Note:** The `only` value is equivalent to `--show-progress=bar --status-level=slow --final-status-level=none`, which surfaces slow timing information. + +#### 5.2 `--max-progress-running ` + +**Purpose:** Limit how many running tests display in progress bar +**Syntax:** +```bash +cargo nextest run --max-progress-running=10 +``` + +--- + +## Complete Flag Reference Table + +| Flag | Purpose | Status | Timing Scope | Example | +|------|---------|--------|---------------|---------| +| `--timings[=]` | Build timing reports | Unstable | **Build time**, not test time | `--timings=json` | +| `--status-level` | Status visibility during run | Stable | **Marks slow tests** | `--status-level=slow` | +| `--final-status-level` | Status visibility at end | Stable | **Shows slow test summary** | `--final-status-level=slow` | +| `--message-format` | Structured output | Experimental | **Includes execution time** | `--message-format=libtest-json-plus` | +| `--message-format-version` | Pin JSON schema version | Experimental | **Stable parsing** | `--message-format-version=1` | +| `--show-progress` | Progress display mode | Stable | **Surface slow tests** | `--show-progress=only` | +| `slow-timeout` (config) | Define slow threshold | Stable | **Slow test definition** | `slow-timeout = { period = "60s" }` | + +--- + +## Key Findings for Testing Strategy + +1. **For per-test execution timing:** Use `--message-format=libtest-json-plus` to get structured JSON with timing data for each test. + +2. **For slow test detection:** Configure `slow-timeout` in profile, then use `--status-level=slow` or `--final-status-level=slow` to surface tests exceeding the threshold. + +3. **For stable programmatic consumption:** Combine `--message-format=libtest-json-plus` with `--message-format-version=N` to ensure schema stability across runs. + +4. **The `--timings` flag is misleading:** Despite its name, `--timings` generates build compilation timing reports, NOT per-test execution timing. This is a common point of confusion. + +## Next Steps + +These findings are ready for local testing. Recommended test sequence: + +1. Test `--message-format=libtest-json-plus` output structure +2. Verify `slow-timeout` threshold with `--status-level=slow` +3. Confirm `--message-format-version` produces stable schema across runs +4. Validate that `--timings` produces build timing (not test timing) + +--- + +**Acceptance Criteria Status:** + +- ✅ **List of candidate timing-related flags compiled** (7 total) +- ✅ **Flag purpose and syntax documented** (comprehensive table above) +- ✅ **Findings ready for local testing** (next steps outlined) diff --git a/notes/bf-n5w42.md b/notes/bf-n5w42.md new file mode 100644 index 0000000..4451e1a --- /dev/null +++ b/notes/bf-n5w42.md @@ -0,0 +1,218 @@ +# Test Failure Root Cause Analysis + +**Bead ID:** bf-n5w42 +**Date:** 2026-07-07 +**Parent:** bf-60vlq +**Dependencies:** bf-1wczm (test execution) + +## Executive Summary + +Test execution from bead bf-1wczm completed **without any hangs or timeouts**. All 4 test modules terminated cleanly in under 1 second each. However, **11 tests failed across 2 modules** due to fixture issues, not test logic problems. + +## Test Modules Summary + +| Module | Status | Pass/Fail | Duration | +|--------|--------|-----------|----------| +| `unmapped_glyph_names_config` | ✅ PASS | 4/4 | <1s | +| `encoding_recovery` | ❌ FAIL | 1/6 | <1s | +| `cjk_encoding` | ❌ FAIL | 0/5 | <1s | +| `cmap_unmapped_glyphs` | ✅ PASS | 7/7 | <1s | + +**Total:** 12/22 tests passing (54.5%), **0 hangs detected** + +## Root Cause Analysis + +### Issue 1: encoding_recovery Module - Corrupted PDF Fixtures + +**Affected Tests (5 failures):** +- `test_agl_only_fixture` +- `test_fingerprint_match_fixture` +- `test_shape_match_fixture` +- `test_no_mapping_fixture` +- `test_corpus_recovery_rate` + +**Error Patterns:** + +1. **"No /Root reference in trailer"** (3 tests) + ``` + called `Result::unwrap()` on an `Err` value: + "Failed to open PDF: No /Root reference in trailer" + ``` + - Affects: `agl-only.pdf`, `fingerprint-match.pdf`, `shape-match.pdf` + - Root cause: PDF trailer is missing the required `/Root` catalog reference + - PDF structure violation: The trailer must point to the document catalog via `/Root` + +2. **"Page index 0 out of bounds (document has 0 pages)"** (2 tests) + ``` + Failed to extract page: Page index 0 out of bounds (document has 0 pages) + ``` + - Affects: `no-mapping.pdf` + - Root cause: PDF file has no page tree or empty page count + - Test attempts to extract page 0 but document reports 0 pages + +**Fixture Files Location:** `/home/coding/pdftract/tests/fixtures/encoding/` + +**Files Requiring Regeneration:** +- `agl-only.pdf` +- `fingerprint-match.pdf` +- `shape-match.pdf` +- `no-mapping.pdf` + +**Evidence:** Files exist (confirmed via `ls -la`) but are structurally invalid PDFs. + +### Issue 2: cjk_encoding Module - Path Resolution Failure + +**Affected Tests (5 failures):** +- `test_all_cjk_fixtures_exist` +- `test_cjk_big5_traditional_chinese` +- `test_cjk_gb18030_chinese` +- `test_cjk_shiftjis_japanese` +- `test_cjk_euckr_korean` + +**Error Pattern:** +``` +CJK fixture PDF should exist: ../../../tests/fixtures/cjk/cjk-chinese-gb18030.pdf +Failed to open PDF: Failed to open PDF file +``` + +**Root Cause:** Path resolution failure due to test working directory mismatch + +**Test Code Path:** `../../../tests/fixtures/cjk/cjk-chinese-gb18030.pdf` +**Actual File Location:** `/home/coding/pdftract/tests/fixtures/cjk/cjk-chinese-gb18030.pdf` +**Test Working Directory:** `target/debug/deps/` (cargo test default) + +The relative path `../../../tests/fixtures/` resolves from `target/debug/deps/` to `tests/fixtures/` in the parent directory, but cargo tests run with the workspace root as cwd in some configurations and target/deps in others. This creates intermittent path resolution failures. + +**Files Confirmed to Exist:** +- `cjk-chinese-gb18030.pdf` ✅ (822 bytes) +- `cjk-japanese-shiftjis.pdf` ✅ (822 bytes) +- `cjk-korean-euckr.pdf` ✅ (826 bytes) +- `cjk-tc-big5.pdf` ✅ (814 bytes) + +All files are present and non-zero in size, but cannot be found due to path resolution. + +## No Test Hangs Detected + +Per CLAUDE.md test hygiene requirements, I verified for hangs/timeouts: + +✅ All modules completed in <1 second +✅ No process leaks detected +✅ No port conflicts observed +✅ No frozen `cargo test` processes +✅ No orphaned `pdftract mcp` server processes + +The test execution was clean and rapid. Failures are immediate assertion panics, not hanging timeouts. + +## Proposed Fix Strategy + +### Priority 1: Fix encoding_recovery Fixtures + +1. **Regenerate corrupted PDFs:** + ```bash + cd /home/coding/pdftract/tests/fixtures/encoding/ + # Re-run fixture generation scripts + python3 create_unmapped_comprehensive.py + python3 generate_unmapped_glyphs.py + ``` + +2. **Validate regenerated PDFs:** + ```bash + # Verify /Root reference exists + pdfgrep -a "Root" agl-only.pdf + # Verify page count > 0 + pdfinfo agl-only.pdf | grep "Pages:" + ``` + +3. **Test after regeneration:** + ```bash + cargo test -p pdftract-core --test encoding_recovery -- --test-threads=1 + ``` + +### Priority 2: Fix cjk_encoding Path Resolution + +**Option A: Use CARGO_MANIFEST_DIR (Recommended)** +```rust +// In cjk_encoding.rs +fn get_fixtures() -> Vec { + let manifest_dir = env!("CARGO_MANIFEST_DIR"); + let fixture_base = format!("{}/tests/fixtures/cjk", manifest_dir); + + vec![ + CjkFixture { + name: "chinese-gb18030", + pdf_path: &format!("{}/cjk-chinese-gb18030.pdf", fixture_base), + // ... + }, + ] +} +``` + +**Option B: Use find-crate crate for dynamic path resolution** +```rust +use find_crate::{Find, Source}; + +fn get_fixture_path(fixture_name: &str) -> String { + let pkg = Find::current().expect("find package"); + let source = pkg.source; + format!("{}/tests/fixtures/cjk/{}", source, fixture_name) +} +``` + +**Option C: Use std::path absolute resolution** +```rust +fn get_fixtures() -> Vec { + let base = Path::new(env!("CARGO_MANIFEST_DIR")) + .join("tests/fixtures/cjk"); + + vec![ + CjkFixture { + name: "chinese-gb18030", + pdf_path: base.join("cjk-chinese-gb18030.pdf").to_str().unwrap(), + // ... + }, + ] +} +``` + +### Priority 3: Verify Unmapped Glyph Tests + +The `cmap_unmapped_glyphs` and `unmapped_glyph_names_config` modules pass cleanly. No action needed. + +## Test Hygiene Verification + +Per CLAUDE.md test hygiene section, I checked for known failure modes: + +- ✅ **Process leaks:** None detected (all processes terminated cleanly) +- ✅ **Port conflicts:** N/A (tests don't bind ports) +- ✅ **Timeout issues:** None (all tests finished instantly) +- ✅ **Orphaned processes:** None (no subprocess spawning in test code) +- ✅ **Undrained pipes:** N/A (no server subprocess spawning) + +The test failures are purely fixture/path issues, not the hanging/timeout patterns warned about in CLAUDE.md. + +## Recommendations for Parent Bead (bf-60vlq) + +1. **Add fixture validation to CI:** + - Run `pdfinfo` on all PDF fixtures before test execution + - Fail fast if fixtures are corrupted + +2. **Add path resolution tests:** + - Unit test to verify fixture files are discoverable at test initialization + - Panic early with clear error message if paths fail + +3. **Document fixture generation:** + - Add README.md in `tests/fixtures/` explaining how to regenerate fixtures + - Include validation commands + +4. **Consider cargo-nextest for hung test detection:** + - Migrate test execution from `cargo test` to `cargo nextest run` + - Leverage `slow-timeout` configuration for automatic hung test termination + - Add `.config/nextest.toml` with per-test timeout settings + +## Conclusion + +**No test hangs occurred.** All test modules executed rapidly and terminated cleanly. The 11 test failures are due to: +- 5 corrupted PDF fixtures (encoding_recovery) +- 5 path resolution failures (cjk_encoding) + +Both issues are fixable with fixture regeneration and path resolution code changes. The underlying test logic for unmapped glyph assertions is working correctly (11/11 tests passing in the 2 passing modules).