Import the original book when its conversion fails (#1094)

[new-usemame]

Why

@auspex dropped a 63MB PDF into the ingest folder (#1094). It was picked up, spent 45 minutes in ebook-convert, got killed by the service safety timeout — and then simply was not in the library. No entry, and the file gone from the ingest folder. Their words: "There's no reason that any output conversion must be successful, but the input file should always be ingested regardless of any conversion problem."

Root cause

main() in scripts/ingest_processor.py imported the book only inside if convert_successful: and had no else. Any conversion failure returned without ever calling add_book_to_library(), while the finally block's delete_current_file() removed the source from ingest. The service then logged Successfully processed.

This is not timeout-specific — it hit every conversion failure: a corrupt source, unsupported internals, a format needing an input plugin the user doesn't have. That is the widest part of the blast radius, and none of it was visible to the user.

The inconsistency is the tell: the two sibling branches that decline to convert (auto_convert off, or the format in auto_convert_ignored_formats) both import the original already. Confirmed live — the same unconvertible PDF imports fine with auto-convert off and is lost with it on.

Fix

An elif conversion_attempted and is_rescuable_on_conversion_failure(...) branch imports the original.

Correction to an earlier version of this description. It claimed the reporter's timeout case was covered by that branch. It wasn't. The service runs the processor under timeout "$safety_timeout" (run:245) and nothing inside the processor bounded conversion, so an overrun arrived as a SIGTERM and main() never regained control to reach the fallback. Their log shows CON_ERROR ... EXIT/ERROR CODE: -15 one second before the shell's SAFETY TIMEOUT — that is timeout(1) signalling the process group, and whether Python survives long enough to import is a race it loses. The cross-family review caught the overclaim; d24365a3c fixes the underlying gap by giving conversion its own deadline just inside the hard one, derived from the same safety_timeout so the two can't drift. Full disposition of all six findings is in the review comment below.

The guard flag is load-bearing, not decoration. The ignore-list branch reports convert_successful = False having already imported the original, so a bare else would have filed every deliberately-unconverted book twice — worse than the bug being fixed. I hit that in the blast-radius pass before pushing; it is pinned by test_ignored_format_is_imported_exactly_once.

Two smaller items from the same report:

• backup() now logs its absolute destination, and the safety-timeout branch names /config/processed_books/failed/<file>. The reporter: "I've got no idea where 'failed backup' is!"
• The service no longer claims the processor "should have timed out internally at 900 seconds". ingest_timeout_minutes is read only by is_file_in_use() (ingest_processor.py:1169, :1811) — there is no internal conversion timeout at all, so that line sent anyone debugging a slow conversion looking for a limit that does not exist. It now points at the setting that does govern it.

Reproduction and validation

Red/green, mutation-verified. 8 tests in tests/unit/test_1094_failed_conversion_imports_original.py driving the real main() control flow over a fake processor.

Against pristine main: 4 failed — including the reported symptom, add_book_to_library calls were []. After the fix: 8 passed. Stubbing the new branch back out (elif False:) re-reds exactly the two fallback tests, so they are falsifiable rather than vacuous.

The suite includes an anti-vacuity test (a successful conversion must still import the converted file) and a premise guard (ingest_timeout_minutes must not appear inside convert_book), so the timeout assertions can't silently outlive their reason.

Live verification (cwn-local, mirroring the reporter's config)

auto_convert=1, target epub — the out-of-box path, not this container's prior state.

	pre-fix	post-fix
Unconvertible PDF	CON_ERROR → Successfully processed, books 42 (lost)	imports, books 42 → 43
Imported book usable	—	/book/205 200, /api/v1/books/205 200, PDF format attached
Failed-backup path in log	to failed backup	to /config/processed_books/failed

Cross-cutting re-checks after the fix:

• Happy path — a convertible .txt still converts (END_CON in 1.46s), imports one row, format EPUB, fallback silent.
• Ignore-list path — pdf in auto_convert_ignored_formats: exactly one row, no conversion attempted, fallback silent.
• Log scan since deploy: the only errors are ebook-convert's own complaints about the deliberately-corrupt PDF. None from our code.

Test artifacts removed and the container's settings restored (42 books, auto_convert=0).

Suite

Full unit + smoke: 3 failed / 4206 passed. All 3 fail identically on pristine main (verified by stashing this change) — test_802_metadata_change_dispatch, test_ingest_batch_dirty, test_smoke::test_required_directories_exist. Zero regressions.

Scope left out, deliberately

The reporter's item 5 — make the conversion timeout proportional to page count rather than a flat 15 minutes — is a real ask and a separate change with its own design question (what the scaling factor should be, and where the ceiling goes). Filing it as a credited child issue rather than stretching this one. Their items 1 and 3 they withdrew themselves after testing: the doubled DeDRM log is calibre's ebook-convert, reproducible outside CWA, and the file does have a text layer.

Addresses #1094.

Tier: fork-original behaviour change. No dependency, license, route or external URL change (rule 6 clear). Not auth/session/CSRF/crypto/subprocess-input/path-handling, so /security-review is not triggered.

[new-usemame]

Cross-family review disposition (Terra, thread 019f9eda)

Verdict on the first push was DO-NOT-SHIP, and it was right. Three of the findings were real and two of them are the difference between fixing @auspex's bug and fixing a neighbour of it. All dispositioned below; the two follow-up commits are 1c5bf794b and d24365a3c.

1 — HIGH, the reported case never reached the fallback. FIXED.
The service runs the processor under timeout "$safety_timeout" (run:245) and nothing inside the processor bounded conversion, so an overrun arrived as a SIGTERM and main() never regained control. My original PR body claimed this case was covered. It wasn't — that was an overclaim and the reviewer caught it.

The reporter's own log is the evidence either way: CON_ERROR ... EXIT/ERROR CODE: -15 lands one second before the shell's SAFETY TIMEOUT, which is timeout(1) signalling the process group. Whether Python survives long enough to print is a race; whether it survives long enough to import is a race it loses.

Fix: the converter now runs under subprocess.run(timeout=...), read from CWA_CONVERSION_DEADLINE_SECONDS, which the s6 script derives from the same safety_timeout it enforces — one source of truth, so the two limits can't drift. ~10% margin, proportional fallback where a flat floor would leave no headroom, and unset entirely when timeout 0 means no hard limit. Verified live: 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.

2 — HIGH, .acsm would be rescued as a book. Already fixed, mid-review.
The reviewer flagged this against the diff I supplied and noted it saw a later local fix not in that diff — correct on both counts; I'd found the same contradiction independently while it was running. _NOT_A_BOOK_FORMATS + is_rescuable_on_conversion_failure(), and a test pins that every format on that list also has guidance explaining why it was declined. The shipped ACSM guidance promises the file went to processed_books/failed, so that promise now stays true. Verified live: ticket not filed, guidance printed, path named.

3 — HIGH, kepub's generic except returned None. FIXED.
Confirmed by reading: it printed and fell through. main() unpacks that call, so it raised TypeError, skipped the fallback and dropped the book — the exact failure this issue is about, by a different route. Every non-success path now returns a pair, and convert_book() no longer lets an OSError escape either. Parametrised over OSError / RuntimeError / ValueError, asserting the result is unpackable as main() does it.

4 — MEDIUM, failed folder held the intermediate, not the source. FIXED.
Correct, and the reviewer was careful to say it could not confirm the intermediate gets imported — it doesn't; finally removes that directory and the fallback passes filepath. The real defect was recovery: for a non-epub input the failed folder never held the file the user dropped in. Now keeps both, which are distinguishable by extension.

5 — HIGH, automerge=overwrite could replace a good existing format. DECLINED, tracked.
Real, but pre-existing and not introduced here: the same unconditional add_book_to_library(filepath) already runs on the auto-convert-off and ignore-list branches, both reachable today. The default is new_record (cwa_schema.sql:46, confirmed on the live instance), so the destructive path needs a non-default setting. Folding a policy change for a pre-existing hazard into a data-loss fix would widen the blast radius of the thing meant to reduce it. Filed as #1159.

6, 7 — LOW, no defect found. The reviewer explicitly could not confirm a double-import on the normal return paths or an orphaned-calibredb race, and said so rather than padding. Recorded as agreed.

Where this leaves confidence

27 tests, mutation-verified. Live evidence for all four behaviours that changed: the clean-failure rescue (42→43, /book/205 200 with PDF attached), the deadline overrun (imports as TXT), the happy path (converts, one EPUB row, fallback silent), and the two declines (ignore-list once; .acsm not at all). Container restored to 42 books with settings as found.

Not claimed: I have not reproduced the reporter's specific 63MB file. The mechanism is verified with a forced deadline rather than a 45-minute conversion, and the fix is general to any overrun.

[new-usemame]

Second review round (Terra, same thread 019f9eda)

Re-reviewing the two follow-up commits returned NOT-FIXED, and it was right again. The commit that was supposed to close the timeout gap had a hole in one of its own paths.

1 — HIGH, the deadline was per-subprocess, not per-run. FIXED in 3c6659096.

conversion_deadline_seconds() was read fresh at each subprocess.run(). A kepub ingest of a non-EPUB converts twice back to back — original to epub, then epub to kepub — inside one hard timeout. Each stage was granted the full deadline, so the two could add up to more than the watchdog they were meant to sit inside, leaving the second conversion running when SIGTERM arrived. That is this issue's own failure, reachable at the default timeout: at S=2700/D=2430, stage one can burn 2429s and stage two starts with a fresh 2430s budget against 271s of real time.

The budget is now one allowance anchored to process start, which is the span the service's timeout is actually measuring. Each stage draws on what is left. An exhausted budget returns a small positive value rather than zero or a negative, so it expires as an ordinary TimeoutExpired the failure handler already turns into an import of the original, instead of a ValueError escaping the handlers.

2 — MED, the shell reserve had a cliff. FIXED.

A flat 30s floor applied to a small timeout inverted the two limits: a 31s timeout left 1s to convert while a 30s timeout left 23s. The reserve is now capped at a fifth of the budget, making the deadline monotonic in the timeout. ingest_timeout_minutes is clamped to 5..120 server-side so the shipped range (900..21600s) never reached the cliff — this is defence in depth, and the 900s and 2700s endpoints are unchanged and pinned by tests.

3 — MED, inf crashed before the fallback. FIXED.

float("inf") parses cleanly and fails at int() with OverflowError, which is neither TypeError nor ValueError. Uncaught, it escaped while evaluating the timeout= argument — before subprocess.run() was called and outside the handlers that import the original. Now caught. /security-review independently flagged the same line as a non-security note.

4 — Converter child processes can outlive the deadline. NOT fixed here, filed as #1161.

subprocess.run(timeout=) kills and reaps the direct child, so the fallback control flow is sound, but it signals one process rather than a group and calibre helpers can linger. The obvious fix has a real trade-off: start_new_session=True takes the converter out of the outer timeout's group, so the last-resort watchdog would no longer reach it. That needs its own lifecycle and signal-handling design, and it is resource cleanup rather than the data-loss path. Split rather than stretched; the reviewer agreed the split is defensible.

Deliberate trade-off, now documented. Anchoring at process start means the wait for a file to finish copying in is deducted from the conversion budget, so a late-ready file gets less time to convert. That is the correct direction — the outer watchdog starts at process launch too, so anchoring anywhere later lets the inner deadline outrun it, which is how the book gets lost. Under-granting costs a conversion; over-granting costs the book. 5e45719b6 makes the timeout message say what the budget covers, so nobody sizes their Ingest Timeout against the wrong number, and two tests pin the policy.

Also filed: #1163 — a failure after a successful conversion (DB bookkeeping) still unwinds without importing either file. Different cause, same user-visible symptom; outside this PR's contract.

Validation

15 tests added (49 in the module). Every fix mutation-verified: stubbing out the shared budget, the OverflowError catch, the margin cap, or the import-time anchor each re-reds its own test, so none are vacuous. Full suite 2 failed / 4246 passed; both failures reproduce identically on pristine main (0e423fb04).

Live in cwn-local (container Python 3.13.14), real processor over the real ingest path:

Case	Result
309MB .txt, 1s budget	deadline fires, backed up to /config/processed_books/failed, imports the original as TXT (42 → 43 books)
short .txt, 600s budget	converts, imports EPUB
short .txt, no budget set	converts, imports EPUB

The last two are the anti-vacuity control: the fallback fires when conversion fails and not otherwise. Budget sharing confirmed on the deployed module (600s → 200s after 400s elapsed), exhausted budget returns 0.1 not a negative, and inf/1e309/banana all degrade to no-deadline. Test books removed and auto_convert restored.