I am currently suffering from sync fail issue while running my own private network.
Over 20 nodes were fully connected each other and running consensus (or mining) as archive mode, with full sync mode peacefully.
Then with some reason, one of them terminated ungracefully, so I tried re-running geth and expected to it recovers itself and sync from other peers.
In this moment, local head block number was 310489 and other nodes were mining 324011. Crashed node successfully loaded last-saved states from disk, but it stopped sync (i guess). 310490~323505 were well synced and stopped on 323506 for 15 hours even it's far way from other peers (distance > 200 at least).
After long searches, I removed all chaindata, reset all of it and restarted geth to sync from genesis for clean sync. Then it dropped all peers from itself, printing logs and stopped sync on height 0 (logs below are recreated):
DEBUG[09-17|21:33:00.239|p2p/discover/table.go:344] Revalidated node b=14 id=32f7e89d30e83b68 checks=1
INFO [09-17|21:33:06.780|p2p/dial.go:339] Looking for peers peercount=0 tried=0 static=0
DEBUG[09-17|21:33:06.995|p2p/discover/table.go:344] Revalidated node b=16 id=ef2d7ab886910dc8 checks=1
DEBUG[09-17|21:33:11.413|p2p/discover/table.go:344] Revalidated node b=15 id=6b36f791352f15eb checks=2
DEBUG[09-17|21:33:16.199|rpc/handler.go:308] Served admin_addPeer reqid=9 duration="140.918µs"
DEBUG[09-17|21:33:16.203|p2p/server.go:760] Adding p2p peer peercount=1 id=18fd40638e45213b conn=staticdial addr=<hidden> name=Geth/v1.0.0-unstable...
INFO [09-17|21:33:16.203|eth/handler.go:506] Trying to register equalize extension with peer peer=18fd4063 peer=<hidden>
DEBUG[09-17|21:33:16.204|eth/handler.go:357] Ethereum peer connected id=18fd40638e45213b conn=staticdial name=Geth/v1.0.0-unstable...
INFO [09-17|21:33:16.204|eth/downloader/downloader.go:389] Block synchronisation started
DEBUG[09-17|21:33:16.204|eth/downloader/downloader.go:461] Synchronising with the network peer=18fd40638e45213b<...hidden> eth=66 head=49dac2..06a2ad td=415,004 mode=full
DEBUG[09-17|21:33:16.204|eth/downloader/downloader.go:692] Retrieving remote chain head peer=18fd4063
DEBUG[09-17|21:33:16.204|eth/protocols/eth/peer.go:362] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=1 fromhash=49dac2..06a2ad skip=63 reverse=true
DEBUG[09-17|21:33:16.204|p2p/msgrate/msgrate.go:416] Recalculated msgrate QoS values proto=eth rtt=20s confidence=1.000 ttl=1m0s next=2022-09-17T21:33:36+0000
DEBUG[09-17|21:33:16.205|eth/downloader/downloader.go:720] Remote head identified, no pivot peer=18fd4063 number=415,003 hash=49dac2..06a2ad
DEBUG[09-17|21:33:16.205|eth/downloader/downloader.go:805] Looking for common ancestor peer=18fd4063 local=0 remote=415,003
DEBUG[09-17|21:33:16.205|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=12 fromnum=414,826 skip=15 reverse=false
DEBUG[09-17|21:33:16.207|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=1 fromnum=207,501 skip=0 reverse=false
DEBUG[09-17|21:33:16.208|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=1 fromnum=103,750 skip=0 reverse=false
DEBUG[09-17|21:33:16.209|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=1 fromnum=51875 skip=0 reverse=false
DEBUG[09-17|21:33:16.210|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=1 fromnum=25937 skip=0 reverse=false
DEBUG[09-17|21:33:16.211|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=1 fromnum=12968 skip=0 reverse=false
DEBUG[09-17|21:33:16.213|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=1 fromnum=6484 skip=0 reverse=false
DEBUG[09-17|21:33:16.214|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=1 fromnum=3242 skip=0 reverse=false
DEBUG[09-17|21:33:16.215|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=1 fromnum=1621 skip=0 reverse=false
DEBUG[09-17|21:33:16.216|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=1 fromnum=810 skip=0 reverse=false
DEBUG[09-17|21:33:16.217|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=1 fromnum=405 skip=0 reverse=false
DEBUG[09-17|21:33:16.218|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=1 fromnum=202 skip=0 reverse=false
DEBUG[09-17|21:33:16.219|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=1 fromnum=101 skip=0 reverse=false
DEBUG[09-17|21:33:16.221|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=1 fromnum=50 skip=0 reverse=false
DEBUG[09-17|21:33:16.222|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=1 fromnum=25 skip=0 reverse=false
DEBUG[09-17|21:33:16.223|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=1 fromnum=12 skip=0 reverse=false
DEBUG[09-17|21:33:16.224|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=1 fromnum=6 skip=0 reverse=false
DEBUG[09-17|21:33:16.225|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=1 fromnum=3 skip=0 reverse=false
DEBUG[09-17|21:33:16.226|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=1 fromnum=1 skip=0 reverse=false
DEBUG[09-17|21:33:16.228|eth/downloader/downloader.go:968] Found common ancestor peer=18fd4063 number=0 hash=000000..000000
DEBUG[09-17|21:33:16.228|eth/downloader/downloader.go:981] Directing header downloads peer=18fd4063 origin=1
DEBUG[09-17|21:33:16.228|eth/downloader/downloader.go:1233] Downloading receipts origin=1
DEBUG[09-17|21:33:16.228|eth/downloader/downloader.go:1222] Downloading block bodies origin=1
DEBUG[09-17|21:33:16.228|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=128 fromnum=192 skip=191 reverse=false
DEBUG[09-17|21:33:16.232|eth/downloader/downloader.go:1204] Filling up skeleton from=1
INFO [09-17|21:33:16.232|eth/downloader/fetchers_concurrent.go:190] Deliver requested request="&{Peer:0xc0011095c0 From:1 Headers:[] Time:2022-09-17 21:33:16.232603999 +0000 UTC m=+29.844696400}"
DEBUG[09-17|21:33:16.232|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=192 fromnum=1 skip=0 reverse=false
DEBUG[09-17|21:33:16.234|eth/downloader/queue.go:716] Skeleton filling not accepted peer=18fd40638e45213b from=1 headers=1 max-header-fetch=192
DEBUG[09-17|21:33:16.234|eth/downloader/fetchers_concurrent_headers.go:94] Failed to deliver retrieved headers peer=18fd4063 err="delivery not accepted"
INFO [09-17|21:33:16.234|eth/downloader/fetchers_concurrent.go:190] Deliver requested request="&{Peer:0xc0011095c0 From:193 Headers:[] Time:2022-09-17 21:33:16.234091554 +0000 UTC m=+29.846183956}"
DEBUG[09-17|21:33:16.234|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=192 fromnum=193 skip=0 reverse=false
DEBUG[09-17|21:33:16.235|eth/downloader/queue.go:716] Skeleton filling not accepted peer=18fd40638e45213b from=193 headers=1 max-header-fetch=192
DEBUG[09-17|21:33:16.235|eth/downloader/fetchers_concurrent_headers.go:94] Failed to deliver retrieved headers peer=18fd4063 err="delivery not accepted"
INFO [09-17|21:33:16.235|eth/downloader/fetchers_concurrent.go:190] Deliver requested request="&{Peer:0xc0011095c0 From:385 Headers:[] Time:2022-09-17 21:33:16.235509251 +0000 UTC m=+29.847601653}"
DEBUG[09-17|21:33:16.235|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=192 fromnum=385 skip=0 reverse=false
DEBUG[09-17|21:33:16.236|eth/downloader/queue.go:716] Skeleton filling not accepted peer=18fd40638e45213b from=385 headers=1 max-header-fetch=192
DEBUG[09-17|21:33:16.236|eth/downloader/fetchers_concurrent_headers.go:94] Failed to deliver retrieved headers peer=18fd4063 err="delivery not accepted"
INFO [09-17|21:33:16.236|eth/downloader/fetchers_concurrent.go:190] Deliver requested request="&{Peer:0xc0011095c0 From:577 Headers:[] Time:2022-09-17 21:33:16.236897015 +0000 UTC m=+29.848989416}"
DEBUG[09-17|21:33:16.236|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=192 fromnum=577 skip=0 reverse=false
DEBUG[09-17|21:33:16.238|eth/downloader/queue.go:716] Skeleton filling not accepted peer=18fd40638e45213b from=577 headers=1 max-header-fetch=192
DEBUG[09-17|21:33:16.238|eth/downloader/fetchers_concurrent_headers.go:94] Failed to deliver retrieved headers peer=18fd4063 err="delivery not accepted"
INFO [09-17|21:33:16.238|eth/downloader/fetchers_concurrent.go:190] Deliver requested request="&{Peer:0xc0011095c0 From:769 Headers:[] Time:2022-09-17 21:33:16.23827991 +0000 UTC m=+29.850372312}"
DEBUG[09-17|21:33:16.238|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=192 fromnum=769 skip=0 reverse=false
DEBUG[09-17|21:33:16.239|eth/downloader/queue.go:716] Skeleton filling not accepted peer=18fd40638e45213b from=769 headers=1 max-header-fetch=192
DEBUG[09-17|21:33:16.239|eth/downloader/fetchers_concurrent_headers.go:94] Failed to deliver retrieved headers peer=18fd4063 err="delivery not accepted"
INFO [09-17|21:33:16.239|eth/downloader/fetchers_concurrent.go:190] Deliver requested request="&{Peer:0xc0011095c0 From:961 Headers:[] Time:2022-09-17 21:33:16.239662021 +0000 UTC m=+29.851754422}"
DEBUG[09-17|21:33:16.239|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=192 fromnum=961 skip=0 reverse=false
DEBUG[09-17|21:33:16.241|eth/downloader/queue.go:716] Skeleton filling not accepted peer=18fd40638e45213b from=961 headers=1 max-header-fetch=192
DEBUG[09-17|21:33:16.241|eth/downloader/fetchers_concurrent_headers.go:94] Failed to deliver retrieved headers peer=18fd4063 err="delivery not accepted"
INFO [09-17|21:33:16.241|eth/downloader/fetchers_concurrent.go:190] Deliver requested request="&{Peer:0xc0011095c0 From:1153 Headers:[] Time:2022-09-17 21:33:16.241038388 +0000 UTC m=+29.853130789}"
DEBUG[09-17|21:33:16.241|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=192 fromnum=1153 skip=0 reverse=false
DEBUG[09-17|21:33:16.242|eth/downloader/queue.go:716] Skeleton filling not accepted peer=18fd40638e45213b from=1153 headers=1 max-header-fetch=192
DEBUG[09-17|21:33:16.242|eth/downloader/fetchers_concurrent_headers.go:94] Failed to deliver retrieved headers peer=18fd4063 err="delivery not accepted"
INFO [09-17|21:33:16.242|eth/downloader/fetchers_concurrent.go:190] Deliver requested request="&{Peer:0xc0011095c0 From:1345 Headers:[] Time:2022-09-17 21:33:16.242390146 +0000 UTC m=+29.854482547}"
DEBUG[09-17|21:33:16.242|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=192 fromnum=1345 skip=0 reverse=false
DEBUG[09-17|21:33:16.243|eth/downloader/queue.go:716] Skeleton filling not accepted peer=18fd40638e45213b from=1345 headers=1 max-header-fetch=192
DEBUG[09-17|21:33:16.243|eth/downloader/fetchers_concurrent_headers.go:94] Failed to deliver retrieved headers peer=18fd4063 err="delivery not accepted"
INFO [09-17|21:33:16.243|eth/downloader/fetchers_concurrent.go:190] Deliver requested request="&{Peer:0xc0011095c0 From:1537 Headers:[] Time:2022-09-17 21:33:16.243795247 +0000 UTC m=+29.855887648}"
DEBUG[09-17|21:33:16.243|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=192 fromnum=1537 skip=0 reverse=false
DEBUG[09-17|21:33:16.245|eth/downloader/queue.go:716] Skeleton filling not accepted peer=18fd40638e45213b from=1537 headers=1 max-header-fetch=192
DEBUG[09-17|21:33:16.245|eth/downloader/fetchers_concurrent_headers.go:94] Failed to deliver retrieved headers peer=18fd4063 err="delivery not accepted"
INFO [09-17|21:33:16.245|eth/downloader/fetchers_concurrent.go:190] Deliver requested request="&{Peer:0xc0011095c0 From:1729 Headers:[] Time:2022-09-17 21:33:16.245167069 +0000 UTC m=+29.857259470}"
DEBUG[09-17|21:33:16.245|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=192 fromnum=1729 skip=0 reverse=false
DEBUG[09-17|21:33:16.246|eth/downloader/queue.go:716] Skeleton filling not accepted peer=18fd40638e45213b from=1729 headers=1 max-header-fetch=192
DEBUG[09-17|21:33:16.246|eth/downloader/fetchers_concurrent_headers.go:94] Failed to deliver retrieved headers peer=18fd4063 err="delivery not accepted"
INFO [09-17|21:33:16.246|eth/downloader/fetchers_concurrent.go:190] Deliver requested request="&{Peer:0xc0011095c0 From:1921 Headers:[] Time:2022-09-17 21:33:16.246501989 +0000 UTC m=+29.858594390}"
DEBUG[09-17|21:33:16.246|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=192 fromnum=1921 skip=0 reverse=false
DEBUG[09-17|21:33:16.247|eth/downloader/queue.go:716] Skeleton filling not accepted peer=18fd40638e45213b from=1921 headers=1 max-header-fetch=192
DEBUG[09-17|21:33:16.247|eth/downloader/fetchers_concurrent_headers.go:94] Failed to deliver retrieved headers peer=18fd4063 err="delivery not accepted"
...
(skipping)
...
DEBUG[09-17|21:37:56.415|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=192 fromnum=24193 skip=0 reverse=false
DEBUG[09-17|21:37:56.416|eth/downloader/queue.go:716] Skeleton filling not accepted peer=18fd40638e45213b from=24193 headers=1 max-header-fetch=192
DEBUG[09-17|21:37:56.416|eth/downloader/fetchers_concurrent_headers.go:94] Failed to deliver retrieved headers peer=18fd4063 err="delivery not accepted"
INFO [09-17|21:37:56.416|eth/downloader/fetchers_concurrent.go:190] Deliver requested request="&{Peer:0xc0015bf200 From:24385 Headers:[] Time:2022-09-17 21:37:56.416625449 +0000 UTC m=+310.028717862}"
DEBUG[09-17|21:37:56.416|eth/protocols/eth/peer.go:389] Fetching batch of headers id=18fd40638e45213b conn=staticdial count=192 fromnum=24385 skip=0 reverse=false
DEBUG[09-17|21:37:56.417|eth/downloader/queue.go:716] Skeleton filling not accepted peer=18fd40638e45213b from=24385 headers=1 max-header-fetch=192
DEBUG[09-17|21:37:56.417|eth/downloader/fetchers_concurrent_headers.go:94] Failed to deliver retrieved headers peer=18fd4063 err="delivery not accepted"
DEBUG[09-17|21:37:56.417|eth/downloader/downloader.go:1209] Skeleton fill failed err="no peers available or all tried for download"
DEBUG[09-17|21:37:56.417|eth/downloader/downloader.go:1116] Skeleton chain invalid peer=18fd4063 err="no peers available or all tried for download"
DEBUG[09-17|21:37:56.417|eth/downloader/downloader.go:1117] Header download terminated peer=18fd4063
DEBUG[09-17|21:37:56.418|eth/downloader/downloader.go:1236] Receipt download terminated err="syncing canceled (requested)"
DEBUG[09-17|21:37:56.418|eth/downloader/downloader.go:1225] Block body download terminated err="syncing canceled (requested)"
INFO [09-17|21:37:56.418|eth/downloader/queue.go:394] Downloader queue stats receiptTasks=0 blockTasks=0 itemSize=0.00B throttle=8192
DEBUG[09-17|21:37:56.418|eth/downloader/downloader.go:466] Synchronisation terminated elapsed=209.379ms
WARN [09-17|21:37:56.418|eth/downloader/downloader.go:342] Synchronisation failed, dropping peer peer=18fd40638e45213b<...hidden> err="retrieved hash chain is invalid: no peers available or all tried for download"
WARN [09-17|21:37:56.418|eth/protocols/equalize/handler.go:75] Message handling failed in `equalize` peer=18fd4063 err=EOF
WARN [09-17|21:37:56.418|eth/protocols/eth/handler.go:155] Message handling failed in `eth` id=18fd40638e45213b conn=staticdial err=EOF
DEBUG[09-17|21:37:56.418|eth/handler.go:533] Removing Ethereum peer peer=18fd4063 snap=true eq=true
WARN [09-17|21:37:56.418|eth/protocols/snap/handler.go:124] Message handling failed in `snap` peer=18fd4063 err=EOF
DEBUG[09-17|21:37:56.418|p2p/server.go:772] Removing p2p peer peercount=0 id=18fd40638e45213b duration=210.955ms req=false err="useless peer"
Sorry for dirty logs, I added some logs for debug.
btw, geth prints Failed to deliver retrieved headers and retrieved hash chain is invalid error. So I tried to figure out what is wrong with sync, debugging with logs, these are what I found out:
(Crashed Node: A, Connected Peer: B)
- A requested headers 1~192, 193~384, 385~576, ... to B.
- B found just one header from cache, none from db.
- From db, B just get 100
rlpHeadersfrom db (ancientRangemethod), while expecting 192. Returning nothing eventually because of mismatching of counts of headers. - A expected to received 192 headers from B, but single header was delivered.
- Given header count (1) doesn't match with
MaxHeaderFetch(192), so given delivery not accepted. - Any peers from network gives same unexpected responses, so all of them dropped from crashed node, left as alone.
After all this now I'm doubting the syncing is not the actual problem, rather I'm assuming other nodes really doesn't give appropriate header set as expected or acting wrong. I don't understand this situation because all peers are archive node, which saves all states and headers but they're not giving proper counts of headers.
Am I doing wrong with debugging or all of these (from initial running nodes of network and configuring geth stuff)? Or should I update my ethereum code to higher version? (My code was forked from go-ethereum on 2022 may)
Used geth command (all nodes as same):
geth \
...
--networkid "0" \
--verbosity=4 \
--syncmode "full" \
--gcmode "archive" \
--log.debug \
--nat "none"
