From 88c1f425d3cc80b2bee585a6af253e6f542fdedc Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Wed, 7 Oct 2020 13:14:54 +0200 Subject: [PATCH 01/42] Initial commit Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master From 95762f149971db4413479ae6ad0dbf5e06bb4429 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Fri, 9 Oct 2020 12:08:14 +0200 Subject: [PATCH 02/42] WIP Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master --- client/cli/src/config.rs | 20 +++++++-------- client/cli/src/lib.rs | 21 ++++++---------- client/service/src/config.rs | 2 ++ client/service/src/lib.rs | 2 ++ client/service/src/logger.rs | 45 ++++++++++++++++++++++++++++++++++ client/service/test/src/lib.rs | 1 + client/tracing/src/lib.rs | 2 +- utils/browser/src/lib.rs | 1 + 8 files changed, 69 insertions(+), 25 deletions(-) create mode 100644 client/service/src/logger.rs diff --git a/client/cli/src/config.rs b/client/cli/src/config.rs index 43b755100244f..2619ce28e2816 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -472,6 +472,13 @@ pub trait CliConfiguration: Sized { .map(|p| p.unsafe_pruning) .unwrap_or(false); + let logger_pattern = self.log_filters()?; + let tracing_receiver = self.tracing_receiver()?; + let tracing_targets = self.tracing_targets()?; + // TODO: this should be fatal right? + let logger = init_logger(&logger_pattern, tracing_receiver, tracing_targets.as_ref())?; + //log::warn!("💬 Problem initializing global logging framework: {:}", e) + Ok(Configuration { impl_name: C::impl_name(), impl_version: C::impl_version(), @@ -507,8 +514,9 @@ pub trait CliConfiguration: Sized { force_authoring: self.force_authoring()?, disable_grandpa: self.disable_grandpa()?, dev_key_seed: self.dev_key_seed(is_dev)?, - tracing_targets: self.tracing_targets()?, - tracing_receiver: self.tracing_receiver()?, + tracing_targets, + tracing_receiver, + logger: logger.into(), chain_spec, max_runtime_instances, announce_block: self.announce_block()?, @@ -536,16 +544,8 @@ pub trait CliConfiguration: Sized { /// 2. Initializes the logger /// 3. Raises the FD limit fn init(&self) -> Result<()> { - let logger_pattern = self.log_filters()?; - let tracing_receiver = self.tracing_receiver()?; - let tracing_targets = self.tracing_targets()?; - sp_panic_handler::set(&C::support_url(), &C::impl_version()); - if let Err(e) = init_logger(&logger_pattern, tracing_receiver, tracing_targets) { - 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 { warn!( diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index bd71c50fb70ea..616211570f697 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -46,6 +46,7 @@ use structopt::{ use tracing_subscriber::{ filter::Directive, fmt::time::ChronoLocal, layer::SubscriberExt, FmtSubscriber, Layer, }; +use std::sync::Arc; /// Substrate client CLI /// @@ -234,8 +235,8 @@ pub trait SubstrateCli: Sized { pub fn init_logger( pattern: &str, tracing_receiver: sc_tracing::TracingReceiver, - tracing_targets: Option, -) -> std::result::Result<(), String> { + tracing_targets: Option<&String>, +) -> std::result::Result, String> { fn parse_directives(dirs: impl AsRef) -> Vec { dirs.as_ref() .split(',') @@ -308,25 +309,17 @@ pub fn init_logger( .with_level(!simple) .with_thread_names(!simple) .with_timer(timer) + //.with_writer(std::io::sink) .with_writer(std::io::stderr) .finish(); if let Some(tracing_targets) = tracing_targets { - let profiling = sc_tracing::ProfilingLayer::new(tracing_receiver, &tracing_targets); + let profiling = sc_tracing::ProfilingLayer::new(tracing_receiver, tracing_targets); - if let Err(e) = tracing::subscriber::set_global_default(subscriber.with(profiling)) { - return Err(format!( - "Registering Substrate tracing subscriber failed: {:}!", e - )) - } + Ok(Arc::new(subscriber.with(profiling))) } else { - if let Err(e) = tracing::subscriber::set_global_default(subscriber) { - return Err(format!( - "Registering Substrate tracing subscriber failed: {:}!", e - )) - } + Ok(Arc::new(subscriber)) } - Ok(()) } #[cfg(test)] diff --git a/client/service/src/config.rs b/client/service/src/config.rs index 15783a87f9917..ad741f17543a7 100644 --- a/client/service/src/config.rs +++ b/client/service/src/config.rs @@ -101,6 +101,8 @@ pub struct Configuration { pub tracing_targets: Option, /// Tracing receiver pub tracing_receiver: sc_tracing::TracingReceiver, + /// Logger. + pub logger: crate::Logger, /// The size of the instances cache. /// /// The default value is 8. diff --git a/client/service/src/lib.rs b/client/service/src/lib.rs index 39f1dff289a1a..3051e04e41020 100644 --- a/client/service/src/lib.rs +++ b/client/service/src/lib.rs @@ -33,6 +33,7 @@ pub mod client; #[cfg(not(feature = "test-helpers"))] mod client; mod task_manager; +mod logger; use std::{io, pin::Pin}; use std::net::SocketAddr; @@ -82,6 +83,7 @@ pub use task_manager::TaskManager; pub use sp_consensus::import_queue::ImportQueue; use sc_client_api::BlockchainEvents; pub use sc_keystore::KeyStorePtr as KeyStore; +pub use logger::*; const DEFAULT_PROTOCOL_ID: &str = "sup"; diff --git a/client/service/src/logger.rs b/client/service/src/logger.rs new file mode 100644 index 0000000000000..cc0c24703dc88 --- /dev/null +++ b/client/service/src/logger.rs @@ -0,0 +1,45 @@ +// 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 . + +//! Logger wrapper around `tracing::Subscriber`. + +use std::sync::Arc; + +#[derive(Clone)] +pub enum Logger { + Sink, + Logger(Arc), +} + +impl Default for Logger { + fn default() -> Self { + Self::Sink + } +} + +impl std::fmt::Debug for Logger { + fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result { + write!(f, "Logger") + } +} + +impl From> for Logger { + fn from(value: Arc) -> Self { + Self::Logger(value) + } +} diff --git a/client/service/test/src/lib.rs b/client/service/test/src/lib.rs index cfe815f174fac..b91bccaea8425 100644 --- a/client/service/test/src/lib.rs +++ b/client/service/test/src/lib.rs @@ -269,6 +269,7 @@ fn node_config Date: Wed, 14 Oct 2020 15:12:42 +0200 Subject: [PATCH 03/42] WIP Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master --- Cargo.lock | 11 +++ client/cli/src/config.rs | 20 +++--- client/cli/src/lib.rs | 92 ++++++++++++++++++++++---- client/service/Cargo.toml | 1 + client/service/src/builder.rs | 4 ++ client/service/src/config.rs | 2 - client/service/src/lib.rs | 2 - client/service/src/task_manager/mod.rs | 3 +- client/service/test/src/lib.rs | 1 - client/tracing/src/lib.rs | 2 +- utils/browser/src/lib.rs | 1 - 11 files changed, 107 insertions(+), 32 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index f80b073f51d4f..d9a245e069db8 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -7195,6 +7195,7 @@ dependencies = [ "tempfile", "tokio 0.2.22", "tracing", + "tracing-futures", "wasm-timer", ] @@ -9402,6 +9403,16 @@ dependencies = [ "lazy_static", ] +[[package]] +name = "tracing-futures" +version = "0.2.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ab7bb6f14721aa00656086e9335d363c5c8747bae02ebe32ea2c7dece5689b4c" +dependencies = [ + "pin-project", + "tracing", +] + [[package]] name = "tracing-log" version = "0.1.1" diff --git a/client/cli/src/config.rs b/client/cli/src/config.rs index 2619ce28e2816..43b755100244f 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -472,13 +472,6 @@ pub trait CliConfiguration: Sized { .map(|p| p.unsafe_pruning) .unwrap_or(false); - let logger_pattern = self.log_filters()?; - let tracing_receiver = self.tracing_receiver()?; - let tracing_targets = self.tracing_targets()?; - // TODO: this should be fatal right? - let logger = init_logger(&logger_pattern, tracing_receiver, tracing_targets.as_ref())?; - //log::warn!("💬 Problem initializing global logging framework: {:}", e) - Ok(Configuration { impl_name: C::impl_name(), impl_version: C::impl_version(), @@ -514,9 +507,8 @@ pub trait CliConfiguration: Sized { force_authoring: self.force_authoring()?, disable_grandpa: self.disable_grandpa()?, dev_key_seed: self.dev_key_seed(is_dev)?, - tracing_targets, - tracing_receiver, - logger: logger.into(), + tracing_targets: self.tracing_targets()?, + tracing_receiver: self.tracing_receiver()?, chain_spec, max_runtime_instances, announce_block: self.announce_block()?, @@ -544,8 +536,16 @@ pub trait CliConfiguration: Sized { /// 2. Initializes the logger /// 3. Raises the FD limit fn init(&self) -> Result<()> { + let logger_pattern = self.log_filters()?; + let tracing_receiver = self.tracing_receiver()?; + let tracing_targets = self.tracing_targets()?; + sp_panic_handler::set(&C::support_url(), &C::impl_version()); + if let Err(e) = init_logger(&logger_pattern, tracing_receiver, tracing_targets) { + 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 { warn!( diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 616211570f697..648293b42ae87 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -37,16 +37,18 @@ pub use runner::*; use sc_service::{Configuration, TaskExecutor}; pub use sc_service::{ChainSpec, Role}; pub use sp_version::RuntimeVersion; +use std::fmt; use std::io::Write; pub use structopt; use structopt::{ clap::{self, AppSettings}, StructOpt, }; +use tracing::{Event, Subscriber, Id, span::Attributes}; use tracing_subscriber::{ - filter::Directive, fmt::time::ChronoLocal, layer::SubscriberExt, FmtSubscriber, Layer, + filter::Directive, fmt::{time::ChronoLocal, FormatEvent, FmtContext, FormatFields, format::FmtSpan}, layer::{SubscriberExt, Context}, FmtSubscriber, Layer, registry::LookupSpan, }; -use std::sync::Arc; +use std::fmt::Write as OtherWrite; /// Substrate client CLI /// @@ -235,8 +237,8 @@ pub trait SubstrateCli: Sized { pub fn init_logger( pattern: &str, tracing_receiver: sc_tracing::TracingReceiver, - tracing_targets: Option<&String>, -) -> std::result::Result, String> { + tracing_targets: Option, +) -> std::result::Result<(), String> { fn parse_directives(dirs: impl AsRef) -> Vec { dirs.as_ref() .split(',') @@ -305,20 +307,82 @@ pub fn init_logger( let subscriber = FmtSubscriber::builder() .with_env_filter(env_filter) .with_ansi(enable_color) - .with_target(!simple) - .with_level(!simple) - .with_thread_names(!simple) - .with_timer(timer) - //.with_writer(std::io::sink) - .with_writer(std::io::stderr) - .finish(); + //.with_target(!simple) + //.with_level(!simple) + //.with_thread_names(!simple) + //.with_timer(timer) + //.with_writer(std::io::stderr) + //.with_max_level(tracing::Level::INFO) + //.with_span_events(FmtSpan::FULL) + .event_format(EventFormat) + //.event_format(tracing_subscriber::fmt::format().json().with_span_list(true)) + .finish().with(MyLayer {}); if let Some(tracing_targets) = tracing_targets { - let profiling = sc_tracing::ProfilingLayer::new(tracing_receiver, tracing_targets); + let profiling = sc_tracing::ProfilingLayer::new(tracing_receiver, &tracing_targets); - Ok(Arc::new(subscriber.with(profiling))) + if let Err(e) = tracing::subscriber::set_global_default(subscriber.with(profiling)) { + return Err(format!( + "Registering Substrate tracing subscriber failed: {:}!", e + )) + } } else { - Ok(Arc::new(subscriber)) + if let Err(e) = tracing::subscriber::set_global_default(subscriber) { + return Err(format!( + "Registering Substrate tracing subscriber failed: {:}!", e + )) + } + } + Ok(()) +} + +struct EventFormat; + +impl FormatEvent for EventFormat +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, +{ + fn format_event(&self, ctx: &FmtContext, writer: &mut dyn fmt::Write, event: &Event) -> fmt::Result { + use tracing_subscriber::fmt::FormattedFields; + ctx.visit_spans::<(), _>(|span| { + let exts = span.extensions(); + let fields = exts.get::>(); + writeln!(writer, "{:?} {:?} {:?}", span.name(), fields.map(|x| x.as_str()), event); + Ok(()) + }).unwrap(); + Ok(()) + } +} + +pub struct MyLayer { + // ... +} + +impl Layer for MyLayer { + fn new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { + let mut s = String::new(); + let mut v = StringVisitor { string: &mut s }; + attrs.record(&mut v); + eprintln!("### {:?}", s); + } +} + +pub struct StringVisitor<'a> { + string: &'a mut String, +} + +impl<'a> tracing::field::Visit for StringVisitor<'a> { + fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { + if field.name() == "name" { + write!(self.string, " [name = {:?}]", value).unwrap(); + } + } + + fn record_str(&mut self, field: &tracing::field::Field, value: &str) { + if field.name() == "name" { + write!(self.string, " [{}]", value).unwrap(); + } } } diff --git a/client/service/Cargo.toml b/client/service/Cargo.toml index f57a145422c8c..292515411fea2 100644 --- a/client/service/Cargo.toml +++ b/client/service/Cargo.toml @@ -76,6 +76,7 @@ prometheus-endpoint = { package = "substrate-prometheus-endpoint", path = "../.. sc-tracing = { version = "2.0.0", path = "../tracing" } sp-tracing = { version = "2.0.0", path = "../../primitives/tracing" } tracing = "0.1.19" +tracing-futures = { version = "0.2.4" } parity-util-mem = { version = "0.7.0", default-features = false, features = ["primitive-types"] } [target.'cfg(not(target_os = "unknown"))'.dependencies] diff --git a/client/service/src/builder.rs b/client/service/src/builder.rs index 410198af26da3..6ece5c791d68f 100644 --- a/client/service/src/builder.rs +++ b/client/service/src/builder.rs @@ -490,6 +490,10 @@ pub fn spawn_tasks( telemetry_connection_sinks, } = params; + let abc = String::from("a\"b\'c"); + let span = tracing::info_span!("substrate-node", name = config.network.node_name.as_str(), test = abc.as_str()); + let _enter = span.enter(); + let chain_info = client.usage_info().chain; sp_session::generate_initial_session_keys( diff --git a/client/service/src/config.rs b/client/service/src/config.rs index ad741f17543a7..15783a87f9917 100644 --- a/client/service/src/config.rs +++ b/client/service/src/config.rs @@ -101,8 +101,6 @@ pub struct Configuration { pub tracing_targets: Option, /// Tracing receiver pub tracing_receiver: sc_tracing::TracingReceiver, - /// Logger. - pub logger: crate::Logger, /// The size of the instances cache. /// /// The default value is 8. diff --git a/client/service/src/lib.rs b/client/service/src/lib.rs index 3051e04e41020..39f1dff289a1a 100644 --- a/client/service/src/lib.rs +++ b/client/service/src/lib.rs @@ -33,7 +33,6 @@ pub mod client; #[cfg(not(feature = "test-helpers"))] mod client; mod task_manager; -mod logger; use std::{io, pin::Pin}; use std::net::SocketAddr; @@ -83,7 +82,6 @@ pub use task_manager::TaskManager; pub use sp_consensus::import_queue::ImportQueue; use sc_client_api::BlockchainEvents; pub use sc_keystore::KeyStorePtr as KeyStore; -pub use logger::*; const DEFAULT_PROTOCOL_ID: &str = "sup"; diff --git a/client/service/src/task_manager/mod.rs b/client/service/src/task_manager/mod.rs index 88a44e1360d7f..a0aeba3009dee 100644 --- a/client/service/src/task_manager/mod.rs +++ b/client/service/src/task_manager/mod.rs @@ -27,6 +27,7 @@ use prometheus_endpoint::{ CounterVec, HistogramOpts, HistogramVec, Opts, Registry, U64 }; use sp_utils::mpsc::{TracingUnboundedSender, TracingUnboundedReceiver, tracing_unbounded}; +use tracing_futures::Instrument; use crate::{config::{TaskExecutor, TaskType, JoinFuture}, Error}; mod prometheus_future; @@ -116,7 +117,7 @@ impl SpawnTaskHandle { } }; - let join_handle = self.executor.spawn(Box::pin(future), task_type); + let join_handle = self.executor.spawn(Box::pin(future.in_current_span()), task_type); let mut task_notifier = self.task_notifier.clone(); self.executor.spawn( Box::pin(async move { diff --git a/client/service/test/src/lib.rs b/client/service/test/src/lib.rs index b91bccaea8425..cfe815f174fac 100644 --- a/client/service/test/src/lib.rs +++ b/client/service/test/src/lib.rs @@ -269,7 +269,6 @@ fn node_config Date: Wed, 14 Oct 2020 18:06:07 +0200 Subject: [PATCH 04/42] WIP Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master --- client/cli/src/lib.rs | 41 ++++++++++++++++++++++++++++------------- 1 file changed, 28 insertions(+), 13 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 648293b42ae87..a3b32f2b27e91 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -49,6 +49,7 @@ use tracing_subscriber::{ filter::Directive, fmt::{time::ChronoLocal, FormatEvent, FmtContext, FormatFields, format::FmtSpan}, layer::{SubscriberExt, Context}, FmtSubscriber, Layer, registry::LookupSpan, }; use std::fmt::Write as OtherWrite; +use std::marker::PhantomData; /// Substrate client CLI /// @@ -316,7 +317,7 @@ pub fn init_logger( //.with_span_events(FmtSpan::FULL) .event_format(EventFormat) //.event_format(tracing_subscriber::fmt::format().json().with_span_list(true)) - .finish().with(MyLayer {}); + .finish().with(MyLayer); if let Some(tracing_targets) = tracing_targets { let profiling = sc_tracing::ProfilingLayer::new(tracing_receiver, &tracing_targets); @@ -347,24 +348,35 @@ where use tracing_subscriber::fmt::FormattedFields; ctx.visit_spans::<(), _>(|span| { let exts = span.extensions(); - let fields = exts.get::>(); - writeln!(writer, "{:?} {:?} {:?}", span.name(), fields.map(|x| x.as_str()), event); + let fields = exts.get::(); + write!(writer, "{:?} {:?}", span.name(), fields); Ok(()) }).unwrap(); - Ok(()) + + writeln!(writer, " {:?}", event) } } -pub struct MyLayer { - // ... -} +pub struct MyLayer; -impl Layer for MyLayer { +impl Layer for MyLayer +where + S: Subscriber + for<'a> LookupSpan<'a>, +{ fn new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { - let mut s = String::new(); - let mut v = StringVisitor { string: &mut s }; - attrs.record(&mut v); - eprintln!("### {:?}", s); + let span = ctx.span(id).expect("new_span has been called for this span; qed"); + let mut extensions = span.extensions_mut(); + + if extensions.get_mut::().is_none() { + let mut s = String::new(); + let mut v = StringVisitor { string: &mut s }; + attrs.record(&mut v); + + if !s.is_empty() { + let fmt_fields = MyFormattedFields(s); + extensions.insert(fmt_fields); + } + } } } @@ -375,7 +387,7 @@ pub struct StringVisitor<'a> { impl<'a> tracing::field::Visit for StringVisitor<'a> { fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { if field.name() == "name" { - write!(self.string, " [name = {:?}]", value).unwrap(); + write!(self.string, "[name = {:?}]", value).unwrap(); } } @@ -386,6 +398,9 @@ impl<'a> tracing::field::Visit for StringVisitor<'a> { } } +#[derive(Debug)] +struct MyFormattedFields(String); + #[cfg(test)] mod tests { use super::*; From f0d5964b64c8e3bdd1485e6924d0c44c4ebb18b5 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Thu, 15 Oct 2020 11:48:10 +0200 Subject: [PATCH 05/42] WIP Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master --- client/cli/src/lib.rs | 260 +++++++++++++++++++++++++++++++++++++++--- 1 file changed, 245 insertions(+), 15 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index a3b32f2b27e91..8531c904740ac 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -44,12 +44,14 @@ use structopt::{ clap::{self, AppSettings}, StructOpt, }; -use tracing::{Event, Subscriber, Id, span::Attributes}; +use tracing::{Event, Subscriber, Id, span::{self, Attributes}, Level}; use tracing_subscriber::{ - filter::Directive, fmt::{time::ChronoLocal, FormatEvent, FmtContext, FormatFields, format::FmtSpan}, layer::{SubscriberExt, Context}, FmtSubscriber, Layer, registry::LookupSpan, + filter::Directive, fmt::{time::{SystemTime, ChronoLocal, FormatTime}, FormatEvent, FmtContext, FormatFields}, layer::{SubscriberExt, Context}, FmtSubscriber, Layer, registry::LookupSpan, }; use std::fmt::Write as OtherWrite; -use std::marker::PhantomData; +use ansi_term::{Colour, Style}; +use std::iter; +use tracing_log::NormalizeEvent; /// Substrate client CLI /// @@ -315,7 +317,14 @@ pub fn init_logger( //.with_writer(std::io::stderr) //.with_max_level(tracing::Level::INFO) //.with_span_events(FmtSpan::FULL) - .event_format(EventFormat) + .event_format(EventFormat { + timer, + ansi: enable_color, + display_target: !simple, + display_level: !simple, + display_thread_id: false, + display_thread_name: !simple, + }) //.event_format(tracing_subscriber::fmt::format().json().with_span_list(true)) .finish().with(MyLayer); @@ -337,27 +346,80 @@ pub fn init_logger( Ok(()) } -struct EventFormat; +struct EventFormat { + pub(crate) timer: T, + pub(crate) ansi: bool, + pub(crate) display_target: bool, + pub(crate) display_level: bool, + pub(crate) display_thread_id: bool, + pub(crate) display_thread_name: bool, +} -impl FormatEvent for EventFormat +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 { - use tracing_subscriber::fmt::FormattedFields; - ctx.visit_spans::<(), _>(|span| { + 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 if !self.display_thread_id => { + write!(writer, "{:0>2?} ", current_thread.id())?; + } + _ => {} + } + } + + if self.display_thread_id { + write!(writer, "{:0>2?} ", std::thread::current().id())?; + } + + // Custom code to display node name + ctx.visit_spans::(|span| { let exts = span.extensions(); - let fields = exts.get::(); - write!(writer, "{:?} {:?}", span.name(), fields); - Ok(()) + if let Some(node_name) = exts.get::() { + write!(writer, "{}", node_name.as_str()) + } else { + Ok(()) + } }).unwrap(); - writeln!(writer, " {:?}", event) + let fmt_ctx = { + FmtCtx::new(&ctx, event.parent(), self.ansi) + }; + write!(writer, "{}", fmt_ctx)?; + if self.display_target { + write!(writer, "{}:", meta.target())?; + } + ctx.format_fields(writer, event)?; + let span = ctx.lookup_current(); + if let Some(ref id) = span.map(|x| x.id()) { + if let Some(span) = ctx.metadata(id) { + write!(writer, "{}", span.fields()).unwrap_or(()); + } + } + writeln!(writer) } } -pub struct MyLayer; +struct MyLayer; impl Layer for MyLayer where @@ -380,7 +442,7 @@ where } } -pub struct StringVisitor<'a> { +struct StringVisitor<'a> { string: &'a mut String, } @@ -393,7 +455,7 @@ impl<'a> tracing::field::Visit for StringVisitor<'a> { fn record_str(&mut self, field: &tracing::field::Field, value: &str) { if field.name() == "name" { - write!(self.string, " [{}]", value).unwrap(); + write!(self.string, "[{}] ", value).unwrap(); } } } @@ -401,6 +463,174 @@ impl<'a> tracing::field::Visit for StringVisitor<'a> { #[derive(Debug)] struct MyFormattedFields(String); +impl MyFormattedFields { + 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 } + } +} + +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) + } +} + +struct FmtCtx<'a, S, N> { + ctx: &'a FmtContext<'a, S, N>, + span: Option<&'a span::Id>, + ansi: bool, +} + +impl<'a, S, N: 'a> FmtCtx<'a, S, N> +where + S: Subscriber + for<'lookup> LookupSpan<'lookup>, + N: for<'writer> FormatFields<'writer> + 'static, +{ + pub(crate) fn new( + ctx: &'a FmtContext<'_, S, N>, + span: Option<&'a span::Id>, + ansi: bool, + ) -> Self { + Self { ctx, ansi, span } + } + + fn bold(&self) -> Style { + if self.ansi { + return Style::new().bold(); + } + + Style::new() + } +} + +impl<'a, S, N: 'a> fmt::Display for FmtCtx<'a, S, N> +where + S: Subscriber + for<'lookup> LookupSpan<'lookup>, + N: for<'writer> FormatFields<'writer> + 'static, +{ + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let bold = self.bold(); + let mut seen = false; + + let span = self + .span + .and_then(|id| self.ctx.span(&id)) + .or_else(|| self.ctx.lookup_current()); + + let scope = span + .into_iter() + .flat_map(|span| span.from_root().chain(iter::once(span))); + + for span in scope { + seen = true; + write!(f, "{}:", bold.paint(span.metadata().name()))?; + } + + if seen { + f.write_char(' ')?; + } + Ok(()) + } +} + +mod time { +use std::fmt; +use ansi_term::{Style}; +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(()) +} +} + #[cfg(test)] mod tests { use super::*; From a55ccf09b314359b731448c5b097ead35daebdf7 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Thu, 15 Oct 2020 11:58:35 +0200 Subject: [PATCH 06/42] WIP Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master --- client/cli/src/lib.rs | 300 +------------------------------------- client/cli/src/logging.rs | 296 +++++++++++++++++++++++++++++++++++++ 2 files changed, 300 insertions(+), 296 deletions(-) create mode 100644 client/cli/src/logging.rs diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 8531c904740ac..5dfc4ab31786f 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -27,6 +27,7 @@ mod config; mod error; mod params; mod runner; +mod logging; pub use arg_enums::*; pub use commands::*; @@ -309,15 +310,8 @@ pub fn init_logger( let subscriber = FmtSubscriber::builder() .with_env_filter(env_filter) - .with_ansi(enable_color) - //.with_target(!simple) - //.with_level(!simple) - //.with_thread_names(!simple) - //.with_timer(timer) - //.with_writer(std::io::stderr) - //.with_max_level(tracing::Level::INFO) - //.with_span_events(FmtSpan::FULL) - .event_format(EventFormat { + .with_writer(std::io::stderr) + .event_format(logging::EventFormat { timer, ansi: enable_color, display_target: !simple, @@ -325,8 +319,7 @@ pub fn init_logger( display_thread_id: false, display_thread_name: !simple, }) - //.event_format(tracing_subscriber::fmt::format().json().with_span_list(true)) - .finish().with(MyLayer); + .finish().with(logging::MyLayer); if let Some(tracing_targets) = tracing_targets { let profiling = sc_tracing::ProfilingLayer::new(tracing_receiver, &tracing_targets); @@ -346,291 +339,6 @@ pub fn init_logger( Ok(()) } -struct EventFormat { - pub(crate) timer: T, - pub(crate) ansi: bool, - pub(crate) display_target: bool, - pub(crate) display_level: bool, - pub(crate) display_thread_id: bool, - pub(crate) display_thread_name: bool, -} - -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 if !self.display_thread_id => { - write!(writer, "{:0>2?} ", current_thread.id())?; - } - _ => {} - } - } - - if self.display_thread_id { - write!(writer, "{:0>2?} ", std::thread::current().id())?; - } - - // Custom code to display node name - ctx.visit_spans::(|span| { - let exts = span.extensions(); - if let Some(node_name) = exts.get::() { - write!(writer, "{}", node_name.as_str()) - } else { - Ok(()) - } - }).unwrap(); - - let fmt_ctx = { - FmtCtx::new(&ctx, event.parent(), self.ansi) - }; - write!(writer, "{}", fmt_ctx)?; - if self.display_target { - write!(writer, "{}:", meta.target())?; - } - ctx.format_fields(writer, event)?; - let span = ctx.lookup_current(); - if let Some(ref id) = span.map(|x| x.id()) { - if let Some(span) = ctx.metadata(id) { - write!(writer, "{}", span.fields()).unwrap_or(()); - } - } - writeln!(writer) - } -} - -struct MyLayer; - -impl Layer for MyLayer -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"); - let mut extensions = span.extensions_mut(); - - if extensions.get_mut::().is_none() { - let mut s = String::new(); - let mut v = StringVisitor { string: &mut s }; - attrs.record(&mut v); - - if !s.is_empty() { - let fmt_fields = MyFormattedFields(s); - extensions.insert(fmt_fields); - } - } - } -} - -struct StringVisitor<'a> { - string: &'a mut String, -} - -impl<'a> tracing::field::Visit for StringVisitor<'a> { - fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { - if field.name() == "name" { - write!(self.string, "[name = {:?}]", value).unwrap(); - } - } - - fn record_str(&mut self, field: &tracing::field::Field, value: &str) { - if field.name() == "name" { - write!(self.string, "[{}] ", value).unwrap(); - } - } -} - -#[derive(Debug)] -struct MyFormattedFields(String); - -impl MyFormattedFields { - 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 } - } -} - -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) - } -} - -struct FmtCtx<'a, S, N> { - ctx: &'a FmtContext<'a, S, N>, - span: Option<&'a span::Id>, - ansi: bool, -} - -impl<'a, S, N: 'a> FmtCtx<'a, S, N> -where - S: Subscriber + for<'lookup> LookupSpan<'lookup>, - N: for<'writer> FormatFields<'writer> + 'static, -{ - pub(crate) fn new( - ctx: &'a FmtContext<'_, S, N>, - span: Option<&'a span::Id>, - ansi: bool, - ) -> Self { - Self { ctx, ansi, span } - } - - fn bold(&self) -> Style { - if self.ansi { - return Style::new().bold(); - } - - Style::new() - } -} - -impl<'a, S, N: 'a> fmt::Display for FmtCtx<'a, S, N> -where - S: Subscriber + for<'lookup> LookupSpan<'lookup>, - N: for<'writer> FormatFields<'writer> + 'static, -{ - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - let bold = self.bold(); - let mut seen = false; - - let span = self - .span - .and_then(|id| self.ctx.span(&id)) - .or_else(|| self.ctx.lookup_current()); - - let scope = span - .into_iter() - .flat_map(|span| span.from_root().chain(iter::once(span))); - - for span in scope { - seen = true; - write!(f, "{}:", bold.paint(span.metadata().name()))?; - } - - if seen { - f.write_char(' ')?; - } - Ok(()) - } -} - -mod time { -use std::fmt; -use ansi_term::{Style}; -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(()) -} -} - #[cfg(test)] mod tests { use super::*; diff --git a/client/cli/src/logging.rs b/client/cli/src/logging.rs new file mode 100644 index 0000000000000..2c2adb2e1a785 --- /dev/null +++ b/client/cli/src/logging.rs @@ -0,0 +1,296 @@ +use std::fmt; +use tracing::{Event, Subscriber, Id, span::{self, Attributes}, Level}; +use tracing_subscriber::{ + filter::Directive, fmt::{time::{SystemTime, ChronoLocal, FormatTime}, FormatEvent, FmtContext, FormatFields}, layer::{SubscriberExt, Context}, FmtSubscriber, Layer, registry::LookupSpan, +}; +use std::fmt::Write as OtherWrite; +use ansi_term::{Colour, Style}; +use std::iter; +use tracing_log::NormalizeEvent; + +pub(crate) struct EventFormat { + pub(crate) timer: T, + pub(crate) ansi: bool, + pub(crate) display_target: bool, + pub(crate) display_level: bool, + pub(crate) display_thread_id: bool, + pub(crate) display_thread_name: bool, +} + +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 if !self.display_thread_id => { + write!(writer, "{:0>2?} ", current_thread.id())?; + } + _ => {} + } + } + + if self.display_thread_id { + write!(writer, "{:0>2?} ", std::thread::current().id())?; + } + + // Custom code to display node name + ctx.visit_spans::(|span| { + let exts = span.extensions(); + if let Some(node_name) = exts.get::() { + write!(writer, "{}", node_name.as_str()) + } else { + Ok(()) + } + }).unwrap(); + + let fmt_ctx = { + FmtCtx::new(&ctx, event.parent(), self.ansi) + }; + write!(writer, "{}", fmt_ctx)?; + if self.display_target { + write!(writer, "{}:", meta.target())?; + } + ctx.format_fields(writer, event)?; + let span = ctx.lookup_current(); + if let Some(ref id) = span.map(|x| x.id()) { + if let Some(span) = ctx.metadata(id) { + write!(writer, "{}", span.fields()).unwrap_or(()); + } + } + writeln!(writer) + } +} + +pub(crate) struct MyLayer; + +impl Layer for MyLayer +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"); + let mut extensions = span.extensions_mut(); + + if extensions.get_mut::().is_none() { + let mut s = String::new(); + let mut v = StringVisitor { string: &mut s }; + attrs.record(&mut v); + + if !s.is_empty() { + let fmt_fields = MyFormattedFields(s); + extensions.insert(fmt_fields); + } + } + } +} + +struct StringVisitor<'a> { + string: &'a mut String, +} + +impl<'a> tracing::field::Visit for StringVisitor<'a> { + fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { + if field.name() == "name" { + write!(self.string, "[name = {:?}]", value).unwrap(); + } + } + + fn record_str(&mut self, field: &tracing::field::Field, value: &str) { + if field.name() == "name" { + write!(self.string, "[{}] ", value).unwrap(); + } + } +} + +#[derive(Debug)] +struct MyFormattedFields(String); + +impl MyFormattedFields { + 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 } + } +} + +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) + } +} + +struct FmtCtx<'a, S, N> { + ctx: &'a FmtContext<'a, S, N>, + span: Option<&'a span::Id>, + ansi: bool, +} + +impl<'a, S, N: 'a> FmtCtx<'a, S, N> +where + S: Subscriber + for<'lookup> LookupSpan<'lookup>, + N: for<'writer> FormatFields<'writer> + 'static, +{ + pub(crate) fn new( + ctx: &'a FmtContext<'_, S, N>, + span: Option<&'a span::Id>, + ansi: bool, + ) -> Self { + Self { ctx, ansi, span } + } + + fn bold(&self) -> Style { + if self.ansi { + return Style::new().bold(); + } + + Style::new() + } +} + +impl<'a, S, N: 'a> fmt::Display for FmtCtx<'a, S, N> +where + S: Subscriber + for<'lookup> LookupSpan<'lookup>, + N: for<'writer> FormatFields<'writer> + 'static, +{ + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let bold = self.bold(); + let mut seen = false; + + let span = self + .span + .and_then(|id| self.ctx.span(&id)) + .or_else(|| self.ctx.lookup_current()); + + let scope = span + .into_iter() + .flat_map(|span| span.from_root().chain(iter::once(span))); + + for span in scope { + seen = true; + write!(f, "{}:", bold.paint(span.metadata().name()))?; + } + + if seen { + f.write_char(' ')?; + } + Ok(()) + } +} + +mod time { +use std::fmt; +use ansi_term::{Style}; +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 ad7dbd58d5f9364b5e944dc16c02bcbabe08a4e5 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Thu, 15 Oct 2020 13:44:35 +0200 Subject: [PATCH 07/42] CLEANUP Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master --- client/cli/src/lib.rs | 11 +-- client/cli/src/logging.rs | 127 +++++++++++++++++++-------------- client/service/src/builder.rs | 3 +- client/service/src/logger.rs | 45 ------------ client/telemetry/src/worker.rs | 10 ++- 5 files changed, 83 insertions(+), 113 deletions(-) delete mode 100644 client/service/src/logger.rs diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 5dfc4ab31786f..a4c6cc0d86c3d 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -38,21 +38,15 @@ pub use runner::*; use sc_service::{Configuration, TaskExecutor}; pub use sc_service::{ChainSpec, Role}; pub use sp_version::RuntimeVersion; -use std::fmt; use std::io::Write; pub use structopt; use structopt::{ clap::{self, AppSettings}, StructOpt, }; -use tracing::{Event, Subscriber, Id, span::{self, Attributes}, Level}; use tracing_subscriber::{ - filter::Directive, fmt::{time::{SystemTime, ChronoLocal, FormatTime}, FormatEvent, FmtContext, FormatFields}, layer::{SubscriberExt, Context}, FmtSubscriber, Layer, registry::LookupSpan, + filter::Directive, fmt::time::ChronoLocal, layer::SubscriberExt, FmtSubscriber, Layer, }; -use std::fmt::Write as OtherWrite; -use ansi_term::{Colour, Style}; -use std::iter; -use tracing_log::NormalizeEvent; /// Substrate client CLI /// @@ -316,10 +310,9 @@ pub fn init_logger( ansi: enable_color, display_target: !simple, display_level: !simple, - display_thread_id: false, display_thread_name: !simple, }) - .finish().with(logging::MyLayer); + .finish().with(logging::NodeNameLayer); if let Some(tracing_targets) = tracing_targets { let profiling = sc_tracing::ProfilingLayer::new(tracing_receiver, &tracing_targets); diff --git a/client/cli/src/logging.rs b/client/cli/src/logging.rs index 2c2adb2e1a785..51866ab769543 100644 --- a/client/cli/src/logging.rs +++ b/client/cli/src/logging.rs @@ -1,19 +1,45 @@ -use std::fmt; -use tracing::{Event, Subscriber, Id, span::{self, Attributes}, Level}; -use tracing_subscriber::{ - filter::Directive, fmt::{time::{SystemTime, ChronoLocal, FormatTime}, FormatEvent, FmtContext, FormatFields}, layer::{SubscriberExt, Context}, FmtSubscriber, Layer, registry::LookupSpan, -}; -use std::fmt::Write as OtherWrite; +// 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, Style}; +use std::fmt; +use std::fmt::Write as _; use std::iter; +use tracing::{ + span::{self, Attributes}, + Event, Id, Level, Subscriber, +}; use tracing_log::NormalizeEvent; +use tracing_subscriber::{ + fmt::{ + time::{FormatTime, SystemTime}, + FmtContext, FormatEvent, FormatFields, + }, + layer::Context, + registry::LookupSpan, + Layer, +}; pub(crate) struct EventFormat { pub(crate) timer: T, pub(crate) ansi: bool, pub(crate) display_target: bool, pub(crate) display_level: bool, - pub(crate) display_thread_id: bool, pub(crate) display_thread_name: bool, } @@ -23,15 +49,18 @@ where N: for<'a> FormatFields<'a> + 'static, T: FormatTime, { - fn format_event(&self, ctx: &FmtContext, writer: &mut dyn fmt::Write, event: &Event) -> fmt::Result { + 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) - }; + let fmt_level = { FmtLevel::new(meta.level(), self.ansi) }; write!(writer, "{} ", fmt_level)?; } @@ -42,62 +71,52 @@ where write!(writer, "{} ", FmtThreadName::new(name))?; } // fall-back to thread id when name is absent and ids are not enabled - None if !self.display_thread_id => { + None => { write!(writer, "{:0>2?} ", current_thread.id())?; } - _ => {} } } - if self.display_thread_id { - write!(writer, "{:0>2?} ", std::thread::current().id())?; - } - // Custom code to display node name ctx.visit_spans::(|span| { let exts = span.extensions(); - if let Some(node_name) = exts.get::() { + if let Some(node_name) = exts.get::() { write!(writer, "{}", node_name.as_str()) } else { Ok(()) } - }).unwrap(); + }) + .unwrap(); - let fmt_ctx = { - FmtCtx::new(&ctx, event.parent(), self.ansi) - }; + let fmt_ctx = { FmtCtx::new(&ctx, event.parent(), self.ansi) }; write!(writer, "{}", fmt_ctx)?; if self.display_target { write!(writer, "{}:", meta.target())?; } ctx.format_fields(writer, event)?; - let span = ctx.lookup_current(); - if let Some(ref id) = span.map(|x| x.id()) { - if let Some(span) = ctx.metadata(id) { - write!(writer, "{}", span.fields()).unwrap_or(()); - } - } writeln!(writer) } } -pub(crate) struct MyLayer; +pub(crate) struct NodeNameLayer; -impl Layer for MyLayer +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"); + let span = ctx + .span(id) + .expect("new_span has been called for this span; qed"); let mut extensions = span.extensions_mut(); - if extensions.get_mut::().is_none() { + if extensions.get_mut::().is_none() { let mut s = String::new(); let mut v = StringVisitor { string: &mut s }; attrs.record(&mut v); if !s.is_empty() { - let fmt_fields = MyFormattedFields(s); + let fmt_fields = NodeName(s); extensions.insert(fmt_fields); } } @@ -123,9 +142,9 @@ impl<'a> tracing::field::Visit for StringVisitor<'a> { } #[derive(Debug)] -struct MyFormattedFields(String); +struct NodeName(String); -impl MyFormattedFields { +impl NodeName { fn as_str(&self) -> &str { self.0.as_str() } @@ -272,25 +291,23 @@ where } mod time { -use std::fmt; -use ansi_term::{Style}; -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)?; + 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(()) } - writer.write_char(' ')?; - Ok(()) } -} - - diff --git a/client/service/src/builder.rs b/client/service/src/builder.rs index 6ece5c791d68f..3f72845703302 100644 --- a/client/service/src/builder.rs +++ b/client/service/src/builder.rs @@ -490,8 +490,7 @@ pub fn spawn_tasks( telemetry_connection_sinks, } = params; - let abc = String::from("a\"b\'c"); - let span = tracing::info_span!("substrate-node", name = config.network.node_name.as_str(), test = abc.as_str()); + let span = tracing::info_span!("substrate-node", name = config.network.node_name.as_str()); let _enter = span.enter(); let chain_info = client.usage_info().chain; diff --git a/client/service/src/logger.rs b/client/service/src/logger.rs deleted file mode 100644 index cc0c24703dc88..0000000000000 --- a/client/service/src/logger.rs +++ /dev/null @@ -1,45 +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 . - -//! Logger wrapper around `tracing::Subscriber`. - -use std::sync::Arc; - -#[derive(Clone)] -pub enum Logger { - Sink, - Logger(Arc), -} - -impl Default for Logger { - fn default() -> Self { - Self::Sink - } -} - -impl std::fmt::Debug for Logger { - fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result { - write!(f, "Logger") - } -} - -impl From> for Logger { - fn from(value: Arc) -> Self { - Self::Logger(value) - } -} diff --git a/client/telemetry/src/worker.rs b/client/telemetry/src/worker.rs index e01ac62d12dc3..9db7cc57f246e 100644 --- a/client/telemetry/src/worker.rs +++ b/client/telemetry/src/worker.rs @@ -150,12 +150,18 @@ impl TelemetryWorker { } }; + let serialized = { + let mut out = Vec::new(); + slog_json::Json::default(&mut out).log(record, values).map_err(|_| ())?; + out + }; + // None of the nodes want that verbosity, so just return without doing any serialization. if self.nodes.iter().all(|(_, node_max_verbosity)| msg_verbosity > *node_max_verbosity) { trace!( target: "telemetry", - "Skipping log entry because verbosity {:?} is too high for all endpoints", - msg_verbosity + "Skipping log entry because verbosity {:?} is too high for all endpoints: {}", + msg_verbosity, String::from_utf8(serialized).unwrap() ); return Ok(()) } From c8e0841072354e0f8964e1cd9bdde94548aacd04 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Thu, 15 Oct 2020 13:53:19 +0200 Subject: [PATCH 08/42] Add notes to original source code --- client/cli/src/logging.rs | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/client/cli/src/logging.rs b/client/cli/src/logging.rs index 51866ab769543..b53c91bfeff95 100644 --- a/client/cli/src/logging.rs +++ b/client/cli/src/logging.rs @@ -199,6 +199,9 @@ impl<'a> FmtThreadName<'a> { } } +// 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::{ @@ -260,6 +263,9 @@ where } } +// 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#L711 impl<'a, S, N: 'a> fmt::Display for FmtCtx<'a, S, N> where S: Subscriber + for<'lookup> LookupSpan<'lookup>, @@ -290,6 +296,9 @@ where } } +// 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; From dc2f4018c7cf3f0677a602d7ce68cb8fe6ccd9b4 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Thu, 15 Oct 2020 14:03:08 +0200 Subject: [PATCH 09/42] CLEANUP Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master --- client/cli/src/logging.rs | 20 +++++++++++++------- 1 file changed, 13 insertions(+), 7 deletions(-) diff --git a/client/cli/src/logging.rs b/client/cli/src/logging.rs index b53c91bfeff95..0e854a8a6fd84 100644 --- a/client/cli/src/logging.rs +++ b/client/cli/src/logging.rs @@ -43,6 +43,9 @@ pub(crate) struct EventFormat { pub(crate) display_thread_name: bool, } +// NOTE: the following code has been inspiref 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>, @@ -108,11 +111,16 @@ where let span = ctx .span(id) .expect("new_span has been called for this span; qed"); + + if span.name() != "substrate-node" { + return; + } + let mut extensions = span.extensions_mut(); if extensions.get_mut::().is_none() { let mut s = String::new(); - let mut v = StringVisitor { string: &mut s }; + let mut v = NodeNameVisitor(&mut s); attrs.record(&mut v); if !s.is_empty() { @@ -123,20 +131,18 @@ where } } -struct StringVisitor<'a> { - string: &'a mut String, -} +struct NodeNameVisitor<'a, W: std::fmt::Write>(&'a mut W); -impl<'a> tracing::field::Visit for StringVisitor<'a> { +impl<'a, W: std::fmt::Write> tracing::field::Visit for NodeNameVisitor<'a, W> { fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { if field.name() == "name" { - write!(self.string, "[name = {:?}]", value).unwrap(); + write!(self.0, "[name = {:?}]", value).unwrap(); } } fn record_str(&mut self, field: &tracing::field::Field, value: &str) { if field.name() == "name" { - write!(self.string, "[{}] ", value).unwrap(); + write!(self.0, "[{}] ", value).unwrap(); } } } From 34106dd7d95f526cd543195b6c5067fdc53623d6 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Thu, 15 Oct 2020 14:32:21 +0200 Subject: [PATCH 10/42] CLEANUP Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master --- client/telemetry/src/worker.rs | 10 ++-------- 1 file changed, 2 insertions(+), 8 deletions(-) diff --git a/client/telemetry/src/worker.rs b/client/telemetry/src/worker.rs index 9db7cc57f246e..e01ac62d12dc3 100644 --- a/client/telemetry/src/worker.rs +++ b/client/telemetry/src/worker.rs @@ -150,18 +150,12 @@ impl TelemetryWorker { } }; - let serialized = { - let mut out = Vec::new(); - slog_json::Json::default(&mut out).log(record, values).map_err(|_| ())?; - out - }; - // None of the nodes want that verbosity, so just return without doing any serialization. if self.nodes.iter().all(|(_, node_max_verbosity)| msg_verbosity > *node_max_verbosity) { trace!( target: "telemetry", - "Skipping log entry because verbosity {:?} is too high for all endpoints: {}", - msg_verbosity, String::from_utf8(serialized).unwrap() + "Skipping log entry because verbosity {:?} is too high for all endpoints", + msg_verbosity ); return Ok(()) } From 76f2d430aafb51b0eb16952a629ef748c54c9d9f Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Thu, 15 Oct 2020 15:32:58 +0200 Subject: [PATCH 11/42] WIP Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master --- client/cli/src/logging.rs | 21 +++++++++++++++------ 1 file changed, 15 insertions(+), 6 deletions(-) diff --git a/client/cli/src/logging.rs b/client/cli/src/logging.rs index 0e854a8a6fd84..880413a1cd9b9 100644 --- a/client/cli/src/logging.rs +++ b/client/cli/src/logging.rs @@ -81,10 +81,16 @@ where } // Custom code to display node name + let mut found_node_name = false; ctx.visit_spans::(|span| { - let exts = span.extensions(); - if let Some(node_name) = exts.get::() { - write!(writer, "{}", node_name.as_str()) + if !found_node_name { + let exts = span.extensions(); + if let Some(node_name) = exts.get::() { + found_node_name = true; + write!(writer, "{}", node_name.as_str()) + } else { + Ok(()) + } } else { Ok(()) } @@ -269,7 +275,7 @@ where } } -// NOTE: the following code has been duplicated from tracing-subscriber +// NOTE: the following code has been inspired from tracing-subscriber // // https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/format/mod.rs#L711 impl<'a, S, N: 'a> fmt::Display for FmtCtx<'a, S, N> @@ -290,9 +296,12 @@ where .into_iter() .flat_map(|span| span.from_root().chain(iter::once(span))); - for span in scope { + for name in scope + .map(|span| span.metadata().name()) + .filter(|&x| x != "substrate-node") + { seen = true; - write!(f, "{}:", bold.paint(span.metadata().name()))?; + write!(f, "{}:", bold.paint(name))?; } if seen { From 0c278a8fdf1527ad0226d65134a4b400504c95cd Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Fri, 16 Oct 2020 07:15:20 +0200 Subject: [PATCH 12/42] WIP Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master --- Cargo.lock | 10 ++++++ Cargo.toml | 1 + bin/node-template/node/src/service.rs | 1 + client/cli/Cargo.toml | 1 + client/cli/derive/Cargo.toml | 20 ++++++++++++ client/cli/derive/src/lib.rs | 36 +++++++++++++++++++++ client/cli/src/lib.rs | 3 ++ client/cli/src/logging.rs | 45 ++++++++++++++------------- client/service/src/builder.rs | 3 -- 9 files changed, 95 insertions(+), 25 deletions(-) create mode 100644 client/cli/derive/Cargo.toml create mode 100644 client/cli/derive/src/lib.rs diff --git a/Cargo.lock b/Cargo.lock index d9a245e069db8..985a596900504 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6331,6 +6331,7 @@ dependencies = [ "rand 0.7.3", "regex", "rpassword", + "sc-cli-derive", "sc-client-api", "sc-informant", "sc-keystore", @@ -6360,6 +6361,15 @@ dependencies = [ "tracing-subscriber", ] +[[package]] +name = "sc-cli-derive" +version = "2.0.0" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + [[package]] name = "sc-client-api" version = "2.0.0" diff --git a/Cargo.toml b/Cargo.toml index 99b1d418a5153..3b7b0e96a2287 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -21,6 +21,7 @@ members = [ "client/chain-spec", "client/chain-spec/derive", "client/cli", + "client/cli/derive", "client/consensus/aura", "client/consensus/babe", "client/consensus/babe/rpc", diff --git a/bin/node-template/node/src/service.rs b/bin/node-template/node/src/service.rs index 3de31dc61ab51..50916cfe1113b 100644 --- a/bin/node-template/node/src/service.rs +++ b/bin/node-template/node/src/service.rs @@ -227,6 +227,7 @@ pub fn new_full(config: Configuration) -> Result { } /// Builds a new service for a light client. +#[sc_cli::substrate_cli_node_name("light")] pub fn new_light(config: Configuration) -> Result { let (client, backend, keystore, mut task_manager, on_demand) = sc_service::new_light_parts::(&config)?; diff --git a/client/cli/Cargo.toml b/client/cli/Cargo.toml index 65cf7ee642c23..385a4d29abf27 100644 --- a/client/cli/Cargo.toml +++ b/client/cli/Cargo.toml @@ -53,6 +53,7 @@ serde = "1.0.111" tracing = "0.1.10" tracing-log = "0.1.1" tracing-subscriber = "0.2.10" +sc-cli-derive = { version = "2.0.0", path = "./derive" } [target.'cfg(not(target_os = "unknown"))'.dependencies] rpassword = "4.0.1" diff --git a/client/cli/derive/Cargo.toml b/client/cli/derive/Cargo.toml new file mode 100644 index 0000000000000..53fe7f744cadd --- /dev/null +++ b/client/cli/derive/Cargo.toml @@ -0,0 +1,20 @@ +[package] +name = "sc-cli-derive" +version = "2.0.0" +authors = ["Parity Technologies "] +edition = "2018" +license = "Apache-2.0" +homepage = "https://substrate.dev" +repository = "https://github.com/paritytech/substrate/" +description = "Helper macros for Substrate's client CLI" + +[package.metadata.docs.rs] +targets = ["x86_64-unknown-linux-gnu"] + +[lib] +proc-macro = true + +[dependencies] +proc-macro2 = "1.0.6" +quote = { version = "1.0.3", features = ["proc-macro"] } +syn = { version = "1.0.7", features = ["proc-macro" ,"full", "extra-traits", "parsing"] } diff --git a/client/cli/derive/src/lib.rs b/client/cli/derive/src/lib.rs new file mode 100644 index 0000000000000..b54ffb71b69ff --- /dev/null +++ b/client/cli/derive/src/lib.rs @@ -0,0 +1,36 @@ +use proc_macro::TokenStream; +use proc_macro2::Span; +use quote::quote; +use syn::{Error, Expr, ItemFn}; + +#[proc_macro_attribute] +pub fn substrate_cli_node_name(arg: TokenStream, item: TokenStream) -> TokenStream { + let item_fn = syn::parse_macro_input!(item as ItemFn); + + if arg.is_empty() { + return Error::new(Span::call_site(), "missing expression (name of the node)") + .to_compile_error() + .into(); + } + + let name = syn::parse_macro_input!(arg as Expr); + + let ItemFn { + attrs, + vis, + sig, + block, + } = item_fn; + + (quote! { + #(#attrs)* + #vis #sig { + // TODO: use whatever imported name for the crate + let span = ::sc_cli::tracing::info_span!("substrate-node", name = #name); + let _enter = span.enter(); + + #block + } + }) + .into() +} diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index a4c6cc0d86c3d..f7527134a21ab 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -47,6 +47,9 @@ use structopt::{ use tracing_subscriber::{ filter::Directive, fmt::time::ChronoLocal, layer::SubscriberExt, FmtSubscriber, Layer, }; +#[doc(hidden)] +pub use tracing; +pub use sc_cli_derive::*; /// Substrate client CLI /// diff --git a/client/cli/src/logging.rs b/client/cli/src/logging.rs index 880413a1cd9b9..09fa4995f6eec 100644 --- a/client/cli/src/logging.rs +++ b/client/cli/src/logging.rs @@ -81,21 +81,18 @@ where } // Custom code to display node name - let mut found_node_name = false; - ctx.visit_spans::(|span| { - if !found_node_name { - let exts = span.extensions(); - if let Some(node_name) = exts.get::() { - found_node_name = true; - write!(writer, "{}", node_name.as_str()) - } else { - Ok(()) - } - } else { - Ok(()) + let mut found_node_name = None; + ctx.visit_spans::<(), _>(|span| { + let exts = span.extensions(); + if let Some(node_name) = exts.get::() { + found_node_name = Some(node_name.as_str().to_owned()); } + Ok(()) }) .unwrap(); + if let Some(node_name) = found_node_name { + write!(writer, "{}", node_name)?; + } let fmt_ctx = { FmtCtx::new(&ctx, event.parent(), self.ansi) }; write!(writer, "{}", fmt_ctx)?; @@ -139,18 +136,22 @@ where struct NodeNameVisitor<'a, W: std::fmt::Write>(&'a mut W); -impl<'a, W: std::fmt::Write> tracing::field::Visit for NodeNameVisitor<'a, W> { - fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { - if field.name() == "name" { - write!(self.0, "[name = {:?}]", value).unwrap(); +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).unwrap(); + } } - } + }; +} - fn record_str(&mut self, field: &tracing::field::Field, value: &str) { - if field.name() == "name" { - write!(self.0, "[{}] ", value).unwrap(); - } - } +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)] diff --git a/client/service/src/builder.rs b/client/service/src/builder.rs index 3f72845703302..410198af26da3 100644 --- a/client/service/src/builder.rs +++ b/client/service/src/builder.rs @@ -490,9 +490,6 @@ pub fn spawn_tasks( telemetry_connection_sinks, } = params; - let span = tracing::info_span!("substrate-node", name = config.network.node_name.as_str()); - let _enter = span.enter(); - let chain_info = client.usage_info().chain; sp_session::generate_initial_session_keys( From 825748060bb6aee638f07a6bbc47045151edb015 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Fri, 16 Oct 2020 07:24:27 +0200 Subject: [PATCH 13/42] WIP Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master --- Cargo.lock | 1 + client/cli/derive/Cargo.toml | 3 ++- client/cli/derive/src/lib.rs | 17 ++++++++++++++--- 3 files changed, 17 insertions(+), 4 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 985a596900504..5c4646515cf33 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6365,6 +6365,7 @@ dependencies = [ name = "sc-cli-derive" version = "2.0.0" dependencies = [ + "proc-macro-crate", "proc-macro2", "quote", "syn", diff --git a/client/cli/derive/Cargo.toml b/client/cli/derive/Cargo.toml index 53fe7f744cadd..bdae061e1ee4f 100644 --- a/client/cli/derive/Cargo.toml +++ b/client/cli/derive/Cargo.toml @@ -15,6 +15,7 @@ targets = ["x86_64-unknown-linux-gnu"] proc-macro = true [dependencies] +proc-macro-crate = "0.1.4" proc-macro2 = "1.0.6" quote = { version = "1.0.3", features = ["proc-macro"] } -syn = { version = "1.0.7", features = ["proc-macro" ,"full", "extra-traits", "parsing"] } +syn = { version = "1.0.7", features = ["proc-macro", "full", "extra-traits", "parsing"] } diff --git a/client/cli/derive/src/lib.rs b/client/cli/derive/src/lib.rs index b54ffb71b69ff..9c940acb61285 100644 --- a/client/cli/derive/src/lib.rs +++ b/client/cli/derive/src/lib.rs @@ -1,7 +1,8 @@ use proc_macro::TokenStream; use proc_macro2::Span; +use proc_macro_crate::crate_name; use quote::quote; -use syn::{Error, Expr, ItemFn}; +use syn::{Error, Expr, Ident, ItemFn}; #[proc_macro_attribute] pub fn substrate_cli_node_name(arg: TokenStream, item: TokenStream) -> TokenStream { @@ -15,6 +16,17 @@ pub fn substrate_cli_node_name(arg: TokenStream, item: TokenStream) -> TokenStre let name = syn::parse_macro_input!(arg as Expr); + let crate_name = if std::env::var("CARGO_PKG_NAME").unwrap() == "sc-cli" { + Ident::new("sc_cli", Span::call_site().into()) + } else { + let crate_name = match crate_name("sc-cli") { + Ok(x) => x, + Err(err) => return Error::new(Span::call_site(), err).to_compile_error().into(), + }; + + Ident::new(&crate_name, Span::call_site().into()) + }; + let ItemFn { attrs, vis, @@ -25,8 +37,7 @@ pub fn substrate_cli_node_name(arg: TokenStream, item: TokenStream) -> TokenStre (quote! { #(#attrs)* #vis #sig { - // TODO: use whatever imported name for the crate - let span = ::sc_cli::tracing::info_span!("substrate-node", name = #name); + let span = #crate_name::tracing::info_span!("substrate-node", name = #name); let _enter = span.enter(); #block From 47f7d3f2ebb5cb6a04597517c3a6008f4ffe290c Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Fri, 16 Oct 2020 07:27:10 +0200 Subject: [PATCH 14/42] CLEANUP Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master --- client/cli/derive/src/lib.rs | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) diff --git a/client/cli/derive/src/lib.rs b/client/cli/derive/src/lib.rs index 9c940acb61285..d6ac3a31217e7 100644 --- a/client/cli/derive/src/lib.rs +++ b/client/cli/derive/src/lib.rs @@ -1,3 +1,21 @@ +// 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 proc_macro::TokenStream; use proc_macro2::Span; use proc_macro_crate::crate_name; From efb9b822a0045c2ed743862098c4fbfac7c43732 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Fri, 16 Oct 2020 08:03:22 +0200 Subject: [PATCH 15/42] WIP Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master --- client/cli/src/logging.rs | 18 ++++++++---------- 1 file changed, 8 insertions(+), 10 deletions(-) diff --git a/client/cli/src/logging.rs b/client/cli/src/logging.rs index 09fa4995f6eec..3159aaeb628a5 100644 --- a/client/cli/src/logging.rs +++ b/client/cli/src/logging.rs @@ -81,17 +81,15 @@ where } // Custom code to display node name - let mut found_node_name = None; - ctx.visit_spans::<(), _>(|span| { - let exts = span.extensions(); - if let Some(node_name) = exts.get::() { - found_node_name = Some(node_name.as_str().to_owned()); + 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; + } } - Ok(()) - }) - .unwrap(); - if let Some(node_name) = found_node_name { - write!(writer, "{}", node_name)?; } let fmt_ctx = { FmtCtx::new(&ctx, event.parent(), self.ansi) }; From 346eaf1babfbc96c12d433d37156fbd0c7b7812a Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Fri, 16 Oct 2020 08:16:35 +0200 Subject: [PATCH 16/42] Some doc --- client/cli/derive/src/lib.rs | 74 ++++++++++++++++++++++++++++++++++++ 1 file changed, 74 insertions(+) diff --git a/client/cli/derive/src/lib.rs b/client/cli/derive/src/lib.rs index d6ac3a31217e7..e34c9ae26c1f5 100644 --- a/client/cli/derive/src/lib.rs +++ b/client/cli/derive/src/lib.rs @@ -22,6 +22,80 @@ use proc_macro_crate::crate_name; use quote::quote; use syn::{Error, Expr, Ident, ItemFn}; +/// Macro that inserts a span with the node name at the beginning of the function. This prefix all +/// the log lines with `[]` (after the timestamp). +/// +/// # Implementation notes +/// +/// If there are multiple spans with a node name, only the latest will be shown. +/// +/// # Example with a literal +/// +/// ```ignore +/// Builds a new service for a light client. +/// #[sc_cli::substrate_cli_node_name("light")] +/// pub fn new_light(config: Configuration) -> Result { +/// let (client, backend, keystore, mut task_manager, on_demand) = +/// sc_service::new_light_parts::(&config)?; +/// +/// ... +/// } +/// ``` +/// +/// Will produce logs that look like this: +/// +/// ```text +/// 2020-10-16 08:03:14 Substrate Node +/// 2020-10-16 08:03:14 ✌️ version 2.0.0-47f7d3f2e-x86_64-linux-gnu +/// 2020-10-16 08:03:14 ❤️ by Anonymous, 2017-2020 +/// 2020-10-16 08:03:14 📋 Chain specification: Local Testnet +/// 2020-10-16 08:03:14 🏷 Node name: nice-glove-1401 +/// 2020-10-16 08:03:14 👤 Role: LIGHT +/// 2020-10-16 08:03:14 💾 Database: RocksDb at /tmp/substrate95w2Dk/chains/local_testnet/db +/// 2020-10-16 08:03:14 ⛓ Native runtime: node-template-1 (node-template-1.tx1.au1) +/// 2020-10-16 08:03:14 [light] 🔨 Initializing Genesis block/state (state: 0x121d…8e36, header-hash: 0x24ef…8ff6) +/// 2020-10-16 08:03:14 [light] Loading GRANDPA authorities from genesis on what appears to be first startup. +/// 2020-10-16 08:03:15 [light] ⏱ Loaded block-time = 6000 milliseconds from genesis on first-launch +/// 2020-10-16 08:03:15 [light] Using default protocol ID "sup" because none is configured in the chain specs +/// 2020-10-16 08:03:15 [light] 🏷 Local node identity is: 12D3KooWHX4rkWT6a6N55Km7ZnvenGdShSKPkzJ3yj9DU5nqDtWR +/// 2020-10-16 08:03:15 [light] 📦 Highest known block at #0 +/// 2020-10-16 08:03:15 [light] 〽️ Prometheus server started at 127.0.0.1:9615 +/// 2020-10-16 08:03:15 [light] Listening for new connections on 127.0.0.1:9944. +/// ``` +/// +/// # Example using the actual node name +/// +/// ```ignore +/// Builds a new service for a light client. +/// #[sc_cli::substrate_cli_node_name(config.network.node_name.as_str())] +/// pub fn new_light(config: Configuration) -> Result { +/// let (client, backend, keystore, mut task_manager, on_demand) = +/// sc_service::new_light_parts::(&config)?; +/// +/// ... +/// } +/// ``` +/// +/// Will produce logs that look like this: +/// +/// ```text +/// 2020-10-16 08:12:57 Substrate Node +/// 2020-10-16 08:12:57 ✌️ version 2.0.0-efb9b822a-x86_64-linux-gnu +/// 2020-10-16 08:12:57 ❤️ by Anonymous, 2017-2020 +/// 2020-10-16 08:12:57 📋 Chain specification: Local Testnet +/// 2020-10-16 08:12:57 🏷 Node name: open-harbor-1619 +/// 2020-10-16 08:12:57 👤 Role: LIGHT +/// 2020-10-16 08:12:57 💾 Database: RocksDb at /tmp/substrate9T9Mtb/chains/local_testnet/db +/// 2020-10-16 08:12:57 ⛓ Native runtime: node-template-1 (node-template-1.tx1.au1) +/// 2020-10-16 08:12:58 [open-harbor-1619] 🔨 Initializing Genesis block/state (state: 0x121d…8e36, header-hash: 0x24ef…8ff6) +/// 2020-10-16 08:12:58 [open-harbor-1619] Loading GRANDPA authorities from genesis on what appears to be first startup. +/// 2020-10-16 08:12:58 [open-harbor-1619] ⏱ Loaded block-time = 6000 milliseconds from genesis on first-launch +/// 2020-10-16 08:12:58 [open-harbor-1619] Using default protocol ID "sup" because none is configured in the chain specs +/// 2020-10-16 08:12:58 [open-harbor-1619] 🏷 Local node identity is: 12D3KooWRzmYC8QTK1Pm8Cfvid3skTS4Hn54jc4AUtje8Rqbfgtp +/// 2020-10-16 08:12:58 [open-harbor-1619] 📦 Highest known block at #0 +/// 2020-10-16 08:12:58 [open-harbor-1619] 〽️ Prometheus server started at 127.0.0.1:9615 +/// 2020-10-16 08:12:58 [open-harbor-1619] Listening for new connections on 127.0.0.1:9944. +/// ``` #[proc_macro_attribute] pub fn substrate_cli_node_name(arg: TokenStream, item: TokenStream) -> TokenStream { let item_fn = syn::parse_macro_input!(item as ItemFn); From 9055ec2206808ba3ddce6e3d87eb358907fa5e42 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Fri, 16 Oct 2020 08:33:13 +0200 Subject: [PATCH 17/42] Test with trybuild --- Cargo.lock | 1 + client/cli/Cargo.toml | 1 + client/cli/tests/ui.rs | 23 +++++++++++++++++++++++ 3 files changed, 25 insertions(+) create mode 100644 client/cli/tests/ui.rs diff --git a/Cargo.lock b/Cargo.lock index 5c4646515cf33..b3abaaefb5fb5 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6359,6 +6359,7 @@ dependencies = [ "tracing", "tracing-log", "tracing-subscriber", + "trybuild", ] [[package]] diff --git a/client/cli/Cargo.toml b/client/cli/Cargo.toml index 385a4d29abf27..fa94d8610ae5a 100644 --- a/client/cli/Cargo.toml +++ b/client/cli/Cargo.toml @@ -65,6 +65,7 @@ nix = "0.17.0" tempfile = "3.1.0" sp-io = { version = "2.0.0-rc3", path = "../../primitives/io" } sp-application-crypto = { version = "2.0.0-alpha.2", default-features = false, path = "../../primitives/application-crypto" } +trybuild = { version = "1.0.35", features = ["diff"] } [features] wasmtime = [ diff --git a/client/cli/tests/ui.rs b/client/cli/tests/ui.rs new file mode 100644 index 0000000000000..ab2c6f5b2faf6 --- /dev/null +++ b/client/cli/tests/ui.rs @@ -0,0 +1,23 @@ +// 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 . + +#[test] +fn sc_cli_derive_trybuild() { + let t = trybuild::TestCases::new(); + t.compile_fail("tests/ui/missing_argument.rs"); +} From d46d87b93223bf50fa6695296c4fe8b79e5c58c4 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Fri, 16 Oct 2020 08:33:26 +0200 Subject: [PATCH 18/42] Revert "Test with trybuild" (issue with trybuild atm) This reverts commit 9055ec2206808ba3ddce6e3d87eb358907fa5e42. https://github.com/dtolnay/trybuild/issues/53 --- Cargo.lock | 1 - client/cli/Cargo.toml | 1 - client/cli/tests/ui.rs | 23 ----------------------- 3 files changed, 25 deletions(-) delete mode 100644 client/cli/tests/ui.rs diff --git a/Cargo.lock b/Cargo.lock index b3abaaefb5fb5..5c4646515cf33 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6359,7 +6359,6 @@ dependencies = [ "tracing", "tracing-log", "tracing-subscriber", - "trybuild", ] [[package]] diff --git a/client/cli/Cargo.toml b/client/cli/Cargo.toml index fa94d8610ae5a..385a4d29abf27 100644 --- a/client/cli/Cargo.toml +++ b/client/cli/Cargo.toml @@ -65,7 +65,6 @@ nix = "0.17.0" tempfile = "3.1.0" sp-io = { version = "2.0.0-rc3", path = "../../primitives/io" } sp-application-crypto = { version = "2.0.0-alpha.2", default-features = false, path = "../../primitives/application-crypto" } -trybuild = { version = "1.0.35", features = ["diff"] } [features] wasmtime = [ diff --git a/client/cli/tests/ui.rs b/client/cli/tests/ui.rs deleted file mode 100644 index ab2c6f5b2faf6..0000000000000 --- a/client/cli/tests/ui.rs +++ /dev/null @@ -1,23 +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 . - -#[test] -fn sc_cli_derive_trybuild() { - let t = trybuild::TestCases::new(); - t.compile_fail("tests/ui/missing_argument.rs"); -} From 2401a7ca12b271c3f3dd902e3e86bf0ead1be293 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Fri, 16 Oct 2020 13:39:38 +0200 Subject: [PATCH 19/42] Apply suggestions --- client/cli/derive/src/lib.rs | 5 ++++- client/cli/src/logging.rs | 6 +++--- 2 files changed, 7 insertions(+), 4 deletions(-) diff --git a/client/cli/derive/src/lib.rs b/client/cli/derive/src/lib.rs index e34c9ae26c1f5..24a9bf2e33d61 100644 --- a/client/cli/derive/src/lib.rs +++ b/client/cli/derive/src/lib.rs @@ -108,7 +108,10 @@ pub fn substrate_cli_node_name(arg: TokenStream, item: TokenStream) -> TokenStre let name = syn::parse_macro_input!(arg as Expr); - let crate_name = if std::env::var("CARGO_PKG_NAME").unwrap() == "sc-cli" { + let crate_name = if std::env::var("CARGO_PKG_NAME") + .expect("cargo env var always there when compiling; qed") + == "sc-cli" + { Ident::new("sc_cli", Span::call_site().into()) } else { let crate_name = match crate_name("sc-cli") { diff --git a/client/cli/src/logging.rs b/client/cli/src/logging.rs index 3159aaeb628a5..7760940a510d4 100644 --- a/client/cli/src/logging.rs +++ b/client/cli/src/logging.rs @@ -43,7 +43,7 @@ pub(crate) struct EventFormat { pub(crate) display_thread_name: bool, } -// NOTE: the following code has been inspiref from tracing-subscriber +// 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 @@ -138,7 +138,7 @@ 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).unwrap(); + write!(self.0, $format, value).expect("no way to return the err; qed"); } } }; @@ -274,7 +274,7 @@ where } } -// NOTE: the following code has been inspired from tracing-subscriber +// NOTE: the following code took inspiration from tracing-subscriber // // https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/format/mod.rs#L711 impl<'a, S, N: 'a> fmt::Display for FmtCtx<'a, S, N> From 25970af0fe1f757c1055aad3354c5baaac709725 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Fri, 16 Oct 2020 13:47:52 +0200 Subject: [PATCH 20/42] Rename derive to proc-macro --- Cargo.lock | 4 ++-- Cargo.toml | 2 +- client/cli/Cargo.toml | 2 +- client/cli/{derive => proc-macro}/Cargo.toml | 2 +- client/cli/{derive => proc-macro}/src/lib.rs | 0 client/cli/src/lib.rs | 2 +- 6 files changed, 6 insertions(+), 6 deletions(-) rename client/cli/{derive => proc-macro}/Cargo.toml (95%) rename client/cli/{derive => proc-macro}/src/lib.rs (100%) diff --git a/Cargo.lock b/Cargo.lock index 0ddc649604800..a0c12bc8455d9 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6340,7 +6340,7 @@ dependencies = [ "rand 0.7.3", "regex", "rpassword", - "sc-cli-derive", + "sc-cli-proc-macro", "sc-client-api", "sc-consensus-babe", "sc-consensus-epochs", @@ -6375,7 +6375,7 @@ dependencies = [ ] [[package]] -name = "sc-cli-derive" +name = "sc-cli-proc-macro" version = "2.0.0" dependencies = [ "proc-macro-crate", diff --git a/Cargo.toml b/Cargo.toml index 2bb3468fecd08..ccfd0ab5fdf1b 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -21,7 +21,7 @@ members = [ "client/chain-spec", "client/chain-spec/derive", "client/cli", - "client/cli/derive", + "client/cli/proc-macro", "client/consensus/aura", "client/consensus/babe", "client/consensus/babe/rpc", diff --git a/client/cli/Cargo.toml b/client/cli/Cargo.toml index 606f3caf1bfdf..c19d61aecc102 100644 --- a/client/cli/Cargo.toml +++ b/client/cli/Cargo.toml @@ -57,7 +57,7 @@ serde = "1.0.111" tracing = "0.1.10" tracing-log = "0.1.1" tracing-subscriber = "0.2.10" -sc-cli-derive = { version = "2.0.0", path = "./derive" } +sc-cli-proc-macro = { version = "2.0.0", path = "./proc-macro" } [target.'cfg(not(target_os = "unknown"))'.dependencies] rpassword = "4.0.1" diff --git a/client/cli/derive/Cargo.toml b/client/cli/proc-macro/Cargo.toml similarity index 95% rename from client/cli/derive/Cargo.toml rename to client/cli/proc-macro/Cargo.toml index bdae061e1ee4f..9b9d134c5a836 100644 --- a/client/cli/derive/Cargo.toml +++ b/client/cli/proc-macro/Cargo.toml @@ -1,5 +1,5 @@ [package] -name = "sc-cli-derive" +name = "sc-cli-proc-macro" version = "2.0.0" authors = ["Parity Technologies "] edition = "2018" diff --git a/client/cli/derive/src/lib.rs b/client/cli/proc-macro/src/lib.rs similarity index 100% rename from client/cli/derive/src/lib.rs rename to client/cli/proc-macro/src/lib.rs diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 28d75b5759ffd..307bd446fe0d4 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -49,7 +49,7 @@ use tracing_subscriber::{ }; #[doc(hidden)] pub use tracing; -pub use sc_cli_derive::*; +pub use sc_cli_proc_macro::*; /// Substrate client CLI /// From 848061935b6bc4514cfc3e01d1783116cd8237a2 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Fri, 16 Oct 2020 14:10:57 +0200 Subject: [PATCH 21/42] Remove "prefix" feature from informant --- client/informant/src/display.rs | 6 ++---- client/informant/src/lib.rs | 30 ++++-------------------------- utils/browser/src/lib.rs | 1 - 3 files changed, 6 insertions(+), 31 deletions(-) diff --git a/client/informant/src/display.rs b/client/informant/src/display.rs index ce7fb4fc4b12b..aa2d883b5baa0 100644 --- a/client/informant/src/display.rs +++ b/client/informant/src/display.rs @@ -104,9 +104,8 @@ impl InformantDisplay { if self.format.enable_color { info!( target: "substrate", - "{} {}{}{} ({} peers), best: #{} ({}), finalized #{} ({}), {} {}", + "{} {}{} ({} peers), best: #{} ({}), finalized #{} ({}), {} {}", level, - self.format.prefix, Colour::White.bold().paint(&status), target, Colour::White.bold().paint(format!("{}", num_connected_peers)), @@ -120,9 +119,8 @@ impl InformantDisplay { } else { info!( target: "substrate", - "{} {}{}{} ({} peers), best: #{} ({}), finalized #{} ({}), ⬇ {} ⬆ {}", + "{} {}{} ({} peers), best: #{} ({}), finalized #{} ({}), ⬇ {} ⬆ {}", level, - self.format.prefix, status, target, num_connected_peers, diff --git a/client/informant/src/lib.rs b/client/informant/src/lib.rs index a1f0ba9ae5fac..c60eda76f63f6 100644 --- a/client/informant/src/lib.rs +++ b/client/informant/src/lib.rs @@ -37,29 +37,12 @@ mod display; pub struct OutputFormat { /// Enable color output in logs. True by default. pub enable_color: bool, - /// Defines the informant's prefix for the logs. An empty string by default. - /// - /// By default substrate will show logs without a prefix. Example: - /// - /// ```text - /// 2020-05-28 15:11:06 ✨ Imported #2 (0xc21c…2ca8) - /// 2020-05-28 15:11:07 💤 Idle (0 peers), best: #2 (0xc21c…2ca8), finalized #0 (0x7299…e6df), ⬇ 0 ⬆ 0 - /// ``` - /// - /// But you can define a prefix by setting this string. This will output: - /// - /// ```text - /// 2020-05-28 15:11:06 ✨ [Prefix] Imported #2 (0xc21c…2ca8) - /// 2020-05-28 15:11:07 💤 [Prefix] Idle (0 peers), best: #2 (0xc21c…2ca8), finalized #0 (0x7299…e6df), ⬇ 0 ⬆ 0 - /// ``` - pub prefix: String, } impl Default for OutputFormat { fn default() -> Self { Self { enable_color: true, - prefix: String::new(), } } } @@ -118,14 +101,11 @@ where future::join( display_notifications, - display_block_import(client, format.prefix), + display_block_import(client), ).map(|_| ()) } -fn display_block_import( - client: Arc, - prefix: String, -) -> impl Future +fn display_block_import(client: Arc) -> impl Future where C: UsageProvider + HeaderMetadata + BlockchainEvents, >::Error: Display, @@ -151,8 +131,7 @@ where match maybe_ancestor { Ok(ref ancestor) if ancestor.hash != *last_hash => info!( - "♻️ {}Reorg on #{},{} to #{},{}, common ancestor #{},{}", - prefix, + "♻️ Reorg on #{},{} to #{},{}, common ancestor #{},{}", Colour::Red.bold().paint(format!("{}", last_num)), last_hash, Colour::Green.bold().paint(format!("{}", n.header.number())), n.hash, Colour::White.bold().paint(format!("{}", ancestor.number)), ancestor.hash, @@ -179,8 +158,7 @@ where info!( target: "substrate", - "✨ {}Imported #{} ({})", - prefix, + "✨ Imported #{} ({})", Colour::White.bold().paint(format!("{}", n.header.number())), n.hash, ); diff --git a/utils/browser/src/lib.rs b/utils/browser/src/lib.rs index 196282ddecab7..e31db1d77c9d5 100644 --- a/utils/browser/src/lib.rs +++ b/utils/browser/src/lib.rs @@ -104,7 +104,6 @@ where base_path: None, informant_output_format: sc_informant::OutputFormat { enable_color: false, - prefix: String::new(), }, }; From b14c3f8ef5d1cfc80512906a0919b9b76a4b4207 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Fri, 16 Oct 2020 18:01:37 +0200 Subject: [PATCH 22/42] Blocking task should use SpawnHandle::spawn_blocking --- bin/node-template/node/src/service.rs | 1 + bin/node/bench/src/construct.rs | 3 +- bin/node/cli/src/service.rs | 1 + bin/node/testing/src/bench.rs | 21 ++++++++---- .../basic-authorship/src/basic_authorship.rs | 33 +++++++++++++++---- client/service/src/task_manager/mod.rs | 2 +- 6 files changed, 46 insertions(+), 15 deletions(-) diff --git a/bin/node-template/node/src/service.rs b/bin/node-template/node/src/service.rs index a88d447f74199..7d32d54986eec 100644 --- a/bin/node-template/node/src/service.rs +++ b/bin/node-template/node/src/service.rs @@ -146,6 +146,7 @@ pub fn new_full(config: Configuration) -> Result { if role.is_authority() { let proposer = sc_basic_authorship::ProposerFactory::new( + Box::new(task_manager.spawn_handle()), client.clone(), transaction_pool, prometheus_registry.as_ref(), diff --git a/bin/node/bench/src/construct.rs b/bin/node/bench/src/construct.rs index e23594dd4364a..5506dc426de0b 100644 --- a/bin/node/bench/src/construct.rs +++ b/bin/node/bench/src/construct.rs @@ -147,6 +147,7 @@ impl core::Benchmark for ConstructionBenchmark { } let mut proposer_factory = sc_basic_authorship::ProposerFactory::new( + context.spawn_handle.clone(), context.client.clone(), self.transactions.clone().into(), None, @@ -293,4 +294,4 @@ impl sp_transaction_pool::TransactionPool for Transactions { fn ready_transaction(&self, _hash: &TxHash) -> Option> { unimplemented!() } -} \ No newline at end of file +} diff --git a/bin/node/cli/src/service.rs b/bin/node/cli/src/service.rs index 3502ed196e752..dd9523003a55e 100644 --- a/bin/node/cli/src/service.rs +++ b/bin/node/cli/src/service.rs @@ -231,6 +231,7 @@ pub fn new_full_base( if let sc_service::config::Role::Authority { .. } = &role { let proposer = sc_basic_authorship::ProposerFactory::new( + Box::new(task_manager.spawn_handle()), client.clone(), transaction_pool.clone(), prometheus_registry.as_ref(), diff --git a/bin/node/testing/src/bench.rs b/bin/node/testing/src/bench.rs index 754552fe4f174..153a52375c2a9 100644 --- a/bin/node/testing/src/bench.rs +++ b/bin/node/testing/src/bench.rs @@ -373,7 +373,12 @@ impl BenchDb { "Created seed db at {}", dir.path().to_string_lossy(), ); - let (_client, _backend) = Self::bench_client(database_type, dir.path(), Profile::Native, &keyring); + let (_client, _backend, _task_executor) = Self::bench_client( + database_type, + dir.path(), + Profile::Native, + &keyring, + ); let directory_guard = Guard(dir); BenchDb { keyring, directory_guard, database_type } @@ -401,13 +406,14 @@ impl BenchDb { dir: &std::path::Path, profile: Profile, keyring: &BenchKeyring, - ) -> (Client, std::sync::Arc) { + ) -> (Client, std::sync::Arc, TaskExecutor) { let db_config = sc_client_db::DatabaseSettings { state_cache_size: 16*1024*1024, state_cache_child_ratio: Some((0, 100)), pruning: PruningMode::ArchiveAll, source: database_type.into_settings(dir.into()), }; + let task_executor = TaskExecutor::new(); let (client, backend) = sc_service::new_client( db_config, @@ -416,12 +422,12 @@ impl BenchDb { None, None, ExecutionExtensions::new(profile.into_execution_strategies(), None), - Box::new(TaskExecutor::new()), + Box::new(task_executor.clone()), None, Default::default(), ).expect("Should not fail"); - (client, backend) + (client, backend, task_executor) } /// Generate list of required inherents. @@ -450,7 +456,7 @@ impl BenchDb { /// Get cliet for this database operations. pub fn client(&mut self) -> Client { - let (client, _backend) = Self::bench_client( + let (client, _backend, _task_executor) = Self::bench_client( self.database_type, self.directory_guard.path(), Profile::Wasm, @@ -504,7 +510,7 @@ impl BenchDb { /// Clone this database and create context for testing/benchmarking. pub fn create_context(&self, profile: Profile) -> BenchContext { let BenchDb { directory_guard, keyring, database_type } = self.clone(); - let (client, backend) = Self::bench_client( + let (client, backend, task_executor) = Self::bench_client( database_type, directory_guard.path(), profile, @@ -515,6 +521,7 @@ impl BenchDb { client: Arc::new(client), db_guard: directory_guard, backend, + spawn_handle: Box::new(task_executor), } } } @@ -649,6 +656,8 @@ pub struct BenchContext { pub client: Arc, /// Node backend. pub backend: Arc, + /// Spawn handle. + pub spawn_handle: Box, db_guard: Guard, } diff --git a/client/basic-authorship/src/basic_authorship.rs b/client/basic-authorship/src/basic_authorship.rs index 41d12970464f4..3d56437b107a9 100644 --- a/client/basic-authorship/src/basic_authorship.rs +++ b/client/basic-authorship/src/basic_authorship.rs @@ -20,10 +20,11 @@ // FIXME #1021 move this into sp-consensus -use std::{time, sync::Arc}; +use std::{pin::Pin, time, sync::Arc}; use sc_client_api::backend; use codec::Decode; use sp_consensus::{evaluation, Proposal, RecordProof}; +use sp_core::traits::SpawnNamed; use sp_inherents::InherentData; use log::{error, info, debug, trace, warn}; use sp_runtime::{ @@ -34,7 +35,7 @@ use sp_transaction_pool::{TransactionPool, InPoolTransaction}; use sc_telemetry::{telemetry, CONSENSUS_INFO}; use sc_block_builder::{BlockBuilderApi, BlockBuilderProvider}; use sp_api::{ProvideRuntimeApi, ApiExt}; -use futures::{executor, future, future::Either}; +use futures::{executor, future, future::{Either, Future}, channel::oneshot}; use sp_blockchain::{HeaderBackend, ApplyExtrinsicFailed::Validity, Error::ApplyExtrinsicFailed}; use std::marker::PhantomData; @@ -43,6 +44,7 @@ use sc_proposer_metrics::MetricsLink as PrometheusMetrics; /// Proposer factory. pub struct ProposerFactory { + spawn_handle: Box, /// The client instance. client: Arc, /// The transaction pool. @@ -55,11 +57,13 @@ pub struct ProposerFactory { impl ProposerFactory { pub fn new( + spawn_handle: Box, client: Arc, transaction_pool: Arc, prometheus: Option<&PrometheusRegistry>, ) -> Self { ProposerFactory { + spawn_handle, client, transaction_pool, metrics: PrometheusMetrics::new(prometheus), @@ -90,6 +94,7 @@ impl ProposerFactory info!("🙌 Starting consensus session on top of parent {:?}", parent_hash); let proposer = Proposer { + spawn_handle: self.spawn_handle.clone(), client: self.client.clone(), parent_hash, parent_id: id, @@ -129,6 +134,7 @@ impl sp_consensus::Environment for /// The proposer logic. pub struct Proposer { + spawn_handle: Box, client: Arc, parent_hash: ::Hash, parent_id: BlockId, @@ -151,9 +157,9 @@ impl sp_consensus::Proposer for + BlockBuilderApi, { type Transaction = backend::TransactionFor; - type Proposal = tokio_executor::blocking::Blocking< - Result, Self::Error> - >; + type Proposal = Pin, Self::Error> + > + Send>>; type Error = sp_blockchain::Error; fn propose( @@ -163,10 +169,23 @@ impl sp_consensus::Proposer for max_duration: time::Duration, record_proof: RecordProof, ) -> Self::Proposal { - tokio_executor::blocking::run(move || { + let (tx, rx) = oneshot::channel(); + let spawn_handle = self.spawn_handle.clone(); + + spawn_handle.spawn_blocking("basic-authorship-proposer", Box::pin(async move { // leave some time for evaluation and block finalization (33%) let deadline = (self.now)() + max_duration - max_duration / 3; - self.propose_with(inherent_data, inherent_digests, deadline, record_proof) + let res = self.propose_with(inherent_data, inherent_digests, deadline, record_proof); + if tx.send(res).is_err() { + error!("Could not send message to oneshot channel"); + } + })); + + Box::pin(async move { + match rx.await { + Ok(x) => x, + Err(err) => Err(sp_blockchain::Error::Msg(err.to_string())) + } }) } } diff --git a/client/service/src/task_manager/mod.rs b/client/service/src/task_manager/mod.rs index a0aeba3009dee..4199af2e9aaad 100644 --- a/client/service/src/task_manager/mod.rs +++ b/client/service/src/task_manager/mod.rs @@ -228,7 +228,7 @@ pub struct TaskManager { impl TaskManager { /// If a Prometheus registry is passed, it will be used to report statistics about the /// service tasks. - pub(super) fn new( + pub fn new( executor: TaskExecutor, prometheus_registry: Option<&Registry> ) -> Result { From 499ade7b557ea21878d0ae6bd7ff37b4445c27ef Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Fri, 16 Oct 2020 18:22:54 +0200 Subject: [PATCH 23/42] Improve doc as suggested --- client/cli/proc-macro/src/lib.rs | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/client/cli/proc-macro/src/lib.rs b/client/cli/proc-macro/src/lib.rs index 24a9bf2e33d61..a042187f95191 100644 --- a/client/cli/proc-macro/src/lib.rs +++ b/client/cli/proc-macro/src/lib.rs @@ -22,8 +22,14 @@ use proc_macro_crate::crate_name; use quote::quote; use syn::{Error, Expr, Ident, ItemFn}; -/// Macro that inserts a span with the node name at the beginning of the function. This prefix all -/// the log lines with `[]` (after the timestamp). +/// Macro that inserts a tracing span with the node name at the beginning of the function. This +/// prefixes all the log lines with `[]` (after the timestamp). Tracing's span are propagated +/// to all the child calls and child tasks (futures) if they are spawned properly with the +/// `SpawnHandle` (see `TaskManager` in sc-cli) or if the futures use `.in_current_span()` (see +/// tracing-futures). +/// +/// See Tokio's [tracing documentation](https://docs.rs/tracing-core/) and +/// [tracing-futures documentation](https://docs.rs/tracing-futures/) for more details. /// /// # Implementation notes /// From aea5b5339ad0134f85c6dd6d24b9e53a2a9446c6 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Fri, 16 Oct 2020 18:38:31 +0200 Subject: [PATCH 24/42] Fixes Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master --- bin/node/cli/src/service.rs | 1 + .../basic-authorship/src/basic_authorship.rs | 36 ++++++++++++++----- client/consensus/manual-seal/src/lib.rs | 9 +++-- client/service/test/src/lib.rs | 5 +++ 4 files changed, 40 insertions(+), 11 deletions(-) diff --git a/bin/node/cli/src/service.rs b/bin/node/cli/src/service.rs index dd9523003a55e..89ab4186888ad 100644 --- a/bin/node/cli/src/service.rs +++ b/bin/node/cli/src/service.rs @@ -558,6 +558,7 @@ mod tests { ); let mut proposer_factory = sc_basic_authorship::ProposerFactory::new( + Box::new(service.spawn_handle()), service.client(), service.transaction_pool(), None, diff --git a/client/basic-authorship/src/basic_authorship.rs b/client/basic-authorship/src/basic_authorship.rs index 3d56437b107a9..90a1e6f2b2b26 100644 --- a/client/basic-authorship/src/basic_authorship.rs +++ b/client/basic-authorship/src/basic_authorship.rs @@ -379,7 +379,7 @@ mod tests { let txpool = BasicPool::new_full( Default::default(), None, - spawner, + spawner.clone(), client.clone(), ); @@ -395,7 +395,12 @@ mod tests { )) ); - let mut proposer_factory = ProposerFactory::new(client.clone(), txpool.clone(), None); + let mut proposer_factory = ProposerFactory::new( + Box::new(spawner.clone()), + client.clone(), + txpool.clone(), + None, + ); let cell = Mutex::new((false, time::Instant::now())); let proposer = proposer_factory.init_with_now( @@ -432,11 +437,16 @@ mod tests { let txpool = BasicPool::new_full( Default::default(), None, - spawner, + spawner.clone(), client.clone(), ); - let mut proposer_factory = ProposerFactory::new(client.clone(), txpool.clone(), None); + let mut proposer_factory = ProposerFactory::new( + Box::new(spawner.clone()), + client.clone(), + txpool.clone(), + None, + ); let cell = Mutex::new((false, time::Instant::now())); let proposer = proposer_factory.init_with_now( @@ -467,7 +477,7 @@ mod tests { let txpool = BasicPool::new_full( Default::default(), None, - spawner, + spawner.clone(), client.clone(), ); @@ -486,7 +496,12 @@ mod tests { )) ); - let mut proposer_factory = ProposerFactory::new(client.clone(), txpool.clone(), None); + let mut proposer_factory = ProposerFactory::new( + Box::new(spawner.clone()), + client.clone(), + txpool.clone(), + None, + ); let proposer = proposer_factory.init_with_now( &client.header(&block_id).unwrap().unwrap(), @@ -529,7 +544,7 @@ mod tests { let txpool = BasicPool::new_full( Default::default(), None, - spawner, + spawner.clone(), client.clone(), ); @@ -555,7 +570,12 @@ mod tests { ]) ).unwrap(); - let mut proposer_factory = ProposerFactory::new(client.clone(), txpool.clone(), None); + let mut proposer_factory = ProposerFactory::new( + Box::new(spawner.clone()), + client.clone(), + txpool.clone(), + None, + ); let mut propose_block = | client: &TestClient, number, diff --git a/client/consensus/manual-seal/src/lib.rs b/client/consensus/manual-seal/src/lib.rs index 0a8ed28a27c81..1267c14421251 100644 --- a/client/consensus/manual-seal/src/lib.rs +++ b/client/consensus/manual-seal/src/lib.rs @@ -294,9 +294,10 @@ mod tests { let inherent_data_providers = InherentDataProviders::new(); let spawner = sp_core::testing::TaskExecutor::new(); let pool = Arc::new(BasicPool::with_revalidation_type( - Options::default(), api(), None, RevalidationType::Full, spawner, + Options::default(), api(), None, RevalidationType::Full, spawner.clone(), )); let env = ProposerFactory::new( + Box::new(spawner.clone()), client.clone(), pool.clone(), None, @@ -365,9 +366,10 @@ mod tests { let inherent_data_providers = InherentDataProviders::new(); let spawner = sp_core::testing::TaskExecutor::new(); let pool = Arc::new(BasicPool::with_revalidation_type( - Options::default(), api(), None, RevalidationType::Full, spawner, + Options::default(), api(), None, RevalidationType::Full, spawner.clone(), )); let env = ProposerFactory::new( + Box::new(spawner.clone()), client.clone(), pool.clone(), None, @@ -440,9 +442,10 @@ mod tests { let pool_api = api(); let spawner = sp_core::testing::TaskExecutor::new(); let pool = Arc::new(BasicPool::with_revalidation_type( - Options::default(), pool_api.clone(), None, RevalidationType::Full, spawner, + Options::default(), pool_api.clone(), None, RevalidationType::Full, spawner.clone(), )); let env = ProposerFactory::new( + Box::new(spawner.clone()), client.clone(), pool.clone(), None, diff --git a/client/service/test/src/lib.rs b/client/service/test/src/lib.rs index 7c4e28f4ddc4a..50966b52fc7ee 100644 --- a/client/service/test/src/lib.rs +++ b/client/service/test/src/lib.rs @@ -31,6 +31,7 @@ use tokio::{runtime::Runtime, prelude::FutureExt}; use tokio::timer::Interval; use sc_service::{ TaskManager, + SpawnTaskHandle, GenericChainSpec, ChainSpecExtension, Configuration, @@ -75,6 +76,7 @@ pub trait TestNetNode: Clone + Future + Se fn client(&self) -> Arc>; fn transaction_pool(&self) -> Arc; fn network(&self) -> Arc::Hash>>; + fn spawn_handle(&self) -> SpawnTaskHandle; } pub struct TestNetComponents { @@ -147,6 +149,9 @@ TestNetComponents fn network(&self) -> Arc::Hash>> { self.network.clone() } + fn spawn_handle(&self) -> SpawnTaskHandle { + self.task_manager.lock().spawn_handle() + } } impl TestNet From 0c838903f81f5f4c358c6b11bcd45953ce9866ac Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Fri, 16 Oct 2020 18:44:04 +0200 Subject: [PATCH 25/42] Apply suggestion --- client/cli/proc-macro/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/cli/proc-macro/src/lib.rs b/client/cli/proc-macro/src/lib.rs index a042187f95191..27050647f15a8 100644 --- a/client/cli/proc-macro/src/lib.rs +++ b/client/cli/proc-macro/src/lib.rs @@ -107,7 +107,7 @@ pub fn substrate_cli_node_name(arg: TokenStream, item: TokenStream) -> TokenStre let item_fn = syn::parse_macro_input!(item as ItemFn); if arg.is_empty() { - return Error::new(Span::call_site(), "missing expression (name of the node)") + return Error::new(Span::call_site(), "missing expression: name of the node (in argument)") .to_compile_error() .into(); } From 2e6b6136dc635b6c891dfcc97f6a4749cde53e42 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Wed, 21 Oct 2020 09:40:02 +0200 Subject: [PATCH 26/42] Update client/cli/proc-macro/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/proc-macro/src/lib.rs | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/client/cli/proc-macro/src/lib.rs b/client/cli/proc-macro/src/lib.rs index 27050647f15a8..7a86c54e4a376 100644 --- a/client/cli/proc-macro/src/lib.rs +++ b/client/cli/proc-macro/src/lib.rs @@ -22,8 +22,9 @@ use proc_macro_crate::crate_name; use quote::quote; use syn::{Error, Expr, Ident, ItemFn}; -/// Macro that inserts a tracing span with the node name at the beginning of the function. This -/// prefixes all the log lines with `[]` (after the timestamp). Tracing's span are propagated +/// Macro that inserts a tracing span with the node name at the beginning of the function. +/// +/// This prefixes all the log lines with `[]` (after the timestamp). Tracing's span are propagated /// to all the child calls and child tasks (futures) if they are spawned properly with the /// `SpawnHandle` (see `TaskManager` in sc-cli) or if the futures use `.in_current_span()` (see /// tracing-futures). From 3f61450c69408752c08e9396381f326a4783e4e9 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Wed, 21 Oct 2020 09:40:53 +0200 Subject: [PATCH 27/42] More suggestions --- bin/node-template/node/src/service.rs | 2 +- client/basic-authorship/src/basic_authorship.rs | 6 +++--- client/cli/proc-macro/src/lib.rs | 4 ++-- 3 files changed, 6 insertions(+), 6 deletions(-) diff --git a/bin/node-template/node/src/service.rs b/bin/node-template/node/src/service.rs index 7d32d54986eec..1408bd0bb0fc4 100644 --- a/bin/node-template/node/src/service.rs +++ b/bin/node-template/node/src/service.rs @@ -223,7 +223,7 @@ pub fn new_full(config: Configuration) -> Result { } /// Builds a new service for a light client. -#[sc_cli::substrate_cli_node_name("light")] +#[sc_cli::prefix_logs_with("light")] pub fn new_light(config: Configuration) -> Result { let (client, backend, keystore_container, mut task_manager, on_demand) = sc_service::new_light_parts::(&config)?; diff --git a/client/basic-authorship/src/basic_authorship.rs b/client/basic-authorship/src/basic_authorship.rs index 90a1e6f2b2b26..5b0bb773e1e39 100644 --- a/client/basic-authorship/src/basic_authorship.rs +++ b/client/basic-authorship/src/basic_authorship.rs @@ -35,7 +35,7 @@ use sp_transaction_pool::{TransactionPool, InPoolTransaction}; use sc_telemetry::{telemetry, CONSENSUS_INFO}; use sc_block_builder::{BlockBuilderApi, BlockBuilderProvider}; use sp_api::{ProvideRuntimeApi, ApiExt}; -use futures::{executor, future, future::{Either, Future}, channel::oneshot}; +use futures::{executor, future, future::{Either, Future, FutureExt}, channel::oneshot}; use sp_blockchain::{HeaderBackend, ApplyExtrinsicFailed::Validity, Error::ApplyExtrinsicFailed}; use std::marker::PhantomData; @@ -181,12 +181,12 @@ impl sp_consensus::Proposer for } })); - Box::pin(async move { + async move { match rx.await { Ok(x) => x, Err(err) => Err(sp_blockchain::Error::Msg(err.to_string())) } - }) + }.boxed() } } diff --git a/client/cli/proc-macro/src/lib.rs b/client/cli/proc-macro/src/lib.rs index 7a86c54e4a376..a519ce16f74dc 100644 --- a/client/cli/proc-macro/src/lib.rs +++ b/client/cli/proc-macro/src/lib.rs @@ -104,11 +104,11 @@ use syn::{Error, Expr, Ident, ItemFn}; /// 2020-10-16 08:12:58 [open-harbor-1619] Listening for new connections on 127.0.0.1:9944. /// ``` #[proc_macro_attribute] -pub fn substrate_cli_node_name(arg: TokenStream, item: TokenStream) -> TokenStream { +pub fn prefix_logs_with(arg: TokenStream, item: TokenStream) -> TokenStream { let item_fn = syn::parse_macro_input!(item as ItemFn); if arg.is_empty() { - return Error::new(Span::call_site(), "missing expression: name of the node (in argument)") + return Error::new(Span::call_site(), "missing expression in argument: name of the node") .to_compile_error() .into(); } From a5544804ed2dd77d0bf10432f6b8856613df0800 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Wed, 21 Oct 2020 09:42:01 +0200 Subject: [PATCH 28/42] CLEANUP Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master --- client/cli/proc-macro/src/lib.rs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/client/cli/proc-macro/src/lib.rs b/client/cli/proc-macro/src/lib.rs index a519ce16f74dc..57b0a54d18273 100644 --- a/client/cli/proc-macro/src/lib.rs +++ b/client/cli/proc-macro/src/lib.rs @@ -22,11 +22,11 @@ use proc_macro_crate::crate_name; use quote::quote; use syn::{Error, Expr, Ident, ItemFn}; -/// Macro that inserts a tracing span with the node name at the beginning of the function. +/// Macro that inserts a tracing span with the node name at the beginning of the function. /// -/// This prefixes all the log lines with `[]` (after the timestamp). Tracing's span are propagated -/// to all the child calls and child tasks (futures) if they are spawned properly with the -/// `SpawnHandle` (see `TaskManager` in sc-cli) or if the futures use `.in_current_span()` (see +/// This prefixes all the log lines with `[]` (after the timestamp). Tracing's span are +/// propagated to all the child calls and child tasks (futures) if they are spawned properly with +/// the `SpawnHandle` (see `TaskManager` in sc-cli) or if the futures use `.in_current_span()` (see /// tracing-futures). /// /// See Tokio's [tracing documentation](https://docs.rs/tracing-core/) and From 58a72845c7c9a58c72e78e58bdccc7f77a419bb2 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Wed, 21 Oct 2020 09:46:29 +0200 Subject: [PATCH 29/42] Improve error message --- client/cli/proc-macro/src/lib.rs | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/client/cli/proc-macro/src/lib.rs b/client/cli/proc-macro/src/lib.rs index 57b0a54d18273..e54a4aba55087 100644 --- a/client/cli/proc-macro/src/lib.rs +++ b/client/cli/proc-macro/src/lib.rs @@ -108,9 +108,12 @@ pub fn prefix_logs_with(arg: TokenStream, item: TokenStream) -> TokenStream { let item_fn = syn::parse_macro_input!(item as ItemFn); if arg.is_empty() { - return Error::new(Span::call_site(), "missing expression in argument: name of the node") - .to_compile_error() - .into(); + return Error::new( + Span::call_site(), + "missing argument: name of the node. Example: sc_cli::prefix_logs_with()", + ) + .to_compile_error() + .into(); } let name = syn::parse_macro_input!(arg as Expr); From de4678fcb7cda37bfcb914d82d6a0312d636ba7f Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Wed, 21 Oct 2020 09:52:26 +0200 Subject: [PATCH 30/42] CLEANUP Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master --- client/service/src/task_manager/mod.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/service/src/task_manager/mod.rs b/client/service/src/task_manager/mod.rs index 4199af2e9aaad..a0aeba3009dee 100644 --- a/client/service/src/task_manager/mod.rs +++ b/client/service/src/task_manager/mod.rs @@ -228,7 +228,7 @@ pub struct TaskManager { impl TaskManager { /// If a Prometheus registry is passed, it will be used to report statistics about the /// service tasks. - pub fn new( + pub(super) fn new( executor: TaskExecutor, prometheus_registry: Option<&Registry> ) -> Result { From c101a09c311f801caf952cab9d449c4719d58cfb Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Wed, 21 Oct 2020 12:00:35 +0200 Subject: [PATCH 31/42] Fix async issue --- .../basic-authorship/src/basic_authorship.rs | 29 ++++++++++++------- 1 file changed, 18 insertions(+), 11 deletions(-) diff --git a/client/basic-authorship/src/basic_authorship.rs b/client/basic-authorship/src/basic_authorship.rs index 5b0bb773e1e39..743a76b4c14c3 100644 --- a/client/basic-authorship/src/basic_authorship.rs +++ b/client/basic-authorship/src/basic_authorship.rs @@ -35,7 +35,7 @@ use sp_transaction_pool::{TransactionPool, InPoolTransaction}; use sc_telemetry::{telemetry, CONSENSUS_INFO}; use sc_block_builder::{BlockBuilderApi, BlockBuilderProvider}; use sp_api::{ProvideRuntimeApi, ApiExt}; -use futures::{executor, future, future::{Either, Future, FutureExt}, channel::oneshot}; +use futures::{executor, future, future::{Either, Future, FutureExt}, channel::oneshot, select}; use sp_blockchain::{HeaderBackend, ApplyExtrinsicFailed::Validity, Error::ApplyExtrinsicFailed}; use std::marker::PhantomData; @@ -175,7 +175,12 @@ impl sp_consensus::Proposer for spawn_handle.spawn_blocking("basic-authorship-proposer", Box::pin(async move { // leave some time for evaluation and block finalization (33%) let deadline = (self.now)() + max_duration - max_duration / 3; - let res = self.propose_with(inherent_data, inherent_digests, deadline, record_proof); + let res = self.propose_with( + inherent_data, + inherent_digests, + deadline, + record_proof, + ).await; if tx.send(res).is_err() { error!("Could not send message to oneshot channel"); } @@ -200,7 +205,7 @@ impl Proposer C::Api: ApiExt> + BlockBuilderApi, { - fn propose_with( + async fn propose_with( self, inherent_data: InherentData, inherent_digests: DigestFor, @@ -237,18 +242,20 @@ impl Proposer let block_timer = time::Instant::now(); let mut skipped = 0; let mut unqueue_invalid = Vec::new(); - let pending_iterator = match executor::block_on(future::select( - self.transaction_pool.ready_at(self.parent_number), - futures_timer::Delay::new(deadline.saturating_duration_since((self.now)()) / 8), - )) { - Either::Left((iterator, _)) => iterator, - Either::Right(_) => { + + let mut t1 = self.transaction_pool.ready_at(self.parent_number).fuse(); + let mut t2 = futures_timer::Delay::new(deadline.saturating_duration_since((self.now)()) / 8).fuse(); + + let pending_iterator = select! { + res = t1 => res, + _ = t2 => { log::warn!( - "Timeout fired waiting for transaction pool at block #{}. Proceeding with production.", + "Timeout fired waiting for transaction pool at block #{}. \ + Proceeding with production.", self.parent_number, ); self.transaction_pool.ready() - } + }, }; debug!("Attempting to push transactions from the pool."); From 35ae15236fb5e79477907b869c3a65b5c0f62b84 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Wed, 21 Oct 2020 12:26:16 +0200 Subject: [PATCH 32/42] CLEANUP Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master --- client/basic-authorship/src/basic_authorship.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/basic-authorship/src/basic_authorship.rs b/client/basic-authorship/src/basic_authorship.rs index 743a76b4c14c3..09c1df27c6b2b 100644 --- a/client/basic-authorship/src/basic_authorship.rs +++ b/client/basic-authorship/src/basic_authorship.rs @@ -35,7 +35,7 @@ use sp_transaction_pool::{TransactionPool, InPoolTransaction}; use sc_telemetry::{telemetry, CONSENSUS_INFO}; use sc_block_builder::{BlockBuilderApi, BlockBuilderProvider}; use sp_api::{ProvideRuntimeApi, ApiExt}; -use futures::{executor, future, future::{Either, Future, FutureExt}, channel::oneshot, select}; +use futures::{executor, future, future::{Future, FutureExt}, channel::oneshot, select}; use sp_blockchain::{HeaderBackend, ApplyExtrinsicFailed::Validity, Error::ApplyExtrinsicFailed}; use std::marker::PhantomData; From fb4c7bb7a34ba2e92b6588993f936530a64d2696 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Wed, 21 Oct 2020 12:39:21 +0200 Subject: [PATCH 33/42] CLEANUP Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master --- client/basic-authorship/src/basic_authorship.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/basic-authorship/src/basic_authorship.rs b/client/basic-authorship/src/basic_authorship.rs index 09c1df27c6b2b..74397406107c2 100644 --- a/client/basic-authorship/src/basic_authorship.rs +++ b/client/basic-authorship/src/basic_authorship.rs @@ -35,7 +35,7 @@ use sp_transaction_pool::{TransactionPool, InPoolTransaction}; use sc_telemetry::{telemetry, CONSENSUS_INFO}; use sc_block_builder::{BlockBuilderApi, BlockBuilderProvider}; use sp_api::{ProvideRuntimeApi, ApiExt}; -use futures::{executor, future, future::{Future, FutureExt}, channel::oneshot, select}; +use futures::{future, future::{Future, FutureExt}, channel::oneshot, select}; use sp_blockchain::{HeaderBackend, ApplyExtrinsicFailed::Validity, Error::ApplyExtrinsicFailed}; use std::marker::PhantomData; From 2238794d099d9b5f131127238883f2f5a5d2d6fc Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Wed, 21 Oct 2020 13:05:59 +0200 Subject: [PATCH 34/42] Add test --- bin/node-template/node/src/service.rs | 1 - client/cli/src/lib.rs | 45 +++++++++++++++++++++++---- 2 files changed, 39 insertions(+), 7 deletions(-) diff --git a/bin/node-template/node/src/service.rs b/bin/node-template/node/src/service.rs index 1408bd0bb0fc4..4063ae814450c 100644 --- a/bin/node-template/node/src/service.rs +++ b/bin/node-template/node/src/service.rs @@ -223,7 +223,6 @@ pub fn new_full(config: Configuration) -> Result { } /// Builds a new service for a light client. -#[sc_cli::prefix_logs_with("light")] pub fn new_light(config: Configuration) -> Result { let (client, backend, keystore_container, mut task_manager, on_demand) = sc_service::new_light_parts::(&config)?; diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 307bd446fe0d4..29c3ab62d62c5 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -25,9 +25,9 @@ pub mod arg_enums; mod commands; mod config; mod error; +mod logging; mod params; mod runner; -mod logging; pub use arg_enums::*; pub use commands::*; @@ -35,8 +35,9 @@ pub use config::*; pub use error::*; pub use params::*; pub use runner::*; -use sc_service::{Configuration, TaskExecutor}; +pub use sc_cli_proc_macro::*; pub use sc_service::{ChainSpec, Role}; +use sc_service::{Configuration, TaskExecutor}; pub use sp_version::RuntimeVersion; use std::io::Write; pub use structopt; @@ -44,12 +45,11 @@ use structopt::{ clap::{self, AppSettings}, StructOpt, }; +#[doc(hidden)] +pub use tracing; use tracing_subscriber::{ filter::Directive, fmt::time::ChronoLocal, layer::SubscriberExt, FmtSubscriber, Layer, }; -#[doc(hidden)] -pub use tracing; -pub use sc_cli_proc_macro::*; /// Substrate client CLI /// @@ -345,8 +345,9 @@ pub fn init_logger( #[cfg(test)] mod tests { use super::*; + use crate as sc_cli; + use std::{env, process::Command}; use tracing::{metadata::Kind, subscriber::Interest, Callsite, Level, Metadata}; - use std::{process::Command, env}; #[test] fn test_logger_filters() { @@ -415,4 +416,36 @@ mod tests { log::info!(target: "test-target", "{}", EXPECTED_LOG_MESSAGE); } } + + const EXPECTED_NODE_NAME: &'static str = "THE_NODE"; + + #[test] + fn prefix_in_log_lines() { + let executable = env::current_exe().unwrap(); + let output = Command::new(executable) + .env("ENABLE_LOGGING", "1") + .args(&["--nocapture", "prefix_in_log_lines_entrypoint"]) + .output() + .unwrap(); + + let output = String::from_utf8(output.stderr).unwrap(); + assert!(output.contains(&format!(" [{}] ", EXPECTED_NODE_NAME))); + } + + /// This is no actual test, it will be used by the `prefix_in_log_lines` test. + /// The given test will call the test executable to only execute this test that + /// will only print a log line prefixed by the node name `EXPECTED_NODE_NAME`. + #[test] + 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(); + prefix_in_log_lines_process(); + } + } + + #[crate::prefix_logs_with(EXPECTED_NODE_NAME)] + fn prefix_in_log_lines_process() { + log::info!("Hello World!"); + } } From c4e0039c345bff6e5a8f92d0f6b77aca24756aee Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Wed, 21 Oct 2020 13:14:26 +0200 Subject: [PATCH 35/42] fix doc test --- client/basic-authorship/src/lib.rs | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/client/basic-authorship/src/lib.rs b/client/basic-authorship/src/lib.rs index b405fc6de0f01..f85fc71d89627 100644 --- a/client/basic-authorship/src/lib.rs +++ b/client/basic-authorship/src/lib.rs @@ -35,11 +35,16 @@ //! # let txpool = BasicPool::new_full( //! # Default::default(), //! # None, -//! # spawner, +//! # spawner.clone(), //! # client.clone(), //! # ); //! // The first step is to create a `ProposerFactory`. -//! let mut proposer_factory = ProposerFactory::new(client.clone(), txpool.clone(), None); +//! let mut proposer_factory = ProposerFactory::new( +//! Box::new(spawner), +//! client.clone(), +//! txpool.clone(), +//! None, +//! ); //! //! // From this factory, we create a `Proposer`. //! let proposer = proposer_factory.init( From 275206274b1e242282aea9f0de73835f688952ab Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Wed, 21 Oct 2020 15:00:57 +0200 Subject: [PATCH 36/42] Update client/cli/src/logging.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/logging.rs | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/client/cli/src/logging.rs b/client/cli/src/logging.rs index 7760940a510d4..5f40e80c95fc3 100644 --- a/client/cli/src/logging.rs +++ b/client/cli/src/logging.rs @@ -17,9 +17,7 @@ // along with this program. If not, see . use ansi_term::{Colour, Style}; -use std::fmt; -use std::fmt::Write as _; -use std::iter; +use std::{fmt::{self, Write as _}, iter}; use tracing::{ span::{self, Attributes}, Event, Id, Level, Subscriber, From 208bbe2e38e0b370c2a2cdae192bde8eec27ad26 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Wed, 21 Oct 2020 15:09:01 +0200 Subject: [PATCH 37/42] Update client/basic-authorship/src/basic_authorship.rs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Bastian Köcher --- client/basic-authorship/src/basic_authorship.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/client/basic-authorship/src/basic_authorship.rs b/client/basic-authorship/src/basic_authorship.rs index 74397406107c2..f32547ec6b9b3 100644 --- a/client/basic-authorship/src/basic_authorship.rs +++ b/client/basic-authorship/src/basic_authorship.rs @@ -57,13 +57,13 @@ pub struct ProposerFactory { impl ProposerFactory { pub fn new( - spawn_handle: Box, + spawn_handle: impl SpawnNamed + 'static, client: Arc, transaction_pool: Arc, prometheus: Option<&PrometheusRegistry>, ) -> Self { ProposerFactory { - spawn_handle, + spawn_handle: Box::new(spawn_handle), client, transaction_pool, metrics: PrometheusMetrics::new(prometheus), From 243dd6cf60a9859488ec15041bbd745d0b8203a0 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Wed, 21 Oct 2020 15:09:22 +0200 Subject: [PATCH 38/42] Update client/basic-authorship/src/basic_authorship.rs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Bastian Köcher --- client/basic-authorship/src/basic_authorship.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/basic-authorship/src/basic_authorship.rs b/client/basic-authorship/src/basic_authorship.rs index f32547ec6b9b3..91a9b37833a28 100644 --- a/client/basic-authorship/src/basic_authorship.rs +++ b/client/basic-authorship/src/basic_authorship.rs @@ -182,7 +182,7 @@ impl sp_consensus::Proposer for record_proof, ).await; if tx.send(res).is_err() { - error!("Could not send message to oneshot channel"); + trace!("Could not send block production result to proposer!"); } })); From 929bd1ecfff687a8ce67f19c5a630bfdaf32b8ba Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Wed, 21 Oct 2020 15:09:35 +0200 Subject: [PATCH 39/42] Apply suggestions --- client/cli/proc-macro/src/lib.rs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/client/cli/proc-macro/src/lib.rs b/client/cli/proc-macro/src/lib.rs index e54a4aba55087..ce6138fa00e1f 100644 --- a/client/cli/proc-macro/src/lib.rs +++ b/client/cli/proc-macro/src/lib.rs @@ -22,7 +22,7 @@ use proc_macro_crate::crate_name; use quote::quote; use syn::{Error, Expr, Ident, ItemFn}; -/// Macro that inserts a tracing span with the node name at the beginning of the function. +/// Add a log prefix to the function. /// /// This prefixes all the log lines with `[]` (after the timestamp). Tracing's span are /// propagated to all the child calls and child tasks (futures) if they are spawned properly with @@ -34,13 +34,13 @@ use syn::{Error, Expr, Ident, ItemFn}; /// /// # Implementation notes /// -/// If there are multiple spans with a node name, only the latest will be shown. +/// If there are multiple spans with a log prefix, only the latest will be shown. /// /// # Example with a literal /// /// ```ignore /// Builds a new service for a light client. -/// #[sc_cli::substrate_cli_node_name("light")] +/// #[sc_cli::prefix_logs_with("light")] /// pub fn new_light(config: Configuration) -> Result { /// let (client, backend, keystore, mut task_manager, on_demand) = /// sc_service::new_light_parts::(&config)?; @@ -74,7 +74,7 @@ use syn::{Error, Expr, Ident, ItemFn}; /// /// ```ignore /// Builds a new service for a light client. -/// #[sc_cli::substrate_cli_node_name(config.network.node_name.as_str())] +/// #[sc_cli::prefix_logs_with(config.network.node_name.as_str())] /// pub fn new_light(config: Configuration) -> Result { /// let (client, backend, keystore, mut task_manager, on_demand) = /// sc_service::new_light_parts::(&config)?; From f12a3f766c5a446024656d165f5962b1fb49cc0d Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Wed, 21 Oct 2020 15:27:08 +0200 Subject: [PATCH 40/42] Suggestions --- bin/node-template/node/src/service.rs | 2 +- bin/node/cli/src/service.rs | 4 ++-- client/basic-authorship/src/basic_authorship.rs | 8 ++++---- client/cli/proc-macro/src/lib.rs | 5 ++++- client/cli/src/lib.rs | 2 ++ client/cli/src/logging.rs | 5 ++++- client/consensus/manual-seal/src/lib.rs | 6 +++--- 7 files changed, 20 insertions(+), 12 deletions(-) diff --git a/bin/node-template/node/src/service.rs b/bin/node-template/node/src/service.rs index 4063ae814450c..90187061c9cf7 100644 --- a/bin/node-template/node/src/service.rs +++ b/bin/node-template/node/src/service.rs @@ -146,7 +146,7 @@ pub fn new_full(config: Configuration) -> Result { if role.is_authority() { let proposer = sc_basic_authorship::ProposerFactory::new( - Box::new(task_manager.spawn_handle()), + task_manager.spawn_handle(), client.clone(), transaction_pool, prometheus_registry.as_ref(), diff --git a/bin/node/cli/src/service.rs b/bin/node/cli/src/service.rs index 89ab4186888ad..3d5bb8a329af4 100644 --- a/bin/node/cli/src/service.rs +++ b/bin/node/cli/src/service.rs @@ -231,7 +231,7 @@ pub fn new_full_base( if let sc_service::config::Role::Authority { .. } = &role { let proposer = sc_basic_authorship::ProposerFactory::new( - Box::new(task_manager.spawn_handle()), + task_manager.spawn_handle(), client.clone(), transaction_pool.clone(), prometheus_registry.as_ref(), @@ -558,7 +558,7 @@ mod tests { ); let mut proposer_factory = sc_basic_authorship::ProposerFactory::new( - Box::new(service.spawn_handle()), + service.spawn_handle(), service.client(), service.transaction_pool(), None, diff --git a/client/basic-authorship/src/basic_authorship.rs b/client/basic-authorship/src/basic_authorship.rs index 91a9b37833a28..89edfac0d4e98 100644 --- a/client/basic-authorship/src/basic_authorship.rs +++ b/client/basic-authorship/src/basic_authorship.rs @@ -403,7 +403,7 @@ mod tests { ); let mut proposer_factory = ProposerFactory::new( - Box::new(spawner.clone()), + spawner.clone(), client.clone(), txpool.clone(), None, @@ -449,7 +449,7 @@ mod tests { ); let mut proposer_factory = ProposerFactory::new( - Box::new(spawner.clone()), + spawner.clone(), client.clone(), txpool.clone(), None, @@ -504,7 +504,7 @@ mod tests { ); let mut proposer_factory = ProposerFactory::new( - Box::new(spawner.clone()), + spawner.clone(), client.clone(), txpool.clone(), None, @@ -578,7 +578,7 @@ mod tests { ).unwrap(); let mut proposer_factory = ProposerFactory::new( - Box::new(spawner.clone()), + spawner.clone(), client.clone(), txpool.clone(), None, diff --git a/client/cli/proc-macro/src/lib.rs b/client/cli/proc-macro/src/lib.rs index ce6138fa00e1f..9a1273069c6ed 100644 --- a/client/cli/proc-macro/src/lib.rs +++ b/client/cli/proc-macro/src/lib.rs @@ -142,7 +142,10 @@ pub fn prefix_logs_with(arg: TokenStream, item: TokenStream) -> TokenStream { (quote! { #(#attrs)* #vis #sig { - let span = #crate_name::tracing::info_span!("substrate-node", name = #name); + let span = #crate_name::tracing::info_span!( + #crate_name::PREFIX_LOG_SPAN, + name = #name, + ); let _enter = span.enter(); #block diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 29c3ab62d62c5..e63e379533a62 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -51,6 +51,8 @@ use tracing_subscriber::{ filter::Directive, fmt::time::ChronoLocal, layer::SubscriberExt, FmtSubscriber, Layer, }; +pub use logging::PREFIX_LOG_SPAN; + /// Substrate client CLI /// /// This trait needs to be defined on the root structopt of the application. It will provide the diff --git a/client/cli/src/logging.rs b/client/cli/src/logging.rs index 5f40e80c95fc3..3b87d95fe0643 100644 --- a/client/cli/src/logging.rs +++ b/client/cli/src/logging.rs @@ -33,6 +33,9 @@ use tracing_subscriber::{ 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(crate) struct EventFormat { pub(crate) timer: T, pub(crate) ansi: bool, @@ -111,7 +114,7 @@ where .span(id) .expect("new_span has been called for this span; qed"); - if span.name() != "substrate-node" { + if span.name() != PREFIX_LOG_SPAN { return; } diff --git a/client/consensus/manual-seal/src/lib.rs b/client/consensus/manual-seal/src/lib.rs index 1267c14421251..d025d6aaf689f 100644 --- a/client/consensus/manual-seal/src/lib.rs +++ b/client/consensus/manual-seal/src/lib.rs @@ -297,7 +297,7 @@ mod tests { Options::default(), api(), None, RevalidationType::Full, spawner.clone(), )); let env = ProposerFactory::new( - Box::new(spawner.clone()), + spawner.clone(), client.clone(), pool.clone(), None, @@ -369,7 +369,7 @@ mod tests { Options::default(), api(), None, RevalidationType::Full, spawner.clone(), )); let env = ProposerFactory::new( - Box::new(spawner.clone()), + spawner.clone(), client.clone(), pool.clone(), None, @@ -445,7 +445,7 @@ mod tests { Options::default(), pool_api.clone(), None, RevalidationType::Full, spawner.clone(), )); let env = ProposerFactory::new( - Box::new(spawner.clone()), + spawner.clone(), client.clone(), pool.clone(), None, From b9d7723bdac6558b254b0b719cf1d764026510b4 Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Wed, 21 Oct 2020 15:45:58 +0200 Subject: [PATCH 41/42] Clarify doc --- client/cli/proc-macro/src/lib.rs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/client/cli/proc-macro/src/lib.rs b/client/cli/proc-macro/src/lib.rs index 9a1273069c6ed..775d1eb96ea38 100644 --- a/client/cli/proc-macro/src/lib.rs +++ b/client/cli/proc-macro/src/lib.rs @@ -24,10 +24,10 @@ use syn::{Error, Expr, Ident, ItemFn}; /// Add a log prefix to the function. /// -/// This prefixes all the log lines with `[]` (after the timestamp). Tracing's span are -/// propagated to all the child calls and child tasks (futures) if they are spawned properly with -/// the `SpawnHandle` (see `TaskManager` in sc-cli) or if the futures use `.in_current_span()` (see -/// tracing-futures). +/// This prefixes all the log lines with `[]` (after the timestamp). It works by making a +/// tracing's span that is propagated to all the child calls and child tasks (futures) if they are +/// spawned properly with the `SpawnHandle` (see `TaskManager` in sc-cli) or if the futures use +/// `.in_current_span()` (see tracing-futures). /// /// See Tokio's [tracing documentation](https://docs.rs/tracing-core/) and /// [tracing-futures documentation](https://docs.rs/tracing-futures/) for more details. From f141b730fd9a84def96f6009ebe0570ace4efbfe Mon Sep 17 00:00:00 2001 From: Cecile Tonglet Date: Wed, 21 Oct 2020 16:15:08 +0200 Subject: [PATCH 42/42] WIP Forked at: d67fc4c2cb6db6fdd2af92909bd13467c20029e5 Parent branch: origin/master --- client/basic-authorship/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/basic-authorship/src/lib.rs b/client/basic-authorship/src/lib.rs index f85fc71d89627..9b0c491508231 100644 --- a/client/basic-authorship/src/lib.rs +++ b/client/basic-authorship/src/lib.rs @@ -40,7 +40,7 @@ //! # ); //! // The first step is to create a `ProposerFactory`. //! let mut proposer_factory = ProposerFactory::new( -//! Box::new(spawner), +//! spawner, //! client.clone(), //! txpool.clone(), //! None,