V8: write to module logs on exception (#3518)

# Description of Changes

Fixes #3497.

```
2025-10-28T15:33:26.846107Z PANIC: test spacetimedb_module:2610: Uncaught Error: i don't want to be called
    in spacetimedb_module:2610:8 :: bar
    in spacetimedb_module:2607:2 :: <anonymous>
    in spacetimedb_module:2256:30 :: __call_reducer__
```

# API and ABI breaking changes

None

# Expected complexity level and risk

1

# Testing

- Confirmed manually that it works by creating a module that throws an
error. See the printout above.

Author: Centril

crates/core/src/host/instance_env.rs

@@ -4,6 +4,7 @@ use crate::db::relational_db::{MutTx, RelationalDB};
 use crate::error::{DBError, DatastoreError, IndexError, NodesError};
 use crate::host::wasm_common::TimingSpan;
 use crate::replica_context::ReplicaContext;
+use chrono::{DateTime, Utc};
 use core::mem;
 use parking_lot::{Mutex, MutexGuard};
 use smallvec::SmallVec;
@@ -222,7 +223,7 @@ impl InstanceEnv {
         }
 
         let record = Record {
-            ts: chrono::Utc::now(),
+            ts: Self::now_for_logging(),
             target: None,
             filename: None,
             line_number: None,
@@ -232,6 +233,12 @@ impl InstanceEnv {
         self.console_log(LogLevel::Info, &record, &Noop);
     }
 
+    /// Returns the current time suitable for logging.
+    pub fn now_for_logging() -> DateTime<Utc> {
+        // TODO: figure out whether to use walltime now or logical reducer now (env.reducer_start).
+        chrono::Utc::now()
+    }
+
     /// Project `cols` in `row_ref` encoded in BSATN to `buffer`
     /// and return the full length of the BSATN.
     ///

crates/core/src/host/v8/error.rs

@@ -3,7 +3,11 @@
 use super::de::scratch_buf;
 use super::serialize_to_js;
 use super::string::IntoJsString;
-use crate::database_logger::{BacktraceFrame, BacktraceProvider, ModuleBacktrace};
+use crate::{
+    database_logger::{BacktraceFrame, BacktraceProvider, LogLevel, ModuleBacktrace, Record},
+    host::instance_env::InstanceEnv,
+    replica_context::ReplicaContext,
+};
 use core::fmt;
 use spacetimedb_sats::Serialize;
 use v8::{tc_scope, Exception, HandleScope, Local, PinScope, PinnedRef, StackFrame, StackTrace, TryCatch, Value};
@@ -228,9 +232,7 @@ pub(super) struct JsError {
 impl fmt::Display for JsError {
     fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
         writeln!(f, "js error {}", self.msg)?;
-        if !f.alternate() {
-            writeln!(f, "{}", self.trace)?;
-        }
+        writeln!(f, "{}", self.trace)?;
         Ok(())
     }
 }
@@ -272,17 +274,32 @@ impl fmt::Display for JsStackTrace {
 
 impl BacktraceProvider for JsStackTrace {
     fn capture(&self) -> Box<dyn ModuleBacktrace> {
-        Box::new(self.clone())
+        let trace = self
+            .frames
+            .iter()
+            .map(|f| {
+                (
+                    format!("{}:{}:{}", f.script_name(), f.line, f.column),
+                    f.fn_name().to_owned(),
+                )
+            })
+            .collect();
+        Box::new(JsBacktrace { trace })
     }
 }
 
-impl ModuleBacktrace for JsStackTrace {
+/// A rendered backtrace for a JS exception.
+struct JsBacktrace {
+    trace: Vec<(String, String)>,
+}
+
+impl ModuleBacktrace for JsBacktrace {
     fn frames(&self) -> Vec<BacktraceFrame<'_>> {
-        self.frames
+        self.trace
             .iter()
-            .map(|frame| BacktraceFrame {
-                module_name: frame.script_name.as_deref(),
-                func_name: frame.fn_name.as_deref(),
+            .map(|(module_name, func_name)| BacktraceFrame {
+                module_name: Some(module_name),
+                func_name: Some(func_name),
             })
             .collect()
     }
@@ -388,13 +405,28 @@ impl JsError {
     }
 }
 
-pub(super) fn log_traceback(func_type: &str, func: &str, e: &anyhow::Error) {
-    log::info!("{func_type} \"{func}\" runtime error: {e:#}");
+pub(super) fn log_traceback(replica_ctx: &ReplicaContext, func_type: &str, func: &str, e: &anyhow::Error) {
+    log::info!("{func_type} \"{func}\" runtime error: {e:}");
     if let Some(js_err) = e.downcast_ref::<JsError>() {
         log::info!("js error {}", js_err.msg);
         for (index, frame) in js_err.trace.frames.iter().enumerate() {
             log::info!("  Frame #{index}: {frame}");
         }
+
+        // Also log to module logs.
+        let first_frame = js_err.trace.frames.first();
+        let filename = first_frame.map(|f| f.script_name());
+        let line_number = first_frame.map(|f| f.line as u32);
+        let message = &js_err.msg;
+        let record = Record {
+            ts: InstanceEnv::now_for_logging(),
+            target: None,
+            filename,
+            line_number,
+            function: Some(func),
+            message,
+        };
+        replica_ctx.logger.write(LogLevel::Panic, &record, &js_err.trace);
     }
 }
 

crates/core/src/host/v8/mod.rs

@@ -333,7 +333,7 @@ fn startup_instance_worker<'scope>(
     let module_common = match module_or_mcc {
         Either::Left(module_common) => Either::Left(module_common),
         Either::Right(mcc) => {
-            let def = extract_description(scope)?;
+            let def = extract_description(scope, &mcc.replica_ctx)?;
 
             // Validate and create a common module from the raw definition.
             Either::Right(build_common_module_from_raw(mcc, def)?)
@@ -577,72 +577,84 @@ fn call_reducer<'scope>(
 ) -> (super::ReducerCallResult, bool) {
     let mut trapped = false;
 
-    let (res, _) = instance_common.call_reducer_with_tx(replica_ctx, tx, params, log_traceback, |tx, op, budget| {
-        // TODO(v8): Start the budget timeout and long-running logger.
-        let env = env_on_isolate_unwrap(scope);
-        let mut tx_slot = env.instance_env.tx.clone();
-
-        // Start the timer.
-        // We'd like this tightly around `__call_reducer__`.
-        env.start_reducer(op.name, op.timestamp);
-
-        // Call `__call_reducer__` with `tx` provided.
-        // It should not be available before.
-        let (tx, call_result) = tx_slot.set(tx, || {
-            catch_exception(scope, |scope| {
-                let res = call_call_reducer(scope, fun, op)?;
-                Ok(res)
-            })
-            .map_err(|(e, can_continue)| {
-                // Convert `can_continue` to whether the isolate has "trapped".
-                // Also cancel execution termination if needed,
-                // that can occur due to terminating long running reducers.
-                trapped = match can_continue {
-                    CanContinue::No => false,
-                    CanContinue::Yes => true,
-                    CanContinue::YesCancelTermination => {
-                        scope.cancel_terminate_execution();
-                        true
-                    }
-                };
-
-                e
-            })
-            .map_err(anyhow::Error::from)
-        });
-
-        // Finish timings.
-        let timings = env_on_isolate_unwrap(scope).finish_reducer();
-
-        // Derive energy stats.
-        let energy = energy_from_elapsed(budget, timings.total_duration);
-
-        // Fetch the currently used heap size in V8.
-        // The used size is ostensibly fairer than the total size.
-        let memory_allocation = scope.get_heap_statistics().used_heap_size();
+    let (res, _) = instance_common.call_reducer_with_tx(
+        replica_ctx,
+        tx,
+        params,
+        move |a, b, c| log_traceback(replica_ctx, a, b, c),
+        |tx, op, budget| {
+            // TODO(v8): Start the budget timeout and long-running logger.
+            let env = env_on_isolate_unwrap(scope);
+            let mut tx_slot = env.instance_env.tx.clone();
+
+            // Start the timer.
+            // We'd like this tightly around `__call_reducer__`.
+            env.start_reducer(op.name, op.timestamp);
+
+            // Call `__call_reducer__` with `tx` provided.
+            // It should not be available before.
+            let (tx, call_result) = tx_slot.set(tx, || {
+                catch_exception(scope, |scope| {
+                    let res = call_call_reducer(scope, fun, op)?;
+                    Ok(res)
+                })
+                .map_err(|(e, can_continue)| {
+                    // Convert `can_continue` to whether the isolate has "trapped".
+                    // Also cancel execution termination if needed,
+                    // that can occur due to terminating long running reducers.
+                    trapped = match can_continue {
+                        CanContinue::No => false,
+                        CanContinue::Yes => true,
+                        CanContinue::YesCancelTermination => {
+                            scope.cancel_terminate_execution();
+                            true
+                        }
+                    };
 
-        let exec_result = ExecuteResult {
-            energy,
-            timings,
-            memory_allocation,
-            call_result,
-        };
-        (tx, exec_result)
-    });
+                    e
+                })
+                .map_err(anyhow::Error::from)
+            });
+
+            // Finish timings.
+            let timings = env_on_isolate_unwrap(scope).finish_reducer();
+
+            // Derive energy stats.
+            let energy = energy_from_elapsed(budget, timings.total_duration);
+
+            // Fetch the currently used heap size in V8.
+            // The used size is ostensibly fairer than the total size.
+            let memory_allocation = scope.get_heap_statistics().used_heap_size();
+
+            let exec_result = ExecuteResult {
+                energy,
+                timings,
+                memory_allocation,
+                call_result,
+            };
+            (tx, exec_result)
+        },
+    );
 
     (res, trapped)
 }
 
 /// Extracts the raw module def by running the registered `__describe_module__` hook.
-fn extract_description<'scope>(scope: &mut PinScope<'scope, '_>) -> Result<RawModuleDef, DescribeError> {
-    run_describer(log_traceback, || {
-        catch_exception(scope, |scope| {
-            let def = call_describe_module(scope)?;
-            Ok(def)
-        })
-        .map_err(|(e, _)| e)
-        .map_err(Into::into)
-    })
+fn extract_description<'scope>(
+    scope: &mut PinScope<'scope, '_>,
+    replica_ctx: &ReplicaContext,
+) -> Result<RawModuleDef, DescribeError> {
+    run_describer(
+        |a, b, c| log_traceback(replica_ctx, a, b, c),
+        || {
+            catch_exception(scope, |scope| {
+                let def = call_describe_module(scope)?;
+                Ok(def)
+            })
+            .map_err(|(e, _)| e)
+            .map_err(Into::into)
+        },
+    )
 }
 #[cfg(test)]
 mod test {

crates/core/src/host/v8/syscall.rs

@@ -1216,7 +1216,7 @@ fn console_log<'scope>(scope: &mut PinScope<'scope, '_>, args: FunctionCallbackA
     let function = env.log_record_function();
     let record = Record {
         // TODO: figure out whether to use walltime now or logical reducer now (env.reducer_start)
-        ts: chrono::Utc::now(),
+        ts: InstanceEnv::now_for_logging(),
         target: None,
         filename: filename.as_deref(),
         line_number: Some(frame.get_line_number() as u32),

crates/core/src/host/wasmtime/wasm_instance_env.rs

@@ -1256,8 +1256,7 @@ impl WasmInstanceEnv {
             let function = env.log_record_function();
 
             let record = Record {
-                // TODO: figure out whether to use walltime now or logical reducer now (env.reducer_start)
-                ts: chrono::Utc::now(),
+                ts: InstanceEnv::now_for_logging(),
                 target: target.as_deref(),
                 filename: filename.as_deref(),
                 line_number,