mirror of
https://github.com/outbackdingo/firezone.git
synced 2026-01-27 18:18:55 +00:00
2e43523f75
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 development guide
Firezone uses Rust for all data plane components. This directory contains the Linux and Windows clients, and low-level networking implementations related to STUN/TURN.
We target the last stable release of Rust using rust-toolchain.toml.
If you are using rustup, that is automatically handled for you.
Otherwise, ensure you have the latest stable version of Rust installed.
Reading Client logs
The Client logs are written as JSONL for machine-readability.
To make them more human-friendly, pipe them through jq like this:
cd path/to/logs # e.g. `$HOME/.cache/dev.firezone.client/data/logs` on Linux
cat *.log | jq -r '"\(.time) \(.severity) \(.message)"'
Resulting in, e.g.
2024-04-01T18:25:47.237661392Z INFO started log
2024-04-01T18:25:47.238193266Z INFO GIT_VERSION = 1.0.0-pre.11-35-gcc0d43531
2024-04-01T18:25:48.295243016Z INFO No token / actor_name on disk, starting in signed-out state
2024-04-01T18:25:48.295360641Z INFO null
Benchmarking on Linux
The recommended way for benchmarking any of the Rust components is Linux' perf utility.
For example, to attach to a running application, do:
- Ensure the binary you are profiling is compiled with the
releaseprofile. sudo perf record -g --freq 10000 --pid $(pgrep <your-binary>).- Run the speed test or whatever load-inducing task you want to measure.
sudo perf script > profile.perf- Open profiler.firefox.com and load
profile.perf
Instead of attaching to a process with --pid, you can also specify the path to executable directly.
That is useful if you want to capture perf data for a test or a micro-benchmark.