Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Peering issues with Prysm / Schlesi sync stuck #989

Closed
q9f opened this issue May 7, 2020 · 13 comments
Closed

Peering issues with Prysm / Schlesi sync stuck #989

q9f opened this issue May 7, 2020 · 13 comments

Comments

@q9f
Copy link
Contributor

q9f commented May 7, 2020

nim-beacon-chain devel @ 3ffd0d7

Config:

beacon_node_shared_schlesi \
--log-level="DEBUG" \
--data-dir="/home/user/.opt/status-im/nim-beacon-chain/build/data/shared_schlesi" \
--web3-url="wss://goerli.infura.io/ws/v3/809a18497dd74102b5f37d25aae3c85a" \
--deposit-contract="0xA15554BF93a052669B511ae29EA21f3581677ac5" \
--bootstrap-file="/home/user/.opt/status-im/nim-beacon-chain/build/eth2-testnets/shared/schlesi/bootstrap_nodes.txt" \
--tcp-port=9876 \
--udp-port=9876 \
--state-snapshot="/home/user/.opt/status-im/nim-beacon-chain/build/eth2-testnets/shared/schlesi/genesis.ssz"

The initial sync of my Schlesi beacon node was interrupted and stalled after this:

INF 2020-05-07 14:29:34+02:00 Requesting detected missing blocks         topics="beacnde" tid=4076669 file=beacon_node.nim:471 missingBlocks="@[(root: EF071EDF09F5015B11A5DBFF858DA7A08F4F440D69EFCCE5D15614BC31EA7F1D, historySlots: 70579)]"
DBG 2020-05-07 14:29:34+02:00 Peer (incoming) lost                       topics="networking" tid=4076669 file=eth2_network.nim:637 peer="16Uiu2HAkvLCWwVEfF365ZWXB6siDL1mUpcd1XQ1nSXAHmvM5W7wn @[] @[]"
WRN 2020-05-07 14:29:34+02:00 unable to initiate pubsub                  tid=4076669 file=switch.nim:337 exc="Incomplete data received\nAsync traceback:\nException message: Incomplete data received\nException type:" topic=Switch
DBG 2020-05-07 14:29:34+02:00 Error, while waiting getBlocks response    topics="syncman" tid=4076669 file=sync_manager.nim:242 errMsg="Connection dead on arrival\nAsync traceback:\nException message: Connection dead on arrival\nException type:" peer=16Uiu2HAkvLCWwVEfF365ZWXB6siDL1mUpcd1XQ1nSXAHmvM5W7wn slot=2208 slot_count=32 step=1
DBG 2020-05-07 14:29:34+02:00 Failed to receive blocks on request        topics="syncman" tid=4076669 file=sync_manager.nim:356 peer=16Uiu2HAkvLCWwVEfF365ZWXB6siDL1mUpcd1XQ1nSXAHmvM5W7wn peer_score=4700 request_count=32 request_slot=2208 request_step=1
DBG 2020-05-07 14:29:34+02:00 Synchronization loop got worker finished   topics="syncman" tid=4076669 file=sync_manager.nim:461 local_head_slot=2207 peer=16Uiu2HAkvLCWwVEfF365ZWXB6siDL1mUpcd1XQ1nSXAHmvM5W7wn peer_score=4700 wall_head_slot=72768
DBG 2020-05-07 14:29:34+02:00 Synchronization loop end tick              topics="syncman" tid=4076669 file=sync_manager.nim:479 local_head_slot=2207 waiting_for_new_peer=true wall_head_slot=72768 workers_count=0
DBG 2020-05-07 14:29:34+02:00 Synchronization loop start tick            topics="syncman" tid=4076669 file=sync_manager.nim:387 local_head_slot=2207 queue_last_slot=72768 queue_start_slot=0 queue_status=3 wall_head_slot=72768 workers_count=0
DBG 2020-05-07 14:29:34+02:00 Synchronization loop waiting for new peer  topics="syncman" tid=4076669 file=sync_manager.nim:410 local_head_slot=2207 wall_head_slot=72768 workers_count=0
INF 2020-05-07 14:29:36+02:00 Slot start                                 topics="beacnde" tid=4076669 file=beacon_node.nim:337 beaconTime=872976 cat=scheduling finalizedEpoch=66 finalizedRoot=90d0b84c finalizedSlot=2112 headEpoch=68 headRoot=225c6229 headSlot=2207 lastSlot=72747 pcs=slot_start peers=0 scheduledSlot=72748
INF 2020-05-07 14:29:36+02:00 No head block update                       topics="blkpool" tid=4076669 file=block_pool.nim:872 cat=fork_choice head=225c6229:2207 pcs=fork_choice
NOT 2020-05-07 14:29:36+02:00 Node out of sync, skipping validator duties topics="beacval" tid=4076669 file=validator_duties.nim:363 headSlot=2207 slot=72748
INF 2020-05-07 14:29:36+02:00 Slot end                                   topics="beacnde" tid=4076669 file=beacon_node.nim:442 cat=scheduling finalizedEpoch=66 finalizedRoot=90d0b84c finalizedSlot=2112 headEpoch=68 headRoot=225c6229 headSlot=2207 nextSlot=72749 pcs=slot_start slot=72748
INF 2020-05-07 14:29:38+02:00 Requesting detected missing blocks         topics="beacnde" tid=4076669 file=beacon_node.nim:471 missingBlocks="@[(root: EF071EDF09F5015B11A5DBFF858DA7A08F4F440D69EFCCE5D15614BC31EA7F1D, historySlots: 70579)]"
DBG 2020-05-07 14:29:40+02:00 Failed to connect to peer                  topics="networking" tid=4076669 file=eth2_network.nim:720 err="Unable to connect to peer\nAsync traceback:\nException message: Unable to connect to peer\nException type:" peer=Node[75.172.0.5:12000]
DBG 2020-05-07 14:29:40+02:00 Discovered new peer                        topics="networking" tid=4076669 file=eth2_network.nim:714 peer=Node[5.252.224.98:12000]
DBG 2020-05-07 14:29:40+02:00 Connecting to peer                         topics="networking" tid=4076669 file=eth2_network.nim:682 peer="16Uiu2HAmRiNQUDa3t2RkpL8CatK7SMVtzdoKzGjDonmdzsvJ2AHn @[/ip4/5.252.224.98/tcp/13000] @[]"
WRN 2020-05-07 14:29:40+02:00 no handlers for                            tid=4076669 file=multistream.nim:152 protocol=/prysm/0.0.0/dht topic=Multistream
WRN 2020-05-07 14:29:40+02:00 no handlers for                            tid=4076669 file=multistream.nim:152 protocol=/eth2/beacon_chain/req/goodbye/1/ssz_snappy topic=Multistream
WRN 2020-05-07 14:29:40+02:00 ignored an error                           tid=4076669 file=errors.nim:62 multistream handle="multistream handle" name=LPStreamIncompleteError topic=Multistream
WRN 2020-05-07 14:29:40+02:00 ignored an error                           tid=4076669 file=errors.nim:62 multistream handle="multistream handle" name=LPStreamIncompleteError topic=Multistream

