Merge branch 'kevinglasson/switch-logging-to-tokio-tracing' into 'master'

Kevinglasson/switch logging to tokio tracing

Closes #595

See merge request veloren/veloren!1098

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

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"
+name = "tracing-log"
-version = "0.2.5"
+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",
+ "tracing",
- "pretty_env_logger",
+ "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",
+ "tracing",
- "pretty_env_logger",
+ "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",
 ]

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"
+tracing = { version = "0.1", default-features = false }
-pretty_env_logger = "0.3.1"
+tracing-subscriber = { version = "0.2.3", default-features = false, features = ["fmt", "chrono", "ansi", "smallvec"] }

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...");
 

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"] }

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: {:?}",
+                    ?e,
-                    err
+                    ?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()

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"

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: {:?}",
+                                    ?e,
-                                    name, specifier, 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) {
+            if let Err(e) = reload::<A>(&owned_specifier) {
-                error!("Error reloading {}: {:#?}", &owned_specifier, err);
+                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));
         }

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) {
+                if let Err(e) = self.watcher.watch(path.clone(), RecursiveMode::Recursive) {
-                    warn!("Could not start watching {:#?} due to: {}", &path, err);
+                    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(_) => (),
                     },

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 {

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 {

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 {
+pub fn chunk_transition_cost(_start: &Vec2<i32>, _end: &Vec2<i32>) -> f32 { 1.0f32 }
-    1.0f32
-}

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;

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 {
+    fn from(err: io::Error) -> Self { Error::Network }
-        Error::Network
-    }
 }
 
 impl From<TryRecvError> for Error {
-    fn from(err: TryRecvError) -> Self {
+    fn from(err: TryRecvError) -> Self { Error::Internal }
-        Error::Internal
-    }
 }
 
 impl From<bincode::ErrorKind> for Error {
-    fn from(err: bincode::ErrorKind) -> Self {
+    fn from(err: bincode::ErrorKind) -> Self { Error::InvalidMsg }
-        Error::InvalidMsg
-    }
 }
 
 impl<T> From<mio_extras::channel::SendError<T>> for Error {
-    fn from(err: mio_extras::channel::SendError<T>) -> Self {
+    fn from(err: mio_extras::channel::SendError<T>) -> Self { Error::Internal }
-        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 TCP_TOK: Token = Token(0);
-const CTRL_TOK:      Token = Token(1);
+const CTRL_TOK: Token = Token(1);
-const POSTBOX_TOK:   Token = Token(2);
+const POSTBOX_TOK: Token = Token(2);
-const SEND_TOK:      Token = Token(3);
+const SEND_TOK: Token = Token(3);
-const RECV_TOK:      Token = Token(4);
+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(
+        let worker =
-            worker_poll,
+            thread::spawn(move || office_worker(worker_poll, tcp_listener, ctrl_rx, postbox_tx));
-            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> {
+    pub fn error(&self) -> Option<Error> { self.err.clone() }
-        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(
+        if let Err(err) = self.poll.poll(&mut events, Some(Duration::new(0, 0))) {
-            &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(
+                TCP_TOK => postbox_tx.send(match tcp_listener.accept() {
-                    match tcp_listener.accept() {
+                    Ok((stream, _)) => PostBox::from_tcpstream(stream),
-                        Ok((stream, _)) => PostBox::from_tcpstream(stream),
+                    Err(err) => Err(err.into()),
-                        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(
+        let worker = thread::spawn(move || {
-            worker_poll,
+            postbox_worker(worker_poll, tcp_stream, ctrl_rx, send_rx, recv_tx)
-            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> {
+    pub fn error(&self) -> Option<Error> { self.err.clone() }
-        self.err.clone()
-    }
 
-    pub fn send(&mut self, data: S) {
+    pub fn send(&mut self, data: S) { let _ = self.send_tx.send(data); }
-        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(
+            if let Err(err) = self.poll.poll(&mut events, Some(Duration::new(0, 0))) {
-                &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(
+        if let Err(err) = self.poll.poll(&mut events, Some(Duration::new(0, 0))) {
-            &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 =>
+                CTRL_TOK => match ctrl_rx.try_recv() {
-                    match ctrl_rx.try_recv() {
+                    Ok(CtrlMsg::Shutdown) => {
-                        Ok(CtrlMsg::Shutdown) => {
+                        break 'work;
-                            break 'work;
+                    },
-                        },
+                    Err(TryRecvError::Empty) => (),
-                        Err(TryRecvError::Empty) => (),
+                    Err(err) => {
-                        Err(err) => {
+                        recv_tx.send(Err(err.into()))?;
-                            recv_tx.send(Err(err.into()))?;
+                        break 'work;
-                            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
+                            let mut bytes = msg_bytes.len().to_le_bytes().as_ref().to_vec();
-                                .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 {
+                            RecvState::ReadHead(head) => {
-                                let len = usize::from_le_bytes(<[u8; 8]>::try_from(head.as_slice()).unwrap());
+                                if head.len() == 8 {
-                                if len > MAX_MSG_BYTES {
+                                    let len = usize::from_le_bytes(
-                                    println!("TOO BIG! {:x}", len);
+                                        <[u8; 8]>::try_from(head.as_slice()).unwrap(),
-                                    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(),
                                     );
-                                }
+                                    if len > MAX_MSG_BYTES {
-                            } else {
+                                        println!("TOO BIG! {:x}", len);
-                                let mut b = [0; 1];
+                                        recv_tx.send(Err(Error::InvalidMsg))?;
-                                match tcp_stream.read(&mut b) {
+                                        break 'work;
-                                    Ok(0) => {},
+                                    } else if len == 0 {
-                                    Ok(_) => head.push(b[0]),
+                                        recv_state = RecvState::ReadHead(Vec::with_capacity(8));
-                                    Err(_) => break,
+                                        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 {
+                            RecvState::ReadBody(len, body) => {
-                                match bincode::deserialize(&body) {
+                                if body.len() == *len {
-                                    Ok(msg) => {
+                                    match bincode::deserialize(&body) {
-                                        recv_tx.send(Ok(msg))?;
+                                        Ok(msg) => {
-                                        recv_state = RecvState::ReadHead(Vec::with_capacity(8));
+                                            recv_tx.send(Ok(msg))?;
-                                    },
+                                            recv_state = RecvState::ReadHead(Vec::with_capacity(8));
-                                    Err(err) => {
+                                        },
-                                        recv_tx.send(Err((*err).into()))?;
+                                        Err(err) => {
-                                        break 'work;
+                                            recv_tx.send(Err((*err).into()))?;
-                                    },
+                                            break 'work;
-                                }
+                                        },
-                            } else {
+                                    }
-                                let left = *len - body.len();
+                                } else {
-                                let mut buf = vec![0; left];
+                                    let left = *len - body.len();
-                                match tcp_stream.read(&mut buf) {
+                                    let mut buf = vec![0; left];
-                                    Ok(_) => body.append(&mut buf),
+                                    match tcp_stream.read(&mut buf) {
-                                    Err(err) => {
+                                        Ok(_) => body.append(&mut buf),
-                                        recv_tx.send(Err(err.into()))?;
+                                        Err(err) => {
-                                        break 'work;
+                                            recv_tx.send(Err(err.into()))?;
-                                    },
+                                            break 'work;
+                                        },
+                                    }
                                 }
                             },
                         }

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 {

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) {
+    if let Err(e) = world.write_storage::<C>().insert(entity, comp) {
-        error!("Error inserting : {:?}", err);
+        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"
         );
     }
 }

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) {
+            if let Err(e) = self.delete_entity(entity) {
-                error!("Failed to delete entity: {:?}", err);
+                error!(?e, "Failed to delete entity");
             }
         }
     }

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);
         }
     }
 

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"
+tracing = { version = "0.1", default-features = false }
-pretty_env_logger = "0.3.1"
+tracing-subscriber = { version = "0.2.3", default-features = false, features = ["fmt", "chrono", "ansi", "smallvec"] }

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

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"

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 {

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) {
+        if let Err(e) = server.state.delete_entity_recorded(entity) {
-            error!("Failed to delete light: {:?}", err);
+            error!(?e, "Failed to delete light: {:?}", e);
         }
     }
 

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: {:?}",
+                    ?e,
-                    err
+                    "Error inserting ForceUpdate component when respawning client"
                 )
             });
     }

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| {
+                clients
-                    error!(
+                    .insert(possesse, client)
-                        "Error inserting client component during possession: {:?}",
+                    .err()
-                        e
+                    .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!(?e, "Error inserting player component during possession")
-                                "Error inserting player component during possession: {:?}",
-                                e
-                            )
                         });
                     }
                 }
@@ -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!(?e, "Error inserting waypoint component during possession",)
-                                "Error inserting waypoint component during possession {:?}",
-                                e
-                            )
                         });
                     }
                 }

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
                     }
                 },

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) {
+    if let Err(e) = state.delete_entity_recorded(entity) {
-        error!("Failed to delete entity when removing character: {:?}", err);
+        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) {
+    if let Err(e) = state.delete_entity_recorded(entity) {
-        error!("Failed to delete disconnected client: {:?}", err);
+        error!(?e, ?entity, "Failed to delete disconnected client");
     }
 
     Event::ClientDisconnected { entity }

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) =
+        if let Some(e) = persistence::run_migrations(&this.server_settings.persistence_db_dir).err()
-            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!(
+        let git_hash = *common::util::GIT_HASH;
-            "Server version: {}[{}]",
+        let git_date = *common::util::GIT_DATE;
-            *common::util::GIT_HASH,
+        info!(?git_hash, ?git_date, "Server version",);
-            *common::util::GIT_DATE
-        );
 
         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) {
+            if let Err(e) = self.state.delete_entity_recorded(entity) {
-                error!("Failed to delete agent outside the terrain: {:?}", err);
+                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 });
             }

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",
                     );
                 }
             }

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,
+                        &character_data.id, error
-                        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!(
+                    let char_id = character_data.id;
-                        "Failed to create an loadout record for character {}: {}",
+                    warn!(
-                        &character_data.id,
+                        ?e,
-                        error
+                        ?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) {
+        if let Err(e) = self.update_tx.as_ref().unwrap().send(updates) {
-            log::error!("Could not send stats updates: {:?}", err);
+            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!(
+        warn!(?e, ?character_id, "Failed to update stats for character",)
-            "Failed to update stats for character: {:?}: {:?}",
-            character_id,
-            error
-        )
     }
 
-    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!(
+        warn!(
-            "Failed to update inventory for character: {:?}: {:?}",
+            ?e,
-            character_id,
+            ?character_id,
-            error
+            "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!(
+        warn!(?e, ?character_id, "Failed to update loadout for character",)
-            "Failed to update loadout for character: {:?}: {:?}",
-            character_id,
-            error
-        )
     }
 }
 
 impl Drop for CharacterUpdater {
     fn drop(&mut self) {
         drop(self.update_tx.take());
-        if let Err(err) = self.handle.take().unwrap().join() {
+        if let Err(e) = self.handle.take().unwrap().join() {
-            log::error!("Error from joining character update thread: {:?}", err);
+            error!(?e, "Error from joining character update thread");
         }
     }
 }

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: {}",
+             result in a higher likelihood of locking errors"
-            error
         );
     }
 
@@ -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") {
+    if let Some(saves_dir) = env::var_os("VELOREN_SAVES_DIR") {
-        let path = PathBuf::from(val);
+        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()
 }

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) => {
+            Err(e) => {
-                log::warn!("Failed to deserialise inventory data: {}", error);
+                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) => {
+            Err(e) => {
-                log::warn!("Failed to deserialise loadout data: {}", error);
+                warn!(?e, "Failed to deserialise loadout data");
 
                 // We don't have a weapon reference here, so we default to sword
                 let loadout = LoadoutBuilder::new()

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

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) => {
+            Err(e) => {
-                log::warn!(
+                warn!(
-                    "{}",
+                    ?e,
-                    format!(
+                    ?character_id,
-                        "Failed to load character data for character_id {}: {}",
+                    "Failed to load character data for character_id"
-                        character_id, error
-                    )
                 );
 
                 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"

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!(
+                            Err(ChatMsgValidationError::TooLong) => {
-                                "Recieved a chat message that's too long (max:{} len:{})",
+                                let max = MAX_BYTES_CHAT_MSG;
-                                MAX_BYTES_CHAT_MSG,
+                                let len = message.len();
-                                message.len()
+                                warn!(?len, ?max, "Recieved a chat message that's too long")
-                            ),
+                            },
                         },
                         ClientState::Pending => {},
                     },

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"
         );

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"
 

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();
+            warn!(
-            for path in std::mem::take(&mut modified_paths) {
+                ?modified_paths,
-                info.push('\n');
+                "Hot reloading animations because these files were modified"
-                info.push('\"');
+            );
-                info.push_str(&path);
-                info.push('\"');
-            }
-            log::warn!("{}", info);
 
             // 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
     }
 }

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
                 )
             });
 

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()
         },
     }

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)
                 );

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)
                 );

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()
                 })

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

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!(
+            error!(?full_specifier, "Could not load vox file for item images",);
-                "Could not load vox file for item images: {}",
-                full_specifier
-            );
             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!(
+            error!(?full_specifier, "Could not load image file for item images");
-                "Could not load image file for item images: {}",
-                full_specifier
-            );
             assets::load_expect::<DynamicImage>("voxygen.element.not_found")
         },
     }

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,
+                self.metadata.language_identifier, missing_key
-                missing_key
             );
         }
         for missing_key in missing_vectors {
-            log::warn!(
+            warn!(
                 "[{:?}] Missing vector key {:?}",
-                self.metadata.language_identifier,
+                self.metadata.language_identifier, missing_key
-                missing_key
             );
         }
     }

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
+use tracing::{error, info};
-pub fn init(
+use tracing_subscriber::{filter::LevelFilter, prelude::*, registry, EnvFilter};
-    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);
 
