From 2e43523f75f6136eb9c75da991dfcc43d7da1408 Mon Sep 17 00:00:00 2001 From: Thomas Eizinger Date: Tue, 18 Feb 2025 19:25:45 +1100 Subject: [PATCH] fix(snownet): servers should not initiate WireGuard sessions (#8169) Whilst ICE for a connection is in progress, it might happen that packets for a particular client are arriving at the Gateway's TUN device. I assume that these might be from a previous session? We can only negotiate a WireGuard session once we have a nominated socket. Thus, the very first packet sent on a session will always trigger a new handshake. We don't want Gateway's to start handshakes though, those should always be initiated by the Clients. To avoid this, we add a conditional to `snownet::Node` that drops packets iff the current node is a `ServerNode` and we haven't nominated a socket yet. The following log output from a Gateway motivated this change: ``` 2025-02-17T15:36:45.372Z INFO snownet::node: Connection failed (ICE timeout) cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 // Here the previous connection failed. 2025-02-17T15:36:45.989Z DEBUG firezone_tunnel::gateway: Unknown client, perhaps already disconnected? dst=100.64.69.110 2025-02-17T15:36:45.989Z DEBUG firezone_tunnel::gateway: Unknown client, perhaps already disconnected? dst=100.64.69.110 2025-02-17T15:36:45.989Z DEBUG firezone_tunnel::gateway: Unknown client, perhaps already disconnected? dst=100.64.69.110 2025-02-17T15:36:46.213Z DEBUG firezone_tunnel::gateway: Unknown client, perhaps already disconnected? dst=100.64.69.110 // Until here, packets for this client got dropped but now a new connection (for the same IP!) is being created. 2025-02-17T15:36:46.474Z DEBUG snownet::node: Sampled relay rid=b7198983-0cf6-48ba-a459-e7d27ef7d6c9 client_id=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.474Z INFO str0m::ice_::agent: Set local credentials: IceCreds { ufrag: "ipcg", pass: "eyy6s27emu2joisw7aqc7q" } client_id=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.474Z INFO str0m::ice_::agent: Set remote credentials: IceCreds { ufrag: "up5k", pass: "4q6uvhawhcbnhbqrddvy5x" } client_id=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.474Z INFO str0m::ice_::agent: Add local candidate: Candidate(host=10.0.0.4:38621/udp prio=2130706175) client_id=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.474Z INFO str0m::ice_::agent: Add local candidate: Candidate(relay=34.16.221.134:62250/udp prio=37748479) client_id=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.474Z INFO str0m::ice_::agent: Add local candidate: Candidate(relay=[2600:1900:4180:ee3:0:78::]:62250/udp prio=37748735) client_id=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.474Z INFO str0m::ice_::agent: State change (new connection): New -> Checking client_id=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.474Z INFO snownet::node: Created new connection client_id=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.475Z INFO firezone_tunnel::peer: Allowing access to resource client=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 resource=dca3fcc6-b5e0-470a-bc7b-6446cdd03bb3 expires=Some("2025-02-24T15:09:11+00:00") client_id=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 // The connection has been created and very likely another packet has arrived at the TUN interface. This time though, we have an entry in our connection map for this IP and try to route it. 2025-02-17T15:36:46.546Z DEBUG boringtun::noise: Sending handshake_initiation cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.546Z DEBUG snownet::node: ICE is still in progress, buffering WG handshake num_buffered=1 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 // We buffered the handshake packet. This is only meant to be done by clients. 2025-02-17T15:36:46.572Z INFO str0m::ice_::agent: Created peer reflexive remote candidate from STUN request: Candidate(prflx=107.197.104.68:49376/udp prio=1862270719) cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.572Z DEBUG str0m::ice_::agent: Created new pair for STUN request: CandidatePair(1-0 prio=162128486503284223 state=Waiting attempts=0 unanswered=0 remote=0 last=None nom=None) cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.574Z INFO str0m::ice_::agent: Created peer reflexive remote candidate from STUN request: Candidate(prflx=[2600:1700:3ecb:2410:7499:175a:5c9:9bc5]:57622/udp prio=1862270975) cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.574Z DEBUG str0m::ice_::agent: Created new pair for STUN request: CandidatePair(2-1 prio=162129586014912511 state=Waiting attempts=0 unanswered=0 remote=0 last=None nom=None) cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.611Z DEBUG str0m::ice_::pair: Nominated pair: CandidatePair(2-1 prio=162129586014912511 state=Succeeded attempts=1 unanswered=0 remote=2 last=Some(Instant { tv_sec: 286264, tv_nsec: 840170135 }) nom=Nominated) cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.612Z INFO str0m::ice_::agent: State change (got nomination, still trying others): Checking -> Connected cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.612Z DEBUG snownet::node: Flushing packets buffered during ICE num_buffered=1 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.612Z INFO snownet::node: Updating remote socket old=None new=Relay { relay: b7198983-0cf6-48ba-a459-e7d27ef7d6c9, dest: [2600:1700:3ecb:2410:7499:175a:5c9:9bc5]:57622 } duration_since_intent=137.48517ms cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 // The connection has been established and we receive the (forced) handshake initiation by the client. However, we also flushed a handshake initiation. 2025-02-17T15:36:46.612Z DEBUG boringtun::noise: Received handshake_initiation remote_idx=731337473 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.613Z DEBUG boringtun::noise: Sending handshake_response local_idx=185230594 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.613Z DEBUG boringtun::noise: Sending handshake_initiation cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.629Z DEBUG snownet::node: Unknown connection or socket has already been nominated ignored_candidate=candidate:fffeff021b36b51d6f7abdc3 1 udp 50331391 34.94.63.38 55487 typ relay cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.629Z DEBUG snownet::node: Unknown connection or socket has already been nominated ignored_candidate=candidate:fffeff64a52b02479dab9c4 1 udp 1694498559 107.197.104.68 49376 typ srflx cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.629Z DEBUG snownet::node: Unknown connection or socket has already been nominated ignored_candidate=candidate:fffeff7ec9b7a7db40ec1c44 1 udp 2130706175 192.168.1.150 49376 typ host cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.630Z DEBUG snownet::node: Unknown connection or socket has already been nominated ignored_candidate=candidate:ffffff026d81f5c8a4d5600e 1 udp 50331647 2600:1900:4120:521c:0:78:: 55487 typ relay cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.630Z DEBUG snownet::node: Unknown connection or socket has already been nominated ignored_candidate=candidate:ffffff64e2c91c4ff6f343f5 1 udp 1694498815 2600:1700:3ecb:2410:7499:175a:5c9:9bc5 57622 typ srflx cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.630Z DEBUG snownet::node: Unknown connection or socket has already been nominated ignored_candidate=candidate:ffffff7ed64262b110d1f279 1 udp 2130706431 2600:1700:3ecb:2410:7499:175a:5c9:9bc5 57622 typ host cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 // We are receiving a response for our handshake initiation. Let the fight begin! 2025-02-17T15:36:46.651Z DEBUG boringtun::noise: Received handshake_response local_idx=185230593 remote_idx=731337474 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.651Z DEBUG firezone_gateway::eventloop: Tunnel error: Failed to decapsulate: Failed to decapsulate: UnexpectedPacket 2025-02-17T15:36:46.651Z DEBUG boringtun::noise: Received handshake_initiation remote_idx=731337475 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.652Z DEBUG boringtun::noise: Sending handshake_response local_idx=185230596 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.652Z DEBUG boringtun::noise: Sending handshake_initiation cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.652Z DEBUG boringtun::noise: Received handshake_response local_idx=185230595 remote_idx=731337476 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.652Z DEBUG firezone_gateway::eventloop: Tunnel error: Failed to decapsulate: Failed to decapsulate: UnexpectedPacket 2025-02-17T15:36:46.652Z DEBUG boringtun::noise: Received handshake_initiation remote_idx=731337477 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.653Z DEBUG boringtun::noise: Sending handshake_response local_idx=185230598 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.653Z DEBUG boringtun::noise: Sending handshake_initiation cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.691Z DEBUG boringtun::noise: Received handshake_response local_idx=185230597 remote_idx=731337478 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.691Z DEBUG firezone_gateway::eventloop: Tunnel error: Failed to decapsulate: Failed to decapsulate: UnexpectedPacket 2025-02-17T15:36:46.691Z DEBUG boringtun::noise: Received handshake_initiation remote_idx=731337479 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.692Z DEBUG boringtun::noise: Sending handshake_response local_idx=185230600 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 2025-02-17T15:36:46.692Z INFO snownet::node: Completed wireguard handshake cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 duration_since_intent=217.247362ms 2025-02-17T15:36:46.692Z DEBUG firezone_gateway::eventloop: Tunnel error: Failed to decapsulate: Failed to decapsulate: NoCurrentSession 2025-02-17T15:36:46.692Z DEBUG firezone_gateway::eventloop: Tunnel error: Failed to decapsulate: Failed to decapsulate: NoCurrentSession 2025-02-17T15:36:46.692Z DEBUG firezone_gateway::eventloop: Tunnel error: Failed to decapsulate: Failed to decapsulate: NoCurrentSession 2025-02-17T15:36:46.692Z DEBUG firezone_gateway::eventloop: Tunnel error: Failed to decapsulate: Failed to decapsulate: NoCurrentSession 2025-02-17T15:36:46.708Z DEBUG firezone_gateway::eventloop: Tunnel error: Failed to decapsulate: Failed to decapsulate: NoCurrentSession 2025-02-17T15:36:46.731Z DEBUG boringtun::noise: New session session=185230600 cid=8b106344-ba59-4050-8f9a-e2f0bab6e9e5 ``` As you can see, with both parties initiating handshakes, they end up fighting over who should initiate the session. --- rust/connlib/snownet/src/node.rs | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/rust/connlib/snownet/src/node.rs b/rust/connlib/snownet/src/node.rs index e1761a5c4..22af6fc34 100644 --- a/rust/connlib/snownet/src/node.rs +++ b/rust/connlib/snownet/src/node.rs @@ -54,6 +54,10 @@ pub struct Client {} trait Mode { fn new() -> Self; fn is_client(&self) -> bool; + + fn is_server(&self) -> bool { + !self.is_client() + } } impl Mode for Server { @@ -446,6 +450,12 @@ where .get_established_mut(&connection) .ok_or(Error::NotConnected)?; + if self.mode.is_server() && !conn.state.has_nominated_socket() { + tracing::debug!(?packet, "ICE is still in progress; dropping packet because server should not initiate WireGuard sessions"); + + return Ok(None); + } + let mut buffer = self.buffer_pool.pull_owned(); // Encode the packet with an offset of 4 bytes, in case we need to wrap it in a channel-data message. @@ -1723,6 +1733,10 @@ where }; apply_default_stun_timings(agent); } + + fn has_nominated_socket(&self) -> bool { + matches!(self, Self::Connected { .. } | Self::Idle { .. }) + } } fn idle_at(last_incoming: Instant, last_outgoing: Instant) -> Instant {