add debug logs

air/src/execution_step/air/call.rs

@@ -39,6 +39,7 @@ impl<'i> super::ExecutableInstruction<'i> for Call<'i> {
     fn execute(&self, exec_ctx: &mut ExecutionCtx<'i>, trace_ctx: &mut TraceHandler) -> ExecutionResult<()> {
         log_instruction!(call, exec_ctx, trace_ctx);
         exec_ctx.tracker.meet_call();
+        println!("> {}", self);
 
         let resolved_call = joinable!(ResolvedCall::new(self, exec_ctx), exec_ctx)
             .map_err(|e| set_last_error(self, exec_ctx, e, None))?;

air/src/execution_step/air/fold_stream.rs

@@ -36,6 +36,7 @@ impl<'i> ExecutableInstruction<'i> for FoldStream<'i> {
     fn execute(&self, exec_ctx: &mut ExecutionCtx<'i>, trace_ctx: &mut TraceHandler) -> ExecutionResult<()> {
         log_instruction!(fold, exec_ctx, trace_ctx);
         exec_ctx.tracker.meet_fold_stream();
+        println!("> {}", self);
 
         let iterable = &self.iterable;
         let stream = match exec_ctx.streams.get(iterable.name, iterable.position) {
@@ -46,6 +47,7 @@ impl<'i> ExecutableInstruction<'i> for FoldStream<'i> {
                 return Ok(());
             }
         };
+        println!("  stream {:?}", stream);
 
         let fold_id = exec_ctx.tracker.fold.seen_stream_count;
         trace_to_exec_err!(trace_ctx.meet_fold_start(fold_id), self)?;

air/tests/test_module/issues/issue_999.rs

@@ -19,7 +19,19 @@ use air_test_utils::prelude::*;
 
 #[test]
 fn issue_999() {
-    //env_logger::init();
+    let client_peer_id = "client";
+    let mut client_vm = create_avm(set_variable_call_service(json!([["p1",[[["p1",1],["p2",2],["p3",3]],[["p1",4],["p3",5],["p2",6]]]],["p2",[[["p2",7],["p1",8],["p3",9]],[["p2",10],["p3",11],["p1",12]]]],["p3",[[["p3",13],["p1",14],["p2",15]],[["p3",16],["p2",17],["p1",18]]]]])), client_peer_id);
+
+    let relay_peer_id = "relay";
+    let mut relay_vm = create_avm(echo_call_service(), relay_peer_id);
+
+    let p1 = "p1";
+    let mut p1_vm = create_avm(set_variable_call_service(json!("p1")), p1);
+    let p2 = "p2";
+    let mut p2_vm = create_avm(set_variable_call_service(json!("p2")), p2);
+    let p3 = "p3";
+    let mut p3_vm = create_avm(set_variable_call_service(json!("p3")), p3);
+
     let script = r#"
         (seq
             (seq
@@ -49,7 +61,8 @@ fn issue_999() {
                                             (call pair.$.[0] ("op" "noop") []) ; ok = null
                                             (seq
                                                 (ap pair.$.[1] $result)
-                                                (call pair.$.[0] ("" "") [$result]) ; behaviour = echo
+                                                (null)
+                                                 ; (call pair.$.[0] ("" "") [$result]) ; behaviour = echo
                                             )
                                         )
                                         (next pair)
@@ -92,6 +105,78 @@ fn issue_999() {
         )
         "#;
 
+    let client_result = checked_call_vm!(client_vm, <_>::default(), script, "", "");
+    //println!("client next peer id = {:?}", client_result.next_peer_pks);
+
+    let p1_result_1 = checked_call_vm!(p1_vm, <_>::default(), script, "", client_result.data.clone());
+    //println!("p1 1 next peer id = {:?}", p1_result_1.next_peer_pks);
+
+    let p2_result_1 = checked_call_vm!(p2_vm, <_>::default(), script, "", p1_result_1.data.clone());
+    //println!("p2 1 next peer id = {:?}", p2_result_1.next_peer_pks);
+
+    let p3_result_1 = checked_call_vm!(p3_vm, <_>::default(), script, "", p2_result_1.data.clone());
+    //println!("p3 1 next peer id = {:?}\n", p3_result_1.next_peer_pks);
+    //print_trace(&p3_result_1, "p3 1");
+
+    // p3 -> p2, p1
+    //print_trace(&p1_result_1, "p1 1");
+    //print_trace(&p3_result_1, "p3 1");
+    println!("\n\n\n========\n\n\n");
+    let ddd: InterpreterData = serde_json::from_slice(&p1_result_1.data).unwrap();
+    let ddd1: InterpreterData = serde_json::from_slice(&p3_result_1.data).unwrap();
+    println!("PREV DATA: {:?}", ddd.global_streams);
+    println!("CURRENT DATA: {:?}", ddd1.global_streams);
+    let p1_result_2 = checked_call_vm!(p1_vm, <_>::default(), script, p1_result_1.data.clone(), p3_result_1.data.clone());
+    println!("p1 2 next peer id = {:?}", p1_result_2.next_peer_pks);
+    print_trace(&p1_result_2, "p1 2");
+    /*
+    let p2_result_2 = checked_call_vm!(p2_vm, <_>::default(), script, p2_result_1.data.clone(), p3_result_1.data.clone());
+    println!("p2 2 next peer id = {:?}\n", p2_result_2.next_peer_pks);
+    //print_trace(&p2_result_2, "p2 2");
+
+    // p1 -> p3, p2
+    let p3_result_2 = checked_call_vm!(p3_vm, <_>::default(), script, p3_result_1.data.clone(), p1_result_2.data.clone());
+    println!("p3 2 next peer id = {:?}", p3_result_2.next_peer_pks);
+    let p2_result_3 = checked_call_vm!(p2_vm, <_>::default(), script, p2_result_2.data.clone(), p1_result_2.data.clone());
+    println!("p1 3 next peer id = {:?}\n", p2_result_3.next_peer_pks);
+
+    // p2 -> p3, p1
+    let p3_result_3 = checked_call_vm!(p3_vm, <_>::default(), script, p3_result_2.data.clone(), p2_result_2.data.clone());
+    println!("p3 3 next peer id = {:?}", p3_result_3.next_peer_pks);
+    let p1_result_3 = checked_call_vm!(p1_vm, <_>::default(), script, p1_result_2.data.clone(), p2_result_2.data.clone());
+    println!("p1 3 next peer id = {:?}\n", p1_result_3.next_peer_pks);
+
+    // p3 -> p2
+    // p1 -> p3
+    // p3 -> p1
+    // p1 -> p3
+    let p2_result_4 = checked_call_vm!(p2_vm, <_>::default(), script, p2_result_3.data.clone(), p3_result_3.data.clone());
+    println!("p2 4 next peer id = {:?}", p2_result_4.next_peer_pks);
+    let p3_result_4 = checked_call_vm!(p3_vm, <_>::default(), script, p3_result_3.data.clone(), p1_result_3.data.clone());
+    println!("p3 4 next peer id = {:?}", p3_result_4.next_peer_pks);
+    let p1_result_4 = checked_call_vm!(p1_vm, <_>::default(), script, p1_result_3.data.clone(), p3_result_4.data.clone());
+    println!("p1 4 next peer id = {:?}", p1_result_4.next_peer_pks);
+    let p3_result_5 = checked_call_vm!(p3_vm, <_>::default(), script, p3_result_4.data.clone(), p1_result_4.data.clone());
+    println!("p3 5 next peer id = {:?}\n", p3_result_5.next_peer_pks);
+
+    //print_trace(&p3_result_4, "p3 result 4");
+    //print_trace(&p3_result_5, "p3 result 5");
+
+    // p2 = ["p1", "relay"]
+    // p3 = ["relay"]
+    // p1 = ["p2"]
+    // p3 = []
+    let p1_result_5 = checked_call_vm!(p1_vm, <_>::default(), script, p1_result_4.data.clone(), p2_result_4.data.clone());
+    println!("p1 5 next peer id = {:?}", p1_result_5.next_peer_pks);
+    let relay_result_1 = checked_call_vm!(relay_vm, <_>::default(), script, "", p2_result_4.data.clone());
+    println!("relay 1 next peer id = {:?}", relay_result_1.next_peer_pks);
+    let relay_result_2 = checked_call_vm!(relay_vm, <_>::default(), script, relay_result_1.data.clone(), p3_result_5.data.clone());
+    println!("relay 2 next peer id = {:?}", relay_result_2.next_peer_pks);
+    let p2_result_5 = checked_call_vm!(p2_vm, <_>::default(), script, p2_result_4.data.clone(), p1_result_5.data.clone());
+    println!("p2 5 next peer id = {:?}\n", p2_result_5.next_peer_pks);
+     */
+    //print_trace(&relay_result_2, "relay 2");
+
     /*
     17 - [71, 2], [75, 0]
     20 - [91, 2], [93, 0]
@@ -107,6 +192,7 @@ fn issue_999() {
     64 - [87, 2], [89, 0]
     67 - [89, 2], [91, 0]
      */
+    /*
     let engine = TestExecutor::new(
         TestRunParameters::from_init_peer_id("client"),
         vec![],
@@ -135,6 +221,8 @@ fn issue_999() {
         }
     }
 
+     */
+
 /*
     for cycle in 0..8 {
         for peer in ["client", "relay", "p1", "p2", "p3"] {

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

@@ -90,6 +90,7 @@ impl<R: AirRunner> TestRunner<R> {
 
             next_peer_pks.extend(outcome.next_peer_pks);
 
+            println!("  call_requests: {:?}", outcome.call_requests);
             if outcome.call_requests.is_empty() {
                 outcome.next_peer_pks = next_peer_pks.into_iter().collect::<Vec<_>>();
                 return Ok(outcome);

crates/air-lib/trace-handler/src/handler.rs

@@ -88,7 +88,9 @@ impl TraceHandler {
 impl TraceHandler {
     /// Should be called at the beginning of a call execution.
     pub fn meet_call_start(&mut self) -> TraceHandlerResult<MergerCallResult> {
-        try_merge_next_state_as_call(&mut self.data_keeper).map_err(Into::into)
+        let result = try_merge_next_state_as_call(&mut self.data_keeper).map_err(Into::into);
+        println!("  meet_call_result: {:?}", result);
+        result
     }
 
     /// Should be called when a call instruction was executed successfully. It adds the supplied