-    let mut base = fern::Dispatch::new()
+const RUST_LOG_ENV: &str = "RUST_LOG";
-        .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);
 
-    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 =
+    // We will do lower logging than the default (INFO) by INCLUSION. This
-        fern::Dispatch::new()
+    // means that if you need lower level logging for a specific module, then
-            .level(file_log_level)
+    // put it in the environment in the correct format i.e. DEBUG logging for
-            .format(|out, message, record| {
+    // this crate would be veloren_voxygen=debug.
-                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
-                ))
-            });
 
-    // Try to create the logs file parent directories.
+    let filter = match std::env::var_os(RUST_LOG_ENV).map(|s| s.into_string()) {
-    let mut log_file_created = fs::create_dir_all(&settings.log.logs_path);
+        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() {
+    // Create the terminal writer layer.
-        // Try to create the log file.
+    let (non_blocking, _stdio_guard) = tracing_appender::non_blocking(std::io::stdout());
-        match fern::log_file(
+    _guards.push(_stdio_guard);
-            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),
-        }
-    }
 
-    let stdout_cfg = fern::Dispatch::new()
+    // Try to create the log file's parent folders.
-        .level(term_log_level)
+    let log_folders_created = fs::create_dir_all(&settings.log.logs_path);
-        .format(move |out, message, record| {
+    const LOG_FILENAME: &str = "voxygen.log";
-            out.finish(format_args!(
-                "[{}] {}",
-                colors.color(record.level()),
-                message
-            ))
-        })
-        .chain(std::io::stdout());
 
