Failing relay connection on master

[drHuangMHT]

Relay connection works fine on 0.53.2 but not on master branch. I managed to pin down the problematic commit 6a91617 however the commit seems unrelated to relay. Previous commit 6f9c9e5 works fine. On problematic commit, dialer swarm reported OutgoingConnectionError with Outgoing connection error: [("/ip4/./tcp/./p2p/12D3KooWFfS5mMZxMhuTr2LVA2oWFURr6gu6rvgntEVWZk3vJqTb/p2p-circuit/p2p/12D3KooWS2cxB2fTkigGX79zuxJwnRS3ds6RJsDuhKmTdyNwQham", "Response from behaviour was canceled")].
Using later commits result in half-established relay connection e.g. data flows one way but not another.

[drHuangMHT]

Confirmed that kad behaviour will upset relay server. Still digging.

[drHuangMHT]

It seems that kadelima bootstrapping interferes relay connection, any idea @PanGan21 since you started #4838

[PanGan21]

Hi @drHuangMHT I am not sure how the change in bootstrapping effects the relay connection. I will scan again the commit you pointed to see if I can find something related

[drHuangMHT]

by the way, I have observed some significant performance downgrade with DHT walkthrough. It ran just fine even on my surface go but now my laptop is having a hard time.

[PanGan21]

I had a first look, but couldn't identify something. Wouldn't it be better to directly open a bug in the issues?

[drHuangMHT]

I'm struggling to setup a minimal working example because the runtime did not want to poll the swarm, nor futures_timer::Delay (I accidentally set timeout to 200s instead of 200 milliseconds). I don't know why because the setup looks exactly the same as my application, which includes a lot of glue code that I'm not sure if it has some effect on how the swarm is handled. I will open an issue when I get the example working.

[dariusc93]

Testing with master myself, I do not see this error nor have any issues with relay connections. Could you provide any code or maybe logs @drHuangMHT?

[dariusc93]

And bare in mind, this id with kad enabled too but also tested without it enabled.

[drHuangMHT]

This test would fail on 6a91617: https://github.com/Owlput/OwlNest/blob/a07837110feee235a030595ac8c0396a466746e1/owlnest/src/net/p2p/protocols/relay_client.rs#L110-L157
The last assertion would fail(dialer not connected to listener through relay) with log:

server 12D3KooWGyGdMg2UytssPncbXd1dDCUtWhKs6e29GjGvW8ZS3NXk setup
listener 12D3KooWHP9btdU3djk6sUpgpnTYDLQzoS94DPrPPnSS23guDKQB setup
dialer 12D3KooWKX5qPjqunugs8b8o2Kcwtp8NHmsrFY1z1JDFE5PswD3r setup
......
2024-04-23T04:12:01.211575Z  INFO owlnest::net::p2p::swarm::event_handlers: A possible external address has been discovered: /ip4/127.0.0.1/tcp/11487   
2024-04-23T04:12:01.393827Z DEBUG owlnest::net::p2p::protocols::relay_server: Reservation from 12D3KooWHP9btdU3djk6sUpgpnTYDLQzoS94DPrPPnSS23guDKQB accepted, IsRenew:false
2024-04-23T04:12:01.394536Z DEBUG Swarm::poll: libp2p_kad::behaviour: Switching to server-mode assuming that one of [/ip4/127.0.0.1/tcp/11487/p2p/12D3KooWGyGdMg2UytssPncbXd1dDCUtWhKs6e29GjGvW8ZS3NXk/p2p-circuit/p2p/12D3KooWHP9btdU3djk6sUpgpnTYDLQzoS94DPrPPnSS23guDKQB] is externally reachable
2024-04-23T04:12:01.394820Z DEBUG Swarm::poll: libp2p_kad::behaviour: Re-configuring 1 established connection
2024-04-23T04:12:01.395057Z  INFO owlnest::net::p2p::swarm::event_handlers: A possible external address has been confirmed: /ip4/127.0.0.1/tcp/11487/p2p/12D3KooWGyGdMg2UytssPncbXd1dDCUtWhKs6e29GjGvW8ZS3NXk/p2p-circuit/p2p/12D3KooWHP9btdU3djk6sUpgpnTYDLQzoS94DPrPPnSS23guDKQB
2024-04-23T04:12:01.395520Z  INFO owlnest::net::p2p::protocols::kad: The mode of this peer has been changed to server
2024-04-23T04:12:01.395922Z DEBUG Swarm::poll: libp2p_swarm: New listener address listener=ListenerId(2) address=/ip4/127.0.0.1/tcp/11487/p2p/12D3KooWGyGdMg2UytssPncbXd1dDCUtWhKs6e29GjGvW8ZS3NXk/p2p-circuit/p2p/12D3KooWHP9btdU3djk6sUpgpnTYDLQzoS94DPrPPnSS23guDKQB
2024-04-23T04:12:01.396247Z DEBUG Swarm::poll: libp2p_upnp::behaviour: multiaddress not supported for UPnP /ip4/127.0.0.1/tcp/11487/p2p/12D3KooWGyGdMg2UytssPncbXd1dDCUtWhKs6e29GjGvW8ZS3NXk/p2p-circuit/p2p/12D3KooWHP9btdU3djk6sUpgpnTYDLQzoS94DPrPPnSS23guDKQB
2024-04-23T04:12:01.396531Z  INFO owlnest::net::p2p::swarm::event_handlers: Listening on "/ip4/127.0.0.1/tcp/11487/p2p/12D3KooWGyGdMg2UytssPncbXd1dDCUtWhKs6e29GjGvW8ZS3NXk/p2p-circuit/p2p/12D3KooWHP9btdU3djk6sUpgpnTYDLQzoS94DPrPPnSS23guDKQB"
2024-04-23T04:12:01.396996Z DEBUG new_established_connection{remote_addr=/ip4/127.0.0.1/tcp/11487 id=1 peer=12D3KooWGyGdMg2UytssPncbXd1dDCUtWhKs6e29GjGvW8ZS3NXk}: libp2p_kad::handler: Changed mode on outbound connection peer=12D3KooWGyGdMg2UytssPncbXd1dDCUtWhKs6e29GjGvW8ZS3NXk mode=server
2024-04-23T04:12:01.397483Z DEBUG new_established_connection{remote_addr=/ip4/127.0.0.1/tcp/11487 id=1 peer=12D3KooWGyGdMg2UytssPncbXd1dDCUtWhKs6e29GjGvW8ZS3NXk}:Connection::poll: libp2p_identify::handler: Supported listen protocols changed, pushing to peer peer=12D3KooWGyGdMg2UytssPncbXd1dDCUtWhKs6e29GjGvW8ZS3NXk before=/libp2p/circuit/relay/0.2.0/stop, /libp2p/autonat/1.0.0, /owlnest/blob/0.0.1, /ipfs/ping/1.0.0, /libp2p/circuit/relay/0.2.0/hop, /owlnest/advertise/0.0.1, /ipfs/id/1.0.0, /owlnest/messaging/0.0.1, /ipfs/id/push/1.0.0 after=/libp2p/circuit/relay/0.2.0/stop, /libp2p/autonat/1.0.0, /owlnest/blob/0.0.1, /ipfs/ping/1.0.0, /libp2p/circuit/relay/0.2.0/hop, /owlnest/advertise/0.0.1, /ipfs/kad/1.0.0, /ipfs/id/1.0.0, /owlnest/messaging/0.0.1, /ipfs/id/push/1.0.0
2024-04-23T04:12:01.399783Z DEBUG owlnest::net::p2p::protocols::identify: Identified peer 12D3KooWHP9btdU3djk6sUpgpnTYDLQzoS94DPrPPnSS23guDKQB : /owlnest/0.0.1
2024-04-23T04:12:01.510076Z DEBUG Transport::dial{address=/ip4/10.21.219.12/tcp/11487/p2p/12D3KooWGyGdMg2UytssPncbXd1dDCUtWhKs6e29GjGvW8ZS3NXk}: libp2p_dns: Dialing address address=/ip4/10.21.219.12/tcp/11487/p2p/12D3KooWGyGdMg2UytssPncbXd1dDCUtWhKs6e29GjGvW8ZS3NXk
2024-04-23T04:12:01.510589Z DEBUG Transport::dial{address=/ip4/10.21.219.12/tcp/11487/p2p/12D3KooWGyGdMg2UytssPncbXd1dDCUtWhKs6e29GjGvW8ZS3NXk}: libp2p_tcp: dialing address address=10.21.219.12:11487
2024-04-23T04:12:01.511229Z DEBUG Transport::dial{address=/ip4/172.28.192.1/tcp/11487/p2p/12D3KooWGyGdMg2UytssPncbXd1dDCUtWhKs6e29GjGvW8ZS3NXk}: libp2p_dns: Dialing address address=/ip4/172.28.192.1/tcp/11487/p2p/12D3KooWGyGdMg2UytssPncbXd1dDCUtWhKs6e29GjGvW8ZS3NXk
2024-04-23T04:12:01.511603Z DEBUG Transport::dial{address=/ip4/172.28.192.1/tcp/11487/p2p/12D3KooWGyGdMg2UytssPncbXd1dDCUtWhKs6e29GjGvW8ZS3NXk}: libp2p_tcp: dialing address address=172.28.192.1:11487
2024-04-23T04:12:01.511984Z  INFO owlnest::net::p2p::protocols::kad: Incoming request: FindNode { num_closer_peers: 0 }
2024-04-23T04:12:01.513100Z DEBUG owlnest::net::p2p::protocols::kad: Outbound query QueryId(0) progressed, stats: QueryStats { requests: 1, success: 1, failure: 0, start: Some(Instant { t: 418702.8310703s }), end: Some(Instant { t: 418702.8350222s }) }, step: ProgressStep { count: 1, last: true }, result: Bootstrap(Ok(BootstrapOk { peer: PeerId("12D3KooWHP9btdU3djk6sUpgpnTYDLQzoS94DPrPPnSS23guDKQB"), num_remaining: 0 }))
2024-04-23T04:12:01.593210Z DEBUG Swarm::poll: libp2p_swarm: Connection attempt to peer failed with Transport([("/ip4/127.0.0.1/tcp/11487/p2p/12D3KooWGyGdMg2UytssPncbXd1dDCUtWhKs6e29GjGvW8ZS3NXk/p2p-circuit/p2p/12D3KooWHP9btdU3djk6sUpgpnTYDLQzoS94DPrPPnSS23guDKQB", Other(Custom { kind: Other, error: Other(Left(Left(Left(ResponseFromBehaviourCanceled(Canceled))))) }))]). peer=12D3KooWHP9btdU3djk6sUpgpnTYDLQzoS94DPrPPnSS23guDKQB
2024-04-23T04:12:01.593804Z  INFO owlnest::net::p2p::swarm::event_handlers: Outgoing connection error: [("/ip4/127.0.0.1/tcp/11487/p2p/12D3KooWGyGdMg2UytssPncbXd1dDCUtWhKs6e29GjGvW8ZS3NXk/p2p-circuit/p2p/12D3KooWHP9btdU3djk6sUpgpnTYDLQzoS94DPrPPnSS23guDKQB", "other error")],self:12D3KooWKX5qPjqunugs8b8o2Kcwtp8NHmsrFY1z1JDFE5PswD3r
2024-04-23T04:12:01.712851Z  INFO owlnest::net::p2p::protocols::kad: Incoming request: FindNode { num_closer_peers: 0 }

