Add debug logging to valence_protocol (#191)

Adds `tracing` to `valence_protocol` so we can log debug info about
partially decoded packets. `packet_inspector` has been set to print log
messages at the debug level.

crates/packet_inspector/Cargo.toml

@@ -5,8 +5,9 @@ edition = "2021"
 description = "A simple Minecraft proxy for inspecting packets."
 
 [dependencies]
-valence_protocol = { path = "../valence_protocol", version = "0.1.0", features = ["compression"] }
-clap = { version = "4.0.30", features = ["derive"] }
-tokio = { version = "1", features = ["full"] }
 anyhow = "1"
+clap = { version = "4.0.30", features = ["derive"] }
 regex = "1.6.0"
+tokio = { version = "1", features = ["full"] }
+tracing-subscriber = "0.3.16"
+valence_protocol = { path = "../valence_protocol", version = "0.1.0", features = ["compression"] }

crates/packet_inspector/src/main.rs

@@ -13,6 +13,7 @@ use tokio::net::tcp::{OwnedReadHalf, OwnedWriteHalf};
 use tokio::net::{TcpListener, TcpStream};
 use tokio::sync::Semaphore;
 use tokio::task::JoinHandle;
+use tracing_subscriber::filter::LevelFilter;
 use valence_protocol::packets::c2s::handshake::Handshake;
 use valence_protocol::packets::c2s::login::{EncryptionResponse, LoginStart};
 use valence_protocol::packets::c2s::play::C2sPlayPacket;
@@ -111,6 +112,10 @@ impl State {
 
 #[tokio::main]
 async fn main() -> Result<(), Box<dyn Error>> {
+    tracing_subscriber::fmt()
+        .with_max_level(LevelFilter::DEBUG)
+        .init();
+
     let cli = Arc::new(Cli::parse());
 
     let sema = Arc::new(Semaphore::new(cli.max_connections.unwrap_or(100_000)));

crates/valence/src/server/packet_manager.rs

@@ -1,3 +1,4 @@
+use std::fmt;
 use std::io::ErrorKind;
 use std::time::Duration;
 
@@ -60,7 +61,7 @@ where
 
     pub async fn recv_packet<'a, P>(&'a mut self) -> Result<P>
     where
-        P: DecodePacket<'a>,
+        P: DecodePacket<'a> + fmt::Debug,
     {
         timeout(self.timeout, async {
             while !self.dec.has_next_packet()? {
@@ -259,7 +260,7 @@ pub struct PlayPacketReceiver {
 impl PlayPacketReceiver {
     pub fn try_next_packet<'a, P>(&'a mut self) -> Result<Option<P>>
     where
-        P: DecodePacket<'a>,
+        P: DecodePacket<'a> + fmt::Debug,
     {
         self.dec.try_next_packet()
     }

crates/valence_protocol/Cargo.toml

@@ -7,7 +7,7 @@ build = "build/main.rs"
 [dependencies]
 aes = { version = "0.7.5", optional = true }
 anyhow = "1.0.66"
-bitfield-struct = "0.1.7"
+bitfield-struct = "0.3.1"
 byteorder = "1.4.3"
 bytes = "1.2.1"
 cfb8 = { version = "0.7.1", optional = true }
@@ -15,6 +15,7 @@ flate2 = { version = "1.0.24", optional = true }
 serde = { version = "1.0.147", features = ["derive"] }
 serde_json = "1.0.87"
 thiserror = "1.0.37"
+tracing = "0.1.37"
 uuid = "1.2.1"
 valence_derive = { version = "0.1.0", path = "../valence_derive" }
 valence_nbt = { version = "0.5.0", path = "../valence_nbt" }

crates/valence_protocol/src/codec.rs

@@ -1,7 +1,10 @@
+use std::fmt;
+
 #[cfg(feature = "encryption")]
 use aes::cipher::{AsyncStreamCipher, NewCipher};
 use anyhow::{bail, ensure};
 use bytes::{Buf, BufMut, BytesMut};
+use tracing::debug;
 
 use crate::var_int::{VarInt, VarIntDecodeError};
 use crate::{DecodePacket, Encode, EncodePacket, Result, MAX_PACKET_SIZE};
@@ -285,7 +288,7 @@ impl PacketDecoder {
 
     pub fn try_next_packet<'a, P>(&'a mut self) -> Result<Option<P>>
     where
-        P: DecodePacket<'a>,
+        P: DecodePacket<'a> + fmt::Debug,
     {
         self.buf.advance(self.cursor);
         self.cursor = 0;
@@ -345,11 +348,13 @@ impl PacketDecoder {
         #[cfg(not(feature = "compression"))]
         let packet = P::decode_packet(&mut r)?;
 
-        ensure!(
-            r.is_empty(),
-            "packet contents were not read completely ({} bytes remain)",
-            r.len()
-        );
+        if !r.is_empty() {
+            let remaining = r.len();
+
+            debug!("packet after partial decode ({remaining} bytes remain): {packet:?}");
+
+            bail!("packet contents were not read completely ({remaining} bytes remain)");
+        }
 
         let total_packet_len = VarInt(packet_len).written_size() + packet_len as usize;
         self.cursor = total_packet_len;