Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

The right combination of SubApp, refresh rate, and AppExit event causes a panic half the time #9543

Open
pmikolajek opened this issue Aug 22, 2023 · 3 comments
Labels
A-App Bevy apps and plugins C-Bug An unexpected or incorrect behavior S-Needs-Investigation This issue requires detective work to figure out what's going wrong

Comments

@pmikolajek
Copy link

What you did

Using a specific combination of SubApp, ScheduleRunnerPlugin, and issuing an AppExit event, I can get bevy to sometimes panic. It doesn't happen 100% of the time—sometimes it exits correctly. A few executions of cargo run is usually enough to reproduce the bug.

Bevy version

0.11.2

Minimal example:

use bevy::app::AppExit;
use bevy::app::{AppLabel, SubApp};
use bevy::app::{RunMode, ScheduleRunnerPlugin};
use bevy::prelude::*;
use bevy::window::ExitCondition;
use std::time::Duration;

const TICK_RATE: f64 = 2.0;

#[derive(AppLabel)]
struct SubAppLabel;

#[derive(Resource)]
struct TimeToLive {
    timer: Timer,
}

impl Default for TimeToLive {
    fn default() -> Self {
        Self {
            timer: Timer::new(Duration::from_secs(1), TimerMode::Once),
        }
    }
}

fn main() {
    let mut app = App::new();
    app.add_plugins(DefaultPlugins.set(WindowPlugin {
        primary_window: None,
        exit_condition: ExitCondition::DontExit,
        ..default()
    }));

    let mut sub_app = App::new();
    sub_app.add_plugins(MinimalPlugins.set(ScheduleRunnerPlugin {
        run_mode: RunMode::Loop {
            wait: Some(Duration::from_secs_f64(1.0 / TICK_RATE)),
        },
    }));
    app.insert_sub_app(SubAppLabel, SubApp::new(sub_app, |_, _| {}));

    app.insert_resource(TimeToLive::default());
    app.add_systems(Update, exit_after_1_second);

    app.run();
}

fn exit_after_1_second(
    time: Res<Time>,
    mut time_to_live: ResMut<TimeToLive>,
    mut app_exit_events: EventWriter<AppExit>,
) {
    time_to_live.timer.tick(time.delta());

    if time_to_live.timer.finished() {
        info!("Exiting.");
        app_exit_events.send(AppExit);
    }
}

The only dependency is bevy = "0.11.2".

What went wrong

Bevy sometimes runs correctly, and sometimes panics. The issue can usually be reproduced by running cargo run under 5 times.

When the app exits correctly, the output is:

2023-08-22T22:42:07.391576Z  INFO wgpu_core::device: Created compute pipeline Valid((1, 1, Vulkan)) with ComputePipelineDescriptor { label: Some("ssao_preprocess_depth_pipeline"), layout: Some((1, 1, Vulkan)), stage: ProgrammableStageDescriptor { module: (1, 1, Vulkan), entry_point: "preprocess_depth" } }    
2023-08-22T22:42:08.357965Z  INFO master: Exiting.

When the app panics, the output is:

2023-08-22T22:42:47.185491Z  INFO wgpu_core::device: Created compute pipeline Valid((1, 1, Vulkan)) with ComputePipelineDescriptor { label: Some("ssao_preprocess_depth_pipeline"), layout: Some((1, 1, Vulkan)), stage: ProgrammableStageDescriptor { module: (1, 1, Vulkan), entry_point: "preprocess_depth" } }    
2023-08-22T22:42:48.154022Z  INFO master: Exiting.
2023-08-22T22:42:48.154741Z DEBUG bevy_render::pipelined_rendering: exiting pipelined rendering thread
2023-08-22T22:42:48.155306Z DEBUG wgpu_core::device: buffer (0, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155323Z DEBUG wgpu_core::device: texture (12, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155333Z DEBUG wgpu_core::device: texture view (12, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155350Z DEBUG wgpu_core::device: sampler (7, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155360Z DEBUG wgpu_core::device: texture (15, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155369Z DEBUG wgpu_core::device: texture view (15, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155378Z DEBUG wgpu_core::device: texture (14, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155392Z DEBUG wgpu_core::device: texture view (14, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155400Z DEBUG wgpu_core::device: sampler (9, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155408Z DEBUG wgpu_core::device: texture (13, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155416Z DEBUG wgpu_core::device: texture view (13, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155425Z DEBUG wgpu_core::device: sampler (8, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155453Z DEBUG wgpu_core::device: pipeline layout (1, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155464Z DEBUG wgpu_core::device: pipeline layout (0, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155489Z DEBUG wgpu_core::device: shader module (1, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155521Z DEBUG wgpu_core::device: shader module (0, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155913Z DEBUG wgpu_core::device: compute pipeline (1, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155927Z DEBUG wgpu_core::device: compute pipeline (0, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155938Z DEBUG wgpu_core::device: buffer (2, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155948Z DEBUG wgpu_core::device: bind group (0, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155964Z DEBUG wgpu_core::device: buffer (1, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155977Z DEBUG wgpu_core::device: buffer (4, 1, Vulkan) is dropped    
2023-08-22T22:42:48.155987Z DEBUG wgpu_core::device: bind group (1, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156003Z DEBUG wgpu_core::device::life: Bind group Valid((1, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156049Z DEBUG wgpu_core::device::life: Bind group Valid((0, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156064Z DEBUG wgpu_core::device::life: Texture view Valid((12, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156071Z DEBUG wgpu_core::device::life: Texture view Valid((15, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156078Z DEBUG wgpu_core::device::life: Texture view Valid((14, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156084Z DEBUG wgpu_core::device::life: Texture view Valid((13, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156091Z DEBUG wgpu_core::device::life: Texture Valid((12, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156099Z DEBUG wgpu_core::device::life: Texture Valid((15, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156105Z DEBUG wgpu_core::device::life: Texture Valid((14, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156112Z DEBUG wgpu_core::device::life: Texture Valid((13, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156120Z DEBUG wgpu_core::device::life: Sampler Valid((7, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156127Z DEBUG wgpu_core::device::life: Sampler Valid((9, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156133Z DEBUG wgpu_core::device::life: Sampler Valid((8, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156139Z DEBUG wgpu_core::device::life: Buffer Valid((0, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156146Z DEBUG wgpu_core::device::life: Buffer Valid((2, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156153Z DEBUG wgpu_core::device::life: Buffer Valid((1, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156165Z DEBUG wgpu_core::device::life: Buffer Valid((4, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156173Z DEBUG wgpu_core::device::life: Compute pipeline Valid((1, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156181Z DEBUG wgpu_core::device::life: Compute pipeline Valid((0, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156188Z DEBUG wgpu_core::device::life: Pipeline layout Valid((1, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156196Z DEBUG wgpu_core::device::life: Pipeline layout Valid((0, 1, Vulkan)) will be destroyed    
2023-08-22T22:42:48.156235Z DEBUG wgpu_core::device: device (0, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156246Z DEBUG wgpu_core::device: bind group layout (0, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156254Z DEBUG wgpu_core::device: texture (0, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156262Z DEBUG wgpu_core::device: texture view (0, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156269Z DEBUG wgpu_core::device: texture (1, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156276Z DEBUG wgpu_core::device: texture view (1, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156283Z DEBUG wgpu_core::device: texture (2, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156290Z DEBUG wgpu_core::device: texture view (2, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156297Z DEBUG wgpu_core::device: texture (3, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156304Z DEBUG wgpu_core::device: texture view (3, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156311Z DEBUG wgpu_core::device: texture (4, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156318Z DEBUG wgpu_core::device: texture view (4, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156325Z DEBUG wgpu_core::device: texture (5, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156332Z DEBUG wgpu_core::device: texture view (5, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156339Z DEBUG wgpu_core::device: texture (6, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156348Z DEBUG wgpu_core::device: texture view (6, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156355Z DEBUG wgpu_core::device: texture (7, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156365Z DEBUG wgpu_core::device: texture view (7, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156376Z DEBUG wgpu_core::device: bind group layout (1, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156383Z DEBUG wgpu_core::device: bind group layout (2, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156393Z DEBUG wgpu_core::device: sampler (1, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156410Z DEBUG wgpu_core::device: bind group layout (3, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156417Z DEBUG wgpu_core::device: bind group layout (4, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156428Z DEBUG wgpu_core::device: sampler (2, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156438Z DEBUG wgpu_core::device: bind group layout (4, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156448Z DEBUG wgpu_core::device: bind group layout (6, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156457Z DEBUG wgpu_core::device: bind group layout (7, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156466Z DEBUG wgpu_core::device: sampler (3, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156475Z DEBUG wgpu_core::device: bind group layout (8, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156485Z DEBUG wgpu_core::device: bind group layout (6, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156494Z DEBUG wgpu_core::device: texture (8, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156503Z DEBUG wgpu_core::device: texture view (8, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156513Z DEBUG wgpu_core::device: bind group layout (12, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156524Z DEBUG wgpu_core::device: bind group layout (8, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156534Z DEBUG wgpu_core::device: bind group layout (6, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156543Z DEBUG wgpu_core::device: sampler (4, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156552Z DEBUG wgpu_core::device: sampler (5, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156561Z DEBUG wgpu_core::device: buffer (3, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156573Z DEBUG wgpu_core::device: bind group layout (22, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156582Z DEBUG wgpu_core::device: bind group layout (10, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156591Z DEBUG wgpu_core::device: bind group layout (21, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156601Z DEBUG wgpu_core::device: bind group layout (21, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156611Z DEBUG wgpu_core::device: bind group layout (25, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156620Z DEBUG wgpu_core::device: bind group layout (26, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156629Z DEBUG wgpu_core::device: bind group layout (27, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156638Z DEBUG wgpu_core::device: bind group layout (28, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156648Z DEBUG wgpu_core::device: texture view (11, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156655Z DEBUG wgpu_core::device: sampler (6, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156664Z DEBUG wgpu_core::device: bind group layout (10, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156672Z DEBUG wgpu_core::device: bind group layout (11, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156680Z DEBUG wgpu_core::device: texture (9, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156687Z DEBUG wgpu_core::device: texture view (9, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156694Z DEBUG wgpu_core::device: bind group layout (15, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156701Z DEBUG wgpu_core::device: bind group layout (16, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156708Z DEBUG wgpu_core::device: texture (10, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156715Z DEBUG wgpu_core::device: texture view (10, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156722Z DEBUG wgpu_core::device: sampler (0, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156729Z DEBUG wgpu_core::device: bind group layout (17, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156736Z DEBUG wgpu_core::device: bind group layout (18, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156743Z DEBUG wgpu_core::device: bind group layout (19, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156750Z DEBUG wgpu_core::device: bind group layout (20, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156757Z DEBUG wgpu_core::device: bind group layout (29, 1, Vulkan) is dropped    
2023-08-22T22:42:48.156764Z  INFO wgpu_core::hub: Dropping Global    
2023-08-22T22:42:48.157864Z  INFO wgpu_core::device: Destroying 4 command encoders    
2023-08-22T22:42:48.166969Z ERROR wgpu_hal::gles::egl: EGL 'eglDestroyContext' code 0x3008:     
2023-08-22T22:42:48.166984Z  WARN wgpu_hal::gles::egl: Error in destroy_context: BadDisplay    
2023-08-22T22:42:48.166993Z ERROR wgpu_hal::gles::egl: EGL 'eglTerminate' code 0x3008:     
2023-08-22T22:42:48.167002Z  WARN wgpu_hal::gles::egl: Error in terminate: BadDisplay    
thread '<unnamed>' panicked at 'Attempted to access or drop non-send resource bevy_render::view::window::NonSendMarker from thread Some(ThreadId(1)) on a thread ThreadId(17). This is not allowed. Aborting.', /home/santa/.cargo/registry/src/index.crates.io-6f17d22bba15001f/bevy_ecs-0.11.2/src/storage/resource.rs:56:13

The expected behavior is never panicking.

My Rust info:

$ cargo --version
cargo 1.71.1 (7f1d04c00 2023-07-29)

My OS info:

$ lsb_release -a
Distributor ID:	Linuxmint
Description:	Linux Mint 20.1
Release:	20.1
Codename:	ulyssa

My adapter info:

2023-08-22T22:53:38.500205Z  INFO wgpu_core::instance: Adapter Vulkan AdapterInfo { name: "NVIDIA GeForce GTX 1060", vendor: 4318, device: 7200, device_type: DiscreteGpu, driver: "NVIDIA", driver_info: "470.199.02", backend: Vulkan }    

Extra notes

  • The issue appears to be related to sub worlds and/or pipelined rendering.

  • On bevy 0.11, the same issue occurs, but the error message is different:

# note: this is on bevy 0.11
thread 'Compute Task Pool (2)' panicked at 'called `Result::unwrap()` on an `Err` value: RecvError', /home/santa/.cargo/registry/src/index.crates.io-6f17d22bba15001f/bevy_render-0.11.0/src/pipelined_rendering.rs:110:77
@pmikolajek pmikolajek added C-Bug An unexpected or incorrect behavior S-Needs-Triage This issue needs to be labelled labels Aug 22, 2023
@ickshonpe
Copy link
Contributor

I got the error message

thread '<unnamed>' panicked at 'The TimeSender channel should always be empty during render. You might need to add the bevy::core::time_system to your app.: "Disconnected(..)"', F:\projects\bevy-fork\bevy\crates\bevy_render\src\renderer\mod.rs:91:44

on main

@alice-i-cecile alice-i-cecile added A-App Bevy apps and plugins S-Needs-Investigation This issue requires detective work to figure out what's going wrong and removed S-Needs-Triage This issue needs to be labelled labels Aug 25, 2023
@hymm
Copy link
Contributor

hymm commented Aug 29, 2023

thread '<unnamed>' panicked at 'The TimeSender channel should always be empty during render. You might need to add the bevy::core::time_system to your app.: "Disconnected(..)"', F:\projects\bevy-fork\bevy\crates\bevy_render\src\renderer\mod.rs:91:44

The above should be fixed by ignoring disconnected errors from the time channel in the render app.
https://docs.rs/crossbeam/latest/crossbeam/channel/enum.TrySendError.html

The original issue is a bit harder to fix. It's due to the render world being dropped on the render thread during shutdown when it can only be dropped on the main thread. To fix this the main app should wait for the render thread to send back the render world before ending, but I think that might be a pain to implement as bevy's story around cleaning up resources on shutdown isn't the greatest. It might be better to wait for #9122 which would allow dropping the render world on another thread.

@hymm
Copy link
Contributor

hymm commented Aug 30, 2023

One reason not to wait for removing non-send resources is that dropping on the wrong thread is potentially UB. I think we avoid any UB currently because the non-send data in the render world is just a marker without any special needs for where it is dropped.

An option for fixing this might be to wrap the channels in the main world with a drop impl that will wait for the render world to come back if it's in another thread. We'd need to make sure that it handles panics in the render world correctly.

github-merge-queue bot pushed a commit that referenced this issue Oct 1, 2023
# Objective

- sometimes when bevy shuts down on certain machines the render thread
tries to send the time after the main world has been dropped.
- fixes an error mentioned in a reply in
#9543

---

## Changelog

- ignore disconnected errors from the time channel.
regnarock pushed a commit to regnarock/bevy that referenced this issue Oct 13, 2023
# Objective

- sometimes when bevy shuts down on certain machines the render thread
tries to send the time after the main world has been dropped.
- fixes an error mentioned in a reply in
bevyengine#9543

---

## Changelog

- ignore disconnected errors from the time channel.
rdrpenguin04 pushed a commit to rdrpenguin04/bevy that referenced this issue Jan 9, 2024
# Objective

- sometimes when bevy shuts down on certain machines the render thread
tries to send the time after the main world has been dropped.
- fixes an error mentioned in a reply in
bevyengine#9543

---

## Changelog

- ignore disconnected errors from the time channel.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-App Bevy apps and plugins C-Bug An unexpected or incorrect behavior S-Needs-Investigation This issue requires detective work to figure out what's going wrong
Projects
None yet
Development

No branches or pull requests

4 participants