Trace response of traceBlockByHash is non-deterministic and get "execution reverted" error

[ghost]

System information

Geth version: v1.10.2

Expected behaviour

1. When getting block traces using traceBlockByHash, the response should be deterministic
2. For a transaction with Success status, should not get "execution reverted" trace error

Actual behaviour

In Ethereum mainnet

1. Run debug.traceBlockByHash("0x27049febec8fd16fb662d0d8c00f5ff7cec571b71585b18c30e0c6d2df93b4fe", {"tracer": "callTracer", "timeout": "60s"}) twice, get different trace result for the transaction 0x44de5f0ce469c09e4003f974e4ae119aea69ac461fdb0974fe410a1657284ce5

First time tx trace result:

    result: {
      calls: [{...}],
      from: "0x00000000c0293c8ca34dac9bcc0f953532d34e4d",
      gas: "0xa7ac",
      gasUsed: "0x6876",
      input: "0xca722cdc5ae6e1d89dcdb255d8851f3b47f374103d5022146b4e29a3bf4aea91993ae06fdd3d5766c2b7db16c171487fdb4800eaabf851f35488b76b33e53faa21b36588",
      output: "0x",
      time: "86.428742ms",
      to: "0xd1ceeeeee83f8bcf3bedad437202b6154e9f5405",
      type: "CALL",
      value: "0x0"
    }
}

Second time tx trace result:

{
    result: {
      error: "execution reverted",
      from: "0x00000000c0293c8ca34dac9bcc0f953532d34e4d",
      gas: "0xa7ac",
      gasUsed: "0xa8f",
      input: "0xca722cdc5ae6e1d89dcdb255d8851f3b47f374103d5022146b4e29a3bf4aea91993ae06fdd3d5766c2b7db16c171487fdb4800eaabf851f35488b76b33e53faa21b36588",
      time: "15.241119ms",
      to: "0xd1ceeeeee83f8bcf3bedad437202b6154e9f5405",
      type: "CALL",
      value: "0x0"
    }
}

2. Why get "execution reverted" error for the successful transaction 0x44de5f0ce469c09e4003f974e4ae119aea69ac461fdb0974fe410a1657284ce5 at the second traceBlockByHash call

[rjl493456442]

So I ran the tracing for a few times with the latest master code, but I can't reproduce your issue. Can you please try the latest master if it still happens to you?

geth attach ./ssd/geth_data/geth.ipc --exec "debug.traceBlockByHash('0x27049febec8fd16fb662d0d8c00f5ff7cec571b71585b18c30e0c6d2df93b4fe', {'tracer': 'callTracer',
'timeout': '60s'})" > output

[jiezhang]

Here's another repro using a newer version v1.10.4. It returned out-of-gas error in the first call and subsequently traced the transaction successfully.

The transaction with non-deterministic tracing result is linked here.

After you try the following commands, you may need to wait for a while before you can repro the issue again, potentially due to some state being cached in the node.

Welcome to the Geth JavaScript console!

instance: Geth/v1.10.4-stable-aa637fd3/linux-amd64/go1.15.13
at block: 12826894 (Wed Jul 14 2021 12:06:57 GMT-0700 (PDT))
 modules: debug:1.0 eth:1.0 net:1.0 rpc:1.0 web3:1.0

