From a8ad0c6cc3b32d86cecd12a83b065fd8fa9784df Mon Sep 17 00:00:00 2001 From: "claude@clouddev1" Date: Wed, 10 Jun 2026 11:26:45 +0000 Subject: [PATCH] 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 | 63 +++++++++++++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 61 insertions(+), 2 deletions(-) diff --git a/src/db.rs b/src/db.rs index cc77bfd..fc730d0 100644 --- a/src/db.rs +++ b/src/db.rs @@ -1921,7 +1921,7 @@ fn worker_loop( snapshots: Option, mut rx: mpsc::Receiver, ) { - 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 { + 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 { + 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 { + 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 { + 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 { + 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 { + 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 { + 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 { + 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 { + 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 { + 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 { + 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 { + 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 { } fn do_list_tables(conn: &Connection) -> Result, 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, 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, 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, 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 { + 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, 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 { + 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 { + 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, 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 { + 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 { + 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 { + 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 { + 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 { + 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 { + 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 { + 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>], ) -> Result { + 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)], ) -> Result { + 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, ) -> Result { + debug!(table = %table, limit = ?limit, "query_data"); let schema = read_schema(conn, table)?; let column_names: Vec = schema.columns.iter().map(|c| c.name.clone()).collect(); let column_types: Vec> = @@ -9602,6 +9659,7 @@ fn format_cell(value: rusqlite::types::Value, ty: Option) -> Option Result { + 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);