0

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)

  1. A requested headers 1~192, 193~384, 385~576, ... to B.
  2. B found just one header from cache, none from db.
  3. From db, B just get 100 rlpHeaders from db (ancientRange method), while expecting 192. Returning nothing eventually because of mismatching of counts of headers.
  4. A expected to received 192 headers from B, but single header was delivered.
  5. Given header count (1) doesn't match with MaxHeaderFetch(192), so given delivery not accepted.
  6. 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" 

1 Answer 1

1

I resolved this issue myself, the problem was the max buffer size of the header size when fetching headers.

Originally it's below 700 bytes I guess, updated headers of the chain of my version was above 700 bytes. So I raised it to 7000 then it was resolved.

Hope this is helpful to custom ethereum chain developers.

1
  • It will be usefull if you tell us how to do this.
    – Magno C
    Commented Aug 16, 2023 at 0:46

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.