Fix order of logs such that they are printed after tested function na…

…me (FuelLabs#3828)

closes FuelLabs#3824.


With this PR, different tests are emitting logs separately as pointed
out by @mitchmindtree in FuelLabs#3808.

(Github code block indentations are showing up weird)

## Before this PR
```console
fuel/test_projects/deploy [⏱ 4s]
❯ mforc test --logs
  Compiled library "core".
  Compiled library "std".
  Compiled library "deploy".
  Bytecode size is 52 bytes.
   Running 2 tests
[{"Log":{"id":"0000000000000000000000000000000000000000000000000000000000000000","is":10344,"pc":10368,"ra":1,"rb":0,"rc":0,"rd":0}}]
[{"Log":{"id":"0000000000000000000000000000000000000000000000000000000000000000","is":10344,"pc":10380,"ra":2,"rb":1,"rc":0,"rd":0}}]
      test my_test ... ok (393.833µs)
      test my_test2 ... ok (371.833µs)
   Result: OK. 2 passed. 0 failed. Finished in 765.666µs.
```


## After this PR
```console
fuel/test_projects/deploy [⏱ 4s]
❯ mforc test --logs
  Compiled library "core".
  Compiled library "std".
  Compiled library "deploy".
  Bytecode size is 52 bytes.
   Running 2 tests
      test my_test ... ok (608.041µs)
[{"Log":{"id":"0000000000000000000000000000000000000000000000000000000000000000","is":10344,"pc":10368,"ra":1,"rb":0,"rc":0,"rd":0}}]
      test my_test2 ... ok (360.041µs)
[{"Log":{"id":"0000000000000000000000000000000000000000000000000000000000000000","is":10344,"pc":10380,"ra":2,"rb":1,"rc":0,"rd":0}}]
   Result: OK. 2 passed. 0 failed. Finished in 968.082µs.
```

forc-test/Cargo.toml

@@ -11,7 +11,6 @@ description = "A library for building and running Sway unit tests within Forc pa
 [dependencies]
 anyhow = "1"
 forc-pkg = { version = "0.33.1", path = "../forc-pkg" }
-forc-util = { version = "0.33.1", path = "../forc-util" }
 fuel-tx = { version = "0.23", features = ["builder"] }
 fuel-vm = { version = "0.22", features = ["random"] }
 rand = "0.8"

forc-test/src/lib.rs

@@ -1,7 +1,6 @@
 use std::{collections::HashSet, fs, path::PathBuf, sync::Arc};
 
 use forc_pkg as pkg;
-use forc_util::format_log_receipts;
 use fuel_tx as tx;
 use fuel_vm::{self as vm, prelude::Opcode};
 use pkg::{Built, BuiltPackage};
@@ -47,6 +46,8 @@ pub struct TestResult {
     pub state: vm::state::ProgramState,
     /// The required state of the VM for this test to pass.
     pub condition: TestPassCondition,
+    /// Emitted `Recipt`s during the execution of the test.
+    pub logs: Vec<fuel_tx::Receipt>,
 }
 
 /// The possible conditions for a test result to be considered "passing".
@@ -192,10 +193,7 @@ impl<'a> PackageTests {
     }
 
     /// Run all tests for this package and collect their results.
