State changes appear to have system order ambiguities

[jonathandw743]

System Info

bevy 0.14.0-rc.2
Ubuntu 22.04

Program

use bevy::{
    input::{keyboard::KeyboardInput, mouse::MouseButtonInput, ButtonState},
    prelude::*,
};

fn main() {
    App::new()
        .add_plugins(DefaultPlugins)
        .insert_state(S1::A)
        .add_sub_state::<S2>()
        .add_systems(Update, transition_to_s1_b_on_click.run_if(in_state(S1::A)))
        .add_systems(Update, transition_to_s2_d_on_click.run_if(in_state(S2::C)))
        .add_systems(Update, info_states)
        .add_systems(Update, reset)
        .run();
}

fn transition_to_s1_b_on_click(
    mut mouse_events: EventReader<MouseButtonInput>,
    mut ns_s1: ResMut<NextState<S1>>,
) {
    for e in mouse_events.read() {
        match e {
            MouseButtonInput {
                button: MouseButton::Left,
                state: ButtonState::Pressed,
                ..
            } => ns_s1.set(S1::B),
            _ => {}
        }
    }
}

fn transition_to_s2_d_on_click(
    mut mouse_events: EventReader<MouseButtonInput>,
    mut ns_s2: ResMut<NextState<S2>>,
) {
    for e in mouse_events.read() {
        match e {
            MouseButtonInput {
                button: MouseButton::Left,
                state: ButtonState::Pressed,
                ..
            } => ns_s2.set(S2::D),
            _ => {}
        }
    }
}

fn info_states(s1: Res<State<S1>>, s2: Option<Res<State<S2>>>) {
    info!("{:?}, {:?}", s1, s2);
}

fn reset(keyboard_input: Res<ButtonInput<KeyCode>>, mut ns_s1: ResMut<NextState<S1>>) {
    if keyboard_input.just_pressed(KeyCode::Escape) {
        ns_s1.set(S1::A);
    }
}

#[derive(States, Debug, Clone, PartialEq, Eq, Hash)]
enum S1 {
    A,
    B,
}

#[derive(SubStates, Debug, Clone, PartialEq, Eq, Hash, Default)]
#[source(S1 = S1::B)]
enum S2 {
    #[default]
    C,
    D,
}

Program summary:

state S1 is set to A
state S2 is a sub state of S1 and has a default value of C
when the mouse is pressed, S1 transitions to B

then sometimes, S2 also transitions to D

Output

I would expect the output to be:

2024-06-20T15:02:47.198639Z  INFO gam: Res(State(A)), None
2024-06-20T15:02:47.213971Z  INFO gam: Res(State(A)), None
2024-06-20T15:02:47.227818Z  INFO gam: Res(State(A)), None
<mouse pressed>
2024-06-20T15:02:47.254104Z  INFO gam: Res(State(B)), Some(Res(State(C)))
2024-06-20T15:02:47.267907Z  INFO gam: Res(State(B)), Some(Res(State(C)))
2024-06-20T15:02:47.280845Z  INFO gam: Res(State(B)), Some(Res(State(C)))

but occasionally (apparently at random) the output is:

2024-06-20T15:10:34.521087Z  INFO gam: Res(State(A)), None
2024-06-20T15:10:34.534237Z  INFO gam: Res(State(A)), None
2024-06-20T15:10:34.547726Z  INFO gam: Res(State(A)), None
<mouse pressed>
2024-06-20T15:10:34.560954Z  INFO gam: Res(State(B)), Some(Res(State(C)))
2024-06-20T15:10:34.587293Z  INFO gam: Res(State(B)), Some(Res(State(D)))
2024-06-20T15:10:34.601005Z  INFO gam: Res(State(B)), Some(Res(State(D)))
2024-06-20T15:10:34.613692Z  INFO gam: Res(State(B)), Some(Res(State(D)))

("" is not logged)

(this is not a double press or anything like that, it happens consistently)

My guess about what is happening in the expected output and why

