diff --git a/Cargo.lock b/Cargo.lock index 90f730fc1c..145b0cffe1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2026,7 +2026,6 @@ dependencies = [ "futures", "hmac 0.13.0-rc.5", "libloading", - "log", "num-bigint", "pkcs8 0.11.0-rc.10", "pumpkin-config", @@ -2070,10 +2069,10 @@ dependencies = [ name = "pumpkin-config" version = "0.1.0-dev+1.21.11" dependencies = [ - "log", "pumpkin-util", "serde", "toml", + "tracing", "uuid", ] @@ -2094,13 +2093,13 @@ name = "pumpkin-inventory" version = "0.1.0-dev+1.21.11" dependencies = [ "crossbeam-utils", - "log", "pumpkin-data", "pumpkin-protocol", "pumpkin-util", "pumpkin-world", "thiserror", "tokio", + "tracing", ] [[package]] @@ -2185,7 +2184,6 @@ dependencies = [ "flate2", "futures", "itertools 0.14.0", - "log", "lz4-java-wrc", "num_cpus", "pumpkin-config", @@ -2204,6 +2202,7 @@ dependencies = [ "thiserror", "tokio", "tokio-util", + "tracing", "uuid", ] diff --git a/Cargo.toml b/Cargo.toml index 44d87cc4a6..185dd4c59d 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -87,7 +87,6 @@ debug = true strip = false [workspace.dependencies] -log = "0.4" tokio = { version = "1.49", default-features = false } syn = { version = "2.0", default-features = false, features = ["printing"] } diff --git a/pumpkin-config/Cargo.toml b/pumpkin-config/Cargo.toml index c060ab2abe..2bbdd80866 100644 --- a/pumpkin-config/Cargo.toml +++ b/pumpkin-config/Cargo.toml @@ -7,7 +7,7 @@ rust-version.workspace = true [dependencies] pumpkin-util.workspace = true serde.workspace = true -log.workspace = true +tracing.workspace = true uuid.workspace = true toml.workspace = true diff --git a/pumpkin-config/src/lib.rs b/pumpkin-config/src/lib.rs index 214845e0f0..0f30087e93 100644 --- a/pumpkin-config/src/lib.rs +++ b/pumpkin-config/src/lib.rs @@ -7,6 +7,7 @@ use serde::{Deserialize, Serialize, de::DeserializeOwned}; use std::net::SocketAddr; use std::path::PathBuf; use std::{fs, num::NonZeroU8, path::Path}; +use tracing::{debug, warn}; pub mod fun; pub mod logging; pub mod networking; @@ -189,7 +190,7 @@ pub trait LoadConfiguration { Self: Sized + Default + Serialize + DeserializeOwned, { if !config_dir.exists() { - log::debug!("creating new config root folder"); + debug!("creating new config root folder"); fs::create_dir(config_dir).expect("Failed to create config root folder"); } let path = config_dir.join(Self::get_path()); @@ -215,7 +216,7 @@ pub trait LoadConfiguration { path.file_name().unwrap().display() ); if let Err(err) = fs::write(&path, toml::to_string(&merged_config).unwrap()) { - log::warn!( + warn!( "Couldn't write merged config to {}. Reason: {}", path.display(), err @@ -227,7 +228,7 @@ pub trait LoadConfiguration { } else { let content = Self::default(); if let Err(err) = fs::write(&path, toml::to_string(&content).unwrap()) { - log::warn!( + warn!( "Couldn't write default config to {:?}. Reason: {}", path.display(), err diff --git a/pumpkin-inventory/Cargo.toml b/pumpkin-inventory/Cargo.toml index 3b432cff11..a854009da6 100644 --- a/pumpkin-inventory/Cargo.toml +++ b/pumpkin-inventory/Cargo.toml @@ -11,7 +11,7 @@ pumpkin-data.workspace = true pumpkin-world.workspace = true pumpkin-util.workspace = true -log.workspace = true +tracing.workspace = true tokio.workspace = true thiserror.workspace = true crossbeam-utils.workspace = true diff --git a/pumpkin-inventory/src/furnace_like/furnace_like_screen_handler.rs b/pumpkin-inventory/src/furnace_like/furnace_like_screen_handler.rs index 1a14ea4357..686d46b8f5 100644 --- a/pumpkin-inventory/src/furnace_like/furnace_like_screen_handler.rs +++ b/pumpkin-inventory/src/furnace_like/furnace_like_screen_handler.rs @@ -14,6 +14,7 @@ use crate::{ ScreenHandlerFuture, ScreenHandlerListener, ScreenProperty, }, }; +use tracing::debug; use super::furnace_like_slot::{FurnaceLikeSlot, FurnaceLikeSlotType, FurnaceOutputSlot}; @@ -119,7 +120,7 @@ impl ScreenHandler for FurnaceLikeScreenHandler { const FUEL_SLOT: i32 = 1; // Note: Slots 0, 1, 2 are Furnace slots. const OUTPUT_SLOT: i32 = 2; - log::debug!("FurnaceLikeScreenHandler::quick_move slot_index={slot_index}"); + debug!("FurnaceLikeScreenHandler::quick_move slot_index={slot_index}"); let mut stack_left = ItemStack::EMPTY.clone(); @@ -163,7 +164,7 @@ impl ScreenHandler for FurnaceLikeScreenHandler { // Award XP when taking from output slot (slot 2) if slot_index == OUTPUT_SLOT { - log::debug!("quick_move: taking from output slot, calling on_take_item"); + debug!("quick_move: taking from output slot, calling on_take_item"); slot.on_take_item(player, &stack_left).await; } diff --git a/pumpkin-inventory/src/furnace_like/furnace_like_slot.rs b/pumpkin-inventory/src/furnace_like/furnace_like_slot.rs index 617db44a2b..35bb0d8bc9 100644 --- a/pumpkin-inventory/src/furnace_like/furnace_like_slot.rs +++ b/pumpkin-inventory/src/furnace_like/furnace_like_slot.rs @@ -5,6 +5,8 @@ use pumpkin_world::{ block::entities::furnace_like_block_entity::ExperienceContainer, inventory::Inventory, }; +use tracing::debug; + use crate::{ screen_handler::InventoryPlayer, slot::{BoxFuture, Slot}, @@ -118,12 +120,12 @@ impl Slot for FurnaceOutputSlot { _stack: &'a pumpkin_world::item::ItemStack, ) -> BoxFuture<'a, ()> { Box::pin(async move { - log::debug!("FurnaceOutputSlot: on_take_item called"); + debug!("FurnaceOutputSlot: on_take_item called"); // Extract accumulated experience and award to player let experience = self.experience_container.extract_experience(); - log::debug!("FurnaceOutputSlot: extracted experience = {experience}"); + debug!("FurnaceOutputSlot: extracted experience = {experience}"); if experience > 0 { - log::debug!("FurnaceOutputSlot: awarding {experience} xp to player"); + debug!("FurnaceOutputSlot: awarding {experience} xp to player"); player.award_experience(experience).await; } self.mark_dirty().await; diff --git a/pumpkin-inventory/src/player/player_inventory.rs b/pumpkin-inventory/src/player/player_inventory.rs index c34e891bf9..6fdeccc02a 100644 --- a/pumpkin-inventory/src/player/player_inventory.rs +++ b/pumpkin-inventory/src/player/player_inventory.rs @@ -14,6 +14,7 @@ use std::pin::Pin; use std::sync::Arc; use std::sync::atomic::{AtomicU8, Ordering}; use tokio::sync::Mutex; +use tracing::warn; pub struct PlayerInventory { pub main_inventory: [Arc>; Self::MAIN_SIZE], @@ -401,13 +402,10 @@ impl Inventory for PlayerInventory { Box::pin(async move { if slot < self.main_inventory.len() { *self.main_inventory[slot].lock().await = stack; + } else if let Some(slot) = self.equipment_slots.get(&slot) { + self.entity_equipment.lock().await.put(slot, stack).await; } else { - match self.equipment_slots.get(&slot) { - Some(slot) => { - self.entity_equipment.lock().await.put(slot, stack).await; - } - None => log::warn!("Failed to get Equipment Slot at {slot}"), - } + warn!("Failed to get Equipment Slot at {slot}"); } }) } diff --git a/pumpkin-inventory/src/screen_handler.rs b/pumpkin-inventory/src/screen_handler.rs index 14890465af..f0f5edfd8f 100644 --- a/pumpkin-inventory/src/screen_handler.rs +++ b/pumpkin-inventory/src/screen_handler.rs @@ -4,7 +4,6 @@ use crate::{ slot::{NormalSlot, Slot}, sync_handler::{SyncHandler, TrackedStack}, }; -use log::warn; use pumpkin_data::{ data_component_impl::{EquipmentSlot, EquipmentType, EquippableImpl}, screen::WindowType, @@ -29,6 +28,7 @@ use std::sync::atomic::{AtomicU32, Ordering}; use std::{any::Any, collections::HashMap, sync::Arc}; use std::{cmp::max, pin::Pin}; use tokio::sync::Mutex; +use tracing::warn; const SLOT_INDEX_OUTSIDE: i32 = -999; diff --git a/pumpkin-world/Cargo.toml b/pumpkin-world/Cargo.toml index 5db92b47ed..99facc53ce 100644 --- a/pumpkin-world/Cargo.toml +++ b/pumpkin-world/Cargo.toml @@ -29,7 +29,7 @@ uuid.workspace = true thiserror.workspace = true serde.workspace = true serde_json.workspace = true -log.workspace = true +tracing.workspace = true crossbeam.workspace = true sha2.workspace = true diff --git a/pumpkin-world/src/block/entities/chiseled_bookshelf.rs b/pumpkin-world/src/block/entities/chiseled_bookshelf.rs index d7f09d9d8e..9cabf164dd 100644 --- a/pumpkin-world/src/block/entities/chiseled_bookshelf.rs +++ b/pumpkin-world/src/block/entities/chiseled_bookshelf.rs @@ -1,4 +1,3 @@ -use log::warn; use pumpkin_data::Block; use pumpkin_data::block_properties::{BlockProperties, ChiseledBookshelfLikeProperties}; use pumpkin_nbt::compound::NbtCompound; @@ -13,6 +12,7 @@ use std::{ }, }; use tokio::sync::Mutex; +use tracing::warn; use crate::inventory::InventoryFuture; use crate::{ diff --git a/pumpkin-world/src/chunk/format/anvil.rs b/pumpkin-world/src/chunk/format/anvil.rs index 65aae8bedb..f5a9681f62 100644 --- a/pumpkin-world/src/chunk/format/anvil.rs +++ b/pumpkin-world/src/chunk/format/anvil.rs @@ -16,6 +16,7 @@ use tokio::{ io::{AsyncSeekExt, AsyncWrite, AsyncWriteExt, BufWriter}, sync::Mutex, }; +use tracing::{debug, trace}; use crate::chunk::{ ChunkParsingError, ChunkReadingError, ChunkSerializingError, ChunkWritingError, @@ -348,7 +349,7 @@ impl AnvilChunkFile { where I: IntoIterator, { - log::trace!("Writing in place: {}", path.display()); + trace!("Writing in place: {}", path.display()); let file = tokio::fs::OpenOptions::new() .write(true) @@ -364,11 +365,9 @@ impl AnvilChunkFile { if let Some(chunk) = metadata { let chunk_data = &chunk.serialized_data; let sector_count = chunk_data.sector_count(); - log::trace!( + trace!( "Writing position for chunk {} - {}:{}", - index, - chunk.file_sector_offset, - sector_count + index, chunk.file_sector_offset, sector_count ); write .write_u32((chunk.file_sector_offset << 8) | sector_count) @@ -421,7 +420,7 @@ impl AnvilChunkFile { // Seek only if we need to if chunk.file_sector_offset != current_sector { - log::trace!("Seeking to sector {}", chunk.file_sector_offset); + trace!("Seeking to sector {}", chunk.file_sector_offset); let _ = write .seek(SeekFrom::Start( chunk.file_sector_offset as u64 * SECTOR_BYTES as u64, @@ -429,7 +428,7 @@ impl AnvilChunkFile { .await?; current_sector = chunk.file_sector_offset; } - log::trace!( + trace!( "Writing chunk {} - {}:{}", index, current_sector, @@ -447,7 +446,7 @@ impl AnvilChunkFile { /// Write entire file, disregarding saved offsets async fn write_all(&self, path: &Path) -> Result<(), std::io::Error> { let temp_path = path.with_extension("tmp"); - log::trace!("Writing tmp file to disk: {temp_path:?}"); + trace!("Writing tmp file to disk: {temp_path:?}"); let file = tokio::fs::File::create(&temp_path).await?; @@ -487,7 +486,7 @@ impl AnvilChunkFile { // that the data is not corrupted before the rename is completed tokio::fs::rename(temp_path, path).await?; - log::trace!("Wrote file to Disk: {}", path.display()); + trace!("Wrote file to Disk: {}", path.display()); Ok(()) } } @@ -531,7 +530,7 @@ impl ChunkSerializer for AnvilChunkFile { let mut write_action = self.write_action.lock().await; match &*write_action { WriteAction::Pass => { - log::debug!( + debug!( "Skipping write for {}, as there were no dirty chunks", path.display() ); @@ -632,7 +631,7 @@ impl ChunkSerializer for AnvilChunkFile { match &*write_action { WriteAction::All => { - log::trace!("Write action is all: setting chunk in place"); + trace!("Write action is all: setting chunk in place"); // Doesn't matter, just add the data self.chunks_data[index] = Some(AnvilChunkMetadata { serialized_data: new_chunk_data, @@ -643,7 +642,7 @@ impl ChunkSerializer for AnvilChunkFile { _ => { match self.chunks_data[index].as_ref() { None => { - log::trace!( + trace!( "Chunk {} does not exist, appending to EOF: {}:{}", index, self.end_sector, @@ -662,7 +661,7 @@ impl ChunkSerializer for AnvilChunkFile { Some(old_chunk) => { if old_chunk.serialized_data.sector_count() == new_chunk_data.sector_count() { - log::trace!( + trace!( "Chunk {} exists, writing in place: {}:{}", index, old_chunk.file_sector_offset, @@ -710,7 +709,7 @@ impl ChunkSerializer for AnvilChunkFile { .collect::>(); if chunks_to_shift.last().is_none_or(|chunk| chunk.0 == index) { - log::trace!( + trace!( "Unable to find a chunk to swap with; falling back to serialize all", ); @@ -755,7 +754,7 @@ impl ChunkSerializer for AnvilChunkFile { // If positive, now larger -> shift right, else shift left let offset = new_sectors as i64 - swapped_sectors as i64; - log::trace!( + trace!( "Swapping {index} with {swapped_index}, shifting all chunks {swapped_index} and after by {offset}" ); diff --git a/pumpkin-world/src/chunk/format/linear.rs b/pumpkin-world/src/chunk/format/linear.rs index 71daf906ba..914fb55333 100644 --- a/pumpkin-world/src/chunk/format/linear.rs +++ b/pumpkin-world/src/chunk/format/linear.rs @@ -7,12 +7,12 @@ use crate::chunk::format::anvil::{AnvilChunkFile, SingleChunkDataSerializer}; use crate::chunk::io::{ChunkSerializer, LoadedData}; use crate::chunk::{ChunkReadingError, ChunkWritingError}; use bytes::{Buf, BufMut, Bytes}; -use log::error; use pumpkin_config::chunk::LinearChunkConfig; use pumpkin_util::math::vector2::Vector2; use ruzstd::decoding::StreamingDecoder; use ruzstd::encoding::{CompressionLevel, compress_to_vec}; use tokio::io::{AsyncWriteExt, BufWriter}; +use tracing::{error, trace, warn}; use super::anvil::CHUNK_COUNT; @@ -177,7 +177,7 @@ impl ChunkSerializer for LinearFile { async fn write(&self, path: &PathBuf) -> Result<(), std::io::Error> { let temp_path = path.with_extension("tmp"); - log::trace!("Writing tmp file to disk: {}", temp_path.display()); + trace!("Writing tmp file to disk: {}", temp_path.display()); let file = tokio::fs::File::create(&temp_path).await?; let mut write = BufWriter::new(file); @@ -227,7 +227,7 @@ impl ChunkSerializer for LinearFile { // that the data is not corrupted before the rename is completed tokio::fs::rename(temp_path, &path).await?; - log::trace!("Wrote file to Disk: {}", path.display()); + trace!("Wrote file to Disk: {}", path.display()); Ok(()) } @@ -293,7 +293,7 @@ impl ChunkSerializer for LinearFile { let last_index = bytes_offset; bytes_offset += header.size as usize; if bytes_offset > buffer.len() { - log::warn!( + warn!( "Not enough bytes are available for chunk {} ({} vs {})", i, header.size, diff --git a/pumpkin-world/src/chunk/format/mod.rs b/pumpkin-world/src/chunk/format/mod.rs index cc669dac7d..d2be03f292 100644 --- a/pumpkin-world/src/chunk/format/mod.rs +++ b/pumpkin-world/src/chunk/format/mod.rs @@ -14,6 +14,7 @@ use pumpkin_data::{Block, chunk::ChunkStatus, fluid::Fluid}; use pumpkin_nbt::{compound::NbtCompound, from_bytes, nbt_long_array}; use rustc_hash::FxHashMap; use tokio::sync::Mutex; +use tracing::debug; use uuid::Uuid; use crate::{ @@ -311,11 +312,9 @@ impl ChunkEntityData { | (uuid[3] as u128), ) } else { - log::debug!( + debug!( "Entity in chunk {},{} is missing UUID: {:?}", - position.x, - position.y, - entity_nbt + position.x, position.y, entity_nbt ); continue; }; diff --git a/pumpkin-world/src/chunk/io/file_manager.rs b/pumpkin-world/src/chunk/io/file_manager.rs index 73f371b708..8a3dc1b36f 100644 --- a/pumpkin-world/src/chunk/io/file_manager.rs +++ b/pumpkin-world/src/chunk/io/file_manager.rs @@ -5,12 +5,12 @@ use std::{ }; use futures::future::join_all; -use log::{error, trace}; use pumpkin_util::math::vector2::Vector2; use tokio::{ join, sync::{OnceCell, RwLock, mpsc}, }; +use tracing::{debug, error, trace}; use crate::{ chunk::{ @@ -294,7 +294,7 @@ where // The closure now needs `move` to capture `self` and `folder` by value .map(move |(file_name, chunk_locks)| async move { let path = P::file_path(folder, &file_name); - log::trace!("Updating data for file {}", path.display()); + trace!("Updating data for file {}", path.display()); let chunk_serializer = match self.get_serializer(&path).await { Ok(file) => Ok(file), @@ -327,7 +327,7 @@ where }); // Run all update tasks concurrently and propagate any error futures::future::try_join_all(update_tasks).await?; - log::trace!("Updated data for file {}", path.display()); + trace!("Updated data for file {}", path.display()); let is_watched = self .watchers @@ -341,7 +341,7 @@ where // to avoid other threads to write/modify the data, but allow other threads to read it let serializer = chunk_serializer.read().await; - log::debug!("Writing file for {}", path.display()); + debug!("Writing file for {}", path.display()); serializer .write(&path) .await @@ -370,9 +370,9 @@ where if can_remove { locks.remove(&path); - log::trace!("Removed lockfile cache {}", path.display()); + trace!("Removed lockfile cache {}", path.display()); } else { - log::trace!("Wanted to remove lockfile cache {} but someone still holds a reference to it!", path.display()); + trace!("Wanted to remove lockfile cache {} but someone still holds a reference to it!", path.display()); } } } diff --git a/pumpkin-world/src/chunk/mod.rs b/pumpkin-world/src/chunk/mod.rs index df00c67d0a..b68ee28f7f 100644 --- a/pumpkin-world/src/chunk/mod.rs +++ b/pumpkin-world/src/chunk/mod.rs @@ -19,6 +19,7 @@ use std::sync::atomic::AtomicBool; use std::sync::{Arc, RwLock}; use thiserror::Error; use tokio::sync::Mutex; +use tracing::info; pub mod format; pub mod io; @@ -270,7 +271,7 @@ impl ChunkHeightmaps { .collect::>() .join("\n"); - log::info!("\nHeightMap:\n{header}\n{grid}"); + info!("\nHeightMap:\n{header}\n{grid}"); } } diff --git a/pumpkin-world/src/chunk/palette.rs b/pumpkin-world/src/chunk/palette.rs index fee6c0755c..721048406c 100644 --- a/pumpkin-world/src/chunk/palette.rs +++ b/pumpkin-world/src/chunk/palette.rs @@ -2,6 +2,7 @@ use std::{collections::HashMap, hash::Hash}; use pumpkin_data::{Block, BlockState, block_properties::is_air, chunk::Biome}; use pumpkin_util::encompassing_bits; +use tracing::warn; use crate::block::BlockStateCodec; @@ -144,7 +145,7 @@ impl PalettedContainer minimum_bits_per_entry: u8, ) -> Self { if palette.is_empty() { - log::warn!("No palette data! Defaulting..."); + warn!("No palette data! Defaulting..."); return Self::Homogeneous(V::default()); } @@ -179,7 +180,7 @@ impl PalettedContainer .get(lookup_index as usize) .copied() .unwrap_or_else(|| { - log::warn!("Lookup index out of bounds! Defaulting..."); + warn!("Lookup index out of bounds! Defaulting..."); V::default() }); @@ -196,7 +197,7 @@ impl PalettedContainer counts[index] += 1; } else { // This case should ideally not happen if the palette is complete. - log::warn!("Decompressed value not found in palette!"); + warn!("Decompressed value not found in palette!"); } } diff --git a/pumpkin-world/src/chunk_system/chunk_loading.rs b/pumpkin-world/src/chunk_system/chunk_loading.rs index beed7eda8f..1ddd2da5f0 100644 --- a/pumpkin-world/src/chunk_system/chunk_loading.rs +++ b/pumpkin-world/src/chunk_system/chunk_loading.rs @@ -1,12 +1,12 @@ use super::{ChunkLevel, ChunkPos, HashMapType, LevelChannel}; use crate::chunk_system::chunk_state::StagedChunkEnum; // Fixed path use itertools::Itertools; -use log::debug; use std::cmp::{Ordering, PartialEq, min}; use std::collections::BinaryHeap; use std::collections::hash_map::Entry; use std::mem::swap; use std::sync::Arc; +use tracing::debug; pub struct HeapNode(i8, ChunkPos); impl PartialEq for HeapNode { @@ -316,13 +316,13 @@ impl ChunkLoading { } pub fn add_force_ticket(&mut self, pos: ChunkPos) { - // log::debug!("add force ticket at {pos:?}"); + // debug!("add force ticket at {pos:?}"); self.high_priority.push(pos); self.is_priority_dirty = true; self.add_ticket(pos, Self::FULL_CHUNK_LEVEL); } pub fn remove_force_ticket(&mut self, pos: ChunkPos) { - // log::debug!("remove force ticket at {pos:?}"); + // debug!("remove force ticket at {pos:?}"); let index = self .high_priority .iter() @@ -334,7 +334,7 @@ impl ChunkLoading { self.remove_ticket(pos, Self::FULL_CHUNK_LEVEL); } pub fn add_ticket(&mut self, pos: ChunkPos, level: i8) { - // log::debug!("add ticket at {pos:?} level {level}"); + // debug!("add ticket at {pos:?} level {level}"); debug_assert!(level < Self::MAX_LEVEL); match self.ticket.entry(pos) { Entry::Occupied(mut vec) => { @@ -359,14 +359,14 @@ impl ChunkLoading { debug_assert!(self.debug_check_error()); } pub fn remove_ticket(&mut self, pos: ChunkPos, level: i8) { - // log::debug!("remove ticket at {pos:?} level {level}"); + // debug!("remove ticket at {pos:?} level {level}"); debug_assert!(level < Self::MAX_LEVEL); let Some(vec) = self.ticket.get_mut(&pos) else { - // log::warn!("No ticket found at {pos:?}"); + // warn!("No ticket found at {pos:?}"); return; }; let Some((index, _)) = vec.iter().find_position(|x| **x == level) else { - // log::warn!("No ticket found at {pos:?}"); + // warn!("No ticket found at {pos:?}"); return; }; vec.remove(index); diff --git a/pumpkin-world/src/chunk_system/generation_cache.rs b/pumpkin-world/src/chunk_system/generation_cache.rs index d345744452..8d7baf6ce8 100644 --- a/pumpkin-world/src/chunk_system/generation_cache.rs +++ b/pumpkin-world/src/chunk_system/generation_cache.rs @@ -17,6 +17,7 @@ use pumpkin_util::math::position::BlockPos; use pumpkin_util::math::vector3::Vector3; use std::future::Future; use std::pin::Pin; +use tracing::debug; pub struct Cache { pub x: i32, @@ -155,11 +156,9 @@ impl GenerationCache for Cache { // debug_assert!(dx >= 0 && dz >= 0); if !(dx < self.size && dz < self.size && dx >= 0 && dz >= 0) { // breakpoint here - log::debug!( + debug!( "illegal get_block_state {pos:?} cache pos ({}, {}) size {}", - self.x, - self.z, - self.size + self.x, self.z, self.size ); return RawBlockState::AIR; } @@ -179,11 +178,9 @@ impl GenerationCache for Cache { // debug_assert!(dx >= 0 && dz >= 0); if !(dx < self.size && dz < self.size && dx >= 0 && dz >= 0) { // breakpoint here - log::debug!( + debug!( "illegal set_block_state {pos:?} cache pos ({}, {}) size {}", - self.x, - self.z, - self.size + self.x, self.z, self.size ); return; } diff --git a/pumpkin-world/src/chunk_system/schedule.rs b/pumpkin-world/src/chunk_system/schedule.rs index 15f2a95bb4..a734dfacf5 100644 --- a/pumpkin-world/src/chunk_system/schedule.rs +++ b/pumpkin-world/src/chunk_system/schedule.rs @@ -10,7 +10,6 @@ use super::{ }; use crate::level::{Level, SyncChunk}; use dashmap::DashMap; -use log::error; use pumpkin_config::lighting::LightingEngineConfig; use pumpkin_util::math::vector2::Vector2; use slotmap::Key; @@ -21,6 +20,7 @@ use std::sync::atomic::Ordering::Relaxed; use std::sync::{Arc, Condvar, Mutex}; use std::thread; use std::time::Duration; +use tracing::{debug, error, info, trace, warn}; struct TaskHeapNode(i8, NodeKey); impl PartialEq for TaskHeapNode { @@ -221,14 +221,14 @@ impl GenerationSchedule { return false; } if let Some(high_priority) = new_data.1 { - // log::debug!("receive new priority"); + // debug!("receive new priority"); self.last_high_priority = high_priority; } let Some(new_level) = new_data.0 else { self.sort_queue(); return true; }; - // log::debug!("receive new level"); + // debug!("receive new level"); for (pos, (old_stage, new_stage)) in new_level.0 { debug_assert_ne!(old_stage, new_stage); debug_assert_eq!( @@ -386,14 +386,13 @@ impl GenerationSchedule { } let sc = Arc::strong_count(&chunk); if sc == 1 { - // log::debug!("unload chunk {pos:?} to file"); + // debug!("unload chunk {pos:?} to file"); chunks.push((pos, Chunk::Level(chunk))); self.chunk_map.remove(&pos); } else { - log::warn!( + warn!( "unload_chunk: chunk {pos:?} still has {} strong refs; cannot unload. holder.public={}", - sc, - holder.public + sc, holder.public ); self.unload_chunks.insert(pos); holder.chunk = Some(Chunk::Level(chunk)); @@ -401,14 +400,14 @@ impl GenerationSchedule { } Chunk::Proto(chunk) => { debug_assert!(!holder.public); - // log::debug!("unload proto chunk {pos:?} to file"); + // debug!("unload proto chunk {pos:?} to file"); chunks.push((pos, Chunk::Proto(chunk))); self.chunk_map.remove(&pos); } } } } - // log::debug!("send {} unloaded chunks to io write", chunks.len()); + // debug!("send {} unloaded chunks to io write", chunks.len()); if chunks.is_empty() { return; } @@ -418,7 +417,7 @@ impl GenerationSchedule { } drop(data); if let Err(e) = self.io_write.send(chunks) { - log::error!( + error!( "Failed to send chunks to io write thread during save (may have shut down): {:?}", e ); @@ -447,7 +446,7 @@ impl GenerationSchedule { if chunks.is_empty() { return; } - log::info!( + info!( "Saving {} chunks (collected from {} holders)...", chunks.len(), self.chunk_map.len() @@ -458,7 +457,7 @@ impl GenerationSchedule { } drop(data); if let Err(e) = self.io_write.send(chunks) { - log::error!( + error!( "Failed to send chunks to io write thread during unload (may have shut down): {:?}", e ); @@ -499,7 +498,7 @@ impl GenerationSchedule { // debug!("receive io chunk pos {pos:?}"); let mut holder = self.chunk_map.remove(&pos).unwrap(); if holder.chunk.is_some() { - log::warn!( + warn!( "receive_chunk(IO): holder already has chunk at {:?}; replacing", pos ); @@ -521,13 +520,13 @@ impl GenerationSchedule { self.apply_lighting_override(data); let result = self.public_chunk_map.insert(pos, data.clone()); if result.is_some() { - log::warn!( + warn!( "receive_chunk(IO): replacing existing public chunk at {:?}", pos ); } holder.public = true; - log::trace!( + trace!( "Notifying players: chunk {:?} loaded from disk (Full status)", pos ); @@ -537,7 +536,7 @@ impl GenerationSchedule { // Proto chunk from IO (downgraded for relighting) - mark as non-public // so players get notified when it finishes generation if holder.public { - log::debug!( + debug!( "Chunk {:?} downgraded to Proto for relighting, marking as non-public", pos ); @@ -562,7 +561,7 @@ impl GenerationSchedule { // Expect the holder to be one stage before Full (Lighting). If not, // log and align so we don't panic in production/debug runs. if holder.current_stage != StagedChunkEnum::Lighting { - log::warn!( + warn!( "receive_chunk(Level): holder at {:?} for pos {:?} expected {:?}; aligning", holder.current_stage, new_pos, @@ -589,19 +588,19 @@ impl GenerationSchedule { self.public_chunk_map.insert(new_pos, public_chunk); holder.public = true; if result.is_some() { - log::warn!( + warn!( "public_chunk_map.insert returned existing chunk for {new_pos:?}" ); } // Notify players about the new chunk if let Some(pc) = self.public_chunk_map.get(&new_pos) { - log::trace!( + trace!( "Notifying players: new chunk at {:?} (generation complete)", new_pos ); self.listener.process_new_chunk(new_pos, &pc); } else { - log::error!( + error!( "CRITICAL: Failed to retrieve chunk {:?} from public_chunk_map immediately after insert!", new_pos ); @@ -612,7 +611,7 @@ impl GenerationSchedule { self.apply_lighting_override(&chunk); holder.chunk = Some(Chunk::Level(chunk.clone())); self.public_chunk_map.insert(new_pos, chunk.clone()); - log::info!( + info!( "Notifying players: regenerated chunk at {:?} (was already public)", new_pos ); @@ -682,11 +681,9 @@ impl GenerationSchedule { stage, error, } => { - log::error!( + error!( "Received generation failure notification for chunk {:?} at stage {:?}: {}", - fail_pos, - stage, - error + fail_pos, stage, error ); // Clean up the holder @@ -744,13 +741,12 @@ impl GenerationSchedule { self.chunk_map.insert(pos, holder); - log::warn!( + warn!( "Chunk {:?} reset to None and re-queued for regeneration (target: {:?})", - pos, - target_stage + pos, target_stage ); } else { - log::error!("Failed to find holder for failed chunk {:?}", pos); + error!("Failed to find holder for failed chunk {:?}", pos); } } } @@ -758,7 +754,7 @@ impl GenerationSchedule { } fn work(mut self, level: Arc) { - log::debug!( + debug!( "schedule thread start id: {:?} name: {}", thread::current().id(), thread::current().name().unwrap_or("unknown") @@ -773,7 +769,7 @@ impl GenerationSchedule { } if level.shut_down_chunk_system.load(Relaxed) { // Save all chunks BEFORE breaking the loop to ensure IO write thread processes them - log::info!("Saving chunks before shutdown..."); + info!("Saving chunks before shutdown..."); self.save_all_chunk(true); break; } @@ -783,7 +779,7 @@ impl GenerationSchedule { if level.shut_down_chunk_system.load(Relaxed) { // Don't process any more tasks, just break to save chunks self.queue.push(task); - log::info!("Shutdown detected during task processing, saving chunks..."); + info!("Shutdown detected during task processing, saving chunks..."); self.save_all_chunk(true); break 'out2; } @@ -821,7 +817,7 @@ impl GenerationSchedule { if self.io_read.send(node.pos).is_err() { // IO thread closed (likely due to shutdown), save and exit cleanly - log::info!("IO read thread closed, saving remaining chunks..."); + info!("IO read thread closed, saving remaining chunks..."); self.save_all_chunk(true); break 'out2; } @@ -982,7 +978,7 @@ impl GenerationSchedule { if self.generate.send((node.pos, cache, node.stage)).is_err() { // revert running task count increment and exit cleanly with save self.running_task_count = self.running_task_count.saturating_sub(1); - log::info!("Generation thread closed, saving remaining chunks..."); + info!("Generation thread closed, saving remaining chunks..."); self.save_all_chunk(true); break 'out2; } @@ -1014,7 +1010,7 @@ impl GenerationSchedule { } } } - log::info!( + info!( "schedule: waiting for {} generation tasks to finish", self.running_task_count ); @@ -1029,7 +1025,7 @@ impl GenerationSchedule { Err(_) => { wait_iterations += 1; if wait_iterations % 20 == 0 { - log::warn!( + warn!( "Still waiting for {} tasks to complete (waited {}ms)", self.running_task_count, wait_iterations * 50 @@ -1041,7 +1037,7 @@ impl GenerationSchedule { } if self.running_task_count > 0 { - log::warn!( + warn!( "Cancelling {} in-flight generation tasks", self.running_task_count ); @@ -1075,7 +1071,7 @@ impl GenerationSchedule { // Clean up any remaining graph structures let unreleased_count = self.graph.nodes.len(); if unreleased_count > 0 { - log::warn!( + warn!( "Cleaning up {} unreleased nodes from incomplete tasks", unreleased_count ); diff --git a/pumpkin-world/src/chunk_system/worker_logic.rs b/pumpkin-world/src/chunk_system/worker_logic.rs index 3d3f4cd8e9..01f741ac80 100644 --- a/pumpkin-world/src/chunk_system/worker_logic.rs +++ b/pumpkin-world/src/chunk_system/worker_logic.rs @@ -14,6 +14,7 @@ use pumpkin_data::chunk_gen_settings::GenerationSettings; use std::collections::hash_map::Entry; use std::sync::Arc; use std::sync::atomic::Ordering::Relaxed; +use tracing::{debug, error, warn}; pub enum RecvChunk { IO(Chunk), @@ -60,7 +61,7 @@ pub async fn io_read_work( lock: IOLock, ) { use crate::biome::hash_seed; - log::debug!("io read thread start"); + debug!("io read thread start"); let biome_mixer_seed = hash_seed(level.world_gen.random_config.seed); let dimension = &level.world_gen.dimension; let (t_send, mut t_recv) = tokio::sync::mpsc::channel(1); @@ -92,7 +93,7 @@ pub async fn io_read_work( let needs_relight = needs_relighting(&chunk, &level.lighting_config); if needs_relight { - log::debug!( + debug!( "Chunk {pos:?} has uniform lighting, downgrading to Features stage for relighting" ); @@ -147,7 +148,7 @@ pub async fn io_read_work( } LoadedData::Missing(_) => {} LoadedData::Error(_) => { - log::warn!("chunk data read error pos: {pos:?}. regenerating"); + warn!("chunk data read error pos: {pos:?}. regenerating"); } } @@ -168,7 +169,7 @@ pub async fn io_read_work( break; } } - log::debug!("io read thread stop"); + debug!("io read thread stop"); } pub async fn io_write_work(recv: AsyncRx>, level: Arc, lock: IOLock) { @@ -197,7 +198,7 @@ pub async fn io_write_work(recv: AsyncRx>, level: Arc>, level: Arc { - log::warn!( + warn!( "io_write: attempted to release missing lock entry for {:?}", i ); @@ -236,7 +237,7 @@ pub fn generation_work( let (pos, mut cache, stage) = match recv.recv() { Ok(data) => data, Err(_) => { - log::debug!("generation channel closed, exiting"); + debug!("generation channel closed, exiting"); break; } }; @@ -269,7 +270,7 @@ pub fn generation_work( .or_else(|| payload.downcast_ref::().map(|s| s.as_str())) .unwrap_or("Unknown panic payload"); - log::error!("Chunk generation FAILED at {pos:?} ({stage:?}): {msg}"); + error!("Chunk generation FAILED at {pos:?} ({stage:?}): {msg}"); // Send failure notification let _ = send.send(( diff --git a/pumpkin-world/src/data/player_data.rs b/pumpkin-world/src/data/player_data.rs index 2b5c3c7d1e..3cfb2d00fe 100644 --- a/pumpkin-world/src/data/player_data.rs +++ b/pumpkin-world/src/data/player_data.rs @@ -2,6 +2,7 @@ use pumpkin_nbt::compound::NbtCompound; use std::fs::{File, create_dir_all}; use std::io; use std::path::PathBuf; +use tracing::{debug, error}; use uuid::Uuid; /// Manages the storage and retrieval of player data from disk and memory cache. @@ -30,7 +31,7 @@ impl PlayerDataStorage { if !path.exists() && let Err(e) = create_dir_all(&path) { - log::error!( + error!( "Failed to create player data directory at {}: {e}", path.display() ); @@ -83,25 +84,25 @@ impl PlayerDataStorage { // If not in cache, load from disk let path = self.get_player_data_path(uuid); if !path.exists() { - log::debug!("No player data file found for {uuid}"); + debug!("No player data file found for {uuid}"); return Ok((false, NbtCompound::new())); } let file = match File::open(&path) { Ok(file) => file, Err(e) => { - log::error!("Failed to open player data file for {uuid}: {e}"); + error!("Failed to open player data file for {uuid}: {e}"); return Err(PlayerDataError::Io(e)); } }; match pumpkin_nbt::nbt_compress::read_gzip_compound_tag(file) { Ok(nbt) => { - log::debug!("Loaded player data for {uuid} from disk"); + debug!("Loaded player data for {uuid} from disk"); Ok((true, nbt)) } Err(e) => { - log::error!("Failed to read player data for {uuid}: {e}"); + error!("Failed to read player data for {uuid}: {e}"); Err(PlayerDataError::Nbt(e.to_string())) } } @@ -132,7 +133,7 @@ impl PlayerDataStorage { if let Some(parent) = path.parent() && let Err(e) = create_dir_all(parent) { - log::error!("Failed to create player data directory for {uuid}: {e}"); + error!("Failed to create player data directory for {uuid}: {e}"); return Err(PlayerDataError::Io(e)); } @@ -140,15 +141,15 @@ impl PlayerDataStorage { match File::create(&path) { Ok(file) => { if let Err(e) = pumpkin_nbt::nbt_compress::write_gzip_compound_tag(data, file) { - log::error!("Failed to write compressed player data for {uuid}: {e}"); + error!("Failed to write compressed player data for {uuid}: {e}"); Err(PlayerDataError::Nbt(e.to_string())) } else { - log::debug!("Saved player data for {uuid} to disk"); + debug!("Saved player data for {uuid} to disk"); Ok(()) } } Err(e) => { - log::error!("Failed to create player data file for {uuid}: {e}"); + error!("Failed to create player data file for {uuid}: {e}"); Err(PlayerDataError::Io(e)) } } diff --git a/pumpkin-world/src/generation/height_provider.rs b/pumpkin-world/src/generation/height_provider.rs index fca184a7f1..8a1cac0a61 100644 --- a/pumpkin-world/src/generation/height_provider.rs +++ b/pumpkin-world/src/generation/height_provider.rs @@ -5,6 +5,7 @@ use pumpkin_util::{ y_offset::YOffset, }; use serde::Deserialize; +use tracing::warn; #[derive(Deserialize)] #[serde(tag = "type")] @@ -76,7 +77,7 @@ impl TrapezoidHeightProvider { let j = self.max_inclusive.get_y(min_y as i16, height); if i > j { - log::warn!("Empty height range"); + warn!("Empty height range"); return i; } diff --git a/pumpkin-world/src/generation/structure/structures/mod.rs b/pumpkin-world/src/generation/structure/structures/mod.rs index 615eafc85b..180ab2ad8c 100644 --- a/pumpkin-world/src/generation/structure/structures/mod.rs +++ b/pumpkin-world/src/generation/structure/structures/mod.rs @@ -8,6 +8,7 @@ use pumpkin_util::{ math::{block_box::BlockBox, position::BlockPos, vector3::Vector3}, random::{RandomGenerator, RandomImpl, get_carver_seed, xoroshiro128::Xoroshiro}, }; +use tracing::debug; use crate::generation::structure::structures::stronghold::PieceWeight; use crate::generation::structure::structures::stronghold::StrongholdPieceType; @@ -319,7 +320,7 @@ impl StructurePiece { let block_pos = self.offset_pos(x, y, z); if !box_limit.contains_pos(&block_pos) { - log::debug!("Structure out of bounds"); + debug!("Structure out of bounds"); return Block::AIR.default_state; } @@ -339,7 +340,7 @@ impl StructurePiece { // Bounds and logic checks if !box_limit.contains_pos(&block_pos) { - log::debug!("Structure out of bounds"); + debug!("Structure out of bounds"); return; } diff --git a/pumpkin-world/src/level.rs b/pumpkin-world/src/level.rs index 383ac7ba60..ff7536285c 100644 --- a/pumpkin-world/src/level.rs +++ b/pumpkin-world/src/level.rs @@ -15,7 +15,6 @@ use crate::{ }; use crossbeam::channel::Sender; use dashmap::DashMap; -use log::trace; use pumpkin_config::{chunk::ChunkConfig, lighting::LightingEngineConfig, world::LevelConfig}; use pumpkin_data::biome::Biome; use pumpkin_data::dimension::Dimension; @@ -35,6 +34,7 @@ use std::{ }; use tokio::time::timeout; use tokio_util::sync::CancellationToken; +use tracing::{debug, error, info, trace, warn}; // use tokio::runtime::Handle; use tokio::{ select, @@ -278,7 +278,7 @@ impl Level { pub async fn shutdown(&self) { let world_id = self.level_folder.root_folder.display(); - log::info!("Saving level ({})...", world_id); + info!("Saving level ({})...", world_id); self.cancel_token.cancel(); self.shut_down_chunk_system.store(true, Ordering::Relaxed); self.level_channel.notify(); @@ -292,7 +292,7 @@ impl Level { }; let handle_count = handles.len(); - log::info!("Joining {} threads for {}...", handle_count, world_id); + info!("Joining {} threads for {}...", handle_count, world_id); let join_task = tokio::task::spawn_blocking(move || { let mut failed_count = 0; for handle in handles.into_iter() { @@ -306,25 +306,24 @@ impl Level { match timeout(Duration::from_secs(3), join_task).await { Ok(Ok(failed_count)) => { if failed_count > 0 { - log::warn!( + warn!( "{} threads failed to join properly for {}.", - failed_count, - world_id + failed_count, world_id ); } } Ok(Err(_)) => { - log::warn!("Thread join task panicked for {}.", world_id); + warn!("Thread join task panicked for {}.", world_id); } Err(_) => { - log::warn!("Timed out waiting for threads to join for {}.", world_id); + warn!("Timed out waiting for threads to join for {}.", world_id); } } self.tasks.wait().await; self.chunk_system_tasks.wait().await; - log::info!("Flushing data to disk for {}...", world_id); + info!("Flushing data to disk for {}...", world_id); self.chunk_saver.block_and_await_ongoing_tasks().await; self.entity_saver.block_and_await_ongoing_tasks().await; @@ -359,7 +358,7 @@ impl Level { pub fn list_cached(&self) { for entry in self.loaded_chunks.iter() { - log::debug!("In map: {:?}", entry.key()); + debug!("In map: {:?}", entry.key()); } } @@ -441,7 +440,7 @@ impl Level { let level = self.clone(); self.spawn_task(async move { - log::debug!("Writing {} entity chunks to disk", chunks_to_process.len()); + debug!("Writing {} entity chunks to disk", chunks_to_process.len()); level.write_entity_chunks(chunks_to_process).await; }); } @@ -734,7 +733,7 @@ impl Level { .save_chunks(&level_folder, chunks_to_write) .await { - log::error!("Failed writing Chunk to disk {error}"); + error!("Failed writing Chunk to disk {error}"); } } @@ -751,7 +750,7 @@ impl Level { .save_chunks(&level_folder, chunks_to_write) .await { - log::error!("Failed writing Chunk to disk {error}"); + error!("Failed writing Chunk to disk {error}"); } } diff --git a/pumpkin-world/src/poi/mod.rs b/pumpkin-world/src/poi/mod.rs index 66a8adb72a..4b5a91ac03 100644 --- a/pumpkin-world/src/poi/mod.rs +++ b/pumpkin-world/src/poi/mod.rs @@ -1,6 +1,7 @@ use std::collections::HashMap; use std::io::{Cursor, Read, Write}; use std::path::{Path, PathBuf}; +use tracing::{info, warn}; use flate2::Compression; use flate2::read::ZlibDecoder; @@ -356,7 +357,7 @@ impl PoiRegion { } } Err(e) => { - log::warn!("Failed to parse POI chunk at index {index}: {e}"); + warn!("Failed to parse POI chunk at index {index}: {e}"); } } } @@ -398,7 +399,7 @@ impl PoiStorage { let path = self.region_path(rx, rz); let region = PoiRegion::load(&path).unwrap_or_else(|e| { if path.exists() { - log::warn!("Failed to load POI region {}: {}", path.display(), e); + warn!("Failed to load POI region {}: {}", path.display(), e); } PoiRegion::new() }); @@ -485,7 +486,7 @@ impl PoiStorage { } if saved > 0 { - log::info!("Saved {saved} POI region(s)"); + info!("Saved {saved} POI region(s)"); } Ok(()) } diff --git a/pumpkin-world/src/world_info/anvil.rs b/pumpkin-world/src/world_info/anvil.rs index e7f04dbed3..309beb5a52 100644 --- a/pumpkin-world/src/world_info/anvil.rs +++ b/pumpkin-world/src/world_info/anvil.rs @@ -4,6 +4,7 @@ use std::{ path::Path, time::{SystemTime, UNIX_EPOCH}, }; +use tracing::error; use flate2::{Compression, read::GzDecoder, write::GzEncoder}; use serde::{Deserialize, Serialize}; @@ -38,7 +39,7 @@ fn check_file_data_version(raw_nbt: &[u8]) -> Result<(), WorldInfoError> { let info: LevelDat = pumpkin_nbt::from_bytes(Cursor::new(raw_nbt)) .map_err(|e|{ - log::error!("The level.dat file does not have a data version! This means it is either corrupt or very old (read unsupported)"); + error!("The level.dat file does not have a data version! This means it is either corrupt or very old (read unsupported)"); WorldInfoError::DeserializationError(e.to_string())})?; let data_version = info.data.data_version; @@ -65,7 +66,7 @@ fn check_file_level_version(raw_nbt: &[u8]) -> Result<(), WorldInfoError> { let info: LevelDat = pumpkin_nbt::from_bytes(Cursor::new(raw_nbt)) .map_err(|e|{ - log::error!("The level.dat file does not have a level version! This means it is either corrupt or very old (read unsupported)"); + error!("The level.dat file does not have a level version! This means it is either corrupt or very old (read unsupported)"); WorldInfoError::DeserializationError(e.to_string())})?; let level_version = info.data.version; diff --git a/pumpkin/Cargo.toml b/pumpkin/Cargo.toml index 6a19f8d843..ebfbe53120 100644 --- a/pumpkin/Cargo.toml +++ b/pumpkin/Cargo.toml @@ -27,7 +27,6 @@ pumpkin-data.workspace = true pumpkin-protocol.workspace = true pumpkin-macros.workspace = true -log.workspace = true crossbeam.workspace = true uuid.workspace = true tokio = { workspace = true, features = [ diff --git a/pumpkin/src/block/blocks/command.rs b/pumpkin/src/block/blocks/command.rs index e90cb9689d..1955f17925 100644 --- a/pumpkin/src/block/blocks/command.rs +++ b/pumpkin/src/block/blocks/command.rs @@ -1,6 +1,5 @@ use std::sync::{Arc, atomic::Ordering}; -use log::warn; use pumpkin_data::{ Block, FacingExt, block_properties::{BlockProperties, CommandBlockLikeProperties, Facing}, @@ -11,6 +10,7 @@ use pumpkin_world::{ block::entities::{BlockEntity, command_block::CommandBlockEntity}, tick::TickPriority, }; +use tracing::warn; use crate::{ block::{ diff --git a/pumpkin/src/block/blocks/jukebox.rs b/pumpkin/src/block/blocks/jukebox.rs index ebf31d3397..f08ff81859 100644 --- a/pumpkin/src/block/blocks/jukebox.rs +++ b/pumpkin/src/block/blocks/jukebox.rs @@ -23,6 +23,8 @@ use pumpkin_world::block::entities::jukebox::JukeboxBlockEntity; use pumpkin_world::world::BlockFlags; use rand::{RngExt, rng}; +use tracing::error; + #[pumpkin_block("minecraft:jukebox")] pub struct JukeboxBlock; @@ -147,7 +149,7 @@ impl BlockBehaviour for JukeboxBlock { }; let Some(jukebox_song) = JukeboxSong::from_name(song_name) else { - log::error!("Jukebox playable song not registered: {song_name}"); + error!("Jukebox playable song not registered: {song_name}"); return BlockActionResult::PassToDefaultBlockAction; }; diff --git a/pumpkin/src/command/args/entities.rs b/pumpkin/src/command/args/entities.rs index 31d5f733d0..24935ab505 100644 --- a/pumpkin/src/command/args/entities.rs +++ b/pumpkin/src/command/args/entities.rs @@ -11,6 +11,7 @@ use pumpkin_data::entity::EntityType; use pumpkin_nbt::compound::NbtCompound; use pumpkin_protocol::java::client::play::{ArgumentType, SuggestionProviders}; use pumpkin_util::GameMode; +use tracing::debug; use uuid::Uuid; use super::super::args::ArgumentConsumer; @@ -265,7 +266,7 @@ impl ArgumentConsumer for EntitiesArgumentConsumer { let entity_selector = match s.parse::() { Ok(selector) => selector, Err(e) => { - log::debug!("Failed to parse target selector '{s}': {e}"); + debug!("Failed to parse target selector '{s}': {e}"); return Box::pin(async move { None }); // Return a Future resolving to None } }; diff --git a/pumpkin/src/command/args/entity.rs b/pumpkin/src/command/args/entity.rs index c865d3dcb1..3eecb99faf 100644 --- a/pumpkin/src/command/args/entity.rs +++ b/pumpkin/src/command/args/entity.rs @@ -8,6 +8,7 @@ use crate::command::tree::RawArgs; use crate::entity::EntityBase; use crate::server::Server; use pumpkin_protocol::java::client::play::{ArgumentType, SuggestionProviders}; +use tracing::debug; use super::super::args::ArgumentConsumer; use super::{Arg, DefaultNameArgConsumer, FindArg, GetClientSideArgParser}; @@ -48,13 +49,13 @@ impl ArgumentConsumer for EntityArgumentConsumer { let entity_selector = match s.parse::() { Ok(selector) => selector, Err(e) => { - log::debug!("Failed to parse target selector '{s}': {e}"); + debug!("Failed to parse target selector '{s}': {e}"); return Box::pin(async move { None }); } }; if entity_selector.get_limit() > 1 { - log::debug!("Target selector '{s}' has limit > 1, expected single entity"); + debug!("Target selector '{s}' has limit > 1, expected single entity"); return Box::pin(async move { None }); } diff --git a/pumpkin/src/command/args/textcomponent.rs b/pumpkin/src/command/args/textcomponent.rs index dc9f7b8664..7f1904ae13 100644 --- a/pumpkin/src/command/args/textcomponent.rs +++ b/pumpkin/src/command/args/textcomponent.rs @@ -5,6 +5,7 @@ use crate::command::tree::RawArgs; use crate::server::Server; use pumpkin_protocol::java::client::play::{ArgumentType, SuggestionProviders}; use pumpkin_util::text::TextComponent; +use tracing::debug; pub struct TextComponentArgConsumer; @@ -62,7 +63,7 @@ impl FindArg<'_> for TextComponentArgConsumer { fn parse_text_component(input: &str) -> Option { let result = serde_json::from_str(input); if let Err(e) = result { - log::debug!("Failed to parse text component: {e}"); + debug!("Failed to parse text component: {e}"); None } else { result.unwrap() diff --git a/pumpkin/src/command/commands/transfer.rs b/pumpkin/src/command/commands/transfer.rs index 93a754caff..679b170835 100644 --- a/pumpkin/src/command/commands/transfer.rs +++ b/pumpkin/src/command/commands/transfer.rs @@ -1,6 +1,7 @@ use pumpkin_protocol::codec::var_int::VarInt; use pumpkin_protocol::java::client::play::CTransfer; use pumpkin_util::text::TextComponent; +use tracing::info; use crate::command::CommandResult; use crate::command::args::bounded_num::BoundedNumArgumentConsumer; @@ -53,7 +54,7 @@ impl CommandExecutor for TargetSelfExecutor { if let CommandSender::Player(player) = sender { let name = &player.gameprofile.name; - log::info!("[{name}: Transferring {name} to {hostname}:{port}]"); + info!("[{name}: Transferring {name} to {hostname}:{port}]"); player .client .enqueue_packet(&CTransfer::new(hostname, VarInt(port))) @@ -106,7 +107,7 @@ impl CommandExecutor for TargetPlayerExecutor { p.client .enqueue_packet(&CTransfer::new(hostname, VarInt(port))) .await; - log::info!( + info!( "[{sender}: Transferring {} to {hostname}:{port}]", p.gameprofile.name ); diff --git a/pumpkin/src/command/dispatcher.rs b/pumpkin/src/command/dispatcher.rs index fda4e6392a..d6146fd7df 100644 --- a/pumpkin/src/command/dispatcher.rs +++ b/pumpkin/src/command/dispatcher.rs @@ -1,6 +1,7 @@ use pumpkin_protocol::java::client::play::CommandSuggestion; use pumpkin_util::text::TextComponent; use rustc_hash::FxHashMap; +use tracing::{debug, error, warn}; use super::args::ConsumedArgs; @@ -33,19 +34,19 @@ impl CommandError { pub fn into_component(self, cmd: &str) -> TextComponent { match self { InvalidConsumption(s) => { - log::error!( + error!( "Error while parsing command \"{cmd}\": {s:?} was consumed, but couldn't be parsed" ); TextComponent::text("Internal error (See logs for details)") } InvalidRequirement => { - log::error!( + error!( "Error while parsing command \"{cmd}\": a requirement that was expected was not met." ); TextComponent::text("Internal error (See logs for details)") } PermissionDenied => { - log::warn!("Permission denied for command \"{cmd}\""); + warn!("Permission denied for command \"{cmd}\""); TextComponent::text( "I'm sorry, but you do not have permission to perform this command. Please contact the server administrator if you believe this is an error.", ) @@ -110,30 +111,30 @@ impl CommandDispatcher { .await { Err(InvalidConsumption(s)) => { - log::debug!( + debug!( "Error while parsing command \"{cmd}\": {s:?} was consumed, but couldn't be parsed" ); return Vec::new(); } Err(InvalidRequirement) => { - log::debug!( + debug!( "Error while parsing command \"{cmd}\": a requirement that was expected was not met." ); return Vec::new(); } Err(PermissionDenied) => { - log::debug!("Permission denied for command \"{cmd}\""); + debug!("Permission denied for command \"{cmd}\""); return Vec::new(); } Err(CommandFailed(_)) => { - log::debug!("Command failed"); + debug!("Command failed"); return Vec::new(); } Ok(Some(new_suggestions)) => { suggestions.extend(new_suggestions); } Ok(None) => { - log::debug!("Command none"); + debug!("Command none"); } } } @@ -286,7 +287,7 @@ impl CommandDispatcher { Command::Tree(tree) => Ok(tree), Command::Alias(target) => { let Some(Command::Tree(tree)) = self.commands.get(target) else { - log::error!( + error!( "Error while parsing command alias \"{key}\": pointing to \"{target}\" which is not a valid tree" ); return Err(CommandFailed(TextComponent::text( @@ -314,7 +315,7 @@ impl CommandDispatcher { executor.execute(src, server, &parsed_args).await?; Ok(true) } else { - log::debug!( + debug!( "Error while parsing command: {raw_args:?} was not consumed, but should have been" ); Ok(false) @@ -322,7 +323,7 @@ impl CommandDispatcher { } NodeType::Literal { string, .. } => { if raw_args.pop() != Some(string) { - log::debug!("Error while parsing command: {raw_args:?}: expected {string}"); + debug!("Error while parsing command: {raw_args:?}: expected {string}"); return Ok(false); } } @@ -330,7 +331,7 @@ impl CommandDispatcher { if let Some(consumed) = consumer.consume(src, server, raw_args).await { parsed_args.insert(name, consumed); } else { - log::debug!( + debug!( "Error while parsing command: {raw_args:?}: cannot parse argument {name}" ); return Ok(false); @@ -338,7 +339,7 @@ impl CommandDispatcher { } NodeType::Require { predicate, .. } => { if !predicate(src) { - log::debug!( + debug!( "Error while parsing command: {raw_args:?} does not meet the requirement" ); return Ok(false); @@ -347,9 +348,7 @@ impl CommandDispatcher { } } - log::debug!( - "Error while parsing command: {raw_args:?} was not consumed, but should have been" - ); + debug!("Error while parsing command: {raw_args:?} was not consumed, but should have been"); Ok(false) } diff --git a/pumpkin/src/command/mod.rs b/pumpkin/src/command/mod.rs index c5ea6ae827..6c27029edd 100644 --- a/pumpkin/src/command/mod.rs +++ b/pumpkin/src/command/mod.rs @@ -70,7 +70,8 @@ impl fmt::Display for CommandSender { impl CommandSender { pub async fn send_message(&self, text: TextComponent) { match self { - Self::Console => log::info!("{}", text.to_pretty_console()), + #[allow(clippy::print_stdout)] + Self::Console => println!("{}", text.to_pretty_console()), Self::Player(c) => c.send_system_message(&text).await, Self::Rcon(s) => s.lock().await.push(text.to_pretty_console()), Self::CommandBlock(block_entity, _) => { diff --git a/pumpkin/src/data/mod.rs b/pumpkin/src/data/mod.rs index 201668cb24..6d53aeba16 100644 --- a/pumpkin/src/data/mod.rs +++ b/pumpkin/src/data/mod.rs @@ -2,6 +2,7 @@ use std::{env, fs, path::Path}; use serde::{Deserialize, Serialize}; use tokio::sync::RwLock; +use tracing::{debug, error, warn}; const DATA_FOLDER: &str = "data/"; @@ -41,7 +42,7 @@ pub trait LoadJSONConfiguration { let exe_dir = env::current_dir().unwrap(); let data_dir = exe_dir.join(DATA_FOLDER); if !data_dir.exists() { - log::debug!("creating new data root folder"); + debug!("creating new data root folder"); fs::create_dir(&data_dir).expect("Failed to create data root folder"); } let path = data_dir.join(Self::get_path()); @@ -60,7 +61,7 @@ pub trait LoadJSONConfiguration { let content = Self::default(); if let Err(err) = fs::write(&path, serde_json::to_string_pretty(&content).unwrap()) { - log::error!( + error!( "Couldn't write default data config to {}. Reason: {err}. This is probably caused by a config update. Just delete the old data config and restart.", path.display(), ); @@ -86,7 +87,7 @@ pub trait SaveJSONConfiguration: LoadJSONConfiguration { let exe_dir = env::current_dir().unwrap(); let data_dir = exe_dir.join(DATA_FOLDER); if !data_dir.exists() { - log::debug!("creating new data root folder"); + debug!("creating new data root folder"); fs::create_dir(&data_dir).expect("Failed to create data root folder"); } let path = data_dir.join(Self::get_path()); @@ -94,7 +95,7 @@ pub trait SaveJSONConfiguration: LoadJSONConfiguration { let content = match serde_json::to_string_pretty(self) { Ok(content) => content, Err(err) => { - log::warn!( + warn!( "Couldn't serialize operator data config to {}. Reason: {err}", path.display() ); @@ -103,7 +104,7 @@ pub trait SaveJSONConfiguration: LoadJSONConfiguration { }; if let Err(err) = std::fs::write(&path, content) { - log::warn!( + warn!( "Couldn't write operator config to {}. Reason: {err}", path.display() ); diff --git a/pumpkin/src/data/player_server.rs b/pumpkin/src/data/player_server.rs index 123acc78d3..24fb1190b5 100644 --- a/pumpkin/src/data/player_server.rs +++ b/pumpkin/src/data/player_server.rs @@ -11,6 +11,8 @@ use std::{ path::PathBuf, time::{Duration, Instant}, }; +use tracing::{debug, error}; + /// Helper for managing player data in the server context. /// /// This struct provides server-wide access to the `PlayerDataStorage` and @@ -81,7 +83,7 @@ impl ServerPlayerData { // Save to disk periodically to prevent data loss on server crash if let Err(e) = self.storage.save_player_data(&player.gameprofile.id, nbt) { - log::error!( + error!( "Failed to save player data for {}: {e}", player.gameprofile.id, ); @@ -89,7 +91,7 @@ impl ServerPlayerData { } } - log::debug!("Periodic player data save completed"); + debug!("Periodic player data save completed"); } Ok(()) @@ -110,7 +112,7 @@ impl ServerPlayerData { } } - log::debug!("Saved data for {total_players} online players"); + debug!("Saved data for {total_players} online players"); Ok(()) } @@ -138,10 +140,10 @@ impl ServerPlayerData { Err(e) => { if self.storage.is_save_enabled() { // Only log as error if player data saving is enabled - log::error!("Error loading player data for {uuid}: {e}"); + error!("Error loading player data for {uuid}: {e}"); } else { // Otherwise just log as info since it's expected - log::debug!("Not loading player data for {uuid} (saving disabled)"); + debug!("Not loading player data for {uuid} (saving disabled)"); } // Continue with default data even if there's an error Ok(None) diff --git a/pumpkin/src/entity/effect/mod.rs b/pumpkin/src/entity/effect/mod.rs index 5ea57f4586..c7a8f0c70b 100644 --- a/pumpkin/src/entity/effect/mod.rs +++ b/pumpkin/src/entity/effect/mod.rs @@ -2,6 +2,7 @@ use crate::entity::{NBTInitFuture, NBTStorage, NBTStorageInit, NbtFuture}; use pumpkin_data::effect::StatusEffect; use pumpkin_nbt::compound::NbtCompound; use pumpkin_nbt::tag::NbtTag; +use tracing::warn; impl NBTStorage for pumpkin_data::potion::Effect { fn write_nbt<'a>(&'a self, nbt: &'a mut NbtCompound) -> NbtFuture<'a, ()> { @@ -30,15 +31,15 @@ impl NBTStorageInit for pumpkin_data::potion::Effect { { Box::pin(async move { let Some(effect_id) = nbt.get_string("id") else { - log::warn!("Unable to read effect. Effect id is not present"); + warn!("Unable to read effect. Effect id is not present"); return None; }; let Some(effect_type) = StatusEffect::from_minecraft_name(effect_id) else { - log::warn!("Unable to read effect. Unknown effect type: {effect_id}"); + warn!("Unable to read effect. Unknown effect type: {effect_id}"); return None; }; let Some(show_icon) = nbt.get_byte("show_icon") else { - log::warn!("Unable to read effect. Show icon is not present"); + warn!("Unable to read effect. Show icon is not present"); return None; }; let amplifier = nbt.get_int("amplifier").unwrap_or(0) as u8; diff --git a/pumpkin/src/entity/living.rs b/pumpkin/src/entity/living.rs index dc04288bbd..313b66942e 100644 --- a/pumpkin/src/entity/living.rs +++ b/pumpkin/src/entity/living.rs @@ -15,6 +15,7 @@ use std::sync::atomic::{ Ordering::{Relaxed, SeqCst}, }; use std::{collections::HashMap, sync::atomic::AtomicI32}; +use tracing::warn; use super::{Entity, NBTStorage}; use super::{EntityBase, NBTStorageInit}; @@ -1194,7 +1195,7 @@ impl NBTStorage for LivingEntity { if let NbtTag::Compound(effect_nbt) = effect { let effect = Effect::create_from_nbt(&mut effect_nbt.clone()).await; if effect.is_none() { - log::warn!("Unable to read effect from nbt"); + warn!("Unable to read effect from nbt"); continue; } let mut effect = effect.unwrap(); diff --git a/pumpkin/src/entity/player.rs b/pumpkin/src/entity/player.rs index cc24f75d7d..8f5ee158e7 100644 --- a/pumpkin/src/entity/player.rs +++ b/pumpkin/src/entity/player.rs @@ -11,7 +11,6 @@ use std::time::{Duration, Instant}; use arc_swap::ArcSwap; use crossbeam::atomic::AtomicCell; use crossbeam::channel::Receiver; -use log::warn; use pumpkin_data::dimension::Dimension; use pumpkin_data::meta_data_type::MetaDataType; use pumpkin_data::tracked_data::TrackedData; @@ -27,6 +26,7 @@ use pumpkin_world::chunk::{ChunkData, ChunkEntityData}; use pumpkin_world::inventory::Inventory; use tokio::sync::Mutex; use tokio::task::JoinHandle; +use tracing::{debug, warn}; use uuid::Uuid; use pumpkin_data::block_properties::{BlockProperties, EnumVariants, HorizontalFacing}; @@ -590,7 +590,7 @@ impl Player { // Given enough time, all of these chunks will be in memory. let radial_chunks = cylindrical.all_chunks_within(); - log::debug!( + debug!( "Removing player {}, unwatching {} chunks", self.gameprofile.name, radial_chunks.len() @@ -605,7 +605,7 @@ impl Player { // Remove left over entries from all possiblily loaded chunks level.clean_memory(); - log::debug!( + debug!( "Removed player id {} from world {} ({} chunks remain cached)", self.gameprofile.name, self.world().get_world_name(), @@ -882,10 +882,9 @@ impl Player { f64::from(pos.0.y) + 0.1, f64::from(pos.0.z) + 0.5, ); - log::debug!( + debug!( "Returning forced spawn point at {:?}, dimension: {:?}", - position, - respawn_point.dimension + position, respawn_point.dimension ); return Some(CalculatedRespawnPoint { position, @@ -3475,9 +3474,9 @@ impl InventoryPlayer for Player { fn award_experience(&self, amount: i32) -> PlayerFuture<'_, ()> { Box::pin(async move { - log::debug!("Player::award_experience called with amount={amount}"); + debug!("Player::award_experience called with amount={amount}"); if amount > 0 { - log::debug!("Player: adding {amount} experience points"); + debug!("Player: adding {amount} experience points"); self.add_experience_points(amount).await; } }) diff --git a/pumpkin/src/error.rs b/pumpkin/src/error.rs index f16506272a..f2e52eb54b 100644 --- a/pumpkin/src/error.rs +++ b/pumpkin/src/error.rs @@ -1,17 +1,19 @@ -use log::log; use pumpkin_inventory::InventoryError; use pumpkin_protocol::ser::ReadingError; use pumpkin_world::data::player_data::PlayerDataError; use std::fmt::Display; +use tracing::Level; + +use crate::log_at_level; pub trait PumpkinError: Send + std::error::Error + Display { fn is_kick(&self) -> bool; fn log(&self) { - log!(self.severity(), "{self}"); + log_at_level!(self.severity(), "{self}"); } - fn severity(&self) -> log::Level; + fn severity(&self) -> Level; fn client_kick_reason(&self) -> Option; } @@ -32,7 +34,7 @@ impl PumpkinError for InventoryError { LockError | OutOfOrderDragging | MultiplePlayersDragging => false, } } - fn severity(&self) -> log::Level { + fn severity(&self) -> Level { use InventoryError::{ ClosedContainerInteract, InvalidPacket, InvalidSlot, LockError, MultiplePlayersDragging, OutOfOrderDragging, PermissionError, @@ -42,9 +44,9 @@ impl PumpkinError for InventoryError { | InvalidSlot | ClosedContainerInteract(..) | InvalidPacket - | PermissionError => log::Level::Error, - OutOfOrderDragging => log::Level::Info, - MultiplePlayersDragging => log::Level::Warn, + | PermissionError => Level::ERROR, + OutOfOrderDragging => Level::INFO, + MultiplePlayersDragging => Level::WARN, } } @@ -58,8 +60,8 @@ impl PumpkinError for ReadingError { true } - fn severity(&self) -> log::Level { - log::Level::Error + fn severity(&self) -> Level { + Level::ERROR } fn client_kick_reason(&self) -> Option { @@ -72,8 +74,8 @@ impl PumpkinError for PlayerDataError { false } - fn severity(&self) -> log::Level { - log::Level::Warn + fn severity(&self) -> Level { + Level::WARN } fn client_kick_reason(&self) -> Option { diff --git a/pumpkin/src/lib.rs b/pumpkin/src/lib.rs index ed654c3f83..3545316bce 100644 --- a/pumpkin/src/lib.rs +++ b/pumpkin/src/lib.rs @@ -8,7 +8,6 @@ use crate::net::java::{JavaClient, PacketHandlerResult}; use crate::net::{ClientPlatform, DisconnectReason}; use crate::net::{lan_broadcast::LANBroadcast, query, rcon::RCONServer}; use crate::server::{Server, ticker::Ticker}; -use log::LevelFilter; use plugin::server::server_command::ServerCommandEvent; use pumpkin_config::{AdvancedConfiguration, BasicConfiguration}; use pumpkin_macros::send_cancellable; @@ -29,6 +28,8 @@ use tokio::sync::Mutex; use tokio::time::sleep; use tokio_util::sync::CancellationToken; use tokio_util::task::TaskTracker; +use tracing::{debug, error, info, warn}; +use tracing_subscriber::filter::LevelFilter; use tracing_subscriber::layer::SubscriberExt; use tracing_subscriber::util::SubscriberInitExt; @@ -44,7 +45,13 @@ pub mod plugin; pub mod server; pub mod world; -pub type LoggerOption = Option<(ReadlineLogWrapper, LevelFilter)>; +pub struct LoggingConfig { + pub color: bool, + pub threads: bool, + pub timestamp: bool, +} + +pub type LoggerOption = Option<(ReadlineLogWrapper, LevelFilter, LoggingConfig)>; pub static LOGGER_IMPL: LazyLock>> = LazyLock::new(|| Arc::new(OnceLock::new())); @@ -59,16 +66,16 @@ pub fn init_logger(advanced_config: &AdvancedConfiguration) { .as_deref() .map(LevelFilter::from_str) .and_then(Result::ok) - .unwrap_or(LevelFilter::Info); + .unwrap_or(LevelFilter::INFO); let env_filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| { let level_str = match level { - LevelFilter::Off => "off", - LevelFilter::Error => "error", - LevelFilter::Warn => "warn", - LevelFilter::Info => "info", - LevelFilter::Debug => "debug", - LevelFilter::Trace => "trace", + LevelFilter::OFF => "off", + LevelFilter::ERROR => "error", + LevelFilter::WARN => "warn", + LevelFilter::INFO => "info", + LevelFilter::DEBUG => "debug", + LevelFilter::TRACE => "trace", }; EnvFilter::new(level_str) }); @@ -112,7 +119,7 @@ pub fn init_logger(advanced_config: &AdvancedConfiguration) { let fmt_layer = fmt::layer() .with_writer(std::sync::Mutex::new(logger)) .with_ansi(advanced_config.logging.color) - .with_target(false) + .with_target(true) .with_thread_names(advanced_config.logging.threads) .with_thread_ids(advanced_config.logging.threads); @@ -140,7 +147,13 @@ pub fn init_logger(advanced_config: &AdvancedConfiguration) { } } - (ReadlineLogWrapper::new(rl), level) + let logging_config = LoggingConfig { + color: advanced_config.logging.color, + threads: advanced_config.logging.threads, + timestamp: advanced_config.logging.timestamp, + }; + + (ReadlineLogWrapper::new(rl), level, logging_config) }); assert!( @@ -175,6 +188,9 @@ pub struct PumpkinServer { } impl PumpkinServer { + pub fn log_info(&self, message: &str) { + tracing::info!(target: "plugin", "{}", message); + } #[expect(clippy::if_then_some_else_none)] pub async fn new( basic_config: BasicConfiguration, @@ -186,13 +202,13 @@ impl PumpkinServer { let rcon = server.advanced_config.networking.rcon.clone(); if server.advanced_config.commands.use_console - && let Some((wrapper, _)) = LOGGER_IMPL.wait() + && let Some((wrapper, _, _)) = LOGGER_IMPL.wait() { if let Some(rl) = wrapper.take_readline() { setup_console(rl, server.clone()); } else { if server.advanced_config.commands.use_tty { - log::warn!( + warn!( "The input is not a TTY; falling back to simple logger and ignoring `use_tty` setting" ); } @@ -201,7 +217,7 @@ impl PumpkinServer { } if rcon.enabled { - log::warn!( + warn!( "RCON is enabled, but it's highly insecure as it transmits passwords and commands in plain text. This makes it vulnerable to interception and exploitation by anyone on the network" ); let rcon_server = server.clone(); @@ -217,25 +233,21 @@ impl PumpkinServer { Ok(l) => l, Err(e) => match e.kind() { ErrorKind::AddrInUse => { - log::error!("Error: Address {address} is already in use."); - log::error!( - "Make sure another instance of the server isn't already running" - ); + error!("Error: Address {address} is already in use."); + error!("Make sure another instance of the server isn't already running"); std::process::exit(1); } ErrorKind::PermissionDenied => { - log::error!("Error: Permission denied when binding to {address}."); - log::error!("You might need sudo/admin privileges to use ports below 1024"); + error!("Error: Permission denied when binding to {address}."); + error!("You might need sudo/admin privileges to use ports below 1024"); std::process::exit(1); } ErrorKind::AddrNotAvailable => { - log::error!( - "Error: The address {address} is not available on this machine" - ); + error!("Error: The address {address} is not available on this machine"); std::process::exit(1); } _ => { - log::error!("Failed to start TcpListener on {address}: {e}"); + error!("Failed to start TcpListener on {address}: {e}"); std::process::exit(1); } }, @@ -246,7 +258,7 @@ impl PumpkinServer { .expect("Unable to get the address of the server!"); if server.advanced_config.networking.query.enabled { - log::info!("Query protocol is enabled. Starting..."); + info!("Query protocol is enabled. Starting..."); server.spawn_task(query::start_query_handler( server.clone(), server.advanced_config.networking.query.address, @@ -254,7 +266,7 @@ impl PumpkinServer { } if server.advanced_config.networking.lan_broadcast.enabled { - log::info!("LAN broadcast is enabled. Starting..."); + info!("LAN broadcast is enabled. Starting..."); let lan_broadcast = LANBroadcast::new( &server.advanced_config.networking.lan_broadcast, @@ -303,15 +315,15 @@ impl PumpkinServer { .set_server(self.server.clone()) .await; if let Err(err) = self.server.plugin_manager.load_plugins().await { - log::error!("{err}"); + error!("{err}"); } } pub async fn unload_plugins(&self) { if let Err(err) = self.server.plugin_manager.unload_all_plugins().await { - log::error!("Error unloading plugins: {err}"); + error!("Error unloading plugins: {err}"); } else { - log::info!("All plugins unloaded successfully"); + info!("All plugins unloaded successfully"); } } @@ -329,7 +341,7 @@ impl PumpkinServer { } } - log::info!("Stopped accepting incoming connections"); + info!("Stopped accepting incoming connections"); if let Err(e) = self .server @@ -337,7 +349,7 @@ impl PumpkinServer { .save_all_players(&self.server) .await { - log::error!("Error saving all players during shutdown: {e}"); + error!("Error saving all players during shutdown: {e}"); } let kick_message = TextComponent::text("Server stopped"); @@ -347,20 +359,20 @@ impl PumpkinServer { .await; } - log::info!("Ending player tasks"); + info!("Ending player tasks"); tasks.close(); tasks.wait().await; self.unload_plugins().await; - log::info!("Starting save."); + info!("Starting save."); self.server.shutdown().await; - log::info!("Completed save!"); + info!("Completed save!"); - if let Some((wrapper, _)) = LOGGER_IMPL.wait() + if let Some((wrapper, _, _)) = LOGGER_IMPL.wait() && let Some(rl) = wrapper.take_readline() { let _ = rl; @@ -382,7 +394,7 @@ impl PumpkinServer { match tcp_result { Ok((connection, client_addr)) => { if let Err(e) = connection.set_nodelay(true) { - log::warn!("Failed to set TCP_NODELAY: {e}"); + warn!("Failed to set TCP_NODELAY: {e}"); } let client_id = *master_client_id_counter; @@ -393,7 +405,7 @@ impl PumpkinServer { } else { format!("{client_addr}") }; - log::debug!("Accepted connection from Java Edition: {formatted_address} (id {client_id})"); + debug!("Accepted connection from Java Edition: {formatted_address} (id {client_id})"); let server_clone = self.server.clone(); tasks.spawn(async move { @@ -425,7 +437,7 @@ impl PumpkinServer { if let Err(e) = server_clone.player_data_storage .handle_player_leave(&player) .await { - log::error!("Failed to save player data on disconnect: {e}"); + error!("Failed to save player data on disconnect: {e}"); } } }, @@ -433,7 +445,7 @@ impl PumpkinServer { }); } Err(e) => { - log::error!("Failed to accept Java client connection: {e}"); + error!("Failed to accept Java client connection: {e}"); sleep(Duration::from_millis(50)).await; } } @@ -444,7 +456,7 @@ impl PumpkinServer { match udp_result { Ok((len, client_addr)) => { if len == 0 { - log::warn!("Received empty UDP packet from {client_addr}"); + warn!("Received empty UDP packet from {client_addr}"); } else { let id = udp_buf[0]; let is_online = id & 128 != 0; @@ -484,7 +496,7 @@ impl PumpkinServer { } // Since all packets go over this match statement, there should be not waiting Err(e) => { - log::error!("{e}"); + error!("{e}"); } } }, @@ -513,7 +525,7 @@ fn setup_stdin_console(server: Arc) { break; } if line.is_empty() || line.as_bytes()[line.len() - 1] != b'\n' { - log::warn!("Console command was not terminated with a newline"); + warn!("Console command was not terminated with a newline"); } rt.block_on(tx.send(line.trim().to_string())) .expect("Failed to send command to server"); @@ -558,22 +570,22 @@ fn setup_console(mut rl: Editor, server: A } } Err(ReadlineError::Interrupted) => { - log::info!("CTRL-C"); + info!("CTRL-C"); stop_server(); break; } Err(ReadlineError::Eof) => { - log::info!("CTRL-D"); + info!("CTRL-D"); stop_server(); break; } Err(err) => { - log::error!("Error reading console input: {err}"); + error!("Error reading console input: {err}"); break; } } } - if let Some((wrapper, _)) = LOGGER_IMPL.wait() { + if let Some((wrapper, _, _)) = LOGGER_IMPL.wait() { wrapper.return_readline(rl); } }); @@ -603,7 +615,7 @@ fn setup_console(mut rl: Editor, server: A break; } } - log::debug!("Stopped console commands task"); + debug!("Stopped console commands task"); }); } diff --git a/pumpkin/src/logging.rs b/pumpkin/src/logging.rs index 595a2809e8..98e538ed97 100644 --- a/pumpkin/src/logging.rs +++ b/pumpkin/src/logging.rs @@ -2,7 +2,6 @@ #![allow(clippy::print_stdout)] use flate2::write::GzEncoder; -use log::LevelFilter; use rustyline::completion::Completer; use rustyline::highlight::Highlighter; use rustyline::hint::Hinter; @@ -18,11 +17,69 @@ use std::sync::Arc; use time::{Duration, OffsetDateTime}; use tracing::Subscriber; use tracing_subscriber::Layer; +use tracing_subscriber::filter::LevelFilter; use crate::command::CommandSender; use crate::command::tree::NodeType; use crate::server::Server; +#[macro_export] +macro_rules! log_at_level { + ($level:expr, $($arg:tt)*) => { + match $level { + tracing::Level::TRACE => tracing::trace!($($arg)*), + tracing::Level::DEBUG => tracing::debug!($($arg)*), + tracing::Level::INFO => tracing::info!($($arg)*), + tracing::Level::WARN => tracing::warn!($($arg)*), + tracing::Level::ERROR => tracing::error!($($arg)*), + } + }; +} + +#[macro_export] +macro_rules! plugin_log { + ($level:expr, $plugin_name:expr, $($arg:tt)*) => {{ + let plugin_name = $plugin_name; + match $level { + tracing::Level::TRACE => { + tracing::trace!( + target: "pumpkin_plugin", + plugin = plugin_name, + $($arg)* + ) + }, + tracing::Level::DEBUG => { + tracing::debug!( + target: "pumpkin_plugin", + plugin = plugin_name, + $($arg)* + ) + }, + tracing::Level::INFO => { + tracing::info!( + target: "pumpkin_plugin", + plugin = plugin_name, + $($arg)* + ) + }, + tracing::Level::WARN => { + tracing::warn!( + target: "pumpkin_plugin", + plugin = plugin_name, + $($arg)* + ) + }, + tracing::Level::ERROR => { + tracing::error!( + target: "pumpkin_plugin", + plugin = plugin_name, + $($arg)* + ) + }, + } + }}; +} + const LOG_DIR: &str = "logs"; const MAX_ATTEMPTS: u32 = 100; @@ -175,11 +232,11 @@ where // Check if we should log this event based on level let should_log = match *level { - tracing::Level::ERROR => self.log_level >= LevelFilter::Error, - tracing::Level::WARN => self.log_level >= LevelFilter::Warn, - tracing::Level::INFO => self.log_level >= LevelFilter::Info, - tracing::Level::DEBUG => self.log_level >= LevelFilter::Debug, - tracing::Level::TRACE => self.log_level >= LevelFilter::Trace, + tracing::Level::ERROR => self.log_level >= LevelFilter::ERROR, + tracing::Level::WARN => self.log_level >= LevelFilter::WARN, + tracing::Level::INFO => self.log_level >= LevelFilter::INFO, + tracing::Level::DEBUG => self.log_level >= LevelFilter::DEBUG, + tracing::Level::TRACE => self.log_level >= LevelFilter::TRACE, }; if !should_log { diff --git a/pumpkin/src/main.rs b/pumpkin/src/main.rs index 348c4297c0..59410f89e3 100644 --- a/pumpkin/src/main.rs +++ b/pumpkin/src/main.rs @@ -21,6 +21,7 @@ use pumpkin::{LoggerOption, PumpkinServer, SHOULD_STOP, STOP_INTERRUPT, stop_ser use pumpkin_config::{AdvancedConfiguration, BasicConfiguration, LoadConfiguration}; use pumpkin_util::text::{TextComponent, color::NamedColor}; use std::time::Instant; +use tracing::{debug, info, warn}; // Setup some tokens to allow us to identify which event is for which socket. @@ -67,7 +68,7 @@ async fn main() { // We need to abide by the panic rules here. std::process::exit(1); })); - log::info!( + info!( "{}", TextComponent::text(format!( "Starting {} {} Minecraft (Protocol {})", @@ -84,7 +85,7 @@ async fn main() { .to_pretty_console(), ); - log::debug!( + debug!( "Build info: FAMILY: \"{}\", OS: \"{}\", ARCH: \"{}\", BUILD: \"{}\"", std::env::consts::FAMILY, std::env::consts::OS, @@ -106,14 +107,14 @@ async fn main() { let pumpkin_server = PumpkinServer::new(basic_config, advanced_config, vanilla_data).await; pumpkin_server.init_plugins().await; - log::info!( + info!( "Started server; took {}", TextComponent::text(format!("{}ms", time.elapsed().as_millis())) .color_named(NamedColor::Gold) .to_pretty_console() ); let basic_config = &pumpkin_server.server.basic_config; - log::info!( + info!( "Server is now running. Connect using port: {}{}{}", if basic_config.java_edition { format!( @@ -149,7 +150,7 @@ async fn main() { ); pumpkin_server.start().await; - log::info!( + info!( "{}", TextComponent::text("The server has stopped.") .color_named(NamedColor::Red) @@ -157,19 +158,19 @@ async fn main() { ); } fn print_support_links_and_warning() { - log::warn!( + warn!( "{}", TextComponent::text("Pumpkin is currently under heavy development!") .color_named(NamedColor::DarkRed) .to_pretty_console(), ); - log::info!( + info!( "Report issues on {}", TextComponent::text("https://github.com/Pumpkin-MC/Pumpkin/issues") .color_named(NamedColor::DarkAqua) .to_pretty_console() ); - log::info!( + info!( "Join our {} for community support: {}", TextComponent::text("Discord") .color_named(NamedColor::DarkBlue) @@ -180,7 +181,7 @@ fn print_support_links_and_warning() { ); } fn handle_interrupt() { - log::warn!( + warn!( "{}", TextComponent::text("Received interrupt signal; stopping server...") .color_named(NamedColor::Red) diff --git a/pumpkin/src/net/bedrock/login.rs b/pumpkin/src/net/bedrock/login.rs index b09337a26e..19213c572d 100644 --- a/pumpkin/src/net/bedrock/login.rs +++ b/pumpkin/src/net/bedrock/login.rs @@ -22,6 +22,7 @@ use pumpkin_world::CURRENT_BEDROCK_MC_VERSION; use serde::Deserialize; use std::sync::Arc; use thiserror::Error; +use tracing::{debug, warn}; use uuid::Uuid; #[derive(Debug, Error)] @@ -58,7 +59,7 @@ impl BedrockClient { match self.try_handle_login(packet, server).await { Ok(()) => Some(()), Err(error) => { - log::warn!("Bedrock login failed: {error}"); + warn!("Bedrock login failed: {error}"); let message = match error { LoginError::InvalidUsername => "Your username is invalid.".to_string(), _ => "Failed to log in. The data sent by your client was invalid.".to_string(), @@ -124,7 +125,7 @@ impl BedrockClient { pub async fn handle_resource_pack_response(&self, packet: SResourcePackResponse) { // TODO: Add all if packet.response == SResourcePackResponse::STATUS_HAVE_ALL_PACKS { - log::debug!("Bedrock: STATUS_HAVE_ALL_PACKS"); + debug!("Bedrock: STATUS_HAVE_ALL_PACKS"); let mut frame_set = FrameSet::default(); self.write_game_packet_to_set( diff --git a/pumpkin/src/net/bedrock/mod.rs b/pumpkin/src/net/bedrock/mod.rs index 051c03c21c..aa6da647a1 100644 --- a/pumpkin/src/net/bedrock/mod.rs +++ b/pumpkin/src/net/bedrock/mod.rs @@ -8,6 +8,8 @@ use std::{ }, }; +use tracing::{debug, error, warn}; + use bytes::Bytes; use pumpkin_config::networking::compression::CompressionInfo; use pumpkin_protocol::{ @@ -150,7 +152,7 @@ impl BedrockClient { { // It is expected that the packet will fail if we are closed if !close_token.is_cancelled() { - log::warn!("Failed to send packet to client: {err}",); + warn!("Failed to send packet to client: {err}",); // We now need to close the connection to the client since the stream is in an // unknown state close_token.cancel(); @@ -167,7 +169,7 @@ impl BedrockClient { && let Err(error) = self.handle_packet_payload(server, packet).await { let _text = format!("Error while reading incoming packet {error}"); - log::error!("Failed to read incoming packet with : {error}"); + error!("Failed to read incoming packet with : {error}"); self.kick(DisconnectReason::BadPacket, error.to_string()) .await; } @@ -201,7 +203,7 @@ impl BedrockClient { if let Err(err) = self.outgoing_packet_queue_send.send(packet_data).await { // This is expected to fail if we are closed if !self.is_closed() { - log::error!("Failed to add packet to the outgoing packet queue for client: {err}"); + error!("Failed to add packet to the outgoing packet queue for client: {err}"); } } } @@ -351,7 +353,7 @@ impl BedrockClient { { // It is expected that the packet will fail if we are closed if !self.is_closed() { - log::warn!("Failed to send packet to client: {err}"); + warn!("Failed to send packet to client: {err}"); // We now need to close the connection to the client since the stream is in an // unknown state self.close_token.cancel(); @@ -385,7 +387,7 @@ impl BedrockClient { .write_packet(&packet_buf, self.address, &self.socket) .await { - log::warn!("Failed to send packet to client: {err}"); + warn!("Failed to send packet to client: {err}"); self.close().await; } } @@ -402,13 +404,13 @@ impl BedrockClient { Self::handle_ack(&Ack::read(reader)?); } RAKNET_NACK => { - log::debug!("received nack, client is missing packets"); + debug!("received nack, client is missing packets"); } 0x80..0x8d => { self.handle_frame_set(server, FrameSet::read(reader)?).await; } id => { - log::warn!("Bedrock: Received unknown packet header {id}"); + warn!("Bedrock: Received unknown packet header {id}"); } } Ok(()) @@ -545,7 +547,7 @@ impl BedrockClient { .await; } _ => { - log::warn!("Bedrock: Received Unknown Game packet: {}", packet.id); + warn!("Bedrock: Received Unknown Game packet: {}", packet.id); } } } @@ -582,7 +584,7 @@ impl BedrockClient { self.handle_game_packet(server, game_packet).await?; } _ => { - log::warn!("Bedrock: Received Unknown RakNet Online packet: {packet_id}"); + warn!("Bedrock: Received Unknown RakNet Online packet: {packet_id}"); } } Ok(()) @@ -623,7 +625,7 @@ impl BedrockClient { ) .await; } - _ => log::error!("Bedrock: Received Unknown RakNet Offline packet: {packet_id}"), + _ => error!("Bedrock: Received Unknown RakNet Offline packet: {packet_id}"), } Ok(()) } @@ -636,7 +638,7 @@ impl BedrockClient { let mut network_reader = self.network_reader.lock().await; tokio::select! { () = self.await_close_interrupt() => { - log::debug!("Canceling player packet processing"); + debug!("Canceling player packet processing"); None }, packet_result = network_reader.get_packet_payload(packet) => { @@ -644,7 +646,7 @@ impl BedrockClient { Ok(packet) => Some(packet), Err(err) => { if !matches!(err, PacketDecodeError::ConnectionClosed) { - log::warn!("Failed to decode packet from client: {err}"); + warn!("Failed to decode packet from client: {err}"); let text = format!("Error while reading incoming packet {err}"); self.kick(DisconnectReason::BadPacket, text).await; } diff --git a/pumpkin/src/net/bedrock/play.rs b/pumpkin/src/net/bedrock/play.rs index 309634a839..2f83d65609 100644 --- a/pumpkin/src/net/bedrock/play.rs +++ b/pumpkin/src/net/bedrock/play.rs @@ -29,6 +29,7 @@ use crate::{ server::{Server, seasonal_events}, world::chunker::{self}, }; +use tracing::{debug, info}; impl BedrockClient { pub async fn handle_request_chunk_radius( @@ -68,11 +69,9 @@ impl BedrockClient { }; if old_view_distance.get() != view_distance as u8 { - log::debug!( + debug!( "Player {} updated their render distance: {} -> {}.", - player.gameprofile.name, - old_view_distance, - view_distance + player.gameprofile.name, old_view_distance, view_distance ); chunker::update_position(player).await; } @@ -145,7 +144,7 @@ impl BedrockClient { PlayerChatEvent::new(player.clone(), packet.message, vec![]); 'after: { - log::info!(" {}: {}", gameprofile.name, event.message); + info!(" {}: {}", gameprofile.name, event.message); let config = &server.advanced_config; @@ -213,7 +212,7 @@ impl BedrockClient { }); if server.advanced_config.commands.log_console { - log::info!( + info!( "Player ({}): executed command /{}", player.gameprofile.name, command diff --git a/pumpkin/src/net/java/config.rs b/pumpkin/src/net/java/config.rs index f0735953f9..61b1fd1f2d 100644 --- a/pumpkin/src/net/java/config.rs +++ b/pumpkin/src/net/java/config.rs @@ -21,6 +21,7 @@ use pumpkin_protocol::{ }, }; use pumpkin_util::{Hand, text::TextComponent, version::MinecraftVersion}; +use tracing::{debug, trace, warn}; const BRAND_CHANNEL_PREFIX: &str = "minecraft:brand"; @@ -29,7 +30,7 @@ impl JavaClient { &self, client_information: SClientInformationConfig, ) { - log::debug!("Handling client settings"); + debug!("Handling client settings"); if client_information.view_distance <= 0 { self.kick(TextComponent::text( "Cannot have zero or negative view distance!", @@ -60,9 +61,9 @@ impl JavaClient { } pub async fn handle_plugin_message(&self, plugin_message: SPluginMessage) { - log::debug!("Handling plugin message"); + debug!("Handling plugin message"); if plugin_message.channel.starts_with(BRAND_CHANNEL_PREFIX) { - log::debug!("Got a client brand"); + debug!("Got a client brand"); match str::from_utf8(&plugin_message.data) { Ok(brand) => *self.brand.lock().await = Some(brand.to_string()), Err(e) => self.kick(TextComponent::text(e.to_string())).await, @@ -83,57 +84,56 @@ impl JavaClient { if packet.uuid == expected_uuid { match packet.response_result() { ResourcePackResponseResult::DownloadSuccess => { - log::trace!( + trace!( "Client {} successfully downloaded the resource pack", self.id ); } ResourcePackResponseResult::DownloadFail => { - log::warn!( + warn!( "Client {} failed to downloaded the resource pack. Is it available on the internet?", self.id ); } ResourcePackResponseResult::Downloaded => { - log::trace!("Client {} already has the resource pack", self.id); + trace!("Client {} already has the resource pack", self.id); } ResourcePackResponseResult::Accepted => { - log::trace!("Client {} accepted the resource pack", self.id); + trace!("Client {} accepted the resource pack", self.id); // Return here to wait for the next response update return; } ResourcePackResponseResult::Declined => { - log::trace!("Client {} declined the resource pack", self.id); + trace!("Client {} declined the resource pack", self.id); } ResourcePackResponseResult::InvalidUrl => { - log::warn!( + warn!( "Client {} reported that the resource pack URL is invalid!", self.id ); } ResourcePackResponseResult::ReloadFailed => { - log::trace!("Client {} failed to reload the resource pack", self.id); + trace!("Client {} failed to reload the resource pack", self.id); } ResourcePackResponseResult::Discarded => { - log::trace!("Client {} discarded the resource pack", self.id); + trace!("Client {} discarded the resource pack", self.id); } ResourcePackResponseResult::Unknown(result) => { - log::warn!( + warn!( "Client {} responded with a bad result: {}!", - self.id, - result + self.id, result ); } } } else { - log::warn!( + warn!( "Client {} returned a response for a resource pack we did not set!", self.id ); } } else { - log::warn!( + warn!( "Client {} returned a response for a resource pack that was not enabled!", self.id ); @@ -143,7 +143,7 @@ impl JavaClient { pub fn handle_config_cookie_response(&self, packet: &SConfigCookieResponse) { // TODO: allow plugins to access this - log::debug!( + debug!( "Received cookie_response[config]: key: \"{}\", has_payload: \"{}\", payload_length: \"{:?}\"", packet.key, packet.has_payload, @@ -152,7 +152,7 @@ impl JavaClient { } pub async fn handle_known_packs(&self, _config_acknowledged: SKnownPacks) { - log::debug!("Handling known packs"); + debug!("Handling known packs"); // let mut tags_to_send = Vec::new(); let registry = Registry::get_synced(self.version.load()); for registry in registry { @@ -186,12 +186,12 @@ impl JavaClient { self.send_packet_now(&CUpdateTags::new(&tags)).await; // We are done with configuring - log::debug!("Finished config"); + debug!("Finished config"); self.send_packet_now(&CFinishConfig).await; } pub async fn handle_config_acknowledged(&self, server: &Arc) -> PacketHandlerResult { - log::debug!("Handling config acknowledgement"); + debug!("Handling config acknowledgement"); self.connection_state.store(ConnectionState::Play); let profile = self.gameprofile.lock().await.clone(); diff --git a/pumpkin/src/net/java/handshake.rs b/pumpkin/src/net/java/handshake.rs index f3b5e73c8e..1c74189489 100644 --- a/pumpkin/src/net/java/handshake.rs +++ b/pumpkin/src/net/java/handshake.rs @@ -1,6 +1,7 @@ use pumpkin_data::{packet::CURRENT_MC_PROTOCOL, translation}; use pumpkin_protocol::{ConnectionState, java::server::handshake::SHandShake}; use pumpkin_util::{text::TextComponent, version::MinecraftVersion}; +use tracing::debug; use pumpkin_world::{CURRENT_MC_VERSION, LOWEST_SUPPRORTED_PROTOCOL_VERSION}; @@ -12,7 +13,7 @@ impl JavaClient { *self.server_address.lock().await = handshake.server_address; self.version.store(MinecraftVersion::from_protocol(version)); - log::debug!("Handshake: next state is {:?}", &handshake.next_state); + debug!("Handshake: next state is {:?}", &handshake.next_state); self.connection_state.store(handshake.next_state); if self.connection_state.load() != ConnectionState::Status { let protocol = version; diff --git a/pumpkin/src/net/java/login.rs b/pumpkin/src/net/java/login.rs index e94a3da06a..11ec60eb11 100644 --- a/pumpkin/src/net/java/login.rs +++ b/pumpkin/src/net/java/login.rs @@ -10,6 +10,7 @@ use pumpkin_protocol::{ }, }; use pumpkin_util::text::TextComponent; +use tracing::debug; use uuid::Uuid; use crate::{ @@ -26,7 +27,7 @@ use crate::{ impl JavaClient { pub async fn handle_login_start(&self, server: &Server, login_start: SLoginStart) { - log::debug!("login start"); + debug!("login start"); // Don't allow new logons when the server is full. // If `max_players` is set to zero, then there is no max player count enforced. @@ -109,7 +110,7 @@ impl JavaClient { server: &Server, encryption_response: SEncryptionResponse, ) { - log::debug!("Handling encryption"); + debug!("Handling encryption"); let shared_secret = server .decrypt(&encryption_response.shared_secret) .await @@ -153,7 +154,7 @@ impl JavaClient { // Don't allow duplicate UUIDs if let Some(online_player) = &server.get_player_by_uuid(profile.id) { - log::debug!( + debug!( "Player (IP '{}', username '{}') tried to log in with the same UUID ('{}') as an online player (username '{}')", &self.address.lock().await, &profile.name, @@ -170,7 +171,7 @@ impl JavaClient { // Don't allow a duplicate username if let Some(online_player) = &server.get_player_by_name(&profile.name) { - log::debug!( + debug!( "A player (IP '{}', attempted username '{}') tried to log in with the same username as an online player (UUID '{}', username '{}')", &self.address.lock().await, &profile.name, @@ -263,7 +264,7 @@ impl JavaClient { pub fn handle_login_cookie_response(&self, packet: &SLoginCookieResponse) { // TODO: allow plugins to access this - log::debug!( + debug!( "Received cookie_response[login]: key: \"{}\", payload_length: \"{:?}\"", packet.key, packet.payload.as_ref().map(|p| p.len()) @@ -274,7 +275,7 @@ impl JavaClient { server: &Server, plugin_response: SLoginPluginResponse, ) { - log::debug!("Handling plugin"); + debug!("Handling plugin"); let velocity_config = &server.advanced_config.networking.proxy.velocity; if velocity_config.enabled { let mut address = self.address.lock().await; @@ -295,7 +296,7 @@ impl JavaClient { } pub async fn handle_login_acknowledged(&self, server: &Server) { - log::debug!("Handling login acknowledgement"); + debug!("Handling login acknowledgement"); self.connection_state.store(ConnectionState::Config); self.send_packet_now(&server.get_branding()).await; @@ -380,7 +381,7 @@ impl JavaClient { // This will be invoked by our resource pack handler in the case of the above branch. self.send_known_packs().await; } - log::debug!("login acknowledged"); + debug!("login acknowledged"); } /// Send the known data packs to the client. diff --git a/pumpkin/src/net/java/mod.rs b/pumpkin/src/net/java/mod.rs index a0f734d995..be0f5c14ef 100644 --- a/pumpkin/src/net/java/mod.rs +++ b/pumpkin/src/net/java/mod.rs @@ -52,6 +52,7 @@ use tokio::{ }; use tokio_util::sync::CancellationToken; use tokio_util::task::TaskTracker; +use tracing::{debug, error, warn}; pub mod config; pub mod handshake; @@ -162,7 +163,7 @@ impl JavaClient { pub async fn set_compression(&self, compression: CompressionInfo) { if compression.level > 9 { - log::error!("Invalid compression level! Clients will not be able to read this!"); + error!("Invalid compression level! Clients will not be able to read this!"); } self.network_reader @@ -199,10 +200,9 @@ impl JavaClient { } Err(error) => { let text = format!("Error while reading incoming packet {error}"); - log::debug!( + debug!( "Failed to read incoming packet with id {}: {}", - packet.id, - error + packet.id, error ); self.kick(TextComponent::text(text)).await; } @@ -275,10 +275,9 @@ impl JavaClient { { // This is expected to fail if we are closed if !self.close_token.is_cancelled() { - log::error!( + error!( "Failed to add packet to the outgoing packet queue for client {}: {}", - self.id, - err + self.id, err ); } } @@ -292,7 +291,7 @@ impl JavaClient { let mut network_reader = self.network_reader.lock().await; tokio::select! { () = self.await_close_interrupt() => { - log::debug!("Canceling player packet processing"); + debug!("Canceling player packet processing"); None }, packet_result = network_reader.get_raw_packet() => { @@ -300,7 +299,7 @@ impl JavaClient { Ok(packet) => Some(packet), Err(err) => { if !matches!(err, PacketDecodeError::ConnectionClosed) { - log::warn!("Failed to decode packet from client {}: {}", self.id, err); + warn!("Failed to decode packet from client {}: {}", self.id, err); let text = format!("Error while reading incoming packet {err}"); self.kick(TextComponent::text(text)).await; } @@ -327,7 +326,7 @@ impl JavaClient { ConnectionState::Play => self.send_packet_now(&CPlayDisconnect::new(&reason)).await, _ => {} } - log::debug!("Closing connection for {}", self.id); + debug!("Closing connection for {}", self.id); self.close(); } @@ -348,10 +347,9 @@ impl JavaClient { { // It is expected that the packet will fail if we are closed if !self.close_token.is_cancelled() { - log::warn!( + warn!( "Failed to add high-priority packet to the outgoing packet queue for client {}: {}", - self.id, - err + self.id, err ); // We now need to close the connection to the client since the stream is in an // unknown state @@ -438,7 +436,7 @@ impl JavaClient { &self, packet: &RawPacket, ) -> Result, ReadingError> { - log::debug!("Handling handshake group"); + debug!("Handling handshake group"); let payload = &packet.payload[..]; match packet.id { 0 => { @@ -457,7 +455,7 @@ impl JavaClient { server: &Server, packet: &RawPacket, ) -> Result, ReadingError> { - log::debug!("Handling status group"); + debug!("Handling status group"); let payload = &packet.payload[..]; match packet.id { id if id == SStatusRequest::PACKET_ID => { @@ -528,7 +526,7 @@ impl JavaClient { send_failed = true; // It is expected that the packet will fail if we are closed if !close_token.is_cancelled() { - log::warn!("Failed to send packet to client {id}: {err}"); + warn!("Failed to send packet to client {id}: {err}"); } break; } @@ -537,7 +535,7 @@ impl JavaClient { if !send_failed && let Err(err) = writer.flush().await { send_failed = true; if !close_token.is_cancelled() { - log::warn!("Failed to flush packet batch for client {id}: {err}"); + warn!("Failed to flush packet batch for client {id}: {err}"); } } drop(writer); @@ -579,7 +577,7 @@ impl JavaClient { server: &Server, packet: &RawPacket, ) -> Result, ReadingError> { - log::debug!("Handling login group for id"); + debug!("Handling login group for id"); let payload = &packet.payload[..]; match packet.id { id if id == SLoginStart::PACKET_ID => { @@ -601,7 +599,7 @@ impl JavaClient { self.handle_login_cookie_response(&SLoginCookieResponse::read(payload)?); } _ => { - log::error!( + error!( "Failed to handle java client packet id {} in Login State", packet.id ); @@ -615,7 +613,7 @@ impl JavaClient { server: &Arc, packet: &RawPacket, ) -> Result, ReadingError> { - log::debug!("Handling config group for id {}", packet.id); + debug!("Handling config group for id {}", packet.id); let payload = &packet.payload[..]; match packet.id { @@ -641,7 +639,7 @@ impl JavaClient { .await; } _ => { - log::error!( + error!( "Failed to handle java client packet id {} in Config State", packet.id ); @@ -793,7 +791,7 @@ impl JavaClient { // TODO: this fixes Failed to handle player packet id for now } _ => { - log::warn!("Failed to handle player packet id {}", packet.id); + warn!("Failed to handle player packet id {}", packet.id); } } Ok(()) diff --git a/pumpkin/src/net/java/play.rs b/pumpkin/src/net/java/play.rs index 65c7a82fad..edee846c11 100644 --- a/pumpkin/src/net/java/play.rs +++ b/pumpkin/src/net/java/play.rs @@ -8,6 +8,7 @@ use std::sync::Arc; use std::sync::atomic::{AtomicU32, Ordering}; use std::time::{SystemTime, UNIX_EPOCH}; use thiserror::Error; +use tracing::{Level, debug, error, info, trace, warn}; use crate::block::BlockHitResult; use crate::block::registry::BlockActionResult; @@ -16,6 +17,7 @@ use crate::command::CommandSender; use crate::entity::EntityBase; use crate::entity::player::{ChatMode, ChatSession, Player}; use crate::error::PumpkinError; +use crate::log_at_level; use crate::net::PlayerConfig; use crate::net::java::JavaClient; use crate::plugin::player::player_chat::PlayerChatEvent; @@ -87,10 +89,10 @@ impl PumpkinError for BlockPlacingError { } } - fn severity(&self) -> log::Level { + fn severity(&self) -> Level { match self { - Self::BlockOutOfWorld | Self::InvalidGamemode => log::Level::Trace, - Self::BlockOutOfReach | Self::InvalidBlockFace | Self::InvalidHand => log::Level::Warn, + Self::BlockOutOfWorld | Self::InvalidGamemode => Level::TRACE, + Self::BlockOutOfReach | Self::InvalidBlockFace | Self::InvalidHand => Level::WARN, } } @@ -128,8 +130,8 @@ impl PumpkinError for ChatError { true } - fn severity(&self) -> log::Level { - log::Level::Warn + fn severity(&self) -> Level { + Level::WARN } fn client_kick_reason(&self) -> Option { @@ -597,7 +599,7 @@ impl JavaClient { }); if server.advanced_config.commands.log_console { - log::info!( + info!( "Player ({}): executed command /{}", player.gameprofile.name, command @@ -681,9 +683,7 @@ impl JavaClient { let pos = command.pos; if let Some(block_entity) = player.world().get_block_entity(&pos).await { if block_entity.resource_location() != CommandBlockEntity::ID { - log::warn!( - "Client tried to change Command block but not Command block entity found" - ); + warn!("Client tried to change Command block but not Command block entity found"); return; } @@ -788,7 +788,7 @@ impl JavaClient { Action::LeaveBed => player.wake_up().await, Action::StartHorseJump | Action::StopHorseJump | Action::OpenVehicleInventory => { - log::debug!("todo"); + debug!("todo"); } Action::StartFlyingElytra => { let fall_flying = entity.check_fall_flying(); @@ -877,7 +877,7 @@ impl JavaClient { .validate_chat_message(server, player, &chat_message) .await { - log::log!( + log_at_level!( err.severity(), "{} (uuid {}) {}", gameprofile.name, @@ -897,7 +897,7 @@ impl JavaClient { PlayerChatEvent::new(player.clone(), chat_message.message.clone(), vec![]); 'after: { - log::info!(" {}: {}", gameprofile.name, event.message); + info!(" {}: {}", gameprofile.name, event.message); let config = &server.advanced_config; @@ -1002,7 +1002,7 @@ impl JavaClient { } if let Err(err) = self.validate_chat_session(player, server, &session) { - log::log!( + log_at_level!( err.severity(), "{} (uuid {}) {}", player.gameprofile.name, @@ -1112,12 +1112,9 @@ impl JavaClient { let update_watched = if old_view_distance.get() == new_view_distance_raw { false } else { - log::debug!( + debug!( "Player {} ({}) updated their render distance: {} -> {}.", - player.gameprofile.name, - self.id, - old_view_distance, - new_view_distance_raw + player.gameprofile.name, self.id, old_view_distance, new_view_distance_raw ); true }; @@ -1150,10 +1147,9 @@ impl JavaClient { } if update_settings { - log::debug!( + debug!( "Player {} ({}) updated their skin.", - player.gameprofile.name, - self.id, + player.gameprofile.name, self.id, ); player.send_client_information().await; } @@ -1186,7 +1182,7 @@ impl JavaClient { } 1 => { // Request stats - log::debug!("todo"); + debug!("todo"); } _ => { self.kick(TextComponent::text("Invalid client status")) @@ -1260,7 +1256,7 @@ impl JavaClient { } else if let Some(entity_victim) = world.get_entity_by_id(entity_id.0) { player.attack(entity_victim).await; } else { - log::error!( + error!( "Player id {} interacted with entity id {}, which was not found.", player.entity_id(), entity_id.0 @@ -1302,10 +1298,9 @@ impl JavaClient { Ok(status) => match status { Status::StartedDigging => { if !player.can_interact_with_block_at(&player_action.position, 1.0) { - log::warn!( + warn!( "Player {0} tried to interact with block out of reach at {1}", - player.gameprofile.name, - player_action.position + player.gameprofile.name, player_action.position ); self.update_sequence(player, player_action.sequence.0); return; @@ -1383,10 +1378,9 @@ impl JavaClient { } Status::CancelledDigging => { if !player.can_interact_with_block_at(&player_action.position, 1.0) { - log::warn!( + warn!( "Player {0} tried to interact with block out of reach at {1}", - player.gameprofile.name, - player_action.position + player.gameprofile.name, player_action.position ); self.update_sequence(player, player_action.sequence.0); return; @@ -1404,10 +1398,9 @@ impl JavaClient { // TODO: do validation let location = player_action.position; if !player.can_interact_with_block_at(&location, 1.0) { - log::warn!( + warn!( "Player {0} tried to interact with block out of reach at {1}", - player.gameprofile.name, - player_action.position + player.gameprofile.name, player_action.position ); self.update_sequence(player, player_action.sequence.0); return; @@ -1458,7 +1451,7 @@ impl JavaClient { player.swap_item().await; } Status::SpearJab => { - log::debug!("todo"); + debug!("todo"); } }, Err(_) => self.kick(TextComponent::text("Invalid status")).await, @@ -1486,7 +1479,7 @@ impl JavaClient { pub fn update_sequence(&self, player: &Player, sequence: i32) { if sequence < 0 { - log::error!("Expected packet sequence >= 0"); + error!("Expected packet sequence >= 0"); } player.packet_sequence.store( player.packet_sequence.load(Ordering::Relaxed).max(sequence), @@ -1906,7 +1899,7 @@ impl JavaClient { .lock() .await .handle_acknowledge(packet.chunks_per_tick); - log::trace!( + trace!( "Client requested {} chunks per tick", packet.chunks_per_tick ); @@ -1956,7 +1949,7 @@ impl JavaClient { pub fn handle_cookie_response(&self, packet: &SPCookieResponse) { // TODO: allow plugins to access this - log::debug!( + debug!( "Received cookie_response[play]: key: \"{}\", payload_length: \"{:?}\"", packet.key, packet.payload.as_ref().map(|p| p.len()) diff --git a/pumpkin/src/net/java/status.rs b/pumpkin/src/net/java/status.rs index 57d772e95d..329bad9262 100644 --- a/pumpkin/src/net/java/status.rs +++ b/pumpkin/src/net/java/status.rs @@ -3,17 +3,18 @@ use pumpkin_protocol::{ }; use crate::{net::java::JavaClient, server::Server}; +use tracing::debug; impl JavaClient { pub async fn handle_status_request(&self, server: &Server) { - log::debug!("Handling status request"); + debug!("Handling status request"); let status = server.get_status(); self.send_packet_now(&status.lock().await.get_status()) .await; } pub async fn handle_ping_request(&self, ping_request: SStatusPingRequest) { - log::debug!("Handling ping request"); + debug!("Handling ping request"); self.send_packet_now(&CPingResponse::new(ping_request.payload)) .await; self.close(); diff --git a/pumpkin/src/net/lan_broadcast.rs b/pumpkin/src/net/lan_broadcast.rs index 88f15c461e..8932b98fe9 100644 --- a/pumpkin/src/net/lan_broadcast.rs +++ b/pumpkin/src/net/lan_broadcast.rs @@ -4,6 +4,7 @@ use std::sync::atomic::Ordering; use std::time::Duration; use tokio::net::UdpSocket; use tokio::{select, time}; +use tracing::{info, warn}; use crate::{SHOULD_STOP, STOP_INTERRUPT}; @@ -28,7 +29,7 @@ impl LANBroadcast { let advanced_motd = config.motd.clone().unwrap_or_default(); let motd = if advanced_motd.is_empty() { - log::warn!( + warn!( "Using the server MOTD as the LAN broadcast MOTD. Note that the LAN broadcast MOTD does not support multiple lines, RGB colors, or gradients so consider defining it accordingly." ); basic_config.motd.replace('\n', " ") @@ -61,7 +62,7 @@ impl LANBroadcast { let advertisement = format!("[MOTD]{}[/MOTD][AD]{}[/AD]", &self.motd, bound_addr.port()); - log::info!( + info!( "LAN broadcast running on {}", socket .local_addr() diff --git a/pumpkin/src/net/proxy/velocity.rs b/pumpkin/src/net/proxy/velocity.rs index 7133c65129..af77b5d20a 100644 --- a/pumpkin/src/net/proxy/velocity.rs +++ b/pumpkin/src/net/proxy/velocity.rs @@ -16,6 +16,7 @@ use pumpkin_protocol::{ use rand::RngExt; use sha2::Sha256; use thiserror::Error; +use tracing::debug; use crate::net::{GameProfile, java::JavaClient}; @@ -108,7 +109,7 @@ pub fn receive_velocity_plugin_response( config: &VelocityConfig, response: SLoginPluginResponse, ) -> Result<(GameProfile, SocketAddr), VelocityError> { - log::debug!("Received velocity response"); + debug!("Received velocity response"); if let Some(data) = response.data { let (signature, mut data_without_signature) = data.split_at(32); diff --git a/pumpkin/src/net/query.rs b/pumpkin/src/net/query.rs index 3b61e9d252..0a6ad322c5 100644 --- a/pumpkin/src/net/query.rs +++ b/pumpkin/src/net/query.rs @@ -13,6 +13,7 @@ use pumpkin_util::text::{TextComponent, color::NamedColor}; use pumpkin_world::CURRENT_MC_VERSION; use rand::RngExt; use tokio::{net::UdpSocket, sync::RwLock, time}; +use tracing::{error, info}; use crate::{SHOULD_STOP, STOP_INTERRUPT, server::Server}; @@ -36,7 +37,7 @@ pub async fn start_query_handler(server: Arc, query_addr: SocketAddr) { } }); - log::info!( + info!( "Server query running on port {}", TextComponent::text(format!( "{}", @@ -75,7 +76,7 @@ pub async fn start_query_handler(server: Arc, query_addr: SocketAddr) { ) .await { - log::error!("Interior 0 bytes found! Cannot encode query response! {err}"); + error!("Interior 0 bytes found! Cannot encode query response! {err}"); } }); } diff --git a/pumpkin/src/net/rcon/mod.rs b/pumpkin/src/net/rcon/mod.rs index 4e9d31a5fd..b581c80877 100644 --- a/pumpkin/src/net/rcon/mod.rs +++ b/pumpkin/src/net/rcon/mod.rs @@ -7,6 +7,7 @@ use tokio::{ io::{AsyncReadExt, AsyncWriteExt}, select, }; +use tracing::{debug, error, info}; use crate::{SHOULD_STOP, STOP_INTERRUPT, server::Server}; @@ -48,7 +49,7 @@ impl RCONServer { let password = password.clone(); let server = server.clone(); tokio::spawn(async move { while !client.handle(&server, &password).await {} }); - log::debug!("closed RCON connection"); + debug!("closed RCON connection"); connections -= 1; } Ok(()) @@ -83,13 +84,13 @@ impl RCONClient { Ok(true) => return true, Ok(false) => {} Err(e) => { - log::error!("Could not read packet: {e}"); + error!("Could not read packet: {e}"); return true; } } // 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}"); + error!("RCON error: {e}"); self.closed = true; }); } @@ -107,12 +108,12 @@ impl RCONClient { self.send(ClientboundPacket::AuthResponse, packet.get_id(), "") .await?; if config.logging.logged_successfully { - log::info!("RCON ({}): Client logged in successfully", self.address); + info!("RCON ({}): Client logged in successfully", self.address); } self.logged_in = true; } else { if config.logging.wrong_password { - log::info!("RCON ({}): Client tried the wrong password", self.address); + info!("RCON ({}): Client tried the wrong password", self.address); } self.send(ClientboundPacket::AuthResponse, -1, "").await?; self.closed = true; @@ -144,7 +145,7 @@ impl RCONClient { let output = output.lock().await; for line in output.iter() { if config.logging.commands { - log::info!("RCON ({}): {}", self.address, line); + info!("RCON ({}): {}", self.address, line); } self.send(ClientboundPacket::Output, packet.get_id(), line) .await?; diff --git a/pumpkin/src/plugin/api/context.rs b/pumpkin/src/plugin/api/context.rs index 95f5a0b694..0d77338092 100644 --- a/pumpkin/src/plugin/api/context.rs +++ b/pumpkin/src/plugin/api/context.rs @@ -4,12 +4,13 @@ use std::{ sync::{Arc, OnceLock}, }; -use crate::{LoggerOption, command::client_suggestions}; +use crate::{LoggerOption, command::client_suggestions, plugin_log}; use pumpkin_util::{ PermissionLvl, permission::{Permission, PermissionManager}, }; use tokio::sync::RwLock; +use tracing::Level; use crate::{ entity::player::Player, @@ -17,6 +18,8 @@ use crate::{ server::Server, }; +use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt}; + use super::{EventPriority, Payload, PluginMetadata}; /// The `Context` struct represents the context of a plugin, containing metadata, @@ -300,15 +303,42 @@ impl Context { after_count > before_count } - /// Initializes logging via the log crate for the plugin. + /// Initializes logging via the tracing crate for the plugin. pub fn init_log(&self) { - let logger_arc = self.logger.clone(); - - let static_logger = Box::leak(Box::new(logger_arc)); + if let Some(Some((_logger_impl, level, config))) = self.logger.get() { + let fmt_layer = fmt::layer() + .with_writer(std::io::stderr) + .with_ansi(config.color) + .with_target(true) + .with_thread_names(config.threads) + .with_thread_ids(config.threads); - if let Some(Some((_logger_impl, level))) = static_logger.get() { - // TODO - log::set_max_level(*level); + if config.timestamp { + let fmt_layer = fmt_layer.with_timer(fmt::time::UtcTime::new( + time::macros::format_description!( + "[year]-[month]-[day] [hour]:[minute]:[second]" + ), + )); + tracing_subscriber::registry() + .with(*level) + .with(fmt_layer) + .init(); + } else { + let fmt_layer = fmt_layer.without_time(); + tracing_subscriber::registry() + .with(*level) + .with(fmt_layer) + .init(); + } } } + + pub fn log(&self, message: impl std::fmt::Display) { + let level = if let Some(Some((_, level, _))) = self.logger.get() { + level.into_level().unwrap_or(Level::INFO) + } else { + Level::INFO + }; + plugin_log!(level, self.metadata.name, "{}", message); + } } diff --git a/pumpkin/src/plugin/mod.rs b/pumpkin/src/plugin/mod.rs index dda57d975f..65bc820c03 100644 --- a/pumpkin/src/plugin/mod.rs +++ b/pumpkin/src/plugin/mod.rs @@ -9,6 +9,7 @@ use std::{ }; use thiserror::Error; use tokio::sync::{Notify, RwLock}; +use tracing::{error, info}; pub mod api; pub mod loader; @@ -238,7 +239,7 @@ impl PluginManager { for name in plugin_names { if let Err(e) = self.unload_plugin(&name).await { - log::error!("Failed to unload plugin {name}: {e}"); + error!("Failed to unload plugin {name}: {e}"); } } @@ -401,7 +402,7 @@ impl PluginManager { .insert(plugin_name.clone(), PluginState::Loaded); state_notify.notify_waiters(); - log::info!("Loaded {} ({})", metadata.name, metadata.version); + info!("Loaded {} ({})", metadata.name, metadata.version); } Err(e) => { // Handle initialization failure @@ -437,7 +438,7 @@ impl PluginManager { ); state_notify.notify_waiters(); - log::error!("Failed to initialize plugin {plugin_name}: {error_msg}",); + error!("Failed to initialize plugin {plugin_name}: {error_msg}",); } } }); diff --git a/pumpkin/src/server/connection_cache.rs b/pumpkin/src/server/connection_cache.rs index d854ef9089..0d6d6481c0 100644 --- a/pumpkin/src/server/connection_cache.rs +++ b/pumpkin/src/server/connection_cache.rs @@ -13,6 +13,7 @@ use std::{ fs::{self}, path::Path, }; +use tracing::{debug, info, warn}; use uuid::Uuid; const DEFAULT_ICON: &[u8] = include_bytes!("../../../assets/default_icon.png"); @@ -144,7 +145,7 @@ impl CachedStatus { let favicon = if config.use_favicon { config.favicon_path.as_ref().map_or_else( || { - log::debug!("Loading default icon"); + debug!("Loading default icon"); // Attempt to load default icon Some(load_icon_from_bytes(DEFAULT_ICON)) @@ -154,10 +155,10 @@ impl CachedStatus { .extension() .is_some_and(|ext| ext.eq_ignore_ascii_case("png")) { - log::warn!("Favicon is not a PNG-image, using default."); + warn!("Favicon is not a PNG-image, using default."); return Some(load_icon_from_bytes(DEFAULT_ICON)); } - log::debug!("Attempting to load server favicon from '{icon_path}'"); + debug!("Attempting to load server favicon from '{icon_path}'"); match load_icon_from_file(icon_path) { Ok(icon) => Some(icon), @@ -172,9 +173,7 @@ impl CachedStatus { } }, ); - log::warn!( - "Failed to load favicon from '{icon_path}': {error_message}" - ); + warn!("Failed to load favicon from '{icon_path}': {error_message}"); Some(load_icon_from_bytes(DEFAULT_ICON)) } @@ -182,7 +181,7 @@ impl CachedStatus { }, ) } else { - log::info!("Favicon usage is disabled."); + info!("Favicon usage is disabled."); None }; diff --git a/pumpkin/src/server/key_store.rs b/pumpkin/src/server/key_store.rs index 3dfd8d4b3f..07acbc3163 100644 --- a/pumpkin/src/server/key_store.rs +++ b/pumpkin/src/server/key_store.rs @@ -6,6 +6,7 @@ use pumpkin_protocol::java::client::login::CEncryptionRequest; use rsa::{Pkcs1v15Encrypt, RsaPrivateKey}; use sha1::Sha1; use sha2::Digest; +use tracing::debug; use crate::net::EncryptionError; @@ -18,7 +19,7 @@ impl KeyStore { #[must_use] pub fn new() -> Self { let instant = Instant::now(); - log::debug!("Creating encryption keys..."); + debug!("Creating encryption keys..."); let private_key = Self::generate_private_key(); let public_key = private_key.to_public_key(); @@ -29,7 +30,7 @@ impl KeyStore { .into_vec() .into_boxed_slice(); - log::debug!("Created RSA keys, took {}ms", instant.elapsed().as_millis()); + debug!("Created RSA keys, took {}ms", instant.elapsed().as_millis()); Self { private_key, diff --git a/pumpkin/src/server/mod.rs b/pumpkin/src/server/mod.rs index 78f123dd2a..51e5d9abb4 100644 --- a/pumpkin/src/server/mod.rs +++ b/pumpkin/src/server/mod.rs @@ -21,6 +21,7 @@ use pumpkin_data::dimension::Dimension; use pumpkin_util::permission::{PermissionManager, PermissionRegistry}; use pumpkin_util::text::color::NamedColor; use pumpkin_world::dimension::into_level; +use tracing::{debug, error, info, warn}; use crate::command::CommandSender; use pumpkin_macros::send_cancellable; @@ -147,8 +148,8 @@ impl Server { WorldInfoError::InfoNotFound => (), WorldInfoError::UnsupportedDataVersion(_version) | WorldInfoError::UnsupportedLevelVersion(_version) => { - log::error!("Failed to load world info!"); - log::error!("{error}"); + error!("Failed to load world info!"); + error!("{error}"); panic!("Unsupported world version! See the logs for more info."); } e => { @@ -165,7 +166,7 @@ impl Server { let locker = match AnvilLevelLocker::lock(&world_path) { Ok(l) => Some(l), Err(err) => { - log::warn!( + warn!( "Could not lock the level file. Data corruption is possible if the world is accessed by multiple processes simultaneously. Error: {err}" ); None @@ -173,7 +174,7 @@ impl Server { }; let level_info = level_info.unwrap_or_else(|err| { - log::warn!("Failed to get level_info, using default instead: {err}"); + warn!("Failed to get level_info, using default instead: {err}"); LevelData::default(basic_config.seed) }); @@ -199,7 +200,7 @@ impl Server { async move { if allow_chat { fetch_mojang_public_keys(&auth_config).unwrap_or_else(|e| { - log::error!("Failed to fetch Mojang keys: {e}"); + error!("Failed to fetch Mojang keys: {e}"); Vec::new() }) } else { @@ -264,7 +265,7 @@ impl Server { let config = Arc::new(server.advanced_config.world.clone()); tokio::task::spawn_blocking(move || { - log::info!( + info!( "Loading {}", TextComponent::text(dim.minecraft_name.to_string()) .color_named(NamedColor::DarkGreen) @@ -280,7 +281,7 @@ impl Server { }) }; - log::info!("Starting parallel world load..."); + info!("Starting parallel world load..."); let (overworld, nether, end, keys) = tokio::join!( world_loader(Dimension::OVERWORLD), world_loader(Dimension::THE_NETHER), @@ -298,7 +299,7 @@ impl Server { server.mojang_public_keys.store(Arc::new(k)); } - log::info!("All worlds loaded successfully."); + info!("All worlds loaded successfully."); server } @@ -365,7 +366,7 @@ impl Server { let world = self.get_world_from_dimension(dimension); (world, Some(data)) } else { - log::warn!("Invalid dimension key in player data: {dimension_key}"); + warn!("Invalid dimension key in player data: {dimension_key}"); let default_world = self .worlds .load() @@ -448,11 +449,11 @@ impl Server { pub async fn shutdown(&self) { self.tasks.close(); - log::debug!("Awaiting tasks for server"); + debug!("Awaiting tasks for server"); self.tasks.wait().await; - log::debug!("Done awaiting tasks for server"); + debug!("Done awaiting tasks for server"); - log::info!("Starting worlds"); + info!("Starting worlds"); for world in self.worlds.load().iter() { world.shutdown().await; } @@ -463,9 +464,9 @@ impl Server { .world_info_writer .write_world_info(&level_data, &self.basic_config.get_world_path()) { - log::error!("Failed to save level.dat: {err}"); + error!("Failed to save level.dat: {err}"); } - log::info!("Completed worlds"); + info!("Completed worlds"); } /// Broadcasts a packet to all players in all worlds. @@ -742,7 +743,7 @@ impl Server { // Global tasks if let Err(e) = self.player_data_storage.tick(self).await { - log::error!("Error ticking player data: {e}"); + error!("Error ticking player data: {e}"); } } diff --git a/pumpkin/src/server/ticker.rs b/pumpkin/src/server/ticker.rs index c2d82e0595..6a65947a73 100644 --- a/pumpkin/src/server/ticker.rs +++ b/pumpkin/src/server/ticker.rs @@ -4,6 +4,7 @@ use std::{ time::{Duration, Instant}, }; use tokio::time::sleep; +use tracing::debug; pub struct Ticker; @@ -56,6 +57,6 @@ impl Ticker { last_tick = Instant::now(); } - log::debug!("Ticker stopped"); + debug!("Ticker stopped"); } } diff --git a/pumpkin/src/world/mod.rs b/pumpkin/src/world/mod.rs index be7d71aa0f..1dd61a1e5a 100644 --- a/pumpkin/src/world/mod.rs +++ b/pumpkin/src/world/mod.rs @@ -5,6 +5,7 @@ use std::{ collections::{BTreeMap, HashMap}, sync::atomic::Ordering, }; +use tracing::{debug, error, info, trace, warn}; pub mod chunker; pub mod explosion; @@ -150,8 +151,8 @@ impl PumpkinError for GetBlockError { false } - fn severity(&self) -> log::Level { - log::Level::Warn + fn severity(&self) -> tracing::Level { + tracing::Level::WARN } fn client_kick_reason(&self) -> Option { @@ -271,7 +272,7 @@ impl World { // Save portal POI to disk let save_result = self.portal_poi.lock().await.save_all(); if let Err(e) = save_result { - log::error!("Failed to save portal POI: {e}"); + error!("Failed to save portal POI: {e}"); } self.level.shutdown().await; @@ -413,7 +414,7 @@ impl World { let packet_data = match JavaClient::serialize_packet_for_version(packet, version) { Ok(packet_data) => packet_data, Err(err) => { - log::error!( + error!( "Failed to serialize packet {} for version {:?}: {}", std::any::type_name::

(), version, @@ -697,7 +698,7 @@ impl World { let total_elapsed = start.elapsed(); if total_elapsed.as_millis() > 50 { - log::debug!( + debug!( "Slow Tick [{}ms]: Chunks: {:?} | Players({}): {:?} | Entities({}): {:?}", total_elapsed.as_millis(), chunk_elapsed, @@ -1525,10 +1526,9 @@ impl World { // This code follows the vanilla packet order let entity_id = player.entity_id(); let gamemode = player.gamemode.load(); - log::debug!( + debug!( "spawning player {}, entity id {}", - player.gameprofile.name, - entity_id + player.gameprofile.name, entity_id ); let client = player.client.java(); @@ -1603,7 +1603,7 @@ impl World { let velocity = player.living_entity.entity.velocity.load(); - log::debug!("Sending player teleport to {}", player.gameprofile.name); + debug!("Sending player teleport to {}", player.gameprofile.name); player.request_teleport(position, yaw, pitch).await; player.living_entity.entity.last_pos.store(position); @@ -1611,7 +1611,7 @@ impl World { let gameprofile = &player.gameprofile; // Firstly, send an info update to our new player, so they can see their skin // and also send their info to everyone else. - log::debug!("Broadcasting player info for {}", player.gameprofile.name); + debug!("Broadcasting player info for {}", player.gameprofile.name); self.broadcast_packet_all(&CPlayerInfoUpdate::new( (PlayerInfoFlags::ADD_PLAYER | PlayerInfoFlags::UPDATE_GAME_MODE @@ -1674,7 +1674,7 @@ impl World { }) .collect::>(); - log::debug!("Sending player info to {}", player.gameprofile.name); + debug!("Sending player info to {}", player.gameprofile.name); client .enqueue_packet(&CPlayerInfoUpdate::new(action_flags.bits(), &entries)) .await; @@ -1682,7 +1682,7 @@ impl World { let gameprofile = &player.gameprofile; - log::debug!("Broadcasting player spawn for {}", player.gameprofile.name); + debug!("Broadcasting player spawn for {}", player.gameprofile.name); // Spawn the player for every client. self.broadcast_packet_except( &[player.gameprofile.id], @@ -1711,7 +1711,7 @@ impl World { let entity = &existing_player.living_entity.entity; let pos = entity.pos.load(); let gameprofile = &existing_player.gameprofile; - log::debug!("Sending player entities to {}", player.gameprofile.name); + debug!("Sending player entities to {}", player.gameprofile.name); client .enqueue_packet(&CSpawnEntity::new( @@ -1792,7 +1792,7 @@ impl World { .await; // Start waiting for level chunks. Sets the "Loading Terrain" screen - log::debug!("Sending waiting chunks to {}", player.gameprofile.name); + debug!("Sending waiting chunks to {}", player.gameprofile.name); client .send_packet_now(&CGameEvent::new(GameEvent::StartWaitingChunks, 0.0)) .await; @@ -2022,7 +2022,7 @@ impl World { // Cross-dimension respawn: get target world from server self.server.upgrade().map_or_else( || { - log::warn!("Could not get server for cross-dimension respawn"); + warn!("Could not get server for cross-dimension respawn"); None }, |server| { @@ -2037,10 +2037,9 @@ impl World { // Handle cross-dimension transfer if we found a different target world let (target_world, position) = if let Some(ref new_world) = target_world { - log::debug!( + debug!( "Cross-dimension respawn: {} -> {}", - self.dimension.minecraft_name, - new_world.dimension.minecraft_name + self.dimension.minecraft_name, new_world.dimension.minecraft_name ); // Remove player from current world @@ -2064,10 +2063,9 @@ impl World { (new_world.as_ref(), position) } else if respawn_dimension != self.dimension { // Cross-dimension failed - fall back to current world's spawn - log::warn!( + warn!( "Target world {:?} not found, using world spawn in {:?}", - respawn_dimension, - self.dimension + respawn_dimension, self.dimension ); // FIXME: This spawn position calculation is incorrect. Should use vanilla's // proper spawn position calculation (see #1381). @@ -2217,7 +2215,7 @@ impl World { 'main: loop { let recv_result = tokio::select! { () = player.client.await_close_interrupt() => { - log::debug!("Canceling player packet processing"); + debug!("Canceling player packet processing"); None }, recv_result = entity_receiver.recv() => { @@ -2233,7 +2231,7 @@ impl World { let chunk = if level.is_chunk_watched(&position) { chunk } else { - log::trace!( + trace!( "Received chunk {:?}, but it is no longer watched... cleaning", &position ); @@ -2241,13 +2239,13 @@ impl World { for (uuid, entity_nbt) in chunk.data.lock().await.iter() { let Some(id) = entity_nbt.get_string("id") else { - log::warn!("Entity has no ID"); + warn!("Entity has no ID"); continue; }; let Some(entity_type) = EntityType::from_name(id.strip_prefix("minecraft:").unwrap_or(id)) else { - log::warn!("Entity has no valid Entity Type {id}"); + warn!("Entity has no valid Entity Type {id}"); continue; }; // Pos is zero since it will read from nbt @@ -2305,13 +2303,13 @@ impl World { for (uuid, entity_nbt) in chunk.data.lock().await.iter() { let Some(id) = entity_nbt.get_string("id") else { - log::debug!("Entity has no ID"); + debug!("Entity has no ID"); continue; }; let Some(entity_type) = EntityType::from_name(id.strip_prefix("minecraft:").unwrap_or(id)) else { - log::warn!("Entity has no valid Entity Type {id}"); + warn!("Entity has no valid Entity Type {id}"); continue; }; // Pos is zero since it will read from nbt @@ -2337,7 +2335,7 @@ impl World { } #[cfg(debug_assertions)] - log::debug!("Chunks queued after {}ms", inst.elapsed().as_millis()); + debug!("Chunks queued after {}ms", inst.elapsed().as_millis()); }); } @@ -2597,7 +2595,8 @@ impl World { for player in current_players.iter() { player.send_system_message(&event.join_message).await; } - log::info!("{}", event.join_message.to_pretty_console()); + // TODO: Switch to structured logging, e.g. info!(player = %name, "connected") + info!("{}", event.join_message.to_pretty_console()); } }); Ok(()) @@ -2667,7 +2666,7 @@ impl World { for player in self.players.load().iter() { player.send_system_message(&event.leave_message).await; } - log::info!("{}", event.leave_message.to_pretty_console()); + info!("{}", event.leave_message.to_pretty_console()); } } } diff --git a/pumpkin/src/world/scoreboard.rs b/pumpkin/src/world/scoreboard.rs index 121a1cbc96..7c852826a0 100644 --- a/pumpkin/src/world/scoreboard.rs +++ b/pumpkin/src/world/scoreboard.rs @@ -7,6 +7,7 @@ use pumpkin_protocol::{ java::client::play::{CDisplayObjective, CUpdateObjectives, CUpdateScore, RenderType}, }; use pumpkin_util::text::TextComponent; +use tracing::warn; use super::World; @@ -20,7 +21,7 @@ impl Scoreboard { pub async fn add_objective(&mut self, world: &World, objective: ScoreboardObjective<'_>) { if self.objectives.contains_key(objective.name) { // Maybe make this an error? - log::warn!( + warn!( "Tried to create an objective which already exists: {}", &objective.name ); @@ -45,7 +46,7 @@ impl Scoreboard { pub async fn update_score(&self, world: &World, score: ScoreboardScore<'_>) { if self.objectives.contains_key(score.objective_name) { - log::warn!( + warn!( "Tried to place a score into an objective which does not exist: {}", &score.objective_name );