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

Preventing MaxListenersExceededWarning #4421

Merged
merged 6 commits into from
Sep 1, 2022

Conversation

dadepo
Copy link
Contributor

@dadepo dadepo commented Aug 15, 2022

Motivation

See #3569 and # #4394 for bug report

Description

The waitForBlockSlot should execute once per slot and per slot there should be a ValidatorEvent.chainHead event emitted In the unexpected situation where ValidatorEvent.chainHead is never emitted or is emitted but takes longer to propagate to the validator, to prevent accumulating listeners for ValidatorEvent.chainHead and triggering MaxListenersExceededWarning.

This PR clears listener for ValidatorEvent.chainHead if any before setting a new one.

Closes #3569

Beacon Node

  • Leak Related to use of Any-signal in Res/Req
  (node:56301) MaxListenersExceededWarning: Possible EventTarget memory leak detected. 11 abort listeners added to [AbortSignal]. Use events.setMaxListeners() to increase limit
    at AbortSignal.[kNewListener] (node:internal/event_target:426:17)
    at AbortSignal.[kNewListener] (node:internal/abort_controller:173:24)
    at AbortSignal.addEventListener (node:internal/event_target:535:23)
    at anySignal (/Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/node_modules/any-signal/index.js:27:12)
    at withTimeout (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/utils/src/timeout.ts:11:34)
    at sendRequest (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/network/reqresp/request/index.ts:87:50)
    at ReqResp.sendRequest (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/network/reqresp/reqResp.ts:154:28)
    at ReqResp.status (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/network/reqresp/reqResp.ts:92:23)
    at PeerManager.requestStatus (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/network/peers/peerManager.ts:359:46)
    at file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/network/peers/peerManager.ts:368:56
  • Leak Related to jsonRpcHttpClient
(node:56301) MaxListenersExceededWarning: Possible EventTarget memory leak detected. 11 abort listeners added to [AbortSignal]. Use events.setMaxListeners() to increase limit
    at AbortSignal.[kNewListener] (node:internal/event_target:426:17)
    at AbortSignal.[kNewListener] (node:internal/abort_controller:173:24)
    at AbortSignal.addEventListener (node:internal/event_target:535:23)
    at JsonRpcHttpClient.fetchJsonOneUrl (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/eth1/provider/jsonRpcHttpClient.ts:194:24)
    at JsonRpcHttpClient.fetchJson (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/eth1/provider/jsonRpcHttpClient.ts:160:27)
    at retry.retries._b (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/eth1/provider/jsonRpcHttpClient.ts:125:27)
    at retry (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/utils/src/retry.ts:33:20)
    at JsonRpcHttpClient.fetchWithRetries (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/eth1/provider/jsonRpcHttpClient.ts:119:23)
    at ExecutionEngineHttp.exchangeTransitionConfigurationV1 (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/execution/engine/http.ts:298:27)
    at BeaconChain.exchangeTransitionConfiguration (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/chain/chain.ts:573:62)
