diff --git a/docs/requirements.md b/docs/requirements.md index 144b459..fea72ef 100644 --- a/docs/requirements.md +++ b/docs/requirements.md @@ -804,17 +804,27 @@ since ADR-0027.) ## Cross-cutting -- [/] **X1** Comprehensive logging via the project's logging +- [x] **X1** Comprehensive logging via the project's logging infrastructure per `CLAUDE.md` (decision points, parameter values, fallback paths). - *(Partial, verified 2026-06-07: the logging **harness** is - wired — `src/logging.rs` sets up file-backed `tracing` with an - env filter — but instrumentation is **sparse**: ~25 `tracing::` - call sites across the tree, concentrated in `runtime.rs` and - `undo.rs` and mostly error/warning on failure paths. The - decision-point / parameter-value / fallback-path coverage the - `CLAUDE.md` "log liberally" standard calls for — especially in - `db.rs`, the parser, and the executors — is largely absent.)* + *(Done 2026-06-10 via a full-sweep instrumentation pass. The + prior state (verified 2026-06-07) was a wired harness + (`src/logging.rs`) but sparse instrumentation — failure-path + heavy, nothing in `db.rs`/parser/executors. The sweep brought + every layer to the "log liberally" bar under a documented level + discipline (see the `logging.rs` module doc): **`db.rs`** gained + entry-level `debug!` on all 34 `do_*` executors plus decision-point + logs (rebuild-table primitive, insert auto-fill, delete cascade, + FK resolution) — so the route through delegating executors is + visible in the log sequence; **persistence** logs every + yaml/CSV/history write (the silent-failure paths); **runtime** + logs `execute_command_typed` dispatch; **`app.rs`** logs + submit / app-command dispatch / render-mode choice; the **parser** + logs parse begin/outcome at `trace` (it is a per-keystroke hot + path). Levels: `debug` for per-command detail (off by default, + `RDBMS_PLAYGROUND_LOG=debug`), `info` for lifecycle, `warn` for + fallbacks, `trace` for hot paths. Emission verified end-to-end + through the real worker thread + `logging::init`. ~75 → ~135 sites.)* - [~] **X2** Language: English-only for v1; multi-language is an open question to revisit later. - [~] **X3** Accessibility: TUI screen-reader support is diff --git a/src/app.rs b/src/app.rs index 75ec9d9..00e7bae 100644 --- a/src/app.rs +++ b/src/app.rs @@ -1311,6 +1311,13 @@ impl App { return Vec::new(); } + debug!( + persistent_mode = ?self.mode, + submission_mode = ?submission_mode, + len = effective_input.len(), + "submit" + ); + // Parse-first: app-level commands and DSL commands now // share the chumsky parser (per the round-5 refactor). // App commands work in both modes — they're not gated by @@ -1342,6 +1349,7 @@ impl App { source: &str, ) -> Vec { use crate::dsl::{AppCommand, MessagesValue, ModeValue}; + debug!(command = ?cmd, "dispatch app command"); match cmd { AppCommand::Quit => vec![Action::Quit], AppCommand::Help { topic } => { @@ -1700,6 +1708,7 @@ impl App { | Command::AddRelationship { .. } | Command::DropRelationship { .. } ) { + debug!(verb = command.verb(), width = self.last_output_width, "render: relationship diagrams (ADR-0044)"); for line in crate::output_render::render_structure_with_diagrams( desc, self.last_output_width, diff --git a/src/dsl/parser.rs b/src/dsl/parser.rs index 2a1e650..9e260c8 100644 --- a/src/dsl/parser.rs +++ b/src/dsl/parser.rs @@ -12,6 +12,8 @@ //! synthetic "unknown command" error when the input's first //! identifier-shape token isn't a registered entry word. +use tracing::trace; + use crate::dsl::command::Command; use crate::mode::Mode; @@ -150,13 +152,27 @@ fn parse_command_inner( schema: Option<&crate::completion::SchemaCache>, mode: Mode, ) -> Result { + // `trace`, not `debug`: parsing is a hot path — the live overlay / + // completion (completion.rs) re-parse per keystroke, probing + // candidates in a loop, so a per-parse `debug` line would flood. The + // executed-command story lives at `debug` in db.rs (one per submit). + trace!( + len = input.len(), + mode = ?mode, + schema_aware = schema.is_some(), + "parse: begin" + ); if input.trim().is_empty() { + trace!("parse: empty input"); return Err(ParseError::Empty); } - if let Some(result) = try_walker_route(input, schema, mode) { - return result; + let result = + try_walker_route(input, schema, mode).unwrap_or_else(|| Err(unknown_command_error(input))); + match &result { + Ok(cmd) => trace!(command = cmd.verb(), "parse: ok"), + Err(e) => trace!(error = %e, "parse: rejected"), } - Err(unknown_command_error(input)) + result } /// Synthetic ParseError for inputs whose first identifier-shape diff --git a/src/logging.rs b/src/logging.rs index ad00703..6183e49 100644 --- a/src/logging.rs +++ b/src/logging.rs @@ -6,6 +6,38 @@ //! environment variable; if neither is set we default to //! `~/.rdbms-playground/playground.log` and create directories as //! needed. +//! +//! ## Level conventions (X1 — `requirements.md`) +//! +//! Instrumentation across the tree follows a consistent level +//! discipline so the default `info` filter stays quiet and +//! `RDBMS_PLAYGROUND_LOG=debug` (or `=trace`) is a rich, layered +//! diagnostic stream. The env filter (`RDBMS_PLAYGROUND_LOG`, +//! full `EnvFilter` syntax) controls this independently of the +//! file path above; the default is `info`. +//! +//! - **`error!`** — unrecoverable failure (fatal persistence, a +//! panic-equivalent). The process is going down or a command is +//! hard-failing. +//! - **`warn!`** — recoverable failure or a fallback taken (a +//! snapshot couldn't be staged, a `PRAGMA` couldn't be restored, +//! an integrity check rolled a rebuild back). +//! - **`info!`** — low-volume lifecycle, visible by default: db +//! worker start/exit, project create/open, "logging initialised". +//! - **`debug!`** — the bulk of instrumentation, one line per +//! *executed* command and the decision points within it (executor +//! entry with key params, autofill/cascade summaries, the +//! rebuild-table primitive, persistence writes, render-mode +//! choice). Off by default. +//! - **`trace!`** — hot paths only: per-keystroke parsing +//! (`dsl::parser`), per-key input handling (`app`), per-refresh +//! table reads. A firehose; never on except when debugging that +//! specific layer. +//! +//! Rule of thumb for new code: a loop logs a single summary count, +//! never per-iteration at `debug`/`info`. Logs are developer-facing, +//! so naming the engine (SQLite/PRAGMA) is fine here even though the +//! "no engine name" rule (ADR-0002) forbids it in user-facing strings. use std::fs::{File, OpenOptions, create_dir_all}; use std::path::{Path, PathBuf}; diff --git a/src/persistence/mod.rs b/src/persistence/mod.rs index 5197b4f..96ccec7 100644 --- a/src/persistence/mod.rs +++ b/src/persistence/mod.rs @@ -19,6 +19,8 @@ use std::fs; use std::io::Write as _; use std::path::{Path, PathBuf}; +use tracing::debug; + use crate::dsl::action::ReferentialAction; use crate::dsl::types::Type; use crate::mode::Mode; @@ -338,6 +340,7 @@ impl Persistence { /// renames over the destination. pub fn write_schema(&self, schema: &SchemaSnapshot) -> Result<(), PersistenceError> { let body = yaml::serialize_schema(schema); + debug!(bytes = body.len(), "persist: write project.yaml (atomic)"); atomic_write(&self.project_path.join(PROJECT_YAML), body.as_bytes()) } @@ -355,8 +358,10 @@ impl Persistence { /// with files they didn't ask for. pub fn write_table_data(&self, table: &TableSnapshot) -> Result<(), PersistenceError> { if table.rows.is_empty() { + debug!(table = %table.name, "persist: table empty -> removing CSV (no data, no CSV)"); return self.delete_table_data(&table.name); } + debug!(table = %table.name, rows = table.rows.len(), "persist: write data/.csv (atomic)"); let data_dir = self.project_path.join(DATA_DIR); fs::create_dir_all(&data_dir).map_err(|source| PersistenceError::Io { operation: "create", @@ -394,6 +399,7 @@ impl Persistence { pub fn append_history(&self, command_text: &str) -> Result<(), PersistenceError> { let path = self.project_path.join(HISTORY_LOG); let line = history::format_record(command_text, history::utc_iso8601_now()); + debug!(len = command_text.len(), "persist: append ok record to history.log"); history::append(&path, &line) } @@ -411,6 +417,7 @@ impl Persistence { history::utc_iso8601_now(), history::STATUS_ERR, ); + debug!(len = command_text.len(), "persist: append err record to history.log"); history::append(&path, &line) } diff --git a/src/runtime.rs b/src/runtime.rs index 9124b19..2ef09b4 100644 --- a/src/runtime.rs +++ b/src/runtime.rs @@ -2531,6 +2531,7 @@ async fn execute_command_typed( command: Command, source: String, ) -> Result { + debug!(verb = command.verb(), "execute command (routing to worker)"); let src = Some(source); match command { Command::CreateTable {