fix(tracing): End timed-out transactions when the timeout is due

CHANGELOG.md

@@ -1,5 +1,11 @@
 # Changelog
 
+## Unreleased
+
+### Fixes
+
+- End a timed-out transaction at the moment its timeout fell due, rather than whenever the timer thread next gets to run. A device that slept, or froze the process, through an idle or deadline timeout used to turn an abandoned app start into a multi-hour transaction ([#6091](https://github.com/getsentry/sentry-java/pull/6091))
+
 ## 8.56.0
 
 ### Behavioral Changes

sentry/api/sentry.api

@@ -7640,6 +7640,7 @@ public final class io/sentry/time/SystemEpochClock : io/sentry/time/EpochClock {
 public final class io/sentry/time/Timestamp {
 	public fun epochNanos ()J
 	public fun equals (Ljava/lang/Object;)Z
+	public fun getSentryDate ()Lio/sentry/SentryDate;
 	public fun hashCode ()I
 	public static fun ofEpochNanos (J)Lio/sentry/time/Timestamp;
 	public fun toString ()Ljava/lang/String;

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

@@ -5,6 +5,8 @@
 import io.sentry.protocol.SentryId;
 import io.sentry.protocol.SentryTransaction;
 import io.sentry.protocol.TransactionNameSource;
+import io.sentry.time.Deadline;
+import io.sentry.time.Timestamp;
 import io.sentry.util.AutoClosableReentrantLock;
 import io.sentry.util.CollectionUtils;
 import io.sentry.util.Objects;
@@ -15,6 +17,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;
@@ -40,6 +43,10 @@ public final class SentryTracer implements ITransaction {
   private volatile @Nullable Future<?> idleTimeoutFuture;
   private volatile @Nullable Future<?> deadlineTimeoutFuture;
 
+  // When each timeout falls due, captured when its timer is scheduled. See Expiry.
+  private volatile @Nullable Expiry idleExpiry;
+  private volatile @Nullable Expiry deadlineExpiry;
+
   // 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.
   private volatile boolean timersEnabled = false;
@@ -117,6 +124,7 @@ public void scheduleFinish() {
         if (idleTimeout != null) {
           cancelIdleTimer();
           isIdleFinishTimerRunning.set(true);
+          idleExpiry = expiryIn(idleTimeout);
 
           try {
             idleTimeoutFuture =
@@ -140,7 +148,7 @@ public void scheduleFinish() {
 
   private void onIdleTimeoutReached() {
     final @Nullable SpanStatus status = getStatus();
-    finish((status != null) ? status : SpanStatus.OK);
+    finish((status != null) ? status : SpanStatus.OK, finishDateOf(idleExpiry));
     isIdleFinishTimerRunning.set(false);
   }
 
@@ -149,18 +157,77 @@ private void onDeadlineTimeoutReached() {
     forceFinish(
         (status != null) ? status : SpanStatus.DEADLINE_EXCEEDED,
         transactionOptions.getIdleTimeout() != null,
-        null);
+        null,
+        finishDateOf(deadlineExpiry));
     isDeadlineTimerRunning.set(false);
   }
 
+  /** When a timeout of {@code timeoutMillis}, scheduled now, falls due. */
+  private @NotNull Expiry expiryIn(final long timeoutMillis) {
+    // Yeah, we can just reach in to that scopes.options and grab whatever we want. Can't even hide
+    // this one behind an interface.
+    final @NotNull SentryOptions options = scopes.getOptions();
+    return new Expiry(
+        Deadline.after(options.getMonotonicTicker(), timeoutMillis, TimeUnit.MILLISECONDS),
+        // This is just the current Timestamp + deadline as a wall clock time.
+        Timestamp.ofEpochNanos(
+            options.getEpochClock().now().epochNanos()
+                + TimeUnit.MILLISECONDS.toNanos(timeoutMillis)));
+  }
+
+  // A little bridge between the new Timestamp API and the old SentryDate.
+  private static @Nullable SentryDate finishDateOf(final @Nullable Expiry expiry) {
+    // In Kotlin it would be expiry?.expiredAt()?.sentryDate if that makes it easier to read.
+    final @Nullable Timestamp expiredAt = expiry == null ? null : expiry.expiredAt();
+    return expiredAt == null ? null : expiredAt.getSentryDate();
+  }
+
+  /**
+   * When a timeout falls due: the instant to end at, and whether it has arrived.
+   *
+   * <p>The timers run on a thread frozen while the device sleeps or the process is cached, so one
+   * scheduled for 30s can fire hours later. Ending at the wake-up time turns an app start the user
+   * walked away from into a multi-hour transaction, so an expired timeout ends at the instant it
+   * fell due instead.
+   *
+   * <p>Only a {@link Deadline} can say whether it expired: the executor's own delay stops during
+   * deep sleep, and the wall clock can step either way while the timer waits.
+   */
+  private static final class Expiry {
+
+    private final @NotNull Deadline deadline;
+    private final @NotNull Timestamp expiredAt;
+
+    Expiry(final @NotNull Deadline deadline, final @NotNull Timestamp expiredAt) {
+      this.deadline = deadline;
+      this.expiredAt = expiredAt;
+    }
+
+    /** The instant to end at, or null to end now because the timeout has not actually expired. */
+    @Nullable
+    Timestamp expiredAt() {
+      return deadline.hasPassed() ? expiredAt : null;
+    }
+  }
+
   @Override
-  public @NotNull void forceFinish(
+  public void forceFinish(
       final @NotNull SpanStatus status, final boolean dropIfNoChildren, final @Nullable Hint hint) {
+    forceFinish(status, dropIfNoChildren, hint, null);
+  }
+
+  // Use the finishDate provided to finish the transaction in case the timeout/deadline has passed.
+  private void forceFinish(
+      final @NotNull SpanStatus status,
+      final boolean dropIfNoChildren,
+      final @Nullable Hint hint,
+      final @Nullable SentryDate finishDate) {
     if (isFinished()) {
       return;
     }
 
-    final @NotNull SentryDate finishTimestamp = scopes.getOptions().getDateProvider().now();
+    final @NotNull SentryDate finishTimestamp =
+        finishDate != null ? finishDate : scopes.getOptions().getDateProvider().now();
 
     // abort all child-spans first, this ensures the transaction can be finished,
     // even if waitForChildren is true
@@ -310,6 +377,7 @@ private void scheduleDeadlineTimeout() {
         if (timersEnabled) {
           cancelDeadlineTimer();
           isDeadlineTimerRunning.set(true);
+          deadlineExpiry = expiryIn(deadlineTimeOut);
           try {
             deadlineTimeoutFuture =
                 scopes

sentry/src/main/java/io/sentry/time/Timestamp.java

@@ -1,5 +1,7 @@
 package io.sentry.time;
 
+import io.sentry.SentryDate;
+import io.sentry.SentryLongDate;
 import org.jetbrains.annotations.ApiStatus;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.Nullable;
@@ -47,11 +49,20 @@ public boolean equals(final @Nullable Object other) {
 
   @Override
   public int hashCode() {
-    return (int) (epochNanos ^ (epochNanos >>> 32));
+    return Long.hashCode(epochNanos);
   }
 
   @Override
   public @NotNull String toString() {
     return "Timestamp{epochNanos=" + epochNanos + '}';
   }
+
+  /**
+   * This forms an easy bridge between our old API and the new API.
+   *
+   * @return a SentryDate implemented by a SentryLongDate
+   */
+  public SentryDate getSentryDate() {
+    return new SentryLongDate(epochNanos);
+  }
 }

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

@@ -5,11 +5,17 @@ import io.sentry.profiling.ProfileRecordingState
 import io.sentry.protocol.SentryId
 import io.sentry.protocol.TransactionNameSource
 import io.sentry.protocol.User
+import io.sentry.test.DeferredExecutorService
 import io.sentry.test.createTestScopes
 import io.sentry.test.getProperty
+import io.sentry.time.EpochClock
+import io.sentry.time.FixedEpochClock
+import io.sentry.time.MonotonicTicker
+import io.sentry.time.TestMonotonicTicker
 import io.sentry.util.thread.IThreadChecker
 import java.time.LocalDateTime
 import java.time.ZoneOffset
+import java.util.concurrent.TimeUnit
 import kotlin.test.Test
 import kotlin.test.assertEquals
 import kotlin.test.assertFalse
@@ -34,8 +40,18 @@ import org.mockito.kotlin.verify
 import org.mockito.kotlin.whenever
 
 class SentryTracerTest {
+  /** The clocks have getters but no setters on options, so a test fakes them by overriding. */
+  private class TestOptions : SentryOptions() {
+    var testEpochClock: EpochClock? = null
+    var testTicker: MonotonicTicker? = null
+
+    override fun getEpochClock(): EpochClock = testEpochClock ?: super.getEpochClock()
+
+    override fun getMonotonicTicker(): MonotonicTicker = testTicker ?: super.getMonotonicTicker()
+  }
+
   private class Fixture {
-    val options = SentryOptions()
+    val options = TestOptions()
     val scopes: Scopes
     val compositePerformanceCollector: CompositePerformanceCollector
 
@@ -79,6 +95,32 @@ class SentryTracerTest {
 
   private val fixture = Fixture()
 
+  /** An arbitrary but fixed instant the clock tests measure from. */
+  private val start = 1_000_000_000_000L
+
+  /**
+   * Everything the timeout logic reads, under the test's control: what time it is, how much time
+   * has passed, and when the timer gets to run.
+   */
+  private class Clocks(startEpochNanos: Long) {
+    val epoch = FixedEpochClock(startEpochNanos)
+    val ticker = TestMonotonicTicker()
+    val timer = DeferredExecutorService()
+
+    /** Time passing for real: every clock moves together, as they do on a device. */
+    fun advance(amount: Long, unit: TimeUnit) {
+      epoch.epochNanos += unit.toNanos(amount)
+      ticker.advance(amount, unit)
+    }
+
+    fun installOn(options: TestOptions) {
+      options.testEpochClock = epoch
+      options.testTicker = ticker
+      options.timerExecutorService = timer
+      options.dateProvider = SentryDateProvider { SentryLongDate(epoch.epochNanos) }
+    }
+  }
+
   @Test
   fun `transfer origin from transaction options to transaction context`() {
     fixture.getSut()
@@ -1103,6 +1145,83 @@ class SentryTracerTest {
     assertEquals(SpanStatus.DEADLINE_EXCEEDED, span.status)
   }
 
+  @Test
+  fun `when the deadline timer fires late, tx and children end when the deadline fell due`() {
+    val clocks = Clocks(start)
+    clocks.installOn(fixture.options)
+    val transaction = fixture.getSut(deadlineTimeout = 20)
+    val span = transaction.startChild("op")
+
+    // the device sleeps through the deadline; the timer thread only runs again three hours on
+    clocks.advance(3, TimeUnit.HOURS)
+    clocks.timer.runAll()
+
+    val due = start + TimeUnit.MILLISECONDS.toNanos(20)
+    assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(due)
+    assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(due)
+  }
+
+  @Test
+  fun `when the wall clock steps back past the deadline, the transaction still ends when it fell due`() {
+    val clocks = Clocks(start)
+    clocks.installOn(fixture.options)
+    val transaction = fixture.getSut(deadlineTimeout = 20)
+
+    // an NTP correction drags the wall clock back while the timer waits, so the due instant now
+    // looks like it is ahead of us. Whether the deadline expired is not the wall clock's to say
+    clocks.epoch.epochNanos = start - TimeUnit.HOURS.toNanos(1)
+    clocks.ticker.advance(20, TimeUnit.MILLISECONDS)
+    clocks.timer.runAll()
+
+    assertThat(transaction.finishDate!!.nanoTimestamp())
+      .isEqualTo(start + TimeUnit.MILLISECONDS.toNanos(20))
+  }
+
+  @Test
+  fun `when the deadline timer fires on time, the transaction ends when it fell due`() {
+    val clocks = Clocks(start)
+    clocks.installOn(fixture.options)
+    val transaction = fixture.getSut(deadlineTimeout = 20)
+    transaction.startChild("op")
+
+    clocks.advance(20, TimeUnit.MILLISECONDS)
+    clocks.timer.runAll()
+
+    // an expired deadline ends the transaction at the deadline, not at whenever the timer ran
+    assertThat(transaction.finishDate!!.nanoTimestamp())
+      .isEqualTo(start + TimeUnit.MILLISECONDS.toNanos(20))
+  }
+
+  @Test
+  fun `when the deadline has not expired, the transaction ends now`() {
+    val clocks = Clocks(start)
+    clocks.installOn(fixture.options)
+    // scheduling fails, so the tracer finishes inline while the deadline is still in the future
+    val executor = mock<ISentryExecutorService>()
+    whenever(executor.schedule(any(), any())).thenThrow(RuntimeException("rejected"))
+
+    val transaction =
+      fixture.getSut(
+        optionsConfiguration = { it.timerExecutorService = executor },
+        deadlineTimeout = 20,
+      )
+
+    assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(start)
+  }
+
+  @Test
+  fun `when the idle timer fires late, the transaction ends when the idle timeout fell due`() {
+    val clocks = Clocks(start)
+    clocks.installOn(fixture.options)
+    val transaction = fixture.getSut(idleTimeout = 20)
+
+    clocks.advance(3, TimeUnit.HOURS)
+    clocks.timer.runAll()
+
+    assertThat(transaction.finishDate!!.nanoTimestamp())
+      .isEqualTo(start + TimeUnit.MILLISECONDS.toNanos(20))
+  }
+
   @Test
   fun `when transaction is finished before deadline is reached, deadline should not be running anymore`() {
     val transaction = fixture.getSut(deadlineTimeout = 1000)