Add option to include tracing spans in anyhow errors.

[aikalant]

Wondering about thoughts adding optional support for capturing tracing::Spans in anyhow errors, very similar to backtraces.

The motivation behind this is that spans have the ability to provide lots of context for all log messages by themselves, however bubbling up an error to print loses a lot of this context, so I often find myself duplicating a lot of this "context adding" effort when using anyhow in conjunction, and still missing things that could be nice to have in an error message. It never feels great to have to use the .with_context(|| format!(...)) pattern.

There are some options, like logging errors "on site" in some deeply nested function rather than bubbling, but generally I tend to want to return some kind of message to a high level function when something went wrong before changing some flow, letting it decide the severity and print with an appropriate level, which is not possible with on-site logging. It's easy to filter spans out by level, target to reduce verbosity as well.

By having a span attached to this error, we can briefly enter it, print the error, and exit the span at some higher level function. This allows log messages to be printed as if they happened on site for "free".

        if let Err(e) = do_something() {
            e.span().in_scope(|| warn!("{e:#}"));
        }

The tracing-error crate does a lot of this, but it seems more geared toward printing a multi line trace, and does not provide the option to access spans within its SpanTrace type, forcing you to write your own visitor to change the way it is printed, and I don't find that it's TracedError type plays well with anyhow errors.

I basically duplicated most of the internal macros/machinery that goes with capturing backtraces like hiding the functionality behind a feature flag and capturing the span at the "lowest" point only. Spans themselves being just identifiers makes them small, and the side effect of keeping the span branch in the tracing subscriber registry alive during the bubbling process is pretty small, since errors are generally short lived anyway.

If this seems like a good fit, I am happy to write the appropriate tests and any other requests.

Here is some example output using a contrived, overly logged anyhow_tracing_example.zip:

no tracing, debug

2024-11-27T04:27:01.122304Z  INFO example::no_tracing: Doing something to "file.txt"
2024-11-27T04:27:01.122411Z DEBUG example::no_tracing: Got data: [1, 2, 3]
2024-11-27T04:27:01.122421Z DEBUG example::no_tracing: Modifying data
2024-11-27T04:27:01.122649Z  WARN example::no_tracing: Couldn't do the thing: Couldn't save data [2, 3, 4]: Failed to write to file: "/canonicalized/file.txt": Permission denied (os error 13)
2024-11-27T04:27:01.122676Z  INFO example::no_tracing: Doing something else
2024-11-27T04:27:01.122890Z ERROR example::no_tracing: Couldn't do the other thing: Failed to write to file: "other_file.txt": Permission denied (os error 13)

no tracing, info

2024-11-27T04:27:05.744915Z  INFO example::no_tracing: Doing something to "file.txt"
2024-11-27T04:27:05.745275Z  WARN example::no_tracing: Couldn't do the thing: Couldn't save data [2, 3, 4]: Failed to write to file: "/canonicalized/file.txt": Permission denied (os error 13)
2024-11-27T04:27:05.745301Z  INFO example::no_tracing: Doing something else
2024-11-27T04:27:05.745509Z ERROR example::no_tracing: Couldn't do the other thing: Failed to write to file: "other_file.txt": Permission denied (os error 13)

no tracing, warn

2024-11-27T04:27:09.485193Z  WARN example::no_tracing: Couldn't do the thing: Couldn't save data [2, 3, 4]: Failed to write to file: "/canonicalized/file.txt": Permission denied (os error 13)
2024-11-27T04:27:09.485373Z ERROR example::no_tracing: Couldn't do the other thing: Failed to write to file: "other_file.txt": Permission denied (os error 13)

tracing, debug

2024-11-27T04:27:18.228970Z  INFO do_something{path="file.txt"}: example: Doing something
2024-11-27T04:27:18.229064Z DEBUG do_something{path="file.txt" data="[1, 2, 3]"}: example: Got data
2024-11-27T04:27:18.229077Z DEBUG do_something{path="file.txt" data="[1, 2, 3]"}: example: Modifying data
2024-11-27T04:27:18.229091Z DEBUG do_something{path="file.txt" data="[1, 2, 3]" new_data="[2, 3, 4]"}: example: Changed data
2024-11-27T04:27:18.229355Z  WARN do_something{path="file.txt" data="[1, 2, 3]" new_data="[2, 3, 4]"}:write_to_a_file{path=/canonicalized/file.txt}: example: Failed to write to file: Permission denied (os error 13)
2024-11-27T04:27:18.229392Z  INFO do_something_else: example: Doing something else
2024-11-27T04:27:18.229636Z ERROR do_something_else:write_to_a_file{path=/canonicalized/other_file.txt}: example: Failed to write to file: Permission denied (os error 13)

tracing, info

2024-11-27T04:27:23.281684Z  INFO do_something{path="file.txt"}: example: Doing something
2024-11-27T04:27:23.282000Z  WARN do_something{path="file.txt" data="[1, 2, 3]" new_data="[2, 3, 4]"}:write_to_a_file{path=/canonicalized/file.txt}: example: Failed to write to file: Permission denied (os error 13)
2024-11-27T04:27:23.282041Z  INFO do_something_else: example: Doing something else
2024-11-27T04:27:23.282232Z ERROR do_something_else:write_to_a_file{path=/canonicalized/other_file.txt}: example: Failed to write to file: Permission denied (os error 13)

tracing, warn

2024-11-27T04:38:20.053579Z  WARN do_something{path="file.txt" data="[1, 2, 3]" new_data="[2, 3, 4]"}: example: Failed to write to file: Permission denied (os error 13)
2024-11-27T04:38:20.053930Z ERROR do_something_else: example: Failed to write to file: Permission denied (os error 13)