The mouse click event happens and is in the first EventReader.
The state then changes to S1::B
The mouse click event leaves the EventReader
The transition_to_s2_d_on_click system runs
The mouse click event is no longer in the EventReader
The state does not change

My guess about what is happening in the unexpected output and why

The mouse click event happens and is in the first EventReader.
The state then changes to S1::B
The transition_to_s2_d_on_click system runs
The mouse click event is still in the EventReader
The state changes to S2::D

[alice-i-cecile]

Are you able to turn this into a test case that doesn't rely on user input at all? Ideally using App::update calls :)

[jonathandw743]

Are you able to turn this into a test case that doesn't rely on user input at all? Ideally using App::update calls :)

Will do when I have the chance 👍

[jonathandw743]

Are you able to turn this into a test case that doesn't rely on user input at all? Ideally using App::update calls :)

could you point me to a resource on how to do this please?

[alice-i-cecile]

Here's an example of writing integration tests in Bevy in this style from leafwing-input-manager: https://github.com/Leafwing-Studios/leafwing-input-manager/blob/main/tests/integration.rs :)

[jonathandw743]

Are you able to turn this into a test case that doesn't rely on user input at all? Ideally using App::update calls :)

fn main() {
    let mut app: bevy::app::App = App::new();

    app.add_plugins(DefaultPlugins);
    app.insert_state(S1::A);
    app.add_sub_state::<S2>();
    app.add_systems(Update, transition_to_s1_b_on_click.run_if(in_state(S1::A)));
    app.add_systems(Update, transition_to_s2_d_on_click.run_if(in_state(S2::C)));
    app.add_systems(Update, info_states);
    app.add_systems(Update, reset);

    app.finish();
    app.cleanup();

    app.update();
    app.update();
    app.update();
    app.update();
    app.update();
    app.world_mut().send_event(MouseButtonInput {
        button: MouseButton::Left,
        state: ButtonState::Pressed,
        window: Entity::from_bits(934587943958),
    });
    app.update();
    app.update();
    app.update();
    app.update();
    app.update();
    app.world_mut().send_event(MouseButtonInput {
        button: MouseButton::Left,
        state: ButtonState::Released,
        window: Entity::from_bits(934587943958),
    });
    app.update();
    app.update();
    app.update();
    app.update();
    app.update();

    app.should_exit().unwrap_or(AppExit::Success);
}

fn transition_to_s1_b_on_click(
    mut mouse_events: EventReader<MouseButtonInput>,
    mut ns_s1: ResMut<NextState<S1>>,
) {
    for e in mouse_events.read() {
        info!("\n{:#?}", e);
        match e {
            MouseButtonInput {
                button: MouseButton::Left,
                state: ButtonState::Pressed,
                ..
            } => {
                ns_s1.set(S1::B);
            }
            _ => {}
        }
    }
}

fn transition_to_s2_d_on_click(
    mut mouse_events: EventReader<MouseButtonInput>,
    mut ns_s2: ResMut<NextState<S2>>,
) {
    for e in mouse_events.read() {
        info!("\n{:#?}", e);
        match e {
            MouseButtonInput {
                button: MouseButton::Left,
                state: ButtonState::Pressed,
                ..
            } => {
                ns_s2.set(S2::D);
            }
            _ => {}
        }
    }
}

fn info_states(s1: Res<State<S1>>, s2: Option<Res<State<S2>>>) {
    info!("{:?}, {:?}", s1, s2);
}

fn reset(keyboard_input: Res<ButtonInput<KeyCode>>, mut ns_s1: ResMut<NextState<S1>>) {
    if keyboard_input.just_pressed(KeyCode::Escape) {
        ns_s1.set(S1::A);
    }
}

#[derive(States, Debug, Clone, PartialEq, Eq, Hash)]
enum S1 {
    A,
    B,
}

#[derive(SubStates, Debug, Clone, PartialEq, Eq, Hash, Default)]
#[source(S1 = S1::B)]
enum S2 {
    #[default]
    C,
    D,
}

output

sometimes:

