feat: Rebrand Polkadot/Substrate references to PezkuwiChain

This commit systematically rebrands various references from Parity Technologies'
Polkadot/Substrate ecosystem to PezkuwiChain within the kurdistan-sdk.

Key changes include:
- Updated external repository URLs (zombienet-sdk, parity-db, parity-scale-codec, wasm-instrument) to point to pezkuwichain forks.
- Modified internal documentation and code comments to reflect PezkuwiChain naming and structure.
- Replaced direct references to  with  or specific paths within the  for XCM, Pezkuwi, and other modules.
- Cleaned up deprecated  issue and PR references in various  and  files, particularly in  and  modules.
- Adjusted image and logo URLs in documentation to point to PezkuwiChain assets.
- Removed or rephrased comments related to external Polkadot/Substrate PRs and issues.

This is a significant step towards fully customizing the SDK for the PezkuwiChain ecosystem.

bizinikiwi/client/tracing/Cargo.toml

@@ -0,0 +1,71 @@
+[package]
+name = "pezsc-tracing"
+version = "28.0.0"
+license = "GPL-3.0-or-later WITH Classpath-exception-2.0"
+authors.workspace = true
+edition.workspace = true
+homepage.workspace = true
+repository.workspace = true
+description = "Instrumentation implementation for bizinikiwi."
+readme = "README.md"
+
+[lints]
+workspace = true
+
+[package.metadata.docs.rs]
+targets = ["x86_64-unknown-linux-gnu"]
+
+[[bench]]
+name = "bench"
+harness = false
+
+[[bench]]
+name = "interest_cache_realistic"
+harness = false
+
+[[bench]]
+name = "interest_cache_diverse"
+harness = false
+
+[[bench]]
+name = "interest_cache_multithreaded"
+harness = false
+
+[dependencies]
+chrono = { workspace = true }
+codec = { workspace = true, default-features = true }
+console = { workspace = true }
+is-terminal = { workspace = true }
+libc = { workspace = true }
+log = { workspace = true, default-features = true }
+parking_lot = { workspace = true, default-features = true }
+rustc-hash = { workspace = true }
+pezsc-client-api = { workspace = true, default-features = true }
+pezsc-tracing-proc-macro = { workspace = true, default-features = true }
+serde = { workspace = true, default-features = true }
+pezsp-api = { workspace = true, default-features = true }
+pezsp-blockchain = { workspace = true, default-features = true }
+pezsp-core = { workspace = true, default-features = true }
+pezsp-rpc = { workspace = true, default-features = true }
+pezsp-runtime = { workspace = true, default-features = true }
+pezsp-tracing = { workspace = true, default-features = true }
+thiserror = { workspace = true }
+tracing = { workspace = true, default-features = true }
+tracing-log = { workspace = true, features = ["interest-cache"] }
+tracing-subscriber = { workspace = true, features = [
+	"env-filter",
+	"parking_lot",
+] }
+
+[dev-dependencies]
+criterion = { workspace = true, default-features = true }
+regex = { workspace = true }
+tracing-subscriber = { workspace = true, features = ["chrono", "parking_lot"] }
+
+[features]
+runtime-benchmarks = [
+	"pezsc-client-api/runtime-benchmarks",
+	"pezsp-api/runtime-benchmarks",
+	"pezsp-blockchain/runtime-benchmarks",
+	"pezsp-runtime/runtime-benchmarks",
+]

bizinikiwi/client/tracing/README.md

@@ -0,0 +1,11 @@
+Instrumentation implementation for Bizinikiwi.
+
+This crate is unstable and the API and usage may change.
+
+# Usage
+
+See `pezsp-tracing` for examples on how to use tracing.
+
+Currently we provide `Log` (default), `Telemetry` variants for `Receiver`
+
+License: GPL-3.0-or-later WITH Classpath-exception-2.0

bizinikiwi/client/tracing/benches/bench.rs

@@ -0,0 +1,55 @@
+// This file is part of Bizinikiwi.
+
+// Copyright (C) Parity Technologies (UK) Ltd.
+// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0
+
+// This program is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+
+// This program is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+// GNU General Public License for more details.
+
+// You should have received a copy of the GNU General Public License
+// along with this program. If not, see <https://www.gnu.org/licenses/>.
+
+use criterion::{criterion_group, criterion_main, Criterion};
+use tracing_subscriber::fmt::{
+	format,
+	time::{ChronoLocal, FormatTime},
+};
+
+fn bench_fast_local_time(c: &mut Criterion) {
+	c.bench_function("fast_local_time", |b| {
+		let mut buffer = String::new();
+		let t = pezsc_tracing::logging::FastLocalTime { with_fractional: true };
+		b.iter(|| {
+			buffer.clear();
+			let mut writer = format::Writer::new(&mut buffer);
+			t.format_time(&mut writer).unwrap();
+		})
+	});
+}
+
+// This is here just as a point of comparison.
+fn bench_chrono_local(c: &mut Criterion) {
+	c.bench_function("chrono_local", |b| {
+		let mut buffer = String::new();
+		let t = ChronoLocal::new("%Y-%m-%d %H:%M:%S%.3f".to_string());
+		b.iter(|| {
+			buffer.clear();
+			let mut writer: format::Writer<'_> = format::Writer::new(&mut buffer);
+			t.format_time(&mut writer).unwrap();
+		})
+	});
+}
+
+criterion_group! {
+	name = benches;
+	config = Criterion::default();
+	targets = bench_fast_local_time, bench_chrono_local
+}
+criterion_main!(benches);

bizinikiwi/client/tracing/benches/common/mod.rs

@@ -0,0 +1,105 @@
+// This file is part of Bizinikiwi.
+//
+// Copyright (C) Parity Technologies (UK) Ltd.
+// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0
+
+//! Common utilities for interest cache benchmarks.
+
+use log::{Level, LevelFilter};
+use tracing_subscriber::{EnvFilter, FmtSubscriber};
+
+/// Initialize logger with interest cache configuration from INTEREST_CACHE environment variable.
+pub fn init_logger() {
+	let mut log_tracer = tracing_log::LogTracer::builder().with_max_level(LevelFilter::Trace);
+
+	if let Some(config) = parse_interest_cache_config() {
+		eprintln!("Interest cache config: {config:?}");
+		log_tracer = log_tracer.with_interest_cache(config);
+	}
+
+	log_tracer.init().expect("Failed to init LogTracer");
+
+	let env_filter = EnvFilter::default()
+		.add_directive("info".parse().unwrap())
+		.add_directive("dummy=trace".parse().unwrap());
+
+	let subscriber = FmtSubscriber::builder()
+		.with_env_filter(env_filter)
+		.with_writer(std::io::sink)
+		.with_filter_reloading()
+		.finish();
+
+	tracing::subscriber::set_global_default(subscriber).expect("Failed to set subscriber");
+}
+
+/// Parse interest cache configuration from INTEREST_CACHE environment variable.
+///
+/// Returns `None` if cache should be disabled, `Some(config)` otherwise.
+///
+/// Supported formats:
+/// - "disabled", "none", "no", "false" - cache disabled
+/// - "default" - cache enabled with default config
+/// - "key=value,key=value" - cache enabled with custom config
+///   - lru_cache_size=<number> - set LRU cache size
+///   - min_verbosity=<level> - set minimum verbosity level (error, warn, info, debug, trace)
+fn parse_interest_cache_config() -> Option<tracing_log::InterestCacheConfig> {
+	let config_str = std::env::var("INTEREST_CACHE").ok()?;
+	let config_lower = config_str.to_lowercase();
+	let mut config = tracing_log::InterestCacheConfig::default();
+
+	// Check if disabled
+	if matches!(config_lower.as_str(), "none" | "disabled" | "no" | "false") {
+		eprintln!("Interest cache: disabled");
+		return Some(config.with_lru_cache_size(0));
+	}
+
+	// If "default", use default config
+	if config_lower == "default" {
+		eprintln!("Interest cache: default config");
+		return Some(config);
+	}
+
+	// Parse key=value pairs
+	for pair in config_str.split(',') {
+		let parts: Vec<&str> = pair.trim().split('=').collect();
+		if parts.len() != 2 {
+			eprintln!("Invalid config pair '{}', expected key=value", pair);
+			continue;
+		}
+
+		let key = parts[0].trim();
+		let value = parts[1].trim();
+
+		match key {
+			"lru_cache_size" =>
+				if let Ok(size) = value.parse::<usize>() {
+					config = config.with_lru_cache_size(size);
+					eprintln!("Interest cache: lru_cache_size = {}", size);
+				} else {
+					eprintln!("Invalid lru_cache_size value '{}'", value);
+				},
+			"min_verbosity" => {
+				let level = match value.to_lowercase().as_str() {
+					"error" => Some(Level::Error),
+					"warn" => Some(Level::Warn),
+					"info" => Some(Level::Info),
+					"debug" => Some(Level::Debug),
+					"trace" => Some(Level::Trace),
+					_ => {
+						eprintln!("Invalid min_verbosity '{}', using default", value);
+						None
+					},
+				};
+				if let Some(level) = level {
+					config = config.with_min_verbosity(level);
+					eprintln!("Interest cache: min_verbosity = {:?}", level);
+				}
+			},
+			_ => {
+				eprintln!("Unknown config key '{}'", key);
+			},
+		}
+	}
+
+	Some(config)
+}

bizinikiwi/client/tracing/benches/interest_cache_diverse.rs

@@ -0,0 +1,33 @@
+// This file is part of Bizinikiwi.
+//
+// Copyright (C) Parity Technologies (UK) Ltd.
+// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0
+
+//! Benchmark diverse targets with interest cache configuration from INTEREST_CACHE env var.
+//!
+//! Usage:
+//! ```
+//! INTEREST_CACHE=lru_cache_size=1024,min_verbosity=debug cargo bench --bench interest_cache_diverse
+//! INTEREST_CACHE=default cargo bench --bench interest_cache_diverse
+//! INTEREST_CACHE=disabled cargo bench --bench interest_cache_diverse
+//! ```
+
+use criterion::{criterion_group, criterion_main, Criterion};
+
+mod common;
+
+fn bench_diverse_targets(c: &mut Criterion) {
+	common::init_logger();
+	c.bench_function("diverse_targets", |b| {
+		b.iter(|| {
+			for i in 0..1000 {
+				let target = format!("module_{}", i % 50);
+				log::debug!(target: &target, "message {}", i);
+				log::trace!(target: &target, "trace {}", i);
+			}
+		})
+	});
+}
+
+criterion_group!(benches, bench_diverse_targets);
+criterion_main!(benches);

bizinikiwi/client/tracing/benches/interest_cache_multithreaded.rs

@@ -0,0 +1,44 @@
+// This file is part of Bizinikiwi.
+//
+// Copyright (C) Parity Technologies (UK) Ltd.
+// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0
+
+//! Benchmark multithreaded logging with interest cache configuration from INTEREST_CACHE env var.
+//!
+//! Usage:
+//! ```
+//! INTEREST_CACHE=lru_cache_size=1024,min_verbosity=debug cargo bench --bench interest_cache_multithreaded
+//! INTEREST_CACHE=default cargo bench --bench interest_cache_multithreaded
+//! INTEREST_CACHE=disabled cargo bench --bench interest_cache_multithreaded
+//! ```
+
+use criterion::{criterion_group, criterion_main, Criterion};
+
+mod common;
+
+fn bench_multithreaded(c: &mut Criterion) {
+	common::init_logger();
+	let mut group = c.benchmark_group("multithreaded");
+
+	group.bench_function("8_threads", |b| {
+		b.iter(|| {
+			let handles: Vec<_> = (0..8)
+				.map(|thread_id| {
+					std::thread::spawn(move || {
+						for i in 0..1000 {
+							log::debug!(target: "bizinikiwi", "thread {} msg {}", thread_id, i);
+							log::trace!(target: "runtime", "thread {} trace {}", thread_id, i);
+						}
+					})
+				})
+				.collect();
+			for handle in handles {
+				handle.join().unwrap();
+			}
+		})
+	});
+	group.finish();
+}
+
+criterion_group!(benches, bench_multithreaded);
+criterion_main!(benches);

bizinikiwi/client/tracing/benches/interest_cache_realistic.rs

@@ -0,0 +1,38 @@
+// This file is part of Bizinikiwi.
+//
+// Copyright (C) Parity Technologies (UK) Ltd.
+// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0
+
+//! Benchmark realistic logging with interest cache configuration from INTEREST_CACHE env var.
+//!
+//! Usage:
+//! ```
+//! INTEREST_CACHE=lru_cache_size=1024,min_verbosity=debug cargo bench --bench interest_cache_realistic
+//! INTEREST_CACHE=default cargo bench --bench interest_cache_realistic
+//! INTEREST_CACHE=disabled cargo bench --bench interest_cache_realistic
+//! ```
+
+use criterion::{criterion_group, criterion_main, Criterion};
+
+mod common;
+
+fn bench_realistic_logging(c: &mut Criterion) {
+	common::init_logger();
+	c.bench_function("realistic_logging", |b| {
+		b.iter(|| {
+			for i in 0..1000 {
+				log::trace!(target: "bizinikiwi", "trace message {}", i);
+				log::debug!(target: "runtime", "debug message {}", i);
+				log::debug!(target: "sync", "sync debug {}", i);
+				log::trace!(target: "consensus", "consensus trace {}", i);
+				log::debug!(target: "network", "network debug {}", i);
+				if i % 10 == 0 {
+					log::info!(target: "bizinikiwi", "info message {}", i);
+				}
+			}
+		})
+	});
+}
+
+criterion_group!(benches, bench_realistic_logging);
+criterion_main!(benches);

bizinikiwi/client/tracing/proc-macro/Cargo.toml

@@ -0,0 +1,29 @@
+[package]
+name = "pezsc-tracing-proc-macro"
+version = "11.0.0"
+authors.workspace = true
+edition.workspace = true
+license = "Apache-2.0"
+homepage.workspace = true
+repository.workspace = true
+description = "Helper macros for Bizinikiwi's client CLI"
+
+[lints]
+workspace = true
+
+[package.metadata.docs.rs]
+targets = ["x86_64-unknown-linux-gnu"]
+
+[lib]
+proc-macro = true
+
+[dependencies]
+proc-macro-crate = { workspace = true }
+proc-macro2 = { workspace = true }
+quote = { features = ["proc-macro"], workspace = true }
+syn = { features = [
+	"extra-traits",
+	"full",
+	"parsing",
+	"proc-macro",
+], workspace = true }

