From d5c1738c15f8c22b6e3f011daf9af31b6c4b0159 Mon Sep 17 00:00:00 2001 From: Noa Date: Tue, 21 Apr 2026 08:08:57 -0500 Subject: [PATCH] Better module backtraces for panics and whatnot (#577) # Description of Changes ![image](https://github.com/clockworklabs/SpacetimeDB/assets/33094578/9c6356af-9b34-462a-8441-8bd859a73b86) If these symbols aren't in the stack, it does no processing # Expected complexity level and risk 1 - it's pretty self-contained, and backwards-compatible with the existing logs data format --------- Co-authored-by: Tyler Cloutier Co-authored-by: clockwork-labs-bot --- .../internal/runtime_registration.h | 15 ++ .../spacetimedb/internal/v10_builder.h | 36 +++- .../diag/snapshots/Module#FFI.verified.cs | 184 +++++++++++++++++- .../snapshots/Module#FFI.verified.cs | 30 ++- .../server/snapshots/Module#FFI.verified.cs | 90 ++++++++- crates/bindings-csharp/Codegen/Module.cs | 18 +- crates/bindings-macro/src/lib.rs | 14 +- crates/bindings-macro/src/view.rs | 1 + .../src/server/procedures.ts | 2 +- .../src/server/reducers.ts | 8 +- .../bindings-typescript/src/server/schema.ts | 9 +- .../bindings-typescript/src/server/views.ts | 6 + crates/bindings/src/rt.rs | 26 ++- crates/cli/src/subcommands/logs.rs | 105 ++++++++-- crates/cli/src/tasks/mod.rs | 2 +- crates/core/src/database_logger.rs | 73 +++++-- crates/core/src/host/instance_env.rs | 17 +- crates/core/src/host/v8/error.rs | 48 ++--- .../src/host/wasmtime/wasm_instance_env.rs | 56 +++++- .../core/src/host/wasmtime/wasmtime_module.rs | 16 +- templates/basic-rs/spacetimedb/Cargo.toml | 3 + 21 files changed, 611 insertions(+), 148 deletions(-) diff --git a/crates/bindings-cpp/include/spacetimedb/internal/runtime_registration.h b/crates/bindings-cpp/include/spacetimedb/internal/runtime_registration.h index 4d84cb975..66d827616 100644 --- a/crates/bindings-cpp/include/spacetimedb/internal/runtime_registration.h +++ b/crates/bindings-cpp/include/spacetimedb/internal/runtime_registration.h @@ -1,9 +1,12 @@ #ifndef SPACETIMEDB_RUNTIME_REGISTRATION_H #define SPACETIMEDB_RUNTIME_REGISTRATION_H +#include #include #include #include +#include +#include #include #include "../abi/opaque_types.h" #include "autogen/Lifecycle.g.h" @@ -33,6 +36,18 @@ std::vector ConsumeBytes(BytesSource source); void SetMultiplePrimaryKeyError(const std::string& table_name); void SetConstraintRegistrationError(const std::string& code, const std::string& details); +template +__attribute__((noinline)) decltype(auto) __spacetimedb_begin_short_backtrace(F&& f) { + if constexpr (std::is_void_v>) { + std::forward(f)(); + std::atomic_signal_fence(std::memory_order_seq_cst); + } else { + decltype(auto) result = std::forward(f)(); + std::atomic_signal_fence(std::memory_order_seq_cst); + return result; + } +} + } // namespace Internal } // namespace SpacetimeDB diff --git a/crates/bindings-cpp/include/spacetimedb/internal/v10_builder.h b/crates/bindings-cpp/include/spacetimedb/internal/v10_builder.h index 9de0f0a23..7cbecc097 100644 --- a/crates/bindings-cpp/include/spacetimedb/internal/v10_builder.h +++ b/crates/bindings-cpp/include/spacetimedb/internal/v10_builder.h @@ -337,7 +337,9 @@ public: std::function handler; if constexpr (traits::arity == 1) { handler = [func](ReducerContext& ctx, BytesSource) { - auto result = func(ctx); + auto result = __spacetimedb_begin_short_backtrace([&] { + return func(ctx); + }); if (result.is_err()) { ::SpacetimeDB::fail_reducer(result.error()); } @@ -349,7 +351,9 @@ public: bsatn::Reader reader(bytes.data(), bytes.size()); auto args = std::make_tuple(bsatn::deserialize>(reader)...); std::apply([&ctx_inner, fn](auto&&... unpacked) { - auto result = fn(ctx_inner, std::forward(unpacked)...); + auto result = __spacetimedb_begin_short_backtrace([&] { + return fn(ctx_inner, std::forward(unpacked)...); + }); if (result.is_err()) { ::SpacetimeDB::fail_reducer(result.error()); } @@ -406,7 +410,9 @@ public: std::function handler; if constexpr (traits::arity == 1) { handler = [func](ReducerContext& ctx, BytesSource) { - auto result = func(ctx); + auto result = __spacetimedb_begin_short_backtrace([&] { + return func(ctx); + }); if (result.is_err()) { ::SpacetimeDB::fail_reducer(result.error()); } @@ -418,7 +424,9 @@ public: bsatn::Reader reader(bytes.data(), bytes.size()); auto args = std::make_tuple(bsatn::deserialize>(reader)...); std::apply([&ctx_inner, fn](auto&&... unpacked) { - auto result = fn(ctx_inner, std::forward(unpacked)...); + auto result = __spacetimedb_begin_short_backtrace([&] { + return fn(ctx_inner, std::forward(unpacked)...); + }); if (result.is_err()) { ::SpacetimeDB::fail_reducer(result.error()); } @@ -461,7 +469,9 @@ public: std::function(ViewContext&, BytesSource)> handler = [func](ViewContext& ctx, BytesSource args_source) -> std::vector { (void)args_source; - auto result = func(ctx); + auto result = __spacetimedb_begin_short_backtrace([&] { + return func(ctx); + }); auto result_vec = view_result_to_vec(std::move(result)); IterBuf buf = IterBuf::take(); { @@ -475,7 +485,9 @@ public: std::function(AnonymousViewContext&, BytesSource)> handler = [func](AnonymousViewContext& ctx, BytesSource args_source) -> std::vector { (void)args_source; - auto result = func(ctx); + auto result = __spacetimedb_begin_short_backtrace([&] { + return func(ctx); + }); auto result_vec = view_result_to_vec(std::move(result)); IterBuf buf = IterBuf::take(); { @@ -525,7 +537,9 @@ public: std::function(ProcedureContext&, BytesSource)> handler; if constexpr (traits::arity == 1) { handler = [func](ProcedureContext& ctx, BytesSource) -> std::vector { - auto result = func(ctx); + auto result = __spacetimedb_begin_short_backtrace([&] { + return func(ctx); + }); IterBuf buf = IterBuf::take(); { bsatn::Writer writer(buf.get()); @@ -539,9 +553,11 @@ public: return [](std::index_sequence, Func fn, ProcedureContext& ctx_inner, const std::vector& bytes) -> std::vector { bsatn::Reader reader(bytes.data(), bytes.size()); auto args = std::make_tuple(bsatn::deserialize>(reader)...); - auto result = std::apply([&ctx_inner, fn](auto&&... unpacked) { - return fn(ctx_inner, std::forward(unpacked)...); - }, args); + auto result = __spacetimedb_begin_short_backtrace([&] { + return std::apply([&ctx_inner, fn](auto&&... unpacked) { + return fn(ctx_inner, std::forward(unpacked)...); + }, args); + }); IterBuf buf = IterBuf::take(); { bsatn::Writer writer(buf.get()); diff --git a/crates/bindings-csharp/Codegen.Tests/fixtures/diag/snapshots/Module#FFI.verified.cs b/crates/bindings-csharp/Codegen.Tests/fixtures/diag/snapshots/Module#FFI.verified.cs index 3ce055b4b..921019b30 100644 --- a/crates/bindings-csharp/Codegen.Tests/fixtures/diag/snapshots/Module#FFI.verified.cs +++ b/crates/bindings-csharp/Codegen.Tests/fixtures/diag/snapshots/Module#FFI.verified.cs @@ -2053,6 +2053,14 @@ sealed class view_def_ienumerable_return_from_filterViewDispatcher public byte[] Invoke( System.IO.BinaryReader reader, global::SpacetimeDB.Internal.IViewContext ctx + ) => __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static byte[] __spacetimedb_begin_short_backtrace( + System.IO.BinaryReader reader, + global::SpacetimeDB.Internal.IViewContext ctx ) { try @@ -2103,6 +2111,14 @@ sealed class view_def_ienumerable_return_from_iterViewDispatcher public byte[] Invoke( System.IO.BinaryReader reader, global::SpacetimeDB.Internal.IViewContext ctx + ) => __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static byte[] __spacetimedb_begin_short_backtrace( + System.IO.BinaryReader reader, + global::SpacetimeDB.Internal.IViewContext ctx ) { try @@ -2147,6 +2163,14 @@ sealed class view_def_no_contextViewDispatcher : global::SpacetimeDB.Internal.IV public byte[] Invoke( System.IO.BinaryReader reader, global::SpacetimeDB.Internal.IViewContext ctx + ) => __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static byte[] __spacetimedb_begin_short_backtrace( + System.IO.BinaryReader reader, + global::SpacetimeDB.Internal.IViewContext ctx ) { try @@ -2189,6 +2213,14 @@ sealed class view_def_no_publicViewDispatcher : global::SpacetimeDB.Internal.IVi public byte[] Invoke( System.IO.BinaryReader reader, global::SpacetimeDB.Internal.IViewContext ctx + ) => __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static byte[] __spacetimedb_begin_short_backtrace( + System.IO.BinaryReader reader, + global::SpacetimeDB.Internal.IViewContext ctx ) { try @@ -2231,6 +2263,14 @@ sealed class view_def_wrong_contextViewDispatcher : global::SpacetimeDB.Internal public byte[] Invoke( System.IO.BinaryReader reader, global::SpacetimeDB.Internal.IViewContext ctx + ) => __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static byte[] __spacetimedb_begin_short_backtrace( + System.IO.BinaryReader reader, + global::SpacetimeDB.Internal.IViewContext ctx ) { try @@ -2271,6 +2311,14 @@ sealed class view_def_wrong_returnViewDispatcher : global::SpacetimeDB.Internal. public byte[] Invoke( System.IO.BinaryReader reader, global::SpacetimeDB.Internal.IViewContext ctx + ) => __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static byte[] __spacetimedb_begin_short_backtrace( + System.IO.BinaryReader reader, + global::SpacetimeDB.Internal.IViewContext ctx ) { try @@ -2312,6 +2360,14 @@ sealed class view_no_deleteViewDispatcher : global::SpacetimeDB.Internal.IView public byte[] Invoke( System.IO.BinaryReader reader, global::SpacetimeDB.Internal.IViewContext ctx + ) => __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static byte[] __spacetimedb_begin_short_backtrace( + System.IO.BinaryReader reader, + global::SpacetimeDB.Internal.IViewContext ctx ) { try @@ -2357,6 +2413,14 @@ sealed class view_no_insertViewDispatcher : global::SpacetimeDB.Internal.IView public byte[] Invoke( System.IO.BinaryReader reader, global::SpacetimeDB.Internal.IViewContext ctx + ) => __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static byte[] __spacetimedb_begin_short_backtrace( + System.IO.BinaryReader reader, + global::SpacetimeDB.Internal.IViewContext ctx ) { try @@ -2402,6 +2466,14 @@ sealed class view_def_index_no_mutationViewDispatcher : global::SpacetimeDB.Inte public byte[] Invoke( System.IO.BinaryReader reader, global::SpacetimeDB.Internal.IAnonymousViewContext ctx + ) => __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static byte[] __spacetimedb_begin_short_backtrace( + System.IO.BinaryReader reader, + global::SpacetimeDB.Internal.IAnonymousViewContext ctx ) { try @@ -2447,6 +2519,14 @@ sealed class view_def_no_anon_identityViewDispatcher : global::SpacetimeDB.Inter public byte[] Invoke( System.IO.BinaryReader reader, global::SpacetimeDB.Internal.IAnonymousViewContext ctx + ) => __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static byte[] __spacetimedb_begin_short_backtrace( + System.IO.BinaryReader reader, + global::SpacetimeDB.Internal.IAnonymousViewContext ctx ) { try @@ -2492,6 +2572,14 @@ sealed class view_def_no_iterViewDispatcher : global::SpacetimeDB.Internal.IAnon public byte[] Invoke( System.IO.BinaryReader reader, global::SpacetimeDB.Internal.IAnonymousViewContext ctx + ) => __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static byte[] __spacetimedb_begin_short_backtrace( + System.IO.BinaryReader reader, + global::SpacetimeDB.Internal.IAnonymousViewContext ctx ) { try @@ -2539,6 +2627,14 @@ sealed class view_def_returns_not_a_spacetime_typeViewDispatcher public byte[] Invoke( System.IO.BinaryReader reader, global::SpacetimeDB.Internal.IAnonymousViewContext ctx + ) => __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static byte[] __spacetimedb_begin_short_backtrace( + System.IO.BinaryReader reader, + global::SpacetimeDB.Internal.IAnonymousViewContext ctx ) { try @@ -2981,7 +3077,16 @@ static class ModuleRegistration public SpacetimeDB.Internal.Lifecycle? Lifecycle => null; - public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) + public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) => + __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static void __spacetimedb_begin_short_backtrace( + BinaryReader reader, + SpacetimeDB.Internal.IReducerContext ctx + ) { Reducers.__ReducerWithReservedPrefix((SpacetimeDB.ReducerContext)ctx); } @@ -3004,7 +3109,16 @@ static class ModuleRegistration public SpacetimeDB.Internal.Lifecycle? Lifecycle => null; - public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) + public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) => + __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static void __spacetimedb_begin_short_backtrace( + BinaryReader reader, + SpacetimeDB.Internal.IReducerContext ctx + ) { TestScheduleIssues.DummyScheduledReducer( (SpacetimeDB.ReducerContext)ctx, @@ -3028,7 +3142,16 @@ static class ModuleRegistration public SpacetimeDB.Internal.Lifecycle? Lifecycle => null; - public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) + public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) => + __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static void __spacetimedb_begin_short_backtrace( + BinaryReader reader, + SpacetimeDB.Internal.IReducerContext ctx + ) { Reducers.OnReducerWithReservedPrefix((SpacetimeDB.ReducerContext)ctx); } @@ -3049,7 +3172,16 @@ static class ModuleRegistration public SpacetimeDB.Internal.Lifecycle? Lifecycle => SpacetimeDB.Internal.Lifecycle.Init; - public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) + public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) => + __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static void __spacetimedb_begin_short_backtrace( + BinaryReader reader, + SpacetimeDB.Internal.IReducerContext ctx + ) { Reducers.TestDuplicateReducerKind1((SpacetimeDB.ReducerContext)ctx); } @@ -3070,7 +3202,16 @@ static class ModuleRegistration public SpacetimeDB.Internal.Lifecycle? Lifecycle => SpacetimeDB.Internal.Lifecycle.Init; - public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) + public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) => + __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static void __spacetimedb_begin_short_backtrace( + BinaryReader reader, + SpacetimeDB.Internal.IReducerContext ctx + ) { Reducers.TestDuplicateReducerKind2((SpacetimeDB.ReducerContext)ctx); } @@ -3091,7 +3232,16 @@ static class ModuleRegistration public SpacetimeDB.Internal.Lifecycle? Lifecycle => null; - public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) + public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) => + __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static void __spacetimedb_begin_short_backtrace( + BinaryReader reader, + SpacetimeDB.Internal.IReducerContext ctx + ) { Reducers.TestDuplicateReducerName((SpacetimeDB.ReducerContext)ctx); } @@ -3112,7 +3262,16 @@ static class ModuleRegistration public SpacetimeDB.Internal.Lifecycle? Lifecycle => null; - public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) + public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) => + __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static void __spacetimedb_begin_short_backtrace( + BinaryReader reader, + SpacetimeDB.Internal.IReducerContext ctx + ) { Reducers.TestReducerReturnType((SpacetimeDB.ReducerContext)ctx); } @@ -3133,7 +3292,16 @@ static class ModuleRegistration public SpacetimeDB.Internal.Lifecycle? Lifecycle => null; - public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) + public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) => + __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static void __spacetimedb_begin_short_backtrace( + BinaryReader reader, + SpacetimeDB.Internal.IReducerContext ctx + ) { throw new System.InvalidOperationException(); } diff --git a/crates/bindings-csharp/Codegen.Tests/fixtures/explicitnames/snapshots/Module#FFI.verified.cs b/crates/bindings-csharp/Codegen.Tests/fixtures/explicitnames/snapshots/Module#FFI.verified.cs index a9774bfc6..bc9e34c4c 100644 --- a/crates/bindings-csharp/Codegen.Tests/fixtures/explicitnames/snapshots/Module#FFI.verified.cs +++ b/crates/bindings-csharp/Codegen.Tests/fixtures/explicitnames/snapshots/Module#FFI.verified.cs @@ -370,6 +370,14 @@ sealed class demo_viewViewDispatcher : global::SpacetimeDB.Internal.IView public byte[] Invoke( System.IO.BinaryReader reader, global::SpacetimeDB.Internal.IViewContext ctx + ) => __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static byte[] __spacetimedb_begin_short_backtrace( + System.IO.BinaryReader reader, + global::SpacetimeDB.Internal.IViewContext ctx ) { try @@ -477,7 +485,16 @@ static class ModuleRegistration public SpacetimeDB.Internal.Lifecycle? Lifecycle => null; - public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) + public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) => + __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static void __spacetimedb_begin_short_backtrace( + BinaryReader reader, + SpacetimeDB.Internal.IReducerContext ctx + ) { Reducers.DemoReducer((SpacetimeDB.ReducerContext)ctx, valueRW.Read(reader)); } @@ -495,7 +512,16 @@ static class ModuleRegistration Visibility: SpacetimeDB.Internal.FunctionVisibility.ClientCallable ); - public byte[] Invoke(BinaryReader reader, SpacetimeDB.Internal.IProcedureContext ctx) + public byte[] Invoke(BinaryReader reader, SpacetimeDB.Internal.IProcedureContext ctx) => + __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static byte[] __spacetimedb_begin_short_backtrace( + BinaryReader reader, + SpacetimeDB.Internal.IProcedureContext ctx + ) { Reducers.DemoProcedure((SpacetimeDB.ProcedureContext)ctx); return System.Array.Empty(); diff --git a/crates/bindings-csharp/Codegen.Tests/fixtures/server/snapshots/Module#FFI.verified.cs b/crates/bindings-csharp/Codegen.Tests/fixtures/server/snapshots/Module#FFI.verified.cs index 4632875e0..bc1acbae7 100644 --- a/crates/bindings-csharp/Codegen.Tests/fixtures/server/snapshots/Module#FFI.verified.cs +++ b/crates/bindings-csharp/Codegen.Tests/fixtures/server/snapshots/Module#FFI.verified.cs @@ -1725,6 +1725,14 @@ sealed class public_table_queryViewDispatcher : global::SpacetimeDB.Internal.IVi public byte[] Invoke( System.IO.BinaryReader reader, global::SpacetimeDB.Internal.IViewContext ctx + ) => __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static byte[] __spacetimedb_begin_short_backtrace( + System.IO.BinaryReader reader, + global::SpacetimeDB.Internal.IViewContext ctx ) { try @@ -1767,6 +1775,14 @@ sealed class public_table_viewViewDispatcher : global::SpacetimeDB.Internal.IVie public byte[] Invoke( System.IO.BinaryReader reader, global::SpacetimeDB.Internal.IViewContext ctx + ) => __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static byte[] __spacetimedb_begin_short_backtrace( + System.IO.BinaryReader reader, + global::SpacetimeDB.Internal.IViewContext ctx ) { try @@ -1814,6 +1830,14 @@ sealed class find_public_table__by_identityViewDispatcher public byte[] Invoke( System.IO.BinaryReader reader, global::SpacetimeDB.Internal.IAnonymousViewContext ctx + ) => __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static byte[] __spacetimedb_begin_short_backtrace( + System.IO.BinaryReader reader, + global::SpacetimeDB.Internal.IAnonymousViewContext ctx ) { try @@ -2286,7 +2310,16 @@ static class ModuleRegistration public SpacetimeDB.Internal.Lifecycle? Lifecycle => SpacetimeDB.Internal.Lifecycle.Init; - public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) + public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) => + __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static void __spacetimedb_begin_short_backtrace( + BinaryReader reader, + SpacetimeDB.Internal.IReducerContext ctx + ) { Timers.Init((SpacetimeDB.ReducerContext)ctx); } @@ -2309,7 +2342,16 @@ static class ModuleRegistration public SpacetimeDB.Internal.Lifecycle? Lifecycle => null; - public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) + public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) => + __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static void __spacetimedb_begin_short_backtrace( + BinaryReader reader, + SpacetimeDB.Internal.IReducerContext ctx + ) { Reducers.InsertData((SpacetimeDB.ReducerContext)ctx, dataRW.Read(reader)); } @@ -2332,7 +2374,16 @@ static class ModuleRegistration public SpacetimeDB.Internal.Lifecycle? Lifecycle => null; - public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) + public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) => + __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static void __spacetimedb_begin_short_backtrace( + BinaryReader reader, + SpacetimeDB.Internal.IReducerContext ctx + ) { Test.NestingNamespaces.AndClasses.InsertData2( (SpacetimeDB.ReducerContext)ctx, @@ -2358,7 +2409,16 @@ static class ModuleRegistration public SpacetimeDB.Internal.Lifecycle? Lifecycle => null; - public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) + public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) => + __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static void __spacetimedb_begin_short_backtrace( + BinaryReader reader, + SpacetimeDB.Internal.IReducerContext ctx + ) { MultiTableRow.InsertMultiData((SpacetimeDB.ReducerContext)ctx, dataRW.Read(reader)); } @@ -2381,7 +2441,16 @@ static class ModuleRegistration public SpacetimeDB.Internal.Lifecycle? Lifecycle => null; - public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) + public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) => + __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static void __spacetimedb_begin_short_backtrace( + BinaryReader reader, + SpacetimeDB.Internal.IReducerContext ctx + ) { Reducers.ScheduleImmediate((SpacetimeDB.ReducerContext)ctx, dataRW.Read(reader)); } @@ -2404,7 +2473,16 @@ static class ModuleRegistration public SpacetimeDB.Internal.Lifecycle? Lifecycle => null; - public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) + public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) => + __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl( + System.Runtime.CompilerServices.MethodImplOptions.NoInlining + )] + private static void __spacetimedb_begin_short_backtrace( + BinaryReader reader, + SpacetimeDB.Internal.IReducerContext ctx + ) { Timers.SendScheduledMessage((SpacetimeDB.ReducerContext)ctx, argRW.Read(reader)); } diff --git a/crates/bindings-csharp/Codegen/Module.cs b/crates/bindings-csharp/Codegen/Module.cs index e778b6d69..415d403e9 100644 --- a/crates/bindings-csharp/Codegen/Module.cs +++ b/crates/bindings-csharp/Codegen/Module.cs @@ -1389,6 +1389,12 @@ record ViewDeclaration public byte[] Invoke( System.IO.BinaryReader reader, {{{interfaceContext}}} ctx + ) => __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl(System.Runtime.CompilerServices.MethodImplOptions.NoInlining)] + private static byte[] __spacetimedb_begin_short_backtrace( + System.IO.BinaryReader reader, + {{{interfaceContext}}} ctx ) { try { {{{paramReads}}} @@ -1491,7 +1497,11 @@ record ReducerDeclaration _ => "null" }}}; - public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) { + public void Invoke(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) => + __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl(System.Runtime.CompilerServices.MethodImplOptions.NoInlining)] + private static void __spacetimedb_begin_short_backtrace(BinaryReader reader, SpacetimeDB.Internal.IReducerContext ctx) { {{invocation}}; } } @@ -1713,7 +1723,11 @@ record ProcedureDeclaration Visibility: SpacetimeDB.Internal.FunctionVisibility.ClientCallable ); - public byte[] Invoke(BinaryReader reader, SpacetimeDB.Internal.IProcedureContext ctx) { + public byte[] Invoke(BinaryReader reader, SpacetimeDB.Internal.IProcedureContext ctx) => + __spacetimedb_begin_short_backtrace(reader, ctx); + + [System.Runtime.CompilerServices.MethodImpl(System.Runtime.CompilerServices.MethodImplOptions.NoInlining)] + private static byte[] __spacetimedb_begin_short_backtrace(BinaryReader reader, SpacetimeDB.Internal.IProcedureContext ctx) { {{{paramReads}}}{{{invokeBody}}} } } diff --git a/crates/bindings-macro/src/lib.rs b/crates/bindings-macro/src/lib.rs index 8fa9705ca..d01f275a1 100644 --- a/crates/bindings-macro/src/lib.rs +++ b/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::(args, item, quote!(), |args, original_function| { + cvt_attr::(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::(args, item, quote!(), |args, original_function| { + cvt_attr::(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 { diff --git a/crates/bindings-macro/src/view.rs b/crates/bindings-macro/src/view.rs index 63bed482f..29244345c 100644 --- a/crates/bindings-macro/src/view.rs +++ b/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 diff --git a/crates/bindings-typescript/src/server/procedures.ts b/crates/bindings-typescript/src/server/procedures.ts index 5e0791c15..708ef9e92 100644 --- a/crates/bindings-typescript/src/server/procedures.ts +++ b/crates/bindings-typescript/src/server/procedures.ts @@ -107,7 +107,7 @@ function registerProcedure< fn: ProcedureFn, opts?: ProcedureOpts ) { - ctx.defineFunction(exportName); + ctx.defineFunction(exportName, fn); const paramsType: ProductType = { elements: Object.entries(params).map(([n, c]) => ({ name: n, diff --git a/crates/bindings-typescript/src/server/reducers.ts b/crates/bindings-typescript/src/server/reducers.ts index f8aa1c390..fc6da29ad 100644 --- a/crates/bindings-typescript/src/server/reducers.ts +++ b/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); } diff --git a/crates/bindings-typescript/src/server/schema.ts b/crates/bindings-typescript/src/server/schema.ts index b9eb25876..03e6e23dd 100644 --- a/crates/bindings-typescript/src/server/schema.ts +++ b/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() { diff --git a/crates/bindings-typescript/src/server/views.ts b/crates/bindings-typescript/src/server/views.ts index accd0c925..1bad5f492 100644 --- a/crates/bindings-typescript/src/server/views.ts +++ b/crates/bindings-typescript/src/server/views.ts @@ -143,6 +143,12 @@ export function registerView< ? AnonymousViewFn : ViewFn ) { + // 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 diff --git a/crates/bindings/src/rt.rs b/crates/bindings/src/rt.rs index d6d55eba5..f64b46f7e 100644 --- a/crates/bindings/src/rt.rs +++ b/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> { 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: F) -> T +where + F: FnOnce() -> T, +{ + let result = f(); + + // prevent this frame from being tail-call optimised away + std::hint::black_box(()); + + result +} diff --git a/crates/cli/src/subcommands/logs.rs b/crates/cli/src/subcommands/logs.rs index 57d388fea..3dc938b8a 100644 --- a/crates/cli/src/subcommands/logs.rs +++ b/crates/cli/src/subcommands/logs.rs @@ -158,6 +158,32 @@ pub struct BacktraceFrame<'a> { pub module_name: Option>, #[serde(borrow)] pub func_name: Option>, + #[serde(borrow)] + pub file: Option>, + pub line: Option, + pub column: Option, + #[serde(default)] + pub symbols: Vec>, + #[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>, + #[serde(borrow)] + pub file: Option>, + pub line: Option, + pub column: Option, } #[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(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(""); + 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 => "", + }; + 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, level_exact: bool) -> bool { match min_level { diff --git a/crates/cli/src/tasks/mod.rs b/crates/cli/src/tasks/mod.rs index 16414efbe..ada670642 100644 --- a/crates/cli/src/tasks/mod.rs +++ b/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) => { diff --git a/crates/core/src/database_logger.rs b/crates/core/src/database_logger.rs index 0e202229d..518b3feea 100644 --- a/crates/core/src/database_logger.rs +++ b/crates/core/src/database_logger.rs @@ -254,22 +254,40 @@ impl<'a> Record<'a> { } pub trait BacktraceProvider { - fn capture(&self) -> Box; + fn capture(&self) -> Box; } impl BacktraceProvider for () { - fn capture(&self) -> Box { - Box::new(()) + fn capture(&self) -> Box { + struct Empty; + impl ModuleBacktrace for Empty { + fn frames(&self) -> Box> + '_> { + Box::new(std::iter::empty()) + } + } + Box::new(Empty) + } +} + +impl BacktraceProvider for T { + fn capture(&self) -> Box { + Box::new(self) } } pub trait ModuleBacktrace { - fn frames(&self) -> Vec>; + fn frames(&self) -> Box> + '_>; } -impl ModuleBacktrace for () { - fn frames(&self) -> Vec> { - vec![] +impl ModuleBacktrace for &T { + fn frames(&self) -> Box> + '_> { + (**self).frames() + } +} + +impl serde::Serialize for dyn ModuleBacktrace + '_ { + fn serialize(&self, serializer: S) -> Result { + serializer.collect_seq(self.frames()) } } @@ -277,10 +295,38 @@ impl ModuleBacktrace for () { #[serde_with::serde_as] #[derive(serde::Serialize)] pub struct BacktraceFrame<'a> { - #[serde_as(as = "Option")] - pub module_name: Option<&'a str>, #[serde_as(as = "Option")] pub func_name: Option<&'a str>, + pub file: Option<&'a str>, + pub line: Option, + pub column: Option, + #[serde(flatten)] + pub kind: BacktraceFrameKind<'a>, +} + +#[serde_with::skip_serializing_none] +#[serde_with::serde_as] +#[derive(serde::Serialize)] +#[serde(rename_all = "lowercase", tag = "kind")] +pub enum BacktraceFrameKind<'a> { + Wasm { + #[serde_as(as = "Option")] + module_name: Option<&'a str>, + #[serde(skip_serializing_if = "<[_]>::is_empty")] + symbols: Box<[BacktraceFrameSymbol<'a>]>, + }, + Js, +} + +#[serde_with::skip_serializing_none] +#[serde_with::serde_as] +#[derive(serde::Serialize, Copy, Clone)] +pub struct BacktraceFrameSymbol<'a> { + #[serde_as(as = "Option")] + pub name: Option<&'a str>, + pub file: Option<&'a str>, + pub line: Option, + pub column: Option, } struct DemangleSymbol; @@ -290,7 +336,7 @@ impl serde_with::SerializeAs<&str> for DemangleSymbol { S: serde::Serializer, { if let Ok(sym) = rustc_demangle::try_demangle(source) { - serializer.serialize_str(&sym.to_string()) + serializer.collect_str(&sym) } else { serializer.serialize_str(source) } @@ -309,7 +355,7 @@ enum LogEvent<'a> { Panic { #[serde(flatten)] record: Record<'a>, - trace: &'a [BacktraceFrame<'a>], + trace: &'a dyn ModuleBacktrace, }, } @@ -355,7 +401,7 @@ impl DatabaseLogger { } pub fn write(&self, level: LogLevel, &record: &Record<'_>, bt: &dyn BacktraceProvider) { - let (trace, frames); + let trace; let event = match level { LogLevel::Error => LogEvent::Error(record), LogLevel::Warn => LogEvent::Warn(record), @@ -364,8 +410,7 @@ impl DatabaseLogger { LogLevel::Trace => LogEvent::Trace(record), LogLevel::Panic => { trace = bt.capture(); - frames = trace.frames(); - LogEvent::Panic { record, trace: &frames } + LogEvent::Panic { record, trace: &*trace } } }; // TODO(perf): Reuse serialization buffer. diff --git a/crates/core/src/host/instance_env.rs b/crates/core/src/host/instance_env.rs index 96b876a03..c77d1f6b7 100644 --- a/crates/core/src/host/instance_env.rs +++ b/crates/core/src/host/instance_env.rs @@ -1,5 +1,5 @@ use super::scheduler::{get_schedule_from_row, ScheduleError, Scheduler}; -use crate::database_logger::{BacktraceFrame, BacktraceProvider, LogLevel, ModuleBacktrace, Record}; +use crate::database_logger::{BacktraceProvider, LogLevel, Record}; use crate::db::relational_db::{MutTx, RelationalDB}; use crate::error::{DBError, DatastoreError, IndexError, NodesError}; use crate::host::module_host::{DatabaseUpdate, EventStatus, ModuleEvent, ModuleFunctionCall}; @@ -298,19 +298,6 @@ impl InstanceEnv { /// Logs a simple `message` at `level`. pub(crate) fn console_log_simple_message(&self, level: LogLevel, function: Option<&str>, message: &str) { - /// A backtrace provider that provides nothing. - struct Noop; - impl BacktraceProvider for Noop { - fn capture(&self) -> Box { - Box::new(Noop) - } - } - impl ModuleBacktrace for Noop { - fn frames(&self) -> Vec> { - Vec::new() - } - } - let record = Record { ts: Self::now_for_logging(), target: None, @@ -319,7 +306,7 @@ impl InstanceEnv { function, message, }; - self.console_log(level, &record, &Noop); + self.console_log(level, &record, &()); } /// End a console timer by logging the span at INFO level. diff --git a/crates/core/src/host/v8/error.rs b/crates/core/src/host/v8/error.rs index 451c33a72..37fc7f9aa 100644 --- a/crates/core/src/host/v8/error.rs +++ b/crates/core/src/host/v8/error.rs @@ -2,9 +2,10 @@ use super::serialize_to_js; use super::string::IntoJsString; +use crate::database_logger::BacktraceFrameKind; use crate::error::NodesError; use crate::{ - database_logger::{BacktraceFrame, BacktraceProvider, LogLevel, ModuleBacktrace, Record}, + database_logger::{BacktraceFrame, LogLevel, ModuleBacktrace, Record}, host::instance_env::InstanceEnv, replica_context::ReplicaContext, }; @@ -344,36 +345,15 @@ impl fmt::Display for JsStackTrace { } } -impl BacktraceProvider for JsStackTrace { - fn capture(&self) -> Box { - 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 }) - } -} - -/// A rendered backtrace for a JS exception. -struct JsBacktrace { - trace: Vec<(String, String)>, -} - -impl ModuleBacktrace for JsBacktrace { - fn frames(&self) -> Vec> { - self.trace - .iter() - .map(|(module_name, func_name)| BacktraceFrame { - module_name: Some(module_name), - func_name: Some(func_name), - }) - .collect() +impl ModuleBacktrace for JsStackTrace { + fn frames(&self) -> Box> + '_> { + Box::new(self.frames.iter().map(|f| BacktraceFrame { + func_name: f.fn_name.as_deref(), + file: f.script_name.as_deref(), + line: Some(f.line as u32), + column: Some(f.column as u32), + kind: BacktraceFrameKind::Js, + })) } } @@ -546,10 +526,10 @@ impl JsError { } 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::() { - log::info!("JS error: {js_err}",); + // no need to log `JsError` separately; it'll be displayed if it exists in the error. + log::info!("{func_type} \"{func}\" raised a runtime error: {e:#}"); + if let Some(js_err) = e.downcast_ref::() { // Also log to module logs. let first_frame = js_err.trace.frames.first(); let filename = first_frame.map(|f| f.script_name()); diff --git a/crates/core/src/host/wasmtime/wasm_instance_env.rs b/crates/core/src/host/wasmtime/wasm_instance_env.rs index 7c0b2a088..3b1838257 100644 --- a/crates/core/src/host/wasmtime/wasm_instance_env.rs +++ b/crates/core/src/host/wasmtime/wasm_instance_env.rs @@ -4,7 +4,9 @@ use super::wasmtime_module::{ call_view_export, decode_view_result_sink_code, CallViewAnonType, CallViewType, ViewResultSinkError, }; use super::{Mem, MemView, NullableMemOp, WasmError, WasmPointee, WasmPtr}; -use crate::database_logger::{BacktraceFrame, BacktraceProvider, ModuleBacktrace, Record}; +use crate::database_logger::{ + BacktraceFrame, BacktraceFrameKind, BacktraceFrameSymbol, BacktraceProvider, ModuleBacktrace, Record, +}; use crate::error::NodesError; use crate::host::instance_env::{ChunkPool, InstanceEnv}; use crate::host::wasm_common::instrumentation::{span, CallTimes}; @@ -1971,19 +1973,55 @@ impl WasmInstanceEnv { type Fut<'caller, T> = Box>; impl BacktraceProvider for wasmtime::StoreContext<'_, T> { - fn capture(&self) -> Box { + fn capture(&self) -> Box { Box::new(wasmtime::WasmBacktrace::capture(self)) } } impl ModuleBacktrace for wasmtime::WasmBacktrace { - fn frames(&self) -> Vec> { - self.frames() + fn frames(&self) -> Box> + '_> { + let is_end_short_backtrace = |func_name: &str| { + func_name.contains("__spacetimedb_end_short_backtrace") || func_name.contains("__rust_end_short_backtrace") + }; + let is_begin_short_backtrace = |func_name: &str| { + func_name.contains("__spacetimedb_begin_short_backtrace") + || func_name.contains("__rust_begin_short_backtrace") + }; + + let frames = self.frames(); + + // Handle gracefully the case where there's no `end_short_backtrace` frame in the stack + // (e.g. because the trace wasn't collected in a panic handler, or isn't from rust code). + let frames = frames .iter() - .map(|f| BacktraceFrame { - module_name: None, - func_name: f.func_name(), - }) - .collect() + .position(|f| f.func_name().is_some_and(is_end_short_backtrace)) + .map_or(frames, |i| &frames[i + 1..]); + + let frames = frames + .split(|f| f.func_name().is_some_and(is_begin_short_backtrace)) + .next() + .unwrap(); + + Box::new(frames.iter().map(|f| BacktraceFrame { + func_name: f.func_name(), + file: None, + line: None, + column: None, + kind: BacktraceFrameKind::Wasm { + module_name: f.module().name(), + symbols: f.symbols().iter().map(BacktraceFrameSymbol::from).collect(), + }, + })) + } +} + +impl<'a> From<&'a wasmtime::FrameSymbol> for BacktraceFrameSymbol<'a> { + fn from(sym: &'a wasmtime::FrameSymbol) -> Self { + Self { + name: sym.name(), + file: sym.file(), + line: sym.line(), + column: sym.column(), + } } } diff --git a/crates/core/src/host/wasmtime/wasmtime_module.rs b/crates/core/src/host/wasmtime/wasmtime_module.rs index 0690120eb..4585bbd77 100644 --- a/crates/core/src/host/wasmtime/wasmtime_module.rs +++ b/crates/core/src/host/wasmtime/wasmtime_module.rs @@ -22,22 +22,12 @@ use spacetimedb_primitives::errno::HOST_CALL_FAILURE; use spacetimedb_schema::def::ModuleDef; use spacetimedb_schema::identifier::Identifier; use wasmtime::{ - AsContext, AsContextMut, ExternType, Instance, InstancePre, Linker, Store, TypedFunc, WasmBacktrace, WasmParams, - WasmResults, + AsContext, AsContextMut, ExternType, Instance, InstancePre, Linker, Store, TypedFunc, WasmParams, WasmResults, }; fn log_traceback(func_type: &str, func: &str, e: &wasmtime::Error) { - log::info!("{func_type} \"{func}\" runtime error: {e}"); - if let Some(bt) = e.downcast_ref::() { - let frames_len = bt.frames().len(); - for (i, frame) in bt.frames().iter().enumerate() { - log::info!( - " Frame #{}: {}", - frames_len - i, - rustc_demangle::demangle(frame.func_name().unwrap_or("")) - ); - } - } + // no need to handle `WasmBacktrace` separately; it'll be displayed if it exists in the error. + log::info!("{func_type} \"{func}\" raised a runtime error (panic message in module logs): {e:#}"); } #[derive(Clone)] diff --git a/templates/basic-rs/spacetimedb/Cargo.toml b/templates/basic-rs/spacetimedb/Cargo.toml index 5aef99717..fedec91dd 100644 --- a/templates/basic-rs/spacetimedb/Cargo.toml +++ b/templates/basic-rs/spacetimedb/Cargo.toml @@ -8,6 +8,9 @@ edition = "2024" [lib] crate-type = ["cdylib"] +[profile.release] +debug = 1 # include some location information for backtraces + [dependencies] spacetimedb = { path = "../../../crates/bindings" } log = "0.4"