There's a lot going on in that log:

  • pubsub: Incomplete data received
  • getBlocks: Connection dead on arrival
  • sync manager apparently unable to continue sync afterwards
  • node out of sync
  • failed to connect peer (Prysm?)
  • no handlers for: goodbye (Prysm?)

After that it's an endless loop of:

NOT 2020-05-07 14:41:48+02:00 Node out of sync, skipping validator duties topics="beacval" tid=4076669 file=validator_duties.nim:363 headSlot=2527 slot=72809
INF 2020-05-07 14:41:48+02:00 Slot end                                   topics="beacnde" tid=4076669 file=beacon_node.nim:442 cat=scheduling finalizedEpoch=76 finalizedRoot=252d351d finalizedSlot=2432 headEpoch=78 headRoot=f2c65381 headSlot=2527 nextSlot=72810 pcs=slot_start slot=72809
INF 2020-05-07 14:42:00+02:00 Slot start                                 topics="beacnde" tid=4076669 file=beacon_node.nim:337 beaconTime=873720 cat=scheduling finalizedEpoch=76 finalizedRoot=252d351d finalizedSlot=2432 headEpoch=78 headRoot=f2c65381 headSlot=2527 lastSlot=72809 pcs=slot_start peers=0 scheduledSlot=72810
INF 2020-05-07 14:42:00+02:00 No head block update                       topics="blkpool" tid=4076669 file=block_pool.nim:872 cat=fork_choice head=f2c65381:2527 pcs=fork_choice
NOT 2020-05-07 14:42:00+02:00 Node out of sync, skipping validator duties topics="beacval" tid=4076669 file=validator_duties.nim:363 headSlot=2527 slot=72810
INF 2020-05-07 14:42:00+02:00 Slot end                                   topics="beacnde" tid=4076669 file=beacon_node.nim:442 cat=scheduling finalizedEpoch=76 finalizedRoot=252d351d finalizedSlot=2432 headEpoch=78 headRoot=f2c65381 headSlot=2527 nextSlot=72811 pcs=slot_start slot=72810
INF 2020-05-07 14:42:12+02:00 Slot start                                 topics="beacnde" tid=4076669 file=beacon_node.nim:337 beaconTime=873732 cat=scheduling finalizedEpoch=76 finalizedRoot=252d351d finalizedSlot=2432 headEpoch=78 headRoot=f2c65381 headSlot=2527 lastSlot=72810 pcs=slot_start peers=0 scheduledSlot=72811
INF 2020-05-07 14:42:12+02:00 No head block update                       topics="blkpool" tid=4076669 file=block_pool.nim:872 cat=fork_choice head=f2c65381:2527 pcs=fork_choice
NOT 2020-05-07 14:42:12+02:00 Node out of sync, skipping validator duties topics="beacval" tid=4076669 file=validator_duties.nim:363 headSlot=2527 slot=72811
INF 2020-05-07 14:42:12+02:00 Slot end                                   topics="beacnde" tid=4076669 file=beacon_node.nim:442 cat=scheduling finalizedEpoch=76 finalizedRoot=252d351d finalizedSlot=2432 headEpoch=78 headRoot=f2c65381 headSlot=2527 nextSlot=72812 pcs=slot_start slot=72811
INF 2020-05-07 14:42:24+02:00 Slot start                                 topics="beacnde" tid=4076669 file=beacon_node.nim:337 beaconTime=873744 cat=scheduling finalizedEpoch=76 finalizedRoot=252d351d finalizedSlot=2432 headEpoch=78 headRoot=f2c65381 headSlot=2527 lastSlot=72811 pcs=slot_start peers=0 scheduledSlot=72812
INF 2020-05-07 14:42:24+02:00 No head block update                       topics="blkpool" tid=4076669 file=block_pool.nim:872 cat=fork_choice head=f2c65381:2527 pcs=fork_choice
@protolambda
Copy link
Contributor

