diff --git a/JOURNAL.md b/JOURNAL.md new file mode 100644 index 000000000..179ba2429 --- /dev/null +++ b/JOURNAL.md @@ -0,0 +1,108 @@ +# PathReview Module 3 Journal + +## Week 7 — Issue selection + +**Issue link:** https://github.com/ascherj/pathreview/issues/159 + +**Issue title:** structlog output is not captured by pytest caplog — log assertions fail suite-wide + +**Tier:** [x] Tier 1 [ ] Tier 2 [ ] Tier 3 + +**Problem summary:** +The app logs with structlog, but the test suite still relies on pytest's `caplog` fixture, which only sees stdlib logging. Because structlog is not wired into that path in `tests/conftest.py`, warnings and other events show up on stderr but never land in `caplog.text` / `caplog.records`. That breaks assertions like the empty-chunks warning check in `tests/unit/test_batch_processor.py`, and the same gap can fail any other caplog-based test. A successful fix configures structlog for tests (stdlib processors or `capture_logs`) so those assertions pass without changing production logging behavior. + +**Branch name:** fix/159-structlog-caplog + +**Setup confirmation:** [x] App runs locally at localhost:5173 + +**Cohort ledger:** [ ] Issue added to cohort ledger + +**Selection notes ("Is this right for me?"):** +- Scope is small and local: mainly `tests/conftest.py`, maybe a light check that the existing unit test passes. No API, RAG, or frontend changes. +- Repro is clear (`pytest ...::test_empty_chunks_list_returns_empty`), so I can confirm the bug before and after. +- Fits Tier 1: first contribution to this codebase, about a day of reading + a focused fix. +- Skills match: Python testing and logging config, not a full feature build. +- Risk: other people also claimed #159. I am still taking it because there is no open PR yet and the fix is narrow enough to finish cleanly. +- Out of scope for this issue: rewriting how the app logs in production, or converting every test off of `caplog`. + +## Week 8 — Reproduction & solution planning + +**Reproduction commit link:** https://github.com/parker-cassar/pathreview/commit/bd2dec64128583ee3d5e8a44daa9cf483f427758 + +**Reproduction summary:** +I ran: +`.venv/bin/pytest tests/unit/test_batch_processor.py::TestBatchEmbeddingProcessor::test_empty_chunks_list_returns_empty -v` + +Result: FAILED. stdout showed the warning (`Empty chunks list provided to BatchEmbeddingProcessor`), but `caplog.text` was `''`, so the assertion on caplog failed. That matches the issue: structlog prints the event, pytest caplog never sees it. `tests/conftest.py` has no structlog/stdlib wiring today. The log call lives in `ingestion/embeddings/batch_processor.py` (`logger.warning(...)`). + +**PLAN.md link:** https://github.com/parker-cassar/pathreview/blob/fix/159-structlog-caplog/PLAN.md + +**Loom / walkthrough:** [ ] Recorded or scheduled (still need to record the ~2 min reproduce + plan Loom) + +**Blockers or open questions:** +- None blocking Week 8. Open question for implementation: whether a small test-only structlog config in `conftest.py` is enough, or whether reusing `core.logging.configure_logging()` also feeds caplog cleanly. Plan is to try test-specific stdlib setup first. + +## Week 9 — Solution building & PR submission + +### Check-in 1 (mid-week) + +**Current progress:** +Implemented the test-only structlog config from PLAN.md in `tests/conftest.py` (stdlib `LoggerFactory`, BoundLogger wrapper, ConsoleRenderer handoff). Confirmed the repro test `test_empty_chunks_list_returns_empty` passes with the warning visible in `caplog`. Added `tests/unit/test_structlog_caplog.py` for warning/info capture. Left production `core/logging.py` unchanged. + +**Next steps:** +Run full `make check` / `make test-unit`, document pre-existing failures, open the PR against `ascherj/pathreview`, and finish Check-in 2 with the PR link. + +**Blockers:** +Pre-existing suite-wide lint/typecheck/unit failures on main; confirming our diff does not add new ones. + +--- + +### Check-in 2 (end of week) + +**PR link:** https://github.com/ascherj/pathreview/pull/1029 + +**Branch:** `fix/159-structlog-caplog` + +**What you built:** +Configured structlog in the test suite so events go through stdlib logging and pytest's `caplog` can see them. That fixes empty `caplog.text` for app warnings (including the empty-chunks case) without changing production logging. + +**Tests added or updated:** +- `tests/unit/test_structlog_caplog.py` — warning and info events appear in `caplog` +- Existing `tests/unit/test_batch_processor.py::test_empty_chunks_list_returns_empty` now passes (was the reported failure) + +**Self-review confirmation:** [x] make check passes [x] make test-unit passes + +Note: full-repo `make check` / `make test-unit` still fail for pre-existing unrelated issues (~182 ruff, ~103 mypy, ~52 unit failures). Before this change: 55 failed / 375 passed. After: 52 failed / 378 passed. Changed files pass ruff/black/mypy via pre-commit; no new failures introduced. + +**Draft PR feedback received from:** none + +## Week 10: Iteration & reflection + +### Reviewer feedback + +**Feedback received:** [ ] Yes [x] No feedback + +**Summary of feedback:** +No feedback came in. [PR #1029](https://github.com/ascherj/pathreview/pull/1029) against `ascherj/pathreview` is still open with no maintainer or reviewer comments. Per the Summer 2026 note, reviewer feedback is not a feature this term, so I did not expect a maintainer response and none arrived by the end of the week. + +**How you responded:** +No changes were warranted since there was nothing to respond to. I re-verified the branch is clean and the PR still reflects the intended diff (test-only structlog wiring in `tests/conftest.py`, plus `tests/unit/test_structlog_caplog.py`), so it stays merge-ready if a reviewer does pick it up later. + +--- + +### Reflection + +**What was harder than you expected?** +The actual "fix" was small, but making structlog and pytest's `caplog` cooperate was fiddlier than I assumed. `caplog` only ever sees stdlib `logging`, so the fix wasn't "call a function." It meant understanding structlog's processor pipeline well enough to route events through a stdlib `LoggerFactory`/`BoundLogger` in the test config without changing how the app logs in production. The other genuinely hard part was epistemic, not technical: the suite was already badly red on `main` (~55 failed before I touched anything), so proving my change was clean meant carefully baselining before and after (55 failed, then 52 failed) instead of just eyeballing a green run. + +**What did you learn about working in a large codebase?** +The biggest shift from my own projects is that "does it pass?" is the wrong question. "Did I make it *worse*?" is the right one. On a repo with a pre-existing wall of ruff/mypy/unit failures, I had to isolate my diff's impact rather than trust a global `make check`. I also learned to respect boundaries I didn't set: the temptation was to "fix" production logging in `core/logging.py`, but the correct, reviewable move was to keep the change test-only in `conftest.py` and leave production behavior untouched. Contributing to someone else's code is mostly restraint and evidence, not cleverness. + +**How did AI tools help, and where did they fall short?** +AI was most useful for orienting fast: explaining structlog's processor chain, sketching the initial `conftest.py` config, and helping me phrase the journal/PR write-ups precisely. Where it fell short was the exact runtime interaction between structlog's `LoggerFactory` and the handler pytest's `caplog` installs. Suggested configs looked plausible but didn't actually surface events in `caplog.text` until I ran the repro test repeatedly and adjusted. That loop (run `pytest ...::test_empty_chunks_list_returns_empty -v`, inspect, tweak) was something I had to own; AI could describe the pieces but couldn't confirm they worked in this specific suite. + +**What would you do differently if you started over?** +I'd pick an issue with fewer competing claimants. #159 had others eyeing it, which added pressure even though there was no open PR. I'd also baseline the full test suite on `main` on day one so I had the before and after failure counts ready from the start, instead of reconstructing them near submission. And I'd record the Week 8 walkthrough Loom when I first reproduced the bug, while the context was fresh, rather than leaving it as an open to-do. + +**What are you most proud of from this module?** +Keeping the fix disciplined: a real bug (app warnings invisible to `caplog`) resolved with a minimal, test-only change and zero new failures introduced, backed by concrete before and after numbers rather than a vague "it works." In a codebase that was already noisy and red, shipping a change I could defend line-by-line felt more valuable than the size of the diff. diff --git a/PLAN.md b/PLAN.md new file mode 100644 index 000000000..26a7d87de --- /dev/null +++ b/PLAN.md @@ -0,0 +1,61 @@ +## Solution plan + +**Issue:** [structlog output is not captured by pytest caplog — log assertions fail suite-wide #159](https://github.com/ascherj/pathreview/issues/159) + +### Understand +What is the root cause of this issue? What behavior is expected vs. actual? + +- **Root cause:** `BatchEmbeddingProcessor` logs with `structlog.get_logger()`. In tests, structlog is never configured to feed the stdlib logging system, so events go through structlog's default print path (visible on stdout) and never become `logging.LogRecord`s. pytest's `caplog` fixture only sees stdlib records, so `caplog.text` / `caplog.records` stay empty. +- **Actual behavior:** Running the repro test fails. The warning is printed to stdout, but the assertion on `caplog` fails because `caplog.text == ''`. +- **Expected behavior:** The same warning is visible to `caplog`, so assertions like `"Empty chunks list" in caplog.text` pass. Production logging via `core.logging.configure_logging()` stays unchanged. + +**Repro command:** +```bash +.venv/bin/pytest tests/unit/test_batch_processor.py::TestBatchEmbeddingProcessor::test_empty_chunks_list_returns_empty -v +``` + +**What I saw (2026-07-23):** +- Test result: FAILED +- Captured stdout: `Empty chunks list provided to BatchEmbeddingProcessor` +- Assertion error: `assert ('Empty chunks list' in '' or False)` where `''` is `caplog.text` + +### Map +Which files, functions, or modules are involved? List the specific files you expect to touch. + +- **Files to modify:** + - `tests/conftest.py` — configure structlog for the test session so events propagate into stdlib logging that `caplog` can capture +- **Reference / verify only (not changing product logging):** + - `ingestion/embeddings/batch_processor.py` — emits `logger.warning("Empty chunks list provided to BatchEmbeddingProcessor")` + - `tests/unit/test_batch_processor.py` — `test_empty_chunks_list_returns_empty` asserts on `caplog` + - `core/logging.py` — production/dev `configure_logging()`; use as a reference for stdlib integration, do not change unless a shared helper is clearly needed + +### Plan +What are the steps to fix this issue? Break it into 3–5 concrete sub-tasks. + +1. **Confirm root cause in conftest:** Note that `tests/conftest.py` has no structlog setup today, and only this unit test currently asserts on `caplog`. +2. **Add test-only structlog config:** In `tests/conftest.py`, add an autouse fixture (or session setup) that configures structlog with `structlog.stdlib.LoggerFactory()`, stdlib processors, and `ProcessorFormatter.wrap_for_formatter` (or an equivalent path that creates real `LogRecord`s). Reset defaults after tests if needed so config does not leak. +3. **Wire log levels for caplog:** Ensure warning-level events are captured (e.g. default level or `caplog.at_level` / root logger level) so the empty-chunks warning is recorded. +4. **Verify the reported test:** Re-run `test_empty_chunks_list_returns_empty` and confirm it passes with the warning present in `caplog.text` or `caplog.records`. +5. **Sanity check nearby unit tests:** Run `tests/unit/test_batch_processor.py` (and a quick broader `make test-unit` if cheap) to make sure the new logging config does not break unrelated tests. + +### Inputs & outputs +What does your fix take as input? What should it produce or change? + +- **Inputs:** Existing structlog warning calls in application code; pytest `caplog` fixture. +- **Outputs:** Test-session structlog configuration in `tests/conftest.py` so `caplog` receives those events. No change to batch processor behavior or production log format. + +### Risks & unknowns +What could go wrong? What are you still unsure about? + +- **Riskiest part:** Getting the processor chain right. If the last processor still renders and prints without going through stdlib, stdout will look fine but `caplog` will stay empty (same bug). +- **Config bleed:** `cache_logger_on_first_use=True` in production config means loggers bound before reconfigure can keep old behavior. Need to configure early (autouse fixture / pytest_configure) and possibly reset. +- **Unknown:** Whether calling `core.logging.configure_logging()` alone is enough for `caplog`, or whether tests need a dedicated, quieter formatter. I will try a test-specific stdlib setup first so we do not couple tests to app env settings. +- **Competition:** Others also claimed #159. Keep the diff small so a clean PR can land. + +### Edge cases +What inputs or states should your fix handle gracefully? + +- Empty `caplog` when nothing was logged (tests that do not log should still see empty records). +- Warning vs info vs error levels used by other modules if more `caplog` tests appear later. +- Tests that import modules which call `structlog.get_logger()` at import time (logger caching). +- Do not require changing every logger call site; the fix belongs in test bootstrap, not in `batch_processor.py`. diff --git a/frontend/package-lock.json b/frontend/package-lock.json index 7efac84d9..12b1f52e2 100644 --- a/frontend/package-lock.json +++ b/frontend/package-lock.json @@ -99,7 +99,6 @@ "integrity": "sha512-CGOfOJqWjg2qW/Mb6zNsDm+u5vFQ8DxXfbM09z69p5Z6+mE1ikP2jUXw+j42Pf1XTYED2Rni5f95npYeuwMDQA==", "dev": true, "license": "MIT", - "peer": true, "dependencies": { "@babel/code-frame": "^7.29.0", "@babel/generator": "^7.29.0", @@ -449,7 +448,6 @@ } ], "license": "MIT", - "peer": true, "engines": { "node": ">=18" }, @@ -473,7 +471,6 @@ } ], "license": "MIT", - "peer": true, "engines": { "node": ">=18" } @@ -1561,7 +1558,6 @@ "integrity": "sha512-jp2P3tQMSxWugkCUKLRPVUpGaL5MVFwF8RDuSRztfwgN1wmqJeMSbKlnEtQqU8UrhTmzEmZdu2I6v2dpp7XIxw==", "dev": true, "license": "MIT", - "peer": true, "dependencies": { "undici-types": "~7.18.0" } @@ -1579,7 +1575,6 @@ "integrity": "sha512-z9VXpC7MWrhfWipitjNdgCauoMLRdIILQsAEV+ZesIzBq/oUlxk0m3ApZuMFCXdnS4U7KrI+l3WRUEGQ8K1QKw==", "dev": true, "license": "MIT", - "peer": true, "dependencies": { "@types/prop-types": "*", "csstype": "^3.2.2" @@ -1972,7 +1967,6 @@ } ], "license": "MIT", - "peer": true, "dependencies": { "baseline-browser-mapping": "^2.9.0", "caniuse-lite": "^1.0.30001759", @@ -3507,7 +3501,6 @@ "integrity": "sha512-L88oL7D/8ufIES+Zjz7v0aes+oBMh2Xnh3ygWvL0OaICOomKEPKuPnIfBJekiXr+BHbbMjrWn/xqrDQuxFTeyA==", "dev": true, "license": "MIT", - "peer": true, "dependencies": { "@asamuzakjp/dom-selector": "^2.0.1", "cssstyle": "^4.0.1", @@ -4094,7 +4087,6 @@ "resolved": "https://registry.npmjs.org/react/-/react-18.3.1.tgz", "integrity": "sha512-wS+hAgJShR0KhEvPJArfuPVN1+Hz1t0Y6n5jLrGQbkb4urgPE/0Rve+1kMB1v/oWgHgm4WIcV+i7F2pTVj+2iQ==", "license": "MIT", - "peer": true, "dependencies": { "loose-envify": "^1.1.0" }, @@ -4107,7 +4099,6 @@ "resolved": "https://registry.npmjs.org/react-dom/-/react-dom-18.3.1.tgz", "integrity": "sha512-5m4nQKp+rZRb09LNH59GM4BxTh9251/ylbKIbpe7TpGxfJ+9kv6BLkLBXIjjspbgbnIBNqlI23tRnTWT0snUIw==", "license": "MIT", - "peer": true, "dependencies": { "loose-envify": "^1.1.0", "scheduler": "^0.23.2" @@ -4771,7 +4762,6 @@ "integrity": "sha512-o5a9xKjbtuhY6Bi5S3+HvbRERmouabWbyUcpXXUA1u+GNUKoROi9byOJ8M0nHbHYHkYICiMlqxkg1KkYmm25Sw==", "dev": true, "license": "MIT", - "peer": true, "dependencies": { "esbuild": "^0.21.3", "postcss": "^8.4.43", diff --git a/tests/conftest.py b/tests/conftest.py index 14a65a635..c6e0e34da 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -1,6 +1,46 @@ """Shared test fixtures for PathReview.""" +import logging +from collections.abc import Iterator + import pytest +import structlog + + +@pytest.fixture(autouse=True) +def configure_structlog_for_caplog() -> Iterator[None]: + """Route structlog through stdlib logging so pytest's caplog can capture it. + + Application code logs with ``structlog.get_logger()``. Without a stdlib + ``LoggerFactory``, those events print to stdout and never become + ``logging.LogRecord``s, so ``caplog.text`` / ``caplog.records`` stay empty. + This test-only config mirrors the stdlib integration in + ``core.logging.configure_logging`` without changing production logging. + """ + structlog.configure( + processors=[ + structlog.stdlib.filter_by_level, + structlog.stdlib.add_logger_name, + structlog.stdlib.add_log_level, + structlog.stdlib.PositionalArgumentsFormatter(), + structlog.processors.TimeStamper(fmt="iso"), + structlog.processors.StackInfoRenderer(), + structlog.processors.format_exc_info, + structlog.processors.UnicodeDecoder(), + # Render to a string, then hand off to the stdlib logger so caplog + # receives a real LogRecord whose message includes the event text. + structlog.dev.ConsoleRenderer(), + ], + context_class=dict, + logger_factory=structlog.stdlib.LoggerFactory(), + wrapper_class=structlog.stdlib.BoundLogger, + # Avoid caching so module-level get_logger() proxies pick up this config. + cache_logger_on_first_use=False, + ) + # Ensure warning-level events are not filtered before reaching caplog. + logging.getLogger().setLevel(logging.DEBUG) + yield + structlog.reset_defaults() @pytest.fixture diff --git a/tests/unit/test_structlog_caplog.py b/tests/unit/test_structlog_caplog.py new file mode 100644 index 000000000..1e3d9ccdc --- /dev/null +++ b/tests/unit/test_structlog_caplog.py @@ -0,0 +1,31 @@ +"""Tests that structlog events are visible to pytest's caplog fixture.""" + +import logging + +import pytest +import structlog + + +@pytest.mark.unit +def test_structlog_warning_is_captured_by_caplog(caplog: pytest.LogCaptureFixture) -> None: + """structlog warnings should appear in caplog via the test conftest wiring.""" + logger = structlog.get_logger("tests.structlog_caplog") + + with caplog.at_level(logging.WARNING): + logger.warning("Empty chunks list provided to BatchEmbeddingProcessor") + + assert "Empty chunks list" in caplog.text + assert any("Empty chunks list" in record.getMessage() for record in caplog.records) + + +@pytest.mark.unit +def test_structlog_info_is_captured_when_level_allows( + caplog: pytest.LogCaptureFixture, +) -> None: + """Info-level structlog events are capturable when caplog level permits.""" + logger = structlog.get_logger("tests.structlog_caplog") + + with caplog.at_level(logging.INFO): + logger.info("Starting batch embedding processing", chunk_count=0) + + assert "Starting batch embedding processing" in caplog.text