Log to file #5342

IceSentry · 2022-07-16T19:08:14Z

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 · 2022-07-17T18:49:19Z

I opened tokio-rs/tracing#2225 to fix the lack of suffix customisation in tracing-appender

johanhelsing · 2023-02-22T22:09:59Z

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: IceSentry#3

mockersf · 2023-02-23T07:45:12Z

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

IceSentry · 2023-02-23T07:51:21Z

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 · 2023-02-23T07:55:00Z

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 · 2023-02-23T08:19:08Z

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

bevy/crates/bevy_window/src/window.rs

Lines 122 to 125 in 695d30b

    
               //  ## Platform-specific 
        
               // 
        
               //  **`iOS`**, **`Android`**, and the **`Web`** do not have decorations. 
        
               pub decorations: bool,

crates/bevy_log/Cargo.toml

crates/bevy_log/src/lib.rs

johanhelsing

Seems like you accidentally committed the log file, but otherwise it seems good to me :)

johanhelsing · 2023-03-10T08:23:20Z

Made a PR to this branch to remove the extra log file: IceSentry#4

johanhelsing · 2023-03-20T08:53:46Z

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 · 2023-03-20T22:38:30Z

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 · 2023-03-20T22:43:07Z

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 · 2023-03-21T07:29:56Z

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 · 2023-07-28T15:07:02Z

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 · 2023-09-01T03:31:58Z

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.

crates/bevy_log/src/lib.rs

Co-authored-by: François <[email protected]>

crates/bevy_log/src/lib.rs

Co-authored-by: François <[email protected]>

spectria-limina

Hi, I was asked to jump in and review this PR. It's my first Bevy review, so hopefully all is good.

The idea looks good, but I have left some suggestions on potential improvements. Hope they are helpful!

crates/bevy_log/src/lib.rs

+    /// ## Platform-specific
+    ///
+    /// **`WASM`** does not support logging to a file.
+    pub file_appender_settings: Option<FileAppenderSettings>,


crates/bevy_log/src/lib.rs

-            let subscriber = subscriber.with(fmt_layer);
+                let subscriber = subscriber.with(fmt_layer);
+
+                #[cfg(feature = "tracing-chrome")]


spectria-limina · 2024-01-24T22:33:55Z

crates/bevy_log/src/lib.rs

+                }
+
+                if settings.rolling == Rolling::Never && settings.prefix.is_empty() {
+                    panic!("Using the Rolling::Never variant with no prefix will result in an empty filename which is invalid");


nit: add a comma before "which"

crates/bevy_log/src/lib.rs

+                    .with_ansi(false)
+                    .with_writer(non_blocking);
+                Some(file_fmt_layer)
+            } else {


spectria-limina · 2024-01-24T22:38:51Z

crates/bevy_log/src/lib.rs

+                let (non_blocking, worker_guard) = tracing_appender::non_blocking(file_appender);
+                // WARN We need to keep this somewhere so it doesn't get dropped.
+                // If it gets dropped then it will silently stop writing to the file
+                app.insert_resource(FileAppenderWorkerGuard(worker_guard));


This isn't fully robust as it will mean that logs still get lost after teardown of the current app. This would apply to logs generated later in the teardown, or perhaps in a multi-App process if the App with the logging configuration were to be destroyed but others were to continue.

Given that only one logger can ever be configured globally, perhaps it's okay to simply mem::forget the guard? This applies equally to the existing guards elsewhere in the code.

johanhelsing · 2024-01-25T02:12:54Z

crates/bevy_log/src/lib.rs

+            } else {
+                None
+            };
+            let subscriber = subscriber.with(file_appender_layer);


Iirc the subscriber changes type with each call, and is relatively unergonomic to use, which is why much of this code seems arbitrarily strange.

IceSentry · 2024-01-26T22:38:00Z

examples/app/logs.rs

