diff --git a/rust/Cargo.lock b/rust/Cargo.lock index 628b77edc..b93018bba 100644 --- a/rust/Cargo.lock +++ b/rust/Cargo.lock @@ -1053,6 +1053,7 @@ dependencies = [ "bimap", "chrono", "connlib-model", + "firezone-logging", "firezone-telemetry", "firezone-tunnel", "ip_network", @@ -2040,6 +2041,7 @@ dependencies = [ "difference", "env_logger", "firezone-bin-shared", + "firezone-logging", "futures", "hex", "hex-display", @@ -5699,6 +5701,7 @@ dependencies = [ name = "socket-factory" version = "0.1.0" dependencies = [ + "firezone-logging", "quinn-udp", "socket2", "tokio", diff --git a/rust/bin-shared/Cargo.toml b/rust/bin-shared/Cargo.toml index f0475242a..176643a2e 100644 --- a/rust/bin-shared/Cargo.toml +++ b/rust/bin-shared/Cargo.toml @@ -9,6 +9,7 @@ description = "Firezone-specific modules shared between binaries." anyhow = "1.0.82" axum = { version = "0.7.7", default-features = false, features = ["http1", "tokio"] } clap = { version = "4.5.19", features = ["derive", "env"] } +firezone-logging = { workspace = true } futures = "0.3" git-version = "0.3.9" ip_network = { version = "0.4", default-features = false, features = ["serde"] } @@ -19,7 +20,6 @@ tracing = { workspace = true } tun = { workspace = true } [dev-dependencies] -firezone-logging = { workspace = true } hex-literal = "0.4.1" tokio = { workspace = true, features = ["macros", "rt-multi-thread"] } diff --git a/rust/bin-shared/src/tun_device_manager/linux.rs b/rust/bin-shared/src/tun_device_manager/linux.rs index 2f6ea011e..9ba32d0c9 100644 --- a/rust/bin-shared/src/tun_device_manager/linux.rs +++ b/rust/bin-shared/src/tun_device_manager/linux.rs @@ -2,6 +2,7 @@ use crate::FIREZONE_MARK; use anyhow::{anyhow, Context as _, Result}; +use firezone_logging::std_dyn_err; use futures::TryStreamExt; use ip_network::{IpNetwork, Ipv4Network, Ipv6Network}; use libc::{ @@ -257,7 +258,7 @@ async fn add_route(route: &IpNetwork, idx: u32, handle: &Handle) { return; } - tracing::warn!(%route, "Failed to add route: {err}"); + tracing::warn!(error = std_dyn_err(&err), %route, "Failed to add route"); } async fn remove_route(route: &IpNetwork, idx: u32, handle: &Handle) { @@ -279,7 +280,7 @@ async fn remove_route(route: &IpNetwork, idx: u32, handle: &Handle) { return; } - tracing::warn!(%route, "Failed to remove route: {err}"); + tracing::warn!(error = std_dyn_err(&err), %route, "Failed to remove route"); } #[derive(Debug)] diff --git a/rust/bin-shared/src/tun_device_manager/windows.rs b/rust/bin-shared/src/tun_device_manager/windows.rs index a82871131..25734ec5c 100644 --- a/rust/bin-shared/src/tun_device_manager/windows.rs +++ b/rust/bin-shared/src/tun_device_manager/windows.rs @@ -1,6 +1,7 @@ use crate::windows::{CREATE_NO_WINDOW, TUNNEL_UUID}; use crate::TUNNEL_NAME; use anyhow::{Context as _, Result}; +use firezone_logging::std_dyn_err; use ip_network::{IpNetwork, Ipv4Network, Ipv6Network}; use ring::digest; use std::{ @@ -139,7 +140,7 @@ fn add_route(route: IpNetwork, iface_idx: u32) { return; } - tracing::warn!(%route, "Failed to add route: {e}"); + tracing::warn!(error = std_dyn_err(&e), %route, "Failed to add route"); } // It's okay if this blocks until the route is removed in the OS. @@ -159,7 +160,7 @@ fn remove_route(route: IpNetwork, iface_idx: u32) { return; } - tracing::warn!(%route, "Failed to remove route: {e}") + tracing::warn!(error = std_dyn_err(&e), %route, "Failed to remove route") } fn forward_entry(route: IpNetwork, iface_idx: u32) -> MIB_IPFORWARD_ROW2 { diff --git a/rust/bin-shared/src/windows.rs b/rust/bin-shared/src/windows.rs index 02959d746..b0a965c60 100644 --- a/rust/bin-shared/src/windows.rs +++ b/rust/bin-shared/src/windows.rs @@ -1,5 +1,6 @@ use crate::TUNNEL_NAME; use anyhow::{Context as _, Result}; +use firezone_logging::std_dyn_err; use known_folders::{get_known_folder_path, KnownFolder}; use socket_factory::{TcpSocket, UdpSocket}; use std::{ @@ -137,7 +138,7 @@ fn delete_all_routing_entries_matching(addr: IpAddr) -> io::Result<()> { // Safety: The `entry` is initialised. if let Err(e) = unsafe { DeleteIpForwardEntry2(entry) }.ok() { - tracing::warn!("Failed to remove routing entry: {e}"); + tracing::warn!(error = std_dyn_err(&e), "Failed to remove routing entry"); continue; }; @@ -200,7 +201,7 @@ impl Drop for RoutingTableEntry { // Safety: The entry we stored is valid. if let Err(e) = unsafe { DeleteIpForwardEntry2(&self.entry) }.ok() { - tracing::warn!("Failed to delete routing entry: {e}"); + tracing::warn!(error = std_dyn_err(&e), "Failed to delete routing entry"); return; }; diff --git a/rust/connlib/clients/shared/Cargo.toml b/rust/connlib/clients/shared/Cargo.toml index b870dd632..8ef866883 100644 --- a/rust/connlib/clients/shared/Cargo.toml +++ b/rust/connlib/clients/shared/Cargo.toml @@ -11,6 +11,7 @@ anyhow = "1.0.82" backoff = { workspace = true } bimap = "0.6" connlib-model = { workspace = true } +firezone-logging = { workspace = true } firezone-telemetry = { workspace = true } firezone-tunnel = { workspace = true } ip_network = { version = "0.4", default-features = false } diff --git a/rust/connlib/clients/shared/src/eventloop.rs b/rust/connlib/clients/shared/src/eventloop.rs index 22a405a32..c550c5a92 100644 --- a/rust/connlib/clients/shared/src/eventloop.rs +++ b/rust/connlib/clients/shared/src/eventloop.rs @@ -1,6 +1,7 @@ use crate::{callbacks::Callbacks, PHOENIX_TOPIC}; use anyhow::Result; use connlib_model::ResourceId; +use firezone_logging::{anyhow_dyn_err, std_dyn_err}; use firezone_tunnel::messages::{client::*, *}; use firezone_tunnel::ClientTunnel; use phoenix_channel::{ErrorReply, OutboundRequestId, PhoenixChannel, PublicKeyParam}; @@ -91,7 +92,7 @@ where continue; } Poll::Ready(Err(e)) => { - tracing::warn!("Tunnel error: {e}"); + tracing::warn!(error = std_dyn_err(&e), "Tunnel error"); continue; } Poll::Pending => {} @@ -300,7 +301,7 @@ where gateway_public_key.0.into(), Instant::now(), ) { - tracing::warn!("Failed to accept connection: {e}"); + tracing::warn!(error = anyhow_dyn_err(&e), "Failed to accept connection"); } } ReplyMessages::Connect(Connect { @@ -332,7 +333,10 @@ where ) { Ok(()) => {} Err(e) => { - tracing::warn!("Failed to request new connection: {e}"); + tracing::warn!( + error = anyhow_dyn_err(&e), + "Failed to request new connection" + ); } }; } diff --git a/rust/connlib/clients/shared/src/lib.rs b/rust/connlib/clients/shared/src/lib.rs index 202b7c178..b8117066a 100644 --- a/rust/connlib/clients/shared/src/lib.rs +++ b/rust/connlib/clients/shared/src/lib.rs @@ -3,6 +3,7 @@ pub use crate::serde_routelist::{V4RouteList, V6RouteList}; pub use callbacks::{Callbacks, DisconnectError}; pub use connlib_model::StaticSecret; pub use eventloop::Eventloop; +use firezone_logging::std_dyn_err; pub use firezone_tunnel::messages::client::{ ResourceDescription, {IngressMessages, ReplyMessages}, }; @@ -159,7 +160,7 @@ async fn connect_supervisor( telemetry::capture_error(&e); } - tracing::error!("connlib failed: {e}"); + tracing::error!(error = std_dyn_err(&e), "connlib failed"); callbacks.on_disconnect(&e); } Err(e) => { diff --git a/rust/connlib/snownet/Cargo.toml b/rust/connlib/snownet/Cargo.toml index 733167b8b..f779ed1ae 100644 --- a/rust/connlib/snownet/Cargo.toml +++ b/rust/connlib/snownet/Cargo.toml @@ -8,6 +8,7 @@ backoff = "0.4.0" boringtun = { workspace = true } bytecodec = "0.4.15" bytes = "1.7.1" +firezone-logging = { workspace = true } hex = "0.4.0" hex-display = "0.3.0" ip-packet = { workspace = true } @@ -21,8 +22,5 @@ stun_codec = "0.3.4" thiserror = "1" tracing = { workspace = true } -[dev-dependencies] -firezone-logging = { workspace = true } - [lints] workspace = true diff --git a/rust/connlib/snownet/src/allocation.rs b/rust/connlib/snownet/src/allocation.rs index f489b2176..61ab58119 100644 --- a/rust/connlib/snownet/src/allocation.rs +++ b/rust/connlib/snownet/src/allocation.rs @@ -7,6 +7,7 @@ use crate::{ }; use ::backoff::backoff::Backoff; use bytecodec::{DecodeExt as _, EncodeExt as _}; +use firezone_logging::std_dyn_err; use hex_display::HexDisplayExt as _; use rand::random; use std::{ @@ -1131,7 +1132,10 @@ fn srflx_candidate(local: SocketAddr, attr: &Attribute) -> Option { let new_candidate = match Candidate::server_reflexive(a.address(), local, Protocol::Udp) { Ok(c) => c, Err(e) => { - tracing::debug!("Observed address is not a valid candidate: {e}"); + tracing::debug!( + error = std_dyn_err(&e), + "Observed address is not a valid candidate" + ); return None; } }; @@ -1155,7 +1159,10 @@ fn relay_candidate( let new_candidate = match Candidate::relayed(addr, Protocol::Udp) { Ok(c) => c, Err(e) => { - tracing::debug!("Acquired allocation is not a valid candidate: {e}"); + tracing::debug!( + error = std_dyn_err(&e), + "Acquired allocation is not a valid candidate" + ); return None; } }; @@ -1218,7 +1225,9 @@ impl ChannelBindings { fn try_decode<'p>(&mut self, packet: &'p [u8], now: Instant) -> Option<(SocketAddr, &'p [u8])> { let (channel_number, payload) = crate::channel_data::decode(packet) - .inspect_err(|e| tracing::debug!("Malformed channel data message: {e}")) + .inspect_err(|e| { + tracing::debug!(error = std_dyn_err(e), "Malformed channel data message") + }) .ok()?; let Some(channel) = self.inner.get_mut(&channel_number) else { tracing::debug!(%channel_number, "Unknown channel"); diff --git a/rust/connlib/snownet/src/node.rs b/rust/connlib/snownet/src/node.rs index 77fbe893d..374d4e3cd 100644 --- a/rust/connlib/snownet/src/node.rs +++ b/rust/connlib/snownet/src/node.rs @@ -8,6 +8,7 @@ use boringtun::noise::{Tunn, TunnResult}; use boringtun::x25519::PublicKey; use boringtun::{noise::rate_limiter::RateLimiter, x25519::StaticSecret}; use core::fmt; +use firezone_logging::std_dyn_err; use hex_display::HexDisplayExt; use ip_packet::{ ConvertibleIpv4Packet, ConvertibleIpv6Packet, IpPacket, IpPacketBuf, MAX_DATAGRAM_PAYLOAD, @@ -328,7 +329,7 @@ where let candidate = match Candidate::from_sdp_string(&candidate) { Ok(c) => c, Err(e) => { - tracing::debug!("Failed to parse candidate: {e}"); + tracing::debug!(error = std_dyn_err(&e), "Failed to parse candidate"); return; } }; @@ -369,7 +370,7 @@ where let candidate = match Candidate::from_sdp_string(&candidate) { Ok(c) => c, Err(e) => { - tracing::debug!("Failed to parse candidate: {e}"); + tracing::debug!(error = std_dyn_err(&e), "Failed to parse candidate"); return; } }; diff --git a/rust/connlib/tunnel/src/client.rs b/rust/connlib/tunnel/src/client.rs index da0a2bb15..e0d1479c6 100644 --- a/rust/connlib/tunnel/src/client.rs +++ b/rust/connlib/tunnel/src/client.rs @@ -14,7 +14,7 @@ use bimap::BiMap; use connlib_model::PublicKey; use connlib_model::{GatewayId, RelayId, ResourceId, ResourceStatus, ResourceView}; use connlib_model::{Site, SiteId}; -use firezone_logging::LogUnwrap as _; +use firezone_logging::{anyhow_dyn_err, std_dyn_err, LogUnwrap as _}; use ip_network::{IpNetwork, Ipv4Network, Ipv6Network}; use ip_network_table::IpNetworkTable; use ip_packet::{IpPacket, UdpSlice}; @@ -325,7 +325,7 @@ impl ClientState { packet.as_ref(), now, ) - .inspect_err(|e| tracing::debug!(%local, num_bytes = %packet.len(), "Failed to decapsulate incoming packet: {e}")) + .inspect_err(|e| tracing::debug!(error = std_dyn_err(e), %local, num_bytes = %packet.len(), "Failed to decapsulate incoming packet")) .ok()??; if self.tcp_dns_client.accepts(&packet) { @@ -379,7 +379,7 @@ impl ClientState { } }) .unwrap_or_else(|e| { - tracing::debug!("Recursive UDP DNS query failed: {e}"); + tracing::debug!(error = std_dyn_err(&e), "Recursive UDP DNS query failed"); dns::servfail(response.query.for_slice_ref()) }); @@ -393,7 +393,7 @@ impl ClientState { tracing::trace!("Received recursive TCP DNS response"); }) .unwrap_or_else(|e| { - tracing::debug!("Recursive TCP DNS query failed: {e}"); + tracing::debug!(error = std_dyn_err(&e), "Recursive TCP DNS query failed"); dns::servfail(response.query.for_slice_ref()) }); @@ -444,7 +444,7 @@ impl ClientState { let transmit = self .node .encapsulate(gid, packet, now, buffer) - .inspect_err(|e| tracing::debug!(%gid, "Failed to encapsulate: {e}")) + .inspect_err(|e| tracing::debug!(error = std_dyn_err(e), %gid, "Failed to encapsulate")) .ok()??; Some(transmit) @@ -719,7 +719,10 @@ impl ClientState { .collect(); if let Err(e) = self.tcp_dns_client.set_resolvers(upstream_resolvers) { - tracing::warn!("Failed to connect to upstream DNS resolvers over TCP: {e:#}"); + tracing::warn!( + error = anyhow_dyn_err(&e), + "Failed to connect to upstream DNS resolvers over TCP" + ); } } @@ -950,7 +953,11 @@ impl ClientState { let (datagram, message) = match parse_udp_dns_message(&packet) { Ok((datagram, message)) => (datagram, message), Err(e) => { - tracing::trace!(?packet, "Failed to parse DNS query: {e:#}"); + tracing::trace!( + error = anyhow_dyn_err(&e), + ?packet, + "Failed to parse DNS query" + ); return ControlFlow::Break(()); } }; @@ -1014,7 +1021,10 @@ impl ClientState { match self.tcp_dns_client.send_query(server, message.clone()) { Ok(()) => {} Err(e) => { - tracing::debug!("Failed to send recursive TCP DNS query {e:#}"); + tracing::debug!( + error = anyhow_dyn_err(&e), + "Failed to send recursive TCP DNS quer" + ); self.tcp_dns_server .send_message(query.socket, dns::servfail(message.for_slice_ref())) diff --git a/rust/connlib/tunnel/src/dns.rs b/rust/connlib/tunnel/src/dns.rs index dbd753591..68fab3926 100644 --- a/rust/connlib/tunnel/src/dns.rs +++ b/rust/connlib/tunnel/src/dns.rs @@ -10,6 +10,7 @@ use domain::{ }, dep::octseq::OctetsInto, }; +use firezone_logging::{anyhow_dyn_err, std_dyn_err}; use itertools::Itertools; use pattern::{Candidate, Pattern}; use std::io; @@ -178,7 +179,7 @@ impl StubResolver { let parsed_pattern = match Pattern::new(&pattern) { Ok(p) => p, Err(e) => { - tracing::warn!(%pattern, "Domain pattern is not valid: {e}"); + tracing::warn!(error = std_dyn_err(&e), %pattern, "Domain pattern is not valid"); return false; } }; @@ -273,7 +274,7 @@ impl StubResolver { match self.try_handle(message) { Ok(s) => s, Err(e) => { - tracing::trace!("Failed to handle DNS query: {e:#}"); + tracing::trace!(error = anyhow_dyn_err(&e), "Failed to handle DNS query"); ResolveStrategy::LocalResponse(servfail(message)) } @@ -390,7 +391,7 @@ pub fn is_subdomain(name: &DomainName, resource: &str) -> bool { let pattern = match Pattern::new(resource) { Ok(p) => p, Err(e) => { - tracing::warn!(%resource, "Unable to parse pattern: {e}"); + tracing::warn!(error = std_dyn_err(&e), %resource, "Unable to parse pattern"); return false; } }; diff --git a/rust/connlib/tunnel/src/gateway.rs b/rust/connlib/tunnel/src/gateway.rs index 9a48f648b..780a57858 100644 --- a/rust/connlib/tunnel/src/gateway.rs +++ b/rust/connlib/tunnel/src/gateway.rs @@ -8,6 +8,7 @@ use anyhow::Context; use boringtun::x25519::PublicKey; use chrono::{DateTime, Utc}; use connlib_model::{ClientId, DomainName, RelayId, ResourceId}; +use firezone_logging::{anyhow_dyn_err, std_dyn_err}; use ip_network::{Ipv4Network, Ipv6Network}; use ip_packet::{FzP2pControlSlice, IpPacket}; use secrecy::{ExposeSecret as _, Secret}; @@ -106,7 +107,7 @@ impl GatewayState { let transmit = self .node .encapsulate(cid, packet, now, buffer) - .inspect_err(|e| tracing::debug!(%cid, "Failed to encapsulate: {e}")) + .inspect_err(|e| tracing::debug!(error = std_dyn_err(e), %cid, "Failed to encapsulate")) .ok()??; Some(transmit) @@ -131,7 +132,7 @@ impl GatewayState { packet, now, ) - .inspect_err(|e| tracing::debug!(%from, num_bytes = %packet.len(), "Failed to decapsulate incoming packet: {e}")) + .inspect_err(|e| tracing::debug!(error = std_dyn_err(e), %from, num_bytes = %packet.len(), "Failed to decapsulate incoming packet")) .ok()??; let Some(peer) = self.peers.get_mut(&cid) else { @@ -257,7 +258,7 @@ impl GatewayState { }; if let Err(e) = peer.refresh_translation(name.clone(), resource_id, resolved_ips, now) { - tracing::warn!(rid = %resource_id, %name, "Failed to refresh DNS resource IP translations: {e:#}"); + tracing::warn!(error = anyhow_dyn_err(&e), rid = %resource_id, %name, "Failed to refresh DNS resource IP translations"); }; } @@ -316,7 +317,10 @@ impl GatewayState { ) .map(|()| dns_resource_nat::NatStatus::Active) .unwrap_or_else(|e| { - tracing::debug!("Failed to setup DNS resource NAT: {e:#}"); + tracing::debug!( + error = anyhow_dyn_err(&e), + "Failed to setup DNS resource NAT" + ); dns_resource_nat::NatStatus::Inactive }); @@ -490,7 +494,7 @@ fn encrypt_packet<'a>( ) -> Option> { let encrypted_packet = node .encapsulate(cid, packet, now, buffer) - .inspect_err(|e| tracing::debug!(%cid, "Failed to encapsulate: {e}")) + .inspect_err(|e| tracing::debug!(error = std_dyn_err(e), %cid, "Failed to encapsulate")) .ok()??; Some(encrypted_packet.to_transmit(buffer)) diff --git a/rust/connlib/tunnel/src/io.rs b/rust/connlib/tunnel/src/io.rs index 4fcef0ff2..f9489c6bb 100644 --- a/rust/connlib/tunnel/src/io.rs +++ b/rust/connlib/tunnel/src/io.rs @@ -1,5 +1,6 @@ use crate::{device_channel::Device, dns, sockets::Sockets}; use domain::base::Message; +use firezone_logging::std_dyn_err; use futures::{ future::{self, Either}, stream, Stream, StreamExt, @@ -348,7 +349,7 @@ async fn tun_send_recv( { Either::Left((Some(Command::SendPacket(p)), _)) => { if let Err(e) = device.write(p) { - tracing::debug!("Failed to write TUN packet: {e}"); + tracing::debug!(error = std_dyn_err(&e), "Failed to write TUN packet"); }; } Either::Left((Some(Command::UpdateTun(tun)), _)) => { @@ -365,7 +366,10 @@ async fn tun_send_recv( }; } Either::Right((Err(e), _)) => { - tracing::debug!("Failed to read packet from TUN device: {e}"); + tracing::debug!( + error = std_dyn_err(&e), + "Failed to read packet from TUN device" + ); return; } }; diff --git a/rust/connlib/tunnel/src/sockets.rs b/rust/connlib/tunnel/src/sockets.rs index ba311fec1..8560df002 100644 --- a/rust/connlib/tunnel/src/sockets.rs +++ b/rust/connlib/tunnel/src/sockets.rs @@ -1,3 +1,4 @@ +use firezone_logging::std_dyn_err; use socket_factory::{DatagramIn, DatagramOut, SocketFactory, UdpSocket}; use std::{ io, @@ -19,10 +20,10 @@ pub(crate) struct Sockets { impl Sockets { pub fn rebind(&mut self, socket_factory: &dyn SocketFactory) { self.socket_v4 = socket_factory(&SocketAddr::V4(UNSPECIFIED_V4_SOCKET)) - .inspect_err(|e| tracing::warn!("Failed to bind IPv4 socket: {e}")) + .inspect_err(|e| tracing::warn!(error = std_dyn_err(e), "Failed to bind IPv4 socket")) .ok(); self.socket_v6 = socket_factory(&SocketAddr::V6(UNSPECIFIED_V6_SOCKET)) - .inspect_err(|e| tracing::warn!("Failed to bind IPv6 socket: {e}")) + .inspect_err(|e| tracing::warn!(error = std_dyn_err(e), "Failed to bind IPv6 socket")) .ok(); if let Some(waker) = self.waker.take() { diff --git a/rust/connlib/tunnel/src/tests/sut.rs b/rust/connlib/tunnel/src/tests/sut.rs index b2051a643..006c7a4df 100644 --- a/rust/connlib/tunnel/src/tests/sut.rs +++ b/rust/connlib/tunnel/src/tests/sut.rs @@ -18,6 +18,7 @@ use connlib_model::{ClientId, DomainName, GatewayId, RelayId}; use domain::base::iana::{Class, Rcode}; use domain::base::{Message, MessageBuilder, Record, Rtype, ToName as _, Ttl}; use domain::rdata::AllRecordData; +use firezone_logging::anyhow_dyn_err; use secrecy::ExposeSecret as _; use snownet::Transmit; use std::collections::BTreeSet; @@ -533,7 +534,7 @@ impl TunnelTest { c.handle_dns_response(message.for_slice()) } Err(e) => { - tracing::error!("TCP DNS query failed: {e:#}"); + tracing::error!(error = anyhow_dyn_err(&e), "TCP DNS query failed"); } } } diff --git a/rust/dns-over-tcp/Cargo.toml b/rust/dns-over-tcp/Cargo.toml index 6052dea2e..c21c7f434 100644 --- a/rust/dns-over-tcp/Cargo.toml +++ b/rust/dns-over-tcp/Cargo.toml @@ -7,6 +7,7 @@ description = "User-space implementation of DNS over TCP." [dependencies] anyhow = "1.0" domain = { workspace = true } +firezone-logging = { workspace = true } ip-packet = { workspace = true } itertools = "0.13" rand = "0.8" @@ -15,7 +16,6 @@ tracing = { workspace = true } [dev-dependencies] firezone-bin-shared = { workspace = true } -firezone-logging = { workspace = true } futures = "0.3" ip_network = { version = "0.4", default-features = false } tokio = { workspace = true, features = ["process", "rt", "macros"] } diff --git a/rust/dns-over-tcp/src/server.rs b/rust/dns-over-tcp/src/server.rs index df94c9582..0dadd9c3e 100644 --- a/rust/dns-over-tcp/src/server.rs +++ b/rust/dns-over-tcp/src/server.rs @@ -10,6 +10,7 @@ use crate::{ }; use anyhow::{Context as _, Result}; use domain::{base::Message, dep::octseq::OctetsInto as _}; +use firezone_logging::anyhow_dyn_err; use ip_packet::IpPacket; use smoltcp::{ iface::{Interface, PollResult, SocketSet}, @@ -187,7 +188,7 @@ impl Server { }); } Err(e) => { - tracing::debug!("Error on receiving DNS query: {e}"); + tracing::debug!(error = anyhow_dyn_err(&e), "Error on receiving DNS query"); socket.abort(); break; } diff --git a/rust/gateway/src/eventloop.rs b/rust/gateway/src/eventloop.rs index fee544999..3852567bd 100644 --- a/rust/gateway/src/eventloop.rs +++ b/rust/gateway/src/eventloop.rs @@ -4,6 +4,7 @@ use connlib_model::DomainName; use connlib_model::{ClientId, ResourceId}; #[cfg(not(target_os = "windows"))] use dns_lookup::{AddrInfoHints, AddrInfoIter, LookupError}; +use firezone_logging::{anyhow_dyn_err, std_dyn_err}; use firezone_tunnel::messages::gateway::{ AllowAccess, ClientIceCandidates, ClientsIceCandidates, ConnectionReady, EgressMessages, IngressMessages, RejectAccess, RequestConnection, @@ -76,7 +77,7 @@ impl Eventloop { continue; } Poll::Ready(Err(e)) => { - tracing::warn!("Tunnel error: {e}"); + tracing::warn!(error = std_dyn_err(&e), "Tunnel error"); continue; } Poll::Pending => {} @@ -99,7 +100,8 @@ impl Eventloop { let addresses = result .inspect_err(|e| { tracing::debug!( - "DNS resolution timed out as part of setup NAT request: {e}" + error = std_dyn_err(e), + "DNS resolution timed out as part of setup NAT request" ) }) .unwrap_or_default(); @@ -109,7 +111,10 @@ impl Eventloop { addresses, Instant::now(), ) { - tracing::warn!("Failed to set DNS resource NAT: {e:#}"); + tracing::warn!( + error = anyhow_dyn_err(&e), + "Failed to set DNS resource NAT" + ); }; continue; @@ -310,7 +315,7 @@ impl Eventloop { // For the gateway, it doesn't do anything else so in an ideal world, we would cause the side-effect out here and just pass an opaque `Device` to the `Tunnel`. // That requires more refactoring of other platforms, so for now, we need to rely on the `Tunnel` interface and cause the side-effect separately via the `TunDeviceManager`. if let Err(e) = self.tun_device_channel.try_send(init.interface) { - tracing::warn!("Failed to set interface: {e}"); + tracing::warn!(error = std_dyn_err(&e), "Failed to set interface"); } } phoenix_channel::Event::InboundMessage { @@ -339,7 +344,7 @@ impl Eventloop { req: RequestConnection, ) { let addresses = result - .inspect_err(|e| tracing::debug!(client = %req.client.id, reference = %req.reference, "DNS resolution timed out as part of connection request: {e}")) + .inspect_err(|e| tracing::debug!(error = std_dyn_err(e), client = %req.client.id, reference = %req.reference, "DNS resolution timed out as part of connection request")) .unwrap_or_default(); let answer = self.tunnel.state_mut().accept( @@ -367,7 +372,7 @@ impl Eventloop { let client = req.client.id; self.tunnel.state_mut().cleanup_connection(&client); - tracing::debug!(%client, "Connection request failed: {e:#}"); + tracing::debug!(error = anyhow_dyn_err(&e), %client, "Connection request failed"); return; } @@ -384,7 +389,7 @@ impl Eventloop { pub fn allow_access(&mut self, result: Result, Timeout>, req: AllowAccess) { let addresses = result - .inspect_err(|e| tracing::debug!(client = %req.client_id, reference = %req.reference, "DNS resolution timed out as part of allow access request: {e}")) + .inspect_err(|e| tracing::debug!(error = std_dyn_err(e), client = %req.client_id, reference = %req.reference, "DNS resolution timed out as part of allow access request")) .unwrap_or_default(); if let Err(e) = self.tunnel.state_mut().allow_access( @@ -396,7 +401,7 @@ impl Eventloop { req.payload.map(|r| DnsResourceNatEntry::new(r, addresses)), Instant::now(), ) { - tracing::warn!(client = %req.client_id, "Allow access request failed: {e:#}"); + tracing::warn!(error = anyhow_dyn_err(&e), client = %req.client_id, "Allow access request failed"); }; } @@ -408,7 +413,7 @@ impl Eventloop { name: DomainName, ) { let addresses = result - .inspect_err(|e| tracing::debug!(%conn_id, "DNS resolution timed out as part of allow access request: {e}")) + .inspect_err(|e| tracing::debug!(error = std_dyn_err(e), %conn_id, "DNS resolution timed out as part of allow access request")) .unwrap_or_default(); self.tunnel.state_mut().refresh_translation( @@ -431,12 +436,12 @@ async fn resolve(domain: Option) -> Vec { match tokio::task::spawn_blocking(move || resolve_addresses(&dname)).await { Ok(Ok(addresses)) => addresses, Ok(Err(e)) => { - tracing::warn!("Failed to resolve '{domain}': {e}"); + tracing::warn!(error = std_dyn_err(&e), "Failed to resolve '{domain}'"); vec![] } Err(e) => { - tracing::warn!("Failed to resolve '{domain}': {e}"); + tracing::warn!(error = std_dyn_err(&e), "Failed to resolve '{domain}'"); vec![] } diff --git a/rust/gateway/src/main.rs b/rust/gateway/src/main.rs index 1a135f90d..667cd38be 100644 --- a/rust/gateway/src/main.rs +++ b/rust/gateway/src/main.rs @@ -7,6 +7,7 @@ use firezone_bin_shared::{ linux::{tcp_socket_factory, udp_socket_factory}, TunDeviceManager, }; +use firezone_logging::anyhow_dyn_err; use firezone_tunnel::messages::Interface; use firezone_tunnel::{GatewayTunnel, IPV4_PEERS, IPV6_PEERS}; use phoenix_channel::get_user_agent; @@ -42,7 +43,7 @@ async fn main() { // By default, `anyhow` prints a stacktrace when it exits. // That looks like a "crash" but we "just" exit with a fatal error. if let Err(e) = try_main().await { - tracing::error!("{e:#}"); + tracing::error!(error = anyhow_dyn_err(&e)); std::process::exit(1); } } @@ -143,14 +144,14 @@ async fn update_device_task( .set_ips(next_interface.ipv4, next_interface.ipv6) .await { - tracing::warn!("Failed to set interface: {e:#}"); + tracing::warn!(error = anyhow_dyn_err(&e), "Failed to set interface"); } if let Err(e) = tun_device .set_routes(vec![IPV4_PEERS], vec![IPV6_PEERS]) .await { - tracing::warn!("Failed to set routes: {e:#}"); + tracing::warn!(error = anyhow_dyn_err(&e), "Failed; to set routes"); }; } } diff --git a/rust/headless-client/src/main.rs b/rust/headless-client/src/main.rs index 259fb9e60..ed103aaad 100644 --- a/rust/headless-client/src/main.rs +++ b/rust/headless-client/src/main.rs @@ -12,6 +12,7 @@ use firezone_bin_shared::{ use firezone_headless_client::{ device_id, signals, CallbackHandler, CliCommon, ConnlibMsg, DnsController, }; +use firezone_logging::LogUnwrap; use firezone_telemetry::Telemetry; use futures::{FutureExt as _, StreamExt as _}; use phoenix_channel::get_user_agent; @@ -157,6 +158,9 @@ fn main() -> Result<()> { git_version = firezone_bin_shared::git_version!("headless-client-*") ); + anyhow::Result::<()>::Err(anyhow::Error::msg("foo").context("bar").context("baz")) + .log_unwrap_debug("Something failed"); + let rt = tokio::runtime::Builder::new_current_thread() .enable_all() .build()?; diff --git a/rust/logging/src/dyn_err.rs b/rust/logging/src/dyn_err.rs new file mode 100644 index 000000000..9c2406d45 --- /dev/null +++ b/rust/logging/src/dyn_err.rs @@ -0,0 +1,9 @@ +use std::error::Error; + +pub fn std_dyn_err(e: &(impl Error + 'static)) -> &(dyn Error + 'static) { + e as &(dyn Error + 'static) +} + +pub fn anyhow_dyn_err(e: &anyhow::Error) -> &(dyn Error + 'static) { + e.as_ref() +} diff --git a/rust/logging/src/lib.rs b/rust/logging/src/lib.rs index 80b2420ca..5ed1327bd 100644 --- a/rust/logging/src/lib.rs +++ b/rust/logging/src/lib.rs @@ -1,3 +1,4 @@ +mod dyn_err; pub mod file; mod format; mod log_unwrap; @@ -9,6 +10,7 @@ use tracing_subscriber::{ Registry, }; +pub use dyn_err::{anyhow_dyn_err, std_dyn_err}; pub use format::Format; pub use log_unwrap::LogUnwrap; diff --git a/rust/logging/src/log_unwrap.rs b/rust/logging/src/log_unwrap.rs index 50652eda3..c2bd9efef 100644 --- a/rust/logging/src/log_unwrap.rs +++ b/rust/logging/src/log_unwrap.rs @@ -1,23 +1,33 @@ +use std::error::Error; + pub trait LogUnwrap { + #[track_caller] fn log_unwrap_debug(&self, msg: &str); + #[track_caller] fn log_unwrap_trace(&self, msg: &str); } impl LogUnwrap for anyhow::Result<()> { + #[track_caller] fn log_unwrap_debug(&self, msg: &str) { match self { Ok(()) => {} Err(e) => { - tracing::debug!("{msg}: {e:#}") + let error: &dyn Error = e.as_ref(); + + tracing::debug!(error, "{msg}") } } } + #[track_caller] fn log_unwrap_trace(&self, msg: &str) { match self { Ok(()) => {} Err(e) => { - tracing::trace!("{msg}: {e:#}") + let error: &dyn Error = e.as_ref(); + + tracing::trace!(error, "{msg}") } } } diff --git a/rust/phoenix-channel/Cargo.toml b/rust/phoenix-channel/Cargo.toml index 6bf601b04..7823f7bd9 100644 --- a/rust/phoenix-channel/Cargo.toml +++ b/rust/phoenix-channel/Cargo.toml @@ -7,6 +7,7 @@ edition = "2021" [dependencies] backoff = "0.4.0" base64 = "0.22.1" +firezone-logging = { workspace = true } futures = "0.3.29" hex = "0.4" libc = "0.2" @@ -28,7 +29,6 @@ uuid = { version = "1.10", default-features = false, features = ["std", "v4"] } hostname = "0.4.0" [dev-dependencies] -firezone-logging = { workspace = true } tokio = { workspace = true, features = ["macros", "rt", "tracing"] } [lints] diff --git a/rust/phoenix-channel/src/lib.rs b/rust/phoenix-channel/src/lib.rs index 1a328c233..89f72a8fc 100644 --- a/rust/phoenix-channel/src/lib.rs +++ b/rust/phoenix-channel/src/lib.rs @@ -12,6 +12,7 @@ use std::{io, mem}; use backoff::backoff::Backoff; use backoff::ExponentialBackoff; use base64::Engine; +use firezone_logging::std_dyn_err; use futures::future::BoxFuture; use futures::{FutureExt, SinkExt, StreamExt}; use heartbeat::{Heartbeat, MissedLastHeartbeat}; @@ -155,6 +156,7 @@ impl Error { } } +#[derive(Debug)] enum InternalError { WebSocket(tokio_tungstenite::tungstenite::Error), Serde(serde_json::Error), @@ -178,13 +180,28 @@ impl fmt::Display for InternalError { write!(f, "http error: {status} - {body}") } - InternalError::WebSocket(e) => write!(f, "websocket connection failed: {e}"), - InternalError::Serde(e) => write!(f, "failed to deserialize message: {e}"), + InternalError::WebSocket(_) => write!(f, "websocket connection failed"), + InternalError::Serde(_) => write!(f, "failed to deserialize message"), InternalError::MissedHeartbeat => write!(f, "portal did not respond to our heartbeat"), InternalError::CloseMessage => write!(f, "portal closed the websocket connection"), InternalError::StreamClosed => write!(f, "websocket stream was closed"), InternalError::InvalidUrl => write!(f, "failed to resolve url"), - InternalError::SocketConnection(e) => write!(f, "failed to connect socket: {e}"), + InternalError::SocketConnection(_) => write!(f, "failed to connect socket"), + } + } +} + +impl std::error::Error for InternalError { + fn source(&self) -> Option<&(dyn std::error::Error + 'static)> { + match self { + InternalError::WebSocket(tokio_tungstenite::tungstenite::Error::Http(_)) => None, + InternalError::WebSocket(e) => Some(e), + InternalError::Serde(e) => Some(e), + InternalError::SocketConnection(e) => Some(e), + InternalError::MissedHeartbeat => None, + InternalError::CloseMessage => None, + InternalError::StreamClosed => None, + InternalError::InvalidUrl => None, } } } @@ -351,7 +368,7 @@ where return Poll::Ready(Ok(Event::Closed)); } Poll::Ready(Err(e)) => { - tracing::warn!("Error while closing websocket: {e}"); + tracing::warn!(error = std_dyn_err(&e), "Error while closing websocket"); return Poll::Ready(Ok(Event::Closed)); } @@ -390,7 +407,7 @@ where let user_agent = self.user_agent.clone(); let socket_factory = self.socket_factory.clone(); - tracing::debug!(?backoff, max_elapsed_time = ?self.reconnect_backoff.max_elapsed_time, "Reconnecting to portal on transient client error: {e}"); + tracing::debug!(error = std_dyn_err(&e), ?backoff, max_elapsed_time = ?self.reconnect_backoff.max_elapsed_time, "Reconnecting to portal on transient client error"); self.state = State::Connecting(Box::pin(async move { tokio::time::sleep(backoff).await; @@ -464,7 +481,10 @@ where continue; } Err(e) => { - tracing::warn!("Failed to deserialize message: {e}"); + tracing::warn!( + error = std_dyn_err(&e), + "Failed to deserialize message" + ); continue; } }; diff --git a/rust/relay/Cargo.toml b/rust/relay/Cargo.toml index f906e8ee8..c0f09edd4 100644 --- a/rust/relay/Cargo.toml +++ b/rust/relay/Cargo.toml @@ -12,6 +12,7 @@ bytes = "1.7.1" clap = { version = "4.5.19", features = ["derive", "env"] } derive_more = { version = "1.0.0", features = ["from"] } firezone-bin-shared = { workspace = true } +firezone-logging = { workspace = true } futures = "0.3.29" hex = "0.4.3" hex-display = "0.3.0" diff --git a/rust/relay/src/main.rs b/rust/relay/src/main.rs index 3dd4c3f08..afa0387da 100644 --- a/rust/relay/src/main.rs +++ b/rust/relay/src/main.rs @@ -2,6 +2,7 @@ use anyhow::{anyhow, bail, Context, Result}; use backoff::ExponentialBackoffBuilder; use clap::Parser; use firezone_bin_shared::http_health_check; +use firezone_logging::std_dyn_err; use firezone_relay::sockets::Sockets; use firezone_relay::{ sockets, AddressFamily, AllocationPort, ChannelData, ClientSocket, Command, IpStack, @@ -384,7 +385,7 @@ where recipient.into_socket(), &payload, ) { - tracing::warn!(target: "relay", %recipient, "Failed to send message: {e}"); + tracing::warn!(target: "relay", error = std_dyn_err(&e), %recipient, "Failed to send message"); } } Command::CreateAllocation { port, family } => { @@ -454,7 +455,7 @@ where self.sockets .try_send(port.value(), peer.into_socket(), payload) { - tracing::warn!(target: "relay", %peer, "Failed to relay data to peer: {e}"); + tracing::warn!(target: "relay", error = std_dyn_err(&e), %peer, "Failed to relay data to peer"); } }; continue; @@ -480,13 +481,13 @@ where client.into_socket(), &self.buffer[..total_length], ) { - tracing::warn!(target: "relay", %client, "Failed to relay data to client: {e}"); + tracing::warn!(target: "relay", error = std_dyn_err(&e), %client, "Failed to relay data to client"); }; }; continue; } Poll::Ready(Err(sockets::Error::Io(e))) => { - tracing::warn!(target: "relay", "Error while receiving message: {e}"); + tracing::warn!(target: "relay", error = std_dyn_err(&e), "Error while receiving message"); continue; } Poll::Ready(Err(sockets::Error::MioTaskCrashed(e))) => return Poll::Ready(Err(e)), // Fail the event-loop. We can't operate without the `mio` worker-task. diff --git a/rust/relay/src/server.rs b/rust/relay/src/server.rs index 11becfcd0..eaeff4983 100644 --- a/rust/relay/src/server.rs +++ b/rust/relay/src/server.rs @@ -12,6 +12,7 @@ use crate::{ClientSocket, IpStack, PeerSocket}; use anyhow::Result; use bytecodec::EncodeExt; use core::fmt; +use firezone_logging::std_dyn_err; use hex_display::HexDisplayExt as _; use opentelemetry::metrics::{Counter, UpDownCounter}; use opentelemetry::KeyValue; @@ -782,7 +783,7 @@ where .value() .parse::() .map_err(|e| { - tracing::debug!(target: "relay", "failed to parse nonce: {e}"); + tracing::debug!(target: "relay", error = std_dyn_err(&e), "failed to parse nonce"); self.make_error_response(Unauthorized, request, ResponseErrorLevel::Warn) })?; diff --git a/rust/socket-factory/Cargo.toml b/rust/socket-factory/Cargo.toml index de2c7586b..e0f4c1032 100644 --- a/rust/socket-factory/Cargo.toml +++ b/rust/socket-factory/Cargo.toml @@ -4,6 +4,7 @@ version = "0.1.0" edition = "2021" [dependencies] +firezone-logging = { workspace = true } quinn-udp = "0.5.2" socket2 = { workspace = true } tokio = { version = "1.39", features = ["net"] } diff --git a/rust/socket-factory/src/lib.rs b/rust/socket-factory/src/lib.rs index f56659ad9..b543c8a72 100644 --- a/rust/socket-factory/src/lib.rs +++ b/rust/socket-factory/src/lib.rs @@ -1,3 +1,4 @@ +use firezone_logging::std_dyn_err; use std::collections::HashMap; use std::fmt; use std::{ @@ -330,8 +331,9 @@ impl UdpSocket { Ok(src_ip) => src_ip, Err(e) => { tracing::trace!( + error = std_dyn_err(&e), dst = %dst.ip(), - "No available interface for packet: {e}" + "No available interface for packet" ); return Ok(None); // Not an error because we log it above already. }