Merge pull request #412 from filecoin-project/asr/exec-trace

Implement execution traces for the FVM

Author: arajasek

fvm/src/call_manager/default.rs

@@ -4,17 +4,19 @@ use fvm_ipld_encoding::{RawBytes, DAG_CBOR};
 use fvm_shared::actor::builtin::Type;
 use fvm_shared::address::{Address, Protocol};
 use fvm_shared::econ::TokenAmount;
-use fvm_shared::error::ExitCode;
+use fvm_shared::error::{ErrorNumber, ExitCode};
 use fvm_shared::version::NetworkVersion;
 use fvm_shared::{ActorID, MethodNum, METHOD_SEND};
 use num_traits::Zero;
 
 use super::{Backtrace, CallManager, InvocationResult, NO_DATA_BLOCK_ID};
 use crate::call_manager::backtrace::Frame;
+use crate::call_manager::FinishRet;
 use crate::gas::GasTracker;
-use crate::kernel::{ClassifyResult, ExecutionError, Kernel, Result};
+use crate::kernel::{ClassifyResult, ExecutionError, Kernel, Result, SyscallError};
 use crate::machine::Machine;
 use crate::syscalls::error::Abort;
+use crate::trace::{ExecutionEvent, ExecutionTrace, SendParams};
 use crate::{account_actor, syscall_error};
 
 /// The default [`CallManager`] implementation.
@@ -40,6 +42,8 @@ pub struct InnerDefaultCallManager<M> {
     call_stack_depth: u32,
     /// The current chain of errors, if any.
     backtrace: Backtrace,
+    /// The current execution trace.
+    exec_trace: ExecutionTrace,
 }
 
 #[doc(hidden)]
@@ -73,6 +77,7 @@ where
             num_actors_created: 0,
             call_stack_depth: 0,
             backtrace: Backtrace::default(),
+            exec_trace: vec![],
         })))
     }
 
@@ -87,6 +92,16 @@ where
     where
         K: Kernel<CallManager = Self>,
     {
+        if self.machine.context().tracing {
+            self.exec_trace.push(ExecutionEvent::Call(SendParams {
+                from,
+                to,
+                method,
+                params: params.clone(),
+                value: value.clone(),
+            }));
+        }
+
         // We check _then_ set because we don't count the top call. This effectivly allows a
         // call-stack depth of `max_call_depth + 1` (or `max_call_depth` sub-calls). While this is
         // likely a bug, this is how NV15 behaves so we mimic that behavior here.
@@ -108,6 +123,20 @@ where
         self.call_stack_depth += 1;
         let result = self.send_unchecked::<K>(from, to, method, params, value);
         self.call_stack_depth -= 1;
+
+        if self.machine.context().tracing {
+            self.exec_trace.push(ExecutionEvent::Return(match result {
+                Err(ref e) => Err(match e {
+                    ExecutionError::OutOfGas => {
+                        SyscallError::new(ErrorNumber::Forbidden, "out of gas")
+                    }
+                    ExecutionError::Fatal(_) => SyscallError::new(ErrorNumber::Forbidden, "fatal"),
+                    ExecutionError::Syscall(s) => s.clone(),
+                }),
+                Ok(ref v) => Ok(v.clone()),
+            }));
+        }
+
         result
     }
 
@@ -124,12 +153,19 @@ where
         res
     }
 
-    fn finish(mut self) -> (i64, Backtrace, Self::Machine) {
+    fn finish(mut self) -> (FinishRet, Self::Machine) {
         let gas_used = self.gas_tracker.gas_used().max(0);
 
         let inner = self.0.take().expect("call manager is poisoned");
         // TODO: Having to check against zero here is fishy, but this is what lotus does.
-        (gas_used, inner.backtrace, inner.machine)
+        (
+            FinishRet {
+                gas_used,
+                backtrace: inner.backtrace,
+                exec_trace: inner.exec_trace,
+            },
+            inner.machine,
+        )
     }
 
     // Accessor methods so the trait can implement some common methods by default.

fvm/src/call_manager/mod.rs

@@ -11,12 +11,15 @@ use crate::state_tree::StateTree;
 use crate::Kernel;
 
 pub mod backtrace;
+
 pub use backtrace::Backtrace;
 
 mod default;
 
 pub use default::DefaultCallManager;
 
+use crate::trace::ExecutionTrace;
+
 /// BlockID representing nil parameters or return data.
 pub const NO_DATA_BLOCK_ID: u32 = 0;
 
@@ -59,8 +62,8 @@ pub trait CallManager: 'static {
         f: impl FnOnce(&mut Self) -> Result<InvocationResult>,
     ) -> Result<InvocationResult>;
 
