From ff5321cceba00300fd62097c6b6ed885a1b4d8d5 Mon Sep 17 00:00:00 2001 From: Brandon McAnsh Date: Fri, 2 Oct 2026 11:15:46 -0400 Subject: [PATCH] fix(logging): leave Bugsnag breadcrumbs off the tracing thread Play's ANR list for 2026.9.2 (4581) puts 16 of 21 ANRs in BugsnagBreadcrumbSink.record, tagged lock contention, while handling an FCM push or NotificationService. trace() runs every sink on the caller's thread, so a trace on main waited on whatever Bugsnag was waiting on, for 10s or more. The sink now queues breadcrumbs and one worker on its own thread hands them to Bugsnag in order. The queue holds 100, Bugsnag's own breadcrumb limit, and drops the oldest, so a worker stuck behind the same lock can't grow it. It isn't on Dispatchers.IO because that pool is saturated during cold start, which is when these ANRs fire. Error breadcrumbs still go to Bugsnag on the caller's thread. trace() reports the error right after the sinks run and the report snapshots breadcrumbs then, so a queued one would be missing from its own report. That adds no new way to block: Client.notify leaves its own breadcrumb on the same thread. Bugsnag never reported these ANRs. Its ANR plugin arms by posting to the main looper (AnrPlugin.kt:55, 6.27.0), which can't run while main is blocked in record. Expect Bugsnag's ANR counts to change shape once this ships. --- .../internal/startup/BugsnagBreadcrumbSink.kt | 70 +++++++++++++- .../startup/BugsnagBreadcrumbSinkTest.kt | 95 +++++++++++++++++++ 2 files changed, 162 insertions(+), 3 deletions(-) create mode 100644 apps/flipcash/app/src/test/kotlin/com/flipcash/app/internal/startup/BugsnagBreadcrumbSinkTest.kt diff --git a/apps/flipcash/app/src/main/kotlin/com/flipcash/app/internal/startup/BugsnagBreadcrumbSink.kt b/apps/flipcash/app/src/main/kotlin/com/flipcash/app/internal/startup/BugsnagBreadcrumbSink.kt index 774f37397d..a4f1adb460 100644 --- a/apps/flipcash/app/src/main/kotlin/com/flipcash/app/internal/startup/BugsnagBreadcrumbSink.kt +++ b/apps/flipcash/app/src/main/kotlin/com/flipcash/app/internal/startup/BugsnagBreadcrumbSink.kt @@ -4,15 +4,79 @@ import com.bugsnag.android.BreadcrumbType import com.bugsnag.android.Bugsnag import com.getcode.utils.BreadcrumbSink import com.getcode.utils.TraceType +import kotlinx.coroutines.CoroutineDispatcher +import kotlinx.coroutines.CoroutineScope +import kotlinx.coroutines.SupervisorJob +import kotlinx.coroutines.asCoroutineDispatcher +import kotlinx.coroutines.channels.BufferOverflow +import kotlinx.coroutines.channels.Channel +import kotlinx.coroutines.launch +import java.util.concurrent.Executors + +/** + * Forwards breadcrumbs to Bugsnag from one background worker, never from the thread that traced. + * + * `trace()` runs every sink on the caller's thread, and `Bugsnag.leaveBreadcrumb` can block: on + * 2026.9.2 Play reported the main thread stuck in it for 10 s+ while handling FCM pushes. Queueing + * here keeps `trace()` on the main thread from ever waiting on Bugsnag. + * + * One worker keeps breadcrumbs in order. The queue holds [capacity] and drops the oldest when full, + * so a stuck worker can't grow it; the default matches Bugsnag's own 100-breadcrumb limit, which + * would discard the same ones. Bugsnag timestamps a breadcrumb when the worker delivers it, normally + * microseconds after it was traced. The worker has its own thread because the shared IO pool is + * saturated during cold start, which is when these ANRs happen. + * + * [TraceType.Error] is the exception: it goes to Bugsnag on the caller's thread. `trace()` reports + * the error right after the sinks run, and the report snapshots breadcrumbs at that point, so a + * queued crumb would be missing from its own report. This adds no new way to block: the report + * that follows leaves its own breadcrumb on the same thread anyway. It can land ahead of crumbs + * still in the queue. + */ +class BugsnagBreadcrumbSink( + dispatcher: CoroutineDispatcher = newWorkerDispatcher(), + capacity: Int = DEFAULT_CAPACITY, + private val leave: (String, Map, BreadcrumbType) -> Unit = ::leaveBugsnagBreadcrumb, +) : BreadcrumbSink { + + private class Pending(val message: String, val metadata: Map, val type: BreadcrumbType) + + private val pending = Channel(capacity, BufferOverflow.DROP_OLDEST) + + init { + CoroutineScope(SupervisorJob() + dispatcher).launch { + for (crumb in pending) deliver(crumb.message, crumb.metadata, crumb.type) + } + } -class BugsnagBreadcrumbSink : BreadcrumbSink { override fun record(message: String, metadata: Map, type: TraceType) { - if (!Bugsnag.isStarted()) return val breadcrumbType = type.toBugsnagBreadcrumbType() ?: return - Bugsnag.leaveBreadcrumb(message, metadata, breadcrumbType) + if (breadcrumbType == BreadcrumbType.ERROR) { + deliver(message, metadata, breadcrumbType) + } else { + pending.trySend(Pending(message, metadata, breadcrumbType)) + } + } + + private fun deliver(message: String, metadata: Map, type: BreadcrumbType) { + // Can't trace a failure here: it would come straight back into this sink. + runCatching { leave(message, metadata, type) } + } + + private companion object { + const val DEFAULT_CAPACITY = 100 } } +private fun newWorkerDispatcher(): CoroutineDispatcher = + Executors.newSingleThreadExecutor { runnable -> + Thread(runnable, "bugsnag-breadcrumbs").apply { isDaemon = true } + }.asCoroutineDispatcher() + +private fun leaveBugsnagBreadcrumb(message: String, metadata: Map, type: BreadcrumbType) { + if (!Bugsnag.isStarted()) return + Bugsnag.leaveBreadcrumb(message, metadata, type) +} + private fun TraceType.toBugsnagBreadcrumbType(): BreadcrumbType? { return when (this) { TraceType.Silent -> null diff --git a/apps/flipcash/app/src/test/kotlin/com/flipcash/app/internal/startup/BugsnagBreadcrumbSinkTest.kt b/apps/flipcash/app/src/test/kotlin/com/flipcash/app/internal/startup/BugsnagBreadcrumbSinkTest.kt new file mode 100644 index 0000000000..ef002d54c5 --- /dev/null +++ b/apps/flipcash/app/src/test/kotlin/com/flipcash/app/internal/startup/BugsnagBreadcrumbSinkTest.kt @@ -0,0 +1,95 @@ +package com.flipcash.app.internal.startup + +import com.bugsnag.android.BreadcrumbType +import com.getcode.utils.TraceType +import kotlinx.coroutines.test.StandardTestDispatcher +import kotlinx.coroutines.test.TestScope +import kotlinx.coroutines.test.advanceUntilIdle +import kotlinx.coroutines.test.runTest +import kotlin.test.Test +import kotlin.test.assertEquals +import kotlin.test.assertTrue + +class BugsnagBreadcrumbSinkTest { + + private data class Left(val message: String, val metadata: Map, val type: BreadcrumbType) + + private val left = mutableListOf() + + private fun TestScope.sink( + capacity: Int = 100, + leave: (String, Map, BreadcrumbType) -> Unit = { m, md, t -> left += Left(m, md, t) }, + ) = BugsnagBreadcrumbSink( + dispatcher = StandardTestDispatcher(testScheduler), + capacity = capacity, + leave = leave, + ) + + @Test + fun `record returns before Bugsnag is called`() = runTest { + val sink = sink() + + sink.record("onMessageReceived", mapOf("seq" to "1"), TraceType.Process) + + // The ANR on 2026.9.2: the main thread sat inside this call while Bugsnag waited on a lock. + assertTrue(left.isEmpty()) + + advanceUntilIdle() + assertEquals(listOf(Left("onMessageReceived", mapOf("seq" to "1"), BreadcrumbType.PROCESS)), left) + } + + @Test + fun `error breadcrumbs reach Bugsnag before record returns`() = runTest { + val sink = sink() + + sink.record("Failed to handle push", emptyMap(), TraceType.Error) + + // trace() reports the error right after the sinks run, and the report snapshots + // breadcrumbs then; a queued crumb would be missing from its own report. + assertEquals(listOf("Failed to handle push"), left.map { it.message }) + } + + @Test + fun `keeps the order breadcrumbs were recorded in`() = runTest { + val sink = sink() + + repeat(5) { sink.record("crumb $it", emptyMap(), TraceType.Log) } + advanceUntilIdle() + + assertEquals((0 until 5).map { "crumb $it" }, left.map { it.message }) + } + + @Test + fun `drops the oldest when the queue is full`() = runTest { + val sink = sink(capacity = 2) + + repeat(3) { sink.record("crumb $it", emptyMap(), TraceType.Log) } + advanceUntilIdle() + + assertEquals(listOf("crumb 1", "crumb 2"), left.map { it.message }) + } + + @Test + fun `skips silent traces`() = runTest { + val sink = sink() + + sink.record("local only", emptyMap(), TraceType.Silent) + advanceUntilIdle() + + assertTrue(left.isEmpty()) + } + + @Test + fun `keeps delivering after Bugsnag throws`() = runTest { + val sink = sink(leave = { m, md, t -> + if (m == "boom") error("leaveBreadcrumb failed") + left += Left(m, md, t) + }) + + sink.record("boom", emptyMap(), TraceType.Log) + sink.record("after", emptyMap(), TraceType.Log) + advanceUntilIdle() + + assertEquals(listOf("after"), left.map { it.message }) + } +}