Undeterministic startup vs. main schedule execution during unit tests

[rohel01]

Hello,

I am currently unit testing an application developed with:

• Bevy 0.10.1
• cargo 1.71.0-nightly (d0a4cbcee 2023-04-16)
• cargo-nextest-nextest 0.9.49

I have noticed one of my test is flakky. After some investigation, it seems my startup systems are not always run before the start of the main schedule.
My code is rather simple:

    #[test]
    fn test_nominal_tc_execution() {
        let mut app = App::new();

        app.add_plugins(MinimalPlugins)
            .add_startup_system(initialize_cmd_register)
            // Standard system
            .add_system(new_cycle.in_base_set(CoreSet::First))
            .add_system(execute_command);

         /* Generate test data */

        /* Run one cycle */
        app.update();

       /* Check test results */

initialize_cmd_register initializes a resource to be used by execute_command. I have added trace in my code, and when the test panics, it seems execute_command tried to run before initialize_cmd_register finished.

Are there any specific steps I need to take to guarantee system schedule rodering in a unit testing context?

[alice-i-cecile]

Startup systems should always be executed first, and commands should be applied after startup systems. Can you open an issue with a failing unit test written on main?

Does this always happen, or is it nondeterministic?

[rohel01]

This is undeterministic.

For more context,

• initialize_cmd_register is an exclusive system that performs initialization of a list of systems to be run in an isolated schedule (How to implement a more complex Command processing scheme #7363)
• execute_command is in fact a generic system, added via .add_system(execute_command::<Bound>);

If I stop registering initialize_cmd_register as a startup system and run it directly as part of the test setup, the test stops failing

#[test]
    fn test_nominal_tc_execution() {
        let mut app = App::new();

        app.add_plugins(MinimalPlugins)
            // Commented !
            //.add_startup_system(initialize_cmd_register)
            // Standard system
            .add_system(new_cycle.in_base_set(CoreSet::First))
            .add_system(execute_command);

          // Run "sysuem" manually
          initialize_cmd_register(&mut app.world)

         /* Generate test data */

        /* Run one cycle */
        app.update();

I will try to produce an minimal test case this evening.

[alice-i-cecile]

Bizarre: that's very surprising to me. Thanks for putting the work into create a minimal reproduction; let's see if we can fix that.

[rohel01]

Also, both initialize_cmd_register and execute_command use world.resource_scope

[rohel01]

This is the reduced example I was able to produce, but I cannot reproduce the above behavior with it yet.
I will have another round of tweaking, probably on Thursday evening

mod fwk {
    use std::collections::HashMap;

    use bevy::prelude::*;

    // A key to uniquely identify a command to be executed by a specific command system
    pub type CmdSystemKey = u8;

    // Input/Output type aliases for command systems
    pub type CmdSystemInput = u8;
    pub type CmdSystemOutput = u8;

    // Convenient type alias for command systems
    pub type BoxedCmdSystem<In = CmdSystemInput, Out = CmdSystemOutput> =
        Box<dyn System<In = In, Out = Out>>;

    // The resource to store the key -> system mapping
    #[derive(Default, Resource)]
    pub struct CmdRegistry(HashMap<CmdSystemKey, BoxedCmdSystem>);

    // Trait to be able to register command systems for a specific command key
    pub trait CommandSystemRegistry {
        fn register_command<
            Params,
            S: IntoSystem<CmdSystemInput, CmdSystemOutput, Params> + 'static,
        >(
            &mut self,
            cmd: CmdSystemKey,
            system: S,
        );
    }

    impl CommandSystemRegistry for World {
        fn register_command<
            Params,
            S: IntoSystem<CmdSystemInput, CmdSystemOutput, Params> + 'static,
        >(
            &mut self,
            cmd_config: CmdSystemKey,
            system: S,
        ) {
            let mut cmds = self.resource_mut::<CmdRegistry>();

            cmds.0
                .insert(cmd_config, Box::new(IntoSystem::into_system(system)));
        }
    }

    pub fn initialize_registry_systems(world: &mut World) {
        world.resource_scope(|world, mut registry: Mut<CmdRegistry>| {
            for system in registry.0.values_mut() {
                system.initialize(world);
            }
        });
    }

    pub struct CmdMessage(pub u8);

    #[derive(Component)]
    pub struct MessageQueue(pub Vec<CmdMessage>);

    pub fn run_systems(world: &mut World) {
        world.resource_scope(|world, mut registry: Mut<CmdRegistry>| {
            let mut query = world.query::<(Entity, &mut MessageQueue)>();

            let mut cmds = Vec::new();
            for (_e, queue) in query.iter_mut(world) {
                queue.0.iter().for_each(|f| cmds.push(f.0));
            }

            for cmd in cmds.into_iter() {
                if let Some(system) = registry.0.get_mut(&cmd) {
                    system.run(cmd, world);
                }
            }
        });
    }
}

mod cmd {
    use bevy::prelude::*;

    use crate::fwk::{CmdRegistry, CommandSystemRegistry};

    #[derive(Component, Default)]
    pub struct DummyComponent(pub Vec<u8>);

    // Add Any command system here, and do not forget to register it with the desired cmd key!

    // A sample command execution system!!
    fn execute_simple_cmd(input: In<u8>, mut query: Query<&mut DummyComponent>) -> u8 {
        for mut dummy in query.iter_mut() {
            dummy.0.push(input.0);
        }

        input.0
    }

    pub fn register_systems(world: &mut World) {
        world.init_resource::<CmdRegistry>();
        world.register_command(
            1, // Dummy command message 1
            execute_simple_cmd,
        );
    }
}

#[cfg(test)]
mod tests {
    use bevy::prelude::*;

    use crate::{
        cmd::{self, DummyComponent},
        fwk::{self, CmdMessage, MessageQueue},
    };

    fn spawn_entities(world: &mut World) -> Entity {
        world
            .spawn((
                MessageQueue(Vec::with_capacity(10)),
                DummyComponent(Vec::new()),
            ))
            .id()
    }

    #[test]
    fn nominal_test() {
        let mut app = App::new();

        app.add_plugins(MinimalPlugins)
            .add_event::<CmdMessage>()
            .add_startup_system(cmd::register_systems)
            .add_startup_system(
                fwk::initialize_registry_systems.in_base_set(StartupSet::PostStartup),
            )
            .add_system(fwk::run_systems);

        let eid = spawn_entities(&mut app.world);

        let mut entity = app.world.entity_mut(eid);
        let mut queue = entity.get_mut::<MessageQueue>().unwrap();

        queue.0.push(CmdMessage(1));
        queue.0.push(CmdMessage(2));
        queue.0.push(CmdMessage(1));

        app.update();

        let entity = app.world.entity_mut(eid);
        let queue = &entity.get::<DummyComponent>().unwrap().0;

        assert_eq!(queue.len(), 2);
        assert_eq!(queue, &vec![1, 1]);
    }
}

fn main() {
    println!("Hello World!");
}

[rohel01]

I found the issue, this is not a Bevy bug.

In my production unit test, I failed to add the proper dependencies between my startup systems so their execution order was nondeterministic. Using the above example to illustrate the issue, sometimes fwk::initialize_registry_systems would run before cmd::register_systems. So, the former would try to initialize all systems in the register, but it does not contain any yet...

This does not happen in production and in the example because I added initialize_cmd_system_register to the StartupSet::PostStartup set. When writing the unit test, I forgot to do it.

Sorry for the noise