Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

eth/tracers: add position field for callTracer logs #28389

Merged
merged 6 commits into from
Nov 3, 2023

Conversation

alvarosevilla95
Copy link
Contributor

@alvarosevilla95 alvarosevilla95 commented Oct 20, 2023

Currently, one can use the "withLog" parameter to include logs in the callTracer results, which allows the user to see at which trace level was each log emitted.

However, it does not permit to distinguish the exact ordering of a particular trace's logs and subexecutions. For example, if a trace emits a log, then calls another contract (subexecution starts), and after that returns it emits a second log, both would be included in the top trace's logs array, but one couldn't tell one was emitted before the call and the other after it.

This commit introduces a new field to the callLog struct named Position. It is equal to the current length of the calls array for the current trace at the time of the log emission. So a log that is emitted before any sub-calls are made will have position 0, and one that is emitted after a sub-call has happened will have position 1.

Currently, one can use the "withLogs" parameter to include logs in the
callTracer results, which allows the user to see at which trace level
was each log emitted.
However, it does not permit to distinguish the exact ordering of a
particular trace's logs and subexecutions. For example, if a trace emits
a log, then calls another contract (subexecution starts), and after that
returns it emits a second log, both would be included in the top trace's
logs array, but one couldn't tell one was emitted before the call and
the other after it.
This commit introduces a new field to the callLog struct named
`Position`. It is equal to the current length of the calls array for the
current trace at the time of the log emission. So a log that is emitted
before any sub-calls are made will have position 0, and one that is
emitted after a sub-call has happened will have position 1.
@alvarosevilla95 alvarosevilla95 changed the title Add position field for callTracer logs eth/tracers: add position field for callTracer logs Oct 20, 2023
@alvarosevilla95
Copy link
Contributor Author

@jsvisa tagging you as you developed the original feature. I found this added granularity useful for my use cases, thought I'd propose as a PR. I understand the added field may or may not be worth it for the majority of scenarios.

@jsvisa
Copy link
Contributor

jsvisa commented Oct 20, 2023

That sounds good to me.

@@ -188,7 +189,9 @@ func (t *callTracer) CaptureState(pc uint64, op vm.OpCode, gas, cost uint64, sco
return
}

log := callLog{Address: scope.Contract.Address(), Topics: topics, Data: hexutil.Bytes(data)}
position := len(t.callstack[len(t.callstack)-1].Calls)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Isn't position same thing as depth ?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think they are not the same thing. here the log.position is used as relative to the number of calls in the current depth

@s1na
Copy link
Contributor

s1na commented Oct 20, 2023

both would be included in the top trace's logs array, but one couldn't tell one was emitted before the call and the other after it.

Hm fair, I understand people care about this ordering.

How about using the logIndex field like we have them in eth_getLogs to stay more-or-less consistent? It will be a global incrementing index of logs.

@jsvisa
Copy link
Contributor

jsvisa commented Oct 20, 2023

both would be included in the top trace's logs array, but one couldn't tell one was emitted before the call and the other after it.
Hm fair, I understand people care about this ordering.

How about using the logIndex field like we have them in eth_getLogs to stay more-or-less consistent? It will be a global incrementing index of logs.

I've considered that option, too, but I think index is incremental and should not interrupt, but there may be an interruption in this use-case, such as:

Call
Log -> Position 0
Call
Call
Log -> Position 2

@s1na
Copy link
Contributor

s1na commented Oct 20, 2023

I've considered that option, too, but I think index is incremental and should not interrupt, but there may be an interruption in this use-case, such as:

I'm confused. In your case it's still possible to tell the ordering of logs by index.

Call
Log -> Index 0
Call
Call
Log -> Index 1

@alvarosevilla95
Copy link
Contributor Author

alvarosevilla95 commented Oct 20, 2023

I've considered that option, too, but I think index is incremental and should not interrupt, but there may be an interruption in this use-case, such as:

I'm confused. In your case it's still possible to tell the ordering of logs by index.

Call
Log -> Index 0
Call
Call
Log -> Index 1

You would know the ordering of logs among themselves (but you already have this as the logs array is ordered). What I want to add here is a way to know the order of logs relative to calls made in the same trace. You want the second log to have a value of 2 so that you know that it was emitted after the second call.

As such I think using index for the field name could lead to confusion as the semantics are different from its use in getLogs (both in meaning and range). Admittedly, I'm not very happy with Position either, but I'm having trouble coming up with a better name that remains concise.

@alvarosevilla95
Copy link
Contributor Author

I've considered that option, too, but I think index is incremental and should not interrupt, but there may be an interruption in this use-case, such as:

