feat(avm)!: optionally use TS logger in C++ simulation (#19305)

This PR
* Makes BB's `info`/`vinfo`/etc customizable by a logging function
* Updates the TS side of CPP simulation to optionally take a logger function.

The TS-side of the CPP simulator now uses the pino logger.

![image.png](https://app.graphite.com/user-attachments/assets/ca2fbaf1-2a72-4590-a9e9-eeb92563e1d3.png)

I've also refactored the `avm_simulate_napi.cpp` file to avoid referencing the parameter indices many times, and using them in a very "local" way. Otherwise it was getting a bit dangerous that we would use some magic index in places many lines away.

This shouldn't cause any overhead if logging is not active (as expected in block building, because ANY logging might take a `ms` - e.g., showing the transaction hash). If you are doing any logging, you will pay dearly.

Closes [AVM-182](https://linear.app/aztec-labs/issue/AVM-182/optionally-use-ts-logger-in-c-simulation).

Author: fcarreiro

barretenberg/cpp/src/barretenberg/common/log.cpp

@@ -2,6 +2,8 @@
 #include <cstdlib>
 #include <string>
 
+#include "barretenberg/common/log.hpp"
+
 #ifndef __wasm__
 bool verbose_logging = std::getenv("BB_VERBOSE") == nullptr ? false : std::string(std::getenv("BB_VERBOSE")) == "1";
 #else
@@ -10,3 +12,11 @@ bool verbose_logging = true;
 
 // Used for `debug` in log.hpp.
 bool debug_logging = false;
+
+// Used for `log_function` in log.hpp. Defaults to `logstr`.
+LogFunction log_function = [](LogLevel /*unused*/, const char* msg) { logstr(msg); };
+
+void set_log_function(LogFunction new_log_function)
+{
+    log_function = std::move(new_log_function);
+}

barretenberg/cpp/src/barretenberg/common/log.hpp

@@ -1,12 +1,14 @@
 #pragma once
-#include "barretenberg/env/logstr.hpp"
-#include "barretenberg/stdlib/primitives/circuit_builders/circuit_builders_fwd.hpp"
+
 #include <algorithm>
 #include <functional>
 #include <sstream>
 #include <string>
 #include <vector>
 
+#include "barretenberg/env/logstr.hpp"
+#include "barretenberg/stdlib/primitives/circuit_builders/circuit_builders_fwd.hpp"
+
 #define BENCHMARK_INFO_PREFIX "##BENCHMARK_INFO_PREFIX##"
 #define BENCHMARK_INFO_SEPARATOR "#"
 #define BENCHMARK_INFO_SUFFIX "##BENCHMARK_INFO_SUFFIX##"
@@ -32,7 +34,7 @@ template <typename T> void benchmark_format_chain(std::ostream& os, T const& fir
     std::stringstream current_argument;
     current_argument << first;
     std::string current_argument_string = current_argument.str();
-    std::replace(current_argument_string.begin(), current_argument_string.end(), ',', ';');
+    std::ranges::replace(current_argument_string, ',', ';');
     os << current_argument_string << BENCHMARK_INFO_SUFFIX;
 }
 
@@ -43,7 +45,7 @@ void benchmark_format_chain(std::ostream& os, T const& first, Args const&... arg
     std::stringstream current_argument;
     current_argument << first;
     std::string current_argument_string = current_argument.str();
-    std::replace(current_argument_string.begin(), current_argument_string.end(), ',', ';');
+    std::ranges::replace(current_argument_string, ',', ';');
     os << current_argument_string << BENCHMARK_INFO_SEPARATOR;
     benchmark_format_chain(os, args...);
 }
@@ -56,6 +58,18 @@ template <typename... Args> std::string benchmark_format(Args... args)
     return os.str();
 }
 
+enum class LogLevel : int {
+    DEBUG = 0,
+    INFO = 1,
+    VERBOSE = 2,
+    IMPORTANT = 3,
+};
+
+// This allows the logging sink to be customized. Useful for Typescript use-cases.
+using LogFunction = std::function<void(LogLevel level, const char* msg)>;
+extern LogFunction log_function;
+void set_log_function(LogFunction new_log_function);
+
 extern bool debug_logging;
 // In release mode (e.g., NDEBUG is defined), we don't compile debug logs.
 #ifndef NDEBUG
@@ -68,13 +82,13 @@ extern bool debug_logging;
 inline void debug_(std::function<std::string()> func)
 {
     if (debug_logging) {
-        logstr(func().c_str());
+        log_function(LogLevel::DEBUG, func().c_str());
     }
 }
 
 template <typename... Args> inline void info(Args... args)
 {
-    logstr(format(args...).c_str());
+    log_function(LogLevel::INFO, format(args...).c_str());
 }
 
 #define vinfo(...) vinfo_([&]() { return format(__VA_ARGS__); })
@@ -83,19 +97,19 @@ extern bool verbose_logging;
 inline void vinfo_(std::function<std::string()> func)
 {
     if (verbose_logging) {
-        info(func());
+        log_function(LogLevel::VERBOSE, func().c_str());
     }
 }
 
 template <typename... Args> inline void important(Args... args)
 {
-    logstr(format("important: ", args...).c_str());
+    log_function(LogLevel::IMPORTANT, format("important: ", args...).c_str());
 }
 
 /**
  * @brief Info used to store circuit statistics during CI/CD with concrete structure. Writes straight to log
  *
- * @details Automatically appends the necessary prefix and suffix,  as well as separators.
+ * @details Automatically appends the necessary prefix and suffix, as well as separators.
  *
  * @tparam Args
  * @param args
@@ -129,7 +143,7 @@ class BenchmarkInfoCollator {
  * @brief Info used to store circuit statistics during CI/CD with concrete structure. Stores string in vector for now
  * (used to flush all benchmarks at the end of test).
  *
- * @details Automatically appends the necessary prefix and suffix,  as well as separators.
+ * @details Automatically appends the necessary prefix and suffix, as well as separators.
  *
  * @tparam Args
  * @param args

barretenberg/cpp/src/barretenberg/nodejs_module/avm_simulate/avm_simulate_napi.cpp

@@ -1,5 +1,6 @@
-#include "avm_simulate_napi.hpp"
+#include "barretenberg/nodejs_module/avm_simulate/avm_simulate_napi.hpp"
 
+#include <array>
 #include <memory>
 #include <vector>
 
@@ -13,8 +14,8 @@
 #include "barretenberg/vm2/simulation/lib/cancellation_token.hpp"
 
 namespace bb::nodejs {
-
 namespace {
+
 // Log levels from TS foundation/src/log/log-levels.ts: ['silent', 'fatal', 'error', 'warn', 'info', 'verbose', 'debug',
 // 'trace'] Map: 0=silent, 1=fatal, 2=error, 3=warn, 4=info, 5=verbose, 6=debug, 7=trace
 constexpr int LOG_LEVEL_VERBOSE = 5;
@@ -29,6 +30,46 @@ inline void set_logging_from_level(int log_level)
     debug_logging = (log_level >= LOG_LEVEL_TRACE);
 }
 
+// Map C++ LogLevel enum to TypeScript log level string
+// C++ LogLevel: DEBUG=0, INFO=1, VERBOSE=2, IMPORTANT=3
+// TS LogLevels: ['silent', 'fatal', 'error', 'warn', 'info', 'verbose', 'debug', 'trace']
+inline const char* cpp_log_level_to_ts(LogLevel level)
+{
+    switch (level) {
+    case LogLevel::DEBUG:
+        return "debug";
+    case LogLevel::INFO:
+        return "info";
+    case LogLevel::VERBOSE:
+        return "verbose";
+    case LogLevel::IMPORTANT:
+        return "warn";
+    default:
+        return "info";
+    }
+}
+
+// Helper to create a LogFunction wrapper from a ThreadSafeFunction
+// This allows C++ logging to call back to TypeScript logger from worker threads
+LogFunction create_log_function_from_tsfn(const std::shared_ptr<Napi::ThreadSafeFunction>& logger_tsfn)
+{
+    return [logger_tsfn](LogLevel level, const char* msg) {
+        // Convert C++ LogLevel to TS log level string
+        const char* ts_level = cpp_log_level_to_ts(level);
+        std::string msg_str(msg);
+
+        // Call TypeScript logger function on the JS main thread
+        // Using BlockingCall to ensure synchronous execution
+        // Ignore errors - logging failures shouldn't crash the simulation
+        logger_tsfn->BlockingCall([ts_level, msg_str](Napi::Env env, Napi::Function js_logger) {
+            // Create arguments: (level: string, msg: string)
+            auto level_js = Napi::String::New(env, ts_level);
+            auto msg_js = Napi::String::New(env, msg_str);
+            js_logger.Call({ level_js, msg_js });
+        });
+    };
+}
+
 // Callback method names
 constexpr const char* CALLBACK_GET_CONTRACT_INSTANCE = "getContractInstance";
 constexpr const char* CALLBACK_GET_CONTRACT_CLASS = "getContractClass";
@@ -117,63 +158,42 @@ Napi::Value AvmSimulateNapi::simulate(const Napi::CallbackInfo& cb_info)
 {
     Napi::Env env = cb_info.Env();
 
-    // Validate arguments - expects 4-5 arguments
+    // Validate arguments - expects 3-6 arguments
     // arg[0]: inputs Buffer (required)
     // arg[1]: contractProvider object (required)
     // arg[2]: worldStateHandle external (required)
-    // arg[3]: logLevel number (required) - index into TS LogLevels array
-    // arg[4]: cancellationToken external (optional)
-    if (cb_info.Length() < 4) {
-        throw Napi::TypeError::New(env,
-                                   "Wrong number of arguments. Expected 4-5 arguments: inputs Buffer, contractProvider "
-                                   "object, worldStateHandle, logLevel, and optional cancellationToken.");
+    // arg[3]: logLevel number (optional) - index into TS LogLevels array, -1 if omitted
+    // arg[4]: loggerFunction (optional) - can be null/undefined
+    // arg[5]: cancellationToken external (optional)
+    if (cb_info.Length() < 3) {
+        throw Napi::TypeError::New(
+            env,
+            "Wrong number of arguments. Expected 3-6 arguments: inputs Buffer, contractProvider "
+            "object, worldStateHandle, optional logLevel, optional loggerFunction, and optional cancellationToken.");
     }
 
+    /*******************************
+     *** AvmFastSimulationInputs ***
+     *******************************/
     if (!cb_info[0].IsBuffer()) {
         throw Napi::TypeError::New(env,
                                    "First argument must be a Buffer containing serialized AvmFastSimulationInputs");
     }
-
-    if (!cb_info[1].IsObject()) {
-        throw Napi::TypeError::New(env, "Second argument must be a contractProvider object");
-    }
-
-    if (!cb_info[2].IsExternal()) {
-        throw Napi::TypeError::New(env, "Third argument must be a WorldState handle (External)");
-    }
-
-    if (!cb_info[3].IsNumber()) {
-        throw Napi::TypeError::New(env, "Fourth argument must be a log level number (0-7)");
-    }
-
-    // Extract optional cancellation token (5th argument)
-    avm2::simulation::CancellationTokenPtr cancellation_token = nullptr;
-    if (cb_info.Length() > 4 && cb_info[4].IsExternal()) {
-        auto token_external = cb_info[4].As<Napi::External<avm2::simulation::CancellationToken>>();
-        // Wrap the raw pointer in a shared_ptr that does NOT delete (since the External owns it)
-        cancellation_token = std::shared_ptr<avm2::simulation::CancellationToken>(
-            token_external.Data(), [](avm2::simulation::CancellationToken*) {
-                // No-op deleter: the External
-                // (via shared_ptr destructor
-                // callback) owns the token
-            });
-    }
-
-    // Extract log level and set logging flags
-    int log_level = cb_info[3].As<Napi::Number>().Int32Value();
-    set_logging_from_level(log_level);
-
     // Extract the inputs buffer
     auto inputs_buffer = cb_info[0].As<Napi::Buffer<uint8_t>>();
     size_t length = inputs_buffer.Length();
-
     // Copy the buffer data into C++ memory (we can't access Napi objects from worker thread)
     auto data = std::make_shared<std::vector<uint8_t>>(inputs_buffer.Data(), inputs_buffer.Data() + length);
 
+    /***********************************
+     *** ContractProvider (required) ***
+     ***********************************/
+    if (!cb_info[1].IsObject()) {
+        throw Napi::TypeError::New(env, "Second argument must be a contractProvider object");
+    }
     // Extract and validate contract provider callbacks
     auto contract_provider = cb_info[1].As<Napi::Object>();
     ContractCallbacks::validate(env, contract_provider);
-
     // Create thread-safe function wrappers for callbacks
     // These allow us to call TypeScript from the C++ worker thread
     ContractTsfns tsfns{
@@ -196,18 +216,68 @@ Napi::Value AvmSimulateNapi::simulate(const Napi::CallbackInfo& cb_info)
             env, ContractCallbacks::get(contract_provider, CALLBACK_REVERT_CHECKPOINT), CALLBACK_REVERT_CHECKPOINT),
     };
 
+    /*****************************
+     *** WorldState (required) ***
+     *****************************/
+    if (!cb_info[2].IsExternal()) {
+        throw Napi::TypeError::New(env, "Third argument must be a WorldState handle (External)");
+    }
     // Extract WorldState handle (3rd argument)
     auto external = cb_info[2].As<Napi::External<world_state::WorldState>>();
     world_state::WorldState* ws_ptr = external.Data();
 
-    // Create a deferred promise
-    auto deferred = std::make_shared<Napi::Promise::Deferred>(env);
+    /***************************
+     *** LogLevel (optional) ***
+     ***************************/
+    int log_level = -1;
+    if (cb_info.Length() > 3 && cb_info[3].IsNumber()) {
+        log_level = cb_info[3].As<Napi::Number>().Int32Value();
+        set_logging_from_level(log_level);
+    }
+
+    /*********************************
+     *** LoggerFunction (optional) ***
+     *********************************/
+    std::shared_ptr<Napi::ThreadSafeFunction> logger_tsfn = nullptr;
+    if (cb_info.Length() > 4 && !cb_info[4].IsNull() && !cb_info[4].IsUndefined()) {
+        if (cb_info[4].IsFunction()) {
+            // Logger function provided - create thread-safe wrapper
+            auto logger_function = cb_info[4].As<Napi::Function>();
+            logger_tsfn = make_tsfn(env, logger_function, "LoggerCallback");
+            // Create LogFunction wrapper and set it as the global log function
+            // This will be used by C++ logging macros (info, debug, vinfo, important)
+            set_log_function(create_log_function_from_tsfn(logger_tsfn));
+        } else {
+            throw Napi::TypeError::New(env, "Fifth argument must be a logger function, null, or undefined");
+        }
+    }
+
+    /*************************************
+     *** Cancellation Token (optional) ***
+     *************************************/
+    avm2::simulation::CancellationTokenPtr cancellation_token = nullptr;
+    if (cb_info.Length() > 5 && cb_info[5].IsExternal()) {
+        auto token_external = cb_info[5].As<Napi::External<avm2::simulation::CancellationToken>>();
+        // Wrap the raw pointer in a shared_ptr that does NOT delete (since the External owns it)
+        cancellation_token = std::shared_ptr<avm2::simulation::CancellationToken>(
+            token_external.Data(), [](avm2::simulation::CancellationToken*) {
+                // No-op deleter: the External (via shared_ptr destructor callback) owns the token
+            });
+    }
+
+    /**********************************************************
+     *** Create Deferred Promise and launch async operation ***
+     **********************************************************/
 
+    auto deferred = std::make_shared<Napi::Promise::Deferred>(env);
     // Create async operation that will run on a worker thread
-    auto* op =
-        new AsyncOperation(env, deferred, [data, tsfns, ws_ptr, cancellation_token](msgpack::sbuffer& result_buffer) {
+    auto* op = new AsyncOperation(
+        env, deferred, [data, tsfns, logger_tsfn, ws_ptr, cancellation_token](msgpack::sbuffer& result_buffer) {
+            // Collect all thread-safe functions including logger for cleanup
+            auto all_tsfns = tsfns.to_vector();
+            all_tsfns.push_back(logger_tsfn);
             // Ensure all thread-safe functions are released in all code paths
-            TsfnReleaser releaser = TsfnReleaser(tsfns.to_vector());
+            TsfnReleaser releaser = TsfnReleaser(std::move(all_tsfns));
 
             try {
                 // Deserialize inputs from msgpack

barretenberg/cpp/src/barretenberg/vm2/constraining/prover.cpp

@@ -49,7 +49,7 @@ void AvmProver::execute_preamble_round()
 {
     FF vk_hash = vk->hash();
     transcript->add_to_hash_buffer("avm_vk_hash", vk_hash);
-    info("AVM vk hash in prover: ", vk_hash);
+    vinfo("AVM vk hash in prover: ", vk_hash);
 }
 
 /**

barretenberg/cpp/src/barretenberg/vm2/proving_helper.cpp

@@ -44,7 +44,7 @@ AvmProvingHelper::VkData AvmProvingHelper::get_verification_key()
     auto verification_key =
         std::make_shared<AvmVerifier::VerificationKey>(constraining::AvmFixedVKCommitments::get_all());
 
-    info("AVM vk hash: ", verification_key->hash());
+    vinfo("AVM vk hash: ", verification_key->hash());
 
     auto serialized_vk = to_buffer(verification_key->to_field_elements());
 

barretenberg/cpp/src/barretenberg/vm2/simulation/gadgets/execution.cpp

@@ -1809,7 +1809,7 @@ EnqueuedCallResult Execution::execute(std::unique_ptr<ContextInterface> enqueued
         } catch (const std::exception& e) {
             // This is a coding error, we should not get here.
             // All exceptions should fall in the above catch blocks.
-            info("An unhandled exception occurred: ", e.what());
+            important("An unhandled exception occurred: ", e.what());
             throw e;
         }
 

barretenberg/cpp/src/barretenberg/vm2/simulation/gadgets/tx_execution.cpp

@@ -255,7 +255,7 @@ TxExecutionResult TxExecution::simulate(const Tx& tx)
         merkle_db.commit_checkpoint();
         contract_db.commit_checkpoint();
     } catch (const TxExecutionException& e) {
-        info("Teardown failure while simulating tx ", tx.hash, ": ", e.what());
+        important("Teardown failure while simulating tx ", tx.hash, ": ", e.what());
         tx_context.revert_code = tx_context.revert_code == RevertCode::APP_LOGIC_REVERTED
                                      ? RevertCode::BOTH_REVERTED
                                      : RevertCode::TEARDOWN_REVERTED;

barretenberg/cpp/src/barretenberg/vm2/simulation/standalone/hybrid_execution.cpp

@@ -87,7 +87,7 @@ EnqueuedCallResult HybridExecution::execute(std::unique_ptr<ContextInterface> en
         } catch (const std::exception& e) {
             // This is a coding error, we should not get here.
             // All exceptions should fall in the above catch blocks.
-            info("An unhandled exception occurred: ", e.what());
+            important("An unhandled exception occurred: ", e.what());
             throw e;
         }
 

barretenberg/cpp/src/barretenberg/vm2/simulation_helper.cpp

@@ -478,7 +478,7 @@ TxSimulationResult AvmSimulationHelper::simulate_fast_internal(ContractDBInterfa
             const DebugLogLevel debug_log_level = DebugLogLevel::INFO;
             return std::make_unique<DebugLogger>(debug_log_level,
                                                  config.collection_limits.max_debug_log_memory_reads,
-                                                 [](const std::string& message) { info(message); });
+                                                 [](const std::string& message) { vinfo(message); });
         } else {
             return std::make_unique<NoopDebugLogger>();
         }