github-personal/firezone
1
0
Fork 0
mirror of https://github.com/outbackdingo/firezone.git synced 2026-01-27 10:18:54 +00:00
Code Issues Packages Projects Releases Wiki Activity

refactor(rust): consistently record errors as tracing::Value (#7104)

Browse Source 
Our logging library, `tracing` supports structured logging. This is
useful because it preserves the more than just the string representation
of a value and thus allows the active logging backend(s) to capture more
information for a particular value.

In the case of errors, this is especially useful because it allows us to
capture the sources of a particular error.

Unfortunately, recording an error as a tracing value is a bit cumbersome
because `tracing::Value` is only implemented for `&dyn
std::error::Error`. Casting an error to this is quite verbose. To make
it easier, we introduce two utility functions in `firezone-logging`:

- `std_dyn_err`
- `anyhow_dyn_err`

Tracking errors as correct `tracing::Value`s will be especially helpful
once we enable Sentry's `tracing` integration:
https://docs.rs/sentry-tracing/latest/sentry_tracing/#tracking-errors
This commit is contained in:
Thomas Eizinger
2024-10-22 15:46:26 +11:00
committed by GitHub
parent 21ab270ebc
commit 73eebd2c4d
32 changed files with 170 additions and 71 deletions
Download Patch File Download Diff File Expand all files Collapse all files

3
rust/Cargo.lock generated
View File

@@ -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",

2
rust/bin-shared/Cargo.toml
View File

@@ -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"] }

5
rust/bin-shared/src/tun_device_manager/linux.rs
View File

@@ -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)]

5
rust/bin-shared/src/tun_device_manager/windows.rs
View File

@@ -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 {

5
rust/bin-shared/src/windows.rs
View File

@@ -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;
};

1
rust/connlib/clients/shared/Cargo.toml
View File

@@ -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 }

10
rust/connlib/clients/shared/src/eventloop.rs
View File

@@ -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"
);
}
};
}

3
rust/connlib/clients/shared/src/lib.rs
View File

@@ -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<CB>(
telemetry::capture_error(&e);
}
tracing::error!("connlib failed: {e}");
tracing::error!(error = std_dyn_err(&e), "connlib failed");
callbacks.on_disconnect(&e);
}
Err(e) => {

4
rust/connlib/snownet/Cargo.toml
View File

@@ -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

15
rust/connlib/snownet/src/allocation.rs
View File

@@ -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<Candidate> {
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");

5
rust/connlib/snownet/src/node.rs
View File

@@ -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;
}
};

26
rust/connlib/tunnel/src/client.rs
View File

@@ -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()))

7
rust/connlib/tunnel/src/dns.rs
View File

@@ -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;
}
};

14
rust/connlib/tunnel/src/gateway.rs
View File

@@ -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<Transmit<'a>> {
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))

8
rust/connlib/tunnel/src/io.rs
View File

@@ -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;
}
};

5
rust/connlib/tunnel/src/sockets.rs
View File

@@ -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<UdpSocket>) {
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() {

3
rust/connlib/tunnel/src/tests/sut.rs
View File

@@ -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");
}
}
}

2
rust/dns-over-tcp/Cargo.toml
View File

@@ -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"] }

3
rust/dns-over-tcp/src/server.rs
View File

@@ -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;
}

27
rust/gateway/src/eventloop.rs
View File

@@ -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<Vec<IpAddr>, 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<DomainName>) -> Vec<IpAddr> {
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![]
}

7
rust/gateway/src/main.rs
View File

@@ -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");
};
}
}

4
rust/headless-client/src/main.rs
View File

@@ -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()?;

9
rust/logging/src/dyn_err.rs Normal file
View File

@@ -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()
}

2
rust/logging/src/lib.rs
View File

@@ -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;

14
rust/logging/src/log_unwrap.rs
View File

@@ -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}")
}
}
}

2
rust/phoenix-channel/Cargo.toml
View File

@@ -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]

32
rust/phoenix-channel/src/lib.rs
View File

@@ -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;
}
};

1
rust/relay/Cargo.toml
View File

@@ -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"

9
rust/relay/src/main.rs
View File

@@ -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.

3
rust/relay/src/server.rs
View File

@@ -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::<Uuid>()
.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)
})?;

1
rust/socket-factory/Cargo.toml
View File

@@ -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"] }

4
rust/socket-factory/src/lib.rs
View File

@@ -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.
}