feat: comprehensive logging across parser, app, persistence, runtime (X1)

Completes the X1 full sweep started in a8ad0c6 (db.rs). Closes X1 -> [x].

- persistence/mod.rs: debug! on every yaml/CSV/history write -- the
  silent-failure-prone disk paths (write_schema, write_table_data incl.
  the empty->delete branch, append_history/_failure).
- runtime.rs: debug! on execute_command_typed dispatch (one per executed
  command, complements the db.rs executor logs).
- app.rs: debug! on submit (route + submission mode), dispatch_app_command,
  and the ADR-0044 diagram-vs-prose render-mode choice.
- dsl/parser.rs: trace! on parse begin/outcome at the parse_command_inner
  choke point -- trace, not debug, because the live overlay/completion
  re-parse per keystroke (hot path).
- logging.rs: documented level discipline (error/warn/info/debug/trace) so
  the convention survives across sessions.

Levels verified end-to-end through the real worker thread + logging::init.
~75 -> 135 tracing sites total. Tests: 2207 pass / 0 fail / 1 ignored.
Clippy clean.
This commit is contained in:
claude@clouddev1
2026-06-10 11:38:22 +00:00
parent a8ad0c6cc3
commit 0a7612efe2
6 changed files with 87 additions and 12 deletions
+19 -9
View File
@@ -804,17 +804,27 @@ since ADR-0027.)
## Cross-cutting ## 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 infrastructure per `CLAUDE.md` (decision points, parameter
values, fallback paths). values, fallback paths).
*(Partial, verified 2026-06-07: the logging **harness** is *(Done 2026-06-10 via a full-sweep instrumentation pass. The
wired — `src/logging.rs` sets up file-backed `tracing` with an prior state (verified 2026-06-07) was a wired harness
env filter — but instrumentation is **sparse**: ~25 `tracing::` (`src/logging.rs`) but sparse instrumentation — failure-path
call sites across the tree, concentrated in `runtime.rs` and heavy, nothing in `db.rs`/parser/executors. The sweep brought
`undo.rs` and mostly error/warning on failure paths. The every layer to the "log liberally" bar under a documented level
decision-point / parameter-value / fallback-path coverage the discipline (see the `logging.rs` module doc): **`db.rs`** gained
`CLAUDE.md` "log liberally" standard calls for — especially in entry-level `debug!` on all 34 `do_*` executors plus decision-point
`db.rs`, the parser, and the executors — is largely absent.)* 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 - [~] **X2** Language: English-only for v1; multi-language is an
open question to revisit later. open question to revisit later.
- [~] **X3** Accessibility: TUI screen-reader support is - [~] **X3** Accessibility: TUI screen-reader support is
+9
View File
@@ -1311,6 +1311,13 @@ impl App {
return Vec::new(); 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 // Parse-first: app-level commands and DSL commands now
// share the chumsky parser (per the round-5 refactor). // share the chumsky parser (per the round-5 refactor).
// App commands work in both modes — they're not gated by // App commands work in both modes — they're not gated by
@@ -1342,6 +1349,7 @@ impl App {
source: &str, source: &str,
) -> Vec<Action> { ) -> Vec<Action> {
use crate::dsl::{AppCommand, MessagesValue, ModeValue}; use crate::dsl::{AppCommand, MessagesValue, ModeValue};
debug!(command = ?cmd, "dispatch app command");
match cmd { match cmd {
AppCommand::Quit => vec![Action::Quit], AppCommand::Quit => vec![Action::Quit],
AppCommand::Help { topic } => { AppCommand::Help { topic } => {
@@ -1700,6 +1708,7 @@ impl App {
| Command::AddRelationship { .. } | Command::AddRelationship { .. }
| Command::DropRelationship { .. } | 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( for line in crate::output_render::render_structure_with_diagrams(
desc, desc,
self.last_output_width, self.last_output_width,
+19 -3
View File
@@ -12,6 +12,8 @@
//! synthetic "unknown command" error when the input's first //! synthetic "unknown command" error when the input's first
//! identifier-shape token isn't a registered entry word. //! identifier-shape token isn't a registered entry word.
use tracing::trace;
use crate::dsl::command::Command; use crate::dsl::command::Command;
use crate::mode::Mode; use crate::mode::Mode;
@@ -150,13 +152,27 @@ fn parse_command_inner(
schema: Option<&crate::completion::SchemaCache>, schema: Option<&crate::completion::SchemaCache>,
mode: Mode, mode: Mode,
) -> Result<Command, ParseError> { ) -> Result<Command, ParseError> {
// `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() { if input.trim().is_empty() {
trace!("parse: empty input");
return Err(ParseError::Empty); return Err(ParseError::Empty);
} }
if let Some(result) = try_walker_route(input, schema, mode) { let result =
return 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 /// Synthetic ParseError for inputs whose first identifier-shape
+32
View File
@@ -6,6 +6,38 @@
//! environment variable; if neither is set we default to //! environment variable; if neither is set we default to
//! `~/.rdbms-playground/playground.log` and create directories as //! `~/.rdbms-playground/playground.log` and create directories as
//! needed. //! 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::fs::{File, OpenOptions, create_dir_all};
use std::path::{Path, PathBuf}; use std::path::{Path, PathBuf};
+7
View File
@@ -19,6 +19,8 @@ use std::fs;
use std::io::Write as _; use std::io::Write as _;
use std::path::{Path, PathBuf}; use std::path::{Path, PathBuf};
use tracing::debug;
use crate::dsl::action::ReferentialAction; use crate::dsl::action::ReferentialAction;
use crate::dsl::types::Type; use crate::dsl::types::Type;
use crate::mode::Mode; use crate::mode::Mode;
@@ -338,6 +340,7 @@ impl Persistence {
/// renames over the destination. /// renames over the destination.
pub fn write_schema(&self, schema: &SchemaSnapshot) -> Result<(), PersistenceError> { pub fn write_schema(&self, schema: &SchemaSnapshot) -> Result<(), PersistenceError> {
let body = yaml::serialize_schema(schema); 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()) atomic_write(&self.project_path.join(PROJECT_YAML), body.as_bytes())
} }
@@ -355,8 +358,10 @@ impl Persistence {
/// with files they didn't ask for. /// with files they didn't ask for.
pub fn write_table_data(&self, table: &TableSnapshot) -> Result<(), PersistenceError> { pub fn write_table_data(&self, table: &TableSnapshot) -> Result<(), PersistenceError> {
if table.rows.is_empty() { 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); return self.delete_table_data(&table.name);
} }
debug!(table = %table.name, rows = table.rows.len(), "persist: write data/<table>.csv (atomic)");
let data_dir = self.project_path.join(DATA_DIR); let data_dir = self.project_path.join(DATA_DIR);
fs::create_dir_all(&data_dir).map_err(|source| PersistenceError::Io { fs::create_dir_all(&data_dir).map_err(|source| PersistenceError::Io {
operation: "create", operation: "create",
@@ -394,6 +399,7 @@ impl Persistence {
pub fn append_history(&self, command_text: &str) -> Result<(), PersistenceError> { pub fn append_history(&self, command_text: &str) -> Result<(), PersistenceError> {
let path = self.project_path.join(HISTORY_LOG); let path = self.project_path.join(HISTORY_LOG);
let line = history::format_record(command_text, history::utc_iso8601_now()); 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) history::append(&path, &line)
} }
@@ -411,6 +417,7 @@ impl Persistence {
history::utc_iso8601_now(), history::utc_iso8601_now(),
history::STATUS_ERR, history::STATUS_ERR,
); );
debug!(len = command_text.len(), "persist: append err record to history.log");
history::append(&path, &line) history::append(&path, &line)
} }
+1
View File
@@ -2531,6 +2531,7 @@ async fn execute_command_typed(
command: Command, command: Command,
source: String, source: String,
) -> Result<CommandOutcome, DbError> { ) -> Result<CommandOutcome, DbError> {
debug!(verb = command.verb(), "execute command (routing to worker)");
let src = Some(source); let src = Some(source);
match command { match command {
Command::CreateTable { Command::CreateTable {