Race condition in `JsonRpcExecutor`

[Dzejkop]

Description

We started noticing that when we're frequently using the eth_call method, every now and then it would fail unexpectedly with the Block not found error.

After observing the logs I believe the issue is a race condition:

Logs from the time the error occured:

2022-07-28 13:39:11.899+00:00 | vert.x-worker-thread-15 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_call [{to=0xd0f52767c5d2d3a5a1b5de558dc673ad35a4b7e8, data=0x003e36bf000000000000000000000000d0584d4d37157f7105a4b41ed8ecbdfafdb2547f}, latest]
2022-07-28 13:39:11.901+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:11.901+00:00 | vert.x-worker-thread-14 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_call [{to=0xd0f52767c5d2d3a5a1b5de558dc673ad35a4b7e8, data=0x6adb038b}, latest]
2022-07-28 13:39:11.951+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:11.952+00:00 | vert.x-worker-thread-16 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_blockNumber []
2022-07-28 13:39:12.001+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | IbftRound | Creating proposed block. round=ConsensusRoundIdentifier{Sequence=862, Round=0}
2022-07-28 13:39:12.002+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:12.003+00:00 | vert.x-worker-thread-2 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_call [{to=0xd0f52767c5d2d3a5a1b5de558dc673ad35a4b7e8, data=0x003e36bf000000000000000000000000d0584d4d37157f7105a4b41ed8ecbdfafdb2547f}, latest]
2022-07-28 13:39:12.005+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | IbftRound | Sending commit message. round=ConsensusRoundIdentifier{Sequence=862, Round=0}
2022-07-28 13:39:12.006+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:12.006+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | IbftRound | Importing block to chain. round=ConsensusRoundIdentifier{Sequence=862, Round=0}, hash=0x402c2dad739593c3dd5a6efc5f051c1bdf6ab1eaef0240da42cb222652155e0f
2022-07-28 13:39:12.007+00:00 | vert.x-worker-thread-17 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_call [{to=0xd0f52767c5d2d3a5a1b5de558dc673ad35a4b7e8, data=0x6adb038b}, latest]
2022-07-28 13:39:12.008+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | TransactionLogBloomCacher | Caching logs bloom for block 0x35e.
2022-07-28 13:39:12.009+00:00 | BftProcessorExecutor-IBFT-0 | INFO  | IbftBesuControllerBuilder | Produced #862 / 0 tx / 0 pending / 0 (0.0%) gas / (0x402c2dad739593c3dd5a6efc5f051c1bdf6ab1eaef0240da42cb222652155e0f)
2022-07-28 13:39:12.009+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | BaseBftController | New chain head detected (block number=862), currently mining on top of 861.
2022-07-28 13:39:12.056+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:12.056+00:00 | vert.x-worker-thread-19 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_blockNumber []

Logs from other calls to eth_call that didn't fail:

2022-07-28 13:39:10.975+00:00 | vert.x-worker-thread-5 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_call [{to=0xd0f52767c5d2d3a5a1b5de558dc673ad35a4b7e8, data=0x003e36bf000000000000000000000000d0584d4d37157f7105a4b41ed8ecbdfafdb2547f}, latest]
2022-07-28 13:39:10.984+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:10.986+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:10.987+00:00 | vert.x-worker-thread-7 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_blockNumber []
2022-07-28 13:39:10.987+00:00 | vert.x-worker-thread-7 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_call [{to=0xd0f52767c5d2d3a5a1b5de558dc673ad35a4b7e8, data=0x6adb038b}, latest]
2022-07-28 13:39:11.004+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | IbftRound | Creating proposed block. round=ConsensusRoundIdentifier{Sequence=861, Round=0}
2022-07-28 13:39:11.007+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | IbftRound | Sending commit message. round=ConsensusRoundIdentifier{Sequence=861, Round=0}
2022-07-28 13:39:11.009+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | IbftRound | Importing block to chain. round=ConsensusRoundIdentifier{Sequence=861, Round=0}, hash=0x9776c29ee0d9c5656f01f487b3e44c3f8bf329af4a827950cff34738a23a9c23
2022-07-28 13:39:11.011+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | TransactionLogBloomCacher | Caching logs bloom for block 0x35d.
2022-07-28 13:39:11.012+00:00 | BftProcessorExecutor-IBFT-0 | INFO  | IbftBesuControllerBuilder | Produced #861 / 0 tx / 0 pending / 0 (0.0%) gas / (0x9776c29ee0d9c5656f01f487b3e44c3f8bf329af4a827950cff34738a23a9c23)
2022-07-28 13:39:11.012+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | BaseBftController | New chain head detected (block number=861), currently mining on top of 860.
2022-07-28 13:39:11.078+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:11.078+00:00 | vert.x-worker-thread-9 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_call [{to=0xd0f52767c5d2d3a5a1b5de558dc673ad35a4b7e8, data=0x003e36bf000000000000000000000000d0584d4d37157f7105a4b41ed8ecbdfafdb2547f}, latest]
2022-07-28 13:39:11.089+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:11.090+00:00 | vert.x-worker-thread-8 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_call [{to=0xd0f52767c5d2d3a5a1b5de558dc673ad35a4b7e8, data=0x6adb038b}, latest]

