diff --git a/yarn-project/archiver/src/archiver/archiver.ts b/yarn-project/archiver/src/archiver/archiver.ts index 71ba4bfc8dc..471acf687c0 100644 --- a/yarn-project/archiver/src/archiver/archiver.ts +++ b/yarn-project/archiver/src/archiver/archiver.ts @@ -274,7 +274,10 @@ export class Archiver implements ArchiveSource, Traceable { } if (initialRun) { - this.log.info(`Initial archiver sync to L1 block ${currentL1BlockNumber} complete.`); + this.log.info(`Initial archiver sync to L1 block ${currentL1BlockNumber} complete.`, { + l1BlockNumber: currentL1BlockNumber, + ...(await this.getL2Tips()), + }); } } @@ -364,6 +367,16 @@ export class Archiver implements ArchiveSource, Traceable { const updateProvenBlock = async () => { const localBlockForDestinationProvenBlockNumber = await this.getBlock(Number(provenBlockNumber)); + + // Sanity check. I've hit what seems to be a state where the proven block is set to a value greater than the latest + // synched block when requesting L2Tips from the archiver. This is the only place where the proven block is set. + const synched = await this.store.getSynchedL2BlockNumber(); + if (localBlockForDestinationProvenBlockNumber && synched < localBlockForDestinationProvenBlockNumber?.number) { + this.log.error( + `Hit local block greater than last synched block: ${localBlockForDestinationProvenBlockNumber.number} > ${synched}`, + ); + } + if ( localBlockForDestinationProvenBlockNumber && provenArchive === localBlockForDestinationProvenBlockNumber.archive.root.toString() @@ -798,11 +811,13 @@ export class Archiver implements ArchiveSource, Traceable { ] as const); if (latestBlockNumber > 0 && !latestBlockHeader) { - throw new Error('Failed to retrieve latest block header'); + throw new Error(`Failed to retrieve latest block header for block ${latestBlockNumber}`); } if (provenBlockNumber > 0 && !provenBlockHeader) { - throw new Error('Failed to retrieve proven block header'); + throw new Error( + `Failed to retrieve proven block header for block ${provenBlockNumber} (latest block is ${latestBlockNumber})`, + ); } return { diff --git a/yarn-project/aztec.js/src/utils/chain_monitor.ts b/yarn-project/aztec.js/src/utils/chain_monitor.ts new file mode 100644 index 00000000000..d46c5e9ed90 --- /dev/null +++ b/yarn-project/aztec.js/src/utils/chain_monitor.ts @@ -0,0 +1,75 @@ +import { type RollupContract } from '@aztec/ethereum'; +import { createLogger } from '@aztec/foundation/log'; + +import { type PublicClient } from 'viem'; + +/** Utility class that polls the chain on quick intervals and logs new L1 blocks, L2 blocks, and L2 proofs. */ +export class ChainMonitor { + private readonly l1Client: PublicClient; + private handle: NodeJS.Timeout | undefined; + + /** Current L1 block number */ + public l1BlockNumber!: number; + /** Current L2 block number */ + public l2BlockNumber!: number; + /** Current L2 proven block number */ + public l2ProvenBlockNumber!: number; + + constructor( + private readonly rollup: RollupContract, + private logger = createLogger('aztecjs:utils:chain_monitor'), + private readonly intervalMs = 200, + ) { + this.l1Client = rollup.client; + } + + start() { + if (this.handle) { + throw new Error('Chain monitor already started'); + } + this.handle = setInterval(() => this.run(), this.intervalMs); + } + + stop() { + if (this.handle) { + clearInterval(this.handle!); + this.handle = undefined; + } + } + + async run() { + const newL1BlockNumber = Number(await this.l1Client.getBlockNumber({ cacheTime: 0 })); + if (this.l1BlockNumber === newL1BlockNumber) { + return; + } + this.l1BlockNumber = newL1BlockNumber; + + const block = await this.l1Client.getBlock({ blockNumber: BigInt(newL1BlockNumber), includeTransactions: false }); + const timestamp = block.timestamp; + const timestampString = new Date(Number(timestamp) * 1000).toTimeString().split(' ')[0]; + + let msg = `L1 block ${newL1BlockNumber} mined at ${timestampString}`; + + const newL2BlockNumber = Number(await this.rollup.getBlockNumber()); + if (this.l2BlockNumber !== newL2BlockNumber) { + const epochNumber = await this.rollup.getEpochNumber(BigInt(newL2BlockNumber)); + msg += ` with new L2 block ${newL2BlockNumber} for epoch ${epochNumber}`; + this.l2BlockNumber = newL2BlockNumber; + } + + const newL2ProvenBlockNumber = Number(await this.rollup.getProvenBlockNumber()); + if (this.l2ProvenBlockNumber !== newL2ProvenBlockNumber) { + const epochNumber = await this.rollup.getEpochNumber(BigInt(newL2ProvenBlockNumber)); + msg += ` with proof up to L2 block ${newL2ProvenBlockNumber} for epoch ${epochNumber}`; + this.l2ProvenBlockNumber = newL2ProvenBlockNumber; + } + + this.logger.info(msg, { + l1Timestamp: timestamp, + l1BlockNumber: this.l1BlockNumber, + l2SlotNumber: await this.rollup.getSlotNumber(), + l2BlockNumber: this.l2BlockNumber, + l2ProvenBlockNumber: this.l2ProvenBlockNumber, + }); + } +} diff --git a/yarn-project/aztec.js/src/utils/index.ts b/yarn-project/aztec.js/src/utils/index.ts index 68a1b4d12fa..a2ed02d5d9e 100644 --- a/yarn-project/aztec.js/src/utils/index.ts +++ b/yarn-project/aztec.js/src/utils/index.ts @@ -8,3 +8,4 @@ export * from './node.js'; export * from './anvil_test_watcher.js'; export * from './field_compressed_string.js'; export * from './portal_manager.js'; +export * from './chain_monitor.js'; diff --git a/yarn-project/end-to-end/package.json b/yarn-project/end-to-end/package.json index 7f998abcfea..d6e63d75e3a 100644 --- a/yarn-project/end-to-end/package.json +++ b/yarn-project/end-to-end/package.json @@ -54,6 +54,7 @@ "@aztec/simulator": "workspace:^", "@aztec/telemetry-client": "workspace:^", "@aztec/types": "workspace:^", + "@aztec/validator-client": "workspace:^", "@aztec/world-state": "workspace:^", "@iarna/toml": "^2.2.5", "@jest/globals": "^29.5.0", diff --git a/yarn-project/end-to-end/src/e2e_epochs.test.ts b/yarn-project/end-to-end/src/e2e_epochs.test.ts index b6217c6206b..d3c32a3f4d0 100644 --- a/yarn-project/end-to-end/src/e2e_epochs.test.ts +++ b/yarn-project/end-to-end/src/e2e_epochs.test.ts @@ -1,4 +1,5 @@ import { type Logger, getTimestampRangeForEpoch, retryUntil, sleep } from '@aztec/aztec.js'; +import { ChainMonitor } from '@aztec/aztec.js/utils'; // eslint-disable-next-line no-restricted-imports import { type L1RollupConstants } from '@aztec/circuit-types'; import { Proof } from '@aztec/circuits.js'; @@ -25,11 +26,7 @@ describe('e2e_epochs', () => { let logger: Logger; let proverDelayer: Delayer; let sequencerDelayer: Delayer; - - let l2BlockNumber: number = 0; - let l2ProvenBlockNumber: number = 0; - let l1BlockNumber: number; - let handle: NodeJS.Timeout; + let monitor: ChainMonitor; const EPOCH_DURATION_IN_L2_SLOTS = 4; const L2_SLOT_DURATION_IN_L1_SLOTS = 2; @@ -59,34 +56,8 @@ describe('e2e_epochs', () => { rollup = RollupContract.getFromConfig(context.config); // Loop that tracks L1 and L2 block numbers and logs whenever there's a new one. - // We could refactor this out to an utility if we want to use this in other tests. - handle = setInterval(async () => { - const newL1BlockNumber = Number(await l1Client.getBlockNumber({ cacheTime: 0 })); - if (l1BlockNumber === newL1BlockNumber) { - return; - } - const block = await l1Client.getBlock({ blockNumber: BigInt(newL1BlockNumber), includeTransactions: false }); - const timestamp = block.timestamp; - l1BlockNumber = newL1BlockNumber; - - let msg = `L1 block ${newL1BlockNumber} mined at ${timestamp}`; - - const newL2BlockNumber = Number(await rollup.getBlockNumber()); - if (l2BlockNumber !== newL2BlockNumber) { - const epochNumber = await rollup.getEpochNumber(BigInt(newL2BlockNumber)); - msg += ` with new L2 block ${newL2BlockNumber} for epoch ${epochNumber}`; - l2BlockNumber = newL2BlockNumber; - } - - const newL2ProvenBlockNumber = Number(await rollup.getProvenBlockNumber()); - - if (l2ProvenBlockNumber !== newL2ProvenBlockNumber) { - const epochNumber = await rollup.getEpochNumber(BigInt(newL2ProvenBlockNumber)); - msg += ` with proof up to L2 block ${newL2ProvenBlockNumber} for epoch ${epochNumber}`; - l2ProvenBlockNumber = newL2ProvenBlockNumber; - } - logger.info(msg); - }, 200); + monitor = new ChainMonitor(rollup, logger); + monitor.start(); proverDelayer = ((context.proverNode as TestProverNode).publisher as TestL1Publisher).delayer!; sequencerDelayer = ((context.sequencer as TestSequencerClient).sequencer.publisher as TestL1Publisher).delayer!; @@ -106,8 +77,8 @@ describe('e2e_epochs', () => { }); afterEach(async () => { - clearInterval(handle); jest.restoreAllMocks(); + monitor.stop(); await context.teardown(); }); @@ -121,12 +92,12 @@ describe('e2e_epochs', () => { /** Waits until the given L2 block number is mined. */ const waitUntilL2BlockNumber = async (target: number) => { - await retryUntil(() => Promise.resolve(target === l2BlockNumber), `Wait until L2 block ${target}`, 60, 0.1); + await retryUntil(() => Promise.resolve(target === monitor.l2BlockNumber), `Wait until L2 block ${target}`, 60, 0.1); }; /** Waits until the given L2 block number is marked as proven. */ - const waitUntilProvenL2BlockNumber = async (target: number) => { - await retryUntil(() => Promise.resolve(target === l2ProvenBlockNumber), `Wait proven L2 block ${target}`, 60, 0.1); + const waitUntilProvenL2BlockNumber = async (t: number) => { + await retryUntil(() => Promise.resolve(t === monitor.l2ProvenBlockNumber), `Wait proven L2 block ${t}`, 60, 0.1); }; it('does not allow submitting proof after epoch end', async () => { @@ -169,7 +140,7 @@ describe('e2e_epochs', () => { logger.info(`Starting epoch 1 after L2 block ${blockNumberAtEndOfEpoch0}`); await waitUntilProvenL2BlockNumber(blockNumberAtEndOfEpoch0); - expect(l2BlockNumber).toEqual(blockNumberAtEndOfEpoch0); + expect(monitor.l2BlockNumber).toEqual(blockNumberAtEndOfEpoch0); logger.info(`Test succeeded`); }); @@ -199,7 +170,7 @@ describe('e2e_epochs', () => { logger.info(`Starting epoch 2`); // No proof for epoch zero should have landed during epoch one - expect(l2ProvenBlockNumber).toEqual(0); + expect(monitor.l2ProvenBlockNumber).toEqual(0); // Wait until the prover job finalises (and a bit more) and check that it aborted and never attempted to submit a tx logger.info(`Awaiting finalise epoch`); diff --git a/yarn-project/end-to-end/src/e2e_p2p/p2p_network.ts b/yarn-project/end-to-end/src/e2e_p2p/p2p_network.ts index ba092589a22..8331c217261 100644 --- a/yarn-project/end-to-end/src/e2e_p2p/p2p_network.ts +++ b/yarn-project/end-to-end/src/e2e_p2p/p2p_network.ts @@ -1,7 +1,8 @@ import { getSchnorrAccount } from '@aztec/accounts/schnorr'; import { type AztecNodeConfig, type AztecNodeService } from '@aztec/aztec-node'; import { type AccountWalletWithSecretKey } from '@aztec/aztec.js'; -import { L1TxUtils, getL1ContractsConfigEnvVars } from '@aztec/ethereum'; +import { ChainMonitor } from '@aztec/aztec.js/utils'; +import { L1TxUtils, RollupContract, getL1ContractsConfigEnvVars } from '@aztec/ethereum'; import { EthCheatCodesWithState } from '@aztec/ethereum/test'; import { type Logger, createLogger } from '@aztec/foundation/log'; import { RollupAbi, TestERC20Abi } from '@aztec/l1-artifacts'; @@ -38,6 +39,7 @@ export class P2PNetworkTest { private baseAccount; public logger: Logger; + public monitor!: ChainMonitor; public ctx!: SubsystemsContext; public attesterPrivateKeys: `0x${string}`[] = []; @@ -308,6 +310,9 @@ export class P2PNetworkTest { stallTimeMs: 1000, }, ); + + this.monitor = new ChainMonitor(RollupContract.getFromL1ContractsValues(this.ctx.deployL1ContractsValues)); + this.monitor.start(); } async stopNodes(nodes: AztecNodeService[]) { @@ -325,6 +330,7 @@ export class P2PNetworkTest { } async teardown() { + this.monitor.stop(); await this.bootstrapNode.stop(); await this.snapshotManager.teardown(); if (this.cleanupInterval) { diff --git a/yarn-project/end-to-end/src/e2e_p2p/reex.test.ts b/yarn-project/end-to-end/src/e2e_p2p/reex.test.ts index b91d154f1dc..ff5d183184e 100644 --- a/yarn-project/end-to-end/src/e2e_p2p/reex.test.ts +++ b/yarn-project/end-to-end/src/e2e_p2p/reex.test.ts @@ -2,9 +2,13 @@ import { type AztecNodeService } from '@aztec/aztec-node'; import { type SentTx, sleep } from '@aztec/aztec.js'; /* eslint-disable-next-line no-restricted-imports */ -import { BlockProposal, SignatureDomainSeparator, getHashedSignaturePayload } from '@aztec/circuit-types'; +import { BlockProposal, SignatureDomainSeparator, type Tx, getHashedSignaturePayload } from '@aztec/circuit-types'; +import { times } from '@aztec/foundation/collection'; +import { type PublicProcessorFactory, type PublicTxResult, type PublicTxSimulator } from '@aztec/simulator/server'; +import { type ValidatorClient } from '@aztec/validator-client'; +import { ReExFailedTxsError, ReExStateMismatchError, ReExTimeoutError } from '@aztec/validator-client/errors'; -import { beforeAll, describe, it, jest } from '@jest/globals'; +import { describe, it, jest } from '@jest/globals'; import fs from 'fs'; import { shouldCollectMetrics } from '../fixtures/fixtures.js'; @@ -14,71 +18,105 @@ import { submitComplexTxsTo } from './shared.js'; const NUM_NODES = 4; const NUM_TXS_PER_NODE = 1; -const BOOT_NODE_UDP_PORT = 41000; - -const DATA_DIR = './data/re-ex'; +const BASE_BOOT_NODE_UDP_PORT = 40000; +const BASE_DATA_DIR = './data/re-ex'; describe('e2e_p2p_reex', () => { let t: P2PNetworkTest; let nodes: AztecNodeService[]; + let bootNodeUdpPort: number = BASE_BOOT_NODE_UDP_PORT; + let dataDir: string; + let txs: SentTx[]; beforeAll(async () => { nodes = []; + bootNodeUdpPort += 1000; + dataDir = `${BASE_DATA_DIR}/${bootNodeUdpPort.toString()}`; t = await P2PNetworkTest.create({ testName: 'e2e_p2p_reex', numberOfNodes: NUM_NODES, - basePort: BOOT_NODE_UDP_PORT, + basePort: bootNodeUdpPort, // To collect metrics - run in aztec-packages `docker compose --profile metrics up` and set COLLECT_METRICS=true metricsPort: shouldCollectMetrics(), + initialConfig: { enforceTimeTable: true, txTimeoutMs: 30_000 }, }); - t.logger.verbose('Setup account'); + t.logger.info('Setup account'); await t.setupAccount(); - t.logger.verbose('Deploy spam contract'); + t.logger.info('Deploy spam contract'); await t.deploySpamContract(); - t.logger.verbose('Apply base snapshots'); + t.logger.info('Apply base snapshots'); await t.applyBaseSnapshots(); - t.logger.verbose('Setup nodes'); + t.logger.info('Setup snapshot manager'); await t.setup(); - }); - afterAll(async () => { - // shutdown all nodes. - await t.stopNodes(nodes); - await t.teardown(); - for (let i = 0; i < NUM_NODES; i++) { - fs.rmSync(`${DATA_DIR}-${i}`, { recursive: true, force: true }); - } - }); + t.logger.info('Stopping main node sequencer'); + await t.ctx.aztecNode.getSequencer()?.stop(); - it('validators should re-execute transactions before attesting', async () => { - // create the bootstrap node for the network if (!t.bootstrapNodeEnr) { throw new Error('Bootstrap node ENR is not available'); } - t.ctx.aztecNodeConfig.validatorReexecute = true; - + t.logger.info('Creating peer nodes'); nodes = await createNodes( - t.ctx.aztecNodeConfig, + { + ...t.ctx.aztecNodeConfig, + validatorReexecute: true, + minTxsPerBlock: NUM_TXS_PER_NODE + 1, + maxTxsPerBlock: NUM_TXS_PER_NODE, + }, t.ctx.dateProvider, t.bootstrapNodeEnr, NUM_NODES, - BOOT_NODE_UDP_PORT, - DATA_DIR, + bootNodeUdpPort, + dataDir, // To collect metrics - run in aztec-packages `docker compose --profile metrics up` and set COLLECT_METRICS=true shouldCollectMetrics(), ); - // Hook into the node and intercept re-execution logic, ensuring that it was infact called - const reExecutionSpies = []; - for (const node of nodes) { - // Make sure the nodes submit faulty proposals, in this case a faulty proposal is one where we remove one of the transactions - // Such that the calculated archive will be different! + // Wait a bit for peers to discover each other + t.logger.info('Waiting for peer discovery'); + await sleep(4000); + + // Submit the txs to the mempool. We submit a single set of txs, and then inject different behaviors + // into the vlaidator nodes to cause them to fail in different ways. + t.logger.info('Submitting txs'); + txs = await submitComplexTxsTo(t.logger, t.spamContract!, NUM_TXS_PER_NODE, { callPublic: true }); + }); + + afterAll(async () => { + // shutdown all nodes. + await t.stopNodes(nodes); + await t.teardown(); + for (let i = 0; i < NUM_NODES; i++) { + fs.rmSync(`${dataDir}-${i}`, { recursive: true, force: true }); + } + }); + + describe('validators re-execute transactions before attesting', () => { + // Keep track of txs we have seen, so we do not intercept the simulate call on the first run (the block-proposer's) + let seenTxs: Set; + beforeEach(() => { + seenTxs = new Set(); + }); + + // Hold off sequencers from building a block + const pauseProposals = () => + Promise.all( + nodes.map(node => node.getSequencer()?.updateSequencerConfig({ minTxsPerBlock: NUM_TXS_PER_NODE + 1 })), + ); + + // Reenable them + const resumeProposals = () => + Promise.all(nodes.map(node => node.getSequencer()?.updateSequencerConfig({ minTxsPerBlock: NUM_TXS_PER_NODE }))); + + // Make sure the nodes submit faulty proposals, in this case a faulty proposal is one where we remove one of the transactions + // Such that the calculated archive will be different! + const interceptBroadcastProposal = (node: AztecNodeService) => { jest.spyOn((node as any).p2pClient, 'broadcastProposal').mockImplementation(async (...args: unknown[]) => { // We remove one of the transactions, therefore the block root will be different! const proposal = args[0] as BlockProposal; @@ -97,40 +135,103 @@ describe('e2e_p2p_reex', () => { return (node as any).p2pClient.p2pService.propagate(newProposal); }); - - // Store re-execution spys node -> sequencer Client -> seqeuncer -> validator - const spy = jest.spyOn((node as any).sequencer.sequencer.validatorClient, 'reExecuteTransactions'); - reExecutionSpies.push(spy); - } - - // wait a bit for peers to discover each other - await sleep(4000); - - nodes.forEach(node => { - node.getSequencer()?.updateSequencerConfig({ - minTxsPerBlock: NUM_TXS_PER_NODE, - maxTxsPerBlock: NUM_TXS_PER_NODE, + }; + + // Intercepts the simulator within the tx processor within the processor factory with the given function + // Only the processor for validators is intercepted, the one for the proposer is left untouched + // We abuse the fact that the proposer will always run before the validators + const interceptTxProcessorSimulate = ( + node: AztecNodeService, + stub: (tx: Tx, originalSimulate: (tx: Tx) => Promise) => Promise, + ) => { + const processorFactory: PublicProcessorFactory = (node as any).sequencer.sequencer.publicProcessorFactory; + const originalCreate = processorFactory.create.bind(processorFactory); + jest + .spyOn(processorFactory, 'create') + .mockImplementation((...args: Parameters) => { + const processor = originalCreate(...args); + t.logger.warn('Creating mocked processor factory'); + const simulator: PublicTxSimulator = (processor as any).publicTxSimulator; + const originalSimulate = simulator.simulate.bind(simulator); + // We only stub the simulate method if it's NOT the first time we see the tx + // so the proposer works fine, but we cause the failure in the validators. + jest.spyOn(simulator, 'simulate').mockImplementation((tx: Tx) => { + const txHash = tx.getTxHash().toString(); + if (seenTxs.has(txHash)) { + t.logger.warn('Calling stubbed simulate for tx', { txHash }); + return stub(tx, originalSimulate); + } else { + seenTxs.add(txHash); + t.logger.warn('Calling original simulate for tx', { txHash }); + return originalSimulate(tx); + } + }); + return processor; + }); + }; + + // Have the public tx processor take an extra long time to process the tx, so the validator times out + const interceptTxProcessorWithTimeout = (node: AztecNodeService) => { + interceptTxProcessorSimulate(node, async (tx: Tx, originalSimulate: (tx: Tx) => Promise) => { + t.logger.warn('Public tx simulator sleeping for 40s to simulate timeout', { txHash: tx.getTxHash() }); + await sleep(40_000); + return originalSimulate(tx); }); - }); - const txs = await submitComplexTxsTo(t.logger, t.spamContract!, NUM_TXS_PER_NODE); - - // We ensure that the transactions are NOT mined - try { - await Promise.all( - txs.map(async (tx: SentTx, i: number) => { - t.logger.info(`Waiting for tx ${i}: ${await tx.getTxHash()} to be mined`); - return tx.wait(); - }), - ); - } catch (e) { - t.logger.info('Failed to mine all txs, as planned'); - } + }; + + // Have the public tx processor throw when processing a tx + const interceptTxProcessorWithFailure = (node: AztecNodeService) => { + interceptTxProcessorSimulate(node, async (tx: Tx, _originalSimulate: (tx: Tx) => Promise) => { + await sleep(1); + t.logger.warn('Public tx simulator failing', { txHash: tx.getTxHash() }); + throw new Error(`Fake tx failure`); + }); + }; + + it.each([ + ['ReExStateMismatchError', new ReExStateMismatchError().message, interceptBroadcastProposal], + ['ReExTimeoutError', new ReExTimeoutError().message, interceptTxProcessorWithTimeout], + ['ReExFailedTxsError', new ReExFailedTxsError(1).message, interceptTxProcessorWithFailure], + ])( + 'rejects proposal with %s', + async (_errType: string, errMsg: string, nodeInterceptor: (node: AztecNodeService) => void) => { + await pauseProposals(); + + // Hook into the node and intercept re-execution logic + t.logger.info('Installing interceptors'); + jest.restoreAllMocks(); + const reExecutionSpies = []; + for (const node of nodes) { + nodeInterceptor(node); + // Collect re-execution spies + reExecutionSpies.push( + jest.spyOn((node as any).sequencer.sequencer.validatorClient as ValidatorClient, 'reExecuteTransactions'), + ); + } + + // Start a fresh slot and resume proposals + await t.ctx.cheatCodes.rollup.advanceToNextSlot(); + await resumeProposals(); + + // We ensure that the transactions are NOT mined in the next slot + const txResults = await Promise.allSettled( + txs.map(async (tx: SentTx, i: number) => { + t.logger.info(`Waiting for tx ${i}: ${await tx.getTxHash()} to be mined`); + return tx.wait({ timeout: 24 }); + }), + ); - // Expect that all of the re-execution attempts failed with an invalid root - for (const spy of reExecutionSpies) { - for (const result of spy.mock.results) { - await expect(result.value).rejects.toThrow('Validator Error: Re-execution state mismatch'); - } - } + // Check that txs are not mined + expect(txResults.map(r => r.status)).toEqual(times(NUM_TXS_PER_NODE, () => 'rejected')); + t.logger.info('Failed to mine txs as planned'); + + // Expect that all of the re-execution attempts failed with an invalid root + for (const spy of reExecutionSpies) { + for (const result of spy.mock.results) { + await expect(result.value).rejects.toThrow(errMsg); + } + } + }, + ); }); }); diff --git a/yarn-project/end-to-end/src/e2e_p2p/shared.ts b/yarn-project/end-to-end/src/e2e_p2p/shared.ts index 5ff6a421157..07347e224dc 100644 --- a/yarn-project/end-to-end/src/e2e_p2p/shared.ts +++ b/yarn-project/end-to-end/src/e2e_p2p/shared.ts @@ -9,13 +9,20 @@ import { type PXEService, createPXEService, getPXEServiceConfig as getRpcConfig import { type NodeContext } from '../fixtures/setup_p2p_test.js'; // submits a set of transactions to the provided Private eXecution Environment (PXE) -export const submitComplexTxsTo = async (logger: Logger, spamContract: SpamContract, numTxs: number) => { +export const submitComplexTxsTo = async ( + logger: Logger, + spamContract: SpamContract, + numTxs: number, + opts: { callPublic?: boolean } = {}, +) => { const txs: SentTx[] = []; const seed = 1234n; const spamCount = 15; for (let i = 0; i < numTxs; i++) { - const tx = spamContract.methods.spam(seed + BigInt(i * spamCount), spamCount, false).send(); + const tx = spamContract.methods + .spam(seed + BigInt(i * spamCount), spamCount, !!opts.callPublic) + .send({ skipPublicSimulation: true }); const txHash = await tx.getTxHash(); logger.info(`Tx sent with hash ${txHash}`); diff --git a/yarn-project/end-to-end/src/fixtures/setup_p2p_test.ts b/yarn-project/end-to-end/src/fixtures/setup_p2p_test.ts index 5ddcc3b6ee2..cfdfc1fd544 100644 --- a/yarn-project/end-to-end/src/fixtures/setup_p2p_test.ts +++ b/yarn-project/end-to-end/src/fixtures/setup_p2p_test.ts @@ -2,12 +2,14 @@ * Test fixtures and utilities to set up and run a test using multiple validators */ import { type AztecNodeConfig, AztecNodeService } from '@aztec/aztec-node'; -import { type SentTx, createLogger } from '@aztec/aztec.js'; +import { type SentTx } from '@aztec/aztec.js'; import { type AztecAddress } from '@aztec/circuits.js'; +import { addLogNameHandler, removeLogNameHandler } from '@aztec/foundation/log'; import { type DateProvider } from '@aztec/foundation/timer'; import { type PXEService } from '@aztec/pxe'; import getPort from 'get-port'; +import { AsyncLocalStorage } from 'node:async_hooks'; import { TEST_PEER_CHECK_INTERVAL_MS } from './fixtures.js'; import { getPrivateKeyFromIndex } from './utils.js'; @@ -34,7 +36,7 @@ export function generatePrivateKeys(startIndex: number, numberOfKeys: number): ` return privateKeys; } -export function createNodes( +export async function createNodes( config: AztecNodeConfig, dateProvider: DateProvider, bootstrapNodeEnr: string, @@ -43,16 +45,32 @@ export function createNodes( dataDirectory?: string, metricsPort?: number, ): Promise { - const nodePromises = []; + const nodePromises: Promise[] = []; + const loggerIdStorage = new AsyncLocalStorage(); + const logNameHandler = (module: string) => + loggerIdStorage.getStore() ? `${module}:${loggerIdStorage.getStore()}` : module; + addLogNameHandler(logNameHandler); + for (let i = 0; i < numNodes; i++) { // We run on ports from the bootnode upwards const port = bootNodePort + i + 1; const dataDir = dataDirectory ? `${dataDirectory}-${i}` : undefined; - const nodePromise = createNode(config, dateProvider, port, bootstrapNodeEnr, i, dataDir, metricsPort); + const nodePromise = createNode( + config, + dateProvider, + port, + bootstrapNodeEnr, + i, + dataDir, + metricsPort, + loggerIdStorage, + ); nodePromises.push(nodePromise); } - return Promise.all(nodePromises); + const nodes = await Promise.all(nodePromises); + removeLogNameHandler(logNameHandler); + return nodes; } // creates a P2P enabled instance of Aztec Node Service @@ -64,16 +82,14 @@ export async function createNode( accountIndex: number, dataDirectory?: string, metricsPort?: number, + loggerIdStorage?: AsyncLocalStorage, ) { - const validatorConfig = await createValidatorConfig(config, bootstrapNode, tcpPort, accountIndex, dataDirectory); - - const telemetryClient = await getEndToEndTestTelemetryClient(metricsPort); - - return await AztecNodeService.createAndSync(validatorConfig, { - telemetry: telemetryClient, - logger: createLogger(`node:${tcpPort}`), - dateProvider, - }); + const createNode = async () => { + const validatorConfig = await createValidatorConfig(config, bootstrapNode, tcpPort, accountIndex, dataDirectory); + const telemetry = await getEndToEndTestTelemetryClient(metricsPort); + return await AztecNodeService.createAndSync(validatorConfig, { telemetry, dateProvider }); + }; + return loggerIdStorage ? await loggerIdStorage.run(tcpPort.toString(), createNode) : createNode(); } export async function createValidatorConfig( diff --git a/yarn-project/end-to-end/tsconfig.json b/yarn-project/end-to-end/tsconfig.json index a8117b5a5db..15793f32a2c 100644 --- a/yarn-project/end-to-end/tsconfig.json +++ b/yarn-project/end-to-end/tsconfig.json @@ -84,6 +84,9 @@ { "path": "../types" }, + { + "path": "../validator-client" + }, { "path": "../world-state" } diff --git a/yarn-project/ethereum/src/contracts/rollup.ts b/yarn-project/ethereum/src/contracts/rollup.ts index 69bc1065653..cbaf9d689e0 100644 --- a/yarn-project/ethereum/src/contracts/rollup.ts +++ b/yarn-project/ethereum/src/contracts/rollup.ts @@ -1,3 +1,4 @@ +import { AztecAddress } from '@aztec/foundation/aztec-address'; import { memoize } from '@aztec/foundation/decorators'; import { RollupAbi } from '@aztec/l1-artifacts'; @@ -12,16 +13,21 @@ import { http, } from 'viem'; +import { type DeployL1Contracts } from '../deploy_l1_contracts.js'; import { createEthereumChain } from '../ethereum_chain.js'; import { type L1ReaderConfig } from '../l1_reader.js'; export class RollupContract { private readonly rollup: GetContractReturnType>; - constructor(client: PublicClient, address: Hex) { + constructor(public readonly client: PublicClient, address: Hex) { this.rollup = getContract({ address, abi: RollupAbi, client }); } + public get address() { + return AztecAddress.fromString(this.rollup.address); + } + @memoize getL1StartBlock() { return this.rollup.read.L1_BLOCK_AT_GENESIS(); @@ -69,6 +75,14 @@ export class RollupContract { return this.rollup.read.getEpochForBlock([BigInt(blockNumber)]); } + static getFromL1ContractsValues(deployL1ContractsValues: DeployL1Contracts) { + const { + publicClient, + l1ContractAddresses: { rollupAddress }, + } = deployL1ContractsValues; + return new RollupContract(publicClient, rollupAddress.toString()); + } + static getFromConfig(config: L1ReaderConfig) { const client = createPublicClient({ transport: http(config.l1RpcUrl), diff --git a/yarn-project/foundation/src/log/pino-logger.ts b/yarn-project/foundation/src/log/pino-logger.ts index f8e74948314..21772b4bc59 100644 --- a/yarn-project/foundation/src/log/pino-logger.ts +++ b/yarn-project/foundation/src/log/pino-logger.ts @@ -10,7 +10,7 @@ import { type LogLevel } from './log-levels.js'; import { type LogData, type LogFn } from './log_fn.js'; export function createLogger(module: string): Logger { - module = module.replace(/^aztec:/, ''); + module = logNameHandlers.reduce((moduleName, handler) => handler(moduleName), module.replace(/^aztec:/, '')); const pinoLogger = logger.child({ module }, { level: getLogLevelFromFilters(logFilters, module) }); // We check manually for isLevelEnabled to avoid calling processLogData unnecessarily. @@ -56,6 +56,22 @@ function processLogData(data: LogData): LogData { return logDataHandlers.reduce((accum, handler) => handler(accum), data); } +// Allow global hooks for tweaking module names. +// Used in tests to add a uid to modules, so we can differentiate multiple nodes in the same process. +type LogNameHandler = (module: string) => string; +const logNameHandlers: LogNameHandler[] = []; + +export function addLogNameHandler(handler: LogNameHandler): void { + logNameHandlers.push(handler); +} + +export function removeLogNameHandler(handler: LogNameHandler) { + const index = logNameHandlers.indexOf(handler); + if (index !== -1) { + logNameHandlers.splice(index, 1); + } +} + // Patch isLevelEnabled missing from pino/browser. function isLevelEnabled(logger: pino.Logger<'verbose', boolean>, level: LogLevel): boolean { return typeof logger.isLevelEnabled === 'function' diff --git a/yarn-project/sequencer-client/src/sequencer/sequencer.ts b/yarn-project/sequencer-client/src/sequencer/sequencer.ts index 68f634ea878..69336ddf2f1 100644 --- a/yarn-project/sequencer-client/src/sequencer/sequencer.ts +++ b/yarn-project/sequencer-client/src/sequencer/sequencer.ts @@ -36,6 +36,8 @@ import { type PublicProcessorFactory } from '@aztec/simulator/server'; import { Attributes, type TelemetryClient, type Tracer, trackSpan } from '@aztec/telemetry-client'; import { type ValidatorClient } from '@aztec/validator-client'; +import assert from 'assert'; + import { type GlobalVariableBuilder } from '../global_variable_builder/global_builder.js'; import { type L1Publisher, VoteType } from '../publisher/l1-publisher.js'; import { type SlasherClient } from '../slasher/slasher_client.js'; @@ -86,6 +88,7 @@ export class Sequencer { private maxBlockSizeInBytes: number = 1024 * 1024; private maxBlockGas: Gas = new Gas(10e9, 10e9); protected processTxTime: number = 12; + private attestationPropagationTime: number = 2; private metrics: SequencerMetrics; private isFlushing: boolean = false; @@ -168,7 +171,9 @@ export class Sequencer { if (config.maxL1TxInclusionTimeIntoSlot !== undefined) { this.maxL1TxInclusionTimeIntoSlot = config.maxL1TxInclusionTimeIntoSlot; } - this.enforceTimeTable = config.enforceTimeTable === true; + if (config.enforceTimeTable !== undefined) { + this.enforceTimeTable = config.enforceTimeTable; + } this.setTimeTable(); @@ -183,15 +188,17 @@ export class Sequencer { // How long it takes to get ready to start building const blockPrepareTime = 1; - // How long it takes to for attestations to travel across the p2p layer. + // How long it takes to for proposals and attestations to travel across the p2p layer (one-way) const attestationPropagationTime = 2; + this.attestationPropagationTime = attestationPropagationTime; // How long it takes to get a published block into L1. L1 builders typically accept txs up to 4 seconds into their slot, // but we'll timeout sooner to give it more time to propagate (remember we also have blobs!). Still, when working in anvil, - // we can just post in the very last second of the L1 slot. + // we can just post in the very last second of the L1 slot and still expect the tx to be accepted. const l1PublishingTime = this.l1Constants.ethereumSlotDuration - this.maxL1TxInclusionTimeIntoSlot; - // How much time we spend validating and processing a block after building it + // How much time we spend validating and processing a block after building it, + // and assembling the proposal to send to attestors const blockValidationTime = 1; // How much time we have left in the slot for actually processing txs and building the block. @@ -199,11 +206,11 @@ export class Sequencer { this.aztecSlotDuration - initialTime - blockPrepareTime - - l1PublishingTime - + blockValidationTime - 2 * attestationPropagationTime - - blockValidationTime; + l1PublishingTime; - // Check that numbers make sense + // Check that we actually have time left for processing txs if (this.enforceTimeTable && remainingTimeInSlot < 0) { throw new Error(`Not enough time for block building in ${this.aztecSlotDuration}s slot`); } @@ -212,6 +219,22 @@ export class Sequencer { const processTxsTime = remainingTimeInSlot / 2; this.processTxTime = processTxsTime; + // Sanity check + const totalSlotTime = + initialTime + // Archiver, world-state, and p2p sync + blockPrepareTime + // Setup globals, initial checks, etc + processTxsTime + // Processing public txs for building the block + blockValidationTime + // Validating the block produced + attestationPropagationTime + // Propagating the block proposal to validators + processTxsTime + // Validators run public txs before signing + attestationPropagationTime + // Attestations fly back to the proposer + l1PublishingTime; // The publish tx sits on the L1 mempool waiting to be picked up + + assert( + totalSlotTime === this.aztecSlotDuration, + `Computed total slot time does not match slot duration: ${totalSlotTime}s`, + ); + const newTimeTable: Record = { // No checks needed for any of these transitions [SequencerState.STOPPED]: this.aztecSlotDuration, @@ -472,7 +495,12 @@ export class Sequencer { const l1ToL2Messages = await this.l1ToL2MessageSource.getL1ToL2Messages(blockNumber); const msgCount = l1ToL2Messages.length; - this.log.verbose(`Building block ${blockNumber} for slot ${slot}`, { slot, blockNumber, msgCount }); + this.log.verbose(`Building block ${blockNumber} for slot ${slot}`, { + slot, + blockNumber, + msgCount, + validator: opts.validateOnly, + }); // Sync to the previous block at least await this.worldState.syncImmediate(newGlobalVariables.blockNumber.toNumber() - 1); @@ -493,12 +521,19 @@ export class Sequencer { const blockBuilder = this.blockBuilderFactory.create(orchestratorFork); await blockBuilder.startNewBlock(newGlobalVariables, l1ToL2Messages); - // We set the deadline for tx processing to the start of the CREATING_BLOCK phase, plus the expected time for tx processing. + // When building a block as a proposer, we set the deadline for tx processing to the start of the + // CREATING_BLOCK phase, plus the expected time for tx processing. When validating, we start counting + // the time for tx processing from the start of the COLLECTING_ATTESTATIONS phase plus the attestation + // propagation time. See the comments in setTimeTable for more details. + const processingEndTimeWithinSlot = opts.validateOnly + ? this.timeTable[SequencerState.COLLECTING_ATTESTATIONS] + this.attestationPropagationTime + this.processTxTime + : this.timeTable[SequencerState.CREATING_BLOCK] + this.processTxTime; + // Deadline is only set if enforceTimeTable is enabled. - const processingEndTimeWithinSlot = this.timeTable[SequencerState.CREATING_BLOCK] + this.processTxTime; const deadline = this.enforceTimeTable ? new Date((this.getSlotStartTimestamp(slot) + processingEndTimeWithinSlot) * 1000) : undefined; + this.log.verbose(`Processing pending txs`, { slot, slotStart: new Date(this.getSlotStartTimestamp(slot) * 1000), @@ -514,7 +549,7 @@ export class Sequencer { this.allowedInSetup, ); - // REFACTOR: Public processor should just handle processing, one tx at a time. It should be responsibility + // TODO(#11000): Public processor should just handle processing, one tx at a time. It should be responsibility // of the sequencer to update world state and iterate over txs. We should refactor this along with unifying the // publicProcessorFork and orchestratorFork, to avoid doing tree insertions twice when building the block. const limits = { deadline, maxTransactions: this.maxTxsPerBlock, maxBlockSize: this.maxBlockSizeInBytes }; @@ -522,7 +557,7 @@ export class Sequencer { processor.process(pendingTxs, limits, validators), ); - if (failedTxs.length > 0) { + if (!opts.validateOnly && failedTxs.length > 0) { const failedTxData = failedTxs.map(fail => fail.tx); this.log.verbose(`Dropping failed txs ${Tx.getHashes(failedTxData).join(', ')}`); await this.p2pClient.deleteTxs(Tx.getHashes(failedTxData)); @@ -555,6 +590,7 @@ export class Sequencer { publicProcessorDuration, numMsgs: l1ToL2Messages.length, numTxs: processedTxs.length, + numFailedTxs: failedTxs.length, blockBuildingTimer, }; } finally { diff --git a/yarn-project/validator-client/package.json b/yarn-project/validator-client/package.json index d0b6efa372c..cba8738eb21 100644 --- a/yarn-project/validator-client/package.json +++ b/yarn-project/validator-client/package.json @@ -5,7 +5,8 @@ "type": "module", "exports": { ".": "./dest/index.js", - "./config": "./dest/config.js" + "./config": "./dest/config.js", + "./errors": "./dest/errors/index.js" }, "bin": "./dest/bin/index.js", "typedocOptions": { diff --git a/yarn-project/validator-client/src/errors/validator.error.ts b/yarn-project/validator-client/src/errors/validator.error.ts index c19b118f398..2075b94953e 100644 --- a/yarn-project/validator-client/src/errors/validator.error.ts +++ b/yarn-project/validator-client/src/errors/validator.error.ts @@ -36,6 +36,18 @@ export class ReExStateMismatchError extends ValidatorError { } } +export class ReExFailedTxsError extends ValidatorError { + constructor(numFailedTxs: number) { + super(`Re-execution failed to process ${numFailedTxs} txs`); + } +} + +export class ReExTimeoutError extends ValidatorError { + constructor() { + super('Re-execution timed out or failed to process all txs in the proposal'); + } +} + export class BlockBuilderNotProvidedError extends ValidatorError { constructor() { super('Block builder not provided'); diff --git a/yarn-project/validator-client/src/validator.ts b/yarn-project/validator-client/src/validator.ts index 09c19eac82b..6d5d55a4553 100644 --- a/yarn-project/validator-client/src/validator.ts +++ b/yarn-project/validator-client/src/validator.ts @@ -18,7 +18,9 @@ import { AttestationTimeoutError, BlockBuilderNotProvidedError, InvalidValidatorPrivateKeyError, + ReExFailedTxsError, ReExStateMismatchError, + ReExTimeoutError, TransactionsNotAvailableError, } from './errors/validator.error.js'; import { type ValidatorKeyStore } from './key_store/interface.js'; @@ -35,7 +37,13 @@ type BlockBuilderCallback = ( globalVariables: GlobalVariables, historicalHeader?: BlockHeader, opts?: { validateOnly?: boolean }, -) => Promise<{ block: L2Block; publicProcessorDuration: number; numTxs: number; blockBuildingTimer: Timer }>; +) => Promise<{ + block: L2Block; + publicProcessorDuration: number; + numTxs: number; + numFailedTxs: number; + blockBuildingTimer: Timer; +}>; export interface Validator { start(): Promise; @@ -235,11 +243,23 @@ export class ValidatorClient extends WithTracer implements Validator { // Use the sequencer's block building logic to re-execute the transactions const stopTimer = this.metrics.reExecutionTimer(); - const { block } = await this.blockBuilder(txs, header.globalVariables, undefined, { validateOnly: true }); + const { block, numFailedTxs } = await this.blockBuilder(txs, header.globalVariables, undefined, { + validateOnly: true, + }); stopTimer(); this.log.verbose(`Transaction re-execution complete`); + if (numFailedTxs > 0) { + this.metrics.recordFailedReexecution(proposal); + throw new ReExFailedTxsError(numFailedTxs); + } + + if (block.body.txEffects.length !== txHashes.length) { + this.metrics.recordFailedReexecution(proposal); + throw new ReExTimeoutError(); + } + // This function will throw an error if state updates do not match if (!block.archive.root.equals(proposal.archive)) { this.metrics.recordFailedReexecution(proposal); diff --git a/yarn-project/yarn.lock b/yarn-project/yarn.lock index 9d7882a01cb..74d6e1cc21e 100644 --- a/yarn-project/yarn.lock +++ b/yarn-project/yarn.lock @@ -582,6 +582,7 @@ __metadata: "@aztec/simulator": "workspace:^" "@aztec/telemetry-client": "workspace:^" "@aztec/types": "workspace:^" + "@aztec/validator-client": "workspace:^" "@aztec/world-state": "workspace:^" "@iarna/toml": "npm:^2.2.5" "@jest/globals": "npm:^29.5.0"