besu
besu copied to clipboard
Ropsten: Unable to trace_block [0xbe70da] - error 500, blocks whole node
Besu is unable to return traces for one specific block on ropsten, which makes it unusable for indexing transaction from traces.
Steps to Reproduce (Bug)
- launch Besu+Teku on ropsten
- wait for it to be fully synced (both Eth1 and beacon API return syncing = false)
- request traces for block https://ropsten.etherscan.io/block/12480730
curl --request POST 'localhost:8545' \
--header 'Content-Type: application/json' \
--data-raw '{
"jsonrpc": "2.0",
"method": "trace_block",
"params": ["0xbe70da"],
"id": "test"
}' -v
besu-merge-besu-1 | 2022-07-04 09:52:46.551+00:00 | vert.x-worker-thread-16 | DEBUG | JsonRpcExecutor | JSON-RPC request -> trace_block [0xbe70da]
Expected behavior: Should return traces, continue to operate and respond to other RPC requests. Like it succesfully does for the previous and following blocks (0xbe70d9, 0xbe70db).
Actual behavior: HTTP request blocks for multiple minutes, eventually finishes with error 500. In that time all other RPC requests are blocked as well. The log is full with:
besu-merge-besu-1 | 2022-07-04 09:53:51.409+00:00 | vertx-blocked-thread-checker | WARN | BlockedThreadChecker | Thread Thread[vert.x-worker-thread-16,5,main] has been blocked for 64853 ms, time limit is 60000 ms
besu-merge-besu-1 | io.vertx.core.VertxException: Thread blocked
besu-merge-besu-1 | at app//org.apache.tuweni.bytes.MutableBytes32.create(MutableBytes32.java:28)
besu-merge-besu-1 | at app//org.apache.tuweni.bytes.Bytes32.leftPad(Bytes32.java:177)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.vm.DebugOperationTracer.captureStack(DebugOperationTracer.java:218)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.vm.DebugOperationTracer.traceExecution(DebugOperationTracer.java:59)
besu-merge-besu-1 | at app//org.hyperledger.besu.evm.EVM.executeNextOperation(EVM.java:81)
besu-merge-besu-1 | at app//org.hyperledger.besu.evm.EVM.runToHalt(EVM.java:74)
besu-merge-besu-1 | at app//org.hyperledger.besu.evm.processor.AbstractMessageProcessor.codeExecute(AbstractMessageProcessor.java:161)
besu-merge-besu-1 | at app//org.hyperledger.besu.evm.processor.AbstractMessageProcessor.process(AbstractMessageProcessor.java:173)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.mainnet.MainnetTransactionProcessor.process(MainnetTransactionProcessor.java:485)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.mainnet.MainnetTransactionProcessor.processTransaction(MainnetTransactionProcessor.java:397)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.mainnet.MainnetTransactionProcessor.processTransaction(MainnetTransactionProcessor.java:181)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.processor.BlockTracer.lambda$prepareReplayAction$0(BlockTracer.java:60)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.processor.BlockTracer$$Lambda$1369/0x0000000840703c40.performAction(Unknown Source)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.processor.BlockReplay.lambda$block$0(BlockReplay.java:60)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.processor.BlockReplay$$Lambda$1371/0x0000000840710440.apply(Unknown Source)
besu-merge-besu-1 | at [email protected]/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
besu-merge-besu-1 | at [email protected]/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1655)
besu-merge-besu-1 | at [email protected]/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
besu-merge-besu-1 | at [email protected]/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
besu-merge-besu-1 | at [email protected]/java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:913)
besu-merge-besu-1 | at [email protected]/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
besu-merge-besu-1 | at [email protected]/java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:578)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.processor.BlockReplay.lambda$block$1(BlockReplay.java:66)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.processor.BlockReplay$$Lambda$1370/0x0000000840710040.perform(Unknown Source)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.processor.BlockReplay.performActionWithBlock(BlockReplay.java:155)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.processor.BlockReplay.block(BlockReplay.java:52)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.processor.BlockTracer.trace(BlockTracer.java:45)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.TraceBlock.traceBlock(TraceBlock.java:94)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.TraceBlock.lambda$resultByBlockNumber$0(TraceBlock.java:79)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.TraceBlock$$Lambda$1367/0x0000000840704440.apply(Unknown Source)
besu-merge-besu-1 | at [email protected]/java.util.Optional.map(Optional.java:265)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.TraceBlock.resultByBlockNumber(TraceBlock.java:79)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.AbstractBlockParameterMethod.findResultByParamType(AbstractBlockParameterMethod.java:88)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.AbstractBlockParameterMethod.response(AbstractBlockParameterMethod.java:102)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.BaseJsonRpcProcessor.process(BaseJsonRpcProcessor.java:42)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.TracedJsonRpcProcessor.process(TracedJsonRpcProcessor.java:41)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.TimedJsonRpcProcessor.process(TimedJsonRpcProcessor.java:45)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.JsonRpcExecutor.execute(JsonRpcExecutor.java:91)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.lambda$handler$6(JsonRpcExecutorHandler.java:76)
besu-merge-besu-1 | at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler$$Lambda$731/0x00000008404b9440.handle(Unknown Source)
besu-merge-besu-1 | at app//io.vertx.ext.web.impl.BlockingHandlerDecorator.lambda$handle$0(BlockingHandlerDecorator.java:48)
besu-merge-besu-1 | at app//io.vertx.ext.web.impl.BlockingHandlerDecorator$$Lambda$1110/0x000000084068b440.handle(Unknown Source)
besu-merge-besu-1 | at app//io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
besu-merge-besu-1 | at app//io.vertx.core.impl.ContextImpl$$Lambda$950/0x00000008405d6c40.handle(Unknown Source)
besu-merge-besu-1 | at app//io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
besu-merge-besu-1 | at app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
besu-merge-besu-1 | at app//io.vertx.core.impl.ContextImpl$$Lambda$946/0x00000008405d4840.run(Unknown Source)
besu-merge-besu-1 | at app//io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
besu-merge-besu-1 | at app//io.vertx.core.impl.TaskQueue$$Lambda$667/0x000000084048c040.run(Unknown Source)
besu-merge-besu-1 | at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
besu-merge-besu-1 | at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
besu-merge-besu-1 | at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
besu-merge-besu-1 | at [email protected]/java.lang.Thread.run(Thread.java:829)
Also teku complains immediately and does not sync new blocks anymore:
besu-merge-teku-1 | 2022-07-04 09:52:58.986 ERROR - Execution Client is offline
besu-merge-teku-1 | java.util.concurrent.TimeoutException: null
The node recovers a few minutes after that and starts to respond again.
Frequency: 100% with this block/RPC
Versions (Add all that apply)
- Software/Java version: official docker imge:
hyperledger/besu:22.4.3-openjdk-11-amd64
- OS Name & Version: Ubuntu 20.04.4 LTS
- Kernel Version: 5.4.0-121-generic
- Docker Version: 20.10.17
Additional Information
- Besu setup info
"--data-path=/var/lib/besu/",
"--network=ropsten",
"--rpc-http-enabled=true",
"--rpc-http-host=0.0.0.0",
"--rpc-http-cors-origins=*",
"--host-allowlist=*",
"--engine-host-allowlist=*",
"--engine-jwt-enabled=true",
"--engine-rpc-http-port=8550",
"--Xmerge-support=true",
"--engine-jwt-secret=/run/secrets/jwtsecret",
"--override-genesis-config=terminalTotalDifficulty=50000000000000000",
"--logging=DEBUG"
- System info - 64GB RAM, 1TB SSD
- Not sure if it is related, but the debug level log regularly contains:
besu-merge-besu-1 | 2022-07-04 09:53:21.715+00:00 | nioEventLoopGroup-3-5 | DEBUG | DeFramer | Invalid incoming message
besu-merge-besu-1 | io.netty.handler.codec.DecoderException: org.hyperledger.besu.ethereum.rlp.RLPException: Expected current item to be a list, but it is: BYTE_ELEMENT (at bytes 0-1: [04])
besu-merge-besu-1 | at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:480)
besu-merge-besu-1 | at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:279)
besu-merge-besu-1 | at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
besu-merge-besu-1 | at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
besu-merge-besu-1 | at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
besu-merge-besu-1 | at org.hyperledger.besu.ethereum.p2p.rlpx.connections.netty.AbstractHandshakeHandler.channelRead0(AbstractHandshakeHandler.java:135)
besu-merge-besu-1 | at org.hyperledger.besu.ethereum.p2p.rlpx.connections.netty.AbstractHandshakeHandler.channelRead0(AbstractHandshakeHandler.java:44)
besu-merge-besu-1 | at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99)
besu-merge-besu-1 | at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
besu-merge-besu-1 | at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
besu-merge-besu-1 | at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
besu-merge-besu-1 | at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
besu-merge-besu-1 | at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
besu-merge-besu-1 | at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
besu-merge-besu-1 | at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
besu-merge-besu-1 | at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
besu-merge-besu-1 | at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722)
besu-merge-besu-1 | at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658)
besu-merge-besu-1 | at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584)
besu-merge-besu-1 | at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496)
besu-merge-besu-1 | at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
besu-merge-besu-1 | at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
besu-merge-besu-1 | at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
besu-merge-besu-1 | at java.base/java.lang.Thread.run(Thread.java:829)
besu-merge-besu-1 | Caused by: org.hyperledger.besu.ethereum.rlp.RLPException: Expected current item to be a list, but it is: BYTE_ELEMENT (at bytes 0-1: [04])
besu-merge-besu-1 | at org.hyperledger.besu.ethereum.rlp.AbstractRLPInput.error(AbstractRLPInput.java:202)
besu-merge-besu-1 | at org.hyperledger.besu.ethereum.rlp.AbstractRLPInput.enterList(AbstractRLPInput.java:448)
besu-merge-besu-1 | at org.hyperledger.besu.ethereum.rlp.BytesValueRLPInput.enterList(BytesValueRLPInput.java:23)
besu-merge-besu-1 | at org.hyperledger.besu.ethereum.rlp.AbstractRLPInput.enterList(AbstractRLPInput.java:432)
besu-merge-besu-1 | at org.hyperledger.besu.ethereum.rlp.BytesValueRLPInput.enterList(BytesValueRLPInput.java:23)
besu-merge-besu-1 | at org.hyperledger.besu.ethereum.p2p.rlpx.wire.messages.DisconnectMessage$Data.readFrom(DisconnectMessage.java:83)
besu-merge-besu-1 | at org.hyperledger.besu.ethereum.p2p.rlpx.wire.messages.DisconnectMessage.getReason(DisconnectMessage.java:61)
besu-merge-besu-1 | at org.hyperledger.besu.ethereum.p2p.rlpx.connections.netty.DeFramer.decode(DeFramer.java:180)
besu-merge-besu-1 | at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:510)
besu-merge-besu-1 | at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:449)
besu-merge-besu-1 | ... 23 more
Looking at this block there is one VERY big transaction that uses more than 15 million gas and executes more than 1200 static calls: https://ropsten.etherscan.io/tx/0x877f7cfe8ac00ec1c87300d9d8890bb05692a429cbbfc973d39cf6155b5b67eb
My guess is creating the trace for it is very compute intense and is blocking the node. We need to look into this to confirm this theory and see if we can optimize that if this should indeed by the case.
Also something similar happened a while ago: https://ropsten.etherscan.io/block/12080598 https://ropsten.etherscan.io/tx/0x249c9d5f2a5784d13bdae569f51f07298763fab2c3e2e842615e90e1095b52ba Although this was limited to 3 mio. gas and not a problem for the exact same node - it returned 177 MB of trace json.
We are also wondering, whoever tested this if he is planning to send something like this on mainnet. At current prices 15 mio gas would cost about 0.3 Eth and could be a DoS attack for node operators, at least if the app depends on traces.
blocked by #4140 but the workaround to set fast-sync-min-peers=1 should help
Required fix from #4210
Also 2 cases on mainnet now:
- https://etherscan.io/tx/0xb24837d52c3861c9ef77b13d1db801350f08387dc93b489b156bd2e62b9850b3 - 28 mio. gas
- https://etherscan.io/tx/0xe313192dce958b606b1bad21c8890c1cf52460fa745e5239ef6841f91b5e46aa - 23 mio. gas
In my testing besu takes over 200 seconds = 3 minutes to respond in both cases, for example 2 "method": "trace_block", "params": ["0xf1bde6"]
, even on a fairly powerful machine (16 core, 128 GB RAM).
This makes it increasingly difficult to run in production, if applications depending on traces have lower http timeouts. We were only able to get around it with a custom caching proxy. Please reconsider prioritization of this issue.
@Jakeler We're currently reviewing a few approaches to resolve this issue.
Are you able to share your usecase that experiences this issue? Are you tracing every block?
Ok, thank you. Yes, we are tracing every block, parsing the output to check for some calls/events on contracts/wallets we care about.
@daniellehrner - related to current work? or can i close as a duplicate ?
@daniellehrner - related to current work? or can i close as a duplicate ?
Yes, that appears to a duplicate