Error logs are silently lost if LogPlugin is added late.

[shanecelis]

Problem

Perfectly good error logs are silently lost if DefaultPlugins or LogPlugin has not been added early enough.

I found this behavior on the main branch but I expect it goes pretty far back.

Example

I was mucking around with mesh2d_manual for reasons and I made this mistake: I put ExtractResourcePlugin ahead of DefaultPlugins.

fn main() {
    App::new()
        .init_resource::<DistBuffer>()
        .add_plugins(ExtractResourcePlugin::<DistBuffer>::default())
        // Error message that "Render app did not exist..." is never shown.
        .add_plugins((DefaultPlugins, ColoredMesh2dPlugin))
        .add_systems(Startup, star)
        .run();
}

I was befuddled by this because I could see the error message in the code and assumed I must not be hitting that execution path. I added some eprintln! and figured out it was the LogPlugin that needed to come first before the error was reported. To provoke the error again and log it, I added LogPlugin manually.

fn main() {
    App::new()
        .add_plugins(LogPlugin::default())
        .add_plugins(ExtractResourcePlugin::<DistBuffer>::default())
        .add_plugins((DefaultPlugins.build().disable::<LogPlugin>(), ColoredMesh2dPlugin))
        .init_resource::<DistBuffer>()
        .add_systems(Startup, star)
        .run();
}

This then showed me the right error message:

2024-05-17T05:12:34.125757Z ERROR bevy_render::extract_resource: Render app did not exist when trying to add `extract_resource` for <mesh2d_manual::DistBuffer>.

This is a great error message and would have set me straight if I had seen it.

Suggested Solutions

Fix in the small

One could have ExtractResourcePlugin come before DefaultPlugins if it did its work in finish() rather than build(). I've seen a few plugins opt for this when dealing with the RenderApp. Maybe that should be done but I think that's avoiding a larger issue.

Accumulate Log Counts

Perhaps errors emitted before LogPlugin ought to be accumulated somehow so they aren't silently lost until LogPlugin is added. Keeping an accounting of the missing log types would be helpful. Then when LogPlugin is added, it could emit this warning if there are missing log types that we care about:

2024-05-17T05:12:34.125757Z WARNING bevy_log::LogPlugin: Missed logs: 2 warn, 1 error; consider adding LogPlugin or DefaultPlugins to App earlier.

Maybe a LogCountPlugin could be devised that only collects those counts.

And if the App never adds LogPlugin, maybe those counts could be made available somewhere.

Conclusion

I'm happy to submit a PR for either of these solutions if desired.

[alice-i-cecile]

Ultimately caused by #1255. We need real plugin ordering in some form to avoid this sort of footgun.

[benfrankel]

The following gives an unwrap panic with no warning:

App::new().init_state::<Foo>();

However, init_state tries to warn that StatesPlugin hasn't been added yet, but the warning gets dropped because LogPlugin hasn't been added yet either. This defeats the point of the warning for anyone using DefaultPlugins, which bundles StatesPlugin and LogPlugin together.

None of the approaches suggested in this issue would solve this case. It may be worth considering setting up logging in App::new, with an alternative like App::minimal that does not set up logging. I'm not sure how logging would be configured then, though.

[thebluefish]

I like the idea of adding it in App::new/default, and App::empty already exists for those who want a bit more control. I think doing some kind of pub App::init_logging that's called by App::default would allow the same level of customization we have with LogPlugin, by allowing the user to pass in new layers.

[benfrankel]

Actually you're right. App::empty already exists, and App::new already sets up foundational plugins and resources:

bevy/crates/bevy_app/src/app.rs

Lines 92 to 114 in a0f5ea0

	impl Default for App {
	fn default() -> Self {
	let mut app = App::empty();
	app.sub_apps.main.update_schedule = Some(Main.intern());
	#[cfg(feature = "bevy_reflect")]
	app.init_resource::<AppTypeRegistry>();
	#[cfg(feature = "reflect_functions")]
	app.init_resource::<AppFunctionRegistry>();
	app.add_plugins(MainSchedulePlugin);
	app.add_systems(
	First,
	event_update_system
	.in_set(bevy_ecs::event::EventUpdates)
	.run_if(bevy_ecs::event::event_update_condition),
	);
	app.add_event::<AppExit>();
	app
	}
	}

LogPlugin would fit right in here.

[SpecificProtagonist]

App::default can insert LogPlugin itself if we merge bevy_log into bevy_app, probably behind an optional but default feature.

The problem is that LogPlugina allows configuration, and we need a way to provide that.