Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Log to file #5342

Closed
wants to merge 8 commits into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions crates/bevy_log/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,7 @@ tracing-subscriber = { version = "0.3.1", features = [
tracing-chrome = { version = "0.7.0", optional = true }
tracing-log = "0.1.2"
tracing-error = { version = "0.2.0", optional = true }
tracing-appender = "0.2.2"

# Tracy dependency compatibility table:
# https://github.com/nagisa/rust_tracy_client
Expand Down
188 changes: 155 additions & 33 deletions crates/bevy_log/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,8 @@
#[cfg(feature = "trace")]
use std::panic;

use std::path::PathBuf;

#[cfg(target_os = "android")]
mod android_tracing;

Expand All @@ -33,6 +35,7 @@ pub mod prelude {
pub use bevy_utils::{debug_once, error_once, info_once, once, trace_once, warn_once};
}

use bevy_ecs::system::Resource;
pub use bevy_utils::{
debug_once, error_once, info_once, once, trace_once,
tracing::{
Expand Down Expand Up @@ -70,6 +73,7 @@ use tracing_subscriber::{prelude::*, registry::Registry, EnvFilter};
/// level: Level::DEBUG,
/// filter: "wgpu=error,bevy_render=info,bevy_ecs=trace".to_string(),
/// update_subscriber: None,
/// file_appender_settings: None
/// }))
/// .run();
/// }
Expand Down Expand Up @@ -110,6 +114,14 @@ pub struct LogPlugin {
/// Optionally apply extra transformations to the tracing subscriber.
/// For example add [`Layers`](tracing_subscriber::layer::Layer)
pub update_subscriber: Option<fn(BoxedSubscriber) -> BoxedSubscriber>,

/// Configure file logging
///
/// ## Platform-specific
///
/// **`WASM`** does not support logging to a file.
#[cfg(not(target_arch = "wasm32"))]
pub file_appender_settings: Option<FileAppenderSettings>,

This comment was marked as resolved.

}

/// Alias for a boxed [`Subscriber`].
Expand All @@ -121,6 +133,69 @@ impl Default for LogPlugin {
filter: "wgpu=error,naga=warn".to_string(),
level: Level::INFO,
update_subscriber: None,
file_appender_settings: None,
}
}
}

/// Enum to control how often a new log file will be created
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
pub enum Rolling {
/// Creates a new file every minute and appends the date to the file name
/// Date format: YYYY-MM-DD-HH-mm
Minutely,
/// Creates a new file every hour and appends the date to the file name
/// Date format: YYYY-MM-DD-HH
Hourly,
/// Creates a new file every day and appends the date to the file name
/// Date format: YYYY-MM-DD
Daily,
/// Never creates a new file
Never,
}

impl From<Rolling> for tracing_appender::rolling::Rotation {
fn from(val: Rolling) -> Self {
match val {
Rolling::Minutely => tracing_appender::rolling::Rotation::MINUTELY,
Rolling::Hourly => tracing_appender::rolling::Rotation::HOURLY,
Rolling::Daily => tracing_appender::rolling::Rotation::DAILY,
Rolling::Never => tracing_appender::rolling::Rotation::NEVER,
}
}
}

#[derive(Resource)]
struct FileAppenderWorkerGuard(tracing_appender::non_blocking::WorkerGuard);

/// Settings to control how to log to a file

This comment was marked as resolved.

#[derive(Debug, Clone)]
pub struct FileAppenderSettings {
/// Controls how often a new file will be created
///
/// Defaults to [`Rolling::Never`]
pub rolling: Rolling,
/// The path of the directory where the log files will be added
///
/// Defaults to the local directory
pub path: PathBuf,
/// The prefix added when creating a file
IceSentry marked this conversation as resolved.
Show resolved Hide resolved
///
/// Defaults to "log"
pub prefix: String,
/// When this is enabled, a panic hook will be used and any panic will be logged as an error
///
/// Defaults to true
pub use_panic_hook: bool,
}

impl Default for FileAppenderSettings {
fn default() -> Self {
Self {
rolling: Rolling::Never,
path: PathBuf::from("."),
prefix: String::from("log"),
alice-i-cecile marked this conversation as resolved.
Show resolved Hide resolved
use_panic_hook: true,
}
}
}
Expand All @@ -147,46 +222,93 @@ impl Plugin for LogPlugin {
#[cfg(feature = "trace")]
let subscriber = subscriber.with(tracing_error::ErrorLayer::default());

#[cfg(all(not(target_arch = "wasm32"), not(target_os = "android")))]
#[cfg(not(target_arch = "wasm32"))]
{
#[cfg(feature = "tracing-chrome")]
let chrome_layer = {
let mut layer = tracing_chrome::ChromeLayerBuilder::new();
if let Ok(path) = std::env::var("TRACE_CHROME") {
layer = layer.file(path);
}
let (chrome_layer, guard) = layer
.name_fn(Box::new(|event_or_span| match event_or_span {
tracing_chrome::EventOrSpan::Event(event) => event.metadata().name().into(),
tracing_chrome::EventOrSpan::Span(span) => {
if let Some(fields) =
span.extensions().get::<FormattedFields<DefaultFields>>()
{
format!("{}: {}", span.metadata().name(), fields.fields.as_str())
} else {
span.metadata().name().into()
#[cfg(not(target_os = "android"))]
let subscriber = {
#[cfg(feature = "tracing-chrome")]
let chrome_layer = {
let mut layer = tracing_chrome::ChromeLayerBuilder::new();
if let Ok(path) = std::env::var("TRACE_CHROME") {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

layer = layer.file(path);
}
let (chrome_layer, guard) = layer
.name_fn(Box::new(|event_or_span| match event_or_span {
tracing_chrome::EventOrSpan::Event(event) => {
event.metadata().name().into()
}
}
}))
.build();
app.world.insert_non_send_resource(guard);
chrome_layer
tracing_chrome::EventOrSpan::Span(span) => {
if let Some(fields) =
span.extensions().get::<FormattedFields<DefaultFields>>()
{
format!(
"{}: {}",
span.metadata().name(),
fields.fields.as_str()
)
} else {
span.metadata().name().into()
}
}
}))
.build();
app.world.insert_non_send_resource(guard);
chrome_layer
};

#[cfg(feature = "tracing-tracy")]
let tracy_layer = tracing_tracy::TracyLayer::new();

let fmt_layer =
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should this not be conditional on #[cfg(not(feature = "tracing-tracy"))]?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not sure why it should, tracing and logging to a file are not necessarily related features. It's very possible someone would want to generate a log file while tracing.

tracing_subscriber::fmt::Layer::default().with_writer(std::io::stderr);

// bevy_render::renderer logs a `tracy.frame_mark` event every frame
// at Level::INFO. Formatted logs should omit it.
#[cfg(feature = "tracing-tracy")]
let fmt_layer =
fmt_layer.with_filter(tracing_subscriber::filter::FilterFn::new(|meta| {
meta.fields().field("tracy.frame_mark").is_none()
}));

#[cfg(feature = "tracing-chrome")]

This comment was marked as resolved.

let subscriber = subscriber.with(chrome_layer);
#[cfg(feature = "tracing-tracy")]
let subscriber = subscriber.with(tracy_layer);
subscriber.with(fmt_layer)
};

#[cfg(feature = "tracing-tracy")]
let tracy_layer = tracing_tracy::TracyLayer::new();
let file_appender_layer = self.file_appender_settings.as_ref().map(|settings| {
if settings.use_panic_hook {
let old_handler = std::panic::take_hook();
std::panic::set_hook(Box::new(move |panic_info| {
if let Some(s) = panic_info.payload().downcast_ref::<&str>() {
error!("panic occurred: {s:?}");
} else {
error!("panic occurred");
}
old_handler(panic_info);
}));
}

let fmt_layer = tracing_subscriber::fmt::Layer::default().with_writer(std::io::stderr);
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");
}
let file_appender = tracing_appender::rolling::RollingFileAppender::new(
settings.rolling.into(),
&settings.path,
&settings.prefix,
);

// bevy_render::renderer logs a `tracy.frame_mark` event every frame
// at Level::INFO. Formatted logs should omit it.
#[cfg(feature = "tracing-tracy")]
let fmt_layer =
fmt_layer.with_filter(tracing_subscriber::filter::FilterFn::new(|meta| {
meta.fields().field("tracy.frame_mark").is_none()
}));
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));
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.


let subscriber = subscriber.with(fmt_layer);
tracing_subscriber::fmt::Layer::default()
.with_ansi(false)
.with_writer(non_blocking)
});
let subscriber = subscriber.with(file_appender_layer);

This comment was marked as resolved.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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


#[cfg(feature = "tracing-chrome")]
let subscriber = subscriber.with(chrome_layer);
Expand Down
3 changes: 3 additions & 0 deletions examples/app/logs.rs
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
//! This example illustrates how to use logs in bevy.

use bevy::log::once;
use bevy::log::FileAppenderSettings;
use bevy::prelude::*;

fn main() {
Expand All @@ -9,6 +10,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 comment was marked as resolved.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

// file_appender_settings: Some(FileAppenderSettings::default()),
..default()
}))
.add_systems(Startup, setup)
Expand Down
Loading