diff --git a/CHANGELOG.md b/CHANGELOG.md index 85bbfc57c8f..78bdf0a45cf 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,7 @@ ### Fixes +- Idle spans (including those produced by `SentryTraced`) now let any idle parent transaction finish after the idle timeout rather than waiting for the deadline and reporting `DEADLINE_EXCEEDED` ([#6396](https://github.com/getsentry/sentry-java/pull/6396)). - 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-compose/src/androidUnitTest/kotlin/io/sentry/compose/SentryTracedTest.kt b/sentry-compose/src/androidUnitTest/kotlin/io/sentry/compose/SentryTracedTest.kt index 431ce297c46..935fb6933d5 100644 --- a/sentry-compose/src/androidUnitTest/kotlin/io/sentry/compose/SentryTracedTest.kt +++ b/sentry-compose/src/androidUnitTest/kotlin/io/sentry/compose/SentryTracedTest.kt @@ -31,6 +31,7 @@ import io.sentry.ITransaction import io.sentry.NoOpSpan import io.sentry.Sentry import io.sentry.SentryOptions +import io.sentry.SpanStatus import io.sentry.TransactionOptions import kotlin.test.assertFailsWith import org.junit.After @@ -446,8 +447,30 @@ class SentryTracedTest { assertThat(renderingTx.countSpans(OP_RENDER)).isEqualTo(0) } + @Test + fun `an idle transaction hosting a traced composable finishes after the idle timeout`() { + val tx = + initSentryAndStartTransaction( + "tx", + configureTransactionOptions = { transactionOptions -> + transactionOptions.idleTimeout = 1_000 + transactionOptions.isWaitForChildren = true + }, + ) + + rule.setContent { + ProvideSentrySpan(tx) { SentryTraced(tag = "product_info") { Box(Modifier.size(1.dp)) } } + } + tx.waitForSpanCount(OP_COMPOSE, 1) + + rule.waitUntil(timeoutMillis = 5_000) { tx.isFinished } + assertThat(tx.status).isEqualTo(SpanStatus.OK) + assertThat(tx.singleSpan(OP_PARENT_COMPOSITION).isFinished).isTrue() + } + private fun initSentryAndStartTransaction( name: String, + configureTransactionOptions: (TransactionOptions) -> Unit = {}, configureOptions: (SentryOptions) -> Unit = {}, ): ITransaction { lateinit var tx: ITransaction @@ -460,7 +483,7 @@ class SentryTracedTest { }, true, ) - tx = startBoundTransaction(name) + tx = startBoundTransaction(name, configureTransactionOptions) var boundTransaction: ITransaction? = null Sentry.configureScope { boundTransaction = it.transaction } assertThat(boundTransaction).isSameInstanceAs(tx) @@ -468,9 +491,16 @@ class SentryTracedTest { return tx } - private fun startBoundTransaction(name: String): ITransaction { - val transaction = - Sentry.startTransaction(name, "test", TransactionOptions().apply { isBindToScope = true }) + private fun startBoundTransaction( + name: String, + configureTransactionOptions: (TransactionOptions) -> Unit = {}, + ): ITransaction { + val transactionOptions = + TransactionOptions().apply { + isBindToScope = true + configureTransactionOptions(this) + } + val transaction = Sentry.startTransaction(name, "test", transactionOptions) Sentry.configureScope { it.setTransaction(transaction) } return transaction } diff --git a/sentry/src/main/java/io/sentry/SentryTracer.java b/sentry/src/main/java/io/sentry/SentryTracer.java index 781cf51417e..96f5b183a50 100644 --- a/sentry/src/main/java/io/sentry/SentryTracer.java +++ b/sentry/src/main/java/io/sentry/SentryTracer.java @@ -469,7 +469,13 @@ private ISpan createChild( if (children.size() < scopes.getOptions().getMaxSpans()) { Objects.requireNonNull(parentSpanId, "parentSpanId is required"); Objects.requireNonNull(operation, "operation is required"); - cancelIdleTimer(); + + // When this transaction finishes, we want its idle spans to finish as well. We don't let idle + // spans cancel the idle timer b/c it would keep the transaction alive until its deadline. + if (!spanOptions.isIdle()) { + cancelIdleTimer(); + } + final Span span = new Span( this, @@ -762,10 +768,20 @@ private void updateBaggageValues(final @NotNull Baggage baggage) { return null; } + /** + * Returns true if no child span should keep this transaction from finishing. + * + *

