From 17a75d2481b0a214daf8fdb18eca684447ccadc5 Mon Sep 17 00:00:00 2001 From: Pi Lanningham Date: Mon, 17 Feb 2025 15:16:20 -0500 Subject: [PATCH] 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 | 84 +++++++------------ crates/aiken-project/src/telemetry/json.rs | 4 +- .../aiken-project/src/telemetry/terminal.rs | 4 +- crates/aiken/src/cmd/tx/simulate.rs | 2 +- crates/uplc/src/ast.rs | 8 +- crates/uplc/src/machine.rs | 37 +++++++- crates/uplc/src/machine/eval_result.rs | 24 ++++-- crates/uplc/src/machine/runtime.rs | 16 ++-- crates/uplc/src/tx.rs | 18 ++-- crates/uplc/src/tx/error.rs | 5 +- crates/uplc/src/tx/eval.rs | 14 ++-- crates/uplc/src/tx/tests.rs | 16 ++-- 12 files changed, 128 insertions(+), 104 deletions(-) diff --git a/crates/aiken-lang/src/test_framework.rs b/crates/aiken-lang/src/test_framework.rs index 57ba0491..e5bc05d1 100644 --- a/crates/aiken-lang/src/test_framework.rs +++ b/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 { #[derive(Debug, Clone, thiserror::Error, miette::Diagnostic)] #[error("Fuzzer exited unexpectedly: {uplc_error}.")] pub struct FuzzerError { - traces: Vec, + logs: Vec, 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() - .into_iter() - .filter(|s| PropertyTest::extract_label(s).is_none()) - .collect(), + .logs(), Ok(Some(counterexample.value)), n - remaining, ), - Err(FuzzerError { traces, uplc_error }) => ( - traces - .into_iter() - .filter(|s| PropertyTest::extract_label(s).is_none()) - .collect(), + Err(FuzzerError { logs, uplc_error }) => ( + logs, 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 - .entry(label) - .and_modify(|count| *count += 1) - .or_insert(1); - } + labels + .entry(label) + .and_modify(|count| *count += 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 { - if s.starts_with('\0') { - Some(s.split_at(1).1.to_string()) - } else { - None - } - } } /// ----- Benchmark ----------------------------------------------------------------- @@ -498,21 +482,21 @@ pub struct Sampler { pub enum BenchmarkError { #[error("Sampler exited unexpectedly: {uplc_error}.")] SamplerError { - traces: Vec, + logs: Vec, uplc_error: uplc::machine::Error, }, #[error("Bench exited unexpectedly: {uplc_error}.")] BenchError { - traces: Vec, + logs: Vec, uplc_error: uplc::machine::Error, }, } impl BenchmarkError { - pub fn traces(&self) -> &[String] { + pub fn logs(&self) -> &[String] { match self { - BenchmarkError::SamplerError { traces, .. } - | BenchmarkError::BenchError { traces, .. } => traces.as_slice(), + BenchmarkError::SamplerError { logs, .. } + | 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() - .into_iter() - .filter(|s| PropertyTest::extract_label(s).is_none()) - .collect(), + logs: result.logs(), uplc_error, }); } } } - Err(FuzzerError { traces, uplc_error }) => { - error = Some(BenchmarkError::SamplerError { traces, uplc_error }); + Err(FuzzerError { logs, 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 TestResult { } } - pub fn traces(&self) -> &[String] { + pub fn logs(&self) -> &[String] { match self { - TestResult::UnitTestResult(UnitTestResult { traces, .. }) - | TestResult::PropertyTestResult(PropertyTestResult { traces, .. }) => traces, + TestResult::UnitTestResult(UnitTestResult { logs, .. }) + | 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 TestResult { pub struct UnitTestResult { pub success: bool, pub spent_budget: ExBudget, - pub traces: Vec, + pub logs: Vec, pub test: UnitTest, pub assertion: Option>, } @@ -1196,7 +1176,7 @@ impl UnitTestResult<(Constant, Rc)> { 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 { pub counterexample: Result, uplc::machine::Error>, pub iterations: usize, pub labels: BTreeMap, - pub traces: Vec, + pub logs: Vec, } unsafe impl Send for PropertyTestResult {} @@ -1249,7 +1229,7 @@ impl PropertyTestResult { iterations: self.iterations, test: self.test, labels: self.labels, - traces: self.traces, + logs: self.logs, } } } diff --git a/crates/aiken-project/src/telemetry/json.rs b/crates/aiken-project/src/telemetry/json.rs index f2f0893b..8a892b0b 100644 --- a/crates/aiken-project/src/telemetry/json.rs +++ b/crates/aiken-project/src/telemetry/json.rs @@ -129,8 +129,8 @@ fn fmt_test_json(result: &TestResult) -> serde_json::V TestResult::BenchmarkResult(_) => unreachable!("benchmark returned in JSON output"), } - if !result.traces().is_empty() { - test["traces"] = json!(result.traces()); + if !result.logs().is_empty() { + test["traces"] = json!(result.logs()); } test diff --git a/crates/aiken-project/src/telemetry/terminal.rs b/crates/aiken-project/src/telemetry/terminal.rs index 2be6bc52..83015d93 100644 --- a/crates/aiken-project/src/telemetry/terminal.rs +++ b/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::>() diff --git a/crates/aiken/src/cmd/tx/simulate.rs b/crates/aiken/src/cmd/tx/simulate.rs index d89e7b00..142b5d05 100644 --- a/crates/aiken/src/cmd/tx/simulate.rs +++ b/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 = redeemers .iter() - .map(|curr| ExBudget { + .map(|(curr, _)| ExBudget { mem: curr.ex_units.mem as i64, cpu: curr.ex_units.steps as i64, }) diff --git a/crates/uplc/src/ast.rs b/crates/uplc/src/ast.rs index 87f12fae..e1b623d4 100644 --- a/crates/uplc/src/ast.rs +++ b/crates/uplc/src/ast.rs @@ -856,7 +856,7 @@ impl Program { term, machine.ex_budget, initial_budget, - machine.logs, + machine.traces, machine.spend_counter.map(|i| i.into()), ) } @@ -871,7 +871,7 @@ impl Program { term, machine.ex_budget, initial_budget, - machine.logs, + machine.traces, machine.spend_counter.map(|i| i.into()), ) } @@ -897,7 +897,7 @@ impl Program { term, machine.ex_budget, budget, - machine.logs, + machine.traces, machine.spend_counter.map(|i| i.into()), ) } @@ -916,7 +916,7 @@ impl Program { term, machine.ex_budget, initial_budget, - machine.logs, + machine.traces, machine.spend_counter.map(|i| i.into()), ) } diff --git a/crates/uplc/src/machine.rs b/crates/uplc/src/machine.rs index 2d19a854..c976bbb0 100644 --- a/crates/uplc/src/machine.rs +++ b/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 { + match self { + Trace::Log(log) => Some(log), + _ => None, + } + } + + pub fn unwrap_label(self) -> Option { + 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, pub spend_counter: Option<[i64; (TERM_COUNT + BUILTIN_COUNT) * 2]>, - pub logs: Vec, 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 { diff --git a/crates/uplc/src/machine/eval_result.rs b/crates/uplc/src/machine/eval_result.rs index 58043220..9fbddceb 100644 --- a/crates/uplc/src/machine/eval_result.rs +++ b/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, Error>, remaining_budget: ExBudget, initial_budget: ExBudget, - logs: Vec, + traces: Vec, debug_cost: Option>, } @@ -15,14 +15,14 @@ impl EvalResult { result: Result, Error>, remaining_budget: ExBudget, initial_budget: ExBudget, - logs: Vec, + traces: Vec, debug_cost: Option>, ) -> 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 { + std::mem::take(&mut self.traces) + } + pub fn logs(&mut self) -> Vec { - 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 { + std::mem::take(&mut self.traces) + .into_iter() + .filter_map(Trace::unwrap_label) + .collect() } pub fn failed(&self, can_error: bool) -> bool { diff --git a/crates/uplc/src/machine/runtime.rs b/crates/uplc/src/machine/runtime.rs index c55dd859..823069f6 100644 --- a/crates/uplc/src/machine/runtime.rs +++ b/crates/uplc/src/machine/runtime.rs @@ -1,7 +1,5 @@ use super::{ - cost_model::{BuiltinCosts, ExBudget}, - value::{from_pallas_bigint, to_pallas_bigint}, - Error, Value, + cost_model::{BuiltinCosts, ExBudget}, value::{from_pallas_bigint, to_pallas_bigint}, Error, Trace, 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) -> Result { - self.fun.call(language.into(), &self.args, logs) + pub fn call(&self, language: &Language, traces: &mut Vec) -> Result { + 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, + traces: &mut Vec, ) -> Result { 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()) } diff --git a/crates/uplc/src/tx.rs b/crates/uplc/src/tx.rs index bb790d2b..69d76a2e 100644 --- a/crates/uplc/src/tx.rs +++ b/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, Error> { +) -> Result, 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>, Error> { +) -> Result, 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() - .map(|r| r.encode_fragment().unwrap()) + .into_iter() + .map(|(r, e)| (r.encode_fragment().unwrap(), e)) .collect()), Err(err) => Err(err), } diff --git a/crates/uplc/src/tx/error.rs b/crates/uplc/src/tx/error.rs index 17308fa1..61622f17 100644 --- a/crates/uplc/src/tx/error.rs +++ b/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), + Machine(machine::Error, ExBudget, Vec), #[error("native script can't be executed in phase-two")] NativeScriptPhaseTwo, diff --git a/crates/uplc/src/tx/eval.rs b/crates/uplc/src/tx/eval.rs index f9adf3b2..b1259d9c 100644 --- a/crates/uplc/src/tx/eval.rs +++ b/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 { +) -> 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, - ) -> Result { + ) -> 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() { - Ok(_) => (), - Err(err) => return Err(Error::Machine(err, cost, logs)), + if let Err(err) = eval_result.result() { + return Err(Error::Machine(err, cost, eval_result.traces())); } let new_redeemer = Redeemer { @@ -73,7 +71,7 @@ pub fn eval_redeemer( }, }; - Ok(new_redeemer) + Ok((new_redeemer, eval_result)) } let program = |script: Bytes| { diff --git a/crates/uplc/src/tx/tests.rs b/crates/uplc/src/tx/tests.rs index d239fb6f..40a83397 100644 --- a/crates/uplc/src/tx/tests.rs +++ b/crates/uplc/src/tx/tests.rs @@ -254,7 +254,7 @@ fn test_eval_0() { let total_budget_used: Vec = 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 = 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 = 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 = 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 = 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 = 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 = 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 = redeemers .iter() - .map(|curr| ExBudget { + .map(|(curr, _)| ExBudget { mem: curr.ex_units.mem as i64, cpu: curr.ex_units.steps as i64, })