Clean sync Goerli broken(?) post merge on 1.10.21 and 1.10.23

[ulope]

System information

Geth version: v1.10.21 / v1.10.23
OS & Version: Linux

Expected behaviour

A fresh sync from scratch of Goerli to work

Actual behaviour

Does not work.

• Geth 1.10.21:
  • Snap sync completes, afterwards State heal seems to continue indefinitely (aborted after 4 days)
  • Last state heal log before abort:
    INFO [09-05|14:37:35.138] State heal in progress accounts=9@647.00B slots=0@0.00B codes=0@0.00B nodes=16,319,436@8.09GiB pending=4369
  • Many, many Unexpected trienode heal packet messages (~70% of all log lines)
  • Pivot is only changed 12 times. Last one:
    WARN [09-02|16:42:58.589] Pivot seemingly stale, moving old=7,516,913 new=7,516,977
  • Suspiciously new blocks are no longer imported:
    INFO [09-05|14:37:34.872] Imported new block headers count=0 elapsed=15.422ms number=7,382,818 hash=aa32c4..48c7cc age=3w4d12h ignored=178
    • Probably because of:
      Local chain is post-merge, waiting for beacon client sync switch-over...
    • However Prsym claims geth is not synced:
      level=error msg="Unable to process past deposit contract logs, perhaps your execution client is not fully synced" error="no contract code at given address" prefix=powchain
• Geth 1.10.23:
  • Syncing never even starts
    No sync progress is reported, apparently every peer is dropped because of:
    WARN [09-06|09:25:04.945] Snapshot extension registration failed peer=6de3885d err="peer connected on snap without compatible eth support"

Steps to reproduce the behaviour

Compose file used:

version: "3"

services:
  geth:
    image: ethereum/client-go:v1.10.23
    restart: always
    network_mode: host
    stop_grace_period: 1m
    volumes:
      - /data/geth:/data
      - jwt:/jwt
    command: >
      --goerli
      --datadir=/data
      --http
      --http.api eth,net,web3,txpool
      --http.addr 0.0.0.0
      --http.corsdomain '*'
      --ws
      --ws.api eth,web3,net
      --authrpc.jwtsecret /jwt/jwtsecret
      --authrpc.vhosts '*'
      --metrics
      --metrics.addr=0.0.0.0
      --metrics.port=9191

  prysm:
    image: gcr.io/prysmaticlabs/prysm/beacon-chain:stable
    restart: always
    network_mode: host
    volumes:
      - /data/prysm:/data
      - jwt:/jwt
    command: >
      --goerli
      --datadir=/data
      --rpc-host=0.0.0.0
      --http-web3provider=http://localhost:8551
      --jwt-secret=/jwt/jwtsecret
      --accept-terms-of-use

volumes:
  jwt:

[fjl]

Syncing never even starts
No sync progress is reported

Can you provide more information that leads you to this conclusion? It can take a while to start sometimes, just leave it running for a bit.

[rjl493456442]

We have a couple of PRs for fixing/improving snap sync on master recently. Maybe you can try to use master once we merge this PR #25694

[ulope]

Syncing never even starts
No sync progress is reported

Can you provide more information that leads you to this conclusion? It can take a while to start sometimes, just leave it running for a bit.

Are 20 hours enough? ;)

These are the top non unique log messages by count:

1776 Snapshot extension registration failed
 236 Beacon client online, but never received consensus updates. Please ensure your beacon client is operational to follow the chain!
  73 Dropping unsynced node during sync
  28 Looking for peers
  20 Regenerated local transaction journal
  19 Writing clean trie cache to disk
  19 Persisted the clean trie cache

I also re-tried this locally before submitting the issue (the above setup is running on a droplet).

• 1.10.21 starts syncing within minutes.
• 1.10.23 has been running for 15+ minutes and shows the same behaviour as on the droplet (i.e. no sync and lots of Snapshot extension registration failed)

[ulope]

Update: It's now been almost 40h and still no sync. Going to stop it now and try with latest master.

[holiman]

I'm wondering if your node actually manages to find any peers -- is your firewall sufficiently open, so bidirectional communication can occur over the relevant ports ?

[ulope]

Next update:
Using commit 5ddedd2 (which includes #25694, @rjl493456442) I'm seeing the same behaviour - No sync, Snapshot extension registration failed.
Left it running for 30min.

@holiman As I wrote in the initial report 1.10.21 was able to sync (but then got stuck in the heal stage).
Just to verify doubly I switched back to the 1.10.21 docker image and sync started within ~30 seconds (but I'll just assume it will run into the healing issue again as it did so the last two attempts).
Edit: Also it definitely finds peers. Here's the complete log of the run: https://gist.github.com/ulope/776e87c5bb1e3fcd893d1a512a2f6f48

Also as I wrote yesterday, I can replicate the non-syncing behaviour locally by just running geth --goerli (>=1.10.23) with an empty datadir

[holiman]

@ulope that log say

Beacon client online, but never received consensus updates. Please ensure your beacon client is operational to follow the chain!

Goerli is post-merge, it needs the beacon client to tell it what the head is, and then it will sync to that.

[ulope]

@holiman Unless I'm very much mistaken (and the release notes are wrong) 1.10.21 is just as aware of the goerli merge as later versions. However it does start snap syncing immediately as mentioned.

Also with both versions Prysm seems to wait for geth to be synced to some degree because it continually logs:

level=error msg="Unable to process past deposit contract logs, perhaps your execution client is not fully synced" error="no contract code at given address" prefix=powchain

(I also tried other beacon clients before, but didn't record their output unfortunately. Can check again if that's helpful.)

So either I'm missing something else or this looks like a hen/egg problem.

[holiman]

They are both aware, but not quite "as awaare" :) The more recent version will spit out something like

INFO [09-07|11:25:00.972] Merge configured: 
INFO [09-07|11:25:00.972]  - Hard-fork specification:    https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/paris.md 
INFO [09-07|11:25:00.972]  - Network known to be merged: true 

The difference being that this flag is set for goerli:

	// TerminalTotalDifficultyPassed is a flag specifying that the network already
	// passed the terminal total difficulty. Its purpose is to disable legacy sync
	// even without having seen the TTD locally (safer long term).
	TerminalTotalDifficultyPassed bool `json:"terminalTotalDifficultyPassed,omitempty"`

See #24538 for more info:

The rationale is that once a network transitions into PoS mode, sync is directed by the beacon client. If a new Geth instance is started may years down the line however, it will not know of the transition event, so will still attempt to do a PoW based legacy sync. The legacy sync will need to "fail" when TTD is reached and sync swapped from legacy algo to beacon algo.

[Snehapati11]

We are closely following this issue as we are also receiving the same message “Beacon client online, but never received consensus updates. Please ensure your beacon client is operational to follow the chain!”. Our current setup is GETH 1.10.23 and prysm alpine image. We are connecting to network goerli prater.

[fjl]

Maybe something is broken in Prysm <-> Geth in TTD-passed mode? AFAIK geth needs a signal from the CL to start syncing. Could be that this signal doesn't come?