Log to file

[IceSentry]

trafficstars

Objective

• Add the ability to log to a file

Solution

• Add a dependency on tracing-appender

Notes

For reasons I don't know, tracing-appender didn't support custom suffix. This means it's impossible to log to a file with a .log extension. I submitted a fix that was merged to add support for it, but there has been no release of tracing-appender in almost a year

Closes: #5233

[IceSentry]

I opened https://github.com/tokio-rs/tracing/pull/2225 to fix the lack of suffix customisation in tracing-appender

[johanhelsing]

First of all, the design of tracing subscriber makes it really hard to conditionally add a layer without using cfg flags. This means that I need a cfg flag to conditionally add the file appender, but that also means the file appender settings need to be conditionally added to the LogSettings. An alternate option could be to simply have a separate setting resource for the file appender.

I found out it's possible to circumvent some of the type issues by adding an Option<Layer>.

See: https://github.com/IceSentry/bevy/pull/3

[mockersf]

this will not work in wasm, and it should either be gated or mentioned in the docs

[IceSentry]

this will not work in wasm

The diff doesn't show it, but it's in the block that adds layers that don't work in wasm or android. I will add documentation explaining this, but do you also want the field on the struct to be gated?

[IceSentry]

I'm not sure why I put it there actually. I don't see why it wouldn't work on android. I'll move it to a new gated section for not wasm

[mockersf]

I will add documentation explaining this, but do you also want the field on the struct to be gated?

Documentation should be good enough, something like https://github.com/bevyengine/bevy/blob/695d30bd54af2978dc99f214dda34b568348cf86/crates/bevy_window/src/window.rs#L122-L125

[johanhelsing]

Made a PR to this branch to remove the extra log file: https://github.com/IceSentry/bevy/pull/4

[johanhelsing]

One caveat with this, is that it won't catch panics. That is if you add a panic to the logs example, you get:

dev/bevy b69aec5 ~1 …1 cargo run --example logs
    Finished dev [unoptimized + debuginfo] target(s) in 0.34s
     Running `target\debug\examples\logs.exe`
