Ropsten corrupt database on reorg

[omarsayha]

System information

Geth version: v1.10.8
OS & Version: Ubuntu 18.04.4 LTS (Bionic Beaver)
Network: ropsten

Expected behaviour

eth_getBlockByNumber 0xA6A153 (10920275):

{
    ...
    "hash": "0x06533bf198874719a3de36317181459ad99a139d7a8555d4f209cc07fcf86483",
    "parentHash": "0xfd652086d220d506ae5b7cb80fde97d2f3f7028d346cc7d9d384a83d3d638532",
    ...
}

eth_getBlockByNumber 0xA6A152 (10920274):

{
    ...
    "hash": "0xfd652086d220d506ae5b7cb80fde97d2f3f7028d346cc7d9d384a83d3d638532",
    "parentHash": "0x1a481511d4b8e7a2ab55e5e03eabc81be7ccda47763da9ab18414074ae678355",
    ...
}

Actual behaviour

eth_getBlockByNumber 0xA6A153 (10920275) - different then expcted:

{
    ...
    "hash": "0x5b6007e7e4d44c0ff8df036c01c42bf2c15313fbd95cfa4c403bbc6051077e39",
    "parentHash": "0x2fd63eb95c8059a46b5afedb903ef1639b9414e9d38f70b3dfb0f733b7ced14f",
    ...
}

eth_getBlockByNumber 0xA6A152 (10920274) - same as expected:

{
    ...
    "hash": "0xfd652086d220d506ae5b7cb80fde97d2f3f7028d346cc7d9d384a83d3d638532",
    "parentHash": "0x1a481511d4b8e7a2ab55e5e03eabc81be7ccda47763da9ab18414074ae678355",
    ...
}

Note that the parentHash of 0xA6A153 is different than the hash of 0xA6A152.

Steps to reproduce the behaviour

Might be hard to reproduce as I expect it might be a race condition with rewinding reorgs that corrupts the database but here are the possibly relevant flags I used:

--syncmode fast --gcmode=full

And the relevant log lines that make me possibly suspect a race condition:

WARN [09-10|19:52:11.182] Rewinding blockchain target=11,008,644
WARN [09-10|19:52:14.253] Rewinding blockchain target=10,920,274

Backtrace

