diff --git a/yarn-project/aztec-node/src/aztec-node/server.ts b/yarn-project/aztec-node/src/aztec-node/server.ts index ebc1acae4d93..06d218d6c441 100644 --- a/yarn-project/aztec-node/src/aztec-node/server.ts +++ b/yarn-project/aztec-node/src/aztec-node/server.ts @@ -1172,7 +1172,7 @@ export class AztecNodeService implements AztecNode, AztecNodeAdmin, Traceable { const processor = publicProcessorFactory.create(merkleTreeFork, newGlobalVariables, config); // REFACTOR: Consider merging ProcessReturnValues into ProcessedTx - const [processedTxs, failedTxs, _usedTxs, returns] = await processor.process([tx]); + const [processedTxs, failedTxs, _usedTxs, returns, _blobFields, debugLogs] = await processor.process([tx]); // REFACTOR: Consider returning the error rather than throwing if (failedTxs.length) { this.log.warn(`Simulated tx ${txHash} fails: ${failedTxs[0].error}`, { txHash }); @@ -1186,6 +1186,7 @@ export class AztecNodeService implements AztecNode, AztecNodeAdmin, Traceable { processedTx.txEffect, returns, processedTx.gasUsed, + debugLogs, ); } finally { await merkleTreeFork.close(); diff --git a/yarn-project/prover-node/src/job/epoch-proving-job.test.ts b/yarn-project/prover-node/src/job/epoch-proving-job.test.ts index 93a5920cb80d..c94818623302 100644 --- a/yarn-project/prover-node/src/job/epoch-proving-job.test.ts +++ b/yarn-project/prover-node/src/job/epoch-proving-job.test.ts @@ -134,7 +134,7 @@ describe('epoch-proving-job', () => { publicProcessor.process.mockImplementation(async txs => { const txsArray = await toArray(txs); const processedTxs = await Promise.all(txsArray.map(tx => mock({ hash: tx.getTxHash() }))); - return [processedTxs, [], txsArray, [], 0]; + return [processedTxs, [], txsArray, [], 0, []]; }); }); @@ -179,7 +179,7 @@ describe('epoch-proving-job', () => { publicProcessor.process.mockImplementation(async txs => { const txsArray = await toArray(txs); const errors = txsArray.map(tx => ({ error: new Error('Failed to process tx'), tx })); - return [[], errors, [], [], 0]; + return [[], errors, [], [], 0, []]; }); const job = createJob(); @@ -190,7 +190,7 @@ describe('epoch-proving-job', () => { }); it('fails if does not process all txs for a block', async () => { - publicProcessor.process.mockImplementation(_txs => Promise.resolve([[], [], [], [], 0])); + publicProcessor.process.mockImplementation(_txs => Promise.resolve([[], [], [], [], 0, []])); const job = createJob(); await job.run(); diff --git a/yarn-project/pxe/src/contract_function_simulator/oracle/utility_execution_oracle.ts b/yarn-project/pxe/src/contract_function_simulator/oracle/utility_execution_oracle.ts index 00242b8bb925..f957d44326a8 100644 --- a/yarn-project/pxe/src/contract_function_simulator/oracle/utility_execution_oracle.ts +++ b/yarn-project/pxe/src/contract_function_simulator/oracle/utility_execution_oracle.ts @@ -3,7 +3,7 @@ import type { BlockNumber } from '@aztec/foundation/branded-types'; import { Aes128 } from '@aztec/foundation/crypto/aes128'; import { Fr } from '@aztec/foundation/curves/bn254'; import { Point } from '@aztec/foundation/curves/grumpkin'; -import { LogLevels, type Logger, applyStringFormatting, createLogger } from '@aztec/foundation/log'; +import { LogLevels, type Logger, createLogger } from '@aztec/foundation/log'; import type { MembershipWitness } from '@aztec/foundation/trees'; import type { KeyStore } from '@aztec/key-store'; import type { AuthWitness } from '@aztec/stdlib/auth-witness'; @@ -21,6 +21,7 @@ import { MerkleTreeId, type NullifierMembershipWitness, PublicDataWitness } from import type { BlockHeader, Capsule } from '@aztec/stdlib/tx'; import type { AccessScopes } from '../../access_scopes.js'; +import { createContractLogger, logContractMessage } from '../../contract_logging.js'; import { EventService } from '../../events/event_service.js'; import { LogService } from '../../logs/log_service.js'; import { NoteService } from '../../notes/note_service.js'; @@ -402,12 +403,13 @@ export class UtilityExecutionOracle implements IMiscOracle, IUtilityExecutionOra */ async #getContractLogger(): Promise { if (!this.contractLogger) { - const addrAbbrev = this.contractAddress.toString().slice(0, 10); - const name = await this.contractStore.getDebugContractName(this.contractAddress); - const module = name ? `contract_log::${name}(${addrAbbrev})` : `contract_log::${addrAbbrev}`; // Purpose of instanceId is to distinguish logs from different instances of the same component. It makes sense // to re-use jobId as instanceId here as executions of different PXE jobs are isolated. - this.contractLogger = createLogger(module, { instanceId: this.jobId }); + this.contractLogger = await createContractLogger( + this.contractAddress, + addr => this.contractStore.getDebugContractName(addr), + { instanceId: this.jobId }, + ); } return this.contractLogger; } @@ -416,9 +418,8 @@ export class UtilityExecutionOracle implements IMiscOracle, IUtilityExecutionOra if (!LogLevels[level]) { throw new Error(`Invalid log level: ${level}`); } - const levelName = LogLevels[level]; const logger = await this.#getContractLogger(); - logger[levelName](`${applyStringFormatting(message, fields)}`); + logContractMessage(logger, LogLevels[level], message, fields); } public async utilityFetchTaggedLogs(pendingTaggedLogArrayBaseSlot: Fr) { diff --git a/yarn-project/pxe/src/contract_logging.ts b/yarn-project/pxe/src/contract_logging.ts new file mode 100644 index 000000000000..cb32e2026fa1 --- /dev/null +++ b/yarn-project/pxe/src/contract_logging.ts @@ -0,0 +1,39 @@ +import type { Fr } from '@aztec/foundation/curves/bn254'; +import { type LogLevel, type Logger, applyStringFormatting, createLogger } from '@aztec/foundation/log'; +import type { AztecAddress } from '@aztec/stdlib/aztec-address'; +import type { DebugLog } from '@aztec/stdlib/logs'; + +/** Resolves a contract address to a human-readable name, if available. */ +export type ContractNameResolver = (address: AztecAddress) => Promise; + +/** + * Creates a logger whose output is prefixed with `contract_log::()`. + */ +export async function createContractLogger( + contractAddress: AztecAddress, + getContractName: ContractNameResolver, + options?: { instanceId?: string }, +): Promise { + const addrAbbrev = contractAddress.toString().slice(0, 10); + const name = await getContractName(contractAddress); + const module = name ? `contract_log::${name}(${addrAbbrev})` : `contract_log::Unknown(${addrAbbrev})`; + return createLogger(module, options); +} + +/** + * Formats and emits a single contract log message through the given logger. + */ +export function logContractMessage(logger: Logger, level: LogLevel, message: string, fields: Fr[]): void { + logger[level](applyStringFormatting(message, fields)); +} + +/** + * Displays debug logs collected during public function simulation, + * using the `contract_log::` prefixed logger format. + */ +export async function displayDebugLogs(debugLogs: DebugLog[], getContractName: ContractNameResolver): Promise { + for (const log of debugLogs) { + const logger = await createContractLogger(log.contractAddress, getContractName); + logContractMessage(logger, log.level, log.message, log.fields); + } +} diff --git a/yarn-project/pxe/src/entrypoints/client/bundle/index.ts b/yarn-project/pxe/src/entrypoints/client/bundle/index.ts index e532ec2b7b8a..d854f0abf873 100644 --- a/yarn-project/pxe/src/entrypoints/client/bundle/index.ts +++ b/yarn-project/pxe/src/entrypoints/client/bundle/index.ts @@ -3,6 +3,7 @@ export * from '../../../notes_filter.js'; export * from '../../../pxe.js'; export * from '../../../config/index.js'; export * from '../../../error_enriching.js'; +export * from '../../../contract_logging.js'; export * from '../../../storage/index.js'; export * from './utils.js'; export type { PXECreationOptions } from '../../pxe_creation_options.js'; diff --git a/yarn-project/pxe/src/entrypoints/client/lazy/index.ts b/yarn-project/pxe/src/entrypoints/client/lazy/index.ts index 5efe9b4e4ec6..17b4025cbf74 100644 --- a/yarn-project/pxe/src/entrypoints/client/lazy/index.ts +++ b/yarn-project/pxe/src/entrypoints/client/lazy/index.ts @@ -4,5 +4,6 @@ export * from '../../../pxe.js'; export * from '../../../config/index.js'; export * from '../../../storage/index.js'; export * from '../../../error_enriching.js'; +export * from '../../../contract_logging.js'; export * from './utils.js'; export { type PXECreationOptions } from '../../pxe_creation_options.js'; diff --git a/yarn-project/pxe/src/pxe.ts b/yarn-project/pxe/src/pxe.ts index 206809206590..d3819da91aad 100644 --- a/yarn-project/pxe/src/pxe.ts +++ b/yarn-project/pxe/src/pxe.ts @@ -61,6 +61,7 @@ import { generateSimulatedProvingResult, } from './contract_function_simulator/contract_function_simulator.js'; import { ProxiedContractStoreFactory } from './contract_function_simulator/proxied_contract_data_source.js'; +import { displayDebugLogs } from './contract_logging.js'; import { ContractSyncService } from './contract_sync/contract_sync_service.js'; import { readCurrentClassId } from './contract_sync/helpers.js'; import { PXEDebugUtils } from './debug/pxe_debug_utils.js'; @@ -947,6 +948,9 @@ export class PXE { const publicSimulationTimer = new Timer(); publicOutput = await this.#simulatePublicCalls(simulatedTx, skipFeeEnforcement); publicSimulationTime = publicSimulationTimer.ms(); + if (publicOutput?.debugLogs?.length) { + await displayDebugLogs(publicOutput.debugLogs, addr => this.contractStore.getDebugContractName(addr)); + } } let validationTime: number | undefined; diff --git a/yarn-project/simulator/src/public/public_processor/public_processor.ts b/yarn-project/simulator/src/public/public_processor/public_processor.ts index 92698d928a20..74b83fdb9f96 100644 --- a/yarn-project/simulator/src/public/public_processor/public_processor.ts +++ b/yarn-project/simulator/src/public/public_processor/public_processor.ts @@ -25,6 +25,7 @@ import type { PublicProcessorValidator, SequencerConfig, } from '@aztec/stdlib/interfaces/server'; +import type { DebugLog } from '@aztec/stdlib/logs'; import { ProvingRequestType } from '@aztec/stdlib/proofs'; import { MerkleTreeId } from '@aztec/stdlib/trees'; import { @@ -130,7 +131,6 @@ class PublicProcessorTimeoutError extends Error { */ export class PublicProcessor implements Traceable { private metrics: PublicProcessorMetrics; - constructor( protected globalVariables: GlobalVariables, private guardedMerkleTree: GuardedMerkleTreeOperations, @@ -159,12 +159,13 @@ export class PublicProcessor implements Traceable { txs: Iterable | AsyncIterable, limits: PublicProcessorLimits = {}, validator: PublicProcessorValidator = {}, - ): Promise<[ProcessedTx[], FailedTx[], Tx[], NestedProcessReturnValues[], number]> { + ): Promise<[ProcessedTx[], FailedTx[], Tx[], NestedProcessReturnValues[], number, DebugLog[]]> { const { maxTransactions, maxBlockSize, deadline, maxBlockGas, maxBlobFields } = limits; const { preprocessValidator, nullifierCache } = validator; const result: ProcessedTx[] = []; const usedTxs: Tx[] = []; const failed: FailedTx[] = []; + const debugLogs: DebugLog[] = []; const timer = new Timer(); let totalSizeInBytes = 0; @@ -241,7 +242,7 @@ export class PublicProcessor implements Traceable { this.contractsDB.createCheckpoint(); try { - const [processedTx, returnValues] = await this.processTx(tx, deadline); + const [processedTx, returnValues, txDebugLogs] = await this.processTx(tx, deadline); // Inject a fake processing failure after N txs if requested const fakeThrowAfter = this.opts.fakeThrowAfterProcessingTxCount; @@ -290,6 +291,7 @@ export class PublicProcessor implements Traceable { result.push(processedTx); usedTxs.push(tx); returns = returns.concat(returnValues); + debugLogs.push(...txDebugLogs); totalPublicGas = totalPublicGas.add(processedTx.gasUsed.publicGas); totalBlockGas = totalBlockGas.add(processedTx.gasUsed.totalGas); @@ -363,7 +365,7 @@ export class PublicProcessor implements Traceable { totalSizeInBytes, }); - return [result, failed, usedTxs, returns, totalBlobFields]; + return [result, failed, usedTxs, returns, totalBlobFields, debugLogs]; } private async checkWorldStateUnchanged( @@ -383,8 +385,13 @@ export class PublicProcessor implements Traceable { } @trackSpan('PublicProcessor.processTx', tx => ({ [Attributes.TX_HASH]: tx.getTxHash().toString() })) - private async processTx(tx: Tx, deadline: Date | undefined): Promise<[ProcessedTx, NestedProcessReturnValues[]]> { - const [time, [processedTx, returnValues]] = await elapsed(() => this.processTxWithinDeadline(tx, deadline)); + private async processTx( + tx: Tx, + deadline: Date | undefined, + ): Promise<[ProcessedTx, NestedProcessReturnValues[], DebugLog[]]> { + const [time, [processedTx, returnValues, debugLogs]] = await elapsed(() => + this.processTxWithinDeadline(tx, deadline), + ); this.log.verbose( !tx.hasPublicCalls() @@ -407,7 +414,7 @@ export class PublicProcessor implements Traceable { }, ); - return [processedTx, returnValues ?? []]; + return [processedTx, returnValues ?? [], debugLogs]; } private async doTreeInsertionsForPrivateOnlyTx(processedTx: ProcessedTx): Promise { @@ -441,10 +448,9 @@ export class PublicProcessor implements Traceable { private async processTxWithinDeadline( tx: Tx, deadline: Date | undefined, - ): Promise<[ProcessedTx, NestedProcessReturnValues[] | undefined]> { - const innerProcessFn: () => Promise<[ProcessedTx, NestedProcessReturnValues[] | undefined]> = tx.hasPublicCalls() - ? () => this.processTxWithPublicCalls(tx) - : () => this.processPrivateOnlyTx(tx); + ): Promise<[ProcessedTx, NestedProcessReturnValues[] | undefined, DebugLog[]]> { + const innerProcessFn: () => Promise<[ProcessedTx, NestedProcessReturnValues[] | undefined, DebugLog[]]> = + tx.hasPublicCalls() ? () => this.processTxWithPublicCalls(tx) : () => this.processPrivateOnlyTx(tx); // Fake a delay per tx if instructed (used for tests) const fakeDelayPerTxMs = this.opts.fakeProcessingDelayPerTxMs; @@ -512,7 +518,7 @@ export class PublicProcessor implements Traceable { @trackSpan('PublicProcessor.processPrivateOnlyTx', (tx: Tx) => ({ [Attributes.TX_HASH]: tx.getTxHash().toString(), })) - private async processPrivateOnlyTx(tx: Tx): Promise<[ProcessedTx, undefined]> { + private async processPrivateOnlyTx(tx: Tx): Promise<[ProcessedTx, undefined, DebugLog[]]> { const gasFees = this.globalVariables.gasFees; const transactionFee = computeTransactionFee(gasFees, tx.data.constants.txContext.gasSettings, tx.data.gasUsed); @@ -537,13 +543,13 @@ export class PublicProcessor implements Traceable { await this.contractsDB.addNewContracts(tx); - return [processedTx, undefined]; + return [processedTx, undefined, []]; } @trackSpan('PublicProcessor.processTxWithPublicCalls', tx => ({ [Attributes.TX_HASH]: tx.getTxHash().toString(), })) - private async processTxWithPublicCalls(tx: Tx): Promise<[ProcessedTx, NestedProcessReturnValues[]]> { + private async processTxWithPublicCalls(tx: Tx): Promise<[ProcessedTx, NestedProcessReturnValues[], DebugLog[]]> { const timer = new Timer(); const result = await this.publicTxSimulator.simulate(tx); @@ -581,7 +587,7 @@ export class PublicProcessor implements Traceable { revertReason, ); - return [processedTx, appLogicReturnValues]; + return [processedTx, appLogicReturnValues, result.logs ?? []]; } /** diff --git a/yarn-project/stdlib/src/tx/public_simulation_output.ts b/yarn-project/stdlib/src/tx/public_simulation_output.ts index 20e5d743e3d2..984a747fcf3d 100644 --- a/yarn-project/stdlib/src/tx/public_simulation_output.ts +++ b/yarn-project/stdlib/src/tx/public_simulation_output.ts @@ -7,6 +7,7 @@ import { z } from 'zod'; import { SimulationError } from '../errors/simulation_error.js'; import { Gas } from '../gas/gas.js'; import type { GasUsed } from '../gas/gas_used.js'; +import { DebugLog } from '../logs/debug_log.js'; import { NullishToUndefined } from '../schemas/schemas.js'; import { TxEffect } from '../tx/tx_effect.js'; import { GlobalVariables } from './global_variables.js'; @@ -71,6 +72,7 @@ export class PublicSimulationOutput { public txEffect: TxEffect, public publicReturnValues: NestedProcessReturnValues[], public gasUsed: GasUsed, + public debugLogs: DebugLog[] = [], ) {} static get schema(): ZodFor { @@ -86,6 +88,7 @@ export class PublicSimulationOutput { publicGas: Gas.schema, billedGas: Gas.schema, }), + debugLogs: z.array(DebugLog.schema).default([]), }) .transform( fields => @@ -95,6 +98,7 @@ export class PublicSimulationOutput { fields.txEffect, fields.publicReturnValues, fields.gasUsed, + fields.debugLogs, ), ); } diff --git a/yarn-project/validator-client/src/checkpoint_builder.test.ts b/yarn-project/validator-client/src/checkpoint_builder.test.ts index 9b1323316a0e..1a543b5a98e5 100644 --- a/yarn-project/validator-client/src/checkpoint_builder.test.ts +++ b/yarn-project/validator-client/src/checkpoint_builder.test.ts @@ -94,6 +94,7 @@ describe('CheckpointBuilder', () => { [], // usedTxs [], // returnValues 0, // usedTxBlobFields + [], // debugLogs ]); const result = await checkpointBuilder.buildBlock([], blockNumber, 1000n); @@ -117,6 +118,7 @@ describe('CheckpointBuilder', () => { [], // usedTxs [], // returnValues 0, // usedTxBlobFields + [], // debugLogs ]); const result = await checkpointBuilder.buildBlock([], blockNumber, 1000n); @@ -136,6 +138,7 @@ describe('CheckpointBuilder', () => { [], // usedTxs [], // returnValues 0, // usedTxBlobFields + [], // debugLogs ]); await expect(checkpointBuilder.buildBlock([], blockNumber, 1000n)).rejects.toThrow(NoValidTxsError); diff --git a/yarn-project/wallet-sdk/src/base-wallet/base_wallet.test.ts b/yarn-project/wallet-sdk/src/base-wallet/base_wallet.test.ts index ac3983ce72ae..2b2c4cc5e300 100644 --- a/yarn-project/wallet-sdk/src/base-wallet/base_wallet.test.ts +++ b/yarn-project/wallet-sdk/src/base-wallet/base_wallet.test.ts @@ -88,6 +88,7 @@ describe('BaseWallet', () => { txEffect: TxEffect.empty(), publicReturnValues: [optimizedRv0, optimizedRv1], gasUsed: { totalGas: Gas.empty(), teardownGas: Gas.empty(), publicGas: Gas.empty(), billedGas: Gas.empty() }, + debugLogs: [], }; node.simulatePublicCalls.mockResolvedValue(optimizedPublicOutput); @@ -98,6 +99,7 @@ describe('BaseWallet', () => { txEffect: TxEffect.empty(), publicReturnValues: [normalRv0], gasUsed: { totalGas: Gas.empty(), teardownGas: Gas.empty(), publicGas: Gas.empty(), billedGas: Gas.empty() }, + debugLogs: [], }; const normalResult = new TxSimulationResult( mock(), diff --git a/yarn-project/wallet-sdk/src/base-wallet/base_wallet.ts b/yarn-project/wallet-sdk/src/base-wallet/base_wallet.ts index d3d6ffc90185..4111944a1685 100644 --- a/yarn-project/wallet-sdk/src/base-wallet/base_wallet.ts +++ b/yarn-project/wallet-sdk/src/base-wallet/base_wallet.ts @@ -28,7 +28,7 @@ import type { ChainInfo } from '@aztec/entrypoints/interfaces'; import { Fr } from '@aztec/foundation/curves/bn254'; import { createLogger } from '@aztec/foundation/log'; import type { FieldsOf } from '@aztec/foundation/types'; -import type { AccessScopes } from '@aztec/pxe/client/lazy'; +import type { AccessScopes, ContractNameResolver } from '@aztec/pxe/client/lazy'; import type { PXE, PackedPrivateEvent } from '@aztec/pxe/server'; import { type ContractArtifact, @@ -338,6 +338,15 @@ export abstract class BaseWallet implements Wallet { blockHeader = (await this.aztecNode.getBlockHeader())!; } + const getContractName: ContractNameResolver = async address => { + const instance = await this.pxe.getContractInstance(address); + if (!instance) { + return undefined; + } + const artifact = await this.pxe.getContractArtifact(instance.currentContractClassId); + return artifact?.name; + }; + const [optimizedResults, normalResult] = await Promise.all([ optimizableCalls.length > 0 ? simulateViaNode( @@ -348,6 +357,7 @@ export abstract class BaseWallet implements Wallet { feeOptions.gasSettings, blockHeader, opts.skipFeeEnforcement ?? true, + getContractName, ) : Promise.resolve([]), remainingCalls.length > 0 diff --git a/yarn-project/wallet-sdk/src/base-wallet/utils.ts b/yarn-project/wallet-sdk/src/base-wallet/utils.ts index 81737e7674dc..24153108d8ce 100644 --- a/yarn-project/wallet-sdk/src/base-wallet/utils.ts +++ b/yarn-project/wallet-sdk/src/base-wallet/utils.ts @@ -4,6 +4,8 @@ import type { ChainInfo } from '@aztec/entrypoints/interfaces'; import { makeTuple } from '@aztec/foundation/array'; import { Fr } from '@aztec/foundation/curves/bn254'; import type { Tuple } from '@aztec/foundation/serialize'; +import type { ContractNameResolver } from '@aztec/pxe/client/lazy'; +import { displayDebugLogs } from '@aztec/pxe/client/lazy'; import { generateSimulatedProvingResult } from '@aztec/pxe/simulator'; import { type FunctionCall, FunctionSelector } from '@aztec/stdlib/abi'; import type { AztecAddress } from '@aztec/stdlib/aztec-address'; @@ -72,6 +74,7 @@ async function simulateBatchViaNode( gasSettings: GasSettings, blockHeader: BlockHeader, skipFeeEnforcement: boolean, + getContractName: ContractNameResolver, ): Promise { const txContext = new TxContext(chainInfo.chainId, chainInfo.version, gasSettings); @@ -145,6 +148,9 @@ async function simulateBatchViaNode( throw publicOutput.revertReason; } + // Display debug logs from the public simulation. + await displayDebugLogs(publicOutput.debugLogs, getContractName); + return new TxSimulationResult(privateResult, provingResult.publicInputs, publicOutput, undefined); } @@ -169,6 +175,7 @@ export async function simulateViaNode( gasSettings: GasSettings, blockHeader: BlockHeader, skipFeeEnforcement: boolean = true, + getContractName: ContractNameResolver, ): Promise { const batches: FunctionCall[][] = []; @@ -187,6 +194,7 @@ export async function simulateViaNode( gasSettings, blockHeader, skipFeeEnforcement, + getContractName, ); results.push(result); }