diff --git a/Packages/StrandAnalytics/Sources/StrandAnalytics/ConnectionReadout.swift b/Packages/StrandAnalytics/Sources/StrandAnalytics/ConnectionReadout.swift index 7e06e1fa13..ab13b16bc6 100644 --- a/Packages/StrandAnalytics/Sources/StrandAnalytics/ConnectionReadout.swift +++ b/Packages/StrandAnalytics/Sources/StrandAnalytics/ConnectionReadout.swift @@ -13,6 +13,23 @@ import Foundation // counts, durations and ISO dates only. No em-dashes. The Kotlin twin is ConnectionReadout.kt. public enum ConnectionTrace { + /// The ` after s` suffix on a `connect down` trace line, or empty when the session start is + /// unknown (#1020). + /// + /// A session's length separates the causes of a drop at a glance: a bond watchdog fires seconds in, + /// a keep-alive stall bounce minutes in, a radio drop anywhere. The bare `connect down (uptime ends)` + /// could not distinguish them, which is why a report of thousands of reconnects needed a round trip + /// before anyone could start on it. + /// + /// An unknown start yields NO suffix rather than `after 0.0s` — "instant drop" and "we do not know" + /// are different diagnoses. Locale-fixed so a decimal comma cannot follow the phone language into a + /// log people paste into issues. Twin of the Kotlin `ConnectionTrace.sessionHeldSuffix`. + public static func sessionHeldSuffix(millis: Int) -> String { + guard millis >= 0 else { return "" } + return " after " + String(format: "%.1f", locale: Locale(identifier: "en_US_POSIX"), + Double(millis) / 1000.0) + "s" + } + /// The CLOCK-DRIFT summary line (#767 / #754 cluster): the strap-reported banked-record window /// [oldest, newest] against the wall clock, with a FUTURE-DATE flag when the strap's newest record is diff --git a/Packages/StrandAnalytics/Tests/StrandAnalyticsTests/ConnectionReadoutTests.swift b/Packages/StrandAnalytics/Tests/StrandAnalyticsTests/ConnectionReadoutTests.swift index be0f8d1853..e0465378f3 100644 --- a/Packages/StrandAnalytics/Tests/StrandAnalyticsTests/ConnectionReadoutTests.swift +++ b/Packages/StrandAnalytics/Tests/StrandAnalyticsTests/ConnectionReadoutTests.swift @@ -93,6 +93,17 @@ final class ConnectionReadoutTests: XCTestCase { XCTAssertEqual(ConnectionReadout.uptimeLabel(taggedTail: tail, nowUnix: 5000), "not connected") } + /// #1020: the emitter appends a session duration, so the line the parser actually receives is no + /// longer the bare one above. Pinned because the two are edited independently — the suffix was added + /// on the strength of this match being a `contains`, and nothing was asserting that. + func testUptimeLabelDownWithASessionDuration() { + let tail = [ + "[connection] connect up gen=1 latencyMs=420 uptimeStart=1000", + "[connection] connect down (uptime ends after 6.8s)", + ] + XCTAssertEqual(ConnectionReadout.uptimeLabel(taggedTail: tail, nowUnix: 5000), "not connected") + } + func testUptimeLabelEmptyTail() { XCTAssertEqual(ConnectionReadout.uptimeLabel(taggedTail: [], nowUnix: 5000), "not connected") } diff --git a/Packages/StrandAnalytics/Tests/StrandAnalyticsTests/SessionHeldSuffixTests.swift b/Packages/StrandAnalytics/Tests/StrandAnalyticsTests/SessionHeldSuffixTests.swift new file mode 100644 index 0000000000..5bc4da1f87 --- /dev/null +++ b/Packages/StrandAnalytics/Tests/StrandAnalyticsTests/SessionHeldSuffixTests.swift @@ -0,0 +1,31 @@ +import XCTest +@testable import StrandAnalytics + +/// #1020 — the ` after s` suffix on a `connect down` trace line. Twin of the Kotlin +/// `ConnectionDownReasonTest`'s duration cases; the same inputs, because a log pasted into an issue must +/// read the same whichever platform wrote it. +/// +/// The reason this exists: a report of thousands of reconnects arrived with a log whose every drop read +/// `connect down (uptime ends)`. Nothing in that line said whether the sessions lasted seconds or +/// minutes, which is the first split between a bond watchdog firing and a radio-side drop, so the issue +/// needed a round trip before anyone could start on it. +final class SessionHeldSuffixTests: XCTestCase { + + /// The ordinary case, to a tenth: enough to separate a watchdog from a stall, no false precision. + func testAHeldSessionReportsItsLengthToATenth() { + XCTAssertEqual(ConnectionTrace.sessionHeldSuffix(millis: 6_800), " after 6.8s") + XCTAssertEqual(ConnectionTrace.sessionHeldSuffix(millis: 120_000), " after 120.0s") + XCTAssertEqual(ConnectionTrace.sessionHeldSuffix(millis: 432), " after 0.4s") + } + + /// An unknown start yields NO suffix rather than `after 0.0s` — "dropped instantly" and "we do not + /// know when it came up" are different diagnoses and must not render alike. + func testAnUnknownStartAddsNothing() { + XCTAssertEqual(ConnectionTrace.sessionHeldSuffix(millis: -1), "") + } + + /// A genuine instant drop is still reported: zero is a measurement, unlike the negative sentinel. + func testAnInstantDropIsStillReported() { + XCTAssertEqual(ConnectionTrace.sessionHeldSuffix(millis: 0), " after 0.0s") + } +} diff --git a/Strand/BLE/BLEManager.swift b/Strand/BLE/BLEManager.swift index 927706e0db..52170a224a 100644 --- a/Strand/BLE/BLEManager.swift +++ b/Strand/BLE/BLEManager.swift @@ -618,6 +618,16 @@ public final class BLEManager: NSObject, ObservableObject { /// Count of INVOLUNTARY reconnects this run (a drop or failed-connect that was not user-initiated), /// surfaced as the reconnect-churn count. Reset by an intentional disconnect. private var connReconnectCount = 0 + /// When the current session reached connected, for the `connect down` duration readout (#1020). + /// A session's length separates the causes of a drop at a glance — a bond watchdog fires seconds + /// in, a stall bounce minutes in, a radio drop anywhere. + /// + /// Set on EVERY connect, not only when the connection test mode is active: the mode is usually + /// switched on after something already looks wrong, so a stamp taken under the gate would carry a + /// previous session's start. Never cleared on the way down, so read it only where a session is known + /// to have been held (`didDisconnectPeripheral`, which fires only for a peripheral that connected). + /// Android twin: `WhoopBleClient.connectedAtMs`. + private var connSessionStartedAt: Date? /// #126 false-alarm guard: tracks CONSECUTIVE console-only completed syncs so the "clock has lost /// sync" banner only fires on sustained emptiness, not a single transient empty cycle on a healthy strap. private var emptySyncTracker = EmptySyncTracker() @@ -3918,6 +3928,11 @@ extension BLEManager: @preconcurrency CBCentralManagerDelegate { } lastDataAt = Date() log("Connected — discovering services") + // #1020: stamped OUTSIDE the gate below. Test Centre is usually switched on AFTER something looks + // wrong, so a stamp taken only when the mode happened to be on at connect time would either be + // missing or, worse, still hold a PREVIOUS session's start - reporting a duration that spans the + // gap between them. A field assignment, not a log line, so it costs nothing when the mode is off. + connSessionStartedAt = Date() // Connection test mode: report the connect latency + the uptime-start marker the readout reads. // Gated zero-cost: the .connection bool is read before any string is built, so this is a no-op // when the mode is off. Behaviour-neutral diagnostics only - the connect flow above is unchanged. @@ -4103,7 +4118,11 @@ extension BLEManager: @preconcurrency CBCentralManagerDelegate { if TestCentre.active(.connection) { let reason = (error as? CBError)?.code == .connectionTimeout ? "connectionTimeout" : connErrorToken(error) - state.append(log: "connect down (uptime ends)", domain: .connection) + // #1020: the session's length separates the causes of a drop at a glance. Same suffix the + // Android twin emits, so the shared ConnectionReadout parser sees one format. + let held = ConnectionTrace.sessionHeldSuffix( + millis: connSessionStartedAt.map { Int(Date().timeIntervalSince($0) * 1000) } ?? -1) + state.append(log: "connect down (uptime ends\(held))", domain: .connection) state.append(log: "reconnect n=\(connReconnectCount) reason=\(reason)", domain: .connection) } DispatchQueue.main.asyncAfter(deadline: .now() + 3) { [weak self] in diff --git a/android/app/src/main/java/com/noop/analytics/ConnectionReadout.kt b/android/app/src/main/java/com/noop/analytics/ConnectionReadout.kt index 6246889829..2fdfd976de 100644 --- a/android/app/src/main/java/com/noop/analytics/ConnectionReadout.kt +++ b/android/app/src/main/java/com/noop/analytics/ConnectionReadout.kt @@ -12,6 +12,22 @@ import java.util.TimeZone // Swift line shapes so a shared report reads identically on either platform. object ConnectionTrace { + /** + * The ` after s` suffix on a `connect down` trace line, or empty when the session start is + * unknown (#1020). + * + * A session's length separates the causes of a drop at a glance: a bond watchdog fires seconds in, a + * keep-alive stall bounce minutes in, a radio drop anywhere. The bare `connect down (uptime ends)` + * could not distinguish them, which is why a report of thousands of reconnects needed a round trip + * before anyone could start on it. + * + * An unknown start yields NO suffix rather than `after 0.0s` — "instant drop" and "we do not know" + * are different diagnoses. Locale-fixed so a decimal comma cannot follow the phone language into a + * log people paste into issues. Twin of the Swift `ConnectionTrace.sessionHeldSuffix`. + */ + fun sessionHeldSuffix(millis: Long): String = + if (millis < 0L) "" else " after ${"%.1f".format(java.util.Locale.US, millis / 1000.0)}s" + /** * The CLOCK-DRIFT summary line (#767 / #754 cluster): the strap-reported banked-record window 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 d87153f0ed..c980ed8c6d 100644 --- a/android/app/src/main/java/com/noop/ble/WhoopBleClient.kt +++ b/android/app/src/main/java/com/noop/ble/WhoopBleClient.kt @@ -538,6 +538,21 @@ class WhoopBleClient( else -> BluetoothGatt.CONNECTION_PRIORITY_BALANCED } + /** + * The `reason=` token for a connection-down trace line (#1020), pure so the composition is + * unit-testable without a BLE stack. + * + * A local teardown arrives as GATT status 22 and used to print the bare `localTerminate`, which + * five different paths of ours produce. [localTeardownOrigin] names which one; `unknown` when the + * drop was local but no path claimed it, which is itself worth seeing — it means a teardown route + * exists that is not tagged. + */ + fun connectionDownReason(status: Int, localTeardownOrigin: String?): String = when (status) { + GATT_CONN_TIMEOUT -> "connectionTimeout" + GATT_CONN_TERMINATE_LOCAL_HOST -> "localTerminate via=${localTeardownOrigin ?: "unknown"}" + else -> "status$status" + } + /** Pure battery-adaptive gate (#477), unit-testable without a BLE stack. Keyed on the STRAP's * battery (WHOOP/Oura/Fitbit): the lever is ARMED by [thresholdPct] > 0 (the Settings slider is * 10–30; 0 disables it) and engages while the strap is DISCHARGING at/below [thresholdPct]. The @@ -2515,6 +2530,7 @@ class WhoopBleClient( */ @SuppressLint("MissingPermission") fun disconnect() { + noteLocalTeardown("userDisconnect") // #1020 intentionalDisconnect = true handler.removeCallbacks(scanTimeoutRunnable) // #1030 (ryanbr): a user teardown supersedes any pending involuntary reconnect timer. @@ -2668,6 +2684,7 @@ class WhoopBleClient( * `BLEManager.forgetDevice` (which iOS already wires from DevicesView's Remove). Runs on the main looper. */ fun releaseStrap() { + noteLocalTeardown("releaseStrap") // #1020 handler.post { intentionalDisconnect = true // defuse the disconnect→3s-reconnect loop's guard handler.removeCallbacks(scanTimeoutRunnable) @@ -3971,6 +3988,35 @@ class WhoopBleClient( * nag the user. Reset to 0 on any genuine bond. (5/MG firmware reset parity, 2026-06) */ private var staleDirectFailures = 0 + /** + * Which of OUR OWN paths last tore the link down, and when the current session started (#1020). + * + * A local teardown surfaces as GATT status 22 (`GATT_CONN_TERMINATE_LOCAL_HOST`), which the + * connection trace has always reported as the bare `reason=localTerminate`. At least five paths + * produce it — the bond watchdog, the keep-alive stall bounce, a user disconnect, releaseStrap, and + * a safeGatt teardown after a dead binder — and the log could not tell them apart. A report showing + * thousands of localTerminate reconnects (#1020) therefore could not be diagnosed from the log at + * all; the existing comment beside the reason string just guesses ("e.g. #971 bond watchdog"). + * + * Set at each initiating site, cleared when a new session comes up, and printed alongside the + * reason. @Volatile because the setters run on the main looper and timer callbacks while + * handleDisconnect reads it from a GATT binder thread on API 26/27. + */ + @Volatile private var lastLocalTeardown: String? = null + + /** Wall clock when the current session reached STATE_CONNECTED, for the session-duration readout. + * 0 until the first connect; set on EVERY connect (not gated on the test mode, which is usually + * switched on only after something looks wrong) and never cleared on the way down, so read it only + * under a `wasConnected` guard. @Volatile for the same reason as [lastLocalTeardown]. */ + @Volatile private var connectedAtMs = 0L + + /** Record which local path is about to drop the link. Unconditional rather than gated on the test + * mode, because the clear in the connect path is ungated too - gating one and not the other is what + * let a previous session's origin survive. Four of the five call sites pass a literal; `safeGatt` + * interpolates the failing op, but that is an exception path where a String allocation is noise + * against the teardown it is about to perform. None of the five is on a per-record path. */ + private fun noteLocalTeardown(origin: String) { lastLocalTeardown = origin } + /** Consecutive involuntary reconnect attempts, feeding the capped-exponential [ReconnectBackoff] * (3, 6, 12, 24, 48, 60s…). Replaces the old fixed [RECONNECT_DELAY_MS] rescan loop so a strap * that's genuinely out of range stops hammering BLE — the Android twin of the iOS @@ -4097,6 +4143,7 @@ class WhoopBleClient( // through to a clean teardown if it does (mirrors the keep-alive bounce). When we gave up above, // [handleDisconnect] takes its paused branch and schedules NO reconnect; otherwise it backoff- // reconnects and [armBondWatchdog] arms the NEXT (wider) window from [bondWatchdogBackoff]. + noteLocalTeardown("bondWatchdog") // #1020: name the origin of the localTerminate that follows try { gatt?.disconnect() // → handleDisconnect → reset() (cancels this) → (paused | backoff reconnect) } catch (t: Throwable) { @@ -4418,6 +4465,13 @@ class WhoopBleClient( // Connection test mode: report the connect latency + the uptime-start marker the readout // reads. Gated zero-cost (the CONNECTION bool is read before any string is built). // Behaviour-neutral diagnostics only - the connect flow below is unchanged. Twin of macOS. + // #1020: both stamped OUTSIDE the gate. Test Centre is usually switched on AFTER + // something looks wrong, and noteLocalTeardown() writes are themselves ungated - so a + // clear that only ran when the mode was already on would let a PREVIOUS session's origin + // survive, printing a stale via=bondWatchdog where via=unknown is the honest answer. + // Field assignments, not log lines: no cost when the mode is off. + connectedAtMs = System.currentTimeMillis() + lastLocalTeardown = null if (testCentre.active(com.noop.testcentre.TestDomain.CONNECTION)) { val nowUnix = System.currentTimeMillis() / 1000L val latencyMs = connectAttemptStartedAtMs?.let { System.currentTimeMillis() - it } @@ -5473,6 +5527,7 @@ class WhoopBleClient( // Nothing for the fuse window — the live stream/link stalled. Bounce it: the auto-rescan on // disconnect re-bonds and resumes streaming (the automatic version of the manual fix). log("No data for ${silentMs / 1000}s — bouncing link to resume live stream") + noteLocalTeardown("keepAliveStall") // #1020 intentionalDisconnect = false // make sure the auto-reconnect fires // disconnect() throwing on a dead binder (#314) would crash from the keep-alive timer; // tear down directly so the bounce degrades to a clean disconnect. @@ -6846,6 +6901,7 @@ class WhoopBleClient( // policy (always tear down) is single-sourced in shouldTeardownOnGattThrow so it's testable. if (shouldTeardownOnGattThrow(t)) { log("GATT op '$reason' failed (${t.javaClass.simpleName}); tearing down link") + noteLocalTeardown("gattThrow:$reason") // #1020 teardownAfterGattFailure() } false @@ -7049,13 +7105,14 @@ class WhoopBleClient( // so the reconnect-churn count means the same thing on both platforms. if (wasConnected) connReconnectCount += 1 if (testCentre.active(com.noop.testcentre.TestDomain.CONNECTION)) { - val reason = when (status) { - GATT_CONN_TIMEOUT -> "connectionTimeout" - GATT_CONN_TERMINATE_LOCAL_HOST -> "localTerminate" // our own bounce (e.g. #971 bond watchdog) - else -> "status$status" - } + // #1020: `via=` names WHICH of our own paths dropped it — bondWatchdog, keepAliveStall, + // userDisconnect, releaseStrap or gattThrow:. Five paths produced one string before, + // which made a thousands-of-reconnects report undiagnosable from the log alone. + val reason = connectionDownReason(status, lastLocalTeardown) if (wasConnected) { - log("connect down (uptime ends)", com.noop.testcentre.TestDomain.CONNECTION) + val heldMs = if (connectedAtMs > 0L) System.currentTimeMillis() - connectedAtMs else -1L + log("connect down (uptime ends${com.noop.analytics.ConnectionTrace.sessionHeldSuffix(heldMs)})", + com.noop.testcentre.TestDomain.CONNECTION) log("reconnect n=$connReconnectCount reason=$reason", com.noop.testcentre.TestDomain.CONNECTION) } else { log("reconnect n=$connReconnectCount failedConnect reason=$reason", com.noop.testcentre.TestDomain.CONNECTION) diff --git a/android/app/src/test/java/com/noop/analytics/ConnectionReadoutTest.kt b/android/app/src/test/java/com/noop/analytics/ConnectionReadoutTest.kt index eda8bda1e1..03bdf84ba4 100644 --- a/android/app/src/test/java/com/noop/analytics/ConnectionReadoutTest.kt +++ b/android/app/src/test/java/com/noop/analytics/ConnectionReadoutTest.kt @@ -98,6 +98,19 @@ class ConnectionReadoutTest { assertEquals("not connected", ConnectionReadout.uptimeLabel(tail, nowUnix = 5000)) } + /** + * #1020: the emitter appends a session duration, so the line the parser actually receives is no + * longer the bare one above. Pinned because the two are edited independently - the suffix was added + * on the strength of this match being a `contains`, and nothing was asserting that. + */ + @Test fun uptimeLabelDownWithASessionDuration() { + val tail = listOf( + "[connection] connect up gen=1 latencyMs=420 uptimeStart=1000", + "[connection] connect down (uptime ends after 6.8s)", + ) + assertEquals("not connected", ConnectionReadout.uptimeLabel(tail, nowUnix = 5000)) + } + @Test fun uptimeLabelEmptyTail() { assertEquals("not connected", ConnectionReadout.uptimeLabel(emptyList(), nowUnix = 5000)) } diff --git a/android/app/src/test/java/com/noop/ble/ConnectionDownReasonTest.kt b/android/app/src/test/java/com/noop/ble/ConnectionDownReasonTest.kt new file mode 100644 index 0000000000..b10d540eed --- /dev/null +++ b/android/app/src/test/java/com/noop/ble/ConnectionDownReasonTest.kt @@ -0,0 +1,74 @@ +package com.noop.ble + +import com.noop.analytics.ConnectionTrace +import org.junit.Assert.assertEquals +import org.junit.Test + +/** + * #1020 — the connection-down trace has to say WHICH path dropped the link. + * + * The report that prompted this showed nearly 2,800 reconnects, every one `reason=localTerminate`. + * That token is GATT status 22, and at least five of NOOP's own paths produce it — the bond watchdog, + * the keep-alive stall bounce, a user disconnect, releaseStrap, and a safeGatt teardown after a dead + * binder. With one string for five causes the log could not be diagnosed at all; the comment beside it + * in the source could only guess ("e.g. #971 bond watchdog"). + */ +class ConnectionDownReasonTest { + + /** The regression itself: a local teardown now names its origin. */ + @Test fun aLocalTeardownNamesThePathThatCausedIt() { + assertEquals( + "localTerminate via=bondWatchdog", + WhoopBleClient.connectionDownReason(22, "bondWatchdog"), + ) + assertEquals( + "localTerminate via=keepAliveStall", + WhoopBleClient.connectionDownReason(22, "keepAliveStall"), + ) + } + + /** + * A safeGatt teardown carries the failing operation with it, so `gattThrow:requestMtu` is + * distinguishable from `gattThrow:readRemoteRssi` — those point at different bugs. + */ + @Test fun aGattThrowCarriesTheOperationThatFailed() { + assertEquals( + "localTerminate via=gattThrow:requestMtu", + WhoopBleClient.connectionDownReason(22, "gattThrow:requestMtu"), + ) + } + + /** + * `unknown` is a real signal, not a fallback to ignore: the drop was local but no tagged path + * claimed it, which means a teardown route exists that this change missed. + */ + @Test fun anUntaggedLocalTeardownReadsAsUnknown() { + assertEquals("localTerminate via=unknown", WhoopBleClient.connectionDownReason(22, null)) + } + + /** A remote timeout is not ours, so no origin is attached — the strap or the radio dropped it. */ + @Test fun aRemoteTimeoutIsNotAttributedToUs() { + assertEquals("connectionTimeout", WhoopBleClient.connectionDownReason(8, "bondWatchdog")) + } + + /** Any other status passes through verbatim, as before. */ + @Test fun otherStatusesPassThrough() { + assertEquals("status19", WhoopBleClient.connectionDownReason(19, null)) + assertEquals("status133", WhoopBleClient.connectionDownReason(133, "userDisconnect")) + } + + /** The session length is what separates a 7-second bond watchdog from a 120-second stall bounce. */ + @Test fun theSessionLengthIsReportedToATenthOfASecond() { + assertEquals(" after 6.8s", ConnectionTrace.sessionHeldSuffix(6_800)) + assertEquals(" after 120.0s", ConnectionTrace.sessionHeldSuffix(120_000)) + assertEquals(" after 0.4s", ConnectionTrace.sessionHeldSuffix(432)) + } + + /** + * Unknown session start yields no suffix rather than a misleading zero — "after 0.0s" would read as + * an instant drop, which is a different diagnosis from "we do not know". + */ + @Test fun anUnknownSessionStartYieldsNoSuffix() { + assertEquals("", ConnectionTrace.sessionHeldSuffix(-1)) + } +}