@@ -8,6 +8,8 @@ fn main() {
            // Uncomment this to override the default log settings:
            // level: bevy::log::Level::TRACE,
            // filter: "wgpu=warn,bevy_ecs=info".to_string(),
+            // This will let you configure file logging


This will generate artifacts which is not ideal and examples shouldn't have to clean up after themselves.

crates/bevy_log/src/lib.rs

+#[derive(Resource)]
+struct FileAppenderWorkerGuard(tracing_appender::non_blocking::WorkerGuard);
+
+/// Settings to control how to log to a file


crates/bevy_log/src/lib.rs

spectria-limina · 2024-01-24T22:50:01Z

crates/bevy_log/src/lib.rs

+                #[cfg(feature = "tracing-chrome")]
+                let chrome_layer = {
+                    let mut layer = tracing_chrome::ChromeLayerBuilder::new();
+                    if let Ok(path) = std::env::var("TRACE_CHROME") {


If I understand correctly, this PR will leave things in a situation where the Chrome tracing is controlled purely by environment variable, and the file logging purely by code. It might be good to unify both of these paths and allow control of both variations by either method, with environment variables taking priority.

I'd rather leave this to be fixed in a future PR but I agree that support for ENV controlled file logging would be good.

IceSentry · 2024-05-06T03:26:15Z

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.

IceSentry added A-Diagnostics Logging, crash handling, error reporting and performance analysis C-Dependencies A change to the crates that Bevy depends on C-Usability A targeted quality-of-life change that makes Bevy easier to use labels Jul 16, 2022

Indy2222 mentioned this pull request Jul 17, 2022

Logging to file DigitalExtinction/Game#90

Closed

IceSentry force-pushed the log_to_file branch 2 times, most recently from 224e129 to 0ae3a0c Compare July 17, 2022 18:53

brandon-reinhart mentioned this pull request Jul 26, 2022

Bevy Log Output to Files #5233

Open

IceSentry force-pushed the log_to_file branch from 0ae3a0c to 1d017a7 Compare August 18, 2022 15:21

johanhelsing mentioned this pull request Feb 15, 2023

Add support for adding custom log layers #7682

Closed

IceSentry force-pushed the log_to_file branch from 0417cb3 to d050805 Compare February 23, 2023 07:41

IceSentry marked this pull request as ready for review February 23, 2023 07:41

IceSentry force-pushed the log_to_file branch 2 times, most recently from 2ba5958 to ae4782f Compare February 23, 2023 07:48

IceSentry changed the title ~~add log_to_file feature~~ Log to file Feb 23, 2023

johanhelsing reviewed Feb 23, 2023

View reviewed changes

crates/bevy_log/Cargo.toml Outdated Show resolved Hide resolved

crates/bevy_log/src/lib.rs Show resolved Hide resolved

johanhelsing reviewed Feb 25, 2023

View reviewed changes

IceSentry force-pushed the log_to_file branch 2 times, most recently from bf553e3 to b6de76a Compare September 1, 2023 03:05

IceSentry added 2 commits September 4, 2023 22:31

add log to file

1aa6311

add panic hook

94d686f

IceSentry force-pushed the log_to_file branch from cb0b5d0 to 94d686f Compare September 5, 2023 02:31

mockersf reviewed Sep 5, 2023

View reviewed changes

crates/bevy_log/src/lib.rs Outdated Show resolved Hide resolved

IceSentry and others added 2 commits September 5, 2023 02:09

Update crates/bevy_log/src/lib.rs

ba78be9

Co-authored-by: François <[email protected]>

fix for ci

d634146

mockersf reviewed Sep 5, 2023

View reviewed changes

crates/bevy_log/src/lib.rs Outdated Show resolved Hide resolved

Update crates/bevy_log/src/lib.rs

88fc5ec

Co-authored-by: François <[email protected]>

mockersf approved these changes Sep 5, 2023

View reviewed changes

alice-i-cecile added this to the 0.13 milestone Nov 3, 2023

spectria-limina suggested changes Jan 24, 2024

View reviewed changes

alice-i-cecile modified the milestones: 0.13, 0.14 Jan 26, 2024

IceSentry added 3 commits January 26, 2024 17:25

Merge remote-tracking branch 'upstream/main' into log_to_file

7daaafa

fix merge

f13630f

address come comments

1e3a579

alice-i-cecile added the M-Needs-Release-Note Work that should be called out in the blog due to impact label Feb 22, 2024

IceSentry closed this May 6, 2024

IceSentry added the S-Adopt-Me The original PR author has no intent to complete this work. Pick me up! label May 6, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Log to file #5342

Log to file #5342

IceSentry commented Jul 16, 2022 •

edited

Loading

IceSentry commented Jul 17, 2022

johanhelsing commented Feb 22, 2023

mockersf commented Feb 23, 2023

IceSentry commented Feb 23, 2023

IceSentry commented Feb 23, 2023

mockersf commented Feb 23, 2023

johanhelsing left a comment

johanhelsing commented Mar 10, 2023

johanhelsing commented Mar 20, 2023

mockersf commented Mar 20, 2023 •

edited

Loading

IceSentry commented Mar 20, 2023

johanhelsing commented Mar 21, 2023

arsmilitaris commented Jul 28, 2023

IceSentry commented Sep 1, 2023 •

edited

Loading

spectria-limina left a comment

This comment was marked as resolved.

This comment was marked as resolved.

spectria-limina Jan 24, 2024

This comment was marked as resolved.

spectria-limina Jan 24, 2024

This comment was marked as resolved.

johanhelsing Jan 25, 2024

This comment was marked as resolved.

IceSentry Jan 26, 2024

This comment was marked as resolved.

spectria-limina Jan 24, 2024

IceSentry Jan 26, 2024

IceSentry commented May 6, 2024

Log to file #5342

Log to file #5342

Conversation

IceSentry commented Jul 16, 2022 • edited Loading

Objective

Solution

Notes

IceSentry commented Jul 17, 2022

johanhelsing commented Feb 22, 2023

mockersf commented Feb 23, 2023

IceSentry commented Feb 23, 2023

IceSentry commented Feb 23, 2023

mockersf commented Feb 23, 2023

johanhelsing left a comment

Choose a reason for hiding this comment

johanhelsing commented Mar 10, 2023

johanhelsing commented Mar 20, 2023

mockersf commented Mar 20, 2023 • edited Loading

IceSentry commented Mar 20, 2023

johanhelsing commented Mar 21, 2023

arsmilitaris commented Jul 28, 2023

IceSentry commented Sep 1, 2023 • edited Loading

spectria-limina left a comment

Choose a reason for hiding this comment

This comment was marked as resolved.

This comment was marked as resolved.

spectria-limina Jan 24, 2024

Choose a reason for hiding this comment

This comment was marked as resolved.

spectria-limina Jan 24, 2024

Choose a reason for hiding this comment

This comment was marked as resolved.

johanhelsing Jan 25, 2024

Choose a reason for hiding this comment

This comment was marked as resolved.

IceSentry Jan 26, 2024

Choose a reason for hiding this comment

This comment was marked as resolved.

spectria-limina Jan 24, 2024

Choose a reason for hiding this comment

IceSentry Jan 26, 2024

Choose a reason for hiding this comment

IceSentry commented May 6, 2024

IceSentry commented Jul 16, 2022 •

edited

Loading

mockersf commented Mar 20, 2023 •

edited

Loading

IceSentry commented Sep 1, 2023 •

edited

Loading