Publish health signals so a Freeze Doctor can diagnose freezes, crashes and zombies (BL-16719) - #8218
Publish health signals so a Freeze Doctor can diagnose freezes, crashes and zombies (BL-16719)#8218JohnThomson wants to merge 13 commits into
Conversation
Bloom now publishes just enough about its own health for the Freeze Doctor (github.com/BloomBooks/bloom-freeze-doctor) to tell a frozen Bloom from a busy one, and a crash from an orderly shutdown. WHY BLOOM HAS TO HELP AT ALL. Watching from outside cannot detect the freeze we should most expect. A UI thread blocked in a managed wait on an STA thread - WaitHandle.WaitOne, Task.Wait, anything ending in CoWaitForMultipleHandles - keeps dispatching SENT messages so that COM still works. The window therefore answers SendMessageTimeout, IsHungAppWindow reports it healthy, and Process.Responding returns true, while Bloom is completely stuck. That was measured, not assumed, and confirmed again here: with this change in place a deliberately frozen Bloom reported Responding=true for nine minutes while its UI thread sat in Monitor.ObjWait. WM_TIMER is NOT dispatched by those restricted pumps, so a WinForms timer that stops ticking is the one signal that gives the freeze away. Since Bloom's UI thread awaits WebView2 constantly, this shape of freeze is likely common rather than exotic. What is published, through a memory-mapped page the Doctor can read without Bloom's cooperation: a UI-thread heartbeat; a separate background-thread heartbeat, so "the UI thread is blocked" can be told from "the whole process is wedged"; what Bloom says it is doing; how far shutdown has got; whether a debugger is attached, which is authoritative and is why a developer stopping their debugger never produces a report; and a clean-exit proof written from ProcessExit. ProcessExit is deliberately the whole of the clean-exit mechanism rather than an edit to each exit path: it runs for a normal return from Main and for Environment.Exit, and NOT for FailFast, TerminateProcess or an access violation. That is exactly the line the Doctor wants drawn, and no future exit path in Program.cs can forget to honour it. Shared memory rather than a pipe, a socket, or Bloom's own web server, because the Doctor has to read this while Bloom is wedged. A request/response channel needs Bloom well enough to answer, which is precisely what we cannot assume - and a deadlocked or worker-starved BloomServer is itself one of the failures being hunted. The code lives by three rules, because it runs on the UI thread and in a shutdown path that has historically been fragile: it must never throw, never block, and never matter. Every entry point swallows its own failures, and if the channel cannot be created Bloom carries on exactly as before while the Doctor falls back to watching from outside, as it must for every Bloom already in the field. DoctorChannel.cs is a copy of a file in the Doctor's repository, identical apart from its namespace, so that the two sides cannot implement one format two ways. DoctorChannelContractTests pins the schema version, page size and name format BY VALUE, and the Doctor's repository pins the same numbers: if the copies ever drift, nothing would fail loudly - Bloom would write one set of offsets while the Doctor read another and produce reports full of plausible nonsense - so a layout change is meant to break two builds in two repositories. Also adds FreezeSimulator, which breaks Bloom on purpose so the Doctor's detection can be tested against a real Bloom rather than only a stand-in. It is inert unless BLOOM_SIMULATE_FREEZE is set AND this is a developer channel, so there is no menu item, endpoint or keystroke that could set it off on a user's machine. A test asserts it stays inert on Release and Beta. Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
…Doctor (BL-16719) Completes Bloom's side of the Freeze Doctor work, verified end to end: a Bloom launched from a build tree started the Doctor itself one second later, wrote its session file, froze in the way that cannot be seen from outside, and the Doctor produced a full report - which it then declined to file, because this was a developer build. That last part matters as much as the rest: the Doctor had been handed the real BL project and still kept our own work off the tracker. THE SESSION FILE removes guesses the Doctor would otherwise have to make from outside, and this run demonstrated why that is worth doing. Bloom recorded its log as Log-tmplo0jmp.txt - the fallback name it uses only when it cannot create Log.txt - so anything inferring "the newest Log*.txt" would have attached a different run's log to the report. It also carries the ports (Bloom's own HTTP port cannot be discovered from outside at all, because http.sys owns it), the version, channel, and collection. It is written to disk rather than shared memory because it has to outlive the process: a Bloom that crashes while no Doctor is watching must still leave something for a Doctor installed tomorrow to read. An unexplained session file is kept for a week for exactly that reason, while one recording a clean exit is pruned as soon as the process is gone. THE IN-FLIGHT API TABLE is the item most likely to answer BL-16697 outright. A stack trace says the UI thread is waiting; this says which request has been running for 47 seconds, which is usually the whole answer. It is instrumented at the inner dispatch rather than the outer one, because that is where the work and the waiting on the sync locks actually happen, so that is where a hung request sits. It sits in the hot path, so it is written to be unable to hurt: one concurrent-dictionary insert and one removal per request, no locks, nothing that can throw, and a using scope so an exception cannot leave a phantom entry making a healthy Bloom look stuck. The summary is computed on the watchdog thread rather than per request, and published through the existing activity field, so no change to the shared layout was needed. BloomServer gains a BusyWorkerCount to sit beside the BlockedWorkerCount the tests already used. Read without the lock deliberately: this is only ever used for diagnostics, where a value one tick out of date is worth far more than a diagnostic that can block on the very lock a frozen server is fighting over. AUTO-LAUNCH, because a diagnostic tool is no use unless it is already running when the trouble starts, and nobody launches one in advance. There is deliberately no handshake: Bloom's only job is to make sure a Doctor is running, and a second Doctor hands off to the first and exits, so Bloom never has to know which case it is in. Nothing waits for it, checks on it, or is affected by whether it worked. It costs one directory check on a machine without the Doctor installed, which is every machine today, and BLOOM_NO_FREEZE_DOCTOR turns it off. ProblemReportApi now records when Bloom has successfully reported a problem itself, and the Doctor reads that and stays quiet - a user filing a report by hand and a Doctor noticing the same trouble being precisely the situation that would otherwise produce two cards about one problem. Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
…L-16719) Bloom's watchdog thread now waits on a named event the Doctor sets when it has decided Bloom's UI is gone and the process is in the user's way. Bloom exits itself rather than being killed, which is worth the round trip: ProcessExit runs, so the single-instance token is released properly and Bloom's own record of the shutdown is written. Bloom also asks a watching Doctor to dump it on the way down, from its two outermost crash handlers and from AppDomain.UnhandledException - the last of those because the handlers only catch TargetInvocationException and AccessViolationException from the message loop, whereas an unhandled exception can arrive on any thread. It checks with a zero timeout whether a Doctor is actually watching before it agrees to wait for anything, because nearly every user has no Doctor installed and an unconditional pause would make every crash worse for them. Adds a crashthread case to the freeze simulator: a direct FailFast runs no managed handlers by design, so it cannot be used to exercise the dump handshake, and an exception on the UI thread is caught by Bloom's own error reporting. An exception on a plain background thread is the one fatal path available for testing.
Two findings from reviewing this branch's own diff. Environment.Exit runs the ProcessExit handler, so a Bloom that exits because the Freeze Doctor asked it to was writing the clean-exit proof on its way out - which is the opposite of the truth about a process we had to end, and exactly the conclusion that proof exists to stop anyone drawing. It now marks the exit as forced before exiting, and the handler only claims a clean shutdown when it was one. Pruning old session files was also happening on the UI thread during startup. Enumerating and deleting a directory of files has no business on Bloom's startup path, so the watchdog thread does it on its first beat instead.
…6719) Five real findings, all in this branch's own new code. The publishing seqlock was broken. Two threads publish - the UI-thread timer and the watchdog - and the sequence counter was incremented non-atomically, so a lost update could leave it resting on an odd value, which every reader treats as 'a write is in progress' and gives up on for ever. That would have silently disabled the whole channel for the rest of the run, which is the one failure mode this feature cannot afford. The write is now serialised on a private lock, and the sequence is always left even even if the update throws, so one failed write can no longer disable the channel permanently. The activity field was only ever written while something interesting was running and never cleared, so it kept naming a request that had finished minutes earlier - a freeze report blaming work that had already completed, which is worse than no lead at all. The 'Bloom already reported this problem' note was being written inside the exit record, so a user who filed a report and carried on working left a live Bloom described on disk as finished. A reader takes that as proof of an orderly shutdown, for a process that may still go on to crash. The note now lives on the session itself, where it says what it means, and the real exit is always recorded. An exit forced by the Doctor is marked as such, so ending a zombie is not later mistaken for a clean shutdown either. Session updates from two threads could lose that same note: the watchdog rewrites the record every ten seconds by read-modify-write, and a refresh that read before the note was applied would discard it. All mutations now compose on the current value under one lock. Bloom also skipped installing the clean-exit hook when the shared page could not be created, which left the session file claiming for ever that the run never shut down properly - manufacturing exactly the false positive the proof exists to prevent. The hook is now installed before anything can return early. Also from the informational findings: UTF-8-safe truncation of the activity string (with a regression test, because the first attempt at it read past the end of the array and demonstrated the odd-sequence trap above), a static reference so the simulator's countdown timer cannot be collected before it fires, a note about pid reuse in the session file, and two corrected comments.
…(BL-16719) Devin's re-review caught a regression I introduced in the previous round, plus a false negative that had been there all along. THE REGRESSION. Fixing 'the activity field never gets cleared' by writing it every second made the public SetActivity entry point useless: anything Bloom's own code said it was doing survived less than a second, so a Bloom that wedged during startup published 'no request in flight' instead of 'starting up' - wrong, and the least helpful thing it could have said. The watchdog now composes the two sources rather than letting either clobber the other, and SetActivity remembers what it was told so the composition has something to work with. THE FALSE NEGATIVE. RecordCleanExit is wired to ProcessExit, which fires for every Environment.Exit - including Bloom's hard failures, such as WebView2 failing to initialise and the non-message-loop branch of the fatal exception handler. Those runs were being recorded as orderly shutdowns, so a Bloom that died because its browser would not start would have been passed over in silence by the very tool built to notice it. The test is now whether the shutdown sequence actually ran: Program.Run's phase markers are only reached on the orderly path, so a phase of zero means it was not walked. That needs no cooperation from each exit site, which matters because the next hard-failure exit somebody adds is then covered without anyone remembering to think about it. Also from the informational findings: the initial session write now takes the same lock as every other mutation (nothing can race it today, but a rule with an exception is a rule someone follows into a bug later), and pruning no longer treats a forced exit as explained - a forced exit is not an explanation, it is the evidence.
|
[Claude Opus 5 from Thomson's machine during preflight] Consulted Devin on 2026-08-19 16:43 up to commit Three rounds. The first found 4 bugs and 1 Investigate flag, all genuine and all in this branch's new code; the second found 1 new bug (a regression I introduced fixing one of the first four) and 1 new Investigate flag. Every one of those six has its own thread above with a reply saying what changed, and is resolved. Also acted on five of the informational items (UTF-8-safe truncation, a timer that could be collected before firing, the initial session write taking its own lock, pruning no longer discarding forced-exit evidence, and two wrong comments). One thing worth knowing for anyone reading the review page: on the second and third rounds Devin re-emitted its earlier findings verbatim rather than re-checking them. Each was verified against the analysed commit and is fixed — the clearest case quotes CI ( |
The simulator's channel gate allowed only developer builds. That excluded the one population where deliberately reproducing a freeze is most useful: reproducing a freeze usually means working alongside somebody who is actually experiencing it, and those people run Alpha, not a build from source. As written, the tool was available only on the machines where we can least often reproduce the problem. So the gate is now "developer or Alpha", pulled out into a named predicate with the reasoning beside it. Beta and Release stay excluded, and the internal channels are deliberately not listed - add them there if that proves inconvenient, rather than loosening the test. ArmIfRequested now returns whether it armed, so a test can tell "armed" from "declined" without waiting for Bloom to actually break, and Disarm() cancels a pending simulation so an armed timer cannot be left behind as a booby trap for whichever later test happens to pump messages. Tests: the existing Release/Beta test now asserts the return value rather than merely that nothing threw; two new tests pin that Alpha and developer channels do arm, and that the channel is a gate rather than a trigger - no environment variable means no simulation even on Alpha.
There was a problem hiding this comment.
Your trial has ended. Reactivate Greptile to resume code reviews.
An earlier fix made the watchdog compose the activity string from what Bloom's own code stated and what the request table says, instead of one overwriting the other. But Start() still wrote "starting up" straight into the shared page rather than through SetActivity, so nothing was ever recorded in _statedActivity for the composer to carry forward. One second later the first watchdog tick replaced it with "no request in flight". The effect was the whole point of the field, lost: a Bloom that wedges during startup, the one case where the activity string is the only clue there is, reported the least useful thing it could say. Start() now goes through the wrapper. The composition is pulled out into an internal ComposeCurrentActivity() so the chain can be tested, and a regression test pins it end to end - stated text survives a refresh, can be replaced, and clears back to idle rather than going stale. This bug has now been introduced twice in two different ways, which is what earns it a test rather than a comment. Also: - SetLongOperation carries a prominent note that nothing calls it yet and what that costs: the Doctor reads the flag, so with no caller it is permanently false and every freeze is judged at the one-minute threshold rather than five. Which operations to mark is a judgement about how Bloom really behaves - "a request has run a minute" is the same signal as the freeze itself - so it is left deliberately unwired rather than guessed at. - FreezeSimulator.ArmIfRequested disarms any pending simulation before arming a new one, so arming twice cannot abandon a running timer that then goes off when nobody asked for it.
There was a problem hiding this comment.
Your trial has ended. Reactivate Greptile to resume code reviews.
| /// Says what Bloom is doing, in words fit to appear at the top of a bug report — "Publishing to | ||
| /// BloomPUB", "Saving Foo.htm". Truncated if very long; safe to call from any thread. | ||
| /// </summary> | ||
| public static void SetActivity(string activity) |
There was a problem hiding this comment.
[Devin — Investigate, current commit] SetActivity and SetLongOperation are defined but never called from Bloom.
Confirmed, and the second one has a real cost. The Freeze Doctor reads LongOperationInProgress and uses it to raise its freeze threshold from one minute to five — the mechanism that stops a legitimately slow operation being filed as a freeze. Nothing in Bloom ever sets it, so it is permanently false and that patience does not exist: every freeze is judged at one minute.
What that does and doesn't threaten:
- Work behind a modal progress dialog is safe either way.
ShowDialogruns a nested message loop, so the UI-thread heartbeat keeps ticking and no freeze is detected at all. - Work that blocks the UI thread for over a minute without pumping messages would be filed as a freeze. That is the false positive the flag exists to prevent.
It is left deliberately unwired rather than guessed at, with the gap written up at the method so nobody assumes the grace works. Choosing which operations to mark is a judgement about how Bloom really behaves, and it cannot be inferred: "a request has been running a minute" is the same signal as the freeze itself, so no automatic rule can tell legitimately-slow from wedged. It also spans several progress/publish paths rather than one chokepoint.
Raised with the developer as the one open decision on this PR. Thread stays open until that comes back.
SetActivity having no callers is fine and needs nothing — it is a public entry point for Bloom code to use, and Start() is now a caller as of d7f5f59.
The previous commit stopped the watchdog erasing what Bloom states it is doing, which fixed a startup freeze reporting "no request in flight". It introduced the opposite fault: nothing ever cleared "starting up" again, so an idle Bloom would still be describing itself that way hours later, and a freeze at 4pm would be reported as a freeze during startup. These two failures are opposite, which is why this has now been got wrong three times in three ways. Bloom states "starting up" once and has no natural "finished starting" moment to clear it at - Start() runs immediately before Application.Run, and there is no later hook that means "now interactive". Handling an API request is that moment: the UI is up and talking to the server. So ApiActivityTracker exposes HasHandledARequest, and the composer retires the startup note once it is true. Reading the condition rather than requiring a call means no future startup path has to remember to announce itself. Any other stated activity is left alone - a long publish must keep saying so until its caller says otherwise. The composition rule is now a pure Compose(stated, request, hasHandledARequest) with no static state in it, so both directions are pinned deterministically rather than one of them depending on what else ran first in the assembly. The previous version of this test asserted whichever outcome the ambient state happened to produce, which would have passed whatever the rule did.
There was a problem hiding this comment.
Your trial has ended. Reactivate Greptile to resume code reviews.
… (BL-16719)
The seqlock in DoctorChannelWriter.Write incremented the sequence counter in the
same statement that published it, from OUTSIDE the inner try:
view.Write(OffsetWriteSequence, ++_writeSequence);
try { update(view); } finally { view.Write(OffsetWriteSequence, ++_writeSequence); }
The ++ happens before the call, so a throw from that one write left the counter
odd with no finally to correct it. From then on the parity was inverted for the
rest of the run: every write published an EVEN value while the write was in
progress and came to rest on an ODD one. Readers treat odd as "a write is in
progress" and give up, so the channel silently disabled itself - the Doctor
would fall back to watching Bloom from outside, which is blind to the very
freeze this exists to catch, with nothing anywhere saying why.
This is the second time this counter has produced exactly that failure, the
first being the non-atomic increment fixed by _writeLock. The pattern is that
the invariant was maintained by careful statement ordering, which is fragile in
proportion to how bad breaking it is.
Now every increment is inside the try, and the finally restores parity from
whatever value was actually reached rather than assuming one more increment is
correct. Two consequences worth having: no ordering of failures can leave the
counter odd, and a failure that stops even the final view.Write is repaired by
the next successful write instead of lasting for ever.
Applied identically to the copy in BloomBooks/bloom-freeze-doctor, which is
where this file's source of truth lives.
Not unit tested directly: reaching it needs the memory-mapped view itself to
fail mid-write, which cannot be injected without adding test surface to a file
whose whole point is being the same in both repos. The existing tests do cover
an update delegate that throws, and would fail if the parity were inverted.
There was a problem hiding this comment.
Your trial has ended. Reactivate Greptile to resume code reviews.
|
[Claude Opus 5 from Thomson's machine during preflight] Consulted Devin up to Three real bugs, all fixed, each with its own thread. All three were in this branch's new code, and none would have been caught by testing — a freeze report would simply have said something false.
Two patterns in there worth a reviewer's attention, both about invariants held up by statement ordering:
One flag refuted — "a Bloom that cannot create the shared page never writes a clean-exit record". It does: the session file is written before the shared page is attempted, and the One flag open, and it is the decision on this PR — Finally, so the review page is not misread: Devin re-emits earlier findings verbatim on re-review rather than re-checking them. Several Informational flags across these rounds are demonstrably false against the very commit they were raised on — a pruning rule they describe is the opposite of what the code does, a comment they call contradictory is correct and explains itself, and a list of simulator kinds they call mismatched is complete. Each was checked individually rather than assumed. The resolved threads, not the flag count, are the accurate record. CI ( |
…16719) Three files under src/BloomExe/FreezeDoctor are copies of files whose source of truth is BloomBooks/bloom-freeze-doctor. They describe a wire format two separate programs must agree about exactly, and they are 750 lines maintained by hand. That has already gone wrong: the two copies had diverged, and a fix made in one repo had to be carried across by hand. Drift here fails silently and expensively - Bloom writes one set of offsets, the Doctor reads another, and the result is a stream of confident, wrong diagnostic reports that nobody can tell apart from real ones. Until now the only guard was each repo pinning the layout constants in a test, which catches a changed constant but not a changed anything-else. So: build/check-freeze-doctor-contract.sh compares the copies, and a small workflow runs it on any PR touching them. It also has a manual trigger, because a change in the other repo cannot trigger a workflow in this one. Two details that took a couple of attempts: - The comparison ignores whitespace, and deletes it rather than collapsing it. The two repos formatters disagree about where to wrap long lines, so a byte comparison fails permanently; and collapsing runs to a single space is not enough, because rewrapping inserts a newline after an opening bracket that then collapses to a space the other copy does not have. Deleting is safe here because none of the three files has a string literal containing a space - checked, and noted in the script in case that changes. - It takes a shallow git clone rather than reading raw.githubusercontent.com. That CDN served the previous version of a file for minutes after a push, so the check reported drift that did not exist. A check that cries wolf gets switched off, which is worse than not having one. The check is deliberately temporary: the real fix is to publish the contract as a NuGet package from the Doctor repo and delete these copies, at which point the script and the workflow go too. The file header now says that, and also stops claiming the copies are byte-identical, which they are not. Verified by running it six ways: local sibling clone, explicit override, bad override, the CI path with no clone present, and - the ones that matter - that a changed layout offset and a changed schema version both fail it, while a pure reflow does not.
There was a problem hiding this comment.
Your trial has ended. Reactivate Greptile to resume code reviews.
…-16719) The Doctor repo is moving these files into their own project so the contract can be published as a package. The check hardcoded the old path, so whichever repo merged first would have broken the other. It now looks in both places, newest first, and says which one it used. It tests for the FILES, not the directory. Testing for the directory looked fine and was wrong: switching the Doctor repo between branches leaves behind the directory of the branch you left whenever it holds build output, because obj/ is gitignored and git cannot remove a non-empty folder. So the check found an empty BloomFreezeDoctor.Contract/ and reported all three files as drifted. A false alarm is the one thing this check must not produce - a check that cries wolf gets switched off - so it was worth the extra condition. Found by testing it against the Doctor repo on each branch in turn, which is also how the two orderings are now verified.
There was a problem hiding this comment.
Your trial has ended. Reactivate Greptile to resume code reviews.
Problem
Users report that Bloom froze, and we get almost nothing to work with. Their problem report is written after they killed Bloom, so it describes a healthy new process, and the log only shows what Bloom managed to write before it stopped responding. Three quite different failures all arrive looking identical — the UI stops responding; Bloom exits without managing to report anything; or Bloom's window is gone while the process lives on, so the user cannot start Bloom again — and none of them currently leaves usable evidence. BL-16697 is the live example.
Cause
Nobody is watching at the moment it happens, and the worst case cannot be watched from outside at all. A UI thread blocked in a managed wait on an STA thread keeps dispatching sent messages so COM still works, so the window answers probes,
IsHungAppWindowreports it healthy andProcess.Respondingreturnstruewhile Bloom is completely stuck. Measured on a real Bloom: nine minutes frozen, reported responsive throughout. Since Bloom's UI thread awaits WebView2 constantly, that is likely the common shape of freeze rather than an exotic one.What this PR changes
This is Bloom's half of the work; the diagnostic tool itself lives in BloomBooks/bloom-freeze-doctor. Nothing here changes what Bloom does for a user, and all of it is inert on a machine where the Doctor is not installed.
ProcessExithandler. That runs for a normal return fromMainand forEnvironment.Exit, and not forFailFast,TerminateProcessor an access violation — which is exactly the line worth drawing, and one no future exit path can forget to honour. A Doctor-requested exit is deliberately not recorded as clean.Log.txteach run and falls back to a random name when another Bloom holds it, so guessing from the filesystem picks the wrong file in exactly the restart-after-a-freeze case), plus its ports, version, channel and collection.BLOOM_SIMULATE_FREEZEis set and the channel is one we are willing to break deliberately, so the detection can be tested against a real Bloom instead of waiting for a real freeze. Alpha is included on purpose: reproducing a freeze usually means working with somebody who is actually having one, and those people are running Alpha, not a build from source. A stray environment variable on a Release or Beta machine does nothing at all, and three tests pin exactly which channels are allowed, so widening or narrowing that set breaks a test.raw.githubusercontent.com, whose CDN serves stale content for minutes after a push.Also:
BloomServergains aBusyWorkerCountbeside the existingBlockedWorkerCount, and theRobustFilepre-commit check exempts the two of those shared files that do file I/O — they cannot callRobustFile, because it does not exist in the Doctor's repository. Every call in them is a best-effort diagnostic write already wrapped in a catch-everything, and the failureRobustFilewould retry through just means "no session file this time", which the callers are built to tolerate.The duplication is temporary
Keeping three files in step across two repositories by hand is not the intended end state, and the drift check exists only because they are copies. #8219 removes the duplication: the Doctor publishes them as a NuGet package (
BloomBooks.FreezeDoctor.Protocol) and Bloom references it, which deletes the copies, the drift check, its workflow, and theRobustFileexemption above. That PR is stacked on this one and can be read for shape now; it is not mergeable until the package is actually published.Ref: https://issues.bloomlibrary.org/youtrack/issue/BL-16719
Devin review
This change is