Implement execution traces for the FVM #412

arajasek · 2022-03-27T02:36:27Z

Resolves #318

This gets us most of the way to matching Lotus execution traces -- fine gas tracing isn't implemented yet, but it will be impossible to meet that level of detail in M1 anyway.

The ExecutionTrace is created and populated by the call manager, which returns it on finish.

fvm/src/call_manager/default.rs

testing/conformance/src/vm.rs

shared/src/receipt.rs

fvm/src/call_manager/default.rs

Stebalien · 2022-03-30T20:35:24Z

fvm/src/call_manager/default.rs

+                ExecutionError::Syscall(s) => Receipt {
+                    exit_code: match s.1.try_into() {
+                        Ok(e) => e,
+                        _ => ErrPlaceholder,
+                    },


Hm. Any chance we could change the format? We're intentionally distinguishing between syscall errors and exit codes.

Basically, receipts are really for recording results on-chain, but aren't the best for debugging. In this case, it's also causing us to drop the error message.

fvm/src/call_manager/default.rs

raulk · 2022-04-05T14:23:07Z

fvm/src/call_manager/default.rs

@@ -110,12 +138,19 @@ where
        res
    }

-    fn finish(mut self) -> (i64, Backtrace, Self::Machine) {
+    fn finish(mut self) -> (FinishResult, Self::Machine) {


nit: FinishResult sounds like a specialized Result type. Can we change this type name to FinishRet, parallel with ApplyRet?

raulk · 2022-04-05T14:23:50Z

fvm/src/call_manager/mod.rs

@@ -140,3 +146,9 @@ impl InvocationResult {
        }
    }
 }
+
+pub struct FinishResult {


raulk · 2022-04-05T14:25:44Z

fvm/src/call_manager/mod.rs

@@ -140,3 +146,9 @@ impl InvocationResult {
        }
    }
 }
+
+pub struct FinishResult {


Maybe just make the type pub(crate) instead of its fields? It's a little bit useless to have a public method-less struct with all pub(crate) fields.

I'd just make it all public.

raulk · 2022-04-05T14:35:16Z

fvm/src/executor/default.rs

@@ -149,12 +153,15 @@ 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, exec_trace)


Hm, this was confusing to me. I didn't expect finish_message to operate on the exec_trace, so I didn't understand why we passed it in. And indeed it doesn't.

Did you consider:

.map(|apply_ret| { apply_ret.exec_trace = exec_trace; apply_ret })

It's a few more lines of code but it's less surprising (for me). Alternatively we could use a one-liner:

.inspect(|apply_ret| { apply_ret.exec_trace = exec_trace })

But it requires us to enable an experimental API: rust-lang/rust#91345.

fvm/src/kernel/error.rs

fvm/src/trace/mod.rs

dignifiedquire · 2022-04-05T18:37:34Z

fvm/src/call_manager/default.rs

+                self.exec_trace = Some(vec![call_event]);
+            } else {
+                self.exec_trace.as_mut().unwrap().push(call_event);
+            }


should be written as

if let Some(ref mut exec_trace) = self.exec_trace { exec_trace.push(call_event); } else { self.exec_trace = Some(vec![call_event]); }

dignifiedquire · 2022-04-05T18:38:33Z

fvm/src/call_manager/default.rs

+        if self.machine.config().debug {
+            self.exec_trace
+                .as_mut()
+                .unwrap()


this should be at least an .expect explaining why this is already checked

Stebalien · 2022-04-11T10:01:52Z

fvm/src/call_manager/default.rs

+            if self.exec_trace.is_none() {
+                self.exec_trace = Some(vec![call_event]);
+            } else {
+                self.exec_trace.as_mut().unwrap().push(call_event);
+            }


Given that this is just a vector, we can probably drop the option entirely and just start out with an empty vector.

But I also feel compelled to one-up @dignifiedquire:

Suggested change

if self.exec_trace.is_none() {

self.exec_trace = Some(vec![call_event]);

} else {

self.exec_trace.as_mut().unwrap().push(call_event);

}

self.exec_trace.get_or_insert_with(Vec::new).push(call_event);

Y'all and this entire language are outta control. But that's cool to see.

Stebalien · 2022-04-11T10:05:19Z

fvm/src/call_manager/mod.rs

@@ -140,3 +146,9 @@ impl InvocationResult {
        }
    }
 }