Ignores idle spans. Including them would mean an idle transaction would never restart its + * idle timer once it had an unfinished idle span, causing the transaction to always live until + * its deadline. + */ private boolean hasAllChildrenFinished() { @NotNull final ListIterator iterator = this.children.listIterator(); while (iterator.hasNext()) { @NotNull final Span span = iterator.next(); + if (span.getOptions().isIdle()) { + continue; + } // This is used in the spanFinishCallback, when the span isn't finished, but has a finish // date if (!span.isFinished() && span.getFinishDate() == null) { diff --git a/sentry/src/main/java/io/sentry/SpanOptions.java b/sentry/src/main/java/io/sentry/SpanOptions.java index 69f93e00a9e..effe3449a53 100644 --- a/sentry/src/main/java/io/sentry/SpanOptions.java +++ b/sentry/src/main/java/io/sentry/SpanOptions.java @@ -48,8 +48,11 @@ public void setStartTimestamp(@Nullable SentryDate startTimestamp) { private boolean trimEnd = false; /** - * true if the span is considered idle and should be automatically finished when it's parent gets - * finished. + * `true` if the span is idle, in which case its transaction finishes it when the transaction + * finishes, with the transaction's status and end time. + * + *

Note: An unfinished idle span doesn't keep a transaction that waits for its children from + * finishing, but non-idle spans created under it do. */ private boolean isIdle = false; diff --git a/sentry/src/test/java/io/sentry/SentryTracerTest.kt b/sentry/src/test/java/io/sentry/SentryTracerTest.kt index 95f19344243..3b97519229e 100644 --- a/sentry/src/test/java/io/sentry/SentryTracerTest.kt +++ b/sentry/src/test/java/io/sentry/SentryTracerTest.kt @@ -1204,6 +1204,54 @@ class SentryTracerTest { assertNull(transaction.idleTimeoutFuture) } + @Test + fun `when idle transaction has only an unfinished idle span, finishes the transaction and the idle span after the idle timeout`() { + val transaction = fixture.getSut(waitForChildren = true, idleTimeout = 50) + + val idleSpan = transaction.startChild("ui.load", null, SpanOptions().apply { isIdle = true }) + + await.untilAsserted { + verify(fixture.scopes).captureTransaction(anyOrNull(), anyOrNull(), anyOrNull(), anyOrNull()) + } + assertThat(transaction.status).isEqualTo(SpanStatus.OK) + assertThat(idleSpan.isFinished).isTrue() + assertThat(idleSpan.status).isEqualTo(SpanStatus.OK) + } + + @Test + fun `when idle transaction has an idle span with a finished child, finishes the transaction after the idle timeout`() { + val transaction = fixture.getSut(waitForChildren = true, idleTimeout = 50) + val idleSpan = transaction.startChild("ui.load", null, SpanOptions().apply { isIdle = true }) + + idleSpan.startChild("ui.render").finish() + + await.untilAsserted { + verify(fixture.scopes).captureTransaction(anyOrNull(), anyOrNull(), anyOrNull(), anyOrNull()) + } + assertThat(transaction.status).isEqualTo(SpanStatus.OK) + } + + @Test + fun `when idle transaction has an unfinished span under an idle span, does not finish the transaction until that span finishes`() { + val transaction = fixture.getSut(waitForChildren = true, idleTimeout = 50) + val idleSpan = transaction.startChild("ui.load", null, SpanOptions().apply { isIdle = true }) + val spanUnderIdleSpan = idleSpan.startChild("ui.render") + + transaction.startChild("op").finish() + Thread.sleep(200) + + assertThat(transaction.isFinished).isFalse() + verify(fixture.scopes, never()) + .captureTransaction(anyOrNull(), anyOrNull(), anyOrNull(), anyOrNull()) + + spanUnderIdleSpan.finish() + + await.untilAsserted { + verify(fixture.scopes).captureTransaction(anyOrNull(), anyOrNull(), anyOrNull(), anyOrNull()) + } + assertThat(transaction.status).isEqualTo(SpanStatus.OK) + } + @Test fun `when trimEnd, trims idle transaction time to the latest child timestamp`() { val transaction =