Getting the same:

DBG 2020-05-10 14:05:14+02:00 Synchronization loop waiting for new peer  topics="syncman" tid=22564 file=sync_manager.nim:410 local_head_slot=975 wall_head_slot=94240 workers_count=1
DBG 2020-05-10 14:05:14+02:00 Synchronization loop got worker finished   topics="syncman" tid=22564 file=sync_manager.nim:461 local_head_slot=975 peer=16Uiu2HAmG3WDFfwoB9fPpnXEx4Msq9rfZX5oX4uRT4aWvLeqft69 peer_score=0 wall_head_slot=94240
DBG 2020-05-10 14:05:14+02:00 Synchronization loop starting new worker   topics="syncman" tid=22564 file=sync_manager.nim:444 local_head_slot=975 peer=16Uiu2HAmG3WDFfwoB9fPpnXEx4Msq9rfZX5oX4uRT4aWvLeqft69 peer_score=0 wall_head_slot=94240
DBG 2020-05-10 14:05:14+02:00 Starting syncing with peer                 topics="syncman" tid=22564 file=sync_manager.nim:263 peer=16Uiu2HAmG3WDFfwoB9fPpnXEx4Msq9rfZX5oX4uRT4aWvLeqft69 peer_score=0
DBG 2020-05-10 14:05:14+02:00 Peer's syncing status                      topics="syncman" tid=22564 file=sync_manager.nim:274 local_head_slot=975 peer=16Uiu2HAmG3WDFfwoB9fPpnXEx4Msq9rfZX5oX4uRT4aWvLeqft69 peer_score=0 remote_head_slot=0 wall_clock_slot=94240
DBG 2020-05-10 14:05:14+02:00 Updating peer's status information         topics="syncman" tid=22564 file=sync_manager.nim:289 local_head_slot=975 peer=16Uiu2HAmG3WDFfwoB9fPpnXEx4Msq9rfZX5oX4uRT4aWvLeqft69 peer_score=0 remote_head_slot=0 wall_clock_slot=94240
DBG 2020-05-10 14:05:14+02:00 Failed to get remote peer's status, exiting topics="syncman" tid=22564 file=sync_manager.nim:295 peer=16Uiu2HAmG3WDFfwoB9fPpnXEx4Msq9rfZX5oX4uRT4aWvLeqft69 peer_head_slot=0 peer_score=-100
DBG 2020-05-10 14:05:14+02:00 Peer score is too low, removing it from PeerPool topics="beacnde" tid=22564 file=beacon_node.nim:530 peer=16Uiu2HAmG3WDFfwoB9fPpnXEx4Msq9rfZX5oX4uRT4aWvLeqft69 peer_score=-100 score_limit=0
DBG 2020-05-10 14:05:14+02:00 Synchronization loop end tick              topics="syncman" tid=22564 file=sync_manager.nim:479 local_head_slot=975 waiting_for_new_peer=true wall_head_slot=94240 workers_count=1
DBG 2020-05-10 14:05:14+02:00 Synchronization loop start tick            topics="syncman" tid=22564 file=sync_manager.nim:387 local_head_slot=975 queue_last_slot=94240 queue_start_slot=0 queue_status=1 wall_head_slot=94240 workers_count=1
DBG 2020-05-10 14:05:14+02:00 Synchronization loop waiting for new peer  topics="syncman" tid=22564 file=sync_manager.nim:410 local_head_slot=975 wall_head_slot=94240 workers_count=1
DBG 2020-05-10 14:05:14+02:00 Synchronization loop got worker finished   topics="syncman" tid=22564 file=sync_manager.nim:461 local_head_slot=975 peer=16Uiu2HAmG3WDFfwoB9fPpnXEx4Msq9rfZX5oX4uRT4aWvLeqft69 peer_score=-100 wall_head_slot=94240
DBG 2020-05-10 14:05:14+02:00 Synchronization loop end tick              topics="syncman" tid=22564 file=sync_manager.nim:479 local_head_slot=975 waiting_for_new_peer=true wall_head_slot=94240 workers_count=0
DBG 2020-05-10 14:05:14+02:00 Synchronization loop start tick            topics="syncman" tid=22564 file=sync_manager.nim:387 local_head_slot=975 queue_last_slot=94240 queue_start_slot=0 queue_status=1 wall_head_slot=94240 workers_count=0
DBG 2020-05-10 14:05:14+02:00 Synchronization loop waiting for new peer  topics="syncman" tid=22564 file=sync_manager.nim:410 local_head_slot=975 wall_head_slot=94240 workers_count=0
DBG 2020-05-10 14:05:15+02:00 Received an invalid request                topics="networking" tid=22564 file=eth2_network.nim:395 errMsg="Serialisation error while processing <msg>" msgBytes=@[] msgName=statusObj peer=16Uiu2HAmG3WDFfwoB9fPpnXEx4Msq9rfZX5oX4uRT4aWvLeqft69
WRN 2020-05-10 14:05:15+02:00 unable to initiate pubsub                  tid=22564 file=switch.nim:337 exc="Stream EOF!\nAsync traceback:\nException message: Stream EOF!\nException type:" topic=Switch
DBG 2020-05-10 14:05:15+02:00 Failed to connect to peer                  topics="networking" tid=22564 file=eth2_network.nim:720 err="Connection dead on arrival\nAsync traceback:\nException message: Connection dead on arrival\nException type:" peer=Node[35.175.213.27:9000]
DBG 2020-05-10 14:05:15+02:00 Discovered new peer                        topics="networking" tid=22564 file=eth2_network.nim:714 peer=Node[68.183.226.13:12000]
DBG 2020-05-10 14:05:15+02:00 Connecting to peer                         topics="networking" tid=22564 file=eth2_network.nim:682 peer="16Uiu2HAmCQc6Dy9rFG7a1RFgTzuH6NSCbp8oCRb4g1smTWcympeV @[/ip4/68.183.226.13/tcp/13000] @[]"
INF 2020-05-10 14:05:24+02:00 Slot start                                 topics="beacnde" tid=22564 file=beacon_node.nim:326 beaconTime=1130724 cat=scheduling finalizedEpoch=28 finalizedRoot=77af76d7 finalizedSlot=896 headEpoch=30 headRoot=31b64e45 headSlot=975 lastSlot=94226 pcs=slot_start peers=0 scheduledSlot=94227
INF 2020-05-10 14:05:24+02:00 No head block update                       topics="blkpool" tid=22564 file=block_pool.nim:881 cat=fork_choice head=31b64e45:975 pcs=fork_choice
INF 2020-05-10 14:05:24+02:00 Slot end                                   topics="beacnde" tid=22564 file=beacon_node.nim:428 cat=scheduling finalizedEpoch=28 finalizedRoot=77af76d7 finalizedSlot=896 headEpoch=30 headRoot=31b64e45 headSlot=975 nextSlot=94228 pcs=slot_start slot=94227
INF 2020-05-10 14:05:36+02:00 Slot start                                 topics="beacnde" tid=22564 file=beacon_node.nim:326 beaconTime=1130736 cat=scheduling finalizedEpoch=28 finalizedRoot=77af76d7 finalizedSlot=896 headEpoch=30 headRoot=31b64e45 headSlot=975 lastSlot=94227 pcs=slot_start peers=0 scheduledSlot=94228
INF 2020-05-10 14:05:36+02:00 No head block update                       topics="blkpool" tid=22564 file=block_pool.nim:881 cat=fork_choice head=31b64e45:975 pcs=fork_choice
INF 2020-05-10 14:05:36+02:00 Slot end                                   topics="beacnde" tid=22564 file=beacon_node.nim:428 cat=scheduling finalizedEpoch=28 finalizedRoot=77af76d7 finalizedSlot=896 headEpoch=30 headRoot=31b64e45 headSlot=975 nextSlot=94229 pcs=slot_start slot=94228
INF 2020-05-10 14:05:48+02:00 Slot start                                 topics="beacnde" tid=22564 file=beacon_node.nim:326 beaconTime=1130748 cat=scheduling finalizedEpoch=28 finalizedRoot=77af76d7 finalizedSlot=896 headEpoch=30 headRoot=31b64e45 headSlot=975 lastSlot=94228 pcs=slot_start peers=0 scheduledSlot=94229
INF 2020-05-10 14:05:48+02:00 No head block update                       topics="blkpool" tid=22564 file=block_pool.nim:881 cat=fork_choice head=31b64e45:975 pcs=fork_choice
INF 2020-05-10 14:05:48+02:00 Slot end                                   topics="beacnde" tid=22564 file=beacon_node.nim:428 cat=scheduling finalizedEpoch=28 finalizedRoot=77af76d7 finalizedSlot=896 headEpoch=30 headRoot=31b64e45 headSlot=975 nextSlot=94230 pcs=slot_start slot=94229
INF 2020-05-10 14:06:00+02:00 Slot start                                 topics="beacnde" tid=22564 file=beacon_node.nim:326 beaconTime=1130760 cat=scheduling finalizedEpoch=28 finalizedRoot=77af76d7 finalizedSlot=896 headEpoch=30 headRoot=31b64e45 headSlot=975 lastSlot=94229 pcs=slot_start peers=0 scheduledSlot=94230
INF 2020-05-10 14:06:00+02:00 No head block update                       topics="blkpool" tid=22564 file=block_pool.nim:881 cat=fork_choice head=31b64e45:975 pcs=fork_choice
INF 2020-05-10 14:06:00+02:00 Slot end                                   topics="beacnde" tid=22564 file=beacon_node.nim:428 cat=scheduling finalizedEpoch=28 finalizedRoot=77af76d7 finalizedSlot=896 headEpoch=30 headRoot=31b64e45 headSlot=975 nextSlot=94231 pcs=slot_start slot=94230
INF 2020-05-10 14:06:12+02:00 Slot start                                 topics="beacnde" tid=22564 file=beacon_node.nim:326 beaconTime=1130772 cat=scheduling finalizedEpoch=28 finalizedRoot=77af76d7 finalizedSlot=896 headEpoch=30 headRoot=31b64e45 headSlot=975 lastSlot=94230 pcs=slot_start peers=0 scheduledSlot=94231
INF 2020-05-10 14:06:12+02:00 No head block update                       topics="blkpool" tid=22564 file=block_pool.nim:881 cat=fork_choice head=31b64e45:975 pcs=fork_choice
INF 2020-05-10 14:06:12+02:00 Slot end                                   topics="beacnde" tid=22564 file=beacon_node.nim:428 cat=scheduling finalizedEpoch=28 finalizedRoot=77af76d7 finalizedSlot=896 headEpoch=30

