diff --git a/src/function/backdate.rs b/src/function/backdate.rs index 330fba7c4..97eb626a0 100644 --- a/src/function/backdate.rs +++ b/src/function/backdate.rs @@ -1,7 +1,9 @@ use crate::function::memo::Memo; use crate::function::{Configuration, IngredientImpl}; use crate::zalsa_local::QueryRevisions; +use crate::Backtrace; use crate::DatabaseKeyIndex; +use std::fmt; impl IngredientImpl where @@ -39,9 +41,71 @@ where old_memo.revisions.changed_at, ); - assert!(old_memo.revisions.changed_at <= revisions.changed_at); + if old_memo.revisions.changed_at > revisions.changed_at { + report_backdate_violation( + index, + old_memo.revisions.changed_at, + revisions.changed_at, + ); + } + revisions.changed_at = old_memo.revisions.changed_at; } } } } + +#[cold] +#[inline(never)] +fn report_backdate_violation( + index: DatabaseKeyIndex, + old_changed_at: crate::Revision, + new_changed_at: crate::Revision, +) { + if cfg!(debug_assertions) { + let message = BackdateViolation { + index, + old_changed_at, + new_changed_at, + backtrace: None, + }; + panic!("{message}"); + } else { + let message = BackdateViolation { + index, + old_changed_at, + new_changed_at, + backtrace: Backtrace::capture(), + }; + crate::tracing::warn!("{message}"); + } +} + +struct BackdateViolation { + index: DatabaseKeyIndex, + old_changed_at: crate::Revision, + new_changed_at: crate::Revision, + backtrace: Option, +} + +impl fmt::Display for BackdateViolation { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!( + f, + "query {:?} returned the same value, but the previous execution changed at {:?} and \ + the new execution changed at {:?}. This usually means the query re-executed because \ + an input changed, but then branched on untracked state (for example, a global \ + variable, a non-salsa field on the database, or filesystem state read outside salsa) \ + and no longer read that input. This is usually a bug in the query implementation. \ + Queries that branch on untracked state can also produce stale results. If the query \ + has no untracked reads, please open a Salsa issue.", + self.index, self.old_changed_at, self.new_changed_at, + )?; + + if let Some(backtrace) = &self.backtrace { + write!(f, "\n{backtrace}")?; + } + + Ok(()) + } +} diff --git a/tests/backdate_untracked_db_field.rs b/tests/backdate_untracked_db_field.rs new file mode 100644 index 000000000..6488b6d90 --- /dev/null +++ b/tests/backdate_untracked_db_field.rs @@ -0,0 +1,83 @@ +#![cfg(feature = "inventory")] + +use salsa::Setter; + +#[salsa::input(debug)] +struct MyInput { + field: u32, +} + +#[salsa::db] +trait Db: salsa::Database { + /// Untracked database state. Reading this inside a tracked query is a footgun. + fn extra(&self) -> u32; +} + +#[salsa::db] +#[derive(Default, Clone)] +struct ExtraFieldDatabase { + storage: salsa::Storage, + extra: u32, +} + +#[salsa::db] +impl salsa::Database for ExtraFieldDatabase {} + +#[salsa::db] +impl Db for ExtraFieldDatabase { + fn extra(&self) -> u32 { + self.extra + } +} + +impl ExtraFieldDatabase { + fn set_extra(&mut self, value: u32) { + self.extra = value; + } +} + +#[salsa::tracked] +fn dep_a_db(db: &dyn Db, input: MyInput) -> u32 { + input.field(db) +} + +#[salsa::tracked] +fn dep_b_db(db: &dyn Db, input: MyInput) -> u32 { + input.field(db) +} + +#[salsa::tracked] +fn db_field_branch_query(db: &dyn Db, a: MyInput, b: MyInput) -> u32 { + if db.extra() == 0 { + dep_a_db(db, a) + } else { + dep_b_db(db, b) + } +} + +#[test] +#[cfg_attr(debug_assertions, should_panic(expected = "returned the same value"))] +fn db_field_branch_can_trip_backdate_assertion() { + let mut db = ExtraFieldDatabase::default(); + db.set_extra(0); + + let a = MyInput::new(&db, 0); + let b = MyInput::new(&db, 0); + + // R1: depends on `a`, returns 0 + assert_eq!(db_field_branch_query(&db, a, b), 0); + + // R2: force the memo to have a recent changed_at. + a.set_field(&mut db).to(1); + assert_eq!(db_field_branch_query(&db, a, b), 1); + + // R3: return to 0 (still depending on `a`). + a.set_field(&mut db).to(0); + assert_eq!(db_field_branch_query(&db, a, b), 0); + + // R4/R5: switch branch via untracked db field, and force re-execution by changing `a`. + // New execution returns 0 (equal) but depends only on older `b`, triggering the backdate check. + db.set_extra(1); + a.set_field(&mut db).to(1); + let _ = db_field_branch_query(&db, a, b); +} diff --git a/tests/debug.rs b/tests/debug.rs index da184b40a..60a34f18c 100644 --- a/tests/debug.rs +++ b/tests/debug.rs @@ -65,6 +65,58 @@ fn untracked_dependencies() { assert!(s.contains(", field: 22 }")); } +#[salsa::tracked] +fn dep_a(db: &dyn salsa::Database, input: MyInput) -> u32 { + input.field(db) +} + +#[salsa::tracked] +fn dep_b(db: &dyn salsa::Database, input: MyInput) -> u32 { + input.field(db) +} + +#[salsa::tracked] +fn debug_branch_query(db: &dyn salsa::Database, selector: MyInput, a: MyInput, b: MyInput) -> u32 { + // `Debug` for salsa structs is explicitly untracked; branching on it is unsound. + // This test demonstrates it can break the backdate invariant. + let s = format!("{selector:?}"); + if s.contains("field: 0") { + dep_a(db, a) + } else { + dep_b(db, b) + } +} + +/// Backdating warns about branching on the output of a Salsa struct's derived `Debug` output, +/// because it doesn't track its reads (can lead to stale results). +#[test] +#[cfg_attr(debug_assertions, should_panic(expected = "returned the same value"))] +fn debug_branch_can_trip_backdate_assertion() { + let mut db = salsa::DatabaseImpl::new(); + + let selector = MyInput::new(&db, 0); + let a = MyInput::new(&db, 0); + let b = MyInput::new(&db, 0); + + // R1: depends on `a`, returns 0 + assert_eq!(debug_branch_query(&db, selector, a, b), 0); + + // R2: force `debug_branch_query` to change (0 -> 1) so its memo's changed_at advances. + a.set_field(&mut db).to(1); + assert_eq!(debug_branch_query(&db, selector, a, b), 1); + + // R3: change back to 0; memo value is 0 but changed_at is now "recent". + a.set_field(&mut db).to(0); + assert_eq!(debug_branch_query(&db, selector, a, b), 0); + + // R4/R5: change `selector` (untracked) so the query switches to `b`, and change `a` + // to force re-execution. New execution returns 0 (equal) but depends only on older `b`, + // so `new.changed_at < old.changed_at` and backdating asserts. + selector.set_field(&mut db).to(1); + a.set_field(&mut db).to(1); + let _ = debug_branch_query(&db, selector, a, b); +} + #[salsa::tracked] struct DerivedCustom<'db> { my_input: MyInput,