chore: Clean up archiver logs (#10429)

- Logs reorgs as warn - Logs every new L2 block downloaded as info - Logs messages and contracts retrieved as verbose - Logs everything else (including detailed block info) as debug Fixes #10428 as we log one entry per block synced --------- Co-authored-by: Mitch <[email protected]>
AztecProtocol · Dec 6, 2024 · 4fcbc59 · 4fcbc59
1 parent 3304046
commit 4fcbc59
Show file tree

Hide file tree

Showing 4 changed files with 74 additions and 46 deletions.
diff --git a/yarn-project/archiver/src/archiver/archiver.test.ts b/yarn-project/archiver/src/archiver/archiver.test.ts
@@ -255,7 +255,7 @@ describe('Archiver', () => {
   }, 10_000);
 
   it('skip event search if no changes found', async () => {
-    const loggerSpy = jest.spyOn((archiver as any).log, 'verbose');
+    const loggerSpy = jest.spyOn((archiver as any).log, 'debug');
 
     let latestBlockNum = await archiver.getBlockNumber();
     expect(latestBlockNum).toEqual(0);
@@ -294,15 +294,12 @@ describe('Archiver', () => {
     expect(latestBlockNum).toEqual(numL2BlocksInTest);
 
     // For some reason, this is 1-indexed.
-    expect(loggerSpy).toHaveBeenNthCalledWith(
-      1,
-      `Retrieved no new L1 -> L2 messages between L1 blocks ${1n} and ${50}.`,
-    );
-    expect(loggerSpy).toHaveBeenNthCalledWith(2, `No blocks to retrieve from ${1n} to ${50n}`);
+    expect(loggerSpy).toHaveBeenNthCalledWith(1, `Retrieved no new L1 to L2 messages between L1 blocks 1 and 50.`);
+    expect(loggerSpy).toHaveBeenNthCalledWith(2, `No blocks to retrieve from 1 to 50`);
   }, 10_000);
 
   it('handles L2 reorg', async () => {
-    const loggerSpy = jest.spyOn((archiver as any).log, 'verbose');
+    const loggerSpy = jest.spyOn((archiver as any).log, 'debug');
 
     let latestBlockNum = await archiver.getBlockNumber();
     expect(latestBlockNum).toEqual(0);
@@ -354,17 +351,13 @@ describe('Archiver', () => {
     expect(latestBlockNum).toEqual(numL2BlocksInTest);
 
     // For some reason, this is 1-indexed.
-    expect(loggerSpy).toHaveBeenNthCalledWith(
-      1,
-      `Retrieved no new L1 -> L2 messages between L1 blocks ${1n} and ${50}.`,
-    );
-    expect(loggerSpy).toHaveBeenNthCalledWith(2, `No blocks to retrieve from ${1n} to ${50n}`);
+    expect(loggerSpy).toHaveBeenNthCalledWith(1, `Retrieved no new L1 to L2 messages between L1 blocks 1 and 50.`);
+    expect(loggerSpy).toHaveBeenNthCalledWith(2, `No blocks to retrieve from 1 to 50`);
 
     // Lets take a look to see if we can find re-org stuff!
     await sleep(1000);
 
-    expect(loggerSpy).toHaveBeenNthCalledWith(6, `L2 prune have occurred, unwind state`);
-    expect(loggerSpy).toHaveBeenNthCalledWith(7, `Unwinding 1 block from block 2`);
+    expect(loggerSpy).toHaveBeenNthCalledWith(9, `L2 prune has been detected.`);
 
     // Should also see the block number be reduced
     latestBlockNum = await archiver.getBlockNumber();

diff --git a/yarn-project/archiver/src/archiver/archiver.ts b/yarn-project/archiver/src/archiver/archiver.ts
@@ -193,7 +193,6 @@ export class Archiver implements ArchiveSource {
     }
 
     if (blockUntilSynced) {
-      this.log.info(`Performing initial chain sync to rollup contract ${this.rollupAddress.toString()}`);
       await this.sync(blockUntilSynced);
     }
 
@@ -233,6 +232,15 @@ export class Archiver implements ArchiveSource {
     const { blocksSynchedTo = l1StartBlock, messagesSynchedTo = l1StartBlock } = await this.store.getSynchPoint();
     const currentL1BlockNumber = await this.publicClient.getBlockNumber();
 
+    if (blockUntilSynced) {
+      this.log.info(
+        `Starting archiver sync to rollup contract ${this.rollupAddress.toString()} from L1 block ${Math.min(
+          Number(blocksSynchedTo),
+          Number(messagesSynchedTo),
+        )} to current L1 block ${currentL1BlockNumber}`,
+      );
+    }
+
     // ********** Ensuring Consistency of data pulled from L1 **********
 
     /**
@@ -272,6 +280,10 @@ export class Archiver implements ArchiveSource {
       // up to which point we're pruning, and then requesting L2 blocks up to that point only.
       await this.handleEpochPrune(provenBlockNumber, currentL1BlockNumber);
     }
+
+    if (blockUntilSynced) {
+      this.log.info(`Initial archiver sync to L1 block ${currentL1BlockNumber} complete.`);
+    }
   }
 
   /** Checks if there'd be a reorg for the next block submission and start pruning now. */
@@ -286,13 +298,13 @@ export class Archiver implements ArchiveSource {
 
     if (canPrune) {
       const blocksToUnwind = localPendingBlockNumber - provenBlockNumber;
-      this.log.verbose(
-        `L2 prune will occur on next submission. ` +
-          `Unwinding ${count(blocksToUnwind, 'block')} from block ${localPendingBlockNumber} ` +
-          `to the last proven block ${provenBlockNumber}.`,
-      );
+      this.log.debug(`L2 prune will occur on next block submission.`);
       await this.store.unwindBlocks(Number(localPendingBlockNumber), Number(blocksToUnwind));
-      this.log.verbose(`Unwound ${count(blocksToUnwind, 'block')}. New L2 block is ${await this.getBlockNumber()}.`);
+      this.log.warn(
+        `Unwound ${count(blocksToUnwind, 'block')} from L2 block ${localPendingBlockNumber} ` +
+          `to ${provenBlockNumber} due to predicted reorg at L1 block ${currentL1BlockNumber}. ` +
+          `Updated L2 latest block is ${await this.getBlockNumber()}.`,
+      );
       // TODO(palla/reorg): Do we need to set the block synched L1 block number here?
       // Seems like the next iteration should handle this.
       // await this.store.setBlockSynchedL1BlockNumber(currentL1BlockNumber);
@@ -313,8 +325,8 @@ export class Archiver implements ArchiveSource {
 
     if (localTotalMessageCount === destinationTotalMessageCount) {
       await this.store.setMessageSynchedL1BlockNumber(currentL1BlockNumber);
-      this.log.verbose(
-        `Retrieved no new L1 -> L2 messages between L1 blocks ${messagesSynchedTo + 1n} and ${currentL1BlockNumber}.`,
+      this.log.debug(
+        `Retrieved no new L1 to L2 messages between L1 blocks ${messagesSynchedTo + 1n} and ${currentL1BlockNumber}.`,
       );
       return;
     }
@@ -329,7 +341,7 @@ export class Archiver implements ArchiveSource {
     await this.store.addL1ToL2Messages(retrievedL1ToL2Messages);
 
     this.log.verbose(
-      `Retrieved ${retrievedL1ToL2Messages.retrievedData.length} new L1 -> L2 messages between L1 blocks ${
+      `Retrieved ${retrievedL1ToL2Messages.retrievedData.length} new L1 to L2 messages between L1 blocks ${
         messagesSynchedTo + 1n
       } and ${currentL1BlockNumber}.`,
     );
@@ -356,10 +368,10 @@ export class Archiver implements ArchiveSource {
         localBlockForDestinationProvenBlockNumber &&
         provenArchive === localBlockForDestinationProvenBlockNumber.archive.root.toString()
       ) {
-        this.log.verbose(`Updating the proven block number to ${provenBlockNumber} and epoch to ${provenEpochNumber}`);
         await this.store.setProvenL2BlockNumber(Number(provenBlockNumber));
         // if we are here then we must have a valid proven epoch number
         await this.store.setProvenL2EpochNumber(Number(provenEpochNumber));
+        this.log.info(`Updated proven chain`, { provenBlockNumber, provenEpochNumber });
       }
       this.instrumentation.updateLastProvenBlock(Number(provenBlockNumber));
     };
@@ -369,7 +381,7 @@ export class Archiver implements ArchiveSource {
     const noBlocks = localPendingBlockNumber === 0n && pendingBlockNumber === 0n;
     if (noBlocks) {
       await this.store.setBlockSynchedL1BlockNumber(currentL1BlockNumber);
-      this.log.verbose(`No blocks to retrieve from ${blocksSynchedTo + 1n} to ${currentL1BlockNumber}`);
+      this.log.debug(`No blocks to retrieve from ${blocksSynchedTo + 1n} to ${currentL1BlockNumber}`);
       return { provenBlockNumber };
     }
 
@@ -386,7 +398,7 @@ export class Archiver implements ArchiveSource {
       const noBlockSinceLast = localPendingBlock && pendingArchive === localPendingBlock.archive.root.toString();
       if (noBlockSinceLast) {
         await this.store.setBlockSynchedL1BlockNumber(currentL1BlockNumber);
-        this.log.verbose(`No blocks to retrieve from ${blocksSynchedTo + 1n} to ${currentL1BlockNumber}`);
+        this.log.debug(`No blocks to retrieve from ${blocksSynchedTo + 1n} to ${currentL1BlockNumber}`);
         return { provenBlockNumber };
       }
 
@@ -396,7 +408,7 @@ export class Archiver implements ArchiveSource {
         // or the L1 have reorged.
         // In any case, we have to figure out how far into the past the action will take us.
         // For simplicity here, we will simply rewind until we end in a block that is also on the chain on L1.
-        this.log.verbose(`L2 prune have occurred, unwind state`);
+        this.log.debug(`L2 prune has been detected.`);
 
         let tipAfterUnwind = localPendingBlockNumber;
         while (true) {
@@ -414,15 +426,18 @@ export class Archiver implements ArchiveSource {
         }
 
         const blocksToUnwind = localPendingBlockNumber - tipAfterUnwind;
-        this.log.verbose(
-          `Unwinding ${blocksToUnwind} block${blocksToUnwind > 1n ? 's' : ''} from block ${localPendingBlockNumber}`,
-        );
-
         await this.store.unwindBlocks(Number(localPendingBlockNumber), Number(blocksToUnwind));
+
+        this.log.warn(
+          `Unwound ${count(blocksToUnwind, 'block')} from L2 block ${localPendingBlockNumber} ` +
+            `due to mismatched block hashes at L1 block ${currentL1BlockNumber}. ` +
+            `Updated L2 latest block is ${await this.getBlockNumber()}.`,
+        );
       }
     }
 
-    this.log.debug(`Retrieving blocks from ${blocksSynchedTo + 1n} to ${currentL1BlockNumber}`);
+    // TODO(palla/log) Downgrade to trace
+    this.log.debug(`Retrieving L2 blocks from L1 block ${blocksSynchedTo + 1n} to ${currentL1BlockNumber}`);
     const retrievedBlocks = await retrieveBlockFromRollup(
       this.rollup,
       this.publicClient,
@@ -435,34 +450,42 @@ export class Archiver implements ArchiveSource {
     if (retrievedBlocks.length === 0) {
       // We are not calling `setBlockSynchedL1BlockNumber` because it may cause sync issues if based off infura.
       // See further details in earlier comments.
-      this.log.verbose(`Retrieved no new L2 blocks from ${blocksSynchedTo + 1n} to ${currentL1BlockNumber}`);
+      // TODO(palla/log) Downgrade to trace
+      this.log.debug(`Retrieved no new L2 blocks from L1 block ${blocksSynchedTo + 1n} to ${currentL1BlockNumber}`);
       return { provenBlockNumber };
     }
 
+    const lastProcessedL1BlockNumber = retrievedBlocks[retrievedBlocks.length - 1].l1.blockNumber;
     this.log.debug(
       `Retrieved ${retrievedBlocks.length} new L2 blocks between L1 blocks ${
         blocksSynchedTo + 1n
-      } and ${currentL1BlockNumber}.`,
+      } and ${currentL1BlockNumber} with last processed L1 block ${lastProcessedL1BlockNumber}.`,
     );
 
-    const lastProcessedL1BlockNumber = retrievedBlocks[retrievedBlocks.length - 1].l1.blockNumber;
-
-    this.log.debug(`last processed L1 block: [${lastProcessedL1BlockNumber}]`);
     for (const block of retrievedBlocks) {
-      this.log.debug(`ingesting new L2 block`, block.data.header.globalVariables.toFriendlyJSON());
+      this.log.debug(`Ingesting new L2 block ${block.data.number}`, {
+        ...block.data.header.globalVariables.toInspect(),
+        blockHash: block.data.hash,
+        l1BlockNumber: block.l1.blockNumber,
+      });
     }
 
     const timer = new Timer();
     await this.store.addBlocks(retrievedBlocks);
 
+    for (const block of retrievedBlocks) {
+      this.log.info(`Downloaded L2 block ${block.data.number}`, {
+        blockHash: block.data.hash(),
+        blockNumber: block.data.number,
+      });
+    }
+
     // Important that we update AFTER inserting the blocks.
     await updateProvenBlock();
     this.instrumentation.processNewBlocks(
       timer.ms() / retrievedBlocks.length,
       retrievedBlocks.map(b => b.data),
     );
-    const lastL2BlockNumber = retrievedBlocks[retrievedBlocks.length - 1].data.number;
-    this.log.verbose(`Processed ${retrievedBlocks.length} new L2 blocks up to ${lastL2BlockNumber}`);
 
     return { provenBlockNumber };
   }
@@ -825,7 +848,7 @@ class ArchiverStoreHelper
       .map(log => ContractClassRegisteredEvent.fromLog(log.data))
       .map(e => e.toContractClassPublic());
     if (contractClasses.length > 0) {
-      contractClasses.forEach(c => this.#log.verbose(`Registering contract class ${c.id.toString()}`));
+      contractClasses.forEach(c => this.#log.verbose(`${Operation[operation]} contract class ${c.id.toString()}`));
       if (operation == Operation.Store) {
         // TODO: Will probably want to create some worker threads to compute these bytecode commitments as they are expensive
         return await this.store.addContractClasses(

diff --git a/yarn-project/archiver/src/archiver/kv_archiver_store/log_store.ts b/yarn-project/archiver/src/archiver/kv_archiver_store/log_store.ts
@@ -94,7 +94,7 @@ export class LogStore {
           }
           const tag = new Fr(correctedBuffer);
 
-          this.#log.verbose(`Found tagged unencrypted log with tag ${tag.toString()} in block ${block.number}`);
+          this.#log.debug(`Found tagged unencrypted log with tag ${tag.toString()} in block ${block.number}`);
           const currentLogs = taggedLogs.get(tag.toString()) ?? [];
           currentLogs.push(
             new TxScopedL2Log(txHash, dataStartIndexForTx, block.number, /* isFromPublic */ true, log.data).toBuffer(),

diff --git a/yarn-project/circuits.js/src/structs/global_variables.ts b/yarn-project/circuits.js/src/structs/global_variables.ts
@@ -159,10 +159,22 @@ export class GlobalVariables {
     );
   }
 
+  toInspect() {
+    return {
+      chainId: this.chainId.toNumber(),
+      version: this.version.toNumber(),
+      blockNumber: this.blockNumber.toNumber(),
+      slotNumber: this.slotNumber.toNumber(),
+      timestamp: this.timestamp.toNumber(),
+      coinbase: this.coinbase.toString(),
+      feeRecipient: this.feeRecipient.toString(),
+      feePerDaGas: this.gasFees.feePerDaGas.toNumber(),
+      feePerL2Gas: this.gasFees.feePerL2Gas.toNumber(),
+    };
+  }
+
   [inspect.custom]() {
-    return `GlobalVariables { chainId: ${this.chainId.toString()}, version: ${this.version.toString()}, blockNumber: ${this.blockNumber.toString()}, slotNumber: ${this.slotNumber.toString()}, timestamp: ${this.timestamp.toString()}, coinbase: ${this.coinbase.toString()}, feeRecipient: ${this.feeRecipient.toString()}, gasFees: ${inspect(
-      this.gasFees,
-    )} }`;
+    return `GlobalVariables ${inspect(this.toInspect())}`;
   }
 
   public equals(other: this): boolean {