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