diff --git a/Cargo.lock b/Cargo.lock index 15408ba75af6c..a0c12bc8455d9 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6340,6 +6340,7 @@ dependencies = [ "rand 0.7.3", "regex", "rpassword", + "sc-cli-proc-macro", "sc-client-api", "sc-consensus-babe", "sc-consensus-epochs", @@ -6373,6 +6374,16 @@ dependencies = [ "tracing-subscriber", ] +[[package]] +name = "sc-cli-proc-macro" +version = "2.0.0" +dependencies = [ + "proc-macro-crate", + "proc-macro2", + "quote", + "syn", +] + [[package]] name = "sc-client-api" version = "2.0.0" @@ -7218,6 +7229,7 @@ dependencies = [ "tempfile", "tokio 0.2.22", "tracing", + "tracing-futures", "wasm-timer", ] @@ -9456,6 +9468,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/Cargo.toml b/Cargo.toml index dc78ad41571fd..ccfd0ab5fdf1b 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -21,6 +21,7 @@ members = [ "client/chain-spec", "client/chain-spec/derive", "client/cli", + "client/cli/proc-macro", "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 1029685628986..90187061c9cf7 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( + 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..3d5bb8a329af4 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( + task_manager.spawn_handle(), client.clone(), transaction_pool.clone(), prometheus_registry.as_ref(), @@ -557,6 +558,7 @@ mod tests { ); let mut proposer_factory = sc_basic_authorship::ProposerFactory::new( + service.spawn_handle(), service.client(), service.transaction_pool(), None, 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..89edfac0d4e98 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::{future, future::{Future, FutureExt}, channel::oneshot, select}; 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: impl SpawnNamed + 'static, client: Arc, transaction_pool: Arc, prometheus: Option<&PrometheusRegistry>, ) -> Self { ProposerFactory { + spawn_handle: Box::new(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,11 +169,29 @@ 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, + ).await; + if tx.send(res).is_err() { + trace!("Could not send block production result to proposer!"); + } + })); + + async move { + match rx.await { + Ok(x) => x, + Err(err) => Err(sp_blockchain::Error::Msg(err.to_string())) + } + }.boxed() } } @@ -181,7 +205,7 @@ impl Proposer C::Api: ApiExt> + BlockBuilderApi, { - fn propose_with( + async fn propose_with( self, inherent_data: InherentData, inherent_digests: DigestFor, @@ -218,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."); @@ -360,7 +386,7 @@ mod tests { let txpool = BasicPool::new_full( Default::default(), None, - spawner, + spawner.clone(), client.clone(), ); @@ -376,7 +402,12 @@ mod tests { )) ); - let mut proposer_factory = ProposerFactory::new(client.clone(), txpool.clone(), None); + let mut proposer_factory = ProposerFactory::new( + spawner.clone(), + client.clone(), + txpool.clone(), + None, + ); let cell = Mutex::new((false, time::Instant::now())); let proposer = proposer_factory.init_with_now( @@ -413,11 +444,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( + spawner.clone(), + client.clone(), + txpool.clone(), + None, + ); let cell = Mutex::new((false, time::Instant::now())); let proposer = proposer_factory.init_with_now( @@ -448,7 +484,7 @@ mod tests { let txpool = BasicPool::new_full( Default::default(), None, - spawner, + spawner.clone(), client.clone(), ); @@ -467,7 +503,12 @@ mod tests { )) ); - let mut proposer_factory = ProposerFactory::new(client.clone(), txpool.clone(), None); + let mut proposer_factory = ProposerFactory::new( + spawner.clone(), + client.clone(), + txpool.clone(), + None, + ); let proposer = proposer_factory.init_with_now( &client.header(&block_id).unwrap().unwrap(), @@ -510,7 +551,7 @@ mod tests { let txpool = BasicPool::new_full( Default::default(), None, - spawner, + spawner.clone(), client.clone(), ); @@ -536,7 +577,12 @@ mod tests { ]) ).unwrap(); - let mut proposer_factory = ProposerFactory::new(client.clone(), txpool.clone(), None); + let mut proposer_factory = ProposerFactory::new( + spawner.clone(), + client.clone(), + txpool.clone(), + None, + ); let mut propose_block = | client: &TestClient, number, diff --git a/client/basic-authorship/src/lib.rs b/client/basic-authorship/src/lib.rs index b405fc6de0f01..9b0c491508231 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( +//! spawner, +//! client.clone(), +//! txpool.clone(), +//! None, +//! ); //! //! // From this factory, we create a `Proposer`. //! let proposer = proposer_factory.init( diff --git a/client/cli/Cargo.toml b/client/cli/Cargo.toml index 437799895779d..c19d61aecc102 100644 --- a/client/cli/Cargo.toml +++ b/client/cli/Cargo.toml @@ -57,6 +57,7 @@ serde = "1.0.111" tracing = "0.1.10" tracing-log = "0.1.1" tracing-subscriber = "0.2.10" +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/proc-macro/Cargo.toml b/client/cli/proc-macro/Cargo.toml new file mode 100644 index 0000000000000..9b9d134c5a836 --- /dev/null +++ b/client/cli/proc-macro/Cargo.toml @@ -0,0 +1,21 @@ +[package] +name = "sc-cli-proc-macro" +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-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"] } diff --git a/client/cli/proc-macro/src/lib.rs b/client/cli/proc-macro/src/lib.rs new file mode 100644 index 0000000000000..775d1eb96ea38 --- /dev/null +++ b/client/cli/proc-macro/src/lib.rs @@ -0,0 +1,155 @@ +// 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; +use quote::quote; +use syn::{Error, Expr, Ident, ItemFn}; + +/// Add a log prefix to the function. +/// +/// 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. +/// +/// # Implementation notes +/// +/// 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::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)?; +/// +/// ... +/// } +/// ``` +/// +/// 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::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)?; +/// +/// ... +/// } +/// ``` +/// +/// 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 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 argument: name of the node. Example: sc_cli::prefix_logs_with()", + ) + .to_compile_error() + .into(); + } + + let name = syn::parse_macro_input!(arg as Expr); + + 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") { + 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, + sig, + block, + } = item_fn; + + (quote! { + #(#attrs)* + #vis #sig { + let span = #crate_name::tracing::info_span!( + #crate_name::PREFIX_LOG_SPAN, + name = #name, + ); + let _enter = span.enter(); + + #block + } + }) + .into() +} diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index b7d11f68df08e..e63e379533a62 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -25,6 +25,7 @@ pub mod arg_enums; mod commands; mod config; mod error; +mod logging; mod params; mod runner; @@ -34,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; @@ -43,10 +45,14 @@ use structopt::{ clap::{self, AppSettings}, StructOpt, }; +#[doc(hidden)] +pub use tracing; 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 @@ -310,13 +316,15 @@ 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) - .finish(); + .event_format(logging::EventFormat { + timer, + ansi: enable_color, + display_target: !simple, + display_level: !simple, + display_thread_name: !simple, + }) + .finish().with(logging::NodeNameLayer); if let Some(profiling_targets) = profiling_targets { let profiling = sc_tracing::ProfilingLayer::new(tracing_receiver, &profiling_targets); @@ -339,8 +347,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() { @@ -409,4 +418,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!"); + } } diff --git a/client/cli/src/logging.rs b/client/cli/src/logging.rs new file mode 100644 index 0000000000000..3b87d95fe0643 --- /dev/null +++ b/client/cli/src/logging.rs @@ -0,0 +1,337 @@ +// 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::{self, Write as _}, 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, +}; + +/// 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, + pub(crate) display_target: bool, + pub(crate) display_level: bool, + pub(crate) display_thread_name: bool, +} + +// NOTE: the following code took inspiration from tracing-subscriber +// +// https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/format/mod.rs#L449 +impl FormatEvent for EventFormat +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, + T: FormatTime, +{ + fn format_event( + &self, + ctx: &FmtContext, + writer: &mut dyn fmt::Write, + event: &Event, + ) -> fmt::Result { + let normalized_meta = event.normalized_metadata(); + let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata()); + time::write(&self.timer, writer, self.ansi)?; + + if self.display_level { + let fmt_level = { FmtLevel::new(meta.level(), self.ansi) }; + write!(writer, "{} ", fmt_level)?; + } + + if self.display_thread_name { + let current_thread = std::thread::current(); + match current_thread.name() { + Some(name) => { + write!(writer, "{} ", FmtThreadName::new(name))?; + } + // fall-back to thread id when name is absent and ids are not enabled + None => { + write!(writer, "{:0>2?} ", current_thread.id())?; + } + } + } + + // Custom code to display node name + if let Some(span) = ctx.lookup_current() { + let parents = span.parents(); + for span in std::iter::once(span).chain(parents) { + let exts = span.extensions(); + if let Some(node_name) = exts.get::() { + write!(writer, "{}", node_name.as_str())?; + break; + } + } + } + + 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)?; + writeln!(writer) + } +} + +pub(crate) struct NodeNameLayer; + +impl Layer for NodeNameLayer +where + S: Subscriber + for<'a> LookupSpan<'a>, +{ + fn new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { + let span = ctx + .span(id) + .expect("new_span has been called for this span; qed"); + + if span.name() != PREFIX_LOG_SPAN { + return; + } + + let mut extensions = span.extensions_mut(); + + if extensions.get_mut::().is_none() { + let mut s = String::new(); + let mut v = NodeNameVisitor(&mut s); + attrs.record(&mut v); + + if !s.is_empty() { + let fmt_fields = NodeName(s); + extensions.insert(fmt_fields); + } + } + } +} + +struct NodeNameVisitor<'a, W: std::fmt::Write>(&'a mut W); + +macro_rules! write_node_name { + ($method:ident, $type:ty, $format:expr) => { + fn $method(&mut self, field: &tracing::field::Field, value: $type) { + if field.name() == "name" { + write!(self.0, $format, value).expect("no way to return the err; qed"); + } + } + }; +} + +impl<'a, W: std::fmt::Write> tracing::field::Visit for NodeNameVisitor<'a, W> { + write_node_name!(record_debug, &dyn std::fmt::Debug, "[{:?}] "); + write_node_name!(record_str, &str, "[{}] "); + write_node_name!(record_i64, i64, "[{}] "); + write_node_name!(record_u64, u64, "[{}] "); + write_node_name!(record_bool, bool, "[{}] "); +} + +#[derive(Debug)] +struct NodeName(String); + +impl NodeName { + fn as_str(&self) -> &str { + self.0.as_str() + } +} + +struct FmtLevel<'a> { + level: &'a Level, + ansi: bool, +} + +impl<'a> FmtLevel<'a> { + pub(crate) fn new(level: &'a Level, ansi: bool) -> Self { + Self { level, ansi } + } +} + +const TRACE_STR: &str = "TRACE"; +const DEBUG_STR: &str = "DEBUG"; +const INFO_STR: &str = " INFO"; +const WARN_STR: &str = " WARN"; +const ERROR_STR: &str = "ERROR"; + +impl<'a> fmt::Display for FmtLevel<'a> { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + if self.ansi { + match *self.level { + Level::TRACE => write!(f, "{}", Colour::Purple.paint(TRACE_STR)), + Level::DEBUG => write!(f, "{}", Colour::Blue.paint(DEBUG_STR)), + Level::INFO => write!(f, "{}", Colour::Green.paint(INFO_STR)), + Level::WARN => write!(f, "{}", Colour::Yellow.paint(WARN_STR)), + Level::ERROR => write!(f, "{}", Colour::Red.paint(ERROR_STR)), + } + } else { + match *self.level { + Level::TRACE => f.pad(TRACE_STR), + Level::DEBUG => f.pad(DEBUG_STR), + Level::INFO => f.pad(INFO_STR), + Level::WARN => f.pad(WARN_STR), + Level::ERROR => f.pad(ERROR_STR), + } + } + } +} + +struct FmtThreadName<'a> { + name: &'a str, +} + +impl<'a> FmtThreadName<'a> { + pub(crate) fn new(name: &'a str) -> Self { + Self { name } + } +} + +// NOTE: the following code has been duplicated from tracing-subscriber +// +// https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/format/mod.rs#L845 +impl<'a> fmt::Display for FmtThreadName<'a> { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + use std::sync::atomic::{ + AtomicUsize, + Ordering::{AcqRel, Acquire, Relaxed}, + }; + + // Track the longest thread name length we've seen so far in an atomic, + // so that it can be updated by any thread. + static MAX_LEN: AtomicUsize = AtomicUsize::new(0); + let len = self.name.len(); + // Snapshot the current max thread name length. + let mut max_len = MAX_LEN.load(Relaxed); + + while len > max_len { + // Try to set a new max length, if it is still the value we took a + // snapshot of. + match MAX_LEN.compare_exchange(max_len, len, AcqRel, Acquire) { + // We successfully set the new max value + Ok(_) => break, + // Another thread set a new max value since we last observed + // it! It's possible that the new length is actually longer than + // ours, so we'll loop again and check whether our length is + // still the longest. If not, we'll just use the newer value. + Err(actual) => max_len = actual, + } + } + + // pad thread name using `max_len` + write!(f, "{:>width$}", self.name, width = max_len) + } +} + +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() + } +} + +// 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> +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 name in scope + .map(|span| span.metadata().name()) + .filter(|&x| x != "substrate-node") + { + seen = true; + write!(f, "{}:", bold.paint(name))?; + } + + if seen { + f.write_char(' ')?; + } + Ok(()) + } +} + +// NOTE: the following code has been duplicated from tracing-subscriber +// +// https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/time/mod.rs#L252 +mod time { + use ansi_term::Style; + use std::fmt; + use tracing_subscriber::fmt::time::FormatTime; + + pub(crate) fn write(timer: T, writer: &mut dyn fmt::Write, with_ansi: bool) -> fmt::Result + where + T: FormatTime, + { + if with_ansi { + let style = Style::new().dimmed(); + write!(writer, "{}", style.prefix())?; + timer.format_time(writer)?; + write!(writer, "{}", style.suffix())?; + } else { + timer.format_time(writer)?; + } + writer.write_char(' ')?; + Ok(()) + } +} diff --git a/client/consensus/manual-seal/src/lib.rs b/client/consensus/manual-seal/src/lib.rs index 0a8ed28a27c81..d025d6aaf689f 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( + 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( + 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( + spawner.clone(), client.clone(), pool.clone(), None, 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/client/service/Cargo.toml b/client/service/Cargo.toml index 9c0ddbc54c904..ef10b7e906983 100644 --- a/client/service/Cargo.toml +++ b/client/service/Cargo.toml @@ -77,6 +77,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/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 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 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(), }, };