search

status-im / nimbus-eth2

Nim implementation of the Ethereum Beacon Chain
https://nimbus.guide
Other
543 stars 233 forks source link

'Eth1 chain not synced' after upgrade from nimbus v1.4.1 to v1.5.0. #2971

Closed zven77 closed 3 years ago

zven77 commented 3 years ago

Describe the bug I just updated from nimbus v1.4.1 to v1.5.0. Geth 1.0.9 is fully synced. But after the update nimbus cannot sync with the Eth1 chain anymore. Notice how depositsProcessed=247414 before the update differs from ourDepositsCount=247374 after the update to 1.5.0.

To Reproduce Steps to reproduce the behavior:

  1. Platform details (OS, architecture): Ubuntu 21.04

  2. Branch/commit used: '...'

  3. Commands being executed: ExecStart=/bin/bash -c '/usr/local/bin/nimbus_beacon_node --network=mainnet --data-dir=/var/lib/nimbus --web3-url=ws://127.0.0.1:8546 --nat=extip:${ClientIP} --max-peers=180 --graffiti="graffiti" --log-level=INFO'

  4. Relevant log lines:

After the update after 19:04:32 only 'Eth1 chain not synced' appeared:

[…]
Oct  8 18:53:02 eth bash[1213]: NOT 2021-10-08 18:53:02.674+02:00 Eth1 sync progress                         topics="eth1" tid=1213 file=eth1_monitor.nim:966 blockNumber=13377314 depositsProcessed=247398
Oct  8 19:04:32 eth bash[1213]: NOT 2021-10-08 19:04:32.501+02:00 Eth1 sync progress                         topics="eth1" tid=1213 file=eth1_monitor.nim:966 blockNumber=13377369 depositsProcessed=247414
Oct  8 20:11:49 eth bash[15833]: INF 2021-10-08 20:11:49.254+02:00 Starting Eth1 deposit contract monitoring  topics="eth1" tid=15833 file=eth1_monitor.nim:1045 contract=0x00000000219ab540356cbb839cbe05303d7705fa url=ws://127.0.0.1:8546
Oct  8 20:11:51 eth bash[15833]: INF 2021-10-08 20:11:51.154+02:00 Waiting for new Eth1 block headers         topics="eth1" tid=15833 file=eth1_monitor.nim:545
Oct  8 20:24:31 eth bash[15833]: WRN 2021-10-08 20:24:31.005+02:00 Eth1 chain not synced                      topics="eth1" tid=15833 file=eth1_monitor.nim:664 ourDepositsCount=247374 targetDepositsCount=247375
Oct  8 20:30:55 eth bash[15833]: WRN 2021-10-08 20:30:55.010+02:00 Eth1 chain not synced                      topics="eth1" tid=15833 file=eth1_monitor.nim:664 ourDepositsCount=247374 targetDepositsCount=247375
[…]

After some time the ‚Block signature verification failed‘ line appeared….

Oct  8 23:01:11 pn50-eth bash[16188]: INF 2021-10-08 23:01:11.458+02:00 Block signature verification failed        topics="clearance" tid=16188 file=block_clearance.nim:327 blockRoot=24546d2f signature=b6072889 blck="(slot: 2241904, proposer_index: 98730, parent_root: \"0e02ed95\", state_root: \"d62bce3a\", eth1data: (deposit_root: 267737fc04b431a9678ff7ee44001ade0a895a90d51f1f1fd0f6789d82c33b6d, deposit_count: 247396, block_hash: 7f199112d6a31d27a9af348588c029a491d247cb93ae4ee269b77206d7809258), graffiti: \"\", proposer_slashings_len: 0, attester_slashings_len: 0, attestations_len: 128, deposits_len: 0, voluntary_exits_len: 0, sync_committee_participants: -1)"
Oct  8 23:04:31 pn50-eth bash[16188]: WRN 2021-10-08 23:04:31.008+02:00 Eth1 chain not synced                      topics="eth1" tid=16188 file=eth1_monitor.nim:664 ourDepositsCount=247374 targetDepositsCount=247396
Oct  8 23:11:48 pn50-eth bash[17636]: INF 2021-10-08 23:11:48.988+02:00 Starting Eth1 deposit contract monitoring  topics="eth1" tid=17636 file=eth1_monitor.nim:1045 contract=0x00000000219ab540356cbb839cbe05303d7705fa url=ws://127.0.0.1:8546
Oct  8 23:11:50 pn50-eth bash[17636]: INF 2021-10-08 23:11:50.519+02:00 Waiting for new Eth1 block headers         topics="eth1" tid=17636 file=eth1_monitor.nim:545
Oct  8 23:23:43 pn50-eth bash[17636]: WRN 2021-10-08 23:23:43.007+02:00 Eth1 chain not synced                      topics="eth1" tid=17636 file=eth1_monitor.nim:664 ourDepositsCount=247374 targetDepositsCount=247396
Oct  8 23:29:38 pn50-eth bash[17817]: INF 2021-10-08 23:29:38.892+02:00 Starting Eth1 deposit contract monitoring  topics="eth1" tid=17817 file=eth1_monitor.nim:1047 contract=0x00000000219ab540356cbb839cbe05303d7705fa url=ws://127.0.0.1:8546
Oct  8 23:29:38 pn50-eth bash[17817]: INF 2021-10-08 23:29:38.894+02:00 Waiting for new Eth1 block headers         topics="eth1" tid=17817 file=eth1_monitor.nim:544

… I decided to rollback to v1.4.1 and Eth1 sync progress lines appeared instantly after start of v1.4.1:

Oct 8 23:30:02 pn50-eth bash[17817]: NOT 2021-10-08 23:30:02.708+02:00 Eth1 sync progress topics="eth1" tid=17817 file=eth1_monitor.nim:966 blockNumber=13378377 depositsProcessed=247417

Screenshots

Additional context

stefantalpalaru commented 3 years ago

Same problem on my end, with Infura (almost 21 hours of logs here):

grep 'Eth1 chain not synced' /var/log/nimbus-eth2/nimbus-eth2.log | wc -l
195

ourDepositsCount=244964 targetDepositsCount=247396

TennisBowling commented 3 years ago

also getting this here, yet much more infrequently than you.

zven77 commented 3 years ago

also getting this here, yet much more infrequently than you.

do you get 'Eth1 sync progress' lines too after the update? Or always the same status 'ourDepositsCount=xyz targetDepositsCount=xyz ?

stefantalpalaru commented 3 years ago

Bisected to this commit: https://github.com/status-im/nimbus-eth2/commit/66b9f33edd0e9553280aabfb1305f9788d72b7ab

stefantalpalaru commented 3 years ago

Fixed in the "stable" branch and released as 1.5.1. Thanks for reporting and helping debug it!

Fix commit: https://github.com/status-im/nimbus-eth2/commit/dbbdbea7da4fa88b53dfded7f26a49fb91c2f5e9