wasi-nn: be explicit about the error on BackendError variants

[ereslibre]

BackendAccess and GuestAccess variants contain more information that might be helpful to diagnose an underlying problem. Bubble up that information to the user.

I added this in the context of an openvino installation that was missing plugins.xml. Adding this information helped me in finding out the issue.

[alexcrichton]

Thanks! I think the issue though might lie in what's rendering this error to something human readable. The Error derive here means that (I think) the two underlying errors here you're displaying are already configured via source() in the Rust Error trait. When rendering errors though some processes accidentally only render the top-level of the error rather than the whole chain of errors.

Can you share a reproduction for example to help track down where the error rendering is happening? Or do you know that off the top of your head perchance?

When dealing with anyhow::Error rendering the full error is done with {:?} as opposed to {} which I suspect is what needs to be fixed here.

[ereslibre]

Thank you for the quick response @alexcrichton!

I have created https://github.com/ereslibre/wasmtime-wasi-nn-reproducer. It has two branches: main and detailed-errors.

The detailed-errors one contains a crates.io patch for openvino-rs similar to this one.

An example of the fail report in the different branches:

• main branch:

Error: Failed while accessing backend

Caused by:
    0: library loading error
    1: system failed to load shared libraries (see https://github.com/intel/openvino-rs/blob/main/crates/openvino-finder): Unable to find the `openvino_c` library to load

Please, note that the error itself only contains the "Failed while accessing backend" message. With this patch (and the one proposed for openvino-rs), by using the detailed-errors branch:

• detailed-errors branch:

Error: Failed while accessing backend: library loading error: system failed to load shared libraries (see https://github.com/intel/openvino-rs/blob/main/crates/openvino-finder): Unable to find the `openvino_c` library to load

Caused by:
    0: library loading error: system failed to load shared libraries (see https://github.com/intel/openvino-rs/blob/main/crates/openvino-finder): Unable to find the `openvino_c` library to load
    1: system failed to load shared libraries (see https://github.com/intel/openvino-rs/blob/main/crates/openvino-finder): Unable to find the `openvino_c` library to load

[ereslibre]

Just to add more context to my previous message. In the non-detailed version (main branch in the reproducer), the std::fmt::Display for BackendError (showing the BackendAccess variant only in this example) is expanded to the following:

    #[allow(unused_qualifications)]
    impl std::fmt::Display for BackendError {
        fn fmt(&self, __formatter: &mut std::fmt::Formatter) -> std::fmt::Result {
            #[allow(unused_imports)]
            use thiserror::__private::{DisplayAsDisplay, PathAsDisplay};
            #[allow(unused_variables, deprecated, clippy::used_underscore_binding)]
            match self {
                BackendError::BackendAccess(_0) => {
                    __formatter.write_fmt(format_args!("Failed while accessing backend"))
(snip)

In the detailed-errors branch, it is expanded to:

    #[allow(unused_qualifications)]
    impl std::fmt::Display for BackendError {
        fn fmt(&self, __formatter: &mut std::fmt::Formatter) -> std::fmt::Result {
            #[allow(unused_imports)]
            use thiserror::__private::{DisplayAsDisplay, PathAsDisplay};
            #[allow(unused_variables, deprecated, clippy::used_underscore_binding)]
            match self {
                BackendError::BackendAccess(_0) => {
                    __formatter
                        .write_fmt(
                            format_args!(
                                "Failed while accessing backend: {0}",
                                _0.as_display(),
                            ),
                        )
                }
(snip)

[alexcrichton]

I'm a bit confused though, the main branch looks like the correct rendering of the error to me? The detailed-errors branch repeats the error information on each line where the main one correctly has only one specific error for each line, which I would imagine is sufficient. Is there a reason though that you'd prefer the rendering of the detailed-errors branch rather than main?

[ereslibre]

Is there a reason though that you'd prefer the rendering of the detailed-errors branch rather than main?

Sorry, I think I didn't provide the best example. I was referring only to the display implementation of the error. I have updated both branches of the example, where this is more clear: assuming this is happening in a log entry, the difference is as follows:

• In the main branch:

❯ RUST_LOG=warn cargo run
[2023-10-06T19:37:32Z WARN  reproducer] error setting up wasi-nn: Failed while accessing backend

• In the detailed-errors branch:

❯ RUST_LOG=warn cargo run
[2023-10-06T19:37:43Z WARN  reproducer] error setting up wasi-nn: Failed while accessing backend: library loading error: system failed to load shared libraries (see https://github.com/intel/openvino-rs/blob/main/crates/openvino-finder): Unable to find the `openvino_c` library to load

The use case I'm thinking about is when this might not be a fatal error, and just logged with the Display implementation. I think it might help an administrator to understand what is the issue by looking at the logs. However, I also think is reasonable to say that the Display implementation should be brief and not so detailed.

[alexcrichton]

Ok yes that makes sense, but my comment above was basically saying that whatever is emitting this log is using {} when it should be using {:?}. Would it be possible update the logger to do that?

[ereslibre]

Would it be possible update the logger to do that?

Yes, that would certainly be an option. Being multi-line output, it might look a bit off when surrounded by other log entries ("something" and "something else"):

❯ RUST_LOG=warn cargo run
[2023-10-06T20:55:54Z WARN  reproducer] something
[2023-10-06T20:55:54Z WARN  reproducer] error setting up wasi-nn: Failed while accessing backend

    Caused by:
        0: library loading error
        1: system failed to load shared libraries (see https://github.com/intel/openvino-rs/blob/main/crates/openvino-finder): Unable to find the `openvino_c` library to load
[2023-10-06T20:55:54Z WARN  reproducer] something else

I thought having this information in one line was easier in terms of log processing, but I'm fine if you think what we have is enough :)

[alexcrichton]

Indeed! That seems like something to handle in whatever is rendering the error in my opinion. This PR, by default, means that by default all other renderers of the error will render duplicate information which isn't correct. This to me seems like a bug and/or improvement in the local rendering you have of an error to logs.

Much of this is derivative of how errors are designed in Rust. Errors are designed as a chain of errors and each error in the chain should not render everything else in the chain but rather only they themselves. This PR is effectively violating that design principle of errors in Rust.

What I might recommend is to either:

• Split the {:?} output on lines and log each line, that way the multi-line output looks better.
• Split the {:?} output on lines and then rejoin with semicolons - this creates one long line effectively as this PR does already
• Iterate over .sources() directly and generate a custom log message.

[ereslibre]

This PR, by default, means that by default all other renderers of the error will render duplicate information which isn't correct.

Yes, thanks a lot for your suggestions and the rationale!