Peer keeps reconnecting every ~30 seconds.

[AlexMesser]

• Version: 0.40.0

• Platform: macOS 12.5

• Subsystem: Connection Manager

Severity: Medium

Description:

I have two peers connected to the same relay server. Peers successfully connect to each other, but keep reconnecting every ~30 seconds being unreachable for 80-100ms. Since we are heavily using pubsub in our app, this behavior leads to missing pubsub messages in this reconnection intervals.

I put some logs on connect/disconnect events on both peers:

    // Listen for new connections to peers
    libp2p.connectionManager.addEventListener("peer:connect", async (evt) => {
      const connection = evt.detail
      console.log(`Connected to ${connection.remotePeer.toString()}`)
      console.time("disconnected after")
      console.timeEnd("reconnected after")
    })

    // Listen for peers disconnecting
    libp2p.connectionManager.addEventListener("peer:disconnect", (evt) => {
      const connection = evt.detail
      console.log(`Disconnected from ${connection.remotePeer.toString()}`)
      console.timeEnd("disconnected after")
      console.time("reconnected after")
    })

Relay logs:

----------------------------------------------
PeerId: 12D3KooWNvSZnPi3RrhrTwEY4LuuBeB6K6facKUCJcyWG1aoDd2p
Listening on: [
  '/ip4/127.0.0.1/tcp/5001/p2p/12D3KooWNvSZnPi3RrhrTwEY4LuuBeB6K6facKUCJcyWG1aoDd2p',
  '/ip4/192.168.68.115/tcp/5001/p2p/12D3KooWNvSZnPi3RrhrTwEY4LuuBeB6K6facKUCJcyWG1aoDd2p'
]
----------------------------------------------
Connected to 12D3KooWLV3w42LqUb9MWE7oTzG7vwaFjPw9GvDqmsuDif5chTn9
Connected to 12D3KooWFYyvJysHGbbYiruVY8bgjKn7sYN9axgbnMxrWVkGXABF

Peer A:

----------------------------------------------
PeerId: 12D3KooWLV3w42LqUb9MWE7oTzG7vwaFjPw9GvDqmsuDif5chTn9
Listening on: [
  '/ip4/127.0.0.1/tcp/5001/p2p/12D3KooWNvSZnPi3RrhrTwEY4LuuBeB6K6facKUCJcyWG1aoDd2p/p2p-circuit/p2p/12D3KooWLV3w42LqUb9MWE7oTzG7vwaFjPw9GvDqmsuDif5chTn9'
]
----------------------------------------------
Connected to 12D3KooWFYyvJysHGbbYiruVY8bgjKn7sYN9axgbnMxrWVkGXABF
Disconnected from 12D3KooWFYyvJysHGbbYiruVY8bgjKn7sYN9axgbnMxrWVkGXABF
disconnected after: 29.925s
Connected to 12D3KooWFYyvJysHGbbYiruVY8bgjKn7sYN9axgbnMxrWVkGXABF
reconnected after: 99.658ms
Disconnected from 12D3KooWFYyvJysHGbbYiruVY8bgjKn7sYN9axgbnMxrWVkGXABF
disconnected after: 29.954s
Connected to 12D3KooWFYyvJysHGbbYiruVY8bgjKn7sYN9axgbnMxrWVkGXABF
reconnected after: 89.978ms
Disconnected from 12D3KooWFYyvJysHGbbYiruVY8bgjKn7sYN9axgbnMxrWVkGXABF
disconnected after: 29.968s
Connected to 12D3KooWFYyvJysHGbbYiruVY8bgjKn7sYN9axgbnMxrWVkGXABF
reconnected after: 85.511ms
Disconnected from 12D3KooWFYyvJysHGbbYiruVY8bgjKn7sYN9axgbnMxrWVkGXABF
disconnected after: 29.963s

Peer B:

----------------------------------------------
PeerId: 12D3KooWFYyvJysHGbbYiruVY8bgjKn7sYN9axgbnMxrWVkGXABF
Listening on: [
  '/ip4/127.0.0.1/tcp/5001/p2p/12D3KooWNvSZnPi3RrhrTwEY4LuuBeB6K6facKUCJcyWG1aoDd2p/p2p-circuit/p2p/12D3KooWFYyvJysHGbbYiruVY8bgjKn7sYN9axgbnMxrWVkGXABF'
]
----------------------------------------------
Connected to 12D3KooWLV3w42LqUb9MWE7oTzG7vwaFjPw9GvDqmsuDif5chTn9
Disconnected from 12D3KooWLV3w42LqUb9MWE7oTzG7vwaFjPw9GvDqmsuDif5chTn9
reconnected after: 29.937s
Connected to 12D3KooWLV3w42LqUb9MWE7oTzG7vwaFjPw9GvDqmsuDif5chTn9
unavailable for: 127.696ms
Disconnected from 12D3KooWLV3w42LqUb9MWE7oTzG7vwaFjPw9GvDqmsuDif5chTn9
reconnected after: 29.960s
Connected to 12D3KooWLV3w42LqUb9MWE7oTzG7vwaFjPw9GvDqmsuDif5chTn9
unavailable for: 89.762ms
Disconnected from 12D3KooWLV3w42LqUb9MWE7oTzG7vwaFjPw9GvDqmsuDif5chTn9
reconnected after: 29.967s
Connected to 12D3KooWLV3w42LqUb9MWE7oTzG7vwaFjPw9GvDqmsuDif5chTn9
unavailable for: 78.319ms
Disconnected from 12D3KooWLV3w42LqUb9MWE7oTzG7vwaFjPw9GvDqmsuDif5chTn9
reconnected after: 29.969s

I tested the same behavior on go-libp2p nodes and there were no reconnects during the node lifecycle.

Is this a bug or by design or is it configurable somehow?

[achingbrain]

Could you provide a runnable example that shows the problem? It would help me get to the bottom of the issue.

[AlexMesser]

@achingbrain sure, here it is

[sadeghte]

Same problem !!
Any progress ?

[bakhshandeh]

Same problem with libp2p 0.40.1.

Code:

import { createLibp2p } from 'libp2p'
import { tcp } from '@libp2p/tcp'
import { mplex } from '@libp2p/mplex'
import { noise } from '@chainsafe/libp2p-noise'
import { kadDHT } from '@libp2p/kad-dht'
import last from 'it-last'
import delay from 'delay'
import drain from 'it-drain'
import { fromString as uint8ArrayFromString } from 'uint8arrays/from-string'

const createNode = async () => {
  const node = await createLibp2p({
    addresses: {
      listen: ['/ip4/0.0.0.0/tcp/0']
    },
    transports: [tcp()],
    streamMuxers: [mplex()],
    connectionEncryption: [noise()],
    dht: kadDHT()
  })

  node.connectionManager.addEventListener("peer:connect", (evt) => {
    const connection = evt.detail;
    console.log("Connection established to:", connection.remotePeer.toString()); // Emitted when a peer has been found
  });

  node.connectionManager.addEventListener("peer:disconnect", (evt) => {
    const connection = evt.detail;
    console.log("Connection disconnected:", connection.remotePeer.toString()); // Emitted when a peer has been found
  });

  node.addEventListener("peer:discovery", (evt) => {
    const peer = evt.detail;
    // No need to dial, autoDial is on
    console.log("Discovered:", peer.id.toString());
  });

  await node.start()
  return node
}

;(async () => {
  const [node1, node2, node3] = await Promise.all([
    createNode(),
    createNode(),
    createNode()
  ])

  await node1.peerStore.addressBook.set(node2.peerId, node2.getMultiaddrs())
  await node2.peerStore.addressBook.set(node3.peerId, node3.getMultiaddrs())

  await Promise.all([
    node1.dial(node2.peerId),
    node2.dial(node3.peerId)
  ])
})();

Output:

Discovered: 12D3KooWPqmnwQPMJ5wVhun2WFuK9UthnDbULFh4RpcBgTZao1Ws
Discovered: 12D3KooWHCpstPcfUXPY88JJXMmHbXKWRh8qtnPKY5QjKkkPGbyR
Connection established to: 12D3KooWPqmnwQPMJ5wVhun2WFuK9UthnDbULFh4RpcBgTZao1Ws
Connection established to: 12D3KooWPqmnwQPMJ5wVhun2WFuK9UthnDbULFh4RpcBgTZao1Ws
Connection established to: 12D3KooWMcw3GcARVjgrLYWoYU23kL7oiV51zXfQXuLVyBa1UQmF
Connection established to: 12D3KooWMcw3GcARVjgrLYWoYU23kL7oiV51zXfQXuLVyBa1UQmF
Connection established to: 12D3KooWHCpstPcfUXPY88JJXMmHbXKWRh8qtnPKY5QjKkkPGbyR
Connection established to: 12D3KooWPqmnwQPMJ5wVhun2WFuK9UthnDbULFh4RpcBgTZao1Ws
Discovered: 12D3KooWMcw3GcARVjgrLYWoYU23kL7oiV51zXfQXuLVyBa1UQmF
Connection established to: 12D3KooWHCpstPcfUXPY88JJXMmHbXKWRh8qtnPKY5QjKkkPGbyR
Connection established to: 12D3KooWHCpstPcfUXPY88JJXMmHbXKWRh8qtnPKY5QjKkkPGbyR
Connection established to: 12D3KooWMcw3GcARVjgrLYWoYU23kL7oiV51zXfQXuLVyBa1UQmF
Discovered: 12D3KooWHCpstPcfUXPY88JJXMmHbXKWRh8qtnPKY5QjKkkPGbyR
Discovered: 12D3KooWHCpstPcfUXPY88JJXMmHbXKWRh8qtnPKY5QjKkkPGbyR
Discovered: 12D3KooWPqmnwQPMJ5wVhun2WFuK9UthnDbULFh4RpcBgTZao1Ws
Discovered: 12D3KooWMcw3GcARVjgrLYWoYU23kL7oiV51zXfQXuLVyBa1UQmF
Discovered: 12D3KooWPqmnwQPMJ5wVhun2WFuK9UthnDbULFh4RpcBgTZao1Ws
Connection disconnected: 12D3KooWMcw3GcARVjgrLYWoYU23kL7oiV51zXfQXuLVyBa1UQmF
Connection disconnected: 12D3KooWPqmnwQPMJ5wVhun2WFuK9UthnDbULFh4RpcBgTZao1Ws
Connection disconnected: 12D3KooWHCpstPcfUXPY88JJXMmHbXKWRh8qtnPKY5QjKkkPGbyR
Connection disconnected: 12D3KooWPqmnwQPMJ5wVhun2WFuK9UthnDbULFh4RpcBgTZao1Ws
Connection disconnected: 12D3KooWHCpstPcfUXPY88JJXMmHbXKWRh8qtnPKY5QjKkkPGbyR
Connection disconnected: 12D3KooWMcw3GcARVjgrLYWoYU23kL7oiV51zXfQXuLVyBa1UQmF
Connection established to: 12D3KooWHCpstPcfUXPY88JJXMmHbXKWRh8qtnPKY5QjKkkPGbyR
Connection established to: 12D3KooWHCpstPcfUXPY88JJXMmHbXKWRh8qtnPKY5QjKkkPGbyR
Connection established to: 12D3KooWMcw3GcARVjgrLYWoYU23kL7oiV51zXfQXuLVyBa1UQmF
Connection established to: 12D3KooWMcw3GcARVjgrLYWoYU23kL7oiV51zXfQXuLVyBa1UQmF
...

[bakhshandeh]

It seems that the issue is on libp2p-tcp package.
https://github.com/libp2p/js-libp2p-tcp/blob/92e144211784bb9c21f799c4c5fcab9c72ef5d8a/src/socket-to-conn.ts#L64
inactivityTimeout is 30 seconds by default and the sockets will be closed after that.
This lib2p2 config disables timeout and fixes the issue:

transports: [tcp({
        outboundSocketInactivityTimeout: 0,
        inboundSocketInactivityTimeout: 0
      })]

It disabling the timeout safe?

[achingbrain]

It disabling the timeout safe?

If the default in node is to not have a timeout, then maybe? It's possible the default timeout is too short - the solution might be to have no timeout by default (e.g the same as node) and let people configure it if they need it.

Please can you open an issue against libp2p/js-libp2p-tcp to discuss this?

Closing as the solution is to disable the timeout.

[sneaker1]

I am having the same issue.
The problem exists with tcp as well as with websockets.
I also tried to manually set the timeout to 0 as mentioned above. But this didn't help.