Aug-17 21:32:00.064[CHAI

Validator Client
Spent some time trying to reproducing the warning for the validator client but could not. Even though back in January I observed the warning emanating from ValidatorEventEmitter see #3569

@dadepo dadepo requested a review from a team as a code owner August 15, 2022 21:38
@github-actions
Copy link
Contributor

github-actions bot commented Aug 15, 2022

Performance Report

✔️ no performance regression detected

Full benchmark results
Benchmark suite Current: 73efabf Previous: 506630e Ratio
getPubkeys - index2pubkey - req 1000 vs - 250000 vc 2.6182 ms/op 2.1565 ms/op 1.21
getPubkeys - validatorsArr - req 1000 vs - 250000 vc 71.511 us/op 69.709 us/op 1.03
BLS verify - blst-native 2.1728 ms/op 1.6419 ms/op 1.32
BLS verifyMultipleSignatures 3 - blst-native 4.4802 ms/op 3.3636 ms/op 1.33
BLS verifyMultipleSignatures 8 - blst-native 9.6740 ms/op 7.2327 ms/op 1.34
BLS verifyMultipleSignatures 32 - blst-native 35.159 ms/op 26.240 ms/op 1.34
BLS aggregatePubkeys 32 - blst-native 47.206 us/op 35.022 us/op 1.35
BLS aggregatePubkeys 128 - blst-native 183.42 us/op 134.35 us/op 1.37
getAttestationsForBlock 159.64 ms/op 169.54 ms/op 0.94
isKnown best case - 1 super set check 490.00 ns/op 439.00 ns/op 1.12
isKnown normal case - 2 super set checks 479.00 ns/op 426.00 ns/op 1.12
isKnown worse case - 16 super set checks 479.00 ns/op 424.00 ns/op 1.13
CheckpointStateCache - add get delete 9.5070 us/op 9.2560 us/op 1.03
validate gossip signedAggregateAndProof - struct 5.0213 ms/op 4.2604 ms/op 1.18
validate gossip attestation - struct 2.3643 ms/op 2.0315 ms/op 1.16
altair verifyImport mainnet_s3766816:31 4.7754 s/op 4.6083 s/op 1.04
pickEth1Vote - no votes 2.2051 ms/op 1.9568 ms/op 1.13
pickEth1Vote - max votes 25.034 ms/op 22.652 ms/op 1.11
pickEth1Vote - Eth1Data hashTreeRoot value x2048 13.514 ms/op 10.653 ms/op 1.27
pickEth1Vote - Eth1Data hashTreeRoot tree x2048 25.322 ms/op 22.073 ms/op 1.15
pickEth1Vote - Eth1Data fastSerialize value x2048 1.4602 ms/op 1.2860 ms/op 1.14
pickEth1Vote - Eth1Data fastSerialize tree x2048 14.698 ms/op 12.503 ms/op 1.18
bytes32 toHexString 1.0810 us/op 897.00 ns/op 1.21
bytes32 Buffer.toString(hex) 766.00 ns/op 586.00 ns/op 1.31
bytes32 Buffer.toString(hex) from Uint8Array 1.0300 us/op 804.00 ns/op 1.28
bytes32 Buffer.toString(hex) + 0x 774.00 ns/op 612.00 ns/op 1.26
Object access 1 prop 0.38300 ns/op 0.31900 ns/op 1.20
Map access 1 prop 0.32900 ns/op 0.26400 ns/op 1.25
Object get x1000 10.892 ns/op 15.750 ns/op 0.69
Map get x1000 1.0840 ns/op 0.98900 ns/op 1.10
Object set x1000 79.841 ns/op 108.83 ns/op 0.73
Map set x1000 52.758 ns/op 65.583 ns/op 0.80
Return object 10000 times 0.44220 ns/op 0.33060 ns/op 1.34
Throw Error 10000 times 6.2442 us/op 5.2111 us/op 1.20
enrSubnets - fastDeserialize 64 bits 2.7720 us/op 2.5590 us/op 1.08
enrSubnets - ssz BitVector 64 bits 811.00 ns/op 668.00 ns/op 1.21
enrSubnets - fastDeserialize 4 bits 383.00 ns/op 367.00 ns/op 1.04
enrSubnets - ssz BitVector 4 bits 818.00 ns/op 660.00 ns/op 1.24
prioritizePeers score -10:0 att 32-0.1 sync 2-0 86.966 us/op 93.682 us/op 0.93
prioritizePeers score 0:0 att 32-0.25 sync 2-0.25 115.70 us/op 124.33 us/op 0.93
prioritizePeers score 0:0 att 32-0.5 sync 2-0.5 205.74 us/op 214.60 us/op 0.96
prioritizePeers score 0:0 att 64-0.75 sync 4-0.75 400.27 us/op 452.96 us/op 0.88
prioritizePeers score 0:0 att 64-1 sync 4-1 408.28 us/op 470.17 us/op 0.87
RateTracker 1000000 limit, 1 obj count per request 186.03 ns/op 183.83 ns/op 1.01
RateTracker 1000000 limit, 2 obj count per request 137.44 ns/op 139.03 ns/op 0.99
RateTracker 1000000 limit, 4 obj count per request 113.35 ns/op 114.83 ns/op 0.99
RateTracker 1000000 limit, 8 obj count per request 101.23 ns/op 101.87 ns/op 0.99
RateTracker with prune 4.2530 us/op 4.4300 us/op 0.96
array of 16000 items push then shift 51.598 us/op 3.1857 us/op 16.20
LinkedList of 16000 items push then shift 17.755 ns/op 29.239 ns/op 0.61
array of 16000 items push then pop 213.16 ns/op 232.10 ns/op 0.92
LinkedList of 16000 items push then pop 15.134 ns/op 24.228 ns/op 0.62
array of 24000 items push then shift 77.385 us/op 4.0384 us/op 19.16
LinkedList of 24000 items push then shift 23.013 ns/op 31.000 ns/op 0.74
array of 24000 items push then pop 208.22 ns/op 209.29 ns/op 0.99
LinkedList of 24000 items push then pop 17.051 ns/op 22.978 ns/op 0.74
intersect bitArray bitLen 8 10.785 ns/op 10.300 ns/op 1.05
intersect array and set length 8 155.73 ns/op 149.67 ns/op 1.04
intersect bitArray bitLen 128 55.477 ns/op 71.301 ns/op 0.78
intersect array and set length 128 1.8497 us/op 2.2563 us/op 0.82
Buffer.concat 32 items 1.8690 ns/op 1.9430 ns/op 0.96
pass gossip attestations to forkchoice per slot 3.1398 ms/op 5.0002 ms/op 0.63
computeDeltas 4.8348 ms/op 5.2547 ms/op 0.92
computeProposerBoostScoreFromBalances 805.43 us/op 812.70 us/op 0.99
altair processAttestation - 250000 vs - 7PWei normalcase 4.2595 ms/op 3.9656 ms/op 1.07
altair processAttestation - 250000 vs - 7PWei worstcase 6.1607 ms/op 6.3713 ms/op 0.97
altair processAttestation - setStatus - 1/6 committees join 183.32 us/op 194.89 us/op 0.94
altair processAttestation - setStatus - 1/3 committees join 353.54 us/op 372.32 us/op 0.95
altair processAttestation - setStatus - 1/2 committees join 500.30 us/op 516.32 us/op 0.97
altair processAttestation - setStatus - 2/3 committees join 651.03 us/op 739.45 us/op 0.88
altair processAttestation - setStatus - 4/5 committees join 916.96 us/op 1.0292 ms/op 0.89
altair processAttestation - setStatus - 100% committees join 1.0985 ms/op 1.1053 ms/op 0.99
altair processBlock - 250000 vs - 7PWei normalcase 28.414 ms/op 28.926 ms/op 0.98
altair processBlock - 250000 vs - 7PWei normalcase hashState 46.306 ms/op 40.486 ms/op 1.14
altair processBlock - 250000 vs - 7PWei worstcase 90.330 ms/op 91.273 ms/op 0.99
altair processBlock - 250000 vs - 7PWei worstcase hashState 99.615 ms/op 91.184 ms/op 1.09
phase0 processBlock - 250000 vs - 7PWei normalcase 3.9698 ms/op 4.0165 ms/op 0.99
phase0 processBlock - 250000 vs - 7PWei worstcase 52.916 ms/op 47.711 ms/op 1.11
altair processEth1Data - 250000 vs - 7PWei normalcase 937.27 us/op 1.1943 ms/op 0.78
Tree 40 250000 create 701.23 ms/op 857.90 ms/op 0.82
Tree 40 250000 get(125000) 244.70 ns/op 324.32 ns/op 0.75
Tree 40 250000 set(125000) 1.9236 us/op 2.4159 us/op 0.80
Tree 40 250000 toArray() 29.207 ms/op 36.723 ms/op 0.80
Tree 40 250000 iterate all - toArray() + loop 31.569 ms/op 36.450 ms/op 0.87
Tree 40 250000 iterate all - get(i) 110.37 ms/op 114.13 ms/op 0.97
MutableVector 250000 create 19.356 ms/op 23.956 ms/op 0.81
MutableVector 250000 get(125000) 10.993 ns/op 13.219 ns/op 0.83
MutableVector 250000 set(125000) 435.50 ns/op 526.48 ns/op 0.83
MutableVector 250000 toArray() 5.6653 ms/op 6.9111 ms/op 0.82
MutableVector 250000 iterate all - toArray() + loop 5.6375 ms/op 6.7873 ms/op 0.83
MutableVector 250000 iterate all - get(i) 2.6111 ms/op 2.9053 ms/op 0.90
Array 250000 create 5.4224 ms/op 6.5648 ms/op 0.83
Array 250000 clone - spread 2.3781 ms/op 2.6393 ms/op 0.90
Array 250000 get(125000) 1.1580 ns/op 1.1550 ns/op 1.00
Array 250000 set(125000) 1.1510 ns/op 1.1580 ns/op 0.99
Array 250000 iterate all - loop 153.23 us/op 170.61 us/op 0.90
effectiveBalanceIncrements clone Uint8Array 300000 35.410 us/op 88.579 us/op 0.40
effectiveBalanceIncrements clone MutableVector 300000 722.00 ns/op 813.00 ns/op 0.89
effectiveBalanceIncrements rw all Uint8Array 300000 247.26 us/op 252.69 us/op 0.98
effectiveBalanceIncrements rw all MutableVector 300000 135.07 ms/op 198.85 ms/op 0.68
phase0 afterProcessEpoch - 250000 vs - 7PWei 187.52 ms/op 203.85 ms/op 0.92
phase0 beforeProcessEpoch - 250000 vs - 7PWei 109.86 ms/op 151.66 ms/op 0.72
altair processEpoch - mainnet_e81889 645.96 ms/op 745.36 ms/op 0.87
mainnet_e81889 - altair beforeProcessEpoch 175.90 ms/op 222.65 ms/op 0.79
mainnet_e81889 - altair processJustificationAndFinalization 21.441 us/op 19.891 us/op 1.08
mainnet_e81889 - altair processInactivityUpdates 8.4602 ms/op 11.079 ms/op 0.76
mainnet_e81889 - altair processRewardsAndPenalties 155.76 ms/op 194.74 ms/op 0.80
mainnet_e81889 - altair processRegistryUpdates 3.7420 us/op 4.0470 us/op 0.92
mainnet_e81889 - altair processSlashings 676.00 ns/op 1.0990 us/op 0.62
mainnet_e81889 - altair processEth1DataReset 772.00 ns/op 872.00 ns/op 0.89
mainnet_e81889 - altair processEffectiveBalanceUpdates 2.2341 ms/op 2.6306 ms/op 0.85
mainnet_e81889 - altair processSlashingsReset 4.0980 us/op 5.0270 us/op 0.82
mainnet_e81889 - altair processRandaoMixesReset 3.9070 us/op 7.0300 us/op 0.56
mainnet_e81889 - altair processHistoricalRootsUpdate 663.00 ns/op 861.00 ns/op 0.77
mainnet_e81889 - altair processParticipationFlagUpdates 2.4170 us/op 3.9840 us/op 0.61
mainnet_e81889 - altair processSyncCommitteeUpdates 575.00 ns/op 1.2430 us/op 0.46
mainnet_e81889 - altair afterProcessEpoch 197.23 ms/op 193.86 ms/op 1.02
phase0 processEpoch - mainnet_e58758 618.33 ms/op 698.92 ms/op 0.88
mainnet_e58758 - phase0 beforeProcessEpoch 235.97 ms/op 298.11 ms/op 0.79
mainnet_e58758 - phase0 processJustificationAndFinalization 17.190 us/op 29.984 us/op 0.57
mainnet_e58758 - phase0 processRewardsAndPenalties 135.18 ms/op 153.23 ms/op 0.88
mainnet_e58758 - phase0 processRegistryUpdates 7.5730 us/op 9.0020 us/op 0.84
mainnet_e58758 - phase0 processSlashings 667.00 ns/op 717.00 ns/op 0.93
mainnet_e58758 - phase0 processEth1DataReset 641.00 ns/op 756.00 ns/op 0.85
mainnet_e58758 - phase0 processEffectiveBalanceUpdates 1.6630 ms/op 2.0276 ms/op 0.82
mainnet_e58758 - phase0 processSlashingsReset 4.5260 us/op 4.8610 us/op 0.93
mainnet_e58758 - phase0 processRandaoMixesReset 5.8150 us/op 5.2170 us/op 1.11
mainnet_e58758 - phase0 processHistoricalRootsUpdate 812.00 ns/op 845.00 ns/op 0.96
mainnet_e58758 - phase0 processParticipationRecordUpdates 5.3030 us/op 5.3590 us/op 0.99
mainnet_e58758 - phase0 afterProcessEpoch 162.48 ms/op 160.42 ms/op 1.01
phase0 processEffectiveBalanceUpdates - 250000 normalcase 2.0897 ms/op 2.6387 ms/op 0.79
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5 2.2326 ms/op 3.0807 ms/op 0.72
altair processInactivityUpdates - 250000 normalcase 52.171 ms/op 46.468 ms/op 1.12
altair processInactivityUpdates - 250000 worstcase 55.172 ms/op 59.030 ms/op 0.93
phase0 processRegistryUpdates - 250000 normalcase 7.2610 us/op 12.692 us/op 0.57
phase0 processRegistryUpdates - 250000 badcase_full_deposits 374.52 us/op 515.63 us/op 0.73
phase0 processRegistryUpdates - 250000 worstcase 0.5 215.84 ms/op 272.41 ms/op 0.79
altair processRewardsAndPenalties - 250000 normalcase 130.61 ms/op 164.22 ms/op 0.80
altair processRewardsAndPenalties - 250000 worstcase 130.40 ms/op 163.48 ms/op 0.80
phase0 getAttestationDeltas - 250000 normalcase 11.532 ms/op 12.302 ms/op 0.94
phase0 getAttestationDeltas - 250000 worstcase 11.776 ms/op 13.233 ms/op 0.89
phase0 processSlashings - 250000 worstcase 5.1103 ms/op 5.4134 ms/op 0.94
altair processSyncCommitteeUpdates - 250000 288.31 ms/op 265.55 ms/op 1.09
BeaconState.hashTreeRoot - No change 531.00 ns/op 529.00 ns/op 1.00
BeaconState.hashTreeRoot - 1 full validator 71.427 us/op 54.874 us/op 1.30
BeaconState.hashTreeRoot - 32 full validator 714.43 us/op 630.33 us/op 1.13
BeaconState.hashTreeRoot - 512 full validator 7.6018 ms/op 7.8598 ms/op 0.97
BeaconState.hashTreeRoot - 1 validator.effectiveBalance 90.415 us/op 80.004 us/op 1.13
BeaconState.hashTreeRoot - 32 validator.effectiveBalance 1.4836 ms/op 1.2741 ms/op 1.16
BeaconState.hashTreeRoot - 512 validator.effectiveBalance 18.250 ms/op 16.940 ms/op 1.08
BeaconState.hashTreeRoot - 1 balances 67.359 us/op 64.363 us/op 1.05
BeaconState.hashTreeRoot - 32 balances 705.51 us/op 651.72 us/op 1.08
BeaconState.hashTreeRoot - 512 balances 6.4989 ms/op 6.0489 ms/op 1.07
BeaconState.hashTreeRoot - 250000 balances 112.23 ms/op 101.70 ms/op 1.10
aggregationBits - 2048 els - zipIndexesInBitList 30.191 us/op 28.816 us/op 1.05
regular array get 100000 times 60.565 us/op 67.416 us/op 0.90
wrappedArray get 100000 times 60.604 us/op 67.409 us/op 0.90
arrayWithProxy get 100000 times 32.011 ms/op 34.829 ms/op 0.92
ssz.Root.equals 523.00 ns/op 446.00 ns/op 1.17
byteArrayEquals 445.00 ns/op 464.00 ns/op 0.96
shuffle list - 16384 els 11.371 ms/op 11.175 ms/op 1.02
shuffle list - 250000 els 167.83 ms/op 164.71 ms/op 1.02
processSlot - 1 slots 12.875 us/op 13.186 us/op 0.98
processSlot - 32 slots 1.9052 ms/op 1.6535 ms/op 1.15
getEffectiveBalanceIncrementsZeroInactive - 250000 vs - 7PWei 316.06 us/op 335.41 us/op 0.94
getCommitteeAssignments - req 1 vs - 250000 vc 5.4701 ms/op 5.2798 ms/op 1.04
getCommitteeAssignments - req 100 vs - 250000 vc 7.9916 ms/op 7.3470 ms/op 1.09
getCommitteeAssignments - req 1000 vs - 250000 vc 8.5740 ms/op 7.8097 ms/op 1.10
RootCache.getBlockRootAtSlot - 250000 vs - 7PWei 7.5800 ns/op 10.500 ns/op 0.72
state getBlockRootAtSlot - 250000 vs - 7PWei 1.0806 us/op 989.48 ns/op 1.09
computeProposers - vc 250000 17.373 ms/op 15.870 ms/op 1.09
computeEpochShuffling - vc 250000 170.52 ms/op 169.29 ms/op 1.01
getNextSyncCommittee - vc 250000 286.61 ms/op 267.97 ms/op 1.07

by benchmarkbot/action

// if any before setting a new one.
if (this.emitter.listenerCount(ValidatorEvent.chainHead) > 0) {
this.emitter.off(ValidatorEvent.chainHead, headListener);
}
this.emitter.on(ValidatorEvent.chainHead, headListener);
Copy link
Contributor

Choose a reason for hiding this comment

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

This solution looks very strange, I don't follow the argument. The handler headListener is created in this scope so it can be proven that headListener has never been subscribed to this event, it's impossible. So the line this.emitter.off(ValidatorEvent.chainHead, headListener) is useless.

I also want see first a hard proof that the MaxListenersExceededWarning comes actually from this specific listener, and not from sleep()

Copy link
Contributor Author

Choose a reason for hiding this comment

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

The handler headListener is created in this scope so it can be proven that headListener has never been subscribed to this event, it's impossible

In the case where waitForBlockSlot is called multiple times (before the unsubscribe), it is possible to have headListener subscribed multiple times. The intention of the check is to prevent this. But I will look into this again to ascertain your concern.

I also want see first a hard proof that the MaxListenersExceededWarning comes actually from this specific listener, and not from sleep()

I am almost certain it does not come from the sleep as no where in the sleep code path is EventEmitter used. The sleep code path makes use of AbortSignal and from what I see, that uses a different API. But will try and reproduce and confirm this.

@dapplion dapplion marked this pull request as draft August 18, 2022 19:01
// We set infinity to prevent MaxListenersExceededWarning which get logged when listeners > 10
// Since it is perfectly fine to have listeners > 10
emitter.setMaxListeners(Infinity);
setMaxListeners(Infinity, signal);
Copy link
Contributor

@dapplion dapplion Aug 23, 2022

Choose a reason for hiding this comment

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

Can you commit as comment the stack trace proving that this very specific event emitter gets more that 10 listeners?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I could not create a situation where the warning is triggered locally. So I have removed the changes.

@@ -118,6 +119,9 @@ export class BeaconNode {
metricsRegistries = [],
}: IBeaconNodeInitModules): Promise<T> {
const controller = new AbortController();
// We set infinity to prevent MaxListenersExceededWarning which get logged when listeners > 10
// Since it is perfectly fine to have listeners > 10
setMaxListeners(Infinity, controller.signal);
Copy link
Contributor

Choose a reason for hiding this comment

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

Can you commit as comment the stack trace proving that this very specific event emitter gets more that 10 listeners?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

The signal here was what was passed down and triggered this:

(node:56301) MaxListenersExceededWarning: Possible EventTarget memory leak detected. 11 abort listeners added to [AbortSignal]. Use events.setMaxListeners() to increase limit
    at AbortSignal.[kNewListener] (node:internal/event_target:426:17)
    at AbortSignal.[kNewListener] (node:internal/abort_controller:173:24)
    at AbortSignal.addEventListener (node:internal/event_target:535:23)
    at JsonRpcHttpClient.fetchJsonOneUrl (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/eth1/provider/jsonRpcHttpClient.ts:194:24)
    at JsonRpcHttpClient.fetchJson (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/eth1/provider/jsonRpcHttpClient.ts:160:27)
    at retry.retries._b (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/eth1/provider/jsonRpcHttpClient.ts:125:27)
    at retry (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/utils/src/retry.ts:33:20)
    at JsonRpcHttpClient.fetchWithRetries (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/eth1/provider/jsonRpcHttpClient.ts:119:23)
    at ExecutionEngineHttp.exchangeTransitionConfigurationV1 (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/execution/engine/http.ts:298:27)
    at BeaconChain.exchangeTransitionConfiguration (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/chain/chain.ts:573:62)
Aug-17 21:32:00.064[CHAI

@@ -52,7 +52,7 @@ export class AttestationService {
// A validator should create and broadcast the attestation to the associated attestation subnet when either
// (a) the validator has received a valid block from the expected block proposer for the assigned slot or
// (b) one-third of the slot has transpired (SECONDS_PER_SLOT / 3 seconds after the start of slot) -- whichever comes first.
await Promise.race([sleep(this.clock.msToSlot(slot + 1 / 3), signal), this.waitForBlockSlot(slot)]);
await Promise.race([this.waitForBlockSlot(slot), sleep(this.clock.msToSlot(slot + 1 / 3), signal)]);
Copy link
Contributor

Choose a reason for hiding this comment

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

Why is it necessary to change the order here?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

It was not a necessity. It was changed to align with the text of the spec, which was placed as a comment

Copy link
Contributor

Choose a reason for hiding this comment

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

What do you mean the spec? Where does the spec specify the order of promises in javascript?

@@ -41,6 +42,10 @@ export async function beaconHandler(args: IBeaconArgs & IGlobalArgs): Promise<vo
const options = beaconNodeOptions.getWithDefaults();

const abortController = new AbortController();
// We set infinity to prevent MaxListenersExceededWarning which get logged when listeners > 10
// Since it is perfectly fine to have listeners > 10
setMaxListeners(Infinity, abortController.signal);
Copy link
Contributor

Choose a reason for hiding this comment

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

Can you commit as comment the stack trace proving that this very specific event emitter gets more that 10 listeners?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I could not create a situation where the warning is triggered locally. So I have removed the changes

@@ -85,6 +86,10 @@ export class Validator {
} = opts;
const config = createIBeaconConfig(dbOps.config, genesis.genesisValidatorsRoot);
this.controller = new AbortController();
// We set infinity to prevent MaxListenersExceededWarning which get logged when listeners > 10
// Since it is perfectly fine to have listeners > 10
setMaxListeners(Infinity, this.controller.signal);
Copy link
Contributor

Choose a reason for hiding this comment

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

Can you commit as comment the stack trace proving that this very specific event emitter gets more that 10 listeners? Same for below

Copy link
Contributor Author

@dadepo dadepo Aug 24, 2022

Choose a reason for hiding this comment

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

I removed the changes for the abort controller, as I could find a situation where it triggered the warning. I left the one for ValidatorEventEmitter, even though I could not recreate the situation that triggered it, I did observe by chance back in January. See #3569. The log reproduced here

(node:15159) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 chainHead listeners added to [ValidatorEventEmitter]. Use emitter.setMaxListeners() to increase limit

@@ -71,6 +72,9 @@ export class ReqResp implements IReqResp {

async start(): Promise<void> {
this.controller = new AbortController();
// We set infinity to prevent MaxListenersExceededWarning which get logged when listeners > 10
// Since it is perfectly fine to have listeners > 10
setMaxListeners(Infinity, this.controller.signal);
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Responsible for the warning observed in the trace:

(node:56301) MaxListenersExceededWarning: Possible EventTarget memory leak detected. 11 abort listeners added to [AbortSignal]. Use events.setMaxListeners() to increase limit
    at AbortSignal.[kNewListener] (node:internal/event_target:426:17)
    at AbortSignal.[kNewListener] (node:internal/abort_controller:173:24)
    at AbortSignal.addEventListener (node:internal/event_target:535:23)
    at anySignal (/Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/node_modules/any-signal/index.js:27:12)
    at withTimeout (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/utils/src/timeout.ts:11:34)
    at sendRequest (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/network/reqresp/request/index.ts:87:50)
    at ReqResp.sendRequest (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/network/reqresp/reqResp.ts:154:28)
    at ReqResp.status (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/network/reqresp/reqResp.ts:92:23)
    at PeerManager.requestStatus (file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/network/peers/peerManager.ts:359:46)
    at file:///Users/dadepoaderemi/Documents/work/chainsafe/official/lodestar/packages/beacon-node/src/network/peers/peerManager.ts:368:56

@dadepo dadepo marked this pull request as ready for review August 24, 2022 10:03
private reqRespHandlers: ReqRespHandlers;
private metadataController: MetadataController;
private peerRpcScores: IPeerRpcScoreStore;
private inboundRateLimiter: IRateLimiter;
private networkEventBus: INetworkEventBus;
private controller = new AbortController();
Copy link
Contributor

Choose a reason for hiding this comment

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

Why do you need to initialize the AbortController on constructor?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Not sure why this is showing as a diff here, but this is not newly introduced. See it on unstable branch. See here

@@ -121,6 +121,10 @@ export class Validator {
}

const emitter = new ValidatorEventEmitter();
// Validator event emitter can have more than 10 listeners in a normal course of operation
// We set infinity to prevent MaxListenersExceededWarning which get logged when listeners > 10
emitter.setMaxListeners(Infinity);
Copy link
Contributor

Choose a reason for hiding this comment

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

Can you add proof with stack trace that this event listener triggers warnings?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Already responded to the diff in the comment here

Copy link
Member

@wemeetagain wemeetagain left a comment

Choose a reason for hiding this comment

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

LGTM

@@ -1,3 +1,4 @@
import {setMaxListeners} from "node:events";
Copy link
Member

Choose a reason for hiding this comment

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

Shame we have to introduce a nodejs specific api here.

Later we can pass down a signal from the top-level beacon node and avoid creating a new signal here.

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

Successfully merging this pull request may close these issues.

Investigate possible EventEmitter memory leak
3 participants