Use tracing-based subscriber logging (paritytech#6825)

* init_logger: switch from log-based to tracing-based and add compatibility layer

* Move tracing profiling subscriber related config realization

* sp-tracing: change profiling to be a layer instead of a subscriber

* Enable profiling layer in cli

* Change all test env_logger init to sp_tracing::try_init_simple

* Remove all local env_logger dependency

* Add missing tracing-subscriber dependency

* frame-sudo: fix tests

* frame-support: fix tests

* Fix frame/pallet and executor tests

* Fix the remaining tests

* Use subscriber's try_init as recommended by @davidbarsky

* Be explict that the tracing-log feature is needed

* Set subscriber writer to stderr

* Shorter line width

* Update cargo lock tracing version

* Fix sc_tracing crate compile

* Fix sc_authority_discovery crate test

* unremove default-features

* Leave enabled to default true

* Warn if global default cannot be set

* Fix unused import

* Remove unused PROXY_TARGET

* Change all reference from rc5 to rc6

* Change all reference of rc2 to rc6

* Fix styling

* Fix typo

* make logger init error'ing

* re-fixing the test issue

Co-authored-by: Benjamin Kampmann <ben@parity.io>

bin/node/bench/Cargo.toml

@@ -22,7 +22,7 @@ serde_json = "1.0.41"
 structopt = "0.3"
 derive_more = "0.99.2"
 kvdb = "0.7"
-kvdb-rocksdb = "0.9"
+kvdb-rocksdb = "0.9.1"
 sp-trie = { version = "2.0.0-rc5", path = "../../../primitives/trie" }
 sp-core = { version = "2.0.0-rc5", path = "../../../primitives/core" }
 sp-consensus = { version = "0.8.0-rc5", path = "../../../primitives/consensus/common" }
@@ -31,6 +31,7 @@ sc-basic-authorship = { version = "0.8.0-rc5", path = "../../../client/basic-aut
 sp-inherents = { version = "2.0.0-rc5", path = "../../../primitives/inherents" }
 sp-finality-tracker = { version = "2.0.0-rc5", default-features = false, path = "../../../primitives/finality-tracker" }
 sp-timestamp = { version = "2.0.0-rc5", default-features = false, path = "../../../primitives/timestamp" }
+sp-tracing = { version = "2.0.0-rc5", path = "../../../primitives/tracing" }
 hash-db = "0.15.2"
 tempfile = "3.1.0"
 fs_extra = "1"

bin/node/bench/src/main.rs

@@ -79,7 +79,7 @@ fn main() {
 	let opt = Opt::from_args();
 
 	if !opt.json {
-		sc_cli::init_logger("");
+		sp_tracing::try_init_simple();
 	}
 
 	let mut import_benchmarks = Vec::new();

bin/node/executor/Cargo.toml

@@ -41,7 +41,7 @@ sp-application-crypto = { version = "2.0.0-rc5", path = "../../../primitives/app
 sp-runtime = { version = "2.0.0-rc5", path = "../../../primitives/runtime" }
 sp-externalities = { version = "0.8.0-rc5", path = "../../../primitives/externalities" }
 substrate-test-client = { version = "2.0.0-rc5", path = "../../../test-utils/client" }
-wabt = "0.9.2"
+wabt = "0.10.0"
 
 [features]
 wasmtime = [

bin/node/rpc-client/Cargo.toml

@@ -11,10 +11,10 @@ repository = "https://github.com/paritytech/substrate/"
 targets = ["x86_64-unknown-linux-gnu"]
 
 [dependencies]
-env_logger = "0.7.0"
 futures = "0.1.29"
 hyper = "0.12.35"
 jsonrpc-core-client = { version = "14.2.0", default-features = false, features = ["http"] }
 log = "0.4.8"
 node-primitives = { version = "2.0.0-rc5", path = "../primitives" }
+sp-tracing = { version = "2.0.0-rc5", path = "../../../primitives/tracing" }
 sc-rpc = { version = "2.0.0-rc5", path = "../../../client/rpc" }

bin/node/rpc-client/src/main.rs

@@ -35,7 +35,7 @@ use jsonrpc_core_client::{
 };
 
 fn main() {
-	env_logger::init();
+	sp_tracing::try_init_simple();
 
 	rt::run(rt::lazy(|| {
 		let uri = "http://localhost:9933";

bin/node/testing/Cargo.toml

@@ -39,7 +39,7 @@ substrate-test-client = { version = "2.0.0-rc5", path = "../../../test-utils/cli
 pallet-timestamp = { version = "2.0.0-rc5", path = "../../../frame/timestamp" }
 pallet-transaction-payment = { version = "2.0.0-rc5", path = "../../../frame/transaction-payment" }
 pallet-treasury = { version = "2.0.0-rc5", path = "../../../frame/treasury" }
-wabt = "0.9.2"
+wabt = "0.10.0"
 sp-api = { version = "2.0.0-rc5", path = "../../../primitives/api" }
 sp-finality-tracker = { version = "2.0.0-rc5", default-features = false, path = "../../../primitives/finality-tracker" }
 sp-timestamp = { version = "2.0.0-rc5", default-features = false, path = "../../../primitives/timestamp" }

client/authority-discovery/Cargo.toml

@@ -37,7 +37,7 @@ sp-runtime = { version = "2.0.0-rc5", path = "../../primitives/runtime" }
 sp-api = { version = "2.0.0-rc5", path = "../../primitives/api" }
 
 [dev-dependencies]
-env_logger = "0.7.0"
 quickcheck = "0.9.0"
+sp-tracing = { version = "2.0.0-rc5", path = "../../primitives/tracing" }
 sc-peerset = { version = "2.0.0-rc5", path = "../peerset" }
 substrate-test-runtime-client = { version = "2.0.0-rc5", path = "../../test-utils/runtime/client"}

client/cli/Cargo.toml

@@ -13,7 +13,6 @@ targets = ["x86_64-unknown-linux-gnu"]
 
 [dependencies]
 derive_more = "0.99.2"
-env_logger = "0.7.0"
 log = "0.4.8"
 atty = "0.2.13"
 regex = "1.3.4"
@@ -44,6 +43,9 @@ sc-tracing = { version = "2.0.0-rc5", path = "../tracing" }
 chrono = "0.4.10"
 parity-util-mem = { version = "0.7.0", default-features = false, features = ["primitive-types"] }
 serde = "1.0.111"
+tracing = "0.1.10"
+tracing-log = "0.1.1"
+tracing-subscriber = "0.2.10"
 
 [target.'cfg(not(target_os = "unknown"))'.dependencies]
 rpassword = "4.0.1"

client/cli/src/config.rs

@@ -488,7 +488,7 @@ pub trait CliConfiguration: Sized {
 		Ok(self.shared_params().log_filters().join(","))
 	}
 
-	/// Initialize substrate. This must be done only once.
+	/// Initialize substrate. This must be done only once per process.
 	///
 	/// This method:
 	///
@@ -497,11 +497,14 @@ pub trait CliConfiguration: Sized {
 	/// 3. Initialize the logger
 	fn init<C: SubstrateCli>(&self) -> Result<()> {
 		let logger_pattern = self.log_filters()?;
+		let tracing_receiver = self.tracing_receiver()?;
+		let tracing_targets = self.tracing_targets()?;
 
 		sp_panic_handler::set(&C::support_url(), &C::impl_version());
 
-		fdlimit::raise_fd_limit();
-		init_logger(&logger_pattern);
+		if let Err(e) = init_logger(&logger_pattern, tracing_receiver, tracing_targets) {
+			log::warn!("💬 Problem initializing global logging framework: {:}", e)
+		}
 
 		Ok(())
 	}

client/cli/src/lib.rs

@@ -32,10 +32,7 @@ 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 +43,7 @@ use structopt::{
 	clap::{self, AppSettings},
 	StructOpt,
 };
+use tracing_subscriber::layer::SubscriberExt;
 
 /// Substrate client CLI
 ///
@@ -228,79 +226,76 @@ pub trait SubstrateCli: Sized {
 	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("cranelift_codegen"), 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);
+/// Initialize the global logger
+///
+/// This sets various global logging and tracing instances and thus may only be called once.
+pub fn init_logger(
+	pattern: &str,
+	tracing_receiver: sc_tracing::TracingReceiver,
+	tracing_targets: Option<String>,
+) -> std::result::Result<(), String> {
+	if let Err(e) = tracing_log::LogTracer::init() {
+		return Err(format!(
+			"Registering Substrate logger failed: {:}!", e
+		))
+	}
+
+	let mut env_filter = tracing_subscriber::EnvFilter::default()
+		// Disable info logging by default for some modules.
+		.add_directive("ws=off".parse().expect("provided directive is valid"))
+		.add_directive("yamux=off".parse().expect("provided directive is valid"))
+		.add_directive("cranelift_codegen=off".parse().expect("provided directive is valid"))
+		// Set warn logging by default for some modules.
+		.add_directive("cranelife_wasm=warn".parse().expect("provided directive is valid"))
+		.add_directive("hyper=warn".parse().expect("provided directive is valid"))
+		// Always log the special target `sc_tracing`, overrides global level.
+		.add_directive("sc_tracing=trace".parse().expect("provided directive is valid"))
+		// Enable info for others.
+		.add_directive(tracing_subscriber::filter::LevelFilter::INFO.into());
 
 	if let Ok(lvl) = std::env::var("RUST_LOG") {
-		builder.parse_filters(&lvl);
+		if lvl != "" {
+			// We're not sure if log or tracing is available at this moment, so silently ignore the
+			// parse error.
+			if let Ok(directive) = lvl.parse() {
+				env_filter = env_filter.add_directive(directive);
+			}
+		}
+	}
+
+	if pattern != "" {
+		// We're not sure if log or tracing is available at this moment, so silently ignore the
+		// parse error.
+		if let Ok(directive) = pattern.parse() {
+			env_filter = env_filter.add_directive(directive);
+		}
 	}
 
-	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);
+	let subscriber = tracing_subscriber::FmtSubscriber::builder()
+		.with_env_filter(env_filter)
+		.with_target(false)
+		.with_ansi(enable_color)
+		.with_writer(std::io::stderr)
+		.compact()
+		.finish();
+
+	if let Some(tracing_targets) = tracing_targets {
+		let profiling = sc_tracing::ProfilingLayer::new(tracing_receiver, &tracing_targets);
+
+		if let Err(e) = tracing::subscriber::set_global_default(subscriber.with(profiling)) {
+			return Err(format!(
+				"Registering Substrate tracing subscriber failed: {:}!", e
+			))
 		}
-
-		if !enable_color {
-			output = kill_color(output.as_ref());
+	} else {
+		if let Err(e) = tracing::subscriber::set_global_default(subscriber) {
+			return Err(format!(
+				"Registering Substrate tracing subscriber  failed: {:}!", e
+			))
 		}
-
-		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()
+	Ok(())
 }

client/consensus/aura/Cargo.toml

@@ -39,10 +39,10 @@ prometheus-endpoint = { package = "substrate-prometheus-endpoint", path = "../..
 
 [dev-dependencies]
 sp-keyring = { version = "2.0.0-rc5", path = "../../../primitives/keyring" }
+sp-tracing = { version = "2.0.0-rc5", path = "../../../primitives/tracing" }
 sc-executor = { version = "0.8.0-rc5", path = "../../executor" }
 sc-network = { version = "0.8.0-rc5", path = "../../network" }
 sc-network-test = { version = "0.8.0-rc5", path = "../../network/test" }
 sc-service = { version = "0.8.0-rc5", default-features = false, path = "../../service" }
 substrate-test-runtime-client = { version = "2.0.0-rc5", path = "../../../test-utils/runtime/client" }
-env_logger = "0.7.0"
 tempfile = "3.1.0"

client/consensus/aura/src/lib.rs

@@ -973,7 +973,7 @@ mod tests {
 	#[test]
 	#[allow(deprecated)]
 	fn authoring_blocks() {
-		let _ = env_logger::try_init();
+		sp_tracing::try_init_simple();
 		let net = AuraTestNet::new(3);
 
 		let peers = &[

client/consensus/babe/Cargo.toml

@@ -53,13 +53,13 @@ retain_mut = "0.1.1"
 
 [dev-dependencies]
 sp-keyring = { version = "2.0.0-rc5", path = "../../../primitives/keyring" }
+sp-tracing = { version = "2.0.0-rc5", path = "../../../primitives/tracing" }
 sc-executor = { version = "0.8.0-rc5", path = "../../executor" }
 sc-network = { version = "0.8.0-rc5", path = "../../network" }
 sc-network-test = { version = "0.8.0-rc5", path = "../../network/test" }
 sc-service = { version = "0.8.0-rc5", default-features = false, path = "../../service" }
 substrate-test-runtime-client = { version = "2.0.0-rc5", path = "../../../test-utils/runtime/client" }
 sc-block-builder = { version = "0.8.0-rc5", path = "../../block-builder" }
-env_logger = "0.7.0"
 rand_chacha = "0.2.2"
 tempfile = "3.1.0"
 

client/consensus/babe/src/tests.rs

@@ -346,7 +346,7 @@ impl TestNetFactory for BabeTestNet {
 #[test]
 #[should_panic]
 fn rejects_empty_block() {
-	env_logger::try_init().unwrap();
+	sp_tracing::try_init_simple();
 	let mut net = BabeTestNet::new(3);
 	let block_builder = |builder: BlockBuilder<_, _, _>| {
 		builder.build().unwrap().block
@@ -359,7 +359,7 @@ fn rejects_empty_block() {
 fn run_one_test(
 	mutator: impl Fn(&mut TestHeader, Stage) + Send + Sync + 'static,
 ) {
-	let _ = env_logger::try_init();
+	sp_tracing::try_init_simple();
 	let mutator = Arc::new(mutator) as Mutator;
 
 	MUTATOR.with(|m| *m.borrow_mut() = mutator.clone());
@@ -488,7 +488,7 @@ fn rejects_missing_consensus_digests() {
 
 #[test]
 fn wrong_consensus_engine_id_rejected() {
-	let _ = env_logger::try_init();
+	sp_tracing::try_init_simple();
 	let sig = AuthorityPair::generate().0.sign(b"");
 	let bad_seal: Item = DigestItem::Seal([0; 4], sig.to_vec());
 	assert!(bad_seal.as_babe_pre_digest().is_none());
@@ -497,14 +497,14 @@ fn wrong_consensus_engine_id_rejected() {
 
 #[test]
 fn malformed_pre_digest_rejected() {
-	let _ = env_logger::try_init();
+	sp_tracing::try_init_simple();
 	let bad_seal: Item = DigestItem::Seal(BABE_ENGINE_ID, [0; 64].to_vec());
 	assert!(bad_seal.as_babe_pre_digest().is_none());
 }
 
 #[test]
 fn sig_is_not_pre_digest() {
-	let _ = env_logger::try_init();
+	sp_tracing::try_init_simple();
 	let sig = AuthorityPair::generate().0.sign(b"");
 	let bad_seal: Item = DigestItem::Seal(BABE_ENGINE_ID, sig.to_vec());
 	assert!(bad_seal.as_babe_pre_digest().is_none());
@@ -513,7 +513,7 @@ fn sig_is_not_pre_digest() {
 
 #[test]
 fn can_author_block() {
-	let _ = env_logger::try_init();
+	sp_tracing::try_init_simple();
 	let keystore_path = tempfile::tempdir().expect("Creates keystore path");
 	let keystore = sc_keystore::Store::open(keystore_path.path(), None).expect("Creates keystore");
 	let pair = keystore.write().insert_ephemeral_from_seed::<AuthorityPair>("//Alice")
@@ -820,7 +820,7 @@ fn verify_slots_are_strictly_increasing() {
 
 #[test]
 fn babe_transcript_generation_match() {
-	let _ = env_logger::try_init();
+	sp_tracing::try_init_simple();
 	let keystore_path = tempfile::tempdir().expect("Creates keystore path");
 	let keystore = sc_keystore::Store::open(keystore_path.path(), None).expect("Creates keystore");
 	let pair = keystore.write().insert_ephemeral_from_seed::<AuthorityPair>("//Alice")