feat: add log decoding capabilities to show decoded log values for forc-test

docs/book/src/testing/unit-testing.md

@@ -141,3 +141,51 @@ By default, `forc test` will use all the available threads in your system. To re
 ```console
 forc test --test-threads 1
 ```
+
+## Logs Inside Tests
+
+<!-- This section should explain how log decoding works with Sway unit tests -->
+<!-- unit_test_log::example::start -->
+Forc has some capacity to help decode logs returned from the unit tests. You can use this feature to decode raw logs into a human readable format.
+
+```sway
+script;
+
+fn main() {}
+
+#[test]
+fn test_fn() {
+let a = 10;
+    log(a);
+    let b = 30;
+    log(b);
+    assert_eq(a, 10)
+    assert_eq(b, 30)
+}
+```
+
+The example shown above is logging two different variables, `a` and `b` and their values are `10` and `30`, respectively. Without log decoding printed log for this test with `forc test --logs` (`--logs` flag is required to see the logs for this example since the test is passing. Logs are silenced by default in passing tests, and can be enabled using the `--logs` flag.):
+
+```console
+Finished debug [unoptimized + fuel] target(s) in 5.23s
+      Bytecode hash: 0x1cb1edc031691c5c08b50fd0f07b02431848ab81b325b72eb3fd233c67d6b548
+   Running 1 test, filtered 0 tests
+      test test_fn ... ok (38.875µs, 232 gas)
+[{"LogData":{"data":"000000000000000a","digest":"8d85f8467240628a94819b26bee26e3a9b2804334c63482deacec8d64ab4e1e7","id":"0000000000000000000000000000000000000000000000000000000000000000","is":10368,"len":8,"pc":11032,"ptr":67107840,"ra":0,"rb":0}},{"LogData":{"data":"000000000000001e","digest":"48a97e421546f8d4cae1cf88c51a459a8c10a88442eed63643dd263cef880c1c","id":"0000000000000000000000000000000000000000000000000000000000000000","is":10368,"len":8,"pc":11516,"ptr":67106816,"ra":0,"rb":1}}]
+```
+
+This is not very easy to understand, it is possible to decode these logs with `--decode` flag, executing `forc test --logs --decode`:
+
+```console
+Finished debug [unoptimized + fuel] target(s) in 5.23s
+      Bytecode hash: 0x1cb1edc031691c5c08b50fd0f07b02431848ab81b325b72eb3fd233c67d6b548
+   Running 1 test, filtered 0 tests
+      test test_fn ... ok (38.875µs, 232 gas)
+Decoded log value: 10, log rb: 0
+Decoded log value: 30, log rb: 1
+```
+
+As it can be seen, the values are human readable and easier to understand which makes debugging much more easier.
+
+**Note**: This is an experimental feature and we are actively working on reporting variable names next to their values.
+<!-- unit_test_log::example::end -->

forc-test/Cargo.toml

@@ -14,6 +14,7 @@ forc-pkg = { version = "0.58.0", path = "../forc-pkg" }
 fuel-abi-types = { workspace = true }
 fuel-tx = { workspace = true, features = ["test-helpers"] }
 fuel-vm = { workspace = true, features = ["random", "test-helpers"] }
+fuels-core = { workspace = true }
 rand = "0.8"
 rayon = "1.7.0"
 sway-core = { version = "0.58.0", path = "../sway-core" }

forc-test/src/lib.rs

@@ -10,12 +10,15 @@ use fuel_abi_types::error_codes::ErrorSignal;
 use fuel_tx as tx;
 use fuel_vm::checked_transaction::builder::TransactionBuilderExt;
 use fuel_vm::{self as vm};
+use fuels_core::codec::ABIDecoder;
+use fuels_core::types::param_types::ParamType;
 use pkg::manifest::build_profile::ExperimentalFlags;
 use pkg::TestPassCondition;
 use pkg::{Built, BuiltPackage};
 use rand::{Rng, SeedableRng};
 use rayon::prelude::*;
 use std::{collections::HashMap, fs, path::PathBuf, sync::Arc};
