Capture Bloom's stacks at the moment page checks fail (BL-16612) by andrew-polk · Pull Request #8141 · BloomBooks/BloomDesktop

andrew-polk · 2026-08-03T20:46:59Z

CI-only. No product code — one script, nothing that can affect Bloom's behavior for users or the behavior of the run it watches.

Why the existing captures can't settle the question

The watchdog from #8114 worked: the 2026-08-03 hang produced three stack captures proving Bloom is hard-deadlocked in OffScreenBrowser.RunAndBlock — 0.72s of CPU across 24 minutes, working set paging 258MB → 16MB. That much is now certain.

But its captures come from 8 minutes in, and by then the evidence can't distinguish anything. The wedged thread holds the API lock (SyncObj), so every later request — and the suite polls constantly — must queue behind it and register as blocked. A fully-consumed worker pool is the inevitable end state of any hang that holds that lock, whatever made the navigation fail. So "all 6 workers were unavailable" is explained by the hang rather than being evidence about its cause. It cannot separate worker starvation from a WebView2/renderer stall.

The moment that does distinguish them

When the navigation gives up — about 26 seconds after Bloom launches, long before the old 8-minute threshold:

what the stacks show at that instant	conclusion
workers all occupied	starvation caused it
workers parked idle in `WaitHandle.WaitAny`	starvation did not; the pool filling up later is just aftermath

So the watchdog now also captures on a trigger: it watches Bloom's log and captures the instant Failed to navigate fully appears, then again a few seconds later (identical stacks prove it is stuck rather than crawling). Polling drops to 5s while Bloom is young so the window isn't missed, and the log's size is recorded as it grows — which both confirms the log is readable and marks when Bloom went quiet.

Why not just sample stacks continuously

dotnet-stack starts an EventPipe session and walks every thread; it isn't free. Doing that every few seconds through startup could itself slow Bloom enough to cause the 10-second navigation timeout we're trying to explain — manufacturing the failure under investigation. The only frequent sampling here is Get-Process, a counter read.

Still dotnet-stack rather than dotnet-dump, for the reason given in #8114: this repo is public and artifacts are widely downloadable, so we must not publish a memory dump of a process holding CI secrets.

Testing

Exercised locally against a real .NET process, driving both paths: the trigger path fires from a log append and produces two captures of genuine per-thread stacks; the hung path still works after the counter rename.

That testing earned its keep — it caught a bug that would have silently produced nothing in CI. PowerShell variable names are case-insensitive, so the counter $triggerCaptures was the parameter $TriggerCaptures; initialising it to 0 turned the limit into 0 and made the capture condition 0 -lt 0, false forever. The counters are now $triggerShotsTaken / $hungShotsTaken so they cannot alias the parameters.

At roughly 1 hang in 3 scheduled runs, this should have an answer within a few nights.

Ref: https://issues.bloomlibrary.org/youtrack/issue/BL-16612

Devin review

This change is

