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

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.
 

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