From 5d9cb23b213a2d4f4b79577954a1f92e04f70ddd Mon Sep 17 00:00:00 2001 From: ryanbr Date: Wed, 8 Jul 2026 17:37:40 +1200 Subject: [PATCH] Strap log: surface WHERE offloaded rows landed + WHY, to diagnose stale-RTC "missed sleep" (#67) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A reset/stale strap RTC banks last night's sleep with a years-old timestamp, so the offload files it far in the past — off the recent timeline, where it reads as "missed sleep". The log showed the strap was stale and that rows persisted, but NOT where those rows landed or what clock reference decoded them, so the misdating was invisible. Logging only — no BLE/offload behaviour change: - Backfiller: new "Backfill: rows landed on " session line, plus the effective clock state — "IDENTITY fallback (GET_CLOCK never correlated) - stale-record correction OFF", "strap clock Nd behind wall - correction engaged", or "clock ref in sync". The dates are the ACTUAL post-correction landing days (the same night-keys the persist tally builds), so a night that landed in 2024 is self-evident. Captures the decode ref on the first chunk; reset in begin(). - DebugDataDiagnostics: the existing "Strap clock: Nd behind wall" line now notes recent sleep may be filed ~Nd in the past (#67), not just that the alarm is unreliable. - Tests: cover the new formatter — identity-fallback past-date signature, correlated-stale "correction engaged", in-sync, multi-night UTC range, and the no-em-dash convention shared with the sibling strap-log lines. Pairs with the root-cause investigation on #67: on a reset-RTC strap the offload falls back to an identity clock ref (Backfiller.swift), which zeroes the offset FIX #72's correctedWall needs, so stale records are stored verbatim. This makes that failure mode visible before touching the BLE clock handshake. --- Strand/BLE/BLEManager.swift | 9 ++++ Strand/Collect/Backfiller.swift | 54 ++++++++++++++++++- Strand/System/DebugDataDiagnostics.swift | 9 ++-- StrandTests/BackfillerSessionTallyTests.swift | 52 ++++++++++++++++++ 4 files changed, 119 insertions(+), 5 deletions(-) diff --git a/Strand/BLE/BLEManager.swift b/Strand/BLE/BLEManager.swift index 296ba8b73..2c3dd0053 100644 --- a/Strand/BLE/BLEManager.swift +++ b/Strand/BLE/BLEManager.swift @@ -1625,6 +1625,15 @@ public final class BLEManager: NSObject, ObservableObject { if let bf = backfiller, let summary = Backfiller.sessionSummaryLine(rows: bf.sessionRowsPersisted, motion: bf.sessionMotionRows, skinTemp: bf.sessionSkinTempRows, nights: bf.sessionNights) { log(summary) + // #67: WHERE the rows landed + WHY (the clock ref that decoded them). A reset-RTC strap banks + // last night into the past; this line makes the misdating self-evident in the strap log instead + // of leaving "persisted N rows across 1 night(s)" looking like a clean sync. + if let diag = Backfiller.sessionClockDiagLine(nightKeys: bf.sessionNightKeys, + device: bf.sessionClockDevice, + wall: bf.sessionClockWall, + usedIdentityRef: bf.sessionUsedIdentityRef) { + log(diag) + } } // Connection test mode: the offload OUTCOME the readout's lastOffloadResult id binds. Gated // zero-cost (the .connection bool is read before any string is built). Diagnostic only - it reads diff --git a/Strand/Collect/Backfiller.swift b/Strand/Collect/Backfiller.swift index 1c801736e..f46daf977 100644 --- a/Strand/Collect/Backfiller.swift +++ b/Strand/Collect/Backfiller.swift @@ -104,8 +104,19 @@ final class Backfiller { /// ONLY in its full DSP sleep records; a strap banking HR/RR-only records reports 0 here even on a /// healthy-looking sync, so surfacing it makes "skin temp never appears" reports self-diagnosing. private(set) var sessionSkinTempRows = 0 - private var sessionNightKeys: Set = [] + private(set) var sessionNightKeys: Set = [] var sessionNights: Int { sessionNightKeys.count } + + /// #67 diag: the clock reference the offload ACTUALLY decoded with, captured on the first chunk of the + /// session. Surfaces whether the stale-RTC timestamp correction (FIX #72's `correctedWall`) could even + /// engage. `sessionUsedIdentityRef` = GET_CLOCK never correlated, so decode fell back to an identity + /// ref (device==wall==now) → clock offset 0 → correction OFF. On a strap whose RTC has reset, that + /// silently stores the strap's stale (years-old) timestamps verbatim, so the night lands off the recent + /// timeline and reads as "missed sleep". Paired with the persisted-nights DATE RANGE below, one strap + /// log now shows both WHERE the rows landed and WHY. Reset in begin(). Log-only. + private(set) var sessionClockDevice: Int? + private(set) var sessionClockWall: Int? + private(set) var sessionUsedIdentityRef = false /// Logged once per session when the strap reports trim=0xFFFFFFFF — the "no valid flash cursor" /// sentinel: it has no banked history to offload (a clock/charge state, not a decode bug). private var loggedNoCursor = false @@ -207,6 +218,9 @@ final class Backfiller { sessionMotionRows = 0 sessionSkinTempRows = 0 sessionNightKeys.removeAll(keepingCapacity: true) + sessionClockDevice = nil // #67: re-capture the decode clock ref for this session + sessionClockWall = nil + sessionUsedIdentityRef = false loggedNoCursor = false loggedFutureRtc = false sessionDroppedImplausible = 0 @@ -271,6 +285,37 @@ final class Backfiller { return "Backfill: session persisted \(rows) rows (\(motion) with motion, \(skinTemp) skin-temp) across \(nights) night(s)." } + /// #67 diag: the persisted-nights DATE RANGE plus the offload's effective clock state — the two facts + /// the summary above omits. `nightKeys` are UTC day-keys (ts / 86400); their min/max are the day(s) the + /// rows LANDED on. When those days sit years in the past while the clock ref reads ~now (an identity + /// fallback, or an in-sync ref on a strap that banked stale), the night is misdated off the recent + /// timeline — the "missed sleep" signature (#67). Returns nil when nothing landed. Log-only, pure. + nonisolated static func sessionClockDiagLine(nightKeys: Set, + device: Int?, wall: Int?, usedIdentityRef: Bool) -> String? { + guard let lo = nightKeys.min(), let hi = nightKeys.max() else { return nil } + let day: (Int) -> String = { key in + let f = DateFormatter() + f.locale = Locale(identifier: "en_US_POSIX") // fixed Gregorian yyyy — not the device calendar + f.dateFormat = "yyyy-MM-dd" + f.timeZone = TimeZone(identifier: "UTC") + return f.string(from: Date(timeIntervalSince1970: Double(key) * 86_400)) + } + let range = lo == hi ? day(lo) : "\(day(lo))…\(day(hi))" + var line = "Backfill: rows landed on \(range)" + if let device, let wall { + let offset = wall - device + let days = offset / 86_400 + if usedIdentityRef { + line += " · clock ref: IDENTITY fallback (GET_CLOCK never correlated) - stale-record correction OFF" + } else if abs(offset) > 86_400 { + line += " · strap clock \(days >= 0 ? "\(days)d behind" : "\(-days)d ahead") wall - correction engaged" + } else { + line += " · clock ref in sync" + } + } + return line + } + /// The trim=0xFFFFFFFF sentinel line (#783). 0xFFFFFFFF means two different things depending on whether /// THIS run already banked rows. On the first end of a fresh offload it's the "no valid flash cursor" /// state (no banked history, a clock/charge problem). But the #364 auto-continuation re-kicks @@ -355,6 +400,13 @@ final class Backfiller { // decodes to correct wall time, and we can persist + ack + upload. The correlation is only // truly required to map REALTIME (type-40/43) device-epoch timestamps, never in a hist chunk. let ref = clockRef ?? { let now = Int(Date().timeIntervalSince1970); return ClockRef(device: now, wall: now) }() + // #67 diag: remember the ref (and whether it was the identity fallback) for the session summary, + // so a strap log shows whether stale-RTC correction could engage. Captured on the first chunk. + if sessionClockDevice == nil { + sessionClockDevice = ref.device + sessionClockWall = ref.wall + sessionUsedIdentityRef = (clockRef == nil) + } // PERF (2026-07-03): the heavy decode — parseFrame ×N, extractHistoricalStreams, and the // reject-classifier's SECOND full parse — runs OFF the main actor so a long history offload no // longer freezes the UI (was ~54K parseFrame calls on main for a 27K-row import). Pure functions diff --git a/Strand/System/DebugDataDiagnostics.swift b/Strand/System/DebugDataDiagnostics.swift index 8f3c44fc0..3a1f98739 100644 --- a/Strand/System/DebugDataDiagnostics.swift +++ b/Strand/System/DebugDataDiagnostics.swift @@ -197,14 +197,15 @@ enum DebugDataDiagnostics { } else { lines.append("Model: \(model)") } - // #4: strap clock health — a reset/stale OR future-dated clock (the #34 / #928 causes) breaks the - // alarm even when armed. + // #4 / #67: strap clock health — a reset/stale OR future-dated clock (the #34 / #928 causes) breaks + // the alarm even when armed, AND misdates offloaded sleep: the strap banks last night with its wrong + // RTC, so the night lands on the stale date and reads as "missed sleep" on the recent timeline (#67). if let newest = d.object(forKey: "strap.newestRecordTs") as? Int, newest > 0 { let behind = Int(Date().timeIntervalSince1970) - newest if behind > 3 * 86400 { - lines.append("Strap clock: \(behind / 86400)d behind wall (reset/stale — alarm unreliable)") + lines.append("Strap clock: \(behind / 86400)d behind wall (reset/stale — alarm unreliable; recent sleep may be filed ~\(behind / 86400)d in the past, #67)") } else if behind < -3 * 86400 { - lines.append("Strap clock: \(-behind / 86400)d AHEAD of wall (future-dated — alarm unreliable)") + lines.append("Strap clock: \(-behind / 86400)d AHEAD of wall (future-dated — alarm unreliable; recent sleep may be misdated, #67)") } else { lines.append("Strap clock: OK") } diff --git a/StrandTests/BackfillerSessionTallyTests.swift b/StrandTests/BackfillerSessionTallyTests.swift index 68a967397..3b04dc1f8 100644 --- a/StrandTests/BackfillerSessionTallyTests.swift +++ b/StrandTests/BackfillerSessionTallyTests.swift @@ -50,6 +50,58 @@ final class BackfillerSessionTallyTests: XCTestCase { "Backfill: session persisted 872 rows (172 with motion, 0 skin-temp) across 1 night(s).") } + // MARK: - #67 offload clock-diagnostic line (WHERE rows landed + WHY) + + // No nights persisted → no line (nothing to date). + func testClockDiagNilWhenNoNights() { + XCTAssertNil(Backfiller.sessionClockDiagLine(nightKeys: [], device: 1_700_000_000, wall: 1_700_000_000, usedIdentityRef: false)) + } + + // The #67 signature: rows landed years in the past AND the offload used the identity fallback (no + // GET_CLOCK correlation), so the stale-RTC correction never engaged. Day-key formats as a UTC date. + func testClockDiagIdentityFallbackShowsPastDateAndCorrectionOff() { + let marchDay = 1_711_276_123 / 86_400 // 2024-03-24 + let line = Backfiller.sessionClockDiagLine(nightKeys: [marchDay], + device: 1_783_486_611, wall: 1_783_486_611, + usedIdentityRef: true) + XCTAssertEqual(line, "Backfill: rows landed on 2024-03-24 · clock ref: IDENTITY fallback (GET_CLOCK never correlated) - stale-record correction OFF") + } + + // A genuinely stale-but-correlated ref: the correction IS engaged and the behind-by days are named. + func testClockDiagCorrelatedStaleRefReportsCorrectionEngaged() { + let day = 1_711_276_123 / 86_400 + let line = Backfiller.sessionClockDiagLine(nightKeys: [day], + device: 1_711_276_123, wall: 1_783_486_123, + usedIdentityRef: false) + XCTAssertNotNil(line) + XCTAssertTrue(line!.contains("835d behind wall - correction engaged"), line ?? "") + } + + // A healthy strap: in-sync ref, single night, and the date range collapses to one day. + func testClockDiagInSyncSingleDay() { + let day = 1_783_400_000 / 86_400 + let line = Backfiller.sessionClockDiagLine(nightKeys: [day], + device: 1_783_400_000, wall: 1_783_400_050, + usedIdentityRef: false) + XCTAssertTrue(line!.hasSuffix("· clock ref in sync"), line ?? "") + XCTAssertFalse(line!.contains("…")) // one day, not a range + } + + // Multi-night chunk shows a lo…hi UTC range. + func testClockDiagMultiNightRange() { + let d0 = 1_711_276_123 / 86_400 + let d1 = d0 + 2 + let line = Backfiller.sessionClockDiagLine(nightKeys: [d0, d1], device: nil, wall: nil, usedIdentityRef: false) + XCTAssertTrue(line!.contains("2024-03-24…2024-03-26"), line ?? "") + } + + // No em-dash leaks (matches the noCursorLine/futureRtcLine convention). + func testClockDiagHasNoEmDash() { + let line = Backfiller.sessionClockDiagLine(nightKeys: [1_711_276_123 / 86_400], + device: 1_783_486_611, wall: 1_783_486_611, usedIdentityRef: true) + XCTAssertFalse(line!.contains("\u{2014}")) + } + // #783: trim=0xFFFFFFFF on a fresh run that banked NOTHING means "no banked history": the genuine // clock/charge guidance with the "fully charge it" hint. func testNoCursorLineNoRowsGivesNoHistoryGuidance() {