feat(logging)!: Move logging setup to setup_logging, disable bevy LogPlugin, add logging to file system

[MaxCWhitehead]

Implement LogPlugin in bones based off Bevy's LogPlugin.

Shouldn't be much of a change in behavior, just 1st step in adding additional log functionality in bones, such as saving game log files to disk.

One difference is that it no longer includes the tracing_error crate layer, I will review how this is used in bevy and see if we want to add this dependency. Want to make sure not going to degrade in error reporting quality for errors originating in bevy. (Plus maybe there is something can learn from this / use in bones). Context: https://github.com/bevyengine/bevy/blob/3cf70ba4f9d62396240b186ff379d27a312d2aa2/crates/bevy_log/src/lib.rs#L205

Logging is behind a feature flag, enabled by default. May be removed if user wants their own global subscriber configured.

[MaxCWhitehead]

Updated this to remove LogPlugin - logging is now setup with logging::setup_logging.

This does a few things:

• Setups layers for tracing subscriber + inits global subscriber
• Adds a new panic hook tracing_panic_hook (and preserves existing hook). This ensures panics (and backtrace if available) goes through tracing subscriber, so it may be written to logs on file system, and not just sent to stderr.
• If LogFileConfig is provided in LogSettings, configures logging to filesystem.

Logging to files

tracing-appender crate is used, it's very light on deps and handles non-blocking writing to log files, and rotating log files based on LogFileRotation. Max files may be set so that older log files are cleaned up. I don't think rotating files by day/hour/minute is really what we'd prefer, but I think this setup should be serviceable for now. Maybe more flexible options (rotate file on each run) could be added in the future.

More docs on setup_logging, but example of what configuring this looks like w/ automatic discovery of appropriate platform app data directory:

fn main() {
    let log_file =
        match LogPath::find_app_data_dir(("org".into(), "fishfolk".into(), "jumpy".into())) {
            Ok(log_path) => Some(LogFileConfig {
                log_path,
                rotation: LogFileRotation::Daily,
                file_name_prefix: "Jumpy.log".to_string(),
                max_log_files: Some(7),
            }),
            Err(err) => {
                // Cannot use error! macro as logging not configured yet.
                //
                // Note that on wasm, this will not log to console - will fail silently.
                eprintln!("Failed to configure file logging: {err}");
                None
            }
        };

    let _log_guard = bones_framework::logging::setup_logging(LogSettings {
        log_file,
        ..default()
    });
    // ...
}

Where the logs end up:

~/.local/share/org.fishfolk.jumpy/logs,
C:\Users\<User>\Appdata\Roaming\org.fishfolk.jumpy\logs,
~/Library/Application Support/org.fishfolk.jumpy/logs

Updating Bones

With Bevy LogPlugin disabled, bones users will need to call setup_logging to get tracing to console output again, is a breaking change.

[MaxCWhitehead]

Hmm miri fails with error: unsupported operation: can't call foreign function "getpwuid_r" on OS "linux" from the directories crate I'm using here. (We use this in other places like for storage backend path, but maybe those don't get test coverage).

Will need to see if this is just something unsupported by miri / how to resolve, thinking it's not a real issue.

[RockasMockas]

Nice job.

If setup_logging() is required to get tracing in console again (and for a simpler initial setup for devs to get up and running quickly) I'd recommend implementing a setup_logging_default(("org".into(), "fishfolk".into(), "jumpy".into())) function which doesn't require any other inputs, and simply defaults to daily rotation, 7 logs, and using the last element jumpy appended to .log for the file name prefix.

Will help to keep examples cleaner with just a straightforward 1-line path, and advanced cases can do the 10 line approach.

[zicklag]

Hmm miri fails with error: unsupported operation: can't call foreign function "getpwuid_r" on OS "linux" from the directories crate I'm using here. (We use this in other places like for storage backend path, but maybe those don't get test coverage).

Yeah, Miri can't run syscalls IIRC. We might be able to put a #[cfg(test)] flag in there to ignore the actual filesystem stuff when running in tests.

---

Also, is it necessary to have the _log_guard? What does it need it for?

[MaxCWhitehead]

Also, is it necessary to have the _log_guard? What does it need it for?

I put a description on our LogFileGuard type + mentioned in setup_logging doc so hopefully it's explained enough, I had the same question about it. It wraps this: https://docs.rs/tracing-appender/latest/tracing_appender/non_blocking/struct.WorkerGuard.html

We are using a async writer to files which does not flush on every write, is buffered. When the guard is dropped, it flushes the buffers ensuring that during a exit or unwind in panic, that the buffered traces are flushed and nothing is lost. The guard must be help / kept alive, if it is dropped will stop writing to file system.

As we init logging in main, keeping guard on the stack in main() works out well, just need to save it. (And the #[must_use] annotation is present, so should help ensure returned guard is held).

[zicklag]

The let _guard = ... bugs me just enough that I feel like maybe it'd be good to make a macro for it, so that you can just call setup_loggin!(...). What do you think?

[MaxCWhitehead]

The let _guard = ... bugs me just enough that I feel like maybe it'd be good to make a macro for it, so that you can just call setup_loggin!(...). What do you think?

Hmm... I do think the guard is confusing / will make people have to think about it more then they probably want to.

That said there is complexity here for good reason, and hiding it can lead to mistakes. If someone was to conditionally use bones setup logging based on either a feature flag, or a target_arch setting, if call is not a single expression may end up in a scope, all of a sudden breaking file logging.

fn main()
{
    #[cfg(feature = "bones-logging")]
    {
        let settings = LogSettings {
            // ... som setup
        }; 
        setup_logging!(settings);
     } // guard is dropped - no file logging
 }  

Obviously can add good docs helping communicate this pitfall, and complex uses could also not use macro. And we could add a error!() on guard drop to alert user. I think that combination of things is probably good enough w/ good docs. I'll add a macro option + the default 1-liner @RockasMockas mentioned, and can see how that feels.

I'm just a bit wary of hiding complexity and possibly trading visual appeal for bugs or unexpected issues for first time users. Even if ugly, at least most folks can probably feel confident copy and pasting a line with let _guard = ... from demo and knowing it will work even if not understanding it.

[MaxCWhitehead]

Added setup_logging_default for setup w/ file logging from app_namespace and default everything else.

Added setup_logs! macro -

• setup_logs!(): calls setup_logging(LogSettings::default());
• setup_logs!("org", "fishfolk", "jumpy); does setup_logging_default(("org", "fishfolk", "jumpy));

LogFileGuard prints a warning with dropped / if macros are not used in the root scope.