chore: small logging changes (#5654)

* Use environment LOG_LEVEL if defined, otherwise verbose (this lets you run `LOG_LEVEL=sth yarn test src/e2e_test`)
* Small changes and additions of logging to AVM/public.

yarn-project/end-to-end/package.json

@@ -15,7 +15,7 @@
     "clean": "rm -rf ./dest .tsbuildinfo",
     "formatting": "run -T prettier --check ./src \"!src/web/main.js\" && run -T eslint ./src",
     "formatting:fix": "run -T eslint --fix ./src && run -T prettier -w ./src",
-    "test": "LOG_LEVEL=verbose NODE_NO_WARNINGS=1 node --experimental-vm-modules ../node_modules/.bin/jest --runInBand --testTimeout=60000 --forceExit",
+    "test": "LOG_LEVEL=${LOG_LEVEL:-verbose} NODE_NO_WARNINGS=1 node --experimental-vm-modules ../node_modules/.bin/jest --runInBand --testTimeout=60000 --forceExit",
     "test:integration": "concurrently -k -s first -c reset,dim -n test,anvil \"yarn test:integration:run\" \"anvil\"",
     "test:integration:run": "NODE_NO_WARNINGS=1 node --experimental-vm-modules ../node_modules/.bin/jest --no-cache --runInBand --config jest.integration.config.json"
   },

yarn-project/end-to-end/package.local.json

@@ -2,6 +2,6 @@
   "scripts": {
     "build": "yarn clean && tsc -b && webpack",
     "formatting": "run -T prettier --check ./src \"!src/web/main.js\" && run -T eslint ./src",
-    "test": "LOG_LEVEL=verbose NODE_NO_WARNINGS=1 node --experimental-vm-modules ../node_modules/.bin/jest --runInBand --testTimeout=60000 --forceExit"
+    "test": "LOG_LEVEL=${LOG_LEVEL:-verbose} NODE_NO_WARNINGS=1 node --experimental-vm-modules ../node_modules/.bin/jest --runInBand --testTimeout=60000 --forceExit"
   }
 }

yarn-project/simulator/src/acvm/acvm.ts

