Document timeout behavior

[mbovel]

What does munitTimeout do exactly?

I would have expected it to stop a test if it runs for too long, but that's not the case, for example with infinite loops:

//> using scala 3.3.1
//> using test.dep org.scalameta::munit:1.0.0-M10

import scala.concurrent.Future
import scala.concurrent.duration.Duration
import scala.concurrent.ExecutionContext.Implicits.global

class TimeoutSuite extends munit.FunSuite:
  override val munitTimeout = Duration(1, "s")

  test("timeout async"):
    Future:
      while true do
        Thread.sleep(1000)
        println("Async tick")
  
  test("timeout sync"):
    while true do
      Thread.sleep(1000)
      println("Sync tick")

[mbovel]

See also #292.

[mbovel]

Note, this timeouts as expected:

//> using scala 3.3.1

import scala.concurrent.{Await, Future}
import scala.concurrent.duration.Duration
import scala.concurrent.ExecutionContext.Implicits.global

@main def main =
  def future =
    Future:
      while true do
        Thread.sleep(1000)
        println("tick")

  Await.result(future, Duration(2, "s"))

So this doesn't seem to be a limitation of Futures.

[samuelchassot]

My observation is that if the program terminates, an error is thrown if the duration exceeds the timeout (but it does not kill the test):

class MySuite extends munit.FunSuite {
  override def munitTimeout = Duration(2, "s")
  val l = (1 to 10000).map(_ => Random.nextDouble() * 1000000).toList
  test("while with flag"):
    var res = 0.0
    var flag = true
    var i = 0 
    while flag do
      val x = l.map(x => x * x * 2).sum
      res += x
      i += 1
      flag &= i < 1000000
    res = 1.0
    assertEquals(res, 1.0)
}

results in:

MySuite:
==> X MySuite.while with flag  126.834s java.util.concurrent.TimeoutException: test timed out after 2 seconds
[error] Failed: Total 1, Failed 1, Errors 0, Passed 0
[error] Failed tests:
[error] 	MySuite
[error] (Test / test) sbt.TestsFailedException: Tests unsuccessful

However, this test never terminates and so the test suite also loops forever:

class MySuite extends munit.FunSuite {
  override def munitTimeout = Duration(2, "s")
  val l = (1 to 10000).map(_ => Random.nextDouble() * 1000000).toList
  test("while true"):
    var res= 0.0
    while true do
      val x = l.map(x => x * x * 2).sum
      res += x
    res = 1.0
    assertEquals(res, 1.0)
}

[mbovel]

The default execution context is the parasitic one:

munit/munit/shared/src/main/scala/munit/Suite.scala

Line 31 in 0d20dbc

def munitExecutionContext: ExecutionContext = parasiticExecutionContext

which is used when wrapping a sync test in a Future:

munit/munit/shared/src/main/scala/munit/ValueTransforms.scala

Lines 22 to 39 in 0d20dbc

	final def munitValueTransform(testValue: => Any): Future[Any] = {
	// Takes an arbitrarily nested future `Future[Future[Future[...]]]` and
	// returns a `Future[T]` where `T` is not a `Future`.
	def flattenFuture(future: Future[_]): Future[_] = {
	val nested: Future[Future[Any]] = future.map { value =>
	val transformed = munitValueTransforms.iterator
	.map(fn => fn(value))
	.collectFirst { case Some(future) => future }
	transformed match {
	case Some(f) => flattenFuture(f)
	case None => Future.successful(value)
	}
	}(munitExecutionContext)
	nested.flattenCompat(munitExecutionContext)
	}
	val wrappedFuture = Future.fromTry(Try(StackTraces.dropOutside(testValue)))
	flattenFuture(wrappedFuture)
	}

Apparently, blocking the main thread prevents the timeouts from being triggered.

Not sure why, as waitAtMost uses a scheduler that should run its runnables in a separate thread:

The timeout task is scheduled on a separate thread (using sh). This allows the timeout task to be executed at some point, however the main thread stays stuck executing the test body and cannot proceed to report the timeout or execute other tests.

