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

Log expected api errors as warning instead of error #5285

Merged
merged 2 commits into from
Mar 21, 2023

Conversation

nflaig
Copy link
Member

@nflaig nflaig commented Mar 20, 2023

Motivation

Expected API errors (ApiError) should be logged as warnings instead of errors to not unnecessarily scare users. Printing out the stacktrace does not help here either, it just creates noise.

Description

Check if error is ApiError and just log it as warn and only print out the err.message.

Unexpected errors (non ApiError) will still be logged as error including the stacktrace.

Closes #5265, related discussion

@nflaig nflaig requested a review from a team as a code owner March 20, 2023 12:47
@nflaig nflaig added the scope-ux Issues for CLI UX or general consumer UX. label Mar 20, 2023
@github-actions
Copy link
Contributor

github-actions bot commented Mar 20, 2023

Performance Report

✔️ no performance regression detected

Full benchmark results
Benchmark suite Current: 1f4215c Previous: df1ef97 Ratio
getPubkeys - index2pubkey - req 1000 vs - 250000 vc 710.71 us/op 511.75 us/op 1.39
getPubkeys - validatorsArr - req 1000 vs - 250000 vc 45.404 us/op 46.057 us/op 0.99
BLS verify - blst-native 1.2046 ms/op 1.2111 ms/op 0.99
BLS verifyMultipleSignatures 3 - blst-native 2.4509 ms/op 2.4663 ms/op 0.99
BLS verifyMultipleSignatures 8 - blst-native 5.2992 ms/op 5.3115 ms/op 1.00
BLS verifyMultipleSignatures 32 - blst-native 18.996 ms/op 19.409 ms/op 0.98
BLS aggregatePubkeys 32 - blst-native 25.426 us/op 25.587 us/op 0.99
BLS aggregatePubkeys 128 - blst-native 99.584 us/op 101.20 us/op 0.98
getAttestationsForBlock 51.478 ms/op 52.708 ms/op 0.98
isKnown best case - 1 super set check 246.00 ns/op 263.00 ns/op 0.94
isKnown normal case - 2 super set checks 240.00 ns/op 258.00 ns/op 0.93
isKnown worse case - 16 super set checks 243.00 ns/op 253.00 ns/op 0.96
CheckpointStateCache - add get delete 4.7960 us/op 4.8180 us/op 1.00
validate gossip signedAggregateAndProof - struct 2.6591 ms/op 2.7351 ms/op 0.97
validate gossip attestation - struct 1.2570 ms/op 1.3063 ms/op 0.96
pickEth1Vote - no votes 1.2362 ms/op 1.3189 ms/op 0.94
pickEth1Vote - max votes 9.0653 ms/op 8.3392 ms/op 1.09
pickEth1Vote - Eth1Data hashTreeRoot value x2048 8.6979 ms/op 8.4065 ms/op 1.03
pickEth1Vote - Eth1Data hashTreeRoot tree x2048 14.140 ms/op 13.111 ms/op 1.08
pickEth1Vote - Eth1Data fastSerialize value x2048 647.55 us/op 705.55 us/op 0.92
pickEth1Vote - Eth1Data fastSerialize tree x2048 6.8734 ms/op 4.9644 ms/op 1.38
bytes32 toHexString 470.00 ns/op 518.00 ns/op 0.91
bytes32 Buffer.toString(hex) 344.00 ns/op 357.00 ns/op 0.96
bytes32 Buffer.toString(hex) from Uint8Array 539.00 ns/op 544.00 ns/op 0.99
bytes32 Buffer.toString(hex) + 0x 342.00 ns/op 377.00 ns/op 0.91
Object access 1 prop 0.16000 ns/op 0.16900 ns/op 0.95
Map access 1 prop 0.15700 ns/op 0.16200 ns/op 0.97
Object get x1000 7.2250 ns/op 7.2050 ns/op 1.00
Map get x1000 0.60300 ns/op 0.63000 ns/op 0.96
Object set x1000 51.611 ns/op 54.747 ns/op 0.94
Map set x1000 43.610 ns/op 46.374 ns/op 0.94
Return object 10000 times 0.23400 ns/op 0.23770 ns/op 0.98
Throw Error 10000 times 4.3039 us/op 4.1452 us/op 1.04
fastMsgIdFn sha256 / 200 bytes 3.4130 us/op 3.4720 us/op 0.98
fastMsgIdFn h32 xxhash / 200 bytes 279.00 ns/op 285.00 ns/op 0.98
fastMsgIdFn h64 xxhash / 200 bytes 393.00 ns/op 392.00 ns/op 1.00
fastMsgIdFn sha256 / 1000 bytes 11.476 us/op 11.474 us/op 1.00
fastMsgIdFn h32 xxhash / 1000 bytes 409.00 ns/op 399.00 ns/op 1.03
fastMsgIdFn h64 xxhash / 1000 bytes 470.00 ns/op 453.00 ns/op 1.04
fastMsgIdFn sha256 / 10000 bytes 103.29 us/op 103.30 us/op 1.00
fastMsgIdFn h32 xxhash / 10000 bytes 1.9320 us/op 1.8980 us/op 1.02
fastMsgIdFn h64 xxhash / 10000 bytes 1.3470 us/op 1.3040 us/op 1.03
enrSubnets - fastDeserialize 64 bits 1.2660 us/op 1.2850 us/op 0.99
enrSubnets - ssz BitVector 64 bits 494.00 ns/op 500.00 ns/op 0.99
enrSubnets - fastDeserialize 4 bits 167.00 ns/op 179.00 ns/op 0.93
enrSubnets - ssz BitVector 4 bits 503.00 ns/op 488.00 ns/op 1.03
prioritizePeers score -10:0 att 32-0.1 sync 2-0 99.036 us/op 101.28 us/op 0.98
prioritizePeers score 0:0 att 32-0.25 sync 2-0.25 128.67 us/op 131.88 us/op 0.98
prioritizePeers score 0:0 att 32-0.5 sync 2-0.5 161.87 us/op 166.54 us/op 0.97
prioritizePeers score 0:0 att 64-0.75 sync 4-0.75 298.73 us/op 304.73 us/op 0.98
prioritizePeers score 0:0 att 64-1 sync 4-1 360.86 us/op 363.57 us/op 0.99
array of 16000 items push then shift 1.6222 us/op 1.6329 us/op 0.99
LinkedList of 16000 items push then shift 8.7360 ns/op 8.8340 ns/op 0.99
array of 16000 items push then pop 78.810 ns/op 81.262 ns/op 0.97
LinkedList of 16000 items push then pop 8.4810 ns/op 8.6500 ns/op 0.98
array of 24000 items push then shift 2.3326 us/op 2.3471 us/op 0.99
LinkedList of 24000 items push then shift 8.6870 ns/op 8.7760 ns/op 0.99
array of 24000 items push then pop 74.564 ns/op 74.835 ns/op 1.00
LinkedList of 24000 items push then pop 8.1950 ns/op 8.5470 ns/op 0.96
intersect bitArray bitLen 8 12.942 ns/op 13.144 ns/op 0.98
intersect array and set length 8 76.178 ns/op 80.266 ns/op 0.95
intersect bitArray bitLen 128 43.060 ns/op 43.834 ns/op 0.98
intersect array and set length 128 1.0322 us/op 1.0889 us/op 0.95
Buffer.concat 32 items 2.9020 us/op 2.6830 us/op 1.08
Uint8Array.set 32 items 2.7610 us/op 3.0450 us/op 0.91
pass gossip attestations to forkchoice per slot 2.7021 ms/op 3.2323 ms/op 0.84
computeDeltas 2.8243 ms/op 2.9235 ms/op 0.97
computeProposerBoostScoreFromBalances 1.7747 ms/op 1.7683 ms/op 1.00
altair processAttestation - 250000 vs - 7PWei normalcase 2.0740 ms/op 2.1019 ms/op 0.99
altair processAttestation - 250000 vs - 7PWei worstcase 3.2411 ms/op 3.2527 ms/op 1.00
altair processAttestation - setStatus - 1/6 committees join 139.62 us/op 138.10 us/op 1.01
altair processAttestation - setStatus - 1/3 committees join 274.53 us/op 271.82 us/op 1.01
altair processAttestation - setStatus - 1/2 committees join 367.48 us/op 366.47 us/op 1.00
altair processAttestation - setStatus - 2/3 committees join 458.00 us/op 457.54 us/op 1.00
altair processAttestation - setStatus - 4/5 committees join 647.82 us/op 639.24 us/op 1.01
altair processAttestation - setStatus - 100% committees join 747.91 us/op 749.72 us/op 1.00
altair processBlock - 250000 vs - 7PWei normalcase 16.569 ms/op 16.295 ms/op 1.02
altair processBlock - 250000 vs - 7PWei normalcase hashState 27.390 ms/op 29.056 ms/op 0.94
altair processBlock - 250000 vs - 7PWei worstcase 47.273 ms/op 45.768 ms/op 1.03
altair processBlock - 250000 vs - 7PWei worstcase hashState 66.131 ms/op 63.494 ms/op 1.04
phase0 processBlock - 250000 vs - 7PWei normalcase 1.9509 ms/op 2.0193 ms/op 0.97
phase0 processBlock - 250000 vs - 7PWei worstcase 28.229 ms/op 29.210 ms/op 0.97
altair processEth1Data - 250000 vs - 7PWei normalcase 451.46 us/op 461.83 us/op 0.98
vc - 250000 eb 1 eth1 1 we 0 wn 0 - smpl 15 6.6800 us/op 7.1510 us/op 0.93
vc - 250000 eb 0.95 eth1 0.1 we 0.05 wn 0 - smpl 219 19.099 us/op 21.301 us/op 0.90
vc - 250000 eb 0.95 eth1 0.3 we 0.05 wn 0 - smpl 42 8.2930 us/op 8.8640 us/op 0.94
vc - 250000 eb 0.95 eth1 0.7 we 0.05 wn 0 - smpl 18 6.3280 us/op 7.4370 us/op 0.85
vc - 250000 eb 0.1 eth1 0.1 we 0 wn 0 - smpl 1020 74.683 us/op 84.720 us/op 0.88
vc - 250000 eb 0.03 eth1 0.03 we 0 wn 0 - smpl 11777 640.31 us/op 633.04 us/op 1.01
vc - 250000 eb 0.01 eth1 0.01 we 0 wn 0 - smpl 16384 917.33 us/op 902.37 us/op 1.02
vc - 250000 eb 0 eth1 0 we 0 wn 0 - smpl 16384 854.45 us/op 857.86 us/op 1.00
vc - 250000 eb 0 eth1 0 we 0 wn 0 nocache - smpl 16384 2.3434 ms/op 2.2780 ms/op 1.03
vc - 250000 eb 0 eth1 1 we 0 wn 0 - smpl 16384 1.6262 ms/op 1.4975 ms/op 1.09
vc - 250000 eb 0 eth1 1 we 0 wn 0 nocache - smpl 16384 3.7310 ms/op 3.7820 ms/op 0.99
Tree 40 250000 create 302.37 ms/op 300.01 ms/op 1.01
Tree 40 250000 get(125000) 180.52 ns/op 182.08 ns/op 0.99
Tree 40 250000 set(125000) 959.71 ns/op 896.50 ns/op 1.07
Tree 40 250000 toArray() 17.598 ms/op 16.680 ms/op 1.06
Tree 40 250000 iterate all - toArray() + loop 17.669 ms/op 17.385 ms/op 1.02
Tree 40 250000 iterate all - get(i) 71.979 ms/op 66.774 ms/op 1.08
MutableVector 250000 create 9.3500 ms/op 9.6544 ms/op 0.97
MutableVector 250000 get(125000) 6.3690 ns/op 6.1900 ns/op 1.03
MutableVector 250000 set(125000) 249.59 ns/op 256.03 ns/op 0.97
MutableVector 250000 toArray() 2.6891 ms/op 2.6775 ms/op 1.00
MutableVector 250000 iterate all - toArray() + loop 2.7425 ms/op 2.8243 ms/op 0.97
MutableVector 250000 iterate all - get(i) 1.5106 ms/op 1.4781 ms/op 1.02
Array 250000 create 2.4555 ms/op 2.7719 ms/op 0.89
Array 250000 clone - spread 1.1272 ms/op 1.0997 ms/op 1.03
Array 250000 get(125000) 0.57200 ns/op 0.52900 ns/op 1.08
Array 250000 set(125000) 0.63900 ns/op 0.61600 ns/op 1.04
Array 250000 iterate all - loop 82.034 us/op 108.44 us/op 0.76
effectiveBalanceIncrements clone Uint8Array 300000 25.958 us/op 23.983 us/op 1.08
effectiveBalanceIncrements clone MutableVector 300000 360.00 ns/op 335.00 ns/op 1.07
effectiveBalanceIncrements rw all Uint8Array 300000 167.80 us/op 167.48 us/op 1.00
effectiveBalanceIncrements rw all MutableVector 300000 80.807 ms/op 76.710 ms/op 1.05
phase0 afterProcessEpoch - 250000 vs - 7PWei 112.10 ms/op 111.06 ms/op 1.01
phase0 beforeProcessEpoch - 250000 vs - 7PWei 40.863 ms/op 42.615 ms/op 0.96
altair processEpoch - mainnet_e81889 319.60 ms/op 299.39 ms/op 1.07
mainnet_e81889 - altair beforeProcessEpoch 45.838 ms/op 47.870 ms/op 0.96
mainnet_e81889 - altair processJustificationAndFinalization 15.662 us/op 16.444 us/op 0.95
mainnet_e81889 - altair processInactivityUpdates 5.3788 ms/op 5.2723 ms/op 1.02
mainnet_e81889 - altair processRewardsAndPenalties 65.485 ms/op 66.817 ms/op 0.98
mainnet_e81889 - altair processRegistryUpdates 2.2990 us/op 2.3260 us/op 0.99
mainnet_e81889 - altair processSlashings 449.00 ns/op 535.00 ns/op 0.84
mainnet_e81889 - altair processEth1DataReset 469.00 ns/op 541.00 ns/op 0.87
mainnet_e81889 - altair processEffectiveBalanceUpdates 1.4495 ms/op 1.2298 ms/op 1.18
mainnet_e81889 - altair processSlashingsReset 3.9310 us/op 4.7810 us/op 0.82
mainnet_e81889 - altair processRandaoMixesReset 5.3800 us/op 4.2820 us/op 1.26
mainnet_e81889 - altair processHistoricalRootsUpdate 1.0480 us/op 644.00 ns/op 1.63
mainnet_e81889 - altair processParticipationFlagUpdates 2.8250 us/op 2.4280 us/op 1.16
mainnet_e81889 - altair processSyncCommitteeUpdates 588.00 ns/op 646.00 ns/op 0.91
mainnet_e81889 - altair afterProcessEpoch 125.09 ms/op 117.78 ms/op 1.06
phase0 processEpoch - mainnet_e58758 366.24 ms/op 310.34 ms/op 1.18
mainnet_e58758 - phase0 beforeProcessEpoch 136.75 ms/op 119.70 ms/op 1.14
mainnet_e58758 - phase0 processJustificationAndFinalization 16.967 us/op 16.019 us/op 1.06
mainnet_e58758 - phase0 processRewardsAndPenalties 63.704 ms/op 56.078 ms/op 1.14
mainnet_e58758 - phase0 processRegistryUpdates 9.4400 us/op 7.6620 us/op 1.23
mainnet_e58758 - phase0 processSlashings 485.00 ns/op 509.00 ns/op 0.95
mainnet_e58758 - phase0 processEth1DataReset 496.00 ns/op 524.00 ns/op 0.95
mainnet_e58758 - phase0 processEffectiveBalanceUpdates 1.5160 ms/op 968.17 us/op 1.57
mainnet_e58758 - phase0 processSlashingsReset 4.0500 us/op 3.3060 us/op 1.23
mainnet_e58758 - phase0 processRandaoMixesReset 4.5560 us/op 4.7090 us/op 0.97
mainnet_e58758 - phase0 processHistoricalRootsUpdate 494.00 ns/op 601.00 ns/op 0.82
mainnet_e58758 - phase0 processParticipationRecordUpdates 3.6740 us/op 3.8010 us/op 0.97
mainnet_e58758 - phase0 afterProcessEpoch 100.65 ms/op 95.080 ms/op 1.06
phase0 processEffectiveBalanceUpdates - 250000 normalcase 1.2415 ms/op 1.2062 ms/op 1.03
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5 1.4978 ms/op 1.4407 ms/op 1.04
altair processInactivityUpdates - 250000 normalcase 25.800 ms/op 23.544 ms/op 1.10
altair processInactivityUpdates - 250000 worstcase 23.954 ms/op 20.475 ms/op 1.17
phase0 processRegistryUpdates - 250000 normalcase 7.8880 us/op 6.2910 us/op 1.25
phase0 processRegistryUpdates - 250000 badcase_full_deposits 267.22 us/op 239.39 us/op 1.12
phase0 processRegistryUpdates - 250000 worstcase 0.5 134.87 ms/op 111.66 ms/op 1.21
altair processRewardsAndPenalties - 250000 normalcase 68.341 ms/op 51.939 ms/op 1.32
altair processRewardsAndPenalties - 250000 worstcase 68.956 ms/op 60.646 ms/op 1.14
phase0 getAttestationDeltas - 250000 normalcase 6.6302 ms/op 6.2305 ms/op 1.06
phase0 getAttestationDeltas - 250000 worstcase 6.6995 ms/op 6.3208 ms/op 1.06
phase0 processSlashings - 250000 worstcase 3.3426 ms/op 3.4424 ms/op 0.97
altair processSyncCommitteeUpdates - 250000 180.57 ms/op 172.58 ms/op 1.05
BeaconState.hashTreeRoot - No change 363.00 ns/op 257.00 ns/op 1.41
BeaconState.hashTreeRoot - 1 full validator 52.068 us/op 50.512 us/op 1.03
BeaconState.hashTreeRoot - 32 full validator 534.34 us/op 512.21 us/op 1.04
BeaconState.hashTreeRoot - 512 full validator 5.2516 ms/op 4.9410 ms/op 1.06
BeaconState.hashTreeRoot - 1 validator.effectiveBalance 63.004 us/op 60.809 us/op 1.04
BeaconState.hashTreeRoot - 32 validator.effectiveBalance 929.89 us/op 928.49 us/op 1.00
BeaconState.hashTreeRoot - 512 validator.effectiveBalance 11.401 ms/op 11.062 ms/op 1.03
BeaconState.hashTreeRoot - 1 balances 48.868 us/op 48.884 us/op 1.00
BeaconState.hashTreeRoot - 32 balances 457.37 us/op 439.76 us/op 1.04
BeaconState.hashTreeRoot - 512 balances 4.4041 ms/op 4.2475 ms/op 1.04
BeaconState.hashTreeRoot - 250000 balances 71.924 ms/op 75.768 ms/op 0.95
aggregationBits - 2048 els - zipIndexesInBitList 15.257 us/op 16.131 us/op 0.95
regular array get 100000 times 31.988 us/op 32.740 us/op 0.98
wrappedArray get 100000 times 32.360 us/op 32.657 us/op 0.99
arrayWithProxy get 100000 times 16.578 ms/op 16.036 ms/op 1.03
ssz.Root.equals 536.00 ns/op 543.00 ns/op 0.99
byteArrayEquals 529.00 ns/op 539.00 ns/op 0.98
shuffle list - 16384 els 6.9601 ms/op 6.8081 ms/op 1.02
shuffle list - 250000 els 99.729 ms/op 98.044 ms/op 1.02
processSlot - 1 slots 8.6810 us/op 8.4500 us/op 1.03
processSlot - 32 slots 1.2786 ms/op 1.2989 ms/op 0.98
getEffectiveBalanceIncrementsZeroInactive - 250000 vs - 7PWei 36.457 ms/op 34.201 ms/op 1.07
getCommitteeAssignments - req 1 vs - 250000 vc 2.7799 ms/op 2.8550 ms/op 0.97
getCommitteeAssignments - req 100 vs - 250000 vc 4.0116 ms/op 4.0577 ms/op 0.99
getCommitteeAssignments - req 1000 vs - 250000 vc 4.3218 ms/op 4.3951 ms/op 0.98
RootCache.getBlockRootAtSlot - 250000 vs - 7PWei 4.4700 ns/op 4.4400 ns/op 1.01
state getBlockRootAtSlot - 250000 vs - 7PWei 843.93 ns/op 935.35 ns/op 0.90
computeProposers - vc 250000 10.170 ms/op 10.805 ms/op 0.94
computeEpochShuffling - vc 250000 97.206 ms/op 100.98 ms/op 0.96
getNextSyncCommittee - vc 250000 167.60 ms/op 176.34 ms/op 0.95

