From 04b1ef3e04dcdd603ebc89a6c811e24deb0b2f25 Mon Sep 17 00:00:00 2001 From: serversdown Date: Fri, 25 Sep 2026 13:07:12 -0400 Subject: [PATCH] docs(series4): REPRODUCED -- THOR stops polling after a drop mid-download The field failure on UM12947 ("wouldn't stay connected, refresh did nothing, no way to view a connection attempt") reproduced on the bench, with timestamps. THOR was mid-bulk-download when the link was faulted. Sequence: 13:02:50 connection dies mid-transfer (165 BULK_DOWNLOAD frames in) 13:03:10 THOR reconnects once after 20 s, sends SUB_1F to resume, fails 13:03:33 link fully restored and healthy 13:04:21 operator clicks Refresh -> full 11-command check, all correct 13:06:27 still nothing. That refresh is the ONLY connection since 13:03:10. Before the fault THOR had connected every 30 s without a miss for over an hour. Establishes four things: * one retry then give up -- no backoff, no further attempts * the automatic poll loop dies too, not just the download * it does not recover when the link returns (3 min of healthy link, nothing) * Refresh works but only once -- it does NOT restart the automatic loop The fourth is the dangerous one: Refresh makes the UI report a healthy unit while nothing is watching it. Silent failure that looks like success. It also explains why the field symptom resists characterisation -- the unit is reachable the whole time; THOR has simply stopped asking and says nothing about it. CAVEAT, recorded prominently: what THOR experienced was a TCP close mid-download, not the silent link intended. mm_link.py mistook socket.timeout (which subclasses OSError) for a closed socket, so 200 ms of quiet closed the connection -- the relay killed the link it was meant to be faking a fault on. Fixed in this commit. The run stands as a drop-mid-download test, arguably the more realistic case. Single trial; true blackhole and clean drop not yet tested. Adds four design consequences for SFM: unbounded retry with backoff; a manual check must restart the automatic loop or the UI must say it is stopped; surface the poll loop's own state (last success, last attempt, next attempt, consecutive failures -- all four invisible here); and distinguish "unit unreachable" from "we stopped checking", which present identically in THOR. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01Ru8Lg9HkkYvX9VWWo65SmL --- bridges/mm_link.py | 10 +++- docs/micromate_protocol_reference.md | 80 ++++++++++++++++++++++++++++ 2 files changed, 89 insertions(+), 1 deletion(-) diff --git a/bridges/mm_link.py b/bridges/mm_link.py index a1724d2..8a72bfc 100644 --- a/bridges/mm_link.py +++ b/bridges/mm_link.py @@ -236,11 +236,19 @@ class Link: arrow = "THOR->unit" if is_request else "unit->THOR" last = time.time() while not stop.is_set(): + timed_out = False try: data = src.recv(4096) if isinstance(src, socket.socket) else src.read(4096) + except TimeoutError: + timed_out = True + # socket.timeout subclasses OSError, so it MUST be caught first. + # Treating it as a dead socket closes the connection after 200 ms + # of quiet -- which is exactly what `blackhole` produces, so the + # relay killed the link it was supposed to be faking a fault on. + data = b"" except OSError: break - if isinstance(src, socket.socket) and data == b"": + if isinstance(src, socket.socket) and data == b"" and not timed_out: self.say(f"{arrow}: peer closed the connection") break if not data: diff --git a/docs/micromate_protocol_reference.md b/docs/micromate_protocol_reference.md index 5901d1f..f058996 100644 --- a/docs/micromate_protocol_reference.md +++ b/docs/micromate_protocol_reference.md @@ -1758,6 +1758,86 @@ Three things this argues for, all cheap: 3. **Bound every operation with its own timeout**, independent of TCP's. Do not rely on the socket to report a dead peer. +## Reproduced: THOR stops polling after a connection drops mid-download + +**2026-09-25, one trial, on the bench link.** This is the failure the operator +described in the field on UM12947 — *"just wouldn't stay connected… clicking the +little refresh button did nothing… no way to view the status of a connection +attempt."* + +### What was done + +THOR was downloading events. Partway through the bulk transfer the link was +faulted, the connection died, and the link was then fully restored. + +⚠ **What THOR actually experienced was a TCP close mid-download**, not the silent +link that was intended — `mm_link.py` had a bug (`socket.timeout` subclasses +`OSError`, so 200 ms of quiet was mistaken for a closed socket). Fixed, but the +run stands as a **drop-mid-download** test, which is arguably the more realistic +case: a modem losing its tower often does produce a real close. + +### What happened + +``` +13:02:49.0 THOR connects, bulk download running (165 BULK_DOWNLOAD frames in) +13:02:50.0 link faulted -> connection dies mid-transfer +13:03:10.4 THOR reconnects once, 20 s later, sends SUB_1F (advance event + pointer) — an attempt to resume +13:03:10.8 that attempt dies too +13:03:33.3 link fully restored and healthy + ... 48 s of complete silence ... +13:04:21.4 operator clicks Refresh -> full 11-command check, every response + correct, unit perfectly healthy + ... 2 min 6 s of complete silence ... +13:06:27 still nothing. That refresh is the ONLY connection since 13:03:10. +``` + +Before the fault THOR was connecting every 30 s without a miss for over an hour. + +### What this establishes + +1. **One retry, then give up.** THOR retried once after 20 s and stopped. No + backoff, no further attempts. +2. **The automatic poll loop dies with it.** Not just the download — the 30 s + connection check and 60 s status check both stopped entirely. +3. **It does not recover when the link returns.** Three minutes of healthy link + produced zero connection attempts. +4. **Refresh works, but only once.** The manual check succeeded completely — + all eleven commands, correct responses. It did **not** restart the automatic + loop; two minutes later there was still nothing. + +⚠ **Point 4 is the dangerous one.** Refresh makes the UI report a healthy unit +while nothing is actually watching it. The operator sees a successful check and +moves on; the background loop stays dead. That is worse than a refresh button +that plainly fails, because the failure is *silent and looks like success*. + +It also explains why the field symptom is hard to characterise: the unit is +perfectly reachable the whole time. Poke it and it answers. Nothing is wrong +with the unit, the modem, or the link — THOR has simply stopped asking, and says +nothing about it. + +### Design consequences for SFM + +1. **Retry must be unbounded with backoff**, never one-and-done. A transient + link fault should not take a unit out of service until a human notices. +2. **A manual check must restart the automatic loop**, or the UI must state + clearly that automatic checking is stopped. A green tick that means "it + worked when you asked" is a trap. +3. **Surface the poll loop's own state** — last successful check, last attempt, + next scheduled attempt, consecutive failures. All four were invisible here, + and every one of them would have made this diagnosable in seconds. +4. **Distinguish "unit unreachable" from "we stopped checking."** They present + identically in THOR and have completely different causes and fixes. + +### Caveats + +- **One trial.** Not yet repeated, and not yet tried with a true silent link + (`blackhole` with the fixed tool) or with a clean `drop`. +- THOR's UI state during the dead window was not recorded — worth capturing on a + repeat, since what the operator *sees* is half the problem. +- Whether a THOR restart is required, or whether it eventually recovers on a + longer timescale, was not tested. + ## Thor's conventions vs the protocol's requirements **SFM is not meant to reimplement Thor.** Thor is the only available teacher of