munit/munit/jvm/src/main/scala/munit/internal/PlatformCompat.scala

Lines 53 to 66 in 0d20dbc

	def waitAtMost[T](
	startFuture: () => Future[T],
	duration: Duration,
	ec: ExecutionContext
	): Future[T] = {
	val onComplete = Promise[T]()
	val timeout = sh.schedule[Unit](
	() =>
	onComplete.tryFailure(
	new TimeoutException(s"test timed out after $duration")
	),
	duration.toMillis,
	TimeUnit.MILLISECONDS
	)

munit/munit/jvm/src/main/scala/munit/internal/PlatformCompat.scala

Lines 22 to 32 in 0d20dbc

	private val sh = Executors.newSingleThreadScheduledExecutor(
	new ThreadFactory {
	val counter = new AtomicInteger
	def threadNumber() = counter.incrementAndGet()
	def newThread(r: Runnable) =
	new Thread(r, s"munit-scheduler-${threadNumber()}") {
	setDaemon(true)
	setPriority(Thread.NORM_PRIORITY)
	}
	}
	)

[mbovel]

Using the global execution context as munitExecutionContext seems to result in the expected behavior.

//> using scala 3.3.1
//> using test.dep org.scalameta::munit:1.0.0-M10

import scala.concurrent.{ExecutionContext, Future}
import scala.concurrent.duration.Duration

class TimeoutSuite extends munit.FunSuite:
  override val munitTimeout = Duration(1, "s")
  override def munitExecutionContext: ExecutionContext = ExecutionContext.global
  given ExecutionContext = ExecutionContext.global

  test("timeout async"):
    Future:
      while true do
        Thread.sleep(1000)
        println("Async tick")

  test("timeout sync"):
    while true do
      Thread.sleep(1000)
      println("Sync tick")

➜  ~/munit-timeout scala-cli test .
Compiling project (test, Scala 3.3.1, JVM)
Compiled project (test, Scala 3.3.1, JVM)
Async tick
Async tick
Sync tick
TimeoutSuite:
==> X TimeoutSuite.timeout async  1.009s java.util.concurrent.TimeoutException: test timed out after 1 second
==> X TimeoutSuite.timeout sync  1.002s java.util.concurrent.TimeoutException: test timed out after 1 second

[samuelchassot]

Could you try with a long computation instead of Tread.sleep?

[mbovel]

@samuelchassot I observe the same behavior with an infinite loop, and without Thread.sleep:

//> using scala 3.3.1
//> using test.dep org.scalameta::munit:1.0.0-M10

import scala.concurrent.{ExecutionContext, Future}
import scala.concurrent.duration.Duration

class TimeoutSuite extends munit.FunSuite:
  override val munitTimeout = Duration(1, "s")
  override def munitExecutionContext: ExecutionContext = ExecutionContext.global
  given ExecutionContext = ExecutionContext.global

  test("timeout async")(Future(while true do ()))
  test("timeout sync")(while true do ())

➜  ~/munit-timeout scala-cli test .
Compiling project (test, Scala 3.3.1, JVM)
Compiled project (test, Scala 3.3.1, JVM)
TimeoutSuite:
==> X TimeoutSuite.timeout async  1.008s java.util.concurrent.TimeoutException: test timed out after 1 second
==> X TimeoutSuite.timeout sync  1.002s java.util.concurrent.TimeoutException: test timed out after 1 second

[mbovel]

Well, the timeout test suite does use the global execution context as munitExecutionContext as well, so it seems this is needed for timeouts of sync test to work.

munit/tests/jvm/src/test/scala/munit/TimeoutSuite.scala

Line 11 in 0d20dbc

override def munitExecutionContext: ExecutionContext = global

[mbovel]

Here is a somewhat minimal reproduction:

//> using scala 3.3.1

package waitAtMost

import scala.concurrent.{Await, ExecutionContext, Future, Promise}
import scala.concurrent.duration.Duration
import java.util.concurrent.{
  Executors,
  ScheduledThreadPoolExecutor,
  ThreadFactory,
  TimeUnit,
  TimeoutException
}
import java.util.concurrent.atomic.AtomicInteger

val sh = Executors.newSingleThreadScheduledExecutor(
  new ThreadFactory {
    val counter = new AtomicInteger
    def threadNumber() = counter.incrementAndGet()
    def newThread(r: Runnable) =
      new Thread(r, s"munit-scheduler-${threadNumber()}") {
        setDaemon(true)
        setPriority(Thread.NORM_PRIORITY)
      }
  }
)

def waitAtMost[T](
    startFuture: () => Future[T],
    duration: Duration,
    ec: ExecutionContext
): Future[T] = {
  val onComplete = Promise[T]()
  val timeout = sh.schedule[Unit](
    () =>
      println("TIMEOUT")
      onComplete.tryFailure(
        new TimeoutException(s"test timed out after $duration")
      ),
    duration.toMillis,
    TimeUnit.MILLISECONDS
  )
  ec.execute(new Runnable {
    def run(): Unit = {
      startFuture().onComplete { result =>
        onComplete.tryComplete(result)
        timeout.cancel(false)
      }(ec)
    }
  })
  onComplete.future
}

@main def main =
  //import scala.concurrent.ExecutionContext.Implicits.global
  given ExecutionContext = ExecutionContext.parasitic
  def makeFuture() =
    Future:
      while true do
        Thread.sleep(1000)
        println("tick")

  val withTimeout = waitAtMost(makeFuture, Duration(2, "s"), ExecutionContext.parasitic)
  withTimeout.onComplete(_ => println("DONE"))
  Thread.sleep(5000)

➜  ~/munit-timeout scala-cli run waitAtMost.scala
Compiling project (Scala 3.3.1, JVM)
Compiled project (Scala 3.3.1, JVM)
tick
TIMEOUT
tick
tick
tick
tick
tick
tick
tick
tick
tick
tick
^C

whereas commenting given ExecutionContext = ExecutionContext.parasitic and uncommenting the previous line yields:

➜  ~/munit-timeout scala-cli run waitAtMost.scala
Compiling project (Scala 3.3.1, JVM)
Compiled project (Scala 3.3.1, JVM)
tick
TIMEOUT
DONE
tick
tick
tick

So, if the main thread is blocked, which is the case if the future runs in the parasitic context, there is no hope to go on with any other task or to exit properly.

However, if it runs in a separate thread, as it is the case when it runs in the global context, the main thread can report that it timed out (but not stop it!) and go on to schedule other tests. This is better but still suboptimal: the future is not stopped and if many tests loop forever, there will be threads starvation.

Ideally, we would like to force kill a thread after some time, but this is generally not possible on the JVM.

[mbovel]

It seems to me that we should:

1. Either:
   • Call waitAtMost with an execution context that will execute tasks on a separate thread, not munitExecutionContext as it's the case now:
     

     munit/munit/shared/src/main/scala/munit/FunSuite.scala

     Lines 50 to 51 in 0d20dbc

     	private final def waitForCompletion[T](f: () => Future[T]) =
     	PlatformCompat.waitAtMost(f, munitTimeout, munitExecutionContext)

   • Or document that timeouts on sync tests only make sense when overriding munitExecutionContext.
2. Either:

   • Exit the test runner the first time a timeout is encountered (and ignore all following tests). Maybe that would be the only sane behavior given JVM's inability to cancel computations.

   • Or document that timeouts do not cancel Futures, but only "race them with a timer". Demo:

     //> using scala 3.3.1
     //> using test.dep org.scalameta::munit:1.0.0-M10
     
     import scala.concurrent.{ExecutionContext, Future}
     import scala.concurrent.duration.Duration
     class TimeoutSuite extends munit.FunSuite:
     given ExecutionContext = ExecutionContext.global
     override val munitTimeout = Duration(3, "s")
     test("timeout async 1")(Future(while true do {Thread.sleep(1000); println("hello 1")}))
     test("timeout async 2")(Future(while true do {Thread.sleep(1000); println("hello 2")}))

     Here, both tests continue running after they time out. Test 1 runs for 6 seconds, while one could expect it to be killed after the timeout of 3 seconds. Output:

     hello 1
     hello 1
     hello 1
     hello 2
     hello 1
     hello 2
     hello 1
     TimeoutSuite:
     ==> X TimeoutSuite.timeout async 1  3.013s java.util.concurrent.TimeoutException: test timed out after 3 seconds
     ==> X TimeoutSuite.timeout async 2  3.001s java.util.concurrent.TimeoutException: test timed out after 3 seconds
     hello 2
     

     Graphically:

     

[mbovel]

Note, about supporting several test timeouts: while a thread can't be killed in Java, one could imagine a different testing framework architecture where tests would be run in a separate process. That would be quite a heavy change though, probably not worth it.

Proof of concept

package testServer

import scala.sys.process.ProcessLogger
import scala.collection.mutable.ArrayBuffer

import java.time.Duration
import java.util.concurrent.{Callable, Executors, TimeUnit}

import TestFramework.test

def mySuite() =
  test("1 + 1 == 2"):
    assert(1 + 1 == 2)

  test("infinite loop"):
    while true do
      println("looping")
      Thread.sleep(1000)

  test("2 + 1 == 2"):
    assert(2 + 1 == 2)

  test("infinite loop 2"):
    while true do
      println("looping 2")
      Thread.sleep(1000)

object TestFramework:
  case class Test(name: String, body: () => Unit)
  val tests = ArrayBuffer[Test]()

  enum TestStatus:
    case Success, Failure, Timeout

  case class TestResult(name: String, status: TestStatus)

  def test(name: String)(body: => Unit) =
    tests += Test(name, () => body)

  def main(args: Array[String]): Unit =
    mySuite() // should be called automatically upon definition

    args match
      case Array()                     => runAll()
      case Array("runFrom", fromIndex) => runFrom(fromIndex.toInt)
      case _                           => println("usage: testServer [runFrom fromIndex]")

  def runAll(previousResults: IArray[TestResult] = IArray.empty): Unit =
    val results = previousResults ++ spawnRunFrom(previousResults.length)
    if results.size == tests.size then
      println("all tests ran")
    else
      runAll(results)

  def spawnRunFrom(fromIndex: Int): IArray[TestResult] =
    println(s"fork to run from $fromIndex")
    val process = scala.sys.process.Process(
      List(
        "java",
        "-cp",
        System.getProperty("java.class.path"),
        "testServer.TestFramework",
        "runFrom",
        fromIndex.toString()
      )
    )

    val results = ArrayBuffer[TestResult]()

    val logger = ProcessLogger(line =>
      println(line)
      line match
        // better serialization needed, JSON or something
        case s"success: $name" => results += TestResult(name, TestStatus.Success)
        case s"failure: $name" => results += TestResult(name, TestStatus.Failure)
        case s"timeout: $name" => results += TestResult(name, TestStatus.Timeout)
        case _                 => ()
    )

    process.run(logger).exitValue()
    IArray.from(results)

  def runFrom(fromIndex: Int) =
    val timeout = Duration.ofSeconds(2) // should be configurable
    val executor = Executors.newScheduledThreadPool(1)
    for Test(name, body) <- tests.drop(fromIndex) do
      val timeoutFuture = executor.schedule(
        new Runnable:
          override def run() =
            println(s"timeout: $name")
            System.exit(1)
        ,
        2,
        TimeUnit.SECONDS
      )
      try
        body()
        println(s"success: $name")
        timeoutFuture.cancel(false)
      catch
        case e: Throwable =>
          println(s"failure: $name")
          timeoutFuture.cancel(false)

Note: the problem with such an architecture is that the tests initialization is re-run every time the worker is re-spawned.