Tests failing with timeout in ScalaTest not reported to DataDog

[mwisnicki]

Tracer Version(s)

1.46.1~8e0205904b

Java Version(s)

11.0.26

JVM Vendor

Amazon Corretto

Bug Report

My Scala + Slick + ScalaTest tests are timing out due to connection timeout and none of this is captured by DataDog.

Other tests and typical failures work fine.

I'm using github action to integrate with DD:

    - name: Configure Datadog Test Optimization
      if: ${{ inputs.upload-to-datadog == 'true' }}
      uses: datadog/test-visibility-github-action@v2
      with:
        languages: java
        api_key: ${{ inputs.datadog-api-key }}
        service: ${{ env.DD_SERVICE }}

Here's a stack reported after each failed test:

stack reported after each failed test

Reporter completed abruptly with an exception after receiving event: TestFailed(Ordinal(0, 381),redshift - Connection is not available, request timed out after 30000ms.,MapperSpec,com.evenfinancial.slick.mapper.MapperSpec,Some(com.evenfinancial.slick.mapper.MapperSpec),Redshift when Instant when Database NOW(),Database NOW(),Vector(),Vector(),Some(java.sql.SQLTransientConnectionException: redshift - Connection is not available, request timed out after 30000ms.),Some(30001),Some(IndentedText(  - when Database NOW(),when Database NOW(),2)),Some(SeeStackDepthException),Some(com.evenfinancial.slick.mapper.MapperSpec),None,pool-9-thread-13-ScalaTest-running-MapperSpec,1740166061118).
java.lang.IllegalStateException: No active scope present, it is possible that end() was called multiple times
	at datadog.trace.civisibility.domain.TestImpl.end(TestImpl.java:225)
	at datadog.trace.civisibility.events.TestEventsHandlerImpl.onTestFinish(TestEventsHandlerImpl.java:236)
	at datadog.trace.instrumentation.scalatest.DatadogReporter.onTestFailure(DatadogReporter.java:192)
	at datadog.trace.instrumentation.scalatest.DatadogReporter.handle(DatadogReporter.java:64)
	at org.scalatest.DispatchReporter.apply(DispatchReporter.scala:300)
	at org.scalatest.tools.SuiteSortingReporter.handleTestEvents(SuiteSortingReporter.scala:161)
	at org.scalatest.tools.SuiteSortingReporter.doApply(SuiteSortingReporter.scala:80)
	at org.scalatest.CatchReporter.apply(CatchReporter.scala:36)
	at org.scalatest.CatchReporter.apply$(CatchReporter.scala:34)
	at org.scalatest.tools.SuiteSortingReporter.apply(SuiteSortingReporter.scala:26)
	at org.scalatest.tools.Framework$SbtReporter.apply(Framework.scala:1165)
	at org.scalatest.WrapperCatchReporter.doApply(CatchReporter.scala:70)
	at org.scalatest.CatchReporter.apply(CatchReporter.scala:36)
	at org.scalatest.CatchReporter.apply$(CatchReporter.scala:34)
	at org.scalatest.WrapperCatchReporter.apply(CatchReporter.scala:63)
	at org.scalatest.tools.TestSortingReporter.handleTestCompleted(TestSortingReporter.scala:208)
	at org.scalatest.tools.TestSortingReporter.doApply(TestSortingReporter.scala:155)
	at org.scalatest.CatchReporter.apply(CatchReporter.scala:36)
	at org.scalatest.CatchReporter.apply$(CatchReporter.scala:34)
	at org.scalatest.tools.TestSortingReporter.apply(TestSortingReporter.scala:28)
	at org.scalatest.Suite$.reportTestFailed(Suite.scala:1635)
	at org.scalatest.AsyncSuperEngine.$anonfun$runTestImpl$6(AsyncEngine.scala:321)
	at org.scalatest.AsyncSuperEngine.$anonfun$runTestImpl$6$adapted(AsyncEngine.scala:294)
	at org.scalatest.FutureAsyncOutcome.$anonfun$new$1(AsyncOutcome.scala:40)
	at org.scalatest.FutureAsyncOutcome.$anonfun$new$1$adapted(AsyncOutcome.scala:39)
	at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:64)
	at org.scalatest.concurrent.SerialExecutionContext.recRunNow(SerialExecutionContext.scala:120)
	at org.scalatest.concurrent.SerialExecutionContext.runNow(SerialExecutionContext.scala:111)
	at org.scalatest.AsyncSuperEngine.runTestImpl(AsyncEngine.scala:377)
	at org.scalatest.wordspec.AsyncWordSpecLike.runTest(AsyncWordSpecLike.scala:1073)
	at org.scalatest.wordspec.AsyncWordSpecLike.runTest$(AsyncWordSpecLike.scala:1053)
	at org.scalatest.wordspec.AsyncWordSpec.runTest(AsyncWordSpec.scala:2296)
	at org.scalatest.wordspec.AsyncWordSpecLike.$anonfun$runTests$1(AsyncWordSpecLike.scala:1132)
	at org.scalatest.AsyncSuperEngine.$anonfun$runTestsInBranch$3(AsyncEngine.scala:435)
	at org.scalatest.Status.$anonfun$thenRun$1(Status.scala:227)
	at org.scalatest.Status.$anonfun$thenRun$1$adapted(Status.scala:225)
	at org.scalatest.ScalaTestStatefulStatus.whenCompleted(Status.scala:648)
	at org.scalatest.Status.thenRun(Status.scala:225)
	at org.scalatest.Status.thenRun$(Status.scala:220)
	at org.scalatest.ScalaTestStatefulStatus.thenRun(Status.scala:511)
	at org.scalatest.AsyncSuperEngine.$anonfun$runTestsInBranch$1(AsyncEngine.scala:435)
	at scala.collection.LinearSeqOptimized.foldLeft(LinearSeqOptimized.scala:126)
	at scala.collection.LinearSeqOptimized.foldLeft$(LinearSeqOptimized.scala:122)
	at scala.collection.immutable.List.foldLeft(List.scala:91)
	at org.scalatest.AsyncSuperEngine.traverseSubNodes$1(AsyncEngine.scala:406)
	at org.scalatest.AsyncSuperEngine.runTestsInBranch(AsyncEngine.scala:479)
	at org.scalatest.AsyncSuperEngine.$anonfun$runTestsInBranch$4(AsyncEngine.scala:463)
	at org.scalatest.Status.$anonfun$thenRun$1(Status.scala:227)
	at org.scalatest.Status.$anonfun$thenRun$1$adapted(Status.scala:225)
	at org.scalatest.ScalaTestStatefulStatus.whenCompleted(Status.scala:648)
	at org.scalatest.Status.thenRun(Status.scala:225)
	at org.scalatest.Status.thenRun$(Status.scala:220)
	at org.scalatest.ScalaTestStatefulStatus.thenRun(Status.scala:511)
	at org.scalatest.AsyncSuperEngine.$anonfun$runTestsInBranch$1(AsyncEngine.scala:463)
	at scala.collection.LinearSeqOptimized.foldLeft(LinearSeqOptimized.scala:126)
	at scala.collection.LinearSeqOptimized.foldLeft$(LinearSeqOptimized.scala:122)
	at scala.collection.immutable.List.foldLeft(List.scala:91)
	at org.scalatest.AsyncSuperEngine.traverseSubNodes$1(AsyncEngine.scala:406)
	at org.scalatest.AsyncSuperEngine.runTestsInBranch(AsyncEngine.scala:479)
	at org.scalatest.AsyncSuperEngine.$anonfun$runTestsInBranch$4(AsyncEngine.scala:463)
	at org.scalatest.Status.$anonfun$thenRun$1(Status.scala:227)
	at org.scalatest.Status.$anonfun$thenRun$1$adapted(Status.scala:225)
	at org.scalatest.ScalaTestStatefulStatus.whenCompleted(Status.scala:648)
	at org.scalatest.Status.thenRun(Status.scala:225)
	at org.scalatest.Status.thenRun$(Status.scala:220)
	at org.scalatest.ScalaTestStatefulStatus.thenRun(Status.scala:511)
	at org.scalatest.AsyncSuperEngine.$anonfun$runTestsInBranch$1(AsyncEngine.scala:463)
	at scala.collection.LinearSeqOptimized.foldLeft(LinearSeqOptimized.scala:126)
	at scala.collection.LinearSeqOptimized.foldLeft$(LinearSeqOptimized.scala:122)
	at scala.collection.immutable.List.foldLeft(List.scala:91)
	at org.scalatest.AsyncSuperEngine.traverseSubNodes$1(AsyncEngine.scala:406)
	at org.scalatest.AsyncSuperEngine.runTestsInBranch(AsyncEngine.scala:487)
	at org.scalatest.AsyncSuperEngine.runTestsImpl(AsyncEngine.scala:555)
	at org.scalatest.wordspec.AsyncWordSpecLike.runTests(AsyncWordSpecLike.scala:1132)
	at org.scalatest.wordspec.AsyncWordSpecLike.runTests$(AsyncWordSpecLike.scala:1131)
	at org.scalatest.wordspec.AsyncWordSpec.runTests(AsyncWordSpec.scala:2296)
	at org.scalatest.Suite.run(Suite.scala:1112)
	at org.scalatest.Suite.run$(Suite.scala:1094)
	at org.scalatest.wordspec.AsyncWordSpec.org$scalatest$wordspec$AsyncWordSpecLike$$super$run(AsyncWordSpec.scala:2296)
	at org.scalatest.wordspec.AsyncWordSpecLike.$anonfun$run$1(AsyncWordSpecLike.scala:1177)
	at org.scalatest.AsyncSuperEngine.runImpl(AsyncEngine.scala:625)
	at org.scalatest.wordspec.AsyncWordSpecLike.run(AsyncWordSpecLike.scala:1177)
	at org.scalatest.wordspec.AsyncWordSpecLike.run$(AsyncWordSpecLike.scala:1175)
	at org.scalatest.wordspec.AsyncWordSpec.run(AsyncWordSpec.scala:2296)
	at org.scalatest.tools.Framework.org$scalatest$tools$Framework$$runSuite(Framework.scala:318)
	at org.scalatest.tools.Framework$ScalaTestTask.execute(Framework.scala:513)
	at sbt.TestRunner.runTest$1(TestFramework.scala:140)
	at sbt.TestRunner.run(TestFramework.scala:155)
	at sbt.TestFramework$$anon$3$$anonfun$$lessinit$greater$1.$anonfun$apply$1(TestFramework.scala:318)
	at sbt.TestFramework$.sbt$TestFramework$$withContextLoader(TestFramework.scala:278)
	at sbt.TestFramework$$anon$3$$anonfun$$lessinit$greater$1.apply(TestFramework.scala:318)
	at sbt.TestFramework$$anon$3$$anonfun$$lessinit$greater$1.apply(TestFramework.scala:318)
	at sbt.TestFunction.apply(TestFramework.scala:330)
	at sbt.Tests$.processRunnable$1(Tests.scala:474)
	at sbt.Tests$.$anonfun$makeSerial$1(Tests.scala:480)
	at sbt.std.Transform$$anon$3.$anonfun$apply$2(Transform.scala:46)
	at sbt.std.Transform$$anon$4.work(Transform.scala:68)
	at sbt.Execute.$anonfun$submit$2(Execute.scala:282)
	at sbt.internal.util.ErrorHandling$.wideConvert(ErrorHandling.scala:23)
	at sbt.Execute.work(Execute.scala:291)
	at sbt.Execute.$anonfun$submit$1(Execute.scala:282)
	at sbt.ConcurrentRestrictions$$anon$4.$anonfun$submitValid$1(ConcurrentRestrictions.scala:265)
	at sbt.CompletionService$$anon$2.call(CompletionService.scala:64)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)

