bug: nwaku disconnects every 10 minutes

[agazso]

Problem

I was investigating connectivity issues with js-waku and it turns out that nwaku disconnects every 10 minutes. I also tried with the latest version of go-waku and it does not disconnect after 10 minutes.

Impact

In client applications after a reconnection there is usually a logic to synchronize the state since the last seen message, that generally means store queries which are not strictly necessary. Also having these disconnects makes it more difficult to debug connectivity issues in general.

This is not a critical issue, but it would be nice to have the same behavior as the go-waku version.

To reproduce

1. Run nwaku with docker: docker compose -f ./docker-compose.yaml up -d
2. Start the js app and wait 10 minutes

There is a docker file below for nwaku, and another one for go-waku for comparison.

Expected behavior

It would be nice to have the same behavior as the go-waku version and keep the connection.

Screenshots/logs

Output of the js test app (see below), from the timestamp it can be seen that 600_000 milliseconds after the first connect event there is a disconnect event and then it automatically reconnects.

peer:connect 2023-10-06 13:40:58.346 CustomEventPolyfill {
  type: 'peer:connect',
  defaultPrevented: false,
  cancelable: false,
  timeStamp: 895.4591110050678
}
peer:disconnect 2023-10-06 13:50:58.348 {
  event: CustomEventPolyfill {
    type: 'peer:disconnect',
    defaultPrevented: false,
    cancelable: false,
    timeStamp: 600898.4589509964
  }
}
peer:connect 2023-10-06 13:50:58.429 CustomEventPolyfill {
  type: 'peer:connect',
  defaultPrevented: false,
  cancelable: false,
  timeStamp: 600978.7678619921
}

nwaku logs with debug loglevel:

2023-10-06 15:50:58 waku-objects-playground-waku-1  | DBG 2023-10-06 13:50:58.341+00:00 unsubscribing pubsub peer                  topics="libp2p pubsub" tid=1 file=pubsub.nim:135 peerId=12D*8nmib3
2023-10-06 15:50:58 waku-objects-playground-waku-1  | DBG 2023-10-06 13:50:58.341+00:00 Error while reading message from secure connection, closing. topics="libp2p secure" tid=1 file=secure.nim:164 error=AsyncStreamReadError message="Read stream failed, originated from [TransportUseClosedError] Attempt to read data from closed stream" connection=12D*8nmib3:65200e6ae7b7bb2a9524b6dd
2023-10-06 15:50:58 waku-objects-playground-waku-1  | DBG 2023-10-06 13:50:58.341+00:00 Timeout handler cancelled                  topics="libp2p connection" tid=1 file=connection.nim:107 s=12D*8nmib3:65200e6ae7b7bb2a9524b6dd
2023-10-06 15:50:58 waku-objects-playground-waku-1  | DBG 2023-10-06 13:50:58.342+00:00 Unexpected exception in mplex read loop    topics="libp2p mplex" tid=1 file=mplex.nim:196 m=12D*8nmib3:65200e6ae7b7bb2a9524b6dd msg="Read stream failed, originated from [TransportUseClosedError] Attempt to read data from closed stream"
2023-10-06 15:50:58 waku-objects-playground-waku-1  | DBG 2023-10-06 13:50:58.357+00:00 Accepted an incoming connection            topics="libp2p switch" tid=1 file=switch.nim:271 conn=:652010c2e7b7bb2a9524b6e7
2023-10-06 15:50:58 waku-objects-playground-waku-1  | DBG 2023-10-06 13:50:58.357+00:00 About to accept incoming connection        topics="libp2p switch" tid=1 file=switch.nim:245
2023-10-06 15:50:58 waku-objects-playground-waku-1  | DBG 2023-10-06 13:50:58.385+00:00 created new pubsub peer                    topics="libp2p pubsub" tid=1 file=pubsub.nim:296 peerId=12D*8nmib3
2023-10-06 15:50:58 waku-objects-playground-waku-1  | DBG 2023-10-06 13:50:58.439+00:00 decodeMsg: decoded identify                topics="libp2p identify" tid=1 file=identify.nim:136 pubkey=some(e...94CA)) addresses= protocols=/ipfs/id/1.0.0,/ipfs/id/push/1.0.0,/ipfs/ping/1.0.0,/vac/waku/filter-push/2.0.0-beta1 observable_address=some(/ip4/0.0.0.0/tcp/8000/ws/p2p/16Uiu2HAm53sojJN72rFbYg6GV2LpRRER9XeWkiEAhjKy3aL9cN5Z) proto_version=ipfs/0.1.0 agent_version=js-waku signedPeerRecord=None
2023-10-06 15:50:58 waku-objects-playground-waku-1  | DBG 2023-10-06 13:50:58.450+00:00 Could not establish send connection        topics="libp2p pubsubpeer" tid=1 file=pubsubpeer.nim:221 msg="Unable to select sub-protocol @[\"/vac/waku/relay/2.0.0\", \"/meshsub/1.1.0\", \"/meshsub/1.0.0\", \"/meshsub/1.1.0\", \"/meshsub/1.0.0\"]"

