From dc6799a3a404210f9ebf5c5eaa39e34a75299bf4 Mon Sep 17 00:00:00 2001 From: Facundo Date: Tue, 14 May 2024 16:53:07 +0100 Subject: [PATCH] feat!: debug logs for all (#6392) Unify and implement debug log Noir and oracles. --- avm-transpiler/src/opcodes.rs | 5 + avm-transpiler/src/transpile.rs | 56 ++++++++- .../barretenberg/vm/avm_trace/avm_opcode.hpp | 3 + docs/docs/misc/migration_notes.md | 11 ++ .../contracts/avm_test_contract/src/main.nr | 8 ++ .../src/main.nr | 12 +- .../src/main.nr | 2 +- .../crates/types/src/debug_log.nr | 41 ++----- yarn-project/circuits.js/src/debug_log.ts | 110 ------------------ yarn-project/circuits.js/src/index.ts | 1 - yarn-project/foundation/src/log/debug.ts | 21 ++++ .../noir-protocol-circuits-types/src/index.ts | 19 ++- .../simulator/src/acvm/oracle/oracle.ts | 14 +-- .../simulator/src/acvm/oracle/typed_oracle.ts | 4 + yarn-project/simulator/src/avm/avm_gas.ts | 2 + .../simulator/src/avm/avm_simulator.test.ts | 9 ++ .../simulator/src/avm/opcodes/index.ts | 2 + .../simulator/src/avm/opcodes/misc.ts | 63 ++++++++++ .../serialization/bytecode_serialization.ts | 6 +- .../instruction_serialization.ts | 2 + .../src/client/client_execution_context.ts | 6 +- .../src/public/public_execution_context.ts | 7 +- 22 files changed, 234 insertions(+), 170 deletions(-) delete mode 100644 yarn-project/circuits.js/src/debug_log.ts create mode 100644 yarn-project/simulator/src/avm/opcodes/misc.ts diff --git a/avm-transpiler/src/opcodes.rs b/avm-transpiler/src/opcodes.rs index 206325cfeff..44d2fa7cffe 100644 --- a/avm-transpiler/src/opcodes.rs +++ b/avm-transpiler/src/opcodes.rs @@ -64,6 +64,8 @@ pub enum AvmOpcode { DELEGATECALL, RETURN, REVERT, + // Misc + DEBUGLOG, // Gadgets KECCAK, POSEIDON2, @@ -152,6 +154,9 @@ impl AvmOpcode { AvmOpcode::RETURN => "RETURN", AvmOpcode::REVERT => "REVERT", + // Misc + AvmOpcode::DEBUGLOG => "DEBUGLOG", + // Gadgets AvmOpcode::KECCAK => "KECCAK", AvmOpcode::POSEIDON2 => "POSEIDON2", diff --git a/avm-transpiler/src/transpile.rs b/avm-transpiler/src/transpile.rs index c76802e14bf..0f3b89e5a99 100644 --- a/avm-transpiler/src/transpile.rs +++ b/avm-transpiler/src/transpile.rs @@ -359,6 +359,7 @@ fn handle_foreign_call( } "storageRead" => handle_storage_read(avm_instrs, destinations, inputs), "storageWrite" => handle_storage_write(avm_instrs, destinations, inputs), + "debugLog" => handle_debug_log(avm_instrs, destinations, inputs), // Getters. _ if inputs.is_empty() && destinations.len() == 1 => { handle_getter_instruction(avm_instrs, function, destinations, inputs) @@ -431,12 +432,14 @@ fn handle_external_call( opcode: opcode, // (left to right) // * selector direct + // * success offset direct + // * (n/a) ret size is an immeadiate // * ret offset INDIRECT // * arg size offset direct // * args offset INDIRECT // * address offset direct // * gas offset INDIRECT - indirect: Some(0b010101), + indirect: Some(0b00010101), operands: vec![ AvmOperand::U32 { value: gas_offset }, AvmOperand::U32 { @@ -1003,6 +1006,57 @@ fn handle_black_box_function(avm_instrs: &mut Vec, operation: &B _ => panic!("Transpiler doesn't know how to process {:?}", operation), } } + +fn handle_debug_log( + avm_instrs: &mut Vec, + destinations: &Vec, + inputs: &Vec, +) { + if !destinations.is_empty() || inputs.len() != 3 { + panic!( + "Transpiler expects ForeignCall::DEBUGLOG to have 0 destinations and 3 inputs, got {} and {}", + destinations.len(), + inputs.len() + ); + } + let (message_offset, message_size) = match &inputs[0] { + ValueOrArray::HeapArray(HeapArray { pointer, size }) => (pointer.0 as u32, *size as u32), + _ => panic!("Message for ForeignCall::DEBUGLOG should be a HeapArray."), + }; + // The fields are a slice, and this is represented as a (length: Field, slice: HeapVector). + // The length field is redundant and we skipt it. + let (fields_offset_ptr, fields_size_ptr) = match &inputs[2] { + ValueOrArray::HeapVector(HeapVector { pointer, size }) => (pointer.0 as u32, size.0 as u32), + _ => panic!("List of fields for ForeignCall::DEBUGLOG should be a HeapVector (slice)."), + }; + avm_instrs.push(AvmInstruction { + opcode: AvmOpcode::DEBUGLOG, + // (left to right) + // * fields_size_ptr direct + // * fields_offset_ptr INDIRECT + // * (N/A) message_size is an immediate + // * message_offset direct + indirect: Some(0b011), + operands: vec![ + AvmOperand::U32 { + value: message_offset, + }, + AvmOperand::U32 { + value: message_size, + }, + // indirect + AvmOperand::U32 { + value: fields_offset_ptr, + }, + // indirect + AvmOperand::U32 { + value: fields_size_ptr, + }, + ], + ..Default::default() + }); +} + /// Emit a storage write opcode /// The current implementation writes an array of values into storage ( contiguous slots in memory ) fn handle_storage_write( diff --git a/barretenberg/cpp/src/barretenberg/vm/avm_trace/avm_opcode.hpp b/barretenberg/cpp/src/barretenberg/vm/avm_trace/avm_opcode.hpp index 21423838f43..fd655a026f3 100644 --- a/barretenberg/cpp/src/barretenberg/vm/avm_trace/avm_opcode.hpp +++ b/barretenberg/cpp/src/barretenberg/vm/avm_trace/avm_opcode.hpp @@ -92,6 +92,9 @@ enum class OpCode : uint8_t { RETURN, REVERT, + // Misc + DEBUGLOG, + // Gadgets KECCAK, POSEIDON2, diff --git a/docs/docs/misc/migration_notes.md b/docs/docs/misc/migration_notes.md index 7f990738590..6c117f69099 100644 --- a/docs/docs/misc/migration_notes.md +++ b/docs/docs/misc/migration_notes.md @@ -6,6 +6,17 @@ keywords: [sandbox, cli, aztec, notes, migration, updating, upgrading] Aztec is in full-speed development. Literally every version breaks compatibility with the previous ones. This page attempts to target errors and difficulties you might encounter when upgrading, and how to resolve them. +## TBD + +### [Aztec.nr] Debug logging + +The function `debug_log_array_with_prefix` has been removed. Use `debug_log_format` with `{}` instead. The special sequence `{}` will be replaced with the whole array. You can also use `{0}`, `{1}`, ... as usual with `debug_log_format`. + +```diff +- debug_log_array_with_prefix("Prefix", my_array); ++ debug_log_format("Prefix {}", my_array); +``` + ## 0.39.0 ### [Aztec.nr] Mutable delays in `SharedMutable` diff --git a/noir-projects/noir-contracts/contracts/avm_test_contract/src/main.nr b/noir-projects/noir-contracts/contracts/avm_test_contract/src/main.nr index cbff33dd760..a68129cae9e 100644 --- a/noir-projects/noir-contracts/contracts/avm_test_contract/src/main.nr +++ b/noir-projects/noir-contracts/contracts/avm_test_contract/src/main.nr @@ -177,6 +177,14 @@ contract AvmTest { helper_with_failed_assertion() } + #[aztec(public-vm)] + fn debug_logging() { + dep::aztec::oracle::debug_log::debug_log("just text"); + dep::aztec::oracle::debug_log::debug_log_format("second: {1}", [1, 2, 3, 4]); + dep::aztec::oracle::debug_log::debug_log_format("whole array: {}", [1, 2, 3, 4]); + dep::aztec::oracle::debug_log::debug_log("tabs and newlines\n\t- first\n\t- second"); + } + /************************************************************************ * Hashing functions ************************************************************************/ diff --git a/noir-projects/noir-contracts/contracts/contract_class_registerer_contract/src/main.nr b/noir-projects/noir-contracts/contracts/contract_class_registerer_contract/src/main.nr index 0dbf1fbb2c9..aa5e3bf242d 100644 --- a/noir-projects/noir-contracts/contracts/contract_class_registerer_contract/src/main.nr +++ b/noir-projects/noir-contracts/contracts/contract_class_registerer_contract/src/main.nr @@ -43,8 +43,8 @@ contract ContractClassRegisterer { context.push_new_nullifier(contract_class_id.to_field(), 0); // Broadcast class info including public bytecode - dep::aztec::oracle::debug_log::debug_log_array_with_prefix( - "ContractClassRegistered", + dep::aztec::oracle::debug_log::debug_log_format( + "ContractClassRegistered: {}", [ contract_class_id.to_field(), artifact_hash, @@ -76,8 +76,8 @@ contract ContractClassRegisterer { artifact_function_tree_leaf_index, function: function_data }; - dep::aztec::oracle::debug_log::debug_log_array_with_prefix( - "ClassPrivateFunctionBroadcasted", + dep::aztec::oracle::debug_log::debug_log_format( + "ClassPrivateFunctionBroadcasted: {}", [ contract_class_id.to_field(), artifact_metadata_hash, @@ -107,8 +107,8 @@ contract ContractClassRegisterer { artifact_function_tree_leaf_index, function: function_data }; - dep::aztec::oracle::debug_log::debug_log_array_with_prefix( - "ClassUnconstrainedFunctionBroadcasted", + dep::aztec::oracle::debug_log::debug_log_format( + "ClassUnconstrainedFunctionBroadcasted: {}", [ contract_class_id.to_field(), artifact_metadata_hash, diff --git a/noir-projects/noir-contracts/contracts/contract_instance_deployer_contract/src/main.nr b/noir-projects/noir-contracts/contracts/contract_instance_deployer_contract/src/main.nr index 2c152e5f746..43e7d45c655 100644 --- a/noir-projects/noir-contracts/contracts/contract_instance_deployer_contract/src/main.nr +++ b/noir-projects/noir-contracts/contracts/contract_instance_deployer_contract/src/main.nr @@ -35,7 +35,7 @@ contract ContractInstanceDeployer { // Broadcast the event let event = ContractInstanceDeployed { contract_class_id, address, public_keys_hash, initialization_hash, salt, deployer, version: 1 }; let event_payload = event.serialize(); - dep::aztec::oracle::debug_log::debug_log_array_with_prefix("ContractInstanceDeployed", event_payload); + dep::aztec::oracle::debug_log::debug_log_format("ContractInstanceDeployed: {}", event_payload); context.emit_unencrypted_log(event_payload); } } diff --git a/noir-projects/noir-protocol-circuits/crates/types/src/debug_log.nr b/noir-projects/noir-protocol-circuits/crates/types/src/debug_log.nr index d9892f1617e..cfcaca43b2f 100644 --- a/noir-projects/noir-protocol-circuits/crates/types/src/debug_log.nr +++ b/noir-projects/noir-protocol-circuits/crates/types/src/debug_log.nr @@ -2,22 +2,7 @@ // WARNING: sometimes when using debug logs the ACVM errors with: `thrown: "solver opcode resolution error: cannot solve opcode: expression has too many unknowns x155"` #[oracle(debugLog)] -fn debug_log_oracle(_msg: T, _num_args: Field) {} -#[oracle(debugLog)] -fn debug_log_format_oracle(_msg: T, _args: [Field; N], _num_args: Field) {} -#[oracle(debugLog)] -fn debug_log_field_oracle(_field: Field) {} -#[oracle(debugLog)] -fn debug_log_array_oracle(_arbitrary_array: [T; N]) {} -#[oracle(debugLogWithPrefix)] -fn debug_log_array_with_prefix_oracle(_prefix: S, _arbitrary_array: [T; N]) {} - -/// NOTE: call this with a str msg of length > 1 -/// Example: -/// `debug_log("blah blah this is a debug string");` -unconstrained pub fn debug_log(msg: T) { - debug_log_oracle(msg, 0); -} +fn debug_log_oracle(_msg: str, args: [Field]) {} /// NOTE: call this with a str msg of form /// "some string with {0} and {1} ... {N}" @@ -25,24 +10,14 @@ unconstrained pub fn debug_log(msg: T) { /// into the string in the simulator. /// Example: /// debug_log_format("get_2(slot:{0}) =>\n\t0:{1}\n\t1:{2}", [storage_slot, note0_hash, note1_hash]); -unconstrained pub fn debug_log_format(msg: T, args: [Field; N]) { - debug_log_format_oracle(msg, args, args.len() as Field); -} - -/// Example: -/// `debug_log_field(my_field);` -unconstrained pub fn debug_log_field(field: Field) { - debug_log_field_oracle(field); -} - -/// Example: -/// `debug_log_array(my_array);` -unconstrained fn debug_log_array(arbitrary_array: [T; N]) { - debug_log_array_oracle(arbitrary_array); +/// debug_log_format("whole array: {}", [e1, e2, e3, e4]); +unconstrained pub fn debug_log_format(msg: str, args: [Field; N]) { + debug_log_oracle(msg, args.as_slice()); } +/// NOTE: call this with a str msg of length > 1 /// Example: -/// `debug_log_array_with_prefix("Prefix", my_array);` -unconstrained pub fn debug_log_array_with_prefix(prefix: S, arbitrary_array: [T; N]) { - debug_log_array_with_prefix_oracle(prefix, arbitrary_array); +/// `debug_log("blah blah this is a debug string");` +unconstrained pub fn debug_log(msg: str) { + debug_log_format(msg, []); } diff --git a/yarn-project/circuits.js/src/debug_log.ts b/yarn-project/circuits.js/src/debug_log.ts deleted file mode 100644 index 36517cda505..00000000000 --- a/yarn-project/circuits.js/src/debug_log.ts +++ /dev/null @@ -1,110 +0,0 @@ -// Placed here as it is used both by simulator and by noir-protocol-circuits-types -import { type ForeignCallInput } from '@noir-lang/acvm_js'; - -type ACVMField = string; - -/** - * Convert an array of ACVMFields to a string. - * - * @param msg - array of ACVMFields where each represents a single ascii character - * @returns string representation of the message - */ -export function acvmFieldMessageToString(msg: ACVMField[]): string { - let msgStr = ''; - for (const msgChar of msg) { - const asciiCode = Number(msgChar); - const asciiChar = String.fromCharCode(asciiCode); - msgStr = msgStr.concat(asciiChar); - } - // cut off string in case of preemptive null termination - const nullCharIndex = msgStr.indexOf('\\0'); - if (nullCharIndex >= 0) { - msgStr = msgStr.substring(0, nullCharIndex); - } - return msgStr.replaceAll('\\n', '\n').replaceAll('\\t', '\t'); -} - -/** - * Format a debug string for Aztec.nr filling in `'{0}'` entries with their - * corresponding values from the args array. - * - * @param formatStr - str of form `'this is a string with some entries like {0} and {1}'` - * @param args - array of fields to fill in the string format entries with - * @returns formatted string - */ -function applyStringFormatting(formatStr: string, args: ACVMField[]): string { - const matches = formatStr.match(/{\d+}/g); - if (matches == null) { - return formatStr; - } - // Get the numeric values within the curly braces, convert them to numbers, - // and find the maximum value. - const maxIndex = Math.max(...matches.map(match => Number(match.slice(1, -1)))); - const argsPadded = args.concat(Array.from({ length: Math.max(0, maxIndex - args.length) }, () => '0xBAD')); - - return formatStr.replace(/{(\d+)}/g, function (match, index) { - return typeof args[index] != 'undefined' ? argsPadded[index] : match; - }); -} - -/** - * Convert an array of ACVMFields from ACVM to a formatted string. - * - * @param parameters - either one parameter representing a simple field or array, or two parameters when - * It's a message without args or three parameters when it's a message with arguments. - * - * @returns formatted string - */ -export function oracleDebugCallToFormattedStr(parameters: ForeignCallInput[]): string { - if (parameters.length === 1) { - return processFieldOrArray(parameters[0]); - } - - let formatArgs: string[] = []; - - if (parameters.length > 2) { - formatArgs = parameters[1]; - } - - const formattedMsg = applyStringFormatting(acvmFieldMessageToString(parameters[0]), formatArgs); - - return formattedMsg; -} - -/** - * Processes a field or an array and returns a string representation. - * @param fieldOrArray - The field or array to be processed. - * @returns Returns the processed string representation of the field or array. - */ -function processFieldOrArray(fieldOrArray: string[]) { - if (fieldOrArray.length === 1) { - return `${fieldOrArray[0]}`; - } - - // Check if all the elements start with 63 zero bytes - // --> if yes, we have an array of bytes and we print as hex - if (onlyBytes(fieldOrArray)) { - const decimalArray = fieldOrArray.map(element => parseInt(element, 16)); - return '0x' + Buffer.from(decimalArray).toString('hex'); - } - - return '[' + fieldOrArray.join(', ') + ']'; -} - -/** - * Checks if all elements in the array are valid byte representations. - * @param array - The array to be checked. - * @returns Returns `true` if all elements are valid byte representations, `false` otherwise. - * @throws Throws an error if any element has an invalid length. - */ -function onlyBytes(array: string[]): boolean { - for (const element of array) { - if (element.length != 66) { - throw new Error('Invalid element length. Expected 66 chars, got ' + element.length + ' chars.'); - } - if (!element.startsWith('0x00000000000000000000000000000000000000000000000000000000000000')) { - return false; - } - } - return true; -} diff --git a/yarn-project/circuits.js/src/index.ts b/yarn-project/circuits.js/src/index.ts index d4c939ef836..875f51fe952 100644 --- a/yarn-project/circuits.js/src/index.ts +++ b/yarn-project/circuits.js/src/index.ts @@ -1,6 +1,5 @@ export * from './constants.gen.js'; export * from './contract/index.js'; -export * from './debug_log.js'; export * from './hints/index.js'; export * from './interfaces/index.js'; export * from './keys/index.js'; diff --git a/yarn-project/foundation/src/log/debug.ts b/yarn-project/foundation/src/log/debug.ts index aeef1993b45..69d9e66c76d 100644 --- a/yarn-project/foundation/src/log/debug.ts +++ b/yarn-project/foundation/src/log/debug.ts @@ -81,3 +81,24 @@ export function enableLogs(str: string) { export function isLogEnabled(str: string) { return debug.enabled(str); } + +/** + * Format a debug string filling in `'{0}'` entries with their + * corresponding values from the args array, amd `'{}'` with the whole array. + * + * @param formatStr - str of form `'this is a string with some entries like {0} and {1}'` + * @param args - array of fields to fill in the string format entries with + * @returns formatted string + */ +interface Printable { + toString(): string; +} +export function applyStringFormatting(formatStr: string, args: Printable[]): string { + return formatStr + .replace(/{(\d+)}/g, (match, index) => { + return typeof args[index] === 'undefined' ? match : args[index].toString(); + }) + .replace(/{}/g, (_match, _index) => { + return args.toString(); + }); +} diff --git a/yarn-project/noir-protocol-circuits-types/src/index.ts b/yarn-project/noir-protocol-circuits-types/src/index.ts index a1aae17d756..1f68ee651a9 100644 --- a/yarn-project/noir-protocol-circuits-types/src/index.ts +++ b/yarn-project/noir-protocol-circuits-types/src/index.ts @@ -2,6 +2,7 @@ import { type BaseOrMergeRollupPublicInputs, type BaseParityInputs, type BaseRollupInputs, + Fr, type KernelCircuitPublicInputs, type MergeRollupInputs, type ParityPublicInputs, @@ -16,16 +17,15 @@ import { type RootParityInputs, type RootRollupInputs, type RootRollupPublicInputs, - acvmFieldMessageToString, - oracleDebugCallToFormattedStr, } from '@aztec/circuits.js'; -import { createDebugLogger } from '@aztec/foundation/log'; +import { applyStringFormatting, createDebugLogger } from '@aztec/foundation/log'; import { type NoirCompiledCircuit } from '@aztec/types/noir'; import { type ForeignCallInput, type ForeignCallOutput } from '@noir-lang/acvm_js'; import { type CompiledCircuit } from '@noir-lang/noir_js'; import { type Abi, abiDecode, abiEncode } from '@noir-lang/noirc_abi'; import { type WitnessMap } from '@noir-lang/types'; +import { strict as assert } from 'assert'; import BaseParityJson from './target/parity_base.json' assert { type: 'json' }; import RootParityJson from './target/parity_root.json' assert { type: 'json' }; @@ -631,13 +631,20 @@ export function convertPublicTailOutputFromWitnessMap(outputs: WitnessMap): Kern return mapKernelCircuitPublicInputsFromNoir(returnType); } +function fromACVMField(field: string): Fr { + return Fr.fromBuffer(Buffer.from(field.slice(2), 'hex')); +} + export function foreignCallHandler(name: string, args: ForeignCallInput[]): Promise { + // ForeignCallInput is actually a string[], so the args are string[][]. const log = createDebugLogger('aztec:noir-protocol-circuits:oracle'); if (name === 'debugLog') { - log.info(oracleDebugCallToFormattedStr(args)); - } else if (name === 'debugLogWithPrefix') { - log.info(`${acvmFieldMessageToString(args[0])}: ${oracleDebugCallToFormattedStr(args.slice(1))}`); + assert(args.length === 3, 'expected 3 arguments for debugLog: msg, fields_length, fields'); + const [msgRaw, _ignoredFieldsSize, fields] = args; + const msg: string = msgRaw.map(acvmField => String.fromCharCode(fromACVMField(acvmField).toNumber())).join(''); + const fieldsFr: Fr[] = fields.map((field: string) => fromACVMField(field)); + log.verbose('debug_log ' + applyStringFormatting(msg, fieldsFr)); } else { throw Error(`unexpected oracle during execution: ${name}`); } diff --git a/yarn-project/simulator/src/acvm/oracle/oracle.ts b/yarn-project/simulator/src/acvm/oracle/oracle.ts index a118129cd17..ed48931edf2 100644 --- a/yarn-project/simulator/src/acvm/oracle/oracle.ts +++ b/yarn-project/simulator/src/acvm/oracle/oracle.ts @@ -1,9 +1,7 @@ import { MerkleTreeId, UnencryptedL2Log } from '@aztec/circuit-types'; -import { acvmFieldMessageToString, oracleDebugCallToFormattedStr } from '@aztec/circuits.js'; import { EventSelector, FunctionSelector } from '@aztec/foundation/abi'; import { AztecAddress } from '@aztec/foundation/aztec-address'; import { Fr, Point } from '@aztec/foundation/fields'; -import { createDebugLogger } from '@aztec/foundation/log'; import { type ACVMField } from '../acvm_types.js'; import { frToBoolean, frToNumber, fromACVMField } from '../deserialize.js'; @@ -14,7 +12,7 @@ import { type TypedOracle } from './typed_oracle.js'; * A data source that has all the apis required by Aztec.nr. */ export class Oracle { - constructor(private typedOracle: TypedOracle, private log = createDebugLogger('aztec:simulator:oracle')) {} + constructor(private typedOracle: TypedOracle) {} getRandomField(): ACVMField { const val = this.typedOracle.getRandomField(); @@ -350,12 +348,10 @@ export class Oracle { return toACVMField(logHash); } - debugLog(...args: ACVMField[][]): void { - this.log.verbose(oracleDebugCallToFormattedStr(args)); - } - - debugLogWithPrefix(arg0: ACVMField[], ...args: ACVMField[][]): void { - this.log.verbose(`${acvmFieldMessageToString(arg0)}: ${oracleDebugCallToFormattedStr(args)}`); + debugLog(message: ACVMField[], _ignoredFieldsSize: ACVMField[], fields: ACVMField[]): void { + const messageStr = message.map(acvmField => String.fromCharCode(fromACVMField(acvmField).toNumber())).join(''); + const fieldsFr = fields.map(fromACVMField); + this.typedOracle.debugLog(messageStr, fieldsFr); } async callPrivateFunction( diff --git a/yarn-project/simulator/src/acvm/oracle/typed_oracle.ts b/yarn-project/simulator/src/acvm/oracle/typed_oracle.ts index 231d8cd99d1..59ae7ee9705 100644 --- a/yarn-project/simulator/src/acvm/oracle/typed_oracle.ts +++ b/yarn-project/simulator/src/acvm/oracle/typed_oracle.ts @@ -249,4 +249,8 @@ export abstract class TypedOracle { aes128Encrypt(_input: Buffer, _initializationVector: Buffer, _key: Buffer): Buffer { throw new OracleMethodNotAvailableError('encrypt'); } + + debugLog(_message: string, _fields: Fr[]): void { + throw new OracleMethodNotAvailableError('debugLog'); + } } diff --git a/yarn-project/simulator/src/avm/avm_gas.ts b/yarn-project/simulator/src/avm/avm_gas.ts index b16b171212f..6f33654f715 100644 --- a/yarn-project/simulator/src/avm/avm_gas.ts +++ b/yarn-project/simulator/src/avm/avm_gas.ts @@ -118,6 +118,8 @@ export const GasCosts: Record = { [Opcode.DELEGATECALL]: TemporaryDefaultGasCost, [Opcode.RETURN]: TemporaryDefaultGasCost, [Opcode.REVERT]: TemporaryDefaultGasCost, + // Misc + [Opcode.DEBUGLOG]: TemporaryDefaultGasCost, // Gadgets [Opcode.KECCAK]: TemporaryDefaultGasCost, [Opcode.POSEIDON2]: TemporaryDefaultGasCost, diff --git a/yarn-project/simulator/src/avm/avm_simulator.test.ts b/yarn-project/simulator/src/avm/avm_simulator.test.ts index 3e180e51c57..19d1eb95a83 100644 --- a/yarn-project/simulator/src/avm/avm_simulator.test.ts +++ b/yarn-project/simulator/src/avm/avm_simulator.test.ts @@ -121,6 +121,15 @@ describe('AVM simulator: transpiled Noir contracts', () => { }); }); + it('Logging', async () => { + const context = initContext(); + const bytecode = getAvmTestContractBytecode('debug_logging'); + const results = await new AvmSimulator(context).executeBytecode(bytecode); + + expect(results.reverted).toBe(false); + expect(results.output).toEqual([]); + }); + it('Assertion message', async () => { const calldata: Fr[] = [new Fr(20)]; const context = initContext({ env: initExecutionEnvironment({ calldata }) }); diff --git a/yarn-project/simulator/src/avm/opcodes/index.ts b/yarn-project/simulator/src/avm/opcodes/index.ts index e3263fdfd1c..d0614bb169a 100644 --- a/yarn-project/simulator/src/avm/opcodes/index.ts +++ b/yarn-project/simulator/src/avm/opcodes/index.ts @@ -2,9 +2,11 @@ export * from './arithmetic.js'; export * from './bitwise.js'; export * from './control_flow.js'; export * from './contract.js'; +export * from './conversion.js'; export * from './instruction.js'; export * from './comparators.js'; export * from './memory.js'; +export * from './misc.js'; export * from './storage.js'; export * from './external_calls.js'; export * from './environment_getters.js'; diff --git a/yarn-project/simulator/src/avm/opcodes/misc.ts b/yarn-project/simulator/src/avm/opcodes/misc.ts new file mode 100644 index 00000000000..98aeac63f9d --- /dev/null +++ b/yarn-project/simulator/src/avm/opcodes/misc.ts @@ -0,0 +1,63 @@ +import { applyStringFormatting, createDebugLogger } from '@aztec/foundation/log'; + +import { type AvmContext } from '../avm_context.js'; +import { TypeTag } from '../avm_memory_types.js'; +import { Opcode, OperandType } from '../serialization/instruction_serialization.js'; +import { Addressing } from './addressing_mode.js'; +import { Instruction } from './instruction.js'; + +export class DebugLog extends Instruction { + static type: string = 'DEBUGLOG'; + static readonly opcode: Opcode = Opcode.DEBUGLOG; + static readonly logger = createDebugLogger('aztec:avm_simulator:debug_log'); + + // Informs (de)serialization. See Instruction.deserialize. + static readonly wireFormat: OperandType[] = [ + OperandType.UINT8, // Opcode + OperandType.UINT8, // Indirect + OperandType.UINT32, // message memory address + OperandType.UINT32, // message size + OperandType.UINT32, // fields memory address + OperandType.UINT32, // fields size address + ]; + + constructor( + private indirect: number, + private messageOffset: number, + private messageSize: number, + private fieldsOffset: number, + private fieldsSizeOffset: number, + ) { + super(); + } + + public async execute(context: AvmContext): Promise { + const memory = context.machineState.memory.track(this.type); + const [messageOffset, fieldsOffset, fieldsSizeOffset] = Addressing.fromWire(this.indirect).resolve( + [this.messageOffset, this.fieldsOffset, this.fieldsSizeOffset], + memory, + ); + + const fieldsSize = memory.get(fieldsSizeOffset).toNumber(); + memory.checkTagsRange(TypeTag.UINT8, messageOffset, this.messageSize); + memory.checkTagsRange(TypeTag.FIELD, fieldsOffset, fieldsSize); + + const memoryOperations = { reads: 1 + fieldsSize + this.messageSize, writes: 0, indirect: this.indirect }; + context.machineState.consumeGas(this.gasCost(memoryOperations)); + + const rawMessage = memory.getSlice(messageOffset, this.messageSize); + const fields = memory.getSlice(fieldsOffset, fieldsSize); + + // Interpret str = [u8; N] to string. + const messageAsStr = rawMessage.map(field => String.fromCharCode(field.toNumber())).join(''); + const formattedStr = applyStringFormatting( + messageAsStr, + fields.map(field => field.toFr()), + ); + + DebugLog.logger.verbose(formattedStr); + + memory.assert(memoryOperations); + context.machineState.incrementPc(); + } +} diff --git a/yarn-project/simulator/src/avm/serialization/bytecode_serialization.ts b/yarn-project/simulator/src/avm/serialization/bytecode_serialization.ts index c6158e6bd76..d5b029cb103 100644 --- a/yarn-project/simulator/src/avm/serialization/bytecode_serialization.ts +++ b/yarn-project/simulator/src/avm/serialization/bytecode_serialization.ts @@ -1,5 +1,4 @@ import { DAGasLeft, L2GasLeft } from '../opcodes/context_getters.js'; -import { ToRadixLE } from '../opcodes/conversion.js'; import { Keccak, Pedersen, Poseidon2, Sha256 } from '../opcodes/hashing.js'; import type { Instruction } from '../opcodes/index.js'; import { @@ -12,6 +11,7 @@ import { CalldataCopy, Cast, ChainId, + DebugLog, Div, EmitNoteHash, EmitNullifier, @@ -47,6 +47,7 @@ import { StorageAddress, Sub, Timestamp, + ToRadixLE, TransactionFee, Version, Xor, @@ -132,6 +133,9 @@ const INSTRUCTION_SET = () => [Return.opcode, Return], [Revert.opcode, Revert], + // Misc + [DebugLog.opcode, DebugLog], + // //// Gadgets [Keccak.opcode, Keccak], [Poseidon2.opcode, Poseidon2], diff --git a/yarn-project/simulator/src/avm/serialization/instruction_serialization.ts b/yarn-project/simulator/src/avm/serialization/instruction_serialization.ts index dabf361d04c..dca3368b89b 100644 --- a/yarn-project/simulator/src/avm/serialization/instruction_serialization.ts +++ b/yarn-project/simulator/src/avm/serialization/instruction_serialization.ts @@ -69,6 +69,8 @@ export enum Opcode { DELEGATECALL, RETURN, REVERT, + // Misc + DEBUGLOG, // Gadgets KECCAK, POSEIDON2, diff --git a/yarn-project/simulator/src/client/client_execution_context.ts b/yarn-project/simulator/src/client/client_execution_context.ts index d07b7087300..6b381dd723c 100644 --- a/yarn-project/simulator/src/client/client_execution_context.ts +++ b/yarn-project/simulator/src/client/client_execution_context.ts @@ -24,7 +24,7 @@ import { computePublicDataTreeLeafSlot, computeUniqueNoteHash, siloNoteHash } fr import { type FunctionAbi, type FunctionArtifact, countArgumentsSize } from '@aztec/foundation/abi'; import { type AztecAddress } from '@aztec/foundation/aztec-address'; import { Fr, type Point } from '@aztec/foundation/fields'; -import { createDebugLogger } from '@aztec/foundation/log'; +import { applyStringFormatting, createDebugLogger } from '@aztec/foundation/log'; import { type NoteData, toACVMWitness } from '../acvm/index.js'; import { type PackedValuesCache } from '../common/packed_values_cache.js'; @@ -642,4 +642,8 @@ export class ClientExecutionContext extends ViewDataOracle { const aes128 = new Aes128(); return aes128.encryptBufferCBC(input, initializationVector, key); } + + public override debugLog(message: string, fields: Fr[]) { + this.log.verbose(`debug_log ${applyStringFormatting(message, fields)}`); + } } diff --git a/yarn-project/simulator/src/public/public_execution_context.ts b/yarn-project/simulator/src/public/public_execution_context.ts index c6279209ecf..e8c6fefcda8 100644 --- a/yarn-project/simulator/src/public/public_execution_context.ts +++ b/yarn-project/simulator/src/public/public_execution_context.ts @@ -12,7 +12,7 @@ import { } from '@aztec/circuits.js'; import { type AztecAddress } from '@aztec/foundation/aztec-address'; import { Fr } from '@aztec/foundation/fields'; -import { createDebugLogger } from '@aztec/foundation/log'; +import { applyStringFormatting, createDebugLogger } from '@aztec/foundation/log'; import { type ContractInstance } from '@aztec/types/contracts'; import { TypedOracle, toACVMWitness } from '../acvm/index.js'; @@ -281,4 +281,9 @@ export class PublicExecutionContext extends TypedOracle { } return instance; } + + public override debugLog(message: string, fields: Fr[]): void { + const formattedStr = applyStringFormatting(message, fields); + this.log.verbose(`debug_log ${formattedStr}`); + } }