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.
This commit is contained in:
Thomas Eizinger
2024-07-12 09:38:19 +10:00
committed by GitHub
parent 64e0b71b77
commit 2013d6a2bf
6 changed files with 52 additions and 54 deletions

View File

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

View File

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

View File

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

View File

@@ -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<snownet::Transmit<'s>> {
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<IpPacket<'b>> {
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(

View File

@@ -163,25 +163,29 @@ impl GatewayState {
packet: MutableIpPacket<'_>,
now: Instant,
) -> Option<snownet::Transmit<'s>> {
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<IpPacket<'b>> {
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())

View File

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