feat: print logs of failed test when error is thrown in bouncer test.

bouncer/shared/utils/logger.ts

@@ -1,8 +1,20 @@
+import { toUpperCase } from '@chainflip/utils/string';
+import { appendFileSync, existsSync, mkdirSync } from 'fs';
+import { dirname } from 'path';
 import pino from 'pino';
 
 export type Logger = pino.Logger;
 
 const logFile = process.env.BOUNCER_LOG_PATH ?? '/tmp/chainflip/bouncer.log';
+const testLogDir = process.env.BOUNCER_TEST_LOGS_PATH ?? '/tmp/chainflip/bouncer-tests';
+
+export function getTestLogFile(logger: Logger): string {
+  const startTime = logger.bindings().startTime ?? 'UnknownStartStime';
+  const testname = logger.bindings().test ?? 'UnknownTest';
+  const tag = logger.bindings().tag ?? '';
+  const suffix = tag === '' ? '' : `-${tag}`;
+  return `${testLogDir}/${startTime}/${testname}${suffix}.log`;
+}
 
 const logFileDestination = pino.destination({
   dest: logFile,
@@ -14,25 +26,47 @@ const prettyConsoleTransport = pino.transport({
   options: {
     colorize: true,
     // Note: we are ignoring the common bindings to keep the cli log clean.
-    ignore: 'test,module,tag',
+    ignore: 'test,module,tag,startTime',
   },
 });
 
+const getIsoTime = () => {
+  // Getting the time using the time function of pino, there might be a better way to do this.
+  const { time } = JSON.parse(`{"noop": "nothing"${pino.stdTimeFunctions.isoTime()}}`);
+  return time as string;
+};
+
 // Log the given value without having to include %s in the message. Just like console.log
-function logMethod(this: pino.Logger, args: Parameters<pino.LogFn>, method: pino.LogFn) {
+function logMethod(
+  this: pino.Logger,
+  args: Parameters<pino.LogFn>,
+  method: pino.LogFn,
+  level: number,
+) {
   const newArgs = args;
   if (args.length === 2 && !args[0].includes('%s')) {
     newArgs[0] = `${args[0]} %s`;
   }
   method.apply(this, newArgs);
+
+  // Append log line to file. We ignore log levels that are 'trace' or below.
+  if (level > this.levels.values.trace) {
+    const testLogFile = getTestLogFile(this);
+    if (!existsSync(dirname(testLogFile))) {
+      mkdirSync(dirname(testLogFile), { recursive: true });
+    }
+    const logLine = `[${getIsoTime()}] ${toUpperCase(this.levels.labels[level])}: ${newArgs}\n`;
+    appendFileSync(testLogFile, logLine);
+  }
 }
 
 export const globalLogger: Logger = pino(
   {
     hooks: { logMethod },
     level: 'trace',
     // We don't want to log the hostname or pid
-    base: undefined,
+    // We do want to save the start time.
+    base: { startTime: getIsoTime() },
     timestamp: pino.stdTimeFunctions.isoTime,
     // Log the level as a string ("info") instead of a number (30)
     formatters: {

bouncer/shared/utils/substrate.ts

@@ -514,6 +514,7 @@ export function observeEvents<T = any>(
 
   const controller = abortable ? new AbortController() : undefined;
 
+  const logMessagePeriod: number = 5;
   let blocksChecked = 0;
   const findEvent = async () => {
     await using subscription = await subscribeHeads({ chain, finalized });
@@ -525,7 +526,11 @@ export function observeEvents<T = any>(
 
     const checkEvents = (events: Event[], log: string) => {
       blocksChecked += 1;
-      logger.trace(`Checking ${events.length} ${log} events for ${eventName}`);
+      if (blocksChecked % logMessagePeriod === 0) {
+        logger.trace(
+          `Checking ${events.length} ${log} events for ${eventName} (${blocksChecked}th block)`,
+        );
+      }
       let stop = false;
       const foundEvents: Event[] = [];
       for (const event of events) {
@@ -598,7 +603,7 @@ export function observeEvents<T = any>(
           )} seconds`,
         );
         break;
-      } else {
+      } else if (blocksChecked % logMessagePeriod === 0) {
         logger.trace(`No ${eventName} events found in subscription.`);
       }
     }

bouncer/shared/utils/vitest.ts

@@ -1,7 +1,8 @@
 import { existsSync, readFileSync, writeFileSync } from 'fs';
 import { afterEach, beforeEach, it } from 'vitest';
 import { TestContext } from 'shared/utils/test_context';
-import { testInfoFile } from 'shared/utils';
+import { runWithTimeout, testInfoFile } from 'shared/utils';
+import { getTestLogFile } from './logger';
 
 // Write the test name and function name to a file to be used by the `run_test.ts` command
 function writeTestInfoFile(name: string, functionName: string) {
@@ -30,16 +31,27 @@ afterEach<{ testContext: TestContext }>((context) => {
   context.testContext.printReport();
 });
 
-function createTestFunction(name: string, testFunction: (context: TestContext) => Promise<void>) {
+function createTestFunction(
+  name: string,
+  timeoutSeconds: number,
+  testFunction: (context: TestContext) => Promise<void>,
+) {
   return async (context: { testContext: TestContext }) => {
     // Attach the test name to the logger
     context.testContext.logger = context.testContext.logger.child({ test: name });
     context.testContext.logger.info(`🧪 Starting test ${name}`);
+
     // Run the test with the test context
-    await testFunction(context.testContext).catch((error) => {
+    await runWithTimeout(testFunction(context.testContext), timeoutSeconds).catch((error) => {
       // We must catch the error here to be able to log it
       context.testContext.error(error);
-      throw error;
+
+      // get local logs from file and append them to the error
+      const testLogFileName = getTestLogFile(context.testContext.logger);
+      const logs = readFileSync(testLogFileName);
+
+      // re-throw error with logs
+      throw new Error(`${error}\n\nhistory:\n${logs}`);
     });
     context.testContext.logger.info(`✅ Finished test ${name}`);
   };
@@ -53,8 +65,10 @@ export function concurrentTest(
 ) {
   it.concurrent<{ testContext: TestContext }>(
     name,
-    createTestFunction(name, testFunction),
-    timeoutSeconds * 1000,
+    createTestFunction(name, timeoutSeconds, testFunction),
+    // we catch the timeout manually inside `createTestFunction` so that we can print the test logs.
+    // the timeout here is a fallback and should never trigger:
+    (timeoutSeconds + 5) * 1000,
   );
 
   if (!excludeFromList) {
@@ -70,8 +84,10 @@ export function serialTest(
 ) {
   it.sequential<{ testContext: TestContext }>(
     name,
-    createTestFunction(name, testFunction),
-    timeoutSeconds * 1000,
+    createTestFunction(name, timeoutSeconds, testFunction),
+    // we catch the timeout manually inside `createTestFunction` so that we can print the test logs.
+    // the timeout here is a fallback and should never trigger:
+    (timeoutSeconds + 5) * 1000,
   );
 
   if (!excludeFromList) {