-    /// Finishes execution, returning the gas used and the machine.
-    fn finish(self) -> (i64, backtrace::Backtrace, Self::Machine);
+    /// Finishes execution, returning the gas used, machine, and exec trace if requested.
+    fn finish(self) -> (FinishRet, Self::Machine);
 
     /// Returns a reference to the machine.
     fn machine(&self) -> &Self::Machine;
@@ -119,6 +122,7 @@ pub trait CallManager: 'static {
 }
 
 /// The result of a method invocation.
+#[derive(Clone, Debug)]
 pub enum InvocationResult {
     /// Indicates that the actor successfully returned. The value may be empty.
     Return(RawBytes),
@@ -142,3 +146,10 @@ impl InvocationResult {
         }
     }
 }
+
+/// The returned values upon finishing a call manager.
+pub struct FinishRet {
+    pub gas_used: i64,
+    pub backtrace: Backtrace,
+    pub exec_trace: ExecutionTrace,
+}

fvm/src/executor/default.rs

@@ -59,12 +59,12 @@ where
             };
 
         // Apply the message.
-        let (res, gas_used, mut backtrace) = self.map_machine(|machine| {
+        let (res, gas_used, mut backtrace, exec_trace) = self.map_machine(|machine| {
             let mut cm = K::CallManager::new(machine, msg.gas_limit, msg.from, msg.sequence);
-            // This error is fatal because it should have already been acounted for inside
+            // This error is fatal because it should have already been accounted for inside
             // preflight_message.
             if let Err(e) = cm.charge_gas(inclusion_cost) {
-                return (Err(e), cm.finish().2);
+                return (Err(e), cm.finish().1);
             }
 
             let result = cm.with_transaction(|cm| {
@@ -79,8 +79,11 @@ where
 
                 Ok(ret)
             });
-            let (gas_used, backtrace, machine) = cm.finish();
-            (Ok((result, gas_used, backtrace)), machine)
+            let (res, machine) = cm.finish();
+            (
+                Ok((result, res.gas_used, res.backtrace, res.exec_trace)),
+                machine,
+            )
         })?;
 
         // Extract the exit code and build the result of the message application.
@@ -142,7 +145,7 @@ where
                     msg.sequence,
                     msg.method_num,
                     self.context().epoch
-                )))
+                )));
             }
         };
 
@@ -153,12 +156,18 @@ where
         };
 
         match apply_kind {
-            ApplyKind::Explicit => self.finish_message(msg, receipt, failure_info, gas_cost),
+            ApplyKind::Explicit => self
+                .finish_message(msg, receipt, failure_info, gas_cost)
+                .map(|mut apply_ret| {
+                    apply_ret.exec_trace = exec_trace;
+                    apply_ret
+                }),
             ApplyKind::Implicit => Ok(ApplyRet {
                 msg_receipt: receipt,
                 failure_info,
                 penalty: TokenAmount::zero(),
                 miner_tip: TokenAmount::zero(),
+                exec_trace,
             }),
         }
     }
@@ -234,7 +243,7 @@ where
                     ExitCode::SYS_SENDER_INVALID,
                     "Sender invalid",
                     miner_penalty_amount,
-                )))
+                )));
             }
         };
 
@@ -253,7 +262,7 @@ where
                     ExitCode::SYS_SENDER_INVALID,
                     "Sender invalid",
                     miner_penalty_amount,
-                )))
+                )));
             }
         };
 
@@ -365,6 +374,7 @@ where
             failure_info,
             penalty: miner_penalty,
             miner_tip,
+            exec_trace: vec![],
         })
     }
 

fvm/src/executor/mod.rs

@@ -11,6 +11,7 @@ use fvm_shared::receipt::Receipt;
 use num_traits::Zero;
 
 use crate::call_manager::Backtrace;
+use crate::trace::ExecutionTrace;
 use crate::Kernel;
 
 /// An executor executes messages on the underlying machine/kernel. It's responsible for:
@@ -71,6 +72,8 @@ pub struct ApplyRet {
     pub miner_tip: BigInt,
     /// Additional failure information for debugging, if any.
     pub failure_info: Option<ApplyFailure>,
+    /// Execution trace information, for debugging.
+    pub exec_trace: ExecutionTrace,
 }
 
 impl ApplyRet {
@@ -89,6 +92,7 @@ impl ApplyRet {
             penalty: miner_penalty,
             failure_info: Some(ApplyFailure::PreValidation(message.into())),
             miner_tip: BigInt::zero(),
+            exec_trace: vec![],
         }
     }
 

fvm/src/kernel/error.rs

@@ -26,7 +26,7 @@ macro_rules! syscall_error {
     };
 }
 
-// NOTE: this intentionally does not implemnent error so we can make the context impl work out
+// NOTE: this intentionally does not implement error so we can make the context impl work out
 // below.
 #[derive(Display, Debug)]
 pub enum ExecutionError {

fvm/src/lib.rs

@@ -30,6 +30,8 @@ mod power_actor;
 mod reward_actor;
 mod system_actor;
 
+pub mod trace;
+
 use cid::multihash::{Code, MultihashDigest};
 use cid::Cid;
 use fvm_ipld_encoding::{to_vec, DAG_CBOR};

fvm/src/machine/mod.rs

@@ -129,8 +129,8 @@ impl NetworkConfig {
 
     /// Enable actor debugging. This is a consensus-critical option (affects gas usage) so it should
     /// only be enabled for local testing or as a network-wide parameter.
-    pub fn enable_actor_debugging(&mut self, enabled: bool) -> &mut Self {
-        self.actor_debugging = enabled;
+    pub fn enable_actor_debugging(&mut self) -> &mut Self {
+        self.actor_debugging = true;
         self
     }
 
@@ -149,6 +149,7 @@ impl NetworkConfig {
             initial_state_root: initial_state,
             base_fee: TokenAmount::zero(),
             circ_supply: fvm_shared::TOTAL_FILECOIN.clone(),
+            tracing: false,
         }
     }
 }
@@ -178,18 +179,28 @@ pub struct MachineContext {
     ///
     /// DEFAULT: Total FIL supply (likely not what you want).
     pub circ_supply: TokenAmount,
+
+    /// Whether or not to produce execution traces in the returned result.
+    /// Not consensus-critical, but has a performance impact.
+    pub tracing: bool,
 }
 
 impl MachineContext {
-    /// Sets [`EpochContext::base_fee`].
+    /// Sets [`MachineContext::base_fee`].
     pub fn set_base_fee(&mut self, amt: TokenAmount) -> &mut Self {
         self.base_fee = amt;
         self
     }
 
-    /// Set [`EpochContext::circ_supply`].
+    /// Set [`MachineContext::circ_supply`].
     pub fn set_circulating_supply(&mut self, amt: TokenAmount) -> &mut Self {
         self.circ_supply = amt;
         self
     }
+
+    /// Enable execution traces. [`MachineContext::tracing`].
+    pub fn enable_tracing(&mut self) -> &mut Self {
+        self.tracing = true;
+        self
+    }
 }

fvm/src/trace/mod.rs

@@ -0,0 +1,25 @@
+use fvm_ipld_encoding::RawBytes;
+use fvm_shared::address::Address;
+use fvm_shared::econ::TokenAmount;
+use fvm_shared::{ActorID, MethodNum};
+
+use crate::call_manager::InvocationResult;
+use crate::kernel::SyscallError;
+
+/// Execution Trace, only for informational and debugging purposes.
+pub type ExecutionTrace = Vec<ExecutionEvent>;
+
+#[derive(Clone, Debug)]
+pub enum ExecutionEvent {
+    Call(SendParams),
+    Return(Result<InvocationResult, SyscallError>),
+}
+
+#[derive(Clone, Debug)]
+pub struct SendParams {
+    pub from: ActorID,
+    pub to: Address,
+    pub method: MethodNum,
+    pub params: RawBytes,
+    pub value: TokenAmount,
+}

testing/conformance/src/vm.rs

@@ -3,7 +3,7 @@ use std::convert::TryFrom;
 
 use cid::Cid;
 use futures::executor::block_on;
-use fvm::call_manager::{Backtrace, CallManager, DefaultCallManager, InvocationResult};
+use fvm::call_manager::{CallManager, DefaultCallManager, FinishRet, InvocationResult};
 use fvm::gas::{GasTracker, PriceList};
 use fvm::kernel::*;
 use fvm::machine::{DefaultMachine, Engine, Machine, MachineContext, NetworkConfig};
@@ -211,7 +211,7 @@ where
         })
     }
 
-    fn finish(self) -> (i64, Backtrace, Self::Machine) {
+    fn finish(self) -> (FinishRet, Self::Machine) {
         self.0.finish()
     }