Beacon node active handles after close sequence is completed

[nflaig]

Describe the bug

In some rare cases when the node is running for a longer time it does not exit when receiving a exit signal.

Active handles

[WTF Node?] open handles:
- File descriptors: (note: stdio always exists)
  - fd 2 (tty) (stdio)
  - fd 1 (tty) (stdio)
  - fd 0 (tty)
- Sockets:
  - 135.181.2.45:9000 -> undefined:undefined
  - 135.181.2.45:9000 -> undefined:undefined
.... (45 more)
  - 135.181.2.45:9000 -> undefined:undefined
  - 135.181.2.45:9000 -> 57.128.86.167:45906
  - 135.181.2.45:9000 -> 34.222.49.115:9252
- Servers:
  - 0.0.0.0:9000 (TCP)
    - Listeners:
      - connection: bound onSocket @ file:///home/devops/goerli/lodestar/node_modules/@libp2p/tcp/src/listener.ts:78
- Timers:
  - (30000 ~ 30 s) (anonymous) @ /home/devops/goerli/lodestar/node_modules/retimer/retimer.js:25

The Sockets that show 135.181.2.45:9000 -> undefined:undefined can probably be ignored as those are also there if beacon node exits correctly.

Debug logs

Jun-14 09:58:42.886[network]       verbose: Failed to send goodbye peer=16...3dHdMu Timeout
Error: Timeout
    at timeoutPromise (file:///home/devops/goerli/lodestar/packages/utils/src/timeout.ts:15:11)
    at runNextTicks (node:internal/process/task_queues:60:5)
    at listOnTimeout (node:internal/timers:538:9)
    at processTimers (node:internal/timers:512:7)
    at withTimeout (file:///home/devops/goerli/lodestar/packages/utils/src/timeout.ts:19:12)
    at PeerManager.goodbyeAndDisconnect (file:///home/devops/goerli/lodestar/packages/beacon-node/src/network/peers/peerManager.ts:648:7)
    at async Promise.all (index 50)
    at PeerManager.goodbyeAndDisconnectAllPeers (file:///home/devops/goerli/lodestar/packages/beacon-node/src/network/peers/peerManager.ts:223:5)
    at NetworkCore.close (file:///home/devops/goerli/lodestar/packages/beacon-node/src/network/core/networkCore.ts:255:5)
    at Network.close (file:///home/devops/goerli/lodestar/packages/beacon-node/src/network/network.ts:197:5)
Jun-14 09:58:42.887[network]       verbose: Req  done method=goodbye, version=1, encoding=ssz_snappy, client=Lighthouse, peer=16...3dHdMu, requestId=1769
Jun-14 09:58:42.887[network]       verbose: Failed to send goodbye peer=16...GW2Ein Timeout
Error: Timeout
    at timeoutPromise (file:///home/devops/goerli/lodestar/packages/utils/src/timeout.ts:15:11)
    at withTimeout (file:///home/devops/goerli/lodestar/packages/utils/src/timeout.ts:19:12)
    at PeerManager.goodbyeAndDisconnect (file:///home/devops/goerli/lodestar/packages/beacon-node/src/network/peers/peerManager.ts:648:7)
    at async Promise.all (index 54)
    at PeerManager.goodbyeAndDisconnectAllPeers (file:///home/devops/goerli/lodestar/packages/beacon-node/src/network/peers/peerManager.ts:223:5)
    at NetworkCore.close (file:///home/devops/goerli/lodestar/packages/beacon-node/src/network/core/networkCore.ts:255:5)
    at Network.close (file:///home/devops/goerli/lodestar/packages/beacon-node/src/network/network.ts:197:5)
    at BeaconNode.close (file:///home/devops/goerli/lodestar/packages/beacon-node/src/node/nodejs.ts:316:7)
    at EventTarget.abortController.signal.addEventListener.once (file:///home/devops/goerli/lodestar/packages/cli/src/cmds/beacon/handler.ts:137:11)
Jun-14 09:58:42.889[network]         debug: network sent goodbye to all peers
Jun-14 09:58:42.889[network]       verbose: Req  done method=goodbye, version=1, encoding=ssz_snappy, client=Teku, peer=16...GW2Ein, requestId=1773
Jun-14 09:58:42.932[network]         debug: network peerManager closed
Jun-14 09:58:42.934[network]         debug: network gossip closed
Jun-14 09:58:43.038[network]         debug: Dialing discovered peer peer=16...HRUh4M
Jun-14 09:58:43.038[network]         debug: Dialing discovered peer peer=16...zqJUKj
Jun-14 09:58:43.130[network]         debug: network reqResp closed
Jun-14 09:58:43.146[network]         debug: Error dialing discovered peer peer=16...m56aPB All promises were rejected
AggregateError: All promises were rejected
Jun-14 09:58:43.146[network]         debug: Error dialing discovered peer peer=16...MS9Luf All promises were rejected
AggregateError: All promises were rejected
Jun-14 09:58:43.146[network]         debug: Error dialing discovered peer peer=16...HRUh4M All promises were rejected
AggregateError: All promises were rejected
Jun-14 09:58:43.152[network]         debug: Error dialing discovered peer peer=16...zqJUKj All promises were rejected
AggregateError: All promises were rejected
Jun-14 09:58:43.152[network]         debug: Error dialing discovered peer peer=16...yH119U All promises were rejected
AggregateError: All promises were rejected
Jun-14 09:58:43.153[network]         debug: network lib2p closed
Jun-14 09:58:43.153[network]         debug: network core closed
Jun-14 09:58:43.649[chain]         verbose: Archived finalized state finalizedEpoch=182885
Jun-14 09:58:44.617[]                debug: Beacon node closed

What looks really suspicious is that we are dialing peers after network is already closed

Jun-14 09:58:43.038[network]         debug: Dialing discovered peer peer=16...HRUh4M
Jun-14 09:58:43.038[network]         debug: Dialing discovered peer peer=16...zqJUKj

Expected behavior

Beacon node should always exit process after close sequence succeeds. No explicit process.exit should be required.

Steps to reproduce

Run beacon node for a while with the following command (or similar)

./lodestar beacon \
    --dataDir /home/devops/goerli/data/beacon \
    --rest \
    --rest.address "0.0.0.0" \
    --rest.namespace '*' \
    --metrics \
    --execution.urls http://localhost:8551 \
    --jwt-secret /home/devops/goerli/data/jwtsecret \
    --logLevel info \
    --network goerli \
    --checkpointSyncUrl "https://beaconstate-goerli.chainsafe.io/"

CTRL + C to exit gracefully and observe that it is not shutting down even though close sequence is executed successfully.

Operating system

Linux

Lodestar version or commit hash

unstable (bf58427)

[nflaig]

Another issue reported on discord, the BN process is not shutting down but based on the logs (beacon-2023-06-25.log) it is hard to tell what the issue is.

We might have to call process.exit explicitly after beacon node closed if this issue can't be resolved.

lodestar/packages/cli/src/cmds/beacon/handler.ts

Line 132 in f5d12a8

logger.debug("Beacon node closed");

[nflaig]

The issue seems to be fixed with upgrade to libp2p to 0.45.9 in 7280234.

The PR that fixed the issue:

• fix: unhandle protocol on stop js-libp2p-gossipsub#438

[nflaig]

Reopening as issue does not yet seem to be resolved.

Looks like we are pinging peers after sending goodbye

Jun-25 02:58:27.655[network]         �[34mdebug�[39m: Req  dialing peer method=goodbye, version=1, encoding=ssz_snappy, client=Lighthouse, peer=16...VYqoz3, requestId=295952

Jun-25 02:58:27.903[network]         �[34mdebug�[39m: Req  received method=ping, client=Lighthouse, peer=16...VYqoz3, requestId=295961
Jun-25 02:58:27.903[network]       �[36mverbose�[39m: Resp done method=ping, client=Lighthouse, peer=16...VYqoz3, requestId=295961

or still dialing peers while disconnecting (goodbyeAndDisconnectAllPeers)

Jun-25 02:58:28.311[network]         �[34mdebug�[39m: Req  dialing peer method=metadata, version=2, encoding=ssz_snappy, client=Unknown, peer=16...ohL5Xo, requestId=295963

Based on the current network close sequence it looks like we close the peer manager after disconnecting peers which could explain this behavior

lodestar/packages/beacon-node/src/network/core/networkCore.ts

Lines 253 to 256 in 85ff3cf

	await this.peerManager.goodbyeAndDisconnectAllPeers();
	this.logger.debug("network sent goodbye to all peers");
	await this.peerManager.close();
	this.logger.debug("network peerManager closed");

as only after closing, the intervals and event listeners are removed

lodestar/packages/beacon-node/src/network/peers/peerManager.ts

Lines 203 to 212 in 85ff3cf

	async close(): Promise<void> {
	await this.discovery?.stop();
	this.libp2p.services.components.events.removeEventListener(Libp2pEvent.connectionOpen, this.onLibp2pPeerConnect);
	this.libp2p.services.components.events.removeEventListener(
	Libp2pEvent.connectionClose,
	this.onLibp2pPeerDisconnect
	);
	this.networkEventBus.off(NetworkEvent.reqRespRequest, this.onRequest);
	for (const interval of this.intervals) clearInterval(interval);
	}

Changing the order of the closing sequence will likely fix the issue, but extensive testing is required as this issue is hard to reproduce.

[nflaig]

Proposed solution #5642 (comment) does not resolve the issue.

The problem seems to be with libp2p which in the end must take care of closing all connections / removing tcp listeners. There are several closed but also open issues regarding connections not being closed properly.

• [switch] Prevent dials when switch is not in state STARTED libp2p/js-libp2p#433
• [switch] ensure all connections are closed on switch stop libp2p/js-libp2p#436

This comment libp2p/js-libp2p#436 (comment) summarizes open tasks but there was no progress in a while.

For now, we just have to explicitly exit process until upstream issues are fixed.

[nflaig]

Potential fix has been merged to unstable

• chore: bump libp2p deps #6015

It is hard to verify if this actually fixed the issue due to the fact that it is not really reproducible and happens rarely.

Two things have to be done to confirm a fix

• set --network.useWorker false and
• explicit exit has to be removed
  

  lodestar/packages/cli/src/cmds/beacon/handler.ts

  Line 136 in ab2dfdd

  process.exit(0);

• then run beacon node for multiple hours and shutdown process, likely after a week of doing that without hanging process we can be confident enough and close this issue

Note: there is a chance that the process would also hang with --network.useWorker true set (#5775 <-- this issue was still observed recently) but this happened even less often, hence it is harder to confirm a fix of the issue.

[wemeetagain]

@nflaig I think this issue is resolved now?

[nflaig]

I don't think so, did libp2p releae a fix for this? Since we switched to running libp2p in a worker we get a differnet issue #5775 but this one should be reproducible by setting --network.useWorker false