Expected Behavior

All test failures are uploaded

Reproduction Code

WIP. Trying to minimize the problem.

Details

import com.github.tminglei.slickpg.ExPostgresProfile
import com.typesafe.config.ConfigFactory
import org.scalatest.matchers.must.Matchers._
import org.scalatest.wordspec.AsyncWordSpec
import slick.basic.DatabaseConfig

import scala.concurrent.Future

class MapperSpec extends AsyncWordSpec {
  import ExPostgresProfile.api._

  class Tests(dbConfig: DatabaseConfig[ExPostgresProfile]) {
    def runDb[R](dbio: DBIO[R]): Future[R] = dbConfig.db.run(dbio)

    "UUID" in {
      runDb(sql"SELECT 1".as[Int].head).map(_ mustEqual 1)
    }
  }

  "Redshift" when (buildRedshift() match {
    case Some(dbConfig) => new Tests(dbConfig): Unit
    case _ => "no connection" ignore fail
  })

  def buildRedshift() = sys.env.get("REDSHIFT_TEST_PASSWORD") map { _ =>
    DatabaseConfig.forConfig[ExPostgresProfile](
      "redshiftConfig",
      ConfigFactory
        .parseString("""
                       |redshiftConfig {
                       |  profile = "com.github.tminglei.slickpg.ExPostgresProfile$"
                       |  db {
                       |    url = "jdbc:redshift://REPLACE_WITH_VALID/foo"
                       |    user = ${REDSHIFT_TEST_USER}
                       |    password = ${REDSHIFT_TEST_PASSWORD}
                       |    driver = com.amazon.redshift.jdbc.Driver
                       |    numThreads = 10
                       |    maxConnections = 10
                       |    keepAliveConnection = false
                       |    poolName = "redshift"
                       |  }
                       |}
                       |""".stripMargin)
        .resolveWith(ConfigFactory.systemEnvironment()),
    )
  }
}

[nikita-tkachenko-datadog]

Hi @mwisnicki, thank you for reporting this! The reproducer you provided helped a lot in identifying the problem. The fix will be included in the upcoming DD Java tracer release scheduled for March, 3rd

[github-actions]

🤖 This issue has been addressed in the latest release. Check full details in the Release Notes.