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.

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

fix(validator): log api errors as warn if node is syncing #5467

Merged
merged 2 commits into from
May 8, 2023

Conversation

nflaig
Copy link
Member

@nflaig nflaig commented May 5, 2023

Motivation

Logs mentioned in #5359 (comment) should not be shown as errors on the VC if beacon node is syncing.

Description

HttpError is not thrown anymore, instead API client returns a ApiClientResponse

if (err instanceof HttpError) {
return {ok: false, error: {code: err.status, message: err.message, operationId: routeId}} as ReturnType<
Api[keyof Api]
>;
}

which will be handled by ApiError.assert and if not ok, will throw ApiError

static assert(res: ApiClientResponse, message?: string): asserts res is ApiClientSuccessResponse<any, unknown> {
if (!res.ok) {
throw new ApiError([message, res.error.message].join(" - "), res.error.code, res.error.operationId);
}
}

Before

Error: Error on getProposerDuties - Service Unavailable: Node is syncing - headSlot 5529152 currentSlot 5529417
    at Function.assert (file:///usr/app/packages/api/src/utils/client/httpClient.ts:44:13)
    at BlockDutiesService.pollBeaconProposers (file:///usr/app/packages/validator/src/services/blockDuties.ts:155:14)
    at processTicksAndRejections (node:internal/process/task_queues:95:5)
    at BlockDutiesService.pollBeaconProposersAndNotify (file:///usr/app/packages/validator/src/services/blockDuties.ts:129:5)
    at BlockDutiesService.runBlockDutiesTask (file:///usr/app/packages/validator/src/services/blockDuties.ts:87:9)
    at Clock.runAtMostEvery (file:///usr/app/packages/validator/src/util/clock.ts:96:7)

After

warn: Node is syncing - Error on getProposerDuties - Service Unavailable: Node is syncing - headSlot 5564286 currentSlot 5565452
warn: Node is syncing - Error on getProposerDuties - Service Unavailable: Node is syncing - headSlot 5564383 currentSlot 5565453
warn: Node is syncing - Error on getProposerDuties - Service Unavailable: Node is syncing - headSlot 5564479 currentSlot 5565454

@nflaig nflaig requested a review from a team as a code owner May 5, 2023 13:44
@nflaig
Copy link
Member Author

nflaig commented May 5, 2023

considering the log level if node is syncing, should we use warn instead of info? As this log is quite expected I am guessing we are correct to use info here

@github-actions
Copy link
Contributor

github-actions bot commented May 5, 2023

Performance Report

✔️ no performance regression detected

🚀🚀 Significant benchmark improvement detected

Benchmark suite Current: ce3f2b6 Previous: cd7709b Ratio
vc - 250000 eb 0 eth1 1 we 0 wn 0 nocache - smpl 16384 3.8365 ms/op 11.668 ms/op 0.33
Full benchmark results
Benchmark suite Current: ce3f2b6 Previous: cd7709b Ratio
getPubkeys - index2pubkey - req 1000 vs - 250000 vc 1.0426 ms/op 589.85 us/op 1.77
getPubkeys - validatorsArr - req 1000 vs - 250000 vc 88.945 us/op 55.395 us/op 1.61
BLS verify - blst-native 1.9416 ms/op 1.2645 ms/op 1.54
BLS verifyMultipleSignatures 3 - blst-native 3.9850 ms/op 2.5831 ms/op 1.54
BLS verifyMultipleSignatures 8 - blst-native 8.3678 ms/op 5.5505 ms/op 1.51
BLS verifyMultipleSignatures 32 - blst-native 21.254 ms/op 20.153 ms/op 1.05
BLS aggregatePubkeys 32 - blst-native 28.231 us/op 26.712 us/op 1.06
BLS aggregatePubkeys 128 - blst-native 111.00 us/op 104.59 us/op 1.06
getAttestationsForBlock 88.043 ms/op 69.993 ms/op 1.26
isKnown best case - 1 super set check 290.00 ns/op 278.00 ns/op 1.04
isKnown normal case - 2 super set checks 275.00 ns/op 273.00 ns/op 1.01
isKnown worse case - 16 super set checks 266.00 ns/op 271.00 ns/op 0.98
CheckpointStateCache - add get delete 5.6890 us/op 6.1620 us/op 0.92
validate gossip signedAggregateAndProof - struct 2.9185 ms/op 2.9104 ms/op 1.00
validate gossip attestation - struct 1.3862 ms/op 1.4393 ms/op 0.96
pickEth1Vote - no votes 1.4422 ms/op 1.4342 ms/op 1.01
pickEth1Vote - max votes 10.972 ms/op 11.261 ms/op 0.97
pickEth1Vote - Eth1Data hashTreeRoot value x2048 9.9231 ms/op 9.4406 ms/op 1.05
pickEth1Vote - Eth1Data hashTreeRoot tree x2048 16.043 ms/op 16.074 ms/op 1.00
pickEth1Vote - Eth1Data fastSerialize value x2048 785.68 us/op 676.67 us/op 1.16
pickEth1Vote - Eth1Data fastSerialize tree x2048 5.7669 ms/op 6.5080 ms/op 0.89
bytes32 toHexString 694.00 ns/op 582.00 ns/op 1.19
bytes32 Buffer.toString(hex) 446.00 ns/op 392.00 ns/op 1.14
bytes32 Buffer.toString(hex) from Uint8Array 687.00 ns/op 586.00 ns/op 1.17
bytes32 Buffer.toString(hex) + 0x 449.00 ns/op 367.00 ns/op 1.22
Object access 1 prop 0.22000 ns/op 0.18000 ns/op 1.22
Map access 1 prop 0.21100 ns/op 0.16800 ns/op 1.26
Object get x1000 7.6080 ns/op 6.9350 ns/op 1.10
Map get x1000 0.67900 ns/op 0.64300 ns/op 1.06
Object set x1000 63.233 ns/op 59.947 ns/op 1.05
Map set x1000 51.904 ns/op 48.494 ns/op 1.07
Return object 10000 times 0.28200 ns/op 0.24180 ns/op 1.17
Throw Error 10000 times 4.7890 us/op 4.3851 us/op 1.09
fastMsgIdFn sha256 / 200 bytes 3.7990 us/op 3.5580 us/op 1.07
fastMsgIdFn h32 xxhash / 200 bytes 329.00 ns/op 288.00 ns/op 1.14
fastMsgIdFn h64 xxhash / 200 bytes 495.00 ns/op 406.00 ns/op 1.22
fastMsgIdFn sha256 / 1000 bytes 17.366 us/op 11.868 us/op 1.46
fastMsgIdFn h32 xxhash / 1000 bytes 820.00 ns/op 408.00 ns/op 2.01
fastMsgIdFn h64 xxhash / 1000 bytes 607.00 ns/op 469.00 ns/op 1.29
fastMsgIdFn sha256 / 10000 bytes 111.33 us/op 103.60 us/op 1.07
fastMsgIdFn h32 xxhash / 10000 bytes 2.5240 us/op 1.8890 us/op 1.34
fastMsgIdFn h64 xxhash / 10000 bytes 1.6990 us/op 1.3520 us/op 1.26
enrSubnets - fastDeserialize 64 bits 1.8390 us/op 1.3260 us/op 1.39
enrSubnets - ssz BitVector 64 bits 756.00 ns/op 504.00 ns/op 1.50
enrSubnets - fastDeserialize 4 bits 261.00 ns/op 176.00 ns/op 1.48
enrSubnets - ssz BitVector 4 bits 748.00 ns/op 500.00 ns/op 1.50
prioritizePeers score -10:0 att 32-0.1 sync 2-0 176.16 us/op 111.45 us/op 1.58
prioritizePeers score 0:0 att 32-0.25 sync 2-0.25 239.38 us/op 137.75 us/op 1.74
prioritizePeers score 0:0 att 32-0.5 sync 2-0.5 297.70 us/op 168.05 us/op 1.77
prioritizePeers score 0:0 att 64-0.75 sync 4-0.75 451.78 us/op 304.85 us/op 1.48
prioritizePeers score 0:0 att 64-1 sync 4-1 551.34 us/op 405.70 us/op 1.36
array of 16000 items push then shift 1.8604 us/op 1.6712 us/op 1.11
LinkedList of 16000 items push then shift 11.037 ns/op 9.0020 ns/op 1.23
array of 16000 items push then pop 131.09 ns/op 115.20 ns/op 1.14
LinkedList of 16000 items push then pop 9.9400 ns/op 8.9440 ns/op 1.11
array of 24000 items push then shift 2.8502 us/op 2.4629 us/op 1.16
LinkedList of 24000 items push then shift 13.915 ns/op 9.3630 ns/op 1.49
array of 24000 items push then pop 131.50 ns/op 83.177 ns/op 1.58
LinkedList of 24000 items push then pop 12.418 ns/op 8.9220 ns/op 1.39
intersect bitArray bitLen 8 17.317 ns/op 13.815 ns/op 1.25
intersect array and set length 8 132.64 ns/op 87.473 ns/op 1.52
intersect bitArray bitLen 128 57.024 ns/op 46.810 ns/op 1.22
intersect array and set length 128 1.5587 us/op 1.2897 us/op 1.21
Buffer.concat 32 items 3.4560 us/op 2.8520 us/op 1.21
Uint8Array.set 32 items 3.0510 us/op 2.2270 us/op 1.37
pass gossip attestations to forkchoice per slot 3.0547 ms/op 2.8777 ms/op 1.06
computeDeltas 3.0355 ms/op 2.8828 ms/op 1.05
computeProposerBoostScoreFromBalances 1.7531 ms/op 1.8322 ms/op 0.96
altair processAttestation - 250000 vs - 7PWei normalcase 2.0278 ms/op 2.3476 ms/op 0.86
altair processAttestation - 250000 vs - 7PWei worstcase 3.2676 ms/op 3.4458 ms/op 0.95
altair processAttestation - setStatus - 1/6 committees join 135.16 us/op 142.09 us/op 0.95
altair processAttestation - setStatus - 1/3 committees join 267.97 us/op 283.78 us/op 0.94
altair processAttestation - setStatus - 1/2 committees join 356.02 us/op 375.03 us/op 0.95
altair processAttestation - setStatus - 2/3 committees join 444.51 us/op 472.40 us/op 0.94
altair processAttestation - setStatus - 4/5 committees join 627.35 us/op 647.87 us/op 0.97
altair processAttestation - setStatus - 100% committees join 728.52 us/op 780.87 us/op 0.93
altair processBlock - 250000 vs - 7PWei normalcase 16.029 ms/op 16.465 ms/op 0.97
altair processBlock - 250000 vs - 7PWei normalcase hashState 27.141 ms/op 28.301 ms/op 0.96
altair processBlock - 250000 vs - 7PWei worstcase 55.109 ms/op 47.864 ms/op 1.15
altair processBlock - 250000 vs - 7PWei worstcase hashState 70.031 ms/op 65.486 ms/op 1.07
phase0 processBlock - 250000 vs - 7PWei normalcase 1.9548 ms/op 2.4503 ms/op 0.80
phase0 processBlock - 250000 vs - 7PWei worstcase 28.108 ms/op 38.638 ms/op 0.73
altair processEth1Data - 250000 vs - 7PWei normalcase 468.06 us/op 705.42 us/op 0.66
vc - 250000 eb 1 eth1 1 we 0 wn 0 - smpl 15 7.6870 us/op 16.722 us/op 0.46
vc - 250000 eb 0.95 eth1 0.1 we 0.05 wn 0 - smpl 219 22.389 us/op 42.126 us/op 0.53
vc - 250000 eb 0.95 eth1 0.3 we 0.05 wn 0 - smpl 42 8.9660 us/op 19.398 us/op 0.46
vc - 250000 eb 0.95 eth1 0.7 we 0.05 wn 0 - smpl 18 6.6590 us/op 17.986 us/op 0.37
vc - 250000 eb 0.1 eth1 0.1 we 0 wn 0 - smpl 1020 93.215 us/op 142.42 us/op 0.65
vc - 250000 eb 0.03 eth1 0.03 we 0 wn 0 - smpl 11777 640.42 us/op 1.2938 ms/op 0.49
vc - 250000 eb 0.01 eth1 0.01 we 0 wn 0 - smpl 16384 895.94 us/op 1.7401 ms/op 0.51
vc - 250000 eb 0 eth1 0 we 0 wn 0 - smpl 16384 843.22 us/op 1.6479 ms/op 0.51
vc - 250000 eb 0 eth1 0 we 0 wn 0 nocache - smpl 16384 2.3258 ms/op 6.8493 ms/op 0.34
vc - 250000 eb 0 eth1 1 we 0 wn 0 - smpl 16384 1.5586 ms/op 3.2700 ms/op 0.48
vc - 250000 eb 0 eth1 1 we 0 wn 0 nocache - smpl 16384 3.8365 ms/op 11.668 ms/op 0.33
Tree 40 250000 create 309.92 ms/op 980.75 ms/op 0.32
Tree 40 250000 get(125000) 180.93 ns/op 234.80 ns/op 0.77
Tree 40 250000 set(125000) 962.82 ns/op 2.9822 us/op 0.32
Tree 40 250000 toArray() 17.175 ms/op 31.974 ms/op 0.54
Tree 40 250000 iterate all - toArray() + loop 17.451 ms/op 31.002 ms/op 0.56
Tree 40 250000 iterate all - get(i) 67.092 ms/op 94.191 ms/op 0.71
MutableVector 250000 create 10.579 ms/op 19.218 ms/op 0.55
MutableVector 250000 get(125000) 6.3550 ns/op 13.312 ns/op 0.48
MutableVector 250000 set(125000) 259.98 ns/op 842.34 ns/op 0.31
MutableVector 250000 toArray() 2.7495 ms/op 5.7045 ms/op 0.48
MutableVector 250000 iterate all - toArray() + loop 2.8706 ms/op 5.3498 ms/op 0.54
MutableVector 250000 iterate all - get(i) 1.4931 ms/op 1.8451 ms/op 0.81
Array 250000 create 2.4387 ms/op 4.8020 ms/op 0.51
Array 250000 clone - spread 1.2111 ms/op 1.8345 ms/op 0.66
Array 250000 get(125000) 0.60300 ns/op 1.5200 ns/op 0.40
Array 250000 set(125000) 0.67700 ns/op 1.6240 ns/op 0.42
Array 250000 iterate all - loop 103.15 us/op 162.16 us/op 0.64
effectiveBalanceIncrements clone Uint8Array 300000 26.433 us/op 72.307 us/op 0.37
effectiveBalanceIncrements clone MutableVector 300000 397.00 ns/op 980.00 ns/op 0.41
effectiveBalanceIncrements rw all Uint8Array 300000 165.71 us/op 200.26 us/op 0.83
effectiveBalanceIncrements rw all MutableVector 300000 84.382 ms/op 188.54 ms/op 0.45
phase0 afterProcessEpoch - 250000 vs - 7PWei 117.59 ms/op 152.09 ms/op 0.77
phase0 beforeProcessEpoch - 250000 vs - 7PWei 36.451 ms/op 46.603 ms/op 0.78
altair processEpoch - mainnet_e81889 293.33 ms/op 307.66 ms/op 0.95
mainnet_e81889 - altair beforeProcessEpoch 63.995 ms/op 64.311 ms/op 1.00
mainnet_e81889 - altair processJustificationAndFinalization 17.219 us/op 18.106 us/op 0.95
mainnet_e81889 - altair processInactivityUpdates 4.7559 ms/op 5.6111 ms/op 0.85
mainnet_e81889 - altair processRewardsAndPenalties 51.121 ms/op 49.254 ms/op 1.04
mainnet_e81889 - altair processRegistryUpdates 2.2380 us/op 2.4090 us/op 0.93
mainnet_e81889 - altair processSlashings 502.00 ns/op 581.00 ns/op 0.86
mainnet_e81889 - altair processEth1DataReset 540.00 ns/op 770.00 ns/op 0.70
mainnet_e81889 - altair processEffectiveBalanceUpdates 1.1930 ms/op 1.2896 ms/op 0.93
mainnet_e81889 - altair processSlashingsReset 5.2120 us/op 4.4230 us/op 1.18
mainnet_e81889 - altair processRandaoMixesReset 4.6250 us/op 5.2400 us/op 0.88
mainnet_e81889 - altair processHistoricalRootsUpdate 610.00 ns/op 677.00 ns/op 0.90
mainnet_e81889 - altair processParticipationFlagUpdates 2.4070 us/op 2.7450 us/op 0.88
mainnet_e81889 - altair processSyncCommitteeUpdates 602.00 ns/op 1.1010 us/op 0.55
mainnet_e81889 - altair afterProcessEpoch 113.42 ms/op 132.29 ms/op 0.86
phase0 processEpoch - mainnet_e58758 311.35 ms/op 364.62 ms/op 0.85
mainnet_e58758 - phase0 beforeProcessEpoch 120.70 ms/op 135.23 ms/op 0.89
mainnet_e58758 - phase0 processJustificationAndFinalization 17.911 us/op 21.308 us/op 0.84
mainnet_e58758 - phase0 processRewardsAndPenalties 54.167 ms/op 44.243 ms/op 1.22
mainnet_e58758 - phase0 processRegistryUpdates 7.5720 us/op 9.8200 us/op 0.77
mainnet_e58758 - phase0 processSlashings 540.00 ns/op 1.0800 us/op 0.50
mainnet_e58758 - phase0 processEth1DataReset 568.00 ns/op 1.2180 us/op 0.47
mainnet_e58758 - phase0 processEffectiveBalanceUpdates 965.09 us/op 1.1617 ms/op 0.83
mainnet_e58758 - phase0 processSlashingsReset 5.9960 us/op 3.8930 us/op 1.54
mainnet_e58758 - phase0 processRandaoMixesReset 4.7220 us/op 4.5470 us/op 1.04
mainnet_e58758 - phase0 processHistoricalRootsUpdate 655.00 ns/op 747.00 ns/op 0.88
mainnet_e58758 - phase0 processParticipationRecordUpdates 3.9620 us/op 4.8180 us/op 0.82
mainnet_e58758 - phase0 afterProcessEpoch 94.575 ms/op 104.97 ms/op 0.90
phase0 processEffectiveBalanceUpdates - 250000 normalcase 1.1952 ms/op 1.6699 ms/op 0.72
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5 1.4779 ms/op 1.5340 ms/op 0.96
altair processInactivityUpdates - 250000 normalcase 20.505 ms/op 27.917 ms/op 0.73
altair processInactivityUpdates - 250000 worstcase 21.609 ms/op 28.324 ms/op 0.76
phase0 processRegistryUpdates - 250000 normalcase 6.3150 us/op 7.9190 us/op 0.80
phase0 processRegistryUpdates - 250000 badcase_full_deposits 270.60 us/op 302.53 us/op 0.89
phase0 processRegistryUpdates - 250000 worstcase 0.5 120.86 ms/op 132.19 ms/op 0.91
altair processRewardsAndPenalties - 250000 normalcase 57.639 ms/op 65.881 ms/op 0.87
altair processRewardsAndPenalties - 250000 worstcase 51.666 ms/op 71.311 ms/op 0.72
phase0 getAttestationDeltas - 250000 normalcase 6.4897 ms/op 7.6207 ms/op 0.85
phase0 getAttestationDeltas - 250000 worstcase 6.6737 ms/op 7.1272 ms/op 0.94
phase0 processSlashings - 250000 worstcase 3.5220 ms/op 3.5158 ms/op 1.00
altair processSyncCommitteeUpdates - 250000 167.71 ms/op 188.80 ms/op 0.89
BeaconState.hashTreeRoot - No change 254.00 ns/op 312.00 ns/op 0.81
BeaconState.hashTreeRoot - 1 full validator 50.596 us/op 59.343 us/op 0.85
BeaconState.hashTreeRoot - 32 full validator 505.22 us/op 539.81 us/op 0.94
BeaconState.hashTreeRoot - 512 full validator 5.6918 ms/op 5.9564 ms/op 0.96
BeaconState.hashTreeRoot - 1 validator.effectiveBalance 64.284 us/op 87.060 us/op 0.74
BeaconState.hashTreeRoot - 32 validator.effectiveBalance 866.76 us/op 999.41 us/op 0.87
BeaconState.hashTreeRoot - 512 validator.effectiveBalance 11.097 ms/op 13.156 ms/op 0.84
BeaconState.hashTreeRoot - 1 balances 48.126 us/op 54.130 us/op 0.89
BeaconState.hashTreeRoot - 32 balances 444.02 us/op 484.25 us/op 0.92
BeaconState.hashTreeRoot - 512 balances 4.3339 ms/op 4.8370 ms/op 0.90
BeaconState.hashTreeRoot - 250000 balances 75.020 ms/op 71.909 ms/op 1.04
aggregationBits - 2048 els - zipIndexesInBitList 16.889 us/op 17.899 us/op 0.94
regular array get 100000 times 32.336 us/op 35.990 us/op 0.90
wrappedArray get 100000 times 32.334 us/op 34.759 us/op 0.93
arrayWithProxy get 100000 times 15.669 ms/op 18.003 ms/op 0.87
ssz.Root.equals 544.00 ns/op 614.00 ns/op 0.89
byteArrayEquals 537.00 ns/op 611.00 ns/op 0.88
shuffle list - 16384 els 6.8314 ms/op 7.4582 ms/op 0.92
shuffle list - 250000 els 98.875 ms/op 110.23 ms/op 0.90
processSlot - 1 slots 8.0040 us/op 9.4770 us/op 0.84
processSlot - 32 slots 1.2591 ms/op 1.4583 ms/op 0.86
getEffectiveBalanceIncrementsZeroInactive - 250000 vs - 7PWei 33.262 ms/op 39.114 ms/op 0.85
getCommitteeAssignments - req 1 vs - 250000 vc 2.8782 ms/op 3.1261 ms/op 0.92
getCommitteeAssignments - req 100 vs - 250000 vc 4.0689 ms/op 4.3512 ms/op 0.94
getCommitteeAssignments - req 1000 vs - 250000 vc 4.4209 ms/op 4.7676 ms/op 0.93
RootCache.getBlockRootAtSlot - 250000 vs - 7PWei 4.5100 ns/op 5.4600 ns/op 0.83
state getBlockRootAtSlot - 250000 vs - 7PWei 770.79 ns/op 684.20 ns/op 1.13
computeProposers - vc 250000 10.481 ms/op 12.765 ms/op 0.82
computeEpochShuffling - vc 250000 101.45 ms/op 107.18 ms/op 0.95
getNextSyncCommittee - vc 250000 173.73 ms/op 196.09 ms/op 0.89
computeSigningRoot for AttestationData 13.137 us/op 14.698 us/op 0.89
hash AttestationData serialized data then Buffer.toString(base64) 2.4708 us/op 2.6199 us/op 0.94
toHexString serialized data 1.0835 us/op 1.3582 us/op 0.80
Buffer.toString(base64) 318.14 ns/op 379.87 ns/op 0.84

by benchmarkbot/action

@nflaig
Copy link
Member Author

nflaig commented May 5, 2023

considering comments such as #4977 (comment), maybe we want to log "Node is syncing" as warn

@wemeetagain
Copy link
Member

IMO a warn makes sense here. Once the node is synced, any "Node is syncing" message is likely not desired. Good to show a yellow light in that case.

@nflaig nflaig force-pushed the nflaig/fix-node-is-syncing-log branch from 913a51d to b28d5a9 Compare May 5, 2023 16:05
@nflaig nflaig changed the title fix(validator): only log info message if node is syncing fix(validator): only log warning if beacon node is syncing May 5, 2023
@nflaig nflaig changed the title fix(validator): only log warning if beacon node is syncing fix(validator): only log warnings if beacon node is syncing May 5, 2023
@nflaig nflaig changed the title fix(validator): only log warnings if beacon node is syncing fix(validator): log errors as warn if beacon node is syncing May 5, 2023
@nflaig nflaig changed the title fix(validator): log errors as warn if beacon node is syncing fix(validator): log http errors as warn if node is syncing May 5, 2023
@nflaig nflaig changed the title fix(validator): log http errors as warn if node is syncing fix(validator): log api errors as warn if node is syncing May 5, 2023
@nflaig nflaig merged commit a14bf0d into unstable May 8, 2023
@nflaig nflaig deleted the nflaig/fix-node-is-syncing-log branch May 8, 2023 07:40
@wemeetagain
Copy link
Member

🎉 This PR is included in v1.9.0 🎉

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants