diff --git a/CHANGELOG.md b/CHANGELOG.md index 0d2634c4bb..589b305a28 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -37,6 +37,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - Energy regen resets on last ability use instead of on wield - Fixed unable to use ability; Secondary and ability3 (fire rod) will now automatically wield - Gliding is now a toggle that can be triggered from the ground +- Replaced `log` with `tracing` in all crates ### Removed diff --git a/Cargo.lock b/Cargo.lock index 7a15df740c..7c3998c28b 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -571,17 +571,6 @@ dependencies = [ "objc", ] -[[package]] -name = "colored" -version = "1.9.3" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f4ffc801dacf156c5854b9df4f425a626539c3a6ef7893cc0c5084a23f0b6c59" -dependencies = [ - "atty", - "lazy_static", - "winapi 0.3.8", -] - [[package]] name = "conrod_core" version = "0.63.0" @@ -1136,19 +1125,6 @@ version = "1.5.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "bb1f6b1ce1c140482ea30ddd3335fc0024ac7ee112895426e0a629a6c20adfe3" -[[package]] -name = "env_logger" -version = "0.6.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "aafcde04e90a5226a6443b7aabdb016ba2f8307c847d524724bd9b346dd1a2d3" -dependencies = [ - "atty", - "humantime", - "log", - "regex", - "termcolor", -] - [[package]] name = "error-chain" version = "0.12.2" @@ -1210,17 +1186,6 @@ dependencies = [ "synstructure", ] -[[package]] -name = "fern" -version = "0.5.9" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "e69ab0d5aca163e388c3a49d284fed6c3d0810700e77c5ae2756a50ec1a4daaa" -dependencies = [ - "chrono", - "colored", - "log", -] - [[package]] name = "filetime" version = "0.2.10" @@ -1976,15 +1941,6 @@ version = "1.3.4" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "cd179ae861f0c2e53da70d892f5f3029f9594be0c41dc5269cd371691b1dc2f9" -[[package]] -name = "humantime" -version = "1.3.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "df004cfca50ef23c36850aaaa59ad52cc70d0e90243c3c7737a4dd32dc7a3c4f" -dependencies = [ - "quick-error", -] - [[package]] name = "hyper" version = "0.12.35" @@ -3056,17 +3012,6 @@ version = "0.2.8" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "237a5ed80e274dbc66f86bd59c1e25edc039660be53194b5fe0a482e0f2612ea" -[[package]] -name = "pretty_env_logger" -version = "0.3.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "717ee476b1690853d222af4634056d830b5197ffd747726a9a1eee6da9f49074" -dependencies = [ - "chrono", - "env_logger", - "log", -] - [[package]] name = "proc-macro-hack" version = "0.5.16" @@ -4022,15 +3967,6 @@ dependencies = [ "unicode-xid 0.2.0", ] -[[package]] -name = "termcolor" -version = "1.1.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "bb6bfa289a4d7c5766392812c0a1f4c1ba45afa1ad47803c11e1f407d846d75f" -dependencies = [ - "winapi-util", -] - [[package]] name = "textwrap" version = "0.11.0" @@ -4254,6 +4190,17 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-appender" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1e86a61ff69b54f44ffdf02cf27f2da864639dde602d5f90d9f7ef2ea76629c0" +dependencies = [ + "chrono", + "crossbeam-channel 0.4.2", + "tracing-subscriber", +] + [[package]] name = "tracing-core" version = "0.1.10" @@ -4274,19 +4221,44 @@ dependencies = [ ] [[package]] -name = "tracing-subscriber" -version = "0.2.5" +name = "tracing-log" +version = "0.1.1" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "1d53c40489aa69c9aed21ff483f26886ca8403df33bdc2d2f87c60c1617826d2" +checksum = "5e0f8c7178e13481ff6765bd169b33e8d554c5d2bbede5e32c356194be02b9b9" +dependencies = [ + "lazy_static", + "log", + "tracing-core", +] + +[[package]] +name = "tracing-serde" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b6ccba2f8f16e0ed268fc765d9b7ff22e965e7185d32f8f1ec8294fe17d86e79" +dependencies = [ + "serde", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.2.6" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "04a11b459109e38ff6e1b580bafef4142a11d44889f5d07424cbce2fd2a2a119" dependencies = [ "ansi_term", "chrono", "lazy_static", "matchers", "regex", + "serde", + "serde_json", "sharded-slab", "smallvec 1.4.0", "tracing-core", + "tracing-log", + "tracing-serde", ] [[package]] @@ -4452,8 +4424,8 @@ dependencies = [ name = "veloren-chat-cli" version = "0.6.0" dependencies = [ - "log", - "pretty_env_logger", + "tracing", + "tracing-subscriber", "veloren-client", "veloren-common", ] @@ -4466,9 +4438,9 @@ dependencies = [ "byteorder 1.3.4", "hashbrown", "image", - "log", "num_cpus", "specs", + "tracing", "uvth 3.1.1", "vek", "veloren-common", @@ -4488,7 +4460,6 @@ dependencies = [ "image", "indexmap", "lazy_static", - "log", "lz4-compress", "mio", "notify", @@ -4502,6 +4473,7 @@ dependencies = [ "specs", "specs-idvs", "sum_type", + "tracing", "vek", ] @@ -4518,7 +4490,6 @@ dependencies = [ "hashbrown", "lazy_static", "libsqlite3-sys", - "log", "portpicker", "prometheus", "prometheus-static-metric", @@ -4531,6 +4502,7 @@ dependencies = [ "specs", "specs-idvs", "tiny_http", + "tracing", "uvth 3.1.1", "vek", "veloren-common", @@ -4541,8 +4513,8 @@ dependencies = [ name = "veloren-server-cli" version = "0.6.0" dependencies = [ - "log", - "pretty_env_logger", + "tracing", + "tracing-subscriber", "veloren-common", "veloren-server", ] @@ -4567,7 +4539,6 @@ dependencies = [ "dot_vox", "euc", "failure", - "fern", "gfx", "gfx_device_gl", "gfx_window_glutin", @@ -4578,7 +4549,6 @@ dependencies = [ "guillotiere", "hashbrown", "image", - "log", "msgbox", "num 0.2.1", "rand 0.7.3", @@ -4588,6 +4558,10 @@ dependencies = [ "serde_derive", "specs", "specs-idvs", + "tracing", + "tracing-appender", + "tracing-log", + "tracing-subscriber", "treeculler", "uvth 3.1.1", "vek", @@ -4624,13 +4598,11 @@ dependencies = [ "image", "itertools 0.8.2", "lazy_static", - "log", "minifb", "noise", "num 0.2.1", "ordered-float", "packed_simd", - "pretty_env_logger", "rand 0.7.3", "rand_chacha 0.2.2", "rayon", @@ -4638,6 +4610,8 @@ dependencies = [ "roots", "serde", "serde_derive", + "tracing", + "tracing-subscriber", "vek", "veloren-common", ] diff --git a/chat-cli/Cargo.toml b/chat-cli/Cargo.toml index 26496086dd..20acca2c87 100644 --- a/chat-cli/Cargo.toml +++ b/chat-cli/Cargo.toml @@ -8,5 +8,5 @@ edition = "2018" client = { package = "veloren-client", path = "../client" } common = { package = "veloren-common", path = "../common" } -log = "0.4.8" -pretty_env_logger = "0.3.1" +tracing = { version = "0.1", default-features = false } +tracing-subscriber = { version = "0.2.3", default-features = false, features = ["fmt", "chrono", "ansi", "smallvec"] } diff --git a/chat-cli/src/main.rs b/chat-cli/src/main.rs index e982be403e..c7e1aabacf 100644 --- a/chat-cli/src/main.rs +++ b/chat-cli/src/main.rs @@ -3,8 +3,8 @@ use client::{Client, Event}; use common::{clock::Clock, comp}; -use log::{error, info}; use std::{io, net::ToSocketAddrs, sync::mpsc, thread, time::Duration}; +use tracing::{error, info}; const TPS: u64 = 10; // Low value is okay, just reading messages. @@ -20,7 +20,7 @@ fn read_input() -> String { fn main() { // Initialize logging. - pretty_env_logger::init(); + tracing_subscriber::fmt::init(); info!("Starting chat-cli..."); diff --git a/client/Cargo.toml b/client/Cargo.toml index e32e0a3771..73fe3dc06e 100644 --- a/client/Cargo.toml +++ b/client/Cargo.toml @@ -11,7 +11,7 @@ byteorder = "1.3.2" uvth = "3.1.1" image = { version = "0.22.3", default-features = false, features = ["png"] } num_cpus = "1.10.1" -log = "0.4.8" +tracing = { version = "0.1", default-features = false } specs = "0.15.1" vek = { version = "0.11.0", features = ["serde"] } hashbrown = { version = "0.6", features = ["rayon", "serde", "nightly"] } diff --git a/client/src/lib.rs b/client/src/lib.rs index 5e0a84fc0d..bfd16b278c 100644 --- a/client/src/lib.rs +++ b/client/src/lib.rs @@ -36,12 +36,12 @@ use common::{ }; use hashbrown::HashMap; use image::DynamicImage; -use log::{error, warn}; use std::{ net::SocketAddr, sync::Arc, time::{Duration, Instant}, }; +use tracing::{debug, error, warn}; use uvth::{ThreadPool, ThreadPoolBuilder}; use vek::*; @@ -117,7 +117,7 @@ impl Client { } => { // TODO: Display that versions don't match in Voxygen if server_info.git_hash != common::util::GIT_HASH.to_string() { - log::warn!( + warn!( "Server is running {}[{}], you are running {}[{}], versions might be \ incompatible!", server_info.git_hash, @@ -127,7 +127,7 @@ impl Client { ); } - log::debug!("Auth Server: {:?}", server_info.auth_provider); + debug!("Auth Server: {:?}", server_info.auth_provider); // Initialize `State` let mut state = State::default(); @@ -142,7 +142,7 @@ impl Client { assert_eq!(world_map.len(), (map_size.x * map_size.y) as usize); let mut world_map_raw = vec![0u8; 4 * world_map.len()/*map_size.x * map_size.y*/]; LittleEndian::write_u32_into(&world_map, &mut world_map_raw); - log::debug!("Preparing image..."); + debug!("Preparing image..."); let world_map = Arc::new( image::DynamicImage::ImageRgba8({ // Should not fail if the dimensions are correct. @@ -154,7 +154,7 @@ impl Client { // positive x axis to positive y axis is counterclockwise around the z axis. .flipv(), ); - log::debug!("Done preparing image..."); + debug!("Done preparing image..."); (state, entity, server_info, (world_map, map_size)) }, @@ -463,7 +463,7 @@ impl Client { pub fn send_chat(&mut self, message: String) { match validate_chat_msg(&message) { Ok(()) => self.postbox.send_message(ClientMsg::ChatMsg { message }), - Err(ChatMsgValidationError::TooLong) => log::warn!( + Err(ChatMsgValidationError::TooLong) => warn!( "Attempted to send a message that's too long (Over {} bytes)", MAX_BYTES_CHAT_MSG ), @@ -522,7 +522,7 @@ impl Client { // 1) Handle input from frontend. // Pass character actions from frontend input to the player's entity. if let ClientState::Character = self.client_state { - if let Err(err) = self + if let Err(e) = self .state .ecs() .write_storage::<Controller>() @@ -537,9 +537,11 @@ impl Client { .inputs = inputs.clone(); }) { + let entry = self.entity; error!( - "Couldn't access controller component on client entity: {:?}", - err + ?e, + ?entry, + "Couldn't access controller component on client entity" ); } self.postbox @@ -691,7 +693,7 @@ impl Client { /* // Output debug metrics - if log_enabled!(log::Level::Info) && self.tick % 600 == 0 { + if log_enabled!(Level::Info) && self.tick % 600 == 0 { let metrics = self .state .terrain() diff --git a/common/Cargo.toml b/common/Cargo.toml index 3b733d4354..7773463a68 100644 --- a/common/Cargo.toml +++ b/common/Cargo.toml @@ -20,7 +20,7 @@ serde_derive = "1.0" serde_json = "1.0.41" ron = { version = "0.6", default-features = false } bincode = "1.2.0" -log = "0.4.8" +tracing = { version = "0.1", default-features = false } rand = "0.7" rayon = "^1.3.0" lazy_static = "1.4.0" diff --git a/common/src/assets/mod.rs b/common/src/assets/mod.rs index 05ff190eb7..e3737728b6 100644 --- a/common/src/assets/mod.rs +++ b/common/src/assets/mod.rs @@ -5,7 +5,6 @@ use dot_vox::DotVoxData; use hashbrown::HashMap; use image::DynamicImage; use lazy_static::lazy_static; -use log::error; use serde_json::Value; use std::{ any::Any, @@ -15,6 +14,7 @@ use std::{ path::PathBuf, sync::{Arc, RwLock}, }; +use tracing::{error, trace}; /// The error returned by asset loading functions #[derive(Debug, Clone)] @@ -120,8 +120,8 @@ pub fn load_glob<A: Asset + 'static>(specifier: &str) -> Result<Arc<Vec<Arc<A>>> load(&specifier.replace("*", &name)) .map_err(|e| { error!( - "Failed to load \"{}\" as part of glob \"{}\" with error: {:?}", - name, specifier, e + ?e, + "Failed to load \"{}\" as part of glob \"{}\"", name, specifier ) }) .ok() @@ -204,8 +204,8 @@ pub fn load_watched<A: Asset + 'static>( indicator.add( path_with_extension.ok_or_else(|| Error::NotFound(path.to_string_lossy().into_owned()))?, move || { - if let Err(err) = reload::<A>(&owned_specifier) { - error!("Error reloading {}: {:#?}", &owned_specifier, err); + if let Err(e) = reload::<A>(&owned_specifier) { + error!(?e, ?owned_specifier, "Error reloading owned_specifier"); } }, ); @@ -351,7 +351,7 @@ pub fn load_file(specifier: &str, endings: &[&str]) -> Result<BufReader<File>, E let mut path = path.clone(); path.set_extension(ending); - trace!("Trying to access \"{:?}\"", path); + trace!(?path, "Trying to access"); if let Ok(file) = File::open(path) { return Ok(BufReader::new(file)); } @@ -367,7 +367,7 @@ pub fn load_file_glob(specifier: &str, endings: &[&str]) -> Result<BufReader<Fil let mut path = path.clone(); path.set_extension(ending); - debug!("Trying to access \"{:?}\"", path); + trace!(?path, "Trying to access"); if let Ok(file) = File::open(path) { return Ok(BufReader::new(file)); } diff --git a/common/src/assets/watch.rs b/common/src/assets/watch.rs index 3fd652385e..f425c106f1 100644 --- a/common/src/assets/watch.rs +++ b/common/src/assets/watch.rs @@ -1,6 +1,5 @@ use crossbeam::channel::{select, unbounded, Receiver, Sender}; use lazy_static::lazy_static; -use log::warn; use notify::{Event, EventKind, RecommendedWatcher, RecursiveMode, Watcher as _}; use std::{ collections::HashMap, @@ -11,6 +10,7 @@ use std::{ }, thread, }; +use tracing::{error, warn}; type Handler = Box<dyn Fn() + Send>; @@ -50,8 +50,8 @@ impl Watcher { } }, None => { - if let Err(err) = self.watcher.watch(path.clone(), RecursiveMode::Recursive) { - warn!("Could not start watching {:#?} due to: {}", &path, err); + if let Err(e) = self.watcher.watch(path.clone(), RecursiveMode::Recursive) { + warn!(?e, ?path, "Could not start watching file"); return; } self.watching.insert(path, (handler, vec![signal])); @@ -121,7 +121,7 @@ impl Watcher { recv(self.event_rx) -> res => match res { Ok(Ok(event)) => self.handle_event(event), // Notify Error - Ok(Err(err)) => error!("Notify error: {}", err), + Ok(Err(e)) => error!(?e, "Notify error"), // Disconnected Err(_) => (), }, diff --git a/common/src/cmd.rs b/common/src/cmd.rs index f54a27997c..4a803c7c5d 100644 --- a/common/src/cmd.rs +++ b/common/src/cmd.rs @@ -1,6 +1,7 @@ use crate::{assets, comp, npc}; use lazy_static::lazy_static; use std::{ops::Deref, path::Path, str::FromStr}; +use tracing::warn; /// Struct representing a command that a user can run from server chat. pub struct ChatCommandData { diff --git a/common/src/comp/inventory/slot.rs b/common/src/comp/inventory/slot.rs index aefdd5c503..8bcf69edff 100644 --- a/common/src/comp/inventory/slot.rs +++ b/common/src/comp/inventory/slot.rs @@ -1,6 +1,6 @@ use crate::{comp, comp::item}; use comp::{Inventory, Loadout}; -use log::warn; +use tracing::warn; #[derive(Clone, Copy, PartialEq, Debug, Serialize, Deserialize)] pub enum Slot { diff --git a/common/src/hierarchical.rs b/common/src/hierarchical.rs index 32dcb3e747..91feaad848 100644 --- a/common/src/hierarchical.rs +++ b/common/src/hierarchical.rs @@ -60,10 +60,12 @@ impl ChunkPath { } } - //let neighbors: Vec<Vec2<i32>> = directions.into_iter().map(|dir| dir + pos).collect(); + //let neighbors: Vec<Vec2<i32>> = directions.into_iter().map(|dir| dir + + // pos).collect(); neighbors.into_iter() } + pub fn worldpath_get_neighbors<V: RectRasterableVol + ReadVol + Debug>( &mut self, vol: &VolGrid2d<V>, @@ -95,6 +97,7 @@ impl ChunkPath { .collect(); neighbors.into_iter() } + pub fn is_valid_space<V: RectRasterableVol + ReadVol + Debug>( &mut self, vol: &VolGrid2d<V>, @@ -107,13 +110,14 @@ impl ChunkPath { is_within_chunk = chunk_path .iter() .any(|new_pos| new_pos.cmpeq(&vol.pos_key(pos)).iter().all(|e| *e)); - } + }, _ => { //println!("No chunk path"); - } + }, } return is_walkable_position && is_within_chunk; } + pub fn get_worldpath<V: RectRasterableVol + ReadVol + Debug>( &mut self, vol: &VolGrid2d<V>, @@ -132,6 +136,4 @@ pub fn chunk_euclidean_distance(start: &Vec2<i32>, end: &Vec2<i32>) -> f32 { istart.distance(iend) } -pub fn chunk_transition_cost(_start: &Vec2<i32>, _end: &Vec2<i32>) -> f32 { - 1.0f32 -} +pub fn chunk_transition_cost(_start: &Vec2<i32>, _end: &Vec2<i32>) -> f32 { 1.0f32 } diff --git a/common/src/lib.rs b/common/src/lib.rs index 99f9020b76..213587d337 100644 --- a/common/src/lib.rs +++ b/common/src/lib.rs @@ -11,7 +11,6 @@ )] #[macro_use] extern crate serde_derive; -#[macro_use] extern crate log; pub mod assets; pub mod astar; diff --git a/common/src/net/post.rs b/common/src/net/post.rs index 2dd7620c05..5912e323e9 100644 --- a/common/src/net/post.rs +++ b/common/src/net/post.rs @@ -1,29 +1,21 @@ -use std::{ - fmt, - thread, - net::{SocketAddr, Shutdown}, - sync::mpsc::TryRecvError, - io::{self, Read, Write}, - collections::VecDeque, - time::Duration, - convert::TryFrom, -}; -use serde; -use mio::{ - net::{TcpListener, TcpStream}, - Events, - Poll, - PollOpt, - Ready, - Token, -}; -use mio_extras::channel::{ - channel, - Receiver, - Sender, -}; use bincode; use middleman::Middleman; +use mio::{ + net::{TcpListener, TcpStream}, + Events, Poll, PollOpt, Ready, Token, +}; +use mio_extras::channel::{channel, Receiver, Sender}; +use serde; +use std::{ + collections::VecDeque, + convert::TryFrom, + fmt, + io::{self, Read, Write}, + net::{Shutdown, SocketAddr}, + sync::mpsc::TryRecvError, + thread, + time::Duration, +}; #[derive(Clone, Debug, PartialEq)] pub enum Error { @@ -34,37 +26,29 @@ pub enum Error { } impl From<io::Error> for Error { - fn from(err: io::Error) -> Self { - Error::Network - } + fn from(err: io::Error) -> Self { Error::Network } } impl From<TryRecvError> for Error { - fn from(err: TryRecvError) -> Self { - Error::Internal - } + fn from(err: TryRecvError) -> Self { Error::Internal } } impl From<bincode::ErrorKind> for Error { - fn from(err: bincode::ErrorKind) -> Self { - Error::InvalidMsg - } + fn from(err: bincode::ErrorKind) -> Self { Error::InvalidMsg } } impl<T> From<mio_extras::channel::SendError<T>> for Error { - fn from(err: mio_extras::channel::SendError<T>) -> Self { - Error::Internal - } + fn from(err: mio_extras::channel::SendError<T>) -> Self { Error::Internal } } pub trait PostSend = 'static + serde::Serialize + Send + middleman::Message; pub trait PostRecv = 'static + serde::de::DeserializeOwned + Send + middleman::Message; -const TCP_TOK: Token = Token(0); -const CTRL_TOK: Token = Token(1); -const POSTBOX_TOK: Token = Token(2); -const SEND_TOK: Token = Token(3); -const RECV_TOK: Token = Token(4); +const TCP_TOK: Token = Token(0); +const CTRL_TOK: Token = Token(1); +const POSTBOX_TOK: Token = Token(2); +const SEND_TOK: Token = Token(3); +const RECV_TOK: Token = Token(4); const MIDDLEMAN_TOK: Token = Token(5); const MAX_MSG_BYTES: usize = 1 << 28; @@ -95,12 +79,8 @@ impl<S: PostSend, R: PostRecv> PostOffice<S, R> { let office_poll = Poll::new()?; office_poll.register(&postbox_rx, POSTBOX_TOK, Ready::readable(), PollOpt::edge())?; - let worker = thread::spawn(move || office_worker( - worker_poll, - tcp_listener, - ctrl_rx, - postbox_tx, - )); + let worker = + thread::spawn(move || office_worker(worker_poll, tcp_listener, ctrl_rx, postbox_tx)); Ok(Self { worker: Some(worker), @@ -111,11 +91,9 @@ impl<S: PostSend, R: PostRecv> PostOffice<S, R> { }) } - pub fn error(&self) -> Option<Error> { - self.err.clone() - } + pub fn error(&self) -> Option<Error> { self.err.clone() } - pub fn new_connections(&mut self) -> impl ExactSizeIterator<Item=PostBox<S, R>> { + pub fn new_connections(&mut self) -> impl ExactSizeIterator<Item = PostBox<S, R>> { let mut conns = VecDeque::new(); if self.err.is_some() { @@ -123,10 +101,7 @@ impl<S: PostSend, R: PostRecv> PostOffice<S, R> { } let mut events = Events::with_capacity(64); - if let Err(err) = self.poll.poll( - &mut events, - Some(Duration::new(0, 0)), - ) { + if let Err(err) = self.poll.poll(&mut events, Some(Duration::new(0, 0))) { self.err = Some(err.into()); return conns.into_iter(); } @@ -188,12 +163,10 @@ fn office_worker<S: PostSend, R: PostRecv>( }, } }, - TCP_TOK => postbox_tx.send( - match tcp_listener.accept() { - Ok((stream, _)) => PostBox::from_tcpstream(stream), - Err(err) => Err(err.into()), - } - )?, + TCP_TOK => postbox_tx.send(match tcp_listener.accept() { + Ok((stream, _)) => PostBox::from_tcpstream(stream), + Err(err) => Err(err.into()), + })?, tok => panic!("Unexpected event token '{:?}'", tok), } } @@ -211,7 +184,9 @@ pub struct PostBox<S: PostSend, R: PostRecv> { impl<S: PostSend, R: PostRecv> PostBox<S, R> { pub fn to_server<A: Into<SocketAddr>>(addr: A) -> Result<Self, Error> { - Self::from_tcpstream(TcpStream::from_stream(std::net::TcpStream::connect(&addr.into())?)?) + Self::from_tcpstream(TcpStream::from_stream(std::net::TcpStream::connect( + &addr.into(), + )?)?) } fn from_tcpstream(tcp_stream: TcpStream) -> Result<Self, Error> { @@ -220,20 +195,21 @@ impl<S: PostSend, R: PostRecv> PostBox<S, R> { let (recv_tx, recv_rx) = channel(); let worker_poll = Poll::new()?; - worker_poll.register(&tcp_stream, TCP_TOK, Ready::readable() | Ready::writable(), PollOpt::edge())?; + worker_poll.register( + &tcp_stream, + TCP_TOK, + Ready::readable() | Ready::writable(), + PollOpt::edge(), + )?; worker_poll.register(&ctrl_rx, CTRL_TOK, Ready::readable(), PollOpt::edge())?; worker_poll.register(&send_rx, SEND_TOK, Ready::readable(), PollOpt::edge())?; let postbox_poll = Poll::new()?; postbox_poll.register(&recv_rx, RECV_TOK, Ready::readable(), PollOpt::edge())?; - let worker = thread::spawn(move || postbox_worker( - worker_poll, - tcp_stream, - ctrl_rx, - send_rx, - recv_tx, - )); + let worker = thread::spawn(move || { + postbox_worker(worker_poll, tcp_stream, ctrl_rx, send_rx, recv_tx) + }); Ok(Self { worker: Some(worker), @@ -245,13 +221,9 @@ impl<S: PostSend, R: PostRecv> PostBox<S, R> { }) } - pub fn error(&self) -> Option<Error> { - self.err.clone() - } + pub fn error(&self) -> Option<Error> { self.err.clone() } - pub fn send(&mut self, data: S) { - let _ = self.send_tx.send(data); - } + pub fn send(&mut self, data: S) { let _ = self.send_tx.send(data); } // TODO: This method is super messy. pub fn next_message(&mut self) -> Option<R> { @@ -261,10 +233,7 @@ impl<S: PostSend, R: PostRecv> PostBox<S, R> { loop { let mut events = Events::with_capacity(10); - if let Err(err) = self.poll.poll( - &mut events, - Some(Duration::new(0, 0)), - ) { + if let Err(err) = self.poll.poll(&mut events, Some(Duration::new(0, 0))) { self.err = Some(err.into()); return None; } @@ -292,7 +261,7 @@ impl<S: PostSend, R: PostRecv> PostBox<S, R> { } } - pub fn new_messages(&mut self) -> impl ExactSizeIterator<Item=R> { + pub fn new_messages(&mut self) -> impl ExactSizeIterator<Item = R> { let mut msgs = VecDeque::new(); if self.err.is_some() { @@ -300,10 +269,7 @@ impl<S: PostSend, R: PostRecv> PostBox<S, R> { } let mut events = Events::with_capacity(64); - if let Err(err) = self.poll.poll( - &mut events, - Some(Duration::new(0, 0)), - ) { + if let Err(err) = self.poll.poll(&mut events, Some(Duration::new(0, 0))) { self.err = Some(err.into()); return msgs.into_iter(); } @@ -347,7 +313,10 @@ fn postbox_worker<S: PostSend, R: PostRecv>( send_rx: Receiver<S>, recv_tx: Sender<Result<R, Error>>, ) -> Result<(), Error> { - fn try_tcp_send(tcp_stream: &mut TcpStream, chunks: &mut VecDeque<Vec<u8>>) -> Result<(), Error> { + fn try_tcp_send( + tcp_stream: &mut TcpStream, + chunks: &mut VecDeque<Vec<u8>>, + ) -> Result<(), Error> { loop { let chunk = match chunks.pop_front() { Some(chunk) => chunk, @@ -389,16 +358,15 @@ fn postbox_worker<S: PostSend, R: PostRecv>( for event in &events { match event.token() { - CTRL_TOK => - match ctrl_rx.try_recv() { - Ok(CtrlMsg::Shutdown) => { - break 'work; - }, - Err(TryRecvError::Empty) => (), - Err(err) => { - recv_tx.send(Err(err.into()))?; - break 'work; - }, + CTRL_TOK => match ctrl_rx.try_recv() { + Ok(CtrlMsg::Shutdown) => { + break 'work; + }, + Err(TryRecvError::Empty) => (), + Err(err) => { + recv_tx.send(Err(err.into()))?; + break 'work; + }, }, SEND_TOK => loop { match send_rx.try_recv() { @@ -411,11 +379,7 @@ fn postbox_worker<S: PostSend, R: PostRecv>( }, }; - let mut bytes = msg_bytes - .len() - .to_le_bytes() - .as_ref() - .to_vec(); + let mut bytes = msg_bytes.len().to_le_bytes().as_ref().to_vec(); bytes.append(&mut msg_bytes); bytes @@ -450,49 +414,52 @@ fn postbox_worker<S: PostSend, R: PostRecv>( }, } match &mut recv_state { - RecvState::ReadHead(head) => if head.len() == 8 { - let len = usize::from_le_bytes(<[u8; 8]>::try_from(head.as_slice()).unwrap()); - if len > MAX_MSG_BYTES { - println!("TOO BIG! {:x}", len); - recv_tx.send(Err(Error::InvalidMsg))?; - break 'work; - } else if len == 0 { - recv_state = RecvState::ReadHead(Vec::with_capacity(8)); - break; - } else { - recv_state = RecvState::ReadBody( - len, - Vec::new(), + RecvState::ReadHead(head) => { + if head.len() == 8 { + let len = usize::from_le_bytes( + <[u8; 8]>::try_from(head.as_slice()).unwrap(), ); - } - } else { - let mut b = [0; 1]; - match tcp_stream.read(&mut b) { - Ok(0) => {}, - Ok(_) => head.push(b[0]), - Err(_) => break, + if len > MAX_MSG_BYTES { + println!("TOO BIG! {:x}", len); + recv_tx.send(Err(Error::InvalidMsg))?; + break 'work; + } else if len == 0 { + recv_state = RecvState::ReadHead(Vec::with_capacity(8)); + break; + } else { + recv_state = RecvState::ReadBody(len, Vec::new()); + } + } else { + let mut b = [0; 1]; + match tcp_stream.read(&mut b) { + Ok(0) => {}, + Ok(_) => head.push(b[0]), + Err(_) => break, + } } }, - RecvState::ReadBody(len, body) => if body.len() == *len { - match bincode::deserialize(&body) { - Ok(msg) => { - recv_tx.send(Ok(msg))?; - recv_state = RecvState::ReadHead(Vec::with_capacity(8)); - }, - Err(err) => { - recv_tx.send(Err((*err).into()))?; - break 'work; - }, - } - } else { - let left = *len - body.len(); - let mut buf = vec![0; left]; - match tcp_stream.read(&mut buf) { - Ok(_) => body.append(&mut buf), - Err(err) => { - recv_tx.send(Err(err.into()))?; - break 'work; - }, + RecvState::ReadBody(len, body) => { + if body.len() == *len { + match bincode::deserialize(&body) { + Ok(msg) => { + recv_tx.send(Ok(msg))?; + recv_state = RecvState::ReadHead(Vec::with_capacity(8)); + }, + Err(err) => { + recv_tx.send(Err((*err).into()))?; + break 'work; + }, + } + } else { + let left = *len - body.len(); + let mut buf = vec![0; left]; + match tcp_stream.read(&mut buf) { + Ok(_) => body.append(&mut buf), + Err(err) => { + recv_tx.send(Err(err.into()))?; + break 'work; + }, + } } }, } diff --git a/common/src/net/post2.rs b/common/src/net/post2.rs index 6429eedb24..e4ba5b31cb 100644 --- a/common/src/net/post2.rs +++ b/common/src/net/post2.rs @@ -1,5 +1,4 @@ use crossbeam::channel; -use log::warn; use serde::{de::DeserializeOwned, Serialize}; use std::{ collections::VecDeque, @@ -14,6 +13,7 @@ use std::{ thread, time::Duration, }; +use tracing::warn; #[derive(Clone, Debug)] pub enum Error { diff --git a/common/src/sync/packet.rs b/common/src/sync/packet.rs index 37e47ae30b..ed9d93f4d2 100644 --- a/common/src/sync/packet.rs +++ b/common/src/sync/packet.rs @@ -1,5 +1,4 @@ use super::{track::UpdateTracker, uid::Uid}; -use log::error; use serde::{de::DeserializeOwned, Deserialize, Serialize}; use specs::{Component, Entity, Join, ReadStorage, World, WorldExt}; use std::{ @@ -7,6 +6,7 @@ use std::{ fmt::Debug, marker::PhantomData, }; +use tracing::error; /// Implemented by type that carries component data for insertion and /// modification The assocatied `Phantom` type only carries information about @@ -21,8 +21,8 @@ pub trait CompPacket: Clone + Debug + Send + 'static { /// Useful for implementing CompPacket trait pub fn handle_insert<C: Component>(comp: C, entity: Entity, world: &World) { - if let Err(err) = world.write_storage::<C>().insert(entity, comp) { - error!("Error inserting : {:?}", err); + if let Err(e) = world.write_storage::<C>().insert(entity, comp) { + error!(?e, "Error inserting"); } } /// Useful for implementing CompPacket trait @@ -31,8 +31,8 @@ pub fn handle_modify<C: Component + Debug>(comp: C, entity: Entity, world: &Worl *c = comp } else { error!( - "Error modifying synced component: {:?}, it doesn't seem to exist", - comp + ?comp, + "Error modifying synced component, it doesn't seem to exist" ); } } diff --git a/common/src/sync/sync_ext.rs b/common/src/sync/sync_ext.rs index a8224b62a5..17ac09fff9 100644 --- a/common/src/sync/sync_ext.rs +++ b/common/src/sync/sync_ext.rs @@ -5,12 +5,12 @@ use super::{ track::UpdateTracker, uid::{Uid, UidAllocator}, }; -use log::error; use specs::{ saveload::{MarkedBuilder, MarkerAllocator}, world::Builder, WorldExt, }; +use tracing::error; pub trait WorldSyncExt { fn register_sync_marker(&mut self); @@ -90,8 +90,8 @@ impl WorldSyncExt for specs::World { // Clear from uid allocator let maybe_entity = self.write_resource::<UidAllocator>().remove_entity(uid); if let Some(entity) = maybe_entity { - if let Err(err) = self.delete_entity(entity) { - error!("Failed to delete entity: {:?}", err); + if let Err(e) = self.delete_entity(entity) { + error!(?e, "Failed to delete entity"); } } } diff --git a/common/src/util/dir.rs b/common/src/util/dir.rs index 763c527fdd..41bfe0ffbd 100644 --- a/common/src/util/dir.rs +++ b/common/src/util/dir.rs @@ -1,3 +1,4 @@ +use tracing::warn; use vek::*; /// Type representing a direction using Vec3 that is normalized and NaN free @@ -18,10 +19,16 @@ impl From<SerdeDir> for Dir { fn from(dir: SerdeDir) -> Self { let dir = dir.0; if dir.map(f32::is_nan).reduce_or() { - warn!("Deserialized dir containing NaNs, replacing with default"); + warn!( + ?dir, + "Deserialized dir containing NaNs, replacing with default" + ); Default::default() } else if !dir.is_normalized() { - warn!("Deserialized unnormalized dir, replacing with default"); + warn!( + ?dir, + "Deserialized unnormalized dir, replacing with default" + ); Default::default() } else { Self(dir) @@ -108,7 +115,7 @@ fn slerp_normalized(from: vek::Vec3<f32>, to: vek::Vec3<f32>, factor: f32) -> ve }; if unnormalized { - panic!("Called slerp_normalized with unnormalized from: {:?}", from); + panic!("Called slerp_normalized with unnormalized `from`: {}", from); } } @@ -121,7 +128,7 @@ fn slerp_normalized(from: vek::Vec3<f32>, to: vek::Vec3<f32>, factor: f32) -> ve }; if unnormalized { - panic!("Called slerp_normalized with unnormalized to: {:?}", to); + panic!("Called slerp_normalized with unnormalized `to`: {}", to); } } diff --git a/server-cli/Cargo.toml b/server-cli/Cargo.toml index a7e64705d5..2f46bb8e13 100644 --- a/server-cli/Cargo.toml +++ b/server-cli/Cargo.toml @@ -12,5 +12,5 @@ default = ["worldgen"] server = { package = "veloren-server", path = "../server", default-features = false } common = { package = "veloren-common", path = "../common" } -log = "0.4.8" -pretty_env_logger = "0.3.1" +tracing = { version = "0.1", default-features = false } +tracing-subscriber = { version = "0.2.3", default-features = false, features = ["fmt", "chrono", "ansi", "smallvec"] } diff --git a/server-cli/src/main.rs b/server-cli/src/main.rs index 5b5c9af5f9..d0fdd7ae61 100644 --- a/server-cli/src/main.rs +++ b/server-cli/src/main.rs @@ -2,9 +2,9 @@ #![allow(clippy::option_map_unit_fn)] use common::clock::Clock; -use log::info; use server::{Event, Input, Server, ServerSettings}; use std::time::Duration; +use tracing::info; const TPS: u64 = 30; @@ -14,7 +14,8 @@ fn main() { if let Err(_) = std::env::var("RUST_LOG") { std::env::set_var("RUST_LOG", "info"); } - pretty_env_logger::init(); + + tracing_subscriber::fmt::init(); info!("Starting server..."); @@ -29,7 +30,7 @@ fn main() { let mut server = Server::new(settings).expect("Failed to create server instance!"); info!("Server is ready to accept connections."); - info!("Metrics port: {}", metrics_port); + info!(?metrics_port, "starting metrics at port"); loop { let events = server diff --git a/server/Cargo.toml b/server/Cargo.toml index 12df9946b4..5696b593a1 100644 --- a/server/Cargo.toml +++ b/server/Cargo.toml @@ -14,7 +14,7 @@ world = { package = "veloren-world", path = "../world" } specs-idvs = { git = "https://gitlab.com/veloren/specs-idvs.git" } -log = "0.4.8" +tracing = { version = "0.1", default-features = false } specs = { version = "0.15.1", features = ["shred-derive"] } vek = "0.11.0" uvth = "3.1.1" diff --git a/server/src/auth_provider.rs b/server/src/auth_provider.rs index 61623b6076..d08f8e5b63 100644 --- a/server/src/auth_provider.rs +++ b/server/src/auth_provider.rs @@ -1,8 +1,8 @@ use authc::{AuthClient, AuthToken, Uuid}; use common::msg::RegisterError; use hashbrown::HashMap; -use log::error; use std::str::FromStr; +use tracing::{error, info}; fn derive_uuid(username: &str) -> Uuid { let mut state = 144066263297769815596495629667062367629; @@ -35,7 +35,7 @@ impl AuthProvider { pub fn logout(&mut self, uuid: Uuid) { if self.accounts.remove(&uuid).is_none() { - error!("Attempted to logout user that is not logged in."); + error!(?uuid, "Attempted to logout user that is not logged in."); }; } @@ -45,7 +45,7 @@ impl AuthProvider { match &self.auth_server { // Token from auth server expected Some(srv) => { - log::info!("Validating '{}' token.", &username_or_token); + info!(?username_or_token, "Validating token"); // Parse token let token = AuthToken::from_str(&username_or_token) .map_err(|e| RegisterError::AuthError(e.to_string()))?; @@ -66,7 +66,7 @@ impl AuthProvider { let username = username_or_token; let uuid = derive_uuid(&username); if !self.accounts.contains_key(&uuid) { - log::info!("New User '{}'", username); + info!(?username, "New User"); self.accounts.insert(uuid, username.clone()); Ok((username, uuid)) } else { diff --git a/server/src/cmd.rs b/server/src/cmd.rs index 3fdf6cd6aa..bbceca466e 100644 --- a/server/src/cmd.rs +++ b/server/src/cmd.rs @@ -22,8 +22,8 @@ use specs::{Builder, Entity as EcsEntity, Join, WorldExt}; use vek::*; use world::util::Sampler; -use log::error; use scan_fmt::{scan_fmt, scan_fmt_some}; +use tracing::error; pub trait ChatCommandExt { fn execute(&self, server: &mut Server, entity: EcsEntity, args: String); @@ -1265,8 +1265,8 @@ fn handle_remove_lights( let size = to_delete.len(); for entity in to_delete { - if let Err(err) = server.state.delete_entity_recorded(entity) { - error!("Failed to delete light: {:?}", err); + if let Err(e) = server.state.delete_entity_recorded(entity) { + error!(?e, "Failed to delete light: {:?}", e); } } diff --git a/server/src/events/entity_manipulation.rs b/server/src/events/entity_manipulation.rs index cdc8527f93..8de46e9df8 100644 --- a/server/src/events/entity_manipulation.rs +++ b/server/src/events/entity_manipulation.rs @@ -9,9 +9,9 @@ use common::{ terrain::{Block, TerrainGrid}, vol::{ReadVol, Vox}, }; -use log::error; use rand::seq::SliceRandom; use specs::{join::Join, Entity as EcsEntity, WorldExt}; +use tracing::error; use vek::Vec3; pub fn handle_damage(server: &Server, uid: Uid, change: HealthChange) { @@ -80,13 +80,13 @@ pub fn handle_destroy(server: &mut Server, entity: EcsEntity, cause: HealthSourc .write_storage() .insert(entity, comp::Vel(Vec3::zero())) .err() - .map(|err| error!("Failed to set zero vel on dead client: {:?}", err)); + .map(|e| error!(?e, ?entity, "Failed to set zero vel on dead client")); state .ecs() .write_storage() .insert(entity, comp::ForceUpdate) .err() - .map(|err| error!("Failed to insert ForceUpdate on dead client: {:?}", err)); + .map(|e| error!(?e, ?entity, "Failed to insert ForceUpdate on dead client")); state .ecs() .write_storage::<comp::LightEmitter>() @@ -306,14 +306,14 @@ pub fn handle_destroy(server: &mut Server, entity: EcsEntity, cause: HealthSourc } else { let _ = state .delete_entity_recorded(entity) - .map_err(|err| error!("Failed to delete destroyed entity: {:?}", err)); + .map_err(|e| error!(?e, ?entity, "Failed to delete destroyed entity")); } // TODO: Add Delete(time_left: Duration) component /* // If not a player delete the entity if let Err(err) = state.delete_entity_recorded(entity) { - error!("Failed to delete destroyed entity: {:?}", err); + error!(?e, "Failed to delete destroyed entity"); } */ } @@ -361,10 +361,10 @@ pub fn handle_respawn(server: &Server, entity: EcsEntity) { .write_storage() .insert(entity, comp::ForceUpdate) .err() - .map(|err| { + .map(|e| { error!( - "Error inserting ForceUpdate component when respawning client: {:?}", - err + ?e, + "Error inserting ForceUpdate component when respawning client" ) }); } diff --git a/server/src/events/interaction.rs b/server/src/events/interaction.rs index b07c68bed4..9189803e55 100644 --- a/server/src/events/interaction.rs +++ b/server/src/events/interaction.rs @@ -8,8 +8,8 @@ use common::{ msg::ServerMsg, sync::{Uid, WorldSyncExt}, }; -use log::error; use specs::{world::WorldExt, Entity as EcsEntity}; +use tracing::error; pub fn handle_lantern(server: &mut Server, entity: EcsEntity) { let ecs = server.state_mut().ecs(); @@ -121,12 +121,10 @@ pub fn handle_possess(server: &Server, possessor_uid: Uid, possesse_uid: Uid) { if clients.get_mut(possesse).is_none() { if let Some(mut client) = clients.remove(possessor) { client.notify(ServerMsg::SetPlayerEntity(possesse_uid.into())); - clients.insert(possesse, client).err().map(|e| { - error!( - "Error inserting client component during possession: {:?}", - e - ) - }); + clients + .insert(possesse, client) + .err() + .map(|e| error!(?e, "Error inserting client component during possession")); // Put possess item into loadout let mut loadouts = ecs.write_storage::<comp::Loadout>(); let loadout = loadouts @@ -155,10 +153,7 @@ pub fn handle_possess(server: &Server, possessor_uid: Uid, possesse_uid: Uid) { let mut players = ecs.write_storage::<comp::Player>(); if let Some(player) = players.remove(possessor) { players.insert(possesse, player).err().map(|e| { - error!( - "Error inserting player component during possession: {:?}", - e - ) + error!(?e, "Error inserting player component during possession") }); } } @@ -168,8 +163,8 @@ pub fn handle_possess(server: &Server, possessor_uid: Uid, possesse_uid: Uid) { if let Some(s) = subscriptions.remove(possessor) { subscriptions.insert(possesse, s).err().map(|e| { error!( - "Error inserting subscription component during possession: {:?}", - e + ?e, + "Error inserting subscription component during possession" ) }); } @@ -185,7 +180,7 @@ pub fn handle_possess(server: &Server, possessor_uid: Uid, possesse_uid: Uid) { let mut admins = ecs.write_storage::<comp::Admin>(); if let Some(admin) = admins.remove(possessor) { admins.insert(possesse, admin).err().map(|e| { - error!("Error inserting admin component during possession: {:?}", e) + error!(?e, "Error inserting admin component during possession") }); } } @@ -194,10 +189,7 @@ pub fn handle_possess(server: &Server, possessor_uid: Uid, possesse_uid: Uid) { let mut waypoints = ecs.write_storage::<comp::Waypoint>(); if let Some(waypoint) = waypoints.remove(possessor) { waypoints.insert(possesse, waypoint).err().map(|e| { - error!( - "Error inserting waypoint component during possession {:?}", - e - ) + error!(?e, "Error inserting waypoint component during possession",) }); } } diff --git a/server/src/events/inventory_manip.rs b/server/src/events/inventory_manip.rs index 3c87baac02..a07d50adb2 100644 --- a/server/src/events/inventory_manip.rs +++ b/server/src/events/inventory_manip.rs @@ -9,9 +9,9 @@ use common::{ terrain::block::Block, vol::{ReadVol, Vox}, }; -use log::error; use rand::Rng; use specs::{join::Join, world::WorldExt, Builder, Entity as EcsEntity, WriteStorage}; +use tracing::error; use vek::Vec3; pub fn swap_lantern( @@ -108,7 +108,10 @@ pub fn handle_inventory(server: &mut Server, entity: EcsEntity, manip: comp::Inv let inventory = if let Some(inventory) = inventories.get_mut(entity) { inventory } else { - error!("Can't manipulate inventory, entity doesn't have one"); + error!( + ?entity, + "Can't manipulate inventory, entity doesn't have one" + ); return; }; @@ -220,7 +223,7 @@ pub fn handle_inventory(server: &mut Server, entity: EcsEntity, manip: comp::Inv slot::unequip(slot, inventory, loadout); Some(comp::InventoryUpdateEvent::Used) } else { - error!("Entity doesn't have a loadout, can't unequip..."); + error!(?entity, "Entity doesn't have a loadout, can't unequip..."); None } }, diff --git a/server/src/events/player.rs b/server/src/events/player.rs index f857e4a1a5..ce5f476e00 100644 --- a/server/src/events/player.rs +++ b/server/src/events/player.rs @@ -8,8 +8,8 @@ use common::{ msg::{ClientState, PlayerListUpdate, ServerMsg}, sync::{Uid, UidAllocator}, }; -use log::error; use specs::{saveload::MarkerAllocator, Builder, Entity as EcsEntity, Join, WorldExt}; +use tracing::error; pub fn handle_exit_ingame(server: &mut Server, entity: EcsEntity) { let state = server.state_mut(); @@ -36,8 +36,12 @@ pub fn handle_exit_ingame(server: &mut Server, entity: EcsEntity) { entity_builder.with(uid).build(); } // Delete old entity - if let Err(err) = state.delete_entity_recorded(entity) { - error!("Failed to delete entity when removing character: {:?}", err); + if let Err(e) = state.delete_entity_recorded(entity) { + error!( + ?e, + ?entity, + "Failed to delete entity when removing character" + ); } } @@ -87,8 +91,8 @@ pub fn handle_client_disconnect(server: &mut Server, entity: EcsEntity) -> Event } // Delete client entity - if let Err(err) = state.delete_entity_recorded(entity) { - error!("Failed to delete disconnected client: {:?}", err); + if let Err(e) = state.delete_entity_recorded(entity) { + error!(?e, ?entity, "Failed to delete disconnected client"); } Event::ClientDisconnected { entity } diff --git a/server/src/lib.rs b/server/src/lib.rs index eb74ac30b4..db19408fc0 100644 --- a/server/src/lib.rs +++ b/server/src/lib.rs @@ -38,7 +38,6 @@ use common::{ terrain::TerrainChunkSize, vol::{ReadVol, RectVolSize}, }; -use log::{debug, error}; use metrics::{ServerMetrics, TickMetrics}; use specs::{join::Join, Builder, Entity as EcsEntity, RunNow, SystemData, WorldExt}; use std::{ @@ -48,6 +47,7 @@ use std::{ }; #[cfg(not(feature = "worldgen"))] use test_world::{World, WORLD_SIZE}; +use tracing::{debug, error, info}; use uvth::{ThreadPool, ThreadPoolBuilder}; use vek::*; #[cfg(feature = "worldgen")] @@ -253,19 +253,16 @@ impl Server { // Run pending DB migrations (if any) debug!("Running DB migrations..."); - if let Some(error) = - persistence::run_migrations(&this.server_settings.persistence_db_dir).err() + if let Some(e) = persistence::run_migrations(&this.server_settings.persistence_db_dir).err() { - log::info!("Migration error: {}", format!("{:#?}", error)); + info!(?e, "Migration error"); } - debug!("created veloren server with: {:?}", &settings); + debug!(?settings, "created veloren server with"); - log::info!( - "Server version: {}[{}]", - *common::util::GIT_HASH, - *common::util::GIT_DATE - ); + let git_hash = *common::util::GIT_HASH; + let git_date = *common::util::GIT_DATE; + info!(?git_hash, ?git_date, "Server version",); Ok(this) } @@ -378,8 +375,8 @@ impl Server { .collect::<Vec<_>>() }; for entity in to_delete { - if let Err(err) = self.state.delete_entity_recorded(entity) { - error!("Failed to delete agent outside the terrain: {:?}", err); + if let Err(e) = self.state.delete_entity_recorded(entity) { + error!(?e, "Failed to delete agent outside the terrain"); } } @@ -536,7 +533,7 @@ impl Server { .build(); // Send client all the tracked components currently attached to its entity as // well as synced resources (currently only `TimeOfDay`) - log::debug!("Starting initial sync with client."); + debug!("Starting initial sync with client."); self.state .ecs() .write_storage::<Client>() @@ -550,7 +547,7 @@ impl Server { time_of_day: *self.state.ecs().read_resource(), world_map: (WORLD_SIZE.map(|e| e as u32), self.map.clone()), }); - log::debug!("Done initial sync with client."); + debug!("Done initial sync with client."); frontend_events.push(Event::ClientConnected { entity }); } diff --git a/server/src/metrics.rs b/server/src/metrics.rs index 89faf74114..a5e1c915b3 100644 --- a/server/src/metrics.rs +++ b/server/src/metrics.rs @@ -1,4 +1,3 @@ -use log::{debug, error}; use prometheus::{Encoder, Gauge, IntGauge, IntGaugeVec, Opts, Registry, TextEncoder}; use std::{ convert::TryInto, @@ -11,6 +10,7 @@ use std::{ thread, time::{Duration, SystemTime, UNIX_EPOCH}, }; +use tracing::{debug, error}; pub struct TickMetrics { pub chonks_count: IntGauge, @@ -142,7 +142,7 @@ impl ServerMetrics { Ok(Some(rq)) => rq, Ok(None) => continue, Err(e) => { - println!("error: {}", e); + error!(?e, "metrics http server error"); break; }, }; @@ -157,8 +157,8 @@ impl ServerMetrics { ); if let Err(e) = request.respond(response) { error!( - "The metrics HTTP server had encountered and error with answering, {}", - e + ?e, + "The metrics HTTP server had encountered and error with answering", ); } } diff --git a/server/src/persistence/character.rs b/server/src/persistence/character.rs index c0b6650b63..58a08594ff 100644 --- a/server/src/persistence/character.rs +++ b/server/src/persistence/character.rs @@ -16,6 +16,7 @@ use common::{ }; use crossbeam::channel; use diesel::prelude::*; +use tracing::{error, warn}; type CharacterListResult = Result<Vec<CharacterItem>, Error>; @@ -54,10 +55,9 @@ pub fn load_character_data( .values(&row) .execute(&connection) { - log::warn!( + warn!( "Failed to create an inventory record for character {}: {}", - &character_data.id, - error + &character_data.id, error ) } @@ -77,14 +77,15 @@ pub fn load_character_data( let row = NewLoadout::from((character_data.id, &default_loadout)); - if let Err(error) = diesel::insert_into(schema::loadout::table) + if let Err(e) = diesel::insert_into(schema::loadout::table) .values(&row) .execute(&connection) { - log::warn!( - "Failed to create an loadout record for character {}: {}", - &character_data.id, - error + let char_id = character_data.id; + warn!( + ?e, + ?char_id, + "Failed to create an loadout record for character", ) } @@ -232,7 +233,7 @@ pub fn create_character( .values(&new_loadout) .execute(&connection)?; }, - _ => log::warn!("Creating non-humanoid characters is not supported."), + _ => warn!("Creating non-humanoid characters is not supported."), }; Ok(()) @@ -315,8 +316,8 @@ impl CharacterUpdater { }) .collect(); - if let Err(err) = self.update_tx.as_ref().unwrap().send(updates) { - log::error!("Could not send stats updates: {:?}", err); + if let Err(e) = self.update_tx.as_ref().unwrap().send(updates) { + error!(?e, "Could not send stats updates"); } } @@ -334,7 +335,7 @@ impl CharacterUpdater { fn batch_update(updates: impl Iterator<Item = (i32, CharacterUpdateData)>, db_dir: &str) { let connection = establish_connection(db_dir); - if let Err(err) = connection.transaction::<_, diesel::result::Error, _>(|| { + if let Err(e) = connection.transaction::<_, diesel::result::Error, _>(|| { updates.for_each( |(character_id, (stats_update, inventory_update, loadout_update))| { update( @@ -349,7 +350,7 @@ fn batch_update(updates: impl Iterator<Item = (i32, CharacterUpdateData)>, db_di Ok(()) }) { - log::error!("Error during stats batch update transaction: {:?}", err); + error!(?e, "Error during stats batch update transaction"); } } @@ -360,50 +361,42 @@ fn update( loadout: &LoadoutUpdate, connection: &SqliteConnection, ) { - if let Err(error) = + if let Err(e) = diesel::update(schema::stats::table.filter(schema::stats::character_id.eq(character_id))) .set(stats) .execute(connection) { - log::warn!( - "Failed to update stats for character: {:?}: {:?}", - character_id, - error - ) + warn!(?e, ?character_id, "Failed to update stats for character",) } - if let Err(error) = diesel::update( + if let Err(e) = diesel::update( schema::inventory::table.filter(schema::inventory::character_id.eq(character_id)), ) .set(inventory) .execute(connection) { - log::warn!( - "Failed to update inventory for character: {:?}: {:?}", - character_id, - error + warn!( + ?e, + ?character_id, + "Failed to update inventory for character", ) } - if let Err(error) = diesel::update( + if let Err(e) = diesel::update( schema::loadout::table.filter(schema::loadout::character_id.eq(character_id)), ) .set(loadout) .execute(connection) { - log::warn!( - "Failed to update loadout for character: {:?}: {:?}", - character_id, - error - ) + warn!(?e, ?character_id, "Failed to update loadout for character",) } } impl Drop for CharacterUpdater { fn drop(&mut self) { drop(self.update_tx.take()); - if let Err(err) = self.handle.take().unwrap().join() { - log::error!("Error from joining character update thread: {:?}", err); + if let Err(e) = self.handle.take().unwrap().join() { + error!(?e, "Error from joining character update thread"); } } } diff --git a/server/src/persistence/mod.rs b/server/src/persistence/mod.rs index e3e788b72e..25363b00e3 100644 --- a/server/src/persistence/mod.rs +++ b/server/src/persistence/mod.rs @@ -9,6 +9,7 @@ extern crate diesel; use diesel::{connection::SimpleConnection, prelude::*}; use diesel_migrations::embed_migrations; use std::{env, fs, path::PathBuf}; +use tracing::warn; // See: https://docs.rs/diesel_migrations/1.4.0/diesel_migrations/macro.embed_migrations.html // This macro is called at build-time, and produces the necessary migration info @@ -30,16 +31,16 @@ fn establish_connection(db_dir: &str) -> SqliteConnection { // Use Write-Ahead-Logging for improved concurrency: https://sqlite.org/wal.html // Set a busy timeout (in ms): https://sqlite.org/c3ref/busy_timeout.html - if let Err(error) = connection.batch_execute( + if let Err(e) = connection.batch_execute( " PRAGMA journal_mode = WAL; PRAGMA busy_timeout = 250; ", ) { - log::warn!( + warn!( + ?e, "Failed adding PRAGMA statements while establishing sqlite connection, this will \ - result in a higher likelihood of locking errors: {}", - error + result in a higher likelihood of locking errors" ); } @@ -48,8 +49,8 @@ fn establish_connection(db_dir: &str) -> SqliteConnection { #[allow(clippy::single_match)] // TODO: Pending review in #587 fn apply_saves_dir_override(db_dir: &str) -> String { - if let Some(val) = env::var_os("VELOREN_SAVES_DIR") { - let path = PathBuf::from(val); + if let Some(saves_dir) = env::var_os("VELOREN_SAVES_DIR") { + let path = PathBuf::from(saves_dir.clone()); if path.exists() || path.parent().map(|x| x.exists()).unwrap_or(false) { // Only allow paths with valid unicode characters match path.to_str() { @@ -57,7 +58,7 @@ fn apply_saves_dir_override(db_dir: &str) -> String { None => {}, } } - log::warn!("VELOREN_SAVES_DIR points to an invalid path."); + warn!(?saves_dir, "VELOREN_SAVES_DIR points to an invalid path."); } db_dir.to_string() } diff --git a/server/src/persistence/models.rs b/server/src/persistence/models.rs index 563d11d12c..9e4c910425 100644 --- a/server/src/persistence/models.rs +++ b/server/src/persistence/models.rs @@ -5,6 +5,7 @@ use crate::comp; use common::{character::Character as CharacterData, LoadoutBuilder}; use diesel::sql_types::Text; use serde::{Deserialize, Serialize}; +use tracing::warn; /// The required elements to build comp::Stats from database data pub struct StatsJoinData<'a> { @@ -172,8 +173,8 @@ where match serde_json::from_str(&t) { Ok(data) => Ok(Self(data)), - Err(error) => { - log::warn!("Failed to deserialise inventory data: {}", error); + Err(e) => { + warn!(?e, "Failed to deserialise inventory data"); Ok(Self(comp::Inventory::default())) }, } @@ -258,8 +259,8 @@ where match serde_json::from_str(&t) { Ok(data) => Ok(Self(data)), - Err(error) => { - log::warn!("Failed to deserialise loadout data: {}", error); + Err(e) => { + warn!(?e, "Failed to deserialise loadout data"); // We don't have a weapon reference here, so we default to sword let loadout = LoadoutBuilder::new() diff --git a/server/src/settings.rs b/server/src/settings.rs index 3432482777..9cb9c60de2 100644 --- a/server/src/settings.rs +++ b/server/src/settings.rs @@ -1,6 +1,7 @@ use portpicker::pick_unused_port; use serde_derive::{Deserialize, Serialize}; use std::{fs, io::prelude::*, net::SocketAddr, path::PathBuf}; +use tracing::{error, warn}; use world::sim::FileOpts; const DEFAULT_WORLD_SEED: u32 = 59686; @@ -71,7 +72,7 @@ impl ServerSettings { match ron::de::from_reader(file) { Ok(x) => x, Err(e) => { - log::warn!("Failed to parse setting file! Fallback to default. {}", e); + warn!(?e, "Failed to parse setting file! Fallback to default"); Self::default() }, } @@ -79,7 +80,7 @@ impl ServerSettings { let default_settings = Self::default(); match default_settings.save_to_file() { - Err(e) => log::error!("Failed to create default setting file! {}", e), + Err(e) => error!(?e, "Failed to create default setting file!"), _ => {}, } default_settings diff --git a/server/src/state_ext.rs b/server/src/state_ext.rs index 06c3645cf0..88abc1afb4 100644 --- a/server/src/state_ext.rs +++ b/server/src/state_ext.rs @@ -12,8 +12,8 @@ use common::{ sync::{Uid, WorldSyncExt}, util::Dir, }; -use log::warn; use specs::{Builder, Entity as EcsEntity, EntityBuilder as EcsEntityBuilder, Join, WorldExt}; +use tracing::warn; use vek::*; pub trait StateExt { @@ -172,13 +172,11 @@ impl StateExt for State { self.write_component(entity, inventory); self.write_component(entity, loadout); }, - Err(error) => { - log::warn!( - "{}", - format!( - "Failed to load character data for character_id {}: {}", - character_id, error - ) + Err(e) => { + warn!( + ?e, + ?character_id, + "Failed to load character data for character_id" ); if let Some(client) = self.ecs().write_storage::<Client>().get_mut(entity) { @@ -295,6 +293,8 @@ impl StateExt for State { // and then deleted before the region manager had a chance to assign it a // region warn!( + ?uid, + ?pos, "Failed to find region containing entity during entity deletion, assuming \ it wasn't sent to any clients and so deletion doesn't need to be \ recorded for sync purposes" diff --git a/server/src/sys/message.rs b/server/src/sys/message.rs index 676b768fbd..84e8fc099c 100644 --- a/server/src/sys/message.rs +++ b/server/src/sys/message.rs @@ -22,6 +22,7 @@ use hashbrown::HashMap; use specs::{ Entities, Join, Read, ReadExpect, ReadStorage, System, Write, WriteExpect, WriteStorage, }; +use tracing::warn; /// This system will handle new messages from clients pub struct Sys; @@ -274,11 +275,11 @@ impl<'a> System<'a> for Sys { | ClientState::Spectator | ClientState::Character => match validate_chat_msg(&message) { Ok(()) => new_chat_msgs.push((Some(entity), ServerMsg::chat(message))), - Err(ChatMsgValidationError::TooLong) => log::warn!( - "Recieved a chat message that's too long (max:{} len:{})", - MAX_BYTES_CHAT_MSG, - message.len() - ), + Err(ChatMsgValidationError::TooLong) => { + let max = MAX_BYTES_CHAT_MSG; + let len = message.len(); + warn!(?len, ?max, "Recieved a chat message that's too long") + }, }, ClientState::Pending => {}, }, diff --git a/server/src/sys/subscription.rs b/server/src/sys/subscription.rs index 8195cde1eb..7fd52d8613 100644 --- a/server/src/sys/subscription.rs +++ b/server/src/sys/subscription.rs @@ -11,11 +11,11 @@ use common::{ terrain::TerrainChunkSize, vol::RectVolSize, }; -use log::{debug, error}; use specs::{ Entities, Join, ReadExpect, ReadStorage, System, SystemData, World, WorldExt, Write, WriteStorage, }; +use tracing::{debug, error}; use vek::*; /// This system will update region subscriptions based on client positions @@ -259,14 +259,15 @@ pub fn initialize_region_subscription(world: &World, entity: specs::Entity) { } } - if let Err(err) = world.write_storage().insert(entity, RegionSubscription { + if let Err(e) = world.write_storage().insert(entity, RegionSubscription { fuzzy_chunk, regions, }) { - error!("Failed to insert region subscription component: {:?}", err); + error!(?e, "Failed to insert region subscription component"); } } else { debug!( + ?entity, "Failed to initialize region subcription. Couldn't retrieve all the neccesary \ components on the provided entity" ); diff --git a/voxygen/Cargo.toml b/voxygen/Cargo.toml index bd96e5c9f4..4f1cea843a 100644 --- a/voxygen/Cargo.toml +++ b/voxygen/Cargo.toml @@ -48,14 +48,12 @@ server = { package = "veloren-server", path = "../server", optional = true } # Utility glsl-include = "0.3.1" failure = "0.1.6" -log = "0.4.8" dot_vox = "4.0" image = { version = "0.22.5", default-features = false, features = ["ico", "png"] } serde = "1.0" serde_derive = "1.0" ron = { version = "0.6", default-features = false } guillotiere = { git = "https://github.com/Imberflur/guillotiere" } -fern = { version = "0.5.8", features = ["colored"] } msgbox = { git = "https://github.com/bekker/msgbox-rs.git", default-features = false, rev = "68fe39a", optional = true } directories = "2.0.2" num = "0.2.0" @@ -73,6 +71,12 @@ uvth = "3.1.1" authc = { git = "https://gitlab.com/veloren/auth.git", rev = "223a4097f7ebc8d451936dccb5e6517194bbf086" } const-tweaker = { version = "0.2.5", optional = true } +# Logging +tracing = { version = "0.1", default-features = false } +tracing-subscriber = { version = "0.2.3", default-features = false, features = ["env-filter", "fmt", "chrono", "ansi", "smallvec" , "tracing-log"] } +tracing-log = "0.1.1" +tracing-appender = "0.1" + [target.'cfg(target_os = "macos")'.dependencies] dispatch = "0.1.4" diff --git a/voxygen/src/anim/src/dyn_lib.rs b/voxygen/src/anim/src/dyn_lib.rs index 9308c97e30..b6b5d36c8a 100644 --- a/voxygen/src/anim/src/dyn_lib.rs +++ b/voxygen/src/anim/src/dyn_lib.rs @@ -62,14 +62,10 @@ pub fn init() { modified_paths.insert(path); } - let mut info = "Hot reloading animations because these files were modified:".to_owned(); - for path in std::mem::take(&mut modified_paths) { - info.push('\n'); - info.push('\"'); - info.push_str(&path); - info.push('\"'); - } - log::warn!("{}", info); + warn!( + ?modified_paths, + "Hot reloading animations because these files were modified" + ); // Reload reload(); @@ -96,7 +92,7 @@ fn event_fn(res: notify::Result<notify::Event>, sender: &mpsc::Sender<String>) { }, _ => {}, }, - Err(e) => log::error!("Animation hotreload watcher error: {:?}", e), + Err(e) => error!("Animation hotreload watcher error: {:?}", e), } } @@ -119,7 +115,7 @@ fn reload() { // Open new lib *lock = Some(LoadedLib::load()); - log::warn!("Updated animations"); + warn!("Updated animations"); } // Returns false if compile failed @@ -135,10 +131,10 @@ fn compile() -> bool { // If compile failed if !output.status.success() { - log::error!("Failed to compile anim crate"); + error!("Failed to compile anim crate"); false } else { - log::warn!("Animation recompile success!!"); + warn!("Animation recompile success!!"); true } } diff --git a/voxygen/src/anim/src/lib.rs b/voxygen/src/anim/src/lib.rs index 766775c36d..0afdbbbae5 100644 --- a/voxygen/src/anim/src/lib.rs +++ b/voxygen/src/anim/src/lib.rs @@ -86,14 +86,14 @@ pub trait Skeleton: Send + Sync + 'static { let lib = &lock.as_ref().unwrap().lib; let compute_fn: libloading::Symbol<fn(&Self) -> ([FigureBoneData; 16], Vec3<f32>)> = - unsafe { lib.get(Self::COMPUTE_FN) }.unwrap_or_else(|err| { + unsafe { lib.get(Self::COMPUTE_FN) }.unwrap_or_else(|e| { panic!( "Trying to use: {} but had error: {:?}", CStr::from_bytes_with_nul(Self::COMPUTE_FN) .map(CStr::to_str) .unwrap() .unwrap(), - err + e ) }); @@ -154,14 +154,14 @@ pub trait Animation { //println!("{}", start.elapsed().as_nanos()); f } - .unwrap_or_else(|err| { + .unwrap_or_else(|e| { panic!( "Trying to use: {} but had error: {:?}", CStr::from_bytes_with_nul(Self::UPDATE_FN) .map(CStr::to_str) .unwrap() .unwrap(), - err + e ) }); diff --git a/voxygen/src/audio/mod.rs b/voxygen/src/audio/mod.rs index 370c3ec45f..9c7b022dc4 100644 --- a/voxygen/src/audio/mod.rs +++ b/voxygen/src/audio/mod.rs @@ -9,6 +9,7 @@ pub mod soundcache; use channel::{MusicChannel, MusicChannelTag, SfxChannel}; use fader::Fader; use soundcache::SoundCache; +use tracing::warn; use common::assets; use cpal::traits::DeviceTrait; @@ -272,7 +273,7 @@ fn list_devices_raw() -> Vec<Device> { devices.filter(|d| d.name().is_ok()).collect() }, Err(_) => { - log::warn!("Failed to enumerate audio output devices, audio will not be available"); + warn!("Failed to enumerate audio output devices, audio will not be available"); Vec::new() }, } diff --git a/voxygen/src/audio/music.rs b/voxygen/src/audio/music.rs index 6d86908666..643b4826b5 100644 --- a/voxygen/src/audio/music.rs +++ b/voxygen/src/audio/music.rs @@ -37,12 +37,12 @@ //! tracks //! - If you are not the author of the track, ensure that the song's licensing //! permits usage of the track for non-commercial use - use crate::audio::AudioFrontend; use common::{assets, state::State}; use rand::{seq::IteratorRandom, thread_rng}; use serde::Deserialize; use std::time::Instant; +use tracing::warn; const DAY_START_SECONDS: u32 = 28800; // 8:00 const DAY_END_SECONDS: u32 = 70200; // 19:30 @@ -146,7 +146,7 @@ impl MusicMgr { Ok(file) => match ron::de::from_reader(file) { Ok(config) => config, Err(error) => { - log::warn!( + warn!( "Error parsing music config file, music will not be available: {}", format!("{:#?}", error) ); @@ -155,7 +155,7 @@ impl MusicMgr { }, }, Err(error) => { - log::warn!( + warn!( "Error reading music config file, music will not be available: {}", format!("{:#?}", error) ); diff --git a/voxygen/src/audio/sfx/mod.rs b/voxygen/src/audio/sfx/mod.rs index 38e50412db..63f5ef9619 100644 --- a/voxygen/src/audio/sfx/mod.rs +++ b/voxygen/src/audio/sfx/mod.rs @@ -94,6 +94,7 @@ use event_mapper::SfxEventMapper; use hashbrown::HashMap; use serde::Deserialize; use specs::WorldExt; +use tracing::warn; use vek::*; /// We watch the states of nearby entities in order to emit SFX at their @@ -193,7 +194,7 @@ impl SfxMgr { Ok(file) => match ron::de::from_reader(file) { Ok(config) => config, Err(error) => { - log::warn!( + warn!( "Error parsing sfx config file, sfx will not be available: {}", format!("{:#?}", error) ); @@ -202,7 +203,7 @@ impl SfxMgr { }, }, Err(error) => { - log::warn!( + warn!( "Error reading sfx config file, sfx will not be available: {}", format!("{:#?}", error) ); diff --git a/voxygen/src/audio/soundcache.rs b/voxygen/src/audio/soundcache.rs index f7672720dc..61488e3e56 100644 --- a/voxygen/src/audio/soundcache.rs +++ b/voxygen/src/audio/soundcache.rs @@ -3,6 +3,7 @@ use common::assets; use hashbrown::HashMap; use std::{convert::AsRef, io, io::Read, sync::Arc}; +use tracing::warn; // Implementation of sound taken from this github issue: // https://github.com/RustAudio/rodio/issues/141 @@ -52,7 +53,7 @@ impl SoundCache { .entry(name.to_string()) .or_insert_with(|| { Sound::load(name).unwrap_or_else(|_| { - log::warn!("SoundCache: Failed to load sound: {}", name); + warn!(?name, "SoundCache: Failed to load sound"); Sound::empty() }) diff --git a/voxygen/src/ecs/sys/interpolation.rs b/voxygen/src/ecs/sys/interpolation.rs index fa48e15504..626d86d65f 100644 --- a/voxygen/src/ecs/sys/interpolation.rs +++ b/voxygen/src/ecs/sys/interpolation.rs @@ -4,8 +4,8 @@ use common::{ state::DeltaTime, util::Dir, }; -use log::warn; use specs::{Entities, Join, Read, ReadStorage, System, WriteStorage}; +use tracing::warn; use vek::*; /// This system will allow NPCs to modify their controller @@ -46,7 +46,7 @@ impl<'a> System<'a> for Sys { interpolated .insert(entity, Interpolated { pos, ori }) .err() - .map(|err| warn!("Error inserting Interpolated component: {}", err)); + .map(|e| warn!(?e, "Error inserting Interpolated component")); } // Remove Interpolated component from entities which don't have a position or an // orientation or a velocity diff --git a/voxygen/src/hud/item_imgs.rs b/voxygen/src/hud/item_imgs.rs index 3b6434d73a..e6383e0c81 100644 --- a/voxygen/src/hud/item_imgs.rs +++ b/voxygen/src/hud/item_imgs.rs @@ -12,9 +12,9 @@ use conrod_core::image::Id; use dot_vox::DotVoxData; use hashbrown::HashMap; use image::DynamicImage; -use log::{error, warn}; use serde_derive::{Deserialize, Serialize}; use std::{fs::File, io::BufReader, sync::Arc}; +use tracing::{error, warn}; use vek::*; #[derive(Clone, Debug, PartialEq, Eq, Hash, Serialize, Deserialize)] @@ -141,8 +141,8 @@ impl ItemImgs { // There was no specification in the ron None => { warn!( - "{:?} has no specified image file (note: hot-reloading won't work here)", - item_kind + ?item_kind, + "missing specified image file (note: hot-reloading won't work here)", ); None }, @@ -161,10 +161,7 @@ fn graceful_load_vox(specifier: &str) -> Arc<DotVoxData> { match assets::load::<DotVoxData>(full_specifier.as_str()) { Ok(dot_vox) => dot_vox, Err(_) => { - error!( - "Could not load vox file for item images: {}", - full_specifier - ); + error!(?full_specifier, "Could not load vox file for item images",); assets::load_expect::<DotVoxData>("voxygen.voxel.not_found") }, } @@ -174,10 +171,7 @@ fn graceful_load_img(specifier: &str) -> Arc<DynamicImage> { match assets::load::<DynamicImage>(full_specifier.as_str()) { Ok(img) => img, Err(_) => { - error!( - "Could not load image file for item images: {}", - full_specifier - ); + error!(?full_specifier, "Could not load image file for item images"); assets::load_expect::<DynamicImage>("voxygen.element.not_found") }, } diff --git a/voxygen/src/i18n.rs b/voxygen/src/i18n.rs index 9e8a14573b..57b6a376e7 100644 --- a/voxygen/src/i18n.rs +++ b/voxygen/src/i18n.rs @@ -10,6 +10,7 @@ use std::{ fs::File, io::BufReader, }; +use tracing::warn; /// The reference language, aka the more up-to-date localization data. /// Also the default language at first startup. @@ -124,17 +125,15 @@ impl VoxygenLocalization { pub fn log_missing_entries(&self) { let (missing_strings, missing_vectors) = self.list_missing_entries(); for missing_key in missing_strings { - log::warn!( + warn!( "[{:?}] Missing string key {:?}", - self.metadata.language_identifier, - missing_key + self.metadata.language_identifier, missing_key ); } for missing_key in missing_vectors { - log::warn!( + warn!( "[{:?}] Missing vector key {:?}", - self.metadata.language_identifier, - missing_key + self.metadata.language_identifier, missing_key ); } } diff --git a/voxygen/src/logging.rs b/voxygen/src/logging.rs index fd292bbd74..7f53f2a1f5 100644 --- a/voxygen/src/logging.rs +++ b/voxygen/src/logging.rs @@ -1,82 +1,105 @@ -use fern::colors::{Color, ColoredLevelConfig}; use std::fs; use crate::settings::Settings; -#[allow(clippy::or_fun_call)] // TODO: Pending review in #587 -pub fn init( - settings: &Settings, - term_log_level: log::LevelFilter, - file_log_level: log::LevelFilter, -) { - let colors = ColoredLevelConfig::new() - .error(Color::Red) - .warn(Color::Yellow) - .info(Color::Cyan) - .debug(Color::Green) - .trace(Color::BrightBlack); +use tracing::{error, info}; +use tracing_subscriber::{filter::LevelFilter, prelude::*, registry, EnvFilter}; - let mut base = fern::Dispatch::new() - .level_for("dot_vox::parser", log::LevelFilter::Warn) - .level_for("gfx_device_gl::factory", log::LevelFilter::Warn) - .level_for("uvth", log::LevelFilter::Warn) - .level_for("tiny_http", log::LevelFilter::Warn); +const RUST_LOG_ENV: &str = "RUST_LOG"; - let time = chrono::offset::Utc::now(); +/// Initialise tracing and logging for the settings. +/// +/// This function will attempt to set up both a file and a terminal logger, +/// falling back to just a terminal logger if the file is unable to be created. +/// +/// The logging level is by default set to `INFO`, to change this for any +/// particular crate or module you must use the `RUST_LOG` environment +/// variable. +/// +/// For example to set this crate's debug level to `TRACE` you would need the +/// following in your environment. +/// `RUST_LOG="veloren_voxygen=trace"` +/// +/// more complex tracing can be done by concatenating with a `,` as seperator: +/// - warn for `uvth`, `tiny_http`, `dot_vox`, `gfx_device_gl::factory, +/// `gfx_device_gl::shade` trace for `veloren_voxygen`, info for everything +/// else +/// `RUST_LOG="uvth=warn,tiny_http=warn,dot_vox::parser=warn,gfx_device_gl:: +/// factory=warn,gfx_device_gl::shade=warn,veloren_voxygen=trace,info"` +/// +/// By default a few directives are set to `warn` by default, until explicitly +/// overwritten! e.g. `RUST_LOG="uvth=debug"` +pub fn init(settings: &Settings) -> Vec<impl Drop> { + // To hold the guards that we create, they will cause the logs to be + // flushed when they're dropped. + let mut _guards = vec![]; - let mut file_cfg = - fern::Dispatch::new() - .level(file_log_level) - .format(|out, message, record| { - out.finish(format_args!( - "{}[{}:{}][{}] {}", - chrono::Local::now().format("[%Y-%m-%d][%H:%M:%S]"), - record.target(), - record - .line() - .map(|x| x.to_string()) - .unwrap_or("X".to_string()), - record.level(), - message - )) - }); + // We will do lower logging than the default (INFO) by INCLUSION. This + // means that if you need lower level logging for a specific module, then + // put it in the environment in the correct format i.e. DEBUG logging for + // this crate would be veloren_voxygen=debug. - // Try to create the logs file parent directories. - let mut log_file_created = fs::create_dir_all(&settings.log.logs_path); + let filter = match std::env::var_os(RUST_LOG_ENV).map(|s| s.into_string()) { + Some(Ok(env)) => { + let mut filter = EnvFilter::new("dot_vox::parser=warn") + .add_directive("gfx_device_gl=warn".parse().unwrap()) + .add_directive("uvth=warn".parse().unwrap()) + .add_directive("tiny_http=warn".parse().unwrap()) + .add_directive(LevelFilter::INFO.into()); + for s in env.split(',').into_iter() { + match s.parse() { + Ok(d) => filter = filter.add_directive(d), + Err(err) => println!("WARN ignoring log directive: `{}`: {}", s, err), + }; + } + filter + }, + _ => EnvFilter::from_env(RUST_LOG_ENV) + .add_directive("dot_vox::parser=warn".parse().unwrap()) + .add_directive("gfx_device_gl=warn".parse().unwrap()) + .add_directive("uvth=warn".parse().unwrap()) + .add_directive("tiny_http=warn".parse().unwrap()) + .add_directive(LevelFilter::INFO.into()), + }; - if log_file_created.is_ok() { - // Try to create the log file. - match fern::log_file( - settings - .log - .logs_path - .join(&format!("voxygen-{}.log", time.format("%Y-%m-%d-%H"))), - ) { - Ok(log_file) => file_cfg = file_cfg.chain(log_file), - Err(e) => log_file_created = Err(e), - } - } + // Create the terminal writer layer. + let (non_blocking, _stdio_guard) = tracing_appender::non_blocking(std::io::stdout()); + _guards.push(_stdio_guard); - let stdout_cfg = fern::Dispatch::new() - .level(term_log_level) - .format(move |out, message, record| { - out.finish(format_args!( - "[{}] {}", - colors.color(record.level()), - message - )) - }) - .chain(std::io::stdout()); + // Try to create the log file's parent folders. + let log_folders_created = fs::create_dir_all(&settings.log.logs_path); + const LOG_FILENAME: &str = "voxygen.log"; - if settings.log.log_to_file { - base = base.chain(file_cfg); - } - base.chain(stdout_cfg) - .apply() - .expect("Failed to setup logging!"); + match log_folders_created { + // If the parent folders were created then attach both a terminal and a + // file writer to the registry and init it. + Ok(_) => { + let file_appender = + tracing_appender::rolling::daily(&settings.log.logs_path, LOG_FILENAME); + let (non_blocking_file, _file_guard) = tracing_appender::non_blocking(file_appender); + _guards.push(_file_guard); + registry() + .with(tracing_subscriber::fmt::layer().with_writer(non_blocking)) + .with(tracing_subscriber::fmt::layer().with_writer(non_blocking_file)) + .with(filter) + .init(); + let logdir = &settings.log.logs_path; + info!(?logdir, "Setup terminal and file logging."); + }, + // Otherwise just add a terminal writer and init it. + Err(e) => { + error!( + ?e, + "Failed to create log file!. Falling back to terminal logging only.", + ); + registry() + .with(tracing_subscriber::fmt::layer().with_writer(non_blocking)) + .with(filter) + .init(); + info!("Setup terminal logging."); + }, + }; - // Incase that the log file creation failed simply print it to the console - if let Err(e) = log_file_created { - log::error!("Failed to create log file! {}", e); - } + // Return the guards + _guards } diff --git a/voxygen/src/main.rs b/voxygen/src/main.rs index 2f2b37ec20..b4f64dc017 100644 --- a/voxygen/src/main.rs +++ b/voxygen/src/main.rs @@ -15,34 +15,24 @@ use veloren_voxygen::{ }; use common::assets::{load, load_expect}; -use log::{debug, error}; -use std::{mem, panic, str::FromStr}; +use std::{mem, panic}; +use tracing::{debug, error, warn}; fn main() { #[cfg(feature = "tweak")] const_tweaker::run().expect("Could not run server"); - // Initialize logging. - let term_log_level = std::env::var_os("VOXYGEN_LOG") - .and_then(|env| env.to_str().map(|s| s.to_owned())) - .and_then(|s| log::LevelFilter::from_str(&s).ok()) - .unwrap_or(log::LevelFilter::Warn); - - let file_log_level = std::env::var_os("VOXYGEN_FILE_LOG") - .and_then(|env| env.to_str().map(|s| s.to_owned())) - .and_then(|s| log::LevelFilter::from_str(&s).ok()) - .unwrap_or(log::LevelFilter::Debug); // Load the settings // Note: This won't log anything due to it being called before - // ``logging::init``. The issue is we need to read a setting to decide + // `logging::init`. The issue is we need to read a setting to decide // whether we create a log file or not. let settings = Settings::load(); - let profile = Profile::load(); + // Init logging and hold the guards. + let _guards = logging::init(&settings); - logging::init(&settings, term_log_level, file_log_level); - - // Save settings to add new fields or create the file if it is not already there + // Save settings to add new fields or create the file if it is not already + // there. if let Err(err) = settings.save_to_file() { panic!("Failed to save settings: {:?}", err); } @@ -58,6 +48,9 @@ fn main() { audio.set_music_volume(settings.audio.music_volume); audio.set_sfx_volume(settings.audio.sfx_volume); + // Load the profile. + let profile = Profile::load(); + let mut global_state = GlobalState { audio, profile, @@ -71,12 +64,12 @@ fn main() { let localized_strings = load::<VoxygenLocalization>(&i18n_asset_key( &global_state.settings.language.selected_language, )) - .unwrap_or_else(|error| { - log::warn!( - "Impossible to load {} language: change to the default language (English) instead. \ - Source error: {:?}", - &global_state.settings.language.selected_language, - error + .unwrap_or_else(|e| { + let preferred_language = &global_state.settings.language.selected_language; + warn!( + ?e, + ?preferred_language, + "Impossible to load language: change to the default language (English) instead.", ); global_state.settings.language.selected_language = i18n::REFERENCE_LANG.to_owned(); load_expect::<VoxygenLocalization>(&i18n_asset_key( @@ -168,9 +161,10 @@ fn main() { // Set up the initial play state. let mut states: Vec<Box<dyn PlayState>> = vec![Box::new(MainMenuState::new(&mut global_state))]; - states - .last() - .map(|current_state| debug!("Started game with state '{}'", current_state.name())); + states.last().map(|current_state| { + let current_state = current_state.name(); + debug!(?current_state, "Started game with state") + }); // What's going on here? // --------------------- @@ -192,7 +186,8 @@ fn main() { debug!("Shutting down all states..."); while states.last().is_some() { states.pop().map(|old_state| { - debug!("Popped state '{}'.", old_state.name()); + let old_state = old_state.name(); + debug!(?old_state, "Popped state"); global_state.on_play_state_changed(); }); } @@ -200,7 +195,8 @@ fn main() { PlayStateResult::Pop => { direction = Direction::Backwards; states.pop().map(|old_state| { - debug!("Popped state '{}'.", old_state.name()); + let old_state = old_state.name(); + debug!(?old_state, "Popped state"); global_state.on_play_state_changed(); }); }, @@ -210,15 +206,13 @@ fn main() { states.push(new_state); global_state.on_play_state_changed(); }, - PlayStateResult::Switch(mut new_state) => { + PlayStateResult::Switch(mut new_state_box) => { direction = Direction::Forwards; - states.last_mut().map(|old_state| { - debug!( - "Switching to state '{}' from state '{}'.", - new_state.name(), - old_state.name() - ); - mem::swap(old_state, &mut new_state); + states.last_mut().map(|old_state_box| { + let old_state = old_state_box.name(); + let new_state = new_state_box.name(); + debug!(?old_state, ?new_state, "Switching to states",); + mem::swap(old_state_box, &mut new_state_box); global_state.on_play_state_changed(); }); }, diff --git a/voxygen/src/menu/char_selection/mod.rs b/voxygen/src/menu/char_selection/mod.rs index 8d82f7b4f7..51c2de60f5 100644 --- a/voxygen/src/menu/char_selection/mod.rs +++ b/voxygen/src/menu/char_selection/mod.rs @@ -9,9 +9,9 @@ use crate::{ }; use client::{self, Client}; use common::{assets, clock::Clock, comp, msg::ClientState, state::DeltaTime}; -use log::error; use specs::WorldExt; use std::{cell::RefCell, rc::Rc, time::Duration}; +use tracing::error; use ui::CharSelectionUi; pub struct CharSelectionState { @@ -156,14 +156,14 @@ impl PlayState for CharSelectionState { let localized_strings = assets::load_expect::<VoxygenLocalization>(&i18n_asset_key( &global_state.settings.language.selected_language, )); - if let Err(err) = self.client.borrow_mut().tick( + if let Err(e) = self.client.borrow_mut().tick( comp::ControllerInputs::default(), clock.get_last_delta(), |_| {}, ) { global_state.info_message = Some(localized_strings.get("common.connection_lost").to_owned()); - error!("[char_selection] Failed to tick the scene: {:?}", err); + error!(?e, "[char_selection] Failed to tick the scene"); return PlayStateResult::Pop; } diff --git a/voxygen/src/menu/main/mod.rs b/voxygen/src/menu/main/mod.rs index 3d7b3d2c58..071b4a9a09 100644 --- a/voxygen/src/menu/main/mod.rs +++ b/voxygen/src/menu/main/mod.rs @@ -7,9 +7,9 @@ use crate::{ }; use client_init::{ClientInit, Error as InitError, Msg as InitMsg}; use common::{assets::load_expect, clock::Clock, comp}; -use log::{error, warn}; #[cfg(feature = "singleplayer")] use std::time::Duration; +use tracing::{error, warn}; use ui::{Event as MainMenuEvent, MainMenuUi}; pub struct MainMenuState { @@ -75,10 +75,10 @@ impl PlayState for MainMenuState { std::rc::Rc::new(std::cell::RefCell::new(client)), ))); }, - Some(InitMsg::Done(Err(err))) => { + Some(InitMsg::Done(Err(e))) => { client_init = None; global_state.info_message = Some({ - let err = match err { + let err = match e { InitError::BadAddress(_) | InitError::NoAddress => { localized_strings.get("main.login.server_not_found").into() }, @@ -262,8 +262,8 @@ fn attempt_login( if !net_settings.servers.contains(&server_address) { net_settings.servers.push(server_address.clone()); } - if let Err(err) = global_state.settings.save_to_file() { - warn!("Failed to save settings: {:?}", err); + if let Err(e) = global_state.settings.save_to_file() { + warn!(?e, "Failed to save settings"); } if comp::Player::alias_is_valid(&username) { diff --git a/voxygen/src/meta.rs b/voxygen/src/meta.rs index 71d66087f9..30ef1a3c7b 100644 --- a/voxygen/src/meta.rs +++ b/voxygen/src/meta.rs @@ -1,8 +1,8 @@ use common::comp; use directories::ProjectDirs; -use log::warn; use serde_derive::{Deserialize, Serialize}; use std::{fs, io::Write, path::PathBuf}; +use tracing::warn; const VALID_VERSION: u32 = 0; // Change this if you broke charsaves #[derive(Clone, Debug, Serialize, Deserialize)] @@ -47,13 +47,13 @@ impl Meta { } }, Err(e) => { - log::warn!("Failed to parse meta file! Fallback to default. {}", e); + warn!(?e, ?file, "Failed to parse meta file! Fallback to default"); // Rename the corrupted settings file let mut new_path = path.to_owned(); new_path.pop(); new_path.push("meta.invalid.ron"); - if let Err(err) = std::fs::rename(path, new_path) { - log::warn!("Failed to rename meta file. {}", err); + if let Err(e) = std::fs::rename(path.clone(), new_path.clone()) { + warn!(?e, ?path, ?new_path, "Failed to rename meta file"); } }, } @@ -68,7 +68,7 @@ impl Meta { pub fn save_to_file_warn(&self) { if let Err(err) = self.save_to_file() { - warn!("Failed to save settings: {:?}", err); + warn!(?e, "Failed to save settings"); } } @@ -85,12 +85,12 @@ impl Meta { } pub fn get_meta_path() -> PathBuf { - if let Some(val) = std::env::var_os("VOXYGEN_CONFIG") { - let meta = PathBuf::from(val).join("meta.ron"); + if let Some(path) = std::env::var_os("VOXYGEN_CONFIG") { + let meta = PathBuf::from(path).join("meta.ron"); if meta.exists() || meta.parent().map(|x| x.exists()).unwrap_or(false) { return meta; } - log::warn!("VOXYGEN_CONFIG points to invalid path."); + warn!(?path, "VOXYGEN_CONFIG points to invalid path."); } let proj_dirs = ProjectDirs::from("net", "veloren", "voxygen") diff --git a/voxygen/src/profile.rs b/voxygen/src/profile.rs index b4193041dc..75d6ee9573 100644 --- a/voxygen/src/profile.rs +++ b/voxygen/src/profile.rs @@ -1,9 +1,9 @@ use crate::hud; use directories::ProjectDirs; use hashbrown::HashMap; -use log::warn; use serde_derive::{Deserialize, Serialize}; use std::{fs, io::prelude::*, path::PathBuf}; +use tracing::warn; /// Represents a character in the profile. #[derive(Clone, Debug, Serialize, Deserialize)] @@ -65,14 +65,15 @@ impl Profile { match ron::de::from_reader(file) { Ok(profile) => return profile, Err(e) => { - log::warn!( - "Failed to parse profile file! Falling back to default. {}", - e + warn!( + ?e, + ?path, + "Failed to parse profile file! Falling back to default." ); // Rename the corrupted profile file. let new_path = path.with_extension("invalid.ron"); - if let Err(err) = std::fs::rename(path, new_path) { - log::warn!("Failed to rename profile file. {}", err); + if let Err(e) = std::fs::rename(path.clone(), new_path.clone()) { + warn!(?e, ?path, ?new_path, "Failed to rename profile file."); } }, } @@ -87,8 +88,8 @@ impl Profile { /// Save the current profile to disk, warn on failure. pub fn save_to_file_warn(&self) { - if let Err(err) = self.save_to_file() { - warn!("Failed to save profile: {:?}", err); + if let Err(e) = self.save_to_file() { + warn!(?e, "Failed to save profile"); } } @@ -156,12 +157,12 @@ impl Profile { } fn get_path() -> PathBuf { - if let Some(val) = std::env::var_os("VOXYGEN_CONFIG") { - let profile = PathBuf::from(val).join("profile.ron"); + if let Some(path) = std::env::var_os("VOXYGEN_CONFIG") { + let profile = PathBuf::from(path.clone()).join("profile.ron"); if profile.exists() || profile.parent().map(|x| x.exists()).unwrap_or(false) { return profile; } - log::warn!("VOXYGEN_CONFIG points to invalid path."); + warn!(?path, "VOXYGEN_CONFIG points to invalid path."); } let proj_dirs = ProjectDirs::from("net", "veloren", "voxygen") diff --git a/voxygen/src/render/renderer.rs b/voxygen/src/render/renderer.rs index 9dd874c083..a6e37ff192 100644 --- a/voxygen/src/render/renderer.rs +++ b/voxygen/src/render/renderer.rs @@ -16,7 +16,7 @@ use gfx::{ traits::{Device, Factory, FactoryExt}, }; use glsl_include::Context as IncludeContext; -use log::error; +use tracing::error; use vek::*; /// Represents the format of the pre-processed color target. @@ -354,10 +354,7 @@ impl Renderer { self.postprocess_pipeline = postprocess_pipeline; self.player_shadow_pipeline = player_shadow_pipeline; }, - Err(e) => error!( - "Could not recreate shaders from assets due to an error: {:#?}", - e - ), + Err(e) => error!(?e, "Could not recreate shaders from assets due to an error",), } } diff --git a/voxygen/src/scene/figure/load.rs b/voxygen/src/scene/figure/load.rs index d4ea8ccc41..08c920775f 100644 --- a/voxygen/src/scene/figure/load.rs +++ b/voxygen/src/scene/figure/load.rs @@ -24,9 +24,9 @@ use common::{ }; use dot_vox::DotVoxData; use hashbrown::HashMap; -use log::{error, warn}; use serde_derive::{Deserialize, Serialize}; use std::{fs::File, io::BufReader, sync::Arc}; +use tracing::{error, warn}; use vek::*; fn load_segment(mesh_name: &str) -> Segment { @@ -38,7 +38,7 @@ fn graceful_load_vox(mesh_name: &str) -> Arc<DotVoxData> { match assets::load::<DotVoxData>(full_specifier.as_str()) { Ok(dot_vox) => dot_vox, Err(_) => { - error!("Could not load vox file for figure: {}", full_specifier); + error!(?full_specifier, "Could not load vox file for figure"); assets::load_expect::<DotVoxData>("voxygen.voxel.not_found") }, } @@ -157,8 +157,9 @@ impl HumHeadSpec { Some(spec) => spec, None => { error!( - "No head specification exists for the combination of {:?} and {:?}", - body.species, body.body_type + ?body.species, + ?body.body_type, + "No head specification exists for the combination of species and body" ); return load_mesh("not_found", Vec3::new(-5.0, -5.0, -2.5), generate_mesh); }, @@ -368,7 +369,7 @@ impl HumArmorShoulderSpec { match self.0.map.get(&shoulder) { Some(spec) => spec, None => { - error!("No shoulder specification exists for {:?}", shoulder); + error!(?shoulder, "No shoulder specification exists"); return load_mesh("not_found", Vec3::new(-3.0, -3.5, 0.1), generate_mesh); }, } @@ -450,7 +451,7 @@ impl HumArmorChestSpec { match self.0.map.get(&chest) { Some(spec) => spec, None => { - error!("No chest specification exists for {:?}", loadout.chest); + error!(?loadout.chest, "No chest specification exists"); return load_mesh("not_found", Vec3::new(-7.0, -3.5, 2.0), generate_mesh); }, } @@ -507,7 +508,7 @@ impl HumArmorHandSpec { match self.0.map.get(&hand) { Some(spec) => spec, None => { - error!("No hand specification exists for {:?}", hand); + error!(?hand, "No hand specification exists"); return load_mesh("not_found", Vec3::new(-1.5, -1.5, -7.0), generate_mesh); }, } @@ -583,7 +584,7 @@ impl HumArmorBeltSpec { match self.0.map.get(&belt) { Some(spec) => spec, None => { - error!("No belt specification exists for {:?}", belt); + error!(?belt, "No belt specification exists"); return load_mesh("not_found", Vec3::new(-4.0, -3.5, 2.0), generate_mesh); }, } @@ -627,7 +628,7 @@ impl HumArmorBackSpec { match self.0.map.get(&back) { Some(spec) => spec, None => { - error!("No back specification exists for {:?}", back); + error!(?back, "No back specification exists"); return load_mesh("not_found", Vec3::new(-4.0, -3.5, 2.0), generate_mesh); }, } @@ -670,7 +671,7 @@ impl HumArmorPantsSpec { match self.0.map.get(&pants) { Some(spec) => spec, None => { - error!("No pants specification exists for {:?}", pants); + error!(?pants, "No pants specification exists"); return load_mesh("not_found", Vec3::new(-5.0, -3.5, 1.0), generate_mesh); }, } @@ -727,7 +728,7 @@ impl HumArmorFootSpec { match self.0.map.get(&foot) { Some(spec) => spec, None => { - error!("No foot specification exists for {:?}", foot); + error!(?foot, "No foot specification exists"); return load_mesh("not_found", Vec3::new(-2.5, -3.5, -9.0), generate_mesh); }, } @@ -793,7 +794,7 @@ impl HumMainWeaponSpec { let spec = match self.0.get(tool_kind) { Some(spec) => spec, None => { - error!("No tool/weapon specification exists for {:?}", tool_kind); + error!(?tool_kind, "No tool/weapon specification exists"); return load_mesh("not_found", Vec3::new(-1.5, -1.5, -7.0), generate_mesh); }, }; @@ -820,7 +821,7 @@ impl HumArmorLanternSpec { match self.0.map.get(&kind) { Some(spec) => spec, None => { - error!("No lantern specification exists for {:?}", kind); + error!(?kind, "No lantern specification exists"); return load_mesh("not_found", Vec3::new(-4.0, -3.5, 2.0), generate_mesh); }, } @@ -863,7 +864,7 @@ impl HumArmorHeadSpec { match self.0.map.get(&head) { Some(spec) => spec, None => { - error!("No head specification exists for {:?}", head); + error!(?head, "No head specification exists"); return load_mesh("not_found", Vec3::new(-5.0, -3.5, 1.0), generate_mesh); }, } @@ -918,7 +919,7 @@ impl HumArmorTabardSpec { match self.0.map.get(&tabard) { Some(spec) => spec, None => { - error!("No tabard specification exists for {:?}", tabard); + error!(?tabard, "No tabard specification exists"); return load_mesh("not_found", Vec3::new(-5.0, -3.5, 1.0), generate_mesh); }, } diff --git a/voxygen/src/scene/figure/mod.rs b/voxygen/src/scene/figure/mod.rs index 0408cbc275..eb5ed03ddc 100644 --- a/voxygen/src/scene/figure/mod.rs +++ b/voxygen/src/scene/figure/mod.rs @@ -30,8 +30,8 @@ use common::{ vol::RectRasterableVol, }; use hashbrown::HashMap; -use log::trace; use specs::{Entity as EcsEntity, Join, WorldExt}; +use tracing::trace; use treeculler::{BVol, BoundingSphere}; use vek::*; diff --git a/voxygen/src/scene/simple.rs b/voxygen/src/scene/simple.rs index 22e971d1ed..3988e64739 100644 --- a/voxygen/src/scene/simple.rs +++ b/voxygen/src/scene/simple.rs @@ -21,7 +21,7 @@ use common::{ terrain::BlockKind, vol::{BaseVol, ReadVol, Vox}, }; -use log::error; +use tracing::error; use vek::*; #[derive(PartialEq, Eq, Copy, Clone)] @@ -169,7 +169,7 @@ impl Scene { } = self.camera.dependents(); const VD: f32 = 115.0; // View Distance const TIME: f64 = 43200.0; // 12 hours*3600 seconds - if let Err(err) = renderer.update_consts(&mut self.globals, &[Globals::new( + if let Err(e) = renderer.update_consts(&mut self.globals, &[Globals::new( view_mat, proj_mat, cam_pos, @@ -186,7 +186,7 @@ impl Scene { self.camera.get_mode(), 250.0, )]) { - error!("Renderer failed to update: {:?}", err); + error!(?e, "Renderer failed to update"); } self.figure_model_cache.clean(scene_data.tick); diff --git a/voxygen/src/session.rs b/voxygen/src/session.rs index 8afd79201b..5052536989 100644 --- a/voxygen/src/session.rs +++ b/voxygen/src/session.rs @@ -21,9 +21,9 @@ use common::{ vol::ReadVol, ChatType, }; -use log::{error, info}; use specs::{Join, WorldExt}; use std::{cell::RefCell, rc::Rc, time::Duration}; +use tracing::{error, info}; use vek::*; /// The action to perform after a tick @@ -761,7 +761,7 @@ impl PlayState for SessionState { global_state.profile.save_to_file_warn(); - log::info!("Event! -> ChangedHotbarState") + info!("Event! -> ChangedHotbarState") }, HudEvent::Ability3(state) => self.inputs.ability3.set_state(state), HudEvent::ChangeFOV(new_fov) => { diff --git a/voxygen/src/settings.rs b/voxygen/src/settings.rs index 290e97bcd4..f496c0c23c 100644 --- a/voxygen/src/settings.rs +++ b/voxygen/src/settings.rs @@ -8,9 +8,9 @@ use crate::{ use directories::{ProjectDirs, UserDirs}; use glutin::{MouseButton, VirtualKeyCode}; use hashbrown::{HashMap, HashSet}; -use log::warn; use serde_derive::{Deserialize, Serialize}; use std::{fs, io::prelude::*, path::PathBuf}; +use tracing::warn; // ControlSetting-like struct used by Serde, to handle not serializing/building // post-deserializing the inverse_keybindings hashmap @@ -718,13 +718,13 @@ impl Settings { match ron::de::from_reader(file) { Ok(s) => return s, Err(e) => { - log::warn!("Failed to parse setting file! Fallback to default. {}", e); + warn!(?e, "Failed to parse setting file! Fallback to default."); // Rename the corrupted settings file let mut new_path = path.to_owned(); new_path.pop(); new_path.push("settings.invalid.ron"); - if let Err(err) = std::fs::rename(path, new_path) { - log::warn!("Failed to rename settings file. {}", err); + if let Err(e) = std::fs::rename(path.clone(), new_path.clone()) { + warn!(?e, ?path, ?new_path, "Failed to rename settings file."); } }, } @@ -738,8 +738,8 @@ impl Settings { } pub fn save_to_file_warn(&self) { - if let Err(err) = self.save_to_file() { - warn!("Failed to save settings: {:?}", err); + if let Err(e) = self.save_to_file() { + warn!(?e, "Failed to save settings"); } } @@ -756,12 +756,12 @@ impl Settings { } pub fn get_settings_path() -> PathBuf { - if let Some(val) = std::env::var_os("VOXYGEN_CONFIG") { - let settings = PathBuf::from(val).join("settings.ron"); + if let Some(path) = std::env::var_os("VOXYGEN_CONFIG") { + let settings = PathBuf::from(path.clone()).join("settings.ron"); if settings.exists() || settings.parent().map(|x| x.exists()).unwrap_or(false) { return settings; } - log::warn!("VOXYGEN_CONFIG points to invalid path."); + warn!(?path, "VOXYGEN_CONFIG points to invalid path."); } let proj_dirs = ProjectDirs::from("net", "veloren", "voxygen") diff --git a/voxygen/src/singleplayer.rs b/voxygen/src/singleplayer.rs index b9c833fed6..aee967caf4 100644 --- a/voxygen/src/singleplayer.rs +++ b/voxygen/src/singleplayer.rs @@ -1,7 +1,6 @@ use client::Client; use common::clock::Clock; use crossbeam::channel::{unbounded, Receiver, Sender, TryRecvError}; -use log::info; use server::{Event, Input, Server, ServerSettings}; use std::{ sync::{ @@ -11,6 +10,7 @@ use std::{ thread::{self, JoinHandle}, time::Duration, }; +use tracing::info; const TPS: u64 = 30; diff --git a/voxygen/src/ui/graphic/mod.rs b/voxygen/src/ui/graphic/mod.rs index acb3aa5be3..aa696be782 100644 --- a/voxygen/src/ui/graphic/mod.rs +++ b/voxygen/src/ui/graphic/mod.rs @@ -8,9 +8,9 @@ use common::figure::Segment; use guillotiere::{size2, SimpleAtlasAllocator}; use hashbrown::{hash_map::Entry, HashMap}; use image::{DynamicImage, RgbaImage}; -use log::warn; use pixel_art::resize_pixel_art; use std::sync::Arc; +use tracing::warn; use vek::*; #[derive(Clone)] @@ -43,7 +43,7 @@ const ATLAS_CUTTOFF_FRAC: f32 = 0.2; /// Multiplied by current window size const GRAPHIC_CACHE_RELATIVE_SIZE: u16 = 1; -#[derive(PartialEq, Eq, Hash, Copy, Clone)] +#[derive(PartialEq, Eq, Hash, Copy, Clone, Debug)] pub struct Id(u32); // TODO these can become invalid when clearing the cache @@ -300,7 +300,10 @@ fn draw_graphic(graphic_map: &GraphicMap, graphic_id: Id, dims: Vec2<u16>) -> Op *sample_strat, )), None => { - warn!("A graphic was requested via an id which is not in use"); + warn!( + ?graphic_id, + "A graphic was requested via an id which is not in use" + ); None }, } @@ -333,12 +336,12 @@ fn aabr_from_alloc_rect(rect: guillotiere::Rectangle) -> Aabr<u16> { fn upload_image(renderer: &mut Renderer, aabr: Aabr<u16>, tex: &Texture, image: &RgbaImage) { let offset = aabr.min.into_array(); let size = aabr.size().into_array(); - if let Err(err) = renderer.update_texture( + if let Err(e) = renderer.update_texture( tex, offset, size, &image.pixels().map(|p| p.0).collect::<Vec<[u8; 4]>>(), ) { - warn!("Failed to update texture: {:?}", err); + warn!(?e, "Failed to update texture"); } } diff --git a/voxygen/src/ui/mod.rs b/voxygen/src/ui/mod.rs index c46a438b5b..21d490c799 100644 --- a/voxygen/src/ui/mod.rs +++ b/voxygen/src/ui/mod.rs @@ -44,7 +44,6 @@ use conrod_core::{ Rect, UiBuilder, UiCell, }; use graphic::{Rotation, TexId}; -use log::{error, warn}; use std::{ f32, f64, fs::File, @@ -53,6 +52,7 @@ use std::{ sync::Arc, time::Duration, }; +use tracing::{error, warn}; use vek::*; #[derive(Debug)] diff --git a/voxygen/src/window.rs b/voxygen/src/window.rs index 5e9e8b2ed8..26fe048c97 100644 --- a/voxygen/src/window.rs +++ b/voxygen/src/window.rs @@ -8,9 +8,9 @@ use gilrs::{EventType, Gilrs}; use hashbrown::HashMap; use crossbeam::channel; -use log::{error, warn}; use serde_derive::{Deserialize, Serialize}; use std::fmt; +use tracing::{error, info, warn}; use vek::*; /// Represents a key that the game recognises after input mapping. @@ -429,6 +429,18 @@ impl Window { ) .map_err(|err| Error::BackendError(Box::new(err)))?; + let vendor = device.get_info().platform_name.vendor; + let renderer = device.get_info().platform_name.renderer; + let opengl_version = device.get_info().version; + let glsl_version = device.get_info().shading_language; + info!( + ?vendor, + ?renderer, + ?opengl_version, + ?glsl_version, + "selected graphics device" + ); + let keypress_map = HashMap::new(); let gilrs = match Gilrs::new() { @@ -443,11 +455,11 @@ impl Window { ); None }, - Err(gilrs::Error::Other(err)) => { + Err(gilrs::Error::Other(e)) => { error!( - "Platform-specific error when creating a Gilrs instance: `{}`. Falling back \ - to no controller support.", - err + ?e, + "Platform-specific error when creating a Gilrs instance. Falling back to no \ + controller support." ); None }, @@ -962,8 +974,8 @@ impl Window { use std::time::SystemTime; // Check if folder exists and create it if it does not if !path.exists() { - if let Err(err) = std::fs::create_dir_all(&path) { - warn!("Couldn't create folder for screenshot: {:?}", err); + if let Err(e) = std::fs::create_dir_all(&path) { + warn!(?e, "Couldn't create folder for screenshot"); let _result = sender.send(String::from("Couldn't create folder for screenshot")); } @@ -975,8 +987,8 @@ impl Window { .map(|d| d.as_millis()) .unwrap_or(0) )); - if let Err(err) = img.save(&path) { - warn!("Couldn't save screenshot: {:?}", err); + if let Err(e) = img.save(&path) { + warn!(?e, "Couldn't save screenshot"); let _result = sender.send(String::from("Couldn't save screenshot")); } else { let _result = @@ -984,10 +996,7 @@ impl Window { } }); }, - Err(err) => error!( - "Couldn't create screenshot due to renderer error: {:?}", - err - ), + Err(e) => error!(?e, "Couldn't create screenshot due to renderer error"), } } diff --git a/world/Cargo.toml b/world/Cargo.toml index d8b2def456..90b58e4528 100644 --- a/world/Cargo.toml +++ b/world/Cargo.toml @@ -17,7 +17,7 @@ num = "0.2.0" ordered-float = "1.0" hashbrown = { version = "0.6", features = ["rayon", "serde", "nightly"] } lazy_static = "1.4.0" -log = "0.4.8" +tracing = { version = "0.1", default-features = false } rand = "0.7" rand_chacha = "0.2.1" arr_macro = "0.1.2" @@ -29,5 +29,5 @@ serde_derive = "1.0" ron = { version = "0.6", default-features = false } [dev-dependencies] -pretty_env_logger = "0.3.0" +tracing-subscriber = { version = "0.2.3", default-features = false, features = ["fmt", "chrono", "ansi", "smallvec"] } minifb = "0.14.0" diff --git a/world/examples/water.rs b/world/examples/water.rs index d1bb627eb5..1b1c47354f 100644 --- a/world/examples/water.rs +++ b/world/examples/water.rs @@ -1,5 +1,7 @@ use common::{terrain::TerrainChunkSize, vol::RectVolSize}; use std::{f64, io::Write, path::PathBuf, time::SystemTime}; +use tracing::warn; +use tracing_subscriber; use vek::*; use veloren_world::{ sim::{self, MapConfig, MapDebug, WorldOpts, WORLD_SIZE}, @@ -12,7 +14,7 @@ const H: usize = 1024; #[allow(clippy::needless_update)] // TODO: Pending review in #587 #[allow(clippy::unused_io_amount)] // TODO: Pending review in #587 fn main() { - pretty_env_logger::init(); + tracing_subscriber::fmt::init(); // To load a map file of your choice, replace map_file with the name of your map // (stored locally in the map directory of your Veloren root), and swap the @@ -112,8 +114,8 @@ fn main() { .expect("Image dimensions must be valid"); let mut path = PathBuf::from("./screenshots"); if !path.exists() { - if let Err(err) = std::fs::create_dir(&path) { - log::warn!("Couldn't create folder for screenshot: {:?}", err); + if let Err(e) = std::fs::create_dir(&path) { + warn!(?e, ?path, "Couldn't create folder for screenshot"); } } path.push(format!( @@ -123,8 +125,8 @@ fn main() { .map(|d| d.as_millis()) .unwrap_or(0) )); - if let Err(err) = world_map.save(&path) { - log::warn!("Couldn't save screenshot: {:?}", err); + if let Err(e) = world_map.save(&path) { + warn!(?e, ?path, "Couldn't save screenshot"); } } } diff --git a/world/src/civ/mod.rs b/world/src/civ/mod.rs index 921607931a..28d0982a4f 100644 --- a/world/src/civ/mod.rs +++ b/world/src/civ/mod.rs @@ -25,6 +25,7 @@ use fxhash::{FxHasher32, FxHasher64}; use hashbrown::{HashMap, HashSet}; use rand::prelude::*; use rand_chacha::ChaChaRng; +use tracing::{debug, info, warn}; use vek::*; const INITIAL_CIV_COUNT: usize = (crate::sim::WORLD_SIZE.x * crate::sim::WORLD_SIZE.y * 3) / 65536; //48 at default scale @@ -76,11 +77,12 @@ impl Civs { let mut ctx = GenCtx { sim, rng }; for _ in 0..INITIAL_CIV_COUNT { - log::info!("Creating civilisation..."); + debug!("Creating civilisation..."); if this.birth_civ(&mut ctx.reseed()).is_none() { - log::warn!("Failed to find starting site for civilisation."); + warn!("Failed to find starting site for civilisation."); } } + info!(?INITIAL_CIV_COUNT, "all civilisations created"); for _ in 0..INITIAL_CIV_COUNT * 3 { attempt(5, || { @@ -159,7 +161,9 @@ impl Civs { } // Place sites in world + let mut cnt = 0; for site in this.sites.iter() { + cnt += 1; let wpos = site .center .map2(Vec2::from(TerrainChunkSize::RECT_SIZE), |e, sz: u32| { @@ -186,8 +190,9 @@ impl Civs { .get_mut(pos) .map(|chunk| chunk.sites.push(world_site.clone())); } - log::info!("Placed site at {:?}", site.center); + debug!(?site.center, "Placed site at location"); } + info!(?cnt, "all sites placed"); //this.display_info(); diff --git a/world/src/column/mod.rs b/world/src/column/mod.rs index 8d3bc2a419..f587ceba86 100644 --- a/world/src/column/mod.rs +++ b/world/src/column/mod.rs @@ -13,6 +13,7 @@ use std::{ f32, f64, ops::{Add, Div, Mul, Neg, Sub}, }; +use tracing::error; use vek::*; pub struct ColumnGen<'a> { @@ -213,7 +214,7 @@ impl<'a> Sampler<'a> for ColumnGen<'a> { } else { match kind { RiverKind::River { .. } => { - log::error!("What? River: {:?}, Pos: {:?}", river, posj); + error!(?river, ?posj, "What?"); panic!("How can a river have no downhill?"); }, RiverKind::Lake { .. } => { @@ -617,11 +618,11 @@ impl<'a> Sampler<'a> for ColumnGen<'a> { ) = if let Some(dist) = max_border_river_dist { dist } else { - log::error!( - "Ocean: {:?} Here: {:?}, Ocean: {:?}", - max_border_river, - chunk_pos, - max_border_river_pos + error!( + ?max_border_river, + ?chunk_pos, + ?max_border_river_pos, + "downhill error details" ); panic!( "Oceans should definitely have a downhill! \ diff --git a/world/src/sim/erosion.rs b/world/src/sim/erosion.rs index 1412de21af..d1deccd414 100644 --- a/world/src/sim/erosion.rs +++ b/world/src/sim/erosion.rs @@ -4,6 +4,7 @@ use super::{ }; use crate::{config::CONFIG, util::RandomField}; use common::{terrain::TerrainChunkSize, vol::RectVolSize}; +use tracing::{debug, error, warn}; // use faster::*; use itertools::izip; use noise::{NoiseFn, Point3}; @@ -427,7 +428,7 @@ pub fn get_rivers<F: fmt::Debug + Float + Into<f64>, G: Float + Into<f64>>( if slope == 0.0 { // This is not a river--how did this even happen? let pass_idx = (-indirection_idx) as usize; - log::error!( + error!( "Our chunk (and downhill, lake, pass, neighbor_pass): {:?} (to {:?}, in {:?} via \ {:?} to {:?}), chunk water alt: {:?}, lake water alt: {:?}", uniform_idx_as_vec2(chunk_idx), @@ -715,7 +716,7 @@ fn erode( k_da_scale: impl Fn(f64) -> f64, ) { let compute_stats = true; - log::debug!("Done draining..."); + debug!("Done draining..."); // NOTE: To experimentally allow erosion to proceed below sea level, replace 0.0 // with -<Alt as Float>::infinity(). let min_erosion_height = 0.0; // -<Alt as Float>::infinity(); @@ -723,7 +724,7 @@ fn erode( // NOTE: The value being divided by here sets the effective maximum uplift rate, // as everything is scaled to it! let dt = max_uplift as f64 / 1e-3; - log::debug!("dt={:?}", dt); + debug!(?dt, ""); // Minimum sediment thickness before we treat erosion as sediment based. let sediment_thickness = |_n| /*6.25e-5*/1.0e-4 * dt; let neighbor_coef = TerrainChunkSize::RECT_SIZE.map(|e| e as f64); @@ -801,9 +802,9 @@ fn erode( let ((dh, newh, maxh, mrec, mstack, mwrec, area), (mut max_slopes, h_t)) = rayon::join( || { let mut dh = downhill(|posi| h[posi], |posi| is_ocean(posi) && h[posi] <= 0.0); - log::debug!("Computed downhill..."); + debug!("Computed downhill..."); let (boundary_len, _indirection, newh, maxh) = get_lakes(|posi| h[posi], &mut dh); - log::debug!("Got lakes..."); + debug!("Got lakes..."); let (mrec, mstack, mwrec) = get_multi_rec( |posi| h[posi], &dh, @@ -815,12 +816,12 @@ fn erode( dy as Compute, maxh, ); - log::debug!("Got multiple receivers..."); + debug!("Got multiple receivers..."); // TODO: Figure out how to switch between single-receiver and multi-receiver // drainage, as the former is much less computationally costly. // let area = get_drainage(&newh, &dh, boundary_len); let area = get_multi_drainage(&mstack, &mrec, &*mwrec, boundary_len); - log::debug!("Got flux..."); + debug!("Got flux..."); (dh, newh, maxh, mrec, mstack, mwrec, area) }, || { @@ -828,7 +829,7 @@ fn erode( || { let max_slope = get_max_slope(h, rock_strength_nz, |posi| height_scale(n_f(posi))); - log::debug!("Got max slopes..."); + debug!("Got max slopes..."); max_slope }, || h.to_vec().into_boxed_slice(), @@ -987,7 +988,7 @@ fn erode( }, ); - log::debug!("Computed stream power factors..."); + debug!("Computed stream power factors..."); let mut lake_water_volume = vec![0.0 as Compute; WORLD_SIZE.x * WORLD_SIZE.y].into_boxed_slice(); @@ -1056,7 +1057,7 @@ fn erode( }); while err > tol && n_gs_stream_power_law < max_n_gs_stream_power_law { - log::debug!("Stream power iteration #{:?}", n_gs_stream_power_law); + debug!("Stream power iteration #{:?}", n_gs_stream_power_law); // Reset statistics in each loop. maxh = 0.0; @@ -1096,7 +1097,7 @@ fn erode( }); }, ); - log::debug!( + debug!( "(Done precomputation, time={:?}ms).", start_time.elapsed().as_millis() ); @@ -1131,7 +1132,7 @@ fn erode( }); } }); - log::debug!( + debug!( "(Done sediment transport computation, time={:?}ms).", start_time.elapsed().as_millis() ); @@ -1206,7 +1207,7 @@ fn erode( } }, ); - log::debug!( + debug!( "(Done elevation estimation, time={:?}ms).", start_time.elapsed().as_millis() ); @@ -1232,7 +1233,7 @@ fn erode( panic!("Disconnected lake!"); } if h_t_i > 0.0 { - log::warn!("Ocean above zero?"); + warn!("Ocean above zero?"); } // Egress with no outgoing flows. // wh for oceans is always at least min_erosion_height. @@ -1427,21 +1428,20 @@ fn erode( sum_err += (iteration_error + h_stack[stacki] as Compute - h_p_i as Compute).powi(2); }); - log::debug!( + debug!( "(Done erosion computation, time={:?}ms)", start_time.elapsed().as_millis() ); err = (sum_err / mstack.len() as Compute).sqrt(); - log::debug!("(RMSE: {:?})", err); + debug!("(RMSE: {:?})", err); if max_g == 0.0 { err = 0.0; } if n_gs_stream_power_law == max_n_gs_stream_power_law { - log::warn!( + warn!( "Beware: Gauss-Siedel scheme not convergent: err={:?}, expected={:?}", - err, - tol + err, tol ); } } @@ -1507,7 +1507,7 @@ fn erode( new_b_i = new_b_i.min(h_i); *b = new_b_i; }); - log::debug!("Done updating basement and applying soil production..."); + debug!("Done updating basement and applying soil production..."); // update the height to reflect sediment flux. if max_g > 0.0 { @@ -1541,7 +1541,7 @@ fn erode( // endif // enddo - log::debug!( + debug!( "Done applying stream power (max height: {:?}) (avg height: {:?}) (min height: {:?}) (avg \ slope: {:?})\n (above talus angle, geom. mean slope [actual/critical/ratio]: {:?} \ / {:?} / {:?})\n (old avg sediment thickness [all/land]: {:?} / {:?})\n \ @@ -1670,7 +1670,7 @@ fn erode( maxh = h_i.max(maxh); } }); - log::debug!( + debug!( "Done applying thermal erosion (max height: {:?}) (avg height: {:?}) (min height: {:?}) \ (avg slope: {:?})\n (above talus angle, geom. mean slope [actual/critical/ratio]: \ {:?} / {:?} / {:?})\n (avg sediment thickness [all/land]: {:?} / {:?})\n \ @@ -1702,8 +1702,8 @@ fn erode( |posi| max_slopes[posi], -1.0, ); - log::debug!("Done applying diffusion."); - log::debug!("Done eroding."); + debug!("Done applying diffusion."); + debug!("Done eroding."); } /// The Planchon-Darboux algorithm for extracting drainage networks. @@ -1878,7 +1878,7 @@ pub fn get_lakes<F: Float>( }); assert_eq!(newh.len(), downhill.len()); - log::debug!("Old lake roots: {:?}", lake_roots.len()); + debug!("Old lake roots: {:?}", lake_roots.len()); let newh = newh.into_boxed_slice(); let mut maxh = -F::infinity(); @@ -2112,7 +2112,7 @@ pub fn get_lakes<F: Float>( ))); } } - log::debug!("Total lakes: {:?}", pass_flows_sorted.len()); + debug!("Total lakes: {:?}", pass_flows_sorted.len()); // Perform the bfs once again. #[derive(Clone, Copy, PartialEq)] @@ -2520,7 +2520,7 @@ pub fn do_erosion( k_d_scale: f64, k_da_scale: impl Fn(f64) -> f64, ) -> (Box<[Alt]>, Box<[Alt]> /* , Box<[Alt]> */) { - log::debug!("Initializing erosion arrays..."); + debug!("Initializing erosion arrays..."); let oldh_ = (0..WORLD_SIZE.x * WORLD_SIZE.y) .into_par_iter() .map(|posi| oldh(posi) as Alt) @@ -2587,7 +2587,7 @@ pub fn do_erosion( .cloned() .map(|e| e as f64) .sum::<f64>(); - log::debug!("Sum uplifts: {:?}", sum_uplift); + debug!("Sum uplifts: {:?}", sum_uplift); let max_uplift = uplift .into_par_iter() @@ -2599,8 +2599,8 @@ pub fn do_erosion( .cloned() .max_by(|a, b| a.partial_cmp(&b).unwrap()) .unwrap(); - log::debug!("Max uplift: {:?}", max_uplift); - log::debug!("Max g: {:?}", max_g); + debug!("Max uplift: {:?}", max_uplift); + debug!("Max g: {:?}", max_g); // Height of terrain, including sediment. let mut h = oldh_; // Bedrock transport coefficients (diffusivity) in m^2 / year, for sediment. @@ -2619,7 +2619,7 @@ pub fn do_erosion( let height_scale = |n| height_scale(n); let k_da_scale = |q| k_da_scale(q); (0..n_steps).for_each(|i| { - log::debug!("Erosion iteration #{:?}", i); + debug!("Erosion iteration #{:?}", i); erode( &mut h, &mut b, diff --git a/world/src/sim/mod.rs b/world/src/sim/mod.rs index 08d26d4965..67d5d57e14 100644 --- a/world/src/sim/mod.rs +++ b/world/src/sim/mod.rs @@ -52,6 +52,7 @@ use std::{ ops::{Add, Div, Mul, Neg, Sub}, path::PathBuf, }; +use tracing::{debug, warn}; use vek::*; // NOTE: I suspect this is too small (1024 * 16 * 1024 * 16 * 8 doesn't fit in @@ -876,8 +877,8 @@ impl WorldSim { FileOpts::LoadLegacy(ref path) => { let file = match File::open(path) { Ok(file) => file, - Err(err) => { - log::warn!("Couldn't read path for maps: {:?}", err); + Err(e) => { + warn!(?e, ?path, "Couldn't read path for maps"); return None; }, }; @@ -885,11 +886,11 @@ impl WorldSim { let reader = BufReader::new(file); let map: WorldFileLegacy = match bincode::deserialize_from(reader) { Ok(map) => map, - Err(err) => { - log::warn!( - "Couldn't parse legacy map: {:?}). Maybe you meant to try a \ - regular load?", - err + Err(e) => { + warn!( + ?e, + "Couldn't parse legacy map. Maybe you meant to try a regular \ + load?" ); return None; }, @@ -900,8 +901,8 @@ impl WorldSim { FileOpts::Load(ref path) => { let file = match File::open(path) { Ok(file) => file, - Err(err) => { - log::warn!("Couldn't read path for maps: {:?}", err); + Err(e) => { + warn!(?e, ?path, "Couldn't read path for maps"); return None; }, }; @@ -909,11 +910,10 @@ impl WorldSim { let reader = BufReader::new(file); let map: WorldFile = match bincode::deserialize_from(reader) { Ok(map) => map, - Err(err) => { - log::warn!( - "Couldn't parse modern map: {:?}). Maybe you meant to try a \ - legacy load?", - err + Err(e) => { + warn!( + ?e, + "Couldn't parse modern map. Maybe you meant to try a legacy load?" ); return None; }, @@ -924,23 +924,18 @@ impl WorldSim { FileOpts::LoadAsset(ref specifier) => { let reader = match assets::load_file(specifier, &["bin"]) { Ok(reader) => reader, - Err(err) => { - log::warn!( - "Couldn't read asset specifier {:?} for maps: {:?}", - specifier, - err - ); + Err(e) => { + warn!(?e, ?specifier, "Couldn't read asset specifier for maps",); return None; }, }; let map: WorldFile = match bincode::deserialize_from(reader) { Ok(map) => map, - Err(err) => { - log::warn!( - "Couldn't parse modern map: {:?}). Maybe you meant to try a \ - legacy load?", - err + Err(e) => { + warn!( + ?e, + "Couldn't parse modern map. Maybe you meant to try a legacy load?" ); return None; }, @@ -956,7 +951,7 @@ impl WorldSim { Err(e) => { match e { WorldFileError::WorldSizeInvalid => { - log::warn!("World size of map is invalid."); + warn!("World size of map is invalid."); }, } None @@ -1026,8 +1021,8 @@ impl WorldSim { // Check if folder exists and create it if it does not let mut path = PathBuf::from("./maps"); if !path.exists() { - if let Err(err) = std::fs::create_dir(&path) { - log::warn!("Couldn't create folder for map: {:?}", err); + if let Err(e) = std::fs::create_dir(&path) { + warn!(?e, ?path, "Couldn't create folder for map"); return; } } @@ -1039,17 +1034,17 @@ impl WorldSim { .map(|d| d.as_millis()) .unwrap_or(0) )); - let file = match File::create(path) { + let file = match File::create(path.clone()) { Ok(file) => file, - Err(err) => { - log::warn!("Couldn't create file for maps: {:?}", err); + Err(e) => { + warn!(?e, ?path, "Couldn't create file for maps"); return; }, }; let writer = BufWriter::new(file); - if let Err(err) = bincode::serialize_into(writer, &map) { - log::warn!("Couldn't write map: {:?}", err); + if let Err(e) = bincode::serialize_into(writer, &map) { + warn!(?e, "Couldn't write map"); } } })(); @@ -1088,7 +1083,7 @@ impl WorldSim { let is_ocean_fn = |posi: usize| is_ocean[posi]; let mut dh = downhill(|posi| alt[posi], is_ocean_fn); let (boundary_len, indirection, water_alt_pos, maxh) = get_lakes(|posi| alt[posi], &mut dh); - log::debug!("Max height: {:?}", maxh); + debug!(?maxh, "Max height"); let (mrec, mstack, mwrec) = { let mut wh = vec![0.0; WORLD_SIZE.x * WORLD_SIZE.y]; get_multi_rec( @@ -1911,12 +1906,9 @@ impl SimChunk { ); */ } if river_slope.abs() >= 0.25 && cross_section.x >= 1.0 { - log::debug!( - "Big waterfall! Pos area: {:?}, River data: {:?}, slope: {:?}", - wposf, - river, - river_slope - ); + let pos_area = wposf; + let river_data = &river; + debug!(?pos_area, ?river_data, ?river_slope, "Big waterfall!",); } }, Some(RiverKind::Lake { .. }) => {