Test is performed with and without libp2p-kad, and with 6a91617, with 6f9c9e5, with libp2p={version = "*", features = ["full"]}, only with libp2p-kad and 6a91617 resulted in error.

[dariusc93]

I did skim over the code but dont see anything explicitly that would cause it to error though based on the error I wonder if the connection is being closed early. Do you have the idle timeout set to anything besides 0? If not, could you add with_swarm_config(|cfg| cfg.with_idle_connection_timeout(Duration::from_secs(10))) to your swarm builder and see if it helps?

EDIT: Though I misread the beginning of the error, seeing ResponseFromBehaviourCanceled suggest to me that it may have been closed in some way as the only reason why it would have been cancelled is if the sender was dropped, which i can only imagine being the case when preloading the relay handler or sending the event to the handler but the connection closed before it had the chance to process the future. Havent been able to reproduce it myself on libp2p or on my own project using the latest commit though

[drHuangMHT]

In theory, relayed peers will start exchanging ping messages immediately after connection established, plus the connection was dropped immediately after dialing, so idle_connection_timeout shouldn't matter. In practice, setting it to 10 seconds(not 10 milliseconds I swear I'm not making the same mistake) did not make a difference. Longer duration(10s for example) between listen and dial will pass, probably because the connection will be established after bootstrapping has stopped.
EDIT: 10 seconds between listen and dial didn't work, seemingly because there's still ongoing query(OutboundQueryProgressed reported num_remaining = 1), and 20 seconds would pass.