2023-03-20T08:51:49.583296Z  INFO bevy_winit::system: Creating new window "Bevy App" (0v0)
2023-03-20T08:51:49.763815Z  INFO bevy_render::renderer: AdapterInfo { name: "NVIDIA GeForce GTX 970", vendor: 4318, device: 5058, device_type: DiscreteGpu, driver: "NVIDIA", driver_info: "522.25", backend: Vulkan }
2023-03-20T08:51:50.363948Z  INFO bevy_diagnostic::system_information_diagnostics_plugin::internal: SystemInfo { os: "Windows 11 Pro", kernel: "22621", cpu: "AMD Ryzen 9 3900X 12-Core Processor", core_count: "12", memory: "31.9 GiB" }
2023-03-20T08:51:50.443608Z  INFO logs: helpful information that is worth printing by default
2023-03-20T08:51:50.443754Z  WARN logs: something bad happened that isn't a failure, but thats worth calling out
2023-03-20T08:51:50.443842Z ERROR logs: something failed
thread 'Compute Task Pool (14)' panicked at 'something really horrible happened!', examples/app/logs.rs:28:5
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
thread 'Compute Task Pool (14)' panicked at 'A system has panicked so the executor cannot continue.: RecvError', crates\bevy_ecs\src\schedule\executor\multi_threaded.rs:190:60
thread 'main' panicked at 'called `Option::unwrap()` on a `None` value', C:\Users\Johan\dev\bevy\crates\bevy_tasks\src\task_pool.rs:371:49
error: process didn't exit successfully: `target\debug\examples\logs.exe` (exit code: 101)
dev/bevy b69aec5 ~1 …1 cat log
2023-03-20T08:51:33.556888Z  INFO bevy_winit::system: Creating new window "Bevy App" (0v0)
2023-03-20T08:51:33.939334Z  INFO bevy_render::renderer: AdapterInfo { name: "NVIDIA GeForce GTX 970", vendor: 4318, device: 5058, device_type: DiscreteGpu, driver: "NVIDIA", driver_info: "522.25", backend: Vulkan }
2023-03-20T08:51:34.961082Z  INFO bevy_diagnostic::system_information_diagnostics_plugin::internal: SystemInfo { os: "Windows 11 Pro", kernel: "22621", cpu: "AMD Ryzen 9 3900X 12-Core Processor", core_count: "12", memory: "31.9 GiB" }
2023-03-20T08:51:35.041160Z  INFO logs: helpful information that is worth printing by default
2023-03-20T08:51:35.041269Z  WARN logs: something bad happened that isn't a failure, but thats worth calling out
2023-03-20T08:51:35.041366Z ERROR logs: something failed
2023-03-20T08:51:49.583414Z  INFO bevy_winit::system: Creating new window "Bevy App" (0v0)
2023-03-20T08:51:49.763948Z  INFO bevy_render::renderer: AdapterInfo { name: "NVIDIA GeForce GTX 970", vendor: 4318, device: 5058, device_type: DiscreteGpu, driver: "NVIDIA", driver_info: "522.25", backend: Vulkan }
2023-03-20T08:51:50.364098Z  INFO bevy_diagnostic::system_information_diagnostics_plugin::internal: SystemInfo { os: "Windows 11 Pro", kernel: "22621", cpu: "AMD Ryzen 9 3900X 12-Core Processor", core_count: "12", memory: "31.9 GiB" }
2023-03-20T08:51:50.443724Z  INFO logs: helpful information that is worth printing by default
2023-03-20T08:51:50.443828Z  WARN logs: something bad happened that isn't a failure, but thats worth calling out
2023-03-20T08:51:50.443896Z ERROR logs: something failed

I'm not sure if it is out of scope for this new API, or whether we should try to create a more high-level API, less coupled to file appender?

[mockersf]

I'm not sure why I put it there actually. I don't see why it wouldn't work on android. I'll move it to a new gated section for not wasm

Could you check how it works on Android? Aren't apps sandboxed, unless you require additional permissions? Is the log file in a reachable place?

[IceSentry]

it won't catch panics

I think that's fine, if people want to log an error message before a panic they should do that. We could probably provide a panic_print!() or something like that I guess.

Could you check how it works on Android?

I'm not sure how to do that. I guess I should just keep it gated for now.

[johanhelsing]

it won't catch panics

I think that's fine, if people want to log an error message before a panic they should do that. We could probably provide a panic_print!() or something like that I guess.

That would be quite some boilerplate on expect, unwrap, unreachable! etc. and wouldn't handle panics like those coming from incorrect use of Query::single, World::resource, or systems with missing resources, not to mention 3rd party crates.

Not really sure how this is commonly solved, maybe possible through a panic hook? Currently I'm wrapping my whole executable in a launcher process that pipes both stdout and stderr to files, mainly to catch panics, would be nice if I didn't have to.

[arsmilitaris]

I would like to add that I'm using this PR in my project, and the solution I found to capture panics (which was the only thing the updated LogPlugin wasn't doing) to a file was indeed using a panic hook.

If one adds this to the beginning of the main() function:

std::panic::set_hook(Box::new(custom_panic_hook));

and then the custom_panic_hook can be just:

// Logging
fn custom_panic_hook(info: &std::panic::PanicInfo) {
    // Perform any necessary logging or error handling here
    error!("Panic occurred: {:?}", info);
}

In this way, panics are correctly logged to the log file.

The launcher process solution is also interesting, and can be useful.

[IceSentry]

I added a panic hook that is only enabled when using the file appender. After some quick testing it does seem to catch panics from systems correctly.

[IceSentry]

I have way too much going on right now and don't have the time to update this PR. If anyone is interested in picking up this work feel free to pick this up.