[Node Operator Question] l2geth endpoint returns empty response for debug_traceTransaction method with callTracer and 180s timeout

[mateipopa]

Are you running the most up to date node software?

• Yes

Did you check the documentation?

• Yes

Did you check for duplicate questions?

• Yes

Issue Description

We are trying to trace historical transactions on an OP Mainnet archive node directly via the l2geth endpoint. In most cases, everything works fine, but sometimes queries that should return trace data return an empty response:

~# curl --request POST --header 'Content-Type: application/json' --url http://localhost:8548 --data '[{"jsonrpc": "2.0","method": "debug_traceTransaction","params": ["0xcd08b04edcd08d27da458e6e16bd3c1bdebb5a3b2782939b8fe102b8f578e91b",{"tracer": "callTracer","timeout": "300s"}],"id": 1}]'
curl: (52) Empty reply from server

Usually, more complex and/or transactions with errors exhibit this behavior, but it isn't consistent. The same debug call might work in the future, but the results are inconsistent.
Simpler, error-free transactions return properly, but sometimes they also return empty responses.

Protocol Description

geth version 0.1.0-unstable-0402d543
l2geth Version: 1.9.10-stable
op-node version v0.0.0-99a53381-1710933867
network is OP mainnet
chainid 10
L1 is ETH

Node Logs

2024-06-05 13:13:55.681799939 +00:00|op-l2geth|DEBUG[06-05|13:13:55.681] Revalidated node                         b=5  id=60bbef8b62ccbd4b checks=26
2024-06-05 13:13:55.830553416 +00:00|op-l2geth|DEBUG[06-05|13:13:55.830] Served debug_traceTransaction            conn=127.0.0.1:47650 reqid=1    t=1.046129118s
2024-06-05 13:13:55.837010671 +00:00|op-l2geth|DEBUG[06-05|13:13:55.836] Adding L1 fee                            l1-fee=103386642803136
2024-06-05 13:13:56.652066521 +00:00|op-l2geth|DEBUG[06-05|13:13:56.652] Served debug_traceTransaction            conn=127.0.0.1:47674 reqid=0    t=976.260018ms
2024-06-05 13:13:56.657017493 +00:00|op-l2geth|DEBUG[06-05|13:13:56.656] Adding L1 fee                            l1-fee=103386642803136
2024-06-05 13:13:57.725613556 +00:00|op-l2geth|DEBUG[06-05|13:13:57.725] VM returned with error                   err="evm: execution reverted"                ret=0x08c379a00000000000000000000000000000000000000000000000000000000000000020000000000000000000000000000000000000000000000000000000000000000743485f544c524c00000000000000000000000000000000000000000000000000
2024-06-05 13:13:57.734474199 +00:00|op-l2geth|DEBUG[06-05|13:13:57.734] Served debug_traceTransaction            conn=127.0.0.1:48012 reqid=2    t=2.854925671s
2024-06-05 13:13:57.810143425 +00:00|op-l2geth|DEBUG[06-05|13:13:57.810] Adding L1 fee                            l1-fee=147679770858816
2024-06-05 13:13:57.830093255 +00:00|op-l2geth|DEBUG[06-05|13:13:57.830] VM returned with error                   err="evm: execution reverted"                ret=0x08c379a000000000000000000000000000000000000000000000000000000000000000200000000000000000000000000000000000000000000000000000000000000022526f757465723a20494e53554646494349454e545f4f55545055545f414d4f554e54000000000000000000000000000000000000000000000000000000000000
2024-06-05 13:13:57.831084712 +00:00|op-l2geth|DEBUG[06-05|13:13:57.831] Served debug_traceTransaction            conn=127.0.0.1:47676 reqid=0    t=26.128522ms
2024-06-05 13:13:57.837260818 +00:00|op-l2geth|DEBUG[06-05|13:13:57.837] Adding L1 fee                            l1-fee=147571738839168
2024-06-05 13:13:57.956306366 +00:00|op-l2geth|DEBUG[06-05|13:13:57.956] VM returned with error                   err="evm: execution reverted"                ret=0x08c379a000000000000000000000000000000000000000000000000000000000000000200000000000000000000000000000000000000000000000000000000000000013546f6f206c6974746c6520726563656976656400000000000000000000000000
2024-06-05 13:13:57.957151793 +00:00|op-l2geth|DEBUG[06-05|13:13:57.957] Served debug_traceTransaction            conn=127.0.0.1:47676 reqid=1    t=126.042946ms
2024-06-05 13:13:57.961962697 +00:00|op-l2geth|DEBUG[06-05|13:13:57.961] Adding L1 fee                            l1-fee=147571738839168
2024-06-05 13:13:58.089302324 +00:00|op-l2geth|DEBUG[06-05|13:13:58.089] Served debug_traceTransaction            conn=127.0.0.1:47676 reqid=2    t=132.100685ms
2024-06-05 13:13:58.124340902 +00:00|op-l2geth|DEBUG[06-05|13:13:58.124] Adding L1 fee                            l1-fee=156970524548544
2024-06-05 13:13:59.165998244 +00:00|op-l2geth|DEBUG[06-05|13:13:59.165] VM returned with error                   err="evm: execution reverted"                ret=0x08c379a00000000000000000000000000000000000000000000000000000000000000020000000000000000000000000000000000000000000000000000000000000000743485f544c524c00000000000000000000000000000000000000000000000000
2024-06-05 13:13:59.170331685 +00:00|op-l2geth|DEBUG[06-05|13:13:59.170] Served debug_traceTransaction            conn=127.0.0.1:47680 reqid=0    t=1.051158951s
2024-06-05 13:13:59.175324608 +00:00|op-l2geth|DEBUG[06-05|13:13:59.175] Adding L1 fee                            l1-fee=103386642803136
2024-06-05 13:14:01.258090988 +00:00|op-l2geth|DEBUG[06-05|13:14:01.258] Served debug_traceTransaction            conn=127.0.0.1:47672 reqid=0    t=6.323569852s
2024-06-05 13:14:01.270665075 +00:00|op-l2geth|DEBUG[06-05|13:14:01.270] Adding L1 fee                            l1-fee=129638423577600
2024-06-05 13:14:01.645261174 +00:00|op-l2geth|DEBUG[06-05|13:14:01.645] Served debug_traceTransaction            conn=127.0.0.1:47660 reqid=1    t=5.977093557s
2024-06-05 13:14:01.650739375 +00:00|op-l2geth|DEBUG[06-05|13:14:01.650] Adding L1 fee                            l1-fee=334791228889152
2024-06-05 13:14:01.942822317 +00:00|op-l2geth|DEBUG[06-05|13:14:01.942] Served debug_traceTransaction            conn=127.0.0.1:47672 reqid=1    t=684.701894ms
2024-06-05 13:14:01.947813817 +00:00|op-l2geth|DEBUG[06-05|13:14:01.947] Adding L1 fee                            l1-fee=129962519636544
2024-06-05 13:14:02.189788010 +00:00|op-l2geth|DEBUG[06-05|13:14:02.189] Served debug_traceTransaction            conn=127.0.0.1:47650 reqid=2    t=6.359193294s
2024-06-05 13:14:02.263060597 +00:00|op-l2geth|DEBUG[06-05|13:14:02.263] Adding L1 fee                            l1-fee=134391832442112
2024-06-05 13:14:02.275739244 +00:00|op-l2geth|DEBUG[06-05|13:14:02.275] VM returned with error                   err="evm: execution reverted"                ret=0x08c379a00000000000000000000000000000000000000000000000000000000000000020000000000000000000000000000000000000000000000000000000000000000353504c0000000000000000000000000000000000000000000000000000000000
2024-06-05 13:14:02.276762272 +00:00|op-l2geth|DEBUG[06-05|13:14:02.276] Served debug_traceTransaction            conn=127.0.0.1:47696 reqid=0    t=20.107079ms
2024-06-05 13:14:02.282912318 +00:00|op-l2geth|DEBUG[06-05|13:14:02.282] Adding L1 fee                            l1-fee=152217115684032
2024-06-05 13:14:02.353636740 +00:00|op-l2geth|DEBUG[06-05|13:14:02.353] Served debug_traceTransaction            conn=127.0.0.1:47696 reqid=1    t=76.853097ms
2024-06-05 13:14:02.358584125 +00:00|op-l2geth|DEBUG[06-05|13:14:02.358] Adding L1 fee                            l1-fee=103386642803136
2024-06-05 13:14:02.596961557 +00:00|op-l2geth|DEBUG[06-05|13:14:02.596] Served debug_traceTransaction            conn=127.0.0.1:47672 reqid=2    t=654.122047ms
2024-06-05 13:14:02.676521263 +00:00|op-l2geth|DEBUG[06-05|13:14:02.676] Adding L1 fee                            l1-fee=129962519636544
2024-06-05 13:14:02.705043523 +00:00|op-l2geth|DEBUG[06-05|13:14:02.705] Served debug_traceTransaction            conn=127.0.0.1:47674 reqid=1    t=6.052972133s
2024-06-05 13:14:02.710470496 +00:00|op-l2geth|DEBUG[06-05|13:14:02.710] Adding L1 fee                            l1-fee=152433179723328
2024-06-05 13:14:02.980566071 +00:00|op-l2geth|DEBUG[06-05|13:14:02.980] Served debug_traceTransaction            conn=127.0.0.1:47660 reqid=2    t=1.335287653s

