Return an EvalResult alongside the redeemer

This refactors things so that eval_phase_two can expose logs even when the script succeeds.

It also enriches traces to be either Logs or Labels, so that we can tell the difference between the two when inspecting the traces.

crates/aiken-lang/src/test_framework.rs

@@ -231,17 +231,17 @@ impl UnitTest {
             OnTestFailure::FailImmediately => false,
         });
 
-        let mut traces = Vec::new();
+        let mut logs = Vec::new();
         if let Err(err) = eval_result.result() {
-            traces.push(format!("{err}"))
+            logs.push(format!("{err}"))
         }
-        traces.extend(eval_result.logs());
+        logs.extend(eval_result.logs());
 
         UnitTestResult {
             success,
             test: self.to_owned(),
             spent_budget: eval_result.cost(),
-            traces,
+            logs,
             assertion: self.assertion,
         }
     }
@@ -276,7 +276,7 @@ pub struct Fuzzer<T> {
 #[derive(Debug, Clone, thiserror::Error, miette::Diagnostic)]
 #[error("Fuzzer exited unexpectedly: {uplc_error}.")]
 pub struct FuzzerError {
-    traces: Vec<String>,
+    logs: Vec<String>,
     uplc_error: uplc::machine::Error,
 }
 
@@ -330,7 +330,7 @@ impl PropertyTest {
         let mut labels = BTreeMap::new();
         let mut remaining = n;
 
-        let (traces, counterexample, iterations) = match self.run_n_times(
+        let (logs, counterexample, iterations) = match self.run_n_times(
             &mut remaining,
             Prng::from_seed(seed),
             &mut labels,
@@ -339,18 +339,12 @@ impl PropertyTest {
             Ok(None) => (Vec::new(), Ok(None), n),
             Ok(Some(counterexample)) => (
                 self.eval(&counterexample.value, plutus_version)
-                    .logs()
+                    .logs(),
-                    .into_iter()
-                    .filter(|s| PropertyTest::extract_label(s).is_none())
-                    .collect(),
                 Ok(Some(counterexample.value)),
                 n - remaining,
             ),
-            Err(FuzzerError { traces, uplc_error }) => (
+            Err(FuzzerError { logs, uplc_error }) => (
-                traces
+                logs,
-                    .into_iter()
-                    .filter(|s| PropertyTest::extract_label(s).is_none())
-                    .collect(),
                 Err(uplc_error),
                 n - remaining + 1,
             ),
@@ -361,7 +355,7 @@ impl PropertyTest {
             counterexample,
             iterations,
             labels,
-            traces,
+            logs,
         }
     }
 
@@ -397,16 +391,14 @@ impl PropertyTest {
 
         let mut result = self.eval(&value, plutus_version);
 
-        for s in result.logs() {
+        for label in result.labels() {
             // NOTE: There may be other log outputs that interefere with labels. So *by
             // convention*, we treat as label strings that starts with a NUL byte, which
             // should be a guard sufficient to prevent inadvertent clashes.
-            if let Some(label) = PropertyTest::extract_label(&s) {
+            labels
-                labels
+                .entry(label)
-                    .entry(label)
+                .and_modify(|count| *count += 1)
-                    .and_modify(|count| *count += 1)
+                .or_insert(1);
-                    .or_insert(1);
-            }
         }
 
         let is_failure = result.failed(false);
@@ -470,14 +462,6 @@ impl PropertyTest {
             .unwrap()
             .eval_version(ExBudget::max(), &plutus_version.into())
     }
-
-    fn extract_label(s: &str) -> Option<String> {
-        if s.starts_with('\0') {
-            Some(s.split_at(1).1.to_string())
-        } else {
-            None
-        }
-    }
 }
 
 /// ----- Benchmark -----------------------------------------------------------------
@@ -498,21 +482,21 @@ pub struct Sampler<T> {
 pub enum BenchmarkError {
     #[error("Sampler exited unexpectedly: {uplc_error}.")]
     SamplerError {
-        traces: Vec<String>,
+        logs: Vec<String>,
         uplc_error: uplc::machine::Error,
     },
     #[error("Bench exited unexpectedly: {uplc_error}.")]
     BenchError {
-        traces: Vec<String>,
+        logs: Vec<String>,
         uplc_error: uplc::machine::Error,
     },
 }
 
 impl BenchmarkError {
-    pub fn traces(&self) -> &[String] {
+    pub fn logs(&self) -> &[String] {
         match self {
-            BenchmarkError::SamplerError { traces, .. }
+            BenchmarkError::SamplerError { logs, .. }
-            | BenchmarkError::BenchError { traces, .. } => traces.as_slice(),
+            | BenchmarkError::BenchError { logs, .. } => logs.as_slice(),
         }
     }
 }
@@ -561,19 +545,15 @@ impl Benchmark {
                         Ok(_) => measures.push((size, result.cost())),
                         Err(uplc_error) => {
                             error = Some(BenchmarkError::BenchError {
-                                traces: result
+                                logs: result.logs(),
-                                    .logs()
-                                    .into_iter()
-                                    .filter(|s| PropertyTest::extract_label(s).is_none())
-                                    .collect(),
                                 uplc_error,
                             });
                         }
                     }
                 }
 
-                Err(FuzzerError { traces, uplc_error }) => {
+                Err(FuzzerError { logs, uplc_error }) => {
-                    error = Some(BenchmarkError::SamplerError { traces, uplc_error });
+                    error = Some(BenchmarkError::SamplerError { logs, uplc_error });
                 }
             }
 
@@ -692,7 +672,7 @@ impl Prng {
         result
             .result()
             .map_err(|uplc_error| FuzzerError {
-                traces: result.logs(),
+                logs: result.logs(),
                 uplc_error,
             })
             .map(Prng::from_result)
@@ -1166,12 +1146,12 @@ impl<U, T> TestResult<U, T> {
         }
     }
 
-    pub fn traces(&self) -> &[String] {
+    pub fn logs(&self) -> &[String] {
         match self {
-            TestResult::UnitTestResult(UnitTestResult { traces, .. })
+            TestResult::UnitTestResult(UnitTestResult { logs, .. })
-            | TestResult::PropertyTestResult(PropertyTestResult { traces, .. }) => traces,
+            | TestResult::PropertyTestResult(PropertyTestResult { logs, .. }) => logs,
             TestResult::BenchmarkResult(BenchmarkResult { error, .. }) => {
-                error.as_ref().map(|e| e.traces()).unwrap_or_default()
+                error.as_ref().map(|e| e.logs()).unwrap_or_default()
             }
         }
     }
@@ -1181,7 +1161,7 @@ impl<U, T> TestResult<U, T> {
 pub struct UnitTestResult<T> {
     pub success: bool,
     pub spent_budget: ExBudget,
-    pub traces: Vec<String>,
+    pub logs: Vec<String>,
     pub test: UnitTest,
     pub assertion: Option<Assertion<T>>,
 }
@@ -1196,7 +1176,7 @@ impl UnitTestResult<(Constant, Rc<Type>)> {
         UnitTestResult {
             success: self.success,
             spent_budget: self.spent_budget,
-            traces: self.traces,
+            logs: self.logs,
             test: self.test,
             assertion: self.assertion.and_then(|assertion| {
                 // No need to spend time/cpu on reifying assertions for successful
@@ -1229,7 +1209,7 @@ pub struct PropertyTestResult<T> {
     pub counterexample: Result<Option<T>, uplc::machine::Error>,
     pub iterations: usize,
     pub labels: BTreeMap<String, usize>,
-    pub traces: Vec<String>,
+    pub logs: Vec<String>,
 }
 
 unsafe impl<T> Send for PropertyTestResult<T> {}
@@ -1249,7 +1229,7 @@ impl PropertyTestResult<PlutusData> {
             iterations: self.iterations,
             test: self.test,
             labels: self.labels,
-            traces: self.traces,
+            logs: self.logs,
         }
     }
 }

crates/aiken-project/src/telemetry/json.rs

@@ -129,8 +129,8 @@ fn fmt_test_json(result: &TestResult<UntypedExpr, UntypedExpr>) -> serde_json::V
         TestResult::BenchmarkResult(_) => unreachable!("benchmark returned in JSON output"),
     }
 
-    if !result.traces().is_empty() {
+    if !result.logs().is_empty() {
-        test["traces"] = json!(result.traces());
+        test["traces"] = json!(result.logs());
     }
 
     test

crates/aiken-project/src/telemetry/terminal.rs

@@ -584,12 +584,12 @@ fn fmt_test(
     }
 
     // Traces
-    if !result.traces().is_empty() {
+    if !result.logs().is_empty() {
         test = format!(
             "{test}\n{title}\n{traces}",
             title = "· with traces".if_supports_color(Stderr, |s| s.bold()),
             traces = result
-                .traces()
+                .logs()
                 .iter()
                 .map(|line| { format!("| {line}",) })
                 .collect::<Vec<_>>()

crates/aiken/src/cmd/tx/simulate.rs

@@ -137,7 +137,7 @@ pub fn exec(
                 // this should allow N scripts to be
                 let total_budget_used: Vec<ExBudget> = redeemers
                     .iter()
-                    .map(|curr| ExBudget {
+                    .map(|(curr, _)| ExBudget {
                         mem: curr.ex_units.mem as i64,
                         cpu: curr.ex_units.steps as i64,
                     })

crates/uplc/src/ast.rs

@@ -856,7 +856,7 @@ impl Program<NamedDeBruijn> {
             term,
             machine.ex_budget,
             initial_budget,
-            machine.logs,
+            machine.traces,
             machine.spend_counter.map(|i| i.into()),
         )
     }
@@ -871,7 +871,7 @@ impl Program<NamedDeBruijn> {
             term,
             machine.ex_budget,
             initial_budget,
-            machine.logs,
+            machine.traces,
             machine.spend_counter.map(|i| i.into()),
         )
     }
@@ -897,7 +897,7 @@ impl Program<NamedDeBruijn> {
             term,
             machine.ex_budget,
             budget,
-            machine.logs,
+            machine.traces,
             machine.spend_counter.map(|i| i.into()),
         )
     }
@@ -916,7 +916,7 @@ impl Program<NamedDeBruijn> {
             term,
             machine.ex_budget,
             initial_budget,
-            machine.logs,
+            machine.traces,
             machine.spend_counter.map(|i| i.into()),
         )
     }

crates/uplc/src/machine.rs

@@ -45,13 +45,42 @@ enum Context {
 pub const TERM_COUNT: usize = 9;
 pub const BUILTIN_COUNT: usize = 87;
 
+#[derive(Debug, Clone)]
+pub enum Trace {
+    Log(String),
+    Label(String),
+}
+
+impl Trace {
+    pub fn to_string(&self) -> String {
+        match self {
+            Trace::Log(log) => log.clone(),
+            Trace::Label(label) => label.clone(),
+        }
+    }
+
+    pub fn unwrap_log(self) -> Option<String> {
+        match self {
+            Trace::Log(log) => Some(log),
+            _ => None,
+        }
+    }
+
+    pub fn unwrap_label(self) -> Option<String> {
+        match self {
+            Trace::Label(label) => Some(label),
+            _ => None,
+        }
+    }
+}
+
 pub struct Machine {
     costs: CostModel,
     pub ex_budget: ExBudget,
     slippage: u32,
     unbudgeted_steps: [u32; 10],
+    pub traces: Vec<Trace>,
     pub spend_counter: Option<[i64; (TERM_COUNT + BUILTIN_COUNT) * 2]>,
-    pub logs: Vec<String>,
     version: Language,
 }
 
@@ -67,8 +96,8 @@ impl Machine {
             ex_budget: initial_budget,
             slippage,
             unbudgeted_steps: [0; 10],
+            traces: vec![],
             spend_counter: None,
-            logs: vec![],
             version,
         }
     }
@@ -84,8 +113,8 @@ impl Machine {
             ex_budget: initial_budget,
             slippage,
             unbudgeted_steps: [0; 10],
+            traces: vec![],
             spend_counter: Some([0; (TERM_COUNT + BUILTIN_COUNT) * 2]),
-            logs: vec![],
             version,
         }
     }
@@ -353,7 +382,7 @@ impl Machine {
             counter[i + 1] += cost.cpu;
         }
 
-        runtime.call(&self.version, &mut self.logs)
+        runtime.call(&self.version, &mut self.traces)
     }
 
     fn lookup_var(&mut self, name: &NamedDeBruijn, env: &[Value]) -> Result<Value, Error> {

crates/uplc/src/machine/eval_result.rs

@@ -1,4 +1,4 @@
-use super::{cost_model::ExBudget, Error};
+use super::{cost_model::ExBudget, Error, Trace};
 use crate::ast::{Constant, NamedDeBruijn, Term};
 
 #[derive(Debug)]
@@ -6,7 +6,7 @@ pub struct EvalResult {
     result: Result<Term<NamedDeBruijn>, Error>,
     remaining_budget: ExBudget,
     initial_budget: ExBudget,
-    logs: Vec<String>,
+    traces: Vec<Trace>,
     debug_cost: Option<Vec<i64>>,
 }
 
@@ -15,14 +15,14 @@ impl EvalResult {
         result: Result<Term<NamedDeBruijn>, Error>,
         remaining_budget: ExBudget,
         initial_budget: ExBudget,
-        logs: Vec<String>,
+        traces: Vec<Trace>,
         debug_cost: Option<Vec<i64>>,
     ) -> EvalResult {
         EvalResult {
             result,
             remaining_budget,
             initial_budget,
-            logs,
+            traces,
             debug_cost,
         }
     }
@@ -31,8 +31,22 @@ impl EvalResult {
         self.initial_budget - self.remaining_budget
     }
 
+    pub fn traces(&mut self) -> Vec<Trace> {
+        std::mem::take(&mut self.traces)
+    }
+
     pub fn logs(&mut self) -> Vec<String> {
-        std::mem::take(&mut self.logs)
+        std::mem::take(&mut self.traces)
+            .into_iter()
+            .filter_map(Trace::unwrap_log)
+            .collect()
+    }
+
+    pub fn labels(&mut self) -> Vec<String> {
+        std::mem::take(&mut self.traces)
+            .into_iter()
+            .filter_map(Trace::unwrap_label)
+            .collect()
     }
 
     pub fn failed(&self, can_error: bool) -> bool {

crates/uplc/src/machine/runtime.rs

@@ -1,7 +1,5 @@
 use super::{
-    cost_model::{BuiltinCosts, ExBudget},
+    cost_model::{BuiltinCosts, ExBudget}, value::{from_pallas_bigint, to_pallas_bigint}, Error, Trace, Value
-    value::{from_pallas_bigint, to_pallas_bigint},
-    Error, Value,
 };
 use crate::{
     ast::{Constant, Data, Type},
@@ -82,8 +80,8 @@ impl BuiltinRuntime {
         self.forces += 1;
     }
 
-    pub fn call(&self, language: &Language, logs: &mut Vec<String>) -> Result<Value, Error> {
+    pub fn call(&self, language: &Language, traces: &mut Vec<Trace>) -> Result<Value, Error> {
-        self.fun.call(language.into(), &self.args, logs)
+        self.fun.call(language.into(), &self.args, traces)
     }
 
     pub fn push(&mut self, arg: Value) -> Result<(), Error> {
@@ -388,7 +386,7 @@ impl DefaultFunction {
         &self,
         semantics: BuiltinSemantics,
         args: &[Value],
-        logs: &mut Vec<String>,
+        traces: &mut Vec<Trace>,
     ) -> Result<Value, Error> {
         match self {
             DefaultFunction::AddInteger => {
@@ -777,7 +775,11 @@ impl DefaultFunction {
             DefaultFunction::Trace => {
                 let arg1 = args[0].unwrap_string()?;
 
-                logs.push(arg1.clone());
+                if arg1.starts_with('\0') {
+                    traces.push(Trace::Label(arg1.split_at(1).1.to_string()));
+                } else {
+                    traces.push(Trace::Log(arg1.clone()));
+                }
 
                 Ok(args[1].clone())
             }

crates/uplc/src/tx.rs

@@ -1,6 +1,6 @@
 use crate::{
     ast::{DeBruijn, Program},
-    machine::cost_model::ExBudget,
+    machine::{cost_model::ExBudget, eval_result::EvalResult},
     PlutusData,
 };
 use error::Error;
@@ -36,7 +36,7 @@ pub fn eval_phase_two(
     slot_config: &SlotConfig,
     run_phase_one: bool,
     with_redeemer: fn(&Redeemer) -> (),
-) -> Result<Vec<Redeemer>, Error> {
+) -> Result<Vec<(Redeemer, EvalResult)>, Error> {
     let redeemers = tx.transaction_witness_set.redeemer.as_ref();
 
     let lookup_table = DataLookupTable::from_transaction(tx, utxos);
@@ -48,7 +48,7 @@ pub fn eval_phase_two(
 
     match redeemers {
         Some(rs) => {
-            let mut collected_redeemers = vec![];
+            let mut collected_results = vec![];
 
             let mut remaining_budget = *initial_budget.unwrap_or(&ExBudget::default());
 
@@ -62,7 +62,7 @@ pub fn eval_phase_two(
 
                 with_redeemer(&redeemer);
 
-                let redeemer = eval::eval_redeemer(
+                let (redeemer, eval_result) = eval::eval_redeemer(
                     tx,
                     utxos,
                     slot_config,
@@ -77,10 +77,10 @@ pub fn eval_phase_two(
                 remaining_budget.cpu -= redeemer.ex_units.steps as i64;
                 remaining_budget.mem -= redeemer.ex_units.mem as i64;
 
-                collected_redeemers.push(redeemer)
+                collected_results.push((redeemer, eval_result));
             }
 
-            Ok(collected_redeemers)
+            Ok(collected_results)
         }
         None => Ok(vec![]),
     }
@@ -98,7 +98,7 @@ pub fn eval_phase_two_raw(
     slot_config: (u64, u64, u32),
     run_phase_one: bool,
     with_redeemer: fn(&Redeemer) -> (),
-) -> Result<Vec<Vec<u8>>, Error> {
+) -> Result<Vec<(Vec<u8>, EvalResult)>, Error> {
     let multi_era_tx = MultiEraTx::decode_for_era(Era::Conway, tx_bytes)
         .or_else(|e| MultiEraTx::decode_for_era(Era::Babbage, tx_bytes).map_err(|_| e))
         .or_else(|e| MultiEraTx::decode_for_era(Era::Alonzo, tx_bytes).map_err(|_| e))?;
@@ -139,8 +139,8 @@ pub fn eval_phase_two_raw(
                 with_redeemer,
             ) {
                 Ok(redeemers) => Ok(redeemers
-                    .iter()
+                    .into_iter()
-                    .map(|r| r.encode_fragment().unwrap())
+                    .map(|(r, e)| (r.encode_fragment().unwrap(), e))
                     .collect()),
                 Err(err) => Err(err),
             }

crates/uplc/src/tx/error.rs

@@ -1,5 +1,5 @@
 use crate::{
-    machine::{self, cost_model::ExBudget},
+    machine::{self, cost_model::ExBudget, Trace},
     TransactionInput,
 };
 use pallas_primitives::conway::Language;
@@ -15,6 +15,7 @@ pub enum Error {
     #[error("{0}")]
     FragmentDecode(#[from] pallas_primitives::Error),
     #[error("{}{}", .0, .2.iter()
+        .map(|trace| trace.to_string())
         .map(|trace| {
             format!(
                 "\n{:>13} {}",
@@ -42,7 +43,7 @@ pub enum Error {
         .join("")
         .as_str()
     )]
-    Machine(machine::Error, ExBudget, Vec<String>),
+    Machine(machine::Error, ExBudget, Vec<Trace>),
 
     #[error("native script can't be executed in phase-two")]
     NativeScriptPhaseTwo,

crates/uplc/src/tx/eval.rs

@@ -5,7 +5,7 @@ use super::{
 };
 use crate::{
     ast::{FakeNamedDeBruijn, NamedDeBruijn, Program},
-    machine::cost_model::ExBudget,
+    machine::{cost_model::ExBudget, eval_result::EvalResult},
     tx::{
         phase_one::redeemer_tag_to_string,
         script_context::{DataLookupTable, ScriptVersion, TxInfoV1, TxInfoV2, TxInfoV3},
@@ -23,7 +23,7 @@ pub fn eval_redeemer(
     lookup_table: &DataLookupTable,
     cost_mdls_opt: Option<&CostModels>,
     initial_budget: &ExBudget,
-) -> Result<Redeemer, Error> {
+) -> Result<(Redeemer, EvalResult), Error> {
     fn do_eval_redeemer(
         cost_mdl_opt: Option<&CostModel>,
         initial_budget: &ExBudget,
@@ -32,7 +32,7 @@ pub fn eval_redeemer(
         redeemer: &Redeemer,
         tx_info: TxInfo,
         program: Program<NamedDeBruijn>,
-    ) -> Result<Redeemer, Error> {
+    ) -> Result<(Redeemer, EvalResult), Error> {
         let script_context = tx_info
             .into_script_context(redeemer, datum.as_ref())
             .expect("couldn't create script context from transaction?");
@@ -56,11 +56,9 @@ pub fn eval_redeemer(
         };
 
         let cost = eval_result.cost();
-        let logs = eval_result.logs();
 
-        match eval_result.result() {
+        if let Err(err) = eval_result.result() {
-            Ok(_) => (),
+            return Err(Error::Machine(err, cost, eval_result.traces()));
-            Err(err) => return Err(Error::Machine(err, cost, logs)),
         }
 
         let new_redeemer = Redeemer {
@@ -73,7 +71,7 @@ pub fn eval_redeemer(
             },
         };
 
-        Ok(new_redeemer)
+        Ok((new_redeemer, eval_result))
     }
 
     let program = |script: Bytes| {

crates/uplc/src/tx/tests.rs

@@ -254,7 +254,7 @@ fn test_eval_0() {
 
             let total_budget_used: Vec<ExBudget> = redeemers
                 .iter()
-                .map(|curr| ExBudget {
+                .map(|(curr, _)| ExBudget {
                     mem: curr.ex_units.mem as i64,
                     cpu: curr.ex_units.steps as i64,
                 })
@@ -527,7 +527,7 @@ fn test_eval_1() {
 
             let total_budget_used: Vec<ExBudget> = redeemers
                 .iter()
-                .map(|curr| ExBudget {
+                .map(|(curr, _)| ExBudget {
                     mem: curr.ex_units.mem as i64,
                     cpu: curr.ex_units.steps as i64,
                 })
@@ -638,7 +638,7 @@ fn test_eval_2() {
 
             let total_budget_used: Vec<ExBudget> = redeemers
                 .iter()
-                .map(|curr| ExBudget {
+                .map(|(curr, _)| ExBudget {
                     mem: curr.ex_units.mem as i64,
                     cpu: curr.ex_units.steps as i64,
                 })
@@ -908,7 +908,7 @@ fn test_eval_3() {
 
             let total_budget_used: Vec<ExBudget> = redeemers
                 .iter()
-                .map(|curr| ExBudget {
+                .map(|(curr, _)| ExBudget {
                     mem: curr.ex_units.mem as i64,
                     cpu: curr.ex_units.steps as i64,
                 })
@@ -1101,7 +1101,7 @@ fn test_eval_5() {
 
             let total_budget_used: Vec<ExBudget> = redeemers
                 .iter()
-                .map(|curr| ExBudget {
+                .map(|(curr, _)| ExBudget {
                     mem: curr.ex_units.mem as i64,
                     cpu: curr.ex_units.steps as i64,
                 })
@@ -1211,7 +1211,7 @@ fn test_eval_6() {
 
             let total_budget_used: Vec<ExBudget> = redeemers
                 .iter()
-                .map(|curr| ExBudget {
+                .map(|(curr, _)| ExBudget {
                     mem: curr.ex_units.mem as i64,
                     cpu: curr.ex_units.steps as i64,
                 })
@@ -1321,7 +1321,7 @@ fn test_eval_7() {
 
             let total_budget_used: Vec<ExBudget> = redeemers
                 .iter()
-                .map(|curr| ExBudget {
+                .map(|(curr, _)| ExBudget {
                     mem: curr.ex_units.mem as i64,
                     cpu: curr.ex_units.steps as i64,
                 })
@@ -1582,7 +1582,7 @@ fn test_eval_8() {
 
             let total_budget_used: Vec<ExBudget> = redeemers
                 .iter()
-                .map(|curr| ExBudget {
+                .map(|(curr, _)| ExBudget {
                     mem: curr.ex_units.mem as i64,
                     cpu: curr.ex_units.steps as i64,
                 })