Simplified backtraces #12305

SpecificProtagonist · 2024-03-04T22:24:13Z

Objective

Remove Bevy internals from backtraces

Solution

Executors insert __rust_begin_short_backtrace into the callstack before running a system.

Example current output

thread 'Compute Task Pool (3)' panicked at src/main.rs:7:33:
Foo
stack backtrace:
   0: rust_begin_unwind
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:647:5
   1: core::panicking::panic_fmt
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/panicking.rs:72:14
   2: foo::main::{{closure}}
             at ./src/main.rs:7:33
   3: core::ops::function::impls::<impl core::ops::function::FnMut<A> for &mut F>::call_mut
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/ops/function.rs:294:13
   4: <Func as bevy_ecs::system::function_system::SystemParamFunction<fn() .> Out>>::run::call_inner
             at /home/vj/workspace/rust/bevy/crates/bevy_ecs/src/system/function_system.rs:661:21
   5: <Func as bevy_ecs::system::function_system::SystemParamFunction<fn() .> Out>>::run
             at /home/vj/workspace/rust/bevy/crates/bevy_ecs/src/system/function_system.rs:664:17
   6: <bevy_ecs::system::function_system::FunctionSystem<Marker,F> as bevy_ecs::system::system::System>::run_unsafe
             at /home/vj/workspace/rust/bevy/crates/bevy_ecs/src/system/function_system.rs:504:19
   7: bevy_ecs::schedule::executor::multi_threaded::ExecutorState::spawn_system_task::{{closure}}::{{closure}}
             at /home/vj/workspace/rust/bevy/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs:621:26
   8: core::ops::function::FnOnce::call_once
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/ops/function.rs:250:5
   9: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/panic/unwind_safe.rs:272:9
  10: std::panicking::try::do_call
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:554:40
  11: __rust_try
  12: std::panicking::try
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:518:19
  13: std::panic::catch_unwind
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panic.rs:142:14
  14: bevy_ecs::schedule::executor::multi_threaded::ExecutorState::spawn_system_task::{{closure}}
             at /home/vj/workspace/rust/bevy/crates/bevy_ecs/src/schedule/executor/multi_threaded.rs:614:23
  15: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::future::future::Future>::poll
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/panic/unwind_safe.rs:297:9
  16: <futures_lite::future::CatchUnwind<F> as core::future::future::Future>::poll::{{closure}}
             at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/futures-lite-2.2.0/src/future.rs:588:42
  17: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/panic/unwind_safe.rs:272:9
  18: std::panicking::try::do_call
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:554:40
  19: __rust_try
  20: std::panicking::try
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:518:19
  21: std::panic::catch_unwind
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panic.rs:142:14
  22: <futures_lite::future::CatchUnwind<F> as core::future::future::Future>::poll
             at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/futures-lite-2.2.0/src/future.rs:588:9
  23: async_executor::Executor::spawn::{{closure}}
             at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/async-executor-1.8.0/src/lib.rs:158:20
  24: async_task::raw::RawTask<F,T,S,M>::run::{{closure}}
             at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/async-task-4.7.0/src/raw.rs:550:21
  25: core::ops::function::FnOnce::call_once
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/ops/function.rs:250:5
  26: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/panic/unwind_safe.rs:272:9
  27: std::panicking::try::do_call
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:554:40
  28: __rust_try
  29: std::panicking::try
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:518:19
  30: std::panic::catch_unwind
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panic.rs:142:14
  31: async_task::raw::RawTask<F,T,S,M>::run
             at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/async-task-4.7.0/src/raw.rs:549:23
  32: async_task::runnable::Runnable<M>::run
             at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/async-task-4.7.0/src/runnable.rs:781:18
  33: async_executor::Executor::run::{{closure}}::{{closure}}
             at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/async-executor-1.8.0/src/lib.rs:254:21
  34: <futures_lite::future::Or<F1,F2> as core::future::future::Future>::poll
             at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/futures-lite-2.2.0/src/future.rs:449:33
  35: async_executor::Executor::run::{{closure}}
             at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/async-executor-1.8.0/src/lib.rs:261:32
  36: futures_lite::future::block_on::{{closure}}
             at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/futures-lite-2.2.0/src/future.rs:99:19
  37: std::thread::local::LocalKey<T>::try_with
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/thread/local.rs:286:16
  38: std::thread::local::LocalKey<T>::with
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/thread/local.rs:262:9
  39: futures_lite::future::block_on
             at /home/vj/.cargo/registry/src/index.crates.io-6f17d22bba15001f/futures-lite-2.2.0/src/future.rs:78:5
  40: bevy_tasks::task_pool::TaskPool::new_internal::{{closure}}::{{closure}}::{{closure}}::{{closure}}
             at /home/vj/workspace/rust/bevy/crates/bevy_tasks/src/task_pool.rs:180:37
  41: std::panicking::try::do_call
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:554:40
  42: __rust_try
  43: std::panicking::try
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:518:19
  44: std::panic::catch_unwind
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panic.rs:142:14
  45: bevy_tasks::task_pool::TaskPool::new_internal::{{closure}}::{{closure}}::{{closure}}
             at /home/vj/workspace/rust/bevy/crates/bevy_tasks/src/task_pool.rs:174:43
  46: std::thread::local::LocalKey<T>::try_with
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/thread/local.rs:286:16
  47: std::thread::local::LocalKey<T>::with
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/thread/local.rs:262:9
  48: bevy_tasks::task_pool::TaskPool::new_internal::{{closure}}::{{closure}}
             at /home/vj/workspace/rust/bevy/crates/bevy_tasks/src/task_pool.rs:167:25
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
Encountered a panic in system `foo::main::{{closure}}`!
Encountered a panic in system `bevy_app::main_schedule::Main::run_main`!
get on your knees and beg mommy for forgiveness you pervert~ 💖

