From 9ddee774b4174fa809929aef2e8a308972b1a520 Mon Sep 17 00:00:00 2001 From: Thomas Eizinger Date: Thu, 27 Jun 2024 16:36:49 +1000 Subject: [PATCH] chore(connlib): allow filtering of `wire` log target (#5578) Currently, enabling the `wire` log is an all or nothing approach, logging incoming and outgoing messages from the TUN device, network and the portal. Often, only one or more of these is desired but enabling all of `wire` spams the logs to the point where one cannot see the information they'd like. With this PR, we move some of the fields of the `wire` log statements to the log target instead. This allows controlling the logs via the `RUST_LOG` env variable. For example, to only see messages sent and received to the API, one can set `RUST_LOG=wire::api=trace` which will output something like: ``` 2024-06-27T02:12:41.821374Z TRACE wire::api::send: {"topic":"client","event":"phx_join","payload":null,"ref":0} 2024-06-27T02:12:42.030573Z TRACE wire::api::recv: {"event":"phx_reply","ref":0,"topic":"client","payload":{"status":"ok","response":{}}} ``` Similarly, enabling `wire::net=trace` will give you logs for packets sent over the network: ``` 2024-06-27T02:12:50.487503Z TRACE wire::net::send: src=None dst=34.80.2.250:3478 num_bytes=20 2024-06-27T02:12:50.487589Z TRACE wire::net::send: src=None dst=[2600:1900:4030:b0d9:0:5::]:3478 num_bytes=20 2024-06-27T02:12:50.487622Z TRACE wire::net::send: src=None dst=34.87.210.10:3478 num_bytes=20 2024-06-27T02:12:50.487652Z TRACE wire::net::send: src=None dst=[2600:1900:40b0:1504:0:17::]:3478 num_bytes=20 2024-06-27T02:12:50.510049Z TRACE wire::net::recv: src=34.87.210.10:3478 dst=192.168.188.71:39207 num_bytes=32 2024-06-27T02:12:50.510382Z TRACE wire::net::send: src=None dst=34.87.210.10:3478 num_bytes=112 2024-06-27T02:12:50.526947Z TRACE wire::net::recv: src=34.87.210.10:3478 dst=192.168.188.71:39207 num_bytes=92 2024-06-27T02:12:50.527295Z TRACE wire::net::send: src=None dst=34.87.210.10:3478 num_bytes=152 ``` These targets have been designed to take up equal amounts of space. All three types (`dev`, `net`, `api`) have 3 letters and `send` and `recv` have 4. That way, these logs are always aligned which makes them easier to scan. --- rust/connlib/tunnel/src/device_channel.rs | 6 +++--- rust/connlib/tunnel/src/sockets.rs | 4 ++-- rust/phoenix-channel/src/lib.rs | 4 ++-- 3 files changed, 7 insertions(+), 7 deletions(-) diff --git a/rust/connlib/tunnel/src/device_channel.rs b/rust/connlib/tunnel/src/device_channel.rs index e04d838b1..68bb507e3 100644 --- a/rust/connlib/tunnel/src/device_channel.rs +++ b/rust/connlib/tunnel/src/device_channel.rs @@ -135,7 +135,7 @@ impl Device { ) })?; - tracing::trace!(target: "wire", from = "device", dst = %packet.destination(), src = %packet.source(), bytes = %packet.packet().len()); + tracing::trace!(target: "wire::dev::recv", dst = %packet.destination(), src = %packet.source(), bytes = %packet.packet().len()); Poll::Ready(Ok(packet)) } @@ -169,7 +169,7 @@ impl Device { ) })?; - tracing::trace!(target: "wire", from = "device", dst = %packet.destination(), src = %packet.source(), bytes = %packet.packet().len()); + tracing::trace!(target: "wire::dev::recv", dst = %packet.destination(), src = %packet.source(), bytes = %packet.packet().len()); Poll::Ready(Ok(packet)) } @@ -191,7 +191,7 @@ impl Device { } pub fn write(&self, packet: IpPacket<'_>) -> io::Result { - tracing::trace!(target: "wire", to = "device", dst = %packet.destination(), src = %packet.source(), bytes = %packet.packet().len()); + tracing::trace!(target: "wire::dev::send", dst = %packet.destination(), src = %packet.source(), bytes = %packet.packet().len()); match packet { IpPacket::Ipv4(msg) => self.tun()?.write4(msg.packet()), diff --git a/rust/connlib/tunnel/src/sockets.rs b/rust/connlib/tunnel/src/sockets.rs index 4837ab4d4..7f1441ae2 100644 --- a/rust/connlib/tunnel/src/sockets.rs +++ b/rust/connlib/tunnel/src/sockets.rs @@ -283,7 +283,7 @@ impl Socket { packet, }) .inspect(|r| { - tracing::trace!(target: "wire", from = "network", src = %r.from, dst = %r.local, num_bytes = %r.packet.len()); + tracing::trace!(target: "wire::net::recv", src = %r.from, dst = %r.local, num_bytes = %r.packet.len()); }); return Poll::Ready(Ok(iter)); @@ -322,7 +322,7 @@ impl Socket { } fn send(&mut self, transmit: quinn_udp::Transmit) { - tracing::trace!(target: "wire", to = "network", src = ?transmit.src_ip, dst = %transmit.destination, num_bytes = %transmit.contents.len()); + tracing::trace!(target: "wire::net::send", src = ?transmit.src_ip, dst = %transmit.destination, num_bytes = %transmit.contents.len()); self.buffered_transmits.push(transmit); diff --git a/rust/phoenix-channel/src/lib.rs b/rust/phoenix-channel/src/lib.rs index 7cc60e7cd..80d5ea9f2 100644 --- a/rust/phoenix-channel/src/lib.rs +++ b/rust/phoenix-channel/src/lib.rs @@ -321,7 +321,7 @@ where if let Some(message) = self.pending_messages.pop_front() { match stream.start_send_unpin(Message::Text(message.clone())) { Ok(()) => { - tracing::trace!(target: "wire", to="portal", %message); + tracing::trace!(target: "wire::api::send", %message); match stream.poll_flush_unpin(cx) { Poll::Ready(Ok(())) => { @@ -359,7 +359,7 @@ where continue; }; - tracing::trace!(target: "wire", from="portal", %message); + tracing::trace!(target: "wire::api::recv", %message); let message = match serde_json::from_str::< PhoenixMessage,