Print instruction on trace errors (#201)

air/src/execution_step/air/ap.rs

@@ -41,7 +41,7 @@ impl<'i> super::ExecutableInstruction<'i> for Ap<'i> {
         let should_touch_trace = should_touch_trace(self);
 
         let merger_ap_result = if should_touch_trace {
-            let merger_ap_result = trace_to_exec_err!(trace_ctx.meet_ap_start())?;
+            let merger_ap_result = trace_to_exec_err!(trace_ctx.meet_ap_start(), self)?;
             try_match_trace_to_instr(&merger_ap_result, self)?;
             merger_ap_result
         } else {

air/src/execution_step/air/call.rs

@@ -44,7 +44,7 @@ impl<'i> super::ExecutableInstruction<'i> for Call<'i> {
             .map_err(|e| set_last_error(self, exec_ctx, e, None))?;
 
         let tetraplet = resolved_call.as_tetraplet();
-        joinable!(resolved_call.execute(exec_ctx, trace_ctx), exec_ctx)
+        joinable!(resolved_call.execute(self, exec_ctx, trace_ctx), exec_ctx)
             .map_err(|e| set_last_error(self, exec_ctx, e, Some(tetraplet)))
     }
 }

air/src/execution_step/air/call/resolved_call.rs

@@ -67,8 +67,13 @@ impl<'i> ResolvedCall<'i> {
     }
 
     /// Executes resolved instruction, updates contexts based on a execution_step result.
