Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Attempting to unsafe reorg using backupUnsafe even though it is empty #10267

Open
0x366 opened this issue Apr 23, 2024 · 5 comments
Open

Attempting to unsafe reorg using backupUnsafe even though it is empty #10267

0x366 opened this issue Apr 23, 2024 · 5 comments

Comments

@0x366
Copy link

0x366 commented Apr 23, 2024 •
edited

Bug Description
Can't sync node after restart

Steps to Reproduce
Snapsync on Base
Restart a few times (not sure about that steps, but eventually at some restart it happens). even if all restarts are graceful
Node will switch to fullsync
And sometimes it will never sync after that

Expected behavior
Node should catch the tip after restart

Environment Information:
Ubuntu 22
us-docker.pkg.dev/oplabs-tools-artifacts/images/op-node:v1.7.3
us-docker.pkg.dev/oplabs-tools-artifacts/images/op-geth:v1.101311.0

Configurations:
https://github.com/smartcontracts/simple-optimism-node/blob/main/scripts/start-op-node.sh
https://github.com/smartcontracts/simple-optimism-node/blob/main/scripts/start-op-geth.sh

Logs:
Geth:

INFO [04-23|09:07:33.550] Loaded most recent local header          number=13,535,550 hash=a8a1e3..5a2957 td=0 age=46m46s
INFO [04-23|09:07:33.550] Loaded most recent local block           number=13,519,348 hash=c72011..6ddc24 td=0 age=9h46m50s
INFO [04-23|09:07:33.550] Loaded most recent local snap block      number=13,535,550 hash=a8a1e3..5a2957 td=0 age=46m46s
INFO [04-23|09:07:33.550] Loaded most recent local finalized block number=13,535,000 hash=92a704..940097 td=0 age=1h5m6s
INFO [04-23|09:07:33.550] Loaded last snap-sync pivot marker       number=13,518,990
WARN [04-23|09:07:33.551] Enabling snapshot recovery               chainhead=13,519,348 diskbase=13,535,357
WARN [04-23|09:07:33.604] Snapshot is not continuous with chain    snaproot=68d3cc..4d673d chainroot=3990fd..7cf24f
INFO [04-23|09:07:33.604] Initialized transaction indexer          range="last 2350000 blocks"
INFO [04-23|09:07:33.604] Initialising Ethereum protocol           network=8453         dbversion=8
INFO [04-23|09:07:33.611] Loaded local transaction journal         transactions=0 dropped=0
INFO [04-23|09:07:33.611] Regenerated local transaction journal    transactions=0 accounts=0
WARN [04-23|09:07:33.611] Switch sync mode from snap sync to full sync
INFO [04-23|09:07:33.611] Chain post-merge, sync via beacon client
INFO [04-23|09:07:33.611] Gasprice oracle is ignoring threshold set threshold=2
WARN [04-23|09:07:33.612] Unclean shutdown detected                booted=2024-04-23T08:16:02+0000 age=51m31s
WARN [04-23|09:07:33.612] Unclean shutdown detected                booted=2024-04-23T08:40:28+0000 age=27m5s
WARN [04-23|09:07:33.612] Unclean shutdown detected                booted=2024-04-23T08:44:13+0000 age=23m20s
WARN [04-23|09:07:33.612] Engine API enabled                       protocol=eth
INFO [04-23|09:07:33.612] Starting peer-to-peer node               instance=Geth/v0.1.0-unstable-e9a306ba/linux-amd64/go1.21.9
INFO [04-23|09:07:33.633] New local node record                    seq=1,713,823,089,268 id=c16dd62f88dfbb33 ip=127.0.0.1 udp=30303 tcp=30303
INFO [04-23|09:07:33.634] Started P2P networking                   self=<>
7.0.0.1:30303
INFO [04-23|09:07:33.634] IPC endpoint opened                      url=/geth/geth.ipc
INFO [04-23|09:07:33.635] Loaded JWT secret file                   path=/shared/jwt.txt crc32=0x92b12d96
INFO [04-23|09:07:33.635] HTTP server started                      endpoint=[::]:8545 auth=false prefix= cors=* vhosts=*
INFO [04-23|09:07:33.635] WebSocket enabled                        url=ws://[::]:8546
INFO [04-23|09:07:33.635] WebSocket enabled                        url=ws://[::]:8551
INFO [04-23|09:07:33.635] HTTP server started                      endpoint=[::]:8551 auth=true  prefix= cors=localhost vhosts=*
INFO [04-23|09:07:46.304] Looking for peers                        peercount=0 tried=183 static=0
INFO [04-23|09:07:56.771] Looking for peers                        peercount=1 tried=154 static=0
INFO [04-23|09:08:06.790] Looking for peers                        peercount=2 tried=73  static=0
INFO [04-23|09:08:16.809] Looking for peers                        peercount=2 tried=91  static=0
INFO [04-23|09:08:26.948] Looking for peers                        peercount=3 tried=104 static=0
INFO [04-23|09:08:36.980] Looking for peers                        peercount=4 tried=145 static=0
INFO [04-23|09:08:37.217] New local node record                    seq=1,713,823,089,269 id=c16dd62f88dfbb33 ip=65.109.127.229 udp=30303 tcp=30303
INFO [04-23|09:08:47.042] Looking for peers                        peercount=5 tried=108 static=0
INFO [04-23|09:08:57.059] Looking for peers                        peercount=7 tried=63  static=0
INFO [04-23|09:09:07.092] Looking for peers                        peercount=8 tried=101 static=0
INFO [04-23|09:09:17.148] Looking for peers                        peercount=8 tried=102 static=0
^[[B^[[BqINFO [04-23|09:09:27.292] Looking for peers                        peercount=8 tried=69  static=0
INFO [04-23|09:09:37.383] Looking for peers                        peercount=8 tried=34  static=0
INFO [04-23|09:09:47.418] Looking for peers                        peercount=8 tried=117 static=0
INFO [04-23|09:09:57.545] Looking for peers                        peercount=8 tried=87  static=0
INFO [04-23|09:10:07.549] Looking for peers                        peercount=8 tried=124 static=0
INFO [04-23|09:10:17.553] Looking for peers                        peercount=9 tried=83  static=0
INFO [04-23|09:10:27.594] Looking for peers                        peercount=8 tried=39  static=0
INFO [04-23|09:10:37.639] Looking for peers                        peercount=8 tried=94  static=0

.....

INFO [04-23|09:28:52.199] Starting work on payload                 id=0x03b83ed157662f6c
WARN [04-23|09:28:52.204] Ignoring already known beacon payload    number=13,519,349 hash=71b29d..a60608 age=10h8m7s
ERROR[04-23|09:28:52.215] Failed to create sealing context         err="missing trie node 2bb487cd77c59f2ee7c2e16d349e627e8e1cbe4832c688e1c13a4c2b2afad697 (path ) state 0x2bb487cd77c59f2ee7c2e16d349e627e8e1cbe4832c688e1c13a4c2b2afad697 is not available, not found"
ERROR[04-23|09:28:52.215] Failed to build payload                  err="missing trie node 2bb487cd77c59f2ee7c2e16d349e627e8e1cbe4832c688e1c13a4c2b2afad697 (path ) state 0x2bb487cd77c59f2ee7c2e16d349e627e8e1cbe4832c688e1c13a4c2b2afad697 is not available, not found"
WARN [04-23|09:28:52.215] Served engine_forkchoiceUpdatedV3        conn=172.25.0.6:41488 reqid=45854 duration=1.082646ms err="Invalid payload attributes" errdata="{Error:missing trie node 2bb487cd77c59f2ee7c2e16d349e627e8e1cbe4832c688e1c13a4c2b2afad697 (path ) state 0x2bb487cd77c59f2ee7c2e16d349e627e8e1cbe4832c688e1c13a4c2b2afad697 is not available, not found}"
INFO [04-23|09:29:01.019] Looking for peers                        peercount=23 tried=112 static=0
INFO [04-23|09:29:11.023] Looking for peers                        peercount=23 tried=44  static=0
INFO [04-23|09:29:21.115] Looking for peers                        peercount=23 tried=98  static=0
INFO [04-23|09:29:31.139] Looking for peers                        peercount=23 tried=39  static=0
INFO [04-23|09:29:41.172] Looking for peers                        peercount=23 tried=190 static=0
INFO [04-23|09:29:51.355] Looking for peers                        peercount=23 tried=28  static=0

There are the logs of node during trie missing error

t=2024-04-23T09:28:51+0000 lvl=warn msg="failed p2p sync request" peer=16Uiu2HAm3qwgs4Bvfx1GJ5qnY4LjPbYCc394kvdjpxuJBsP3SQnW num=13536508 err="failed to open stream: failed to negotiate protocol: protocols not supported: [/opstack/req/payload_by_number/8453/0]"
t=2024-04-23T09:28:52+0000 lvl=info msg="Sync progress" reason="reconciled with L1" l2_finalized=0x92a7041fbe4555b114dfde769d2cdf43adc55c8aa4206523ec01b345a3940097:13535000 l2_safe=0x52bd62c19483aae89ce071311626d33bf320f308561756416e2d3213f9bb4442:13519311 l2_pending_safe=0x8b856efbd0136e53dbee87c303a347fa8ca4f699f9aee1a7b9a4eafe91383b08:13519343 l2_unsafe=0xc72011035474a5f0215a6da809506af698539bb79a93185a144d374a996ddc24:13519348 l2_backup_unsafe=0x0000000000000000000000000000000000000000000000000000000000000000:0 l2_time=1713828043 l1_derived=0xc6426fd3fab2dd21788435ebe2641269c1c8dbf9530ca838442bdfb088809520:19714188
t=2024-04-23T09:28:52+0000 lvl=info msg="generated attributes in payload queue" txs=55 timestamp=1713828035
t=2024-04-23T09:28:52+0000 lvl=info msg="Sync progress" reason="reconciled with L1" l2_finalized=0x92a7041fbe4555b114dfde769d2cdf43adc55c8aa4206523ec01b345a3940097:13535000 l2_safe=0x52bd62c19483aae89ce071311626d33bf320f308561756416e2d3213f9bb4442:13519311 l2_pending_safe=0xfd630550ed1200a6c80e799cb2156a5de37537d4743841fdfe7e289a52c442c0:13519344 l2_unsafe=0xc72011035474a5f0215a6da809506af698539bb79a93185a144d374a996ddc24:13519348 l2_backup_unsafe=0x0000000000000000000000000000000000000000000000000000000000000000:0 l2_time=1713828043 l1_derived=0xc6426fd3fab2dd21788435ebe2641269c1c8dbf9530ca838442bdfb088809520:19714188
t=2024-04-23T09:28:52+0000 lvl=info msg="generated attributes in payload queue" txs=52 timestamp=1713828037
t=2024-04-23T09:28:52+0000 lvl=info msg="Sync progress" reason="reconciled with L1" l2_finalized=0x92a7041fbe4555b114dfde769d2cdf43adc55c8aa4206523ec01b345a3940097:13535000 l2_safe=0x52bd62c19483aae89ce071311626d33bf320f308561756416e2d3213f9bb4442:13519311 l2_pending_safe=0xd65019090563064b0a7d5deb9573f531fb789fd06e9648b7e9c19988f9e63d85:13519345 l2_unsafe=0xc72011035474a5f0215a6da809506af698539bb79a93185a144d374a996ddc24:13519348 l2_backup_unsafe=0x0000000000000000000000000000000000000000000000000000000000000000:0 l2_time=1713828043 l1_derived=0xc6426fd3fab2dd21788435ebe2641269c1c8dbf9530ca838442bdfb088809520:19714188
t=2024-04-23T09:28:52+0000 lvl=info msg="generated attributes in payload queue" txs=58 timestamp=1713828039
t=2024-04-23T09:28:52+0000 lvl=warn msg="failed p2p sync request" peer=16Uiu2HAmRXRHgHSKdWguDrPuuKBp3dps76k8TgnMxb9whuLs4c4h num=13536498 err="peer failed to serve request with code 1"
t=2024-04-23T09:28:52+0000 lvl=info msg="Sync progress" reason="reconciled with L1" l2_finalized=0x92a7041fbe4555b114dfde769d2cdf43adc55c8aa4206523ec01b345a3940097:13535000 l2_safe=0x52bd62c19483aae89ce071311626d33bf320f308561756416e2d3213f9bb4442:13519311 l2_pending_safe=0x6f9e732da82e4131414ec0c6d764d3319026e1ec141a178c5706ab92393a9245:13519346 l2_unsafe=0xc72011035474a5f0215a6da809506af698539bb79a93185a144d374a996ddc24:13519348 l2_backup_unsafe=0x0000000000000000000000000000000000000000000000000000000000000000:0 l2_time=1713828043 l1_derived=0xc6426fd3fab2dd21788435ebe2641269c1c8dbf9530ca838442bdfb088809520:19714188
t=2024-04-23T09:28:52+0000 lvl=info msg="generated attributes in payload queue" txs=62 timestamp=1713828041
t=2024-04-23T09:28:52+0000 lvl=info msg="Sync progress" reason="reconciled with L1" l2_finalized=0x92a7041fbe4555b114dfde769d2cdf43adc55c8aa4206523ec01b345a3940097:13535000 l2_safe=0x52bd62c19483aae89ce071311626d33bf320f308561756416e2d3213f9bb4442:13519311 l2_pending_safe=0xc02ae132f0763a942b8de8dbc8345c01d7313201487daf8609b195409112923b:13519347 l2_unsafe=0xc72011035474a5f0215a6da809506af698539bb79a93185a144d374a996ddc24:13519348 l2_backup_unsafe=0x0000000000000000000000000000000000000000000000000000000000000000:0 l2_time=1713828043 l1_derived=0xc6426fd3fab2dd21788435ebe2641269c1c8dbf9530ca838442bdfb088809520:19714188
t=2024-04-23T09:28:52+0000 lvl=info msg="generated attributes in payload queue" txs=57 timestamp=1713828043
t=2024-04-23T09:28:52+0000 lvl=info msg="Sync progress" reason="reconciled with L1" l2_finalized=0x92a7041fbe4555b114dfde769d2cdf43adc55c8aa4206523ec01b345a3940097:13535000 l2_safe=0x52bd62c19483aae89ce071311626d33bf320f308561756416e2d3213f9bb4442:13519311 l2_pending_safe=0xc72011035474a5f0215a6da809506af698539bb79a93185a144d374a996ddc24:13519348 l2_unsafe=0xc72011035474a5f0215a6da809506af698539bb79a93185a144d374a996ddc24:13519348 l2_backup_unsafe=0x0000000000000000000000000000000000000000000000000000000000000000:0 l2_time=1713828043 l1_derived=0xc6426fd3fab2dd21788435ebe2641269c1c8dbf9530ca838442bdfb088809520:19714188
t=2024-04-23T09:28:52+0000 lvl=info msg="generated attributes in payload queue" txs=37 timestamp=1713828045
t=2024-04-23T09:28:52+0000 lvl=warn msg="failed p2p sync request" peer=16Uiu2HAmGdGxw1QtPaFk1BnytgrfVTDzcjxzeLqEXhnZxQwjXNrs num=13536502 err="peer failed to serve request with code 1"
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAm1XLTLCHQMfSBKJ1KPbBd9knVsZQYpxBrEnVNqE2BnK2A
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAmStdntMJZhmZyA2ZBmGFYVxWXoYW97fHvNkTAAoo7sfRQ
t=2024-04-23T09:28:52+0000 lvl=info msg="inserted block" hash=0x71b29dbcd5d7920e5a3782adef952354f7ae269553f40371fa379dbb0aa60608 number=13519349 state_root=0x2bb487cd77c59f2ee7c2e16d349e627e8e1cbe4832c688e1c13a4c2b2afad697 timestamp=1713828045 parent=0xc72011035474a5f0215a6da809506af698539bb79a93185a144d374a996ddc24 prev_randao=0xaa5b68b596d94e501f146ae24e564215ed75681c24e7b95161c4167ae9552665 fee_recipient=0x4200000000000000000000000000000000000011 txs=37 update_safe=false
t=2024-04-23T09:28:52+0000 lvl=info msg="Sync progress" reason="processed safe block derived from L1" l2_finalized=0x92a7041fbe4555b114dfde769d2cdf43adc55c8aa4206523ec01b345a3940097:13535000 l2_safe=0x52bd62c19483aae89ce071311626d33bf320f308561756416e2d3213f9bb4442:13519311 l2_pending_safe=0x71b29dbcd5d7920e5a3782adef952354f7ae269553f40371fa379dbb0aa60608:13519349 l2_unsafe=0x71b29dbcd5d7920e5a3782adef952354f7ae269553f40371fa379dbb0aa60608:13519349 l2_backup_unsafe=0x0000000000000000000000000000000000000000000000000000000000000000:0 l2_time=1713828045 l1_derived=0xc6426fd3fab2dd21788435ebe2641269c1c8dbf9530ca838442bdfb088809520:19714188
t=2024-04-23T09:28:52+0000 lvl=info msg="generated attributes in payload queue" txs=41 timestamp=1713828047
t=2024-04-23T09:28:52+0000 lvl=warn msg="Failed to share forkchoice-updated signal" state="&{HeadBlockHash:0x71b29dbcd5d7920e5a3782adef952354f7ae269553f40371fa379dbb0aa60608 SafeBlockHash:0x52bd62c19483aae89ce071311626d33bf320f308561756416e2d3213f9bb4442 FinalizedBlockHash:0x92a7041fbe4555b114dfde769d2cdf43adc55c8aa4206523ec01b345a3940097}" err="Invalid payload attributes"
t=2024-04-23T09:28:52+0000 lvl=warn msg="could not process payload derived from L1 data, dropping batch" err="payload attributes are not valid, cannot build block: Invalid payload attributes"
t=2024-04-23T09:28:52+0000 lvl=warn msg="Attempting to unsafe reorg using backupUnsafe even though it is empty"
t=2024-04-23T09:28:52+0000 lvl=warn msg="parent block does not match the next batch. dropped cached batches" parent=0x52bd62c19483aae89ce071311626d33bf320f308561756416e2d3213f9bb4442:13519311 nextBatchTime=1713828049
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAmMGKxrdGK9GAaJ4Lup5q1G4eBteSAfzz7ztNoJXbovc1K
t=2024-04-23T09:28:52+0000 lvl=warn msg="peer is temporarily banned" method=InterceptPeerDial peer_id=16Uiu2HAmMGKxrdGK9GAaJ4Lup5q1G4eBteSAfzz7ztNoJXbovc1K
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAm6ktDkA4PcneBB94aFmHMg2rehMxrZqfSofoQHEsUz1Kb
t=2024-04-23T09:28:52+0000 lvl=warn msg="peer is temporarily banned" method=InterceptPeerDial peer_id=16Uiu2HAm6ktDkA4PcneBB94aFmHMg2rehMxrZqfSofoQHEsUz1Kb
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAmEi2VCvuo9YDeUZT96zcqmCDRbBUTrt8bn1HjB1ScHk6L
t=2024-04-23T09:28:52+0000 lvl=warn msg="peer is temporarily banned" method=InterceptPeerDial peer_id=16Uiu2HAmEi2VCvuo9YDeUZT96zcqmCDRbBUTrt8bn1HjB1ScHk6L
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAmT7VSaG9xwu6SqSpU4ckVggWGLt6h3cyq1nd9NkqX414j
t=2024-04-23T09:28:52+0000 lvl=warn msg="peer is temporarily banned" method=InterceptPeerDial peer_id=16Uiu2HAmT7VSaG9xwu6SqSpU4ckVggWGLt6h3cyq1nd9NkqX414j
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAkw4TwbTjfyEvSXUeUrNuTfuuNbPV9Nj18ATe2QkJGasRG
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAm25w7k2tiMkqqUzwbTpLQcTLEH1Q3PF6jLp625cfRtteT
t=2024-04-23T09:28:52+0000 lvl=warn msg="peer is temporarily banned" method=InterceptPeerDial peer_id=16Uiu2HAm25w7k2tiMkqqUzwbTpLQcTLEH1Q3PF6jLp625cfRtteT
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAkxL5k1BNkp6rN76hWnXUUCQh8EV9L5R1w6CCiDCoQkcTr
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAkw43FRRh6PBX43q7PV5YSqwacfe8oVnYPFRr9oTZ9xqF6
t=2024-04-23T09:28:52+0000 lvl=warn msg="peer is temporarily banned" method=InterceptPeerDial peer_id=16Uiu2HAkw43FRRh6PBX43q7PV5YSqwacfe8oVnYPFRr9oTZ9xqF6
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAkzBgV9xkN2GVHxFACMr5Mz4PvoHUuwLH2kieUcaqEpxSM
t=2024-04-23T09:28:52+0000 lvl=warn msg="peer is temporarily banned" method=InterceptPeerDial peer_id=16Uiu2HAkzBgV9xkN2GVHxFACMr5Mz4PvoHUuwLH2kieUcaqEpxSM
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAmUHbkSDdsPMQc4YyZ98xY6WmwiBc9xMn8neeb2EEui7ce
t=2024-04-23T09:28:52+0000 lvl=warn msg="peer is temporarily banned" method=InterceptPeerDial peer_id=16Uiu2HAmUHbkSDdsPMQc4YyZ98xY6WmwiBc9xMn8neeb2EEui7ce
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAmM3uhYhU6YhKuAuQWti5MeAdEfKHrrj11c2nKo5f2gQbC
t=2024-04-23T09:28:52+0000 lvl=warn msg="peer is temporarily banned" method=InterceptPeerDial peer_id=16Uiu2HAmM3uhYhU6YhKuAuQWti5MeAdEfKHrrj11c2nKo5f2gQbC
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAky2Uw31EXaQj1Ywhtrn1sZLXLEKEMJt1jFn3PEaaJeTGn
t=2024-04-23T09:28:52+0000 lvl=warn msg="peer is temporarily banned" method=InterceptPeerDial peer_id=16Uiu2HAky2Uw31EXaQj1Ywhtrn1sZLXLEKEMJt1jFn3PEaaJeTGn
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAm4RWmKtMsGMDdaryRePc6qWswgpnDT49coTbF2UF2UVHj
t=2024-04-23T09:28:52+0000 lvl=warn msg="peer is temporarily banned" method=InterceptPeerDial peer_id=16Uiu2HAm4RWmKtMsGMDdaryRePc6qWswgpnDT49coTbF2UF2UVHj
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAmEuQ9oWcQa8VuBMnGDqNP68hqnAK12i1WN2ocxFwLJMk4
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAkyvYZ5Ri3KGMc1rzsKozJ51EtTfWYjyhZYqu5C5YDcGt4
t=2024-04-23T09:28:52+0000 lvl=warn msg="peer is temporarily banned" method=InterceptPeerDial peer_id=16Uiu2HAkyvYZ5Ri3KGMc1rzsKozJ51EtTfWYjyhZYqu5C5YDcGt4
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAmGsP6D1aa7kHjJg9RuSoMLH9x5nPWvzwt8Q3gisGr37pd
t=2024-04-23T09:28:52+0000 lvl=warn msg="peer is temporarily banned" method=InterceptPeerDial peer_id=16Uiu2HAmGsP6D1aa7kHjJg9RuSoMLH9x5nPWvzwt8Q3gisGr37pd
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAmV3Jv6TujZSQuwZWQubMEtiEKXq5LmLHrZGz4BMkakbp9
t=2024-04-23T09:28:52+0000 lvl=warn msg="peer is temporarily banned" method=InterceptPeerDial peer_id=16Uiu2HAmV3Jv6TujZSQuwZWQubMEtiEKXq5LmLHrZGz4BMkakbp9
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAkvWMemHAHsvyZbQozeYeBd11GjdYanqB3nPps9LKCV2Ay
t=2024-04-23T09:28:52+0000 lvl=info msg="Advancing bq origin" origin=0x210901be8b51928b9dc8f04948d16868b7f94e938d545bdbce2269fd396830fc:19714189 originBehind=false
t=2024-04-23T09:28:52+0000 lvl=warn msg="failed p2p sync request" peer=16Uiu2HAmKt9zvrbzAmrH3jrtFdCm6h52J2Ue2rPQYEqKZFmWejC6 num=13536505 err="failed to open stream: failed to negotiate protocol: protocols not supported: [/opstack/req/payload_by_number/8453/0]"
t=2024-04-23T09:28:52+0000 lvl=warn msg="failed p2p sync request" peer=16Uiu2HAm4wN4epAyuj82ix2QC1Uc2vQd833szwvsNpLqhubPz8xa num=13536497 err="failed to open stream: failed to negotiate protocol: protocols not supported: [/opstack/req/payload_by_number/8453/0]"
t=2024-04-23T09:28:52+0000 lvl=info msg="Advancing bq origin" origin=0x01b113cc50b94c7ab31c16e4ce63231fa85a08aef102b5e4668183525555ace2:19714190 originBehind=false
t=2024-04-23T09:28:52+0000 lvl=info msg="Advancing bq origin" origin=0x2f9871da2b0a4cfde5ca9cde3997fc02a74eccc0091f7ab8015655720a35c109:19714191 originBehind=false
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAmUW2cdYcHQ4FiihM9Nx9TimYDuEVGGRND28vB7WxTZLGf
t=2024-04-23T09:28:52+0000 lvl=info msg="connected to peer" peer=16Uiu2HAkvWMemHAHsvyZbQozeYeBd11GjdYanqB3nPps9LKCV2Ay addr=/ip4/188.40.66.109/tcp/9222
t=2024-04-23T09:28:52+0000 lvl=info msg="Starting P2P sync client event loop" peer=16Uiu2HAkvWMemHAHsvyZbQozeYeBd11GjdYanqB3nPps9LKCV2Ay
t=2024-04-23T09:28:52+0000 lvl=info msg="attempting connection" peer=16Uiu2HAm2mx9PeadxjTm2QgDeieRmAHGnRHM1b6GcsdZiRi8pi96
t=2024-04-23T09:28:52+0000 lvl=warn msg="failed p2p sync request" peer=16Uiu2HAkvWMemHAHsvyZbQozeYeBd11GjdYanqB3nPps9LKCV2Ay num=13536494 err="peer failed to serve request with code 1"
t=2024-04-23T09:28:52+0000 lvl=warn msg="failed p2p sync request" peer=16Uiu2HAmK5edX8N8hodJx6j2gsZRy6pKFs33AEgAfVFKZEHRfzCr num=13536492 err="peer failed to serve request with code 3"
t=2024-04-23T09:28:52+0000 lvl=warn msg="failed p2p sync request" peer=16Uiu2HAmKt9zvrbzAmrH3jrtFdCm6h52J2Ue2rPQYEqKZFmWejC6 num=13536481 err="failed to open stream: failed to negotiate protocol: protocols not supported: [/opstack/req/payload_by_number/8453/0]"
t=2024-04-23T09:28:52+0000 lvl=warn msg="failed p2p sync request" peer=16Uiu2HAmNgtRGUrwKa4ZNaRwcN1u4k5cJtyzeUZH64EpwzBmVVGW num=13536479 err="peer failed to serve request with code 1"
t=2024-04-23T09:28:52+0000 lvl=info msg="Advancing bq origin" origin=0xb1f7cced65cb25c47bc8fd1a1552e33a813121f9b77a2e5d6a51a0f106b91865:19714192 originBehind=false
t=2024-04-23T09:28:52+0000 lvl=warn msg="failed p2p sync request" peer=16Uiu2HAkvWMemHAHsvyZbQozeYeBd11GjdYanqB3nPps9LKCV2Ay num=13536471 err="peer failed to serve request with code 1"
t=2024-04-23T09:28:53+0000 lvl=info msg="Advancing bq origin" origin=0xf1e88840c41a0c0b841901cb3a41f6017014d9d952fa6d3d206ab861d0d55de9:19714193 originBehind=false
t=2024-04-23T09:28:53+0000 lvl=info msg="Received signed execution payload from p2p" id=0xacc78a824f27b0716d2ac3ee73aa5405a31bb86070544c9bc7d6bafd8d1e1f92:13537592 peer=16Uiu2HAmNgtRGUrwKa4ZNaRwcN1u4k5cJtyzeUZH64EpwzBmVVGW
t=2024-04-23T09:28:53+0000 lvl=warn msg="failed p2p sync request" peer=16Uiu2HAkx6kBsEHZgUbeS3NgRG2grHVma78ky29c4QgXs49gRyRv num=13536467 err="peer failed to serve request with code 3"

Additional context
L1 rpc and beacon are pingable from inside containers, node and geth p2p ports are opened
@top2hightech
Copy link

I encountered the same problem...

@opfocus
Copy link

opfocus commented Apr 25, 2024 

WARN [04-23|09:07:33.612] Unclean shutdown detected                booted=2024-04-23T08:16:02+0000 age=51m31s
WARN [04-23|09:07:33.612] Unclean shutdown detected                booted=2024-04-23T08:40:28+0000 age=27m5s
WARN [04-23|09:07:33.612] Unclean shutdown detected                booted=2024-04-23T08:44:13+0000 age=23m20s

https://docs.optimism.io/builders/chain-operators/management/operations#stop-op-geth
There may be some kind of corruption in the database, see this link for the cause.
One suggestion is to always keep op-geth and op-node running one-to-one.
Synchronous mode is usually very fast, it is also recommended that you delete the database (geth folder) and start from scratch

@0x366
Copy link
Author

0x366 commented Apr 25, 2024 •
edited

@opfocus seems like its the root issue. But was wondering what's the cause, as on mainnet geth is able to recover itself in such cases.

always keep op-geth and op-node running one-to-one

Do you mean you need to restart both op-node and op-geth, if for example you only need to restart one of them?

@opfocus
Copy link

opfocus commented Apr 25, 2024

Following the startup sequence in the documentation will reduce error messages in the log. But I don't mean to say that it must be done. The original text of the document is: Always run op-node and op-geth in a one-to-one configuration. Don't run multiple op-geth instances behind one op-node, or vice versa.

@alecalve
Copy link

alecalve commented May 3, 2024

I am encountering the same issue:

INFO [05-03|13:32:51.975] Starting geth on an OP network...        network=op-mainnet
INFO [05-03|13:32:51.975] Bumping default cache on mainnet         provided=1024 updated=4096
INFO [05-03|13:32:51.976] Maximum peer count                       ETH=100 total=100
INFO [05-03|13:32:51.977] Smartcard socket not found, disabling    err="stat /run/pcscd/pcscd.comm: no such file or directory"
WARN [05-03|13:32:51.981] The flag --txlookuplimit is deprecated and will be removed, please use --history.transactions
INFO [05-03|13:32:51.981] Set global gas cap                       cap=50,000,000
INFO [05-03|13:32:51.982] Initializing the KZG library             backend=gokzg
INFO [05-03|13:32:52.002] Allocated trie memory caches             clean=614.00MiB dirty=1024.00MiB
INFO [05-03|13:32:52.139] Using pebble as the backing database
INFO [05-03|13:32:52.139] Allocated cache and file handles         database=/opt/data/geth/chaindata cache=2.00GiB handles=524,288
INFO [05-03|13:32:55.216] Opened ancient database                  database=/opt/data/geth/chaindata/ancient/chain readonly=false
INFO [05-03|13:32:55.228] State schema set to default              scheme=hash
INFO [05-03|13:32:55.849]
INFO [05-03|13:32:55.849] ---------------------------------------------------------------------------------------------------------------------------------------------------------
INFO [05-03|13:32:55.849] Chain ID:  10 (OP-Mainnet)
INFO [05-03|13:32:55.849] Consensus: Optimism
INFO [05-03|13:32:55.849]
INFO [05-03|13:32:55.849] Pre-Merge hard forks (block based):
INFO [05-03|13:32:55.849]  - Homestead:                   #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/homestead.md)
INFO [05-03|13:32:55.849]  - Tangerine Whistle (EIP 150): #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/tangerine-whistle.md)
INFO [05-03|13:32:55.849]  - Spurious Dragon/1 (EIP 155): #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/spurious-dragon.md)
INFO [05-03|13:32:55.849]  - Spurious Dragon/2 (EIP 158): #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/spurious-dragon.md)
INFO [05-03|13:32:55.849]  - Byzantium:                   #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/byzantium.md)
INFO [05-03|13:32:55.849]  - Constantinople:              #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/constantinople.md)
INFO [05-03|13:32:55.849]  - Petersburg:                  #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/petersburg.md)
INFO [05-03|13:32:55.849]  - Istanbul:                    #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/istanbul.md)
INFO [05-03|13:32:55.849]  - Muir Glacier:                #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/muir-glacier.md)
INFO [05-03|13:32:55.849]  - Berlin:                      #3950000  (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/berlin.md)
INFO [05-03|13:32:55.849]  - London:                      #105235063 (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/london.md)
INFO [05-03|13:32:55.849]  - Arrow Glacier:               #105235063 (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/arrow-glacier.md)
INFO [05-03|13:32:55.849]  - Gray Glacier:                #105235063 (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/gray-glacier.md)
INFO [05-03|13:32:55.849]
INFO [05-03|13:32:55.849] Merge configured:
INFO [05-03|13:32:55.849]  - Hard-fork specification:    https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/paris.md
INFO [05-03|13:32:55.849]  - Network known to be merged: true
INFO [05-03|13:32:55.849]  - Total terminal difficulty:  0
INFO [05-03|13:32:55.849]  - Merge netsplit block:       #105235063
INFO [05-03|13:32:55.849]
INFO [05-03|13:32:55.849] Post-Merge hard forks (timestamp based):
INFO [05-03|13:32:55.849]  - Shanghai:                    @1704992401 (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/shanghai.md)
INFO [05-03|13:32:55.849]  - Cancun:                      @1710374401
INFO [05-03|13:32:55.849]  - Regolith:                    @0
INFO [05-03|13:32:55.849]  - Canyon:                      @1704992401
INFO [05-03|13:32:55.849]  - Ecotone:                     @1710374401
INFO [05-03|13:32:55.849]
INFO [05-03|13:32:55.849] ---------------------------------------------------------------------------------------------------------------------------------------------------------
INFO [05-03|13:32:55.849]
INFO [05-03|13:32:55.852] Loaded most recent local header          number=119,395,391 hash=f0d82e..e3615f td=210,470,125 age=4d2h13m
INFO [05-03|13:32:55.852] Loaded most recent local block           number=119,375,892 hash=a4cc1b..6a6dae td=210,470,125 age=4d13h3m
INFO [05-03|13:32:55.852] Loaded most recent local snap block      number=119,395,391 hash=f0d82e..e3615f td=210,470,125 age=4d2h13m
INFO [05-03|13:32:55.852] Loaded most recent local finalized block number=119,394,792 hash=a5ea7d..2f960d td=210,470,125 age=4d2h33m
INFO [05-03|13:32:55.852] Loaded last snap-sync pivot marker       number=119,269,703
WARN [05-03|13:32:55.855] Enabling snapshot recovery               chainhead=119,375,892 diskbase=119,395,112
WARN [05-03|13:32:55.892] Snapshot is not continuous with chain    snaproot=3a6707..8d2fb3 chainroot=1365fd..3278ec
INFO [05-03|13:32:55.892] Initialized transaction indexer          range="entire chain"
INFO [05-03|13:32:55.892] Initialising Ethereum protocol           network=10         dbversion=8
INFO [05-03|13:32:55.892] Loaded local transaction journal         transactions=0 dropped=0
INFO [05-03|13:32:55.892] Regenerated local transaction journal    transactions=0 accounts=0
INFO [05-03|13:32:55.892] Chain post-merge, sync via beacon client
INFO [05-03|13:32:55.893] Gasprice oracle is ignoring threshold set threshold=2
WARN [05-03|13:32:55.894] Unclean shutdown detected                booted=2024-04-29T11:17:57+0000 age=4d2h14m
WARN [05-03|13:32:55.895] Engine API enabled                       protocol=eth
INFO [05-03|13:32:55.895] Starting peer-to-peer node               instance=Geth/v0.1.0-unstable/linux-amd64/go1.21.7
INFO [05-03|13:32:55.936] New local node record                    seq=xxxxxxxx id=xxxxxxxx ip=127.0.0.1 udp=30303 tcp=30303
INFO [05-03|13:32:55.936] Started P2P networking                   self=enode://xxxxxxxx
INFO [05-03|13:32:55.938] Loaded JWT secret file                   path=/secrets/auth_rpc_jwt_secret crc32=xxxxxxxx
INFO [05-03|13:32:55.938] HTTP server started                      endpoint=[::]:8545 auth=false prefix= cors=* vhosts=*
INFO [05-03|13:32:55.938] WebSocket enabled                        url=ws://[::]:8551
INFO [05-03|13:32:55.938] HTTP server started                      endpoint=[::]:8551 auth=true  prefix= cors=localhost vhosts=*
INFO [05-03|13:33:06.464] Looking for peers                        peercount=0 tried=0 static=0
INFO [05-03|13:33:16.469] Looking for peers                        peercount=2 tried=162 static=0
INFO [05-03|13:33:26.828] Looking for peers                        peercount=2 tried=83  static=0
INFO [05-03|13:34:14.076] New local node record                    seq=xxxxxxxx id=xxxxxxxx ip=xxxxxxxx udp=30303 tcp=30303
INFO [05-03|13:44:21.992] Starting work on payload                 id=0x037240beadac8b1f
WARN [05-03|13:44:22.001] Ignoring already known beacon payload    number=119,375,893 hash=b9eea1..93d66e age=4d13h14m
ERROR[05-03|13:44:22.013] Failed to create sealing context         err="missing trie node 6eab2ff4bb552b28de78f1b62849bd376642a68cb45143d85d425ecf79fe832e (path ) state 0x6eab2ff4bb552b28de78f1b62849bd376642a68cb45143d85d425ecf79fe832e is not available, not found"
ERROR[05-03|13:44:22.013] Failed to build payload                  err="missing trie node 6eab2ff4bb552b28de78f1b62849bd376642a68cb45143d85d425ecf79fe832e (path ) state 0x6eab2ff4bb552b28de78f1b62849bd376642a68cb45143d85d425ecf79fe832e is not available, not found"
WARN [05-03|13:44:22.013] Served engine_forkchoiceUpdatedV3        reqid=45663 duration=1.577977ms err="Invalid payload attributes" errdata="{Error:missing trie node 6eab2ff4bb552b28de78f1b62849bd376642a68cb45143d85d425ecf79fe832e (path ) state 0x6eab2ff4bb552b28de78f1b62849bd376642a68cb45143d85d425ecf79fe832e is not available, not found}"

It seems the unclean shutdown caused it, however our other Geth nodes for ETH mainnet run just fine with unclean shutdowns.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@alecalve @0x366 @opfocus @top2hightech