feat: log(LogEntry) to handle different log types

[rvagg]

Just toying around here to see if I can come up with an answer to #2101 (comment); @Stebalien I'm not sure what you mean by generalising the execution log but this is my take on it.

[Stebalien]

I was thinking we could add an entirely new event type (not just string logs). New event types aren't breaking (personally, I'd add "put" and "get" events).

The more breaking version would be to change the structure of the event log. Right now the log preserves the tree structure of the calls but not the tree structure of the syscalls, but we could also preserve the structure of the syscalls. But I don't think that's critical right now.

[Stebalien]

note: I'd also just add these as separate methods? Maybe?

Or maybe we can avoid adding more methods to the kernel by recording put events at the blockstore level? But then we'd need to wrap the blockstore somehow which is... probably even more annoying.

[rvagg]

I was thinking we could add an entirely new event type (not just string logs)

OK, so this would involve changing the serialisation as it travels through FFI and would break existing clients. What's the general rule we've followed here for versioning? If we did that we would have to bump some number, is a semver-minor appropriate for that? What justifies a semver-major bump in here?

[Stebalien]

Well:

1. Adding new event types isn't a breaking change, users will just ignore the ones they don't understand.
2. All FFI serialization is internal to the FFI anyways.
3. We allow API breaking changes in the FVM in minor releases, patch releases are for releases with no breaking changes. This violates semver, but we use major versions for network upgrades. See FVM versioning and technical debt #1724 and ref-fvm version philosophy  #358.

[rvagg]

OK, so maybe just an internally tagged enum serialization, ["syscall","some debug logging from sys::debug::log"] and ["block_write",{"/":"bafy..."}] for what I want, then we extend the enum as far as we want with additional stuff.

Thoughts on what other log items might be useful in execution traces?

[Stebalien]

I wouldn't think hard about the serialization format. Well, that'll be an issue in the Lotus API but the execution trace has a completely different structure there.

I was thinking:

diff --git a/fvm/src/trace/mod.rs b/fvm/src/trace/mod.rs
index 370828b1..32fbd045 100644
--- a/fvm/src/trace/mod.rs
+++ b/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;
@@ -39,4 +40,15 @@ pub enum ExecutionEvent {
         state: ActorState,
     },
     Log(String),
+    Ipld {
+        op: IpldOperation,
+        cid: Cid,
+        size: u64,
+    },
+}
+
+#[derive(Clone, Debug)]
+pub enum IpldOperation {
+    Get, // open
+    Put, // link
 }

[rvagg]

OK, introduced a trace_ipld() on the CallManager that adds a new ExecutionEvent::Ipld, for both reads and writes. I wrestled for far too long to try and do it at the Blockstore level by introducing a wrapper that could record on reads and writes but I just couldn't reconcile the lifetimes and borrowing and all that guff so I gave up. There's a preload() call in here that I also track and it uses a Blockstore that gets passed in, but I'm going with the fairly-safe assumption that we're only going to try and load a single block, if any. We don't know whether we had a cache hit or not but I record it anyway. I'm not sure whether this block load will end up being useful or not but they're raw blocks anyway so shouldn't be too hard to filter out if we cared.

[Stebalien]

OK, introduced a trace_ipld() on the CallManager that adds a new ExecutionEvent::Ipld, for both reads and writes. I wrestled for far too long to try and do it at the Blockstore level by introducing a wrapper that could record on reads and writes but I just couldn't reconcile the lifetimes and borrowing and all that guff so I gave up.

Yeah, rust really expects exactly one owner. I'm not surprised.

There's a preload() call in here that I also track and it uses a Blockstore that gets passed in, but I'm going with the fairly-safe assumption that we're only going to try and load a single block, if any.

We don't even use that right now. We added that for user-deployable actors but it isn't hooked up anywhere.

[Stebalien]

In terms of the tests, it's dying with exit code 143 which apparently means "SIGTERM".

[Stebalien]

The hidden error only visible in the raw logs is:

2025-04-02T05:27:02.6034191Z ##[error]The runner has received a shutdown signal. This can happen when the runner service is stopped, or a manually started runner is canceled.

Of course, this is also visible to copilot so it was able to figure out the issue immediately....