Unable to trace_block [0xbe70da] - error 500, blocks whole node #4050

Jakeler · 2022-07-04T10:59:19Z

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

The text was updated successfully, but these errors were encountered:

daniellehrner · 2022-07-04T11:20:17Z

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.

Jakeler · 2022-07-04T17:33:27Z

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.

macfarla · 2022-07-27T23:38:32Z

blocked by #4140 but the workaround to set fast-sync-min-peers=1 should help

mark-terry · 2022-08-05T02:55:31Z

Required fix from #4210

Jakeler · 2022-10-28T13:09:50Z

Also 2 cases on mainnet now:

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.

mark-terry · 2022-10-30T23:53:54Z

@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?

Jakeler · 2022-11-07T19:10:50Z

Ok, thank you.
Yes, we are tracing every block, parsing the output to check for some calls/events on contracts/wallets we care about.

non-fungible-nelson · 2023-01-26T12:29:40Z

@daniellehrner - related to current work? or can i close as a duplicate ?

daniellehrner · 2023-01-26T12:40:51Z

@daniellehrner - related to current work? or can i close as a duplicate ?

Yes, that appears to a duplicate

daniellehrner added bug Something isn't working performance labels Jul 4, 2022

matkt self-assigned this Jul 5, 2022

matkt mentioned this issue Jul 5, 2022

OutOfMemoryError on JSON RPC method trace_replayBlockTransactions #3786

Closed

matkt added the TeamRevenant GH issues worked on by Revenant Team label Jul 5, 2022

mark-terry self-assigned this Jul 27, 2022

iamhsk added the P3 Medium (ex: JSON-RPC request not working with a specific client library due to loose spec assumtion) label Aug 1, 2022

iamhsk unassigned matkt Aug 18, 2022

mark-terry mentioned this issue Aug 18, 2022

Trace block timeout #4278

Closed

2 tasks

non-fungible-nelson mentioned this issue Nov 7, 2022

RPC / Tracing Performance #4621

Closed

non-fungible-nelson changed the title ~~Ropsten: Unable to trace_block [0xbe70da] - error 500, blocks whole node~~ Unable to trace_block [0xbe70da] - error 500, blocks whole node Nov 7, 2022

non-fungible-nelson closed this as completed Jan 26, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Unable to trace_block [0xbe70da] - error 500, blocks whole node #4050

Unable to trace_block [0xbe70da] - error 500, blocks whole node #4050

Jakeler commented Jul 4, 2022

daniellehrner commented Jul 4, 2022

Jakeler commented Jul 4, 2022

macfarla commented Jul 27, 2022

mark-terry commented Aug 5, 2022

Jakeler commented Oct 28, 2022

mark-terry commented Oct 30, 2022

Jakeler commented Nov 7, 2022

non-fungible-nelson commented Jan 26, 2023

daniellehrner commented Jan 26, 2023

Unable to trace_block [0xbe70da] - error 500, blocks whole node #4050

Unable to trace_block [0xbe70da] - error 500, blocks whole node #4050

Comments

Jakeler commented Jul 4, 2022

Steps to Reproduce (Bug)

Versions (Add all that apply)

Additional Information

daniellehrner commented Jul 4, 2022

Jakeler commented Jul 4, 2022

macfarla commented Jul 27, 2022

mark-terry commented Aug 5, 2022

Jakeler commented Oct 28, 2022

mark-terry commented Oct 30, 2022

Jakeler commented Nov 7, 2022

non-fungible-nelson commented Jan 26, 2023

daniellehrner commented Jan 26, 2023