error messages don't compose well with anyhow #533

New issue

Closed

opened 2021-10-15 21:39:51 -05:00 by davepacheco · 3 comments

davepacheco commented

2021-10-15 21:39:51 -05:00

(Migrated from github.com)

Describe the bug

I've been using @dtolnay's anyhow crate as a great way to annotate errors with context about was happening when an error was generated. I found that with uuid, though, it generates duplicate messages.

To Reproduce

Steps to reproduce the behavior:

Clone https://github.com/davepacheco/test-uuid-anyhow (or see the code below)
cargo run

Here's the relevant code:

    let f = "foo".parse::<Uuid>().context("parsing").unwrap_err();
    ...
    eprintln!("    alt format: {:#}", f);

Expected behavior

I expected this to print:

parsing: invalid length: expected one of [36, 32], found 3

but it actually prints:

parsing: invalid length: expected one of [36, 32], found 3: invalid length: expected one of [36, 32], found 3

Screenshots

The rest of the program shows exactly what the error chain looks like. Here's the output:

top-level (anyhow) error:
     formatted: parsing
    alt format: parsing: invalid length: expected one of [36, 32], found 3: invalid length: expected one of [36, 32], found 3
anyhow debug format:
parsing

Caused by:
    0: invalid length: expected one of [36, 32], found 3
    1: invalid length: expected one of [36, 32], found 3

CAUSE CHAIN
chain 0: Error { context: "parsing", source: Error(Parser(InvalidLength { expected: Any([36, 32]), found: 3 })) }
     formatted: parsing
    alt format: parsing


chain 1: Error(Parser(InvalidLength { expected: Any([36, 32]), found: 3 }))
     formatted: invalid length: expected one of [36, 32], found 3
    alt format: invalid length: expected one of [36, 32], found 3


chain 2: InvalidLength { expected: Any([36, 32]), found: 3 }
     formatted: invalid length: expected one of [36, 32], found 3
    alt format: invalid length: expected one of [36, 32], found 3

Specifications (please complete the following information):

Target
Version [e.g. 1.0]
Features Enabled

This is with uuid 0.8.2, anyhow 1.0.44, rust 1.52.0, on MacOS 11.6 (Big Sur). I haven't enabled any features. (You can see the complete details in the Cargo.toml and Cargo.lock in the repo I linked to.)

Additional context

anyhow uses the alternate Display format to print the whole cause chain as a single message. I like this a lot because it prints errors the way most standard Unix tools do.

I believe the way it works is it follows the cause chain using std::error::Error::source() and prints out the message associated with each one. This seems pretty reasonable.

I think the problem is that the uuid crate uses a few levels of Error (i.e., a cause chain), and Display on the higher level impl delegates to the next level. So if one walks the cause chain and prints each one out, you get the duplicated message. This structure doesn't really seem right, though I'm not sure the best fix because I'm not sure why the indirection.

