diff --git a/Cargo.lock b/Cargo.lock index edfe8b45e..9b6675880 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1968,6 +1968,8 @@ dependencies = [ "rusqlite", "serde", "serde_json", + "tracing", + "tracing-subscriber", ] [[package]] diff --git a/simulator/Cargo.toml b/simulator/Cargo.toml index 991f10866..31200f86e 100644 --- a/simulator/Cargo.toml +++ b/simulator/Cargo.toml @@ -32,3 +32,6 @@ notify = "8.0.0" rusqlite = { version = "0.34", features = ["bundled"] } dirs = "6.0.0" chrono = { version = "0.4.40", features = ["serde"] } +tracing = "0.1.41" +tracing-subscriber = { version = "0.3.19", features = ["env-filter"] } + diff --git a/simulator/generation/plan.rs b/simulator/generation/plan.rs index 6473b9a88..1adc4f94a 100644 --- a/simulator/generation/plan.rs +++ b/simulator/generation/plan.rs @@ -1,17 +1,18 @@ use std::{fmt::Display, path::Path, rc::Rc, vec}; -use limbo_core::{Connection, Result, StepResult}; +use limbo_core::{Connection, Result, StepResult, IO}; use serde::{Deserialize, Serialize}; use crate::{ model::{ query::{ select::{Distinctness, Predicate, ResultColumn}, + update::Update, Create, Delete, Drop, Insert, Query, Select, }, table::Value, }, - runner::env::SimConnection, + runner::{env::SimConnection, io::SimulatorIO}, SimulatorEnv, }; @@ -202,6 +203,7 @@ pub(crate) struct InteractionStats { pub(crate) read_count: usize, pub(crate) write_count: usize, pub(crate) delete_count: usize, + pub(crate) update_count: usize, pub(crate) create_count: usize, pub(crate) drop_count: usize, } @@ -210,10 +212,11 @@ impl Display for InteractionStats { fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { write!( f, - "Read: {}, Write: {}, Delete: {}, Create: {}, Drop: {}", + "Read: {}, Write: {}, Delete: {}, Update: {}, Create: {}, Drop: {}", self.read_count, self.write_count, self.delete_count, + self.update_count, self.create_count, self.drop_count ) @@ -369,6 +372,9 @@ impl Interactions { Query::Select(select) => { select.shadow(env); } + Query::Update(update) => { + update.shadow(env); + } }, Interaction::Assertion(_) => {} Interaction::Assumption(_) => {} @@ -395,6 +401,7 @@ impl InteractionPlan { let mut delete = 0; let mut create = 0; let mut drop = 0; + let mut update = 0; for interactions in &self.plan { match interactions { @@ -407,6 +414,7 @@ impl InteractionPlan { Query::Delete(_) => delete += 1, Query::Create(_) => create += 1, Query::Drop(_) => drop += 1, + Query::Update(_) => update += 1, } } } @@ -417,6 +425,7 @@ impl InteractionPlan { Query::Delete(_) => delete += 1, Query::Create(_) => create += 1, Query::Drop(_) => drop += 1, + Query::Update(_) => update += 1, }, Interactions::Fault(_) => {} } @@ -428,6 +437,7 @@ impl InteractionPlan { delete_count: delete, create_count: create, drop_count: drop, + update_count: update, } } } @@ -446,7 +456,7 @@ impl ArbitraryFrom<&mut SimulatorEnv> for InteractionPlan { .push(Interactions::Query(Query::Create(create_query))); while plan.plan.len() < num_interactions { - log::debug!( + tracing::debug!( "Generating interaction {}/{}", plan.plan.len(), num_interactions @@ -457,7 +467,7 @@ impl ArbitraryFrom<&mut SimulatorEnv> for InteractionPlan { plan.plan.push(interactions); } - log::info!("Generated plan with {} interactions", plan.plan.len()); + tracing::info!("Generated plan with {} interactions", plan.plan.len()); plan } } @@ -469,13 +479,13 @@ impl Interaction { Self::Assumption(_) | Self::Assertion(_) | Self::Fault(_) => vec![], } } - pub(crate) fn execute_query(&self, conn: &mut Rc) -> ResultSet { + pub(crate) fn execute_query(&self, conn: &mut Rc, io: &SimulatorIO) -> ResultSet { if let Self::Query(query) = self { let query_str = query.to_string(); let rows = conn.query(&query_str); if rows.is_err() { let err = rows.err(); - log::debug!( + tracing::debug!( "Error running query '{}': {:?}", &query_str[0..query_str.len().min(4096)], err @@ -503,7 +513,9 @@ impl Interaction { } out.push(r); } - StepResult::IO => {} + StepResult::IO => { + io.run_once().unwrap(); + } StepResult::Interrupt => {} StepResult::Done => { break; @@ -626,6 +638,10 @@ fn random_delete(rng: &mut R, env: &SimulatorEnv) -> Interactions Interactions::Query(Query::Delete(Delete::arbitrary_from(rng, env))) } +fn random_update(rng: &mut R, env: &SimulatorEnv) -> Interactions { + Interactions::Query(Query::Update(Update::arbitrary_from(rng, env))) +} + fn random_drop(rng: &mut R, env: &SimulatorEnv) -> Interactions { Interactions::Query(Query::Drop(Drop::arbitrary_from(rng, env))) } @@ -664,6 +680,10 @@ impl ArbitraryFrom<(&SimulatorEnv, InteractionStats)> for Interactions { remaining_.delete, Box::new(|rng: &mut R| random_delete(rng, env)), ), + ( + remaining_.update, + Box::new(|rng: &mut R| random_update(rng, env)), + ), ( // remaining_.drop, 0.0, diff --git a/simulator/generation/property.rs b/simulator/generation/property.rs index a876a833d..3d6adade9 100644 --- a/simulator/generation/property.rs +++ b/simulator/generation/property.rs @@ -444,6 +444,7 @@ pub(crate) struct Remaining { pub(crate) write: f64, pub(crate) create: f64, pub(crate) delete: f64, + pub(crate) update: f64, pub(crate) drop: f64, } @@ -460,6 +461,9 @@ pub(crate) fn remaining(env: &SimulatorEnv, stats: &InteractionStats) -> Remaini let remaining_delete = ((env.opts.max_interactions as f64 * env.opts.delete_percent / 100.0) - (stats.delete_count as f64)) .max(0.0); + let remaining_update = ((env.opts.max_interactions as f64 * env.opts.delete_percent / 100.0) + - (stats.update_count as f64)) + .max(0.0); let remaining_drop = ((env.opts.max_interactions as f64 * env.opts.drop_percent / 100.0) - (stats.drop_count as f64)) .max(0.0); @@ -470,6 +474,7 @@ pub(crate) fn remaining(env: &SimulatorEnv, stats: &InteractionStats) -> Remaini create: remaining_create, delete: remaining_delete, drop: remaining_drop, + update: remaining_update, } } diff --git a/simulator/generation/query.rs b/simulator/generation/query.rs index 9e46c5afb..421df9b0d 100644 --- a/simulator/generation/query.rs +++ b/simulator/generation/query.rs @@ -1,7 +1,10 @@ +use std::collections::HashSet; + use crate::generation::table::{GTValue, LTValue}; use crate::generation::{one_of, Arbitrary, ArbitraryFrom}; use crate::model::query::select::{Distinctness, Predicate, ResultColumn}; +use crate::model::query::update::Update; use crate::model::query::{Create, Delete, Drop, Insert, Query, Select}; use crate::model::table::{Table, Value}; use crate::SimulatorEnv; @@ -469,3 +472,32 @@ impl ArbitraryFrom<(&Table, &Vec)> for Predicate { result } } + +impl ArbitraryFrom<&SimulatorEnv> for Update { + fn arbitrary_from(rng: &mut R, env: &SimulatorEnv) -> Self { + let table = pick(&env.tables, rng); + let mut seen = HashSet::new(); + let num_cols = rng.gen_range(1..=table.columns.len()); + let set_values: Vec<(String, Value)> = (0..num_cols) + .map(|_| { + let column = loop { + let column = pick(&table.columns, rng); + if seen.contains(&column.name) { + continue; + } + break column; + }; + seen.insert(column.name.clone()); + ( + column.name.clone(), + Value::arbitrary_from(rng, &column.column_type), + ) + }) + .collect(); + Update { + table: table.name.clone(), + set_values, + predicate: Predicate::arbitrary_from(rng, table), + } + } +} diff --git a/simulator/main.rs b/simulator/main.rs index 34fdac17b..28bb24ecd 100644 --- a/simulator/main.rs +++ b/simulator/main.rs @@ -12,9 +12,12 @@ use runner::execution::{execute_plans, Execution, ExecutionHistory, ExecutionRes use runner::{differential, watch}; use std::any::Any; use std::backtrace::Backtrace; +use std::fs::OpenOptions; use std::io::Write; use std::path::{Path, PathBuf}; use std::sync::{mpsc, Arc, Mutex}; +use tracing_subscriber::EnvFilter; +use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt}; mod generation; mod model; @@ -192,7 +195,7 @@ fn watch_mode( match res { Ok(event) => { if let EventKind::Modify(ModifyKind::Data(DataChange::Content)) = event.kind { - log::info!("plan file modified, rerunning simulation"); + tracing::info!("plan file modified, rerunning simulation"); let result = SandboxedResult::from( std::panic::catch_unwind(|| { @@ -211,12 +214,12 @@ fn watch_mode( ); match result { SandboxedResult::Correct => { - log::info!("simulation succeeded"); + tracing::info!("simulation succeeded"); println!("simulation succeeded"); } SandboxedResult::Panicked { error, .. } | SandboxedResult::FoundBug { error, .. } => { - log::error!("simulation failed: '{}'", error); + tracing::error!("simulation failed: '{}'", error); } } } @@ -238,19 +241,19 @@ fn run_simulator( last_execution: Arc>, ) -> Result<(), String> { std::panic::set_hook(Box::new(move |info| { - log::error!("panic occurred"); + tracing::error!("panic occurred"); let payload = info.payload(); if let Some(s) = payload.downcast_ref::<&str>() { - log::error!("{}", s); + tracing::error!("{}", s); } else if let Some(s) = payload.downcast_ref::() { - log::error!("{}", s); + tracing::error!("{}", s); } else { - log::error!("unknown panic payload"); + tracing::error!("unknown panic payload"); } let bt = Backtrace::force_capture(); - log::error!("captured backtrace:\n{}", bt); + tracing::error!("captured backtrace:\n{}", bt); })); let env = Arc::new(Mutex::new(env)); @@ -275,7 +278,7 @@ fn run_simulator( // No doublecheck, run shrinking if panicking or found a bug. match &result { SandboxedResult::Correct => { - log::info!("simulation succeeded"); + tracing::info!("simulation succeeded"); println!("simulation succeeded"); bugbase.mark_successful_run(seed, cli_opts).unwrap(); Ok(()) @@ -305,14 +308,14 @@ fn run_simulator( } } - log::error!("simulation failed: '{}'", error); - log::info!("Starting to shrink"); + tracing::error!("simulation failed: '{}'", error); + tracing::info!("Starting to shrink"); let shrunk_plans = plans .iter() .map(|plan| { let shrunk = plan.shrink_interaction_plan(last_execution); - log::info!("{}", shrunk.stats()); + tracing::info!("{}", shrunk.stats()); shrunk }) .collect::>(); @@ -346,13 +349,15 @@ fn run_simulator( SandboxedResult::FoundBug { error: e2, .. }, ) => { if e1 != e2 { - log::error!("shrinking failed, the error was not properly reproduced"); + tracing::error!( + "shrinking failed, the error was not properly reproduced" + ); bugbase .add_bug(seed, plans[0].clone(), Some(error.clone()), cli_opts) .unwrap(); Err(format!("failed with error: '{}'", error)) } else { - log::info!( + tracing::info!( "shrinking succeeded, reduced the plan from {} to {}", plans[0].plan.len(), shrunk_plans[0].plan.len() @@ -368,7 +373,7 @@ fn run_simulator( unreachable!("shrinking should never be called on a correct simulation") } _ => { - log::error!("shrinking failed, the error was not properly reproduced"); + tracing::error!("shrinking failed, the error was not properly reproduced"); bugbase .add_bug(seed, plans[0].clone(), Some(error.clone()), cli_opts) .unwrap(); @@ -438,13 +443,13 @@ fn doublecheck( match doublecheck_result { Ok(_) => { - log::info!("doublecheck succeeded"); + tracing::info!("doublecheck succeeded"); println!("doublecheck succeeded"); bugbase.mark_successful_run(seed, cli_opts)?; Ok(()) } Err(e) => { - log::error!("doublecheck failed: '{}'", e); + tracing::error!("doublecheck failed: '{}'", e); bugbase .add_bug(seed, plans[0].clone(), Some(e.clone()), cli_opts) .unwrap(); @@ -484,13 +489,13 @@ fn differential_testing( match result { SandboxedResult::Correct => { - log::info!("simulation succeeded, output of Limbo conforms to SQLite"); + tracing::info!("simulation succeeded, output of Limbo conforms to SQLite"); println!("simulation succeeded, output of Limbo conforms to SQLite"); bugbase.mark_successful_run(seed, cli_opts).unwrap(); Ok(()) } SandboxedResult::Panicked { error, .. } | SandboxedResult::FoundBug { error, .. } => { - log::error!("simulation failed: '{}'", error); + tracing::error!("simulation failed: '{}'", error); bugbase .add_bug(seed, plans[0].clone(), Some(error.clone()), cli_opts) .unwrap(); @@ -529,15 +534,15 @@ impl SandboxedResult { } } Err(payload) => { - log::error!("panic occurred"); + tracing::error!("panic occurred"); let err = if let Some(s) = payload.downcast_ref::<&str>() { - log::error!("{}", s); + tracing::error!("{}", s); s.to_string() } else if let Some(s) = payload.downcast_ref::() { - log::error!("{}", s); + tracing::error!("{}", s); s.to_string() } else { - log::error!("unknown panic payload"); + tracing::error!("unknown panic payload"); "unknown panic payload".to_string() }; @@ -560,6 +565,7 @@ fn setup_simulation( ) -> (u64, SimulatorEnv, Vec) { if let Some(seed) = &cli_opts.load { let seed = seed.parse::().expect("seed should be a number"); + tracing::info!("seed={}", seed); let bug = bugbase .get_bug(seed) .unwrap_or_else(|| panic!("bug '{}' not found in bug base", seed)); @@ -595,6 +601,7 @@ fn setup_simulation( let mut rng = rand::thread_rng(); rng.next_u64() }); + tracing::info!("seed={}", seed); let paths = bugbase.paths(seed); if !paths.base.exists() { @@ -602,7 +609,7 @@ fn setup_simulation( } let mut env = SimulatorEnv::new(seed, cli_opts, &paths.db); - log::info!("Generating database interaction plan..."); + tracing::info!("Generating database interaction plan..."); let plans = (1..=env.opts.max_connections) .map(|_| InteractionPlan::arbitrary_from(&mut env.rng.clone(), &mut env)) @@ -610,7 +617,7 @@ fn setup_simulation( // todo: for now, we only use 1 connection, so it's safe to use the first plan. let plan = &plans[0]; - log::info!("{}", plan.stats()); + tracing::info!("{}", plan.stats()); std::fs::write(plan_path(&paths), plan.to_string()).unwrap(); std::fs::write( plan_path(&paths).with_extension("json"), @@ -627,7 +634,7 @@ fn run_simulation( plans: &mut [InteractionPlan], last_execution: Arc>, ) -> ExecutionResult { - log::info!("Executing database interaction plan..."); + tracing::info!("Executing database interaction plan..."); let mut states = plans .iter() @@ -642,17 +649,36 @@ fn run_simulation( let env = env.lock().unwrap(); env.io.print_stats(); - log::info!("Simulation completed"); + tracing::info!("Simulation completed"); result } fn init_logger() { - env_logger::Builder::from_env(env_logger::Env::default().filter_or("RUST_LOG", "info")) - .format_timestamp(None) - .format_module_path(false) - .format_target(false) - .init(); + let file = OpenOptions::new() + .create(true) + .write(true) + .truncate(true) + .open("simulator.log") + .unwrap(); + let _ = tracing_subscriber::registry() + .with( + tracing_subscriber::fmt::layer() + .with_ansi(true) + .with_line_number(true) + .without_time() + .with_thread_ids(false), + ) + .with(EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"))) + .with( + tracing_subscriber::fmt::layer() + .with_writer(file) + .with_ansi(false) + .with_line_number(true) + .without_time() + .with_thread_ids(false), + ) + .try_init(); } fn banner() { diff --git a/simulator/model/query/mod.rs b/simulator/model/query/mod.rs index 15e703443..1e6fbb48a 100644 --- a/simulator/model/query/mod.rs +++ b/simulator/model/query/mod.rs @@ -6,6 +6,7 @@ pub(crate) use drop::Drop; pub(crate) use insert::Insert; pub(crate) use select::Select; use serde::{Deserialize, Serialize}; +use update::Update; use crate::{model::table::Value, runner::env::SimulatorEnv}; @@ -14,6 +15,7 @@ pub mod delete; pub mod drop; pub mod insert; pub mod select; +pub mod update; // This type represents the potential queries on the database. #[derive(Debug, Clone, Serialize, Deserialize)] @@ -22,6 +24,7 @@ pub(crate) enum Query { Select(Select), Insert(Insert), Delete(Delete), + Update(Update), Drop(Drop), } @@ -33,6 +36,7 @@ impl Query { | Query::Insert(Insert::Select { table, .. }) | Query::Insert(Insert::Values { table, .. }) | Query::Delete(Delete { table, .. }) + | Query::Update(Update { table, .. }) | Query::Drop(Drop { table, .. }) => vec![table.clone()], } } @@ -43,6 +47,7 @@ impl Query { | Query::Insert(Insert::Select { table, .. }) | Query::Insert(Insert::Values { table, .. }) | Query::Delete(Delete { table, .. }) + | Query::Update(Update { table, .. }) | Query::Drop(Drop { table, .. }) => vec![table.clone()], } } @@ -53,6 +58,7 @@ impl Query { Query::Insert(insert) => insert.shadow(env), Query::Delete(delete) => delete.shadow(env), Query::Select(select) => select.shadow(env), + Query::Update(update) => update.shadow(env), Query::Drop(drop) => drop.shadow(env), } } @@ -65,6 +71,7 @@ impl Display for Query { Self::Select(select) => write!(f, "{}", select), Self::Insert(insert) => write!(f, "{}", insert), Self::Delete(delete) => write!(f, "{}", delete), + Self::Update(update) => write!(f, "{}", update), Self::Drop(drop) => write!(f, "{}", drop), } } diff --git a/simulator/model/query/update.rs b/simulator/model/query/update.rs new file mode 100644 index 000000000..acfc1e8e4 --- /dev/null +++ b/simulator/model/query/update.rs @@ -0,0 +1,56 @@ +use std::fmt::Display; + +use serde::{Deserialize, Serialize}; + +use crate::{model::table::Value, SimulatorEnv}; + +use super::select::Predicate; + +#[derive(Clone, Debug, PartialEq, Serialize, Deserialize)] +pub(crate) struct Update { + pub(crate) table: String, + pub(crate) set_values: Vec<(String, Value)>, // Pair of value for set expressions => SET name=value + pub(crate) predicate: Predicate, +} + +impl Update { + pub(crate) fn shadow(&self, env: &mut SimulatorEnv) -> Vec> { + let table = env + .tables + .iter_mut() + .find(|t| t.name == self.table) + .unwrap(); + let t2 = table.clone(); + for row in table + .rows + .iter_mut() + .filter(|r| self.predicate.test(r, &t2)) + { + for (column, set_value) in &self.set_values { + let (idx, _) = table + .columns + .iter() + .enumerate() + .find(|(_, c)| &c.name == column) + .unwrap(); + row[idx] = set_value.clone(); + } + } + + vec![] + } +} + +impl Display for Update { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!(f, "UPDATE {} SET ", self.table)?; + for (i, (name, value)) in self.set_values.iter().enumerate() { + if i != 0 { + write!(f, ", ")?; + } + write!(f, "{} = {}", name, value)?; + } + write!(f, " WHERE {}", self.predicate)?; + Ok(()) + } +} diff --git a/simulator/runner/bugbase.rs b/simulator/runner/bugbase.rs index c59744046..c11cf0afd 100644 --- a/simulator/runner/bugbase.rs +++ b/simulator/runner/bugbase.rs @@ -116,7 +116,7 @@ impl BugBase { for path in potential_paths { let path = path.join(".bugbase"); if std::fs::create_dir_all(&path).is_ok() { - log::info!("bug base created at {}", path.display()); + tracing::info!("bug base created at {}", path.display()); return BugBase::new(path); } } @@ -172,7 +172,7 @@ impl BugBase { unreachable!("bug base already exists at {}", path.display()); } else { std::fs::create_dir_all(&path).or(Err("failed to create bug base"))?; - log::info!("bug base created at {}", path.display()); + tracing::info!("bug base created at {}", path.display()); BugBase::new(path) } } @@ -185,7 +185,7 @@ impl BugBase { error: Option, cli_options: &SimulatorCLI, ) -> Result<(), String> { - log::debug!("adding bug with seed {}", seed); + tracing::debug!("adding bug with seed {}", seed); let bug = self.get_bug(seed); if bug.is_some() { @@ -290,11 +290,11 @@ impl BugBase { }; self.bugs.insert(seed, Bug::Loaded(bug.clone())); - log::debug!("Loaded bug with seed {}", seed); + tracing::debug!("Loaded bug with seed {}", seed); Ok(bug) } Some(Bug::Loaded(bug)) => { - log::warn!( + tracing::warn!( "Bug with seed {} is already loaded, returning the existing plan", seed ); @@ -311,7 +311,7 @@ impl BugBase { let bug = self.get_bug(seed); match bug { None => { - log::debug!("removing bug base entry for {}", seed); + tracing::debug!("removing bug base entry for {}", seed); std::fs::remove_dir_all(self.path.join(seed.to_string())) .or(Err("should be able to remove bug directory".to_string()))?; } @@ -327,7 +327,7 @@ impl BugBase { // Save the bug to the bug base. self.save_bug(seed) .or(Err("should be able to save bug".to_string()))?; - log::debug!("Updated bug with seed {}", seed); + tracing::debug!("Updated bug with seed {}", seed); } } diff --git a/simulator/runner/cli.rs b/simulator/runner/cli.rs index c62c023bb..0a018958f 100644 --- a/simulator/runner/cli.rs +++ b/simulator/runner/cli.rs @@ -90,7 +90,7 @@ impl SimulatorCLI { } if self.minimum_tests > self.maximum_tests { - log::warn!( + tracing::warn!( "minimum size '{}' is greater than '{}' maximum size, setting both to '{}'", self.minimum_tests, self.maximum_tests, diff --git a/simulator/runner/differential.rs b/simulator/runner/differential.rs index 0db6b8ecd..9c4ea3736 100644 --- a/simulator/runner/differential.rs +++ b/simulator/runner/differential.rs @@ -22,7 +22,7 @@ pub(crate) fn run_simulation( plans: &mut [InteractionPlan], last_execution: Arc>, ) -> ExecutionResult { - log::info!("Executing database interaction plan..."); + tracing::info!("Executing database interaction plan..."); let mut states = plans .iter() @@ -52,7 +52,7 @@ pub(crate) fn run_simulation( last_execution, ); - log::info!("Simulation completed"); + tracing::info!("Simulation completed"); result } @@ -101,6 +101,10 @@ fn execute_query_rusqlite( connection.execute(drop.to_string().as_str(), ())?; Ok(vec![]) } + Query::Update(update) => { + connection.execute(update.to_string().as_str(), ())?; + Ok(vec![]) + } } } @@ -184,7 +188,7 @@ fn execute_plan( match (connection, rusqlite_connection) { (SimConnection::Disconnected, SimConnection::Disconnected) => { - log::debug!("connecting {}", connection_index); + tracing::debug!("connecting {}", connection_index); env.connections[connection_index] = SimConnection::LimboConnection(env.db.connect().unwrap()); rusqlite_env.connections[connection_index] = @@ -202,7 +206,7 @@ fn execute_plan( match (limbo_result, ruqlite_result) { (Ok(next_execution), Ok(next_execution_rusqlite)) => { if next_execution != next_execution_rusqlite { - log::error!("limbo and rusqlite results do not match"); + tracing::error!("limbo and rusqlite results do not match"); return Err(limbo_core::LimboError::InternalError( "limbo and rusqlite results do not match".into(), )); @@ -215,30 +219,30 @@ fn execute_plan( match (limbo_values, rusqlite_values) { (Ok(limbo_values), Ok(rusqlite_values)) => { if limbo_values != rusqlite_values { - log::error!("limbo and rusqlite results do not match"); + tracing::error!("limbo and rusqlite results do not match"); return Err(limbo_core::LimboError::InternalError( "limbo and rusqlite results do not match".into(), )); } } (Err(limbo_err), Err(rusqlite_err)) => { - log::warn!( + tracing::warn!( "limbo and rusqlite both fail, requires manual check" ); - log::warn!("limbo error {}", limbo_err); - log::warn!("rusqlite error {}", rusqlite_err); + tracing::warn!("limbo error {}", limbo_err); + tracing::warn!("rusqlite error {}", rusqlite_err); } (Ok(limbo_result), Err(rusqlite_err)) => { - log::error!("limbo and rusqlite results do not match"); - log::error!("limbo values {:?}", limbo_result); - log::error!("rusqlite error {}", rusqlite_err); + tracing::error!("limbo and rusqlite results do not match"); + tracing::error!("limbo values {:?}", limbo_result); + tracing::error!("rusqlite error {}", rusqlite_err); return Err(limbo_core::LimboError::InternalError( "limbo and rusqlite results do not match".into(), )); } (Err(limbo_err), Ok(_)) => { - log::error!("limbo and rusqlite results do not match"); - log::error!("limbo error {}", limbo_err); + tracing::error!("limbo and rusqlite results do not match"); + tracing::error!("limbo error {}", limbo_err); return Err(limbo_core::LimboError::InternalError( "limbo and rusqlite results do not match".into(), )); @@ -247,7 +251,7 @@ fn execute_plan( } (None, None) => {} _ => { - log::error!("limbo and rusqlite results do not match"); + tracing::error!("limbo and rusqlite results do not match"); return Err(limbo_core::LimboError::InternalError( "limbo and rusqlite results do not match".into(), )); @@ -276,20 +280,20 @@ fn execute_plan( } } (Err(err), Ok(_)) => { - log::error!("limbo and rusqlite results do not match"); - log::error!("limbo error {}", err); + tracing::error!("limbo and rusqlite results do not match"); + tracing::error!("limbo error {}", err); return Err(err); } (Ok(val), Err(err)) => { - log::error!("limbo and rusqlite results do not match"); - log::error!("limbo {:?}", val); - log::error!("rusqlite error {}", err); + tracing::error!("limbo and rusqlite results do not match"); + tracing::error!("limbo {:?}", val); + tracing::error!("rusqlite error {}", err); return Err(err); } (Err(err), Err(err_rusqlite)) => { - log::error!("limbo and rusqlite both fail, requires manual check"); - log::error!("limbo error {}", err); - log::error!("rusqlite error {}", err_rusqlite); + tracing::error!("limbo and rusqlite both fail, requires manual check"); + tracing::error!("limbo error {}", err); + tracing::error!("rusqlite error {}", err_rusqlite); return Err(err); } } @@ -306,7 +310,7 @@ fn execute_interaction_rusqlite( interaction: &Interaction, stack: &mut Vec, ) -> limbo_core::Result { - log::trace!( + tracing::trace!( "execute_interaction_rusqlite(connection_index={}, interaction={})", connection_index, interaction @@ -319,11 +323,11 @@ fn execute_interaction_rusqlite( SimConnection::Disconnected => unreachable!(), }; - log::debug!("{}", interaction); + tracing::debug!("{}", interaction); let results = execute_query_rusqlite(conn, query).map_err(|e| { limbo_core::LimboError::InternalError(format!("error executing query: {}", e)) }); - log::debug!("{:?}", results); + tracing::debug!("{:?}", results); stack.push(results); } Interaction::Assertion(_) => { @@ -335,7 +339,7 @@ fn execute_interaction_rusqlite( stack.clear(); if assumption_result.is_err() { - log::warn!("assumption failed: {:?}", assumption_result); + tracing::warn!("assumption failed: {:?}", assumption_result); return Ok(ExecutionContinuation::NextProperty); } } diff --git a/simulator/runner/execution.rs b/simulator/runner/execution.rs index 7b8204604..5f1f284e4 100644 --- a/simulator/runner/execution.rs +++ b/simulator/runner/execution.rs @@ -121,15 +121,15 @@ fn execute_plan( let interaction = &plan.plan[state.interaction_pointer].interactions()[state.secondary_pointer]; if let SimConnection::Disconnected = connection { - log::debug!("connecting {}", connection_index); + tracing::debug!("connecting {}", connection_index); env.connections[connection_index] = SimConnection::LimboConnection(env.db.connect().unwrap()); } else { - log::debug!("connection {} already connected", connection_index); + tracing::debug!("connection {} already connected", connection_index); match execute_interaction(env, connection_index, interaction, &mut state.stack) { Ok(next_execution) => { interaction.shadow(env); - log::debug!("connection {} processed", connection_index); + tracing::debug!("connection {} processed", connection_index); // Move to the next interaction or property match next_execution { ExecutionContinuation::NextInteraction => { @@ -152,7 +152,7 @@ fn execute_plan( } } Err(err) => { - log::error!("error {}", err); + tracing::error!("error {}", err); return Err(err); } } @@ -179,7 +179,7 @@ pub(crate) fn execute_interaction( interaction: &Interaction, stack: &mut Vec, ) -> Result { - log::trace!( + tracing::trace!( "execute_interaction(connection_index={}, interaction={})", connection_index, interaction @@ -192,9 +192,9 @@ pub(crate) fn execute_interaction( SimConnection::Disconnected => unreachable!(), }; - log::debug!("{}", interaction); - let results = interaction.execute_query(conn); - log::debug!("{:?}", results); + tracing::debug!("{}", interaction); + let results = interaction.execute_query(conn, &env.io); + tracing::debug!("{:?}", results); stack.push(results); } Interaction::Assertion(_) => { @@ -206,7 +206,7 @@ pub(crate) fn execute_interaction( stack.clear(); if assumption_result.is_err() { - log::warn!("assumption failed: {:?}", assumption_result); + tracing::warn!("assumption failed: {:?}", assumption_result); return Ok(ExecutionContinuation::NextProperty); } } diff --git a/simulator/runner/file.rs b/simulator/runner/file.rs index 5d1c2cd4b..d676608b1 100644 --- a/simulator/runner/file.rs +++ b/simulator/runner/file.rs @@ -32,29 +32,29 @@ impl SimulatorFile { } pub(crate) fn print_stats(&self) { - log::info!("op calls faults"); - log::info!("--------- -------- --------"); - log::info!( + tracing::info!("op calls faults"); + tracing::info!("--------- -------- --------"); + tracing::info!( "pread {:8} {:8}", *self.nr_pread_calls.borrow(), *self.nr_pread_faults.borrow() ); - log::info!( + tracing::info!( "pwrite {:8} {:8}", *self.nr_pwrite_calls.borrow(), *self.nr_pwrite_faults.borrow() ); - log::info!( + tracing::info!( "sync {:8} {:8}", *self.nr_sync_calls.borrow(), 0 // No fault counter for sync ); - log::info!("--------- -------- --------"); + tracing::info!("--------- -------- --------"); 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(); - log::info!("total {:8} {:8}", sum_calls, sum_faults); + tracing::info!("total {:8} {:8}", sum_calls, sum_faults); } } diff --git a/simulator/runner/io.rs b/simulator/runner/io.rs index 634873453..6318e711c 100644 --- a/simulator/runner/io.rs +++ b/simulator/runner/io.rs @@ -43,10 +43,10 @@ impl SimulatorIO { } pub(crate) fn print_stats(&self) { - log::info!("run_once faults: {}", self.nr_run_once_faults.borrow()); + tracing::info!("run_once faults: {}", self.nr_run_once_faults.borrow()); for file in self.files.borrow().iter() { - log::info!(""); - log::info!("==========================="); + tracing::info!(""); + tracing::info!("==========================="); file.print_stats(); } } diff --git a/simulator/runner/watch.rs b/simulator/runner/watch.rs index cb7648fc3..6660a918b 100644 --- a/simulator/runner/watch.rs +++ b/simulator/runner/watch.rs @@ -31,7 +31,7 @@ pub(crate) fn run_simulation( let env = env.lock().unwrap(); env.io.print_stats(); - log::info!("Simulation completed"); + tracing::info!("Simulation completed"); result } @@ -97,13 +97,13 @@ fn execute_plan( let interaction = &plan[state.interaction_pointer][state.secondary_pointer]; if let SimConnection::Disconnected = connection { - log::debug!("connecting {}", connection_index); + tracing::debug!("connecting {}", connection_index); env.connections[connection_index] = SimConnection::LimboConnection(env.db.connect().unwrap()); } else { match execute_interaction(env, connection_index, interaction, &mut state.stack) { Ok(next_execution) => { - log::debug!("connection {} processed", connection_index); + tracing::debug!("connection {} processed", connection_index); // Move to the next interaction or property match next_execution { ExecutionContinuation::NextInteraction => { @@ -124,7 +124,7 @@ fn execute_plan( } } Err(err) => { - log::error!("error {}", err); + tracing::error!("error {}", err); return Err(err); } } diff --git a/simulator/shrink/plan.rs b/simulator/shrink/plan.rs index 01b191c9c..20b553493 100644 --- a/simulator/shrink/plan.rs +++ b/simulator/shrink/plan.rs @@ -46,7 +46,7 @@ impl InteractionPlan { let after = plan.plan.len(); - log::info!( + tracing::info!( "Shrinking interaction plan from {} to {} properties", before, after