Geth refuses to sync after being a few months offline

[elsampsa]

Weird behaviour from geth when putting a client online after it's been offline for a few months. I would really appreciate if someone would explain me what's going on / put me on the right track.

So far happened:

• On Jan 22 did a fresh snap sync from scratch. The blockchain was synced within a matter of days. Awesome!
• Wen't offline for the summer. Let's call the world state before summer "S0".
• On Sept 22 went online again & wanted to go POS, so updated to geth 1.10.23 and started using prysm 3.0.0.
• After going online again, geth refuses to reconstruct the current world state "SC".

I am using the "--syncmode=snap" option. When "--syncmode=snap" is enabled, I have to admit I am not sure which one of the two ways, (A) or (B), geth is syncing:

A. The full-node way:

• Picks up the world state "S0" where it was left in before summer.
• Starts executing the blocks, until the state has been updated from "S0"->"SC"

B. Snapshot download:

• Proceeds in downloading state snapshot fragments from other peers
• ..using snapshot packets, reconstructs the state from scratch into "SC"?
• ..or tries to do an incremental heal of "S0" --> "SC" using snapshot fragments (sounds silly, right? I guess I'm just imaging this)

Is there some criteria which one of the two ways geth ends up doing? Say, if state is enough old, then do (B) instead of (A)?

Obviously, I would prefer (A), since I'm not syncing from scratch. Should I then remove "--syncmode=snap" ?

Next, let's take a look at the logs:

syys 05 11:28:36 sampsa-asus geth[11610]: INFO [09-05|11:28:36.595] Imported new block headers               count=1    elapsed=4.940ms     number=15,476,571 hash=0cb37e..4b58b2 age=1h51m15s
syys 05 11:28:46 sampsa-asus geth[11610]: INFO [09-05|11:28:46.906] State heal in progress                   accounts=11,848,726@533.25MiB slots=34,874,749@2.60GiB    codes=107,715@798.25MiB nodes=363,163,945@58.88GiB pending=1
syys 05 11:29:04 sampsa-asus geth[11610]: WARN [09-05|11:29:04.616] Snapshot extension registration failed   peer=35ba3061 err="peer connected on snap without compatible eth support"
syys 05 11:29:08 sampsa-asus geth[11610]: INFO [09-05|11:29:08.040] State heal in progress                   accounts=11,848,726@533.25MiB slots=34,874,749@2.60GiB    codes=107,715@798.25MiB nodes=363,163,945@58.88GiB pending=1
syys 05 11:29:08 sampsa-asus geth[11610]: INFO [09-05|11:29:08.096] Imported new block headers               count=1    elapsed=5.270ms     number=15,476,572 hash=eab73d..75ece5 age=1h51m42s
syys 05 11:29:08 sampsa-asus geth[11610]: WARN [09-05|11:29:08.098] Dropping unsynced node during sync       id=c83d584aa6a7cf69 conn=inbound addr=146.0.216.163:40678   type=Geth/v1.10.23-stable...
syys 05 11:29:23 sampsa-asus geth[11610]: WARN [09-05|11:29:23.229] Snapshot extension registration failed   peer=2b87dc19 err="peer connected on snap without compatible eth support"
syys 05 11:29:27 sampsa-asus geth[11610]: WARN [09-05|11:29:27.443] Snapshot extension registration failed   peer=6de3885d err="peer connected on snap without compatible eth support"
syys 05 11:30:04 sampsa-asus geth[11610]: INFO [09-05|11:30:04.652] Imported new block headers               count=1    elapsed=5.077ms     number=15,476,573 hash=695338..95f981 age=1h52m27s
syys 05 11:30:05 sampsa-asus geth[11610]: INFO [09-05|11:30:05.349] Downloader queue stats                   receiptTasks=0     blockTasks=0     itemSize=254.59KiB throttle=1030
syys 05 11:30:48 sampsa-asus geth[11610]: INFO [09-05|11:30:48.716] Imported new block headers               count=2    elapsed=5.064ms     number=15,476,575 hash=664007..cdd2dd age=1h52m55s
syys 05 11:30:49 sampsa-asus geth[11610]: WARN [09-05|11:30:49.374] Pivot became stale, moving               old=15,476,449 new=15,476,513
syys 05 11:30:49 sampsa-asus geth[11610]: INFO [09-05|11:30:49.504] Imported new block receipts              count=64   elapsed=129.241ms   number=15,476,512 hash=14ddfa..f13f36 age=2h9m6s    size=8.55MiB
syys 05 11:30:49 sampsa-asus geth[11610]: INFO [09-05|11:30:49.504] State heal in progress                   accounts=11,848,726@533.25MiB slots=34,874,749@2.60GiB    codes=107,715@798.25MiB nodes=363,163,945@58.88GiB pending=1
syys 05 11:30:55 sampsa-asus geth[11610]: INFO [09-05|11:30:55.112] Imported new block headers               count=1    elapsed=4.197ms     number=15,476,576 hash=413332..413f19 age=1h52m57s
syys 05 11:31:23 sampsa-asus geth[11610]: INFO [09-05|11:31:23.472] Imported new block headers               count=1    elapsed=4.914ms     number=15,476,577 hash=192227..5f294e age=1h52m55s
syys 05 11:31:24 sampsa-asus geth[11610]: INFO [09-05|11:31:24.524] Downloader queue stats                   receiptTasks=0     blockTasks=0     itemSize=260.17KiB throttle=1008
syys 05 11:31:36 sampsa-asus geth[11610]: INFO [09-05|11:31:36.180] Imported new block headers               count=2    elapsed=9.148ms     number=15,476,579 hash=1d9258..ef0920 age=1h52m52s
syys 05 11:32:04 sampsa-asus geth[11610]: INFO [09-05|11:32:04.529] Imported new block headers               count=2    elapsed=6.110ms     number=15,476,581 hash=37288d..497e7a age=1h53m14s
syys 05 11:32:07 sampsa-asus geth[11610]: INFO [09-05|11:32:07.813] Imported new block headers               count=6    elapsed=17.703ms    number=15,476,587 hash=dbcbde..6a6aa8 age=1h52m40s
syys 05 11:32:11 sampsa-asus geth[11610]: INFO [09-05|11:32:11.064] Imported new block headers               count=2    elapsed=5.816ms     number=15,476,589 hash=f78c93..d547a7 age=1h52m35s
syys 05 11:32:14 sampsa-asus geth[11610]: INFO [09-05|11:32:14.329] Imported new block headers               count=1    elapsed=5.343ms     number=15,476,590 hash=1d970a..dbb580 age=1h52m36s
syys 05 11:32:17 sampsa-asus geth[11610]: INFO [09-05|11:32:17.596] Imported new block headers               count=1    elapsed=5.462ms     number=15,476,591 hash=8efbe0..077eb1 age=1h52m28s
syys 05 11:32:24 sampsa-asus geth[11610]: INFO [09-05|11:32:24.007] Imported new block headers               count=2    elapsed=13.627ms    number=15,476,593 hash=9d2ae6..f64c80 age=1h51m17s
syys 05 11:32:24 sampsa-asus geth[11610]: INFO [09-05|11:32:24.562] Downloader queue stats                   receiptTasks=0     blockTasks=0     itemSize=372.89KiB throttle=704
syys 05 11:32:30 sampsa-asus geth[11610]: INFO [09-05|11:32:30.406] Imported new block headers               count=1    elapsed=5.857ms     number=15,476,594 hash=59a38c..b964ff age=1h50m21s
syys 05 11:32:33 sampsa-asus geth[11610]: INFO [09-05|11:32:33.696] Imported new block headers               count=1    elapsed=5.346ms     number=15,476,595 hash=a0f7d8..ccb3e3 age=1h50m1s
syys 05 11:32:40 sampsa-asus geth[11610]: INFO [09-05|11:32:40.090] Imported new block headers               count=3    elapsed=5.102ms     number=15,476,598 hash=961009..fc298a age=1h49m9s
syys 05 11:32:43 sampsa-asus geth[11610]: INFO [09-05|11:32:43.361] Imported new block headers               count=1    elapsed=4.918ms     number=15,476,599 hash=05bd57..d6f4b9 age=1h49m
syys 05 11:32:49 sampsa-asus geth[11610]: INFO [09-05|11:32:49.788] Imported new block headers               count=6    elapsed=22.194ms    number=15,476,605 hash=91c36f..a618eb age=1h48m28s
syys 05 11:32:53 sampsa-asus geth[11610]: INFO [09-05|11:32:53.036] Imported new block headers               count=1    elapsed=4.784ms     number=15,476,606 hash=d3a357..1cb4d0 age=1h48m30s
syys 05 11:32:56 sampsa-asus geth[11610]: INFO [09-05|11:32:56.313] Imported new block headers               count=1    elapsed=4.866ms     number=15,476,607 hash=c0fc48..6b72f0 age=1h48m30s
syys 05 11:32:59 sampsa-asus geth[11610]: INFO [09-05|11:32:59.583] Imported new block headers               count=1    elapsed=5.789ms     number=15,476,608 hash=f7470d..d2f3c5 age=1h48m31s

• Blocks are imported at a good pace? A few milliseconds per block.
• "Pivot became stale, moving" : does this has to do something with downloading the snapshot from other peers? .. starting it all over again? Is it doing (A) or (B) (see above)?
• State heal in progress reports the number of accounts in ethereum.. this should be near hundred millions at the moment? Why the state is healed/updated soooo slow? (this is after being a few days online).

Let's continue:

syys 05 11:50:13 sampsa-asus geth[11610]: INFO [09-05|11:50:13.381] Disabling direct-ancient mode            origin=15,477,053 ancient=14,627,238
syys 05 11:50:13 sampsa-asus geth[11610]: INFO [09-05|11:50:13.381] State heal in progress                   accounts=11,848,726@533.25MiB slots=34,874,749@2.60GiB    codes=107,715@798.25MiB nodes=363,168,162@58.88GiB pending=1
syys 05 11:50:13 sampsa-asus geth[11610]: INFO [09-05|11:50:13.750] Imported new block headers               count=9    elapsed=90.869ms    number=15,477,128 hash=8cad3b..8a6686 age=1m10s     ignored=66
syys 05 11:50:17 sampsa-asus geth[11610]: INFO [09-05|11:50:17.219] Imported new block headers               count=1    elapsed=4.008ms     number=15,477,129 hash=4a8b20..97bd42 age=1m10s
syys 05 11:50:18 sampsa-asus geth[11610]: INFO [09-05|11:50:18.430] Downloader queue stats                   receiptTasks=0     blockTasks=0     itemSize=262.34KiB throttle=1000
syys 05 11:50:18 sampsa-asus geth[11610]: INFO [09-05|11:50:18.451] Imported new block receipts              count=10   elapsed=20.515ms    number=15,477,063 hash=68f457..1a4bca age=14m52s    size=2.11MiB
syys 05 11:50:18 sampsa-asus geth[11610]: INFO [09-05|11:50:18.451] State heal in progress                   accounts=11,848,726@533.25MiB slots=34,874,749@2.60GiB    codes=107,715@798.25MiB nodes=363,168,162@58.88GiB pending=1
syys 05 11:50:25 sampsa-asus geth[11610]: INFO [09-05|11:50:25.672] Imported new block headers               count=1    elapsed=6.006ms     number=15,477,130 hash=5c6caa..88b273
syys 05 11:50:29 sampsa-asus geth[11610]: INFO [09-05|11:50:29.716] State heal in progress                   accounts=11,848,726@533.25MiB slots=34,874,749@2.60GiB    codes=107,715@798.25MiB nodes=363,169,396@58.88GiB pending=19532
syys 05 11:50:40 sampsa-asus geth[11610]: WARN [09-05|11:50:40.869] Snapshot extension registration failed   peer=1125cc47 err="peer connected on snap without compatible eth support"
syys 05 11:50:47 sampsa-asus geth[11610]: INFO [09-05|11:50:47.686] Imported new block headers               count=1    elapsed=8.713ms     number=15,477,131 hash=0145a7..0ce6dc

• What is disabling direct-ancient mode? Does it has to do with the problem at hand?
• Note the "State heal in progress" reporting number of pending accounts jumping from 1 to 19532. Why's that?
• Note that donwloaded and verified blocks are practically there: "age=1m10s"
• Then we have a lot of this going on:

syys 05 16:08:19 sampsa-asus geth[11610]: WARN [09-05|16:08:19.561] Unexpected bytecode heal packet          peer=905d36fa reqid=7,304,675,219,279,965,590

• what's that about? Haven't seen a proper explanation of this anywhere.

The client was running ~ 4 days until I got fed up and put it offline. Got this far:

syys 05 16:08:58 sampsa-asus geth[11610]: INFO [09-05|16:08:58.909] State heal in progress                   accounts=12,866,567@579.80MiB slots=37,899,809@2.82GiB    codes=111,459@826.38MiB nodes=371,245,285@60.02GiB pending=188,584

I interprete that downloaded and verified blocks are ok (it seem to reach the latest block occasionally), but the client is unable to reconstruct the up-to-date world state "SC".

I don't understand why. Once the block is downloaded and verified you get the state change, so what is interfering here with the state update/reconstruction?

Is there some competition/contradiction going on between (A) and (B)? (see above)

Some details on my system:
8 x Intel(R) Core(TM) i7-4700HQ CPU @ 2.40GHz
2TB SSD drive: "Crucial BX500"
12 GB RAM (& all the swap you could wish for)
(as mentioned, this was able to snapsync from scratch before summer)

P. S. It would be important to be able to contribute to the network without being a 24/7 avail/on-call eth-client-massage service provider.. to be offline if needed, etc. Imagine that I'd done staking at this point..!

[MariusVanDerWijden]

It looks like you were not fully snap synced when you shut down your node the last time. You were most likely still in the state heal phase. Otherwise geth would import blocks one by one afterwards. The problem now is that you have a really old state that is not fully healed, so a lot of accounts, balances etc are different than the current state. In the state healing phase these states are fetched one by one from the network. Since they are so many differences between you and the network, the state heal phase will likely never finish. The best way to fix this is to stop geth and remove the old state that you have (via geth removedb y 'n`). This will force the node to start a new snap sync which should finish in a couple of hours.

Regarding your PS: nodes can recover very quickly from a couple of days of downtime once they are fully synced (and healed). Since the gas limit in ethereum was voted up and is pretty high atm, the nodes have to do a lot of computation, especially if they want to sync up to the network

[elsampsa]

Thanks for the reply. But I am 100% sure that it synced.. checked it form the geth console, etc.

I guess there's nothing else left to do than to do yet another snap sync & I keep this ticket still open a few days just in case..

To confirm.. once the snap sync is over, after that geth will behave like a normal "full" node.. there's no condition/bug? under which it would start a snap sync again. And it's pitty no-one never explains that "Unexpected bytecode heal packet"..!

[MariusVanDerWijden]

Yes a node will never start a sync again after its been synced once
The "unexpected bytecode heal packet" is printed either when a peer sends us data that we haven't requested or if a reply arrives after the request already timed out (so you request something, the peer takes too long to respond, you stop tracking the request, the peer finally responds)

[elsampsa]

I'm running

geth removedb

Should I remove ancient database as well..?

I keps the ancient database & now it seems to work like a full node..?

syys 12 08:23:08 sampsa-asus geth[2567]: INFO [09-12|08:23:08.248] Imported new block receipts              count=18   elapsed=135.821ms   number=14,627,793 hash=769804..0be43a age=4mo3w2d
....
syys 12 08:23:03 sampsa-asus geth[2567]: WARN [09-12|08:23:03.989] Pivot seemingly stale, moving            old=15,519,069 new=15,519,133

State heal logs missing at the moment

[aathan]

I've spent some time looking around and trying to understand the differences between geth's sync modes but am still left with some open questions. For example: Does a geth node that either snap or fast sync's initially, end up with the same database state as a "full node" that has executed all of the transactions since the genesis block? Or does snap sync involve only acquiring a "digest" of the storage state of all addresses as of the sync point, such that future requests made to this node for storage as of some older block, would then involve the node making new requests to peers to acquire that older state? Please forgive me if any of this is malformed. I'm asking these questions having made some possibly incorrect assumptions about "everything."

Having just written these questions, I thought of a better google query, and found this: #24413

Probably a good idea to incorporate some/all of the wisdom there, into the docs.

[elsampsa]

After doing ``geth removedb" (but keeping ancient database/freezer) now it's in the state heal process again. It downloaded all missing blocks and after that "state heal" logs started to appear.

Now, as always, logs are saturated with:

Unexpected trienode heal packet

State healing is painstakingly slow:

syys 13 16:51:30 sampsa-asus geth[1325]: INFO [09-13|16:51:30.912] State heal in progress                   accounts=524,748@26.14MiB     slots=1,009,090@76.24MiB    codes=877@6.82MiB     nodes=5,091,192@1.26GiB    pending=29246

Maybe 500 000 accounts per 24h ..?

So geth removedb didn't help. Now what? Should I also remove also the "ancient" database and try to do snap sync?

download recent global state "SC0" using snap

then that global state needs to be "healed" using the downloaded blocks "SC0" --> blocks --> "SC1" (current global state)

Nobody knows why.. just (clueless) nerds (like myself) trying to scrap information from the internet. Do you have any "testing" lab where you put clients on & offline & try to disturb them in some private geth ethereum network? Or does "ci/cd testing" equal to "merge" (I hope not).

EDIT: maybe the ancient database is corrupt..? Does the ancient database include a state trie that is loaded in the beginning & then it tries to heal it..
..or is the latest state fetched with snap sync if I have done geth removedb (but not removed the ancient database)

[aathan]

On a related note, I ended up with the impression that it has become quite difficult to stand up a full node in lieu of using centralized providers such as alchemy/moralis/infura etc because of these types of troubles (and perhaps my last attempt was when snap sync was too new). That slowness and/or troubles in this area ends up pushing dApp providers to rely on centralized resources such as Infura/Moralis/Alchemy (vs it being super easy to stand up their own nodes) may be an issue to think about (pros and cons to each).

It would be really nice to be able to stand up a full node that can answer historical requests (gcmode archive) quickly by acquiring that database and/or being able to forward such queries to/from peers, and then verifying it on a best-efforts basis over a longer timeframe. I'm not fully conversant on the security implications and/or implementation difficulties and/or bandwidth/resource management issues of doing such a thing -- but I sense it would help reduce centralization onto a handful of dApp service providers.

[Sreeram1993]

Similar scenarios in my node as well. I have 2 geth archival nodes connected to 2 beacon nodes and both seems to have completed merge. But the nodes seems to be syncing very slowly. PFB the status from both nodes

GETH
node 0 - INFO [09-21|06:25:06.231] Imported new potential chain segment blocks=1 txs=295 mgas=22.221 elapsed=9.974s mgasps=2.228 number=15,559,291 hash=0961a7..1d9571 age=2d21h47m dirty=0.00B
node 1 - INFO [09-21|06:25:07.196] Imported new potential chain segment blocks=1 txs=371 mgas=27.281 elapsed=9.188s mgasps=2.969 number=15,557,806 hash=9b6067..887a31 age=3d2h46m dirty=0.00B

BEACON
node 0 - time="2022-09-21 06:26:27" level=info msg="Processing block batch of size 64 starting from 0xb47a08d1... 4722176/4743130 - estimated time remaining 15m39s" blocksPerSecond=22.3 peers=49 prefix=initial-sync
node 1 - time="2022-09-21 06:25:20" level=info msg="Processing block batch of size 64 starting from 0x2ff82104... 4720690/4743124 - estimated time remaining 29m19s" blocksPerSecond=12.8 peers=45 prefix=initial-sync

The slots(3 days behind current slot) in beacon seems to be in sync with the block shown in geth node. Can anyone confirm if this is healthy and our sync is well and good but a bit slow ?

[holiman]

Now, as always, logs are saturated with:

Unexpected trienode heal packet

This has actually been fixed, but not pushed to stable(a.k.a v1.10.xx). If you use latest (a.k.a 1.11.xx -unstable) you should not see these messages (as much). Several issues related to snap-sync were fixed, and in many cases that were previously unable to sync due to IO performance is now made possible.

So, I recommend switching geth-version.

So geth removedb didn't help. Now what? Should I also remove also the "ancient" database and try to do snap sync?

I recommend

1. Use 1.11
2. do geth removedb but keep ancients intact.

@Sreeram1993

node 0 - INFO [09-21|06:25:06.231] Imported new potential chain segment blocks=1 txs=295 mgas=22.221 elapsed=9.974s mgasps=2.228 number=15,559,291 hash=0961a7..1d9571 age=2d21h47m dirty=0.00B
node 1 - INFO [09-21|06:25:07.196] Imported new potential chain segment blocks=1 txs=371 mgas=27.281 elapsed=9.188s mgasps=2.969 number=15,557,806 hash=9b6067..887a31 age=3d2h46m dirty=0.00B

These numbers aren't great -- as you can sees, importing one block takes almost 10s. That is very close to the block-time. Obviously, if import is slower than block-time, then you will not be able to keep up. Other than that, yeah, looks ok to me

[holiman]

Oh, btw -- is there really a point in keeping this bug open? Seems like the discussion has trailed off into new areas?

[Sreeram1993]

Thanks for the update @holiman Is there anyway to increase the import time, I am already using an 16TB SSD and the nodes are in AKS as well. Any sol to increase peers or network bandwidth so that archival node stays upto date ?

[holiman]

Increasing peers will most likely have a negative impact. I don't know what AKS means.

If you are interested in trying something new, we have a new database backend which we think will be an improvement: #24615 . Unfortunately, we don't have any conversion-tool, so the only thing one can do with it is to sync from scratch -- which is a PITA with archive node, I know, so I don't actually expect you to try it out.

Other than that, I don't have a lot of ideas.

[Sreeram1993]

@holiman Got it fixed and I started running. But I get this INFO for blocks multiple times for a same block.

--GETH--
INFO [09-22|13:01:36.034] Imported new potential chain segment blocks=1 txs=210 mgas=25.110 elapsed=1m19.317s mgasps=0.317 number=15,588,279 hash=461b03..8964d1 age=2h34m37s dirty=0.00B
INFO [09-22|13:01:36.176] Imported new potential chain segment blocks=1 txs=210 mgas=25.110 elapsed=142.118ms mgasps=176.686 number=15,588,279 hash=461b03..8964d1 age=2h34m37s dirty=0.00B
INFO [09-22|13:01:36.318] Imported new potential chain segment blocks=1 txs=210 mgas=25.110 elapsed=141.422ms mgasps=177.556 number=15,588,279 hash=461b03..8964d1 age=2h34m37s dirty=0.00B
--GETH--
Certain blocks show import just once while some shows multiple info messages like above. Is it corrupting the node ?