From 0c480effd075a35398e90c33e5d78a427fe16749 Mon Sep 17 00:00:00 2001 From: Matt Date: Fri, 30 Oct 2020 19:45:50 +0000 Subject: [PATCH 01/50] Add filter reload handle --- client/cli/Cargo.toml | 4 ++-- client/cli/src/lib.rs | 17 ++++++++++++----- client/cli/src/logging.rs | 2 +- client/tracing/Cargo.toml | 3 ++- client/tracing/src/lib.rs | 18 +++++++++++++++++- 5 files changed, 34 insertions(+), 10 deletions(-) diff --git a/client/cli/Cargo.toml b/client/cli/Cargo.toml index 33fc39f8217eb..147b83053c172 100644 --- a/client/cli/Cargo.toml +++ b/client/cli/Cargo.toml @@ -44,9 +44,9 @@ structopt = "0.3.8" sc-tracing = { version = "2.0.0", path = "../tracing" } chrono = "0.4.10" serde = "1.0.111" -tracing = "0.1.10" +tracing = "0.1.21" tracing-log = "0.1.1" -tracing-subscriber = "0.2.10" +tracing-subscriber = "0.2.14" sc-cli-proc-macro = { version = "2.0.0", path = "./proc-macro" } thiserror = "1.0.21" diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index c25693dc418b1..a64f563944de9 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -50,10 +50,13 @@ use structopt::{ #[doc(hidden)] pub use tracing; use tracing_subscriber::{ - filter::Directive, fmt::time::ChronoLocal, layer::SubscriberExt, FmtSubscriber, Layer, + filter::Directive, fmt::time::ChronoLocal, layer::SubscriberExt, FmtSubscriber, Layer, fmt::Formatter, reload::Handle, EnvFilter }; pub use logging::PREFIX_LOG_SPAN; +use tracing_subscriber::layer::Layered; +use crate::logging::{NodeNameLayer, EventFormat}; +use tracing_subscriber::fmt::format::DefaultFields; /// Substrate client CLI /// @@ -243,7 +246,8 @@ pub fn init_logger( pattern: &str, tracing_receiver: sc_tracing::TracingReceiver, profiling_targets: Option, -) -> std::result::Result<(), String> { +) -> std::result::Result<(), String> +{ fn parse_directives(dirs: impl AsRef) -> Vec { dirs.as_ref() .split(',') @@ -316,7 +320,7 @@ pub fn init_logger( "%Y-%m-%d %H:%M:%S%.3f".to_string() }); - let subscriber = FmtSubscriber::builder() + let subscriber_builder = FmtSubscriber::builder() .with_env_filter(env_filter) .with_writer(std::io::stderr) .event_format(logging::EventFormat { @@ -326,8 +330,11 @@ pub fn init_logger( display_level: !simple, display_thread_name: !simple, }) - .finish().with(logging::NodeNameLayer); - + // TODO: Q - There's a small cost to this, do we make it opt-in/out with cli flag? + .with_filter_reloading(); + let handle = subscriber_builder.reload_handle(); + let subscriber = subscriber_builder.finish().with(logging::NodeNameLayer); + sc_tracing::set_reload_handle(handle); if let Some(profiling_targets) = profiling_targets { let profiling = sc_tracing::ProfilingLayer::new(tracing_receiver, &profiling_targets); diff --git a/client/cli/src/logging.rs b/client/cli/src/logging.rs index e1fc90505b45f..e29e13e28dae7 100644 --- a/client/cli/src/logging.rs +++ b/client/cli/src/logging.rs @@ -33,7 +33,7 @@ use tracing_subscriber::{ /// Span name used for the logging prefix. See macro `sc_cli::prefix_logs_with!` pub const PREFIX_LOG_SPAN: &str = "substrate-log-prefix"; -pub(crate) struct EventFormat { +pub struct EventFormat { pub(crate) timer: T, pub(crate) ansi: bool, pub(crate) display_target: bool, diff --git a/client/tracing/Cargo.toml b/client/tracing/Cargo.toml index 35db326c94929..73d04d7d6603c 100644 --- a/client/tracing/Cargo.toml +++ b/client/tracing/Cargo.toml @@ -15,6 +15,7 @@ targets = ["x86_64-unknown-linux-gnu"] [dependencies] erased-serde = "0.3.9" log = { version = "0.4.8" } +once_cell = "1.4.1" parking_lot = "0.10.0" rustc-hash = "1.1.0" serde = "1.0.101" @@ -22,6 +23,6 @@ serde_json = "1.0.41" slog = { version = "2.5.2", features = ["nested-values"] } tracing = "0.1.21" tracing-core = "0.1.17" -tracing-subscriber = "0.2.13" +tracing-subscriber = "0.2.14" sp-tracing = { version = "2.0.0", path = "../../primitives/tracing" } sc-telemetry = { version = "2.0.0", path = "../telemetry" } diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 6690f283464ea..c1852305db06f 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -37,12 +37,28 @@ use tracing::{ span::{Attributes, Id, Record}, subscriber::Subscriber, }; -use tracing_subscriber::{CurrentSpan, layer::{Layer, Context}}; +use tracing_subscriber::{CurrentSpan, layer::{Layer, Context}, EnvFilter}; use sc_telemetry::{telemetry, SUBSTRATE_INFO}; use sp_tracing::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER}; +use tracing_subscriber::reload::Handle; +use tracing_subscriber::fmt::Formatter; +use tracing_subscriber::fmt::format::DefaultFields; +use tracing_subscriber::fmt::time::ChronoLocal; +use once_cell::sync::OnceCell; + const ZERO_DURATION: Duration = Duration::from_nanos(0); +static FILTER_RELOAD_HANDLE: OnceCell, impl FnOnce() -> std::io::Stderr>>> = OnceCell::new(); + +pub fn set_reload_handle(handle: Handle, impl FnOnce() -> std::io::Stderr>>) { + let _ = FILTER_RELOAD_HANDLE.set(handle); +} + +pub fn get_Reload_handle() -> Option<&Handle, impl FnOnce() -> std::io::Stderr>>> { + FILTER_RELOAD_HANDLE.get() +} + /// Responsible for assigning ids to new spans, which are not re-used. pub struct ProfilingLayer { targets: Vec<(String, Level)>, From 767f61a05b17b4d8535cc03ff4cc495668db6479 Mon Sep 17 00:00:00 2001 From: Matt Date: Fri, 30 Oct 2020 22:23:59 +0000 Subject: [PATCH 02/50] add RPC, move logging module from cli to tracing --- Cargo.lock | 39 ++- client/cli/src/lib.rs | 2 +- client/rpc-api/src/system/mod.rs | 5 + client/rpc/Cargo.toml | 1 + client/rpc/src/system/mod.rs | 4 + client/tracing/Cargo.toml | 2 + client/tracing/src/lib.rs | 25 +- client/tracing/src/logging.rs | 268 ++++++++++++++++++ .../cli => primitives/tracing}/src/logging.rs | 0 9 files changed, 338 insertions(+), 8 deletions(-) create mode 100644 client/tracing/src/logging.rs rename {client/cli => primitives/tracing}/src/logging.rs (100%) diff --git a/Cargo.lock b/Cargo.lock index 1841c01faf84c..551f3320317f9 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2018,6 +2018,19 @@ version = "0.3.55" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "8f5f3913fa0bfe7ee1fd8248b6b9f42a5af4b9d65ec2dd2c3c26132b950ecfc2" +[[package]] +name = "generator" +version = "0.6.23" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8cdc09201b2e8ca1b19290cf7e65de2246b8e91fb6874279722189c4de7b94dc" +dependencies = [ + "cc", + "libc", + "log", + "rustc_version", + "winapi 0.3.9", +] + [[package]] name = "generic-array" version = "0.12.3" @@ -3381,6 +3394,19 @@ dependencies = [ "cfg-if", ] +[[package]] +name = "loom" +version = "0.3.6" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a0e8460f2f2121162705187214720353c517b97bdfb3494c0b1e33d83ebe4bed" +dependencies = [ + "cfg-if", + "generator", + "scoped-tls", + "serde", + "serde_json", +] + [[package]] name = "lru" version = "0.4.3" @@ -7246,6 +7272,7 @@ dependencies = [ "sc-keystore", "sc-network", "sc-rpc-api", + "sc-tracing", "sc-transaction-pool", "serde_json", "sp-api", @@ -7481,8 +7508,10 @@ dependencies = [ name = "sc-tracing" version = "2.0.0" dependencies = [ + "ansi_term 0.12.1", "erased-serde", "log", + "once_cell 1.4.1", "parking_lot 0.10.2", "rustc-hash", "sc-telemetry", @@ -7492,6 +7521,7 @@ dependencies = [ "sp-tracing", "tracing", "tracing-core", + "tracing-log", "tracing-subscriber", ] @@ -7804,11 +7834,12 @@ dependencies = [ [[package]] name = "sharded-slab" -version = "0.0.9" +version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "06d5a3f5166fb5b42a5439f2eee8b9de149e235961e3eb21c5808fc3ea17ff3e" +checksum = "7b4921be914e16899a80adefb821f8ddb7974e3f1250223575a44ed994882127" dependencies = [ "lazy_static", + "loom", ] [[package]] @@ -9652,9 +9683,9 @@ dependencies = [ [[package]] name = "tracing-subscriber" -version = "0.2.13" +version = "0.2.14" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "4ef0a5e15477aa303afbfac3a44cba9b6430fdaad52423b1e6c0dbbe28c3eedd" +checksum = "2810660b9d5b18895d140caba6401765749a6a162e5d0736cfc44ea50db9d79d" dependencies = [ "ansi_term 0.12.1", "chrono", diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index a64f563944de9..fc5fb8caeeb8c 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -27,7 +27,6 @@ pub mod arg_enums; mod commands; mod config; mod error; -mod logging; mod params; mod runner; @@ -52,6 +51,7 @@ pub use tracing; use tracing_subscriber::{ filter::Directive, fmt::time::ChronoLocal, layer::SubscriberExt, FmtSubscriber, Layer, fmt::Formatter, reload::Handle, EnvFilter }; +pub use sc_tracing::logging; pub use logging::PREFIX_LOG_SPAN; use tracing_subscriber::layer::Layered; diff --git a/client/rpc-api/src/system/mod.rs b/client/rpc-api/src/system/mod.rs index fbeec23ea5085..adc5348f15d78 100644 --- a/client/rpc-api/src/system/mod.rs +++ b/client/rpc-api/src/system/mod.rs @@ -108,4 +108,9 @@ pub trait SystemApi { /// known block. #[rpc(name = "system_syncState", returns = "SyncState")] fn system_sync_state(&self) -> Receiver>; + + /// Reloads the logging filter, replacing current with the supplied directives + #[rpc(name = "system_reloadLogFilter", returns = "()")] + fn system_reload_log_filter(&self, directives: String) + -> Result<(), jsonrpc_core::Error>; } diff --git a/client/rpc/Cargo.toml b/client/rpc/Cargo.toml index 021c795fe5b94..ff0fb76a3e201 100644 --- a/client/rpc/Cargo.toml +++ b/client/rpc/Cargo.toml @@ -37,6 +37,7 @@ sc-block-builder = { version = "0.8.0", path = "../../client/block-builder" } sc-keystore = { version = "2.0.0", path = "../keystore" } sp-transaction-pool = { version = "2.0.0", path = "../../primitives/transaction-pool" } sp-blockchain = { version = "2.0.0", path = "../../primitives/blockchain" } +sc-tracing = { version = "2.0.0", path = "../../client/tracing" } hash-db = { version = "0.15.2", default-features = false } parking_lot = "0.10.0" lazy_static = { version = "1.4.0", optional = true } diff --git a/client/rpc/src/system/mod.rs b/client/rpc/src/system/mod.rs index 17fb6b77a5710..cff72bbc1278d 100644 --- a/client/rpc/src/system/mod.rs +++ b/client/rpc/src/system/mod.rs @@ -197,4 +197,8 @@ impl SystemApi::Number> for Sy let _ = self.send_back.unbounded_send(Request::SyncState(tx)); Receiver(Compat::new(rx)) } + + fn system_reload_log_filter(&self, directives: String)-> std::result::Result<(), rpc::Error> { + sc_tracing::reload_filter(directives).map_err(|e| rpc::Error::internal_error()) + } } diff --git a/client/tracing/Cargo.toml b/client/tracing/Cargo.toml index 73d04d7d6603c..5fd45eb839a53 100644 --- a/client/tracing/Cargo.toml +++ b/client/tracing/Cargo.toml @@ -13,6 +13,8 @@ readme = "README.md" targets = ["x86_64-unknown-linux-gnu"] [dependencies] +ansi_term = "0.12.1" +tracing-log = "0.1.1" erased-serde = "0.3.9" log = { version = "0.4.8" } once_cell = "1.4.1" diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index c1852305db06f..66b0d6d652f57 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -23,6 +23,7 @@ //! See `sp-tracing` for examples on how to use tracing. //! //! Currently we provide `Log` (default), `Telemetry` variants for `Receiver` +pub mod logging; use rustc_hash::FxHashMap; use std::fmt; @@ -46,17 +47,35 @@ use tracing_subscriber::fmt::Formatter; use tracing_subscriber::fmt::format::DefaultFields; use tracing_subscriber::fmt::time::ChronoLocal; use once_cell::sync::OnceCell; +use tracing_subscriber::filter::Directive; const ZERO_DURATION: Duration = Duration::from_nanos(0); -static FILTER_RELOAD_HANDLE: OnceCell, impl FnOnce() -> std::io::Stderr>>> = OnceCell::new(); +static FILTER_RELOAD_HANDLE: OnceCell, fn() -> std::io::Stderr>>> = OnceCell::new(); -pub fn set_reload_handle(handle: Handle, impl FnOnce() -> std::io::Stderr>>) { +/// Initialize FILTER_RELOAD_HANDLE, only possible once +pub fn set_reload_handle(handle: Handle, fn() -> std::io::Stderr>>) { let _ = FILTER_RELOAD_HANDLE.set(handle); } -pub fn get_Reload_handle() -> Option<&Handle, impl FnOnce() -> std::io::Stderr>>> { +/// Reload the logging filter with the supplied directives +pub fn reload_filter(directives: String) -> Result<(), String> { + let mut env_filter = tracing_subscriber::EnvFilter::default(); + for directive in parse_directives(directives) { + env_filter = env_filter.add_directive(directive); + } FILTER_RELOAD_HANDLE.get() + .ok_or("No reload handle present".to_string())? + .reload(env_filter) + .map_err(|e| format!("{}", e)) +} + +/// Parse the supplied text directives into `Vec` +pub fn parse_directives(dirs: impl AsRef) -> Vec { + dirs.as_ref() + .split(',') + .filter_map(|s| s.parse().ok()) + .collect() } /// Responsible for assigning ids to new spans, which are not re-used. diff --git a/client/tracing/src/logging.rs b/client/tracing/src/logging.rs new file mode 100644 index 0000000000000..4e72c9897d143 --- /dev/null +++ b/client/tracing/src/logging.rs @@ -0,0 +1,268 @@ +// 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 std::fmt; +use tracing::{span::Attributes, Event, Id, Level, Subscriber}; +use tracing_log::NormalizeEvent; +use tracing_subscriber::{ + fmt::{ + time::{FormatTime, SystemTime}, + FmtContext, FormatEvent, FormatFields, + }, + layer::Context, + registry::LookupSpan, + Layer, +}; + +/// Span name used for the logging prefix. See macro `sc_cli::prefix_logs_with!` +pub const PREFIX_LOG_SPAN: &str = "substrate-log-prefix"; + +pub struct EventFormat { + pub timer: T, + pub ansi: bool, + pub display_target: bool, + pub display_level: bool, + pub display_thread_name: bool, +} + +// NOTE: the following code took inspiration from tracing-subscriber +// +// https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/format/mod.rs#L449 +impl FormatEvent for EventFormat +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, + T: FormatTime, +{ + fn format_event( + &self, + ctx: &FmtContext, + writer: &mut dyn fmt::Write, + event: &Event, + ) -> fmt::Result { + let normalized_meta = event.normalized_metadata(); + let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata()); + time::write(&self.timer, writer, self.ansi)?; + + if self.display_level { + let fmt_level = { FmtLevel::new(meta.level(), self.ansi) }; + write!(writer, "{} ", fmt_level)?; + } + + if self.display_thread_name { + let current_thread = std::thread::current(); + match current_thread.name() { + Some(name) => { + write!(writer, "{} ", FmtThreadName::new(name))?; + } + // fall-back to thread id when name is absent and ids are not enabled + None => { + write!(writer, "{:0>2?} ", current_thread.id())?; + } + } + } + + // Custom code to display node name + if let Some(span) = ctx.lookup_current() { + let parents = span.parents(); + for span in std::iter::once(span).chain(parents) { + let exts = span.extensions(); + if let Some(node_name) = exts.get::() { + write!(writer, "{}", node_name.as_str())?; + break; + } + } + } + + if self.display_target { + write!(writer, "{}:", meta.target())?; + } + ctx.format_fields(writer, event)?; + writeln!(writer) + } +} + +pub struct NodeNameLayer; + +impl Layer for NodeNameLayer +where + S: Subscriber + for<'a> LookupSpan<'a>, +{ + fn new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { + let span = ctx + .span(id) + .expect("new_span has been called for this span; qed"); + + if span.name() != PREFIX_LOG_SPAN { + return; + } + + let mut extensions = span.extensions_mut(); + + if extensions.get_mut::().is_none() { + let mut s = String::new(); + let mut v = NodeNameVisitor(&mut s); + attrs.record(&mut v); + + if !s.is_empty() { + let fmt_fields = NodeName(s); + extensions.insert(fmt_fields); + } + } + } +} + +struct NodeNameVisitor<'a, W: std::fmt::Write>(&'a mut W); + +macro_rules! write_node_name { + ($method:ident, $type:ty, $format:expr) => { + fn $method(&mut self, field: &tracing::field::Field, value: $type) { + if field.name() == "name" { + write!(self.0, $format, value).expect("no way to return the err; qed"); + } + } + }; +} + +impl<'a, W: std::fmt::Write> tracing::field::Visit for NodeNameVisitor<'a, W> { + write_node_name!(record_debug, &dyn std::fmt::Debug, "[{:?}] "); + write_node_name!(record_str, &str, "[{}] "); + write_node_name!(record_i64, i64, "[{}] "); + write_node_name!(record_u64, u64, "[{}] "); + write_node_name!(record_bool, bool, "[{}] "); +} + +#[derive(Debug)] +struct NodeName(String); + +impl NodeName { + fn as_str(&self) -> &str { + self.0.as_str() + } +} + +struct FmtLevel<'a> { + level: &'a Level, + ansi: bool, +} + +impl<'a> FmtLevel<'a> { + pub(crate) fn new(level: &'a Level, ansi: bool) -> Self { + Self { level, ansi } + } +} + +const TRACE_STR: &str = "TRACE"; +const DEBUG_STR: &str = "DEBUG"; +const INFO_STR: &str = " INFO"; +const WARN_STR: &str = " WARN"; +const ERROR_STR: &str = "ERROR"; + +impl<'a> fmt::Display for FmtLevel<'a> { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + if self.ansi { + match *self.level { + Level::TRACE => write!(f, "{}", Colour::Purple.paint(TRACE_STR)), + Level::DEBUG => write!(f, "{}", Colour::Blue.paint(DEBUG_STR)), + Level::INFO => write!(f, "{}", Colour::Green.paint(INFO_STR)), + Level::WARN => write!(f, "{}", Colour::Yellow.paint(WARN_STR)), + Level::ERROR => write!(f, "{}", Colour::Red.paint(ERROR_STR)), + } + } else { + match *self.level { + Level::TRACE => f.pad(TRACE_STR), + Level::DEBUG => f.pad(DEBUG_STR), + Level::INFO => f.pad(INFO_STR), + Level::WARN => f.pad(WARN_STR), + Level::ERROR => f.pad(ERROR_STR), + } + } + } +} + +struct FmtThreadName<'a> { + name: &'a str, +} + +impl<'a> FmtThreadName<'a> { + pub(crate) fn new(name: &'a str) -> Self { + Self { name } + } +} + +// NOTE: the following code has been duplicated from tracing-subscriber +// +// https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/format/mod.rs#L845 +impl<'a> fmt::Display for FmtThreadName<'a> { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + use std::sync::atomic::{ + AtomicUsize, + Ordering::{AcqRel, Acquire, Relaxed}, + }; + + // Track the longest thread name length we've seen so far in an atomic, + // so that it can be updated by any thread. + static MAX_LEN: AtomicUsize = AtomicUsize::new(0); + let len = self.name.len(); + // Snapshot the current max thread name length. + let mut max_len = MAX_LEN.load(Relaxed); + + while len > max_len { + // Try to set a new max length, if it is still the value we took a + // snapshot of. + match MAX_LEN.compare_exchange(max_len, len, AcqRel, Acquire) { + // We successfully set the new max value + Ok(_) => break, + // Another thread set a new max value since we last observed + // it! It's possible that the new length is actually longer than + // ours, so we'll loop again and check whether our length is + // still the longest. If not, we'll just use the newer value. + Err(actual) => max_len = actual, + } + } + + // pad thread name using `max_len` + write!(f, "{:>width$}", self.name, width = max_len) + } +} + +// NOTE: the following code has been duplicated from tracing-subscriber +// +// https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/time/mod.rs#L252 +mod time { + use ansi_term::Style; + use std::fmt; + use tracing_subscriber::fmt::time::FormatTime; + + pub(crate) fn write(timer: T, writer: &mut dyn fmt::Write, with_ansi: bool) -> fmt::Result + where + T: FormatTime, + { + if with_ansi { + let style = Style::new().dimmed(); + write!(writer, "{}", style.prefix())?; + timer.format_time(writer)?; + write!(writer, "{}", style.suffix())?; + } else { + timer.format_time(writer)?; + } + writer.write_char(' ')?; + Ok(()) + } +} diff --git a/client/cli/src/logging.rs b/primitives/tracing/src/logging.rs similarity index 100% rename from client/cli/src/logging.rs rename to primitives/tracing/src/logging.rs From 5643e7ed7f6ae18a20b7074659f7090719cdac44 Mon Sep 17 00:00:00 2001 From: Matt Date: Fri, 30 Oct 2020 22:26:48 +0000 Subject: [PATCH 03/50] remove dup fn --- client/cli/src/lib.rs | 7 +------ 1 file changed, 1 insertion(+), 6 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index fc5fb8caeeb8c..70d4096cfa3bd 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -248,12 +248,7 @@ pub fn init_logger( profiling_targets: Option, ) -> std::result::Result<(), String> { - fn parse_directives(dirs: impl AsRef) -> Vec { - dirs.as_ref() - .split(',') - .filter_map(|s| s.parse().ok()) - .collect() - } + use sc_tracing::parse_directives; if let Err(e) = tracing_log::LogTracer::init() { return Err(format!( From cd8815edd71121ceec4908320a55a119e1d4a4fe Mon Sep 17 00:00:00 2001 From: Matt Date: Sat, 31 Oct 2020 13:11:01 +0000 Subject: [PATCH 04/50] working example --- client/cli/src/lib.rs | 25 ++++++++++++++----------- client/tracing/src/lib.rs | 6 ++---- 2 files changed, 16 insertions(+), 15 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 70d4096cfa3bd..153e680794328 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -256,7 +256,7 @@ pub fn init_logger( )) } - let mut env_filter = tracing_subscriber::EnvFilter::default() + let mut env_filter: EnvFilter = 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")) @@ -317,18 +317,21 @@ pub fn init_logger( let subscriber_builder = FmtSubscriber::builder() .with_env_filter(env_filter) - .with_writer(std::io::stderr) - .event_format(logging::EventFormat { - timer, - ansi: enable_color, - display_target: !simple, - display_level: !simple, - display_thread_name: !simple, - }) // TODO: Q - There's a small cost to this, do we make it opt-in/out with cli flag? .with_filter_reloading(); - let handle = subscriber_builder.reload_handle(); - let subscriber = subscriber_builder.finish().with(logging::NodeNameLayer); + let handle = subscriber_builder.reload_handle(); + let subscriber = subscriber_builder + // TODO: re-enable this + // .with_writer(std::io::stderr) + // .event_format(logging::EventFormat { + // timer, + // ansi: enable_color, + // display_target: !simple, + // display_level: !simple, + // display_thread_name: !simple, + // }) + .finish() + .with(logging::NodeNameLayer); sc_tracing::set_reload_handle(handle); if let Some(profiling_targets) = profiling_targets { let profiling = sc_tracing::ProfilingLayer::new(tracing_receiver, &profiling_targets); diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 66b0d6d652f57..2749383ebd2a6 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -44,17 +44,15 @@ use sc_telemetry::{telemetry, SUBSTRATE_INFO}; use sp_tracing::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER}; use tracing_subscriber::reload::Handle; use tracing_subscriber::fmt::Formatter; -use tracing_subscriber::fmt::format::DefaultFields; -use tracing_subscriber::fmt::time::ChronoLocal; use once_cell::sync::OnceCell; use tracing_subscriber::filter::Directive; const ZERO_DURATION: Duration = Duration::from_nanos(0); -static FILTER_RELOAD_HANDLE: OnceCell, fn() -> std::io::Stderr>>> = OnceCell::new(); +static FILTER_RELOAD_HANDLE: OnceCell> = OnceCell::new(); /// Initialize FILTER_RELOAD_HANDLE, only possible once -pub fn set_reload_handle(handle: Handle, fn() -> std::io::Stderr>>) { +pub fn set_reload_handle(handle: Handle) { let _ = FILTER_RELOAD_HANDLE.set(handle); } From eb429e17e843c0375b41e6ea10aa583c6fada58d Mon Sep 17 00:00:00 2001 From: David Date: Mon, 2 Nov 2020 11:31:19 +0100 Subject: [PATCH 05/50] Update client/rpc-api/src/system/mod.rs Co-authored-by: Pierre Krieger --- client/rpc-api/src/system/mod.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/client/rpc-api/src/system/mod.rs b/client/rpc-api/src/system/mod.rs index adc5348f15d78..9b665f5b42db3 100644 --- a/client/rpc-api/src/system/mod.rs +++ b/client/rpc-api/src/system/mod.rs @@ -109,8 +109,8 @@ pub trait SystemApi { #[rpc(name = "system_syncState", returns = "SyncState")] fn system_sync_state(&self) -> Receiver>; - /// Reloads the logging filter, replacing current with the supplied directives - #[rpc(name = "system_reloadLogFilter", returns = "()")] + /// Sets the logging filter, replacing current with the supplied directives + #[rpc(name = "system_setLogFilter", returns = "()")] fn system_reload_log_filter(&self, directives: String) -> Result<(), jsonrpc_core::Error>; } From 884c1db2729f43054ca0581d1635a04530bac997 Mon Sep 17 00:00:00 2001 From: David Palm Date: Tue, 3 Nov 2020 16:46:30 +0100 Subject: [PATCH 06/50] Prefer "set" to "reload" --- client/rpc-api/src/system/mod.rs | 2 +- client/rpc/src/system/mod.rs | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/client/rpc-api/src/system/mod.rs b/client/rpc-api/src/system/mod.rs index 9b665f5b42db3..3ada7af0d0927 100644 --- a/client/rpc-api/src/system/mod.rs +++ b/client/rpc-api/src/system/mod.rs @@ -111,6 +111,6 @@ pub trait SystemApi { /// Sets the logging filter, replacing current with the supplied directives #[rpc(name = "system_setLogFilter", returns = "()")] - fn system_reload_log_filter(&self, directives: String) + fn system_set_log_filter(&self, directives: String) -> Result<(), jsonrpc_core::Error>; } diff --git a/client/rpc/src/system/mod.rs b/client/rpc/src/system/mod.rs index cff72bbc1278d..46a4325e145b5 100644 --- a/client/rpc/src/system/mod.rs +++ b/client/rpc/src/system/mod.rs @@ -198,7 +198,7 @@ impl SystemApi::Number> for Sy Receiver(Compat::new(rx)) } - fn system_reload_log_filter(&self, directives: String)-> std::result::Result<(), rpc::Error> { - sc_tracing::reload_filter(directives).map_err(|e| rpc::Error::internal_error()) + fn system_set_log_filter(&self, directives: String)-> std::result::Result<(), rpc::Error> { + sc_tracing::reload_filter(directives).map_err(|_e| rpc::Error::internal_error()) } } From 57ae457a5e49fc2a62e846eb8543bda5a640564b Mon Sep 17 00:00:00 2001 From: David Palm Date: Wed, 4 Nov 2020 13:28:38 +0100 Subject: [PATCH 07/50] Re-enable the commented out features of the logger --- Cargo.lock | 1 - client/cli/Cargo.toml | 1 - client/cli/src/lib.rs | 29 +++++++++++++++-------------- client/tracing/src/lib.rs | 22 ++++++++++++++++++---- 4 files changed, 33 insertions(+), 20 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 551f3320317f9..61be579e1c499 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6513,7 +6513,6 @@ dependencies = [ name = "sc-cli" version = "0.8.0" dependencies = [ - "ansi_term 0.12.1", "atty", "bip39", "chrono", diff --git a/client/cli/Cargo.toml b/client/cli/Cargo.toml index 147b83053c172..88c80fb79f069 100644 --- a/client/cli/Cargo.toml +++ b/client/cli/Cargo.toml @@ -16,7 +16,6 @@ targets = ["x86_64-unknown-linux-gnu"] log = "0.4.11" atty = "0.2.13" regex = "1.3.4" -ansi_term = "0.12.1" tokio = { version = "0.2.21", features = [ "signal", "rt-core", "rt-threaded", "blocking" ] } futures = "0.3.4" fdlimit = "0.2.1" diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 153e680794328..68e3edcdf4f3d 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -49,14 +49,15 @@ use structopt::{ #[doc(hidden)] pub use tracing; use tracing_subscriber::{ - filter::Directive, fmt::time::ChronoLocal, layer::SubscriberExt, FmtSubscriber, Layer, fmt::Formatter, reload::Handle, EnvFilter + fmt::time::ChronoLocal, + EnvFilter, + FmtSubscriber, + Layer, + layer::SubscriberExt, }; pub use sc_tracing::logging; pub use logging::PREFIX_LOG_SPAN; -use tracing_subscriber::layer::Layered; -use crate::logging::{NodeNameLayer, EventFormat}; -use tracing_subscriber::fmt::format::DefaultFields; /// Substrate client CLI /// @@ -317,22 +318,22 @@ pub fn init_logger( let subscriber_builder = FmtSubscriber::builder() .with_env_filter(env_filter) + .with_writer(std::io::stderr as _) + .event_format(logging::EventFormat { + timer, + ansi: enable_color, + display_target: !simple, + display_level: !simple, + display_thread_name: !simple, + }) // TODO: Q - There's a small cost to this, do we make it opt-in/out with cli flag? .with_filter_reloading(); let handle = subscriber_builder.reload_handle(); let subscriber = subscriber_builder - // TODO: re-enable this - // .with_writer(std::io::stderr) - // .event_format(logging::EventFormat { - // timer, - // ansi: enable_color, - // display_target: !simple, - // display_level: !simple, - // display_thread_name: !simple, - // }) .finish() .with(logging::NodeNameLayer); - sc_tracing::set_reload_handle(handle); + + sc_tracing::set_reload_handle(handle); if let Some(profiling_targets) = profiling_targets { let profiling = sc_tracing::ProfilingLayer::new(tracing_receiver, &profiling_targets); diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 2749383ebd2a6..fcc567d5e7d10 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -38,21 +38,35 @@ use tracing::{ span::{Attributes, Id, Record}, subscriber::Subscriber, }; -use tracing_subscriber::{CurrentSpan, layer::{Layer, Context}, EnvFilter}; +use tracing_subscriber::{ + fmt::time::ChronoLocal, + CurrentSpan, + EnvFilter, + layer::{self, Layer, Context}, + fmt as tracing_fmt, + Registry, +}; use sc_telemetry::{telemetry, SUBSTRATE_INFO}; use sp_tracing::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER}; use tracing_subscriber::reload::Handle; -use tracing_subscriber::fmt::Formatter; use once_cell::sync::OnceCell; use tracing_subscriber::filter::Directive; const ZERO_DURATION: Duration = Duration::from_nanos(0); -static FILTER_RELOAD_HANDLE: OnceCell> = OnceCell::new(); +// The layered Subscriber as built up in `init_logger()`. +// Used in the reload `Handle`. +type SCSubscriber< + N = tracing_fmt::format::DefaultFields, + E = logging::EventFormat, + W = fn() -> std::io::Stderr +> = layer::Layered, Registry>; + +static FILTER_RELOAD_HANDLE: OnceCell> = OnceCell::new(); /// Initialize FILTER_RELOAD_HANDLE, only possible once -pub fn set_reload_handle(handle: Handle) { +pub fn set_reload_handle(handle: Handle) { let _ = FILTER_RELOAD_HANDLE.set(handle); } From 7960ebb8d879656599688cc151002681604888d1 Mon Sep 17 00:00:00 2001 From: David Palm Date: Wed, 4 Nov 2020 14:26:21 +0100 Subject: [PATCH 08/50] Remove duplicate code --- primitives/tracing/src/logging.rs | 268 ------------------------------ 1 file changed, 268 deletions(-) delete mode 100644 primitives/tracing/src/logging.rs diff --git a/primitives/tracing/src/logging.rs b/primitives/tracing/src/logging.rs deleted file mode 100644 index e29e13e28dae7..0000000000000 --- a/primitives/tracing/src/logging.rs +++ /dev/null @@ -1,268 +0,0 @@ -// 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 std::fmt; -use tracing::{span::Attributes, Event, Id, Level, Subscriber}; -use tracing_log::NormalizeEvent; -use tracing_subscriber::{ - fmt::{ - time::{FormatTime, SystemTime}, - FmtContext, FormatEvent, FormatFields, - }, - layer::Context, - registry::LookupSpan, - Layer, -}; - -/// Span name used for the logging prefix. See macro `sc_cli::prefix_logs_with!` -pub const PREFIX_LOG_SPAN: &str = "substrate-log-prefix"; - -pub struct EventFormat { - pub(crate) timer: T, - pub(crate) ansi: bool, - pub(crate) display_target: bool, - pub(crate) display_level: bool, - pub(crate) display_thread_name: bool, -} - -// NOTE: the following code took inspiration from tracing-subscriber -// -// https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/format/mod.rs#L449 -impl FormatEvent for EventFormat -where - S: Subscriber + for<'a> LookupSpan<'a>, - N: for<'a> FormatFields<'a> + 'static, - T: FormatTime, -{ - fn format_event( - &self, - ctx: &FmtContext, - writer: &mut dyn fmt::Write, - event: &Event, - ) -> fmt::Result { - let normalized_meta = event.normalized_metadata(); - let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata()); - time::write(&self.timer, writer, self.ansi)?; - - if self.display_level { - let fmt_level = { FmtLevel::new(meta.level(), self.ansi) }; - write!(writer, "{} ", fmt_level)?; - } - - if self.display_thread_name { - let current_thread = std::thread::current(); - match current_thread.name() { - Some(name) => { - write!(writer, "{} ", FmtThreadName::new(name))?; - } - // fall-back to thread id when name is absent and ids are not enabled - None => { - write!(writer, "{:0>2?} ", current_thread.id())?; - } - } - } - - // Custom code to display node name - if let Some(span) = ctx.lookup_current() { - let parents = span.parents(); - for span in std::iter::once(span).chain(parents) { - let exts = span.extensions(); - if let Some(node_name) = exts.get::() { - write!(writer, "{}", node_name.as_str())?; - break; - } - } - } - - if self.display_target { - write!(writer, "{}:", meta.target())?; - } - ctx.format_fields(writer, event)?; - writeln!(writer) - } -} - -pub(crate) struct NodeNameLayer; - -impl Layer for NodeNameLayer -where - S: Subscriber + for<'a> LookupSpan<'a>, -{ - fn new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { - let span = ctx - .span(id) - .expect("new_span has been called for this span; qed"); - - if span.name() != PREFIX_LOG_SPAN { - return; - } - - let mut extensions = span.extensions_mut(); - - if extensions.get_mut::().is_none() { - let mut s = String::new(); - let mut v = NodeNameVisitor(&mut s); - attrs.record(&mut v); - - if !s.is_empty() { - let fmt_fields = NodeName(s); - extensions.insert(fmt_fields); - } - } - } -} - -struct NodeNameVisitor<'a, W: std::fmt::Write>(&'a mut W); - -macro_rules! write_node_name { - ($method:ident, $type:ty, $format:expr) => { - fn $method(&mut self, field: &tracing::field::Field, value: $type) { - if field.name() == "name" { - write!(self.0, $format, value).expect("no way to return the err; qed"); - } - } - }; -} - -impl<'a, W: std::fmt::Write> tracing::field::Visit for NodeNameVisitor<'a, W> { - write_node_name!(record_debug, &dyn std::fmt::Debug, "[{:?}] "); - write_node_name!(record_str, &str, "[{}] "); - write_node_name!(record_i64, i64, "[{}] "); - write_node_name!(record_u64, u64, "[{}] "); - write_node_name!(record_bool, bool, "[{}] "); -} - -#[derive(Debug)] -struct NodeName(String); - -impl NodeName { - fn as_str(&self) -> &str { - self.0.as_str() - } -} - -struct FmtLevel<'a> { - level: &'a Level, - ansi: bool, -} - -impl<'a> FmtLevel<'a> { - pub(crate) fn new(level: &'a Level, ansi: bool) -> Self { - Self { level, ansi } - } -} - -const TRACE_STR: &str = "TRACE"; -const DEBUG_STR: &str = "DEBUG"; -const INFO_STR: &str = " INFO"; -const WARN_STR: &str = " WARN"; -const ERROR_STR: &str = "ERROR"; - -impl<'a> fmt::Display for FmtLevel<'a> { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - if self.ansi { - match *self.level { - Level::TRACE => write!(f, "{}", Colour::Purple.paint(TRACE_STR)), - Level::DEBUG => write!(f, "{}", Colour::Blue.paint(DEBUG_STR)), - Level::INFO => write!(f, "{}", Colour::Green.paint(INFO_STR)), - Level::WARN => write!(f, "{}", Colour::Yellow.paint(WARN_STR)), - Level::ERROR => write!(f, "{}", Colour::Red.paint(ERROR_STR)), - } - } else { - match *self.level { - Level::TRACE => f.pad(TRACE_STR), - Level::DEBUG => f.pad(DEBUG_STR), - Level::INFO => f.pad(INFO_STR), - Level::WARN => f.pad(WARN_STR), - Level::ERROR => f.pad(ERROR_STR), - } - } - } -} - -struct FmtThreadName<'a> { - name: &'a str, -} - -impl<'a> FmtThreadName<'a> { - pub(crate) fn new(name: &'a str) -> Self { - Self { name } - } -} - -// NOTE: the following code has been duplicated from tracing-subscriber -// -// https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/format/mod.rs#L845 -impl<'a> fmt::Display for FmtThreadName<'a> { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - use std::sync::atomic::{ - AtomicUsize, - Ordering::{AcqRel, Acquire, Relaxed}, - }; - - // Track the longest thread name length we've seen so far in an atomic, - // so that it can be updated by any thread. - static MAX_LEN: AtomicUsize = AtomicUsize::new(0); - let len = self.name.len(); - // Snapshot the current max thread name length. - let mut max_len = MAX_LEN.load(Relaxed); - - while len > max_len { - // Try to set a new max length, if it is still the value we took a - // snapshot of. - match MAX_LEN.compare_exchange(max_len, len, AcqRel, Acquire) { - // We successfully set the new max value - Ok(_) => break, - // Another thread set a new max value since we last observed - // it! It's possible that the new length is actually longer than - // ours, so we'll loop again and check whether our length is - // still the longest. If not, we'll just use the newer value. - Err(actual) => max_len = actual, - } - } - - // pad thread name using `max_len` - write!(f, "{:>width$}", self.name, width = max_len) - } -} - -// NOTE: the following code has been duplicated from tracing-subscriber -// -// https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/time/mod.rs#L252 -mod time { - use ansi_term::Style; - use std::fmt; - use tracing_subscriber::fmt::time::FormatTime; - - pub(crate) fn write(timer: T, writer: &mut dyn fmt::Write, with_ansi: bool) -> fmt::Result - where - T: FormatTime, - { - if with_ansi { - let style = Style::new().dimmed(); - write!(writer, "{}", style.prefix())?; - timer.format_time(writer)?; - write!(writer, "{}", style.suffix())?; - } else { - timer.format_time(writer)?; - } - writer.write_char(' ')?; - Ok(()) - } -} From 8ca1301493e9bc350b4ab4fa3dfb8de348b0ddf5 Mon Sep 17 00:00:00 2001 From: David Palm Date: Wed, 4 Nov 2020 14:28:24 +0100 Subject: [PATCH 09/50] cleanup --- client/cli/src/lib.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 68e3edcdf4f3d..0b2e99e831eb4 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -50,7 +50,6 @@ use structopt::{ pub use tracing; use tracing_subscriber::{ fmt::time::ChronoLocal, - EnvFilter, FmtSubscriber, Layer, layer::SubscriberExt, @@ -257,7 +256,7 @@ pub fn init_logger( )) } - let mut env_filter: EnvFilter = tracing_subscriber::EnvFilter::default() + 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")) @@ -316,6 +315,7 @@ pub fn init_logger( "%Y-%m-%d %H:%M:%S%.3f".to_string() }); + let subscriber_builder = FmtSubscriber::builder() .with_env_filter(env_filter) .with_writer(std::io::stderr as _) From 2b11d455317a06267da832b357377fff2b738622 Mon Sep 17 00:00:00 2001 From: David Palm Date: Sun, 8 Nov 2020 17:38:56 +0100 Subject: [PATCH 10/50] unneeded lvar --- client/cli/src/lib.rs | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 0b2e99e831eb4..74f3c40a0ec86 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -308,20 +308,18 @@ pub fn init_logger( } let isatty = atty::is(atty::Stream::Stderr); - let enable_color = isatty; let timer = ChronoLocal::with_format(if simple { "%Y-%m-%d %H:%M:%S".to_string() } else { "%Y-%m-%d %H:%M:%S%.3f".to_string() }); - let subscriber_builder = FmtSubscriber::builder() .with_env_filter(env_filter) .with_writer(std::io::stderr as _) .event_format(logging::EventFormat { timer, - ansi: enable_color, + ansi: isatty, display_target: !simple, display_level: !simple, display_thread_name: !simple, From 14062071906f5cbfd1996a9a1ead393f4868bb35 Mon Sep 17 00:00:00 2001 From: David Palm Date: Mon, 9 Nov 2020 16:09:33 +0100 Subject: [PATCH 11/50] Bump to latest patch release --- Cargo.lock | 4 ++-- client/cli/Cargo.toml | 2 +- client/cli/src/lib.rs | 1 - client/executor/Cargo.toml | 2 +- client/tracing/Cargo.toml | 2 +- 5 files changed, 5 insertions(+), 6 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 399923172eec2..ce7344ba8a18e 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -9728,9 +9728,9 @@ dependencies = [ [[package]] name = "tracing-subscriber" -version = "0.2.14" +version = "0.2.15" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "2810660b9d5b18895d140caba6401765749a6a162e5d0736cfc44ea50db9d79d" +checksum = "a1fa8f0c8f4c594e4fc9debc1990deab13238077271ba84dd853d54902ee3401" dependencies = [ "ansi_term 0.12.1", "chrono", diff --git a/client/cli/Cargo.toml b/client/cli/Cargo.toml index d9e9b9c415218..b368f35a4230b 100644 --- a/client/cli/Cargo.toml +++ b/client/cli/Cargo.toml @@ -45,7 +45,7 @@ chrono = "0.4.10" serde = "1.0.111" tracing = "0.1.21" tracing-log = "0.1.1" -tracing-subscriber = "0.2.14" +tracing-subscriber = "0.2.15" sc-cli-proc-macro = { version = "2.0.0", path = "./proc-macro" } thiserror = "1.0.21" diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 74f3c40a0ec86..8eab3d794aa01 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -324,7 +324,6 @@ pub fn init_logger( display_level: !simple, display_thread_name: !simple, }) - // TODO: Q - There's a small cost to this, do we make it opt-in/out with cli flag? .with_filter_reloading(); let handle = subscriber_builder.reload_handle(); let subscriber = subscriber_builder diff --git a/client/executor/Cargo.toml b/client/executor/Cargo.toml index b88e8926be141..f936fbd42e683 100644 --- a/client/executor/Cargo.toml +++ b/client/executor/Cargo.toml @@ -49,7 +49,7 @@ sp-runtime = { version = "2.0.0", path = "../../primitives/runtime" } sp-tracing = { version = "2.0.0", path = "../../primitives/tracing" } sc-tracing = { version = "2.0.0", path = "../tracing" } tracing = "0.1.19" -tracing-subscriber = "0.2.10" +tracing-subscriber = "0.2.15" [features] default = [ "std" ] diff --git a/client/tracing/Cargo.toml b/client/tracing/Cargo.toml index 5fd45eb839a53..ea4e90133b4aa 100644 --- a/client/tracing/Cargo.toml +++ b/client/tracing/Cargo.toml @@ -25,6 +25,6 @@ serde_json = "1.0.41" slog = { version = "2.5.2", features = ["nested-values"] } tracing = "0.1.21" tracing-core = "0.1.17" -tracing-subscriber = "0.2.14" +tracing-subscriber = "0.2.15" sp-tracing = { version = "2.0.0", path = "../../primitives/tracing" } sc-telemetry = { version = "2.0.0", path = "../telemetry" } From 2d8dfa08398841daa8cc6dca93d240cb16138db0 Mon Sep 17 00:00:00 2001 From: Matt Date: Mon, 9 Nov 2020 20:25:39 +0000 Subject: [PATCH 12/50] Add new CLI option to disable log filter reloading, Move profiling CLI options to SharedParams --- client/cli/src/config.rs | 27 +++++++++++------ client/cli/src/lib.rs | 42 +++++++++++++++++--------- client/cli/src/params/import_params.rs | 25 +-------------- client/cli/src/params/shared_params.rs | 33 ++++++++++++++++++++ client/service/src/config.rs | 2 ++ client/service/test/src/lib.rs | 1 + client/tracing/src/lib.rs | 2 +- utils/browser/src/lib.rs | 1 + 8 files changed, 84 insertions(+), 49 deletions(-) diff --git a/client/cli/src/config.rs b/client/cli/src/config.rs index ab7a335c1ce64..e76f3ad0aef3a 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -408,22 +408,18 @@ pub trait CliConfiguration: Sized { /// Get the tracing targets from the current object (if any) /// - /// By default this is retrieved from `ImportParams` if it is available. Otherwise its + /// By default this is retrieved from `SharedParams` if it is available. Otherwise its /// `None`. fn tracing_targets(&self) -> Result> { - Ok(self.import_params() - .map(|x| x.tracing_targets()) - .unwrap_or_else(|| Default::default())) + Ok(self.shared_params().tracing_targets()) } /// Get the TracingReceiver value from the current object /// - /// By default this is retrieved from `ImportParams` if it is available. Otherwise its + /// By default this is retrieved from `SharedParams` if it is available. Otherwise its /// `TracingReceiver::default()`. fn tracing_receiver(&self) -> Result { - Ok(self.import_params() - .map(|x| x.tracing_receiver()) - .unwrap_or_default()) + Ok(self.shared_params().tracing_receiver()) } /// Get the node key from the current object @@ -519,6 +515,7 @@ pub trait CliConfiguration: Sized { dev_key_seed: self.dev_key_seed(is_dev)?, tracing_targets: self.tracing_targets()?, tracing_receiver: self.tracing_receiver()?, + log_reloading_disabled: self.is_log_filter_reloading_disabled()?, chain_spec, max_runtime_instances, announce_block: self.announce_block()?, @@ -538,6 +535,12 @@ pub trait CliConfiguration: Sized { Ok(self.shared_params().log_filters().join(",")) } + + /// Is log reloading disabled + fn is_log_filter_reloading_disabled(&self) -> Result { + Ok(self.shared_params().is_log_filter_reloading_disabled()) + } + /// Initialize substrate. This must be done only once per process. /// /// This method: @@ -549,10 +552,16 @@ pub trait CliConfiguration: Sized { let logger_pattern = self.log_filters()?; let tracing_receiver = self.tracing_receiver()?; let tracing_targets = self.tracing_targets()?; + let disable_log_reloading = self.is_log_filter_reloading_disabled().unwrap_or_default(); sp_panic_handler::set(&C::support_url(), &C::impl_version()); - if let Err(e) = init_logger(&logger_pattern, tracing_receiver, tracing_targets) { + if let Err(e) = init_logger( + &logger_pattern, + tracing_receiver, + tracing_targets, + disable_log_reloading + ) { log::warn!("💬 Problem initializing global logging framework: {:}", e) } diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 74f3c40a0ec86..9c7bd0b508147 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -48,12 +48,7 @@ use structopt::{ }; #[doc(hidden)] pub use tracing; -use tracing_subscriber::{ - fmt::time::ChronoLocal, - FmtSubscriber, - Layer, - layer::SubscriberExt, -}; +use tracing_subscriber::{fmt::time::ChronoLocal, FmtSubscriber, Layer, layer::SubscriberExt}; pub use sc_tracing::logging; pub use logging::PREFIX_LOG_SPAN; @@ -246,6 +241,7 @@ pub fn init_logger( pattern: &str, tracing_receiver: sc_tracing::TracingReceiver, profiling_targets: Option, + disable_log_reloading: bool, ) -> std::result::Result<(), String> { use sc_tracing::parse_directives; @@ -323,15 +319,31 @@ pub fn init_logger( display_target: !simple, display_level: !simple, display_thread_name: !simple, - }) - // TODO: Q - There's a small cost to this, do we make it opt-in/out with cli flag? - .with_filter_reloading(); - let handle = subscriber_builder.reload_handle(); - let subscriber = subscriber_builder - .finish() - .with(logging::NodeNameLayer); - - sc_tracing::set_reload_handle(handle); + }); + if disable_log_reloading { + let subscriber = subscriber_builder + .finish() + .with(logging::NodeNameLayer); + initialize_tracing(subscriber, tracing_receiver, profiling_targets) + } else { + let subscriber_builder = subscriber_builder.with_filter_reloading(); + let handle = subscriber_builder.reload_handle(); + sc_tracing::set_reload_handle(handle); + let subscriber = subscriber_builder + .finish() + .with(logging::NodeNameLayer); + initialize_tracing(subscriber, tracing_receiver, profiling_targets) + } +} + +fn initialize_tracing( + subscriber: S, + tracing_receiver: sc_tracing::TracingReceiver, + profiling_targets: Option, +) -> std::result::Result<(), String> +where + S: tracing::Subscriber + Send + Sync + 'static, +{ if let Some(profiling_targets) = profiling_targets { let profiling = sc_tracing::ProfilingLayer::new(tracing_receiver, &profiling_targets); diff --git a/client/cli/src/params/import_params.rs b/client/cli/src/params/import_params.rs index 1efd4383432fb..376a72b8421f5 100644 --- a/client/cli/src/params/import_params.rs +++ b/client/cli/src/params/import_params.rs @@ -17,7 +17,7 @@ // along with this program. If not, see . use crate::arg_enums::{ - ExecutionStrategy, TracingReceiver, WasmExecutionMethod, DEFAULT_EXECUTION_BLOCK_CONSTRUCTION, + ExecutionStrategy, WasmExecutionMethod, DEFAULT_EXECUTION_BLOCK_CONSTRUCTION, DEFAULT_EXECUTION_IMPORT_BLOCK, DEFAULT_EXECUTION_IMPORT_BLOCK_VALIDATOR, DEFAULT_EXECUTION_OFFCHAIN_WORKER, DEFAULT_EXECUTION_OTHER, DEFAULT_EXECUTION_SYNCING, }; @@ -73,32 +73,9 @@ pub struct ImportParams { default_value = "67108864" )] pub state_cache_size: usize, - - /// Comma separated list of targets for tracing. - #[structopt(long = "tracing-targets", value_name = "TARGETS")] - pub tracing_targets: Option, - - /// Receiver to process tracing messages. - #[structopt( - long = "tracing-receiver", - value_name = "RECEIVER", - possible_values = &TracingReceiver::variants(), - case_insensitive = true, - default_value = "Log" - )] - pub tracing_receiver: TracingReceiver, } impl ImportParams { - /// Receiver to process tracing messages. - pub fn tracing_receiver(&self) -> sc_service::TracingReceiver { - self.tracing_receiver.clone().into() - } - - /// Comma separated list of targets for tracing. - pub fn tracing_targets(&self) -> Option { - self.tracing_targets.clone() - } /// Specify the state cache size. pub fn state_cache_size(&self) -> usize { diff --git a/client/cli/src/params/shared_params.rs b/client/cli/src/params/shared_params.rs index ad9ab04070563..f566415a514e1 100644 --- a/client/cli/src/params/shared_params.rs +++ b/client/cli/src/params/shared_params.rs @@ -19,6 +19,7 @@ use sc_service::config::BasePath; use std::path::PathBuf; use structopt::StructOpt; +use crate::arg_enums::TracingReceiver; /// Shared parameters used by all `CoreParams`. #[derive(Debug, StructOpt)] @@ -41,6 +42,24 @@ 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, + + /// Performance optimisation to disable setting the log filter at runtime. + #[structopt(long = "disable-log-reloading")] + pub disable_log_reloading: bool, + + /// Comma separated list of targets for tracing. + #[structopt(long = "tracing-targets", value_name = "TARGETS")] + pub tracing_targets: Option, + + /// Receiver to process tracing messages. + #[structopt( + long = "tracing-receiver", + value_name = "RECEIVER", + possible_values = &TracingReceiver::variants(), + case_insensitive = true, + default_value = "Log" + )] + pub tracing_receiver: TracingReceiver, } impl SharedParams { @@ -72,4 +91,18 @@ impl SharedParams { pub fn log_filters(&self) -> &[String] { &self.log } + + /// Is log reloading disabled + pub fn is_log_filter_reloading_disabled(&self) -> bool { + self.disable_log_reloading + } + /// Receiver to process tracing messages. + pub fn tracing_receiver(&self) -> sc_service::TracingReceiver { + self.tracing_receiver.clone().into() + } + + /// Comma separated list of targets for tracing. + pub fn tracing_targets(&self) -> Option { + self.tracing_targets.clone() + } } diff --git a/client/service/src/config.rs b/client/service/src/config.rs index 0caf05b2485db..04073a2592808 100644 --- a/client/service/src/config.rs +++ b/client/service/src/config.rs @@ -103,6 +103,8 @@ pub struct Configuration { pub dev_key_seed: Option, /// Tracing targets pub tracing_targets: Option, + /// Is log filter reloading disabled + pub log_reloading_disabled: bool, /// Tracing receiver pub tracing_receiver: sc_tracing::TracingReceiver, /// The size of the instances cache. diff --git a/client/service/test/src/lib.rs b/client/service/test/src/lib.rs index 8a9f0ace171d8..9df2866344e9f 100644 --- a/client/service/test/src/lib.rs +++ b/client/service/test/src/lib.rs @@ -274,6 +274,7 @@ fn node_config, W = fn() -> std::io::Stderr diff --git a/utils/browser/src/lib.rs b/utils/browser/src/lib.rs index 95ec7ca19c9a4..5cc22e9bbadb0 100644 --- a/utils/browser/src/lib.rs +++ b/utils/browser/src/lib.rs @@ -105,6 +105,7 @@ where informant_output_format: sc_informant::OutputFormat { enable_color: false, }, + log_reloading_disabled: false, }; Ok(config) From 65ad10d0e0793dfc018103a0b5d1d0b93d6e4c30 Mon Sep 17 00:00:00 2001 From: mattrutherford <44339188+mattrutherford@users.noreply.github.com> Date: Mon, 9 Nov 2020 23:42:56 +0000 Subject: [PATCH 13/50] Apply suggestions from code review MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Bastian Köcher --- client/cli/src/config.rs | 4 ++-- client/cli/src/params/shared_params.rs | 5 ++++- client/tracing/src/lib.rs | 1 + 3 files changed, 7 insertions(+), 3 deletions(-) diff --git a/client/cli/src/config.rs b/client/cli/src/config.rs index e76f3ad0aef3a..e2afd30620423 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -552,7 +552,7 @@ pub trait CliConfiguration: Sized { let logger_pattern = self.log_filters()?; let tracing_receiver = self.tracing_receiver()?; let tracing_targets = self.tracing_targets()?; - let disable_log_reloading = self.is_log_filter_reloading_disabled().unwrap_or_default(); + let disable_log_reloading = self.is_log_filter_reloading_disabled()?; sp_panic_handler::set(&C::support_url(), &C::impl_version()); @@ -560,7 +560,7 @@ pub trait CliConfiguration: Sized { &logger_pattern, tracing_receiver, tracing_targets, - disable_log_reloading + disable_log_reloading, ) { log::warn!("💬 Problem initializing global logging framework: {:}", e) } diff --git a/client/cli/src/params/shared_params.rs b/client/cli/src/params/shared_params.rs index f566415a514e1..0ac512653cc89 100644 --- a/client/cli/src/params/shared_params.rs +++ b/client/cli/src/params/shared_params.rs @@ -43,7 +43,9 @@ pub struct SharedParams { #[structopt(short = "l", long, value_name = "LOG_PATTERN")] pub log: Vec, - /// Performance optimisation to disable setting the log filter at runtime. + /// Disable log reloading at runtime. + /// + /// By default this feature is enabled, however it leads to a small performance decrease. #[structopt(long = "disable-log-reloading")] pub disable_log_reloading: bool, @@ -96,6 +98,7 @@ impl SharedParams { pub fn is_log_filter_reloading_disabled(&self) -> bool { self.disable_log_reloading } + /// Receiver to process tracing messages. pub fn tracing_receiver(&self) -> sc_service::TracingReceiver { self.tracing_receiver.clone().into() diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 7d04dd9246eac..aa0a88f246f6f 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -23,6 +23,7 @@ //! See `sp-tracing` for examples on how to use tracing. //! //! Currently we provide `Log` (default), `Telemetry` variants for `Receiver` + pub mod logging; use rustc_hash::FxHashMap; From d9a815a233ea222ca63797acc712ff95a014c42f Mon Sep 17 00:00:00 2001 From: Matt Date: Tue, 10 Nov 2020 12:05:17 +0000 Subject: [PATCH 14/50] Applied suggestions from reviews --- client/cli/src/config.rs | 2 +- client/cli/src/params/shared_params.rs | 12 ++++++------ client/rpc-api/src/system/mod.rs | 6 +++++- client/service/src/config.rs | 2 +- client/service/test/src/lib.rs | 2 +- client/tracing/src/lib.rs | 2 +- utils/browser/src/lib.rs | 2 +- 7 files changed, 16 insertions(+), 12 deletions(-) diff --git a/client/cli/src/config.rs b/client/cli/src/config.rs index e2afd30620423..c9282aa1d822d 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -515,7 +515,7 @@ pub trait CliConfiguration: Sized { dev_key_seed: self.dev_key_seed(is_dev)?, tracing_targets: self.tracing_targets()?, tracing_receiver: self.tracing_receiver()?, - log_reloading_disabled: self.is_log_filter_reloading_disabled()?, + disable_log_reloading: self.is_log_filter_reloading_disabled()?, chain_spec, max_runtime_instances, announce_block: self.announce_block()?, diff --git a/client/cli/src/params/shared_params.rs b/client/cli/src/params/shared_params.rs index 0ac512653cc89..8198515c0753f 100644 --- a/client/cli/src/params/shared_params.rs +++ b/client/cli/src/params/shared_params.rs @@ -49,17 +49,17 @@ pub struct SharedParams { #[structopt(long = "disable-log-reloading")] pub disable_log_reloading: bool, - /// Comma separated list of targets for tracing. + /// Sets a custom profiling filter. Syntax is the same as for logging: = #[structopt(long = "tracing-targets", value_name = "TARGETS")] pub tracing_targets: Option, /// Receiver to process tracing messages. #[structopt( - long = "tracing-receiver", - value_name = "RECEIVER", - possible_values = &TracingReceiver::variants(), - case_insensitive = true, - default_value = "Log" + long = "tracing-receiver", + value_name = "RECEIVER", + possible_values = &TracingReceiver::variants(), + case_insensitive = true, + default_value = "Log" )] pub tracing_receiver: TracingReceiver, } diff --git a/client/rpc-api/src/system/mod.rs b/client/rpc-api/src/system/mod.rs index 3ada7af0d0927..5a25261cb0a7d 100644 --- a/client/rpc-api/src/system/mod.rs +++ b/client/rpc-api/src/system/mod.rs @@ -109,7 +109,11 @@ pub trait SystemApi { #[rpc(name = "system_syncState", returns = "SyncState")] fn system_sync_state(&self) -> Receiver>; - /// Sets the logging filter, replacing current with the supplied directives + /// Sets the logging filter, replacing current with the supplied directives. + /// + /// The syntax is identical to the CLI: = + /// eg: + /// `sync=debug,state=trace` #[rpc(name = "system_setLogFilter", returns = "()")] fn system_set_log_filter(&self, directives: String) -> Result<(), jsonrpc_core::Error>; diff --git a/client/service/src/config.rs b/client/service/src/config.rs index 04073a2592808..20a4995bbc75c 100644 --- a/client/service/src/config.rs +++ b/client/service/src/config.rs @@ -104,7 +104,7 @@ pub struct Configuration { /// Tracing targets pub tracing_targets: Option, /// Is log filter reloading disabled - pub log_reloading_disabled: bool, + pub disable_log_reloading: bool, /// Tracing receiver pub tracing_receiver: sc_tracing::TracingReceiver, /// The size of the instances cache. diff --git a/client/service/test/src/lib.rs b/client/service/test/src/lib.rs index 9df2866344e9f..6d69adeef84e4 100644 --- a/client/service/test/src/lib.rs +++ b/client/service/test/src/lib.rs @@ -274,7 +274,7 @@ fn node_config, W = fn() -> std::io::Stderr diff --git a/utils/browser/src/lib.rs b/utils/browser/src/lib.rs index 5cc22e9bbadb0..bffd9fbedb28e 100644 --- a/utils/browser/src/lib.rs +++ b/utils/browser/src/lib.rs @@ -105,7 +105,7 @@ where informant_output_format: sc_informant::OutputFormat { enable_color: false, }, - log_reloading_disabled: false, + disable_log_reloading: false, }; Ok(config) From f2c57fb99b872e318d39fb22a42c6a6ca5c8d4ab Mon Sep 17 00:00:00 2001 From: David Palm Date: Wed, 11 Nov 2020 11:26:02 +0100 Subject: [PATCH 15/50] Fix calls to init_logger() --- client/cli/src/lib.rs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 82b598695ed15..f77cd43a65f10 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -377,7 +377,7 @@ mod tests { #[test] fn test_logger_filters() { let test_pattern = "afg=debug,sync=trace,client=warn,telemetry,something-with-dash=error"; - init_logger(&test_pattern, Default::default(), Default::default()).unwrap(); + init_logger(&test_pattern, Default::default(), Default::default(), false).unwrap(); tracing::dispatcher::get_default(|dispatcher| { let test_filter = |target, level| { @@ -436,7 +436,7 @@ mod tests { fn log_something_with_dash_target_name() { if env::var("ENABLE_LOGGING").is_ok() { let test_pattern = "test-target=info"; - init_logger(&test_pattern, Default::default(), Default::default()).unwrap(); + init_logger(&test_pattern, Default::default(), Default::default(), false).unwrap(); log::info!(target: "test-target", "{}", EXPECTED_LOG_MESSAGE); } @@ -472,7 +472,7 @@ mod tests { fn prefix_in_log_lines_entrypoint() { if env::var("ENABLE_LOGGING").is_ok() { let test_pattern = "test-target=info"; - init_logger(&test_pattern, Default::default(), Default::default()).unwrap(); + init_logger(&test_pattern, Default::default(), Default::default(), false).unwrap(); prefix_in_log_lines_process(); } } From 1906cc9a167b0eddd74bff7ac2a5be5ce5f069ca Mon Sep 17 00:00:00 2001 From: David Palm Date: Wed, 11 Nov 2020 12:23:39 +0100 Subject: [PATCH 16/50] Handle errors when parsing logging directives --- client/cli/src/lib.rs | 6 +++--- client/tracing/src/lib.rs | 11 +++++------ 2 files changed, 8 insertions(+), 9 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index f77cd43a65f10..4d869adf642d3 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -272,7 +272,7 @@ pub fn init_logger( if lvl != "" { // We're not sure if log or tracing is available at this moment, so silently ignore the // parse error. - for directive in parse_directives(lvl) { + for directive in parse_directives(lvl)? { env_filter = env_filter.add_directive(directive); } } @@ -281,7 +281,7 @@ pub fn init_logger( if pattern != "" { // We're not sure if log or tracing is available at this moment, so silently ignore the // parse error. - for directive in parse_directives(pattern) { + for directive in parse_directives(pattern)? { env_filter = env_filter.add_directive(directive); } } @@ -303,7 +303,7 @@ pub fn init_logger( // Make sure to include profiling targets in the filter if let Some(profiling_targets) = profiling_targets.clone() { - for directive in parse_directives(profiling_targets) { + for directive in parse_directives(profiling_targets)? { env_filter = env_filter.add_directive(directive); } } diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index f38480dc21f1d..1b8e6321a5a6a 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -74,7 +74,7 @@ pub fn set_reload_handle(handle: Handle) { /// Reload the logging filter with the supplied directives pub fn reload_filter(directives: String) -> Result<(), String> { let mut env_filter = tracing_subscriber::EnvFilter::default(); - for directive in parse_directives(directives) { + for directive in parse_directives(directives)? { env_filter = env_filter.add_directive(directive); } FILTER_RELOAD_HANDLE.get() @@ -82,12 +82,11 @@ pub fn reload_filter(directives: String) -> Result<(), String> { .reload(env_filter) .map_err(|e| format!("{}", e)) } - -/// Parse the supplied text directives into `Vec` -pub fn parse_directives(dirs: impl AsRef) -> Vec { - dirs.as_ref() +/// Parse the supplied text directives into a vector of `Directive`s. +pub fn parse_directives(directives: impl AsRef) -> Result, String> { + directives.as_ref() .split(',') - .filter_map(|s| s.parse().ok()) + .map(|d| d.parse().map_err(|e| format!("Unparseable logging directive '{}': {:?}", d, e))) .collect() } From 714eb48440f5d7c2eddb85e9f9dc3b0d558ce063 Mon Sep 17 00:00:00 2001 From: David Palm Date: Wed, 11 Nov 2020 12:38:29 +0100 Subject: [PATCH 17/50] Deny `system_setLogFilter` RPC by default --- client/rpc/src/system/mod.rs | 1 + 1 file changed, 1 insertion(+) diff --git a/client/rpc/src/system/mod.rs b/client/rpc/src/system/mod.rs index 46a4325e145b5..cd05ae689bb18 100644 --- a/client/rpc/src/system/mod.rs +++ b/client/rpc/src/system/mod.rs @@ -199,6 +199,7 @@ impl SystemApi::Number> for Sy } fn system_set_log_filter(&self, directives: String)-> std::result::Result<(), rpc::Error> { + bail_if_unsafe!(self.deny_unsafe); sc_tracing::reload_filter(directives).map_err(|_e| rpc::Error::internal_error()) } } From 3d7d458e3e9009b73368e06d910b5f3019b5853a Mon Sep 17 00:00:00 2001 From: David Palm Date: Wed, 11 Nov 2020 16:04:37 +0100 Subject: [PATCH 18/50] One more time --- client/rpc/src/system/mod.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/rpc/src/system/mod.rs b/client/rpc/src/system/mod.rs index cd05ae689bb18..8c03425ff37fb 100644 --- a/client/rpc/src/system/mod.rs +++ b/client/rpc/src/system/mod.rs @@ -199,7 +199,7 @@ impl SystemApi::Number> for Sy } fn system_set_log_filter(&self, directives: String)-> std::result::Result<(), rpc::Error> { - bail_if_unsafe!(self.deny_unsafe); + self.deny_unsafe.check_if_safe()?; sc_tracing::reload_filter(directives).map_err(|_e| rpc::Error::internal_error()) } } From d82a74a13d206c345900e07eec23f6e4e3631637 Mon Sep 17 00:00:00 2001 From: Matt Date: Wed, 18 Nov 2020 21:06:30 +0000 Subject: [PATCH 19/50] Don't ignore parse errors for log directives set via CLI or RPC --- client/cli/src/lib.rs | 39 +++++++++++++++++++++++++-------------- client/tracing/src/lib.rs | 33 +++++++++++++++++++++++---------- 2 files changed, 48 insertions(+), 24 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 82b598695ed15..973ed82bf2209 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -50,6 +50,7 @@ use structopt::{ pub use tracing; use tracing_subscriber::{ fmt::time::ChronoLocal, + EnvFilter, FmtSubscriber, Layer, layer::SubscriberExt, @@ -249,15 +250,13 @@ pub fn init_logger( disable_log_reloading: bool, ) -> std::result::Result<(), String> { - use sc_tracing::parse_directives; - if let Err(e) = tracing_log::LogTracer::init() { return Err(format!( "Registering Substrate logger failed: {:}!", e )) } - let mut env_filter = tracing_subscriber::EnvFilter::default() + let mut env_filter = 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")) @@ -270,20 +269,14 @@ pub fn init_logger( if let Ok(lvl) = std::env::var("RUST_LOG") { if lvl != "" { - // We're not sure if log or tracing is available at this moment, so silently ignore the - // parse error. - for directive in parse_directives(lvl) { - env_filter = env_filter.add_directive(directive); - } + env_filter = add_directives(env_filter, &lvl); } } if pattern != "" { // We're not sure if log or tracing is available at this moment, so silently ignore the // parse error. - for directive in parse_directives(pattern) { - env_filter = env_filter.add_directive(directive); - } + env_filter = add_directives(env_filter, pattern); } // If we're only logging `INFO` entries then we'll use a simplified logging format. @@ -303,9 +296,7 @@ pub fn init_logger( // Make sure to include profiling targets in the filter if let Some(profiling_targets) = profiling_targets.clone() { - for directive in parse_directives(profiling_targets) { - env_filter = env_filter.add_directive(directive); - } + env_filter = add_directives(env_filter, &profiling_targets); } let isatty = atty::is(atty::Stream::Stderr); @@ -341,6 +332,26 @@ pub fn init_logger( } } +fn add_directives(mut env_filter: EnvFilter, directives: &str) -> EnvFilter +{ + use sc_tracing::parse_directives; + + let (oks, errs): (Vec<_>, Vec<_>) = parse_directives(directives) + .into_iter() + .partition(|res| res.is_ok()); + for invalid_directive in errs { + eprintln!("Logging directive not valid: {}", + invalid_directive.expect_err("Already partitioned into Result::Err; qed") + ); + } + for directive in oks { + env_filter = env_filter.add_directive( + directive.expect("Already partitioned into Result::Ok; qed") + ); + } + env_filter +} + fn initialize_tracing( subscriber: S, tracing_receiver: sc_tracing::TracingReceiver, diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index f38480dc21f1d..6088faca409ac 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -73,21 +73,34 @@ pub fn set_reload_handle(handle: Handle) { /// Reload the logging filter with the supplied directives pub fn reload_filter(directives: String) -> Result<(), String> { + log::info!("Setting log filter"); let mut env_filter = tracing_subscriber::EnvFilter::default(); - for directive in parse_directives(directives) { - env_filter = env_filter.add_directive(directive); + for directive in parse_directives(&directives) { + match directive { + Ok(d) => env_filter = env_filter.add_directive(d), + Err(invalid_directive) => { + log::warn!("Unable to parse directive while setting log filter: {:?}", invalid_directive); + } + } } + env_filter = env_filter.add_directive( + "sc_tracing=trace" + .parse() + .expect("provided directive is valid"), + ); FILTER_RELOAD_HANDLE.get() .ok_or("No reload handle present".to_string())? .reload(env_filter) .map_err(|e| format!("{}", e)) } -/// Parse the supplied text directives into `Vec` -pub fn parse_directives(dirs: impl AsRef) -> Vec { - dirs.as_ref() - .split(',') - .filter_map(|s| s.parse().ok()) +/// Parse the supplied text directives into `Vec>`, +/// with a `Result::Ok` containing the parsed `Directive` +/// or a `Result::Err` containing the `String` that failed to parse +pub fn parse_directives(dirs: &str) -> Vec> { + dirs.split(',') + .into_iter() + .map(|d| d.parse().map_err(|_| d.to_owned())) .collect() } @@ -280,14 +293,14 @@ impl ProfilingLayer { /// or without: "pallet" in which case the level defaults to `trace`. /// wasm_tracing indicates whether to enable wasm traces pub fn new_with_handler(trace_handler: Box, targets: &str) - -> Self + -> Self { let targets: Vec<_> = targets.split(',').map(|s| parse_target(s)).collect(); Self { targets, trace_handler, span_data: Mutex::new(FxHashMap::default()), - current_span: Default::default() + current_span: Default::default(), } } @@ -509,7 +522,7 @@ mod tests { }; let layer = ProfilingLayer::new_with_handler( Box::new(handler), - "test_target" + "test_target", ); let subscriber = tracing_subscriber::fmt().finish().with(layer); (subscriber, spans, events) From ae4a0ac11294b2fbe6af928a2871198b0d104131 Mon Sep 17 00:00:00 2001 From: Matt Date: Wed, 18 Nov 2020 21:19:33 +0000 Subject: [PATCH 20/50] Improve docs --- client/cli/src/config.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/cli/src/config.rs b/client/cli/src/config.rs index c9282aa1d822d..f032797d9e632 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -536,7 +536,7 @@ pub trait CliConfiguration: Sized { } - /// Is log reloading disabled + /// Is log reloading disabled (enabled by default) fn is_log_filter_reloading_disabled(&self) -> Result { Ok(self.shared_params().is_log_filter_reloading_disabled()) } From f81577f1ed188c97d1682a5c4f546ddb34d22287 Mon Sep 17 00:00:00 2001 From: mattrutherford <44339188+mattrutherford@users.noreply.github.com> Date: Wed, 18 Nov 2020 21:24:09 +0000 Subject: [PATCH 21/50] Apply suggestions from code review MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Bastian Köcher --- client/cli/src/config.rs | 3 +-- client/cli/src/lib.rs | 3 +-- client/rpc-api/src/system/mod.rs | 4 ++-- 3 files changed, 4 insertions(+), 6 deletions(-) diff --git a/client/cli/src/config.rs b/client/cli/src/config.rs index f032797d9e632..cd4fd5384414f 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -416,7 +416,7 @@ pub trait CliConfiguration: Sized { /// Get the TracingReceiver value from the current object /// - /// By default this is retrieved from `SharedParams` if it is available. Otherwise its + /// By default this is retrieved from [`SharedParams`] if it is available. Otherwise its /// `TracingReceiver::default()`. fn tracing_receiver(&self) -> Result { Ok(self.shared_params().tracing_receiver()) @@ -535,7 +535,6 @@ pub trait CliConfiguration: Sized { Ok(self.shared_params().log_filters().join(",")) } - /// Is log reloading disabled (enabled by default) fn is_log_filter_reloading_disabled(&self) -> Result { Ok(self.shared_params().is_log_filter_reloading_disabled()) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 7515757578027..4d04001f46967 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -248,8 +248,7 @@ pub fn init_logger( tracing_receiver: sc_tracing::TracingReceiver, profiling_targets: Option, disable_log_reloading: bool, -) -> std::result::Result<(), String> -{ +) -> std::result::Result<(), String> { if let Err(e) = tracing_log::LogTracer::init() { return Err(format!( "Registering Substrate logger failed: {:}!", e diff --git a/client/rpc-api/src/system/mod.rs b/client/rpc-api/src/system/mod.rs index 5a25261cb0a7d..f7a505a4961bc 100644 --- a/client/rpc-api/src/system/mod.rs +++ b/client/rpc-api/src/system/mod.rs @@ -111,8 +111,8 @@ pub trait SystemApi { /// Sets the logging filter, replacing current with the supplied directives. /// - /// The syntax is identical to the CLI: = - /// eg: + /// The syntax is identical to the CLI `=`: + /// /// `sync=debug,state=trace` #[rpc(name = "system_setLogFilter", returns = "()")] fn system_set_log_filter(&self, directives: String) From b18002dba19b4d54390578ba93232f0095d4e39b Mon Sep 17 00:00:00 2001 From: mattrutherford <44339188+mattrutherford@users.noreply.github.com> Date: Wed, 18 Nov 2020 21:24:30 +0000 Subject: [PATCH 22/50] Update client/cli/src/config.rs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Bastian Köcher --- client/cli/src/config.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/cli/src/config.rs b/client/cli/src/config.rs index cd4fd5384414f..068a9af4ce4fb 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -408,7 +408,7 @@ pub trait CliConfiguration: Sized { /// Get the tracing targets from the current object (if any) /// - /// By default this is retrieved from `SharedParams` if it is available. Otherwise its + /// By default this is retrieved from [`SharedParams`] if it is available. Otherwise its /// `None`. fn tracing_targets(&self) -> Result> { Ok(self.shared_params().tracing_targets()) From 1e8b115587674b700926b410c5fe1e546f264b58 Mon Sep 17 00:00:00 2001 From: Matt Date: Thu, 19 Nov 2020 09:55:17 +0000 Subject: [PATCH 23/50] fix merge errors --- Cargo.lock | 4 ++-- client/cli/Cargo.toml | 2 -- client/cli/src/lib.rs | 4 ++-- client/tracing/Cargo.toml | 2 ++ 4 files changed, 6 insertions(+), 6 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 58fc5bd910340..0a04894c9a70a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6504,13 +6504,11 @@ dependencies = [ name = "sc-cli" version = "0.8.0" dependencies = [ - "ansi_term 0.12.1", "atty", "chrono", "fdlimit", "futures 0.3.5", "hex", - "lazy_static", "libp2p", "log", "names", @@ -7505,9 +7503,11 @@ version = "2.0.0" dependencies = [ "ansi_term 0.12.1", "erased-serde", + "lazy_static", "log", "once_cell", "parking_lot 0.10.2", + "regex", "rustc-hash", "sc-telemetry", "serde", diff --git a/client/cli/Cargo.toml b/client/cli/Cargo.toml index f3d130d0ff5db..5c16bb484877a 100644 --- a/client/cli/Cargo.toml +++ b/client/cli/Cargo.toml @@ -16,8 +16,6 @@ targets = ["x86_64-unknown-linux-gnu"] log = "0.4.11" atty = "0.2.13" regex = "1.4.2" -lazy_static = "1.4.0" -ansi_term = "0.12.1" tokio = { version = "0.2.21", features = [ "signal", "rt-core", "rt-threaded", "blocking" ] } futures = "0.3.4" fdlimit = "0.2.1" diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 13e224a2d3b4c..10a639a9316f9 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -299,7 +299,7 @@ pub fn init_logger( env_filter = add_directives(env_filter, &profiling_targets); } - let isatty = atty::is(atty::Stream::Stderr); + let enable_color = atty::is(atty::Stream::Stderr); let timer = ChronoLocal::with_format(if simple { "%Y-%m-%d %H:%M:%S".to_string() } else { @@ -311,7 +311,7 @@ pub fn init_logger( .with_writer(std::io::stderr as _) .event_format(logging::EventFormat { timer, - ansi: isatty, + enable_color, display_target: !simple, display_level: !simple, display_thread_name: !simple, diff --git a/client/tracing/Cargo.toml b/client/tracing/Cargo.toml index ea4e90133b4aa..f93f5d3edcffd 100644 --- a/client/tracing/Cargo.toml +++ b/client/tracing/Cargo.toml @@ -16,9 +16,11 @@ targets = ["x86_64-unknown-linux-gnu"] ansi_term = "0.12.1" tracing-log = "0.1.1" erased-serde = "0.3.9" +lazy_static = "1.4.0" log = { version = "0.4.8" } once_cell = "1.4.1" parking_lot = "0.10.0" +regex = "1.4.2" rustc-hash = "1.1.0" serde = "1.0.101" serde_json = "1.0.41" From dbd3a124b61e1ae2e383e284e7919c4881da85c2 Mon Sep 17 00:00:00 2001 From: Matt Date: Thu, 19 Nov 2020 12:46:22 +0000 Subject: [PATCH 24/50] include default directives with system_setLogFilter RPC, implement system_rawSetLogFilter RPC to exclude defaults --- client/cli/src/lib.rs | 32 +++++++++++++++----------------- client/rpc-api/src/system/mod.rs | 16 +++++++++++++++- client/rpc/src/system/mod.rs | 7 ++++++- client/tracing/src/lib.rs | 31 +++++++++++++++++++++++-------- 4 files changed, 59 insertions(+), 27 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 10a639a9316f9..07f7686f1ad84 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -256,17 +256,17 @@ pub fn init_logger( )) } + // Initialize filter - ensure to use `add_directives` so that the given directives are + // included as defaults. let mut env_filter = 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("cranelift_wasm=warn".parse().expect("provided directive is valid")) - .add_directive("hyper=warn".parse().expect("provided directive is valid")) - // Enable info for others. + // Enable info .add_directive(tracing_subscriber::filter::LevelFilter::INFO.into()); + // Disable info logging by default for some modules. + env_filter = add_directives(env_filter,"ws=off,yamux=off,cranelift_codegen=off"); + // Set warn logging by default for some modules. + env_filter = add_directives(env_filter,"cranelift_wasm=warn,hyper=warn"); + if let Ok(lvl) = std::env::var("RUST_LOG") { if lvl != "" { env_filter = add_directives(env_filter, &lvl); @@ -288,11 +288,8 @@ pub fn init_logger( // Always log the special target `sc_tracing`, overrides global level. // NOTE: this must be done after we check the `max_level_hint` otherwise // it is always raised to `TRACE`. - env_filter = env_filter.add_directive( - "sc_tracing=trace" - .parse() - .expect("provided directive is valid"), - ); + env_filter = add_directives(env_filter, "sc_tracing=trace"); + // Make sure to include profiling targets in the filter if let Some(profiling_targets) = profiling_targets.clone() { @@ -332,10 +329,10 @@ pub fn init_logger( } } -fn add_directives(mut env_filter: EnvFilter, directives: &str) -> EnvFilter -{ - use sc_tracing::parse_directives; - +// Adds default directives to ensure setLogFilter RPC functions correctly +fn add_directives(mut env_filter: EnvFilter, directives: &str) -> EnvFilter { + use sc_tracing::{parse_directives, add_default_directives}; + add_default_directives(directives); let (oks, errs): (Vec<_>, Vec<_>) = parse_directives(directives) .into_iter() .partition(|res| res.is_ok()); @@ -348,6 +345,7 @@ fn add_directives(mut env_filter: EnvFilter, directives: &str) -> EnvFilter env_filter = env_filter.add_directive( directive.expect("Already partitioned into Result::Ok; qed") ); + } env_filter } diff --git a/client/rpc-api/src/system/mod.rs b/client/rpc-api/src/system/mod.rs index 5a25261cb0a7d..0151df9a2b0d0 100644 --- a/client/rpc-api/src/system/mod.rs +++ b/client/rpc-api/src/system/mod.rs @@ -109,12 +109,26 @@ pub trait SystemApi { #[rpc(name = "system_syncState", returns = "SyncState")] fn system_sync_state(&self) -> Receiver>; - /// Sets the logging filter, replacing current with the supplied directives. + /// Sets the logging filter, adding the supplied directives to the defaults. /// /// The syntax is identical to the CLI: = /// eg: /// `sync=debug,state=trace` + /// + /// The default filters, including those provided to the CLI will be merged + /// with the directives given. #[rpc(name = "system_setLogFilter", returns = "()")] fn system_set_log_filter(&self, directives: String) -> Result<(), jsonrpc_core::Error>; + + /// Sets the logging filter with the supplied directives, excluding the defaults. + /// + /// The syntax is identical to the CLI: = + /// eg: + /// `sync=debug,state=trace` + /// + /// Only logs the directives given + #[rpc(name = "system_rawSetLogFilter", returns = "()")] + fn system_raw_set_log_filter(&self, directives: String) + -> Result<(), jsonrpc_core::Error>; } diff --git a/client/rpc/src/system/mod.rs b/client/rpc/src/system/mod.rs index 8c03425ff37fb..d501ed8d74079 100644 --- a/client/rpc/src/system/mod.rs +++ b/client/rpc/src/system/mod.rs @@ -200,6 +200,11 @@ impl SystemApi::Number> for Sy fn system_set_log_filter(&self, directives: String)-> std::result::Result<(), rpc::Error> { self.deny_unsafe.check_if_safe()?; - sc_tracing::reload_filter(directives).map_err(|_e| rpc::Error::internal_error()) + sc_tracing::reload_filter(directives, true).map_err(|_e| rpc::Error::internal_error()) + } + + fn system_raw_set_log_filter(&self, directives: String)-> std::result::Result<(), rpc::Error> { + self.deny_unsafe.check_if_safe()?; + sc_tracing::reload_filter(directives, false).map_err(|_e| rpc::Error::internal_error()) } } diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 6088faca409ac..412600fcf51c4 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -65,24 +65,27 @@ type SCSubscriber< > = layer::Layered, Registry>; static FILTER_RELOAD_HANDLE: OnceCell> = OnceCell::new(); +static DEFAULT_DIRECTIVES: OnceCell>> = OnceCell::new(); /// Initialize FILTER_RELOAD_HANDLE, only possible once pub fn set_reload_handle(handle: Handle) { let _ = FILTER_RELOAD_HANDLE.set(handle); } +pub fn add_default_directives(directive: &str) { + DEFAULT_DIRECTIVES.get_or_init(|| Mutex::new(Vec::new())).lock().push(directive.to_owned()); +} + /// Reload the logging filter with the supplied directives -pub fn reload_filter(directives: String) -> Result<(), String> { +pub fn reload_filter(directives: String, with_defaults: bool) -> Result<(), String> { log::info!("Setting log filter"); - let mut env_filter = tracing_subscriber::EnvFilter::default(); - for directive in parse_directives(&directives) { - match directive { - Ok(d) => env_filter = env_filter.add_directive(d), - Err(invalid_directive) => { - log::warn!("Unable to parse directive while setting log filter: {:?}", invalid_directive); - } + let mut env_filter = EnvFilter::default(); + if with_defaults { + if let Some(default_directives) = DEFAULT_DIRECTIVES.get() { + env_filter = add_directives(env_filter, default_directives.lock().join(",")); } } + env_filter = add_directives(env_filter, directives); env_filter = env_filter.add_directive( "sc_tracing=trace" .parse() @@ -94,6 +97,18 @@ pub fn reload_filter(directives: String) -> Result<(), String> { .map_err(|e| format!("{}", e)) } +fn add_directives(mut env_filter: EnvFilter, directives: String) -> EnvFilter { + for directive in parse_directives(&directives) { + match directive { + Ok(d) => env_filter = env_filter.add_directive(d), + Err(invalid_directive) => { + log::warn!("Unable to parse directive while setting log filter: {:?}", invalid_directive); + } + } + } + env_filter +} + /// Parse the supplied text directives into `Vec>`, /// with a `Result::Ok` containing the parsed `Directive` /// or a `Result::Err` containing the `String` that failed to parse From fd82f68832fc8743d4a2024c32211a6b0b409732 Mon Sep 17 00:00:00 2001 From: Matt Date: Thu, 19 Nov 2020 12:55:20 +0000 Subject: [PATCH 25/50] docs etc... --- client/tracing/src/lib.rs | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 412600fcf51c4..ea7254fb3c5cc 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -72,15 +72,20 @@ pub fn set_reload_handle(handle: Handle) { let _ = FILTER_RELOAD_HANDLE.set(handle); } +/// Add log filter directive(s) to the defaults +/// +/// The syntax is identical to the CLI `=`: +/// +/// `sync=debug,state=trace` pub fn add_default_directives(directive: &str) { DEFAULT_DIRECTIVES.get_or_init(|| Mutex::new(Vec::new())).lock().push(directive.to_owned()); } /// Reload the logging filter with the supplied directives -pub fn reload_filter(directives: String, with_defaults: bool) -> Result<(), String> { +pub fn reload_filter(directives: String, use_defaults: bool) -> Result<(), String> { log::info!("Setting log filter"); let mut env_filter = EnvFilter::default(); - if with_defaults { + if use_defaults { if let Some(default_directives) = DEFAULT_DIRECTIVES.get() { env_filter = add_directives(env_filter, default_directives.lock().join(",")); } From 89f615d9b5e7e808798901449453f2dceec79e85 Mon Sep 17 00:00:00 2001 From: Matt Date: Thu, 19 Nov 2020 13:08:09 +0000 Subject: [PATCH 26/50] update test --- Cargo.lock | 1 + client/cli/Cargo.toml | 1 + client/cli/src/lib.rs | 2 +- 3 files changed, 3 insertions(+), 1 deletion(-) diff --git a/Cargo.lock b/Cargo.lock index 0a04894c9a70a..60fd2b46b5cfb 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6504,6 +6504,7 @@ dependencies = [ name = "sc-cli" version = "0.8.0" dependencies = [ + "ansi_term 0.12.1", "atty", "chrono", "fdlimit", diff --git a/client/cli/Cargo.toml b/client/cli/Cargo.toml index 5c16bb484877a..e6c3448675a75 100644 --- a/client/cli/Cargo.toml +++ b/client/cli/Cargo.toml @@ -54,6 +54,7 @@ rpassword = "4.0.1" [dev-dependencies] tempfile = "3.1.0" +ansi_term = "0.12.1" [features] wasmtime = [ diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 1922dcd405e1a..3bf874440a330 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -496,7 +496,7 @@ mod tests { #[test] fn do_not_write_with_colors_on_tty_entrypoint() { if env::var("ENABLE_LOGGING").is_ok() { - init_logger("", Default::default(), Default::default()).unwrap(); + init_logger("", Default::default(), Default::default(), false).unwrap(); log::info!("{}", ansi_term::Colour::Yellow.paint(EXPECTED_LOG_MESSAGE)); } } From 65f58b748c385f08277f16554d5066525b232741 Mon Sep 17 00:00:00 2001 From: Matt Date: Thu, 19 Nov 2020 15:46:30 +0000 Subject: [PATCH 27/50] refactor: rename fn --- client/cli/src/lib.rs | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 3bf874440a330..4ee2e7ca0c2d5 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -262,20 +262,20 @@ pub fn init_logger( .add_directive(tracing_subscriber::filter::LevelFilter::INFO.into()); // Disable info logging by default for some modules. - env_filter = add_directives(env_filter,"ws=off,yamux=off,cranelift_codegen=off"); + env_filter = add_default_directives(env_filter, "ws=off,yamux=off,cranelift_codegen=off"); // Set warn logging by default for some modules. - env_filter = add_directives(env_filter,"cranelift_wasm=warn,hyper=warn"); + env_filter = add_default_directives(env_filter, "cranelift_wasm=warn,hyper=warn"); if let Ok(lvl) = std::env::var("RUST_LOG") { if lvl != "" { - env_filter = add_directives(env_filter, &lvl); + env_filter = add_default_directives(env_filter, &lvl); } } if pattern != "" { // We're not sure if log or tracing is available at this moment, so silently ignore the // parse error. - env_filter = add_directives(env_filter, pattern); + env_filter = add_default_directives(env_filter, pattern); } // If we're only logging `INFO` entries then we'll use a simplified logging format. @@ -287,12 +287,12 @@ pub fn init_logger( // Always log the special target `sc_tracing`, overrides global level. // NOTE: this must be done after we check the `max_level_hint` otherwise // it is always raised to `TRACE`. - env_filter = add_directives(env_filter, "sc_tracing=trace"); + env_filter = add_default_directives(env_filter, "sc_tracing=trace"); // Make sure to include profiling targets in the filter if let Some(profiling_targets) = profiling_targets.clone() { - env_filter = add_directives(env_filter, &profiling_targets); + env_filter = add_default_directives(env_filter, &profiling_targets); } let enable_color = atty::is(atty::Stream::Stderr); @@ -329,7 +329,7 @@ pub fn init_logger( } // Adds default directives to ensure setLogFilter RPC functions correctly -fn add_directives(mut env_filter: EnvFilter, directives: &str) -> EnvFilter { +fn add_default_directives(mut env_filter: EnvFilter, directives: &str) -> EnvFilter { use sc_tracing::{parse_directives, add_default_directives}; add_default_directives(directives); let (oks, errs): (Vec<_>, Vec<_>) = parse_directives(directives) From 4c51a081f35744379230b1cbdc79de6c0deb4be7 Mon Sep 17 00:00:00 2001 From: David Palm Date: Fri, 20 Nov 2020 11:20:12 +0100 Subject: [PATCH 28/50] =?UTF-8?q?Add=20a=20test=20for=20system=5Fset=5Flog?= =?UTF-8?q?=5Ffilter=20=E2=80=93=20NOTE:=20the=20code=20should=20likely=20?= =?UTF-8?q?change=20to=20return=20an=20error=20when=20bad=20directives=20a?= =?UTF-8?q?re=20passed?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- Cargo.lock | 1 + client/rpc/Cargo.toml | 1 + client/rpc/src/system/mod.rs | 2 +- client/rpc/src/system/tests.rs | 7 +++++++ 4 files changed, 10 insertions(+), 1 deletion(-) diff --git a/Cargo.lock b/Cargo.lock index 60fd2b46b5cfb..3cc210b252ea5 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -7261,6 +7261,7 @@ dependencies = [ "parity-scale-codec", "parking_lot 0.10.2", "sc-block-builder", + "sc-cli", "sc-client-api", "sc-executor", "sc-keystore", diff --git a/client/rpc/Cargo.toml b/client/rpc/Cargo.toml index 0254c47b305f0..e68ac6e4e918f 100644 --- a/client/rpc/Cargo.toml +++ b/client/rpc/Cargo.toml @@ -51,6 +51,7 @@ sp-io = { version = "2.0.0", path = "../../primitives/io" } substrate-test-runtime-client = { version = "2.0.0", path = "../../test-utils/runtime/client" } tokio = "0.1.22" sc-transaction-pool = { version = "2.0.0", path = "../transaction-pool" } +sc-cli = { version = "0.8.0", path = "../cli" } [features] test-helpers = ["lazy_static"] diff --git a/client/rpc/src/system/mod.rs b/client/rpc/src/system/mod.rs index d501ed8d74079..3ac94eefb17af 100644 --- a/client/rpc/src/system/mod.rs +++ b/client/rpc/src/system/mod.rs @@ -198,7 +198,7 @@ impl SystemApi::Number> for Sy Receiver(Compat::new(rx)) } - fn system_set_log_filter(&self, directives: String)-> std::result::Result<(), rpc::Error> { + fn system_set_log_filter(&self, directives: String) -> std::result::Result<(), rpc::Error> { self.deny_unsafe.check_if_safe()?; sc_tracing::reload_filter(directives, true).map_err(|_e| rpc::Error::internal_error()) } diff --git a/client/rpc/src/system/tests.rs b/client/rpc/src/system/tests.rs index 61f1940dc2010..50e467a7d879e 100644 --- a/client/rpc/src/system/tests.rs +++ b/client/rpc/src/system/tests.rs @@ -333,3 +333,10 @@ fn system_network_remove_reserved() { assert_eq!(runtime.block_on(good_fut), Ok(())); assert!(runtime.block_on(bad_fut).is_err()); } + +#[test] +fn system_set_log_filter() { + sc_cli::init_logger("afg=debug", Default::default(), Default::default(), false).unwrap(); + let res = api(None).system_set_log_filter("bla no ok -\\ /lba".into()); + assert_eq!(res, Ok(())); +} From 04e17860430dfd38cba2e777dd504bdf4e491c18 Mon Sep 17 00:00:00 2001 From: David Date: Tue, 24 Nov 2020 13:44:53 +0000 Subject: [PATCH 29/50] Update client/cli/src/lib.rs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Bastian Köcher --- client/cli/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 4ee2e7ca0c2d5..b48f181fe287a 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -353,7 +353,7 @@ fn initialize_tracing( subscriber: S, tracing_receiver: sc_tracing::TracingReceiver, profiling_targets: Option, -) -> std::result::Result<(), String> +) -> std::result::Result<(), String> where S: tracing::Subscriber + Send + Sync + 'static, { From c0996c5f0c51c131355e7cc3b1403f37853445c2 Mon Sep 17 00:00:00 2001 From: David Palm Date: Tue, 24 Nov 2020 15:07:09 +0100 Subject: [PATCH 30/50] Address review grumbles --- client/cli/src/lib.rs | 9 +++++---- client/tracing/src/lib.rs | 4 +--- 2 files changed, 6 insertions(+), 7 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 4ee2e7ca0c2d5..d148ec0d4769e 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -330,21 +330,22 @@ pub fn init_logger( // Adds default directives to ensure setLogFilter RPC functions correctly fn add_default_directives(mut env_filter: EnvFilter, directives: &str) -> EnvFilter { - use sc_tracing::{parse_directives, add_default_directives}; - add_default_directives(directives); - let (oks, errs): (Vec<_>, Vec<_>) = parse_directives(directives) + sc_tracing::add_default_directives(directives); + let (oks, errs): (Vec<_>, Vec<_>) = sc_tracing::parse_directives(directives) .into_iter() .partition(|res| res.is_ok()); + for invalid_directive in errs { eprintln!("Logging directive not valid: {}", invalid_directive.expect_err("Already partitioned into Result::Err; qed") ); + panic!("Invalid logging directives."); } + for directive in oks { env_filter = env_filter.add_directive( directive.expect("Already partitioned into Result::Ok; qed") ); - } env_filter } diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index ea7254fb3c5cc..03e3cb0298a40 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -312,9 +312,7 @@ impl ProfilingLayer { /// either with a level, eg: "pallet=trace" /// or without: "pallet" in which case the level defaults to `trace`. /// wasm_tracing indicates whether to enable wasm traces - pub fn new_with_handler(trace_handler: Box, targets: &str) - -> Self - { + pub fn new_with_handler(trace_handler: Box, targets: &str) -> Self { let targets: Vec<_> = targets.split(',').map(|s| parse_target(s)).collect(); Self { targets, From cd51835e63655bcebabbafbb5f03b5a57f8208e3 Mon Sep 17 00:00:00 2001 From: David Palm Date: Tue, 24 Nov 2020 15:15:19 +0100 Subject: [PATCH 31/50] Add doc note on panicking behaviour --- client/cli/src/lib.rs | 1 + 1 file changed, 1 insertion(+) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 61634b917cc11..0a0f9c1c78932 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -329,6 +329,7 @@ pub fn init_logger( } // Adds default directives to ensure setLogFilter RPC functions correctly +// Panics if any of the provided directives is invalid. fn add_default_directives(mut env_filter: EnvFilter, directives: &str) -> EnvFilter { sc_tracing::add_default_directives(directives); let (oks, errs): (Vec<_>, Vec<_>) = sc_tracing::parse_directives(directives) From f41b93f58773098d14813eb5a31e8f7faaaee7ca Mon Sep 17 00:00:00 2001 From: Matt Date: Tue, 24 Nov 2020 17:32:24 +0000 Subject: [PATCH 32/50] print all invalid directives before panic --- client/cli/src/lib.rs | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 0a0f9c1c78932..3722fb6984e2c 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -336,10 +336,12 @@ fn add_default_directives(mut env_filter: EnvFilter, directives: &str) -> EnvFil .into_iter() .partition(|res| res.is_ok()); - for invalid_directive in errs { - eprintln!("Logging directive not valid: {}", - invalid_directive.expect_err("Already partitioned into Result::Err; qed") - ); + if !errs.is_empty() { + for invalid_directive in errs { + eprintln!("Logging directive not valid: {}", + invalid_directive.expect_err("Already partitioned into Result::Err; qed") + ); + } panic!("Invalid logging directives."); } From 23938a4a11dbeba7ae9c16fe6a4636ec759e0a7a Mon Sep 17 00:00:00 2001 From: Matt Date: Tue, 24 Nov 2020 21:52:43 +0000 Subject: [PATCH 33/50] change RPCs to: addLogFilter and resetLogFilter --- client/cli/src/lib.rs | 29 +++++++++++++------------- client/rpc-api/src/system/mod.rs | 21 ++++++------------- client/rpc/src/system/mod.rs | 9 ++++---- client/tracing/src/lib.rs | 35 +++++++++++++++++++++----------- 4 files changed, 49 insertions(+), 45 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 3722fb6984e2c..419c45f672ef9 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -255,12 +255,11 @@ pub fn init_logger( )) } - // Initialize filter - ensure to use `add_directives` so that the given directives are - // included as defaults. - let mut env_filter = EnvFilter::default() - // Enable info - .add_directive(tracing_subscriber::filter::LevelFilter::INFO.into()); - + // Initialize filter - ensure to use `add_default_directives` for any defaults to persist + // after log filter reloading by RPC + let mut env_filter = EnvFilter::default(); + // Enable info + env_filter = add_default_directives(env_filter,"info"); // Disable info logging by default for some modules. env_filter = add_default_directives(env_filter, "ws=off,yamux=off,cranelift_codegen=off"); // Set warn logging by default for some modules. @@ -274,8 +273,8 @@ pub fn init_logger( if pattern != "" { // We're not sure if log or tracing is available at this moment, so silently ignore the - // parse error. - env_filter = add_default_directives(env_filter, pattern); + // parse error. Use add_directives to ensure RPC addLogFilter functions correctly. + env_filter = add_directives(env_filter, pattern); } // If we're only logging `INFO` entries then we'll use a simplified logging format. @@ -285,11 +284,11 @@ pub fn init_logger( }; // Always log the special target `sc_tracing`, overrides global level. + // Required because profiling traces are emitted via `sc_tracing` // NOTE: this must be done after we check the `max_level_hint` otherwise // it is always raised to `TRACE`. env_filter = add_default_directives(env_filter, "sc_tracing=trace"); - // Make sure to include profiling targets in the filter if let Some(profiling_targets) = profiling_targets.clone() { env_filter = add_default_directives(env_filter, &profiling_targets); @@ -329,13 +328,17 @@ pub fn init_logger( } // Adds default directives to ensure setLogFilter RPC functions correctly -// Panics if any of the provided directives is invalid. -fn add_default_directives(mut env_filter: EnvFilter, directives: &str) -> EnvFilter { +// Panics if any of the provided directives are invalid. +fn add_default_directives(env_filter: EnvFilter, directives: &str) -> EnvFilter { sc_tracing::add_default_directives(directives); + add_directives(env_filter, directives) +} + +// Panics if any of the provided directives are invalid. +fn add_directives(mut env_filter: EnvFilter, directives: &str) -> EnvFilter { let (oks, errs): (Vec<_>, Vec<_>) = sc_tracing::parse_directives(directives) .into_iter() .partition(|res| res.is_ok()); - if !errs.is_empty() { for invalid_directive in errs { eprintln!("Logging directive not valid: {}", @@ -344,7 +347,6 @@ fn add_default_directives(mut env_filter: EnvFilter, directives: &str) -> EnvFil } panic!("Invalid logging directives."); } - for directive in oks { env_filter = env_filter.add_directive( directive.expect("Already partitioned into Result::Ok; qed") @@ -363,7 +365,6 @@ where { if let Some(profiling_targets) = profiling_targets { let profiling = sc_tracing::ProfilingLayer::new(tracing_receiver, &profiling_targets); - if let Err(e) = tracing::subscriber::set_global_default(subscriber.with(profiling)) { return Err(format!( "Registering Substrate tracing subscriber failed: {:}!", e diff --git a/client/rpc-api/src/system/mod.rs b/client/rpc-api/src/system/mod.rs index c230c05672960..f05f1fada901e 100644 --- a/client/rpc-api/src/system/mod.rs +++ b/client/rpc-api/src/system/mod.rs @@ -109,26 +109,17 @@ pub trait SystemApi { #[rpc(name = "system_syncState", returns = "SyncState")] fn system_sync_state(&self) -> Receiver>; - /// Sets the logging filter, adding the supplied directives to the defaults. + /// Adds the supplied directives to the current log filter /// /// The syntax is identical to the CLI `=`: /// /// `sync=debug,state=trace` - /// - /// The default filters, including those provided to the CLI will be merged - /// with the directives given. - #[rpc(name = "system_setLogFilter", returns = "()")] - fn system_set_log_filter(&self, directives: String) + #[rpc(name = "system_addLogFilter", returns = "()")] + fn system_add_log_filter(&self, directives: String) -> Result<(), jsonrpc_core::Error>; - /// Sets the logging filter with the supplied directives, excluding the defaults. - /// - /// The syntax is identical to the CLI: = - /// eg: - /// `sync=debug,state=trace` - /// - /// Only logs the directives given - #[rpc(name = "system_rawSetLogFilter", returns = "()")] - fn system_raw_set_log_filter(&self, directives: String) + /// Resets the log filter to Substrate defaults + #[rpc(name = "system_resetLogFilter", returns = "()")] + fn system_reset_log_filter(&self) -> Result<(), jsonrpc_core::Error>; } diff --git a/client/rpc/src/system/mod.rs b/client/rpc/src/system/mod.rs index 3ac94eefb17af..f1ebf5f702a27 100644 --- a/client/rpc/src/system/mod.rs +++ b/client/rpc/src/system/mod.rs @@ -198,13 +198,14 @@ impl SystemApi::Number> for Sy Receiver(Compat::new(rx)) } - fn system_set_log_filter(&self, directives: String) -> std::result::Result<(), rpc::Error> { + fn system_add_log_filter(&self, directives: String) -> std::result::Result<(), rpc::Error> { self.deny_unsafe.check_if_safe()?; - sc_tracing::reload_filter(directives, true).map_err(|_e| rpc::Error::internal_error()) + sc_tracing::add_directives(&directives); + sc_tracing::reload_filter().map_err(|_e| rpc::Error::internal_error()) } - fn system_raw_set_log_filter(&self, directives: String)-> std::result::Result<(), rpc::Error> { + fn system_reset_log_filter(&self)-> std::result::Result<(), rpc::Error> { self.deny_unsafe.check_if_safe()?; - sc_tracing::reload_filter(directives, false).map_err(|_e| rpc::Error::internal_error()) + sc_tracing::reset_log_filter().map_err(|_e| rpc::Error::internal_error()) } } diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 03e3cb0298a40..a19a603e162f0 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -66,6 +66,7 @@ type SCSubscriber< static FILTER_RELOAD_HANDLE: OnceCell> = OnceCell::new(); static DEFAULT_DIRECTIVES: OnceCell>> = OnceCell::new(); +static CURRENT_DIRECTIVES: OnceCell>> = OnceCell::new(); /// Initialize FILTER_RELOAD_HANDLE, only possible once pub fn set_reload_handle(handle: Handle) { @@ -77,37 +78,47 @@ pub fn set_reload_handle(handle: Handle) { /// The syntax is identical to the CLI `=`: /// /// `sync=debug,state=trace` -pub fn add_default_directives(directive: &str) { - DEFAULT_DIRECTIVES.get_or_init(|| Mutex::new(Vec::new())).lock().push(directive.to_owned()); +pub fn add_default_directives(directives: &str) { + DEFAULT_DIRECTIVES.get_or_init(|| Mutex::new(Vec::new())).lock().push(directives.to_owned()); + add_directives(directives); } -/// Reload the logging filter with the supplied directives -pub fn reload_filter(directives: String, use_defaults: bool) -> Result<(), String> { - log::info!("Setting log filter"); +/// Add directives to current directives +pub fn add_directives(directives: &str) { + CURRENT_DIRECTIVES.get_or_init(|| Mutex::new(Vec::new())).lock().push(directives.to_owned()); +} + +/// Reload the logging filter with the supplied directives added to the existing directives +pub fn reload_filter() -> Result<(), String> { let mut env_filter = EnvFilter::default(); - if use_defaults { - if let Some(default_directives) = DEFAULT_DIRECTIVES.get() { - env_filter = add_directives(env_filter, default_directives.lock().join(",")); - } + if let Some(current_directives) = CURRENT_DIRECTIVES.get() { + env_filter = add_to_filter(env_filter, current_directives.lock().join(",")); } - env_filter = add_directives(env_filter, directives); env_filter = env_filter.add_directive( "sc_tracing=trace" .parse() .expect("provided directive is valid"), ); + log::debug!(target: "tracing", "Reloading log filter with: {}", env_filter); FILTER_RELOAD_HANDLE.get() .ok_or("No reload handle present".to_string())? .reload(env_filter) .map_err(|e| format!("{}", e)) } -fn add_directives(mut env_filter: EnvFilter, directives: String) -> EnvFilter { +pub fn reset_log_filter() -> Result<(), String> { + *CURRENT_DIRECTIVES + .get_or_init(|| Mutex::new(Vec::new())).lock() = + DEFAULT_DIRECTIVES.get_or_init(|| Mutex::new(Vec::new())).lock().clone(); + reload_filter() +} + +fn add_to_filter(mut env_filter: EnvFilter, directives: String) -> EnvFilter { for directive in parse_directives(&directives) { match directive { Ok(d) => env_filter = env_filter.add_directive(d), Err(invalid_directive) => { - log::warn!("Unable to parse directive while setting log filter: {:?}", invalid_directive); + log::warn!(target: "tracing", "Unable to parse directive while setting log filter: {:?}", invalid_directive); } } } From f90443a628965e0b496500c7827bb320b8d98ef3 Mon Sep 17 00:00:00 2001 From: Matt Date: Tue, 24 Nov 2020 22:06:03 +0000 Subject: [PATCH 34/50] make CLI log directives default --- client/cli/src/lib.rs | 13 ++++--------- 1 file changed, 4 insertions(+), 9 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 419c45f672ef9..9cf04f1fcbd34 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -273,8 +273,8 @@ pub fn init_logger( if pattern != "" { // We're not sure if log or tracing is available at this moment, so silently ignore the - // parse error. Use add_directives to ensure RPC addLogFilter functions correctly. - env_filter = add_directives(env_filter, pattern); + // parse error. + env_filter = add_default_directives(env_filter, pattern); } // If we're only logging `INFO` entries then we'll use a simplified logging format. @@ -327,15 +327,10 @@ pub fn init_logger( } } -// Adds default directives to ensure setLogFilter RPC functions correctly +// Adds default directives to ensure addLogFilter and resetLogFilter RPCs function correctly // Panics if any of the provided directives are invalid. -fn add_default_directives(env_filter: EnvFilter, directives: &str) -> EnvFilter { +fn add_default_directives(mut env_filter: EnvFilter, directives: &str) -> EnvFilter { sc_tracing::add_default_directives(directives); - add_directives(env_filter, directives) -} - -// Panics if any of the provided directives are invalid. -fn add_directives(mut env_filter: EnvFilter, directives: &str) -> EnvFilter { let (oks, errs): (Vec<_>, Vec<_>) = sc_tracing::parse_directives(directives) .into_iter() .partition(|res| res.is_ok()); From 37565c1e1e578cc4319b27b4cd5cb354650ca02b Mon Sep 17 00:00:00 2001 From: Matt Date: Tue, 24 Nov 2020 22:16:37 +0000 Subject: [PATCH 35/50] add comments --- client/tracing/src/lib.rs | 3 +++ 1 file changed, 3 insertions(+) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index a19a603e162f0..365cf95b960c8 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -64,8 +64,11 @@ type SCSubscriber< W = fn() -> std::io::Stderr > = layer::Layered, Registry>; +// Handle to reload the tracing log filter static FILTER_RELOAD_HANDLE: OnceCell> = OnceCell::new(); +// Directives that are defaulted to when resetting the log filter static DEFAULT_DIRECTIVES: OnceCell>> = OnceCell::new(); +// Current state of log filter static CURRENT_DIRECTIVES: OnceCell>> = OnceCell::new(); /// Initialize FILTER_RELOAD_HANDLE, only possible once From d827037af6415a13816274c2caa107ed89590a2e Mon Sep 17 00:00:00 2001 From: Matt Date: Wed, 25 Nov 2020 09:37:25 +0000 Subject: [PATCH 36/50] restore previous behaviour to panic when hard-coded directives are invalid --- client/cli/src/lib.rs | 24 +++++++++++++----------- 1 file changed, 13 insertions(+), 11 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 9cf04f1fcbd34..721f3fb5ebe33 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -259,22 +259,22 @@ pub fn init_logger( // after log filter reloading by RPC let mut env_filter = EnvFilter::default(); // Enable info - env_filter = add_default_directives(env_filter,"info"); + env_filter = add_default_directives(env_filter,"info", true); // Disable info logging by default for some modules. - env_filter = add_default_directives(env_filter, "ws=off,yamux=off,cranelift_codegen=off"); + env_filter = add_default_directives(env_filter, "ws=off,yamux=off,cranelift_codegen=off", true); // Set warn logging by default for some modules. - env_filter = add_default_directives(env_filter, "cranelift_wasm=warn,hyper=warn"); + env_filter = add_default_directives(env_filter, "cranelift_wasm=warn,hyper=warn", true); if let Ok(lvl) = std::env::var("RUST_LOG") { if lvl != "" { - env_filter = add_default_directives(env_filter, &lvl); + env_filter = add_default_directives(env_filter, &lvl, true); } } if pattern != "" { // We're not sure if log or tracing is available at this moment, so silently ignore the // parse error. - env_filter = add_default_directives(env_filter, pattern); + env_filter = add_default_directives(env_filter, pattern, false); } // If we're only logging `INFO` entries then we'll use a simplified logging format. @@ -287,11 +287,11 @@ pub fn init_logger( // Required because profiling traces are emitted via `sc_tracing` // NOTE: this must be done after we check the `max_level_hint` otherwise // it is always raised to `TRACE`. - env_filter = add_default_directives(env_filter, "sc_tracing=trace"); + env_filter = add_default_directives(env_filter, "sc_tracing=trace", true); // Make sure to include profiling targets in the filter if let Some(profiling_targets) = profiling_targets.clone() { - env_filter = add_default_directives(env_filter, &profiling_targets); + env_filter = add_default_directives(env_filter, &profiling_targets, false); } let enable_color = atty::is(atty::Stream::Stderr); @@ -328,8 +328,8 @@ pub fn init_logger( } // Adds default directives to ensure addLogFilter and resetLogFilter RPCs function correctly -// Panics if any of the provided directives are invalid. -fn add_default_directives(mut env_filter: EnvFilter, directives: &str) -> EnvFilter { +// Panics if any of the provided directives are invalid when `panic_if_invalid` is true. +fn add_default_directives(mut env_filter: EnvFilter, directives: &str, panic_if_invalid: bool) -> EnvFilter { sc_tracing::add_default_directives(directives); let (oks, errs): (Vec<_>, Vec<_>) = sc_tracing::parse_directives(directives) .into_iter() @@ -340,7 +340,9 @@ fn add_default_directives(mut env_filter: EnvFilter, directives: &str) -> EnvFil invalid_directive.expect_err("Already partitioned into Result::Err; qed") ); } - panic!("Invalid logging directives."); + if panic_if_invalid { + panic!("Invalid logging directives."); + } } for directive in oks { env_filter = env_filter.add_directive( @@ -368,7 +370,7 @@ where } else { if let Err(e) = tracing::subscriber::set_global_default(subscriber) { return Err(format!( - "Registering Substrate tracing subscriber failed: {:}!", e + "Registering Substrate tracing subscriber failed: {:}!", e )) } } From 08c87532aa31ce7cbc1afa6fe5a2ee38ae4e98b2 Mon Sep 17 00:00:00 2001 From: Matt Date: Wed, 25 Nov 2020 13:19:08 +0000 Subject: [PATCH 37/50] change/refactor directive parsing --- client/cli/src/lib.rs | 66 ++++++++++++++++++--------------------- client/tracing/src/lib.rs | 38 ++++++++++------------ 2 files changed, 47 insertions(+), 57 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 721f3fb5ebe33..e26785098d472 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -249,6 +249,22 @@ pub fn init_logger( profiling_targets: Option, disable_log_reloading: bool, ) -> std::result::Result<(), String> { + use sc_tracing::parse_default_directive; + + // Accept all valid directives and print invalid ones + fn parse_user_directives(mut env_filter: EnvFilter, dirs: &str) -> EnvFilter { + let dir_list: Vec<&str> = dirs + .split(',') + .collect(); + for dir in dir_list { + match parse_default_directive(&dir) { + Ok(d) => env_filter = env_filter.add_directive(d), + Err(e) => eprintln!("Supplied log directive is not valid: {}", e), + } + } + env_filter + } + if let Err(e) = tracing_log::LogTracer::init() { return Err(format!( "Registering Substrate logger failed: {:}!", e @@ -257,24 +273,27 @@ pub fn init_logger( // Initialize filter - ensure to use `add_default_directives` for any defaults to persist // after log filter reloading by RPC - let mut env_filter = EnvFilter::default(); - // Enable info - env_filter = add_default_directives(env_filter,"info", true); - // Disable info logging by default for some modules. - env_filter = add_default_directives(env_filter, "ws=off,yamux=off,cranelift_codegen=off", true); - // Set warn logging by default for some modules. - env_filter = add_default_directives(env_filter, "cranelift_wasm=warn,hyper=warn", true); + let mut env_filter = EnvFilter::default() + // Enable info + .add_directive(parse_default_directive("info").expect("provided directive is valid")) + // Disable info logging by default for some modules. + .add_directive(parse_default_directive("ws=off").expect("provided directive is valid")) + .add_directive(parse_default_directive("yamux=off").expect("provided directive is valid")) + .add_directive(parse_default_directive("cranelift_codegen=off").expect("provided directive is valid")) + // Set warn logging by default for some modules. + .add_directive(parse_default_directive("cranelift_wasm=warn").expect("provided directive is valid")) + .add_directive(parse_default_directive("hyper=warn").expect("provided directive is valid")); if let Ok(lvl) = std::env::var("RUST_LOG") { if lvl != "" { - env_filter = add_default_directives(env_filter, &lvl, true); + env_filter = parse_user_directives(env_filter, &lvl); } } if pattern != "" { // We're not sure if log or tracing is available at this moment, so silently ignore the // parse error. - env_filter = add_default_directives(env_filter, pattern, false); + env_filter = parse_user_directives(env_filter, pattern); } // If we're only logging `INFO` entries then we'll use a simplified logging format. @@ -287,11 +306,11 @@ pub fn init_logger( // Required because profiling traces are emitted via `sc_tracing` // NOTE: this must be done after we check the `max_level_hint` otherwise // it is always raised to `TRACE`. - env_filter = add_default_directives(env_filter, "sc_tracing=trace", true); + env_filter = env_filter.add_directive(parse_default_directive("sc_tracing=trace").expect("provided directive is valid")); // Make sure to include profiling targets in the filter if let Some(profiling_targets) = profiling_targets.clone() { - env_filter = add_default_directives(env_filter, &profiling_targets, false); + env_filter = parse_user_directives(env_filter, &profiling_targets); } let enable_color = atty::is(atty::Stream::Stderr); @@ -327,31 +346,6 @@ pub fn init_logger( } } -// Adds default directives to ensure addLogFilter and resetLogFilter RPCs function correctly -// Panics if any of the provided directives are invalid when `panic_if_invalid` is true. -fn add_default_directives(mut env_filter: EnvFilter, directives: &str, panic_if_invalid: bool) -> EnvFilter { - sc_tracing::add_default_directives(directives); - let (oks, errs): (Vec<_>, Vec<_>) = sc_tracing::parse_directives(directives) - .into_iter() - .partition(|res| res.is_ok()); - if !errs.is_empty() { - for invalid_directive in errs { - eprintln!("Logging directive not valid: {}", - invalid_directive.expect_err("Already partitioned into Result::Err; qed") - ); - } - if panic_if_invalid { - panic!("Invalid logging directives."); - } - } - for directive in oks { - env_filter = env_filter.add_directive( - directive.expect("Already partitioned into Result::Ok; qed") - ); - } - env_filter -} - fn initialize_tracing( subscriber: S, tracing_receiver: sc_tracing::TracingReceiver, diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 365cf95b960c8..eb5e1a691c374 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -95,7 +95,15 @@ pub fn add_directives(directives: &str) { pub fn reload_filter() -> Result<(), String> { let mut env_filter = EnvFilter::default(); if let Some(current_directives) = CURRENT_DIRECTIVES.get() { - env_filter = add_to_filter(env_filter, current_directives.lock().join(",")); + // Use join and then split in case any directives added together + for directive in current_directives.lock().join(",").split(',').map(|d| d.parse()) { + match directive { + Ok(dir) => env_filter = env_filter.add_directive(dir), + Err(invalid_directive) => { + log::warn!(target: "tracing", "Unable to parse directive while setting log filter: {:?}", invalid_directive); + } + } + } } env_filter = env_filter.add_directive( "sc_tracing=trace" @@ -116,26 +124,14 @@ pub fn reset_log_filter() -> Result<(), String> { reload_filter() } -fn add_to_filter(mut env_filter: EnvFilter, directives: String) -> EnvFilter { - for directive in parse_directives(&directives) { - match directive { - Ok(d) => env_filter = env_filter.add_directive(d), - Err(invalid_directive) => { - log::warn!(target: "tracing", "Unable to parse directive while setting log filter: {:?}", invalid_directive); - } - } - } - env_filter -} - -/// Parse the supplied text directives into `Vec>`, -/// with a `Result::Ok` containing the parsed `Directive` -/// or a `Result::Err` containing the `String` that failed to parse -pub fn parse_directives(dirs: &str) -> Vec> { - dirs.split(',') - .into_iter() - .map(|d| d.parse().map_err(|_| d.to_owned())) - .collect() +/// Parse `Directive` and add to default directives if successful. Ensures the supplied directive +/// will be restored when resetting the log filter. +pub fn parse_default_directive(directive: &str) -> Result { + let dir = directive + .parse() + .map_err(|_| format!("Unable to parse directive: {}", directive))?; + add_default_directives(directive); + Ok(dir) } /// Responsible for assigning ids to new spans, which are not re-used. From 59ad63e506a16f0193c05795f63cc34f31572bbe Mon Sep 17 00:00:00 2001 From: Matt Date: Wed, 25 Nov 2020 13:28:09 +0000 Subject: [PATCH 38/50] fix line width --- client/cli/src/lib.rs | 22 +++++++++++++++------- client/tracing/src/lib.rs | 5 ++++- 2 files changed, 19 insertions(+), 8 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index e26785098d472..446ee1914c4f7 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -275,14 +275,20 @@ pub fn init_logger( // after log filter reloading by RPC let mut env_filter = EnvFilter::default() // Enable info - .add_directive(parse_default_directive("info").expect("provided directive is valid")) + .add_directive(parse_default_directive("info") + .expect("provided directive is valid")) // Disable info logging by default for some modules. - .add_directive(parse_default_directive("ws=off").expect("provided directive is valid")) - .add_directive(parse_default_directive("yamux=off").expect("provided directive is valid")) - .add_directive(parse_default_directive("cranelift_codegen=off").expect("provided directive is valid")) + .add_directive(parse_default_directive("ws=off") + .expect("provided directive is valid")) + .add_directive(parse_default_directive("yamux=off") + .expect("provided directive is valid")) + .add_directive(parse_default_directive("cranelift_codegen=off") + .expect("provided directive is valid")) // Set warn logging by default for some modules. - .add_directive(parse_default_directive("cranelift_wasm=warn").expect("provided directive is valid")) - .add_directive(parse_default_directive("hyper=warn").expect("provided directive is valid")); + .add_directive(parse_default_directive("cranelift_wasm=warn") + .expect("provided directive is valid")) + .add_directive(parse_default_directive("hyper=warn") + .expect("provided directive is valid")); if let Ok(lvl) = std::env::var("RUST_LOG") { if lvl != "" { @@ -306,7 +312,9 @@ pub fn init_logger( // Required because profiling traces are emitted via `sc_tracing` // NOTE: this must be done after we check the `max_level_hint` otherwise // it is always raised to `TRACE`. - env_filter = env_filter.add_directive(parse_default_directive("sc_tracing=trace").expect("provided directive is valid")); + env_filter = env_filter.add_directive( + parse_default_directive("sc_tracing=trace").expect("provided directive is valid") + ); // Make sure to include profiling targets in the filter if let Some(profiling_targets) = profiling_targets.clone() { diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index eb5e1a691c374..2e304ad3fc995 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -100,7 +100,10 @@ pub fn reload_filter() -> Result<(), String> { match directive { Ok(dir) => env_filter = env_filter.add_directive(dir), Err(invalid_directive) => { - log::warn!(target: "tracing", "Unable to parse directive while setting log filter: {:?}", invalid_directive); + log::warn!( + target: "tracing", + "Unable to parse directive while setting log filter: {:?}", invalid_directive + ); } } } From 2d96c18b539c38bdbd024528af0325cb8dd81a2d Mon Sep 17 00:00:00 2001 From: Matt Date: Fri, 27 Nov 2020 22:32:17 +0000 Subject: [PATCH 39/50] add test for log filter reloading --- client/rpc/src/system/tests.rs | 90 ++++++++++++++++++++++++++++++++-- client/tracing/src/lib.rs | 8 +++ 2 files changed, 94 insertions(+), 4 deletions(-) diff --git a/client/rpc/src/system/tests.rs b/client/rpc/src/system/tests.rs index 50e467a7d879e..1a09a99bcfe63 100644 --- a/client/rpc/src/system/tests.rs +++ b/client/rpc/src/system/tests.rs @@ -335,8 +335,90 @@ fn system_network_remove_reserved() { } #[test] -fn system_set_log_filter() { - sc_cli::init_logger("afg=debug", Default::default(), Default::default(), false).unwrap(); - let res = api(None).system_set_log_filter("bla no ok -\\ /lba".into()); - assert_eq!(res, Ok(())); +fn test_add_reset_log_filter() { + use std::process::{Stdio, Command}; + use std::env; + use std::io::{BufReader, BufRead, Write}; + use std::sync::{Arc, Mutex}; + use std::thread; + use std::time::Duration; + + const EXPECTED_BEFORE_ADD: &'static str = "EXPECTED_BEFORE_ADD"; + const EXPECTED_AFTER_ADD: &'static str = "EXPECTED_AFTER_ADD"; + + // Enter log generation / filter reload + if std::env::var("TEST_LOG_FILTER").is_ok() { + sc_cli::init_logger("test_before_add=debug", Default::default(), Default::default(), false).unwrap(); + loop { + for line in std::io::stdin().lock().lines() { + let line = line.expect("Failed to read bytes"); + if line.contains("add_reload") { + sc_tracing::add_directives("test_after_add"); + assert!(sc_tracing::reload_filter().is_ok(), "Reload handle not present"); + } else if line.contains("reset") { + assert!(sc_tracing::reset_log_filter().is_ok(), "Unable to reset log filter"); + } else if line.contains("exit") { + return; + } + log::debug!(target: "test_before_add", "{}", EXPECTED_BEFORE_ADD); + log::debug!(target: "test_after_add", "{}", EXPECTED_AFTER_ADD); + } + } + } + + // Call this test again to enter the log generation / filter reload block + let test_executable = env::current_exe().expect("Unable to get current executable!"); + let mut child_process = Command::new(test_executable) + .env("TEST_LOG_FILTER", "1") + .args(&["--nocapture", "test_add_reset_log_filter"]) + .stdin(Stdio::piped()) + .stderr(Stdio::piped()) + .stdout(Stdio::inherit()) + .spawn() + .unwrap(); + + let child_stderr = child_process.stderr.take().expect("Could not get child stderr"); + let mut child_out = BufReader::new(child_stderr); + let mut child_in = child_process.stdin.take().expect("Could not get child stdin"); + + let child_out_str = Arc::new(Mutex::new(String::new())); + let shared = child_out_str.clone(); + + let _handle = thread::spawn(move || { + let mut line = String::new(); + while let Ok(_) = child_out.read_line(&mut line) { + shared.lock().unwrap().push_str(&line); + line.clear(); + } + }); + + // Initiate logs loop in child process + child_in.write("\n".as_bytes()).unwrap(); + thread::sleep(Duration::from_millis(100)); + let test1_str = child_out_str.lock().unwrap().clone(); + // Assert that only the first target is present + assert!(test1_str.contains(EXPECTED_BEFORE_ADD)); + assert!(!test1_str.contains(EXPECTED_AFTER_ADD)); + child_out_str.lock().unwrap().clear(); + + // Initiate add directive & reload in child process + child_in.write("add_reload\n".as_bytes()).unwrap(); + thread::sleep(Duration::from_millis(100)); + let test2_str = child_out_str.lock().unwrap().clone(); + // Assert that both targets are now present + assert!(test2_str.contains(EXPECTED_BEFORE_ADD)); + assert!(test2_str.contains(EXPECTED_AFTER_ADD)); + child_out_str.lock().unwrap().clear(); + + // Initiate logs filter reset in child process + child_in.write("reset\n".as_bytes()).unwrap(); + thread::sleep(Duration::from_millis(100)); + let test3_str = child_out_str.lock().unwrap().clone(); + // Assert that only the first target is present as it was initially + assert!(test3_str.contains(EXPECTED_BEFORE_ADD)); + assert!(!test3_str.contains(EXPECTED_AFTER_ADD)); + + // Return from child process + child_in.write("exit\n".as_bytes()).unwrap(); + assert!(child_process.wait().expect("Error waiting for child process").success()); } diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 2e304ad3fc995..5f6bf615759ee 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -91,6 +91,14 @@ pub fn add_directives(directives: &str) { CURRENT_DIRECTIVES.get_or_init(|| Mutex::new(Vec::new())).lock().push(directives.to_owned()); } +/// Add directives to current directives +pub fn get_directives() -> String { + CURRENT_DIRECTIVES + .get_or_init(|| Mutex::new(Vec::new())) + .lock() + .join(",") +} + /// Reload the logging filter with the supplied directives added to the existing directives pub fn reload_filter() -> Result<(), String> { let mut env_filter = EnvFilter::default(); From 3d49c2a160d0fff8674f2e2c70d5325c9854850a Mon Sep 17 00:00:00 2001 From: mattrutherford <44339188+mattrutherford@users.noreply.github.com> Date: Mon, 30 Nov 2020 10:05:09 +0000 Subject: [PATCH 40/50] Apply suggestions from code review MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Bastian Köcher --- client/cli/src/lib.rs | 14 ++++---------- client/rpc/src/system/tests.rs | 10 ++++------ 2 files changed, 8 insertions(+), 16 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 446ee1914c4f7..af5481c835011 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -252,17 +252,11 @@ pub fn init_logger( use sc_tracing::parse_default_directive; // Accept all valid directives and print invalid ones - fn parse_user_directives(mut env_filter: EnvFilter, dirs: &str) -> EnvFilter { - let dir_list: Vec<&str> = dirs - .split(',') - .collect(); - for dir in dir_list { - match parse_default_directive(&dir) { - Ok(d) => env_filter = env_filter.add_directive(d), - Err(e) => eprintln!("Supplied log directive is not valid: {}", e), - } + fn parse_user_directives(mut env_filter: EnvFilter, dirs: &str) -> std::result::Result { + for dir in dirs.split(',') { + parse_default_directive(&dir).map_err(|e| format!("Supplied log directive is not valid: {}", e))?; } - env_filter + Ok(env_filter) } if let Err(e) = tracing_log::LogTracer::init() { diff --git a/client/rpc/src/system/tests.rs b/client/rpc/src/system/tests.rs index 1a09a99bcfe63..2025c5ec09937 100644 --- a/client/rpc/src/system/tests.rs +++ b/client/rpc/src/system/tests.rs @@ -336,12 +336,10 @@ fn system_network_remove_reserved() { #[test] fn test_add_reset_log_filter() { - use std::process::{Stdio, Command}; - use std::env; - use std::io::{BufReader, BufRead, Write}; - use std::sync::{Arc, Mutex}; - use std::thread; - use std::time::Duration; + use std::{ + process::{Stdio, Command}, env, io::{BufReader, BufRead, Write}, + sync::{Arc, Mutex}, time::Duration + }; const EXPECTED_BEFORE_ADD: &'static str = "EXPECTED_BEFORE_ADD"; const EXPECTED_AFTER_ADD: &'static str = "EXPECTED_AFTER_ADD"; From 098e73024bec96210ccac52f7305d1fe939655c8 Mon Sep 17 00:00:00 2001 From: Matt Date: Mon, 30 Nov 2020 10:54:41 +0000 Subject: [PATCH 41/50] finish up suggestions from code review --- client/cli/src/lib.rs | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index af5481c835011..ebd6f0589ce6b 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -252,11 +252,14 @@ pub fn init_logger( use sc_tracing::parse_default_directive; // Accept all valid directives and print invalid ones - fn parse_user_directives(mut env_filter: EnvFilter, dirs: &str) -> std::result::Result { + fn parse_user_directives(mut env_filter: EnvFilter, dirs: &str) -> EnvFilter { for dir in dirs.split(',') { - parse_default_directive(&dir).map_err(|e| format!("Supplied log directive is not valid: {}", e))?; + match parse_default_directive(&dir) { + Ok(d) => env_filter = env_filter.add_directive(d), + Err(e) => eprintln!("Supplied log directive is not valid: {}", e), + } } - Ok(env_filter) + env_filter } if let Err(e) = tracing_log::LogTracer::init() { From b5d437860874f065036f977220598502890e4213 Mon Sep 17 00:00:00 2001 From: Matt Date: Mon, 30 Nov 2020 10:55:44 +0000 Subject: [PATCH 42/50] improve test --- client/rpc/src/system/tests.rs | 42 +++++++++++++++------------------- 1 file changed, 18 insertions(+), 24 deletions(-) diff --git a/client/rpc/src/system/tests.rs b/client/rpc/src/system/tests.rs index 2025c5ec09937..75723f7d91dbe 100644 --- a/client/rpc/src/system/tests.rs +++ b/client/rpc/src/system/tests.rs @@ -24,7 +24,10 @@ use substrate_test_runtime_client::runtime::Block; use assert_matches::assert_matches; use futures::prelude::*; use sp_utils::mpsc::tracing_unbounded; -use std::thread; +use std::{ + process::{Stdio, Command}, env, io::{BufReader, BufRead, Write}, + sync::{Arc, Mutex}, thread, time::Duration +}; struct Status { pub peers: usize, @@ -336,31 +339,23 @@ fn system_network_remove_reserved() { #[test] fn test_add_reset_log_filter() { - use std::{ - process::{Stdio, Command}, env, io::{BufReader, BufRead, Write}, - sync::{Arc, Mutex}, time::Duration - }; - const EXPECTED_BEFORE_ADD: &'static str = "EXPECTED_BEFORE_ADD"; const EXPECTED_AFTER_ADD: &'static str = "EXPECTED_AFTER_ADD"; // Enter log generation / filter reload if std::env::var("TEST_LOG_FILTER").is_ok() { sc_cli::init_logger("test_before_add=debug", Default::default(), Default::default(), false).unwrap(); - loop { - for line in std::io::stdin().lock().lines() { - let line = line.expect("Failed to read bytes"); - if line.contains("add_reload") { - sc_tracing::add_directives("test_after_add"); - assert!(sc_tracing::reload_filter().is_ok(), "Reload handle not present"); - } else if line.contains("reset") { - assert!(sc_tracing::reset_log_filter().is_ok(), "Unable to reset log filter"); - } else if line.contains("exit") { - return; - } - log::debug!(target: "test_before_add", "{}", EXPECTED_BEFORE_ADD); - log::debug!(target: "test_after_add", "{}", EXPECTED_AFTER_ADD); + for line in std::io::stdin().lock().lines() { + let line = line.expect("Failed to read bytes"); + if line.contains("add_reload") { + assert!(api(None).system_add_log_filter("test_after_add".to_owned()).is_ok(), "Unable to add log filter"); + } else if line.contains("reset") { + assert!(api(None).system_reset_log_filter().is_ok(), "Unable to reset log filter"); + } else if line.contains("exit") { + return; } + log::debug!(target: "test_before_add", "{}", EXPECTED_BEFORE_ADD); + log::debug!(target: "test_after_add", "{}", EXPECTED_AFTER_ADD); } } @@ -371,7 +366,6 @@ fn test_add_reset_log_filter() { .args(&["--nocapture", "test_add_reset_log_filter"]) .stdin(Stdio::piped()) .stderr(Stdio::piped()) - .stdout(Stdio::inherit()) .spawn() .unwrap(); @@ -391,7 +385,7 @@ fn test_add_reset_log_filter() { }); // Initiate logs loop in child process - child_in.write("\n".as_bytes()).unwrap(); + child_in.write(b"\n").unwrap(); thread::sleep(Duration::from_millis(100)); let test1_str = child_out_str.lock().unwrap().clone(); // Assert that only the first target is present @@ -400,7 +394,7 @@ fn test_add_reset_log_filter() { child_out_str.lock().unwrap().clear(); // Initiate add directive & reload in child process - child_in.write("add_reload\n".as_bytes()).unwrap(); + child_in.write(b"add_reload\n").unwrap(); thread::sleep(Duration::from_millis(100)); let test2_str = child_out_str.lock().unwrap().clone(); // Assert that both targets are now present @@ -409,7 +403,7 @@ fn test_add_reset_log_filter() { child_out_str.lock().unwrap().clear(); // Initiate logs filter reset in child process - child_in.write("reset\n".as_bytes()).unwrap(); + child_in.write(b"reset\n").unwrap(); thread::sleep(Duration::from_millis(100)); let test3_str = child_out_str.lock().unwrap().clone(); // Assert that only the first target is present as it was initially @@ -417,6 +411,6 @@ fn test_add_reset_log_filter() { assert!(!test3_str.contains(EXPECTED_AFTER_ADD)); // Return from child process - child_in.write("exit\n".as_bytes()).unwrap(); + child_in.write(b"exit\n").unwrap(); assert!(child_process.wait().expect("Error waiting for child process").success()); } From 5da34f0eaa71723227bbd884fb76b36eafc473ca Mon Sep 17 00:00:00 2001 From: Matt Date: Mon, 30 Nov 2020 16:05:18 +0000 Subject: [PATCH 43/50] change expect message --- client/rpc/src/system/tests.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/client/rpc/src/system/tests.rs b/client/rpc/src/system/tests.rs index 75723f7d91dbe..fa3574e9dae02 100644 --- a/client/rpc/src/system/tests.rs +++ b/client/rpc/src/system/tests.rs @@ -348,9 +348,9 @@ fn test_add_reset_log_filter() { for line in std::io::stdin().lock().lines() { let line = line.expect("Failed to read bytes"); if line.contains("add_reload") { - assert!(api(None).system_add_log_filter("test_after_add".to_owned()).is_ok(), "Unable to add log filter"); + assert!(api(None).system_add_log_filter("test_after_add".to_owned()).is_ok(), "`system_add_log_filter` failed"); } else if line.contains("reset") { - assert!(api(None).system_reset_log_filter().is_ok(), "Unable to reset log filter"); + assert!(api(None).system_reset_log_filter().is_ok(), "`system_reset_log_filter` failed"); } else if line.contains("exit") { return; } From 728ed213fef73157268390b52e52abefec0366e0 Mon Sep 17 00:00:00 2001 From: Matt Date: Mon, 30 Nov 2020 16:05:46 +0000 Subject: [PATCH 44/50] change fn name --- client/cli/src/lib.rs | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index ebd6f0589ce6b..c85cc3fa5b573 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -252,11 +252,11 @@ pub fn init_logger( use sc_tracing::parse_default_directive; // Accept all valid directives and print invalid ones - fn parse_user_directives(mut env_filter: EnvFilter, dirs: &str) -> EnvFilter { + fn add_directives_and_print_invalid(mut env_filter: EnvFilter, dirs: &str) -> EnvFilter { for dir in dirs.split(',') { match parse_default_directive(&dir) { Ok(d) => env_filter = env_filter.add_directive(d), - Err(e) => eprintln!("Supplied log directive is not valid: {}", e), + Err(e) => eprintln!("{}", e), } } env_filter @@ -289,14 +289,14 @@ pub fn init_logger( if let Ok(lvl) = std::env::var("RUST_LOG") { if lvl != "" { - env_filter = parse_user_directives(env_filter, &lvl); + env_filter = add_directives_and_print_invalid(env_filter, &lvl); } } if pattern != "" { // We're not sure if log or tracing is available at this moment, so silently ignore the // parse error. - env_filter = parse_user_directives(env_filter, pattern); + env_filter = add_directives_and_print_invalid(env_filter, pattern); } // If we're only logging `INFO` entries then we'll use a simplified logging format. @@ -315,7 +315,7 @@ pub fn init_logger( // Make sure to include profiling targets in the filter if let Some(profiling_targets) = profiling_targets.clone() { - env_filter = parse_user_directives(env_filter, &profiling_targets); + env_filter = add_directives_and_print_invalid(env_filter, &profiling_targets); } let enable_color = atty::is(atty::Stream::Stderr); From 990c0c9be9f1fb3b51194bbc8e8d13826c99ea76 Mon Sep 17 00:00:00 2001 From: mattrutherford <44339188+mattrutherford@users.noreply.github.com> Date: Mon, 30 Nov 2020 16:12:56 +0000 Subject: [PATCH 45/50] Apply suggestions from code review MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Bastian Köcher --- client/tracing/src/lib.rs | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 5f6bf615759ee..922cff2956dff 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -110,7 +110,8 @@ pub fn reload_filter() -> Result<(), String> { Err(invalid_directive) => { log::warn!( target: "tracing", - "Unable to parse directive while setting log filter: {:?}", invalid_directive + "Unable to parse directive while setting log filter: {:?}", + invalid_directive, ); } } @@ -135,8 +136,9 @@ pub fn reset_log_filter() -> Result<(), String> { reload_filter() } -/// Parse `Directive` and add to default directives if successful. Ensures the supplied directive -/// will be restored when resetting the log filter. +/// Parse `Directive` and add to default directives if successful. +/// +/// Ensures the supplied directive will be restored when resetting the log filter. pub fn parse_default_directive(directive: &str) -> Result { let dir = directive .parse() From 1a7cf5ceaaaa1354c106b25d3957b6ec0ea1c524 Mon Sep 17 00:00:00 2001 From: mattrutherford <44339188+mattrutherford@users.noreply.github.com> Date: Mon, 30 Nov 2020 16:16:22 +0000 Subject: [PATCH 46/50] Apply suggestions from code review MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Bastian Köcher --- client/cli/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index c85cc3fa5b573..ae0a611472675 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -268,7 +268,7 @@ pub fn init_logger( )) } - // Initialize filter - ensure to use `add_default_directives` for any defaults to persist + // Initialize filter - ensure to use `parse_default_directive` for any defaults to persist // after log filter reloading by RPC let mut env_filter = EnvFilter::default() // Enable info From b941066831f6fa77d3265e047d550c6e2e6829f2 Mon Sep 17 00:00:00 2001 From: Matt Date: Mon, 30 Nov 2020 16:18:42 +0000 Subject: [PATCH 47/50] add docs, remove unused fn --- client/tracing/src/lib.rs | 11 +++-------- 1 file changed, 3 insertions(+), 8 deletions(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 922cff2956dff..f4017023eff19 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -91,14 +91,6 @@ pub fn add_directives(directives: &str) { CURRENT_DIRECTIVES.get_or_init(|| Mutex::new(Vec::new())).lock().push(directives.to_owned()); } -/// Add directives to current directives -pub fn get_directives() -> String { - CURRENT_DIRECTIVES - .get_or_init(|| Mutex::new(Vec::new())) - .lock() - .join(",") -} - /// Reload the logging filter with the supplied directives added to the existing directives pub fn reload_filter() -> Result<(), String> { let mut env_filter = EnvFilter::default(); @@ -129,6 +121,9 @@ pub fn reload_filter() -> Result<(), String> { .map_err(|e| format!("{}", e)) } +/// Resets the log filter back to the original state when the node was started. +/// +/// Includes substrate defaults and CLI supplied directives. pub fn reset_log_filter() -> Result<(), String> { *CURRENT_DIRECTIVES .get_or_init(|| Mutex::new(Vec::new())).lock() = From 1207ef7f4957d8699407e0541a6133b868ee64f8 Mon Sep 17 00:00:00 2001 From: Matt Date: Tue, 1 Dec 2020 09:41:33 +0000 Subject: [PATCH 48/50] propagate Err on invalid log directive --- client/cli/src/config.rs | 6 ++---- client/cli/src/lib.rs | 15 ++++++--------- 2 files changed, 8 insertions(+), 13 deletions(-) diff --git a/client/cli/src/config.rs b/client/cli/src/config.rs index 068a9af4ce4fb..e4411e49408e5 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -555,14 +555,12 @@ pub trait CliConfiguration: Sized { sp_panic_handler::set(&C::support_url(), &C::impl_version()); - if let Err(e) = init_logger( + init_logger( &logger_pattern, tracing_receiver, tracing_targets, disable_log_reloading, - ) { - log::warn!("💬 Problem initializing global logging framework: {:}", e) - } + )?; if let Some(new_limit) = fdlimit::raise_fd_limit() { if new_limit < RECOMMENDED_OPEN_FILE_DESCRIPTOR_LIMIT { diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index ae0a611472675..80882924bd3ad 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -252,14 +252,11 @@ pub fn init_logger( use sc_tracing::parse_default_directive; // Accept all valid directives and print invalid ones - fn add_directives_and_print_invalid(mut env_filter: EnvFilter, dirs: &str) -> EnvFilter { + fn parse_user_directives(mut env_filter: EnvFilter, dirs: &str) -> std::result::Result { for dir in dirs.split(',') { - match parse_default_directive(&dir) { - Ok(d) => env_filter = env_filter.add_directive(d), - Err(e) => eprintln!("{}", e), - } + env_filter = env_filter.add_directive(parse_default_directive(&dir)?); } - env_filter + Ok(env_filter) } if let Err(e) = tracing_log::LogTracer::init() { @@ -289,14 +286,14 @@ pub fn init_logger( if let Ok(lvl) = std::env::var("RUST_LOG") { if lvl != "" { - env_filter = add_directives_and_print_invalid(env_filter, &lvl); + env_filter = parse_user_directives(env_filter, &lvl)?; } } if pattern != "" { // We're not sure if log or tracing is available at this moment, so silently ignore the // parse error. - env_filter = add_directives_and_print_invalid(env_filter, pattern); + env_filter = parse_user_directives(env_filter, pattern)?; } // If we're only logging `INFO` entries then we'll use a simplified logging format. @@ -315,7 +312,7 @@ pub fn init_logger( // Make sure to include profiling targets in the filter if let Some(profiling_targets) = profiling_targets.clone() { - env_filter = add_directives_and_print_invalid(env_filter, &profiling_targets); + env_filter = parse_user_directives(env_filter, &profiling_targets)?; } let enable_color = atty::is(atty::Stream::Stderr); From 397b09cca12299bbac7ec6036a62045f27f537b4 Mon Sep 17 00:00:00 2001 From: Matt Date: Tue, 1 Dec 2020 10:00:21 +0000 Subject: [PATCH 49/50] Update tracing-subscriber version --- client/executor/Cargo.toml | 2 +- primitives/tracing/Cargo.toml | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/client/executor/Cargo.toml b/client/executor/Cargo.toml index 803a49d1deaaf..c5ce4b86e12f5 100644 --- a/client/executor/Cargo.toml +++ b/client/executor/Cargo.toml @@ -49,7 +49,7 @@ sp-runtime = { version = "2.0.0", path = "../../primitives/runtime" } sp-tracing = { version = "2.0.0", path = "../../primitives/tracing" } sc-tracing = { version = "2.0.0", path = "../tracing" } tracing = "0.1.22" -tracing-subscriber = "0.2.10" +tracing-subscriber = "0.2.15" [features] default = [ "std" ] diff --git a/primitives/tracing/Cargo.toml b/primitives/tracing/Cargo.toml index ba370f46b9b6a..c6d4d7b4caccd 100644 --- a/primitives/tracing/Cargo.toml +++ b/primitives/tracing/Cargo.toml @@ -23,7 +23,7 @@ codec = { version = "1.3.1", package = "parity-scale-codec", default-features = tracing = { version = "0.1.22", default-features = false } tracing-core = { version = "0.1.17", default-features = false } log = { version = "0.4.8", optional = true } -tracing-subscriber = { version = "0.2.10", optional = true, features = ["tracing-log"] } +tracing-subscriber = { version = "0.2.15", optional = true, features = ["tracing-log"] } [features] default = [ "std" ] From 0489d8a60a7fd42e7dd0ea02ee0123c280d95381 Mon Sep 17 00:00:00 2001 From: Matt Date: Wed, 2 Dec 2020 14:56:49 +0000 Subject: [PATCH 50/50] Improve docs for `disable_log_reloading` CLI param --- client/cli/src/params/shared_params.rs | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/client/cli/src/params/shared_params.rs b/client/cli/src/params/shared_params.rs index a790f25b0db99..52b1488ea9ccd 100644 --- a/client/cli/src/params/shared_params.rs +++ b/client/cli/src/params/shared_params.rs @@ -46,9 +46,11 @@ pub struct SharedParams { #[structopt(short = "l", long, value_name = "LOG_PATTERN")] pub log: Vec, - /// Disable log reloading at runtime. + /// Disable feature to dynamically update and reload the log filter. /// - /// By default this feature is enabled, however it leads to a small performance decrease. + /// By default this feature is enabled, however it leads to a small performance decrease. + /// The `system_addLogFilter` and `system_resetLogFilter` RPCs will have no effect with this + /// option set. #[structopt(long = "disable-log-reloading")] pub disable_log_reloading: bool,