Better logging (#167)

* feat: logs for when a player interacts with a block out of reach

* cleanup: used self.gameprofile instead of getting it from the client

* cleanup: better logging

* fix: added logging library

* cleanup:removed unused namespace

* cleanup: capitalisation and log levels

* fix: removed simple logging

* fix: removed todo! where not needed

* cleanup: removed duplicate dbg!

* Fix mistake in merging

* Fix my bad

* Merge repeated match arms

pumpkin-core/src/math/position.rs

@@ -1,3 +1,5 @@
+use std::fmt;
+
 use serde::{Deserialize, Serialize};
 
 use super::vector3::Vector3;
@@ -43,3 +45,9 @@ impl<'de> Deserialize<'de> for WorldPosition {
         deserializer.deserialize_i64(Visitor)
     }
 }
+
+impl std::fmt::Display for WorldPosition {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        write!(f, "({}, {},{})", self.0.x, self.0.y, self.0.z)
+    }
+}

pumpkin-inventory/Cargo.toml

@@ -7,6 +7,8 @@ edition.workspace = true
 # For items
 pumpkin-world = { path = "../pumpkin-world" }
 
+log.workspace = true
+
 num-traits = "0.2"
 num-derive = "0.4"
 thiserror = "1.0.63"

pumpkin-inventory/src/open_container.rs

@@ -2,7 +2,6 @@ use crate::{Container, WindowType};
 use pumpkin_world::item::ItemStack;
 use std::sync::Arc;
 use tokio::sync::Mutex;
