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. + * + *
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
diff --git a/sentry/src/main/java/io/sentry/time/Timestamp.java b/sentry/src/main/java/io/sentry/time/Timestamp.java
index d703cfb9c9..87395ab8d5 100644
--- a/sentry/src/main/java/io/sentry/time/Timestamp.java
+++ b/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);
+ }
}
diff --git a/sentry/src/test/java/io/sentry/SentryTracerTest.kt b/sentry/src/test/java/io/sentry/SentryTracerTest.kt
index 7c6324db0a..950a9c8d06 100644
--- a/sentry/src/test/java/io/sentry/SentryTracerTest.kt
+++ b/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