Race condition in `JsonRpcExecutor`
Dzejkop opened this issue · 7 comments
Dzejkop commented
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)
- Start up Besu
- Frequently call
eth_callwith 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 commented
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 commented
@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 commented
@samsondav, checking in again. Are you still seeing the error? If yes, we would love to help investigate the issue.
citizen-stig commented
@samsondav , We still have this bug in our private QBFT deployment
massun-onibakuchi commented
same issue here.
massun-onibakuchi commented
I use Besu and call eth_call with ethersjs. besu version : besu-22.10.2
I run Besu on EC2 instance and call from another EC2 instance.
Error
something like this.
"error\\\" : {\\n \\\"code\\\" : -32000,\\n \\\"message\\\" : \\\"Block not found\\\"\\n }\\n}\",\"error\":{\"code\":-32000},\"requestBody\":\"{\\\"method\\\":\\\"eth_call\\\",\\\"params\\\":[{\\\"to\\\":\\\"0x1e2f9e10d02a6b8f8f69fcbf515e75039d2ea30d\\\",\\\"data\\\":\\\"0xb4658bfb000000000000000000000000000000000000000000000000000000000000004000000000000000000000000000000000000000000000000000000000000001e000000000000000000000000000000000000000000000000000000000000000010000000000000000000000001d7022f5b17d2f8b695918fb48fa1089c9f854010000000000000000000000000b1ba0af832d7c05fd64161e0db78e85978e8082000000000000000000000000000000000000000000000018baaaf5637dd7aba00000000000000000000000000000000000000000000000008ac7230489e800000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000a9f3a3e8eac6461d83072dbc2ae64f765b46ab3400000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000063a48dc7000000000000000000000000000000000000000000000000000001853ac800b200000000000000000000000000000000000000000000000000000000000000010000000000000000000000000000000000000000000000000000000000000003000000000000000000000000000000000000000000000000000000000000001c97d558b84456e3a943922ff6132fecd633bc4797909fe657bfd08cd82368bc1a27e01c22ea28745eaaeba45d5defcab0cdddb7ac3deac6bbed7abd3ce8218f7e\\\"},\\\"latest\\\"],\\\"id\\\":405348,\\\"jsonrpc\\\":\\\"2.0\\\"}\",\"requestMethod\":\"POST\",\"url\":\"http://54.65.214.149:8545\"},
frequency
sometimes I got the error 90 times when i try 420000 times.
massun-onibakuchi commented
I have not yet been able to reproduce it.