From 0d919a9dc6b8cfc4bdcba726d771c5070049c749 Mon Sep 17 00:00:00 2001 From: Songtronix Date: Sat, 23 Nov 2019 15:34:03 +0100 Subject: [PATCH 1/4] improve(log): adjust verbosity of some logging fix: settings do not log due to logging being initialized to late --- server/src/lib.rs | 9 +++-- voxygen/src/logging.rs | 55 +++++++++++++++++++++++++++++ voxygen/src/main.rs | 76 ++++++++-------------------------------- world/src/sim/erosion.rs | 22 ++++++------ world/src/sim/mod.rs | 2 +- 5 files changed, 85 insertions(+), 79 deletions(-) create mode 100644 voxygen/src/logging.rs diff --git a/server/src/lib.rs b/server/src/lib.rs index 3ce446fed5..41eaeb78d6 100644 --- a/server/src/lib.rs +++ b/server/src/lib.rs @@ -30,7 +30,7 @@ use common::{ terrain::{block::Block, TerrainChunkSize, TerrainGrid}, vol::{ReadVol, RectVolSize, Vox}, }; -use log::{debug, trace}; +use log::debug; use metrics::ServerMetrics; use rand::Rng; use specs::{join::Join, world::EntityBuilder as EcsEntityBuilder, Builder, Entity as EcsEntity}; @@ -178,8 +178,7 @@ impl Server { .expect("Failed to initialize server metrics submodule."), server_settings: settings.clone(), }; - debug!("created veloren server"); - trace!("server configuration: {:?}", &settings); + debug!("created veloren server with: {:?}", &settings); Ok(this) } @@ -973,7 +972,7 @@ impl Server { .with(client) .build(); // Return the state of the current world (all of the components that Sphynx tracks). - log::info!("Starting initial sync with client."); + log::debug!("Starting initial sync with client."); self.state .ecs() .write_storage::() @@ -985,7 +984,7 @@ impl Server { server_info: self.server_info.clone(), // world_map: (WORLD_SIZE/*, self.world.sim().get_map()*/), }); - log::info!("Done initial sync with client."); + log::debug!("Done initial sync with client."); frontend_events.push(Event::ClientConnected { entity }); } diff --git a/voxygen/src/logging.rs b/voxygen/src/logging.rs new file mode 100644 index 0000000000..6420df83f5 --- /dev/null +++ b/voxygen/src/logging.rs @@ -0,0 +1,55 @@ +use fern::colors::{Color, ColoredLevelConfig}; + +pub fn init(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 base = fern::Dispatch::new() + .level_for("dot_vox::parser", log::LevelFilter::Warn) + .level_for("gfx_device_gl::factory", log::LevelFilter::Warn) + .level_for("veloren_voxygen::discord", log::LevelFilter::Warn) + .level_for("uvth", log::LevelFilter::Warn) + .level_for("tiny_http", log::LevelFilter::Warn); + + let time = chrono::offset::Utc::now(); + + let file_cfg = fern::Dispatch::new() + .level(file_log_level) + .format(|out, message, record| { + out.finish(format_args!( + "{}[{}:{}][{}] {}", + chrono::Local::now().format("[%Y-%m-%d][%H:%M:%S]"), + record.target(), + record + .line() + .map(|x| x.to_string()) + .unwrap_or("X".to_string()), + record.level(), + message + )) + }) + .chain( + fern::log_file(&format!("voxygen-{}.log", time.format("%Y-%m-%d-%H"))) + .expect("Failed to create log file!"), + ); + + let stdout_cfg = fern::Dispatch::new() + .level(term_log_level) + .format(move |out, message, record| { + out.finish(format_args!( + "[{}] {}", + colors.color(record.level()), + message + )) + }) + .chain(std::io::stdout()); + + base.chain(file_cfg) + .chain(stdout_cfg) + .apply() + .expect("Failed to setup logging!"); +} diff --git a/voxygen/src/main.rs b/voxygen/src/main.rs index 2d6ff274e3..d8817b27db 100644 --- a/voxygen/src/main.rs +++ b/voxygen/src/main.rs @@ -19,6 +19,7 @@ pub mod audio; pub mod error; pub mod hud; pub mod key_state; +mod logging; pub mod menu; pub mod mesh; pub mod render; @@ -33,9 +34,7 @@ pub mod window; pub use crate::error::Error; use crate::{audio::AudioFrontend, menu::main::MainMenuState, settings::Settings, window::Window}; -use log::{self, debug, error, info}; - -use fern::colors::{Color, ColoredLevelConfig}; +use log::{self, debug, error}; use std::{mem, panic, str::FromStr}; /// A type used to store state that is shared between all play states. @@ -97,6 +96,16 @@ lazy_static! { } fn main() { + // 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); + + // TODO: Use another environment variable for this? + let file_log_level = log::LevelFilter::Debug; + logging::init(term_log_level, file_log_level); + // Load the settings let settings = Settings::load(); // Save settings to add new fields or create the file if it is not already there @@ -126,63 +135,6 @@ fn main() { let settings = &global_state.settings; - // 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 colors = ColoredLevelConfig::new() - .error(Color::Red) - .warn(Color::Yellow) - .info(Color::Cyan) - .debug(Color::Green) - .trace(Color::BrightBlack); - - let base = fern::Dispatch::new() - .level_for("dot_vox::parser", log::LevelFilter::Warn) - .level_for("gfx_device_gl::factory", log::LevelFilter::Warn) - .level_for("veloren_voxygen::discord", log::LevelFilter::Warn); - // TODO: Filter tracing better such that our own tracing gets seen more easily - - let time = chrono::offset::Utc::now(); - - let file_cfg = fern::Dispatch::new() - .level(log::LevelFilter::Trace) - .format(|out, message, record| { - out.finish(format_args!( - "{}[{}:{}][{}] {}", - chrono::Local::now().format("[%Y-%m-%d][%H:%M:%S]"), - record.target(), - record - .line() - .map(|x| x.to_string()) - .unwrap_or("X".to_string()), - record.level(), - message - )) - }) - .chain( - fern::log_file(&format!("voxygen-{}.log", time.format("%Y-%m-%d-%H"))) - .expect("Failed to create log file!"), - ); - - let stdout_cfg = fern::Dispatch::new() - .level(term_log_level) - .format(move |out, message, record| { - out.finish(format_args!( - "[{}] {}", - colors.color(record.level()), - message - )) - }) - .chain(std::io::stdout()); - - base.chain(file_cfg) - .chain(stdout_cfg) - .apply() - .expect("Failed to setup logging!"); - // Set up panic handler to relay swish panic messages to the user let settings_clone = settings.clone(); let default_hook = panic::take_hook(); @@ -261,7 +213,7 @@ fn main() { let mut states: Vec> = vec![Box::new(MainMenuState::new(&mut global_state))]; states .last() - .map(|current_state| info!("Started game with state '{}'", current_state.name())); + .map(|current_state| debug!("Started game with state '{}'", current_state.name())); // What's going on here? // --------------------- @@ -279,7 +231,7 @@ fn main() { match state_result { PlayStateResult::Shutdown => { direction = Direction::Backwards; - info!("Shutting down all states..."); + debug!("Shutting down all states..."); while states.last().is_some() { states.pop().map(|old_state| { debug!("Popped state '{}'.", old_state.name()); diff --git a/world/src/sim/erosion.rs b/world/src/sim/erosion.rs index 4845033236..b4af42878e 100644 --- a/world/src/sim/erosion.rs +++ b/world/src/sim/erosion.rs @@ -579,22 +579,22 @@ fn erode( uplift: impl Fn(usize) -> f32, is_ocean: impl Fn(usize) -> bool + Sync, ) { - log::info!("Done draining..."); + log::debug!("Done draining..."); let mmaxh = 1.0; let k = erosion_base as f64 + 2.244 / mmaxh as f64 * max_uplift as f64; let ((dh, indirection, newh, area), max_slope) = rayon::join( || { let mut dh = downhill(h, |posi| is_ocean(posi)); - log::info!("Computed downhill..."); + log::debug!("Computed downhill..."); let (boundary_len, indirection, newh) = get_lakes(&h, &mut dh); - log::info!("Got lakes..."); + log::debug!("Got lakes..."); let area = get_drainage(&newh, &dh, boundary_len); - log::info!("Got flux..."); + log::debug!("Got flux..."); (dh, indirection, newh, area) }, || { let max_slope = get_max_slope(h, rock_strength_nz); - log::info!("Got max slopes..."); + log::debug!("Got max slopes..."); max_slope }, ); @@ -669,7 +669,7 @@ fn erode( } maxh = h[posi].max(maxh); } - log::info!( + log::debug!( "Done eroding (max height: {:?}) (avg height: {:?}) (avg slope: {:?})", maxh, if nland == 0 { @@ -841,7 +841,7 @@ pub fn get_lakes(h: &[f32], downhill: &mut [isize]) -> (usize, Box<[i32]>, Box<[ } assert_eq!(newh.len(), downhill.len()); - log::info!("Old lake roots: {:?}", lake_roots.len()); + log::debug!("Old lake roots: {:?}", lake_roots.len()); let newh = newh.into_boxed_slice(); // Now, we know that the sum of all the indirection nodes will be the same as the number of @@ -1067,7 +1067,7 @@ pub fn get_lakes(h: &[f32], downhill: &mut [isize]) -> (usize, Box<[i32]>, Box<[ } // println!("I am a pass: {:?}", (uniform_idx_as_vec2(chunk_idx as usize), uniform_idx_as_vec2(neighbor_idx as usize))); } - log::info!("Total lakes: {:?}", pass_flows_sorted.len()); + log::debug!("Total lakes: {:?}", pass_flows_sorted.len()); // Perform the bfs once again. let mut newh = Vec::with_capacity(downhill.len()); @@ -1130,17 +1130,17 @@ pub fn do_erosion( .cloned() .map(|e| e as f64) .sum::(); - log::info!("Sum uplifts: {:?}", sum_uplift); + log::debug!("Sum uplifts: {:?}", sum_uplift); let max_uplift = uplift .into_par_iter() .cloned() .max_by(|a, b| a.partial_cmp(&b).unwrap()) .unwrap(); - log::info!("Max uplift: {:?}", max_uplift); + log::debug!("Max uplift: {:?}", max_uplift); let mut h = oldh_; for i in 0..n { - log::info!("Erosion iteration #{:?}", i); + log::debug!("Erosion iteration #{:?}", i); erode( &mut h, erosion_base, diff --git a/world/src/sim/mod.rs b/world/src/sim/mod.rs index d18281b334..ce7a484676 100644 --- a/world/src/sim/mod.rs +++ b/world/src/sim/mod.rs @@ -1083,7 +1083,7 @@ impl SimChunk { ); */ } if river_slope.abs() >= 1.0 && cross_section.x >= 1.0 { - log::info!( + log::debug!( "Big waterfall! Pos area: {:?}, River data: {:?}, slope: {:?}", wposf, river, From 9141cc07d05231f9db3d50670169b19a23c67d86 Mon Sep 17 00:00:00 2001 From: Songtronix Date: Sun, 24 Nov 2019 17:22:15 +0100 Subject: [PATCH 2/4] feat(env): configurable verbosity of log file via VOXYGEN_FILE_LOG environment variable --- voxygen/src/main.rs | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/voxygen/src/main.rs b/voxygen/src/main.rs index d8817b27db..da6a80261e 100644 --- a/voxygen/src/main.rs +++ b/voxygen/src/main.rs @@ -102,8 +102,11 @@ fn main() { .and_then(|s| log::LevelFilter::from_str(&s).ok()) .unwrap_or(log::LevelFilter::Warn); - // TODO: Use another environment variable for this? - let file_log_level = log::LevelFilter::Debug; + 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); + logging::init(term_log_level, file_log_level); // Load the settings From b03e4ac261a8a1630577fb4b327cbc45c76c7398 Mon Sep 17 00:00:00 2001 From: Songtronix Date: Wed, 18 Dec 2019 20:35:17 +0100 Subject: [PATCH 3/4] feat(log): configurable creation of log file additionally allows to ignore any errors with the log file furthermore prints out full log file path to the user incase of a panic --- voxygen/src/logging.rs | 58 +++++++++++++++++++++++++++-------------- voxygen/src/main.rs | 19 +++++++++----- voxygen/src/settings.rs | 14 +++++++--- 3 files changed, 60 insertions(+), 31 deletions(-) diff --git a/voxygen/src/logging.rs b/voxygen/src/logging.rs index 6420df83f5..78b9587eea 100644 --- a/voxygen/src/logging.rs +++ b/voxygen/src/logging.rs @@ -1,6 +1,12 @@ use fern::colors::{Color, ColoredLevelConfig}; -pub fn init(term_log_level: log::LevelFilter, file_log_level: log::LevelFilter) { +use crate::settings::Settings; + +pub fn init( + settings: &Settings, + term_log_level: log::LevelFilter, + file_log_level: log::LevelFilter, +) { let colors = ColoredLevelConfig::new() .error(Color::Red) .warn(Color::Yellow) @@ -8,7 +14,7 @@ pub fn init(term_log_level: log::LevelFilter, file_log_level: log::LevelFilter) .debug(Color::Green) .trace(Color::BrightBlack); - let base = fern::Dispatch::new() + let mut base = fern::Dispatch::new() .level_for("dot_vox::parser", log::LevelFilter::Warn) .level_for("gfx_device_gl::factory", log::LevelFilter::Warn) .level_for("veloren_voxygen::discord", log::LevelFilter::Warn) @@ -17,25 +23,35 @@ pub fn init(term_log_level: log::LevelFilter, file_log_level: log::LevelFilter) let time = chrono::offset::Utc::now(); - let file_cfg = fern::Dispatch::new() - .level(file_log_level) - .format(|out, message, record| { - out.finish(format_args!( - "{}[{}:{}][{}] {}", - chrono::Local::now().format("[%Y-%m-%d][%H:%M:%S]"), - record.target(), - record - .line() - .map(|x| x.to_string()) - .unwrap_or("X".to_string()), - record.level(), - message - )) - }) - .chain( + let mut file_cfg = + fern::Dispatch::new() + .level(file_log_level) + .format(|out, message, record| { + out.finish(format_args!( + "{}[{}:{}][{}] {}", + chrono::Local::now().format("[%Y-%m-%d][%H:%M:%S]"), + record.target(), + record + .line() + .map(|x| x.to_string()) + .unwrap_or("X".to_string()), + record.level(), + message + )) + }); + + // Based on settings ignore errors incase log file can't be created + if !settings.log.ignore_errors { + file_cfg = file_cfg.chain( fern::log_file(&format!("voxygen-{}.log", time.format("%Y-%m-%d-%H"))) .expect("Failed to create log file!"), ); + } else { + if let Ok(log_file) = fern::log_file(&format!("voxygen-{}.log", time.format("%Y-%m-%d-%H"))) + { + file_cfg = file_cfg.chain(log_file); + } + } let stdout_cfg = fern::Dispatch::new() .level(term_log_level) @@ -48,8 +64,10 @@ pub fn init(term_log_level: log::LevelFilter, file_log_level: log::LevelFilter) }) .chain(std::io::stdout()); - base.chain(file_cfg) - .chain(stdout_cfg) + if settings.log.log_to_file { + base = base.chain(file_cfg); + } + base.chain(stdout_cfg) .apply() .expect("Failed to setup logging!"); } diff --git a/voxygen/src/main.rs b/voxygen/src/main.rs index da6a80261e..6ebdfc38a6 100644 --- a/voxygen/src/main.rs +++ b/voxygen/src/main.rs @@ -34,7 +34,7 @@ pub mod window; pub use crate::error::Error; use crate::{audio::AudioFrontend, menu::main::MainMenuState, settings::Settings, window::Window}; -use log::{self, debug, error}; +use log::{debug, error}; use std::{mem, panic, str::FromStr}; /// A type used to store state that is shared between all play states. @@ -107,10 +107,13 @@ fn main() { .and_then(|s| log::LevelFilter::from_str(&s).ok()) .unwrap_or(log::LevelFilter::Debug); - logging::init(term_log_level, file_log_level); - // 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 whether we create a log file or not. let settings = Settings::load(); + + 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 if let Err(err) = settings.save_to_file() { panic!("Failed to save settings: {:?}", err); @@ -136,10 +139,7 @@ fn main() { info_message: None, }; - let settings = &global_state.settings; - // Set up panic handler to relay swish panic messages to the user - let settings_clone = settings.clone(); let default_hook = panic::take_hook(); panic::set_hook(Box::new(move |panic_info| { let panic_info_payload = panic_info.payload(); @@ -186,7 +186,12 @@ fn main() { \n\ Panic Payload: {:?}\n\ PanicInfo: {}", - settings_clone.log.file, reason, panic_info, + // TODO: Verify that this works + Settings::get_settings_path() + .join("voxygen-.log") + .display(), + reason, + panic_info, ); error!( diff --git a/voxygen/src/settings.rs b/voxygen/src/settings.rs index 85028412ec..24672153dd 100644 --- a/voxygen/src/settings.rs +++ b/voxygen/src/settings.rs @@ -151,17 +151,23 @@ impl Default for NetworkingSettings { } } -/// `Log` stores the name to the log file. +/// `Log` stores whether we should create a log file #[derive(Clone, Debug, Serialize, Deserialize)] #[serde(default)] pub struct Log { - pub file: PathBuf, + // Whether to create a log file or not. + // Default is to create one. + pub log_to_file: bool, + // Should we ignore errors if we are unable to create the log file + // Default is to panic if log file can't be created. + pub ignore_errors: bool, } impl Default for Log { fn default() -> Self { Self { - file: "voxygen.log".into(), + log_to_file: true, + ignore_errors: false, } } } @@ -290,7 +296,7 @@ impl Settings { Ok(()) } - fn get_settings_path() -> PathBuf { + pub fn get_settings_path() -> PathBuf { if let Some(val) = std::env::var_os("VOXYGEN_CONFIG") { let settings = PathBuf::from(val).join("settings.ron"); if settings.exists() || settings.parent().map(|x| x.exists()).unwrap_or(false) { From f070c139e9aa6e8612879067e5a7899faadf4175 Mon Sep 17 00:00:00 2001 From: Songtronix Date: Fri, 20 Dec 2019 15:59:50 +0100 Subject: [PATCH 4/4] change(log): only print out log file errors, no panic --- voxygen/src/logging.rs | 21 ++++++++++----------- voxygen/src/settings.rs | 8 +------- 2 files changed, 11 insertions(+), 18 deletions(-) diff --git a/voxygen/src/logging.rs b/voxygen/src/logging.rs index 78b9587eea..48fb256e95 100644 --- a/voxygen/src/logging.rs +++ b/voxygen/src/logging.rs @@ -40,17 +40,12 @@ pub fn init( )) }); - // Based on settings ignore errors incase log file can't be created - if !settings.log.ignore_errors { - file_cfg = file_cfg.chain( - fern::log_file(&format!("voxygen-{}.log", time.format("%Y-%m-%d-%H"))) - .expect("Failed to create log file!"), - ); - } else { - if let Ok(log_file) = fern::log_file(&format!("voxygen-{}.log", time.format("%Y-%m-%d-%H"))) - { - file_cfg = file_cfg.chain(log_file); - } + // Try to create the log file. + // Incase of it failing we simply print it out to the console. + let mut log_file_created = Ok(()); + match fern::log_file(&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() @@ -70,4 +65,8 @@ pub fn init( base.chain(stdout_cfg) .apply() .expect("Failed to setup logging!"); + + if let Err(e) = log_file_created { + log::error!("Failed to create log file! {}", e); + } } diff --git a/voxygen/src/settings.rs b/voxygen/src/settings.rs index 24672153dd..e2a567f174 100644 --- a/voxygen/src/settings.rs +++ b/voxygen/src/settings.rs @@ -158,17 +158,11 @@ pub struct Log { // Whether to create a log file or not. // Default is to create one. pub log_to_file: bool, - // Should we ignore errors if we are unable to create the log file - // Default is to panic if log file can't be created. - pub ignore_errors: bool, } impl Default for Log { fn default() -> Self { - Self { - log_to_file: true, - ignore_errors: false, - } + Self { log_to_file: true } } }