-    pub(crate) fn run_tests(
-        &self,
-        test_print_opts: &TestPrintOpts,
-    ) -> anyhow::Result<TestedPackage> {
+    pub(crate) fn run_tests(&self) -> anyhow::Result<TestedPackage> {
         let pkg_with_tests = self.built_pkg_with_tests();
         // TODO: We can easily parallelise this, but let's wait until testing is stable first.
         let tests = pkg_with_tests
@@ -207,12 +205,18 @@ impl<'a> PackageTests {
                     u32::try_from(entry.imm).expect("test instruction offset out of range");
                 let name = entry.fn_name.clone();
                 let test_setup = self.setup()?;
-                let (state, duration) = exec_test(
-                    &pkg_with_tests.bytecode,
-                    offset,
-                    test_setup,
-                    test_print_opts,
-                );
+                let (state, duration, receipts) =
+                    exec_test(&pkg_with_tests.bytecode, offset, test_setup);
+
+                // Only retain `Log` and `LogData` receipts.
+                let logs = receipts
+                    .into_iter()
+                    .filter(|receipt| {
+                        matches!(receipt, fuel_tx::Receipt::Log { .. })
+                            || matches!(receipt, fuel_tx::Receipt::LogData { .. })
+                    })
+                    .collect();
+
                 let test_decl_id = entry
                     .test_decl_id
                     .clone()
@@ -229,6 +233,7 @@ impl<'a> PackageTests {
                     span,
                     state,
                     condition,
+                    logs,
                 })
             })
             .collect::<anyhow::Result<_>>()?;
@@ -357,8 +362,8 @@ impl BuiltTests {
     }
 
     /// Run all built tests, return the result.
-    pub fn run(self, test_print_opts: &TestPrintOpts) -> anyhow::Result<Tested> {
-        run_tests(self, test_print_opts)
+    pub fn run(self) -> anyhow::Result<Tested> {
+        run_tests(self)
     }
 }
 
@@ -440,16 +445,16 @@ fn test_pass_condition(
 }
 
 /// Build the given package and run its tests, returning the results.
