## Module frame_logging

Source
Expand description

Learn about how to do logging in FRAME-based runtimes.

## §FRAME Logging

This reference docs briefly explores how to do logging and printing runtimes, mainly FRAME-based.

> Please make sure to read the section below on using logging in production.

### §Using `println!`

To recap, as with standard Rust, you can use `println!` in your tests, but it will only print out if executed with `--nocapture`, or if the test panics.

    fn it_print() {
    	println!("Hello, world!");
    }

within the pezpallet, if you want to use the standard `println!`, it needs to be wrapped in [`pezsp_std::if_std`]. Of course, this means that this print code is only available to you in the `std` compiler flag, and never present in a wasm build.

    // somewhere in your pezpallet. This is not a real pezpallet code.
    mod pezpallet {
    	struct Pezpallet;
    	impl Pezpallet {
    		fn print() {
    			pezsp_std::if_std! {
    				println!("Hello, world!");
    			}
    		}
    	}
    }

### §Using `log`

First, ensure you are familiar with the `log` crate. In short, each log statement has:

1. `log-level`, signifying how important it is.
2. `log-target`, signifying to which component it belongs.

Add log statements to your pezpallet as such:

You can add the log crate to the `Cargo.toml` of the pezpallet.

    #[dependencies]
    log = { version = "x.y.z", default-features = false }

    #[features]
    std = [
    	// snip -- other pallets
    	"log/std"
    ]

More conveniently, the `frame` umbrella crate re-exports the log crate as `pezframe::log`.

Then, the pezpallet can use this crate to emit log statements. In this statement, we use the info level, and the target is `pezpallet-example`.

    mod pezpallet {
    	struct Pezpallet;

    	impl Pezpallet {
    		fn logs() {
    			pezframe::log::info!(target: "pezpallet-example", "Hello, world!");
    		}
    	}
    }

This will in itself just emit the log messages, but unless if captured by a logger, they will not go anywhere. [`pezsp_api`] provides a handy function to enable the runtime logging:

    // in your test
    fn it_also_prints() {
    	pezsp_api::init_runtime_logger();
    	// call into your pezpallet, and now it will print `log` statements.
    }

Alternatively, you can use [`pezsp_tracing::try_init_simple`].

`info`, `error` and `warn` logs are printed by default, but if you want lower level logs to also be printed, you must to add the following compiler flag:

    RUST_LOG=pezpallet-example=trace cargo test

### §Enabling Logs in Production

All logs from the runtime are emitted by default, but there is a feature flag in [`pezsp_api`], called `disable-logging`, that can be used to disable all logs in the runtime. This is useful for production chains to reduce the size and overhead of the wasm runtime.

ⓘ

    pub fn init_runtime_logger() {
    	#[cfg(not(feature = "disable-logging"))]
    	pezsp_runtime::runtime_logger::RuntimeLogger::init();
    }

Similar to the above, the proper `RUST_LOG` must also be passed to your compiler flag when compiling the runtime.

### §Log Target Prefixing

Many `crate::pezkuwi_sdk::frame_runtime` pallets emit logs with log target `runtime::<name of pezpallet>`, for example `runtime::system`. This then allows one to run a node with a wasm blob compiled with `LOG_TARGET=runtime=debug`, which enables the log target of all pallets who’s log target starts with `runtime`.

### §Low Level Primitives

Under the hood, logging is another instance of host functions under the hood (as defined in `crate::reference_docs::wasm_meta_protocol`). The runtime uses a set of host functions under [`pezsp_io::logging`] and [`pezsp_io::misc`] to emit all logs and prints. You typically do not need to use these APIs directly.

### §Using Logging in Production

Note that within FRAME, reading storage values only for the purpose of logging is dangerous, and can lead to consensus issues. This is because with the introduction of `crate::guides::enable_pov_reclaim`, the node side code will track the storage changes, and tries to update the onchain record of the `proof_size` weight used (stored in [`pezframe_system::BlockWeight`]) after the block is executed.

If one node has a different log level enabled than the rest of the network, and the extra logs impose additional storage reads, then the amount of `proof_size` weight reclaimed into [`pezframe_system::BlockWeight`] will be different, causing a state root mismatch, which is typically a fatal error emitted from [`pezframe_executive`].

This also can also happen in a teyrchain context, and cause discrepancies between the relay chain and the teyrchain, when execution the Teyrchain Validation Function (PVF) on the relay chain.

In summary, you should only used storage values in logging (especially for levels lower than `info` which is typically enabled by all parties) that are already read from storage, and will be part of the storage proof of execution in any case.

A typical faulty code would look like this:

ⓘ

    /// This function will have a different storage footprint depending on the log level
    fn faulty_logging() {
    	log::debug!(
    		"what I am about to print is only read when `RUST_LOG=debug` {:?}",
    		StorageValue::<T>::get()
     	);
    }

Please read this issue for one instance of the consensus issues caused by this mistake.