nwaku version/commit hash

Using nwaku v0.19.0 from docker
Using @waku/sdk 0.0.19
Testing with go-waku from wakuorg/go-waku:latest docker image

Additional context

Test js code:

import { Protocols } from '@waku/interfaces'
import { createLightNode, waitForRemotePeer } from '@waku/sdk'
import { multiaddr } from '@multiformats/multiaddr'

// change the id of the peer
const peerMultiaddr = multiaddr(
	'/ip4/127.0.0.1/tcp/8000/ws/p2p/16Uiu2HAm53sojJN72rFbYg6GV2LpRRER9XeWkiEAhjKy3aL9cN5Z',
)

main()

async function main() {
    const waku = await createLightNode({})

    waku.libp2p.addEventListener('peer:disconnect', (event) => console.log('peer:disconnect', { event }))
    waku.libp2p.addEventListener('peer:connect', (event) => console.log('peer:connect', event))

    await waku.start()
    await waku.dial(peerMultiaddr)
    await waitForRemotePeer(waku, [Protocols.Filter, Protocols.LightPush, Protocols.Store])
}

nwaku docker file (docker-compose.yaml):

version: '2.4'
services:
  waku:
    image: statusteam/nim-waku:v0.19.0
    command: |
      --store:true
      --filter:true
      --lightpush:true
      --websocket-support:true
      --nodekey:7b8d9a670aae6421500b7b3f933d0b5d08b51fcf0f0c2f14cba3a4737c83a228
      --log-level:DEBUG
    ports:
      - 8000:8000/tcp

go-waku docker file for comparison:

version: '2.4'
services:
  waku:
    image: wakuorg/go-waku:latest
    command: |
      --store=true
      --filter=true
      --lightpush=true
      --websocket-support=true
      --websocket-port=8000
      --nodekey=7b8d9a670aae6421500b7b3f933d0b5d08b51fcf0f0c2f14cba3a4737c83a228
      --min-relay-peers-to-publish=0
    ports:
      - 8000:8000/tcp

[alrevuelta]

Is there any traffic in the topic that your node is running? If not, then it would be expected to drop innactive connections every 10 minutes. We have the keep-alive flag for that: https://github.com/waku-org/nwaku/blob/master/apps/wakunode2/external_config.nim#L195 but we maay remove it in the future.

[agazso]

Is there any traffic in the topic that your node is running? If not, then it would be expected to drop innactive connections every 10 minutes. We have the keep-alive flag for that: https://github.com/waku-org/nwaku/blob/master/apps/wakunode2/external_config.nim#L195 but we maay remove it in the future.

I tried nwaku with some traffic and without the keep-alive flag and it still disconnected after 10 minutes.
I tried the keep-alive flag and even without traffic it did not disconnect.

Anyways I don't mind it working either way, but it would be good if nwaku worked the same way as go-waku and maybe if this were also documented somewhere.

[alrevuelta]

The jswaku-nwaku connection is being closed because there is no activity. I would consider this the desirable behaviour, but we will look into it. The filter protocol has a ping that may help here

nwaku/waku/waku_filter_v2/rpc.nim

Line 15 in a0033df

SUBSCRIBER_PING = uint32(0)

, but imho this should be handled under the hood by the waku sdk.

In any case, note that waku is a peer to peer protocol, so single peers don't matter. What matters is that you have a set of healthy peers that can be used for your needs. Peers can disconnect from you at any time due to different reasons i) max capacity reached, ii) you are missbehaving, iii) unused connetion, etc. So you shouldn't rely on just one peer. But well, again all this should be abstracted away by the waku sdk, so we may need some modifications in there.

Thanks for the report, we will get back to you.

[chair28980]

Issue discussed during nwaku pm call 2023-10-10.

[agazso]

Proposed fix in js-waku: waku-org/js-waku#1647