I'm confused. In your case it's still possible to tell the ordering of logs by index.

Call
Log -> Index 0
Call
Call
Log -> Index 1

You would know the ordering of logs among themselves (but you already have this as the logs array is ordered). What I want to add here is a way to know the order of logs relative to calls made in the same trace. You want the second log to have a value of 2 so that you know that it was emitted after the second call.

As such I think using index for the field name could lead to confusion as the semantics are different from its use in getLogs (both in meaning and range). Admittedly, I'm not very happy with Position either, but I'm having trouble coming up with a better name that remains concise.

(for clarity, I'm assuming in the example above the first call is the one that initializes the trace. If the 3 calls listed were subcalls emitted by the trace, the log positions would be 1 and 3 respectively)

@alvarosevilla95
Copy link
Contributor Author

Perhaps CallOrder would be more descriptive?

@s1na
Copy link
Contributor

s1na commented Oct 23, 2023

What I want to add here is a way to know the order of logs relative to calls made in the same trace.

Ok I thought you want to have a global ordering of logs. Can you remind me please what is the use-case for this?

It is still possible to infer the information you want from a global index. Because there will be a gap in the index between for logs before and after a subcall. And you can compare the index of a log to that of a subcalls' logs to know after which subcall it exactly happened. Would this solve your problem? I want to know if we can re-use a field before we decide to add a new one. We should be careful with regards to reverts and fix up the indices (because logs of a reverted call are cleared). For position this is not an issue.

@alvarosevilla95
Copy link
Contributor Author

alvarosevilla95 commented Oct 25, 2023

What I want to add here is a way to know the order of logs relative to calls made in the same trace.

Ok I thought you want to have a global ordering of logs. Can you remind me please what is the use-case for this?

It is still possible to infer the information you want from a global index. Because there will be a gap in the index between for logs before and after a subcall. And you can compare the index of a log to that of a subcalls' logs to know after which subcall it exactly happened. Would this solve your problem? I want to know if we can re-use a field before we decide to add a new one. We should be careful with regards to reverts and fix up the indices (because logs of a reverted call are cleared). For position this is not an issue.

Ah, I think I see what you mean better now. Starting with you first question, the use case for the interleaved order for calls and logs for me is to display an "advanced trace" view, where every relevant action (call or log) is displayed, in the exact order that it happened. This can be useful when trying to understand the flow of execution of a transaction, where the exact order of calls made and logs emitted can help visualize the logic executed.

Your proposed solution, if I understand correctly, is to reconstruct the global order of logs (such as you'd get from the tx receipt), in this trace structure. That would definitely be useful, as you don't need a second rpc call to be able to exactly sort the logs, but it would not entirely address my usecase. Think of the scenario where a subcall is made where no logs are emitted: the global index would remain unchanged, so you can't sort the logs wrt that subcall.

It is definitely a bit of a niche use case, and I see how for most people just a global log index, that allows to keep the original log order without the receipt, could make more sense. In that case I agree reusing the logIndex field would be best, as it would have the same purpose and values.

@jsvisa
Copy link
Contributor

jsvisa commented Oct 26, 2023

Here is a simple example to present what @alvarosevilla95 what to do.

// SPDX-License-Identifier: GPL-3.0

pragma solidity >=0.8.2 <0.9.0;

contract Bar {
    uint x;
    function setX(uint _x) public {
        x = _x;
    }
}

contract Foo {
    event Call(address indexed from, address indexed to, uint indexed index);

    function callWithEvent(address _to) public {
        Bar bar = Bar(_to);
        bar.setX(0);
        emit Call(msg.sender, _to, 0);

        bar.setX(1);
        emit Call(msg.sender, _to, 1);
    }

    function callThenEvent(address _to) public {
        Bar bar = Bar(_to);
        bar.setX(0);
        bar.setX(1);
        emit Call(msg.sender, _to, 0);
        emit Call(msg.sender, _to, 1);
    }
}

the trace for callThenEvent

debug.traceTransaction( '0x62025a8d5bee781f139034a85e89b7722f2e057e0e24e25b35619f907e5a5c10', {'tracer': 'callTracer', 'tracerConfig': {'withLog': true}})
{
  "calls": [
    {
      "from": "0x52d3634b22b18b5076b696b9e597375b98bb3a33",
      "gas": "0x69bd",
      "gasUsed": "0xa26",
      "input": "0x4018d9aa0000000000000000000000000000000000000000000000000000000000000000",
      "to": "0xd79a837e2b3a2b370d14eec56850aaee7e83eb91",
      "type": "CALL",
      "value": "0x0"
    },
    {
      "from": "0x52d3634b22b18b5076b696b9e597375b98bb3a33",
      "gas": "0x5d63",
      "gasUsed": "0x4fae",
      "input": "0x4018d9aa0000000000000000000000000000000000000000000000000000000000000001",
      "to": "0xd79a837e2b3a2b370d14eec56850aaee7e83eb91",
      "type": "CALL",
      "value": "0x0"
    }
  ],
  "from": "0xf4d8223ff330debba976d219f459695090222640",
  "gas": "0xcce7",
  "gasUsed": "0xcce7",
  "input": "0x9864af23000000000000000000000000d79a837e2b3a2b370d14eec56850aaee7e83eb91",
  "logs": [
    {
      "address": "0x52d3634b22b18b5076b696b9e597375b98bb3a33",
      "data": "0x",
      "topics": [
        "0xda6f1030e46613a9add5390434c8e68a48f738007f0f5ab6986a52d0640a66f4",
        "0x000000000000000000000000f4d8223ff330debba976d219f459695090222640",
        "0x000000000000000000000000d79a837e2b3a2b370d14eec56850aaee7e83eb91",
        "0x0000000000000000000000000000000000000000000000000000000000000000"
      ]
    },
    {
      "address": "0x52d3634b22b18b5076b696b9e597375b98bb3a33",
      "data": "0x",
      "topics": [
        "0xda6f1030e46613a9add5390434c8e68a48f738007f0f5ab6986a52d0640a66f4",
        "0x000000000000000000000000f4d8223ff330debba976d219f459695090222640",
        "0x000000000000000000000000d79a837e2b3a2b370d14eec56850aaee7e83eb91",
        "0x0000000000000000000000000000000000000000000000000000000000000001"
      ]
    }
  ],
  "to": "0x52d3634b22b18b5076b696b9e597375b98bb3a33",
  "type": "CALL",
  "value": "0x0"
}

traces for callWithEvent

debug.traceTransaction( '0x04e38e0a4033915e560741828699e86c104491efa52cf34c2dedbae90da2cd99', {'tracer': 'callTracer', 'tracerConfig': {'withLog': true}})
{
  "calls": [
    {
      "from": "0x52d3634b22b18b5076b696b9e597375b98bb3a33",
      "gas": "0x2900",
      "gasUsed": "0x1516",
      "input": "0x4018d9aa0000000000000000000000000000000000000000000000000000000000000000",
      "to": "0xd79a837e2b3a2b370d14eec56850aaee7e83eb91",
      "type": "CALL",
      "value": "0x0"
    },
    {
      "from": "0x52d3634b22b18b5076b696b9e597375b98bb3a33",
      "gas": "0xa7e",
      "gasUsed": "0x1f2",
      "input": "0x4018d9aa0000000000000000000000000000000000000000000000000000000000000001",
      "to": "0xd79a837e2b3a2b370d14eec56850aaee7e83eb91",
      "type": "CALL",
      "value": "0x0"
    }
  ],
  "from": "0xf4d8223ff330debba976d219f459695090222640",
  "gas": "0x8b39",
  "gasUsed": "0x7f41",
  "input": "0xdccadbc2000000000000000000000000d79a837e2b3a2b370d14eec56850aaee7e83eb91",
  "logs": [
    {
      "address": "0x52d3634b22b18b5076b696b9e597375b98bb3a33",
      "data": "0x",
      "topics": [
        "0xda6f1030e46613a9add5390434c8e68a48f738007f0f5ab6986a52d0640a66f4",
        "0x000000000000000000000000f4d8223ff330debba976d219f459695090222640",
        "0x000000000000000000000000d79a837e2b3a2b370d14eec56850aaee7e83eb91",
        "0x0000000000000000000000000000000000000000000000000000000000000000"
      ]
    },
    {
      "address": "0x52d3634b22b18b5076b696b9e597375b98bb3a33",
      "data": "0x",
      "topics": [
        "0xda6f1030e46613a9add5390434c8e68a48f738007f0f5ab6986a52d0640a66f4",
        "0x000000000000000000000000f4d8223ff330debba976d219f459695090222640",
        "0x000000000000000000000000d79a837e2b3a2b370d14eec56850aaee7e83eb91",
        "0x0000000000000000000000000000000000000000000000000000000000000001"
      ]
    }
  ],
  "to": "0x52d3634b22b18b5076b696b9e597375b98bb3a33",
  "type": "CALL",
  "value": "0x0"
}

We can't find the difference between the two, and there is no way to know the order between the log and trace. But after this PR, we can see the differ:

image

@alvarosevilla95 please correct me if I'm wrong.

@s1na
Copy link
Contributor

s1na commented Oct 26, 2023

Think of the scenario where a subcall is made where no logs are emitted: the global index would remain unchanged, so you can't sort the logs wrt that subcall.

Yes your counter-example is valid. If there is no log emitted in a subcall it is not possible to say whether a log in the parent call was emitted before or after that subcall. I was mostly trying to understand if the index is enough, but seems like it's not. I'm fine with adding the position field.

@jsvisa thanks for the example!

@alvarosevilla95
Copy link
Contributor Author

Yeah @jsvisa that's a perfect example, thanks!

Copy link
Contributor

@s1na s1na left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

SGTM

@s1na
Copy link
Contributor

s1na commented Oct 26, 2023

CI is failing, can you please fix?

>>> build/cache/golangci-lint-1.51.1-linux-amd64/golangci-lint run --config .golangci.yml ./...
eth/tracers/native/call.go:40: File is not `goimports`-ed (goimports)
	Address  common.Address `json:"address"`
	Topics   []common.Hash  `json:"topics"`
	Data     hexutil.Bytes  `json:"data"`
util.go:48: exit status 1
exit status 1

@alvarosevilla95
Copy link
Contributor Author

CI is failing, can you please fix?

>>> build/cache/golangci-lint-1.51.1-linux-amd64/golangci-lint run --config .golangci.yml ./...
eth/tracers/native/call.go:40: File is not `goimports`-ed (goimports)
	Address  common.Address `json:"address"`
	Topics   []common.Hash  `json:"topics"`
	Data     hexutil.Bytes  `json:"data"`
util.go:48: exit status 1
exit status 1

Ah yes sorry about that. All green now

@jsvisa
Copy link
Contributor

jsvisa commented Oct 27, 2023

@s1na @alvarosevilla95 should we also add an index field to indicate the event's chronological order?

@s1na
Copy link
Contributor

s1na commented Oct 27, 2023

@jsvisa sure, but please make sure to have it consistent with the core log object. I believe it's called logIndex.

Signed-off-by: jsvisa <delweng@gmail.com>
Signed-off-by: jsvisa <delweng@gmail.com>
Signed-off-by: jsvisa <delweng@gmail.com>
@jsvisa
Copy link
Contributor

jsvisa commented Oct 28, 2023

  1. As we always return use hex-encoded integer instead of an integer, I changed the type of Position from int to hexutil.Uint.
  2. I also added a new LogIndex field.
  3. I added WRITE_TEST_FILES environment to rewrite the test response files, in this way you don't have to manually change a bunch of JSON files, so if we run the below command, it will rewrite the response file instead of the test checking:
WRITE_TEST_FILES=true go test ./eth/tracers/... -v

@s1na do you think this kind of adjustment is appropriate or not?

But seems I can't directly push to alvarosevilla95:master, so @alvarosevilla95 could you please cherry pick the commits from https://github.com/jsvisa/go-ethereum/tree/av-trace-position after @s1na approved those changes?

@s1na
Copy link
Contributor

s1na commented Oct 30, 2023

As we always return use hex-encoded integer instead of an integer, I changed the type of Position from int to hexutil.Uint.

Ah good catch! glad we didn't merge this before this fix.

I also added a new LogIndex field.

I checked your code and as I mentioned earlier it's not that simple. When there is a revert we will delete logs for some subcalls. That means those indices will be wiped. So all subsequent ones have to be updated.

@jsvisa
Copy link
Contributor

jsvisa commented Oct 31, 2023

I checked your code and as I mentioned earlier it's not that simple. When there is a revert we will delete logs for some subcalls. That means those indices will be wiped. So all subsequent ones have to be updated.

Thanks for the tips, so let's move this one first(after fixing the hexadecimal), and implement the logIndex in another PR.

@alvarosevilla95
Copy link
Contributor Author

Ah thanks for the catch about using hexutil.Uint @jsvisa, I missed the inconsistency there. Given the disccussion I've cherry-picked the position -> hex commits.

FWIW the write_test_files flags seems quite useful, would def have saved me time when changing the testcases, and in my case at least it was a relatively small change needed, but something bigger would get very annoying. But that can be decided on the follow up PR.

As a suggestion for logIndex, perhaps it makes sense to just add the logic to CaptureTxEnd, after the failed logs are cleared, and just assign all the indexes at that point.

@alvarosevilla95
Copy link
Contributor Author

alvarosevilla95 commented Oct 31, 2023

@s1na apologies but the CI is failing and I can't spot what is it complaining about.. can you help identify it?

@s1na
Copy link
Contributor

s1na commented Nov 2, 2023

@s1na apologies but the CI is failing and I can't spot what is it complaining about.. can you help identify it?

Ah don't mind that. That's just because the test suite times out on 32-bit build. It's a known issue.

As a suggestion for logIndex, perhaps it makes sense to just add the logic to CaptureTxEnd, after the failed logs are cleared, and just assign all the indexes at that point.

I'm afraid it's not possible to determine the order at that point similar to the reason why it's not possible to determine the "position". In fact that's why I confused your PR in the first place :) But we'll figure it out in a future PR. This one is good to go!

Copy link
Contributor

@s1na s1na left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@alvarosevilla95
Copy link
Contributor Author

alvarosevilla95 commented Nov 2, 2023

@s1na apologies but the CI is failing and I can't spot what is it complaining about.. can you help identify it?

Ah don't mind that. That's just because the test suite times out on 32-bit build. It's a known issue.

As a suggestion for logIndex, perhaps it makes sense to just add the logic to CaptureTxEnd, after the failed logs are cleared, and just assign all the indexes at that point.

I'm afraid it's not possible to determine the order at that point similar to the reason why it's not possible to determine the "position". In fact that's why I confused your PR in the first place :) But we'll figure it out in a future PR. This one is good to go!

