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

Handle timeout errors as api errors #5331

Merged
merged 1 commit into from
Apr 3, 2023
Merged

Handle timeout errors as api errors #5331

merged 1 commit into from
Apr 3, 2023

Conversation

nflaig
Copy link
Member

@nflaig nflaig commented Apr 1, 2023

Motivation

Error logs due to a http timeout are hard to read as those are not handled as by ApiError.assert which adds more context to the error.

Current error log

Error message itself it not detailed, need to look into stack trace to find out where it failed

Eph 0/3 0.022[]                error: Error on runEvery fn  Timeout request
Error: Timeout request
    at HttpClient.requestWithBody (file:///home/nico/projects/ethereum/lodestar/packages/api/src/utils/client/httpClient.ts:302:17)
    at processTicksAndRejections (node:internal/process/task_queues:95:5)
    at Object.request [as produceAttestationData] (file:///home/nico/projects/ethereum/lodestar/packages/api/src/utils/client/client.ts:69:23)
    at AttestationService.produceAttestation (file:///home/nico/projects/ethereum/lodestar/packages/validator/src/services/attestation.ts:151:17)
    at AttestationService.runAttestationTasksGrouped (file:///home/nico/projects/ethereum/lodestar/packages/validator/src/services/attestation.ts:119:36)
    at AttestationService.runAttestationTasks (file:///home/nico/projects/ethereum/lodestar/packages/validator/src/services/attestation.ts:87:7)
    at Clock.runAtMostEvery (file:///home/nico/projects/ethereum/lodestar/packages/validator/src/util/clock.ts:96:7)

Expected error log

Error message includes all details, we know it was timeout and that it happened on produce attestation data request

Eph 0/1 2.002[]                error: Error on runEvery fn  Error producing attestation - Timeout request
Error: Error producing attestation - Timeout request
    at Function.assert (file:///home/nico/projects/ethereum/lodestar/packages/api/src/utils/client/httpClient.ts:44:13)
    at AttestationService.produceAttestation (file:///home/nico/projects/ethereum/lodestar/packages/validator/src/services/attestation.ts:152:14)
    at processTicksAndRejections (node:internal/process/task_queues:95:5)
    at AttestationService.runAttestationTasksGrouped (file:///home/nico/projects/ethereum/lodestar/packages/validator/src/services/attestation.ts:119:36)
    at AttestationService.runAttestationTasks (file:///home/nico/projects/ethereum/lodestar/packages/validator/src/services/attestation.ts:87:7)
    at Clock.runAtMostEvery (file:///home/nico/projects/ethereum/lodestar/packages/validator/src/util/clock.ts:96:7)

Description

Check if error is TimeoutError and instead of throwing it return a API response with code 500.

@nflaig nflaig requested a review from a team as a code owner April 1, 2023 15:27
@github-actions
Copy link
Contributor

github-actions bot commented Apr 1, 2023

Performance Report

✔️ no performance regression detected

Full benchmark results
Benchmark suite Current: df7b22b Previous: 3ddd326 Ratio
getPubkeys - index2pubkey - req 1000 vs - 250000 vc 822.19 us/op 876.01 us/op 0.94
getPubkeys - validatorsArr - req 1000 vs - 250000 vc 49.266 us/op 44.109 us/op 1.12
BLS verify - blst-native 1.2207 ms/op 1.1923 ms/op 1.02
BLS verifyMultipleSignatures 3 - blst-native 2.4627 ms/op 2.4277 ms/op 1.01
BLS verifyMultipleSignatures 8 - blst-native 5.2900 ms/op 5.2060 ms/op 1.02
BLS verifyMultipleSignatures 32 - blst-native 19.103 ms/op 18.828 ms/op 1.01
BLS aggregatePubkeys 32 - blst-native 25.474 us/op 25.273 us/op 1.01
BLS aggregatePubkeys 128 - blst-native 99.842 us/op 98.483 us/op 1.01
getAttestationsForBlock 51.975 ms/op 52.477 ms/op 0.99
isKnown best case - 1 super set check 247.00 ns/op 257.00 ns/op 0.96
isKnown normal case - 2 super set checks 238.00 ns/op 255.00 ns/op 0.93
isKnown worse case - 16 super set checks 238.00 ns/op 254.00 ns/op 0.94
CheckpointStateCache - add get delete 4.8610 us/op 4.6180 us/op 1.05
validate gossip signedAggregateAndProof - struct 2.7550 ms/op 2.6124 ms/op 1.05
validate gossip attestation - struct 1.3167 ms/op 1.2457 ms/op 1.06
pickEth1Vote - no votes 1.2268 ms/op 1.2462 ms/op 0.98
pickEth1Vote - max votes 10.118 ms/op 9.7038 ms/op 1.04
pickEth1Vote - Eth1Data hashTreeRoot value x2048 8.6556 ms/op 8.4850 ms/op 1.02
pickEth1Vote - Eth1Data hashTreeRoot tree x2048 14.580 ms/op 14.606 ms/op 1.00
pickEth1Vote - Eth1Data fastSerialize value x2048 649.71 us/op 645.18 us/op 1.01
pickEth1Vote - Eth1Data fastSerialize tree x2048 7.9379 ms/op 7.6090 ms/op 1.04
bytes32 toHexString 490.00 ns/op 459.00 ns/op 1.07
bytes32 Buffer.toString(hex) 341.00 ns/op 325.00 ns/op 1.05
bytes32 Buffer.toString(hex) from Uint8Array 549.00 ns/op 504.00 ns/op 1.09
bytes32 Buffer.toString(hex) + 0x 337.00 ns/op 328.00 ns/op 1.03
Object access 1 prop 0.16300 ns/op 0.14500 ns/op 1.12
Map access 1 prop 0.15300 ns/op 0.14500 ns/op 1.06
Object get x1000 6.6400 ns/op 6.3510 ns/op 1.05
Map get x1000 0.60300 ns/op 0.59100 ns/op 1.02
Object set x1000 51.256 ns/op 48.847 ns/op 1.05
Map set x1000 43.355 ns/op 40.765 ns/op 1.06
Return object 10000 times 0.23450 ns/op 0.22230 ns/op 1.05
Throw Error 10000 times 4.2544 us/op 4.0445 us/op 1.05
fastMsgIdFn sha256 / 200 bytes 3.3850 us/op 3.2610 us/op 1.04
fastMsgIdFn h32 xxhash / 200 bytes 265.00 ns/op 258.00 ns/op 1.03
fastMsgIdFn h64 xxhash / 200 bytes 385.00 ns/op 368.00 ns/op 1.05
fastMsgIdFn sha256 / 1000 bytes 11.522 us/op 11.063 us/op 1.04
fastMsgIdFn h32 xxhash / 1000 bytes 399.00 ns/op 380.00 ns/op 1.05
fastMsgIdFn h64 xxhash / 1000 bytes 464.00 ns/op 453.00 ns/op 1.02
fastMsgIdFn sha256 / 10000 bytes 103.76 us/op 103.58 us/op 1.00
fastMsgIdFn h32 xxhash / 10000 bytes 1.9180 us/op 1.8400 us/op 1.04
fastMsgIdFn h64 xxhash / 10000 bytes 1.3670 us/op 1.2990 us/op 1.05
enrSubnets - fastDeserialize 64 bits 1.2700 us/op 1.2530 us/op 1.01
enrSubnets - ssz BitVector 64 bits 476.00 ns/op 468.00 ns/op 1.02
enrSubnets - fastDeserialize 4 bits 164.00 ns/op 160.00 ns/op 1.02
enrSubnets - ssz BitVector 4 bits 484.00 ns/op 470.00 ns/op 1.03
prioritizePeers score -10:0 att 32-0.1 sync 2-0 102.53 us/op 103.20 us/op 0.99
prioritizePeers score 0:0 att 32-0.25 sync 2-0.25 130.07 us/op 127.19 us/op 1.02
prioritizePeers score 0:0 att 32-0.5 sync 2-0.5 162.56 us/op 160.94 us/op 1.01
prioritizePeers score 0:0 att 64-0.75 sync 4-0.75 291.82 us/op 296.52 us/op 0.98
prioritizePeers score 0:0 att 64-1 sync 4-1 354.22 us/op 359.09 us/op 0.99
array of 16000 items push then shift 1.5890 us/op 1.5461 us/op 1.03
LinkedList of 16000 items push then shift 8.5950 ns/op 8.4490 ns/op 1.02
array of 16000 items push then pop 79.568 ns/op 73.754 ns/op 1.08
LinkedList of 16000 items push then pop 8.3320 ns/op 8.1550 ns/op 1.02
array of 24000 items push then shift 2.2978 us/op 2.3590 us/op 0.97
LinkedList of 24000 items push then shift 8.5240 ns/op 8.5490 ns/op 1.00
array of 24000 items push then pop 79.875 ns/op 72.305 ns/op 1.10
LinkedList of 24000 items push then pop 8.4740 ns/op 8.1000 ns/op 1.05
intersect bitArray bitLen 8 13.262 ns/op 12.639 ns/op 1.05
intersect array and set length 8 78.054 ns/op 74.353 ns/op 1.05
intersect bitArray bitLen 128 43.974 ns/op 41.904 ns/op 1.05
intersect array and set length 128 1.0434 us/op 995.40 ns/op 1.05
Buffer.concat 32 items 2.6530 us/op 2.5040 us/op 1.06
Uint8Array.set 32 items 2.9900 us/op 2.3320 us/op 1.28
pass gossip attestations to forkchoice per slot 2.9836 ms/op 2.9959 ms/op 1.00
computeDeltas 3.4138 ms/op 2.8321 ms/op 1.21
computeProposerBoostScoreFromBalances 1.7788 ms/op 1.7606 ms/op 1.01
altair processAttestation - 250000 vs - 7PWei normalcase 2.1359 ms/op 2.1049 ms/op 1.01
altair processAttestation - 250000 vs - 7PWei worstcase 3.1858 ms/op 3.1840 ms/op 1.00
altair processAttestation - setStatus - 1/6 committees join 139.61 us/op 137.69 us/op 1.01
altair processAttestation - setStatus - 1/3 committees join 273.02 us/op 273.16 us/op 1.00
altair processAttestation - setStatus - 1/2 committees join 362.11 us/op 365.95 us/op 0.99
altair processAttestation - setStatus - 2/3 committees join 454.53 us/op 464.30 us/op 0.98
altair processAttestation - setStatus - 4/5 committees join 636.56 us/op 643.25 us/op 0.99
altair processAttestation - setStatus - 100% committees join 747.20 us/op 754.32 us/op 0.99
altair processBlock - 250000 vs - 7PWei normalcase 18.557 ms/op 14.341 ms/op 1.29
altair processBlock - 250000 vs - 7PWei normalcase hashState 25.621 ms/op 27.997 ms/op 0.92
altair processBlock - 250000 vs - 7PWei worstcase 51.965 ms/op 46.538 ms/op 1.12
altair processBlock - 250000 vs - 7PWei worstcase hashState 64.686 ms/op 66.663 ms/op 0.97
phase0 processBlock - 250000 vs - 7PWei normalcase 2.0243 ms/op 2.3305 ms/op 0.87
phase0 processBlock - 250000 vs - 7PWei worstcase 27.429 ms/op 28.525 ms/op 0.96
altair processEth1Data - 250000 vs - 7PWei normalcase 471.55 us/op 449.19 us/op 1.05
vc - 250000 eb 1 eth1 1 we 0 wn 0 - smpl 15 6.7140 us/op 6.6210 us/op 1.01
vc - 250000 eb 0.95 eth1 0.1 we 0.05 wn 0 - smpl 219 19.216 us/op 19.619 us/op 0.98
vc - 250000 eb 0.95 eth1 0.3 we 0.05 wn 0 - smpl 42 8.2670 us/op 8.2720 us/op 1.00
vc - 250000 eb 0.95 eth1 0.7 we 0.05 wn 0 - smpl 18 6.2490 us/op 6.3210 us/op 0.99
vc - 250000 eb 0.1 eth1 0.1 we 0 wn 0 - smpl 1020 73.745 us/op 76.473 us/op 0.96
vc - 250000 eb 0.03 eth1 0.03 we 0 wn 0 - smpl 11777 607.67 us/op 631.84 us/op 0.96
vc - 250000 eb 0.01 eth1 0.01 we 0 wn 0 - smpl 16384 903.05 us/op 902.04 us/op 1.00
vc - 250000 eb 0 eth1 0 we 0 wn 0 - smpl 16384 885.02 us/op 883.96 us/op 1.00
vc - 250000 eb 0 eth1 0 we 0 wn 0 nocache - smpl 16384 2.2489 ms/op 2.2794 ms/op 0.99
vc - 250000 eb 0 eth1 1 we 0 wn 0 - smpl 16384 1.4617 ms/op 1.4721 ms/op 0.99
vc - 250000 eb 0 eth1 1 we 0 wn 0 nocache - smpl 16384 3.7684 ms/op 3.7615 ms/op 1.00
Tree 40 250000 create 312.37 ms/op 297.30 ms/op 1.05
Tree 40 250000 get(125000) 179.66 ns/op 179.41 ns/op 1.00
Tree 40 250000 set(125000) 922.84 ns/op 881.79 ns/op 1.05
Tree 40 250000 toArray() 16.624 ms/op 17.107 ms/op 0.97
Tree 40 250000 iterate all - toArray() + loop 17.895 ms/op 17.722 ms/op 1.01
Tree 40 250000 iterate all - get(i) 64.996 ms/op 67.643 ms/op 0.96
MutableVector 250000 create 9.6516 ms/op 9.3580 ms/op 1.03
MutableVector 250000 get(125000) 6.2550 ns/op 6.7000 ns/op 0.93
MutableVector 250000 set(125000) 241.75 ns/op 239.70 ns/op 1.01
MutableVector 250000 toArray() 2.6646 ms/op 2.7117 ms/op 0.98
MutableVector 250000 iterate all - toArray() + loop 2.7023 ms/op 2.7266 ms/op 0.99
MutableVector 250000 iterate all - get(i) 1.5287 ms/op 1.5012 ms/op 1.02
Array 250000 create 2.5190 ms/op 2.5661 ms/op 0.98
Array 250000 clone - spread 1.1968 ms/op 1.0911 ms/op 1.10
Array 250000 get(125000) 0.55200 ns/op 0.53900 ns/op 1.02
Array 250000 set(125000) 0.64400 ns/op 0.60500 ns/op 1.06
Array 250000 iterate all - loop 101.71 us/op 85.303 us/op 1.19
effectiveBalanceIncrements clone Uint8Array 300000 24.799 us/op 24.290 us/op 1.02
effectiveBalanceIncrements clone MutableVector 300000 356.00 ns/op 328.00 ns/op 1.09
effectiveBalanceIncrements rw all Uint8Array 300000 168.73 us/op 167.13 us/op 1.01
effectiveBalanceIncrements rw all MutableVector 300000 80.691 ms/op 77.136 ms/op 1.05
phase0 afterProcessEpoch - 250000 vs - 7PWei 110.71 ms/op 111.16 ms/op 1.00
phase0 beforeProcessEpoch - 250000 vs - 7PWei 42.359 ms/op 42.916 ms/op 0.99
altair processEpoch - mainnet_e81889 311.21 ms/op 312.59 ms/op 1.00
mainnet_e81889 - altair beforeProcessEpoch 63.282 ms/op 63.190 ms/op 1.00
mainnet_e81889 - altair processJustificationAndFinalization 18.154 us/op 17.080 us/op 1.06
mainnet_e81889 - altair processInactivityUpdates 5.1453 ms/op 5.5699 ms/op 0.92
mainnet_e81889 - altair processRewardsAndPenalties 63.934 ms/op 68.965 ms/op 0.93
mainnet_e81889 - altair processRegistryUpdates 2.8890 us/op 2.3750 us/op 1.22
mainnet_e81889 - altair processSlashings 433.00 ns/op 442.00 ns/op 0.98
mainnet_e81889 - altair processEth1DataReset 514.00 ns/op 449.00 ns/op 1.14
mainnet_e81889 - altair processEffectiveBalanceUpdates 1.2359 ms/op 1.2111 ms/op 1.02
mainnet_e81889 - altair processSlashingsReset 4.0250 us/op 4.7330 us/op 0.85
mainnet_e81889 - altair processRandaoMixesReset 4.6170 us/op 4.3890 us/op 1.05
mainnet_e81889 - altair processHistoricalRootsUpdate 595.00 ns/op 560.00 ns/op 1.06
mainnet_e81889 - altair processParticipationFlagUpdates 2.3760 us/op 2.5320 us/op 0.94
mainnet_e81889 - altair processSyncCommitteeUpdates 487.00 ns/op 520.00 ns/op 0.94
mainnet_e81889 - altair afterProcessEpoch 115.58 ms/op 114.39 ms/op 1.01
phase0 processEpoch - mainnet_e58758 314.74 ms/op 314.18 ms/op 1.00
mainnet_e58758 - phase0 beforeProcessEpoch 123.04 ms/op 120.48 ms/op 1.02
mainnet_e58758 - phase0 processJustificationAndFinalization 17.431 us/op 16.300 us/op 1.07
mainnet_e58758 - phase0 processRewardsAndPenalties 57.243 ms/op 54.395 ms/op 1.05
mainnet_e58758 - phase0 processRegistryUpdates 7.4750 us/op 7.6110 us/op 0.98
mainnet_e58758 - phase0 processSlashings 586.00 ns/op 506.00 ns/op 1.16
mainnet_e58758 - phase0 processEth1DataReset 533.00 ns/op 474.00 ns/op 1.12
mainnet_e58758 - phase0 processEffectiveBalanceUpdates 948.37 us/op 942.28 us/op 1.01
mainnet_e58758 - phase0 processSlashingsReset 3.1960 us/op 3.2460 us/op 0.98
mainnet_e58758 - phase0 processRandaoMixesReset 4.2950 us/op 4.3730 us/op 0.98
mainnet_e58758 - phase0 processHistoricalRootsUpdate 595.00 ns/op 585.00 ns/op 1.02
mainnet_e58758 - phase0 processParticipationRecordUpdates 3.7660 us/op 3.8950 us/op 0.97
mainnet_e58758 - phase0 afterProcessEpoch 95.681 ms/op 96.003 ms/op 1.00
phase0 processEffectiveBalanceUpdates - 250000 normalcase 1.2341 ms/op 1.1756 ms/op 1.05
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5 1.4662 ms/op 1.4418 ms/op 1.02
altair processInactivityUpdates - 250000 normalcase 21.173 ms/op 22.886 ms/op 0.93
altair processInactivityUpdates - 250000 worstcase 21.273 ms/op 22.674 ms/op 0.94
phase0 processRegistryUpdates - 250000 normalcase 6.2960 us/op 6.3380 us/op 0.99
phase0 processRegistryUpdates - 250000 badcase_full_deposits 230.49 us/op 239.42 us/op 0.96
phase0 processRegistryUpdates - 250000 worstcase 0.5 106.43 ms/op 111.90 ms/op 0.95
altair processRewardsAndPenalties - 250000 normalcase 50.346 ms/op 59.653 ms/op 0.84
altair processRewardsAndPenalties - 250000 worstcase 60.663 ms/op 60.434 ms/op 1.00
phase0 getAttestationDeltas - 250000 normalcase 6.5742 ms/op 6.2762 ms/op 1.05
phase0 getAttestationDeltas - 250000 worstcase 6.5190 ms/op 6.5478 ms/op 1.00
phase0 processSlashings - 250000 worstcase 3.4531 ms/op 3.4627 ms/op 1.00
altair processSyncCommitteeUpdates - 250000 166.60 ms/op 166.44 ms/op 1.00
BeaconState.hashTreeRoot - No change 257.00 ns/op 248.00 ns/op 1.04
BeaconState.hashTreeRoot - 1 full validator 50.428 us/op 50.285 us/op 1.00
BeaconState.hashTreeRoot - 32 full validator 498.66 us/op 505.24 us/op 0.99
BeaconState.hashTreeRoot - 512 full validator 5.1317 ms/op 4.9317 ms/op 1.04
BeaconState.hashTreeRoot - 1 validator.effectiveBalance 60.461 us/op 62.887 us/op 0.96
BeaconState.hashTreeRoot - 32 validator.effectiveBalance 875.37 us/op 860.21 us/op 1.02
BeaconState.hashTreeRoot - 512 validator.effectiveBalance 11.015 ms/op 12.101 ms/op 0.91
BeaconState.hashTreeRoot - 1 balances 46.768 us/op 49.470 us/op 0.95
BeaconState.hashTreeRoot - 32 balances 434.52 us/op 446.73 us/op 0.97
BeaconState.hashTreeRoot - 512 balances 4.2119 ms/op 4.3958 ms/op 0.96
BeaconState.hashTreeRoot - 250000 balances 73.926 ms/op 72.684 ms/op 1.02
aggregationBits - 2048 els - zipIndexesInBitList 16.383 us/op 16.204 us/op 1.01
regular array get 100000 times 32.079 us/op 41.317 us/op 0.78
wrappedArray get 100000 times 32.082 us/op 32.446 us/op 0.99
arrayWithProxy get 100000 times 16.369 ms/op 16.408 ms/op 1.00
ssz.Root.equals 517.00 ns/op 613.00 ns/op 0.84
byteArrayEquals 512.00 ns/op 550.00 ns/op 0.93
shuffle list - 16384 els 6.7243 ms/op 6.9761 ms/op 0.96
shuffle list - 250000 els 98.811 ms/op 102.50 ms/op 0.96
processSlot - 1 slots 8.4840 us/op 8.6500 us/op 0.98
processSlot - 32 slots 1.3006 ms/op 1.3729 ms/op 0.95
getEffectiveBalanceIncrementsZeroInactive - 250000 vs - 7PWei 33.478 ms/op 35.261 ms/op 0.95
getCommitteeAssignments - req 1 vs - 250000 vc 2.9559 ms/op 2.9218 ms/op 1.01
getCommitteeAssignments - req 100 vs - 250000 vc 4.1730 ms/op 4.1527 ms/op 1.00
getCommitteeAssignments - req 1000 vs - 250000 vc 4.5065 ms/op 4.4610 ms/op 1.01
RootCache.getBlockRootAtSlot - 250000 vs - 7PWei 4.4100 ns/op 4.6900 ns/op 0.94
state getBlockRootAtSlot - 250000 vs - 7PWei 959.28 ns/op 657.21 ns/op 1.46
computeProposers - vc 250000 10.453 ms/op 10.783 ms/op 0.97
computeEpochShuffling - vc 250000 98.848 ms/op 105.03 ms/op 0.94
getNextSyncCommittee - vc 250000 167.83 ms/op 178.65 ms/op 0.94

by benchmarkbot/action

@wemeetagain wemeetagain merged commit 4f2d811 into unstable Apr 3, 2023
@wemeetagain wemeetagain deleted the nflaig/handle-timeout-errors branch April 3, 2023 17:20
@nflaig nflaig mentioned this pull request Apr 8, 2023
Merged
4 tasks
@wemeetagain
Copy link
Member

🎉 This PR is included in v1.8.0 🎉

This was referenced Jul 20, 2023
Merged
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@wemeetagain wemeetagain wemeetagain 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.
2 participants
@nflaig @wemeetagain