Add the Bloom Freeze Doctor (BL-16719) - #8229
Conversation
|
| Filename | Overview |
|---|---|
| src/BloomFreezeDoctor.Core/Outbox/ReportOutbox.cs | Implements persistent report queuing and cross-process drain serialization; the latest lock-timeout fix now exits without entering the drain when another process holds the gate. |
| src/BloomFreezeDoctor/DoctorSupervisor.cs | Coordinates process discovery, evidence gathering, report-now requests, queued submission, and watcher lifecycle without a remaining blocking issue from the reviewed threads. |
| src/BloomFreezeDoctor.Core/FreezeDetector.cs | Implements heartbeat-based freeze, crash, and windowless-process classification with slow-activity and debugger handling. |
| src/BloomFreezeDoctor.Protocol/DoctorChannel.cs | Defines the shared-memory health protocol and compatibility behavior used between Bloom and the Doctor. |
| src/BloomExe/FreezeDoctor/FreezeDoctorSupport.cs | Publishes Bloom health, activity, debugger, shutdown, logging, and diagnostic-signal state to the companion process. |
| src/BloomFreezeDoctor.Core/Outbox/YouTrackSubmitter.cs | Submits queued diagnostic reports and attachments to YouTrack while supporting fingerprint-based report consolidation. |
| src/BloomFreezeDoctor.Tests/ReportOutboxTests.cs | Covers outbox persistence, submission limits, retention, and refusal of a second drain while another process owns the lock. |
| build/Bloom.proj | Builds, signs, and packages the Freeze Doctor alongside Bloom. |
Reviews (15): Last reviewed commit: "Stop the comments pointing at the abando..." | Re-trigger Greptile
Both found by Devin on PR #8229, and both verified against the code before changing anything. THE 6.3 WEBVIEW2 FALLBACK COULD NEVER FIRE FindCdpPort ended with return children.Count == 0 ? null : (int?)null; Both arms are null, so the documented fallback to the port 6.3 hardcodes was dead code. A Bloom 6.3 with no session file therefore got no CdpPort, and its WebView2 section was dropped from the report with nothing to say why. The guard around it was right and is kept: WebView2 children that advertise no port mean this is NOT the 6.3 arrangement, and guessing 9222 would interrogate some other program's browser and put the answers on a Bloom card. It is the no-children case that looks like 6.3, and that now returns WebView2Processes.LegacyHardcodedPort as the comment always said it did. FOUR DEDUP SETS MUTATED FROM SEVERAL THREADS AT ONCE _dumpsRequested, _exitsExamined, _zombiesReported and _zombiesEnded are shared across watchers, but every watcher raises Observed on ITS OWN timer thread, so with two Blooms being watched - routine on a developer's machine - they were touched concurrently with no lock. An unsynchronised HashSet can corrupt itself or throw, and worst of all can silently lose an entry, which is what these sets exist to prevent: a second dump of a crashing Bloom while it holds its own death open for us, or a second report of one exit. Telling detail: one of the five call sites, the _zombiesReported.Add after a zombie report is queued, ALREADY held _lock. So locking these was the intention and the other sites were simply missed. Each test-and-claim is now inside _lock, and only the test-and-claim - never the work that follows, which includes gathering and killing processes. The zombie pair is under a single lock together, because "the evidence is gathered AND nobody else has taken the one attempt" is one decision; splitting it would let two threads both conclude they were the one to end the process. DumpRequested() was pulled out of its short-circuit so it is not called while holding the lock. 110 tests pass. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Found by Greptile on PR #8229, and correct. Three separate things ask for a drain - startup, the five-minute timer, and the end of a gather - and all three were fire-and-forget tasks, so two could overlap. Both would then list the SAME pending bundles and both walk the search-then-create flow against YouTrack, which is not atomic. The results are duplicate cards, or duplicate comments on one card, and a combined total that can exceed the deliberate three-per-day cap. That cap exists so that a machine in a bad state cannot spam the tracker, so quietly exceeding it is the worst version of this. Neither the supervisor nor ReportOutbox had any mutual exclusion, so a SemaphoreSlim(1,1) now serialises it, and it is disposed with the supervisor. It WAITS rather than skipping. Skipping would be cheaper and is tempting, since a second concurrent drain would usually find nothing left to do - but ReportNowAsync awaits this and then looks for its own bundle in the queue. Had its drain been skipped because another was already running, it could have reported failure for a report that was in fact about to be filed perfectly well. 110 tests pass.
Found by Devin on PR #8229, and it is the exact failure _workInFlight exists to prevent - on the one path that never got the guard. The field's own comment says why it is there: a Bloom would crash, the Doctor would notice the process was gone, conclude there was nothing left to watch, and exit, cancelling the examination of the very crash it had just seen. It is incremented for the report-gathering job and for the exit examination. The crash DUMP job never incremented it, so ConsiderExiting could see zero work in flight and shut the Doctor down mid-dump. This is also the likeliest path for it to happen, not the least: the dump runs because Bloom is in the act of crashing, so the process is about to disappear - which is precisely the event that makes the Doctor look around and find nothing left to watch. And it is the worst one to lose, because Bloom is holding its own death open for about three seconds waiting for us, so the dump either happens now or never. The decrement goes after SignalDumpComplete, so Bloom is released before our bookkeeping rather than after it. 110 tests pass.
776a56e to
7269268
Compare
|
[Claude Opus 5 during preflight] Consulted Devin up to Devin had timed out on this PR five times over two days — jobs reported Most of it was already dealt with. Devin itself marks 7 of the 10 bugs resolved by earlier commits on this branch. Of what was still live:
Every current Bug and Investigate flag has its own thread above with its outcome. The informational flags are not mirrored. Greptile has reviewed this branch 15 times and its threads are all resolved; its most recent review predates today's commits. CI is green. One thing Devin cannot tell us, and says so itself: the crash-dump path is still unexercised end to end. |
…re (BL-16719) Two decisions from the preflight report, and John's question on the first turned out to matter more than the fix. **A failed attachment now says so on the card**, the way the too-large path already does. Skipping in silence left a card that looked complete and was not, and the evidence it was missing sits on a machine we will lose access to - so nobody would find out until they went looking for a dump that had never been there. Note this also covers the case UploadAsync reports by RETURNING NULL rather than throwing, which the old code's catch could never have seen. **And John caught that the message the too-large path already writes was itself misleading.** "Still on the user's machine at ..." reads as a permanent fact. The folder is not permanent: the outbox drops a bundle 30 days after it was gathered, and sooner if more than MaxBundles reports pile up and it stops being one of the newest. So the sentence could be true when the card was filed and quietly false by the time somebody acted on it - which is worse than saying nothing, because it sends them looking. Both limits matter and only one is a date, so the wording promises the floor and warns about the other: "kept until about 2026-09-30 - or less if the Doctor gathers more than 20 reports before then, so ask sooner rather than later." One helper, used by both paths, with three tests pinning the path, the date and the warning - because the wrong version of this sentence is the natural one to write. **The YouTrack token: settled, and recorded so the question stops recurring.** There is no new risk; the key was already exposed by Bloom itself, and this code uses it in the ways we intend. That reasoning was already in the comment, but buried at the end of three paragraphs, which is why reviewers and bots kept re-raising it. It is now the first line, marked settled and dated, with the long form below for anyone who wants it. 196 Doctor tests plus the three new ones pass.
Found by John's manual run, which produced nothing. Both are mine, from e9650d8, and the second one broke the feature outright. **Every discovery tick that adopted a Bloom immediately un-adopted it.** Whether the watched Bloom had gone was read from a flag set only in the "we already have a target" branch - so on a tick that ADOPTED, that branch never ran, the flag was still false, and the Bloom just adopted was treated as departed. The log from the run shows it plainly: "watching Bloom 109480 (Developer/Debug)" twenty-one times, settling into once every five seconds, which is the discovery interval. **And no exit was ever examined.** Fixing Fable's race, I had claimed the examination inside Discover and then called ConsiderReportingAnExit - which begins by refusing a death already claimed. So it returned immediately, every time. That is why a real crashing Bloom produced no report at all: the crash happened, the process died, and the Doctor said nothing. The claim goes back where it was, inside ConsiderReportingAnExit, which already test-and-claims under the lock. Fable's race is still fixed, by a smaller change than the one that caused this: the sweep reads "we asked it to stop" under the lock and carries it out, and simply never CLEARS it. Clearing was the race, and with a single target there is nothing to clear it for - adoption resets it. Departure is now considered only for a Bloom we actually checked, and only if the watcher is still the one we checked. A test that would have caught it, and getting there took two goes, which is worth recording: - The first version pre-adopted with Adopt() and then called Discover. It passed against the bug, because pre-adopting takes the OTHER branch - Discover never reached the adopting path where the fault lived. The test now lets the sweep find the test process itself, so one tick both adopts and decides. - My first attempt to reproduce the bug was also unfaithful: I removed one guard, but the fix has two, and the second blocks it independently. Removing only one left the test passing and would have let me believe it was worthless. With both removed - the original shape - it fails. Discover is now internal so a test can drive one tick rather than waiting on a five-second timer. 200 Doctor tests pass.
John's run filed a report, and the run showed up two more faults. The good news first: the churn is gone and the diagnosis was right - "Windows logged an application error, WER left a report, it exited with an unhandled managed exception (0xE0434352)", which is exactly what the simulated crash did. **The card got the report WITHOUT the crash dump, and the one with the dump was thrown away as a duplicate.** Two paths reported the same death: the crash-dump path, which Bloom triggers by asking to be dumped while it is still alive and holding its own death open for us, and the exit examination, which runs once the process has gone. Both gathered, both filed, and the outbox's fingerprint dedup kept whichever arrived first. That was the dumpless one - it has less to collect, so it wins the race - and the dump-bearing report was demoted to a "this happened again" comment, which by design attaches nothing. Net effect: we held a dying Bloom open for three seconds to capture a dump, then told the reader it was "near enough a copy" of what was already on the card and left it on the user's machine. So the exit examination now stands down when the dump path already has the death. It is strictly better evidence, gathered from a process that still existed, which the examination can never recover afterwards. **And "filed 1 report(s)" could not tell you which one.** DrainOutcome carried a count; the ids were known right there and dropped. Since everything the Doctor gathers is queued and sent by a later drain, the drain is where card ids come into being - so the only path that could ever light up "Open card" was an inline filing during gathering, which is the rare case. Hence a balloon that said a report was filed and a window that could not offer to open it. DrainOutcome now carries FiledIssueIds and derives Filed from it, so the count and the ids cannot drift apart, the log names the cards, and the supervisor raises ReportFiled for every filing path rather than just the freeze one. Both faults were in the same decision, which has now been wrong twice - the earlier time it silenced reporting outright - so it is no longer three flags read in sequence inside a lock. WhoReportsTheDeath.Decide is a pure function over (we ended it, a dump is being reported, already claimed) with a four-way answer, and its fixture pins the whole table, including one test per historical bug. The one for the claim-then-decide bug asserts the property that makes that shape wrong: the answer depends on whether anything has claimed the death, so a caller must decide before it claims. Two outbox tests cover the ids: which cards a drain filed, in order, and that a drain filing nothing names none - the button reads the last id, so a stray one would point at a card that does not exist. 208 tests pass (was 200).
The previous fix worked - John's run gathered ONE report, the exit examination stood down with "its crash dump is already being reported", and the bundle contains bloom-103828.dmp. The "Open card" button worked too. But the dump still did not reach the card, for a different reason. The report was a RECURRENCE: its fingerprint matched the card the earlier buggy run had opened, so it became a "This happened again" comment - and that path deliberately attaches nothing. The rationale was sound as far as it went: two reports sharing a fingerprint share their reason, version, channel and top frames, so a second dump is usually a near-duplicate of the first at some 16 MB, and a card carrying several becomes unreadable exactly when it matters most. It holds only while the card HAS a first dump to be a near-duplicate of, and often it does not. The Doctor only gets a dump when Bloom notices it is crashing and asks to be dumped; a Bloom that dies without noticing - an unhandled exception on a thread it does not control, which is the case this whole feature exists for - is reported by the exit examination, which runs after the process has gone, when no dump can be taken. So the first card for a problem frequently has no dump, and the first occurrence that COULD have supplied one did not, the comment assuring the reader the evidence was "near enough a copy" of what was already on the card. What was already on the card was nothing. So a recurrence now contributes a dump, and only a dump, and only to a card that has none - one dump per problem, which is what a developer needs and cannot reconstruct, without letting a repeatedly-crashing machine pile 16 MB onto the same card every time. Logs stay out: they are not attachments at all, the report body inlines the tail of Bloom's log in a collapsed section, so "the card has no log attachment" is true of every card and would attach one to all of them. The decision is RecurrenceArtifacts.WorthAttaching, pure and tested, including the case where somebody has already attached a dump by hand under a name of their own. Reading the card's existing attachments errs towards attaching if the request fails: a duplicate dump is untidy, a missing one is gone once the user's outbox clears. The comment now says which of the two situations it is in, rather than one sentence that is false in the other, and both branches name the date the bundle folder is kept until - the same correction already made to the too-big-to-attach path. AttachArtifactsAsync is now a one-line call into AttachTheseAsync, so the recurrence contributes its one file through the same upload-then-restrict-to- Developers path as everything else. Decision D2 applies unchanged. 214 tests pass (was 208).
My own bug, from the commit before this one: the attach ran between posting the comment and checking whether the post had succeeded. A failed comment leaves the bundle pending for a later drain to comment again - so the dump would be uploaded twice, and the second pass would then see its own upload on the card and conclude, correctly by its own rule, that the card already had a dump. Check first, then attach.
John: "we shouldn't get multiple reports at all for the same crash". Chasing that found the reverse problem as well - one card collecting crashes that were never the same crash - and the two share a cause. **The fingerprint could not tell two crashes apart.** It hashes the reason, Bloom's version, the channel, and the top five frames of the UI THREAD. That last ingredient is the only one that distinguishes anything, and it is exactly right for a freeze, where the UI thread's stack IS the problem. In a crash the fault is on some other thread and the UI thread is sitting in its message pump, identical every time - so the fingerprint degenerated to reason+version+channel and EVERY unexplained crash on a given build landed on one card as "This happened again". Measured, not theorised: three separate simulated crashes in three separate processes in one afternoon all produced 1ec8760ad8a5. A crash's identity is the faulting thread's exception type and top frames, which Windows already records in the .NET Runtime event the collector reads for other reasons. CrashSignature pulls it out, deliberately dropping two things: the file and line, which change whenever anyone edits above the fault and would give the same crash a new identity after any rebuild, and the exception MESSAGE, which routinely carries a path or a book name and would give one fault a different identity on every machine. Its fixture is built on a real event copied verbatim from this machine rather than one written to suit the parser. The timing is the awkward part and shaped the design. The crash-dump path starts gathering while Bloom is still ALIVE - blocked, waiting for its dump - so at that moment no event exists to read; my first attempt looked it up there and would have found nothing. It is resolved at the END of gathering instead, by which time the process has gone and the entry is there. A measured run had ten seconds between the two. When it is still missing, the fingerprint falls back to what it always used, which is today's behaviour and not a regression. Also fixes a smaller thing the same run exposed. "its crash dump is already being reported" appeared twice, a second apart: two passes reached the decision for one death, and because the reasons were tested before the claim, the second re-took its own branch instead of standing down - logging again and disposing a handle the first pass had already released. A stand-down is not just a decision, it acts. So "already claimed" is now tested first, and a test asserts every reason gives the same answer once a death is claimed. Two properties are pinned in both directions, because trading this bug for its opposite would be no better: two different faults get two cards, and the same fault twice still gets one. A freeze is fingerprinted exactly as before, and there is a test for that too - plus one asserting the OLD collapse, kept as an executable record of why any of this is needed. 226 tests pass (was 214).
The crash-fingerprint fix in a098233 did nothing. John's run filed a proper new card with its dump attached and no duplicate comments - all correct - but the bundle was still 1ec8760ad8a5, the same degenerate fingerprint as every crash before it. The identity was null every time. Windows writes several entries for one crash, and the walk sees the newest first. Measured on this machine, for the crash at 15:18:55: 15:18:59 Windows Error Reporting 1001 Fault bucket 2085764476734548794, type 4 15:18:55 Application Error 1000 Faulting application name: Bloom.exe, ... 15:18:55 .NET Runtime 1026 Application: Bloom.exe ... Exception Info: System... The Application Error entry names Bloom, so it matched, and the walk returned it and stopped - four lines above the only entry that carries an exception. So the parser was handed a message with no "Exception Info:" in it, correctly returned null, and the fingerprint fell back to hashing an idle UI thread. The walk now carries on past a match that cannot identify the fault. It answers two questions in one pass - was there a crash entry, and which crash was it - and stops once it has both. The judging is separated from the walking as PickTheCrashThatIdentifiesItself, purely so it can be tested, because this is a bug that reads as obviously correct code. "Take the first entry that names Bloom" looks right, and produced a null identity on every real crash. Only the data showed it. Its fixture uses the measured entry order, and covers the case that must NOT change: FailFast and an access violation produce a 1000 entry and no managed one, and that is still evidence of a crash - it just leaves the fingerprint on its old fallback. Also unpinned the process id in A_discovery_tick_does_not_drop_the_Bloom_it_just_ adopted. The sweep looks up by process NAME, so on a machine running a second test host it adopted the other one and the test failed for a reason it is not about. It now asserts what it is about: the tick that adopted did not also decide the adopted Bloom had gone. 230 tests pass (was 226).
Bloom was up for eighty-three seconds - about sixteen discovery ticks - before the Doctor began watching it, and the log said nothing at all. That silence is the real defect: a freeze in that window would have gone unreported with no trace of why, and afterwards there was nothing to work from, because the code's only record of the decision was a `continue`. The sweep asks GatherContextBuilder.DescribeRunningProcess to describe each candidate, and that swallowed every exception and returned a bare null. Both it and BloomTargetWatcher.DescribeProcess now say why, and the reasons are worth having: reading MainModule of a process that is still starting fails in identifiable ways, and that is the likeliest explanation for what John saw. Logging it needs a little care, because both obvious approaches are quiet failures. Say it every tick and the log fills with one line every five seconds for as long as the process lives, burying whatever else it was recording. Say it only the first time and the reason is lost the moment it CHANGES - which is exactly what a process part-way through starting up does. So the pair is what counts: a reason is said once per process, and again if the reason itself changes. DeclineNotes holds that, with its own tests, and it also supplies the number the run was missing: on adopting a Bloom it had been declining, the log now reads "watching Bloom 53468 (Developer/Debug), 83s after first seeing it". The timer runs from the first sighting rather than from the latest reason, or a process whose reason changed half way would under-report precisely the case worth measuring. It deliberately remembers ONE process rather than a dictionary keyed by process id. The Doctor watches one Bloom, and a map keyed by pid is the shape whose stale entries caused both bugs the one-Bloom rewrite removed; a diagnostic is not a good reason to bring it back. 238 tests pass (was 230).
John: "got a duplicate report, claiming (wrongly) that the card had none". Both halves are real and the second one is my wording. The crash-identity fix landed - the fingerprint moved from 1ec8760ad8a5 to 0e608aa803c6 - so this was a genuine recurrence of a genuinely-matched problem. What went wrong is what the recurrence checked. It asked whether the card had a dump ATTACHMENT, and the card did not: AUT-20987's dump was 8,389,030 bytes, 422 over the attachment ceiling, so it went to the support bucket and was linked from a comment. The card plainly carried the dump and had no attachment at all. So the next occurrence - 8,054,542 bytes, just under - uploaded a second copy and announced that the card had none. The question is now "does this card carry a dump by any route", and the answer reads the card's text as well as its attachments. Two traps in doing that, both covered by tests, because either would be worse than the bug: - The Doctor's own comments TALK about dumps. "this dump could not be attached; it is still on the user's machine at ..." must not read as the card carrying one, or the first failure would suppress every later attempt to supply it. - The bucket is shared with Bloom's problem-book uploads, so the bucket name alone proves nothing. Hence both halves are required: a link into the bucket AND a .dmp in it. And the comment no longer invents a reason. It said the card had none "because the first report for this problem was made after the process had already gone, when no dump could be taken" - which was false the first time it was ever printed. That card's dump had been taken perfectly well and was sitting in the bucket. It now says only what is true: the card was not already carrying one. Also in here, from the same run: every refusal in AdoptFacts said why. Two were bare `return`s, so a Bloom can run for a minute with the Doctor declining it every five seconds and the log showing nothing - measured at 83 seconds once and 54 the next time, both still unexplained. The sweep now reports each candidate it passes over, suppressed per reason by DeclineNotes, so the next occurrence names itself. One trap found while writing that: returning null from inside AdoptFacts's lock on the success path made the WatchingBloomAt notification unreachable, and the window would never have learned where Bloom is. The compiler caught it. The refusals do return early, which is right - there is nothing to notify anyone about. 241 tests pass (was 238).
Three runs have now had a Bloom sit unadopted for a long time with not one line in the log: 83 seconds, then 54, then 110. The third one shows why it matters rather than merely being untidy. Bloom started at 15:55:59, was adopted at 15:57:49, and crashed nine seconds later - and the card has no dump, because Bloom only asks to be dumped if a Doctor is ALREADY watching, and when it asked, twenty seconds before we noticed it existed, none was. The delay did not just look bad; it lost the evidence. Every other path through the sweep now says something: a process we cannot describe, a headless run, a second Bloom, a process that went away mid-look. This was the one remaining silence, and it is the one that can swallow anything - including Process.GetProcessesByName itself throwing, which would produce exactly what was observed, since the OS could see the process throughout (checked from PowerShell mid-episode: GetProcessesByName(Bloom) returned it while the Doctor was still not adopting it). So the catch logs, suppressed by repetition like the other notes because a fault here repeats every five seconds for as long as it lasts. Keyed on 0, since this is the sweep itself failing rather than a particular process being declined. I am not claiming this fixes the delay - it explains nothing yet. It means the next occurrence names its own cause instead of costing another manual run. 241 tests pass.
…-16719) **Decision, recorded in the code where the question arises.** An unguessable URL is sufficient protection for a dump too large to attach. John's call, August 2026. The asymmetry is written down next to the upload so nobody rediscovers it: an attached dump is restricted to the Developers group, as decision D2 requires, while one in the support bucket is a public-read URL linked from an ordinarily visible comment, protected by the random component of its key. That is not a corner case - a real minidump is 16-17 MB, so the bucket is the route essentially every production dump takes, and D2's group restriction therefore almost never applies in practice. It surfaced only because one simulated dump came out 422 bytes over the ceiling and the next 334 KB under, so the same crash was seen going both ways within an hour. Accepted: a full GUID in the key is the protection a presigned link would give, without expiring in the middle of an investigation. **And the delay now has nowhere left to hide.** A fourth measurement, 34 seconds this time, with the new instrumentation silent: no process was declined, and the sweep did not throw. That rules out both paths added for it and leaves the one outcome that still had no voice - the sweep looking and genuinely finding nothing. It now says so, naming the process names it searched, because "found nothing while looking for the wrong name" and "found nothing while looking for the right one" need completely different fixes and are indistinguishable in the log today. Sweep-level notes get their own DeclineNotes instance. Each one remembers a single subject, so sharing it with the per-process notes would have the two kinds evict each other and a run that alternated would report both every five seconds. Not a fix for the delay, and I am not going to keep implying otherwise: four runs in and it is still unexplained. This is the last silence in the sweep. 241 tests pass.
…16719) Every Doctor on this machine writes to one doctor.log, and nothing identified them or recorded when one started - so a log containing two instances could not be read at all. That stopped being theoretical: four lines appeared from a process nobody could account for, and there was no way to tell where it came from, what arguments it had, or which Bloom it thought it was watching. So one line per run, at startup, naming the executable's full path and what the Doctor was told to do. The path matters as much as the arguments: it is what the channel is derived from, and therefore the difference between a Doctor built from this worktree and one from an installed Bloom. The unaccounted-for lines read: [25736] watching Bloom 25736 (Release) The log prefix is the writing process's own id, so that Doctor had adopted itself. That remains unexplained - it was not a Doctor launched by the beta-internal build, which has none of this code - and a guard is the right response to an unexplained route rather than a guess at which route it was: adopting our own process id is now refused and said out loud. Watching ourselves is nonsense however we got there, and it would have us report on that process's "death" as we exited. Also: an adoption REQUEST that comes to nothing now says so. That is Bloom telling us which process it is - the one adoption route that is not a guess - and it failing silently leaves a Doctor that Bloom started watching nothing, with a log showing only that it never adopted anything. The self-refusal broke three tests, correctly: they adopted the test host itself as a Bloom stand-in. They now start real child processes, which is the more faithful stand-in anyway - the test host is the one process whose lifetime can tell us nothing about watching another - and they clean them up in teardown rather than per-test. The refusal itself gets a test. 242 tests pass (was 241).
b084b3b does not compile. SayWhatWeAre landed inside CommandLineOptions instead of Program, because I anchored the insertion on a doc comment that appears in both classes and picked the wrong one. Worth recording WHY I pushed it: `build/agent-dotnet.sh test` builds Core and the test project, and the test project does not reference the WinExe - so 242 tests passed while Program.cs did not compile at all. A green test run is not evidence that the Doctor builds. The exe needs its own `dotnet build`, which is also the build that has to be done to run it, and that is now the check before any commit touching src/BloomFreezeDoctor.
Four runs measured a Bloom sitting unadopted for 34, 54, 83 and 110 seconds, and the 110-second one cost a crash dump outright - Bloom only asks to be dumped if a Doctor is already watching, and it asked before we had noticed it existed. The instrumentation added for it stayed silent every time, which is what finally narrowed it: nothing was declined and nothing threw, so the time was going somewhere inside a sweep that believed it was working. It was. WebView2Processes.ReadCommandLine is a WMI Win32_Process query, and the discovery sweep calls it for every candidate, every five seconds. Measured on an idle machine: **1.9 to 2.7 seconds per call**, repeatedly. Under the load of Bloom starting up - a debug build, a Vite dev server, WebView2 spinning up its children - it is far worse, and the timer fires whether or not the previous callback returned, so the calls pile up and compete for the same slow resource, making each other slower. A pile-up that worsens the longer it lasts is exactly the shape of delays that ranged from 34 to 110 seconds. Two fixes, both of which are the correct behaviour independent of speed. **Ask once per process.** A command line cannot change while a process lives, so querying it on every tick was not merely expensive, it was the wrong number of times to ask. Cached on process id AND start time: keyed on the id alone, a Bloom inheriting a dead process's id would be handed that process's command line, and this is used to decide whether a run is headless - so the wrong answer means either watching a console verb or silently refusing to watch a real Bloom. **One sweep at a time.** A timer callback that can outlast its own period needs a re-entrancy guard, and skipping a tick costs nothing: the work it would do is what the running sweep is already doing. Released in a finally, because a sweep that threw without releasing would stop the Doctor looking for Bloom for the rest of its life - much worse than the overlap it prevents. The test suite is the incidental proof: same 242 tests, 1 minute 36 seconds before, 16 seconds after. The stand-in process in OneBloomAtATimeTests also goes from a minute to ten, because one run took 76 seconds to reach its assertion and the stand-in had exited by then - the same fault, failing a test for a reason it was not about. 242 tests pass, and the exe builds - which, per the previous commit, is a separate check that has to be run.
19cf1b4 claimed the adoption delay was the WMI query. It was not. The next run measured 52 seconds - Bloom up at 16:39:58, watched at 16:40:50 - with the caching and the re-entrancy guard both in place. That commit message overstates what was found and this one is the correction: the WMI query is a real cost and worth having fixed (the test suite went from 1m36s to 16s on the same 242 tests), but it is not why a Bloom sits unadopted. Five measurements now: 34, 52, 54, 83, 110 seconds. Every instrumented path stays silent through all of them - nothing declined, nothing thrown - which leaves two explanations that need opposite fixes: 1. the sweep runs and genuinely finds no process named Bloom while one exists; 2. the sweep is not running. **The log cannot tell them apart, and that is a flaw in the instrumentation I added.** "No Bloom running" is said once and then suppressed as a repeat, so a silent log means either "still nothing" or "no longer sweeping". Five runs of guessing between those is enough. So the sweep is counted, and the count appears in both places it settles the question: on the adoption line, and in a "still nothing" note repeated about once a minute instead of never. If Bloom is up for fifty seconds and the sweep number advanced by ten, the timer is fine and the search itself is wrong. If it advanced by one, the timer stalled. Either way the next run answers it instead of narrowing it. No behaviour change beyond the logging. 242 tests pass; the exe builds.
A probe running in a separate process, calling the identical
Process.GetProcessesByName("Bloom") once a second, settles the question the last
five runs could not:
Bloom 81632 really started at 16:51:48.595
the same API first saw it at 16:51:48.947 (+0.35s)
the Doctor adopted it at 16:52:02 (+14s, sweep 82)
So nothing is blind. A new Bloom is visible to that call within 350 milliseconds,
and the whole delay is the sweep's own latency. It also explains the range: the
sweep counter shows sweeps running 5.0 seconds apart while idle and 12.75 seconds
apart while Bloom was starting, so "wait up to one sweep" IS fourteen seconds, and
the 96-second case is several sweeps at that cadence or a few much slower ones
during the build.
That leaves one question - where a sweep spends twelve seconds - and two suspects
with nothing to choose between them by reading:
- looking for Bloom: one enumeration of every process on the machine;
- the bookkeeping afterwards: RaiseStatusChanged calls Pending(), which lists the
outbox directory and deserialises every meta.json in it, on EVERY tick, and has
nothing to do with discovery.
The second is the obvious suspect and would explain the load-dependence, since it
is disk-bound and a Bloom build saturates the disk. But it is a guess, and this
session has had enough of my guesses stated as findings, so the sweep is now timed
in those two halves and reports when it takes longer than the interval between
sweeps. Durations are bucketed coarsely before the repeat-suppressor sees them, so
repeated slow sweeps read as one shape of slowness rather than a fresh number every
five seconds.
Instrumentation only. One run should now name the half.
242 tests pass; the exe builds.
…-16719)
The instrumentation named the half, and it was not the one I predicted:
sweep 31 took 18905ms, longer than the 5s between sweeps:
18903ms looking for Bloom, 2ms on bookkeeping afterwards
My outbox theory was wrong - the bookkeeping is 2 milliseconds. And it is not the
process enumeration either, which measures 8-22ms and which the sweeps that found
nothing all did in under five seconds. The difference on sweep 31 is that it FOUND
Bloom, and finding it meant describing it, and describing it meant a WMI
Win32_Process query for the command line. For a process a few hundred milliseconds
old, on a machine busy launching it, that query took 18.9 seconds.
Caching it, two commits ago, could not help: the FIRST call is the one on the
adoption path.
The command line is wanted for exactly one decision - is this one of Bloom's
console verbs, which legitimately have no window and would otherwise earn a false
zombie report. That decision does not have to be made before adopting. So:
- describing a process no longer reads the command line at all;
- adoption happens on the strength of the process name;
- a background task then reads the command line and LETS GO of the Bloom if it
turns out to be a headless run;
- gathering reads it for the report, which is the right place to pay: gathering
already takes seconds and is racing nothing.
Safe because nothing is reported quickly. The freeze rules want twenty seconds of
silence before they even suspect, sixty before they report, and the zombie rule
thirty - so letting go after a few seconds, or even nineteen, lands well inside.
The release checks it is still the same Bloom before dropping it, since by then that
one may have gone and another been adopted.
This also matters beyond the delay itself, and John made the point: adoption
latency is the window in which Bloom's startup problems cannot be doctored at all,
and it is why one run lost a crash dump - Bloom asks to be dumped only if a Doctor
is already watching, and it asked twenty seconds before we had noticed it existed.
Not the whole answer. A poll still costs up to one interval, which is what a Bloom
too old to announce itself will always be stuck with - worth keeping, per John,
because those are the Blooms that most need watching. A signal from Bloom on
startup would make adoption immediate for everything current; that is the next
piece, not this one.
242 tests pass; the exe builds.
…lease" (BL-16719) **1. Adoption no longer waits for a poll.** Bloom already starts a Doctor when none is running, but a Doctor that is ALREADY running never learned a new Bloom existed: the one Bloom starts is a duplicate, which exits on the singleton mutex without telling the original anything. So adoption waited for the next sweep - five seconds now that WMI is off that path, but five seconds in which Bloom's own startup cannot be doctored at all. That is not hypothetical: on one measured run Bloom crashed and asked to be dumped twenty seconds before the Doctor had noticed it, and since Bloom only asks when a Doctor is already watching, the dump was never taken. So Bloom announces itself on a named event and the Doctor waits on it, using the same mechanism that already carries the dump request. The signal is the only one with no process id in its name, and cannot have one: the Doctor is waiting before it knows which Bloom will appear. It is also the only one Bloom sets without first checking whether anyone is listening, because there is nobody to check for - hence Announce, which creates the event if needed, rather than TrySignal, which reports "nobody there". A manual-reset event set into an empty room is still set when a Doctor arrives. Polling stays, and must: a Bloom too old to know about any of this cannot announce itself, and John's point stands that those are the ones most worth watching. This is an accelerator on top, not a replacement. If the announcement lands while a sweep is already running, the re-entrancy guard makes it a no-op - correct rather than a missed chance, since that sweep is doing the work being asked for, and the timer covers the sliver where a sweep listed the processes just before ours appeared. **2. A path we could not read is no longer called "Release".** DeriveFromExePath fell through to Release for anything unmatched, including an empty path - so a Bloom whose executable we could not read was labelled Release on its card, in the log, and inside the fingerprint, where it merged with genuine Release reports. Seen in a real log as "watching Bloom 25736 (Release)" for processes that were nothing of the kind. Only the empty case changes: a path we can read but do not recognise is still Release, because that is what an ordinary installation looks like and that is the answer the method exists to give. 244 Doctor tests pass (was 242), the 27 Bloom-side Freeze Doctor tests pass, and both executables build - BloomExe as well this time, since this is the first change in a while to touch it.
…L-16719) Three faults in the announcement I added an hour ago, all found by running it. **It spun.** The Doctor waits with ThreadPool.RegisterWaitForSingleObject, which re-arms before the callback runs, so a MANUAL-reset event fires the callback over and over until something resets it - and my Reset in the callback was racing that re-arm rather than preventing it. One announcement produced 103 wake-ups and 103 needless sweeps. A pulse wants an auto-reset event, where one Set releases exactly one wait and the kernel does the reset atomically. Both sides must create it the same way, since the first creator fixes the mode, so Announce creates it that way too. Now: one announcement, one wake-up. **It was gated on the wrong thing.** I put it after the RunFreezeDoctor check, so it only fired when Bloom was also configured to START a Doctor. That setting governs starting one, not cooperating with one already watching - nothing else here consults it either, since the heartbeat and the dying request for a dump both key off whether a Doctor is listening. The case it excluded is the one that matters most: support asking a user to start a Doctor by hand, which is also every Doctor in this session's testing. **It was too late to be worth anything.** Announced from where the Doctor is launched, near the end of Program.Main, it was measured arriving 6.2 seconds into startup - after the five-second sweep had already found Bloom. It is now the first thing Main does after Logger.Init, which it can be because it needs nothing: one named event, set, return. Measured at about 1.3 seconds now, that being .NET startup rather than anything we control, so worst-case adoption goes from 5 seconds to under 1.5. The point is not the number but what the number covers: everything before the announcement is time in which a hang or crash cannot be doctored at all, because Bloom only asks for a dump when a Doctor is already watching. And a correction to my own comment, which claimed an announcement into an empty room would still be waiting when a Doctor arrived. It will not: a Windows named event lives only while a handle is open, so create-set-dispose destroys it on the way out. Observed - a Bloom announcing 9 seconds before a Doctor started was never heard. Not a hole, since "no Doctor running" is the case Bloom handles by starting one, which then finds Bloom by sweeping. Verified end to end on a real run: adoption, dump requested and taken, exit examination standing down, one report filed. 244 tests pass; both executables build.
**Stop the Doctor before building.** A running Freeze Doctor loads BloomFreezeDoctor.Core.dll and .Protocol.dll from output/Debug/AnyCPU and holds them open, so any build that has to refresh them fails with MSB3027. That is not confined to building the Doctor: BloomExe's build copies Protocol.dll, so a running Doctor stops Bloom building at all. It cost John a whole test run - the build failed, Bloom never started, and the only symptom was a Doctor sitting there watching for a Bloom that could not come. Killing it is safe: reports are written to the outbox on disk as they are gathered, an interrupted send is picked up by the next drain, and Bloom starts a new Doctor moments later if the user has it on. Two things about that were got wrong first, both worth recording because both were invisible in the code: - It ran with stderr PIPED and never read. "close" waits for every stdio stream to end, so the promise never settled - and since the launcher awaits it, Bloom was never started at all. A convenience that can hang the launcher is worse than the problem it solves. It now ignores stderr, resolves on "exit", and has a timeout that cannot be missed. - Then it ran, but timed out. `taskkill /IM` walks the whole process table, and called just before the build it was doing that while Vite, LESS and seven file watchers were all starting; it needed longer than the five seconds allowed. It is now the first thing main does, while the machine is still quiet, where it returns at once. It only ever needed to happen before the BUILD, not immediately before. **--nowatch** runs Bloom under `dotnet run` instead of `dotnet watch run`. C# edits then do not rebuild by themselves, which is the right trade whenever you are not editing C#. The front end is untouched - Vite still serves it, so TypeScript and LESS remain live. Measured, twice, on a warm build: 35 seconds to a running Bloom with watch, 27 without. A real gain and worth having, but I should say plainly that it is not the halving we hoped for - most of the wall clock is Vite starting and Bloom itself, not the watcher. The saving should be larger on a cold or changed build, and it also stops dotnet watch competing for the machine for the rest of the session.
…e (BL-16719)
Found by running the simulated failures through a Doctor that Bloom launched
itself and reading what came out. For a SPIN the report named the thread burning a
whole core - correct and useful - and then said nothing whatever about where it
was spinning, which is the only thing a developer needs. Two faults behind that:
**The UI thread was not recognised at all.** It was found by looking for a
"RunMessageLoop" frame, and on a thread that is RUNNING rather than waiting the
stack walk yields "(native)" where those frames should be. So the one failure mode
where the UI thread IS the story had no UI-thread section in its report. It is now
also recognised by Bloom.Program.Main at the base, which survives when nothing
above it does, and which no other thread has.
**And recognising it would have made the report worse.** The old description fell
through to the first frame beginning "Bloom.", which on such a stack is
Bloom.Program.Run - the bottom of every UI thread there has ever been. The report
would have announced "The UI thread is blocked in Bloom.Program.Run": wrong twice,
since it is not blocked and that frame means nothing. A stack that cannot be read
is a fact worth reporting as one, so it now says so and names the thread to open
the attached dump at.
The two headlines then corroborate each other instead of one being absent:
- The UI thread's stack could not be read - which is itself a clue, because a
stack walk fails on a thread that is RUNNING far more often than on one that is
waiting. Thread 109948 in the attached dump is the one to open.
- Thread 109948 is using a whole core, so this looks like a spin rather than a
deadlock.
The reading is now a pure function with its own tests, built on two REAL stacks
copied from reports - one blocked, one spinning - rather than stacks written to
suit the code. Verified by re-running the simulation.
250 tests pass.
Running the simulated zombie and reading the result. Bloom alive, pumping, window
gone - and the report said:
Verdict: alive with no visible window for 31s
No thread is burning CPU, so this is a wait rather than a spin.
WebView2 answers normally, so the block is in Bloom's .NET UI thread, not the browser.
There is no block. The last line asserts one, and a reader could easily come away
hunting a deadlock instead of asking where the window went - which is the actual
question, and one the report answers a few lines later by listing both of Bloom's
windows as hidden.
The cause is that IsAboutAFreeze counts a zombie as a freeze, and several
collectors use it to decide whether an observation supports a CONCLUSION. For a
frozen UI thread "no CPU, so a wait not a spin" is a real deduction; for a zombie
it is a non sequitur about a thread that is running perfectly well.
So the concept is split. IsAboutTheUiBeingStuck covers only the three states where
the UI thread is actually suspect, and the two deductions use that. IsAboutAFreeze
stays where the distinction being drawn is merely live-versus-dying - notably "the
UI thread is in its message loop", which on a zombie report is not a reassurance
but the key finding: Bloom is fine, its window is not.
The zombie report now reads:
Verdict: alive with no visible window for 30s
The UI thread is in its message loop (idle or pumping).
WebView2 answers normally.
Also, while in here: the UI-thread section heading now carries the thread's OS id.
Every other section that mentions a thread uses it - the wait chains name "thread
83756", the CPU table "thread 109948" - so without it the reader cannot tell
whether the thread in the wait chain IS the UI thread, which is usually the whole
question. Noticed on the mutexchain run, whose wait chain named a thread the report
never connected to anything.
250 tests pass. Verified by re-running the simulation.
…L-16719)
Running the simulated unhandled exception. The Doctor caught it exactly as
designed - Bloom's fatal handler asked to be dumped, the dump was taken, the stack
showed the whole crash path - and the report's headlines were:
Verdict: Bloom was crashing and asked to be dumped before it died
The UI thread is blocked in System.Threading.WaitHandle.WaitOneCore.
Not one word about WHAT was thrown, which for a crash is the first question anybody
asks. The answer was in the report all along, 370 lines down inside the tail of
Bloom's log:
exception = System.ApplicationException: FreezeSimulator was asked to throw
A fact that is present but unfindable is barely better than a missing one, and
headlines are what a reader reads. BloomsOwnException pulls the last exception out
of the log tail and the report now leads with it.
The other headline was worse than useless. The UI thread WAS blocked in
WaitHandle.WaitOneCore - inside Bloom's fatal handler, waiting for the Doctor to
finish the dump. That is this tool doing its job, reported as though it were the
fault, and it invites a reader to go hunting a deadlock. It now says what it is:
the UI thread is in Bloom's own fatal-error handler waiting for this dump, so the
stack below is the path to the crash rather than a deadlock.
The report now opens:
Verdict: Bloom was crashing and asked to be dumped before it died
The UI thread is inside Bloom's own fatal-error handler, waiting for this dump -
so the stack below is the path to the crash, not a deadlock.
WebView2 answers normally.
Bloom's own error handling recorded: System.ApplicationException: FreezeSimulator
was asked to throw
Tests use a real log tail, and cover the traps: taking the LAST exception when a
session logged several, not swallowing the stack that follows it, cutting a message
long enough to wreck a headline, and refusing to announce an exception when the
marker has nothing after it.
256 tests pass. Verified by re-running the simulation.
…16719)
**FailFast now says why.** It was the one crash kind whose report never stated
what went wrong. It runs no managed handlers by design, so there is no dump and
nothing in Bloom's log - the .NET Runtime event is the sole record, and its
"Message:" line was sitting a hundred lines down in the evidence while the
headlines said only that the process had called FailFast. The report now opens:
Verdict: Bloom crashed: ... it called FailFast (0x80131623)
Bloom called FailFast: FreezeSimulator was asked to fail fast
Only when Bloom's own log has not already supplied a headline, which is a closer
account of itself than Windows' record of it.
**And "Send it anyway".** John asked for a way to really send a report from a dev
build. The Doctor declines to file on a developer build, on an automation run, and
when the failure was simulated on purpose; all three are right by default, and all
three are ones a developer sometimes wants to override for the report in front of
them. Until now the only way was "Report now", which gathers a WHOLE NEW report -
impossible once the Bloom in question has died, and about a different moment even
when it has not.
The button appears beside "Show report" whenever a report was saved and not sent,
and it asks first, naming the project. That matters: a Doctor that Bloom started
uses the ordinary project rather than the test one - being a developer build is
precisely why the report was held back - so this is not a rehearsal, and the person
clicking should know before rather than after.
ReportOutbox.SendThisAfterAll lifts only a deliberate refusal. Anything already
pending, uploading or filed is left exactly as it is: this is not a way to re-send,
and a button that quietly re-sent a filed report would make duplicate cards from
one click. Tested, including that it declines a bundle it should not touch and
reports failure for a folder that is not there.
262 tests pass. Both headline changes verified by re-running the simulations.
Found reviewing my own change from an hour ago. The new "Bloom's own error handling recorded: ..." headline was not gated to crash reports, and the log tail it reads is a couple of hundred lines of a real session - which routinely contains handled exceptions that came to nothing. On a FREEZE report that would put one of them at the top as though it explained the freeze. A plausible wrong answer in the headlines is worse than no answer, because the headlines are where the reader starts and a named exception is exactly the kind of thing they would go and investigate. Now only on reports that are not about a freeze, which is where it earns its place: a crash, where what was thrown is the first question anybody asks. On a freeze the log is still in the section below, unchanged. 262 tests pass.
Two conflicts, both where base and this branch added to the same place. AppApi.cs and the debug menu: base added the "Use dev.BloomLibrary.org" choice exactly where this branch added the "Run Freeze Doctor" toggle - the endpoint registration, the React state, the mount-effect read, the menu item and the useMemo deps. Independent features throughout; both kept. One of those needed more than keeping both sides. Base refactored the menu from `return [ ... ]` into `const items = [ ... ]` followed by a conditional push and `return items;`, so that it could add its item only on the builds that offer it. The merge had already taken base's opening line, which left this branch's items inside an array nothing returned. Resolved to base's structure, with the Freeze Doctor item where it was in the literal - so the array is built once, base's item is pushed when that build allows it, and the whole thing is returned. Typecheck clean, BloomExe builds, 262 Doctor tests pass on the merged tree.
Decision from the preflight report: leave it as it is. John's words - "we want to catch all the real freezes we can, including older Blooms that happen to be adopted." Written down next to the code because it reads like a bug and is not. A Doctor Bloom launched is not narrowed to the channel that started it, so once that Bloom has gone it will take up whatever other Bloom it finds - which is what you want when you restart Bloom after a freeze, and is also how a Doctor started by a development build came to adopt the BetaInternal install that happened to be running. That one is not a developer channel, so a genuine freeze in it would have been filed as a real card about work nobody asked us to watch. Accepted: a freeze noticed by accident is still a freeze we would otherwise never have heard about, which is the whole point of the tool. Also noted in the card's tester notes as expected behaviour, so a card about a Bloom that was not being deliberately tested is not filed as a mix-up. 262 tests pass.
John took apart the reasoning I had written for leaving it ungated, and he is right. The claim was that support may have had a user start a Doctor by hand with the setting off. Both support routes are covered without ungating: - told to switch the Doctor on and relaunch Bloom, the setting is on by the time Main runs; - told to start a Doctor while Bloom is already running, Main has long since finished and it is the Doctor's own sweep that finds Bloom. What ungating actually bought was at most one poll interval - five seconds - in the narrow case of a Doctor left running while the setting is off. Against that it ran a line in the startup of every user who has never switched the feature on. That is a bad trade, and I made it on a scenario that does not hold. Also moved from the top of Main to just after CheckForCorruptUserConfig, because it now reads a setting and that call is what makes reading one safe. The cost is microseconds and it is still far earlier than the 6.2 seconds measured when the announcement lived down beside the launcher. Verified with a Doctor already running: Bloom started at 09:41:10.244, the Doctor logged "a Bloom has just started and said so" and adopted it within the same second. 262 Doctor tests pass; BloomExe builds.
|
Too many files changed for review (110 files, 100 file limit). Bypass the limit by tagging |
Problem
Users tell us 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 holds only what Bloom managed to write before it stopped responding. Three quite different failures arrive looking identical — the UI stops responding; Bloom exits without reporting anything; or Bloom's window is gone while the process lives on, so the user cannot start Bloom again. 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.
The measurement the whole design rests on — check this first if you check one thing: a WinForms UI thread blocked in a managed wait on an STA thread still dispatches sent messages, 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.WM_TIMERis not dispatched, which is why detection rests on a UI-thread timer heartbeat published through shared memory, and not on either API that looks built for the job.What this PR does
Adds a companion Windows app — the Freeze Doctor, four projects in this repository — and teaches Bloom to publish enough about itself that the Doctor can tell it has stopped and say something useful about why.
Bloom's side:
Log.txteach run and falls back to a random name only when another Bloom holds it, so guessing from outside picks the wrong file in exactly the restart-after-a-freeze case); in-flight API requests and which lock each is waiting on; and long-operation scopes at the half-dozen places Bloom legitimately stops answering for minutes, which raise the freeze threshold rather than letting a publish look like a freeze.Main, so a Doctor already running adopts it at once rather than at its next sweep. Everything before that announcement is time in which a hang or a crash cannot be doctored at all, because Bloom only asks for a crash dump when a Doctor is already watching. For the users who have never switched the Doctor on it costs one setting read.The Doctor's side: it is already running when the trouble starts, gathers what can only be gathered at that instant, and files a YouTrack card by itself.
It ships inside Bloom's installer with no installer of its own, and is off by default, switched on from the debug menu on the Collections tab.
Ref: https://issues.bloomlibrary.org/youtrack/issue/BL-16719
Devin review
This change is