fix(tracing): Stop idle spans from keeping idle transactions alive until their deadline (JAVA-795)

An idle span (SpanOptions.isIdle) is meant to be finished by its parent transaction when the transaction finishes. Before this commit, SentryTracer treated an unfinished idle span as blocking. Creating one canceled the idle timer; SentryTracer.hasAllChildrenFinished() counted it as unfinished; and the timer never restarted. As a consequence, any idle transaction that i) waited for its children (i.e., all Android idle transactions, including ui.load and nav transactions) and ii) had an unfinished idle span was kept alive until its deadline (30 s by default), causing it to be reported as DEADLINE_EXCEEDED even though in most cases no actual work was keeping the transaction alive.

**Current producers of idle spans**

SentryTraced is the SDK's only producer of idle spans, so the effects mentioned above are limited to idle transactions that, prior to this commit, contain a span from SentryTraced. (The issue has been with SentryTraced from the beginning – see #2507).

Author: 0xadam-brown

CHANGELOG.md

@@ -4,6 +4,7 @@
 
 ### Fixes
 
+- `SentryTraced` now lets any idle parent transaction finish after the idle timeout rather than waiting for the deadline and reporting `DEADLINE_EXCEEDED` ([#XXXX](https://github.com/getsentry/sentry-java/pull/XXXX)).
 - 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.
 

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,17 +483,24 @@ class SentryTracedTest {
         },
         true,
       )
-      tx = startBoundTransaction(name)
+      tx = startBoundTransaction(name, configureTransactionOptions)
       var boundTransaction: ITransaction? = null
       Sentry.configureScope { boundTransaction = it.transaction }
       assertThat(boundTransaction).isSameInstanceAs(tx)
     }
     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
   }

sentry/src/main/java/io/sentry/SentryTracer.java

@@ -469,7 +469,11 @@ private ISpan createChild(
     if (children.size() < scopes.getOptions().getMaxSpans()) {
       Objects.requireNonNull(parentSpanId, "parentSpanId is required");
       Objects.requireNonNull(operation, "operation is required");
-      cancelIdleTimer();
+      // An idle span doesn't keep this transaction from finishing (see hasAllChildrenFinished), so
+      // creating one leaves the idle timer running.
+      if (!spanOptions.isIdle()) {
+        cancelIdleTimer();
+      }
       final Span span =
           new Span(
               this,
@@ -762,10 +766,20 @@ private void updateBaggageValues(final @NotNull Baggage baggage) {
     return null;
   }
 
+  /**
+   * Returns true if no child span should keep this transaction from finishing.
+   *
+   * <p>Idle spans don't count (but spans created under them do). Including idle spans 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<Span> 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) {

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.
+   *
+   * <p>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;
 

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 =