search

ChainSafe / lodestar

🌟 TypeScript Implementation of Ethereum Consensus
https://lodestar.chainsafe.io
Apache License 2.0
1.15k stars 282 forks source link

Beacon node active handles after close sequence is completed #5642

Open nflaig opened 1 year ago

nflaig commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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

The PR that fixed the issue:

nflaig commented 1 year ago

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]         debug: Req  dialing peer method=goodbye, version=1, encoding=ssz_snappy, client=Lighthouse, peer=16...VYqoz3, requestId=295952
Jun-25 02:58:27.903[network]         debug: Req  received method=ping, client=Lighthouse, peer=16...VYqoz3, requestId=295961
Jun-25 02:58:27.903[network]       verbose: 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]         debug: 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 commented 1 year ago

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.

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 commented 11 months ago

Potential fix has been merged to unstable

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

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.