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

Do not duplicate forkchoice.onAttestation() errors #3573

Merged
merged 2 commits into from
Jan 7, 2022
Merged

Do not duplicate forkchoice.onAttestation() errors #3573

merged 2 commits into from
Jan 7, 2022

Conversation

twoeths
Copy link
Contributor

@twoeths twoeths commented Jan 5, 2022

Motivation

In Kintsugi, there are a lot of duplicate errorred attestations in same block like this:

Jan-04 17:21:11.909 [CHAIN]           ^[[31merror^[[39m: Error processing attestation from block slot=138066 code=FORKCHOICE_ERROR_INVALID_ATTESTATION, err={"code        ":"UNKNOWN_HEAD_BLOCK","beaconBlockRoot":"0x64535ff2cc85ecaaf73c44b1b35f1e084fae6702eb507e375fb104136756bdb9"}
2357023 Error: FORKCHOICE_ERROR_INVALID_ATTESTATION
2357024     at ForkChoice.validateOnAttestation (/usr/app/node_modules/@chainsafe/lodestar-fork-choice/src/forkChoice/forkChoice.ts:826:13)
2357025     at ForkChoice.onAttestation (/usr/app/node_modules/@chainsafe/lodestar-fork-choice/src/forkChoice/forkChoice.ts:427:10)
2357026     at importBlock (/usr/app/node_modules/@chainsafe/lodestar/src/chain/blocks/importBlock.ts:125:26)
2357027     at processBlock (/usr/app/node_modules/@chainsafe/lodestar/src/chain/blocks/index.ts:65:22)
2357028     at runMicrotasks (<anonymous>)
2357029     at processTicksAndRejections (node:internal/process/task_queues:96:5)
2357030     at JobItemQueue.runJob (/usr/app/node_modules/@chainsafe/lodestar/src/util/queue/itemQueue.ts:85:22)
2357031 Jan-04 17:21:11.910 [CHAIN]           ^[[31merror^[[39m: Error processing attestation from block slot=138066 code=FORKCHOICE_ERROR_INVALID_ATTESTATION, err={"code        ":"UNKNOWN_HEAD_BLOCK","beaconBlockRoot":"0x64535ff2cc85ecaaf73c44b1b35f1e084fae6702eb507e375fb104136756bdb9"}
2357032 Error: FORKCHOICE_ERROR_INVALID_ATTESTATION
2357033     at ForkChoice.validateOnAttestation (/usr/app/node_modules/@chainsafe/lodestar-fork-choice/src/forkChoice/forkChoice.ts:826:13)
2357034     at ForkChoice.onAttestation (/usr/app/node_modules/@chainsafe/lodestar-fork-choice/src/forkChoice/forkChoice.ts:427:10)
2357035     at importBlock (/usr/app/node_modules/@chainsafe/lodestar/src/chain/blocks/importBlock.ts:125:26)
2357036     at processBlock (/usr/app/node_modules/@chainsafe/lodestar/src/chain/blocks/index.ts:65:22)
2357037     at runMicrotasks (<anonymous>)
2357038     at processTicksAndRejections (node:internal/process/task_queues:96:5)
2357039     at JobItemQueue.runJob (/usr/app/node_modules/@chainsafe/lodestar/src/util/queue/itemQueue.ts:85:22)

That happens when we import a block with a lot of errorred attestations of the same type

Description

  • That error does not affect the functionality, we still import that block in the end so it's more suitable for a log.warn instead
  • It's redundant to show a lot of duplicate errors like that in same block, we should log it once per code and number of attestations that have the same error instead

@codeclimate
Copy link

codeclimate bot commented Jan 5, 2022 •
edited

Code Climate has analyzed commit b246332 and detected 0 issues on this pull request.

View more on Code Climate.

@codecov
Copy link

codecov bot commented Jan 5, 2022 •
edited

Codecov Report

Merging #3573 (b246332) into master (c384b36) will decrease coverage by 0.65%.
The diff coverage is n/a.

@@            Coverage Diff             @@
##           master    #3573      +/-   ##
==========================================
- Coverage   37.47%   36.81%   -0.66%     
==========================================
  Files         311      311              
  Lines        8291     8673     +382     
  Branches     1282     1389     +107     
==========================================
+ Hits         3107     3193      +86     
- Misses       5036     5330     +294     
- Partials      148      150       +2

@github-actions
Copy link
Contributor

github-actions bot commented Jan 5, 2022 •
edited

Performance Report

✔️ no performance regression detected

Full benchmark results
Benchmark suite Current: 90e6053 Previous: d78d0c5 Ratio
BeaconState.hashTreeRoot - No change 515.00 ns/op 578.00 ns/op 0.89
BeaconState.hashTreeRoot - 1 full validator 118.08 us/op 123.02 us/op 0.96
BeaconState.hashTreeRoot - 32 full validator 1.7561 ms/op 1.9085 ms/op 0.92
BeaconState.hashTreeRoot - 512 full validator 23.218 ms/op 24.990 ms/op 0.93
BeaconState.hashTreeRoot - 1 validator.effectiveBalance 115.12 us/op 125.82 us/op 0.91
BeaconState.hashTreeRoot - 32 validator.effectiveBalance 1.9385 ms/op 2.0708 ms/op 0.94
BeaconState.hashTreeRoot - 512 validator.effectiveBalance 23.754 ms/op 27.339 ms/op 0.87
BeaconState.hashTreeRoot - 1 balances 77.885 us/op 89.584 us/op 0.87
BeaconState.hashTreeRoot - 32 balances 693.52 us/op 753.87 us/op 0.92
BeaconState.hashTreeRoot - 512 balances 6.5631 ms/op 7.2896 ms/op 0.90
BeaconState.hashTreeRoot - 250000 balances 121.87 ms/op 139.31 ms/op 0.87
processSlot - 1 slots 42.184 us/op 49.125 us/op 0.86
processSlot - 32 slots 2.5585 ms/op 2.8973 ms/op 0.88
getCommitteeAssignments - req 1 vs - 250000 vc 5.0967 ms/op 5.3190 ms/op 0.96
getCommitteeAssignments - req 100 vs - 250000 vc 6.8984 ms/op 7.3499 ms/op 0.94
getCommitteeAssignments - req 1000 vs - 250000 vc 7.3823 ms/op 7.8996 ms/op 0.93
computeProposers - vc 250000 18.573 ms/op 20.802 ms/op 0.89
computeEpochShuffling - vc 250000 165.11 ms/op 188.15 ms/op 0.88
getNextSyncCommittee - vc 250000 311.15 ms/op 339.34 ms/op 0.92
altair processAttestation - 250000 vs - 7PWei normalcase 40.426 ms/op 44.670 ms/op 0.90
altair processAttestation - 250000 vs - 7PWei worstcase 42.249 ms/op 46.245 ms/op 0.91
altair processAttestation - setStatus - 1/6 committees join 9.0482 ms/op 10.481 ms/op 0.86
altair processAttestation - setStatus - 1/3 committees join 21.168 ms/op 21.955 ms/op 0.96
altair processAttestation - setStatus - 1/2 committees join 33.172 ms/op 34.775 ms/op 0.95
altair processAttestation - setStatus - 2/3 committees join 39.391 ms/op 44.410 ms/op 0.89
altair processAttestation - setStatus - 4/5 committees join 48.047 ms/op 56.639 ms/op 0.85
altair processAttestation - setStatus - 100% committees join 58.930 ms/op 70.827 ms/op 0.83
altair processAttestation - updateEpochParticipants - 1/6 committees join 9.8475 ms/op 13.141 ms/op 0.75
altair processAttestation - updateEpochParticipants - 1/3 committees join 20.178 ms/op 27.536 ms/op 0.73
altair processAttestation - updateEpochParticipants - 1/2 committees join 32.298 ms/op 35.021 ms/op 0.92
altair processAttestation - updateEpochParticipants - 2/3 committees join 28.162 ms/op 29.941 ms/op 0.94
altair processAttestation - updateEpochParticipants - 4/5 committees join 29.931 ms/op 32.034 ms/op 0.93
altair processAttestation - updateEpochParticipants - 100% committees join 29.607 ms/op 33.336 ms/op 0.89
altair processAttestation - updateAllStatus 25.067 ms/op 28.476 ms/op 0.88
altair processBlock - 250000 vs - 7PWei normalcase 43.778 ms/op 48.449 ms/op 0.90
altair processBlock - 250000 vs - 7PWei worstcase 108.51 ms/op 121.31 ms/op 0.89
altair processEpoch - mainnet_e81889 976.97 ms/op 1.0582 s/op 0.92
mainnet_e81889 - altair beforeProcessEpoch 253.67 ms/op 381.61 ms/op 0.66
mainnet_e81889 - altair processJustificationAndFinalization 124.38 us/op 50.886 us/op 2.44
mainnet_e81889 - altair processInactivityUpdates 20.587 ms/op 18.135 ms/op 1.14
mainnet_e81889 - altair processRewardsAndPenalties 138.11 ms/op 149.45 ms/op 0.92
mainnet_e81889 - altair processRegistryUpdates 15.662 us/op 5.2030 us/op 3.01
mainnet_e81889 - altair processSlashings 5.0280 us/op 1.2000 us/op 4.19
mainnet_e81889 - altair processEth1DataReset 4.3810 us/op 1.0080 us/op 4.35
mainnet_e81889 - altair processEffectiveBalanceUpdates 10.538 ms/op 11.577 ms/op 0.91
mainnet_e81889 - altair processSlashingsReset 21.920 us/op 8.8590 us/op 2.47
mainnet_e81889 - altair processRandaoMixesReset 32.656 us/op 11.466 us/op 2.85
mainnet_e81889 - altair processHistoricalRootsUpdate 6.6210 us/op 1.6000 us/op 4.14
mainnet_e81889 - altair processParticipationFlagUpdates 151.15 ms/op 113.25 ms/op 1.33
mainnet_e81889 - altair processSyncCommitteeUpdates 4.1560 us/op 965.00 ns/op 4.31
mainnet_e81889 - altair afterProcessEpoch 195.67 ms/op 227.31 ms/op 0.86
altair processInactivityUpdates - 250000 normalcase 64.063 ms/op 78.336 ms/op 0.82
altair processInactivityUpdates - 250000 worstcase 61.519 ms/op 99.104 ms/op 0.62
altair processParticipationFlagUpdates - 250000 anycase 92.407 ms/op 108.54 ms/op 0.85
altair processRewardsAndPenalties - 250000 normalcase 152.36 ms/op 154.40 ms/op 0.99
altair processRewardsAndPenalties - 250000 worstcase 147.79 ms/op 155.33 ms/op 0.95
altair processSyncCommitteeUpdates - 250000 310.79 ms/op 360.16 ms/op 0.86
Tree 40 250000 create 769.35 ms/op 932.61 ms/op 0.82
Tree 40 250000 get(125000) 290.61 ns/op 324.26 ns/op 0.90
Tree 40 250000 set(125000) 1.5994 us/op 2.1313 us/op 0.75
Tree 40 250000 toArray() 33.211 ms/op 47.592 ms/op 0.70
Tree 40 250000 iterate all - toArray() + loop 40.721 ms/op 40.205 ms/op 1.01
Tree 40 250000 iterate all - get(i) 109.05 ms/op 118.45 ms/op 0.92
MutableVector 250000 create 22.575 ms/op 25.688 ms/op 0.88
MutableVector 250000 get(125000) 14.773 ns/op 13.796 ns/op 1.07
MutableVector 250000 set(125000) 514.14 ns/op 533.50 ns/op 0.96
MutableVector 250000 toArray() 8.2996 ms/op 8.4737 ms/op 0.98
MutableVector 250000 iterate all - toArray() + loop 7.9144 ms/op 8.9521 ms/op 0.88
MutableVector 250000 iterate all - get(i) 3.4232 ms/op 3.3177 ms/op 1.03
Array 250000 create 4.9674 ms/op 5.1083 ms/op 0.97
Array 250000 clone - spread 2.4050 ms/op 2.2448 ms/op 1.07
Array 250000 get(125000) 1.0740 ns/op 1.0750 ns/op 1.00
Array 250000 set(125000) 1.0030 ns/op 1.0360 ns/op 0.97
Array 250000 iterate all - loop 162.98 us/op 169.00 us/op 0.96
aggregationBits - 2048 els - readonlyValues 206.63 us/op 240.74 us/op 0.86
aggregationBits - 2048 els - zipIndexesInBitList 38.484 us/op 40.383 us/op 0.95
regular array get 100000 times 62.604 us/op 67.349 us/op 0.93
wrappedArray get 100000 times 62.967 us/op 67.421 us/op 0.93
arrayWithProxy get 100000 times 25.813 ms/op 28.889 ms/op 0.89
ssz.Root.equals 1.0050 us/op 1.1970 us/op 0.84
ssz.Root.equals with valueOf() 1.1750 us/op 1.3670 us/op 0.86
byteArrayEquals with valueOf() 1.2080 us/op 1.3020 us/op 0.93
phase0 processBlock - 250000 vs - 7PWei normalcase 9.3743 ms/op 10.718 ms/op 0.87
phase0 processBlock - 250000 vs - 7PWei worstcase 69.657 ms/op 79.439 ms/op 0.88
phase0 afterProcessEpoch - 250000 vs - 7PWei 185.33 ms/op 209.11 ms/op 0.89
phase0 beforeProcessEpoch - 250000 vs - 7PWei 536.00 ms/op 602.15 ms/op 0.89
phase0 processEpoch - mainnet_e58758 796.35 ms/op 848.43 ms/op 0.94
mainnet_e58758 - phase0 beforeProcessEpoch 429.32 ms/op 464.24 ms/op 0.92
mainnet_e58758 - phase0 processJustificationAndFinalization 130.74 us/op 59.569 us/op 2.19
mainnet_e58758 - phase0 processRewardsAndPenalties 94.636 ms/op 106.39 ms/op 0.89
mainnet_e58758 - phase0 processRegistryUpdates 74.966 us/op 35.809 us/op 2.09
mainnet_e58758 - phase0 processSlashings 6.4450 us/op 1.1940 us/op 5.40
mainnet_e58758 - phase0 processEth1DataReset 5.1080 us/op 983.00 ns/op 5.20
mainnet_e58758 - phase0 processEffectiveBalanceUpdates 8.6242 ms/op 10.472 ms/op 0.82
mainnet_e58758 - phase0 processSlashingsReset 22.195 us/op 7.1920 us/op 3.09
mainnet_e58758 - phase0 processRandaoMixesReset 32.696 us/op 11.689 us/op 2.80
mainnet_e58758 - phase0 processHistoricalRootsUpdate 6.5430 us/op 1.2310 us/op 5.32
mainnet_e58758 - phase0 processParticipationRecordUpdates 21.565 us/op 8.3580 us/op 2.58
mainnet_e58758 - phase0 afterProcessEpoch 160.53 ms/op 184.58 ms/op 0.87
phase0 processEffectiveBalanceUpdates - 250000 normalcase 9.7261 ms/op 10.728 ms/op 0.91
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5 1.1245 s/op 1.5409 s/op 0.73
phase0 processRegistryUpdates - 250000 normalcase 85.159 us/op 35.687 us/op 2.39
phase0 processRegistryUpdates - 250000 badcase_full_deposits 2.6349 ms/op 3.1390 ms/op 0.84
phase0 processRegistryUpdates - 250000 worstcase 0.5 1.2526 s/op 1.9403 s/op 0.65
phase0 getAttestationDeltas - 250000 normalcase 32.290 ms/op 37.817 ms/op 0.85
phase0 getAttestationDeltas - 250000 worstcase 33.913 ms/op 37.952 ms/op 0.89
phase0 processSlashings - 250000 worstcase 33.050 ms/op 41.917 ms/op 0.79
shuffle list - 16384 els 11.386 ms/op 12.940 ms/op 0.88
shuffle list - 250000 els 161.80 ms/op 184.57 ms/op 0.88
getEffectiveBalances - 250000 vs - 7PWei 9.4428 ms/op 12.902 ms/op 0.73
computeDeltas 3.4890 ms/op 4.0158 ms/op 0.87
getPubkeys - index2pubkey - req 1000 vs - 250000 vc 1.9395 ms/op 2.2805 ms/op 0.85
getPubkeys - validatorsArr - req 1000 vs - 250000 vc 586.54 us/op 644.08 us/op 0.91
BLS verify - blst-native 1.6720 ms/op 1.8582 ms/op 0.90
BLS verifyMultipleSignatures 3 - blst-native 3.3666 ms/op 3.8136 ms/op 0.88
BLS verifyMultipleSignatures 8 - blst-native 7.7037 ms/op 8.2259 ms/op 0.94
BLS verifyMultipleSignatures 32 - blst-native 27.281 ms/op 29.853 ms/op 0.91
BLS aggregatePubkeys 32 - blst-native 35.677 us/op 39.387 us/op 0.91
BLS aggregatePubkeys 128 - blst-native 139.57 us/op 153.44 us/op 0.91
getAttestationsForBlock 77.472 ms/op 83.252 ms/op 0.93
CheckpointStateCache - add get delete 13.497 us/op 15.293 us/op 0.88
validate gossip signedAggregateAndProof - struct 4.0136 ms/op 4.4667 ms/op 0.90
validate gossip signedAggregateAndProof - treeBacked 3.8955 ms/op 4.3992 ms/op 0.89
validate gossip attestation - struct 1.9157 ms/op 2.0841 ms/op 0.92
validate gossip attestation - treeBacked 1.9019 ms/op 2.1151 ms/op 0.90
bytes32 toHexString 1.5160 us/op 1.6700 us/op 0.91
bytes32 Buffer.toString(hex) 586.00 ns/op 669.00 ns/op 0.88
bytes32 Buffer.toString(hex) from Uint8Array 800.00 ns/op 918.00 ns/op 0.87
bytes32 Buffer.toString(hex) + 0x 641.00 ns/op 676.00 ns/op 0.95
Object access 1 prop 0.29900 ns/op 0.31900 ns/op 0.94
Map access 1 prop 0.25800 ns/op 0.27300 ns/op 0.95
Object get x1000 15.506 ns/op 17.043 ns/op 0.91
Map get x1000 0.86400 ns/op 0.98200 ns/op 0.88
Object set x1000 100.15 ns/op 104.52 ns/op 0.96
Map set x1000 65.106 ns/op 63.851 ns/op 1.02
Return object 10000 times 0.34860 ns/op 0.36580 ns/op 0.95
Throw Error 10000 times 5.3588 us/op 5.9642 us/op 0.90
enrSubnets - fastDeserialize 64 bits 1.0890 us/op 1.2270 us/op 0.89
enrSubnets - ssz BitVector 64 bits 14.507 us/op 16.213 us/op 0.89
enrSubnets - fastDeserialize 4 bits 370.00 ns/op 434.00 ns/op 0.85
enrSubnets - ssz BitVector 4 bits 2.5680 us/op 2.8100 us/op 0.91
RateTracker 1000000 limit, 1 obj count per request 160.07 ns/op 179.36 ns/op 0.89
RateTracker 1000000 limit, 2 obj count per request 119.75 ns/op 130.84 ns/op 0.92
RateTracker 1000000 limit, 4 obj count per request 98.900 ns/op 108.35 ns/op 0.91
RateTracker 1000000 limit, 8 obj count per request 88.762 ns/op 100.60 ns/op 0.88
RateTracker with prune 3.4870 us/op 4.0600 us/op 0.86

by benchmarkbot/action

g11tech
g11tech previously approved these changes Jan 5, 2022
View reviewed changes
@dapplion dapplion merged commit f52c33d into master Jan 7, 2022
@dapplion dapplion deleted the tuyen/log-onAttestation-error branch January 7, 2022 11:26
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@dapplion dapplion dapplion approved these changes

@g11tech g11tech g11tech approved these changes

@mpetrunic mpetrunic Awaiting requested review from mpetrunic

@wemeetagain wemeetagain Awaiting requested review from wemeetagain

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

None yet
3 participants
@twoeths @dapplion @g11tech