feat(trace): introduce new Ipld ExecutionEvent

Author: rvagg

fvm/src/call_manager/default.rs

@@ -24,7 +24,7 @@ use crate::eam_actor::EAM_ACTOR_ID;
 use crate::engine::Engine;
 use crate::gas::{Gas, GasTracker};
 use crate::kernel::{
-    Block, BlockRegistry, ClassifyResult, ExecutionError, Kernel, LogEntry, Result, SyscallError,
+    Block, BlockRegistry, ClassifyResult, ExecutionError, Kernel, Result, SyscallError,
 };
 use crate::machine::limiter::MemoryLimiter;
 use crate::machine::Machine;
@@ -514,11 +514,12 @@ where
         Ok(())
     }
 
-    fn log(&mut self, entry: LogEntry) {
-        self.trace(ExecutionEvent::Log(match entry {
-            LogEntry::Syscall(msg) => format!("SyscallLog({})", msg),
-            LogEntry::BlockLink(cid) => format!("BlockLink({})", cid),
-        }));
+    fn log(&mut self, msg: String) {
+        self.trace(ExecutionEvent::Log(msg))
+    }
+
+    fn trace_ipld(&mut self, op: crate::trace::IpldOperation, cid: Cid, size: usize) {
+        self.trace(ExecutionEvent::Ipld { op, cid, size })
     }
 }
 

fvm/src/call_manager/mod.rs

@@ -10,7 +10,7 @@ use fvm_shared::{ActorID, MethodNum, METHOD_CONSTRUCTOR};
 
 use crate::engine::Engine;
 use crate::gas::{Gas, GasCharge, GasTimer, GasTracker, PriceList};
-use crate::kernel::{self, BlockRegistry, ClassifyResult, Context, LogEntry, Result};
+use crate::kernel::{self, BlockRegistry, ClassifyResult, Context, Result};
 use crate::machine::{Machine, MachineContext};
 use crate::state_tree::ActorState;
 use crate::Kernel;
@@ -24,7 +24,7 @@ mod default;
 pub use default::DefaultCallManager;
 use fvm_shared::event::StampedEvent;
 
-use crate::trace::ExecutionTrace;
+use crate::trace::{ExecutionTrace, IpldOperation};
 
 /// BlockID representing nil parameters or return data.
 pub const NO_DATA_BLOCK_ID: u32 = 0;
@@ -87,6 +87,7 @@ pub trait CallManager: 'static {
 
     /// Returns a reference to the machine.
     fn machine(&self) -> &Self::Machine;
+
     /// Returns a mutable reference to the machine.
     fn machine_mut(&mut self) -> &mut Self::Machine;
 
@@ -176,7 +177,9 @@ pub trait CallManager: 'static {
     fn append_event(&mut self, evt: StampedEvent);
 
     /// log
-    fn log(&mut self, entry: LogEntry);
+    fn log(&mut self, msg: String);
+
+    fn trace_ipld(&mut self, op: IpldOperation, cid: Cid, size: usize);
 }
 
 /// The result of calling actor's entrypoint

fvm/src/kernel/default.rs

@@ -27,6 +27,7 @@ use crate::gas::GasTimer;
 use crate::init_actor::INIT_ACTOR_ID;
 use crate::machine::{MachineContext, NetworkConfig, BURNT_FUNDS_ACTOR_ID};
 use crate::state_tree::ActorState;
+use crate::trace::IpldOperation;
 use crate::{ipld, syscall_error};
 
 const BLAKE2B_256: u64 = 0xb220;
@@ -409,6 +410,9 @@ where
 
         t.stop();
 
+        self.call_manager
+            .trace_ipld(IpldOperation::Get, *cid, data.len());
+
         // This can fail because we can run out of gas.
         let children = ipld::scan_for_reachable_links(
             cid.codec(),
@@ -483,11 +487,13 @@ where
             // TODO: This is really "super fatal". It means we failed to store state, and should
             // probably abort the entire block.
             .or_fatal()?;
+        let size = block.data().len();
         self.blocks.mark_reachable(&k);
 
         t.stop_with(start);
 
-        self.call_manager.log(LogEntry::BlockLink(k));
+        self.call_manager.trace_ipld(IpldOperation::Put, k, size);
+
         Ok(k)
     }
 
