bug: Internal warning in iroh when doing 0rtt connections

[rklaehn]

In 0rtt connections, you can't always assume that the remote node id is available just because you have a connection. I discovered this in #3336 .

After further testing I found that this also seems to cause an internal warning inside iroh. I am not sure if this causes big problems - my test still passes. But we should either avoid this or - if this is nominal behaviour - change the log level from warn to info.

Log output of my test:

running 1 test
2025-06-03T16:42:22.958455Z  INFO iroh_content_tracker::tracker: creating tracker using database at /var/folders/b1/5yt2dj750d17d68gmjr7fqnm0000gn/T/.tmpemuplS/announce.redb
added content with hash: d3nl5jbv42eoqit2ujex4hi4r7zrdvv2wvqmt4unoc4njbc4rkca
2025-06-03T16:42:23.387380Z  INFO ep{me=1b45cc246d}:magicsock:actor: iroh::magicsock: home is now relay https://euw1-1.relay.iroh.network./, was None
2025-06-03T16:42:23.387486Z  INFO ep{me=506bd0bf45}:magicsock:actor: iroh::magicsock: home is now relay https://euw1-1.relay.iroh.network./, was None
2025-06-03T16:42:23.387539Z  INFO ep{me=4a77e8c137}:magicsock:actor: iroh::magicsock: home is now relay https://euw1-1.relay.iroh.network./, was None
querying tracker 1b45cc246d3e9f949044d0d610525f5b0c68550334bd229518ee4b4bc9846b16 for content with hash: d3nl5jbv42eoqit2ujex4hi4r7zrdvv2wvqmt4unoc4njbc4rkca
2025-06-03T16:42:24.232829Z  INFO connect{me="4a77e8c137" alpn="n0/tracker/1" remote="1b45cc246d"}:discovery{me=4a77e8c137 node=1b45cc246d}:add_node_addr{me=4a77e8c137}:add_node_addr{node=1b45cc246d}: iroh::magicsock::node_map: inserting new node in NodeMap node=1b45cc246d relay_url=Some(RelayUrl("https://euw1-1.relay.iroh.network./")) source=dns
2025-06-03T16:42:24.239958Z  INFO connect{me="4a77e8c137" alpn="n0/tracker/1" remote="1b45cc246d"}:try_send:get_send_addrs{node=1b45cc246d}: iroh::magicsock::node_map::node_state: new connection type typ=relay(https://euw1-1.relay.iroh.network./)
2025-06-03T16:42:24.281108Z  INFO ep{me=1b45cc246d}:magicsock:poll_recv:poll_recv_relay:disco_in{node=4a77e8c137 src=Relay(https://euw1-1.relay.iroh.network./, 4a77e8c137)}: iroh::magicsock::node_map: inserting new node in NodeMap node=4a77e8c137 relay_url=Some(RelayUrl("https://euw1-1.relay.iroh.network./")) source=relay
2025-06-03T16:42:24.291380Z  INFO ep{me=4a77e8c137}:magicsock:poll_recv:disco_in{node=1b45cc246d src=Udp(192.168.0.242:63768)}: iroh::magicsock::node_map::node_state: new direct addr for node addr=192.168.0.242:63768
2025-06-03T16:42:24.292885Z  INFO ep{me=1b45cc246d}:magicsock:poll_recv:disco_in{node=4a77e8c137 src=Udp(192.168.0.242:60831)}:handle_pong{m=Pong { tx_id: TransactionId(0x4B2477DE821079B66C16F530), ping_observed_addr: Udp(192.168.0.242:63768) } src=Udp(192.168.0.242:60831)}: iroh::magicsock::node_map::best_addr: selecting new direct path for node addr=192.168.0.242:60831 latency=7.664125ms trust_for=6.499963916s
2025-06-03T16:42:24.295269Z  INFO ep{me=4a77e8c137}:magicsock:poll_recv:disco_in{node=1b45cc246d src=Udp(192.168.0.242:63768)}:handle_pong{m=Pong { tx_id: TransactionId(0x8A6455D52E94854A252264CF), ping_observed_addr: Udp(192.168.0.242:60831) } src=Udp(192.168.0.242:63768)}: iroh::magicsock::node_map::best_addr: selecting new direct path for node addr=192.168.0.242:63768 latency=3.505209ms trust_for=6.499991584s
2025-06-03T16:42:24.312213Z  INFO try_send:get_send_addrs{node=4a77e8c137}: iroh::magicsock::node_map::node_state: new connection type typ=direct(192.168.0.242:60831)
2025-06-03T16:42:24.313167Z  WARN iroh::endpoint failed to get remote node id conn=Connection { inner: Connection(ConnectionRef(ConnectionInner { state: Mutex { inner: Mutex { data: State { inner: Connection { handshake_cid: [197, 1, 160, 203, 25, 76, 139, 43] } }, poisoned: false, .. } }, shared: Shared { stream_budget_available: [Notify { state: 0, waiters: Mutex(Mutex { data: LinkedList { head: None, tail: None }, poisoned: false, .. }) }, Notify { state: 0, waiters: Mutex(Mutex { data: LinkedList { head: None, tail: None }, poisoned: false, .. }) }], stream_incoming: [Notify { state: 0, waiters: Mutex(Mutex { data: LinkedList { head: None, tail: None }, poisoned: false, .. }) }, Notify { state: 0, waiters: Mutex(Mutex { data: LinkedList { head: None, tail: None }, poisoned: false, .. }) }], datagram_received: Notify { state: 0, waiters: Mutex(Mutex { data: LinkedList { head: None, tail: None }, poisoned: false, .. }) }, datagrams_unblocked: Notify { state: 0, waiters: Mutex(Mutex { data: LinkedList { head: None, tail: None }, poisoned: false, .. }) }, closed: Notify { state: 0, waiters: Mutex(Mutex { data: LinkedList { head: None, tail: None }, poisoned: false, .. }) } } })), tls_auth: RawPublicKey }
2025-06-03T16:42:24.318531Z  INFO connect{me="4a77e8c137" alpn="n0/tracker/1" remote="1b45cc246d"}:try_send:get_send_addrs{node=1b45cc246d}: iroh::magicsock::node_map::node_state: new connection type typ=direct(192.168.0.242:63768)

Location of the error:

iroh/iroh/src/endpoint.rs

Line 2189 in fad99ab

warn!(?conn, "failed to get remote node id");

[rklaehn]

@flub says the magic words "multipath fixes this"...

Todo: revisit after multipath gets merged!