To exit, press ctrl-d
> debug.traceBlockByNumber(11087337, {"tracer": "callTracer", "timeout": "60s"})[30]
{
  result: {
    calls: [{
        from: "0x06012c8cf97bead5deae237070f9587f8e7a266d",
        gas: "0x345fe",
        gasUsed: "0x19b0c",
        input: "0x0d9f5aed00006ad0859dab4a46372c493304c1a46c0a0a24b092428a07255b20582794e1000032d2b71c84498013aca2004ce7bd4578c8c7b1ea5398c4217a2a84a198030000000000000000000000000000000000000000000000000000000000a92da9",
        output: "0x00006ad28391c4480235b8450818e7a8650bc8c4bc8a430ac7215b50822198e1",
        to: "0xb77feddb7e627a78140a2a32cac65a49ed1dba8e",
        type: "CALL",
        value: "0x0"
    }],
    error: "out of gas",
    from: "0x09191d18729da57a83a9afc8ace0c8d7d104e118",
    gas: "0x38c86",
    gasUsed: "0x38c86",
    input: "0x88c2a0bf0000000000000000000000000000000000000000000000000000000000183e2c",
    time: "659.691392ms",
    to: "0x06012c8cf97bead5deae237070f9587f8e7a266d",
    type: "CALL",
    value: "0x0"
  }
}
> debug.traceBlockByNumber(11087337, {"tracer": "callTracer", "timeout": "60s"})[30]
{
  result: {
    calls: [{
        from: "0x06012c8cf97bead5deae237070f9587f8e7a266d",
        gas: "0x345fe",
        gasUsed: "0x195e2",
        input: "0x0d9f5aed00006ad0859dab4a46372c493304c1a46c0a0a24b092428a07255b20582794e1000032d2b71c84498013aca2004ce7bd4578c8c7b1ea5398c4217a2a84a198030000000000000000000000000000000000000000000000000000000000a92da9",
        output: "0x00006ad28590eb48d2172c4b0044c7a4651bc2c63df2428a07255b2a982198e0",
        to: "0xb77feddb7e627a78140a2a32cac65a49ed1dba8e",
        type: "CALL",
        value: "0x0"
    }, {
        from: "0x06012c8cf97bead5deae237070f9587f8e7a266d",
        input: "0x",
        output: "0x",
        to: "0x09191d18729da57a83a9afc8ace0c8d7d104e118",
        type: "CALL",
        value: "0x1c6bf526340000"
    }],
    from: "0x09191d18729da57a83a9afc8ace0c8d7d104e118",
    gas: "0x38c86",
    gasUsed: "0x383dd",
    input: "0x88c2a0bf0000000000000000000000000000000000000000000000000000000000183e2c",
    output: "0x00000000000000000000000000000000000000000000000000000000001e1289",
    time: "1.073330468s",
    to: "0x06012c8cf97bead5deae237070f9587f8e7a266d",
    type: "CALL",
    value: "0x0"
  }
}

[jiezhang]

We have observed lots of transactions exhibiting this non-deterministic tracing behavior. Coincidentally they all seem to interact with following two contracts:

• Dice2Win
• CryptoKitties

[karalabe]

Do you have some logs from the Geth node executing these? Do you see warnings that it might be running out of file descriptors? If the database remains without those, it starts returning empty responses to state requests, which might explain occasional bad traces.

[MariusVanDerWijden]

This is the tx btw: https://etherscan.io/tx/0x7c03e48c1ceb3cd30f53c76fec97ab57b9073e21e598cf8afcddc1e4b38accf6

[max-mapper]

I am able to reproduce this issue by tracing the hash shared by OP: curl -X POST -H "Content-Type: application/json" --data '{"method":"debug_traceBlockByHash","params":["0x27049febec8fd16fb662d0d8c00f5ff7cec571b71585b18c30e0c6d2df93b4fe",{"tracer":"callTracer","timeout":null}],"id":15293,"jsonrpc":"2.0"}' http://localhost:8545

I ran that twice (on geth master, archive mode), the first time it took 30 seconds to complete, and the second 1.5 seconds. The only difference was this:

I'm also seeing many execution reverted errors on other blocks. Edit: there's nothing weird in our geth logs, and our ulimit -n is set to 1048576

[holiman]

@maxogden thanks, I'll try to debug this next week

[holiman]

I'm having some problems obtaining the data to repro this, since the blocks are so old. Does anyone have a more recent example to try and repro this with?

[ghost]

Seems we get this issue again, and this time those transactions seem to interact with this smart contract.

Transaction examples:
https://etherscan.io/tx/0x3174ce409b9895dae36fa3869587b0937d102f896a662fea65c6471a994c6423
https://etherscan.io/tx/0x0827f411f7f8bc7256786d8486a9e04990540e57770b4f4eecbbbc03220be547
https://etherscan.io/tx/0x7b05c28bcacc8b521f426096027c73c7d24a0761e19c7f6e311da2d18ee2a27d

@holiman could you help take a look on this? Thanks!

[holiman]

could you help take a look on this? Thanks

Yup, will do

[holiman]

Ok, managed to repro it!

[holiman]

Out of 7 blockdumps, two are different from the other five. I set the node to archive-mode as it was processing that block, so this has nothing to do with any errors during the reexec-phase -- all the trie data is at hand.
Very curious.

1733636 jan 24 16:42 out.1
1733636 jan 24 16:43 out.2
1738663 jan 24 16:43 out.3
1733636 jan 24 16:43 out.4
1733636 jan 24 16:43 out.5
1738663 jan 24 16:43 out.6
1733636 jan 24 16:43 out.7

[ghost]

@holiman Thanks for the fix! Any idea when will this get released? Thanks