Add log rotation (#6564)

* Use flexi_logger; Add log rotation

* Add default rotation; Add FlexiLogger error

* Fix compilation error

* Remove logging to stdout if it's not a tty

* Fix formatting

Co-authored-by: Kian Paimani <5588131+kianenigma@users.noreply.github.com>

* Remove needless debug statement

* Default to unlimited size for log rotation

* Add more comments about log-age option

* Remove unused variable

* Fix typo in comment

Co-authored-by: Kian Paimani <5588131+kianenigma@users.noreply.github.com>

substrate/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<C: SubstrateCli>(&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(())
 	}

substrate/client/cli/src/error.rs

@@ -17,6 +17,7 @@
 // along with this program. If not, see <https://www.gnu.org/licenses/>.
 
 //! Initialization errors.
+use flexi_logger::FlexiLoggerError;
 
 /// Result type alias for the CLI.
 pub type Result<T> = std::result::Result<T, Error>;
@@ -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,

substrate/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<dyn ChainSpec>) -> &'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()
-}

substrate/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 <https://www.gnu.org/licenses/>.
+
+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<PathBuf>,
+	
+	/// 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<Age>,
+
+	/// Rotate the log file when it exceeds this size (in bytes).
+	#[structopt(long, conflicts_with("log-age"))]
+	log_size: Option<u64>,
+}
+
+/// 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());
+	}
+}

substrate/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<level>.
 	#[structopt(short = "l", long, value_name = "LOG_PATTERN")]
 	pub log: Vec<String>,
+
+	#[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
+	}
 }