Log the entire error chain when sled-agent cannot communicate with nexus

[emunn13]

When sled-agent fails to communicate with Nexus, it doesn't log the underlying error.

Example:

01:13:21.478Z WARN SledAgent: Received Error from Nexus for Get request: Communication Error: error sending request for url (http://_nexus._tcp.control-plane.oxide.internal:12221/sled-agents/<SLED_ID>)
    file = sled-agent/src/nexus.rs:530
    sled_id = <SLED_ID>

This issue is to ask for logging the whole error chain.

[jgallagher]

#9803 logs the full chain for this specific error message (and several others), but we ought to make similar changes to every log message throughout the codebase that currently emits errors using their display or debug impls, since those won't include inner errors.

[sruggier]

I've been thinking about this a bit more today, and concluded there's no graceful way to carry out this transition piecemeal:

• Each error must be handled in a consistent way in all of the places where it gets logged.
• If all of the handlers of a given Error are logging it using the Display trait, they have to be switched over to log the full chain before switching any of its variants to use #[source] or #[from], otherwise the logging will get more lossy as duplicate log output is removed from each variant.
• Once an error's full source chain is being logged, the duplication of source errors in Display implementations has to be removed at the same time, otherwise log output will regress in the other way (duplicate errors). This applies transitively to source errors, forcing the whole chain to be converted from the top down, in one step.

Taken together, these constraints create a requirement to update an error's handlers and its sources at the same time as the error itself, or face a temporary regression. Applied transitively, it's impossible to touch any of them without touching all of the error types that have a direct or indirect source relationship with that one, in either direction.

The duplication of error messages is less harmful to troubleshooting than losing the source chain altogether, though, so I think it's reasonable to try to approach the problem from the top down, and tolerate some temporary duplication. Better than trying to do it in one step, not merging anything for a potentially long time, wasting time on conflicts along the way, and not gaining any benefit until all of the changes are done.

Does that sound reasonable? Am I missing anything?

[jgallagher]

there's no graceful way to carry out this transition

Yes, this is a pretty accurate summary :(

Taken together, these constraints create a requirement to update an error's handlers and its sources at the same time as the error itself, or face a temporary regression.

A quibble here is that it's very hard to tell if partial changes in this area would introduce a temporary regressions, improve the situation, or have no effect at all. It's very dependent on how the error types involved are currently defined, how the log sites display them, and what partial changes we land.

The duplication of error messages is less harmful to troubleshooting than losing the source chain altogether, though, so I think it's reasonable to try to approach the problem from the top down, and tolerate some temporary duplication. Better than trying to do it in one step, not merging anything for a potentially long time, wasting time on conflicts along the way, and not gaining any benefit until all of the changes are done.

This pretty closely matches my disposition. I think the path of least harm is:

1. Update log / stringification sites to display the entire error chain. For errors that don't use #[source]/#[from] at all, this will make no changes. For errors that use #[source]/#[from] and include the next error in their Display impl, we'll introduce doublespeak, which is not great (but any path here has some pain, as you noted). For correct error types, this will make the log / stringification sites correct.
2. Update all the error types to correctly define their sources without duplicating them in their Display impls.

In cases where we can do both together that's great, but that will require somewhat larger chunks of work to land at once (e.g., the WIP branch I pointed you at I believe basically does "item 1 within sled-agent", without doing any of item 2 or any logging in other crates, and is still approaching large enough that I'd rather land it as it is without adding more to it).

[sruggier]

A quibble here is that it's very hard to tell if partial changes in this area would introduce a temporary regressions, improve the situation, or have no effect at all. It's very dependent on how the error types involved are currently defined, how the log sites display them, and what partial changes we land.

No quibbles from me: I think it's possible, but I've been trying to do it, and it's definitely harder than it should be. It turns out rust-analyzer doesn't quite find all references, perhaps confused by the macros involved, and recursively auditing the callers of every function that returns a particular error type takes too much time, if one is going to have to do it for each error type.

I'm going to try to find an easy way to make it the compiler's problem, either through an easy temporary change to each error type, or by adding a hacked-up version of thiserror as a local dependency. If an error type no longer implements Display, then every line of code that needs to be updated should become a build error.

If successful, then I can approach this one Error type at a time, which should make the changes less disruptive. If you land any related changes, though, I'm happy to rebase mine.

[sruggier]

Removing the Display implementation works great within the same crate. Unfortunately, it can't highlight usages in other crates, because it prevents the crate from building (because Display is required by std::Error). I also considered using the #[deprecated] attribute on an implementation of Display, but the language doesn't allow that.

Instead, the closest hack I could find was to make a given Error type private outside its crate, using pub (crate), which then causes all usages outside the crate to be visible. That requires more manual auditing than if I'd managed to only trigger errors on usages of to_string, but it's more reliable than rust-analyzer, at least. With the check times involved, it may still require too much time to be worthwhile, but I'm not sure yet. I hadn't yet given rust-analyzer its own target directory, so I'm doing that now, and it may be enough to make this approach tolerable.

In the long term, this makes me want to spend some time getting familiar with rust-analyzer internals, but for now I think I have to settle for the status quo.

[sruggier]

The pub (crate) hack seems to be robust enough: it's giving me hits like this:

error: type `omicron_sled_agent::bootstrap::server::StartError` is private
  --> sled-agent/src/bin/sled-agent.rs:78:26
   |
78 |               let server = bootstrap_server::Server::start(config)
   |  __________________________^
79 | |                 .await
80 | |                 .map_err(|err| CmdError::Failure(anyhow!(err)))?;
   | |_______________________________________________________________^ private type

Rust analyzer seems to miss this call site when I try to find all references, and it would be impossible to grep for directly, so I'd otherwise have had to audit every caller of every function that returns StartError, which is a bit of a non-starter.

With rust-analyzer using its own target directory, wait times are pretty tolerable, so I'm going to continue with this approach and see how far I can get.

[sruggier]

What I've done so far is already more significant what was in the first PR, so I've made another. I'm going to keep rebasing and adding fixes to it until someone either reviews it, or triggers test execution. At that point I'll defer future changes for a later PR, so as not to interrupt the CI pipeline or make it harder to review.

[sruggier]

@jgallagher I've started writing a clippy lint for this. It's still very work-in-progress, and the diagnostics are absolutely minimal as of now, but it has reached a point where it's approaching being useful, and it looks like it'll probably be possible to make it do what it needs to do in order to be worth doing, so it felt like a good time to mention it here.

It currently triggers on all calls to to_string on an error type, and also all cases where an error is Display formatted in a call to one of the standard library formatting macros, like format!, write!, println!. It doesn't trigger yet for thiserror expansions, uses of Display with the slog macros, or uses of Debug.

I plan to fix those shortcomings, add a couple of configuration entries to make it generic enough to be useful, regardless of what kind of error handling libraries a codebase uses, backport it to the toolchain omicron is pinned to, and then use it to continue doing the cleanup I was doing by hand last week.

I've pushed a working version to this branch. It can be tested on the omicron codebase by cloning it and following the Install from source instructions in clippy's documentation. In other words, by running cargo dev setup toolchain, and then calling it from omicron with cargo +clippy clippy.

[sruggier]

Sorry if this is too verbose and off-topic for this particular issue, but as a bit of a status update, it turns out that the approach I started with there won't work, in its current form, to try to lint inside macro expansions, because clippy seems to deliberately filter FormatArgs expressions from the cache it builds during the early pass, if they came from a proc macro expansion.

I probably can work around that, though, with a bit of extra effort.

Edit (to avoid generating more notification noise):
the lint now triggers on everything, including slog macros and thiserror derives. I'll see how much polish I can add on top, now that it works at some level.

[sruggier]

I've pushed a backported version of the lint to a separate branch.

When I run it on the omicron codebase, it currently triggers 1300 times on 295 separate types of error. Some of those will involve error types that are safe to format, such as types that don't have sources, or types that emit the whole chain with whatever format options are given. I'm going to explore what configuration and additional filtering I can implement to be able to weed those out.

On the other hand, it also includes individual offending attributes from thiserror derives, which brings me such joy to look at:

warning: use of `Display` formatting on an error type (`illumos_utils::vmm_reservoir::Error`)
  --> sled-agent/src/vmm_reservoir.rs:19:13
   |
17 | #[derive(thiserror::Error, Debug)]
   |          ---------------- in this derive macro expansion
18 | pub enum Error {
19 |     #[error("Failed to create reservoir: {0}")]
   |             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
   |
   = help: for further information visit https://rust-lang.github.io/rust-clippy/master/index.html#error_format_without_sources
   = note: this warning originates in the macro `$crate::format_args` which comes from the expansion of the derive macro `thiserror::Error` (in Nightly builds, run with -Z macro-backtrace for more info)

One can get a count by type with something like this:

cargo +clippy clippy 2>&1 | grep 'on an error type' | cut -f4 -d\` | sort | uniq -c | sort -nr

[sruggier]

I updated the lint implementation to ignore Error types that don't define a source method (if there are no sources, they can be safely formatted without losing source info), and now it only emits 704 warnings on 166 types.

I still plan to add some configuration options to it, but it's getting pretty tempting to take a break from that and do some cleanup.