-    pub(super) fn execute(&self, exec_ctx: &mut ExecutionCtx<'i>, trace_ctx: &mut TraceHandler) -> ExecutionResult<()> {
-        let state = self.prepare_current_executed_state(exec_ctx, trace_ctx)?;
+    pub(super) fn execute(
+        &self,
+        raw_call: &Call<'i>,
+        exec_ctx: &mut ExecutionCtx<'i>,
+        trace_ctx: &mut TraceHandler,
+    ) -> ExecutionResult<()> {
+        let state = self.prepare_current_executed_state(raw_call, exec_ctx, trace_ctx)?;
         if !state.should_execute() {
             state.maybe_set_prev_state(trace_ctx);
             return Ok(());
@@ -130,10 +135,11 @@ impl<'i> ResolvedCall<'i> {
     /// Determine whether this call should be really called and adjust prev executed trace accordingly.
     fn prepare_current_executed_state(
         &self,
+        raw_call: &Call<'i>,
         exec_ctx: &mut ExecutionCtx<'i>,
         trace_ctx: &mut TraceHandler,
     ) -> ExecutionResult<StateDescriptor> {
-        let (call_result, trace_pos) = match trace_to_exec_err!(trace_ctx.meet_call_start(&self.output))? {
+        let (call_result, trace_pos) = match trace_to_exec_err!(trace_ctx.meet_call_start(&self.output), raw_call)? {
             MergerCallResult::CallResult { value, trace_pos } => (value, trace_pos),
             MergerCallResult::Empty => return Ok(StateDescriptor::no_previous_state()),
         };

air/src/execution_step/air/fold_stream.rs

@@ -40,11 +40,11 @@ impl<'i> ExecutableInstruction<'i> for FoldStream<'i> {
 
         let fold_id = exec_ctx.tracker.fold.seen_stream_count;
 
-        trace_to_exec_err!(trace_ctx.meet_fold_start(fold_id))?;
+        trace_to_exec_err!(trace_ctx.meet_fold_start(fold_id), self)?;
 
         let result = execute_iterations(iterables, self, fold_id, exec_ctx, trace_ctx);
 
-        trace_to_exec_err!(trace_ctx.meet_fold_end(fold_id))?;
+        trace_to_exec_err!(trace_ctx.meet_fold_end(fold_id), self)?;
 
         result
     }
@@ -66,7 +66,7 @@ fn execute_iterations<'i>(
         };
 
         let value_pos = value.pos();
-        trace_to_exec_err!(trace_ctx.meet_iteration_start(fold_id, value_pos))?;
+        trace_to_exec_err!(trace_ctx.meet_iteration_start(fold_id, value_pos), fold_stream)?;
         let result = fold(
             iterable,
             IterableType::Stream(fold_id),
@@ -75,7 +75,7 @@ fn execute_iterations<'i>(
             exec_ctx,
             trace_ctx,
         );
-        trace_to_exec_err!(trace_ctx.meet_generation_end(fold_id))?;
+        trace_to_exec_err!(trace_ctx.meet_generation_end(fold_id), fold_stream)?;
 
         result?;
         if !exec_ctx.subtree_complete {

air/src/execution_step/air/next.rs

@@ -30,48 +30,63 @@ impl<'i> super::ExecutableInstruction<'i> for Next<'i> {
 
         let iterator_name = &self.iterator.name;
         let fold_state = exec_ctx.scalars.get_iterable_mut(iterator_name)?;
-        maybe_meet_iteration_end(fold_state, trace_ctx)?;
+        maybe_meet_iteration_end(self, fold_state, trace_ctx)?;
 
         if !fold_state.iterable.next() {
-            maybe_meet_back_iterator(fold_state, trace_ctx)?;
+            maybe_meet_back_iterator(self, fold_state, trace_ctx)?;
 
             // just do nothing to exit
             return Ok(());
         }
 
         let next_instr = fold_state.instr_head.clone();
-        maybe_meet_iteration_start(fold_state, trace_ctx)?;
+        maybe_meet_iteration_start(self, fold_state, trace_ctx)?;
 
         next_instr.execute(exec_ctx, trace_ctx)?;
 
         // get the same fold state again because of borrow checker
         let fold_state = exec_ctx.scalars.get_iterable_mut(iterator_name)?;
         fold_state.iterable.prev();
-        maybe_meet_back_iterator(fold_state, trace_ctx)?;
+        maybe_meet_back_iterator(self, fold_state, trace_ctx)?;
 
         Ok(())
     }
 }
 
-fn maybe_meet_iteration_start(fold_state: &FoldState<'_>, trace_ctx: &mut TraceHandler) -> ExecutionResult<()> {
+fn maybe_meet_iteration_start<'i>(
+    next: &Next<'i>,
+    fold_state: &FoldState<'i>,
+    trace_ctx: &mut TraceHandler,
+) -> ExecutionResult<()> {
     if let IterableType::Stream(fold_id) = &fold_state.iterable_type {
-        trace_to_exec_err!(trace_ctx.meet_iteration_start(*fold_id, fold_state.iterable.peek().unwrap().pos()))?;
+        trace_to_exec_err!(
+            trace_ctx.meet_iteration_start(*fold_id, fold_state.iterable.peek().unwrap().pos()),
+            next
+        )?;
     }
 
     Ok(())
 }
 
-fn maybe_meet_iteration_end(fold_state: &FoldState<'_>, trace_ctx: &mut TraceHandler) -> ExecutionResult<()> {
+fn maybe_meet_iteration_end<'i>(
+    next: &Next<'i>,
+    fold_state: &FoldState<'i>,
+    trace_ctx: &mut TraceHandler,
+) -> ExecutionResult<()> {
     if let IterableType::Stream(fold_id) = &fold_state.iterable_type {
-        trace_to_exec_err!(trace_ctx.meet_iteration_end(*fold_id))?;
+        trace_to_exec_err!(trace_ctx.meet_iteration_end(*fold_id), next)?;
     }
 
     Ok(())
 }
 
-fn maybe_meet_back_iterator(fold_state: &FoldState<'_>, trace_ctx: &mut TraceHandler) -> ExecutionResult<()> {
+fn maybe_meet_back_iterator<'i>(
+    next: &Next<'i>,
+    fold_state: &FoldState<'i>,
+    trace_ctx: &mut TraceHandler,
+) -> ExecutionResult<()> {
     if let IterableType::Stream(fold_id) = &fold_state.iterable_type {
-        trace_to_exec_err!(trace_ctx.meet_back_iterator(*fold_id))?;
+        trace_to_exec_err!(trace_ctx.meet_back_iterator(*fold_id), next)?;
     }
 
     Ok(())

air/src/execution_step/air/par.rs

@@ -35,13 +35,13 @@ impl<'i> ExecutableInstruction<'i> for Par<'i> {
         log_instruction!(par, exec_ctx, trace_ctx);
 
         let mut completeness_updater = ParCompletenessUpdater::new();
-        trace_to_exec_err!(trace_ctx.meet_par_start())?;
+        trace_to_exec_err!(trace_ctx.meet_par_start(), self)?;
 
         // execute a left subtree of par
-        let left_result = execute_subtree(&self.0, exec_ctx, trace_ctx, &mut completeness_updater, SubtreeType::Left)?;
+        let left_result = execute_subtree(&self, exec_ctx, trace_ctx, &mut completeness_updater, SubtreeType::Left)?;
 
         // execute a right subtree of par
-        let right_result = execute_subtree(&self.1, exec_ctx, trace_ctx, &mut completeness_updater, SubtreeType::Right)?;
+        let right_result = execute_subtree(&self, exec_ctx, trace_ctx, &mut completeness_updater, SubtreeType::Right)?;
 
         completeness_updater.set_completeness(exec_ctx);
         prepare_par_result(left_result, right_result, exec_ctx)
@@ -50,23 +50,27 @@ impl<'i> ExecutableInstruction<'i> for Par<'i> {
 
 /// Execute provided subtree and update Par state in trace_ctx.new_trace.
 fn execute_subtree<'i>(
-    subtree: &Instruction<'i>,
+    par: &Par<'i>,
     exec_ctx: &mut ExecutionCtx<'i>,
     trace_ctx: &mut TraceHandler,
     completeness_updater: &mut ParCompletenessUpdater,
     subtree_type: SubtreeType,
 ) -> ExecutionResult<SubtreeResult> {
+    let subtree = match subtree_type {
+        SubtreeType::Left => &par.0,
+        SubtreeType::Right => &par.1,
+    };
     exec_ctx.subtree_complete = determine_subtree_complete(subtree);
 
     // execute a subtree
     let result = match subtree.execute(exec_ctx, trace_ctx) {
         Ok(_) => {
-            trace_to_exec_err!(trace_ctx.meet_par_subtree_end(subtree_type))?;
+            trace_to_exec_err!(trace_ctx.meet_par_subtree_end(subtree_type), par)?;
             SubtreeResult::Succeeded
         }
         Err(e) if e.is_catchable() => {
             exec_ctx.subtree_complete = false;
-            trace_to_exec_err!(trace_ctx.meet_par_subtree_end(subtree_type))?;
+            trace_to_exec_err!(trace_ctx.meet_par_subtree_end(subtree_type), par)?;
             SubtreeResult::Failed(e)
         }
         Err(e) => {

air/src/execution_step/errors/execution_errors.rs

@@ -62,9 +62,12 @@ impl From<CatchableError> for ExecutionError {
 
 #[macro_export]
 macro_rules! trace_to_exec_err {
-    ($trace_expr: expr) => {
-        $trace_expr.map_err(|e| {
-            crate::execution_step::ExecutionError::Uncatchable(crate::execution_step::UncatchableError::TraceError(e))
+    ($trace_expr: expr, $instruction: ident) => {
+        $trace_expr.map_err(|trace_error| {
+            crate::execution_step::ExecutionError::Uncatchable(crate::execution_step::UncatchableError::TraceError {
+                trace_error,
+                instruction: $instruction.to_string(),
+            })
         })
     };
 }

air/src/execution_step/errors/uncatchable_errors.rs

@@ -32,8 +32,11 @@ use thiserror::Error as ThisError;
 #[strum_discriminants(derive(EnumIter))]
 pub enum UncatchableError {
     /// Errors bubbled from a trace handler.
-    #[error(transparent)]
-    TraceError(#[from] TraceHandlerError),
+    #[error("on instruction '{instruction}' trace handler encountered an error: {trace_error}")]
+    TraceError {
+        trace_error: TraceHandlerError,
+        instruction: String,
+    },
 
     /// Fold state wasn't found for such iterator name.
     #[error("fold state not found for this iterable '{0}'")]
@@ -49,7 +52,7 @@ pub enum UncatchableError {
 
     /// Errors occurred when result from data doesn't match to a instruction, f.e. an instruction
     /// could be applied to a stream, but result doesn't contain generation in a source position.
-    #[error("ap result {0:?} doesn't match corresponding instruction")]
+    #[error("ap result {0:?} doesn't match with corresponding instruction")]
     ApResultNotCorrespondToInstr(MergerApResult),
 
     /// Multiple values for such name found.

air/tests/test_module/integration/streams_early_exit.rs

@@ -144,8 +144,8 @@ fn par_early_exit() {
     let setter_3_malicious_data = raw_data_from_trace(setter_3_malicious_trace);
     let init_result_3 = call_vm!(init, "", &script, init_result_2.data.clone(), setter_3_malicious_data);
 
-    let expected_error = UncatchableError::TraceError(TraceHandlerError::MergeError(MergeError::IncorrectCallResult(
-        CallResultError::ValuesNotEqual {
+    let expected_error = UncatchableError::TraceError {
+        trace_error: TraceHandlerError::MergeError(MergeError::IncorrectCallResult(CallResultError::ValuesNotEqual {
             prev_value: Value::Stream {
                 value: rc!(json!("1")),
                 generation: 0,
@@ -154,8 +154,9 @@ fn par_early_exit() {
                 value: rc!(json!("non_exist_value")),
                 generation: 0,
             },
-        },
-    )));
+        })),
+        instruction: r#"call "setter_1" ("" "") [] $stream"#.to_string(),
+    };
     assert!(check_error(&init_result_3, expected_error));
 
     let actual_trace = trace_from_result(&init_result_3);

crates/air-lib/test-utils/src/lib.rs

@@ -122,12 +122,5 @@ pub fn is_interpreter_succeded(result: &RawAVMOutcome) -> bool {
 }
 
 pub fn check_error(result: &RawAVMOutcome, error: impl ToErrorCode + ToString) -> bool {
-    println!(
-        "{} == {} || {} == {}",
-        result.ret_code,
-        error.to_error_code(),
-        result.error_message,
-        error.to_string()
-    );
     result.ret_code == error.to_error_code() && result.error_message == error.to_string()
 }