And a lot of status (rpc, not you, haha) errors like this:

DBG 2020-05-10 14:08:47+02:00 Failed to get remote peer's status, exiting topics="syncman" tid=22564 file=sync_manager.nim:295 peer=16Uiu2HAmGM8WU83nKNz6mogphpc3hkEjxiSwRPvkrx2nyTmiHRoF peer_head_slot=0 peer_score=0

@cheatfate
Copy link
Contributor

cheatfate commented May 11, 2020 •
edited

@protolambda syncing freezes because there no more peers available/connected.

DBG 2020-05-10 14:05:14+02:00 Synchronization loop start tick            topics="syncman" tid=22564 file=sync_manager.nim:387 local_head_slot=975 queue_last_slot=94240 queue_start_slot=0 queue_status=1 wall_head_slot=94240 workers_count=0

workers_count = 0. so sync is waiting for new peers. And last peer it knows was disconnected because it failed to answer status message with 10seconds timeout 4 times.

DBG 2020-05-10 14:05:14+02:00 Peer score is too low, removing it from PeerPool topics="beacnde" tid=22564 file=beacon_node.nim:530 peer=16Uiu2HAmG3WDFfwoB9fPpnXEx4Msq9rfZX5oX4uRT4aWvLeqft69 peer_score=-100 score_limit=0

