search

smartcontracts / simple-optimism-node

The easiest way to run an Optimism node
MIT License
324 stars 112 forks source link

Can't sync after restart - missing trie node & Attempting to unsafe reorg using backupUnsafe even though it is empty #140

Closed 0x366 closed 1 month ago

0x366 commented 5 months ago

Hello, thank you for nice repo first of all!

Im recently stumbled upon the issue - after full node is synced from scratch using snap sync (Base) - I can't restart it. If I restart it - it switches to full sync. And after that geth doesnt do anything.

Node prints normally after walking L1:

t=2024-04-23T09:23:11+0000 lvl=info msg="Sync progress" reason="reconciled with L1" l2_finalized=0x92a7041fbe4555b114dfde769d2cdf43adc55c8aa4206523ec01b345a3940097:13535000 l2_safe=0x50fe86d5c3207292f2b4c7a525caf625ed8572b32226bc9190b66ed714b4b264:13509153 l2_pending_safe=0xa0a84eff1e3c448245d72dd56fd3a57541fed1d3be3672d8cdfdeac221025ba2:13509195 l2_unsafe=0xc72011035474a5f0215a6da809506af698539bb79a93185a144d374a996ddc24:13519348 l2_backup_unsafe=0x0000000000000000000000000000000000000000000000000000000000000000:0 l2_time=1713828043 l1_derived=0xd94c3746549ada8a2bbcd2bd4504934e50e8024d673a0263ce9d938cf995f180:19712501
t=2024-04-23T09:23:11+0000 lvl=info msg="generated attributes in payload queue" txs=102 timestamp=1713807739
t=2024-04-23T09:23:11+0000 lvl=info msg="Sync progress" reason="reconciled with L1" l2_finalized=0x92a7041fbe4555b114dfde769d2cdf43adc55c8aa4206523ec01b345a3940097:13535000 l2_safe=0x50fe86d5c3207292f2b4c7a525caf625ed8572b32226bc9190b66ed714b4b264:13509153 l2_pending_safe=0x53ecc4e933c21bf99f11b075ded487559aae7aa32687d4662e1c5a2928550c61:13509196 l2_unsafe=0xc72011035474a5f0215a6da809506af698539bb79a93185a144d374a996ddc24:13519348 l2_backup_unsafe=0x0000000000000000000000000000000000000000000000000000000000000000:0 l2_time=1713828043 l1_derived=0xd94c3746549ada8a2bbcd2bd4504934e50e8024d673a0263ce9d938cf995f180:19712501
t=2024-04-23T09:23:11+0000 lvl=info msg="generated attributes in payload queue" txs=120 timestamp=1713807741
t=2024-04-23T09:23:11+0000 lvl=info msg="Sync progress" reason="reconciled with L1" l2_finalized=0x92a7041fbe4555b114dfde769d2cdf43adc55c8aa4206523ec01b345a3940097:13535000 l2_safe=0x50fe86d5c3207292f2b4c7a525caf625ed8572b32226bc9190b66ed714b4b264:13509153 l2_pending_safe=0x010c3feafe0d7ed67addab7c1e08acfec21cdaf6d81c962f620bfc0ccdd819e5:13509197 l2_unsafe=0xc72011035474a5f0215a6da809506af698539bb79a93185a144d374a996ddc24:13519348 l2_backup_unsafe=0x0000000000000000000000000000000000000000000000000000000000000000:0 l2_time=1713828043 l1_derived=0xd94c3746549ada8a2bbcd2bd4504934e50e8024d673a0263ce9d938cf995f180:19712501
t=2024-04-23T09:23:11+0000 lvl=info msg="generated attributes in payload queue" txs=122 timestamp=1713807743
t=2024-04-23T09:23:11+0000 lvl=info msg="Sync progress" reason="reconciled with L1" l2_finalized=0x92a7041fbe4555b114dfde769d2cdf43adc55c8aa4206523ec01b345a3940097:13535000 l2_safe=0x50fe86d5c3207292f2b4c7a525caf625ed8572b32226bc9190b66ed714b4b264:13509153 l2_pending_safe=0x48d7d228754b23e54ac145f005cfc6fade440d80ab57d79d5f8c12a6d315d365:13509198 l2_unsafe=0xc72011035474a5f0215a6da809506af698539bb79a93185a144d374a996ddc24:13519348 l2_backup_unsafe=0x0000000000000000000000000000000000000000000000000000000000000000:0 l2_time=1713828043 l1_derived=0xd94c3746549ada8a2bbcd2bd4504934e50e8024d673a0263ce9d938cf995f180:19712501
t=2024-04-23T09:23:11+0000 lvl=info msg="generated attributes in payload queue" txs=121 timestamp=1713807745
t=2024-04-23T09:23:11+0000 lvl=info msg="Sync progress" reason="reconciled with L1" l2_finalized=0x92a7041fbe4555b114dfde769d2cdf43adc55c8aa4206523ec01b345a3940097:13535000 l2_safe=0x50fe86d5c3207292f2b4c7a525caf625ed8572b32226bc9190b66ed714b4b264:13509153 l2_pending_safe=0xb53da648b1ab5b336b79f3b52537323f36ad94e9c0ab57dd8c047b4450071fd9:13509199 l2_unsafe=0xc72011035474a5f0215a6da809506af698539bb79a93185a144d374a996ddc24:13519348 l2_backup_unsafe=0x0000000000000000000000000000000000000000000000000000000000000000:0 l2_time=1713828043 l1_derived=0xd94c3746549ada8a2bbcd2bd4504934e50e8024d673a0263ce9d938cf995f180:19712501
t=2024-04-23T09:23:11+0000 lvl=info msg="generated attributes in payload queue" txs=128 timestamp=1713807747
t=2024-04-23T09:23:11+0000 lvl=warn msg="failed p2p sync request" peer=16Uiu2HAm2CwBANi861fGUm9LRG4WbKC1P6YNA8a6MbcvZgaVndWw num=13536480 err="peer failed to serve request with code 1"
t=2024-04-23T09:23:11+0000 lvl=info msg="Sync progress" reason="reconciled with L1" l2_finalized=0x92a7041fbe4555b114dfde769d2cdf43adc55c8aa4206523ec01b345a3940097:13535000 l2_safe=0x50fe86d5c3207292f2b4c7a525caf625ed8572b32226bc9190b66ed714b4b264:13509153 l2_pending_safe=0xc2ce440dde473a66582d23ac4c166ed7c108f88481d62bc1c4151273fc678481:13509200 l2_unsafe=0xc72011035474a5f0215a6da809506af698539bb79a93185a144d374a996ddc24:13519348 l2_backup_unsafe=0x0000000000000000000000000000000000000000000000000000000000000000:0 l2_time=1713828043 l1_derived=0xd94c3746549ada8a2bbcd2bd4504934e50e8024d673a0263ce9d938cf995f180:19712501
t=2024-04-23T09:23:11+0000 lvl=info msg="generated attributes in payload queue" txs=128 timestamp=1713807749
t=2024-04-23T09:23:11+0000 lvl=info msg="Sync progress" reason="reconciled with L1" l2_finalized=0x92a7041fbe4555b114dfde769d2cdf43adc55c8aa4206523ec01b345a3940097:13535000 l2_safe=0x826066dfe82899961792ad67ed3b6f9a2459aa2cbb07be0d46792987e299e3cf:13509201 l2_pending_safe=0x826066dfe82899961792ad67ed3b6f9a2459aa2cbb07be0d46792987e299e3cf:13509201 l2_unsafe=0xc72011035474a5f0215a6da809506af698539bb79a93185a144d374a996ddc24:13519348 l2_backup_unsafe=0x0000000000000000000000000000000000000000000000000000000000000000:0 l2_time=1713828043 l1_derived=0xd94c3746549ada8a2bbcd2bd4504934e50e8024d673a0263ce9d938cf995f180:19712501
t=2024-04-23T09:23:12+0000 lvl=info msg="Advancing bq origin" origin=0xf201a65459faba81685e71bfe412f9877cec4ce2129c1e70829ad154848d7251:19712502 originBehind=false
t=2024-04-23T09:23:12+0000 lvl=info msg="Advancing bq origin" origin=0x68e08288da4f2d30ee6c33a0f55b7e6c13d9558f9ad2c88bd42b6ba134089577:19712503 originBehind=false
t=2024-04-23T09:23:12+0000 lvl=info msg="Advancing bq origin" origin=0x3c32dc75712053d47ec2300781a01ed8923dc9f61a4a0f19babb562357261807:19712504 originBehind=false
t=2024-04-23T09:23:12+0000 lvl=warn msg="failed p2p sync request" peer=16Uiu2HAmABArWSnXfbAYfidsLJLTeKo5uFGB4eCdxa8K7ei7Vvzv num=13536425 err="peer failed to serve request with code 3"
t=2024-04-23T09:23:12+0000 lvl=warn msg="failed p2p sync request" peer=16Uiu2HAmQiKBE5a6A8Egd1Xgfw8NZLXKBtvttHhuhkfv5j5xMuXF num=13536422 err="peer failed to serve request with code 1"
t=2024-04-23T09:23:12+0000 lvl=warn msg="failed p2p sync request" peer=16Uiu2HAmRXRHgHSKdWguDrPuuKBp3dps76k8TgnMxb9whuLs4c4h num=13536419 err="peer failed to serve request with code 1"
t=2024-04-23T09:23:13+0000 lvl=warn msg="failed p

But geth only prints looking for peers and then at some point show trie node missing error:

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

And node logs at the time of trie node 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"

t=2024-04-23T09:28:52+0000 lvl=warn msg="Attempting to unsafe reorg using backupUnsafe even though it is empty"

It wasn't always the case, previously I was restarting snapsynced node without a problem. But this problem appeared recently. L1 rpc and beacon are accessible, 30303 and 9222 ports are opened.

I suspect it's the problem with full sync. Because I can't sync my node with full sync from scratch. Only snap sync works. But don't really get why.

Do you know by any chance what may be the problem

Chomtana commented 5 months ago

This requires some more investigation. Could you please open this ticket on https://github.com/ethereum-optimism/developers/discussions ?

Chomtana commented 5 months ago

Full sync requires L1 archive beacon node and it's may take months as we only have an archive node snapshot for Base