diff --git a/CHANGELOG.md b/CHANGELOG.md index 505aa075b5..0a523497f4 100644 --- a/CHANGELOG.md +++ b/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. diff --git a/sentry/src/main/java/io/sentry/SentryTracer.java b/sentry/src/main/java/io/sentry/SentryTracer.java index 475729f3b6..1ca005a683 100644 --- a/sentry/src/main/java/io/sentry/SentryTracer.java +++ b/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; diff --git a/sentry/src/test/java/io/sentry/SentryTracerTest.kt b/sentry/src/test/java/io/sentry/SentryTracerTest.kt index de23f5be2a..6e8cca0e80 100644 --- a/sentry/src/test/java/io/sentry/SentryTracerTest.kt +++ b/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() + 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 { 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() + 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