From 7fbdbfea029c5956cf9d1f81993f9bb3ae6b56f5 Mon Sep 17 00:00:00 2001 From: ryanbr Date: Sun, 2 Aug 2026 10:44:58 -0700 Subject: [PATCH] Stop a connection bug from invalidating its own capture, and tag the fifth teardown route (#1040) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit #1040 is a WHOOP MG reconnect loop: 816 reconnects, status 22, ~3s of uptime each. Three things in our own instrumentation made it harder to act on than it should be, plus one thing that made the report itself hard to read. The Connection capture reported itself INCOMPLETE. Its killer token `clockDrift ` is emitted from the strap-clock/history read, which a link that dies three seconds after every connect never reaches — so the worse the connection bug, the more certainly the Connection mode reads MISSING. #1040 arrived with a log full of [connection] lines and "INCOMPLETE: missing connection" stamped on exactly the report we wanted. `reconnect n=` now serves as the domain's evidence token. It is emitted under CONNECTION on BOTH sides of the wasConnected branch — after a link that came up and dropped, and as `failedConnect` when it never reached CONNECTED — so it is present precisely when the connection is broken, in either failure mode. Not `bondState` (the Swift twin's second token), which fires only on a COMPLETED encrypted bond and so would miss a loop whose bond never completes; and not `connect up gen=`, which would leave "never connects at all" reports still self-invalidating. A healthy session that never dropped and never synced still reads MISSING, unchanged: it records no connection problem to obstruct. The Capture-check tokens are now QUOTED. They are raw grep literals that end in `=` or a significant trailing space, so unquoted they rendered as dangling fragments — #1040's own export reads `connection: MISSING (expected clockDrift )`, which looks like a typo rather than a substring to search for. Naming the matched token is deliberate (#386); quoting makes it legible. No effect on the #950 self-poisoning guard, since the bare token still occurs inside the quotes. readoptWorkingStrap tore the link down without calling noteLocalTeardown, so the multi-WHOOP re-adopt was the one local route that printed `via=unknown` — which the reason doc already describes as meaning a teardown path exists that is not tagged. It now reads `via=readopt` instead of being indistinguishable from a bond-watchdog bounce. connectAttemptStartedAtMs was stamped only in connect(), which the auto-reconnect path never calls, so latencyMs was measured from the original user-initiated connect and grew without bound: #1040 reported latencyMs=7847081 (2.18 h) for a link that came up 6 seconds after the previous drop. Stamping in connectToDevice — the single funnel every connect passes through — makes it per-attempt. Latency is now GATT-attempt time and no longer includes scan time on the first connect. Diagnostics only: no connection behaviour, no protocol and no stored data changes. --- .../main/java/com/noop/ble/WhoopBleClient.kt | 17 ++++- .../com/noop/testcentre/ReportCompleteness.kt | 36 +++++++++- .../ReportCompletenessParityTest.kt | 67 ++++++++++++++++--- 3 files changed, 106 insertions(+), 14 deletions(-) diff --git a/android/app/src/main/java/com/noop/ble/WhoopBleClient.kt b/android/app/src/main/java/com/noop/ble/WhoopBleClient.kt index 4bd31428e8..99bccc8478 100644 --- a/android/app/src/main/java/com/noop/ble/WhoopBleClient.kt +++ b/android/app/src/main/java/com/noop/ble/WhoopBleClient.kt @@ -2436,9 +2436,6 @@ class WhoopBleClient( @SuppressLint("MissingPermission") fun connect(model: WhoopModel = WhoopModel.WHOOP4) { intentionalDisconnect = false - // Connection test mode: stamp when this connect attempt began so onConnectionStateChange can report - // the connect latency. A plain timestamp, no behaviour change; only read behind the CONNECTION gate. - connectAttemptStartedAtMs = System.currentTimeMillis() // PR #588: an explicit user-driven Connect is never an out-of-range retry — clear the involuntary- // reconnect streak so this scan (and any reconnects it spawns) starts back at the snappy // LOW_LATENCY scan mode + the 3s backoff base, never inheriting a backed-off lower-power scan. @@ -4299,6 +4296,11 @@ class WhoopBleClient( // connect — onScanResult (pin now null) connects to the working strap when it advertises. resetReconnectBackoff() // a deliberate re-adopt, not an out-of-range retry — start fresh intentionalDisconnect = false + // #1040: the FIFTH local-teardown route, and the only one that was never stamped — so the status-22 + // drop it causes printed `via=unknown`, which the reason doc calls out as meaning exactly this: a + // teardown path that exists and is not tagged. A multi-WHOOP re-adopt looks identical in the trace + // to a bond-watchdog bounce without it. + noteLocalTeardown("readopt") // #1020 try { gatt?.disconnect() // drop the dead-pin link → handleDisconnect → rescan (pin cleared) } catch (t: Throwable) { @@ -4414,6 +4416,15 @@ class WhoopBleClient( // Close any prior/pending GATT so a direct-reconnect attempt doesn't leak the old client. // close() can throw on a dead binder (#314); swallow it — we're replacing the handle anyway. try { gatt?.close() } catch (t: Throwable) { log("prior gatt.close() threw ${t.javaClass.simpleName} (ignored)") } + // Connection test mode: stamp when THIS GATT attempt began, so onConnectionStateChange reports the + // latency of the attempt that just succeeded. Stamped here rather than in connect() (#1040): the + // auto-reconnect path never calls connect(), so the mark went stale and `latencyMs` was measured + // from the original user-initiated connect — #1040 reported latencyMs=7847081 (2.18 h) for a link + // that came up 6 seconds after the previous drop, and it grows without bound the longer a reconnect + // loop runs. connectToDevice is the single funnel every connect passes through, so every attempt + // now gets a fresh mark. Latency is therefore GATT-attempt time, no longer including scan time on + // the first connect. A plain timestamp; only read behind the CONNECTION gate. + connectAttemptStartedAtMs = System.currentTimeMillis() // autoConnect=false → a fast, direct connect (CoreBluetooth central.connect default), used for // the scan-discovered first connect. autoConnect=true → the OS reconnects whenever the bonded // strap is reachable WITHOUT needing an advertisement (used by the dropout auto-reconnect, #61). diff --git a/android/app/src/main/java/com/noop/testcentre/ReportCompleteness.kt b/android/app/src/main/java/com/noop/testcentre/ReportCompleteness.kt index 52f8f48b03..07a80cdffd 100644 --- a/android/app/src/main/java/com/noop/testcentre/ReportCompleteness.kt +++ b/android/app/src/main/java/com/noop/testcentre/ReportCompleteness.kt @@ -67,6 +67,29 @@ object ReportCompleteness { */ val evidenceTokens: Map = linkedMapOf( TestDomain.SLEEP to "sleep day=", + // #1040: CONNECTION's killer token `clockDrift ` is emitted from the strap-clock/history read, so a + // connection that never stays up long enough to reach that read cannot produce it — i.e. the worse + // the connection bug, the more certainly the Connection capture reads MISSING. #1040 arrived with + // 816 reconnects, a log full of `[connection] connect up/down` lines, and `INCOMPLETE: missing + // connection` stamped on it, which reads as an unusable capture when it is in fact the report we + // want. `reconnect n=` is the token that survives every way a connection can fail: it is emitted + // under TestDomain.CONNECTION on BOTH sides of the wasConnected branch — `reconnect n= + // reason=<…>` after a link that came up and dropped, and `reconnect n= failedConnect reason=<…>` + // when it never reached CONNECTED at all. So it is present precisely when the connection is broken, + // in either failure mode. + // + // Deliberately NOT `bondState`, the Swift twin's second token + // (`CaptureCompleteness.tokens[.connection] == ["clockDrift", "bondState"]`): that fires from only + // two sites, both on a COMPLETED encrypted bond, so a loop whose bond never completes — a prime + // suspect for a ~3 s bounce — would not emit it and the capture would still read MISSING. Nor + // `connect up gen=`, which covers a link that comes up and drops but NOT one that never connects, + // leaving a whole failure mode still self-invalidating. Swift wants the same widening; tracked with + // #1040 rather than diverging its map from here. + // + // Residual, accepted: a HEALTHY session that never dropped and never synced history has neither + // token. That capture reads MISSING as it always has — but it records no connection problem, so it + // is not a bug report being obstructed, which is what this rescue exists to prevent. + TestDomain.CONNECTION to "reconnect n=", // #141: the NIGHTLY HRV trace proves the HRV mode captured, even when the user never took a manual // (spot) reading — `hrv rmssd=` only fires on the Live-screen snapshot, but the overnight per-window // trace emits `hrv nightSummary …`. So a wear-overnight-and-export HRV capture reads complete. @@ -112,10 +135,17 @@ object ReportCompleteness { sb.append("=== Capture check ===") for ((d, status) in statuses) { val matched = matchedToken(reportText, d) + // #1040: QUOTE the token. These are raw grep literals — they end in `=` or a significant + // trailing space (`clockDrift `), so unquoted they render as a dangling fragment: a real + // report read `connection: MISSING (expected clockDrift )`, and an evidence match would read + // `present (via reconnect n=)`. Quoting makes it unambiguous that the text IS the substring to + // search for, which is the whole point of naming it (#386). Does not affect the #950 + // self-poisoning guard: the bare token still occurs inside the quotes, so the assembler must + // keep passing the PRE-append body either way. val label = when { - status == Status.MISSING -> "expected ${killerTokens[d]}" - matched == killerTokens[d] -> matched - else -> "via $matched" + status == Status.MISSING -> "expected \"${killerTokens[d]}\"" + matched == killerTokens[d] -> "\"$matched\"" + else -> "via \"$matched\"" } sb.append('\n') .append(d.id).append(": ").append(status.token) diff --git a/android/app/src/test/java/com/noop/testcentre/ReportCompletenessParityTest.kt b/android/app/src/test/java/com/noop/testcentre/ReportCompletenessParityTest.kt index b048eded5e..1c5f69ef9b 100644 --- a/android/app/src/test/java/com/noop/testcentre/ReportCompletenessParityTest.kt +++ b/android/app/src/test/java/com/noop/testcentre/ReportCompletenessParityTest.kt @@ -81,7 +81,58 @@ class ReportCompletenessParityTest { // the absent killer trace — `present (gate run=)` over an evidence-only match sent a maintainer // hunting for gate lines the report never contained. assertTrue("an evidence-only match must be labelled `via `", - section.contains("sleep: present (via sleep day=)")) + section.contains("sleep: present (via \"sleep day=\")")) + } + + @Test fun connectionIsPresentFromConnectChurnWhenTheLinkNeverReachesTheClockRead() { + // #1040, reproduced verbatim: CONNECTION's killer token `clockDrift ` is emitted from the strap-clock + // read, which a link that dies ~3 s after every connect never reaches. So the WORSE the connection + // bug, the more certainly its own capture reads MISSING — the report arrived with 816 reconnects, a + // log full of `[connection]` lines, and `INCOMPLETE: missing connection` stamped on exactly the + // capture we needed. + // + // No `bondState` in this fixture ON PURPOSE: that line only fires on a COMPLETED encrypted bond, so + // a loop whose bond never completes wouldn't emit it and the rescue would not fire. + val report = buildString { + appendLine("dayOwner day=2026-08-02 readId=whoop-D0 writeActiveId=whoop-D0 hrRows=2439 provenance=measured") + appendLine("[connection] connect up gen=852 latencyMs=6120 uptimeStart=1785663906") + appendLine("[connection] connect down (uptime ends after 3.0s)") + appendLine("[connection] reconnect n=816 reason=localTerminate via=bondWatchdog") + // NOTE: neither `clockDrift ` nor `bondState` — the link never got far enough for either. + } + val s = ReportCompleteness.statuses(report, active = setOf(TestDomain.CONNECTION)) + assertEquals(ReportCompleteness.Status.PRESENT, s[TestDomain.CONNECTION]) + val section = ReportCompleteness.captureCheckSection(report, active = setOf(TestDomain.CONNECTION)) + assertTrue("a reconnect-loop capture must read complete, not INCOMPLETE", + section.endsWith("complete: all active traces present")) + assertTrue("an evidence-only match must be labelled `via `", + section.contains("connection: present (via \"reconnect n=\")")) + } + + @Test fun connectionIsPresentWhenTheLinkNEVERConnectsAtAll() { + // The other half of the same bug class, and the reason the token is `reconnect n=` rather than + // `connect up gen=`: a strap that never reaches CONNECTED emits ONLY the failedConnect branch, so a + // token keyed on a successful connect-up would leave "can't connect at all" reports still stamped + // INCOMPLETE — a connection failure invalidating its own capture, exactly what #1040 was about. + val report = buildString { + appendLine("dayOwner day=2026-08-02 readId=my-whoop writeActiveId=my-whoop hrRows=0 provenance=measured") + appendLine("[connection] reconnect n=42 failedConnect reason=connectionTimeout") + // NOTE: no `connect up gen=` — the link never came up even once. + } + val s = ReportCompleteness.statuses(report, active = setOf(TestDomain.CONNECTION)) + assertEquals(ReportCompleteness.Status.PRESENT, s[TestDomain.CONNECTION]) + assertTrue(ReportCompleteness.captureCheckSection(report, active = setOf(TestDomain.CONNECTION)) + .endsWith("complete: all active traces present")) + } + + @Test fun connectionStillPrefersTheClockDriftKillerTraceWhenItIsPresent() { + // The churn line is the rescue path, not a replacement: a capture that DID reach the strap-clock read + // must still name the deeper trace, so `via` continues to mean "the killer trace is genuinely absent". + val both = "clockDrift newest=2026-08-02 wall=2026-08-02 ok\nreconnect n=3 reason=connectionTimeout" + assertEquals("clockDrift ", ReportCompleteness.matchedToken(both, TestDomain.CONNECTION)) + assertEquals("reconnect n=", + ReportCompleteness.matchedToken("reconnect n=3 reason=connectionTimeout", TestDomain.CONNECTION)) + assertEquals(null, ReportCompleteness.matchedToken("no connection traces here", TestDomain.CONNECTION)) } @Test fun matchedTokenPrefersTheKillerTraceOverTheEvidenceLine() { @@ -107,8 +158,8 @@ class ReportCompletenessParityTest { val section = ReportCompleteness.captureCheckSection(report, active = setOf(TestDomain.SLEEP)) assertEquals( "=== Capture check ===\n" + - "universal: present (dayOwner day=)\n" + - "sleep: present (gate run=)\n" + + "universal: present (\"dayOwner day=\")\n" + + "sleep: present (\"gate run=\")\n" + "complete: all active traces present", section, ) @@ -117,7 +168,7 @@ class ReportCompletenessParityTest { /** * #950 — the capture check must not read its OWN output as evidence. * - * The section renders a missing domain as `: MISSING (expected )`, and that line + * The section renders a missing domain as `: MISSING (expected \"\")`, and that line * contains the killer token. meta.json's capture_check was computed over report.txt AFTER the section * was appended, so the re-scan found the token inside its own "expected …" text and recorded the * domain as present. Every missing trace flipped and `complete` went true while report.txt said @@ -156,9 +207,9 @@ class ReportCompletenessParityTest { ) assertEquals( "=== Capture check ===\n" + - "universal: present (dayOwner day=)\n" + - "sleep: MISSING (expected gate run=)\n" + - "connection: MISSING (expected clockDrift )\n" + + "universal: present (\"dayOwner day=\")\n" + + "sleep: MISSING (expected \"gate run=\")\n" + + "connection: MISSING (expected \"clockDrift \")\n" + "INCOMPLETE: missing sleep, connection", section, ) @@ -170,7 +221,7 @@ class ReportCompletenessParityTest { val section = ReportCompleteness.captureCheckSection("nothing here", active = emptySet()) assertEquals( "=== Capture check ===\n" + - "universal: MISSING (expected dayOwner day=)\n" + + "universal: MISSING (expected \"dayOwner day=\")\n" + "complete: all active traces present", section, )