2024-06-22T16:34:07.858210Z  INFO gam: Res(State(A)), None
2024-06-22T16:34:07.863300Z  INFO gam: Res(State(A)), None
2024-06-22T16:34:07.872809Z  INFO gam: Res(State(A)), None
2024-06-22T16:34:07.873689Z  INFO gam: Res(State(A)), None
2024-06-22T16:34:07.874237Z  INFO gam: Res(State(A)), None
2024-06-22T16:34:07.875343Z  INFO gam: Res(State(A)), None
2024-06-22T16:34:07.875368Z  INFO gam: 
MouseButtonInput {
    button: Left,
    state: Pressed,
    window: Entity {
        index: 2580040726,
        generation: 217,
    },
}
2024-06-22T16:34:07.876410Z  INFO gam: 
MouseButtonInput {
    button: Left,
    state: Pressed,
    window: Entity {
        index: 2580040726,
        generation: 217,
    },
}
2024-06-22T16:34:07.876426Z  INFO gam: Res(State(B)), Some(Res(State(C)))
2024-06-22T16:34:07.876964Z  INFO gam: Res(State(B)), Some(Res(State(D)))
2024-06-22T16:34:07.877392Z  INFO gam: Res(State(B)), Some(Res(State(D)))
2024-06-22T16:34:07.877996Z  INFO gam: Res(State(B)), Some(Res(State(D)))
2024-06-22T16:34:07.878666Z  INFO gam: Res(State(B)), Some(Res(State(D)))
2024-06-22T16:34:07.879262Z  INFO gam: Res(State(B)), Some(Res(State(D)))
2024-06-22T16:34:07.880229Z  INFO gam: Res(State(B)), Some(Res(State(D)))
2024-06-22T16:34:07.880631Z  INFO gam: Res(State(B)), Some(Res(State(D)))
2024-06-22T16:34:07.881006Z  INFO gam: Res(State(B)), Some(Res(State(D)))

sometimes:

2024-06-22T16:34:11.109256Z  INFO gam: Res(State(A)), None
2024-06-22T16:34:11.113957Z  INFO gam: Res(State(A)), None
2024-06-22T16:34:11.123502Z  INFO gam: Res(State(A)), None
2024-06-22T16:34:11.124138Z  INFO gam: Res(State(A)), None
2024-06-22T16:34:11.124997Z  INFO gam: Res(State(A)), None
2024-06-22T16:34:11.125470Z  INFO gam: Res(State(A)), None
2024-06-22T16:34:11.125472Z  INFO gam: 
MouseButtonInput {
    button: Left,
    state: Pressed,
    window: Entity {
        index: 2580040726,
        generation: 217,
    },
}
2024-06-22T16:34:11.125880Z  INFO gam: Res(State(B)), Some(Res(State(C)))
2024-06-22T16:34:11.125907Z  INFO gam: 
MouseButtonInput {
    button: Left,
    state: Pressed,
    window: Entity {
        index: 2580040726,
        generation: 217,
    },
}
2024-06-22T16:34:11.126460Z  INFO gam: Res(State(B)), Some(Res(State(D)))
2024-06-22T16:34:11.126831Z  INFO gam: Res(State(B)), Some(Res(State(D)))
2024-06-22T16:34:11.127320Z  INFO gam: Res(State(B)), Some(Res(State(D)))
2024-06-22T16:34:11.127699Z  INFO gam: Res(State(B)), Some(Res(State(D)))
2024-06-22T16:34:11.128096Z  INFO gam: Res(State(B)), Some(Res(State(D)))
2024-06-22T16:34:11.128543Z  INFO gam: Res(State(B)), Some(Res(State(D)))
2024-06-22T16:34:11.129202Z  INFO gam: Res(State(B)), Some(Res(State(D)))
2024-06-22T16:34:11.130297Z  INFO gam: Res(State(B)), Some(Res(State(D)))

expected output

