diff --git a/CHANGELOG.md b/CHANGELOG.md index a3baff8d6b..1032285e31 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -30,6 +30,7 @@ ### Fixes +- Drop transactions whose deadline timer is delayed by device sleep ([#5755](https://github.com/getsentry/sentry-java/pull/5755)) - Fix main thread identification for tombstone (native crash) events ([#5742](https://github.com/getsentry/sentry-java/pull/5742)) ### Dependencies diff --git a/sentry/src/main/java/io/sentry/SentryTracer.java b/sentry/src/main/java/io/sentry/SentryTracer.java index 9729ac406b..5814a22217 100644 --- a/sentry/src/main/java/io/sentry/SentryTracer.java +++ b/sentry/src/main/java/io/sentry/SentryTracer.java @@ -39,6 +39,7 @@ public final class SentryTracer implements ITransaction { private volatile @Nullable TimerTask idleTimeoutTask; private volatile @Nullable TimerTask deadlineTimeoutTask; + private volatile long deadlineTimeoutScheduledAtNanos; private volatile @Nullable Timer timer = null; private final @NotNull AutoClosableReentrantLock timerLock = new AutoClosableReentrantLock(); @@ -146,6 +147,48 @@ 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 && DateUtils.nanosToMillis(elapsedNanos) > deadlineTimeout * 2.0) { + scopes + .getOptions() + .getLogger() + .log( + SentryLevel.DEBUG, + "Dropping transaction %s because the deadline timer fired too late", + name); + root.finish(); + scopes.configureScope( + scope -> { + scope.withTransaction( + transaction -> { + if (transaction == this) { + scope.clearTransaction(); + } + }); + }); + if (timer != null) { + try (final @NotNull ISentryLifecycleToken ignored = timerLock.acquire()) { + if (timer != null) { + cancelIdleTimer(); + cancelDeadlineTimer(); + timer.cancel(); + timer = null; + } + } + } + return; + } + } + final @Nullable SpanStatus status = getStatus(); forceFinish( (status != null) ? status : SpanStatus.DEADLINE_EXCEEDED, @@ -310,6 +353,8 @@ private void scheduleDeadlineTimeout() { if (timer != null) { cancelDeadlineTimer(); isDeadlineTimerRunning.set(true); + deadlineTimeoutScheduledAtNanos = + scopes.getOptions().getDateProvider().now().nanoTimestamp(); deadlineTimeoutTask = new TimerTask() { @Override @@ -536,7 +581,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(); @@ -633,7 +679,8 @@ private void setDefaultSpanData(final @NotNull ISpan span) { .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(); diff --git a/sentry/src/test/java/io/sentry/SentryTracerTest.kt b/sentry/src/test/java/io/sentry/SentryTracerTest.kt index 3b808dd222..29a33860bd 100644 --- a/sentry/src/test/java/io/sentry/SentryTracerTest.kt +++ b/sentry/src/test/java/io/sentry/SentryTracerTest.kt @@ -1,5 +1,6 @@ package io.sentry +import com.google.common.truth.Truth.assertThat import io.sentry.protocol.SentryId import io.sentry.protocol.TransactionNameSource import io.sentry.protocol.User @@ -28,6 +29,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 @@ -925,19 +931,85 @@ 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 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 @@ -953,6 +1025,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