nimbus-eth2
nimbus-eth2 copied to clipboard
Published
20 hours ago •
status-im
status-im
Long delay between BN in sync and VC duties
Beacon node was syncing and finished - took >10 slots before attester duties resumed - duties should be checked every slot
WRN 2022-10-27 16:02:18.885+02:00 No suitable beacon nodes available online_nodes=0 offline_nodes=0 uninitalized_nodes=0 incompatible_nodes=0 nonsynced_nodes=1 total_nodes=1 service=fallback_service
INF 2022-10-27 16:02:18.885+02:00 Beacon node has been identified agent=Nimbus/v22.10.1-a95831-stateofus service=fallback_service node=localhost:5152[Nimbus/v22.10.1-a95831-stateofus] node_index=0 node_roles=AGBSD
INF 2022-10-27 16:02:18.967+02:00 Beacon node has compatible configuration service=fallback_service node=localhost:5152[Nimbus/v22.10.1-a95831-stateofus] node_index=0 node_roles=AGBSD
INF 2022-10-27 16:02:19.008+02:00 Beacon node is in sync sync_distance=0 head_slot=4197611 is_opimistic=false service=fallback_service node=localhost:5152[Nimbus/v22.10.1-a95831-stateofus] node_index=0 node_roles=AGBSD
INF 2022-10-27 16:02:24.001+02:00 Slot start slot=4197612 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=1ms122us794ns
INF 2022-10-27 16:02:36.001+02:00 Slot start slot=4197613 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=1ms42us554ns
INF 2022-10-27 16:02:48.000+02:00 Slot start slot=4197614 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=117us826ns
INF 2022-10-27 16:03:00.001+02:00 Slot start slot=4197615 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=1ms45us359ns
INF 2022-10-27 16:03:12.001+02:00 Slot start slot=4197616 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=1ms328us613ns
INF 2022-10-27 16:03:24.001+02:00 Slot start slot=4197617 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=1ms38us990ns
INF 2022-10-27 16:03:36.001+02:00 Slot start slot=4197618 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=1ms40us657ns
INF 2022-10-27 16:03:48.001+02:00 Slot start slot=4197619 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=996us300ns
INF 2022-10-27 16:04:00.001+02:00 Slot start slot=4197620 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=1ms56us47ns
INF 2022-10-27 16:04:12.001+02:00 Slot start slot=4197621 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=1ms36us161ns
INF 2022-10-27 16:04:24.001+02:00 Slot start slot=4197622 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=1ms14us29ns
INF 2022-10-27 16:04:36.000+02:00 Slot start slot=4197623 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=757us32ns
INF 2022-10-27 16:04:48.001+02:00 Slot start slot=4197624 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=1ms52us389ns
INF 2022-10-27 16:05:00.001+02:00 Slot start slot=4197625 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=1ms66us200ns
INF 2022-10-27 16:05:12.001+02:00 Slot start slot=4197626 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=1ms141us786ns
INF 2022-10-27 16:05:24.000+02:00 Slot start slot=4197627 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=934us603ns
INF 2022-10-27 16:05:36.000+02:00 Slot start slot=4197628 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=989us76ns
INF 2022-10-27 16:05:48.001+02:00 Slot start slot=4197629 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=1ms63us712ns
INF 2022-10-27 16:06:00.000+02:00 Slot start slot=4197630 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=933us494ns
INF 2022-10-27 16:06:12.001+02:00 Slot start slot=4197631 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=1ms58us630ns
INF 2022-10-27 16:06:24.000+02:00 Slot start slot=4197632 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=862us93ns
NOT 2022-10-27 16:06:24.275+02:00 Fork schedule updated fork_schedule="@[(previous_version: 00001020, current_version: 00001020, epoch: 0), (previous_version: 00001020, current_version: 01001020, epoch: 36660), (previous_version: 01001020, current_version: 02001020, epoch: 112260)]" service=fork_service
INF 2022-10-27 16:06:24.323+02:00 Received new attester duty pubkey=937665ff slot=4197647 validator_index=212546 committee_index=0 committee_length=189 committees_at_slot=64 validator_committee_index=81 epoch=131176 dependent_root=2419eaa6 service=duties_service
INF 2022-10-27 16:06:24.323+02:00 Received new attester duty pubkey=81bb939d slot=4197635 validator_index=212570 committee_index=1 committee_length=189 committees_at_slot=64 validator_committee_index=103 epoch=131176 dependent_root=2419eaa6 service=duties_service
INF 2022-10-27 16:06:24.323+02:00 Received new attester duty pubkey=a06f1201 slot=4197659 validator_index=212569 committee_index=1 committee_length=189 committees_at_slot=64 validator_committee_index=120 epoch=131176 dependent_root=2419eaa6 service=duties_service
...
a958313feb417d7bb27d24ce6a638424d431d6d3
note: this is not doppelganger protection - that happens (correctly) after duties:
INF 2022-10-27 16:06:24.438+02:00 Received new attester duty pubkey=9306e4a1 slot=4197680 validator_index=212535 committee_index=63 committee_length=189 committees_at_slot=64 validator_committee_index=33 epoch=131177 dependent_root=ebe2692d service=duties_service
INF 2022-10-27 16:06:28.000+02:00 Doppelganger protection disabled validator duties validators=3 service=attestation_service
INF 2022-10-27 16:06:36.001+02:00 Slot start slot=4197633 attestationIn=16s0ns blockIn=<unknown> validators=62 delay=1ms58us912ns
INF 2022-10-27 16:06:48.001+02:00 Slot start slot=4197634 attestationIn=4s0ns blockIn=<unknown> validators=62 delay=1ms8us412ns
INF 2022-10-27 16:06:52.000+02:00 Doppelganger protection disabled validator duties validators=2 service=attestation_service
INF 2022-10-27 16:07:00.001+02:00 Slot start slot=4197635 attestationIn=4s0ns blockIn=<unknown> validators=62 delay=1ms28us729ns
INF 2022-10-27 16:07:04.000+02:00 Doppelganger protection disabled validator duties validators=2 service=attestation_service
INF 2022-10-27 16:07:12.000+02:00 Slot start slot=4197636 attestationIn=16s0ns blockIn=<unknown> validators=62 delay=926us680ns
INF 2022-10-27 16:07:24.000+02:00 Slot start slot=4197637 attestationIn=4s0ns blockIn=<unknown> validators=62 delay=877us947ns
INF 2022-10-27 16:07:28.000+02:00 Doppelganger protection disabled validator duties validators=3 service=attestation_service
INF 2022-10-27 16:07:36.000+02:00 Slot start slot=4197638 attestationIn=4s0ns blockIn=<unknown> validators=62 delay=875us516ns
Duties are checked every slot: https://github.com/status-im/nimbus-eth2/blob/stable/beacon_chain/validator_client/duties_service.nim#L500-L501
What i see from your log is that you do not have any attestation duties for period [4197612, 4197632]. Have you actually missed attestations for this period of time?
INF 2022-10-27 16:02:19.008+02:00 Beacon node is in sync sync_distance=0 head_slot=4197611 is_opimistic=false service=fallback_service node=localhost:5152[Nimbus/v22.10.1-a95831-stateofus] node_index=0 node_roles=AGBSD
DBG 2022-10-27 16:02:21.010+02:00 Sending REST request to remote server remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer http_method=POST
DBG 2022-10-27 16:02:21.010+02:00 Opened connection to remote server remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer http_method=POST connection=1
DBG 2022-10-27 16:02:21.010+02:00 Sending REST request to remote server remote=localhost:5152 request=/eth/v1/beacon/blocks/head/root http_method=GET
DBG 2022-10-27 16:02:21.010+02:00 REST request body has been sent remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer size=5581 http_method=POST connection=1
DBG 2022-10-27 16:02:21.011+02:00 Got REST response headers from remote server status=200 http_method=GET remote=localhost:5152 request=/eth/v1/beacon/blocks/head/root connection=2
DBG 2022-10-27 16:02:21.012+02:00 Received REST response body from remote server remote=localhost:5152 request=/eth/v1/beacon/blocks/head/root contentType=application/json size=115 connection=2
DBG 2022-10-27 16:02:21.012+02:00 Sync committee message statistics total=0 succeed=0 failed_to_deliver=0 not_accepted=0 delay=5s12ms86us173ns slot=4197611 duties_count=0 service=sync_committee_service
DBG 2022-10-27 16:02:21.012+02:00 Producing contribution and proofs delay=1s12ms136us515ns service=sync_committee_service
DBG 2022-10-27 16:02:21.012+02:00 No contribution and proofs scheduled for slot slot=4197611 service=sync_committee_service
DBG 2022-10-27 16:02:21.051+02:00 Got REST response headers from remote server status=200 http_method=POST remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer connection=1
DBG 2022-10-27 16:02:21.051+02:00 Received REST response body from remote server remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer contentType=text/plain size=0 connection=1
DBG 2022-10-27 16:02:21.051+02:00 Beacon proposers prepared validators_count=62 proposers_count=62 prepared_count=1 service=duties_service
INF 2022-10-27 16:02:24.001+02:00 Slot start slot=4197612 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=1ms122us794ns
DBG 2022-10-27 16:02:24.001+02:00 Sending REST request to remote server remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer http_method=POST
DBG 2022-10-27 16:02:24.001+02:00 Opened connection to remote server remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer http_method=POST connection=1
DBG 2022-10-27 16:02:24.001+02:00 REST request body has been sent remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer size=5581 http_method=POST connection=1
DBG 2022-10-27 16:02:24.198+02:00 Got REST response headers from remote server status=200 http_method=POST remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer connection=1
DBG 2022-10-27 16:02:24.198+02:00 Received REST response body from remote server remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer contentType=text/plain size=0 connection=1
DBG 2022-10-27 16:02:24.198+02:00 Beacon proposers prepared validators_count=62 proposers_count=62 prepared_count=1 service=duties_service
DBG 2022-10-27 16:02:28.001+02:00 Block proposal awaited slot=4197612 duration=2us140ns service=sync_committee_service
DBG 2022-10-27 16:02:28.001+02:00 Producing sync committee messages delay=1ms156us277ns slot=4197612 duties_count=0 service=sync_committee_service
DBG 2022-10-27 16:02:28.001+02:00 Sending REST request to remote server remote=localhost:5152 request=/eth/v1/beacon/blocks/head/root http_method=GET
DBG 2022-10-27 16:02:28.002+02:00 Got REST response headers from remote server status=200 http_method=GET remote=localhost:5152 request=/eth/v1/beacon/blocks/head/root connection=1
DBG 2022-10-27 16:02:28.002+02:00 Received REST response body from remote server remote=localhost:5152 request=/eth/v1/beacon/blocks/head/root contentType=application/json size=115 connection=1
DBG 2022-10-27 16:02:28.002+02:00 Sync committee message statistics total=0 succeed=0 failed_to_deliver=0 not_accepted=0 delay=2ms261us758ns slot=4197612 duties_count=0 service=sync_committee_service
DBG 2022-10-27 16:02:32.001+02:00 Producing contribution and proofs delay=1ms42us982ns service=sync_committee_service
DBG 2022-10-27 16:02:32.001+02:00 No contribution and proofs scheduled for slot slot=4197612 service=sync_committee_service
INF 2022-10-27 16:02:36.001+02:00 Slot start slot=4197613 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=1ms42us554ns
DBG 2022-10-27 16:02:36.001+02:00 Sending REST request to remote server remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer http_method=POST
DBG 2022-10-27 16:02:36.001+02:00 Opened connection to remote server remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer http_method=POST connection=1
DBG 2022-10-27 16:02:36.001+02:00 REST request body has been sent remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer size=5581 http_method=POST connection=1
DBG 2022-10-27 16:02:36.042+02:00 Got REST response headers from remote server status=200 http_method=POST remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer connection=1
DBG 2022-10-27 16:02:36.042+02:00 Received REST response body from remote server remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer contentType=text/plain size=0 connection=1
DBG 2022-10-27 16:02:36.042+02:00 Beacon proposers prepared validators_count=62 proposers_count=62 prepared_count=1 service=duties_service
DBG 2022-10-27 16:02:40.001+02:00 Block proposal awaited slot=4197613 duration=2us112ns service=sync_committee_service
DBG 2022-10-27 16:02:40.001+02:00 Producing sync committee messages delay=1ms97us619ns slot=4197613 duties_count=0 service=sync_committee_service
DBG 2022-10-27 16:02:40.001+02:00 Sending REST request to remote server remote=localhost:5152 request=/eth/v1/beacon/blocks/head/root http_method=GET
DBG 2022-10-27 16:02:40.002+02:00 Got REST response headers from remote server status=200 http_method=GET remote=localhost:5152 request=/eth/v1/beacon/blocks/head/root connection=1
DBG 2022-10-27 16:02:40.002+02:00 Received REST response body from remote server remote=localhost:5152 request=/eth/v1/beacon/blocks/head/root contentType=application/json size=115 connection=1
DBG 2022-10-27 16:02:40.002+02:00 Sync committee message statistics total=0 succeed=0 failed_to_deliver=0 not_accepted=0 delay=2ms171us512ns slot=4197613 duties_count=0 service=sync_committee_service
DBG 2022-10-27 16:02:44.001+02:00 Producing contribution and proofs delay=1ms51us170ns service=sync_committee_service
DBG 2022-10-27 16:02:44.001+02:00 No contribution and proofs scheduled for slot slot=4197613 service=sync_committee_service
INF 2022-10-27 16:02:48.000+02:00 Slot start slot=4197614 attestationIn=<unknown> blockIn=<unknown> validators=62 delay=117us826ns
DBG 2022-10-27 16:02:48.000+02:00 Sending REST request to remote server remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer http_method=POST
DBG 2022-10-27 16:02:48.000+02:00 Opened connection to remote server remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer http_method=POST connection=1
DBG 2022-10-27 16:02:48.000+02:00 REST request body has been sent remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer size=5581 http_method=POST connection=1
DBG 2022-10-27 16:02:48.041+02:00 Got REST response headers from remote server status=200 http_method=POST remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer connection=1
DBG 2022-10-27 16:02:48.041+02:00 Received REST response body from remote server remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer contentType=text/plain size=0 connection=1
DBG 2022-10-27 16:02:48.041+02:00 Beacon proposers prepared validators_count=62 proposers_count=62 prepared_count=1 service=duties_service
DBG 2022-10-27 16:02:52.001+02:00 Block proposal awaited slot=4197614 duration=12us446ns service=sync_committee_service
DBG 2022-10-27 16:02:52.001+02:00 Producing sync committee messages delay=1ms175us468ns slot=4197614 duties_count=0 service=sync_committee_service
DBG 2022-10-27 16:02:52.001+02:00 Sending REST request to remote server remote=localhost:5152 request=/eth/v1/beacon/blocks/head/root http_method=GET
DBG 2022-10-27 16:02:52.001+02:00 Got REST response headers from remote server status=200 http_method=GET remote=localhost:5152 request=/eth/v1/beacon/blocks/head/root connection=1
DBG 2022-10-27 16:02:52.002+02:00 Received REST response body from remote server remote=localhost:5152 request=/eth/v1/beacon/blocks/head/root contentType=application/json size=115 connection=1
...
DBG 2022-10-27 16:06:24.001+02:00 REST request body has been sent remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer size=5581 http_method=POST connection=1
DBG 2022-10-27 16:06:24.079+02:00 Sending REST request to remote server remote=localhost:5152 request=/eth/v1/config/fork_schedule http_method=GET
DBG 2022-10-27 16:06:24.079+02:00 Sending REST request to remote server remote=localhost:5152 request=/nimbus/v1/validator/activity/131175 http_method=POST
DBG 2022-10-27 16:06:24.080+02:00 Opened connection to remote server remote=localhost:5152 request=/nimbus/v1/validator/activity/131175 http_method=POST connection=3
DBG 2022-10-27 16:06:24.080+02:00 REST request body has been sent remote=localhost:5152 request=/nimbus/v1/validator/activity/131175 size=559 http_method=POST connection=3
DBG 2022-10-27 16:06:24.275+02:00 Got REST response headers from remote server status=200 http_method=GET remote=localhost:5152 request=/eth/v1/config/fork_schedule connection=2
DBG 2022-10-27 16:06:24.275+02:00 Received REST response body from remote server remote=localhost:5152 request=/eth/v1/config/fork_schedule contentType=application/json size=250 connection=2
NOT 2022-10-27 16:06:24.275+02:00 Fork schedule updated fork_schedule="@[(previous_version: 00001020, current_version: 00001020, epoch: 0), (previous_version: 00001020, current_version: 01001020, epoch: 36660), (previous_version: 01001020, current_version: 02001020, epoch: 112260)]" service=fork_service
DBG 2022-10-27 16:06:24.276+02:00 Sending REST request to remote server remote=localhost:5152 request=/eth/v1/validator/duties/attester/131176 http_method=POST
DBG 2022-10-27 16:06:24.276+02:00 Opened connection to remote server remote=localhost:5152 request=/eth/v1/validator/duties/attester/131176 http_method=POST connection=2
DBG 2022-10-27 16:06:24.276+02:00 Sending REST request to remote server remote=localhost:5152 request=/eth/v1/validator/duties/proposer/131176 http_method=GET
DBG 2022-10-27 16:06:24.276+02:00 Sending REST request to remote server remote=localhost:5152 request=/eth/v1/validator/duties/sync/131176 http_method=POST
DBG 2022-10-27 16:06:24.276+02:00 Sleeping until next epoch sleep_time=6m23s802ms663us529ns service=fork_service
DBG 2022-10-27 16:06:24.276+02:00 REST request body has been sent remote=localhost:5152 request=/eth/v1/validator/duties/attester/131176 size=559 http_method=POST connection=2
DBG 2022-10-27 16:06:24.276+02:00 Got REST response headers from remote server status=200 http_method=POST remote=localhost:5152 request=/nimbus/v1/validator/activity/131175 connection=3
DBG 2022-10-27 16:06:24.276+02:00 Opened connection to remote server remote=localhost:5152 request=/eth/v1/validator/duties/sync/131176 http_method=POST connection=5
DBG 2022-10-27 16:06:24.276+02:00 Got REST response headers from remote server status=200 http_method=POST remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer connection=1
DBG 2022-10-27 16:06:24.276+02:00 REST request body has been sent remote=localhost:5152 request=/eth/v1/validator/duties/sync/131176 size=559 http_method=POST connection=5
DBG 2022-10-27 16:06:24.276+02:00 Received REST response body from remote server remote=localhost:5152 request=/nimbus/v1/validator/activity/131175 contentType=application/json size=3172 connection=3
DBG 2022-10-27 16:06:24.276+02:00 Received REST response body from remote server remote=localhost:5152 request=/eth/v1/validator/prepare_beacon_proposer contentType=text/plain size=0 connection=1
DBG 2022-10-27 16:06:24.276+02:00 Received validators activity response node=localhost:5152[Nimbus/v22.10.1-a95831-stateofus] node_index=0 node_roles=AGBSD validators_count=62 activities_count=62 request=getValidatorsActivity
DBG 2022-10-27 16:06:24.276+02:00 Validator's activity was not seen validator_index=212571 epoch=131175 epochs_count=1 service=doppelganger_service
DBG 2022-10-27 16:06:24.276+02:00 Validator's activity was not seen validator_index=212572 epoch=131175 epochs_count=1 service=doppelganger_service
DBG 2022-10-27 16:06:24.276+02:00 Validator's activity was not seen validator_index=212566 epoch=131175 epochs_count=1 service=doppelganger_service
DBG 2022-10-27 16:06:24.276+02:00 Validator's activity was not seen validator_index=212540 epoch=131175 epochs_count=1 service=doppelganger_service
DBG 2022-10-27 16:06:24.276+02:00 Validator's activity was not seen validator_index=212561 epoch=131175 epochs_count=1 service=doppelganger_service
DBG 2022-10-27 16:06:24.276+02:00 Validator's activity was not seen validator_index=212533 epoch=131175 epochs_count=1 service=doppelganger_service
Per debug logs, there are no duties requests in the period leading up to 4197632 - also, if duties were fetched, they should be seen in attestationIn because of the lookahead into the next epoch.