Fix app start span end-time is wrong if SDK init is deferred

CHANGELOG.md

@@ -5,6 +5,7 @@
 ### Fixes
 
 - Ignore Shutdown in progress when closing ShutdownHookIntegration ([#2521](https://github.com/getsentry/sentry-java/pull/2521))
+- Fix app start span end-time is wrong if SDK init is deferred ([#2519](https://github.com/getsentry/sentry-java/pull/2519))
 
 ## 6.13.1
 

sentry-android-core/api/sentry-android-core.api

@@ -71,6 +71,7 @@ public final class io/sentry/android/core/AppLifecycleIntegration : io/sentry/In
 }
 
 public final class io/sentry/android/core/AppStartState {
+	public fun getAppStartEndTime ()Lio/sentry/SentryDate;
 	public fun getAppStartInterval ()Ljava/lang/Long;
 	public fun getAppStartMillis ()Ljava/lang/Long;
 	public fun getAppStartTime ()Lio/sentry/SentryDate;

sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java

@@ -56,8 +56,7 @@ public final class ActivityLifecycleIntegration
   private boolean isAllActivityCallbacksAvailable;
 
   private boolean firstActivityCreated = false;
-  private boolean firstActivityResumed = false;
-  private boolean foregroundImportance = false;
+  private final boolean foregroundImportance;
 
   private @Nullable ISpan appStartSpan;
   private final @NotNull WeakHashMap<Activity, ISpan> ttidSpanMap = new WeakHashMap<>();
@@ -210,6 +209,11 @@ private void startTracing(final @NotNull Activity activity) {
                 getAppStartDesc(coldStart),
                 appStartTime,
                 Instrumenter.SENTRY);
+
+        // in case there's already an end time (e.g. due to deferred SDK init)
+        // we can finish the app-start span
+        finishAppStartSpan();
+
         // The first activity ttidSpan should start at the same time as the app start time
         ttidSpanMap.put(
             activity,
@@ -328,28 +332,17 @@ public synchronized void onActivityStarted(final @NotNull Activity activity) {
   @SuppressLint("NewApi")
   @Override
   public synchronized void onActivityResumed(final @NotNull Activity activity) {
-    if (!firstActivityResumed) {
-
-      // we only finish the app start if the process is of foregroundImportance
-      if (foregroundImportance) {
-        // sets App start as finished when the very first activity calls onResume
-        AppStartState.getInstance().setAppStartEnd();
-      } else {
-        if (options != null) {
-          options
-              .getLogger()
-              .log(
-                  SentryLevel.DEBUG,
-                  "App Start won't be reported because Process wasn't of foregroundImportance.");
-        }
-      }
 
-      // finishes app start span
-      if (performanceEnabled && appStartSpan != null) {
-        appStartSpan.finish();
-      }
-      firstActivityResumed = true;
+    // app start span
+    @Nullable final SentryDate appStartStartTime = AppStartState.getInstance().getAppStartTime();
+    @Nullable final SentryDate appStartEndTime = AppStartState.getInstance().getAppStartEndTime();
+    // in case the SentryPerformanceProvider is disabled it does not set the app start times,
+    // and we need to set the end time manually here,
+    // the start time gets set manually in SentryAndroid.init()
+    if (appStartStartTime != null && appStartEndTime == null) {
+      AppStartState.getInstance().setAppStartEnd();
     }
+    finishAppStartSpan();
 
     final ISpan ttidSpan = ttidSpanMap.get(activity);
     final View rootView = activity.findViewById(android.R.id.content);
@@ -507,4 +500,17 @@ private void setColdStart(final @Nullable Bundle savedInstanceState) {
       return APP_START_WARM;
     }
   }
+
+  private void finishAppStartSpan() {
+    final @Nullable SentryDate appStartEndTime = AppStartState.getInstance().getAppStartEndTime();
+    if (appStartSpan != null
+        && !appStartSpan.isFinished()
+        && performanceEnabled
+        && appStartEndTime != null) {
+
+      final SpanStatus status =
+          appStartSpan.getStatus() != null ? appStartSpan.getStatus() : SpanStatus.OK;
+      appStartSpan.finish(status, appStartEndTime);
+    }
+  }
 }

sentry-android-core/src/main/java/io/sentry/android/core/AppStartState.java

@@ -1,7 +1,9 @@
 package io.sentry.android.core;
 
 import android.os.SystemClock;
+import io.sentry.DateUtils;
 import io.sentry.SentryDate;
+import io.sentry.SentryLongDate;
 import org.jetbrains.annotations.ApiStatus;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.Nullable;
@@ -84,6 +86,20 @@ public SentryDate getAppStartTime() {
     return appStartTime;
   }
 
+  @Nullable
+  public SentryDate getAppStartEndTime() {
+    @Nullable final SentryDate start = getAppStartTime();
+    if (start != null) {
+      @Nullable final Long durationMillis = getAppStartInterval();
+      if (durationMillis != null) {
+        final long startNanos = start.nanoTimestamp();
+        final long endNanos = startNanos + DateUtils.millisToNanos(durationMillis);
+        return new SentryLongDate(endNanos);
+      }
+    }
+    return null;
+  }
+
   @Nullable
   public Long getAppStartMillis() {
     return appStartMillis;

sentry-android-core/src/main/java/io/sentry/android/core/SentryPerformanceProvider.java

@@ -29,6 +29,8 @@ public final class SentryPerformanceProvider extends EmptySecureContentProvider
   private static long appStartMillis = SystemClock.uptimeMillis();
 
   private boolean firstActivityCreated = false;
+  private boolean firstActivityResumed = false;
+
   private @Nullable Application application;
 
   public SentryPerformanceProvider() {
@@ -91,9 +93,6 @@ public void onActivityCreated(@NotNull Activity activity, @Nullable Bundle saved
       final boolean coldStart = savedInstanceState == null;
       AppStartState.getInstance().setColdStart(coldStart);
 
-      if (application != null) {
-        application.unregisterActivityLifecycleCallbacks(this);
-      }
       firstActivityCreated = true;
     }
   }
@@ -102,7 +101,16 @@ public void onActivityCreated(@NotNull Activity activity, @Nullable Bundle saved
   public void onActivityStarted(@NotNull Activity activity) {}
 
   @Override
-  public void onActivityResumed(@NotNull Activity activity) {}
+  public void onActivityResumed(@NotNull Activity activity) {
+    if (!firstActivityResumed) {
+      // sets App start as finished when the very first activity calls onResume
+      firstActivityResumed = true;
+      AppStartState.getInstance().setAppStartEnd();
+    }
+    if (application != null) {
+      application.unregisterActivityLifecycleCallbacks(this);
+    }
+  }
 
   @Override
   public void onActivityPaused(@NotNull Activity activity) {}

sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt

@@ -6,6 +6,7 @@ import android.app.ActivityManager.RunningAppProcessInfo
 import android.app.Application
 import android.os.Bundle
 import io.sentry.Breadcrumb
+import io.sentry.DateUtils
 import io.sentry.Hub
 import io.sentry.Scope
 import io.sentry.SentryDate
@@ -650,66 +651,142 @@ class ActivityLifecycleIntegrationTest {
     }
 
     @Test
-    fun `App start end time is set`() {
-        val sut = fixture.getSut(14)
+    fun `When firstActivityCreated is true, start transaction with given appStartTime`() {
+        val sut = fixture.getSut()
         fixture.options.tracesSampleRate = 1.0
         sut.register(fixture.hub, fixture.options)
 
-        setAppStartTime()
+        val date = SentryNanotimeDate(Date(0), 0)
+        setAppStartTime(date)
 
         val activity = mock<Activity>()
-        sut.onActivityCreated(activity, null)
-        sut.onActivityResumed(activity)
+        sut.onActivityCreated(activity, fixture.bundle)
 
-        // SystemClock.uptimeMillis() always returns 0, can't assert real values
-        assertNotNull(AppStartState.getInstance().appStartInterval)
+        // call only once
+        verify(fixture.hub).startTransaction(any(), check<TransactionOptions> { assertEquals(date, it.startTimestamp) })
     }
 
     @Test
-    fun `App start end time isnt set if not foregroundImportance`() {
-        val sut = fixture.getSut(14, importance = RunningAppProcessInfo.IMPORTANCE_BACKGROUND)
+    fun `When firstActivityCreated is true, do not create app start span if not foregroundImportance`() {
+        val sut = fixture.getSut(importance = RunningAppProcessInfo.IMPORTANCE_BACKGROUND)
         fixture.options.tracesSampleRate = 1.0
         sut.register(fixture.hub, fixture.options)
 
-        setAppStartTime()
+        // usually set by SentryPerformanceProvider
+        val date = SentryNanotimeDate(Date(0), 0)
+        setAppStartTime(date)
+        AppStartState.getInstance().setAppStartEnd(1)
 
         val activity = mock<Activity>()
-        sut.onActivityCreated(activity, null)
-        sut.onActivityResumed(activity)
+        sut.onActivityCreated(activity, fixture.bundle)
 
-        assertNull(AppStartState.getInstance().appStartInterval)
+        // call only once
+        verify(fixture.hub).startTransaction(any(), check<TransactionOptions> { assertNull(it.startTimestamp) })
     }
 
     @Test
-    fun `When firstActivityCreated is true, start transaction with given appStartTime`() {
-        val sut = fixture.getSut()
+    fun `Create and finish app start span immediately in case SDK init is deferred`() {
+        val sut = fixture.getSut(importance = RunningAppProcessInfo.IMPORTANCE_FOREGROUND)
         fixture.options.tracesSampleRate = 1.0
         sut.register(fixture.hub, fixture.options)
 
-        val date = SentryNanotimeDate(Date(0), 0)
-        setAppStartTime(date)
+        // usually set by SentryPerformanceProvider
+        val startDate = SentryNanotimeDate(Date(0), 0)
+        setAppStartTime(startDate)
+        AppStartState.getInstance().setColdStart(false)
+        AppStartState.getInstance().setAppStartEnd(1)
+
+        val endDate = AppStartState.getInstance().appStartEndTime!!
 
         val activity = mock<Activity>()
         sut.onActivityCreated(activity, fixture.bundle)
 
-        // call only once
-        verify(fixture.hub).startTransaction(any(), check<TransactionOptions> { assertEquals(date, it.startTimestamp) })
+        val appStartSpanCount = fixture.transaction.children.count {
+            it.spanContext.operation.startsWith("app.start.warm") &&
+                it.startDate.nanoTimestamp() == startDate.nanoTimestamp() &&
+                it.finishDate!!.nanoTimestamp() == endDate.nanoTimestamp()
+        }
+        assertEquals(1, appStartSpanCount)
     }
 
     @Test
-    fun `When firstActivityCreated is true, do not use appStartTime if not foregroundImportance`() {
-        val sut = fixture.getSut(importance = RunningAppProcessInfo.IMPORTANCE_BACKGROUND)
+    fun `When SentryPerformanceProvider is disabled, app start time span is still created`() {
+        val sut = fixture.getSut(importance = RunningAppProcessInfo.IMPORTANCE_FOREGROUND)
         fixture.options.tracesSampleRate = 1.0
         sut.register(fixture.hub, fixture.options)
 
-        val date = SentryNanotimeDate(Date(0), 0)
-        setAppStartTime(date)
+        // usually done by SentryPerformanceProvider, if disabled it's done by
+        // SentryAndroid.init
+        val startDate = SentryNanotimeDate(Date(0), 0)
+        setAppStartTime(startDate)
+        AppStartState.getInstance().setColdStart(false)
 
+        // when activity is created
         val activity = mock<Activity>()
         sut.onActivityCreated(activity, fixture.bundle)
+        // then app-start end time should still be null
+        assertNull(AppStartState.getInstance().appStartEndTime)
 
-        // call only once
-        verify(fixture.hub).startTransaction(any(), check<TransactionOptions> { assertNull(it.startTimestamp) })
+        // when activity is resumed
+        sut.onActivityResumed(activity)
+        // end-time should be set
+        assertNotNull(AppStartState.getInstance().appStartEndTime)
+    }
+
+    @Test
+    fun `When app-start end time is already set, it should not be overwritten`() {
+        val sut = fixture.getSut(importance = RunningAppProcessInfo.IMPORTANCE_FOREGROUND)
+        fixture.options.tracesSampleRate = 1.0
+        sut.register(fixture.hub, fixture.options)
+
+        // usually done by SentryPerformanceProvider
+        val startDate = SentryNanotimeDate(Date(0), 0)
+        setAppStartTime(startDate)
+        AppStartState.getInstance().setColdStart(false)
+        AppStartState.getInstance().setAppStartEnd(1234)
+
+        // when activity is created and resumed
+        val activity = mock<Activity>()
+        sut.onActivityCreated(activity, fixture.bundle)
+        sut.onActivityResumed(activity)
+
+        // then the end time should not be overwritten
+        assertEquals(
+            DateUtils.millisToNanos(1234),
+            AppStartState.getInstance().appStartEndTime!!.nanoTimestamp()
+        )
+    }
+
+    @Test
+    fun `When activity lifecycle happens multiple times, app-start end time should not be overwritten`() {
+        val sut = fixture.getSut(importance = RunningAppProcessInfo.IMPORTANCE_FOREGROUND)
+        fixture.options.tracesSampleRate = 1.0
+        sut.register(fixture.hub, fixture.options)
+
+        // usually done by SentryPerformanceProvider
+        val startDate = SentryNanotimeDate(Date(0), 0)
+        setAppStartTime(startDate)
+        AppStartState.getInstance().setColdStart(false)
+
+        // when activity is created, started and resumed multiple times
+        val activity = mock<Activity>()
+        sut.onActivityCreated(activity, fixture.bundle)
+        sut.onActivityStarted(activity)
+        sut.onActivityResumed(activity)
+
+        val firstAppStartEndTime = AppStartState.getInstance().appStartEndTime
+
+        Thread.sleep(1)
+        sut.onActivityPaused(activity)
+        sut.onActivityStopped(activity)
+        sut.onActivityStarted(activity)
+        sut.onActivityResumed(activity)
+
+        // then the end time should not be overwritten
+        assertEquals(
+            firstAppStartEndTime!!.nanoTimestamp(),
+            AppStartState.getInstance().appStartEndTime!!.nanoTimestamp()
+        )
     }
 
     @Test

sentry-android-core/src/test/java/io/sentry/android/core/SentryPerformanceProviderTest.kt

@@ -1,16 +1,20 @@
 package io.sentry.android.core
 
+import android.app.Application
 import android.content.pm.ProviderInfo
 import android.os.Bundle
 import androidx.test.ext.junit.runners.AndroidJUnit4
 import io.sentry.SentryNanotimeDate
 import org.junit.runner.RunWith
+import org.mockito.kotlin.any
 import org.mockito.kotlin.mock
+import org.mockito.kotlin.verify
 import java.util.Date
 import kotlin.test.BeforeTest
 import kotlin.test.Test
 import kotlin.test.assertEquals
 import kotlin.test.assertFalse
+import kotlin.test.assertNotNull
 import kotlin.test.assertTrue
 
 @RunWith(AndroidJUnit4::class)
@@ -73,6 +77,26 @@ class SentryPerformanceProviderTest {
         assertFalse(AppStartState.getInstance().isColdStart!!)
     }
 
+    @Test
+    fun `provider sets app start end on first activity resume, and unregisters afterwards`() {
+        val providerInfo = ProviderInfo()
+
+        val mockContext = ContextUtilsTest.createMockContext(true)
+        providerInfo.authority = AUTHORITY
+
+        val provider = SentryPerformanceProvider()
+        provider.attachInfo(mockContext, providerInfo)
+
+        provider.onActivityCreated(mock(), Bundle())
+        provider.onActivityResumed(mock())
+
+        assertNotNull(AppStartState.getInstance().appStartInterval)
+        assertNotNull(AppStartState.getInstance().appStartEndTime)
+
+        verify((mockContext.applicationContext as Application))
+            .unregisterActivityLifecycleCallbacks(any())
+    }
+
     companion object {
         private const val AUTHORITY = "io.sentry.sample.SentryPerformanceProvider"
     }