diff --git a/Cargo.lock b/Cargo.lock index 3a68eb4b1dd9d..9a7083875beb7 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -133,12 +133,6 @@ version = "0.4.7" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "db55d72333851e17d572bec876e390cd3b11eb1ef53ae821dd9f3b653d2b4569" -[[package]] -name = "arc-swap" -version = "0.4.7" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "4d25d88fd6b8041580a654f9d0c581a047baee2b3efee13275f2fc392fc75034" - [[package]] name = "arrayref" version = "0.3.6" @@ -797,16 +791,6 @@ dependencies = [ "wasm-bindgen", ] -[[package]] -name = "console_log" -version = "0.2.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "501a375961cef1a0d44767200e66e4a559283097e91d0730b1d75dfb2f8a1494" -dependencies = [ - "log", - "web-sys", -] - [[package]] name = "const_fn" version = "0.4.3" @@ -3818,7 +3802,6 @@ dependencies = [ "substrate-build-script-utils", "substrate-frame-cli", "tempfile", - "tracing", "wasm-bindgen", "wasm-bindgen-futures", ] @@ -4023,6 +4006,7 @@ dependencies = [ "sc-rpc", "sc-rpc-api", "sc-service", + "sc-telemetry", "sc-transaction-pool", "sp-api", "sp-block-builder", @@ -6547,8 +6531,6 @@ dependencies = [ name = "sc-cli" version = "0.8.1" dependencies = [ - "ansi_term 0.12.1", - "atty", "chrono", "fdlimit", "futures 0.3.9", @@ -6560,7 +6542,6 @@ dependencies = [ "rand 0.7.3", "regex", "rpassword", - "sc-cli-proc-macro", "sc-client-api", "sc-keystore", "sc-network", @@ -6582,19 +6563,6 @@ dependencies = [ "thiserror", "tiny-bip39", "tokio 0.2.23", - "tracing", - "tracing-log", - "tracing-subscriber", -] - -[[package]] -name = "sc-cli-proc-macro" -version = "2.0.0" -dependencies = [ - "proc-macro-crate", - "proc-macro2", - "quote", - "syn", ] [[package]] @@ -7166,8 +7134,6 @@ dependencies = [ "sc-peerset", "serde", "serde_json", - "slog", - "slog_derive", "smallvec 1.5.0", "sp-arithmetic", "sp-blockchain", @@ -7423,7 +7389,6 @@ dependencies = [ "sc-transaction-pool", "serde", "serde_json", - "slog", "sp-api", "sp-application-crypto", "sp-block-builder", @@ -7528,18 +7493,19 @@ dependencies = [ name = "sc-telemetry" version = "2.0.1" dependencies = [ + "chrono", "futures 0.3.9", - "futures-timer 3.0.2", "libp2p", "log", "parking_lot 0.11.1", "pin-project 0.4.27", "rand 0.7.3", "serde", - "slog", - "slog-json", - "slog-scope", + "serde_json", + "sp-utils", "take_mut", + "tracing", + "tracing-subscriber", "void", "wasm-timer", ] @@ -7549,6 +7515,7 @@ name = "sc-tracing" version = "2.0.1" dependencies = [ "ansi_term 0.12.1", + "atty", "erased-serde", "lazy_static", "log", @@ -7557,14 +7524,27 @@ dependencies = [ "regex", "rustc-hash", "sc-telemetry", + "sc-tracing-proc-macro", "serde", "serde_json", - "slog", "sp-tracing", + "thiserror", "tracing", "tracing-core", "tracing-log", "tracing-subscriber", + "wasm-bindgen", + "web-sys", +] + +[[package]] +name = "sc-tracing-proc-macro" +version = "2.0.0" +dependencies = [ + "proc-macro-crate", + "proc-macro2", + "quote", + "syn", ] [[package]] @@ -7934,50 +7914,6 @@ version = "0.4.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c111b5bd5695e56cffe5129854aa230b39c93a305372fdbb2668ca2394eea9f8" -[[package]] -name = "slog" -version = "2.5.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "1cc9c640a4adbfbcc11ffb95efe5aa7af7309e002adab54b185507dbf2377b99" -dependencies = [ - "erased-serde", -] - -[[package]] -name = "slog-json" -version = "2.3.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "ddc0d2aff1f8f325ef660d9a0eb6e6dcd20b30b3f581a5897f58bf42d061c37a" -dependencies = [ - "chrono", - "erased-serde", - "serde", - "serde_json", - "slog", -] - -[[package]] -name = "slog-scope" -version = "4.3.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "7c44c89dd8b0ae4537d1ae318353eaf7840b4869c536e31c41e963d1ea523ee6" -dependencies = [ - "arc-swap", - "lazy_static", - "slog", -] - -[[package]] -name = "slog_derive" -version = "0.2.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a945ec7f7ce853e89ffa36be1e27dce9a43e82ff9093bf3461c30d5da74ed11b" -dependencies = [ - "proc-macro2", - "quote", - "syn", -] - [[package]] name = "smallvec" version = "0.6.13" @@ -8934,7 +8870,6 @@ version = "0.8.1" dependencies = [ "chrono", "console_error_panic_hook", - "console_log", "futures 0.1.30", "futures 0.3.9", "futures-timer 3.0.2", @@ -8948,6 +8883,8 @@ dependencies = [ "sc-informant", "sc-network", "sc-service", + "sc-telemetry", + "sc-tracing", "sp-database", "wasm-bindgen", "wasm-bindgen-futures", diff --git a/Cargo.toml b/Cargo.toml index 1754f896c8846..2a0db9b385a6b 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -21,7 +21,6 @@ members = [ "client/chain-spec", "client/chain-spec/derive", "client/cli", - "client/cli/proc-macro", "client/consensus/aura", "client/consensus/babe", "client/consensus/babe/rpc", @@ -56,6 +55,7 @@ members = [ "client/sync-state-rpc", "client/telemetry", "client/tracing", + "client/tracing/proc-macro", "client/transaction-pool", "client/transaction-pool/graph", "frame/assets", diff --git a/bin/node-template/node/Cargo.toml b/bin/node-template/node/Cargo.toml index 38cdaa1eea48c..878e49fe9b1f0 100644 --- a/bin/node-template/node/Cargo.toml +++ b/bin/node-template/node/Cargo.toml @@ -22,6 +22,7 @@ sc-cli = { version = "0.8.0", path = "../../../client/cli", features = ["wasmtim sp-core = { version = "2.0.0", path = "../../../primitives/core" } sc-executor = { version = "0.8.0", path = "../../../client/executor", features = ["wasmtime"] } sc-service = { version = "0.8.0", path = "../../../client/service", features = ["wasmtime"] } +sc-telemetry = { version = "2.0.0", path = "../../../client/telemetry" } sc-keystore = { version = "2.0.0", path = "../../../client/keystore" } sp-inherents = { version = "2.0.0", path = "../../../primitives/inherents" } sc-transaction-pool = { version = "2.0.0", path = "../../../client/transaction-pool" } diff --git a/bin/node-template/node/src/service.rs b/bin/node-template/node/src/service.rs index 92dfc8f1887cc..b9e5705333e70 100644 --- a/bin/node-template/node/src/service.rs +++ b/bin/node-template/node/src/service.rs @@ -11,6 +11,7 @@ pub use sc_executor::NativeExecutor; use sp_consensus_aura::sr25519::{AuthorityPair as AuraPair}; use sc_finality_grandpa::SharedVoterState; use sc_keystore::LocalKeystore; +use sc_telemetry::TelemetrySpan; // Our native executor instance. native_executor_instance!( @@ -35,7 +36,8 @@ pub fn new_partial(config: &Configuration) -> Result, AuraPair >, - sc_finality_grandpa::LinkHalf + sc_finality_grandpa::LinkHalf, + Option, ) >, ServiceError> { if config.keystore_remote.is_some() { @@ -44,7 +46,7 @@ pub fn new_partial(config: &Configuration) -> Result(&config)?; let client = Arc::new(client); @@ -77,9 +79,15 @@ pub fn new_partial(config: &Configuration) -> Result Result, &'static str> { /// Builds a new service for a full client. pub fn new_full(mut config: Configuration) -> Result { let sc_service::PartialComponents { - client, backend, mut task_manager, import_queue, mut keystore_container, - select_chain, transaction_pool, inherent_data_providers, - other: (block_import, grandpa_link), + client, + backend, + mut task_manager, + import_queue, + mut keystore_container, + select_chain, + transaction_pool, + inherent_data_providers, + other: (block_import, grandpa_link, telemetry_span), } = new_partial(&config)?; if let Some(url) = &config.keystore_remote { @@ -133,7 +147,6 @@ pub fn new_full(mut config: Configuration) -> Result let name = config.network.node_name.clone(); let enable_grandpa = !config.disable_grandpa; let prometheus_registry = config.prometheus_registry().cloned(); - let telemetry_connection_sinks = sc_service::TelemetryConnectionSinks::default(); let rpc_extensions_builder = { let client = client.clone(); @@ -150,18 +163,23 @@ pub fn new_full(mut config: Configuration) -> Result }) }; - sc_service::spawn_tasks(sc_service::SpawnTasksParams { - network: network.clone(), - client: client.clone(), - keystore: keystore_container.sync_keystore(), - task_manager: &mut task_manager, - transaction_pool: transaction_pool.clone(), - telemetry_connection_sinks: telemetry_connection_sinks.clone(), - rpc_extensions_builder, - on_demand: None, - remote_blockchain: None, - backend, network_status_sinks, system_rpc_tx, config, - })?; + let (_rpc_handlers, telemetry_connection_notifier) = sc_service::spawn_tasks( + sc_service::SpawnTasksParams { + network: network.clone(), + client: client.clone(), + keystore: keystore_container.sync_keystore(), + task_manager: &mut task_manager, + transaction_pool: transaction_pool.clone(), + rpc_extensions_builder, + on_demand: None, + remote_blockchain: None, + backend, + network_status_sinks, + system_rpc_tx, + config, + telemetry_span, + }, + )?; if role.is_authority() { let proposer = sc_basic_authorship::ProposerFactory::new( @@ -222,7 +240,7 @@ pub fn new_full(mut config: Configuration) -> Result config: grandpa_config, link: grandpa_link, network, - telemetry_on_connect: Some(telemetry_connection_sinks.on_connect_stream()), + telemetry_on_connect: telemetry_connection_notifier.map(|x| x.on_connect_stream()), voting_rule: sc_finality_grandpa::VotingRulesBuilder::default().build(), prometheus_registry, shared_voter_state: SharedVoterState::empty(), @@ -242,7 +260,7 @@ pub fn new_full(mut config: Configuration) -> Result /// Builds a new service for a light client. pub fn new_light(mut config: Configuration) -> Result { - let (client, backend, keystore_container, mut task_manager, on_demand) = + let (client, backend, keystore_container, mut task_manager, on_demand, telemetry_span) = sc_service::new_light_parts::(&config)?; config.network.extra_sets.push(sc_finality_grandpa::grandpa_peers_set_config()); @@ -302,7 +320,6 @@ pub fn new_light(mut config: Configuration) -> Result task_manager: &mut task_manager, on_demand: Some(on_demand), rpc_extensions_builder: Box::new(|_, _| ()), - telemetry_connection_sinks: sc_service::TelemetryConnectionSinks::default(), config, client, keystore: keystore_container.sync_keystore(), @@ -310,9 +327,10 @@ pub fn new_light(mut config: Configuration) -> Result network, network_status_sinks, system_rpc_tx, - })?; + telemetry_span, + })?; - network_starter.start_network(); + network_starter.start_network(); - Ok(task_manager) + Ok(task_manager) } diff --git a/bin/node/cli/Cargo.toml b/bin/node/cli/Cargo.toml index 5c84f4cab7d61..aaee373119592 100644 --- a/bin/node/cli/Cargo.toml +++ b/bin/node/cli/Cargo.toml @@ -41,7 +41,6 @@ hex-literal = "0.3.1" log = "0.4.8" rand = "0.7.2" structopt = { version = "0.3.8", optional = true } -tracing = "0.1.22" parking_lot = "0.11.1" # primitives diff --git a/bin/node/cli/browser-demo/build.sh b/bin/node/cli/browser-demo/build.sh index be52b7a523f01..8840106daeb5c 100755 --- a/bin/node/cli/browser-demo/build.sh +++ b/bin/node/cli/browser-demo/build.sh @@ -1,4 +1,5 @@ #!/usr/bin/env sh +set -e -x cargo +nightly build --release -p node-cli --target wasm32-unknown-unknown --no-default-features --features browser -Z features=itarget wasm-bindgen ../../../../target/wasm32-unknown-unknown/release/node_cli.wasm --out-dir pkg --target web python -m http.server 8000 diff --git a/bin/node/cli/src/browser.rs b/bin/node/cli/src/browser.rs index 42886a668d348..6c0a2f10d95e5 100644 --- a/bin/node/cli/src/browser.rs +++ b/bin/node/cli/src/browser.rs @@ -21,9 +21,8 @@ use log::info; use wasm_bindgen::prelude::*; use browser_utils::{ Client, - browser_configuration, set_console_error_panic_hook, init_console_log, + browser_configuration, init_logging_and_telemetry, set_console_error_panic_hook, }; -use std::str::FromStr; /// Starts the client. #[wasm_bindgen] @@ -33,20 +32,27 @@ pub async fn start_client(chain_spec: Option, log_level: String) -> Resu .map_err(|err| JsValue::from_str(&err.to_string())) } -async fn start_inner(chain_spec: Option, log_level: String) -> Result> { +async fn start_inner( + chain_spec: Option, + log_directives: String, +) -> Result> { set_console_error_panic_hook(); - init_console_log(log::Level::from_str(&log_level)?)?; + let telemetry_worker = init_logging_and_telemetry(&log_directives)?; let chain_spec = match chain_spec { Some(chain_spec) => ChainSpec::from_json_bytes(chain_spec.as_bytes().to_vec()) .map_err(|e| format!("{:?}", e))?, None => crate::chain_spec::development_config(), }; - let config = browser_configuration(chain_spec).await?; + let telemetry_handle = telemetry_worker.handle(); + let config = browser_configuration( + chain_spec, + Some(telemetry_handle), + ).await?; info!("Substrate browser node"); info!("✌️ version {}", config.impl_version); - info!("❤️ by Parity Technologies, 2017-2020"); + info!("❤️ by Parity Technologies, 2017-2021"); info!("📋 Chain specification: {}", config.chain_spec.name()); info!("🏷 Node name: {}", config.network.node_name); info!("👤 Role: {:?}", config.role); @@ -54,8 +60,10 @@ async fn start_inner(chain_spec: Option, log_level: String) -> Result; type FullBackend = sc_service::TFullBackend; @@ -57,9 +58,10 @@ pub fn new_partial(config: &Configuration) -> Result, ), grandpa::SharedVoterState, + Option, ) >, ServiceError> { - let (client, backend, keystore_container, task_manager) = + let (client, backend, keystore_container, task_manager, telemetry_span) = sc_service::new_full_parts::(&config)?; let client = Arc::new(client); @@ -147,9 +149,15 @@ pub fn new_partial(config: &Configuration) -> Result Result { let sc_service::PartialComponents { - client, backend, mut task_manager, import_queue, keystore_container, - select_chain, transaction_pool, inherent_data_providers, - other: (rpc_extensions_builder, import_setup, rpc_setup), + client, + backend, + mut task_manager, + import_queue, + keystore_container, + select_chain, + transaction_pool, + inherent_data_providers, + other: (rpc_extensions_builder, import_setup, rpc_setup, telemetry_span), } = new_partial(&config)?; let shared_voter_state = rpc_setup; @@ -204,23 +218,24 @@ pub fn new_full_base( let name = config.network.node_name.clone(); let enable_grandpa = !config.disable_grandpa; let prometheus_registry = config.prometheus_registry().cloned(); - let telemetry_connection_sinks = sc_service::TelemetryConnectionSinks::default(); - sc_service::spawn_tasks(sc_service::SpawnTasksParams { - config, - backend: backend.clone(), - client: client.clone(), - keystore: keystore_container.sync_keystore(), - network: network.clone(), - rpc_extensions_builder: Box::new(rpc_extensions_builder), - transaction_pool: transaction_pool.clone(), - task_manager: &mut task_manager, - on_demand: None, - remote_blockchain: None, - telemetry_connection_sinks: telemetry_connection_sinks.clone(), - network_status_sinks: network_status_sinks.clone(), - system_rpc_tx, - })?; + let (_rpc_handlers, telemetry_connection_notifier) = sc_service::spawn_tasks( + sc_service::SpawnTasksParams { + config, + backend: backend.clone(), + client: client.clone(), + keystore: keystore_container.sync_keystore(), + network: network.clone(), + rpc_extensions_builder: Box::new(rpc_extensions_builder), + transaction_pool: transaction_pool.clone(), + task_manager: &mut task_manager, + on_demand: None, + remote_blockchain: None, + network_status_sinks: network_status_sinks.clone(), + system_rpc_tx, + telemetry_span, + }, + )?; let (block_import, grandpa_link, babe_link) = import_setup; @@ -305,7 +320,7 @@ pub fn new_full_base( config, link: grandpa_link, network: network.clone(), - telemetry_on_connect: Some(telemetry_connection_sinks.on_connect_stream()), + telemetry_on_connect: telemetry_connection_notifier.map(|x| x.on_connect_stream()), voting_rule: grandpa::VotingRulesBuilder::default().build(), prometheus_registry, shared_voter_state, @@ -339,11 +354,11 @@ pub fn new_full(config: Configuration) } pub fn new_light_base(mut config: Configuration) -> Result<( - TaskManager, RpcHandlers, Arc, + TaskManager, RpcHandlers, Option, Arc, Arc::Hash>>, Arc>> ), ServiceError> { - let (client, backend, keystore_container, mut task_manager, on_demand) = + let (client, backend, keystore_container, mut task_manager, on_demand, telemetry_span) = sc_service::new_light_parts::(&config)?; config.network.extra_sets.push(grandpa::grandpa_peers_set_config()); @@ -412,7 +427,7 @@ pub fn new_light_base(mut config: Configuration) -> Result<( let rpc_extensions = node_rpc::create_light(light_deps); - let rpc_handlers = + let (rpc_handlers, telemetry_connection_notifier) = sc_service::spawn_tasks(sc_service::SpawnTasksParams { on_demand: Some(on_demand), remote_blockchain: Some(backend.remote_blockchain()), @@ -422,16 +437,23 @@ pub fn new_light_base(mut config: Configuration) -> Result<( keystore: keystore_container.sync_keystore(), config, backend, network_status_sinks, system_rpc_tx, network: network.clone(), - telemetry_connection_sinks: sc_service::TelemetryConnectionSinks::default(), task_manager: &mut task_manager, + telemetry_span, })?; - Ok((task_manager, rpc_handlers, client, network, transaction_pool)) + Ok(( + task_manager, + rpc_handlers, + telemetry_connection_notifier, + client, + network, + transaction_pool, + )) } /// Builds a new service for a light client. pub fn new_light(config: Configuration) -> Result { - new_light_base(config).map(|(task_manager, _, _, _, _)| { + new_light_base(config).map(|(task_manager, _, _, _, _, _)| { task_manager }) } @@ -513,7 +535,7 @@ mod tests { Ok((node, (inherent_data_providers, setup_handles.unwrap()))) }, |config| { - let (keep_alive, _, client, network, transaction_pool) = new_light_base(config)?; + let (keep_alive, _, _, client, network, transaction_pool) = new_light_base(config)?; Ok(sc_service_test::TestNetComponents::new(keep_alive, client, network, transaction_pool)) }, |service, &mut (ref inherent_data_providers, (ref mut block_import, ref babe_link))| { @@ -671,7 +693,7 @@ mod tests { Ok(sc_service_test::TestNetComponents::new(task_manager, client, network, transaction_pool)) }, |config| { - let (keep_alive, _, client, network, transaction_pool) = new_light_base(config)?; + let (keep_alive, _, _, client, network, transaction_pool) = new_light_base(config)?; Ok(sc_service_test::TestNetComponents::new(keep_alive, client, network, transaction_pool)) }, vec![ diff --git a/client/cli/Cargo.toml b/client/cli/Cargo.toml index 32299e6e5f695..17390a5f225c4 100644 --- a/client/cli/Cargo.toml +++ b/client/cli/Cargo.toml @@ -14,7 +14,6 @@ targets = ["x86_64-unknown-linux-gnu"] [dependencies] log = "0.4.11" -atty = "0.2.13" regex = "1.4.2" tokio = { version = "0.2.21", features = [ "signal", "rt-core", "rt-threaded", "blocking" ] } futures = "0.3.9" @@ -43,10 +42,6 @@ structopt = "0.3.8" sc-tracing = { version = "2.0.0", path = "../tracing" } chrono = "0.4.10" serde = "1.0.111" -tracing = "0.1.22" -tracing-log = "0.1.1" -tracing-subscriber = "0.2.15" -sc-cli-proc-macro = { version = "2.0.0", path = "./proc-macro" } thiserror = "1.0.21" [target.'cfg(not(target_os = "unknown"))'.dependencies] @@ -54,7 +49,6 @@ rpassword = "5.0.0" [dev-dependencies] tempfile = "3.1.0" -ansi_term = "0.12.1" [features] wasmtime = [ diff --git a/client/cli/src/commands/insert_key.rs b/client/cli/src/commands/insert_key.rs index 90588f96d20b0..6e4324deed042 100644 --- a/client/cli/src/commands/insert_key.rs +++ b/client/cli/src/commands/insert_key.rs @@ -123,7 +123,7 @@ mod tests { } fn copyright_start_year() -> i32 { - 2020 + 2021 } fn author() -> String { diff --git a/client/cli/src/config.rs b/client/cli/src/config.rs index 854e73ae78125..ae43e8f334c6d 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -21,8 +21,8 @@ use crate::arg_enums::Database; use crate::error::Result; use crate::{ - init_logger, DatabaseParams, ImportParams, KeystoreParams, NetworkParams, NodeKeyParams, - OffchainWorkerParams, PruningParams, SharedParams, SubstrateCli, InitLoggerParams, + DatabaseParams, ImportParams, KeystoreParams, NetworkParams, NodeKeyParams, + OffchainWorkerParams, PruningParams, SharedParams, SubstrateCli, }; use log::warn; use names::{Generator, Name}; @@ -32,7 +32,9 @@ use sc_service::config::{ NodeKeyConfig, OffchainWorkerConfig, PrometheusConfig, PruningMode, Role, RpcMethods, TaskExecutor, TelemetryEndpoints, TransactionPoolOptions, WasmExecutionMethod, }; -use sc_service::{ChainSpec, TracingReceiver, KeepBlocks, TransactionStorageMode }; +use sc_service::{ChainSpec, TracingReceiver, KeepBlocks, TransactionStorageMode}; +use sc_telemetry::TelemetryHandle; +use sc_tracing::logging::GlobalLoggerBuilder; use std::net::SocketAddr; use std::path::PathBuf; @@ -468,6 +470,7 @@ pub trait CliConfiguration: Sized { &self, cli: &C, task_executor: TaskExecutor, + telemetry_handle: Option, ) -> Result { let is_dev = self.is_dev()?; let chain_id = self.chain_id(is_dev)?; @@ -539,6 +542,7 @@ pub trait CliConfiguration: Sized { role, base_path: Some(base_path), informant_output_format: Default::default(), + telemetry_handle, }) } @@ -569,34 +573,38 @@ pub trait CliConfiguration: Sized { /// 1. Sets the panic handler /// 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()?; - let disable_log_reloading = self.is_log_filter_reloading_disabled()?; - let disable_log_color = self.disable_log_color()?; - + fn init(&self) -> Result { sp_panic_handler::set(&C::support_url(), &C::impl_version()); - init_logger(InitLoggerParams { - pattern: logger_pattern, - tracing_receiver, - tracing_targets, - disable_log_reloading, - disable_log_color, - })?; + let mut logger = GlobalLoggerBuilder::new(self.log_filters()?); + logger.with_log_reloading(!self.is_log_filter_reloading_disabled()?); + + if let Some(transport) = self.telemetry_external_transport()? { + logger.with_transport(transport); + } + + if let Some(tracing_targets) = self.tracing_targets()? { + let tracing_receiver = self.tracing_receiver()?; + logger.with_profiling(tracing_receiver, tracing_targets); + } + + if self.disable_log_color()? { + logger.with_colors(false); + } + + let telemetry_worker = logger.init()?; if let Some(new_limit) = fdlimit::raise_fd_limit() { if new_limit < RECOMMENDED_OPEN_FILE_DESCRIPTOR_LIMIT { warn!( "Low open file descriptor limit configured for the process. \ - Current value: {:?}, recommended value: {:?}.", + Current value: {:?}, recommended value: {:?}.", new_limit, RECOMMENDED_OPEN_FILE_DESCRIPTOR_LIMIT, ); } } - Ok(()) + Ok(telemetry_worker) } } diff --git a/client/cli/src/error.rs b/client/cli/src/error.rs index 75867e2f76b28..c5784b2018172 100644 --- a/client/cli/src/error.rs +++ b/client/cli/src/error.rs @@ -77,6 +77,9 @@ pub enum Error { /// Application specific error chain sequence forwarder. #[error(transparent)] Application(#[from] Box), + + #[error(transparent)] + GlobalLoggerError(#[from] sc_tracing::logging::Error), } impl std::convert::From<&str> for Error { diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index bf8be8a4e77b9..a4b0bd45727e2 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -21,7 +21,6 @@ #![warn(missing_docs)] #![warn(unused_extern_crates)] #![warn(unused_imports)] -#![warn(unused_crate_dependencies)] pub mod arg_enums; mod commands; @@ -36,9 +35,10 @@ pub use config::*; pub use error::*; pub use params::*; pub use runner::*; -pub use sc_cli_proc_macro::*; pub use sc_service::{ChainSpec, Role}; use sc_service::{Configuration, TaskExecutor}; +use sc_telemetry::TelemetryHandle; +pub use sc_tracing::logging::GlobalLoggerBuilder; pub use sp_version::RuntimeVersion; use std::io::Write; pub use structopt; @@ -46,18 +46,6 @@ use structopt::{ clap::{self, AppSettings}, StructOpt, }; -use tracing_subscriber::{ - fmt::time::ChronoLocal, - EnvFilter, - FmtSubscriber, - Layer, - layer::SubscriberExt, -}; -pub use sc_tracing::logging; - -pub use logging::PREFIX_LOG_SPAN; -#[doc(hidden)] -pub use tracing; /// Substrate client CLI /// @@ -82,7 +70,8 @@ pub trait SubstrateCli: Sized { /// Extracts the file name from `std::env::current_exe()`. /// Resorts to the env var `CARGO_PKG_NAME` in case of Error. fn executable_name() -> String { - std::env::current_exe().ok() + std::env::current_exe() + .ok() .and_then(|e| e.file_name().map(|s| s.to_os_string())) .and_then(|w| w.into_string().ok()) .unwrap_or_else(|| env!("CARGO_PKG_NAME").into()) @@ -112,7 +101,10 @@ pub trait SubstrateCli: Sized { /// /// Gets the struct from the command line arguments. Print the /// error message and quit the program in case of failure. - fn from_args() -> Self where Self: StructOpt + Sized { + fn from_args() -> Self + where + Self: StructOpt + Sized, + { ::from_iter(&mut std::env::args_os()) } @@ -167,7 +159,7 @@ pub trait SubstrateCli: Sized { let _ = std::io::stdout().write_all(e.message.as_bytes()); std::process::exit(0); } - }, + } }; ::from_clap(&matches) @@ -222,377 +214,18 @@ pub trait SubstrateCli: Sized { &self, command: &T, task_executor: TaskExecutor, + telemetry_handle: Option, ) -> error::Result { - command.create_configuration(self, task_executor) + command.create_configuration(self, task_executor, telemetry_handle) } /// Create a runner for the command provided in argument. This will create a Configuration and /// a tokio runtime fn create_runner(&self, command: &T) -> error::Result> { - command.init::()?; - Runner::new(self, command) + let telemetry_worker = command.init::()?; + Runner::new(self, command, telemetry_worker) } /// Native runtime version. fn native_runtime_version(chain_spec: &Box) -> &'static RuntimeVersion; } - -/// The parameters for [`init_logger`]. -#[derive(Default)] -pub struct InitLoggerParams { - /// A comma seperated list of logging patterns. - /// - /// E.g.: `test-crate=debug` - pub pattern: String, - /// The tracing receiver. - pub tracing_receiver: sc_tracing::TracingReceiver, - /// Optional comma seperated list of tracing targets. - pub tracing_targets: Option, - /// Should log reloading be disabled? - pub disable_log_reloading: bool, - /// Should the log color output be disabled? - pub disable_log_color: bool, -} - -/// Initialize the global logger -/// -/// This sets various global logging and tracing instances and thus may only be called once. -pub fn init_logger( - InitLoggerParams { - pattern, - tracing_receiver, - tracing_targets, - disable_log_reloading, - disable_log_color, - }: InitLoggerParams, -) -> std::result::Result<(), String> { - use sc_tracing::parse_default_directive; - - // Accept all valid directives and print invalid ones - fn parse_user_directives( - mut env_filter: EnvFilter, - dirs: &str, - ) -> std::result::Result { - for dir in dirs.split(',') { - env_filter = env_filter.add_directive(parse_default_directive(&dir)?); - } - Ok(env_filter) - } - - // Initialize filter - ensure to use `parse_default_directive` for any defaults to persist - // after log filter reloading by RPC - let mut env_filter = EnvFilter::default() - // Enable info - .add_directive(parse_default_directive("info") - .expect("provided directive is valid")) - // Disable info logging by default for some modules. - .add_directive(parse_default_directive("ws=off") - .expect("provided directive is valid")) - .add_directive(parse_default_directive("yamux=off") - .expect("provided directive is valid")) - .add_directive(parse_default_directive("cranelift_codegen=off") - .expect("provided directive is valid")) - // Set warn logging by default for some modules. - .add_directive(parse_default_directive("cranelift_wasm=warn") - .expect("provided directive is valid")) - .add_directive(parse_default_directive("hyper=warn") - .expect("provided directive is valid")); - - if let Ok(lvl) = std::env::var("RUST_LOG") { - if lvl != "" { - env_filter = parse_user_directives(env_filter, &lvl)?; - } - } - - if pattern != "" { - // We're not sure if log or tracing is available at this moment, so silently ignore the - // parse error. - env_filter = parse_user_directives(env_filter, &pattern)?; - } - - let max_level_hint = Layer::::max_level_hint(&env_filter); - - let max_level = if tracing_targets.is_some() { - // If profiling is activated, we require `trace` logging. - log::LevelFilter::Trace - } else { - match max_level_hint { - Some(tracing_subscriber::filter::LevelFilter::INFO) | None => log::LevelFilter::Info, - Some(tracing_subscriber::filter::LevelFilter::TRACE) => log::LevelFilter::Trace, - Some(tracing_subscriber::filter::LevelFilter::WARN) => log::LevelFilter::Warn, - Some(tracing_subscriber::filter::LevelFilter::ERROR) => log::LevelFilter::Error, - Some(tracing_subscriber::filter::LevelFilter::DEBUG) => log::LevelFilter::Debug, - Some(tracing_subscriber::filter::LevelFilter::OFF) => log::LevelFilter::Off, - } - }; - - tracing_log::LogTracer::builder() - .with_max_level(max_level) - .init() - .map_err(|e| format!("Registering Substrate logger failed: {:}!", e))?; - - // If we're only logging `INFO` entries then we'll use a simplified logging format. - let simple = match max_level_hint { - Some(level) if level <= tracing_subscriber::filter::LevelFilter::INFO => true, - _ => false, - }; - - // Make sure to include profiling targets in the filter - if let Some(tracing_targets) = tracing_targets.clone() { - // Always log the special target `sc_tracing`, overrides global level. - // Required because profiling traces are emitted via `sc_tracing` - // NOTE: this must be done after we check the `max_level_hint` otherwise - // it is always raised to `TRACE`. - env_filter = env_filter.add_directive( - parse_default_directive("sc_tracing=trace").expect("provided directive is valid") - ); - - env_filter = parse_user_directives(env_filter, &tracing_targets)?; - } - - let enable_color = atty::is(atty::Stream::Stderr) && !disable_log_color; - let timer = ChronoLocal::with_format(if simple { - "%Y-%m-%d %H:%M:%S".to_string() - } else { - "%Y-%m-%d %H:%M:%S%.3f".to_string() - }); - - let subscriber_builder = FmtSubscriber::builder() - .with_env_filter(env_filter) - .with_writer(std::io::stderr as _) - .event_format(logging::EventFormat { - timer, - enable_color, - display_target: !simple, - display_level: !simple, - display_thread_name: !simple, - }); - if disable_log_reloading { - let subscriber = subscriber_builder - .finish() - .with(logging::NodeNameLayer); - initialize_tracing(subscriber, tracing_receiver, tracing_targets) - } else { - let subscriber_builder = subscriber_builder.with_filter_reloading(); - let handle = subscriber_builder.reload_handle(); - sc_tracing::set_reload_handle(handle); - let subscriber = subscriber_builder - .finish() - .with(logging::NodeNameLayer); - initialize_tracing(subscriber, tracing_receiver, tracing_targets) - } -} - -fn initialize_tracing( - subscriber: S, - tracing_receiver: sc_tracing::TracingReceiver, - profiling_targets: Option, -) -> std::result::Result<(), String> -where - S: tracing::Subscriber + Send + Sync + 'static, -{ - if let Some(profiling_targets) = profiling_targets { - let profiling = sc_tracing::ProfilingLayer::new(tracing_receiver, &profiling_targets); - if let Err(e) = tracing::subscriber::set_global_default(subscriber.with(profiling)) { - return Err(format!( - "Registering Substrate tracing subscriber failed: {:}!", e - )) - } - } else { - if let Err(e) = tracing::subscriber::set_global_default(subscriber) { - return Err(format!( - "Registering Substrate tracing subscriber failed: {:}!", e - )) - } - } - Ok(()) -} - -#[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}; - - #[test] - fn test_logger_filters() { - let test_pattern = "afg=debug,sync=trace,client=warn,telemetry,something-with-dash=error"; - init_logger( - InitLoggerParams { pattern: test_pattern.into(), ..Default::default() }, - ).unwrap(); - - tracing::dispatcher::get_default(|dispatcher| { - let test_filter = |target, level| { - struct DummyCallSite; - impl Callsite for DummyCallSite { - fn set_interest(&self, _: Interest) {} - fn metadata(&self) -> &Metadata<'_> { - unreachable!(); - } - } - - let metadata = tracing::metadata!( - name: "", - target: target, - level: level, - fields: &[], - callsite: &DummyCallSite, - kind: Kind::SPAN, - ); - - dispatcher.enabled(&metadata) - }; - - assert!(test_filter("afg", Level::INFO)); - assert!(test_filter("afg", Level::DEBUG)); - assert!(!test_filter("afg", Level::TRACE)); - - assert!(test_filter("sync", Level::TRACE)); - assert!(test_filter("client", Level::WARN)); - - assert!(test_filter("telemetry", Level::TRACE)); - assert!(test_filter("something-with-dash", Level::ERROR)); - }); - } - - const EXPECTED_LOG_MESSAGE: &'static str = "yeah logging works as expected"; - - #[test] - fn dash_in_target_name_works() { - let executable = env::current_exe().unwrap(); - let output = Command::new(executable) - .env("ENABLE_LOGGING", "1") - .args(&["--nocapture", "log_something_with_dash_target_name"]) - .output() - .unwrap(); - - let output = String::from_utf8(output.stderr).unwrap(); - assert!(output.contains(EXPECTED_LOG_MESSAGE)); - } - - /// This is no actual test, it will be used by the `dash_in_target_name_works` test. - /// The given test will call the test executable to only execute this test that - /// will only print `EXPECTED_LOG_MESSAGE` through logging while using a target - /// name that contains a dash. This ensures that targets names with dashes work. - #[test] - fn log_something_with_dash_target_name() { - if env::var("ENABLE_LOGGING").is_ok() { - let test_pattern = "test-target=info"; - init_logger( - InitLoggerParams { pattern: test_pattern.into(), ..Default::default() }, - ).unwrap(); - - log::info!(target: "test-target", "{}", EXPECTED_LOG_MESSAGE); - } - } - - const EXPECTED_NODE_NAME: &'static str = "THE_NODE"; - - #[test] - fn prefix_in_log_lines() { - let re = regex::Regex::new(&format!( - r"^\d{{4}}-\d{{2}}-\d{{2}} \d{{2}}:\d{{2}}:\d{{2}} \[{}\] {}$", - EXPECTED_NODE_NAME, - EXPECTED_LOG_MESSAGE, - )).unwrap(); - 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!( - re.is_match(output.trim()), - format!("Expected:\n{}\nGot:\n{}", re, output), - ); - } - - /// 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( - InitLoggerParams { pattern: test_pattern.into(), ..Default::default() }, - ).unwrap(); - prefix_in_log_lines_process(); - } - } - - #[crate::prefix_logs_with(EXPECTED_NODE_NAME)] - fn prefix_in_log_lines_process() { - log::info!("{}", EXPECTED_LOG_MESSAGE); - } - - /// This is no actual test, it will be used by the `do_not_write_with_colors_on_tty` test. - /// The given test will call the test executable to only execute this test that - /// will only print a log line with some colors in it. - #[test] - fn do_not_write_with_colors_on_tty_entrypoint() { - if env::var("ENABLE_LOGGING").is_ok() { - init_logger(InitLoggerParams::default()).unwrap(); - log::info!("{}", ansi_term::Colour::Yellow.paint(EXPECTED_LOG_MESSAGE)); - } - } - - #[test] - fn do_not_write_with_colors_on_tty() { - let re = regex::Regex::new(&format!( - r"^\d{{4}}-\d{{2}}-\d{{2}} \d{{2}}:\d{{2}}:\d{{2}} {}$", - EXPECTED_LOG_MESSAGE, - )).unwrap(); - let executable = env::current_exe().unwrap(); - let output = Command::new(executable) - .env("ENABLE_LOGGING", "1") - .args(&["--nocapture", "do_not_write_with_colors_on_tty_entrypoint"]) - .output() - .unwrap(); - - let output = String::from_utf8(output.stderr).unwrap(); - assert!( - re.is_match(output.trim()), - format!("Expected:\n{}\nGot:\n{}", re, output), - ); - } - - #[test] - fn log_max_level_is_set_properly() { - fn run_test(rust_log: Option, tracing_targets: Option) -> String { - let executable = env::current_exe().unwrap(); - let mut command = Command::new(executable); - - command.env("PRINT_MAX_LOG_LEVEL", "1") - .args(&["--nocapture", "log_max_level_is_set_properly"]); - - if let Some(rust_log) = rust_log { - command.env("RUST_LOG", rust_log); - } - - if let Some(tracing_targets) = tracing_targets { - command.env("TRACING_TARGETS", tracing_targets); - } - - let output = command.output().unwrap(); - - String::from_utf8(output.stderr).unwrap() - } - - if env::var("PRINT_MAX_LOG_LEVEL").is_ok() { - init_logger(InitLoggerParams { - tracing_targets: env::var("TRACING_TARGETS").ok(), - ..Default::default() - }).unwrap(); - eprint!("MAX_LOG_LEVEL={:?}", log::max_level()); - } else { - assert_eq!("MAX_LOG_LEVEL=Info", run_test(None, None)); - assert_eq!("MAX_LOG_LEVEL=Trace", run_test(Some("test=trace".into()), None)); - assert_eq!("MAX_LOG_LEVEL=Debug", run_test(Some("test=debug".into()), None)); - assert_eq!("MAX_LOG_LEVEL=Trace", run_test(None, Some("test=info".into()))); - } - } -} diff --git a/client/cli/src/runner.rs b/client/cli/src/runner.rs index 74ac9e5bc7f62..06676655581b1 100644 --- a/client/cli/src/runner.rs +++ b/client/cli/src/runner.rs @@ -25,6 +25,7 @@ use futures::select; use futures::{future, future::FutureExt, Future}; use log::info; use sc_service::{Configuration, TaskType, TaskManager}; +use sc_telemetry::{TelemetryHandle, TelemetryWorker}; use sp_utils::metrics::{TOKIO_THREADS_ALIVE, TOKIO_THREADS_TOTAL}; use std::marker::PhantomData; use sc_service::Error as ServiceError; @@ -114,12 +115,17 @@ where pub struct Runner { config: Configuration, tokio_runtime: tokio::runtime::Runtime, + telemetry_worker: TelemetryWorker, phantom: PhantomData, } impl Runner { /// Create a new runtime with the command provided in argument - pub fn new(cli: &C, command: &T) -> Result> { + pub fn new( + cli: &C, + command: &T, + telemetry_worker: TelemetryWorker, + ) -> Result> { let tokio_runtime = build_runtime()?; let runtime_handle = tokio_runtime.handle().clone(); @@ -132,9 +138,16 @@ impl Runner { } }; + let telemetry_handle = telemetry_worker.handle(); + Ok(Runner { - config: command.create_configuration(cli, task_executor.into())?, + config: command.create_configuration( + cli, + task_executor.into(), + Some(telemetry_handle), + )?, tokio_runtime, + telemetry_worker, phantom: PhantomData, }) } @@ -184,6 +197,7 @@ impl Runner { { self.print_node_infos(); let mut task_manager = self.tokio_runtime.block_on(initialize(self.config))?; + task_manager.spawn_handle().spawn("telemetry_worker", self.telemetry_worker.run()); let res = self.tokio_runtime.block_on(main(task_manager.future().fuse())); self.tokio_runtime.block_on(task_manager.clean_shutdown()); Ok(res?) @@ -222,4 +236,11 @@ impl Runner { pub fn config_mut(&mut self) -> &mut Configuration { &mut self.config } + + /// Get a new [`TelemetryHandle`]. + /// + /// This is used when you want to register a new telemetry for a Substrate node. + pub fn telemetry_handle(&self) -> TelemetryHandle { + self.telemetry_worker.handle() + } } diff --git a/client/network/Cargo.toml b/client/network/Cargo.toml index 9c0fab84a87d2..f7d7f7fafde38 100644 --- a/client/network/Cargo.toml +++ b/client/network/Cargo.toml @@ -47,8 +47,6 @@ sc-client-api = { version = "2.0.0", path = "../api" } sc-peerset = { version = "2.0.0", path = "../peerset" } serde = { version = "1.0.101", features = ["derive"] } serde_json = "1.0.41" -slog = { version = "2.5.2", features = ["nested-values"] } -slog_derive = "0.2.0" smallvec = "1.5.0" sp-arithmetic = { version = "2.0.0", path = "../../primitives/arithmetic" } sp-blockchain = { version = "2.0.0", path = "../../primitives/blockchain" } diff --git a/client/network/src/network_state.rs b/client/network/src/network_state.rs index fe612dcccf912..4ddfadda172e4 100644 --- a/client/network/src/network_state.rs +++ b/client/network/src/network_state.rs @@ -22,7 +22,6 @@ use libp2p::{core::ConnectedPoint, Multiaddr}; use serde::{Deserialize, Serialize}; -use slog_derive::SerdeValue; use std::{collections::{HashMap, HashSet}, time::Duration}; /// Returns general information about the networking. @@ -30,7 +29,7 @@ use std::{collections::{HashMap, HashSet}, time::Duration}; /// Meant for general diagnostic purposes. /// /// **Warning**: This API is not stable. -#[derive(Clone, Debug, PartialEq, Serialize, Deserialize, SerdeValue)] +#[derive(Clone, Debug, PartialEq, Serialize, Deserialize)] #[serde(rename_all = "camelCase")] pub struct NetworkState { /// PeerId of the local node. diff --git a/client/network/src/request_responses.rs b/client/network/src/request_responses.rs index fbdb1432379ed..d30e398916419 100644 --- a/client/network/src/request_responses.rs +++ b/client/network/src/request_responses.rs @@ -52,8 +52,9 @@ use libp2p::{ }; use std::{ borrow::Cow, collections::{hash_map::Entry, HashMap}, convert::TryFrom as _, io, iter, - pin::Pin, task::{Context, Poll}, time::{Duration, Instant}, + pin::Pin, task::{Context, Poll}, time::Duration, }; +use wasm_timer::Instant; pub use libp2p::request_response::{InboundFailure, OutboundFailure, RequestId}; diff --git a/client/rpc/src/system/mod.rs b/client/rpc/src/system/mod.rs index 60a410b805688..240de6c62876e 100644 --- a/client/rpc/src/system/mod.rs +++ b/client/rpc/src/system/mod.rs @@ -24,6 +24,7 @@ mod tests; use futures::{future::BoxFuture, FutureExt, TryFutureExt}; use futures::{channel::oneshot, compat::Compat}; use sc_rpc_api::{DenyUnsafe, Receiver}; +use sc_tracing::logging; use sp_utils::mpsc::TracingUnboundedSender; use sp_runtime::traits::{self, Header as HeaderT}; @@ -200,12 +201,12 @@ impl SystemApi::Number> for Sy fn system_add_log_filter(&self, directives: String) -> std::result::Result<(), rpc::Error> { self.deny_unsafe.check_if_safe()?; - sc_tracing::add_directives(&directives); - sc_tracing::reload_filter().map_err(|_e| rpc::Error::internal_error()) + logging::add_directives(&directives); + logging::reload_filter().map_err(|_e| rpc::Error::internal_error()) } fn system_reset_log_filter(&self)-> std::result::Result<(), rpc::Error> { self.deny_unsafe.check_if_safe()?; - sc_tracing::reset_log_filter().map_err(|_e| rpc::Error::internal_error()) + logging::reset_log_filter().map_err(|_e| rpc::Error::internal_error()) } } diff --git a/client/rpc/src/system/tests.rs b/client/rpc/src/system/tests.rs index c24c7a3faa6ec..89676acae26bf 100644 --- a/client/rpc/src/system/tests.rs +++ b/client/rpc/src/system/tests.rs @@ -344,9 +344,7 @@ fn test_add_reset_log_filter() { // Enter log generation / filter reload if std::env::var("TEST_LOG_FILTER").is_ok() { - sc_cli::init_logger( - sc_cli::InitLoggerParams { pattern: "test_before_add=debug".into(), ..Default::default() }, - ).unwrap(); + sc_tracing::logging::GlobalLoggerBuilder::new("test_before_add=debug").init().unwrap(); for line in std::io::stdin().lock().lines() { let line = line.expect("Failed to read bytes"); if line.contains("add_reload") { diff --git a/client/service/Cargo.toml b/client/service/Cargo.toml index 9d040802e66ae..95ce02e195f1e 100644 --- a/client/service/Cargo.toml +++ b/client/service/Cargo.toml @@ -33,7 +33,6 @@ rand = "0.7.3" parking_lot = "0.11.1" lazy_static = "1.4.0" log = "0.4.11" -slog = { version = "2.5.2", features = ["nested-values"] } futures-timer = "3.0.1" wasm-timer = "0.2" exit-future = "0.2.0" diff --git a/client/service/src/builder.rs b/client/service/src/builder.rs index bac5191f0ccae..a155899fbd99c 100644 --- a/client/service/src/builder.rs +++ b/client/service/src/builder.rs @@ -17,8 +17,7 @@ // along with this program. If not, see . use crate::{ - error::Error, DEFAULT_PROTOCOL_ID, MallocSizeOfWasm, - TelemetryConnectionSinks, RpcHandlers, NetworkStatusSinks, + error::Error, DEFAULT_PROTOCOL_ID, MallocSizeOfWasm, RpcHandlers, NetworkStatusSinks, start_rpc_servers, build_network_future, TransactionPoolAdapter, TaskManager, SpawnTaskHandle, metrics::MetricsService, client::{light, Client, ClientConfig}, @@ -46,13 +45,19 @@ use sc_network::NetworkService; use sc_network::block_request_handler::{self, BlockRequestHandler}; use sp_runtime::generic::BlockId; use sp_runtime::traits::{ - Block as BlockT, SaturatedConversion, HashFor, Zero, BlockIdTo, + Block as BlockT, HashFor, Zero, BlockIdTo, }; use sp_api::{ProvideRuntimeApi, CallApiAt}; use sc_executor::{NativeExecutor, NativeExecutionDispatch, RuntimeInfo}; use std::sync::Arc; use wasm_timer::SystemTime; -use sc_telemetry::{telemetry, SUBSTRATE_INFO}; +use sc_telemetry::{ + telemetry, + ConnectionMessage, + TelemetryConnectionNotifier, + TelemetrySpan, + SUBSTRATE_INFO, +}; use sp_transaction_pool::MaintainedTransactionPool; use prometheus_endpoint::Registry; use sc_client_db::{Backend, DatabaseSettings}; @@ -179,6 +184,7 @@ type TFullParts = ( Arc>, KeystoreContainer, TaskManager, + Option, ); type TLightParts = ( @@ -187,6 +193,7 @@ type TLightParts = ( KeystoreContainer, TaskManager, Arc>, + Option, ); /// Light client backend type with a specific hash type. @@ -301,9 +308,14 @@ pub fn new_full_parts( { let keystore_container = KeystoreContainer::new(&config.keystore)?; + let telemetry_span = if config.telemetry_endpoints.is_some() { + Some(TelemetrySpan::new()) + } else { + None + }; let task_manager = { let registry = config.prometheus_config.as_ref().map(|cfg| &cfg.registry); - TaskManager::new(config.task_executor.clone(), registry)? + TaskManager::new(config.task_executor.clone(), registry, telemetry_span.clone())? }; let executor = NativeExecutor::::new( @@ -359,20 +371,26 @@ pub fn new_full_parts( backend, keystore_container, task_manager, + telemetry_span, )) } /// Create the initial parts of a light node. pub fn new_light_parts( - config: &Configuration + config: &Configuration, ) -> Result, Error> where TBl: BlockT, TExecDisp: NativeExecutionDispatch + 'static, { let keystore_container = KeystoreContainer::new(&config.keystore)?; + let telemetry_span = if config.telemetry_endpoints.is_some() { + Some(TelemetrySpan::new()) + } else { + None + }; let task_manager = { let registry = config.prometheus_config.as_ref().map(|cfg| &cfg.registry); - TaskManager::new(config.task_executor.clone(), registry)? + TaskManager::new(config.task_executor.clone(), registry, telemetry_span.clone())? }; let executor = NativeExecutor::::new( @@ -411,7 +429,7 @@ pub fn new_light_parts( config.prometheus_config.as_ref().map(|config| config.registry.clone()), )?); - Ok((client, backend, keystore_container, task_manager, on_demand)) + Ok((client, backend, keystore_container, task_manager, on_demand, telemetry_span)) } /// Create an instance of db-backed client. @@ -463,6 +481,8 @@ pub fn new_client( pub struct SpawnTasksParams<'a, TBl: BlockT, TCl, TExPool, TRpc, Backend> { /// The service configuration. pub config: Configuration, + /// Telemetry span, if any. + pub telemetry_span: Option, /// A shared client returned by `new_full_parts`/`new_light_parts`. pub client: Arc, /// A shared backend returned by `new_full_parts`/`new_light_parts`. @@ -486,8 +506,6 @@ pub struct SpawnTasksParams<'a, TBl: BlockT, TCl, TExPool, TRpc, Backend> { pub network_status_sinks: NetworkStatusSinks, /// A Sender for RPC requests. pub system_rpc_tx: TracingUnboundedSender>, - /// Shared Telemetry connection sinks, - pub telemetry_connection_sinks: TelemetryConnectionSinks, } /// Build a shared offchain workers instance. @@ -534,7 +552,7 @@ pub fn build_offchain_workers( /// Spawn the tasks that are required to run a node. pub fn spawn_tasks( params: SpawnTasksParams, -) -> Result +) -> Result<(RpcHandlers, Option), Error> where TCl: ProvideRuntimeApi + HeaderMetadata + Chain + BlockBackend + BlockIdTo + ProofProvider + @@ -557,6 +575,7 @@ pub fn spawn_tasks( let SpawnTasksParams { mut config, task_manager, + telemetry_span, client, on_demand, backend, @@ -567,7 +586,6 @@ pub fn spawn_tasks( network, network_status_sinks, system_rpc_tx, - telemetry_connection_sinks, } = params; let chain_info = client.usage_info().chain; @@ -578,13 +596,15 @@ pub fn spawn_tasks( config.dev_key_seed.clone().map(|s| vec![s]).unwrap_or_default(), )?; + let telemetry_connection_notifier = telemetry_span + .and_then(|span| init_telemetry( + &mut config, + span, + network.clone(), + client.clone(), + )); + info!("📦 Highest known block at #{}", chain_info.best_number); - telemetry!( - SUBSTRATE_INFO; - "node.start"; - "height" => chain_info.best_number.saturated_into::(), - "best" => ?chain_info.best_hash - ); let spawn_handle = task_manager.spawn_handle(); @@ -642,24 +662,6 @@ pub fn spawn_tasks( sc_rpc_server::RpcMiddleware::new(rpc_metrics, "inbrowser") ).into())); - // Telemetry - let telemetry = config.telemetry_endpoints.clone().and_then(|endpoints| { - if endpoints.is_empty() { - // we don't want the telemetry to be initialized if telemetry_endpoints == Some([]) - return None; - } - - let genesis_hash = match client.block_hash(Zero::zero()) { - Ok(Some(hash)) => hash, - _ => Default::default(), - }; - - Some(build_telemetry( - &mut config, endpoints, telemetry_connection_sinks.clone(), network.clone(), - task_manager.spawn_handle(), genesis_hash, - )) - }); - // Spawn informant task spawn_handle.spawn("informant", sc_informant::build( client.clone(), @@ -668,21 +670,22 @@ pub fn spawn_tasks( config.informant_output_format, )); - task_manager.keep_alive((telemetry, config.base_path, rpc, rpc_handlers.clone())); + task_manager.keep_alive((config.base_path, rpc, rpc_handlers.clone())); - Ok(rpc_handlers) + Ok((rpc_handlers, telemetry_connection_notifier)) } async fn transaction_notifications( transaction_pool: Arc, - network: Arc::Hash>> + network: Arc::Hash>>, ) where TBl: BlockT, TExPool: MaintainedTransactionPool::Hash>, { // transaction notifications - transaction_pool.import_notification_stream() + transaction_pool + .import_notification_stream() .for_each(move |hash| { network.propagate_transaction(hash); let status = transaction_pool.status(); @@ -695,55 +698,35 @@ async fn transaction_notifications( .await; } -fn build_telemetry( +fn init_telemetry>( config: &mut Configuration, - endpoints: sc_telemetry::TelemetryEndpoints, - telemetry_connection_sinks: TelemetryConnectionSinks, + telemetry_span: TelemetrySpan, network: Arc::Hash>>, - spawn_handle: SpawnTaskHandle, - genesis_hash: ::Hash, -) -> sc_telemetry::Telemetry { - let is_authority = config.role.is_authority(); - let network_id = network.local_peer_id().to_base58(); - let name = config.network.node_name.clone(); - let impl_name = config.impl_name.clone(); - let impl_version = config.impl_version.clone(); - let chain_name = config.chain_spec.name().to_owned(); - let telemetry = sc_telemetry::init_telemetry(sc_telemetry::TelemetryConfig { - endpoints, - wasm_external_transport: config.telemetry_external_transport.take(), - }); - let startup_time = SystemTime::UNIX_EPOCH.elapsed() - .map(|dur| dur.as_millis()) - .unwrap_or(0); - - spawn_handle.spawn( - "telemetry-worker", - telemetry.clone() - .for_each(move |event| { - // Safe-guard in case we add more events in the future. - let sc_telemetry::TelemetryEvent::Connected = event; - - telemetry!(SUBSTRATE_INFO; "system.connected"; - "name" => name.clone(), - "implementation" => impl_name.clone(), - "version" => impl_version.clone(), - "config" => "", - "chain" => chain_name.clone(), - "genesis_hash" => ?genesis_hash, - "authority" => is_authority, - "startup_time" => startup_time, - "network_id" => network_id.clone() - ); - - telemetry_connection_sinks.0.lock().retain(|sink| { - sink.unbounded_send(()).is_ok() - }); - ready(()) - }) - ); + client: Arc, +) -> Option { + let endpoints = config.telemetry_endpoints()?.clone(); + let genesis_hash = client.block_hash(Zero::zero()).ok().flatten().unwrap_or_default(); + let connection_message = ConnectionMessage { + name: config.network.node_name.to_owned(), + implementation: config.impl_name.to_owned(), + version: config.impl_version.to_owned(), + config: String::new(), + chain: config.chain_spec.name().to_owned(), + genesis_hash: format!("{:?}", genesis_hash), + authority: config.role.is_authority(), + startup_time: SystemTime::UNIX_EPOCH.elapsed() + .map(|dur| dur.as_millis()) + .unwrap_or(0).to_string(), + network_id: network.local_peer_id().to_base58(), + }; - telemetry + config.telemetry_handle + .as_mut() + .map(|handle| handle.start_telemetry( + telemetry_span, + endpoints, + connection_message, + )) } fn gen_handler( diff --git a/client/service/src/config.rs b/client/service/src/config.rs index 5197aa655b249..c3be40e08397c 100644 --- a/client/service/src/config.rs +++ b/client/service/src/config.rs @@ -96,6 +96,11 @@ pub struct Configuration { /// External WASM transport for the telemetry. If `Some`, when connection to a telemetry /// endpoint, this transport will be tried in priority before all others. pub telemetry_external_transport: Option, + /// Telemetry handle. + /// + /// This is a handle to a `TelemetryWorker` instance. It is used to initialize the telemetry for + /// a substrate node. + pub telemetry_handle: Option, /// The default number of 64KB pages to allocate for Wasm execution pub default_heap_pages: Option, /// Should offchain workers be executed. @@ -198,9 +203,22 @@ impl Configuration { } /// Returns the prometheus metrics registry, if available. - pub fn prometheus_registry<'a>(&'a self) -> Option<&'a Registry> { + pub fn prometheus_registry(&self) -> Option<&Registry> { self.prometheus_config.as_ref().map(|config| &config.registry) } + + /// Returns the telemetry endpoints if any and if the telemetry handle exists. + pub(crate) fn telemetry_endpoints(&self) -> Option<&TelemetryEndpoints> { + if self.telemetry_handle.is_none() { + return None; + } + + match self.telemetry_endpoints.as_ref() { + // Don't initialise telemetry if `telemetry_endpoints` == Some([]) + Some(endpoints) if !endpoints.is_empty() => Some(endpoints), + _ => None, + } + } } /// Available RPC methods. diff --git a/client/service/src/lib.rs b/client/service/src/lib.rs index df1cd47db0f7e..09a08a7dff37b 100644 --- a/client/service/src/lib.rs +++ b/client/service/src/lib.rs @@ -39,7 +39,6 @@ use std::net::SocketAddr; use std::collections::HashMap; use std::time::Duration; use std::task::Poll; -use parking_lot::Mutex; use futures::{Future, FutureExt, Stream, StreamExt, stream, compat::*}; use sc_network::{NetworkStatus, network_state::NetworkState, PeerId}; @@ -48,7 +47,7 @@ use codec::{Encode, Decode}; use sp_runtime::generic::BlockId; use sp_runtime::traits::{Block as BlockT, Header as HeaderT}; use parity_util_mem::MallocSizeOf; -use sp_utils::{status_sinks, mpsc::{tracing_unbounded, TracingUnboundedReceiver, TracingUnboundedSender}}; +use sp_utils::{status_sinks, mpsc::{tracing_unbounded, TracingUnboundedReceiver}}; pub use self::error::Error; pub use self::builder::{ @@ -161,20 +160,7 @@ impl NetworkStatusSinks { } -/// Sinks to propagate telemetry connection established events. -#[derive(Default, Clone)] -pub struct TelemetryConnectionSinks(Arc>>>); - -impl TelemetryConnectionSinks { - /// Get event stream for telemetry connection established events. - pub fn on_connect_stream(&self) -> TracingUnboundedReceiver<()> { - let (sink, stream) =tracing_unbounded("mpsc_telemetry_on_connect"); - self.0.lock().push(sink); - stream - } -} - -/// An imcomplete set of chain components, but enough to run the chain ops subcommands. +/// An incomplete set of chain components, but enough to run the chain ops subcommands. pub struct PartialComponents { /// A shared client instance. pub client: Arc, diff --git a/client/service/src/task_manager/mod.rs b/client/service/src/task_manager/mod.rs index d1ab8c9c2a7ee..4d9e16d900327 100644 --- a/client/service/src/task_manager/mod.rs +++ b/client/service/src/task_manager/mod.rs @@ -34,6 +34,7 @@ use prometheus_endpoint::{ use sp_utils::mpsc::{TracingUnboundedSender, TracingUnboundedReceiver, tracing_unbounded}; use tracing_futures::Instrument; use crate::{config::{TaskExecutor, TaskType, JoinFuture}, Error}; +use sc_telemetry::TelemetrySpan; mod prometheus_future; #[cfg(test)] @@ -46,6 +47,7 @@ pub struct SpawnTaskHandle { executor: TaskExecutor, metrics: Option, task_notifier: TracingUnboundedSender, + telemetry_span: Option, } impl SpawnTaskHandle { @@ -89,7 +91,10 @@ impl SpawnTaskHandle { metrics.tasks_ended.with_label_values(&[name, "finished"]).inc_by(0); } + let telemetry_span = self.telemetry_span.clone(); let future = async move { + let _telemetry_entered = telemetry_span.as_ref().map(|x| x.enter()); + if let Some(metrics) = metrics { // Add some wrappers around `task`. let task = { @@ -228,14 +233,17 @@ pub struct TaskManager { /// terminates and gracefully shutdown. Also ends the parent `future()` if a child's essential /// task fails. children: Vec, + /// A telemetry handle used to enter the telemetry span when a task is spawned. + telemetry_span: Option, } impl TaskManager { - /// If a Prometheus registry is passed, it will be used to report statistics about the - /// service tasks. + /// If a Prometheus registry is passed, it will be used to report statistics about the + /// service tasks. pub(super) fn new( executor: TaskExecutor, - prometheus_registry: Option<&Registry> + prometheus_registry: Option<&Registry>, + telemetry_span: Option, ) -> Result { let (signal, on_exit) = exit_future::signal(); @@ -264,6 +272,7 @@ impl TaskManager { task_notifier, completion_future, children: Vec::new(), + telemetry_span, }) } @@ -274,6 +283,7 @@ impl TaskManager { executor: self.executor.clone(), metrics: self.metrics.clone(), task_notifier: self.task_notifier.clone(), + telemetry_span: self.telemetry_span.clone(), } } diff --git a/client/service/src/task_manager/tests.rs b/client/service/src/task_manager/tests.rs index 0509392ce3888..f0ede1fc389a5 100644 --- a/client/service/src/task_manager/tests.rs +++ b/client/service/src/task_manager/tests.rs @@ -81,13 +81,17 @@ async fn run_background_task_blocking(duration: Duration, _keep_alive: impl Any) } } +fn new_task_manager(task_executor: TaskExecutor) -> TaskManager { + TaskManager::new(task_executor, None, None).unwrap() +} + #[test] fn ensure_tasks_are_awaited_on_shutdown() { let mut runtime = tokio::runtime::Runtime::new().unwrap(); let handle = runtime.handle().clone(); let task_executor: TaskExecutor = (move |future, _| handle.spawn(future).map(|_| ())).into(); - let task_manager = TaskManager::new(task_executor, None).unwrap(); + let task_manager = new_task_manager(task_executor); let spawn_handle = task_manager.spawn_handle(); let drop_tester = DropTester::new(); spawn_handle.spawn("task1", run_background_task(drop_tester.new_ref())); @@ -106,7 +110,7 @@ fn ensure_keep_alive_during_shutdown() { let handle = runtime.handle().clone(); let task_executor: TaskExecutor = (move |future, _| handle.spawn(future).map(|_| ())).into(); - let mut task_manager = TaskManager::new(task_executor, None).unwrap(); + let mut task_manager = new_task_manager(task_executor); let spawn_handle = task_manager.spawn_handle(); let drop_tester = DropTester::new(); task_manager.keep_alive(drop_tester.new_ref()); @@ -125,7 +129,7 @@ fn ensure_blocking_futures_are_awaited_on_shutdown() { let handle = runtime.handle().clone(); let task_executor: TaskExecutor = (move |future, _| handle.spawn(future).map(|_| ())).into(); - let task_manager = TaskManager::new(task_executor, None).unwrap(); + let task_manager = new_task_manager(task_executor); let spawn_handle = task_manager.spawn_handle(); let drop_tester = DropTester::new(); spawn_handle.spawn( @@ -150,7 +154,7 @@ fn ensure_no_task_can_be_spawn_after_terminate() { let handle = runtime.handle().clone(); let task_executor: TaskExecutor = (move |future, _| handle.spawn(future).map(|_| ())).into(); - let mut task_manager = TaskManager::new(task_executor, None).unwrap(); + let mut task_manager = new_task_manager(task_executor); let spawn_handle = task_manager.spawn_handle(); let drop_tester = DropTester::new(); spawn_handle.spawn("task1", run_background_task(drop_tester.new_ref())); @@ -171,7 +175,7 @@ fn ensure_task_manager_future_ends_when_task_manager_terminated() { let handle = runtime.handle().clone(); let task_executor: TaskExecutor = (move |future, _| handle.spawn(future).map(|_| ())).into(); - let mut task_manager = TaskManager::new(task_executor, None).unwrap(); + let mut task_manager = new_task_manager(task_executor); let spawn_handle = task_manager.spawn_handle(); let drop_tester = DropTester::new(); spawn_handle.spawn("task1", run_background_task(drop_tester.new_ref())); @@ -192,7 +196,7 @@ fn ensure_task_manager_future_ends_with_error_when_essential_task_fails() { let handle = runtime.handle().clone(); let task_executor: TaskExecutor = (move |future, _| handle.spawn(future).map(|_| ())).into(); - let mut task_manager = TaskManager::new(task_executor, None).unwrap(); + let mut task_manager = new_task_manager(task_executor); let spawn_handle = task_manager.spawn_handle(); let spawn_essential_handle = task_manager.spawn_essential_handle(); let drop_tester = DropTester::new(); @@ -215,10 +219,10 @@ fn ensure_children_tasks_ends_when_task_manager_terminated() { let handle = runtime.handle().clone(); let task_executor: TaskExecutor = (move |future, _| handle.spawn(future).map(|_| ())).into(); - let mut task_manager = TaskManager::new(task_executor.clone(), None).unwrap(); - let child_1 = TaskManager::new(task_executor.clone(), None).unwrap(); + let mut task_manager = new_task_manager(task_executor.clone()); + let child_1 = new_task_manager(task_executor.clone()); let spawn_handle_child_1 = child_1.spawn_handle(); - let child_2 = TaskManager::new(task_executor.clone(), None).unwrap(); + let child_2 = new_task_manager(task_executor.clone()); let spawn_handle_child_2 = child_2.spawn_handle(); task_manager.add_child(child_1); task_manager.add_child(child_2); @@ -244,11 +248,11 @@ fn ensure_task_manager_future_ends_with_error_when_childs_essential_task_fails() let handle = runtime.handle().clone(); let task_executor: TaskExecutor = (move |future, _| handle.spawn(future).map(|_| ())).into(); - let mut task_manager = TaskManager::new(task_executor.clone(), None).unwrap(); - let child_1 = TaskManager::new(task_executor.clone(), None).unwrap(); + let mut task_manager = new_task_manager(task_executor.clone()); + let child_1 = new_task_manager(task_executor.clone()); let spawn_handle_child_1 = child_1.spawn_handle(); let spawn_essential_handle_child_1 = child_1.spawn_essential_handle(); - let child_2 = TaskManager::new(task_executor.clone(), None).unwrap(); + let child_2 = new_task_manager(task_executor.clone()); let spawn_handle_child_2 = child_2.spawn_handle(); task_manager.add_child(child_1); task_manager.add_child(child_2); @@ -275,10 +279,10 @@ fn ensure_task_manager_future_continues_when_childs_not_essential_task_fails() { let handle = runtime.handle().clone(); let task_executor: TaskExecutor = (move |future, _| handle.spawn(future).map(|_| ())).into(); - let mut task_manager = TaskManager::new(task_executor.clone(), None).unwrap(); - let child_1 = TaskManager::new(task_executor.clone(), None).unwrap(); + let mut task_manager = new_task_manager(task_executor.clone()); + let child_1 = new_task_manager(task_executor.clone()); let spawn_handle_child_1 = child_1.spawn_handle(); - let child_2 = TaskManager::new(task_executor.clone(), None).unwrap(); + let child_2 = new_task_manager(task_executor.clone()); let spawn_handle_child_2 = child_2.spawn_handle(); task_manager.add_child(child_1); task_manager.add_child(child_2); diff --git a/client/service/test/src/lib.rs b/client/service/test/src/lib.rs index bd4f325908b0a..f1d5c6a86b06e 100644 --- a/client/service/test/src/lib.rs +++ b/client/service/test/src/lib.rs @@ -267,6 +267,7 @@ fn node_config **Note**: Cloning the [`Telemetry`] and polling from multiple clones has an unspecified behaviour. +Substrate's nodes initialize/register to the [`TelemetryWorker`] using a [`TelemetryHandle`]. +This handle can be cloned and passed around. It uses an asynchronous channel to communicate with +the running [`TelemetryWorker`] dedicated to registration. Registering a telemetry can happen at +any point in time during the execution. -# Example - -```rust -use futures::prelude::*; - -let telemetry = sc_telemetry::init_telemetry(sc_telemetry::TelemetryConfig { - endpoints: sc_telemetry::TelemetryEndpoints::new(vec![ - // The `0` is the maximum verbosity level of messages to send to this endpoint. - ("wss://example.com".into(), 0) - ]).expect("Invalid URL or multiaddr provided"), - // Can be used to pass an external implementation of WebSockets. - wasm_external_transport: None, -}); - -// The `telemetry` object implements `Stream` and must be processed. -std::thread::spawn(move || { - futures::executor::block_on(telemetry.for_each(|_| future::ready(()))); -}); - -// Sends a message on the telemetry. -sc_telemetry::telemetry!(sc_telemetry::SUBSTRATE_INFO; "test"; - "foo" => "bar", -) -``` - - -License: GPL-3.0-or-later WITH Classpath-exception-2.0 \ No newline at end of file +License: GPL-3.0-or-later WITH Classpath-exception-2.0 diff --git a/client/telemetry/src/async_record.rs b/client/telemetry/src/async_record.rs deleted file mode 100644 index 06650a54defd4..0000000000000 --- a/client/telemetry/src/async_record.rs +++ /dev/null @@ -1,155 +0,0 @@ -//! # Internal types to ssync drain slog -//! FIXME: REMOVE THIS ONCE THE PR WAS MERGE -//! - -use slog::{Record, RecordStatic, Level, SingleKV, KV, BorrowedKV}; -use slog::{Serializer, OwnedKVList, Key}; - -use std::fmt; -use take_mut::take; - -struct ToSendSerializer { - kv: Box, -} - -impl ToSendSerializer { - fn new() -> Self { - ToSendSerializer { kv: Box::new(()) } - } - - fn finish(self) -> Box { - self.kv - } -} - -impl Serializer for ToSendSerializer { - fn emit_bool(&mut self, key: Key, val: bool) -> slog::Result { - take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val)))); - Ok(()) - } - fn emit_unit(&mut self, key: Key) -> slog::Result { - take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, ())))); - Ok(()) - } - fn emit_none(&mut self, key: Key) -> slog::Result { - let val: Option<()> = None; - take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val)))); - Ok(()) - } - fn emit_char(&mut self, key: Key, val: char) -> slog::Result { - take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val)))); - Ok(()) - } - fn emit_u8(&mut self, key: Key, val: u8) -> slog::Result { - take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val)))); - Ok(()) - } - fn emit_i8(&mut self, key: Key, val: i8) -> slog::Result { - take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val)))); - Ok(()) - } - fn emit_u16(&mut self, key: Key, val: u16) -> slog::Result { - take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val)))); - Ok(()) - } - fn emit_i16(&mut self, key: Key, val: i16) -> slog::Result { - take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val)))); - Ok(()) - } - fn emit_u32(&mut self, key: Key, val: u32) -> slog::Result { - take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val)))); - Ok(()) - } - fn emit_i32(&mut self, key: Key, val: i32) -> slog::Result { - take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val)))); - Ok(()) - } - fn emit_f32(&mut self, key: Key, val: f32) -> slog::Result { - take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val)))); - Ok(()) - } - fn emit_u64(&mut self, key: Key, val: u64) -> slog::Result { - take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val)))); - Ok(()) - } - fn emit_i64(&mut self, key: Key, val: i64) -> slog::Result { - take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val)))); - Ok(()) - } - fn emit_f64(&mut self, key: Key, val: f64) -> slog::Result { - take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val)))); - Ok(()) - } - fn emit_usize(&mut self, key: Key, val: usize) -> slog::Result { - take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val)))); - Ok(()) - } - fn emit_isize(&mut self, key: Key, val: isize) -> slog::Result { - take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val)))); - Ok(()) - } - fn emit_str(&mut self, key: Key, val: &str) -> slog::Result { - let val = val.to_owned(); - take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val)))); - Ok(()) - } - fn emit_arguments( - &mut self, - key: Key, - val: &fmt::Arguments, - ) -> slog::Result { - let val = fmt::format(*val); - take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val)))); - Ok(()) - } - - fn emit_serde(&mut self, key: Key, value: &dyn slog::SerdeValue) -> slog::Result { - let val = value.to_sendable(); - take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val)))); - Ok(()) - } -} - -pub(crate) struct AsyncRecord { - msg: String, - level: Level, - location: Box, - tag: String, - logger_values: OwnedKVList, - kv: Box, -} - -impl AsyncRecord { - /// Serializes a `Record` and an `OwnedKVList`. - pub fn from(record: &Record, logger_values: &OwnedKVList) -> Self { - let mut ser = ToSendSerializer::new(); - record - .kv() - .serialize(record, &mut ser) - .expect("`ToSendSerializer` can't fail"); - - AsyncRecord { - msg: fmt::format(*record.msg()), - level: record.level(), - location: Box::new(*record.location()), - tag: String::from(record.tag()), - logger_values: logger_values.clone(), - kv: ser.finish(), - } - } - - /// Deconstruct this `AsyncRecord` into a record and `OwnedKVList`. - pub fn as_record_values(&self, mut f: impl FnMut(&Record, &OwnedKVList)) { - let rs = RecordStatic { - location: &*self.location, - level: self.level, - tag: &self.tag, - }; - - f(&Record::new( - &rs, - &format_args!("{}", self.msg), - BorrowedKV(&self.kv), - ), &self.logger_values) - } -} diff --git a/client/telemetry/src/endpoints.rs b/client/telemetry/src/endpoints.rs new file mode 100644 index 0000000000000..7d0338fb18e3c --- /dev/null +++ b/client/telemetry/src/endpoints.rs @@ -0,0 +1,125 @@ +// This file is part of Substrate. + +// Copyright (C) 2021 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 libp2p::Multiaddr; +use serde::{Deserialize, Deserializer, Serialize}; + +/// List of telemetry servers we want to talk to. Contains the URL of the server, and the +/// maximum verbosity level. +/// +/// The URL string can be either a URL or a multiaddress. +#[derive(Debug, Clone, Serialize, Deserialize, PartialEq, Eq, Hash)] +pub struct TelemetryEndpoints( + #[serde(deserialize_with = "url_or_multiaddr_deser")] pub(crate) Vec<(Multiaddr, u8)>, +); + +/// Custom deserializer for TelemetryEndpoints, used to convert urls or multiaddr to multiaddr. +fn url_or_multiaddr_deser<'de, D>(deserializer: D) -> Result, D::Error> +where + D: Deserializer<'de>, +{ + Vec::<(String, u8)>::deserialize(deserializer)? + .iter() + .map(|e| { + url_to_multiaddr(&e.0) + .map_err(serde::de::Error::custom) + .map(|m| (m, e.1)) + }) + .collect() +} + +impl TelemetryEndpoints { + /// Create a `TelemetryEndpoints` based on a list of `(String, u8)`. + pub fn new(endpoints: Vec<(String, u8)>) -> Result { + let endpoints: Result, libp2p::multiaddr::Error> = endpoints + .iter() + .map(|e| Ok((url_to_multiaddr(&e.0)?, e.1))) + .collect(); + endpoints.map(Self) + } +} + +impl TelemetryEndpoints { + /// Return `true` if there are no telemetry endpoints, `false` otherwise. + pub fn is_empty(&self) -> bool { + self.0.is_empty() + } +} + +/// Parses a WebSocket URL into a libp2p `Multiaddr`. +fn url_to_multiaddr(url: &str) -> Result { + // First, assume that we have a `Multiaddr`. + let parse_error = match url.parse() { + Ok(ma) => return Ok(ma), + Err(err) => err, + }; + + // If not, try the `ws://path/url` format. + if let Ok(ma) = libp2p::multiaddr::from_url(url) { + return Ok(ma); + } + + // If we have no clue about the format of that string, assume that we were expecting a + // `Multiaddr`. + Err(parse_error) +} + +#[cfg(test)] +mod tests { + use super::url_to_multiaddr; + use super::TelemetryEndpoints; + use libp2p::Multiaddr; + + #[test] + fn valid_endpoints() { + let endp = vec![ + ("wss://telemetry.polkadot.io/submit/".into(), 3), + ("/ip4/80.123.90.4/tcp/5432".into(), 4), + ]; + let telem = + TelemetryEndpoints::new(endp.clone()).expect("Telemetry endpoint should be valid"); + let mut res: Vec<(Multiaddr, u8)> = vec![]; + for (a, b) in endp.iter() { + res.push(( + url_to_multiaddr(a).expect("provided url should be valid"), + *b, + )) + } + assert_eq!(telem.0, res); + } + + #[test] + fn invalid_endpoints() { + let endp = vec![ + ("/ip4/...80.123.90.4/tcp/5432".into(), 3), + ("/ip4/no:!?;rlkqre;;::::///tcp/5432".into(), 4), + ]; + let telem = TelemetryEndpoints::new(endp); + assert!(telem.is_err()); + } + + #[test] + fn valid_and_invalid_endpoints() { + let endp = vec![ + ("/ip4/80.123.90.4/tcp/5432".into(), 3), + ("/ip4/no:!?;rlkqre;;::::///tcp/5432".into(), 4), + ]; + let telem = TelemetryEndpoints::new(endp); + assert!(telem.is_err()); + } +} diff --git a/client/telemetry/src/layer.rs b/client/telemetry/src/layer.rs new file mode 100644 index 0000000000000..eb5eee197770b --- /dev/null +++ b/client/telemetry/src/layer.rs @@ -0,0 +1,149 @@ +// This file is part of Substrate. + +// Copyright (C) 2021 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 crate::{initialize_transport, TelemetryWorker}; +use futures::channel::mpsc; +use libp2p::wasm_ext::ExtTransport; +use parking_lot::Mutex; +use std::convert::TryInto; +use std::io; +use tracing::{Event, Id, Subscriber}; +use tracing_subscriber::{layer::Context, registry::LookupSpan, Layer}; + +/// Span name used to report the telemetry. +pub const TELEMETRY_LOG_SPAN: &str = "telemetry-logger"; + +/// `Layer` that handles the logs for telemetries. +#[derive(Debug)] +pub struct TelemetryLayer(Mutex>); + +impl TelemetryLayer { + /// Create a new [`TelemetryLayer`] and [`TelemetryWorker`]. + /// + /// If not provided, the `buffer_size` will be 16 by default. + /// + /// The [`ExtTransport`] is used in WASM contexts where we need some binding between the + /// networking provided by the operating system or environment and libp2p. + /// + /// > **Important**: Each individual call to `write` corresponds to one message. There is no + /// > internal buffering going on. In the context of WebSockets, each `write` + /// > must be one individual WebSockets frame. + pub fn new( + buffer_size: Option, + telemetry_external_transport: Option, + ) -> io::Result<(Self, TelemetryWorker)> { + let transport = initialize_transport(telemetry_external_transport)?; + let worker = TelemetryWorker::new(buffer_size.unwrap_or(16), transport); + let sender = worker.message_sender(); + Ok((Self(Mutex::new(sender)), worker)) + } +} + +impl Layer for TelemetryLayer +where + S: Subscriber + for<'a> LookupSpan<'a>, +{ + fn on_event(&self, event: &Event<'_>, ctx: Context) { + if event.metadata().target() != TELEMETRY_LOG_SPAN { + return; + } + + if let Some(span) = ctx.lookup_current() { + let parents = span.parents(); + + if let Some(span) = std::iter::once(span) + .chain(parents) + .find(|x| x.name() == TELEMETRY_LOG_SPAN) + { + let id = span.id(); + let mut attrs = TelemetryAttrs::new(id.clone()); + let mut vis = TelemetryAttrsVisitor(&mut attrs); + event.record(&mut vis); + + if let TelemetryAttrs { + verbosity: Some(verbosity), + json: Some(json), + .. + } = attrs + { + match self.0.lock().try_send(( + id, + verbosity + .try_into() + .expect("telemetry log message verbosity are u8; qed"), + json, + )) { + Err(err) if err.is_full() => eprintln!("Telemetry buffer overflowed!"), + _ => {} + } + } else { + // NOTE: logging in this function doesn't work + eprintln!( + "missing fields in telemetry log: {:?}. This can happen if \ + `tracing::info_span!` is (mis-)used with the telemetry target \ + directly; you should use the `telemetry!` macro.", + event, + ); + } + } + } + } +} + +#[derive(Debug)] +struct TelemetryAttrs { + verbosity: Option, + json: Option, + id: Id, +} + +impl TelemetryAttrs { + fn new(id: Id) -> Self { + Self { + verbosity: None, + json: None, + id, + } + } +} + +#[derive(Debug)] +struct TelemetryAttrsVisitor<'a>(&'a mut TelemetryAttrs); + +impl<'a> tracing::field::Visit for TelemetryAttrsVisitor<'a> { + fn record_debug(&mut self, _field: &tracing::field::Field, _value: &dyn std::fmt::Debug) { + // noop + } + + fn record_u64(&mut self, field: &tracing::field::Field, value: u64) { + if field.name() == "verbosity" { + (*self.0).verbosity = Some(value); + } + } + + fn record_str(&mut self, field: &tracing::field::Field, value: &str) { + if field.name() == "json" { + (*self.0).json = Some(format!( + r#"{{"id":{},"ts":{:?},"payload":{}}}"#, + self.0.id.into_u64(), + chrono::Local::now().to_rfc3339().to_string(), + value, + )); + } + } +} diff --git a/client/telemetry/src/lib.rs b/client/telemetry/src/lib.rs index 58c9fe73b28cf..6a4533bb7bc40 100644 --- a/client/telemetry/src/lib.rs +++ b/client/telemetry/src/lib.rs @@ -16,339 +16,472 @@ // You should have received a copy of the GNU General Public License // along with this program. If not, see . -//! Telemetry utilities. +//! Substrate's client telemetry is a part of substrate that allows logging telemetry information +//! with a [Polkadot telemetry](https://github.com/paritytech/substrate-telemetry). //! -//! Calling `init_telemetry` registers a global `slog` logger using `slog_scope::set_global_logger`. -//! After that, calling `slog_scope::with_logger` will return a logger that sends information to -//! the telemetry endpoints. The `telemetry!` macro is a short-cut for calling -//! `slog_scope::with_logger` followed with `slog_log!`. +//! It works using Tokio's [tracing](https://github.com/tokio-rs/tracing/). The telemetry +//! information uses tracing's logging to report the telemetry which is then retrieved by a +//! tracing's `Layer`. This layer will then send the data through an asynchronous channel and to a +//! background task called [`TelemetryWorker`] which will send the information to the telemetry +//! server. //! -//! Note that you are supposed to only ever use `telemetry!` and not `slog_scope::with_logger` at -//! the moment. Substrate may eventually be reworked to get proper `slog` support, including sending -//! information to the telemetry. -//! -//! The [`Telemetry`] struct implements `Stream` and must be polled regularly (or sent to a -//! background thread/task) in order for the telemetry to properly function. Dropping the object -//! will also deregister the global logger and replace it with a logger that discards messages. -//! The `Stream` generates [`TelemetryEvent`]s. -//! -//! > **Note**: Cloning the [`Telemetry`] and polling from multiple clones has an unspecified behaviour. -//! -//! # Example -//! -//! ```no_run -//! use futures::prelude::*; -//! -//! let telemetry = sc_telemetry::init_telemetry(sc_telemetry::TelemetryConfig { -//! endpoints: sc_telemetry::TelemetryEndpoints::new(vec![ -//! // The `0` is the maximum verbosity level of messages to send to this endpoint. -//! ("wss://example.com".into(), 0) -//! ]).expect("Invalid URL or multiaddr provided"), -//! // Can be used to pass an external implementation of WebSockets. -//! wasm_external_transport: None, -//! }); -//! -//! // The `telemetry` object implements `Stream` and must be processed. -//! std::thread::spawn(move || { -//! futures::executor::block_on(telemetry.for_each(|_| future::ready(()))); -//! }); -//! -//! // Sends a message on the telemetry. -//! sc_telemetry::telemetry!(sc_telemetry::SUBSTRATE_INFO; "test"; -//! "foo" => "bar", -//! ) -//! ``` +//! If multiple substrate nodes are running, it uses a tracing's `Span` to identify which substrate +//! node is reporting the telemetry. Every task spawned using sc-service's `TaskManager` +//! automatically inherit this span. //! +//! Substrate's nodes initialize/register to the [`TelemetryWorker`] using a [`TelemetryHandle`]. +//! This handle can be cloned and passed around. It uses an asynchronous channel to communicate with +//! the running [`TelemetryWorker`] dedicated to registration. Registering a telemetry can happen at +//! any point in time during the execution. + +#![warn(missing_docs)] -use futures::{prelude::*, channel::mpsc}; -use libp2p::{Multiaddr, wasm_ext}; +use futures::{channel::mpsc, prelude::*}; +use libp2p::Multiaddr; use log::{error, warn}; -use parking_lot::Mutex; -use serde::{Serialize, Deserialize, Deserializer}; -use std::{pin::Pin, sync::Arc, task::{Context, Poll}, time::Duration}; -use wasm_timer::Instant; +use serde::Serialize; +use sp_utils::mpsc::{tracing_unbounded, TracingUnboundedReceiver}; +use std::collections::HashMap; +use tracing::Id; pub use libp2p::wasm_ext::ExtTransport; -pub use slog_scope::with_logger; -pub use slog; - -mod async_record; -mod worker; - -/// Configuration for telemetry. -pub struct TelemetryConfig { - /// Collection of telemetry WebSocket servers with a corresponding verbosity level. - pub endpoints: TelemetryEndpoints, - - /// Optional external implementation of a libp2p transport. Used in WASM contexts where we need - /// some binding between the networking provided by the operating system or environment and - /// libp2p. - /// - /// This parameter exists whatever the target platform is, but it is expected to be set to - /// `Some` only when compiling for WASM. - /// - /// > **Important**: Each individual call to `write` corresponds to one message. There is no - /// > internal buffering going on. In the context of WebSockets, each `write` - /// > must be one individual WebSockets frame. - pub wasm_external_transport: Option, -} - -/// List of telemetry servers we want to talk to. Contains the URL of the server, and the -/// maximum verbosity level. -/// -/// The URL string can be either a URL or a multiaddress. -#[derive(Debug, Clone, Serialize, Deserialize, PartialEq)] -pub struct TelemetryEndpoints( - #[serde(deserialize_with = "url_or_multiaddr_deser")] - Vec<(Multiaddr, u8)> -); - -/// Custom deserializer for TelemetryEndpoints, used to convert urls or multiaddr to multiaddr. -fn url_or_multiaddr_deser<'de, D>(deserializer: D) -> Result, D::Error> - where D: Deserializer<'de> -{ - Vec::<(String, u8)>::deserialize(deserializer)? - .iter() - .map(|e| Ok((url_to_multiaddr(&e.0) - .map_err(serde::de::Error::custom)?, e.1))) - .collect() -} - -impl TelemetryEndpoints { - pub fn new(endpoints: Vec<(String, u8)>) -> Result { - let endpoints: Result, libp2p::multiaddr::Error> = endpoints.iter() - .map(|e| Ok((url_to_multiaddr(&e.0)?, e.1))) - .collect(); - endpoints.map(Self) +pub use serde_json; +pub use tracing; + +mod endpoints; +mod layer; +mod node; +mod transport; + +pub use endpoints::*; +pub use layer::*; +use node::*; +use transport::*; + +/// Substrate DEBUG log level. +pub const SUBSTRATE_DEBUG: u8 = 9; +/// Substrate INFO log level. +pub const SUBSTRATE_INFO: u8 = 0; + +/// Consensus TRACE log level. +pub const CONSENSUS_TRACE: u8 = 9; +/// Consensus DEBUG log level. +pub const CONSENSUS_DEBUG: u8 = 5; +/// Consensus WARN log level. +pub const CONSENSUS_WARN: u8 = 4; +/// Consensus INFO log level. +pub const CONSENSUS_INFO: u8 = 1; + +pub(crate) type TelemetryMessage = (Id, u8, String); + +/// A handle representing a telemetry span, with the capability to enter the span if it exists. +#[derive(Debug, Clone)] +pub struct TelemetrySpan(tracing::Span); + +impl TelemetrySpan { + /// Enters this span, returning a guard that will exit the span when dropped. + pub fn enter(&self) -> tracing::span::Entered { + self.0.enter() } -} -impl TelemetryEndpoints { - /// Return `true` if there are no telemetry endpoints, `false` otherwise. - pub fn is_empty(&self) -> bool { - self.0.is_empty() + /// Constructs a new [`TelemetrySpan`]. + pub fn new() -> Self { + Self(tracing::info_span!(TELEMETRY_LOG_SPAN)) } } -/// Parses a WebSocket URL into a libp2p `Multiaddr`. -fn url_to_multiaddr(url: &str) -> Result { - // First, assume that we have a `Multiaddr`. - let parse_error = match url.parse() { - Ok(ma) => return Ok(ma), - Err(err) => err, - }; - - // If not, try the `ws://path/url` format. - if let Ok(ma) = libp2p::multiaddr::from_url(url) { - return Ok(ma) - } - - // If we have no clue about the format of that string, assume that we were expecting a - // `Multiaddr`. - Err(parse_error) +/// Message sent when the connection (re-)establishes. +#[derive(Debug, Serialize)] +pub struct ConnectionMessage { + /// Node's name. + pub name: String, + /// Node's implementation. + pub implementation: String, + /// Node's version. + pub version: String, + /// Node's configuration. + pub config: String, + /// Node's chain. + pub chain: String, + /// Node's genesis hash. + pub genesis_hash: String, + /// Node is an authority. + pub authority: bool, + /// Node's startup time. + pub startup_time: String, + /// Node's network ID. + pub network_id: String, } -/// Log levels. -pub const SUBSTRATE_DEBUG: &str = "9"; -pub const SUBSTRATE_INFO: &str = "0"; - -pub const CONSENSUS_TRACE: &str = "9"; -pub const CONSENSUS_DEBUG: &str = "5"; -pub const CONSENSUS_WARN: &str = "4"; -pub const CONSENSUS_INFO: &str = "1"; - -/// Telemetry object. Implements `Future` and must be polled regularly. -/// Contains an `Arc` and can be cloned and pass around. Only one clone needs to be polled -/// regularly and should be polled regularly. -/// Dropping all the clones unregisters the telemetry. -#[derive(Clone)] -pub struct Telemetry { - inner: Arc>, - /// Slog guard so that we don't get deregistered. - _guard: Arc, -} - -/// Behind the `Mutex` in `Telemetry`. +/// Telemetry worker. /// -/// Note that ideally we wouldn't have to make the `Telemetry` cloneable, as that would remove the -/// need for a `Mutex`. However there is currently a weird hack in place in `sc-service` -/// where we extract the telemetry registration so that it continues running during the shutdown -/// process. -struct TelemetryInner { - /// Worker for the telemetry. `None` if it failed to initialize. - worker: Option, - /// Receives log entries for them to be dispatched to the worker. - receiver: mpsc::Receiver, +/// It should be ran as a background task using the [`TelemetryWorker::run`] method. This method +/// will consume the object and any further attempts of initializing a new telemetry through its +/// handle will fail (without being fatal). +#[derive(Debug)] +pub struct TelemetryWorker { + message_receiver: mpsc::Receiver, + message_sender: mpsc::Sender, + register_receiver: mpsc::UnboundedReceiver, + register_sender: mpsc::UnboundedSender, + transport: WsTrans, } -/// Implements `slog::Drain`. -struct TelemetryDrain { - /// Sends log entries. - sender: std::panic::AssertUnwindSafe>, -} +impl TelemetryWorker { + pub(crate) fn new(buffer_size: usize, transport: WsTrans) -> Self { + let (message_sender, message_receiver) = mpsc::channel(buffer_size); + let (register_sender, register_receiver) = mpsc::unbounded(); + + Self { + message_receiver, + message_sender, + register_receiver, + register_sender, + transport, + } + } -/// Initializes the telemetry. See the crate root documentation for more information. -/// -/// Please be careful to not call this function twice in the same program. The `slog` crate -/// doesn't provide any way of knowing whether a global logger has already been registered. -pub fn init_telemetry(config: TelemetryConfig) -> Telemetry { - // Build the list of telemetry endpoints. - let (endpoints, wasm_external_transport) = (config.endpoints.0, config.wasm_external_transport); - - let (sender, receiver) = mpsc::channel(16); - let guard = { - let logger = TelemetryDrain { sender: std::panic::AssertUnwindSafe(sender) }; - let root = slog::Logger::root(slog::Drain::fuse(logger), slog::o!()); - slog_scope::set_global_logger(root) - }; - - let worker = match worker::TelemetryWorker::new(endpoints, wasm_external_transport) { - Ok(w) => Some(w), - Err(err) => { - error!(target: "telemetry", "Failed to initialize telemetry worker: {:?}", err); - None + /// Get a new [`TelemetryHandle`]. + /// + /// This is used when you want to register a new telemetry for a Substrate node. + pub fn handle(&self) -> TelemetryHandle { + TelemetryHandle { + message_sender: self.register_sender.clone(), } - }; + } - Telemetry { - inner: Arc::new(Mutex::new(TelemetryInner { - worker, - receiver, - })), - _guard: Arc::new(guard), + /// Get a clone of the channel's `Sender` used to send telemetry events. + pub(crate) fn message_sender(&self) -> mpsc::Sender { + self.message_sender.clone() } -} -/// Event generated when polling the worker. -#[derive(Debug)] -pub enum TelemetryEvent { - /// We have established a connection to one of the telemetry endpoint, either for the first - /// time or after having been disconnected earlier. - Connected, -} + /// Run the telemetry worker. + /// + /// This should be run in a background task. + pub async fn run(self) { + let Self { + mut message_receiver, + message_sender: _, + mut register_receiver, + register_sender: _, + transport, + } = self; + + let mut node_map: HashMap> = HashMap::new(); + let mut node_pool: HashMap = HashMap::new(); -impl Stream for Telemetry { - type Item = TelemetryEvent; - - fn poll_next(self: Pin<&mut Self>, cx: &mut Context) -> Poll> { - let before = Instant::now(); - - // Because the `Telemetry` is cloneable, we need to put the actual fields behind a `Mutex`. - // However, the user is only ever supposed to poll from one instance of `Telemetry`, while - // the other instances are used only for RAII purposes. - // We assume that the user is following this advice and therefore that the `Mutex` is only - // ever locked once at a time. - let mut inner = match self.inner.try_lock() { - Some(l) => l, - None => { - warn!( - target: "telemetry", - "The telemetry seems to be polled multiple times simultaneously" - ); - // Returning `Pending` here means that we may never get polled again, but this is - // ok because we're in a situation where something else is actually currently doing - // the polling. - return Poll::Pending; + loop { + futures::select! { + message = message_receiver.next() => Self::process_message( + message, + &mut node_pool, + &node_map, + ).await, + init_payload = register_receiver.next() => Self::process_register( + init_payload, + &mut node_pool, + &mut node_map, + transport.clone(), + ).await, } - }; - - let mut has_connected = false; + } + } - // The polling pattern is: poll the worker so that it processes its queue, then add one - // message from the receiver (if possible), then poll the worker again, and so on. - loop { - if let Some(worker) = inner.worker.as_mut() { - while let Poll::Ready(event) = worker.poll(cx) { - // Right now we only have one possible event. This line is here in order to not - // forget to handle any possible new event type. - let worker::TelemetryWorkerEvent::Connected = event; - has_connected = true; + async fn process_register( + input: Option, + node_pool: &mut HashMap>, + node_map: &mut HashMap>, + transport: WsTrans, + ) { + let input = input.expect("the stream is never closed; qed"); + + match input { + Register::Telemetry { + id, + endpoints, + connection_message, + } => { + let endpoints = endpoints.0; + + let connection_message = match serde_json::to_value(&connection_message) { + Ok(serde_json::Value::Object(mut value)) => { + value.insert("msg".into(), "system.connected".into()); + let mut obj = serde_json::Map::new(); + obj.insert("id".to_string(), id.into_u64().into()); + obj.insert("payload".to_string(), value.into()); + Some(obj) + } + Ok(_) => { + unreachable!("ConnectionMessage always serialize to an object; qed") + } + Err(err) => { + log::error!( + target: "telemetry", + "Could not serialize connection message: {}", + err, + ); + None + } + }; + + for (addr, verbosity) in endpoints { + node_map + .entry(id.clone()) + .or_default() + .push((verbosity, addr.clone())); + + let node = node_pool.entry(addr.clone()).or_insert_with(|| { + Node::new(transport.clone(), addr.clone(), Vec::new(), Vec::new()) + }); + + node.connection_messages.extend(connection_message.clone()); } } - - if let Poll::Ready(Some(log_entry)) = Stream::poll_next(Pin::new(&mut inner.receiver), cx) { - if let Some(worker) = inner.worker.as_mut() { - log_entry.as_record_values(|rec, val| { let _ = worker.log(rec, val); }); + Register::Notifier { + addresses, + connection_notifier, + } => { + for addr in addresses { + if let Some(node) = node_pool.get_mut(&addr) { + node.telemetry_connection_notifier + .push(connection_notifier.clone()); + } else { + log::error!( + target: "telemetry", + "Received connection notifier for unknown node ({}). This is a bug.", + addr, + ); + } } - } else { - break; } } + } - if before.elapsed() > Duration::from_millis(200) { - warn!(target: "telemetry", "Polling the telemetry took more than 200ms"); - } + // dispatch messages to the telemetry nodes + async fn process_message( + input: Option, + node_pool: &mut HashMap>, + node_map: &HashMap>, + ) { + let (id, verbosity, message) = input.expect("the stream is never closed; qed"); - if has_connected { - Poll::Ready(Some(TelemetryEvent::Connected)) + let nodes = if let Some(nodes) = node_map.get(&id) { + nodes } else { - Poll::Pending + // This is a normal error because the telemetry span is entered before the telemetry + // is initialized so it is possible that some messages in the beginning don't get + // through. + log::trace!( + target: "telemetry", + "Received telemetry log for unknown id ({:?}): {}", + id, + message, + ); + return; + }; + + for (node_max_verbosity, addr) in nodes { + if verbosity > *node_max_verbosity { + log::trace!( + target: "telemetry", + "Skipping {} for log entry with verbosity {:?}", + addr, + verbosity, + ); + continue; + } + + if let Some(node) = node_pool.get_mut(&addr) { + let _ = node.send(message.clone()).await; + } else { + log::error!( + target: "telemetry", + "Received message for unknown node ({}). This is a bug. \ + Message sent: {}", + addr, + message, + ); + } } } } -impl slog::Drain for TelemetryDrain { - type Ok = (); - type Err = (); - - fn log(&self, record: &slog::Record, values: &slog::OwnedKVList) -> Result { - let before = Instant::now(); +/// Handle to the [`TelemetryWorker`] thats allows initializing the telemetry for a Substrate node. +#[derive(Debug, Clone)] +pub struct TelemetryHandle { + message_sender: mpsc::UnboundedSender, +} - let serialized = async_record::AsyncRecord::from(record, values); - // Note: interestingly, `try_send` requires a `&mut` because it modifies some internal value, while `clone()` - // is lock-free. - if let Err(err) = self.sender.clone().try_send(serialized) { - warn!(target: "telemetry", "Ignored telemetry message because of error on channel: {:?}", err); - } +impl TelemetryHandle { + /// Initialize the telemetry with the endpoints provided in argument for the current substrate + /// node. + /// + /// This method must be called during the substrate node initialization. + /// + /// The `endpoints` argument is a collection of telemetry WebSocket servers with a corresponding + /// verbosity level. + /// + /// The `connection_message` argument is a JSON object that is sent every time the connection + /// (re-)establishes. + pub fn start_telemetry( + &mut self, + span: TelemetrySpan, + endpoints: TelemetryEndpoints, + connection_message: ConnectionMessage, + ) -> TelemetryConnectionNotifier { + let Self { message_sender } = self; + + let connection_notifier = TelemetryConnectionNotifier { + message_sender: message_sender.clone(), + addresses: endpoints.0.iter().map(|(addr, _)| addr.clone()).collect(), + }; - if before.elapsed() > Duration::from_millis(50) { - warn!(target: "telemetry", "Writing a telemetry log took more than 50ms"); + match span.0.id() { + Some(id) => { + match message_sender.unbounded_send(Register::Telemetry { + id, + endpoints, + connection_message, + }) { + Ok(()) => {} + Err(err) => error!( + target: "telemetry", + "Could not initialize telemetry: \ + the telemetry is probably already running: {}", + err, + ), + } + } + None => error!( + target: "telemetry", + "Could not initialize telemetry: the span could not be entered", + ), } - Ok(()) + connection_notifier } } -/// Translates to `slog_scope::info`, but contains an additional verbosity -/// parameter which the log record is tagged with. Additionally the verbosity -/// parameter is added to the record as a key-value pair. -#[macro_export] -macro_rules! telemetry { - ( $a:expr; $b:expr; $( $t:tt )* ) => { - $crate::with_logger(|l| { - $crate::slog::slog_info!(l, #$a, $b; $($t)* ) - }) - } +/// Used to create a stream of events with only one event: when a telemetry connection +/// (re-)establishes. +#[derive(Clone, Debug)] +pub struct TelemetryConnectionNotifier { + message_sender: mpsc::UnboundedSender, + addresses: Vec, } -#[cfg(test)] -mod telemetry_endpoints_tests { - use libp2p::Multiaddr; - use super::TelemetryEndpoints; - use super::url_to_multiaddr; - - #[test] - fn valid_endpoints() { - let endp = vec![("wss://telemetry.polkadot.io/submit/".into(), 3), ("/ip4/80.123.90.4/tcp/5432".into(), 4)]; - let telem = TelemetryEndpoints::new(endp.clone()).expect("Telemetry endpoint should be valid"); - let mut res: Vec<(Multiaddr, u8)> = vec![]; - for (a, b) in endp.iter() { - res.push((url_to_multiaddr(a).expect("provided url should be valid"), *b)) +impl TelemetryConnectionNotifier { + /// Get event stream for telemetry connection established events. + /// + /// This function will return an error if the telemetry has already been started by + /// [`TelemetryHandle::start_telemetry`]. + pub fn on_connect_stream(&self) -> TracingUnboundedReceiver<()> { + let (message_sender, message_receiver) = tracing_unbounded("mpsc_telemetry_on_connect"); + if let Err(err) = self.message_sender.unbounded_send(Register::Notifier { + addresses: self.addresses.clone(), + connection_notifier: message_sender, + }) { + error!( + target: "telemetry", + "Could not create a telemetry connection notifier: \ + the telemetry is probably already running: {}", + err, + ); } - assert_eq!(telem.0, res); + message_receiver } +} - #[test] - fn invalid_endpoints() { - let endp = vec![("/ip4/...80.123.90.4/tcp/5432".into(), 3), ("/ip4/no:!?;rlkqre;;::::///tcp/5432".into(), 4)]; - let telem = TelemetryEndpoints::new(endp); - assert!(telem.is_err()); - } +#[derive(Debug)] +enum Register { + Telemetry { + id: Id, + endpoints: TelemetryEndpoints, + connection_message: ConnectionMessage, + }, + Notifier { + addresses: Vec, + connection_notifier: ConnectionNotifierSender, + }, +} - #[test] - fn valid_and_invalid_endpoints() { - let endp = vec![("/ip4/80.123.90.4/tcp/5432".into(), 3), ("/ip4/no:!?;rlkqre;;::::///tcp/5432".into(), 4)]; - let telem = TelemetryEndpoints::new(endp); - assert!(telem.is_err()); - } +/// Report a telemetry. +/// +/// Translates to [`tracing::info`], but contains an additional verbosity parameter which the log +/// record is tagged with. Additionally the verbosity parameter is added to the record as a +/// key-value pair. +/// +/// # Example +/// +/// ```no_run +/// # use sc_telemetry::*; +/// # let authority_id = 42_u64; +/// # let set_id = (43_u64, 44_u64); +/// # let authorities = vec![45_u64]; +/// telemetry!(CONSENSUS_INFO; "afg.authority_set"; +/// "authority_id" => authority_id.to_string(), +/// "authority_set_id" => ?set_id, +/// "authorities" => authorities, +/// ); +/// ``` +#[macro_export(local_inner_macros)] +macro_rules! telemetry { + ( $verbosity:expr; $msg:expr; $( $t:tt )* ) => {{ + let verbosity: u8 = $verbosity; + match format_fields_to_json!($($t)*) { + Err(err) => { + $crate::tracing::error!( + target: "telemetry", + "Could not serialize value for telemetry: {}", + err, + ); + }, + Ok(mut json) => { + // NOTE: the span id will be added later in the JSON for the greater good + json.insert("msg".into(), $msg.into()); + let serialized_json = $crate::serde_json::to_string(&json) + .expect("contains only string keys; qed"); + $crate::tracing::info!(target: $crate::TELEMETRY_LOG_SPAN, + verbosity, + json = serialized_json.as_str(), + ); + }, + } + }}; +} + +#[macro_export(local_inner_macros)] +#[doc(hidden)] +macro_rules! format_fields_to_json { + ( $k:literal => $v:expr $(,)? $(, $($t:tt)+ )? ) => {{ + $crate::serde_json::to_value(&$v) + .map(|value| { + let mut map = $crate::serde_json::Map::new(); + map.insert($k.into(), value); + map + }) + $( + .and_then(|mut prev_map| { + format_fields_to_json!($($t)*) + .map(move |mut other_map| { + prev_map.append(&mut other_map); + prev_map + }) + }) + )* + }}; + ( $k:literal => ? $v:expr $(,)? $(, $($t:tt)+ )? ) => {{ + let mut map = $crate::serde_json::Map::new(); + map.insert($k.into(), std::format!("{:?}", &$v).into()); + $crate::serde_json::Result::Ok(map) + $( + .and_then(|mut prev_map| { + format_fields_to_json!($($t)*) + .map(move |mut other_map| { + prev_map.append(&mut other_map); + prev_map + }) + }) + )* + }}; } diff --git a/client/telemetry/src/node.rs b/client/telemetry/src/node.rs new file mode 100644 index 0000000000000..e47bc2f9634f7 --- /dev/null +++ b/client/telemetry/src/node.rs @@ -0,0 +1,286 @@ +// This file is part of Substrate. + +// Copyright (C) 2017-2021 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 futures::prelude::*; +use libp2p::core::transport::Transport; +use libp2p::Multiaddr; +use rand::Rng as _; +use std::{fmt, mem, pin::Pin, task::Context, task::Poll, time::Duration}; +use wasm_timer::Delay; + +pub(crate) type ConnectionNotifierSender = sp_utils::mpsc::TracingUnboundedSender<()>; + +/// Handler for a single telemetry node. +/// +/// This is a wrapper `Sink` around a network `Sink` with 3 particularities: +/// - It is infallible: if the connection stops, it will reconnect automatically when the server +/// becomes available again. +/// - It holds a list of "connection messages" which are sent automatically when the connection is +/// (re-)established. This is used for the "system.connected" message that needs to be send for +/// every substrate node that connects. +/// - It doesn't stay in pending while waiting for connection. Instead, it moves data into the +/// void if the connection could not be established. This is important for the `Dispatcher` +/// `Sink` which we don't want to block if one connection is broken. +#[derive(Debug)] +pub(crate) struct Node { + /// Address of the node. + addr: Multiaddr, + /// State of the connection. + socket: NodeSocket, + /// Transport used to establish new connections. + transport: TTrans, + /// Messages that are sent when the connection (re-)establishes. + pub(crate) connection_messages: Vec>, + /// Notifier for when the connection (re-)establishes. + pub(crate) telemetry_connection_notifier: Vec, +} + +enum NodeSocket { + /// We're connected to the node. This is the normal state. + Connected(NodeSocketConnected), + /// We are currently dialing the node. + Dialing(TTrans::Dial), + /// A new connection should be started as soon as possible. + ReconnectNow, + /// Waiting before attempting to dial again. + WaitingReconnect(Delay), + /// Temporary transition state. + Poisoned, +} + +impl NodeSocket { + fn wait_reconnect() -> NodeSocket { + let random_delay = rand::thread_rng().gen_range(5, 10); + let delay = Delay::new(Duration::from_secs(random_delay)); + NodeSocket::WaitingReconnect(delay) + } +} + +struct NodeSocketConnected { + /// Where to send data. + sink: TTrans::Output, + /// Queue of packets to send before accepting new packets. + buf: Vec>, +} + +impl Node { + /// Builds a new node handler. + pub(crate) fn new( + transport: TTrans, + addr: Multiaddr, + connection_messages: Vec>, + telemetry_connection_notifier: Vec, + ) -> Self { + Node { + addr, + socket: NodeSocket::ReconnectNow, + transport, + connection_messages, + telemetry_connection_notifier, + } + } +} + +impl Node +where + TTrans: Clone + Unpin, + TTrans::Dial: Unpin, + TTrans::Output: + Sink, Error = TSinkErr> + Stream, TSinkErr>> + Unpin, + TSinkErr: fmt::Debug, +{ + // NOTE: this code has been inspired from `Buffer` (`futures_util::sink::Buffer`). + // https://docs.rs/futures-util/0.3.8/src/futures_util/sink/buffer.rs.html#32 + fn try_send_connection_messages( + self: Pin<&mut Self>, + cx: &mut Context<'_>, + conn: &mut NodeSocketConnected, + ) -> Poll> { + while let Some(item) = conn.buf.pop() { + if let Err(e) = conn.sink.start_send_unpin(item) { + return Poll::Ready(Err(e)); + } + futures::ready!(conn.sink.poll_ready_unpin(cx))?; + } + Poll::Ready(Ok(())) + } +} + +pub(crate) enum Infallible {} + +impl Sink for Node +where + TTrans: Clone + Unpin, + TTrans::Dial: Unpin, + TTrans::Output: + Sink, Error = TSinkErr> + Stream, TSinkErr>> + Unpin, + TSinkErr: fmt::Debug, +{ + type Error = Infallible; + + fn poll_ready(mut self: Pin<&mut Self>, cx: &mut Context) -> Poll> { + let mut socket = mem::replace(&mut self.socket, NodeSocket::Poisoned); + self.socket = loop { + match socket { + NodeSocket::Connected(mut conn) => match conn.sink.poll_ready_unpin(cx) { + Poll::Ready(Ok(())) => { + match self.as_mut().try_send_connection_messages(cx, &mut conn) { + Poll::Ready(Err(err)) => { + log::warn!(target: "telemetry", "⚠️ Disconnected from {}: {:?}", self.addr, err); + socket = NodeSocket::wait_reconnect(); + } + Poll::Ready(Ok(())) => { + self.socket = NodeSocket::Connected(conn); + return Poll::Ready(Ok(())); + } + Poll::Pending => { + self.socket = NodeSocket::Connected(conn); + return Poll::Pending; + } + } + } + Poll::Ready(Err(err)) => { + log::warn!(target: "telemetry", "⚠️ Disconnected from {}: {:?}", self.addr, err); + socket = NodeSocket::wait_reconnect(); + } + Poll::Pending => { + self.socket = NodeSocket::Connected(conn); + return Poll::Pending; + } + }, + NodeSocket::Dialing(mut s) => match Future::poll(Pin::new(&mut s), cx) { + Poll::Ready(Ok(sink)) => { + log::debug!(target: "telemetry", "✅ Connected to {}", self.addr); + + for sender in self.telemetry_connection_notifier.iter_mut() { + let _ = sender.send(()); + } + + let buf = self + .connection_messages + .iter() + .map(|json| { + let mut json = json.clone(); + json.insert( + "ts".to_string(), + chrono::Local::now().to_rfc3339().into(), + ); + json + }) + .filter_map(|json| match serde_json::to_vec(&json) { + Ok(message) => Some(message), + Err(err) => { + log::error!( + target: "telemetry", + "An error occurred while generating new connection \ + messages: {}", + err, + ); + None + } + }) + .collect(); + + socket = NodeSocket::Connected(NodeSocketConnected { sink, buf }); + } + Poll::Pending => break NodeSocket::Dialing(s), + Poll::Ready(Err(err)) => { + log::warn!(target: "telemetry", "❌ Error while dialing {}: {:?}", self.addr, err); + socket = NodeSocket::wait_reconnect(); + } + }, + NodeSocket::ReconnectNow => match self.transport.clone().dial(self.addr.clone()) { + Ok(d) => { + log::debug!(target: "telemetry", "Started dialing {}", self.addr); + socket = NodeSocket::Dialing(d); + } + Err(err) => { + log::warn!(target: "telemetry", "❌ Error while dialing {}: {:?}", self.addr, err); + socket = NodeSocket::wait_reconnect(); + } + }, + NodeSocket::WaitingReconnect(mut s) => { + if let Poll::Ready(_) = Future::poll(Pin::new(&mut s), cx) { + socket = NodeSocket::ReconnectNow; + } else { + break NodeSocket::WaitingReconnect(s); + } + } + NodeSocket::Poisoned => { + log::error!(target: "telemetry", "‼️ Poisoned connection with {}", self.addr); + break NodeSocket::Poisoned; + } + } + }; + + // The Dispatcher blocks when the Node sinks blocks. This is why it is important that the + // Node sinks doesn't go into "Pending" state while waiting for reconnection but rather + // discard the excess of telemetry messages. + Poll::Ready(Ok(())) + } + + fn start_send(mut self: Pin<&mut Self>, item: String) -> Result<(), Self::Error> { + match &mut self.socket { + NodeSocket::Connected(conn) => { + let _ = conn.sink.start_send_unpin(item.into()).expect("boo"); + } + _socket => { + log::trace!( + target: "telemetry", + "Message has been discarded: {}", + item, + ); + } + } + Ok(()) + } + + fn poll_flush(mut self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll> { + match &mut self.socket { + NodeSocket::Connected(conn) => match conn.sink.poll_flush_unpin(cx) { + Poll::Ready(Err(_)) => { + self.socket = NodeSocket::wait_reconnect(); + Poll::Ready(Ok(())) + } + Poll::Ready(Ok(())) => Poll::Ready(Ok(())), + Poll::Pending => Poll::Pending, + }, + _ => Poll::Ready(Ok(())), + } + } + + fn poll_close(mut self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll> { + match &mut self.socket { + NodeSocket::Connected(conn) => conn.sink.poll_close_unpin(cx).map(|_| Ok(())), + _ => Poll::Ready(Ok(())), + } + } +} + +impl fmt::Debug for NodeSocket { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + use NodeSocket::*; + f.write_str(match self { + Connected(_) => "Connected", + Dialing(_) => "Dialing", + ReconnectNow => "ReconnectNow", + WaitingReconnect(_) => "WaitingReconnect", + Poisoned => "Poisoned", + }) + } +} diff --git a/client/telemetry/src/transport.rs b/client/telemetry/src/transport.rs new file mode 100644 index 0000000000000..e32a29d9a950d --- /dev/null +++ b/client/telemetry/src/transport.rs @@ -0,0 +1,163 @@ +// This file is part of Substrate. + +// Copyright (C) 2021 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 futures::{ + prelude::*, + ready, + task::{Context, Poll}, +}; +use libp2p::{ + core::transport::{timeout::TransportTimeout, OptionalTransport}, + wasm_ext, Transport, +}; +use std::io; +use std::pin::Pin; +use std::time::Duration; + +/// Timeout after which a connection attempt is considered failed. Includes the WebSocket HTTP +/// upgrading. +const CONNECT_TIMEOUT: Duration = Duration::from_secs(20); + +pub(crate) fn initialize_transport( + wasm_external_transport: Option, +) -> Result { + let transport = match wasm_external_transport.clone() { + Some(t) => OptionalTransport::some(t), + None => OptionalTransport::none(), + } + .map((|inner, _| StreamSink::from(inner)) as fn(_, _) -> _); + + // The main transport is the `wasm_external_transport`, but if we're on desktop we add + // support for TCP+WebSocket+DNS as a fallback. In practice, you're not expected to pass + // an external transport on desktop and the fallback is used all the time. + #[cfg(not(target_os = "unknown"))] + let transport = transport.or_transport({ + let inner = libp2p::dns::DnsConfig::new(libp2p::tcp::TcpConfig::new())?; + libp2p::websocket::framed::WsConfig::new(inner).and_then(|connec, _| { + let connec = connec + .with(|item| { + let item = libp2p::websocket::framed::OutgoingData::Binary(item); + future::ready(Ok::<_, io::Error>(item)) + }) + .try_filter(|item| future::ready(item.is_data())) + .map_ok(|data| data.into_bytes()); + future::ready(Ok::<_, io::Error>(connec)) + }) + }); + + Ok(TransportTimeout::new( + transport.map(|out, _| { + let out = out + .map_err(|err| io::Error::new(io::ErrorKind::Other, err)) + .sink_map_err(|err| io::Error::new(io::ErrorKind::Other, err)); + Box::pin(out) as Pin> + }), + CONNECT_TIMEOUT, + ) + .boxed()) +} + +/// A trait that implements `Stream` and `Sink`. +pub(crate) trait StreamAndSink: Stream + Sink {} +impl, I> StreamAndSink for T {} + +/// A type alias for the WebSocket transport. +pub(crate) type WsTrans = libp2p::core::transport::Boxed< + Pin< + Box< + dyn StreamAndSink, Item = Result, io::Error>, Error = io::Error> + Send, + >, + >, +>; + +/// Wraps around an `AsyncWrite` and implements `Sink`. Guarantees that each item being sent maps +/// to one call of `write`. +/// +/// For some context, we put this object around the `wasm_ext::ExtTransport` in order to make sure +/// that each telemetry message maps to one single call to `write` in the WASM FFI. +#[pin_project::pin_project] +pub(crate) struct StreamSink(#[pin] T, Option>); + +impl From for StreamSink { + fn from(inner: T) -> StreamSink { + StreamSink(inner, None) + } +} + +impl Stream for StreamSink { + type Item = Result, io::Error>; + + fn poll_next(self: Pin<&mut Self>, cx: &mut Context) -> Poll> { + let this = self.project(); + let mut buf = vec![0; 128]; + match ready!(AsyncRead::poll_read(this.0, cx, &mut buf)) { + Ok(0) => Poll::Ready(None), + Ok(n) => { + buf.truncate(n); + Poll::Ready(Some(Ok(buf))) + } + Err(err) => Poll::Ready(Some(Err(err))), + } + } +} + +impl StreamSink { + fn poll_flush_buffer(self: Pin<&mut Self>, cx: &mut Context) -> Poll> { + let this = self.project(); + + if let Some(buffer) = this.1 { + if ready!(this.0.poll_write(cx, &buffer[..]))? != buffer.len() { + log::error!(target: "telemetry", + "Detected some internal buffering happening in the telemetry"); + let err = io::Error::new(io::ErrorKind::Other, "Internal buffering detected"); + return Poll::Ready(Err(err)); + } + } + + *this.1 = None; + Poll::Ready(Ok(())) + } +} + +impl Sink> for StreamSink { + type Error = io::Error; + + fn poll_ready(self: Pin<&mut Self>, cx: &mut Context) -> Poll> { + ready!(StreamSink::poll_flush_buffer(self, cx))?; + Poll::Ready(Ok(())) + } + + fn start_send(self: Pin<&mut Self>, item: Vec) -> Result<(), Self::Error> { + let this = self.project(); + debug_assert!(this.1.is_none()); + *this.1 = Some(item); + Ok(()) + } + + fn poll_flush(mut self: Pin<&mut Self>, cx: &mut Context) -> Poll> { + ready!(self.as_mut().poll_flush_buffer(cx))?; + let this = self.project(); + AsyncWrite::poll_flush(this.0, cx) + } + + fn poll_close(mut self: Pin<&mut Self>, cx: &mut Context) -> Poll> { + ready!(self.as_mut().poll_flush_buffer(cx))?; + let this = self.project(); + AsyncWrite::poll_close(this.0, cx) + } +} diff --git a/client/telemetry/src/worker.rs b/client/telemetry/src/worker.rs deleted file mode 100644 index 158781f043358..0000000000000 --- a/client/telemetry/src/worker.rs +++ /dev/null @@ -1,263 +0,0 @@ -// This file is part of Substrate. - -// Copyright (C) 2017-2021 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 . - -//! Contains the object that makes the telemetry work. -//! -//! # Usage -//! -//! - Create a `TelemetryWorker` with `TelemetryWorker::new`. -//! - Send messages to the telemetry with `TelemetryWorker::send_message`. Messages will only be -//! sent to the appropriate targets. Messages may be ignored if the target happens to be -//! temporarily unreachable. -//! - You must appropriately poll the worker with `TelemetryWorker::poll`. Polling will/may produce -//! events indicating what happened since the latest polling. -//! - -use futures::{prelude::*, ready}; -use libp2p::{ - core::transport::{OptionalTransport, timeout::TransportTimeout}, - Multiaddr, - Transport, - wasm_ext -}; -use log::{trace, warn, error}; -use slog::Drain; -use std::{io, pin::Pin, task::Context, task::Poll, time}; - -mod node; - -/// Timeout after which a connection attempt is considered failed. Includes the WebSocket HTTP -/// upgrading. -const CONNECT_TIMEOUT: time::Duration = time::Duration::from_secs(20); - -/// Event generated when polling the worker. -#[derive(Debug)] -pub enum TelemetryWorkerEvent { - /// We have established a connection to one of the telemetry endpoint, either for the first - /// time or after having been disconnected earlier. - Connected, -} - -/// Telemetry processing machine. -#[derive(Debug)] -pub struct TelemetryWorker { - /// List of nodes with their maximum verbosity level. - nodes: Vec<(node::Node, u8)>, -} - -trait StreamAndSink: Stream + Sink {} -impl, I> StreamAndSink for T {} - -type WsTrans = libp2p::core::transport::Boxed< - Pin, - Item = Result, io::Error>, - Error = io::Error - > + Send>> ->; - -impl TelemetryWorker { - /// Builds a new `TelemetryWorker`. - /// - /// The endpoints must be a list of targets, plus a verbosity level. When you send a message - /// to the telemetry, only the targets whose verbosity is higher than the verbosity of the - /// message will receive it. - pub fn new( - endpoints: impl IntoIterator, - wasm_external_transport: impl Into> - ) -> Result { - let transport = match wasm_external_transport.into() { - Some(t) => OptionalTransport::some(t), - None => OptionalTransport::none() - }.map((|inner, _| StreamSink::from(inner)) as fn(_, _) -> _); - - // The main transport is the `wasm_external_transport`, but if we're on desktop we add - // support for TCP+WebSocket+DNS as a fallback. In practice, you're not expected to pass - // an external transport on desktop and the fallback is used all the time. - #[cfg(not(target_os = "unknown"))] - let transport = transport.or_transport({ - let inner = libp2p::dns::DnsConfig::new(libp2p::tcp::TcpConfig::new())?; - libp2p::websocket::framed::WsConfig::new(inner) - .and_then(|connec, _| { - let connec = connec - .with(|item| { - let item = libp2p::websocket::framed::OutgoingData::Binary(item); - future::ready(Ok::<_, io::Error>(item)) - }) - .try_filter(|item| future::ready(item.is_data())) - .map_ok(|data| data.into_bytes()); - future::ready(Ok::<_, io::Error>(connec)) - }) - }); - - let transport = TransportTimeout::new( - transport.map(|out, _| { - let out = out - .map_err(|err| io::Error::new(io::ErrorKind::Other, err)) - .sink_map_err(|err| io::Error::new(io::ErrorKind::Other, err)); - Box::pin(out) as Pin> - }), - CONNECT_TIMEOUT - ).boxed(); - - Ok(TelemetryWorker { - nodes: endpoints.into_iter().map(|(addr, verbosity)| { - let node = node::Node::new(transport.clone(), addr); - (node, verbosity) - }).collect() - }) - } - - /// Polls the worker for events that happened. - pub fn poll(&mut self, cx: &mut Context) -> Poll { - for (node, _) in &mut self.nodes { - loop { - match node::Node::poll(Pin::new(node), cx) { - Poll::Ready(node::NodeEvent::Connected) => - return Poll::Ready(TelemetryWorkerEvent::Connected), - Poll::Ready(node::NodeEvent::Disconnected(_)) => continue, - Poll::Pending => break, - } - } - } - - Poll::Pending - } - - /// Equivalent to `slog::Drain::log`, but takes `self` by `&mut` instead, which is more convenient. - /// - /// Keep in mind that you should call `TelemetryWorker::poll` in order to process the messages. - /// You should call this function right after calling `slog::Drain::log`. - pub fn log(&mut self, record: &slog::Record, values: &slog::OwnedKVList) -> Result<(), ()> { - let msg_verbosity = match record.tag().parse::() { - Ok(v) => v, - Err(err) => { - warn!(target: "telemetry", "Failed to parse telemetry tag {:?}: {:?}", - record.tag(), err); - return Err(()) - } - }; - - // 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 - ); - return Ok(()) - } - - // Turn the message into JSON. - let serialized = { - let mut out = Vec::new(); - slog_json::Json::default(&mut out).log(record, values).map_err(|_| ())?; - out - }; - - for (node, node_max_verbosity) in &mut self.nodes { - if msg_verbosity > *node_max_verbosity { - trace!(target: "telemetry", "Skipping {:?} for log entry with verbosity {:?}", - node.addr(), msg_verbosity); - continue; - } - - // `send_message` returns an error if we're not connected, which we silently ignore. - let _ = node.send_message(&serialized.clone()[..]); - } - - Ok(()) - } -} - -/// Wraps around an `AsyncWrite` and implements `Sink`. Guarantees that each item being sent maps -/// to one call of `write`. -/// -/// For some context, we put this object around the `wasm_ext::ExtTransport` in order to make sure -/// that each telemetry message maps to one single call to `write` in the WASM FFI. -#[pin_project::pin_project] -struct StreamSink(#[pin] T, Option>); - -impl From for StreamSink { - fn from(inner: T) -> StreamSink { - StreamSink(inner, None) - } -} - -impl Stream for StreamSink { - type Item = Result, io::Error>; - - fn poll_next(self: Pin<&mut Self>, cx: &mut Context) -> Poll> { - let this = self.project(); - let mut buf = vec![0; 128]; - match ready!(AsyncRead::poll_read(this.0, cx, &mut buf)) { - Ok(0) => Poll::Ready(None), - Ok(n) => { - buf.truncate(n); - Poll::Ready(Some(Ok(buf))) - }, - Err(err) => Poll::Ready(Some(Err(err))), - } - } -} - -impl StreamSink { - fn poll_flush_buffer(self: Pin<&mut Self>, cx: &mut Context) -> Poll> { - let this = self.project(); - - if let Some(buffer) = this.1 { - if ready!(this.0.poll_write(cx, &buffer[..]))? != buffer.len() { - error!(target: "telemetry", - "Detected some internal buffering happening in the telemetry"); - let err = io::Error::new(io::ErrorKind::Other, "Internal buffering detected"); - return Poll::Ready(Err(err)); - } - } - - *this.1 = None; - Poll::Ready(Ok(())) - } -} - -impl Sink> for StreamSink { - type Error = io::Error; - - fn poll_ready(self: Pin<&mut Self>, cx: &mut Context) -> Poll> { - ready!(StreamSink::poll_flush_buffer(self, cx))?; - Poll::Ready(Ok(())) - } - - fn start_send(self: Pin<&mut Self>, item: Vec) -> Result<(), Self::Error> { - let this = self.project(); - debug_assert!(this.1.is_none()); - *this.1 = Some(item); - Ok(()) - } - - fn poll_flush(mut self: Pin<&mut Self>, cx: &mut Context) -> Poll> { - ready!(self.as_mut().poll_flush_buffer(cx))?; - let this = self.project(); - AsyncWrite::poll_flush(this.0, cx) - } - - fn poll_close(mut self: Pin<&mut Self>, cx: &mut Context) -> Poll> { - ready!(self.as_mut().poll_flush_buffer(cx))?; - let this = self.project(); - AsyncWrite::poll_close(this.0, cx) - } -} diff --git a/client/telemetry/src/worker/node.rs b/client/telemetry/src/worker/node.rs deleted file mode 100644 index 5fbafde8c941b..0000000000000 --- a/client/telemetry/src/worker/node.rs +++ /dev/null @@ -1,305 +0,0 @@ -// This file is part of Substrate. - -// Copyright (C) 2017-2021 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 . - -//! Contains the `Node` struct, which handles communications with a single telemetry endpoint. - -use futures::prelude::*; -use futures_timer::Delay; -use libp2p::Multiaddr; -use libp2p::core::transport::Transport; -use log::{trace, debug, warn, error}; -use rand::Rng as _; -use std::{collections::VecDeque, fmt, mem, pin::Pin, task::Context, task::Poll, time::Duration}; - -/// Maximum number of pending telemetry messages. -const MAX_PENDING: usize = 10; - -/// Handler for a single telemetry node. -pub struct Node { - /// Address of the node. - addr: Multiaddr, - /// State of the connection. - socket: NodeSocket, - /// Transport used to establish new connections. - transport: TTrans, -} - -enum NodeSocket { - /// We're connected to the node. This is the normal state. - Connected(NodeSocketConnected), - /// We are currently dialing the node. - Dialing(TTrans::Dial), - /// A new connection should be started as soon as possible. - ReconnectNow, - /// Waiting before attempting to dial again. - WaitingReconnect(Delay), - /// Temporary transition state. - Poisoned, -} - -struct NodeSocketConnected { - /// Where to send data. - sink: TTrans::Output, - /// Queue of packets to send. - pending: VecDeque>, - /// If true, we need to flush the sink. - need_flush: bool, - /// A timeout for the socket to write data. - timeout: Option, -} - -/// Event that can happen with this node. -#[derive(Debug)] -pub enum NodeEvent { - /// We are now connected to this node. - Connected, - /// We are now disconnected from this node. - Disconnected(ConnectionError), -} - -/// Reason for disconnecting from a node. -#[derive(Debug)] -pub enum ConnectionError { - /// The connection timed-out. - Timeout, - /// Reading from the socket returned and end-of-file, indicating that the socket has been - /// closed. - Closed, - /// The sink errored. - Sink(TSinkErr), -} - -impl Node { - /// Builds a new node handler. - pub fn new(transport: TTrans, addr: Multiaddr) -> Self { - Node { - addr, - socket: NodeSocket::ReconnectNow, - transport, - } - } - - /// Returns the address that was passed to `new`. - pub fn addr(&self) -> &Multiaddr { - &self.addr - } -} - -impl Node -where TTrans: Clone + Unpin, TTrans::Dial: Unpin, - TTrans::Output: Sink, Error = TSinkErr> - + Stream, TSinkErr>> - + Unpin, - TSinkErr: fmt::Debug -{ - /// Sends a WebSocket frame to the node. Returns an error if we are not connected to the node. - /// - /// After calling this method, you should call `poll` in order for it to be properly processed. - pub fn send_message(&mut self, payload: impl Into>) -> Result<(), ()> { - if let NodeSocket::Connected(NodeSocketConnected { pending, .. }) = &mut self.socket { - if pending.len() <= MAX_PENDING { - trace!(target: "telemetry", "Adding log entry to queue for {:?}", self.addr); - pending.push_back(payload.into()); - Ok(()) - } else { - warn!(target: "telemetry", "⚠️ Rejected log entry because queue is full for {:?}", - self.addr); - Err(()) - } - } else { - Err(()) - } - } - - /// Polls the node for updates. Must be performed regularly. - pub fn poll(mut self: Pin<&mut Self>, cx: &mut Context) -> Poll> { - let mut socket = mem::replace(&mut self.socket, NodeSocket::Poisoned); - self.socket = loop { - match socket { - NodeSocket::Connected(mut conn) => { - match NodeSocketConnected::poll(Pin::new(&mut conn), cx, &self.addr) { - Poll::Ready(Ok(v)) => match v {}, - Poll::Pending => { - break NodeSocket::Connected(conn) - }, - Poll::Ready(Err(err)) => { - warn!(target: "telemetry", "⚠️ Disconnected from {}: {:?}", self.addr, err); - let timeout = gen_rand_reconnect_delay(); - self.socket = NodeSocket::WaitingReconnect(timeout); - return Poll::Ready(NodeEvent::Disconnected(err)) - } - } - } - NodeSocket::Dialing(mut s) => match Future::poll(Pin::new(&mut s), cx) { - Poll::Ready(Ok(sink)) => { - debug!(target: "telemetry", "✅ Connected to {}", self.addr); - let conn = NodeSocketConnected { - sink, - pending: VecDeque::new(), - need_flush: false, - timeout: None, - }; - self.socket = NodeSocket::Connected(conn); - return Poll::Ready(NodeEvent::Connected) - }, - Poll::Pending => break NodeSocket::Dialing(s), - Poll::Ready(Err(err)) => { - warn!(target: "telemetry", "❌ Error while dialing {}: {:?}", self.addr, err); - let timeout = gen_rand_reconnect_delay(); - socket = NodeSocket::WaitingReconnect(timeout); - } - } - NodeSocket::ReconnectNow => match self.transport.clone().dial(self.addr.clone()) { - Ok(d) => { - debug!(target: "telemetry", "Started dialing {}", self.addr); - socket = NodeSocket::Dialing(d); - } - Err(err) => { - warn!(target: "telemetry", "❌ Error while dialing {}: {:?}", self.addr, err); - let timeout = gen_rand_reconnect_delay(); - socket = NodeSocket::WaitingReconnect(timeout); - } - } - NodeSocket::WaitingReconnect(mut s) => - if let Poll::Ready(_) = Future::poll(Pin::new(&mut s), cx) { - socket = NodeSocket::ReconnectNow; - } else { - break NodeSocket::WaitingReconnect(s) - } - NodeSocket::Poisoned => { - error!(target: "telemetry", "‼️ Poisoned connection with {}", self.addr); - break NodeSocket::Poisoned - } - } - }; - - Poll::Pending - } -} - -/// Generates a `Delay` object with a random timeout. -/// -/// If there are general connection issues, not all endpoints should be synchronized in their -/// re-connection time. -fn gen_rand_reconnect_delay() -> Delay { - let random_delay = rand::thread_rng().gen_range(5, 10); - Delay::new(Duration::from_secs(random_delay)) -} - -impl NodeSocketConnected -where TTrans::Output: Sink, Error = TSinkErr> - + Stream, TSinkErr>> - + Unpin -{ - /// Processes the queue of messages for the connected socket. - /// - /// The address is passed for logging purposes only. - fn poll( - mut self: Pin<&mut Self>, - cx: &mut Context, - my_addr: &Multiaddr, - ) -> Poll>> { - - while let Some(item) = self.pending.pop_front() { - if let Poll::Ready(result) = Sink::poll_ready(Pin::new(&mut self.sink), cx) { - if let Err(err) = result { - return Poll::Ready(Err(ConnectionError::Sink(err))) - } - - let item_len = item.len(); - if let Err(err) = Sink::start_send(Pin::new(&mut self.sink), item) { - return Poll::Ready(Err(ConnectionError::Sink(err))) - } - trace!( - target: "telemetry", "Successfully sent {:?} bytes message to {}", - item_len, my_addr - ); - self.need_flush = true; - - } else { - self.pending.push_front(item); - if self.timeout.is_none() { - self.timeout = Some(Delay::new(Duration::from_secs(10))); - } - break; - } - } - - if self.need_flush { - match Sink::poll_flush(Pin::new(&mut self.sink), cx) { - Poll::Pending => { - if self.timeout.is_none() { - self.timeout = Some(Delay::new(Duration::from_secs(10))); - } - }, - Poll::Ready(Err(err)) => { - self.timeout = None; - return Poll::Ready(Err(ConnectionError::Sink(err))) - }, - Poll::Ready(Ok(())) => { - self.timeout = None; - self.need_flush = false; - }, - } - } - - if let Some(timeout) = self.timeout.as_mut() { - match Future::poll(Pin::new(timeout), cx) { - Poll::Pending => {}, - Poll::Ready(()) => { - self.timeout = None; - return Poll::Ready(Err(ConnectionError::Timeout)) - } - } - } - - match Stream::poll_next(Pin::new(&mut self.sink), cx) { - Poll::Ready(Some(Ok(_))) => { - // We poll the telemetry `Stream` because the underlying implementation relies on - // this in order to answer PINGs. - // We don't do anything with incoming messages, however. - }, - Poll::Ready(Some(Err(err))) => { - return Poll::Ready(Err(ConnectionError::Sink(err))) - }, - Poll::Ready(None) => { - return Poll::Ready(Err(ConnectionError::Closed)) - }, - Poll::Pending => {}, - } - - Poll::Pending - } -} - -impl fmt::Debug for Node { - fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { - let state = match self.socket { - NodeSocket::Connected(_) => "Connected", - NodeSocket::Dialing(_) => "Dialing", - NodeSocket::ReconnectNow => "Pending reconnect", - NodeSocket::WaitingReconnect(_) => "Pending reconnect", - NodeSocket::Poisoned => "Poisoned", - }; - - f.debug_struct("Node") - .field("addr", &self.addr) - .field("state", &state) - .finish() - } -} diff --git a/client/tracing/Cargo.toml b/client/tracing/Cargo.toml index f5cb577a193b4..6a49c92b0f873 100644 --- a/client/tracing/Cargo.toml +++ b/client/tracing/Cargo.toml @@ -14,7 +14,7 @@ targets = ["x86_64-unknown-linux-gnu"] [dependencies] ansi_term = "0.12.1" -tracing-log = "0.1.1" +atty = "0.2.13" erased-serde = "0.3.9" lazy_static = "1.4.0" log = { version = "0.4.8" } @@ -24,9 +24,15 @@ regex = "1.4.2" rustc-hash = "1.1.0" serde = "1.0.101" serde_json = "1.0.41" -slog = { version = "2.5.2", features = ["nested-values"] } +thiserror = "1.0.21" tracing = "0.1.22" tracing-core = "0.1.17" +tracing-log = "0.1.1" tracing-subscriber = "0.2.15" sp-tracing = { version = "2.0.0", path = "../../primitives/tracing" } sc-telemetry = { version = "2.0.0", path = "../telemetry" } +sc-tracing-proc-macro = { version = "2.0.0", path = "./proc-macro" } + +[target.'cfg(target_os = "unknown")'.dependencies] +wasm-bindgen = "0.2.67" +web-sys = { version = "0.3.44", features = ["console"] } diff --git a/client/cli/proc-macro/Cargo.toml b/client/tracing/proc-macro/Cargo.toml similarity index 94% rename from client/cli/proc-macro/Cargo.toml rename to client/tracing/proc-macro/Cargo.toml index 9805d87cb30e3..e2f4cf14435ba 100644 --- a/client/cli/proc-macro/Cargo.toml +++ b/client/tracing/proc-macro/Cargo.toml @@ -1,5 +1,5 @@ [package] -name = "sc-cli-proc-macro" +name = "sc-tracing-proc-macro" version = "2.0.0" authors = ["Parity Technologies "] edition = "2018" diff --git a/client/cli/proc-macro/src/lib.rs b/client/tracing/proc-macro/src/lib.rs similarity index 96% rename from client/cli/proc-macro/src/lib.rs rename to client/tracing/proc-macro/src/lib.rs index 0e2466ec3ae77..6164977f07c1e 100644 --- a/client/cli/proc-macro/src/lib.rs +++ b/client/tracing/proc-macro/src/lib.rs @@ -120,16 +120,16 @@ pub fn prefix_logs_with(arg: TokenStream, item: TokenStream) -> TokenStream { let crate_name = if std::env::var("CARGO_PKG_NAME") .expect("cargo env var always there when compiling; qed") - == "sc-cli" + == "sc-tracing" { - Ident::new("sc_cli", Span::call_site().into()) + Ident::from(Ident::new("sc_tracing", Span::call_site())) } else { - let crate_name = match crate_name("sc-cli") { + let crate_name = match crate_name("sc-tracing") { Ok(x) => x, Err(err) => return Error::new(Span::call_site(), err).to_compile_error().into(), }; - Ident::new(&crate_name, Span::call_site().into()) + Ident::new(&crate_name, Span::call_site()) }; let ItemFn { @@ -143,7 +143,7 @@ pub fn prefix_logs_with(arg: TokenStream, item: TokenStream) -> TokenStream { #(#attrs)* #vis #sig { let span = #crate_name::tracing::info_span!( - #crate_name::PREFIX_LOG_SPAN, + #crate_name::logging::PREFIX_LOG_SPAN, name = #name, ); let _enter = span.enter(); diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 639ba56b12e5f..ebec8f2a8716a 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -26,12 +26,13 @@ //! //! Currently we provide `Log` (default), `Telemetry` variants for `Receiver` +#![warn(missing_docs)] + pub mod logging; use rustc_hash::FxHashMap; use std::fmt; use std::time::{Duration, Instant}; - use parking_lot::Mutex; use serde::ser::{Serialize, Serializer, SerializeMap}; use tracing::{ @@ -42,107 +43,16 @@ use tracing::{ subscriber::Subscriber, }; use tracing_subscriber::{ - fmt::time::ChronoLocal, CurrentSpan, - EnvFilter, - layer::{self, Layer, Context}, - fmt as tracing_fmt, - Registry, + layer::{Layer, Context}, }; - use sc_telemetry::{telemetry, SUBSTRATE_INFO}; use sp_tracing::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER}; -use tracing_subscriber::reload::Handle; -use once_cell::sync::OnceCell; -use tracing_subscriber::filter::Directive; - -const ZERO_DURATION: Duration = Duration::from_nanos(0); - -// The layered Subscriber as built up in `init_logger()`. -// Used in the reload `Handle`. -type SCSubscriber< - N = tracing_fmt::format::DefaultFields, - E = logging::EventFormat, - W = fn() -> std::io::Stderr -> = layer::Layered, Registry>; - -// Handle to reload the tracing log filter -static FILTER_RELOAD_HANDLE: OnceCell> = OnceCell::new(); -// Directives that are defaulted to when resetting the log filter -static DEFAULT_DIRECTIVES: OnceCell>> = OnceCell::new(); -// Current state of log filter -static CURRENT_DIRECTIVES: OnceCell>> = OnceCell::new(); - -/// Initialize FILTER_RELOAD_HANDLE, only possible once -pub fn set_reload_handle(handle: Handle) { - let _ = FILTER_RELOAD_HANDLE.set(handle); -} - -/// Add log filter directive(s) to the defaults -/// -/// The syntax is identical to the CLI `=`: -/// -/// `sync=debug,state=trace` -pub fn add_default_directives(directives: &str) { - DEFAULT_DIRECTIVES.get_or_init(|| Mutex::new(Vec::new())).lock().push(directives.to_owned()); - add_directives(directives); -} - -/// Add directives to current directives -pub fn add_directives(directives: &str) { - CURRENT_DIRECTIVES.get_or_init(|| Mutex::new(Vec::new())).lock().push(directives.to_owned()); -} - -/// Reload the logging filter with the supplied directives added to the existing directives -pub fn reload_filter() -> Result<(), String> { - let mut env_filter = EnvFilter::default(); - if let Some(current_directives) = CURRENT_DIRECTIVES.get() { - // Use join and then split in case any directives added together - for directive in current_directives.lock().join(",").split(',').map(|d| d.parse()) { - match directive { - Ok(dir) => env_filter = env_filter.add_directive(dir), - Err(invalid_directive) => { - log::warn!( - target: "tracing", - "Unable to parse directive while setting log filter: {:?}", - invalid_directive, - ); - } - } - } - } - env_filter = env_filter.add_directive( - "sc_tracing=trace" - .parse() - .expect("provided directive is valid"), - ); - log::debug!(target: "tracing", "Reloading log filter with: {}", env_filter); - FILTER_RELOAD_HANDLE.get() - .ok_or("No reload handle present".to_string())? - .reload(env_filter) - .map_err(|e| format!("{}", e)) -} -/// Resets the log filter back to the original state when the node was started. -/// -/// Includes substrate defaults and CLI supplied directives. -pub fn reset_log_filter() -> Result<(), String> { - *CURRENT_DIRECTIVES - .get_or_init(|| Mutex::new(Vec::new())).lock() = - DEFAULT_DIRECTIVES.get_or_init(|| Mutex::new(Vec::new())).lock().clone(); - reload_filter() -} +#[doc(hidden)] +pub use tracing; -/// Parse `Directive` and add to default directives if successful. -/// -/// Ensures the supplied directive will be restored when resetting the log filter. -pub fn parse_default_directive(directive: &str) -> Result { - let dir = directive - .parse() - .map_err(|_| format!("Unable to parse directive: {}", directive))?; - add_default_directives(directive); - Ok(dir) -} +const ZERO_DURATION: Duration = Duration::from_nanos(0); /// Responsible for assigning ids to new spans, which are not re-used. pub struct ProfilingLayer { @@ -178,10 +88,15 @@ pub trait TraceHandler: Send + Sync { /// Represents a tracing event, complete with values #[derive(Debug)] pub struct TraceEvent { + /// Name of the event. pub name: &'static str, + /// Target of the event. pub target: String, + /// Level of the event. pub level: Level, + /// Values for this event. pub values: Values, + /// Id of the parent tracing event, if any. pub parent_id: Option, } @@ -291,27 +206,6 @@ impl fmt::Display for Values { } } -impl slog::SerdeValue for Values { - fn as_serde(&self) -> &dyn erased_serde::Serialize { - self - } - - fn to_sendable(&self) -> Box { - Box::new(self.clone()) - } -} - -impl slog::Value for Values { - fn serialize( - &self, - _record: &slog::Record, - key: slog::Key, - ser: &mut dyn slog::Serializer, - ) -> slog::Result { - ser.emit_serde(key, self) - } -} - impl ProfilingLayer { /// Takes a `TracingReceiver` and a comma separated list of targets, /// either with a level: "pallet=trace,frame=debug" @@ -510,7 +404,7 @@ impl TraceHandler for TelemetryTraceHandler { "target" => span_datum.target, "time" => span_datum.overall_time.as_nanos(), "id" => span_datum.id.into_u64(), - "parent_id" => span_datum.parent_id.map(|i| i.into_u64()), + "parent_id" => span_datum.parent_id.as_ref().map(|i| i.into_u64()), "values" => span_datum.values ); } @@ -519,7 +413,7 @@ impl TraceHandler for TelemetryTraceHandler { telemetry!(SUBSTRATE_INFO; "tracing.event"; "name" => event.name, "target" => event.target, - "parent_id" => event.parent_id.map(|i| i.into_u64()), + "parent_id" => event.parent_id.as_ref().map(|i| i.into_u64()), "values" => event.values ); } diff --git a/client/tracing/src/logging/directives.rs b/client/tracing/src/logging/directives.rs new file mode 100644 index 0000000000000..b108566bf2bce --- /dev/null +++ b/client/tracing/src/logging/directives.rs @@ -0,0 +1,123 @@ +// Copyright 2021 Parity Technologies (UK) Ltd. +// This file is part of Substrate. + +// Substrate 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. + +// Substrate 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 Substrate. If not, see . + +use once_cell::sync::OnceCell; +use parking_lot::Mutex; +use tracing_subscriber::{ + filter::Directive, fmt as tracing_fmt, fmt::time::ChronoLocal, layer, reload::Handle, + EnvFilter, Registry, +}; + +// Handle to reload the tracing log filter +static FILTER_RELOAD_HANDLE: OnceCell> = OnceCell::new(); +// Directives that are defaulted to when resetting the log filter +static DEFAULT_DIRECTIVES: OnceCell>> = OnceCell::new(); +// Current state of log filter +static CURRENT_DIRECTIVES: OnceCell>> = OnceCell::new(); + +/// Add log filter directive(s) to the defaults +/// +/// The syntax is identical to the CLI `=`: +/// +/// `sync=debug,state=trace` +pub(crate) fn add_default_directives(directives: &str) { + DEFAULT_DIRECTIVES + .get_or_init(|| Mutex::new(Vec::new())) + .lock() + .push(directives.to_owned()); + add_directives(directives); +} + +/// Add directives to current directives +pub fn add_directives(directives: &str) { + CURRENT_DIRECTIVES + .get_or_init(|| Mutex::new(Vec::new())) + .lock() + .push(directives.to_owned()); +} + +/// Parse `Directive` and add to default directives if successful. +/// +/// Ensures the supplied directive will be restored when resetting the log filter. +pub(crate) fn parse_default_directive(directive: &str) -> super::Result { + let dir = directive.parse()?; + add_default_directives(directive); + Ok(dir) +} + +/// Reload the logging filter with the supplied directives added to the existing directives +pub fn reload_filter() -> Result<(), String> { + let mut env_filter = EnvFilter::default(); + if let Some(current_directives) = CURRENT_DIRECTIVES.get() { + // Use join and then split in case any directives added together + for directive in current_directives + .lock() + .join(",") + .split(',') + .map(|d| d.parse()) + { + match directive { + Ok(dir) => env_filter = env_filter.add_directive(dir), + Err(invalid_directive) => { + log::warn!( + target: "tracing", + "Unable to parse directive while setting log filter: {:?}", + invalid_directive, + ); + } + } + } + } + env_filter = env_filter.add_directive( + "sc_tracing=trace" + .parse() + .expect("provided directive is valid"), + ); + log::debug!(target: "tracing", "Reloading log filter with: {}", env_filter); + FILTER_RELOAD_HANDLE + .get() + .ok_or("No reload handle present".to_string())? + .reload(env_filter) + .map_err(|e| format!("{}", e)) +} + +/// Resets the log filter back to the original state when the node was started. +/// +/// Includes substrate defaults and CLI supplied directives. +pub fn reset_log_filter() -> Result<(), String> { + let directive = DEFAULT_DIRECTIVES + .get_or_init(|| Mutex::new(Vec::new())) + .lock() + .clone(); + + *CURRENT_DIRECTIVES + .get_or_init(|| Mutex::new(Vec::new())) + .lock() = directive; + reload_filter() +} + +/// Initialize FILTER_RELOAD_HANDLE, only possible once +pub(crate) fn set_reload_handle(handle: Handle) { + let _ = FILTER_RELOAD_HANDLE.set(handle); +} + +// The layered Subscriber as built up in `init_logger()`. +// Used in the reload `Handle`. +type SCSubscriber< + N = tracing_fmt::format::DefaultFields, + E = crate::logging::EventFormat, + W = fn() -> std::io::Stderr, +> = layer::Layered, Registry>; diff --git a/client/tracing/src/logging.rs b/client/tracing/src/logging/event_format.rs similarity index 73% rename from client/tracing/src/logging.rs rename to client/tracing/src/logging/event_format.rs index c552d64bc7fbd..37f9ed16ead7d 100644 --- a/client/tracing/src/logging.rs +++ b/client/tracing/src/logging/event_format.rs @@ -16,92 +16,56 @@ // You should have received a copy of the GNU General Public License // along with this program. If not, see . -use std::fmt::{self, Write}; use ansi_term::Colour; -use tracing::{span::Attributes, Event, Id, Level, Subscriber}; +use regex::Regex; +use std::fmt::{self, Write}; +use tracing::{Event, Level, Subscriber}; use tracing_log::NormalizeEvent; use tracing_subscriber::{ + field::RecordFields, fmt::{ time::{FormatTime, SystemTime}, FmtContext, FormatEvent, FormatFields, }, layer::Context, - registry::LookupSpan, - Layer, + registry::{LookupSpan, SpanRef}, }; -use regex::Regex; - -/// Span name used for the logging prefix. See macro `sc_cli::prefix_logs_with!` -pub const PREFIX_LOG_SPAN: &str = "substrate-log-prefix"; - -/// A writer that may write to `inner_writer` with colors. -/// -/// This is used by [`EventFormat`] to kill colors when `enable_color` is `false`. -/// -/// It is required to call [`MaybeColorWriter::write`] after all writes are done, -/// because the content of these writes is buffered and will only be written to the -/// `inner_writer` at that point. -struct MaybeColorWriter<'a> { - enable_color: bool, - buffer: String, - inner_writer: &'a mut dyn fmt::Write, -} - -impl<'a> fmt::Write for MaybeColorWriter<'a> { - fn write_str(&mut self, buf: &str) -> fmt::Result { - self.buffer.push_str(buf); - Ok(()) - } -} - -impl<'a> MaybeColorWriter<'a> { - /// Creates a new instance. - fn new(enable_color: bool, inner_writer: &'a mut dyn fmt::Write) -> Self { - Self { - enable_color, - inner_writer, - buffer: String::new(), - } - } - - /// Write the buffered content to the `inner_writer`. - fn write(&mut self) -> fmt::Result { - lazy_static::lazy_static! { - static ref RE: Regex = Regex::new("\x1b\\[[^m]+m").expect("Error initializing color regex"); - } - - if !self.enable_color { - let replaced = RE.replace_all(&self.buffer, ""); - self.inner_writer.write_str(&replaced) - } else { - self.inner_writer.write_str(&self.buffer) - } - } -} +/// A pre-configured event formatter. pub struct EventFormat { + /// Use the given timer for log message timestamps. pub timer: T, + /// Sets whether or not an event's target is displayed. pub display_target: bool, + /// Sets whether or not an event's level is displayed. pub display_level: bool, + /// Sets whether or not the name of the current thread is displayed when formatting events. pub display_thread_name: bool, + /// Enable ANSI terminal colors for formatted output. pub enable_color: 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 +impl EventFormat where - S: Subscriber + for<'a> LookupSpan<'a>, - N: for<'a> FormatFields<'a> + 'static, T: FormatTime, { - fn format_event( + // 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 + pub(crate) fn format_event_custom<'b, S, N>( &self, - ctx: &FmtContext, + ctx: CustomFmtContext<'b, S, N>, writer: &mut dyn fmt::Write, event: &Event, - ) -> fmt::Result { + ) -> fmt::Result + where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, + { + if event.metadata().target() == sc_telemetry::TELEMETRY_LOG_SPAN { + return Ok(()); + } + let writer = &mut MaybeColorWriter::new(self.enable_color, writer); let normalized_meta = event.normalized_metadata(); let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata()); @@ -134,8 +98,8 @@ where 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())?; + if let Some(prefix) = exts.get::() { + write!(writer, "{}", prefix.as_str())?; break; } } @@ -148,62 +112,22 @@ where } } -pub struct NodeNameLayer; - -impl Layer for NodeNameLayer +// 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 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() + fn format_event( + &self, + ctx: &FmtContext, + writer: &mut dyn fmt::Write, + event: &Event, + ) -> fmt::Result { + self.format_event_custom(CustomFmtContext::FmtContext(ctx), writer, event) } } @@ -316,3 +240,95 @@ mod time { Ok(()) } } + +// NOTE: `FmtContext`'s fields are private. This enum allows us to make a `format_event` function +// that works with `FmtContext` or `Context` with `FormatFields` +#[allow(dead_code)] +pub(crate) enum CustomFmtContext<'a, S, N> { + FmtContext(&'a FmtContext<'a, S, N>), + ContextWithFormatFields(&'a Context<'a, S>, &'a N), +} + +impl<'a, S, N> FormatFields<'a> for CustomFmtContext<'a, S, N> +where + S: Subscriber + for<'lookup> LookupSpan<'lookup>, + N: for<'writer> FormatFields<'writer> + 'static, +{ + fn format_fields( + &self, + writer: &'a mut dyn fmt::Write, + fields: R, + ) -> fmt::Result { + match self { + CustomFmtContext::FmtContext(fmt_ctx) => fmt_ctx.format_fields(writer, fields), + CustomFmtContext::ContextWithFormatFields(_ctx, fmt_fields) => { + fmt_fields.format_fields(writer, fields) + } + } + } +} + +// NOTE: the following code has been duplicated from tracing-subscriber +// +// https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/fmt_layer.rs#L788 +impl<'a, S, N> CustomFmtContext<'a, S, N> +where + S: Subscriber + for<'lookup> LookupSpan<'lookup>, + N: for<'writer> FormatFields<'writer> + 'static, +{ + #[inline] + pub fn lookup_current(&self) -> Option> + where + S: for<'lookup> LookupSpan<'lookup>, + { + match self { + CustomFmtContext::FmtContext(fmt_ctx) => fmt_ctx.lookup_current(), + CustomFmtContext::ContextWithFormatFields(ctx, _) => ctx.lookup_current(), + } + } +} + +/// A writer that may write to `inner_writer` with colors. +/// +/// This is used by [`EventFormat`] to kill colors when `enable_color` is `false`. +/// +/// It is required to call [`MaybeColorWriter::write`] after all writes are done, +/// because the content of these writes is buffered and will only be written to the +/// `inner_writer` at that point. +struct MaybeColorWriter<'a> { + enable_color: bool, + buffer: String, + inner_writer: &'a mut dyn fmt::Write, +} + +impl<'a> fmt::Write for MaybeColorWriter<'a> { + fn write_str(&mut self, buf: &str) -> fmt::Result { + self.buffer.push_str(buf); + Ok(()) + } +} + +impl<'a> MaybeColorWriter<'a> { + /// Creates a new instance. + fn new(enable_color: bool, inner_writer: &'a mut dyn fmt::Write) -> Self { + Self { + enable_color, + inner_writer, + buffer: String::new(), + } + } + + /// Write the buffered content to the `inner_writer`. + fn write(&mut self) -> fmt::Result { + lazy_static::lazy_static! { + static ref RE: Regex = Regex::new("\x1b\\[[^m]+m").expect("Error initializing color regex"); + } + + if !self.enable_color { + let replaced = RE.replace_all(&self.buffer, ""); + self.inner_writer.write_str(&replaced) + } else { + self.inner_writer.write_str(&self.buffer) + } + } +} diff --git a/client/tracing/src/logging/layers/console_log.rs b/client/tracing/src/logging/layers/console_log.rs new file mode 100644 index 0000000000000..be992ae814235 --- /dev/null +++ b/client/tracing/src/logging/layers/console_log.rs @@ -0,0 +1,120 @@ +// This file is part of Substrate. + +// Copyright (C) 2021 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 crate::logging::event_format::{CustomFmtContext, EventFormat}; +use std::fmt; +use tracing::{Event, Level, Subscriber}; +use tracing_subscriber::{ + fmt::{ + time::{FormatTime, SystemTime}, + FormatFields, + }, + layer::Context, + registry::LookupSpan, + Layer, +}; +use wasm_bindgen::prelude::*; + +/// A `Layer` that display logs in the browser's console. +pub struct ConsoleLogLayer { + event_format: EventFormat, + fmt_fields: N, + _inner: std::marker::PhantomData, +} + +impl ConsoleLogLayer { + /// Create a new [`ConsoleLogLayer`] using the `EventFormat` provided in argument. + pub fn new(event_format: EventFormat) -> Self { + Self { + event_format, + fmt_fields: Default::default(), + _inner: std::marker::PhantomData, + } + } +} + +// NOTE: the following code took inspiration from `EventFormat` (in this file) +impl ConsoleLogLayer +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'writer> FormatFields<'writer> + 'static, +{ + fn format_event( + &self, + ctx: &Context<'_, S>, + writer: &mut dyn fmt::Write, + event: &Event, + ) -> fmt::Result { + self.event_format.format_event_custom( + CustomFmtContext::ContextWithFormatFields(ctx, &self.fmt_fields), + writer, + event, + ) + } +} + +// NOTE: the following code took inspiration from tracing-subscriber +// +// https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/fmt_layer.rs#L717 +impl Layer for ConsoleLogLayer +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'writer> FormatFields<'writer> + 'static, + T: FormatTime + 'static, +{ + fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { + thread_local! { + static BUF: std::cell::RefCell = std::cell::RefCell::new(String::new()); + } + + BUF.with(|buf| { + let borrow = buf.try_borrow_mut(); + let mut a; + let mut b; + let mut buf = match borrow { + Ok(buf) => { + a = buf; + &mut *a + } + _ => { + b = String::new(); + &mut b + } + }; + + if self.format_event(&ctx, &mut buf, event).is_ok() { + if !buf.is_empty() { + let meta = event.metadata(); + let level = meta.level(); + // NOTE: the following code took inspiration from tracing-subscriber + // + // https://github.com/iamcodemaker/console_log/blob/f13b5d6755/src/lib.rs#L149 + match *level { + Level::ERROR => web_sys::console::error_1(&JsValue::from(buf.as_str())), + Level::WARN => web_sys::console::warn_1(&JsValue::from(buf.as_str())), + Level::INFO => web_sys::console::info_1(&JsValue::from(buf.as_str())), + Level::DEBUG => web_sys::console::log_1(&JsValue::from(buf.as_str())), + Level::TRACE => web_sys::console::debug_1(&JsValue::from(buf.as_str())), + } + } + } + + buf.clear(); + }); + } +} diff --git a/client/tracing/src/logging/layers/mod.rs b/client/tracing/src/logging/layers/mod.rs new file mode 100644 index 0000000000000..8bda65f4c99bb --- /dev/null +++ b/client/tracing/src/logging/layers/mod.rs @@ -0,0 +1,25 @@ +// This file is part of Substrate. + +// Copyright (C) 2021 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 . + +#[cfg(target_os = "unknown")] +mod console_log; +mod prefix_layer; + +#[cfg(target_os = "unknown")] +pub use console_log::*; +pub use prefix_layer::*; diff --git a/client/tracing/src/logging/layers/prefix_layer.rs b/client/tracing/src/logging/layers/prefix_layer.rs new file mode 100644 index 0000000000000..6aa7e6d436e1a --- /dev/null +++ b/client/tracing/src/logging/layers/prefix_layer.rs @@ -0,0 +1,86 @@ +// This file is part of Substrate. + +// Copyright (C) 2021 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 tracing::{span::Attributes, Id, Subscriber}; +use tracing_subscriber::{layer::Context, registry::LookupSpan, Layer}; + +/// Span name used for the logging prefix. See macro `sc_tracing::logging::prefix_logs_with!` +pub const PREFIX_LOG_SPAN: &str = "substrate-log-prefix"; + +/// A `Layer` that captures the prefix span ([`PREFIX_LOG_SPAN`]) which is then used by +/// [`EventFormat`] to prefix the log lines by customizable string. +/// +/// See the macro `sc_cli::prefix_logs_with!` for more details. +pub struct PrefixLayer; + +impl Layer for PrefixLayer +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 = PrefixVisitor(&mut s); + attrs.record(&mut v); + + if !s.is_empty() { + let fmt_fields = Prefix(s); + extensions.insert(fmt_fields); + } + } + } +} + +struct PrefixVisitor<'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" { + let _ = write!(self.0, $format, value); + } + } + }; +} + +impl<'a, W: std::fmt::Write> tracing::field::Visit for PrefixVisitor<'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)] +pub(crate) struct Prefix(String); + +impl Prefix { + pub(crate) fn as_str(&self) -> &str { + self.0.as_str() + } +} diff --git a/client/tracing/src/logging/mod.rs b/client/tracing/src/logging/mod.rs new file mode 100644 index 0000000000000..ca4f74194bcc6 --- /dev/null +++ b/client/tracing/src/logging/mod.rs @@ -0,0 +1,531 @@ +// This file is part of Substrate. + +// Copyright (C) 2021 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 . + +//! Substrate logging library. +//! +//! This crate uses tokio's [tracing](https://github.com/tokio-rs/tracing/) library for logging. + +#![warn(missing_docs)] + +mod directives; +mod event_format; +mod layers; + +pub use directives::*; +pub use sc_tracing_proc_macro::*; + +use sc_telemetry::{ExtTransport, TelemetryWorker}; +use std::io; +use tracing::Subscriber; +use tracing_subscriber::{ + fmt::time::ChronoLocal, + fmt::{ + format, FormatEvent, FormatFields, Formatter, Layer as FmtLayer, MakeWriter, + SubscriberBuilder, + }, + layer::{self, SubscriberExt}, + registry::LookupSpan, + EnvFilter, FmtSubscriber, Layer, Registry, +}; + +pub use event_format::*; +pub use layers::*; + +/// Logging Result typedef. +pub type Result = std::result::Result; + +/// Logging errors. +#[derive(Debug, thiserror::Error)] +#[allow(missing_docs)] +#[non_exhaustive] +pub enum Error { + #[error(transparent)] + IoError(#[from] io::Error), + + #[error(transparent)] + SetGlobalDefaultError(#[from] tracing::subscriber::SetGlobalDefaultError), + + #[error(transparent)] + DirectiveParseError(#[from] tracing_subscriber::filter::ParseError), + + #[error(transparent)] + SetLoggerError(#[from] tracing_log::log_tracer::SetLoggerError), +} + +macro_rules! disable_log_reloading { + ($builder:expr) => {{ + let builder = $builder.with_filter_reloading(); + let handle = builder.reload_handle(); + set_reload_handle(handle); + builder + }}; +} + +/// Common implementation to get the subscriber. +fn get_subscriber_internal( + pattern: &str, + max_level: Option, + force_colors: Option, + telemetry_buffer_size: Option, + telemetry_external_transport: Option, + builder_hook: impl Fn( + SubscriberBuilder< + format::DefaultFields, + EventFormat, + EnvFilter, + fn() -> std::io::Stderr, + >, + ) -> SubscriberBuilder, +) -> Result<(impl Subscriber + for<'a> LookupSpan<'a>, TelemetryWorker)> +where + N: for<'writer> FormatFields<'writer> + 'static, + E: FormatEvent + 'static, + W: MakeWriter + 'static, + F: layer::Layer> + Send + Sync + 'static, + FmtLayer: layer::Layer + Send + Sync + 'static, +{ + // Accept all valid directives and print invalid ones + fn parse_user_directives(mut env_filter: EnvFilter, dirs: &str) -> Result { + for dir in dirs.split(',') { + env_filter = env_filter.add_directive(parse_default_directive(&dir)?); + } + Ok(env_filter) + } + + // Initialize filter - ensure to use `parse_default_directive` for any defaults to persist + // after log filter reloading by RPC + let mut env_filter = EnvFilter::default() + // Enable info + .add_directive(parse_default_directive("info").expect("provided directive is valid")) + // Disable info logging by default for some modules. + .add_directive(parse_default_directive("ws=off").expect("provided directive is valid")) + .add_directive(parse_default_directive("yamux=off").expect("provided directive is valid")) + .add_directive( + parse_default_directive("cranelift_codegen=off").expect("provided directive is valid"), + ) + // Set warn logging by default for some modules. + .add_directive( + parse_default_directive("cranelift_wasm=warn").expect("provided directive is valid"), + ) + .add_directive(parse_default_directive("hyper=warn").expect("provided directive is valid")); + + if let Ok(lvl) = std::env::var("RUST_LOG") { + if lvl != "" { + env_filter = parse_user_directives(env_filter, &lvl)?; + } + } + + if pattern != "" { + // We're not sure if log or tracing is available at this moment, so silently ignore the + // parse error. + env_filter = parse_user_directives(env_filter, pattern)?; + } + + let max_level_hint = Layer::::max_level_hint(&env_filter); + + let max_level = max_level.unwrap_or_else(|| match max_level_hint { + Some(tracing_subscriber::filter::LevelFilter::INFO) | None => log::LevelFilter::Info, + Some(tracing_subscriber::filter::LevelFilter::TRACE) => log::LevelFilter::Trace, + Some(tracing_subscriber::filter::LevelFilter::WARN) => log::LevelFilter::Warn, + Some(tracing_subscriber::filter::LevelFilter::ERROR) => log::LevelFilter::Error, + Some(tracing_subscriber::filter::LevelFilter::DEBUG) => log::LevelFilter::Debug, + Some(tracing_subscriber::filter::LevelFilter::OFF) => log::LevelFilter::Off, + }); + + tracing_log::LogTracer::builder() + .with_max_level(max_level) + .init()?; + + // If we're only logging `INFO` entries then we'll use a simplified logging format. + let simple = match max_level_hint { + Some(level) if level <= tracing_subscriber::filter::LevelFilter::INFO => true, + _ => false, + }; + + let enable_color = force_colors.unwrap_or_else(|| atty::is(atty::Stream::Stderr)); + let timer = ChronoLocal::with_format(if simple { + "%Y-%m-%d %H:%M:%S".to_string() + } else { + "%Y-%m-%d %H:%M:%S%.3f".to_string() + }); + + let (telemetry_layer, telemetry_worker) = + sc_telemetry::TelemetryLayer::new(telemetry_buffer_size, telemetry_external_transport)?; + let event_format = EventFormat { + timer, + display_target: !simple, + display_level: !simple, + display_thread_name: !simple, + enable_color, + }; + let builder = FmtSubscriber::builder().with_env_filter(env_filter); + + #[cfg(not(target_os = "unknown"))] + let builder = builder.with_writer(std::io::stderr as _); + + #[cfg(target_os = "unknown")] + let builder = builder.with_writer(std::io::sink); + + #[cfg(not(target_os = "unknown"))] + let builder = builder.event_format(event_format); + + #[cfg(not(target_os = "unknown"))] + let builder = builder_hook(builder); + + let subscriber = builder.finish().with(PrefixLayer).with(telemetry_layer); + + #[cfg(target_os = "unknown")] + let subscriber = subscriber.with(ConsoleLogLayer::new(event_format)); + + Ok((subscriber, telemetry_worker)) +} + +/// A builder that is used to initialize the global logger. +pub struct GlobalLoggerBuilder { + pattern: String, + profiling: Option<(crate::TracingReceiver, String)>, + telemetry_buffer_size: Option, + telemetry_external_transport: Option, + disable_log_reloading: bool, + force_colors: Option, +} + +impl GlobalLoggerBuilder { + /// Create a new [`GlobalLoggerBuilder`] which can be used to initialize the global logger. + pub fn new>(pattern: S) -> Self { + Self { + pattern: pattern.into(), + profiling: None, + telemetry_buffer_size: None, + telemetry_external_transport: None, + disable_log_reloading: false, + force_colors: None, + } + } + + /// Set up the profiling. + pub fn with_profiling>( + &mut self, + tracing_receiver: crate::TracingReceiver, + profiling_targets: S, + ) -> &mut Self { + self.profiling = Some((tracing_receiver, profiling_targets.into())); + self + } + + /// Wether or not to disable log reloading. + pub fn with_log_reloading(&mut self, enabled: bool) -> &mut Self { + self.disable_log_reloading = !enabled; + self + } + + /// Set a custom buffer size for the telemetry. + pub fn with_telemetry_buffer_size(&mut self, buffer_size: usize) -> &mut Self { + self.telemetry_buffer_size = Some(buffer_size); + self + } + + /// Set a custom network transport (used for the telemetry). + pub fn with_transport(&mut self, transport: ExtTransport) -> &mut Self { + self.telemetry_external_transport = Some(transport); + self + } + + /// Force enable/disable colors. + pub fn with_colors(&mut self, enable: bool) -> &mut Self { + self.force_colors = Some(enable); + self + } + + /// Initialize the global logger + /// + /// This sets various global logging and tracing instances and thus may only be called once. + pub fn init(self) -> Result { + if let Some((tracing_receiver, profiling_targets)) = self.profiling { + // If profiling is activated, we require `trace` logging. + let max_level = Some(log::LevelFilter::Trace); + + if self.disable_log_reloading { + let (subscriber, telemetry_worker) = get_subscriber_internal( + &format!("{},{},sc_tracing=trace", self.pattern, profiling_targets), + max_level, + self.force_colors, + self.telemetry_buffer_size, + self.telemetry_external_transport, + |builder| builder, + )?; + let profiling = crate::ProfilingLayer::new(tracing_receiver, &profiling_targets); + + tracing::subscriber::set_global_default(subscriber.with(profiling))?; + + Ok(telemetry_worker) + } else { + let (subscriber, telemetry_worker) = get_subscriber_internal( + &format!("{},{},sc_tracing=trace", self.pattern, profiling_targets), + max_level, + self.force_colors, + self.telemetry_buffer_size, + self.telemetry_external_transport, + |builder| disable_log_reloading!(builder), + )?; + let profiling = crate::ProfilingLayer::new(tracing_receiver, &profiling_targets); + + tracing::subscriber::set_global_default(subscriber.with(profiling))?; + + Ok(telemetry_worker) + } + } else { + if self.disable_log_reloading { + let (subscriber, telemetry_worker) = get_subscriber_internal( + &self.pattern, + None, + self.force_colors, + self.telemetry_buffer_size, + self.telemetry_external_transport, + |builder| builder, + )?; + + tracing::subscriber::set_global_default(subscriber)?; + + Ok(telemetry_worker) + } else { + let (subscriber, telemetry_worker) = get_subscriber_internal( + &self.pattern, + None, + self.force_colors, + self.telemetry_buffer_size, + self.telemetry_external_transport, + |builder| disable_log_reloading!(builder), + )?; + + tracing::subscriber::set_global_default(subscriber)?; + + Ok(telemetry_worker) + } + } + } +} + +#[cfg(test)] +mod tests { + use super::*; + use crate as sc_tracing; + use std::{env, process::Command}; + use tracing::{metadata::Kind, subscriber::Interest, Callsite, Level, Metadata}; + + const EXPECTED_LOG_MESSAGE: &'static str = "yeah logging works as expected"; + const EXPECTED_NODE_NAME: &'static str = "THE_NODE"; + + fn init_logger(pattern: &str) { + let _ = GlobalLoggerBuilder::new(pattern).init().unwrap(); + } + + fn run_in_process(test_name: &str) { + if env::var("RUN_IN_PROCESS").is_err() { + let status = Command::new(env::current_exe().unwrap()) + .arg(test_name) + .env("RUN_IN_PROCESS", "true") + .status() + .unwrap(); + assert!(status.success(), "process did not ended successfully"); + std::process::exit(0); + } + } + + #[test] + fn test_logger_filters() { + run_in_process("test_logger_filters"); + + let test_pattern = "afg=debug,sync=trace,client=warn,telemetry,something-with-dash=error"; + init_logger(&test_pattern); + + tracing::dispatcher::get_default(|dispatcher| { + let test_filter = |target, level| { + struct DummyCallSite; + impl Callsite for DummyCallSite { + fn set_interest(&self, _: Interest) {} + fn metadata(&self) -> &Metadata<'_> { + unreachable!(); + } + } + + let metadata = tracing::metadata!( + name: "", + target: target, + level: level, + fields: &[], + callsite: &DummyCallSite, + kind: Kind::SPAN, + ); + + dispatcher.enabled(&metadata) + }; + + assert!(test_filter("afg", Level::INFO)); + assert!(test_filter("afg", Level::DEBUG)); + assert!(!test_filter("afg", Level::TRACE)); + + assert!(test_filter("sync", Level::TRACE)); + assert!(test_filter("client", Level::WARN)); + + assert!(test_filter("telemetry", Level::TRACE)); + assert!(test_filter("something-with-dash", Level::ERROR)); + }); + } + + /// This test ensures that using dash (`-`) in the target name in logs and directives actually + /// work. + #[test] + fn dash_in_target_name_works() { + let executable = env::current_exe().unwrap(); + let output = Command::new(executable) + .env("ENABLE_LOGGING", "1") + .args(&["--nocapture", "log_something_with_dash_target_name"]) + .output() + .unwrap(); + + let output = String::from_utf8(output.stderr).unwrap(); + assert!(output.contains(EXPECTED_LOG_MESSAGE)); + } + + /// This is not an actual test, it is used by the `dash_in_target_name_works` test. + /// The given test will call the test executable and only execute this one test that + /// only prints `EXPECTED_LOG_MESSAGE` through logging while using a target + /// name that contains a dash. This ensures that target names with dashes work. + #[test] + fn log_something_with_dash_target_name() { + if env::var("ENABLE_LOGGING").is_ok() { + let test_pattern = "test-target=info"; + let _guard = init_logger(&test_pattern); + + log::info!(target: "test-target", "{}", EXPECTED_LOG_MESSAGE); + } + } + + #[test] + fn prefix_in_log_lines() { + let re = regex::Regex::new(&format!( + r"^\d{{4}}-\d{{2}}-\d{{2}} \d{{2}}:\d{{2}}:\d{{2}} \[{}\] {}$", + EXPECTED_NODE_NAME, EXPECTED_LOG_MESSAGE, + )) + .unwrap(); + 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!( + re.is_match(output.trim()), + format!("Expected:\n{}\nGot:\n{}", re, output), + ); + } + + /// This is not an actual test, it is used by the `prefix_in_log_lines` test. + /// The given test will call the test executable and only execute this one test that + /// only prints 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 _guard = init_logger(""); + prefix_in_log_lines_process(); + } + } + + #[crate::logging::prefix_logs_with(EXPECTED_NODE_NAME)] + fn prefix_in_log_lines_process() { + log::info!("{}", EXPECTED_LOG_MESSAGE); + } + + /// This is not an actual test, it is used by the `do_not_write_with_colors_on_tty` test. + /// The given test will call the test executable and only execute this one test that + /// only prints a log line with some colors in it. + #[test] + fn do_not_write_with_colors_on_tty_entrypoint() { + if env::var("ENABLE_LOGGING").is_ok() { + let _guard = init_logger(""); + log::info!("{}", ansi_term::Colour::Yellow.paint(EXPECTED_LOG_MESSAGE)); + } + } + + #[test] + fn do_not_write_with_colors_on_tty() { + let re = regex::Regex::new(&format!( + r"^\d{{4}}-\d{{2}}-\d{{2}} \d{{2}}:\d{{2}}:\d{{2}} {}$", + EXPECTED_LOG_MESSAGE, + )) + .unwrap(); + let executable = env::current_exe().unwrap(); + let output = Command::new(executable) + .env("ENABLE_LOGGING", "1") + .args(&["--nocapture", "do_not_write_with_colors_on_tty_entrypoint"]) + .output() + .unwrap(); + + let output = String::from_utf8(output.stderr).unwrap(); + assert!( + re.is_match(output.trim()), + format!("Expected:\n{}\nGot:\n{}", re, output), + ); + } + + #[test] + fn log_max_level_is_set_properly() { + fn run_test(rust_log: Option, tracing_targets: Option) -> String { + let executable = env::current_exe().unwrap(); + let mut command = Command::new(executable); + + command + .env("PRINT_MAX_LOG_LEVEL", "1") + .args(&["--nocapture", "log_max_level_is_set_properly"]); + + if let Some(rust_log) = rust_log { + command.env("RUST_LOG", rust_log); + } + + if let Some(tracing_targets) = tracing_targets { + command.env("TRACING_TARGETS", tracing_targets); + } + + let output = command.output().unwrap(); + + String::from_utf8(output.stderr).unwrap() + } + + if env::var("PRINT_MAX_LOG_LEVEL").is_ok() { + init_logger(&env::var("TRACING_TARGETS").unwrap_or_default()); + eprint!("MAX_LOG_LEVEL={:?}", log::max_level()); + } else { + assert_eq!("MAX_LOG_LEVEL=Info", run_test(None, None)); + assert_eq!( + "MAX_LOG_LEVEL=Trace", + run_test(Some("test=trace".into()), None) + ); + assert_eq!( + "MAX_LOG_LEVEL=Debug", + run_test(Some("test=debug".into()), None) + ); + assert_eq!( + "MAX_LOG_LEVEL=Trace", + run_test(None, Some("test=info".into())) + ); + } + } +} diff --git a/utils/browser/Cargo.toml b/utils/browser/Cargo.toml index 7380a308180f5..3137c2698ec33 100644 --- a/utils/browser/Cargo.toml +++ b/utils/browser/Cargo.toml @@ -18,7 +18,6 @@ futures01 = { package = "futures", version = "0.1.29" } log = "0.4.8" libp2p-wasm-ext = { version = "0.27", features = ["websocket"] } console_error_panic_hook = "0.1.6" -console_log = "0.2.0" js-sys = "0.3.34" wasm-bindgen = "0.2.57" wasm-bindgen-futures = "0.4.18" @@ -28,6 +27,8 @@ sc-informant = { version = "0.8.0", path = "../../client/informant" } sc-service = { version = "0.8.0", path = "../../client/service", default-features = false } sc-network = { path = "../../client/network", version = "0.8.0"} sc-chain-spec = { path = "../../client/chain-spec", version = "2.0.0"} +sc-telemetry = { path = "../../client/telemetry", version = "2.0.0"} +sc-tracing = { path = "../../client/tracing", version = "2.0.0"} # Imported just for the `wasm-bindgen` feature getrandom = { version = "0.2", features = ["js"] } diff --git a/utils/browser/src/lib.rs b/utils/browser/src/lib.rs index c59fbb991bee5..5e1e8db316688 100644 --- a/utils/browser/src/lib.rs +++ b/utils/browser/src/lib.rs @@ -24,6 +24,8 @@ use sc_service::{ GenericChainSpec, RuntimeGenesis, KeepBlocks, TransactionStorageMode, }; +use sc_telemetry::TelemetryHandle; +use sc_tracing::logging::GlobalLoggerBuilder; use wasm_bindgen::prelude::*; use futures::{ prelude::*, channel::{oneshot, mpsc}, compat::*, future::{ready, ok, select} @@ -33,20 +35,31 @@ use sc_chain_spec::Extension; use libp2p_wasm_ext::{ExtTransport, ffi}; pub use console_error_panic_hook::set_once as set_console_error_panic_hook; -pub use console_log::init_with_level as init_console_log; + +/// Initialize the logger and return a `TelemetryWorker` and a wasm `ExtTransport`. +pub fn init_logging_and_telemetry( + pattern: &str, +) -> Result { + let transport = ExtTransport::new(ffi::websocket_transport()); + let mut logger = GlobalLoggerBuilder::new(pattern); + logger.with_transport(transport); + logger.init() +} /// Create a service configuration from a chain spec. /// /// This configuration contains good defaults for a browser light client. -pub async fn browser_configuration(chain_spec: GenericChainSpec) - -> Result> +pub async fn browser_configuration( + chain_spec: GenericChainSpec, + telemetry_handle: Option, +) -> Result> where G: RuntimeGenesis + 'static, E: Extension + 'static + Send + Sync, { let name = chain_spec.name().to_string(); - let transport = ExtTransport::new(ffi::websocket_transport()); + let mut network = NetworkConfiguration::new( format!("{} (Browser)", name), "unknown", @@ -69,6 +82,7 @@ where async {} }).into(), telemetry_external_transport: Some(transport), + telemetry_handle, role: Role::Light, database: { info!("Opening Indexed DB database '{}'...", name);