…e if the hypothesis fails) This is the one commit on the branch that rests on a theory rather than on evidence. It is deliberately last so it can be dropped without touching anything else. What it does: RegisterThreadBlocking on its own only makes starvation VISIBLE. The escape hatch in QueueRequest acts on it when the NEXT request arrives, which may be never -- the request that would unblock us (the page the off-screen browser is loading) can already be sitting in the queue with nothing coming in behind it. So RegisterThreadBlockingAndEnsureAFreeWorker does the check at the moment the blocked count goes up, and RunAndBlock uses it. It also logs when it actually has to add a worker: that is the only POSITIVE evidence the starvation condition is real, since every other diagnostic here speaks only after something has gone wrong, and a guard quietly doing its job would otherwise look exactly like a bug that quietly went away. Why it can help at all: the queued requests the browser needs (its in-memory page, CSS, images) are not API requests, so they never touch the API lock the wedged thread holds. A fresh worker can serve them even while the other workers are stuck behind that lock. If they were API requests a new worker would just block too and this would be pointless. Why it is unproven, stated plainly: - The 2026-08-03 stack captures show all six workers unavailable at the wedge, but that is entailed by the hang itself (the wedged thread holds the API lock, so later requests must pile up behind it), so it cannot distinguish starvation-as-cause from starvation-as-aftermath. - Per-publish headroom measurements from three passing runs show the pool never close to exhausted -- 2 idle workers at the tightest, usually 5 of 7 -- and this guard firing zero times across ~36 blocking calls. That is evidence from healthy runs only, so it does not refute the theory, but it does not support it either. - The measurement that would settle it is worker occupancy at the moment the navigation fails, ~26 seconds in. The CI watchdog now captures exactly that (#8141); until a hang is caught with it, this remains a bet. Keep the commits below this one on their own merits. Drop this one if the trigger captures show the workers sitting idle when the navigation fails. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

andrew-polk · 2026-08-03T21:36:35Z

(Claude Opus 5) Consulted Devin on 2026-08-03 up to commit c1b0d4eff6.

Devin ran four times across this branch and found four bugs and two Investigate flags — every one of them real, and all now fixed and resolved. This was an unusually productive review for a 200-line CI script, so it is worth recording what it caught:

The follow-up snapshot landed ~35s late instead of the configured 15s. $interval resets each poll and the early-window rule stops applying once the trigger fires, so nothing kept the loop brisk between the pair. My own testing had missed it because I ran with -PollSeconds 4, masking the reset.
The trigger matched stale log content, including a Failed to navigate fully left by an earlier Bloom launch — which the pre-fix code makes likely, since it logs that line and carries on. Now edge-sensitive.
A momentary read failure collapsed that baseline, because Read-LogText returned "" for both "empty" and "unreadable". Now returns $null for unreadable, and such a poll changes nothing.
The trigger matched a second, unrelated code path — ReportInvalidFontsAsync also logs Failed to navigate fully (PublishHelper.cs:2106). The pattern now includes the DOM name.
The confirming second snapshot could be cancelled entirely, because the capture was gated on the per-poll match rather than the latched fact that the alert fired. Both sites now use the latch.
Plus Find-BloomLog missing its comment, against this repo's commenting rule.

Each fix was verified by driving the script against a real .NET process, including the specific failure scenarios: a log pre-seeded with the alert yields zero captures; a fonts-path line yields zero; a log recreated after the first capture still yields the second.

Devin's final pass re-lists all six titles, but they are stale — it still quotes $triggerMatched at line 257 where the code now reads $triggerSeen. Its results appear cumulative per PR rather than per-commit.

CI green (pr-automation, track). CodeRabbit is disabled for this repo by .coderabbit.yml.

CI-only instrumentation so the next nightly hang tells us its cause. No product code: one PowerShell script under build/ci, purely observational, which cannot change Bloom's behavior for users or the run it watches. The watchdog from #8114 proved the hang is a hard deadlock in OffScreenBrowser.RunAndBlock -- idle, 0.72s of CPU across 24 minutes -- but its captures come from 8 minutes in, and by then they cannot answer the question that matters. The wedged thread holds the API lock, so every later request piles up behind it: a fully-consumed worker pool is the INEVITABLE consequence of any such hang, whatever made the navigation fail. So "all six workers were unavailable" at the wedge is explained by the hang rather than evidence about its cause, and cannot separate worker starvation from a WebView2 stall. The moment that does separate them is when the navigation gives up, about 26 seconds after Bloom launches. If the workers are all occupied right then, starvation caused it; if they are parked idle in WaitHandle.WaitAny, it did not, and the pool filling up afterwards is merely aftermath. So the watchdog now also captures on a trigger: it watches Bloom's log and captures the instant "Failed to navigate fully to RemoveUnwantedContentInternal" appears, then again a few seconds later, since identical stacks prove it is stuck rather than crawling. Polling drops to 5s while Bloom is young so the window is not missed, and the log's size is recorded as it grows -- which both confirms the log is readable and marks when Bloom went quiet. Deliberately NOT sampling stacks continuously: dotnet-stack starts an EventPipe session and walks every thread, so doing that every few seconds through startup could itself cause the 10-second navigation timeout we are trying to explain, manufacturing the failure under investigation. The only frequent sampling is Get-Process, a counter read. And still dotnet-stack rather than dotnet-dump: this repo is public and artifacts are widely downloadable, so we must not publish a memory dump of a process holding CI secrets. Several details exist because testing or review found them the hard way: - The trigger is edge-sensitive. It baselines the log's length when the watch starts and only searches text appended after that, because the pre-fix code logs that same line and carries on -- so a stale line from an earlier launch would otherwise keep the condition permanently true and spend both captures on the wrong moment. It rebaselines if the file shrinks (Bloom recreating it). - Read-LogText returns $null, not "", when the log cannot be read, so a momentary read failure is not mistaken for an empty/recreated log. Conflating them collapsed that baseline. - The pattern includes the DOM name: "Failed to navigate fully" is also logged by ReportInvalidFontsAsync (PublishHelper.cs:2106), a different code path. - Both captures are gated on the LATCHED fact that the alert fired, not on the line still being visible each poll, so a log hiccup cannot cancel the confirming second snapshot. - The loop stays brisk while a capture is owed; otherwise the interval reset each poll put the pair ~35s apart instead of the configured 15. - Brisk polling applies only before Bloom first appears, so a normal run does not bury the samples under hundreds of "no Bloom process running" lines. - Counters are named $triggerShotsTaken/$hungShotsTaken because PowerShell variable names are case-insensitive: $triggerCaptures WAS the parameter $TriggerCaptures, so initialising it to 0 made the capture condition 0 -lt 0 and the watchdog would have silently produced nothing. Verified by driving the script against a real .NET process: the trigger fires from a log append and yields two captures of genuine per-thread stacks; a log pre-seeded with the alert yields none; a fonts-path line yields none; a log recreated after the first capture still yields the second; and with a production-like -PollSeconds 30 the pair lands 6.7s apart. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

github-actions Bot assigned andrew-polk Aug 3, 2026