diff --git a/.changeset/native-crash-timestamp-clock.md b/.changeset/native-crash-timestamp-clock.md new file mode 100644 index 000000000..70685bc17 --- /dev/null +++ b/.changeset/native-crash-timestamp-clock.md @@ -0,0 +1,5 @@ +--- +"posthog-android": patch +--- + +Fix native (NDK) crash events being stamped at the wrong time when the device clock disagrees with network time diff --git a/posthog-android/src/main/java/com/posthog/android/errortracking/PostHogNativeCrashIntegration.kt b/posthog-android/src/main/java/com/posthog/android/errortracking/PostHogNativeCrashIntegration.kt index 9edf12a83..6dacc8fb4 100644 --- a/posthog-android/src/main/java/com/posthog/android/errortracking/PostHogNativeCrashIntegration.kt +++ b/posthog-android/src/main/java/com/posthog/android/errortracking/PostHogNativeCrashIntegration.kt @@ -2,14 +2,19 @@ package com.posthog.android.errortracking import android.app.Application import android.app.ApplicationExitInfo +import android.content.BroadcastReceiver import android.content.Context +import android.content.Intent +import android.content.IntentFilter import android.os.Build +import android.os.Process import android.os.UserManager import androidx.annotation.RequiresApi import com.posthog.PostHogEventName import com.posthog.PostHogIntegration import com.posthog.PostHogInterface import com.posthog.android.PostHogAndroidConfig +import com.posthog.android.internal.errortracking.NativeCrashClockOffsetStore import com.posthog.android.internal.errortracking.NativeCrashEventCoercer import com.posthog.android.internal.errortracking.NativeCrashWatermarkStore import com.posthog.android.internal.errortracking.TombstoneParser @@ -42,8 +47,10 @@ public class PostHogNativeCrashIntegration : PostHogIntegration { private val context: Context private val config: PostHogAndroidConfig private val executorFactory: () -> ExecutorService + private val wallClockMs: () -> Long private var executor: ExecutorService? = null private var postHog: PostHogInterface? = null + private var timeChangedReceiver: BroadcastReceiver? = null // Whether this instance owns the process-wide scanner guard, so only the // owner can release it on uninstall. @@ -56,10 +63,16 @@ public class PostHogNativeCrashIntegration : PostHogIntegration { { Executors.newSingleThreadExecutor(PostHogThreadFactory("PostHogNativeCrashThread")) }, ) - internal constructor(context: Context, config: PostHogAndroidConfig, executorFactory: () -> ExecutorService) { + internal constructor( + context: Context, + config: PostHogAndroidConfig, + executorFactory: () -> ExecutorService, + wallClockMs: () -> Long = System::currentTimeMillis, + ) { this.context = context this.config = config this.executorFactory = executorFactory + this.wallClockMs = wallClockMs } private companion object { @@ -129,6 +142,7 @@ public class PostHogNativeCrashIntegration : PostHogIntegration { val executor = executorFactory() this.executor = executor executor.submit { scanSafely(postHog) } + registerTimeChangedReceiver(executor) } catch (e: Throwable) { config.logger.log("Native crash scan could not be scheduled: $e.") installedByThisInstance = false @@ -140,6 +154,14 @@ public class PostHogNativeCrashIntegration : PostHogIntegration { if (!installedByThisInstance) { return } + timeChangedReceiver?.let { + try { + context.unregisterReceiver(it) + } catch (e: Throwable) { + config.logger.log("Unregistering the time change receiver failed: $e.") + } + } + timeChangedReceiver = null // Stop the scanner before releasing the process-wide guard, so a new // install cannot start a second scanner while this one is still running. executor?.shutdownNow() @@ -175,8 +197,66 @@ public class PostHogNativeCrashIntegration : PostHogIntegration { } } + // The wall clock can change while the app runs (the user sets it, or automatic + // time corrects it), so the run's recorded offset is refreshed each time it does. + private fun registerTimeChangedReceiver(executor: ExecutorService) { + val receiver = + object : BroadcastReceiver() { + override fun onReceive( + context: Context, + intent: Intent, + ) { + try { + // off the main thread: the date provider may do a Binder IPC + executor.submit { recordCurrentClockOffset() } + } catch (e: Throwable) { + config.logger.log("Recording the clock offset failed: $e.") + } + } + } + val filter = IntentFilter(Intent.ACTION_TIME_CHANGED) + try { + if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.TIRAMISU) { + context.registerReceiver(receiver, filter, Context.RECEIVER_NOT_EXPORTED) + } else { + context.registerReceiver(receiver, filter) + } + timeChangedReceiver = receiver + } catch (e: Throwable) { + config.logger.log("Registering the time change receiver failed: $e.") + } + } + + // Exit records carry wall-clock time, but the batch's sent_at comes from config.dateProvider, + // which is network-corrected on API 33+. Ingestion shifts each event by timestamp - sent_at, + // so each crash is moved onto the provider's clock with the offset of the run it crashed in. + private fun currentClockOffsetMs(): Long = config.dateProvider.currentTimeMillis() - wallClockMs() + + private fun recordCurrentClockOffset() { + try { + NativeCrashClockOffsetStore(context).record(Process.myPid(), currentClockOffsetMs()) + } catch (e: Throwable) { + config.logger.log("Recording the clock offset failed: $e.") + } + } + @RequiresApi(Build.VERSION_CODES.S) private fun scan(postHog: PostHogInterface) { + val currentClockOffsetMs = currentClockOffsetMs() + try { + scanCrashes(postHog, NativeCrashClockOffsetStore(context), currentClockOffsetMs) + } finally { + // after the scan: a pid reused from a crashed run must not overwrite that run's offset first + recordCurrentClockOffset() + } + } + + @RequiresApi(Build.VERSION_CODES.S) + private fun scanCrashes( + postHog: PostHogInterface, + clockOffsets: NativeCrashClockOffsetStore, + currentClockOffsetMs: Long, + ) { val activityManager = getActivityManager(context) ?: return val watermarkStore = NativeCrashWatermarkStore(context) val watermark = watermarkStore.get() @@ -240,7 +320,7 @@ public class PostHogNativeCrashIntegration : PostHogIntegration { postHog.capture( PostHogEventName.EXCEPTION.event, properties = it, - timestamp = Date(exitInfo.timestamp), + timestamp = Date(exitInfo.timestamp + (clockOffsets.offsetFor(exitInfo.pid) ?: currentClockOffsetMs)), ) captured++ } diff --git a/posthog-android/src/main/java/com/posthog/android/internal/errortracking/NativeCrashClockOffsetStore.kt b/posthog-android/src/main/java/com/posthog/android/internal/errortracking/NativeCrashClockOffsetStore.kt new file mode 100644 index 000000000..28b7f73f4 --- /dev/null +++ b/posthog-android/src/main/java/com/posthog/android/internal/errortracking/NativeCrashClockOffsetStore.kt @@ -0,0 +1,58 @@ +package com.posthog.android.internal.errortracking + +import android.content.Context + +/** + * Remembers, per app run, how far the SDK's clock was from the wall clock. + * + * Exit records only carry wall-clock time, and a native crash is recovered in a + * later run whose clocks may disagree differently (the user changed the time, or + * network time became available). Recovering with the crashed run's offset puts + * the crash on the SDK's clock as it was when the crash happened. + * + * Runs are keyed by pid, which the exit record carries, rather than by start + * time: the wall clock can move backwards, so start times do not order runs. + */ +internal class NativeCrashClockOffsetStore(context: Context) { + private val preferences = + context.getSharedPreferences("posthog-native-crash", Context.MODE_PRIVATE) + + /** The offset last recorded by the run with [pid], or null if none is known. */ + fun offsetFor(pid: Int): Long? = runs().lastOrNull { it.first == pid }?.second + + fun record( + pid: Int, + offsetMs: Long, + ) { + // Scans on different executors can overlap after an uninstall and + // re-enable, so the read-modify-write must not lose either run's entry. + synchronized(lock) { + // a reused pid belongs to the newer run, so drop the older entry + val runs = (runs().filter { it.first != pid } + (pid to offsetMs)).takeLast(MAX_RUNS) + preferences.edit().putString(KEY, runs.joinToString(";") { "${it.first}:${it.second}" }).apply() + } + } + + // oldest first + private fun runs(): List> = + preferences.getString(KEY, null) + ?.split(';') + ?.mapNotNull { entry -> + val parts = entry.split(':') + val pid = parts.getOrNull(0)?.toIntOrNull() + val offset = parts.getOrNull(1)?.toLongOrNull() + if (pid != null && offset != null) pid to offset else null + } + ?: emptyList() + + private companion object { + private const val KEY = "clockOffsets" + + // every instance shares one SharedPreferences file, so the lock is shared too + private val lock = Any() + + // Crashes from runs older than this fall back to the current offset, + // which is fine: the OS only keeps a handful of exit records anyway. + private const val MAX_RUNS = 16 + } +} diff --git a/posthog-android/src/test/java/com/posthog/android/errortracking/PostHogNativeCrashIntegrationTest.kt b/posthog-android/src/test/java/com/posthog/android/errortracking/PostHogNativeCrashIntegrationTest.kt index 00c5f511a..6d723dfc0 100644 --- a/posthog-android/src/test/java/com/posthog/android/errortracking/PostHogNativeCrashIntegrationTest.kt +++ b/posthog-android/src/test/java/com/posthog/android/errortracking/PostHogNativeCrashIntegrationTest.kt @@ -3,13 +3,18 @@ package com.posthog.android.errortracking import android.app.ActivityManager import android.app.ApplicationExitInfo import android.content.Context +import android.content.Intent +import android.os.Looper +import android.os.Process import androidx.test.core.app.ApplicationProvider import androidx.test.ext.junit.runners.AndroidJUnit4 import com.posthog.PostHogInterface import com.posthog.android.API_KEY import com.posthog.android.PostHogAndroidConfig +import com.posthog.android.internal.errortracking.NativeCrashClockOffsetStore import com.posthog.android.internal.errortracking.NativeCrashWatermarkStore import com.posthog.android.internal.errortracking.TestProtoWriter +import com.posthog.internal.PostHogDateProvider import com.posthog.internal.PostHogRemoteConfig import org.junit.After import org.junit.Before @@ -78,10 +83,24 @@ internal class PostHogNativeCrashIntegrationTest { } } + private class FixedDateProvider(var nowMs: Long) : PostHogDateProvider { + override fun currentDate(): Date = Date(nowMs) + + override fun addSecondsToCurrentDate(seconds: Int): Date = Date(nowMs + seconds * 1000L) + + override fun currentTimeMillis(): Long = nowMs + + override fun nanoTime(): Long = System.nanoTime() + } + + private var wallClockMs = 1_000_000L + private val dateProvider = FixedDateProvider(wallClockMs) + @Before fun setUp() { config = PostHogAndroidConfig(API_KEY).apply { + dateProvider = this@PostHogNativeCrashIntegrationTest.dateProvider errorTrackingConfig.captureNativeCrashes = true remoteConfigHolder = mock { @@ -100,7 +119,7 @@ internal class PostHogNativeCrashIntegrationTest { } private fun install(executor: DirectExecutorService = DirectExecutorService()): PostHogNativeCrashIntegration { - val integration = PostHogNativeCrashIntegration(context, config, { executor }) + val integration = PostHogNativeCrashIntegration(context, config, { executor }, { wallClockMs }) installed.add(integration) integration.install(postHog) return integration @@ -161,6 +180,99 @@ internal class PostHogNativeCrashIntegrationTest { assertEquals(200, watermark()) } + @Test + fun `stamps crashes on the date provider clock and acknowledges the raw exit timestamp`() { + dateProvider.nowMs = wallClockMs - 200_000 + addExitRecord(ApplicationExitInfo.REASON_CRASH_NATIVE, timestamp = 900_000, trace = tombstoneBytes()) + + install() + + verify(postHog).capture( + eq("\$exception"), + anyOrNull(), + any(), + anyOrNull(), + anyOrNull(), + anyOrNull(), + eq(Date(700_000)), + ) + assertEquals(900_000, watermark()) + } + + @Test + fun `stamps crashes with the offset recorded by the run they crashed in`() { + NativeCrashClockOffsetStore(context).record(pid = 7, offsetMs = -50_000) + dateProvider.nowMs = wallClockMs - 200_000 + addExitRecord(ApplicationExitInfo.REASON_CRASH_NATIVE, timestamp = 900_000, pid = 7, trace = tombstoneBytes()) + + install() + + verify(postHog).capture( + eq("\$exception"), + anyOrNull(), + any(), + anyOrNull(), + anyOrNull(), + anyOrNull(), + eq(Date(850_000)), + ) + } + + @Test + fun `picks the crashed run by pid even after the wall clock moved back`() { + // run 7 started with a fast wall clock at 800_000; run 8 started after + // the clock was corrected back to 400_000, then crashed at 900_000 + NativeCrashClockOffsetStore(context).record(pid = 7, offsetMs = -500_000) + NativeCrashClockOffsetStore(context).record(pid = 8, offsetMs = 0) + addExitRecord(ApplicationExitInfo.REASON_CRASH_NATIVE, timestamp = 900_000, pid = 8, trace = tombstoneBytes()) + + install() + + verify(postHog).capture( + eq("\$exception"), + anyOrNull(), + any(), + anyOrNull(), + anyOrNull(), + anyOrNull(), + eq(Date(900_000)), + ) + } + + @Test + fun `records the current run's clock offset`() { + dateProvider.nowMs = wallClockMs - 200_000 + + install() + + assertEquals(-200_000, NativeCrashClockOffsetStore(context).offsetFor(Process.myPid())) + } + + @Test + fun `re-records the current run's clock offset when the wall clock changes`() { + dateProvider.nowMs = wallClockMs - 200_000 + install() + + // the wall clock is corrected to match the provider while the app runs + wallClockMs = dateProvider.nowMs + context.sendBroadcast(Intent(Intent.ACTION_TIME_CHANGED)) + shadowOf(Looper.getMainLooper()).idle() + + assertEquals(0, NativeCrashClockOffsetStore(context).offsetFor(Process.myPid())) + } + + @Test + fun `stops re-recording the clock offset after uninstall`() { + dateProvider.nowMs = wallClockMs - 200_000 + install().uninstall() + + wallClockMs = dateProvider.nowMs + context.sendBroadcast(Intent(Intent.ACTION_TIME_CHANGED)) + shadowOf(Looper.getMainLooper()).idle() + + assertEquals(-200_000, NativeCrashClockOffsetStore(context).offsetFor(Process.myPid())) + } + @Test fun `already acknowledged records are not reprocessed`() { NativeCrashWatermarkStore(context).advance(200) diff --git a/posthog-android/src/test/java/com/posthog/android/internal/errortracking/NativeCrashClockOffsetStoreTest.kt b/posthog-android/src/test/java/com/posthog/android/internal/errortracking/NativeCrashClockOffsetStoreTest.kt new file mode 100644 index 000000000..0d687cb08 --- /dev/null +++ b/posthog-android/src/test/java/com/posthog/android/internal/errortracking/NativeCrashClockOffsetStoreTest.kt @@ -0,0 +1,48 @@ +package com.posthog.android.internal.errortracking + +import android.content.Context +import androidx.test.core.app.ApplicationProvider +import androidx.test.ext.junit.runners.AndroidJUnit4 +import org.junit.runner.RunWith +import org.robolectric.annotation.Config +import kotlin.test.Test +import kotlin.test.assertEquals +import kotlin.test.assertNull + +@RunWith(AndroidJUnit4::class) +@Config(sdk = [34]) +internal class NativeCrashClockOffsetStoreTest { + private val context: Context = ApplicationProvider.getApplicationContext() + private val store = NativeCrashClockOffsetStore(context) + + @Test + fun `returns null for a pid with no recorded run`() { + assertNull(store.offsetFor(1)) + } + + @Test + fun `returns the offset recorded by each pid`() { + store.record(pid = 1, offsetMs = -1) + store.record(pid = 2, offsetMs = -2) + + assertEquals(-1, store.offsetFor(1)) + assertEquals(-2, store.offsetFor(2)) + } + + @Test + fun `a later record for the same pid replaces the earlier one`() { + store.record(pid = 1, offsetMs = -1) + store.record(pid = 1, offsetMs = 0) + + assertEquals(0, store.offsetFor(1)) + } + + @Test + fun `keeps only the most recent runs`() { + (1..20).forEach { store.record(pid = it, offsetMs = -it.toLong()) } + + assertNull(store.offsetFor(4)) + assertEquals(-5, store.offsetFor(5)) + assertEquals(-20, store.offsetFor(20)) + } +}