fix(core): Mark transactions that outlive their deadline as deadline_exceeded (JAVA-642)

CHANGELOG.md

@@ -10,6 +10,7 @@
 ### Fixes
 
 - Android: Count deep sleep in breadcrumb, screenshot and view hierarchy debounce windows, so the first low-memory or battery breadcrumb after a long Doze is no longer dropped ([#6590](https://github.com/getsentry/sentry-java/pull/6590))
+- Android: Mark transactions and spans that finish after their deadline as `deadline_exceeded`, so `ui.load` transactions with TTID, TTFD or app start values that are hours long after a device sleep no longer report `ok` ([#6599](https://github.com/getsentry/sentry-java/pull/6599))
 
 ## 8.64.0
 

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

@@ -15,6 +15,7 @@ import android.view.View
 import android.view.ViewTreeObserver
 import androidx.test.core.app.ApplicationProvider
 import androidx.test.ext.junit.runners.AndroidJUnit4
+import com.google.common.truth.Truth.assertThat
 import io.sentry.DateUtils
 import io.sentry.FullyDisplayedReporter
 import io.sentry.IScope
@@ -43,7 +44,9 @@ import io.sentry.protocol.MeasurementValue
 import io.sentry.protocol.SentryId
 import io.sentry.protocol.TransactionNameSource
 import io.sentry.test.DeferredExecutorService
+import io.sentry.test.ManualTimerExecutorService
 import io.sentry.test.getProperty
+import io.sentry.time.TestMonotonicTicker
 import java.util.concurrent.Future
 import java.util.concurrent.TimeUnit
 import kotlin.test.AfterTest
@@ -68,6 +71,7 @@ import org.mockito.kotlin.clearInvocations
 import org.mockito.kotlin.eq
 import org.mockito.kotlin.mock
 import org.mockito.kotlin.never
+import org.mockito.kotlin.spy
 import org.mockito.kotlin.times
 import org.mockito.kotlin.verify
 import org.mockito.kotlin.whenever
@@ -82,7 +86,12 @@ class ActivityLifecycleIntegrationTest {
   private class Fixture {
     val application = mock<Application>()
     val scopes = mock<Scopes>()
-    val options = SentryAndroidOptions().apply { dsn = "https://key@sentry.io/proj" }
+    val ticker = TestMonotonicTicker()
+    // SentryAndroidOptions is final and has no ticker setter, so a spy supplies the ticker.
+    val options =
+      spy(SentryAndroidOptions().apply { dsn = "https://key@sentry.io/proj" }).also {
+        whenever(it.monotonicTicker).thenReturn(ticker)
+      }
     val bundle = mock<Bundle>()
     val activityFramesTracker = mock<ActivityFramesTracker>()
     val transactionFinishedCallback = mock<TransactionFinishedCallback>()
@@ -2558,6 +2567,99 @@ class ActivityLifecycleIntegrationTest {
     assertNotEquals(0, lastUptimeMillis.nanoTimestamp())
   }
 
+  @Test
+  fun `first frame drawn after the deadline passed changes only the status`() {
+    val timer = ManualTimerExecutorService()
+    val sut = fixture.getSut {
+      it.tracesSampleRate = 1.0
+      it.timerExecutorService = timer
+    }
+    var nowMillis = START_MILLIS
+    fixture.options.dateProvider = SentryDateProvider { SentryNanotimeDate(nowMillis, 0) }
+    setAppStartTime(SentryNanotimeDate(START_MILLIS, 0))
+    sut.register(fixture.scopes, fixture.options)
+    val view = fixture.createView()
+    val activity = createAndResumeActivity(sut, view)
+    val ttidSpan = sut.ttidSpanMap[activity]!!
+    val appStartSpan = sut.appStartSpan!!
+
+    // the device sleeps before the first frame, and the deadline timer hasn't run yet
+    fixture.ticker.advance(3, TimeUnit.HOURS)
+    nowMillis += TimeUnit.HOURS.toMillis(3)
+    runFirstDraw(view)
+    timer.runScheduled(fixture.options.idleTimeout!!)
+
+    val firstFrameNanos = TimeUnit.MILLISECONDS.toNanos(nowMillis)
+    for (span in listOf(ttidSpan, appStartSpan)) {
+      assertThat(span.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED)
+      assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(firstFrameNanos)
+    }
+    assertThat(
+        (ttidSpan as Span).measurements[MeasurementValue.KEY_TIME_TO_INITIAL_DISPLAY]!!.value
+      )
+      .isEqualTo(TimeUnit.HOURS.toMillis(3))
+    assertThat(fixture.transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED)
+    assertThat(fixture.transaction.finishDate!!.nanoTimestamp()).isEqualTo(firstFrameNanos)
+  }
+
+  @Test
+  fun `full display reported after the deadline passed changes only the status`() {
+    val sut = fixture.getSut {
+      it.tracesSampleRate = 1.0
+      it.isEnableTimeToFullDisplayTracing = true
+    }
+    var nowMillis = START_MILLIS
+    fixture.options.dateProvider = SentryDateProvider { SentryNanotimeDate(nowMillis, 0) }
+    setAppStartTime(SentryNanotimeDate(START_MILLIS, 0))
+    sut.register(fixture.scopes, fixture.options)
+    val view = fixture.createView()
+    val activity = createAndResumeActivity(sut, view)
+    val ttfdSpan = sut.ttfdSpanMap[activity]!!
+    runFirstDraw(view)
+
+    fixture.ticker.advance(3, TimeUnit.HOURS)
+    nowMillis += TimeUnit.HOURS.toMillis(3)
+    fixture.options.fullyDisplayedReporter.reportFullyDrawn()
+
+    assertThat(ttfdSpan.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED)
+    assertThat(ttfdSpan.finishDate!!.nanoTimestamp())
+      .isEqualTo(TimeUnit.MILLISECONDS.toNanos(nowMillis))
+    assertThat((ttfdSpan as Span).measurements[MeasurementValue.KEY_TIME_TO_FULL_DISPLAY]!!.value)
+      .isEqualTo(TimeUnit.HOURS.toMillis(3))
+  }
+
+  @Test
+  fun `first frame drawn before the deadline keeps its status`() {
+    val sut = fixture.getSut { it.tracesSampleRate = 1.0 }
+    var nowMillis = START_MILLIS
+    fixture.options.dateProvider = SentryDateProvider { SentryNanotimeDate(nowMillis, 0) }
+    setAppStartTime(SentryNanotimeDate(START_MILLIS, 0))
+    sut.register(fixture.scopes, fixture.options)
+    val view = fixture.createView()
+    val activity = createAndResumeActivity(sut, view)
+    val ttidSpan = sut.ttidSpanMap[activity]!!
+
+    fixture.ticker.advance(29, TimeUnit.SECONDS)
+    nowMillis += TimeUnit.SECONDS.toMillis(29)
+    runFirstDraw(view)
+
+    assertThat(ttidSpan.status).isEqualTo(SpanStatus.OK)
+    assertThat(ttidSpan.finishDate!!.nanoTimestamp())
+      .isEqualTo(TimeUnit.MILLISECONDS.toNanos(nowMillis))
+    assertThat(
+        (ttidSpan as Span).measurements[MeasurementValue.KEY_TIME_TO_INITIAL_DISPLAY]!!.value
+      )
+      .isEqualTo(TimeUnit.SECONDS.toMillis(29))
+  }
+
+  private fun createAndResumeActivity(sut: ActivityLifecycleIntegration, view: View): Activity {
+    val activity = mock<Activity>()
+    whenever(activity.findViewById<View>(any())).thenReturn(view)
+    sut.onActivityCreated(activity, fixture.bundle)
+    sut.onActivityResumed(activity)
+    return activity
+  }
+
   private fun SentryTracer.isFinishing() =
     getProperty<Any>("finishStatus").getProperty<Boolean>("isFinishing")
 
@@ -2645,6 +2747,10 @@ class ActivityLifecycleIntegrationTest {
       AppStartMetrics.getInstance().onActivityCreated(mock(), mock())
     }
   }
+
+  private companion object {
+    const val START_MILLIS = 1_000_000L
+  }
 }
 
 private open class SecondAppStartActivity : Activity()

sentry-test-support/src/main/kotlin/io/sentry/test/Mocks.kt

@@ -75,6 +75,29 @@ class DeferredExecutorService : ISentryExecutorService {
   fun hasScheduledRunnables(): Boolean = scheduledRunnables.isNotEmpty()
 }
 
+/**
+ * Keeps the latest task scheduled with each delay instead of running it, so a test can run one
+ * timer, such as an idle timeout, while another, such as a deadline, stays pending.
+ */
+class ManualTimerExecutorService : ISentryExecutorService {
+  private val scheduled = mutableMapOf<Long, Runnable>()
+
+  fun runScheduled(delayMillis: Long) = synchronized(this) { scheduled.getValue(delayMillis) }.run()
+
+  override fun schedule(runnable: Runnable, delayMillis: Long): Future<*> {
+    synchronized(this) { scheduled[delayMillis] = runnable }
+    return FutureTask {}
+  }
+
+  override fun submit(runnable: Runnable): Future<*> = FutureTask {}
+
+  override fun <T> submit(callable: Callable<T>): Future<T> = FutureTask(callable)
+
+  override fun close(timeoutMillis: Long) {}
+
+  override fun isClosed(): Boolean = false
+}
+
 class NonOverridableNoOpSentryExecutorService : ISentryExecutorService {
   // mirrors NoOpSentryExecutorService: a task that is never run is reported as cancelled, so
   // callers can tell it apart from a queued one

sentry/src/main/java/io/sentry/SentryTracer.java

@@ -5,6 +5,7 @@
 import io.sentry.protocol.SentryId;
 import io.sentry.protocol.SentryTransaction;
 import io.sentry.protocol.TransactionNameSource;
+import io.sentry.time.Deadline;
 import io.sentry.util.AutoClosableReentrantLock;
 import io.sentry.util.CollectionUtils;
 import io.sentry.util.Objects;
@@ -15,6 +16,7 @@
 import java.util.Map;
 import java.util.concurrent.CopyOnWriteArrayList;
 import java.util.concurrent.Future;
+import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.concurrent.atomic.AtomicReference;
 import org.jetbrains.annotations.ApiStatus;
@@ -49,6 +51,15 @@ public final class SentryTracer implements ITransaction {
   private final @NotNull AtomicBoolean isIdleFinishTimerRunning = new AtomicBoolean(false);
   private final @NotNull AtomicBoolean isDeadlineTimerRunning = new AtomicBoolean(false);
 
+  /**
+   * When the deadline timeout is reached, or null without one.
+   *
+   * <p>The deadline timer counts on a clock that stops while an Android device is suspended, so it
+   * runs late after the device slept, and after the process was frozen the app's own threads can
+   * finish spans before it. This deadline keeps counting through both.
+   */
+  private volatile @Nullable Deadline deadline;
+
   private @NotNull TransactionNameSource transactionNameSource;
   private final @NotNull Instrumenter instrumenter;
   private final @NotNull Contexts contexts = new Contexts();
@@ -145,14 +156,23 @@ private void onIdleTimeoutReached() {
   }
 
   private void onDeadlineTimeoutReached() {
-    final @Nullable SpanStatus status = getStatus();
-    forceFinish(
-        (status != null) ? status : SpanStatus.DEADLINE_EXCEEDED,
-        transactionOptions.getIdleTimeout() != null,
-        null);
+    forceFinish(getDeadlineStatus(), transactionOptions.getIdleTimeout() != null, null);
     isDeadlineTimerRunning.set(false);
   }
 
+  /** Whether the deadline timeout has been reached, even if the deadline timer has not run yet. */
+  boolean hasDeadlinePassed() {
+    final @Nullable Deadline deadline = this.deadline;
+    return deadline != null && deadline.hasPassed();
+  }
+
+  /** The status the deadline gives: the transaction's own, if it has one. */
+  @NotNull
+  SpanStatus getDeadlineStatus() {
+    final @Nullable SpanStatus status = getStatus();
+    return (status != null) ? status : SpanStatus.DEADLINE_EXCEEDED;
+  }
+
   @Override
   public void forceFinish(
       final @NotNull SpanStatus status, final boolean dropIfNoChildren, final @Nullable Hint hint) {
@@ -310,6 +330,9 @@ private void scheduleDeadlineTimeout() {
         if (timersEnabled) {
           cancelDeadlineTimer();
           isDeadlineTimerRunning.set(true);
+          deadline =
+              Deadline.after(
+                  scopes.getOptions().getMonotonicTicker(), deadlineTimeOut, TimeUnit.MILLISECONDS);
           try {
             deadlineTimeoutFuture =
                 scopes

sentry/src/main/java/io/sentry/Span.java

@@ -196,7 +196,11 @@ public void finish(final @Nullable SpanStatus status, final @Nullable SentryDate
       return;
     }
 
-    this.context.setStatus(status);
+    // The deadline timer gives this status, but after the device slept or the process was frozen it
+    // runs late, and the app's own finish can come first. Either way the span outlived the
+    // deadline, and the status keeps it out of queries on span.status:ok.
+    this.context.setStatus(
+        transaction.hasDeadlinePassed() ? transaction.getDeadlineStatus() : status);
     this.timestamp = timestamp == null ? scopes.getOptions().getDateProvider().now() : timestamp;
     if (options.isTrimStart() || options.isTrimEnd()) {
       @Nullable SentryDate minChildStart = null;