Example output with this PR

Panic at src/main.rs:7:33:
Foo
stack backtrace:
   0: rust_begin_unwind
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/std/src/panicking.rs:647:5
   1: core::panicking::panic_fmt
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/panicking.rs:72:14
   2: foo::main::{{closure}}
             at ./src/main.rs:7:59
   3: core::ops::function::impls::<impl core::ops::function::FnMut<A> for &mut F>::call_mut
             at /rustc/8ace7ea1f7cbba7b4f031e66c54ca237a0d65de6/library/core/src/ops/function.rs:294:13
   4: <Func as bevy_ecs::system::function_system::SystemParamFunction<fn() .> Out>>::run::call_inner
             at /home/vj/workspace/rust/bevy/crates/bevy_ecs/src/system/function_system.rs:661:21
   5: <Func as bevy_ecs::system::function_system::SystemParamFunction<fn() .> Out>>::run
             at /home/vj/workspace/rust/bevy/crates/bevy_ecs/src/system/function_system.rs:664:17
   6: <bevy_ecs::system::function_system::FunctionSystem<Marker,F> as bevy_ecs::system::system::System>::run_unsafe
             at /home/vj/workspace/rust/bevy/crates/bevy_ecs/src/system/function_system.rs:504:19
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
Encountered a panic in system `foo::main::{{closure}}`!
Encountered a panic in system `bevy_app::main_schedule::Main::run_main`!

Full backtraces (RUST_BACKTRACE=full) are unchanged.

Alternative solutions

Write a custom panic hook. This could potentially let use exclude a few more callstack frames but requires a dependency on backtrace and is incompatible with user-provided panic hooks.

Changelog

Backtraces now exclude many Bevy internals (unless RUST_BACKTRACE=full is used)

james7132

I'm against expanding bevy_utils with more things when it's become such a common dependency within the dep tree. If anything, bevy_tasks is probably where this should go since that's where our top-level catch_unwind calls are.

SpecificProtagonist · 2024-03-04T22:56:25Z

Yeah, I only put it into bevy_utils temporarily because bevy_dev_tools (#11341) isn't merged yet, but bevy_tasks would also be a good place.

ghost · 2024-03-04T23:47:28Z

Could you please ensure this is optional, I have my own panic handler =)