2024-06-22T16:34:11.109256Z  INFO gam: Res(State(A)), None
2024-06-22T16:34:11.113957Z  INFO gam: Res(State(A)), None
2024-06-22T16:34:11.123502Z  INFO gam: Res(State(A)), None
2024-06-22T16:34:11.124138Z  INFO gam: Res(State(A)), None
2024-06-22T16:34:11.124997Z  INFO gam: Res(State(A)), None
2024-06-22T16:34:11.125470Z  INFO gam: Res(State(A)), None
2024-06-22T16:34:11.125472Z  INFO gam: 
MouseButtonInput {
    button: Left,
    state: Pressed,
    window: Entity {
        index: 2580040726,
        generation: 217,
    },
}
2024-06-22T16:34:11.125880Z  INFO gam: Res(State(B)), Some(Res(State(C)))
2024-06-22T16:34:11.126460Z  INFO gam: Res(State(B)), Some(Res(State(C)))
2024-06-22T16:34:11.126831Z  INFO gam: Res(State(B)), Some(Res(State(C)))
2024-06-22T16:34:11.127320Z  INFO gam: Res(State(B)), Some(Res(State(C)))
2024-06-22T16:34:11.127699Z  INFO gam: Res(State(B)), Some(Res(State(C)))
2024-06-22T16:34:11.128096Z  INFO gam: Res(State(B)), Some(Res(State(C)))
2024-06-22T16:34:11.128543Z  INFO gam: Res(State(B)), Some(Res(State(C)))
2024-06-22T16:34:11.129202Z  INFO gam: Res(State(B)), Some(Res(State(C)))
2024-06-22T16:34:11.130297Z  INFO gam: Res(State(B)), Some(Res(State(C)))

[jonathandw743]

I cannot recreate this output using manual button presses:

2024-06-20T15:02:47.198639Z  INFO gam: Res(State(A)), None
2024-06-20T15:02:47.213971Z  INFO gam: Res(State(A)), None
2024-06-20T15:02:47.227818Z  INFO gam: Res(State(A)), None
<mouse pressed>
2024-06-20T15:02:47.254104Z  INFO gam: Res(State(B)), Some(Res(State(C)))
2024-06-20T15:02:47.267907Z  INFO gam: Res(State(B)), Some(Res(State(C)))
2024-06-20T15:02:47.280845Z  INFO gam: Res(State(B)), Some(Res(State(C)))

[mhlakhani]

I've also spent a few hours debugging an issue in my game and got to the same issue. I'll try to work on a clean repro (I don't have one yet) but I used bevy-inspector-egui to confirm similar behavior. In particular I have a sequence of calls like this:

next_game_state.set(GameState::Initializing);
next_init_state.set(InitializationState::DespawningBeforeNextLevel);

with my states defined as (trimmed)

#[derive(Debug, Clone, Copy, Default, Eq, PartialEq, Hash, States, Reflect)]
pub enum GameState {
    #[default]
    Initializing,
    InGame,
}

#[derive(Debug, Clone, Copy, Default, Eq, PartialEq, Hash, SubStates, Reflect)]
#[source(GameState = GameState::Initializing)]
pub enum InitializationState {
    #[default]
    LoadingAssets,
    DespawningBeforeNextLevel,
}

What I'm observing is that the majority of the time it works fine, but some % of the time, next_game_state.set() gets invoked by itself and sets InitializationState to the default value (i.e. LoadingAssets) and that causes my app to get stuck. Ideally I would want an atomic way of expressing this transition.

I suspected this github issue because the issue I observe is not deterministic. On some app launches it runs fine, and when it does run fine it works fine for all the times I hit the codepath (even if that's tens of times). But when it's not fine, it shows up immediately the first time.

I have not yet been able to produce a self-contained repro (will try some more), since it seems like my case relies on some timing issue/interaction with a number of other systems in the game.

[mhlakhani]

Thinking about it a bit more I think what I really want is to have the way to express an atomic transition -> i.e. go from parent state A to parent state B and sub-state value C. If we can couple that with ideally the removal of the Default bound on SubStates then I think things would be cleaner, personally. Should that be tracked as a separate issue? I'm happy to file one with more details.