feat: Write debug-level log to local file in Sandbox (#1846)

Writes all debug logs, regardless of `LOG_LEVEL` or `DEBUG`, to a local
file in `./log` when running the Sandbox. If run within Docker, the log
folder is mounted locally so the user can access the logs without having
to manually connect to the container.

Logs are outputted using `winston`'s
[daily-rotate-file](https://www.npmjs.com/package/winston-daily-rotate-file)
to prevent logs from growing out of control, and formatted as ndjson,
including level, namespace, and timestamp. Note that the winston
dependency is only added to the `sandbox` package, all other packages
still use foundation's plain log.

Example log:

```
$ head -n10 log/aztec-sandbox.debug.log 
{"level":"info","message":"Setting up Aztec Sandbox, please stand by...","namespace":"aztec:sandbox","timestamp":"2023-08-28T18:49:51.961Z"}
{"level":"info","message":"Deploying rollup contracts to L1...","namespace":"aztec:sandbox","timestamp":"2023-08-28T18:49:51.962Z"}
{"level":"debug","message":"Deploying contracts...","namespace":"aztec:sandbox","timestamp":"2023-08-28T18:49:51.981Z"}
{"level":"debug","message":"Deployed Registry at 0x5fbdb2315678afecb367f032d93f642f64180aa3","namespace":"aztec:sandbox","timestamp":"2023-08-28T18:49:52.003Z"}
{"level":"debug","message":"Deployed Inbox at 0xe7f1725e7734ce288f8367e1bb143e90bb3f0512","namespace":"aztec:sandbox","timestamp":"2023-08-28T18:49:52.020Z"}
{"level":"debug","message":"Deployed Outbox at 0x9fe46736679d2d9a65f0992f2272de9f3c7fa6e0","namespace":"aztec:sandbox","timestamp":"2023-08-28T18:49:52.033Z"}
{"level":"debug","message":"Deployed Rollup at 0xcf7ed3acca5a467e9e704c703e8d87f634fb0fc9","namespace":"aztec:sandbox","timestamp":"2023-08-28T18:49:52.048Z"}
{"level":"debug","message":"Deployed contract deployment emitter at 0x5fc8d32690cc91d4c39d9d3abcbd16989f875707","namespace":"aztec:sandbox","timestamp":"2023-08-28T18:49:52.060Z"}
{"level":"debug","message":"Performing initial chain sync...","namespace":"aztec:archiver","timestamp":"2023-08-28T18:49:52.061Z"}
{"level":"debug","message":"Adding pending l1 to l2 messages to store","namespace":"aztec:archiver","timestamp":"2023-08-28T18:49:52.081Z"}
```

Fixes #1605

yarn-project/archiver/src/index.ts

@@ -47,7 +47,7 @@ async function main() {
 if (process.argv[1] === fileURLToPath(import.meta.url).replace(/\/index\.js$/, '')) {
   // eslint-disable-next-line @typescript-eslint/no-floating-promises
   main().catch(err => {
-    log.fatal(err);
+    log.error(err);
     process.exit(1);
   });
 }

yarn-project/aztec-sandbox/.gitignore

@@ -0,0 +1 @@
+/log

yarn-project/aztec-sandbox/docker-compose.yml

@@ -11,7 +11,8 @@ services:
     ports:
       - '8080:8080'
     environment:
-      DEBUG: # DEBUG is loaded from the user shell running compose
+      DEBUG: # Loaded from the user shell if explicitly set
+      HOST_WORKDIR: '${PWD}' # Loaded from the user shell to show log files absolute path in host
       ETHEREUM_HOST: http://ethereum:8545
       CHAIN_ID: 31337
       ARCHIVER_POLLING_INTERVAL_MS: 50
@@ -20,3 +21,5 @@ services:
       WS_BLOCK_CHECK_INTERVAL_MS: 50
       RPC_SERVER_BLOCK_POLLING_INTERVAL_MS: 50
       ARCHIVER_VIEM_POLLING_INTERVAL_MS: 500
+    volumes:
+      - ./log:/usr/src/yarn-project/aztec-sandbox/log:rw

yarn-project/aztec-sandbox/package.json

@@ -43,7 +43,9 @@
     "abitype": "^0.8.11",
     "koa": "^2.14.2",
     "koa-router": "^12.0.0",
-    "viem": "^1.2.5"
+    "viem": "^1.2.5",
+    "winston": "^3.10.0",
+    "winston-daily-rotate-file": "^4.7.1"
   },
   "files": [
     "dest",

yarn-project/aztec-sandbox/src/index.ts

@@ -14,6 +14,7 @@ import { HDAccount, createPublicClient, http as httpViemTransport } from 'viem';
 import { mnemonicToAccount } from 'viem/accounts';
 import { foundry } from 'viem/chains';
 
+import { setupFileDebugLog } from './logging.js';
 import { startHttpRpcServer } from './server.js';
 import { github, splash } from './splash.js';
 
@@ -60,6 +61,7 @@ async function waitThenDeploy(rpcUrl: string, hdAccount: HDAccount) {
  * Create and start a new Aztec RCP HTTP Server
  */
 async function main() {
+  const logPath = setupFileDebugLog();
   const aztecNodeConfig: AztecNodeConfig = getConfigEnvVars();
   const rpcConfig = getRpcConfigEnvVars();
   const hdAccount = mnemonicToAccount(MNEMONIC);
@@ -92,7 +94,8 @@ async function main() {
   process.once('SIGTERM', shutdown);
 
   startHttpRpcServer(aztecRpcServer, deployedL1Contracts, SERVER_PORT);
-  logger.info(`Aztec JSON RPC listening on port ${SERVER_PORT}`);
+  logger.info(`Aztec Sandbox JSON-RPC Server listening on port ${SERVER_PORT}`);
+  logger.info(`Debug logs will be written to ${logPath}`);
   const accountStrings = [`Initial Accounts:\n\n`];
 
   const registeredAccounts = await aztecRpcServer.getAccounts();
@@ -105,10 +108,10 @@ async function main() {
       accountStrings.push(` Public Key: ${completeAddress.publicKey.toString()}\n\n`);
     }
   }
-  logger.info(`${splash}\n${github}\n\n`.concat(...accountStrings).concat(`\nAztec Sandbox now ready for use!`));
+  logger.info(`${splash}\n${github}\n\n`.concat(...accountStrings).concat(`Aztec Sandbox is now ready for use!`));
 }
 
 main().catch(err => {
-  logger.fatal(err);
+  logger.error(err);
   process.exit(1);
 });

yarn-project/aztec-sandbox/src/logging.ts

@@ -0,0 +1,45 @@
+import { onLog } from '@aztec/foundation/log';
+
+import * as path from 'path';
+import * as process from 'process';
+import * as util from 'util';
+import * as winston from 'winston';
+import DailyRotateFile from 'winston-daily-rotate-file';
+
+const { format } = winston;
+const CURRENT_LOG_FILE_NAME = 'aztec-sandbox.debug.log';
+const LOG_DIR = 'log';
+
+/** Creates a winston logger that logs everyting to a local rotating file */
+function createWinstonLogger() {
+  // See https://www.npmjs.com/package/winston-daily-rotate-file#user-content-options
+  const transport: DailyRotateFile = new DailyRotateFile({
+    filename: 'aztec-sandbox-%DATE%.debug.log',
+    dirname: LOG_DIR,
+    datePattern: 'YYYY-MM-DD',
+    zippedArchive: true,
+    maxSize: '30m',
+    maxFiles: '5',
+    createSymlink: true,
+    symlinkName: CURRENT_LOG_FILE_NAME,
+  });
+
+  return winston.createLogger({
+    level: 'debug',
+    transports: [transport],
+    format: format.combine(format.timestamp(), format.json()),
+  });
+}
+
+/**
+ * Hooks to all log statements and outputs them to a local rotating file.
+ * @returns Output log name.
+ */
+export function setupFileDebugLog() {
+  const logger = createWinstonLogger();
+  onLog((level, namespace, args) => {
+    logger.log({ level, namespace, message: util.format(...args) });
+  });
+  const workdir = process.env.HOST_WORKDIR ?? process.cwd();
+  return path.join(workdir, LOG_DIR, CURRENT_LOG_FILE_NAME);
+}

yarn-project/foundation/src/log/logger.ts

@@ -4,7 +4,8 @@ import { isatty } from 'tty';
 
 import { LogFn } from './index.js';
 
-const LogLevels = ['silent', 'fatal', 'error', 'warn', 'info', 'debug'] as const;
+// Matches a subset of Winston log levels
+const LogLevels = ['silent', 'error', 'warn', 'info', 'verbose', 'debug'] as const;
 const DefaultLogLevel = 'info' as const;
 
 /**
@@ -39,13 +40,26 @@ export function createDebugLogger(name: string): DebugLogger {
 
   const logger = {
     silent: () => {},
-    fatal: (...args: any[]) => logWithDebug(debugLogger, 'fatal', args),
     error: (...args: any[]) => logWithDebug(debugLogger, 'error', args),
     warn: (...args: any[]) => logWithDebug(debugLogger, 'warn', args),
     info: (...args: any[]) => logWithDebug(debugLogger, 'info', args),
+    verbose: (...args: any[]) => logWithDebug(debugLogger, 'verbose', args),
     debug: (...args: any[]) => logWithDebug(debugLogger, 'debug', args),
   };
-  return Object.assign(debugLogger, logger);
+  return Object.assign((...args: any[]) => logWithDebug(debugLogger, 'debug', args), logger);
+}
+
+/** A callback to capture all logs. */
+export type LogHandler = (level: LogLevel, namespace: string, args: any[]) => void;
+
+const logHandlers: LogHandler[] = [];
+
+/**
+ * Registers a callback for all logs, whether they are emitted in the current log level or not.
+ * @param handler - Callback to be called on every log.
+ */
+export function onLog(handler: LogHandler) {
+  logHandlers.push(handler);
 }
 
 /**
@@ -55,6 +69,9 @@ export function createDebugLogger(name: string): DebugLogger {
  * @param args - Args to log.
  */
 function logWithDebug(debug: debug.Debugger, level: LogLevel, args: any[]) {
+  for (const handler of logHandlers) {
+    handler(level, debug.namespace, args);
+  }
   if (debug.enabled) {
     debug(args[0], ...args.slice(1));
   } else if (LogLevels.indexOf(level) <= LogLevels.indexOf(currentLevel) && process.env.NODE_ENV !== 'test') {