add support for propagating backtraces on fatal errors.

Author: raulk

fvm/src/call_manager/backtrace.rs

@@ -7,7 +7,9 @@ use fvm_shared::{ActorID, MethodNum};
 
 use crate::kernel::SyscallError;
 
-/// A call backtrace records _why_ an actor exited with a specific error code.
+/// A call backtrace records the actors an error was propagated through, from
+/// the moment it was emitted. The original error is the _cause_. Backtraces are
+/// useful for identifying the root cause of an error.
 #[derive(Debug, Default, Clone)]
 pub struct Backtrace {
     /// The actors through which this error was propagated from bottom (source) to top.
@@ -34,22 +36,35 @@ impl Backtrace {
         self.frames.is_empty() && self.cause.is_none()
     }
 
-    /// Clear the backtrace. This should be called:
-    ///
-    /// 1. Before all syscalls except "abort"
-    /// 2. After an actor returns with a 0 exit code.
+    /// Clear the backtrace.
     pub fn clear(&mut self) {
         self.cause = None;
         self.frames.clear();
     }
 
-    /// Set the backtrace cause. If there is an existing backtrace, this will clear it.
-    pub fn set_cause(&mut self, cause: Cause) {
+    /// Begins a new backtrace. If there is an existing backtrace, this will clear it.
+    ///
+    /// Note: Backtraces are populated _backwards_. That is, a frame is inserted
+    /// every time an actor returns. That's why `begin()` resets any currently
+    /// accumulated state, as once an error occurs, we want to track its
+    /// propagation all the way up.
+    pub fn begin(&mut self, cause: Cause) {
         self.cause = Some(cause);
         self.frames.clear();
     }
 
+    /// Sets the cause of a backtrace.
+    ///
+    /// This is useful to stamp a backtrace with its cause after the frames
+    /// have been collected, such as when we ultimately handle a fatal error at
+    /// the top of its propagation chain.
+    pub fn set_cause(&mut self, cause: Cause) {
+        self.cause = Some(cause);
+    }
+
     /// Push a "frame" (actor exit) onto the backtrace.
+    ///
+    /// This should be called every time an actor exits.
     pub fn push_frame(&mut self, frame: Frame) {
         self.frames.push(frame)
     }
@@ -83,9 +98,8 @@ impl Display for Frame {
     }
 }
 
-/// The ultimate "cause" of a failed message.
 #[derive(Clone, Debug)]
-pub struct Cause {
+pub struct SyscallCause {
     /// The syscall "module".
     pub module: &'static str,
     /// The syscall function name.
@@ -96,23 +110,64 @@ pub struct Cause {
     pub message: String,
 }
 
+#[derive(Clone, Debug)]
+pub struct FatalCause {
+    /// The error message from the error.
+    pub error_msg: String,
+    /// The original cause that initiated the error chain.
+    pub root_cause: String,
+    /// The backtrace, captured if the relevant
+    /// [environment variables](https://doc.rust-lang.org/std/backtrace/index.html#environment-variables) are enabled.
+    pub backtrace: String,
+}
+
+/// The ultimate "cause" of a failed message.
+#[derive(Clone, Debug)]
+pub enum Cause {
+    /// The original cause was a syscall error.
+    Syscall(SyscallCause),
+    /// The original cause was a fatal error.
+    Fatal(FatalCause),
+}
+
 impl Cause {
-    pub fn new(module: &'static str, function: &'static str, err: SyscallError) -> Self {
-        Self {
+    /// Records a failing syscall as the cause of a backtrace.
+    pub fn from_syscall(module: &'static str, function: &'static str, err: SyscallError) -> Self {
+        Self::Syscall(SyscallCause {
             module,
             function,
             error: err.1,
             message: err.0,
-        }
+        })
+    }
+
+    /// Records a fatal error as the cause of a backtrace.
+    pub fn from_fatal(err: anyhow::Error) -> Self {
+        Self::Fatal(FatalCause {
+            error_msg: err.to_string(),
+            root_cause: err.root_cause().to_string(),
+            backtrace: err.backtrace().to_string(),
+        })
     }
 }
 
 impl Display for Cause {
     fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
-        write!(
-            f,
-            "{}::{} -- {} ({}: {})",
-            self.module, self.function, &self.message, self.error as u32, self.error,
-        )
+        match self {
+            Cause::Syscall(cause) => {
+                write!(
+                    f,
+                    "{}::{} -- {} ({}: {})",
+                    cause.module, cause.function, &cause.message, cause.error as u32, cause.error,
+                )
+            }
+            Cause::Fatal(msg) => {
+                write!(
+                    f,
+                    "[FATAL] Root cause: {}, Stacktrace: {}",
+                    msg.root_cause, msg.backtrace
+                )
+            }
+        }
     }
 }

fvm/src/call_manager/default.rs

@@ -393,7 +393,7 @@ where
                 Ok(value) => Ok(InvocationResult::Return(value)),
                 Err(abort) => {
                     if let Some(err) = last_error {
-                        cm.backtrace.set_cause(err);
+                        cm.backtrace.begin(err);
                     }
 
                     let (code, message, res) = match abort {

fvm/src/executor/default.rs

@@ -130,24 +130,29 @@ where
                     ErrorNumber::Forbidden => ExitCode::SYS_ASSERTION_FAILED,
                 };
 
-                backtrace.set_cause(backtrace::Cause::new("send", "send", err));
+                backtrace.begin(backtrace::Cause::from_syscall("send", "send", err));
                 Receipt {
                     exit_code,
                     return_data: Default::default(),
                     gas_used,
                 }
             }
-            Err(ExecutionError::Fatal(e)) => {
-                // Annotate the error with the message context.
-                let _err = e.context(format!(
-                    "[from={}, to={}, seq={}, m={}, h={}] fatal error",
-                    msg.from,
-                    msg.to,
-                    msg.sequence,
-                    msg.method_num,
-                    self.context().epoch
-                ));
-                // TODO backtrace
+            Err(ExecutionError::Fatal(err)) => {
+                // // Annotate the error with the message context.
+                // let err = {
+                //     let backtrace = String::from("foo"); //e.backtrace().to_string();
+                //                                          // e.context(format!(
+                //                                          //     "[from={}, to={}, seq={}, m={}, h={}] fatal error; backtrace: {}",
+                //                                          //     msg.from,
+                //                                          //     msg.to,
+                //                                          //     msg.sequence,
+                //                                          //     msg.method_num,
+                //                                          //     self.context().epoch,
+                //                                          //     backtrace,
+                //                                          // ))
+                // };
+                backtrace.set_cause(backtrace::Cause::from_fatal(err));
+                // Produce a receipt that consumes the full gas amount.
                 Receipt {
                     exit_code: ExitCode::SYS_ASSERTION_FAILED,
                     return_data: Default::default(),

fvm/src/syscalls/bind.rs

@@ -141,7 +141,7 @@ macro_rules! impl_bind_syscalls {
                             Ok(Err(err)) => {
                                 let code = err.1;
                                 log::trace!("syscall {}::{}: fail ({})", module, name, code as u32);
-                                data.last_error = Some(backtrace::Cause::new(module, name, err));
+                                data.last_error = Some(backtrace::Cause::from_syscall(module, name, err));
                                 Ok(code as u32)
                             },
                             Err(e) => Err(e.into()),
@@ -163,7 +163,7 @@ macro_rules! impl_bind_syscalls {
                         if (ret as u64) > (memory.len() as u64)
                             || memory.len() - (ret as usize) < mem::size_of::<Ret::Value>() {
                             let code = ErrorNumber::IllegalArgument;
-                            data.last_error = Some(backtrace::Cause::new(module, name, SyscallError(format!("no space for return value"), code)));
+                            data.last_error = Some(backtrace::Cause::from_syscall(module, name, SyscallError(format!("no space for return value"), code)));
                             return Ok(code as u32);
                         }
 
@@ -178,7 +178,7 @@ macro_rules! impl_bind_syscalls {
                             Ok(Err(err)) => {
                                 let code = err.1;
                                 log::trace!("syscall {}::{}: fail ({})", module, name, code as u32);
-                                data.last_error = Some(backtrace::Cause::new(module, name, err));
+                                data.last_error = Some(backtrace::Cause::from_syscall(module, name, err));
                                 Ok(code as u32)
                             },
                             Err(e) => Err(e.into()),

testing/integration/tests/lib.rs

@@ -206,6 +206,8 @@ fn out_of_stack() {
 
 #[test]
 fn backtraces() {
+    // Note: this test **does not actually assert anything**, but it's useful to
+    // let us peep into FVM backtrace generation under different scenarios.
     const WAT_ABORT: &str = r#"
     (module
       ;; ipld::open
@@ -300,8 +302,7 @@ fn backtraces() {
         .execute_message(message, ApplyKind::Explicit, 100)
         .unwrap();
 
-    println!("abort backtrace:");
-    dbg!(res.failure_info);
+    println!("abort backtrace: {}", res.failure_info.unwrap());
 
     // Send message
     let message = Message {
@@ -320,8 +321,7 @@ fn backtraces() {
         .execute_message(message, ApplyKind::Explicit, 100)
         .unwrap();
 
-    println!("fatal backtrace:");
-    dbg!(res.failure_info);
+    println!("fatal backtrace: {}", res.failure_info.unwrap());
 }
 
 #[derive(Default)]