feat: Pino logging in bouncer (#5643)

* feat: use pino logging in all tests and test utils

* fix: log a message after logger init, might help.

* refactor: remove tag argument

* refactor: trying to avoid error on check_bin_and_runtime_versions

* add flag

* chore: output bouncer.log file as artifact in CI

* fix: different name for upgrade test bouncer logs artifact

---------

Co-authored-by: Andrew Dibble <andrew@chainflip.io>

.github/workflows/_40_post_check.yml

@@ -202,6 +202,15 @@ jobs:
             /tmp/chainflip/debug.*log
             /tmp/solana/*.*log
 
+      - name: Upload Bouncer Logs 💾
+        if: always()
+        continue-on-error: true
+        uses: actions/upload-artifact@50769540e7f4bd5e21e526ee35c689e35e0d6874
+        with:
+          name: bouncer-logs
+          path: |
+            /tmp/chainflip/bouncer.log
+
       - name: List /tmp/chainflip 📂
         if: always()
         continue-on-error: true

.github/workflows/upgrade-test.yml

@@ -285,6 +285,15 @@ jobs:
           path: |
             /tmp/chainflip/logs/*.log
 
+      - name: Upload Bouncer Logs 💾
+        if: always()
+        continue-on-error: true
+        uses: actions/upload-artifact@50769540e7f4bd5e21e526ee35c689e35e0d6874
+        with:
+          name: bouncer-logs-upgrade-test
+          path: |
+            /tmp/chainflip/bouncer.log
+
       - name: Write chain explorer to file 📝
         if: failure()
         continue-on-error: true

bouncer/README.md

@@ -103,12 +103,18 @@ describe('ConcurrentTests', () => {
 });
 ```
 
-Now that the test is added, we can run it using the `vitest` command.
+Now that the test is added, we can run it using the `vitest` command:
 
 ```sh copy
 pnpm vitest run -t "myNewTest"
 ```
 
+You can use `vitest`s `list` command to find the name of that test you what to run:
+
+```sh copy
+pnpm vitest list
+```
+
 If your test uses the `SwapContext` within the `TestContext`, then the report will be automatically logged when the test finishes.
 If you would like to run your test with custom arguments, then you will have to create a test command file.
 See the `test_commands` folder for examples.
@@ -122,3 +128,89 @@ pnpm vitest run -t "ConcurrentTests"
 # run all tests in a file
 pnpm vitest run -t ./tests/fast_bouncer.test.ts
 ```
+
+## Logging
+
+In the bouncer we use `Pino` as our logging framework. It has been configured to output the logs to:
+
+- `stdout` at `INFO` level in pretty format
+- `/tmp/chainflip/bouncer.log` at `TRACE` level in `JSON` format
+
+Note: To keep the `stdout` clean, that output is configured to ignore the common `test`, `tag` and `module` bindings that ar attached to log messages.
+
+### Logging in a test
+
+Use the `Logger` that is attached to the `TestContext`.
+This logger already has the name of the test attached to it.
+Do not use `console.log` as it will not be logged to the file.
+
+```ts
+import { TestContext } from '../shared/utils/test_context';
+import { Logger, throwError } from '../shared/utils/logger';
+
+async function testCase(parentLogger: Logger, asset: Asset) {
+  // Attach any contextual data to the logger as a binding. {"inputAsset": "Eth"}.
+  const logger = parentLogger.child({ inputAsset: asset });
+
+  // Basic logging
+  logger.debug('About to foo');
+
+  // Throwing an error with all of the loggers contextual data (bindings) added to the error message.
+  // No need to catch this, it will be logged as at `Error` level.
+  if (foo) {
+    throwError(logger, new Error('Foo happened'));
+  }
+}
+
+export async function myTest(testContext: TestContext) {
+  await testCase(testContext.logger, 'Eth');
+
+  // You can log directly from the `TestContext` as well
+  testContext.info('Goodbye');
+}
+```
+
+Another option for adding information to the logger is using the custom `loggerChild` function.
+This will append the given string to the `module` binding.
+
+```ts
+import { loggerChild } from '../shared/utils/logger';
+
+const logger1 = loggerChild(parentLogger, `myTestCase`);
+const logger2 = loggerChild(logger1, `setupFunction`);
+const logger3 = loggerChild(logger2, `myFunction`);
+logger3.info('This message will have the full module path attached');
+// {"module": `myTestCase::setupFunction::myFunction`}
+```
+
+### Logging outside of a test
+
+If you need to use the logger in a command or any other non-test code, you can use the `globalLogger`.
+It has no bindings attached to it.
+It will still output to both `stdout` and the `bouncer.log` file.
+
+```ts
+import { globalLogger } from '../shared/utils/logger';
+
+globalLogger.info('Executing my command');
+await observeEvent(globalLogger, 'someEvent');
+```
+
+### Debugging
+
+To debug a failed test you can use the `bouncer.log` file. It will have logs at `Trace` level of all test that where ran.
+To filter for the test you are debugging, you can use the `test` value that should be on all log messages (Excluding logs from commands, setup scripts and thrown errors).
+
+An example of using `jq` to filter the logs for an individual test and put them in another file:
+
+```sh copy
+jq 'select(.test=="BoostingForAsset")' /tmp/chainflip/bouncer.log > /tmp/chainflip/failed_test.log
+```
+
+If you want to run a test and have the `stdout` logs be at different level, you can use the `BOUNCER_LOG_LEVEL` environment variable (Does not effect the `bouncer.log` file).
+
+```sh copy
+BOUNCER_LOG_LEVEL=debug pnpm vitest run -t "BoostingForAsset"
+```
+
+Note: you can use the `BOUNCER_LOG_PATH` environment variable to output the logs to a different file.

bouncer/commands/add_boost_funds.ts

@@ -13,9 +13,11 @@
 import { InternalAsset as Asset } from '@chainflip/cli';
 import { runWithTimeoutAndExit } from '../shared/utils';
 import { addBoostFunds } from '../tests/boost';
+import { globalLogger } from '../shared/utils/logger';
 
 await runWithTimeoutAndExit(
   addBoostFunds(
+    globalLogger,
     process.argv[2] as Asset,
     Number(process.argv[3]),
     Number(process.argv[4]),

bouncer/commands/check_bin_and_runtime_versions.ts

@@ -2,13 +2,10 @@
 
 import fs from 'fs';
 import toml from '@iarna/toml';
-import { compareSemVer } from '../shared/utils';
+import { compareSemVer, runWithTimeoutAndExit } from '../shared/utils';
 import { jsonRpc } from '../shared/json_rpc';
 import { specVersion } from '../shared/utils/spec_version';
-
-const projectRoot = process.argv[2];
-const engineReleaseVersion = process.argv[3];
-const network = process.argv[4];
+import { globalLogger as logger } from '../shared/utils/logger';
 
 export function tomlVersion(cargoFilePath: string): Promise<string> {
   return new Promise((resolve, reject) => {
@@ -29,82 +26,94 @@ export function tomlVersion(cargoFilePath: string): Promise<string> {
   });
 }
 
-const versionRegex = /\d+\.\d+\.\d+/;
-const releaseVersion = engineReleaseVersion.match(versionRegex)?.[0];
-if (!releaseVersion) {
-  throw Error('Invalid release version');
-}
+async function main() {
+  const projectRoot = process.argv[2];
+  const engineReleaseVersion = process.argv[3];
+  const network = process.argv[4];
 
-// Ensure all the versions are the same
-const engineTomlVersion = await tomlVersion(`${projectRoot}/engine/Cargo.toml`);
-const runtimeTomlVersion = await tomlVersion(`${projectRoot}/state-chain/runtime/Cargo.toml`);
-const nodeTomlVersion = await tomlVersion(`${projectRoot}/state-chain/node/Cargo.toml`);
-const cliTomlVersion = await tomlVersion(`${projectRoot}/api/bin/chainflip-cli/Cargo.toml`);
-const lpApiTomlVersion = await tomlVersion(`${projectRoot}/api/bin/chainflip-lp-api/Cargo.toml`);
-const apiLibTomlVersion = await tomlVersion(`${projectRoot}/api/lib/Cargo.toml`);
-const runnerTomlVersion = await tomlVersion(`${projectRoot}/engine-runner-bin/Cargo.toml`);
-const dylibTomlVersion = await tomlVersion(`${projectRoot}/engine-dylib/Cargo.toml`);
-// The engine gets the version from this file
-const procMacrosVersion = await tomlVersion(`${projectRoot}/engine-proc-macros/Cargo.toml`);
+  const versionRegex = /\d+\.\d+\.\d+/;
+  const releaseVersion = engineReleaseVersion.match(versionRegex)?.[0];
+  if (!releaseVersion) {
+    throw Error('Invalid release version');
+  }
 
-const brokerTomlVersion = await tomlVersion(
-  `${projectRoot}/api/bin/chainflip-broker-api/Cargo.toml`,
-);
+  // Ensure all the versions are the same
+  const engineTomlVersion = await tomlVersion(`${projectRoot}/engine/Cargo.toml`);
+  const runtimeTomlVersion = await tomlVersion(`${projectRoot}/state-chain/runtime/Cargo.toml`);
+  const nodeTomlVersion = await tomlVersion(`${projectRoot}/state-chain/node/Cargo.toml`);
+  const cliTomlVersion = await tomlVersion(`${projectRoot}/api/bin/chainflip-cli/Cargo.toml`);
+  const lpApiTomlVersion = await tomlVersion(`${projectRoot}/api/bin/chainflip-lp-api/Cargo.toml`);
+  const apiLibTomlVersion = await tomlVersion(`${projectRoot}/api/lib/Cargo.toml`);
+  const runnerTomlVersion = await tomlVersion(`${projectRoot}/engine-runner-bin/Cargo.toml`);
+  const dylibTomlVersion = await tomlVersion(`${projectRoot}/engine-dylib/Cargo.toml`);
+  // The engine gets the version from this file
+  const procMacrosVersion = await tomlVersion(`${projectRoot}/engine-proc-macros/Cargo.toml`);
 
-if (
-  !(
-    engineTomlVersion === runtimeTomlVersion &&
-    runtimeTomlVersion === nodeTomlVersion &&
-    nodeTomlVersion === cliTomlVersion &&
-    cliTomlVersion === lpApiTomlVersion &&
-    lpApiTomlVersion === brokerTomlVersion &&
-    apiLibTomlVersion === brokerTomlVersion &&
-    brokerTomlVersion === runnerTomlVersion &&
-    runnerTomlVersion === dylibTomlVersion &&
-    dylibTomlVersion === procMacrosVersion
-  )
-) {
-  throw Error('All versions should be the same');
-} else if (compareSemVer(engineTomlVersion, releaseVersion) === 'greater') {
-  console.log(
-    `Binary versions are correct. Your branch has version ${engineTomlVersion} greater than the current release ${releaseVersion}.`,
-  );
-} else {
-  throw Error(
-    `Binary versions are incorrect. The version of your branch (${engineTomlVersion}) should be greater than the current release (${releaseVersion}).)`,
+  const brokerTomlVersion = await tomlVersion(
+    `${projectRoot}/api/bin/chainflip-broker-api/Cargo.toml`,
   );
-}
 
-let endpoint;
-switch (network) {
-  case 'mainnet':
-  case 'berghain':
-    endpoint = 'https://mainnet-archive.chainflip.io:443';
-    break;
-  case 'perseverance':
-    endpoint = 'https://perseverance.chainflip.xyz:443';
-    break;
-  case 'sisyphos':
-    endpoint = 'https://archive.sisyphos.chainflip.io:443';
-    break;
-  default:
-    throw Error('Invalid network');
-}
+  if (
+    !(
+      engineTomlVersion === runtimeTomlVersion &&
+      runtimeTomlVersion === nodeTomlVersion &&
+      nodeTomlVersion === cliTomlVersion &&
+      cliTomlVersion === lpApiTomlVersion &&
+      lpApiTomlVersion === brokerTomlVersion &&
+      apiLibTomlVersion === brokerTomlVersion &&
+      brokerTomlVersion === runnerTomlVersion &&
+      runnerTomlVersion === dylibTomlVersion &&
+      dylibTomlVersion === procMacrosVersion
+    )
+  ) {
+    throw Error('All versions should be the same');
+  } else if (compareSemVer(engineTomlVersion, releaseVersion) === 'greater') {
+    logger.info(
+      `Binary versions are correct. Your branch has version ${engineTomlVersion} greater than the current release ${releaseVersion}.`,
+    );
+  } else {
+    throw Error(
+      `Binary versions are incorrect. The version of your branch (${engineTomlVersion}) should be greater than the current release (${releaseVersion}).)`,
+    );
+  }
 
-const releaseSpecVersion = Number(
-  ((await jsonRpc('state_getRuntimeVersion', [], endpoint)) as any).specVersion,
-);
-console.log(`Release spec version: ${releaseSpecVersion}`);
+  let endpoint;
+  switch (network) {
+    case 'mainnet':
+    case 'berghain':
+      endpoint = 'https://mainnet-archive.chainflip.io:443';
+      break;
+    case 'perseverance':
+      endpoint = 'https://perseverance.chainflip.xyz:443';
+      break;
+    case 'sisyphos':
+      endpoint = 'https://archive.sisyphos.chainflip.io:443';
+      break;
+    default:
+      throw Error('Invalid network');
+  }
 
-const specVersionInSource = specVersion(`${projectRoot}/state-chain/runtime/src/lib.rs`, 'read');
-console.log(`Spec version in runtime/src/lib.rs: ${specVersionInSource}`);
-
-if (specVersionInSource >= releaseSpecVersion) {
-  console.log(
-    `Spec version is correct. Version in TOML is greater than or equal to the release spec version.`,
+  const releaseSpecVersion = Number(
+    ((await jsonRpc(logger, 'state_getRuntimeVersion', [], endpoint)) as any).specVersion,
   );
-} else {
-  throw Error(
-    `Spec version is incorrect. Version in TOML (${specVersionInSource}) should be greater than or equal to the release spec version (${releaseSpecVersion}).`,
+  logger.info(`Release spec version: ${releaseSpecVersion}`);
+
+  const specVersionInSource = specVersion(
+    logger,
+    `${projectRoot}/state-chain/runtime/src/lib.rs`,
+    'read',
   );
+  logger.info(`Spec version in runtime/src/lib.rs: ${specVersionInSource}`);
+
+  if (specVersionInSource >= releaseSpecVersion) {
+    logger.info(
+      `Spec version is correct. Version in TOML is greater than or equal to the release spec version.`,
+    );
+  } else {
+    throw Error(
+      `Spec version is incorrect. Version in TOML (${specVersionInSource}) should be greater than or equal to the release spec version (${releaseSpecVersion}).`,
+    );
+  }
 }
+
+await runWithTimeoutAndExit(main(), 60);

bouncer/commands/create_boost_pools.ts

@@ -10,6 +10,7 @@
 
 import { runWithTimeoutAndExit } from '../shared/utils';
 import { BoostPoolId, createBoostPools } from '../shared/setup_boost_pools';
+import { globalLogger } from '../shared/utils/logger';
 
 const newPools: BoostPoolId[] = JSON.parse(process.argv[2]);
-await runWithTimeoutAndExit(createBoostPools(newPools), 30);
+await runWithTimeoutAndExit(createBoostPools(globalLogger, newPools), 30);

bouncer/commands/create_lp_pool.ts

@@ -8,7 +8,8 @@
 
 import { createLpPool } from '../shared/create_lp_pool';
 import { parseAssetString, runWithTimeoutAndExit } from '../shared/utils';
+import { globalLogger } from '../shared/utils/logger';
 
 const initialPrice = parseFloat(process.argv[3]);
 const asset = parseAssetString(process.argv[2]);
-await runWithTimeoutAndExit(createLpPool(asset, initialPrice), 20);
+await runWithTimeoutAndExit(createLpPool(globalLogger, asset, initialPrice), 20);

bouncer/commands/delete_all_orders_lp_api.ts

@@ -6,9 +6,10 @@
 
 import { runWithTimeoutAndExit } from '../shared/utils';
 import { DeleteAllOrdersLpApi } from '../shared/delete_all_orders_lp_api';
+import { globalLogger } from '../shared/utils/logger';
 
 async function main(): Promise<void> {
-  await DeleteAllOrdersLpApi();
+  await DeleteAllOrdersLpApi(globalLogger);
 }
 
 await runWithTimeoutAndExit(main(), 240);

bouncer/commands/deposit_liquidity.ts

@@ -11,8 +11,12 @@
 import { InternalAsset } from '@chainflip/cli';
 import { parseAssetString, runWithTimeoutAndExit } from '../shared/utils';
 import { depositLiquidity } from '../shared/deposit_liquidity';
+import { globalLogger } from '../shared/utils/logger';
 
 const asset = parseAssetString(process.argv[2]);
 const amount = parseFloat(process.argv[3]);
 const lpKey = process.argv[4];
-await runWithTimeoutAndExit(depositLiquidity(asset as InternalAsset, amount, false, lpKey), 120);
+await runWithTimeoutAndExit(
+  depositLiquidity(globalLogger, asset as InternalAsset, amount, false, lpKey),
+  120,
+);

bouncer/commands/fund_flip.ts

@@ -11,7 +11,8 @@
 
 import { runWithTimeoutAndExit } from '../shared/utils';
 import { fundFlip } from '../shared/fund_flip';
+import { globalLogger } from '../shared/utils/logger';
 
 const address = process.argv[2];
 const flipAmount = process.argv[3].trim();
-await runWithTimeoutAndExit(fundFlip(address, flipAmount), 120);
+await runWithTimeoutAndExit(fundFlip(globalLogger, address, flipAmount), 120);