fix: drop app-start transaction when deadline timer fires doze-delayed

CHANGELOG.md

@@ -15,6 +15,7 @@
 
 ### Fixes
 
+- Drop transactions whose deadline timer is delayed by device sleep ([#5755](https://github.com/getsentry/sentry-java/pull/5755))
 - Keep UI profiling running when `startProfiler` is called before a requested stop takes effect at the end of the current chunk ([#6291](https://github.com/getsentry/sentry-java/pull/6291))
   - Before, the start call was ignored and the profiler still stopped at the end of the chunk, even in `TRACE` mode while sampled spans were active. On API 34 and lower, every later profile also stopped after one chunk.
 

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

@@ -15,6 +15,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;
@@ -39,6 +40,8 @@ public final class SentryTracer implements ITransaction {
 
   private volatile @Nullable Future<?> idleTimeoutFuture;
   private volatile @Nullable Future<?> deadlineTimeoutFuture;
+  private volatile long deadlineTimeoutScheduledAtNanos;
+  private volatile boolean dropOnFinish = false;
 
   // Whether timeout tasks may still be scheduled. Set to false once the tracer is finished. The
   // executor itself is owned by the options (shared SDK-wide) and obtained from there when needed.
@@ -145,6 +148,34 @@ private void onIdleTimeoutReached() {
   }
 
   private void onDeadlineTimeoutReached() {
+    if (isFinished()) {
+      isDeadlineTimerRunning.set(false);
+      return;
+    }
+
+    final @Nullable Long deadlineTimeout = transactionOptions.getDeadlineTimeout();
+    if (deadlineTimeout != null) {
+      final long elapsedNanos =
+          scopes.getOptions().getDateProvider().now().nanoTimestamp()
+              - deadlineTimeoutScheduledAtNanos;
+      if (deadlineTimeout > 0
+          && TimeUnit.NANOSECONDS.toMillis(elapsedNanos) > deadlineTimeout * 2) {
+        scopes
+            .getOptions()
+            .getLogger()
+            .log(
+                SentryLevel.DEBUG,
+                "Dropping transaction %s because the deadline timer fired too late",
+                name);
+        // run the regular finish path (child spans, callbacks, collectors, profilers, scope and
+        // timers) but skip capturing the transaction
+        dropOnFinish = true;
+        forceFinish(SpanStatus.DEADLINE_EXCEEDED, false, null);
+        isDeadlineTimerRunning.set(false);
+        return;
+      }
+    }
+
     final @Nullable SpanStatus status = getStatus();
     forceFinish(
         (status != null) ? status : SpanStatus.DEADLINE_EXCEEDED,
@@ -276,6 +307,10 @@ public void finish(
         }
       }
 
+      if (dropOnFinish) {
+        return;
+      }
+
       if (dropIfNoChildren && children.isEmpty() && transactionOptions.getIdleTimeout() != null) {
         // if it's an idle transaction which has no children, we drop it to save user's quota
         scopes
@@ -310,6 +345,8 @@ private void scheduleDeadlineTimeout() {
         if (timersEnabled) {
           cancelDeadlineTimer();
           isDeadlineTimerRunning.set(true);
+          deadlineTimeoutScheduledAtNanos =
+              scopes.getOptions().getDateProvider().now().nanoTimestamp();
           try {
             deadlineTimeoutFuture =
                 scopes
@@ -533,7 +570,8 @@ private ISpan createChild(
           .getLogger()
           .log(
               SentryLevel.WARNING,
-              "Span operation: %s, description: %s dropped due to limit reached. Returning NoOpSpan.",
+              "Span operation: %s, description: %s dropped due to limit reached. Returning"
+                  + " NoOpSpan.",
               operation,
               description);
       return NoOpSpan.getInstance();
@@ -689,7 +727,8 @@ private boolean isProfileMissing(
           .getLogger()
           .log(
               SentryLevel.WARNING,
-              "Span operation: %s, description: %s dropped due to limit reached. Returning NoOpSpan.",
+              "Span operation: %s, description: %s dropped due to limit reached. Returning"
+                  + " NoOpSpan.",
               operation,
               description);
       return NoOpSpan.getInstance();
@@ -1045,6 +1084,24 @@ Future<?> getDeadlineTimeoutFuture() {
     return deadlineTimeoutFuture;
   }
 
+  @TestOnly
+  @Nullable
+  Future<?> getIdleTimeoutTask() {
+    return idleTimeoutFuture;
+  }
+
+  @TestOnly
+  @Nullable
+  Runnable getDeadlineTimeoutTask() {
+    return deadlineTimeoutFuture == null ? null : this::onDeadlineTimeoutReached;
+  }
+
+  @TestOnly
+  @Nullable
+  Object getTimer() {
+    return null;
+  }
+
   @TestOnly
   boolean areTimersEnabled() {
     return timersEnabled;

sentry/src/test/java/io/sentry/SentryTracerTest.kt

@@ -34,6 +34,11 @@ import org.mockito.kotlin.verify
 import org.mockito.kotlin.whenever
 
 class SentryTracerTest {
+  private class MutableDateProvider(var currentTimeMillis: Long = 0) : SentryDateProvider {
+    override fun now(): SentryDate =
+      SentryNanotimeDate(currentTimeMillis, DateUtils.millisToNanos(currentTimeMillis))
+  }
+
   private class Fixture {
     val options = SentryOptions()
     val scopes: Scopes
@@ -1108,19 +1113,112 @@ class SentryTracerTest {
   }
 
   @Test
-  fun `when deadline is reached transaction is finished`() {
-    // when a transaction with a deadline timeout is created
-    // and the tx and child keep on running
-    val transaction = fixture.getSut(deadlineTimeout = 20)
+  fun `when deadline is reached on time transaction and children are captured as deadline exceeded`() {
+    val dateProvider = MutableDateProvider()
+    val transaction =
+      fixture.getSut(
+        optionsConfiguration = { it.setDateProvider(dateProvider) },
+        deadlineTimeout = 10_000,
+      )
     val span = transaction.startChild("op")
 
-    // and the deadline is exceed
-    await.untilFalse(transaction.isDeadlineTimerRunning)
+    dateProvider.currentTimeMillis = 10_000
+    transaction.deadlineTimeoutTask!!.run()
 
-    // then both tx + span should be force finished
-    assertEquals(transaction.isFinished, true)
-    assertEquals(SpanStatus.DEADLINE_EXCEEDED, transaction.status)
-    assertEquals(SpanStatus.DEADLINE_EXCEEDED, span.status)
+    assertThat(transaction.isFinished).isTrue()
+    assertThat(transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED)
+    assertThat(span.isFinished).isTrue()
+    assertThat(span.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED)
+    verify(fixture.scopes)
+      .captureTransaction(
+        check { assertThat(it.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) },
+        anyOrNull(),
+        anyOrNull(),
+        anyOrNull(),
+      )
+  }
+
+  @Test
+  fun `when deadline timer fires after device sleep transaction is dropped and timers are cancelled`() {
+    val dateProvider = MutableDateProvider()
+    val logger = mock<ILogger>()
+    val transaction =
+      fixture.getSut(
+        optionsConfiguration = {
+          it.setDateProvider(dateProvider)
+          it.setLogger(logger)
+          it.isDebug = true
+        },
+        idleTimeout = 60_000,
+        deadlineTimeout = 10_000,
+      )
+    transaction.startChild("op")
+    transaction.scheduleFinish()
+    fixture.scopes.configureScope { it.transaction = transaction }
+
+    dateProvider.currentTimeMillis = 30_000
+    transaction.deadlineTimeoutTask!!.run()
+    assertThat(transaction.isFinished).isTrue()
+    transaction.finish()
+
+    verify(fixture.scopes, never())
+      .captureTransaction(anyOrNull(), anyOrNull(), anyOrNull(), anyOrNull())
+    verify(logger)
+      .log(
+        SentryLevel.DEBUG,
+        "Dropping transaction %s because the deadline timer fired too late",
+        "name",
+      )
+    assertThat(fixture.scopes.span).isNull()
+    assertThat(transaction.idleTimeoutTask).isNull()
+    assertThat(transaction.deadlineTimeoutTask).isNull()
+    assertThat(transaction.isFinishTimerRunning.get()).isFalse()
+    assertThat(transaction.isDeadlineTimerRunning.get()).isFalse()
+    assertThat(transaction.timer).isNull()
+  }
+
+  @Test
+  fun `when deadline timer fires after device sleep the regular finish cleanup still runs`() {
+    val dateProvider = MutableDateProvider()
+    var transactionFinishedCallbackCalled = false
+    val transaction =
+      fixture.getSut(
+        optionsConfiguration = { it.setDateProvider(dateProvider) },
+        idleTimeout = 60_000,
+        deadlineTimeout = 10_000,
+        transactionFinishedCallback = { transactionFinishedCallbackCalled = true },
+        samplingDecision = TracesSamplingDecision(true),
+      )
+    val span = transaction.startChild("op")
+
+    dateProvider.currentTimeMillis = 30_000
+    transaction.deadlineTimeoutTask!!.run()
+
+    assertThat(transaction.isFinished).isTrue()
+    assertThat(span.isFinished).isTrue()
+    assertThat(span.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED)
+    assertThat(transactionFinishedCallbackCalled).isTrue()
+    verify(fixture.compositePerformanceCollector)
+      .stop(check<ITransaction> { assertEquals(transaction, it) })
+    verify(fixture.scopes, never())
+      .captureTransaction(anyOrNull(), anyOrNull(), anyOrNull(), anyOrNull())
+  }
+
+  @Test
+  fun `when deadline timer fires at twice the deadline transaction is still captured`() {
+    val dateProvider = MutableDateProvider()
+    val transaction =
+      fixture.getSut(
+        optionsConfiguration = { it.setDateProvider(dateProvider) },
+        deadlineTimeout = 10_000,
+      )
+
+    dateProvider.currentTimeMillis = 20_000
+    transaction.deadlineTimeoutTask!!.run()
+
+    assertThat(transaction.isFinished).isTrue()
+    assertThat(transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED)
+    verify(fixture.scopes).captureTransaction(any(), anyOrNull(), anyOrNull(), anyOrNull())
   }
 
   @Test
@@ -1136,6 +1234,38 @@ class SentryTracerTest {
     assertEquals(transaction.isFinished, true)
     assertEquals(SpanStatus.OK, transaction.status)
     assertEquals(SpanStatus.OK, span.status)
+    verify(fixture.scopes).captureTransaction(any(), anyOrNull(), anyOrNull(), anyOrNull())
+  }
+
+  @Test
+  fun `when idle transaction without children reaches late deadline it is dropped once`() {
+    val dateProvider = MutableDateProvider()
+    val logger = mock<ILogger>()
+    val transaction =
+      fixture.getSut(
+        optionsConfiguration = {
+          it.setDateProvider(dateProvider)
+          it.setLogger(logger)
+          it.isDebug = true
+        },
+        idleTimeout = 60_000,
+        deadlineTimeout = 10_000,
+      )
+
+    dateProvider.currentTimeMillis = 30_000
+    transaction.deadlineTimeoutTask!!.run()
+
+    verify(fixture.scopes, never())
+      .captureTransaction(anyOrNull(), anyOrNull(), anyOrNull(), anyOrNull())
+    verify(logger, times(1))
+      .log(
+        SentryLevel.DEBUG,
+        "Dropping transaction %s because the deadline timer fired too late",
+        "name",
+      )
+    assertThat(transaction.idleTimeoutTask).isNull()
+    assertThat(transaction.deadlineTimeoutTask).isNull()
+    assertThat(transaction.timer).isNull()
   }
 
   @Test