diff --git a/.gitlab-ci.yml b/.gitlab-ci.yml index 56ac4c7f9487d..ec22c993031bf 100644 --- a/.gitlab-ci.yml +++ b/.gitlab-ci.yml @@ -336,6 +336,9 @@ check-web-wasm: - time cargo build --target=wasm32-unknown-unknown -p sc-telemetry # Note: the command below is a bit weird because several Cargo issues prevent us from compiling the node in a more straight-forward way. - time cargo +nightly build --manifest-path=bin/node/cli/Cargo.toml --no-default-features --features browser --target=wasm32-unknown-unknown -Z features=itarget + # with-tracing must be explicitly activated, we run a test to ensure this works as expected in both cases + - time cargo +nightly test --manifest-path primitives/tracing/Cargo.toml --no-default-features + - time cargo +nightly test --manifest-path primitives/tracing/Cargo.toml --no-default-features --features=with-tracing - sccache -s test-full-crypto-feature: diff --git a/Cargo.lock b/Cargo.lock index 38904fb98e727..5a35650712e3f 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6019,27 +6019,6 @@ dependencies = [ "winapi 0.3.9", ] -[[package]] -name = "rental" -version = "0.5.5" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "8545debe98b2b139fb04cad8618b530e9b07c152d99a5de83c860b877d67847f" -dependencies = [ - "rental-impl", - "stable_deref_trait", -] - -[[package]] -name = "rental-impl" -version = "0.5.5" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "475e68978dc5b743f2f40d8e0a8fdc83f1c5e78cbf4b8fa5e74e73beebc340de" -dependencies = [ - "proc-macro2", - "quote", - "syn", -] - [[package]] name = "retain_mut" version = "0.1.1" @@ -7203,6 +7182,7 @@ dependencies = [ "sp-runtime", "sp-session", "sp-state-machine", + "sp-tracing", "sp-transaction-pool", "sp-trie", "sp-utils", @@ -7298,6 +7278,7 @@ dependencies = [ "slog", "sp-tracing", "tracing", + "tracing-core", "tracing-subscriber", ] @@ -8148,6 +8129,8 @@ dependencies = [ "sp-tracing", "sp-trie", "sp-wasm-interface", + "tracing", + "tracing-core", ] [[package]] @@ -8291,6 +8274,7 @@ dependencies = [ "sp-runtime-interface-test-wasm-deprecated", "sp-state-machine", "tracing", + "tracing-core", ] [[package]] @@ -8427,8 +8411,10 @@ name = "sp-tracing" version = "2.0.0-rc6" dependencies = [ "log", - "rental", + "parity-scale-codec", + "sp-std", "tracing", + "tracing-core", "tracing-subscriber", ] @@ -9383,9 +9369,9 @@ checksum = "e987b6bf443f4b5b3b6f38704195592cca41c5bb7aedd3c3693c7081f8289860" [[package]] name = "tracing" -version = "0.1.18" +version = "0.1.19" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f0aae59226cf195d8e74d4b34beae1859257efb4e5fed3f147d2dc2c7d372178" +checksum = "6d79ca061b032d6ce30c660fded31189ca0b9922bf483cd70759f13a2d86786c" dependencies = [ "cfg-if", "log", @@ -9406,9 +9392,9 @@ dependencies = [ [[package]] name = "tracing-core" -version = "0.1.12" +version = "0.1.16" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "b2734b5a028fa697686f16c6d18c2c6a3c7e41513f9a213abb6754c4acb3c8d7" +checksum = "5bcf46c1f1f06aeea2d6b81f3c863d0930a596c86ad1920d4e5bad6dd1d7119a" dependencies = [ "lazy_static", ] @@ -9516,9 +9502,9 @@ checksum = "59547bce71d9c38b83d9c0e92b6066c4253371f15005def0c30d9657f50c7642" [[package]] name = "trybuild" -version = "1.0.30" +version = "1.0.35" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "bbe777c4e2060f44d83892be1189f96200be8ed3d99569d5c2d5ee26e62c0ea9" +checksum = "b7d30fe369fd650072b352b1a9cb9587669de6b89be3b8225544012c1c45292d" dependencies = [ "dissimilar", "glob", diff --git a/bin/node/cli/Cargo.toml b/bin/node/cli/Cargo.toml index fdc63f09555bb..26894a9115c89 100644 --- a/bin/node/cli/Cargo.toml +++ b/bin/node/cli/Cargo.toml @@ -41,7 +41,7 @@ hex-literal = "0.3.1" log = "0.4.8" rand = "0.7.2" structopt = { version = "0.3.8", optional = true } -tracing = "0.1.18" +tracing = "0.1.19" parking_lot = "0.10.0" # primitives diff --git a/bin/node/runtime/Cargo.toml b/bin/node/runtime/Cargo.toml index 1195456b0fada..ed8ae0c1d4b0b 100644 --- a/bin/node/runtime/Cargo.toml +++ b/bin/node/runtime/Cargo.toml @@ -88,6 +88,7 @@ sp-io = { version = "2.0.0-rc6", path = "../../../primitives/io" } [features] default = ["std"] +with-tracing = [ "frame-executive/with-tracing" ] std = [ "sp-authority-discovery/std", "pallet-authority-discovery/std", diff --git a/client/executor/Cargo.toml b/client/executor/Cargo.toml index a60bff877d71e..b0f420de4f068 100644 --- a/client/executor/Cargo.toml +++ b/client/executor/Cargo.toml @@ -46,7 +46,7 @@ test-case = "0.3.3" sp-runtime = { version = "2.0.0-rc6", path = "../../primitives/runtime" } sp-tracing = { version = "2.0.0-rc6", path = "../../primitives/tracing" } sc-tracing = { version = "2.0.0-rc6", path = "../tracing" } -tracing = "0.1.18" +tracing = "0.1.19" tracing-subscriber = "0.2.10" [features] diff --git a/client/executor/runtime-test/Cargo.toml b/client/executor/runtime-test/Cargo.toml index 037359ac9eef6..dddbb780ca808 100644 --- a/client/executor/runtime-test/Cargo.toml +++ b/client/executor/runtime-test/Cargo.toml @@ -29,5 +29,7 @@ std = [ "sp-io/std", "sp-sandbox/std", "sp-std/std", + "sp-core/std", + "sp-runtime/std", "sp-allocator/std", ] diff --git a/client/executor/runtime-test/build.rs b/client/executor/runtime-test/build.rs index 1ed5aa44bc5c4..cf4fca01acd9f 100644 --- a/client/executor/runtime-test/build.rs +++ b/client/executor/runtime-test/build.rs @@ -17,10 +17,21 @@ use wasm_builder_runner::WasmBuilder; fn main() { + // regular build WasmBuilder::new() .with_current_project() .with_wasm_builder_from_crates_or_path("2.0.0", "../../../utils/wasm-builder") .export_heap_base() .import_memory() - .build() + .build(); + + // and building with tracing activated + WasmBuilder::new() + .with_current_project() + .with_wasm_builder_from_crates_or_path("2.0.0", "../../../utils/wasm-builder") + .export_heap_base() + .import_memory() + .set_file_name("wasm_binary_with_tracing.rs") + .append_to_rust_flags("--cfg feature=\\\"with-tracing\\\"") + .build(); } diff --git a/client/executor/runtime-test/src/lib.rs b/client/executor/runtime-test/src/lib.rs index a80ee1d6ba40f..04397afd776d7 100644 --- a/client/executor/runtime-test/src/lib.rs +++ b/client/executor/runtime-test/src/lib.rs @@ -254,11 +254,11 @@ sp_core::wasm_export_functions! { } fn test_enter_span() -> u64 { - wasm_tracing::enter_span("integration_test_span_target", "integration_test_span_name") + wasm_tracing::enter_span(Default::default()) } fn test_exit_span(span_id: u64) { - wasm_tracing::exit_span(span_id) + wasm_tracing::exit(span_id) } fn returns_mutable_static() -> u64 { diff --git a/client/executor/src/integration_tests/mod.rs b/client/executor/src/integration_tests/mod.rs index 1c744f544b48f..3ff676fdbe61f 100644 --- a/client/executor/src/integration_tests/mod.rs +++ b/client/executor/src/integration_tests/mod.rs @@ -681,7 +681,7 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { // Create subscriber with wasm_tracing disabled let test_subscriber = tracing_subscriber::fmt().finish().with( sc_tracing::ProfilingLayer::new_with_handler( - Box::new(handler), "integration_test_span_target" + Box::new(handler), "default" ) ); @@ -690,49 +690,9 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { let mut ext = TestExternalities::default(); let mut ext = ext.ext(); - // Test tracing disabled - assert!(!sp_tracing::wasm_tracing_enabled()); - - let span_id = call_in_wasm( - "test_enter_span", - &[], - wasm_method, - &mut ext, - ).unwrap(); - - assert_eq!( - 0u64.encode(), - span_id - ); - // Repeat to check span id always 0 when deactivated - let span_id = call_in_wasm( - "test_enter_span", - &[], - wasm_method, - &mut ext, - ).unwrap(); - - assert_eq!( - 0u64.encode(), - span_id - ); - - call_in_wasm( - "test_exit_span", - &span_id.encode(), - wasm_method, - &mut ext, - ).unwrap(); - // Check span has not been recorded - let len = traces.lock().unwrap().len(); - assert_eq!(len, 0); - - // Test tracing enabled - sp_tracing::set_wasm_tracing(true); - let span_id = call_in_wasm( "test_enter_span", - &[], + Default::default(), wasm_method, &mut ext, ).unwrap(); @@ -756,8 +716,7 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { let span_datum = traces.lock().unwrap().pop().unwrap(); let values = span_datum.values; - assert_eq!(span_datum.target, "integration_test_span_target"); - assert_eq!(span_datum.name, "integration_test_span_name"); + assert_eq!(span_datum.target, "default"); + assert_eq!(span_datum.name, ""); assert_eq!(values.bool_values.get("wasm").unwrap(), &true); - assert_eq!(values.bool_values.get("is_valid_trace").unwrap(), &true); } diff --git a/client/service/Cargo.toml b/client/service/Cargo.toml index 370ee679154e3..fb9d489adf480 100644 --- a/client/service/Cargo.toml +++ b/client/service/Cargo.toml @@ -73,7 +73,8 @@ sc-telemetry = { version = "2.0.0-rc6", path = "../telemetry" } sc-offchain = { version = "2.0.0-rc6", path = "../offchain" } prometheus-endpoint = { package = "substrate-prometheus-endpoint", path = "../../utils/prometheus", version = "0.8.0-rc6"} sc-tracing = { version = "2.0.0-rc6", path = "../tracing" } -tracing = "0.1.18" +sp-tracing = { version = "2.0.0-rc6", path = "../../primitives/tracing" } +tracing = "0.1.19" parity-util-mem = { version = "0.7.0", default-features = false, features = ["primitive-types"] } [target.'cfg(not(target_os = "unknown"))'.dependencies] diff --git a/client/tracing/Cargo.toml b/client/tracing/Cargo.toml index 9444a9520f665..42d6fc5b34667 100644 --- a/client/tracing/Cargo.toml +++ b/client/tracing/Cargo.toml @@ -19,7 +19,8 @@ rustc-hash = "1.1.0" serde = "1.0.101" serde_json = "1.0.41" slog = { version = "2.5.2", features = ["nested-values"] } -tracing = "0.1.18" +tracing = "0.1.19" +tracing-core = "0.1.13" tracing-subscriber = "0.2.10" sp-tracing = { version = "2.0.0-rc6", path = "../../primitives/tracing" } sc-telemetry = { version = "2.0.0-rc6", path = "../telemetry" } diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index e509f2218a2ea..6690f283464ea 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -40,8 +40,7 @@ use tracing::{ use tracing_subscriber::{CurrentSpan, layer::{Layer, Context}}; use sc_telemetry::{telemetry, SUBSTRATE_INFO}; -use sp_tracing::proxy::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER}; - +use sp_tracing::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER}; const ZERO_DURATION: Duration = Duration::from_nanos(0); /// Responsible for assigning ids to new spans, which are not re-used. @@ -275,12 +274,6 @@ impl Layer for ProfilingLayer { fn new_span(&self, attrs: &Attributes<'_>, id: &Id, _ctx: Context) { let mut values = Values::default(); attrs.record(&mut values); - // If this is a wasm trace, check if target/level is enabled - if let Some(wasm_target) = values.string_values.get(WASM_TARGET_KEY) { - if !self.check_target(wasm_target, attrs.metadata().level()) { - return - } - } let span_datum = SpanDatum { id: id.clone(), parent_id: attrs.parent().cloned().or_else(|| self.current_span.id()), @@ -327,18 +320,13 @@ impl Layer for ProfilingLayer { fn on_exit(&self, span: &Id, _ctx: Context) { self.current_span.exit(); let end_time = Instant::now(); - let mut span_data = self.span_data.lock(); - if let Some(mut s) = span_data.get_mut(&span) { - s.overall_time = end_time - s.start_time + s.overall_time; - } - } - - fn on_close(&self, span: Id, _ctx: Context) { let span_datum = { let mut span_data = self.span_data.lock(); span_data.remove(&span) }; + if let Some(mut span_datum) = span_datum { + span_datum.overall_time += end_time - span_datum.start_time; if span_datum.name == WASM_TRACE_IDENTIFIER { span_datum.values.bool_values.insert("wasm".to_owned(), true); if let Some(n) = span_datum.values.string_values.remove(WASM_NAME_KEY) { @@ -355,6 +343,10 @@ impl Layer for ProfilingLayer { } }; } + + fn on_close(&self, span: Id, ctx: Context) { + self.on_exit(&span, ctx) + } } /// TraceHandler for sending span data to the logger diff --git a/client/transaction-pool/src/api.rs b/client/transaction-pool/src/api.rs index c6671fd5bd7f0..853b66f6e74bb 100644 --- a/client/transaction-pool/src/api.rs +++ b/client/transaction-pool/src/api.rs @@ -168,23 +168,28 @@ where Client::Api: TaggedTransactionQueue, sp_api::ApiErrorFor: Send + std::fmt::Display, { - sp_tracing::enter_span!("validate_transaction"); - let runtime_api = client.runtime_api(); - let has_v2 = sp_tracing::tracing_span! { "check_version"; - runtime_api - .has_api_with::, _>(&at, |v| v >= 2) - .unwrap_or_default() - }; - - sp_tracing::enter_span!("runtime::validate_transaction"); - let res = if has_v2 { - runtime_api.validate_transaction(&at, source, uxt) - } else { - #[allow(deprecated)] // old validate_transaction - runtime_api.validate_transaction_before_version_2(&at, uxt) - }; - - res.map_err(|e| Error::RuntimeApi(e.to_string())) + sp_tracing::within_span!(sp_tracing::Level::TRACE, "validate_transaction"; + { + let runtime_api = client.runtime_api(); + let has_v2 = sp_tracing::within_span! { sp_tracing::Level::TRACE, "check_version"; + runtime_api + .has_api_with::, _>(&at, |v| v >= 2) + .unwrap_or_default() + }; + + let res = sp_tracing::within_span!( + sp_tracing::Level::TRACE, "runtime::validate_transaction"; + { + if has_v2 { + runtime_api.validate_transaction(&at, source, uxt) + } else { + #[allow(deprecated)] // old validate_transaction + runtime_api.validate_transaction_before_version_2(&at, uxt) + } + }); + + res.map_err(|e| Error::RuntimeApi(e.to_string())) + }) } impl FullChainApi diff --git a/frame/executive/Cargo.toml b/frame/executive/Cargo.toml index 8114f74b8fe67..76a9251e546de 100644 --- a/frame/executive/Cargo.toml +++ b/frame/executive/Cargo.toml @@ -20,6 +20,7 @@ sp-runtime = { version = "2.0.0-rc6", default-features = false, path = "../../pr sp-tracing = { version = "2.0.0-rc6", default-features = false, path = "../../primitives/tracing" } sp-std = { version = "2.0.0-rc6", default-features = false, path = "../../primitives/std" } sp-io = { version = "2.0.0-rc6", default-features = false, path = "../../primitives/io" } +sp-core = { version = "2.0.0-rc6", default-features = false, path = "../../primitives/core" } [dev-dependencies] hex-literal = "0.3.1" @@ -32,11 +33,15 @@ sp-version = { version = "2.0.0-rc6", path = "../../primitives/version" } [features] default = ["std"] +with-tracing = [ + "sp-tracing/with-tracing" +] std = [ "codec/std", "frame-support/std", "frame-system/std", "serde", + "sp-core/std", "sp-runtime/std", "sp-tracing/std", "sp-std/std", diff --git a/frame/executive/src/lib.rs b/frame/executive/src/lib.rs index 24dccf8b0b4a4..5f370643094f8 100644 --- a/frame/executive/src/lib.rs +++ b/frame/executive/src/lib.rs @@ -207,6 +207,8 @@ where { /// Start the execution of a particular block. pub fn initialize_block(header: &System::Header) { + sp_io::init_tracing(); + sp_tracing::enter_span!(sp_tracing::Level::TRACE, "init_block"); let digests = Self::extract_pre_digest(&header); Self::initialize_block_impl( header.number(), @@ -270,6 +272,7 @@ where } fn initial_checks(block: &Block) { + sp_tracing::enter_span!(sp_tracing::Level::TRACE, "initial_checks"); let header = block.header(); // Check that `parent_hash` is correct. @@ -288,23 +291,28 @@ where /// Actually execute all transitions for `block`. pub fn execute_block(block: Block) { - Self::initialize_block(block.header()); + sp_io::init_tracing(); + sp_tracing::within_span! { + sp_tracing::info_span!( "execute_block", ?block); + { + Self::initialize_block(block.header()); - // any initial checks - Self::initial_checks(&block); + // any initial checks + Self::initial_checks(&block); - let signature_batching = sp_runtime::SignatureBatching::start(); + let signature_batching = sp_runtime::SignatureBatching::start(); - // execute extrinsics - let (header, extrinsics) = block.deconstruct(); - Self::execute_extrinsics_with_book_keeping(extrinsics, *header.number()); + // execute extrinsics + let (header, extrinsics) = block.deconstruct(); + Self::execute_extrinsics_with_book_keeping(extrinsics, *header.number()); - if !signature_batching.verify() { - panic!("Signature verification failed."); - } + if !signature_batching.verify() { + panic!("Signature verification failed."); + } - // any final checks - Self::final_checks(&header); + // any final checks + Self::final_checks(&header); + } }; } /// Execute given extrinsics and take care of post-extrinsics book-keeping. @@ -320,6 +328,8 @@ where /// Finalize the block - it is up the caller to ensure that all header fields are valid /// except state-root. pub fn finalize_block() -> System::Header { + sp_io::init_tracing(); + sp_tracing::enter_span!( sp_tracing::Level::TRACE, "finalize_block" ); >::note_finished_extrinsics(); let block_number = >::block_number(); as OnFinalize>::on_finalize(block_number); @@ -335,6 +345,7 @@ where /// This doesn't attempt to validate anything regarding the block, but it builds a list of uxt /// hashes. pub fn apply_extrinsic(uxt: Block::Extrinsic) -> ApplyExtrinsicResult { + sp_io::init_tracing(); let encoded = uxt.encode(); let encoded_len = encoded.len(); Self::apply_extrinsic_with_len(uxt, encoded_len, Some(encoded)) @@ -355,6 +366,10 @@ where encoded_len: usize, to_note: Option>, ) -> ApplyExtrinsicResult { + sp_tracing::enter_span!( + sp_tracing::info_span!("apply_extrinsic", + ext=?sp_core::hexdisplay::HexDisplay::from(&uxt.encode())) + ); // Verify that the signature is good. let xt = uxt.check(&Default::default())?; @@ -377,6 +392,7 @@ where } fn final_checks(header: &System::Header) { + sp_tracing::enter_span!(sp_tracing::Level::TRACE, "final_checks"); // remove temporaries let new_header = >::finalize(); @@ -406,24 +422,32 @@ where source: TransactionSource, uxt: Block::Extrinsic, ) -> TransactionValidity { - use sp_tracing::tracing_span; + sp_io::init_tracing(); + use sp_tracing::{enter_span, within_span}; - sp_tracing::enter_span!("validate_transaction"); + enter_span!{ sp_tracing::Level::TRACE, "validate_transaction" }; - let encoded_len = tracing_span!{ "using_encoded"; uxt.using_encoded(|d| d.len()) }; + let encoded_len = within_span!{ sp_tracing::Level::TRACE, "using_encoded"; + uxt.using_encoded(|d| d.len()) + }; - let xt = tracing_span!{ "check"; uxt.check(&Default::default())? }; + let xt = within_span!{ sp_tracing::Level::TRACE, "check"; + uxt.check(&Default::default()) + }?; - let dispatch_info = tracing_span!{ "dispatch_info"; xt.get_dispatch_info() }; + let dispatch_info = within_span!{ sp_tracing::Level::TRACE, "dispatch_info"; + xt.get_dispatch_info() + }; - tracing_span! { - "validate"; + within_span! { + sp_tracing::Level::TRACE, "validate"; xt.validate::(source, &dispatch_info, encoded_len) } } /// Start an offchain worker and generate extrinsics. pub fn offchain_worker(header: &System::Header) { + sp_io::init_tracing(); // We need to keep events available for offchain workers, // hence we initialize the block manually. // OffchainWorker RuntimeApi should skip initialization. diff --git a/frame/support/src/debug.rs b/frame/support/src/debug.rs index e4a48068460c6..86b40f1664dcf 100644 --- a/frame/support/src/debug.rs +++ b/frame/support/src/debug.rs @@ -87,11 +87,11 @@ //! native::print!("My struct: {:?}", x); //! ``` -use sp_std::vec::Vec; use sp_std::fmt::{self, Debug}; pub use log::{info, debug, error, trace, warn}; pub use crate::runtime_print as print; +pub use sp_std::Writer; /// Native-only logging. /// @@ -132,9 +132,9 @@ macro_rules! runtime_print { ($($arg:tt)+) => { { use core::fmt::Write; - let mut w = $crate::debug::Writer::default(); + let mut w = $crate::sp_std::Writer::default(); let _ = core::write!(&mut w, $($arg)+); - w.print(); + sp_io::misc::print_utf8(&w.inner()) } } } @@ -144,24 +144,6 @@ pub fn debug(data: &impl Debug) { runtime_print!("{:?}", data); } -/// A target for `core::write!` macro - constructs a string in memory. -#[derive(Default)] -pub struct Writer(Vec); - -impl fmt::Write for Writer { - fn write_str(&mut self, s: &str) -> fmt::Result { - self.0.extend(s.as_bytes()); - Ok(()) - } -} - -impl Writer { - /// Print the content of this `Writer` out. - pub fn print(&self) { - sp_io::misc::print_utf8(&self.0) - } -} - /// Runtime logger implementation - `log` crate backend. /// /// The logger should be initialized if you want to display @@ -204,13 +186,13 @@ impl log::Log for RuntimeLogger { fn log(&self, record: &log::Record) { use fmt::Write; - let mut w = Writer::default(); + let mut w = sp_std::Writer::default(); let _ = core::write!(&mut w, "{}", record.args()); sp_io::logging::log( record.level().into(), record.target(), - &w.0, + w.inner(), ); } diff --git a/frame/support/src/dispatch.rs b/frame/support/src/dispatch.rs index 5446b4a59bd66..ca0a78d730b7c 100644 --- a/frame/support/src/dispatch.rs +++ b/frame/support/src/dispatch.rs @@ -1275,7 +1275,7 @@ macro_rules! decl_module { for $module<$trait_instance$(, $instance)?> where $( $other_where_bounds )* { fn on_initialize(_block_number_not_used: <$trait_instance as $system::Trait>::BlockNumber) -> $return { - $crate::sp_tracing::enter_span!("on_initialize"); + $crate::sp_tracing::enter_span!($crate::sp_tracing::trace_span!("on_initialize")); { $( $impl )* } } } @@ -1292,7 +1292,7 @@ macro_rules! decl_module { for $module<$trait_instance$(, $instance)?> where $( $other_where_bounds )* { fn on_initialize($param: $param_ty) -> $return { - $crate::sp_tracing::enter_span!("on_initialize"); + $crate::sp_tracing::enter_span!($crate::sp_tracing::trace_span!("on_initialize")); { $( $impl )* } } } @@ -1319,7 +1319,7 @@ macro_rules! decl_module { for $module<$trait_instance$(, $instance)?> where $( $other_where_bounds )* { fn on_runtime_upgrade() -> $return { - $crate::sp_tracing::enter_span!("on_runtime_upgrade"); + $crate::sp_tracing::enter_span!($crate::sp_tracing::trace_span!("on_runtime_upgrade")); { $( $impl )* } } } @@ -1375,7 +1375,7 @@ macro_rules! decl_module { for $module<$trait_instance$(, $instance)?> where $( $other_where_bounds )* { fn on_finalize(_block_number_not_used: <$trait_instance as $system::Trait>::BlockNumber) { - $crate::sp_tracing::enter_span!("on_finalize"); + $crate::sp_tracing::enter_span!($crate::sp_tracing::trace_span!("on_finalize")); { $( $impl )* } } } @@ -1392,7 +1392,7 @@ macro_rules! decl_module { for $module<$trait_instance$(, $instance)?> where $( $other_where_bounds )* { fn on_finalize($param: $param_ty) { - $crate::sp_tracing::enter_span!("on_finalize"); + $crate::sp_tracing::enter_span!($crate::sp_tracing::trace_span!("on_finalize")); { $( $impl )* } } } @@ -1465,7 +1465,7 @@ macro_rules! decl_module { $vis fn $name( $origin: $origin_ty $(, $param: $param_ty )* ) -> $crate::dispatch::DispatchResult { - $crate::sp_tracing::enter_span!(stringify!($name)); + $crate::sp_tracing::enter_span!($crate::sp_tracing::trace_span!(stringify!($name))); { $( $impl )* } Ok(()) } @@ -1484,7 +1484,7 @@ macro_rules! decl_module { ) => { $(#[$fn_attr])* $vis fn $name($origin: $origin_ty $(, $param: $param_ty )* ) -> $result { - $crate::sp_tracing::enter_span!(stringify!($name)); + $crate::sp_tracing::enter_span!($crate::sp_tracing::trace_span!(stringify!($name))); $( $impl )* } }; diff --git a/frame/support/test/Cargo.toml b/frame/support/test/Cargo.toml index f2f70fb95279e..7c839e4462ad1 100644 --- a/frame/support/test/Cargo.toml +++ b/frame/support/test/Cargo.toml @@ -21,7 +21,7 @@ sp-inherents = { version = "2.0.0-rc6", default-features = false, path = "../../ sp-runtime = { version = "2.0.0-rc6", default-features = false, path = "../../../primitives/runtime" } sp-core = { version = "2.0.0-rc6", default-features = false, path = "../../../primitives/core" } sp-std = { version = "2.0.0-rc6", default-features = false, path = "../../../primitives/std" } -trybuild = "1.0.17" +trybuild = "1.0.33" pretty_assertions = "0.6.1" rustversion = "1.0.0" diff --git a/primitives/arithmetic/src/biguint.rs b/primitives/arithmetic/src/biguint.rs index 41e2c759a5967..1fed54f598eec 100644 --- a/primitives/arithmetic/src/biguint.rs +++ b/primitives/arithmetic/src/biguint.rs @@ -18,7 +18,7 @@ //! Infinite precision unsigned integer for substrate runtime. use num_traits::Zero; -use sp_std::{cmp::Ordering, ops, prelude::*, cell::RefCell, convert::TryFrom}; +use sp_std::{cmp::Ordering, ops, prelude::*, vec, cell::RefCell, convert::TryFrom}; // A sensible value for this would be half of the dword size of the host machine. Since the // runtime is compiled to 32bit webassembly, using 32 and 64 for single and double respectively diff --git a/primitives/io/Cargo.toml b/primitives/io/Cargo.toml index a08451db24389..06672190e7fe3 100644 --- a/primitives/io/Cargo.toml +++ b/primitives/io/Cargo.toml @@ -28,6 +28,8 @@ sp-tracing = { version = "2.0.0-rc6", default-features = false, path = "../traci log = { version = "0.4.8", optional = true } futures = { version = "0.3.1", features = ["thread-pool"], optional = true } parking_lot = { version = "0.10.0", optional = true } +tracing = { version = "0.1.19", default-features = false } +tracing-core = { version = "0.1.15", default-features = false} [features] default = ["std"] @@ -42,11 +44,18 @@ std = [ "sp-runtime-interface/std", "sp-externalities", "sp-wasm-interface/std", + "sp-tracing/std", + "tracing/std", + "tracing-core/std", "log", "futures", "parking_lot", ] +with-tracing = [ + "sp-tracing/with-tracing" +] + # These two features are used for `no_std` builds for the environments which already provides # `#[panic_handler]`, `#[alloc_error_handler]` and `#[global_allocator]`. # diff --git a/primitives/io/src/lib.rs b/primitives/io/src/lib.rs index 9c4a0c59b51c2..2e7cb3e7efad9 100644 --- a/primitives/io/src/lib.rs +++ b/primitives/io/src/lib.rs @@ -32,6 +32,9 @@ use sp_std::vec::Vec; #[cfg(feature = "std")] use sp_std::ops::Deref; +#[cfg(feature = "std")] +use tracing; + #[cfg(feature = "std")] use sp_core::{ crypto::Pair, @@ -52,6 +55,7 @@ use sp_core::{ use sp_trie::{TrieConfiguration, trie_types::Layout}; use sp_runtime_interface::{runtime_interface, Pointer}; +use sp_runtime_interface::pass_by::PassBy; use codec::{Encode, Decode}; @@ -1004,55 +1008,156 @@ pub trait Logging { } } -#[cfg(feature = "std")] -sp_externalities::decl_extension! { - /// Extension to allow running traces in wasm via Proxy - pub struct TracingProxyExt(sp_tracing::proxy::TracingProxy); +#[derive(Encode, Decode)] +/// Crossing is a helper wrapping any Encode-Decodeable type +/// for transferring over the wasm barrier. +pub struct Crossing(T); + +impl PassBy for Crossing { + type PassBy = sp_runtime_interface::pass_by::Codec; } -/// Interface that provides functions for profiling the runtime. -#[runtime_interface] +impl Crossing { + + /// Convert into the inner type + pub fn into_inner(self) -> T { + self.0 + } +} + +// useful for testing +impl core::default::Default for Crossing + where T: core::default::Default + Encode + Decode +{ + fn default() -> Self { + Self(Default::default()) + } + +} + +/// Interface to provide tracing facilities for wasm. Modelled after tokios `tracing`-crate +/// interfaces. See `sp-tracing` for more information. +#[runtime_interface(wasm_only, no_tracing)] pub trait WasmTracing { - /// To create and enter a `tracing` span, using `sp_tracing::proxy` - /// Returns 0 value to indicate that no further traces should be attempted - fn enter_span(&mut self, target: &str, name: &str) -> u64 { - if sp_tracing::wasm_tracing_enabled() { - match self.extension::() { - Some(proxy) => return proxy.enter_span(target, name), - None => { - if self.register_extension(TracingProxyExt(sp_tracing::proxy::TracingProxy::new())).is_ok() { - if let Some(proxy) = self.extension::() { - return proxy.enter_span(target, name); - } - } else { - log::warn!( - target: "tracing", - "Unable to register extension: TracingProxyExt" - ); - } - } + /// Whether the span described in `WasmMetadata` should be traced wasm-side + /// On the host converts into a static Metadata and checks against the global `tracing` dispatcher. + /// + /// When returning false the calling code should skip any tracing-related execution. In general + /// within the same block execution this is not expected to change and it doesn't have to be + /// checked more than once per metadata. This exists for optimisation purposes but is still not + /// cheap as it will jump the wasm-native-barrier every time it is called. So an implementation might + /// chose to cache the result for the execution of the entire block. + fn enabled(&mut self, metadata: Crossing) -> bool { + let metadata: &tracing_core::metadata::Metadata<'static> = (&metadata.into_inner()).into(); + tracing::dispatcher::get_default(|d| { + d.enabled(metadata) + }) + } + + /// Open a new span with the given attributes. Return the u64 Id of the span. + /// + /// On the native side this goes through the default `tracing` dispatcher to register the span + /// and then calls `clone_span` with the ID to signal that we are keeping it around on the wasm- + /// side even after the local span is dropped. The resulting ID is then handed over to the wasm- + /// side. + fn enter_span(&mut self, span: Crossing) -> u64 { + let span: tracing::Span = span.into_inner().into(); + match span.id() { + Some(id) => tracing::dispatcher::get_default(|d| { + // inform dispatch that we'll keep the ID around + // then enter it immediately + let final_id = d.clone_span(&id); + d.enter(&final_id); + final_id.into_u64() + }), + _ => { + 0 } } - log::debug!( - target: "tracing", - "Notify to runtime that tracing is disabled." - ); - 0 - } - - /// Exit a `tracing` span, using `sp_tracing::proxy` - fn exit_span(&mut self, id: u64) { - if let Some(proxy) = self.extension::() { - proxy.exit_span(id) - } else { - log::warn!( - target: "tracing", - "Unable to load extension: TracingProxyExt" - ); + } + + /// Emit the given event to the global tracer on the native side + fn event(&mut self, event: Crossing) { + event.into_inner().emit(); + } + + /// Signal that a given span-id has been exited. On native, this directly + /// proxies the span to the global dispatcher. + fn exit(&mut self, span: u64) { + tracing::dispatcher::get_default(|d| { + let id = tracing_core::span::Id::from_u64(span); + d.exit(&id); + }); + } +} + +#[cfg(all(not(feature="std"), feature="with-tracing"))] +mod tracing_setup { + use core::sync::atomic::{AtomicBool, Ordering}; + use tracing_core::{ + dispatcher::{Dispatch, set_global_default}, + span::{Id, Record, Attributes}, + Metadata, Event, + }; + use super::{wasm_tracing, Crossing}; + + const TRACING_SET : AtomicBool = AtomicBool::new(false); + + + /// The PassingTracingSubscriber implements `tracing_core::Subscriber` + /// and pushes the information across the runtime interface to the host + struct PassingTracingSubsciber; + + impl tracing_core::Subscriber for PassingTracingSubsciber { + fn enabled(&self, metadata: &Metadata<'_>) -> bool { + wasm_tracing::enabled(Crossing(metadata.into())) + } + fn new_span(&self, attrs: &Attributes<'_>) -> Id { + Id::from_u64(wasm_tracing::enter_span(Crossing(attrs.into()))) + } + fn enter(&self, span: &Id) { + // Do nothing, we already entered the span previously + } + /// Not implemented! We do not support recording values later + /// Will panic when used. + fn record(&self, span: &Id, values: &Record<'_>) { + unimplemented!{} // this usage is not supported + } + /// Not implemented! We do not support recording values later + /// Will panic when used. + fn record_follows_from(&self, span: &Id, follows: &Id) { + unimplemented!{ } // this usage is not supported + } + fn event(&self, event: &Event<'_>) { + wasm_tracing::event(Crossing(event.into())) + } + fn exit(&self, span: &Id) { + wasm_tracing::exit(span.into_u64()) + } + } + + + /// Initialize tracing of sp_tracing on wasm with `with-tracing` enabled. + /// Can be called multiple times from within the same process and will only + /// set the global bridging subscriber once. + pub fn init_tracing() { + if TRACING_SET.load(Ordering::Relaxed) == false { + set_global_default(Dispatch::new(PassingTracingSubsciber {})) + .expect("We only ever call this once"); + TRACING_SET.store(true, Ordering::Relaxed); } } } +#[cfg(not(all(not(feature="std"), feature="with-tracing")))] +mod tracing_setup { + /// Initialize tracing of sp_tracing not necessary – noop. To enable build + /// without std and with the `with-tracing`-feature. + pub fn init_tracing() { } +} + +pub use tracing_setup::init_tracing; + /// Wasm-only interface that provides functions for interacting with the sandbox. #[runtime_interface(wasm_only)] pub trait Sandbox { diff --git a/primitives/npos-elections/src/reduce.rs b/primitives/npos-elections/src/reduce.rs index 6d458a5fffb38..17d7dd1290f7d 100644 --- a/primitives/npos-elections/src/reduce.rs +++ b/primitives/npos-elections/src/reduce.rs @@ -52,6 +52,7 @@ use crate::{ExtendedBalance, IdentifierT, StakedAssignment}; use sp_arithmetic::traits::{Bounded, Zero}; use sp_std::{ collections::btree_map::{BTreeMap, Entry::*}, + vec, prelude::*, }; diff --git a/primitives/runtime-interface/proc-macro/src/lib.rs b/primitives/runtime-interface/proc-macro/src/lib.rs index 2f5b9de1c14e7..df43551398a12 100644 --- a/primitives/runtime-interface/proc-macro/src/lib.rs +++ b/primitives/runtime-interface/proc-macro/src/lib.rs @@ -26,21 +26,59 @@ //! 3. The [`PassByEnum`](derive.PassByInner.html) derive macro for implementing `PassBy` with `Enum`. //! 4. The [`PassByInner`](derive.PassByInner.html) derive macro for implementing `PassBy` with `Inner`. -use syn::{parse_macro_input, ItemTrait, DeriveInput}; +use syn::{parse_macro_input, ItemTrait, DeriveInput, Result, Token}; +use syn::parse::{Parse, ParseStream}; mod pass_by; mod runtime_interface; mod utils; +struct Options { + wasm_only: bool, + tracing: bool +} + +impl Options { + fn unpack(self) -> (bool, bool) { + (self.wasm_only, self.tracing) + } +} +impl Default for Options { + fn default() -> Self { + Options { wasm_only: false, tracing: true } + } +} + +impl Parse for Options { + fn parse(input: ParseStream) -> Result { + let mut res = Self::default(); + while !input.is_empty() { + let lookahead = input.lookahead1(); + if lookahead.peek(runtime_interface::keywords::wasm_only) { + let _ = input.parse::(); + res.wasm_only = true; + } else if lookahead.peek(runtime_interface::keywords::no_tracing) { + let _ = input.parse::(); + res.tracing = false; + } else if lookahead.peek(Token![,]) { + let _ = input.parse::(); + } else { + return Err(lookahead.error()) + } + } + Ok(res) + } +} + #[proc_macro_attribute] pub fn runtime_interface( attrs: proc_macro::TokenStream, input: proc_macro::TokenStream, ) -> proc_macro::TokenStream { let trait_def = parse_macro_input!(input as ItemTrait); - let wasm_only = parse_macro_input!(attrs as Option); + let (wasm_only, tracing) = parse_macro_input!(attrs as Options).unpack(); - runtime_interface::runtime_interface_impl(trait_def, wasm_only.is_some()) + runtime_interface::runtime_interface_impl(trait_def, wasm_only, tracing) .unwrap_or_else(|e| e.to_compile_error()) .into() } @@ -61,4 +99,4 @@ pub fn pass_by_inner(input: proc_macro::TokenStream) -> proc_macro::TokenStream pub fn pass_by_enum(input: proc_macro::TokenStream) -> proc_macro::TokenStream { let input = parse_macro_input!(input as DeriveInput); pass_by::enum_derive_impl(input).unwrap_or_else(|e| e.to_compile_error()).into() -} +} \ No newline at end of file diff --git a/primitives/runtime-interface/proc-macro/src/runtime_interface/bare_function_interface.rs b/primitives/runtime-interface/proc-macro/src/runtime_interface/bare_function_interface.rs index 6760e9656113a..2725bd2c89ce5 100644 --- a/primitives/runtime-interface/proc-macro/src/runtime_interface/bare_function_interface.rs +++ b/primitives/runtime-interface/proc-macro/src/runtime_interface/bare_function_interface.rs @@ -46,7 +46,7 @@ use std::iter; /// Generate one bare function per trait method. The name of the bare function is equal to the name /// of the trait method. -pub fn generate(trait_def: &ItemTrait, is_wasm_only: bool) -> Result { +pub fn generate(trait_def: &ItemTrait, is_wasm_only: bool, tracing: bool) -> Result { let trait_name = &trait_def.ident; let runtime_interface = get_runtime_interface(trait_def)?; @@ -63,7 +63,7 @@ pub fn generate(trait_def: &ItemTrait, is_wasm_only: bool) -> Result = runtime_interface.all_versions().try_fold(token_stream?, |mut t, (version, method)| { - t.extend(function_std_impl(trait_name, method, version, is_wasm_only)?); + t.extend(function_std_impl(trait_name, method, version, is_wasm_only, tracing)?); Ok(t) }); @@ -145,6 +145,7 @@ fn function_std_impl( method: &TraitItemMethod, version: u32, is_wasm_only: bool, + tracing: bool, ) -> Result { let function_name = create_function_ident_with_version(&method.sig.ident, version); let function_name_str = function_name.to_string(); @@ -168,13 +169,21 @@ fn function_std_impl( let attrs = method.attrs.iter().filter(|a| !a.path.is_ident("version")); // Don't make the function public accessible when this is a wasm only interface. let call_to_trait = generate_call_to_trait(trait_name, method, version, is_wasm_only); + let call_to_trait = if !tracing { + call_to_trait + } else { + parse_quote!( + #crate_::sp_tracing::within_span! { #crate_::sp_tracing::trace_span!(#function_name_str); + #call_to_trait + } + ) + }; Ok( quote_spanned! { method.span() => #[cfg(feature = "std")] #( #attrs )* fn #function_name( #( #args, )* ) #return_value { - #crate_::sp_tracing::enter_span!(#function_name_str); #call_to_trait } } diff --git a/primitives/runtime-interface/proc-macro/src/runtime_interface/host_function_interface.rs b/primitives/runtime-interface/proc-macro/src/runtime_interface/host_function_interface.rs index 721eed649c25d..7a4dbc5773a28 100644 --- a/primitives/runtime-interface/proc-macro/src/runtime_interface/host_function_interface.rs +++ b/primitives/runtime-interface/proc-macro/src/runtime_interface/host_function_interface.rs @@ -227,7 +227,6 @@ fn generate_host_function_implementation( __function_context__: &mut dyn #crate_::sp_wasm_interface::FunctionContext, args: &mut dyn Iterator, ) -> std::result::Result, String> { - #crate_::sp_tracing::enter_span!(#name); #( #wasm_to_ffi_values )* #( #ffi_to_host_values )* #host_function_call diff --git a/primitives/runtime-interface/proc-macro/src/runtime_interface/mod.rs b/primitives/runtime-interface/proc-macro/src/runtime_interface/mod.rs index c9b6edf68fd5a..02c291975738c 100644 --- a/primitives/runtime-interface/proc-macro/src/runtime_interface/mod.rs +++ b/primitives/runtime-interface/proc-macro/src/runtime_interface/mod.rs @@ -33,14 +33,20 @@ mod trait_decl_impl; pub mod keywords { // Custom keyword `wasm_only` that can be given as attribute to [`runtime_interface`]. syn::custom_keyword!(wasm_only); + // Disable tracing-macros added to the [`runtime_interface`] by specifying this optional entry + syn::custom_keyword!(no_tracing); } /// Implementation of the `runtime_interface` attribute. /// /// It expects the trait definition the attribute was put above and if this should be an wasm only /// interface. -pub fn runtime_interface_impl(trait_def: ItemTrait, is_wasm_only: bool) -> Result { - let bare_functions = bare_function_interface::generate(&trait_def, is_wasm_only)?; +pub fn runtime_interface_impl( + trait_def: ItemTrait, + is_wasm_only: bool, + tracing: bool, +) -> Result { + let bare_functions = bare_function_interface::generate(&trait_def, is_wasm_only, tracing)?; let crate_include = generate_runtime_interface_include(); let mod_name = Ident::new(&trait_def.ident.to_string().to_snake_case(), Span::call_site()); let trait_decl_impl = trait_decl_impl::process(&trait_def, is_wasm_only)?; diff --git a/primitives/runtime-interface/src/lib.rs b/primitives/runtime-interface/src/lib.rs index 562f94b278efc..2273e453f104a 100644 --- a/primitives/runtime-interface/src/lib.rs +++ b/primitives/runtime-interface/src/lib.rs @@ -284,6 +284,14 @@ pub use sp_std; /// 1. The generated functions are not callable from the native side. /// 2. The trait as shown above is not implemented for `Externalities` and is instead implemented /// for `FunctionExecutor` (from `sp-wasm-interface`). +/// +/// # Disable tracing +/// By addding `no_tracing` to the list of options you can prevent the wasm-side interface from +/// generating the default `sp-tracing`-calls. Note that this is rarely needed but only meant for +/// the case when that would create a circular dependency. You usually _do not_ want to add this +/// flag, as tracing doesn't cost you anything by default anyways (it is added as a no-op) but is +/// super useful for debugging later. +/// pub use sp_runtime_interface_proc_macro::runtime_interface; #[doc(hidden)] diff --git a/primitives/runtime-interface/test/Cargo.toml b/primitives/runtime-interface/test/Cargo.toml index 39a48d10b141e..eb916da245a19 100644 --- a/primitives/runtime-interface/test/Cargo.toml +++ b/primitives/runtime-interface/test/Cargo.toml @@ -20,4 +20,5 @@ sp-state-machine = { version = "0.8.0-rc6", path = "../../../primitives/state-ma sp-runtime = { version = "2.0.0-rc6", path = "../../runtime" } sp-core = { version = "2.0.0-rc6", path = "../../core" } sp-io = { version = "2.0.0-rc6", path = "../../io" } -tracing = "0.1.18" +tracing = "0.1.19" +tracing-core = "0.1.15" diff --git a/primitives/runtime-interface/test/src/lib.rs b/primitives/runtime-interface/test/src/lib.rs index c213c977829e6..c66609daa2f29 100644 --- a/primitives/runtime-interface/test/src/lib.rs +++ b/primitives/runtime-interface/test/src/lib.rs @@ -18,8 +18,6 @@ //! Integration tests for runtime interface primitives #![cfg(test)] -#![cfg(test)] - use sp_runtime_interface::*; use sp_runtime_interface_test_wasm::{wasm_binary_unwrap, test_api::HostFunctions}; @@ -157,14 +155,26 @@ fn test_versionining_with_new_host_works() { #[test] fn test_tracing() { - use tracing::span::Id as SpanId; + use std::fmt; + use tracing::{span::Id as SpanId}; + use tracing_core::field::{Field, Visit}; #[derive(Clone)] struct TracingSubscriber(Arc>); + struct FieldConsumer(&'static str, Option); + impl Visit for FieldConsumer { + + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + if field.name() == self.0 { + self.1 = Some(format!("{:?}", value)) + } + } + } + #[derive(Default)] struct Inner { - spans: HashSet<&'static str>, + spans: HashSet, } impl tracing::subscriber::Subscriber for TracingSubscriber { @@ -173,7 +183,9 @@ fn test_tracing() { fn new_span(&self, span: &tracing::span::Attributes) -> tracing::Id { let mut inner = self.0.lock().unwrap(); let id = SpanId::from_u64((inner.spans.len() + 1) as _); - inner.spans.insert(span.metadata().name()); + let mut f = FieldConsumer("name", None); + span.record(&mut f); + inner.spans.insert(f.1.unwrap_or_else(||span.metadata().name().to_owned())); id } @@ -196,5 +208,4 @@ fn test_tracing() { let inner = subscriber.0.lock().unwrap(); assert!(inner.spans.contains("return_input_version_1")); - assert!(inner.spans.contains("ext_test_api_return_input_version_1")); -} +} \ No newline at end of file diff --git a/primitives/std/src/lib.rs b/primitives/std/src/lib.rs index 8ff1efc63d8df..b323c43720da1 100644 --- a/primitives/std/src/lib.rs +++ b/primitives/std/src/lib.rs @@ -20,7 +20,6 @@ #![cfg_attr(not(feature = "std"), no_std)] - #![cfg_attr(feature = "std", doc = "Substrate runtime standard library as compiled when linked with Rust's standard library.")] #![cfg_attr(not(feature = "std"), @@ -65,6 +64,30 @@ include!("../with_std.rs"); #[cfg(not(feature = "std"))] include!("../without_std.rs"); + +/// A target for `core::write!` macro - constructs a string in memory. +#[derive(Default)] +pub struct Writer(vec::Vec); + +impl fmt::Write for Writer { + fn write_str(&mut self, s: &str) -> fmt::Result { + self.0.extend(s.as_bytes()); + Ok(()) + } +} + +impl Writer { + /// Access the content of this `Writer` e.g. for printout + pub fn inner(&self) -> &vec::Vec { + &self.0 + } + + /// Convert into the content of this `Writer` + pub fn into_inner(self) -> vec::Vec { + self.0 + } +} + /// Prelude of common useful imports. /// /// This should include only things which are in the normal std prelude. diff --git a/primitives/tracing/Cargo.toml b/primitives/tracing/Cargo.toml index 889d116221b5f..98a57bafe5ef9 100644 --- a/primitives/tracing/Cargo.toml +++ b/primitives/tracing/Cargo.toml @@ -9,14 +9,33 @@ repository = "https://github.com/paritytech/substrate/" description = "Instrumentation primitives and macros for Substrate." [package.metadata.docs.rs] -targets = ["x86_64-unknown-linux-gnu"] +# let's default to wasm32 +default-target = "wasm32-unknown-unknown" +# with the tracing enabled +features = ["with-tracing"] +# allowing for linux-gnu here, too, allows for `std` to show up as well +targets = ["x86_64-unknown-linux-gnu", "wasm32-unknown-unknown"] [dependencies] -tracing = { version = "0.1.18", optional = true } -rental = { version = "0.5.5", optional = true } +sp-std = { version = "2.0.0-rc6", path = "../std", default-features = false} +codec = { version = "1.3.1", package = "parity-scale-codec", default-features = false, features = ["derive"]} +tracing = { version = "0.1.19", default-features = false } +tracing-core = { version = "0.1.16", default-features = false } log = { version = "0.4.8", optional = true } tracing-subscriber = { version = "0.2.10", optional = true, features = ["tracing-log"] } [features] default = [ "std" ] -std = [ "tracing", "rental", "log", "tracing-subscriber" ] +with-tracing = [ + "codec/derive", + "codec/full", +] +std = [ + "with-tracing", + "tracing/std", + "tracing-core/std", + "codec/std", + "sp-std/std", + "log", + "tracing-subscriber", +] diff --git a/primitives/tracing/src/lib.rs b/primitives/tracing/src/lib.rs index ec692b90dfdec..fb074d5579c82 100644 --- a/primitives/tracing/src/lib.rs +++ b/primitives/tracing/src/lib.rs @@ -17,7 +17,7 @@ //! Substrate tracing primitives and macros. //! -//! To trace functions or invidual code in Substrate, this crate provides [`tracing_span`] +//! To trace functions or invidual code in Substrate, this crate provides [`within_span`] //! and [`enter_span`]. See the individual docs for how to use these macros. //! //! Note that to allow traces from wasm execution environment there are @@ -28,21 +28,80 @@ //! Additionally, we have a const: `WASM_TRACE_IDENTIFIER`, which holds a span name used //! to signal that the 'actual' span name and target should be retrieved instead from //! the associated Fields mentioned above. + #![cfg_attr(not(feature = "std"), no_std)] -#[cfg(feature = "std")] -#[macro_use] -extern crate rental; +/// Tracing facilities and helpers. +/// +/// This is modeled after the `tracing`/`tracing-core` interface and uses that more or +/// less directly for the native side. Because of certain optimisations the these crates +/// have done, the wasm implementation diverges slightly and is optimised for thtat use +/// case (like being able to cross the wasm/native boundary via scale codecs). +/// +/// One of said optimisations is that all macros will yield to a `noop` in non-std unless +/// the `with-tracing` feature is explicitly activated. This allows you to just use the +/// tracing wherever you deem fit and without any performance impact by default. Only if +/// the specific `with-tracing`-feature is activated on this crate will it actually include +/// the tracing code in the non-std environment. +/// +/// Because of that optimisation, you should not use the `span!` and `span_*!` macros +/// directly as they yield nothing without the feature present. Instead you should use +/// `enter_span!` and `within_span!` – which would strip away even any parameter conversion +/// you do within the span-definition (and thus optimise your performance). For your +/// convineience you directly specify the `Level` and name of the span or use the full +/// feature set of `span!`/`span_*!` on it: +/// +/// # Example +/// +/// ```rust +/// sp_tracing::enter_span!(sp_tracing::Level::TRACE, "fn wide span"); +/// { +/// sp_tracing::enter_span!(sp_tracing::trace_span!("outer-span")); +/// { +/// sp_tracing::enter_span!(sp_tracing::Level::TRACE, "inner-span"); +/// // .. +/// } // inner span exists here +/// } // outer span exists here +/// +/// sp_tracing::within_span! { +/// sp_tracing::debug_span!("debug-span", you_can_pass="any params"); +/// 1 + 1; +/// // some other complex code +/// } // debug span ends here +/// +/// ``` +/// +/// +/// # Setup +/// +/// This project only provides the macros and facilities to manage tracing +/// it doesn't implement the tracing subscriber or backend directly – that is +/// up to the developer integrating it into a specific environment. In native +/// this can and must be done through the regular `tracing`-facitilies, please +/// see their documentation for details. +/// +/// On the wasm-side we've adopted a similar approach of having a global +/// `TracingSubscriber` that the macros call and that does the actual work +/// of tracking. To provide your tracking, you must implement `TracingSubscriber` +/// and call `set_tracing_subscriber` at the very beginning of your execution – +/// the default subscriber is doing nothing, so any spans or events happening before +/// will not be recorded! +/// -#[cfg(feature = "std")] -#[doc(hidden)] -pub use tracing; +mod types; #[cfg(feature = "std")] -pub mod proxy; +use tracing; + +pub use tracing::{ + debug, debug_span, error, error_span, info, info_span, trace, trace_span, warn, warn_span, + span, event, Level, Span, +}; + +pub use crate::types::{ + WasmMetadata, WasmEntryAttributes, WasmValuesSet, WasmValue, WasmFields, WasmLevel, WasmFieldName +}; -#[cfg(feature = "std")] -use std::sync::atomic::{AtomicBool, Ordering}; /// Try to init a simple tracing subscriber with log compatibility layer. /// Ignores any error. Useful for testing. @@ -51,74 +110,127 @@ pub fn try_init_simple() { let _ = tracing_subscriber::fmt().with_writer(std::io::stderr).try_init(); } -/// Flag to signal whether to run wasm tracing #[cfg(feature = "std")] -static WASM_TRACING_ENABLED: AtomicBool = AtomicBool::new(false); +pub use crate::types::{ + WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER +}; + /// Runs given code within a tracing span, measuring it's execution time. /// -/// If tracing is not enabled, the code is still executed. +/// If tracing is not enabled, the code is still executed. Pass in level and name or +/// use any valid `sp_tracing::Span`followe by `;` and the code to execute, /// /// # Example /// /// ``` -/// sp_tracing::tracing_span! { +/// sp_tracing::within_span! { +/// sp_tracing::Level::TRACE, /// "test-span"; /// 1 + 1; /// // some other complex code /// } +/// +/// sp_tracing::within_span! { +/// sp_tracing::span!(sp_tracing::Level::WARN, "warn-span", you_can_pass="any params"); +/// 1 + 1; +/// // some other complex code +/// } +/// +/// sp_tracing::within_span! { +/// sp_tracing::debug_span!("debug-span", you_can_pass="any params"); +/// 1 + 1; +/// // some other complex code +/// } /// ``` +#[cfg(any(feature = "std", feature = "with-tracing"))] #[macro_export] -macro_rules! tracing_span { +macro_rules! within_span { + ( + $span:expr; + $( $code:tt )* + ) => { + $span.in_scope(|| + { + $( $code )* + } + ) + }; ( + $lvl:expr, $name:expr; $( $code:tt )* ) => { { - $crate::enter_span!($name); - $( $code )* + $crate::within_span!($crate::span!($crate::Level::TRACE, $name); $( $code )*) } - } + }; +} + +#[cfg(all(not(feature = "std"), not(feature = "with-tracing")))] +#[macro_export] +macro_rules! within_span { + ( + $span:stmt; + $( $code:tt )* + ) => { + $( $code )* + }; + ( + $lvl:expr, + $name:expr; + $( $code:tt )* + ) => { + $( $code )* + }; +} + + +/// Enter a span - noop for `no_std` without `with-tracing` +#[cfg(all(not(feature = "std"), not(feature = "with-tracing")))] +#[macro_export] +macro_rules! enter_span { + ( $lvl:expr, $name:expr ) => ( ); + ( $name:expr ) => ( ) // no-op } /// Enter a span. /// -/// The span will be valid, until the scope is left. +/// The span will be valid, until the scope is left. Use either level and name +/// or pass in any valid `sp_tracing::Span` for extended usage. The span will +/// be exited on drop – which is at the end of the block or to the next +/// `enter_span!` calls, as this overwrites the local variable. For nested +/// usage or to ensure the span closes at certain time either put it into a block +/// or use `within_span!` /// /// # Example /// /// ``` -/// sp_tracing::enter_span!("test-span"); +/// sp_tracing::enter_span!(sp_tracing::Level::TRACE, "test-span"); +/// // previous will be dropped here +/// sp_tracing::enter_span!( +/// sp_tracing::span!(sp_tracing::Level::DEBUG, "debug-span", params="value")); +/// sp_tracing::enter_span!(sp_tracing::info_span!("info-span", params="value")); +/// +/// { +/// sp_tracing::enter_span!(sp_tracing::Level::TRACE, "outer-span"); +/// { +/// sp_tracing::enter_span!(sp_tracing::Level::TRACE, "inner-span"); +/// // .. +/// } // inner span exists here +/// } // outer span exists here +/// /// ``` +#[cfg(any(feature = "std", feature = "with-tracing"))] #[macro_export] macro_rules! enter_span { - ( $name:expr ) => { - let __tracing_span__ = $crate::if_tracing!( - $crate::tracing::span!($crate::tracing::Level::TRACE, $name) - ); - let __tracing_guard__ = $crate::if_tracing!(__tracing_span__.enter()); - } -} - -/// Generates the given code if the tracing dependency is enabled. -#[macro_export] -#[cfg(feature = "std")] -macro_rules! if_tracing { - ( $if:expr ) => {{ $if }} -} - -#[macro_export] -#[cfg(not(feature = "std"))] -macro_rules! if_tracing { - ( $if:expr ) => {{}} -} - -#[cfg(feature = "std")] -pub fn wasm_tracing_enabled() -> bool { - WASM_TRACING_ENABLED.load(Ordering::Relaxed) -} - -#[cfg(feature = "std")] -pub fn set_wasm_tracing(b: bool) { - WASM_TRACING_ENABLED.store(b, Ordering::Relaxed) + ( $span:expr ) => { + // Calling this twice in a row will overwrite (and drop) the earlier + // that is a _documented feature_! + let __within_span__ = $span; + let __tracing_guard__ = __within_span__.enter(); + }; + ( $lvl:expr, $name:expr ) => { + $crate::enter_span!($crate::span!($crate::Level::TRACE, $name)) + }; } diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs deleted file mode 100644 index 270f57aaa69f0..0000000000000 --- a/primitives/tracing/src/proxy.rs +++ /dev/null @@ -1,165 +0,0 @@ -// Copyright 2020 Parity Technologies (UK) Ltd. -// This file is part of Substrate. - -// Substrate is free software: you can redistribute it and/or modify -// it under the terms of the GNU General Public License as published by -// the Free Software Foundation, either version 3 of the License, or -// (at your option) any later version. - -// Substrate is distributed in the hope that it will be useful, -// but WITHOUT ANY WARRANTY; without even the implied warranty of -// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the -// GNU General Public License for more details. - -// You should have received a copy of the GNU General Public License -// along with Substrate. If not, see . - -//! Proxy to allow entering tracing spans from wasm. -//! -//! Use `enter_span` and `exit_span` to surround the code that you wish to trace -use rental; -use tracing::info_span; - -/// Used to identify a proxied WASM trace -pub const WASM_TRACE_IDENTIFIER: &'static str = "WASM_TRACE"; -/// Used to extract the real `target` from the associated values of the span -pub const WASM_TARGET_KEY: &'static str = "proxied_wasm_target"; -/// Used to extract the real `name` from the associated values of the span -pub const WASM_NAME_KEY: &'static str = "proxied_wasm_name"; - -const MAX_SPANS_LEN: usize = 1000; - -rental! { - pub mod rent_span { - #[rental] - pub struct SpanAndGuard { - span: Box, - guard: tracing::span::Entered<'span>, - } - } -} - -/// Requires a tracing::Subscriber to process span traces, -/// this is available when running with client (and relevant cli params). -pub struct TracingProxy { - next_id: u64, - spans: Vec<(u64, rent_span::SpanAndGuard)>, -} - -impl Drop for TracingProxy { - fn drop(&mut self) { - if !self.spans.is_empty() { - log::debug!( - target: "tracing", - "Dropping TracingProxy with {} un-exited spans, marking as not valid", self.spans.len() - ); - while let Some((_, mut sg)) = self.spans.pop() { - sg.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); - } - } - } -} - -impl TracingProxy { - pub fn new() -> TracingProxy { - TracingProxy { - next_id: 0, - spans: Vec::new(), - } - } -} - -impl TracingProxy { - /// Create and enter a `tracing` Span, returning the span id, - /// which should be passed to `exit_span(id)` to signal that the span should exit. - pub fn enter_span(&mut self, proxied_wasm_target: &str, proxied_wasm_name: &str) -> u64 { - // The identifiers `proxied_wasm_target` and `proxied_wasm_name` must match their associated const, - // WASM_TARGET_KEY and WASM_NAME_KEY. - let span = info_span!(WASM_TRACE_IDENTIFIER, is_valid_trace = true, proxied_wasm_target, proxied_wasm_name); - self.next_id += 1; - let sg = rent_span::SpanAndGuard::new( - Box::new(span), - |span| span.enter(), - ); - self.spans.push((self.next_id, sg)); - if self.spans.len() > MAX_SPANS_LEN { - // This is to prevent unbounded growth of Vec and could mean one of the following: - // 1. Too many nested spans, or MAX_SPANS_LEN is too low. - // 2. Not correctly exiting spans due to misconfiguration / misuse - log::warn!( - target: "tracing", - "TracingProxy MAX_SPANS_LEN exceeded, removing oldest span." - ); - let mut sg = self.spans.remove(0).1; - sg.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); - } - self.next_id - } - - /// Exit a span by dropping it along with it's associated guard. - pub fn exit_span(&mut self, id: u64) { - if self.spans.last().map(|l| id > l.0).unwrap_or(true) { - log::warn!(target: "tracing", "Span id not found in TracingProxy: {}", id); - return; - } - let mut last_span = self.spans.pop().expect("Just checked that there is an element to pop; qed"); - while id < last_span.0 { - log::warn!( - target: "tracing", - "TracingProxy Span ids not equal! id parameter given: {}, last span: {}", - id, - last_span.0, - ); - last_span.1.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); - if let Some(s) = self.spans.pop() { - last_span = s; - } else { - log::warn!(target: "tracing", "Span id not found in TracingProxy {}", id); - return; - } - } - } -} - - -#[cfg(test)] -mod tests { - use super::*; - - fn create_spans(proxy: &mut TracingProxy, qty: usize) -> Vec { - let mut spans = Vec::new(); - for n in 0..qty { - spans.push(proxy.enter_span("target", &format!("{}", n))); - } - spans - } - - #[test] - fn max_spans_len_respected() { - let mut proxy = TracingProxy::new(); - let _spans = create_spans(&mut proxy, MAX_SPANS_LEN + 10); - assert_eq!(proxy.spans.len(), MAX_SPANS_LEN); - // ensure oldest spans removed - assert_eq!(proxy.spans[0].0, 11); - } - - #[test] - fn handles_span_exit_scenarios() { - let mut proxy = TracingProxy::new(); - let _spans = create_spans(&mut proxy, 10); - assert_eq!(proxy.spans.len(), 10); - // exit span normally - proxy.exit_span(10); - assert_eq!(proxy.spans.len(), 9); - // skip and exit outer span without exiting inner, id: 8 instead of 9 - proxy.exit_span(8); - // should have also removed the inner span that was lost - assert_eq!(proxy.spans.len(), 7); - // try to exit span not held - proxy.exit_span(9); - assert_eq!(proxy.spans.len(), 7); - // exit all spans - proxy.exit_span(1); - assert_eq!(proxy.spans.len(), 0); - } -} diff --git a/primitives/tracing/src/types.rs b/primitives/tracing/src/types.rs new file mode 100644 index 0000000000000..050ac4c314166 --- /dev/null +++ b/primitives/tracing/src/types.rs @@ -0,0 +1,623 @@ +// This file is part of Substrate. + +// Copyright (C) 2020 Parity Technologies (UK) Ltd. +// SPDX-License-Identifier: Apache-2.0 + +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +/// Types for wasm based tracing. Loosly inspired by `tracing-core` but +/// optimised for the specific use case. + +use core::{format_args, fmt::Debug}; +use sp_std::{ + vec, vec::Vec, +}; +use sp_std::Writer; +use codec::{Encode, Decode}; + +/// The Tracing Level – the user can filter by this +#[derive(Clone, Encode, Decode, Debug)] +pub enum WasmLevel { + /// This is a fatal errors + ERROR, + /// This is a warning you should be aware of + WARN, + /// Nice to now info + INFO, + /// Further information for debugging purposes + DEBUG, + /// The lowest level, keeping track of minute detail + TRACE +} + + +impl From<&tracing_core::Level> for WasmLevel { + fn from(l: &tracing_core::Level) -> WasmLevel { + match l { + &tracing_core::Level::ERROR => WasmLevel::ERROR, + &tracing_core::Level::WARN => WasmLevel::WARN, + &tracing_core::Level::INFO => WasmLevel::INFO, + &tracing_core::Level::DEBUG => WasmLevel::DEBUG, + &tracing_core::Level::TRACE => WasmLevel::TRACE, + } + } +} + + + +impl core::default::Default for WasmLevel { + fn default() -> Self { + WasmLevel::TRACE + } +} + +/// A paramter value provided to the span/event +#[derive(Encode, Decode, Clone)] +pub enum WasmValue { + U8(u8), + I8(i8), + U32(u32), + I32(i32), + I64(i64), + U64(u64), + Bool(bool), + Str(Vec), + /// Debug or Display call, this is most-likely a print-able UTF8 String + Formatted(Vec), + /// SCALE CODEC encoded object – the name should allow the received to know + /// how to decode this. + Encoded(Vec), +} + +impl core::fmt::Debug for WasmValue { + fn fmt(&self, f: &mut core::fmt::Formatter) -> core::fmt::Result { + match self { + WasmValue::U8(ref i) => { + f.write_fmt(format_args!("{}_u8", i)) + } + WasmValue::I8(ref i) => { + f.write_fmt(format_args!("{}_i8", i)) + } + WasmValue::U32(ref i) => { + f.write_fmt(format_args!("{}_u32", i)) + } + WasmValue::I32(ref i) => { + f.write_fmt(format_args!("{}_i32", i)) + } + WasmValue::I64(ref i) => { + f.write_fmt(format_args!("{}_i64", i)) + } + WasmValue::U64(ref i) => { + f.write_fmt(format_args!("{}_u64", i)) + } + WasmValue::Bool(ref i) => { + f.write_fmt(format_args!("{}_bool", i)) + } + WasmValue::Formatted(ref i) | WasmValue::Str(ref i) => { + if let Ok(v) = core::str::from_utf8(i) { + f.write_fmt(format_args!("{}", v)) + } else { + f.write_fmt(format_args!("{:?}", i)) + } + } + WasmValue::Encoded(ref v) => { + f.write_str("Scale(")?; + for byte in v { + f.write_fmt(format_args!("{:02x}", byte))?; + } + f.write_str(")") + } + } + } +} + +impl From for WasmValue { + fn from(u: u8) -> WasmValue { + WasmValue::U8(u) + } +} + +impl From<&i8> for WasmValue { + fn from(inp: &i8) -> WasmValue { + WasmValue::I8(inp.clone()) + } +} + +impl From<&str> for WasmValue { + fn from(inp: &str) -> WasmValue { + WasmValue::Str(inp.as_bytes().to_vec()) + } +} + +impl From<&&str> for WasmValue { + fn from(inp: &&str) -> WasmValue { + WasmValue::Str((*inp).as_bytes().to_vec()) + } +} + +impl From for WasmValue { + fn from(inp: bool) -> WasmValue { + WasmValue::Bool(inp) + } +} + +impl From> for WasmValue { + fn from(inp: core::fmt::Arguments<'_>) -> WasmValue { + let mut buf = Writer::default(); + core::fmt::write(&mut buf, inp).expect("Writing of arguments doesn't fail"); + WasmValue::Formatted(buf.into_inner()) + } +} + +impl From for WasmValue { + fn from(u: i8) -> WasmValue { + WasmValue::I8(u) + } +} + +impl From for WasmValue { + fn from(u: i32) -> WasmValue { + WasmValue::I32(u) + } +} + +impl From<&i32> for WasmValue { + fn from(u: &i32) -> WasmValue { + WasmValue::I32(*u) + } +} + +impl From for WasmValue { + fn from(u: u32) -> WasmValue { + WasmValue::U32(u) + } +} + +impl From<&u32> for WasmValue { + fn from(u: &u32) -> WasmValue { + WasmValue::U32(*u) + } +} + +impl From for WasmValue { + fn from(u: u64) -> WasmValue { + WasmValue::U64(u) + } +} + +impl From for WasmValue { + fn from(u: i64) -> WasmValue { + WasmValue::I64(u) + } +} + +/// The name of a field provided as the argument name when contstructing an +/// `event!` or `span!`. +/// Generally generated automaticaly via `stringify` from an `'static &str`. +/// Likely print-able. +#[derive(Encode, Decode, Clone)] +pub struct WasmFieldName(Vec); + +impl core::fmt::Debug for WasmFieldName { + fn fmt(&self, f: &mut core::fmt::Formatter) -> core::fmt::Result { + if let Ok(v) = core::str::from_utf8(&self.0) { + f.write_fmt(format_args!("{}", v)) + } else { + for byte in self.0.iter() { + f.write_fmt(format_args!("{:02x}", byte))?; + } + Ok(()) + } + } +} + +impl From> for WasmFieldName { + fn from(v: Vec) -> Self { + WasmFieldName(v) + } +} + +impl From<&str> for WasmFieldName { + fn from(v: &str) -> Self { + WasmFieldName(v.as_bytes().to_vec()) + } +} + +/// A list of `WasmFieldName`s in the order provided +#[derive(Encode, Decode, Clone, Debug)] +pub struct WasmFields(Vec); + +impl WasmFields { + /// Iterate over the fields + pub fn iter(&self) -> core::slice::Iter<'_, WasmFieldName> { + self.0.iter() + } +} + +impl From> for WasmFields { + fn from(v: Vec) -> WasmFields { + WasmFields(v.into()) + } +} + +impl From> for WasmFields { + fn from(v: Vec<&str>) -> WasmFields { + WasmFields(v.into_iter().map(|v| v.into()).collect()) + } +} + +impl WasmFields { + /// Create an empty entry + pub fn empty() -> Self { + WasmFields(Vec::with_capacity(0)) + } +} + +impl From<&tracing_core::field::FieldSet> for WasmFields { + fn from(wm: &tracing_core::field::FieldSet) -> WasmFields { + WasmFields(wm.iter().map(|s| s.name().into()).collect()) + } +} + +/// A list of `WasmFieldName`s with the given `WasmValue` (if provided) +/// in the order specified. +#[derive(Encode, Decode, Clone)] +pub struct WasmValuesSet(Vec<(WasmFieldName, Option)>); + +impl core::fmt::Debug for WasmValuesSet { + fn fmt(&self, f: &mut core::fmt::Formatter) -> core::fmt::Result { + let mut wrt = f.debug_struct(""); + let mut non_str = false; + for (f, v) in self.0.iter() { + if let Ok(s) = core::str::from_utf8(&f.0) { + match v { + Some(ref i) => wrt.field(s, i), + None => wrt.field(s, &(None as Option)), + }; + } else { + non_str = true; + } + } + + // FIXME: replace with using `finish_non_exhaustive()` once stable + // https://github.com/rust-lang/rust/issues/67364 + if non_str { + wrt.field("..", &".."); + } + + wrt.finish() + } +} + + +impl From)>> for WasmValuesSet { + fn from(v: Vec<(WasmFieldName, Option)>) -> Self { + WasmValuesSet(v) + } +} +impl From)>> for WasmValuesSet { + fn from(v: Vec<(&&WasmFieldName, Option)>) -> Self { + WasmValuesSet(v.into_iter().map(|(k, v)| ((**k).clone(), v)).collect()) + } +} + +impl From)>> for WasmValuesSet { + fn from(v: Vec<(&&str, Option)>) -> Self { + WasmValuesSet(v.into_iter().map(|(k, v)| ((*k).into(), v)).collect()) + } +} + +impl WasmValuesSet { + /// Create an empty entry + pub fn empty() -> Self { + WasmValuesSet(Vec::with_capacity(0)) + } +} + +impl tracing_core::field::Visit for WasmValuesSet { + fn record_debug(&mut self, field: &tracing_core::field::Field, value: &dyn Debug) { + self.0.push( ( + field.name().into(), + Some(WasmValue::from(format_args!("{:?}", value))) + )) + } + fn record_i64(&mut self, field: &tracing_core::field::Field, value: i64) { + self.0.push( ( + field.name().into(), + Some(WasmValue::from(value)) + )) + } + fn record_u64(&mut self, field: &tracing_core::field::Field, value: u64) { + self.0.push( ( + field.name().into(), + Some(WasmValue::from(value)) + )) + } + fn record_bool(&mut self, field: &tracing_core::field::Field, value: bool) { + self.0.push( ( + field.name().into(), + Some(WasmValue::from(value)) + )) + } + fn record_str(&mut self, field: &tracing_core::field::Field, value: &str) { + self.0.push( ( + field.name().into(), + Some(WasmValue::from(value)) + )) + } +} +/// Metadata provides generic information about the specifc location of the +/// `span!` or `event!` call on the wasm-side. +#[derive(Encode, Decode, Clone)] +pub struct WasmMetadata { + /// The name given to `event!`/`span!`, `&'static str` converted to bytes + pub name: Vec, + /// The given target to `event!`/`span!` – or module-name, `&'static str` converted to bytes + pub target: Vec, + /// The level of this entry + pub level: WasmLevel, + /// The file this was emitted from – useful for debugging; `&'static str` converted to bytes + pub file: Vec, + /// The specific line number in the file – useful for debugging + pub line: u32, + /// The module path; `&'static str` converted to bytes + pub module_path: Vec, + /// Whether this is a call to `span!` or `event!` + pub is_span: bool, + /// The list of fields specified in the call + pub fields: WasmFields, +} + +impl From<&tracing_core::Metadata<'_>> for WasmMetadata { + fn from(wm: &tracing_core::Metadata<'_>) -> WasmMetadata { + WasmMetadata { + name: wm.name().as_bytes().to_vec(), + target: wm.target().as_bytes().to_vec(), + level: wm.level().into(), + file: wm.file().map(|f| f.as_bytes().to_vec()).unwrap_or_default(), + line: wm.line().unwrap_or_default(), + module_path: wm.module_path().map(|m| m.as_bytes().to_vec()).unwrap_or_default(), + is_span: wm.is_span(), + fields: wm.fields().into() + } + } +} + +impl core::fmt::Debug for WasmMetadata { + fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { + f.debug_struct("WasmMetadata") + .field("name", &decode_field(&self.name)) + .field("target", &decode_field(&self.target)) + .field("level", &self.level) + .field("file", &decode_field(&self.file)) + .field("line", &self.line) + .field("module_path", &decode_field(&self.module_path)) + .field("is_span", &self.is_span) + .field("fields", &self.fields) + .finish() + } +} + +impl core::default::Default for WasmMetadata { + fn default() -> Self { + let target = "default".as_bytes().to_vec(); + WasmMetadata { + target, + name: Default::default(), + level: Default::default(), + file: Default::default(), + line: Default::default(), + module_path: Default::default(), + is_span: true, + fields: WasmFields::empty() + } + } +} + + +fn decode_field(field: &[u8]) -> &str { + core::str::from_utf8(field).unwrap_or_default() +} + +/// Span or Event Attributes +#[derive(Encode, Decode, Clone, Debug)] +pub struct WasmEntryAttributes { + /// the parent, if directly specified – otherwise assume most inner span + pub parent_id: Option, + /// the metadata of the location + pub metadata: WasmMetadata, + /// the Values provided + pub fields: WasmValuesSet, +} + +impl From<&tracing_core::Event<'_>> for WasmEntryAttributes { + fn from(evt: &tracing_core::Event<'_>) -> WasmEntryAttributes { + let mut fields = WasmValuesSet(Vec::new()); + evt.record(&mut fields); + WasmEntryAttributes { + parent_id: evt.parent().map(|id| id.into_u64()), + metadata: evt.metadata().into(), + fields: fields + } + } +} + +impl From<&tracing_core::span::Attributes<'_>> for WasmEntryAttributes { + fn from(attrs: &tracing_core::span::Attributes<'_>) -> WasmEntryAttributes { + let mut fields = WasmValuesSet(Vec::new()); + attrs.record(&mut fields); + WasmEntryAttributes { + parent_id: attrs.parent().map(|id| id.into_u64()), + metadata: attrs.metadata().into(), + fields: fields + } + } +} + +impl core::default::Default for WasmEntryAttributes { + fn default() -> Self { + WasmEntryAttributes { + parent_id: None, + metadata: Default::default(), + fields: WasmValuesSet(vec![]), + } + } +} + +#[cfg(feature = "std")] +mod std_features { + + use tracing_core::callsite; + use tracing; + + /// Static entry use for wasm-originated metadata. + pub struct WasmCallsite; + impl callsite::Callsite for WasmCallsite { + fn set_interest(&self, _: tracing_core::Interest) { unimplemented!() } + fn metadata(&self) -> &tracing_core::Metadata { unimplemented!() } + } + static CALLSITE: WasmCallsite = WasmCallsite; + /// The identifier we are using to inject the wasm events in the generic `tracing` system + pub static WASM_TRACE_IDENTIFIER: &'static str = "wasm_tracing"; + /// The fieldname for the wasm-originated name + pub static WASM_NAME_KEY: &'static str = "name"; + /// The fieldname for the wasm-originated target + pub static WASM_TARGET_KEY: &'static str = "target"; + /// The the list of all static field names we construct from the given metadata + pub static GENERIC_FIELDS: &'static [&'static str] = &[WASM_TARGET_KEY, WASM_NAME_KEY, + "file", "line", "module_path", "params"]; + + // Implementation Note: + // the original `tracing` crate generates these static metadata entries at every `span!` and + // `event!` location to allow for highly optimised filtering. For us to allow level-based emitting + // of wasm events we need these static metadata entries to inject into that system. We then provide + // generic `From`-implementations picking the right metadata to refer to. + + static SPAN_ERROR_METADATA : tracing_core::Metadata<'static> = tracing::Metadata::new( + WASM_TRACE_IDENTIFIER, WASM_TRACE_IDENTIFIER, tracing::Level::ERROR, None, None, None, + tracing_core::field::FieldSet::new(GENERIC_FIELDS, tracing_core::identify_callsite!(&CALLSITE)), + tracing_core::metadata::Kind::SPAN + ); + + static SPAN_WARN_METADATA : tracing_core::Metadata<'static> = tracing::Metadata::new( + WASM_TRACE_IDENTIFIER, WASM_TRACE_IDENTIFIER, tracing::Level::WARN, None, None, None, + tracing_core::field::FieldSet::new(GENERIC_FIELDS, tracing_core::identify_callsite!(&CALLSITE)), + tracing_core::metadata::Kind::SPAN + ); + static SPAN_INFO_METADATA : tracing_core::Metadata<'static> = tracing::Metadata::new( + WASM_TRACE_IDENTIFIER, WASM_TRACE_IDENTIFIER, tracing::Level::INFO, None, None, None, + tracing_core::field::FieldSet::new(GENERIC_FIELDS, tracing_core::identify_callsite!(&CALLSITE)), + tracing_core::metadata::Kind::SPAN + ); + + static SPAN_DEBUG_METADATA : tracing_core::Metadata<'static> = tracing::Metadata::new( + WASM_TRACE_IDENTIFIER, WASM_TRACE_IDENTIFIER, tracing::Level::DEBUG, None, None, None, + tracing_core::field::FieldSet::new(GENERIC_FIELDS, tracing_core::identify_callsite!(&CALLSITE)), + tracing_core::metadata::Kind::SPAN + ); + + static SPAN_TRACE_METADATA : tracing_core::Metadata<'static> = tracing::Metadata::new( + WASM_TRACE_IDENTIFIER, WASM_TRACE_IDENTIFIER, tracing::Level::TRACE, None, None, None, + tracing_core::field::FieldSet::new(GENERIC_FIELDS, tracing_core::identify_callsite!(&CALLSITE)), + tracing_core::metadata::Kind::SPAN + ); + + static EVENT_ERROR_METADATA : tracing_core::Metadata<'static> = tracing::Metadata::new( + WASM_TRACE_IDENTIFIER, WASM_TRACE_IDENTIFIER, tracing::Level::ERROR, None, None, None, + tracing_core::field::FieldSet::new(GENERIC_FIELDS, tracing_core::identify_callsite!(&CALLSITE)), + tracing_core::metadata::Kind::EVENT + ); + + static EVENT_WARN_METADATA : tracing_core::Metadata<'static> = tracing::Metadata::new( + WASM_TRACE_IDENTIFIER, WASM_TRACE_IDENTIFIER, tracing::Level::WARN, None, None, None, + tracing_core::field::FieldSet::new(GENERIC_FIELDS, tracing_core::identify_callsite!(&CALLSITE)), + tracing_core::metadata::Kind::EVENT + ); + + static EVENT_INFO_METADATA : tracing_core::Metadata<'static> = tracing::Metadata::new( + WASM_TRACE_IDENTIFIER, WASM_TRACE_IDENTIFIER, tracing::Level::INFO, None, None, None, + tracing_core::field::FieldSet::new(GENERIC_FIELDS, tracing_core::identify_callsite!(&CALLSITE)), + tracing_core::metadata::Kind::EVENT + ); + + static EVENT_DEBUG_METADATA : tracing_core::Metadata<'static> = tracing::Metadata::new( + WASM_TRACE_IDENTIFIER, WASM_TRACE_IDENTIFIER, tracing::Level::DEBUG, None, None, None, + tracing_core::field::FieldSet::new(GENERIC_FIELDS, tracing_core::identify_callsite!(&CALLSITE)), + tracing_core::metadata::Kind::EVENT + ); + + static EVENT_TRACE_METADATA : tracing_core::Metadata<'static> = tracing::Metadata::new( + WASM_TRACE_IDENTIFIER, WASM_TRACE_IDENTIFIER, tracing::Level::TRACE, None, None, None, + tracing_core::field::FieldSet::new(GENERIC_FIELDS, tracing_core::identify_callsite!(&CALLSITE)), + tracing_core::metadata::Kind::EVENT + ); + + // FIXME: this could be done a lot in 0.2 if they opt for using `Cow` instead + // https://github.com/paritytech/substrate/issues/7134 + impl From<&crate::WasmMetadata> for &'static tracing_core::Metadata<'static> { + fn from(wm: &crate::WasmMetadata) -> &'static tracing_core::Metadata<'static> { + match (&wm.level, wm.is_span) { + (&crate::WasmLevel::ERROR, true) => &SPAN_ERROR_METADATA, + (&crate::WasmLevel::WARN, true) => &SPAN_WARN_METADATA, + (&crate::WasmLevel::INFO, true) => &SPAN_INFO_METADATA, + (&crate::WasmLevel::DEBUG, true) => &SPAN_DEBUG_METADATA, + (&crate::WasmLevel::TRACE, true) => &SPAN_TRACE_METADATA, + (&crate::WasmLevel::ERROR, false) => &EVENT_ERROR_METADATA, + (&crate::WasmLevel::WARN, false) => &EVENT_WARN_METADATA, + (&crate::WasmLevel::INFO, false) => &EVENT_INFO_METADATA, + (&crate::WasmLevel::DEBUG, false) => &EVENT_DEBUG_METADATA, + (&crate::WasmLevel::TRACE, false) => &EVENT_TRACE_METADATA, + } + } + } + + impl From for tracing::Span { + fn from(a: crate::WasmEntryAttributes) -> tracing::Span { + let name = std::str::from_utf8(&a.metadata.name).unwrap_or_default(); + let target = std::str::from_utf8(&a.metadata.target).unwrap_or_default(); + let file = std::str::from_utf8(&a.metadata.file).unwrap_or_default(); + let line = a.metadata.line; + let module_path = std::str::from_utf8(&a.metadata.module_path).unwrap_or_default(); + let params = a.fields; + let metadata : &tracing_core::metadata::Metadata<'static> = (&a.metadata).into(); + + tracing::span::Span::child_of( + a.parent_id.map(|i|tracing_core::span::Id::from_u64(i)), + &metadata, + &tracing::valueset!{ metadata.fields(), target, name, file, line, module_path, ?params } + ) + } + } + + impl crate::WasmEntryAttributes { + /// convert the given Attributes to an event and emit it using `tracing_core`. + pub fn emit(self: crate::WasmEntryAttributes) { + let name = std::str::from_utf8(&self.metadata.name).unwrap_or_default(); + let target = std::str::from_utf8(&self.metadata.target).unwrap_or_default(); + let file = std::str::from_utf8(&self.metadata.file).unwrap_or_default(); + let line = self.metadata.line; + let module_path = std::str::from_utf8(&self.metadata.module_path).unwrap_or_default(); + let params = self.fields; + let metadata : &tracing_core::metadata::Metadata<'static> = (&self.metadata).into(); + + tracing_core::Event::child_of( + self.parent_id.map(|i|tracing_core::span::Id::from_u64(i)), + &metadata, + &tracing::valueset!{ metadata.fields(), target, name, file, line, module_path, ?params } + ) + } + } +} + +#[cfg(feature = "std")] +pub use std_features::*;