lodestar icon indicating copy to clipboard operation
lodestar copied to clipboard
verified publisher icon ChainSafe

Beacon node active handles after close sequence is completed

Open nflaig opened this issue 2 years ago • 7 comments

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 (bf5842733a738c59a6f9aa147496806fb2d4c98f)

nflaig avatar Jun 14 '23 09:06 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. https://github.com/ChainSafe/lodestar/blob/f5d12a893f5b913a04938275bb248ace1ca47539/packages/cli/src/cmds/beacon/handler.ts#L132

nflaig avatar Jun 26 '23 14:06 nflaig

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

The PR that fixed the issue:

  • https://github.com/ChainSafe/js-libp2p-gossipsub/pull/438

nflaig avatar Jul 07 '23 10:07 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

https://github.com/ChainSafe/lodestar/blob/85ff3cf17e9f8338865cc66f129f9e60e0ec029b/packages/beacon-node/src/network/core/networkCore.ts#L253-L256

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

https://github.com/ChainSafe/lodestar/blob/85ff3cf17e9f8338865cc66f129f9e60e0ec029b/packages/beacon-node/src/network/peers/peerManager.ts#L203-L212

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 avatar Jul 11 '23 12:07 nflaig

Proposed solution https://github.com/ChainSafe/lodestar/issues/5642#issuecomment-1630749223 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.

  • https://github.com/libp2p/js-libp2p/issues/433
  • https://github.com/libp2p/js-libp2p/issues/436

This comment https://github.com/libp2p/js-libp2p/issues/436#issuecomment-432624680 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 avatar Jul 12 '23 07:07 nflaig

Potential fix has been merged to unstable

  • https://github.com/ChainSafe/lodestar/pull/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 https://github.com/ChainSafe/lodestar/blob/ab2dfdde652b0b0e4e9b2b96f8d8ee08fec6b720/packages/cli/src/cmds/beacon/handler.ts#L136
  • 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 (https://github.com/ChainSafe/lodestar/issues/5775 <-- this issue was still observed recently) but this happened even less often, hence it is harder to confirm a fix of the issue.

nflaig avatar Oct 13 '23 12:10 nflaig

@nflaig I think this issue is resolved now?

wemeetagain avatar Oct 15 '24 16:10 wemeetagain

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 https://github.com/ChainSafe/lodestar/issues/5775 but this one should be reproducible by setting --network.useWorker false

nflaig avatar Oct 15 '24 16:10 nflaig

Resolved by upgrading to libp2p 2.0 in https://github.com/ChainSafe/lodestar/pull/7359 which includes https://github.com/libp2p/js-libp2p/pull/2763

nflaig avatar Apr 28 '25 09:04 nflaig