error-stack: beginner question "confusing backtrace"

[kwinz]

Hi!

I have troubles deciphering the backtraces / error messages that either logging or unwrapping error-stack's errors gives me.
Here is an example:

1. For testing I purposely create a new IOError Err(std::io::Error::new(std::io::ErrorKind::NotConnected, "Simulated Broken connection"))
2. and attach it a printable error cause and return/propagate it with .attach_printable("Can't flush serial buffer")?;
3. Then I change context from an IOError to my own library's error type and give it another printable error explanation and propagate to the caller with write(command, serial).change_context(AtError::SerialIOError).attach_printable("Can't execute AT command")?;
4. In the caller I attach yet another printable explanation and pass it with execute_at_command("AT\\Q3\r", &mut serial).attach_printable("Can't set flow control.")?;
5. Finally I unwrap the error in main (and panic, or log it - the message is basically the same) in main.rs in line 16 giving me this output:

To me this is completely unintuitive. It does not align how I mentally imagine this to happen chronologically.

I am relatively new to both Rust and error-stack so please excuse if I am missing something obvious!

Is this how it is intended to look? Am I using this library wrong? Do I have to create a new Error Enum for every single function that the error passes through and change context each time I propagate?

[TimDiekmann]

Hi @kwinz

I am relatively new to both Rust and error-stack so please excuse if I am missing something obvious!

I'm sure you're not the only one with this question and others will thank you for asking it. You're not missing something obvious!

---

error-stack follows the principle that you have errors/contexts (you can see them as interchangeable). These can have additional attachments to provide further information. Errors typically have a source - a reason why they failed (the official Error trait uses the source method for that). This source may be interesting for the consumer of the function (such as an end user or a library) to handle the error.

For the consumer of a function, the interesting thing is that the operation did not succeed. In your example, you tried to execute an AT command, that failed. This is the reason the contexts are listed first. Attachments add more information on that context, things that either help to understand the context or can be used later to handle the error properly. Further, the source(s) of the error is listed. This is the reason why your error is misleading: That you tried to execute an AT command is not just purely additive information, it's the context of your error. What you want to see is something like "Could not execute AT command" as a top-level message - that is your actual error. That failed because you had an IO error. The IO error happened because you want to execute a command. (Rule of thumb: An IO error is almost never a top-level error, there is (almost) always more context for what the IO error is the reason for (e.g. you tried opening a file, but it failed because of an IO error.)

