diff --git a/CHANGELOG.md b/CHANGELOG.md index 1e05874449d..5839f4d447d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,6 +10,7 @@ ### Fixes - Android: Count deep sleep in breadcrumb, screenshot and view hierarchy debounce windows, so the first low-memory or battery breadcrumb after a long Doze is no longer dropped ([#6590](https://github.com/getsentry/sentry-java/pull/6590)) +- Android: Mark transactions and spans that finish after their deadline as `deadline_exceeded`, so `ui.load` transactions with TTID, TTFD or app start values that are hours long after a device sleep no longer report `ok` ([#6599](https://github.com/getsentry/sentry-java/pull/6599)) ## 8.64.0 diff --git a/sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt b/sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt index 1a88c1bec6d..931a171e480 100644 --- a/sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt +++ b/sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt @@ -15,6 +15,7 @@ import android.view.View import android.view.ViewTreeObserver import androidx.test.core.app.ApplicationProvider import androidx.test.ext.junit.runners.AndroidJUnit4 +import com.google.common.truth.Truth.assertThat import io.sentry.DateUtils import io.sentry.FullyDisplayedReporter import io.sentry.IScope @@ -43,7 +44,9 @@ import io.sentry.protocol.MeasurementValue import io.sentry.protocol.SentryId import io.sentry.protocol.TransactionNameSource import io.sentry.test.DeferredExecutorService +import io.sentry.test.ManualTimerExecutorService import io.sentry.test.getProperty +import io.sentry.time.TestMonotonicTicker import java.util.concurrent.Future import java.util.concurrent.TimeUnit import kotlin.test.AfterTest @@ -68,6 +71,7 @@ import org.mockito.kotlin.clearInvocations import org.mockito.kotlin.eq import org.mockito.kotlin.mock import org.mockito.kotlin.never +import org.mockito.kotlin.spy import org.mockito.kotlin.times import org.mockito.kotlin.verify import org.mockito.kotlin.whenever @@ -82,7 +86,12 @@ class ActivityLifecycleIntegrationTest { private class Fixture { val application = mock() val scopes = mock() - val options = SentryAndroidOptions().apply { dsn = "https://key@sentry.io/proj" } + val ticker = TestMonotonicTicker() + // SentryAndroidOptions is final and has no ticker setter, so a spy supplies the ticker. + val options = + spy(SentryAndroidOptions().apply { dsn = "https://key@sentry.io/proj" }).also { + whenever(it.monotonicTicker).thenReturn(ticker) + } val bundle = mock() val activityFramesTracker = mock() val transactionFinishedCallback = mock() @@ -2558,6 +2567,99 @@ class ActivityLifecycleIntegrationTest { assertNotEquals(0, lastUptimeMillis.nanoTimestamp()) } + @Test + fun `first frame drawn after the deadline passed changes only the status`() { + val timer = ManualTimerExecutorService() + val sut = fixture.getSut { + it.tracesSampleRate = 1.0 + it.timerExecutorService = timer + } + var nowMillis = START_MILLIS + fixture.options.dateProvider = SentryDateProvider { SentryNanotimeDate(nowMillis, 0) } + setAppStartTime(SentryNanotimeDate(START_MILLIS, 0)) + sut.register(fixture.scopes, fixture.options) + val view = fixture.createView() + val activity = createAndResumeActivity(sut, view) + val ttidSpan = sut.ttidSpanMap[activity]!! + val appStartSpan = sut.appStartSpan!! + + // the device sleeps before the first frame, and the deadline timer hasn't run yet + fixture.ticker.advance(3, TimeUnit.HOURS) + nowMillis += TimeUnit.HOURS.toMillis(3) + runFirstDraw(view) + timer.runScheduled(fixture.options.idleTimeout!!) + + val firstFrameNanos = TimeUnit.MILLISECONDS.toNanos(nowMillis) + for (span in listOf(ttidSpan, appStartSpan)) { + assertThat(span.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(firstFrameNanos) + } + assertThat( + (ttidSpan as Span).measurements[MeasurementValue.KEY_TIME_TO_INITIAL_DISPLAY]!!.value + ) + .isEqualTo(TimeUnit.HOURS.toMillis(3)) + assertThat(fixture.transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(fixture.transaction.finishDate!!.nanoTimestamp()).isEqualTo(firstFrameNanos) + } + + @Test + fun `full display reported after the deadline passed changes only the status`() { + val sut = fixture.getSut { + it.tracesSampleRate = 1.0 + it.isEnableTimeToFullDisplayTracing = true + } + var nowMillis = START_MILLIS + fixture.options.dateProvider = SentryDateProvider { SentryNanotimeDate(nowMillis, 0) } + setAppStartTime(SentryNanotimeDate(START_MILLIS, 0)) + sut.register(fixture.scopes, fixture.options) + val view = fixture.createView() + val activity = createAndResumeActivity(sut, view) + val ttfdSpan = sut.ttfdSpanMap[activity]!! + runFirstDraw(view) + + fixture.ticker.advance(3, TimeUnit.HOURS) + nowMillis += TimeUnit.HOURS.toMillis(3) + fixture.options.fullyDisplayedReporter.reportFullyDrawn() + + assertThat(ttfdSpan.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(ttfdSpan.finishDate!!.nanoTimestamp()) + .isEqualTo(TimeUnit.MILLISECONDS.toNanos(nowMillis)) + assertThat((ttfdSpan as Span).measurements[MeasurementValue.KEY_TIME_TO_FULL_DISPLAY]!!.value) + .isEqualTo(TimeUnit.HOURS.toMillis(3)) + } + + @Test + fun `first frame drawn before the deadline keeps its status`() { + val sut = fixture.getSut { it.tracesSampleRate = 1.0 } + var nowMillis = START_MILLIS + fixture.options.dateProvider = SentryDateProvider { SentryNanotimeDate(nowMillis, 0) } + setAppStartTime(SentryNanotimeDate(START_MILLIS, 0)) + sut.register(fixture.scopes, fixture.options) + val view = fixture.createView() + val activity = createAndResumeActivity(sut, view) + val ttidSpan = sut.ttidSpanMap[activity]!! + + fixture.ticker.advance(29, TimeUnit.SECONDS) + nowMillis += TimeUnit.SECONDS.toMillis(29) + runFirstDraw(view) + + assertThat(ttidSpan.status).isEqualTo(SpanStatus.OK) + assertThat(ttidSpan.finishDate!!.nanoTimestamp()) + .isEqualTo(TimeUnit.MILLISECONDS.toNanos(nowMillis)) + assertThat( + (ttidSpan as Span).measurements[MeasurementValue.KEY_TIME_TO_INITIAL_DISPLAY]!!.value + ) + .isEqualTo(TimeUnit.SECONDS.toMillis(29)) + } + + private fun createAndResumeActivity(sut: ActivityLifecycleIntegration, view: View): Activity { + val activity = mock() + whenever(activity.findViewById(any())).thenReturn(view) + sut.onActivityCreated(activity, fixture.bundle) + sut.onActivityResumed(activity) + return activity + } + private fun SentryTracer.isFinishing() = getProperty("finishStatus").getProperty("isFinishing") @@ -2645,6 +2747,10 @@ class ActivityLifecycleIntegrationTest { AppStartMetrics.getInstance().onActivityCreated(mock(), mock()) } } + + private companion object { + const val START_MILLIS = 1_000_000L + } } private open class SecondAppStartActivity : Activity() diff --git a/sentry-test-support/src/main/kotlin/io/sentry/test/Mocks.kt b/sentry-test-support/src/main/kotlin/io/sentry/test/Mocks.kt index b66c0f29475..41b4baae64a 100644 --- a/sentry-test-support/src/main/kotlin/io/sentry/test/Mocks.kt +++ b/sentry-test-support/src/main/kotlin/io/sentry/test/Mocks.kt @@ -75,6 +75,29 @@ class DeferredExecutorService : ISentryExecutorService { fun hasScheduledRunnables(): Boolean = scheduledRunnables.isNotEmpty() } +/** + * Keeps the latest task scheduled with each delay instead of running it, so a test can run one + * timer, such as an idle timeout, while another, such as a deadline, stays pending. + */ +class ManualTimerExecutorService : ISentryExecutorService { + private val scheduled = mutableMapOf() + + fun runScheduled(delayMillis: Long) = synchronized(this) { scheduled.getValue(delayMillis) }.run() + + override fun schedule(runnable: Runnable, delayMillis: Long): Future<*> { + synchronized(this) { scheduled[delayMillis] = runnable } + return FutureTask {} + } + + override fun submit(runnable: Runnable): Future<*> = FutureTask {} + + override fun submit(callable: Callable): Future = FutureTask(callable) + + override fun close(timeoutMillis: Long) {} + + override fun isClosed(): Boolean = false +} + class NonOverridableNoOpSentryExecutorService : ISentryExecutorService { // mirrors NoOpSentryExecutorService: a task that is never run is reported as cancelled, so // callers can tell it apart from a queued one diff --git a/sentry/src/main/java/io/sentry/SentryTracer.java b/sentry/src/main/java/io/sentry/SentryTracer.java index cc1ce8e22ac..a4f527f0f58 100644 --- a/sentry/src/main/java/io/sentry/SentryTracer.java +++ b/sentry/src/main/java/io/sentry/SentryTracer.java @@ -5,6 +5,7 @@ import io.sentry.protocol.SentryId; import io.sentry.protocol.SentryTransaction; import io.sentry.protocol.TransactionNameSource; +import io.sentry.time.Deadline; import io.sentry.util.AutoClosableReentrantLock; import io.sentry.util.CollectionUtils; import io.sentry.util.Objects; @@ -15,6 +16,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; @@ -49,6 +51,15 @@ public final class SentryTracer implements ITransaction { private final @NotNull AtomicBoolean isIdleFinishTimerRunning = new AtomicBoolean(false); private final @NotNull AtomicBoolean isDeadlineTimerRunning = new AtomicBoolean(false); + /** + * When the deadline timeout is reached, or null without one. + * + *