bizinikiwi/client/tracing/proc-macro/src/lib.rs

@@ -0,0 +1,154 @@
+// This file is part of Bizinikiwi.
+
+// Copyright (C) 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.
+
+use proc_macro::TokenStream;
+use proc_macro2::Span;
+use proc_macro_crate::{crate_name, FoundCrate};
+use quote::quote;
+use syn::{Error, Expr, ItemFn, Path, Result};
+
+/// This prefixes all the log lines with `[<name>]` (after the timestamp). It works by making a
+/// tracing's span that is propagated to all the child calls and child tasks (futures) if they are
+/// spawned properly with the `SpawnHandle` (see `TaskManager` in sc-cli) or if the futures use
+/// `.in_current_span()` (see tracing-futures).
+///
+/// See Tokio's [tracing documentation](https://docs.rs/tracing-core/) and
+/// [tracing-futures documentation](https://docs.rs/tracing-futures/) for more details.
+///
+/// # Implementation notes
+///
+/// If there are multiple spans with a log prefix, only the latest will be shown.
+///
+/// # Example with a literal
+///
+/// ```ignore
+/// Builds a new service for a light client.
+/// #[pezsc_cli::prefix_logs_with("light")]
+/// pub fn new_light(config: Configuration) -> Result<TaskManager, ServiceError> {
+///     let (client, backend, keystore, mut task_manager, on_demand) =
+///         pezsc_service::new_light_parts::<Block, RuntimeApi, Executor>(&config)?;
+///
+///        ...
+/// }
+/// ```
+///
+/// Will produce logs that look like this:
+///
+/// ```text
+/// 2020-10-16 08:03:14  Bizinikiwi Node
+/// 2020-10-16 08:03:14  ✌️  version 2.0.0-47f7d3f2e-x86_64-linux-gnu
+/// 2020-10-16 08:03:14  ❤️  by Anonymous, 2017-2020
+/// 2020-10-16 08:03:14  📋 Chain specification: Local Testnet
+/// 2020-10-16 08:03:14  🏷  Node name: nice-glove-1401
+/// 2020-10-16 08:03:14  👤 Role: LIGHT
+/// 2020-10-16 08:03:14  💾 Database: RocksDb at /tmp/bizinikiwi95w2Dk/chains/local_testnet/db
+/// 2020-10-16 08:03:14  ⛓  Native runtime: node-template-1 (node-template-1.tx1.au1)
+/// 2020-10-16 08:03:14  [light] 🔨 Initializing Genesis block/state (state: 0x121d…8e36, header-hash: 0x24ef…8ff6)
+/// 2020-10-16 08:03:14  [light] Loading GRANDPA authorities from genesis on what appears to be first startup.
+/// 2020-10-16 08:03:15  [light] ⏱  Loaded block-time = 6000 milliseconds from genesis on first-launch
+/// 2020-10-16 08:03:15  [light] Using default protocol ID "sup" because none is configured in the chain specs
+/// 2020-10-16 08:03:15  [light] 🏷  Local node identity is: 12D3KooWHX4rkWT6a6N55Km7ZnvenGdShSKPkzJ3yj9DU5nqDtWR
+/// 2020-10-16 08:03:15  [light] 📦 Highest known block at #0
+/// 2020-10-16 08:03:15  [light] 〽️ Prometheus server started at 127.0.0.1:9615
+/// 2020-10-16 08:03:15  [light] Listening for new connections on 127.0.0.1:9944.
+/// ```
+///
+/// # Example using the actual node name
+///
+/// ```ignore
+/// Builds a new service for a light client.
+/// #[pezsc_cli::prefix_logs_with(config.network.node_name.as_str())]
+/// pub fn new_light(config: Configuration) -> Result<TaskManager, ServiceError> {
+///     let (client, backend, keystore, mut task_manager, on_demand) =
+///         pezsc_service::new_light_parts::<Block, RuntimeApi, Executor>(&config)?;
+///
+///        ...
+/// }
+/// ```
+///
+/// Will produce logs that look like this:
+///
+/// ```text
+/// 2020-10-16 08:12:57  Bizinikiwi Node
+/// 2020-10-16 08:12:57  ✌️  version 2.0.0-efb9b822a-x86_64-linux-gnu
+/// 2020-10-16 08:12:57  ❤️  by Anonymous, 2017-2020
+/// 2020-10-16 08:12:57  📋 Chain specification: Local Testnet
+/// 2020-10-16 08:12:57  🏷  Node name: open-harbor-1619
+/// 2020-10-16 08:12:57  👤 Role: LIGHT
+/// 2020-10-16 08:12:57  💾 Database: RocksDb at /tmp/bizinikiwi9T9Mtb/chains/local_testnet/db
+/// 2020-10-16 08:12:57  ⛓  Native runtime: node-template-1 (node-template-1.tx1.au1)
+/// 2020-10-16 08:12:58  [open-harbor-1619] 🔨 Initializing Genesis block/state (state: 0x121d…8e36, header-hash: 0x24ef…8ff6)
+/// 2020-10-16 08:12:58  [open-harbor-1619] Loading GRANDPA authorities from genesis on what appears to be first startup.
+/// 2020-10-16 08:12:58  [open-harbor-1619] ⏱  Loaded block-time = 6000 milliseconds from genesis on first-launch
+/// 2020-10-16 08:12:58  [open-harbor-1619] Using default protocol ID "sup" because none is configured in the chain specs
+/// 2020-10-16 08:12:58  [open-harbor-1619] 🏷  Local node identity is: 12D3KooWRzmYC8QTK1Pm8Cfvid3skTS4Hn54jc4AUtje8Rqbfgtp
+/// 2020-10-16 08:12:58  [open-harbor-1619] 📦 Highest known block at #0
+/// 2020-10-16 08:12:58  [open-harbor-1619] 〽️ Prometheus server started at 127.0.0.1:9615
+/// 2020-10-16 08:12:58  [open-harbor-1619] Listening for new connections on 127.0.0.1:9944.
+/// ```
+#[proc_macro_attribute]
+pub fn prefix_logs_with(arg: TokenStream, item: TokenStream) -> TokenStream {
+	// Ensure an argument was provided.
+	if arg.is_empty() {
+		return Error::new(
+			proc_macro2::Span::call_site(),
+			"missing argument: prefix. Example: prefix_logs_with(\"Relaychain\")",
+		)
+		.to_compile_error()
+		.into();
+	}
+
+	let prefix_expr = syn::parse_macro_input!(arg as Expr);
+	let item_fn = syn::parse_macro_input!(item as ItemFn);
+
+	// Resolve the proper pezsc_tracing path.
+	let crate_name = match resolve_sc_tracing() {
+		Ok(path) => path,
+		Err(err) => return err.to_compile_error().into(),
+	};
+
+	let syn::ItemFn { attrs, vis, sig, block } = item_fn;
+
+	(quote! {
+		#(#attrs)*
+		#vis #sig {
+			let span = #crate_name::tracing::info_span!(
+				#crate_name::logging::PREFIX_LOG_SPAN,
+				name = #prefix_expr,
+			);
+			let _enter = span.enter();
+
+			#block
+		}
+	})
+	.into()
+}
+
+/// Resolve the correct path for pezsc_tracing:
+/// - If `pezkuwi-sdk` is in scope, returns a Path corresponding to `pezkuwi_sdk::pezsc_tracing`
+/// - Otherwise, falls back to `pezsc_tracing`
+fn resolve_sc_tracing() -> Result<Path> {
+	match crate_name("pezkuwi-sdk") {
+		Ok(FoundCrate::Itself) => syn::parse_str("pezkuwi_sdk::pezsc_tracing"),
+		Ok(FoundCrate::Name(sdk_name)) => syn::parse_str(&format!("{}::pezsc_tracing", sdk_name)),
+		Err(_) => match crate_name("sc-tracing") {
+			Ok(FoundCrate::Itself) => syn::parse_str("pezsc_tracing"),
+			Ok(FoundCrate::Name(name)) => syn::parse_str(&name),
+			Err(e) => Err(syn::Error::new(Span::call_site(), e)),
+		},
+	}
+}

bizinikiwi/client/tracing/src/block/mod.rs

@@ -0,0 +1,387 @@
+// Copyright (C) Parity Technologies (UK) Ltd.
+// This file is part of Bizinikiwi.
+// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0
+
+// Bizinikiwi 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.
+
+// Bizinikiwi 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 Bizinikiwi. If not, see <https://www.gnu.org/licenses/>.
+
+//! Utilities for tracing block execution
+
+use std::{
+	collections::HashMap,
+	sync::{
+		atomic::{AtomicU64, Ordering},
+		Arc,
+	},
+	time::Instant,
+};
+
+use codec::Encode;
+use parking_lot::Mutex;
+use tracing::{
+	dispatcher,
+	span::{Attributes, Id, Record},
+	Dispatch, Level, Subscriber,
+};
+
+use crate::{SpanDatum, TraceEvent, Values};
+use pezsc_client_api::BlockBackend;
+use pezsp_api::{Core, ProvideRuntimeApi};
+use pezsp_blockchain::HeaderBackend;
+use pezsp_core::hexdisplay::HexDisplay;
+use pezsp_rpc::tracing::{BlockTrace, Span, TraceBlockResponse};
+use pezsp_runtime::{
+	generic::BlockId,
+	traits::{Block as BlockT, Header},
+};
+use pezsp_tracing::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER};
+
+// Default to only pallet, frame support and state related traces
+const DEFAULT_TARGETS: &str = "pallet,frame,state";
+const TRACE_TARGET: &str = "block_trace";
+// The name of a field required for all events.
+const REQUIRED_EVENT_FIELD: &str = "method";
+
+/// Something that can execute a block in a tracing context.
+pub trait TracingExecuteBlock<Block: BlockT>: Send + Sync {
+	/// Execute the given `block`.
+	///
+	/// The `block` is prepared to be executed right away, this means that any `Seal` was already
+	/// removed from the header. As this changes the `hash` of the block, `orig_hash` is passed
+	/// alongside to the callee.
+	///
+	/// The execution should be done sync on the same thread, because the caller will register
+	/// special tracing collectors.
+	fn execute_block(&self, orig_hash: Block::Hash, block: Block) -> pezsp_blockchain::Result<()>;
+}
+
+/// Default implementation of [`ExecuteBlock`].
+///
+/// Uses [`Core::execute_block`] to directly execute a block.
+struct DefaultExecuteBlock<Client> {
+	client: Arc<Client>,
+}
+
+impl<Client> DefaultExecuteBlock<Client> {
+	/// Creates a new instance.
+	pub fn new(client: Arc<Client>) -> Self {
+		Self { client }
+	}
+}
+
+impl<Client, Block> TracingExecuteBlock<Block> for DefaultExecuteBlock<Client>
+where
+	Client: ProvideRuntimeApi<Block> + Send + Sync + 'static,
+	Client::Api: Core<Block>,
+	Block: BlockT,
+{
+	fn execute_block(&self, _: Block::Hash, block: Block) -> pezsp_blockchain::Result<()> {
+		self.client
+			.runtime_api()
+			.execute_block(*block.header().parent_hash(), block.into())
+			.map_err(Into::into)
+	}
+}
+
+/// Tracing Block Result type alias
+pub type TraceBlockResult<T> = Result<T, Error>;
+
+/// Tracing Block error
+#[derive(Debug, thiserror::Error)]
+#[allow(missing_docs)]
+#[non_exhaustive]
+pub enum Error {
+	#[error("Invalid block Id: {0}")]
+	InvalidBlockId(#[from] pezsp_blockchain::Error),
+	#[error("Missing block component: {0}")]
+	MissingBlockComponent(String),
+	#[error("Dispatch error: {0}")]
+	Dispatch(String),
+}
+
+struct BlockSubscriber {
+	targets: Vec<(String, Level)>,
+	next_id: AtomicU64,
+	spans: Mutex<HashMap<Id, SpanDatum>>,
+	events: Mutex<Vec<TraceEvent>>,
+}
+
+impl BlockSubscriber {
+	fn new(targets: &str) -> Self {
+		let next_id = AtomicU64::new(1);
+		let mut targets: Vec<_> = targets.split(',').map(crate::parse_target).collect();
+		// Ensure that WASM traces are always enabled
+		// Filtering happens when decoding the actual target / level
+		targets.push((WASM_TRACE_IDENTIFIER.to_owned(), Level::TRACE));
+		BlockSubscriber {
+			targets,
+			next_id,
+			spans: Mutex::new(HashMap::new()),
+			events: Mutex::new(Vec::new()),
+		}
+	}
+}
+
+impl Subscriber for BlockSubscriber {
+	fn enabled(&self, metadata: &tracing::Metadata<'_>) -> bool {
+		if !metadata.is_span() && metadata.fields().field(REQUIRED_EVENT_FIELD).is_none() {
+			return false;
+		}
+
+		for (target, level) in &self.targets {
+			if metadata.level() <= level && metadata.target().starts_with(target) {
+				return true;
+			}
+		}
+
+		false
+	}
+
+	fn new_span(&self, attrs: &Attributes<'_>) -> Id {
+		let id = Id::from_u64(self.next_id.fetch_add(1, Ordering::Relaxed));
+		let mut values = Values::default();
+		attrs.record(&mut values);
+		let parent_id = attrs.parent().cloned();
+		let span = SpanDatum {
+			id: id.clone(),
+			parent_id,
+			name: attrs.metadata().name().to_owned(),
+			target: attrs.metadata().target().to_owned(),
+			level: *attrs.metadata().level(),
+			line: attrs.metadata().line().unwrap_or(0),
+			start_time: Instant::now(),
+			values,
+			overall_time: Default::default(),
+		};
+
+		self.spans.lock().insert(id.clone(), span);
+		id
+	}
+
+	fn record(&self, span: &Id, values: &Record<'_>) {
+		let mut span_data = self.spans.lock();
+		if let Some(s) = span_data.get_mut(span) {
+			values.record(&mut s.values);
+		}
+	}
+
+	fn record_follows_from(&self, _span: &Id, _follows: &Id) {
+		// Not currently used
+		unimplemented!("record_follows_from is not implemented");
+	}
+
+	fn event(&self, event: &tracing::Event<'_>) {
+		let mut values = crate::Values::default();
+		event.record(&mut values);
+		let parent_id = event.parent().cloned();
+		let trace_event = TraceEvent {
+			name: event.metadata().name().to_owned(),
+			target: event.metadata().target().to_owned(),
+			level: *event.metadata().level(),
+			values,
+			parent_id,
+		};
+		self.events.lock().push(trace_event);
+	}
+
+	fn enter(&self, _id: &Id) {}
+
+	fn exit(&self, _span: &Id) {}
+}
+
+/// Holds a reference to the client in order to execute the given block.
+/// Records spans & events for the supplied targets (eg. "pallet,frame,state") and
+/// only records events with the specified hex encoded storage key prefixes.
+/// Note: if `targets` or `storage_keys` is an empty string then nothing is
+/// filtered out.
+pub struct BlockExecutor<Block: BlockT, Client> {
+	client: Arc<Client>,
+	block: Block::Hash,
+	targets: Option<String>,
+	storage_keys: Option<String>,
+	methods: Option<String>,
+	execute_block: Arc<dyn TracingExecuteBlock<Block>>,
+}
+
+impl<Block, Client> BlockExecutor<Block, Client>
+where
+	Block: BlockT + 'static,
+	Client: HeaderBackend<Block>
+		+ BlockBackend<Block>
+		+ ProvideRuntimeApi<Block>
+		+ Send
+		+ Sync
+		+ 'static,
+	Client::Api: Core<Block>,
+{
+	/// Create a new `BlockExecutor`
+	pub fn new(
+		client: Arc<Client>,
+		block: Block::Hash,
+		targets: Option<String>,
+		storage_keys: Option<String>,
+		methods: Option<String>,
+		execute_block: Option<Arc<dyn TracingExecuteBlock<Block>>>,
+	) -> Self {
+		Self {
+			client: client.clone(),
+			block,
+			targets,
+			storage_keys,
+			methods,
+			execute_block: execute_block
+				.unwrap_or_else(|| Arc::new(DefaultExecuteBlock::new(client))),
+		}
+	}
+
+	/// Execute block, record all spans and events belonging to `Self::targets`
+	/// and filter out events which do not have keys starting with one of the
+	/// prefixes in `Self::storage_keys`.
+	pub fn trace_block(&self) -> TraceBlockResult<TraceBlockResponse> {
+		tracing::debug!(target: "state_tracing", "Tracing block: {}", self.block);
+		// Prepare the block
+		let mut header = self
+			.client
+			.header(self.block)
+			.map_err(Error::InvalidBlockId)?
+			.ok_or_else(|| Error::MissingBlockComponent("Header not found".to_string()))?;
+		let extrinsics = self
+			.client
+			.block_body(self.block)
+			.map_err(Error::InvalidBlockId)?
+			.ok_or_else(|| Error::MissingBlockComponent("Extrinsics not found".to_string()))?;
+		tracing::debug!(target: "state_tracing", "Found {} extrinsics", extrinsics.len());
+		let parent_hash = *header.parent_hash();
+		// Remove all `Seal`s as they are added by the consensus engines after building the block.
+		// On import they are normally removed by the consensus engine.
+		header.digest_mut().logs.retain(|d| d.as_seal().is_none());
+		let block = Block::new(header, extrinsics);
+
+		let targets = if let Some(t) = &self.targets { t } else { DEFAULT_TARGETS };
+		let block_subscriber = BlockSubscriber::new(targets);
+		let dispatch = Dispatch::new(block_subscriber);
+
+		{
+			let dispatcher_span = tracing::debug_span!(
+				target: "state_tracing",
+				"execute_block",
+				extrinsics_len = block.extrinsics().len(),
+			);
+			let _guard = dispatcher_span.enter();
+
+			if let Err(e) = dispatcher::with_default(&dispatch, || {
+				let span = tracing::info_span!(target: TRACE_TARGET, "trace_block");
+				let _enter = span.enter();
+				self.execute_block.execute_block(self.block, block)
+			}) {
+				return Err(Error::Dispatch(format!(
+					"Failed to collect traces and execute block: {e:?}"
+				)));
+			}
+		}
+
+		let block_subscriber = dispatch.downcast_ref::<BlockSubscriber>().ok_or_else(|| {
+			Error::Dispatch(
+				"Cannot downcast Dispatch to BlockSubscriber after tracing block".to_string(),
+			)
+		})?;
+		let spans: Vec<_> = block_subscriber
+			.spans
+			.lock()
+			.drain()
+			// Patch wasm identifiers
+			.filter_map(|(_, s)| patch_and_filter(s, targets))
+			.collect();
+		let events: Vec<_> = block_subscriber
+			.events
+			.lock()
+			.drain(..)
+			.filter(|e| {
+				self.storage_keys
+					.as_ref()
+					.map(|keys| event_values_filter(e, "key", keys))
+					.unwrap_or(false)
+			})
+			.filter(|e| {
+				self.methods
+					.as_ref()
+					.map(|methods| event_values_filter(e, "method", methods))
+					.unwrap_or(false)
+			})
+			.map(|s| s.into())
+			.collect();
+		tracing::debug!(target: "state_tracing", "Captured {} spans and {} events", spans.len(), events.len());
+
+		Ok(TraceBlockResponse::BlockTrace(BlockTrace {
+			block_hash: block_id_as_string(BlockId::<Block>::Hash(self.block)),
+			parent_hash: block_id_as_string(BlockId::<Block>::Hash(parent_hash)),
+			tracing_targets: targets.to_string(),
+			storage_keys: self.storage_keys.clone().unwrap_or_default(),
+			methods: self.methods.clone().unwrap_or_default(),
+			spans,
+			events,
+		}))
+	}
+}
+
+fn event_values_filter(event: &TraceEvent, filter_kind: &str, values: &str) -> bool {
+	event
+		.values
+		.string_values
+		.get(filter_kind)
+		.map(|value| check_target(values, value, &event.level))
+		.unwrap_or(false)
+}
+
+/// Filter out spans that do not match our targets and if the span is from WASM update its `name`
+/// and `target` fields to the WASM values for those fields.
+// The `tracing` crate requires trace metadata to be static. This does not work for wasm code in
+// bizinikiwi, as it is regularly updated with new code from on-chain events. The workaround for this
+// is for bizinikiwi's WASM tracing wrappers to put the `name` and `target` data in the `values` map
+// (normally they would be in the static metadata assembled at compile time). Here, if a special
+// WASM `name` or `target` key is found in the `values` we remove it and put the key value pair in
+// the span's metadata, making it consistent with spans that come from native code.
+fn patch_and_filter(mut span: SpanDatum, targets: &str) -> Option<Span> {
+	if span.name == WASM_TRACE_IDENTIFIER {
+		span.values.bool_values.insert("wasm".to_owned(), true);
+		if let Some(n) = span.values.string_values.remove(WASM_NAME_KEY) {
+			span.name = n;
+		}
+		if let Some(t) = span.values.string_values.remove(WASM_TARGET_KEY) {
+			span.target = t;
+		}
+		if !check_target(targets, &span.target, &span.level) {
+			return None;
+		}
+	}
+
+	Some(span.into())
+}
+
+/// Check if a `target` matches any `targets` by prefix
+fn check_target(targets: &str, target: &str, level: &Level) -> bool {
+	for (t, l) in targets.split(',').map(crate::parse_target) {
+		if target.starts_with(t.as_str()) && level <= &l {
+			return true;
+		}
+	}
+
+	false
+}
+
+fn block_id_as_string<T: BlockT>(block_id: BlockId<T>) -> String {
+	match block_id {
+		BlockId::Hash(h) => HexDisplay::from(&h.encode()).to_string(),
+		BlockId::Number(n) => HexDisplay::from(&n.encode()).to_string(),
+	}
+}

bizinikiwi/client/tracing/src/lib.rs

@@ -0,0 +1,675 @@
+// This file is part of Bizinikiwi.
+
+// Copyright (C) Parity Technologies (UK) Ltd.
+// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0
+
+// This program is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+
+// This program is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+// GNU General Public License for more details.
+
+// You should have received a copy of the GNU General Public License
+// along with this program. If not, see <https://www.gnu.org/licenses/>.
+
+//! Instrumentation implementation for bizinikiwi.
+//!
+//! This crate is unstable and the API and usage may change.
+//!
+//! # Usage
+//!
+//! See `sp-tracing` for examples on how to use tracing.
+//!
+//! Currently we only provide `Log` (default).
+
+#![warn(missing_docs)]
+
+pub mod block;
+pub mod logging;
+
+use rustc_hash::FxHashMap;
+use serde::ser::{Serialize, SerializeMap, Serializer};
+use pezsp_tracing::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER};
+use std::{
+	fmt,
+	time::{Duration, Instant},
+};
+use tracing::{
+	event::Event,
+	field::{Field, Visit},
+	span::{Attributes, Id, Record},
+	subscriber::Subscriber,
+	Level,
+};
+use tracing_subscriber::{
+	layer::{Context, Layer},
+	registry::LookupSpan,
+};
+
+#[doc(hidden)]
+pub use tracing;
+
+const ZERO_DURATION: Duration = Duration::from_nanos(0);
+
+/// Responsible for assigning ids to new spans, which are not re-used.
+pub struct ProfilingLayer {
+	targets: Vec<(String, Level)>,
+	trace_handlers: Vec<Box<dyn TraceHandler>>,
+}
+
+/// Used to configure how to receive the metrics
+#[derive(Debug, Clone)]
+pub enum TracingReceiver {
+	/// Output to logger
+	Log,
+}
+
+impl Default for TracingReceiver {
+	fn default() -> Self {
+		Self::Log
+	}
+}
+
+/// A handler for tracing `SpanDatum`
+pub trait TraceHandler: Send + Sync {
+	/// Process a `SpanDatum`.
+	fn handle_span(&self, span: &SpanDatum);
+	/// Process a `TraceEvent`.
+	fn handle_event(&self, event: &TraceEvent);
+}
+
+/// Represents a tracing event, complete with values
+#[derive(Debug, Clone)]
+pub struct TraceEvent {
+	/// Name of the event.
+	pub name: String,
+	/// Target of the event.
+	pub target: String,
+	/// Level of the event.
+	pub level: Level,
+	/// Values for this event.
+	pub values: Values,
+	/// Id of the parent tracing event, if any.
+	pub parent_id: Option<Id>,
+}
+
+/// Represents a single instance of a tracing span
+#[derive(Debug, Clone)]
+pub struct SpanDatum {
+	/// id for this span
+	pub id: Id,
+	/// id of the parent span, if any
+	pub parent_id: Option<Id>,
+	/// Name of this span
+	pub name: String,
+	/// Target, typically module
+	pub target: String,
+	/// Tracing Level - ERROR, WARN, INFO, DEBUG or TRACE
+	pub level: Level,
+	/// Line number in source
+	pub line: u32,
+	/// Time that the span was last entered
+	pub start_time: Instant,
+	/// Total duration of span while entered
+	pub overall_time: Duration,
+	/// Values recorded to this span
+	pub values: Values,
+}
+
+/// Holds associated values for a tracing span
+#[derive(Default, Clone, Debug)]
+pub struct Values {
+	/// FxHashMap of `bool` values
+	pub bool_values: FxHashMap<String, bool>,
+	/// FxHashMap of `i64` values
+	pub i64_values: FxHashMap<String, i64>,
+	/// FxHashMap of `u64` values
+	pub u64_values: FxHashMap<String, u64>,
+	/// FxHashMap of `String` values
+	pub string_values: FxHashMap<String, String>,
+}
+
+impl Values {
+	/// Returns a new instance of Values
+	pub fn new() -> Self {
+		Default::default()
+	}
+
+	/// Checks if all individual collections are empty
+	pub fn is_empty(&self) -> bool {
+		self.bool_values.is_empty() &&
+			self.i64_values.is_empty() &&
+			self.u64_values.is_empty() &&
+			self.string_values.is_empty()
+	}
+}
+
+impl Visit for Values {
+	fn record_i64(&mut self, field: &Field, value: i64) {
+		self.i64_values.insert(field.name().to_string(), value);
+	}
+
+	fn record_u64(&mut self, field: &Field, value: u64) {
+		self.u64_values.insert(field.name().to_string(), value);
+	}
+
+	fn record_bool(&mut self, field: &Field, value: bool) {
+		self.bool_values.insert(field.name().to_string(), value);
+	}
+
+	fn record_str(&mut self, field: &Field, value: &str) {
+		self.string_values.insert(field.name().to_string(), value.to_owned());
+	}
+
+	fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
+		self.string_values.insert(field.name().to_string(), format!("{:?}", value));
+	}
+}
+
+impl Serialize for Values {
+	fn serialize<S>(&self, serializer: S) -> Result<S::Ok, S::Error>
+	where
+		S: Serializer,
+	{
+		let len = self.bool_values.len() +
+			self.i64_values.len() +
+			self.u64_values.len() +
+			self.string_values.len();
+		let mut map = serializer.serialize_map(Some(len))?;
+		for (k, v) in &self.bool_values {
+			map.serialize_entry(k, v)?;
+		}
+		for (k, v) in &self.i64_values {
+			map.serialize_entry(k, v)?;
+		}
+		for (k, v) in &self.u64_values {
+			map.serialize_entry(k, v)?;
+		}
+		for (k, v) in &self.string_values {
+			map.serialize_entry(k, v)?;
+		}
+		map.end()
+	}
+}
+
+impl fmt::Display for Values {
+	fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+		let bool_iter = self.bool_values.iter().map(|(k, v)| format!("{}={}", k, v));
+		let i64_iter = self.i64_values.iter().map(|(k, v)| format!("{}={}", k, v));
+		let u64_iter = self.u64_values.iter().map(|(k, v)| format!("{}={}", k, v));
+		let string_iter = self.string_values.iter().map(|(k, v)| format!("{}=\"{}\"", k, v));
+		let values = bool_iter
+			.chain(i64_iter)
+			.chain(u64_iter)
+			.chain(string_iter)
+			.collect::<Vec<String>>()
+			.join(", ");
+		write!(f, "{}", values)
+	}
+}
+
+/// Trace handler event types.
+#[derive(Debug)]
+pub enum TraceHandlerEvents {
+	/// An event.
+	Event(TraceEvent),
+	/// A span.
+	Span(SpanDatum),
+}
+
+impl ProfilingLayer {
+	/// Takes a `TracingReceiver` and a comma separated list of targets,
+	/// either with a level: "pallet=trace,frame=debug"
+	/// or without: "pallet,frame" in which case the level defaults to `trace`.
+	/// wasm_tracing indicates whether to enable wasm traces
+	pub fn new(receiver: TracingReceiver, targets: &str) -> Self {
+		match receiver {
+			TracingReceiver::Log => Self::new_with_handler(Box::new(LogTraceHandler), targets),
+		}
+	}
+
+	/// Allows use of a custom TraceHandler to create a new instance of ProfilingSubscriber.
+	/// Takes a comma separated list of targets,
+	/// either with a level, eg: "pallet=trace"
+	/// or without: "pallet" in which case the level defaults to `trace`.
+	/// wasm_tracing indicates whether to enable wasm traces
+	pub fn new_with_handler(trace_handler: Box<dyn TraceHandler>, targets: &str) -> Self {
+		let targets: Vec<_> = targets.split(',').map(parse_target).collect();
+		Self { targets, trace_handlers: vec![trace_handler] }
+	}
+
+	/// Attach additional handlers to allow handling of custom events/spans.
+	pub fn add_handler(&mut self, trace_handler: Box<dyn TraceHandler>) {
+		self.trace_handlers.push(trace_handler);
+	}
+
+	fn check_target(&self, target: &str, level: &Level) -> bool {
+		for t in &self.targets {
+			if target.starts_with(t.0.as_str()) && level <= &t.1 {
+				return true;
+			}
+		}
+		false
+	}
+
+	/// Sequentially dispatch a trace event to all handlers.
+	fn dispatch_event(&self, event: TraceHandlerEvents) {
+		match &event {
+			TraceHandlerEvents::Span(span_datum) => {
+				self.trace_handlers.iter().for_each(|handler| handler.handle_span(span_datum));
+			},
+			TraceHandlerEvents::Event(event) => {
+				self.trace_handlers.iter().for_each(|handler| handler.handle_event(event));
+			},
+		}
+	}
+}
+
+// Default to TRACE if no level given or unable to parse Level
+// We do not support a global `Level` currently
+fn parse_target(s: &str) -> (String, Level) {
+	match s.find('=') {
+		Some(i) => {
+			let target = s[0..i].to_string();
+			if s.len() > i {
+				let level = s[i + 1..].parse::<Level>().unwrap_or(Level::TRACE);
+				(target, level)
+			} else {
+				(target, Level::TRACE)
+			}
+		},
+		None => (s.to_string(), Level::TRACE),
+	}
+}
+
+impl<S> Layer<S> for ProfilingLayer
+where
+	S: Subscriber + for<'span> LookupSpan<'span>,
+{
+	fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<S>) {
+		if let Some(span) = ctx.span(id) {
+			let mut extension = span.extensions_mut();
+			let parent_id = attrs.parent().cloned().or_else(|| {
+				if attrs.is_contextual() {
+					ctx.lookup_current().map(|span| span.id())
+				} else {
+					None
+				}
+			});
+
+			let mut values = Values::default();
+			attrs.record(&mut values);
+			let span_datum = SpanDatum {
+				id: id.clone(),
+				parent_id,
+				name: attrs.metadata().name().to_owned(),
+				target: attrs.metadata().target().to_owned(),
+				level: *attrs.metadata().level(),
+				line: attrs.metadata().line().unwrap_or(0),
+				start_time: Instant::now(),
+				overall_time: ZERO_DURATION,
+				values,
+			};
+			extension.insert(span_datum);
+		}
+	}
+
+	fn on_record(&self, id: &Id, values: &Record<'_>, ctx: Context<S>) {
+		if let Some(span) = ctx.span(id) {
+			let mut extensions = span.extensions_mut();
+			if let Some(s) = extensions.get_mut::<SpanDatum>() {
+				values.record(&mut s.values);
+			}
+		}
+	}
+
+	fn on_event(&self, event: &Event<'_>, ctx: Context<S>) {
+		if !self.check_target(event.metadata().target(), &event.metadata().level()) {
+			return;
+		}
+
+		let parent_id = event.parent().cloned().or_else(|| {
+			if event.is_contextual() {
+				ctx.lookup_current().map(|span| span.id())
+			} else {
+				None
+			}
+		});
+
+		let mut values = Values::default();
+		event.record(&mut values);
+		let trace_event = TraceEvent {
+			name: event.metadata().name().to_owned(),
+			target: event.metadata().target().to_owned(),
+			level: *event.metadata().level(),
+			values,
+			parent_id,
+		};
+		self.dispatch_event(TraceHandlerEvents::Event(trace_event));
+	}
+
+	fn on_enter(&self, span: &Id, ctx: Context<S>) {
+		if let Some(span) = ctx.span(span) {
+			let mut extensions = span.extensions_mut();
+			if let Some(s) = extensions.get_mut::<SpanDatum>() {
+				let start_time = Instant::now();
+				s.start_time = start_time;
+			}
+		}
+	}
+
+	fn on_exit(&self, span: &Id, ctx: Context<S>) {
+		if let Some(span) = ctx.span(span) {
+			let end_time = Instant::now();
+			let mut extensions = span.extensions_mut();
+			if let Some(mut span_datum) = extensions.remove::<SpanDatum>() {
+				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) {
+						span_datum.name = n;
+					}
+					if let Some(t) = span_datum.values.string_values.remove(WASM_TARGET_KEY) {
+						span_datum.target = t;
+					}
+					if self.check_target(&span_datum.target, &span_datum.level) {
+						self.dispatch_event(TraceHandlerEvents::Span(span_datum));
+					}
+				} else {
+					self.dispatch_event(TraceHandlerEvents::Span(span_datum));
+				}
+			}
+		}
+	}
+
+	fn on_close(&self, _span: Id, _ctx: Context<S>) {}
+}
+
+/// TraceHandler for sending span data to the logger
+pub struct LogTraceHandler;
+
+fn log_level(level: Level) -> log::Level {
+	match level {
+		Level::TRACE => log::Level::Trace,
+		Level::DEBUG => log::Level::Debug,
+		Level::INFO => log::Level::Info,
+		Level::WARN => log::Level::Warn,
+		Level::ERROR => log::Level::Error,
+	}
+}
+
+impl TraceHandler for LogTraceHandler {
+	fn handle_span(&self, span_datum: &SpanDatum) {
+		if span_datum.values.is_empty() {
+			log::log!(
+				log_level(span_datum.level),
+				"{}: {}, time: {}, id: {}, parent_id: {:?}",
+				span_datum.target,
+				span_datum.name,
+				span_datum.overall_time.as_nanos(),
+				span_datum.id.into_u64(),
+				span_datum.parent_id.as_ref().map(|s| s.into_u64()),
+			);
+		} else {
+			log::log!(
+				log_level(span_datum.level),
+				"{}: {}, time: {}, id: {}, parent_id: {:?}, values: {}",
+				span_datum.target,
+				span_datum.name,
+				span_datum.overall_time.as_nanos(),
+				span_datum.id.into_u64(),
+				span_datum.parent_id.as_ref().map(|s| s.into_u64()),
+				span_datum.values,
+			);
+		}
+	}
+
+	fn handle_event(&self, event: &TraceEvent) {
+		log::log!(
+			log_level(event.level),
+			"{}, parent_id: {:?}, {}",
+			event.target,
+			event.parent_id.as_ref().map(|s| s.into_u64()),
+			event.values,
+		);
+	}
+}
+
+impl From<TraceEvent> for pezsp_rpc::tracing::Event {
+	fn from(trace_event: TraceEvent) -> Self {
+		let data = pezsp_rpc::tracing::Data { string_values: trace_event.values.string_values };
+		pezsp_rpc::tracing::Event {
+			target: trace_event.target,
+			data,
+			parent_id: trace_event.parent_id.map(|id| id.into_u64()),
+		}
+	}
+}
+
+impl From<SpanDatum> for pezsp_rpc::tracing::Span {
+	fn from(span_datum: SpanDatum) -> Self {
+		let wasm = span_datum.values.bool_values.get("wasm").is_some();
+		pezsp_rpc::tracing::Span {
+			id: span_datum.id.into_u64(),
+			parent_id: span_datum.parent_id.map(|id| id.into_u64()),
+			name: span_datum.name,
+			target: span_datum.target,
+			wasm,
+		}
+	}
+}
+
+#[cfg(test)]
+mod tests {
+	use super::*;
+	use parking_lot::Mutex;
+	use std::sync::{
+		mpsc::{Receiver, Sender},
+		Arc,
+	};
+	use tracing_subscriber::layer::SubscriberExt;
+
+	struct TestTraceHandler {
+		spans: Arc<Mutex<Vec<SpanDatum>>>,
+		events: Arc<Mutex<Vec<TraceEvent>>>,
+	}
+
+	impl TraceHandler for TestTraceHandler {
+		fn handle_span(&self, sd: &SpanDatum) {
+			self.spans.lock().push(sd.clone());
+		}
+
+		fn handle_event(&self, event: &TraceEvent) {
+			self.events.lock().push(event.clone());
+		}
+	}
+
+	fn setup_subscriber() -> (
+		impl tracing::Subscriber + Send + Sync,
+		Arc<Mutex<Vec<SpanDatum>>>,
+		Arc<Mutex<Vec<TraceEvent>>>,
+	) {
+		let spans = Arc::new(Mutex::new(Vec::new()));
+		let events = Arc::new(Mutex::new(Vec::new()));
+		let handler = TestTraceHandler { spans: spans.clone(), events: events.clone() };
+		let layer = ProfilingLayer::new_with_handler(Box::new(handler), "test_target");
+		let subscriber = tracing_subscriber::fmt().with_writer(std::io::sink).finish().with(layer);
+		(subscriber, spans, events)
+	}
+
+	#[test]
+	fn test_span() {
+		let (sub, spans, events) = setup_subscriber();
+		let _sub_guard = tracing::subscriber::set_default(sub);
+		let span = tracing::info_span!(target: "test_target", "test_span1");
+		assert_eq!(spans.lock().len(), 0);
+		assert_eq!(events.lock().len(), 0);
+		let _guard = span.enter();
+		assert_eq!(spans.lock().len(), 0);
+		assert_eq!(events.lock().len(), 0);
+		drop(_guard);
+		drop(span);
+		assert_eq!(spans.lock().len(), 1);
+		assert_eq!(events.lock().len(), 0);
+		let sd = spans.lock().remove(0);
+		assert_eq!(sd.name, "test_span1");
+		assert_eq!(sd.target, "test_target");
+		let time: u128 = sd.overall_time.as_nanos();
+		assert!(time > 0);
+	}
+
+	#[test]
+	fn test_span_parent_id() {
+		let (sub, spans, _events) = setup_subscriber();
+		let _sub_guard = tracing::subscriber::set_default(sub);
+		let span1 = tracing::info_span!(target: "test_target", "test_span1");
+		let _guard1 = span1.enter();
+		let span2 = tracing::info_span!(target: "test_target", "test_span2");
+		let _guard2 = span2.enter();
+		drop(_guard2);
+		drop(span2);
+		let sd2 = spans.lock().remove(0);
+		drop(_guard1);
+		drop(span1);
+		let sd1 = spans.lock().remove(0);
+		assert_eq!(sd1.id, sd2.parent_id.unwrap())
+	}
+
+	#[test]
+	fn test_span_values() {
+		let (sub, spans, _events) = setup_subscriber();
+		let _sub_guard = tracing::subscriber::set_default(sub);
+		let test_bool = true;
+		let test_u64 = 1u64;
+		let test_i64 = 2i64;
+		let test_str = "test_str";
+		let span = tracing::info_span!(
+			target: "test_target",
+			"test_span1",
+			test_bool,
+			test_u64,
+			test_i64,
+			test_str
+		);
+		let _guard = span.enter();
+		drop(_guard);
+		drop(span);
+		let sd = spans.lock().remove(0);
+		assert_eq!(sd.name, "test_span1");
+		assert_eq!(sd.target, "test_target");
+		let values = sd.values;
+		assert_eq!(values.bool_values.get("test_bool").unwrap(), &test_bool);
+		assert_eq!(values.u64_values.get("test_u64").unwrap(), &test_u64);
+		assert_eq!(values.i64_values.get("test_i64").unwrap(), &test_i64);
+		assert_eq!(values.string_values.get("test_str").unwrap(), &test_str.to_owned());
+	}
+
+	#[test]
+	fn test_event() {
+		let (sub, _spans, events) = setup_subscriber();
+		let _sub_guard = tracing::subscriber::set_default(sub);
+		tracing::event!(target: "test_target", tracing::Level::INFO, "test_event");
+		let mut te1 = events.lock().remove(0);
+		assert_eq!(
+			te1.values.string_values.remove(&"message".to_owned()).unwrap(),
+			"test_event".to_owned()
+		);
+	}
+
+	#[test]
+	fn test_event_parent_id() {
+		let (sub, spans, events) = setup_subscriber();
+		let _sub_guard = tracing::subscriber::set_default(sub);
+
+		// enter span
+		let span1 = tracing::info_span!(target: "test_target", "test_span1");
+		let _guard1 = span1.enter();
+
+		// emit event
+		tracing::event!(target: "test_target", tracing::Level::INFO, "test_event");
+
+		// exit span
+		drop(_guard1);
+		drop(span1);
+
+		let sd1 = spans.lock().remove(0);
+		let te1 = events.lock().remove(0);
+
+		assert_eq!(sd1.id, te1.parent_id.unwrap());
+	}
+
+	#[test]
+	fn test_parent_id_with_threads() {
+		use std::{sync::mpsc, thread};
+
+		if std::env::var("RUN_TEST_PARENT_ID_WITH_THREADS").is_err() {
+			let executable = std::env::current_exe().unwrap();
+			let mut command = std::process::Command::new(executable);
+
+			let res = command
+				.env("RUN_TEST_PARENT_ID_WITH_THREADS", "1")
+				.args(&["--nocapture", "test_parent_id_with_threads"])
+				.output()
+				.unwrap()
+				.status;
+			assert!(res.success());
+		} else {
+			let (sub, spans, events) = setup_subscriber();
+			let _sub_guard = tracing::subscriber::set_global_default(sub);
+			let span1 = tracing::info_span!(target: "test_target", "test_span1");
+			let _guard1 = span1.enter();
+
+			let (tx, rx): (Sender<bool>, Receiver<bool>) = mpsc::channel();
+			let handle = thread::spawn(move || {
+				let span2 = tracing::info_span!(target: "test_target", "test_span2");
+				let _guard2 = span2.enter();
+				// emit event
+				tracing::event!(target: "test_target", tracing::Level::INFO, "test_event1");
+				let _ = rx.recv();
+				// guard2 and span2 dropped / exited
+			});
+
+			// wait for Event to be dispatched and stored
+			while events.lock().is_empty() {
+				thread::sleep(Duration::from_millis(1));
+			}
+
+			// emit new event (will be second item in Vec) while span2 still active in other thread
+			tracing::event!(target: "test_target", tracing::Level::INFO, "test_event2");
+
+			// stop thread and drop span
+			let _ = tx.send(false);
+			let _ = handle.join();
+
+			// wait for Span to be dispatched and stored
+			while spans.lock().is_empty() {
+				thread::sleep(Duration::from_millis(1));
+			}
+			let span2 = spans.lock().remove(0);
+			let event1 = events.lock().remove(0);
+			drop(_guard1);
+			drop(span1);
+
+			// emit event with no parent
+			tracing::event!(target: "test_target", tracing::Level::INFO, "test_event3");
+
+			let span1 = spans.lock().remove(0);
+			let event2 = events.lock().remove(0);
+
+			assert_eq!(event1.values.string_values.get("message").unwrap(), "test_event1");
+			assert_eq!(event2.values.string_values.get("message").unwrap(), "test_event2");
+			assert!(span1.parent_id.is_none());
+			assert!(span2.parent_id.is_none());
+			assert_eq!(span2.id, event1.parent_id.unwrap());
+			assert_eq!(span1.id, event2.parent_id.unwrap());
+			assert_ne!(span2.id, span1.id);
+
+			let event3 = events.lock().remove(0);
+			assert!(event3.parent_id.is_none());
+		}
+	}
+}

