From c5065e1cd893c6602769961f6f60584db6fb1b75 Mon Sep 17 00:00:00 2001 From: Pierre Krieger Date: Fri, 5 Jan 2024 10:36:49 +0100 Subject: [PATCH 01/14] Add a `PlatformRef::log` function --- light-base/src/platform.rs | 21 +++++++++++++++++++++ light-base/src/platform/default.rs | 22 +++++++++++++++++++--- wasm-node/rust/src/platform.rs | 17 +++++++++++++++++ 3 files changed, 57 insertions(+), 3 deletions(-) diff --git a/light-base/src/platform.rs b/light-base/src/platform.rs index 548c16c9aa..7f3a98dccd 100644 --- a/light-base/src/platform.rs +++ b/light-base/src/platform.rs @@ -148,6 +148,15 @@ pub trait PlatformRef: UnwindSafe + Clone + Send + Sync + 'static { task: impl future::Future + Send + 'static, ); + /// Emit a log line. + fn log<'a>( + &self, + log_level: LogLevel, + log_target: &'a str, + message: fmt::Arguments<'a>, + key_values: impl Iterator, + ); + /// Value returned when a JSON-RPC client requests the name of the client, or when a peer /// performs an identification request. Reasonable value is `env!("CARGO_PKG_NAME")`. fn client_name(&self) -> Cow; @@ -263,6 +272,18 @@ pub trait PlatformRef: UnwindSafe + Clone + Send + Sync + 'static { ) -> Self::StreamUpdateFuture<'a>; } +/// Log level of a log entry. +/// +/// See [`PlatformRef::log`]. +#[derive(Debug)] +pub enum LogLevel { + Error = 1, + Warn = 2, + Info = 3, + Debug = 4, + Trace = 5, +} + /// Established multistream connection information. See [`PlatformRef::connect_multistream`]. #[derive(Debug)] pub struct MultiStreamWebRtcConnection { diff --git a/light-base/src/platform/default.rs b/light-base/src/platform/default.rs index c51897b41a..b99374a092 100644 --- a/light-base/src/platform/default.rs +++ b/light-base/src/platform/default.rs @@ -32,12 +32,12 @@ //! use super::{ - with_buffers, Address, ConnectionType, IpAddr, MultiStreamAddress, MultiStreamWebRtcConnection, - PlatformRef, SubstreamDirection, + with_buffers, Address, ConnectionType, IpAddr, LogLevel, MultiStreamAddress, + MultiStreamWebRtcConnection, PlatformRef, SubstreamDirection, }; use alloc::{borrow::Cow, sync::Arc}; -use core::{panic, pin::Pin, str, time::Duration}; +use core::{fmt, panic, pin::Pin, str, time::Duration}; use futures_util::{future, FutureExt as _}; use smoldot::libp2p::websocket; use std::{ @@ -153,6 +153,22 @@ impl PlatformRef for Arc { .detach(); } + fn log<'a>( + &self, + log_level: LogLevel, + log_target: &'a str, + message: fmt::Arguments<'a>, + key_values: impl Iterator, + ) { + log::logger().log( + &log::RecordBuilder::new() + //.level(todo!()) + .target(log_target) + .args(message) + .build(), + ) + } + fn client_name(&self) -> Cow { Cow::Borrowed(&self.client_name) } diff --git a/wasm-node/rust/src/platform.rs b/wasm-node/rust/src/platform.rs index 9eae12d831..7e55f7c4ff 100644 --- a/wasm-node/rust/src/platform.rs +++ b/wasm-node/rust/src/platform.rs @@ -180,6 +180,23 @@ impl smoldot_light::platform::PlatformRef for PlatformRef { runnable.schedule(); } + fn log<'a>( + &self, + log_level: LogLevel, + log_target: &'a str, + message: fmt::Arguments<'a>, + key_values: impl Iterator, + ) { + // TODO: + log::logger().log( + &log::RecordBuilder::new() + //.level(todo!()) + .target(log_target) + .args(message) + .build(), + ) + } + fn client_name(&self) -> Cow { env!("CARGO_PKG_NAME").into() } From 08e24d4052ee8558a48c9a6bf55e282802434f34 Mon Sep 17 00:00:00 2001 From: Pierre Krieger Date: Fri, 5 Jan 2024 11:11:41 +0100 Subject: [PATCH 02/14] [WIP] Add a log! macro and rework all the log lines --- light-base/src/json_rpc_service.rs | 40 ++- .../json_rpc_service/background/chain_head.rs | 12 +- .../background/legacy_state_sub.rs | 86 +++--- .../background/state_chain.rs | 38 ++- light-base/src/lib.rs | 262 ++++++++++++------ light-base/src/network_service/tasks.rs | 118 ++++++-- light-base/src/platform/default.rs | 10 +- light-base/src/sync_service.rs | 11 +- light-base/src/sync_service/parachain.rs | 165 +++++++---- light-base/src/transactions_service.rs | 249 ++++++++++------- 10 files changed, 671 insertions(+), 320 deletions(-) diff --git a/light-base/src/json_rpc_service.rs b/light-base/src/json_rpc_service.rs index 8f6980d02e..d27b1d79aa 100644 --- a/light-base/src/json_rpc_service.rs +++ b/light-base/src/json_rpc_service.rs @@ -52,7 +52,10 @@ use core::num::NonZeroU32; use smoldot::{chain_spec, json_rpc::service}; /// Configuration for [`service()`]. -pub struct Config { +pub struct Config { + /// Access to the platform's capabilities. + pub platform: TPlat, + /// Name of the chain, for logging purposes. /// /// > **Note**: This name will be directly printed out. Any special character should already @@ -86,7 +89,7 @@ pub struct Config { /// be initialized using [`ServicePrototype::start`]. /// /// Destroying the [`Frontend`] automatically shuts down the service. -pub fn service(config: Config) -> (Frontend, ServicePrototype) { +pub fn service(config: Config) -> (Frontend, ServicePrototype) { let log_target = format!("json-rpc-{}", config.log_name); let (requests_processing_task, requests_responses_io) = @@ -96,6 +99,7 @@ pub fn service(config: Config) -> (Frontend, ServicePrototype) { }); let frontend = Frontend { + platform: config.platform, log_target: log_target.clone(), requests_responses_io: Arc::new(requests_responses_io), }; @@ -116,7 +120,10 @@ pub fn service(config: Config) -> (Frontend, ServicePrototype) { /// /// Destroying all the [`Frontend`]s automatically shuts down the associated service. #[derive(Clone)] -pub struct Frontend { +pub struct Frontend { + /// See [`Config::platform`]. + platform: TPlat, + /// Sending requests and receiving responses. /// /// Connected to the [`background`]. @@ -126,7 +133,7 @@ pub struct Frontend { log_target: String, } -impl Frontend { +impl Frontend { /// Queues the given JSON-RPC request to be processed in the background. /// /// An error is returned if [`Config::max_pending_requests`] is exceeded, which can happen @@ -142,10 +149,12 @@ impl Frontend { .try_send_request(json_rpc_request) { Ok(()) => { - log::debug!( - target: &self.log_target, - "JSON-RPC => {}", - log_friendly_request + log!( + &self.platform, + Debug, + &self.log_target, + "json-rpc-request-queued", + request = log_friendly_request ); Ok(()) } @@ -172,13 +181,13 @@ impl Frontend { Err(service::WaitNextResponseError::ClientMainTaskDestroyed) => unreachable!(), }; - log::debug!( - target: &self.log_target, - "JSON-RPC <= {}", - crate::util::truncated_str( - message.chars().filter(|c| !c.is_control()), - 250, - ) + log!( + &self.platform, + Debug, + &self.log_target, + "json-rpc-response-yielded", + response = + crate::util::truncated_str(message.chars().filter(|c| !c.is_control()), 250,) ); message @@ -202,6 +211,7 @@ pub struct ServicePrototype { /// Configuration for a JSON-RPC service. pub struct StartConfig<'a, TPlat: PlatformRef> { /// Access to the platform's capabilities. + // TODO: redundant with Config above? pub platform: TPlat, /// Access to the network, and identifier of the chain from the point of view of the network diff --git a/light-base/src/json_rpc_service/background/chain_head.rs b/light-base/src/json_rpc_service/background/chain_head.rs index 768c3dd73a..d3996d0fb9 100644 --- a/light-base/src/json_rpc_service/background/chain_head.rs +++ b/light-base/src/json_rpc_service/background/chain_head.rs @@ -93,8 +93,10 @@ impl Background { // JSON-RPC client implementations are made aware of this limit. This number of 2 might // be relaxed and/or configurable in the future. if lock.len() >= 2 { - log::warn!( - target: &self.log_target, + log!( + &self.platform, + Warn, + &self.log_target, "Rejected `chainHead_unstable_follow` subscription due to limit reached." ); request.fail(json_rpc::parse::ErrorResponse::ApplicationDefined( @@ -1031,8 +1033,10 @@ impl ChainHeadFollowTask { -32000, "Child key storage queries not supported yet", )); - log::warn!( - target: &self.log_target, + log!( + &self.platform, + Warn, + &self.log_target, "chainHead_unstable_storage has been called with a non-null childTrie. \ This isn't supported by smoldot yet." ); diff --git a/light-base/src/json_rpc_service/background/legacy_state_sub.rs b/light-base/src/json_rpc_service/background/legacy_state_sub.rs index 8f2fceb279..fbd86d6ae6 100644 --- a/light-base/src/json_rpc_service/background/legacy_state_sub.rs +++ b/light-base/src/json_rpc_service/background/legacy_state_sub.rs @@ -376,12 +376,16 @@ async fn run(mut task: Task) { ) { Ok(h) => h, Err(error) => { - log::warn!( - target: &task.log_target, - "`chain_subscribeFinalizedHeads` subscription has skipped block \ - due to undecodable header. Hash: {}. Error: {}", - HashDisplay(current_finalized_block), - error, + log!( + &task.platform, + Warn, + &task.log_target, + format!( + "`chain_subscribeFinalizedHeads` subscription has skipped \ + block due to undecodable header. Hash: {}. Error: {}", + HashDisplay(current_finalized_block), + error, + ) ); continue; } @@ -420,12 +424,16 @@ async fn run(mut task: Task) { ) { Ok(h) => h, Err(error) => { - log::warn!( - target: &task.log_target, - "`chain_subscribeNewHeads` subscription has skipped block due to \ - undecodable header. Hash: {}. Error: {}", - HashDisplay(current_best_block), - error, + log!( + &task.platform, + Warn, + &task.log_target, + format!( + "`chain_subscribeNewHeads` subscription has skipped block due to \ + undecodable header. Hash: {}. Error: {}", + HashDisplay(current_best_block), + error + ) ); continue; } @@ -685,14 +693,18 @@ async fn run(mut task: Task) { ) { Ok(h) => h, Err(error) => { - log::warn!( - target: &task.log_target, - "`chain_subscribeAllHeads` subscription has skipped block due to \ - undecodable header. Hash: {}. Error: {}", - HashDisplay(&header::hash_from_scale_encoded_header( - &block.scale_encoded_header - )), - error, + log!( + &task.platform, + Warn, + &task.log_target, + format!( + "`chain_subscribeAllHeads` subscription has skipped block \ + due to undecodable header. Hash: {}. Error: {}", + HashDisplay(&header::hash_from_scale_encoded_header( + &block.scale_encoded_header + )), + error + ) ); continue; } @@ -818,12 +830,17 @@ async fn run(mut task: Task) { ) { Ok(h) => h, Err(error) => { - log::warn!( - target: &task.log_target, - "`chain_subscribeNewHeads` subscription has skipped \ - block due to undecodable header. Hash: {}. Error: {}", - HashDisplay(current_best_block), - error, + log!( + &task.platform, + Warn, + &task.log_target, + format!( + "`chain_subscribeNewHeads` subscription has \ + skipped block due to undecodable header. Hash: {}. \ + Error: {}", + HashDisplay(current_best_block), + error + ) ); continue; } @@ -862,12 +879,17 @@ async fn run(mut task: Task) { ) { Ok(h) => h, Err(error) => { - log::warn!( - target: &task.log_target, - "`chain_subscribeFinalizedHeads` subscription has skipped \ - block due to undecodable header. Hash: {}. Error: {}", - HashDisplay(current_finalized_block), - error, + log!( + &task.platform, + Warn, + &task.log_target, + format!( + "`chain_subscribeFinalizedHeads` subscription \ + has skipped block due to undecodable header. \ + Hash: {}. Error: {}", + HashDisplay(current_finalized_block), + error, + ) ); continue; } diff --git a/light-base/src/json_rpc_service/background/state_chain.rs b/light-base/src/json_rpc_service/background/state_chain.rs index fea19c9ab6..2dbb9d2464 100644 --- a/light-base/src/json_rpc_service/background/state_chain.rs +++ b/light-base/src/json_rpc_service/background/state_chain.rs @@ -70,11 +70,14 @@ impl Background { request.respond(methods::Response::system_accountNextIndex(u64::from(index))); } Err(error) => { - log::warn!( - target: &self.log_target, - "Returning error from `system_accountNextIndex`. \ - API user might not function properly. Error: {}", - error + log!( + &self.platform, + Warn, + &self.log_target, + format!( + "Returning error from `system_accountNextIndex`. \ + API user might not function properly. Error: {error}" + ) ); request.fail(service::ErrorResponse::ServerError( -32000, @@ -421,11 +424,14 @@ impl Background { )), }, Err(error) => { - log::warn!( - target: &self.log_target, - "Returning error from `payment_queryInfo`. \ - API user might not function properly. Error: {}", - error + log!( + &self.platform, + Warn, + &self.log_target, + format!( + "Returning error from `payment_queryInfo`. \ + API user might not function properly. Error: {error}" + ) ); request.fail(json_rpc::parse::ErrorResponse::ServerError( -32000, @@ -744,10 +750,14 @@ impl Background { &format!("Failed to decode metadata from runtime. Error: {error}"), )), Err(error) => { - log::warn!( - target: &self.log_target, - "Returning error from `state_getMetadata`. API user might not function \ - properly. Error: {error}" + log!( + &self.platform, + Warn, + &self.log_target, + format!( + "Returning error from `state_getMetadata`. API user might not function \ + properly. Error: {error}" + ) ); request.fail(json_rpc::parse::ErrorResponse::ServerError( -32000, diff --git a/light-base/src/lib.rs b/light-base/src/lib.rs index 56f418b7f7..0b33a5af7c 100644 --- a/light-base/src/lib.rs +++ b/light-base/src/lib.rs @@ -89,12 +89,61 @@ use alloc::{borrow::ToOwned as _, boxed::Box, format, string::String, sync::Arc, use core::{num::NonZeroU32, ops, pin, time::Duration}; use hashbrown::{hash_map::Entry, HashMap}; use itertools::Itertools as _; +use platform::PlatformRef; use smoldot::{ chain, chain_spec, header, informant::HashDisplay, libp2p::{multiaddr, peer_id}, }; +macro_rules! log_inner { + () => { + core::iter::empty() + }; + (,) => { + core::iter::empty() + }; + ($key:ident = $value:expr) => { + log_inner!($key = $value,) + }; + ($key:ident = ?$value:expr) => { + log_inner!($key = ?$value,) + }; + ($key:ident) => { + log_inner!($key = $key,) + }; + (?$key:ident) => { + log_inner!($key = ?$key,) + }; + ($key:ident = $value:expr, $($rest:tt)*) => { + core::iter::once((stringify!($key), &$value as &dyn core::fmt::Display)).chain(log_inner!($($rest)*)) + }; + ($key:ident = ?$value:expr, $($rest:tt)*) => { + core::iter::once((stringify!($key), &format_args!("{:?}", $value) as &dyn core::fmt::Display)).chain(log_inner!($($rest)*)) + }; + ($key:ident, $($rest:tt)*) => { + log_inner!($key = $key, $($rest)*) + }; + (?$key:ident, $($rest:tt)*) => { + log_inner!($key = ?$key, $($rest)*) + }; +} + +macro_rules! log { + ($plat:expr, $level:ident, $target:expr, $message:expr) => { + log!($plat, $level, $target, $message,) + }; + ($plat:expr, $level:ident, $target:expr, $message:expr, $($params:tt)*) => { + $crate::platform::PlatformRef::log( + $plat, + $crate::platform::LogLevel::$level, + $target, + core::format_args!("{}", $message), + log_inner!($($params)*) + ) + }; +} + mod database; mod json_rpc_service; mod runtime_service; @@ -208,7 +257,7 @@ pub struct Client { /// List of chains currently running according to the public API. Indices in this container /// are reported through the public API. The values are either an error if the chain has failed /// to initialize, or key found in [`Client::chains_by_key`]. - public_api_chains: slab::Slab>, + public_api_chains: slab::Slab>, /// De-duplicated list of chains that are *actually* running. /// @@ -224,7 +273,7 @@ pub struct Client { network_service: Option>>, } -struct PublicApiChain { +struct PublicApiChain { /// Opaque user data passed to [`Client::add_chain`]. user_data: TChain, @@ -238,7 +287,7 @@ struct PublicApiChain { /// Handle that sends requests to the JSON-RPC service that runs in the background. /// Destroying this handle also shuts down the service. `None` iff /// [`AddChainConfig::json_rpc`] was [`AddChainConfigJsonRpc::Disabled`] when adding the chain. - json_rpc_frontend: Option, + json_rpc_frontend: Option>, /// Notified when the [`PublicApiChain`] is destroyed, in order for the [`JsonRpcResponses`] /// to detect when the chain has been removed. @@ -299,7 +348,7 @@ impl Clone for ChainServices { } /// Returns by [`Client::add_chain`] on success. -pub struct AddChainSuccess { +pub struct AddChainSuccess { /// Newly-allocated identifier for the chain. pub chain_id: ChainId, @@ -308,26 +357,26 @@ pub struct AddChainSuccess { /// Is always `Some` if [`AddChainConfig::json_rpc`] was [`AddChainConfigJsonRpc::Enabled`], /// and `None` if it was [`AddChainConfigJsonRpc::Disabled`]. In other words, you can unwrap /// this `Option` if you passed `Enabled`. - pub json_rpc_responses: Option, + pub json_rpc_responses: Option>, } /// Stream of JSON-RPC responses or notifications. /// /// See [`AddChainSuccess::json_rpc_responses`]. -pub struct JsonRpcResponses { +pub struct JsonRpcResponses { /// Receiving side for responses. /// /// As long as this object is alive, the JSON-RPC service will continue running. In order /// to prevent that from happening, we destroy it as soon as the /// [`JsonRpcResponses::public_api_chain_destroyed`] is notified of the destruction of /// the sender. - inner: Option, + inner: Option>, /// Notified when the [`PublicApiChain`] is destroyed. public_api_chain_destroyed: pin::Pin>, } -impl JsonRpcResponses { +impl JsonRpcResponses { /// Returns the next response or notification, or `None` if the chain has been removed. pub async fn next(&mut self) -> Option { if let Some(frontend) = self.inner.as_mut() { @@ -366,7 +415,7 @@ impl Client { pub fn add_chain( &mut self, config: AddChainConfig<'_, TChain, impl Iterator>, - ) -> Result { + ) -> Result, AddChainError> { // `chains_by_key` is created lazily whenever needed. let chains_by_key = self.chains_by_key.get_or_insert_with(|| { HashMap::with_hasher(util::SipHasherBuild::new({ @@ -737,86 +786,128 @@ impl Client { // Note that the chain name is printed through the `Debug` trait (rather // than `Display`) because it is an untrusted user input. if let Some((_, para_id, relay_chain_log_name)) = relay_chain.as_ref() { - log::info!( - target: "smoldot", - "Parachain initialization complete for {}. Name: {:?}. Genesis \ - hash: {}. Relay chain: {} (id: {})", - log_name, - chain_spec.name(), - HashDisplay(&genesis_block_hash), - relay_chain_log_name, - para_id, + log!( + &self.platform, + Info, + "smoldot", + format!( + "Parachain initialization complete for {}. Name: {:?}. Genesis \ + hash: {}. Relay chain: {} (id: {})", + log_name, + chain_spec.name(), + HashDisplay(&genesis_block_hash), + relay_chain_log_name, + para_id + ) ); } else { - log::info!( - target: "smoldot", - "Chain initialization complete for {}. Name: {:?}. Genesis \ - hash: {}. {} starting at: {} (#{})", - log_name, - chain_spec.name(), - HashDisplay(&genesis_block_hash), - if used_database_chain_information { "Database" } else { "Chain specification" }, - HashDisplay(&chain_information - .as_ref() - .map(|ci| ci.as_ref().finalized_block_header.hash(usize::from(chain_spec.block_number_bytes()))) - .unwrap_or(genesis_block_hash)), - chain_information - .as_ref() - .map(|ci| ci.as_ref().finalized_block_header.number) - .unwrap_or(0) + log!( + &self.platform, + Info, + "smoldot", + format!( + "Chain initialization complete for {}. Name: {:?}. Genesis \ + hash: {}. {} starting at: {} (#{})", + log_name, + chain_spec.name(), + HashDisplay(&genesis_block_hash), + if used_database_chain_information { + "Database" + } else { + "Chain specification" + }, + HashDisplay( + &chain_information + .as_ref() + .map(|ci| ci + .as_ref() + .finalized_block_header + .hash(usize::from(chain_spec.block_number_bytes()))) + .unwrap_or(genesis_block_hash) + ), + chain_information + .as_ref() + .map(|ci| ci.as_ref().finalized_block_header.number) + .unwrap_or(0) + ) ); } if print_warning_genesis_root_chainspec { - log::info!( - target: "smoldot", - "Chain specification of {} contains a `genesis.raw` item. It is \ - possible to significantly improve the initialization time by \ - replacing the `\"raw\": ...` field with \ - `\"stateRootHash\": \"0x{}\"`", - log_name, hex::encode(genesis_block_state_root) - ) + log!( + &self.platform, + Info, + "smoldot", + format!( + "Chain specification of {} contains a `genesis.raw` item. It is \ + possible to significantly improve the initialization time by \ + replacing the `\"raw\": ...` field with \ + `\"stateRootHash\": \"0x{}\"`", + log_name, + hex::encode(genesis_block_state_root) + ) + ); } if chain_spec.protocol_id().is_some() { - log::warn!( - target: "smoldot", - "Chain specification of {} contains a `protocolId` field. This \ - field is deprecated and its value is no longer used. It can be \ - safely removed from the JSON document.", log_name + log!( + &self.platform, + Warn, + "smoldot", + format!( + "Chain specification of {} contains a `protocolId` field. This \ + field is deprecated and its value is no longer used. It can be \ + safely removed from the JSON document.", + log_name + ) ); } if chain_spec.telemetry_endpoints().count() != 0 { - log::warn!( - target: "smoldot", - "Chain specification of {} contains a non-empty \ - `telemetryEndpoints` field. Smoldot doesn't support telemetry \ - endpoints and as such this field is unused.", log_name + log!( + &self.platform, + Warn, + "smoldot", + format!( + "Chain specification of {} contains a non-empty \ + `telemetryEndpoints` field. Smoldot doesn't support telemetry \ + endpoints and as such this field is unused.", + log_name + ) ); } // TODO: remove after https://github.com/paritytech/smoldot/issues/2584 if chain_spec.bad_blocks_hashes().count() != 0 { - log::warn!( - target: "smoldot", - "Chain specification of {} contains a list of bad blocks. Bad \ - blocks are not implemented in the light client. An appropriate \ - way to silence this warning is to remove the bad blocks from the \ - chain specification, which can safely be done:\n\ - - For relay chains: if the chain specification contains a \ - checkpoint and that the bad blocks have a block number inferior \ - to this checkpoint.\n\ - - For parachains: if the bad blocks have a block number inferior \ - to the current parachain finalized block.", log_name + log!( + &self.platform, + Warn, + "smoldot", + format!( + "Chain specification of {} contains a list of bad blocks. Bad \ + blocks are not implemented in the light client. An appropriate \ + way to silence this warning is to remove the bad blocks from the \ + chain specification, which can safely be done:\n\ + - For relay chains: if the chain specification contains a \ + checkpoint and that the bad blocks have a block number inferior \ + to this checkpoint.\n\ + - For parachains: if the bad blocks have a block number inferior \ + to the current parachain finalized block.", + log_name + ) ); } if database_was_wrong_chain { - log::warn!( - target: "smoldot", - "Ignore database of {} because its genesis hash didn't match the \ - genesis hash of the chain.", log_name + log!( + &self.platform, + Warn, + "smoldot", + format!( + "Ignore database of {} because its genesis hash didn't match the \ + genesis hash of the chain.", + log_name + ) ) } @@ -831,11 +922,16 @@ impl Client { }; if !invalid_bootstrap_nodes_sanitized.is_empty() { - log::warn!( - target: "smoldot", - "Failed to parse some of the bootnodes of {}. \ - These bootnodes have been ignored. List: {}", - log_name, invalid_bootstrap_nodes_sanitized.join(", ") + log!( + &self.platform, + Warn, + "smoldot", + format!( + "Failed to parse some of the bootnodes of {}. \ + These bootnodes have been ignored. List: {}", + log_name, + invalid_bootstrap_nodes_sanitized.join(", ") + ) ); } @@ -844,11 +940,15 @@ impl Client { // Note the usage of the word "likely", because another chain with the same key might // have been added earlier and contains bootnodes, or we might receive an incoming // substream on a connection normally used for a different chain. - log::warn!( - target: "smoldot", - "Newly-added chain {} has an empty list of bootnodes. Smoldot will likely fail \ - to connect to its peer-to-peer network.", - log_name + log!( + &self.platform, + Warn, + "smoldot", + format!( + "Newly-added chain {} has an empty list of bootnodes. Smoldot will \ + likely fail to connect to its peer-to-peer network.", + log_name + ) ); } @@ -879,6 +979,7 @@ impl Client { { // TODO: the JSON-RPC service splits between first creation and actual services starting because starting the service couldn't be done immediately, since this is now the case considering merging the two together again let (frontend, service_starter) = json_rpc_service::service(json_rpc_service::Config { + platform: self.platform.clone(), log_name: log_name.clone(), // TODO: add a way to differentiate multiple different json-rpc services under the same chain max_pending_requests, max_subscriptions, @@ -958,7 +1059,12 @@ impl Client { let running_chain = chains_by_key.get_mut(&removed_chain.key).unwrap(); if running_chain.num_references.get() == 1 { - log::info!(target: "smoldot", "Shutting down chain {}", running_chain.log_name); + log!( + &self.platform, + Info, + "smoldot", + format!("Shutting down chain {}", running_chain.log_name) + ); chains_by_key.remove(&removed_chain.key); } else { running_chain.num_references = diff --git a/light-base/src/network_service/tasks.rs b/light-base/src/network_service/tasks.rs index 953481805c..bbbbf22d39 100644 --- a/light-base/src/network_service/tasks.rs +++ b/light-base/src/network_service/tasks.rs @@ -69,25 +69,36 @@ pub(super) async fn single_stream_connection_task( || socket_read_write.write_bytes_queued != written_bytes_before || (!write_closed && socket_read_write.write_bytes_queueable.is_none()) { - log::trace!(target: "connections", - "Connection({address_string}) <=> read={}; written={}; wake_up_after={:?}; write_close={:?}", - socket_read_write.read_bytes - read_bytes_before, - socket_read_write.write_bytes_queued - written_bytes_before, - socket_read_write.wake_up_after.as_ref().map(|w| { + log!( + &platform, + Trace, + "connections", + "connection-activity", + address = address_string, + read = socket_read_write.read_bytes - read_bytes_before, + written = socket_read_write.write_bytes_queued - written_bytes_before, + wake_up_after = ?socket_read_write.wake_up_after.as_ref().map(|w| { if *w > socket_read_write.now { w.clone() - socket_read_write.now.clone() } else { Duration::new(0, 0) } }), - socket_read_write.write_bytes_queueable.is_none(), + write_closed = socket_read_write.write_bytes_queueable.is_none(), ); } } Err(err) => { // Error on the socket. if !task.is_reset_called() { - log::trace!(target: "connections", "Connection({address_string}) => Reset(reason={err:?})"); + log!( + &platform, + Trace, + "connections", + "reset", + address = address_string, + reason = ?err + ); task.reset(); } } @@ -123,7 +134,13 @@ pub(super) async fn single_stream_connection_task( // If the connection task has self-destructed and that no message is being sent, stop // the task altogether as nothing will happen. if connection_task.is_none() && message_sending.is_none() { - log::trace!(target: "connections", "Connection({address_string}) => TaskShutdown"); + log!( + &platform, + Trace, + "connections", + "shutdown", + address = address_string + ); return; } @@ -179,7 +196,13 @@ pub(super) async fn single_stream_connection_task( connection_task.inject_coordinator_message(&platform.now(), message); } WakeUpReason::CoordinatorDead => { - log::trace!(target: "connections", "Connection({address_string}) => TaskShutdown"); + log!( + &platform, + Trace, + "connections", + "shutdown", + address = address_string + ); return; } WakeUpReason::SocketEvent => {} @@ -229,7 +252,13 @@ pub(super) async fn webrtc_multi_stream_connection_task( .desired_outbound_substreams() .saturating_sub(pending_opening_out_substreams) { - log::trace!(target: "connections", "Connection({address_string}) <= OpenSubstream"); + log!( + &platform, + Trace, + "connections", + "substream-open-start", + address = address_string + ); platform.open_out_substream(&mut connection); pending_opening_out_substreams += 1; } @@ -314,7 +343,13 @@ pub(super) async fn webrtc_multi_stream_connection_task( connection_task.inject_coordinator_message(&platform.now(), message); } WakeUpReason::CoordinatorDead => { - log::trace!(target: "connections", "Connection({address_string}) => TaskShutdown"); + log!( + &platform, + Trace, + "connections", + "shutdown", + address = address_string + ); return; } WakeUpReason::SocketEvent(mut socket, substream_id) => { @@ -334,30 +369,49 @@ pub(super) async fn webrtc_multi_stream_connection_task( || socket_read_write.write_bytes_queued != written_bytes_before || (!write_closed && socket_read_write.write_bytes_queueable.is_none()) { - log::trace!(target: "connections", - "Connection({address_string}) <=> substream_id={substream_id}; read={}; written={}; wake_up_after={:?}; write_close={:?}", - socket_read_write.read_bytes - read_bytes_before, - socket_read_write.write_bytes_queued - written_bytes_before, - socket_read_write.wake_up_after.as_ref().map(|w| { + log!( + &platform, + Trace, + "connections", + "connection-activity", + address = address_string, + read = socket_read_write.read_bytes - read_bytes_before, + written = socket_read_write.write_bytes_queued - written_bytes_before, + wake_up_after = ?socket_read_write.wake_up_after.as_ref().map(|w| { if *w > socket_read_write.now { w.clone() - socket_read_write.now.clone() } else { Duration::new(0, 0) } }), - socket_read_write.write_bytes_queueable.is_none(), + write_close = ?socket_read_write.write_bytes_queueable.is_none(), ); } if let SubstreamFate::Reset = substream_fate { - log::trace!(target: "connections", "Connection({address_string}) <= ResetSubstream(substream_id={substream_id})"); + log!( + &platform, + Trace, + "connections", + "reset-substream", + address = address_string, + substream_id + ); } substream_fate } Err(err) => { // Error on the substream. - log::trace!(target: "connections", "Connection({address_string}) => SubstreamReset(substream_id={substream_id}, error={err:?})"); + log!( + &platform, + Trace, + "connections", + "substream-reset-by-remote", + address = address_string, + substream_id, + error = ?err + ); connection_task.reset_substream(&substream_id); SubstreamFate::Reset } @@ -379,7 +433,13 @@ pub(super) async fn webrtc_multi_stream_connection_task( )); } } else { - log::trace!(target: "connections", "Connection({address_string}) => TaskShutdown"); + log!( + &platform, + Trace, + "connections", + "shutdown", + address = address_string + ); return; } @@ -397,7 +457,13 @@ pub(super) async fn webrtc_multi_stream_connection_task( WakeUpReason::MessageSent => {} WakeUpReason::ConnectionReset => { debug_assert!(!connection_task.is_reset_called()); - log::trace!(target: "connections", "Connection({address_string}) => Reset"); + log!( + &platform, + Trace, + "connections", + "reset", + address = address_string + ); connection_task.reset(); } WakeUpReason::NewSubstream(substream, direction) => { @@ -407,7 +473,15 @@ pub(super) async fn webrtc_multi_stream_connection_task( }; let substream_id = next_substream_id; next_substream_id += 1; - log::trace!(target: "connections", "Connection({address_string}) => SubstreamOpened(substream_id={substream_id}, direction={direction:?})"); + log!( + &platform, + Trace, + "connections", + "substream-opened", + address = address_string, + substream_id, + ?direction + ); connection_task.add_substream(substream_id, outbound); if outbound { pending_opening_out_substreams -= 1; diff --git a/light-base/src/platform/default.rs b/light-base/src/platform/default.rs index b99374a092..f2a37e4cd8 100644 --- a/light-base/src/platform/default.rs +++ b/light-base/src/platform/default.rs @@ -160,9 +160,17 @@ impl PlatformRef for Arc { message: fmt::Arguments<'a>, key_values: impl Iterator, ) { + let log_level = match log_level { + LogLevel::Error => log::Level::Error, + LogLevel::Warn => log::Level::Warn, + LogLevel::Info => log::Level::Info, + LogLevel::Debug => log::Level::Debug, + LogLevel::Trace => log::Level::Trace, + }; + log::logger().log( &log::RecordBuilder::new() - //.level(todo!()) + .level(log_level) .target(log_target) .args(message) .build(), diff --git a/light-base/src/sync_service.rs b/light-base/src/sync_service.rs index e6a69508e0..b497f17bc8 100644 --- a/light-base/src/sync_service.rs +++ b/light-base/src/sync_service.rs @@ -170,12 +170,13 @@ impl SyncService { } }; - config - .platform - .spawn_task(log_target.clone().into(), async move { + config.platform.spawn_task(log_target.clone().into(), { + let platform = config.platform.clone(); + async move { task.await; - log::debug!(target: &log_target, "Shutdown"); - }); + log!(&platform, Debug, &log_target, "shutdown"); + } + }); SyncService { to_background, diff --git a/light-base/src/sync_service/parachain.rs b/light-base/src/sync_service/parachain.rs index b44f143340..e463ae4965 100644 --- a/light-base/src/sync_service/parachain.rs +++ b/light-base/src/sync_service/parachain.rs @@ -339,14 +339,21 @@ impl ParachainBackgroundTask { (WakeUpReason::NewSubscription(relay_chain_subscribe_all), _) => { // Subscription to the relay chain has finished. - log::debug!( - target: &self.log_target, - "RelayChain => NewSubscription(finalized_hash={})", - HashDisplay(&header::hash_from_scale_encoded_header( + log!( + &self.platform, + Debug, + &self.log_target, + "relay-chain-new-subscription", + finalized_hash = HashDisplay(&header::hash_from_scale_encoded_header( &relay_chain_subscribe_all.finalized_block_scale_encoded_header )) ); - log::debug!(target: &self.log_target, "ParaheadFetchOperations <= Clear"); + log!( + &self.platform, + Debug, + &self.log_target, + "parahead-fetch-operations-cleared" + ); let async_tree = { let mut async_tree = @@ -460,10 +467,12 @@ impl ParachainBackgroundTask { } } - log::debug!( - target: &self.log_target, - "Subscriptions <= ParablockFinalized(hash={})", - HashDisplay(&hash) + log!( + &self.platform, + Debug, + &self.log_target, + "subscriptions-notify-parablock-finalized", + hash = HashDisplay(&hash) ); let best_block_hash = runtime_subscription @@ -532,10 +541,12 @@ impl ParachainBackgroundTask { .await; } - log::debug!( - target: &self.log_target, - "Subscriptions <= BestBlockChanged(hash={})", - HashDisplay(¶hash) + log!( + &self.platform, + Debug, + &self.log_target, + "subscriptions-notify-best-block-changed", + hash = HashDisplay(¶hash) ); // Elements in `all_subscriptions` are removed one by one and @@ -609,10 +620,12 @@ impl ParachainBackgroundTask { .await; } - log::debug!( - target: &self.log_target, - "Subscriptions <= BestBlockChanged(hash={})", - HashDisplay(¶hash) + log!( + &self.platform, + Debug, + &self.log_target, + "subscriptions-notify-best-block-changed", + hash = HashDisplay(¶hash) ); // Elements in `all_subscriptions` are removed one by one and @@ -635,10 +648,12 @@ impl ParachainBackgroundTask { continue; } - log::debug!( - target: &self.log_target, - "Subscriptions <= NewParablock(hash={})", - HashDisplay(¶hash) + log!( + &self.platform, + Debug, + &self.log_target, + "subscriptions-notify-new-parablock", + hash = HashDisplay(¶hash) ); if is_new_best { @@ -715,10 +730,12 @@ impl ParachainBackgroundTask { Box::pin(future::pending()); } async_tree::NextNecessaryAsyncOp::Ready(op) => { - log::debug!( - target: &self.log_target, - "ParaheadFetchOperations <= StartFetch(relay_block_hash={})", - HashDisplay(op.block_user_data), + log!( + &self.platform, + Debug, + &self.log_target, + "parahead-fetch-operation-started", + relay_block_hash = HashDisplay(op.block_user_data), ); runtime_subscription.in_progress_paraheads.push({ @@ -761,10 +778,12 @@ impl ParachainBackgroundTask { ParachainBackgroundState::Subscribed(runtime_subscription), ) => { // Relay chain has a new finalized block. - log::debug!( - target: &self.log_target, - "RelayChain => Finalized(hash={})", - HashDisplay(&hash) + log!( + &self.platform, + Debug, + &self.log_target, + "relay-chain-block-finalized", + hash = HashDisplay(&hash) ); let finalized = runtime_subscription @@ -792,11 +811,13 @@ impl ParachainBackgroundTask { // Relay chain has a new block. let hash = header::hash_from_scale_encoded_header(&block.scale_encoded_header); - log::debug!( - target: &self.log_target, - "RelayChain => Block(hash={}, parent_hash={})", - HashDisplay(&hash), - HashDisplay(&block.parent_hash) + log!( + &self.platform, + Debug, + &self.log_target, + "relay-chain-new-block", + hash = HashDisplay(&hash), + parent_hash = HashDisplay(&block.parent_hash) ); let parent = runtime_subscription @@ -822,10 +843,12 @@ impl ParachainBackgroundTask { ParachainBackgroundState::Subscribed(runtime_subscription), ) => { // Relay chain has a new best block. - log::debug!( - target: &self.log_target, - "RelayChain => BestBlockChanged(hash={})", - HashDisplay(&hash) + log!( + &self.platform, + Debug, + &self.log_target, + "relay-chain-best-block-changed", + hash = HashDisplay(&hash) ); // If the block isn't found in `async_tree`, assume that it is equal to the @@ -844,7 +867,12 @@ impl ParachainBackgroundTask { (WakeUpReason::SubscriptionDead, _) => { // Recreate the channel. - log::debug!(target: &self.log_target, "Subscriptions <= Reset"); + log!( + &self.platform, + Debug, + &self.log_target, + "relay-chain-subscription-reset" + ); self.subscription_state = ParachainBackgroundState::NotSubscribed { all_subscriptions: Vec::new(), subscribe_future: { @@ -869,11 +897,19 @@ impl ParachainBackgroundTask { ParachainBackgroundState::Subscribed(runtime_subscription), ) => { // A parahead fetching operation is successful. - log::debug!( - target: &self.log_target, - "ParaheadFetchOperations => Parahead(hash={}, relay_blocks={})", - HashDisplay(blake2_rfc::blake2b::blake2b(32, b"", ¶head).as_bytes()), - runtime_subscription.async_tree.async_op_blocks(async_op_id).map(|b| HashDisplay(b)).join(",") + log!( + &self.platform, + Debug, + &self.log_target, + "parahead-fetch-operation-success", + parahead_hash = HashDisplay( + blake2_rfc::blake2b::blake2b(32, b"", ¶head).as_bytes() + ), + relay_blocks = runtime_subscription + .async_tree + .async_op_blocks(async_op_id) + .map(|b| HashDisplay(b)) + .join(",") ); // Unpin the relay blocks whose parahead is now known. @@ -903,7 +939,12 @@ impl ParachainBackgroundTask { // The relay chain runtime service has some kind of gap or issue and has // discarded the runtime. // Destroy the subscription and recreate the channels. - log::debug!(target: &self.log_target, "Subscriptions <= Reset"); + log!( + &self.platform, + Debug, + &self.log_target, + "relay-chain-subscription-reset" + ); self.subscription_state = ParachainBackgroundState::NotSubscribed { all_subscriptions: Vec::new(), subscribe_future: { @@ -943,19 +984,33 @@ impl ParachainBackgroundTask { .await && !error.is_network_problem() { - log::error!( - target: &self.log_target, - "Failed to fetch the parachain head from relay chain blocks {}: {}", - runtime_subscription.async_tree.async_op_blocks(async_op_id).map(|b| HashDisplay(b)).join(", "), - error + log!( + &self.platform, + Error, + &self.log_target, + format!( + "Failed to fetch the parachain head from relay chain blocks {}: {}", + runtime_subscription + .async_tree + .async_op_blocks(async_op_id) + .map(|b| HashDisplay(b)) + .join(", "), + error + ) ); } - log::debug!( - target: &self.log_target, - "ParaheadFetchOperations => Error(relay_blocks={}, error={:?})", - runtime_subscription.async_tree.async_op_blocks(async_op_id).map(|b| HashDisplay(b)).join(","), - error + log!( + &self.platform, + Debug, + &self.log_target, + "parahead-fetch-operation-error", + relay_blocks = runtime_subscription + .async_tree + .async_op_blocks(async_op_id) + .map(|b| HashDisplay(b)) + .join(","), + ?error ); runtime_subscription diff --git a/light-base/src/transactions_service.rs b/light-base/src/transactions_service.rs index cb6a4e327e..e31b91362a 100644 --- a/light-base/src/transactions_service.rs +++ b/light-base/src/transactions_service.rs @@ -167,12 +167,13 @@ impl TransactionsService { from_foreground, )); - config - .platform - .spawn_task(log_target.clone().into(), async move { + config.platform.spawn_task(log_target.clone().into(), { + let platform = config.platform.clone(); + async move { task.await; - log::debug!(target: &log_target, "Shutdown"); - }); + log!(&platform, Debug, &log_target, "shutdown"); + } + }); TransactionsService { to_background: async_lock::Mutex::new(to_background), @@ -237,9 +238,9 @@ impl TransactionsService { // Sleep for a bit in order to avoid potential infinite loops // of repeated crashing. platform.sleep(Duration::from_secs(2)).await; - log::debug!(target: &log_target, "Restart"); + log!(&platform, Debug, &log_target, "restart"); task.await; - log::debug!(target: &log_target, "Shutdown"); + log!(&platform, Debug, &log_target, "shutdown"); }, ); *lock = tx; @@ -520,10 +521,12 @@ async fn background_task( worker.validations_in_progress.clear(); worker.next_reannounce.clear(); - log::debug!( - target: &config.log_target, - "Reset(new_finalized={}. dropped-transactions={{{}}})", - HashDisplay(&initial_finalized_block_hash), + log!( + &worker.platform, + Debug, + &config.log_target, + "reset", + new_finalized = HashDisplay(&initial_finalized_block_hash), dropped_transactions ); @@ -572,6 +575,7 @@ async fn background_task( // Make copies of everything in order to move the values into the future. let runtime_service = worker.runtime_service.clone(); + let platform = worker.platform.clone(); let log_target = config.log_target.clone(); let relay_chain_sync_subscription_id = subscribe_all.new_blocks.id(); let scale_encoded_transaction = worker @@ -582,6 +586,7 @@ async fn background_task( // TODO: race condition /!\ the block could be pruned and unpinned before this future starts executing async move { let result = validate_transaction( + &platform, &log_target, &runtime_service, relay_chain_sync_subscription_id, @@ -632,11 +637,13 @@ async fn background_task( let (tx_body, mut transaction) = worker.pending_transactions.remove_transaction(tx_id); - log::debug!( - target: &config.log_target, - "Discarded(tx_hash={}, error={:?})", - HashDisplay(&blake2_hash(&tx_body)), - error, + log!( + &worker.platform, + Debug, + &config.log_target, + "discarded", + tx_hash = HashDisplay(&blake2_hash(&tx_body)), + ?error ); transaction.update_status(TransactionStatus::Dropped(match error { @@ -709,10 +716,12 @@ async fn background_task( .unwrap() .downloading = true; - log::debug!( - target: &config.log_target, - "BlockDownloads <= Start(block={})", - HashDisplay(&block_hash) + log!( + &worker.platform, + Debug, + &config.log_target, + "blocks-download-started", + block = HashDisplay(&block_hash) ); } @@ -722,11 +731,13 @@ async fn background_task( // Unpin them when they're removed. subscribe_all.new_blocks.unpin_block(block.block_hash).await; - log::debug!( - target: &config.log_target, - "Finalized(block={}, body-transactions={{{}}})", - HashDisplay(&block.block_hash), - block + log!( + &worker.platform, + Debug, + &config.log_target, + "finalized", + block = HashDisplay(&block.block_hash), + body_transactions = block .included_transactions .iter() .map(|tx| HashDisplay(&blake2_hash(&tx.scale_encoding)).to_string()) @@ -865,12 +876,18 @@ async fn background_task( .set_block_body(&block_hash, block_body.into_iter()) .collect::>(); - log::debug!( - target: &config.log_target, - "BlockDownloads => Success(block={}, included-transactions={{{}}})", - HashDisplay(&block_hash), - included_transactions.iter() - .map(|(id, _)| HashDisplay(&blake2_hash(worker.pending_transactions.scale_encoding(*id).unwrap())).to_string()) + log!( + &worker.platform, + Debug, + &config.log_target, + "blocks-download-success", + block = HashDisplay(&block_hash), + included_transactions = included_transactions + .iter() + .map(|(id, _)| HashDisplay(&blake2_hash( + worker.pending_transactions.scale_encoding(*id).unwrap() + )) + .to_string()) .join(", ") ); @@ -888,10 +905,12 @@ async fn background_task( } } else { block.failed_downloads = block.failed_downloads.saturating_add(1); - log::debug!( - target: &config.log_target, - "BlockDownloads => Failed(block={})", - HashDisplay(&block_hash) + log!( + &worker.platform, + Debug, + &config.log_target, + "blocks-download-failure", + block = HashDisplay(&block_hash) ); } } @@ -957,11 +976,18 @@ async fn background_task( .unwrap(), ) .await; - log::debug!( - target: &config.log_target, - "NetworkService <= Announced(tx={}, peers={{{}}})", - HashDisplay(&blake2_hash(worker.pending_transactions.scale_encoding(maybe_reannounce_tx_id).unwrap())), - peers_sent.iter().join(", ") + log!( + &worker.platform, + Debug, + &config.log_target, + "announced-to-network", + transaction = HashDisplay(&blake2_hash( + worker + .pending_transactions + .scale_encoding(maybe_reannounce_tx_id) + .unwrap() + )), + peers = peers_sent.iter().join(", ") ); // TODO: is this correct? and what should we do if announcing the same transaction multiple times? is it cumulative? `Broadcast` isn't super well documented @@ -1013,31 +1039,39 @@ async fn background_task( // possible for the validation to have been performed against a block // that has already been finalized and removed from the pool. if !worker.pending_transactions.has_block(&block_hash) { - log::debug!( - target: &config.log_target, - "TxValidations => ObsoleteBlock(tx={}, block={})", - HashDisplay(&tx_hash), - HashDisplay(&block_hash) + log!( + &worker.platform, + Debug, + &config.log_target, + "transaction-validation-obsolete-block", + transaction = HashDisplay(&tx_hash), + block = HashDisplay(&block_hash) ); continue; } let validation_result = match validation_result { Ok(result) => { - log::debug!( - target: &config.log_target, - "TxValidations => Success(tx={}, block={}, priority={}, longevity={}, propagate={:?})", - HashDisplay(&tx_hash), - HashDisplay(&block_hash), - result.priority, - result.longevity, - result.propagate, + log!( + &worker.platform, + Debug, + &config.log_target, + "transaction-validation-success", + transaction = HashDisplay(&tx_hash), + block = HashDisplay(&block_hash), + priority = result.priority, + longevity = result.longevity, + propagate = ?result.propagate, ); - log::info!( - target: &config.log_target, - "Successfully validated transaction {}", - HashDisplay(&tx_hash) + log!( + &worker.platform, + Info, + &config.log_target, + format!( + "Successfully validated transaction {}", + HashDisplay(&tx_hash) + ) ); worker @@ -1059,20 +1093,26 @@ async fn background_task( continue 'channels_rebuild; } Err(ValidationError::InvalidOrError(InvalidOrError::Invalid(error))) => { - log::debug!( - target: &config.log_target, - "TxValidations => Invalid(tx={}, block={}, error={:?})", - HashDisplay(&tx_hash), - HashDisplay(&block_hash), - error, + log!( + &worker.platform, + Debug, + &config.log_target, + "transaction-validation-invalid-tx", + transaction = HashDisplay(&tx_hash), + block = HashDisplay(&block_hash), + ?error, ); - log::warn!( - target: &config.log_target, - "Transaction {} invalid against block {}: {}", - HashDisplay(&tx_hash), - HashDisplay(&block_hash), - error, + log!( + &worker.platform, + Warn, + &config.log_target, + format!( + "Transaction {} invalid against block {}: {}", + HashDisplay(&tx_hash), + HashDisplay(&block_hash), + error, + ) ); Err(InvalidOrError::Invalid(error)) @@ -1080,19 +1120,25 @@ async fn background_task( Err(ValidationError::InvalidOrError(InvalidOrError::ValidateError( error, ))) => { - log::debug!( - target: &config.log_target, - "TxValidations => Error(tx={}, block={}, error={:?})", - HashDisplay(&tx_hash), - HashDisplay(&block_hash), - error, + log!( + &worker.platform, + Debug, + &config.log_target, + "transaction-validation-error", + transaction = HashDisplay(&tx_hash), + block = HashDisplay(&block_hash), + ?error, ); - log::warn!( - target: &config.log_target, - "Failed to validate transaction {}: {}", - HashDisplay(&tx_hash), - error + log!( + &worker.platform, + Warn, + &config.log_target, + format!( + "Failed to validate transaction {}: {}", + HashDisplay(&tx_hash), + error + ) ); Err(InvalidOrError::ValidateError(error)) @@ -1239,15 +1285,27 @@ impl Worker { // In that situation we need to first signal `Retracted`, then only `InBlock`. // Consequently, process `retracted_transactions` first. - log::debug!( - target: log_target, - "BestChainUpdate(new-best-block={}, included-transactions={{{}}}, retracted-transactions={{{}}})", - HashDisplay(new_best_block_hash), - updates.included_transactions.iter() - .map(|(id, _, _)| HashDisplay(&blake2_hash(self.pending_transactions.scale_encoding(*id).unwrap())).to_string()) + log!( + &self.platform, + Debug, + &log_target, + "best-chain-update", + new_best_block = HashDisplay(new_best_block_hash), + included_transactions = updates + .included_transactions + .iter() + .map(|(id, _, _)| HashDisplay(&blake2_hash( + self.pending_transactions.scale_encoding(*id).unwrap() + )) + .to_string()) .join(", "), - updates.retracted_transactions.iter() - .map(|(id, _, _)| HashDisplay(&blake2_hash(self.pending_transactions.scale_encoding(*id).unwrap())).to_string()) + retracted_transactions = updates + .retracted_transactions + .iter() + .map(|(id, _, _)| HashDisplay(&blake2_hash( + self.pending_transactions.scale_encoding(*id).unwrap() + )) + .to_string()) .join(", ") ); @@ -1338,6 +1396,7 @@ impl PendingTransaction { /// /// Returns the result of the validation, and the hash of the block it was validated against. async fn validate_transaction( + platform: &TPlat, log_target: &str, relay_chain_sync: &Arc>, relay_chain_sync_subscription_id: runtime_service::SubscriptionId, @@ -1357,12 +1416,14 @@ async fn validate_transaction( }; // TODO: move somewhere else? - log::debug!( - target: log_target, - "TxValidations <= Start(tx={}, block={}, block_height={})", - HashDisplay(&blake2_hash(scale_encoded_transaction.as_ref())), - HashDisplay(runtime_lock.block_hash()), - header::decode( + log!( + platform, + Debug, + &log_target, + "transaction-validation-started", + transaction = HashDisplay(&blake2_hash(scale_encoded_transaction.as_ref())), + block = HashDisplay(runtime_lock.block_hash()), + block_height = header::decode( block_scale_encoded_header, relay_chain_sync.block_number_bytes() ) From 5c9acd7d1bbc898521660b3fb9af473857aee470 Mon Sep 17 00:00:00 2001 From: Pierre Krieger Date: Fri, 5 Jan 2024 14:29:20 +0100 Subject: [PATCH 03/14] Update wasm-node --- Cargo.lock | 1 - wasm-node/rust/Cargo.toml | 1 - wasm-node/rust/src/init.rs | 137 +++++++++++++-------------------- wasm-node/rust/src/platform.rs | 97 ++++++++++++++++++----- 4 files changed, 130 insertions(+), 106 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index b04ff61ab5..c2d7cc8463 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2355,7 +2355,6 @@ dependencies = [ "futures-lite", "futures-util", "hashbrown 0.14.3", - "log", "no-std-net", "nom", "pin-project", diff --git a/wasm-node/rust/Cargo.toml b/wasm-node/rust/Cargo.toml index a3d1fcfc47..3a7b639704 100644 --- a/wasm-node/rust/Cargo.toml +++ b/wasm-node/rust/Cargo.toml @@ -26,7 +26,6 @@ fnv = { version = "1.0.7", default-features = false } futures-lite = { version = "2.0.0", default-features = false, features = ["alloc"] } futures-util = { version = "0.3.27", default-features = false } hashbrown = { version = "0.14.0", default-features = false } -log = { version = "0.4.18", default-features = false } nom = { version = "7.1.3", default-features = false } no-std-net = { version = "0.6.0", default-features = false } pin-project = "1.1.3" diff --git a/wasm-node/rust/src/init.rs b/wasm-node/rust/src/init.rs index 80be5a1b86..a505d3b2e9 100644 --- a/wasm-node/rust/src/init.rs +++ b/wasm-node/rust/src/init.rs @@ -17,8 +17,8 @@ use crate::{allocator, bindings, platform, timers::Delay}; -use alloc::{boxed::Box, format, string::String}; -use core::{sync::atomic::Ordering, time::Duration}; +use alloc::{boxed::Box, string::String}; +use core::{iter, sync::atomic::Ordering, time::Duration}; use futures_util::stream; use smoldot::informant::BytesDisplay; use smoldot_light::platform::PlatformRef; @@ -55,70 +55,64 @@ pub(crate) enum Chain { } pub(crate) fn init(max_log_level: u32) { - // Try initialize the logging. - if let Ok(_) = log::set_logger(&LOGGER) { - log::set_max_level(match max_log_level { - 0 => log::LevelFilter::Off, - 1 => log::LevelFilter::Error, - 2 => log::LevelFilter::Warn, - 3 => log::LevelFilter::Info, - 4 => log::LevelFilter::Debug, - _ => log::LevelFilter::Trace, - }) - } - - // First things first, print the version in order to make it easier to debug issues by - // reading logs provided by third parties. - log::info!( - target: "smoldot", - "Smoldot v{}", - env!("CARGO_PKG_VERSION") + // First things first, initialize the maximum log level. + platform::MAX_LOG_LEVEL.store(max_log_level, Ordering::SeqCst); + + // Print the version in order to make it easier to debug issues by reading logs provided by + // third parties. + platform::PLATFORM_REF.log( + smoldot_light::platform::LogLevel::Info, + "smoldot", + format_args!("Smoldot v{}", env!("CARGO_PKG_VERSION")), + iter::empty(), ); // Spawn a constantly-running task that periodically prints the total memory usage of // the node. - platform::PLATFORM_REF.spawn_task( - "memory-printer".into(), - async move { - let mut previous_read_bytes = 0; - let mut previous_sent_bytes = 0; - let interval = 60; - - loop { - Delay::new(Duration::from_secs(interval)).await; - - // For the unwrap below to fail, the quantity of allocated would have to - // not fit in a `u64`, which as of 2021 is basically impossible. - let mem = u64::try_from(allocator::total_alloc_bytes()).unwrap(); - - // Due to the way the calculation below is performed, sending or receiving - // more than `type_of(TOTAL_BYTES_RECEIVED or TOTAL_BYTES_SENT)::max_value` - // bytes within an interval will lead to an erroneous value being shown to the - // user. At the time of writing of this comment, they are 64bits, so we just - // assume that this can't happen. If it does happen, the fix would consist in - // increasing the size of `TOTAL_BYTES_RECEIVED` or `TOTAL_BYTES_SENT`. - - let bytes_rx = platform::TOTAL_BYTES_RECEIVED.load(Ordering::Relaxed); - let avg_dl = bytes_rx.wrapping_sub(previous_read_bytes) / interval; - previous_read_bytes = bytes_rx; - - let bytes_tx = platform::TOTAL_BYTES_SENT.load(Ordering::Relaxed); - let avg_up = bytes_tx.wrapping_sub(previous_sent_bytes) / interval; - previous_sent_bytes = bytes_tx; - - // Note that we also print the version at every interval, in order to increase - // the chance of being able to know the version in case of truncated logs. - log::info!( - target: "smoldot", - "Smoldot v{}. Current memory usage: {}. Average download: {}/s. Average upload: {}/s.", + platform::PLATFORM_REF.spawn_task("memory-printer".into(), async move { + let mut previous_read_bytes = 0; + let mut previous_sent_bytes = 0; + let interval = 60; + + loop { + Delay::new(Duration::from_secs(interval)).await; + + // For the unwrap below to fail, the quantity of allocated would have to + // not fit in a `u64`, which as of 2021 is basically impossible. + let mem = u64::try_from(allocator::total_alloc_bytes()).unwrap(); + + // Due to the way the calculation below is performed, sending or receiving + // more than `type_of(TOTAL_BYTES_RECEIVED or TOTAL_BYTES_SENT)::max_value` + // bytes within an interval will lead to an erroneous value being shown to the + // user. At the time of writing of this comment, they are 64bits, so we just + // assume that this can't happen. If it does happen, the fix would consist in + // increasing the size of `TOTAL_BYTES_RECEIVED` or `TOTAL_BYTES_SENT`. + + let bytes_rx = platform::TOTAL_BYTES_RECEIVED.load(Ordering::Relaxed); + let avg_dl = bytes_rx.wrapping_sub(previous_read_bytes) / interval; + previous_read_bytes = bytes_rx; + + let bytes_tx = platform::TOTAL_BYTES_SENT.load(Ordering::Relaxed); + let avg_up = bytes_tx.wrapping_sub(previous_sent_bytes) / interval; + previous_sent_bytes = bytes_tx; + + // Note that we also print the version at every interval, in order to increase + // the chance of being able to know the version in case of truncated logs. + platform::PLATFORM_REF.log( + smoldot_light::platform::LogLevel::Info, + "smoldot", + format_args!( + "Smoldot v{}. Current memory usage: {}. \ + Average download: {}/s. Average upload: {}/s.", env!("CARGO_PKG_VERSION"), BytesDisplay(mem), BytesDisplay(avg_dl), BytesDisplay(avg_up) - ); - } - }, - ); + ), + iter::empty(), + ); + } + }); } /// Stops execution, providing a string explaining what happened. @@ -142,30 +136,3 @@ fn panic(info: &core::panic::PanicInfo) -> ! { unreachable!(); } } - -/// Implementation of [`log::Log`] that sends out logs to the FFI. -struct Logger; -static LOGGER: Logger = Logger; - -impl log::Log for Logger { - fn enabled(&self, _: &log::Metadata) -> bool { - true - } - - fn log(&self, record: &log::Record) { - let target = record.target(); - let message = format!("{}", record.args()); - - unsafe { - bindings::log( - record.level() as usize as u32, - u32::try_from(target.as_bytes().as_ptr() as usize).unwrap(), - u32::try_from(target.as_bytes().len()).unwrap(), - u32::try_from(message.as_bytes().as_ptr() as usize).unwrap(), - u32::try_from(message.as_bytes().len()).unwrap(), - ) - } - } - - fn flush(&self) {} -} diff --git a/wasm-node/rust/src/platform.rs b/wasm-node/rust/src/platform.rs index 7e55f7c4ff..de7c088cc7 100644 --- a/wasm-node/rust/src/platform.rs +++ b/wasm-node/rust/src/platform.rs @@ -30,8 +30,9 @@ use alloc::{ }; use async_lock::Mutex; use core::{ + fmt::{self, Write as _}, future, iter, mem, ops, pin, str, - sync::atomic::{AtomicU64, Ordering}, + sync::atomic::{AtomicU32, AtomicU64, Ordering}, task, time::Duration, }; @@ -45,6 +46,9 @@ pub static TOTAL_BYTES_SENT: AtomicU64 = AtomicU64::new(0); pub(crate) const PLATFORM_REF: PlatformRef = PlatformRef {}; +/// Log level above which log entries aren't emitted. +pub static MAX_LOG_LEVEL: AtomicU32 = AtomicU32::new(0); + #[derive(Debug, Copy, Clone)] pub(crate) struct PlatformRef {} @@ -145,18 +149,33 @@ impl smoldot_light::platform::PlatformRef for PlatformRef { // For this reason, the threshold above which a task takes too long must be // above 16ms no matter what. if poll_duration.as_millis() >= 20 { - log::debug!( - "Tasks({}) => LongPoll({}ms)", - this.name, - poll_duration.as_millis(), + smoldot_light::platform::PlatformRef::log( + &PLATFORM_REF, + smoldot_light::platform::LogLevel::Debug, + "smoldot", + format_args!("task-too-long-time"), + [ + ("name", this.name as &dyn fmt::Display), + ( + "poll_duration_ms", + &poll_duration.as_millis() as &dyn fmt::Display, + ), + ] + .into_iter(), ); } if poll_duration.as_millis() >= 150 { - log::warn!( - "The task named `{}` has occupied the CPU for an unreasonable amount \ - of time ({}ms).", - this.name, - poll_duration.as_millis(), + smoldot_light::platform::PlatformRef::log( + &PLATFORM_REF, + smoldot_light::platform::LogLevel::Warn, + "smoldot", + format_args!( + "The task named `{}` has occupied the CPU for an \ + unreasonable amount of time ({}ms).", + this.name, + poll_duration.as_millis(), + ), + iter::empty(), ); } @@ -182,19 +201,59 @@ impl smoldot_light::platform::PlatformRef for PlatformRef { fn log<'a>( &self, - log_level: LogLevel, + log_level: smoldot_light::platform::LogLevel, log_target: &'a str, message: fmt::Arguments<'a>, key_values: impl Iterator, ) { - // TODO: - log::logger().log( - &log::RecordBuilder::new() - //.level(todo!()) - .target(log_target) - .args(message) - .build(), - ) + let log_level = match log_level { + smoldot_light::platform::LogLevel::Error => 1, + smoldot_light::platform::LogLevel::Warn => 2, + smoldot_light::platform::LogLevel::Info => 3, + smoldot_light::platform::LogLevel::Debug => 4, + smoldot_light::platform::LogLevel::Trace => 5, + }; + + if log_level > MAX_LOG_LEVEL.load(Ordering::Relaxed) { + return; + } + + let mut key_values = key_values.peekable(); + + if let (Some(static_message), None) = (message.as_str(), key_values.peek()) { + unsafe { + bindings::log( + log_level, + u32::try_from(log_target.as_bytes().as_ptr() as usize).unwrap(), + u32::try_from(log_target.as_bytes().len()).unwrap(), + u32::try_from(static_message.as_bytes().as_ptr() as usize).unwrap(), + u32::try_from(static_message.as_bytes().len()).unwrap(), + ) + } + } else { + let mut message_build = String::with_capacity(128); + let _ = write!(message_build, "{}", message); + let mut first = true; + for (key, value) in key_values { + if first { + let _ = write!(message_build, "; "); + first = false; + } else { + let _ = write!(message_build, ", "); + } + let _ = write!(message_build, "{}={}", key, value); + } + + unsafe { + bindings::log( + log_level, + u32::try_from(log_target.as_bytes().as_ptr() as usize).unwrap(), + u32::try_from(log_target.as_bytes().len()).unwrap(), + u32::try_from(message_build.as_bytes().as_ptr() as usize).unwrap(), + u32::try_from(message_build.as_bytes().len()).unwrap(), + ) + } + } } fn client_name(&self) -> Cow { From e83ebc2733e140b0e0fd8c0d813c827096083a3d Mon Sep 17 00:00:00 2001 From: Pierre Krieger Date: Fri, 5 Jan 2024 15:16:38 +0100 Subject: [PATCH 04/14] Continue updating log statements --- light-base/src/network_service.rs | 404 ++++++++++++++-------- light-base/src/sync_service/parachain.rs | 2 +- light-base/src/sync_service/standalone.rs | 214 ++++++++---- 3 files changed, 399 insertions(+), 221 deletions(-) diff --git a/light-base/src/network_service.rs b/light-base/src/network_service.rs index c236690092..75f5fe71cd 100644 --- a/light-base/src/network_service.rs +++ b/light-base/src/network_service.rs @@ -1079,7 +1079,13 @@ async fn background_task(mut task: BackgroundTask) { )))), ) as Pin>); - log::debug!(target: "network", "Chains <= AddChain(id={})", task.network[chain_id].log_name); + log!( + &task.platform, + Debug, + "network", + "chain-added", + id = task.network[chain_id].log_name + ); } WakeUpReason::EventSendersReady => { // Dispatch the pending event, if any, to the various senders. @@ -1185,7 +1191,13 @@ async fn background_task(mut task: BackgroundTask) { .remove(&(task.network[chain_id].next_discovery_when.clone(), chain_id)); debug_assert!(_was_in.is_some()); - log::debug!(target: "network", "Chains <= RemoveChain(id={})", task.network[chain_id].log_name); + log!( + &task.platform, + Debug, + "network", + "chain-removed", + id = task.network[chain_id].log_name + ); task.network.remove_chain(chain_id).unwrap(); task.peering_strategy.remove_chain_peers(&chain_id); } @@ -1215,13 +1227,16 @@ async fn background_task(mut task: BackgroundTask) { ); if had_slot { - log::debug!( - target: "network", - "Slots({}) ∌ {} (reason=user-ban, ban-duration={:?}, user-reason={})", - &task.network[chain_id].log_name, + log!( + &task.platform, + Debug, + "network", + "slot-unassigned", + chain = &task.network[chain_id].log_name, peer_id, - ban_duration, - reason + ?ban_duration, + reason = "user-ban", + user_reason = reason ); task.network.gossip_remove_desired( chain_id, @@ -1242,10 +1257,12 @@ async fn background_task(mut task: BackgroundTask) { ); debug_assert!(_closed_result.is_ok()); - log::debug!( - target: "network", - "Gossip({}, {}) => Closed", - &task.network[chain_id].log_name, + log!( + &task.platform, + Debug, + "network", + "gossip-closed", + chain = &task.network[chain_id].log_name, peer_id, ); @@ -1267,23 +1284,29 @@ async fn background_task(mut task: BackgroundTask) { ) => { match &config.start { codec::BlocksRequestConfigStart::Hash(hash) => { - log::debug!( - target: "network", - "Connections({}) <= BlocksRequest(chain={}, start={}, num={}, descending={:?}, header={:?}, body={:?}, justifications={:?})", - target, task.network[chain_id].log_name, HashDisplay(hash), - config.desired_count.get(), - matches!(config.direction, codec::BlocksRequestDirection::Descending), - config.fields.header, config.fields.body, config.fields.justifications + log!( + &task.platform, + Debug, + "network", + "blocks-request-started", + chain = task.network[chain_id].log_name, target, + start = HashDisplay(hash), + num = config.desired_count.get(), + descending = ?matches!(config.direction, codec::BlocksRequestDirection::Descending), + header = ?config.fields.header, body = ?config.fields.body, + justifications = ?config.fields.justifications ); } codec::BlocksRequestConfigStart::Number(number) => { - log::debug!( - target: "network", - "Connections({}) <= BlocksRequest(chain={}, start=#{}, num={}, descending={:?}, header={:?}, body={:?}, justifications={:?})", - target, task.network[chain_id].log_name, number, - config.desired_count.get(), - matches!(config.direction, codec::BlocksRequestDirection::Descending), - config.fields.header, config.fields.body, config.fields.justifications + log!( + &task.platform, + Debug, + "network", + "blocks-request-started", + chain = task.network[chain_id].log_name, target, start = number, + num = config.desired_count.get(), + descending = ?matches!(config.direction, codec::BlocksRequestDirection::Descending), + header = ?config.fields.header, body = ?config.fields.body, justifications = ?config.fields.justifications ); } } @@ -1296,11 +1319,14 @@ async fn background_task(mut task: BackgroundTask) { task.blocks_requests.insert(substream_id, result); } Err(service::StartRequestError::NoConnection) => { - log::debug!( - target: "network", - "Connections({}) => BlocksRequest(chain={}, error=NoConnection)", + log!( + &task.platform, + Debug, + "network", + "blocks-request-error", + chain = task.network[chain_id].log_name, target, - task.network[chain_id].log_name, + error = "NoConnection" ); let _ = result.send(Err(BlocksRequestError::NoConnection)); } @@ -1441,12 +1467,14 @@ async fn background_task(mut task: BackgroundTask) { chain_id, ToBackgroundChain::SetLocalGrandpaState { grandpa_state }, ) => { - log::debug!( - target: "network", - "Chain({}) <= SetLocalGrandpaState(set_id: {}, commit_finalized_height: {})", - task.network[chain_id].log_name, - grandpa_state.set_id, - grandpa_state.commit_finalized_height, + log!( + &task.platform, + Debug, + "network", + "local-grandpa-state-announced", + chain = task.network[chain_id].log_name, + set_id = grandpa_state.set_id, + commit_finalized_height = grandpa_state.commit_finalized_height, ); // TODO: log the list of peers we sent the packet to @@ -1484,14 +1512,17 @@ async fn background_task(mut task: BackgroundTask) { } } - log::debug!( - target: "network", - "Chain({}) <= AnnounceTransaction(hash={}, len={}, peers_sent={}, peers_queue_full={})", - task.network[chain_id].log_name, - hex::encode(blake2_rfc::blake2b::blake2b(32, &[], &transaction).as_bytes()), - transaction.len(), - peers_sent.join(", "), - peers_queue_full.join(", "), + log!( + &task.platform, + Debug, + "network", + "transaction-announced", + chain = task.network[chain_id].log_name, + transaction = + hex::encode(blake2_rfc::blake2b::blake2b(32, &[], &transaction).as_bytes()), + size = transaction.len(), + peers_sent = peers_sent.join(", "), + peers_queue_full = peers_queue_full.join(", "), ); let _ = result.send(peers_to_send); @@ -1606,18 +1637,22 @@ async fn background_task(mut task: BackgroundTask) { Err(service::StartRequestError::NoConnection) => unreachable!(), }; - log::debug!( - target: "network", - "Discovery({}) => FindNode(request_target={}, requested_peer_id={})", - &task.network[chain_id].log_name, - target, - random_peer_id + log!( + &task.platform, + Debug, + "network", + "discovery-find-node-started", + chain = &task.network[chain_id].log_name, + request_target = target, + requested_peer_id = random_peer_id ); } else { - log::debug!( - target: "network", - "Discovery({}) => NoPeer", - &task.network[chain_id].log_name + log!( + &task.platform, + Debug, + "network", + "discovery-skipped-no-peer", + chain = &task.network[chain_id].log_name ); } } @@ -1630,7 +1665,15 @@ async fn background_task(mut task: BackgroundTask) { Multiaddr::from_bytes(task.network.connection_remote_addr(id)).unwrap(); // TODO: review this unwrap if let Some(expected_peer_id) = expected_peer_id.as_ref().filter(|p| **p != peer_id) { - log::debug!(target: "network", "Connections({}, {}) => HandshakePeerIdMismatch(actual={})", expected_peer_id, remote_addr, peer_id); + log!( + &task.platform, + Debug, + "network", + "handshake-finished-peer-id-mismatch", + remote_addr, + expected_peer_id, + actual_peer_id = peer_id + ); let _was_in = task .peering_strategy @@ -1645,7 +1688,14 @@ async fn background_task(mut task: BackgroundTask) { 10, ); } else { - log::debug!(target: "network", "Connections({}, {}) => HandshakeFinished", peer_id, remote_addr); + log!( + &task.platform, + Debug, + "network", + "handshake-finished", + remote_addr, + peer_id + ); } } WakeUpReason::NetworkEvent(service::Event::PreHandshakeDisconnected { @@ -1671,7 +1721,15 @@ async fn background_task(mut task: BackgroundTask) { .decrease_address_connections(&peer_id, &address) .unwrap(); let address = Multiaddr::from_bytes(address).unwrap(); - log::debug!(target: "network", "Connections({}, {}) => Shutdown(handshake_finished={handshake_finished:?})", peer_id, address); + log!( + &task.platform, + Debug, + "network", + "connection-shutdown", + peer_id, + address, + ?handshake_finished + ); // Ban the peer in order to avoid trying over and over again the same address(es). // Even if the handshake was finished, it is possible that the peer simply shuts @@ -1693,12 +1751,15 @@ async fn background_task(mut task: BackgroundTask) { what_happened, basic_peering_strategy::UnassignSlotsAndBan::Banned { had_slot: true } ) { - log::debug!( - target: "network", - "Slots({}) ∌ {} (reason=pre-handshake-disconnect, ban-duration={:?})", - &task.network[chain_id].log_name, + log!( + &task.platform, + Debug, + "network", + "slot-unassigned", + chain = &task.network[chain_id].log_name, peer_id, - ban_duration + ?ban_duration, + reason = "pre-handshake-disconnect" ); } } @@ -1828,12 +1889,15 @@ async fn background_task(mut task: BackgroundTask) { }; if had_slot { - log::debug!( - target: "network", - "Slots({}) ∌ {} (reason=gossip-open-failed, ban-duration={:?})", - &task.network[chain_id].log_name, + log!( + &task.platform, + Debug, + "network", + "slot-unassigned", + chain = &task.network[chain_id].log_name, peer_id, - ban_duration + ?ban_duration, + reason = "gossip-open-failed" ); task.network.gossip_remove_desired( chain_id, @@ -1847,10 +1911,12 @@ async fn background_task(mut task: BackgroundTask) { chain_id, kind: service::GossipKind::ConsensusTransactions, }) => { - log::debug!( - target: "network", - "Gossip({}, {}) => Closed", - &task.network[chain_id].log_name, + log!( + &task.platform, + Debug, + "network", + "gossip-closed", + chain = &task.network[chain_id].log_name, peer_id, ); let ban_duration = Duration::from_secs(10); @@ -1868,12 +1934,15 @@ async fn background_task(mut task: BackgroundTask) { ), basic_peering_strategy::UnassignSlotAndBan::Banned { had_slot: true } ) { - log::debug!( - target: "network", - "Slots({}) ∌ {} (reason=gossip-closed, ban-duration={:?})", - &task.network[chain_id].log_name, + log!( + &task.platform, + Debug, + "network", + "slot-unassigned", + chain = &task.network[chain_id].log_name, peer_id, - ban_duration + ?ban_duration, + reason = "gossip-closed" ); task.network.gossip_remove_desired( chain_id, @@ -2067,23 +2136,29 @@ async fn background_task(mut task: BackgroundTask) { { valid_addrs.push(a) } else { - log::debug!( - target: "network", - "Discovery({}) => UnsupportedAddress(peer_id={}, addr={}, obtained_from={requestee_peer_id})", - &task.network[chain_id].log_name, + log!( + &task.platform, + Debug, + "network", + "discovered-address-not-supported", + chain = &task.network[chain_id].log_name, peer_id, - &a + addr = &a, + obtained_from = requestee_peer_id ); } } - Err((err, addr)) => { - log::debug!( - target: "network", - "Discovery({}) => InvalidAddress(peer_id={}, error={}, addr={}, obtained_from={requestee_peer_id})", - &task.network[chain_id].log_name, + Err((error, addr)) => { + log!( + &task.platform, + Debug, + "network", + "discovered-address-invalid", + chain = &task.network[chain_id].log_name, peer_id, - err, - hex::encode(&addr) + error, + addr = hex::encode(&addr), + obtained_from = requestee_peer_id ); } } @@ -2101,18 +2176,25 @@ async fn background_task(mut task: BackgroundTask) { } = insert_outcome { if let Some(peer_removed) = peer_removed { - log::debug!( - target: "network", "Discovery({}) => PeerPurged(peer_id={})", - &task.network[chain_id].log_name, - peer_removed, + log!( + &task.platform, + Debug, + "network", + "peer-purged-from-address-book", + chain = &task.network[chain_id].log_name, + peer_id = peer_removed, ); } - log::debug!( - target: "network", "Discovery({}) => NewPeer(peer_id={}, addr={}, obtained_from={requestee_peer_id})", - &task.network[chain_id].log_name, + log!( + &task.platform, + Debug, + "network", + "peer-discovered", + chain = &task.network[chain_id].log_name, peer_id, - valid_addrs.iter().map(|a| a.to_string()).join(", addr=") + addrs = ?valid_addrs.iter().map(|a| a.to_string()).collect::>(), // TODO: better formatting? + obtained_from = requestee_peer_id ); } } @@ -2134,11 +2216,14 @@ async fn background_task(mut task: BackgroundTask) { response: service::RequestResult::KademliaFindNode(Err(error)), .. }) => { - log::debug!( - target: "network", - "Discovery({}) => FindNodeError(error={:?}, find_node_target={peer_id})", - &task.network[chain_id].log_name, - error + log!( + &task.platform, + Debug, + "network", + "discovery-find-node-error", + chain = &task.network[chain_id].log_name, + ?error, + find_node_target = peer_id, ); // No error is printed if the request fails due to a benign networking error such @@ -2191,11 +2276,14 @@ async fn background_task(mut task: BackgroundTask) { .count() < 4 { - log::debug!( - target: "network", - "Gossip({}, {}) => GossipInDesired(outcome=accepted)", - &task.network[chain_id].log_name, + log!( + &task.platform, + Debug, + "network", + "gossip-in-request", + chain = &task.network[chain_id].log_name, peer_id, + outcome = "accepted" ); task.network .gossip_open( @@ -2205,11 +2293,14 @@ async fn background_task(mut task: BackgroundTask) { ) .unwrap(); } else { - log::debug!( - target: "network", - "Gossip({}, {}) => GossipInDesired(outcome=rejected)", - &task.network[chain_id].log_name, + log!( + &task.platform, + Debug, + "network", + "gossip-in-request", + chain = &task.network[chain_id].log_name, peer_id, + outcome = "rejected", ); task.network .gossip_close( @@ -2228,9 +2319,11 @@ async fn background_task(mut task: BackgroundTask) { peer_id, substream_id, }) => { - log::debug!( - target: "network", - "Connections({}) => IdentifyRequest", + log!( + &task.platform, + Debug, + "network", + "identify-request-received", peer_id, ); task.network @@ -2246,14 +2339,16 @@ async fn background_task(mut task: BackgroundTask) { peer_id, state, }) => { - log::debug!( - target: "network", - "Gossip({}, {}) => GrandpaNeighborPacket(round_number={}, set_id={}, commit_finalized_height={})", - &task.network[chain_id].log_name, + log!( + &task.platform, + Debug, + "network", + "grandpa-neighbor-packet-received", + chain = &task.network[chain_id].log_name, peer_id, - state.round_number, - state.set_id, - state.commit_finalized_height, + round_number = state.round_number, + set_id = state.set_id, + commit_finalized_height = state.commit_finalized_height, ); task.open_gossip_links @@ -2275,12 +2370,14 @@ async fn background_task(mut task: BackgroundTask) { peer_id, message, }) => { - log::debug!( - target: "network", - "Gossip({}, {}) => GrandpaCommitMessage(target_block_hash={})", - &task.network[chain_id].log_name, + log!( + &task.platform, + Debug, + "network", + "grandpa-commit-message-received", + chain = &task.network[chain_id].log_name, peer_id, - HashDisplay(message.decode().target_hash), + target_block_hash = HashDisplay(message.decode().target_hash), ); debug_assert!(task.event_pending_send.is_none()); @@ -2289,11 +2386,13 @@ async fn background_task(mut task: BackgroundTask) { } WakeUpReason::NetworkEvent(service::Event::ProtocolError { peer_id, error }) => { // TODO: handle properly? - log::warn!( - target: "network", - "Connections({}) => ProtocolError(error={:?})", + log!( + &task.platform, + Warn, + "network", + "protocol-error", peer_id, - error, + ?error ); // TODO: disconnect peer @@ -2301,10 +2400,12 @@ async fn background_task(mut task: BackgroundTask) { WakeUpReason::CanAssignSlot(peer_id, chain_id) => { task.peering_strategy.assign_slot(&chain_id, &peer_id); - log::debug!( - target: "network", - "Slots({}) ∋ {}", - &task.network[chain_id].log_name, + log!( + &task.platform, + Debug, + "network", + "slot-assigned", + chain = &task.network[chain_id].log_name, peer_id ); @@ -2337,12 +2438,15 @@ async fn background_task(mut task: BackgroundTask) { what_happened, basic_peering_strategy::UnassignSlotsAndBan::Banned { had_slot: true } ) { - log::debug!( - target: "network", - "Slots({}) ∌ {} (reason=no-address, ban-duration={:?})", - &task.network[chain_id].log_name, - expected_peer_id, - ban_duration + log!( + &task.platform, + Debug, + "network", + "slot-unassigned", + chain = &task.network[chain_id].log_name, + peer_id = expected_peer_id, + ?ban_duration, + reason = "no-address" ); } } @@ -2398,12 +2502,16 @@ async fn background_task(mut task: BackgroundTask) { connection::NoiseKey::new(&libp2p_key, &noise_static_key) }; - log::debug!( - target: "network", - "Connections({}) <= StartConnecting(remote_addr={}, local_peer_id={})", + log!( + &task.platform, + Debug, + "network", + "connection-started", expected_peer_id, - multiaddr, - peer_id::PublicKey::Ed25519(*noise_key.libp2p_public_ed25519_key()).into_peer_id(), + remote_addr = multiaddr, + local_peer_id = + peer_id::PublicKey::Ed25519(*noise_key.libp2p_public_ed25519_key()) + .into_peer_id(), ); task.num_recent_connection_opening += 1; @@ -2511,10 +2619,12 @@ async fn background_task(mut task: BackgroundTask) { ) .unwrap(); - log::debug!( - target: "network", - "Gossip({}, {}) <= Open", - &task.network[chain_id].log_name, + log!( + &task.platform, + Debug, + "network", + "gossip-open-start", + chain = &task.network[chain_id].log_name, peer_id, ); } diff --git a/light-base/src/sync_service/parachain.rs b/light-base/src/sync_service/parachain.rs index e463ae4965..fec7b36015 100644 --- a/light-base/src/sync_service/parachain.rs +++ b/light-base/src/sync_service/parachain.rs @@ -18,7 +18,7 @@ use super::ToBackground; use crate::{network_service, platform::PlatformRef, runtime_service, util}; -use alloc::{borrow::ToOwned as _, boxed::Box, string::String, sync::Arc, vec::Vec}; +use alloc::{borrow::ToOwned as _, boxed::Box, format, string::String, sync::Arc, vec::Vec}; use core::{ iter, mem, num::{NonZeroU32, NonZeroUsize}, diff --git a/light-base/src/sync_service/standalone.rs b/light-base/src/sync_service/standalone.rs index 65f859d20d..35156656c0 100644 --- a/light-base/src/sync_service/standalone.rs +++ b/light-base/src/sync_service/standalone.rs @@ -24,6 +24,7 @@ use crate::{network_service, platform::PlatformRef, util}; use alloc::{ borrow::{Cow, ToOwned as _}, boxed::Box, + format, string::String, sync::Arc, vec::Vec, @@ -289,13 +290,17 @@ pub(super) async fn start_standalone_chain( match header::decode(decoded.scale_encoded_header, task.sync.block_number_bytes()) { Ok(decoded_header) => { - log::debug!( - target: &task.log_target, - "Sync <= BlockAnnounce(sender={}, hash={}, is_best={}, parent_hash={})", - peer_id, - HashDisplay(&header::hash_from_scale_encoded_header(decoded.scale_encoded_header)), - decoded.is_best, - HashDisplay(decoded_header.parent_hash) + log!( + &task.platform, + Debug, + &task.log_target, + "block-announce", + sender = peer_id, + hash = HashDisplay(&header::hash_from_scale_encoded_header( + decoded.scale_encoded_header + )), + is_best = decoded.is_best, + parent_hash = HashDisplay(decoded_header.parent_hash) ); } Err(error) => { @@ -414,15 +419,21 @@ pub(super) async fn start_standalone_chain( { all::GrandpaCommitMessageOutcome::Queued => { // TODO: print more details? - log::debug!( - target: &task.log_target, - "Sync <= QueuedGrandpaCommit" + log!( + &task.platform, + Debug, + &task.log_target, + "grandpa-commit-message-queued", + sender = peer_id ); } all::GrandpaCommitMessageOutcome::Discarded => { - log::debug!( - target: &task.log_target, - "Sync <= IgnoredGrandpaCommit" + log!( + &task.platform, + Debug, + &task.log_target, + "grandpa-commit-message-ignored", + sender = peer_id ); } } @@ -900,11 +911,15 @@ pub(super) async fn start_standalone_chain( finalized_block_hash, finalized_block_number, } => { - log::warn!( - target: &task.log_target, - "GrandPa warp sync idle at block #{} (0x{})", - finalized_block_number, - HashDisplay(&finalized_block_hash), + log!( + &task.platform, + Warn, + &task.log_target, + format!( + "GrandPa warp sync idle at block #{} (0x{})", + finalized_block_number, + HashDisplay(&finalized_block_hash) + ), ); } all::Status::WarpSyncFragments { @@ -916,11 +931,15 @@ pub(super) async fn start_standalone_chain( finalized_block_hash, finalized_block_number, } => { - log::warn!( - target: &task.log_target, - "GrandPa warp sync in progress. Block: #{} (0x{}).", - finalized_block_number, - HashDisplay(&finalized_block_hash) + log!( + &task.platform, + Warn, + &task.log_target, + format!( + "GrandPa warp sync in progress. Block: #{} (0x{}).", + finalized_block_number, + HashDisplay(&finalized_block_hash) + ) ); } }; @@ -1013,16 +1032,33 @@ impl Task { let elapsed = self.platform.now() - before_instant; match error { Ok(()) => { - log::debug!( - target: &self.log_target, - "Sync => WarpSyncRuntimeBuild(success=true, duration={:?})", - elapsed + log!( + &self.platform, + Debug, + &self.log_target, + "warp-sync-runtime-build-success", + success = ?true, + duration = ?elapsed ); } - Err(err) => { - log::debug!(target: &self.log_target, "Sync => WarpSyncRuntimeBuild(error={})", err); - if !matches!(err, all::WarpSyncBuildRuntimeError::SourceMisbehavior(_)) { - log::warn!(target: &self.log_target, "Failed to compile runtime during warp syncing process: {}", err); + Err(error) => { + log!( + &self.platform, + Debug, + &self.log_target, + "warp-sync-runtime-build-error", + ?error + ); + if !matches!(error, all::WarpSyncBuildRuntimeError::SourceMisbehavior(_)) { + log!( + &self.platform, + Debug, + &self.log_target, + format!( + "Failed to compile runtime during warp syncing process: {}", + error + ) + ); } } }; @@ -1060,11 +1096,15 @@ impl Task { self.sync = sync; let finalized_header = self.sync.finalized_block_header(); - log::info!( - target: &self.log_target, - "GrandPa warp sync finished to #{} ({})", - finalized_header.number, - HashDisplay(&finalized_header.hash(self.sync.block_number_bytes())) + log!( + &self.platform, + Debug, + &self.log_target, + format!( + "GrandPa warp sync finished to #{} ({})", + finalized_header.number, + HashDisplay(&finalized_header.hash(self.sync.block_number_bytes())) + ) ); self.warp_sync_taking_long_time_warning = @@ -1102,11 +1142,17 @@ impl Task { match result { Ok((fragment_hash, fragment_number)) => { // TODO: must call `set_local_grandpa_state` and `set_local_best_block` so that other peers notify us of neighbor packets - log::debug!( - target: &self.log_target, - "Sync => WarpSyncFragmentVerified(sender={}, verified_hash={}, verified_height={fragment_number})", - sender_if_still_connected.as_ref().map(|p| Cow::Owned(p.to_base58())).unwrap_or(Cow::Borrowed("")), - HashDisplay(&fragment_hash) + log!( + &self.platform, + Debug, + &self.log_target, + "warp-sync-fragment-verify-success", + sender = sender_if_still_connected + .as_ref() + .map(|p| Cow::Owned(p.to_base58())) + .unwrap_or(Cow::Borrowed("")), + verified_hash = HashDisplay(&fragment_hash), + verified_height = fragment_number ); } Err(err) => { @@ -1146,11 +1192,13 @@ impl Task { let verified_height = success.height(); self.sync = success.finish(()); - log::debug!( - target: &self.log_target, - "Sync => HeaderVerified(hash={}, new_best={})", - HashDisplay(&verified_hash), - if is_new_best { "yes" } else { "no" } + log!( + &self.platform, + Debug, + &self.log_target, + "header-verify-success", + hash = HashDisplay(&verified_hash), + is_new_best = if is_new_best { "yes" } else { "no" } ); if is_new_best { @@ -1263,18 +1311,24 @@ impl Task { self.sync = sync; // TODO: print which peer sent the header - log::debug!( - target: &self.log_target, - "Sync => HeaderVerifyError(hash={}, error={:?})", - HashDisplay(&verified_hash), - error + log!( + &self.platform, + Debug, + &self.log_target, + "header-verify-error", + hash = HashDisplay(&verified_hash), + ?error ); - log::warn!( - target: &self.log_target, - "Error while verifying header {}: {}", - HashDisplay(&verified_hash), - error + log!( + &self.platform, + Warn, + &self.log_target, + format!( + "Error while verifying header {}: {}", + HashDisplay(&verified_hash), + error + ) ); // TODO: ban peers that have announced the block @@ -1309,10 +1363,13 @@ impl Task { ) => { self.sync = sync; - log::debug!( - target: &self.log_target, - "Sync => FinalityProofVerified(finalized_blocks={}, sender={sender})", - finalized_blocks_newest_to_oldest.len(), + log!( + &self.platform, + Debug, + &self.log_target, + "finality-proof-verify-success", + finalized_blocks = finalized_blocks_newest_to_oldest.len(), + sender ); if updates_best_block { @@ -1347,15 +1404,21 @@ impl Task { (sync, all::FinalityProofVerifyOutcome::JustificationError(error)) => { self.sync = sync; - log::debug!( - target: &self.log_target, - "Sync => JustificationVerificationError(error={error:?}, sender={sender})", + log!( + &self.platform, + Debug, + &self.log_target, + "finality-proof-verify-error", + ?error, + sender, ); // TODO: don't print for consensusenginemismatch? - log::warn!( - target: &self.log_target, - "Error while verifying justification: {error}" + log!( + &self.platform, + Warn, + &self.log_target, + format!("Error while verifying justification: {error}") ); // TODO: don't ban for consensusenginemismatch? @@ -1371,15 +1434,20 @@ impl Task { (sync, all::FinalityProofVerifyOutcome::GrandpaCommitError(error)) => { self.sync = sync; - log::debug!( - target: &self.log_target, - "Sync => GrandpaCommitVerificationError(error={error:?}, sender={sender})", + log!( + &self.platform, + Debug, + &self.log_target, + "finality-proof-verify-error", + ?error, + sender, ); - log::warn!( - target: &self.log_target, - "Error while verifying GrandPa commit: {}", - error + log!( + &self.platform, + Warn, + &self.log_target, + format!("Error while verifying GrandPa commit: {}", error) ); self.network_service From 2b345cee0bd72fef3c2bada3ec19092bd9c6879a Mon Sep 17 00:00:00 2001 From: Pierre Krieger Date: Fri, 5 Jan 2024 15:21:30 +0100 Subject: [PATCH 05/14] Update documentation --- light-base/examples/basic.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/light-base/examples/basic.rs b/light-base/examples/basic.rs index 6f205f4dce..b2be648df5 100644 --- a/light-base/examples/basic.rs +++ b/light-base/examples/basic.rs @@ -19,7 +19,7 @@ use core::{iter, num::NonZeroU32}; use futures_lite::FutureExt as _; fn main() { - // The `smoldot_light` library uses the `log` crate to emit logs. + // The `DefaultPlatform` that we use below uses the `log` crate to emit logs. // We need to register some kind of logs listener, in this example `env_logger`. // See also . env_logger::Builder::from_env(env_logger::Env::default().default_filter_or("info")).init(); From a88ab3e81eb5df85afdaeac64f2f4c7352dbf439 Mon Sep 17 00:00:00 2001 From: Pierre Krieger Date: Mon, 8 Jan 2024 09:14:00 +0100 Subject: [PATCH 06/14] Finish updating log statements --- light-base/src/json_rpc_service/background.rs | 68 ++-- light-base/src/network_service.rs | 359 +++++++++++------- light-base/src/runtime_service.rs | 258 ++++++++----- light-base/src/sync_service/standalone.rs | 169 +++------ 4 files changed, 482 insertions(+), 372 deletions(-) diff --git a/light-base/src/json_rpc_service/background.rs b/light-base/src/json_rpc_service/background.rs index 965d83bcc6..a3f8945a2a 100644 --- a/light-base/src/json_rpc_service/background.rs +++ b/light-base/src/json_rpc_service/background.rs @@ -325,16 +325,20 @@ impl Background { .printed_legacy_json_rpc_warning .swap(true, atomic::Ordering::Relaxed) { - log::warn!( - target: &self.log_target, - "The JSON-RPC client has just called a JSON-RPC function from the legacy \ - JSON-RPC API ({}). Legacy JSON-RPC functions have loose semantics and \ - cannot be properly implemented on a light client. You are encouraged to \ - use the new JSON-RPC API \ - instead. The \ - legacy JSON-RPC API functions will be deprecated and removed in the \ - distant future.", - request.request().name() + log!( + &self.platform, + Warn, + &self.log_target, + format!( + "The JSON-RPC client has just called a JSON-RPC function from \ + the legacy JSON-RPC API ({}). Legacy JSON-RPC functions have \ + loose semantics and cannot be properly implemented on a light \ + client. You are encouraged to use the new JSON-RPC API \ + instead. The \ + legacy JSON-RPC API functions will be deprecated and removed in the \ + distant future.", + request.request().name() + ) ) } } @@ -503,7 +507,12 @@ impl Background { | methods::MethodCall::system_networkState { .. } | methods::MethodCall::system_removeReservedPeer { .. }) => { // TODO: implement the ones that make sense to implement ^ - log::error!(target: &self.log_target, "JSON-RPC call not supported yet: {:?}", _method); + log!( + &self.platform, + Warn, + &self.log_target, + format!("JSON-RPC call not supported yet: {:?}", _method) + ); request.fail(json_rpc::parse::ErrorResponse::ServerError( -32000, "Not implemented in smoldot yet", @@ -520,12 +529,6 @@ impl Background { request: service::SubscriptionStartProcess, ) { // TODO: restore some form of logging - /*log::debug!(target: &self.log_target, "PendingRequestsQueue => {}", - crate::util::truncated_str( - json_rpc_request.chars().filter(|c| !c.is_control()), - 100, - ) - );*/ // Print a warning for legacy JSON-RPC functions. match request.request() { @@ -593,16 +596,20 @@ impl Background { .printed_legacy_json_rpc_warning .swap(true, atomic::Ordering::Relaxed) { - log::warn!( - target: &self.log_target, - "The JSON-RPC client has just called a JSON-RPC function from the legacy \ - JSON-RPC API ({}). Legacy JSON-RPC functions have loose semantics and \ - cannot be properly implemented on a light client. You are encouraged to \ - use the new JSON-RPC API \ - instead. The \ - legacy JSON-RPC API functions will be deprecated and removed in the \ - distant future.", - request.request().name() + log!( + &self.platform, + Warn, + &self.log_target, + format!( + "The JSON-RPC client has just called a JSON-RPC function from \ + the legacy JSON-RPC API ({}). Legacy JSON-RPC functions have \ + loose semantics and cannot be properly implemented on a light \ + client. You are encouraged to use the new JSON-RPC API \ + instead. The \ + legacy JSON-RPC API functions will be deprecated and removed in the \ + distant future.", + request.request().name() + ) ) } } @@ -650,7 +657,12 @@ impl Background { _method @ methods::MethodCall::network_unstable_subscribeEvents { .. } => { // TODO: implement the ones that make sense to implement ^ - log::error!(target: &self.log_target, "JSON-RPC call not supported yet: {:?}", _method); + log!( + &self.platform, + Warn, + &self.log_target, + format!("JSON-RPC call not supported yet: {:?}", _method) + ); request.fail(json_rpc::parse::ErrorResponse::ServerError( -32000, "Not implemented in smoldot yet", diff --git a/light-base/src/network_service.rs b/light-base/src/network_service.rs index 75f5fe71cd..4cdceb1add 100644 --- a/light-base/src/network_service.rs +++ b/light-base/src/network_service.rs @@ -56,7 +56,6 @@ use futures_channel::oneshot; use futures_lite::FutureExt as _; use futures_util::{future, stream, StreamExt as _}; use hashbrown::{HashMap, HashSet}; -use itertools::Itertools as _; use rand::seq::IteratorRandom as _; use rand_chacha::rand_core::SeedableRng as _; use smoldot::{ @@ -200,12 +199,13 @@ impl NetworkService { chains_by_next_discovery: BTreeMap::new(), })); - config - .platform - .spawn_task("network-service".into(), async move { + config.platform.spawn_task("network-service".into(), { + let platform = config.platform.clone(); + async move { task.await; - log::debug!(target: "network", "Shutdown") - }); + log!(&platform, Debug, "network", "shutdown"); + } + }); Arc::new(NetworkService { messages_tx: main_messages_tx, @@ -1341,9 +1341,14 @@ async fn background_task(mut task: BackgroundTask) { result, }, ) => { - log::debug!( - target: "network", "Connections({}) <= WarpSyncRequest(chain={}, start={})", - target, task.network[chain_id].log_name, HashDisplay(&begin_hash) + log!( + &task.platform, + Debug, + "network", + "warp-sync-request-started", + chain = task.network[chain_id].log_name, + target, + start = HashDisplay(&begin_hash) ); match task @@ -1354,11 +1359,14 @@ async fn background_task(mut task: BackgroundTask) { task.grandpa_warp_sync_requests.insert(substream_id, result); } Err(service::StartRequestError::NoConnection) => { - log::debug!( - target: "network", - "Connections({}) => WarpSyncRequest(chain={}, error=NoConnection)", + log!( + &task.platform, + Debug, + "network", + "warp-sync-request-error", + chain = task.network[chain_id].log_name, target, - task.network[chain_id].log_name, + error = "NoConnection" ); let _ = result.send(Err(WarpSyncRequestError::NoConnection)); } @@ -1373,12 +1381,14 @@ async fn background_task(mut task: BackgroundTask) { result, }, ) => { - log::debug!( - target: "network", - "Connections({}) <= StorageProofRequest(chain={}, block={})", + log!( + &task.platform, + Debug, + "network", + "storage-proof-request-started", + chain = task.network[chain_id].log_name, target, - task.network[chain_id].log_name, - HashDisplay(&config.block_hash) + block_hash = HashDisplay(&config.block_hash) ); match task.network.start_storage_proof_request( @@ -1391,18 +1401,26 @@ async fn background_task(mut task: BackgroundTask) { task.storage_proof_requests.insert(substream_id, result); } Err(service::StartRequestMaybeTooLargeError::NoConnection) => { - log::debug!( - target: "network", - "Connections({target}) => StorageProofRequest(chain={}, error=NoConnection)", - task.network[chain_id].log_name, + log!( + &task.platform, + Debug, + "network", + "storage-proof-request-error", + chain = task.network[chain_id].log_name, + target, + error = "NoConnection" ); let _ = result.send(Err(StorageProofRequestError::NoConnection)); } Err(service::StartRequestMaybeTooLargeError::RequestTooLarge) => { - log::debug!( - target: "network", - "Connections({target}) => StorageProofRequest(chain={}, error=RequestTooLarge)", - task.network[chain_id].log_name, + log!( + &task.platform, + Debug, + "network", + "storage-proof-request-error", + chain = task.network[chain_id].log_name, + target, + error = "RequestTooLarge" ); let _ = result.send(Err(StorageProofRequestError::RequestTooLarge)); } @@ -1417,14 +1435,17 @@ async fn background_task(mut task: BackgroundTask) { result, }, ) => { - log::debug!( - target: "network", - "Connections({}) <= CallProofRequest({}, {}, {})", + log!( + &task.platform, + Debug, + "network", + "call-proof-request-started", + chain = task.network[chain_id].log_name, target, - task.network[chain_id].log_name, - HashDisplay(&config.block_hash), - config.method + block_hash = HashDisplay(&config.block_hash), + function = config.method ); + // TODO: log parameter match task.network.start_call_proof_request( &target, @@ -1436,18 +1457,26 @@ async fn background_task(mut task: BackgroundTask) { task.call_proof_requests.insert(substream_id, result); } Err(service::StartRequestMaybeTooLargeError::NoConnection) => { - log::debug!( - target: "network", - "Connections({target}) => CallProofRequest({}, NoConnection)", - task.network[chain_id].log_name + log!( + &task.platform, + Debug, + "network", + "call-proof-request-error", + chain = task.network[chain_id].log_name, + target, + error = "NoConnection" ); let _ = result.send(Err(CallProofRequestError::NoConnection)); } Err(service::StartRequestMaybeTooLargeError::RequestTooLarge) => { - log::debug!( - target: "network", - "Connections({target}) => CallProofRequest({}, RequestTooLarge)", - task.network[chain_id].log_name + log!( + &task.platform, + Debug, + "network", + "call-proof-request-error", + chain = task.network[chain_id].log_name, + target, + error = "RequestTooLarge" ); let _ = result.send(Err(CallProofRequestError::RequestTooLarge)); } @@ -1779,20 +1808,32 @@ async fn background_task(mut task: BackgroundTask) { }) => { let remote_addr = Multiaddr::from_bytes(task.network.connection_remote_addr(id)).unwrap(); // TODO: review this unwrap - log::debug!(target: "network", "Connections({peer_id}, {remote_addr}) => Ping({ping_time:?})"); + log!( + &task.platform, + Debug, + "network", + "pong", + peer_id, + remote_addr, + ?ping_time + ); } WakeUpReason::NetworkEvent(service::Event::BlockAnnounce { chain_id, peer_id, announce, }) => { - log::debug!( - target: "network", - "Gossip({}, {}) => BlockAnnounce(best_hash={}, is_best={})", - &task.network[chain_id].log_name, + log!( + &task.platform, + Debug, + "network", + "block-announce-received", + chain = &task.network[chain_id].log_name, peer_id, - HashDisplay(&header::hash_from_scale_encoded_header(announce.decode().scale_encoded_header)), - announce.decode().is_best + best_hash = HashDisplay(&header::hash_from_scale_encoded_header( + announce.decode().scale_encoded_header + )), + is_best = announce.decode().is_best ); let decoded_announce = announce.decode(); @@ -1824,13 +1865,15 @@ async fn background_task(mut task: BackgroundTask) { best_hash, kind: service::GossipKind::ConsensusTransactions, }) => { - log::debug!( - target: "network", - "Gossip({}, {}) => Opened(best_height={}, best_hash={})", - &task.network[chain_id].log_name, + log!( + &task.platform, + Debug, + "network", + "gossip-open-success", + chain = &task.network[chain_id].log_name, peer_id, best_number, - HashDisplay(&best_hash) + best_hash = HashDisplay(&best_hash) ); let _prev_value = task.open_gossip_links.insert( @@ -1861,11 +1904,14 @@ async fn background_task(mut task: BackgroundTask) { error, kind: service::GossipKind::ConsensusTransactions, }) => { - log::debug!( - target: "network", - "Gossip({}, {}) => OpenFailed(error={:?})", - &task.network[chain_id].log_name, - peer_id, error, + log!( + &task.platform, + Debug, + "network", + "gossip-open-error", + chain = &task.network[chain_id].log_name, + peer_id, + ?error, ); let ban_duration = Duration::from_secs(15); @@ -1962,44 +2008,58 @@ async fn background_task(mut task: BackgroundTask) { }) => { match &response { Ok(blocks) => { - log::debug!( - target: "network", - "Connections({}) => BlocksRequest(chain={}, num_blocks={}, block_data_total_size={})", - peer_id, - task.network[chain_id].log_name, - blocks.len(), - BytesDisplay(blocks.iter().fold(0, |sum, block| { - let block_size = block.header.as_ref().map_or(0, |h| h.len()) + - block.body.as_ref().map_or(0, |b| b.iter().fold(0, |s, e| s + e.len())) + - block.justifications.as_ref().into_iter().flat_map(|l| l.iter()).fold(0, |s, j| s + j.justification.len()); - sum + u64::try_from(block_size).unwrap() - })) + log!( + &task.platform, + Debug, + "network", + "blocks-request-success", + chain = task.network[chain_id].log_name, + target = peer_id, + num_blocks = blocks.len(), + block_data_total_size = + BytesDisplay(blocks.iter().fold(0, |sum, block| { + let block_size = block.header.as_ref().map_or(0, |h| h.len()) + + block + .body + .as_ref() + .map_or(0, |b| b.iter().fold(0, |s, e| s + e.len())) + + block + .justifications + .as_ref() + .into_iter() + .flat_map(|l| l.iter()) + .fold(0, |s, j| s + j.justification.len()); + sum + u64::try_from(block_size).unwrap() + })) ); } - Err(err) => { - log::debug!( - target: "network", - "Connections({}) => BlocksRequest(chain={}, error={:?})", - peer_id, - task.network[chain_id].log_name, - err + Err(error) => { + log!( + &task.platform, + Debug, + "network", + "blocks-request-error", + chain = task.network[chain_id].log_name, + target = peer_id, + ?error ); } } - if !log::log_enabled!(log::Level::Debug) { - match &response { - Ok(_) => {} - Err(service::BlocksRequestError::Request(err)) - if !err.is_protocol_error() => {} - Err(err) => { - log::warn!( - target: "network", - "Error in block request with {}. This might indicate an incompatibility. Error: {}", - peer_id, - err - ); - } + match &response { + Ok(_) => {} + Err(service::BlocksRequestError::Request(err)) if !err.is_protocol_error() => {} + Err(err) => { + log!( + &task.platform, + Debug, + "network", + format!( + "Error in block request with {}. This might indicate an \ + incompatibility. Error: {}", + peer_id, err + ) + ); } } @@ -2019,22 +2079,26 @@ async fn background_task(mut task: BackgroundTask) { Ok(response) => { // TODO: print total bytes size let decoded = response.decode(); - log::debug!( - target: "network", - "Connections({}) => WarpSyncRequest(chain={}, num_fragments={}, finished={:?})", - peer_id, - task.network[chain_id].log_name, - decoded.fragments.len(), - decoded.is_finished, + log!( + &task.platform, + Debug, + "network", + "warp-sync-request-success", + chain = task.network[chain_id].log_name, + target = peer_id, + num_fragments = decoded.fragments.len(), + is_finished = ?decoded.is_finished, ); } - Err(err) => { - log::debug!( - target: "network", - "Connections({}) => WarpSyncRequest(chain={}, error={:?})", - peer_id, - task.network[chain_id].log_name, - err, + Err(error) => { + log!( + &task.platform, + Debug, + "network", + "warp-sync-request-error", + chain = task.network[chain_id].log_name, + target = peer_id, + ?error, ); } } @@ -2054,19 +2118,25 @@ async fn background_task(mut task: BackgroundTask) { match &response { Ok(items) => { let decoded = items.decode(); - log::debug!( - target: "network", - "Connections({peer_id}) => StorageProofRequest(chain={}, total_size={})", - task.network[chain_id].log_name, - BytesDisplay(u64::try_from(decoded.len()).unwrap()), + log!( + &task.platform, + Debug, + "network", + "storage-proof-request-success", + chain = task.network[chain_id].log_name, + target = peer_id, + total_size = BytesDisplay(u64::try_from(decoded.len()).unwrap()), ); } - Err(err) => { - log::debug!( - target: "network", - "Connections({peer_id}) => StorageProofRequest(chain={}, error={:?})", - task.network[chain_id].log_name, - err + Err(error) => { + log!( + &task.platform, + Debug, + "network", + "storage-proof-request-error", + chain = task.network[chain_id].log_name, + target = peer_id, + ?error ); } } @@ -2086,21 +2156,25 @@ async fn background_task(mut task: BackgroundTask) { match &response { Ok(items) => { let decoded = items.decode(); - log::debug!( - target: "network", - "Connections({}) => CallProofRequest({}, total_size: {})", - peer_id, - task.network[chain_id].log_name, - BytesDisplay(u64::try_from(decoded.len()).unwrap()) + log!( + &task.platform, + Debug, + "network", + "call-proof-request-success", + chain = task.network[chain_id].log_name, + target = peer_id, + total_size = BytesDisplay(u64::try_from(decoded.len()).unwrap()) ); } - Err(err) => { - log::debug!( - target: "network", - "Connections({}) => CallProofRequest({}, {})", - peer_id, - task.network[chain_id].log_name, - err + Err(error) => { + log!( + &task.platform, + Debug, + "network", + "call-proof-request-error", + chain = task.network[chain_id].log_name, + target = peer_id, + ?error ); } } @@ -2238,21 +2312,28 @@ async fn background_task(mut task: BackgroundTask) { ), ) => { // TODO: remove this warning in a long time - log::warn!( - target: "network", - "Problem during discovery on {}: protocol not available. \ - This might indicate that the version of Substrate used by \ - the chain doesn't include \ - .", - &task.network[chain_id].log_name + log!( + &task.platform, + Warn, + "network", + format!( + "Problem during discovery on {}: protocol not available. \ + This might indicate that the version of Substrate used by \ + the chain doesn't include \ + .", + &task.network[chain_id].log_name + ) ); } _ => { - log::warn!( - target: "network", - "Problem during discovery on {}: {}", - &task.network[chain_id].log_name, - error + log!( + &task.platform, + Debug, + "network", + format!( + "Problem during discovery on {}: {}", + &task.network[chain_id].log_name, error + ) ); } } diff --git a/light-base/src/runtime_service.rs b/light-base/src/runtime_service.rs index 0397febd88..3f4f954eb9 100644 --- a/light-base/src/runtime_service.rs +++ b/light-base/src/runtime_service.rs @@ -131,13 +131,14 @@ impl RuntimeService { // Spawns a task that runs in the background and updates the content of the mutex. let to_background; config.platform.spawn_task(log_target.clone().into(), { + let platform = config.platform.clone(); let (tx, rx) = async_channel::bounded(16); let tx_weak = tx.downgrade(); to_background = tx; let background_task_config = background_task_config.clone(); async move { run_background(background_task_config, rx, tx_weak).await; - log::debug!(target: &log_target, "Shutdown"); + log!(&platform, Debug, &log_target, "shutdown"); } }); @@ -392,6 +393,7 @@ impl RuntimeService { self.background_task_config.log_target.clone().into(), { let background_task_config = self.background_task_config.clone(); + let platform = background_task_config.platform.clone(); async move { // Sleep for a bit in order to avoid infinite loops of repeated crashes. background_task_config @@ -399,9 +401,9 @@ impl RuntimeService { .sleep(Duration::from_secs(2)) .await; let log_target = background_task_config.log_target.clone(); - log::debug!(target: &log_target, "Restart"); + log!(&platform, Debug, &log_target, "restart"); run_background(background_task_config, rx, tx_weak).await; - log::debug!(target: &log_target, "Shutdown"); + log!(&platform, Debug, &log_target, "shutdown"); } }, ); @@ -1101,10 +1103,12 @@ async fn run_background( } }; - log::debug!( - target: &background.log_target, - "Worker => NewDownload(block={})", - HashDisplay(&download_params.block_user_data.hash) + log!( + &background.platform, + Debug, + &background.log_target, + "block-runtime-download-started", + block_hash = HashDisplay(&download_params.block_user_data.hash) ); // Dispatches a runtime download task to `runtime_downloads`. @@ -1204,9 +1208,12 @@ async fn run_background( }) } Err(error) => { - log::warn!( - target: &background.log_target, - "Failed to decode header from sync service: {}", error + // TODO: move log somewhere else + log!( + &background.platform, + Warn, + &background.log_target, + format!("Failed to decode header from sync service: {}", error) ); Box::pin(async move { @@ -1241,10 +1248,13 @@ async fn run_background( let best_block_hash = best_block_index .map_or(finalized_block.hash, |idx| tree.block_user_data(idx).hash); - log::debug!( - target: &background.log_target, - "Worker => OutputFinalized(hash={}, best={})", - HashDisplay(&finalized_block.hash), HashDisplay(&best_block_hash) + log!( + &background.platform, + Debug, + &background.log_target, + "output-chain-finalized", + block_hash = HashDisplay(&finalized_block.hash), + best_block_hash = HashDisplay(&best_block_hash) ); // The finalization might cause some runtimes in the list of runtimes @@ -1329,10 +1339,12 @@ async fn run_background( tree.block_async_user_data(idx).unwrap().clone() }); - log::debug!( - target: &background.log_target, - "Worker => OutputNewBlock(hash={}, is_new_best={})", - HashDisplay(&tree.block_user_data(block_index).hash), + log!( + &background.platform, + Debug, + &background.log_target, + "output-chain-new-block", + block_hash = HashDisplay(&tree.block_user_data(block_index).hash), is_new_best ); @@ -1395,10 +1407,12 @@ async fn run_background( .map_or(&*finalized_block, |idx| tree.block_user_data(idx)) .hash; - log::debug!( - target: &background.log_target, - "Worker => OutputBestBlockChanged(hash={})", - HashDisplay(&hash), + log!( + &background.platform, + Debug, + &background.log_target, + "output-chain-best-block-update", + block_hash = HashDisplay(&hash), ); let notif = Notification::BestBlockChanged { hash }; @@ -1449,10 +1463,13 @@ async fn run_background( .map_or(new_finalized.hash, |idx| { tree.block_user_data(idx).hash }); - log::debug!( - target: &background.log_target, - "Worker => RuntimeKnown(finalized_hash={}, best={})", - HashDisplay(&new_finalized.hash), HashDisplay(&best_block_hash) + log!( + &background.platform, + Debug, + &background.log_target, + "output-chain-initialized", + finalized_block_hash = HashDisplay(&new_finalized.hash), + best_block_hash = HashDisplay(&best_block_hash) ); // Substitute `tree` with a dummy empty tree just in order to extract @@ -1499,12 +1516,15 @@ async fn run_background( // but the sync service guarantees that `subscribe_all` returns very quickly. let subscription = background.sync_service.subscribe_all(32, true).await; - log::debug!( - target: &background.log_target, - "Worker <= Reset(finalized_block: {})", - HashDisplay(&header::hash_from_scale_encoded_header( + log!( + &background.platform, + Debug, + &background.log_target, + "sync-service-subscription-started", + finalized_block_hash = HashDisplay(&header::hash_from_scale_encoded_header( &subscription.finalized_block_scale_encoded_header - )) + )), + finalized_block_runtime_known = ?subscription.finalized_block_runtime.is_some() ); // Update the state of `Background` with what we just grabbed. @@ -1559,30 +1579,34 @@ async fn run_background( match &runtime.runtime { Ok(runtime) => { - log::info!( - target: &background.log_target, - "Finalized block runtime ready. Spec version: {}. Size of `:code`: {}.", - runtime.runtime_spec.decode().spec_version, - BytesDisplay(storage_code_len) + log!( + &background.platform, + Info, + &background.log_target, + format!( + "Finalized block runtime ready. Spec version: {}. \ + Size of `:code`: {}.", + runtime.runtime_spec.decode().spec_version, + BytesDisplay(storage_code_len) + ) ); } Err(error) => { - log::warn!( - target: &background.log_target, - "Erroenous finalized block runtime. Size of `:code`: {}.\nError: {}\n\ - This indicates an incompatibility between smoldot and the chain.", - BytesDisplay(storage_code_len), - error + log!( + &background.platform, + Warn, + &background.log_target, + format!( + "Erronenous finalized block runtime. Size of \ + `:code`: {}.\nError: {}\nThis indicates an incompatibility \ + between smoldot and the chain.", + BytesDisplay(storage_code_len), + error + ) ); } } - log::debug!( - target: &background.log_target, - "Worker => RuntimeKnown(finalized_hash={})", - HashDisplay(&finalized_block_hash) - ); - background.tree = Tree::FinalizedBlockRuntimeKnown { all_blocks_subscriptions: hashbrown::HashMap::with_capacity_and_hasher( 32, @@ -1881,8 +1905,13 @@ async fn run_background( existing_runtime } else { // No identical runtime was found. Try compiling the new runtime. - let runtime = - SuccessfulRuntime::from_storage(&storage_code, &storage_heap_pages).await; + let runtime = SuccessfulRuntime::from_storage( + &background.platform, + &background.log_target, + &storage_code, + &storage_heap_pages, + ) + .await; let runtime = Arc::new(Runtime { heap_pages: storage_heap_pages, runtime_code: storage_code, @@ -2031,12 +2060,16 @@ async fn run_background( WakeUpReason::Notification(Some(sync_service::Notification::Block(new_block))) => { // Sync service has reported a new block. - log::debug!( - target: &background.log_target, - "Worker <= InputNewBlock(hash={}, parent={}, is_new_best={})", - HashDisplay(&header::hash_from_scale_encoded_header(&new_block.scale_encoded_header)), - HashDisplay(&new_block.parent_hash), - new_block.is_new_best + log!( + &background.platform, + Debug, + &background.log_target, + "input-chain-new-block", + block_hash = HashDisplay(&header::hash_from_scale_encoded_header( + &new_block.scale_encoded_header + )), + parent_block_hash = HashDisplay(&new_block.parent_hash), + is_new_best = new_block.is_new_best ); let near_head_of_chain = background @@ -2113,10 +2146,13 @@ async fn run_background( })) => { // Sync service has reported a finalized block. - log::debug!( - target: &background.log_target, - "Worker <= InputFinalized(hash={}, best={})", - HashDisplay(&hash), HashDisplay(&best_block_hash) + log!( + &background.platform, + Debug, + &background.log_target, + "input-chain-finalized", + block_hash = HashDisplay(&hash), + best_block_hash = HashDisplay(&best_block_hash) ); background.wake_up_new_necessary_download = Box::pin(future::ready(())); @@ -2163,10 +2199,12 @@ async fn run_background( })) => { // Sync service has reported a change in the best block. - log::debug!( - target: &background.log_target, - "Worker <= BestBlockChanged(hash={})", - HashDisplay(&hash) + log!( + &background.platform, + Debug, + &background.log_target, + "input-chain-best-block-update", + block_hash = HashDisplay(&hash) ); let near_head_of_chain = background @@ -2237,24 +2275,45 @@ async fn run_background( let runtime = if let Some(existing_runtime) = existing_runtime { existing_runtime } else { - let runtime = - SuccessfulRuntime::from_storage(&storage_code, &storage_heap_pages).await; + let runtime = SuccessfulRuntime::from_storage( + &background.platform, + &background.log_target, + &storage_code, + &storage_heap_pages, + ) + .await; match &runtime { Ok(runtime) => { - log::info!( - target: &background.log_target, - "Successfully compiled runtime. Spec version: {}. Size of `:code`: {}.", - runtime.runtime_spec.decode().spec_version, - BytesDisplay(u64::try_from(storage_code.as_ref().map_or(0, |v| v.len())).unwrap()) + log!( + &background.platform, + Info, + &background.log_target, + format!( + "Successfully compiled runtime. Spec version: {}. \ + Size of `:code`: {}.", + runtime.runtime_spec.decode().spec_version, + BytesDisplay( + u64::try_from(storage_code.as_ref().map_or(0, |v| v.len())) + .unwrap() + ) + ) ); } Err(error) => { - log::warn!( - target: &background.log_target, - "Failed to compile runtime. Size of `:code`: {}.\nError: {}\n\ - This indicates an incompatibility between smoldot and the chain.", - BytesDisplay(u64::try_from(storage_code.as_ref().map_or(0, |v| v.len())).unwrap()), - error + log!( + &background.platform, + Warn, + &background.log_target, + format!( + "Failed to compile runtime. Size of `:code`: {}.\nError: {}\n\ + This indicates an incompatibility between smoldot and \ + the chain.", + BytesDisplay( + u64::try_from(storage_code.as_ref().map_or(0, |v| v.len())) + .unwrap() + ), + error + ) ); } } @@ -2301,18 +2360,23 @@ async fn run_background( .format_with(", ", |block, fmt| fmt(&HashDisplay(&block.hash))) .to_string(); - log::debug!( - target: &background.log_target, - "Worker <= FailedDownload(blocks=[{}], error={:?})", - concerned_blocks, - error + log!( + &background.platform, + Debug, + &background.log_target, + "runtime-download-error", + block_hashes = concerned_blocks, + ?error ); if !error.is_network_problem() { - log::warn!( - target: &background.log_target, - "Failed to download :code and :heappages of blocks {}: {}", - concerned_blocks, - error + log!( + &background.platform, + Warn, + &background.log_target, + format!( + "Failed to download :code and :heappages of blocks {}: {}", + concerned_blocks, error + ) ); } @@ -2522,7 +2586,9 @@ struct SuccessfulRuntime { } impl SuccessfulRuntime { - async fn from_storage( + async fn from_storage( + platform: &TPlat, + log_target: &str, code: &Option>, heap_pages: &Option>, ) -> Result { @@ -2565,12 +2631,16 @@ impl SuccessfulRuntime { allow_unresolved_imports: true, }) { Ok(vm) => { - log::warn!( - "Unresolved host function in runtime: `{}`:`{}`. Smoldot might \ - encounter errors later on. Please report this issue in \ - https://github.com/smol-dot/smoldot", - module_name, - function + log!( + platform, + Warn, + log_target, + format!( + "Unresolved host function in runtime: `{}`:`{}`. Smoldot might \ + encounter errors later on. Please report this issue in \ + https://github.com/smol-dot/smoldot", + module_name, function + ) ); Ok(SuccessfulRuntime { diff --git a/light-base/src/sync_service/standalone.rs b/light-base/src/sync_service/standalone.rs index 35156656c0..758ff9ede5 100644 --- a/light-base/src/sync_service/standalone.rs +++ b/light-base/src/sync_service/standalone.rs @@ -288,106 +288,25 @@ pub(super) async fn start_standalone_chain( let sync_source_id = *task.peers_source_id_map.get(&peer_id).unwrap(); let decoded = announce.decode(); - match header::decode(decoded.scale_encoded_header, task.sync.block_number_bytes()) { - Ok(decoded_header) => { - log!( - &task.platform, - Debug, - &task.log_target, - "block-announce", - sender = peer_id, - hash = HashDisplay(&header::hash_from_scale_encoded_header( - decoded.scale_encoded_header - )), - is_best = decoded.is_best, - parent_hash = HashDisplay(decoded_header.parent_hash) - ); - } - Err(error) => { - log::debug!( - target: &task.log_target, - "Sync <= BlockAnnounce(sender={}, hash={}, is_best={}, parent_hash=)", - peer_id, - HashDisplay(&header::hash_from_scale_encoded_header(decoded.scale_encoded_header)), - decoded.is_best, - ); - - log::debug!( - target: &task.log_target, - "Sync => InvalidBlockHeader(error={})", - error - ); - - log::warn!( - target: &task.log_target, - "Failed to decode header in block announce received from {}. Error: {}", - peer_id, error, - ); - } - } + // TODO: improve the logging here, requires some modifications to block_announce() + log!( + &task.platform, + Debug, + &task.log_target, + "block-announce", + sender = peer_id, + hash = HashDisplay(&header::hash_from_scale_encoded_header( + decoded.scale_encoded_header + )), + is_best = decoded.is_best, + ); match task.sync.block_announce( sync_source_id, decoded.scale_encoded_header.to_owned(), decoded.is_best, ) { - all::BlockAnnounceOutcome::HeaderVerify - | all::BlockAnnounceOutcome::AlreadyInChain => { - log::debug!( - target: &task.log_target, - "Sync => Ok" - ); - } - all::BlockAnnounceOutcome::Discarded => { - log::debug!( - target: &task.log_target, - "Sync => Discarded" - ); - } - all::BlockAnnounceOutcome::StoredForLater {} => { - log::debug!( - target: &task.log_target, - "Sync => StoredForLater" - ); - } - all::BlockAnnounceOutcome::TooOld { - announce_block_height, - .. - } => { - log::debug!( - target: &task.log_target, - "Sync => TooOld" - ); - - log::warn!( - target: &task.log_target, - "Block announce header height (#{}) from {} is below finalized block", - announce_block_height, - peer_id - ); - - task.network_service - .ban_and_disconnect( - peer_id, - network_service::BanSeverity::Low, - "announced-block-below-known-finalized", - ) - .await; - } - all::BlockAnnounceOutcome::NotFinalizedChain => { - log::debug!( - target: &task.log_target, - "Sync => NotFinalized" - ); - - log::warn!( - target: &task.log_target, - "Block announce from {} isn't part of finalized chain", - peer_id - ); - } all::BlockAnnounceOutcome::InvalidHeader(_) => { - // Log messages are already printed above. task.network_service .ban_and_disconnect( peer_id, @@ -396,6 +315,7 @@ pub(super) async fn start_standalone_chain( ) .await; } + _ => {} } } @@ -1069,15 +989,31 @@ impl Task { let (new_sync, error) = req.build(); match error { Ok(()) => { - log::debug!(target: &self.log_target, "Sync => WarpSyncBuildChainInformation(success=true)") + log!( + &self.platform, + Debug, + &self.log_target, + "warp-sync-chain-information-build-success" + ); } - Err(err) => { - log::debug!(target: &self.log_target, "Sync => WarpSyncBuildChainInformation(error={})", err); + Err(error) => { + log!( + &self.platform, + Debug, + &self.log_target, + "warp-sync-chain-information-build-error", + ?error + ); if !matches!( - err, + error, all::WarpSyncBuildChainInformationError::SourceMisbehavior(_) ) { - log::warn!(target: &self.log_target, "Failed to build the chain information during warp syncing process: {}", err); + log!( + &self.platform, + Warn, + &self.log_target, + format!("Failed to build the chain information during warp syncing process: {}", error) + ); } } }; @@ -1156,16 +1092,25 @@ impl Task { ); } Err(err) => { - log::warn!( - target: &self.log_target, - "Failed to verify warp sync fragment from {}: {}{}", - sender_if_still_connected.as_ref().map(|p| Cow::Owned(p.to_base58())).unwrap_or(Cow::Borrowed("")), - err, - if matches!(err, all::VerifyFragmentError::JustificationVerify(_)) { - ". This might be caused by a forced GrandPa authorities change having \ + log!( + &self.platform, + Debug, + &self.log_target, + format!( + "Failed to verify warp sync fragment from {}: {}{}", + sender_if_still_connected + .as_ref() + .map(|p| Cow::Owned(p.to_base58())) + .unwrap_or(Cow::Borrowed("")), + err, + if matches!(err, all::VerifyFragmentError::JustificationVerify(_)) { + ". This might be caused by a forced GrandPa authorities change having \ been enacted on the chain. If this is the case, please update the \ chain specification with a checkpoint past this forced change." - } else { "" } + } else { + "" + } + ) ); if let Some(sender_if_still_connected) = sender_if_still_connected { self.network_service @@ -1271,11 +1216,13 @@ impl Task { .await .is_ok() { - log::debug!( - target: &self.log_target, - "Network <= BlockAnnounce(peer_id={}, hash={})", - source_peer_id, - HashDisplay(&verified_hash) + log!( + &self.platform, + Debug, + &self.log_target, + "block-announce-received", + peer_id = source_peer_id, + block_hash = HashDisplay(&verified_hash) ); // Update the sync state machine with the fact that the target of From 52f97d8da93d162c9a547699e775ec773b26a479 Mon Sep 17 00:00:00 2001 From: Pierre Krieger Date: Mon, 8 Jan 2024 10:37:08 +0100 Subject: [PATCH 07/14] Change `log` crate visibility --- light-base/src/json_rpc_service.rs | 3 +- light-base/src/json_rpc_service/background.rs | 4 +- .../json_rpc_service/background/chain_head.rs | 2 +- .../background/legacy_state_sub.rs | 2 + .../background/state_chain.rs | 2 +- light-base/src/lib.rs | 48 ----------------- light-base/src/network_service.rs | 5 +- light-base/src/network_service/tasks.rs | 5 +- light-base/src/platform.rs | 51 +++++++++++++++++++ light-base/src/runtime_service.rs | 2 +- light-base/src/sync_service.rs | 2 +- light-base/src/sync_service/parachain.rs | 2 +- light-base/src/sync_service/standalone.rs | 2 +- light-base/src/transactions_service.rs | 2 +- 14 files changed, 72 insertions(+), 60 deletions(-) diff --git a/light-base/src/json_rpc_service.rs b/light-base/src/json_rpc_service.rs index d27b1d79aa..d7430db788 100644 --- a/light-base/src/json_rpc_service.rs +++ b/light-base/src/json_rpc_service.rs @@ -40,7 +40,8 @@ mod background; use crate::{ - network_service, platform::PlatformRef, runtime_service, sync_service, transactions_service, + log, network_service, platform::PlatformRef, runtime_service, sync_service, + transactions_service, }; use alloc::{ diff --git a/light-base/src/json_rpc_service/background.rs b/light-base/src/json_rpc_service/background.rs index a3f8945a2a..5184fb6855 100644 --- a/light-base/src/json_rpc_service/background.rs +++ b/light-base/src/json_rpc_service/background.rs @@ -16,8 +16,8 @@ // along with this program. If not, see . use crate::{ - network_service, platform::PlatformRef, runtime_service, sync_service, transactions_service, - util, + log, network_service, platform::PlatformRef, runtime_service, sync_service, + transactions_service, util, }; use super::StartConfig; diff --git a/light-base/src/json_rpc_service/background/chain_head.rs b/light-base/src/json_rpc_service/background/chain_head.rs index d3996d0fb9..7ac9c4e613 100644 --- a/light-base/src/json_rpc_service/background/chain_head.rs +++ b/light-base/src/json_rpc_service/background/chain_head.rs @@ -19,7 +19,7 @@ use super::Background; -use crate::{platform::PlatformRef, runtime_service, sync_service}; +use crate::{log, platform::PlatformRef, runtime_service, sync_service}; use alloc::{ borrow::ToOwned as _, diff --git a/light-base/src/json_rpc_service/background/legacy_state_sub.rs b/light-base/src/json_rpc_service/background/legacy_state_sub.rs index fbd86d6ae6..0b39ff47d5 100644 --- a/light-base/src/json_rpc_service/background/legacy_state_sub.rs +++ b/light-base/src/json_rpc_service/background/legacy_state_sub.rs @@ -15,6 +15,8 @@ // You should have received a copy of the GNU General Public License // along with this program. If not, see . +use crate::log; + use core::{ future::Future, iter, diff --git a/light-base/src/json_rpc_service/background/state_chain.rs b/light-base/src/json_rpc_service/background/state_chain.rs index 2dbb9d2464..e6443e0795 100644 --- a/light-base/src/json_rpc_service/background/state_chain.rs +++ b/light-base/src/json_rpc_service/background/state_chain.rs @@ -19,7 +19,7 @@ use super::{legacy_state_sub, Background, GetKeysPagedCacheKey, PlatformRef}; -use crate::sync_service; +use crate::{log, sync_service}; use alloc::{format, string::ToString as _, sync::Arc, vec, vec::Vec}; use core::{iter, num::NonZeroU32, time::Duration}; diff --git a/light-base/src/lib.rs b/light-base/src/lib.rs index 0b33a5af7c..750b4f87d3 100644 --- a/light-base/src/lib.rs +++ b/light-base/src/lib.rs @@ -96,54 +96,6 @@ use smoldot::{ libp2p::{multiaddr, peer_id}, }; -macro_rules! log_inner { - () => { - core::iter::empty() - }; - (,) => { - core::iter::empty() - }; - ($key:ident = $value:expr) => { - log_inner!($key = $value,) - }; - ($key:ident = ?$value:expr) => { - log_inner!($key = ?$value,) - }; - ($key:ident) => { - log_inner!($key = $key,) - }; - (?$key:ident) => { - log_inner!($key = ?$key,) - }; - ($key:ident = $value:expr, $($rest:tt)*) => { - core::iter::once((stringify!($key), &$value as &dyn core::fmt::Display)).chain(log_inner!($($rest)*)) - }; - ($key:ident = ?$value:expr, $($rest:tt)*) => { - core::iter::once((stringify!($key), &format_args!("{:?}", $value) as &dyn core::fmt::Display)).chain(log_inner!($($rest)*)) - }; - ($key:ident, $($rest:tt)*) => { - log_inner!($key = $key, $($rest)*) - }; - (?$key:ident, $($rest:tt)*) => { - log_inner!($key = ?$key, $($rest)*) - }; -} - -macro_rules! log { - ($plat:expr, $level:ident, $target:expr, $message:expr) => { - log!($plat, $level, $target, $message,) - }; - ($plat:expr, $level:ident, $target:expr, $message:expr, $($params:tt)*) => { - $crate::platform::PlatformRef::log( - $plat, - $crate::platform::LogLevel::$level, - $target, - core::format_args!("{}", $message), - log_inner!($($params)*) - ) - }; -} - mod database; mod json_rpc_service; mod runtime_service; diff --git a/light-base/src/network_service.rs b/light-base/src/network_service.rs index 4cdceb1add..6ea6fd5e22 100644 --- a/light-base/src/network_service.rs +++ b/light-base/src/network_service.rs @@ -40,7 +40,10 @@ //! [`NetworkServiceChain::subscribe`]. These channels inform the foreground about updates to the //! network connectivity. -use crate::platform::{self, address_parse, PlatformRef}; +use crate::{ + log, + platform::{self, address_parse, PlatformRef}, +}; use alloc::{ borrow::ToOwned as _, diff --git a/light-base/src/network_service/tasks.rs b/light-base/src/network_service/tasks.rs index bbbbf22d39..6a02a689cb 100644 --- a/light-base/src/network_service/tasks.rs +++ b/light-base/src/network_service/tasks.rs @@ -15,7 +15,10 @@ // You should have received a copy of the GNU General Public License // along with this program. If not, see . -use crate::platform::{PlatformRef, SubstreamDirection}; +use crate::{ + log, + platform::{PlatformRef, SubstreamDirection}, +}; use alloc::{boxed::Box, string::String}; use core::{pin, time::Duration}; diff --git a/light-base/src/platform.rs b/light-base/src/platform.rs index 7f3a98dccd..7ea6aa06c2 100644 --- a/light-base/src/platform.rs +++ b/light-base/src/platform.rs @@ -470,3 +470,54 @@ pub enum IpAddr { V4([u8; 4]), V6([u8; 16]), } + +// TODO: find a way to keep this private somehow? +#[macro_export] +macro_rules! log_inner { + () => { + core::iter::empty() + }; + (,) => { + core::iter::empty() + }; + ($key:ident = $value:expr) => { + $crate::log_inner!($key = $value,) + }; + ($key:ident = ?$value:expr) => { + $crate::log_inner!($key = ?$value,) + }; + ($key:ident) => { + $crate::log_inner!($key = $key,) + }; + (?$key:ident) => { + $crate::log_inner!($key = ?$key,) + }; + ($key:ident = $value:expr, $($rest:tt)*) => { + core::iter::once((stringify!($key), &$value as &dyn core::fmt::Display)).chain($crate::log_inner!($($rest)*)) + }; + ($key:ident = ?$value:expr, $($rest:tt)*) => { + core::iter::once((stringify!($key), &format_args!("{:?}", $value) as &dyn core::fmt::Display)).chain($crate::log_inner!($($rest)*)) + }; + ($key:ident, $($rest:tt)*) => { + $crate::log_inner!($key = $key, $($rest)*) + }; + (?$key:ident, $($rest:tt)*) => { + $crate::log_inner!($key = ?$key, $($rest)*) + }; +} + +#[macro_export] +macro_rules! log { + ($plat:expr, $level:ident, $target:expr, $message:expr) => { + log!($plat, $level, $target, $message,) + }; + ($plat:expr, $level:ident, $target:expr, $message:expr, $($params:tt)*) => { + $crate::platform::PlatformRef::log( + $plat, + $crate::platform::LogLevel::$level, + $target, + core::format_args!("{}", $message), + $crate::log_inner!($($params)*) + ) + }; +} diff --git a/light-base/src/runtime_service.rs b/light-base/src/runtime_service.rs index 3f4f954eb9..86bac3293a 100644 --- a/light-base/src/runtime_service.rs +++ b/light-base/src/runtime_service.rs @@ -54,7 +54,7 @@ //! large, the subscription is force-killed by the [`RuntimeService`]. //! -use crate::{platform::PlatformRef, sync_service}; +use crate::{log, platform::PlatformRef, sync_service}; use alloc::{ borrow::ToOwned as _, diff --git a/light-base/src/sync_service.rs b/light-base/src/sync_service.rs index b497f17bc8..4a32fac1bf 100644 --- a/light-base/src/sync_service.rs +++ b/light-base/src/sync_service.rs @@ -26,7 +26,7 @@ //! //! Use [`SyncService::subscribe_all`] to get notified about updates to the state of the chain. -use crate::{network_service, platform::PlatformRef, runtime_service}; +use crate::{log, network_service, platform::PlatformRef, runtime_service}; use alloc::{borrow::ToOwned as _, boxed::Box, format, string::String, sync::Arc, vec::Vec}; use core::{cmp, fmt, future::Future, mem, num::NonZeroU32, pin::Pin, time::Duration}; diff --git a/light-base/src/sync_service/parachain.rs b/light-base/src/sync_service/parachain.rs index fec7b36015..54d6ddb4ec 100644 --- a/light-base/src/sync_service/parachain.rs +++ b/light-base/src/sync_service/parachain.rs @@ -16,7 +16,7 @@ // along with this program. If not, see . use super::ToBackground; -use crate::{network_service, platform::PlatformRef, runtime_service, util}; +use crate::{log, network_service, platform::PlatformRef, runtime_service, util}; use alloc::{borrow::ToOwned as _, boxed::Box, format, string::String, sync::Arc, vec::Vec}; use core::{ diff --git a/light-base/src/sync_service/standalone.rs b/light-base/src/sync_service/standalone.rs index 758ff9ede5..e4be5712bf 100644 --- a/light-base/src/sync_service/standalone.rs +++ b/light-base/src/sync_service/standalone.rs @@ -19,7 +19,7 @@ use super::{ BlockNotification, ConfigRelayChainRuntimeCodeHint, FinalizedBlockRuntime, Notification, SubscribeAll, ToBackground, }; -use crate::{network_service, platform::PlatformRef, util}; +use crate::{log, network_service, platform::PlatformRef, util}; use alloc::{ borrow::{Cow, ToOwned as _}, diff --git a/light-base/src/transactions_service.rs b/light-base/src/transactions_service.rs index e31b91362a..80f36fb20b 100644 --- a/light-base/src/transactions_service.rs +++ b/light-base/src/transactions_service.rs @@ -67,7 +67,7 @@ //! transaction. //! -use crate::{network_service, platform::PlatformRef, runtime_service, sync_service}; +use crate::{log, network_service, platform::PlatformRef, runtime_service, sync_service}; use alloc::{ borrow::ToOwned as _, From 9bc316b103152149e6fec4567e9e5c7e05a02d82 Mon Sep 17 00:00:00 2001 From: Pierre Krieger Date: Mon, 8 Jan 2024 10:52:17 +0100 Subject: [PATCH 08/14] Update implementation of DefaultPlatform --- light-base/src/platform/default.rs | 25 +++++++++++++++++++++++-- 1 file changed, 23 insertions(+), 2 deletions(-) diff --git a/light-base/src/platform/default.rs b/light-base/src/platform/default.rs index f2a37e4cd8..2003caadb2 100644 --- a/light-base/src/platform/default.rs +++ b/light-base/src/platform/default.rs @@ -37,7 +37,13 @@ use super::{ }; use alloc::{borrow::Cow, sync::Arc}; -use core::{fmt, panic, pin::Pin, str, time::Duration}; +use core::{ + fmt::{self, Write as _}, + panic, + pin::Pin, + str, + time::Duration, +}; use futures_util::{future, FutureExt as _}; use smoldot::libp2p::websocket; use std::{ @@ -160,6 +166,8 @@ impl PlatformRef for Arc { message: fmt::Arguments<'a>, key_values: impl Iterator, ) { + // Note that this conversion is most likely completely optimized out by the compiler due + // to log levels having the same numerical values. let log_level = match log_level { LogLevel::Error => log::Level::Error, LogLevel::Warn => log::Level::Warn, @@ -168,11 +176,24 @@ impl PlatformRef for Arc { LogLevel::Trace => log::Level::Trace, }; + let mut message_build = String::with_capacity(128); + let _ = write!(message_build, "{}", message); + let mut first = true; + for (key, value) in key_values { + if first { + let _ = write!(message_build, "; "); + first = false; + } else { + let _ = write!(message_build, ", "); + } + let _ = write!(message_build, "{}={}", key, value); + } + log::logger().log( &log::RecordBuilder::new() .level(log_level) .target(log_target) - .args(message) + .args(format_args!("{}", message_build)) .build(), ) } From 7a52dcac70d7b962b417ccd68657cc84058c7e68 Mon Sep 17 00:00:00 2001 From: Pierre Krieger Date: Mon, 8 Jan 2024 11:07:51 +0100 Subject: [PATCH 09/14] Use a `&str` for the message instead --- light-base/src/platform.rs | 4 ++-- light-base/src/platform/default.rs | 4 ++-- wasm-node/rust/src/init.rs | 6 +++--- wasm-node/rust/src/platform.rs | 15 ++++++++------- 4 files changed, 15 insertions(+), 14 deletions(-) diff --git a/light-base/src/platform.rs b/light-base/src/platform.rs index 7ea6aa06c2..9a8d9e96ea 100644 --- a/light-base/src/platform.rs +++ b/light-base/src/platform.rs @@ -153,7 +153,7 @@ pub trait PlatformRef: UnwindSafe + Clone + Send + Sync + 'static { &self, log_level: LogLevel, log_target: &'a str, - message: fmt::Arguments<'a>, + message: &'a str, key_values: impl Iterator, ); @@ -516,7 +516,7 @@ macro_rules! log { $plat, $crate::platform::LogLevel::$level, $target, - core::format_args!("{}", $message), + AsRef::::as_ref(&$message), $crate::log_inner!($($params)*) ) }; diff --git a/light-base/src/platform/default.rs b/light-base/src/platform/default.rs index 2003caadb2..c631228ac0 100644 --- a/light-base/src/platform/default.rs +++ b/light-base/src/platform/default.rs @@ -163,7 +163,7 @@ impl PlatformRef for Arc { &self, log_level: LogLevel, log_target: &'a str, - message: fmt::Arguments<'a>, + message: &'a str, key_values: impl Iterator, ) { // Note that this conversion is most likely completely optimized out by the compiler due @@ -177,7 +177,7 @@ impl PlatformRef for Arc { }; let mut message_build = String::with_capacity(128); - let _ = write!(message_build, "{}", message); + message_build.push_str(message); let mut first = true; for (key, value) in key_values { if first { diff --git a/wasm-node/rust/src/init.rs b/wasm-node/rust/src/init.rs index a505d3b2e9..ca7bbf73f5 100644 --- a/wasm-node/rust/src/init.rs +++ b/wasm-node/rust/src/init.rs @@ -17,7 +17,7 @@ use crate::{allocator, bindings, platform, timers::Delay}; -use alloc::{boxed::Box, string::String}; +use alloc::{boxed::Box, format, string::String}; use core::{iter, sync::atomic::Ordering, time::Duration}; use futures_util::stream; use smoldot::informant::BytesDisplay; @@ -63,7 +63,7 @@ pub(crate) fn init(max_log_level: u32) { platform::PLATFORM_REF.log( smoldot_light::platform::LogLevel::Info, "smoldot", - format_args!("Smoldot v{}", env!("CARGO_PKG_VERSION")), + &format!("Smoldot v{}", env!("CARGO_PKG_VERSION")), iter::empty(), ); @@ -101,7 +101,7 @@ pub(crate) fn init(max_log_level: u32) { platform::PLATFORM_REF.log( smoldot_light::platform::LogLevel::Info, "smoldot", - format_args!( + &format!( "Smoldot v{}. Current memory usage: {}. \ Average download: {}/s. Average upload: {}/s.", env!("CARGO_PKG_VERSION"), diff --git a/wasm-node/rust/src/platform.rs b/wasm-node/rust/src/platform.rs index de7c088cc7..0886212a68 100644 --- a/wasm-node/rust/src/platform.rs +++ b/wasm-node/rust/src/platform.rs @@ -25,6 +25,7 @@ use alloc::{ borrow::{Cow, ToOwned as _}, boxed::Box, collections::{BTreeMap, VecDeque}, + format, string::{String, ToString as _}, vec::Vec, }; @@ -153,7 +154,7 @@ impl smoldot_light::platform::PlatformRef for PlatformRef { &PLATFORM_REF, smoldot_light::platform::LogLevel::Debug, "smoldot", - format_args!("task-too-long-time"), + "task-too-long-time", [ ("name", this.name as &dyn fmt::Display), ( @@ -169,7 +170,7 @@ impl smoldot_light::platform::PlatformRef for PlatformRef { &PLATFORM_REF, smoldot_light::platform::LogLevel::Warn, "smoldot", - format_args!( + &format!( "The task named `{}` has occupied the CPU for an \ unreasonable amount of time ({}ms).", this.name, @@ -203,7 +204,7 @@ impl smoldot_light::platform::PlatformRef for PlatformRef { &self, log_level: smoldot_light::platform::LogLevel, log_target: &'a str, - message: fmt::Arguments<'a>, + message: &'a str, key_values: impl Iterator, ) { let log_level = match log_level { @@ -220,19 +221,19 @@ impl smoldot_light::platform::PlatformRef for PlatformRef { let mut key_values = key_values.peekable(); - if let (Some(static_message), None) = (message.as_str(), key_values.peek()) { + if key_values.peek().is_none() { unsafe { bindings::log( log_level, u32::try_from(log_target.as_bytes().as_ptr() as usize).unwrap(), u32::try_from(log_target.as_bytes().len()).unwrap(), - u32::try_from(static_message.as_bytes().as_ptr() as usize).unwrap(), - u32::try_from(static_message.as_bytes().len()).unwrap(), + u32::try_from(message.as_bytes().as_ptr() as usize).unwrap(), + u32::try_from(message.as_bytes().len()).unwrap(), ) } } else { let mut message_build = String::with_capacity(128); - let _ = write!(message_build, "{}", message); + message_build.push_str(message); let mut first = true; for (key, value) in key_values { if first { From 8324a61f6f8fae31f1c4b4f8c644dc6d330cf183 Mon Sep 17 00:00:00 2001 From: Pierre Krieger Date: Mon, 8 Jan 2024 11:14:59 +0100 Subject: [PATCH 10/14] Add documentation --- light-base/src/platform.rs | 34 ++++++++++++++++++++++++++++++++++ 1 file changed, 34 insertions(+) diff --git a/light-base/src/platform.rs b/light-base/src/platform.rs index 9a8d9e96ea..a677eda05b 100644 --- a/light-base/src/platform.rs +++ b/light-base/src/platform.rs @@ -149,6 +149,18 @@ pub trait PlatformRef: UnwindSafe + Clone + Send + Sync + 'static { ); /// Emit a log line. + /// + /// The `log_level` and `log_target` can be used in order to filter desired log lines. + /// + /// The `message` is typically a short constant message indicating the nature of the log line. + /// The `key_values` are a list of keys and values that are the parameters of the log message. + /// + /// For example, `message` can be `"block-announce-received"` and `key_values` can contain + /// the entries `("block_hash", ...)` and `("sender", ...)`. + /// + /// At the time of writing of this comment, `message` can also be a message written in plain + /// english and destined to the user of the library. This might disappear in the future. + // TODO: act on this last sentence ^ fn log<'a>( &self, log_level: LogLevel, @@ -506,6 +518,28 @@ macro_rules! log_inner { }; } +/// Helper macro for using the [`crate::platform::PlatformRef::log`] function. +/// +/// This macro takes at least 4 parameters: +/// +/// - A reference to an implementation of the [`crate::platform::PlatformRef`] trait. +/// - A log level: `Error`, `Warn`, `Info`, `Debug`, or `Trace`. See [`crate::platform::LogLevel`]. +/// - A `&str` representing the target of the logging. This can be used in order to filter log +/// entries belonging to a specific target. +/// - An object that implements of `AsRef` and that contains the log message itself. +/// +/// In addition to these parameters, the macro accepts an unlimited number of extra +/// (comma-separated) parameters. +/// +/// Each parameter has one of these four syntaxes: +/// +/// - `key = value`, where `key` is an identifier and `value` an expression that implements the +/// `Display` trait. +/// - `key = ?value`, where `key` is an identifier and `value` an expression that implements +/// the `Debug` trait. +/// - `key`, which is syntax sugar for `key = key`. +/// - `?key`, which is syntax sugar for `key = ?key`. +/// #[macro_export] macro_rules! log { ($plat:expr, $level:ident, $target:expr, $message:expr) => { From 59baadf929cbaed157719010cc185320dab8619a Mon Sep 17 00:00:00 2001 From: Pierre Krieger Date: Mon, 8 Jan 2024 11:16:37 +0100 Subject: [PATCH 11/14] Conditionally enable the `log` crate --- light-base/Cargo.toml | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/light-base/Cargo.toml b/light-base/Cargo.toml index 7fd4f14629..6c5e0beded 100644 --- a/light-base/Cargo.toml +++ b/light-base/Cargo.toml @@ -27,7 +27,6 @@ futures-util = { version = "0.3.27", default-features = false, features = ["allo hashbrown = { version = "0.14.0", default-features = false } hex = { version = "0.4.3", default-features = false } itertools = { version = "0.12.0", default-features = false, features = ["use_alloc"] } -log = { version = "0.4.18", default-features = false } lru = { version = "0.12.0", default-features = false, features = ["hashbrown"] } # The `hashbrown` feature brings no-std compatibility. no-std-net = { version = "0.6.0", default-features = false } pin-project = "1.1.3" @@ -43,11 +42,12 @@ zeroize = { version = "1.6.0", default-features = false, features = ["alloc"] } # `std` feature # Add here the crates that cannot function without the help of the operating system or environment. parking_lot = { version = "0.12.1", optional = true } +log = { version = "0.4.18", default-features = false, optional = true } smol = { version = "2.0.0", optional = true } [features] default = ["std", "wasmtime"] -std = ["dep:parking_lot", "dep:smol", "rand/std", "rand/std_rng", "smoldot/std"] +std = ["dep:parking_lot", "dep:log", "dep:smol", "rand/std", "rand/std_rng", "smoldot/std"] wasmtime = ["smoldot/wasmtime"] [dev-dependencies] From 1bdc149749c6c465c3bd70249d4b4b5ce2a61fe2 Mon Sep 17 00:00:00 2001 From: Pierre Krieger Date: Mon, 8 Jan 2024 11:23:40 +0100 Subject: [PATCH 12/14] CHANGELOG --- wasm-node/CHANGELOG.md | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/wasm-node/CHANGELOG.md b/wasm-node/CHANGELOG.md index 8908b12d37..b0b7b5f158 100644 --- a/wasm-node/CHANGELOG.md +++ b/wasm-node/CHANGELOG.md @@ -2,6 +2,10 @@ ## Unreleased +### Changed + +- Most of the log messages emitted by smoldot have been modified in order to unify their syntax and be easier to parse programatically. ([#1560](https://github.com/smol-dot/smoldot/pull/1560)) + ### Fixed - Fix the nodes discovery process being slow for chains that are added long after the smoldot client has started. This was caused by the fact that the discovery was started at the same time for all chains, and that this discovery intentionally slows down over time. The discovery is now performed and slowed down for each chain individually. ([#1544](https://github.com/smol-dot/smoldot/pull/1544)) From afc66f9feea9721387cfa489fcbdacc87f93fb04 Mon Sep 17 00:00:00 2001 From: Pierre Krieger Date: Mon, 8 Jan 2024 12:16:23 +0100 Subject: [PATCH 13/14] Document using the `log` crate --- light-base/src/platform/default.rs | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/light-base/src/platform/default.rs b/light-base/src/platform/default.rs index c631228ac0..ea2145e210 100644 --- a/light-base/src/platform/default.rs +++ b/light-base/src/platform/default.rs @@ -22,6 +22,10 @@ //! //! This module contains the [`DefaultPlatform`] struct, which implements [`PlatformRef`]. //! +//! The [`DefaultPlatform`] delegates the logging to the `log` crate. In order to see log +//! messages, you should register as "logger" as documented by the `log` crate. +//! See . +//! //! # Example //! //! ```rust From 6871a032b1213ca750751986ed433a5c20a94dae Mon Sep 17 00:00:00 2001 From: Pierre Krieger Date: Mon, 8 Jan 2024 12:17:27 +0100 Subject: [PATCH 14/14] Register a logger in the doctest --- light-base/src/platform/default.rs | 1 + 1 file changed, 1 insertion(+) diff --git a/light-base/src/platform/default.rs b/light-base/src/platform/default.rs index ea2145e210..c829390fe8 100644 --- a/light-base/src/platform/default.rs +++ b/light-base/src/platform/default.rs @@ -30,6 +30,7 @@ //! //! ```rust //! use smoldot_light::{Client, platform::DefaultPlatform}; +//! env_logger::Builder::from_env(env_logger::Env::default().default_filter_or("info")).init(); //! let client = Client::new(DefaultPlatform::new(env!("CARGO_PKG_NAME").into(), env!("CARGO_PKG_VERSION").into())); //! # let _: Client<_, ()> = client; // Used in this example to infer the generic parameters of the Client //! ```