-    if settings.log.log_to_file {
+    match log_folders_created {
-        base = base.chain(file_cfg);
+        // If the parent folders were created then attach both a terminal and a
-    }
+        // file writer to the registry and init it.
-    base.chain(stdout_cfg)
+        Ok(_) => {
-        .apply()
+            let file_appender =
-        .expect("Failed to setup logging!");
+                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
+    // Return the guards
-    if let Err(e) = log_file_created {
+    _guards
-        log::error!("Failed to create log file! {}", e);
-    }
 }

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};
-use std::{mem, panic, str::FromStr};
+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| {
+    .unwrap_or_else(|e| {
-        log::warn!(
+        let preferred_language = &global_state.settings.language.selected_language;
-            "Impossible to load {} language: change to the default language (English) instead. \
+        warn!(
-             Source error: {:?}",
+            ?e,
-            &global_state.settings.language.selected_language,
+            ?preferred_language,
-            error
+            "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
+    states.last().map(|current_state| {
-        .last()
+        let current_state = current_state.name();
-        .map(|current_state| debug!("Started game with 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| {
+                states.last_mut().map(|old_state_box| {
-                    debug!(
+                    let old_state = old_state_box.name();
-                        "Switching to state '{}' from state '{}'.",
+                    let new_state = new_state_box.name();
-                        new_state.name(),
+                    debug!(?old_state, ?new_state, "Switching to states",);
-                        old_state.name()
+                    mem::swap(old_state_box, &mut new_state_box);
-                    );
-                    mem::swap(old_state, &mut new_state);
                     global_state.on_play_state_changed();
                 });
             },

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;
             }

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() {
+    if let Err(e) = global_state.settings.save_to_file() {
-        warn!("Failed to save settings: {:?}", err);
+        warn!(?e, "Failed to save settings");
     }
 
     if comp::Player::alias_is_valid(&username) {

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) {
+                    if let Err(e) = std::fs::rename(path.clone(), new_path.clone()) {
-                        log::warn!("Failed to rename meta file. {}", err);
+                        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") {
+        if let Some(path) = std::env::var_os("VOXYGEN_CONFIG") {
-            let meta = PathBuf::from(val).join("meta.ron");
+            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")

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!(
+                    warn!(
-                        "Failed to parse profile file! Falling back to default. {}",
+                        ?e,
-                        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) {
+                    if let Err(e) = std::fs::rename(path.clone(), new_path.clone()) {
-                        log::warn!("Failed to rename profile file. {}", err);
+                        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() {
+        if let Err(e) = self.save_to_file() {
-            warn!("Failed to save profile: {:?}", err);
+            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") {
+        if let Some(path) = std::env::var_os("VOXYGEN_CONFIG") {
-            let profile = PathBuf::from(val).join("profile.ron");
+            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")

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!(
+            Err(e) => error!(?e, "Could not recreate shaders from assets due to an error",),
-                "Could not recreate shaders from assets due to an error: {:#?}",
-                e
-            ),
         }
     }
 

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.species, body.body_type
+                    ?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);
                 },
             }

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::*;
 

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);

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) => {

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) {
+                    if let Err(e) = std::fs::rename(path.clone(), new_path.clone()) {
-                        log::warn!("Failed to rename settings file. {}", err);
+                        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() {
+        if let Err(e) = self.save_to_file() {
-            warn!("Failed to save settings: {:?}", err);
+            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") {
+        if let Some(path) = std::env::var_os("VOXYGEN_CONFIG") {
-            let settings = PathBuf::from(val).join("settings.ron");
+            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")

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;
 

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");
     }
 }

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)]

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 \
+                    ?e,
-                     to no controller support.",
+                    "Platform-specific error when creating a Gilrs instance. Falling back to no \
-                    err
+                     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) {
+                        if let Err(e) = std::fs::create_dir_all(&path) {
-                            warn!("Couldn't create folder for screenshot: {:?}", err);
+                            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) {
+                    if let Err(e) = img.save(&path) {
-                        warn!("Couldn't save screenshot: {:?}", err);
+                        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!(
+            Err(e) => error!(?e, "Couldn't create screenshot due to renderer error"),
-                "Couldn't create screenshot due to renderer error: {:?}",
-                err
-            ),
         }
     }
 

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"

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) {
+                    if let Err(e) = std::fs::create_dir(&path) {
-                        log::warn!("Couldn't create folder for screenshot: {:?}", err);
+                        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) {
+                if let Err(e) = world_map.save(&path) {
-                    log::warn!("Couldn't save screenshot: {:?}", err);
+                    warn!(?e, ?path, "Couldn't save screenshot");
                 }
             }
         }

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();
 

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!(
+                                            error!(
-                                                "Ocean: {:?} Here: {:?}, Ocean: {:?}",
+                                                ?max_border_river,
-                                                max_border_river,
+                                                ?chunk_pos,
-                                                chunk_pos,
+                                                ?max_border_river_pos,
-                                                max_border_river_pos
+                                                "downhill error details"
                                             );
                                             panic!(
                                                 "Oceans should definitely have a downhill! \

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,
+                err, tol
-                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.");
+    debug!("Done applying diffusion.");
-    log::debug!("Done eroding.");
+    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);
+    debug!("Max uplift: {:?}", max_uplift);
-    log::debug!("Max g: {:?}", max_g);
+    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,

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) => {
+                        Err(e) => {
-                            log::warn!("Couldn't read path for maps: {:?}", err);
+                            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) => {
+                        Err(e) => {
-                            log::warn!(
+                            warn!(
-                                "Couldn't parse legacy map: {:?}).  Maybe you meant to try a \
+                                ?e,
-                                 regular load?",
+                                "Couldn't parse legacy map.  Maybe you meant to try a regular \
-                                err
+                                 load?"
                             );
                             return None;
                         },
@@ -900,8 +901,8 @@ impl WorldSim {
                 FileOpts::Load(ref path) => {
                     let file = match File::open(path) {
                         Ok(file) => file,
-                        Err(err) => {
+                        Err(e) => {
-                            log::warn!("Couldn't read path for maps: {:?}", err);
+                            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) => {
+                        Err(e) => {
-                            log::warn!(
+                            warn!(
-                                "Couldn't parse modern map: {:?}).  Maybe you meant to try a \
+                                ?e,
-                                 legacy load?",
+                                "Couldn't parse modern map.  Maybe you meant to try a legacy load?"
-                                err
                             );
                             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) => {
+                        Err(e) => {
-                            log::warn!(
+                            warn!(?e, ?specifier, "Couldn't read asset specifier for maps",);
-                                "Couldn't read asset specifier {:?} for maps: {:?}",
-                                specifier,
-                                err
-                            );
                             return None;
                         },
                     };
 
                     let map: WorldFile = match bincode::deserialize_from(reader) {
                         Ok(map) => map,
-                        Err(err) => {
+                        Err(e) => {
-                            log::warn!(
+                            warn!(
-                                "Couldn't parse modern map: {:?}).  Maybe you meant to try a \
+                                ?e,
-                                 legacy load?",
+                                "Couldn't parse modern map.  Maybe you meant to try a legacy load?"
-                                err
                             );
                             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) {
+                    if let Err(e) = std::fs::create_dir(&path) {
-                        log::warn!("Couldn't create folder for map: {:?}", err);
+                        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) => {
+                    Err(e) => {
-                        log::warn!("Couldn't create file for maps: {:?}", err);
+                        warn!(?e, ?path, "Couldn't create file for maps");
                         return;
                     },
                 };
 
                 let writer = BufWriter::new(file);
-                if let Err(err) = bincode::serialize_into(writer, &map) {
+                if let Err(e) = bincode::serialize_into(writer, &map) {
-                    log::warn!("Couldn't write map: {:?}", err);
+                    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!(
+                    let pos_area = wposf;
-                        "Big waterfall! Pos area: {:?}, River data: {:?}, slope: {:?}",
+                    let river_data = &river;
-                        wposf,
+                    debug!(?pos_area, ?river_data, ?river_slope, "Big waterfall!",);
-                        river,
-                        river_slope
-                    );
                 }
             },
             Some(RiverKind::Lake { .. }) => {