bizinikiwi/client/tracing/src/logging/directives.rs

@@ -0,0 +1,119 @@
+// Copyright (C) Parity Technologies (UK) Ltd.
+// This file is part of Bizinikiwi.
+// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0
+
+// Bizinikiwi 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.
+
+// Bizinikiwi 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 Bizinikiwi. If not, see <https://www.gnu.org/licenses/>.
+
+use parking_lot::Mutex;
+use std::sync::OnceLock;
+use tracing_subscriber::{
+	filter::Directive, fmt as tracing_fmt, layer, reload::Handle, EnvFilter, Registry,
+};
+
+// Handle to reload the tracing log filter
+static FILTER_RELOAD_HANDLE: OnceLock<Handle<EnvFilter, SCSubscriber>> = OnceLock::new();
+// Directives that are defaulted to when resetting the log filter
+static DEFAULT_DIRECTIVES: OnceLock<Mutex<Vec<String>>> = OnceLock::new();
+// Current state of log filter
+static CURRENT_DIRECTIVES: OnceLock<Mutex<Vec<String>>> = OnceLock::new();
+
+/// Add log filter directive(s) to the defaults
+///
+/// The syntax is identical to the CLI `<target>=<level>`:
+///
+/// `sync=debug,state=trace`
+pub(crate) fn add_default_directives(directives: &str) {
+	DEFAULT_DIRECTIVES
+		.get_or_init(|| Mutex::new(Vec::new()))
+		.lock()
+		.push(directives.to_owned());
+	add_directives(directives);
+}
+
+/// Add directives to current directives.
+pub fn add_directives(directives: &str) {
+	CURRENT_DIRECTIVES
+		.get_or_init(|| Mutex::new(Vec::new()))
+		.lock()
+		.push(directives.to_owned());
+}
+
+/// Returns the current directives.
+pub fn get_directives() -> Vec<String> {
+	CURRENT_DIRECTIVES.get_or_init(|| Mutex::new(Vec::new())).lock().clone()
+}
+
+/// Parse `Directive` and add to default directives if successful.
+///
+/// Ensures the supplied directive will be restored when resetting the log filter.
+pub(crate) fn parse_default_directive(directive: &str) -> super::Result<Directive> {
+	let dir = directive.parse()?;
+	add_default_directives(directive);
+	Ok(dir)
+}
+
+/// Reload the logging filter with the supplied directives added to the existing directives
+pub fn reload_filter() -> Result<(), String> {
+	let mut env_filter = EnvFilter::default();
+	if let Some(current_directives) = CURRENT_DIRECTIVES.get() {
+		// Use join and then split in case any directives added together
+		for directive in current_directives.lock().join(",").split(',').map(|d| d.parse()) {
+			match directive {
+				Ok(dir) => env_filter = env_filter.add_directive(dir),
+				Err(invalid_directive) => {
+					log::warn!(
+						target: "tracing",
+						"Unable to parse directive while setting log filter: {:?}",
+						invalid_directive,
+					);
+				},
+			}
+		}
+	}
+
+	// Set the max logging level for the `log` macros.
+	let max_level_hint =
+		tracing_subscriber::Layer::<tracing_subscriber::FmtSubscriber>::max_level_hint(&env_filter);
+	log::set_max_level(super::to_log_level_filter(max_level_hint));
+
+	log::debug!(target: "tracing", "Reloading log filter with: {}", env_filter);
+	FILTER_RELOAD_HANDLE
+		.get()
+		.ok_or("No reload handle present")?
+		.reload(env_filter)
+		.map_err(|e| format!("{}", e))
+}
+
+/// Resets the log filter back to the original state when the node was started.
+///
+/// Includes bizinikiwi defaults and CLI supplied directives.
+pub fn reset_log_filter() -> Result<(), String> {
+	let directive = DEFAULT_DIRECTIVES.get_or_init(|| Mutex::new(Vec::new())).lock().clone();
+
+	*CURRENT_DIRECTIVES.get_or_init(|| Mutex::new(Vec::new())).lock() = directive;
+	reload_filter()
+}
+
+/// Initialize FILTER_RELOAD_HANDLE, only possible once
+pub(crate) fn set_reload_handle(handle: Handle<EnvFilter, SCSubscriber>) {
+	let _ = FILTER_RELOAD_HANDLE.set(handle);
+}
+
+// The layered Subscriber as built up in `LoggerBuilder::init()`.
+// Used in the reload `Handle`.
+type SCSubscriber<
+	N = tracing_fmt::format::DefaultFields,
+	E = crate::logging::EventFormat,
+	W = crate::logging::DefaultLogger,
+> = layer::Layered<tracing_fmt::Layer<Registry, N, E, W>, Registry>;

