libp2p / libp2p/rust-libp2p

AutoNAT requests time out

Open
#3,986 8 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

bug
Dominant language
Rust
Stars
5.6k
Forks
1.3k
Avg merge
8h 47m
Merged PRs (30d)
19

Description

Summary

About 20 publicy reachable peers are added as AutoNAT servers and are probed. From behind a NAT. After the timeout (set to 15s), AutoNAT gives an error OutboundRequest(Timeout) and probes another peer again. This continues, but sometimes a Response(DialError) is reported and that results in an AutoNAT status change.

It's unclear to me why the OutboundRequest(Timeout) occurs. This stems from the request_response protocol. I assume an AutoNAT server can't dial a NAT peer, and takes too long to answer the dial-back probe request.

Expected behaviour

Either the timeouts not to happen, or the timeouts to cause the AutoNAT status to change to Private eventually.

Actual behaviour

Sometimes it takes more than a few minutes (up to 20) for a node to determine it's Private. This only happens after a DialError, no the Timeout.

Debug Output 

[2023-05-22T12:28:33.436488Z] Request { probe_id: ProbeId(0), peer: PeerId("12D3KooWAbnBXNeWyy3HAqpV7aFfos9Wv4sPapetvz2Z9oYJ9U81") }
[2023-05-22T12:28:48.437264Z] Error { probe_id: ProbeId(0), peer: Some(PeerId("12D3KooWAbnBXNeWyy3HAqpV7aFfos9Wv4sPapetvz2Z9oYJ9U81")), error: OutboundRequest(Timeout) }
[2023-05-22T12:28:48.437329Z] Request { probe_id: ProbeId(1), peer: PeerId("12D3KooWDzmAGQ9ykuZSb891Df6E8FxkUXJgr9XV38VgPPzgQzx3") }
[2023-05-22T12:29:03.437614Z] Error { probe_id: ProbeId(1), peer: Some(PeerId("12D3KooWDzmAGQ9ykuZSb891Df6E8FxkUXJgr9XV38VgPPzgQzx3")), error: OutboundRequest(Timeout) }
[2023-05-22T12:29:03.437687Z] Request { probe_id: ProbeId(2), peer: PeerId("12D3KooWDzmAGQ9ykuZSb891Df6E8FxkUXJgr9XV38VgPPzgQzx3") }
[2023-05-22T12:29:18.437944Z] Error { probe_id: ProbeId(2), peer: Some(PeerId("12D3KooWDzmAGQ9ykuZSb891Df6E8FxkUXJgr9XV38VgPPzgQzx3")), error: OutboundRequest(Timeout) }
[2023-05-22T12:29:18.438020Z] Request { probe_id: ProbeId(3), peer: PeerId("12D3KooWDzmAGQ9ykuZSb891Df6E8FxkUXJgr9XV38VgPPzgQzx3") }
[2023-05-22T12:29:33.438292Z] Error { probe_id: ProbeId(3), peer: Some(PeerId("12D3KooWDzmAGQ9ykuZSb891Df6E8FxkUXJgr9XV38VgPPzgQzx3")), error: OutboundRequest(Timeout) }
[2023-05-22T12:29:33.438356Z] Request { probe_id: ProbeId(4), peer: PeerId("12D3KooWSf3AciihWbr5sjKdNn55pWQbYqU53taT4RHU378mvDLa") }
[2023-05-22T12:29:48.438727Z] Error { probe_id: ProbeId(4), peer: Some(PeerId("12D3KooWSf3AciihWbr5sjKdNn55pWQbYqU53taT4RHU378mvDLa")), error: OutboundRequest(Timeout) }
[2023-05-22T12:29:48.438803Z] Request { probe_id: ProbeId(5), peer: PeerId("12D3KooWQ6goXTX4QawAzvvFgVymJ28MNXenh3r46bLKCkvKySzP") }
[2023-05-22T12:30:03.439084Z] Error { probe_id: ProbeId(5), peer: Some(PeerId("12D3KooWQ6goXTX4QawAzvvFgVymJ28MNXenh3r46bLKCkvKySzP")), error: OutboundRequest(Timeout) }
[2023-05-22T12:30:03.439166Z] Request { probe_id: ProbeId(6), peer: PeerId("12D3KooWLrZhGdBx8HKcvm2QcLCaZwWHPpj8ScwKYGsTFiV75vqq") }
[2023-05-22T12:30:19.179148Z] Error { probe_id: ProbeId(6), peer: Some(PeerId("12D3KooWLrZhGdBx8HKcvm2QcLCaZwWHPpj8ScwKYGsTFiV75vqq")), error: OutboundRequest(Timeout) }
[2023-05-22T12:30:19.179216Z] Request { probe_id: ProbeId(7), peer: PeerId("12D3KooWLrZhGdBx8HKcvm2QcLCaZwWHPpj8ScwKYGsTFiV75vqq") }
[2023-05-22T12:30:34.179434Z] Error { probe_id: ProbeId(7), peer: Some(PeerId("12D3KooWLrZhGdBx8HKcvm2QcLCaZwWHPpj8ScwKYGsTFiV75vqq")), error: OutboundRequest(Timeout) }
[2023-05-22T12:30:34.179507Z] Request { probe_id: ProbeId(9), peer: PeerId("12D3KooWQ6goXTX4QawAzvvFgVymJ28MNXenh3r46bLKCkvKySzP") }
[2023-05-22T12:30:49.179737Z] Error { probe_id: ProbeId(9), peer: Some(PeerId("12D3KooWQ6goXTX4QawAzvvFgVymJ28MNXenh3r46bLKCkvKySzP")), error: OutboundRequest(Timeout) }
[2023-05-22T12:30:49.179795Z] Request { probe_id: ProbeId(10), peer: PeerId("12D3KooWAHseCqSDRgJbGkhSEiZu6psQ97wVpFDjN6uUHNu5Hbeo") }
[2023-05-22T12:31:04.857627Z] Error { probe_id: ProbeId(10), peer: Some(PeerId("12D3KooWAHseCqSDRgJbGkhSEiZu6psQ97wVpFDjN6uUHNu5Hbeo")), error: OutboundRequest(Timeout) }
[2023-05-22T12:31:04.857685Z] Request { probe_id: ProbeId(11), peer: PeerId("12D3KooWC7cAfXzsrn2VFsR4kzUNZB2FovAtLosbRW43wsBhkesZ") }
[2023-05-22T12:31:19.857992Z] Error { probe_id: ProbeId(11), peer: Some(PeerId("12D3KooWC7cAfXzsrn2VFsR4kzUNZB2FovAtLosbRW43wsBhkesZ")), error: OutboundRequest(Timeout) }
[2023-05-22T12:31:19.858092Z] Request { probe_id: ProbeId(12), peer: PeerId("12D3KooWF9EwYGR7aon6SGzxHv5o2uFrJKEMuGmDjbhm4v9FH7pR") }
[2023-05-22T12:31:34.858414Z] Error { probe_id: ProbeId(12), peer: Some(PeerId("12D3KooWF9EwYGR7aon6SGzxHv5o2uFrJKEMuGmDjbhm4v9FH7pR")), error: OutboundRequest(Timeout) }
[2023-05-22T12:31:34.858492Z] Request { probe_id: ProbeId(13), peer: PeerId("12D3KooWDzmAGQ9ykuZSb891Df6E8FxkUXJgr9XV38VgPPzgQzx3") }
[2023-05-22T12:31:50.232443Z] Error { probe_id: ProbeId(13), peer: Some(PeerId("12D3KooWDzmAGQ9ykuZSb891Df6E8FxkUXJgr9XV38VgPPzgQzx3")), error: OutboundRequest(Timeout) }
[2023-05-22T12:31:50.232501Z] Request { probe_id: ProbeId(14), peer: PeerId("12D3KooWSgSKZ9LqMyW9shqbzqWDEpY5Hdkyi1frinqyTPRfbtL5") }
[2023-05-22T12:32:05.232871Z] Error { probe_id: ProbeId(14), peer: Some(PeerId("12D3KooWSgSKZ9LqMyW9shqbzqWDEpY5Hdkyi1frinqyTPRfbtL5")), error: OutboundRequest(Timeout) }
[2023-05-22T12:32:05.232933Z] Request { probe_id: ProbeId(15), peer: PeerId("12D3KooWAbnBXNeWyy3HAqpV7aFfos9Wv4sPapetvz2Z9oYJ9U81") }
[2023-05-22T12:32:20.233317Z] Error { probe_id: ProbeId(15), peer: Some(PeerId("12D3KooWAbnBXNeWyy3HAqpV7aFfos9Wv4sPapetvz2Z9oYJ9U81")), error: OutboundRequest(Timeout) }
[2023-05-22T12:32:20.233391Z] Request { probe_id: ProbeId(16), peer: PeerId("12D3KooWMnXSasKf1MWKLrwhBinYELzESoeHnpYjospjkMTV8ZUV") }
[2023-05-22T12:32:35.883220Z] Error { probe_id: ProbeId(16), peer: Some(PeerId("12D3KooWMnXSasKf1MWKLrwhBinYELzESoeHnpYjospjkMTV8ZUV")), error: OutboundRequest(Timeout) }
[2023-05-22T12:32:35.883400Z] Request { probe_id: ProbeId(17), peer: PeerId("12D3KooWQ6goXTX4QawAzvvFgVymJ28MNXenh3r46bLKCkvKySzP") }
[2023-05-22T12:32:45.434329Z] Error { probe_id: ProbeId(17), peer: Some(PeerId("12D3KooWQ6goXTX4QawAzvvFgVymJ28MNXenh3r46bLKCkvKySzP")), error: Response(DialError) }
[2023-05-22T12:32:45.434439Z] AutoNAT status changed: Unknown -> Private

Version

  • libp2p version (version number, commit, or branch): 0.51.3

Would you like to work on fixing this bug?

Maybe.

Contributor guide

Open the contributing guide

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.

Research direction

Start with the AutoNAT implementation and its request_response protocol handling, then trace the logged OutboundRequest(Timeout) and Response(DialError) outcomes. Reproduce the behavior using the reported 15-second timeout and debug sequence. Done means timeout outcomes eventually produce the expected Private status, or the reason they should not occur is established with regression coverage.

Written by the indexing model from the issue text.

Assessment

Tech stack
rust
Domain
networking
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.