SpecificProtagonist · 2024-03-05T19:40:56Z

I've done some investigation and changed this to no longer require a custom panic hook. It just inserts an extra entry into the call stack. This also means it's just a change in bevy_ecs.

cart

The new outputs are blissfully simple. This has grated on me since the very beginning and I'm guessing others feel the same way. Thanks!

This impl seems reasonable and nicely scoped. Worth considering something in bevy_tasks, but I see no reason not to include this as-is right now as it solves the majority of real-world cases in a nice way.

BD103 · 2024-03-07T03:24:29Z

Now that bevy_dev_tools has been merged (#11341), can any part of this be moved there? I'm not sure I want bevy_ecs depending on bevy_dev_tools, but we should at least consider it.

SpecificProtagonist · 2024-03-07T04:34:50Z

Now that bevy_dev_tools has been merged (#11341), can any part of this be moved there? I'm not sure I want bevy_ecs depending on bevy_dev_tools, but we should at least consider it.

In the first iteration when this was a panic handler this was the plan, but as it's now it's just a special function name. Because this doesn't interfere with anything, it's always on.

james7132

Today I learned that __rust_begin_short_backtrace works generically in stable Rust.

This is 100% relying on unstable behavior, but the UX improvement is really compelling. Worst case they change it and all the garbage in the callstack becomes visible again.

crates/bevy_ecs/src/schedule/executor/mod.rs

BD103

This looks good! I think it could use a few more comments, probably also links to how Rust formats call stacks, but I won't block on it.

👍

JMS55 · 2024-03-07T21:39:38Z

What does the backtraces look like when there's a panic in the render world?

BD103 · 2024-03-07T22:38:29Z

What does the backtraces look like when there's a panic in the render world?

They're still not great. git apply this, then run RUST_BACKTRACE=1 cargo run --example lighting to see the backtrace.

diff --git a/crates/bevy_render/src/lib.rs b/crates/bevy_render/src/lib.rs
index d972356b0..c4e682d42 100644
--- a/crates/bevy_render/src/lib.rs
+++ b/crates/bevy_render/src/lib.rs
@@ -438,6 +438,7 @@ unsafe fn initialize_render_app(app: &mut App) {
                 )
                     .in_set(RenderSet::Render),
                 World::clear_entities.in_set(RenderSet::Cleanup),
+                || panic!("Render world panic!"),
             ),
         );

SpecificProtagonist · 2024-03-07T23:41:04Z

Yeah, the original panic in the rendering thread gets shortened successfully, but the panic at

bevy/crates/bevy_render/src/pipelined_rendering.rs

Line 49 in 7148639

let render_app = self.render_to_app_receiver.recv().await.unwrap();

is still the same since it doesn't happen inside a system.

That second panic doesn't add any useful information, but we don't just want to call std::process:exit instead because that skips all destructors.

JMS55 · 2024-03-08T23:17:24Z

Is there any way we can skip printing the second panic?

james7132 · 2024-03-09T02:07:22Z

Unless we manipulate it using backtraces, that's likely going to show up for every level of std::panic::catch_unwind we have.

SpecificProtagonist · 2024-03-09T19:21:52Z

Changed it so that a render world panic causes an AppExit event instead of a second panic. The disadvantage of that though is that the process exits normally instead of with an error code.

Is there a way around that? Otherwise I'm not sure if that change is worth it.

BD103 · 2024-03-10T01:34:11Z

Is there a way around that? Otherwise I'm not sure if that change is worth it.

Perhaps AppExit can be modified to be AppExit(ExitCode), but that's probably worth it's own issue and PR.

crates/bevy_render/src/pipelined_rendering.rs

short backtrace wip

fb8291d

alice-i-cecile added C-Usability A targeted quality-of-life change that makes Bevy easier to use A-Diagnostics Logging, crash handling, error reporting and performance analysis labels Mar 4, 2024

