Fatal: Failed to register the Ethereum service: waiting for sync

[arcivanov]

System information

Geth version: 1.13.7
CL client & version: e.g. lighthouse
OS & Version: Linux
Commit hash : (if develop)

Expected behaviour

The node starts normally

Actual behaviour

INFO [12-21|06:58:58.508] Starting Geth on Ethereum mainnet...
INFO [12-21|06:58:58.509] Bumping default cache on mainnet         provided=1024 updated=4096
INFO [12-21|06:58:58.513] Maximum peer count                       ETH=50 total=50
INFO [12-21|06:58:58.515] Smartcard socket not found, disabling    err=\"stat /run/pcscd/pcscd.comm: no such file or directory\"
WARN [12-21|06:58:58.515] Option nousb is deprecated and USB is deactivated by default. Use --usb to enable
WARN [12-21|06:58:58.521] Snap sync requested, enabling --snapshot
INFO [12-21|06:58:58.521] Global gas cap disabled
INFO [12-21|06:58:58.522] Initializing the KZG library             backend=gokzg
INFO [12-21|06:58:58.622] Allocated trie memory caches             clean=614.00MiB dirty=1024.00MiB
INFO [12-21|06:58:58.784] Using pebble as the backing database
INFO [12-21|06:58:58.784] Allocated cache and file handles         database=/root/.ethereum/geth/chaindata cache=2.00GiB handles=524,288
INFO [12-21|06:59:00.972] Opened ancient database                  database=/root/.ethereum/geth/chaindata/ancient/chain readonly=false
INFO [12-21|06:59:00.976] State scheme set by user                 scheme=path
INFO [12-21|06:59:01.010] Initialising Ethereum protocol           network=1 dbversion=8
WARN [12-21|06:59:01.010] Sanitizing invalid node buffer size      provided=1024.00MiB updated=256.00MiB
ERROR[12-21|06:59:01.011] Zero trie root hash!
INFO [12-21|06:59:01.013] Opened ancient database                  database=/root/.ethereum/geth/chaindata/ancient/state readonly=false
INFO [12-21|06:59:01.016] Disabled trie database due to state sync
WARN [12-21|06:59:01.016] Path-based state scheme is an experimental feature
Fatal: Failed to register the Ethereum service: waiting for sync
Fatal: Failed to register the Ethereum service: waiting for sync

Steps to reproduce the behaviour

After upgrading to Path-based state scheme with (geth removedb and keeping ancient) the node was restarted gracefully before finishing syncing.
The node now does not start at all per above. This was an upgrade from 1.12.0 to 1.13.7.

[arcivanov]

We have a Görli testnet with identical results also on the same version with same upgrade path.

[namiloh]

What command parameters are used to start geth?

[arcivanov]

--state.scheme=path --http --http.addr=0.0.0.0 --http.api=web3ethnet --http.vhosts=* --nousb --snapshot=false --rpc.gascap=0 --authrpc.addr=127.0.0.1 --authrpc.port=8551 --authrpc.vhosts=127.0.0.1 --authrpc.jwtsecret=/root/token/token

[arcivanov]

For Gorli we have the same + --goerli

[arcivanov]

This is the shutdown sequence after which mainnet node stopped functioning:

