Direct messages from an ipfs-go node to an ipfs-js node via the circuit-relay are unreliable and very slow

[rmisio]

When I set-up a web node using ipfs-js and try to receive direct messages from a ipfs-go node via a circuit relay, the messages usually come after a several minute delay, if at all.

To summarize:

• ipfs-js node to ipfs-js node, the messages are received very quickly and reliably come in both directions.
• ipfs-js node to ipfs-go node, the messages are received very quickly and reliably.
• ipfs-go node to ipfs-js node, the message are received very unreliable:
  1. Most of the time they come after a several minute delay. If I send a few in quick succession, then after a few minutes, all of them come in the same pull-stream.
  2. Occasionally they don't come at all
  3. On two occasions, the stars were aligned, and the messages came very reliably and almost instantly. But, I have no idea what confluence of circumstances made this happen.

To be clear, I built a little chat app and even during the times when ipfs-go to ipfs-js messages are really flaky, I'm still always able to send reliably in the reverse. So, I'm not understanding why a direct connection can be made and messages sent properly in one direction, but why it's flaky on the other.

When I start my ipfs-js node, I get this output:

Swarm listening on /p2p-circuit/ipfs/QmQVtXNxHbywmhM9JpThgfWhTCXEe6ThsxTS9AZYamAiDZ

When I send to the ipfs-go node, it is via this address:

/p2p-circuit/ipfs/<peer-id>

Here are some related logs on the ipfs-go node. It seems like it's sending to the right address of the ipfs-js node:

[0;37m12:23:55.162 [36mDEBUG [0;34m   namesys: [0mRoutingResolver resolving QmQVtXNxHbywmhM9JpThgfWhTCXEe6ThsxTS9AZYamAiDZ [0;37mrouting.go:55[0m
[0;37m12:23:55.162 [36mDEBUG [0;34m       dht: [0mgetPublicKey for: <peer.ID Qm*amAiDZ> [0;37mrecords.go:27[0m
[0;37m12:23:55.162 [36mDEBUG [0;34m    swarm2: [0m[<peer.ID Qm*bLzJ44>] opening stream to peer [<peer.ID Qm*amAiDZ>] [0;37mswarm.go:280[0m
[0;37m12:23:55.162 [36mDEBUG [0;34m    swarm2: [0m[<peer.ID Qm*bLzJ44>] swarm dialing peer [<peer.ID Qm*amAiDZ>] [0;37mswarm_dial.go:184[0m
[0;37m12:23:55.163 [36mDEBUG [0;34m    swarm2: [0m<peer.ID Qm*bLzJ44> swarm dialing <peer.ID Qm*amAiDZ> [0;37mswarm_dial.go:347[0m
[0;37m12:23:55.176 [36mDEBUG [0;34m       dht: [0mGot public key for <peer.ID Qm*amAiDZ> from DHT [0;37mrecords.go:94[0m
[0;37m12:23:55.305 [36mDEBUG [0;34m   namesys: [0mresolved /ipns/QmQVtXNxHbywmhM9JpThgfWhTCXEe6ThsxTS9AZYamAiDZ to /ipfs/zdj7WekVaUD5d3z5a5GAcY616oqaD8Pv8WxsDDMBgie8QnMtP [0;37mbase.go:70[0m

[0;37m12:23:57.350 [36mDEBUG [0;34m   namesys: [0mRoutingResolver resolving QmQVtXNxHbywmhM9JpThgfWhTCXEe6ThsxTS9AZYamAiDZ [0;37mrouting.go:55[0m
[0;37m12:23:57.350 [36mDEBUG [0;34m       dht: [0mgetPublicKey for: <peer.ID Qm*amAiDZ> [0;37mrecords.go:27[0m
[0;37m12:23:57.421 [36mDEBUG [0;34m   namesys: [0mresolved /ipns/QmQVtXNxHbywmhM9JpThgfWhTCXEe6ThsxTS9AZYamAiDZ to /ipfs/zdj7WekVaUD5d3z5a5GAcY616oqaD8Pv8WxsDDMBgie8QnMtP [0;37mbase.go:70[0m
[0;37m12:23:59.268  INFO [0;34m     relay: [0mrelay connection from: <peer.ID Qm*amAiDZ> [0;37mrelay.go:407[0m

[0;37m12:24:00.560 [36mDEBUG [0;34m     secio: [0m1.1 Identify: <peer.ID Qm*bLzJ44> Remote Peer Identified as <peer.ID Qm*amAiDZ> [0;37mprotocol.go:222[0m
[0;37m12:24:01.151 [36mDEBUG [0;34mstream-upg: [0mlistener <stream.Listener /p2p-circuit> accepted connection: <stream.Conn /ip4/192.168.1.190/tcp/61951/ws (<peer.ID Qm*bLzJ44>) <-> /ipfs/QmSAumietCn85sF68xgCUtVS7UuZbyBi5LQPWqLe4vfwYb/p2p-circuit (<peer.ID Qm*amAiDZ>)> [0;37mlistener.go:114[0m
[0;37m12:24:01.151 [36mDEBUG [0;34m    swarm2: [0mswarm listener accepted connection: <stream.Conn /ip4/192.168.1.190/tcp/61951/ws (<peer.ID Qm*bLzJ44>) <-> /ipfs/QmSAumietCn85sF68xgCUtVS7UuZbyBi5LQPWqLe4vfwYb/p2p-circuit (<peer.ID Qm*amAiDZ>)> [0;37mswarm_listen.go:80[0m
[0;37m12:24:01.152 [36mDEBUG [0;34m    swarm2: [0m[<peer.ID Qm*bLzJ44>] opening stream to peer [<peer.ID Qm*amAiDZ>] [0;37mswarm.go:280[0m
[0;37m12:24:01.672 [36mDEBUG [0;34m    swarm2: [0m[<peer.ID Qm*bLzJ44>] opening stream to peer [<peer.ID Qm*amAiDZ>] [0;37mswarm.go:280[0m
[0;37m12:24:01.681  INFO [0;34m     relay: [0mnew relay stream from: <peer.ID Qm*amAiDZ> [0;37mrelay.go:235[0m
[0;37m12:24:01.835 [36mDEBUG [0;34mnet/identi: [0m<peer.ID Qm*bLzJ44> received listen addrs for <peer.ID Qm*amAiDZ>: [/p2p-circuit/ipfs/QmQVtXNxHbywmhM9JpThgfWhTCXEe6ThsxTS9AZYamAiDZ /ipfs/QmSAumietCn85sF68xgCUtVS7UuZbyBi5LQPWqLe4vfwYb/p2p-circuit /ipfs/QmSAumietCn85sF68xgCUtVS7UuZbyBi5LQPWqLe4vfwYb/p2p-circuit] [0;37mid.go:220[0m
[0;37m12:24:01.835 [36mDEBUG [0;34mnet/identi: [0m/ipfs/id/1.0.0 received message from <peer.ID Qm*amAiDZ> /ipfs/QmSAumietCn85sF68xgCUtVS7UuZbyBi5LQPWqLe4vfwYb/p2p-circuit [0;37mid.go:135[0m
[0m[36m12:24:02.303 [DEBUG] [service/handleChat] Received CHAT message from QmQVtXNxHbywmhM9JpThgfWhTCXEe6ThsxTS9AZYamAiDZ
[0m[36m12:24:02.303 [DEBUG] [service/handleNewMessage] Disconnected from peer QmQVtXNxHbywmhM9JpThgfWhTCXEe6ThsxTS9AZYamAiDZ
[0m[36m12:24:07.030 [DEBUG] [service/SendMessage] Sending CHAT message to QmQVtXNxHbywmhM9JpThgfWhTCXEe6ThsxTS9AZYamAiDZ
[0m[36m12:24:07.045 [DEBUG] [service/SendMessage] Sending CHAT message to QmQVtXNxHbywmhM9JpThgfWhTCXEe6ThsxTS9AZYamAiDZ
[0m[36m12:24:07.302 [DEBUG] [service/SendMessage] Sending CHAT message to QmQVtXNxHbywmhM9JpThgfWhTCXEe6ThsxTS9AZYamAiDZ
[0m[36m12:24:07.752 [DEBUG] [service/SendMessage] Sending CHAT message to QmQVtXNxHbywmhM9JpThgfWhTCXEe6ThsxTS9AZYamAiDZ

The ipfs-js node is started with this config:

    return {
      EXPERIMENTAL: {
        pubsub: true
      },
      relay: {
        "enabled": true,
      },
      repo: `./ipfs/${peerId}`,
      init: { privateKey },
    }

And the ipfs-go node with this config related to the relay:

  "Swarm": {
    "AddrFilters": null,
    "ConnMgr": {
      "GracePeriod": "",
      "HighWater": 0,
      "LowWater": 0,
      "Type": ""
    },
    "DisableBandwidthMetrics": false,
    "DisableNatPortMap": false,
    "DisableRelay": false,
    "EnableRelayHop": false
  },

I'm assuming both side are able to connect to the relay because:

1. I confirmed the relay is up and running
2. IPFS-JS has console output in the callback of the dialFSM after it successfully connects to the relay.
3. I assume ipfs-js to ipfs-go message would fail if both sides weren't connected to the relay... not sure if that's a correct assumption.

If there's any more detail I can provide, please let me know.

[rmisio]

To further elaborate on this, it seems the message is somehow getting clogged up in the pull stream:

            // on the receiving node, which is ipfs-js
            node._libp2pNode.handle('/openbazaar/app/1.0.0', (protocol, conn) => {
              console.log('pulling in incoming message'); // This outputs almost instantly after the message is sent via ipfs-go.

              pull(
                conn,
                pull.collect((err, data) => {
                  if (err) {
                    return console.error('There was an error pulling in an incoming chat ' +
                      'message:', err);
                  }

                  console.log('this incoming data is moo:'); // this takes several minutes to output, after which the data is fine, it's just incredibly delayed
                  window.moo = data;

[alanshaw]

Possibly related to libp2p/js-libp2p#309

@rmisio are you seeing the same problem with js-ipfs 0.34?

[rmisio]

@alanshaw I was using master and seeing this issue. I'v also seen the issue on the dht branch (dht-part-ii).

Is there reason to believe it would work well in 0.34 even though it doesn't in either of those branches?

(using master because part of my code depends on the connection state machine, but I could forego that, at least temporarily)

[whizzzkid]

js-ipfs is being deprecated in favor of Helia. You can #4336 and read the migration guide.

Please feel to reopen with any comments before 2023-06-05. We will do a final pass on reopened issues afterward (see #4336).