@q9f
Copy link
Contributor Author

q9f commented May 11, 2020

It's a peering issue indeed and it's highly reproducible. I cannot consistently peer with Prysm, Lighthouse, and Teku bootnodes on Schlesi.

@protolambda
Copy link
Contributor

See my comments about status message exchange in discord. For debugging with rumor, when I open only the snappy rpc status method, and not the non-snappy one, it failed to detect it. The supports-snappy peer attribute seems to be broken. And I imagine other clients have trouble with the non-snappy version. Additionally, the finalized root for a status message at genesis is wrong.

@arnetheduck
Copy link
Member

Root cause here is a block not being accepted:

DBG 2020-05-11 12:17:49+02:00 Block received                             topics="beacnde" tid=1069620 file=beacon_node.nim:288 blockRoot=bfdeca76 cat=block_listener pcs=receive_block signedBlock="(slot: 7776, proposer_index: 45, parent_root: \"0bb94f15\", state_root: \"173c17e9\", proposer_slashings_len: 0, attester_slashings_len: 0, attestations_len: 1, deposits_len: 16, voluntary_exits_len: 0)"
NOT 2020-05-11 12:17:49+02:00 Deposit signature verification failed      tid=1069620 file=beaconstate.nim:90 pubkey=8e62ced1f9723cebf4135f47a7bf268ebde98ba87ba14337f10e47317292eb90709dfbc769f3fb9be49ba719969f3755 signature=8c311ccd73cd5098f8285ec59edd53a65c2d2a6661ceedd390ad051c2fdcff571fd8a1a4e384dcfcf520b6dd4c4c602300b9e10fa63e3c618c683f131aeb723339cf2ca3e4ba63d733e9814c20de7c912015b90d1ee4072b46710f5b75454343 signing_root=05392a47
NOT 2020-05-11 12:17:49+02:00 processDeposits: deposit invalid           tid=1069620 file=state_transition_block.nim:316