**Describe the bug** I've been using @dtolnay's [anyhow](https://docs.rs/anyhow/1.0.44/anyhow/) crate as a great way to annotate errors with context about was happening when an error was generated. I found that with `uuid`, though, it generates duplicate messages. **To Reproduce** Steps to reproduce the behavior: 1. Clone https://github.com/davepacheco/test-uuid-anyhow (or see the code below) 2. `cargo run` Here's the relevant code: ```rust let f = "foo".parse::<Uuid>().context("parsing").unwrap_err(); ... eprintln!(" alt format: {:#}", f); ``` **Expected behavior** I expected this to print: ``` parsing: invalid length: expected one of [36, 32], found 3 ``` but it actually prints: ``` parsing: invalid length: expected one of [36, 32], found 3: invalid length: expected one of [36, 32], found 3 ``` **Screenshots** The rest of the program shows exactly what the error chain looks like. Here's the output: ``` top-level (anyhow) error: formatted: parsing alt format: parsing: invalid length: expected one of [36, 32], found 3: invalid length: expected one of [36, 32], found 3 anyhow debug format: parsing Caused by: 0: invalid length: expected one of [36, 32], found 3 1: invalid length: expected one of [36, 32], found 3 CAUSE CHAIN chain 0: Error { context: "parsing", source: Error(Parser(InvalidLength { expected: Any([36, 32]), found: 3 })) } formatted: parsing alt format: parsing chain 1: Error(Parser(InvalidLength { expected: Any([36, 32]), found: 3 })) formatted: invalid length: expected one of [36, 32], found 3 alt format: invalid length: expected one of [36, 32], found 3 chain 2: InvalidLength { expected: Any([36, 32]), found: 3 } formatted: invalid length: expected one of [36, 32], found 3 alt format: invalid length: expected one of [36, 32], found 3 ``` **Specifications (please complete the following information):** - Target - Version [e.g. 1.0] - Features Enabled This is with `uuid` 0.8.2, `anyhow` 1.0.44, rust 1.52.0, on MacOS 11.6 (Big Sur). I haven't enabled any features. (You can see the complete details in the Cargo.toml and Cargo.lock in the repo I linked to.) **Additional context** [`anyhow` uses the alternate Display format to print the whole cause chain as a single message.](https://docs.rs/anyhow/1.0.44/anyhow/struct.Error.html#display-representations) I like this a lot because it prints errors the way most standard Unix tools do. I believe the way it works is it follows the cause chain using [std::error::Error::source()](https://doc.rust-lang.org/std/error/trait.Error.html#method.source) and prints out the message associated with each one. This seems pretty reasonable. I think the problem is that the uuid crate uses a few levels of Error (i.e., a cause chain), and `Display` on the higher level impl [delegates to the next level](https://github.com/uuid-rs/uuid/blob/e51f80a5c33b2483980dcbc53ab04cd705766320/src/error.rs#L47-L54). So if one walks the cause chain and prints each one out, you get the duplicated message. This structure doesn't really seem right, though I'm not sure the best fix because I'm not sure why the indirection.

KodrAus commented

2021-10-27 05:07:46 -05:00

(Migrated from github.com)

Thanks for the report @davepacheco! It looks like we need to take a fresh look at our error handling story. If this is something you’re interested in exploring please feel free to dig into it!

KodrAus commented

2021-10-30 16:50:14 -05:00

(Migrated from github.com)

Alrighty, I’ve reworked the internal shape of uuid::Error so it now reports its inner context through Display instead of source. That should make it work better with anyhow.

Alrighty, I’ve reworked the internal shape of `uuid::Error` so it now reports its inner context through `Display` instead of `source`. That should make it work better with `anyhow`.

davepacheco commented

2021-11-01 10:47:12 -05:00

(Migrated from github.com)

Thanks for doing that! It looks great. If I switch the test repo to use commit 2925da3372 (current tip of main), the output looks like this:

$ cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.00s
     Running `target/debug/uuid-error`
top-level (anyhow) error:
     formatted: parsing
    alt format: parsing: invalid length: expected one of [36, 32], found 3
anyhow debug format:
parsing

Caused by:
    invalid length: expected one of [36, 32], found 3

CAUSE CHAIN
chain 0: Error { context: "parsing", source: Error(InvalidLength { expected: Any([36, 32]), found: 3 }) }
     formatted: parsing
    alt format: parsing


chain 1: Error(InvalidLength { expected: Any([36, 32]), found: 3 })
     formatted: invalid length: expected one of [36, 32], found 3
    alt format: invalid length: expected one of [36, 32], found 3

which is perfect. Thanks!

Any idea when this will wind up in a release on crates.io?

Thanks for doing that! It looks great. If I switch the test repo to use commit 2925da3372e79c4438d65ce331ac9fcdb48a6938 (current tip of main), the output looks like this: ``` $ cargo run Finished dev [unoptimized + debuginfo] target(s) in 0.00s Running `target/debug/uuid-error` top-level (anyhow) error: formatted: parsing alt format: parsing: invalid length: expected one of [36, 32], found 3 anyhow debug format: parsing Caused by: invalid length: expected one of [36, 32], found 3 CAUSE CHAIN chain 0: Error { context: "parsing", source: Error(InvalidLength { expected: Any([36, 32]), found: 3 }) } formatted: parsing alt format: parsing chain 1: Error(InvalidLength { expected: Any([36, 32]), found: 3 }) formatted: invalid length: expected one of [36, 32], found 3 alt format: invalid length: expected one of [36, 32], found 3 ``` which is perfect. Thanks! Any idea when this will wind up in a release on crates.io?