ensure timeouts work

Work around the AsyncProcess timeout not working correctly

tests/integration/testmanager.nim

@@ -40,7 +40,6 @@ type
     hardhatPortLock: AsyncLock
     hardhatProcessLock: AsyncLock
     testTimeout: Duration # individual test timeout
-    futContinuousUpdates: Future[void].Raising([])
 
   IntegrationTestConfig* = object
     startHardhat: bool
@@ -64,6 +63,7 @@ type
     output: ?!CommandExResponse
     testId: string    # when used in datadir path, prevents data dir clashes
     status: IntegrationTestStatus
+    command: string
 
   TestManagerError* = object of CatchableError
 
@@ -214,8 +214,8 @@ proc printOutputMarker(
 
 proc printResult(
   test: IntegrationTest,
-  printStdOut = false,
+  printStdOut = test.manager.debugCodexNodes,
-  printStdErr = false) =
+  printStdErr = test.manager.debugTestHarness) =
 
   case test.status:
   of IntegrationTestStatus.New:
@@ -249,6 +249,13 @@ proc printResult(
     test.printResult(fgRed)
 
   of IntegrationTestStatus.Timeout:
+    if printStdOut and
+       output =? test.output:
+      test.printOutputMarker(MarkerPosition.Start,
+                               "codex node output (stdout)")
+      echo output.stdOutput
+      test.printOutputMarker(MarkerPosition.Finish,
+                               "codex node output (stdout)")
     test.printResult(fgYellow)
 
   of IntegrationTestStatus.Ok:
@@ -325,54 +332,74 @@ proc buildCommand(
                               ", testFile: " & testFile &
                               ", error: " & parent.msg,
                               parent
+proc setup(
+  test: IntegrationTest): Future[?Hardhat] {.async: (raises: [CancelledError, TestManagerError]).} =
 
-proc runTest(
+  var hardhat = Hardhat.none
-  manager: TestManager,
+  var hardhatPort = int.none
-  config: IntegrationTestConfig) {.async: (raises: [CancelledError]).} =
+
+  if test.config.startHardhat:
+    let hh = await test.startHardhat()
+    hardhat = some hh
+    hardhatPort = some hh.port
+    test.manager.hardhats.add hh
+
+  test.command = await test.buildCommand(hardhatPort)
+
+  return hardhat
+
+proc teardown(
+  test: IntegrationTest,
+  hardhat: ?Hardhat) {.async: (raises: [CancelledError]).} =
+
+  if test.config.startHardhat and hardhat =? hardhat:
+    try:
+      trace "Stopping hardhat", name = test.config.name
+      await hardhat.process.stop()
+    except CatchableError as e:
+      warn "Failed to stop hardhat node, continuing",
+        error = e.msg, test = test.config.name
+
+    if test.manager.debugHardhat:
+      test.printOutputMarker(MarkerPosition.Start, "Hardhat stdout")
+      for line in hardhat.output:
+        echo line
+      test.printOutputMarker(MarkerPosition.Finish, "Hardhat stdout")
+
+    test.manager.hardhats.keepItIf( it != hardhat )
+
+proc start(test: IntegrationTest) {.async: (raises: []).} =
 
   logScope:
-    config
+    config = test.config
 
   trace "Running test"
 
-  var test = IntegrationTest(
-    manager: manager,
-    config: config,
-    testId: $ uint16.example
-  )
 
   test.timeStart = some Moment.now()
   test.status = IntegrationTestStatus.Running
-  manager.tests.add test
 
-  var hardhat: Hardhat
+  var hardhat = none Hardhat
-  var hardhatPort = int.none
+
-  var command: string
   try:
-    if config.startHardhat:
+
-      hardhat = await test.startHardhat()
+    try:
-      hardhatPort = hardhat.port.some
+      hardhat = await test.setup()
-      manager.hardhats.add hardhat
-    command = await test.buildCommand(hardhatPort)
     except TestManagerError as e:
       error "Failed to start hardhat and build command", error = e.msg
       test.timeEnd = some Moment.now()
       test.status = IntegrationTestStatus.Error
       test.output = CommandExResponse.failure(e)
-    test.printResult(printStdOut = manager.debugHardhat or manager.debugCodexNodes,
-                      printStdErr = manager.debugTestHarness)
       return
 
-
+    try:
-  trace "Starting parallel integration test", command
+      trace "Starting parallel integration test", command = test.command
       test.printStart()
       test.process = execCommandEx(
-    command = command,
+        command = test.command,
-    timeout = manager.testTimeout
+        timeout = test.manager.testTimeout
       )
 
-  try:
-
       let output = await test.process # waits on waitForExit
       test.output = success(output)
 
@@ -381,45 +408,26 @@ proc runTest(
       else:
         test.status = IntegrationTestStatus.Ok
 
-  except CancelledError as e:
-    raise e
-
     except AsyncProcessTimeoutError as e:
       test.timeEnd = some Moment.now()
-    error "Test timed out", name = config.name, duration = test.duration
+      error "Test timed out", name = test.config.name, duration = test.duration
       test.output = CommandExResponse.failure(e)
       test.status = IntegrationTestStatus.Timeout
-    test.printResult(printStdOut = manager.debugCodexNodes,
-                     printStdErr = manager.debugTestHarness)
 
     except AsyncProcessError as e:
       test.timeEnd = some Moment.now()
-    error "Test failed to complete", name = config.name, duration = test.duration
+      error "Test failed to complete", name = test.config.name, duration = test.duration
       test.output = CommandExResponse.failure(e)
       test.status = IntegrationTestStatus.Error
-    test.printResult(printStdOut = manager.debugCodexNodes,
-                     printStdErr = manager.debugTestHarness)
 
-  if config.startHardhat and not hardhat.isNil:
+    await test.teardown(hardhat)
-    try:
-      trace "Stopping hardhat", name = config.name
-      await hardhat.process.stop()
-    except CatchableError as e:
-      warn "Failed to stop hardhat node, continuing",
-        error = e.msg, test = test.config.name
 
-    if manager.debugHardhat:
+  except CancelledError:
-      test.printOutputMarker(MarkerPosition.Start, "Hardhat stdout")
+    discard # start is asyncSpawned, do not propagate
-      for line in hardhat.output:
-        echo line
-      test.printOutputMarker(MarkerPosition.Finish, "Hardhat stdout")
-
-    manager.hardhats.keepItIf( it != hardhat )
 
   test.timeEnd = some Moment.now()
-  info "Test completed", name = config.name, duration = test.duration
+  if test.status == IntegrationTestStatus.Ok:
-  test.printResult(printStdOut = manager.debugCodexNodes,
+    info "Test completed", name = test.config.name, duration = test.duration
-                  printStdErr = manager.debugTestHarness)
 
 proc continuallyShowUpdates(manager: TestManager) {.async: (raises: []).} =
   try:
@@ -436,15 +444,47 @@ proc continuallyShowUpdates(manager: TestManager) {.async: (raises: []).} =
           &"Integration tests status after {manager.duration}"
 
       for test in manager.tests:
-        test.printResult()
+        test.printResult(false, false)
+
+      if manager.tests.len > 0:
+        echo ""
 
       await sleepAsync(sleepDuration)
 
   except CancelledError as e:
     discard
 
+proc untilTimeout(fut: Future[void], timeout: Duration): Future[bool] {.async: (raises: [CancelledError]).} =
+  # workaround for withTimeout, which did not work correctly
+  try:
+    let timer = sleepAsync(timeout)
+    return (await race(fut, timer)) == fut
+  except ValueError:
+    discard
+
+proc run(test: IntegrationTest) {.async: (raises: []).} =
+  try:
+    let futStart = test.start()
+    let completedBeforeTimeout = await futStart.untilTimeout(test.manager.testTimeout)
+    if not completedBeforeTimeout:
+      test.timeEnd = some Moment.now()
+      error "Test timed out", name = test.config.name, duration = test.duration
+      let e = newException(AsyncProcessTimeoutError,
+        "Test did not complete before elapsed timeout")
+      test.output = CommandExResponse.failure(e)
+      test.status = IntegrationTestStatus.Timeout
+
+      if not futStart.finished:
+        await futStart.cancelAndWait()
+
+    test.printResult()
+
+
+  except CancelledError:
+    discard # do not propagate due to asyncSpawn
+
 proc runTests(manager: TestManager) {.async: (raises: [CancelledError]).} =
-  var testFutures: seq[Future[void].Raising([CancelledError])]
+  var testFutures: seq[Future[void]]
 
   manager.timeStart = some Moment.now()
 
@@ -452,7 +492,17 @@ proc runTests(manager: TestManager) {.async: (raises: [CancelledError]).} =
              "\n[Integration Test Manager] Starting parallel integration tests"
 
   for config in manager.configs:
-    testFutures.add manager.runTest(config)
+
+    var test = IntegrationTest(
+      manager: manager,
+      config: config,
+      testId: $ uint16.example
+    )
+    manager.tests.add test
+
+    let futRun = test.run()
+    testFutures.add futRun
+    asyncSpawn futRun
 
   await allFutures testFutures
 
@@ -476,10 +526,22 @@ proc withBorder(
 proc printResult(manager: TestManager) {.raises: [TestManagerError].}=
   var successes = 0
   var totalDurationSerial: Duration
+  let showSummary = manager.debugCodexNodes or manager.debugHardhat or manager.debugTestHarness
+
+  if showSummary:
+    echo ""
+    echoStyled styleBright, styleUnderscore, bgWhite, fgBlack,
+      &"INTEGRATION TESTS RESULT"
+
   for test in manager.tests:
     totalDurationSerial += test.duration
     if test.status == IntegrationTestStatus.Ok:
       inc successes
+    # because debug output can really make things hard to read, show a nice
+    # summary of test results
+    if showSummary:
+      test.printResult(false, false)
+
   # estimated time saved as serial execution with a single hardhat instance
   # incurs less overhead
   let relativeTimeSaved = ((totalDurationSerial - manager.duration).nanos * 100) div
@@ -489,6 +551,7 @@ proc printResult(manager: TestManager) {.raises: [TestManagerError].}=
                      else:
                        fgGreen
 
+
   echo "\n▢=====================================================================▢"
   echoStyled "| ", styleBright, styleUnderscore, "INTEGRATION TEST SUMMARY", resetStyle, "".withBorder(Align.Right, 43, {Border.Right})
   echo "".withBorder()
@@ -498,9 +561,12 @@ proc printResult(manager: TestManager) {.raises: [TestManagerError].}=
   echo "▢=====================================================================▢"
 
 proc start*(manager: TestManager) {.async: (raises: [CancelledError, TestManagerError]).} =
-  manager.futContinuousUpdates = manager.continuallyShowUpdates()
+  let futContinuousUpdates = manager.continuallyShowUpdates()
-  asyncSpawn manager.futContinuousUpdates
+  asyncSpawn futContinuousUpdates
+
   await manager.runTests()
+  await futContinuousUpdates.cancelAndWait()
+
   manager.printResult()
 
 proc stop*(manager: TestManager) {.async: (raises: [CancelledError]).} =
@@ -513,5 +579,3 @@ proc stop*(manager: TestManager) {.async: (raises: [CancelledError]).} =
       await hardhat.process.stop()
     except CatchableError as e:
       trace "failed to stop hardhat node", error = e.msg
-
-  await manager.futContinuousUpdates.cancelAndWait()