fix: benchmark prover e2e test with proving (#7175)

Resolves #7143

---------

Co-authored-by: fcarreiro <facundo@aztecprotocol.com>

barretenberg/cpp/src/barretenberg/vm/avm_trace/avm_common.hpp

@@ -47,6 +47,7 @@ struct ExternalCallHint {
     std::vector<FF> return_data;
     uint32_t l2_gas_used;
     uint32_t da_gas_used;
+    FF end_side_effect_counter;
 };
 
 // Add support for deserialization of ExternalCallHint. This is implicitly used by serialize::read
@@ -58,6 +59,7 @@ inline void read(uint8_t const*& it, ExternalCallHint& hint)
     read(it, hint.return_data);
     read(it, hint.l2_gas_used);
     read(it, hint.da_gas_used);
+    read(it, hint.end_side_effect_counter);
 }
 
 struct ContractInstanceHint {

barretenberg/cpp/src/barretenberg/vm/avm_trace/avm_trace.cpp

@@ -1469,6 +1469,8 @@ void AvmTraceBuilder::op_emit_note_hash(uint8_t indirect, uint32_t note_hash_off
     gas_trace_builder.constrain_gas_lookup(clk, OpCode::EMITNOTEHASH);
 
     main_trace.push_back(row);
+
+    debug("emit_note_hash side-effect cnt: ", side_effect_counter);
     side_effect_counter++;
 }
 
@@ -1484,23 +1486,27 @@ void AvmTraceBuilder::op_emit_nullifier(uint8_t indirect, uint32_t nullifier_off
     gas_trace_builder.constrain_gas_lookup(clk, OpCode::EMITNULLIFIER);
 
     main_trace.push_back(row);
+
+    debug("emit_nullifier side-effect cnt: ", side_effect_counter);
     side_effect_counter++;
 }
 
-void AvmTraceBuilder::op_emit_l2_to_l1_msg(uint8_t indirect, uint32_t recipient_offset, uint32_t msg_offset)
+void AvmTraceBuilder::op_emit_l2_to_l1_msg(uint8_t indirect, uint32_t recipient_offset, uint32_t content_offset)
 {
     auto const clk = static_cast<uint32_t>(main_trace.size()) + 1;
 
     // Note: unorthadox order - as seen in L2ToL1Message struct in TS
     Row row = create_kernel_output_opcode_with_metadata(
-        indirect, clk, msg_offset, AvmMemoryTag::FF, recipient_offset, AvmMemoryTag::FF);
+        indirect, clk, content_offset, AvmMemoryTag::FF, recipient_offset, AvmMemoryTag::FF);
     kernel_trace_builder.op_emit_l2_to_l1_msg(clk, side_effect_counter, row.main_ia, row.main_ib);
     row.main_sel_op_emit_l2_to_l1_msg = FF(1);
 
     // Constrain gas cost
     gas_trace_builder.constrain_gas_lookup(clk, OpCode::SENDL2TOL1MSG);
 
     main_trace.push_back(row);
+
+    debug("emit_l2_to_l1_msg side-effect cnt: ", side_effect_counter);
     side_effect_counter++;
 }
 
@@ -1520,6 +1526,8 @@ void AvmTraceBuilder::op_emit_unencrypted_log(uint8_t indirect,
     gas_trace_builder.constrain_gas_lookup(clk, OpCode::EMITUNENCRYPTEDLOG);
 
     main_trace.push_back(row);
+
+    debug("emit_unencrypted_log side-effect cnt: ", side_effect_counter);
     side_effect_counter++;
 }
 
@@ -1537,14 +1545,17 @@ void AvmTraceBuilder::op_l1_to_l2_msg_exists(uint8_t indirect, uint32_t log_offs
     gas_trace_builder.constrain_gas_lookup(clk, OpCode::L1TOL2MSGEXISTS);
 
     main_trace.push_back(row);
+
+    debug("l1_to_l2_msg_exists side-effect cnt: ", side_effect_counter);
     side_effect_counter++;
 }
 
