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 4 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.
|
(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 |
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, which have to be fixed together: 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. Part of the hang was that BloomServer could not see the problem: _countBlockedThreads is not computed automatically — callers must register — and OffScreenBrowser never did, so a worker blocked there was invisible to the logic that adds a worker when all of them are blocked. Registering alone is not enough either, because that logic only runs when the NEXT request arrives, which may be never: the request that would unblock us (the page the browser is loading) can already be sitting in the queue. So RegisterThreadBlockingAndEnsureAFreeWorker() does the check at the moment the blocked count goes up. The plain RegisterThreadBlocking is left alone so existing callers keep their current behavior. Deliberately NOT raising the 10s navigation budget: timings from the last 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>
The previous commit makes the stall survivable but does not explain it. The leading hypothesis 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 tell us — Bloom's log simply went silent for 23 minutes. So this adds only what is needed to settle it next time: - BloomServer.GetWorkerPoolDiagnostics(), a one-line snapshot of workers/busy/blocked/recursive/queued. If every worker is busy or blocked while requests sit in the queue, the page the browser is waiting for cannot be served and it is starvation rather than slowness. 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. - Page-check failures log that snapshot plus how long the attempt took, so a future failure says which of the two it was. - The backstop timeout message carries the same snapshot. 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 — all we had to go on originally. Once Bloom stops answering, the remaining cases fail immediately rather than each burning the full 120s (12 x 120s was the 24 wasted minutes). Only a genuine timeout counts as wedged, so a transient blip cannot mask the remaining image diffs, and ordinary image-diff failures still run every case so we keep every diff. None of this changes product behavior; it is all reporting. It can be dropped or reverted independently of the fix in the previous commit. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
The first green nightly on this branch was uninformative, and that is a flaw in the instrumentation rather than good news. None of the diagnostics fired at all: the page-checks navigation succeeded first try, so the retry never ran, the backstop never ran, and no worker-pool snapshot was logged. With 2 of the 4 scheduled nightlies having failed this way, a single pass would happen about half the time even with no fix, so it was worth roughly 2:1 as evidence — and it said nothing about the starvation hypothesis. The underlying problem: every diagnostic added so far speaks only AFTER something has gone wrong. If the free-worker guard is quietly doing its job, that looks exactly like a bug that quietly went away, so the root cause could stay unproven forever. So RegisterThreadBlockingAndEnsureAFreeWorker now logs when it actually has to add a worker, with the pool snapshot. That is POSITIVE evidence: if it appears in a passing run's log, the starvation condition was real and this is what kept requests moving. Logged outside the queue lock so we never hold it while writing a file. This commit originally also made the nightly collect and upload Bloom's log on success rather than only on failure, which is what let any of this be read on a green run. That half has since landed on master separately (#8114, together with the hung-Bloom stack-capture watchdog), so the rebase drops it from here. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…vidence The second green nightly showed the free-worker guard firing zero times across ~24 blocking calls (12 BloomPUB stagings, each doing a navigate and a script). That is useful, but it only tells us the pool never hit absolute exhaustion; it does not say whether it came anywhere near. If the pool routinely sits at 3 of 4 workers free, worker starvation is not a plausible explanation for the hang and we should stop pursuing it; if it regularly drops to 1, it is very plausible. We currently cannot tell, because everything we log fires only once something has already failed. So BloomServer now remembers the snapshot from the tightest moment — the point where the fewest workers were able to take new work — and PublishHelper logs it once per publish, on success as much as on failure. One line per publish, no product behavior change. Measuring idle (workers - busy) rather than merely blocked: a worker busy serving a long request is just as unable to pick up the page the off-screen browser is waiting for as a blocked one, and it is that page not being served that the starvation theory is about. The window is bounded by PublishHelper's lifetime, which is exactly one publish for both callers (BloomPubMaker wraps one in a using; EpubMaker keeps one for the whole epub), so the line describes that publish and not the accumulated session. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
200ee6c to
9b9f062
Compare
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