Better module backtraces for panics and whatnot

crates/bindings-macro/src/lib.rs

@@ -9,25 +9,27 @@
 // (private documentation for the macro authors is totally fine here and you SHOULD write that!)
 
 mod procedure;
+mod reducer;
+mod sats;
+mod table;
+mod util;
+mod view;
 
 #[proc_macro_attribute]
 pub fn procedure(args: StdTokenStream, item: StdTokenStream) -> StdTokenStream {
-    cvt_attr::<ItemFn>(args, item, quote!(), |args, original_function| {
+    cvt_attr::<ItemFn>(args, item, quote!(#[inline(never)]), |args, original_function| {
         let args = procedure::ProcedureArgs::parse(args)?;
         procedure::procedure_impl(args, original_function)
     })
 }
-mod reducer;
 
 #[proc_macro_attribute]
 pub fn reducer(args: StdTokenStream, item: StdTokenStream) -> StdTokenStream {
-    cvt_attr::<ItemFn>(args, item, quote!(), |args, original_function| {
+    cvt_attr::<ItemFn>(args, item, quote!(#[inline(never)]), |args, original_function| {
         let args = reducer::ReducerArgs::parse(args)?;
         reducer::reducer_impl(args, original_function)
     })
 }
-mod sats;
-mod table;
 
 #[proc_macro_attribute]
 pub fn table(args: StdTokenStream, item: StdTokenStream) -> StdTokenStream {
@@ -64,8 +66,6 @@ pub fn table(args: StdTokenStream, item: StdTokenStream) -> StdTokenStream {
         Ok(TokenStream::from_iter([quote!(#derive_input), generated]))
     })
 }
-mod util;
-mod view;
 
 #[proc_macro_attribute]
 pub fn view(args: StdTokenStream, item: StdTokenStream) -> StdTokenStream {

crates/bindings-macro/src/view.rs

@@ -212,6 +212,7 @@ pub(crate) fn view_impl(args: ViewArgs, original_function: &ItemFn) -> syn::Resu
         (
             quote! {
                 #(#original_attrs)*
+                #[inline(never)]
                 #vis
                 #original_sig
                     #emitted_body

crates/bindings-typescript/src/server/procedures.ts

@@ -107,7 +107,7 @@ function registerProcedure<
   fn: ProcedureFn<S, Params, Ret>,
   opts?: ProcedureOpts
 ) {
-  ctx.defineFunction(exportName);
+  ctx.defineFunction(exportName, fn);
   const paramsType: ProductType = {
     elements: Object.entries(params).map(([n, c]) => ({
       name: n,

crates/bindings-typescript/src/server/reducers.ts

@@ -60,7 +60,7 @@ export function registerReducer(
   opts?: ReducerOpts,
   lifecycle?: Lifecycle
 ): void {
-  ctx.defineFunction(exportName);
+  ctx.defineFunction(exportName, fn);
 
   if (!(params instanceof RowBuilder)) {
     params = new RowBuilder(params);
@@ -101,12 +101,6 @@ export function registerReducer(
     });
   }
 
-  // If the function isn't named (e.g. `function foobar() {}`), give it the same
-  // name as the reducer so that it's clear what it is in in backtraces.
-  if (!fn.name) {
-    Object.defineProperty(fn, 'name', { value: exportName, writable: false });
-  }
-
   ctx.reducers.push(fn);
 }
 

crates/bindings-typescript/src/server/schema.ts

@@ -67,13 +67,20 @@ export class SchemaInner<
     this.schemaType = getSchemaType(this);
   }
 
-  defineFunction(name: string) {
+  // eslint-disable-next-line @typescript-eslint/no-unsafe-function-type
+  defineFunction(name: string, fn: Function) {
     if (this.existingFunctions.has(name)) {
       throw new TypeError(
         `There is already a reducer or procedure with the name '${name}'`
       );
     }
     this.existingFunctions.add(name);
+
+    // If the function isn't named (e.g. `function foobar() {}`), give it the same
+    // name as the reducer so that it's clear what it is in in backtraces.
+    if (!fn.name) {
+      Object.defineProperty(fn, 'name', { value: name, writable: false });
+    }
   }
 
   resolveSchedules() {

crates/bindings-typescript/src/server/views.ts

@@ -143,6 +143,12 @@ export function registerView<
     ? AnonymousViewFn<S, Params, Ret>
     : ViewFn<S, Params, Ret>
 ) {
+  // If the function isn't named (e.g. `function foobar() {}`), give it the same
+  // name as the reducer so that it's clear what it is in in backtraces.
+  if (!fn.name) {
+    Object.defineProperty(fn, 'name', { value: exportName, writable: false });
+  }
+
   const paramsBuilder = new RowBuilder(params, toPascalCase(exportName));
 
   // Register return types if they are product types

crates/bindings/src/rt.rs

@@ -625,9 +625,10 @@ macro_rules! impl_reducer_procedure_view {
             Ret: IntoReducerResult
         {
             #[allow(non_snake_case)]
+            #[inline(always)]
             fn invoke(&self, ctx: &ReducerContext, args: ($($T,)*)) -> Result<(), Box<str>> {
                 let ($($T,)*) = args;
-                self(ctx, $($T),*).into_result()
+                __rust_begin_short_backtrace(|| self(ctx, $($T),*).into_result())
             }
         }
 
@@ -638,9 +639,10 @@ macro_rules! impl_reducer_procedure_view {
             Ret: IntoProcedureResult,
         {
             #[allow(non_snake_case)]
+            #[inline(always)]
             fn invoke(&self, ctx: &mut ProcedureContext, args: ($($T,)*)) -> Ret {
                 let ($($T,)*) = args;
-                self(ctx, $($T),*)
+                __rust_begin_short_backtrace(|| self(ctx, $($T),*))
             }
         }
 
@@ -653,9 +655,10 @@ macro_rules! impl_reducer_procedure_view {
             Retn: ViewReturn,
         {
             #[allow(non_snake_case)]
+            #[inline(always)]
             fn invoke(&self, ctx: &ViewContext, args: ($($T,)*)) -> Retn {
                 let ($($T,)*) = args;
-                self(ctx, $($T),*)
+                __rust_begin_short_backtrace(|| self(ctx, $($T),*))
             }
         }
 
@@ -668,9 +671,10 @@ macro_rules! impl_reducer_procedure_view {
             Retn: ViewReturn,
         {
             #[allow(non_snake_case)]
+            #[inline(always)]
             fn invoke(&self, ctx: &AnonymousViewContext, args: ($($T,)*)) -> Retn {
                 let ($($T,)*) = args;
-                self(ctx, $($T),*)
+                __rust_begin_short_backtrace(|| self(ctx, $($T),*))
             }
         }
     };
@@ -1332,3 +1336,17 @@ pub trait ExplicitNames {
         RawExplicitNames::default()
     }
 }
+
+// Used to tidy up the backtrace in `crates/core/src/host/wasmtime/wasmtime_instance_env.rs`
+#[inline(never)]
+pub(crate) fn __rust_begin_short_backtrace<F, T>(f: F) -> T
+where
+    F: FnOnce() -> T,
+{
+    let result = f();
+
+    // prevent this frame from being tail-call optimised away
+    std::hint::black_box(());
+
+    result
+}

crates/cli/src/subcommands/logs.rs

@@ -158,6 +158,32 @@ pub struct BacktraceFrame<'a> {
     pub module_name: Option<Cow<'a, str>>,
     #[serde(borrow)]
     pub func_name: Option<Cow<'a, str>>,
+    #[serde(borrow)]
+    pub file: Option<Cow<'a, str>>,
+    pub line: Option<u32>,
+    pub column: Option<u32>,
+    #[serde(default)]
+    pub symbols: Vec<BacktraceFrameSymbol<'a>>,
+    #[serde(default)]
+    pub kind: BacktraceFrameKind,
+}
+
+#[derive(serde::Deserialize, Default)]
+#[serde(rename_all = "lowercase")]
+pub enum BacktraceFrameKind {
+    #[default]
+    Wasm,
+    Js,
+}
+
+#[derive(serde::Deserialize)]
+pub struct BacktraceFrameSymbol<'a> {
+    #[serde(borrow)]
+    pub name: Option<Cow<'a, str>>,
+    #[serde(borrow)]
+    pub file: Option<Cow<'a, str>>,
+    pub line: Option<u32>,
+    pub column: Option<u32>,
 }
 
 #[derive(serde::Serialize)]
@@ -330,20 +356,8 @@ pub async fn exec(mut config: Config, args: &ArgMatches) -> Result<(), anyhow::E
         }
         writeln!(out, "{}", record.message)?;
         if let Some(trace) = &record.trace {
-            for frame in trace {
-                write!(out, "    in ")?;
-                if let Some(module) = &frame.module_name {
-                    out.set_color(&dimmed)?;
-                    write!(out, "{module}")?;
-                    out.reset()?;
-                    write!(out, " :: ")?;
-                }
-                if let Some(function) = &frame.func_name {
-                    out.set_color(&dimmed)?;
-                    writeln!(out, "{function}")?;
-                    out.reset()?;
-                }
-            }
+            writeln!(out, "backtrace:")?;
+            fmt_backtrace(&mut out, trace)?;
         }
 
         line.clear();
@@ -352,6 +366,69 @@ pub async fn exec(mut config: Config, args: &ArgMatches) -> Result<(), anyhow::E
     Ok(())
 }
 
+// based on fmt::Display impl for wasmtime::WasmBacktrace
+// modified to print in color and to skip irrelevant frames
+fn fmt_backtrace<W: WriteColor>(out: &mut W, trace: &[BacktraceFrame<'_>]) -> anyhow::Result<()> {
+    for (frame_i, frame) in trace.iter().enumerate() {
+        let func_name = frame.func_name.as_deref().unwrap_or("<unknown>");
+        let module_name = frame.module_name.as_deref();
+        write!(out, "  {:>3}: ", frame_i)?;
+
+        let write_func_name = |out: &mut W, name: &str| {
+            let (name, suffix) = match frame.kind {
+                BacktraceFrameKind::Js => (name, None),
+                BacktraceFrameKind::Wasm => {
+                    let has_hash_suffix = name.len() > 19
+                        && &name[name.len() - 19..name.len() - 16] == "::h"
+                        && name[name.len() - 16..].chars().all(|x| x.is_ascii_hexdigit());
+                    let (name_no_suffix, suffix) = has_hash_suffix.then(|| name.split_at(name.len() - 19)).unzip();
+                    (name_no_suffix.unwrap_or(name), suffix)
+                }
+            };
+            out.set_color(ColorSpec::new().set_fg(Some(Color::Red)).set_bold(true))?;
+            write!(out, "{name}")?;
+            if let Some(suffix) = suffix {
+                out.set_color(ColorSpec::new().set_fg(Some(Color::Red)).set_dimmed(true))?;
+                write!(out, "{suffix}")?;
+            }
+            out.reset()
+        };
+        if frame.symbols.is_empty() {
+            if let Some(module_name) = module_name {
+                write!(out, "{module_name}!")?;
+            }
+            write_func_name(out, func_name)?;
+            writeln!(out)?;
+        } else {
+            for (i, symbol) in frame.symbols.iter().enumerate() {
+                if i > 0 {
+                    write!(out, "       ")?;
+                } else {
+                    // ...
+                }
+                let symbol_name = match &symbol.name {
+                    Some(name) => name,
+                    None if i == 0 => func_name,
+                    None => "<inlined function>",
+                };
+                write_func_name(out, symbol_name)?;
+                if let Some(file) = &symbol.file {
+                    writeln!(out)?;
+                    write!(out, "         at {}", file)?;
+                    if let Some(line) = symbol.line {
+                        write!(out, ":{}", line)?;
+                        if let Some(col) = symbol.column {
+                            write!(out, ":{}", col)?;
+                        }
+                    }
+                }
+                writeln!(out)?;
+            }
+        }
+    }
+    Ok(())
+}
+
 /// Returns true if the record should be displayed given the filter settings.
 fn should_display(record_level: LogLevel, min_level: Option<LogLevel>, level_exact: bool) -> bool {
     match min_level {

crates/cli/src/tasks/mod.rs

@@ -36,7 +36,7 @@ pub fn build(
         let mut wasm_path = output_path;
         eprintln!("Optimising module with wasm-opt...");
         let wasm_path_opt = wasm_path.with_extension("opt.wasm");
-        match cmd!("wasm-opt", "-all", "-g", "-O2", &wasm_path, "-o", &wasm_path_opt).run() {
+        match cmd!("wasm-opt", "-all", "-O2", &wasm_path, "-g", "-o", &wasm_path_opt).run() {
             Ok(_) => wasm_path = wasm_path_opt,
             // Non-critical error for backward compatibility with users who don't have wasm-opt.
             Err(err) => {