+
+pub struct FinishResult {


I'd just make it all public.

Stebalien

Mostly LGTM with some comments.

Stebalien · 2022-04-14T13:39:41Z

fvm/src/executor/default.rs

-            (Ok((result, gas_used, backtrace)), machine)
+            let (res, machine) = cm.finish();
+            (
+                Ok((result, res.gas_used, res.backtrace, res.exec_trace)),


Suggested change

Ok((result, res.gas_used, res.backtrace, res.exec_trace)),

Ok(((result, res), machine)),

?

Eh, but we use gas_used so many times, and they're not suuuper related concepts, and I don't like it.

We can destructure this on the outside. I'm just suggesting a way to slightly reduce the amount of code.

(but it doesn't really matter)

Stebalien · 2022-04-14T13:41:40Z

fvm/src/kernel/error.rs

+impl Clone for ExecutionError {
+    fn clone(&self) -> Self {
+        match self {
+            OutOfGas => OutOfGas,
+            Syscall(v) => Syscall(v.clone()),
+            Fatal(v) => Fatal(anyhow::Error::msg(v.to_string())),
+        }
+    }
+}


Hm... this isn't really a clone. I'd handle these cases separately:

fatal/out-of-gas: nothing? We can just cut the trace short because it doesn't really matter.

Syscall error -> push that.

Basically, record Result<InvocationResult, SyscallError> instead of Result<InvocationResult, ExecutionError>.

fvm/src/machine/mod.rs

arajasek · 2022-04-14T23:20:55Z

fvm/src/call_manager/default.rs

@@ -125,7 +125,16 @@ where
        self.call_stack_depth -= 1;

        if self.machine.context().tracing {
-            self.exec_trace.push(ExecutionEvent::Return(result.clone()));
+            self.exec_trace.push(ExecutionEvent::Return(match result {
+                Err(ref e) => Err(match e {


This combination of refs and clones appeased the checker, but I feel like there's something better that can be done?

Not really...

Well, you can use &result and remove the ref e and friends, but you still need to clone. On the other hand, this will only happen when tracing is enabled.

Stebalien

LGTM.

Stebalien · 2022-04-15T12:21:39Z

fvm/src/executor/default.rs

-            (Ok((result, gas_used, backtrace)), machine)
+            let (res, machine) = cm.finish();
+            (
+                Ok((result, res.gas_used, res.backtrace, res.exec_trace)),


We can destructure this on the outside. I'm just suggesting a way to slightly reduce the amount of code.

Stebalien · 2022-04-15T12:21:50Z

fvm/src/executor/default.rs

-            (Ok((result, gas_used, backtrace)), machine)
+            let (res, machine) = cm.finish();
+            (
+                Ok((result, res.gas_used, res.backtrace, res.exec_trace)),


(but it doesn't really matter)

Stebalien · 2022-04-15T12:57:36Z

fvm/src/call_manager/default.rs

@@ -125,7 +125,16 @@ where
        self.call_stack_depth -= 1;

        if self.machine.context().tracing {
-            self.exec_trace.push(ExecutionEvent::Return(result.clone()));
+            self.exec_trace.push(ExecutionEvent::Return(match result {
+                Err(ref e) => Err(match e {


Not really...

raulk

LGTM.

raulk · 2022-04-18T15:54:32Z

fvm/src/call_manager/default.rs

+            self.exec_trace.push(ExecutionEvent::Return(match result {
+                Err(ref e) => Err(match e {
+                    ExecutionError::OutOfGas => {
+                        SyscallError::new(ErrorNumber::Forbidden, "out of gas")


Are these syscall errors numbers the correct ones to use here?

arajasek force-pushed the asr/exec-trace branch from 883df8c to 2c7cca2 Compare March 29, 2022 00:06

Stebalien reviewed Mar 30, 2022

View reviewed changes

raulk requested review from lemmih and noot March 31, 2022 12:01

arajasek force-pushed the asr/exec-trace branch from 2c7cca2 to 9fcf29b Compare April 1, 2022 16:38

raulk reviewed Apr 5, 2022

View reviewed changes

dignifiedquire reviewed Apr 5, 2022

View reviewed changes

arajasek force-pushed the asr/exec-trace branch from 9fcf29b to 9fae9b5 Compare April 8, 2022 17:18

Stebalien reviewed Apr 13, 2022

View reviewed changes

arajasek force-pushed the asr/exec-trace branch from 9fae9b5 to 2ccd494 Compare April 13, 2022 23:10

Stebalien reviewed Apr 14, 2022

View reviewed changes

Implement execution traces for the FVM

19271a8

arajasek force-pushed the asr/exec-trace branch from 2ccd494 to 9b9280e Compare April 14, 2022 23:19

Address review

39a7575

arajasek force-pushed the asr/exec-trace branch from 9b9280e to 39a7575 Compare April 14, 2022 23:20

arajasek commented Apr 14, 2022

View reviewed changes

Stebalien approved these changes Apr 15, 2022

View reviewed changes

arajasek merged commit c9f3c6e into master Apr 18, 2022

arajasek deleted the asr/exec-trace branch April 18, 2022 16:03

raulk approved these changes Apr 18, 2022

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Implement execution traces for the FVM #412

Implement execution traces for the FVM #412

arajasek commented Mar 27, 2022

Stebalien Mar 30, 2022

Stebalien Mar 30, 2022

raulk Apr 5, 2022

raulk Apr 5, 2022

raulk Apr 5, 2022

Stebalien Apr 11, 2022

raulk Apr 5, 2022

dignifiedquire Apr 5, 2022

dignifiedquire Apr 5, 2022

Stebalien Apr 11, 2022

dignifiedquire Apr 13, 2022

arajasek Apr 13, 2022

Stebalien Apr 11, 2022

Stebalien left a comment

Stebalien Apr 14, 2022

arajasek Apr 14, 2022

Stebalien Apr 15, 2022

Stebalien Apr 15, 2022

Stebalien Apr 14, 2022

Stebalien Apr 14, 2022

arajasek Apr 14, 2022

Stebalien Apr 15, 2022

Stebalien Apr 15, 2022

Stebalien left a comment

Stebalien Apr 15, 2022

Stebalien Apr 15, 2022

Stebalien Apr 15, 2022

raulk left a comment

raulk Apr 18, 2022

	Ok((result, res.gas_used, res.backtrace, res.exec_trace)),
	Ok(((result, res), machine)),

Implement execution traces for the FVM #412

Implement execution traces for the FVM #412

Conversation

arajasek commented Mar 27, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Stebalien left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Stebalien left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

raulk left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment