Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improve logging macros to work with IDEs better #2043

Merged
merged 6 commits into from
Dec 20, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
21 changes: 21 additions & 0 deletions radix-engine-tests/assets/blueprints/logger/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -22,5 +22,26 @@ 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 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::<u8>().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
}
}
}
97 changes: 97 additions & 0 deletions radix-engine-tests/tests/vm/logging.rs
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,26 @@ fn call<S: AsRef<str>>(function_name: &str, message: S) -> TransactionReceipt {
receipt
}

fn call_log_macro<S: AsRef<str>>(
ledger: &mut LedgerSimulator<NoExtension, InMemorySubstateDatabase>,
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
Expand Down Expand Up @@ -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::<u8>(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::<u8>(1);

assert_eq!(output, 2);

let expected_logs: Vec<(Level, String)> = vec![];
assert_eq!(logs, expected_logs)
}
}
}
9 changes: 7 additions & 2 deletions scrypto-compiler/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
6 changes: 6 additions & 0 deletions scrypto-test/src/ledger_simulator/compile.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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)| {
Expand Down
42 changes: 37 additions & 5 deletions scrypto/src/macros.rs
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,19 @@ 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.
// 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 {
lrubasze marked this conversation as resolved.
Show resolved Hide resolved
let _ = ::scrypto::prelude::sbor::rust::format!($($args),+);
}
}};
}

/// Logs a `WARN` message.
Expand All @@ -39,7 +51,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 _ = ::scrypto::prelude::sbor::rust::format!($($args),+);
}
}};
}

/// Logs an `INFO` message.
Expand All @@ -61,7 +78,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 _ = ::scrypto::prelude::sbor::rust::format!($($args),+);
}
}};
}

/// Logs a `DEBUG` message.
Expand All @@ -83,7 +105,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 _ = ::scrypto::prelude::sbor::rust::format!($($args),+);
}
}};
}

/// Logs a `TRACE` message.
Expand All @@ -105,7 +132,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 _ = ::scrypto::prelude::sbor::rust::format!($($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/
Expand Down
Loading