alice-i-cecile requested review from JMS55 and BD103 March 4, 2024 22:38

james7132 requested changes Mar 4, 2024

View reviewed changes

BD103 mentioned this pull request Mar 5, 2024

Add bevy_dev_tools crate #11341

Merged

no custom panic hook

0cf1d95

Merge branch 'main' into short-backtrace

6a7fe87

SpecificProtagonist marked this pull request as ready for review March 5, 2024 19:41

SpecificProtagonist added 3 commits March 5, 2024 20:46

exclusive systems

8ae8dbc

clippy

7367655

clippy

323b51d

cart approved these changes Mar 6, 2024

View reviewed changes

james7132 approved these changes Mar 7, 2024

View reviewed changes

crates/bevy_ecs/src/schedule/executor/mod.rs Show resolved Hide resolved

BD103 approved these changes Mar 7, 2024

View reviewed changes

james7132 added the S-Ready-For-Final-Review This PR has been approved by the community. It's ready for a maintainer to consider merging it label Mar 8, 2024

SpecificProtagonist added 2 commits March 9, 2024 20:15

doc

1b5eac9

skip second panic if render world panics

fc54f7b

damnit clippy

41436e6

james7132 reviewed Mar 10, 2024

View reviewed changes

crates/bevy_render/src/pipelined_rendering.rs Outdated Show resolved Hide resolved

Update crates/bevy_render/src/pipelined_rendering.rs

cb87276

james7132 enabled auto-merge March 10, 2024 07:11

james7132 reviewed Mar 10, 2024

View reviewed changes

crates/bevy_render/src/pipelined_rendering.rs Outdated Show resolved Hide resolved

Update crates/bevy_render/src/pipelined_rendering.rs

73f81da

james7132 added this pull request to the merge queue Mar 10, 2024

Merged via the queue into bevyengine:main with commit aea9b4a Mar 10, 2024
25 checks passed

BD103 mentioned this pull request Apr 18, 2024

Add ExitCode to AppExit #13017

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Simplified backtraces #12305

Simplified backtraces #12305

SpecificProtagonist commented Mar 4, 2024 •

edited

Loading

james7132 left a comment •

edited

Loading

SpecificProtagonist commented Mar 4, 2024

ghost commented Mar 4, 2024

SpecificProtagonist commented Mar 5, 2024

cart left a comment

BD103 commented Mar 7, 2024

SpecificProtagonist commented Mar 7, 2024

james7132 left a comment

BD103 left a comment

JMS55 commented Mar 7, 2024

BD103 commented Mar 7, 2024

SpecificProtagonist commented Mar 7, 2024

JMS55 commented Mar 8, 2024

james7132 commented Mar 9, 2024

SpecificProtagonist commented Mar 9, 2024 •

edited

Loading

BD103 commented Mar 10, 2024

Simplified backtraces #12305

Simplified backtraces #12305

Conversation

SpecificProtagonist commented Mar 4, 2024 • edited Loading

Objective

Solution

Alternative solutions

Changelog

james7132 left a comment • edited Loading

Choose a reason for hiding this comment

SpecificProtagonist commented Mar 4, 2024

ghost commented Mar 4, 2024

SpecificProtagonist commented Mar 5, 2024

cart left a comment

Choose a reason for hiding this comment

BD103 commented Mar 7, 2024

SpecificProtagonist commented Mar 7, 2024

james7132 left a comment

Choose a reason for hiding this comment

BD103 left a comment

Choose a reason for hiding this comment

JMS55 commented Mar 7, 2024

BD103 commented Mar 7, 2024

SpecificProtagonist commented Mar 7, 2024

JMS55 commented Mar 8, 2024

james7132 commented Mar 9, 2024

SpecificProtagonist commented Mar 9, 2024 • edited Loading

BD103 commented Mar 10, 2024

SpecificProtagonist commented Mar 4, 2024 •

edited

Loading

james7132 left a comment •

edited

Loading

SpecificProtagonist commented Mar 9, 2024 •

edited

Loading