libp2p / libp2p/go-libp2p

Hole punching over takes over 5 seconds between peers

Open
#2,898 0 comments 0 reactions 1 assignee View on GitHub

@sukunrt is already working on this.

Since Aug 1, 2024.

Dominant language
Go
Stars
6.9k
Forks
1.3k
Avg merge
13d 21h
Merged PRs (30d)
1

Description

## What's wrong

Given the following scenario:
![image](https://github.com/user-attachments/assets/ab920412-fa8a-4064-940e-ed49fbca0e94)

- 1 go-libp2p peer with a public IP
- 1 kubo go-libp2p peer behind NAT with a circuit relay 2 reservation over QUIC
- circuit relay v2 peer

Holepunching take just over 5 seconds even though the latency between the peers is no more than 150ms.

This problem was observed in the [Vole](https://github.com/ipfs-shipyard/vole/blob/main/lib/bitswap.go#L57) `CheckBitswapCID` method.

Due to a context deadline shorter than the ~5 seconds it takes for the hole punching to succeed, that is defined in the Boxo Bitswap implementation, a workaround was added to open a stream before with a longer deadline. Below are debug logs showing the connection succeeding using this approach after a little over 5 seconds.

## logs

Below are the logs from a [feature branch of Vole, whereby we open a stream right after opening the connection to force hole punching](https://github.com/ipfs-shipyard/vole/blob/help-holepunch/lib/bitswap.go#L79-L85)
```
// ----------------- HERE it starts
2024-07-31T11:06:16.992Z DEBUG p2p-holepunch holepunch/svc.go:110 Host now has a public address. Starting holepunch protocol.
2024-07-31T11:06:16.992Z DEBUG net/identify identify/id.go:624 updating snapshot {"seq": 3, "addrs": ["/ip4/127.0.0.1/tcp/36901","/ip4/127.0.0.1/udp/38707/quic-v1","/ip4/127.0.0.1/udp/56914/quic-v1/webtransport/certhash/uEiBEj8e4Ym4vWNZspR4f-U462pNF8nWRXBpKlWwwgdIyrQ/certhash/uEiDk3TStq8mJkiPh5WByUePjJBtHRy-y-n9dS5Ytq23gFQ","/ip4/139.178.82.19/tcp/36901","/ip4/139.178.82.19/udp/38707/quic-v1","/ip4/139.178.82.19/udp/56914/quic-v1/webtransport/certhash/uEiBEj8e4Ym4vWNZspR4f-U462pNF8nWRXBpKlWwwgdIyrQ/certhash/uEiDk3TStq8mJkiPh5WByUePjJBtHRy-y-n9dS5Ytq23gFQ","/ip6/::1/tcp/37059","/ip6/::1/udp/55676/quic-v1/webtransport/certhash/uEiBEj8e4Ym4vWNZspR4f-U462pNF8nWRXBpKlWwwgdIyrQ/certhash/uEiDk3TStq8mJkiPh5WByUePjJBtHRy-y-n9dS5Ytq23gFQ","/ip6/::1/udp/60406/quic-v1","/ip6/2604:1380:4642:6600::1/tcp/37059","/ip6/2604:1380:4642:6600::1/udp/55676/quic-v1/webtransport/certhash/uEiBEj8e4Ym4vWNZspR4f-U462pNF8nWRXBpKlWwwgdIyrQ/certhash/uEiDk3TStq8mJkiPh5WByUePjJBtHRy-y-n9dS5Ytq23gFQ","/ip6/2604:1380:4642:6600::1/udp/60406/quic-v1"]}
2024-07-31T11:06:16.993Z DEBUG swarm2 swarm/swarm.go:456 [12D3KooWR43wPM5xZDiqBJnT9yEDqVXnuXEh5FivJWf2G22UH4uU] opening stream to peer [12D3KooWNBX1doGe7xKQ9yKwetHMbcp9P3BFZLozSvzjwt7QyAX4]
2024-07-31T11:06:16.993Z DEBUG net/identify identify/id.go:489 sending snapshot {"seq": 3, "protocols": ["/ipfs/id/1.0.0","/ipfs/id/push/1.0.0","/ipfs/ping/1.0.0","/libp2p/circuit/relay/0.2.0/stop","/libp2p/dcutr"], "addrs": ["/ip4/127.0.0.1/tcp/36901","/ip4/127.0.0.1/udp/38707/quic-v1","/ip4/127.0.0.1/udp/56914/quic-v1/webtransport/certhash/uEiBEj8e4Ym4vWNZspR4f-U462pNF8nWRXBpKlWwwgdIyrQ/certhash/uEiDk3TStq8mJkiPh5WByUePjJBtHRy-y-n9dS5Ytq23gFQ","/ip4/139.178.82.19/tcp/36901","/ip4/139.178.82.19/udp/38707/quic-v1","/ip4/139.178.82.19/udp/56914/quic-v1/webtransport/certhash/uEiBEj8e4Ym4vWNZspR4f-U462pNF8nWRXBpKlWwwgdIyrQ/certhash/uEiDk3TStq8mJkiPh5WByUePjJBtHRy-y-n9dS5Ytq23gFQ","/ip6/::1/tcp/37059","/ip6/::1/udp/55676/quic-v1/webtransport/certhash/uEiBEj8e4Ym4vWNZspR4f-U462pNF8nWRXBpKlWwwgdIyrQ/certhash/uEiDk3TStq8mJkiPh5WByUePjJBtHRy-y-n9dS5Ytq23gFQ","/ip6/::1/udp/60406/quic-v1","/ip6/2604:1380:4642:6600::1/tcp/37059","/ip6/2604:1380:4642:6600::1/udp/55676/quic-v1/webtransport/certhash/uEiBEj8e4Ym4vWNZspR4f-U462pNF8nWRXBpKlWwwgdIyrQ/certhash/uEiDk3TStq8mJkiPh5WByUePjJBtHRy-y-n9dS5Ytq23gFQ","/ip6/2604:1380:4642:6600::1/udp/60406/quic-v1"]}
2024-07-31T11:06:16.993Z DEBUG net/identify identify/id.go:494 /ipfs/id/1.0.0 sending message to 12D3KooWNBX1doGe7xKQ9yKwetHMbcp9P3BFZLozSvzjwt7QyAX4 /ip4/91.230.111.120/udp/4001/quic-v1
2024-07-31T11:06:17.004Z DEBUG swarm2 swarm/limiter.go:94 [limiter] freeing peer token; peer 12D3KooWRBy97UB99e3J6hiPesre1MZeuNQvfan4gBziswrRJsNK; addr: /ip4/91.230.111.120/udp/4001/quic-v1/p2p/12D3KooWNBX1doGe7xKQ9yKwetHMbcp9P3BFZLozSvzjwt7QyAX4/p2p-circuit; active for peer: 1; waiting on peer limit: 0
2024-07-31T11:06:17.004Z DEBUG swarm2 swarm/limiter.go:195 [limiter] clearing all peer dials: 12D3KooWRBy97UB99e3J6hiPesre1MZeuNQvfan4gBziswrRJsNK
2024-07-31T11:06:17.158Z DEBUG basichost basic/basic_host.go:447 negotiated: /ipfs/id/1.0.0 (took 96.941µs)
2024-07-31T11:06:17.158Z DEBUG net/identify identify/id.go:545 /ipfs/id/1.0.0 received message from 12D3KooWRBy97UB99e3J6hiPesre1MZeuNQvfan4gBziswrRJsNK /ip4/91.230.111.120/udp/4001/quic-v1/p2p/12D3KooWNBX1doGe7xKQ9yKwetHMbcp9P3BFZLozSvzjwt7QyAX4/p2p-circuit
2024-07-31T11:06:17.158Z DEBUG net/identify identify/id.go:489 sending snapshot {"seq": 3, "protocols": ["/ipfs/id/1.0.0","/ipfs/id/push/1.0.0","/ipfs/ping/1.0.0","/libp2p/circuit/relay/0.2.0/stop","/libp2p/dcutr"], "addrs": ["/ip4/127.0.0.1/tcp/36901","/ip4/127.0.0.1/udp/38707/quic-v1","/ip4/127.0.0.1/udp/56914/quic-v1/webtransport/certhash/uEiBEj8e4Ym4vWNZspR4f-U462pNF8nWRXBpKlWwwgdIyrQ/certhash/uEiDk3TStq8mJkiPh5WByUePjJBtHRy-y-n9dS5Ytq23gFQ","/ip4/139.178.82.19/tcp/36901","/ip4/139.178.82.19/udp/38707/quic-v1","/ip4/139.178.82.19/udp/56914/quic-v1/webtransport/certhash/uEiBEj8e4Ym4vWNZspR4f-U462pNF8nWRXBpKlWwwgdIyrQ/certhash/uEiDk3TStq8mJkiPh5WByUePjJBtHRy-y-n9dS5Ytq23gFQ","/ip6/::1/tcp/37059","/ip6/::1/udp/55676/quic-v1/webtransport/certhash/uEiBEj8e4Ym4vWNZspR4f-U462pNF8nWRXBpKlWwwgdIyrQ/certhash/uEiDk3TStq8mJkiPh5WByUePjJBtHRy-y-n9dS5Ytq23gFQ","/ip6/::1/udp/60406/quic-v1","/ip6/2604:1380:4642:6600::1/tcp/37059","/ip6/2604:1380:4642:6600::1/udp/55676/quic-v1/webtransport/certhash/uEiBEj8e4Ym4vWNZspR4f-U462pNF8nWRXBpKlWwwgdIyrQ/certhash/uEiDk3TStq8mJkiPh5WByUePjJBtHRy-y-n9dS5Ytq23gFQ","/ip6/2604:1380:4642:6600::1/udp/60406/quic-v1"]}
2024-07-31T11:06:17.158Z DEBUG net/identify identify/id.go:494 /ipfs/id/1.0.0 sending message to 12D3KooWRBy97UB99e3J6hiPesre1MZeuNQvfan4gBziswrRJsNK /ip4/91.230.111.120/udp/4001/quic-v1/p2p/12D3KooWNBX1doGe7xKQ9yKwetHMbcp9P3BFZLozSvzjwt7QyAX4/p2p-circuit
2024-07-31T11:06:17.159Z DEBUG net/identify identify/obsaddr.go:353 observed multiaddr doesn't match the transports of any announced addresses {"from": "/ip4/91.230.111.120/udp/4001/quic-v1/p2p/12D3KooWNBX1doGe7xKQ9yKwetHMbcp9P3BFZLozSvzjwt7QyAX4/p2p-circuit", "observed": "/ip4/91.230.111.120/udp/4001/quic-v1/p2p/12D3KooWNBX1doGe7xKQ9yKwetHMbcp9P3BFZLozSvzjwt7QyAX4/p2p-circuit"}
2024-07-31T11:06:17.159Z DEBUG net/identify identify/id.go:834 12D3KooWR43wPM5xZDiqBJnT9yEDqVXnuXEh5FivJWf2G22UH4uU received listen addrs for 12D3KooWRBy97UB99e3J6hiPesre1MZeuNQvfan4gBziswrRJsNK: [/ip4/161.97.74.181/udp/4001/quic-v1/webtransport/certhash/uEiAQNCtYsLyEUf_52AjtuaYfZYRatGQu0KEWSkNCyVooPQ/certhash/uEiDGEhiF5CrsLNHhXwPnxJzFHgZG2nqURaRfnDE7INVx1w/p2p/12D3KooWSCZDKzmMMSyQ9dVho3ZoYHwxiKHfK9gWk7QHhMX8NzwR/p2p-circuit /ip4/161.97.74.181/udp/4001/quic-v1/p2p/12D3KooWSCZDKzmMMSyQ9dVho3ZoYHwxiKHfK9gWk7QHhMX8NzwR/p2p-circuit /ip4/161.97.74.181/udp/4001/quic/p2p/12D3KooWSCZDKzmMMSyQ9dVho3ZoYHwxiKHfK9gWk7QHhMX8NzwR/p2p-circuit /ip4/91.230.111.120/udp/4001/quic/p2p/12D3KooWNBX1doGe7xKQ9yKwetHMbcp9P3BFZLozSvzjwt7QyAX4/p2p-circuit /ip4/91.230.111.120/udp/4001/quic-v1/p2p/12D3KooWNBX1doGe7xKQ9yKwetHMbcp9P3BFZLozSvzjwt7QyAX4/p2p-circuit /ip4/91.230.111.120/tcp/4001/p2p/12D3KooWNBX1doGe7xKQ9yKwetHMbcp9P3BFZLozSvzjwt7QyAX4/p2p-circuit /ip4/91.230.111.120/udp/4001/quic-v1/webtransport/certhash/uEiDNzwiXlFvHCwl0z2PT5IdDDZnZPRr-w81ktfiUNu2P5Q/certhash/uEiDS_rMag_DVWzFD9HTXKvqx5z--ChCDhGgRLiJqZR9o3g/p2p/12D3KooWNBX1doGe7xKQ9yKwetHMbcp9P3BFZLozSvzjwt7QyAX4/p2p-circuit]
2024-07-31T11:06:17.159Z DEBUG basichost basic/basic_host.go:770 host 12D3KooWR43wPM5xZDiqBJnT9yEDqVXnuXEh5FivJWf2G22UH4uU finished dialing 12D3KooWRBy97UB99e3J6hiPesre1MZeuNQvfan4gBziswrRJsNK
new stream2024-07-31T11:06:17.159Z DEBUG basichost basic/basic_host.go:753 host 12D3KooWR43wPM5xZDiqBJnT9yEDqVXnuXEh5FivJWf2G22UH4uU dialing 12D3KooWRBy97UB99e3J6hiPesre1MZeuNQvfan4gBziswrRJsNK
2024-07-31T11:06:17.159Z DEBUG swarm2 swarm/swarm_dial.go:240 dialing peer {"from": "12D3KooWR43wPM5xZDiqBJnT9yEDqVXnuXEh5FivJWf2G22UH4uU", "to": "12D3KooWRBy97UB99e3J6hiPesre1MZeuNQvfan4gBziswrRJsNK"}
2024-07-31T11:06:17.159Z DEBUG basichost basic/basic_host.go:770 host 12D3KooWR43wPM5xZDiqBJnT9yEDqVXnuXEh5FivJWf2G22UH4uU finished dialing 12D3KooWRBy97UB99e3J6hiPesre1MZeuNQvfan4gBziswrRJsNK
2024-07-31T11:06:17.160Z DEBUG swarm2 swarm/swarm.go:456 [12D3KooWR43wPM5xZDiqBJnT9yEDqVXnuXEh5FivJWf2G22UH4uU] opening stream to peer [12D3KooWRBy97UB99e3J6hiPesre1MZeuNQvfan4gBziswrRJsNK]
2024-07-31T11:06:22.321Z DEBUG basichost basic/basic_host.go:447 negotiated: /libp2p/dcutr (took 140.802µs)

------------------ FINALLY RECEIVES HOLE PUNCH REQUEST
2024-07-31T11:06:22.322Z DEBUG p2p-holepunch holepunch/svc.go:210 received hole punch request {"peer": "12D3KooWRBy97UB99e3J6hiPesre1MZeuNQvfan4gBziswrRJsNK", "addrs": ["/ip4/87.171.77.178/udp/4001/quic-v1"]}
2024-07-31T11:06:22.475Z DEBUG p2p-holepunch holepunch/svc.go:268 starting hole punch {"peer": "12D3KooWRBy97UB99e3J6hiPesre1MZeuNQvfan4gBziswrRJsNK"}
```

Contributor guide

No contributing guide indexed for this repository

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.