-void AvmTraceBuilder::op_note_hash_exists(uint8_t indirect, uint32_t note_offset, uint32_t dest_offset)
+void AvmTraceBuilder::op_note_hash_exists(uint8_t indirect, uint32_t note_hash_offset, uint32_t dest_offset)
 {
     auto const clk = static_cast<uint32_t>(main_trace.size()) + 1;
 
-    Row row = create_kernel_output_opcode_with_set_metadata_output_from_hint(indirect, clk, note_offset, dest_offset);
+    Row row =
+        create_kernel_output_opcode_with_set_metadata_output_from_hint(indirect, clk, note_hash_offset, dest_offset);
     kernel_trace_builder.op_note_hash_exists(
         clk, side_effect_counter, row.main_ia, /*safe*/ static_cast<uint32_t>(row.main_ib));
     row.main_sel_op_note_hash_exists = FF(1);
@@ -1553,6 +1564,8 @@ void AvmTraceBuilder::op_note_hash_exists(uint8_t indirect, uint32_t note_offset
     gas_trace_builder.constrain_gas_lookup(clk, OpCode::NOTEHASHEXISTS);
 
     main_trace.push_back(row);
+
+    debug("note_hash_exists side-effect cnt: ", side_effect_counter);
     side_effect_counter++;
 }
 
@@ -1570,6 +1583,8 @@ void AvmTraceBuilder::op_nullifier_exists(uint8_t indirect, uint32_t nullifier_o
     gas_trace_builder.constrain_gas_lookup(clk, OpCode::NULLIFIEREXISTS);
 
     main_trace.push_back(row);
+
+    debug("nullifier_exists side-effect cnt: ", side_effect_counter);
     side_effect_counter++;
 }
 
@@ -1629,6 +1644,8 @@ void AvmTraceBuilder::op_sload(uint8_t indirect, uint32_t slot_offset, uint32_t
         gas_trace_builder.constrain_gas_lookup(clk, OpCode::SLOAD);
 
         main_trace.push_back(row);
+
+        debug("sload side-effect cnt: ", side_effect_counter);
         side_effect_counter++;
         clk++;
 
@@ -1691,6 +1708,8 @@ void AvmTraceBuilder::op_sstore(uint8_t indirect, uint32_t src_offset, uint32_t
         gas_trace_builder.constrain_gas_lookup(clk, OpCode::SSTORE);
 
         main_trace.push_back(row);
+
+        debug("sstore side-effect cnt: ", side_effect_counter);
         side_effect_counter++;
         clk++;
         // All future reads are direct, increment the direct address
@@ -2630,6 +2649,8 @@ void AvmTraceBuilder::op_call(uint8_t indirect,
                           { hint.success });
     external_call_counter++;
     pc++;
+    // Adjust the side_effect_counter to the the value at the end of the external call.
+    side_effect_counter = static_cast<uint32_t>(hint.end_side_effect_counter);
 }
 
 void AvmTraceBuilder::op_get_contract_instance(uint8_t indirect, uint32_t address_offset, uint32_t dst_offset)
@@ -2676,6 +2697,9 @@ void AvmTraceBuilder::op_get_contract_instance(uint8_t indirect, uint32_t addres
                           AvmMemoryTag::FF,
                           internal_return_ptr,
                           contract_instance_vec);
+
+    debug("contract_instance cnt: ", side_effect_counter);
+    side_effect_counter++;
 }
 
 /**
@@ -4307,6 +4331,8 @@ std::vector<Row> AvmTraceBuilder::finalize(uint32_t min_trace_size, bool range_c
     // we already prepended the extra row for shifted columns. Therefore, initialization
     // of side_effect_counter occurs occurs on this row.
     main_trace.at(1).kernel_side_effect_counter = initial_side_effect_counter;
+    // This index is required to retrieve the right side effect counter after an external call.
+    size_t external_call_cnt = 0;
 
     // External loop iterates over the kernel entries which are sorted by increasing clk.
     // Internal loop iterates to fill the gap in main trace between each kernel entries.
@@ -4331,7 +4357,15 @@ std::vector<Row> AvmTraceBuilder::finalize(uint32_t min_trace_size, bool range_c
             dest.kernel_l1_to_l2_msg_exists_write_offset = prev.kernel_l1_to_l2_msg_exists_write_offset;
             dest.kernel_sload_write_offset = prev.kernel_sload_write_offset;
             dest.kernel_sstore_write_offset = prev.kernel_sstore_write_offset;
-            dest.kernel_side_effect_counter = prev.kernel_side_effect_counter;
+
+            // Adjust side effect counter after an external call
+            if (prev.main_sel_op_external_call == 1) {
+                dest.kernel_side_effect_counter =
+                    execution_hints.externalcall_hints.at(external_call_cnt).end_side_effect_counter;
+                external_call_cnt++;
+            } else {
+                dest.kernel_side_effect_counter = prev.kernel_side_effect_counter;
+            }
         }
 
         Row& curr = main_trace.at(clk);

barretenberg/cpp/src/barretenberg/vm/avm_trace/avm_trace.hpp

@@ -117,11 +117,11 @@ class AvmTraceBuilder {
     void op_emit_note_hash(uint8_t indirect, uint32_t note_hash_offset);
     void op_emit_nullifier(uint8_t indirect, uint32_t nullifier_offset);
     void op_emit_unencrypted_log(uint8_t indirect, uint32_t log_offset, uint32_t log_size_offset);
-    void op_emit_l2_to_l1_msg(uint8_t indirect, uint32_t msg_offset, uint32_t recipient_offset);
+    void op_emit_l2_to_l1_msg(uint8_t indirect, uint32_t recipient_offset, uint32_t content_offset);
     void op_get_contract_instance(uint8_t indirect, uint32_t address_offset, uint32_t dst_offset);
 
     // With additional metadata output
-    void op_l1_to_l2_msg_exists(uint8_t indirect, uint32_t msg_offset, uint32_t dest_offset);
+    void op_l1_to_l2_msg_exists(uint8_t indirect, uint32_t log_offset, uint32_t dest_offset);
     void op_note_hash_exists(uint8_t indirect, uint32_t note_hash_offset, uint32_t dest_offset);
     void op_nullifier_exists(uint8_t indirect, uint32_t nullifier_offset, uint32_t dest_offset);
 

barretenberg/cpp/src/barretenberg/vm/tests/avm_execution.test.cpp

@@ -2206,8 +2206,13 @@ TEST_F(AvmExecutionTests, opCallOpcodes)
     std::vector<FF> returndata = {};
 
     // Generate Hint for call operation
-    auto execution_hints = ExecutionHints().with_externalcall_hints(
-        { { .success = 1, .return_data = { 9, 8 }, .l2_gas_used = 0, .da_gas_used = 0 } });
+    auto execution_hints = ExecutionHints().with_externalcall_hints({ {
+        .success = 1,
+        .return_data = { 9, 8 },
+        .l2_gas_used = 0,
+        .da_gas_used = 0,
+        .end_side_effect_counter = 0,
+    } });
 
     auto trace = Execution::gen_trace(instructions, returndata, calldata, public_inputs_vec, execution_hints);
     EXPECT_EQ(returndata, std::vector<FF>({ 9, 8, 1 })); // The 1 represents the success

yarn-project/bb-prover/src/bb/execute.ts

@@ -1,6 +1,6 @@
 import { type AvmCircuitInputs } from '@aztec/circuits.js';
 import { sha256 } from '@aztec/foundation/crypto';
-import { type LogFn } from '@aztec/foundation/log';
+import { type LogFn, currentLevel as currentLogLevel } from '@aztec/foundation/log';
 import { Timer } from '@aztec/foundation/timer';
 import { type NoirCompiledCircuit } from '@aztec/types/noir';
 
@@ -335,6 +335,7 @@ export async function generateAvmProof(
       avmHintsPath,
       '-o',
       outputPath,
+      currentLogLevel == 'debug' ? '-d' : 'verbose' ? '-v' : '',
     ];
     const timer = new Timer();
     const logFunction = (message: string) => {

yarn-project/bb-prover/src/prover/bb_prover.ts

@@ -632,7 +632,7 @@ export class BBNativeRollupProver implements ServerCircuitProver {
       await fs.writeFile(verificationKeyPath, verificationKey.keyAsBytes);
 
       const logFunction = (message: string) => {
-        logger.debug(`BB out - ${message}`);
+        logger.verbose(`BB out - ${message}`);
       };
 
       const result = await verificationFunction(
@@ -647,7 +647,7 @@ export class BBNativeRollupProver implements ServerCircuitProver {
         throw new Error(errorMessage);
       }
 
-      logger.debug(`Successfully verified proof from key in ${result.durationMs} ms`);
+      logger.info(`Successfully verified proof from key in ${result.durationMs} ms`);
     };
 
     await runInDirectory(this.config.bbWorkingDirectory, operation);

yarn-project/circuits.js/src/structs/avm/avm.ts

@@ -80,8 +80,14 @@ export class AvmExternalCallHint {
    * @param success whether the external call was successful (= did NOT revert).
    * @param returnData the data returned by the external call.
    * @param gasUsed gas used by the external call (not including the cost of the CALL opcode itself).
+   * @param endSideEffectCounter value of side effect counter at the end of the external call.
    */
-  constructor(public readonly success: Fr, returnData: Fr[], public readonly gasUsed: Gas) {
+  constructor(
+    public readonly success: Fr,
+    returnData: Fr[],
+    public readonly gasUsed: Gas,
+    public readonly endSideEffectCounter: Fr,
+  ) {
     this.returnData = new Vector(returnData);
   }
 
@@ -106,7 +112,12 @@ export class AvmExternalCallHint {
    * @returns whether all members are empty.
    */
   isEmpty(): boolean {
-    return this.success.isZero() && this.returnData.items.length == 0 && this.gasUsed.isEmpty();
+    return (
+      this.success.isZero() &&
+      this.returnData.items.length == 0 &&
+      this.gasUsed.isEmpty() &&
+      this.endSideEffectCounter.isZero()
+    );
   }
 
   /**
@@ -115,7 +126,12 @@ export class AvmExternalCallHint {
    * @returns A new AvmHint instance.
    */
   static from(fields: FieldsOf<AvmExternalCallHint>): AvmExternalCallHint {
-    return new AvmExternalCallHint(fields.success, fields.returnData.items, fields.gasUsed);
+    return new AvmExternalCallHint(
+      fields.success,
+      fields.returnData.items,
+      fields.gasUsed,
+      fields.endSideEffectCounter,
+    );
   }
 
   /**
@@ -124,7 +140,7 @@ export class AvmExternalCallHint {
    * @returns An array of fields.
    */
   static getFields(fields: FieldsOf<AvmExternalCallHint>) {
-    return [fields.success, fields.returnData, fields.gasUsed] as const;
+    return [fields.success, fields.returnData, fields.gasUsed, fields.endSideEffectCounter] as const;
   }
 
   /**
@@ -134,7 +150,12 @@ export class AvmExternalCallHint {
    */
   static fromBuffer(buff: Buffer | BufferReader): AvmExternalCallHint {
     const reader = BufferReader.asReader(buff);
-    return new AvmExternalCallHint(Fr.fromBuffer(reader), reader.readVector(Fr), reader.readObject<Gas>(Gas));
+    return new AvmExternalCallHint(
+      Fr.fromBuffer(reader),
+      reader.readVector(Fr),
+      reader.readObject<Gas>(Gas),
+      Fr.fromBuffer(reader),
+    );
   }
 
   /**

yarn-project/circuits.js/src/tests/factories.ts

@@ -1285,6 +1285,7 @@ export function makeAvmExternalCallHint(seed = 0): AvmExternalCallHint {
     new Fr(seed % 2),
     makeArray((seed % 100) + 10, i => new Fr(i), seed + 0x1000),
     new Gas(seed + 0x200, seed),
+    new Fr(seed + 0x300),
   );
 }