2022-07-28 13:39:12.900+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:12.900+00:00 | vert.x-worker-thread-7 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_blockNumber []
2022-07-28 13:39:12.930+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:12.931+00:00 | vert.x-worker-thread-4 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_call [{to=0xd0f52767c5d2d3a5a1b5de558dc673ad35a4b7e8, data=0x003e36bf000000000000000000000000d0584d4d37157f7105a4b41ed8ecbdfafdb2547f}, latest]
2022-07-28 13:39:12.932+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:12.933+00:00 | vert.x-worker-thread-9 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_call [{to=0xd0f52767c5d2d3a5a1b5de558dc673ad35a4b7e8, data=0x6adb038b}, latest]
2022-07-28 13:39:13.007+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | IbftRound | Creating proposed block. round=ConsensusRoundIdentifier{Sequence=863, Round=0}
2022-07-28 13:39:13.011+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | IbftRound | Sending commit message. round=ConsensusRoundIdentifier{Sequence=863, Round=0}
2022-07-28 13:39:13.013+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | IbftRound | Importing block to chain. round=ConsensusRoundIdentifier{Sequence=863, Round=0}, hash=0x821cee9098df3b642949b04ae0e9bd38f65d8098a0ab27db202fecbb15eb1755
2022-07-28 13:39:13.015+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | TransactionLogBloomCacher | Caching logs bloom for block 0x35f.
2022-07-28 13:39:13.015+00:00 | BftProcessorExecutor-IBFT-0 | INFO  | IbftBesuControllerBuilder | Produced #863 / 0 tx / 0 pending / 0 (0.0%) gas / (0x821cee9098df3b642949b04ae0e9bd38f65d8098a0ab27db202fecbb15eb1755)
2022-07-28 13:39:13.015+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | BaseBftController | New chain head detected (block number=863), currently mining on top of 862.
2022-07-28 13:39:13.017+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:13.018+00:00 | vert.x-worker-thread-8 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_blockNumber []
2022-07-28 13:39:13.021+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:13.021+00:00 | vert.x-worker-thread-10 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_getLogs [{fromBlock=0x35e, toBlock=0x35e, address=0xd0f52767c5d2d3a5a1b5de558dc673ad35a4b7e8, topics=[[0x9d5e3328d970a5c6148e8517851833559e79a94a9e23c376e4fee239d22b0bd1, 0x0c8c078f4dd07dbcb3760ab8ea213e22ae0a6f5131ac172980591d05e85ea41c, 0x274b9db18c1fe5545e1e46c41c24276caa16ea2666000637ed1d9517adcec0dc, 0x953e2be1a971fbc42605a647cf3cfe0ddfeb9ee42a202c2d78d3b24d7a3e1d15]]}]
2022-07-28 13:39:13.023+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:13.023+00:00 | vert.x-worker-thread-13 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_blockNumber []
2022-07-28 13:39:13.035+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.

