Export events in readonly endpoints #6741
Conversation
rob-stacks
requested review from
aaronb-stacks,
adriano-stacks,
brice-stacks and
francesco-stacks
Codecov Report❌ Patch coverage is ❌ Your project check has failed because the head coverage (71.91%) is below the target coverage (80.00%). You can increase the head coverage or adjust the target coverage. Additional details and impacted files@@ Coverage Diff @@
## develop #6741 +/- ##
===========================================
- Coverage 76.86% 71.91% -4.96%
===========================================
Files 579 579
Lines 360066 360127 +61
===========================================
- Hits 276782 258988 -17794
- Misses 83284 101139 +17855
... and 281 files with indirect coverage changes Continue to review full report in Codecov by Sentry.
🚀 New features to boost your workflow:
|
jcnelson
left a comment
jcnelson
left a comment
There was a problem hiding this comment.
Please see my earlier comment. There is no need to modify the Clarity VM to get events; the Clarity API already offers a way to return the events directly. It just needs to be used in the RPC endpoint implementation. Thanks!
| let mut events = vec![]; | ||
| self.global_context | ||
| .event_batches | ||
| .iter() | ||
| .for_each(|event_batch| { | ||
| events.extend(event_batch.events.clone()); | ||
| }); |
There was a problem hiding this comment.
I'm having some difficulty reasoning about what this returns. This makes it so that the execute_function_as_transaction_and_events returns the events at the time of the outermost call -- ignoring the result of the transaction or the read-only-ness but only for the outermost call.
Imagine like the following:
(define-read-only (foo)
(begin (print "foo") (err u1)))
(define-public (bar)
(begin (print "bar") (foo)))
(define-public (baz)
(begin (print "baz") (bar)))Then I think what we'd see is:
execute_function_as_transaction_and_events(foo) -> events: [ "foo" ]
execute_function_as_transaction_and_events(bar) -> events: [ "bar" ]
execute_function_as_transaction_and_events(baz) -> events: [ "baz" ]
Which would be weird, right?
In normal clarity execution, read-only calls won't emit events: they get rolled back. So block events won't include them. With this change, the RPC endpoitn would return block events for those read-only calls, but only the outermost calls. The same logic applies to failing txs (seems bad, even though I'm not sure that failed txs are frequently invoked via the read-only endpoint.).
There was a problem hiding this comment.
I went ahead and tested this on @rob-stacks's branch:
diff --git a/clarity/src/vm/contexts.rs b/clarity/src/vm/contexts.rs
index 64dab3e1c2..73336a94cc 100644
--- a/clarity/src/vm/contexts.rs
+++ b/clarity/src/vm/contexts.rs
@@ -1009,11 +1009,11 @@ impl<'a, 'b, 'hooks> Environment<'a, 'b, 'hooks> {
)
}
- pub fn eval_read_only(
+ fn inner_eval_read_only(
&mut self,
contract_identifier: &QualifiedContractIdentifier,
program: &str,
- ) -> Result<Value, VmExecutionError> {
+ ) -> Result<(Value, Vec<StacksTransactionEvent>), VmExecutionError> {
let clarity_version = self.contract_context.clarity_version;
let parsed = ast::build_ast(
@@ -1062,10 +1062,34 @@ impl<'a, 'b, 'hooks> Environment<'a, 'b, 'hooks> {
let local_context = LocalContext::new();
eval(&parsed[0], &mut nested_env, &local_context)
};
+
+ let mut events = vec![];
+ self.global_context
+ .event_batches
+ .iter()
+ .for_each(|event_batch| {
+ events.extend(event_batch.events.clone());
+ });
self.global_context.roll_back()?;
- result
+ result.map(|value| (value, events))
+ }
+
+ pub fn eval_read_only(
+ &mut self,
+ contract_identifier: &QualifiedContractIdentifier,
+ program: &str,
+ ) -> Result<Value, VmExecutionError> {
+ self.inner_eval_read_only(contract_identifier, program).map(|(value, _)| value)
+ }
+
+ pub fn eval_read_only_with_events(
+ &mut self,
+ contract_identifier: &QualifiedContractIdentifier,
+ program: &str,
+ ) -> Result<(Value, Vec<StacksTransactionEvent>), VmExecutionError> {
+ self.inner_eval_read_only(contract_identifier, program)
}
pub fn eval_raw(&mut self, program: &str) -> Result<Value, VmExecutionError> {
diff --git a/contrib/clarity-cli/src/lib.rs b/contrib/clarity-cli/src/lib.rs
index b029bb03bd..d884674fb9 100644
--- a/contrib/clarity-cli/src/lib.rs
+++ b/contrib/clarity-cli/src/lib.rs
@@ -1486,20 +1486,23 @@ pub fn invoke_command(invoked_by: &str, args: &[String]) -> (i32, Option<serde_j
let placeholder_context =
ContractContext::new(QualifiedContractIdentifier::transient(), clarity_version);
- let (_, _, result_and_cost) = in_block(header_db, marf_kv, |header_db, mut marf| {
- let result_and_cost =
+ let (_, _, result_and_events_and_cost) = in_block(header_db, marf_kv, |header_db, mut marf| {
+ let result_and_events_and_cost =
with_env_costs(mainnet, epoch, &header_db, &mut marf, None, |vm_env| {
vm_env
.get_exec_environment(None, None, &placeholder_context)
- .eval_read_only(&eval_input.contract_identifier, &eval_input.content)
+ .eval_read_only_with_events(&eval_input.contract_identifier, &eval_input.content)
});
- (header_db, marf, result_and_cost)
+ (header_db, marf, result_and_events_and_cost)
});
- match result_and_cost {
- (Ok(result), cost) => {
+ match result_and_events_and_cost {
+ (Ok((result, events)), cost) => {
+ let events_json : Vec<_> = events.into_iter().enumerate().map(|(i, ev)| ev.json_serialize(i, &"", true).unwrap()).collect();
+
let mut result_json = json!({
"output": serde_json::to_value(&result).unwrap(),
+ "events": events_json,
"success": true,
});
I also expanded your test case:
$ cat /tmp/clarity-events-test.clar
(define-read-only (foo)
(begin (print "foo") (ok u1)))
(define-public (bar)
(begin (print "bar") (foo)))
(define-public (baz)
(begin (print "baz") (bar)))
(define-public (quux)
(begin (print "quux") (baz)))
(define-public (xyzzy)
(begin (print "xyzzy") (quux)))
$ clarity-cli initialize /tmp/clarity-events-test.db
INFO [1765572084.549427] [stackslib/src/chainstate/stacks/index/file.rs:242] [main] Migrate 0 blocks to external blob storage at /tmp/clarity-events-test.db/marf.sqlite.blobs
INFO [1765572084.549446] [stackslib/src/chainstate/stacks/index/file.rs:174] [main] Preemptively vacuuming the database file to free up space after copying trie blobs to a separate file
{"message":"Database created.","network":"mainnet"}
$ clarity-cli launch SP2WS2GQHMARP71QE4T8SZ37BAAGKXV4FBX5ANB8.test /tmp/clarity-events-test.clar /tmp/clarity-events-test.db
$ clarity-cli launch SP2WS2GQHMARP71QE4T8SZ37BAAGKXV4FBX5ANB8.test /tmp/clarity-events-test.clar /tmp/clarity-events-test.db
{"events":[],"message":"Contract initialized!"}
$ cat /tmp/call.clar
(xyzzy)
$ clarity-cli eval SP2WS2GQHMARP71QE4T8SZ37BAAGKXV4FBX5ANB8.test /tmp/call.clar /tmp/clarity-events-test.db/ | jq
{
"events": [
{
"committed": true,
"contract_event": {
"contract_identifier": "SP2WS2GQHMARP71QE4T8SZ37BAAGKXV4FBX5ANB8.test",
"raw_value": "0x0d0000000578797a7a79",
"topic": "print",
"value": {
"Sequence": {
"String": {
"ASCII": {
"data": [
120,
121,
122,
122,
121
]
}
}
}
}
},
"event_index": 0,
"txid": "0x\"\"",
"type": "contract_event"
},
{
"committed": true,
"contract_event": {
"contract_identifier": "SP2WS2GQHMARP71QE4T8SZ37BAAGKXV4FBX5ANB8.test",
"raw_value": "0x0d0000000471757578",
"topic": "print",
"value": {
"Sequence": {
"String": {
"ASCII": {
"data": [
113,
117,
117,
120
]
}
}
}
}
},
"event_index": 1,
"txid": "0x\"\"",
"type": "contract_event"
},
{
"committed": true,
"contract_event": {
"contract_identifier": "SP2WS2GQHMARP71QE4T8SZ37BAAGKXV4FBX5ANB8.test",
"raw_value": "0x0d0000000362617a",
"topic": "print",
"value": {
"Sequence": {
"String": {
"ASCII": {
"data": [
98,
97,
122
]
}
}
}
}
},
"event_index": 2,
"txid": "0x\"\"",
"type": "contract_event"
},
{
"committed": true,
"contract_event": {
"contract_identifier": "SP2WS2GQHMARP71QE4T8SZ37BAAGKXV4FBX5ANB8.test",
"raw_value": "0x0d00000003626172",
"topic": "print",
"value": {
"Sequence": {
"String": {
"ASCII": {
"data": [
98,
97,
114
]
}
}
}
}
},
"event_index": 3,
"txid": "0x\"\"",
"type": "contract_event"
}
],
"output": {
"Response": {
"committed": true,
"data": {
"UInt": 1
}
}
},
"output_serialized": "070100000000000000000000000000000001",
"success": true
}Looking at these events, the only event which does not get captured is the innermost event generated by (print "foo"). Meaning:
- This is a bug -- why is the innermost event dropped?
- A read-only evaluation from an
Environment<_', _'>will result in theGlobalContextcapturing all events, except for the inner-most one it seems.
There was a problem hiding this comment.
I have extended the test contract for having nested calls (and related events generation). As reported by @jcnelson all of the events are reported (in the order they are generated). I was not able to reproduce the issue with the innermost (but probably it was caused by some earlier commit that i reverted in the process)
There was a problem hiding this comment.
I don't believe that this is correct. If you can't replicate this in testing, I think that's because testing is insufficient. The code definitely drops events for innermost read-only calls and error results for transactions (but does not do either of those things for outermost read-only calls and error results.
There was a problem hiding this comment.
In more detail, the returned events Vec is not used anywhere but in the API invocations. This means that when transactions are nested at all, the returned events Vec won't be added before the events get rolled back.
There was a problem hiding this comment.
Looking at these events, the only event which does not get captured is the innermost event generated by (print "foo"). Meaning:
This is a bug -- why is the innermost event dropped?
A read-only evaluation from an Environment<_', _'> will result in the GlobalContext capturing all events, except for the inner-most one it seems.
Your example is actually different from the one I posted:
(define-read-only (foo) (begin (print "foo") (err u1)))
(define-public (bar) (begin (print "bar") (foo)))
(define-public (baz) (begin (print "baz") (bar)))Without this PR, I don't think any of these produce events at all -- the read-only function's events are rolled-back when the VM rolls back the read-only execution. bar's invocation is rolled-back because it returns err u1, so the bar event is not emitted. The same is true for baz.
With the changes in this PR, the gathering of events before the rollback for API invocations means that the outermost invocations save those events before they get rolled back. In the case of err results, that seems bad. In the case of read-only results, that seems good because its the point of this PR, but the fact that its only working on the outermost invocations comes down to the way that this PR is gathering events (by pulling them out of the batch a the outermost call, after rollbacks have been applied in internal calls).
Your patch in this thread I think confuses matters further -- none of the examples above produce any events in the CLI with your patch. That's because all of them are rolled back before your patch does any event collection.
The higher-level point here is that the current event system specifically goes through the effort of dropping events whenever mutations are being rolled back (relevant times when this happens: read-only calls, transaction failures, at-block invocations). The changes in this PR (and your patch) only collect events from an outermost call, meaning that any such dropped events won't be picked up.
There was a problem hiding this comment.
The higher-level point here is that the current event system specifically goes through the effort of dropping events whenever mutations are being rolled back (relevant times when this happens: read-only calls, transaction failures, at-block invocations).
This is actually news to me. Is this API contract spelled out anywhere? Is it covered by unit tests?
The changes in this PR (and your patch) only collect events from an outermost call, meaning that any such dropped events won't be picked up.
Okay, yes, I can see that now, given where all the calls to global_context.roll_back() happen.
Okay, so a new strategy is needed here. @aaronb-stacks would it be okay to add a way to buffer up event batches in GlobalContext that would not be rolled back via roll_back()? This would only be consumed by the RPC endpoint, and these events would not be gathered by default. The caller would need to request it.
There was a problem hiding this comment.
I think my preference here would be add some kind of callback fn/hook to the event batch struct. That way, the RPC endpoint can specify exactly how it wants to deal with events and it won't impact any other callers.
4 participants
Description
This patch adds the list of events generated by read-only calls to the output of the readonly endpoints (base and fast).
This is the example output for a simple function:
{"events":[{"key":"print","sender":"ST2DS4MSWSGJ3W9FBC6BVT0Y92S345HY8N3T6AV7R.hello-world","value":"0000000000000000000000000000000064"},{"key":"print","sender":"ST2DS4MSWSGJ3W9FBC6BVT0Y92S345HY8N3T6AV7R.hello-world","value":"01000000000000000000000000000003e8"},{"key":"print","sender":"ST2DS4MSWSGJ3W9FBC6BVT0Y92S345HY8N3T6AV7R.hello-world","value":"0d0000000474657374"},{"key":"print","sender":"ST2DS4MSWSGJ3W9FBC6BVT0Y92S345HY8N3T6AV7R.hello-world","value":"03"}],"okay":true,"result":"0x070100000000000000000000000000000001"}Additional info (benefits, drawbacks, caveats)
The patch includes a refactoring of the two endpoints to share the contract call logic (they differs only for the cost tracker and the max_execution_time)
Checklist
docs/rpc/openapi.yamlandrpc-endpoints.mdfor v2 endpoints,event-dispatcher.mdfor new events)clarity-benchmarkingrepo