Well, you can use the new position field to do it there, couldn't you? :D
After all failed logs have been cleared, you can recursively iterate the logs and subcalls, using Position to know when to perform the recursive step. Something like this:

func (t *callTracer) CaptureTxEnd(restGas uint64) {
	t.callstack[0].GasUsed = t.gasLimit - restGas
	if t.config.WithLog {
		// Logs are not emitted when the call fails
		clearFailedLogs(&t.callstack[0], false)
		assignLogIndexes(&t.callstack[0], 0)
	}
}

func assignLogIndexes(cf *callFrame, index hexutil.Uint) hexutil.Uint {
	subCallIndex := hexutil.Uint(0)
	for i := range cf.Logs {
		for subCallIndex < cf.Logs[i].Position {
			index = assignLogIndexes(&cf.Calls[subCallIndex], index)
			subCallIndex++
		}
		cf.Logs[i].LogIndex = index
		index++
	}
	for subCallIndex < hexutil.Uint(len(cf.Calls)) {
		index = assignLogIndexes(&cf.Calls[subCallIndex], index)
		subCallIndex++
	}
	return index
}

Or maybe I'm missing something, just a suggestion anyway!

@s1na s1na merged commit b1cec85 into ethereum:master Nov 3, 2023
2 checks passed
@s1na
Copy link
Contributor

s1na commented Nov 3, 2023

Well, you can use the new position field to do it there, couldn't you? :D

Ah absolutely! good thinking.

Thanks for the PR and being patient and responsive through the review process!

devopsbo3 pushed a commit to HorizenOfficial/go-ethereum that referenced this pull request Nov 10, 2023
Currently, one can use the "withLogs" parameter to include logs in the
callTracer results, which allows the user to see at which trace level
was each log emitted.
This commit adds a position field to the logs which determine
the exact ordering of a call's logs and its subcalls. This would
be useful e.g. for explorers wishing to display the flow of execution.

Co-authored-by: jsvisa <delweng@gmail.com>
devopsbo3 added a commit to HorizenOfficial/go-ethereum that referenced this pull request Nov 10, 2023
devopsbo3 added a commit to HorizenOfficial/go-ethereum that referenced this pull request Nov 10, 2023
Dergarcon pushed a commit to specialmechanisms/mev-geth-0x2mev that referenced this pull request Jan 31, 2024
Currently, one can use the "withLogs" parameter to include logs in the
callTracer results, which allows the user to see at which trace level
was each log emitted.
This commit adds a position field to the logs which determine
the exact ordering of a call's logs and its subcalls. This would
be useful e.g. for explorers wishing to display the flow of execution.

Co-authored-by: jsvisa <delweng@gmail.com>
colinlyguo pushed a commit to scroll-tech/go-ethereum that referenced this pull request Oct 31, 2024
Currently, one can use the "withLogs" parameter to include logs in the
callTracer results, which allows the user to see at which trace level
was each log emitted.
This commit adds a position field to the logs which determine
the exact ordering of a call's logs and its subcalls. This would
be useful e.g. for explorers wishing to display the flow of execution.

Co-authored-by: jsvisa <delweng@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants