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

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

Open
fallible-algebra opened this issue May 19, 2023 Discussed in #8637 · 8 comments
Open

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

fallible-algebra opened this issue May 19, 2023 Discussed in #8637 · 8 comments
Labels
A-Diagnostics Logging, crash handling, error reporting and performance analysis A-ECS Entities, components, systems, and events C-Usability A targeted quality-of-life change that makes Bevy easier to use S-Needs-Investigation This issue requires detective work to figure out what's going wrong

Comments

@fallible-algebra
Copy link

fallible-algebra commented May 19, 2023

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.

@alice-i-cecile alice-i-cecile added A-ECS Entities, components, systems, and events C-Usability A targeted quality-of-life change that makes Bevy easier to use A-Diagnostics Logging, crash handling, error reporting and performance analysis labels May 19, 2023
@fallible-algebra
Copy link
Author

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
Copy link
Member

Does #8526 resolve this issue?

@JoJoJet
Copy link
Member

JoJoJet commented Jun 5, 2023

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
Copy link
Author

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
Copy link
Contributor

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 NthTensor mentioned this issue Dec 2, 2024
4 tasks
@NthTensor
Copy link
Contributor

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

@fallible-algebra
Copy link
Author

fallible-algebra commented Dec 3, 2024

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
Copy link
Contributor

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.

@BenjaminBrienen BenjaminBrienen added the S-Needs-Investigation This issue requires detective work to figure out what's going wrong label Dec 12, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-Diagnostics Logging, crash handling, error reporting and performance analysis A-ECS Entities, components, systems, and events C-Usability A targeted quality-of-life change that makes Bevy easier to use S-Needs-Investigation This issue requires detective work to figure out what's going wrong
Projects
None yet
Development

No branches or pull requests

5 participants