System piping for error/warn/info logging does not show error source

[fallible-algebra]

Bevy version

• 0.10.1
• 0.11.0-dev
• main branch, commit 25f013b

What you did

Attach warn to a system that would return a result:

// Using bevy 0.11.0-dev, main branch commit 25f013b in this example
use bevy::{log::LogPlugin, prelude::*};

fn main() {
    App::new()
        .add_plugin(LogPlugin::default())
        .add_systems(Startup, where_result_system_is::result_system.pipe(warn))
        .run();
}

pub mod where_result_system_is {
    pub fn result_system() -> Result<(), String> {
        Err("Error returned by system".to_owned())
    }
}

What went wrong

I expected to get information about where the error was generated from, i.e.

# Desired result
# The module path points to where the result system is located.
WARN my_project::where_result_system_is: "Error returned by system"

Instead, I only get the module location of warn:

# Actual result
# The module path instead points to the bevy `warn` adaptor, reducing its 
# usefulness as an approach to error logging.
WARN bevy_ecs::system::system_piping::adapter: "Error returned by system"

Additional information

Discussed in #8637

^{Originally posted by fallible-algebra May 19, 2023}
I've been working on a bevy project for a couple of months and have come across a minor information hiccup with error logging.

When using system piping for error logging, the results the system return will get reported by the logging suite as coming from the wrapper system (i.e. warn or info) rather than the function that returned the error i.e. as a stripped down version of this example

fn main() {
    App::new()
    // ...
    .add_system(result_system.pipe(warn)
    .run();
}

pub mod where_result_system_is {
    pub fn result_system(/* whatever inputs */) -> Result<(), String> {
        Err("Error returned by system".to_owned())
    }
}

# Actual output, shows the path to where `warn` is defined.
WARN bevy_ecs::system::system_piping::adapter: Error returned by system
# Desired output, shows the path to where `result_system` is defined.
WARN my_project::where_result_system_is: Error returned by system

The latter is desired as it gives me information as to where the warning is actually coming from, and my project has a wide and deep directory tree.

I'm aware this is behaviour to be expected from using the logging suite + the system piping interfaces together, but this is suboptimal from a point of view of using system piping for error logging. Is there a macro-based approach someone else has worked on? Something that transforms a system that returns a result into a system that doesn't return a result that matches on the result in-function-body, i.e.

#[system_result_transform_macro_of_some_kind(warn)]
pub fn result_system(/* whatever inputs */) -> Result<(), String> {
    Err("Error returned by system")
}
// Becomes
pub fn result_system(/* whatever inputs */) {
    // Or however else the body needs to be encapsulated to allow i.e. ? syntax.
    let res = {Err("Error returned by system")};
    match res {
        Ok(()) => {},
        Err(err) => warn!(err)
    }
}
// So that error location is preserved.

Or is there something else I should be relying on, have I missed something obvious, or is this all splitting hairs? Thanks.

---

I want to be clear that I don't presume that warn (the adaptor) can be capable of getting this information, that it is correct to pursue a solution where warn can receive that information, or that the macro solution is necessarily correct either.

I am aware this is a limitation on using system piping as error logging, but it was the direction I was pointed in for being able to handle errors in systems via results and ?s instead of unwraps and expects and logging in-systems and I'm losing logging information on a project with a broad and deep structure via this method.

Thanks for continuing to develop bevy.

[fallible-algebra]

I have written a preliminary solution to this: https://github.com/fallible-algebra/bevy_ressys, however I think it needs fleshing out a bit before being developed as a pull request / uploaded to crates.

[alice-i-cecile]

Does #8526 resolve this issue?

[joseph-gio]

Does #8526 resolve this issue?

Unfortunately it does not. It has the same issue where errors point back to the place they were reported rather than where they were created.

[fallible-algebra]

As JoJoJet says, it does not solve the issue of trace location.

It was pointed out to me that https://github.com/nicopap/bevy_mod_sysfail is a similar, if not identical, solution to this problem as I've sketched out.

[NthTensor]

I think it's possible we many be able to sweep this up as part of #16589, or as part of tracing handler follow-up.

[NthTensor]

This appears to have been resolved at some point. I'm not able to replicate the issue on 0.15.

[fallible-algebra]

I'm able to replicate the issue if and only if the new way of doing things is "fallible systems should .map(<choose a logger>) instead of the old .pipe(<choose a logger>)" (basing this off of the current system piping example):

// piping.rs
use bevy::{log::{Level, LogPlugin}, prelude::*, utils::*};

fn main() {
    App::new()
        .add_plugins(LogPlugin {
            ..default()
        })
        .add_systems(
            Startup,
            errors_old::result_system.pipe(consumes_old::error_consumer),
        )
        .add_systems(
            Startup,
            errors_new::result_system.map(warn),
        )
        .run();
}

// this is just going to get mapped to `warn`
mod errors_new {
    pub fn result_system() -> Result<(), String> {
        Err("is there an 'errors_new' to my left?".to_owned())
    }
}

mod errors_old {
    pub fn result_system() -> Result<(), String> {
        Err("is there an 'errors_old' to my left?".to_owned())
    }
}

// replicating the system piping mode
mod consumes_old {
    use bevy::prelude::In;
    pub fn error_consumer(e: In<Result<(), String>>) {
        if let Err(err) = e.0 {
            bevy::log::error!("{err}");
        }
    }
}

Running this gives:

2024-12-03T08:49:40.911283Z ERROR piping::consumes_old: is there an 'errors_old' to my left?
2024-12-03T08:49:40.911288Z  WARN bevy_utils: "is there an 'errors_new' to my left?"

I've not kept up with if this is the current way to handle things properly or if there's a better results type to pack these things together, but if this is still the way to do things then there's still an issue of error source loss.

[NthTensor]

Ah, interesting. I couldn't replicate on my fallible systems branch. Perhaps the scheduled system change happens to resolve this issue, or perhaps I made a mistake. I'll do more testing.

[fallible-algebra]

I've just tested this with main, the "correct" use of fallible systems does address the issue on a more fundamental API design level and reports the source well. Unless there's massive changes to fallible systems before 0.16, I think this can be easily closed.