bizinikiwi/client/tracing/src/logging/event_format.rs

@@ -0,0 +1,232 @@
+// This file is part of Bizinikiwi.
+
+// Copyright (C) Parity Technologies (UK) Ltd.
+// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0
+
+// This program is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+
+// This program is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+// GNU General Public License for more details.
+
+// You should have received a copy of the GNU General Public License
+// along with this program. If not, see <https://www.gnu.org/licenses/>.
+
+use crate::logging::fast_local_time::FastLocalTime;
+use console::style;
+use std::fmt;
+use tracing::{Event, Level, Subscriber};
+use tracing_log::NormalizeEvent;
+use tracing_subscriber::{
+	fmt::{format, time::FormatTime, FmtContext, FormatEvent, FormatFields},
+	registry::LookupSpan,
+};
+
+/// A pre-configured event formatter.
+pub struct EventFormat<T = FastLocalTime> {
+	/// Use the given timer for log message timestamps.
+	pub timer: T,
+	/// Sets whether or not an event's target is displayed.
+	pub display_target: bool,
+	/// Sets whether or not an event's level is displayed.
+	pub display_level: bool,
+	/// Sets whether or not the name of the current thread is displayed when formatting events.
+	pub display_thread_name: bool,
+	/// Duplicate INFO, WARN and ERROR messages to stdout.
+	pub dup_to_stdout: bool,
+}
+
+impl<T> EventFormat<T>
+where
+	T: FormatTime,
+{
+	// NOTE: the following code took inspiration from tracing-subscriber
+	//
+	//       https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/format/mod.rs#L449
+	pub(crate) fn format_event_custom<'b, 'w, S, N>(
+		&self,
+		ctx: &FmtContext<'b, S, N>,
+		mut writer: format::Writer<'w>,
+		event: &Event,
+	) -> fmt::Result
+	where
+		S: Subscriber + for<'a> LookupSpan<'a>,
+		N: for<'a> FormatFields<'a> + 'static,
+	{
+		let normalized_meta = event.normalized_metadata();
+		let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata());
+		time::write(&self.timer, &mut format::Writer::new(&mut writer))?;
+
+		if self.display_level {
+			let fmt_level = FmtLevel::new(meta.level());
+			write!(writer, "{} ", fmt_level)?;
+		}
+
+		if self.display_thread_name {
+			let current_thread = std::thread::current();
+			match current_thread.name() {
+				Some(name) => {
+					write!(&mut writer, "{} ", FmtThreadName::new(name))?;
+				},
+				// fall-back to thread id when name is absent and ids are not enabled
+				None => {
+					write!(&mut writer, "{:0>2?} ", current_thread.id())?;
+				},
+			}
+		}
+
+		if self.display_target {
+			write!(&mut writer, "{}: ", meta.target())?;
+		}
+
+		// Custom code to display node name
+		if let Some(span) = ctx.lookup_current() {
+			for span in span.scope() {
+				let exts = span.extensions();
+				if let Some(prefix) = exts.get::<super::layers::Prefix>() {
+					write!(&mut writer, "{}", prefix.as_str())?;
+					break;
+				}
+			}
+		}
+
+		ctx.format_fields(format::Writer::new(&mut writer), event)?;
+		writeln!(&mut writer)?;
+
+		Ok(())
+	}
+}
+
+// NOTE: the following code took inspiration from tracing-subscriber
+//
+//       https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/format/mod.rs#L449
+impl<S, N, T> FormatEvent<S, N> for EventFormat<T>
+where
+	S: Subscriber + for<'a> LookupSpan<'a>,
+	N: for<'a> FormatFields<'a> + 'static,
+	T: FormatTime,
+{
+	fn format_event(
+		&self,
+		ctx: &FmtContext<S, N>,
+		mut writer: format::Writer<'_>,
+		event: &Event,
+	) -> fmt::Result {
+		if self.dup_to_stdout &&
+			(event.metadata().level() == &Level::INFO ||
+				event.metadata().level() == &Level::WARN ||
+				event.metadata().level() == &Level::ERROR)
+		{
+			let mut out = String::new();
+			let buf_writer = format::Writer::new(&mut out);
+			self.format_event_custom(ctx, buf_writer, event)?;
+			writer.write_str(&out)?;
+			print!("{}", out);
+			Ok(())
+		} else {
+			self.format_event_custom(ctx, writer, event)
+		}
+	}
+}
+
+struct FmtLevel<'a> {
+	level: &'a Level,
+}
+
+impl<'a> FmtLevel<'a> {
+	pub(crate) fn new(level: &'a Level) -> Self {
+		Self { level }
+	}
+}
+
+const TRACE_STR: &str = "TRACE";
+const DEBUG_STR: &str = "DEBUG";
+const INFO_STR: &str = " INFO";
+const WARN_STR: &str = " WARN";
+const ERROR_STR: &str = "ERROR";
+
+impl<'a> fmt::Display for FmtLevel<'a> {
+	fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+		match *self.level {
+			Level::TRACE => write!(f, "{}", style(TRACE_STR).magenta()),
+			Level::DEBUG => write!(f, "{}", style(DEBUG_STR).blue()),
+			Level::INFO => write!(f, "{}", style(INFO_STR).green()),
+			Level::WARN => write!(f, "{}", style(WARN_STR).yellow()),
+			Level::ERROR => write!(f, "{}", style(ERROR_STR).red()),
+		}
+	}
+}
+
+struct FmtThreadName<'a> {
+	name: &'a str,
+}
+
+impl<'a> FmtThreadName<'a> {
+	pub(crate) fn new(name: &'a str) -> Self {
+		Self { name }
+	}
+}
+
+// NOTE: the following code has been duplicated from tracing-subscriber
+//
+//       https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/format/mod.rs#L845
+impl<'a> fmt::Display for FmtThreadName<'a> {
+	fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+		use std::sync::atomic::{
+			AtomicUsize,
+			Ordering::{AcqRel, Acquire, Relaxed},
+		};
+
+		// Track the longest thread name length we've seen so far in an atomic,
+		// so that it can be updated by any thread.
+		static MAX_LEN: AtomicUsize = AtomicUsize::new(0);
+		let len = self.name.len();
+		// Snapshot the current max thread name length.
+		let mut max_len = MAX_LEN.load(Relaxed);
+
+		while len > max_len {
+			// Try to set a new max length, if it is still the value we took a
+			// snapshot of.
+			match MAX_LEN.compare_exchange(max_len, len, AcqRel, Acquire) {
+				// We successfully set the new max value
+				Ok(_) => break,
+				// Another thread set a new max value since we last observed
+				// it! It's possible that the new length is actually longer than
+				// ours, so we'll loop again and check whether our length is
+				// still the longest. If not, we'll just use the newer value.
+				Err(actual) => max_len = actual,
+			}
+		}
+
+		// pad thread name using `max_len`
+		write!(f, "{:>width$}", self.name, width = max_len)
+	}
+}
+
+// NOTE: the following code has been duplicated from tracing-subscriber
+//
+//       https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/time/mod.rs#L252
+mod time {
+	use std::fmt;
+	use tracing_subscriber::fmt::{format, time::FormatTime};
+
+	pub(crate) fn write<T>(timer: T, writer: &mut format::Writer<'_>) -> fmt::Result
+	where
+		T: FormatTime,
+	{
+		if console::colors_enabled() {
+			write!(writer, "\x1B[2m")?;
+			timer.format_time(writer)?;
+			write!(writer, "\x1B[0m")?;
+		} else {
+			timer.format_time(writer)?;
+		}
+
+		writer.write_char(' ')?;
+		Ok(())
+	}
+}

bizinikiwi/client/tracing/src/logging/fast_local_time.rs

@@ -0,0 +1,160 @@
+// This file is part of Bizinikiwi.
+
+// Copyright (C) Parity Technologies (UK) Ltd.
+// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0
+
+// This program is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+
+// This program is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+// GNU General Public License for more details.
+
+// You should have received a copy of the GNU General Public License
+// along with this program. If not, see <https://www.gnu.org/licenses/>.
+
+use chrono::{Datelike, Timelike};
+use std::{cell::RefCell, fmt::Write, time::SystemTime};
+use tracing_subscriber::fmt::{format, time::FormatTime};
+
+/// A structure which, when `Display`d, will print out the current local time.
+#[derive(Debug, Clone, Copy, Eq, PartialEq, Default)]
+pub struct FastLocalTime {
+	/// Decides whenever the fractional timestamp with be included in the output.
+	///
+	/// If `false` the output will match the following `chrono` format string:
+	///   `%Y-%m-%d %H:%M:%S`
+	///
+	/// If `true` the output will match the following `chrono` format string:
+	///   `%Y-%m-%d %H:%M:%S%.3f`
+	pub with_fractional: bool,
+}
+
+// This is deliberately slightly larger than we actually need, just in case.
+const TIMESTAMP_MAXIMUM_LENGTH: usize = 32;
+
+#[derive(Default)]
+struct InlineString {
+	buffer: [u8; TIMESTAMP_MAXIMUM_LENGTH],
+	length: usize,
+}
+
+impl Write for InlineString {
+	fn write_str(&mut self, s: &str) -> std::fmt::Result {
+		let new_length = self.length + s.len();
+		assert!(
+			new_length <= TIMESTAMP_MAXIMUM_LENGTH,
+			"buffer overflow when formatting the current timestamp"
+		);
+
+		self.buffer[self.length..new_length].copy_from_slice(s.as_bytes());
+		self.length = new_length;
+		Ok(())
+	}
+}
+
+impl InlineString {
+	fn as_str(&self) -> &str {
+		// SAFETY: this is safe since the only place we append to the buffer
+		//         is in `write_str` from an `&str`
+		unsafe { std::str::from_utf8_unchecked(&self.buffer[..self.length]) }
+	}
+}
+
+#[derive(Default)]
+struct CachedTimestamp {
+	buffer: InlineString,
+	last_regenerated_at: u64,
+	last_fractional: u32,
+}
+
+thread_local! {
+	static TIMESTAMP: RefCell<CachedTimestamp> = Default::default();
+}
+
+impl FormatTime for FastLocalTime {
+	fn format_time(&self, w: &mut format::Writer<'_>) -> std::fmt::Result {
+		const TIMESTAMP_PARTIAL_LENGTH: usize = "0000-00-00 00:00:00".len();
+
+		let elapsed = SystemTime::now()
+			.duration_since(SystemTime::UNIX_EPOCH)
+			.expect("system time is never before UNIX epoch; qed");
+		let unix_time = elapsed.as_secs();
+
+		TIMESTAMP.with(|cache| {
+			let mut cache = cache.borrow_mut();
+
+			// Regenerate the timestamp only at most once each second.
+			if cache.last_regenerated_at != unix_time {
+				let ts = chrono::Local::now();
+				let fractional = (ts.nanosecond() % 1_000_000_000) / 1_000_000;
+				cache.last_regenerated_at = unix_time;
+				cache.last_fractional = fractional;
+				cache.buffer.length = 0;
+
+				write!(
+					&mut cache.buffer,
+					"{:04}-{:02}-{:02} {:02}:{:02}:{:02}.{:03}",
+					ts.year(),
+					ts.month(),
+					ts.day(),
+					ts.hour(),
+					ts.minute(),
+					ts.second(),
+					fractional
+				)?;
+			} else if self.with_fractional {
+				let fractional = elapsed.subsec_millis();
+
+				// Regenerate the fractional part at most once each millisecond.
+				if cache.last_fractional != fractional {
+					cache.last_fractional = fractional;
+					cache.buffer.length = TIMESTAMP_PARTIAL_LENGTH + 1;
+					write!(&mut cache.buffer, "{:03}", fractional)?;
+				}
+			}
+
+			let mut slice = cache.buffer.as_str();
+			if !self.with_fractional {
+				slice = &slice[..TIMESTAMP_PARTIAL_LENGTH];
+			}
+
+			w.write_str(slice)
+		})
+	}
+}
+
+impl std::fmt::Display for FastLocalTime {
+	fn fmt(&self, mut w: &mut std::fmt::Formatter) -> std::fmt::Result {
+		self.format_time(&mut format::Writer::new(&mut w))
+	}
+}
+
+#[test]
+fn test_format_fast_local_time() {
+	assert_eq!(
+		chrono::Local::now().format("%Y-%m-%d %H:%M:%S").to_string().len(),
+		FastLocalTime { with_fractional: false }.to_string().len()
+	);
+	assert_eq!(
+		chrono::Local::now().format("%Y-%m-%d %H:%M:%S%.3f").to_string().len(),
+		FastLocalTime { with_fractional: true }.to_string().len()
+	);
+
+	// A simple trick to make sure this test won't randomly fail if we so happen
+	// to land on the exact moment when we tick over to the next second.
+	let now_1 = FastLocalTime { with_fractional: false }.to_string();
+	let expected = chrono::Local::now().format("%Y-%m-%d %H:%M:%S").to_string();
+	let now_2 = FastLocalTime { with_fractional: false }.to_string();
+
+	assert!(
+		now_1 == expected || now_2 == expected,
+		"'{}' or '{}' should have been equal to '{}'",
+		now_1,
+		now_2,
+		expected
+	);
+}

bizinikiwi/client/tracing/src/logging/layers/mod.rs

@@ -0,0 +1,21 @@
+// This file is part of Bizinikiwi.
+
+// Copyright (C) Parity Technologies (UK) Ltd.
+// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0
+
+// This program is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+
+// This program is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+// GNU General Public License for more details.
+
+// You should have received a copy of the GNU General Public License
+// along with this program. If not, see <https://www.gnu.org/licenses/>.
+
+mod prefix_layer;
+
+pub use prefix_layer::*;

bizinikiwi/client/tracing/src/logging/layers/prefix_layer.rs

@@ -0,0 +1,95 @@
+// This file is part of Bizinikiwi.
+
+// Copyright (C) Parity Technologies (UK) Ltd.
+// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0
+
+// This program is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+
+// This program is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+// GNU General Public License for more details.
+
+// You should have received a copy of the GNU General Public License
+// along with this program. If not, see <https://www.gnu.org/licenses/>.
+
+use tracing::{span::Attributes, Id, Subscriber};
+use tracing_subscriber::{layer::Context, registry::LookupSpan, Layer};
+
+/// Span name used for the logging prefix. See macro `pezsc_tracing::logging::prefix_logs_with!`
+pub const PREFIX_LOG_SPAN: &str = "bizinikiwi-log-prefix";
+
+/// A `Layer` that captures the prefix span ([`PREFIX_LOG_SPAN`]) which is then used by
+/// [`crate::logging::EventFormat`] to prefix the log lines by customizable string.
+///
+/// See the macro `pezsc_cli::prefix_logs_with!` for more details.
+pub struct PrefixLayer;
+
+impl<S> Layer<S> for PrefixLayer
+where
+	S: Subscriber + for<'a> LookupSpan<'a>,
+{
+	fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) {
+		let span = match ctx.span(id) {
+			Some(span) => span,
+			None => {
+				// this shouldn't happen!
+				debug_assert!(
+					false,
+					"newly created span with ID {:?} did not exist in the registry; this is a bug!",
+					id
+				);
+				return;
+			},
+		};
+
+		if span.name() != PREFIX_LOG_SPAN {
+			return;
+		}
+
+		let mut extensions = span.extensions_mut();
+
+		if extensions.get_mut::<Prefix>().is_none() {
+			let mut s = String::new();
+			let mut v = PrefixVisitor(&mut s);
+			attrs.record(&mut v);
+
+			if !s.is_empty() {
+				let fmt_fields = Prefix(s);
+				extensions.insert(fmt_fields);
+			}
+		}
+	}
+}
+
+struct PrefixVisitor<'a, W: std::fmt::Write>(&'a mut W);
+
+macro_rules! write_node_name {
+	($method:ident, $type:ty, $format:expr) => {
+		fn $method(&mut self, field: &tracing::field::Field, value: $type) {
+			if field.name() == "name" {
+				let _ = write!(self.0, $format, value);
+			}
+		}
+	};
+}
+
+impl<'a, W: std::fmt::Write> tracing::field::Visit for PrefixVisitor<'a, W> {
+	write_node_name!(record_debug, &dyn std::fmt::Debug, "[{:?}] ");
+	write_node_name!(record_str, &str, "[{}] ");
+	write_node_name!(record_i64, i64, "[{}] ");
+	write_node_name!(record_u64, u64, "[{}] ");
+	write_node_name!(record_bool, bool, "[{}] ");
+}
+
+#[derive(Debug)]
+pub(crate) struct Prefix(String);
+
+impl Prefix {
+	pub(crate) fn as_str(&self) -> &str {
+		self.0.as_str()
+	}
+}

