wasmtime / issue #7157 wasi-nn: be explicit about the err... · git-wasmtime

Stream: git-wasmtime

Topic: wasmtime / issue #7157 wasi-nn: be explicit about the err...

Wasmtime GitHub notifications bot (Oct 05 2023 at 14:54):

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.

Wasmtime GitHub notifications bot (Oct 05 2023 at 22:29):

ereslibre commented on issue #7157:

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

Wasmtime GitHub notifications bot (Oct 06 2023 at 07:39):

ereslibre commented on issue #7157:

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 (for 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)

Wasmtime GitHub notifications bot (Oct 06 2023 at 07:42):

ereslibre edited a comment on issue #7157:

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 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)

Wasmtime GitHub notifications bot (Oct 06 2023 at 07:43):

ereslibre edited a comment on issue #7157:

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)

Wasmtime GitHub notifications bot (Oct 06 2023 at 13:58):

alexcrichton commented on issue #7157:

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?

Wasmtime GitHub notifications bot (Oct 06 2023 at 19:44):

ereslibre commented on issue #7157:

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:

n 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.

Wasmtime GitHub notifications bot (Oct 06 2023 at 19:44):

ereslibre edited a comment on issue #7157:

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:

n 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.

Wasmtime GitHub notifications bot (Oct 06 2023 at 19:45):

ereslibre edited a comment on issue #7157:

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.

Wasmtime GitHub notifications bot (Oct 06 2023 at 20:28):

alexcrichton commented on issue #7157:

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?

Wasmtime GitHub notifications bot (Oct 06 2023 at 21:00):

ereslibre commented on issue #7157:

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 :)

Wasmtime GitHub notifications bot (Oct 06 2023 at 21:14):

alexcrichton commented on issue #7157:

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.

Wasmtime GitHub notifications bot (Oct 06 2023 at 21:21):

ereslibre commented on issue #7157:

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!

Last updated: Oct 23 2024 at 20:03 UTC