INFO [12-21|06:31:49.144] Forkchoice requested sync to new head    number=18,832,477 hash=b425e0..8fd05e finalized=18,832,392
INFO [12-21|06:31:49.932] Syncing: state download in progress      synced=92.31%  state=254.32GiB  accounts=215,628,158@42.82GiB slots=987,412,748@204.60GiB codes=1,063,696@6.89GiB  eta=32m49.446s
INFO [12-21|06:31:54.219] Syncing: chain download in progress      synced=100.00% chain=633.09GiB headers=18,832,477@8.64GiB bodies=18,832,407@454.54GiB receipts=18,832,407@169.91GiB eta=18.542s
INFO [12-21|06:31:57.937] Syncing: state download in progress      synced=92.36%  state=254.41GiB  accounts=215,747,107@42.85GiB slots=987,706,812@204.66GiB codes=1,064,357@6.90GiB  eta=32m35.755s
INFO [12-21|06:32:00.719] Forkchoice requested sync to new head    number=18,832,478 hash=697d43..334dc5 finalized=18,832,392
INFO [12-21|06:32:02.276] Syncing: chain download in progress      synced=100.00% chain=633.09GiB headers=18,832,477@8.64GiB bodies=18,832,407@454.54GiB receipts=18,832,407@169.91GiB eta=18.813s
INFO [12-21|06:32:06.014] Syncing: state download in progress      synced=92.39%  state=254.50GiB  accounts=215,812,057@42.86GiB slots=988,084,425@204.74GiB codes=1,064,692@6.90GiB  eta=32m29.444s
INFO [12-21|06:32:10.346] Syncing: chain download in progress      synced=100.00% chain=633.09GiB headers=18,832,478@8.64GiB bodies=18,832,407@454.54GiB receipts=18,832,407@169.91GiB eta=18.820s
INFO [12-21|06:32:13.422] Forkchoice requested sync to new head    number=18,832,479 hash=7bd3a9..a29d2f finalized=18,832,392
INFO [12-21|06:32:14.190] Syncing: state download in progress      synced=92.41%  state=254.55GiB  accounts=215,866,240@42.87GiB slots=988,241,372@204.78GiB codes=1,064,788@6.90GiB  eta=32m19.120s
INFO [12-21|06:32:18.415] Syncing: chain download in progress      synced=100.00% chain=633.09GiB headers=18,832,479@8.64GiB bodies=18,832,407@454.54GiB receipts=18,832,407@169.91GiB eta=19.091s
INFO [12-21|06:32:22.213] Syncing: state download in progress      synced=92.47%  state=254.62GiB  accounts=215,996,134@42.90GiB slots=988,461,486@204.82GiB codes=1,065,434@6.90GiB  eta=32m2.867s
INFO [12-21|06:32:25.259] Forkchoice requested sync to new head    number=18,832,480 hash=d7cd03..467dcf finalized=18,832,392
INFO [12-21|06:32:26.035] Got interrupt, shutting down...
INFO [12-21|06:32:26.035] HTTP server stopped                      endpoint=[::]:8545
INFO [12-21|06:32:26.035] HTTP server stopped                      endpoint=127.0.0.1:8551
INFO [12-21|06:32:26.035] IPC endpoint closed                      url=/root/.ethereum/geth.ipc
INFO [12-21|06:32:26.606] Syncing: state download in progress      synced=92.50%  state=254.67GiB  accounts=216,061,097@42.91GiB slots=988,607,174@204.85GiB codes=1,065,769@6.91GiB  eta=31m54.993s
ERROR[12-21|06:32:26.615] Beacon backfilling failed                err=\"syncing canceled (requested)\"
INFO [12-21|06:32:26.675] Ethereum protocol stopped
INFO [12-21|06:32:26.675] Transaction pool stopped
ERROR[12-21|06:32:26.676] Failed to journal state snapshot         err=\"snapshot [0xd7f8974fb5ac78d9ac099b9ad5018bedc2ce0a72dad1827a1709da30580f0544] missing\"
INFO [12-21|06:32:26.676] Persisting dirty state to disk           root=d7f897..0f0544 layers=0
ERROR[12-21|06:32:26.676] Zero trie root hash!
INFO [12-21|06:32:26.676] Failed to journal in-memory trie nodes   err=\"layer stale\"
INFO [12-21|06:32:26.676] Blockchain stopped

[holiman]

So, did you first start syncing, abort mid-sync, and now it exits as you try to start it again?

[arcivanov]

Correct.

[holiman]

One source of problems may be the use of --snapshot=false. But it should still work.

If I run the same command as you, I get identical lines, up to

