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 =