commit 8f0b4b96048707533c6bd3cfb343dd0f4a73754e
parent ecdf12a8168935f6f10e0fd4f1d682fec6ca0a84
Author: Michael Camilleri <[email protected]>
Date: Tue, 2 Jun 2026 07:36:32 +0900
Add logging to push notifications
Diffstat:
7 files changed, 327 insertions(+), 10 deletions(-)
diff --git a/Crossmate/Persistence/GameStore.swift b/Crossmate/Persistence/GameStore.swift
@@ -1191,6 +1191,74 @@ final class GameStore {
return GridStateMerger.mergeWithProvenance(values).values.map(\.cell)
}
+ /// Sender-side measurements describing *why* the pause-push counts for
+ /// `(gameID, authorID)` came out as they did. Mirrors the set the count
+ /// path (`mergedAuthorCells`) iterates, then breaks it down against the
+ /// current grid: how many merged positions fall inside the bounds and on
+ /// playable squares, the coordinate range, the contributing device count,
+ /// and the edit window. Diagnostic-only; never affects badge or body. The
+ /// time-of-day and per-recipient fields are filled by the caller — only
+ /// the store-derived measurements are populated here.
+ func movesDiagnostics(for gameID: UUID, by authorID: String) -> PushPayload.Diagnostics? {
+ let gReq = NSFetchRequest<GameEntity>(entityName: "GameEntity")
+ gReq.predicate = NSPredicate(format: "id == %@", gameID as CVarArg)
+ gReq.fetchLimit = 1
+ guard let game = try? context.fetch(gReq).first else { return nil }
+
+ let mReq = NSFetchRequest<MovesEntity>(entityName: "MovesEntity")
+ mReq.predicate = NSPredicate(
+ format: "game.id == %@ AND authorID == %@",
+ gameID as CVarArg,
+ authorID
+ )
+ let entities = (try? context.fetch(mReq)) ?? []
+ let values: [MovesValue] = entities.compactMap { Self.movesValue(from: $0) }
+ let merged = GridStateMerger.mergeWithProvenance(values)
+
+ let width = Int(game.gridWidth)
+ let height = Int(game.gridHeight)
+ let puzzle = game.puzzleSource
+ .flatMap { try? XD.parse($0) }
+ .map(Puzzle.init(xd:))
+
+ var inBounds = 0
+ var playable = 0
+ var minRow = Int.max, maxRow = Int.min, minCol = Int.max, maxCol = Int.min
+ var earliest: Date?
+ var latest: Date?
+ for (position, provenance) in merged {
+ minRow = min(minRow, position.row); maxRow = max(maxRow, position.row)
+ minCol = min(minCol, position.col); maxCol = max(maxCol, position.col)
+ let updatedAt = provenance.cell.updatedAt
+ if earliest == nil || updatedAt < earliest! { earliest = updatedAt }
+ if latest == nil || updatedAt > latest! { latest = updatedAt }
+ let within = position.row >= 0 && position.row < height
+ && position.col >= 0 && position.col < width
+ guard within else { continue }
+ inBounds += 1
+ if let puzzle, !puzzle.cells[position.row][position.col].isBlock {
+ playable += 1
+ }
+ }
+ let deviceCount = Set(entities.compactMap { $0.deviceID }).count
+
+ return PushPayload.Diagnostics(
+ gridWidth: width,
+ gridHeight: height,
+ cmVersion: Int(game.puzzleCmVersion),
+ mergedCells: merged.count,
+ inBounds: inBounds,
+ playable: playable,
+ minRow: merged.isEmpty ? nil : minRow,
+ maxRow: merged.isEmpty ? nil : maxRow,
+ minCol: merged.isEmpty ? nil : minCol,
+ maxCol: merged.isEmpty ? nil : maxCol,
+ deviceCount: deviceCount,
+ earliestEdit: earliest,
+ latestEdit: latest
+ )
+ }
+
/// Every `(author, device)` that has written a `MovesEntity` for `gameID` —
/// i.e. every device whose grid letters are present locally. Peers' and this
/// account's *other* devices' Moves sync in as their own per-device rows, so
@@ -1244,6 +1312,14 @@ final class GameStore {
return fetchPlayerEntity(gameID: gameID, authorID: authorID)?.name ?? ""
}
+ /// The read cursor persisted for `(gameID, authorID)`, or `nil` when no row
+ /// exists or none has been stamped. Used by the local pause-diagnostics
+ /// mirror to compare this device's actual cursor against the value a peer's
+ /// pushed diagnostics claim it saw.
+ func readAt(for gameID: UUID, by authorID: String) -> Date? {
+ return fetchPlayerEntity(gameID: gameID, authorID: authorID)?.readAt
+ }
+
private func fetchPlayerEntity(gameID: UUID, authorID: String) -> PlayerEntity? {
let request = NSFetchRequest<PlayerEntity>(entityName: "PlayerEntity")
request.predicate = NSPredicate(
diff --git a/Crossmate/Services/AppServices.swift b/Crossmate/Services/AppServices.swift
@@ -924,6 +924,14 @@ final class AppServices {
return
}
let mergedCells = store.mergedAuthorCells(for: gameID, by: localAuthorID)
+ // Sender-side diagnostics: store-derived measurements plus this
+ // device's clock and the session-start it announced. Rides the
+ // per-recipient payload (the planner stamps each recipient's readAt)
+ // so the receiver can log why the counts came out as they did.
+ var diagnostics = store.movesDiagnostics(for: gameID, by: localAuthorID)
+ ?? PushPayload.Diagnostics()
+ diagnostics.senderNow = Date()
+ diagnostics.sessionStart = sessionAnnouncements.beginTime(gameID)
// Caught-up recipients are *not* dropped: a session end is a presence
// signal worth delivering even with nothing unseen (see
// `SessionPushPlanner.sessionEndAddressees`).
@@ -931,7 +939,8 @@ final class AppServices {
recipients: plan.recipients,
mergedCells: mergedCells,
playerName: preferences.name,
- puzzleTitle: plan.title
+ puzzleTitle: plan.title,
+ diagnostics: diagnostics
)
guard !addressees.isEmpty else {
syncMonitor.note("push(pause): skipped (no addressable recipients)")
@@ -2456,6 +2465,7 @@ final class AppServices {
/// local notification that would otherwise have fired in a few
/// minutes' time. No-op if nothing was accumulated.
func handlePuzzleOpened(gameID: UUID) {
+ logLocalPauseDiagnostics(for: gameID)
let summaries = sessionMonitor.consumeMovesSnapshots(for: gameID)
guard !summaries.isEmpty else { return }
let body = Self.formatSummaryBanner(summaries)
@@ -2468,6 +2478,28 @@ final class AppServices {
))
}
+ /// Logs this device's own view of each peer's Moves for `gameID`, using the
+ /// same `movesDiagnostics` computation the sender embeds in a pause push.
+ /// Pairs with the `pause-diagnostics` receipt the NSE records: a suspicious
+ /// pushed count can be diffed field-for-field against local ground truth.
+ /// Phantom cells that actually synced surface here too; ones that stayed
+ /// local to the sender (un-uploaded churn) won't — which is itself the
+ /// answer. `recipientReadAt` carries this device's *actual* cursor, to
+ /// compare against the value the peer's pushed diagnostics claimed it saw.
+ private func logLocalPauseDiagnostics(for gameID: UUID) {
+ let localAuthorID = identity.currentID
+ let selfReadAt = localAuthorID.flatMap { store.readAt(for: gameID, by: $0) }
+ for peerAuthorID in store.peerAuthorIDs(for: gameID, excluding: localAuthorID) {
+ guard var diagnostics = store.movesDiagnostics(for: gameID, by: peerAuthorID)
+ else { continue }
+ diagnostics.senderNow = Date()
+ diagnostics.recipientReadAt = selfReadAt
+ syncMonitor.note(
+ "local pause diag peer=\(peerAuthorID.prefix(8)): \(diagnostics.summaryLine)"
+ )
+ }
+ }
+
nonisolated static func formatSummaryBanner(_ summaries: [SessionMonitor.SessionSummary]) -> String {
guard !summaries.isEmpty else { return "" }
let phrases: [String] = summaries.map { summary in
diff --git a/Crossmate/Services/SessionPushPlanner.swift b/Crossmate/Services/SessionPushPlanner.swift
@@ -14,22 +14,29 @@ import Foundation
/// pause is actually published — not off a pending timer, so it stays accurate
/// even when a stop carries no unseen content.
struct SessionAnnouncementLog {
- private var announced: Set<UUID> = []
+ private var announced: [UUID: Date] = [:]
/// True when a begin push should fire: this session isn't already announced.
func shouldAnnounceBegin(_ gameID: UUID) -> Bool {
- !announced.contains(gameID)
+ announced[gameID] == nil
}
- /// Record that a "play" push has been sent for `gameID`.
- mutating func noteBeginAnnounced(_ gameID: UUID) {
- announced.insert(gameID)
+ /// Record that a "play" push has been sent for `gameID`, stamping when the
+ /// session was announced so a later pause can report its start.
+ mutating func noteBeginAnnounced(_ gameID: UUID, at time: Date = Date()) {
+ announced[gameID] = time
}
/// Record that a "pause" push has been sent for `gameID`, re-arming the
/// next begin push.
mutating func noteEndAnnounced(_ gameID: UUID) {
- announced.remove(gameID)
+ announced.removeValue(forKey: gameID)
+ }
+
+ /// When the still-open session for `gameID` was announced, or `nil` when no
+ /// begin push is outstanding (e.g. solo play that never announced one).
+ func beginTime(_ gameID: UUID) -> Date? {
+ announced[gameID]
}
}
@@ -44,7 +51,8 @@ enum SessionPushPlanner {
recipients: [AppServices.PushRecipient],
mergedCells: [TimestampedCell],
playerName: String,
- puzzleTitle: String
+ puzzleTitle: String,
+ diagnostics: PushPayload.Diagnostics? = nil
) -> [PushClient.Addressee] {
recipients.compactMap { recipient -> PushClient.Addressee? in
guard let address = recipient.pushAddress else { return nil }
@@ -60,10 +68,18 @@ enum SessionPushPlanner {
added: added,
cleared: cleared
)
+ // Stamp the exact cutoff this recipient's diff used. `nil` readAt
+ // (no cursor yet) is preserved as nil — itself diagnostic, since it
+ // means the count covered the author's entire history.
+ var perRecipient = diagnostics
+ perRecipient?.recipientReadAt = recipient.readAt
return PushClient.Addressee(
address: address,
body: body,
- payload: PushPayload(event: .pause(added: added, cleared: cleared))
+ payload: PushPayload(
+ event: .pause(added: added, cleared: cleared),
+ diagnostics: perRecipient
+ )
)
}
}
diff --git a/NotificationService/NotificationService.swift b/NotificationService/NotificationService.swift
@@ -48,6 +48,16 @@ final class NotificationService: UNNotificationServiceExtension {
body: bestAttemptContent.body,
source: "notification-service-extension"
)
+ // When the sender attached pause diagnostics, record them as a second
+ // receipt so they surface in the app's diagnostics log alongside the
+ // visible body — the only channel we have to inspect a peer's
+ // sender-side counting inputs without reaching that peer's device.
+ if let diagnostics = payload?.diagnostics {
+ VisibleNotificationReceiptLog.record(
+ body: diagnostics.summaryLine,
+ source: "pause-diagnostics"
+ )
+ }
var updatedUserInfo = bestAttemptContent.userInfo
updatedUserInfo["crossmateNSELogged"] = true
bestAttemptContent.userInfo = updatedUserInfo
diff --git a/Shared/PushPayload.swift b/Shared/PushPayload.swift
@@ -19,10 +19,89 @@ struct PushPayload: Codable, Sendable, Equatable {
var version: Int
var event: Event
+ /// Optional, opaque-to-the-worker diagnostic context attached by the
+ /// sender. Carries the inputs that produced a pause body's counts so a
+ /// recipient can record them (via the NSE) and reconstruct *why* the
+ /// numbers came out as they did, without having to reach the sender.
+ /// All fields are optional and the whole block is omitted on non-pause
+ /// pushes, so it never affects badge/visible behaviour.
+ var diagnostics: Diagnostics?
- init(version: Int = PushPayload.currentVersion, event: Event) {
+ init(
+ version: Int = PushPayload.currentVersion,
+ event: Event,
+ diagnostics: Diagnostics? = nil
+ ) {
self.version = version
self.event = event
+ self.diagnostics = diagnostics
+ }
+
+ /// A flat bag of sender-side measurements taken at the moment a pause
+ /// push was built. Every field is optional: each layer (store, services,
+ /// per-recipient planner) fills the part it knows, and a reader tolerates
+ /// any subset. Kept small enough to ride inside the APNs payload budget.
+ struct Diagnostics: Codable, Sendable, Equatable {
+ /// The sender's wall clock when the pause was computed — surfaces
+ /// clock skew against the recipient's own clock.
+ var senderNow: Date? = nil
+ /// When the sender believes this play session began (the begin-push
+ /// timestamp). `nil` if the session was never announced (e.g. solo).
+ var sessionStart: Date? = nil
+ /// The recipient's `Player.readAt` *as the sender saw it* — the exact
+ /// cutoff the per-recipient diff used. A stale value here widens the
+ /// counting window.
+ var recipientReadAt: Date? = nil
+ /// The grid geometry the sender currently holds for the puzzle.
+ var gridWidth: Int? = nil
+ var gridHeight: Int? = nil
+ /// The sender's converter version stamp for the puzzle — a mismatch
+ /// hints the two ends merged against different geometry.
+ var cmVersion: Int? = nil
+ /// Distinct positions in the sender's merged author Moves (the set the
+ /// count path iterates).
+ var mergedCells: Int? = nil
+ /// Of `mergedCells`, how many fall inside the current grid bounds.
+ var inBounds: Int? = nil
+ /// Of `mergedCells`, how many land on a playable (non-block) square.
+ var playable: Int? = nil
+ /// Coordinate range observed across the merged cells — exposes
+ /// out-of-grid or transposed coordinates.
+ var minRow: Int? = nil
+ var maxRow: Int? = nil
+ var minCol: Int? = nil
+ var maxCol: Int? = nil
+ /// Distinct devices that contributed Moves for this author/game.
+ var deviceCount: Int? = nil
+ /// Oldest/newest `updatedAt` across the merged cells — the true edit
+ /// window, independent of the session-start announcement.
+ var earliestEdit: Date? = nil
+ var latestEdit: Date? = nil
+
+ /// Compact single-line rendering for the receipt log, mirroring the
+ /// `key=value` style of the existing diagnostics events.
+ var summaryLine: String {
+ func iso(_ date: Date?) -> String {
+ guard let date else { return "—" }
+ let f = ISO8601DateFormatter()
+ f.formatOptions = [.withInternetDateTime, .withFractionalSeconds]
+ f.timeZone = TimeZone(secondsFromGMT: 0)
+ return f.string(from: date)
+ }
+ func int(_ value: Int?) -> String { value.map(String.init) ?? "—" }
+ return "now=\(iso(senderNow))"
+ + " sessionStart=\(iso(sessionStart))"
+ + " recipientReadAt=\(iso(recipientReadAt))"
+ + " grid=\(int(gridWidth))x\(int(gridHeight))"
+ + " cm=\(int(cmVersion))"
+ + " merged=\(int(mergedCells))"
+ + " inBounds=\(int(inBounds))"
+ + " playable=\(int(playable))"
+ + " rows=[\(int(minRow))..\(int(maxRow))]"
+ + " cols=[\(int(minCol))..\(int(maxCol))]"
+ + " devices=\(int(deviceCount))"
+ + " edits=[\(iso(earliestEdit))..\(iso(latestEdit))]"
+ }
}
enum Event: Sendable, Equatable {
diff --git a/Tests/Unit/PushPayloadTests.swift b/Tests/Unit/PushPayloadTests.swift
@@ -44,6 +44,64 @@ struct PushPayloadTests {
#expect(PushPayload.decode(from: Data("plain text".utf8).base64EncodedString()) == nil)
}
+ @Test("Diagnostics round-trip through the wire encoding")
+ func diagnosticsRoundTrip() throws {
+ let diagnostics = PushPayload.Diagnostics(
+ senderNow: Date(timeIntervalSince1970: 2_000),
+ sessionStart: Date(timeIntervalSince1970: 1_500),
+ recipientReadAt: Date(timeIntervalSince1970: 1_000),
+ gridWidth: 15,
+ gridHeight: 15,
+ cmVersion: 3,
+ mergedCells: 200,
+ inBounds: 78,
+ playable: 78,
+ minRow: 0,
+ maxRow: 14,
+ minCol: 0,
+ maxCol: 14,
+ deviceCount: 2,
+ earliestEdit: Date(timeIntervalSince1970: 1_200),
+ latestEdit: Date(timeIntervalSince1970: 1_900)
+ )
+ let payload = PushPayload(
+ event: .pause(added: 125, cleared: 75),
+ diagnostics: diagnostics
+ )
+
+ let decoded = try roundTrip(payload)
+
+ #expect(decoded == payload)
+ #expect(decoded.diagnostics?.mergedCells == 200)
+ #expect(decoded.diagnostics?.recipientReadAt == Date(timeIntervalSince1970: 1_000))
+ }
+
+ @Test("A pause without diagnostics decodes with nil diagnostics")
+ func diagnosticsAbsenceTolerated() throws {
+ let json = #"{"version":1,"event":{"type":"pause","added":1,"cleared":0}}"#
+ let encoded = Data(json.utf8).base64EncodedString()
+
+ let decoded = try #require(PushPayload.decode(from: encoded))
+
+ #expect(decoded.diagnostics == nil)
+ #expect(decoded.event == .pause(added: 1, cleared: 0))
+ }
+
+ @Test("Diagnostics summary renders values and dashes for absent fields")
+ func diagnosticsSummaryLine() {
+ let diagnostics = PushPayload.Diagnostics(
+ gridWidth: 15,
+ gridHeight: 15,
+ mergedCells: 200
+ )
+
+ let line = diagnostics.summaryLine
+
+ #expect(line.contains("grid=15x15"))
+ #expect(line.contains("merged=200"))
+ #expect(line.contains("recipientReadAt=—"))
+ }
+
@Test("Only unseen content marks a game unread")
func marksUnreadMatrix() {
#expect(PushPayload(event: .pause(added: 1, cleared: 0)).marksUnread)
diff --git a/Tests/Unit/SessionPushPlannerTests.swift b/Tests/Unit/SessionPushPlannerTests.swift
@@ -28,6 +28,19 @@ struct SessionAnnouncementLogTests {
#expect(!log.shouldAnnounceBegin(a))
#expect(log.shouldAnnounceBegin(b))
}
+
+ @Test("Begin time is recorded for the open session and cleared on stop")
+ func beginTimeTracked() {
+ var log = SessionAnnouncementLog()
+ let game = UUID()
+ let start = Date(timeIntervalSince1970: 5_000)
+
+ #expect(log.beginTime(game) == nil)
+ log.noteBeginAnnounced(game, at: start)
+ #expect(log.beginTime(game) == start)
+ log.noteEndAnnounced(game)
+ #expect(log.beginTime(game) == nil)
+ }
}
@Suite("Session push planner")
@@ -84,6 +97,39 @@ struct SessionPushPlannerTests {
#expect(addressees[0].payload?.marksUnread == true)
}
+ @Test("Diagnostics ride each recipient's payload, stamped with that recipient's readAt")
+ func diagnosticsStampedPerRecipient() {
+ let edit = Date(timeIntervalSince1970: 1_000)
+ let cells = [cell("X", at: edit)]
+ let aReadAt = edit.addingTimeInterval(-60)
+ let recipientA = recipient("addr-a", readAt: aReadAt)
+ let recipientB = recipient("addr-b", readAt: nil)
+ let base = PushPayload.Diagnostics(
+ gridWidth: 15,
+ gridHeight: 15,
+ mergedCells: 200
+ )
+
+ let addressees = SessionPushPlanner.sessionEndAddressees(
+ recipients: [recipientA, recipientB],
+ mergedCells: cells,
+ playerName: "Bunny",
+ puzzleTitle: "Tuesday",
+ diagnostics: base
+ )
+
+ let byAddress = Dictionary(uniqueKeysWithValues: addressees.map { ($0.address, $0) })
+ let diagnosticsA = byAddress["addr-a"]?.payload?.diagnostics
+ #expect(diagnosticsA?.recipientReadAt == aReadAt)
+ #expect(diagnosticsA?.gridWidth == 15)
+ #expect(diagnosticsA?.mergedCells == 200)
+ // A recipient with no cursor keeps recipientReadAt nil — itself
+ // diagnostic, since the count then covered the whole history.
+ let diagnosticsB = byAddress["addr-b"]?.payload?.diagnostics
+ #expect(diagnosticsB?.recipientReadAt == nil)
+ #expect(diagnosticsB?.gridWidth == 15)
+ }
+
@Test("Recipients without a push capability are dropped")
func unaddressableDropped() {
let edit = Date(timeIntervalSince1970: 1_000)