-fn run_tests(built: BuiltTests, test_print_opts: &TestPrintOpts) -> anyhow::Result<Tested> {
+fn run_tests(built: BuiltTests) -> anyhow::Result<Tested> {
     match built {
         BuiltTests::Package(pkg) => {
-            let tested_pkg = pkg.run_tests(test_print_opts)?;
+            let tested_pkg = pkg.run_tests()?;
             Ok(Tested::Package(Box::new(tested_pkg)))
         }
         BuiltTests::Workspace(workspace) => {
             let tested_pkgs = workspace
                 .into_iter()
-                .map(|pkg| pkg.run_tests(test_print_opts))
+                .map(|pkg| pkg.run_tests())
                 .collect::<anyhow::Result<Vec<TestedPackage>>>()?;
             Ok(Tested::Workspace(tested_pkgs))
         }
@@ -498,8 +503,11 @@ fn exec_test(
     bytecode: &[u8],
     test_offset: u32,
     test_setup: TestSetup,
-    test_print_opts: &TestPrintOpts,
-) -> (vm::state::ProgramState, std::time::Duration) {
+) -> (
+    vm::state::ProgramState,
+    std::time::Duration,
+    Vec<fuel_tx::Receipt>,
+) {
     let storage = test_setup.storage;
     let contract_id = test_setup.contract_id;
 
@@ -546,20 +554,7 @@ fn exec_test(
     let transition = interpreter.transact(tx).unwrap();
     let duration = start.elapsed();
     let state = *transition.state();
+    let receipts = transition.receipts().to_vec();
 
-    if test_print_opts.print_logs {
-        let receipts: Vec<_> = transition
-            .receipts()
-            .iter()
-            .cloned()
-            .filter(|receipt| {
-                matches!(receipt, tx::Receipt::LogData { .. })
-                    || matches!(receipt, tx::Receipt::Log { .. })
-            })
-            .collect();
-        let formatted_receipts = format_log_receipts(&receipts, test_print_opts.pretty_print)
-            .expect("cannot format log receipts for the test");
-        println!("{}", formatted_receipts);
-    }
-    (state, duration)
+    (state, duration, receipts)
 }

forc/src/cli/commands/test.rs

@@ -4,6 +4,7 @@ use anyhow::{bail, Result};
 use clap::Parser;
 use forc_pkg as pkg;
 use forc_test::TestedPackage;
+use forc_util::format_log_receipts;
 use tracing::info;
 
 /// Run the Sway unit tests for the current project.
@@ -28,14 +29,14 @@ pub struct Command {
     #[clap(flatten)]
     pub build: cli::shared::Build,
     #[clap(flatten)]
-    pub test_print: PrintCommand,
+    pub test_print: TestPrintOpts,
     /// When specified, only tests containing the given string will be executed.
     pub filter: Option<String>,
 }
 
 /// The set of options provided for controlling output of a test.
-#[derive(Parser, Debug)]
-pub struct PrintCommand {
+#[derive(Parser, Debug, Clone)]
+pub struct TestPrintOpts {
     #[clap(long = "pretty-print", short = 'r')]
     /// Pretty-print the logs emiited from tests.
     pub pretty_print: bool,
@@ -49,12 +50,12 @@ pub(crate) fn exec(cmd: Command) -> Result<()> {
         bail!("unit test filter not yet supported");
     }
 
-    let test_print_opts = test_print_opts_from_cmd(&cmd);
+    let test_print_opts = cmd.test_print.clone();
     let opts = opts_from_cmd(cmd);
     let built_tests = forc_test::build(opts)?;
     let start = std::time::Instant::now();
     info!("   Running {} tests", built_tests.test_count());
-    let tested = built_tests.run(&test_print_opts)?;
+    let tested = built_tests.run()?;
     let duration = start.elapsed();
 
     // Eventually we'll print this in a fancy manner, but this will do for testing.
@@ -63,17 +64,17 @@ pub(crate) fn exec(cmd: Command) -> Result<()> {
             for pkg in pkgs {
                 let built = &pkg.built.pkg_name;
                 info!("\n   tested -- {built}\n");
-                print_tested_pkg(&pkg)?;
+                print_tested_pkg(&pkg, &test_print_opts)?;
             }
             info!("\n   Finished in {:?}", duration);
         }
-        forc_test::Tested::Package(pkg) => print_tested_pkg(&pkg)?,
+        forc_test::Tested::Package(pkg) => print_tested_pkg(&pkg, &test_print_opts)?,
     };
 
     Ok(())
 }
 
-fn print_tested_pkg(pkg: &TestedPackage) -> Result<()> {
+fn print_tested_pkg(pkg: &TestedPackage, test_print_opts: &TestPrintOpts) -> Result<()> {
     let succeeded = pkg.tests.iter().filter(|t| t.passed()).count();
     let failed = pkg.tests.len() - succeeded;
     let mut failed_test_details = Vec::new();
@@ -90,6 +91,13 @@ fn print_tested_pkg(pkg: &TestedPackage) -> Result<()> {
             test.duration
         );
 
+        // If logs are enabled, print them.
+        if test_print_opts.print_logs {
+            let logs = &test.logs;
+            let formatted_logs = format_log_receipts(logs, test_print_opts.pretty_print)?;
+            info!("{}", formatted_logs);
+        }
+
         // If the test is failing, save details.
         if !test_passed {
             let details = test.details()?;
@@ -157,10 +165,3 @@ fn opts_from_cmd(cmd: Command) -> forc_test::Opts {
         debug_outfile: cmd.build.debug_outfile,
     }
 }
-
-fn test_print_opts_from_cmd(cmd: &Command) -> forc_test::TestPrintOpts {
-    forc_test::TestPrintOpts {
-        pretty_print: cmd.test_print.pretty_print,
-        print_logs: cmd.test_print.print_logs,
-    }
-}

test/src/e2e_vm_tests/harness.rs

@@ -226,8 +226,7 @@ pub(crate) async fn compile_and_run_unit_tests(
             },
             ..Default::default()
         })?;
-        let test_print_opts = forc_test::TestPrintOpts::default();
-        let tested = built_tests.run(&test_print_opts)?;
+        let tested = built_tests.run()?;
 
         match tested {
             forc_test::Tested::Package(tested_pkg) => Ok(vec![*tested_pkg]),