From bb4447cb5272e937f26123abb903e26183dbb21a Mon Sep 17 00:00:00 2001 From: Lukasz Rubaszewski <117115317+lrubasze@users.noreply.github.com> Date: Thu, 19 Dec 2024 14:14:09 +0100 Subject: [PATCH 1/6] Add FastWithNoLogs compiler profile --- scrypto-compiler/src/lib.rs | 9 +++++++-- scrypto-test/src/ledger_simulator/compile.rs | 6 ++++++ 2 files changed, 13 insertions(+), 2 deletions(-) diff --git a/scrypto-compiler/src/lib.rs b/scrypto-compiler/src/lib.rs index be488684a10..054a6ad8c3f 100644 --- a/scrypto-compiler/src/lib.rs +++ b/scrypto-compiler/src/lib.rs @@ -1326,12 +1326,17 @@ impl ScryptoCompilerBuilder { self } - pub fn log_level(&mut self, log_level: Level) -> &mut Self { - // Firstly clear any log level previously set + pub fn disable_logs(&mut self) -> &mut Self { let all_features = ScryptoCompilerInputParams::log_level_to_scrypto_features(Level::Trace); all_features.iter().for_each(|log_level| { self.input_params.features.swap_remove(log_level); }); + self + } + + pub fn log_level(&mut self, log_level: Level) -> &mut Self { + // Firstly clear any log level previously set + self.disable_logs(); // Now set log level provided by the user if Level::Error <= log_level { diff --git a/scrypto-test/src/ledger_simulator/compile.rs b/scrypto-test/src/ledger_simulator/compile.rs index af064d5338b..d3d29ef5825 100644 --- a/scrypto-test/src/ledger_simulator/compile.rs +++ b/scrypto-test/src/ledger_simulator/compile.rs @@ -12,6 +12,8 @@ pub enum CompileProfile { Fast, /// Disables WASM optimization and enables all logs from error to trace level, by default used by Ledger Simulator. FastWithTraceLogs, + /// Disables WASM optimization and disables all logs. + FastWithNoLogs, } pub struct Compile; @@ -55,6 +57,10 @@ impl Compile { compiler_builder.optimize_with_wasm_opt(None); compiler_builder.log_level(Level::Trace); // all logs from error to trace } + CompileProfile::FastWithNoLogs => { + compiler_builder.optimize_with_wasm_opt(None); + compiler_builder.disable_logs(); + } } env_vars.iter().for_each(|(name, value)| { From 07f86bb0763d97ea77cb87072bfe28fe0aa5f68b Mon Sep 17 00:00:00 2001 From: Lukasz Rubaszewski <117115317+lrubasze@users.noreply.github.com> Date: Thu, 19 Dec 2024 14:17:58 +0100 Subject: [PATCH 2/6] Add logging macros tests --- .../assets/blueprints/logger/src/lib.rs | 20 ++++ radix-engine-tests/tests/vm/logging.rs | 97 +++++++++++++++++++ 2 files changed, 117 insertions(+) diff --git a/radix-engine-tests/assets/blueprints/logger/src/lib.rs b/radix-engine-tests/assets/blueprints/logger/src/lib.rs index c60d9fe332c..de92ff4622b 100644 --- a/radix-engine-tests/assets/blueprints/logger/src/lib.rs +++ b/radix-engine-tests/assets/blueprints/logger/src/lib.rs @@ -22,5 +22,25 @@ mod logger { pub fn assert_length_5(message: String) { assert_eq!(message.len(), 5); } + + fn mutate_in_place(input: &mut u8) -> u8 { + *input += 1; + *input + } + + // This function tests the logging macros. + // If the respective log level is enabled, the macro arguments will be + // ignored (even if an argument is an expression that mutates data or has side effects). + pub fn mutate_input_if_log_level_enabled(level: Level, number: String) -> u8 { + let mut number = number.parse::().unwrap(); + match level { + Level::Error => error!("Mutated input = {}", Self::mutate_in_place(&mut number)), + Level::Warn => warn!("Mutated input = {}", Self::mutate_in_place(&mut number)), + Level::Info => info!("Mutated input = {}", Self::mutate_in_place(&mut number)), + Level::Debug => debug!("Mutated input = {}", Self::mutate_in_place(&mut number)), + Level::Trace => trace!("Mutated input = {}", Self::mutate_in_place(&mut number)), + } + number + } } } diff --git a/radix-engine-tests/tests/vm/logging.rs b/radix-engine-tests/tests/vm/logging.rs index 8322152166c..b67caedfaf6 100644 --- a/radix-engine-tests/tests/vm/logging.rs +++ b/radix-engine-tests/tests/vm/logging.rs @@ -25,6 +25,26 @@ fn call>(function_name: &str, message: S) -> TransactionReceipt { receipt } +fn call_log_macro>( + ledger: &mut LedgerSimulator, + package_address: PackageAddress, + level: Level, + message: S, +) -> TransactionReceipt { + let manifest = ManifestBuilder::new() + .lock_fee_from_faucet() + .call_function( + package_address, + "Logger", + "mutate_input_if_log_level_enabled", + manifest_args!(level, message.as_ref().to_owned()), + ) + .build(); + let receipt = ledger.execute_manifest(manifest, vec![]); + + receipt +} + #[test] fn test_emit_log() { // Arrange @@ -110,3 +130,80 @@ fn test_assert_length_5() { }) } } + +#[test] +fn test_log_macros_enabled() { + // Arrange + let mut ledger = LedgerSimulatorBuilder::new().build(); + // PackageLoader compiles with all logs enabled (CompileProfile::FastWithTraceLogs) + let package_address = ledger.publish_package_simple(PackageLoader::get("logger")); + + let input = "2"; + let output_log = "Mutated input = 3"; + + for level in [ + Level::Error, + Level::Warn, + Level::Info, + Level::Debug, + Level::Trace, + ] { + // Act + let receipt = call_log_macro(&mut ledger, package_address, level, input); + + // Assert + { + receipt.expect_commit_success(); + + let logs = receipt.expect_commit(true).application_logs.clone(); + let output = receipt.expect_commit(true).output::(1); + + assert_eq!(output, 3); + + let expected_logs = vec![(level, output_log.to_owned())]; + assert_eq!(logs, expected_logs) + } + } +} + +#[test] +fn test_log_macros_disabled() { + use std::path::PathBuf; + + // Arrange + let mut ledger = LedgerSimulatorBuilder::new().build(); + let manifest_dir = PathBuf::from_str(env!("CARGO_MANIFEST_DIR")).unwrap(); + let package_dir = manifest_dir + .join("assets") + .join("blueprints") + .join("logger"); + // Disable all logging macros + let package = ledger.compile_with_option(package_dir, CompileProfile::FastWithNoLogs); + + let package_address = ledger.publish_package_simple(package); + let input = "2"; + + for level in [ + Level::Error, + Level::Warn, + Level::Info, + Level::Debug, + Level::Trace, + ] { + // Act + let receipt = call_log_macro(&mut ledger, package_address, level, input); + + // Assert + { + receipt.expect_commit_success(); + + let logs = receipt.expect_commit(true).application_logs.clone(); + let output = receipt.expect_commit(true).output::(1); + + assert_eq!(output, 2); + + let expected_logs: Vec<(Level, String)> = vec![]; + assert_eq!(logs, expected_logs) + } + } +} From a590ce50a0c209a186ef13559a8b77cde843f453 Mon Sep 17 00:00:00 2001 From: Lukasz Rubaszewski <117115317+lrubasze@users.noreply.github.com> Date: Thu, 19 Dec 2024 16:34:26 +0100 Subject: [PATCH 3/6] Improve logging macros to work with IDEs better --- scrypto/src/macros.rs | 39 ++++++++++++++++++++++++++++++++++----- 1 file changed, 34 insertions(+), 5 deletions(-) diff --git a/scrypto/src/macros.rs b/scrypto/src/macros.rs index 49b988c82b6..541bd304fdd 100644 --- a/scrypto/src/macros.rs +++ b/scrypto/src/macros.rs @@ -17,7 +17,16 @@ macro_rules! error { #[cfg(not(feature = "log-error"))] #[macro_export] macro_rules! error { - ($($args: expr),+) => {{}}; + ($($args: expr),+) => {{ + // The operation below does nothing at runtime but consumes the expressions, + // allowing tools (e.g., rust-analyzer) to parse them correctly to identify + // syntactical errors or provide hints and completions. + // Using `false` ensures the expression is optimized out in case of expressions + // that mutate data or have side effects. + if false { + let _ = ($($args),+); + } + }}; } /// Logs a `WARN` message. @@ -39,7 +48,12 @@ macro_rules! warn { #[cfg(not(feature = "log-warn"))] #[macro_export] macro_rules! warn { - ($($args: expr),+) => {{}}; + ($($args: expr),+) => {{ + // See `error` macro comment + if false { + let _ = ($($args),+); + } + }}; } /// Logs an `INFO` message. @@ -61,7 +75,12 @@ macro_rules! info { #[cfg(not(feature = "log-info"))] #[macro_export] macro_rules! info { - ($($args: expr),+) => {{}}; + ($($args: expr),+) => {{ + // See `error` macro comment + if false { + let _ = ($($args),+); + } + }}; } /// Logs a `DEBUG` message. @@ -83,7 +102,12 @@ macro_rules! debug { #[cfg(not(feature = "log-debug"))] #[macro_export] macro_rules! debug { - ($($args: expr),+) => {{}}; + ($($args: expr),+) => {{ + // See `error` macro comment + if false { + let _ = ($($args),+); + } + }}; } /// Logs a `TRACE` message. @@ -105,7 +129,12 @@ macro_rules! trace { #[cfg(not(feature = "log-trace"))] #[macro_export] macro_rules! trace { - ($($args: expr),+) => {{}}; + ($($args: expr),+) => {{ + // See `error` macro comment + if false { + let _ = ($($args),+); + } + }}; } // This is a TT-Muncher, a useful guide for this type of use case is here: https://adventures.michaelfbryan.com/posts/non-trivial-macros/ From 507aecb7c389cf6029281244fef1db6e4e09f1c1 Mon Sep 17 00:00:00 2001 From: Lukasz Rubaszewski <117115317+lrubasze@users.noreply.github.com> Date: Thu, 19 Dec 2024 16:39:01 +0100 Subject: [PATCH 4/6] Comment corrected --- radix-engine-tests/assets/blueprints/logger/src/lib.rs | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/radix-engine-tests/assets/blueprints/logger/src/lib.rs b/radix-engine-tests/assets/blueprints/logger/src/lib.rs index de92ff4622b..49079e46469 100644 --- a/radix-engine-tests/assets/blueprints/logger/src/lib.rs +++ b/radix-engine-tests/assets/blueprints/logger/src/lib.rs @@ -29,8 +29,9 @@ mod logger { } // This function tests the logging macros. - // If the respective log level is enabled, the macro arguments will be - // ignored (even if an argument is an expression that mutates data or has side effects). + // If the respective log level is disabled, the macro arguments will still be + // visible to development tools, but no action will be performed at runtime + // (even if an argument is an expression that mutates data or has side effects). pub fn mutate_input_if_log_level_enabled(level: Level, number: String) -> u8 { let mut number = number.parse::().unwrap(); match level { From 289c8ec4ac904f79a0e00a3706fc532dd708cd9c Mon Sep 17 00:00:00 2001 From: Lukasz Rubaszewski <117115317+lrubasze@users.noreply.github.com> Date: Fri, 20 Dec 2024 08:49:59 +0100 Subject: [PATCH 5/6] Allow unreachable code if log macro disabled --- scrypto/src/macros.rs | 3 +++ 1 file changed, 3 insertions(+) diff --git a/scrypto/src/macros.rs b/scrypto/src/macros.rs index 541bd304fdd..054a16e7cf9 100644 --- a/scrypto/src/macros.rs +++ b/scrypto/src/macros.rs @@ -23,6 +23,9 @@ macro_rules! error { // syntactical errors or provide hints and completions. // Using `false` ensures the expression is optimized out in case of expressions // that mutate data or have side effects. + // As of now, the linter does not complain about unreachable code, but if it does + // in the future, we should address it proactively. + #[allow(unreachable_code)] if false { let _ = ($($args),+); } From 388d68f34b7d7b9a1144cfe5e32262f059ebaef3 Mon Sep 17 00:00:00 2001 From: Lukasz Rubaszewski <117115317+lrubasze@users.noreply.github.com> Date: Fri, 20 Dec 2024 08:51:22 +0100 Subject: [PATCH 6/6] Make sure the syntax of the format string is checked --- scrypto/src/macros.rs | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/scrypto/src/macros.rs b/scrypto/src/macros.rs index 054a16e7cf9..2518f82b125 100644 --- a/scrypto/src/macros.rs +++ b/scrypto/src/macros.rs @@ -27,7 +27,7 @@ macro_rules! error { // in the future, we should address it proactively. #[allow(unreachable_code)] if false { - let _ = ($($args),+); + let _ = ::scrypto::prelude::sbor::rust::format!($($args),+); } }}; } @@ -54,7 +54,7 @@ macro_rules! warn { ($($args: expr),+) => {{ // See `error` macro comment if false { - let _ = ($($args),+); + let _ = ::scrypto::prelude::sbor::rust::format!($($args),+); } }}; } @@ -81,7 +81,7 @@ macro_rules! info { ($($args: expr),+) => {{ // See `error` macro comment if false { - let _ = ($($args),+); + let _ = ::scrypto::prelude::sbor::rust::format!($($args),+); } }}; } @@ -108,7 +108,7 @@ macro_rules! debug { ($($args: expr),+) => {{ // See `error` macro comment if false { - let _ = ($($args),+); + let _ = ::scrypto::prelude::sbor::rust::format!($($args),+); } }}; } @@ -135,7 +135,7 @@ macro_rules! trace { ($($args: expr),+) => {{ // See `error` macro comment if false { - let _ = ($($args),+); + let _ = ::scrypto::prelude::sbor::rust::format!($($args),+); } }}; }