feat: JSON logging (#8095)

Adds a LOG_JSON env var that disables the foundation logger and replaces
it with a winston json logger.

```
{"level":"info","message":"Set block interval to 12","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.509Z"}
{"level":"info","message":"Deploying contracts from 0xf39Fd6e51aad88F6F4ce6aB8827279cffFb92266...","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.509Z"}
{"level":"info","message":"Deployed Registry at 0x3aa5ebb10dc797cac828524e59a333d0a371443c","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.534Z"}
{"level":"info","message":"Deployed AvailabilityOracle at 0xc6e7df5e7b4f2a278906862b61205850344d4e7d","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.551Z"}
{"level":"info","message":"Deployed Fee Juice at 0x59b670e9fa9d0a427751af201d676719a970857b","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.563Z"}
{"level":"info","message":"Deployed Gas Portal at 0x4ed7c70f96b99c776995fb64377f0d4ab3b0e1c1","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.573Z"}
{"level":"info","message":"Funded fee juice portal contract with Fee Juice","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.582Z"}
{"level":"info","message":"Initialized Gas Portal at 0x4ed7c70f96b99c776995fb64377f0d4ab3b0e1c1 to bridge between L1 0x59b670e9fa9d0a427751af201d676719a970857b to L2 0x16a83e3395bc921a2441db55dce24f0e0932636901a2e676fa68b9b2b9a644c1","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.591Z"}
{"level":"info","message":"Deployed Rollup at 0x4a679253410272dd5232b3ff7cf5dbb88f295319","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.608Z"}
{"level":"info","message":"Inbox available at 0x532b02bd614fd18aee45603d02866cfb77575cb3","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.610Z"}
{"level":"info","message":"Outbox available at 0xe801273f775eacc1d74d1d43f92ec4524cabbd35","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.612Z"}
{"level":"info","message":"Using NoopTelemetryClient","module":"aztec:telemetry-client","timestamp":"2024-08-21T02:15:29.644Z"}
{"level":"info","message":"Creating ephemeral data store","module":"aztec:node:lmdb","timestamp":"2024-08-21T02:15:29.645Z"}
{"level":"info","message":"Performing initial chain sync to rollup contract 0x4a679253410272dd5232b3ff7cf5dbb88f295319","module":"aztec:archiver","timestamp":"2024-08-21T02:15:29.661Z"}
{"level":"info","message":"Synced to L1 block 27","module":"aztec:archiver","timestamp":"2024-08-21T02:15:29.672Z"}
{"level":"info","message":"Started block downloader from block 1","module":"aztec:world_state","timestamp":"2024-08-21T02:15:29.743Z"}
{"level":"info","message":"Using WASM ACVM simulation","module":"aztec:node","timestamp":"2024-08-21T02:15:29.744Z"}
{"level":"info","message":"Sequencer started","module":"aztec:sequencer","timestamp":"2024-08-21T02:15:29.745Z"}
{"level":"info","message":"Started Aztec Node against chain 0x7a69 with contracts - \nRollup: 0x4a679253410272dd5232b3ff7cf5dbb88f295319\nRegistry: 0x3aa5ebb10dc797cac828524e59a333d0a371443c\nInbox: 0x532b02bd614fd18aee45603d02866cfb77575cb3\nOutbox: 0xe801273f775eacc1d74d1d43f92ec4524cabbd35\nAvailability Oracle: 0xc6e7df5e7b4f2a278906862b61205850344d4e7d","module":"aztec:node","timestamp":"2024-08-21T02:15:29.746Z"}
{"level":"info","message":"Creating ephemeral data store","module":"aztec:kv-store","timestamp":"2024-08-21T02:15:29.753Z"}
{"level":"info","message":"Creating ephemeral data store","module":"aztec:kv-store","timestamp":"2024-08-21T02:15:29.760Z"}
{"level":"info","message":"Added contract ContractClassRegisterer at 0x05d15342d76e46e5be07d3cda0d753158431cdc5e39d29ce4e8fe1f5c070564a","module":"aztec:pxe_service","timestamp":"2024-08-21T02:15:29.795Z"}
{"level":"info","message":"Added contract ContractInstanceDeployer at 0x2ab1a2bd6d07d8d61ea56d85861446349e52c6b7c0612b702cb1e6db6ad0b089","module":"aztec:pxe_service","timestamp":"2024-08-21T02:15:29.802Z"}
{"level":"info","message":"Added contract MultiCallEntrypoint at 0x0e028bd5acf2e33f647132af47ce05a37a022c3f7a51bb426271bd6764bc0aaf","module":"aztec:pxe_service","timestamp":"2024-08-21T02:15:29.811Z"}
{"level":"info","message":"Added contract FeeJuice at 0x16a83e3395bc921a2441db55dce24f0e0932636901a2e676fa68b9b2b9a644c1","module":"aztec:pxe_service","timestamp":"2024-08-21T02:15:29.820Z"}
{"level":"info","message":"Added contract NewKeyRegistry at 0x2ee3f8c67efa88f9e6fb44242f1e9dcc0f9a6752ded07af0d9fac3875a61d421","module":"aztec:pxe_service","timestamp":"2024-08-21T02:15:29.827Z"}
{"level":"info","message":"Added contract AuthRegistry at 0x24877c50868f86712240eb535d90d1c97403d074805dd3758c3aecb02958f8d4","module":"aztec:pxe_service","timestamp":"2024-08-21T02:15:29.834Z"}
{"level":"info","message":"Initial sync complete","module":"aztec:pxe_synchronizer","timestamp":"2024-08-21T02:15:29.836Z"}
{"level":"info","message":"Started PXE connected to chain 31337 version 1","module":"aztec:pxe_service","timestamp":"2024-08-21T02:15:29.849Z"}
{"level":"info","message":"Aztec Server listening on port 8080","module":"aztec:cli","timestamp":"2024-08-21T02:15:29.852Z"}
{"level":"info","message":"Shutting down...","module":"aztec:cli","timestamp":"2024-08-21T02:15:49.618Z"}
```

yarn-project/aztec/src/cli/cli.ts

@@ -7,6 +7,7 @@ import { createPXERpcServer } from '@aztec/pxe';
 import { Command } from 'commander';
 import http from 'http';
 
+import { setupConsoleJsonLog } from '../logging.js';
 import { createSandbox } from '../sandbox.js';
 import { github, splash } from '../splash.js';
 import { aztecStartOptions } from './aztec_start_options.js';
@@ -36,6 +37,11 @@ export function injectAztecCommands(program: Command, userLog: LogFn, debugLogge
   startCmd.helpInformation = printAztecStartHelpText;
 
   startCmd.action(async options => {
+    // setup json logging
+    if (['1', 'true', 'TRUE'].includes(process.env.LOG_JSON ?? '')) {
+      setupConsoleJsonLog();
+    }
+
     // list of 'stop' functions to call when process ends
     const signalHandlers: Array<() => Promise<void>> = [];
     let services: ServerList = [];
@@ -112,7 +118,7 @@ export function injectAztecCommands(program: Command, userLog: LogFn, debugLogge
 
       const httpServer = http.createServer(app.callback());
       httpServer.listen(options.port);
-      userLog(`Aztec Server listening on port ${options.port}`);
+      debugLogger.info(`Aztec Server listening on port ${options.port}`);
     }
   });
 

yarn-project/aztec/src/logging.ts

@@ -1,4 +1,4 @@
-import { onLog } from '@aztec/foundation/log';
+import { onLog, setLevel } from '@aztec/foundation/log';
 
 import * as path from 'path';
 import * as process from 'process';
@@ -10,7 +10,7 @@ const CURRENT_LOG_FILE_NAME = 'aztec.debug.log';
 const LOG_DIR = 'log';
 
 /** Creates a winston logger that logs everything to a local rotating file */
-function createWinstonLogger() {
+function createWinstonLocalFileLogger() {
   // See https://www.npmjs.com/package/winston-daily-rotate-file#user-content-options
   const transport: DailyRotateFile = new DailyRotateFile({
     filename: 'aztec-%DATE%.debug.log',
@@ -30,15 +30,34 @@ function createWinstonLogger() {
   });
 }
 
+/** Creates a winston logger that logs everything to stdout in json format */
+function createWinstonJsonStdoutLogger() {
+  return winston.createLogger({
+    level: process.env.LOG_LEVEL ?? 'info',
+    transports: [new winston.transports.Console({ 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, message, data) => {
-    logger.log({ ...data, level, namespace, message });
+  const logger = createWinstonLocalFileLogger();
+  onLog((level, module, message, data) => {
+    logger.log({ ...data, level, module, message });
   });
   const workdir = process.env.HOST_WORKDIR ?? process.cwd();
   return path.join(workdir, LOG_DIR, CURRENT_LOG_FILE_NAME);
 }
+
+/**
+ * Silences the foundation stdout logger and funnels all logs through a winston JSON logger.
+ */
+export function setupConsoleJsonLog() {
+  const logger = createWinstonJsonStdoutLogger();
+  setLevel('silent');
+  onLog((level, module, message, data) => {
+    logger.log({ ...data, level, module, message });
+  });
+}

yarn-project/aztec/terraform/bot/main.tf

@@ -172,7 +172,8 @@ resource "aws_ecs_task_definition" "aztec-bot" {
         { name = "PXE_PROVER_ENABLED", value = tostring(var.PROVING_ENABLED) },
         { name = "NETWORK", value = var.DEPLOY_TAG },
         { name = "BOT_FLUSH_SETUP_TRANSACTIONS", value = tostring(var.BOT_FLUSH_SETUP_TRANSACTIONS) },
-        { name = "BOT_MAX_PENDING_TXS", value = tostring(var.BOT_MAX_PENDING_TXS) }
+        { name = "BOT_MAX_PENDING_TXS", value = tostring(var.BOT_MAX_PENDING_TXS) },
+        { name = "LOG_JSON", value = "1" }
       ]
       logConfiguration = {
         logDriver = "awslogs"

yarn-project/aztec/terraform/node/main.tf

@@ -356,6 +356,10 @@ resource "aws_ecs_task_definition" "aztec-node" {
           name  = "LOG_LEVEL"
           value = "info"
         },
+        {
+          name  = "LOG_JSON",
+          value = "1"
+        },
         {
           name  = "NETWORK_NAME",
           value = "${var.DEPLOY_TAG}"

yarn-project/aztec/terraform/prover-node/main.tf

@@ -171,6 +171,7 @@ resource "aws_ecs_task_definition" "aztec-prover-node" {
         // General
         { name = "NODE_ENV", value = "production" },
         { name = "LOG_LEVEL", value = "verbose" },
+        { name = "LOG_JSON", value = "1" },
         { name = "DEBUG", value = "aztec:*,-json-rpc:json_proxy:*,-aztec:avm_simulator:*" },
         { name = "DEPLOY_TAG", value = var.DEPLOY_TAG },
         { name = "NETWORK_NAME", value = "${var.DEPLOY_TAG}" },

yarn-project/aztec/terraform/prover/main.tf

@@ -284,6 +284,10 @@ resource "aws_ecs_task_definition" "aztec-proving-agent" {
       {
         "name": "NETWORK_NAME",
         "value": "${var.DEPLOY_TAG}"
+      },
+      { 
+        "name": "LOG_JSON", 
+        "value": "1" 
       }
     ],
     "logConfiguration": {

yarn-project/aztec/terraform/pxe/main.tf

@@ -150,6 +150,10 @@ resource "aws_ecs_task_definition" "aztec-pxe" {
         {
           name  = "PXE_PROVER_ENABLED"
           value = tostring(var.PROVING_ENABLED)
+        },
+        {
+          name  = "LOG_JSON"
+          value = "1"
         }
       ]
       mountPoints = [

yarn-project/foundation/src/config/env_var.ts

@@ -80,6 +80,7 @@ export type EnvVar =
   | 'PROVER_TEST_DELAY_MS'
   | 'TX_PROVIDER_NODE_URL'
   | 'TXE_PORT'
+  | 'LOG_JSON'
   | 'BOT_PXE_URL'
   | 'BOT_PRIVATE_KEY'
   | 'BOT_RECIPIENT_ENCRYPTION_SECRET'

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

@@ -12,7 +12,7 @@ const DefaultLogLevel = process.env.NODE_ENV === 'test' ? ('silent' as const) :
 export type LogLevel = (typeof LogLevels)[number];
 
 const envLogLevel = process.env.LOG_LEVEL?.toLowerCase() as LogLevel;
-export const currentLevel = LogLevels.includes(envLogLevel) ? envLogLevel : DefaultLogLevel;
+export let currentLevel = LogLevels.includes(envLogLevel) ? envLogLevel : DefaultLogLevel;
 
 const namespaces = process.env.DEBUG ?? 'aztec:*';
 debug.enable(namespaces);
@@ -65,6 +65,11 @@ export function onLog(handler: LogHandler) {
   logHandlers.push(handler);
 }
 
+/** Overrides current log level. */
+export function setLevel(level: LogLevel) {
+  currentLevel = level;
+}
+
 /**
  * Logs args to npm debug if enabled or log level is debug, console.error otherwise.
  * @param debug - Instance of npm debug.