better error messages + cleaner printing of file stats + tracing

instrumentation in `execute_interaction`

simulator/generation/property.rs

@@ -289,20 +289,6 @@ impl Property {
                     }),
                 });
 
-                let assertion = Interaction::Assertion(Assertion {
-                    message: format!(
-                        "select '{}' should return no values for table '{}'",
-                        predicate, table,
-                    ),
-                    func: Box::new(move |stack: &Vec<ResultSet>, _: &SimulatorEnv| {
-                        let rows = stack.last().unwrap();
-                        match rows {
-                            Ok(rows) => Ok(rows.is_empty()),
-                            Err(err) => Err(LimboError::InternalError(err.to_string())),
-                        }
-                    }),
-                });
-
                 let delete = Interaction::Query(Query::Delete(Delete {
                     table: table.clone(),
                     predicate: predicate.clone(),
@@ -316,6 +302,17 @@ impl Property {
                     distinct: Distinctness::All,
                 }));
 
+                let assertion = Interaction::Assertion(Assertion {
+                    message: format!("`{}` should return no values for table `{}`", select, table,),
+                    func: Box::new(move |stack: &Vec<ResultSet>, _: &SimulatorEnv| {
+                        let rows = stack.last().unwrap();
+                        match rows {
+                            Ok(rows) => Ok(rows.is_empty()),
+                            Err(err) => Err(LimboError::InternalError(err.to_string())),
+                        }
+                    }),
+                });
+
                 let mut interactions = Vec::new();
                 interactions.push(assumption);
                 interactions.push(delete);

simulator/main.rs

@@ -17,6 +17,7 @@ use std::fs::OpenOptions;
 use std::io::Write;
 use std::path::{Path, PathBuf};
 use std::sync::{mpsc, Arc, Mutex};
+use tracing_subscriber::field::MakeExt;
 use tracing_subscriber::EnvFilter;
 use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt};
 
@@ -359,6 +360,8 @@ fn run_simulator(
                     ) => {
                         if e1 != e2 {
                             tracing::error!(
+                                ?shrunk,
+                                ?result,
                                 "shrinking failed, the error was not properly reproduced"
                             );
                             if let Some(bugbase) = bugbase {
@@ -391,7 +394,11 @@ fn run_simulator(
                         unreachable!("shrinking should never be called on a correct simulation")
                     }
                     _ => {
-                        tracing::error!("shrinking failed, the error was not properly reproduced");
+                        tracing::error!(
+                            ?shrunk,
+                            ?result,
+                            "shrinking failed, the error was not properly reproduced"
+                        );
                         if let Some(bugbase) = bugbase {
                             bugbase
                                 .add_bug(seed, plans[0].clone(), Some(error.clone()), cli_opts)
@@ -701,7 +708,8 @@ fn init_logger() {
                 .with_ansi(true)
                 .with_line_number(true)
                 .without_time()
-                .with_thread_ids(false),
+                .with_thread_ids(false)
+                .map_fmt_fields(|f| f.debug_alt()),
         )
         .with(EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info")))
         .with(
@@ -710,7 +718,8 @@ fn init_logger() {
                 .with_ansi(false)
                 .with_line_number(true)
                 .without_time()
-                .with_thread_ids(false),
+                .with_thread_ids(false)
+                .map_fmt_fields(|f| f.debug_alt()),
         )
         .try_init();
 }

simulator/runner/execution.rs

@@ -1,6 +1,7 @@
 use std::sync::{Arc, Mutex};
 
 use limbo_core::{LimboError, Result};
+use tracing::instrument;
 
 use crate::generation::{
     pick_index,
@@ -173,17 +174,15 @@ pub(crate) enum ExecutionContinuation {
     NextProperty,
 }
 
+#[instrument(skip(env, interaction, stack), fields(interaction = %interaction))]
 pub(crate) fn execute_interaction(
     env: &mut SimulatorEnv,
     connection_index: usize,
     interaction: &Interaction,
     stack: &mut Vec<ResultSet>,
 ) -> Result<ExecutionContinuation> {
-    tracing::info!(
-        "execute_interaction(connection_index={}, interaction={})",
-        connection_index,
-        interaction
-    );
+    // Leave this empty info! here to print the span of the execution
+    tracing::info!("");
     match interaction {
         Interaction::Query(_) => {
             let conn = match &mut env.connections[connection_index] {
@@ -192,7 +191,6 @@ pub(crate) fn execute_interaction(
                 SimConnection::Disconnected => unreachable!(),
             };
 
-            tracing::debug!("{}", interaction);
             let results = interaction.execute_query(conn, &env.io);
             tracing::debug!("{:?}", results);
             stack.push(results);

simulator/runner/file.rs

@@ -31,30 +31,34 @@ impl SimulatorFile {
         self.fault.replace(fault);
     }
 
-    pub(crate) fn print_stats(&self) {
-        tracing::info!("op           calls   faults");
-        tracing::info!("--------- -------- --------");
-        tracing::info!(
-            "pread     {:8} {:8}",
-            *self.nr_pread_calls.borrow(),
-            *self.nr_pread_faults.borrow()
-        );
-        tracing::info!(
-            "pwrite    {:8} {:8}",
-            *self.nr_pwrite_calls.borrow(),
-            *self.nr_pwrite_faults.borrow()
-        );
-        tracing::info!(
-            "sync      {:8} {:8}",
-            *self.nr_sync_calls.borrow(),
-            0 // No fault counter for sync
-        );
-        tracing::info!("--------- -------- --------");
+    pub(crate) fn stats_table(&self) -> String {
         let sum_calls = *self.nr_pread_calls.borrow()
             + *self.nr_pwrite_calls.borrow()
             + *self.nr_sync_calls.borrow();
         let sum_faults = *self.nr_pread_faults.borrow() + *self.nr_pwrite_faults.borrow();
-        tracing::info!("total     {:8} {:8}", sum_calls, sum_faults);
+        let stats_table = [
+            "op           calls   faults".to_string(),
+            "--------- -------- --------".to_string(),
+            format!(
+                "pread     {:8} {:8}",
+                *self.nr_pread_calls.borrow(),
+                *self.nr_pread_faults.borrow()
+            ),
+            format!(
+                "pwrite    {:8} {:8}",
+                *self.nr_pwrite_calls.borrow(),
+                *self.nr_pwrite_faults.borrow()
+            ),
+            format!(
+                "sync      {:8} {:8}",
+                *self.nr_sync_calls.borrow(),
+                0 // No fault counter for sync
+            ),
+            "--------- -------- --------".to_string(),
+            format!("total     {:8} {:8}", sum_calls, sum_faults),
+        ];
+        let table = stats_table.join("\n");
+        table
     }
 }
 

simulator/runner/io.rs

@@ -45,9 +45,7 @@ impl SimulatorIO {
     pub(crate) fn print_stats(&self) {
         tracing::info!("run_once faults: {}", self.nr_run_once_faults.borrow());
         for file in self.files.borrow().iter() {
-            tracing::info!("");
-            tracing::info!("===========================");
-            file.print_stats();
+            tracing::info!("\n===========================\n{}", file.stats_table());
         }
     }
 }