INFO [09-10|19:51:59.067] Aborting state snapshot generation       root=0e3236..87b644 at=000001..509af0 accounts=4   slots=0 storage=248.00B elapsed=51.021s     eta=150083h9m0.962s
INFO [09-10|19:51:59.067] Resuming state snapshot generation       root=3681db..0e4001 at=000001..509af0 accounts=4   slots=0 storage=248.00B elapsed=51.022s     eta=150086h5m44.054s
INFO [09-10|19:51:59.094] Aborting state snapshot generation       root=3681db..0e4001 at=000001..509af0 accounts=4   slots=0 storage=248.00B elapsed=51.048s     eta=150162h34m23.643s
INFO [09-10|19:51:59.094] Resuming state snapshot generation       root=6f944d..451a16 at=000001..509af0 accounts=4   slots=0 storage=248.00B elapsed=51.049s     eta=150165h31m2.118s
INFO [09-10|19:51:59.121] Aborting state snapshot generation       root=6f944d..451a16 at=000001..509af0 accounts=4   slots=0 storage=248.00B elapsed=51.076s     eta=150244h56m5.756s
INFO [09-10|19:51:59.121] Resuming state snapshot generation       root=fa6b66..554208 at=000001..509af0 accounts=4   slots=0 storage=248.00B elapsed=51.076s     eta=150244h56m5.756s
INFO [09-10|19:51:59.122] Imported new chain segment               blocks=6   txs=41  mgas=5.137  elapsed=172.800ms   mgasps=29.730 number=11,010,688 hash=88029d..cedea3 age=1m52s    dirty=8.71MiB
INFO [09-10|19:51:59.122] Imported new block headers               count=1    elapsed=48.782s     number=11,010,689 hash=5600cc..8dddfc age=1m46s
INFO [09-10|19:51:59.125] Downloader queue stats                   receiptTasks=0 blockTasks=0 itemSize=9.78KiB  throttle=8192
INFO [09-10|19:51:59.155] Aborting state snapshot generation       root=fa6b66..554208 at=000001..509af0 accounts=4   slots=0 storage=248.00B elapsed=51.109s     eta=150342h0m29.837s
INFO [09-10|19:51:59.155] Resuming state snapshot generation       root=cc0506..0499d4 at=000001..509af0 accounts=4   slots=0 storage=248.00B elapsed=51.109s     eta=150342h0m29.837s
INFO [09-10|19:51:59.155] Imported new chain segment               blocks=1   txs=7   mgas=0.871  elapsed=30.536ms    mgasps=28.511 number=11,010,689 hash=5600cc..8dddfc age=1m46s    dirty=8.83MiB
INFO [09-10|19:51:59.156] Imported new block headers               count=1    elapsed=33.179ms    number=11,010,690 hash=021234..bc72b7 age=1m36s
INFO [09-10|19:52:00.123] Indexing transactions                    blocks=2267 txs=22255 tail=8,658,010 total=8,660,277 elapsed=1.000s
INFO [09-10|19:52:08.124] Indexing transactions                    blocks=17465 txs=304,113 tail=8,642,812 total=8,660,277 elapsed=9.000s
INFO [09-10|19:52:11.181] Aborting state snapshot generation       root=cc0506..0499d4 at=000003..efa94d accounts=5   slots=0 storage=318.00B elapsed=1m3.135s    eta=89917h35m40.373s
INFO [09-10|19:52:11.181] Resuming state snapshot generation       root=be77de..5c493a at=000003..efa94d accounts=5   slots=0 storage=318.00B elapsed=1m3.135s    eta=89917h35m40.373s
INFO [09-10|19:52:11.182] Imported new chain segment               blocks=1     txs=26      mgas=6.261  elapsed=12.022s     mgasps=0.521  number=11,010,690 hash=021234..bc72b7 age=1m48s    dirty=9.04MiB
INFO [09-10|19:52:11.182] Imported new block headers               count=3    elapsed=12.026s     number=11,010,693 hash=9ba175..d9bb6d
WARN [09-10|19:52:11.182] Invalid header encountered               number=11,010,695 hash=42b906..0974f7 parent=25c931..a3418f err="unknown ancestor"
WARN [09-10|19:52:11.182] Rewinding blockchain                     target=11,008,644
INFO [09-10|19:52:12.410] Loaded most recent local header          number=11,008,644 hash=a7c19f..910a25 td=34,729,223,946,089,062 age=5h58m45s
INFO [09-10|19:52:12.410] Loaded most recent local full block      number=0          hash=419410..ca4a2d td=1,048,576              age=52y5mo1w
INFO [09-10|19:52:12.410] Loaded most recent local fast block      number=11,008,644 hash=a7c19f..910a25 td=34,729,223,946,089,062 age=5h58m45s
INFO [09-10|19:52:12.410] Loaded last fast-sync pivot marker       number=11,010,598
WARN [09-10|19:52:12.410] Rolled back chain segment                header=11010693->11008644 fast=11010598->11008644 block=11010690->0 reason="unknown ancestor"
WARN [09-10|19:52:12.410] Synchronisation failed, dropping peer    peer=7bd8a743fb976875d4bd0430de8f3c5cf415758db0dcee463697c6580ba28736 err="retrieved hash chain is invalid: unknown ancestor"
WARN [09-10|19:52:14.253] Rewinding blockchain                     target=10,920,274
INFO [09-10|19:52:16.256] Indexing transactions                    blocks=44646 txs=614,681 tail=8,615,631 total=8,660,277 elapsed=17.133s
ERROR[09-10|19:52:18.697] Snapshot extension registration failed   peer=aa1d27f0 err="peer connected on snap without compatible eth support"
ERROR[09-10|19:52:21.247] Snapshot extension registration failed   peer=90896456 err="peer connected on snap without compatible eth support"
INFO [09-10|19:52:23.424] Generating state snapshot                root=be77de..5c493a at=000003..dee3ce accounts=6   slots=0 storage=388.00B elapsed=1m15.378s   eta=106692h59m28.394s
INFO [09-10|19:52:24.257] Indexing transactions                    blocks=75543 txs=862,733 tail=8,584,734 total=8,660,277 elapsed=25.133s
INFO [09-10|19:52:31.435] Generating state snapshot                root=be77de..5c493a in=000393..2778a9 at=ac689f..1f4d80 accounts=1866 slots=6794 storage=639.69KiB elapsed=1m23.389s   eta=424h18m49.322s
INFO [09-10|19:52:32.257] Indexing transactions                    blocks=104,670 txs=1,070,490 tail=8,555,607 total=8,660,277 elapsed=33.134s
INFO [09-10|19:52:39.437] Generating state snapshot                root=be77de..5c493a at=000b11..3ba175 accounts=5797 slots=12887 storage=1.31MiB   elapsed=1m31.391s   eta=150h16m28.83s
WARN [09-10|19:52:39.920] Checkpoint challenge timed out, dropping id=d9fc0b76ace2534f conn=inbound addr=88.198.26.100:37446             type=erigon/v2021.09.2-al...
INFO [09-10|19:52:40.258] Indexing transactions                    blocks=121,430 txs=1,403,189 tail=8,538,847 total=8,660,277 elapsed=41.134s
ERROR[09-10|19:52:41.698] Snapshot extension registration failed   peer=70d956b8 err="peer connected on snap without compatible eth support"
INFO [09-10|19:52:43.592] Writing clean trie cache to disk         path=/mnt/data/.ethereum/geth/triecache threads=1
INFO [09-10|19:52:43.852] Regenerated local transaction journal    transactions=9    accounts=5
INFO [09-10|19:52:45.261] Persisted the clean trie cache           path=/mnt/data/.ethereum/geth/triecache elapsed=1.669s
INFO [09-10|19:52:47.437] Generating state snapshot                root=be77de..5c493a at=001009..6fd975 accounts=8394 slots=19868 storage=1.97MiB   elapsed=1m39.391s   eta=112h47m24.806s
INFO [09-10|19:52:48.258] Indexing transactions                    blocks=138,821 txs=1,715,584 tail=8,521,456 total=8,660,277 elapsed=49.135s
INFO [09-10|19:52:55.437] Generating state snapshot                root=be77de..5c493a at=001783..6641a1 accounts=12275 slots=31399 storage=3.03MiB   elapsed=1m47.392s   eta=83h6m53.369s
INFO [09-10|19:52:56.260] Indexing transactions                    blocks=156,201 txs=1,997,066 tail=8,504,076 total=8,660,277 elapsed=57.136s
INFO [09-10|19:53:03.437] Generating state snapshot                root=be77de..5c493a at=001faf..f85894 accounts=16581 slots=36315 storage=3.65MiB   elapsed=1m55.392s   eta=66h15m43.676s
INFO [09-10|19:53:04.260] Indexing transactions                    blocks=170,693 txs=2,257,924 tail=8,489,584 total=8,660,277 elapsed=1m5.136s

Let me know if there is any other relevant information I can provide, thanks for the help!

[verheesj]

INFO [09-10|19:52:11.182] Imported new block headers               count=3    elapsed=12.026s     number=11,010,693 hash=9ba175..d9bb6d
WARN [09-10|19:52:11.182] Invalid header encountered               number=11,010,695 hash=42b906..0974f7 parent=25c931..a3418f err="unknown ancestor"

Interesting. I'm looking into this.

[holiman]

(not a solution nor full explanation, just notes:) This sync failed to finish the very last phase of fast/snap sync, the last 64 blocks. This causes the fast-sync to go back ~2k blocks, going back before the pivot point.

[holiman]

Best guess if we want to try to repro this:

• fast-(or snap) sync, fail in the last blocks.
• Then restart sync with a peer who has an alternative chain, with fairly deep common ancestor (close to 90K)
• And then when fast-sync will reorg to that common ancestor, and try to sync from there.

[holiman]

@oceja do you have the logs after that portion? A couple of hundred lines, perhaps

[omarsayha]

@holiman and @verheesj thanks for taking a look! Do you think this problem would happen wether or not I was using fast sync or snap sync (I noticed that Geth is sun-setting fast sync in favor of snap sync).

Also here are 1K log lines after the rewind (https://gist.github.com/oceja/fbf55b7c5c1684557316e3fa1c9a7475), hopefully they are helpful. Let me know if I can provide any more info/logs to help debug

[verheesj]

@holiman and @verheesj thanks for taking a look! Do you think this problem would happen wether or not I was using fast sync or snap sync (I noticed that Geth is sun-setting fast sync in favor of snap sync).

Also here are 1K log lines after the rewind (https://gist.github.com/oceja/fbf55b7c5c1684557316e3fa1c9a7475), hopefully they are helpful. Let me know if I can provide any more info/logs to help debug

Can you try adding --cache=2048 and --no-discover to your geth.

You will need to add your peers manually via console or your config.

I know it might not seem relevant...

[omarsayha]

@holiman and @verheesj thanks for taking a look! Do you think this problem would happen wether or not I was using fast sync or snap sync (I noticed that Geth is sun-setting fast sync in favor of snap sync).
Also here are 1K log lines after the rewind (https://gist.github.com/oceja/fbf55b7c5c1684557316e3fa1c9a7475), hopefully they are helpful. Let me know if I can provide any more info/logs to help debug

Can you try adding --cache=2048 and --no-discover to your geth.

You will need to add your peers manually via console or your config.

I know it might not seem relevant...

The cache is already configured to be double that size. Here are all the flags the node is running with:

geth --ropsten --syncmode fast --datadir /mnt/data/.ethereum --gcmode=full --rpc.txfeecap 0 --rpc.gascap 0 --cache 4096 --http.api admin,debug,eth,net,web3,txpool --http --http.addr 0.0.0.0 --http.vhosts * --ws --ws.addr 0.0.0.0 --ws.port 8546 --ws.origins * --ws.api eth --metrics --pprof --pprof.addr 0.0.0.0 --nousb--verbosity 3 --rpc.allow-unprotected-txs

And if I use --nodiscover how do I get a list of nodes to peer from? Is the worry that it might be peering with ropsten nodes that don't have the latest security patch, if so is there a way to specify discovery of peers that are above a certain version?

[verheesj]

@holiman and @verheesj thanks for taking a look! Do you think this problem would happen wether or not I was using fast sync or snap sync (I noticed that Geth is sun-setting fast sync in favor of snap sync).
Also here are 1K log lines after the rewind (https://gist.github.com/oceja/fbf55b7c5c1684557316e3fa1c9a7475), hopefully they are helpful. Let me know if I can provide any more info/logs to help debug

Can you try adding --cache=2048 and --no-discover to your geth.
You will need to add your peers manually via console or your config.
I know it might not seem relevant...

The cache is already configured to be double that size. Here are all the flags the node is running with:

geth --ropsten --syncmode fast --datadir /mnt/data/.ethereum --gcmode=full --rpc.txfeecap 0 --rpc.gascap 0 --cache 4096 --http.api admin,debug,eth,net,web3,txpool --http --http.addr 0.0.0.0 --http.vhosts * --ws --ws.addr 0.0.0.0 --ws.port 8546 --ws.origins * --ws.api eth --metrics --pprof --pprof.addr 0.0.0.0 --nousb--verbosity 3 --rpc.allow-unprotected-txs

And if I use --nodiscover how do I get a list of nodes to peer from? Is the worry that it might be peering with ropsten nodes that don't have the latest security patch, if so is there a way to specify discovery of peers that are above a certain version?

To establish the correct direction, can you answer the questions below?

1. What is the capacity and type of hard disk is /mnt/data/
2. How much RAM do you have?
3. What is the spec of the machine? Is it a home machine/Amazon etc.
4. Why are you allowing unprotected transactions

Please disregard the --nodiscover I had previously asked for you to try.

Q: While geth is running, launch geth console, and execute eth.syncing. Could you the output. It might also be worth monitoring the values so see if they are changing/increasing/reverting etc (focus on the state values in particular).

Q: Is the sync in question a fresh sync without any data pre-existing. This is important as --syncmode=fast will not work on pre-existing data.

Q: Finally, please amend verbosity level to --verbosity=5 to provide more detailed debugging information. Please can you provide the a log from when the node is launched through any errors, and several hundred lines after.

[holiman]

Why are you allowing unprotected transactions

This is not actually relevant for the bug we're investigating.

Q: While geth is running, launch geth console, and execute eth.syncing

It's syncing. It's pretty evident from the logs already what's happening with regards to that (fetching blocks, pulling state)

Q: Is the sync in question a fresh sync without any data pre-existing

The logs are pretty clear (https://gist.github.com/oceja/fbf55b7c5c1684557316e3fa1c9a7475) . It's a snap/fast sync. Doesn't really matter if it's been restarted during the sync.

Q: Finally, please amend verbosity level to --verbosity=5 to provide more detailed debugging information.

Warning, this will be huge, particularly the discovery parts do an extreme amount of logging if verbosity is at 5. I don't know if there's anything in particular we might get from that, personally.

[holiman]

I filtered out the most interesting parts of the log

INFO [09-10|19:51:36.190] Aborting state snapshot generation       root=cf1de9..75101f at=000001..805a2a accounts=2   slots=0 storage=140.00B elapsed=28.145s     eta=113395h1m33.128s
INFO [09-10|19:51:36.191] Resuming state snapshot generation       root=1b09dc..feda43 at=000001..805a2a accounts=2   slots=0 storage=140.00B elapsed=28.145s     eta=113395h1m33.128s
INFO [09-10|19:51:36.218] Aborting state snapshot generation       root=1b09dc..feda43 at=000001..805a2a accounts=2   slots=0 storage=140.00B elapsed=28.172s     eta=113503h48m17.772s
INFO [09-10|19:51:36.218] Resuming state snapshot generation       root=296040..8e7ade at=000001..805a2a accounts=2   slots=0 storage=140.00B elapsed=28.172s     eta=113503h48m17.772s
ERROR[09-10|19:51:36.806] Snapshot extension registration failed   peer=8305ed62 err="peer connected on snap without compatible eth support"
ERROR[09-10|19:51:41.031] Snapshot extension registration failed   peer=3c63a74d err="peer connected on snap without compatible eth support"
ERROR[09-10|19:51:44.262] Snapshot extension registration failed   peer=aa5a2d5b err="peer connected on snap without compatible eth support"
INFO [09-10|19:51:47.233] Aborting state snapshot generation       root=296040..8e7ade at=000001..7abc92 accounts=3   slots=0 storage=210.00B elapsed=39.187s     eta=125737h54m52.375s
INFO [09-10|19:51:47.233] Resuming state snapshot generation       root=94d072..3074d0 at=000001..7abc92 accounts=3   slots=0 storage=210.00B elapsed=39.187s     eta=125737h54m52.375s
INFO [09-10|19:51:47.234] Imported new chain segment               blocks=43  txs=384 mgas=71.512 elapsed=12.216s     mgasps=5.854 number=11,010,655 hash=bba2a3..a67a84 age=8m20s    dirty=5.66MiB
...
INFO [09-10|19:51:47.961] Resuming state snapshot generation       root=d742a8..77647e at=000001..7abc92 accounts=3   slots=0 storage=210.00B elapsed=39.915s     eta=128073h45m36.823s
INFO [09-10|19:51:47.987] Aborting state snapshot generation       root=d742a8..77647e at=000001..7abc92 accounts=3   slots=0 storage=210.00B elapsed=39.942s     eta=128160h23m35.939s
INFO [09-10|19:51:47.988] Resuming state snapshot generation       root=d65f6f..14846b at=000001..7abc92 accounts=3   slots=0 storage=210.00B elapsed=39.942s     eta=128160h23m35.939s
ERROR[09-10|19:51:52.223] Snapshot extension registration failed   peer=b17b6239 err="peer connected on snap without compatible eth support"
WARN [09-10|19:51:54.727] Checkpoint challenge timed out, dropping id=f85b0214f5d7d6ff conn=dyndial addr=157.90.4.232:30303              type=erigon/v2021.08.2-al...
INFO [09-10|19:51:58.948] Aborting state snapshot generation       root=d65f6f..14846b at=000001..509af0 accounts=4   slots=0 storage=248.00B elapsed=50.903s     eta=149736h3m3.762s
INFO [09-10|19:51:58.949] Resuming state snapshot generation       root=1cafb5..20a3e2 at=000001..509af0 accounts=4   slots=0 storage=248.00B elapsed=50.903s     eta=149736h3m3.762s
INFO [09-10|19:51:58.949] Imported new chain segment               blocks=27  txs=192 mgas=38.788 elapsed=11.715s     mgasps=3.311 number=11,010,682 hash=58f7a0..552c4d age=3m19s    dirty=8.19MiB
INFO [09-10|19:51:58.982] Aborting state snapshot generation       root=1cafb5..20a3e2 at=000001..509af0 accounts=4   slots=0 storage=248.00B elapsed=50.937s     eta=149836h3m53.237s
INFO [09-10|19:51:58.983] Resuming state snapshot generation       root=8fcca3..a58dfd at=000001..509af0 accounts=4   slots=0 storage=248.00B elapsed=50.937s     eta=149836h3m53.237s
...
INFO [09-10|19:51:59.121] Resuming state snapshot generation       root=fa6b66..554208 at=000001..509af0 accounts=4   slots=0 storage=248.00B elapsed=51.076s     eta=150244h56m5.756s
INFO [09-10|19:51:59.122] Imported new chain segment               blocks=6   txs=41  mgas=5.137  elapsed=172.800ms   mgasps=29.730 number=11,010,688 hash=88029d..cedea3 age=1m52s    dirty=8.71MiB
INFO [09-10|19:51:59.122] Imported new block headers               count=1    elapsed=48.782s     number=11,010,689 hash=5600cc..8dddfc age=1m46s
INFO [09-10|19:51:59.125] Downloader queue stats                   receiptTasks=0 blockTasks=0 itemSize=9.78KiB  throttle=8192
INFO [09-10|19:51:59.155] Aborting state snapshot generation       root=fa6b66..554208 at=000001..509af0 accounts=4   slots=0 storage=248.00B elapsed=51.109s     eta=150342h0m29.837s
INFO [09-10|19:51:59.155] Resuming state snapshot generation       root=cc0506..0499d4 at=000001..509af0 accounts=4   slots=0 storage=248.00B elapsed=51.109s     eta=150342h0m29.837s
INFO [09-10|19:51:59.155] Imported new chain segment               blocks=1   txs=7   mgas=0.871  elapsed=30.536ms    mgasps=28.511 number=11,010,689 hash=5600cc..8dddfc age=1m46s    dirty=8.83MiB
INFO [09-10|19:51:59.156] Imported new block headers               count=1    elapsed=33.179ms    number=11,010,690 hash=021234..bc72b7 age=1m36s
INFO [09-10|19:52:11.181] Aborting state snapshot generation       root=cc0506..0499d4 at=000003..efa94d accounts=5   slots=0 storage=318.00B elapsed=1m3.135s    eta=89917h35m40.373s
INFO [09-10|19:52:11.181] Resuming state snapshot generation       root=be77de..5c493a at=000003..efa94d accounts=5   slots=0 storage=318.00B elapsed=1m3.135s    eta=89917h35m40.373s
INFO [09-10|19:52:11.182] Imported new chain segment               blocks=1     txs=26      mgas=6.261  elapsed=12.022s     mgasps=0.521  number=11,010,690 hash=021234..bc72b7 age=1m48s    dirty=9.04MiB
INFO [09-10|19:52:11.182] Imported new block headers               count=3    elapsed=12.026s     number=11,010,693 hash=9ba175..d9bb6d
WARN [09-10|19:52:11.182] Invalid header encountered               number=11,010,695 hash=42b906..0974f7 parent=25c931..a3418f err="unknown ancestor"
WARN [09-10|19:52:11.182] Rewinding blockchain                     target=11,008,644
INFO [09-10|19:52:12.410] Loaded most recent local header          number=11,008,644 hash=a7c19f..910a25 td=34,729,223,946,089,062 age=5h58m45s
INFO [09-10|19:52:12.410] Loaded most recent local full block      number=0          hash=419410..ca4a2d td=1,048,576              age=52y5mo1w
INFO [09-10|19:52:12.410] Loaded most recent local fast block      number=11,008,644 hash=a7c19f..910a25 td=34,729,223,946,089,062 age=5h58m45s
INFO [09-10|19:52:12.410] Loaded last fast-sync pivot marker       number=11,010,598
WARN [09-10|19:52:12.410] Rolled back chain segment                header=11010693->11008644 fast=11010598->11008644 block=11010690->0 reason="unknown ancestor"
WARN [09-10|19:52:12.410] Synchronisation failed, dropping peer    peer=7bd8a743fb976875d4bd0430de8f3c5cf415758db0dcee463697c6580ba28736 err="retrieved hash chain is invalid: unknown ancestor"
WARN [09-10|19:52:14.253] Rewinding blockchain                     target=10,920,274
ERROR[09-10|19:52:18.697] Snapshot extension registration failed   peer=aa1d27f0 err="peer connected on snap without compatible eth support"
ERROR[09-10|19:52:21.247] Snapshot extension registration failed   peer=90896456 err="peer connected on snap without compatible eth support"
INFO [09-10|19:52:23.424] Generating state snapshot                root=be77de..5c493a at=000003..dee3ce accounts=6   slots=0 storage=388.00B elapsed=1m15.378s   eta=106692h59m28.394s
INFO [09-10|19:52:31.435] Generating state snapshot                root=be77de..5c493a in=000393..2778a9 at=ac689f..1f4d80 accounts=1866 slots=6794 storage=639.69KiB elapsed=1m23.389s   eta=424h18m49.322s
INFO [09-10|19:52:39.437] Generating state snapshot                root=be77de..5c493a at=000b11..3ba175 accounts=5797 slots=12887 storage=1.31MiB   elapsed=1m31.391s   eta=150h16m28.83s
WARN [09-10|19:52:39.920] Checkpoint challenge timed out, dropping id=d9fc0b76ace2534f conn=inbound addr=88.198.26.100:37446             type=erigon/v2021.09.2-al...
ERROR[09-10|19:52:41.698] Snapshot extension registration failed   peer=70d956b8 err="peer connected on snap without compatible eth support"
INFO [09-10|19:52:43.592] Writing clean trie cache to disk         path=/mnt/data/.ethereum/geth/triecache threads=1
INFO [09-10|19:52:43.852] Regenerated local transaction journal    transactions=9    accounts=5
INFO [09-10|19:52:45.261] Persisted the clean trie cache           path=/mnt/data/.ethereum/geth/triecache elapsed=1.669s
INFO [09-10|19:52:47.437] Generating state snapshot                root=be77de..5c493a at=001009..6fd975 accounts=8394 slots=19868 storage=1.97MiB   elapsed=1m39.391s   eta=112h47m24.806s
INFO [09-10|19:52:55.437] Generating state snapshot                root=be77de..5c493a at=001783..6641a1 accounts=12275 slots=31399 storage=3.03MiB   elapsed=1m47.392s   eta=83h6m53.369s
INFO [09-10|19:53:03.437] Generating state snapshot                root=be77de..5c493a at=001faf..f85894 accounts=16581 slots=36315 storage=3.65MiB   elapsed=1m55.392s   eta=66h15m43.676s
ERROR[09-10|19:53:06.833] Snapshot extension registration failed   peer=aa5a2d5b err="peer connected on snap without compatible eth support"
INFO [09-10|19:53:11.440] Generating state snapshot                root=be77de..5c493a at=0025d5..9cabc6 accounts=19678 slots=41897 storage=4.26MiB   elapsed=2m3.394s    eta=59h20m14.473s
ERROR[09-10|19:53:13.398] Snapshot extension registration failed   peer=4e5d1611 err="peer connected on snap without compatible eth support"
INFO [09-10|19:53:19.441] Generating state snapshot                root=be77de..5c493a in=002818..8be351 at=6f8c10..d88557 accounts=20851 slots=48890 storage=4.80MiB   elapsed=2m11.395s   eta=59h37m20.505s
WARN [09-10|19:53:22.429] Checkpoint challenge timed out, dropping id=d9fc0b76ace2534f conn=inbound addr=88.198.26.100:37470             type=erigon/v2021.09.2-al...
INFO [09-10|19:53:25.481] Loaded most recent local header          number=10,920,274 hash=fd6520..638532 td=34,663,109,555,094,082 age=2w5h20m
INFO [09-10|19:53:25.481] Loaded most recent local full block      number=0          hash=419410..ca4a2d td=1,048,576              age=52y5mo1w
INFO [09-10|19:53:25.481] Loaded most recent local fast block      number=10,920,274 hash=fd6520..638532 td=34,663,109,555,094,082 age=2w5h20m
INFO [09-10|19:53:25.481] Loaded last fast-sync pivot marker       number=11,010,749
INFO [09-10|19:53:26.479] Imported new block headers               count=960  elapsed=162.016ms   number=10,921,233 hash=5e8772..13ca3f age=2w45m15s
INFO [09-10|19:53:26.605] Imported new block headers               count=1728 elapsed=74.522ms    number=10,922,961 hash=883e8c..41e152 age=1w6d17h
INFO [09-10|19:53:26.707] Imported new block headers               count=2048 elapsed=83.657ms    number=10,925,009 hash=4a3a8f..afa348 age=1w6d10h
INFO [09-10|19:53:26.841] Imported new block headers               count=2048 elapsed=125.707ms   number=10,927,057 hash=308dd6..7b51ac age=1w6d1h
INFO [09-10|19:53:26.935] Imported new block headers               count=2048 elapsed=86.299ms    number=10,929,105 hash=8f0d3c..d130be age=1w5d18h
INFO [09-10|19:53:27.020] Imported new block headers               count=2048 elapsed=74.401ms    number=10,931,153 hash=2bad64..099d2a age=1w5d13h
INFO [09-10|19:53:27.103] Imported new block headers               count=2048 elapsed=72.798ms    number=10,933,201 hash=544aa6..f96b71 age=1w5d2h
INFO [09-10|19:53:27.199] Imported new block headers               count=2048 elapsed=73.580ms    number=10,935,249 hash=f5aea3..44f259 age=1w4d17h
INFO [09-10|19:53:27.282] Imported new block headers               count=2048 elapsed=73.897ms    number=10,937,297 hash=369b1f..290a40 age=1w4d11h
INFO [09-10|19:53:27.441] Generating state snapshot                root=be77de..5c493a at=0028ac..8ffe1f accounts=21144 slots=57392 storage=5.38MiB   elapsed=2m19.395s   eta=62h20m52.753s
INFO [09-10|19:53:27.571] Imported new block headers               count=2048 elapsed=279.578ms   number=10,939,345 hash=ad41e7..ae69cb age=1w4d3h
...
INFO [09-10|19:53:30.544] Imported new block headers               count=384  elapsed=25.543ms    number=10,946,961 hash=e74d35..63fbb8 age=1w2d19h
INFO [09-10|19:53:31.934] Imported new state entries               count=387  elapsed="133.38µs"  processed=243,888,946 pending=2832  trieretry=1   coderetry=0 duplicate=129 unexpected=38444
INFO [09-10|19:53:32.251] Downloader queue stats                   receiptTasks=22088 blockTasks=24640 itemSize=21.50KiB throttle=8192
INFO [09-10|19:53:32.454] Imported new block headers               count=2048 elapsed=94.651ms    number=10,949,009 hash=9cc9c1..1ed19b age=1w2d14h
...
INFO [09-10|19:53:33.688] Imported new block receipts              count=514  elapsed=352.925ms   number=10,923,732 hash=18605d..557c18 age=1w6d14h  size=5.10MiB
ERROR[09-10|19:53:33.893] Snapshot extension registration failed   peer=557280d9 err="peer connected on snap without compatible eth support"
INFO [09-10|19:53:34.573] Imported new block receipts              count=385  elapsed=41.408ms    number=10,924,117 hash=7e677c..67846b age=1w6d13h  size=3.15MiB
INFO [09-10|19:53:34.773] Imported new state entries               count=385  elapsed="119.495µs" processed=243,889,331 pending=3286  trieretry=1   coderetry=0 duplicate=129 unexpected=38444
INFO [09-10|19:53:35.396] Imported new block receipts              count=2048 elapsed=306.976ms   number=10,926,165 hash=96ac9c..ad5cf5 age=1w6d6h   size=18.18MiB
INFO [09-10|19:53:35.442] Generating state snapshot                root=be77de..5c493a in=002dfd..4efc6a at=3770c3..74e896 accounts=23916 slots=63524 storage=6.00MiB   elapsed=2m27.396s   eta=58h18m16.51s
INFO [09-10|19:53:35.485] Generating ethash verification cache     epoch=365 percentage=92 elapsed=3.002s
INFO [09-10|19:53:35.725] Imported new block receipts              count=1113 elapsed=316.680ms   number=10,927,278 hash=085004..73a6db age=1w6d41m  size=17.53MiB
INFO [09-10|19:53:35.743] Generated ethash verification cache      epoch=365 elapsed=3.259s
INFO [09-10|19:53:35.962] Imported new block headers               count=2048 elapsed=3.491s      number=10,951,057 hash=9a0f7d..837dac age=1w2d7h
...
INFO [09-10|19:53:43.078] Imported new block headers               count=2048 elapsed=102.928ms   number=10,988,049 hash=a64087..52b62c age=4d50m5s
INFO [09-10|19:53:43.188] Imported new block receipts              count=2048 elapsed=651.073ms   number=10,946,454 hash=dcddf7..5c90a0 age=1w2d20h  size=29.32MiB
INFO [09-10|19:53:43.442] Generating state snapshot                root=be77de..5c493a in=002dfd..4efc6a at=d2ca82..103655 accounts=23916 slots=70692 storage=6.47MiB   elapsed=2m35.396s   eta=61h28m8.682s
INFO [09-10|19:53:43.546] Imported new block receipts              count=2048 elapsed=336.078ms   number=10,948,502 hash=084d7e..e5017c age=1w2d14h  size=18.60MiB
...
INFO [09-10|19:53:47.615] Imported new block receipts              count=2048 elapsed=352.749ms   number=10,959,619 hash=034132..0b081f age=1w1d2h   size=19.91MiB
ERROR[09-10|19:53:47.632] Snapshot extension registration failed   peer=5959b667 err="peer connected on snap without compatible eth support"
INFO [09-10|19:53:47.904] Imported new block receipts              count=2048 elapsed=275.166ms   number=10,961,667 hash=d0c277..440a57 age=1w19h53m size=16.69MiB
...
INFO [09-10|19:53:51.248] Imported new block receipts              count=2048 elapsed=279.183ms   number=10,969,247 hash=1619b5..24bc4a age=6d22h6m  size=22.40MiB
INFO [09-10|19:53:51.442] Generating state snapshot                root=be77de..5c493a at=0032fc..52ceb1 accounts=26497 slots=75619 storage=6.98MiB   elapsed=2m43.397s   eta=58h17m49.18s
...
...
...
WARN [09-10|19:55:31.075] Served eth_call                          conn=10.0.12.53:37966 reqid=64865 t="198.099µs" err="missing trie node 38b975937681f72dfd233efb12e959d7a9f80a4cb86b9de21b3eb1615a6472b5 (path )"
...
INFO [09-10|19:55:48.020] Imported new state entries               count=246  elapsed="906.366µs" processed=243,914,706 pending=29531 trieretry=0   coderetry=0 duplicate=129 unexpected=38444
INFO [09-10|19:55:50.147] Imported new state entries               count=384  elapsed=151.127ms   processed=243,915,090 pending=29734 trieretry=1   coderetry=0 duplicate=129 unexpected=38444
INFO [09-10|19:55:51.874] Generating state snapshot                root=be77de..5c493a in=005c97..d7bc8d at=28a664..0aabc0 accounts=48034 slots=160,912 storage=14.11MiB  elapsed=4m43.828s   eta=55h43m24.76s
INFO [09-10|19:55:53.003] Imported new state entries               count=768  elapsed=1.476ms     processed=243,915,858 pending=30870 trieretry=1   coderetry=0 duplicate=129 unexpected=38444
INFO [09-10|19:55:55.817] Imported new state entries               count=499  elapsed="718.988µs" processed=243,916,357 pending=31366 trieretry=0   coderetry=0 duplicate=129 unexpected=38444
ERROR[09-10|19:55:56.125] Snapshot extension registration failed   peer=f0534649 err="peer connected on snap without compatible eth support"
INFO [09-10|19:55:56.813] Imported new block headers               count=2    elapsed=117.706ms   number=11,010,820 hash=da2643..b14afe age=1m22s
INFO [09-10|19:55:57.644] Downloader queue stats                   receiptTasks=0     blockTasks=0     itemSize=18.70KiB throttle=8192
INFO [09-10|19:55:58.907] Imported new state entries               count=563  elapsed=114.569ms   processed=243,916,920 pending=31858 trieretry=2   coderetry=0 duplicate=129 unexpected=38444
...
INFO [09-10|20:02:27.178] Imported new block headers               count=1    elapsed=4.983ms     number=11,010,831 hash=269f52..3ddccc age=3m11s
...

...
INFO [09-10|20:19:09.472] Imported new block headers               count=1    elapsed=4.971ms     number=11,010,875 hash=f5ddd0..b0fb3b age=1m31s
INFO [09-10|20:19:09.775] Downloader queue stats                   receiptTasks=0     blockTasks=0     itemSize=15.69KiB throttle=8192
WARN [09-10|20:19:09.775] Pivot became stale, moving               old=11,010,749 new=11,010,813
INFO [09-10|20:19:09.790] Imported new block receipts              count=64   elapsed=14.427ms    number=11,010,812 hash=dc2fbd..938272 age=28m26s    size=593.57KiB
INFO [09-10|20:19:10.222] Imported new state entries               count=385  elapsed=2.446ms     processed=244,033,628 pending=23028 trieretry=0   coderetry=0 duplicate=129 unexpected=38444
INFO [09-10|20:19:10.357] Imported new state entries               count=263  elapsed="2.068µs"   processed=244,033,891 pending=3337  trieretry=0   coderetry=0 duplicate=129 unexpected=38444
INFO [09-10|20:19:10.519] Imported new state entries               count=384  elapsed="86.327µs"  processed=244,034,275 pending=4071  trieretry=0   coderetry=0 duplicate=129 unexpected=38444
INFO [09-10|20:19:10.691] Imported new state entries               count=384  elapsed="2.309µs"   processed=244,034,659 pending=7042  trieretry=0   coderetry=0 duplicate=129 unexpected=38444
INFO [09-10|20:19:10.851] Imported new state entries               count=384  elapsed="1.836µs"   processed=244,035,043 pending=9220  trieretry=0   coderetry=0 duplicate=129 unexpected=38444
INFO [09-10|20:19:11.277] Imported new state entries               count=384  elapsed="1.827µs"   processed=244,035,427 pending=12264 trieretry=0   coderetry=0 duplicate=129 unexpected=38444
INFO [09-10|20:19:12.643] Imported new block headers               count=1    elapsed=4.891ms     number=11,010,876 hash=78b719..53cccd age=1m12s
INFO [09-10|20:19:12.683] Generating state snapshot                root=be77de..5c493a in=00a495..2a0fcd at=249cc7..42c791 accounts=85198 slots=440,650 storage=35.99MiB  elapsed=28m4.638s   eta=185h52m2.2s
INFO [09-10|20:19:15.815] Imported new block headers               count=1    elapsed=5.034ms     number=11,010,877 hash=f0495a..a42b1d
INFO [09-10|20:19:15.816] Imported new state entries               count=384  elapsed="163.761µs" processed=244,035,811 pending=12662 trieretry=0   coderetry=0 duplicate=129 unexpected=38444
INFO [09-10|20:21:44.783] Generating state snapshot                root=be77de..5c493a in=00a495..2a0fcd at=2b41fc..55c021 accounts=85198 slots=467,263 storage=37.75MiB  elapsed=30m36.738s  eta=202h38m54.838s

[holiman]

One thing to note is this: WARN [09-10|19:55:31.075] Served eth_call conn=10.0.12.53:37966 reqid=64865 t="198.099µs" err="missing trie node 38b975937681f72dfd233efb12e959d7a9f80a4cb86b9de21b3eb1615a6472b5 (path )". During an RPC request, there was missing state.

[verheesj]

One thing to note is this: WARN [09-10|19:55:31.075] Served eth_call conn=10.0.12.53:37966 reqid=64865 t="198.099µs" err="missing trie node 38b975937681f72dfd233efb12e959d7a9f80a4cb86b9de21b3eb1615a6472b5 (path )". During an RPC request, there was missing state.

Q: Is the sync in question a fresh sync without any data pre-existing (hint: I am not referring to it being restarted)

[holiman]

Another thing to note:
Before and after the Rewinding blockchain, we have Resuming state snapshot generation root=be77de. I wonder if somehow rewinding the blockchain does not properly interact with the snapshot generator.

IIRC, that one is started once we hit the first pivot. But if we have to roll back, we probably need to terminate + restart the generator. Not sure