Improve error reporting in BlockMachineProcessor (#2279)

Extracted from #2275.

This PR makes it easier to debug failing code generation in
`BlockMachineProcessor` by printing the code generated so far.

Example:
```
$ RUST_LOG=debug cargo run pil test_data/std/binary_large_test.asm -o output -f
...
Code generation failed for connection:
  main::instr_and $ [0, main::X0, main::X1, main::X2] is main_binary::latch * main_binary::sel[0] $ [main_binary::operation_id, main_binary::A, main_binary::B, main_binary::C]
Known arguments:
  main_binary::operation_id
  main_binary::A
  main_binary::B
Error:
  Unable to derive algorithm to compute output value "main_binary::C"
The following code was generated so far:
main_binary::sel[0][3] = 1;
main_binary::operation_id[3] = params[0];
main_binary::A[3] = params[1];
main_binary::B[3] = params[2];
main_binary::operation_id[2] = main_binary::operation_id[3];
main_binary::operation_id_next[2] = main_binary::operation_id[3];
main_binary::operation_id[1] = main_binary::operation_id[2];
main_binary::operation_id_next[1] = main_binary::operation_id[2];
main_binary::operation_id[0] = main_binary::operation_id[1];
main_binary::operation_id_next[0] = main_binary::operation_id[1];
...
```

executor/src/witgen/data_structures/mutable_state.rs

@@ -46,18 +46,14 @@ impl<'a, T: FieldElement, Q: QueryCallback<T>> MutableState<'a, T, Q> {
     pub fn get_machine(&self, substring: &str) -> &RefCell<KnownMachine<'a, T>> {
         use itertools::Itertools;
 
-        match self
-            .machines
+        self.machines
             .iter()
             .filter(|m| m.borrow().name().contains(substring))
             .exactly_one()
-        {
-            Ok(m) => m,
-            // Calling unwrap() would require KnownMachine to implement Debug.
-            Err(e) => {
-                panic!("Expected exactly one machine with substring '{substring}', but found {e}.",)
-            }
-        }
+            .map_err(|e| {
+                format!("Expected exactly one machine with substring '{substring}', but found {e}.")
+            })
+            .unwrap()
     }
 
     /// Runs the first machine (unless there are no machines) end returns the generated columns.

executor/src/witgen/jit/block_machine_processor.rs

@@ -1,10 +1,11 @@
 use std::collections::HashSet;
 
 use bit_vec::BitVec;
-use powdr_ast::analyzed::{AlgebraicReference, Identity};
+use itertools::Itertools;
+use powdr_ast::analyzed::{AlgebraicReference, Identity, SelectedExpressions};
 use powdr_number::FieldElement;
 
-use crate::witgen::{machines::MachineParts, FixedData};
+use crate::witgen::{jit::effect::format_code, machines::MachineParts, FixedData};
 
 use super::{
     effect::Effect,
@@ -43,8 +44,8 @@ impl<'a, T: FieldElement> BlockMachineProcessor<'a, T> {
         identity_id: u64,
         known_args: &BitVec,
     ) -> Result<Vec<Effect<T, Variable>>, String> {
-        let connection_rhs = self.machine_parts.connections[&identity_id].right;
-        assert_eq!(connection_rhs.expressions.len(), known_args.len());
+        let connection = self.machine_parts.connections[&identity_id];
+        assert_eq!(connection.right.expressions.len(), known_args.len());
 
         // Set up WitgenInference with known arguments.
         let known_variables = known_args
@@ -55,26 +56,33 @@ impl<'a, T: FieldElement> BlockMachineProcessor<'a, T> {
         let mut witgen = WitgenInference::new(self.fixed_data, self, known_variables);
 
         // In the latch row, set the RHS selector to 1.
-        witgen.assign_constant(&connection_rhs.selector, self.latch_row as i32, T::one());
+        witgen.assign_constant(&connection.right.selector, self.latch_row as i32, T::one());
 
         // For each argument, connect the expression on the RHS with the formal parameter.
-        for (index, expr) in connection_rhs.expressions.iter().enumerate() {
+        for (index, expr) in connection.right.expressions.iter().enumerate() {
             witgen.assign_variable(expr, self.latch_row as i32, Variable::Param(index));
         }
 
         // Solve for the block witness.
         // Fails if any machine call cannot be completed.
-        self.solve_block(can_process, &mut witgen)?;
-
-        for (index, expr) in connection_rhs.expressions.iter().enumerate() {
-            if !witgen.is_known(&Variable::Param(index)) {
-                return Err(format!(
-                    "Unable to derive algorithm to compute output value \"{expr}\""
-                ));
+        match self.solve_block(can_process, &mut witgen, connection.right) {
+            Ok(()) => Ok(witgen.code()),
+            Err(e) => {
+                log::debug!("\nCode generation failed for connection:\n  {connection}");
+                let known_args_str = known_args
+                    .iter()
+                    .enumerate()
+                    .filter_map(|(i, b)| b.then_some(connection.right.expressions[i].to_string()))
+                    .join("\n  ");
+                log::debug!("Known arguments:\n  {known_args_str}");
+                log::debug!("Error:\n  {e}");
+                log::debug!(
+                    "The following code was generated so far:\n{}",
+                    format_code(witgen.code().as_slice())
+                );
+                Err(format!("Code generation failed: {e}\nRun with RUST_LOG=debug to see the code generated so far."))
             }
         }
-
-        Ok(witgen.code())
     }
 
     /// Repeatedly processes all identities on all rows, until no progress is made.
@@ -83,6 +91,7 @@ impl<'a, T: FieldElement> BlockMachineProcessor<'a, T> {
         &self,
         can_process: CanProcess,
         witgen: &mut WitgenInference<'a, T, &Self>,
+        connection_rhs: &SelectedExpressions<T>,
     ) -> Result<(), String> {
         let mut complete = HashSet::new();
         for iteration in 0.. {
@@ -108,6 +117,14 @@ impl<'a, T: FieldElement> BlockMachineProcessor<'a, T> {
             }
         }
 
+        for (index, expr) in connection_rhs.expressions.iter().enumerate() {
+            if !witgen.is_known(&Variable::Param(index)) {
+                return Err(format!(
+                    "Unable to derive algorithm to compute output value \"{expr}\""
+                ));
+            }
+        }
+
         // If any machine call could not be completed, that's bad because machine calls typically have side effects.
         // So, the underlying lookup / permutation / bus argument likely does not hold.
         // TODO: This assumes a rectangular block shape.
@@ -159,11 +176,9 @@ mod test {
     use crate::witgen::{
         data_structures::mutable_state::MutableState,
         global_constraints,
-        jit::{
-            effect::Effect,
-            test_util::{format_code, read_pil},
-        },
+        jit::{effect::Effect, test_util::read_pil},
         machines::{machine_extractor::MachineExtractor, KnownMachine, Machine},
+        FixedData,
     };
 
     use super::*;
@@ -241,15 +256,13 @@ params[2] = Add::c[0];"
         let err_str = generate_for_block_machine(input, "Unconstrained", 2, 1)
             .err()
             .unwrap();
-        assert_eq!(
-            err_str,
-            "Unable to derive algorithm to compute output value \"Unconstrained::c\""
-        );
+        assert!(err_str
+            .contains("Unable to derive algorithm to compute output value \"Unconstrained::c\""));
     }
 
     #[test]
     // TODO: Currently fails, because the machine has a non-rectangular block shape.
-    #[should_panic = "Incomplete machine calls"]
+    #[should_panic = "Unable to derive algorithm to compute output value \\\"main_binary::C\\\""]
     fn binary() {
         let input = read_to_string("../test_data/pil/binary.pil").unwrap();
         generate_for_block_machine(&input, "main_binary", 3, 1).unwrap();

executor/src/witgen/jit/effect.rs

@@ -1,8 +1,9 @@
+use itertools::Itertools;
 use powdr_number::FieldElement;
 
 use crate::witgen::range_constraints::RangeConstraint;
 
-use super::symbolic_expression::SymbolicExpression;
+use super::{symbolic_expression::SymbolicExpression, variable::Variable};
 
 /// The effect of solving a symbolic equation.
 pub enum Effect<T: FieldElement, V> {
@@ -55,3 +56,37 @@ pub enum MachineCallArgument<T: FieldElement, V> {
     Known(SymbolicExpression<T, V>),
     Unknown(V),
 }
+
+/// Helper function to render a list of effects. Used for informational purposes only.
+pub fn format_code<T: FieldElement>(effects: &[Effect<T, Variable>]) -> String {
+    effects
+        .iter()
+        .map(|effect| match effect {
+            Effect::Assignment(v, expr) => format!("{v} = {expr};"),
+            Effect::Assertion(Assertion {
+                lhs,
+                rhs,
+                expected_equal,
+            }) => {
+                format!(
+                    "assert {lhs} {} {rhs};",
+                    if *expected_equal { "==" } else { "!=" }
+                )
+            }
+            Effect::MachineCall(id, args) => {
+                format!(
+                    "machine_call({id}, [{}]);",
+                    args.iter()
+                        .map(|arg| match arg {
+                            MachineCallArgument::Known(k) => format!("Known({k})"),
+                            MachineCallArgument::Unknown(u) => format!("Unknown({u})"),
+                        })
+                        .join(", ")
+                )
+            }
+            Effect::RangeConstraint(..) => {
+                panic!("Range constraints should not be part of the code.")
+            }
+        })
+        .join("\n")
+}

executor/src/witgen/jit/test_util.rs

@@ -1,47 +1,8 @@
-use itertools::Itertools;
 use powdr_ast::analyzed::Analyzed;
 use powdr_executor_utils::VariablySizedColumn;
-use powdr_number::{FieldElement, GoldilocksField};
+use powdr_number::FieldElement;
 
-use crate::{constant_evaluator, witgen::jit::effect::MachineCallArgument};
-
-use super::{
-    effect::{Assertion, Effect},
-    variable::Variable,
-};
-
-pub fn format_code(effects: &[Effect<GoldilocksField, Variable>]) -> String {
-    effects
-        .iter()
-        .map(|effect| match effect {
-            Effect::Assignment(v, expr) => format!("{v} = {expr};"),
-            Effect::Assertion(Assertion {
-                lhs,
-                rhs,
-                expected_equal,
-            }) => {
-                format!(
-                    "assert {lhs} {} {rhs};",
-                    if *expected_equal { "==" } else { "!=" }
-                )
-            }
-            Effect::MachineCall(id, args) => {
-                format!(
-                    "machine_call({id}, [{}]);",
-                    args.iter()
-                        .map(|arg| match arg {
-                            MachineCallArgument::Known(k) => format!("Known({k})"),
-                            MachineCallArgument::Unknown(u) => format!("Unknown({u})"),
-                        })
-                        .join(", ")
-                )
-            }
-            Effect::RangeConstraint(..) => {
-                panic!("Range constraints should not be part of the code.")
-            }
-        })
-        .join("\n")
-}
+use crate::constant_evaluator;
 
 pub fn read_pil<T: FieldElement>(
     input_pil: &str,

executor/src/witgen/jit/witgen_inference.rs

@@ -473,15 +473,13 @@ impl<T: FieldElement, Q: QueryCallback<T>> CanProcessCall<T> for &MutableState<'
 
 #[cfg(test)]
 mod test {
+    use powdr_number::GoldilocksField;
     use pretty_assertions::assert_eq;
     use test_log::test;
 
     use crate::witgen::{
         global_constraints,
-        jit::{
-            test_util::{format_code, read_pil},
-            variable::Cell,
-        },
+        jit::{effect::format_code, test_util::read_pil, variable::Cell},
         machines::{Connection, FixedLookup, KnownMachine},
         FixedData,
     };
@@ -504,7 +502,7 @@ mod test {
         known_cells: Vec<(&str, i32)>,
         expected_complete: Option<usize>,
     ) -> String {
-        let (analyzed, fixed_col_vals) = read_pil(input);
+        let (analyzed, fixed_col_vals) = read_pil::<GoldilocksField>(input);
         let fixed_data = FixedData::new(&analyzed, &fixed_col_vals, &[], Default::default(), 0);
         let (fixed_data, retained_identities) =
             global_constraints::set_global_constraints(fixed_data, &analyzed.identities);