From e858e816610f93dfa914398f811d559e98bf3b5d Mon Sep 17 00:00:00 2001 From: Santiago Palladino Date: Wed, 11 Dec 2024 14:13:41 -0300 Subject: [PATCH 1/2] chore: More logs cleanup Cleanup of logs across archiver, sequencer, and pxe. --- .../archiver/src/archiver/archiver.ts | 2 + .../aztec-node/src/aztec-node/server.ts | 25 ++++--- .../l2_block_stream.test.ts | 2 +- .../l2_block_downloader/l2_block_stream.ts | 3 +- .../circuit-types/src/logs/tx_l2_logs.ts | 2 +- yarn-project/circuit-types/src/tx/tx.ts | 9 +++ .../circuits.js/src/structs/block_header.ts | 11 +++ .../src/structs/content_commitment.ts | 9 +++ .../circuits.js/src/structs/revert_code.ts | 4 ++ .../src/structs/state_reference.ts | 9 +++ .../ethereum/src/deploy_l1_contracts.ts | 36 +++++----- yarn-project/ethereum/src/eth_cheat_codes.ts | 8 ++- .../foundation/src/log/pino-logger.ts | 4 ++ yarn-project/kv-store/src/interfaces/utils.ts | 1 + yarn-project/p2p/src/client/p2p_client.ts | 4 +- .../prover-client/src/block_builder/light.ts | 17 +++-- .../pxe/src/pxe_service/pxe_service.ts | 43 ++++++++---- .../pxe/src/simulator_oracle/index.ts | 68 +++++++++++------- .../pxe/src/synchronizer/synchronizer.ts | 19 +++-- .../src/sequencer/sequencer.ts | 70 +++++++++++-------- .../src/client/client_execution_context.ts | 11 ++- .../simulator/src/client/private_execution.ts | 2 +- .../simulator/src/client/view_data_oracle.ts | 3 +- .../simulator/src/public/public_processor.ts | 26 +++++-- .../src/public/public_tx_simulator.ts | 28 +++++--- yarn-project/txe/src/oracle/txe_oracle.ts | 2 +- .../server_world_state_synchronizer.ts | 11 ++- 27 files changed, 282 insertions(+), 147 deletions(-) diff --git a/yarn-project/archiver/src/archiver/archiver.ts b/yarn-project/archiver/src/archiver/archiver.ts index 8a8ca018575..1549767ba84 100644 --- a/yarn-project/archiver/src/archiver/archiver.ts +++ b/yarn-project/archiver/src/archiver/archiver.ts @@ -491,6 +491,8 @@ export class Archiver implements ArchiveSource { this.log.info(`Downloaded L2 block ${block.data.number}`, { blockHash: block.data.hash(), blockNumber: block.data.number, + txCount: block.data.body.txEffects.length, + globalVariables: block.data.header.globalVariables.toInspect(), }); } } while (searchEndBlock < currentL1BlockNumber); diff --git a/yarn-project/aztec-node/src/aztec-node/server.ts b/yarn-project/aztec-node/src/aztec-node/server.ts index 2865e1f8649..8fbda47e369 100644 --- a/yarn-project/aztec-node/src/aztec-node/server.ts +++ b/yarn-project/aztec-node/src/aztec-node/server.ts @@ -110,13 +110,7 @@ export class AztecNodeService implements AztecNode { this.packageVersion = getPackageInfo().version; this.metrics = new NodeMetrics(telemetry, 'AztecNodeService'); - const message = - `Started Aztec Node against chain 0x${l1ChainId.toString(16)} with contracts - \n` + - `Rollup: ${config.l1Contracts.rollupAddress.toString()}\n` + - `Registry: ${config.l1Contracts.registryAddress.toString()}\n` + - `Inbox: ${config.l1Contracts.inboxAddress.toString()}\n` + - `Outbox: ${config.l1Contracts.outboxAddress.toString()}`; - this.log.info(message); + this.log.info(`Aztec Node started on chain 0x${l1ChainId.toString(16)}`, config.l1Contracts); } public addEpochProofQuote(quote: EpochProofQuote): Promise { @@ -163,7 +157,9 @@ export class AztecNodeService implements AztecNode { // now create the merkle trees and the world state synchronizer const worldStateSynchronizer = await createWorldStateSynchronizer(config, archiver, telemetry); const proofVerifier = config.realProofs ? await BBCircuitVerifier.new(config) : new TestCircuitVerifier(); - log.info(`Aztec node accepting ${config.realProofs ? 'real' : 'test'} proofs`); + if (!config.realProofs) { + log.warn(`Aztec node is accepting test proofs`); + } // create the tx pool and the p2p client, which will need the l2 block source const p2pClient = await createP2PClient(config, archiver, proofVerifier, worldStateSynchronizer, telemetry); @@ -784,7 +780,7 @@ export class AztecNodeService implements AztecNode { * @param tx - The transaction to simulate. **/ public async simulatePublicCalls(tx: Tx): Promise { - this.log.info(`Simulating tx ${tx.getTxHash()}`); + const txHash = tx.getTxHash(); const blockNumber = (await this.blockSource.getBlockNumber()) + 1; // If sequencer is not initialized, we just set these values to zero for simulation. @@ -798,9 +794,14 @@ export class AztecNodeService implements AztecNode { ); const prevHeader = (await this.blockSource.getBlock(-1))?.header; const publicProcessorFactory = new PublicProcessorFactory(this.contractDataSource, this.telemetry); - const fork = await this.worldStateSynchronizer.fork(); + this.log.verbose(`Simulating public calls for tx ${tx.getTxHash()}`, { + globalVariables: newGlobalVariables.toInspect(), + txHash, + blockNumber, + }); + try { const processor = publicProcessorFactory.create(fork, prevHeader, newGlobalVariables); @@ -808,13 +809,11 @@ export class AztecNodeService implements AztecNode { const [processedTxs, failedTxs, returns] = await processor.process([tx]); // REFACTOR: Consider returning the error rather than throwing if (failedTxs.length) { - this.log.warn(`Simulated tx ${tx.getTxHash()} fails: ${failedTxs[0].error}`); + this.log.warn(`Simulated tx ${tx.getTxHash()} fails: ${failedTxs[0].error}`, { txHash }); throw failedTxs[0].error; } const [processedTx] = processedTxs; - this.log.debug(`Simulated tx ${tx.getTxHash()} ${processedTx.revertReason ? 'Reverts' : 'Succeeds'}`); - return new PublicSimulationOutput( processedTx.revertReason, processedTx.constants, diff --git a/yarn-project/circuit-types/src/l2_block_downloader/l2_block_stream.test.ts b/yarn-project/circuit-types/src/l2_block_downloader/l2_block_stream.test.ts index ae25c222d5b..a7d84ea67fa 100644 --- a/yarn-project/circuit-types/src/l2_block_downloader/l2_block_stream.test.ts +++ b/yarn-project/circuit-types/src/l2_block_downloader/l2_block_stream.test.ts @@ -37,7 +37,7 @@ describe('L2BlockStream', () => { Promise.resolve(compactArray(times(limit, i => (from + i > latest ? undefined : makeBlock(from + i))))), ); - blockStream = new TestL2BlockStream(blockSource, localData, handler, { batchSize: 10 }); + blockStream = new TestL2BlockStream(blockSource, localData, handler, undefined, { batchSize: 10 }); }); const makeBlock = (number: number) => ({ number } as L2Block); diff --git a/yarn-project/circuit-types/src/l2_block_downloader/l2_block_stream.ts b/yarn-project/circuit-types/src/l2_block_downloader/l2_block_stream.ts index b4fce559ca9..00e81a388ff 100644 --- a/yarn-project/circuit-types/src/l2_block_downloader/l2_block_stream.ts +++ b/yarn-project/circuit-types/src/l2_block_downloader/l2_block_stream.ts @@ -9,12 +9,11 @@ import { type L2BlockId, type L2BlockSource, type L2Tips } from '../l2_block_sou export class L2BlockStream { private readonly runningPromise: RunningPromise; - private readonly log = createLogger('types:l2_block_stream'); - constructor( private l2BlockSource: Pick, private localData: L2BlockStreamLocalDataProvider, private handler: L2BlockStreamEventHandler, + private readonly log = createLogger('types:block_stream'), private opts: { proven?: boolean; pollIntervalMS?: number; diff --git a/yarn-project/circuit-types/src/logs/tx_l2_logs.ts b/yarn-project/circuit-types/src/logs/tx_l2_logs.ts index 8913fd7659e..299513de970 100644 --- a/yarn-project/circuit-types/src/logs/tx_l2_logs.ts +++ b/yarn-project/circuit-types/src/logs/tx_l2_logs.ts @@ -21,7 +21,7 @@ export abstract class TxL2Logs { abstract hash(): Buffer; constructor( - /** * An array containing logs emitted in individual function invocations in this tx. */ + /** An array containing logs emitted in individual function invocations in this tx. */ public readonly functionLogs: UnencryptedFunctionL2Logs[], ) {} diff --git a/yarn-project/circuit-types/src/tx/tx.ts b/yarn-project/circuit-types/src/tx/tx.ts index bbdd0037d4d..1e8a03107d1 100644 --- a/yarn-project/circuit-types/src/tx/tx.ts +++ b/yarn-project/circuit-types/src/tx/tx.ts @@ -179,6 +179,15 @@ export class Tx extends Gossipable { return new TxHash(firstNullifier.toBuffer()); } + /** Returns the tx hash, or undefined if none is set. */ + tryGetTxHash(): TxHash | undefined { + try { + return this.getTxHash(); + } catch { + return undefined; + } + } + /** Returns stats about this tx. */ getStats(): TxStats { return { diff --git a/yarn-project/circuits.js/src/structs/block_header.ts b/yarn-project/circuits.js/src/structs/block_header.ts index 8d335e7a5de..5a09e139a3e 100644 --- a/yarn-project/circuits.js/src/structs/block_header.ts +++ b/yarn-project/circuits.js/src/structs/block_header.ts @@ -152,6 +152,17 @@ export class BlockHeader { return poseidon2HashWithSeparator(this.toFields(), GeneratorIndex.BLOCK_HASH); } + toInspect() { + return { + lastArchive: this.lastArchive.root.toString(), + contentCommitment: this.contentCommitment.toInspect(), + state: this.state.toInspect(), + globalVariables: this.globalVariables.toInspect(), + totalFees: this.totalFees.toBigInt(), + totalManaUsed: this.totalManaUsed.toBigInt(), + }; + } + [inspect.custom]() { return `Header { lastArchive: ${inspect(this.lastArchive)}, diff --git a/yarn-project/circuits.js/src/structs/content_commitment.ts b/yarn-project/circuits.js/src/structs/content_commitment.ts index 8e2e9680ba2..bdb1b923478 100644 --- a/yarn-project/circuits.js/src/structs/content_commitment.ts +++ b/yarn-project/circuits.js/src/structs/content_commitment.ts @@ -52,6 +52,15 @@ export class ContentCommitment { return serializeToBuffer(this.numTxs, this.txsEffectsHash, this.inHash, this.outHash); } + toInspect() { + return { + numTxs: this.numTxs.toNumber(), + txsEffectsHash: bufferToHex(this.txsEffectsHash), + inHash: bufferToHex(this.inHash), + outHash: bufferToHex(this.outHash), + }; + } + toFields(): Fr[] { const serialized = [ this.numTxs, diff --git a/yarn-project/circuits.js/src/structs/revert_code.ts b/yarn-project/circuits.js/src/structs/revert_code.ts index 7e4357f05ae..405451df563 100644 --- a/yarn-project/circuits.js/src/structs/revert_code.ts +++ b/yarn-project/circuits.js/src/structs/revert_code.ts @@ -33,6 +33,10 @@ export class RevertCode { static readonly TEARDOWN_REVERTED: RevertCode = new RevertCode(RevertCodeEnum.TEARDOWN_REVERTED); static readonly BOTH_REVERTED: RevertCode = new RevertCode(RevertCodeEnum.BOTH_REVERTED); + public getCode(): RevertCodeEnum { + return this.code; + } + public equals(other: RevertCode): boolean { return this.code === other.code; } diff --git a/yarn-project/circuits.js/src/structs/state_reference.ts b/yarn-project/circuits.js/src/structs/state_reference.ts index 49e91ac5324..12945a22e58 100644 --- a/yarn-project/circuits.js/src/structs/state_reference.ts +++ b/yarn-project/circuits.js/src/structs/state_reference.ts @@ -69,6 +69,15 @@ export class StateReference { return this.l1ToL2MessageTree.isZero() && this.partial.isEmpty(); } + toInspect() { + return { + l1ToL2MessageTree: this.l1ToL2MessageTree.root.toString(), + noteHashTree: this.partial.noteHashTree.root.toString(), + nullifierTree: this.partial.nullifierTree.root.toString(), + publicDataTree: this.partial.publicDataTree.root.toString(), + }; + } + [inspect.custom]() { return `StateReference { l1ToL2MessageTree: ${inspect(this.l1ToL2MessageTree)}, diff --git a/yarn-project/ethereum/src/deploy_l1_contracts.ts b/yarn-project/ethereum/src/deploy_l1_contracts.ts index c2c731bb978..31b2c1eeb50 100644 --- a/yarn-project/ethereum/src/deploy_l1_contracts.ts +++ b/yarn-project/ethereum/src/deploy_l1_contracts.ts @@ -304,7 +304,7 @@ export const deployL1Contracts = async ( if (res.error) { throw new Error(`Error setting block interval: ${res.error.message}`); } - logger.info(`Set block interval to ${args.ethereumSlotDuration}`); + logger.warn(`Set block interval to ${args.ethereumSlotDuration}`); } logger.verbose(`Deploying contracts from ${account.address.toString()}`); @@ -315,21 +315,21 @@ export const deployL1Contracts = async ( const govDeployer = new L1Deployer(walletClient, publicClient, args.salt, logger); const registryAddress = await govDeployer.deploy(l1Artifacts.registry, [account.address.toString()]); - logger.info(`Deployed Registry at ${registryAddress}`); + logger.verbose(`Deployed Registry at ${registryAddress}`); const feeAssetAddress = await govDeployer.deploy(l1Artifacts.feeAsset, [ 'FeeJuice', 'FEE', account.address.toString(), ]); - logger.info(`Deployed Fee Juice at ${feeAssetAddress}`); + logger.verbose(`Deployed Fee Juice at ${feeAssetAddress}`); const stakingAssetAddress = await govDeployer.deploy(l1Artifacts.stakingAsset, [ 'Staking', 'STK', account.address.toString(), ]); - logger.info(`Deployed Staking Asset at ${stakingAssetAddress}`); + logger.verbose(`Deployed Staking Asset at ${stakingAssetAddress}`); // @todo #8084 // @note These numbers are just chosen to make testing simple. @@ -340,7 +340,7 @@ export const deployL1Contracts = async ( quorumSize, roundSize, ]); - logger.info(`Deployed GovernanceProposer at ${governanceProposerAddress}`); + logger.verbose(`Deployed GovernanceProposer at ${governanceProposerAddress}`); // @note @LHerskind the assets are expected to be the same at some point, but for better // configurability they are different for now. @@ -348,21 +348,21 @@ export const deployL1Contracts = async ( feeAssetAddress.toString(), governanceProposerAddress.toString(), ]); - logger.info(`Deployed Governance at ${governanceAddress}`); + logger.verbose(`Deployed Governance at ${governanceAddress}`); const coinIssuerAddress = await govDeployer.deploy(l1Artifacts.coinIssuer, [ feeAssetAddress.toString(), 1n * 10n ** 18n, // @todo #8084 governanceAddress.toString(), ]); - logger.info(`Deployed CoinIssuer at ${coinIssuerAddress}`); + logger.verbose(`Deployed CoinIssuer at ${coinIssuerAddress}`); const rewardDistributorAddress = await govDeployer.deploy(l1Artifacts.rewardDistributor, [ feeAssetAddress.toString(), registryAddress.toString(), governanceAddress.toString(), ]); - logger.info(`Deployed RewardDistributor at ${rewardDistributorAddress}`); + logger.verbose(`Deployed RewardDistributor at ${rewardDistributorAddress}`); logger.verbose(`Waiting for governance contracts to be deployed`); await govDeployer.waitForDeployments(); @@ -375,7 +375,7 @@ export const deployL1Contracts = async ( feeAssetAddress.toString(), args.l2FeeJuiceAddress.toString(), ]); - logger.info(`Deployed Fee Juice Portal at ${feeJuicePortalAddress}`); + logger.verbose(`Deployed Fee Juice Portal at ${feeJuicePortalAddress}`); const rollupConfigArgs = { aztecSlotDuration: args.aztecSlotDuration, @@ -394,10 +394,10 @@ export const deployL1Contracts = async ( rollupConfigArgs, ]; const rollupAddress = await deployer.deploy(l1Artifacts.rollup, rollupArgs); - logger.info(`Deployed Rollup at ${rollupAddress}`, rollupConfigArgs); + logger.verbose(`Deployed Rollup at ${rollupAddress}`, rollupConfigArgs); await deployer.waitForDeployments(); - logger.info(`All core contracts deployed`); + logger.verbose(`All core contracts have been deployed`); const feeJuicePortal = getContract({ address: feeJuicePortalAddress.toString(), @@ -428,7 +428,7 @@ export const deployL1Contracts = async ( { const txHash = await feeAsset.write.setFreeForAll([true], {} as any); - logger.info(`Fee asset set to free for all in ${txHash}`); + logger.verbose(`Fee asset set to free for all in ${txHash}`); txHashes.push(txHash); } @@ -464,7 +464,7 @@ export const deployL1Contracts = async ( // @note This is used to ensure we fully wait for the transaction when running against a real chain // otherwise we execute subsequent transactions too soon await publicClient.waitForTransactionReceipt({ hash: mintTxHash }); - logger.info(`Funding fee juice portal contract with fee juice in ${mintTxHash}`); + logger.verbose(`Funding fee juice portal contract with fee juice in ${mintTxHash}`); if (!(await feeJuicePortal.read.initialized([]))) { const initPortalTxHash = await feeJuicePortal.write.initialize([]); @@ -474,7 +474,7 @@ export const deployL1Contracts = async ( logger.verbose(`Fee juice portal is already initialized`); } - logger.info( + logger.verbose( `Initialized Fee Juice Portal at ${feeJuicePortalAddress} to bridge between L1 ${feeAssetAddress} to L2 ${args.l2FeeJuiceAddress}`, ); @@ -504,15 +504,15 @@ export const deployL1Contracts = async ( // Set initial blocks as proven if requested if (args.assumeProvenThrough && args.assumeProvenThrough > 0) { await rollup.write.setAssumeProvenThroughBlockNumber([BigInt(args.assumeProvenThrough)], { account }); - logger.warn(`Set Rollup assumedProvenUntil to ${args.assumeProvenThrough}`); + logger.warn(`Rollup set to assumedProvenUntil to ${args.assumeProvenThrough}`); } // Inbox and Outbox are immutable and are deployed from Rollup's constructor so we just fetch them from the contract. const inboxAddress = EthAddress.fromString((await rollup.read.INBOX([])) as any); - logger.info(`Inbox available at ${inboxAddress}`); + logger.verbose(`Inbox available at ${inboxAddress}`); const outboxAddress = EthAddress.fromString((await rollup.read.OUTBOX([])) as any); - logger.info(`Outbox available at ${outboxAddress}`); + logger.verbose(`Outbox available at ${outboxAddress}`); // We need to call a function on the registry to set the various contract addresses. const registryContract = getContract({ @@ -562,6 +562,8 @@ export const deployL1Contracts = async ( governanceAddress, }; + logger.info(`Aztec L1 contracts initialized`, l1Contracts); + return { walletClient, publicClient, diff --git a/yarn-project/ethereum/src/eth_cheat_codes.ts b/yarn-project/ethereum/src/eth_cheat_codes.ts index ae2f6793891..a68646c17ab 100644 --- a/yarn-project/ethereum/src/eth_cheat_codes.ts +++ b/yarn-project/ethereum/src/eth_cheat_codes.ts @@ -77,11 +77,15 @@ export class EthCheatCodes { * @param numberOfBlocks - The number of blocks to mine */ public async mine(numberOfBlocks = 1): Promise { + await this.doMine(numberOfBlocks); + this.logger.verbose(`Mined ${numberOfBlocks} L1 blocks`); + } + + private async doMine(numberOfBlocks = 1): Promise { const res = await this.rpcCall('hardhat_mine', [numberOfBlocks]); if (res.error) { throw new Error(`Error mining: ${res.error.message}`); } - this.logger.verbose(`Mined ${numberOfBlocks} L1 blocks`); } /** @@ -188,7 +192,7 @@ export class EthCheatCodes { if (res.error) { throw new Error(`Error warping: ${res.error.message}`); } - await this.mine(); + await this.doMine(); this.logger.verbose(`Warped L1 timestamp to ${timestamp}`); } diff --git a/yarn-project/foundation/src/log/pino-logger.ts b/yarn-project/foundation/src/log/pino-logger.ts index 98b92f5fa39..02068fc2930 100644 --- a/yarn-project/foundation/src/log/pino-logger.ts +++ b/yarn-project/foundation/src/log/pino-logger.ts @@ -36,7 +36,10 @@ export function createLogger(module: string): Logger { /** Log as trace. Use for when we want to denial-of-service any recipient of the logs. */ trace: (msg: string, data?: unknown) => logFn('trace', msg, data), level: pinoLogger.level as LogLevel, + /** Whether the given level is enabled for this logger. */ isLevelEnabled: (level: LogLevel) => isLevelEnabled(pinoLogger, level), + /** Module name for the logger. */ + module, }; } @@ -183,6 +186,7 @@ type ErrorLogFn = (msg: string, err?: Error | unknown, data?: LogData) => void; export type Logger = { [K in LogLevel]: LogFn } & { /** Error log function */ error: ErrorLogFn } & { level: LogLevel; isLevelEnabled: (level: LogLevel) => boolean; + module: string; }; /** diff --git a/yarn-project/kv-store/src/interfaces/utils.ts b/yarn-project/kv-store/src/interfaces/utils.ts index 2176a996bbf..bf84fb2e8da 100644 --- a/yarn-project/kv-store/src/interfaces/utils.ts +++ b/yarn-project/kv-store/src/interfaces/utils.ts @@ -12,6 +12,7 @@ export const mockLogger = { trace: (msg: string, data: any) => console.log(msg, data), level: 'trace' as const, isLevelEnabled: (_level: string) => true, + module: 'kv-store:mock-logger', }; /* eslint-enable no-console */ diff --git a/yarn-project/p2p/src/client/p2p_client.ts b/yarn-project/p2p/src/client/p2p_client.ts index 89a9853fe41..db1ced07f76 100644 --- a/yarn-project/p2p/src/client/p2p_client.ts +++ b/yarn-project/p2p/src/client/p2p_client.ts @@ -221,7 +221,7 @@ export class P2PClient extends WithTracer implements P2P { this.keepAttestationsInPoolFor = keepAttestationsInPoolFor; - this.blockStream = new L2BlockStream(l2BlockSource, this, this, { + this.blockStream = new L2BlockStream(l2BlockSource, this, this, createLogger('p2p:block_stream'), { batchSize: blockRequestBatchSize, pollIntervalMS: blockCheckIntervalMS, }); @@ -359,7 +359,7 @@ export class P2PClient extends WithTracer implements P2P { this.setCurrentState(P2PClientState.RUNNING); this.syncPromise = Promise.resolve(); await this.p2pService.start(); - this.log.verbose(`Block ${syncedLatestBlock} (proven ${syncedProvenBlock}) already beyond current block`); + this.log.debug(`Block ${syncedLatestBlock} (proven ${syncedProvenBlock}) already beyond current block`); } // publish any txs in TxPool after its doing initial sync diff --git a/yarn-project/prover-client/src/block_builder/light.ts b/yarn-project/prover-client/src/block_builder/light.ts index efda5e61dd1..02906a42666 100644 --- a/yarn-project/prover-client/src/block_builder/light.ts +++ b/yarn-project/prover-client/src/block_builder/light.ts @@ -14,8 +14,6 @@ import { protocolContractTreeRoot } from '@aztec/protocol-contracts'; import { type TelemetryClient } from '@aztec/telemetry-client'; import { NoopTelemetryClient } from '@aztec/telemetry-client/noop'; -import { inspect } from 'util'; - import { buildBaseRollupHints, buildHeaderAndBodyFromTxs, @@ -37,7 +35,7 @@ export class LightweightBlockBuilder implements BlockBuilder { constructor(private db: MerkleTreeWriteOperations, private telemetry: TelemetryClient) {} async startNewBlock(numTxs: number, globalVariables: GlobalVariables, l1ToL2Messages: Fr[]): Promise { - this.logger.verbose('Starting new block', { numTxs, globalVariables: inspect(globalVariables), l1ToL2Messages }); + this.logger.debug('Starting new block', { numTxs, globalVariables: globalVariables.toInspect(), l1ToL2Messages }); this.numTxs = numTxs; this.globalVariables = globalVariables; this.l1ToL2Messages = padArrayEnd(l1ToL2Messages, Fr.ZERO, NUMBER_OF_L1_L2_MESSAGES_PER_ROLLUP); @@ -47,14 +45,15 @@ export class LightweightBlockBuilder implements BlockBuilder { } async addNewTx(tx: ProcessedTx): Promise { - this.logger.verbose('Adding new tx to block', { txHash: tx.hash.toString() }); + this.logger.debug(tx.hash.isZero() ? 'Adding padding tx to block' : 'Adding new tx to block', { + txHash: tx.hash.toString(), + }); this.txs.push(tx); await buildBaseRollupHints(tx, this.globalVariables!, this.db); } async setBlockCompleted(): Promise { const paddingTxCount = this.numTxs! - this.txs.length; - this.logger.verbose(`Setting block as completed and adding ${paddingTxCount} padding txs`); for (let i = 0; i < paddingTxCount; i++) { await this.addNewTx( makeEmptyProcessedTx( @@ -71,8 +70,6 @@ export class LightweightBlockBuilder implements BlockBuilder { } private async buildBlock(): Promise { - this.logger.verbose(`Finalising block`); - const { header, body } = await buildHeaderAndBodyFromTxs( this.txs, this.globalVariables!, @@ -84,6 +81,12 @@ export class LightweightBlockBuilder implements BlockBuilder { const newArchive = await getTreeSnapshot(MerkleTreeId.ARCHIVE, this.db); const block = new L2Block(newArchive, header, body); + this.logger.debug(`Built block ${block.number}`, { + globalVariables: this.globalVariables?.toInspect(), + archiveRoot: newArchive.root.toString(), + blockHash: block.hash.toString(), + }); + return block; } } diff --git a/yarn-project/pxe/src/pxe_service/pxe_service.ts b/yarn-project/pxe/src/pxe_service/pxe_service.ts index 9f80b18ae39..92f3e449062 100644 --- a/yarn-project/pxe/src/pxe_service/pxe_service.ts +++ b/yarn-project/pxe/src/pxe_service/pxe_service.ts @@ -513,6 +513,19 @@ export class PXEService implements PXE { ): Promise { return await this.jobQueue .put(async () => { + const txInfo = { + origin: txRequest.origin, + functionSelector: txRequest.functionSelector, + simulatePublic, + msgSender, + chainId: txRequest.txContext.chainId, + version: txRequest.txContext.version, + authWitnesses: txRequest.authWitnesses.map(w => w.requestHash), + }; + this.log.verbose( + `Simulating transaction execution request to ${txRequest.functionSelector} at ${txRequest.origin}`, + txInfo, + ); const privateExecutionResult = await this.#executePrivate(txRequest, msgSender, scopes); let publicInputs: PrivateKernelTailCircuitPublicInputs; @@ -540,13 +553,19 @@ export class PXEService implements PXE { } } - // We log only if the msgSender is undefined, as simulating with a different msgSender - // is unlikely to be a real transaction, and likely to be only used to read data. - // Meaning that it will not necessarily have produced a nullifier (and thus have no TxHash) - // If we log, the `getTxHash` function will throw. - if (!msgSender) { - this.log.info(`Executed local simulation for ${simulatedTx.getTxHash()}`); - } + this.log.info(`Simulation completed for ${simulatedTx.tryGetTxHash()}`, { + txHash: simulatedTx.tryGetTxHash(), + ...txInfo, + ...(profileResult ? { gateCounts: profileResult.gateCounts } : {}), + ...(publicOutput + ? { + gasUsed: publicOutput.gasUsed, + revertCode: publicOutput.txEffect.revertCode.getCode(), + revertReason: publicOutput.revertReason, + } + : {}), + }); + return TxSimulationResult.fromPrivateSimulationResultAndPublicOutput( privateSimulationResult, publicOutput, @@ -571,7 +590,7 @@ export class PXEService implements PXE { if (await this.node.getTxEffect(txHash)) { throw new Error(`A settled tx with equal hash ${txHash.toString()} exists.`); } - this.log.info(`Sending transaction ${txHash}`); + this.log.debug(`Sending transaction ${txHash}`); await this.node.sendTx(tx).catch(err => { throw this.contextualizeError(err, inspect(tx)); }); @@ -700,12 +719,14 @@ export class PXEService implements PXE { } async #registerProtocolContracts() { + const registered: Record = {}; for (const name of protocolContractNames) { const { address, contractClass, instance, artifact } = getCanonicalProtocolContract(name); await this.db.addContractArtifact(contractClass.id, artifact); await this.db.addContractInstance(instance); - this.log.info(`Added protocol contract ${name} at ${address.toString()}`); + registered[name] = address.toString(); } + this.log.info(`Registered protocol contracts in pxe`, registered); } /** @@ -737,13 +758,11 @@ export class PXEService implements PXE { scopes?: AztecAddress[], ): Promise { // TODO - Pause syncing while simulating. - const { contractAddress, functionArtifact } = await this.#getSimulationParameters(txRequest); - this.log.debug('Executing simulator...'); try { const result = await this.simulator.run(txRequest, functionArtifact, contractAddress, msgSender, scopes); - this.log.verbose(`Simulation completed for ${contractAddress.toString()}:${functionArtifact.name}`); + this.log.debug(`Private simulation completed for ${contractAddress.toString()}:${functionArtifact.name}`); return result; } catch (err) { if (err instanceof SimulationError) { diff --git a/yarn-project/pxe/src/simulator_oracle/index.ts b/yarn-project/pxe/src/simulator_oracle/index.ts index 27b70628c2b..b6866e9a28c 100644 --- a/yarn-project/pxe/src/simulator_oracle/index.ts +++ b/yarn-project/pxe/src/simulator_oracle/index.ts @@ -290,9 +290,13 @@ export class SimulatorOracle implements DBOracle { ): Promise { const secret = await this.#calculateTaggingSecret(contractAddress, sender, recipient); const contractName = await this.contractDataOracle.getDebugContractName(contractAddress); - this.log.verbose( - `Incrementing secret ${secret} as sender ${sender} for recipient: ${recipient} at contract: ${contractName}(${contractAddress})`, - ); + this.log.debug(`Incrementing app tagging secret at ${contractName}(${contractAddress})`, { + secret, + sender, + recipient, + contractName, + contractAddress, + }); const [index] = await this.db.getTaggingSecretsIndexesAsSender([secret]); await this.db.setTaggingSecretsIndexesAsSender([new IndexedTaggingSecret(secret, index + 1)]); @@ -394,9 +398,13 @@ export class SimulatorOracle implements DBOracle { await this.db.setTaggingSecretsIndexesAsSender([new IndexedTaggingSecret(appTaggingSecret, newIndex)]); const contractName = await this.contractDataOracle.getDebugContractName(contractAddress); - this.log.debug( - `Syncing logs for sender ${sender}, secret ${appTaggingSecret}:${currentIndex} at contract: ${contractName}(${contractAddress})`, - ); + this.log.debug(`Syncing logs for sender ${sender} at contract ${contractName}(${contractAddress})`, { + sender, + secret: appTaggingSecret, + index: currentIndex, + contractName, + contractAddress, + }); } /** @@ -474,24 +482,32 @@ export class SimulatorOracle implements DBOracle { logsByTags.forEach((logsByTag, logIndex) => { const { secret: currentSecret, index: currentIndex } = currentTagggingSecrets[logIndex]; const currentSecretAsStr = currentSecret.toString(); - this.log.debug( - `Syncing logs for recipient ${recipient}, secret ${currentSecretAsStr}:${currentIndex} at contract: ${contractName}(${contractAddress})`, - ); + this.log.debug(`Syncing logs for recipient ${recipient} at contract ${contractName}(${contractAddress})`, { + recipient, + secret: currentSecret, + index: currentIndex, + contractName, + contractAddress, + }); // 3.1. Append logs to the list and increment the index for the tags that have logs (#9380) if (logsByTag.length > 0) { - this.log.verbose( - `Found ${ - logsByTag.length - } logs for secret ${currentSecretAsStr} as recipient ${recipient}. Incrementing index to ${ - currentIndex + 1 - } at contract: ${contractName}(${contractAddress})`, + const newIndex = currentIndex + 1; + this.log.debug( + `Found ${logsByTag.length} logs as recipient ${recipient}. Incrementing index to ${newIndex} at contract ${contractName}(${contractAddress})`, + { + recipient, + secret: currentSecret, + newIndex, + contractName, + contractAddress, + }, ); logs.push(...logsByTag); if (currentIndex >= initialSecretIndexes[currentSecretAsStr]) { // 3.2. Increment the index for the tags that have logs, provided they're higher than the one // we have stored in the db (#9380) - secretsToIncrement[currentSecretAsStr] = currentIndex + 1; + secretsToIncrement[currentSecretAsStr] = newIndex; // 3.3. Slide the window forwards if we have found logs beyond the initial index maxIndexesToCheck[currentSecretAsStr] = currentIndex + INDEX_OFFSET; } @@ -605,11 +621,11 @@ export class SimulatorOracle implements DBOracle { if (incomingNotes.length) { await this.db.addNotes(incomingNotes, recipient); incomingNotes.forEach(noteDao => { - this.log.verbose( - `Added incoming note for contract ${noteDao.contractAddress} at slot ${ - noteDao.storageSlot - } with nullifier ${noteDao.siloedNullifier.toString()}`, - ); + this.log.verbose(`Added incoming note for contract ${noteDao.contractAddress} at slot ${noteDao.storageSlot}`, { + contract: noteDao.contractAddress, + slot: noteDao.storageSlot, + nullifier: noteDao.siloedNullifier.toString(), + }); }); } const nullifiedNotes: IncomingNoteDao[] = []; @@ -628,11 +644,11 @@ export class SimulatorOracle implements DBOracle { await this.db.removeNullifiedNotes(foundNullifiers, recipient.toAddressPoint()); nullifiedNotes.forEach(noteDao => { - this.log.verbose( - `Removed note for contract ${noteDao.contractAddress} at slot ${ - noteDao.storageSlot - } with nullifier ${noteDao.siloedNullifier.toString()}`, - ); + this.log.verbose(`Removed note for contract ${noteDao.contractAddress} at slot ${noteDao.storageSlot}`, { + contract: noteDao.contractAddress, + slot: noteDao.storageSlot, + nullifier: noteDao.siloedNullifier.toString(), + }); }); } } diff --git a/yarn-project/pxe/src/synchronizer/synchronizer.ts b/yarn-project/pxe/src/synchronizer/synchronizer.ts index fe1c607e7da..a4f13e1d019 100644 --- a/yarn-project/pxe/src/synchronizer/synchronizer.ts +++ b/yarn-project/pxe/src/synchronizer/synchronizer.ts @@ -36,7 +36,7 @@ export class Synchronizer implements L2BlockStreamEventHandler { } protected createBlockStream(config: Partial>) { - return new L2BlockStream(this.node, this.l2TipsStore, this, { + return new L2BlockStream(this.node, this.l2TipsStore, this, createLogger('pxe:block_stream'), { pollIntervalMS: config.l2BlockPollingIntervalMS, startingBlock: config.l2StartingBlock, }); @@ -47,12 +47,18 @@ export class Synchronizer implements L2BlockStreamEventHandler { await this.l2TipsStore.handleBlockStreamEvent(event); switch (event.type) { - case 'blocks-added': - this.log.verbose(`Processing blocks ${event.blocks[0].number} to ${event.blocks.at(-1)!.number}`); - await this.db.setHeader(event.blocks.at(-1)!.header); + case 'blocks-added': { + const lastBlock = event.blocks.at(-1)!; + this.log.verbose(`Updated pxe last block to ${lastBlock.number}`, { + blockHash: lastBlock.hash(), + archive: lastBlock.archive.root.toString(), + header: lastBlock.header.toInspect(), + }); + await this.db.setHeader(lastBlock.header); break; - case 'chain-pruned': - this.log.info(`Pruning data after block ${event.blockNumber} due to reorg`); + } + case 'chain-pruned': { + this.log.warn(`Pruning data after block ${event.blockNumber} due to reorg`); // We first unnullify and then remove so that unnullified notes that were created after the block number end up deleted. await this.db.unnullifyNotesAfter(event.blockNumber); await this.db.removeNotesAfter(event.blockNumber); @@ -62,6 +68,7 @@ export class Synchronizer implements L2BlockStreamEventHandler { // Update the header to the last block. await this.db.setHeader(await this.node.getBlockHeader(event.blockNumber)); break; + } } } diff --git a/yarn-project/sequencer-client/src/sequencer/sequencer.ts b/yarn-project/sequencer-client/src/sequencer/sequencer.ts index f868980cf5e..2101578dd30 100644 --- a/yarn-project/sequencer-client/src/sequencer/sequencer.ts +++ b/yarn-project/sequencer-client/src/sequencer/sequencer.ts @@ -195,7 +195,7 @@ export class Sequencer { this.runningPromise = new RunningPromise(this.work.bind(this), this.pollingIntervalMs); this.setState(SequencerState.IDLE, 0n, true /** force */); this.runningPromise.start(); - this.log.info(`Sequencer started`); + this.log.info(`Sequencer started with address ${this.publisher.getSenderAddress().toString()}`); return Promise.resolve(); } @@ -295,11 +295,6 @@ export class Sequencer { return; } - this.log.verbose( - `Retrieved ${pendingTxs.length} txs for block ${newBlockNumber} with global variables`, - newGlobalVariables.toInspect(), - ); - // If I created a "partial" header here that should make our job much easier. const proposalHeader = new BlockHeader( new AppendOnlyTreeSnapshot(Fr.fromBuffer(chainTipArchive), 1), @@ -323,6 +318,10 @@ export class Sequencer { // may break if we start emitting lots of log data from public-land. const validTxs = this.takeTxsWithinMaxSize(allValidTxs); + this.log.verbose( + `Collected ${validTxs.length} txs out of ${allValidTxs.length} valid txs out of ${pendingTxs.length} total pending txs for block ${newBlockNumber}`, + ); + // Bail if we don't have enough valid txs if (!this.shouldProposeBlock(historicalHeader, { validTxsCount: validTxs.length })) { return; @@ -519,12 +518,15 @@ export class Sequencer { this.log.debug(`Requesting L1 to L2 messages from contract for block ${blockNumber}`); const l1ToL2Messages = await this.l1ToL2MessageSource.getL1ToL2Messages(blockNumber); - this.log.verbose(`Building block ${blockNumber}`, { - msgCount: l1ToL2Messages.length, - txCount: validTxs.length, - slot, - blockNumber, - }); + this.log.verbose( + `Building block ${blockNumber} with ${validTxs.length} txs and ${l1ToL2Messages.length} messages`, + { + msgCount: l1ToL2Messages.length, + txCount: validTxs.length, + slot, + blockNumber, + }, + ); const numRealTxs = validTxs.length; const blockSize = Math.max(2, numRealTxs); @@ -562,7 +564,13 @@ export class Sequencer { // All real transactions have been added, set the block as full and complete the proving. const block = await blockBuilder.setBlockCompleted(); - return { block, publicProcessorDuration, numProcessedTxs: processedTxs.length, blockBuildingTimer }; + return { + block, + publicProcessorDuration, + numMsgs: l1ToL2Messages.length, + numProcessedTxs: processedTxs.length, + blockBuildingTimer, + }; } finally { // We create a fresh processor each time to reset any cached state (eg storage writes) await publicProcessorFork.close(); @@ -619,12 +627,8 @@ export class Sequencer { }; try { - const { block, publicProcessorDuration, numProcessedTxs, blockBuildingTimer } = await this.buildBlock( - validTxs, - newGlobalVariables, - historicalHeader, - interrupt, - ); + const buildBlockRes = await this.buildBlock(validTxs, newGlobalVariables, historicalHeader, interrupt); + const { block, publicProcessorDuration, numProcessedTxs, numMsgs, blockBuildingTimer } = buildBlockRes; // TODO(@PhilWindle) We should probably periodically check for things like another // block being published before ours instead of just waiting on our block @@ -641,22 +645,27 @@ export class Sequencer { ...block.getStats(), }; - this.log.verbose(`Built block ${block.number}`, { + const blockHash = block.hash(); + const txHashes = validTxs.map(tx => tx.getTxHash()); + this.log.info(`Built block ${block.number} with hash ${blockHash}`, { txEffectsHash: block.header.contentCommitment.txsEffectsHash.toString('hex'), + blockHash, + globalVariables: block.header.globalVariables.toInspect(), + txHashes, ...blockStats, }); if (this.isFlushing) { - this.log.verbose(`Flushing completed`); + this.log.verbose(`Sequencer flushing completed`); } - const txHashes = validTxs.map(tx => tx.getTxHash()); - this.isFlushing = false; this.log.debug('Collecting attestations'); const stopCollectingAttestationsTimer = this.metrics.startCollectingAttestationsTimer(); const attestations = await this.collectAttestations(block, txHashes); - this.log.verbose(`Collected ${attestations?.length ?? 0} attestations`); + if (attestations !== undefined) { + this.log.verbose(`Collected ${attestations.length} attestations`); + } stopCollectingAttestationsTimer(); this.log.debug('Collecting proof quotes'); @@ -665,12 +674,15 @@ export class Sequencer { await this.publishL2Block(block, attestations, txHashes, proofQuote); this.metrics.recordPublishedBlock(workDuration); this.log.info( - `Published rollup block ${block.number} with ${numProcessedTxs} transactions in ${Math.ceil(workDuration)}ms`, + `Published rollup block ${ + block.number + } with ${numProcessedTxs} transactions and ${numMsgs} messages in ${Math.ceil(workDuration)}ms`, { blockNumber: block.number, - blockHash: block.hash(), + blockHash: blockHash, slot, txCount: numProcessedTxs, + msgCount: numMsgs, duration: Math.ceil(workDuration), submitter: this.publisher.getSenderAddress().toString(), }, @@ -696,10 +708,10 @@ export class Sequencer { const committee = await this.publisher.getCurrentEpochCommittee(); if (committee.length === 0) { - this.log.verbose(`Attesting committee length is 0`); + this.log.verbose(`Attesting committee is empty`); return undefined; } else { - this.log.debug(`Attesting committee length ${committee.length}`); + this.log.debug(`Attesting committee length is ${committee.length}`); } if (!this.validatorClient) { @@ -713,7 +725,7 @@ export class Sequencer { this.log.debug('Creating block proposal'); const proposal = await this.validatorClient.createBlockProposal(block.header, block.archive.root, txHashes); if (!proposal) { - this.log.verbose(`Failed to create block proposal, skipping collecting attestations`); + this.log.warn(`Failed to create block proposal, skipping collecting attestations`); return undefined; } diff --git a/yarn-project/simulator/src/client/client_execution_context.ts b/yarn-project/simulator/src/client/client_execution_context.ts index 5e568872033..da0eadb0f6a 100644 --- a/yarn-project/simulator/src/client/client_execution_context.ts +++ b/yarn-project/simulator/src/client/client_execution_context.ts @@ -419,7 +419,14 @@ export class ClientExecutionContext extends ViewDataOracle { const args = this.packedValuesCache.unpack(argsHash); this.log.verbose( - `Created PublicExecutionRequest to ${targetArtifact.name}@${targetContractAddress}, of type [${callType}], side-effect counter [${sideEffectCounter}]`, + `Created ${callType} public execution request to ${targetArtifact.name}@${targetContractAddress}`, + { + sideEffectCounter, + isStaticCall, + functionSelector, + targetContractAddress, + callType, + }, ); const request = PublicExecutionRequest.from({ @@ -537,7 +544,7 @@ export class ClientExecutionContext extends ViewDataOracle { } public override debugLog(message: string, fields: Fr[]) { - this.log.verbose(`debug_log ${applyStringFormatting(message, fields)}`); + this.log.verbose(`${applyStringFormatting(message, fields)}`, { module: `${this.log.module}:debug_log` }); } public getDebugFunctionName() { diff --git a/yarn-project/simulator/src/client/private_execution.ts b/yarn-project/simulator/src/client/private_execution.ts index 300141672a7..199d395696b 100644 --- a/yarn-project/simulator/src/client/private_execution.ts +++ b/yarn-project/simulator/src/client/private_execution.ts @@ -27,7 +27,7 @@ export async function executePrivateFunction( log = createLogger('simulator:private_execution'), ): Promise { const functionName = await context.getDebugFunctionName(); - log.verbose(`Executing external function ${functionName}@${contractAddress}`); + log.verbose(`Executing private function ${functionName}@${contractAddress}`); const acir = artifact.bytecode; const initialWitness = context.getInitialWitness(artifact); const acvmCallback = new Oracle(context); diff --git a/yarn-project/simulator/src/client/view_data_oracle.ts b/yarn-project/simulator/src/client/view_data_oracle.ts index de71ba38b81..358a3271186 100644 --- a/yarn-project/simulator/src/client/view_data_oracle.ts +++ b/yarn-project/simulator/src/client/view_data_oracle.ts @@ -290,8 +290,7 @@ export class ViewDataOracle extends TypedOracle { } public override debugLog(message: string, fields: Fr[]): void { - const formattedStr = applyStringFormatting(message, fields); - this.log.verbose(`debug_log ${formattedStr}`); + this.log.verbose(`${applyStringFormatting(message, fields)}`, { module: `${this.log.module}:debug_log` }); } /** diff --git a/yarn-project/simulator/src/public/public_processor.ts b/yarn-project/simulator/src/public/public_processor.ts index 35c9d0552b6..eb817b121fc 100644 --- a/yarn-project/simulator/src/public/public_processor.ts +++ b/yarn-project/simulator/src/public/public_processor.ts @@ -121,12 +121,26 @@ export class PublicProcessor { const [processedTx, returnValues] = !tx.hasPublicCalls() ? await this.processPrivateOnlyTx(tx) : await this.processTxWithPublicCalls(tx); - this.log.debug(`Processed tx`, { - txHash: processedTx.hash, - historicalHeaderHash: processedTx.constants.historicalHeader.hash(), - blockNumber: processedTx.constants.globalVariables.blockNumber, - lastArchiveRoot: processedTx.constants.historicalHeader.lastArchive.root, - }); + + this.log.verbose( + !tx.hasPublicCalls() + ? `Processed tx ${processedTx.hash} with no public calls` + : `Processed tx ${processedTx.hash} with ${tx.enqueuedPublicFunctionCalls.length} public calls`, + { + txHash: processedTx.hash, + txFee: processedTx.txEffect.transactionFee.toBigInt(), + revertCode: processedTx.txEffect.revertCode.getCode(), + revertReason: processedTx.revertReason, + gasUsed: processedTx.gasUsed, + publicDataWriteCount: processedTx.txEffect.publicDataWrites.length, + nullifierCount: processedTx.txEffect.nullifiers.length, + noteHashCount: processedTx.txEffect.noteHashes.length, + contractClassLogCount: processedTx.txEffect.contractClassLogs.getTotalLogCount(), + unencryptedLogCount: processedTx.txEffect.unencryptedLogs.getTotalLogCount(), + privateLogCount: processedTx.txEffect.privateLogs.length, + l2ToL1MessageCount: processedTx.txEffect.l2ToL1Msgs.length, + }, + ); // Commit the state updates from this transaction await this.worldStateDB.commit(); diff --git a/yarn-project/simulator/src/public/public_tx_simulator.ts b/yarn-project/simulator/src/public/public_tx_simulator.ts index 81180cd2380..37921773c48 100644 --- a/yarn-project/simulator/src/public/public_tx_simulator.ts +++ b/yarn-project/simulator/src/public/public_tx_simulator.ts @@ -69,8 +69,9 @@ export class PublicTxSimulator { * @param tx - The transaction to simulate. * @returns The result of the transaction's public execution. */ - async simulate(tx: Tx): Promise { - this.log.verbose(`Processing tx ${tx.getTxHash()}`); + public async simulate(tx: Tx): Promise { + const txHash = tx.getTxHash(); + this.log.debug(`Simulating ${tx.enqueuedPublicFunctionCalls.length} public calls for tx ${txHash}`, { txHash }); const context = await PublicTxContext.create( this.db, @@ -207,7 +208,12 @@ export class PublicTxSimulator { const callRequests = context.getCallRequestsForPhase(phase); const executionRequests = context.getExecutionRequestsForPhase(phase); - this.log.debug(`Beginning processing in phase ${TxExecutionPhase[phase]} for tx ${context.getTxHash()}`); + this.log.debug(`Processing phase ${TxExecutionPhase[phase]} for tx ${context.getTxHash()}`, { + txHash: context.getTxHash().toString(), + phase: TxExecutionPhase[phase], + callRequests: callRequests.length, + executionRequests: executionRequests.length, + }); const returnValues: NestedProcessReturnValues[] = []; let reverted = false; @@ -276,8 +282,8 @@ export class PublicTxSimulator { const gasUsed = allocatedGas.sub(result.gasLeft); // by enqueued call context.consumeGas(phase, gasUsed); - this.log.verbose( - `[AVM] Enqueued public call consumed ${gasUsed.l2Gas} L2 gas ending with ${result.gasLeft.l2Gas} L2 gas left.`, + this.log.debug( + `Simulated enqueued public call consumed ${gasUsed.l2Gas} L2 gas ending with ${result.gasLeft.l2Gas} L2 gas left.`, ); stateManager.traceEnqueuedCall(callRequest, executionRequest.args, result.reverted); @@ -320,8 +326,8 @@ export class PublicTxSimulator { const address = executionRequest.callContext.contractAddress; const sender = executionRequest.callContext.msgSender; - this.log.verbose( - `[AVM] Executing enqueued public call to external function ${fnName}@${address} with ${allocatedGas.l2Gas} allocated L2 gas.`, + this.log.debug( + `Executing enqueued public call to external function ${fnName}@${address} with ${allocatedGas.l2Gas} allocated L2 gas.`, ); const timer = new Timer(); @@ -338,10 +344,10 @@ export class PublicTxSimulator { const avmCallResult = await simulator.execute(); const result = avmCallResult.finalize(); - this.log.verbose( - `[AVM] Simulation of enqueued public call ${fnName} completed. reverted: ${result.reverted}${ - result.reverted ? ', reason: ' + result.revertReason : '' - }.`, + this.log.debug( + result.reverted + ? `Simulation of enqueued public call ${fnName} reverted with reason ${result.revertReason}.` + : `Simulation of enqueued public call ${fnName} completed successfully.`, { eventName: 'avm-simulation', appCircuitName: fnName, diff --git a/yarn-project/txe/src/oracle/txe_oracle.ts b/yarn-project/txe/src/oracle/txe_oracle.ts index eda766bdce7..a653aaeca1a 100644 --- a/yarn-project/txe/src/oracle/txe_oracle.ts +++ b/yarn-project/txe/src/oracle/txe_oracle.ts @@ -754,7 +754,7 @@ export class TXE implements TypedOracle { } debugLog(message: string, fields: Fr[]): void { - this.logger.verbose(`debug_log ${applyStringFormatting(message, fields)}`); + this.logger.verbose(`${applyStringFormatting(message, fields)}`, { module: `${this.logger.module}:debug_log` }); } async incrementAppTaggingSecretIndexAsSender(sender: AztecAddress, recipient: AztecAddress): Promise { diff --git a/yarn-project/world-state/src/synchronizer/server_world_state_synchronizer.ts b/yarn-project/world-state/src/synchronizer/server_world_state_synchronizer.ts index a1cb07c6928..901dcb96229 100644 --- a/yarn-project/world-state/src/synchronizer/server_world_state_synchronizer.ts +++ b/yarn-project/world-state/src/synchronizer/server_world_state_synchronizer.ts @@ -111,7 +111,7 @@ export class ServerWorldStateSynchronizer } protected createBlockStream() { - return new L2BlockStream(this.l2BlockSource, this, this, { + return new L2BlockStream(this.l2BlockSource, this, this, createLogger('world_state:block_stream'), { proven: this.config.worldStateProvenBlocksOnly, pollIntervalMS: this.config.worldStateBlockCheckIntervalMS, batchSize: this.config.worldStateBlockRequestBatchSize, @@ -224,14 +224,13 @@ export class ServerWorldStateSynchronizer * @returns Whether the block handled was produced by this same node. */ private async handleL2Blocks(l2Blocks: L2Block[]) { - this.log.verbose(`Handling new L2 blocks from ${l2Blocks[0].number} to ${l2Blocks[l2Blocks.length - 1].number}`); const messagePromises = l2Blocks.map(block => this.l2BlockSource.getL1ToL2Messages(BigInt(block.number))); const l1ToL2Messages: Fr[][] = await Promise.all(messagePromises); let updateStatus: WorldStateStatusFull | undefined = undefined; for (let i = 0; i < l2Blocks.length; i++) { const [duration, result] = await elapsed(() => this.handleL2Block(l2Blocks[i], l1ToL2Messages[i])); - this.log.verbose(`Handled new L2 block`, { + this.log.verbose(`World state updated with L2 block ${l2Blocks[i].number}`, { eventName: 'l2-block-handled', duration, unfinalisedBlockNumber: result.summary.unfinalisedBlockNumber, @@ -272,7 +271,7 @@ export class ServerWorldStateSynchronizer } private async handleChainFinalized(blockNumber: number) { - this.log.verbose(`Chain finalized at block ${blockNumber}`); + this.log.verbose(`Finalized chain is now at block ${blockNumber}`); const summary = await this.merkleTreeDb.setFinalised(BigInt(blockNumber)); if (this.historyToKeep === undefined) { return; @@ -286,12 +285,12 @@ export class ServerWorldStateSynchronizer } private handleChainProven(blockNumber: number) { - this.log.verbose(`Chain proven at block ${blockNumber}`); + this.log.debug(`Proven chain is now at block ${blockNumber}`); return Promise.resolve(); } private async handleChainPruned(blockNumber: number) { - this.log.info(`Chain pruned to block ${blockNumber}`); + this.log.warn(`Chain pruned to block ${blockNumber}`); const status = await this.merkleTreeDb.unwindBlocks(BigInt(blockNumber)); this.latestBlockHashQuery = undefined; this.instrumentation.updateWorldStateMetrics(status); From a1c5f83128ef65e1c6da0ea58c3fb983dfcf3bc7 Mon Sep 17 00:00:00 2001 From: Santiago Palladino Date: Wed, 11 Dec 2024 16:14:49 -0300 Subject: [PATCH 2/2] Replace test proofs with fake proofs --- yarn-project/aztec-node/src/aztec-node/server.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/yarn-project/aztec-node/src/aztec-node/server.ts b/yarn-project/aztec-node/src/aztec-node/server.ts index 8fbda47e369..35476df3fc8 100644 --- a/yarn-project/aztec-node/src/aztec-node/server.ts +++ b/yarn-project/aztec-node/src/aztec-node/server.ts @@ -158,7 +158,7 @@ export class AztecNodeService implements AztecNode { const worldStateSynchronizer = await createWorldStateSynchronizer(config, archiver, telemetry); const proofVerifier = config.realProofs ? await BBCircuitVerifier.new(config) : new TestCircuitVerifier(); if (!config.realProofs) { - log.warn(`Aztec node is accepting test proofs`); + log.warn(`Aztec node is accepting fake proofs`); } // create the tx pool and the p2p client, which will need the l2 block source