diff --git a/Cargo.lock b/Cargo.lock index 9660e11884c86..382d1fd102db7 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1689,6 +1689,7 @@ dependencies = [ "frame-system", "hex-literal", "linregress", + "log", "parity-scale-codec", "paste 1.0.4", "serde", @@ -1769,7 +1770,6 @@ dependencies = [ "pretty_assertions", "serde", "smallvec 1.6.1", - "sp-api", "sp-arithmetic", "sp-core", "sp-inherents", @@ -1779,7 +1779,6 @@ dependencies = [ "sp-state-machine", "sp-std", "sp-tracing", - "substrate-test-runtime-client", ] [[package]] @@ -1840,6 +1839,7 @@ dependencies = [ "criterion", "frame-support", "impl-trait-for-tuples", + "log", "parity-scale-codec", "serde", "sp-core", @@ -4099,6 +4099,7 @@ dependencies = [ "frame-system-rpc-runtime-api", "frame-try-runtime", "hex-literal", + "log", "node-primitives", "pallet-assets", "pallet-authority-discovery", @@ -4525,6 +4526,7 @@ dependencies = [ "frame-benchmarking", "frame-support", "frame-system", + "log", "pallet-authorship", "pallet-balances", "pallet-offences", @@ -4554,6 +4556,7 @@ dependencies = [ "frame-benchmarking", "frame-support", "frame-system", + "log", "pallet-transaction-payment", "parity-scale-codec", "serde", @@ -4589,6 +4592,7 @@ dependencies = [ "frame-support", "frame-system", "hex-literal", + "log", "pallet-balances", "parity-scale-codec", "serde", @@ -4607,6 +4611,7 @@ dependencies = [ "frame-support", "frame-system", "hex-literal", + "log", "pallet-balances", "pallet-contracts-primitives", "pallet-contracts-proc-macro", @@ -4706,6 +4711,7 @@ dependencies = [ "frame-support", "frame-system", "hex-literal", + "log", "pallet-balances", "parity-scale-codec", "parking_lot 0.11.1", @@ -4748,6 +4754,7 @@ dependencies = [ "frame-support", "frame-system", "hex-literal", + "log", "pallet-balances", "parity-scale-codec", "serde", @@ -4782,6 +4789,7 @@ dependencies = [ "frame-support", "frame-system", "lite-json", + "log", "parity-scale-codec", "serde", "sp-core", @@ -4831,6 +4839,7 @@ dependencies = [ "frame-benchmarking", "frame-support", "frame-system", + "log", "pallet-authorship", "pallet-balances", "pallet-offences", @@ -4876,6 +4885,7 @@ dependencies = [ "frame-benchmarking", "frame-support", "frame-system", + "log", "pallet-authorship", "pallet-session", "parity-scale-codec", @@ -4961,6 +4971,7 @@ dependencies = [ "frame-support", "frame-system", "hex-literal", + "log", "parity-scale-codec", "serde", "sp-api", @@ -5006,6 +5017,7 @@ version = "2.0.0" dependencies = [ "frame-support", "frame-system", + "log", "parity-scale-codec", "serde", "sp-core", @@ -5020,6 +5032,7 @@ version = "3.0.0" dependencies = [ "frame-support", "frame-system", + "log", "pallet-balances", "parity-scale-codec", "serde", @@ -5111,6 +5124,7 @@ dependencies = [ "frame-benchmarking", "frame-support", "frame-system", + "log", "parity-scale-codec", "serde", "sp-core", @@ -5203,6 +5217,7 @@ dependencies = [ "frame-support", "frame-system", "hex", + "log", "pallet-authorship", "pallet-balances", "pallet-session", @@ -5295,6 +5310,7 @@ dependencies = [ "frame-support", "frame-system", "impl-trait-for-tuples", + "log", "parity-scale-codec", "serde", "sp-core", @@ -8256,6 +8272,7 @@ name = "sp-api" version = "3.0.0" dependencies = [ "hash-db", + "log", "parity-scale-codec", "sp-api-proc-macro", "sp-core", @@ -8283,6 +8300,7 @@ name = "sp-api-test" version = "2.0.1" dependencies = [ "criterion", + "log", "parity-scale-codec", "rustversion", "sc-block-builder", @@ -8292,6 +8310,7 @@ dependencies = [ "sp-core", "sp-runtime", "sp-state-machine", + "sp-tracing", "sp-version", "substrate-test-runtime-client", "trybuild", @@ -8736,12 +8755,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 7669273f0c82d..dc8ce8bace809 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" } @@ -156,6 +157,7 @@ std = [ "pallet-society/std", "pallet-recovery/std", "pallet-vesting/std", + "log/std", "frame-try-runtime/std", ] runtime-benchmarks = [ diff --git a/bin/node/runtime/src/lib.rs b/bin/node/runtime/src/lib.rs index a63fb341ddac8..0219779ca535f 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}, @@ -845,7 +845,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 20ef87ab15b47..2d7467d82e5b7 100644 --- a/frame/babe/Cargo.toml +++ b/frame/babe/Cargo.toml @@ -30,6 +30,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] pallet-balances = { version = "3.0.0", path = "../balances" } @@ -59,6 +60,7 @@ std = [ "sp-staking/std", "sp-std/std", "sp-timestamp/std", + "log/std", ] runtime-benchmarks = ["frame-benchmarking"] try-runtime = ["frame-support/try-runtime"] 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 53bf4502708e7..22c4ef0976f5f 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.1.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,6 +37,7 @@ std = [ "frame-benchmarking/std", "frame-support/std", "frame-system/std", + "log/std", ] runtime-benchmarks = ["frame-benchmarking"] try-runtime = ["frame-support/try-runtime"] diff --git a/frame/balances/src/lib.rs b/frame/balances/src/lib.rs index cc82497293c8c..cc7b6351c2584 100644 --- a/frame/balances/src/lib.rs +++ b/frame/balances/src/lib.rs @@ -756,7 +756,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." ); @@ -790,7 +791,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 b80b626801dcd..3b20cf7dd048c 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 5b137c3c1532a..1ff8cc8e57627 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. /// @@ -751,7 +757,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 ); @@ -764,12 +770,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 5cff91499bf46..b8f825cc52931 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.1.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] hex-literal = "0.3.1" @@ -38,6 +39,7 @@ std = [ "frame-support/std", "sp-runtime/std", "frame-system/std", + "log/std", ] runtime-benchmarks = [ "frame-benchmarking", diff --git a/frame/collective/src/lib.rs b/frame/collective/src/lib.rs index 50beb8607d61d..a8184b8dd5283 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: {})", + log::error!( + target: "runtime::collective", + "New members count ({}) exceeds maximum amount of members expected ({}).", + new_members.len(), T::MaxMembers::get(), - new_members.len() ); } let old = Members::::get(); if old.len() > old_count as usize { - debug::warn!( - "Wrong count used to estimate set_members weight. (expected: {}, actual: {})", + log::warn!( + target: "runtime::collective", + "Wrong count used to estimate set_members weight. expected ({}) vs actual ({})", old_count, - old.len() + old.len(), ); } 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: {})", + log::error!( + target: "runtime::collective", + "New members count ({}) exceeds maximum amount of members expected ({}).", + new.len(), T::MaxMembers::get(), - new.len() ); } // remove accounts from all current voting in motions. diff --git a/frame/contracts/Cargo.toml b/frame/contracts/Cargo.toml index 2b0843a01d7ca..018a8a5df672e 100644 --- a/frame/contracts/Cargo.toml +++ b/frame/contracts/Cargo.toml @@ -28,6 +28,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 } @@ -60,6 +61,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 b9ba7185706fa..e9befeee2d370 100644 --- a/frame/contracts/src/rent.rs +++ b/frame/contracts/src/rent.rs @@ -26,7 +26,6 @@ use sp_std::prelude::*; use sp_io::hashing::blake2_256; use sp_core::crypto::UncheckedFrom; use frame_support::{ - debug, storage::child, traits::{Currency, ExistenceRequirement, Get, OnUnbalanced, WithdrawReasons}, }; @@ -183,9 +182,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 dbf993bc3bc00..5b9e7c1f583c1 100644 --- a/frame/contracts/src/storage.rs +++ b/frame/contracts/src/storage.rs @@ -31,7 +31,6 @@ use sp_runtime::traits::{Bounded, Saturating, Zero}; use sp_core::crypto::UncheckedFrom; use frame_support::{ dispatch::DispatchResult, - debug, storage::child::{self, KillChildStorageResult}, 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. KillChildStorageResult::SomeRemaining(_) => { - debug::error!( + log::error!( + target: "runtime::contracts", "After deletion keys are remaining in this child trie: {:?}", removed.trie_id, ); diff --git a/frame/election-provider-multi-phase/Cargo.toml b/frame/election-provider-multi-phase/Cargo.toml index a7db8d55465eb..1d63f9df40a25 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" } @@ -49,6 +50,7 @@ default = ["std"] std = [ "serde", "codec/std", + "log/std", "frame-support/std", "frame-system/std", @@ -59,6 +61,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)* ) }; } diff --git a/frame/elections-phragmen/Cargo.toml b/frame/elections-phragmen/Cargo.toml index 6d7e18bd766cc..89723cb85fbe1 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.1.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 cf4b3beaa904e..3718da643da64 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,5 +38,6 @@ std = [ "sp-keystore", "sp-runtime/std", "sp-std/std", + "log/std", ] try-runtime = ["frame-support/try-runtime"] diff --git a/frame/example-offchain-worker/src/lib.rs b/frame/example-offchain-worker/src/lib.rs index 0c5e92a96e6ac..a3c1441e13679 100644 --- a/frame/example-offchain-worker/src/lib.rs +++ b/frame/example-offchain-worker/src/lib.rs @@ -49,7 +49,7 @@ use frame_system::{ SignedPayload, SigningTypes, Signer, SubmitTransaction, } }; -use frame_support::{debug, traits::Get}; +use frame_support::traits::Get; use sp_core::crypto::KeyTypeId; use sp_runtime::{ RuntimeDebug, @@ -153,28 +153,25 @@ pub mod pallet { /// 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. @@ -188,7 +185,7 @@ pub mod pallet { TransactionType::None => Ok(()), }; if let Err(e) = res { - debug::error!("Error: {}", e); + log::error!("Error: {}", e); } } } @@ -446,8 +443,8 @@ impl Pallet { 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), } } @@ -582,7 +579,7 @@ impl Pallet { .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); } @@ -593,19 +590,19 @@ impl Pallet { // 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) } @@ -634,7 +631,7 @@ impl Pallet { /// 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); >::mutate(|prices| { const MAX_LEN: usize = 64; @@ -647,7 +644,7 @@ impl Pallet { 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(Event::NewPrice(price, who)); } diff --git a/frame/executive/src/lib.rs b/frame/executive/src/lib.rs index 924adea95fd01..53353c224a8b7 100644 --- a/frame/executive/src/lib.rs +++ b/frame/executive/src/lib.rs @@ -491,10 +491,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 1bf7561bb20e7..2bf7306f58e15 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.1.0", path = "../benchmarking" } @@ -57,6 +58,7 @@ std = [ "frame-system/std", "pallet-authorship/std", "pallet-session/std", + "log/std", ] runtime-benchmarks = ["frame-benchmarking"] try-runtime = ["frame-support/try-runtime"] 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 efe01a6a6f5a5..4c5b4a8863bcd 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.1.0", default-features = false, path = "../benchmarking", optional = true } @@ -44,6 +45,7 @@ std = [ "sp-staking/std", "frame-support/std", "frame-system/std", + "log/std", ] runtime-benchmarks = ["frame-benchmarking"] try-runtime = ["frame-support/try-runtime"] diff --git a/frame/im-online/src/lib.rs b/frame/im-online/src/lib.rs index bd597acfb1ed5..f0df19d6ab9f0 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,8 +529,8 @@ impl Module { block_number, || { let call = prepare_heartbeat()?; - debug::info!( - target: "imonline", + log::info!( + target: "runtime::im-online", "[index: {:?}] Reporting im-online at block: {:?} (session: {:?}): {:?}", authority_index, block_number, 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 b76976d831c9b..245db9176f740 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,5 +33,6 @@ std = [ "sp-io/std", "sp-runtime/std", "sp-std/std", + "log/std", ] try-runtime = ["frame-support/try-runtime"] 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 cbf779df84744..a34c5f6bc3a3d 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,6 +38,7 @@ std = [ "sp-staking/std", "frame-support/std", "frame-system/std", + "log/std", ] runtime-benchmarks = [] try-runtime = ["frame-support/try-runtime"] 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 a5e00c3444024..4d82133b6af9d 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.1.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 8d95e2d48b2c9..1f9f29570a223 100644 --- a/frame/staking/Cargo.toml +++ b/frame/staking/Cargo.toml @@ -27,6 +27,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 } sp-election-providers = { version = "3.0.0", default-features = false, path = "../../primitives/election-providers" } # Optional imports for benchmarking @@ -62,6 +63,7 @@ std = [ "frame-system/std", "pallet-authorship/std", "sp-application-crypto/std", + "log/std", "sp-election-providers/std", ] runtime-benchmarks = [ diff --git a/frame/staking/src/lib.rs b/frame/staking/src/lib.rs index a74b2d55233ec..ed8a2efbd45a4 100644 --- a/frame/staking/src/lib.rs +++ b/frame/staking/src/lib.rs @@ -335,13 +335,13 @@ use sp_election_providers::ElectionProvider; pub use weights::WeightInfo; const STAKING_ID: LockIdentifier = *b"staking "; -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, concat!("💸 ", $patter) $(, $values)* ) @@ -3404,30 +3404,30 @@ impl sp_election_providers::ElectionDataProvider 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, ); CurrentPlannedSession::put(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 b77907721be22..7b1179122b973 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,8 +54,7 @@ std = [ "sp-staking/std", "sp-state-machine", "frame-support-procedural/std", + "log/std", ] -nightly = [] -strict = [] runtime-benchmarks = [] try-runtime = [] 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/dispatch.rs b/frame/support/src/dispatch.rs index c2315e66e3239..ab9feae3c2495 100644 --- a/frame/support/src/dispatch.rs +++ b/frame/support/src/dispatch.rs @@ -1345,7 +1345,7 @@ macro_rules! decl_module { $system::Config >::PalletInfo as $crate::traits::PalletInfo>::name::().expect("pallet will have name in the runtime; qed"); - $crate::debug::info!( + $crate::log::info!( target: $crate::LOG_TARGET, "⚠️ running migration for {} and setting new storage version to {:?}", pallet_name, @@ -1389,7 +1389,7 @@ macro_rules! decl_module { $system::Config >::PalletInfo as $crate::traits::PalletInfo>::name::().expect("pallet will have name in the runtime; qed"); - $crate::debug::info!( + $crate::log::info!( target: $crate::LOG_TARGET, "✅ no migration for '{}' and setting new storage version to {:?}", pallet_name, 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 e16200ef0b99e..4dbb6bff5ab2d 100644 --- a/frame/support/src/lib.rs +++ b/frame/support/src/lib.rs @@ -44,9 +44,9 @@ pub use sp_state_machine::BasicExternalities; pub use sp_io::{storage::root as storage_root, self}; #[doc(hidden)] pub use sp_runtime::RuntimeDebug; +#[doc(hidden)] +pub use log; -#[macro_use] -pub mod debug; #[macro_use] mod origin; #[macro_use] @@ -340,6 +340,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 @@ -1051,7 +1075,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 66cc7d74fe7db..6f99874743946 100644 --- a/frame/support/src/storage/child.rs +++ b/frame/support/src/storage/child.rs @@ -40,7 +40,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 4789f9b8add39..4306dbd644815 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 124c437c44bfa..a99184650cf55 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, @@ -1060,7 +1060,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) => { @@ -1078,7 +1081,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) } }) @@ -1107,7 +1113,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 8094889d89f48..01aa6ff3cf261 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,7 +43,8 @@ std = [ "frame-support/std", "serde", "frame-system/std", - "sp-timestamp/std" + "sp-timestamp/std", + "log/std", ] runtime-benchmarks = ["frame-benchmarking", "sp-io"] try-runtime = ["frame-support/try-runtime"] 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..c284d1f4791e8 100644 --- a/primitives/api/Cargo.toml +++ b/primitives/api/Cargo.toml @@ -23,6 +23,8 @@ 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 } +log = { version = "0.4.14", default-features = false } + [dev-dependencies] sp-test-primitives = { version = "2.0.0", path = "../test-primitives" } @@ -37,4 +39,15 @@ std = [ "sp-version/std", "hash-db", "thiserror", + "log/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 `log`. +disable-logging = [ + "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 51bbe1c73ac88..2be8545a81d1d 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 592b20b62a77d..afb9af343ba6c 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)] @@ -386,6 +399,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(feature = "std")] #[derive(Debug, thiserror::Error)] 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 94f419b1c44d5..e10e1b34012a8 100644 --- a/primitives/api/test/tests/runtime_calls.rs +++ b/primitives/api/test/tests/runtime_calls.rs @@ -215,3 +215,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..bdb847ae56647 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" ] 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..bfbc4030adfd1 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,10 +136,20 @@ 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!")); - 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 @@ -151,6 +165,8 @@ impl WasmBuilder { file_path, 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 @@ -200,10 +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, @@ -217,6 +238,8 @@ fn build_project( &project_cargo_toml, &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 73dc2e13af348..0392546575446 100644 --- a/utils/wasm-builder/src/wasm_project.rs +++ b/utils/wasm-builder/src/wasm_project.rs @@ -97,6 +97,8 @@ pub(crate) fn create_and_compile( project_cargo_toml: &Path, 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"); @@ -108,12 +110,14 @@ pub(crate) fn create_and_compile( &wasm_workspace, &crate_metadata, &crate_metadata.workspace_root, + features_to_enable, ); build_project(&project, default_rustflags, cargo_cmd); let (wasm_binary, bloaty) = compact_wasm_file( &project, project_cargo_toml, + wasm_binary_name, ); wasm_binary.as_ref().map(|wasm_binary| @@ -199,7 +203,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 +269,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 +343,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 +359,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( @@ -437,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)) @@ -454,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