Additional Information

We're hitting the l2geth endpoint directly, without going through geth via the --rollup.historicalrpc.
This is how I'm starting l2geth:

USING_OVM=true \                     
ETH1_SYNC_SERVICE_ENABLE=false \                     
RPC_API=eth,rollup,net,web3,debug \                     
RPC_ADDR=localhost \                     
RPC_CORS_DOMAIN=* \                     
RPC_ENABLE=true \                     
RPC_PORT=8548 \                     
RPC_VHOSTS=* \                     
l2geth \                     
--datadir /optimism//l2geth \              
--verbosity 5 --rpc.evmtimeout 300s       --port 30304 \                     
--nousb \             
--cache 8192 \                
--rpc.gascap=1000000000

The system is running an Ubuntu 22.04.3 LTS on a 5.15.0-102-generic kernel.

It looks like we might be affected by this (ethereum/go-ethereum#21430 (comment)) geth bug, but I couldn't find any way of updating this legacy endpoint as the repo is archived and there haven't been any releases.

Feedback

No response

[opfocus]

CC @Chomtana @imtipi

[imtipi]

seems this patch isn't in l2geth,maybe have to manually compile?

[mateipopa]

If I'd compile manually and ultimately determine that I'm really affected by that bug, I'd have to upgrade to a newer version. Any idea if that would even work? I'd rather upgrade and see if it makes a difference rather than debugging old issues

[sbvegan]

@imtipi is on the right track here. OP Labs is not making any back fixes to l2geth and unfortunately we won't be able to confirm if this would fix your problem. I think your best bet is to try and apply a patch fix to l2geth that addresses the bug you've found. Sometimes giving a longer timeout helps with these types of tracing issues, but legacy geth is running an old version that doesn't have robust tracing built in.

[mateipopa]

Alright, will give it a shot. Thank you both for the input!