Use tracing-based subscriber logging

bin/node/bench/Cargo.toml

@@ -29,15 +29,16 @@ sp-consensus = { version = "0.8.0-rc5", path = "../../../primitives/consensus/co
 sp-transaction-pool = { version = "2.0.0-rc5", path = "../../../primitives/transaction-pool" }
 sc-basic-authorship = { version = "0.8.0-rc5", path = "../../../client/basic-authorship" }
 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-finality-tracker = { version = "2.0.0-rc5", path = "../../../primitives/finality-tracker" }
+sp-timestamp = { version = "2.0.0-rc5", 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"
 hex = "0.4.0"
 rand = { version = "0.7.2", features = ["small_rng"] }
 lazy_static = "1.4.0"
-parity-util-mem = { version = "0.7.0", default-features = false, features = ["primitive-types"] }
+parity-util-mem = { version = "0.7.0", features = ["primitive-types"] }
 parity-db = { version = "0.1.2" }
 sc-transaction-pool = { version = "2.0.0-rc5", path = "../../../client/transaction-pool" }
 futures = { version = "0.3.4", features = ["thread-pool"] }

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/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";

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/authority-discovery/src/tests.rs

@@ -239,7 +239,7 @@ fn new_registers_metrics() {
 
 #[test]
 fn request_addresses_of_others_triggers_dht_get_query() {
-	let _ = ::env_logger::try_init();
+	sp_tracing::try_init_simple();
 	let (_dht_event_tx, dht_event_rx) = channel(1000);
 
 	// Generate authority keys
@@ -270,7 +270,7 @@ fn request_addresses_of_others_triggers_dht_get_query() {
 
 #[test]
 fn publish_discover_cycle() {
-	let _ = ::env_logger::try_init();
+	sp_tracing::try_init_simple();
 
 	// Node A publishing its address.
 

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

@@ -497,11 +497,13 @@ 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);
+		init_logger(&logger_pattern, tracing_receiver, tracing_targets);
 
 		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
 ///
@@ -229,78 +227,81 @@ pub trait SubstrateCli: Sized {
 }
 
 /// 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);
+pub fn init_logger(
+	pattern: &str,
+	tracing_receiver: sc_tracing::TracingReceiver,
+	tracing_targets: Option<String>
+) {
+	match tracing_log::LogTracer::init() {
+		Ok(_) => (),
+		Err(_) => log::info!(
+			"💬 Not registering Substrate logger, as there is already a global logger registered!"
+		),
+	}
+
+	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=info".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 != "" {
+			match lvl.parse() {
+				Ok(directive) => {
+					env_filter = env_filter.add_directive(directive);
+				}
+				// We're not sure if log or tracing is available at this moment, so silently ignore the
+				// parse error.
+				Err(_) => (),
+			}
+		}
+	}
+
+	if pattern != "" {
+		match pattern.parse() {
+			Ok(directive) => {
+				env_filter = env_filter.add_directive(directive);
+			}
+			// We're not sure if log or tracing is available at this moment, so silently ignore the
+			// parse error.
+			Err(_) => (),
+		}
 	}
 
-	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);
+
+		match tracing::subscriber::set_global_default(subscriber.with(profiling)) {
+			Ok(_) => (),
+			Err(_) => tracing::info!(
+				"💬 Not registering Substrate subscriber, as there is already a global subscriber registered!"
+			),
 		}
-
-		if !enable_color {
-			output = kill_color(output.as_ref());
+	} else {
+		match tracing::subscriber::set_global_default(subscriber) {
+			Ok(_) => (),
+			Err(_) => tracing::info!(
+				"💬 Not registering Substrate subscriber, as there is already a global subscriber registered!"
+			),
 		}
-
-		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()
 }

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")

client/consensus/manual-seal/Cargo.toml

@@ -37,5 +37,4 @@ sc-basic-authorship = { path = "../../basic-authorship", version = "0.8.0-rc5" }
 substrate-test-runtime-client = { path = "../../../test-utils/runtime/client", version = "2.0.0-rc5" }
 substrate-test-runtime-transaction-pool = { path = "../../../test-utils/runtime/transaction-pool", version = "2.0.0-rc5" }
 tokio = { version = "0.2", features = ["rt-core", "macros"] }
-env_logger = "0.7.0"
 tempfile = "3.1.0"

client/db/Cargo.toml

@@ -39,8 +39,8 @@ prometheus-endpoint = { package = "substrate-prometheus-endpoint", version = "0.
 
 [dev-dependencies]
 sp-keyring = { version = "2.0.0-rc5", path = "../../primitives/keyring" }
+sp-tracing = { version = "2.0.0-rc5", path = "../../primitives/tracing" }
 substrate-test-runtime-client = { version = "2.0.0-rc5", path = "../../test-utils/runtime/client" }
-env_logger = "0.7.0"
 quickcheck = "0.9"
 kvdb-rocksdb = "0.9"
 tempfile = "3"

client/db/src/lib.rs

@@ -1908,7 +1908,7 @@ pub(crate) mod tests {
 
 	#[test]
 	fn delete_only_when_negative_rc() {
-		let _ = ::env_logger::try_init();
+		sp_tracing::try_init_simple();
 		let key;
 		let backend = Backend::<Block>::new_test(1, 0);