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

DNM: logging ux changes based on new logging policy #5457

Closed
wants to merge 5 commits into from

Conversation

philknows
Copy link
Member

@philknows philknows commented May 3, 2023

Motivation

This PR is a collection of changes committed by the team, dedicated to discussion and refactoring based on our newly implemented logging policy #5299. Lodestar is implementing a better logging policy to improve our UX for continued adoption by the community.

Meant to track and discuss specific portions of the code that require log UX improvements. Do not merge.

Description

Contributors are asked to submit commits to this PR with potential changes and motivation for why a specific change is being proposed.

Closes #5359
Partially closes #4400

@@ -110,7 +110,7 @@ export async function processBlocks(
if (!(err instanceof BlockError)) {
this.logger.error("Non BlockError received", {}, err);
} else if (!opts.disableOnBlockError) {
this.logger.error("Block error", {slot: err.signedBlock.message.slot}, err);
this.logger.warn("Block error", {slot: err.signedBlock.message.slot}, err);
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reference: #3062
Block errors are sometimes expected, especially for unstable/testnet networks and error doesn't feel like the correct verbosity as the user cannot be expected to do something about it. As mentioned in the issue, warn or info may be more appropriate. Should we also consider removing the stacktrace?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This log here does not make much sense to be above debug level IF ONLY the consumers handle the error properly. Invalid blocks can be submitted via:

  • gossip: a peer is free to submit and invalid block. That's an uncontrolled event the user can't do much about, so we may want to not log it at all. However, if there's a consensus bug the node will just freeze without warning
  • sync: same as above
  • API: this should never happen as long as the API is trusted. The API also logs errors so this will probably be a duplicate

For now, let's manually review every caller of this path and check if they already log the error and at what level

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@github-actions
Copy link
Contributor

github-actions bot commented May 3, 2023

Performance Report

✔️ no performance regression detected

Full benchmark results
Benchmark suite Current: d065243 Previous: d835c8c Ratio
getPubkeys - index2pubkey - req 1000 vs - 250000 vc 660.40 us/op 571.40 us/op 1.16
getPubkeys - validatorsArr - req 1000 vs - 250000 vc 60.095 us/op 45.329 us/op 1.33
BLS verify - blst-native 1.3066 ms/op 1.2293 ms/op 1.06
BLS verifyMultipleSignatures 3 - blst-native 2.6562 ms/op 2.4818 ms/op 1.07
BLS verifyMultipleSignatures 8 - blst-native 5.5958 ms/op 5.3084 ms/op 1.05
BLS verifyMultipleSignatures 32 - blst-native 20.099 ms/op 18.979 ms/op 1.06
BLS aggregatePubkeys 32 - blst-native 27.023 us/op 25.925 us/op 1.04
BLS aggregatePubkeys 128 - blst-native 105.49 us/op 101.56 us/op 1.04
getAttestationsForBlock 60.177 ms/op 56.021 ms/op 1.07
isKnown best case - 1 super set check 269.00 ns/op 256.00 ns/op 1.05
isKnown normal case - 2 super set checks 265.00 ns/op 255.00 ns/op 1.04
isKnown worse case - 16 super set checks 265.00 ns/op 252.00 ns/op 1.05
CheckpointStateCache - add get delete 5.8100 us/op 5.1170 us/op 1.14
validate gossip signedAggregateAndProof - struct 2.9275 ms/op 2.8275 ms/op 1.04
validate gossip attestation - struct 1.3596 ms/op 1.3541 ms/op 1.00
pickEth1Vote - no votes 1.3628 ms/op 1.2605 ms/op 1.08
pickEth1Vote - max votes 10.100 ms/op 11.477 ms/op 0.88
pickEth1Vote - Eth1Data hashTreeRoot value x2048 9.2749 ms/op 9.2133 ms/op 1.01
pickEth1Vote - Eth1Data hashTreeRoot tree x2048 15.282 ms/op 19.569 ms/op 0.78
pickEth1Vote - Eth1Data fastSerialize value x2048 739.92 us/op 676.64 us/op 1.09
pickEth1Vote - Eth1Data fastSerialize tree x2048 6.0012 ms/op 8.9303 ms/op 0.67
bytes32 toHexString 679.00 ns/op 497.00 ns/op 1.37
bytes32 Buffer.toString(hex) 446.00 ns/op 364.00 ns/op 1.23
bytes32 Buffer.toString(hex) from Uint8Array 651.00 ns/op 568.00 ns/op 1.15
bytes32 Buffer.toString(hex) + 0x 435.00 ns/op 348.00 ns/op 1.25
Object access 1 prop 0.20100 ns/op 0.16200 ns/op 1.24
Map access 1 prop 0.17700 ns/op 0.15300 ns/op 1.16
Object get x1000 7.0210 ns/op 6.6350 ns/op 1.06
Map get x1000 0.66400 ns/op 0.61200 ns/op 1.08
Object set x1000 69.071 ns/op 53.324 ns/op 1.30
Map set x1000 55.971 ns/op 45.492 ns/op 1.23
Return object 10000 times 0.25190 ns/op 0.23600 ns/op 1.07
Throw Error 10000 times 4.4575 us/op 4.2968 us/op 1.04
fastMsgIdFn sha256 / 200 bytes 3.6450 us/op 3.5720 us/op 1.02
fastMsgIdFn h32 xxhash / 200 bytes 326.00 ns/op 299.00 ns/op 1.09
fastMsgIdFn h64 xxhash / 200 bytes 493.00 ns/op 444.00 ns/op 1.11
fastMsgIdFn sha256 / 1000 bytes 12.188 us/op 12.408 us/op 0.98
fastMsgIdFn h32 xxhash / 1000 bytes 456.00 ns/op 410.00 ns/op 1.11
fastMsgIdFn h64 xxhash / 1000 bytes 565.00 ns/op 467.00 ns/op 1.21
fastMsgIdFn sha256 / 10000 bytes 107.74 us/op 105.39 us/op 1.02
fastMsgIdFn h32 xxhash / 10000 bytes 2.0230 us/op 1.9170 us/op 1.06
fastMsgIdFn h64 xxhash / 10000 bytes 1.4840 us/op 1.3560 us/op 1.09
enrSubnets - fastDeserialize 64 bits 1.6740 us/op 1.3130 us/op 1.27
enrSubnets - ssz BitVector 64 bits 615.00 ns/op 502.00 ns/op 1.23
enrSubnets - fastDeserialize 4 bits 210.00 ns/op 168.00 ns/op 1.25
enrSubnets - ssz BitVector 4 bits 595.00 ns/op 515.00 ns/op 1.16
prioritizePeers score -10:0 att 32-0.1 sync 2-0 125.43 us/op 124.75 us/op 1.01
prioritizePeers score 0:0 att 32-0.25 sync 2-0.25 150.08 us/op 165.26 us/op 0.91
prioritizePeers score 0:0 att 32-0.5 sync 2-0.5 180.23 us/op 161.87 us/op 1.11
prioritizePeers score 0:0 att 64-0.75 sync 4-0.75 313.42 us/op 309.69 us/op 1.01
prioritizePeers score 0:0 att 64-1 sync 4-1 454.42 us/op 380.58 us/op 1.19
array of 16000 items push then shift 1.7259 us/op 1.6951 us/op 1.02
LinkedList of 16000 items push then shift 12.936 ns/op 9.1390 ns/op 1.42
array of 16000 items push then pop 94.292 ns/op 89.125 ns/op 1.06
LinkedList of 16000 items push then pop 12.246 ns/op 8.8940 ns/op 1.38
array of 24000 items push then shift 2.4312 us/op 2.4692 us/op 0.98
LinkedList of 24000 items push then shift 12.976 ns/op 10.688 ns/op 1.21
array of 24000 items push then pop 87.851 ns/op 77.337 ns/op 1.14
LinkedList of 24000 items push then pop 12.174 ns/op 8.9520 ns/op 1.36
intersect bitArray bitLen 8 13.543 ns/op 13.640 ns/op 0.99
intersect array and set length 8 85.370 ns/op 76.267 ns/op 1.12
intersect bitArray bitLen 128 44.996 ns/op 44.457 ns/op 1.01
intersect array and set length 128 1.2363 us/op 1.0625 us/op 1.16
Buffer.concat 32 items 3.0300 us/op 2.6940 us/op 1.12
Uint8Array.set 32 items 2.4460 us/op 3.0510 us/op 0.80
pass gossip attestations to forkchoice per slot 3.3005 ms/op 3.4857 ms/op 0.95
computeDeltas 3.0296 ms/op 3.6943 ms/op 0.82
computeProposerBoostScoreFromBalances 1.8132 ms/op 1.8645 ms/op 0.97
altair processAttestation - 250000 vs - 7PWei normalcase 2.3244 ms/op 2.5024 ms/op 0.93
altair processAttestation - 250000 vs - 7PWei worstcase 3.7179 ms/op 3.8765 ms/op 0.96
altair processAttestation - setStatus - 1/6 committees join 156.31 us/op 153.97 us/op 1.02
altair processAttestation - setStatus - 1/3 committees join 296.19 us/op 305.16 us/op 0.97
altair processAttestation - setStatus - 1/2 committees join 387.02 us/op 392.91 us/op 0.98
altair processAttestation - setStatus - 2/3 committees join 492.59 us/op 487.18 us/op 1.01
altair processAttestation - setStatus - 4/5 committees join 684.70 us/op 690.36 us/op 0.99
altair processAttestation - setStatus - 100% committees join 809.49 us/op 793.61 us/op 1.02
altair processBlock - 250000 vs - 7PWei normalcase 17.918 ms/op 20.935 ms/op 0.86
altair processBlock - 250000 vs - 7PWei normalcase hashState 25.656 ms/op 31.357 ms/op 0.82
altair processBlock - 250000 vs - 7PWei worstcase 53.598 ms/op 61.625 ms/op 0.87
altair processBlock - 250000 vs - 7PWei worstcase hashState 71.718 ms/op 78.622 ms/op 0.91
phase0 processBlock - 250000 vs - 7PWei normalcase 2.4156 ms/op 2.1915 ms/op 1.10
phase0 processBlock - 250000 vs - 7PWei worstcase 31.069 ms/op 31.168 ms/op 1.00
altair processEth1Data - 250000 vs - 7PWei normalcase 549.38 us/op 490.93 us/op 1.12
vc - 250000 eb 1 eth1 1 we 0 wn 0 - smpl 15 7.8270 us/op 9.5350 us/op 0.82
vc - 250000 eb 0.95 eth1 0.1 we 0.05 wn 0 - smpl 219 23.470 us/op 28.506 us/op 0.82
vc - 250000 eb 0.95 eth1 0.3 we 0.05 wn 0 - smpl 42 9.4150 us/op 9.9190 us/op 0.95
vc - 250000 eb 0.95 eth1 0.7 we 0.05 wn 0 - smpl 18 8.7620 us/op 9.3970 us/op 0.93
vc - 250000 eb 0.1 eth1 0.1 we 0 wn 0 - smpl 1020 103.28 us/op 114.34 us/op 0.90
vc - 250000 eb 0.03 eth1 0.03 we 0 wn 0 - smpl 11777 683.60 us/op 845.27 us/op 0.81
vc - 250000 eb 0.01 eth1 0.01 we 0 wn 0 - smpl 16384 925.34 us/op 1.0843 ms/op 0.85
vc - 250000 eb 0 eth1 0 we 0 wn 0 - smpl 16384 948.38 us/op 1.1244 ms/op 0.84
vc - 250000 eb 0 eth1 0 we 0 wn 0 nocache - smpl 16384 2.4122 ms/op 2.8698 ms/op 0.84
vc - 250000 eb 0 eth1 1 we 0 wn 0 - smpl 16384 1.9115 ms/op 1.9502 ms/op 0.98
vc - 250000 eb 0 eth1 1 we 0 wn 0 nocache - smpl 16384 4.0782 ms/op 4.8816 ms/op 0.84
Tree 40 250000 create 347.88 ms/op 375.94 ms/op 0.93
Tree 40 250000 get(125000) 192.97 ns/op 203.73 ns/op 0.95
Tree 40 250000 set(125000) 1.0239 us/op 1.3145 us/op 0.78
Tree 40 250000 toArray() 19.228 ms/op 24.612 ms/op 0.78
Tree 40 250000 iterate all - toArray() + loop 21.753 ms/op 22.857 ms/op 0.95
Tree 40 250000 iterate all - get(i) 76.634 ms/op 81.869 ms/op 0.94
MutableVector 250000 create 11.443 ms/op 15.338 ms/op 0.75
MutableVector 250000 get(125000) 6.4760 ns/op 7.2690 ns/op 0.89
MutableVector 250000 set(125000) 267.14 ns/op 297.82 ns/op 0.90
MutableVector 250000 toArray() 2.9540 ms/op 3.9289 ms/op 0.75
MutableVector 250000 iterate all - toArray() + loop 3.2648 ms/op 3.5075 ms/op 0.93
MutableVector 250000 iterate all - get(i) 1.5502 ms/op 1.6052 ms/op 0.97
Array 250000 create 2.7197 ms/op 3.2673 ms/op 0.83
Array 250000 clone - spread 1.2598 ms/op 1.2842 ms/op 0.98
Array 250000 get(125000) 0.67700 ns/op 0.65000 ns/op 1.04
Array 250000 set(125000) 0.72700 ns/op 0.71500 ns/op 1.02
Array 250000 iterate all - loop 102.69 us/op 111.25 us/op 0.92
effectiveBalanceIncrements clone Uint8Array 300000 32.285 us/op 41.559 us/op 0.78
effectiveBalanceIncrements clone MutableVector 300000 409.00 ns/op 393.00 ns/op 1.04
effectiveBalanceIncrements rw all Uint8Array 300000 170.04 us/op 187.95 us/op 0.90
effectiveBalanceIncrements rw all MutableVector 300000 89.247 ms/op 92.542 ms/op 0.96
phase0 afterProcessEpoch - 250000 vs - 7PWei 117.18 ms/op 119.75 ms/op 0.98
phase0 beforeProcessEpoch - 250000 vs - 7PWei 35.615 ms/op 47.232 ms/op 0.75
altair processEpoch - mainnet_e81889 322.68 ms/op 351.68 ms/op 0.92
mainnet_e81889 - altair beforeProcessEpoch 63.806 ms/op 98.070 ms/op 0.65
mainnet_e81889 - altair processJustificationAndFinalization 16.402 us/op 19.424 us/op 0.84
mainnet_e81889 - altair processInactivityUpdates 5.4395 ms/op 7.7607 ms/op 0.70
mainnet_e81889 - altair processRewardsAndPenalties 65.445 ms/op 65.076 ms/op 1.01
mainnet_e81889 - altair processRegistryUpdates 2.8030 us/op 3.1920 us/op 0.88
mainnet_e81889 - altair processSlashings 492.00 ns/op 579.00 ns/op 0.85
mainnet_e81889 - altair processEth1DataReset 523.00 ns/op 618.00 ns/op 0.85
mainnet_e81889 - altair processEffectiveBalanceUpdates 1.2340 ms/op 1.5891 ms/op 0.78
mainnet_e81889 - altair processSlashingsReset 4.7920 us/op 9.3850 us/op 0.51
mainnet_e81889 - altair processRandaoMixesReset 5.0970 us/op 4.9850 us/op 1.02
mainnet_e81889 - altair processHistoricalRootsUpdate 566.00 ns/op 675.00 ns/op 0.84
mainnet_e81889 - altair processParticipationFlagUpdates 1.8990 us/op 2.6420 us/op 0.72
mainnet_e81889 - altair processSyncCommitteeUpdates 509.00 ns/op 577.00 ns/op 0.88
mainnet_e81889 - altair afterProcessEpoch 126.83 ms/op 132.99 ms/op 0.95
phase0 processEpoch - mainnet_e58758 370.33 ms/op 407.93 ms/op 0.91
mainnet_e58758 - phase0 beforeProcessEpoch 143.32 ms/op 186.32 ms/op 0.77
mainnet_e58758 - phase0 processJustificationAndFinalization 17.515 us/op 24.382 us/op 0.72
mainnet_e58758 - phase0 processRewardsAndPenalties 66.715 ms/op 67.289 ms/op 0.99
mainnet_e58758 - phase0 processRegistryUpdates 7.4910 us/op 8.7610 us/op 0.86
mainnet_e58758 - phase0 processSlashings 454.00 ns/op 577.00 ns/op 0.79
mainnet_e58758 - phase0 processEth1DataReset 479.00 ns/op 604.00 ns/op 0.79
mainnet_e58758 - phase0 processEffectiveBalanceUpdates 1.2768 ms/op 1.3341 ms/op 0.96
mainnet_e58758 - phase0 processSlashingsReset 3.1400 us/op 3.5800 us/op 0.88
mainnet_e58758 - phase0 processRandaoMixesReset 4.3710 us/op 4.9080 us/op 0.89
mainnet_e58758 - phase0 processHistoricalRootsUpdate 564.00 ns/op 677.00 ns/op 0.83
mainnet_e58758 - phase0 processParticipationRecordUpdates 4.1820 us/op 4.1640 us/op 1.00
mainnet_e58758 - phase0 afterProcessEpoch 92.904 ms/op 113.02 ms/op 0.82
phase0 processEffectiveBalanceUpdates - 250000 normalcase 1.1598 ms/op 1.3345 ms/op 0.87
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5 1.4393 ms/op 2.9214 ms/op 0.49
altair processInactivityUpdates - 250000 normalcase 25.087 ms/op 26.146 ms/op 0.96
altair processInactivityUpdates - 250000 worstcase 26.600 ms/op 28.046 ms/op 0.95
phase0 processRegistryUpdates - 250000 normalcase 5.8890 us/op 5.9500 us/op 0.99
phase0 processRegistryUpdates - 250000 badcase_full_deposits 219.47 us/op 280.20 us/op 0.78
phase0 processRegistryUpdates - 250000 worstcase 0.5 109.89 ms/op 141.47 ms/op 0.78
altair processRewardsAndPenalties - 250000 normalcase 64.300 ms/op 50.839 ms/op 1.26
altair processRewardsAndPenalties - 250000 worstcase 68.680 ms/op 65.531 ms/op 1.05
phase0 getAttestationDeltas - 250000 normalcase 6.2170 ms/op 9.0786 ms/op 0.68
phase0 getAttestationDeltas - 250000 worstcase 6.3468 ms/op 9.5845 ms/op 0.66
phase0 processSlashings - 250000 worstcase 3.4429 ms/op 3.9501 ms/op 0.87
altair processSyncCommitteeUpdates - 250000 172.55 ms/op 200.07 ms/op 0.86
BeaconState.hashTreeRoot - No change 289.00 ns/op 317.00 ns/op 0.91
BeaconState.hashTreeRoot - 1 full validator 52.509 us/op 61.446 us/op 0.85
BeaconState.hashTreeRoot - 32 full validator 558.35 us/op 523.29 us/op 1.07
BeaconState.hashTreeRoot - 512 full validator 5.0039 ms/op 6.4524 ms/op 0.78
BeaconState.hashTreeRoot - 1 validator.effectiveBalance 61.639 us/op 69.562 us/op 0.89
BeaconState.hashTreeRoot - 32 validator.effectiveBalance 864.26 us/op 1.0565 ms/op 0.82
BeaconState.hashTreeRoot - 512 validator.effectiveBalance 11.129 ms/op 14.155 ms/op 0.79
BeaconState.hashTreeRoot - 1 balances 48.745 us/op 54.902 us/op 0.89
BeaconState.hashTreeRoot - 32 balances 443.73 us/op 547.36 us/op 0.81
BeaconState.hashTreeRoot - 512 balances 4.3611 ms/op 5.3989 ms/op 0.81
BeaconState.hashTreeRoot - 250000 balances 80.603 ms/op 81.249 ms/op 0.99
aggregationBits - 2048 els - zipIndexesInBitList 15.134 us/op 17.255 us/op 0.88
regular array get 100000 times 32.115 us/op 34.345 us/op 0.94
wrappedArray get 100000 times 32.097 us/op 44.533 us/op 0.72
arrayWithProxy get 100000 times 16.549 ms/op 15.953 ms/op 1.04
ssz.Root.equals 544.00 ns/op 565.00 ns/op 0.96
byteArrayEquals 546.00 ns/op 565.00 ns/op 0.97
shuffle list - 16384 els 6.7208 ms/op 7.2783 ms/op 0.92
shuffle list - 250000 els 98.765 ms/op 106.49 ms/op 0.93
processSlot - 1 slots 8.3500 us/op 9.6920 us/op 0.86
processSlot - 32 slots 1.3178 ms/op 1.5472 ms/op 0.85
getEffectiveBalanceIncrementsZeroInactive - 250000 vs - 7PWei 37.700 ms/op 37.733 ms/op 1.00
getCommitteeAssignments - req 1 vs - 250000 vc 2.7595 ms/op 3.0751 ms/op 0.90
getCommitteeAssignments - req 100 vs - 250000 vc 3.9036 ms/op 4.3772 ms/op 0.89
getCommitteeAssignments - req 1000 vs - 250000 vc 4.2439 ms/op 4.7543 ms/op 0.89
RootCache.getBlockRootAtSlot - 250000 vs - 7PWei 4.1500 ns/op 4.4300 ns/op 0.94
state getBlockRootAtSlot - 250000 vs - 7PWei 963.68 ns/op 914.22 ns/op 1.05
computeProposers - vc 250000 10.219 ms/op 12.439 ms/op 0.82
computeEpochShuffling - vc 250000 100.89 ms/op 111.59 ms/op 0.90
getNextSyncCommittee - vc 250000 172.54 ms/op 176.22 ms/op 0.98
computeSigningRoot for AttestationData 13.431 us/op 14.273 us/op 0.94
hash AttestationData serialized data then Buffer.toString(base64) 2.3831 us/op 2.6646 us/op 0.89
toHexString serialized data 1.0327 us/op 1.5501 us/op 0.67
Buffer.toString(base64) 305.89 ns/op 386.11 ns/op 0.79

by benchmarkbot/action

@philknows philknows changed the title refactor: logging ux changes based on new logging policy DNM: logging ux changes based on new logging policy May 9, 2023
@philknows philknows added the status-do-not-merge Merging this issue will break the build. Do not merge! label May 9, 2023
@wemeetagain
Copy link
Member

Can this be closed?

@philknows
Copy link
Member Author

Closing. Stale and it probably makes better sense to discuss specific UX logging issues as its own issues for better tracking.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
status-do-not-merge Merging this issue will break the build. Do not merge!
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Implement new logging policy Tracker: Improve Lodestar error UX
4 participants