@@ -882,6 +888,7 @@ where
 
     fn install_actor(&mut self, code_id: Cid) -> Result<()> {
         let start = GasTimer::start();
+
         let size = self
             .call_manager
             .engine()
@@ -894,6 +901,9 @@ where
             .charge_gas(self.call_manager.price_list().on_install_actor(size))?;
         t.stop_with(start);
 
+        self.call_manager
+            .trace_ipld(IpldOperation::Get, code_id, size);
+
         Ok(())
     }
 
@@ -953,8 +963,8 @@ impl<C> DebugOps for DefaultKernel<C>
 where
     C: CallManager,
 {
-    fn log(&mut self, entry: LogEntry) {
-        self.call_manager.log(entry)
+    fn log(&mut self, msg: String) {
+        self.call_manager.log(msg)
     }
 
     fn debug_enabled(&self) -> bool {

fvm/src/kernel/mod.rs

@@ -281,19 +281,11 @@ pub trait RandomnessOps {
         -> Result<[u8; RANDOMNESS_LENGTH]>;
 }
 
-#[derive(PartialEq)]
-pub enum LogEntry {
-    /// A log message originating from a log() syscall.
-    Syscall(String),
-    /// A new block was created.
-    BlockLink(Cid),
-}
-
 /// Debugging APIs.
 #[delegatable_trait]
 pub trait DebugOps {
     /// Log a message.
-    fn log(&mut self, entry: LogEntry);
+    fn log(&mut self, msg: String);
 
     /// Returns whether debug mode is enabled.
     fn debug_enabled(&self) -> bool;
@@ -328,9 +320,7 @@ pub mod prelude {
         ActorOps, CryptoOps, DebugOps, EventOps, IpldBlockOps, MessageOps, NetworkOps,
         RandomnessOps, SelfOps, SendOps, UpgradeOps,
     };
-    pub use super::{
-        Block, BlockId, BlockRegistry, BlockStat, CallResult, Kernel, LogEntry, SyscallHandler,
-    };
+    pub use super::{Block, BlockId, BlockRegistry, BlockStat, CallResult, Kernel, SyscallHandler};
     pub use crate::gas::{Gas, GasTimer, PriceList};
     pub use ambassador::Delegate;
     pub use fvm_shared::address::Address;

fvm/src/syscalls/debug.rs

@@ -1,6 +1,6 @@
 // Copyright 2021-2023 Protocol Labs
 // SPDX-License-Identifier: Apache-2.0, MIT
-use crate::kernel::{ClassifyResult, DebugOps, LogEntry, Result};
+use crate::kernel::{ClassifyResult, DebugOps, Result};
 use crate::syscalls::context::Context;
 
 pub fn log(context: Context<'_, impl DebugOps>, msg_off: u32, msg_len: u32) -> Result<()> {
@@ -11,7 +11,7 @@ pub fn log(context: Context<'_, impl DebugOps>, msg_off: u32, msg_len: u32) -> R
 
     let msg = context.memory.try_slice(msg_off, msg_len)?;
     let msg = String::from_utf8(msg.to_owned()).or_illegal_argument()?;
-    context.kernel.log(LogEntry::Syscall(msg));
+    context.kernel.log(msg);
     Ok(())
 }
 

fvm/src/trace/mod.rs

@@ -1,3 +1,4 @@
+use cid::Cid;
 // Copyright 2021-2023 Protocol Labs
 // SPDX-License-Identifier: Apache-2.0, MIT
 use fvm_ipld_encoding::ipld_block::IpldBlock;
@@ -13,6 +14,13 @@ use crate::kernel::SyscallError;
 /// Execution Trace, only for informational and debugging purposes.
 pub type ExecutionTrace = Vec<ExecutionEvent>;
 
+/// The type of operation being performed in an Ipld ExecutionEvent.
+#[derive(Clone, Debug, PartialEq)]
+pub enum IpldOperation {
+    Get, // open
+    Put, // link
+}
+
 /// An "event" that happened during execution.
 ///
 /// This is marked as `non_exhaustive` so we can introduce additional event types later.
@@ -39,4 +47,9 @@ pub enum ExecutionEvent {
         state: ActorState,
     },
     Log(String),
+    Ipld {
+        op: IpldOperation,
+        cid: Cid,
+        size: usize,
+    },
 }

fvm/tests/default_kernel/ops.rs

@@ -5,8 +5,9 @@ use super::*;
 mod ipld {
 
     use cid::Cid;
-    use fvm::kernel::{IpldBlockOps, LogEntry, SupportedHashes};
+    use fvm::kernel::{IpldBlockOps, SupportedHashes};
     use fvm::machine::Machine;
+    use fvm::trace::IpldOperation;
     use fvm_ipld_blockstore::Blockstore;
     use fvm_ipld_encoding::{DAG_CBOR, IPLD_RAW};
     use multihash_codetable::MultihashDigest;
@@ -200,10 +201,21 @@ mod ipld {
             )
         }
 
-        assert!(call_manager.logs.contains(&LogEntry::BlockLink(cid)));
+        assert!(call_manager
+            .ipld_traces
+            .iter()
+            .any(|(op, c, _)| *op == IpldOperation::Put && *c == cid));
+
         let (call_manager1, _) = kern1.into_inner();
-        assert!(call_manager1.logs.contains(&LogEntry::BlockLink(cid))); // cid1==cid
-        assert!(call_manager1.logs.contains(&LogEntry::BlockLink(other_cid)));
+
+        assert!(call_manager1
+            .ipld_traces
+            .iter()
+            .any(|(op, c, _)| *op == IpldOperation::Put && *c == cid)); // cid1==cid
+        assert!(call_manager1
+            .ipld_traces
+            .iter()
+            .any(|(op, c, _)| *op == IpldOperation::Put && *c == other_cid));
 
         Ok(())
     }

fvm/tests/dummy.rs

@@ -13,6 +13,7 @@ use fvm::gas::{Gas, GasCharge, GasTimer, GasTracker};
 use fvm::machine::limiter::MemoryLimiter;
 use fvm::machine::{Machine, MachineContext, Manifest, NetworkConfig};
 use fvm::state_tree::StateTree;
+use fvm::trace::IpldOperation;
 use fvm::{kernel, Kernel};
 use fvm_ipld_blockstore::{Blockstore, MemoryBlockstore};
 use fvm_ipld_encoding::{CborStore, DAG_CBOR};
@@ -191,7 +192,7 @@ pub struct DummyCallManager {
     pub origin: ActorID,
     pub nonce: u64,
     pub test_data: Rc<RefCell<TestData>>,
-    pub logs: Vec<kernel::LogEntry>,
+    pub ipld_traces: Vec<(IpldOperation, Cid, usize)>,
     limits: DummyLimiter,
 }
 
@@ -217,7 +218,7 @@ impl DummyCallManager {
                 test_data: rc,
                 limits: DummyLimiter::default(),
                 gas_premium: TokenAmount::zero(),
-                logs: vec![],
+                ipld_traces: vec![],
             },
             cell_ref,
         )
@@ -237,7 +238,7 @@ impl DummyCallManager {
                 test_data: rc,
                 limits: DummyLimiter::default(),
                 gas_premium: TokenAmount::zero(),
-                logs: vec![],
+                ipld_traces: vec![],
             },
             cell_ref,
         )
@@ -270,7 +271,7 @@ impl CallManager for DummyCallManager {
             nonce,
             test_data: rc,
             limits,
-            logs: vec![],
+            ipld_traces: vec![],
         }
     }
 
@@ -405,7 +406,11 @@ impl CallManager for DummyCallManager {
         todo!()
     }
 
-    fn log(&mut self, entry: kernel::LogEntry) {
-        self.logs.push(entry);
+    fn log(&mut self, _msg: String) {
+        todo!()
+    }
+
+    fn trace_ipld(&mut self, op: IpldOperation, cid: Cid, size: usize) {
+        self.ipld_traces.push((op, cid, size));
     }
 }