From a404d7079115126d29ca88850410fc1b030ff996 Mon Sep 17 00:00:00 2001 From: serversdown Date: Fri, 25 Sep 2026 14:13:36 -0400 Subject: [PATCH] docs(series4): THOR leaks event subscriptions -- evidence from its own log The office THOR PC's log for 2026-09-22 contains a textbook WPF defect, visible without any instrumentation. 85% of a day's logging is one message: "UnitOperatingModeViewModel - Start/stop monitoring request timed out: False", 178 of 209 lines. Only 12 lines describe an actual operation. Grouping that message by exact timestamp to the millisecond -- so each group is ONE logical event -- the count per event grows over the day: 11:48 1-4 13:36-13:40 2-4 15:16 3 16:03-16:07 6 22:00-22:06 12 1 -> 12 over ten hours of uptime. Twelve identical lines sharing a single millisecond is not twelve events; it is one event dispatched to twelve handlers. That is a subscription leak, and the class name identifies it. THOR is .NET/WPF ("App thread", ViewModel naming), where a view model subscribing on view-open and never unsubscribing on view-close is the archetypal case. Consequences that follow directly: N grows without bound with uptime and usage; every notification does N times the work; and a restart resets N to 1 -- matching the operator's report that only restarting recovers a degraded session. The only five "timed out: True" entries in the file sit at the very top, an episode caught just before rotation. Claim discipline stated explicitly in the doc. ESTABLISHED: the handler count grows. STRONG INFERENCE: it is a subscription leak. NOT ESTABLISHED: that it caused the 2026-09-22 field outage -- this log does not cover that window and the link between leaked handlers and a dead TCP path is unproven. Includes a ten-minute confirmation procedure: restart THOR, note the burst size, open and close a unit detail view ten times, re-count. Three lessons for SFM: unsubscribe on teardown or use weak events; log once per event rather than once per handler; and log what CHANGED -- 178 "timed out: False" lines are noise that buried the five that mattered, which is plausibly why this went unnoticed. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01Ru8Lg9HkkYvX9VWWo65SmL --- docs/micromate_protocol_reference.md | 78 ++++++++++++++++++++++++++++ 1 file changed, 78 insertions(+) diff --git a/docs/micromate_protocol_reference.md b/docs/micromate_protocol_reference.md index 53e12b8..ce34348 100644 --- a/docs/micromate_protocol_reference.md +++ b/docs/micromate_protocol_reference.md @@ -1989,6 +1989,84 @@ useless as a staleness indicator precisely when staleness is the problem. - Whether a THOR restart is required, or whether it eventually recovers on a longer timescale, was not tested. +## THOR leaks event subscriptions — evidence from its own log + +Source: `thor.log.2026-09-22` from the office THOR PC, supplied 2026-09-25. +209 lines covering roughly ten hours. + +### What the log contains + +``` +178x UnitOperatingModeViewModel - Start/stop monitoring request timed out: False + 6x UnitOperatingModeViewModel - Callback of start/stop monitor request received + 5x UnitOperatingModeViewModel - Start/stop monitoring request timed out: True + 3x SchedulerViewModel - Retrieving unit setup ... + 2x BWLicenseManager - License State: IsKeyValid 0, IsActivated 0, ... +``` + +85% of a day's logging is one message. Only **12** lines describe an actual +operation. + +### The message is emitted N times for ONE event, and N grows + +Grouping the repeated message by **exact timestamp to the millisecond** — so +each group is one logical event, not repeated events: + +| time | identical lines | +|---|---| +| 11:48 | 1–4 | +| 13:05 – 13:31 | 1–2 | +| 13:36 – 13:40 | 2–4 | +| 15:16 | 3 | +| 16:03 – 16:07 | **6** | +| 16:14 – 16:16 | 4–6 | +| **22:00 – 22:06** | **12** | + +**1 → 12 over ten hours of uptime.** Twelve identical lines sharing one +millisecond timestamp is not twelve events; it is one event dispatched to twelve +handlers. + +### What it is + +A **subscription leak**, and the class name identifies it: +`UnitOperatingModeViewModel`. THOR is a .NET/WPF application ("App thread", +ViewModel naming), where this is the archetypal leak — a view model subscribes to +an event when its view opens and never unsubscribes when the view closes. Each +open adds a live handler; every later notification runs them all. + +Consequences that follow directly: + +- N grows with **uptime and usage**, without bound. Ten hours of moderate use + reached 12×; a THOR left running for days across a fleet will be far worse. +- Every notification performs N× the work — N timers, N callbacks, N state + updates racing one another. +- **A restart resets N to 1**, which is consistent with the operator's report + that only restarting THOR recovers a degraded session. +- The only `timed out: True` entries in the file — five of them — sit at the very + top, an episode captured just before log rotation. + +⚠ **Claim discipline.** *Established* from this log: the handler count grows. +*Strong inference*: it is a subscription leak. **Not established**: that it +caused the specific field outage on 2026-09-22. This log does not cover that +window, and the connection between leaked handlers and a dead TCP path is +unproven. + +### How to confirm it in ten minutes + +Restart THOR, note the burst size for one event, open and close a unit's detail +view ten times, then trigger another event and re-count. If the burst grows, the +leak is reproducible and attributable to a specific UI action. + +### For SFM + +1. **Unsubscribe on teardown**, or use weak event patterns. This is the single + most common long-running-UI defect and it is entirely preventable. +2. **Log once per event, not once per handler.** The duplication here is what + made the leak visible, which is lucky — but a log that is 85% one repeated + line is also a log nobody reads, which is why this went unnoticed for a year. +3. **Log what changed, not what did not.** `timed out: False` 178 times is + noise; the five `True` entries are the signal, and they are buried. + ## Thor's conventions vs the protocol's requirements **SFM is not meant to reimplement Thor.** Thor is the only available teacher of