enable more logging to file

- test harness chronicles logs to log file
- test process stdout and stderr to log file for each integration test file

Note: does not work when DEBUG=1 is not present in make command

build.nims

@@ -54,7 +54,8 @@ task testIntegration, "Run integration tests":
   var testParams = ""
   for i in 2 ..< paramCount():
     if "DebugTestHarness" in paramStr(i) and truthy paramStr(i).split('=')[1]:
-      testParams = "-d:chronicles_log_level=TRACE -d:chronicles_sinks=textlines[stdout]"
+      testParams =
+        "-d:chronicles_log_level=TRACE -d:chronicles_sinks=textlines[dynamic],json[dynamic],textlines[dynamic]"
       break
   test "testIntegration", params = testParams
   # use params to enable logging from the integration test executable

tests/integration/hardhatprocess.nim

@@ -77,8 +77,7 @@ method start*(
 
   let poptions = node.processOptions + {AsyncProcessOption.StdErrToStdOut}
   let args = @["node", "--export", "deployment-localhost.json"].concat(node.arguments)
-  trace "starting node",
-    args, executable, workingDir = node.workingDir, processOptions = poptions
+  trace "starting node", args, executable, workingDir = node.workingDir
 
   try:
     node.process = await startProcess(

tests/integration/nodeprocess.nim

@@ -53,10 +53,7 @@ method start*(node: NodeProcess) {.base, async: (raises: [CancelledError]).} =
 
   let poptions = node.processOptions + {AsyncProcessOption.StdErrToStdOut}
   trace "starting node",
-    args = node.arguments,
-    executable = node.executable,
-    workingDir = node.workingDir,
-    processOptions = poptions
+    args = node.arguments, executable = node.executable, workingDir = node.workingDir
 
   try:
     if node.debug:

tests/integration/testmanager.nim

@@ -6,6 +6,7 @@ from std/unicode import toUpper
 import std/unittest
 import pkg/chronos
 import pkg/chronos/asyncproc
+import pkg/codex/conf
 import pkg/codex/logutils
 import pkg/codex/utils/trackedfutures
 import pkg/questionable
@@ -66,9 +67,6 @@ type
   IntegrationTest = ref object
     manager: TestManager
     config: IntegrationTestConfig
-    # process: Future[CommandExResponse].Raising(
-    #   [AsyncProcessError, AsyncProcessTimeoutError, CancelledError]
-    # )
     process: AsyncProcessRef
     timeStart: ?Moment
     timeEnd: ?Moment
@@ -124,9 +122,19 @@ template ignoreCancelled(body) =
   except CancelledError:
     discard
 
+func logFile*(_: type TestManager, dir: string): string =
+  dir / "TestHarness.log"
+
+func logFile(manager: TestManager): string =
+  TestManager.logFile(manager.logsDir)
+
+func logFile(test: IntegrationTest, fileName: string): string =
+  test.logsDir / fileName
+
 proc new*(
     _: type TestManager,
     configs: seq[IntegrationTestConfig],
+    logsDir: string,
     debugTestHarness = false,
     debugHardhat = false,
     debugCodexNodes = false,
@@ -144,6 +152,7 @@ proc new*(
     showContinuousStatusUpdates: showContinuousStatusUpdates,
     testTimeout: testTimeout,
     trackedFutures: TrackedFutures.new(),
+    logsDir: logsDir,
   )
 
 func init*(
@@ -409,8 +418,6 @@ proc teardownTest(
       Future[seq[byte]].Raising([CancelledError, AsyncStreamError]),
 ) {.async: (raises: []).} =
   test.timeEnd = some Moment.now()
-  if test.status == IntegrationTestStatus.Ok:
-    info "Test completed", name = test.config.name, duration = test.duration
 
   if not test.process.isNil:
     var output = test.output.expect("should have output value")
@@ -426,6 +433,11 @@ proc teardownTest(
       output.stdOut = string.fromBytes(await noCancel stdOutStream)
       output.stdErr = string.fromBytes(await noCancel stdErrStream)
       test.output = success output
+      test.logFile("stdout.log").appendFile(output.stdOut.stripAnsi)
+      if test.status == IntegrationTestStatus.Error:
+        test.logFile("stderr.log").appendFile(output.stdErr.stripAnsi)
+    except IOError as e:
+      warn "Failed to write test stdout and stderr to file", error = e.msg
     except AsyncStreamError as e:
       test.timeEnd = some Moment.now()
       error "Failed to read test process output stream", error = e.msg
@@ -595,6 +607,25 @@ proc run(test: IntegrationTest) {.async: (raises: []).} =
       printStdOut = test.status != IntegrationTestStatus.Ok,
       printStdErr = test.status == IntegrationTestStatus.Error,
     )
+    logScope:
+      name = test.config.name
+      duration = test.duration
+
+    case test.status
+    of IntegrationTestStatus.New:
+      raiseAssert "Test has completed, but is in the New state"
+    of IntegrationTestStatus.Running:
+      raiseAssert "Test has completed, but is in the Running state"
+    of IntegrationTestStatus.Error:
+      error "Test errored",
+        error = test.output.errorOption .? msg,
+        stack = test.output.errorOption .? getStackTrace()
+    of IntegrationTestStatus.Failed:
+      error "Test failed"
+    of IntegrationTestStatus.Timeout:
+      error "Test timed out"
+    of IntegrationTestStatus.Ok:
+      notice "Test passed"
 
 proc runTests(manager: TestManager) {.async: (raises: [CancelledError]).} =
   var testFutures: seq[Future[void]]
@@ -603,6 +634,7 @@ proc runTests(manager: TestManager) {.async: (raises: [CancelledError]).} =
 
   echoStyled styleBright,
     bgWhite, fgBlack, "\n[Integration Test Manager] Starting parallel integration tests"
+  notice "[Integration Test Manager] Starting parallel integration tests"
 
   for config in manager.configs:
     var test =
@@ -685,35 +717,14 @@ proc printResult(manager: TestManager) {.raises: [TestManagerError].} =
     resetStyle,
     " |"
   echo "▢=====================================================================▢"
+  notice "INTEGRATION TEST SUMMARY",
+    totalTime = manager.duration,
+    timeSavedEst = &"{relativeTimeSaved}%",
+    passing = &"{successes} / {manager.tests.len}"
 
 proc start*(
     manager: TestManager
 ) {.async: (raises: [CancelledError, TestManagerError]).} =
-  try:
-    if manager.debugCodexNodes:
-      let startTime = now().format("yyyy-MM-dd'_'HH:mm:ss")
-      let logsDir =
-        currentSourcePath.parentDir() / "logs" /
-        sanitize(startTime & "__IntegrationTests")
-      createDir(logsDir)
-      manager.logsDir = logsDir
-      #!fmt: off
-      echoStyled bgWhite, fgBlack, styleBright,
-        "\n\n  ",
-        styleUnderscore,
-        "ℹ️  LOGS AVAILABLE ℹ️\n\n",
-        resetStyle, bgWhite, fgBlack, styleBright,
-        """  Logs for this run will be available at:""",
-        resetStyle, bgWhite, fgBlack,
-        &"\n\n  {logsDir}\n\n",
-        resetStyle, bgWhite, fgBlack, styleBright,
-        "  NOTE: For CI runs, logs will be attached as artefacts\n"
-      #!fmt: on
-  except IOError as e:
-    raiseTestManagerError "failed to create hardhat log directory: " & e.msg, e
-  except OSError as e:
-    raiseTestManagerError "failed to create hardhat log directory: " & e.msg, e
-
   if manager.showContinuousStatusUpdates:
     let fut = manager.continuallyShowUpdates()
     manager.trackedFutures.track fut
@@ -748,4 +759,3 @@ proc stop*(manager: TestManager) {.async: (raises: []).} =
         trace "Terminated running hardhat process"
     except CatchableError as e:
       trace "failed to stop hardhat node", error = e.msg
-

tests/integration/utils.nim

@@ -51,3 +51,16 @@ proc getLogFile*(
 
   let fileName = logsDir / fn
   return fileName
+
+proc appendFile*(filename: string, content: string) {.raises: [IOError].} =
+  ## Opens a file named `filename` for writing. Then writes the
+  ## `content` completely to the file and closes the file afterwards.
+  ## Raises an IO exception in case of an error.
+  var f: File
+  try:
+    f = open(filename, fmAppend)
+    f.write(content)
+  except IOError as e:
+    raise newException(IOError, "cannot open and write " & filename & ": " & e.msg)
+  finally:
+    close(f)

tests/testIntegration.nim

@@ -34,14 +34,72 @@ const DebugCodexNodes {.booldefine.} = false
 # Shows test status updates at time intervals. Useful for running locally with
 # active terminal interaction. Set to false for unattended runs, eg CI.
 const ShowContinuousStatusUpdates {.booldefine.} = false
-# Timeout duration (in mimutes) for EACH integration test file.
+# Timeout duration (in minutes) for EACH integration test file.
 const TestTimeout {.intdefine.} = 60
 
 const EnableParallelTests {.booldefine.} = true
 
+proc setupLogging(logFile: string, debugTestHarness: bool) =
+  when defaultChroniclesStream.outputs.type.arity != 3:
+    raiseAssert "Logging configuration options not enabled in the current build"
+  else:
+    proc writeAndFlush(f: File, msg: LogOutputStr) =
+      try:
+        f.write(msg)
+        f.flushFile()
+      except IOError as err:
+        logLoggingFailure(cstring(msg), err)
+
+    proc noOutput(logLevel: LogLevel, msg: LogOutputStr) =
+      discard
+
+    proc stdoutFlush(logLevel: LogLevel, msg: LogOutputStr) =
+      writeAndFlush(stdout, msg)
+
+    proc fileFlush(logLevel: LogLevel, msg: LogOutputStr) =
+      try:
+        logFile.appendFile(stripAnsi(msg))
+      except IOError as error:
+        fatal "Failed to write to log file", error = error.msg # error = error.ioErrorMsg
+        raiseAssert "Could not write to test manager log file: " & error.msg
+
+    defaultChroniclesStream.outputs[0].writer = stdoutFlush
+    defaultChroniclesStream.outputs[1].writer = noOutput
+    if debugTestHarness:
+      defaultChroniclesStream.outputs[2].writer = fileFlush
+    else:
+      defaultChroniclesStream.outputs[2].writer = noOutput
+
 proc run(): Future[bool] {.async: (raises: []).} =
+  let startTime = now().format("yyyy-MM-dd'_'HH:mm:ss")
+  let logsDir =
+    currentSourcePath.parentDir() / "integration" / "logs" /
+    sanitize(startTime & "__IntegrationTests")
+  try:
+    if DebugTestHarness or DebugHardhat or DebugCodexNodes:
+      createDir(logsDir)
+      #!fmt: off
+      styledEcho bgWhite, fgBlack, styleBright,
+        "\n\n  ",
+        styleUnderscore,
+        "ℹ️  LOGS AVAILABLE ℹ️\n\n",
+        resetStyle, bgWhite, fgBlack, styleBright,
+        """  Logs for this run will be available at:""",
+        resetStyle, bgWhite, fgBlack,
+        &"\n\n  {logsDir}\n\n",
+        resetStyle, bgWhite, fgBlack, styleBright,
+        "  NOTE: For CI runs, logs will be attached as artefacts\n"
+      #!fmt: on
+  except IOError as e:
+    raiseAssert "Failed to create log directory and echo log message: " & e.msg
+  except OSError as e:
+    raiseAssert "Failed to create log directory and echo log message: " & e.msg
+
+  setupLogging(TestManager.logFile(logsDir), DebugTestHarness)
+
   let manager = TestManager.new(
     configs = TestConfigs,
+    logsDir,
     DebugTestHarness,
     DebugHardhat,
     DebugCodexNodes,