Skip to content

fix(validator): improve error handling in attestation service #5511

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
Merged
nflaig merged 2 commits into from
May 23, 2023
Merged

fix(validator): improve error handling in attestation service #5511

nflaig merged 2 commits into from
May 23, 2023

Conversation

@nflaig
Copy link
Member

@nflaig nflaig commented May 21, 2023

Motivation

Errors thrown during attestation routine are not handled within AttestationService but instead will be will be logged by Clock which does not use LoggerVC due to circular dependency (LoggerVC depends on clock).

lodestar/packages/validator/src/validator.ts

Lines 73 to 74 in bc88bdd

const clock = new Clock(config, logger, {genesisTime: Number(genesis.genesisTime)});
const loggerVc = getLoggerVc(logger, clock);

When the EL is syncing the BN will throw an error during attestation routine of VC which produces an verbose error

error: Error on runEvery fn  Error producing attestation - Service Unavailable: Node is syncing - Block's execution payload not yet validated, executionPayloadBlockHash=0xfaf4067706a82a716245fcbd963b3ed502a8fc4a6d1c896c44e9cd7efe1ec425 number=9039112
Error: Error producing attestation - Service Unavailable: Node is syncing - Block's execution payload not yet validated, executionPayloadBlockHash=0xfaf4067706a82a716245fcbd963b3ed502a8fc4a6d1c896c44e9cd7efe1ec425 number=9039112
    at Function.assert (file:///home/devops/goerli/lodestar/packages/api/src/utils/client/httpClient.ts:44:13)
    at AttestationService.produceAttestation (file:///home/devops/goerli/lodestar/packages/validator/src/services/attestation.ts:167:14)
    at processTicksAndRejections (node:internal/process/task_queues:95:5)
    at AttestationService.runAttestationTasksGrouped (file:///home/devops/goerli/lodestar/packages/validator/src/services/attestation.ts:134:36)
    at AttestationService.runAttestationTasks (file:///home/devops/goerli/lodestar/packages/validator/src/services/attestation.ts:102:7)
    at Clock.runAtMostEvery (file:///home/devops/goerli/lodestar/packages/validator/src/util/clock.ts:96:7)

Expected error log

warn: Node is syncing - Error producing attestation - Service Unavailable: Node is syncing - Block's execution payload not yet validated, executionPayloadBlockHash=0x1c11477b79fd8d7d0c72411897fb96efa25c15781f7b78a714377af7b02bc02a number=9039134

Description

Catch errors thrown by runAttestationTasksGrouped to properly handle "Node is syncing" errors and improve logging UX.

@nflaig nflaig requested a review from a team as a code owner May 21, 2023 16:01
@github-actions
Copy link
Contributor

github-actions bot commented May 21, 2023 •
edited
Loading

Performance Report

✔️ no performance regression detected

Full benchmark results
Benchmark suite Current: 3235bab Previous: 402c46f Ratio
getPubkeys - index2pubkey - req 1000 vs - 250000 vc 777.27 us/op 538.02 us/op 1.44
getPubkeys - validatorsArr - req 1000 vs - 250000 vc 44.736 us/op 46.888 us/op 0.95
BLS verify - blst-native 1.1708 ms/op 1.2840 ms/op 0.91
BLS verifyMultipleSignatures 3 - blst-native 2.4154 ms/op 2.5627 ms/op 0.94
BLS verifyMultipleSignatures 8 - blst-native 5.2044 ms/op 5.7667 ms/op 0.90
BLS verifyMultipleSignatures 32 - blst-native 18.420 ms/op 20.371 ms/op 0.90
BLS aggregatePubkeys 32 - blst-native 24.675 us/op 26.720 us/op 0.92
BLS aggregatePubkeys 128 - blst-native 96.739 us/op 104.01 us/op 0.93
getAttestationsForBlock 55.694 ms/op 60.285 ms/op 0.92
isKnown best case - 1 super set check 257.00 ns/op 283.00 ns/op 0.91
isKnown normal case - 2 super set checks 251.00 ns/op 276.00 ns/op 0.91
isKnown worse case - 16 super set checks 249.00 ns/op 272.00 ns/op 0.92
CheckpointStateCache - add get delete 4.9690 us/op 5.1070 us/op 0.97
validate gossip signedAggregateAndProof - struct 2.7666 ms/op 2.8112 ms/op 0.98
validate gossip attestation - struct 1.3129 ms/op 1.3523 ms/op 0.97
pickEth1Vote - no votes 1.2206 ms/op 1.2675 ms/op 0.96
pickEth1Vote - max votes 9.7555 ms/op 11.364 ms/op 0.86
pickEth1Vote - Eth1Data hashTreeRoot value x2048 8.7873 ms/op 9.3008 ms/op 0.94
pickEth1Vote - Eth1Data hashTreeRoot tree x2048 13.629 ms/op 19.063 ms/op 0.71
pickEth1Vote - Eth1Data fastSerialize value x2048 595.89 us/op 703.60 us/op 0.85
pickEth1Vote - Eth1Data fastSerialize tree x2048 7.1170 ms/op 8.4191 ms/op 0.85
bytes32 toHexString 486.00 ns/op 541.00 ns/op 0.90
bytes32 Buffer.toString(hex) 342.00 ns/op 360.00 ns/op 0.95
bytes32 Buffer.toString(hex) from Uint8Array 541.00 ns/op 571.00 ns/op 0.95
bytes32 Buffer.toString(hex) + 0x 341.00 ns/op 365.00 ns/op 0.93
Object access 1 prop 0.15600 ns/op 0.17000 ns/op 0.92
Map access 1 prop 0.15800 ns/op 0.16400 ns/op 0.96
Object get x1000 6.3150 ns/op 7.7710 ns/op 0.81
Map get x1000 0.53600 ns/op 0.62700 ns/op 0.85
Object set x1000 49.496 ns/op 54.890 ns/op 0.90
Map set x1000 42.119 ns/op 44.222 ns/op 0.95
Return object 10000 times 0.22750 ns/op 0.23740 ns/op 0.96
Throw Error 10000 times 4.0172 us/op 4.3994 us/op 0.91
fastMsgIdFn sha256 / 200 bytes 3.2870 us/op 3.4960 us/op 0.94
fastMsgIdFn h32 xxhash / 200 bytes 268.00 ns/op 285.00 ns/op 0.94
fastMsgIdFn h64 xxhash / 200 bytes 378.00 ns/op 403.00 ns/op 0.94
fastMsgIdFn sha256 / 1000 bytes 11.149 us/op 12.154 us/op 0.92
fastMsgIdFn h32 xxhash / 1000 bytes 396.00 ns/op 416.00 ns/op 0.95
fastMsgIdFn h64 xxhash / 1000 bytes 447.00 ns/op 480.00 ns/op 0.93
fastMsgIdFn sha256 / 10000 bytes 99.829 us/op 110.00 us/op 0.91
fastMsgIdFn h32 xxhash / 10000 bytes 1.8150 us/op 1.9050 us/op 0.95
fastMsgIdFn h64 xxhash / 10000 bytes 1.2800 us/op 1.3590 us/op 0.94
enrSubnets - fastDeserialize 64 bits 1.2290 us/op 1.4700 us/op 0.84
enrSubnets - ssz BitVector 64 bits 471.00 ns/op 528.00 ns/op 0.89
enrSubnets - fastDeserialize 4 bits 168.00 ns/op 187.00 ns/op 0.90
enrSubnets - ssz BitVector 4 bits 476.00 ns/op 531.00 ns/op 0.90
prioritizePeers score -10:0 att 32-0.1 sync 2-0 106.01 us/op 132.47 us/op 0.80
prioritizePeers score 0:0 att 32-0.25 sync 2-0.25 130.69 us/op 155.23 us/op 0.84
prioritizePeers score 0:0 att 32-0.5 sync 2-0.5 163.59 us/op 185.78 us/op 0.88
prioritizePeers score 0:0 att 64-0.75 sync 4-0.75 290.90 us/op 347.10 us/op 0.84
prioritizePeers score 0:0 att 64-1 sync 4-1 351.77 us/op 423.08 us/op 0.83
array of 16000 items push then shift 1.5757 us/op 1.8020 us/op 0.87
LinkedList of 16000 items push then shift 8.5260 ns/op 9.3190 ns/op 0.91
array of 16000 items push then pop 82.042 ns/op 103.91 ns/op 0.79
LinkedList of 16000 items push then pop 8.2590 ns/op 9.2920 ns/op 0.89
array of 24000 items push then shift 2.2783 us/op 2.5588 us/op 0.89
LinkedList of 24000 items push then shift 8.5810 ns/op 10.657 ns/op 0.81
array of 24000 items push then pop 76.865 ns/op 90.347 ns/op 0.85
LinkedList of 24000 items push then pop 8.1830 ns/op 9.1430 ns/op 0.90
intersect bitArray bitLen 8 12.800 ns/op 14.387 ns/op 0.89
intersect array and set length 8 74.018 ns/op 80.082 ns/op 0.92
intersect bitArray bitLen 128 42.229 ns/op 47.058 ns/op 0.90
intersect array and set length 128 1.0115 us/op 1.1052 us/op 0.92
Buffer.concat 32 items 2.8300 us/op 2.7820 us/op 1.02
Uint8Array.set 32 items 2.8690 us/op 3.3110 us/op 0.87
pass gossip attestations to forkchoice per slot 2.9006 ms/op 3.0591 ms/op 0.95
computeDeltas 3.2342 ms/op 3.6506 ms/op 0.89
computeProposerBoostScoreFromBalances 1.7616 ms/op 1.9103 ms/op 0.92
altair processAttestation - 250000 vs - 7PWei normalcase 2.1600 ms/op 2.5318 ms/op 0.85
altair processAttestation - 250000 vs - 7PWei worstcase 3.4561 ms/op 4.2942 ms/op 0.80
altair processAttestation - setStatus - 1/6 committees join 138.09 us/op 150.22 us/op 0.92
altair processAttestation - setStatus - 1/3 committees join 265.03 us/op 297.90 us/op 0.89
altair processAttestation - setStatus - 1/2 committees join 360.14 us/op 396.41 us/op 0.91
altair processAttestation - setStatus - 2/3 committees join 448.65 us/op 495.11 us/op 0.91
altair processAttestation - setStatus - 4/5 committees join 646.60 us/op 697.61 us/op 0.93
altair processAttestation - setStatus - 100% committees join 738.62 us/op 802.53 us/op 0.92
altair processBlock - 250000 vs - 7PWei normalcase 16.320 ms/op 20.020 ms/op 0.82
altair processBlock - 250000 vs - 7PWei normalcase hashState 27.886 ms/op 29.547 ms/op 0.94
altair processBlock - 250000 vs - 7PWei worstcase 44.800 ms/op 61.079 ms/op 0.73
altair processBlock - 250000 vs - 7PWei worstcase hashState 65.193 ms/op 82.583 ms/op 0.79
phase0 processBlock - 250000 vs - 7PWei normalcase 2.0044 ms/op 1.9907 ms/op 1.01
phase0 processBlock - 250000 vs - 7PWei worstcase 27.562 ms/op 29.550 ms/op 0.93
altair processEth1Data - 250000 vs - 7PWei normalcase 463.86 us/op 491.20 us/op 0.94
vc - 250000 eb 1 eth1 1 we 0 wn 0 - smpl 15 6.6730 us/op 6.6270 us/op 1.01
vc - 250000 eb 0.95 eth1 0.1 we 0.05 wn 0 - smpl 219 19.337 us/op 32.558 us/op 0.59
vc - 250000 eb 0.95 eth1 0.3 we 0.05 wn 0 - smpl 42 8.0400 us/op 9.8520 us/op 0.82
vc - 250000 eb 0.95 eth1 0.7 we 0.05 wn 0 - smpl 18 6.2340 us/op 7.9560 us/op 0.78
vc - 250000 eb 0.1 eth1 0.1 we 0 wn 0 - smpl 1020 74.324 us/op 106.86 us/op 0.70
vc - 250000 eb 0.03 eth1 0.03 we 0 wn 0 - smpl 11777 616.73 us/op 1.0674 ms/op 0.58
vc - 250000 eb 0.01 eth1 0.01 we 0 wn 0 - smpl 16384 874.08 us/op 1.3692 ms/op 0.64
vc - 250000 eb 0 eth1 0 we 0 wn 0 - smpl 16384 847.26 us/op 1.6843 ms/op 0.50
vc - 250000 eb 0 eth1 0 we 0 wn 0 nocache - smpl 16384 2.2464 ms/op 2.2918 ms/op 0.98
vc - 250000 eb 0 eth1 1 we 0 wn 0 - smpl 16384 1.5647 ms/op 1.9564 ms/op 0.80
vc - 250000 eb 0 eth1 1 we 0 wn 0 nocache - smpl 16384 3.7052 ms/op 3.9485 ms/op 0.94
Tree 40 250000 create 284.37 ms/op 362.63 ms/op 0.78
Tree 40 250000 get(125000) 187.82 ns/op 205.38 ns/op 0.91
Tree 40 250000 set(125000) 846.08 ns/op 1.0223 us/op 0.83
Tree 40 250000 toArray() 17.479 ms/op 23.395 ms/op 0.75
Tree 40 250000 iterate all - toArray() + loop 17.847 ms/op 23.508 ms/op 0.76
Tree 40 250000 iterate all - get(i) 64.618 ms/op 79.218 ms/op 0.82
MutableVector 250000 create 9.5416 ms/op 11.464 ms/op 0.83
MutableVector 250000 get(125000) 6.0980 ns/op 7.3000 ns/op 0.84
MutableVector 250000 set(125000) 246.02 ns/op 291.12 ns/op 0.85
MutableVector 250000 toArray() 2.6526 ms/op 2.9808 ms/op 0.89
MutableVector 250000 iterate all - toArray() + loop 2.6916 ms/op 4.0881 ms/op 0.66
MutableVector 250000 iterate all - get(i) 1.4889 ms/op 1.7181 ms/op 0.87
Array 250000 create 2.5029 ms/op 3.1401 ms/op 0.80
Array 250000 clone - spread 1.2409 ms/op 1.1597 ms/op 1.07
Array 250000 get(125000) 0.57900 ns/op 0.57100 ns/op 1.01
Array 250000 set(125000) 0.66400 ns/op 0.65400 ns/op 1.02
Array 250000 iterate all - loop 80.529 us/op 86.237 us/op 0.93
effectiveBalanceIncrements clone Uint8Array 300000 28.846 us/op 36.489 us/op 0.79
effectiveBalanceIncrements clone MutableVector 300000 390.00 ns/op 357.00 ns/op 1.09
effectiveBalanceIncrements rw all Uint8Array 300000 164.37 us/op 190.30 us/op 0.86
effectiveBalanceIncrements rw all MutableVector 300000 81.517 ms/op 84.220 ms/op 0.97
phase0 afterProcessEpoch - 250000 vs - 7PWei 110.78 ms/op 125.87 ms/op 0.88
phase0 beforeProcessEpoch - 250000 vs - 7PWei 32.355 ms/op 45.726 ms/op 0.71
altair processEpoch - mainnet_e81889 296.12 ms/op 354.80 ms/op 0.83
mainnet_e81889 - altair beforeProcessEpoch 49.527 ms/op 70.077 ms/op 0.71
mainnet_e81889 - altair processJustificationAndFinalization 19.821 us/op 18.386 us/op 1.08
mainnet_e81889 - altair processInactivityUpdates 5.3264 ms/op 5.9956 ms/op 0.89
mainnet_e81889 - altair processRewardsAndPenalties 71.323 ms/op 73.829 ms/op 0.97
mainnet_e81889 - altair processRegistryUpdates 2.4900 us/op 3.3790 us/op 0.74
mainnet_e81889 - altair processSlashings 535.00 ns/op 584.00 ns/op 0.92
mainnet_e81889 - altair processEth1DataReset 563.00 ns/op 659.00 ns/op 0.85
mainnet_e81889 - altair processEffectiveBalanceUpdates 1.2253 ms/op 1.5996 ms/op 0.77
mainnet_e81889 - altair processSlashingsReset 4.4730 us/op 4.9610 us/op 0.90
mainnet_e81889 - altair processRandaoMixesReset 4.2820 us/op 9.9240 us/op 0.43
mainnet_e81889 - altair processHistoricalRootsUpdate 609.00 ns/op 1.6410 us/op 0.37
mainnet_e81889 - altair processParticipationFlagUpdates 2.4020 us/op 2.9730 us/op 0.81
mainnet_e81889 - altair processSyncCommitteeUpdates 636.00 ns/op 1.0110 us/op 0.63
mainnet_e81889 - altair afterProcessEpoch 116.36 ms/op 138.14 ms/op 0.84
phase0 processEpoch - mainnet_e58758 307.30 ms/op 420.21 ms/op 0.73
mainnet_e58758 - phase0 beforeProcessEpoch 121.11 ms/op 170.01 ms/op 0.71
mainnet_e58758 - phase0 processJustificationAndFinalization 17.326 us/op 17.118 us/op 1.01
mainnet_e58758 - phase0 processRewardsAndPenalties 55.022 ms/op 77.875 ms/op 0.71
mainnet_e58758 - phase0 processRegistryUpdates 8.1620 us/op 12.271 us/op 0.67
mainnet_e58758 - phase0 processSlashings 528.00 ns/op 943.00 ns/op 0.56
mainnet_e58758 - phase0 processEth1DataReset 542.00 ns/op 940.00 ns/op 0.58
mainnet_e58758 - phase0 processEffectiveBalanceUpdates 943.45 us/op 1.8743 ms/op 0.50
mainnet_e58758 - phase0 processSlashingsReset 3.2250 us/op 6.1960 us/op 0.52
mainnet_e58758 - phase0 processRandaoMixesReset 3.9930 us/op 6.7240 us/op 0.59
mainnet_e58758 - phase0 processHistoricalRootsUpdate 587.00 ns/op 1.0680 us/op 0.55
mainnet_e58758 - phase0 processParticipationRecordUpdates 3.8250 us/op 5.4060 us/op 0.71
mainnet_e58758 - phase0 afterProcessEpoch 94.013 ms/op 103.73 ms/op 0.91
phase0 processEffectiveBalanceUpdates - 250000 normalcase 1.1930 ms/op 2.0270 ms/op 0.59
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5 1.4323 ms/op 2.7191 ms/op 0.53
altair processInactivityUpdates - 250000 normalcase 21.042 ms/op 32.460 ms/op 0.65
altair processInactivityUpdates - 250000 worstcase 23.093 ms/op 31.045 ms/op 0.74
phase0 processRegistryUpdates - 250000 normalcase 6.7930 us/op 10.862 us/op 0.63
phase0 processRegistryUpdates - 250000 badcase_full_deposits 243.16 us/op 313.32 us/op 0.78
phase0 processRegistryUpdates - 250000 worstcase 0.5 114.90 ms/op 149.98 ms/op 0.77
altair processRewardsAndPenalties - 250000 normalcase 49.789 ms/op 73.676 ms/op 0.68
altair processRewardsAndPenalties - 250000 worstcase 56.595 ms/op 77.709 ms/op 0.73
phase0 getAttestationDeltas - 250000 normalcase 6.3580 ms/op 6.9273 ms/op 0.92
phase0 getAttestationDeltas - 250000 worstcase 6.5726 ms/op 7.2137 ms/op 0.91
phase0 processSlashings - 250000 worstcase 3.4147 ms/op 3.7554 ms/op 0.91
altair processSyncCommitteeUpdates - 250000 176.58 ms/op 177.67 ms/op 0.99
BeaconState.hashTreeRoot - No change 279.00 ns/op 275.00 ns/op 1.01
BeaconState.hashTreeRoot - 1 full validator 49.765 us/op 74.442 us/op 0.67
BeaconState.hashTreeRoot - 32 full validator 504.71 us/op 620.91 us/op 0.81
BeaconState.hashTreeRoot - 512 full validator 5.1026 ms/op 5.2543 ms/op 0.97
BeaconState.hashTreeRoot - 1 validator.effectiveBalance 65.685 us/op 74.045 us/op 0.89
BeaconState.hashTreeRoot - 32 validator.effectiveBalance 852.90 us/op 953.91 us/op 0.89
BeaconState.hashTreeRoot - 512 validator.effectiveBalance 11.108 ms/op 14.303 ms/op 0.78
BeaconState.hashTreeRoot - 1 balances 47.956 us/op 52.647 us/op 0.91
BeaconState.hashTreeRoot - 32 balances 438.52 us/op 542.19 us/op 0.81
BeaconState.hashTreeRoot - 512 balances 4.2212 ms/op 4.9071 ms/op 0.86
BeaconState.hashTreeRoot - 250000 balances 75.789 ms/op 81.205 ms/op 0.93
aggregationBits - 2048 els - zipIndexesInBitList 16.237 us/op 16.642 us/op 0.98
regular array get 100000 times 41.097 us/op 32.763 us/op 1.25
wrappedArray get 100000 times 31.669 us/op 33.872 us/op 0.93
arrayWithProxy get 100000 times 15.367 ms/op 16.357 ms/op 0.94
ssz.Root.equals 565.00 ns/op 573.00 ns/op 0.99
byteArrayEquals 512.00 ns/op 571.00 ns/op 0.90
shuffle list - 16384 els 6.5846 ms/op 7.1891 ms/op 0.92
shuffle list - 250000 els 96.710 ms/op 105.30 ms/op 0.92
processSlot - 1 slots 8.2710 us/op 9.4630 us/op 0.87
processSlot - 32 slots 1.2818 ms/op 1.4061 ms/op 0.91
getEffectiveBalanceIncrementsZeroInactive - 250000 vs - 7PWei 32.641 ms/op 41.560 ms/op 0.79
getCommitteeAssignments - req 1 vs - 250000 vc 2.9125 ms/op 3.1148 ms/op 0.94
getCommitteeAssignments - req 100 vs - 250000 vc 4.1262 ms/op 4.3136 ms/op 0.96
getCommitteeAssignments - req 1000 vs - 250000 vc 4.4643 ms/op 4.7387 ms/op 0.94
RootCache.getBlockRootAtSlot - 250000 vs - 7PWei 4.4700 ns/op 5.3000 ns/op 0.84
state getBlockRootAtSlot - 250000 vs - 7PWei 571.83 ns/op 943.93 ns/op 0.61
computeProposers - vc 250000 10.581 ms/op 10.583 ms/op 1.00
computeEpochShuffling - vc 250000 104.75 ms/op 104.16 ms/op 1.01
getNextSyncCommittee - vc 250000 182.56 ms/op 188.50 ms/op 0.97
computeSigningRoot for AttestationData 14.006 us/op 13.349 us/op 1.05
hash AttestationData serialized data then Buffer.toString(base64) 2.5167 us/op 2.4202 us/op 1.04
toHexString serialized data 1.1576 us/op 1.0795 us/op 1.07
Buffer.toString(base64) 339.44 ns/op 320.34 ns/op 1.06

by benchmarkbot/action

twoeths
twoeths reviewed May 22, 2023
View reviewed changes
@nflaig nflaig force-pushed the nflaig/handle-attestation-errors branch from bc88bdd to 484947c Compare May 22, 2023 10:48
@nflaig nflaig merged commit 186a5e8 into unstable May 23, 2023
@nflaig nflaig deleted the nflaig/handle-attestation-errors branch May 23, 2023 08:12
@nflaig nflaig mentioned this pull request May 25, 2023
Closed
@wemeetagain
Copy link
Member

wemeetagain commented Jun 22, 2023

🎉 This PR is included in v1.9.0 🎉

@nflaig nflaig mentioned this pull request Jul 14, 2023
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@twoeths twoeths twoeths approved these changes

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

4 participants

@nflaig @wemeetagain @twoeths