2022-07-28 13:39:13.860+00:00 | vert.x-worker-thread-14 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_call [{to=0xd0f52767c5d2d3a5a1b5de558dc673ad35a4b7e8, data=0x6adb038b}, latest]
2022-07-28 13:39:13.904+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:13.904+00:00 | vert.x-worker-thread-16 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_blockNumber []
2022-07-28 13:39:13.960+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:13.961+00:00 | vert.x-worker-thread-2 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_call [{to=0xd0f52767c5d2d3a5a1b5de558dc673ad35a4b7e8, data=0x003e36bf000000000000000000000000d0584d4d37157f7105a4b41ed8ecbdfafdb2547f}, latest]
2022-07-28 13:39:13.962+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:13.963+00:00 | vert.x-worker-thread-18 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_call [{to=0xd0f52767c5d2d3a5a1b5de558dc673ad35a4b7e8, data=0x6adb038b}, latest]
2022-07-28 13:39:14.002+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | IbftRound | Creating proposed block. round=ConsensusRoundIdentifier{Sequence=864, Round=0}
2022-07-28 13:39:14.003+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | IbftRound | Sending commit message. round=ConsensusRoundIdentifier{Sequence=864, Round=0}
2022-07-28 13:39:14.004+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | IbftRound | Importing block to chain. round=ConsensusRoundIdentifier{Sequence=864, Round=0}, hash=0xdecd60ebd89319caddabae991d531a5968f3630b2c07017cd553bee7be31b7c2
2022-07-28 13:39:14.005+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | TransactionLogBloomCacher | Caching logs bloom for block 0x360.
2022-07-28 13:39:14.005+00:00 | BftProcessorExecutor-IBFT-0 | INFO  | IbftBesuControllerBuilder | Produced #864 / 0 tx / 0 pending / 0 (0.0%) gas / (0xdecd60ebd89319caddabae991d531a5968f3630b2c07017cd553bee7be31b7c2)
2022-07-28 13:39:14.005+00:00 | BftProcessorExecutor-IBFT-0 | DEBUG | BaseBftController | New chain head detected (block number=864), currently mining on top of 863.
2022-07-28 13:39:14.007+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:14.007+00:00 | vert.x-worker-thread-19 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_blockNumber []
2022-07-28 13:39:14.008+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:14.009+00:00 | vert.x-worker-thread-0 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_getLogs [{fromBlock=0x35f, toBlock=0x35f, address=0xd0f52767c5d2d3a5a1b5de558dc673ad35a4b7e8, topics=[[0x9d5e3328d970a5c6148e8517851833559e79a94a9e23c376e4fee239d22b0bd1, 0x0c8c078f4dd07dbcb3760ab8ea213e22ae0a6f5131ac172980591d05e85ea41c, 0x274b9db18c1fe5545e1e46c41c24276caa16ea2666000637ed1d9517adcec0dc, 0x953e2be1a971fbc42605a647cf3cfe0ddfeb9ee42a202c2d78d3b24d7a3e1d15]]}]
2022-07-28 13:39:14.010+00:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2022-07-28 13:39:14.010+00:00 | vert.x-worker-thread-1 | DEBUG | JsonRpcExecutor | JSON-RPC request -> eth_blockNumber []

the fact that the error case has BftProcessorExecutor logs mixed with JsonRpcExecutor makes me believe that some sort of race condition is occuring, but that's all I was able to figure out.

Steps to Reproduce (Bug)

1. Start up Besu
2. Frequently call eth_call with with any smart contract method

Expected behavior:
No errors

Actual behavior:
Besu returns Block not found

Frequency:
We saw it occuring say after 2 or so minutes of running our software.

Versions

Docker image labels:

"org.label-schema.build-date": "2022-07-13T11:08Z",
"org.label-schema.description": "Enterprise Ethereum client",
"org.label-schema.name": "Besu",
"org.label-schema.schema-version": "1.0",
"org.label-schema.url": "https://besu.hyperledger.org/",
"org.label-schema.vcs-ref": "b85b39d3",
"org.label-schema.vcs-url": "https://github.com/hyperledger/besu.git",
"org.label-schema.vendor": "Hyperledger",
"org.label-schema.version": "22.7.0-RC2-SNAPSHOT"

• Software version: 22.7.0-RC2-SNAPSHOT
  We observed this issue on M1 MacBooks and also on our CI - which last time I checked was running various generations of Intel Xeon.

[samsondav]

We are also seeing this bug, it's a blocker for us to use Chainlink with Besu. We need reliable RPC calls.

One example RPC call that triggered it:

curl -v --data '{"method":"eth_call","id":"1","params":[{"from": "0x0000000000000000000000000000000000000000", "to": "0x4c0ce02c1219ce5d2afffba97e484272a4637b49", "gas": 9800000, "data":"c41b813a000000000000000000000000000000000000000000000000000000000000000000000000000000000000000084b90895ef775e63adfc50a4e15b5beea08c0b7f"}, "latest"],"jsonrpc":"2.0"}' -H "Content-Type: application/json" -X POST http://besu-rpc-goerli.example.com

Note that this usually returns the correct payload:

{
  "jsonrpc": "2.0",
  "id": "1",
  "error": {
    "code": -32000,
    "message": "Execution reverted",
    "data": "0x08c379a00000000000000000000000000000000000000000000000000000000000000020000000000000000000000000000000000000000000000000000000000000001175706b656570206e6f74206e6565646564000000000000000000000000000000"
  }
}

But, sometimes it instead returns "Block not found" error as detailed in the OP.

The problem is intermittent.

[jflo]

@samsondav I am assuming this was found on goerli based on the domain in your curl command. Is that true? If so how frequently and how long did you loop this statement to create the "Block not found" error. I have not yet been able to reproduce it.

[iamhsk]

@samsondav, checking in again. Are you still seeing the error? If yes, we would love to help investigate the issue.

[citizen-stig]

@samsondav , We still have this bug in our private QBFT deployment

[massun-onibakuchi]

same issue here.