@@ -95,7 +95,7 @@ export async function acvm(
     initialWitness,
     async (name: string, args: ForeignCallInput[]) => {
       try {
-        logger.verbose(`Oracle callback ${name}`);
+        logger.debug(`Oracle callback ${name}`);
         const oracleFunction = callback[name as ORACLE_NAMES];
         if (!oracleFunction) {
           throw new Error(`Oracle callback ${name} not found`);

yarn-project/simulator/src/avm/avm_memory_types.ts

@@ -240,7 +240,7 @@ export class TaggedMemory implements TaggedMemoryInterface {
     const word = this._mem[offset];
     TaggedMemory.log.debug(`get(${offset}) = ${word}`);
     if (word === undefined) {
-      TaggedMemory.log.warn(`Memory at offset ${offset} is undefined! This might be OK if it's stack dumping.`);
+      TaggedMemory.log.debug(`WARNING: Memory at offset ${offset} is undefined!`);
     }
     return word as T;
   }

yarn-project/simulator/src/avm/avm_simulator.ts

@@ -62,7 +62,7 @@ export class AvmSimulator {
         );
 
         const gasLeft = `l1=${machineState.l1GasLeft} l2=${machineState.l2GasLeft} da=${machineState.daGasLeft}`;
-        this.log.debug(`@${machineState.pc} (${gasLeft}) ${instruction.toString()}`);
+        this.log.debug(`@${machineState.pc} ${instruction.toString()} (${gasLeft})`);
         // Execute the instruction.
         // Normal returns and reverts will return normally here.
         // "Exceptional halts" will throw.

yarn-project/simulator/src/avm/journal/journal.ts

@@ -2,6 +2,7 @@ import { UnencryptedL2Log } from '@aztec/circuit-types';
 import { AztecAddress, EthAddress, L2ToL1Message } from '@aztec/circuits.js';
 import { EventSelector } from '@aztec/foundation/abi';
 import { Fr } from '@aztec/foundation/fields';
+import { type DebugLogger, createDebugLogger } from '@aztec/foundation/log';
 
 import { type HostStorage } from './host_storage.js';
 import { Nullifiers } from './nullifiers.js';
@@ -47,6 +48,7 @@ export type JournalData = {
  * Manages merging of successful/reverted child state into current state.
  */
 export class AvmPersistableStateManager {
+  private readonly log: DebugLogger = createDebugLogger('aztec:avm_simulator:state_manager');
   /** Reference to node storage */
   public readonly hostStorage: HostStorage;
 
@@ -86,6 +88,7 @@ export class AvmPersistableStateManager {
    * @param value - the value being written to the slot
    */
   public writeStorage(storageAddress: Fr, slot: Fr, value: Fr) {
+    this.log.debug(`storage(${storageAddress})@${slot} <- ${value}`);
     // Cache storage writes for later reference/reads
     this.publicStorage.write(storageAddress, slot, value);
     // Trace all storage writes (even reverted ones)
@@ -101,6 +104,7 @@ export class AvmPersistableStateManager {
    */
   public async readStorage(storageAddress: Fr, slot: Fr): Promise<Fr> {
     const [exists, value] = await this.publicStorage.read(storageAddress, slot);
+    this.log.debug(`storage(${storageAddress})@${slot} ?? value: ${value}, exists: ${exists}.`);
     // We want to keep track of all performed reads (even reverted ones)
     this.trace.tracePublicStorageRead(storageAddress, slot, value, exists);
     return Promise.resolve(value);
@@ -118,6 +122,7 @@ export class AvmPersistableStateManager {
   public async checkNoteHashExists(storageAddress: Fr, noteHash: Fr, leafIndex: Fr): Promise<boolean> {
     const gotLeafIndex = await this.hostStorage.commitmentsDb.getCommitmentIndex(noteHash);
     const exists = gotLeafIndex === leafIndex.toBigInt();
+    this.log.debug(`noteHashes(${storageAddress})@${noteHash} ?? leafIndex: ${leafIndex}, exists: ${exists}.`);
     this.trace.traceNoteHashCheck(storageAddress, noteHash, exists, leafIndex);
     return Promise.resolve(exists);
   }
@@ -127,6 +132,7 @@ export class AvmPersistableStateManager {
    * @param noteHash - the unsiloed note hash to write
    */
   public writeNoteHash(storageAddress: Fr, noteHash: Fr) {
+    this.log.debug(`noteHashes(${storageAddress}) += @${noteHash}.`);
     this.trace.traceNewNoteHash(storageAddress, noteHash);
   }
 
@@ -138,6 +144,9 @@ export class AvmPersistableStateManager {
    */
   public async checkNullifierExists(storageAddress: Fr, nullifier: Fr): Promise<boolean> {
     const [exists, isPending, leafIndex] = await this.nullifiers.checkExists(storageAddress, nullifier);
+    this.log.debug(
+      `nullifiers(${storageAddress})@${nullifier} ?? leafIndex: ${leafIndex}, pending: ${isPending}, exists: ${exists}.`,
+    );
     this.trace.traceNullifierCheck(storageAddress, nullifier, exists, isPending, leafIndex);
     return Promise.resolve(exists);
   }
@@ -148,6 +157,7 @@ export class AvmPersistableStateManager {
    * @param nullifier - the unsiloed nullifier to write
    */
   public async writeNullifier(storageAddress: Fr, nullifier: Fr) {
+    this.log.debug(`nullifiers(${storageAddress}) += ${nullifier}.`);
     // Cache pending nullifiers for later access
     await this.nullifiers.append(storageAddress, nullifier);
     // Trace all nullifier creations (even reverted ones)
@@ -178,6 +188,7 @@ export class AvmPersistableStateManager {
       // error getting message - doesn't exist!
       exists = false;
     }
+    this.log.debug(`l1ToL2Messages(${msgHash})@${msgLeafIndex} ?? exists: ${exists}.`);
     this.trace.traceL1ToL2MessageCheck(msgHash, msgLeafIndex, exists);
     return Promise.resolve(exists);
   }
@@ -188,11 +199,13 @@ export class AvmPersistableStateManager {
    * @param content - Message content.
    */
   public writeL1Message(recipient: EthAddress | Fr, content: Fr) {
+    this.log.debug(`L1Messages(${recipient}) += ${content}.`);
     const recipientAddress = recipient instanceof EthAddress ? recipient : EthAddress.fromField(recipient);
     this.newL1Messages.push(new L2ToL1Message(recipientAddress, content));
   }
 
   public writeLog(contractAddress: Fr, event: Fr, log: Fr[]) {
+    this.log.debug(`UnencryptedL2Log(${contractAddress}) += event ${event} with ${log.length} fields.`);
     this.newLogs.push(
       new UnencryptedL2Log(
         AztecAddress.fromField(contractAddress),

yarn-project/simulator/src/public/executor.ts

@@ -75,7 +75,9 @@ async function executePublicFunctionAvm(executionContext: PublicExecutionContext
   const result = await simulator.execute();
   const newWorldState = context.persistableState.flush();
 
-  log.verbose(`[AVM] ${address.toString()}:${selector} returned, reverted: ${result.reverted}.`);
+  log.verbose(
+    `[AVM] ${address.toString()}:${selector} returned, reverted: ${result.reverted}, reason: ${result.revertReason}.`,
+  );
 
   // TODO(@spalladino) Read gas left from machineState and return it
   return await convertAvmResults(executionContext, newWorldState, result);