bizinikiwi/client/tracing/src/logging/mod.rs

@@ -0,0 +1,664 @@
+// This file is part of Bizinikiwi.
+
+// Copyright (C) Parity Technologies (UK) Ltd.
+// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0
+
+// This program is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+
+// This program is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+// GNU General Public License for more details.
+
+// You should have received a copy of the GNU General Public License
+// along with this program. If not, see <https://www.gnu.org/licenses/>.
+
+//! Bizinikiwi logging library.
+//!
+//! This crate uses tokio's [tracing](https://github.com/tokio-rs/tracing/) library for logging.
+
+#![warn(missing_docs)]
+
+mod directives;
+mod event_format;
+mod fast_local_time;
+mod layers;
+mod stderr_writer;
+
+pub(crate) type DefaultLogger = stderr_writer::MakeStderrWriter;
+
+pub use directives::*;
+pub use pezsc_tracing_proc_macro::*;
+
+use is_terminal::IsTerminal;
+use std::io;
+use tracing::Subscriber;
+use tracing_subscriber::{
+	filter::LevelFilter,
+	fmt::{
+		format, FormatEvent, FormatFields, Formatter, Layer as FmtLayer, MakeWriter,
+		SubscriberBuilder,
+	},
+	layer::{self, SubscriberExt},
+	registry::LookupSpan,
+	EnvFilter, FmtSubscriber, Layer, Registry,
+};
+
+pub use event_format::*;
+pub use fast_local_time::FastLocalTime;
+pub use layers::*;
+
+use stderr_writer::MakeStderrWriter;
+
+/// Logging Result typedef.
+pub type Result<T> = std::result::Result<T, Error>;
+
+/// Logging errors.
+#[derive(Debug, thiserror::Error)]
+#[allow(missing_docs)]
+#[non_exhaustive]
+#[error(transparent)]
+pub enum Error {
+	IoError(#[from] io::Error),
+	SetGlobalDefaultError(#[from] tracing::subscriber::SetGlobalDefaultError),
+	DirectiveParseError(#[from] tracing_subscriber::filter::ParseError),
+	SetLoggerError(#[from] tracing_log::log_tracer::SetLoggerError),
+}
+
+macro_rules! enable_log_reloading {
+	($builder:expr) => {{
+		let builder = $builder.with_filter_reloading();
+		let handle = builder.reload_handle();
+		set_reload_handle(handle);
+		builder
+	}};
+}
+
+/// Convert a `Option<LevelFilter>` to a [`log::LevelFilter`].
+///
+/// `None` is interpreted as `Info`.
+fn to_log_level_filter(level_filter: Option<LevelFilter>) -> log::LevelFilter {
+	match level_filter {
+		Some(LevelFilter::INFO) | None => log::LevelFilter::Info,
+		Some(LevelFilter::TRACE) => log::LevelFilter::Trace,
+		Some(LevelFilter::WARN) => log::LevelFilter::Warn,
+		Some(LevelFilter::ERROR) => log::LevelFilter::Error,
+		Some(LevelFilter::DEBUG) => log::LevelFilter::Debug,
+		Some(LevelFilter::OFF) => log::LevelFilter::Off,
+	}
+}
+
+/// Common implementation to get the subscriber.
+fn prepare_subscriber<N, E, F, W>(
+	directives: &str,
+	profiling_targets: Option<&str>,
+	force_colors: Option<bool>,
+	detailed_output: bool,
+	builder_hook: impl Fn(
+		SubscriberBuilder<format::DefaultFields, EventFormat, EnvFilter, DefaultLogger>,
+	) -> SubscriberBuilder<N, E, F, W>,
+) -> Result<impl Subscriber + for<'a> LookupSpan<'a>>
+where
+	N: for<'writer> FormatFields<'writer> + 'static,
+	E: FormatEvent<Registry, N> + 'static,
+	W: for<'writer> MakeWriter<'writer> + 'static,
+	F: layer::Layer<Formatter<N, E, W>> + Send + Sync + 'static,
+	FmtLayer<Registry, N, E, W>: layer::Layer<Registry> + Send + Sync + 'static,
+{
+	// Accept all valid directives and print invalid ones
+	fn parse_user_directives(mut env_filter: EnvFilter, dirs: &str) -> Result<EnvFilter> {
+		for dir in dirs.split(',') {
+			env_filter = env_filter.add_directive(parse_default_directive(dir)?);
+		}
+		Ok(env_filter)
+	}
+
+	// Initialize filter - ensure to use `parse_default_directive` for any defaults to persist
+	// after log filter reloading by RPC
+	let mut env_filter = EnvFilter::default()
+		// Enable info
+		.add_directive(parse_default_directive("info").expect("provided directive is valid"))
+		// Disable info logging by default for some modules.
+		.add_directive(parse_default_directive("ws=off").expect("provided directive is valid"))
+		.add_directive(parse_default_directive("yamux=off").expect("provided directive is valid"))
+		.add_directive(
+			parse_default_directive("regalloc=off").expect("provided directive is valid"),
+		)
+		.add_directive(
+			parse_default_directive("cranelift_codegen=off").expect("provided directive is valid"),
+		)
+		// Set warn logging by default for some modules.
+		.add_directive(
+			parse_default_directive("cranelift_wasm=warn").expect("provided directive is valid"),
+		)
+		.add_directive(parse_default_directive("hyper=warn").expect("provided directive is valid"))
+		.add_directive(
+			parse_default_directive("trust_dns_proto=off").expect("provided directive is valid"),
+		)
+		.add_directive(
+			parse_default_directive("hickory_proto=off").expect("provided directive is valid"),
+		)
+		.add_directive(
+			parse_default_directive("libp2p_mdns::behaviour::iface=off")
+				.expect("provided directive is valid"),
+		)
+		// Disable annoying log messages from rustls
+		.add_directive(
+			parse_default_directive("rustls::common_state=off")
+				.expect("provided directive is valid"),
+		)
+		.add_directive(
+			parse_default_directive("rustls::conn=off").expect("provided directive is valid"),
+		);
+
+	if let Ok(lvl) = std::env::var("RUST_LOG") {
+		if lvl != "" {
+			env_filter = parse_user_directives(env_filter, &lvl)?;
+		}
+	}
+
+	if directives != "" {
+		env_filter = parse_user_directives(env_filter, directives)?;
+	}
+
+	if let Some(profiling_targets) = profiling_targets {
+		env_filter = parse_user_directives(env_filter, profiling_targets)?;
+		env_filter = env_filter.add_directive(
+			parse_default_directive("pezsc_tracing=trace").expect("provided directive is valid"),
+		);
+	}
+
+	let max_level_hint = Layer::<FmtSubscriber>::max_level_hint(&env_filter);
+	let max_level = to_log_level_filter(max_level_hint);
+
+	tracing_log::LogTracer::builder()
+		.with_interest_cache(tracing_log::InterestCacheConfig::default())
+		.with_max_level(max_level)
+		.init()?;
+
+	// If we're only logging `INFO` entries then we'll use a simplified logging format.
+	let detailed_output = match max_level_hint {
+		Some(level) if level <= tracing_subscriber::filter::LevelFilter::INFO => false,
+		_ => true,
+	} || detailed_output;
+
+	let enable_color = force_colors.unwrap_or_else(|| io::stderr().is_terminal());
+	let timer = fast_local_time::FastLocalTime { with_fractional: detailed_output };
+
+	// We need to set both together, because we are may printing to `stdout` and `stderr`.
+	console::set_colors_enabled(enable_color);
+	console::set_colors_enabled_stderr(enable_color);
+
+	let event_format = EventFormat {
+		timer,
+		display_target: detailed_output,
+		display_level: detailed_output,
+		display_thread_name: detailed_output,
+		dup_to_stdout: !io::stderr().is_terminal() && io::stdout().is_terminal(),
+	};
+	let builder = FmtSubscriber::builder().with_env_filter(env_filter);
+
+	let builder = builder.with_span_events(format::FmtSpan::NONE);
+
+	let builder = builder.with_writer(MakeStderrWriter::default());
+
+	let builder = builder.event_format(event_format);
+
+	let builder = builder_hook(builder);
+
+	let subscriber = builder.finish().with(PrefixLayer);
+
+	Ok(subscriber)
+}
+
+/// A builder that is used to initialize the global logger.
+pub struct LoggerBuilder {
+	directives: String,
+	profiling: Option<(crate::TracingReceiver, String)>,
+	custom_profiler: Option<Box<dyn crate::TraceHandler>>,
+	log_reloading: bool,
+	force_colors: Option<bool>,
+	detailed_output: bool,
+}
+
+impl LoggerBuilder {
+	/// Create a new [`LoggerBuilder`] which can be used to initialize the global logger.
+	pub fn new<S: Into<String>>(directives: S) -> Self {
+		Self {
+			directives: directives.into(),
+			profiling: None,
+			custom_profiler: None,
+			log_reloading: false,
+			force_colors: None,
+			detailed_output: false,
+		}
+	}
+
+	/// Set up the profiling.
+	pub fn with_profiling<S: Into<String>>(
+		&mut self,
+		tracing_receiver: crate::TracingReceiver,
+		profiling_targets: S,
+	) -> &mut Self {
+		self.profiling = Some((tracing_receiver, profiling_targets.into()));
+		self
+	}
+
+	/// Add a custom profiler.
+	pub fn with_custom_profiling(
+		&mut self,
+		custom_profiler: Box<dyn crate::TraceHandler>,
+	) -> &mut Self {
+		self.custom_profiler = Some(custom_profiler);
+		self
+	}
+
+	/// Wether or not to disable log reloading.
+	pub fn with_log_reloading(&mut self, enabled: bool) -> &mut Self {
+		self.log_reloading = enabled;
+		self
+	}
+
+	/// Whether detailed log output should be enabled.
+	///
+	/// This includes showing the log target, log level and thread name.
+	///
+	/// This will be automatically enabled when there is a log level enabled that is higher than
+	/// `info`.
+	pub fn with_detailed_output(&mut self, detailed: bool) -> &mut Self {
+		self.detailed_output = detailed;
+		self
+	}
+
+	/// Force enable/disable colors.
+	pub fn with_colors(&mut self, enable: bool) -> &mut Self {
+		self.force_colors = Some(enable);
+		self
+	}
+
+	/// Initialize the global logger
+	///
+	/// This sets various global logging and tracing instances and thus may only be called once.
+	pub fn init(self) -> Result<()> {
+		if let Some((tracing_receiver, profiling_targets)) = self.profiling {
+			if self.log_reloading {
+				let subscriber = prepare_subscriber(
+					&self.directives,
+					Some(&profiling_targets),
+					self.force_colors,
+					self.detailed_output,
+					|builder| enable_log_reloading!(builder),
+				)?;
+				let mut profiling =
+					crate::ProfilingLayer::new(tracing_receiver, &profiling_targets);
+
+				self.custom_profiler
+					.into_iter()
+					.for_each(|profiler| profiling.add_handler(profiler));
+
+				tracing::subscriber::set_global_default(subscriber.with(profiling))?;
+
+				Ok(())
+			} else {
+				let subscriber = prepare_subscriber(
+					&self.directives,
+					Some(&profiling_targets),
+					self.force_colors,
+					self.detailed_output,
+					|builder| builder,
+				)?;
+				let mut profiling =
+					crate::ProfilingLayer::new(tracing_receiver, &profiling_targets);
+
+				self.custom_profiler
+					.into_iter()
+					.for_each(|profiler| profiling.add_handler(profiler));
+
+				tracing::subscriber::set_global_default(subscriber.with(profiling))?;
+
+				Ok(())
+			}
+		} else if self.log_reloading {
+			let subscriber = prepare_subscriber(
+				&self.directives,
+				None,
+				self.force_colors,
+				self.detailed_output,
+				|builder| enable_log_reloading!(builder),
+			)?;
+
+			tracing::subscriber::set_global_default(subscriber)?;
+
+			Ok(())
+		} else {
+			let subscriber = prepare_subscriber(
+				&self.directives,
+				None,
+				self.force_colors,
+				self.detailed_output,
+				|builder| builder,
+			)?;
+
+			tracing::subscriber::set_global_default(subscriber)?;
+
+			Ok(())
+		}
+	}
+}
+
+#[cfg(test)]
+mod tests {
+	use super::*;
+	use crate as pezsc_tracing;
+	use log::info;
+	use std::{
+		collections::BTreeMap,
+		env,
+		process::Command,
+		sync::{
+			atomic::{AtomicBool, AtomicUsize, Ordering},
+			Arc,
+		},
+	};
+	use tracing::{metadata::Kind, subscriber::Interest, Callsite, Level, Metadata};
+
+	const EXPECTED_LOG_MESSAGE: &'static str = "yeah logging works as expected";
+	const EXPECTED_NODE_NAME: &'static str = "THE_NODE";
+
+	fn init_logger(directives: &str) {
+		let _ = LoggerBuilder::new(directives).init().unwrap();
+	}
+
+	fn run_test_in_another_process(
+		test_name: &str,
+		test_body: impl FnOnce(),
+	) -> Option<std::process::Output> {
+		if env::var("RUN_FORKED_TEST").is_ok() {
+			test_body();
+			None
+		} else {
+			let output = Command::new(env::current_exe().unwrap())
+				.arg(test_name)
+				.env("RUN_FORKED_TEST", "1")
+				.output()
+				.unwrap();
+
+			assert!(output.status.success());
+			Some(output)
+		}
+	}
+
+	#[test]
+	fn test_logger_filters() {
+		run_test_in_another_process("test_logger_filters", || {
+			let test_directives =
+				"grandpa=debug,sync=trace,client=warn,telemetry,something-with-dash=error";
+			init_logger(&test_directives);
+
+			tracing::dispatcher::get_default(|dispatcher| {
+				let test_filter = |target, level| {
+					struct DummyCallSite;
+					impl Callsite for DummyCallSite {
+						fn set_interest(&self, _: Interest) {}
+						fn metadata(&self) -> &Metadata<'_> {
+							unreachable!();
+						}
+					}
+
+					let metadata = tracing::metadata!(
+						name: "",
+						target: target,
+						level: level,
+						fields: &[],
+						callsite: &DummyCallSite,
+						kind: Kind::SPAN,
+					);
+
+					dispatcher.enabled(&metadata)
+				};
+
+				assert!(test_filter("grandpa", Level::INFO));
+				assert!(test_filter("grandpa", Level::DEBUG));
+				assert!(!test_filter("grandpa", Level::TRACE));
+
+				assert!(test_filter("sync", Level::TRACE));
+				assert!(test_filter("client", Level::WARN));
+
+				assert!(test_filter("telemetry", Level::TRACE));
+				assert!(test_filter("something-with-dash", Level::ERROR));
+			});
+		});
+	}
+
+	/// This test ensures that using dash (`-`) in the target name in logs and directives actually
+	/// work.
+	#[test]
+	fn dash_in_target_name_works() {
+		let executable = env::current_exe().unwrap();
+		let output = Command::new(executable)
+			.env("ENABLE_LOGGING", "1")
+			.args(&["--nocapture", "log_something_with_dash_target_name"])
+			.output()
+			.unwrap();
+
+		let output = String::from_utf8(output.stderr).unwrap();
+		assert!(output.contains(EXPECTED_LOG_MESSAGE));
+	}
+
+	/// This is not an actual test, it is used by the `dash_in_target_name_works` test.
+	/// The given test will call the test executable and only execute this one test that
+	/// only prints `EXPECTED_LOG_MESSAGE` through logging while using a target
+	/// name that contains a dash. This ensures that target names with dashes work.
+	#[test]
+	fn log_something_with_dash_target_name() {
+		if env::var("ENABLE_LOGGING").is_ok() {
+			let test_directives = "test-target=info";
+			let _guard = init_logger(&test_directives);
+
+			log::info!(target: "test-target", "{}", EXPECTED_LOG_MESSAGE);
+		}
+	}
+
+	#[test]
+	fn prefix_in_log_lines() {
+		let re = regex::Regex::new(&format!(
+			r"^\d{{4}}-\d{{2}}-\d{{2}} \d{{2}}:\d{{2}}:\d{{2}} \[{}\] {}$",
+			EXPECTED_NODE_NAME, EXPECTED_LOG_MESSAGE,
+		))
+		.unwrap();
+		let executable = env::current_exe().unwrap();
+		let output = Command::new(executable)
+			.env("ENABLE_LOGGING", "1")
+			.args(&["--nocapture", "prefix_in_log_lines_entrypoint"])
+			.output()
+			.unwrap();
+
+		let output = String::from_utf8(output.stderr).unwrap();
+		assert!(re.is_match(output.trim()), "Expected:\n{}\nGot:\n{}", re, output);
+	}
+
+	/// This is not an actual test, it is used by the `prefix_in_log_lines` test.
+	/// The given test will call the test executable and only execute this one test that
+	/// only prints a log line prefixed by the node name `EXPECTED_NODE_NAME`.
+	#[test]
+	fn prefix_in_log_lines_entrypoint() {
+		if env::var("ENABLE_LOGGING").is_ok() {
+			let _guard = init_logger("");
+			prefix_in_log_lines_process();
+		}
+	}
+
+	#[crate::logging::prefix_logs_with(EXPECTED_NODE_NAME)]
+	fn prefix_in_log_lines_process() {
+		log::info!("{}", EXPECTED_LOG_MESSAGE);
+	}
+
+	/// This is not an actual test, it is used by the `do_not_write_with_colors_on_tty` test.
+	/// The given test will call the test executable and only execute this one test that
+	/// only prints a log line with some colors in it.
+	#[test]
+	fn do_not_write_with_colors_on_tty_entrypoint() {
+		if env::var("ENABLE_LOGGING").is_ok() {
+			let _guard = init_logger("");
+			log::info!("{}", console::style(EXPECTED_LOG_MESSAGE).yellow());
+		}
+	}
+
+	#[test]
+	fn do_not_write_with_colors_on_tty() {
+		let re = regex::Regex::new(&format!(
+			r"^\d{{4}}-\d{{2}}-\d{{2}} \d{{2}}:\d{{2}}:\d{{2}} {}$",
+			EXPECTED_LOG_MESSAGE,
+		))
+		.unwrap();
+		let executable = env::current_exe().unwrap();
+		let output = Command::new(executable)
+			.env("ENABLE_LOGGING", "1")
+			.args(&["--nocapture", "do_not_write_with_colors_on_tty_entrypoint"])
+			.output()
+			.unwrap();
+
+		let output = String::from_utf8(output.stderr).unwrap();
+		assert!(re.is_match(output.trim()), "Expected:\n{}\nGot:\n{}", re, output);
+	}
+
+	#[test]
+	fn log_max_level_is_set_properly() {
+		fn run_test(rust_log: Option<String>, tracing_targets: Option<String>) -> String {
+			let executable = env::current_exe().unwrap();
+			let mut command = Command::new(executable);
+
+			command
+				.env("PRINT_MAX_LOG_LEVEL", "1")
+				.args(&["--nocapture", "log_max_level_is_set_properly"]);
+
+			if let Some(rust_log) = rust_log {
+				command.env("RUST_LOG", rust_log);
+			}
+
+			if let Some(tracing_targets) = tracing_targets {
+				command.env("TRACING_TARGETS", tracing_targets);
+			}
+
+			let output = command.output().unwrap();
+
+			dbg!(String::from_utf8(output.stderr)).unwrap()
+		}
+
+		if env::var("PRINT_MAX_LOG_LEVEL").is_ok() {
+			let mut builder = LoggerBuilder::new("");
+
+			if let Ok(targets) = env::var("TRACING_TARGETS") {
+				builder.with_profiling(crate::TracingReceiver::Log, targets);
+			}
+
+			builder.init().unwrap();
+
+			eprint!("MAX_LOG_LEVEL={:?}", log::max_level());
+		} else {
+			assert_eq!("MAX_LOG_LEVEL=Info", run_test(None, None));
+			assert_eq!("MAX_LOG_LEVEL=Trace", run_test(Some("test=trace".into()), None));
+			assert_eq!("MAX_LOG_LEVEL=Debug", run_test(Some("test=debug".into()), None));
+			assert_eq!("MAX_LOG_LEVEL=Trace", run_test(None, Some("test=info".into())));
+		}
+	}
+
+	// This creates a bunch of threads and makes sure they start executing
+	// a given callback almost exactly at the same time.
+	fn run_on_many_threads(thread_count: usize, callback: impl Fn(usize) + 'static + Send + Clone) {
+		let started_count = Arc::new(AtomicUsize::new(0));
+		let barrier = Arc::new(AtomicBool::new(false));
+		let threads: Vec<_> = (0..thread_count)
+			.map(|nth_thread| {
+				let started_count = started_count.clone();
+				let barrier = barrier.clone();
+				let callback = callback.clone();
+
+				std::thread::spawn(move || {
+					started_count.fetch_add(1, Ordering::SeqCst);
+					while !barrier.load(Ordering::SeqCst) {
+						std::thread::yield_now();
+					}
+
+					callback(nth_thread);
+				})
+			})
+			.collect();
+
+		while started_count.load(Ordering::SeqCst) != thread_count {
+			std::thread::yield_now();
+		}
+		barrier.store(true, Ordering::SeqCst);
+
+		for thread in threads {
+			if let Err(error) = thread.join() {
+				println!("error: failed to join thread: {:?}", error);
+				unsafe { libc::abort() }
+			}
+		}
+	}
+
+	#[test]
+	fn parallel_logs_from_multiple_threads_are_properly_gathered() {
+		const THREAD_COUNT: usize = 128;
+		const LOGS_PER_THREAD: usize = 1024;
+
+		let output = run_test_in_another_process(
+			"parallel_logs_from_multiple_threads_are_properly_gathered",
+			|| {
+				let builder = LoggerBuilder::new("");
+				builder.init().unwrap();
+
+				run_on_many_threads(THREAD_COUNT, |nth_thread| {
+					for _ in 0..LOGS_PER_THREAD {
+						info!("Thread <<{}>>", nth_thread);
+					}
+				});
+			},
+		);
+
+		if let Some(output) = output {
+			let stderr = String::from_utf8(output.stderr).unwrap();
+			let mut count_per_thread = BTreeMap::new();
+			for line in stderr.split("\n") {
+				if let Some(index_s) = line.find("Thread <<") {
+					let index_s = index_s + "Thread <<".len();
+					let index_e = line.find(">>").unwrap();
+					let nth_thread: usize = line[index_s..index_e].parse().unwrap();
+					*count_per_thread.entry(nth_thread).or_insert(0) += 1;
+				}
+			}
+
+			assert_eq!(count_per_thread.len(), THREAD_COUNT);
+			for (_, count) in count_per_thread {
+				assert_eq!(count, LOGS_PER_THREAD);
+			}
+		}
+	}
+
+	#[test]
+	fn huge_single_line_log_is_properly_printed_out() {
+		let mut line = String::new();
+		line.push_str("$$START$$");
+		for n in 0..16 * 1024 * 1024 {
+			let ch = b'a' + (n as u8 % (b'z' - b'a'));
+			line.push(char::from(ch));
+		}
+		line.push_str("$$END$$");
+
+		let output =
+			run_test_in_another_process("huge_single_line_log_is_properly_printed_out", || {
+				let builder = LoggerBuilder::new("");
+				builder.init().unwrap();
+				info!("{}", line);
+			});
+
+		if let Some(output) = output {
+			let stderr = String::from_utf8(output.stderr).unwrap();
+			assert!(stderr.contains(&line));
+		}
+	}
+}

bizinikiwi/client/tracing/src/logging/stderr_writer.rs

@@ -0,0 +1,228 @@
+// This file is part of Bizinikiwi.
+
+// Copyright (C) Parity Technologies (UK) Ltd.
+// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0
+
+// This program is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+
+// This program is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+// GNU General Public License for more details.
+
+// You should have received a copy of the GNU General Public License
+// along with this program. If not, see <https://www.gnu.org/licenses/>.
+
+//! This module contains a buffered semi-asynchronous stderr writer.
+//!
+//! Depending on how we were started writing to stderr can take a surprisingly long time.
+//!
+//! If the other side takes their sweet sweet time reading whatever we send them then writing
+//! to stderr might block for a long time, since it is effectively a synchronous operation.
+//! And every time we write to stderr we need to grab a global lock, which affects every thread
+//! which also tries to log something at the same time.
+//!
+//! Of course we *will* be ultimately limited by how fast the recipient can ingest our logs,
+//! but it's not like logging is the only thing we're doing. And we still can't entirely
+//! avoid the problem of multiple threads contending for the same lock. (Well, technically
+//! we could employ something like a lock-free circular buffer, but that might be like
+//! killing a fly with a sledgehammer considering the complexity involved; this is only
+//! a logger after all.)
+//!
+//! But we can try to make things a little better. We can offload actually writing to stderr
+//! to another thread and flush the logs in bulk instead of doing it per-line, which should
+//! reduce the amount of CPU time we waste on making syscalls and on spinning waiting for locks.
+//!
+//! How much this helps depends on a multitude of factors, including the hardware we're running on,
+//! how much we're logging, from how many threads, which exact set of threads are logging, to what
+//! stderr is actually connected to (is it a terminal emulator? a file? an UDP socket?), etc.
+//!
+//! In general this can reduce the real time execution time as much as 75% in certain cases, or it
+//! can make absolutely no difference in others.
+
+use parking_lot::{Condvar, Mutex, Once};
+use std::{
+	io::Write,
+	sync::atomic::{AtomicBool, Ordering},
+	time::Duration,
+};
+use tracing::{Level, Metadata};
+
+/// How many bytes of buffered logs will trigger an async flush on another thread?
+const ASYNC_FLUSH_THRESHOLD: usize = 16 * 1024;
+
+/// How many bytes of buffered logs will trigger a sync flush on the current thread?
+const SYNC_FLUSH_THRESHOLD: usize = 768 * 1024;
+
+/// How many bytes can be buffered at maximum?
+const EMERGENCY_FLUSH_THRESHOLD: usize = 2 * 1024 * 1024;
+
+/// If there isn't enough printed out this is how often the logs will be automatically flushed.
+const AUTOFLUSH_EVERY: Duration = Duration::from_millis(50);
+
+/// The least serious level at which a synchronous flush will be triggered.
+const SYNC_FLUSH_LEVEL_THRESHOLD: Level = Level::ERROR;
+
+/// The amount of time we'll block until the buffer is fully flushed on exit.
+///
+/// This should be completely unnecessary in normal circumstances.
+const ON_EXIT_FLUSH_TIMEOUT: Duration = Duration::from_secs(5);
+
+/// A global buffer to which we'll append all of our logs before flushing them out to stderr.
+static BUFFER: Mutex<Vec<u8>> = parking_lot::const_mutex(Vec::new());
+
+/// A spare buffer which we'll swap with the main buffer on each flush to minimize lock contention.
+static SPARE_BUFFER: Mutex<Vec<u8>> = parking_lot::const_mutex(Vec::new());
+
+/// A conditional variable used to forcefully trigger asynchronous flushes.
+static ASYNC_FLUSH_CONDVAR: Condvar = Condvar::new();
+
+static ENABLE_ASYNC_LOGGING: AtomicBool = AtomicBool::new(true);
+
+fn flush_logs(mut buffer: parking_lot::lock_api::MutexGuard<parking_lot::RawMutex, Vec<u8>>) {
+	let mut spare_buffer = SPARE_BUFFER.lock();
+	std::mem::swap(&mut *spare_buffer, &mut *buffer);
+	std::mem::drop(buffer);
+
+	let stderr = std::io::stderr();
+	let mut stderr_lock = stderr.lock();
+	let _ = stderr_lock.write_all(&spare_buffer);
+	std::mem::drop(stderr_lock);
+
+	spare_buffer.clear();
+}
+
+fn log_autoflush_thread() {
+	let mut buffer = BUFFER.lock();
+	loop {
+		ASYNC_FLUSH_CONDVAR.wait_for(&mut buffer, AUTOFLUSH_EVERY);
+		loop {
+			flush_logs(buffer);
+
+			buffer = BUFFER.lock();
+			if buffer.len() >= ASYNC_FLUSH_THRESHOLD {
+				// While we were busy flushing we picked up enough logs to do another flush.
+				continue;
+			} else {
+				break;
+			}
+		}
+	}
+}
+
+#[cold]
+fn initialize() {
+	std::thread::Builder::new()
+		.name("log-autoflush".to_owned())
+		.spawn(log_autoflush_thread)
+		.expect("thread spawning doesn't normally fail; qed");
+
+	// SAFETY: This is safe since we pass a valid pointer to `atexit`.
+	let errcode = unsafe { libc::atexit(on_exit) };
+	assert_eq!(errcode, 0, "atexit failed while setting up the logger: {}", errcode);
+}
+
+extern "C" fn on_exit() {
+	ENABLE_ASYNC_LOGGING.store(false, Ordering::SeqCst);
+
+	if let Some(buffer) = BUFFER.try_lock_for(ON_EXIT_FLUSH_TIMEOUT) {
+		flush_logs(buffer);
+	}
+}
+
+/// A drop-in replacement for [`std::io::stderr`] for use anywhere
+/// a [`tracing_subscriber::fmt::MakeWriter`] is accepted.
+pub struct MakeStderrWriter {
+	// A dummy field so that the structure is not publicly constructible.
+	_dummy: (),
+}
+
+impl Default for MakeStderrWriter {
+	fn default() -> Self {
+		static ONCE: Once = Once::new();
+		ONCE.call_once(initialize);
+		MakeStderrWriter { _dummy: () }
+	}
+}
+
+impl tracing_subscriber::fmt::MakeWriter<'_> for MakeStderrWriter {
+	type Writer = StderrWriter;
+
+	fn make_writer(&self) -> Self::Writer {
+		StderrWriter::new(false)
+	}
+
+	// The `tracing-subscriber` crate calls this for every line logged.
+	fn make_writer_for(&self, meta: &Metadata<'_>) -> Self::Writer {
+		StderrWriter::new(*meta.level() <= SYNC_FLUSH_LEVEL_THRESHOLD)
+	}
+}
+
+pub struct StderrWriter {
+	buffer: Option<parking_lot::lock_api::MutexGuard<'static, parking_lot::RawMutex, Vec<u8>>>,
+	sync_flush_on_drop: bool,
+	original_len: usize,
+}
+
+impl StderrWriter {
+	fn new(mut sync_flush_on_drop: bool) -> Self {
+		if !ENABLE_ASYNC_LOGGING.load(Ordering::Relaxed) {
+			sync_flush_on_drop = true;
+		}
+
+		// This lock isn't as expensive as it might look, since this is only called once the full
+		// line to be logged is already serialized into a thread-local buffer inside of the
+		// `tracing-subscriber` crate, and basically the only thing we'll do when holding this lock
+		// is to copy that over to our global shared buffer in one go in `Write::write_all` and be
+		// immediately dropped.
+		let buffer = BUFFER.lock();
+		StderrWriter { original_len: buffer.len(), buffer: Some(buffer), sync_flush_on_drop }
+	}
+}
+
+#[cold]
+fn emergency_flush(buffer: &mut Vec<u8>, input: &[u8]) {
+	let stderr = std::io::stderr();
+	let mut stderr_lock = stderr.lock();
+	let _ = stderr_lock.write_all(buffer);
+	buffer.clear();
+
+	let _ = stderr_lock.write_all(input);
+}
+
+impl Write for StderrWriter {
+	fn write(&mut self, input: &[u8]) -> Result<usize, std::io::Error> {
+		let buffer = self.buffer.as_mut().expect("buffer is only None after `drop`; qed");
+		if buffer.len() + input.len() >= EMERGENCY_FLUSH_THRESHOLD {
+			// Make sure we don't blow our memory budget. Normally this should never happen,
+			// but there are cases where we directly print out untrusted user input which
+			// can potentially be megabytes in size.
+			emergency_flush(buffer, input);
+		} else {
+			buffer.extend_from_slice(input);
+		}
+		Ok(input.len())
+	}
+
+	fn write_all(&mut self, input: &[u8]) -> Result<(), std::io::Error> {
+		self.write(input).map(|_| ())
+	}
+
+	fn flush(&mut self) -> Result<(), std::io::Error> {
+		Ok(())
+	}
+}
+
+impl Drop for StderrWriter {
+	fn drop(&mut self) {
+		let buf = self.buffer.take().expect("buffer is only None after `drop`; qed");
+		if self.sync_flush_on_drop || buf.len() >= SYNC_FLUSH_THRESHOLD {
+			flush_logs(buf);
+		} else if self.original_len < ASYNC_FLUSH_THRESHOLD && buf.len() >= ASYNC_FLUSH_THRESHOLD {
+			ASYNC_FLUSH_CONDVAR.notify_one();
+		}
+	}
+}