feat(db): comprehensive logging across worker + executors (X1)

Instrument db.rs to the CLAUDE.md "log liberally" bar (X1). 26 -> 67
tracing sites:

- Entry-level debug! on all 34 do_* executors (DDL, DML, relationship,
  index, read paths), matching the existing do_sql_delete/do_run_select
  style -- so the route through delegating executors (e.g. add_column ->
  add_constrained_column_via_rebuild) is visible in the log sequence.
- Decision-point logs: rebuild_table primitive (begin/commit; FK-check
  failure and foreign_keys re-enable failure as warn), do_insert autofill
  summary, do_delete cascade summary, do_create_table FK resolution.
- Worker lifecycle (start/exit) raised debug! -> info! so it shows at the
  default level.

Levels per the X1 discipline: debug for per-command detail (off by
default, opt-in via RDBMS_PLAYGROUND_LOG=debug), info for lifecycle, warn
for fallbacks. Loops log summary counts, never per-row.

Tests: 2207 pass / 0 fail / 1 ignored (unchanged). Clippy clean.

src/db.rs

@@ -1921,7 +1921,7 @@ fn worker_loop(
     snapshots: Option<SnapshotStore>,
     mut rx: mpsc::Receiver<Request>,
 ) {
-    debug!("db worker started");
+    info!("db worker started");
     // `conn` must be mutable: restoring a snapshot (undo/redo) writes
     // into the live connection via the backup API (`&mut`).
     let mut conn = conn;
@@ -1968,7 +1968,7 @@ fn worker_loop(
             other => handle_request(&conn, persistence.as_ref(), snap, &mut batch, other),
         }
     }
-    debug!("db worker exiting");
+    info!("db worker exiting");
 }
 
 /// Worker-side undo bracketing state for the request stream.
@@ -3393,6 +3393,7 @@ fn do_create_table(
     check_constraints: &[String],
     foreign_keys: &[SqlForeignKey],
 ) -> Result<TableDescription, DbError> {
+    debug!(table = %name, cols = columns.len(), pk = ?primary_key, "create_table");
     if columns.is_empty() {
         // SQLite requires at least one column. The DSL grammar
         // already prevents this, but defending here too keeps
@@ -3407,6 +3408,9 @@ fn do_create_table(
     // §5, sub-phase 4b). Self-references validate against the columns
     // being defined; other parents must already exist.
     let resolved_fks = resolve_create_table_fks(conn, name, columns, primary_key, foreign_keys)?;
+    if !resolved_fks.is_empty() {
+        debug!(table = %name, fks = resolved_fks.len(), "create_table: foreign keys resolved + validated");
+    }
 
     // Inline `PRIMARY KEY` on the column when the table has a single
     // primary-key column and it is the **first** column — the exact
@@ -3568,6 +3572,7 @@ fn do_drop_table(
     source: Option<&str>,
     name: &str,
 ) -> Result<(), DbError> {
+    debug!(table = %name, "drop_table");
     // Canonicalize the user-typed name to its stored case (and refuse a
     // non-existent / internal table), so the metadata DELETEs and the CSV
     // removal target the right name regardless of capitalization.
@@ -3647,6 +3652,7 @@ fn do_add_column(
     table: &str,
     column: &ColumnSpec,
 ) -> Result<AddColumnResult, DbError> {
+    debug!(table = %table, column = %column.name, "add_column");
     let canonical_table = require_canonical_table(conn, table)?;
     let table = canonical_table.as_str();
     if matches!(column.ty, Type::Serial | Type::ShortId) {
@@ -3700,6 +3706,7 @@ fn do_add_plain_column(
     table: &str,
     spec: &ColumnSpec,
 ) -> Result<AddColumnResult, DbError> {
+    debug!(table = %table, column = %spec.name, "add_plain_column");
     // The plain `ALTER TABLE ADD COLUMN` path. `do_add_column`
     // only routes here when the constraints are ALTER-expressible
     // (no UNIQUE; NOT NULL only alongside a default), so the
@@ -3752,6 +3759,7 @@ fn do_add_auto_generated_column(
     table: &str,
     spec: &ColumnSpec,
 ) -> Result<AddColumnResult, DbError> {
+    debug!(table = %table, column = %spec.name, "add_auto_generated_column");
     use rusqlite::types::Value as RV;
 
     let ty = spec.ty;
@@ -3883,6 +3891,7 @@ fn do_add_constrained_column_via_rebuild(
     table: &str,
     spec: &ColumnSpec,
 ) -> Result<AddColumnResult, DbError> {
+    debug!(table = %table, column = %spec.name, "add_constrained_column_via_rebuild");
     let old_schema = read_schema(conn, table)?;
     if old_schema.columns.iter().any(|c| c.name == spec.name) {
         return Err(DbError::Unsupported(format!(
@@ -3984,6 +3993,7 @@ fn do_add_constraint(
     column: &str,
     constraint: &Constraint,
 ) -> Result<TableDescription, DbError> {
+    debug!(table = %table, column = %column, "add_constraint");
     // Canonicalize to the stored case (and refuse a non-existent /
     // internal `__rdbms_*` table as "no such table"), like the sibling
     // schema-mutation executors. Closes the simple `add constraint`
@@ -4126,6 +4136,7 @@ fn do_drop_constraint(
     column: &str,
     kind: ConstraintKind,
 ) -> Result<TableDescription, DbError> {
+    debug!(table = %table, column = %column, "drop_constraint");
     let canonical_table = require_canonical_table(conn, table)?;
     let table = canonical_table.as_str();
     let old_schema = read_schema(conn, table)?;
@@ -4228,6 +4239,7 @@ fn do_set_column_default(
     column: &str,
     default_sql: &str,
 ) -> Result<TableDescription, DbError> {
+    debug!(table = %table, column = %column, "set_column_default");
     let canonical_table = require_canonical_table(conn, table)?;
     let table = canonical_table.as_str();
     let old_schema = read_schema(conn, table)?;
@@ -4617,6 +4629,7 @@ fn do_drop_column(
     column: &str,
     cascade: bool,
 ) -> Result<DropColumnResult, DbError> {
+    debug!(table = %table, column = %column, cascade, "drop_column");
     let canonical_table = require_canonical_table(conn, table)?;
     let table = canonical_table.as_str();
     let schema = read_schema(conn, table)?;
@@ -4776,6 +4789,7 @@ fn do_rename_column(
     old: &str,
     new: &str,
 ) -> Result<TableDescription, DbError> {
+    debug!(table = %table, old = %old, new = %new, "rename_column");
     let canonical_table = require_canonical_table(conn, table)?;
     let table = canonical_table.as_str();
     let schema = read_schema(conn, table)?;
@@ -4898,6 +4912,7 @@ fn do_rename_table(
     old: &str,
     new: &str,
 ) -> Result<TableDescription, DbError> {
+    debug!(old = %old, new = %new, "rename_table");
     reject_internal_table_name(new)?;
     // Canonicalize the source to its stored case (and refuse a
     // non-existent / internal source as "no such table") — so a
@@ -5086,6 +5101,7 @@ fn do_change_column_type(
     ty: Type,
     mode: ChangeColumnMode,
 ) -> Result<ChangeColumnTypeResult, DbError> {
+    debug!(table = %table, column = %column, ty = %ty, mode = ?mode, "change_column_type");
     // Canonicalize to the stored case (and refuse a non-existent /
     // internal `__rdbms_*` table as "no such table"), like the sibling
     // column executors. Closes the simple `change column` exposure and
@@ -5888,6 +5904,7 @@ fn more_row(width: usize, more: usize) -> Vec<String> {
 }
 
 fn do_list_tables(conn: &Connection) -> Result<Vec<String>, DbError> {
+    debug!("list_tables");
     let mut stmt = conn
         .prepare(
             "SELECT name FROM sqlite_schema \
@@ -5915,6 +5932,7 @@ fn do_show_relationship(
     conn: &Connection,
     name: &str,
 ) -> Result<Option<RelationshipDiagramData>, DbError> {
+    debug!(name = %name, "show_relationship");
     let Some(rel) = read_all_relationships(conn)?
         .into_iter()
         .find(|r| r.name == name)
@@ -5937,6 +5955,7 @@ fn do_show_list(
     kind: crate::dsl::command::ShowListKind,
     name: Option<&str>,
 ) -> Result<Vec<String>, DbError> {
+    debug!(kind = ?kind, name = ?name, "show_list");
     use crate::dsl::command::ShowListKind;
     // V5a: a named item shows one relationship/index's detail.
     if let Some(name) = name {
@@ -6024,6 +6043,7 @@ fn do_show_one(
     kind: crate::dsl::command::ShowListKind,
     name: &str,
 ) -> Result<Vec<String>, DbError> {
+    debug!(kind = ?kind, name = %name, "show_one");
     use crate::dsl::command::ShowListKind;
     let mut lines = Vec::new();
     match kind {
@@ -6802,6 +6822,7 @@ where
     C: FnOnce(&rusqlite::Transaction<'_>, &str, &str) -> Result<(), DbError>,
     M: FnOnce(&rusqlite::Transaction<'_>) -> Result<(), DbError>,
 {
+    debug!(table = %table, cols = new_schema.columns.len(), "rebuild_table: begin (foreign_keys OFF, temp-copy primitive)");
     // foreign_keys=OFF must be set *outside* a transaction.
     conn.execute_batch("PRAGMA foreign_keys = OFF;")
         .map_err(DbError::from_rusqlite)?;
@@ -6870,6 +6891,7 @@ where
             .map_err(DbError::from_rusqlite)?;
         let mut rows = check.query([]).map_err(DbError::from_rusqlite)?;
         if let Some(_row) = rows.next().map_err(DbError::from_rusqlite)? {
+            warn!(table = %table, "rebuild_table: foreign_key_check failed; existing data violates new constraint, rolling back");
             return Err(DbError::Sqlite {
                 message: format!(
                     "foreign-key check failed after rebuild of `{table}`; \
@@ -6882,6 +6904,7 @@ where
         drop(check);
 
         tx.commit().map_err(DbError::from_rusqlite)?;
+        debug!(table = %table, indexes = captured_indexes.len(), "rebuild_table: committed (indexes recreated)");
         Ok(())
     })();
 
@@ -6889,6 +6912,9 @@ where
     let pragma_result = conn
         .execute_batch("PRAGMA foreign_keys = ON;")
         .map_err(DbError::from_rusqlite);
+    if let Err(e) = &pragma_result {
+        warn!(table = %table, error = %e, "rebuild_table: failed to re-enable foreign_keys after rebuild");
+    }
 
     result.and(pragma_result)
 }
@@ -7249,6 +7275,7 @@ fn do_add_relationship(
     on_update: ReferentialAction,
     create_fk: bool,
 ) -> Result<TableDescription, DbError> {
+    debug!(name = ?name, parent = %parent_table, child = %child_table, "add_relationship");
     // Canonicalize both endpoints to their stored case (and refuse a
     // non-existent / internal `__rdbms_*` table as "no such table"), like
     // the sibling schema-mutation executors — so the relationship metadata
@@ -7409,6 +7436,7 @@ fn do_drop_relationship(
     source: Option<&str>,
     selector: &RelationshipSelector,
 ) -> Result<Option<TableDescription>, DbError> {
+    debug!(selector = ?selector, "drop_relationship");
     // Resolve to a single relationship row.
     let resolved: Option<(String, String, String, String, String)> = match selector {
         RelationshipSelector::Named { name } => conn
@@ -7488,6 +7516,7 @@ fn do_alter_add_table_check(
     name: Option<&str>,
     expr_sql: &str,
 ) -> Result<TableDescription, DbError> {
+    debug!(table = %table, name = ?name, "alter_add_table_check");
     let canonical_table = require_canonical_table(conn, table)?;
     let table = canonical_table.as_str();
     let old_schema = read_schema(conn, table)?;
@@ -7593,6 +7622,7 @@ fn do_alter_add_unique(
     table: &str,
     columns: &[String],
 ) -> Result<TableDescription, DbError> {
+    debug!(table = %table, cols = ?columns, "alter_add_unique");
     let canonical_table = require_canonical_table(conn, table)?;
     let table = canonical_table.as_str();
     let old_schema = read_schema(conn, table)?;
@@ -7660,6 +7690,7 @@ fn do_drop_constraint_by_name(
     table: &str,
     name: &str,
 ) -> Result<Option<TableDescription>, DbError> {
+    debug!(table = %table, name = %name, "drop_constraint_by_name");
     let canonical_table = require_canonical_table(conn, table)?;
     let table = canonical_table.as_str();
 
@@ -7781,6 +7812,7 @@ fn do_alter_add_foreign_key(
     name: Option<&str>,
     fk: &SqlForeignKey,
 ) -> Result<TableDescription, DbError> {
+    debug!(child = %child_table, name = ?name, "alter_add_foreign_key");
     reject_internal_table_name(child_table)?;
     reject_internal_table_name(&fk.parent_table)?;
     // Resolve the parent columns: explicit must be the full PK (F-A);
@@ -7891,6 +7923,7 @@ fn do_add_index(
     columns: &[String],
     unique: bool,
 ) -> Result<TableDescription, DbError> {
+    debug!(name = ?name, table = %table, cols = ?columns, unique, "add_index");
     // 0. Canonicalize to the stored case (and refuse a non-existent /
     //    internal `__rdbms_*` table) — both the simple `add index` and SQL
     //    `CREATE INDEX` surfaces reach here, and the auto-index name embeds
@@ -7979,6 +8012,7 @@ fn do_drop_index(
     source: Option<&str>,
     selector: &IndexSelector,
 ) -> Result<TableDescription, DbError> {
+    debug!(selector = ?selector, "drop_index");
     let (index_name, table_name) = match selector {
         IndexSelector::Named { name } => {
             let lookup = conn.query_row(
@@ -8067,6 +8101,7 @@ fn do_describe_table_request(
 }
 
 fn do_describe_table(conn: &Connection, name: &str) -> Result<TableDescription, DbError> {
+    debug!(name = %name, "describe_table");
     // Column info — including the ADR-0029 constraints — comes
     // from `read_schema`, the single source of per-column truth
     // (it joins `pragma_table_info` with our type metadata and
@@ -8422,6 +8457,7 @@ fn do_insert(
     user_columns: Option<&[String]>,
     user_values: &[Value],
 ) -> Result<InsertResult, DbError> {
+    debug!(table = %table, "insert");
     let canonical_table = require_canonical_table(conn, table)?;
     let table = canonical_table.as_str();
     let schema = read_schema(conn, table)?;
@@ -8500,6 +8536,14 @@ fn do_insert(
         ));
     }
 
+    debug!(
+        table = %table,
+        user_cols = user_cols.len(),
+        total_cols = bindings.len(),
+        autofilled = bindings.len() - user_cols.len(),
+        "insert: column bindings resolved (serial/shortid auto-fill applied)"
+    );
+
     let cols_csv = bindings
         .iter()
         .map(|(c, _)| quote_ident(c))
@@ -8579,6 +8623,7 @@ fn do_update(
     assignments: &[(String, Value)],
     filter: &RowFilter,
 ) -> Result<UpdateResult, DbError> {
+    debug!(table = %table, assignments = assignments.len(), "update");
     if assignments.is_empty() {
         return Err(DbError::InvalidValue(
             "UPDATE requires at least one assignment".to_string(),
@@ -8678,6 +8723,7 @@ fn do_delete(
     table: &str,
     filter: &RowFilter,
 ) -> Result<DeleteResult, DbError> {
+    debug!(table = %table, "delete");
     let canonical_table = require_canonical_table(conn, table)?;
     let table = canonical_table.as_str();
     let schema = read_schema(conn, table)?;
@@ -8732,6 +8778,14 @@ fn do_delete(
         }
     }
 
+    debug!(
+        table = %table,
+        rows_affected,
+        cascaded_relationships = cascade.len(),
+        rewritten_tables = rewritten_tables.len(),
+        "delete: complete (cascade effects detected by child-count diff)"
+    );
+
     let changes = Changes {
         schema_dirty: false,
         rewritten_tables,
@@ -9045,6 +9099,7 @@ fn do_sql_insert(
     returning: bool,
     literal_rows: &[Vec<Option<Value>>],
 ) -> Result<InsertResult, DbError> {
+    debug!(table = %target_table, returning, "sql_insert");
     debug!(sql = %sql, table = %target_table, returning, "sql_insert");
     let canonical_table = require_canonical_table(conn, target_table)?;
     let target_table = canonical_table.as_str();
@@ -9161,6 +9216,7 @@ fn do_sql_update(
     returning: bool,
     set_literals: &[(String, Option<Value>)],
 ) -> Result<UpdateResult, DbError> {
+    debug!(table = %target_table, returning, "sql_update");
     debug!(sql = %sql, table = %target_table, returning, "sql_update");
     let canonical_table = require_canonical_table(conn, target_table)?;
     let target_table = canonical_table.as_str();
@@ -9544,6 +9600,7 @@ fn do_query_data(
     filter: Option<&Expr>,
     limit: Option<u64>,
 ) -> Result<DataResult, DbError> {
+    debug!(table = %table, limit = ?limit, "query_data");
     let schema = read_schema(conn, table)?;
     let column_names: Vec<String> = schema.columns.iter().map(|c| c.name.clone()).collect();
     let column_types: Vec<Option<Type>> =
@@ -9602,6 +9659,7 @@ fn format_cell(value: rusqlite::types::Value, ty: Option<Type>) -> Option<String
 /// executes the statement), and pairs the plan rows with a
 /// standard-SQL display form of the statement.
 fn do_explain_plan(conn: &Connection, query: &Command) -> Result<QueryPlan, DbError> {
+    debug!("explain_plan");
     let (exec_sql, params) = match query {
         Command::ShowData {
             name,
@@ -9855,6 +9913,7 @@ fn do_rebuild_from_text(
     source: Option<&str>,
     project_path: &Path,
 ) -> Result<(), DbError> {
+    debug!(path = %project_path.display(), "rebuild_from_text");
     let yaml_path = project_path.join(PROJECT_YAML);
     let data_dir = project_path.join(DATA_DIR);