Skip to content

Commit 91f49cf

Browse files
sorpaasgnunicorn
authored andcommitted
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>
1 parent 012346d commit 91f49cf

File tree

56 files changed

+547
-522
lines changed

Some content is hidden

Large Commits have some content hidden by default. Use the searchbox below for content that may be hidden.

56 files changed

+547
-522
lines changed

Cargo.lock

Lines changed: 206 additions & 225 deletions
Some generated files are not rendered by default. Learn more about customizing how changed files appear on GitHub.

bin/node/bench/Cargo.toml

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,7 @@ sc-basic-authorship = { version = "0.8.0-rc6", path = "../../../client/basic-aut
3131
sp-inherents = { version = "2.0.0-rc6", path = "../../../primitives/inherents" }
3232
sp-finality-tracker = { version = "2.0.0-rc6", default-features = false, path = "../../../primitives/finality-tracker" }
3333
sp-timestamp = { version = "2.0.0-rc6", default-features = false, path = "../../../primitives/timestamp" }
34+
sp-tracing = { version = "2.0.0-rc6", path = "../../../primitives/tracing" }
3435
hash-db = "0.15.2"
3536
tempfile = "3.1.0"
3637
fs_extra = "1"

bin/node/bench/src/main.rs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -79,7 +79,7 @@ fn main() {
7979
let opt = Opt::from_args();
8080

8181
if !opt.json {
82-
sc_cli::init_logger("");
82+
sp_tracing::try_init_simple();
8383
}
8484

8585
let mut import_benchmarks = Vec::new();

bin/node/rpc-client/Cargo.toml

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -11,10 +11,10 @@ repository = "https://github.com/paritytech/substrate/"
1111
targets = ["x86_64-unknown-linux-gnu"]
1212

1313
[dependencies]
14-
env_logger = "0.7.0"
1514
futures = "0.1.29"
1615
hyper = "0.12.35"
1716
jsonrpc-core-client = { version = "14.2.0", default-features = false, features = ["http"] }
1817
log = "0.4.8"
1918
node-primitives = { version = "2.0.0-rc6", path = "../primitives" }
19+
sp-tracing = { version = "2.0.0-rc6", path = "../../../primitives/tracing" }
2020
sc-rpc = { version = "2.0.0-rc6", path = "../../../client/rpc" }

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -35,7 +35,7 @@ use jsonrpc_core_client::{
3535
};
3636

3737
fn main() {
38-
env_logger::init();
38+
sp_tracing::try_init_simple();
3939

4040
rt::run(rt::lazy(|| {
4141
let uri = "http://localhost:9933";

client/authority-discovery/Cargo.toml

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -38,7 +38,7 @@ sp-runtime = { version = "2.0.0-rc6", path = "../../primitives/runtime" }
3838
sp-api = { version = "2.0.0-rc6", path = "../../primitives/api" }
3939

4040
[dev-dependencies]
41-
env_logger = "0.7.0"
4241
quickcheck = "0.9.0"
42+
sp-tracing = { version = "2.0.0-rc6", path = "../../primitives/tracing" }
4343
sc-peerset = { version = "2.0.0-rc6", path = "../peerset" }
4444
substrate-test-runtime-client = { version = "2.0.0-rc6", path = "../../test-utils/runtime/client"}

client/authority-discovery/src/worker/tests.rs

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -247,8 +247,8 @@ fn new_registers_metrics() {
247247
}
248248

249249
#[test]
250-
fn request_addresses_of_others_triggers_dht_get_query() {
251-
let _ = ::env_logger::try_init();
250+
fn triggers_dht_get_query() {
251+
sp_tracing::try_init_simple();
252252
let (_dht_event_tx, dht_event_rx) = channel(1000);
253253

254254
// Generate authority keys
@@ -282,7 +282,7 @@ fn request_addresses_of_others_triggers_dht_get_query() {
282282

283283
#[test]
284284
fn publish_discover_cycle() {
285-
let _ = ::env_logger::try_init();
285+
sp_tracing::try_init_simple();
286286

287287
// Node A publishing its address.
288288

client/cli/Cargo.toml

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -13,7 +13,6 @@ targets = ["x86_64-unknown-linux-gnu"]
1313

1414
[dependencies]
1515
derive_more = "0.99.2"
16-
env_logger = "0.7.0"
1716
log = "0.4.8"
1817
atty = "0.2.13"
1918
regex = "1.3.4"
@@ -50,6 +49,9 @@ sc-tracing = { version = "2.0.0-rc6", path = "../tracing" }
5049
chrono = "0.4.10"
5150
parity-util-mem = { version = "0.7.0", default-features = false, features = ["primitive-types"] }
5251
serde = "1.0.111"
52+
tracing = "0.1.10"
53+
tracing-log = "0.1.1"
54+
tracing-subscriber = "0.2.10"
5355

5456
[target.'cfg(not(target_os = "unknown"))'.dependencies]
5557
rpassword = "4.0.1"

client/cli/src/config.rs

Lines changed: 6 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -527,7 +527,7 @@ pub trait CliConfiguration<DCV: DefaultConfigurationValues = ()>: Sized {
527527
Ok(self.shared_params().log_filters().join(","))
528528
}
529529

530-
/// Initialize substrate. This must be done only once.
530+
/// Initialize substrate. This must be done only once per process.
531531
///
532532
/// This method:
533533
///
@@ -536,11 +536,14 @@ pub trait CliConfiguration<DCV: DefaultConfigurationValues = ()>: Sized {
536536
/// 3. Initialize the logger
537537
fn init<C: SubstrateCli>(&self) -> Result<()> {
538538
let logger_pattern = self.log_filters()?;
539+
let tracing_receiver = self.tracing_receiver()?;
540+
let tracing_targets = self.tracing_targets()?;
539541

540542
sp_panic_handler::set(&C::support_url(), &C::impl_version());
541543

542-
fdlimit::raise_fd_limit();
543-
init_logger(&logger_pattern);
544+
if let Err(e) = init_logger(&logger_pattern, tracing_receiver, tracing_targets) {
545+
log::warn!("💬 Problem initializing global logging framework: {:}", e)
546+
}
544547

545548
Ok(())
546549
}

client/cli/src/lib.rs

Lines changed: 63 additions & 68 deletions
Original file line numberDiff line numberDiff line change
@@ -32,10 +32,7 @@ pub use arg_enums::*;
3232
pub use commands::*;
3333
pub use config::*;
3434
pub use error::*;
35-
use lazy_static::lazy_static;
36-
use log::info;
3735
pub use params::*;
38-
use regex::Regex;
3936
pub use runner::*;
4037
use sc_service::{Configuration, TaskExecutor};
4138
pub use sc_service::{ChainSpec, Role};
@@ -46,6 +43,7 @@ use structopt::{
4643
clap::{self, AppSettings},
4744
StructOpt,
4845
};
46+
use tracing_subscriber::layer::SubscriberExt;
4947

5048
/// Substrate client CLI
5149
///
@@ -228,79 +226,76 @@ pub trait SubstrateCli: Sized {
228226
fn native_runtime_version(chain_spec: &Box<dyn ChainSpec>) -> &'static RuntimeVersion;
229227
}
230228

231-
/// Initialize the logger
232-
pub fn init_logger(pattern: &str) {
233-
use ansi_term::Colour;
234-
235-
let mut builder = env_logger::Builder::new();
236-
// Disable info logging by default for some modules:
237-
builder.filter(Some("ws"), log::LevelFilter::Off);
238-
builder.filter(Some("yamux"), log::LevelFilter::Off);
239-
builder.filter(Some("cranelift_codegen"), log::LevelFilter::Off);
240-
builder.filter(Some("hyper"), log::LevelFilter::Warn);
241-
builder.filter(Some("cranelift_wasm"), log::LevelFilter::Warn);
242-
// Always log the special target `sc_tracing`, overrides global level
243-
builder.filter(Some("sc_tracing"), log::LevelFilter::Trace);
244-
// Enable info for others.
245-
builder.filter(None, log::LevelFilter::Info);
229+
/// Initialize the global logger
230+
///
231+
/// This sets various global logging and tracing instances and thus may only be called once.
232+
pub fn init_logger(
233+
pattern: &str,
234+
tracing_receiver: sc_tracing::TracingReceiver,
235+
tracing_targets: Option<String>,
236+
) -> std::result::Result<(), String> {
237+
if let Err(e) = tracing_log::LogTracer::init() {
238+
return Err(format!(
239+
"Registering Substrate logger failed: {:}!", e
240+
))
241+
}
242+
243+
let mut env_filter = tracing_subscriber::EnvFilter::default()
244+
// Disable info logging by default for some modules.
245+
.add_directive("ws=off".parse().expect("provided directive is valid"))
246+
.add_directive("yamux=off".parse().expect("provided directive is valid"))
247+
.add_directive("cranelift_codegen=off".parse().expect("provided directive is valid"))
248+
// Set warn logging by default for some modules.
249+
.add_directive("cranelife_wasm=warn".parse().expect("provided directive is valid"))
250+
.add_directive("hyper=warn".parse().expect("provided directive is valid"))
251+
// Always log the special target `sc_tracing`, overrides global level.
252+
.add_directive("sc_tracing=trace".parse().expect("provided directive is valid"))
253+
// Enable info for others.
254+
.add_directive(tracing_subscriber::filter::LevelFilter::INFO.into());
246255

247256
if let Ok(lvl) = std::env::var("RUST_LOG") {
248-
builder.parse_filters(&lvl);
257+
if lvl != "" {
258+
// We're not sure if log or tracing is available at this moment, so silently ignore the
259+
// parse error.
260+
if let Ok(directive) = lvl.parse() {
261+
env_filter = env_filter.add_directive(directive);
262+
}
263+
}
264+
}
265+
266+
if pattern != "" {
267+
// We're not sure if log or tracing is available at this moment, so silently ignore the
268+
// parse error.
269+
if let Ok(directive) = pattern.parse() {
270+
env_filter = env_filter.add_directive(directive);
271+
}
249272
}
250273

251-
builder.parse_filters(pattern);
252274
let isatty = atty::is(atty::Stream::Stderr);
253275
let enable_color = isatty;
254276

255-
builder.format(move |buf, record| {
256-
let now = time::now();
257-
let timestamp =
258-
time::strftime("%Y-%m-%d %H:%M:%S", &now).expect("Error formatting log timestamp");
259-
260-
let mut output = if log::max_level() <= log::LevelFilter::Info {
261-
format!(
262-
"{} {}",
263-
Colour::Black.bold().paint(timestamp),
264-
record.args(),
265-
)
266-
} else {
267-
let name = ::std::thread::current()
268-
.name()
269-
.map_or_else(Default::default, |x| {
270-
format!("{}", Colour::Blue.bold().paint(x))
271-
});
272-
let millis = (now.tm_nsec as f32 / 1000000.0).floor() as usize;
273-
let timestamp = format!("{}.{:03}", timestamp, millis);
274-
format!(
275-
"{} {} {} {} {}",
276-
Colour::Black.bold().paint(timestamp),
277-
name,
278-
record.level(),
279-
record.target(),
280-
record.args()
281-
)
282-
};
283-
284-
if !isatty && record.level() <= log::Level::Info && atty::is(atty::Stream::Stdout) {
285-
// duplicate INFO/WARN output to console
286-
println!("{}", output);
277+
let subscriber = tracing_subscriber::FmtSubscriber::builder()
278+
.with_env_filter(env_filter)
279+
.with_target(false)
280+
.with_ansi(enable_color)
281+
.with_writer(std::io::stderr)
282+
.compact()
283+
.finish();
284+
285+
if let Some(tracing_targets) = tracing_targets {
286+
let profiling = sc_tracing::ProfilingLayer::new(tracing_receiver, &tracing_targets);
287+
288+
if let Err(e) = tracing::subscriber::set_global_default(subscriber.with(profiling)) {
289+
return Err(format!(
290+
"Registering Substrate tracing subscriber failed: {:}!", e
291+
))
287292
}
288-
289-
if !enable_color {
290-
output = kill_color(output.as_ref());
293+
} else {
294+
if let Err(e) = tracing::subscriber::set_global_default(subscriber) {
295+
return Err(format!(
296+
"Registering Substrate tracing subscriber failed: {:}!", e
297+
))
291298
}
292-
293-
writeln!(buf, "{}", output)
294-
});
295-
296-
if builder.try_init().is_err() {
297-
info!("💬 Not registering Substrate logger, as there is already a global logger registered!");
298-
}
299-
}
300-
301-
fn kill_color(s: &str) -> String {
302-
lazy_static! {
303-
static ref RE: Regex = Regex::new("\x1b\\[[^m]+m").expect("Error initializing color regex");
304299
}
305-
RE.replace_all(s, "").to_string()
300+
Ok(())
306301
}

0 commit comments

Comments
 (0)