block-7776-bfdeca76.ssz.gz

@protolambda
Copy link
Contributor

Interesting, good find! Regarding the block: invalid deposit signatures are perfectly valid for the chain. The signature may be wrong because of a user error, but the deposit is proven through the eth1 deposits merkle tree, and will have to be processed so that future deposits can be processed afterwards. This is required since we need fair deposit ordering, and not skip any.

@tersec
Copy link
Contributor

tersec commented May 11, 2020

https://github.com/ethereum/eth2.0-specs/blob/v0.11.1/specs/phase0/beacon-chain.md#deposits says:

        # Verify the deposit signature (proof of possession) which is not checked by the deposit contract
        deposit_message = DepositMessage(
            pubkey=deposit.data.pubkey,
            withdrawal_credentials=deposit.data.withdrawal_credentials,
            amount=deposit.data.amount,
        )
        domain = compute_domain(DOMAIN_DEPOSIT)  # Fork-agnostic domain since deposits are valid across forks
        signing_root = compute_signing_root(deposit_message, domain)
        if not bls.Verify(pubkey, signing_root, deposit.data.signature):
            return

Should that check, then, not be so decisive for deposit processing, or otherwise skipped except if otherwise useful/interesting as a diagnostic warning?

@arnetheduck
Copy link
Member

@tersec https://github.com/status-im/nim-beacon-chain/blob/9636ca3e17628d4bfbdc2a29006e5385fc398e66/beacon_chain/spec/beaconstate.nim#L92

notably, we fail the block, the spec version merely returns and keeps processing

arnetheduck added a commit that referenced this issue May 11, 2020
@arnetheduck
sync fixes
bf2d804 
* fix Status message finalized info
* work around sync starting before initial status exchange
* don't fail block on deposit signature check failure (fixes #989)
* print ForkDigest and Version nicely
* dump incoming blocks
* fix crash when libp2p peer connection is closed
@arnetheduck arnetheduck mentioned this issue May 11, 2020
Merged
arnetheduck added a commit that referenced this issue May 11, 2020
@arnetheduck
sync fixes
0a02762 
* fix Status message finalized info
* work around sync starting before initial status exchange
* don't fail block on deposit signature check failure (fixes #989)
* print ForkDigest and Version nicely
* dump incoming blocks
* fix crash when libp2p peer connection is closed
* update chunk size to 16 to work around missing blocks when syncing
arnetheduck added a commit that referenced this issue May 11, 2020
@arnetheduck
sync fixes
104295a 
* fix Status message finalized info
* work around sync starting before initial status exchange
* don't fail block on deposit signature check failure (fixes #989)
* print ForkDigest and Version nicely
* dump incoming blocks
* fix crash when libp2p peer connection is closed
* update chunk size to 16 to work around missing blocks when syncing
@tersec
Copy link
Contributor

tersec commented May 12, 2020

Is this still an issue?

@q9f
Copy link
Contributor Author

q9f commented May 13, 2020

I cannot test this anymore due to #1012

@arnetheduck
Copy link
Member

#1005 fixes the block sync issue

#986 improves snappy support so that we don't drop certain peers, improving sync performance

@q9f
Copy link
Contributor Author

q9f commented May 13, 2020

Still cannot fully sync schlesi:

INF 2020-05-13 14:08:39+02:00 Block resolved                             topics="blkpool" tid=1154519 file=block_pool.nim:300 blck="(slot: 5772, proposer_index: 53, parent_root: \"28b054db\", state_root: \"08f0f096\", proposer_slashings_len: 0, attester_slashings_len: 0, attestations_len: 1, deposits_len: 0, voluntary_exits_len: 0)" blockRoot=f3ea302a cat=filtering heads=1 justifiedHead=03e59715:4672 pcs=block_resolution                                          [516/1292]
INF 2020-05-13 14:08:40+02:00 Updated head block                         topics="blkpool" tid=1154519 file=block_pool.nim:920 cat=fork_choice finalizedEpoch=145 headBlock=f3ea302a:5772 justifiedEpoch=146 pcs=fork_choice stateRoot=08f0f096 stateSlot=5772
INF 2020-05-13 14:08:40+02:00 Forward sync blocks got imported sucessfully topics="beacnde" tid=1154519 file=beacon_node.nim:523 count=4 local_head_slot=5772
INF 2020-05-13 14:08:40+02:00 No head block update                       topics="blkpool" tid=1154519 file=block_pool.nim:881 cat=fork_choice head=f3ea302a:5772 pcs=fork_choice
INF 2020-05-13 14:08:40+02:00 Forward sync blocks got imported sucessfully topics="beacnde" tid=1154519 file=beacon_node.nim:523 count=0 local_head_slot=5772
INF 2020-05-13 14:08:41+02:00 Requesting detected missing blocks         topics="beacnde" tid=1154519 file=beacon_node.nim:486 missingBlocks="@[(root: DE4887571B891079C7A350718E405E57BD05EBDD9A6BD0C2443A6F65A00FF5A2, historySlots: 20)]"
INF 2020-05-13 14:08:42+02:00 Requesting detected missing blocks         topics="beacnde" tid=1154519 file=beacon_node.nim:486 missingBlocks="@[(root: DE4887571B891079C7A350718E405E57BD05EBDD9A6BD0C2443A6F65A00FF5A2, historySlots: 20)]"
INF 2020-05-13 14:08:44+02:00 Requesting detected missing blocks         topics="beacnde" tid=1154519 file=beacon_node.nim:486 missingBlocks="@[(root: DE4887571B891079C7A350718E405E57BD05EBDD9A6BD0C2443A6F65A00FF5A2, historySlots: 20)]"
INF 2020-05-13 14:08:44+02:00 No head block update                       topics="blkpool" tid=1154519 file=block_pool.nim:881 cat=fork_choice head=f3ea302a:5772 pcs=fork_choice
INF 2020-05-13 14:08:44+02:00 Forward sync blocks got imported sucessfully topics="beacnde" tid=1154519 file=beacon_node.nim:523 count=0 local_head_slot=5772
WRN 2020-05-13 14:08:44+02:00 ignored an error                           tid=1154519 file=errors.nim:62 multistream handle="multistream handle" name=LPStreamEOFError topic=Multistream
INF 2020-05-13 14:08:45+02:00 Requesting detected missing blocks         topics="beacnde" tid=1154519 file=beacon_node.nim:486 missingBlocks="@[(root: 5A78B5B7D9AE1980BB72BCD13770DE503B9C19A2BD4E4EBADB65F452F10F8BA3, historySlots: 34)]"
WRN 2020-05-13 14:08:45+02:00 ignored an error                           tid=1154519 file=errors.nim:62 multistream handle="multistream handle" name=LPStreamEOFError topic=Multistream
WRN 2020-05-13 14:08:45+02:00 ignored an error                           tid=1154519 file=errors.nim:62 multistream handle="multistream handle" name=LPStreamEOFError topic=Multistream
WRN 2020-05-13 14:08:45+02:00 ignored an error                           tid=1154519 file=errors.nim:62 multistream handle="multistream handle" name=LPStreamEOFError topic=Multistream
WRN 2020-05-13 14:08:45+02:00 ignored an error                           tid=1154519 file=errors.nim:62 multistream handle="multistream handle" name=LPStreamEOFError topic=Multistream
WRN 2020-05-13 14:08:45+02:00 ignored an error                           tid=1154519 file=errors.nim:62 multistream handle="multistream handle" name=LPStreamEOFError topic=Multistream
WRN 2020-05-13 14:08:45+02:00 ignored an error                           tid=1154519 file=errors.nim:62 multistream handle="multistream handle" name=LPStreamEOFError topic=Multistream
INF 2020-05-13 14:08:46+02:00 Requesting detected missing blocks         topics="beacnde" tid=1154519 file=beacon_node.nim:486 missingBlocks="@[(root: 5A78B5B7D9AE1980BB72BCD13770DE503B9C19A2BD4E4EBADB65F452F10F8BA3, historySlots: 34)]"
WRN 2020-05-13 14:08:46+02:00 ignored an error                           tid=1154519 file=errors.nim:62 multistream handle="multistream handle" name=LPStreamEOFError topic=Multistream
WRN 2020-05-13 14:08:46+02:00 ignored an error                           tid=1154519 file=errors.nim:62 multistream handle="multistream handle" name=LPStreamEOFError topic=Multistream

[...]

