From ba96cc11aba269aeed4c55326ef0cf4955a0948b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Mon, 15 Feb 2021 15:43:16 +0100 Subject: [PATCH 1/6] Init `RuntimeLogger` automatically for each runtime api call This pr change the runtime api in such a way to always and automatically enable the `RuntimeLogger`. This enables the user to use `log` or `tracing` from inside the runtime to create log messages. As logging introduces some extra code and especially increases the size of the wasm blob. It is advised to disable all logging completely with `sp-api/disable-logging` when doing the wasm builds for the on-chain wasm runtime. Besides these changes, the pr also brings most of the logging found in frame to the same format "runtime::*". --- Cargo.lock | 26 +- bin/node/runtime/Cargo.toml | 2 + bin/node/runtime/src/lib.rs | 4 +- frame/babe/Cargo.toml | 2 + frame/babe/src/equivocation.rs | 22 +- frame/balances/Cargo.toml | 2 + frame/balances/src/lib.rs | 6 +- frame/benchmarking/Cargo.toml | 2 + frame/benchmarking/src/lib.rs | 12 +- frame/collective/Cargo.toml | 2 + frame/collective/src/lib.rs | 29 +- frame/contracts/Cargo.toml | 2 + frame/contracts/src/rent.rs | 7 +- frame/contracts/src/storage.rs | 4 +- frame/elections-phragmen/Cargo.toml | 2 + frame/elections-phragmen/src/lib.rs | 11 +- .../src/migrations_3_0_0.rs | 29 +- frame/example-offchain-worker/Cargo.toml | 2 + frame/example-offchain-worker/src/lib.rs | 35 ++- frame/executive/src/lib.rs | 4 - frame/grandpa/Cargo.toml | 2 + frame/grandpa/src/equivocation.rs | 20 +- frame/im-online/Cargo.toml | 2 + frame/im-online/src/lib.rs | 12 +- .../primitives/Cargo.toml | 2 + .../primitives/src/lib.rs | 16 +- frame/node-authorization/Cargo.toml | 2 + frame/node-authorization/src/lib.rs | 16 +- frame/offences/Cargo.toml | 2 + frame/offences/src/lib.rs | 11 +- frame/scheduler/Cargo.toml | 4 +- frame/scheduler/src/lib.rs | 13 +- frame/staking/Cargo.toml | 2 + frame/staking/src/lib.rs | 28 +- frame/support/Cargo.toml | 7 +- frame/support/src/debug.rs | 247 ------------------ frame/support/src/hash.rs | 4 +- frame/support/src/lib.rs | 28 +- frame/support/src/storage/child.rs | 6 +- .../src/storage/generator/double_map.rs | 6 +- frame/support/src/storage/generator/map.rs | 4 +- frame/support/src/storage/mod.rs | 15 +- frame/support/src/storage/unhashed.rs | 2 +- frame/system/Cargo.toml | 2 + frame/system/src/lib.rs | 17 +- frame/system/src/offchain.rs | 6 +- frame/timestamp/Cargo.toml | 4 +- frame/timestamp/src/lib.rs | 7 +- primitives/api/Cargo.toml | 16 ++ .../api/proc-macro/src/impl_runtime_apis.rs | 3 + primitives/api/src/lib.rs | 19 ++ primitives/api/test/Cargo.toml | 2 + primitives/api/test/tests/runtime_calls.rs | 31 +++ primitives/runtime/Cargo.toml | 7 +- primitives/runtime/src/lib.rs | 1 + primitives/runtime/src/runtime_logger.rs | 108 ++++++++ test-utils/runtime/Cargo.toml | 6 +- test-utils/runtime/build.rs | 10 +- test-utils/runtime/client/src/lib.rs | 10 + test-utils/runtime/src/lib.rs | 21 +- utils/wasm-builder/src/builder.rs | 15 ++ utils/wasm-builder/src/wasm_project.rs | 12 +- 62 files changed, 537 insertions(+), 416 deletions(-) delete mode 100644 frame/support/src/debug.rs create mode 100644 primitives/runtime/src/runtime_logger.rs diff --git a/Cargo.lock b/Cargo.lock index 64949da009e24..780a19f134862 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1665,6 +1665,7 @@ dependencies = [ "frame-system", "hex-literal", "linregress", + "log", "parity-scale-codec", "paste 1.0.4", "serde", @@ -1745,7 +1746,6 @@ dependencies = [ "pretty_assertions", "serde", "smallvec 1.6.1", - "sp-api", "sp-arithmetic", "sp-core", "sp-inherents", @@ -1755,7 +1755,6 @@ dependencies = [ "sp-state-machine", "sp-std", "sp-tracing", - "substrate-test-runtime-client", ] [[package]] @@ -1816,6 +1815,7 @@ dependencies = [ "criterion", "frame-support", "impl-trait-for-tuples", + "log", "parity-scale-codec", "serde", "sp-core", @@ -4059,6 +4059,7 @@ dependencies = [ "frame-system-benchmarking", "frame-system-rpc-runtime-api", "hex-literal", + "log", "node-primitives", "pallet-assets", "pallet-authority-discovery", @@ -4483,6 +4484,7 @@ dependencies = [ "frame-benchmarking", "frame-support", "frame-system", + "log", "pallet-authorship", "pallet-balances", "pallet-offences", @@ -4512,6 +4514,7 @@ dependencies = [ "frame-benchmarking", "frame-support", "frame-system", + "log", "pallet-transaction-payment", "parity-scale-codec", "serde", @@ -4554,6 +4557,7 @@ dependencies = [ "sp-io", "sp-runtime", "sp-std", + "tracing", ] [[package]] @@ -4565,6 +4569,7 @@ dependencies = [ "frame-support", "frame-system", "hex-literal", + "log", "pallet-balances", "pallet-contracts-primitives", "pallet-contracts-proc-macro", @@ -4680,6 +4685,7 @@ dependencies = [ "frame-support", "frame-system", "hex-literal", + "log", "pallet-balances", "parity-scale-codec", "serde", @@ -4714,6 +4720,7 @@ dependencies = [ "frame-support", "frame-system", "lite-json", + "log", "parity-scale-codec", "serde", "sp-core", @@ -4746,6 +4753,7 @@ dependencies = [ "frame-benchmarking", "frame-support", "frame-system", + "log", "pallet-authorship", "pallet-balances", "pallet-offences", @@ -4790,6 +4798,7 @@ dependencies = [ "frame-benchmarking", "frame-support", "frame-system", + "log", "pallet-authorship", "pallet-session", "parity-scale-codec", @@ -4875,6 +4884,7 @@ dependencies = [ "frame-support", "frame-system", "hex-literal", + "log", "parity-scale-codec", "serde", "sp-api", @@ -4920,6 +4930,7 @@ version = "2.0.0" dependencies = [ "frame-support", "frame-system", + "log", "parity-scale-codec", "serde", "sp-core", @@ -4934,6 +4945,7 @@ version = "3.0.0" dependencies = [ "frame-support", "frame-system", + "log", "pallet-balances", "parity-scale-codec", "serde", @@ -5024,6 +5036,7 @@ dependencies = [ "frame-benchmarking", "frame-support", "frame-system", + "log", "parity-scale-codec", "serde", "sp-core", @@ -5115,6 +5128,7 @@ dependencies = [ "frame-support", "frame-system", "hex", + "log", "pallet-authorship", "pallet-balances", "pallet-session", @@ -5205,6 +5219,7 @@ dependencies = [ "frame-support", "frame-system", "impl-trait-for-tuples", + "log", "parity-scale-codec", "serde", "sp-core", @@ -8140,6 +8155,7 @@ name = "sp-api" version = "3.0.0" dependencies = [ "hash-db", + "log", "parity-scale-codec", "sp-api-proc-macro", "sp-core", @@ -8149,6 +8165,7 @@ dependencies = [ "sp-test-primitives", "sp-version", "thiserror", + "tracing", ] [[package]] @@ -8167,6 +8184,7 @@ name = "sp-api-test" version = "2.0.1" dependencies = [ "criterion", + "log", "parity-scale-codec", "rustversion", "sc-block-builder", @@ -8176,6 +8194,7 @@ dependencies = [ "sp-core", "sp-runtime", "sp-state-machine", + "sp-tracing", "sp-version", "substrate-test-runtime-client", "trybuild", @@ -8620,12 +8639,15 @@ dependencies = [ "rand 0.7.3", "serde", "serde_json", + "sp-api", "sp-application-crypto", "sp-arithmetic", "sp-core", "sp-io", "sp-state-machine", "sp-std", + "sp-tracing", + "substrate-test-runtime-client", ] [[package]] diff --git a/bin/node/runtime/Cargo.toml b/bin/node/runtime/Cargo.toml index f77a16a10f4c6..49e62d92021b8 100644 --- a/bin/node/runtime/Cargo.toml +++ b/bin/node/runtime/Cargo.toml @@ -18,6 +18,7 @@ codec = { package = "parity-scale-codec", version = "2.0.0", default-features = serde = { version = "1.0.102", optional = true } static_assertions = "1.1.0" hex-literal = { version = "0.3.1", optional = true } +log = { version = "0.4.14", default-features = false } # primitives sp-authority-discovery = { version = "3.0.0", default-features = false, path = "../../../primitives/authority-discovery" } @@ -151,6 +152,7 @@ std = [ "pallet-society/std", "pallet-recovery/std", "pallet-vesting/std", + "log/std", ] runtime-benchmarks = [ "frame-benchmarking", diff --git a/bin/node/runtime/src/lib.rs b/bin/node/runtime/src/lib.rs index 58c98e529c319..9c1cc122b7f56 100644 --- a/bin/node/runtime/src/lib.rs +++ b/bin/node/runtime/src/lib.rs @@ -25,7 +25,7 @@ use sp_std::prelude::*; use frame_support::{ - construct_runtime, parameter_types, debug, RuntimeDebug, + construct_runtime, parameter_types, RuntimeDebug, weights::{ Weight, IdentityFee, constants::{BlockExecutionWeight, ExtrinsicBaseWeight, RocksDbWeight, WEIGHT_PER_SECOND}, DispatchClass, @@ -804,7 +804,7 @@ impl frame_system::offchain::CreateSignedTransaction for R ); let raw_payload = SignedPayload::new(call, extra) .map_err(|e| { - debug::warn!("Unable to create signed payload: {:?}", e); + log::warn!("Unable to create signed payload: {:?}", e); }) .ok()?; let signature = raw_payload diff --git a/frame/babe/Cargo.toml b/frame/babe/Cargo.toml index 9bde93506241d..7b8f21e1e096f 100644 --- a/frame/babe/Cargo.toml +++ b/frame/babe/Cargo.toml @@ -31,6 +31,7 @@ sp-session = { version = "3.0.0", default-features = false, path = "../../primit sp-staking = { version = "3.0.0", default-features = false, path = "../../primitives/staking" } sp-std = { version = "3.0.0", default-features = false, path = "../../primitives/std" } sp-timestamp = { version = "3.0.0", default-features = false, path = "../../primitives/timestamp" } +log = { version = "0.4.14", default-features = false } [dev-dependencies] frame-benchmarking = { version = "3.0.0", path = "../benchmarking" } @@ -61,5 +62,6 @@ std = [ "sp-staking/std", "sp-std/std", "sp-timestamp/std", + "log/std", ] runtime-benchmarks = ["frame-benchmarking"] diff --git a/frame/babe/src/equivocation.rs b/frame/babe/src/equivocation.rs index b7275d04734ea..14ba0f16cb9e2 100644 --- a/frame/babe/src/equivocation.rs +++ b/frame/babe/src/equivocation.rs @@ -35,10 +35,7 @@ //! definition. //! -use frame_support::{ - debug, - traits::{Get, KeyOwnerProofSystem}, -}; +use frame_support::traits::{Get, KeyOwnerProofSystem}; use sp_consensus_babe::{EquivocationProof, Slot}; use sp_runtime::transaction_validity::{ InvalidTransaction, TransactionPriority, TransactionSource, TransactionValidity, @@ -163,8 +160,15 @@ where let call = Call::report_equivocation_unsigned(equivocation_proof, key_owner_proof); match SubmitTransaction::>::submit_unsigned_transaction(call.into()) { - Ok(()) => debug::info!("Submitted BABE equivocation report."), - Err(e) => debug::error!("Error submitting equivocation report: {:?}", e), + Ok(()) => log::info!( + target: "runtime::babe", + "Submitted BABE equivocation report.", + ), + Err(e) => log::error!( + target: "runtime::babe", + "Error submitting equivocation report: {:?}", + e, + ), } Ok(()) @@ -186,9 +190,9 @@ impl frame_support::unsigned::ValidateUnsigned for Module { match source { TransactionSource::Local | TransactionSource::InBlock => { /* allowed */ } _ => { - debug::warn!( - target: "babe", - "rejecting unsigned report equivocation transaction because it is not local/in-block." + log::warn!( + target: "runtime::babe", + "rejecting unsigned report equivocation transaction because it is not local/in-block.", ); return InvalidTransaction::Call.into(); diff --git a/frame/balances/Cargo.toml b/frame/balances/Cargo.toml index 39b7fda77fef7..95c7760596c8c 100644 --- a/frame/balances/Cargo.toml +++ b/frame/balances/Cargo.toml @@ -20,6 +20,7 @@ sp-runtime = { version = "3.0.0", default-features = false, path = "../../primit frame-benchmarking = { version = "3.0.0", default-features = false, path = "../benchmarking", optional = true } frame-support = { version = "3.0.0", default-features = false, path = "../support" } frame-system = { version = "3.0.0", default-features = false, path = "../system" } +log = { version = "0.4.14", default-features = false } [dev-dependencies] sp-io = { version = "3.0.0", path = "../../primitives/io" } @@ -36,5 +37,6 @@ std = [ "frame-benchmarking/std", "frame-support/std", "frame-system/std", + "log/std", ] runtime-benchmarks = ["frame-benchmarking"] diff --git a/frame/balances/src/lib.rs b/frame/balances/src/lib.rs index e3eb9478b6493..1515cc7499a78 100644 --- a/frame/balances/src/lib.rs +++ b/frame/balances/src/lib.rs @@ -715,7 +715,8 @@ impl, I: 'static> Pallet { /// Update the account entry for `who`, given the locks. fn update_locks(who: &T::AccountId, locks: &[BalanceLock]) { if locks.len() as u32 > T::MaxLocks::get() { - frame_support::debug::warn!( + log::warn!( + target: "runtime::balances", "Warning: A user has more currency locks than expected. \ A runtime configuration adjustment may be needed." ); @@ -749,7 +750,8 @@ impl, I: 'static> Pallet { // No providers for the locks. This is impossible under normal circumstances // since the funds that are under the lock will themselves be stored in the // account and therefore will need a reference. - frame_support::debug::warn!( + log::warn!( + target: "runtime::balances", "Warning: Attempt to introduce lock consumer reference, yet no providers. \ This is unexpected but should be safe." ); diff --git a/frame/benchmarking/Cargo.toml b/frame/benchmarking/Cargo.toml index 41ab9efeced02..d0e9f2af96ab1 100644 --- a/frame/benchmarking/Cargo.toml +++ b/frame/benchmarking/Cargo.toml @@ -24,6 +24,7 @@ sp-io = { version = "3.0.0", path = "../../primitives/io", default-features = fa sp-storage = { version = "3.0.0", path = "../../primitives/storage", default-features = false } frame-support = { version = "3.0.0", default-features = false, path = "../support" } frame-system = { version = "3.0.0", default-features = false, path = "../system" } +log = { version = "0.4.14", default-features = false } [dev-dependencies] hex-literal = "0.3.1" @@ -40,4 +41,5 @@ std = [ "frame-support/std", "frame-system/std", "linregress", + "log/std", ] diff --git a/frame/benchmarking/src/lib.rs b/frame/benchmarking/src/lib.rs index d2cba9cc70973..5342768026d32 100644 --- a/frame/benchmarking/src/lib.rs +++ b/frame/benchmarking/src/lib.rs @@ -29,10 +29,16 @@ pub use utils::*; pub use analysis::{Analysis, BenchmarkSelector, RegressionModel}; #[doc(hidden)] pub use sp_io::storage::root as storage_root; +#[doc(hidden)] pub use sp_runtime::traits::Zero; +#[doc(hidden)] pub use frame_support; +#[doc(hidden)] pub use paste; +#[doc(hidden)] pub use sp_storage::TrackedStorageKey; +#[doc(hidden)] +pub use log; /// Construct pallet benchmarks for weighing dispatchables. /// @@ -731,7 +737,7 @@ macro_rules! impl_benchmark { closure_to_benchmark()?; } else { // Time the extrinsic logic. - frame_support::debug::trace!( + $crate::log::trace!( target: "benchmark", "Start Benchmark: {:?}", c ); @@ -744,12 +750,12 @@ macro_rules! impl_benchmark { let elapsed_extrinsic = finish_extrinsic - start_extrinsic; // Commit the changes to get proper write count $crate::benchmarking::commit_db(); - frame_support::debug::trace!( + $crate::log::trace!( target: "benchmark", "End Benchmark: {} ns", elapsed_extrinsic ); let read_write_count = $crate::benchmarking::read_write_count(); - frame_support::debug::trace!( + $crate::log::trace!( target: "benchmark", "Read/Write Count {:?}", read_write_count ); diff --git a/frame/collective/Cargo.toml b/frame/collective/Cargo.toml index 0c58f41640100..1edd87b382108 100644 --- a/frame/collective/Cargo.toml +++ b/frame/collective/Cargo.toml @@ -22,6 +22,7 @@ sp-runtime = { version = "3.0.0", default-features = false, path = "../../primit frame-benchmarking = { version = "3.0.0", default-features = false, path = "../benchmarking", optional = true } frame-support = { version = "3.0.0", default-features = false, path = "../support" } frame-system = { version = "3.0.0", default-features = false, path = "../system" } +tracing = { version = "0.1.22", default-features = false } [dev-dependencies] hex-literal = "0.3.1" @@ -38,6 +39,7 @@ std = [ "frame-support/std", "sp-runtime/std", "frame-system/std", + "tracing/std", ] runtime-benchmarks = [ "frame-benchmarking", diff --git a/frame/collective/src/lib.rs b/frame/collective/src/lib.rs index 50beb8607d61d..a56cff0140232 100644 --- a/frame/collective/src/lib.rs +++ b/frame/collective/src/lib.rs @@ -49,7 +49,7 @@ use sp_runtime::{RuntimeDebug, traits::Hash}; use frame_support::{ codec::{Decode, Encode}, - debug, decl_error, decl_event, decl_module, decl_storage, + decl_error, decl_event, decl_module, decl_storage, dispatch::{ DispatchError, DispatchResult, DispatchResultWithPostInfo, Dispatchable, Parameter, PostDispatchInfo, @@ -320,19 +320,21 @@ decl_module! { ) -> DispatchResultWithPostInfo { ensure_root(origin)?; if new_members.len() > T::MaxMembers::get() as usize { - debug::error!( - "New members count exceeds maximum amount of members expected. (expected: {}, actual: {})", - T::MaxMembers::get(), - new_members.len() + tracing::error!( + target: "runtime::collective", + expected = %T::MaxMembers::get(), + actual = %new_members.len(), + "New members count exceeds maximum amount of members expected.", ); } let old = Members::::get(); if old.len() > old_count as usize { - debug::warn!( - "Wrong count used to estimate set_members weight. (expected: {}, actual: {})", - old_count, - old.len() + tracing::warn!( + target: "runtime::collective", + expected = %old_count, + actual = %old.len(), + "Wrong count used to estimate set_members weight.", ); } let mut new_members = new_members; @@ -811,10 +813,11 @@ impl, I: Instance> ChangeMembers for Module { new: &[T::AccountId], ) { if new.len() > T::MaxMembers::get() as usize { - debug::error!( - "New members count exceeds maximum amount of members expected. (expected: {}, actual: {})", - T::MaxMembers::get(), - new.len() + tracing::error!( + target: "runtime::collective", + expected = %T::MaxMembers::get(), + actual = %new.len(), + "New members count exceeds maximum amount of members expected.", ); } // remove accounts from all current voting in motions. diff --git a/frame/contracts/Cargo.toml b/frame/contracts/Cargo.toml index c5ba615504c6b..596fc28a6efc3 100644 --- a/frame/contracts/Cargo.toml +++ b/frame/contracts/Cargo.toml @@ -31,6 +31,7 @@ sp-io = { version = "3.0.0", default-features = false, path = "../../primitives/ sp-std = { version = "3.0.0", default-features = false, path = "../../primitives/std" } sp-sandbox = { version = "0.9.0", default-features = false, path = "../../primitives/sandbox" } wasmi-validation = { version = "0.3.0", default-features = false } +log = { version = "0.4.14", default-features = false } # Only used in benchmarking to generate random contract code rand = { version = "0.7.0", optional = true, default-features = false } @@ -63,6 +64,7 @@ std = [ "wasmi-validation/std", "pallet-contracts-primitives/std", "pallet-contracts-proc-macro/full", + "log/std", ] runtime-benchmarks = [ "frame-benchmarking", diff --git a/frame/contracts/src/rent.rs b/frame/contracts/src/rent.rs index 38b1e8bd11753..9a8ed819b1e2d 100644 --- a/frame/contracts/src/rent.rs +++ b/frame/contracts/src/rent.rs @@ -26,7 +26,7 @@ use sp_std::prelude::*; use sp_io::hashing::blake2_256; use sp_core::crypto::UncheckedFrom; use frame_support::{ - debug, StorageMap, + StorageMap, storage::child, traits::{Currency, ExistenceRequirement, Get, OnUnbalanced, WithdrawReasons}, }; @@ -183,9 +183,10 @@ where // accidental loss of a contract. Ony `seal_terminate` can remove a // contract without a tombstone. Therefore this case should be never // hit. - debug::error!( + log::error!( + target: "runtime::contracts", "Tombstoned a contract that is below the subsistence threshold: {:?}", - account + account, ); 0u32.into() } diff --git a/frame/contracts/src/storage.rs b/frame/contracts/src/storage.rs index 2a2d5da225d61..72ecf20fd9750 100644 --- a/frame/contracts/src/storage.rs +++ b/frame/contracts/src/storage.rs @@ -32,7 +32,6 @@ use sp_core::crypto::UncheckedFrom; use frame_support::{ dispatch::DispatchResult, StorageMap, - debug, storage::{child::{self, KillOutcome}, StorageValue}, traits::Get, weights::Weight, @@ -271,7 +270,8 @@ where match outcome { // This should not happen as our budget was large enough to remove all keys. KillOutcome::SomeRemaining => { - debug::error!( + log::error!( + target: "runtime::contracts", "After deletion keys are remaining in this child trie: {:?}", removed.trie_id, ); diff --git a/frame/elections-phragmen/Cargo.toml b/frame/elections-phragmen/Cargo.toml index bdb301c73ec36..62e938bb11187 100644 --- a/frame/elections-phragmen/Cargo.toml +++ b/frame/elections-phragmen/Cargo.toml @@ -21,6 +21,7 @@ frame-support = { version = "3.0.0", default-features = false, path = "../suppor frame-system = { version = "3.0.0", default-features = false, path = "../system" } sp-std = { version = "3.0.0", default-features = false, path = "../../primitives/std" } frame-benchmarking = { version = "3.0.0", default-features = false, path = "../benchmarking", optional = true } +log = { version = "0.4.14", default-features = false } [dev-dependencies] sp-io = { version = "3.0.0", path = "../../primitives/io" } @@ -39,6 +40,7 @@ std = [ "sp-npos-elections/std", "frame-system/std", "sp-std/std", + "log/std", ] runtime-benchmarks = [ "frame-benchmarking", diff --git a/frame/elections-phragmen/src/lib.rs b/frame/elections-phragmen/src/lib.rs index 057e9f181c7af..d4676e98b823a 100644 --- a/frame/elections-phragmen/src/lib.rs +++ b/frame/elections-phragmen/src/lib.rs @@ -704,8 +704,9 @@ impl Module { } else { // overlap. This can never happen. If so, it seems like our intended replacement // is already a member, so not much more to do. - frame_support::debug::error!( - "pallet-elections-phragmen: a member seems to also be a runner-up." + log::error!( + target: "runtime::elections-phragmen", + "A member seems to also be a runner-up.", ); } next_best @@ -998,7 +999,11 @@ impl Module { Self::deposit_event(RawEvent::NewTerm(new_members_sorted_by_id)); ElectionRounds::mutate(|v| *v += 1); }).map_err(|e| { - frame_support::debug::error!("elections-phragmen: failed to run election [{:?}].", e); + log::error!( + target: "runtime::elections-phragmen", + "Failed to run election [{:?}].", + e, + ); Self::deposit_event(RawEvent::ElectionError); }); diff --git a/frame/elections-phragmen/src/migrations_3_0_0.rs b/frame/elections-phragmen/src/migrations_3_0_0.rs index 0737a12207c11..8adc4c1a69f7c 100644 --- a/frame/elections-phragmen/src/migrations_3_0_0.rs +++ b/frame/elections-phragmen/src/migrations_3_0_0.rs @@ -95,9 +95,10 @@ type Voting = StorageMap<__Voting, Twox64Concat, T::AccountId, Voter< /// with care and run at your own risk. pub fn apply(old_voter_bond: T::Balance, old_candidacy_bond: T::Balance) -> Weight { let maybe_storage_version = ::storage_version(); - frame_support::debug::info!( + log::info!( + target: "runtime::elections-phragmen", "Running migration for elections-phragmen with storage version {:?}", - maybe_storage_version + maybe_storage_version, ); match maybe_storage_version { Some(storage_version) if storage_version <= PalletVersion::new(2, 0, 0) => { @@ -108,9 +109,10 @@ pub fn apply(old_voter_bond: T::Balance, old_candidacy_bond: T::Balan Weight::max_value() } _ => { - frame_support::debug::warn!( + log::warn!( + target: "runtime::elections-phragmen", "Attempted to apply migration to V3 but failed because storage version is {:?}", - maybe_storage_version + maybe_storage_version, ); 0 }, @@ -129,7 +131,8 @@ pub fn migrate_voters_to_recorded_deposit(old_deposit: T::Balance) { }, ); - frame_support::debug::info!( + log::info!( + target: "runtime::elections-phragmen", "migrated {} voter accounts.", >::iter().count(), ); @@ -140,9 +143,10 @@ pub fn migrate_candidates_to_recorded_deposit(old_deposit: T::Balance let _ = >::translate::, _>( |maybe_old_candidates| { maybe_old_candidates.map(|old_candidates| { - frame_support::debug::info!( + log::info!( + target: "runtime::elections-phragmen", "migrated {} candidate accounts.", - old_candidates.len() + old_candidates.len(), ); old_candidates .into_iter() @@ -158,7 +162,11 @@ pub fn migrate_members_to_recorded_deposit(old_deposit: T::Balance) { let _ = >::translate::, _>( |maybe_old_members| { maybe_old_members.map(|old_members| { - frame_support::debug::info!("migrated {} member accounts.", old_members.len()); + log::info!( + target: "runtime::elections-phragmen", + "migrated {} member accounts.", + old_members.len(), + ); old_members .into_iter() .map(|(who, stake)| SeatHolder { @@ -177,9 +185,10 @@ pub fn migrate_runners_up_to_recorded_deposit(old_deposit: T::Balance let _ = >::translate::, _>( |maybe_old_runners_up| { maybe_old_runners_up.map(|old_runners_up| { - frame_support::debug::info!( + log::info!( + target: "runtime::elections-phragmen", "migrated {} runner-up accounts.", - old_runners_up.len() + old_runners_up.len(), ); old_runners_up .into_iter() diff --git a/frame/example-offchain-worker/Cargo.toml b/frame/example-offchain-worker/Cargo.toml index 5a2db258f8a19..44610333e92b7 100644 --- a/frame/example-offchain-worker/Cargo.toml +++ b/frame/example-offchain-worker/Cargo.toml @@ -23,6 +23,7 @@ sp-io = { version = "3.0.0", default-features = false, path = "../../primitives/ sp-runtime = { version = "3.0.0", default-features = false, path = "../../primitives/runtime" } sp-std = { version = "3.0.0", default-features = false, path = "../../primitives/std" } lite-json = { version = "0.1", default-features = false } +log = { version = "0.4.14", default-features = false } [features] default = ["std"] @@ -37,4 +38,5 @@ std = [ "sp-keystore", "sp-runtime/std", "sp-std/std", + "log/std", ] diff --git a/frame/example-offchain-worker/src/lib.rs b/frame/example-offchain-worker/src/lib.rs index dbcf7b10f4abd..019e7477a2b48 100644 --- a/frame/example-offchain-worker/src/lib.rs +++ b/frame/example-offchain-worker/src/lib.rs @@ -52,9 +52,7 @@ use frame_system::{ } }; use frame_support::{ - debug, - dispatch::DispatchResult, decl_module, decl_storage, decl_event, - traits::Get, + dispatch::DispatchResult, decl_module, decl_storage, decl_event, traits::Get, }; use sp_core::crypto::KeyTypeId; use sp_runtime::{ @@ -257,28 +255,25 @@ decl_module! { /// so the code should be able to handle that. /// You can use `Local Storage` API to coordinate runs of the worker. fn offchain_worker(block_number: T::BlockNumber) { - // It's a good idea to add logs to your offchain workers. - // Using the `frame_support::debug` module you have access to the same API exposed by - // the `log` crate. // Note that having logs compiled to WASM may cause the size of the blob to increase // significantly. You can use `RuntimeDebug` custom derive to hide details of the types - // in WASM or use `debug::native` namespace to produce logs only when the worker is - // running natively. - debug::native::info!("Hello World from offchain workers!"); + // in WASM. The `sp-api` crate also provides a feature `disable-logging` to disable + // all logging and thus, remove any logging from the WASM. + log::info!("Hello World from offchain workers!"); // Since off-chain workers are just part of the runtime code, they have direct access // to the storage and other included pallets. // // We can easily import `frame_system` and retrieve a block hash of the parent block. let parent_hash = >::block_hash(block_number - 1u32.into()); - debug::debug!("Current block: {:?} (parent hash: {:?})", block_number, parent_hash); + log::debug!("Current block: {:?} (parent hash: {:?})", block_number, parent_hash); // It's a good practice to keep `fn offchain_worker()` function minimal, and move most // of the code to separate `impl` block. // Here we call a helper function to calculate current average price. // This function reads storage entries of the current state. let average: Option = Self::average_price(); - debug::debug!("Current price: {:?}", average); + log::debug!("Current price: {:?}", average); // For this example we are going to send both signed and unsigned transactions // depending on the block number. @@ -292,7 +287,7 @@ decl_module! { TransactionType::None => Ok(()), }; if let Err(e) = res { - debug::error!("Error: {}", e); + log::error!("Error: {}", e); } } } @@ -409,8 +404,8 @@ impl Module { for (acc, res) in &results { match res { - Ok(()) => debug::info!("[{:?}] Submitted price of {} cents", acc.id, price), - Err(e) => debug::error!("[{:?}] Failed to submit transaction: {:?}", acc.id, e), + Ok(()) => log::info!("[{:?}] Submitted price of {} cents", acc.id, price), + Err(e) => log::error!("[{:?}] Failed to submit transaction: {:?}", acc.id, e), } } @@ -545,7 +540,7 @@ impl Module { .map_err(|_| http::Error::DeadlineReached)??; // Let's check the status code before we proceed to reading the response. if response.code != 200 { - debug::warn!("Unexpected status code: {}", response.code); + log::warn!("Unexpected status code: {}", response.code); return Err(http::Error::Unknown); } @@ -556,19 +551,19 @@ impl Module { // Create a str slice from the body. let body_str = sp_std::str::from_utf8(&body).map_err(|_| { - debug::warn!("No UTF8 body"); + log::warn!("No UTF8 body"); http::Error::Unknown })?; let price = match Self::parse_price(body_str) { Some(price) => Ok(price), None => { - debug::warn!("Unable to extract price from the response: {:?}", body_str); + log::warn!("Unable to extract price from the response: {:?}", body_str); Err(http::Error::Unknown) } }?; - debug::warn!("Got price: {} cents", price); + log::warn!("Got price: {} cents", price); Ok(price) } @@ -597,7 +592,7 @@ impl Module { /// Add new price to the list. fn add_price(who: T::AccountId, price: u32) { - debug::info!("Adding to the average: {}", price); + log::info!("Adding to the average: {}", price); Prices::mutate(|prices| { const MAX_LEN: usize = 64; @@ -610,7 +605,7 @@ impl Module { let average = Self::average_price() .expect("The average is not empty, because it was just mutated; qed"); - debug::info!("Current average price is: {}", average); + log::info!("Current average price is: {}", average); // here we are raising the NewPrice event Self::deposit_event(RawEvent::NewPrice(price, who)); } diff --git a/frame/executive/src/lib.rs b/frame/executive/src/lib.rs index df1ae17df613f..9a6c574c544bc 100644 --- a/frame/executive/src/lib.rs +++ b/frame/executive/src/lib.rs @@ -461,10 +461,6 @@ where // as well. frame_system::BlockHash::::insert(header.number(), header.hash()); - // Initialize logger, so the log messages are visible - // also when running WASM. - frame_support::debug::RuntimeLogger::init(); - >::offchain_worker(*header.number()) } } diff --git a/frame/grandpa/Cargo.toml b/frame/grandpa/Cargo.toml index a9ba0ccc56f3b..d9353c452f0f3 100644 --- a/frame/grandpa/Cargo.toml +++ b/frame/grandpa/Cargo.toml @@ -27,6 +27,7 @@ frame-support = { version = "3.0.0", default-features = false, path = "../suppor frame-system = { version = "3.0.0", default-features = false, path = "../system" } pallet-authorship = { version = "3.0.0", default-features = false, path = "../authorship" } pallet-session = { version = "3.0.0", default-features = false, path = "../session" } +log = { version = "0.4.14", default-features = false } [dev-dependencies] frame-benchmarking = { version = "3.0.0", path = "../benchmarking" } @@ -56,5 +57,6 @@ std = [ "frame-system/std", "pallet-authorship/std", "pallet-session/std", + "log/std", ] runtime-benchmarks = ["frame-benchmarking"] diff --git a/frame/grandpa/src/equivocation.rs b/frame/grandpa/src/equivocation.rs index b8bff59d3920c..37496fdeb8592 100644 --- a/frame/grandpa/src/equivocation.rs +++ b/frame/grandpa/src/equivocation.rs @@ -40,10 +40,7 @@ use sp_std::prelude::*; use codec::{self as codec, Decode, Encode}; -use frame_support::{ - debug, - traits::{Get, KeyOwnerProofSystem}, -}; +use frame_support::traits::{Get, KeyOwnerProofSystem}; use sp_finality_grandpa::{EquivocationProof, RoundNumber, SetId}; use sp_runtime::{ transaction_validity::{ @@ -174,8 +171,15 @@ where let call = Call::report_equivocation_unsigned(equivocation_proof, key_owner_proof); match SubmitTransaction::>::submit_unsigned_transaction(call.into()) { - Ok(()) => debug::info!("Submitted GRANDPA equivocation report."), - Err(e) => debug::error!("Error submitting equivocation report: {:?}", e), + Ok(()) => log::info!( + target: "runtime::afg", + "Submitted GRANDPA equivocation report.", + ), + Err(e) => log::error!( + target: "runtime::afg", + "Error submitting equivocation report: {:?}", + e, + ), } Ok(()) @@ -207,8 +211,8 @@ impl frame_support::unsigned::ValidateUnsigned for Module { match source { TransactionSource::Local | TransactionSource::InBlock => { /* allowed */ } _ => { - debug::warn!( - target: "afg", + log::warn!( + target: "runtime::afg", "rejecting unsigned report equivocation transaction because it is not local/in-block." ); diff --git a/frame/im-online/Cargo.toml b/frame/im-online/Cargo.toml index bde041c43764a..fad39a8ae2b7a 100644 --- a/frame/im-online/Cargo.toml +++ b/frame/im-online/Cargo.toml @@ -24,6 +24,7 @@ sp-runtime = { version = "3.0.0", default-features = false, path = "../../primit sp-staking = { version = "3.0.0", default-features = false, path = "../../primitives/staking" } frame-support = { version = "3.0.0", default-features = false, path = "../support" } frame-system = { version = "3.0.0", default-features = false, path = "../system" } +log = { version = "0.4.14", default-features = false } frame-benchmarking = { version = "3.0.0", default-features = false, path = "../benchmarking", optional = true } @@ -44,5 +45,6 @@ std = [ "sp-staking/std", "frame-support/std", "frame-system/std", + "log/std", ] runtime-benchmarks = ["frame-benchmarking"] diff --git a/frame/im-online/src/lib.rs b/frame/im-online/src/lib.rs index bd597acfb1ed5..b37273c05bce9 100644 --- a/frame/im-online/src/lib.rs +++ b/frame/im-online/src/lib.rs @@ -93,7 +93,7 @@ use sp_staking::{ offence::{ReportOffence, Offence, Kind}, }; use frame_support::{ - decl_module, decl_event, decl_storage, Parameter, debug, decl_error, + decl_module, decl_event, decl_storage, Parameter, decl_error, traits::{Get, ValidatorSet, ValidatorSetWithIdentification, OneSessionHandler}, }; use frame_system::ensure_none; @@ -388,8 +388,8 @@ decl_module! { if sp_io::offchain::is_validator() { for res in Self::send_heartbeats(now).into_iter().flatten() { if let Err(e) = res { - debug::debug!( - target: "imonline", + log::debug!( + target: "runtime::im-online", "Skipping heartbeat at {:?}: {:?}", now, e, @@ -397,8 +397,8 @@ decl_module! { } } } else { - debug::trace!( - target: "imonline", + log::trace!( + target: "runtime::im-online", "Skipping heartbeat at {:?}. Not a validator.", now, ) @@ -529,7 +529,7 @@ impl Module { block_number, || { let call = prepare_heartbeat()?; - debug::info!( + log::info!( target: "imonline", "[index: {:?}] Reporting im-online at block: {:?} (session: {:?}): {:?}", authority_index, diff --git a/frame/merkle-mountain-range/primitives/Cargo.toml b/frame/merkle-mountain-range/primitives/Cargo.toml index be0a8bdc3a2bb..62a6f4ff1cde8 100644 --- a/frame/merkle-mountain-range/primitives/Cargo.toml +++ b/frame/merkle-mountain-range/primitives/Cargo.toml @@ -20,6 +20,7 @@ sp-api = { version = "3.0.0", default-features = false, path = "../../../primiti sp-core = { version = "3.0.0", default-features = false, path = "../../../primitives/core" } sp-runtime = { version = "3.0.0", default-features = false, path = "../../../primitives/runtime" } sp-std = { version = "3.0.0", default-features = false, path = "../../../primitives/std" } +log = { version = "0.4.14", default-features = false } [dev-dependencies] hex-literal = "0.3" @@ -35,4 +36,5 @@ std = [ "sp-core/std", "sp-runtime/std", "sp-std/std", + "log/std", ] diff --git a/frame/merkle-mountain-range/primitives/src/lib.rs b/frame/merkle-mountain-range/primitives/src/lib.rs index d57f8565b6081..f1ee15b48b3fe 100644 --- a/frame/merkle-mountain-range/primitives/src/lib.rs +++ b/frame/merkle-mountain-range/primitives/src/lib.rs @@ -20,7 +20,7 @@ #![cfg_attr(not(feature = "std"), no_std)] #![warn(missing_docs)] -use frame_support::{RuntimeDebug, debug}; +use frame_support::RuntimeDebug; use sp_runtime::traits::{self, Saturating, One}; use sp_std::fmt; #[cfg(not(feature = "std"))] @@ -307,13 +307,23 @@ impl Error { #![allow(unused_variables)] /// Consume given error `e` with `self` and generate a native log entry with error details. pub fn log_error(self, e: impl fmt::Debug) -> Self { - debug::native::error!("[{:?}] MMR error: {:?}", self, e); + log::error!( + target: "runtime::mmr", + "[{:?}] MMR error: {:?}", + self, + e, + ); self } /// Consume given error `e` with `self` and generate a native log entry with error details. pub fn log_debug(self, e: impl fmt::Debug) -> Self { - debug::native::debug!("[{:?}] MMR error: {:?}", self, e); + log::debug!( + target: "runtime::mmr", + "[{:?}] MMR error: {:?}", + self, + e, + ); self } } diff --git a/frame/node-authorization/Cargo.toml b/frame/node-authorization/Cargo.toml index db77f25c18871..c49614a788c24 100644 --- a/frame/node-authorization/Cargo.toml +++ b/frame/node-authorization/Cargo.toml @@ -20,6 +20,7 @@ sp-core = { version = "3.0.0", default-features = false, path = "../../primitive sp-io = { version = "3.0.0", default-features = false, path = "../../primitives/io" } sp-runtime = { version = "3.0.0", default-features = false, path = "../../primitives/runtime" } sp-std = { version = "3.0.0", default-features = false, path = "../../primitives/std" } +log = { version = "0.4.14", default-features = false } [features] default = ["std"] @@ -32,4 +33,5 @@ std = [ "sp-io/std", "sp-runtime/std", "sp-std/std", + "log/std", ] diff --git a/frame/node-authorization/src/lib.rs b/frame/node-authorization/src/lib.rs index f1f70e9eacd4b..090be28492630 100644 --- a/frame/node-authorization/src/lib.rs +++ b/frame/node-authorization/src/lib.rs @@ -46,9 +46,7 @@ use sp_std::{ use codec::Decode; use frame_support::{ decl_module, decl_storage, decl_event, decl_error, - debug, ensure, - weights::{DispatchClass, Weight}, - traits::{Get, EnsureOrigin}, + ensure, weights::{DispatchClass, Weight}, traits::{Get, EnsureOrigin}, }; use frame_system::ensure_signed; @@ -387,11 +385,19 @@ decl_module! { fn offchain_worker(now: T::BlockNumber) { let network_state = sp_io::offchain::network_state(); match network_state { - Err(_) => debug::error!("Error: failed to get network state of node at {:?}", now), + Err(_) => log::error!( + target: "runtime::node-authorization", + "Error: failed to get network state of node at {:?}", + now, + ), Ok(state) => { let encoded_peer = state.peer_id.0; match Decode::decode(&mut &encoded_peer[..]) { - Err(_) => debug::error!("Error: failed to decode PeerId at {:?}", now), + Err(_) => log::error!( + target: "runtime::node-authorization", + "Error: failed to decode PeerId at {:?}", + now, + ), Ok(node) => sp_io::offchain::set_authorized_nodes( Self::get_authorized_nodes(&PeerId(node)), true diff --git a/frame/offences/Cargo.toml b/frame/offences/Cargo.toml index 3232d5f3ae5dd..7665dd72fd643 100644 --- a/frame/offences/Cargo.toml +++ b/frame/offences/Cargo.toml @@ -21,6 +21,7 @@ sp-runtime = { version = "3.0.0", default-features = false, path = "../../primit sp-staking = { version = "3.0.0", default-features = false, path = "../../primitives/staking" } frame-support = { version = "3.0.0", default-features = false, path = "../support" } frame-system = { version = "3.0.0", default-features = false, path = "../system" } +log = { version = "0.4.14", default-features = false } [dev-dependencies] sp-io = { version = "3.0.0", path = "../../primitives/io" } @@ -37,5 +38,6 @@ std = [ "sp-staking/std", "frame-support/std", "frame-system/std", + "log/std", ] runtime-benchmarks = [] diff --git a/frame/offences/src/lib.rs b/frame/offences/src/lib.rs index 5c1247853da1a..2765c0aaa0ea6 100644 --- a/frame/offences/src/lib.rs +++ b/frame/offences/src/lib.rs @@ -27,9 +27,7 @@ mod tests; use sp_std::vec::Vec; use frame_support::{ - decl_module, decl_event, decl_storage, Parameter, debug, - traits::Get, - weights::Weight, + decl_module, decl_event, decl_storage, Parameter, traits::Get, weights::Weight, }; use sp_runtime::{traits::{Hash, Zero}, Perbill}; use sp_staking::{ @@ -141,9 +139,10 @@ decl_module! { false }, Err(_) => { - debug::native::error!( - target: "pallet-offences", - "re-submitting a deferred slash returned Err at {}. This should not happen with pallet-staking", + log::error!( + target: "runtime::offences", + "re-submitting a deferred slash returned Err at {:?}. \ + This should not happen with pallet-staking", now, ); true diff --git a/frame/scheduler/Cargo.toml b/frame/scheduler/Cargo.toml index eef287d86771b..cbd80393ccf47 100644 --- a/frame/scheduler/Cargo.toml +++ b/frame/scheduler/Cargo.toml @@ -17,6 +17,7 @@ frame-system = { version = "3.0.0", default-features = false, path = "../system" sp-runtime = { version = "3.0.0", default-features = false, path = "../../primitives/runtime" } sp-std = { version = "3.0.0", default-features = false, path = "../../primitives/std" } sp-io = { version = "3.0.0", default-features = false, path = "../../primitives/io" } +log = { version = "0.4.14", default-features = false } frame-benchmarking = { version = "3.0.0", default-features = false, path = "../benchmarking", optional = true } @@ -34,7 +35,8 @@ std = [ "frame-support/std", "frame-system/std", "sp-io/std", - "sp-std/std" + "sp-std/std", + "log/std", ] runtime-benchmarks = [ "frame-benchmarking", diff --git a/frame/scheduler/src/lib.rs b/frame/scheduler/src/lib.rs index a869fae27d8b3..5cab10b0aff38 100644 --- a/frame/scheduler/src/lib.rs +++ b/frame/scheduler/src/lib.rs @@ -333,7 +333,8 @@ decl_module! { .filter_map(|(index, s)| s.map(|inner| (index as u32, inner))) .collect::>(); if queued.len() as u32 > T::MaxScheduledPerBlock::get() { - frame_support::debug::warn!( + log::warn!( + target: "runtime::scheduler", "Warning: This block has more items queued in Scheduler than \ expected from the runtime configuration. An update might be needed." ); @@ -500,9 +501,10 @@ impl Module { Agenda::::append(when, s); let index = Agenda::::decode_len(when).unwrap_or(1) as u32 - 1; if index > T::MaxScheduledPerBlock::get() { - frame_support::debug::warn!( + log::warn!( + target: "runtime::scheduler", "Warning: There are more items queued in the Scheduler than \ - expected from the runtime configuration. An update might be needed." + expected from the runtime configuration. An update might be needed.", ); } Self::deposit_event(RawEvent::Scheduled(when, index)); @@ -590,9 +592,10 @@ impl Module { Agenda::::append(when, Some(s)); let index = Agenda::::decode_len(when).unwrap_or(1) as u32 - 1; if index > T::MaxScheduledPerBlock::get() { - frame_support::debug::warn!( + log::warn!( + target: "runtime::scheduler", "Warning: There are more items queued in the Scheduler than \ - expected from the runtime configuration. An update might be needed." + expected from the runtime configuration. An update might be needed.", ); } let address = (when, index); diff --git a/frame/staking/Cargo.toml b/frame/staking/Cargo.toml index c5f7dba075455..78651e3221574 100644 --- a/frame/staking/Cargo.toml +++ b/frame/staking/Cargo.toml @@ -26,6 +26,7 @@ frame-system = { version = "3.0.0", default-features = false, path = "../system" pallet-session = { version = "3.0.0", default-features = false, features = ["historical"], path = "../session" } pallet-authorship = { version = "3.0.0", default-features = false, path = "../authorship" } sp-application-crypto = { version = "3.0.0", default-features = false, path = "../../primitives/application-crypto" } +log = { version = "0.4.14", default-features = false } # Optional imports for benchmarking frame-benchmarking = { version = "3.0.0", default-features = false, path = "../benchmarking", optional = true } @@ -59,6 +60,7 @@ std = [ "frame-system/std", "pallet-authorship/std", "sp-application-crypto/std", + "log/std", ] runtime-benchmarks = [ "frame-benchmarking", diff --git a/frame/staking/src/lib.rs b/frame/staking/src/lib.rs index 3ea66e937e83c..8a4f6a86d3f41 100644 --- a/frame/staking/src/lib.rs +++ b/frame/staking/src/lib.rs @@ -337,13 +337,13 @@ const STAKING_ID: LockIdentifier = *b"staking "; pub const MAX_UNLOCKING_CHUNKS: usize = 32; pub const MAX_NOMINATIONS: usize = ::LIMIT; -pub(crate) const LOG_TARGET: &'static str = "staking"; +pub(crate) const LOG_TARGET: &'static str = "runtime::staking"; // syntactic sugar for logging. #[macro_export] macro_rules! log { ($level:tt, $patter:expr $(, $values:expr)* $(,)?) => { - frame_support::debug::$level!( + log::$level!( target: crate::LOG_TARGET, $patter $(, $values)* ) @@ -3189,29 +3189,29 @@ impl Module { /// some session can lag in between the newest session planned and the latest session started. impl pallet_session::SessionManager for Module { fn new_session(new_index: SessionIndex) -> Option> { - frame_support::debug::native::trace!( - target: LOG_TARGET, - "[{}] planning new_session({})", + log!( + trace, + "[{:?}] planning new_session({})", >::block_number(), - new_index + new_index, ); Self::new_session(new_index) } fn start_session(start_index: SessionIndex) { - frame_support::debug::native::trace!( - target: LOG_TARGET, - "[{}] starting start_session({})", + log!( + trace, + "[{:?}] starting start_session({})", >::block_number(), - start_index + start_index, ); Self::start_session(start_index) } fn end_session(end_index: SessionIndex) { - frame_support::debug::native::trace!( - target: LOG_TARGET, - "[{}] ending end_session({})", + log!( + trace, + "[{:?}] ending end_session({})", >::block_number(), - end_index + end_index, ); Self::end_session(end_index) } diff --git a/frame/support/Cargo.toml b/frame/support/Cargo.toml index 8edf1ff6ddadc..0a55b08e59a15 100644 --- a/frame/support/Cargo.toml +++ b/frame/support/Cargo.toml @@ -13,7 +13,6 @@ readme = "README.md" targets = ["x86_64-unknown-linux-gnu"] [dependencies] -log = "0.4" serde = { version = "1.0.101", optional = true, features = ["derive"] } codec = { package = "parity-scale-codec", version = "2.0.0", default-features = false, features = ["derive"] } frame-metadata = { version = "13.0.0", default-features = false, path = "../metadata" } @@ -32,13 +31,12 @@ sp-state-machine = { version = "0.9.0", optional = true, path = "../../primitive bitflags = "1.2" impl-trait-for-tuples = "0.2.1" smallvec = "1.4.1" +log = { version = "0.4.14", default-features = false } [dev-dependencies] pretty_assertions = "0.6.1" frame-system = { version = "3.0.0", path = "../system" } parity-util-mem = { version = "0.9.0", default-features = false, features = ["primitive-types"] } -substrate-test-runtime-client = { version = "2.0.0", path = "../../test-utils/runtime/client" } -sp-api = { version = "3.0.0", default-features = false, path = "../../primitives/api" } [features] default = ["std"] @@ -56,7 +54,6 @@ std = [ "sp-staking/std", "sp-state-machine", "frame-support-procedural/std", + "log/std", ] -nightly = [] -strict = [] runtime-benchmarks = [] diff --git a/frame/support/src/debug.rs b/frame/support/src/debug.rs deleted file mode 100644 index 43efd3d91623e..0000000000000 --- a/frame/support/src/debug.rs +++ /dev/null @@ -1,247 +0,0 @@ -// This file is part of Substrate. - -// Copyright (C) 2019-2021 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. - -//! Runtime debugging and logging utilities. -//! -//! This module contains macros and functions that will allow -//! you to print logs out of the runtime code. -//! -//! First and foremost be aware that adding regular logging code to -//! your runtime will have a negative effect on the performance -//! and size of the blob. Luckily there are some ways to mitigate -//! this that are described below. -//! -//! First component to utilize debug-printing and logging is actually -//! located in `primitives` crate: `sp_core::RuntimeDebug`. -//! This custom-derive generates `core::fmt::Debug` implementation, -//! just like regular `derive(Debug)`, however it does not generate -//! any code when the code is compiled to WASM. This means that -//! you can safely sprinkle `RuntimeDebug` in your runtime codebase, -//! without affecting the size. This also allows you to print/log -//! both when the code is running natively or in WASM, but note -//! that WASM debug formatting of structs will be empty. -//! -//! ```rust,no_run -//! use frame_support::debug; -//! -//! #[derive(sp_core::RuntimeDebug)] -//! struct MyStruct { -//! a: u64, -//! } -//! -//! // First initialize the logger. -//! // -//! // This is only required when you want the logs to be printed -//! // also during non-native run. -//! // Note that enabling the logger has performance impact on -//! // WASM runtime execution and should be used sparingly. -//! debug::RuntimeLogger::init(); -//! -//! let x = MyStruct { a: 5 }; -//! // will log an info line `"My struct: MyStruct{a:5}"` when running -//! // natively, but will only print `"My struct: "` when running WASM. -//! debug::info!("My struct: {:?}", x); -//! -//! // same output here, although this will print to stdout -//! // (and without log format) -//! debug::print!("My struct: {:?}", x); -//! ``` -//! -//! If you want to avoid extra overhead in WASM, but still be able -//! to print / log when the code is executed natively you can use -//! macros coming from `native` sub-module. This module enables -//! logs conditionally and strips out logs in WASM. -//! -//! ```rust,no_run -//! use frame_support::debug::native; -//! -//! #[derive(sp_core::RuntimeDebug)] -//! struct MyStruct { -//! a: u64, -//! } -//! -//! // We don't initialize the logger, since -//! // we are not printing anything out in WASM. -//! // debug::RuntimeLogger::init(); -//! -//! let x = MyStruct { a: 5 }; -//! -//! // Displays an info log when running natively, nothing when WASM. -//! native::info!("My struct: {:?}", x); -//! -//! // same output to stdout, no overhead on WASM. -//! native::print!("My struct: {:?}", x); -//! ``` - -use sp_std::fmt::{self, Debug}; - -pub use log::{info, debug, error, trace, warn}; -pub use crate::runtime_print as print; -pub use sp_std::Writer; - -/// Native-only logging. -/// -/// Using any functions from this module will have any effect -/// only if the runtime is running natively (i.e. not via WASM) -#[cfg(feature = "std")] -pub mod native { - pub use super::{info, debug, error, trace, warn, print}; -} - -/// Native-only logging. -/// -/// Using any functions from this module will have any effect -/// only if the runtime is running natively (i.e. not via WASM) -#[cfg(not(feature = "std"))] -pub mod native { - #[macro_export] - macro_rules! noop { - ($($arg:tt)+) => {} - } - pub use noop as info; - pub use noop as debug; - pub use noop as error; - pub use noop as trace; - pub use noop as warn; - pub use noop as print; -} - -/// Print out a formatted message. -/// -/// # Example -/// -/// ``` -/// frame_support::runtime_print!("my value is {}", 3); -/// ``` -#[macro_export] -macro_rules! runtime_print { - ($($arg:tt)+) => { - { - use core::fmt::Write; - let mut w = $crate::sp_std::Writer::default(); - let _ = core::write!(&mut w, $($arg)+); - $crate::sp_io::misc::print_utf8(&w.inner()) - } - } -} - -/// Print out the debuggable type. -pub fn debug(data: &impl Debug) { - runtime_print!("{:?}", data); -} - -/// Runtime logger implementation - `log` crate backend. -/// -/// The logger should be initialized if you want to display -/// logs inside the runtime that is not necessarily running natively. -/// -/// When runtime is executed natively any log statements are displayed -/// even if this logger is NOT initialized. -/// -/// Note that even though the logs are not displayed in WASM, they -/// may still affect the size and performance of the generated runtime. -/// To lower the footprint make sure to only use macros from `native` -/// sub-module. -pub struct RuntimeLogger; - -impl RuntimeLogger { - /// Initialize the logger. - /// - /// This is a no-op when running natively (`std`). - #[cfg(feature = "std")] - pub fn init() {} - - /// Initialize the logger. - /// - /// This is a no-op when running natively (`std`). - #[cfg(not(feature = "std"))] - pub fn init() { - static LOGGER: RuntimeLogger = RuntimeLogger; - let _ = log::set_logger(&LOGGER); - - // Set max level to `TRACE` to ensure we propagate - // all log entries to the native side that will do the - // final filtering on what should be printed. - // - // If we don't set any level, logging is disabled - // completly. - log::set_max_level(log::LevelFilter::Trace); - } -} - -impl log::Log for RuntimeLogger { - fn enabled(&self, _metadata: &log::Metadata) -> bool { - // to avoid calling to host twice, we pass everything - // and let the host decide what to print. - // If someone is initializing the logger they should - // know what they are doing. - true - } - - fn log(&self, record: &log::Record) { - use fmt::Write; - let mut w = sp_std::Writer::default(); - let _ = core::write!(&mut w, "{}", record.args()); - - sp_io::logging::log( - record.level().into(), - record.target(), - w.inner(), - ); - } - - fn flush(&self) {} -} - -#[cfg(test)] -mod tests { - use substrate_test_runtime_client::{ - ExecutionStrategy, TestClientBuilderExt, DefaultTestClientBuilderExt, - TestClientBuilder, runtime::TestAPI, - }; - use sp_api::ProvideRuntimeApi; - use sp_runtime::generic::BlockId; - - #[test] - fn ensure_runtime_logger_works() { - let executable = std::env::current_exe().unwrap(); - let output = std::process::Command::new(executable) - .env("RUN_TEST", "1") - .env("RUST_LOG", "trace") - .args(&["--nocapture", "ensure_runtime_logger_works_implementation"]) - .output() - .unwrap(); - - let output = dbg!(String::from_utf8(output.stderr).unwrap()); - assert!(output.contains("Hey I'm runtime")); - } - - /// This is no actual test. It will be called by `ensure_runtime_logger_works` - /// to check that the runtime can print from the wasm side using the - /// `RuntimeLogger`. - #[test] - fn ensure_runtime_logger_works_implementation() { - if std::env::var("RUN_TEST").is_ok() { - sp_tracing::try_init_simple(); - - let client = TestClientBuilder::new().set_execution_strategy(ExecutionStrategy::AlwaysWasm).build(); - let runtime_api = client.runtime_api(); - let block_id = BlockId::Number(0); - runtime_api.do_trace_log(&block_id).expect("Logging should not fail"); - } - } -} diff --git a/frame/support/src/hash.rs b/frame/support/src/hash.rs index 0a8be8aec035a..22ccbeb6ceee3 100644 --- a/frame/support/src/hash.rs +++ b/frame/support/src/hash.rs @@ -102,7 +102,7 @@ impl StorageHasher for Twox64Concat { impl ReversibleStorageHasher for Twox64Concat { fn reverse(x: &[u8]) -> &[u8] { if x.len() < 8 { - crate::debug::error!("Invalid reverse: hash length too short"); + log::error!("Invalid reverse: hash length too short"); return &[] } &x[8..] @@ -125,7 +125,7 @@ impl StorageHasher for Blake2_128Concat { impl ReversibleStorageHasher for Blake2_128Concat { fn reverse(x: &[u8]) -> &[u8] { if x.len() < 16 { - crate::debug::error!("Invalid reverse: hash length too short"); + log::error!("Invalid reverse: hash length too short"); return &[] } &x[16..] diff --git a/frame/support/src/lib.rs b/frame/support/src/lib.rs index fc7939fe3010b..c318efa159c09 100644 --- a/frame/support/src/lib.rs +++ b/frame/support/src/lib.rs @@ -45,8 +45,6 @@ pub use sp_io::{storage::root as storage_root, self}; #[doc(hidden)] pub use sp_runtime::RuntimeDebug; -#[macro_use] -pub mod debug; #[macro_use] mod origin; #[macro_use] @@ -337,6 +335,30 @@ macro_rules! ord_parameter_types { } } +/// Print out a formatted message. +/// +/// # Example +/// +/// ``` +/// frame_support::runtime_print!("my value is {}", 3); +/// ``` +#[macro_export] +macro_rules! runtime_print { + ($($arg:tt)+) => { + { + use core::fmt::Write; + let mut w = $crate::sp_std::Writer::default(); + let _ = core::write!(&mut w, $($arg)+); + $crate::sp_io::misc::print_utf8(&w.inner()) + } + } +} + +/// Print out the debuggable type. +pub fn debug(data: &impl sp_std::fmt::Debug) { + runtime_print!("{:?}", data); +} + #[doc(inline)] pub use frame_support_procedural::{ decl_storage, construct_runtime, transactional, RuntimeDebugNoBound @@ -1048,7 +1070,7 @@ pub mod pallet_prelude { pub use frame_support::traits::GenesisBuild; pub use frame_support::{ EqNoBound, PartialEqNoBound, RuntimeDebugNoBound, DebugNoBound, CloneNoBound, Twox256, - Twox128, Blake2_256, Blake2_128, Identity, Twox64Concat, Blake2_128Concat, debug, ensure, + Twox128, Blake2_256, Blake2_128, Identity, Twox64Concat, Blake2_128Concat, ensure, RuntimeDebug, storage, traits::{Get, Hooks, IsType, GetPalletVersion, EnsureOrigin}, dispatch::{DispatchResultWithPostInfo, Parameter, DispatchError}, diff --git a/frame/support/src/storage/child.rs b/frame/support/src/storage/child.rs index c1885fc074307..ca635a4f1d1b5 100644 --- a/frame/support/src/storage/child.rs +++ b/frame/support/src/storage/child.rs @@ -47,7 +47,11 @@ pub fn get( ).and_then(|v| { Decode::decode(&mut &v[..]).map(Some).unwrap_or_else(|_| { // TODO #3700: error should be handleable. - runtime_print!("ERROR: Corrupted state in child trie at {:?}/{:?}", storage_key, key); + crate::runtime_print!( + "ERROR: Corrupted state in child trie at {:?}/{:?}", + storage_key, + key, + ); None }) }) diff --git a/frame/support/src/storage/generator/double_map.rs b/frame/support/src/storage/generator/double_map.rs index 7e1a2456e4536..c02ebe48290eb 100644 --- a/frame/support/src/storage/generator/double_map.rs +++ b/frame/support/src/storage/generator/double_map.rs @@ -393,7 +393,7 @@ impl< let value = match unhashed::get::(&previous_key) { Some(value) => value, None => { - crate::debug::error!("Invalid translate: fail to decode old value"); + log::error!("Invalid translate: fail to decode old value"); continue }, }; @@ -401,7 +401,7 @@ impl< let key1 = match K1::decode(&mut key_material) { Ok(key1) => key1, Err(_) => { - crate::debug::error!("Invalid translate: fail to decode key1"); + log::error!("Invalid translate: fail to decode key1"); continue }, }; @@ -410,7 +410,7 @@ impl< let key2 = match K2::decode(&mut key2_material) { Ok(key2) => key2, Err(_) => { - crate::debug::error!("Invalid translate: fail to decode key2"); + log::error!("Invalid translate: fail to decode key2"); continue }, }; diff --git a/frame/support/src/storage/generator/map.rs b/frame/support/src/storage/generator/map.rs index 7f6eb2a518f57..9abc7883937dd 100644 --- a/frame/support/src/storage/generator/map.rs +++ b/frame/support/src/storage/generator/map.rs @@ -172,7 +172,7 @@ impl< let value = match unhashed::get::(&previous_key) { Some(value) => value, None => { - crate::debug::error!("Invalid translate: fail to decode old value"); + log::error!("Invalid translate: fail to decode old value"); continue }, }; @@ -181,7 +181,7 @@ impl< let key = match K::decode(&mut key_material) { Ok(key) => key, Err(_) => { - crate::debug::error!("Invalid translate: fail to decode key"); + log::error!("Invalid translate: fail to decode key"); continue }, }; diff --git a/frame/support/src/storage/mod.rs b/frame/support/src/storage/mod.rs index 93cf7c6639064..d9820475a7e88 100644 --- a/frame/support/src/storage/mod.rs +++ b/frame/support/src/storage/mod.rs @@ -62,7 +62,7 @@ mod debug_helper { let mut val = v.borrow_mut(); *val += 1; if *val > 10 { - crate::debug::warn!( + log::warn!( "Detected with_transaction with nest level {}. Nested usage of with_transaction is not recommended.", *val ); @@ -532,9 +532,9 @@ impl Iterator for PrefixIterator { let raw_value = match unhashed::get_raw(&self.previous_key) { Some(raw_value) => raw_value, None => { - crate::debug::error!( + log::error!( "next_key returned a key with no value at {:?}", - self.previous_key + self.previous_key, ); continue } @@ -546,9 +546,10 @@ impl Iterator for PrefixIterator { let item = match (self.closure)(raw_key_without_prefix, &raw_value[..]) { Ok(item) => item, Err(e) => { - crate::debug::error!( + log::error!( "(key, value) failed to decode at {:?}: {:?}", - self.previous_key, e + self.previous_key, + e, ); continue } @@ -628,9 +629,9 @@ pub trait StoragePrefixedMap { None => unhashed::kill(&previous_key), }, None => { - crate::debug::error!( + log::error!( "old key failed to decode at {:?}", - previous_key + previous_key, ); continue }, diff --git a/frame/support/src/storage/unhashed.rs b/frame/support/src/storage/unhashed.rs index 8ac4240a9f0e9..d3d54f3de5795 100644 --- a/frame/support/src/storage/unhashed.rs +++ b/frame/support/src/storage/unhashed.rs @@ -25,7 +25,7 @@ pub fn get(key: &[u8]) -> Option { sp_io::storage::get(key).and_then(|val| { Decode::decode(&mut &val[..]).map(Some).unwrap_or_else(|_| { // TODO #3700: error should be handleable. - runtime_print!("ERROR: Corrupted state at {:?}", key); + crate::runtime_print!("ERROR: Corrupted state at {:?}", key); None }) }) diff --git a/frame/system/Cargo.toml b/frame/system/Cargo.toml index c4530e9dfd09f..494001f92c899 100644 --- a/frame/system/Cargo.toml +++ b/frame/system/Cargo.toml @@ -22,6 +22,7 @@ sp-runtime = { version = "3.0.0", default-features = false, path = "../../primit sp-version = { version = "3.0.0", default-features = false, path = "../../primitives/version" } frame-support = { version = "3.0.0", default-features = false, path = "../support" } impl-trait-for-tuples = "0.2.1" +log = { version = "0.4.14", default-features = false } [dev-dependencies] criterion = "0.3.3" @@ -39,6 +40,7 @@ std = [ "frame-support/std", "sp-runtime/std", "sp-version/std", + "log/std", ] runtime-benchmarks = [ "sp-runtime/runtime-benchmarks", diff --git a/frame/system/src/lib.rs b/frame/system/src/lib.rs index e521a082a91ca..e4ae28b8875ef 100644 --- a/frame/system/src/lib.rs +++ b/frame/system/src/lib.rs @@ -85,7 +85,7 @@ use sp_runtime::{ use sp_core::{ChangesTrieConfiguration, storage::well_known_keys}; use frame_support::{ - Parameter, debug, storage, + Parameter, storage, traits::{ Contains, Get, PalletInfo, OnNewAccount, OnKilledAccount, HandleLifetime, StoredMap, EnsureOrigin, OriginTrait, Filter, @@ -1046,7 +1046,10 @@ impl Module { (0, _) => { // Logic error - cannot decrement beyond zero and no item should // exist with zero providers. - debug::print!("Logic error: Unexpected underflow in reducing provider"); + log::error!( + target: "runtime::system", + "Logic error: Unexpected underflow in reducing provider", + ); Ok(DecRefStatus::Reaped) }, (1, 0) => { @@ -1064,7 +1067,10 @@ impl Module { } } } else { - debug::print!("Logic error: Account already dead when reducing provider"); + log::error!( + target: "runtime::system", + "Logic error: Account already dead when reducing provider", + ); Ok(DecRefStatus::Reaped) } }) @@ -1093,7 +1099,10 @@ impl Module { Account::::mutate(who, |a| if a.consumers > 0 { a.consumers -= 1; } else { - debug::print!("Logic error: Unexpected underflow in reducing consumer"); + log::error!( + target: "runtime::system", + "Logic error: Unexpected underflow in reducing consumer", + ); }) } diff --git a/frame/system/src/offchain.rs b/frame/system/src/offchain.rs index f2f446913c477..aa8bce966192e 100644 --- a/frame/system/src/offchain.rs +++ b/frame/system/src/offchain.rs @@ -63,7 +63,7 @@ use sp_std::convert::{TryInto, TryFrom}; use sp_std::prelude::{Box, Vec}; use sp_runtime::app_crypto::RuntimeAppPublic; use sp_runtime::traits::{Extrinsic as ExtrinsicT, IdentifyAccount, One}; -use frame_support::{debug, RuntimeDebug}; +use frame_support::RuntimeDebug; /// Marker struct used to flag using all supported keys to sign a payload. pub struct ForAll {} @@ -550,8 +550,8 @@ pub trait SendSignedTransaction< call: LocalCall, ) -> Option> { let mut account_data = crate::Account::::get(&account.id); - debug::native::debug!( - target: "offchain", + log::debug!( + target: "runtime::offchain", "Creating signed transaction from account: {:?} (nonce: {:?})", account.id, account_data.nonce, diff --git a/frame/timestamp/Cargo.toml b/frame/timestamp/Cargo.toml index f4f7bbda0f885..b68c755dfd19d 100644 --- a/frame/timestamp/Cargo.toml +++ b/frame/timestamp/Cargo.toml @@ -26,6 +26,7 @@ frame-support = { version = "3.0.0", default-features = false, path = "../suppor frame-system = { version = "3.0.0", default-features = false, path = "../system" } sp-timestamp = { version = "3.0.0", default-features = false, path = "../../primitives/timestamp" } impl-trait-for-tuples = "0.2.1" +log = { version = "0.4.14", default-features = false } [dev-dependencies] sp-io ={ version = "3.0.0", path = "../../primitives/io" } @@ -42,6 +43,7 @@ std = [ "frame-support/std", "serde", "frame-system/std", - "sp-timestamp/std" + "sp-timestamp/std", + "log/std", ] runtime-benchmarks = ["frame-benchmarking", "sp-io"] diff --git a/frame/timestamp/src/lib.rs b/frame/timestamp/src/lib.rs index 86ca0c11a70c8..0deef258ed5bd 100644 --- a/frame/timestamp/src/lib.rs +++ b/frame/timestamp/src/lib.rs @@ -97,8 +97,6 @@ pub mod weights; use sp_std::{result, cmp}; use sp_inherents::InherentData; -#[cfg(feature = "std")] -use frame_support::debug; use frame_support::traits::{Time, UnixTime}; use sp_runtime::{ RuntimeString, @@ -287,8 +285,9 @@ impl UnixTime for Pallet { let now = Self::now(); sp_std::if_std! { if now == T::Moment::zero() { - debug::error!( - "`pallet_timestamp::UnixTime::now` is called at genesis, invalid value returned: 0" + log::error!( + target: "runtime::timestamp", + "`pallet_timestamp::UnixTime::now` is called at genesis, invalid value returned: 0", ); } } diff --git a/primitives/api/Cargo.toml b/primitives/api/Cargo.toml index 20987035ef2f0..c9ce83e8b2f51 100644 --- a/primitives/api/Cargo.toml +++ b/primitives/api/Cargo.toml @@ -23,6 +23,9 @@ sp-state-machine = { version = "0.9.0", optional = true, path = "../state-machin hash-db = { version = "0.15.2", optional = true } thiserror = { version = "1.0.21", optional = true } +tracing = { version = "0.1.22", default-features = false } +log = { version = "0.4.14", default-features = false } + [dev-dependencies] sp-test-primitives = { version = "2.0.0", path = "../test-primitives" } @@ -37,4 +40,17 @@ std = [ "sp-version/std", "hash-db", "thiserror", + "log/std", + "tracing/std", +] +# Special feature to disable logging completly. +# +# By default `sp-api` initializes the `RuntimeLogger` for each runtime api function. However, +# logging functionality increases the code size. It is recommended to enable this feature when +# building a runtime for registering it on chain. +# +# This sets the max logging level to `off` for `tracing` and `log`. +disable-logging = [ + "tracing/max_level_off", + "log/max_level_off", ] diff --git a/primitives/api/proc-macro/src/impl_runtime_apis.rs b/primitives/api/proc-macro/src/impl_runtime_apis.rs index f8d7c74b9738b..f217c6adef87b 100644 --- a/primitives/api/proc-macro/src/impl_runtime_apis.rs +++ b/primitives/api/proc-macro/src/impl_runtime_apis.rs @@ -162,6 +162,7 @@ fn generate_dispatch_function(impls: &[ItemImpl]) -> Result { fn generate_wasm_interface(impls: &[ItemImpl]) -> Result { let input = Ident::new("input", Span::call_site()); let c = generate_crate_access(HIDDEN_INCLUDES_ID); + let impl_calls = generate_impl_calls(impls, &input)? .into_iter() .map(|(trait_, fn_name, impl_, attrs)| { @@ -183,6 +184,8 @@ fn generate_wasm_interface(impls: &[ItemImpl]) -> Result { } }; + #c::init_runtime_logger(); + let output = { #impl_ }; #c::to_substrate_wasm_fn_return_value(&output) } diff --git a/primitives/api/src/lib.rs b/primitives/api/src/lib.rs index 8ce447c0d3667..10bb820c9c582 100644 --- a/primitives/api/src/lib.rs +++ b/primitives/api/src/lib.rs @@ -30,6 +30,19 @@ //! api, the [`ApiExt`] trait, the [`CallApiAt`] trait and the [`ConstructRuntimeApi`] trait. //! //! On a meta level this implies, the client calls the generated API from the client perspective. +//! +//! +//! # Logging +//! +//! Substrate supports logging from the runtime in native and in wasm. For that purpose it provides +//! the [`RuntimeLogger`](sp_runtime::runtime_logger::RuntimeLogger). This runtime logger is +//! automatically enabled for each call into the runtime through the runtime api. As logging +//! introduces extra code that isn't actually required for the logic of your runtime and also +//! increases the final wasm blob size, it is recommended to disable the logging for on-chain +//! wasm blobs. This can be done by enabling the `disable-logging` feature of this crate. Be aware +//! that this feature instructs `log` and `tracing` to disable logging at compile time by setting +//! the `max_level_off` feature for these crates. So, you should not enable this feature for a +//! native build as otherwise the node will not output any log messages. #![cfg_attr(not(feature = "std"), no_std)] @@ -392,6 +405,12 @@ pub trait ConstructRuntimeApi> { fn construct_runtime_api<'a>(call: &'a C) -> ApiRef<'a, Self::RuntimeApi>; } +/// Init the [`RuntimeLogger`](sp_runtime::runtime_logger::RuntimeLogger). +pub fn init_runtime_logger() { + #[cfg(not(feature = "disable-logging"))] + sp_runtime::runtime_logger::RuntimeLogger::init(); +} + /// An error describing which API call failed. #[cfg_attr(feature = "std", derive(Debug, thiserror::Error, Eq, PartialEq))] #[cfg_attr(feature = "std", error("Failed to execute API call {tag}"))] diff --git a/primitives/api/test/Cargo.toml b/primitives/api/test/Cargo.toml index e8f06aaf20e1b..2a6325fd09e9a 100644 --- a/primitives/api/test/Cargo.toml +++ b/primitives/api/test/Cargo.toml @@ -15,6 +15,7 @@ targets = ["x86_64-unknown-linux-gnu"] sp-api = { version = "3.0.0", path = "../" } substrate-test-runtime-client = { version = "2.0.0", path = "../../../test-utils/runtime/client" } sp-version = { version = "3.0.0", path = "../../version" } +sp-tracing = { version = "3.0.0", path = "../../tracing" } sp-runtime = { version = "3.0.0", path = "../../runtime" } sp-blockchain = { version = "3.0.0", path = "../../blockchain" } sp-consensus = { version = "0.9.0", path = "../../consensus/common" } @@ -28,6 +29,7 @@ rustversion = "1.0.0" criterion = "0.3.0" substrate-test-runtime-client = { version = "2.0.0", path = "../../../test-utils/runtime/client" } sp-core = { version = "3.0.0", path = "../../core" } +log = "0.4.14" [[bench]] name = "bench" diff --git a/primitives/api/test/tests/runtime_calls.rs b/primitives/api/test/tests/runtime_calls.rs index ec1a86d8379fc..f708033390ce6 100644 --- a/primitives/api/test/tests/runtime_calls.rs +++ b/primitives/api/test/tests/runtime_calls.rs @@ -218,3 +218,34 @@ fn call_runtime_api_with_multiple_arguments() { .test_multiple_arguments(&block_id, data.clone(), data.clone(), data.len() as u32) .unwrap(); } + +#[test] +fn disable_logging_works() { + if std::env::var("RUN_TEST").is_ok() { + sp_tracing::try_init_simple(); + + let mut builder = TestClientBuilder::new() + .set_execution_strategy(ExecutionStrategy::AlwaysWasm); + builder.genesis_init_mut().set_wasm_code( + substrate_test_runtime_client::runtime::wasm_binary_logging_disabled_unwrap().to_vec(), + ); + + let client = builder.build(); + let runtime_api = client.runtime_api(); + let block_id = BlockId::Number(0); + runtime_api.do_trace_log(&block_id).expect("Logging should not fail"); + log::error!("Logging from native works"); + } else { + let executable = std::env::current_exe().unwrap(); + let output = std::process::Command::new(executable) + .env("RUN_TEST", "1") + .env("RUST_LOG", "info") + .args(&["--nocapture", "disable_logging_works"]) + .output() + .unwrap(); + + let output = dbg!(String::from_utf8(output.stderr).unwrap()); + assert!(!output.contains("Hey I'm runtime")); + assert!(output.contains("Logging from native works")); + } +} diff --git a/primitives/runtime/Cargo.toml b/primitives/runtime/Cargo.toml index 0e4f6168ba118..7d33e7fa62d2d 100644 --- a/primitives/runtime/Cargo.toml +++ b/primitives/runtime/Cargo.toml @@ -22,7 +22,7 @@ sp-application-crypto = { version = "3.0.0", default-features = false, path = ". sp-arithmetic = { version = "3.0.0", default-features = false, path = "../arithmetic" } sp-std = { version = "3.0.0", default-features = false, path = "../std" } sp-io = { version = "3.0.0", default-features = false, path = "../io" } -log = { version = "0.4.8", optional = true } +log = { version = "0.4.14", default-features = false } paste = "1.0" rand = { version = "0.7.2", optional = true } impl-trait-for-tuples = "0.2.1" @@ -34,6 +34,9 @@ either = { version = "1.5", default-features = false } serde_json = "1.0.41" rand = "0.7.2" sp-state-machine = { version = "0.9.0", path = "../state-machine" } +sp-api = { version = "3.0.0", path = "../api" } +substrate-test-runtime-client = { version = "2.0.0", path = "../../test-utils/runtime/client" } +sp-tracing = { version = "3.0.0", path = "../../primitives/tracing" } [features] bench = [] @@ -43,7 +46,7 @@ std = [ "sp-application-crypto/std", "sp-arithmetic/std", "codec/std", - "log", + "log/std", "sp-core/std", "rand", "sp-std/std", diff --git a/primitives/runtime/src/lib.rs b/primitives/runtime/src/lib.rs index 2fb4f7546d233..c8b93a083be4e 100644 --- a/primitives/runtime/src/lib.rs +++ b/primitives/runtime/src/lib.rs @@ -57,6 +57,7 @@ pub mod transaction_validity; pub mod random_number_generator; mod runtime_string; mod multiaddress; +pub mod runtime_logger; pub use crate::runtime_string::*; diff --git a/primitives/runtime/src/runtime_logger.rs b/primitives/runtime/src/runtime_logger.rs new file mode 100644 index 0000000000000..e27dc828cdbc6 --- /dev/null +++ b/primitives/runtime/src/runtime_logger.rs @@ -0,0 +1,108 @@ +// This file is part of Substrate. + +// Copyright (C) 2021 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. + +//! A logger that can be used to log from the runtime. +//! +//! See [`RuntimeLogger`] for more docs. + +/// Runtime logger implementation - `log` crate backend. +/// +/// The logger should be initialized if you want to display +/// logs inside the runtime that is not necessarily running natively. +pub struct RuntimeLogger; + +impl RuntimeLogger { + /// Initialize the logger. + /// + /// This is a no-op when running natively (`std`). + #[cfg(feature = "std")] + pub fn init() {} + + /// Initialize the logger. + /// + /// This is a no-op when running natively (`std`). + #[cfg(not(feature = "std"))] + pub fn init() { + static LOGGER: RuntimeLogger = RuntimeLogger; + let _ = log::set_logger(&LOGGER); + + // Set max level to `TRACE` to ensure we propagate + // all log entries to the native side that will do the + // final filtering on what should be printed. + // + // If we don't set any level, logging is disabled + // completly. + log::set_max_level(log::LevelFilter::Trace); + } +} + +impl log::Log for RuntimeLogger { + fn enabled(&self, _metadata: &log::Metadata) -> bool { + // to avoid calling to host twice, we pass everything + // and let the host decide what to print. + // If someone is initializing the logger they should + // know what they are doing. + true + } + + fn log(&self, record: &log::Record) { + use sp_std::fmt::Write; + let mut w = sp_std::Writer::default(); + let _ = ::core::write!(&mut w, "{}", record.args()); + + sp_io::logging::log( + record.level().into(), + record.target(), + w.inner(), + ); + } + + fn flush(&self) {} +} + +#[cfg(test)] +mod tests { + use substrate_test_runtime_client::{ + ExecutionStrategy, TestClientBuilderExt, DefaultTestClientBuilderExt, + TestClientBuilder, runtime::TestAPI, + }; + use sp_api::{ProvideRuntimeApi, BlockId}; + + #[test] + fn ensure_runtime_logger_works() { + if std::env::var("RUN_TEST").is_ok() { + sp_tracing::try_init_simple(); + + let client = TestClientBuilder::new() + .set_execution_strategy(ExecutionStrategy::AlwaysWasm).build(); + let runtime_api = client.runtime_api(); + let block_id = BlockId::Number(0); + runtime_api.do_trace_log(&block_id).expect("Logging should not fail"); + } else { + let executable = std::env::current_exe().unwrap(); + let output = std::process::Command::new(executable) + .env("RUN_TEST", "1") + .env("RUST_LOG", "trace") + .args(&["--nocapture", "ensure_runtime_logger_works"]) + .output() + .unwrap(); + + let output = dbg!(String::from_utf8(output.stderr).unwrap()); + assert!(output.contains("Hey I'm runtime")); + } + } +} diff --git a/test-utils/runtime/Cargo.toml b/test-utils/runtime/Cargo.toml index 1a841ac0755a4..e978f8702e9b7 100644 --- a/test-utils/runtime/Cargo.toml +++ b/test-utils/runtime/Cargo.toml @@ -47,7 +47,7 @@ sp-externalities = { version = "0.9.0", default-features = false, path = "../../ # 3rd party cfg-if = "1.0" -log = { version = "0.4.8", optional = true } +log = { version = "0.4.14", default-features = false } serde = { version = "1.0.101", optional = true, features = ["derive"] } [dev-dependencies] @@ -71,7 +71,7 @@ std = [ "frame-executive/std", "sp-inherents/std", "sp-keyring", - "log", + "log/std", "memory-db/std", "sp-offchain/std", "sp-core/std", @@ -97,3 +97,5 @@ std = [ "sp-transaction-pool/std", "trie-db/std", ] +# Special feature to disable logging +disable-logging = [ "sp-api/disable-logging", "log/max_level_error" ] diff --git a/test-utils/runtime/build.rs b/test-utils/runtime/build.rs index 1de18d32b08b0..50c455b4ad831 100644 --- a/test-utils/runtime/build.rs +++ b/test-utils/runtime/build.rs @@ -26,5 +26,13 @@ fn main() { // depend on the stack-size. .append_to_rust_flags("-Clink-arg=-zstack-size=1048576") .import_memory() - .build() + .build(); + + WasmBuilder::new() + .with_current_project() + .export_heap_base() + .import_memory() + .set_file_name("wasm_binary_logging_disabled.rs") + .enable_feature("disable-logging") + .build(); } diff --git a/test-utils/runtime/client/src/lib.rs b/test-utils/runtime/client/src/lib.rs index 5800203cf7e76..c8d11c9b62221 100644 --- a/test-utils/runtime/client/src/lib.rs +++ b/test-utils/runtime/client/src/lib.rs @@ -92,6 +92,7 @@ pub struct GenesisParameters { changes_trie_config: Option, heap_pages_override: Option, extra_storage: Storage, + wasm_code: Option>, } impl GenesisParameters { @@ -113,6 +114,11 @@ impl GenesisParameters { self.extra_storage.clone(), ) } + + /// Set the wasm code that should be used at genesis. + pub fn set_wasm_code(&mut self, code: Vec) { + self.wasm_code = Some(code); + } } impl substrate_test_client::GenesisInit for GenesisParameters { @@ -121,6 +127,10 @@ impl substrate_test_client::GenesisInit for GenesisParameters { let mut storage = self.genesis_config().genesis_map(); + if let Some(ref code) = self.wasm_code { + storage.top.insert(sp_core::storage::well_known_keys::CODE.to_vec(), code.clone()); + } + let child_roots = storage.children_default.iter().map(|(_sk, child_content)| { let state_root = <<::Header as HeaderT>::Hashing as HashT>::trie_root( child_content.data.clone().into_iter().collect() diff --git a/test-utils/runtime/src/lib.rs b/test-utils/runtime/src/lib.rs index b349d1266b031..e915f345a09aa 100644 --- a/test-utils/runtime/src/lib.rs +++ b/test-utils/runtime/src/lib.rs @@ -69,6 +69,11 @@ pub type AuraId = sp_consensus_aura::sr25519::AuthorityId; #[cfg(feature = "std")] include!(concat!(env!("OUT_DIR"), "/wasm_binary.rs")); +#[cfg(feature = "std")] +pub mod wasm_binary_logging_disabled { + include!(concat!(env!("OUT_DIR"), "/wasm_binary_logging_disabled.rs")); +} + /// Wasm binary unwrapped. If built with `SKIP_WASM_BUILD`, the function panics. #[cfg(feature = "std")] pub fn wasm_binary_unwrap() -> &'static [u8] { @@ -76,6 +81,16 @@ pub fn wasm_binary_unwrap() -> &'static [u8] { supported with the flag disabled.") } +/// Wasm binary unwrapped. If built with `SKIP_WASM_BUILD`, the function panics. +#[cfg(feature = "std")] +pub fn wasm_binary_logging_disabled_unwrap() -> &'static [u8] { + wasm_binary_logging_disabled::WASM_BINARY + .expect( + "Development wasm binary is not available. Testing is only supported with the flag \ + disabled." + ) +} + /// Test runtime version. pub const VERSION: RuntimeVersion = RuntimeVersion { spec_name: create_runtime_str!("test"), @@ -742,8 +757,7 @@ cfg_if! { } fn do_trace_log() { - frame_support::debug::RuntimeLogger::init(); - frame_support::debug::trace!("Hey I'm runtime"); + log::trace!("Hey I'm runtime"); } } @@ -1001,8 +1015,7 @@ cfg_if! { } fn do_trace_log() { - frame_support::debug::RuntimeLogger::init(); - frame_support::debug::trace!("Hey I'm runtime"); + log::error!("Hey I'm runtime: {}", log::STATIC_MAX_LEVEL); } } diff --git a/utils/wasm-builder/src/builder.rs b/utils/wasm-builder/src/builder.rs index 8ef6c95324c78..34dd09f72b211 100644 --- a/utils/wasm-builder/src/builder.rs +++ b/utils/wasm-builder/src/builder.rs @@ -43,6 +43,7 @@ impl WasmBuilderSelectProject { rust_flags: Vec::new(), file_name: None, project_cargo_toml: get_manifest_dir().join("Cargo.toml"), + features_to_enable: Vec::new(), } } @@ -60,6 +61,7 @@ impl WasmBuilderSelectProject { rust_flags: Vec::new(), file_name: None, project_cargo_toml: path, + features_to_enable: Vec::new(), }) } else { Err("Project path must point to the `Cargo.toml` of the project") @@ -88,6 +90,8 @@ pub struct WasmBuilder { /// The path to the `Cargo.toml` of the project that should be built /// for wasm. project_cargo_toml: PathBuf, + /// Features that should be enabled when building the wasm binary. + features_to_enable: Vec, } impl WasmBuilder { @@ -132,6 +136,14 @@ impl WasmBuilder { self } + /// Enable the given feature when building the wasm binary. + /// + /// `feature` needs to be a valid feature that is defined in the project `Cargo.toml`. + pub fn enable_feature(mut self, feature: impl Into) -> Self { + self.features_to_enable.push(feature.into()); + self + } + /// Build the WASM binary. pub fn build(self) { let out_dir = PathBuf::from(env::var("OUT_DIR").expect("`OUT_DIR` is set by cargo!")); @@ -151,6 +163,7 @@ impl WasmBuilder { file_path, self.project_cargo_toml, self.rust_flags.into_iter().map(|f| format!("{} ", f)).collect(), + self.features_to_enable, ); // As last step we need to generate our `rerun-if-changed` stuff. If a build fails, we don't @@ -204,6 +217,7 @@ fn build_project( file_name: PathBuf, project_cargo_toml: PathBuf, default_rustflags: String, + features_to_enable: Vec, ) { let cargo_cmd = match crate::prerequisites::check() { Ok(cmd) => cmd, @@ -217,6 +231,7 @@ fn build_project( &project_cargo_toml, &default_rustflags, cargo_cmd, + features_to_enable, ); let (wasm_binary, wasm_binary_bloaty) = if let Some(wasm_binary) = wasm_binary { diff --git a/utils/wasm-builder/src/wasm_project.rs b/utils/wasm-builder/src/wasm_project.rs index 73dc2e13af348..d80af9b7fc51a 100644 --- a/utils/wasm-builder/src/wasm_project.rs +++ b/utils/wasm-builder/src/wasm_project.rs @@ -97,6 +97,7 @@ pub(crate) fn create_and_compile( project_cargo_toml: &Path, default_rustflags: &str, cargo_cmd: CargoCommandVersioned, + features_to_enable: Vec, ) -> (Option, WasmBinaryBloaty) { let wasm_workspace_root = get_wasm_workspace_root(); let wasm_workspace = wasm_workspace_root.join("wbuild"); @@ -108,6 +109,7 @@ pub(crate) fn create_and_compile( &wasm_workspace, &crate_metadata, &crate_metadata.workspace_root, + features_to_enable, ); build_project(&project, default_rustflags, cargo_cmd); @@ -199,7 +201,7 @@ fn create_project_cargo_toml( crate_name: &str, crate_path: &Path, wasm_binary: &str, - enabled_features: &[String], + enabled_features: impl Iterator, ) { let mut workspace_toml: Table = toml::from_str( &fs::read_to_string( @@ -265,7 +267,7 @@ fn create_project_cargo_toml( wasm_project.insert("package".into(), crate_name.into()); wasm_project.insert("path".into(), crate_path.display().to_string().into()); wasm_project.insert("default-features".into(), false.into()); - wasm_project.insert("features".into(), enabled_features.to_vec().into()); + wasm_project.insert("features".into(), enabled_features.collect::>().into()); dependencies.insert("wasm-project".into(), wasm_project.into()); @@ -339,6 +341,7 @@ fn create_project( wasm_workspace: &Path, crate_metadata: &Metadata, workspace_root_path: &Path, + features_to_enable: Vec, ) -> PathBuf { let crate_name = get_crate_name(project_cargo_toml); let crate_path = project_cargo_toml.parent().expect("Parent path exists; qed"); @@ -354,13 +357,16 @@ fn create_project( enabled_features.push("runtime-wasm".into()); } + let mut enabled_features = enabled_features.into_iter().collect::>(); + enabled_features.extend(features_to_enable.into_iter()); + create_project_cargo_toml( &wasm_project_folder, workspace_root_path, &crate_name, &crate_path, &wasm_binary, - &enabled_features, + enabled_features.into_iter(), ); write_file_if_changed( From f8f5fe3b79a7295141d863ed0d924fd5770b182e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Mon, 15 Feb 2021 17:27:52 +0100 Subject: [PATCH 2/6] Update frame/im-online/src/lib.rs Co-authored-by: Guillaume Thiolliere --- frame/im-online/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/frame/im-online/src/lib.rs b/frame/im-online/src/lib.rs index b37273c05bce9..f0df19d6ab9f0 100644 --- a/frame/im-online/src/lib.rs +++ b/frame/im-online/src/lib.rs @@ -530,7 +530,7 @@ impl Module { || { let call = prepare_heartbeat()?; log::info!( - target: "imonline", + target: "runtime::im-online", "[index: {:?}] Reporting im-online at block: {:?} (session: {:?}): {:?}", authority_index, block_number, From a342b64e7704d3e01298ea712e1c8252e87954a1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Mon, 15 Feb 2021 17:43:47 +0100 Subject: [PATCH 3/6] Update test-utils/runtime/Cargo.toml --- test-utils/runtime/Cargo.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test-utils/runtime/Cargo.toml b/test-utils/runtime/Cargo.toml index e978f8702e9b7..bdb847ae56647 100644 --- a/test-utils/runtime/Cargo.toml +++ b/test-utils/runtime/Cargo.toml @@ -98,4 +98,4 @@ std = [ "trie-db/std", ] # Special feature to disable logging -disable-logging = [ "sp-api/disable-logging", "log/max_level_error" ] +disable-logging = [ "sp-api/disable-logging" ] From 9cf2077f31d33c40bacb89ead75fb53f01637c99 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Thu, 18 Feb 2021 20:11:09 +0100 Subject: [PATCH 4/6] Fix test --- utils/wasm-builder/src/builder.rs | 10 +++++++++- utils/wasm-builder/src/wasm_project.rs | 25 +++++++++++++++++++++---- 2 files changed, 30 insertions(+), 5 deletions(-) diff --git a/utils/wasm-builder/src/builder.rs b/utils/wasm-builder/src/builder.rs index 34dd09f72b211..bfbc4030adfd1 100644 --- a/utils/wasm-builder/src/builder.rs +++ b/utils/wasm-builder/src/builder.rs @@ -147,7 +147,9 @@ impl WasmBuilder { /// Build the WASM binary. pub fn build(self) { let out_dir = PathBuf::from(env::var("OUT_DIR").expect("`OUT_DIR` is set by cargo!")); - let file_path = out_dir.join(self.file_name.unwrap_or_else(|| "wasm_binary.rs".into())); + let file_path = out_dir.join( + self.file_name.clone().unwrap_or_else(|| "wasm_binary.rs".into()), + ); if check_skip_build() { // If we skip the build, we still want to make sure to be called when an env variable @@ -164,6 +166,7 @@ impl WasmBuilder { self.project_cargo_toml, self.rust_flags.into_iter().map(|f| format!("{} ", f)).collect(), self.features_to_enable, + self.file_name, ); // As last step we need to generate our `rerun-if-changed` stuff. If a build fails, we don't @@ -213,11 +216,15 @@ fn generate_rerun_if_changed_instructions() { /// constant `WASM_BINARY`, which contains the built WASM binary. /// `project_cargo_toml` - The path to the `Cargo.toml` of the project that should be built. /// `default_rustflags` - Default `RUSTFLAGS` that will always be set for the build. +/// `features_to_enable` - Features that should be enabled for the project. +/// `wasm_binary_name` - The optional wasm binary name that is extended with `.compact.wasm`. +/// If `None`, the project name will be used. fn build_project( file_name: PathBuf, project_cargo_toml: PathBuf, default_rustflags: String, features_to_enable: Vec, + wasm_binary_name: Option, ) { let cargo_cmd = match crate::prerequisites::check() { Ok(cmd) => cmd, @@ -232,6 +239,7 @@ fn build_project( &default_rustflags, cargo_cmd, features_to_enable, + wasm_binary_name, ); let (wasm_binary, wasm_binary_bloaty) = if let Some(wasm_binary) = wasm_binary { diff --git a/utils/wasm-builder/src/wasm_project.rs b/utils/wasm-builder/src/wasm_project.rs index d80af9b7fc51a..0392546575446 100644 --- a/utils/wasm-builder/src/wasm_project.rs +++ b/utils/wasm-builder/src/wasm_project.rs @@ -98,6 +98,7 @@ pub(crate) fn create_and_compile( default_rustflags: &str, cargo_cmd: CargoCommandVersioned, features_to_enable: Vec, + wasm_binary_name: Option, ) -> (Option, WasmBinaryBloaty) { let wasm_workspace_root = get_wasm_workspace_root(); let wasm_workspace = wasm_workspace_root.join("wbuild"); @@ -116,6 +117,7 @@ pub(crate) fn create_and_compile( let (wasm_binary, bloaty) = compact_wasm_file( &project, project_cargo_toml, + wasm_binary_name, ); wasm_binary.as_ref().map(|wasm_binary| @@ -443,16 +445,22 @@ fn build_project(project: &Path, default_rustflags: &str, cargo_cmd: CargoComman fn compact_wasm_file( project: &Path, cargo_manifest: &Path, + wasm_binary_name: Option, ) -> (Option, WasmBinaryBloaty) { let is_release_build = is_release_build(); let target = if is_release_build { "release" } else { "debug" }; - let wasm_binary = get_wasm_binary_name(cargo_manifest); + let default_wasm_binary_name = get_wasm_binary_name(cargo_manifest); let wasm_file = project.join("target/wasm32-unknown-unknown") .join(target) - .join(format!("{}.wasm", wasm_binary)); + .join(format!("{}.wasm", default_wasm_binary_name)); let wasm_compact_file = if is_release_build { - let wasm_compact_file = project.join(format!("{}.compact.wasm", wasm_binary)); + let wasm_compact_file = project.join( + format!( + "{}.compact.wasm", + wasm_binary_name.clone().unwrap_or_else(|| default_wasm_binary_name.clone()), + ) + ); wasm_gc::garbage_collect_file(&wasm_file, &wasm_compact_file) .expect("Failed to compact generated WASM binary."); Some(WasmBinary(wasm_compact_file)) @@ -460,7 +468,16 @@ fn compact_wasm_file( None }; - (wasm_compact_file, WasmBinaryBloaty(wasm_file)) + let bloaty_file_name = if let Some(name) = wasm_binary_name { + format!("{}.wasm", name) + } else { + format!("{}.wasm", default_wasm_binary_name) + }; + + let bloaty_file = project.join(bloaty_file_name); + fs::copy(wasm_file, &bloaty_file).expect("Copying the bloaty file to the project dir."); + + (wasm_compact_file, WasmBinaryBloaty(bloaty_file)) } /// Custom wrapper for a [`cargo_metadata::Package`] to store it in From 18a98db307212474590b0eafff6b2c3f770f2f33 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Fri, 19 Feb 2021 17:23:17 +0100 Subject: [PATCH 5/6] Don't use tracing in the runtime, as we don't support it :D --- Cargo.lock | 3 +-- frame/collective/Cargo.toml | 4 ++-- frame/collective/src/lib.rs | 24 ++++++++++++------------ primitives/api/Cargo.toml | 5 +---- 4 files changed, 16 insertions(+), 20 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index d3bd171ab1102..4af3614b57c6d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4563,6 +4563,7 @@ dependencies = [ "frame-support", "frame-system", "hex-literal", + "log", "pallet-balances", "parity-scale-codec", "serde", @@ -4570,7 +4571,6 @@ dependencies = [ "sp-io", "sp-runtime", "sp-std", - "tracing", ] [[package]] @@ -8180,7 +8180,6 @@ dependencies = [ "sp-test-primitives", "sp-version", "thiserror", - "tracing", ] [[package]] diff --git a/frame/collective/Cargo.toml b/frame/collective/Cargo.toml index 1edd87b382108..a458064f2fe01 100644 --- a/frame/collective/Cargo.toml +++ b/frame/collective/Cargo.toml @@ -22,7 +22,7 @@ sp-runtime = { version = "3.0.0", default-features = false, path = "../../primit frame-benchmarking = { version = "3.0.0", default-features = false, path = "../benchmarking", optional = true } frame-support = { version = "3.0.0", default-features = false, path = "../support" } frame-system = { version = "3.0.0", default-features = false, path = "../system" } -tracing = { version = "0.1.22", default-features = false } +log = { version = "0.4.14", default-features = false } [dev-dependencies] hex-literal = "0.3.1" @@ -39,7 +39,7 @@ std = [ "frame-support/std", "sp-runtime/std", "frame-system/std", - "tracing/std", + "log/std", ] runtime-benchmarks = [ "frame-benchmarking", diff --git a/frame/collective/src/lib.rs b/frame/collective/src/lib.rs index a56cff0140232..a8184b8dd5283 100644 --- a/frame/collective/src/lib.rs +++ b/frame/collective/src/lib.rs @@ -320,21 +320,21 @@ decl_module! { ) -> DispatchResultWithPostInfo { ensure_root(origin)?; if new_members.len() > T::MaxMembers::get() as usize { - tracing::error!( + log::error!( target: "runtime::collective", - expected = %T::MaxMembers::get(), - actual = %new_members.len(), - "New members count exceeds maximum amount of members expected.", + "New members count ({}) exceeds maximum amount of members expected ({}).", + new_members.len(), + T::MaxMembers::get(), ); } let old = Members::::get(); if old.len() > old_count as usize { - tracing::warn!( + log::warn!( target: "runtime::collective", - expected = %old_count, - actual = %old.len(), - "Wrong count used to estimate set_members weight.", + "Wrong count used to estimate set_members weight. expected ({}) vs actual ({})", + old_count, + old.len(), ); } let mut new_members = new_members; @@ -813,11 +813,11 @@ impl, I: Instance> ChangeMembers for Module { new: &[T::AccountId], ) { if new.len() > T::MaxMembers::get() as usize { - tracing::error!( + log::error!( target: "runtime::collective", - expected = %T::MaxMembers::get(), - actual = %new.len(), - "New members count exceeds maximum amount of members expected.", + "New members count ({}) exceeds maximum amount of members expected ({}).", + new.len(), + T::MaxMembers::get(), ); } // remove accounts from all current voting in motions. diff --git a/primitives/api/Cargo.toml b/primitives/api/Cargo.toml index c9ce83e8b2f51..c284d1f4791e8 100644 --- a/primitives/api/Cargo.toml +++ b/primitives/api/Cargo.toml @@ -23,7 +23,6 @@ sp-state-machine = { version = "0.9.0", optional = true, path = "../state-machin hash-db = { version = "0.15.2", optional = true } thiserror = { version = "1.0.21", optional = true } -tracing = { version = "0.1.22", default-features = false } log = { version = "0.4.14", default-features = false } [dev-dependencies] @@ -41,7 +40,6 @@ std = [ "hash-db", "thiserror", "log/std", - "tracing/std", ] # Special feature to disable logging completly. # @@ -49,8 +47,7 @@ std = [ # logging functionality increases the code size. It is recommended to enable this feature when # building a runtime for registering it on chain. # -# This sets the max logging level to `off` for `tracing` and `log`. +# This sets the max logging level to `off` for `log`. disable-logging = [ - "tracing/max_level_off", "log/max_level_off", ] From d309d836cc5ca9cb6cfb9940592ed09776947d9a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Wed, 24 Feb 2021 21:06:27 +0100 Subject: [PATCH 6/6] Fixes --- Cargo.lock | 1 + frame/election-provider-multi-phase/Cargo.toml | 2 ++ frame/election-provider-multi-phase/src/helpers.rs | 6 +++--- 3 files changed, 6 insertions(+), 3 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 7fefac1f40dbc..3c4921f088d86 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4710,6 +4710,7 @@ dependencies = [ "frame-support", "frame-system", "hex-literal", + "log", "pallet-balances", "parity-scale-codec", "parking_lot 0.11.1", diff --git a/frame/election-provider-multi-phase/Cargo.toml b/frame/election-provider-multi-phase/Cargo.toml index e52093ce1354e..aad1a5b4bb7ee 100644 --- a/frame/election-provider-multi-phase/Cargo.toml +++ b/frame/election-provider-multi-phase/Cargo.toml @@ -16,6 +16,7 @@ targets = ["x86_64-unknown-linux-gnu"] static_assertions = "1.1.0" serde = { version = "1.0.101", optional = true } codec = { package = "parity-scale-codec", version = "2.0.0", default-features = false, features = ["derive"] } +log = { version = "0.4.14", default-features = false } frame-support = { version = "3.0.0", default-features = false, path = "../support" } frame-system = { version = "3.0.0", default-features = false, path = "../system" } @@ -59,6 +60,7 @@ std = [ "sp-npos-elections/std", "sp-arithmetic/std", "sp-election-providers/std", + "log/std", ] runtime-benchmarks = [ "frame-benchmarking", diff --git a/frame/election-provider-multi-phase/src/helpers.rs b/frame/election-provider-multi-phase/src/helpers.rs index be074594e6603..7375ce017f20b 100644 --- a/frame/election-provider-multi-phase/src/helpers.rs +++ b/frame/election-provider-multi-phase/src/helpers.rs @@ -22,10 +22,10 @@ use sp_std::{collections::btree_map::BTreeMap, convert::TryInto, boxed::Box, pre #[macro_export] macro_rules! log { - ($level:tt, $patter:expr $(, $values:expr)* $(,)?) => { - frame_support::debug::$level!( + ($level:tt, $pattern:expr $(, $values:expr)* $(,)?) => { + log::$level!( target: $crate::LOG_TARGET, - concat!("🗳 ", $patter) $(, $values)* + concat!("🗳 ", $pattern) $(, $values)* ) }; }