sp_tracing/lib.rs
1// This file is part of Substrate.
2
3// Copyright (C) Parity Technologies (UK) Ltd.
4// SPDX-License-Identifier: Apache-2.0
5
6// Licensed under the Apache License, Version 2.0 (the "License");
7// you may not use this file except in compliance with the License.
8// You may obtain a copy of the License at
9//
10// http://www.apache.org/licenses/LICENSE-2.0
11//
12// Unless required by applicable law or agreed to in writing, software
13// distributed under the License is distributed on an "AS IS" BASIS,
14// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
15// See the License for the specific language governing permissions and
16// limitations under the License.
17
18//! Substrate tracing primitives and macros.
19//!
20//! To trace functions or individual code in Substrate, this crate provides [`within_span`]
21//! and [`enter_span`]. See the individual docs for how to use these macros.
22//!
23//! Note that to allow traces from wasm execution environment there are
24//! 2 reserved identifiers for tracing `Field` recording, stored in the consts:
25//! `WASM_TARGET_KEY` and `WASM_NAME_KEY` - if you choose to record fields, you
26//! must ensure that your identifiers do not clash with either of these.
27//!
28//! Additionally, we have a const: `WASM_TRACE_IDENTIFIER`, which holds a span name used
29//! to signal that the 'actual' span name and target should be retrieved instead from
30//! the associated Fields mentioned above.
31//!
32//! Note: The `tracing` crate requires trace metadata to be static. This does not work
33//! for wasm code in substrate, as it is regularly updated with new code from on-chain
34//! events. The workaround for this is for the wasm tracing wrappers to put the
35//! `name` and `target` data in the `values` map (normally they would be in the static
36//! metadata assembled at compile time).
37
38#![cfg_attr(not(feature = "std"), no_std)]
39
40extern crate alloc;
41
42#[cfg(feature = "std")]
43pub use tracing;
44pub use tracing::{
45 debug, debug_span, error, error_span, event, info, info_span, span, trace, trace_span, warn,
46 warn_span, Level, Span,
47};
48
49#[cfg(feature = "std")]
50pub use tracing_subscriber;
51
52pub use crate::types::{
53 WasmEntryAttributes, WasmFieldName, WasmFields, WasmLevel, WasmMetadata, WasmValue,
54 WasmValuesSet,
55};
56#[cfg(not(substrate_runtime))]
57pub use crate::types::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER};
58
59/// Tracing facilities and helpers.
60///
61/// This is modeled after the `tracing`/`tracing-core` interface and uses that more or
62/// less directly for the native side. Because of certain optimisations the these crates
63/// have done, the wasm implementation diverges slightly and is optimised for that use
64/// case (like being able to cross the wasm/native boundary via scale codecs).
65///
66/// One of said optimisations is that all macros will yield to a `noop` in non-std unless
67/// the `with-tracing` feature is explicitly activated. This allows you to just use the
68/// tracing wherever you deem fit and without any performance impact by default. Only if
69/// the specific `with-tracing`-feature is activated on this crate will it actually include
70/// the tracing code in the non-std environment.
71///
72/// Because of that optimisation, you should not use the `span!` and `span_*!` macros
73/// directly as they yield nothing without the feature present. Instead you should use
74/// `enter_span!` and `within_span!` – which would strip away even any parameter conversion
75/// you do within the span-definition (and thus optimise your performance). For your
76/// convenience you directly specify the `Level` and name of the span or use the full
77/// feature set of `span!`/`span_*!` on it:
78///
79/// # Example
80///
81/// ```rust
82/// sp_tracing::enter_span!(sp_tracing::Level::TRACE, "fn wide span");
83/// {
84/// sp_tracing::enter_span!(sp_tracing::trace_span!("outer-span"));
85/// {
86/// sp_tracing::enter_span!(sp_tracing::Level::TRACE, "inner-span");
87/// // ..
88/// } // inner span exists here
89/// } // outer span exists here
90///
91/// sp_tracing::within_span! {
92/// sp_tracing::debug_span!("debug-span", you_can_pass="any params");
93/// 1 + 1;
94/// // some other complex code
95/// } // debug span ends here
96/// ```
97///
98///
99/// # Setup
100///
101/// This project only provides the macros and facilities to manage tracing
102/// it doesn't implement the tracing subscriber or backend directly – that is
103/// up to the developer integrating it into a specific environment. In native
104/// this can and must be done through the regular `tracing`-facilities, please
105/// see their documentation for details.
106///
107/// On the wasm-side we've adopted a similar approach of having a global
108/// `TracingSubscriber` that the macros call and that does the actual work
109/// of tracking. To provide your tracking, you must implement `TracingSubscriber`
110/// and call `set_tracing_subscriber` at the very beginning of your execution –
111/// the default subscriber is doing nothing, so any spans or events happening before
112/// will not be recorded!
113mod types;
114
115/// Try to init a simple tracing subscriber with log compatibility layer.
116///
117/// Ignores any error. Useful for testing. Uses the default filter for logs.
118///
119/// Related functions:
120/// - [`init_for_tests()`]: Enables `TRACE` level.
121/// - [`test_log_capture::init_log_capture()`]: Captures logs for assertions and/or outputs logs.
122/// - [`capture_test_logs!()`]: A macro for capturing logs within test blocks.
123#[cfg(feature = "std")]
124pub fn try_init_simple() {
125 let _ = tracing_subscriber::fmt()
126 .with_env_filter(tracing_subscriber::EnvFilter::from_default_env())
127 .with_writer(std::io::stderr)
128 .try_init();
129}
130
131/// Init a tracing subscriber for logging in tests.
132///
133/// Be aware that this enables `TRACE` by default. It also ignores any error
134/// while setting up the logger.
135///
136/// The logs are not shown by default, logs are only shown when the test fails
137/// or if [`nocapture`](https://doc.rust-lang.org/cargo/commands/cargo-test.html#display-options)
138/// is being used.
139///
140/// Related functions:
141/// - [`try_init_simple()`]: Uses the default filter.
142/// - [`test_log_capture::init_log_capture()`]: Captures logs for assertions and/or outputs logs.
143/// - [`capture_test_logs!()`]: A macro for capturing logs within test blocks.
144#[cfg(feature = "std")]
145pub fn init_for_tests() {
146 let _ = tracing_subscriber::fmt()
147 .with_max_level(tracing::Level::TRACE)
148 .with_test_writer()
149 .try_init();
150}
151
152/// Runs given code within a tracing span, measuring it's execution time.
153///
154/// If tracing is not enabled, the code is still executed. Pass in level and name or
155/// use any valid `sp_tracing::Span`followed by `;` and the code to execute,
156///
157/// # Example
158///
159/// ```
160/// sp_tracing::within_span! {
161/// sp_tracing::Level::TRACE,
162/// "test-span";
163/// 1 + 1;
164/// // some other complex code
165/// }
166///
167/// sp_tracing::within_span! {
168/// sp_tracing::span!(sp_tracing::Level::WARN, "warn-span", you_can_pass="any params");
169/// 1 + 1;
170/// // some other complex code
171/// }
172///
173/// sp_tracing::within_span! {
174/// sp_tracing::debug_span!("debug-span", you_can_pass="any params");
175/// 1 + 1;
176/// // some other complex code
177/// }
178/// ```
179#[cfg(any(feature = "std", feature = "with-tracing"))]
180#[macro_export]
181macro_rules! within_span {
182 (
183 $span:expr;
184 $( $code:tt )*
185 ) => {
186 $span.in_scope(||
187 {
188 $( $code )*
189 }
190 )
191 };
192 (
193 $lvl:expr,
194 $name:expr;
195 $( $code:tt )*
196 ) => {
197 {
198 $crate::within_span!($crate::span!($lvl, $name); $( $code )*)
199 }
200 };
201}
202
203#[cfg(all(not(feature = "std"), not(feature = "with-tracing")))]
204#[macro_export]
205macro_rules! within_span {
206 (
207 $span:stmt;
208 $( $code:tt )*
209 ) => {
210 $( $code )*
211 };
212 (
213 $lvl:expr,
214 $name:expr;
215 $( $code:tt )*
216 ) => {
217 $( $code )*
218 };
219}
220
221/// Enter a span - noop for `no_std` without `with-tracing`
222#[cfg(all(not(feature = "std"), not(feature = "with-tracing")))]
223#[macro_export]
224macro_rules! enter_span {
225 ( $lvl:expr, $name:expr ) => {};
226 ( $name:expr ) => {}; // no-op
227}
228
229/// Enter a span.
230///
231/// The span will be valid, until the scope is left. Use either level and name
232/// or pass in any valid `sp_tracing::Span` for extended usage. The span will
233/// be exited on drop – which is at the end of the block or to the next
234/// `enter_span!` calls, as this overwrites the local variable. For nested
235/// usage or to ensure the span closes at certain time either put it into a block
236/// or use `within_span!`
237///
238/// # Example
239///
240/// ```
241/// sp_tracing::enter_span!(sp_tracing::Level::TRACE, "test-span");
242/// // previous will be dropped here
243/// sp_tracing::enter_span!(
244/// sp_tracing::span!(sp_tracing::Level::DEBUG, "debug-span", params="value"));
245/// sp_tracing::enter_span!(sp_tracing::info_span!("info-span", params="value"));
246///
247/// {
248/// sp_tracing::enter_span!(sp_tracing::Level::TRACE, "outer-span");
249/// {
250/// sp_tracing::enter_span!(sp_tracing::Level::TRACE, "inner-span");
251/// // ..
252/// } // inner span exists here
253/// } // outer span exists here
254/// ```
255#[cfg(any(feature = "std", feature = "with-tracing"))]
256#[macro_export]
257macro_rules! enter_span {
258 ( $span:expr ) => {
259 // Calling this twice in a row will overwrite (and drop) the earlier
260 // that is a _documented feature_!
261 let __within_span__ = $span;
262 let __tracing_guard__ = __within_span__.enter();
263 };
264 ( $lvl:expr, $name:expr ) => {
265 $crate::enter_span!($crate::span!($lvl, $name))
266 };
267}
268
269#[cfg(feature = "std")]
270pub mod test_log_capture {
271 use std::{
272 io::Write,
273 sync::{Arc, Mutex},
274 };
275 use tracing::level_filters::LevelFilter;
276 use tracing_subscriber::{fmt, fmt::MakeWriter, layer::SubscriberExt, Layer, Registry};
277
278 /// A reusable log capturing struct for unit tests.
279 /// Captures logs written during test execution for assertions.
280 ///
281 /// # Examples
282 /// ```
283 /// use sp_tracing::test_log_capture::LogCapture;
284 /// use std::io::Write;
285 ///
286 /// let mut log_capture = LogCapture::new();
287 /// writeln!(log_capture, "Test log message").unwrap();
288 /// assert!(log_capture.contains("Test log message"));
289 /// ```
290 pub struct LogCapture {
291 buffer: Arc<Mutex<Vec<u8>>>,
292 }
293
294 impl LogCapture {
295 /// Creates a new `LogCapture` instance with an internal buffer.
296 ///
297 /// # Examples
298 /// ```
299 /// use sp_tracing::test_log_capture::LogCapture;
300 ///
301 /// let log_capture = LogCapture::new();
302 /// assert!(log_capture.get_logs().is_empty());
303 /// ```
304 pub fn new() -> Self {
305 LogCapture { buffer: Arc::new(Mutex::new(Vec::new())) }
306 }
307
308 /// Checks if the captured logs contain a specific substring.
309 ///
310 /// # Examples
311 /// ```
312 /// use sp_tracing::test_log_capture::LogCapture;
313 /// use std::io::Write;
314 ///
315 /// let mut log_capture = LogCapture::new();
316 /// writeln!(log_capture, "Hello, world!").unwrap();
317 /// assert!(log_capture.contains("Hello"));
318 /// assert!(!log_capture.contains("Goodbye"));
319 /// ```
320 pub fn contains(&self, expected: &str) -> bool {
321 let logs = self.get_logs();
322 logs.contains(expected)
323 }
324
325 /// Retrieves the captured logs as a `String`.
326 ///
327 /// # Examples
328 /// ```
329 /// use sp_tracing::test_log_capture::LogCapture;
330 /// use std::io::Write;
331 ///
332 /// let mut log_capture = LogCapture::new();
333 /// writeln!(log_capture, "Log entry").unwrap();
334 /// assert_eq!(log_capture.get_logs().trim(), "Log entry");
335 /// ```
336 pub fn get_logs(&self) -> String {
337 let raw_logs = String::from_utf8(self.buffer.lock().unwrap().clone()).unwrap();
338 let ansi_escape = regex::Regex::new(r"\x1B\[[0-9;]*[mK]").unwrap(); // Regex to match ANSI codes
339 ansi_escape.replace_all(&raw_logs, "").to_string() // Remove ANSI codes
340 }
341
342 /// Returns a clone of the internal buffer for use in `MakeWriter`.
343 pub fn writer(&self) -> Self {
344 LogCapture { buffer: Arc::clone(&self.buffer) }
345 }
346 }
347
348 impl Write for LogCapture {
349 /// Writes log data into the internal buffer.
350 fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
351 let mut logs = self.buffer.lock().unwrap();
352 logs.extend_from_slice(buf);
353 Ok(buf.len())
354 }
355
356 /// Flushes the internal buffer (no-op in this implementation).
357 fn flush(&mut self) -> std::io::Result<()> {
358 Ok(())
359 }
360 }
361
362 impl<'a> MakeWriter<'a> for LogCapture {
363 type Writer = Self;
364
365 /// Provides a `MakeWriter` implementation for `tracing_subscriber`.
366 fn make_writer(&'a self) -> Self::Writer {
367 self.writer()
368 }
369 }
370
371 /// Initialises a log capture utility for testing, with optional log printing.
372 ///
373 /// This function sets up a `LogCapture` instance to capture logs during test execution.
374 /// It also configures a `tracing_subscriber` with the specified maximum log level
375 /// and a writer that directs logs to `LogCapture`. If `print_logs` is enabled, logs
376 /// up to `max_level` are also printed to the test output.
377 ///
378 /// # Arguments
379 ///
380 /// * `max_level` - The maximum log level to capture and print, which can be converted into
381 /// `LevelFilter`.
382 /// * `print_logs` - If `true`, logs up to `max_level` will also be printed to the test output.
383 ///
384 /// # Returns
385 ///
386 /// A tuple containing:
387 /// - `LogCapture`: The log capture instance.
388 /// - `Subscriber`: A configured `tracing_subscriber` that captures logs.
389 ///
390 /// # Examples
391 ///
392 /// ```
393 /// use sp_tracing::{
394 /// test_log_capture::init_log_capture,
395 /// tracing::{info, subscriber, Level},
396 /// };
397 ///
398 /// let (log_capture, subscriber) = init_log_capture(Level::INFO, false);
399 /// subscriber::with_default(subscriber, || {
400 /// info!("This log will be captured");
401 /// assert!(log_capture.contains("This log will be captured"));
402 /// });
403 /// ```
404 ///
405 /// # Usage Guide
406 ///
407 /// - If you only need to **capture logs for assertions** without printing them, use
408 /// `init_log_capture(max_level, false)`.
409 /// - If you need both **capturing and printing logs**, use `init_log_capture(max_level, true)`.
410 /// - If you only need to **print logs** but not capture them, use
411 /// `sp_tracing::init_for_tests()`.
412 pub fn init_log_capture(
413 max_level: impl Into<LevelFilter>,
414 print_logs: bool,
415 ) -> (LogCapture, impl tracing::Subscriber + Send + Sync) {
416 // Create a new log capture instance
417 let log_capture = LogCapture::new();
418
419 // Convert the max log level into LevelFilter
420 let level_filter = max_level.into();
421
422 // Create a layer for capturing logs into LogCapture
423 let capture_layer = fmt::layer()
424 .with_writer(log_capture.writer()) // Use LogCapture as the writer
425 .with_filter(level_filter); // Set the max log level
426
427 // Base subscriber with log capturing
428 let subscriber = Registry::default().with(capture_layer);
429
430 // If `print_logs` is enabled, add a layer that prints logs to test output up to `max_level`
431 let test_layer = if print_logs {
432 Some(
433 fmt::layer()
434 .with_test_writer() // Direct logs to test output
435 .with_filter(level_filter), // Apply the same max log level filter
436 )
437 } else {
438 None
439 };
440
441 // Combine the log capture subscriber with the test layer (if applicable)
442 let combined_subscriber = subscriber.with(test_layer);
443
444 (log_capture, combined_subscriber)
445 }
446
447 /// Macro for capturing logs during test execution.
448 ///
449 /// This macro sets up a log subscriber with a specified maximum log level
450 /// and an option to print logs to the test output while capturing them.
451 ///
452 /// # Arguments
453 ///
454 /// - `$max_level`: The maximum log level to capture.
455 /// - `$print_logs`: Whether to also print logs to the test output.
456 /// - `$test`: The block of code where logs are captured.
457 ///
458 /// # Examples
459 ///
460 /// ```
461 /// use sp_tracing::{
462 /// capture_test_logs,
463 /// tracing::{info, warn, Level},
464 /// };
465 ///
466 /// // Capture logs at WARN level without printing them
467 /// let log_capture = capture_test_logs!(Level::WARN, false, {
468 /// info!("Captured info message");
469 /// warn!("Captured warning");
470 /// });
471 ///
472 /// assert!(!log_capture.contains("Captured info message"));
473 /// assert!(log_capture.contains("Captured warning"));
474 ///
475 /// // Capture logs at TRACE level and also print them
476 /// let log_capture = capture_test_logs!(Level::TRACE, true, {
477 /// info!("This will be captured and printed");
478 /// });
479 ///
480 /// assert!(log_capture.contains("This will be captured and printed"));
481 /// ```
482 ///
483 /// # Related functions:
484 /// - [`init_log_capture()`]: Captures logs for assertions.
485 /// - `sp_tracing::init_for_tests()`: Outputs logs but does not capture them.
486 #[macro_export]
487 macro_rules! capture_test_logs {
488 // Case when max_level and print_logs are provided
489 ($max_level:expr, $print_logs:expr, $test:block) => {{
490 let (log_capture, subscriber) =
491 sp_tracing::test_log_capture::init_log_capture($max_level, $print_logs);
492
493 sp_tracing::tracing::subscriber::with_default(subscriber, || $test);
494
495 log_capture
496 }};
497
498 // Case when only max_level is provided (defaults to not printing logs)
499 ($max_level:expr, $test:block) => {{
500 capture_test_logs!($max_level, false, $test)
501 }};
502
503 // Case when max_level is omitted (defaults to DEBUG, no printing)
504 ($test:block) => {{
505 capture_test_logs!(sp_tracing::tracing::Level::DEBUG, false, $test)
506 }};
507 }
508}