diff --git a/Cargo.lock b/Cargo.lock index b5bbcd6954611..e34b9dcc21760 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1417,6 +1417,20 @@ dependencies = [ "miniz_oxide", ] +[[package]] +name = "flexi_logger" +version = "0.15.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "33897654c23a50cebab45e18356f69fb771c9949a6928344fb1f01ffccc7c5f3" +dependencies = [ + "chrono", + "glob 0.3.0", + "log", + "regex", + "thiserror", + "yansi", +] + [[package]] name = "fnv" version = "1.0.6" @@ -6034,8 +6048,8 @@ dependencies = [ "atty", "chrono", "derive_more", - "env_logger 0.7.1", "fdlimit", + "flexi_logger", "futures 0.3.5", "lazy_static", "log", @@ -9770,6 +9784,12 @@ dependencies = [ "static_assertions", ] +[[package]] +name = "yansi" +version = "0.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9fc79f4a1e39857fc00c3f662cbf2651c771f00e9c15fe2abc341806bd46bd71" + [[package]] name = "zeroize" version = "1.1.0" diff --git a/bin/node/bench/src/main.rs b/bin/node/bench/src/main.rs index 11820247112f8..941176f27746a 100644 --- a/bin/node/bench/src/main.rs +++ b/bin/node/bench/src/main.rs @@ -63,6 +63,9 @@ struct Opt { #[structopt(long)] transactions: Option, + #[structopt(flatten)] + log_rotation_opt: sc_cli::LogRotationOpt, + /// Mode /// /// "regular" for regular benchmark @@ -77,7 +80,7 @@ fn main() { let opt = Opt::from_args(); if !opt.json { - sc_cli::init_logger(""); + sc_cli::init_logger("", &opt.log_rotation_opt).expect("init_logger should not fail."); } let mut import_benchmarks = Vec::new(); diff --git a/client/cli/Cargo.toml b/client/cli/Cargo.toml index 6ebf2f9bf8982..5a7487bb60ce4 100644 --- a/client/cli/Cargo.toml +++ b/client/cli/Cargo.toml @@ -13,7 +13,7 @@ targets = ["x86_64-unknown-linux-gnu"] [dependencies] derive_more = "0.99.2" -env_logger = "0.7.0" +flexi_logger = "0.15.7" log = "0.4.8" atty = "0.2.13" regex = "1.3.1" diff --git a/client/cli/src/config.rs b/client/cli/src/config.rs index fa3f09116c314..35fc95cb6050c 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -21,9 +21,10 @@ use crate::arg_enums::Database; use crate::error::Result; use crate::{ - init_logger, DatabaseParams, ImportParams, KeystoreParams, NetworkParams, NodeKeyParams, + DatabaseParams, ImportParams, KeystoreParams, NetworkParams, NodeKeyParams, OffchainWorkerParams, PruningParams, SharedParams, SubstrateCli, }; +use crate::logger::{LogRotationOpt, init_logger}; use names::{Generator, Name}; use sc_client_api::execution_extensions::ExecutionStrategies; use sc_service::config::{ @@ -488,6 +489,13 @@ pub trait CliConfiguration: Sized { Ok(self.shared_params().log_filters().join(",")) } + /// Get the log directory for logging. + /// + /// By default this is retrieved from `SharedParams`. + fn log_rotation_opt(&self) -> Result<&LogRotationOpt> { + Ok(self.shared_params().log_rotation_opt()) + } + /// Initialize substrate. This must be done only once. /// /// This method: @@ -497,11 +505,12 @@ pub trait CliConfiguration: Sized { /// 3. Initialize the logger fn init(&self) -> Result<()> { let logger_pattern = self.log_filters()?; + let log_rotation_opt = self.log_rotation_opt()?; sp_panic_handler::set(&C::support_url(), &C::impl_version()); fdlimit::raise_fd_limit(); - init_logger(&logger_pattern); + init_logger(&logger_pattern, log_rotation_opt)?; Ok(()) } diff --git a/client/cli/src/error.rs b/client/cli/src/error.rs index f091354be154b..f29b59ed1243e 100644 --- a/client/cli/src/error.rs +++ b/client/cli/src/error.rs @@ -17,6 +17,7 @@ // along with this program. If not, see . //! Initialization errors. +use flexi_logger::FlexiLoggerError; /// Result type alias for the CLI. pub type Result = std::result::Result; @@ -32,6 +33,8 @@ pub enum Error { Service(sc_service::Error), /// Client error Client(sp_blockchain::Error), + /// Flexi Logger error + FlexiLogger(FlexiLoggerError), /// Input error #[from(ignore)] Input(String), @@ -65,6 +68,7 @@ impl std::error::Error for Error { Error::Cli(ref err) => Some(err), Error::Service(ref err) => Some(err), Error::Client(ref err) => Some(err), + Error::FlexiLogger(ref err) => Some(err), Error::Input(_) => None, Error::InvalidListenMultiaddress => None, Error::Other(_) => None, diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index c7f48d2721468..a06e48626f415 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -27,15 +27,13 @@ mod config; mod error; mod params; mod runner; +mod logger; pub use arg_enums::*; pub use commands::*; pub use config::*; pub use error::*; -use lazy_static::lazy_static; -use log::info; pub use params::*; -use regex::Regex; pub use runner::*; use sc_service::{Configuration, TaskExecutor}; pub use sc_service::{ChainSpec, Role}; @@ -46,6 +44,7 @@ use structopt::{ clap::{self, AppSettings}, StructOpt, }; +pub use crate::logger::{init_logger, LogRotationOpt}; /// Substrate client CLI /// @@ -227,79 +226,3 @@ pub trait SubstrateCli: Sized { /// Native runtime version. fn native_runtime_version(chain_spec: &Box) -> &'static RuntimeVersion; } - -/// Initialize the logger -pub fn init_logger(pattern: &str) { - use ansi_term::Colour; - - let mut builder = env_logger::Builder::new(); - // Disable info logging by default for some modules: - builder.filter(Some("ws"), log::LevelFilter::Off); - builder.filter(Some("yamux"), log::LevelFilter::Off); - builder.filter(Some("hyper"), log::LevelFilter::Warn); - builder.filter(Some("cranelift_wasm"), log::LevelFilter::Warn); - // Always log the special target `sc_tracing`, overrides global level - builder.filter(Some("sc_tracing"), log::LevelFilter::Info); - // Enable info for others. - builder.filter(None, log::LevelFilter::Info); - - if let Ok(lvl) = std::env::var("RUST_LOG") { - builder.parse_filters(&lvl); - } - - builder.parse_filters(pattern); - let isatty = atty::is(atty::Stream::Stderr); - let enable_color = isatty; - - builder.format(move |buf, record| { - let now = time::now(); - let timestamp = - time::strftime("%Y-%m-%d %H:%M:%S", &now).expect("Error formatting log timestamp"); - - let mut output = if log::max_level() <= log::LevelFilter::Info { - format!( - "{} {}", - Colour::Black.bold().paint(timestamp), - record.args(), - ) - } else { - let name = ::std::thread::current() - .name() - .map_or_else(Default::default, |x| { - format!("{}", Colour::Blue.bold().paint(x)) - }); - let millis = (now.tm_nsec as f32 / 1000000.0).floor() as usize; - let timestamp = format!("{}.{:03}", timestamp, millis); - format!( - "{} {} {} {} {}", - Colour::Black.bold().paint(timestamp), - name, - record.level(), - record.target(), - record.args() - ) - }; - - if !isatty && record.level() <= log::Level::Info && atty::is(atty::Stream::Stdout) { - // duplicate INFO/WARN output to console - println!("{}", output); - } - - if !enable_color { - output = kill_color(output.as_ref()); - } - - writeln!(buf, "{}", output) - }); - - if builder.try_init().is_err() { - info!("💬 Not registering Substrate logger, as there is already a global logger registered!"); - } -} - -fn kill_color(s: &str) -> String { - lazy_static! { - static ref RE: Regex = Regex::new("\x1b\\[[^m]+m").expect("Error initializing color regex"); - } - RE.replace_all(s, "").to_string() -} diff --git a/client/cli/src/logger.rs b/client/cli/src/logger.rs new file mode 100644 index 0000000000000..2422f0ec600c8 --- /dev/null +++ b/client/cli/src/logger.rs @@ -0,0 +1,271 @@ +// This file is part of Substrate. + +// Copyright (C) 2020 Parity Technologies (UK) Ltd. +// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0 + +// This program is free software: you can redistribute it and/or modify +// it under the terms of the GNU General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. + +// This program is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU General Public License for more details. + +// You should have received a copy of the GNU General Public License +// along with this program. If not, see . + +use ansi_term::Colour; +use flexi_logger::{ + DeferredNow, Duplicate, LogSpecBuilder, + LogSpecification, LogTarget, Logger, Criterion, Naming, Cleanup, Age, +}; +use lazy_static::lazy_static; +use regex::Regex; +use std::path::PathBuf; +use structopt::{ + StructOpt, +}; +use crate::error::{Error, Result}; + +type IoResult = std::result::Result<(), std::io::Error>; + +/// Default size used for rotation. Basically unlimited. +const DEFAULT_ROTATION_SIZE: u64 = u64::MAX; + +/// Options for log rotation. +#[derive(Debug, StructOpt)] +pub struct LogRotationOpt { + /// Specify the path of the directory which will contain the log files. + /// Defaults to never rotating logs. + #[structopt(long, parse(from_os_str))] + log_directory: Option, + + /// Rotate the log file when the local clock has started a new day/hour/minute/second + /// since the current file has been created. + #[structopt(long, + conflicts_with("log-size"), + possible_values(&["day", "hour", "minute", "second"]), + parse(from_str = age_from_str)) + ] + log_age: Option, + + /// Rotate the log file when it exceeds this size (in bytes). + #[structopt(long, conflicts_with("log-age"))] + log_size: Option, +} + +/// Utility for parsing an Age from a &str. +fn age_from_str(s: &str) -> Age { + match s { + "day" => Age::Day, + "hour" => Age::Hour, + "minute" => Age::Minute, + "second" => Age::Second, + _ => unreachable!(), + } +} + +/// Format used when writing to a tty. Colors the output. +fn colored_fmt( + w: &mut dyn std::io::Write, + _now: &mut DeferredNow, + record: &log::Record, +) -> IoResult { + let now = time::now(); + let timestamp = + time::strftime("%Y-%m-%d %H:%M:%S", &now).expect("Error formatting log timestamp"); + + let output = if log::max_level() <= log::LevelFilter::Info { + format!( + "{} {}", + Colour::Black.bold().paint(timestamp), + record.args(), + ) + } else { + let name = ::std::thread::current() + .name() + .map_or_else(Default::default, |x| { + format!("{}", Colour::Blue.bold().paint(x)) + }); + let millis = (now.tm_nsec as f32 / 1000000.0).floor() as usize; + let timestamp = format!("{}.{:03}", timestamp, millis); + format!( + "{} {} {} {} {}", + Colour::Black.bold().paint(timestamp), + name, + record.level(), + record.target(), + record.args() + ) + }; + + write!(w, "{}", output) +} + +/// Format used when logging to files. Does not add any colors. +fn file_fmt( + w: &mut dyn std::io::Write, + _now: &mut DeferredNow, + record: &log::Record, +) -> IoResult { + let now = time::now(); + let timestamp = + time::strftime("%Y-%m-%d %H:%M:%S", &now).expect("Error formatting log timestamp"); + + let output = if log::max_level() <= log::LevelFilter::Info { + format!("{} {}", timestamp, record.args(),) + } else { + let name = std::thread::current() + .name() + .map_or_else(Default::default, |x| format!("{}", x)); + let millis = (now.tm_nsec as f32 / 1000000.0).floor() as usize; + let timestamp = format!("{}.{:03}", timestamp, millis); + format!( + "{} {} {} {} {}", + timestamp, + name, + record.level(), + record.target(), + record.args() + ) + }; + + // Required because substrate sometimes sends strings that are colored. + // Doing this ensures no colors are ever printed to files. + let output = kill_color(&output); + + write!(w, "{}", output) +} + +/// Initialize the logger +pub fn init_logger(pattern: &str, log_rotation_opt: &LogRotationOpt) -> Result<()> { + + let mut builder = LogSpecBuilder::new(); + // Disable info logging by default for some modules: + builder.module("ws", log::LevelFilter::Off); + builder.module("yamux", log::LevelFilter::Off); + builder.module("hyper", log::LevelFilter::Warn); + builder.module("cranelift_wasm", log::LevelFilter::Warn); + // Always log the special target `sc_tracing`, overrides global level + builder.module("sc_tracing", log::LevelFilter::Info); + // Enable info for others. + builder.default(log::LevelFilter::Info); + + // Add filters defined by RUST_LOG. + builder.insert_modules_from(LogSpecification::env()?); + + // Add filters passed in as argument. + builder.insert_modules_from(LogSpecification::parse(pattern)?); + + // Build the LogSpec. + let spec = builder.build(); + + // Use timestamps to differentiate logs. + let naming = Naming::Timestamps; + // Never cleanup old logs; let the end-user take care of that. + let cleanup = Cleanup::Never; + + let age = log_rotation_opt.log_age; + let size = log_rotation_opt.log_size; + + // Build a Criterion from the options. + let criterion = match (age, size) { + (Some(a), None) => Criterion::Age(a), + (None, Some(s)) => Criterion::Size(s), + // Default to rotating with a size of `DEFAULT_ROTATION_SIZE`. + (None, None) => Criterion::Size(DEFAULT_ROTATION_SIZE), + _ => return Err(Error::Input("Only one of Age or Size should be defined".into())) + }; + + let isatty_stderr = atty::is(atty::Stream::Stderr); + let isatty_stdout = atty::is(atty::Stream::Stdout); + let logger = Logger::with(spec) + .format(file_fmt) + .format_for_stderr(colored_fmt) + .format_for_stdout(colored_fmt) + .rotate(criterion, naming, cleanup); // Won't get used if log_directory has not been specified. + + + let logger = match (log_rotation_opt.log_directory.as_ref(), isatty_stderr) { + // Only log to stderr using colored format; nothing to file, nothing to stdout. + (None, true) => { + logger.log_target(LogTarget::StdErr) + } + // Log to stderr using file format, log to stdout using colored format. + (None, false) => { + let logger = logger + .log_target(LogTarget::DevNull) + .format_for_stderr(file_fmt) + .duplicate_to_stderr(Duplicate::All); + + // Write to stdout only if it's a tty. + if isatty_stdout { + logger.duplicate_to_stdout(Duplicate::Info) + } else { + logger + } + } + // Log to stderr with colored format, log to file with file format. Nothing to stdout. + (Some(file), true) => { + logger + .log_target(LogTarget::File) + .duplicate_to_stderr(Duplicate::All) + .directory(file) + } + // Log to stderr with file format, log to file with file format, log to stdout with colored format. + (Some(file), false) => { + let logger = logger + .log_target(LogTarget::File) + .format_for_stderr(file_fmt) + .duplicate_to_stderr(Duplicate::All) + .directory(file); + + // Write to stdout only if it's a tty. + if isatty_stdout { + logger.duplicate_to_stdout(Duplicate::Info) + } else { + logger + } + } + }; + + logger.start().map(|_| ()).map_err(|e| e.into()) +} + +fn kill_color(s: &str) -> String { + lazy_static! { + static ref RE: Regex = Regex::new("\x1b\\[[^m]+m").expect("Error initializing color regex"); + } + RE.replace_all(s, "").to_string() +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn logger_default() { + let pattern = ""; + let log_rotation_opt = LogRotationOpt { + log_directory: None, + log_age: None, + log_size: None, + }; + + assert!(init_logger(pattern, &log_rotation_opt).is_ok()); + } + + #[test] + fn logger_conflicting_opt() { + let pattern = ""; + let log_rotation_opt = LogRotationOpt { + log_directory: None, + log_age: Some(Age::Day), + log_size: Some(1337), + }; + + assert!(init_logger(pattern, &log_rotation_opt).is_err()); + } +} diff --git a/client/cli/src/params/shared_params.rs b/client/cli/src/params/shared_params.rs index ad9ab04070563..42e68757190e2 100644 --- a/client/cli/src/params/shared_params.rs +++ b/client/cli/src/params/shared_params.rs @@ -19,8 +19,10 @@ use sc_service::config::BasePath; use std::path::PathBuf; use structopt::StructOpt; +use crate::logger::LogRotationOpt; /// Shared parameters used by all `CoreParams`. +#[allow(missing_docs)] #[derive(Debug, StructOpt)] pub struct SharedParams { /// Specify the chain specification (one of dev, local, or staging). @@ -41,6 +43,9 @@ pub struct SharedParams { /// By default, all targets log `info`. The global log level can be set with -l. #[structopt(short = "l", long, value_name = "LOG_PATTERN")] pub log: Vec, + + #[structopt(flatten)] + pub log_rotation_opt: LogRotationOpt, } impl SharedParams { @@ -72,4 +77,9 @@ impl SharedParams { pub fn log_filters(&self) -> &[String] { &self.log } + + /// Get the file rotation options for the logging + pub fn log_rotation_opt(&self) -> &LogRotationOpt { + &self.log_rotation_opt + } }