-
 pub struct OpenContainer {
     players: Vec<i32>,
     container: Arc<Mutex<Box<dyn Container>>>,
@@ -11,7 +10,7 @@ pub struct OpenContainer {
 impl OpenContainer {
     pub fn try_open(&self, player_id: i32) -> Option<&Arc<Mutex<Box<dyn Container>>>> {
         if !self.players.contains(&player_id) {
-            dbg!("couldn't open container");
+            log::debug!("couldn't open container");
             return None;
         }
         let container = &self.container;

pumpkin/src/client/client_packet.rs

@@ -32,10 +32,9 @@ use super::{authentication::AuthError, Client, PlayerConfig};
 /// Processes incoming Packets from the Client to the Server
 /// Implements the `Client` Packets
 /// NEVER TRUST THE CLIENT. HANDLE EVERY ERROR, UNWRAP/EXPECT
-/// TODO: REMOVE ALL UNWRAPS
 impl Client {
     pub async fn handle_handshake(&self, handshake: SHandShake) {
-        dbg!("handshake");
+        log::debug!("handshake");
         let version = handshake.protocol_version.0;
         self.protocol_version
             .store(version, std::sync::atomic::Ordering::Relaxed);
@@ -61,7 +60,7 @@ impl Client {
     }
 
     pub async fn handle_ping_request(&self, ping_request: SStatusPingRequest) {
-        dbg!("ping");
+        log::debug!("recieved ping request");
         self.send_packet(&CPingResponse::new(ping_request.payload))
             .await;
         self.close();
@@ -277,13 +276,13 @@ impl Client {
             version: "1.21",
         }]))
         .await;
-        dbg!("login acknowledged");
+        log::debug!("login acknowledged");
     }
     pub async fn handle_client_information_config(
         &self,
         client_information: SClientInformationConfig,
     ) {
-        dbg!("got client settings");
+        log::debug!("got client settings");
         if let (Some(main_hand), Some(chat_mode)) = (
             Hand::from_i32(client_information.main_hand.into()),
             ChatMode::from_i32(client_information.chat_mode.into()),
@@ -307,7 +306,7 @@ impl Client {
         if plugin_message.channel.starts_with("minecraft:brand")
             || plugin_message.channel.starts_with("MC|Brand")
         {
-            dbg!("got a client brand");
+            log::debug!("got a client brand");
             match String::from_utf8(plugin_message.data) {
                 Ok(brand) => *self.brand.lock().await = Some(brand),
                 Err(e) => self.kick(&e.to_string()).await,
@@ -325,12 +324,12 @@ impl Client {
         }
 
         // We are done with configuring
-        dbg!("finish config");
+        log::debug!("finished config");
         self.send_packet(&CFinishConfig::new()).await;
     }
 
     pub fn handle_config_acknowledged(&self, _config_acknowledged: &SAcknowledgeFinishConfig) {
-        dbg!("config acknowledged");
+        log::debug!("config acknowledged");
         self.connection_state.store(ConnectionState::Play);
         self.make_player
             .store(true, std::sync::atomic::Ordering::Relaxed);

pumpkin/src/client/container.rs

@@ -190,7 +190,7 @@ impl Player {
                 //  self.mouse_drag(drag_handler, opened_container.as_deref_mut(), drag_state)
             }
             ClickType::DropType(_drop_type) => {
-                dbg!("todo");
+                log::debug!("todo");
                 Ok(())
             }
         }?;

pumpkin/src/client/mod.rs

@@ -211,9 +211,8 @@ impl Client {
     pub async fn process_packets(&self, server: &Arc<Server>) {
         while let Some(mut packet) = self.client_packets_queue.lock().await.pop_front() {
             if let Err(error) = self.handle_packet(server, &mut packet).await {
-                dbg!("{:?}", packet.id);
                 let text = format!("Error while reading incoming packet {error}");
-                log::error!("{}", text);
+                log::error!("{text}");
                 self.kick(&text).await;
             };
         }
@@ -388,7 +387,7 @@ impl Client {
 
     /// Kicks the Client with a reason depending on the connection state
     pub async fn kick(&self, reason: &str) {
-        dbg!(reason);
+        log::debug!("Kicking client with reason: {}", reason);
         match self.connection_state.load() {
             ConnectionState::Login => {
                 self.try_send_packet(&CLoginDisconnect::new(

pumpkin/src/client/player_packet.rs

@@ -280,7 +280,6 @@ impl Player {
                         entity.set_sneaking(false).await;
                     }
                 }
-                pumpkin_protocol::server::play::Action::LeaveBed => todo!(),
                 pumpkin_protocol::server::play::Action::StartSprinting => {
                     if !entity.sprinting.load(std::sync::atomic::Ordering::Relaxed) {
                         entity.set_sprinting(true).await;
@@ -291,9 +290,12 @@ impl Player {
                         entity.set_sprinting(false).await;
                     }
                 }
-                pumpkin_protocol::server::play::Action::StartHorseJump => todo!(),
-                pumpkin_protocol::server::play::Action::StopHorseJump => todo!(),
-                pumpkin_protocol::server::play::Action::OpenVehicleInventory => todo!(),
+                pumpkin_protocol::server::play::Action::LeaveBed
+                | pumpkin_protocol::server::play::Action::StartHorseJump
+                | pumpkin_protocol::server::play::Action::StopHorseJump
+                | pumpkin_protocol::server::play::Action::OpenVehicleInventory => {
+                    log::debug!("todo");
+                }
                 pumpkin_protocol::server::play::Action::StartFlyingElytra => {
                     let fall_flying = entity.check_fall_flying();
                     if entity
@@ -334,7 +336,7 @@ impl Player {
     }
 
     pub async fn handle_chat_message(&self, chat_message: SChatMessage) {
-        dbg!("got message");
+        log::debug!("Received chat message");
 
         let message = chat_message.message;
         if message.len() > 256 {
@@ -369,7 +371,7 @@ impl Player {
             &CDisguisedChatMessage::new(
                 TextComponent::from(message.clone()),
                 VarInt(0),
-                gameprofile.name.clone().into(),
+               gameprofile.name.clone().into(),
                 None,
             ),
         ) */
@@ -456,11 +458,8 @@ impl Player {
                         }
                     }
                 }
-                ActionType::Interact => {
-                    dbg!("todo");
-                }
-                ActionType::InteractAt => {
-                    dbg!("todo");
+                ActionType::Interact | ActionType::InteractAt => {
+                    log::debug!("todo");
                 }
             },
             None => self.kick(TextComponent::text("Invalid action type")).await,
@@ -472,7 +471,11 @@ impl Player {
             Some(status) => match status {
                 Status::StartedDigging => {
                     if !self.can_interact_with_block_at(&player_action.location, 1.0) {
-                        // TODO: maybe log?
+                        log::warn!(
+                            "Player {0} tried to interact with block out of reach at {1}",
+                            self.gameprofile.name,
+                            player_action.location
+                        );
                         return;
                     }
                     // TODO: do validation
@@ -494,7 +497,11 @@ impl Player {
                 }
                 Status::CancelledDigging => {
                     if !self.can_interact_with_block_at(&player_action.location, 1.0) {
-                        // TODO: maybe log?
+                        log::warn!(
+                            "Player {0} tried to interact with block out of reach at {1}",
+                            self.gameprofile.name,
+                            player_action.location
+                        );
                         return;
                     }
                     self.current_block_destroy_stage
@@ -504,7 +511,11 @@ impl Player {
                     // TODO: do validation
                     let location = player_action.location;
                     if !self.can_interact_with_block_at(&location, 1.0) {
-                        // TODO: maybe log?
+                        log::warn!(
+                            "Player {0} tried to interact with block out of reach at {1}",
+                            self.gameprofile.name,
+                            player_action.location
+                        );
                         return;
                     }
                     // Block break & block break sound
@@ -523,17 +534,11 @@ impl Player {
                         .send_packet(&CAcknowledgeBlockChange::new(player_action.sequence))
                         .await;
                 }
-                Status::DropItemStack => {
-                    dbg!("todo");
-                }
-                Status::DropItem => {
-                    dbg!("todo");
-                }
-                Status::ShootArrowOrFinishEating => {
-                    dbg!("todo");
-                }
-                Status::SwapItem => {
-                    dbg!("todo");
+                Status::DropItemStack
+                | Status::DropItem
+                | Status::ShootArrowOrFinishEating
+                | Status::SwapItem => {
+                    log::debug!("todo");
                 }
             },
             None => self.kick(TextComponent::text("Invalid status")).await,

pumpkin/src/proxy/velocity.rs

@@ -103,7 +103,7 @@ pub fn receive_velocity_plugin_response(
     config: &VelocityConfig,
     response: SLoginPluginResponse,
 ) -> Result<(GameProfile, SocketAddr), VelocityError> {
-    dbg!("velocity response");
+    log::debug!("received velocity response");
     if let Some(data) = response.data {
         let (signature, data_without_signature) = data.split_at(32);
 

pumpkin/src/rcon/mod.rs

@@ -47,7 +47,7 @@ impl RCONServer {
             let password = password.clone();
             let server = server.clone();
             tokio::spawn(async move { while !client.handle(&server, &password).await {} });
-            dbg!("closed");
+            log::debug!("closed RCON connection");
             connections -= 1;
         }
     }
@@ -85,7 +85,6 @@ impl RCONClient {
                     return true;
                 }
             }
-            dbg!("a");
             // If we get a close here, we might have a reply, which we still want to write.
             let _ = self.poll(server, password).await.map_err(|e| {
                 log::error!("RCON error: {e}");

pumpkin/src/world/mod.rs

@@ -120,7 +120,7 @@ impl World {
                 false,
             ))
             .await;
-        dbg!("sending abilities");
+        log::debug!("sending abilities");
         // player abilities
         // TODO: this is for debug purpose, remove later
         player
@@ -308,7 +308,8 @@ impl World {
                     client.send_packet(&CChunkData(&chunk_data)).await;
                 }
             }
-            dbg!("DONE CHUNKS", inst.elapsed());
+
+            log::debug!("chunks sent after {}ms", inst.elapsed().as_millis());
         });
     }
 

pumpkin/src/world/player_chunker.rs

@@ -33,7 +33,11 @@ pub async fn player_join(world: &World, player: Arc<Player>) {
         })
         .await;
     let view_distance = i32::from(get_view_distance(&player).await);
-    dbg!(view_distance);
+    log::debug!(
+        "Player {} joined with view distance: {}",
+        player.gameprofile.name,
+        view_distance
+    );
     let old_cylindrical = Cylindrical::new(
         Vector2::new(watched_section.x, watched_section.z),
         view_distance,