chore!: Remove debug and winston in favor of pino (#10355)

First steps for logging cleanup. Removes all traces of `debug` and `winston` in favor of `pino`. Fixes #10118 ## Breaking changes - `DEBUG` variable is no longer used. Instead, overloads `LOG_LEVEL` by allowing a list of modules to have non-default log levels. For example, `LOG_LEVEL="info; verbose: aztec:sequencer, aztec:archiver; debug: aztec:kv-store"` sets `info` as the default log level, `verbose` for the sequencer and archiver, and `debug` for the kv-store. Match is by prefix. ## Levels Defines the following logging levels, all of them standard in pino, except for `verbose` which we already used extensively before: - fatal: Use when an error has brought down the system. - error: Use for errors in general. - warn: Use for when we stray from the happy path. - info: Use for providing an operator with info on what the system is doing. - verbose: Use for when we need additional insight on what a subsystem is doing. - debug: Use for when we need debugging info to troubleshoot an issue on a specific component. - trace: Use for when we want to denial-of-service any recipient of the logs. Fixes #10116 ## Filtering Removes usage of the `DEBUG` env var for log filtering. Instead, overloads `LOG_LEVEL` by allowing a list of modules to have non-default log levels. For example, `LOG_LEVEL="info; verbose: aztec:sequencer, aztec:archiver; debug: aztec:kv-store"` sets `info` as the default log level, `verbose` for the sequencer and archiver, and `debug` for the kv-store. Match is by prefix. Fixes #10119 ## OTEL integration Vendors the OTEL pino stream from `openetelemetry/instrumentation-pino` and configures it as an additional transport if the `OTEL_EXPORTER_OTLP_LOGS_ENDPOINT` env var is set. Using the instrumentation-pino directly would have required buying in fully into the opentelemetry node sdk, which we preferred to avoid so we have more fine-grained control, and it also pollutes the main worker thread. Instead, we vendor the stream code and initialize it within a transport, which runs it on a worker thread. As for log correlation, instead of having `instrumentation-pino` monkey-patch pino, we wrap the call to the logger to manually inject the trace and span id, which ensures that tempo can load the relevant logs for a trace in loki. https://github.com/user-attachments/assets/9421a22f-4c5a-49f7-80da-ab3e14d323ba Fixes #10121 Fixes #10123 ## Pretty logs Pino logs to json by default, but if `LOG_JSON` is not set, we programmatically set up `pino-pretty` for console logging. Looks like this: ![image](https://github.com/user-attachments/assets/3d547a25-b5a7-49b8-b4a3-9be00e1fa268) Fixes #10126 ## DEBUG settings Given we no longer use `DEBUG`, we remove this variable from most scripts. Since we were using modules to silence some noisy namespaces, we tweak those calls to be passed as `trace` instead, so we can enable debug without fear of being bombarded. For reference, the default `DEBUG` string used in scripts was: ``` aztec:*,-aztec:avm_simulator*,-aztec:libp2p_service*,-aztec:circuits:artifact_hash,-json-rpc*,-aztec:world-state:database,-aztec:l2_block_stream* ``` --------- Co-authored-by: Mitch <[email protected]>
AztecProtocol · Dec 5, 2024 · c246aba · c246aba
1 parent 5299481
commit c246aba
Show file tree

Hide file tree

Showing 84 changed files with 1,092 additions and 978 deletions.
diff --git a/README.md b/README.md
@@ -47,7 +47,7 @@ This provide an interactive environment for debugging the CI test.
 
 ## Debugging
 
-Logging goes through the [DebugLogger](yarn-project/foundation/src/log/debug.ts) module in Typescript. To see the log output, set a `DEBUG` environment variable to the name of the module you want to debug, to `aztec:*`, or to `*` to see all logs.
+Logging goes through the [DebugLogger](yarn-project/foundation/src/log/debug.ts) module in Typescript. `LOG_LEVEL` controls the default log level, and one can set alternate levels for specific modules, such as `debug; warn: module1, module2; error: module3`.
 
 ## Releases
 

diff --git a/aztec-up/bin/.aztec-run b/aztec-up/bin/.aztec-run
@@ -104,8 +104,8 @@ while [[ "$#" -gt 0 ]]; do
 done
 
 DOCKER_ENV="-e HOME=$HOME"
-if ! [ -z "${DEBUG:-}" ] ; then
-  DOCKER_ENV="-e DEBUG=$DEBUG"
+if ! [ -z "${LOG_LEVEL:-}" ] ; then
+  DOCKER_ENV="-e LOG_LEVEL=$LOG_LEVEL"
 fi
 for env in ${ENV_VARS_TO_INJECT:-}; do
   # SSH_AUTH_SOCK must be handled separately

diff --git a/aztec-up/bin/docker-compose.sandbox.yml b/aztec-up/bin/docker-compose.sandbox.yml
@@ -20,7 +20,7 @@ services:
     ports:
       - "${PXE_PORT:-8080}:${PXE_PORT:-8080}"
     environment:
-      DEBUG: # Loaded from the user shell if explicitly set
+      LOG_LEVEL: # 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: ${ETHEREUM_HOST:-http://ethereum}:${ANVIL_PORT:-8545}
       L1_CHAIN_ID: 31337

diff --git a/aztec-up/bin/docker-compose.test.yml b/aztec-up/bin/docker-compose.test.yml
@@ -2,7 +2,6 @@ services:
   txe:
     image: "aztecprotocol/aztec"
     environment:
-      DEBUG: # Loaded from the user shell if explicitly set
       LOG_LEVEL: # Loaded from the user shell if explicitly set
       HOST_WORKDIR: "${PWD}" # Loaded from the user shell to show log files absolute path in host
     volumes:

diff --git a/docker-compose.yml b/docker-compose.yml
@@ -6,8 +6,6 @@ services:
     platform: linux/amd64
     environment:
       LOG_LEVEL: ${LOG_LEVEL:-info}
-      DEBUG: ${DEBUG:-aztec:*,-json-rpc:*,-aztec:circuits:artifact_hash,-aztec:randomness_singleton}
-      DEBUG_COLORS: 1
       L1_CHAIN_ID: 31337
       VERSION: 1
       PXE_PROVER_ENABLED: ${PXE_PROVER_ENABLED:-1}
@@ -38,8 +36,6 @@ services:
     platform: linux/amd64
     environment:
       LOG_LEVEL: ${LOG_LEVEL:-info}
-      DEBUG: ${DEBUG:-aztec:*,-json-rpc:*,-aztec:circuits:artifact_hash,-aztec:randomness_singleton,-aztec:avm_simulator:*}
-      DEBUG_COLORS: 1
       L1_CHAIN_ID: 31337
       VERSION: 1
       NODE_NO_WARNINGS: 1

diff --git a/docs/docs/migration_notes.md b/docs/docs/migration_notes.md
@@ -6,6 +6,35 @@ keywords: [sandbox, aztec, notes, migration, updating, upgrading]
 
 Aztec is in full-speed development. Literally every version breaks compatibility with the previous ones. This page attempts to target errors and difficulties you might encounter when upgrading, and how to resolve them.
 
+## 0.66
+
+### DEBUG env var is removed
+
+The `DEBUG` variable is no longer used. Use `LOG_LEVEL` with one of `silent`, `fatal`, `error`, `warn`, `info`, `verbose`, `debug`, or `trace`. To tweak log levels per module, add a list of module prefixes with their overridden level. For example, LOG_LEVEL="info; verbose: aztec:sequencer, aztec:archiver; debug: aztec:kv-store" sets `info` as the default log level, `verbose` for the sequencer and archiver, and `debug` for the kv-store. Module name match is done by prefix.
+
+### `tty` resolve fallback required for browser bundling
+
+When bundling `aztec.js` for web, the `tty` package now needs to be specified as an empty fallback:
+
+```diff
+resolve: {
+  plugins: [new ResolveTypeScriptPlugin()],
+  alias: { './node/index.js': false },
+  fallback: {
+    crypto: false,
+    os: false,
+    fs: false,
+    path: false,
+    url: false,
++   tty: false,
+    worker_threads: false,
+    buffer: require.resolve('buffer/'),
+    util: require.resolve('util/'),
+    stream: require.resolve('stream-browserify'),
+  },
+},
+```
+
 ## 0.65
 
 ### [aztec.nr] Removed SharedImmutable

diff --git a/docs/docs/reference/developer_references/debugging.md b/docs/docs/reference/developer_references/debugging.md
@@ -53,7 +53,7 @@ debug_log_array(my_array);
 
 ### Start Sandbox in debug mode
 
-Update the `DEBUG` environment variable in docker-compose.sandbox.yml to the following:
+Set `LOG_LEVEL` to `verbose` or `debug`:
 
 ```yml
 # ~/.aztec/docker-compose.sandbox.yml
@@ -65,8 +65,7 @@ aztec:
   ports:
     - "${PXE_PORT:-8080}:${PXE_PORT:-8080}"
   environment:
-    DEBUG: aztec:simulator:client_execution_context, aztec:sandbox, aztec:avm_simulator:debug_log
-    LOG_LEVEL: verbose # optionally add this for more logs
+    LOG_LEVEL: verbose
   # ...
 ```
 

diff --git a/spartan/aztec-network/templates/deploy-l1-verifier.yaml b/spartan/aztec-network/templates/deploy-l1-verifier.yaml
@@ -62,8 +62,6 @@ spec:
           env:
             - name: NODE_NO_WARNINGS
               value: "1"
-            - name: DEBUG
-              value: "aztec:*"
             - name: LOG_LEVEL
               value: "debug"
             - name: L1_CHAIN_ID

diff --git a/spartan/aztec-network/templates/prover-agent.yaml b/spartan/aztec-network/templates/prover-agent.yaml
@@ -85,8 +85,6 @@ spec:
               value: "{{ .Values.proverAgent.logLevel }}"
             - name: LOG_JSON
               value: "1"
-            - name: DEBUG
-              value: "{{ .Values.proverAgent.debug }}"
             - name: PROVER_REAL_PROOFS
               value: "{{ .Values.aztec.realProofs }}"
             - name: PROVER_AGENT_COUNT

diff --git a/spartan/aztec-network/templates/prover-broker.yaml b/spartan/aztec-network/templates/prover-broker.yaml
@@ -66,8 +66,6 @@ spec:
               value: "{{ .Values.proverBroker.logLevel }}"
             - name: LOG_JSON
               value: "1"
-            - name: DEBUG
-              value: "{{ .Values.proverBroker.debug }}"
             - name: PROVER_BROKER_POLL_INTERVAL_MS
               value: "{{ .Values.proverBroker.pollIntervalMs }}"
             - name: PROVER_BROKER_JOB_TIMEOUT_MS

diff --git a/spartan/aztec-network/templates/pxe.yaml b/spartan/aztec-network/templates/pxe.yaml
@@ -84,8 +84,6 @@ spec:
               value: "1"
             - name: LOG_LEVEL
               value: "{{ .Values.pxe.logLevel }}"
-            - name: DEBUG
-              value: "{{ .Values.pxe.debug }}"
             - name: PXE_PROVER_ENABLED
               value: "{{ .Values.aztec.realProofs }}"
           ports:

diff --git a/spartan/aztec-network/templates/setup-l2-contracts.yaml b/spartan/aztec-network/templates/setup-l2-contracts.yaml
@@ -61,8 +61,6 @@ spec:
               node --no-warnings /usr/src/yarn-project/aztec/dest/bin/index.js setup-protocol-contracts --skipProofWait --l1-chain-id {{ .Values.ethereum.chainId }}
               echo "L2 contracts initialized"
           env:
-            - name: DEBUG
-              value: "aztec:*"
             - name: LOG_LEVEL
               value: "debug"
             - name: NETWORK_PUBLIC

diff --git a/spartan/aztec-network/templates/transaction-bot.yaml b/spartan/aztec-network/templates/transaction-bot.yaml
@@ -79,8 +79,6 @@ spec:
               value: "1"
             - name: LOG_LEVEL
               value: "{{ .Values.bot.logLevel }}"
-            - name: DEBUG
-              value: "{{ .Values.bot.debug }}"
             - name: BOT_PRIVATE_KEY
               value: "{{ .Values.bot.botPrivateKey }}"
             - name: BOT_TX_INTERVAL_SECONDS

diff --git a/spartan/aztec-network/values.yaml b/spartan/aztec-network/values.yaml
@@ -45,7 +45,7 @@ bootNode:
     p2pUdpPort: 40400
     nodePort: 8080
   logLevel: "debug"
-  debug: "aztec:*,-aztec:avm_simulator*,-aztec:libp2p_service*,-aztec:circuits:artifact_hash,-json-rpc*,-aztec:world-state:database,-aztec:l2_block_stream*"
+  debug: ""
   coinbaseAddress: "0xaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
   sequencer:
     maxSecondsBetweenBlocks: 0
@@ -88,7 +88,7 @@ validator:
     p2pUdpPort: 40400
     nodePort: 8080
   logLevel: "debug"
-  debug: "aztec:*,-aztec:avm_simulator*,-aztec:libp2p_service*,-aztec:circuits:artifact_hash,-json-rpc*,-aztec:world-state:database,-aztec:l2_block_stream*"
+  debug: ""
   sequencer:
     maxSecondsBetweenBlocks: 0
     minTxsPerBlock: 1
@@ -118,7 +118,7 @@ proverNode:
     p2pUdpPort: 40400
     nodePort: 8080
   logLevel: "debug"
-  debug: "aztec:*,-aztec:avm_simulator*,-aztec:libp2p_service*,-aztec:circuits:artifact_hash,-json-rpc*,-aztec:world-state:database,-aztec:l2_block_stream*"
+  debug: ""
   proverAgent:
     count: 0
     pollIntervalMs: 1000
@@ -137,7 +137,6 @@ proverNode:
 
 pxe:
   logLevel: "debug"
-  debug: "aztec:*,-aztec:avm_simulator*,-aztec:libp2p_service*,-aztec:circuits:artifact_hash,-json-rpc*,-aztec:world-state:database,-aztec:l2_block_stream*"
   replicas: 1
   service:
     nodePort: 8081
@@ -156,7 +155,6 @@ bot:
   enabled: true
   nodeUrl: ""
   logLevel: "debug"
-  debug: "aztec:*,-aztec:avm_simulator*,-aztec:libp2p_service*,-aztec:circuits:artifact_hash,-json-rpc*,-aztec:l2_block_stream,-aztec:world-state:database"
   replicas: 1
   botPrivateKey: "0xcafe"
   txIntervalSeconds: 24
@@ -217,7 +215,6 @@ proverAgent:
   gke:
     spotEnabled: false
   logLevel: "debug"
-  debug: "aztec:*,-aztec:avm_simulator*,-aztec:libp2p_service*,-aztec:circuits:artifact_hash,-json-rpc*,-aztec:world-state:database,-aztec:l2_block_stream*"
   bb:
     hardwareConcurrency: ""
   nodeSelector: {}
@@ -233,7 +230,6 @@ proverBroker:
   jobMaxRetries: 3
   dataDirectory: ""
   logLevel: "debug"
-  debug: "aztec:*,-aztec:avm_simulator*,-aztec:libp2p_service*,-aztec:circuits:artifact_hash,-json-rpc*,-aztec:world-state:database,-aztec:l2_block_stream*"
   nodeSelector: {}
   resources: {}
 

diff --git a/spartan/aztec-network/values/prover-node-with-agents.yaml b/spartan/aztec-network/values/prover-node-with-agents.yaml
@@ -12,7 +12,7 @@ validator:
   external: true
 
 bootNode:
-  debug: "aztec:*,-aztec:avm_simulator:*,-aztec:world-state:database,discv5:*,-JsonProxy:*"
+  debug: "discv5:*"
   validator:
     disabled: true
 

diff --git a/spartan/releases/rough-rhino/aztec-spartan.sh b/spartan/releases/rough-rhino/aztec-spartan.sh
@@ -178,7 +178,6 @@ services:
             - VALIDATOR_PRIVATE_KEY=${KEY}
             - SEQ_PUBLISHER_PRIVATE_KEY=${KEY}
             - L1_PRIVATE_KEY=${KEY}
-            - DEBUG=aztec:*,-aztec:avm_simulator*,-aztec:circuits:artifact_hash,-aztec:libp2p_service,-json-rpc*,-aztec:world-state:database,-aztec:l2_block_stream*
             - LOG_LEVEL=debug
             - AZTEC_PORT=${PORT}
             - P2P_ENABLED=true

diff --git a/spartan/testnet-runbook.md b/spartan/testnet-runbook.md
@@ -45,7 +45,6 @@ Verbose logging on Aztec nodes should be enabled by default using the following
 
 - `LOG_JSON=1`
 - `LOG_LEVEL=debug`
-- `DEBUG=discv5*,aztec:*,-aztec:avm_simulator*,-aztec:circuits:artifact_hash,-json-rpc*,-aztec:world-state:database,-aztec:l2_block_stream*`
 
 Deployments are initiated from CI by manually running the (_name pending_) workflow.
 

diff --git a/yarn-project/Earthfile b/yarn-project/Earthfile
@@ -302,15 +302,16 @@ test:
 
 run-e2e:
     ARG test
+    ARG log_level=""
     ARG debug=""
     FROM +end-to-end
-    RUN DEBUG=$debug yarn test $test
+    RUN DEBUG=$debug LOG_LEVEL=$log_level yarn test $test
 
 prover-client-test:
     FROM +build
     ARG test
-    ARG debug=""
-    RUN cd prover-client && DEBUG=$debug yarn test $test
+    ARG log_level=""
+    RUN cd prover-client && LOG_LEVEL=$log_level yarn test $test
 
 # NOTE: This is not in the end-to-end Earthfile as that is entirely LOCALLY commands that will go away sometime.
 # Running this inside the main builder as the point is not to run this through dockerization.

diff --git a/yarn-project/aztec-faucet/terraform/main.tf b/yarn-project/aztec-faucet/terraform/main.tf
@@ -107,8 +107,8 @@ resource "aws_ecs_task_definition" "aztec-faucet" {
           value = "80"
         },
         {
-          name  = "DEBUG",
-          value = "aztec:*"
+          name  = "LOG_LEVEL",
+          value = "verbose"
         },
         {
           name  = "RPC_URL",

diff --git a/yarn-project/aztec.js/src/index.ts b/yarn-project/aztec.js/src/index.ts
@@ -156,7 +156,7 @@ export { decodeFromAbi, encodeArguments, type AbiType } from '@aztec/foundation/
 export { toBigIntBE } from '@aztec/foundation/bigint-buffer';
 export { sha256 } from '@aztec/foundation/crypto';
 export { makeFetch } from '@aztec/foundation/json-rpc/client';
-export { createDebugLogger, onLog, type DebugLogger } from '@aztec/foundation/log';
+export { createDebugLogger, type DebugLogger } from '@aztec/foundation/log';
 export { retry, retryUntil } from '@aztec/foundation/retry';
 export { to2Fields, toBigInt } from '@aztec/foundation/serialize';
 export { sleep } from '@aztec/foundation/sleep';

diff --git a/yarn-project/aztec.js/webpack.config.js b/yarn-project/aztec.js/webpack.config.js
@@ -61,6 +61,7 @@ export default {
       fs: false,
       path: false,
       url: false,
+      tty: false,
       worker_threads: false,
       buffer: require.resolve('buffer/'),
       util: require.resolve('util/'),

diff --git a/yarn-project/aztec/docker-compose.yml b/yarn-project/aztec/docker-compose.yml
@@ -21,7 +21,7 @@ services:
     ports:
       - '${SANDBOX_PXE_PORT:-8080}:8080'
     environment:
-      DEBUG: # Loaded from the user shell if explicitly set
+      LOG_LEVEL: # 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
       L1_CHAIN_ID: 31337

diff --git a/yarn-project/aztec/package.json b/yarn-project/aztec/package.json
@@ -22,7 +22,7 @@
     "formatting:fix": "run -T eslint --fix ./src && run -T prettier -w ./src",
     "build:dev": "tsc -b --watch",
     "test": "NODE_NO_WARNINGS=1 node --experimental-vm-modules ../node_modules/.bin/jest --passWithNoTests",
-    "run:example:token": "DEBUG='aztec:*' node ./dest/examples/token.js"
+    "run:example:token": "LOG_LEVEL='verbose' node ./dest/examples/token.js"
   },
   "inherits": [
     "../package.common.json"
@@ -55,16 +55,13 @@
     "@aztec/telemetry-client": "workspace:^",
     "@aztec/txe": "workspace:^",
     "@aztec/types": "workspace:^",
-    "@opentelemetry/winston-transport": "^0.7.0",
     "@types/chalk": "^2.2.0",
     "abitype": "^0.8.11",
     "chalk": "^5.3.0",
     "commander": "^12.1.0",
     "koa": "^2.14.2",
     "koa-router": "^12.0.0",
-    "viem": "^2.7.15",
-    "winston": "^3.10.0",
-    "winston-daily-rotate-file": "^4.7.1"
+    "viem": "^2.7.15"
   },
   "files": [
     "dest",
@@ -117,4 +114,4 @@
   "engines": {
     "node": ">=18"
   }
-}
+}
diff --git a/yarn-project/aztec/src/cli/cli.ts b/yarn-project/aztec/src/cli/cli.ts
@@ -9,7 +9,6 @@ import { type DebugLogger, type LogFn } from '@aztec/foundation/log';
 
 import { Command } from 'commander';
 
-import { setupConsoleJsonLog } from '../logging.js';
 import { createSandbox } from '../sandbox.js';
 import { github, splash } from '../splash.js';
 import { aztecStartOptions } from './aztec_start_options.js';
@@ -39,11 +38,6 @@ 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>> = [];
     const services: NamespacedApiHandlers = {};