diff --git a/.gitignore b/.gitignore index 14409355fd..875a5863c7 100644 --- a/.gitignore +++ b/.gitignore @@ -43,3 +43,7 @@ maestro/screenshots/results/ maestro/screenshots/diffs/ docs/superpowers/ + +# Raw spike capture: full device logcat, so it can carry unrelated personal +# content. Keep the summarised results, not the source logs. +docs/spikes/raw/ diff --git a/apps/flipcash/shared/chat/src/main/kotlin/com/flipcash/shared/chat/ChatCoordinator.kt b/apps/flipcash/shared/chat/src/main/kotlin/com/flipcash/shared/chat/ChatCoordinator.kt index c1828277dd..d09195b2db 100644 --- a/apps/flipcash/shared/chat/src/main/kotlin/com/flipcash/shared/chat/ChatCoordinator.kt +++ b/apps/flipcash/shared/chat/src/main/kotlin/com/flipcash/shared/chat/ChatCoordinator.kt @@ -160,6 +160,15 @@ interface MessagingOperations { /** Fetches the full message history for [chatId] from the server and persists locally. */ suspend fun loadMessages(chatId: ChatId) + /** + * Persists a message the server delivered inside a push payload, without an RPC. + * + * Idempotent on `eventSequence`: a copy that is not newer than the stored row is + * dropped, so re-delivery of the same push and a following [loadMessages] converge + * on the same transcript. + */ + suspend fun applyPushedMessage(chatId: ChatId, message: ChatMessage) + /** * Sends a text message to [chatId]. Returns the server-confirmed [ChatMessage]. * diff --git a/apps/flipcash/shared/chat/src/main/kotlin/com/flipcash/shared/chat/internal/delegates/EventStreamDelegate.kt b/apps/flipcash/shared/chat/src/main/kotlin/com/flipcash/shared/chat/internal/delegates/EventStreamDelegate.kt index f2123b6bf7..387aaf37be 100644 --- a/apps/flipcash/shared/chat/src/main/kotlin/com/flipcash/shared/chat/internal/delegates/EventStreamDelegate.kt +++ b/apps/flipcash/shared/chat/src/main/kotlin/com/flipcash/shared/chat/internal/delegates/EventStreamDelegate.kt @@ -51,8 +51,8 @@ import kotlin.time.Duration.Companion.seconds * local persistence and in-memory state. * * Responsibilities: - * - **Message persistence** — resolves messages from `ChatUpdate.events` (preferred) - * or the deprecated `newMessages` field, then upserts to Room. + * - **Message persistence** — resolves messages from `ChatUpdate.events`, then + * upserts to Room. * - **Gap-aware event sequencing** — uses [EventSequenceTracker] to maintain a * contiguous frontier. Only the highest contiguous sequence is persisted; if a * gap is detected, a timed [getDelta][performDeltaSync] backfill is scheduled. @@ -290,17 +290,12 @@ class EventStreamDelegate @Inject constructor( private suspend fun applyUpdate(update: ChatUpdate) { val chatId = update.chatId - // --- Resolve messages: prefer events, fall back to deprecated newMessages --- + // --- Resolve messages from the event log --- - val resolvedMessages = if (update.events.isNotEmpty()) { - update.events - .flatMap { event -> event.mutations.map { it.message } } - .sortedBy { it.eventSequence } - .distinctBy { it.messageId } - } else { - @Suppress("DEPRECATION") - update.newMessages - } + val resolvedMessages = update.events + .flatMap { event -> event.mutations.map { it.message } } + .sortedBy { it.eventSequence } + .distinctBy { it.messageId } trace( tag = TAG, diff --git a/apps/flipcash/shared/chat/src/main/kotlin/com/flipcash/shared/chat/internal/delegates/MessagingDelegate.kt b/apps/flipcash/shared/chat/src/main/kotlin/com/flipcash/shared/chat/internal/delegates/MessagingDelegate.kt index ce2a871c23..779d01cb00 100644 --- a/apps/flipcash/shared/chat/src/main/kotlin/com/flipcash/shared/chat/internal/delegates/MessagingDelegate.kt +++ b/apps/flipcash/shared/chat/src/main/kotlin/com/flipcash/shared/chat/internal/delegates/MessagingDelegate.kt @@ -193,6 +193,20 @@ class MessagingDelegate @Inject constructor( } } + override suspend fun applyPushedMessage(chatId: ChatId, message: ChatMessage) { + // The DAO's upsert already drops a copy older than the stored row, so the only + // ordering this has to protect is the metadata below it. + messageDataSource.upsert(chatId, listOf(message)) + + // Deliberately not advancing the event-log cursor. A push carries one message, not + // a page, so seating the cursor at its sequence would let a later catch-up resume + // from a frontier it never actually fetched and skip whatever it missed in between. + if (message.messageId > (metadataDataSource.getLastMessageId(chatId) ?: 0L)) { + metadataDataSource.updateLastMessageId(chatId, message.messageId) + metadataDataSource.updateLastActivity(chatId, message.timestamp.toEpochMilliseconds()) + } + } + override suspend fun sendMessage( chatId: ChatId, content: String, diff --git a/apps/flipcash/shared/chat/src/test/kotlin/com/flipcash/shared/chat/ChatCoordinatorEagerBalanceTest.kt b/apps/flipcash/shared/chat/src/test/kotlin/com/flipcash/shared/chat/ChatCoordinatorEagerBalanceTest.kt index 33542d4316..af581eae0d 100644 --- a/apps/flipcash/shared/chat/src/test/kotlin/com/flipcash/shared/chat/ChatCoordinatorEagerBalanceTest.kt +++ b/apps/flipcash/shared/chat/src/test/kotlin/com/flipcash/shared/chat/ChatCoordinatorEagerBalanceTest.kt @@ -9,8 +9,10 @@ import com.flipcash.app.tokens.TokenCoordinator import com.flipcash.services.controllers.ChatController import com.flipcash.services.controllers.ChatMessagingController import com.flipcash.services.controllers.EventStreamingController +import com.flipcash.services.models.chat.ChatEvent import com.flipcash.services.models.chat.ChatId import com.flipcash.services.models.chat.ChatMessage +import com.flipcash.services.models.chat.ChatMutation import com.flipcash.services.models.chat.ChatUpdate import com.flipcash.services.models.chat.MessageContent import com.flipcash.shared.chat.internal.ChatIdGenerator @@ -156,12 +158,24 @@ class ChatCoordinatorEagerBalanceTest { unreadSeq = 0, ) + // Each update carries its messages as event-log events. Sequences run + // contiguously from 1 across the whole test so the gap detector stays quiet + // and these tests exercise only the behaviour they name. + private var nextEventSequence = 1L + private fun chatUpdate(vararg messages: ChatMessage) = ChatUpdate( chatId = chatId, - newMessages = messages.toList(), pointerUpdates = emptyList(), typingNotifications = emptyList(), metadataUpdates = emptyList(), + events = messages.map { message -> + ChatEvent( + sequence = nextEventSequence++, + count = 1, + ts = message.timestamp, + mutations = listOf(ChatMutation.MessageSent(message)), + ) + }, ) private suspend fun triggerCollection() { diff --git a/apps/flipcash/shared/chat/src/test/kotlin/com/flipcash/shared/chat/ChatCoordinatorEventsTest.kt b/apps/flipcash/shared/chat/src/test/kotlin/com/flipcash/shared/chat/ChatCoordinatorEventsTest.kt index 3a44e72b1b..c9757aec71 100644 --- a/apps/flipcash/shared/chat/src/test/kotlin/com/flipcash/shared/chat/ChatCoordinatorEventsTest.kt +++ b/apps/flipcash/shared/chat/src/test/kotlin/com/flipcash/shared/chat/ChatCoordinatorEventsTest.kt @@ -161,56 +161,7 @@ class ChatCoordinatorEventsTest { coordinator.onUserLoggedIn(mockk(relaxed = true)) } - // region Events vs newMessages - - @Test - fun `events are preferred over deprecated newMessages`() = runTest(testDispatchers.dispatcher) { - triggerCollection() - - val eventMsg = textMessage(id = 1, eventSequence = 1) - val deprecatedMsg = textMessage(id = 99) - - @Suppress("DEPRECATION") - val update = ChatUpdate( - chatId = chatId, - newMessages = listOf(deprecatedMsg), - events = listOf(chatEvent(1, eventMsg)), - ) - chatUpdatesChannel.send(update) - advanceTimeBy(1_000.milliseconds) - runCurrent() - - // Should upsert the event message, not the deprecated one - coVerify { - messageDataSource.upsert(chatId, match { messages -> - messages.size == 1 && messages[0].messageId == 1L - }) - } - coordinator.teardown() - } - - @Test - fun `falls back to newMessages when events is empty`() = runTest(testDispatchers.dispatcher) { - triggerCollection() - - val msg = textMessage(id = 42) - @Suppress("DEPRECATION") - val update = ChatUpdate( - chatId = chatId, - newMessages = listOf(msg), - events = emptyList(), - ) - chatUpdatesChannel.send(update) - advanceTimeBy(1_000.milliseconds) - runCurrent() - - coVerify { - messageDataSource.upsert(chatId, match { messages -> - messages.size == 1 && messages[0].messageId == 42L - }) - } - coordinator.teardown() - } + // region Event message resolution @Test fun `multiple events are flattened and deduped by messageId`() = runTest(testDispatchers.dispatcher) { diff --git a/apps/flipcash/shared/chat/src/test/kotlin/com/flipcash/shared/chat/MessagingPushedMessageTest.kt b/apps/flipcash/shared/chat/src/test/kotlin/com/flipcash/shared/chat/MessagingPushedMessageTest.kt new file mode 100644 index 0000000000..9eb95bb982 --- /dev/null +++ b/apps/flipcash/shared/chat/src/test/kotlin/com/flipcash/shared/chat/MessagingPushedMessageTest.kt @@ -0,0 +1,135 @@ +package com.flipcash.shared.chat + +import com.flipcash.app.persistence.sources.ChatMessageDataSource +import com.flipcash.app.persistence.sources.ChatMetadataDataSource +import com.flipcash.services.controllers.ChatMessagingController +import com.flipcash.services.models.chat.ChatId +import com.flipcash.services.models.chat.ChatMessage +import com.flipcash.services.models.chat.MessageContent +import com.flipcash.shared.chat.internal.delegates.MessagingDelegate +import io.mockk.coEvery +import io.mockk.coVerify +import io.mockk.mockk +import kotlinx.coroutines.test.runTest +import org.junit.Test +import kotlin.time.Instant + +/** + * Covers the write a push-carried message performs in place of a fetch. + * + * Three properties matter here, and none of them are visible from the planner: the write + * reaches the same data source a fetched page would, the event cursor stays where it was, + * and the feed row only moves forward. + */ +class MessagingPushedMessageTest { + + private val chatId = ChatId("aabbccdd") + + private fun message(id: Long, eventSequence: Long, epochSeconds: Long = 1_757_000_000) = + ChatMessage( + messageId = id, + senderId = listOf(4, 5, 6), + content = listOf(MessageContent.Text("msg-$id")), + timestamp = Instant.fromEpochSeconds(epochSeconds), + unreadSeq = 0, + eventSequence = eventSequence, + ) + + private fun delegateWith( + metadataDataSource: ChatMetadataDataSource, + messageDataSource: ChatMessageDataSource = mockk(relaxed = true), + messagingController: ChatMessagingController = mockk(relaxed = true), + ) = MessagingDelegate( + chatController = mockk(relaxed = true), + messagingController = messagingController, + metadataDataSource = metadataDataSource, + messageDataSource = messageDataSource, + memberDataSource = mockk(relaxed = true), + notificationManager = mockk(relaxed = true), + userManager = mockk(relaxed = true), + stateHolder = mockk(relaxed = true), + analytics = mockk(relaxed = true), + ) + + @Test + fun `a pushed message is written through the same source a fetched page uses`() = runTest { + val pushed = message(id = 12, eventSequence = 9) + val messageDataSource = mockk(relaxed = true) + val metadataDataSource = mockk(relaxed = true) + coEvery { metadataDataSource.getLastMessageId(chatId) } returns 11 + + delegateWith(metadataDataSource, messageDataSource).applyPushedMessage(chatId, pushed) + + coVerify(exactly = 1) { messageDataSource.upsert(chatId, listOf(pushed)) } + } + + @Test + fun `applying a pushed message makes no network call`() = runTest { + val messagingController = mockk(relaxed = true) + val metadataDataSource = mockk(relaxed = true) + coEvery { metadataDataSource.getLastMessageId(chatId) } returns 0 + + delegateWith(metadataDataSource, messagingController = messagingController) + .applyPushedMessage(chatId, message(id = 1, eventSequence = 3)) + + coVerify(exactly = 0) { messagingController.getMessages(any(), any()) } + } + + @Test + fun `a pushed message does not seat the event cursor`() = runTest { + val metadataDataSource = mockk(relaxed = true) + coEvery { metadataDataSource.getLastMessageId(chatId) } returns 0 + + delegateWith(metadataDataSource).applyPushedMessage(chatId, message(id = 12, eventSequence = 99)) + + // A push carries one message, not a page. Seating the cursor at its sequence would let a + // later catch-up resume from a frontier it never fetched. + coVerify(exactly = 0) { metadataDataSource.updateLatestEventSequence(chatId, any()) } + } + + @Test + fun `a newer pushed message moves the feed row forward`() = runTest { + val metadataDataSource = mockk(relaxed = true) + coEvery { metadataDataSource.getLastMessageId(chatId) } returns 11 + + delegateWith(metadataDataSource) + .applyPushedMessage(chatId, message(id = 12, eventSequence = 9, epochSeconds = 1_757_000_042)) + + coVerify(exactly = 1) { metadataDataSource.updateLastMessageId(chatId, 12) } + coVerify(exactly = 1) { metadataDataSource.updateLastActivity(chatId, 1_757_000_042_000) } + } + + @Test + fun `a re-delivered push does not rewind the feed row`() = runTest { + val metadataDataSource = mockk(relaxed = true) + coEvery { metadataDataSource.getLastMessageId(chatId) } returns 20 + + delegateWith(metadataDataSource).applyPushedMessage(chatId, message(id = 12, eventSequence = 9)) + + coVerify(exactly = 0) { metadataDataSource.updateLastMessageId(chatId, any()) } + coVerify(exactly = 0) { metadataDataSource.updateLastActivity(chatId, any()) } + } + + @Test + fun `the same push applied twice moves the feed row once`() = runTest { + val metadataDataSource = mockk(relaxed = true) + coEvery { metadataDataSource.getLastMessageId(chatId) } returns 11 andThen 12 + val pushed = message(id = 12, eventSequence = 9) + val delegate = delegateWith(metadataDataSource) + + delegate.applyPushedMessage(chatId, pushed) + delegate.applyPushedMessage(chatId, pushed) + + coVerify(exactly = 1) { metadataDataSource.updateLastMessageId(chatId, 12) } + } + + @Test + fun `a chat with no stored message id accepts the first push`() = runTest { + val metadataDataSource = mockk(relaxed = true) + coEvery { metadataDataSource.getLastMessageId(chatId) } returns null + + delegateWith(metadataDataSource).applyPushedMessage(chatId, message(id = 1, eventSequence = 3)) + + coVerify(exactly = 1) { metadataDataSource.updateLastMessageId(chatId, 1) } + } +} diff --git a/apps/flipcash/shared/chat/src/test/kotlin/com/flipcash/shared/chat/ReceivedCounterTest.kt b/apps/flipcash/shared/chat/src/test/kotlin/com/flipcash/shared/chat/ReceivedCounterTest.kt index 218ee64734..6bf34ce80d 100644 --- a/apps/flipcash/shared/chat/src/test/kotlin/com/flipcash/shared/chat/ReceivedCounterTest.kt +++ b/apps/flipcash/shared/chat/src/test/kotlin/com/flipcash/shared/chat/ReceivedCounterTest.kt @@ -11,8 +11,10 @@ import com.flipcash.app.tokens.TokenCoordinator import com.flipcash.services.controllers.ChatController import com.flipcash.services.controllers.ChatMessagingController import com.flipcash.services.controllers.EventStreamingController +import com.flipcash.services.models.chat.ChatEvent import com.flipcash.services.models.chat.ChatId import com.flipcash.services.models.chat.ChatMessage +import com.flipcash.services.models.chat.ChatMutation import com.flipcash.services.models.chat.ChatUpdate import com.flipcash.services.models.chat.MessageContent import com.flipcash.services.user.UserManager @@ -180,15 +182,24 @@ class ReceivedCounterTest { unreadSeq = 0, ) - // newMessages is deprecated in favour of `events`, but applyUpdate still falls - // back to it and every existing chat test builds updates this way. Matching the - // existing harness keeps these tests readable next to their neighbours. + // Each update carries its messages as event-log events. Sequences run + // contiguously from 1 across the whole test so the gap detector stays quiet + // and these tests exercise only the behaviour they name. + private var nextEventSequence = 1L + private fun chatUpdate(vararg messages: ChatMessage) = ChatUpdate( chatId = chatId, - newMessages = messages.toList(), pointerUpdates = emptyList(), typingNotifications = emptyList(), metadataUpdates = emptyList(), + events = messages.map { message -> + ChatEvent( + sequence = nextEventSequence++, + count = 1, + ts = message.timestamp, + mutations = listOf(ChatMutation.MessageSent(message)), + ) + }, ) private suspend fun TestScope.deliver(vararg messages: ChatMessage) { diff --git a/apps/flipcash/shared/chat/src/test/kotlin/com/flipcash/shared/chat/ReceivedEventTest.kt b/apps/flipcash/shared/chat/src/test/kotlin/com/flipcash/shared/chat/ReceivedEventTest.kt index ba845a3f6e..8ffa9ce541 100644 --- a/apps/flipcash/shared/chat/src/test/kotlin/com/flipcash/shared/chat/ReceivedEventTest.kt +++ b/apps/flipcash/shared/chat/src/test/kotlin/com/flipcash/shared/chat/ReceivedEventTest.kt @@ -10,8 +10,10 @@ import com.flipcash.app.tokens.TokenCoordinator import com.flipcash.services.controllers.ChatController import com.flipcash.services.controllers.ChatMessagingController import com.flipcash.services.controllers.EventStreamingController +import com.flipcash.services.models.chat.ChatEvent import com.flipcash.services.models.chat.ChatId import com.flipcash.services.models.chat.ChatMessage +import com.flipcash.services.models.chat.ChatMutation import com.flipcash.services.models.chat.ChatType import com.flipcash.services.models.chat.ChatUpdate import com.flipcash.services.models.chat.MessageContent @@ -183,15 +185,24 @@ class ReceivedEventTest { unreadSeq = 0, ) - // newMessages is deprecated in favour of `events`, but applyUpdate still falls - // back to it and every existing chat test builds updates this way. Matching the - // existing harness keeps these tests readable next to their neighbours. + // Each update carries its messages as event-log events. Sequences run + // contiguously from 1 across the whole test so the gap detector stays quiet + // and these tests exercise only the behaviour they name. + private var nextEventSequence = 1L + private fun chatUpdate(vararg messages: ChatMessage) = ChatUpdate( chatId = chatId, - newMessages = messages.toList(), pointerUpdates = emptyList(), typingNotifications = emptyList(), metadataUpdates = emptyList(), + events = messages.map { message -> + ChatEvent( + sequence = nextEventSequence++, + count = 1, + ts = message.timestamp, + mutations = listOf(ChatMutation.MessageSent(message)), + ) + }, ) private suspend fun TestScope.deliver(vararg messages: ChatMessage) { diff --git a/apps/flipcash/shared/notifications/build.gradle.kts b/apps/flipcash/shared/notifications/build.gradle.kts index 3488b33609..d16d684bd4 100644 --- a/apps/flipcash/shared/notifications/build.gradle.kts +++ b/apps/flipcash/shared/notifications/build.gradle.kts @@ -11,6 +11,7 @@ dependencies { implementation(project(":apps:flipcash:shared:authentication")) implementation(project(":apps:flipcash:shared:chat")) implementation(project(":apps:flipcash:shared:contacts")) + implementation(project(":apps:flipcash:shared:featureflags")) implementation(project(":apps:flipcash:shared:persistence:sources")) implementation(project(":apps:flipcash:shared:phone")) implementation(project(":apps:flipcash:shared:push")) diff --git a/apps/flipcash/shared/notifications/src/main/kotlin/com/flipcash/app/notifications/NotificationService.kt b/apps/flipcash/shared/notifications/src/main/kotlin/com/flipcash/app/notifications/NotificationService.kt index c60f0f6122..371f6ab4a5 100644 --- a/apps/flipcash/shared/notifications/src/main/kotlin/com/flipcash/app/notifications/NotificationService.kt +++ b/apps/flipcash/shared/notifications/src/main/kotlin/com/flipcash/app/notifications/NotificationService.kt @@ -68,6 +68,12 @@ class NotificationService : FirebaseMessagingService(), private const val KEY_BODY = "push_notification_body" private const val KEY_PAYLOAD = "flipcash_payload" + // Correlation id for measurement runs. scripts/spike/ sends a known + // sequence number with every push so a missing delivery and a late one + // can be told apart in the log rather than reading as the same silence. + // No production sender sets it, so `seq` is empty in the field. + private const val KEY_SPIKE_SEQ = "spike_seq" + // Upper bound on how long we'll wait for a remote avatar before posting // without one. A memory/disk cache hit returns well under this; the // bound only caps the cold-cache network fetch so the notification isn't @@ -135,54 +141,88 @@ class NotificationService : FirebaseMessagingService(), val title = message.data[KEY_TITLE]?.ifEmpty { message.notification?.title } val body = message.data[KEY_BODY]?.ifEmpty { message.notification?.body } + val payload = message.data.getOrDefault(KEY_PAYLOAD, "") + .takeIf { it.isNotEmpty() } + ?.let { NotificationPayload.fromEncoded(it) } + + val actions = planPushHandling( + title = title, + body = body, + payload = payload, + ) + + val latencyMs = System.currentTimeMillis() - message.sentTime + val bucket = applicationContext.currentStandbyBucket() + trace( message = "onMessageReceived", type = TraceType.Process, metadata = { // Push content is not recorded: TraceType.Process is forwarded to // breadcrumb sinks, and message text does not belong in Bugsnag. - "silent" to (title == null) + "seq" to message.data[KEY_SPIKE_SEQ].orEmpty() "has_body" to (body != null) + "actions" to actions.size + "silent" to (title == null) + "bucket" to bucket + "latency_ms" to latencyMs + "priority" to message.priority + "original_priority" to message.originalPriority } ) - if (title == null) return + if (actions.isEmpty()) return - val payload = message.data.getOrDefault(KEY_PAYLOAD, "") - .takeIf { it.isNotEmpty() } - ?.let { NotificationPayload.fromEncoded(it) } + execute(actions) + } - if (payload?.navigation is NavigationTrigger.CurrencyInfo) { + /** Runs a planned action list. Sync work starts immediately; posting a + * notification waits for authentication, as it always has. */ + private fun execute(actions: List) { + if (PushAction.UpdateTokens in actions) { launch { tokenCoordinator.update() } } - if (payload?.category == NotificationCategory.CONTACT_JOIN) { - launch { - chatCoordinator.refreshFeed() - } + val chatActions = actions.filter { + it is PushAction.RefreshFeed || + it is PushAction.LoadMessages || + it is PushAction.ApplyMessage } - - when (val trigger = payload?.navigation) { - is NavigationTrigger.Chat.ById -> { - launch { - chatCoordinator.refreshFeed() - chatCoordinator.loadMessages(chatId = trigger.chatId) + if (chatActions.isNotEmpty()) { + launch { + chatActions.forEach { action -> + when (action) { + is PushAction.RefreshFeed -> chatCoordinator.refreshFeed() + is PushAction.LoadMessages -> chatCoordinator.loadMessages(chatId = action.chatId) + is PushAction.ApplyMessage -> chatCoordinator.applyPushedMessage( + chatId = action.chatId, + message = action.message, + ) + else -> Unit + } } } - else -> Unit } + val post = actions.filterIsInstance().firstOrNull() + val syncContacts = actions.any { it is PushAction.SyncContacts } + + if (post == null && !syncContacts) return + authenticateIfNeeded { launch { try { - if (payload?.category == NotificationCategory.CONTACT_JOIN) { - launch { contactCoordinator.sync() } + if (syncContacts) launch { contactCoordinator.sync() } + if (post != null) { + val resolvedTitle = + applySubstitutions(post.title, post.payload?.titleSubstitutions.orEmpty()) + val resolvedBody = post.body?.let { + applySubstitutions(it, post.payload?.bodySubstitutions.orEmpty()) + } + postNotification(resolvedTitle, resolvedBody, post.payload) } - val resolvedTitle = applySubstitutions(title, payload?.titleSubstitutions.orEmpty()) - val resolvedBody = body?.let { applySubstitutions(it, payload?.bodySubstitutions.orEmpty()) } - postNotification(resolvedTitle, resolvedBody, payload) } catch (e: Exception) { - trace(tag = "NotificationService", message = "Failed to post notification", error = e) + trace(tag = "NotificationService", message = "Failed to handle push", error = e) } } } diff --git a/apps/flipcash/shared/notifications/src/main/kotlin/com/flipcash/app/notifications/PushAction.kt b/apps/flipcash/shared/notifications/src/main/kotlin/com/flipcash/app/notifications/PushAction.kt new file mode 100644 index 0000000000..21f1084148 --- /dev/null +++ b/apps/flipcash/shared/notifications/src/main/kotlin/com/flipcash/app/notifications/PushAction.kt @@ -0,0 +1,42 @@ +package com.flipcash.app.notifications + +import com.flipcash.services.models.NotificationPayload +import com.flipcash.services.models.chat.ChatId +import com.flipcash.services.models.chat.ChatMessage + +/** + * A single unit of work a received push asks the app to perform. + * + * Modelling this as data rather than as control flow inside + * [NotificationService.onMessageReceived] is what makes the push handling + * rules unit-testable without Robolectric or a live FirebaseMessagingService. + */ +sealed interface PushAction { + /** Server-side feed sync. Safe to request redundantly. */ + data object RefreshFeed : PushAction + + /** Fetch and persist full message history for one chat. */ + data class LoadMessages(val chatId: ChatId) : PushAction + + /** + * Persist a message the push carried, instead of fetching it. + * + * Planned in place of [LoadMessages] when the payload inlines the message. + * The write is local, so this is the one sync action a push can satisfy + * without a network round trip. + */ + data class ApplyMessage(val chatId: ChatId, val message: ChatMessage) : PushAction + + /** Refresh token/mint state. */ + data object UpdateTokens : PushAction + + /** Refresh the contact list. */ + data object SyncContacts : PushAction + + /** Post a user-visible notification. Absent for a silent push. */ + data class PostNotification( + val title: String, + val body: String?, + val payload: NotificationPayload?, + ) : PushAction +} diff --git a/apps/flipcash/shared/notifications/src/main/kotlin/com/flipcash/app/notifications/PushHandlingPlanner.kt b/apps/flipcash/shared/notifications/src/main/kotlin/com/flipcash/app/notifications/PushHandlingPlanner.kt new file mode 100644 index 0000000000..180a5e6345 --- /dev/null +++ b/apps/flipcash/shared/notifications/src/main/kotlin/com/flipcash/app/notifications/PushHandlingPlanner.kt @@ -0,0 +1,79 @@ +package com.flipcash.app.notifications + +import com.flipcash.services.models.NavigationTrigger +import com.flipcash.services.models.NotificationCategory +import com.flipcash.services.models.NotificationPayload + +/** + * Decides what a received push should cause the app to do. + * + * Pure by construction: no Android types, no coroutines, no injection. Every + * rule about push handling is testable here, which is the point. + * + * @param title resolved push title, null for a data-only push + * @param body resolved push body, may be null even for a visible push + * @param payload decoded [NotificationPayload], null when absent or undecodable + */ +fun planPushHandling( + title: String?, + body: String?, + payload: NotificationPayload?, +): List { + val sync = syncActionsFor(payload) + + // The sync half is the same either way; a title only adds the notification on top. + return if (title == null) sync else sync + PushAction.PostNotification(title, body, payload) +} + +/** + * The sync work an event class implies, independent of where the push + * navigates. + * + * `flipcash.push.v1.Payload.category` is the event taxonomy — there is no + * separate event field coming, so this table is keyed on the taxonomy already. + * Adding an event class is an entry here rather than a branch in + * [syncActionsFor]. + * + * A category absent from the table plans no sync of its own, which is every + * category but one today. + */ +private val syncByCategory: Map> = mapOf( + NotificationCategory.CONTACT_JOIN to listOf(PushAction.RefreshFeed, PushAction.SyncContacts), +) + +/** + * The sync work a navigation target implies. + * + * This stays a `when` rather than joining the table above: each arm reads data + * off the trigger it matched, so the actions cannot be written down in advance. + * + * A push at a named chat resolves to one of two shapes. When the payload + * inlines the message, [PushAction.ApplyMessage] writes it locally; when it + * does not — the field is optional and the body is size-limited — the plan + * falls back to the [PushAction.LoadMessages] fetch it has always used. + */ +private fun syncForNavigation(payload: NotificationPayload): List = + when (val navigation = payload.navigation) { + is NavigationTrigger.CurrencyInfo -> listOf(PushAction.UpdateTokens) + is NavigationTrigger.Chat.ById -> listOf( + PushAction.RefreshFeed, + payload.chatMetadata?.message + ?.let { PushAction.ApplyMessage(navigation.chatId, it) } + ?: PushAction.LoadMessages(navigation.chatId), + ) + is NavigationTrigger.Chat.ByContact -> emptyList() + null -> emptyList() + } + +/** + * The sync work implied by [payload], independent of visibility. + * + * `distinct()` is what lets the two sources overlap without the caller + * knowing: a contact-join push that also names a chat asks for + * [PushAction.RefreshFeed] from both and gets one. + */ +private fun syncActionsFor(payload: NotificationPayload?): List { + if (payload == null) return emptyList() + return (syncByCategory[payload.category].orEmpty() + syncForNavigation(payload)) + .distinct() +} diff --git a/apps/flipcash/shared/notifications/src/main/kotlin/com/flipcash/app/notifications/StandbyBucketReporter.kt b/apps/flipcash/shared/notifications/src/main/kotlin/com/flipcash/app/notifications/StandbyBucketReporter.kt new file mode 100644 index 0000000000..3845a61598 --- /dev/null +++ b/apps/flipcash/shared/notifications/src/main/kotlin/com/flipcash/app/notifications/StandbyBucketReporter.kt @@ -0,0 +1,27 @@ +package com.flipcash.app.notifications + +import android.app.usage.UsageStatsManager +import android.content.Context +import androidx.core.content.getSystemService + +/** + * Stable string label for a raw [UsageStatsManager] standby bucket constant. + * + * Separated from the system lookup so the mapping is testable without a + * device, and so an unrecognised bucket is preserved rather than collapsed + * into "unknown" — a new bucket constant would otherwise vanish silently. + */ +fun bucketLabel(bucket: Int): String = when (bucket) { + UsageStatsManager.STANDBY_BUCKET_ACTIVE -> "active" + UsageStatsManager.STANDBY_BUCKET_WORKING_SET -> "working_set" + UsageStatsManager.STANDBY_BUCKET_FREQUENT -> "frequent" + UsageStatsManager.STANDBY_BUCKET_RARE -> "rare" + UsageStatsManager.STANDBY_BUCKET_RESTRICTED -> "restricted" + else -> "unknown_$bucket" +} + +/** The calling app's current standby bucket, or "unavailable" if it cannot be read. */ +fun Context.currentStandbyBucket(): String { + val manager = getSystemService() ?: return "unavailable" + return runCatching { bucketLabel(manager.appStandbyBucket) }.getOrElse { "unavailable" } +} diff --git a/apps/flipcash/shared/notifications/src/test/kotlin/com/flipcash/app/notifications/PushHandlingPlannerTest.kt b/apps/flipcash/shared/notifications/src/test/kotlin/com/flipcash/app/notifications/PushHandlingPlannerTest.kt new file mode 100644 index 0000000000..c5387421e9 --- /dev/null +++ b/apps/flipcash/shared/notifications/src/test/kotlin/com/flipcash/app/notifications/PushHandlingPlannerTest.kt @@ -0,0 +1,205 @@ +package com.flipcash.app.notifications + +import com.flipcash.services.models.NavigationTrigger +import com.flipcash.services.models.NotificationCategory +import com.flipcash.services.models.NotificationPayload +import com.flipcash.services.models.PushChatMetadata +import com.flipcash.services.models.chat.ChatId +import com.flipcash.services.models.chat.ChatMessage +import com.flipcash.services.models.chat.ChatType +import com.flipcash.services.models.chat.MessageContent +import com.getcode.solana.keys.Mint +import kotlin.time.Instant +import kotlin.test.Test +import kotlin.test.assertEquals +import kotlin.test.assertTrue + +class PushHandlingPlannerTest { + + private fun payload( + navigation: NavigationTrigger? = null, + category: NotificationCategory = NotificationCategory.DEFAULT, + chatMetadata: PushChatMetadata? = null, + ) = NotificationPayload( + navigation = navigation, + category = category, + chatMetadata = chatMetadata, + ) + + private fun inlinedMessage(messageId: Long = 42L, eventSequence: Long = 7L) = ChatMessage( + messageId = messageId, + senderId = null, + content = listOf(MessageContent.Text("hello")), + timestamp = Instant.fromEpochSeconds(1_757_000_000), + unreadSeq = 1L, + eventSequence = eventSequence, + ) + + private fun chatMetadata(message: ChatMessage?) = PushChatMetadata( + sendingUserId = null, + chatType = ChatType.CONTACT_DM, + message = message, + ) + + // region A titled push + + @Test + fun `currency info push updates tokens and posts`() { + val p = payload(navigation = NavigationTrigger.CurrencyInfo(mint = TEST_MINT)) + val actions = planPushHandling("Title", "Body", p) + assertTrue(PushAction.UpdateTokens in actions) + assertTrue(actions.last() is PushAction.PostNotification) + } + + @Test + fun `contact join push refreshes feed and syncs contacts`() { + val p = payload(category = NotificationCategory.CONTACT_JOIN) + val actions = planPushHandling("Title", null, p) + assertTrue(PushAction.RefreshFeed in actions) + assertTrue(PushAction.SyncContacts in actions) + } + + @Test + fun `chat push refreshes feed then loads that chat`() { + val chatId = ChatId("aa07") + val p = payload(navigation = NavigationTrigger.Chat.ById(chatId)) + val actions = planPushHandling("Title", "Body", p) + assertEquals( + listOf(PushAction.RefreshFeed, PushAction.LoadMessages(chatId)), + actions.filterNot { it is PushAction.PostNotification }, + ) + } + + @Test + fun `a chat push carrying its message applies it instead of fetching`() { + val chatId = ChatId("aa08") + val message = inlinedMessage() + val p = payload( + navigation = NavigationTrigger.Chat.ById(chatId), + chatMetadata = chatMetadata(message), + ) + val actions = planPushHandling("Title", "Body", p) + assertEquals( + listOf(PushAction.RefreshFeed, PushAction.ApplyMessage(chatId, message)), + actions.filterNot { it is PushAction.PostNotification }, + ) + } + + @Test + fun `chat metadata without a message falls back to fetching`() { + val chatId = ChatId("aa09") + val p = payload( + navigation = NavigationTrigger.Chat.ById(chatId), + chatMetadata = chatMetadata(message = null), + ) + val actions = planPushHandling("Title", "Body", p) + assertEquals( + listOf(PushAction.RefreshFeed, PushAction.LoadMessages(chatId)), + actions.filterNot { it is PushAction.PostNotification }, + ) + } + + @Test + fun `an inlined message on a push that names no chat plans nothing to apply`() { + val p = payload(chatMetadata = chatMetadata(inlinedMessage())) + val actions = planPushHandling("Title", null, p) + assertEquals(listOf(PushAction.PostNotification("Title", null, p)), actions) + } + + @Test + fun `a silent chat push with an inlined message needs no network`() { + val chatId = ChatId("aa10") + val message = inlinedMessage() + val p = payload( + navigation = NavigationTrigger.Chat.ById(chatId), + chatMetadata = chatMetadata(message), + ) + val actions = planPushHandling(null, null, p) + assertTrue(PushAction.ApplyMessage(chatId, message) in actions) + assertTrue(actions.none { it is PushAction.LoadMessages }) + } + + @Test + fun `a contact join that also names a chat refreshes the feed once`() { + val chatId = ChatId("aa11") + val p = payload( + navigation = NavigationTrigger.Chat.ById(chatId), + category = NotificationCategory.CONTACT_JOIN, + ) + val actions = planPushHandling("Title", null, p) + assertEquals( + listOf(PushAction.RefreshFeed, PushAction.SyncContacts, PushAction.LoadMessages(chatId)), + actions.filterNot { it is PushAction.PostNotification }, + ) + } + + @Test + fun `a category with no sync of its own plans nothing`() { + val p = payload(category = NotificationCategory.GAIN) + val actions = planPushHandling("Title", null, p) + assertEquals(listOf(PushAction.PostNotification("Title", null, p)), actions) + } + + @Test + fun `push with no payload still posts the notification`() { + val actions = planPushHandling("Title", "Body", payload = null) + assertEquals( + listOf(PushAction.PostNotification("Title", "Body", null)), + actions, + ) + } + + @Test + fun `post notification is always last so sync starts first`() { + val p = payload(navigation = NavigationTrigger.Chat.ById(ChatId("0c"))) + val actions = planPushHandling("Title", "Body", p) + assertTrue(actions.last() is PushAction.PostNotification) + } + + // endregion + + // region A data-only push + + @Test + fun `a data only push syncs chat without posting`() { + val chatId = ChatId("aa09") + val actions = planPushHandling( + title = null, + body = null, + payload = payload(navigation = NavigationTrigger.Chat.ById(chatId)), + ) + assertEquals(listOf(PushAction.RefreshFeed, PushAction.LoadMessages(chatId)), actions) + } + + @Test + fun `a data only push never posts a notification`() { + val actions = planPushHandling( + title = null, + body = null, + payload = payload(navigation = NavigationTrigger.CurrencyInfo(mint = TEST_MINT)), + ) + assertTrue(actions.none { it is PushAction.PostNotification }) + assertEquals(listOf(PushAction.UpdateTokens), actions) + } + + @Test + fun `a data only push with no payload does nothing`() { + val actions = planPushHandling(null, null, payload = null) + assertEquals(emptyList(), actions) + } + + @Test + fun `a title changes only the notification, not the sync plan`() { + val p = payload(navigation = NavigationTrigger.Chat.ById(ChatId("0c"))) + assertEquals( + planPushHandling(null, null, p), + planPushHandling("Title", "Body", p).filterNot { it is PushAction.PostNotification }, + ) + } + + // endregion + + companion object { + private val TEST_MINT = Mint.usdc + } +} diff --git a/apps/flipcash/shared/notifications/src/test/kotlin/com/flipcash/app/notifications/StandbyBucketReporterTest.kt b/apps/flipcash/shared/notifications/src/test/kotlin/com/flipcash/app/notifications/StandbyBucketReporterTest.kt new file mode 100644 index 0000000000..47f01b6ecc --- /dev/null +++ b/apps/flipcash/shared/notifications/src/test/kotlin/com/flipcash/app/notifications/StandbyBucketReporterTest.kt @@ -0,0 +1,22 @@ +package com.flipcash.app.notifications + +import android.app.usage.UsageStatsManager +import kotlin.test.Test +import kotlin.test.assertEquals + +class StandbyBucketReporterTest { + + @Test + fun `maps every documented bucket to a stable label`() { + assertEquals("active", bucketLabel(UsageStatsManager.STANDBY_BUCKET_ACTIVE)) + assertEquals("working_set", bucketLabel(UsageStatsManager.STANDBY_BUCKET_WORKING_SET)) + assertEquals("frequent", bucketLabel(UsageStatsManager.STANDBY_BUCKET_FREQUENT)) + assertEquals("rare", bucketLabel(UsageStatsManager.STANDBY_BUCKET_RARE)) + assertEquals("restricted", bucketLabel(UsageStatsManager.STANDBY_BUCKET_RESTRICTED)) + } + + @Test + fun `maps an unknown bucket to its raw value rather than losing it`() { + assertEquals("unknown_999", bucketLabel(999)) + } +} diff --git a/apps/flipcash/shared/persistence/db/src/main/kotlin/com/flipcash/app/persistence/dao/ChatMessageDao.kt b/apps/flipcash/shared/persistence/db/src/main/kotlin/com/flipcash/app/persistence/dao/ChatMessageDao.kt index a134687a6a..f8151989a0 100644 --- a/apps/flipcash/shared/persistence/db/src/main/kotlin/com/flipcash/app/persistence/dao/ChatMessageDao.kt +++ b/apps/flipcash/shared/persistence/db/src/main/kotlin/com/flipcash/app/persistence/dao/ChatMessageDao.kt @@ -87,8 +87,16 @@ interface ChatMessageDao { @Transaction suspend fun upsert(entity: ChatMessageEntity) { - // Event-sequence guard: skip if stored sequence is newer (last-writer-wins). - // Passthrough when eventSequence == 0 (legacy messages). + // Event-sequence guard: skip if the stored sequence is strictly newer (last-writer-wins). + // messaging.v1 tells clients to ignore a copy at or below the version they hold; the + // comparison here is strict instead, because a confirmed send needs the equal case. + // confirmPendingMessage stamps the server's event_sequence onto the optimistic row without + // replacing the content written locally, so the server's canonical copy of that message + // arrives at a sequence equal to the one already stored. Dropping it would pin the + // optimistic content forever. + // + // Passthrough when eventSequence == 0: a legacy row or an optimistic one the server has + // not echoed yet. The server cannot send 0 — messaging.v1 constrains event_sequence to >= 1. if (entity.eventSequence > 0) { val stored = getEventSequence(entity.chatIdHex, entity.messageId) if (stored != null && stored > entity.eventSequence) return diff --git a/apps/flipcash/shared/persistence/db/src/main/kotlin/com/flipcash/app/persistence/dao/ChatMetadataDao.kt b/apps/flipcash/shared/persistence/db/src/main/kotlin/com/flipcash/app/persistence/dao/ChatMetadataDao.kt index 0ca8e5b43e..7841c95e7e 100644 --- a/apps/flipcash/shared/persistence/db/src/main/kotlin/com/flipcash/app/persistence/dao/ChatMetadataDao.kt +++ b/apps/flipcash/shared/persistence/db/src/main/kotlin/com/flipcash/app/persistence/dao/ChatMetadataDao.kt @@ -73,6 +73,9 @@ interface ChatMetadataDao { @Query("UPDATE chat_metadata SET last_activity_epoch_ms = :epochMs WHERE chat_id_hex = :chatIdHex") suspend fun updateLastActivity(chatIdHex: String, epochMs: Long) + @Query("SELECT last_message_id FROM chat_metadata WHERE chat_id_hex = :chatIdHex") + suspend fun getLastMessageId(chatIdHex: String): Long? + @Query("UPDATE chat_metadata SET last_message_id = :messageId WHERE chat_id_hex = :chatIdHex") suspend fun updateLastMessageId(chatIdHex: String, messageId: Long) diff --git a/apps/flipcash/shared/persistence/db/src/test/kotlin/com/flipcash/app/persistence/dao/ChatMessageUpsertGuardTest.kt b/apps/flipcash/shared/persistence/db/src/test/kotlin/com/flipcash/app/persistence/dao/ChatMessageUpsertGuardTest.kt new file mode 100644 index 0000000000..670ea2d515 --- /dev/null +++ b/apps/flipcash/shared/persistence/db/src/test/kotlin/com/flipcash/app/persistence/dao/ChatMessageUpsertGuardTest.kt @@ -0,0 +1,176 @@ +package com.flipcash.app.persistence.dao + +import android.content.Context +import androidx.room.Room +import androidx.test.core.app.ApplicationProvider +import com.flipcash.app.persistence.FlipcashDatabase +import com.flipcash.app.persistence.converters.MessageContentSerialized +import com.flipcash.app.persistence.entities.ChatMessageEntity +import com.flipcash.app.persistence.entities.MessageStatus +import kotlinx.coroutines.test.runTest +import org.junit.After +import org.junit.Before +import org.junit.Test +import org.junit.runner.RunWith +import org.robolectric.RobolectricTestRunner +import kotlin.test.assertEquals + +/** + * Covers `upsert`'s last-writer-wins guard on `event_sequence`. + * + * The same message reaches this DAO from three directions — a fetched page, the event stream, + * and now a push that carried it — with no ordering between them. The guard is what makes the + * order they arrive in stop mattering, so its edges are worth pinning: which comparison drops a + * write, which lets one through, and the sequence-0 passthrough that bypasses it entirely. + */ +@RunWith(RobolectricTestRunner::class) +class ChatMessageUpsertGuardTest { + + private lateinit var db: FlipcashDatabase + private lateinit var dao: ChatMessageDao + + @Before + fun setUp() { + val context = ApplicationProvider.getApplicationContext() + db = Room.inMemoryDatabaseBuilder(context, FlipcashDatabase::class.java) + .allowMainThreadQueries() + .build() + dao = db.chatMessageDao() + } + + @After + fun tearDown() { + db.close() + } + + private fun message( + messageId: Long = 7, + body: String, + eventSequence: Long, + ) = ChatMessageEntity( + chatIdHex = CHAT_HEX, + messageId = messageId, + senderIdHex = SENDER_HEX, + contentJson = listOf(MessageContentSerialized.Text(body)), + timestampEpochMs = messageId * 1_000, + unreadSeq = messageId, + eventSequence = eventSequence, + ) + + private suspend fun storedBody(messageId: Long = 7): String? = + (dao.getMessage(CHAT_HEX, messageId)?.contentJson?.firstOrNull() as? MessageContentSerialized.Text) + ?.text + + @Test + fun `a copy older than the stored row is dropped`() = runTest { + dao.upsert(message(body = "newer", eventSequence = 9)) + dao.upsert(message(body = "older", eventSequence = 4)) + + assertEquals("newer", storedBody()) + assertEquals(9L, dao.getEventSequence(CHAT_HEX, 7)) + } + + @Test + fun `a copy newer than the stored row replaces it`() = runTest { + dao.upsert(message(body = "older", eventSequence = 4)) + dao.upsert(message(body = "newer", eventSequence = 9)) + + assertEquals("newer", storedBody()) + assertEquals(9L, dao.getEventSequence(CHAT_HEX, 7)) + } + + /** + * The comparison is strict, so a copy at the same sequence writes through rather than being + * skipped. messaging.v1 tells clients to ignore a copy at or below the held version; the + * equal case is kept because a confirmed send depends on it — confirmPendingMessage stamps + * the server's event_sequence onto the optimistic row but leaves its locally written content, + * and the canonical copy that supersedes it carries that same sequence. A re-delivered push + * hits the same path and converges because the two copies are the same message, not because + * the guard stopped the second one. + */ + @Test + fun `a copy at the same sequence writes through`() = runTest { + dao.upsert(message(body = "first", eventSequence = 9)) + dao.upsert(message(body = "second", eventSequence = 9)) + + assertEquals("second", storedBody()) + } + + /** + * Sequence 0 means "unstamped" — a legacy row, or an optimistic row the server has not + * echoed yet — and the guard lets it past unconditionally. A source that sends 0 for a + * message the server did stamp therefore overwrites a newer stored copy. The server is not + * such a source: messaging.v1 constrains event_sequence to >= 1, so this is reachable only + * from a locally built row. + */ + @Test + fun `an unstamped copy bypasses the guard and overwrites a stamped row`() = runTest { + dao.upsert(message(body = "stamped", eventSequence = 9)) + dao.upsert(message(body = "unstamped", eventSequence = 0)) + + assertEquals("unstamped", storedBody()) + assertEquals(0L, dao.getEventSequence(CHAT_HEX, 7)) + } + + @Test + fun `a stamped copy replaces an unstamped stored row`() = runTest { + dao.upsert(message(body = "unstamped", eventSequence = 0)) + dao.upsert(message(body = "stamped", eventSequence = 9)) + + assertEquals("stamped", storedBody()) + assertEquals(9L, dao.getEventSequence(CHAT_HEX, 7)) + } + + /** + * The path a push-carried message takes: `applyPushedMessage` hands the DAO a single-element + * list, so the guard has to hold through the list overload and not only the single-entity one. + */ + @Test + fun `the list overload guards each entity on its own`() = runTest { + dao.upsert(listOf(message(messageId = 1, body = "one newer", eventSequence = 9))) + dao.upsert(listOf(message(messageId = 2, body = "two older", eventSequence = 4))) + + dao.upsert( + listOf( + message(messageId = 1, body = "one stale", eventSequence = 4), + message(messageId = 2, body = "two fresh", eventSequence = 9), + ) + ) + + assertEquals("one newer", storedBody(messageId = 1)) + assertEquals("two fresh", storedBody(messageId = 2)) + } + + @Test + fun `the guard is scoped to one chat`() = runTest { + dao.upsert(message(body = "here newer", eventSequence = 9)) + dao.upsert(message(body = "elsewhere older", eventSequence = 4).copy(chatIdHex = OTHER_HEX)) + + assertEquals("here newer", storedBody()) + assertEquals(4L, dao.getEventSequence(OTHER_HEX, 7)) + } + + /** + * A dropped write must not take the pending id with it. The row a stale copy loses to may + * still be the optimistic one awaiting confirmation, and losing `pending_client_id_hex` + * strands it — nothing can match the server's echo back to it afterwards. + */ + @Test + fun `a dropped copy leaves the pending id on the stored row`() = runTest { + dao.upsert(message(body = "newer", eventSequence = 9).copy( + status = MessageStatus.SENDING, + pendingClientIdHex = CLIENT_HEX, + )) + + dao.upsert(message(body = "older", eventSequence = 4)) + + assertEquals(CLIENT_HEX, dao.getPendingClientId(CHAT_HEX, 7)) + } + + private companion object { + const val CHAT_HEX = "aabb" + const val OTHER_HEX = "ccdd" + const val SENDER_HEX = "1122" + const val CLIENT_HEX = "eeff" + } +} diff --git a/apps/flipcash/shared/persistence/sources/src/main/kotlin/com/flipcash/app/persistence/sources/ChatMetadataDataSource.kt b/apps/flipcash/shared/persistence/sources/src/main/kotlin/com/flipcash/app/persistence/sources/ChatMetadataDataSource.kt index 71e00eb654..7c1bec7889 100644 --- a/apps/flipcash/shared/persistence/sources/src/main/kotlin/com/flipcash/app/persistence/sources/ChatMetadataDataSource.kt +++ b/apps/flipcash/shared/persistence/sources/src/main/kotlin/com/flipcash/app/persistence/sources/ChatMetadataDataSource.kt @@ -40,6 +40,9 @@ class ChatMetadataDataSource @Inject constructor( db?.chatMetadataDao()?.updateLastActivity(mapper.chatIdHex(chatId), epochMs) } + suspend fun getLastMessageId(chatId: ChatId): Long? = + db?.chatMetadataDao()?.getLastMessageId(mapper.chatIdHex(chatId)) + suspend fun updateLastMessageId(chatId: ChatId, messageId: Long) { db?.chatMetadataDao()?.updateLastMessageId(mapper.chatIdHex(chatId), messageId) } diff --git a/docs/spikes/2026-09-08-standby-bucket-results.md b/docs/spikes/2026-09-08-standby-bucket-results.md new file mode 100644 index 0000000000..52a30a39de --- /dev/null +++ b/docs/spikes/2026-09-08-standby-bucket-results.md @@ -0,0 +1,770 @@ +# Spike results: do App Standby Buckets delay or drop silent pushes? + +Plan: `docs/superpowers/plans/` in the orchestrator repo. +Spec: `docs/superpowers/specs/2026-09-08-push-preload-research.md`. +Raw traces and send manifests: `docs/spikes/raw/` — gitignored and local to the machine +that ran the matrix, because the captures are ~41 MB of logcat carrying unrelated device +chatter. Everything the conclusions rest on is quoted here. + +**Status: all six charging cells collected, plus the deep-Doze cell they were missing.** +Device `SM02G4061915766`, model `Seeker`, Android 16 (API 36), throughout. + +**Correction, 2026-09-10: every cell below measured delivery and nothing else.** The runner sent +`{spike_seq: …}` with no `flipcash_payload`, and the app derives all push-triggered work from that +key, so no cell exercised the push handling path — the trace reads `actions=0` on all 139 sends. +The delivery and latency figures are unaffected. Every claim about work is restated or withdrawn +below; see [The matrix never exercised the push handling +path](#the-matrix-never-exercised-the-push-handling-path). + +Each cell: 20 high-priority pushes, 180 s apart, then a 300 s straggler hold. Latency comes +from `onMessageReceived`'s trace line, joined to the send manifest on `spike_seq`, so a push +that never arrived and a push that arrived late are different outcomes rather than the same +silence. + +--- + +## Delivery + +**139 observable sends, 139 delivered, 0 dropped, 0 priority downgrades.** + +| Cell | Delivered | Priority downgraded | Bucket the app actually saw | +|---|---|---|---| +| `active` / silent | 20 / 20 | 0 | `active` for 4 sends, then `working_set` | +| `working_set` / silent | 19 / 19 observable | 0 | `working_set` throughout | +| `frequent` / silent | 20 / 20 | 0 | `frequent` throughout | +| `rare` / silent | 20 / 20 | 0 | `rare` throughout | +| `restricted` / silent | 20 / 20 | 0 | `restricted` throughout | +| `active` / visible | 20 / 20 | 0 | `active` throughout | +| `restricted` / silent, deep Doze | 20 / 20 | 0 | `restricted` throughout | + +The `working_set` run's 20th send is not a miss. Logcat capture stopped at 18:44:02 and that +push was not due until 18:44:10 — the window was never observed, so it is excluded rather +than counted as a drop. + +A seventh capture exists, `active-silent-20260909T151759.log.gz`, holding three sends from an +aborted first attempt. It is excluded from every figure here. + +## Latency + +The device clock runs behind the host that timestamps the sends, which puts a floor of about +−330 ms under every reading. Each run is corrected against its own floor (−322 to −397 ms +across the seven), which is what `parse-bucket-log.py` does for a single run; earlier revisions +of this document used one global floor and so quoted figures a few ms off these. + +The floor is each run's own fastest sample, which is a noisy estimator of the true skew. Two +runs whose raw distributions match can end up tens of milliseconds apart after correction +purely because one happened to catch a faster outlier. Differences of that size between rows +should not be read as real. + +| Bucket the app reported | n | median | p95 | worst | +|---|---|---|---|---| +| `restricted` | 20 | 61 ms | 233 ms | 444 ms | +| `active` | 24 | 96 ms | 203 ms | 116 s (see below) | +| `working_set` | 35 | 104 ms | 322 ms | 543 ms | +| `frequent` | 20 | 122 ms | 545 ms | 749 ms | +| `rare` | 20 | 138 ms | 529 ms | 836 ms | +| `restricted`, deep Doze | 20 | 131 ms | 316 ms | 317 ms | + +The first five rows are charging cells, grouped by the bucket the app reported rather than the +one the run requested — see below. The `active` row mixes 4 silent observations with 20 visible +ones; every other row is silent only. The last row is the deep-Doze cell, kept separate because +its power state differs. + +**Bucket depth did not gate delivery.** The most throttled bucket Android has, `restricted`, +delivered all 20 and posted the lowest median in the matrix. A 61-to-138 ms spread across five +buckets, with per-bucket p95s that overlap each other, is not a bucket effect — it is the +noise floor of the measurement. High priority is documented to bypass Doze and bucket +deferral, and on this device it does. + +## A visible notification holds `active`; a silent push does not + +`am set-standby-bucket active` is a request the OS re-evaluates, not a latch. In the silent +cell the runner re-asserted it every 45 seconds and the app still reported `working_set` from +the fifth push onward — roughly twelve minutes in. + +The visible cell ran the same pinner against the same app and held `active` for all 20 sends, +just over an hour. The difference between the two runs is the notification: a push the user +can see is itself a signal that keeps the app in `active`, and a silent one is not. + +Two consequences: + +- **The silent `active` cell has n=4, not n=20.** Sixteen of its sends are `working_set` + observations wearing the wrong label, which is why they are counted under `working_set` + above. +- **Any measurement that assumes a pinned bucket is measuring something else.** The per-send + bucket label in the trace is what makes this visible; without it the run would have produced + twenty clean-looking `active` rows that were mostly not active. + +Analysis has to key on the reported bucket rather than the requested one. This run's parser +does. + +## One 116-second delivery, unexplained + +`active-visible-001` was sent at 21:53:26 and reached `onMessageReceived` at 21:55:23.568, +which the app's own trace records as `latency_ms=115608`. Every other send in the matrix +landed inside 850 ms. + +Two candidate explanations were checked against the capture and both fail: + +- **Not the app freezer.** The delivery is preceded by + `sync unfroze 6266 com.flipcash.app.android for 3`, but that line precedes *every* delivery + in the cell — the process is frozen between pushes and unfrozen to receive each one. The + other 19 unfreezes cost ~100 ms. +- **Not an FCM retry.** GMS arms a `FcmRetry` alarm alongside this delivery, but it does so on + every delivery in every cell (29 to 45 per capture), so its presence says nothing about this + message. + +What is distinctive is position: this was the first push of a cell, sent six seconds after the +cell started and one second after logcat began recording. But the first pushes of the +`frequent` and `restricted` cells cost 384 ms and −122 ms, so "first of a cell" is not +sufficient on its own. + +It stays on the record as one unexplained outlier in 119, not averaged away. A 116-second +delay is past the point where preloaded content would still be waiting when the user opens the +app, so if it recurs on battery it stops being a curiosity. + +## The first six cells were measured on a charging device + +`dumpsys battery` reported USB powered, 100%, and `dumpsys deviceidle get deep` reported +`ACTIVE` — deep Doze never engaged for any of the six. + +That was built into the harness rather than overlooked: the runner drove the device over USB +adb, and a device on USB is charging and therefore Doze-exempt. So those six describe delivery +to a plugged-in phone, which is close to the best case and not the case the preload design has +to survive. + +Two things closed the gap. `adb tcpip` took the runner off the cable — the connection needs an +`adb kill-server` after it, because the server holds stale state from the restart of `adbd` and +reports "No route to host" against a device that is plainly listening. And the runner now +samples power and idle state before every send into a `.power` sidecar, so the state a cell ran +in is a property of the capture rather than of a spot check taken beside it. + +## `restricted` under deep Doze, on battery + +**20 / 20 delivered, no priority downgrades, and the chat feed fetched successfully every +time.** `deep=IDLE` on all 20 pre-send samples; the only `IDLE_MAINTENANCE` reading is the +final one, taken after the straggler hold. The app reported `restricted` for all 20. + +Delivery timing is indistinguishable from the same cell on mains: + +| push → `onMessageReceived` | median | p95 | worst | +|---|---|---|---| +| deep Doze, battery | 131 ms | 316 ms | 317 ms | +| charging | 61 ms | 233 ms | 444 ms | + +Do not read the median gap as a Doze penalty. The two runs' *uncorrected* medians are −266 and +−267 ms — the same number — and the whole difference comes from their skew floors, −397 ms +against −328 ms. The tail moves the other way, with Doze's worst case 317 ms against 444 ms. +Both cells sit inside the noise of the matrix. + +**The push woke the process, and the process reached the network.** Waking a frozen process +proves nothing on its own if the network is still shut. On each of the 20 pushes the app brought +its gRPC channel from `CONNECTING` to `READY`, issued `GetDmChatFeedRequest`, and logged +`The request was processed successfully`: + +| push → first successful RPC | n | median | p95 | worst | +|---|---|---|---|---| +| deep Doze, battery | 20 | 373 ms | 455 ms | 521 ms | +| charging | 21 | 524 ms | 1208 ms | 1891 ms | + +So on this device, a `restricted`-bucket app in deep Doze on battery went from a silent push to +a completed chat-feed fetch in under 530 ms, worst case. + +**That is not the preload path, and an earlier revision of this document said it was.** The trace +reads `actions=0` on all 20 of these pushes, so no `PushAction` ran and no push handling took +place. The fetch is the event stream reconnecting once the push woke the process. What the cell +establishes is the precondition for a preload — a push in the most throttled bucket, under forced +deep idle, wakes the process, and the process can then reach the network — rather than the preload +itself. + +One error per push appears in both cells — `An error occurred while processing the request`, +about 20 s after delivery, following `EventStreamingController: Stream error: Event stream +timed out`. It occurs 20 times in the Doze cell and 21 times in the charging cell, once per +push in each, so it is the event stream's own reconnect behaviour and not something Doze did. + +### What this cell does not establish + +- **Forced idle is not naturally-entered Doze.** `deviceidle force-idle` applies the same + restriction set but skips the motion and screen gating that normally precedes it. A phone + that reached deep idle on its own, in a pocket, over hours, is a longer test than this one. + This has since been run — see the natural-idle cell below. Delivery held; the app's network + activity did not, though not for the reason first recorded here, since neither cell exercised + push handling at all. +- **The battery was unplugged at the framework level, not physically.** Every power decision + above the driver was taken as if on battery, which is where Doze decisions are made, but this + says nothing about behaviour at a low charge level or under thermal pressure. +- **Wi-Fi adb held a live socket to the device throughout**, so the radio was up for the whole + hour. A device with no debugger attached may let the radio idle harder. +- **One device, one OEM, one Android version.** Samsung's power management is its own; this + result should not be read as an Android-wide guarantee. + +## `restricted` under Doze the device entered on its own + +The forced cell's first caveat was that `force-idle` skips the gating real Doze applies. That +cell has now been re-run with nothing overridden: phone physically unplugged, screen off, left +untouched until the framework reached deep idle by itself, over Wi-Fi adb. All 22 power samples +read `plugged=[ac=false,usb=false,wireless=false]`, and `dumpsys deviceidle` reported +`mForceIdle=false` throughout. + +Raw: `raw/restricted-silent-natdoze-20260910T102101.{log,sends,power}`. + +**Delivery survives the stronger condition.** 20 sent, 20 delivered, none missing, none +downgraded, every one reporting `bucket=restricted`. + +**Latency does not.** Three consecutive pushes were held and then released together: + +| seq | sent at | held | delivered at | +|---|---|---|---| +| 011 | +1816s | 182 ms | +1815.8s | +| 012 | +1999s | 397.9s | +2396.5s | +| 013 | +2182s | 216.3s | +2397.9s | +| 014 | +2363s | 35.0s | +2397.6s | +| 015 | +2545s | 0 ms | +2544.6s | + +Three pushes sent three minutes apart arriving within 1.4 seconds of each other is a maintenance +window flushing a queue, not three independent delays. The `.power` sidecar agrees from the other +side: 21 of 22 samples read `deep=IDLE`, and the one that does not is the pre-send sample for 015, +which reads `deep=IDLE_MAINTENANCE`. + +Split on that boundary, against this run's own skew floor of −405 ms: + +| push → `onMessageReceived` | n | median | p95 | worst | +|---|---|---|---|---| +| between windows | 17 | 182 ms | 506 ms | 616 ms | +| held for a window | 3 | — | — | 397.9s | +| forced idle, for comparison | 20 | 131 ms | 316 ms | 317 ms | + +Between windows, natural Doze looks exactly like forced Doze. The difference is entirely the tail, +and forcing is what hid it: `DOZE=1` re-asserts `force-idle` before every send, which suppresses +the maintenance windows this cell exists to observe. The forced cell did not measure a device that +had no deferral; it measured a device that was not allowed to flush. + +### The app received all 20 and did no network work on any of them + +The forced cell's stronger claim was that the app completed a chat-feed fetch on every push. That +does not reproduce. Counting log lines from the app's own pid, the same process (6266) in both +cells: + +| tag | forced idle | natural idle | +|---|---|---| +| `LoggingKt \| trace` (deliveries) | 61 | 20 | +| `[RpcLogging]` | 314 | 0 | +| `[gRPC]` | 151 | 0 | +| `[event-streaming]` | 178 | 0 | +| `[BIDI]` | 60 | 0 | +| total app-pid lines | 4,957 | 391 | + +`onMessageReceived` ran 20 times. No gRPC channel was opened, no RPC was issued, and no RPC +completed — including for 015, which arrived *during* the maintenance window. + +**Neither cell asked the app to do anything.** Both read `actions=0` on every send, so the +difference between them is not one of push handling. What differs is that the forced capture's +event stream was alive and cycling — 41 `Stream error`, 15 `Event stream timed out` — and the +natural capture contains none of that machinery at all. + +**The silence is not network denial.** Denied network leaves failed attempts behind. Pid 6266 +logged no network activity of any kind across the hour: no attempt, no failure. The seven +`UNAVAILABLE` and four `NetworkException` lines in the capture belong to other processes — +location reporting, the sync service, Play services — and none to the app. It did not try. + +**The control does not settle it either.** That run was itself `actions=0`, so it tested nothing +about push handling; what it shows is that a push to an awake device wakes the process into doing +work, which was never the point in doubt. An earlier revision of this document offered it as proof +that the app was healthy and the absence was therefore Doze. It does not support that. Whether the +forced/natural difference is Doze or app state — an event stream alive at 00:30 and gone by 10:20 — +is not resolved by anything in these two captures. + +Incidentally the control prices the wake fan-out two parallel investigations have flagged: one +silent push cost eight successful RPCs, none of them asked for by the push. + +### The aborted first attempt + +`raw/restricted-silent-natdoze-20260910T095802.*` is a 5-send capture from the same condition, +kept because it is valid as far as it goes: 5/5 delivered, all five pre-send samples on battery at +`deep=IDLE`. It ended at send 5 when Wi-Fi adb dropped the session and `set -e` took the runner +down — the phone was still in unforced deep idle when it died. The harness now survives that; see +the defects section. + +## The matrix never exercised the push handling path + +Every trace line the matrix produced carries an `actions=` field, and across all seven cells it +reads `actions=0`. 139 sends, no exceptions, plus the awake control run afterwards. + +`NotificationService.onMessageReceived` derives every unit of work from the `flipcash_payload` +data key. `planPushHandling` hands that to `syncActionsFor`, which returns an empty list when the +payload is null (`PushHandlingPlanner.kt:36`), and `onMessageReceived` returns before dispatching +anything. The runner sent `{spike_seq: …}` and nothing else, so the payload was null on every push +in every cell. + +The matrix was built to tell a missing push from a late one, and it does that correctly — the +`spike_seq` correlation, the delivery counts and the latency figures are all unaffected. What it +cannot speak to is what the app does with a push, because it never sent one the app was built to +act on. The field naming that miss was in every line being read. + +Three consequences, two for the cells above and one for the design. + +**The forced cell's RPCs were real, and were not the preload.** They are locked to the sends: 40 +successful RPCs, exactly two per push, each pair 450–650 ms after its own push trace, at the 180 s +send cadence. That is not background noise, and calling it ambient would be wrong. But with +`actions=0` no `PushAction` ran, so the fetch came from the event stream reconnecting once the +push woke the process — a wake effect, not push handling. + +**The natural cell's silence was an app that was never asked.** Not a network it was denied: see +the section above for why the two look different in the capture. + +**Silent preload was gated on a flag while these cells ran.** `planPushHandling` consulted +`PushSilentSync` when the title was null, and the flag defaulted to `false`, so a data-only push +did nothing on a default build however well formed its payload. The flag was on for the device +under test — established by sending one silent push carrying a payload and reading `actions=2` +back, against `actions=0` for all 139 committed sends. The flag has since been removed and a +data-only push plans its sync unconditionally, so a re-run needs no flag setup; every number below +was still measured with it on. + +This also constrained how the remaining cells could be run. A visible push cannot measure Doze: +posting the notification lights the screen, and screen-on ends deep idle. One visible smoke push +took the device from `IDLE` to `ACTIVE`. So a Doze cell has to be silent. + +## Re-run with a payload the app acts on — four samples, then the phone went away + +`raw/restricted-silent-natdoze-20260910T113729.*`. Twelve silent pushes were planned, 180 s apart, +`restricted`, natural deep idle on battery, carrying `flipcash_payload=IAU=` — a two-byte +`flipcash.push.v1.Payload` holding `category=CONTACT_JOIN` and nothing else, which plans +`RefreshFeed` + `SyncContacts` without naming a chat or a contact. + +**The cell aborted at send seven.** Wireless adb went unreachable at sends five, six and seven, and +the runner's three-consecutive-failure guard stopped it. Sends five and six went out but were never +observed, so the traced sample is four. + +**All four handled pushes behaved identically, and the handler completed.** + +| Reading | Value | +|---|---| +| Traced pushes | 4, all `actions=2`, all pid 6266 | +| Power state at every sample | `deep=IDLE`, 5 of 5 | +| `GetDmChatFeedRequest` | 8 — two per push | +| `The request was processed successfully` | 8 — two per push | +| Contact RPCs | 8 — two per push, all `UNAVAILABLE: contact list service disabled` | +| Trace line to both feed RPCs complete | 0.51–0.65 s | + +The contact failures are not network failures. `contact list service disabled` is an application +answer from the backend, which means the RPC left the device, reached the server and came back. So +both halves of the planned action list ran: `RefreshFeed` fetched, and `SyncContacts` was refused +for a reason that has nothing to do with Doze. + +**What four samples support:** the push handling path is not blocked under Doze the device entered +on its own, on a `restricted`-bucket app that is not on the Doze allowlist. That is the thing seven +earlier cells and 139 sends never tested. + +**What they do not support:** any rate. Four consecutive successes cannot distinguish "always works" +from "works until the maintenance window moves", and the cell was designed for twelve partly to see +whether behaviour degrades across a longer idle. The re-run below supplies the missing eight. The adb +drops that ended this cell look like Wi-Fi power management during idle, which is the same failure the +`9b21c6b76` retry loop was added for and did not survive. + +## The same cell, finished — twelve samples, and the app got killed halfway through + +`raw/restricted-silent-natdoze-20260910T131820.*`. Identical settings to the aborted run: +`restricted`, silent, 180 s apart, natural deep idle on battery, `flipcash_payload=IAU=`. Twelve +sends, twelve traced. + +| Reading | Value | +|---|---| +| Delivered | 12 of 12, 0 missing | +| Priority downgraded | 0 of 12 | +| `actions=2` | 12 of 12 | +| Power state | `deep=IDLE`, `light=OVERRIDE`, `bucket=45` at all fourteen samples — `start`, twelve `pre-`, `end` | +| Latency | min -335, median -81, p95 695, max 939 ms (skew floor -335 ms) | +| Feed RPCs per push | 4 `GetDmChatFeedRequest`, 2 completions, uniform across all twelve | +| Contact RPCs per push | 2, all `UNAVAILABLE: contact list service disabled` | + +Four request lines per push against two completions is twice what the four-sample cell logged. The +shape is two requests within 5 ms of the trace line, then two more that each complete: pushes one +through eight had 5.4 s between the pairs, pushes nine through twelve had 0.35 s. That is two +callers rather than a retry: the push's `RefreshFeed` and the event stream's reconnect handler both +call `FeedSyncDelegate.syncFeed()`, which cancels any sync already in flight before launching its +own, so the loser is cancelled after it has issued its RPCs. See below. + +Combined with the aborted cell, that is sixteen payload-carrying pushes at `deep=IDLE` in +`restricted`, all delivered, all planning two actions, all reaching the network. + +### The app was SIGKILLed mid-cell, and the next push brought it back + +Between send five and send six the platform killed the app: + +``` +13:31:22.390 I/ActivityManager: Killing 1307:com.flipcash.app.android/u0a309 (adj 905): + excessive cpu 13300 during 300059 dur=854340751 limit=2 +``` + +`adj 905` is the cached bucket, so this is the background CPU killer: 13.3 s of CPU inside a 300 s +window, about 4.4%, against a 2% limit. It happened three times across the two payload cells — +pid 6266 at 11:50:15 (7,240 ms), pid 1307 at 13:31:22 (13,300 ms), pid 3633 at 13:56:15 (6,730 ms). +The last of those landed during the straggler hold after send twelve, so it cost no samples; the +first ended the four-sample cell. + +What happened next is the finding. Send six arrived 129 s after the kill, into no process at all: + +``` +13:33:30.790 START_DEBUG: ProcessRecord{8f1da92 3633:com.flipcash.app.android/u0a309} +13:33:31.468 onMessageReceived | seq=restricted-silent-006, actions=2, silent=true, bucket=restricted +13:33:34.848 authState change Unknown => Authenticating +13:33:34.864 database init start ZaFTTj4o +13:33:34.878 database init end +13:33:35.014 authState change Authenticating => Ready +13:33:38.074 Request: [GetDmChatFeedRequest ... +``` + +A data-only push, to a `restricted`-bucket app, under deep idle the device entered on its own, cold- +started the process, opened the Room database, completed soft login and fetched. Sends seven through +twelve then ran in pid 3633 exactly as one through five had run in 1307. + +The cost is startup latency, not delivery: 6.6 s from the push to the first RPC on the cold process, +against 14 ms warm. For a preload that is the difference between content being ready and content +arriving while the user is already looking at the screen. + +### What burned the CPU: the wake, not the stream + +The bill is push-driven almost in full. Binned into 30 s buckets, the process logs a ~415-line burst +at each push and nothing at all in between — the quiet stretches are two minutes wide and completely +empty. The stream traffic that looked like a free-running reconnect loop is per-push and one-to-one: +12 `onMessageReceived`, 24 `flipcash-stream => CONNECTING` (two per push), 12 `=> READY`, 11 `Event +stream down, syncing feed and reconnecting`, 10 `Event stream timed out`. Every one of them falls +inside a burst. + +Regressing each kill's CPU against the app-owned log lines inside its own 300 s window: + +| pid | window | CPU | app lines | ms/line | +|---|---|---|---|---| +| 1307 | 13:26:22–13:31:22 | 13,300 ms | 861 (two bursts) | 15.45 | +| 3633 | 13:51:15–13:56:15 | 6,730 ms | 431 (one burst) | 15.61 | +| 6266 | 11:45:15–11:50:15 (aborted cell) | 7,240 ms | 808 | 8.96 | + +The two windows from the same run agree to within 1%. Solving them for a per-burst cost and an idle +rate gives **~6.7 s of CPU per push**, plus a residual of ~0.5 ms per idle second. Only the first +term survived direct measurement — a frozen process reads zero ticks, and the residual turned out to +be burst edges attributed to the gap beside them. See *An untouched cached process costs nothing, +because it is frozen* below. + +That reverses the cadence caveat. 6.7 s is 2.24% of a five-minute window on its own, so **one push +per five minutes already exceeds the 2% limit**, and break-even is a push every ~335 s. The 180 s +cadence decides how fast the kill arrives, not whether it arrives. + +Within a burst the work is front-loaded. Taking pid 3633's 13:36:31 push, 435 lines over ~88 s: + +| Phase | Wall | Lines | +|---|---|---| +| Wake → stream `READY` (reconnect, 162 SQLite statements) | 6.8 s | 205 | +| Feed sync + contact sync | 0.9 s | 207 | +| Stream alive, 5 s pings | 39.4 s | 7 | +| Stream times out, second reconnect cycle | 41.1 s | 16 | + +95% of the logged work is in the first 7.7 s. Holding the stream open is nearly free; +re-establishing it is not. + +### Why a cached process holds a stream open at all + +`RealChatCoordinator.onStop` does tear the stream down — `stopHeartbeat()` then `close()`. It cannot +run here. `onStop` requires the process lifecycle to have reached STARTED, and a push-woken process +never does: the capture has zero `Lifecycle resumed` and zero `teardown complete` lines across 40 +minutes. pid 3633 was created for an FCM broadcast and never had a UI. + +The stream gets opened anyway. Soft login during push handling fires `Events.OnLoggedIn`, which +reaches `onUserLoggedIn`, which calls `open()` and `startHeartbeat { syncFeed() }` with no lifecycle +check; the connectivity observer in `wireDelegateRouting()` calls `open()` on the same terms. A +headless process therefore acquires a stream and a supervisor that nothing in that process can stop. + +The freezer turns that into per-wake cost. A cached process is SIGSTOPped, so the 30 s heartbeat tick +and the stream's own ping timeout both come due while it is suspended and both fire on the next thaw. +Every burst opens the same way: + +``` +13:36:31.815 flipcash-stream => CONNECTING +13:36:31.815 Event stream down, syncing feed and reconnecting +13:36:31.816 event-stream: Timed out, signaling error for reconnect +``` + +The backoff policies are not at fault: `OpenStream` and `EventStreamDelegate.reopenBackoff` both cap +at 30 s and neither spins. The cost is that each wake pays a fresh gRPC connect plus a full +`syncFeed()` from `onReconnect`, on top of the `RefreshFeed` the push asked for. + +Four changes follow, in cost order: + +1. Gate `open()` and `startHeartbeat()` on the process lifecycle having reached STARTED, in + `onUserLoggedIn` and in the connectivity observer. A push-woken process then does its push work + and never touches the stream, which removes the reconnect, the pings and the second reconnect + cycle. +2. Make the heartbeat freeze-aware — compare wall clock across the `withTimeoutOrNull` wait, so a + 180 s gap on a 30 s tick reads as *we were frozen* rather than *the server dropped us*. +3. Coalesce `syncFeed()` within a short window instead of cancelling and relaunching, so two callers + cost one round trip. +4. Skip the contact `FullUpload` when the service is disabled. It ships the entire phone book on + every push and is refused every time. + +**One caveat on the 6.7 s.** The capture build had `TraceManager.includeRpcBodies = true`, so +`LoggingClientCallListener` builds a full proto `toString()` of every request and response — about +55 KB per burst, including the whole contact list and the whole feed with blurhashes and CDN URLs — +and `SQLiteTime` logs every statement at VERBOSE, ~285 per burst. A release build constructs none of +those strings. Treat 6.7 s as an upper bound and re-measure with bodies off before quoting it as a +production figure. The structure it describes — a headless process reconnecting a stream and +full-resyncing on every wake — does not depend on the logging. + +### What this says about option B's Android half + +- **Reliability, as far as twelve samples can say it.** No degradation across 33 minutes of + continuous idle, and no drop when the process underneath changed. +- **Process death is not a delivery failure here.** FCM re-created the process and the handler ran. + The preload design does not need the app to stay resident. +- **The CPU killer is a real constraint, and it is the push path that trips it.** Three kills in + two cells, at 2.2–4.4% average CPU while cached. Each push costs ~6.7 s of CPU, which is 2.24% of + a five-minute window on its own, against an idle cost of zero, since a cached process is frozen + rather than merely quiet. The cadence accelerates the kill rather than causing it, and the ten + `Event stream timed out` errors and 24 `flipcash-stream => CONNECTING` transitions are not work + running alongside the pushes — they are two reconnects per push, triggered by the wake. Preload + work would land inside a window that is already over budget. +- **`actions=2` is the plan, not the outcome.** It is what `planPushHandling` returned. The feed + RPCs prove `RefreshFeed` ran; `SyncContacts` was refused by the backend. Neither is instrumented + to report completion. + +One device, one OEM, one Android version — unchanged. + +## Where this leaves the kill criterion + +The criterion was: *rare-bucket delivery materially better than documented weakens the argument +against option A; delivery as poor as documented settles it.* + +Measured, delivery is better than documented — not just in `rare` but in `restricted`, and with +no drops anywhere. On the evidence collected, bucket assignment is not a reason to reject +option A. + +**The measurement the argument turns on has now been taken twice, and delivery agrees both +times.** The most throttled bucket Android has, in deep idle, on battery, delivered all 20 +pushes — with idle forced, and again with idle reached naturally. Bucket assignment is not a +reason to reject option A on this device. + +**What neither cell supports is any claim about the preload running.** Both read `actions=0` +throughout, so the forced cell's chat-feed fetch was the event stream reconnecting after the wake +and the natural cell's silence was an app that was never asked to do anything. Sizing option A +against either would be sizing it against the wrong measurement. + +**The re-run is the first cell to put the question properly, and across both attempts it says the +path is not blocked.** Sixteen pushes handled at `deep=IDLE`, sixteen times `actions=2`, feed RPCs +that completed every time. Twelve of those ran consecutively across 33 minutes of unbroken idle with +no degradation, which is as close to a rate as this rig produces. + +**What the finished cell added was a constraint the matrix was not looking for.** The platform +SIGKILLed the app mid-cell for excessive background CPU, three times across the two payload cells, +and delivery survived it — the next push cold-started the process, which opened the database and +authenticated before fetching. Delivery is not what the CPU killer threatens. Latency is: 6.6 s to +the first RPC cold against 14 ms warm. + +Generality is unchanged — one device, one OEM, one Android version. The other open question has +shrunk: the natural cell's silence was an app with nothing to do, and the re-run shows that same +process reaching the network under natural idle once the payload asks it to. The forced cell's +unprompted reconnect traffic has closed too, and it was never about Doze: a push-woken process opens +the event stream during soft login and never reaches the lifecycle state that would close it, so +every thaw fires the heartbeat and the stream's ping timeout together and pays a reconnect plus a +full feed sync. Note that the +spec's objection has narrowed rather than closed: high-priority FCM was never the missing +ingredient, since every push in every cell was sent `priority: "high"` and none was downgraded. + +## Harness defects found and fixed + +- **`run-bucket-matrix.sh` exited 0 when the device was gone**, producing three empty cells + that looked like completed work. It now fails fast on a missing device, and checks again + after the straggler hold so a mid-run disconnect is reported rather than read as a delivery + failure. +- **`adb logcat` hung for ~16 minutes** after the device vanished, which is why the first + `working_set` cell reports finishing at 19:00:39 when its last trace is 18:44. +- **The device model and Android version were unrecorded.** The runner now writes them into + each log's header before logcat starts appending. +- **`parse-bucket-log.py` read the log twice**, which silently returned zero deliveries for a + `<(gunzip -c …)` argument, since a process-substitution FIFO can only be read once. It now + makes a single pass and opens `.gz` natively. + +- **Nothing recorded the power state a cell ran in**, so the charging caveat on the first six + cells rests on spot checks taken beside the captures rather than on the captures themselves. + The runner now writes AC/USB/wireless power, deep and light idle state, and the standby bucket + to a `.power` sidecar before every send, and `DOZE=1` aborts the run if the device does not + reach `IDLE` instead of quietly measuring the charging case again. + +**A dropped Wi-Fi adb session killed the cell rather than a sample.** The first natural-idle +attempt died at send 5 of 20 on `adb: device offline`, with the phone still in unforced deep idle +on battery — TCP 5555 was open when probed and the device re-authorized within ten seconds on its +own, so adbd had reset the session and nothing about the device had changed. Under `set -e` a +failed `dumpsys` inside `power_sample` took the run down, and logcat, which is the capture, died +with it. `adb_try` now retries one-shot calls for `ADB_GRACE` seconds and `power_sample` degrades +to `unreachable`; three consecutive unreachable sends still fail the run. logcat runs under a +supervisor that reattaches from the last stamped line and marks the gap. Fixed in `9b21c6b76`; the +re-run recorded zero gaps. + +**The runner sent a payload the app is built to ignore**, which is why seven cells measured +delivery and nothing else. `PAYLOAD` now injects a base64 `flipcash.push.v1.Payload` as the +`flipcash_payload` data key. Checked against the device before use: visible plus payload reads +`actions=3`, silent plus payload reads `actions=2`, against `actions=0` for all 139 committed +sends. This was the costliest defect in the harness — the `actions=` field that exposes it was +present in every trace line the earlier cells were read from. + +**A visible push cannot be used to measure Doze.** Posting the notification lights the screen and +screen-on ends deep idle; one visible smoke push took the device from `IDLE` to `ACTIVE`. Doze +cells have to be silent, which on the build these cells ran against meant `PushSilentSync` on. + +**`DOZE=natural` woke the device it was waiting on.** The setup pressed `KEYCODE_HOME` to +background the app. HOME is a wake key, so on a screen-off phone it lit the display and restarted +the idle countdown. Skipped under `natural`, where the device is already asleep and the app already +backgrounded. + +## Sizing the preload against the 2% ceiling + +The killer's rule is a budget: 2% of a 300 s window is **6000 ms of CPU**, and a cached process that +spends more than that is SIGKILLed. How many pushes fit is that budget minus what the process costs +while nothing is happening, divided by what one push costs. The regression above produced both terms +from log volume. One of them has now been read directly. + +### An untouched cached process costs nothing, because it is frozen + +Sampling `/proc//stat` utime+stime once a minute for **906 s**, with the app cached, the screen +off and the phone physically unplugged, the counters do not move at all: + +| | | +|---|---| +| Samples | 16, at 60 s | +| Span | 906 s | +| `oom_score_adj` | 910 throughout (kills have been seen at 700, 900 and 905) | +| `cgroup.freeze` | `/sys/fs/cgroup/apps/uid_10309/pid_5303/cgroup.freeze` = 1 | +| utime + stime | 2221 + 199 ticks at the first sample, and at all fifteen after it | +| Delta | **0 ticks** | + +`CLK_TCK` is 100, so a tick is 10 ms and zero ticks over 906 s bounds idle at under 11 µs per second +— under 10 ms of the 6000 ms allowance, whichever 300 s window you take. The mechanism is in the +third row: the process is frozen, so it is not sleeping cheaply, it is not running at all. + +**That is not the quantity the regression called idle.** Its ~0.5 ms per idle second was fitted +across windows in which pushes arrived every 180 s, so it is the residue either side of a burst — +thaw, timer catch-up, the stream's ping timer — attributed to the gap it sat in. Measured with +nothing arriving, the floor is zero. The practical consequence is that the budget has one term: the +whole 6000 ms is available to push work, and what remains is the cost of one push and how many of +them a window holds. + +### The answer, at the measured cost + +The instrument has now been run. `scripts/spike/measure-push-cpu.sh` brackets `/proc//stat` +utime+stime around each send, takes a push-free window first for the idle term, and gates each window +on the process having actually reached cached before the push lands. + +Twelve endpoint brackets across three cells, plus one burst sampled at 2 s: + +| Cell | Spacing | n | Per-push (ms) | Mean | +|---|---|---|---|---| +| 240 s, first attempt | 240 s | 4 | 1810, 2200, 1830, 2180 | 2005 | +| 240 s, repeat | 240 s | 3 | 1930, 1990, 2290 | 2070 | +| 420 s | 420 s | 5 | 2680, 2210, 2430, 1970, 2360 | 2330 | +| 2 s profile | single push | 1 | 2030 total | — | + +**A push costs about 2.2 s of CPU, not the 6.7 s the regression inferred.** That number came from log +volume; read off the counters it is a third of the size. Bodies are still on for every figure here — +this is a `debug` install, so `includeRpcBodies` is true and each RPC still builds a full proto +`toString()` — so 2.2 s is also an upper bound on production, just a much tighter one. + +The profile says where it goes: cumulative 1760 ms at t=2 s of a 2030 ms total, then roughly 10 ms +per 2 s out to t≈120 s. **87% of a burst is in its first two seconds.** The tail is the adj-700 +previous-app decay winding down, not work worth trimming. + +### The 300 s window is uptime, not wall clock + +Dividing the budget by the cost gives 6000 / 2200 = 2.7 pushes per five minutes. The device +disagrees, and not in the direction a margin would explain: + +| Cell | Process between pushes | Pushes | Outcome | +|---|---|---|---| +| 120 s spacing | never frozen, adj 0 then 700 | 10 | survived | +| 240 s spacing | cached and frozen | 5 | killed on #5 | +| 240 s spacing, repeat | cached and frozen | 4 | killed on #4 | +| 420 s spacing | cached and frozen | 5 | survived | + +The 120 s row is the voided first attempt, whose readings are unusable because it never backgrounded +the app. Whether the process survived is not a reading, so that row still counts, and it is the row +that makes the pattern impossible to read as a rate: ten pushes at the tightest spacing survived +while four at an intermediate spacing did not. No rate expressed in wall-clock seconds produces that +ordering. The kill record from the repeat cell +resolves it: + +``` +am_kill: [0,12639,com.flipcash.app.android,900,excessive cpu 6230 during 300043 dur=1750357 limit=2,249060] +``` + +6230 ms charged. The three windows measured for that process sum to 1930 + 1990 + 2290 = **6210 ms**. +The instrument and AMS agree to 0.3%, which retires the discrepancy this document previously could +not account for. But those three bursts are 240 s apart, so first to last is at least 480 s of wall +clock, and AMS calls the interval between them `300043`. **The window is 300 s of `uptimeMillis()`, +which does not advance across suspend.** + +How much wall clock a window covers is then a question about how much the phone suspends. Two +readings of `dumpsys batterystats`, 421 s apart with the device asleep and no pushes arriving, differ +by 142 s of uptime: **33.7%**, or a 300 s window stretched across 890 s. Over the whole 14 h on +battery the figure is 38.4%. Neither is the number that applies during a push cadence, because each +push wakes the device and buys back uptime. + +The cells bracket that number better than either aggregate does. Three sends 240 s apart were charged +to one window, so the window covers more than 480 s of wall clock. The 420 s cell survived, so fewer +than three of its sends fit, putting the window at 840 s or less. A 300 s uptime window during a +cadence like this therefore spans between roughly 480 s and 840 s, and every cell follows: + +| Cell | Wall clock per window | Pushes inside it | CPU | vs 6000 ms | +|---|---|---|---|---| +| 120 s, never frozen — device stays awake, so uptime ≈ realtime | 300 s | 2.5 | ~5500 ms | under, survived | +| 240 s, frozen | 480-840 s | 2.0-3.5 | 4400-7700 ms | over at the observed 3, killed twice | +| 420 s, frozen | 480-840 s | 1.1-2.0 | 2500-4400 ms | under, survived | + +Keeping the process out of the freezer is also what keeps the device out of suspend, so the tightest +cadence is safe for the same reason the widest one is: neither manages to compress three bursts into +a single window. + +**One correction to the idle table further up.** It recorded the kills as being at `adj 905`, which +reads as though the killer only reaches fully cached processes. It does not. The two kills in these +cells name `adj 700` and `adj 900`, and AMS checks any process at `setProcState >= PROCESS_STATE_HOME`, +which +includes the previous-app slot. Handling a push promotes the process from 900 to 700 for about 135 s; +that promotion does not buy it immunity. + +### What this means for the preload + +The budget is 6000 ms per 300 s of uptime and a push costs ~2.2 s, so the app can absorb **two pushes +per uptime window**. The third is what killed it in both 240 s cells. + +Turning that into a cadence needs the suspend ratio, which is a property of the user's device and +day rather than of the app. Two pushes per 840 s is **one push every seven minutes**, which is what +420 s delivered: five consecutive pushes, no kill, and by the same bracket 2500-4400 ms against a +6000 ms budget. 240 s killed in both attempts. Treat 420 s as the fastest cadence observed to be +safe, and note the margin is thinner than the ratio 6000/2200 suggests — at the unfavourable end of +the bracket, 420 s is already using 73% of the budget. + +A chat preload driven by message arrival will exceed that on any active conversation, which leaves +two options, and the burst shape chooses between them. Coalescing server-side costs one burst per +window whatever the message volume. Trimming the handler has 87% of its target inside the first two +seconds, in the sync RPC fan-out, and almost nothing in the tail — so it is a fan-out problem, not a +timer problem. + +### What this does not establish + +Bodies were on for all of it. Production sets `includeRpcBodies` false, so the real per-push cost is +below 2.2 s by a margin nothing here measures. The `benchmark` variant would attribute it: it is +`initWith(debug)` with `isDebuggable = false` and shares the `contributors` signing key, so it +installs over the existing build and keeps the login. That run replaces the app on the test device +and was not made. + +The four fixes listed above are unmeasured against the new baseline. Each targets work inside the +first seconds of a burst, which is still where the cost sits, but 2.2 s leaves less to reclaim than +6.7 s did. + +The first 240 s cell's kill charged 7190 ms where its four preceding windows sum to 8020. A window +boundary falling inside a burst rather than between bursts would explain it, but that was not +confirmed; only the repeat cell's charge lines up closely enough to stand as evidence by itself. + +The suspend ratio during a cadence was bracketed, not measured. The 480-840 s span comes from which +cells lived and died, so it is only as tight as the two spacings tried; a cell between them would +narrow it. The direct readings either side — 33.7% over a quiet window, 38.4% over the battery's +lifetime — are both from periods that are not a push cadence. + +Generality is unchanged from the rest of this document: one device, one OEM, one Android version. The +uptime ratio travels worst of all the numbers here, since it is set by how much a given phone +suspends, which varies by device, by user, and by whatever else is installed. diff --git a/gradle/libs.versions.toml b/gradle/libs.versions.toml index 1822713f3f..9967d745b3 100644 --- a/gradle/libs.versions.toml +++ b/gradle/libs.versions.toml @@ -69,7 +69,7 @@ protovalidate-kt = "0.1.2" # 0.3.0 is the first release of either package to ship R8 keep rules for its generated # messages, which is what lets proguard-rules.pro drop its own. ocp-client-protocol = "0.3.0" -flipcash2-client-protocol = "0.4.1" +flipcash2-client-protocol = "0.5.0" # The Android port is the ONLY libphonenumber this app depends on, deliberately. Google's # `com.googlecode` artifact used to sit alongside it; the two ship separate copies of the metadata, diff --git a/maestro/spike_login.yaml b/maestro/spike_login.yaml new file mode 100644 index 0000000000..e3042eb831 --- /dev/null +++ b/maestro/spike_login.yaml @@ -0,0 +1,47 @@ +appId: com.flipcash.app.android +name: "Spike: log in with PushSilentSync enabled" +tags: + - spike +--- +# Login plus flag enablement in one launch, so the flag is set in onCreate +# and no relaunch is needed to make it stick. Run with: +# BETA_FLAGS=push_silent_sync_enabled DEVICE= maestro/run.sh maestro/spike_login.yaml +# +# The device must be unlocked. A locked screen lets launchApp succeed behind +# the keyguard, so the failure surfaces later as "Element not found: Log in". +# +# This inlines subflows/login.yaml instead of calling it, because a real device +# with a Google account raises a Password Manager autofill sheet over the seed +# screen that the CI emulator never shows. The "No thanks" taps are optional so +# the flow still runs where no sheet appears. +- clearState +- launchApp: + arguments: + isUiTest: true + betaFlags: ${BETA_FLAGS} +- extendedWaitUntil: + visible: "Log in" + timeout: 30000 +- tapOn: "Log in" +- tapOn: + text: "No thanks" + optional: true +- extendedWaitUntil: + visible: + id: seed_input_screen + timeout: 20000 +- tapOn: + id: "seed_input_field" +- tapOn: + text: "No thanks" + optional: true +- inputText: ${SEED_PHRASE} +- tapOn: + text: "(?i)Log ?In" +- tapOn: + text: "No thanks" + optional: true +- extendedWaitUntil: + visible: + id: "wallet_screen" + timeout: 60000 diff --git a/scripts/spike/measure-push-cpu.sh b/scripts/spike/measure-push-cpu.sh new file mode 100755 index 0000000000..eed2ac37e7 --- /dev/null +++ b/scripts/spike/measure-push-cpu.sh @@ -0,0 +1,193 @@ +#!/usr/bin/env bash +# Measure what one push costs the app in CPU, and derive how many fit in the +# background CPU budget. +# +# Usage: scripts/spike/measure-push-cpu.sh [count] [settle_s] +# count: pushes to measure (default 10) +# settle_s: seconds to let each push's work finish before sampling (default 120) +# +# Why /proc rather than the log-line regression in the results document: the +# killer in ActivityManager reads utime+stime out of /proc via ProcessCpuTracker +# and compares the delta against 2% of a 300 s window. Sampling the same two +# fields measures the quantity that decides the kill, instead of inferring it +# from how many lines the app logged inside a window that happened to end in +# one. The regression put a push at ~6.7 s; this is the direct reading. +# +# The measurement needs three conditions, none of which is deep Doze: +# - The framework must see battery. The check is gated on it, and a charging +# device is never killed however much CPU it burns. `dumpsys battery unplug` +# is enough; the cable can stay in. +# - The screen must be off and the process cached (oom_score_adj >= 900). The +# observed kills were at adj 905. A process that is top-sleeping or in the +# previous slot is not a candidate and is also not frozen, so it keeps +# paying timer work the cached case does not. +# - Each push needs to finish. The captured bursts ran ~90 s from wake to the +# last line, so a settle window shorter than that measures part of a push. +# Deep Doze is deliberately not required. It adds the Wi-Fi adb drops that took +# down two earlier cells and it does not change what the killer reads. +# +# The run starts with one quiet window of the same length and no push, which +# gives the idle term. Budget arithmetic needs both: the 2% allowance is +# 6000 ms per 300 s window, and idle CPU spends part of it before any push +# arrives. +# +# A pid change between two samples means the process died inside that window — +# usually the killer, which is the outcome being sized. The sample is dropped +# from the mean and reported separately, because a killed process stops +# accruing partway through work it had not finished. +# +# Set DEVICE to an adb serial when more than one device is attached. PAYLOAD is +# the same base64 flipcash.push.v1.Payload the bucket runner sends, and the +# default `IAU=` is category=CONTACT_JOIN, which plans RefreshFeed + +# SyncContacts. +set -euo pipefail + +SCRIPT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" +REPO="$(cd "$SCRIPT_DIR/../.." && pwd)" + +TOKEN="${1:?usage: measure-push-cpu.sh [count] [settle_s]}" +COUNT="${2:-10}" +SETTLE="${3:-120}" +PAYLOAD="${PAYLOAD:-IAU=}" +PACKAGE="com.flipcash.app.android" + +if [ -n "${DEVICE:-}" ]; then + export ANDROID_SERIAL="$DEVICE" +fi + +adb shell true >/dev/null 2>&1 \ + || { echo "FATAL: no device (${ANDROID_SERIAL:-default}) — nothing was measured" >&2; exit 1; } + +STAMP="$(date +%Y%m%dT%H%M%S)" +OUT_DIR="$REPO/docs/spikes/raw" +mkdir -p "$OUT_DIR" +OUT="$OUT_DIR/push-cpu-${STAMP}.cpu" + +MODEL="$(adb shell getprop ro.product.model | tr -d '\r')" +SDK="$(adb shell getprop ro.build.version.sdk | tr -d '\r')" +HZ="$(adb shell getconf CLK_TCK | tr -d '\r')" + +restore() { + adb shell "dumpsys battery reset" >/dev/null 2>&1 || true +} +trap restore EXIT + +adb shell "dumpsys battery unplug" >/dev/null + +# HOME before SLEEP, and then wait for the process to actually fall out of the +# top slot. Turning the screen off on its own is not enough: the app stays the +# top of its task as `top-sleeping` at adj 0, which is neither cached nor frozen +# and keeps paying the timer work the cached case does not. The first run of this +# script measured that state for eleven windows without noticing, because it +# recorded the adj columns instead of gating on them. +# WAKEUP first: HOME sent to a sleeping device does nothing, which is how the +# first run stayed top-sleeping through the HOME it thought had backgrounded it. +adb shell "input keyevent KEYCODE_WAKEUP" >/dev/null || true +sleep 2 +adb shell "input keyevent KEYCODE_HOME" >/dev/null || true +sleep 3 +adb shell "input keyevent KEYCODE_SLEEP" >/dev/null || true + +adj_now() { adb shell "cat /proc/\$(pidof $PACKAGE)/oom_score_adj" 2>/dev/null | tr -d '\r'; } + +waited=0 +until adj="$(adj_now)"; [ -n "$adj" ] && [ "$adj" -ge 900 ] 2>/dev/null; do + [ "$waited" -ge 300 ] && { + echo "FATAL: $PACKAGE never reached adj >= 900 (last: ${adj:-unknown}) — nothing was measured" >&2 + exit 1 + } + sleep 5 + waited=$(( waited + 5 )) +done +echo "cached at adj $adj after ${waited} s" >&2 + +# One round trip returns pid, cached-ness and the two counters together. Read +# apart they can straddle a process death and produce a negative delta. +sample() { + # utime and stime are fields 14 and 15 of /proc/pid/stat. The comm field is + # parenthesised and can hold spaces, so everything up to the closing paren + # is cut before counting: state becomes field 1, which puts utime at 12. + adb shell "pid=\$(pidof $PACKAGE); \ + if [ -z \"\$pid\" ]; then echo 'dead 0 0 0'; else \ + echo \"\$pid \$(cat /proc/\$pid/oom_score_adj) \ + \$(sed 's/.*) //' /proc/\$pid/stat | awk '{print \$12, \$13}')\"; fi" | tr -d '\r' +} + +{ + echo "# model=$MODEL sdk=$SDK clk_tck=$HZ settle_s=$SETTLE payload=$PAYLOAD" + echo "# window pid_before adj_before pid_after adj_after ticks ms" +} > "$OUT" + +# Ticks are per-core sums across the process's threads, so the value is CPU +# time and not wall time; that is what the killer compares too. +ticks_to_ms() { echo "$(( $1 * 1000 / HZ ))"; } + +measure() { + local label="$1" send="$2" + local before after p0 a0 u0 s0 p1 a1 u1 s1 ticks + before="$(sample)"; read -r p0 a0 u0 s0 <<< "$before" + [ "$p0" = "dead" ] && { echo "$label - - - - - dead_before" >> "$OUT"; return; } + if [ "$send" = "yes" ]; then + "$REPO/scripts/fcm.sh" "$TOKEN" \ + "{\"spike_seq\":\"cpu-$label\",\"flipcash_payload\":\"$PAYLOAD\"}" >/dev/null + fi + sleep "$SETTLE" + after="$(sample)"; read -r p1 a1 u1 s1 <<< "$after" + if [ "$p1" = "dead" ] || [ "$p1" != "$p0" ]; then + echo "$label $p0 $a0 ${p1} ${a1} - died" >> "$OUT" + return + fi + ticks=$(( (u1 + s1) - (u0 + s0) )) + echo "$label $p0 $a0 $p1 $a1 $ticks $(ticks_to_ms "$ticks")" >> "$OUT" +} + +measure "idle" no +for i in $(seq -f '%03g' 1 "$COUNT"); do + # A kill ends the cell. Without this the loop keeps calling measure(), which + # returns immediately on a dead process, so the remaining windows land in the + # file as `dead_before` in a couple of seconds and the run looks like it + # completed its full count. Stop and say which push was the last one. + if [ -z "$(adb shell "pidof $PACKAGE" 2>/dev/null | tr -d '\r')" ]; then + echo "process gone before window $i - cell ends here" >&2 + break + fi + measure "$i" yes +done + +# 2% of a 300 s window is 6000 ms. Subtract what idle spends over the same +# window before dividing the remainder by the cost of one push: a budget that +# ignores the idle term overstates how many pushes fit. +python3 - "$OUT" "$SETTLE" <<'PY' +import statistics, sys +path, settle = sys.argv[1], float(sys.argv[2]) +rows = [l.split() for l in open(path) if not l.startswith('#')] + +# The window has to *start* cached. That is the state the killer's budget applies +# to, and the state a push has to thaw the process out of, so it is what decides +# whether the reading is the cold cost or a warm one. It cannot also *end* cached: +# handling a push promotes the process into the previous-app slot at adj 700, +# which it holds for about two minutes after the last activity. Requiring both +# ends discards every push window by construction. +def cached(r): + return r[2].isdigit() and int(r[2]) >= 900 + +complete = [r for r in rows if r[-1].isdigit()] +uncached = [r[0] for r in complete if not cached(r)] +idle = [r for r in complete if r[0] == 'idle' and cached(r)] +push = [int(r[-1]) for r in complete if r[0] != 'idle' and cached(r)] +died = [r[0] for r in rows if r[-1] == 'died'] +if uncached: + print(f"dropped: {len(uncached)} window(s) that did not start cached: {uncached}") +if not push: + print(f"no complete push samples; {len(died)} died: {died}"); sys.exit(0) +idle_ms = int(idle[0][-1]) if idle else 0 +idle_300 = idle_ms * 300 / settle +mean, med = statistics.mean(push), statistics.median(push) +print(f"samples: n={len(push)} died={len(died)} {died if died else ''}") +print(f"idle: {idle_ms} ms over {settle:.0f} s -> {idle_300:.0f} ms per 300 s window") +print(f"push: mean {mean:.0f} ms median {med:.0f} ms min {min(push)} max {max(push)}") +budget = 6000 - idle_300 +print(f"budget: (6000 - {idle_300:.0f}) / {mean:.0f} = {budget/mean:.2f} pushes per 5 min") +PY + +echo "raw: $OUT" diff --git a/scripts/spike/parse-bucket-log.py b/scripts/spike/parse-bucket-log.py new file mode 100755 index 0000000000..506b913c1c --- /dev/null +++ b/scripts/spike/parse-bucket-log.py @@ -0,0 +1,154 @@ +#!/usr/bin/env python3 +"""Summarise one bucket-matrix run. + +Usage: scripts/spike/parse-bucket-log.py + +Joins the sends file against the onMessageReceived traces on the spike_seq id, +so a push that never arrived and a push that arrived late are different +outcomes rather than the same silence. Written against a trace line observed on +device, not a guessed format: + + 09-09 15:13:37.101 D/LoggingKt | trace (15895): onMessageReceived | \ +seq=active-silent-001, has_body=false, actions=0, silent=true, bucket=active, \ +latency_ms=-329, priority=1, original_priority=1 +""" +import datetime +import gzip +import re +import statistics +import sys + +TRACE = re.compile(r"onMessageReceived \| (.+)$") +FIELD = re.compile(r"(\w+)=([^,]+)") +# `adb logcat -v time` stamps lines "MM-DD HH:MM:SS.mmm" with no year. +STAMP = re.compile(r"^(\d{2})-(\d{2}) (\d{2}):(\d{2}):(\d{2})\.(\d{3})") + + +def read_log(path, year): + """Return (first trace per seq, epoch-ms of the last stamped line). + + One pass: the captures run to tens of MB, and a `<(gunzip -c ...)` argument + is a FIFO that cannot be read twice. + """ + opener = gzip.open if path.endswith(".gz") else open + seen = {} + last = None + with opener(path, "rt", errors="replace") as fh: + for line in fh: + stamp = STAMP.match(line) + if stamp: + last = stamp + m = TRACE.search(line) + if not m: + continue + fields = dict(FIELD.findall(m.group(1))) + seq = fields.get("seq", "") + if seq: + # First arrival wins; FCM can redeliver. + seen.setdefault(seq, fields) + return seen, stamp_to_epoch_ms(last, year) + + +def stamp_to_epoch_ms(match, year): + """Epoch-ms for one `adb logcat -v time` stamp, which carries no year. + + A run whose capture stops early makes the sends after that point look like + delivery failures. They are not measurements at all, so they have to be + separable from a push that was inside the window and never arrived. + """ + if not match: + return None + mo, d, h, mi, sec, ms = (int(g) for g in match.groups()) + try: + when = datetime.datetime(year, mo, d, h, mi, sec, ms * 1000) + except ValueError: # 02-29 against a non-leap year, etc. + return None + return int(when.timestamp() * 1000) + + +def pct(values, p): + if not values: + return None + ordered = sorted(values) + idx = min(len(ordered) - 1, int(round((p / 100) * (len(ordered) - 1)))) + return ordered[idx] + + +def main(): + if len(sys.argv) != 3: + sys.exit(__doc__) + log_path, sends_path = sys.argv[1], sys.argv[2] + + sent = [] + with open(sends_path) as fh: + for line in fh: + parts = line.split() + if len(parts) == 2: + sent.append((parts[1], int(parts[0]))) + + year = (datetime.datetime.fromtimestamp(sent[0][1] / 1000).year if sent + else datetime.datetime.now().year) + seen, end = read_log(log_path, year) + delivered = [q for q, _ in sent if q in seen] + # Only a send the capture was still running for can be called missing. + missing = [q for q, at in sent if q not in seen and (end is None or at <= end)] + unobserved = [q for q, at in sent if q not in seen and end is not None and at > end] + unsolicited = [q for q in seen if q not in dict(sent)] + + latencies = [] + downgraded = 0 + buckets = set() + for seq in delivered: + f = seen[seq] + try: + latencies.append(int(f["latency_ms"])) + except (KeyError, ValueError): + pass + if f.get("priority") != f.get("original_priority"): + downgraded += 1 + buckets.add(f.get("bucket", "?")) + + measured = len(delivered) + len(missing) + print(f"sent: {len(sent)}") + print(f"delivered: {len(delivered)}" + + (f" ({100 * len(delivered) / measured:.0f}% of {measured} measured)" if measured else "")) + print(f"missing: {len(missing)}" + + (f" {', '.join(missing)}" if missing else "")) + if unobserved: + print(f"unobserved: {len(unobserved)} {', '.join(unobserved)}" + " (capture ended before these were due — not delivery failures)") + if unsolicited: + print(f"unexpected: {len(unsolicited)} {', '.join(sorted(unsolicited))}") + print(f"bucket(s) reported by app: {', '.join(sorted(buckets)) or 'n/a'}") + print(f"priority downgraded: {downgraded}/{len(delivered)}") + + # Group by the bucket the app reported, not the one the run asked for. + # `am set-standby-bucket` is a request the OS re-evaluates mid-run, so the + # two diverge and only the reported one describes the data point. + by_bucket = {} + for seq in delivered: + f = seen[seq] + try: + by_bucket.setdefault(f.get("bucket", "?"), []).append(int(f["latency_ms"])) + except (KeyError, ValueError): + pass + if len(by_bucket) > 1: + floor = min(min(v) for v in by_bucket.values()) + print("per reported bucket, skew-corrected:") + for b in sorted(by_bucket): + v = sorted(x - floor for x in by_bucket[b]) + print(f" {b:12s} n={len(v):3d} median={v[len(v) // 2]}ms worst={v[-1]}ms") + + if latencies: + # latency_ms is device clock minus FCM sentTime, so it carries the + # device/server clock skew. A small negative floor is skew, not a push + # arriving before it was sent. + print(f"latency_ms min={min(latencies)} median={int(statistics.median(latencies))}" + f" p95={pct(latencies, 95)} max={max(latencies)}") + print(f" (skew floor {min(latencies)} ms; subtract it for a delivery-only figure)") + else: + print("latency_ms: none recorded") + + +if __name__ == "__main__": + main() diff --git a/scripts/spike/run-bucket-matrix.sh b/scripts/spike/run-bucket-matrix.sh new file mode 100755 index 0000000000..6d288c9519 --- /dev/null +++ b/scripts/spike/run-bucket-matrix.sh @@ -0,0 +1,312 @@ +#!/usr/bin/env bash +# Send data-only pushes into one standby bucket and record what arrives. +# +# Usage: scripts/spike/run-bucket-matrix.sh [count] [interval_s] [mode] +# bucket: active | working_set | frequent | rare | restricted +# count: pushes to send (default 20) +# interval_s: seconds between sends (default 180, so 20 sends span an hour) +# mode: silent (default, data-only, no title) | visible (control, with title) +# +# Each send carries a sequence id in the spike_seq data key, which the +# onMessageReceived trace logs as seq=. That is what makes a missing push +# distinguishable from a late one: correlation is per-push, not per-window. +# It is NOT carried in push_notification_body: the trace never logged the body +# (MetadataBuilder.to takes a non-null Any, so a String? resolves to kotlin.to +# and is discarded), and putting message text in a Bugsnag breadcrumb is a leak. +# +# Set DEVICE to an adb serial when more than one device is attached. +# +# DOZE=1 runs the cell under deep Doze on battery instead of the default +# charging, never-idle state. Doze is the one condition under which buckets are +# documented to withhold work, so a cell measured while charging cannot speak to +# it. The mode holds the device there for the whole run: +# - `dumpsys battery unplug` makes the framework see battery. The cable stays +# in, so the run does not depend on a charge level, but every power decision +# above the driver is taken as if unplugged. Reachability over Wi-Fi adb is +# therefore not required, though it is the more faithful setup. +# - `deviceidle force-idle` needs the screen off and the framework unplugged, +# which is why both precede it. +# - Idle is re-asserted before each send: a delivery can pull the device into +# a maintenance window, and a cell that silently left Doze after push 3 +# measures the same thing the charging cells already did. +# Both overrides are released on exit, including on failure. +# +# DOZE=natural waits for deep idle instead of forcing it. `force-idle` applies +# Doze's restriction set but skips the gating that normally precedes it — the +# screen-off timer, and the significant-motion detector that resets the whole +# countdown when the phone is picked up. A cell that reached idle on its own is +# the stronger claim, and it is the one the forced cell explicitly does not make. +# What the mode does differently: +# - Nothing is overridden. The device must be PHYSICALLY unplugged, which is +# why the mode requires adb over Wi-Fi and refuses to run on USB. +# - It polls `deviceidle get deep` until it reads IDLE, up to IDLE_TIMEOUT +# (default 2h) at IDLE_POLL intervals (default 60s), then starts sending. +# - Idle is NOT re-asserted between sends. A delivery that pulls the device +# into a maintenance window is the behaviour under test, not a defect in the +# cell, so the per-send `deep=` in the .power sidecar is the result rather +# than something the runner corrects. +# The phone must be left still for the whole run. Motion restarts Doze's +# countdown, and nothing in this script can see that happen — only the deep= +# samples will show it, after the fact. +# The mode tolerates the Wi-Fi link dropping, which it will: adb calls retry for +# ADB_GRACE seconds and logcat reattaches from where it stopped, so a reset +# connection costs an annotated gap in the capture rather than the cell. Three +# consecutive sends with the device unreachable still fail the run — at that +# point the pushes are going somewhere nothing is recording. +set -euo pipefail + +SCRIPT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" +REPO="$(cd "$SCRIPT_DIR/../.." && pwd)" + +TOKEN="${1:?usage: run-bucket-matrix.sh [count] [interval_s] [mode]}" +BUCKET="${2:?bucket required}" +COUNT="${3:-20}" +INTERVAL="${4:-180}" +MODE="${5:-silent}" +# Seconds to keep the log open after the last send, to catch stragglers. +# Lower it only for a smoke test; a real bucket run needs the full window. +HOLD="${HOLD:-300}" +# 0 (charging, never idle) | 1 (forced deep idle) | natural (idle reached) +DOZE="${DOZE:-0}" +# DOZE=natural only: how long to wait for deep idle, and how often to look. +# Each poll is an adb round trip, which nudges the device awake, so keep the +# cadence coarse — the wait is measured in tens of minutes either way. +IDLE_TIMEOUT="${IDLE_TIMEOUT:-7200}" +IDLE_POLL="${IDLE_POLL:-60}" + +# PAYLOAD is a base64 flipcash.push.v1.Payload, sent as the flipcash_payload +# data key. Without it every cell measures delivery and nothing else, because +# planPushHandling derives all sync work from that payload and returns an empty +# action list when it is absent — which is what the first seven cells did, all +# of them recording actions=0 in the trace they were read from. The two-byte +# encoding `IAU=` is category=CONTACT_JOIN and nothing else, which plans +# RefreshFeed + SyncContacts without naming a chat or a contact. +# +# Note the flag interaction: planPushHandling consults PushSilentSync only when +# the title is null, so MODE=silent measures the flag and the sync path +# together, while MODE=visible exercises the sync path whatever the flag says. +PAYLOAD="${PAYLOAD:-}" + +PACKAGE="com.flipcash.app.android" +# Target one device via ANDROID_SERIAL rather than an adb wrapper function: +# wrapping adb makes $! the wrapper subshell's pid, so the later kill misses the +# real logcat, which then keeps the script's stdout pipe open forever. +if [ -n "${DEVICE:-}" ]; then + export ANDROID_SERIAL="$DEVICE" +fi +STAMP="$(date +%Y%m%dT%H%M%S)" +OUT_DIR="$REPO/docs/spikes/raw" +# A natural-idle cell is marked in the filename. The forced and charging cells +# keep the original naming so the captures already committed still match it. +SUFFIX="" +[ "$DOZE" = "natural" ] && SUFFIX="-natdoze" +LOG="$OUT_DIR/${BUCKET}-${MODE}${SUFFIX}-${STAMP}.log" +SENDS="$OUT_DIR/${BUCKET}-${MODE}${SUFFIX}-${STAMP}.sends" +POWER="$OUT_DIR/${BUCKET}-${MODE}${SUFFIX}-${STAMP}.power" +mkdir -p "$OUT_DIR" + +# Fail before the run rather than after it. A disconnected device makes every +# adb call print "device not found" to stderr and carry on, which once produced +# three cells that reported success against no device at all. +require_device() { + adb shell true >/dev/null 2>&1 \ + || { echo "FATAL: no device (${ANDROID_SERIAL:-default}) — nothing was measured" >&2; exit 1; } +} +require_device + +MODEL="$(adb shell getprop ro.product.model | tr -d '\r')" +RELEASE="$(adb shell getprop ro.build.version.release | tr -d '\r')" +SDK="$(adb shell getprop ro.build.version.sdk | tr -d '\r')" + +# Wi-Fi adb drops, and a drop is not a result. Over screen-off Doze the phone +# resets its adbd connection: TCP 5555 stays open and the device re-authorizes +# within seconds, but every adb call issued in that window returns "device +# offline", and under set -e that took the first natural-Doze cell down at send +# 5 of 20 with the device still sitting in unforced deep idle. So one-shot adb +# calls retry, and only a device that stays unreachable for ADB_GRACE seconds is +# treated as gone. +ADB_GRACE="${ADB_GRACE:-180}" +adb_try() { + local deadline=$((SECONDS + ADB_GRACE)) out + while :; do + if out="$(adb "$@" 2>/dev/null)"; then printf '%s' "$out"; return 0; fi + [ "$SECONDS" -ge "$deadline" ] && return 1 + adb reconnect >/dev/null 2>&1 || true + sleep 5 + done +} + +# logcat dies with the connection too, and it is the capture — a cell whose log +# stops at send 5 reads as fifteen undelivered pushes. Reattach from the last +# stamped line rather than re-dumping the buffer, so the outage window is +# recovered; the parse step keeps the first trace per seq, so the overlap that +# creates is discarded rather than counted twice. Each gap is marked in the log. +logcat_forever() { + local last="" + while :; do + if [ -n "$last" ]; then + adb logcat -v time -T "$last" >> "$LOG" 2>/dev/null & + else + adb logcat -v time >> "$LOG" 2>/dev/null & + fi + echo $! > "$LOGCAT_CHILD" + wait $! 2>/dev/null || true + echo "# logcat detached $(date +%s000)" >> "$LOG" + last="$(grep -oE '^[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}\.[0-9]{3}' "$LOG" | tail -1)" + sleep 5 + adb_try shell true >/dev/null || continue + echo "# logcat reattached $(date +%s000)" >> "$LOG" + done +} + +# Power state is sampled, not assumed. The first six cells were all written up +# as "charging, therefore Doze-exempt" on the strength of spot checks taken +# outside the capture; a reader had to take that on trust. These fields make the +# claim checkable from the artefacts alone, and catch a run that drifted out of +# the state it was supposed to be measuring. +power_sample() { + local label="$1" + local plugged deep light bucket + if ! plugged="$(adb_try shell dumpsys battery | awk -F': ' ' + /AC powered/ {ac=$2} + /USB powered/ {usb=$2} + /Wireless powered/ {wl=$2} + END {printf "ac=%s,usb=%s,wireless=%s", ac, usb, wl}' | tr -d '\r')"; then + echo "$(date +%s000) ${label} unreachable" + return 1 + fi + deep="$(adb_try shell dumpsys deviceidle get deep | tr -d '\r')" || deep="?" + light="$(adb_try shell dumpsys deviceidle get light | tr -d '\r')" || light="?" + bucket="$(adb_try shell am get-standby-bucket "$PACKAGE" | tr -d '\r')" || bucket="?" + echo "$(date +%s000) ${label} plugged=[${plugged}] deep=${deep} light=${light} bucket=${bucket}" +} + +release_overrides() { + if [ "$DOZE" = "1" ]; then + adb shell dumpsys deviceidle unforce >/dev/null 2>&1 || true + adb shell dumpsys battery reset >/dev/null 2>&1 || true + fi +} + +adb shell am set-standby-bucket "$PACKAGE" "$BUCKET" +echo "bucket code now: $(adb shell am get-standby-bucket "$PACKAGE" | tr -d '\r')" +echo "device: $MODEL, Android $RELEASE (API $SDK)" + +# Background the app and let the system settle before measuring. Skipped under +# DOZE=natural: HOME is a wake key, so on a screen-off device it turns the +# display on and restarts the idle countdown the mode is waiting on — and a +# device that is already asleep has already backgrounded the app. +if [ "$DOZE" != "natural" ]; then + adb shell input keyevent KEYCODE_HOME + sleep 5 +fi + +if [ "$DOZE" = "1" ]; then + trap 'release_overrides' EXIT + adb shell input keyevent KEYCODE_SLEEP + sleep 3 + adb shell dumpsys battery unplug >/dev/null + adb shell dumpsys deviceidle force-idle >/dev/null + DEEP="$(adb shell dumpsys deviceidle get deep | tr -d '\r')" + [ "$DEEP" = "IDLE" ] \ + || { echo "FATAL: deep idle is $DEEP, not IDLE — the cell would measure the charging case again" >&2; exit 1; } + echo "deep idle: $DEEP (framework sees battery; cable may stay in)" +elif [ "$DOZE" = "natural" ]; then + # A USB link is a charger. Refuse rather than quietly measure the plugged + # case, which is exactly how the first six cells came to be Doze-exempt. + case "${ANDROID_SERIAL:-}" in + *:*) : ;; + *) echo "FATAL: DOZE=natural needs adb over Wi-Fi — set DEVICE to host:port" >&2; exit 1 ;; + esac + PLUGGED="$(adb shell dumpsys battery | awk -F': ' ' + /AC powered/{ac=$2} /USB powered/{usb=$2} /Wireless powered/{wl=$2} + END {print ac usb wl}' | tr -d '\r')" + case "$PLUGGED" in + *true*) echo "FATAL: device is still on a charger ($PLUGGED) — unplug it; Doze will not start" >&2; exit 1 ;; + esac + adb shell input keyevent KEYCODE_SLEEP + echo "waiting for deep idle (up to ${IDLE_TIMEOUT}s, polling every ${IDLE_POLL}s)" + echo "leave the phone still — motion restarts the countdown" + WAITED=0 + while :; do + DEEP="$(adb shell dumpsys deviceidle get deep 2>/dev/null | tr -d '\r')" + [ "$DEEP" = "IDLE" ] && break + [ "$WAITED" -ge "$IDLE_TIMEOUT" ] \ + && { echo "FATAL: still $DEEP after ${WAITED}s — nothing was measured" >&2; exit 1; } + echo " ${WAITED}s: deep=$DEEP" + sleep "$IDLE_POLL" + WAITED=$((WAITED + IDLE_POLL)) + done + echo "deep idle reached after ${WAITED}s, unforced, on battery" +fi + +adb logcat -c +{ + echo "# device: $MODEL, Android $RELEASE (API $SDK)" + echo "# bucket: $BUCKET mode: $MODE count: $COUNT interval: ${INTERVAL}s hold: ${HOLD}s doze: $DOZE" + echo "# power: $(power_sample start)" +} > "$LOG" +LOGCAT_CHILD="$(mktemp -t bucketlogcat)" +logcat_forever & +LOGCAT_PID=$! +# Kill the supervisor first, or it respawns the child it is watching. +stop_logcat() { + kill "$LOGCAT_PID" 2>/dev/null || true + [ -s "$LOGCAT_CHILD" ] && kill "$(cat "$LOGCAT_CHILD")" 2>/dev/null || true + rm -f "$LOGCAT_CHILD" +} +if [ "$DOZE" = "1" ]; then + trap 'stop_logcat; release_overrides' EXIT +else + trap 'stop_logcat' EXIT +fi + +: > "$SENDS" +: > "$POWER" +power_sample start >> "$POWER" +MISSES=0 +for i in $(seq 1 "$COUNT"); do + SEQ=$(printf "%s-%s-%03d" "$BUCKET" "$MODE" "$i") + if [ "$MODE" = "visible" ]; then + DATA=$(jq -n --arg s "$SEQ" \ + '{spike_seq: $s, push_notification_title: "Spike", push_notification_body: $s}') + else + DATA=$(jq -n --arg s "$SEQ" '{spike_seq: $s}') + fi + if [ -n "$PAYLOAD" ]; then + DATA=$(jq -n --argjson d "$DATA" --arg p "$PAYLOAD" '$d + {flipcash_payload: $p}') + fi + if [ "$DOZE" = "1" ]; then + # Re-assert rather than assert-once: step-idle can advance to a + # maintenance window on its own, and force-idle is idempotent. + adb shell dumpsys deviceidle force-idle >/dev/null 2>&1 || true + fi + if power_sample "pre-$SEQ" >> "$POWER"; then + MISSES=0 + else + MISSES=$((MISSES + 1)) + echo "device unreachable at $SEQ (${MISSES} in a row)" >&2 + [ "$MISSES" -ge 3 ] && { + echo "FATAL: device unreachable across $MISSES consecutive sends — this cell is incomplete" >&2 + exit 1 + } + fi + echo "$(date +%s000) $SEQ" >> "$SENDS" + "$REPO/scripts/fcm.sh" "$TOKEN" "$DATA" > /dev/null 2>&1 \ + && echo "sent $SEQ" || echo "SEND FAILED $SEQ" + [ "$i" -lt "$COUNT" ] && sleep "$INTERVAL" +done + +echo "sends done; holding ${HOLD}s for stragglers" +sleep "$HOLD" +power_sample end >> "$POWER" +kill $LOGCAT_PID 2>/dev/null || true + +# The device can vanish mid-run — a cable, a reboot, a sleeping host. Say so, +# because the log then just stops and the cell reads as a partial delivery +# failure instead of an interrupted capture. +adb_try shell true >/dev/null \ + || { echo "FATAL: device disappeared during the run — this cell is incomplete" >&2; exit 1; } +echo "log: $LOG" +echo "sends: $SENDS" +echo "power: $POWER" diff --git a/scripts/spike/standby-bucket-probe.sh b/scripts/spike/standby-bucket-probe.sh new file mode 100755 index 0000000000..827ff40465 --- /dev/null +++ b/scripts/spike/standby-bucket-probe.sh @@ -0,0 +1,27 @@ +#!/usr/bin/env bash +# Force the app into a standby bucket, then watch how the next pushes land. +# +# Usage: scripts/spike/standby-bucket-probe.sh +# bucket: active | working_set | frequent | rare | restricted +# +# Send the pushes themselves from the server or the FCM console while this +# runs. It does not send them; it only controls the variable and records +# the result. +set -euo pipefail + +PACKAGE="com.flipcash.app.android" +BUCKET="${1:?usage: standby-bucket-probe.sh }" +OUT="docs/spikes/raw/${BUCKET}-$(date +%Y%m%dT%H%M%S).log" + +mkdir -p "$(dirname "$OUT")" + +adb shell am set-standby-bucket "$PACKAGE" "$BUCKET" +echo "bucket now: $(adb shell am get-standby-bucket "$PACKAGE")" + +# Background the app and let the system settle before measuring. +adb shell input keyevent KEYCODE_HOME +sleep 5 + +adb logcat -c +echo "recording to $OUT — send test pushes now, Ctrl-C when done" +adb logcat -v time | grep --line-buffered "onMessageReceived" | tee "$OUT" diff --git a/services/flipcash/src/main/kotlin/com/flipcash/services/controllers/EventStreamingController.kt b/services/flipcash/src/main/kotlin/com/flipcash/services/controllers/EventStreamingController.kt index 4a0269142e..32aa71cc9f 100644 --- a/services/flipcash/src/main/kotlin/com/flipcash/services/controllers/EventStreamingController.kt +++ b/services/flipcash/src/main/kotlin/com/flipcash/services/controllers/EventStreamingController.kt @@ -68,7 +68,7 @@ class EventStreamingController @Inject constructor( scope = scope, owner = owner, onEvent = { update -> - trace("EventStreamingController: Received chat update, messages=${update.newMessages.size}") + trace("EventStreamingController: Received chat update, events=${update.events.size}") _chatUpdates.trySend(update) }, onBlobUpdate = { update -> diff --git a/services/flipcash/src/main/kotlin/com/flipcash/services/internal/network/extensions/ProtobufToLocal.kt b/services/flipcash/src/main/kotlin/com/flipcash/services/internal/network/extensions/ProtobufToLocal.kt index 0bccc3a3cc..c6a67f9dc5 100644 --- a/services/flipcash/src/main/kotlin/com/flipcash/services/internal/network/extensions/ProtobufToLocal.kt +++ b/services/flipcash/src/main/kotlin/com/flipcash/services/internal/network/extensions/ProtobufToLocal.kt @@ -110,6 +110,7 @@ internal fun PushModels.Payload.asPayload(): NotificationPayload { PushChatMetadata( sendingUserId = if (chatMetadata.hasSendingUserId()) chatMetadata.sendingUserId.toId() else null, chatType = chatMetadata.type.toChatType(), + message = if (chatMetadata.hasMessage()) chatMetadata.message.toChatMessage() else null, ) } else null @@ -405,13 +406,11 @@ internal fun ChatModel.Metadata.toChatMetadata(): ChatMetadata { // -- EventModel.ChatUpdate -- -@Suppress("DEPRECATION") internal fun EventModel.ChatUpdate.toChatUpdate( metadataMapper: (ChatModel.Metadata) -> ChatMetadata = { it.toChatMetadata() }, ): ChatUpdate { return ChatUpdate( chatId = chat.toChatId(), - newMessages = if (hasNewMessages()) newMessages.messagesList.map { it.toChatMessage() } else emptyList(), pointerUpdates = if (hasPointerUpdates()) pointerUpdates.pointersList.map { it.toPointer() } else emptyList(), typingNotifications = if (hasIsTypingNotifications()) isTypingNotifications.isTypingNotificationsList.map { it.toTypingNotification() } else emptyList(), metadataUpdates = metadataUpdatesList.map { it.toMetadataUpdate(metadataMapper) }, diff --git a/services/flipcash/src/main/kotlin/com/flipcash/services/models/NotificationPayload.kt b/services/flipcash/src/main/kotlin/com/flipcash/services/models/NotificationPayload.kt index 658bab11a1..9e840814db 100644 --- a/services/flipcash/src/main/kotlin/com/flipcash/services/models/NotificationPayload.kt +++ b/services/flipcash/src/main/kotlin/com/flipcash/services/models/NotificationPayload.kt @@ -3,6 +3,7 @@ package com.flipcash.services.models import com.codeinc.flipcash.gen.push.v1.Model import com.flipcash.services.internal.network.extensions.asPayload import com.flipcash.services.models.chat.ChatId +import com.flipcash.services.models.chat.ChatMessage import com.flipcash.services.models.chat.ChatType import com.getcode.opencode.model.core.ID import com.getcode.solana.keys.Mint @@ -34,10 +35,16 @@ sealed interface Substitution { * * [sendingUserId] is null for system messages or notifications not tied to a user, * mirroring the proto's optional `sending_user_id` field. + * + * [message] is the pushed message itself, present only when the push is for a + * message and the server chose to inline it. It is optional in the proto and + * the body has a size limit, so a chat push can still arrive without one; the + * fetch path stays the fallback rather than being replaced. */ data class PushChatMetadata( val sendingUserId: ID?, val chatType: ChatType, + val message: ChatMessage? = null, ) data class NotificationPayload( diff --git a/services/flipcash/src/main/kotlin/com/flipcash/services/models/chat/ChatUpdate.kt b/services/flipcash/src/main/kotlin/com/flipcash/services/models/chat/ChatUpdate.kt index 5d541ae4be..e20312423e 100644 --- a/services/flipcash/src/main/kotlin/com/flipcash/services/models/chat/ChatUpdate.kt +++ b/services/flipcash/src/main/kotlin/com/flipcash/services/models/chat/ChatUpdate.kt @@ -2,8 +2,6 @@ package com.flipcash.services.models.chat data class ChatUpdate( val chatId: ChatId, - @Deprecated("Use events instead", replaceWith = ReplaceWith("events")) - val newMessages: List = emptyList(), val pointerUpdates: List = emptyList(), val typingNotifications: List = emptyList(), val metadataUpdates: List = emptyList(), diff --git a/services/flipcash/src/test/kotlin/com/flipcash/services/models/chat/DomainModelsTest.kt b/services/flipcash/src/test/kotlin/com/flipcash/services/models/chat/DomainModelsTest.kt index c910523a07..b61b656858 100644 --- a/services/flipcash/src/test/kotlin/com/flipcash/services/models/chat/DomainModelsTest.kt +++ b/services/flipcash/src/test/kotlin/com/flipcash/services/models/chat/DomainModelsTest.kt @@ -55,8 +55,17 @@ class DomainModelsTest { val chatId = ChatId(ByteArray(32)) val update = ChatUpdate( chatId = chatId, - newMessages = listOf( - ChatMessage(1, null, listOf(MessageContent.Text("hi")), Instant.fromEpochSeconds(0), 1) + events = listOf( + ChatEvent( + sequence = 1, + count = 1, + ts = Instant.fromEpochSeconds(0), + mutations = listOf( + ChatMutation.MessageSent( + ChatMessage(1, null, listOf(MessageContent.Text("hi")), Instant.fromEpochSeconds(0), 1) + ) + ), + ) ), pointerUpdates = listOf( MessagePointer(PointerType.READ, listOf(1.toByte()), 5, Instant.fromEpochSeconds(0)) @@ -69,7 +78,7 @@ class DomainModelsTest { ), ) - assertEquals(1, update.newMessages.size) + assertEquals(1, update.events.size) assertEquals(1, update.pointerUpdates.size) assertEquals(1, update.typingNotifications.size) assertEquals(1, update.metadataUpdates.size)