chore(connlib): tune INFO logs (#10677)

The INFO logs of Firezone (specifically `connlib`) should be a good balance between useful and not noisy. Several of the INFO logs we currently have a probably a bit too noisy and can be tuned down or optimised to be easier to read. Before: ``` 2025-10-22T01:48:38.836Z INFO firezone_headless_client: arch="x86_64" version="1.5.5" 2025-10-22T01:48:38.840Z INFO socket_factory: Set UDP socket buffer sizes requested_send_buffer_size=16777216 send_buffer_size=425984 requested_recv_buffer_size=134217728 recv_buffer_size=425984 port=52625 2025-10-22T01:48:38.841Z INFO socket_factory: Set UDP socket buffer sizes requested_send_buffer_size=16777216 send_buffer_size=425984 requested_recv_buffer_size=134217728 recv_buffer_size=425984 port=52625 2025-10-22T01:48:38.851Z INFO firezone_tunnel::device_channel: Initializing TUN device name=tun-firezone 2025-10-22T01:48:38.852Z INFO firezone_tunnel::client: Resetting network state (network changed) 2025-10-22T01:48:38.853Z INFO socket_factory: Set UDP socket buffer sizes requested_send_buffer_size=16777216 send_buffer_size=425984 requested_recv_buffer_size=134217728 recv_buffer_size=425984 port=52625 2025-10-22T01:48:38.854Z INFO socket_factory: Set UDP socket buffer sizes requested_send_buffer_size=16777216 send_buffer_size=425984 requested_recv_buffer_size=134217728 recv_buffer_size=425984 port=52625 2025-10-22T01:48:39.263Z INFO phoenix_channel: Connected to portal host=api 2025-10-22T01:48:39.408Z INFO firezone_tunnel::client: Updating TUN device config=TunConfig { ip: IpConfig { v4: 100.90.205.158, v6: fd00:2021:1111::2:76b2 }, dns_by_sentinel: {}, search_domain: Some(Name(httpbin.search.test.)), ipv4_routes: [100.64.0.0/11, 100.96.0.0/11, 100.100.111.0/24], ipv6_routes: [fd00:2021:1111::/107, fd00:2021:1111:8000::/107, fd00:2021:1111:8000:100:100:111:0/120] } 2025-10-22T01:48:39.408Z INFO firezone_tunnel::client: Updating TUN device config=TunConfig { ip: IpConfig { v4: 100.90.205.158, v6: fd00:2021:1111::2:76b2 }, dns_by_sentinel: {100.100.111.1 <> 127.0.0.11:53}, search_domain: Some(Name(httpbin.search.test.)), ipv4_routes: [100.64.0.0/11, 100.96.0.0/11, 100.100.111.0/24], ipv6_routes: [fd00:2021:1111::/107, fd00:2021:1111:8000::/107, fd00:2021:1111:8000:100:100:111:0/120] } 2025-10-22T01:48:39.408Z INFO firezone_tunnel::client: Activating resource name=foobar.com address=foobar.com sites=mycro-aws-gws 2025-10-22T01:48:39.409Z INFO firezone_tunnel::client: Activating resource name=*.firezone.dev address=*.firezone.dev sites=mycro-aws-gws 2025-10-22T01:48:39.409Z INFO firezone_tunnel::client: Activating resource name=ip6only address=ip6only.me sites=mycro-aws-gws 2025-10-22T01:48:39.409Z INFO firezone_tunnel::client: Activating resource name=example.com address=example.com sites=mycro-aws-gws 2025-10-22T01:48:39.409Z INFO firezone_tunnel::client: Activating resource name=Example address=*.example.com sites=mycro-aws-gws 2025-10-22T01:48:39.409Z INFO firezone_tunnel::client: Activating resource name=**.httpbin address=**.httpbin sites=mycro-aws-gws 2025-10-22T01:48:39.409Z INFO firezone_tunnel::client: Activating resource name=MyCorp Network (IPv6) address=172:20::/64 sites=mycro-aws-gws 2025-10-22T01:48:39.409Z INFO firezone_tunnel::client: Updating TUN device config=TunConfig { ip: IpConfig { v4: 100.90.205.158, v6: fd00:2021:1111::2:76b2 }, dns_by_sentinel: {100.100.111.1 <> 127.0.0.11:53}, search_domain: Some(Name(httpbin.search.test.)), ipv4_routes: [100.64.0.0/11, 100.96.0.0/11, 100.100.111.0/24], ipv6_routes: [172:20::/64, fd00:2021:1111::/107, fd00:2021:1111:8000::/107, fd00:2021:1111:8000:100:100:111:0/120] } 2025-10-22T01:48:39.409Z INFO firezone_tunnel::client: Activating resource name=**.httpbin.search.test address=**.httpbin.search.test sites=mycro-aws-gws 2025-10-22T01:48:39.409Z INFO firezone_tunnel::client: Activating resource name=**.firez.one address=**.firez.one sites=mycro-aws-gws 2025-10-22T01:48:39.409Z INFO firezone_tunnel::client: Activating resource name=MyCorp Network address=172.20.0.0/16 sites=mycro-aws-gws 2025-10-22T01:48:39.409Z INFO firezone_tunnel::client: Updating TUN device config=TunConfig { ip: IpConfig { v4: 100.90.205.158, v6: fd00:2021:1111::2:76b2 }, dns_by_sentinel: {100.100.111.1 <> 127.0.0.11:53}, search_domain: Some(Name(httpbin.search.test.)), ipv4_routes: [100.64.0.0/11, 100.96.0.0/11, 100.100.111.0/24, 172.20.0.0/16], ipv6_routes: [172:20::/64, fd00:2021:1111::/107, fd00:2021:1111:8000::/107, fd00:2021:1111:8000:100:100:111:0/120] } 2025-10-22T01:48:39.418Z INFO firezone_bin_shared::tun_device_manager::linux: Setting new routes new_routes={V4(Ipv4Network { network_address: 100.64.0.0, netmask: 11 }), V4(Ipv4Network { network_address: 172.20.0.0, netmask: 16 }), V6(Ipv6Network { network_address: 172:20::, netmask: 64 }), V4(Ipv4Network { network_address: 100.96.0.0, netmask: 11 }), V6(Ipv6Network { network_address: fd00:2021:1111::, netmask: 107 }), V6(Ipv6Network { network_address: fd00:2021:1111:8000::, netmask: 107 }), V6(Ipv6Network { network_address: fd00:2021:1111:8000:100:100:111:0, netmask: 120 }), V4(Ipv4Network { network_address: 100.100.111.0, netmask: 24 })} 2025-10-22T01:48:39.420Z INFO firezone_headless_client: Tunnel ready elapsed=583.523468ms 2025-10-22T01:48:39.430Z INFO snownet::node: Added new TURN server rid=2a413094-32d4-4a69-8e92-642d60e885e9 address=Dual { v4: 203.0.113.102:3478, v6: [203:0:113::102]:3478 } 2025-10-22T01:49:44.814Z INFO snownet::node: Creating new connection local=IceCreds { ufrag: "bly5", pass: "bdjtlfpvfdhhya6om4kssi" } remote=IceCreds { ufrag: "24gy", pass: "5mqlci4n4nmoovovihswvq" } index=(2378720|0) cid=ea82a87c-ca11-4292-a332-940ac386cba1 2025-10-22T01:49:45.634Z INFO snownet::node: Updating remote socket new=PeerToPeer { source: 172.30.0.100:52625, dest: 203.0.113.3:52625 } duration_since_intent=821.149802ms cid=ea82a87c-ca11-4292-a332-940ac386cba1 2025-10-22T01:49:45.783Z INFO snownet::node: Updating remote socket old=PeerToPeer { source: 172.30.0.100:52625, dest: 203.0.113.3:52625 } new=PeerToPeer { source: [172:30::100]:52625, dest: [203:0:113::3]:52625 } duration_since_intent=971.112388ms cid=ea82a87c-ca11-4292-a332-940ac386cba1 ``` After: ``` 2025-10-22T01:58:09.972Z INFO firezone_headless_client: arch="x86_64" version="1.5.5" 2025-10-22T01:58:09.980Z INFO firezone_tunnel::client: Resetting network state (network changed) 2025-10-22T01:58:10.271Z INFO phoenix_channel: Connected to portal host=api 2025-10-22T01:58:10.369Z INFO firezone_tunnel::client: Activating resource name=foobar.com address=foobar.com sites=mycro-aws-gws 2025-10-22T01:58:10.369Z INFO firezone_tunnel::client: Activating resource name=*.firezone.dev address=*.firezone.dev sites=mycro-aws-gws 2025-10-22T01:58:10.369Z INFO firezone_tunnel::client: Activating resource name=ip6only address=ip6only.me sites=mycro-aws-gws 2025-10-22T01:58:10.369Z INFO firezone_tunnel::client: Activating resource name=example.com address=example.com sites=mycro-aws-gws 2025-10-22T01:58:10.369Z INFO firezone_tunnel::client: Activating resource name=Example address=*.example.com sites=mycro-aws-gws 2025-10-22T01:58:10.369Z INFO firezone_tunnel::client: Activating resource name=**.httpbin address=**.httpbin sites=mycro-aws-gws 2025-10-22T01:58:10.370Z INFO firezone_tunnel::client: Activating resource name=MyCorp Network (IPv6) address=172:20::/64 sites=mycro-aws-gws 2025-10-22T01:58:10.370Z INFO firezone_tunnel::client: Activating resource name=**.httpbin.search.test address=**.httpbin.search.test sites=mycro-aws-gws 2025-10-22T01:58:10.370Z INFO firezone_tunnel::client: Activating resource name=**.firez.one address=**.firez.one sites=mycro-aws-gws 2025-10-22T01:58:10.370Z INFO firezone_tunnel::client: Activating resource name=MyCorp Network address=172.20.0.0/16 sites=mycro-aws-gws 2025-10-22T01:58:10.370Z INFO snownet::node: Added new TURN server rid=2a413094-32d4-4a69-8e92-642d60e885e9 address=Dual { v4: 203.0.113.102:3478, v6: [203:0:113::102]:3478 } 2025-10-22T01:58:10.370Z INFO snownet::node: Added new TURN server rid=54f6ba35-1914-48fc-be24-62f6293936eb address=Dual { v4: 203.0.113.101:3478, v6: [203:0:113::101]:3478 } 2025-10-22T01:58:10.370Z INFO firezone_tunnel::client: Updating TUN device config=TunConfig { ip: IpConfig { v4: 100.90.205.158, v6: fd00:2021:1111::2:76b2 }, dns_by_sentinel: {100.100.111.1 <> 127.0.0.11:53}, search_domain: Some(Name(httpbin.search.test.)), ipv4_routes: [100.64.0.0/11, 100.96.0.0/11, 100.100.111.0/24, 172.20.0.0/16], ipv6_routes: [172:20::/64, fd00:2021:1111::/107, fd00:2021:1111:8000::/107, fd00:2021:1111:8000:100:100:111:0/120] } 2025-10-22T01:58:10.383Z INFO firezone_bin_shared::tun_device_manager::linux: Setting new routes new_routes=[100.64.0.0/11, 100.96.0.0/11, 100.100.111.0/24, 172.20.0.0/16, 172:20::/64, fd00:2021:1111::/107, fd00:2021:1111:8000::/107, fd00:2021:1111:8000:100:100:111:0/120] 2025-10-22T01:58:10.495Z INFO snownet::allocation: Invalidating allocation active_socket=Some(203.0.113.101:3478) 2025-10-22T01:58:10.495Z INFO snownet::allocation: Invalidating allocation active_socket=Some(203.0.113.102:3478) 2025-10-22T02:03:04.410Z INFO snownet::node: Creating new connection local=IceCreds { ufrag: "uxgc", pass: "xxdgp5ivfhqloedzdmgi3j" } remote=IceCreds { ufrag: "es6w", pass: "doa2s3hmiteid7dtlszsbq" } index=(583098|0) cid=ea82a87c-ca11-4292-a332-940ac386cba1 2025-10-22T02:03:04.960Z INFO snownet::node: Updating remote socket new=PeerToPeer { source: 172.30.0.100:52625, dest: 203.0.113.3:52625 } duration_since_intent=550.756408ms cid=ea82a87c-ca11-4292-a332-940ac386cba1 2025-10-22T02:03:05.112Z INFO snownet::node: Updating remote socket old=PeerToPeer { source: 172.30.0.100:52625, dest: 203.0.113.3:52625 } new=PeerToPeer { source: [172:30::100]:52625, dest: [203:0:113::3]:52625 } duration_since_intent=702.23775ms cid=ea82a87c-ca11-4292-a332-940ac386cba1 ```
2026-01-27 10:18:54 +00:00 · 2025-10-23 10:47:55 +11:00
parent 8d69320985
commit 21a848a4cb
12 changed files with 46 additions and 43 deletions
--- a/rust/bin-shared/src/tun_device_manager/linux.rs
+++ b/rust/bin-shared/src/tun_device_manager/linux.rs
@@ -2,7 +2,7 @@

 use crate::FIREZONE_MARK;
 use anyhow::{Context as _, Result};
-use firezone_logging::err_with_src;
+use firezone_logging::{DisplayBTreeSet, err_with_src};
 use firezone_telemetry::otel;
 use futures::{
    SinkExt, StreamExt, TryStreamExt,
@@ -22,9 +22,9 @@ use netlink_packet_route::rule::RuleAction;
 use rtnetlink::sys::AsyncSocket;
 use rtnetlink::{Error::NetlinkError, Handle, RuleAddRequest, new_connection};
 use rtnetlink::{LinkUnspec, RouteMessageBuilder};
-use std::path::Path;
 use std::sync::Arc;
 use std::task::{Context, Poll};
+use std::{collections::BTreeSet, path::Path};
 use std::{
    collections::HashMap,
    os::fd::{FromRawFd as _, OwnedFd},
@@ -55,7 +55,7 @@ const FIREZONE_TABLE: u32 = 0x2021_fd00;
 pub struct TunDeviceManager {
    mtu: u32,
    connection: Connection,
-    routes: HashSet<IpNetwork>,
+    routes: BTreeSet<IpNetwork>,
 }

 struct Connection {
@@ -190,13 +190,13 @@ impl TunDeviceManager {
        ipv4: impl IntoIterator<Item = Ipv4Network>,
        ipv6: impl IntoIterator<Item = Ipv6Network>,
    ) -> Result<()> {
-        let new_routes: HashSet<IpNetwork> = ipv4
+        let new_routes = ipv4
            .into_iter()
            .map(IpNetwork::from)
            .chain(ipv6.into_iter().map(IpNetwork::from))
-            .collect();
+            .collect::<BTreeSet<_>>();

-        tracing::info!(?new_routes, "Setting new routes");
+        tracing::info!(new_routes = %DisplayBTreeSet(&new_routes), "Setting new routes");

        let handle = &self.connection.handle;
        let index = tun_device_index(handle).await?;
--- a/rust/connlib/l4-tcp-dns-server/lib.rs
+++ b/rust/connlib/l4-tcp-dns-server/lib.rs
@@ -48,7 +48,7 @@ impl Server {

        self.waker.wake();

-        tracing::info!(%socket, "Listening for TCP DNS queries");
+        tracing::debug!(%socket, "Listening for TCP DNS queries");

        Ok(())
    }
@@ -62,7 +62,7 @@ impl Server {

        self.waker.wake();

-        tracing::info!(%socket, "Listening for TCP DNS queries");
+        tracing::debug!(%socket, "Listening for TCP DNS queries");

        Ok(())
    }
--- a/rust/connlib/l4-udp-dns-server/lib.rs
+++ b/rust/connlib/l4-udp-dns-server/lib.rs
@@ -46,7 +46,7 @@ impl Server {

        self.waker.wake();

-        tracing::info!(%socket, "Listening for UDP DNS queries");
+        tracing::debug!(%socket, "Listening for UDP DNS queries");

        Ok(())
    }
@@ -63,7 +63,7 @@ impl Server {

        self.waker.wake();

-        tracing::info!(%socket, "Listening for UDP DNS queries");
+        tracing::debug!(%socket, "Listening for UDP DNS queries");

        Ok(())
    }
--- a/rust/connlib/socket-factory/src/lib.rs
+++ b/rust/connlib/socket-factory/src/lib.rs
@@ -208,7 +208,7 @@ impl UdpSocket {
        let send_buffer_size = socket.send_buffer_size()?;
        let recv_buffer_size = socket.recv_buffer_size()?;

-        tracing::info!(%requested_send_buffer_size, %send_buffer_size, %requested_recv_buffer_size, %recv_buffer_size, port = %self.port, "Set UDP socket buffer sizes");
+        tracing::debug!(%requested_send_buffer_size, %send_buffer_size, %requested_recv_buffer_size, %recv_buffer_size, port = %self.port, "Set UDP socket buffer sizes");

        Ok(())
    }
--- a/rust/connlib/tunnel/src/client.rs
+++ b/rust/connlib/tunnel/src/client.rs
@@ -1558,8 +1558,6 @@ impl ClientState {
            return;
        }

-        tracing::info!(config = ?new_tun_config, "Updating TUN device");
-
        self.stub_resolver
            .set_search_domain(new_tun_config.search_domain.clone());

@@ -1649,9 +1647,11 @@ impl ClientState {

    pub(crate) fn poll_event(&mut self) -> Option<ClientEvent> {
        if let Some(pending_tun_update) = self.pending_tun_update.take()
-            && let Some(event) = pending_tun_update.into_event()
+            && let Some(new_config) = pending_tun_update.into_new_config()
        {
-            return Some(event);
+            tracing::info!(config = ?new_config, "Updating TUN device");
+
+            return Some(ClientEvent::TunInterfaceUpdated(new_config));
        }

        self.buffered_events
--- a/rust/connlib/tunnel/src/client/pending_tun_update.rs
+++ b/rust/connlib/tunnel/src/client/pending_tun_update.rs
@@ -1,4 +1,4 @@
-use crate::{ClientEvent, TunConfig};
+use crate::TunConfig;

 /// Acts as a "buffer" for updates to the TUN interface that need to be applied.
 ///
@@ -20,13 +20,13 @@ impl PendingTunUpdate {
        self.want = want;
    }

-    pub fn into_event(self) -> Option<ClientEvent> {
+    pub fn into_new_config(self) -> Option<TunConfig> {
        if let Some(current) = self.current
            && current == self.want
        {
            return None;
        };

-        Some(ClientEvent::TunInterfaceUpdated(self.want))
+        Some(self.want)
    }
 }
--- a/rust/connlib/tunnel/src/device_channel.rs
+++ b/rust/connlib/tunnel/src/device_channel.rs
@@ -17,7 +17,7 @@ impl Device {
    }

    pub(crate) fn set_tun(&mut self, tun: Box<dyn Tun>) {
-        tracing::info!(name = %tun.name(), "Initializing TUN device");
+        tracing::debug!(name = %tun.name(), "Initializing TUN device");

        self.tun = Some(tun);

--- a/rust/connlib/tunnel/src/lib.rs
+++ b/rust/connlib/tunnel/src/lib.rs
@@ -10,6 +10,7 @@ use bimap::BiMap;
 use chrono::Utc;
 use connlib_model::{ClientId, GatewayId, IceCandidate, PublicKey, ResourceId, ResourceView};
 use dns_types::DomainName;
+use firezone_logging::DisplayBTreeSet;
 use futures::{FutureExt, future::BoxFuture};
 use gat_lending_iterator::LendingIterator;
 use io::{Buffers, Io};
@@ -17,7 +18,7 @@ use ip_network::{Ipv4Network, Ipv6Network};
 use socket_factory::{SocketFactory, TcpSocket, UdpSocket};
 use std::{
    collections::BTreeSet,
-    fmt, future, mem,
+    future, mem,
    net::{IpAddr, Ipv4Addr, Ipv6Addr, SocketAddr, SocketAddrV4, SocketAddrV6},
    sync::Arc,
    task::{Context, Poll, ready},
@@ -552,9 +553,9 @@ pub struct TunConfig {
    pub dns_by_sentinel: BiMap<IpAddr, SocketAddr>,
    pub search_domain: Option<DomainName>,

-    #[debug("{}", DisplaySet(ipv4_routes))]
+    #[debug("{}", DisplayBTreeSet(ipv4_routes))]
    pub ipv4_routes: BTreeSet<Ipv4Network>,
-    #[debug("{}", DisplaySet(ipv6_routes))]
+    #[debug("{}", DisplayBTreeSet(ipv6_routes))]
    pub ipv6_routes: BTreeSet<Ipv6Network>,
 }

@@ -643,25 +644,6 @@ pub(crate) struct NotClientIp(IpAddr);
 #[error("Traffic to/from this resource IP is not allowed: {0}")]
 pub(crate) struct NotAllowedResource(IpAddr);

-/// Adapter-struct to [`fmt::Display`] a [`BTreeSet`].
-#[expect(dead_code, reason = "It is used in the `Debug` impl of `TunConfig`")]
-struct DisplaySet<'a, T>(&'a BTreeSet<T>);
-
-impl<T> fmt::Display for DisplaySet<'_, T>
-where
-    T: fmt::Display,
-{
-    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
-        let mut list = f.debug_list();
-
-        for entry in self.0 {
-            list.entry(&format_args!("{entry}"));
-        }
-
-        list.finish()
-    }
-}
-
 pub fn is_peer(dst: IpAddr) -> bool {
    match dst {
        IpAddr::V4(v4) => IPV4_TUNNEL.contains(v4),
--- a/rust/gui-client/src-tauri/src/service.rs
+++ b/rust/gui-client/src-tauri/src/service.rs
@@ -206,7 +206,7 @@ impl Session {
                connlib,
                started_at,
            } => {
-                tracing::info!(elapsed = ?started_at.elapsed(), "Tunnel ready");
+                tracing::debug!(elapsed = ?started_at.elapsed(), "Tunnel ready");

                *self = Self::Connected {
                    event_stream,
--- a/rust/headless-client/src/main.rs
+++ b/rust/headless-client/src/main.rs
@@ -416,7 +416,7 @@ fn try_main() -> Result<()> {
                    // <https://github.com/firezone/firezone/pull/6026#discussion_r1692297438>
                    if let Some(instant) = last_connlib_start_instant.take() {
                        // `OnUpdateResources` appears to be the latest callback that happens during startup
-                        tracing::info!(elapsed = ?instant.elapsed(), "Tunnel ready");
+                        tracing::debug!(elapsed = ?instant.elapsed(), "Tunnel ready");
                        platform::notify_service_controller()?;
                    }
                    if cli.exit {
--- a/rust/logging/src/display_btree_set.rs
+++ b/rust/logging/src/display_btree_set.rs
@@ -0,0 +1,19 @@
+use std::{collections::BTreeSet, fmt};
+
+/// Adapter-struct to [`fmt::Display`] a [`BTreeSet`].
+pub struct DisplayBTreeSet<'a, T>(pub &'a BTreeSet<T>);
+
+impl<T> fmt::Display for DisplayBTreeSet<'_, T>
+where
+    T: fmt::Display,
+{
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        let mut list = f.debug_list();
+
+        for entry in self.0 {
+            list.entry(&format_args!("{entry}"));
+        }
+
+        list.finish()
+    }
+}
--- a/rust/logging/src/lib.rs
+++ b/rust/logging/src/lib.rs
@@ -6,6 +6,7 @@ mod format;
 mod unwrap_or;
 mod ansi;
 mod capturing_writer;
+mod display_btree_set;
 mod err_with_sources;
 mod event_message_contains_filter;

@@ -29,6 +30,7 @@ use tracing_subscriber::{

 pub use ansi::stdout_supports_ansi;
 pub use capturing_writer::CapturingWriter;
+pub use display_btree_set::DisplayBTreeSet;
 pub use err_with_sources::{ErrorWithSources, err_with_src};
 pub use format::Format;