Hole punching over takes over 5 seconds between peers

[2color]

What's wrong

Given the following scenario:

• 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 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

// ----------------- 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"}