Merge branch 'songtronix/improve-logging' into 'master'

improve logging

See merge request veloren/veloren!663
This commit is contained in:
Songtronix 2019-12-20 15:14:23 +00:00
commit b1e8c915d9
6 changed files with 120 additions and 89 deletions

View File

@ -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::<Client>()
@ -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 });
}

72
voxygen/src/logging.rs Normal file
View File

@ -0,0 +1,72 @@
use fern::colors::{Color, ColoredLevelConfig};
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)
.info(Color::Cyan)
.debug(Color::Green)
.trace(Color::BrightBlack);
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)
.level_for("uvth", log::LevelFilter::Warn)
.level_for("tiny_http", log::LevelFilter::Warn);
let time = chrono::offset::Utc::now();
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
))
});
// 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()
.level(term_log_level)
.format(move |out, message, record| {
out.finish(format_args!(
"[{}] {}",
colors.color(record.level()),
message
))
})
.chain(std::io::stdout());
if settings.log.log_to_file {
base = base.chain(file_cfg);
}
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);
}
}

View File

@ -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::{debug, error};
use std::{mem, panic, str::FromStr};
/// A type used to store state that is shared between all play states.
@ -97,8 +96,24 @@ 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);
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 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);
@ -124,67 +139,7 @@ fn main() {
info_message: None,
};
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();
panic::set_hook(Box::new(move |panic_info| {
let panic_info_payload = panic_info.payload();
@ -231,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-<date>.log")
.display(),
reason,
panic_info,
);
error!(
@ -261,7 +221,7 @@ fn main() {
let mut states: Vec<Box<dyn PlayState>> = 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 +239,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());

View File

@ -151,18 +151,18 @@ 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,
}
impl Default for Log {
fn default() -> Self {
Self {
file: "voxygen.log".into(),
}
Self { log_to_file: true }
}
}
@ -290,7 +290,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) {

View File

@ -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::<f64>();
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,

View File

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