From 2013d6a2bf765e6be417616f04db387cce626b19 Mon Sep 17 00:00:00 2001 From: Thomas Eizinger Date: Fri, 12 Jul 2024 09:38:19 +1000 Subject: [PATCH] chore(connlib): improve logging (#5836) Currently, the logging of fields in spans for encapsulate and decapsulate operations is a bit inconsistent between client and gateway. Logging the `from` field for every message is actually quite redundant because most of these logs are emitted within `snownet`'s `Allocation` which can add its own span to indicate, which relay we are talking to. For most other operations, it is much more useful to log the connection ID instead of IPs. This should make the logs a bit more succinct. --- rust/connlib/shared/src/error.rs | 10 ++++---- rust/connlib/snownet/src/allocation.rs | 2 +- rust/connlib/snownet/src/node.rs | 2 -- rust/connlib/tunnel/src/client.rs | 33 ++++++++++++-------------- rust/connlib/tunnel/src/gateway.rs | 27 +++++++++++---------- rust/connlib/tunnel/src/peer.rs | 32 +++++++++++++------------ 6 files changed, 52 insertions(+), 54 deletions(-) diff --git a/rust/connlib/shared/src/error.rs b/rust/connlib/shared/src/error.rs index 6ea76d626..2632810d8 100644 --- a/rust/connlib/shared/src/error.rs +++ b/rust/connlib/shared/src/error.rs @@ -50,9 +50,6 @@ pub enum ConnlibError { /// A panic occurred with a non-string payload. #[error("Panicked with a non-string payload")] PanicNonStringPayload, - /// Invalid destination for packet - #[error("Invalid dest address")] - InvalidDst, /// Exhausted nat table #[error("exhausted nat")] ExhaustedNat, @@ -79,8 +76,11 @@ pub enum ConnlibError { #[error("Error while rewriting `/etc/resolv.conf`: {0}")] ResolvConf(anyhow::Error), - #[error("Packet not allowed; source = {src}")] - UnallowedPacket { src: IpAddr }, + #[error("Source not allowed: {src}")] + SrcNotAllowed { src: IpAddr }, + + #[error("Destination not allowed: {dst}")] + DstNotAllowed { dst: IpAddr }, // Error variants for `systemd-resolved` DNS control #[error("Failed to control system DNS with `resolvectl`")] diff --git a/rust/connlib/snownet/src/allocation.rs b/rust/connlib/snownet/src/allocation.rs index 721435c4a..e231a5ba3 100644 --- a/rust/connlib/snownet/src/allocation.rs +++ b/rust/connlib/snownet/src/allocation.rs @@ -287,7 +287,7 @@ impl Allocation { self.send_binding_requests(); } - #[tracing::instrument(level = "debug", skip_all, fields(tid, method, class, rtt))] + #[tracing::instrument(level = "debug", skip_all, fields(%from, tid, method, class, rtt))] pub fn handle_input( &mut self, from: SocketAddr, diff --git a/rust/connlib/snownet/src/node.rs b/rust/connlib/snownet/src/node.rs index 0c937fd03..4da7d4715 100644 --- a/rust/connlib/snownet/src/node.rs +++ b/rust/connlib/snownet/src/node.rs @@ -291,7 +291,6 @@ where /// - `Ok(None)` if the packet was handled internally, for example, a response from a TURN server. /// - `Ok(Some)` if the packet was an encrypted wireguard packet from a peer. /// The `Option` contains the connection on which the packet was decrypted. - #[tracing::instrument(level = "debug", skip_all, fields(%from))] pub fn decapsulate<'s>( &mut self, local: SocketAddr, @@ -330,7 +329,6 @@ where /// Wireguard is an IP tunnel, so we "enforce" that only IP packets are sent through it. /// We say "enforce" an [`IpPacket`] can be created from an (almost) arbitrary byte buffer at virtually no cost. /// Nevertheless, using [`IpPacket`] in our API has good documentation value. - #[tracing::instrument(level = "debug", skip_all, fields(id = %connection))] pub fn encapsulate<'s>( &'s mut self, connection: TId, diff --git a/rust/connlib/tunnel/src/client.rs b/rust/connlib/tunnel/src/client.rs index e96993662..e2cf48db9 100644 --- a/rust/connlib/tunnel/src/client.rs +++ b/rust/connlib/tunnel/src/client.rs @@ -408,13 +408,12 @@ impl ClientState { }) } - #[tracing::instrument(level = "trace", skip_all, fields(dst))] pub(crate) fn encapsulate<'s>( &'s mut self, packet: MutableIpPacket<'_>, now: Instant, ) -> Option> { - let (packet, dest) = match self.handle_dns(packet) { + let (packet, dst) = match self.handle_dns(packet) { Ok(response) => { self.buffered_packets.push_back(response?.to_owned()); return None; @@ -422,20 +421,18 @@ impl ClientState { Err(non_dns_packet) => non_dns_packet, }; - tracing::Span::current().record("dst", tracing::field::display(dest)); - - if is_definitely_not_a_resource(dest) { + if is_definitely_not_a_resource(dst) { return None; } - let Some(resource) = self.get_resource_by_destination(dest) else { - tracing::trace!("Unknown resource"); + let Some(resource) = self.get_resource_by_destination(dst) else { + tracing::trace!(%dst, "Unknown resource"); return None; }; let Some(peer) = peer_by_resource_mut(&self.resources_gateways, &mut self.peers, resource) else { - self.on_not_connected_resource(resource, &dest, now); + self.on_not_connected_resource(resource, &dst, now); return None; }; @@ -446,18 +443,18 @@ impl ClientState { now, ); - if peer.allowed_ips.longest_match(dest).is_none() { + if peer.allowed_ips.longest_match(dst).is_none() { let gateway_id = peer.id(); - self.send_proxy_ips(&dest, resource, gateway_id); + self.send_proxy_ips(&dst, resource, gateway_id); return None; } - let gateway_id = peer.id(); + let gid = peer.id(); let transmit = self .node - .encapsulate(gateway_id, packet.as_immutable(), now) - .inspect_err(|e| tracing::debug!("Failed to encapsulate: {e}")) + .encapsulate(gid, packet.as_immutable(), now) + .inspect_err(|e| tracing::debug!(%gid, "Failed to encapsulate: {e}")) .ok()??; Some(transmit) @@ -471,24 +468,24 @@ impl ClientState { now: Instant, buffer: &'b mut [u8], ) -> Option> { - let (conn_id, packet) = self.node.decapsulate( + let (gid, packet) = self.node.decapsulate( local, from, packet.as_ref(), now, buffer, ) - .inspect_err(|e| tracing::debug!(%local, %from, num_bytes = %packet.len(), "Failed to decapsulate incoming packet: {e}")) + .inspect_err(|e| tracing::debug!(%local, num_bytes = %packet.len(), "Failed to decapsulate incoming packet: {e}")) .ok()??; - let Some(peer) = self.peers.get_mut(&conn_id) else { - tracing::error!(%conn_id, %local, %from, "Couldn't find connection"); + let Some(peer) = self.peers.get_mut(&gid) else { + tracing::error!(%gid, "Couldn't find connection by ID"); return None; }; peer.ensure_allowed_src(&packet) - .inspect_err(|e| tracing::debug!(%conn_id, %local, %from, "{e}")) + .inspect_err(|e| tracing::debug!(%gid, %local, %from, "{e}")) .ok()?; let packet = maybe_mangle_dns_response_from_cidr_resource( diff --git a/rust/connlib/tunnel/src/gateway.rs b/rust/connlib/tunnel/src/gateway.rs index 0f380d6a9..16ed53931 100644 --- a/rust/connlib/tunnel/src/gateway.rs +++ b/rust/connlib/tunnel/src/gateway.rs @@ -163,25 +163,29 @@ impl GatewayState { packet: MutableIpPacket<'_>, now: Instant, ) -> Option> { - let dest = packet.destination(); + let dst = packet.destination(); - let peer = self.peers.peer_by_ip_mut(dest)?; + let Some(peer) = self.peers.peer_by_ip_mut(dst) else { + tracing::warn!(%dst, "Couldn't find connection by IP"); + + return None; + }; + let cid = peer.id(); let packet = peer .encapsulate(packet, now) - .inspect_err(|e| tracing::debug!("Failed to encapsulate: {e}")) + .inspect_err(|e| tracing::debug!(%cid, "Failed to encapsulate: {e}")) .ok()??; let transmit = self .node .encapsulate(peer.id(), packet.as_immutable(), now) - .inspect_err(|e| tracing::debug!("Failed to encapsulate: {e}")) + .inspect_err(|e| tracing::debug!(%cid, "Failed to encapsulate: {e}")) .ok()??; Some(transmit) } - #[tracing::instrument(level = "trace", skip_all, fields(src, dst))] pub(crate) fn decapsulate<'b>( &mut self, local: SocketAddr, @@ -190,28 +194,25 @@ impl GatewayState { now: Instant, buffer: &'b mut [u8], ) -> Option> { - let (conn_id, packet) = self.node.decapsulate( + let (cid, packet) = self.node.decapsulate( local, from, packet, now, buffer, ) - .inspect_err(|e| tracing::debug!(%local, %from, num_bytes = %packet.len(), "Failed to decapsulate incoming packet: {e}")) + .inspect_err(|e| tracing::debug!(%from, num_bytes = %packet.len(), "Failed to decapsulate incoming packet: {e}")) .ok()??; - tracing::Span::current().record("src", tracing::field::display(packet.source())); - tracing::Span::current().record("dst", tracing::field::display(packet.destination())); - - let Some(peer) = self.peers.get_mut(&conn_id) else { - tracing::error!(%conn_id, %local, %from, "Couldn't find connection"); + let Some(peer) = self.peers.get_mut(&cid) else { + tracing::warn!(%cid, "Couldn't find connection by ID"); return None; }; let packet = peer .decapsulate(packet, now) - .inspect_err(|e| tracing::debug!(%conn_id, %local, %from, "Invalid packet: {e}")) + .inspect_err(|e| tracing::debug!(%cid, "Invalid packet: {e}")) .ok()?; Some(packet.into_immutable()) diff --git a/rust/connlib/tunnel/src/peer.rs b/rust/connlib/tunnel/src/peer.rs index 2966d3bbd..a0929c04c 100644 --- a/rust/connlib/tunnel/src/peer.rs +++ b/rust/connlib/tunnel/src/peer.rs @@ -196,6 +196,7 @@ impl ClientOnGateway { self.recalculate_filters(); } + #[tracing::instrument(level = "debug", skip_all, fields(cid = %self.id))] fn assign_translations( &mut self, name: DomainName, @@ -220,7 +221,7 @@ impl ClientOnGateway { let ip_maps = ipv4_maps.chain(ipv6_maps); for (proxy_ip, real_ip) in ip_maps { - tracing::debug!(%proxy_ip, %real_ip, %name, "Assigned translation"); + tracing::debug!(%name, %proxy_ip, %real_ip); self.permanent_translations.insert( *proxy_ip, @@ -441,10 +442,10 @@ impl ClientOnGateway { &self, packet: &MutableIpPacket<'_>, ) -> Result<(), connlib_shared::Error> { - if !self.allowed_ips().contains(&packet.source()) { - return Err(connlib_shared::Error::UnallowedPacket { - src: packet.source(), - }); + let src = packet.source(); + + if !self.allowed_ips().contains(&src) { + return Err(connlib_shared::Error::SrcNotAllowed { src }); } Ok(()) @@ -461,8 +462,7 @@ impl ClientOnGateway { .longest_match(dst) .is_some_and(|(_, filter)| filter.is_allowed(&packet.to_immutable())) { - tracing::warn!(%dst, "unallowed packet"); - return Err(connlib_shared::Error::InvalidDst); + return Err(connlib_shared::Error::DstNotAllowed { dst }); }; Ok(()) @@ -476,10 +476,12 @@ impl ClientOnGateway { impl GatewayOnClient { pub(crate) fn ensure_allowed_src( &self, - pkt: &MutableIpPacket, + packet: &MutableIpPacket, ) -> Result<(), connlib_shared::Error> { - if self.allowed_ips.longest_match(pkt.source()).is_none() { - return Err(connlib_shared::Error::UnallowedPacket { src: pkt.source() }); + let src = packet.source(); + + if self.allowed_ips.longest_match(src).is_none() { + return Err(connlib_shared::Error::SrcNotAllowed { src }); } Ok(()) @@ -669,7 +671,7 @@ mod tests { assert!(matches!( peer.ensure_allowed_dst(&tcp_packet), - Err(connlib_shared::Error::InvalidDst) + Err(connlib_shared::Error::DstNotAllowed { .. }) )); assert!(peer.ensure_allowed_dst(&udp_packet).is_ok()); @@ -677,11 +679,11 @@ mod tests { assert!(matches!( peer.ensure_allowed_dst(&tcp_packet), - Err(connlib_shared::Error::InvalidDst) + Err(connlib_shared::Error::DstNotAllowed { .. }) )); assert!(matches!( peer.ensure_allowed_dst(&udp_packet), - Err(connlib_shared::Error::InvalidDst) + Err(connlib_shared::Error::DstNotAllowed { .. }) )); } @@ -1210,7 +1212,7 @@ mod proptests { assert!(matches!( peer.ensure_allowed_dst(&packet), - Err(connlib_shared::Error::InvalidDst) + Err(connlib_shared::Error::DstNotAllowed { .. }) )); } @@ -1272,7 +1274,7 @@ mod proptests { assert!(peer.ensure_allowed_dst(&packet_allowed).is_ok()); assert!(matches!( peer.ensure_allowed_dst(&packet_rejected), - Err(connlib_shared::Error::InvalidDst) + Err(connlib_shared::Error::DstNotAllowed { .. }) )); }