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 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Ru8Lg9HkkYvX9VWWo65SmL
This commit is contained in:
2026-09-25 14:13:36 -04:00
co-authored by Claude Opus 5
parent 992b84df51
commit a404d70791
+78
View File
@@ -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