The deadline timer counts on a clock that stops while an Android device is suspended, so it + * runs late after the device slept, and after the process was frozen the app's own threads can + * finish spans before it. This deadline keeps counting through both. + */ + private volatile @Nullable Deadline deadline; + private @NotNull TransactionNameSource transactionNameSource; private final @NotNull Instrumenter instrumenter; private final @NotNull Contexts contexts = new Contexts(); @@ -145,14 +156,23 @@ private void onIdleTimeoutReached() { } private void onDeadlineTimeoutReached() { - final @Nullable SpanStatus status = getStatus(); - forceFinish( - (status != null) ? status : SpanStatus.DEADLINE_EXCEEDED, - transactionOptions.getIdleTimeout() != null, - null); + forceFinish(getDeadlineStatus(), transactionOptions.getIdleTimeout() != null, null); isDeadlineTimerRunning.set(false); } + /** Whether the deadline timeout has been reached, even if the deadline timer has not run yet. */ + boolean hasDeadlinePassed() { + final @Nullable Deadline deadline = this.deadline; + return deadline != null && deadline.hasPassed(); + } + + /** The status the deadline gives: the transaction's own, if it has one. */ + @NotNull + SpanStatus getDeadlineStatus() { + final @Nullable SpanStatus status = getStatus(); + return (status != null) ? status : SpanStatus.DEADLINE_EXCEEDED; + } + @Override public void forceFinish( final @NotNull SpanStatus status, final boolean dropIfNoChildren, final @Nullable Hint hint) { @@ -310,6 +330,9 @@ private void scheduleDeadlineTimeout() { if (timersEnabled) { cancelDeadlineTimer(); isDeadlineTimerRunning.set(true); + deadline = + Deadline.after( + scopes.getOptions().getMonotonicTicker(), deadlineTimeOut, TimeUnit.MILLISECONDS); try { deadlineTimeoutFuture = scopes diff --git a/sentry/src/main/java/io/sentry/Span.java b/sentry/src/main/java/io/sentry/Span.java index 7ee7eed1900..b91978b18ff 100644 --- a/sentry/src/main/java/io/sentry/Span.java +++ b/sentry/src/main/java/io/sentry/Span.java @@ -196,7 +196,11 @@ public void finish(final @Nullable SpanStatus status, final @Nullable SentryDate return; } - this.context.setStatus(status); + // The deadline timer gives this status, but after the device slept or the process was frozen it + // runs late, and the app's own finish can come first. Either way the span outlived the + // deadline, and the status keeps it out of queries on span.status:ok. + this.context.setStatus( + transaction.hasDeadlinePassed() ? transaction.getDeadlineStatus() : status); this.timestamp = timestamp == null ? scopes.getOptions().getDateProvider().now() : timestamp; if (options.isTrimStart() || options.isTrimEnd()) { @Nullable SentryDate minChildStart = null; diff --git a/sentry/src/test/java/io/sentry/SentryTracerTest.kt b/sentry/src/test/java/io/sentry/SentryTracerTest.kt index 20232f56b4d..feca8ad65f6 100644 --- a/sentry/src/test/java/io/sentry/SentryTracerTest.kt +++ b/sentry/src/test/java/io/sentry/SentryTracerTest.kt @@ -5,11 +5,15 @@ import io.sentry.profiling.ProfileRecordingState import io.sentry.protocol.SentryId import io.sentry.protocol.TransactionNameSource import io.sentry.protocol.User +import io.sentry.test.ManualTimerExecutorService import io.sentry.test.createTestScopes import io.sentry.test.getProperty +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 @@ -35,7 +39,12 @@ import org.mockito.kotlin.whenever class SentryTracerTest { private class Fixture { - val options = SentryOptions() + val ticker = TestMonotonicTicker() + // SentryOptions has no ticker setter. + val options = + object : SentryOptions() { + override fun getMonotonicTicker(): MonotonicTicker = ticker + } val scopes: Scopes val compositePerformanceCollector: CompositePerformanceCollector @@ -1870,4 +1879,111 @@ class SentryTracerTest { assertNull(transaction.getTag(null)) assertNull(transaction.getTag("k")) } + + @Test + fun `when a span and the transaction finish after the deadline passed, only their status changes`() { + val clock = TestDateProvider() + val transaction = getSutWithDeadline(ManualTimerExecutorService(), clock) + val span = transaction.startChild("op") + + sleepFor(3, TimeUnit.HOURS, clock) + span.finish(SpanStatus.OK) + transaction.finish(SpanStatus.OK) + + assertThat(span.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(clock.nowNanos) + assertThat(transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.nowNanos) + } + + @Test + fun `when the idle timeout runs after the deadline passed, only the transaction status changes`() { + val timer = ManualTimerExecutorService() + val clock = TestDateProvider() + val transaction = getSutWithDeadline(timer, clock, idleTimeout = IDLE_MILLIS) + // schedules the idle timeout, since the transaction doesn't wait for children + transaction.startChild("op").finish() + + sleepFor(3, TimeUnit.HOURS, clock) + timer.runScheduled(IDLE_MILLIS) + + assertThat(transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.nowNanos) + } + + @Test + fun `when force finished after the deadline passed, the transaction gets the deadline status`() { + val clock = TestDateProvider() + val transaction = getSutWithDeadline(ManualTimerExecutorService(), clock) + val span = transaction.startChild("op") + + sleepFor(3, TimeUnit.HOURS, clock) + transaction.forceFinish(SpanStatus.ABORTED, false, null) + + assertThat(transaction.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.nowNanos) + assertThat(span.status).isEqualTo(SpanStatus.DEADLINE_EXCEEDED) + assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(clock.nowNanos) + } + + @Test + fun `when spans finish after the deadline passed, they keep a status the transaction already has`() { + val transaction = getSutWithDeadline(ManualTimerExecutorService(), TestDateProvider()) + val span = transaction.startChild("op") + transaction.status = SpanStatus.UNAVAILABLE + + fixture.ticker.advance(3, TimeUnit.HOURS) + span.finish(SpanStatus.OK) + transaction.finish(SpanStatus.OK) + + assertThat(span.status).isEqualTo(SpanStatus.UNAVAILABLE) + assertThat(transaction.status).isEqualTo(SpanStatus.UNAVAILABLE) + } + + @Test + fun `when spans finish before the deadline, they keep their own status`() { + val clock = TestDateProvider() + val transaction = getSutWithDeadline(ManualTimerExecutorService(), clock) + val span = transaction.startChild("op") + + sleepFor(DEADLINE_MILLIS - 1, TimeUnit.MILLISECONDS, clock) + span.finish(SpanStatus.OK) + transaction.finish(SpanStatus.OK) + + assertThat(span.status).isEqualTo(SpanStatus.OK) + assertThat(span.finishDate!!.nanoTimestamp()).isEqualTo(clock.nowNanos) + assertThat(transaction.status).isEqualTo(SpanStatus.OK) + assertThat(transaction.finishDate!!.nanoTimestamp()).isEqualTo(clock.nowNanos) + } + + private fun getSutWithDeadline( + timer: ManualTimerExecutorService, + clock: TestDateProvider, + idleTimeout: Long? = null, + ): SentryTracer = + fixture.getSut( + optionsConfiguration = { + it.timerExecutorService = timer + it.dateProvider = clock + }, + idleTimeout = idleTimeout, + deadlineTimeout = DEADLINE_MILLIS, + ) + + /** Moves both clocks on, as a device does across a suspend that the timers don't notice. */ + private fun sleepFor(amount: Long, unit: TimeUnit, clock: TestDateProvider) { + fixture.ticker.advance(amount, unit) + clock.nowNanos += unit.toNanos(amount) + } + + private class TestDateProvider : SentryDateProvider { + var nowNanos = 1_000_000_000_000L + + override fun now(): SentryDate = SentryLongDate(nowNanos) + } + + private companion object { + const val DEADLINE_MILLIS = 30_000L + const val IDLE_MILLIS = 3_000L + } }