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() {