The ordering of the messages in error-stack is very carefully chosen and if you follow the principles of contexts/errors vs attachment you will get the information in the order you are interested in it. Each error-stack Report has a "current context" (that's the T in Report<T>). If you attach information to the Report, you're attaching it to that context, so that information is printed next to the actual context message (= error message).

To summarize: what you probably want is an additional context (maybe AtError::Execute or whatever makes the most sense in your use case). The source of that is the IO error. You may want to add information to both contexts. This directly leads to your next question:

Do I have to create a new Error Enum for every single function that the error passes through and change context each time I propagate?

It depends (as usual 😆).

• Do you have more contextual information? Yes, create an error variant (an enum or a struct, depending what makes most sense for you). That variant will add a layer of errors in your Report and help split the final message into logical pieces. this is your case
• Does your function provide no further information? You may want to reuse the context.

Generally, error-stack requires to add a bunch of new variants (thiserror or any other crates which derive Display help defining these). But in return, you will get a logical chain of events and if the contexts are chosen correctly the chronological order should also match. If that is not the case you probably mixed an attachment and a context. The crate forces you to think about your errors and this is also the main reason why I implemented the crate in the first place. If you defined your variants you even get a decent compile time validation if you properly handle your errors and the function signatures represent the possible outcome.

I hope that helps to understand the idea a bit better. Please feel free to ask if you have any other questions. Also, we're always happy to improve the documentation of error-stack.

[kwinz]

First of all thank you very much for the quick and elaborate and kind reply! It really helped a lot!

You make a good point, that I should be thinking whether I want to split the Errors (structs or enum variants) by the top action that failed (in my example that would be initializing or creating a new SerialAt struct. Right now I am splitting them by how the caller of my library is supposed to handle them! AtError::ModemError variants originate from the modem (allowing the caller to take corrective action such as unlocking SIM PIN before using the modem), and AtError::SerialIOError variants originate from the connection to the modem (allowing other corrective action). But you are right, I should probably change that and create an AtError::Execute or AtError::InitializationFailure instead!

The issue that I have is really not so much with error-stack. But with how error-stack prints the events to the log if I try to unwrap its error. What irks me in particular is the order it prints the events: 5,3,4,1,2.

I actually had first implemented AtError with thiserror annotations, but when I noticed the unnatural order in the log, I implemented AtError by hand and removed the thiserror library, in hopes this would improve the output, but it didn't.

I now changed all error handling to eyre just to see how that would look like, and now I get the most gorgeous trace (color removed):

[2023-09-25T12:44:28Z DEBUG sms_alert_plus::serial_at_modem] Port available: COM5
[2023-09-25T12:44:28Z DEBUG sms_alert_plus::serial_at_modem] Port available: COM6
[2023-09-25T12:44:28Z DEBUG sms_alert_plus::serial_at_modem] Receiving data on COM6 at 9600 baud:
[2023-09-25T12:44:28Z ERROR sms_alert_plus] Can't open new serial AT modem.
The application panicked (crashed).
Message:  called `Result::unwrap()` on an `Err` value: 
   0: Can't open new serial AT modem.
   1: Can't set flow control.
   2: Can't execute AT command
   3: Can't flush serial buffer
   4: Simulated Broken connection

Location:
   src\serial_at_modem\mod.rs:151

  ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ BACKTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
                                ⋮ 11 frames hidden ⋮
  12: sms_alert_plus::serial_at_modem::write<unknown>
      at ...\user\Documents\sms-alert-plus\src\serial_at_modem\mod.rs:147
  13: sms_alert_plus::serial_at_modem::execute_at_command<unknown>
      at ...\user\Documents\sms-alert-plus\src\serial_at_modem\mod.rs:166
  14: sms_alert_plus::serial_at_modem::new<unknown>
      at ...\user\Documents\sms-alert-plus\src\serial_at_modem\mod.rs:87
  15: sms_alert_plus::main<unknown>
      at ...\user\Documents\sms-alert-plus\src\main.rs:18
  16: core::ops::function::FnOnce::call_once<void (*)(),tuple$<> ><unknown>
      at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be\library\core\src\ops\function.rs:250
                                ⋮ 14 frames hidden ⋮

Run with COLORBT_SHOW_HIDDEN=1 environment variable to disable frame filtering.
Run with RUST_BACKTRACE=full to include source snippets.
Location: src\main.rs:24

  ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ BACKTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
                                ⋮ 14 frames hidden ⋮
  15: enum2$<core::result::Result<sms_alert_plus::serial_at_modem::MySerial,eyre::Report> >::unwrap<sms_alert_plus::serial_at_modem::MySerial,eyre::Report><unknown>
      at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be\library\core\src\result.rs:1076
  16: sms_alert_plus::main<unknown>
      at ...\user\Documents\sms-alert-plus\src\main.rs:24
  17: core::ops::function::FnOnce::call_once<void (*)(),tuple$<> ><unknown>
      at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be\library\core\src\ops\function.rs:250
                                ⋮ 14 frames hidden ⋮

Run with COLORBT_SHOW_HIDDEN=1 environment variable to disable frame filtering.
Run with RUST_BACKTRACE=full to include source snippets.

This makes so much sense to me:

   0: Can't open new serial AT modem.
   1: Can't set flow control.
   2: Can't execute AT command
   3: Can't flush serial buffer
   4: Simulated Broken connection

compared to

thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: SerialIOError
├╴at src\serial_at_modem\mod.rs:168:10
├╴Can't execute AT command
├╴Can't set flow control.
│
╰─▶ Simulated Broken connection
    ├╴at src\serial_at_modem\mod.rs:152:6
    ├╴backtrace (1)
    ╰╴Can't flush serial buffer

eyre output matches my expectation of there was a problem 1. creating a new AT modem struct, caused by 2. new()/init() not being able to initialize flow control caused by the 3. at command failing to set flow control, caused by the 4. serial buffer containing the command to set flow control not being able to get flushed caused by 5. the connection being broken.

And below that I get a super pretty, redacted BACKTRACE with exactly the relevant lines of where each of those events happened.

  12: sms_alert_plus::serial_at_modem::write<unknown>
      at ...\user\Documents\sms-alert-plus\src\serial_at_modem\mod.rs:147
  13: sms_alert_plus::serial_at_modem::execute_at_command<unknown>
      at  ...\user\Documents\sms-alert-plus\src\serial_at_modem\mod.rs:166
  14: sms_alert_plus::serial_at_modem::new<unknown>
      at  ...\user\Documents\sms-alert-plus\src\serial_at_modem\mod.rs:87
  15: sms_alert_plus::main<unknown>
      at  ...\user\Documents\sms-alert-plus\src\main.rs:18
  16: core::ops::function::FnOnce::call_once<void (*)(),tuple$<> ><unknown>
      at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be\library\core\src\ops\function.rs:250

The issue I have with eyre is that it's really not designed for libraries. It's designed to be used when you don't care about having your own error types.
It doesn't have a notion of change_context() like error-stack has. Once I have wrapped an IOError from the OS with eyre::Report and attached an error cause, an advice or some other attachment that eyre supports, I can not turn it into an AtError Context any more, like I can with error-stack. So despite how pretty and debuggable the color-eyre crate is, it's not really practical for me. I would like to keep my own error types AND attach context at the same time.

If that is not the case you probably mixed an attachment and a context.

Am I not supposed to mix attached printables and switching context?

Thanks again in advance! And sorry to include so many implementation details of my error-stack use in this thread, I hope it helps illustrate my problem.

[TimDiekmann]

I produced a minimal example to simulate your behavior. To make it a little bit easier to deal with the different error kinds I used thiserror and a single enum:

#[derive(Debug, thiserror::Error)]
pub enum SerialError {
    #[error("Can't open new serial AT modem.")]
    Open,
    #[error("Can't set flow control.")]
    FlowControl,
    #[error("Can't execute AT command.")]
    AtCommand,
    #[error("Can't flush serial buffer.")]
    Flush,
    #[error("Simulated Broken connection.")]
    Broken,
}

Given your description of the causes:

• creating a new AT modem struct,
• caused by new()/init() not being able to initialize flow control
• caused by the at command failing to set flow control
• caused by the serial buffer containing the command to set flow control not being able to get flushed
• caused by the connection being broken.

this means that you start with Broken as the most inner error and bubbling up to Open:

fn main() -> error_stack::Result<(), SerialError> {
    Err(error_stack::Report::new(SerialError::Broken)
        .change_context(SerialError::Flush)
        .change_context(SerialError::AtCommand)
        .change_context(SerialError::FlowControl)
        .change_context(SerialError::Open))
}

which results in the same order as eyre does:

Error: Can't open new serial AT modem.
├╴at examples/ordering.rs:20:10
│
├─▶ Can't set flow control.
│   ╰╴at examples/ordering.rs:19:10
│
├─▶ Can't execute AT command.
│   ╰╴at examples/ordering.rs:18:10
│
├─▶ Can't flush serial buffer.
│   ╰╴at examples/ordering.rs:17:10
│
╰─▶ Simulated Broken connection.
    ╰╴at examples/ordering.rs:16:9

But this assumes that each of these are in a separate context, thus you need an error variant for these (again, for simplicity I did this with an enum).

You are correct, that when replacing some change_context with attach_printable you will get a different order. Let's assume the most inner error is Broken, that's the root cause, so you're starting again with Report::new(SerialError::Broken). Then you're attaching a few more information, such as SerialError::Flush and SerialError::AtCommand to give the user more information what exactly has a broken connection. So your function may call:

fn main() -> error_stack::Result<(), SerialError> {
    Err(error_stack::Report::new(SerialError::Broken)
        .attach_printable(SerialError::Flush)
        .attach_printable(SerialError::AtCommand))
}

which results in

Error: Simulated Broken connection.
├╴at examples/ordering.rs:16:9
├╴Can't flush serial buffer.
╰╴Can't execute AT command.

If you now change the context to a different error, a Flush error, you will call .change_context on that Report, so

fn main() -> error_stack::Result<(), SerialError> {
    Err(error_stack::Report::new(SerialError::Broken)
        .attach_printable(SerialError::Flush)
        .attach_printable(SerialError::AtCommand)
        .change_context(SerialError::FlowControl))
}

will result in

Error: Can't set flow control.
├╴at examples/ordering.rs:19:10
│
╰─▶ Simulated Broken connection.
    ├╴at examples/ordering.rs:16:9
    ├╴Can't flush serial buffer.
    ╰╴Can't execute AT command.

Changing the context here again, will then result in

Error: Can't open new serial AT modem.
├╴at examples/ordering.rs:20:10
│
├─▶ Can't set flow control.
│   ╰╴at examples/ordering.rs:19:10
│
╰─▶ Simulated Broken connection.
    ├╴at examples/ordering.rs:16:9
    ├╴Can't flush serial buffer.
    ╰╴Can't execute AT command.

Note, that I did not change the calling order, just the methods used. Generally, the order of attachment is exactly in the order in which they are attached to the context.

error-stack's distinction between contexts and attachments is a concept that does not exist in eyre or anyhow. If you want to translate code from eyre or anyhow directly to error-stack everything would be an attachment (something, which is not possible with error-stack). To mitigate this the closest translation would be to only use the outermost error as context and everything else as attachment, so the following eyre code:

fn main() -> eyre::Result<()> {
    Err(eyre::Report::new(SerialError::Broken))
        .wrap_err(SerialError::Flush)
        .wrap_err(SerialError::AtCommand)
        .wrap_err(SerialError::FlowControl)
        .wrap_err(SerialError::Open)
}

uses Open as context but everything else as attachment. As a Report always requires a context, this is not easily constructible in error-stack as you know the context too late. Btw, if you want to migrate from eyre or anyhow to error-stack, we provide IntoReportCompat so if you call .into_report on the aboveeyre::Result<T> you will get this Result<T, error_stack::Report<eyre::Report>>:

Error: Can't open new serial AT modem.
├╴at examples/ordering.rs:24:10
├╴Can't set flow control.
├╴Can't execute AT command.
├╴Can't flush serial buffer.
╰╴Simulated Broken connection.

compared to the output from eyre

Error: Can't open new serial AT modem.

Caused by:
   0: Can't set flow control.
   1: Can't execute AT command.
   2: Can't flush serial buffer.
   3: Simulated Broken connection.

but generally it's true that eyre or anyhow are not suited for libraries and this was one of the main motivation factors to write error-stack. Also, with error-stack it's possible on a nightly compiler to use the provider-API to return old contexts and attachments. Without a nightly compiler you can use down casting similar to the approach you have available in eyre and anyhow.

---

Regarding the backtrace output: We did not put any effort to format the backtrace, it's simply the one returned by Backtrace::capture(). It's possible to override the behavior of that (and any other attachment type) and providing a more helpful backtrace is on my list I like to have, especially as in async contexts the backtrace is extremely verbose, but I didn't get to that. As an alternative, we also support SpanTraces but that requires more setup.

---

I hope this is helpful to you and illustrates how and why the output of error-stack is printed the way it is. Generally contexts are printed from the most outer context to the root context (same as in eyre and anyhow) and attachments are printed in the order in which they are attached to it (which is the reversed order of eyre and anyhow). You can see attachments as list of things you're appending. It's implemented differently but you can think of it as report.attachments.push.

[kwinz]

Again thank you so much for the amazing answer!

Error: Can't open new serial AT modem.
├╴at examples/ordering.rs:20:10
│
├─▶ Can't set flow control.
│   ╰╴at examples/ordering.rs:19:10
│
╰─▶ Simulated Broken connection.
    ├╴at examples/ordering.rs:16:9
    ├╴Can't flush serial buffer.
    ╰╴Can't execute AT command.

One last question: Is it possible for me to somehow hook into error-stack and customize how Contexts/Reports are printed?

Can I customize in which order the printables output is concatenated or how the stack gets redacted? As far as I can tell from the documentation this is not part of the library right now? Or is it?

As far as I know in Rust I can not just override the implementation of Display trait for Context, right?
Maybe I can into into my own Error type and then implement the Display trait differently there? The frames in the Report struct seem to be public only for the parent module.

[TimDiekmann]

The general shape of the context cannot be changed, so things like the ordering are hardcoded. You, however, can change the entries itself and the functionality is described in the fmt module.