INF 2020-05-13 14:15:48+02:00 Slot end                                   topics="beacnde" tid=1154519 file=beacon_node.nim:457 cat=scheduling finalizedEpoch=145 finalizedRoot=8a9fd7b3 finalizedSlot=4640 headEpoch=180 headRoot=f3ea302a headSlot=5772 nextSlot=115880 pcs=slot_start slot=115879                                                                                                                                                                               [201/1292]
WRN 2020-05-13 14:15:49+02:00 no handlers for                            tid=1154519 file=multistream.nim:148 protocol=/prysm/0.0.0/dht topic=Multistream
WRN 2020-05-13 14:15:49+02:00 no handlers for                            tid=1154519 file=multistream.nim:148 protocol=/eth2/beacon_chain/req/goodbye/1/ssz_snappy topic=Multistream
WRN 2020-05-13 14:15:49+02:00 ignored an error                           tid=1154519 file=errors.nim:62 multistream handle="multistream handle" name=LPStreamEOFError topic=Multistream
WRN 2020-05-13 14:15:49+02:00 ignored an error                           tid=1154519 file=errors.nim:62 multistream handle="multistream handle" name=LPStreamEOFError topic=Multistream
INF 2020-05-13 14:16:00+02:00 Slot start                                 topics="beacnde" tid=1154519 file=beacon_node.nim:351 beaconTime=1390560 cat=scheduling finalizedEpoch=145 finalizedRoot=8a9fd7b3 finalizedSlot=4640 headEpoch=180 headRoot=f3ea302a headSlot=5772 lastSlot=115879 pcs=slot_start peers=3 scheduledSlot=115880
INF 2020-05-13 14:16:00+02:00 No head block update                       topics="blkpool" tid=1154519 file=block_pool.nim:881 cat=fork_choice head=f3ea302a:5772 pcs=fork_choice
NOT 2020-05-13 14:16:00+02:00 Node out of sync, skipping validator duties topics="beacval" tid=1154519 file=validator_duties.nim:363 headSlot=5772 slot=115880
INF 2020-05-13 14:16:00+02:00 Slot end                                   topics="beacnde" tid=1154519 file=beacon_node.nim:457 cat=scheduling finalizedEpoch=145 finalizedRoot=8a9fd7b3 finalizedSlot=4640 headEpoch=180 headRoot=f3ea302a headSlot=5772 nextSlot=115881 pcs=slot_start slot=115880
INF 2020-05-13 14:16:12+02:00 Slot start                                 topics="beacnde" tid=1154519 file=beacon_node.nim:351 beaconTime=1390572 cat=scheduling finalizedEpoch=145 finalizedRoot=8a9fd7b3 finalizedSlot=4640 headEpoch=180 headRoot=f3ea302a headSlot=5772 lastSlot=115880 pcs=slot_start peers=3 scheduledSlot=115881
INF 2020-05-13 14:16:12+02:00 No head block update                       topics="blkpool" tid=1154519 file=block_pool.nim:881 cat=fork_choice head=f3ea302a:5772 pcs=fork_choice
NOT 2020-05-13 14:16:12+02:00 Node out of sync, skipping validator duties topics="beacval" tid=1154519 file=validator_duties.nim:363 headSlot=5772 slot=115881
INF 2020-05-13 14:16:12+02:00 Slot end                                   topics="beacnde" tid=1154519 file=beacon_node.nim:457 cat=scheduling finalizedEpoch=145 finalizedRoot=8a9fd7b3 finalizedSlot=4640 headEpoch=180 headRoot=f3ea302a headSlot=5772 nextSlot=115882 pcs=slot_start slot=115881
INF 2020-05-13 14:16:24+02:00 Slot start                                 topics="beacnde" tid=1154519 file=beacon_node.nim:351 beaconTime=1390584 cat=scheduling finalizedEpoch=145 finalizedRoot=8a9fd7b3 finalizedSlot=4640 headEpoch=180 headRoot=f3ea302a headSlot=5772 lastSlot=115881 pcs=slot_start peers=3 scheduledSlot=115882
INF 2020-05-13 14:16:24+02:00 No head block update                       topics="blkpool" tid=1154519 file=block_pool.nim:881 cat=fork_choice head=f3ea302a:5772 pcs=fork_choice
NOT 2020-05-13 14:16:24+02:00 Node out of sync, skipping validator duties topics="beacval" tid=1154519 file=validator_duties.nim:363 headSlot=5772 slot=115882
INF 2020-05-13 14:16:24+02:00 Slot end                                   topics="beacnde" tid=1154519 file=beacon_node.nim:457 cat=scheduling finalizedEpoch=145 finalizedRoot=8a9fd7b3 finalizedSlot=4640 headEpoch=180 headRoot=f3ea302a headSlot=5772 nextSlot=115883 pcs=slot_start slot=115882
INF 2020-05-13 14:16:36+02:00 Slot start                                 topics="beacnde" tid=1154519 file=beacon_node.nim:351 beaconTime=1390596 cat=scheduling finalizedEpoch=145 finalizedRoot=8a9fd7b3 finalizedSlot=4640 headEpoch=180 headRoot=f3ea302a headSlot=5772 lastSlot=115882 pcs=slot_start peers=3 scheduledSlot=115883
INF 2020-05-13 14:16:36+02:00 No head block update                       topics="blkpool" tid=1154519 file=block_pool.nim:881 cat=fork_choice head=f3ea302a:5772 pcs=fork_choice
NOT 2020-05-13 14:16:36+02:00 Node out of sync, skipping validator duties topics="beacval" tid=1154519 file=validator_duties.nim:363 headSlot=5772 slot=115883
INF 2020-05-13 14:16:36+02:00 Slot end                                   topics="beacnde" tid=1154519 file=beacon_node.nim:457 cat=scheduling finalizedEpoch=145 finalizedRoot=8a9fd7b3 finalizedSlot=4640 headEpoch=180 headRoot=f3ea302a headSlot=5772 nextSlot=115884 pcs=slot_start slot=115883

devel @ e537ed9

@q9f q9f mentioned this issue May 14, 2020
Closed
@arnetheduck
Copy link
Member

#1026 works around a sync manager issue

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@arnetheduck @cheatfate @tersec @protolambda @q9f