diff --git a/CHANGELOG.md b/CHANGELOG.md index 0eae47afb..5f0e6e6db 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -23,6 +23,12 @@ is for things you can see or feel when running the app. - **Your library keeps working when its extra fields can't be read.** Book pages, the books table and both search screens all ask the library for its custom-column definitions — the extra fields you can add to a book in Calibre. If that lookup failed because the library was mid-write, its folder had moved, or the definitions table wasn't there yet, those pages returned an error instead of simply leaving the extra fields out, even though the rest of the library was perfectly readable. Custom columns are supplementary, so these pages now load without them and note the reason in the log ([#1153](https://github.com/new-usemame/Calibre-Web-NextGen/issues/1153)). +- **A book that fails to convert now still lands in your library.** If CWA could not convert an incoming book to your target format — a big or image-heavy PDF that ran out of time, a file with internals Calibre chokes on, a format needing a plugin you don't have — the book was dropped altogether: no entry in the library, and the file gone from the ingest folder. The log even said `Successfully processed` on its way past, so nothing suggested a book had gone missing until you noticed it wasn't there. A failed conversion says nothing about whether the file is a readable book, and the two settings that decline to convert — auto-convert switched off, or the format on your do-not-convert list — already import the original, so this was inconsistent as well as lossy. The original is now imported whenever a conversion fails. + + A long conversion needed a second fix to get there. Nothing inside the app limited how long a conversion could run; the only limit was the watchdog wrapped around the whole ingest step, and when that fired it killed the ingest outright, so none of the recovery above could happen — which is exactly what the reported 63MB PDF hit after 45 minutes. Conversions now have their own time limit set just inside the watchdog's, so running long ends as a normal failure and the book is imported in its original format instead of disappearing. Raising **Ingest Timeout** in CWA Settings raises both. + + Two smaller things from the same report. The log now names the folder it keeps the copy in, `/config/processed_books/failed/`, where before it said only "failed backup" — a copy existed, but not where. And when a conversion overran, the service claimed the app "should have timed out internally", which was misleading advice about a limit that did not exist; it now points at the setting that does control it. Reported by [@auspex](https://github.com/auspex) ([#1094](https://github.com/new-usemame/Calibre-Web-NextGen/issues/1094)). + - **Opening your library no longer runs the same search twice.** Every visit to the library asked the server for the first page of books, then immediately asked for it again at a different size and threw the first answer away. Nothing looked wrong — the wasted answer never reached the screen — but on a large library that first page is the slowest query on it, and it was being run twice on every load, for every reader. The grid now waits until it knows how many columns it has before asking, so the page is fetched once ([#1144](https://github.com/new-usemame/Calibre-Web-NextGen/issues/1144)). ## [v4.1.21] - 2026-07-25 diff --git a/CHANGES-vs-upstream.md b/CHANGES-vs-upstream.md index 0cef8fbd1..b6d96df7c 100644 --- a/CHANGES-vs-upstream.md +++ b/CHANGES-vs-upstream.md @@ -62,6 +62,7 @@ Format: each row is one fork-PR, mapped to its upstream PR or issue (if any), wi | Fork PR | Upstream issue | Description | SHA | Release | |---|---|---|---|---| +| [#1157](https://github.com/new-usemame/Calibre-Web-NextGen/pull/1157) | (fork issue [#1094](https://github.com/new-usemame/Calibre-Web-NextGen/issues/1094) @auspex) | **A failed conversion dropped the book from the library entirely.** `main()` in `scripts/ingest_processor.py` imported the incoming book only inside `if convert_successful:` and had no `else`, so any conversion failure — the reporter's 63MB PDF killed by the service safety timeout, but equally a corrupt source, unsupported internals, or a missing input plugin — returned without ever calling `add_book_to_library()`, while the `finally` block's `delete_current_file()` removed the source from the ingest folder. The service then logged `Successfully processed`. The two sibling branches that decline to convert (`auto_convert` off; format in `auto_convert_ignored_formats`) already import the original, so the fallback makes behaviour consistent rather than adding a rule. **Fix**: an `elif conversion_attempted:` branch imports the original. The guard flag matters — the ignore-list branch reports `convert_successful=False` *having already imported*, so a bare `else` would have filed every deliberately-unconverted book twice; that near-miss is pinned by `test_ignored_format_is_imported_exactly_once`. Also addressed from the same report: `backup()` now logs the absolute destination and the safety-timeout branch names `/config/processed_books/failed/` (the reporter's "I've got no idea where 'failed backup' is"), and the service no longer claims the processor "should have timed out internally at N seconds" — `ingest_timeout_minutes` bounds only `is_file_in_use()`, so no internal conversion timeout exists; it now points at the setting that does govern it. **Second defect, found by the cross-family review and confirmed by reading `run:245`:** the fallback could not help the reporter's own case at all. The service runs the processor under `timeout "$safety_timeout"`, and nothing inside the processor bounded conversion — so an overrun was a SIGTERM to the processor, not a Python-visible failure, and `main()` never regained control to reach the new branch. (Their log shows `CON_ERROR ... EXIT/ERROR CODE: -15` a second before the shell's `SAFETY TIMEOUT`, which is `timeout` signalling the process group: whether Python survives long enough to print anything is a race, and whether it survives long enough to *import* is a race it usually loses.) **Fix**: `convert_book()`/`convert_to_kepub()` now run the converter with `subprocess.run(timeout=...)` from `CWA_CONVERSION_DEADLINE_SECONDS`, which the s6 script derives from the same `safety_timeout` it enforces (one source of truth; ~10% margin, proportional fallback when a flat floor would leave no headroom; unset when `timeout 0` means no hard limit). An overrun is now an ordinary `(False, "")` and the book is imported. **Third defect, same review**: `convert_to_kepub()`'s generic `except Exception` printed and fell through, returning `None` — `main()` unpacks that call, so it raised `TypeError`, skipped the fallback and dropped the book. Every non-success path now returns a pair. Also, that path backed up only the intermediate epub, so for a non-epub input the failed folder never held the file the user actually dropped in; it now keeps both. **Declined, with reason**: the review's `automerge=overwrite` finding (a rescued file could replace a good existing format) is real but pre-existing and not introduced here — the same unconditional `add_book_to_library(filepath)` runs on the auto-convert-off and ignore-list branches today, and the default is `new_record` (`cwa_schema.sql:46`). Tracked separately rather than folded into this fix. **Verified live in cwn-local mirroring the reporter's config** (`auto_convert=1`, target epub): pre-fix an unconvertible PDF logged `CON_ERROR` then `Successfully processed` with the book count unchanged at 42; post-fix the same file imports (42→43), `/book/205` and `/api/v1/books/205` both 200 with the PDF format attached. Deadline path verified live too: a 12MB txt with a 1s deadline overran, logged the actionable message, backed up to the named folder and imported as **TXT** — the original, not a converted file. Happy path re-checked (txt→epub converts, one EPUB row, fallback silent), ignore-list path re-checked (exactly one row), and an `.acsm` ticket re-checked (not filed, guidance printed, its promise about processed_books/failed now true). 27 regression tests, mutation-verified falsifiable; full unit+smoke suite 3F/4206P against a 3F baseline on `main` — the same three pre-existing failures. No dependency, license, route or external URL change. Fork-original. | `TBD` | TBD | | [#1149](https://github.com/new-usemame/Calibre-Web-NextGen/pull/1149) | (fork issue [#1121](https://github.com/new-usemame/Calibre-Web-NextGen/issues/1121), downstream of [#1048](https://github.com/new-usemame/Calibre-Web-NextGen/issues/1048) @auspex) | **`calibre_db.session` was a single shared attribute standing in for per-thread state, so a background task could tear down the session a request was still streaming from.** `CalibreDB.session_factory` is a `scoped_session`, which exists to hand each thread its own Session; `init_session()` then did `self.session = self.session_factory()`, publishing *the calling thread's* Session onto one attribute of a module-level singleton that **~270 call sites** read. Whichever thread called it last won, and the thread-locality the wrapper exists to provide was discarded by the assignment. It bites harder here than in a typical Flask app because CWNG runs gevent **without** `monkey.patch_all()` (pinned by the AST guard in `test_no_stdlib_futures_on_request_path`), so `WorkerThread` is a real OS thread rather than a greenlet — two genuinely concurrent users of one Session. **Every background task inherits it** (`duplicate_scan`, `thumbnail`, `metadata_backup`, `hardcover_sync`, `auto_send`, `convert`), which is why the symptom kept resurfacing with unrelated-looking tracebacks. **The #1048 link was recorded on #1121 as a hypothesis and is now OBSERVED.** #1121 said exactly what would settle it — "queue a manual scan while a slow paginated browse is streaming, and assert the browse completes" — and noted that two earlier attempts had failed because closing and re-using a Session *sequentially* is harmless (a Session simply re-acquires a connection, even under `NullPool`). The reporter's traceback is a cursor being **drained**, so the interleave had to be genuine. `test_1121_worker_close_during_request_fetch.py` builds it: the reader iterates `yield_per` so rows arrive from a live cursor in batches, pauses mid-stream, and only then lets the worker run `duplicate_scan`'s teardown shape (`ensure_session()` … `session.close()`, `cps/tasks/duplicate_scan.py:90,324-325`). Against `main` the reader dies — `InvalidRequestError: Object <_Row> cannot be converted to 'persistent' state, as this identity map is no longer valid. Has the owning Session been closed?` **Scoped honestly**: that is the *mechanism*, not the reporter's exact frame (they saw `sqlite3.ProgrammingError` from `_raw_all_rows`); which error surfaces depends on how far into the fetch the close lands, and the PR says so rather than over-claiming. **Fix**: `session` becomes a property resolving through the `scoped_session` registry on every read. The setter is kept because callers assign to it — `cps/editbooks.py:1072` drops a poisoned session with `calibre_db.session = None` then calls `ensure_session()`, and tests substitute stubs — but those assignments are now scoped to the assigning thread instead of leaking to every other one. **Three contract gaps, each found by the suite rather than by inspection, and fixed rather than worked around**: `__init__` no longer assigns `self.session = None`, because that would run the setter and tear down the *calling* thread's session and `CalibreDB()` is constructed inside request handlers (`cps/web.py:1373`, `magic_shelf.py:1009,1076`); the thread-local slot is built lazily rather than only in `__init__`, since several tests construct instances via `CalibreDB.__new__(CalibreDB)` to avoid needing a Flask app and a property that raises `AttributeError` on a partially built instance is a worse contract than the plain attribute it replaced; and the property needs a **deleter**, because `mock.patch.object(calibre_db, "session", ...)` records that the attribute was absent from `__dict__` and restores by deleting it. `dispose()` reads a new non-creating `_peek_session()` so it does not materialise a Session for the disposing thread purely to close it. Incidental gain: threads read the current `session_factory` on every access, so a factory rebuilt by `setup_db` now reaches every thread rather than only the one that ran the loop. **Explicitly NOT claimed: this does not make `calibre_db` thread-safe.** `notes/fix-udf-gil-deadlock-DESIGN.md` records that `StaticPool` is architecturally required (the calibre engine is `sqlite://` with per-connection `ATTACH` of calibre.db + app.db; per-thread connections via QueuePool/NullPool were considered and rejected as a much larger change), so **every thread still shares one DBAPI connection** and transaction boundaries on it remain process-global — a `commit()` on one thread still commits another's in-flight writes. That is not a regression: with a single shared Session the same held, *plus* the identity map was shared and could be closed underneath a reader. Session sharing is what the reported crashes come from; the residual connection-level sharing is filed as follow-up, not treated as fixed. **Blast radius, and it earned its keep**: the first version of this change caused **38** regressions and the second **25** — both contract gaps above, neither a design fault. Final state verified by running the full `tests/unit` + `tests/smoke` suite on `main` and on the branch in the same venv and diffing the failure sets: **4174 passed / 8 failed on the branch vs 4172 / 8 on `main`, the 8 byte-identical, zero regressions** (the +2 are this change's own tests). Both new test files proven RED against `main` by swapping in `git show main:cps/db.py` and GREEN after. Un-quarantines `test_1121_session_is_thread_local.py` from #1122, which was RED by design. **One caveat recorded rather than hidden**: during an intermediate state (deleter not yet added, so `patch.object` teardown was raising) one suite run stalled ~10 minutes at 0.6% CPU without `pytest-timeout` firing — the signature of the known GIL↔sqlite-mutex class in that design note. It did not recur; the committed code ran the full suite to completion twice (185s, 176s). No route, dependency, license or external URL change. Fork-original. **Extended to also fix [#1150](https://github.com/new-usemame/Calibre-Web-NextGen/issues/1150), which the review of this PR surfaced and which is the other half of the same question — "what is the lifetime of a Session here".** Restoring *thread*-locality is necessary but not sufficient: requests are gevent greenlets and `monkey.patch_all()` is deliberately absent, so every concurrent request runs on **one** OS thread and `threading.local()` cannot separate them. They therefore still shared a Session, while `shutdown_session` (`cps/__init__.py:469-482`) calls `session_factory.remove()` on **every** request teardown — so the first request to finish closed the Session the others were still reading from, and the victim failed wherever it happened to be (`InvalidRequestError: Instance ... is not persistent within this Session`). That is on `main` today, pre-dates this PR, and is reachable by any two concurrent requests; the property alone would have made it *sharper*, since a foreign `remove()` then changes what `calibre_db.session` returns mid-request. **Fix**: `setup_db` builds the factory through a new `_make_session_factory()` that passes `scopefunc=greenlet.getcurrent`. `greenlet.getcurrent()` is a distinct object per greenlet **and** a distinct root greenlet per OS thread — measured, 4 distinct across main + 3 threads — so greenlet scope *subsumes* thread scope rather than replacing it: worker threads stay isolated exactly as the #1121 fix made them, and request greenlets are now isolated from each other too. Per-request `remove()` becomes correct instead of destructive, because it can only reach the caller's own Session. **A leak the scopefunc introduces, caught by measuring rather than by assuming**: passing any `scopefunc` swaps SQLAlchemy's `ThreadLocalRegistry` (a `threading.local`, freed with its thread) for `ScopedRegistry`'s plain dict, which retains a Session for every greenlet that never reaches a teardown — measured at **50 retained for 50 dead greenlets**. Greenlets are weak-referenceable, so the registry map is a `WeakKeyDictionary`, which measures **0**; the earlier "registry does not leak" finding was about `ThreadLocalRegistry` and does **not** carry over. `greenlet` is already a pinned hard requirement (`requirements.txt:40`) and a dependency of gevent, so **no new dependency** — the `ImportError` fallback to default thread scope exists only for the tornado path, where there are no greenlets and thread scope is already right. Verified live in `cwn-local` against the real `@app.teardown_appcontext` hook, and by parallel-request hammering per `notes/verify/FAILURE-MODES.md` class 7. Regression coverage in `tests/unit/test_1150_greenlet_scoped_sessions.py`, including a **falsifiability control** (class 9b) that runs the identical interleave against the factory `main` builds and asserts it still crashes — the guard cannot be imported on `main`, so this is what keeps it honest. Transaction boundaries remain process-global for the `StaticPool` reason above; unchanged by this, and tracked separately. | `d50be7518` | TBD | | [#1146](https://github.com/new-usemame/Calibre-Web-NextGen/pull/1146) | (fork issue [#1144](https://github.com/new-usemame/Calibre-Web-NextGen/issues/1144)) | **Every load of the library fetched page 1 twice, at two different sizes, and threw the first response away.** `Catalog.tsx` requests `rowsPerLoad × columnCount` books; `columnCount` started as a **guess** derived from `books_per_page` and was then corrected by a `ResizeObserver` reading the grid's computed `gridTemplateColumns`. The guess and the measurement rarely agree, so `perPage` changed immediately after first render and the query refired — observed on the wire as `page=1&per_page=4` followed by `page=1&per_page=12`. Not a visual defect: sampling the rendered card count every 200ms across the first 2.4s of a load gives `0 16 16 16…`, so the discarded response is never painted. The cost is a wasted round trip per load per user, and on a large library the first-page book query is the expensive query on that page. **Fix**: gate the query on the measurement so only the measured size is ever requested. **The obvious form of that gate deadlocks, and that is the substance of this change** — during first load the skeleton *replaced* the grid, so `gridNode` was null, the observer never attached, `measure()` never ran, the query never enabled, and the library came up **empty** (observed on a deployed branch: `page=1` requests 0, rendered cards 4 — the Discover strip alone). The element that reports the column count only existed once there was something to show. The loading state therefore now renders **inside** the grid container rather than in place of it; a CSS grid reports its track count with no children, so it is measurable on the first paint, and as a side effect the load state lays out on the same track geometry as the cards that replace it instead of reflowing into them. Two guards keep the gate from ever being the reason a library is blank: a series rendered as a list builds no grid and does not wait, and any path that fails to measure within 150ms falls back to the guess and queries anyway — **worst case is the old redundant fetch, never an empty page**. `isFirstLoad` also had to account for the pre-measurement render explicitly, since react-query does not consider a *disabled* query "loading"; without that the page fell through to the empty state and flashed "No books here" before issuing its first request. **Verified against the real backend, not a mock**: the new spec counts what the app puts on the wire with no route interception, and was proven **RED against the pre-fix build** by reverting only the source change, rebuilding and redeploying while keeping the test — `Received array: ["4", "12"]`, the reported signature exactly — then **GREEN on desktop and mobile (375×667)**. **Also repairs `infinite-scroll.spec.ts`, one of the 19 specs failing on every run in [#1130](https://github.com/new-usemame/Calibre-Web-NextGen/issues/1130)**, which could not be repaired honestly until this was settled: it pinned `PER_PAGE = 24` and asserted it on every page-1/page-2 request, but `per_page` is `rowsPerLoad × measured columns` and varies with viewport and density, so **no constant is correct**. The constant was the bug; the duplicate fetch underneath it is what made the failure read as a stale test. The mock now reads the size off the request and serves two pages of whatever was asked for, and gained an assertion that both pages are requested at one size. **Removing the redundant fetch then exposed a latent bug in `useIntersectionObserver` that the redundant fetch had been hiding, and the full-suite blast-radius run is what caught it** — `author-separator.spec.ts` went red, and an A/B against the same container and the same database (baseline build passes in 1.5s, fixed build fails after 19s) proved it was caused here rather than flaky. Root cause: the hook read `sentinelRef.current` at the moment its effect ran, with deps `[enabled, onIntersect, threshold, rootMargin]` — none of which change when the sentinel element *mounts*. Every paged list renders its sentinel only after results arrive, so the order that matters is: results land, `enabled` flips true while the accumulator is still empty and the empty state is rendering, the effect runs and finds no sentinel, and the grid and its sentinel then mount with nothing re-running. The observer stayed bound to nothing, scrolling silently stopped loading, and only "Load more" still worked. The second fetch used to churn `isFetching`/`hasMore` enough to re-run the effect *after* the sentinel had mounted, so the observer was getting attached by accident. Tracking the sentinel as **state** rather than a ref makes the ref callback re-run the effect when the element appears (and again with null when it goes), so the observer follows what is rendered; this covers `Shelf`, `Table`, `MagicShelfView` and `AdvancedSearch`, which all mount their sentinel the same way. **Checked, not assumed, whether that bug is live on `main`**: probing scroll auto-load on the library and table views against an unmodified `main` build reaches page 2 in both (library as `[1,1,2]` — the duplicate fetch, then page 2), so it is **latent** upstream of this change and gets no user-facing changelog claim. Covered by a new spec that scrolls the **real** observer instead of clicking the fallback button — deliberately, since the existing #704 spec stubs `IntersectionObserver` out entirely, which is precisely why nothing caught this — verified RED against the old hook (`requested pages [1]`, never 2) and GREEN after, desktop and mobile. **Blast radius**: full SPA e2e suite run three times (baseline 7 failed / 278 passed, final 10 failed / 278 passed); the four `infinite-scroll` failures and both `author-separator` failures are **fixed**, and the residual delta is an `a11y.spec.ts` cluster **proven non-deterministic** by running it twice against one unchanged build (4 vs 9 failures, different pages each time, including `login (unauthenticated)` and `account`) whose violations are light-theme *sidebar* contrast selectors this diff cannot reach — filed separately. Frontend only — no route, dependency, license or external URL, and no auth/session/CSRF/crypto/subprocess/file-path surface, so no `/security-review` class applies. Fork-original. | `a287cdff1` | TBD | | [#1101](https://github.com/new-usemame/Calibre-Web-NextGen/pull/1101) | (fork issue [#920](https://github.com/new-usemame/Calibre-Web-NextGen/issues/920) @iroQuai) | **KOReader highlight sync was undiagnosable: every failure mode on `/kosync/syncs/annotations` was silent, and two of them returned HTTP 200 while saving nothing.** The device surfaces one bit — "Highlights synced" or "Server push failed" — and the plugin has only the HTTP status to go on, so the server log is the sole diagnostic surface for a highlight-sync report. It had none: `push_annotations`/`pull_annotations` carried no INFO logging at all, only two `log.exception` fan-out guards and one `log.debug`. Reproduced on the wire against a live `cwn-local`: four distinct outcomes — 400 `invalid_deleted`, 400 `invalid_delete_source`, an unknown document, and a malformed annotation — produced **zero** log lines between them. Two are worse than silent because they are **200**, so the device tells the user the sync succeeded: an unmatched document returns `matched: false` (the usual shape of a book with no registered checksum, i.e. "my highlights sync but never appear"), and a payload `apply_portable` declines returns `skipped: N` with the highlight dropped on the floor. This is the root cause of #920's ten-day, three-wrong-diagnosis loop: @iroQuai read `docker logs`, correctly saw no annotation processing, and reasonably concluded the request never arrived — but silence was the *expected* output of a fully successful push too, so the observation could not discriminate anything. The progress route next door logs every save at INFO (promoted in #312 for exactly this reason); the annotation routes never got the same treatment. **Fix**: every rejection returns through one `_reject()` helper that logs user + document + error code + message, so no branch can regress to silence individually; the success path logs `created/updated/deleted/skipped` plus `pushed`/`named_deletes` counts; `matched: false` and `skipped > 0` log at **WARNING** since both are 200s that lose data; a delete naming ids that matched no live row logs the ids. **Hardening found in self-review of this change**: `is_valid_key_field` bars only colons and over-length, so a newline passes — logging the raw rejected `document` would have let a device forge log lines in the very surface being added. All nine device-supplied interpolations go through `_loggable()` (repr-escape + 80-char cap). **14 regression tests** in `tests/unit/test_920_koreader_annotation_sync_observability.py`, verified **12 RED on main / 14 GREEN after** (2 added with the hardening), driven through real Flask routing so a rejection that short-circuits before the handler body still has to account for itself. Two test premises were corrected against observed behaviour rather than assumed: an unrecognised key is `skipped`, not a 400, and `is_valid_key_field` accepts spaces. 62 adjacent KOReader/annotation tests re-run green. **Live-container verified** on patched `cwn-local`: the exact delete push the device makes now logs `created=0 updated=0 deleted=1 skipped=0 (pushed=0 named_deletes=1)`, the 400 logs `error=invalid_deleted (...)`, the unmatched book logs `WARN ... matched NO book — 1 annotation(s) and 0 delete(s) were NOT saved`. **Cross-family review (Terra, 2 rounds, session resumed for round 2) caught a regression this PR introduced**: the unmatched-book reply is returned *before* the `annotations`/`deleted` shape checks, so taking `len()` of them for the log line turned a request that has always answered 200 into a **500** (`{"annotations": 1}` -> `TypeError: object of type 'int' has no len()`; `{"deleted": true}` likewise) — confirmed on the wire, fixed via `_describe_count()` (counts a real list, names the shape otherwise), 6 shape cases added of which 4 were RED against the pre-fix commit. Round 2 added three LOW fixes: `_describe_count({})` was calling the single most common shape KOReader sends "not an array" (Lua emits `{}` for an empty table and the handler accepts it as an empty set); the rejection-body test asserted only a substring of `message`, so all six rejection contracts now pin the exact body incl. `invalid_payload` and the invalid-document response that were uncovered; and `test_successful_delete_logs_the_named_ids` was misnamed (it pins counts — aggregate logging kept deliberately, since ids are volume with no diagnostic gain on success and are already logged when they match nothing). Final: **27 tests** in the new file, **108** across the KOReader/annotation suites, live `cwn-local` rebuilt with 0 errors since restart. Logging only — no behaviour, route, dependency, license or external URL change; adds ~2 lines per sync, matching the existing kosync progress convention. Fork-original. | `4b5eacb95` | v4.1.21 | diff --git a/root/etc/s6-overlay/s6-rc.d/cwa-ingest-service/run b/root/etc/s6-overlay/s6-rc.d/cwa-ingest-service/run index 13f9ff03c..43cedb785 100644 --- a/root/etc/s6-overlay/s6-rc.d/cwa-ingest-service/run +++ b/root/etc/s6-overlay/s6-rc.d/cwa-ingest-service/run @@ -236,6 +236,31 @@ is_recent_duplicate_event() { run_processor_with_timeout() { local safety_timeout="$1" local filepath="$2" + # Give the processor its own conversion deadline just inside the hard + # one, so a slow conversion ends as a normal Python failure -- which + # imports the original instead of losing it (#1094) -- rather than as + # a SIGTERM that kills the processor before it can recover. Derived + # here so the two limits can't drift apart. The margin is the budget + # for backing up and importing the original after the deadline fires. + # `timeout 0` means "no limit", so there is nothing to sit inside of. + if [ "$safety_timeout" -gt 0 ] 2>/dev/null; then + # Reserve ~10% for backing up and importing the original after + # the deadline fires, with a 30s floor so the reserve is useful + # at ordinary timeouts. The reserve is then capped at a fifth of + # the budget so it can never swallow the conversion window: a + # flat floor applied to a small timeout used to invert the two + # (a 31s timeout left 1s to convert while 30s left 23s), which + # is a cliff rather than a margin. Capping keeps the deadline + # monotonic in the timeout across the whole range. + local max_margin=$(( safety_timeout / 5 )) + [ "$max_margin" -lt 1 ] && max_margin=1 + local margin=$(( safety_timeout / 10 )) + [ "$margin" -lt 30 ] && margin=30 + [ "$margin" -gt "$max_margin" ] && margin=$max_margin + export CWA_CONVERSION_DEADLINE_SECONDS=$(( safety_timeout - margin )) + else + unset CWA_CONVERSION_DEADLINE_SECONDS + fi # Privilege-drop to the abc service user (PR #37 / #56) so books # written by the ingest pipeline land with PUID:PGID ownership # rather than root:root. The CWA_INGEST_PROCESSOR_CMD override @@ -493,13 +518,14 @@ handle_event() { if [ $exit_code -eq 124 ]; then echo "[cwa-ingest-service] SAFETY TIMEOUT: $filepath took longer than safety timeout of ${safety_timeout} seconds" - echo "[cwa-ingest-service] This indicates a serious issue - processor should have timed out internally at ${configured_timeout} seconds" + echo "[cwa-ingest-service] This is the only limit on conversion time - a large or image-heavy book can legitimately need longer." + echo "[cwa-ingest-service] Raise 'Ingest Timeout' in CWA Settings to increase it (safety timeout is 3x that value)." echo "safety_timeout:$filename:$(date '+%Y-%m-%d %H:%M:%S')" > "$STATUS_FILE" # Move problematic file to failed backup with timestamp if [ -d "/config/processed_books/failed" ]; then local timestamp=$(date '+%Y%m%d_%H%M%S') local failed_filename="${timestamp}_safety_timeout_${filename}" - echo "[cwa-ingest-service] Moving $filename to failed backup as $failed_filename" + echo "[cwa-ingest-service] Moving $filename to /config/processed_books/failed/$failed_filename" cp "$filepath" "/config/processed_books/failed/$failed_filename" 2>/dev/null || true fi rm -f "$filepath" 2>/dev/null || true diff --git a/scripts/ingest_processor.py b/scripts/ingest_processor.py index 4177b34b7..c6b8fb148 100644 --- a/scripts/ingest_processor.py +++ b/scripts/ingest_processor.py @@ -31,6 +31,12 @@ # the lazy load hasn't happened yet (or fails in a test environment). _calibre_plugins = None _CPS_ROOT = "/app/calibre-web-automated" + +# Anchor for the shared conversion budget (#1094). Bound at import so it +# tracks the same span the service's `timeout` wrapper is measuring, rather +# than restarting per conversion stage. Monotonic, so a clock change during a +# long conversion can't hand back a budget that never expires. +_PROCESS_START_MONOTONIC = time.monotonic() from contextlib import contextmanager as _contextmanager @@ -416,6 +422,61 @@ def _ensure_processed_books_dirs() -> None: print(f"[ingest-processor] WARN: Could not ensure processed_books directories: {e}", flush=True) +def conversion_deadline_seconds(): + """In-process conversion deadline, or None when there isn't one. + + The ingest service sets CWA_CONVERSION_DEADLINE_SECONDS just inside the + hard `timeout` it wraps us in. Owning a deadline of our own is what lets a + slow conversion end as an ordinary failure — which imports the original + rather than losing it (#1094) — instead of a SIGTERM that kills us first. + Absent or unparseable means no deadline, which is the right default for a + direct invocation with no supervisor holding a stopwatch. + + OverflowError is caught alongside the parse errors: float('inf') parses + cleanly and only fails at int(), and an unbounded deadline is exactly the + case where we must not raise out of the caller's timeout= argument. + """ + raw = os.environ.get("CWA_CONVERSION_DEADLINE_SECONDS") + if not raw: + return None + try: + value = int(float(raw)) + except (TypeError, ValueError, OverflowError): + print(f"[ingest-processor] WARN: ignoring unparseable CWA_CONVERSION_DEADLINE_SECONDS={raw!r}", flush=True) + return None + return value if value > 0 else None + + +def conversion_budget_remaining(): + """Seconds left of the whole-process conversion budget, or None if unbounded. + + The budget is one shared allowance, not a fresh timeout per subprocess. + A kepub ingest of a non-EPUB runs two conversions back to back, and giving + each the full deadline would let them add up to more than the watchdog + allows — the second would still be running when SIGTERM arrives, which is + the book-losing failure #1094 is about. Anchoring to process start also + matches what the outer `timeout` is actually measuring. + + A budget that is already spent returns a small positive value rather than + zero or a negative: subprocess.run() treats that as an immediate + TimeoutExpired, which routes into the ordinary conversion-failure handler + and imports the original, instead of raising ValueError from a negative. + """ + total = conversion_deadline_seconds() + if total is None: + return None + return max(0.1, total - (time.monotonic() - _PROCESS_START_MONOTONIC)) + + +def failed_backup_dir() -> str: + """Absolute path of the folder holding files that failed to convert. + + cwa-init creates it, so the scandir in _load_backup_destinations() normally + finds it; the literal is the fallback for a container where it is missing. + """ + return backup_destinations.get("failed") or "/config/processed_books/failed" + + def _load_backup_destinations() -> None: global backup_destinations try: @@ -740,6 +801,23 @@ def run_duplicate_scan_for_books(book_ids) -> None: } +# fork #1094: formats where a failed conversion means "this was never a book". +# Importing the original rescues a real book whose conversion failed, but for +# these it would file a junk entry — an .acsm is an Adobe fulfillment ticket, +# and the guidance above promises the user it went to processed_books/failed. +_NOT_A_BOOK_FORMATS = frozenset({'acsm'}) + + +def is_rescuable_on_conversion_failure(input_format) -> bool: + """Whether importing the original is right when its conversion failed. + + True for real book formats: a conversion failure says nothing about + whether the file is a readable book. False for formats that are not + books at all, where the original is a ticket or container. + """ + return (input_format or '').lower() not in _NOT_A_BOOK_FORMATS + + def conversion_failure_guidance(input_format, filename): """Return user-facing guidance for a failed conversion of input_format, or None when no format-specific advice exists. @@ -1048,6 +1126,9 @@ def backup(self, input_file, backup_type): os.makedirs(output_path, exist_ok=True) destination = shutil.copy(input_file, output_path) os.utime(destination, None) + # Name the absolute directory: "moved to failed backup" on its own + # left users with nowhere to look (#1094). + print(f"[ingest-processor]: Saved a copy of {os.path.basename(input_file)} to {output_path}", flush=True) except Exception as e: # Never let backups crash ingest; just log the problem print(f"[ingest-processor]: ERROR - Failed to backup '{input_file}' to '{output_path}': {e}") @@ -1066,7 +1147,8 @@ def convert_book(self, end_format=None) -> tuple[bool, str]: target_filepath = f"{self.tmp_conversion_dir}{original_filepath.stem}.{end_format}" try: t_convert_book_start = time.time() - subprocess.run(['ebook-convert', self.filepath, target_filepath], env=self.calibre_env, check=True) + subprocess.run(['ebook-convert', self.filepath, target_filepath], env=self.calibre_env, check=True, + timeout=conversion_budget_remaining()) t_convert_book_end = time.time() time_book_conversion = t_convert_book_end - t_convert_book_start print(f"\n[ingest-processor]: END_CON: Conversion of {self.filename} complete in {time_book_conversion:.2f} seconds.\n", flush=True) @@ -1092,6 +1174,39 @@ def convert_book(self, end_format=None) -> tuple[bool, str]: self.backup(self.filepath, backup_type="failed") return False, "" + except subprocess.TimeoutExpired: + # Ran past our own deadline. Returning a normal failure hands control + # back to main(), which imports the original — the alternative is the + # supervisor's SIGTERM killing us mid-conversion, taking the book with + # it, which is what #1094 reported. + print(f"\n[ingest-processor]: CON_ERROR: {self.filename} could not be converted to {end_format} within its " + f"{conversion_deadline_seconds()}s conversion budget, which covers this whole ingest run — including " + f"the wait for the file to finish copying in, so a slow copy leaves less time to convert.\n" + f"A large or image-heavy book can legitimately need longer — raise 'Ingest Timeout' in CWA Settings " + f"to allow more time.", flush=True) + self.backup(self.filepath, backup_type="failed") + return False, "" + + except OSError as e: + # ebook-convert missing or not executable. Still a conversion + # failure, so it must not fall through as an unhandled exception. + print(f"\n[ingest-processor]: CON_ERROR: could not run the converter for {self.filename}: {e}", flush=True) + self.backup(self.filepath, backup_type="failed") + return False, "" + + + def _backup_failed_kepub_inputs(self, converted_filepath) -> None: + """Keep the original alongside any intermediate epub. + + The kepub path may convert the original to epub first, and the old + failure handler backed up only that intermediate — so for a non-epub + input the failed folder never held the file the user actually dropped + in, which is the one they would retry (#1094). + """ + self.backup(self.filepath, backup_type="failed") + if converted_filepath and str(converted_filepath) != str(self.filepath): + self.backup(str(converted_filepath), backup_type="failed") + # Kepubify can only convert EPUBs to Kepubs def convert_to_kepub(self) -> tuple[bool,str]: @@ -1112,7 +1227,8 @@ def convert_to_kepub(self) -> tuple[bool,str]: converted_filepath = Path(converted_filepath) target_filepath = f"{self.tmp_conversion_dir}{converted_filepath.stem}.kepub" try: - subprocess.run(['kepubify', '--inplace', '--calibre', '--output', self.tmp_conversion_dir, converted_filepath], check=True) + subprocess.run(['kepubify', '--inplace', '--calibre', '--output', self.tmp_conversion_dir, converted_filepath], check=True, + timeout=conversion_budget_remaining()) if self.cwa_settings['auto_backup_conversions']: self.backup(self.filepath, backup_type="converted") @@ -1126,10 +1242,20 @@ def convert_to_kepub(self) -> tuple[bool,str]: except subprocess.CalledProcessError as e: error_detail = e.stderr if e.stderr else "(see kepubify output above)" print(f"[ingest-processor]: CON_ERROR: {self.filename} could not be converted to kepub due to the following error:\nEXIT/ERROR CODE: {e.returncode}\n{error_detail}", flush=True) - self.backup(converted_filepath, backup_type="failed") + self._backup_failed_kepub_inputs(converted_filepath) + return False, "" + except subprocess.TimeoutExpired: + print(f"[ingest-processor]: CON_ERROR: {self.filename} could not be converted to kepub within " + f"{conversion_deadline_seconds()} seconds.\nRaise 'Ingest Timeout' in CWA Settings to allow more time.", flush=True) + self._backup_failed_kepub_inputs(converted_filepath) return False, "" except Exception as e: + # Must return a pair: main() unpacks this call, so falling + # through returned None and raised TypeError, skipping the + # failure fallback and dropping the book entirely (#1094). print(f"[ingest-processor] ingest-processor ran into the following error:\n{e}", flush=True) + self._backup_failed_kepub_inputs(converted_filepath) + return False, "" else: print(f"[ingest-processor]: An error occurred when converting the original {self.input_format} to epub. Cancelling kepub conversion...", flush=True) return False, "" @@ -1882,13 +2008,21 @@ def main(filepath=None): else: if nbp.auto_convert_on and nbp.can_convert: # File can be converted to target format and Auto-Converter is on + # Tracks whether a conversion was actually run. The ignore-list + # branch below reports convert_successful=False having already + # imported the original, so the failure fallback must not treat + # it as a failed conversion and import a second copy. + conversion_attempted = False + if nbp.input_format in nbp.convert_ignored_formats: # File could be converted & the converter is activated but the user has specified files of this format should not be converted print(f"\n[ingest-processor]: {nbp.filename} not in target format but user has told CWA not to convert this format so importing the file anyway...", flush=True) nbp.add_book_to_library(filepath) convert_successful = False elif nbp.target_format == "kepub": # File is not in the convert ignore list and target is kepub, so we start the kepub conversion process + conversion_attempted = True convert_successful, converted_filepath = nbp.convert_to_kepub() else: # File is not in the convert ignore list and target is not kepub, so we start the regular conversion process + conversion_attempted = True convert_successful, converted_filepath = nbp.convert_book() if convert_successful: # If previous conversion process was successful, remove tmp files and import into library @@ -1919,6 +2053,11 @@ def main(filepath=None): except Exception as e: print(f"[ingest-processor] Error adding retained format: {e}", flush=True) + elif conversion_attempted and is_rescuable_on_conversion_failure(nbp.input_format): # Conversion failed. Import the original anyway — a failed conversion is no reason to drop the book (#1094) + print(f"\n[ingest-processor]: {nbp.filename} could not be converted to {nbp.target_format}, importing the original {nbp.input_format} instead so the book still lands in your library...", flush=True) + print(f"[ingest-processor]: The file that failed to convert was also copied to {failed_backup_dir()} if you want to retry it by hand.", flush=True) + nbp.add_book_to_library(filepath) + elif nbp.can_convert and not nbp.auto_convert_on: # Books not in target format but Auto-Converter is off so files are imported anyway print(f"\n[ingest-processor]: {nbp.filename} not in target format but CWA Auto-Convert is deactivated so importing the file anyway...", flush=True) nbp.add_book_to_library(filepath) diff --git a/tests/unit/test_1094_failed_conversion_imports_original.py b/tests/unit/test_1094_failed_conversion_imports_original.py new file mode 100644 index 000000000..e67e7756a --- /dev/null +++ b/tests/unit/test_1094_failed_conversion_imports_original.py @@ -0,0 +1,660 @@ +# Calibre-Web Automated – fork of Calibre-Web +# Copyright (C) 2024-2026 Calibre-Web-NextGen contributors +# SPDX-License-Identifier: GPL-3.0-or-later + +"""Fork #1094: a book whose conversion failed vanished from the library. + +Reported by @auspex against v4.1.20: a 63MB PDF was picked up, spent 45 +minutes in ``ebook-convert``, got killed by the service safety timeout, and +then simply was not there. The library had no entry for it and the ingest +folder no longer held the file. + +The cause was structural, not timeout-specific. ``main()`` imported the book +only inside ``if convert_successful:`` and had no ``else``, so *every* +conversion failure — timeout, unsupported internals, a corrupt source, a +missing plugin — returned without ever calling ``add_book_to_library()``, +while the ``finally`` block deleted the source from the ingest folder. The +two sibling branches that decline to convert (format in the ignore list, +auto-convert switched off) both import the original already, so the fallback +makes the behaviour consistent rather than introducing a new rule. + +Pinned behaviour: + 1. A failed ``convert_book()`` still imports the ORIGINAL file. + 2. A failed ``convert_to_kepub()`` does the same. + 3. A SUCCESSFUL conversion still imports the CONVERTED file and not the + original (anti-vacuity — a fallback that always fires would pass 1 and 2 + while breaking the normal path). + 4. ``backup()`` names the absolute destination directory it wrote to, so + "moved to failed backup" is actionable instead of a dead end. + 5. The ingest service no longer claims the processor "should have timed out + internally", because it previously had no conversion timeout at all — + ``ingest_timeout_minutes`` bounded only the file-stability wait. + 6. The processor now owns a conversion deadline just inside the service's + hard ``timeout``, derived from it in one place. Without that, the + reporter's own case never reached the fallback at all: the supervisor + SIGTERMed the processor mid-conversion, so ``main()`` never regained + control. An overrun is now an ordinary failure, and the book is imported. + 7. Every non-success path of ``convert_to_kepub()`` returns a ``(bool, str)`` + pair. One returned ``None``, which made ``main()``'s tuple-unpack raise + ``TypeError`` and skip the fallback — dropping the book for exactly the + reason this issue is about. + 8. A failed kepub conversion backs up the original as well as any + intermediate epub, so the failed folder holds the file the user dropped. + 9. The conversion deadline is ONE shared budget across both stages, not a + fresh timeout per subprocess. A kepub ingest of a non-EPUB converts twice + inside one hard timeout; two full deadlines could add up to more than the + watchdog allowed, leaving the second conversion running when SIGTERM + arrived — re-opening this very bug at the DEFAULT timeout setting. + 10. The deadline is monotonic in the hard timeout. A flat 30s reserve applied + to a small timeout inverted the two (a 31s timeout left 1s to convert + while a 30s timeout left 23s); the reserve is now capped so conversion + always keeps the majority of the budget. + +Findings 9 and 10, plus the OverflowError on a non-finite env value, came from +the cross-family review of PR #1157. The converter-child cleanup finding from +the same review is tracked separately in #1161. +""" + +import os +import subprocess +import sys +import time +from pathlib import Path + +import pytest + +pytestmark = pytest.mark.unit + +REPO_ROOT = Path(__file__).resolve().parents[2] +SCRIPTS_DIR = str(REPO_ROOT / "scripts") + +if SCRIPTS_DIR not in sys.path: + sys.path.insert(0, SCRIPTS_DIR) + +import ingest_processor # noqa: E402 + +INGEST_SERVICE_RUN = ( + REPO_ROOT / "root/etc/s6-overlay/s6-rc.d/cwa-ingest-service/run" +) +INGEST_PROCESSOR_PATH = REPO_ROOT / "scripts/ingest_processor.py" + + +def _shell_function_body(text, name): + """Body of a shell function, from its opening line to the closing brace. + + A fixed byte window silently truncated mid-expression and failed on an + edit that only made the function longer. + """ + lines = text.splitlines() + start = next( + (i for i, l in enumerate(lines) if l.startswith(f"{name}() {{")), None + ) + assert start is not None, f"{name}() not found in {INGEST_SERVICE_RUN}" + end = next( + (i for i in range(start + 1, len(lines)) if lines[i] == "}"), None + ) + assert end is not None, f"no closing brace for {name}()" + return "\n".join(lines[start : end + 1]) + + +def _conversion_processor(tmp_path): + """Minimal real NewBookProcessor for exercising convert_book() directly.""" + nbp = object.__new__(ingest_processor.NewBookProcessor) + nbp.filepath = str(tmp_path / "Big Handbook.pdf") + Path(nbp.filepath).write_bytes(b"pdf bytes") + nbp.filename = "Big Handbook.pdf" + nbp.input_format = "pdf" + nbp.target_format = "epub" + nbp.tmp_conversion_dir = str(tmp_path) + os.sep + nbp.calibre_env = os.environ.copy() + nbp.cwa_settings = {"auto_backup_conversions": False} + nbp.backed_up = [] + nbp.backup = lambda f, backup_type: nbp.backed_up.append((f, backup_type)) + return nbp + + +class _FakeProcessor: + """Stands in for NewBookProcessor so main()'s real control flow runs.""" + + def __init__(self, filepath, *, convert_result, target_format="epub"): + self.filepath = filepath + self.filename = os.path.basename(filepath) + self.input_format = "pdf" + self.target_format = target_format + self.tmp_conversion_dir = os.path.join( + os.path.dirname(filepath), "tmp_conversion" + ) + os.sep + self.ingest_ignored_formats = [] + self.convert_ignored_formats = [] + self.convert_retained_formats = [] + self.cwa_settings = {"ingest_timeout_minutes": 15} + self.is_target_format = False + self.auto_convert_on = True + self.can_convert = True + self.last_added_book_id = None + self._convert_result = convert_result + # Recorded calls + self.imported = [] + self.convert_book_calls = 0 + self.convert_to_kepub_calls = 0 + + # -- flow stubs ---------------------------------------------------- + def is_file_in_use(self, timeout=None): + return True + + def is_supported_audiobook(self): + return False + + def convert_book(self, end_format=None): + self.convert_book_calls += 1 + return self._convert_result + + def convert_to_kepub(self): + self.convert_to_kepub_calls += 1 + return self._convert_result + + def add_book_to_library(self, filepath, *args, **kwargs): + self.imported.append(filepath) + + def add_format_to_book(self, book_id, filepath): + pass + + def set_library_permissions(self): + pass + + def delete_current_file(self): + pass + + +def _run_main( + monkeypatch, + tmp_path, + *, + convert_result, + target_format="epub", + convert_ignored_formats=(), +): + """Drive the real main() over a fake processor, return (fake, source_path).""" + source = tmp_path / "Big Handbook.pdf" + source.write_bytes(b"%PDF-1.4 not really a pdf") + + holder = {} + + def _factory(filepath): + fake = _FakeProcessor( + filepath, convert_result=convert_result, target_format=target_format + ) + fake.convert_ignored_formats = list(convert_ignored_formats) + holder["fake"] = fake + return fake + + monkeypatch.setattr(ingest_processor, "NewBookProcessor", _factory) + monkeypatch.setattr( + ingest_processor, "_acquire_process_lock_or_exit", lambda: None + ) + + rc = ingest_processor.main(str(source)) + assert rc == 0 + return holder["fake"], str(source) + + +class TestFailedConversionStillImports: + def test_failed_conversion_imports_the_original(self, monkeypatch, tmp_path): + """#1094: the reported symptom — conversion fails, book is gone.""" + fake, source = _run_main( + monkeypatch, tmp_path, convert_result=(False, "") + ) + + assert fake.convert_book_calls == 1 + assert fake.imported == [source], ( + "a failed conversion must still import the original file; " + f"add_book_to_library calls were {fake.imported!r}" + ) + + def test_failed_kepub_conversion_imports_the_original( + self, monkeypatch, tmp_path + ): + fake, source = _run_main( + monkeypatch, + tmp_path, + convert_result=(False, ""), + target_format="kepub", + ) + + assert fake.convert_to_kepub_calls == 1 + assert fake.imported == [source] + + def test_successful_conversion_still_imports_the_converted_file( + self, monkeypatch, tmp_path + ): + """Anti-vacuity: the fallback must not fire on the happy path.""" + converted = str(tmp_path / "tmp_conversion" / "Big Handbook.epub") + fake, source = _run_main( + monkeypatch, tmp_path, convert_result=(True, converted) + ) + + assert fake.imported == [converted] + assert source not in fake.imported + + def test_ignored_format_is_imported_exactly_once(self, monkeypatch, tmp_path): + """The ignore-list branch imports the original and then reports + convert_successful=False. The fallback must not add a second copy — + that would file the same book twice on every deliberately-unconverted + format, which is worse than the bug being fixed.""" + fake, source = _run_main( + monkeypatch, + tmp_path, + convert_result=(False, ""), + convert_ignored_formats=("pdf",), + ) + + assert fake.convert_book_calls == 0, "no conversion should be attempted" + assert fake.imported == [source], ( + "an ignored format must be imported exactly once; got " + f"{len(fake.imported)} imports: {fake.imported!r}" + ) + + +class TestConversionDeadline: + """The reporter's actual failure was the supervisor's hard `timeout` + SIGTERMing the processor mid-conversion, so main() never regained control + and the fallback could not run. Owning a deadline just inside the hard one + turns that into an ordinary failure the fallback can handle.""" + + def test_absent_env_means_no_deadline(self, monkeypatch): + monkeypatch.delenv("CWA_CONVERSION_DEADLINE_SECONDS", raising=False) + assert ingest_processor.conversion_deadline_seconds() is None + + @pytest.mark.parametrize( + "raw,expected", + [("900", 900), ("2430", 2430), ("30.0", 30), ("0", None), ("-5", None), + ("", None), ("banana", None)], + ) + def test_env_parsing(self, monkeypatch, raw, expected): + monkeypatch.setenv("CWA_CONVERSION_DEADLINE_SECONDS", raw) + assert ingest_processor.conversion_deadline_seconds() == expected + + def test_convert_book_passes_the_deadline_to_the_converter( + self, monkeypatch, tmp_path + ): + monkeypatch.setenv("CWA_CONVERSION_DEADLINE_SECONDS", "1234") + captured = {} + + def _fake_run(cmd, **kwargs): + captured.update(kwargs) + raise subprocess.TimeoutExpired(cmd, 1234) + + monkeypatch.setattr(subprocess, "run", _fake_run) + nbp = _conversion_processor(tmp_path) + ok, out = nbp.convert_book() + + # The converter receives what is LEFT of the budget, not the raw total, + # so two stages can't each spend the whole thing. In a unit test almost + # nothing has elapsed, so it lands just under the total. + assert captured.get("timeout") == pytest.approx(1234, abs=60) + assert captured.get("timeout") <= 1234 + assert (ok, out) == (False, ""), ( + "a deadline overrun must be reported as an ordinary conversion " + "failure so main() imports the original" + ) + assert nbp.backed_up == [(str(nbp.filepath), "failed")] + + def test_converter_missing_is_a_failure_not_a_crash( + self, monkeypatch, tmp_path + ): + def _fake_run(cmd, **kwargs): + raise OSError(2, "No such file or directory") + + monkeypatch.setattr(subprocess, "run", _fake_run) + nbp = _conversion_processor(tmp_path) + assert nbp.convert_book() == (False, "") + + def test_shell_derives_the_deadline_from_the_hard_timeout(self): + """One source of truth for the two limits.""" + text = INGEST_SERVICE_RUN.read_text() + assert "CWA_CONVERSION_DEADLINE_SECONDS" in text + body = _shell_function_body(text, "run_processor_with_timeout") + assert "safety_timeout - margin" in body, ( + "the in-process deadline must be derived from the hard timeout, " + "not hard-coded alongside it" + ) + assert "export CWA_CONVERSION_DEADLINE_SECONDS" in body + assert "unset CWA_CONVERSION_DEADLINE_SECONDS" in body, ( + "`timeout 0` means no hard limit, so there is no envelope to sit " + "inside and no deadline should be imposed" + ) + + +class TestConversionBudgetIsSharedAcrossStages: + """A kepub ingest of a non-EPUB converts twice, back to back, inside ONE + hard timeout. Giving each stage a fresh full deadline let the two add up to + more than the watchdog allowed, so the second was still running when + SIGTERM arrived — the exact book-losing failure #1094 is about, reachable + at the DEFAULT timeout. The budget is therefore one shared allowance + anchored to process start, not a per-subprocess timeout.""" + + def test_second_stage_gets_less_than_the_first(self, monkeypatch): + monkeypatch.setenv("CWA_CONVERSION_DEADLINE_SECONDS", "600") + first = ingest_processor.conversion_budget_remaining() + # Simulate the first conversion having burned real time. Anchored to + # now, not to the import-time value: the suite's own runtime counts + # against a budget that is deliberately measuring wall clock. + monkeypatch.setattr(ingest_processor, "_PROCESS_START_MONOTONIC", + time.monotonic() - 400) + second = ingest_processor.conversion_budget_remaining() + + assert second < first, "the second stage must not get a fresh full budget" + assert second == pytest.approx(200, abs=5), ( + "after 400s of a 600s budget, ~200s must remain" + ) + + def test_two_stages_cannot_outlast_the_hard_timeout(self, monkeypatch): + """The property that actually protects the book: whatever the stages + spend, the total stays inside the budget the watchdog sits outside.""" + monkeypatch.setenv("CWA_CONVERSION_DEADLINE_SECONDS", "600") + for elapsed in (0, 100, 300, 599): + monkeypatch.setattr( + ingest_processor, "_PROCESS_START_MONOTONIC", + time.monotonic() - elapsed + ) + remaining = ingest_processor.conversion_budget_remaining() + assert elapsed + remaining <= 600 + 1, ( + f"at {elapsed}s elapsed, a {remaining}s grant would overrun the budget" + ) + + def test_exhausted_budget_is_positive_not_negative(self, monkeypatch): + """subprocess.run() raises ValueError on a negative timeout, which + would escape the conversion-failure handlers and drop the book. An + exhausted budget must instead expire immediately as a TimeoutExpired.""" + monkeypatch.setenv("CWA_CONVERSION_DEADLINE_SECONDS", "600") + monkeypatch.setattr(ingest_processor, "_PROCESS_START_MONOTONIC", + time.monotonic() - 9000) + remaining = ingest_processor.conversion_budget_remaining() + assert remaining > 0 + assert remaining < 1 + + def test_no_budget_when_unbounded(self, monkeypatch): + monkeypatch.delenv("CWA_CONVERSION_DEADLINE_SECONDS", raising=False) + assert ingest_processor.conversion_budget_remaining() is None + + @pytest.mark.parametrize("raw", ["inf", "Infinity", "1e309", "-inf"]) + def test_non_finite_env_is_ignored_not_raised(self, monkeypatch, raw): + """float('inf') parses cleanly and only fails at int(), raising + OverflowError — which is neither TypeError nor ValueError. Uncaught, it + escaped from the `timeout=` argument before subprocess.run() was even + called, bypassing the conversion-failure handlers entirely.""" + monkeypatch.setenv("CWA_CONVERSION_DEADLINE_SECONDS", raw) + assert ingest_processor.conversion_deadline_seconds() is None + assert ingest_processor.conversion_budget_remaining() is None + + def test_budget_covers_the_whole_run_not_just_converter_time(self): + """Deliberate policy, documented because it has a visible cost. + + The budget is anchored at process start, so time spent waiting for the + file to finish copying in is deducted from it — a file that becomes + ready late leaves less time to convert. Anchoring at conversion start + instead would let the inner deadline outrun the outer `timeout`, which + starts at process launch, and that is precisely the drift that loses + the book. Under-granting costs a conversion; over-granting costs the + book, so the budget is measured from the same origin the watchdog is. + """ + source = INGEST_PROCESSOR_PATH.read_text() + assert "_PROCESS_START_MONOTONIC = time.monotonic()" in source, ( + "the anchor must be bound at import, matching the span the " + "service's `timeout` wrapper measures" + ) + # Sliced on the next function boundary, not a byte window: a fixed + # window is exactly what this file's _shell_function_body() docstring + # warns about, and a docstring edit already pushed the reference out of + # an 800-byte one. + body = source.split("def conversion_budget_remaining()")[1].split("\ndef ")[0] + assert "_PROCESS_START_MONOTONIC" in body, ( + "the budget must be measured from that anchor" + ) + + def test_timeout_message_does_not_promise_pure_converter_time(self): + """The number in the message is the whole-run budget, so the message + must not read as though the converter got all of it.""" + source = INGEST_PROCESSOR_PATH.read_text() + assert "covers this whole ingest run" in source, ( + "a user told 'could not convert within Ns' will size their timeout " + "against converter time unless the message says otherwise" + ) + + def test_kepubify_also_receives_the_shared_budget(self): + """Both converters must draw on the same allowance; a source-pin here + because the two callsites are what the sharing property depends on.""" + source = INGEST_PROCESSOR_PATH.read_text() + assert source.count("timeout=conversion_budget_remaining()") == 2, ( + "both ebook-convert and kepubify must use the shared budget, not " + "a fresh per-subprocess deadline" + ) + assert "timeout=conversion_deadline_seconds()" not in source, ( + "the raw total must not be handed to a subprocess — that is the " + "per-stage deadline this class exists to prevent" + ) + + +class TestShellDeadlineArithmetic: + """Derivation runs in the real service script, so it is executed here + rather than eyeballed. A flat 30s reserve applied to a small timeout used + to invert the two limits — a 31s timeout left 1s to convert while a 30s + timeout left 23s — a cliff rather than a margin.""" + + @staticmethod + def _derive(safety_timeout): + """Run the real derivation block out of the shipped script.""" + body = _shell_function_body(INGEST_SERVICE_RUN.read_text(), + "run_processor_with_timeout") + lines = body.splitlines() + start = next(i for i, l in enumerate(lines) + if 'safety_timeout" -gt 0' in l) + end = next(i for i in range(start, len(lines)) + if lines[i].strip() == "fi") + block = "\n".join(lines[start:end + 1]).replace("local ", "") + script = f'safety_timeout={safety_timeout}\n{block}\necho "${{CWA_CONVERSION_DEADLINE_SECONDS:-unset}}"' + out = subprocess.run(["bash", "-c", script], capture_output=True, text=True) + assert out.returncode == 0, out.stderr + return out.stdout.strip() + + def test_deadline_is_monotonic_in_the_hard_timeout(self): + previous = -1 + for safety_timeout in (2, 5, 10, 29, 30, 31, 35, 45, 60, 120, 300, 900, 2700): + value = int(self._derive(safety_timeout)) + assert value >= previous, ( + f"raising the hard timeout to {safety_timeout}s SHRANK the " + f"conversion deadline to {value}s (was {previous}s) — a cliff" + ) + previous = value + + @pytest.mark.parametrize("safety_timeout", [30, 31, 45, 60, 120, 900, 2700]) + def test_conversion_always_gets_the_majority_of_the_budget(self, safety_timeout): + """The reserve is for backing up and importing the original; it must + never grow to swallow the conversion window it is protecting.""" + value = int(self._derive(safety_timeout)) + assert value > safety_timeout / 2, ( + f"a {safety_timeout}s timeout left only {value}s to convert" + ) + + @pytest.mark.parametrize("safety_timeout,expected", [(900, 810), (2700, 2430)]) + def test_reachable_timeouts_are_unchanged(self, safety_timeout, expected): + """ingest_timeout_minutes is clamped to 5..120 server-side, so the + shipped range is 900..21600s. Pinning the endpoints of what users + actually run keeps the arithmetic repair from moving live behaviour.""" + assert int(self._derive(safety_timeout)) == expected + + def test_no_hard_limit_means_no_deadline(self): + assert self._derive(0) == "unset" + + +class TestKepubFailureAlwaysReturnsAPair: + """main() unpacks convert_to_kepub() into two names. A path that returned + None raised TypeError, skipped the fallback and dropped the book.""" + + def _kepub_processor(self, tmp_path): + nbp = object.__new__(ingest_processor.NewBookProcessor) + nbp.filepath = str(tmp_path / "Book.epub") + Path(nbp.filepath).write_bytes(b"epub bytes") + nbp.filename = "Book.epub" + nbp.input_format = "epub" + nbp.target_format = "kepub" + nbp.tmp_conversion_dir = str(tmp_path) + os.sep + nbp.calibre_env = os.environ.copy() + nbp.cwa_settings = {"auto_backup_conversions": False} + nbp.backed_up = [] + nbp.backup = lambda f, backup_type: nbp.backed_up.append((f, backup_type)) + return nbp + + @pytest.mark.parametrize( + "exc", + [ + OSError(2, "kepubify missing"), + RuntimeError("something unexpected"), + ValueError("bad argument"), + ], + ) + def test_unexpected_error_returns_false_pair( + self, monkeypatch, tmp_path, exc + ): + monkeypatch.setattr( + subprocess, "run", lambda *a, **k: (_ for _ in ()).throw(exc) + ) + nbp = self._kepub_processor(tmp_path) + result = nbp.convert_to_kepub() + + assert result is not None, "returning None makes main() raise TypeError" + assert result == (False, "") + first, second = result # must be unpackable, as main() does + + def test_non_epub_input_backs_up_the_original_too( + self, monkeypatch, tmp_path + ): + """Backing up only the intermediate left the user's own file nowhere.""" + nbp = self._kepub_processor(tmp_path) + nbp.filepath = str(tmp_path / "Book.mobi") + Path(nbp.filepath).write_bytes(b"mobi bytes") + nbp.filename = "Book.mobi" + nbp.input_format = "mobi" + intermediate = str(tmp_path / "Book.epub") + Path(intermediate).write_bytes(b"epub bytes") + + monkeypatch.setattr( + ingest_processor.NewBookProcessor, + "convert_book", + lambda self, end_format=None: (True, intermediate), + ) + monkeypatch.setattr( + subprocess, + "run", + lambda *a, **k: (_ for _ in ()).throw( + subprocess.CalledProcessError(1, "kepubify") + ), + ) + + assert nbp.convert_to_kepub() == (False, "") + backed = [f for f, kind in nbp.backed_up if kind == "failed"] + assert str(nbp.filepath) in backed, ( + "the original the user dropped in must reach the failed folder" + ) + assert intermediate in backed + + +class TestNotABookFormatsAreNotRescued: + """An .acsm is an Adobe fulfillment ticket, not a book. Rescuing it would + file a junk library entry AND contradict the guidance CWA already prints, + which promises the file went to processed_books/failed (fork #448).""" + + def test_acsm_conversion_failure_does_not_import_the_ticket( + self, monkeypatch, tmp_path + ): + source = tmp_path / "fulfillment.acsm" + source.write_text("") + holder = {} + + def _factory(filepath): + fake = _FakeProcessor(filepath, convert_result=(False, "")) + fake.input_format = "acsm" + holder["fake"] = fake + return fake + + monkeypatch.setattr(ingest_processor, "NewBookProcessor", _factory) + monkeypatch.setattr( + ingest_processor, "_acquire_process_lock_or_exit", lambda: None + ) + assert ingest_processor.main(str(source)) == 0 + assert holder["fake"].imported == [], ( + "an .acsm ticket must not be filed as a book when it fails to convert" + ) + + def test_real_book_formats_are_rescuable(self): + for fmt in ("pdf", "mobi", "azw3", "PDF", "djvu", None, ""): + assert ingest_processor.is_rescuable_on_conversion_failure(fmt) is True + + def test_acsm_is_not_rescuable_any_case(self): + for fmt in ("acsm", "ACSM", "Acsm"): + assert ingest_processor.is_rescuable_on_conversion_failure(fmt) is False + + def test_every_not_a_book_format_explains_itself_to_the_user(self): + """Keeps the two registries in sync: silently declining to import a + file the user dropped is only acceptable if we tell them why.""" + for fmt in ingest_processor._NOT_A_BOOK_FORMATS: + guidance = ingest_processor.conversion_failure_guidance( + fmt, f"x.{fmt}" + ) + assert guidance, f"{fmt} is skipped on failure but explains nothing" + assert "processed_books/failed" in guidance + + +class TestFailedBackupIsDiscoverable: + def test_backup_logs_the_absolute_destination(self, tmp_path, capsys): + """#1094: 'Moving ... to failed backup' named no path the user could find.""" + failed_dir = tmp_path / "processed_books" / "failed" + failed_dir.mkdir(parents=True) + monkey_dest = {"failed": str(failed_dir)} + + source = tmp_path / "Big Handbook.pdf" + source.write_bytes(b"data") + + nbp = object.__new__(ingest_processor.NewBookProcessor) + original = ingest_processor.backup_destinations + try: + ingest_processor.backup_destinations = monkey_dest + nbp.backup(str(source), backup_type="failed") + finally: + ingest_processor.backup_destinations = original + + out = capsys.readouterr().out + assert str(failed_dir) in out, ( + "backup() must name the absolute destination directory so the " + f"user can find the file; got: {out!r}" + ) + assert (failed_dir / "Big Handbook.pdf").exists() + + +class TestIngestServiceTimeoutMessaging: + def test_no_false_internal_timeout_claim(self): + """There is no internal conversion timeout to have 'not fired'.""" + text = INGEST_SERVICE_RUN.read_text() + assert "should have timed out internally" not in text, ( + "ingest_timeout_minutes bounds only is_file_in_use(); claiming the " + "processor has an internal conversion timeout misdirects anyone " + "debugging a slow conversion" + ) + + def test_safety_timeout_names_the_failed_backup_path(self): + text = INGEST_SERVICE_RUN.read_text() + idx = text.find("SAFETY TIMEOUT:") + assert idx != -1 + window = text[idx : idx + 1600] + assert "/config/processed_books/failed" in window, ( + "the safety-timeout branch must tell the user where the file went" + ) + + def test_internal_timeout_only_bounds_file_stability_wait(self): + """Guards the premise of the two assertions above.""" + source = (REPO_ROOT / "scripts/ingest_processor.py").read_text() + # ingest_timeout_minutes must not reach the conversion subprocess. + convert_start = source.find("def convert_book") + convert_end = source.find("def convert_to_kepub") + assert 0 < convert_start < convert_end + assert "ingest_timeout_minutes" not in source[convert_start:convert_end]