by benchmarkbot/action

Copy link
Contributor

@maschad maschad left a comment

Choose a reason for hiding this comment

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

I am not sure all non-500 error codes are just warnings

packages/beacon-node/src/api/rest/base.ts Outdated Show resolved Hide resolved
@nflaig
Copy link
Member Author

nflaig commented Mar 20, 2023

I am not sure all non-500 error codes are just warnings

regarding this, if there are non-500 error codes which are not considered a warning but something critical then the error code must be changed

@nflaig nflaig added the scope-logging Issue about logs: hygiene, format issues, improvements. label Mar 20, 2023
this.logger.error(`Req ${req.id} ${operationId} error`, {}, err);

if (err instanceof ApiError) {
this.logger.warn(`Req ${req.id} ${operationId} failed`, {reason: err.message});
Copy link
Member Author

@nflaig nflaig Mar 21, 2023

Choose a reason for hiding this comment

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

@wemeetagain I want to establish this pattern that for non-critical issues we use the terms "failed" and "reason" instead of "error" as based on my observations the term "error" scares a lot of users, especially less technical ones. What do you think?

Copy link
Member

Choose a reason for hiding this comment

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

👍 👍

Copy link
Contributor

Choose a reason for hiding this comment

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

i think the stack trace is very useful, but we can move the log to debug will full trace, an additional warn log in this format is acceptable

Copy link
Member Author

Choose a reason for hiding this comment

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

but we can move the log to debug will full trace, an additional warn log in this format is acceptable

that's also what I was considering, sounds like a reasonable compromise. Not sure if it makes sense here though in case of ApiError, if someone feels strongly about having a stack trace for those we should probably log it as well to debug

@wemeetagain wemeetagain merged commit 5fde8c5 into unstable Mar 21, 2023
@wemeetagain wemeetagain deleted the nflaig/expected-api-errors-as-warning branch March 21, 2023 15:10
@wemeetagain
Copy link
Member

🎉 This PR is included in v1.7.0 🎉

@nflaig nflaig mentioned this pull request Apr 5, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
scope-logging Issue about logs: hygiene, format issues, improvements. scope-ux Issues for CLI UX or general consumer UX.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Log Validator pubkey not found as a warning
4 participants