INFO [12-21|08:29:20.313] Initialising Ethereum protocol           network=1 dbversion=8
WARN [12-21|08:29:20.313] Sanitizing invalid node buffer size      provided=1024.00MiB updated=256.00MiB
INFO [12-21|08:29:20.622] Opened ancient database                  database=/home/user/tmp/deleteme1/geth/chaindata/ancient/state readonly=false
WARN [12-21|08:29:20.622] Path-based state scheme is an experimental feature

You have

INFO [12-21|06:59:01.016] Disabled trie database due to state sync
WARN [12-21|06:59:01.016] Path-based state scheme is an experimental feature

[arcivanov]

Let me try to enable it with Gorli and see if the node recovers.

[arcivanov]

No difference whether --snapshot=false is present or not - still failure with waiting for sync.

[arcivanov]

This is our failing Goerli node

INFO [12-21|07:38:39.026] \"Starting Geth on Görli testnet...\"
INFO [12-21|07:38:39.030] Maximum peer count                       ETH=50 total=50
INFO [12-21|07:38:39.033] Smartcard socket not found, disabling    err=\"stat /run/pcscd/pcscd.comm: no such file or directory\"
WARN [12-21|07:38:39.033] Option nousb is deprecated and USB is deactivated by default. Use --usb to enable
INFO [12-21|07:38:39.038] Global gas cap disabled
INFO [12-21|07:38:39.039] Initializing the KZG library             backend=gokzg
INFO [12-21|07:38:39.184] Allocated trie memory caches             clean=154.00MiB dirty=256.00MiB
INFO [12-21|07:38:39.248] Using pebble as the backing database
INFO [12-21|07:38:39.248] Allocated cache and file handles         database=/root/geth/chaindata cache=512.00MiB handles=524,288
INFO [12-21|07:38:40.082] Opened ancient database                  database=/root/geth/chaindata/ancient/chain readonly=false
INFO [12-21|07:38:40.126] State scheme set by user                 scheme=path
INFO [12-21|07:38:40.129] Initialising Ethereum protocol           network=5 dbversion=8
ERROR[12-21|07:38:40.133] Zero trie root hash!
INFO [12-21|07:38:40.133] Failed to load journal, discard it       err=\"unmatched journal want 5d6cded585e73c4e322c30c2f782a336316f17dd85a4863b9d838d2d4b8b3008 got 56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421\"
INFO [12-21|07:38:40.145] Opened ancient database                  database=/root/geth/chaindata/ancient/state readonly=false
INFO [12-21|07:38:40.149] Disabled trie database due to state sync
WARN [12-21|07:38:40.149] Path-based state scheme is an experimental feature
Fatal: Failed to register the Ethereum service: waiting for sync
Fatal: Failed to register the Ethereum service: waiting for sync

[holiman]

For the goerli node, this seems to be the root problem:

INFO [12-21|07:38:40.133] Failed to load journal, discard it       err=\"unmatched journal want 5d6cded585e73c4e322c30c2f782a336316f17dd85a4863b9d838d2d4b8b3008 got 56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421\"

---

If you are not in a hurry (not a staker), then it would be interesting it keep the machine/database around for a little while, while we investigate.

But if you want get this sorted out as soon as possible, I would recommend doing another geth removedb and remove the database (keep ancients), and re-sync. This time, do not use the --snapshot=false flag.

[arcivanov]

@holiman

I can probably leave the goerli node around in its failing state for about a week. The prod needs to resync as we only have one reserve node operating currently.

Are you sure I should keep the ancients and it's not going to be a problem? I kept them last time as well and ended up with this.

[holiman]

Are you sure I should keep the ancients and it's not going to be a problem? I kept them last time as well and ended up with this.

We've not had any errors that were due to keeping ancients, and it speeds up sync quite a lot, so I'd keep them, yes. We resync our benchmark machines quite a lot, keeping the ancients, so it gets a lot of testing. I think the problem lies elsewhere