Stop publishing hanging forever on the page-checks browser (BL-16612) - #8110
Stop publishing hanging forever on the page-checks browser (BL-16612)#8110andrew-polk wants to merge 7 commits into
Conversation
| throw new ApplicationException( | ||
| "Bloom could not determine which parts of this book are visible, so it stopped rather than " | ||
| + "publish a book with the wrong content or missing fonts. See the log for details." | ||
| ); |
There was a problem hiding this comment.
[Devin] Investigate: Behavior change: failed page-checks navigation now fails BloomPUB publishing instead of producing a book
Devin's point: this PR deliberately turns a previously-silent degradation into a hard failure for BloomPUB (before, only epub noticed, via IsDisplayed throwing). It asks that we confirm the BloomPUB entry points surface the new ApplicationException as a friendly error rather than an unhandled crash, since this path was not previously reachable for BloomPUB.
That is the right question to ask of this change, so I traced every path that can now throw.
There was a problem hiding this comment.
(Claude Opus 5) Good question to press on. I traced every path that can now reach this throw. There are exactly two callers of RemoveUnwantedContent — BloomPubMaker.cs:651 (BloomPUB/BloomReader) and EpubMaker.cs:1733 (epub, which already threw here, so it is unchanged) — and BloomPubMaker's creation entry points are reached from:
| path | what happens now |
|---|---|
Publish tab preview (PublishApi.MakeBloompubPreview) |
explicit try/catch → request.Failed(...) + NonFatalProblem.Report — reported to the user |
Save to file / Send to device (PublishToBloomPubApi:388,415) |
no local catch |
Bulk create (BulkBloomPubCreator:121) |
no local catch |
RAB project (RabProjectService:1257) |
no local catch |
CLI (CreateArtifactsCommand, SendFontAnalyticsCommand) |
no local catch — CLI/harvester, fails the command |
No crash risk: the paths without a local catch still land in BloomServer.RequestProcessorLoop's broad catch (Exception error), which logs the message, URL and stack and fails that request. The worker thread survives and Bloom stays up.
But the messaging is thin on those paths. The user gets a failed request and a log entry rather than a friendly explanation — they may just see the operation stop. The exception text is already written in plain English for that reason ("Bloom could not determine which parts of this book are visible, so it stopped rather than publish a book with the wrong content or missing fonts"), but only the preview path actually shows it.
Improving that means touching user-facing error messaging at four call sites, which is past what I should decide alone, so I am leaving this thread open and putting it to the developer. Not a blocker for the fix itself.
There was a problem hiding this comment.
(Claude Opus 5) Andrew's response: wants to discuss whether we want this change at all -- is it belt and suspenders now that the server adds a worker, and it looks high risk.
Both fair. Two honest qualifications, so the discussion has the full picture:
- It is not purely redundant. The guard addresses starvation-caused navigation failures; this refusal can also fire when the WebView2 renderer genuinely dies or wedges for reasons the pool cannot help with, and via the script backstop in the other open thread. So the path is not dead code -- just much rarer than before.
- Against that: if it ever does fire on Save-to-file or Send-to-device, the user currently sees the operation simply stop, with the explanation going only to the log. That is a poor experience and the kind of thing that generates "it did nothing" support reports.
There is also a middle option I did not offer in the report, which changes the risk calculus: instead of wiring the message into four call sites, report once at the throw site via NonFatalProblem.Report, which the preview path already uses. One edit instead of four, covering every path. The wrinkle is that the preview path would then report twice, since its handler reports any exception generically -- so it would need a look, but it is a much smaller change than four separate progress-channel edits.
Leaving open pending that discussion.
|
(Claude Opus 5) Consulted Devin on 2026-07-27 up to commit Devin ran twice — once on
Four informational items from the first pass were acted on anyway (abandoned-task exception, superseded-publish timeout, body reads brought inside the request timeout, and only-timeouts marking Bloom wedged). The second pass's seven needed no action. CI is green ( |
04ccfe0 to
e313457
Compare
|
(Claude Opus 5) Re-split the branch's history (force-push) so the fix and the instrumentation are separate commits, at Andrew's request — it was hard to tell how much of the diff existed only for diagnosis.
Only ~33 lines of shipping product code are instrumentation ( The resulting tree is byte-identical to the pre-split |
200ee6c to
9b9f062
Compare
9e27960 to
831febc
Compare
Every publish (BloomPUB, ePUB, video) first loads the book into an off-screen browser to ask which elements are visible and which fonts are used. Two defects in that step, fixed together because fixing either alone makes things worse: 1. The wait was unbounded. OffScreenBrowser.RunAndBlock ended in tcs.Task.GetAwaiter().GetResult() with no timeout, so a WebView2 that stopped making progress blocked the caller forever. The caller is a BloomServer worker, so the request was never answered and publishing stayed wedged for the life of the process. Every blocking call is now bounded and throws OffScreenBrowserTimeoutException instead. The constructor's _ready.Wait() was unbounded for the same reason and is now bounded too. 2. A failed page-checks navigation silently produced a bad book. The old code logged the failure and carried on (per BL-7892), but with no element information IsDisplayed answers "displayed" for everything and FontsUsed comes back empty -- so a BloomPUB kept content that should have been stripped and embedded none of its fonts. Only ePUB noticed, because IsDisplayed throws for it. Fixing only (1) would therefore have traded a hang for quiet corruption. Page checks now retry once on a fresh renderer and, failing that, fail the publish rather than emit a book we know is wrong. This is the part of the work that rests on proven facts rather than on any theory about the cause. Thread stacks captured from the 2026-08-03 nightly hang show the process hard-deadlocked in RunAndBlock, idle (0.72s of CPU across 24 minutes) rather than slow, after the log recorded exactly the navigation failure described in (2). An unbounded GetAwaiter().GetResult() on a server worker is indefensible on its own terms. Deliberately NOT raising the 10s navigation budget: timings from a passing nightly show that step normally finishing in a small fraction of it, while the failures blew straight through and never completed -- a stall, not a near-miss, so a longer wait would only delay the hang. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
BloomServer counts blocked worker threads so it can add a worker when they are all stuck, but that count is not computed automatically: callers must call RegisterThreadBlocking. OffScreenBrowser never did, so a worker blocked waiting on the off-screen browser was invisible to it. The thread stacks from the 2026-08-03 nightly hang show the blind spot precisely. Six BloomServer.RequestProcessorLoop threads, all six unavailable: five parked on the API lock (which DO register, in BloomApiHandler) and the sixth blocked in OffScreenBrowser.RunAndBlock without registering. So the top-up test evaluated 5 >= 6 and declined to add a worker, while the true state was 6 of 6 unavailable. The one unregistered thread is the one that would have flipped it. Registering is correct regardless of what caused the hang: the count is supposed to mean "workers that cannot take new work", and this thread cannot. That makes it a fix to a documented mechanism rather than a bet on any theory, which is why it is separate from the commit that follows. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
The commits so far make the stall survivable but do not explain it. The leading theory is BloomServer worker starvation: the thread blocking on the off-screen browser is itself a worker, and the browser's navigation needs a worker to serve the page it is loading. That is a hypothesis, not a finding, and the logs we had could not test it -- Bloom's log simply went silent. Worth being precise about what the 2026-08-03 stack captures did and did not settle. They prove a hard deadlock in RunAndBlock. They do NOT support starvation as the cause: the wedged thread holds the API lock, so every later request piles up behind it, which means a fully-consumed pool is the inevitable consequence of any such hang whatever started it. So this adds the measurements that can actually discriminate: - BloomServer.GetWorkerPoolDiagnostics(), a one-line snapshot of workers/busy/blocked/recursive/queued. It reads the counters without taking the queue lock on purpose: it is called precisely when the pool may be wedged, and taking that lock could block the very report we need. - NoteWorkerPoolHeadroom() remembers the tightest moment -- the point where the fewest workers could take new work -- and PublishHelper logs it once per publish, on success as much as on failure. This is the part that makes a HEALTHY run informative: if the pool never drops below a comfortable margin during a normal publish, starvation is not a plausible explanation, and we learn that without having to catch a failure in the act. Measured as idle (workers - busy) rather than merely blocked, because a worker busy serving a long request is just as unable to serve the page we are waiting for. - Page-check failures log that snapshot plus how long the attempt took. Also makes the visual-regression suite diagnosable, which is how this bug was found the hard way. Each request to Bloom is bounded and labelled, so a hang reports which call stopped answering instead of an opaque "test timed out in 120000ms" pointing at the test function. Once Bloom stops answering the remaining cases fail immediately rather than each burning 120s. Only a genuine timeout counts as wedged, so a transient blip cannot mask remaining image diffs, and ordinary diff failures still run every case. No product behavior changes here; it is all reporting, and can be dropped independently of the fix. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This is the fix for the cause, now measured rather than theorised.
Stacks captured at the moment of failure (nightly run 30864382766, at the
instant Bloom logged "Failed to navigate fully to
RemoveUnwantedContentInternal", 2.5 minutes in) show all four BloomServer
workers occupied and NOT ONE idle:
workers in RequestProcessorLoop 4
idle in WaitHandle.WaitAny 0
blocked on the API lock 3 (SemaphoreSlim.Wait in
BloomApiHandler.ProcessRequestAsync)
blocked in OffScreenBrowser 1 (RunAndBlock)
The chain that produces it:
1. The publish endpoint is registered with requiresSync at its default of
true, so the publish holds the API lock for its whole duration -- minutes.
2. MinWorkerThreads is Math.Max(Environment.ProcessorCount, 2) = 4 on these
runners. Three park waiting for that lock; the fourth is the publish.
3. So no worker is left to serve the in-memory page the off-screen
page-checks browser is navigating to, and that navigation cannot complete.
It times out at its 10s budget.
4. Pre-fix, the code logged that and carried on (BL-7892), then blocked
forever in the follow-up RunJavascript.
The escape hatch in QueueRequest -- if (_countBlockedThreads >=
_workers.Count) SpinUpAWorker() -- evaluated 3 >= 4 and declined, because the
three lock-waiters register but the thread blocked in RunAndBlock does not.
Registering it (previous commit) makes that 4 >= 4.
Registering alone is not enough, though, which is why this commit exists.
QueueRequest only evaluates that condition when a NEW request arrives, and the
request we need served may already be sitting in the queue -- with the browser
issuing nothing further, because it is waiting for exactly that page. So
RegisterThreadBlockingAndEnsureAFreeWorker evaluates the same condition at the
moment the blocked count goes up, and RunAndBlock uses it.
Why this is a safe change to the server's core: it introduces no new
mechanism. Same condition, same SpinUpAWorker(), same lock (_queue). It only
adds one more moment at which a rule the server already applies gets
evaluated. Worst case it creates a worker slightly earlier than the existing
path would; it cannot create one the existing rule would not. The pre-existing
property that workers are never retired is unchanged, and growth is still
bounded by the number of simultaneously-blocked threads.
Why adding a worker helps at all: the requests the browser needs -- its
in-memory page, CSS, images -- are not API requests, so they never touch the
lock the publish thread holds. A fresh worker can serve them while the others
stay parked. If they were API requests a new worker would block too and this
would be pointless.
It also logs when it actually has to add a worker. That line appearing in a
passing run's log is positive confirmation that the starvation condition was
real and that this is what kept requests moving -- otherwise a guard quietly
doing its job is indistinguishable from a bug that quietly went away.
Deliberately NOT bundled here, though it is arguably the deeper smell: that a
minutes-long publish serialises all API traffic at all. Freeing those three
workers by revisiting requiresSync for publish endpoints would change a core
concurrency invariant that exists for reasons (see BL-15586 in
BloomApiHandler), so it wants its own investigation rather than riding along
with a fix we can be confident in.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
831febc to
958f5fb
Compare
… count Found reviewing this before handing it back: the guard registered the block and only then took the lock to add a worker, and the caller's finally that unregisters covers the block only AFTER the guard returns. So if SpinUpAWorker threw -- thread creation failing under memory pressure, say -- the exception would escape before that try, _countBlockedThreads would stay permanently incremented, and an inflated count makes the guard fire on essentially every later block. A slow, permanent corruption of the server's own accounting, from a failure that has nothing to do with the caller. Adding a worker is an optimisation: failing to add one must never fail the caller and must never leak the count. So the lock and the spin-up are now inside a try that logs and carries on, which makes the method unable to throw once it has registered, and the register/unregister pairing unconditional. Unlikely to fire in practice. Included because this sits at the lowest level of the server's request handling, where "unlikely" is not the standard. Also updated the comment to say the starvation is established rather than suspected, and to name the run whose moment-of-failure stacks established it. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Three bugs, all real, two of them artifacts of my own commit-splitting surgery. **The guard's documentation had come adrift.** Splitting the branch into purpose-separated commits left the XML doc block for RegisterThreadBlockingAndEnsureAFreeWorker stranded above two unrelated private counters, so the public method was undocumented and the description was attached to the wrong thing. Reattached. **The recovery attempt could escape uncaught.** On a failed page check the code asks the browser for a clean renderer -- but that is the same unresponsive browser, so StartFreshBrowser can itself hit its backstop and throw. Sitting outside the try, that skipped the retry entirely and surfaced a technical timeout instead of the explanation written for users, in exactly the hang this retry exists for. Now caught and logged so the loop reaches its own verdict. **The blocked-count pairing rested on an argument rather than structure.** The previous commit made the guard unable to throw once it had registered, which closes the leak, but the register call still sat outside the try whose finally unregisters. Now it registers inside the try and unregisters only if it got that far, so the pairing holds regardless of what throws. A leaked count would leave the server permanently believing a worker is blocked, so this is worth being structural about rather than reasoned about. Also raised the visual-regression suite's quick-read timeout from 10s to 30s (Devin's flag). A timeout there does not fail one case, it marks Bloom wedged and fails every remaining case -- and switching to the collection tab reloads a webview, which on a loaded machine can genuinely take a while. A spurious abort of the whole suite is much worse than waiting. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
| // stopped making progress altogether. We used to block forever in that case, which wedged the | ||
| // calling thread permanently; when the caller was a BloomServer worker that wedged publishing with | ||
| // it, and the process never recovered (BL-16612). | ||
| private const int kDefaultBlockTimeoutMs = 30000; |
There was a problem hiding this comment.
[Devin] Investigate: RunJavascript page-checks backstop is a fixed 30s regardless of book size
The backstop that bounds a script run is a constant 30 seconds, but the page-checks script walks every element carrying an id across the whole DOM. On a large enough book that work is not obviously bounded by 30s, and exceeding it now fails the publish rather than degrading it.
There was a problem hiding this comment.
(Claude Opus 5) Andrew's response: needs discussion, and 30s is certainly too low. So no change yet -- leaving this open rather than picking a number.
Recording the shape of the discussion for whoever picks this up: the value is doing two different jobs. A work budget should scale with the book, since the script walks every element carrying an id; a liveness detector should be generous and fixed. It is currently being used as the latter while sized like the former.
The useful asymmetry is that bounding the wait at all is what fixed the disaster case. Now that it can never wait forever, the exact number only trades a spurious refusal against a slower failure -- and a spurious refusal is far worse. That argues for raising it substantially rather than tuning it finely.
Our only timing evidence is from the visual-regression books, which are tiny, so it says nothing about the large-book case. Logging how long page checks take on SUCCESS (we currently only log it on failure) would give a real distribution from the nightly and from user logs, and let the number be set from data.
|
(Claude Opus 5) Consulted Devin on 2026-08-04 up to commit Three passes this run. Every finding was real — no false positives — and two of the three bugs were artifacts of my own commit-splitting surgery rather than the design:
Three flags are deliberately left open for Andrew, all judgement calls rather than defects:
Devin's final pass re-lists the three fixed bugs, but they are stale — I verified each fix is present at CI green. CodeRabbit is disabled for this repo by |
Andrew's call on the preflight question: leave it in English and record the reason, which is what .github/skills/xlf-strings asks for when a string is deliberately not localized. The reasoning, now in the code: reaching this throw means the off-screen browser failed twice in a row, so it is a fault condition rather than a normal outcome, and the skill's guidance is that such strings stay in English. Keeping the wording identical to the log entry just above it is also what lets a user's description of the problem match what we read in their log. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2 participants
Found while investigating repeated Nightly Build and Test failures where all 12 visual-regression cases timed out (~24 minutes wasted). The hang is in publishing, not in the tests. Bloom's log ended at the same point in every failing run:
and then went silent for 23 minutes. Three consecutive nightlies ran the same commit
e2a5d45e62with results fail / pass / fail, so it is a flake rather than a regression.Two defects, which have to be fixed together
1.
OffScreenBrowser.RunAndBlockwaited with no timeout. When the page-checks navigation failed,PublishHelpercarried on (per the BL-7892 comment) and calledRunJavascripton a browser whose page had never loaded — and that never returned. The blocked thread is a BloomServer worker, so the request was never answered and publishing stayed wedged for the life of the process. Every blocking call is now bounded and throwsOffScreenBrowserTimeoutExceptioninstead of waiting forever. The unbounded_ready.Wait()in the constructor is bounded for the same reason.2. Carrying on after a failed navigation silently produced a bad book. With no element information,
IsDisplayedanswers "displayed" for everything andFontsUsedcomes back empty, so a BloomPUB keeps content that should have been stripped and embeds none of its fonts. Only epub publishing noticed, becauseIsDisplayedthrows for it. So merely adding the timeout from (1) would have converted the hang into quiet corruption — which is why both land together. Page checks now retry once on a fresh renderer and, failing that, fail the publish (the existing handler reports it) rather than emit a book we know is wrong.Why the navigation stalls is still unproven
The leading hypothesis is BloomServer worker starvation: the thread blocking on the browser is itself a worker, and the browser's navigation needs a worker to serve the page it is loading.
_countBlockedThreadsis not computed automatically — callers must register — andOffScreenBrowsernever did, so a worker blocked there was invisible to the logic inQueueRequestthat adds a worker when all of them are blocked.RunAndBlocknow registers, which should break that cycle if it is the cause.Deliberately not raised: the 10s navigation budget. Per-test durations from the passing run show the entire first case (tab switches, book select, branding, theme, preview screenshot, full BloomPUB staging, several player captures) taking 18.4s, so that navigation normally finishes in a small fraction of 10s. The failures blew through 10s and then never completed — bimodal, i.e. a stall rather than a near-miss, so a longer wait is not the fix. Added
BloomServer.GetWorkerPoolDiagnostics()and log it, with the elapsed time, whenever page checks fail, so the next occurrence tells us whether the pool was starved.Test-side
The visual-regression suite now bounds each request to Bloom and names the call that hung, instead of an opaque "test timed out" pointing at the test function — which was all the original failure gave us to go on. Once Bloom stops answering, the remaining cases fail immediately rather than each burning 120s. Ordinary image-diff failures still run every case, so we keep every diff.
Testing
OffScreenBrowserTests.RunJavascript_WhenTheBrowserDoesNotComeBackInTime_ThrowsRatherThanBlockingForeverproves the backstop fires (it gives up at 500ms rather than waiting out a 5s script) andGetWorkerPoolDiagnostics_WithAServerRunning_ReportsWorkerCountscovers the new diagnostics. Both pass, with the existing test as a sanity check.node-fetchhonorsAbortSignal.timeout— and that it reportsAbortError, notTimeoutError, which is why the new code checkssignal.abortedrather than the error name.BloomTests.Publish(which drivesRemoveUnwantedContent) cannot run in a worktree without a builtoutput/browser: it aborts on aDebug.Failfor a missingfavicon.ico. Confirmed identical on pristine code (163 vs 164 failures, same abort point), so this PR's CI run is the real check on those suites.Ref: https://issues.bloomlibrary.org/youtrack/issue/BL-16612
Devin review
This change is