failure to hole punch as part of test

[2color]

Background

When running a check with a p2p-circuit multiaddr, e.g. /ip4/77.102.162.54/udp/22942/quic-v1/p2p/12D3KooWHgnuckrBHmV6KJ933PvTRoShzaSQJ7S78cbbfneTh6ve/p2p-circuit/p2p/12D3KooWRBy97UB99e3J6hiPesre1MZeuNQvfan4gBziswrRJsNK, we rely on DCUtR to hole punch after which the Bitswap check runs.

What's wrong

ipfs-check consistently fails to hole punch to the passed maddr, causing it to fail the Bitswap check:
https://github.com/ipfs-shipyard/ipfs-check/blob/a5b6cf2182aba1699022a8b9e60d7110f0ebb7be/daemon.go#L191-L208

This is unexpected beause running the same test with the Vole cli from the same server, e.g. vole bitswap check bafybeicklkqcnlvtiscr2hzkubjwnwjinvskffn4xorqeduft3wq7vm5u4 "/ip4/77.102.162.54/udp/22942/quic-v1/p2p/12D3KooWHgnuckrBHmV6KJ933PvTRoShzaSQJ7S78cbbfneTh6ve/p2p-circuit/p2p/12D3KooWRBy97UB99e3J6hiPesre1MZeuNQvfan4gBziswrRJsNK" is successful. (note that the p2p-circuit maddrs change over time)

The only thing that is different between Vole and ipfs-check is how the libp2p host is created:

• Vole: https://github.com/ipfs-shipyard/vole/blob/d7b80a4611935295799d439967786f3be699e25a/lib/libp2p.go#L10
• ipfs-check: https://github.com/ipfs-shipyard/ipfs-check/blob/a5b6cf2182aba1699022a8b9e60d7110f0ebb7be/daemon.go#L90-L93

Debugging efforts

• Initially, the testHost created by ipfs-check did not have the hole punching enabled. This was added in caf1397 to no avail. Hole punching still fails
• To ensure consistency with how Vole creates the host, I updated how the testHost is created by ipfs-check to be exactly the same as vole and deployed the following branch.
• I started collecting prometheus metrics on the peer, however, these don't provide sufficient insight into individual requests.
• I enabled logging. Initially p2p-holepunch=debug which wasn't informative enough and later debug to get all debug
  • See the following log an attempt to establish a connection to the peerID: 12D3KooWRBy97UB99e3J6hiPesre1MZeuNQvfan4gBziswrRJsNK (error: basic/basic_host.go:463 protocol mux failed: stream reset (took 175.354729ms, id:12D3KooWRB-2-7, remote peer:12D3KooWRBy97UB99e3J6hiPesre1MZeuNQvfan4gBziswrRJsNK, remote addr:/ip4/77.102.162.54/udp/22942/quic-v1/p2p/12D3KooWHgnuckrBHmV6KJ933PvTRoShzaSQJ7S78cbbfneTh6ve/p2p-circuit))
• By comparison, look at the debug log from a successful check with vole

[2color]

I just tried deploying #42, letting Vole create the test host, and I still get the same error protocol mux failed: stream reset (took 193.407741ms, id:12D3KooWRB-2-7, remote peer:12D3KooWRBy97UB99e3J6hiPesre1MZeuNQvfan4gBziswrRJsNK, remote addr:/ip4/77.102.162.54/udp/22942/quic-v1/p2p/12D3KooWHgnuckrBHmV6KJ933PvTRoShzaSQJ7S78cbbfneTh6ve/p2p-circuit)

More extensive log:

Aug 06 15:14:21 ipfs-check-backend ipfs-check[464294]: 2024-08-06T15:14:21.481Z        DEBUG        basichost        basic/basic_host.go:463        protocol mux failed: stream reset (took 193.407741ms, id:12D3KooWRB-2-7, remote peer:12D3KooWRBy97UB99e3J6hiPesre1MZeuNQvfan4gBziswrRJsNK, remote addr:/ip4/77.102.162.54/udp/22942/quic-v1/p2p/12D3KooWHgnuckrBHmV6KJ933PvTRoShzaSQJ7S78cbbfneTh6ve/p2p-circuit)
Aug 06 15:14:22 ipfs-check-backend ipfs-check[464294]: 2024-08-06T15:14:22.101Z        DEBUG        net/identify        identify/id.go:624        updating snapshot        {"seq": 59, "addrs": ["/ip4/127.0.0.1/tcp/37389","/ip4/127.0.0.1/udp/38893/webrtc-direct/certhash/uEiCONRS7m9ARSpE0k7F75NLOb_AapSsT_5-La0oi5xn4lA","/ip4/127.0.0.1/udp/49572/quic-v1","/ip4/127.0.0.1/udp/53436/quic-v1/webtransport/certhash/uEiAySGBS1QrMiDdzRdlR1r194dm4Q0bIBHpZDbcOohIBZA/certhash/uEiAh7IjXWPwLQ06Pzmpm3mur-HqcT7e2NOoUXpCRH-A29w","/ip4/139.178.82.19/tcp/37389","/ip4/139.178.82.19/udp/38893/webrtc-direct/certhash/uEiCONRS7m9ARSpE0k7F75NLOb_AapSsT_5-La0oi5xn4lA","/ip4/139.178.82.19/udp/49572/quic-v1","/ip4/139.178.82.19/udp/53436/quic-v1/webtransport/certhash/uEiAySGBS1QrMiDdzRdlR1r194dm4Q0bIBHpZDbcOohIBZA/certhash/uEiAh7IjXWPwLQ06Pzmpm3mur-HqcT7e2NOoUXpCRH-A29w","/ip4/139.178.82.19/udp/53436/quic-v1/webtransport/certhash/uEiAySGBS1QrMiDdzRdlR1r194dm4Q0bIBHpZDbcOohIBZA/certhash/uEiAh7IjXWPwLQ06Pzmpm3mur-HqcT7e2NOoUXpCRH-A29w","/ip6/::1/tcp/43475","/ip6/::1/udp/38902/quic-v1/webtransport/certhash/uEiAySGBS1QrMiDdzRdlR1r194dm4Q0bIBHpZDbcOohIBZA/certhash/uEiAh7IjXWPwLQ06Pzmpm3mur-HqcT7e2NOoUXpCRH-A29w","/ip6/::1/udp/39778/webrtc-direct/certhash/uEiCONRS7m9ARSpE0k7F75NLOb_AapSsT_5-La0oi5xn4lA","/ip6/::1/udp/57999/quic-v1","/ip6/2604:1380:4642:6600::1/tcp/43475","/ip6/2604:1380:4642:6600::1/udp/38902/quic-v1/webtransport/certhash/uEiAySGBS1QrMiDdzRdlR1r194dm4Q0bIBHpZDbcOohIBZA/certhash/uEiAh7IjXWPwLQ06Pzmpm3mur-HqcT7e2NOoUXpCRH-A29w","/ip6/2604:1380:4642:6600::1/udp/39778/webrtc-direct/certhash/uEiCONRS7m9ARSpE0k7F75NLOb_AapSsT_5-La0oi5xn4lA","/ip6/2604:1380:4642:6600::1/udp/57999/quic-v1"]}
Aug 06 15:14:22 ipfs-check-backend ipfs-check[464294]: 2024-08-06T15:14:22.366Z        DEBUG        basichost        basic/basic_host.go:483        negotiated: /ipfs/id/push/1.0.0 (took 246.682µs)
Aug 06 15:14:22 ipfs-check-backend ipfs-check[464294]: 2024-08-06T15:14:22.367Z        DEBUG        net/identify        identify/id.go:545        /ipfs/id/push/1.0.0 received message from 12D3KooWLSqoMnMmDVHn45ePh3qrfCaTtJyJyr8GoLVb5DvCru9f /ip4/46.138.241.1/udp/35060/quic-v1
Aug 06 15:14:22 ipfs-check-backend ipfs-check[464294]: 2024-08-06T15:14:22.367Z        DEBUG        net/identify        identify/id.go:834        12D3KooWN9TbR9KRhQ684bsnQziRMq2d5msyaqyHGYZMht89Cr15 received listen addrs for 12D3KooWLSqoMnMmDVHn45ePh3qrfCaTtJyJyr8GoLVb5DvCru9f: [/ip4/46.138.241.1/tcp/35060 /ip4/46.138.241.1/udp/35060/quic-v1 /ip4/46.138.241.1/udp/35060/quic-v1/webtransport/certhash/uEiA2j4eHSZGjeytYFwrGM6lcJElCWf0SjrcZm8VFTuDEyw/certhash/uEiAAJ64CV7rWzOxfGqkAxRL5Aygsp5jKjGxi8TNOU4hEBA /ip4/46.138.241.1/tcp/35060 /ip4/46.138.241.1/udp/35060/quic-v1 /ip4/46.138.241.1/udp/35060/quic-v1/webtransport/certhash/uEiA2j4eHSZGjeytYFwrGM6lcJElCWf0SjrcZm8VFTuDEyw/certhash/uEiAAJ64CV7rWzOxfGqkAxRL5Aygsp5jKjGxi8TNOU4hEBA]
Aug 06 15:14:22 ipfs-check-backend ipfs-check[464294]: 2024-08-06T15:14:22.415Z        DEBUG        basichost        basic/basic_host.go:463        protocol mux failed: stream reset (took 183.541321ms, id:12D3KooWRB-2-7, remote peer:12D3KooWRBy97UB99e3J6hiPesre1MZeuNQvfan4gBziswrRJsNK, remote addr:/ip4/77.102.162.54/udp/22942/quic-v1/p2p/12D3KooWHgnuckrBHmV6KJ933PvTRoShzaSQJ7S78cbbfneTh6ve/p2p-circuit)
Aug 06 15:14:22 ipfs-check-backend ipfs-check[464294]: 2024-08-06T15:14:22.566Z        DEBUG        basichost        basic/basic_host.go:483        negotiated: /ipfs/id/push/1.0.0 (took 1.516406ms)

[2color]

After upgrading go-libp2p to the latest release and finding the root cause for the problem, I was able to patch a fix to go-libp2p which would allow hole punching to happen.

However, after discussion with @lidel, we decided that until this is fixed in go-libp2p, we should try to keep the behaviour of ipfs-check as close as possible to Boxo/Kubo.

Therefore, I took a difference approach and updated the node’s firewall rules to allow incoming UDP connections on ephemeral/dynamic ports. This would allow connection establishment through a dial back, which avoids the need for NAT hole punching. This also brings keeps ipfs-check in line with how Kubo/Rainbow works while reducing the latency of the checks.

This means though that ipfs-check does not test whether it's possible to hole punch to the peer in the check. But it's debatable whether that's something ipfs-check should check.