+use sway_core::asm_generation::ProgramABI;
 use sway_core::BuildTarget;
 use sway_types::Span;
 use tx::consensus_parameters::ConsensusParametersV1;
@@ -162,6 +165,11 @@ pub struct TestPrintOpts {
     pub print_logs: bool,
 }
 
+/// A `LogData` decoded into a human readable format with its type information.
+pub struct DecodedLog {
+    pub value: String,
+}
+
 impl TestedPackage {
     pub fn tests_passed(&self) -> bool {
         self.tests.iter().all(|test| test.passed())
@@ -654,6 +662,42 @@ fn deployment_transaction(
     (contract_id, tx)
 }
 
+pub fn decode_log_data(
+    log_id: u64,
+    log_data: &[u8],
+    program_abi: &ProgramABI,
+) -> anyhow::Result<DecodedLog> {
+    let program_abi = match program_abi {
+        ProgramABI::Fuel(fuel_abi) => Some(fuel_abi),
+        _ => None,
+    }
+    .ok_or_else(|| anyhow::anyhow!("only fuelvm is supported for log decoding"))?;
+    // Create type lookup (id, TypeDeclaration)
+    let type_lookup = program_abi
+        .types
+        .iter()
+        .map(|decl| (decl.type_id, decl.clone()))
+        .collect::<HashMap<_, _>>();
+
+    let logged_type_lookup: HashMap<_, _> = program_abi
+        .logged_types
+        .iter()
+        .flatten()
+        .map(|logged_type| (logged_type.log_id, logged_type.application.clone()))
+        .collect();
+
+    let type_application = logged_type_lookup
+        .get(&log_id)
+        .ok_or_else(|| anyhow::anyhow!("log id is missing"))?;
+
+    let abi_decoder = ABIDecoder::default();
+    let param_type = ParamType::try_from_type_application(type_application, &type_lookup)?;
+    let decoded_str = abi_decoder.decode_as_debug_str(&param_type, log_data)?;
+    let decoded_log = DecodedLog { value: decoded_str };
+
+    Ok(decoded_log)
+}
+
 /// Build the given package and run its tests after applying the filter provided.
 ///
 /// Returns the result of test execution.

forc/src/cli/commands/test.rs

@@ -2,9 +2,10 @@ use crate::cli;
 use ansi_term::Colour;
 use clap::Parser;
 use forc_pkg as pkg;
-use forc_test::{TestFilter, TestRunnerCount, TestedPackage};
+use forc_test::{decode_log_data, TestFilter, TestRunnerCount, TestedPackage};
 use forc_util::{tx_utils::format_log_receipts, ForcError, ForcResult};
 use pkg::manifest::build_profile::ExperimentalFlags;
+use sway_core::fuel_prelude::fuel_tx::Receipt;
 use tracing::info;
 
 forc_util::cli_examples! {
@@ -65,6 +66,10 @@ pub struct TestPrintOpts {
     /// Print `Log` and `LogData` receipts for tests.
     #[clap(long = "logs", short = 'l')]
     pub print_logs: bool,
+    /// Decode logs and show decoded log information in human readable format alongside the raw
+    /// logs.
+    #[clap(long = "decode", short = 'd')]
+    pub decode_logs: bool,
 }
 
 pub(crate) fn exec(cmd: Command) -> ForcResult<()> {
@@ -142,6 +147,21 @@ fn print_tested_pkg(pkg: &TestedPackage, test_print_opts: &TestPrintOpts) -> For
         // If logs are enabled, print them.
         if test_print_opts.print_logs {
             let logs = &test.logs;
+            if test_print_opts.decode_logs {
+                for log in logs {
+                    if let Receipt::LogData {
+                        rb,
+                        data: Some(data),
+                        ..
+                    } = log
+                    {
+                        let decoded_log_data = decode_log_data(*rb, data, &pkg.built.program_abi)?;
+                        let var_value = decoded_log_data.value;
+                        info!("Decoded log value: {}, log rb: {}", var_value, rb);
+                    }
+                }
+                info!("Raw logs:");
+            }
             let formatted_logs = format_log_receipts(logs, test_print_opts.pretty_print)?;
             info!("{}", formatted_logs);
         }

test/src/e2e_vm_tests/harness.rs

@@ -325,6 +325,7 @@ pub(crate) async fn compile_and_run_unit_tests(
         ]
         .iter()
         .collect();
+
         match std::panic::catch_unwind(|| {
             forc_test::build(forc_test::TestOpts {
                 pkg: forc_pkg::PkgOpts {
@@ -333,6 +334,9 @@ pub(crate) async fn compile_and_run_unit_tests(
                     terse: !(capture_output || run_config.verbose),
                     ..Default::default()
                 },
+                experimental: ExperimentalFlags {
+                    new_encoding: run_config.experimental.new_encoding,
+                },
                 ..Default::default()
             })
         }) {

test/src/e2e_vm_tests/mod.rs

@@ -10,6 +10,7 @@ use anyhow::{anyhow, bail, Result};
 use colored::*;
 use core::fmt;
 use forc_pkg::BuildProfile;
+use forc_test::decode_log_data;
 use fuel_vm::fuel_tx;
 use fuel_vm::prelude::*;
 use regex::Regex;
@@ -94,6 +95,7 @@ struct TestDescription {
     validate_abi: bool,
     validate_storage_slots: bool,
     supported_targets: HashSet<BuildTarget>,
+    expected_decoded_test_logs: Option<Vec<String>>,
     unsupported_profiles: Vec<&'static str>,
     checker: FileCheck,
     run_config: RunConfig,
@@ -274,6 +276,7 @@ impl TestContext {
             validate_storage_slots,
             checker,
             run_config,
+            expected_decoded_test_logs,
             ..
         } = test;
 
@@ -540,6 +543,8 @@ impl TestContext {
                     harness::compile_and_run_unit_tests(&name, &run_config, true).await;
                 *output = out;
 
+                let mut decoded_logs = vec![];
+
                 result.map(|tested_pkgs| {
                     let mut failed = vec![];
                     for pkg in tested_pkgs {
@@ -551,6 +556,29 @@ impl TestContext {
                                 }
                             }
 
+                            if expected_decoded_test_logs.is_some() {
+                                for log in test.logs.iter() {
+                                    if let Receipt::LogData {
+                                        rb,
+                                        data: Some(data),
+                                        ..
+                                    } = log
+                                    {
+                                        let decoded_log_data =
+                                            decode_log_data(*rb, data, &pkg.built.program_abi)
+                                                .unwrap();
+                                        let var_value = decoded_log_data.value;
+                                        if verbose {
+                                            println!(
+                                                "Decoded log value: {}, log rb: {}",
+                                                var_value, rb
+                                            );
+                                        }
+                                        decoded_logs.push(var_value);
+                                    }
+                                }
+                            }
+
                             if !test.passed() {
                                 failed.push(format!(
                                     "{}: Test '{}' failed with state {:?}, expected: {:?}",
@@ -563,13 +591,21 @@ impl TestContext {
                         }
                     }
 
+                    let expected_decoded_test_logs = expected_decoded_test_logs.unwrap_or_default();
+
                     if !failed.is_empty() {
                         println!("FAILED!! output:\n{}", output);
                         panic!(
                             "For {name}\n{} tests failed:\n{}",
                             failed.len(),
                             failed.into_iter().collect::<String>()
                         );
+                    } else if expected_decoded_test_logs != decoded_logs {
+                        println!("FAILED!! output:\n{}", output);
+                        panic!(
+                            "For {name}\ncollected decoded logs: {:?}\nexpected decoded logs: {:?}",
+                            decoded_logs, expected_decoded_test_logs
+                        );
                     }
                 })
             }
@@ -859,6 +895,19 @@ fn parse_test_toml(path: &Path, run_config: &RunConfig) -> Result<TestDescriptio
             Some(other) => Err(anyhow!("Unknown category '{}'.", other)),
         })?;
 
+    let expected_decoded_test_logs = if let Some(toml::Value::Array(a)) =
+        toml_content.get("expected_decoded_test_logs")
+    {
+        if category != TestCategory::UnitTestsPass {
+            bail!("`expected_decoded_test_logs` is only valid for `unt_tests_pass` type of tests")
+        }
+        a.iter()
+            .map(|elem| elem.as_str().map(|s| s.to_string()))
+            .collect::<Option<Vec<_>>>()
+    } else {
+        None
+    };
+
     // Abort early if we find a FailsToCompile test without any Checker directives.
     if category == TestCategory::FailsToCompile && checker.is_empty() {
         bail!("'fail' tests must contain some FileCheck verification directives.");
@@ -1040,6 +1089,7 @@ fn parse_test_toml(path: &Path, run_config: &RunConfig) -> Result<TestDescriptio
         unsupported_profiles,
         checker: file_check,
         run_config: run_config.clone(),
+        expected_decoded_test_logs,
     })
 }
 

test/src/e2e_vm_tests/test_programs/should_pass/unit_tests/log_decode/.gitignore

@@ -0,0 +1,2 @@
+out
+target

test/src/e2e_vm_tests/test_programs/should_pass/unit_tests/log_decode/Forc.lock

@@ -0,0 +1,13 @@
+[[package]]
+name = "core"
+source = "path+from-root-A2C6CB9CD0980A06"
+
+[[package]]
+name = "log_decode"
+source = "member"
+dependencies = ["std"]
+
+[[package]]
+name = "std"
+source = "path+from-root-A2C6CB9CD0980A06"
+dependencies = ["core"]

test/src/e2e_vm_tests/test_programs/should_pass/unit_tests/log_decode/Forc.toml

@@ -0,0 +1,8 @@
+[project]
+authors = ["Fuel Labs <contact@fuel.sh>"] 
+entry = "main.sw"
+license = "Apache-2.0"
+name = "log_decode"
+
+[dependencies]
+std = { path = "../../../../reduced_std_libs/sway-lib-std-assert" }

test/src/e2e_vm_tests/test_programs/should_pass/unit_tests/log_decode/src/main.sw

@@ -0,0 +1,15 @@
+script;
+
+fn main() {
+
+}
+
+
+#[test]
+fn test_fn() {
+	let a = 10;
+	log(a);
+	let b = 30;
+	log(b);
+	assert_eq(a, 10)
+}

test/src/e2e_vm_tests/test_programs/should_pass/unit_tests/log_decode/test.toml

@@ -0,0 +1,3 @@
+category = "unit_tests_pass"
+expected_decoded_test_logs = ["10", "30"]
+experimental_new_encoding = true

test/src/e2e_vm_tests/test_programs/should_pass/unit_tests/workspace_test/contract_multi_test/src/main.sw

@@ -17,15 +17,15 @@ fn test_foo() {
 
 #[test(should_revert)]
 fn test_fail() {
-    let contract_id = 0x22f840cd4af724e7257dd01ce315d907d694e417778b5f16b205a918baee092e;
+    let contract_id = 0x535d1bbf19a6c7e5e2e2906d09b8c959bd211391e7a3c7602c5dab0455f78305;
     let caller = abi(MyContract, contract_id);
     let result = caller.test_function {}();
     assert(result == false)
 }
 
 #[test]
 fn test_success() {
-    let contract_id = 0x22f840cd4af724e7257dd01ce315d907d694e417778b5f16b205a918baee092e;
+    let contract_id = 0x535d1bbf19a6c7e5e2e2906d09b8c959bd211391e7a3c7602c5dab0455f78305;
     let caller = abi(MyContract, contract_id);
     let result = caller.test_function {}();
     assert(result == true)