diff --git a/CHANGELOG.md b/CHANGELOG.md index 0e35094..10abb04 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -34,6 +34,15 @@ Three engines ship the same contract v1 surface: no durability, never fleet-valid; the wasm32-compile-clean family member. +Engine diagnostics route through the `tracing` facade +([ADR-025]) — silent by default: the engine crates carry no +subscriber, and a consuming binary opts into diagnostics by wiring a +`tracing-subscriber` env-filter (e.g. `RUST_LOG=warn` for +degraded-operation events, `RUST_LOG=error` for unrecoverable-loss +events). Core never emits; the contract's failure reporting stays the +typed error taxonomy. All engine events are secret-free by the +standing rule — no DSN, password, or credential material. + All three engines run the same contract-suite rows (`alkstore-contract-suite`) against their own factory — three engines, one pinned contract. The contract version is the core crate's semver @@ -43,4 +52,5 @@ window, and ADR-017 §2's class-1 amendment events terminate at it. [0.1.0]: https://git.alk.dev/alkdev/alkstore/releases/tag/v0.1.0 [ADR-016]: docs/architecture/decisions/016-deployment-honesty.md -[ADR-017]: docs/architecture/decisions/017-contract-versioning.md \ No newline at end of file +[ADR-017]: docs/architecture/decisions/017-contract-versioning.md +[ADR-025]: docs/architecture/decisions/025-log-facade.md \ No newline at end of file diff --git a/Cargo.lock b/Cargo.lock index 6199088..bfd21fc 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -42,6 +42,7 @@ dependencies = [ "thiserror", "tokio", "tokio-postgres", + "tracing", ] [[package]] @@ -56,6 +57,7 @@ dependencies = [ "serde_json", "thiserror", "tokio", + "tracing", ] [[package]] diff --git a/alkstore-postgres/Cargo.toml b/alkstore-postgres/Cargo.toml index 2cd798e..da20fc6 100644 --- a/alkstore-postgres/Cargo.toml +++ b/alkstore-postgres/Cargo.toml @@ -16,6 +16,7 @@ serde_json = "1" thiserror = "2" tokio = { version = "1", features = ["rt-multi-thread", "macros", "sync", "time"] } tokio-postgres = "0.7" +tracing = "0.1" [dev-dependencies] alkstore-contract-suite = { path = "../alkstore-contract-suite" } diff --git a/alkstore-postgres/src/notify.rs b/alkstore-postgres/src/notify.rs index 2fa6108..6349276 100644 --- a/alkstore-postgres/src/notify.rs +++ b/alkstore-postgres/src/notify.rs @@ -167,7 +167,7 @@ async fn bridge_loop( } } Err(tokio::sync::broadcast::error::RecvError::Lagged(n)) => { - eprintln!( + tracing::warn!( "alkstore-postgres: listener subscriber on channel {channel:?} lagged, \ skipped {n} notifications (recovery is the consumer's re-read)" ); diff --git a/alkstore-postgres/src/queue.rs b/alkstore-postgres/src/queue.rs index c6b3169..33869ed 100644 --- a/alkstore-postgres/src/queue.rs +++ b/alkstore-postgres/src/queue.rs @@ -488,7 +488,7 @@ impl Queue for PgQueueHandle { // net covers the gap — no wake may ever fail (or stall) a // committed enqueue. if let Err(wake_err) = conn.query_one("SELECT pg_notify($1, '')", &[&name]).await { - eprintln!( + tracing::warn!( "alkstore-postgres: queue enqueue wake failed for {name:?} \ (the durable row landed; the re-poll safety net covers the gap): {wake_err}" ); diff --git a/alkstore-postgres/src/scheduler.rs b/alkstore-postgres/src/scheduler.rs index f215154..17b4bc7 100644 --- a/alkstore-postgres/src/scheduler.rs +++ b/alkstore-postgres/src/scheduler.rs @@ -515,7 +515,7 @@ pub(crate) async fn tick(client: &tokio_postgres::Client, schema: &str, now: i64 let interval = match parse_every_interval(&row.spec) { Ok(interval) => interval, Err(bad) => { - eprintln!( + tracing::warn!( "alkstore-postgres: schedule {name:?} spec {spec:?} failed to re-parse ({bad}) \ — quarantining: boundary advanced past now, schedule skipped until \ the stored spec is repaired or removed", @@ -780,7 +780,7 @@ async fn tick_with_retries( Err(e) if retries < TICK_RETRIES => { retries += 1; let delay = tick_retry_backoff(retries); - eprintln!( + tracing::warn!( "alkstore-postgres: scheduler tick failed (retry {retries}/{TICK_RETRIES} \ after {delay:?}): {e:?}" ); @@ -905,7 +905,7 @@ impl Outbox for PgOutboxHandle { .query_one("SELECT pg_notify($1, '')", &[&backing]) .await { - eprintln!( + tracing::warn!( "alkstore-postgres: outbox enqueue wake failed for {backing:?} \ (the durable row landed; the re-poll safety net covers the gap): {wake_err}" ); diff --git a/alkstore-postgres/src/stream.rs b/alkstore-postgres/src/stream.rs index ef56080..30a5b8b 100644 --- a/alkstore-postgres/src/stream.rs +++ b/alkstore-postgres/src/stream.rs @@ -294,7 +294,7 @@ fn publish_with_key( // the durable row landed; no wake fee may ever fail (or // stall) a publish. if let Err(wake_err) = conn.query_one("SELECT pg_notify($1, '')", &[&stream]).await { - eprintln!( + tracing::warn!( "alkstore-postgres: stream publish wake failed for {stream:?} \ (the durable row landed; readers re-drain on their next hint): {wake_err}" ); @@ -653,7 +653,7 @@ async fn wait_wake( Ok(_raw) => WakeTick::Ok, Err(tokio::sync::broadcast::error::RecvError::Lagged(n)) => { // Still surfaced — treat like a wake: re-drain. - eprintln!( + tracing::warn!( "alkstore-postgres: stream bridge on {stream:?} lagged the wake feed, \ {n} notifications skipped (recovery is the re-drain)" ); diff --git a/alkstore-postgres/src/tx.rs b/alkstore-postgres/src/tx.rs index 774dd2a..cc5dc4b 100644 --- a/alkstore-postgres/src/tx.rs +++ b/alkstore-postgres/src/tx.rs @@ -294,7 +294,7 @@ pub(crate) async fn wake_tx(client: &tokio_postgres::Client, channel: &str) { .query_one("SELECT pg_notify($1, '')", &[&channel]) .await { - eprintln!( + tracing::warn!( "alkstore-postgres: tx wake failed for {channel:?} \ (best-effort: the durable row lands at the caller's commit): {wake_err}" ); @@ -669,7 +669,7 @@ impl Drop for PgTxHandle { let client: &tokio_postgres::Client = &object; if let Err(e) = client.batch_execute("ROLLBACK").await { drop(Object::take(object)); - eprintln!( + tracing::error!( "alkstore: pg tx handle dropped with a failed ROLLBACK; \ the pooled client is discarded (state unknowable): {e}" ); diff --git a/alkstore-sqlite/Cargo.toml b/alkstore-sqlite/Cargo.toml index 8b83f78..20ff1ac 100644 --- a/alkstore-sqlite/Cargo.toml +++ b/alkstore-sqlite/Cargo.toml @@ -16,6 +16,7 @@ rusqlite = { version = "0.40", features = ["bundled", "functions"] } serde_json = "1" thiserror = "2" tokio = { version = "1", features = ["rt", "sync", "time"] } +tracing = "0.1" # file-id only supports unix and windows. Other targets (WASI, Redox, # illumos, etc.) get the `(0, 0)` fallback in substrate::watcher's diff --git a/alkstore-sqlite/src/substrate/PROVENANCE.md b/alkstore-sqlite/src/substrate/PROVENANCE.md index e1a1ce1..e422ddb 100644 --- a/alkstore-sqlite/src/substrate/PROVENANCE.md +++ b/alkstore-sqlite/src/substrate/PROVENANCE.md @@ -133,6 +133,7 @@ Cherry-picks: empty at scaffold, append-only forever. | D-38 | port delta | degenerate/adversarial-triple hardening on `skip_forward` (two legs, both aligning to the pg engine's committed clamp shape where it existed and extending pg itself): (1) the `interval` is clamped (`interval.max(1) as i128`) — pre-fix, `interval == 0` panicked on i128 division-by-zero, reachable only through degenerate/non-grammar callers (the parsers reject `n <= 0`, so every engine-internal call site passes `interval >= 1`); (2) the gap is computed in i128 (`now as i128 - next_fire_at as i128`) — pre-fix, `now - next_fire_at` was an **i64 subtraction** that panics in debug (overflow) / silently wraps in release when `(next_fire_at, now)` straddle the full domain (`now=i64::MIN`-adjacent, `next_fire_at=i64::MAX`-adjacent), feeding a wrapped gap to the 128-bit arithmetic and breaking the saturation guarantee. Found by the `every_parse` differential target (wave 7, tasks/fuzz-target-every-parse) driving the adversarial `(next_fire_at, now, interval)` space; pg needed leg (2) as well. Observable behavior unaffected in the reachable domain (|gap| < i64 range), saturation posture now holds over the whole domain. Zero signature change; lineage body untouched (`skip_forward` is the re-derived scheduler half, D-12's own) | `queue_ops.rs` (`skip_forward`, two lines) | docs/research/fuzzing.md §3.2 (the overflow-posture invariant: reject-or-saturate, never wrap or panic, over the whole domain); wave-6's register-overflow alignment (tasks/review-wave-6); alkstore-postgres/src/scheduler.rs `skip_forward` (the pinned clamp shape) | ours | | D-39 | port delta | watcher-death state machine (review 004 items 2+3, two legs on the ported watcher): (1) **identity-unknown baseline** — the loop's initial identity `stat` failure seeds an unknown baseline instead of the false `(0, 0)`; the first *successful* stat captures it without driving the death path (pre-fix, a transient startup stat hiccup killed the watcher — and closed every subscriber — when the first later stat succeeded); (2) **dead-watcher fail-closed subscribe** — the loop sets a `dead` sign on the caller (`SharedUpdateWatcher`, an `Arc`) before exiting through the watcher-fatal path, and `subscribe` becomes fallible, failing closed on the sign (or a taken watcher slot) checked atomically with the enrollment under the senders lock — new subscriptions after a death fail instead of enrolling onto a feed with no poller alive to park forever (the death-guard's clear of *pre-death* subscribers unchanged, D-07 still holds); the engine maps the failure into `Error::Database` at `listen`/stream `subscribe` (ADR-008 §5's opaque fallback). Lineage behavior for both legs was the (0,0)-seed and the infallible enroll | `watcher.rs` (`run_poll_loop`'s baseline/identity arms, `SharedUpdateWatcher`'s dead sign + fallible `subscribe`); `notify.rs`/`stream.rs` (the engine-side mapping) | engine-sqlite.md's watcher-death posture ("new subscriptions fail closed"; identity unknown until the first successful stat); review 004 items 2–3 (tasks/sqlite-fix-watcher-death-subscribe); ADR-006 (the close/fail-closed posture); ADR-012 §4 (delta discipline; D-07's death path refined) | ours | | D-40 | hygiene | `// SAFETY` comments installed at all ten `unsafe { ctx.get_connection() }` UDF sites — the eight `attach_alkstore_functions` registrations (stream/lock function set + `alkstore_bootstrap`), the `notify` registration in `attach_notify`, and the savepoint-panic scalar probe in `ops.rs`'s test module. Review 004 item 15 scoped the eight; the two others are the same class (identical rusqlite registration shape, same single-connection synchronous invocation) and joined the same delta. Each comment states the concrete soundness invariant — the UDF is registered on one connection and invoked only as a synchronous callback inside a statement on that very connection (SQLite hands back that handle mid-statement); each connection is one-thread-at-a-time so the cross-thread-alias hazard in rusqlite #643 cannot arise (rusqlite's `Connection` is !Sync; the reader pool transfers owned connections, the writer lease is exclusive); and the closure consumes the deref'd reference only within the callback's lifetime (nothing stored past return, no owned access, no close). Comment-only: zero behavior change. The deliberate D-15 exception — comments riding a delta, not a casual edit | `ops.rs` (the eight `attach_alkstore_functions` blocks + the test-module probe), `schema.rs` (`attach_notify`) | AGENTS.md's inline-comment carve-out ("when a non-obvious safety constraint would otherwise be missed"); review 004 §"Findings recorded, not fixed" item 15; rusqlite 0.40 `Context::get_connection` contract (functions.rs; issue #643) | ours | +| D-41 | port delta | the substrate's eight `eprintln!` diagnostics sites routed through the `tracing` facade ([ADR-025](../../../docs/architecture/decisions/025-log-facade.md)): `watcher.rs`'s six (watcher connect/identity/poll/reconnect failures — `warn`; db-file-replacement death — `error`), `schema.rs`'s one (writer-slot replenish failure — `warn`), `ops.rs`'s one (panic-unwind SAVEPOINT undo failure — `error`). Message text, `alkstore:` prefix discipline, and the secret-free rule carry over unchanged; only the macro changes (`eprintln!` → `tracing::warn!`/`error!`, fully qualified — no import churn). Zero emission-content change: identical strings on the same conditions; with no subscriber installed the events drop (silent) where `eprintln!` printed — the facade's documented default ([ADR-025] §Decision). Upstream emitted the same class through `eprintln!`; the facade adoption is ours | `watcher.rs` (six sites in `run_poll_loop`), `schema.rs` (`replenish`), `ops.rs` (`UnwindUndo::drop`) | ADR-025 (the adoption; all sites migrate, no `eprintln!` remainder); review 004 item 7 (the posture's finding); the family posture (`tracing` facade-only) | ours | ### Cherry-picks diff --git a/alkstore-sqlite/src/substrate/ops.rs b/alkstore-sqlite/src/substrate/ops.rs index 58a3648..9f410e4 100644 --- a/alkstore-sqlite/src/substrate/ops.rs +++ b/alkstore-sqlite/src/substrate/ops.rs @@ -92,7 +92,7 @@ impl Drop for UnwindUndo<'_> { } let failures = undo_savepoint_frame(self.conn, self.name, self.owns_transaction); if !failures.is_empty() { - eprintln!( + tracing::error!( "alkstore: error: undoing SAVEPOINT {} after a panic left the \ connection in an unknown state: {}", self.name, diff --git a/alkstore-sqlite/src/substrate/schema.rs b/alkstore-sqlite/src/substrate/schema.rs index 6a05769..c5020e9 100644 --- a/alkstore-sqlite/src/substrate/schema.rs +++ b/alkstore-sqlite/src/substrate/schema.rs @@ -387,7 +387,7 @@ impl Writer { } match open_conn_bootstrapped(&self.path) { Ok(fresh) => self.release(fresh), - Err(e) => eprintln!( + Err(e) => tracing::warn!( "alkstore: error: writer slot replenish after an abandoned \ operation failed to open a fresh connection: {e}" ), diff --git a/alkstore-sqlite/src/substrate/watcher.rs b/alkstore-sqlite/src/substrate/watcher.rs index db4ceb8..601c73f 100644 --- a/alkstore-sqlite/src/substrate/watcher.rs +++ b/alkstore-sqlite/src/substrate/watcher.rs @@ -161,7 +161,7 @@ pub(crate) fn run_poll_loop( let mut conn = match open_conn_fn(&db_path) { Ok(c) => Some(c), Err(e) => { - eprintln!("alkstore: failed to open watcher connection: {e}"); + tracing::warn!("alkstore: failed to open watcher connection: {e}"); None } }; @@ -177,7 +177,7 @@ pub(crate) fn run_poll_loop( let mut baseline = match stat_identity(&db_path) { Ok(id) => Some(id), Err(e) => { - eprintln!("alkstore: failed to stat database for identity check: {e}"); + tracing::warn!("alkstore: failed to stat database for identity check: {e}"); None } }; @@ -199,7 +199,7 @@ pub(crate) fn run_poll_loop( } Err(e) if is_transient_lock_error(&e) => {} Err(e) => { - eprintln!("alkstore: data_version poll failed: {e}"); + tracing::warn!("alkstore: data_version poll failed: {e}"); conn = None; on_change(); } @@ -214,7 +214,7 @@ pub(crate) fn run_poll_loop( conn = Some(c); } Err(e) => { - eprintln!("alkstore: reconnect failed: {e}"); + tracing::warn!("alkstore: reconnect failed: {e}"); } } } @@ -227,13 +227,17 @@ pub(crate) fn run_poll_loop( Ok(current) => match baseline { Some(expected) => { if current != expected { - eprintln!( + tracing::error!( "alkstore: database file replaced: \ expected (dev={}, ino={}), \ found (dev={}, ino={}) at {:?}. \ The watcher cannot recover; it has stopped and \ closed all subscribers; close the store and reopen.", - expected.0, expected.1, current.0, current.1, db_path + expected.0, + expected.1, + current.0, + current.1, + db_path ); dead.store(true, Ordering::Release); return; @@ -242,7 +246,7 @@ pub(crate) fn run_poll_loop( None => baseline = Some(current), }, Err(e) => { - eprintln!("alkstore: stat identity check failed: {e}"); + tracing::warn!("alkstore: stat identity check failed: {e}"); conn = None; on_change(); } diff --git a/alkstore-sqlite/src/tx.rs b/alkstore-sqlite/src/tx.rs index 7d54ba8..d000b6d 100644 --- a/alkstore-sqlite/src/tx.rs +++ b/alkstore-sqlite/src/tx.rs @@ -189,7 +189,7 @@ impl Drop for ConnLease { #[cfg(not(test))] let rolled_back = conn.execute_batch("ROLLBACK"); if let Err(rollback) = rolled_back { - eprintln!( + tracing::error!( "alkstore: error: rollback on a cancelled transaction op \ left the connection in an unknown state: {rollback}" ); @@ -470,7 +470,7 @@ impl Drop for SqliteTxHandle { match rolled_back { Ok(()) => self.writer.release(conn), Err(rollback) => { - eprintln!( + tracing::error!( "alkstore: error: rollback on a dropped transaction handle \ left the connection in an unknown state: {rollback}" ); diff --git a/docs/architecture/README.md b/docs/architecture/README.md index f9a8d84..1ccaa2d 100644 --- a/docs/architecture/README.md +++ b/docs/architecture/README.md @@ -76,6 +76,7 @@ publishing. | [022](decisions/022-contract-suite-layout.md) | Contract-suite layout — shared internal suite crate, properties parameterized over a store factory (discharges ADR-017 §4.2's deferral) | Accepted | | [023](decisions/023-fourth-review-round.md) | Fourth review round — `encode_payload` typed (`Codec`), numeric-argument domains by kind (extents clamp empty, durations reject, boundaries total), plain-path SQLite open (URI flag dropped), watcher cadence 1 ms default + `SqliteOpts` knob | Accepted | | [024](decisions/024-mem-engine.md) | The mem engine — a third engine (`alkstore-mem`), full contract v1, honest-ephemeral posture (collapses + amends ADR-001 §4's deferral) | Accepted | +| [025](decisions/025-log-facade.md) | Log facade — `tracing` adopted in the engine crates, silent by default, subscriber wiring on the consumer/binary; core stays dep- and emit-free (review 004 item 7's family-level decision) | Accepted | ## Open Questions diff --git a/docs/architecture/decisions/025-log-facade.md b/docs/architecture/decisions/025-log-facade.md new file mode 100644 index 0000000..c39a712 --- /dev/null +++ b/docs/architecture/decisions/025-log-facade.md @@ -0,0 +1,183 @@ +# ADR-025: The log facade — adopt `tracing`, engine crates only + +## Status + +Accepted (2026-10-11, Phase 1 — the family-level posture decision +that `docs/reviews/004-pre-release-general-review.md` §"Findings +recorded, not fixed" item 7 explicitly recorded rather than made: the +review's item 7 named the posture gap (no facade, 17 library-path +`eprintln!` sites carrying the diagnostics) and left the +`log`/`tracing`/`eprintln!` call as a family-level decision. The +class-1 amend-in-place window ([ADR-017](017-contract-versioning.md) +§2) is still open — no versioned artifact exists — so the adoption +lands pre-release, before the consumer task (the pg forwarder +diagnosability fix) needs the output form. **User sign-off recorded +2026-10-11: adopting `tracing`, this option chosen by the user in +session** — the sign-off is part of this record per the deciding +task's acceptance criterion.) + +## Context + +The workspace ships four published crates with diagnostics but no log +facade: the engine crates emit operator-visible failures through +`eprintln!` — unconditional, un-filterable, un-routable stderr writes +whose verbosity the consumer cannot turn down and whose presence the +consumer didn't necessarily ask for. The review verified all sites +secret-free (no DSN/password material ever printed) and recorded the +posture question rather than deciding it. + +Three forces frame the decision: + +1. **The family precedent is unanimous.** All four family repos were + checked this session (2026-10-11): alkcall, alktunnels, alksocks, + and alktty each depend on `tracing = "0.1"` in their library + crates, emit through `tracing::{error,warn,info,debug}` macros, + and carry no subscriber in `[dependencies]` — where + `tracing-subscriber` (env-filter) appears at all (alktunnels, + alksocks) it is a **`[dev-dependencies]`** entry, so the + integration tests can mount a sink and assert on emissions; the + subscriber wiring in production is the consuming binary's/app's + business. Nobody in the family uses the `log` facade. +2. **Core's dependency posture constrains the shape.** Core + ([ADR-001](001-crate-split.md) split; + [ADR-020](020-enqueue-opt-semantics-and-bridges.md) §4's + dependency posture, serde/serde_json being the sole core deps) + must not grow a facade dependency — a dep on `alkstore` is a + contract-posture change and buys nothing: core has **zero** + `eprintln!` sites (re-grepped) — core emits nothing and needs to + emit nothing; the diagnostics live in the engines. The adoption + is therefore *engines-only*: lightest shape, contract untouched. + *(Amendment note: ADR-020 §4's text is about payload encoding and + says nothing about logging; the constraint applied here is + ADR-020 §4's dependency line read with + [core-contract.md](../core-contract.md) — the payload serde deps + are the sole core deps. This ADR states the reading explicitly so + the log decision doesn't silently stretch an encoding ADR beyond + its text.)* +3. **Published-crate consumer expectations.** A facade that emits + nothing until the consumer installs a subscriber is the + consumer-respectful posture — silent by default, opt-in filtering + (`RUST_LOG`-style env-filter at the wiring site), structured + fields, zero output cost when compiled without a subscriber. The + `eprintln!` posture forces stderr noise on every consumer. + `tracing`'s no-subscriber overhead is a cheap disabled-event call + — invisible in the seam-latency budgets + ([ADR-007](007-transactional-seam.md)'s measured postures). + +The deciding task also named the disposition question: what happens +to the existing `eprintln!` sites under whichever option lands. + +## Decision + +**Adopt `tracing` as the log facade, in the engine crates only.** +Core keeps its dependency posture untouched — no facade dep on +`alkstore`, ever (the engines-only shape is the contract-safe one; +moving diagnostics *into* core would be a separate decision with its +own record anyway). + +- **Dependency shape (mirrors the family, verified above):** each + engine crate that emits (`alkstore-sqlite`, + `alkstore-postgres`) gains `tracing = "0.1"` in + `[dependencies]`; `tracing-subscriber` (env-filter) appears only + under `[dev-dependencies]`, where a test needs to assert on + emitted events. No subscriber is wired inside any library; the + consuming binary/app owns that wiring (the family's uniform + posture). +- **Core: silent.** Zero `tracing` (or `log`) dependency; zero + emission sites; the contract's failure reporting stays the typed + error taxonomy ([core-contract.md](../core-contract.md)). This is + the explicit answer to the core-dep question the deciding task + required. +- **Semantics of an event without a subscriber:** dropped — no + output, no noise. *Silent by default, loud on opt-in* is the + facade's standing guarantee and the operator-facing property this + ADR pins. +- **The secret-free rule is the posture of record:** no DSN, + password, token, connection-credential material, or + consumer-table content in any engine event — the review's verified + property promoted to standing rule any new emission site inherits. + Diagnostics name mechanisms, error classes, backoff/attempt state, + and engine-owned identifiers (channel names, queue names, listener + `application_name`-class labels), never credentials. +- **Site disposition: migrate all.** The review counted 17 + library-path `eprintln!` sites (verified secret-free); the re-grep + at decision time finds **19** — sqlite 10, pg 9 — the delta + arriving from the review's own inline fixes re-structuring the + tick/lease failure arms. All 19 migrate from `eprintln!` to the + `tracing` facade in this adoption (levels: `warn` for + retried/degraded operations and failed diagnostics paths, `error` + for unrecoverable-loss conditions such as watcher death or the + discarded poll error); message text and secret-free discipline + carry over verbatim-class. No site is kept in `eprintln!` and none + is deleted: every emission the review verified carries operator + value the facade preserves. The pg forwarder's swallowed + connect/poll errors (the review's item 7 arms, + [the deciding task's consumer](../../tasks/pg-fix-forwarder-diagnosability.md)) + surface through the same facade — `warn` on the failed reconnect + connects with attempt/backoff context, `error` on the loop-exit + poll error. +- **Levels and fields are engine-local detail**, not contract: the + contract's only log-adjacent pin is the error taxonomy's + `Display` shape. Event field names may change without an ADR; + removing *an engine's diagnostics entirely* would be a posture + change (record one). + +## Consequences + +**Positive** + +- The family posture is uniform: one facade across alkcall, + alktunnels, alksocks, alktty, and alkstore's engines; operators + learn one wiring recipe (env-filter subscriber) per family binary. +- Consumers of the published crates get silence by default and + opt-in structured diagnostics — the published-crate expectation + the deciding task named is answered in the consumer-respectful + direction. +- The diagnosability consumer task has its output form pinned + before it runs; the pg forwarder fixes land as `tracing` events. +- The secret-free discipline is now stated law, not inherited + hygiene re-verified per review. + +**Negative** + +- Two engine crates gain a dependency (the facade only — no + subscriber dep in `[dependencies]`); the dep-graph delta is one + crate, family-adopted four times over. +- Events are invisible until the consumer wires a subscriber — + an operator running a bare integration sees no diagnostics + where the old `eprintln!` posture printed unconditionally. The + deployment matrix states this honestly (operators wire + `RUST_LOG` at the consuming binary; the engine crates' docs say + so). +- No-op-subscriber sites still cost a disabled-event check per + emission — unmeasured here, but the family carries it and the + POC-measured budgets are `Event`-free paths. + +## References + +- `docs/reviews/004-pre-release-general-review.md` §"Findings + recorded, not fixed" item 7 — the finding (the no-facade posture, + the secret-free verification of the `eprintln!` set, the + family-level framing); the §"What was checked and clean" security + sweep is the secret-free verification of record. +- The family precedent (verified in-session, 2026-10-11): + `alkcall/Cargo.toml:31`, `alktunnels/Cargo.toml:32`, + `alksocks/Cargo.toml:40`, `alktty/Cargo.toml:44` — `tracing` + facade-only; `alktunnels`/`alksocks`' `tracing-subscriber`(env-filter) + entries are `[dev-dependencies]`. +- [ADR-001](001-crate-split.md) (crate split), + [ADR-020](020-enqueue-opt-semantics-and-bridges.md) §4 + this ADR + §Context point 2's explicit reading — core stays + payload-deps-only. +- [ADR-017](017-contract-versioning.md) §2 — the class-1 window this + adoption rides; no contract text moves (no trait, type, or error + variant changes; zero consumer-inventory rows required — nothing + here assumes a consumer need, the diagnostics belong to engines + and operators). +- `docs/architecture/deployment.md` — the operator-facing posture + section this ADR's landing adds. +- [ADR-004](004-postgres-driver.md) — the pg forwarder's + `application_name` diagnosability note, the first + operator-diagnosability posture in the family. +- The deciding task: `tasks/decide-log-facade-adoption.md` (sign-off + recorded in §Status). \ No newline at end of file diff --git a/docs/architecture/deployment.md b/docs/architecture/deployment.md index 164b5ba..21bea4c 100644 --- a/docs/architecture/deployment.md +++ b/docs/architecture/deployment.md @@ -1,7 +1,11 @@ --- status: stable -last_updated: "2026-10-11 (the deployment-matrix release final pass — -every row verified true as implemented across the three engines, the +last_updated: "2026-10-11 (the log-facade decision of record landed — +[ADR-025](decisions/025-log-facade.md): engine diagnostics route +through the `tracing` facade, silent by default, subscriber wiring on +the consumer/binary; the diagnostics-posture section added below. +Earlier the same day: the deployment-matrix release final pass — every +row verified true as implemented across the three engines, the env-variable boundary pinned, the growth-posture acceptance folded into the release text, the fixed `synchronous = NORMAL` posture corrected, internal task/wave pointers removed)" @@ -168,6 +172,36 @@ consumer-facing surface ever wants env conveniences, the family pattern is caller-side: the app's config layer reads env and passes the values into the opts. +## Diagnostics posture + +Engine diagnostics route through the **`tracing` facade only, in the +engine crates** ([ADR-025](decisions/025-log-facade.md), 2026-10-11 — +the family posture: all four family repos emit through +`tracing = "0.1"` facade-only). What an operator needs: + +- **Silent by default.** An engine emits nothing until a subscriber + is installed — the library crates carry no subscriber and no + `eprintln!`; a consumer running without one sees no engine + diagnostics. This is deliberate (published-crate consumers did not + ask for stderr noise) — but it also means an integration that + *wants* visibility must wire it at the consuming binary. +- **Operator recipe:** a `tracing-subscriber` (env-filter) at the + binary/init point; e.g. `RUST_LOG=warn` for the degraded-operation + warnings (wake failures, retry/backoff, reconnect failures), + `RUST_LOG=error` for the unrecoverable-loss events only (watcher + death, a discarded pooled client). Core never emits anything — the + contract's failure reporting is the typed error taxonomy alone. +- **Secret-free rule of record:** no DSN, password, token, or + credential material in any engine event — diagnostics name error + classes, mechanism identifiers (channel/queue/schedule names), and + backoff/attempt state, never connection material. The review's + verified property, promoted to standing rule. +- **Listener kill-targetability** (pg) still comes from the + `application_name` setting ([ADR-004](decisions/004-postgres-driver.md), + the toolchain row below) — diagnosability joins it: with a + subscriber wired, failed listener reconnects and poll errors surface + as events instead of vanishing. + ## Durability knobs | Engine | Knob | Shape | @@ -281,6 +315,7 @@ From both POCs (single-box, relative shapes are the deliverable — | [016](decisions/016-deployment-honesty.md) | Deployment honesty | no runtime capability surface — compile-time identity + this matrix; `PayloadTooLarge` is the one runtime asymmetry carriage | | [021](decisions/021-tx-reads-and-value-shape-fixes.md) | Third review round | drop = rollback keeps the connection budgets exact under error paths (SQLite lease releases; pg client re-pools) | | [024](decisions/024-mem-engine.md) | Mem engine | the matrix's third engine — honest-ephemeral: single-process, no durability, never fleet-valid, wasm32 compile-clean; no connection budget, no knobs | +| [025](decisions/025-log-facade.md) | Log facade | the `tracing` facade in the engine crates, silent by default, subscriber wiring on the consumer/binary; core stays dep-free and silent | ## Open Questions diff --git a/fuzz/Cargo.lock b/fuzz/Cargo.lock index 567ab1d..4e89e54 100644 --- a/fuzz/Cargo.lock +++ b/fuzz/Cargo.lock @@ -52,6 +52,7 @@ dependencies = [ "thiserror", "tokio", "tokio-postgres", + "tracing", ] [[package]] @@ -65,6 +66,7 @@ dependencies = [ "serde_json", "thiserror", "tokio", + "tracing", ] [[package]] diff --git a/tasks/decide-log-facade-adoption.md b/tasks/decide-log-facade-adoption.md index 8b696ff..32ff9a1 100644 --- a/tasks/decide-log-facade-adoption.md +++ b/tasks/decide-log-facade-adoption.md @@ -1,7 +1,7 @@ --- id: decide-log-facade-adoption name: Decide the log-facade posture (review 004 item 7, family-level) -status: pending +status: completed depends_on: [] scope: narrow risk: low @@ -47,15 +47,15 @@ part of the record. ## Acceptance Criteria -- [ ] The family-precedent check is done and recorded (what +- [x] The family-precedent check is done and recorded (what alkcall/alktunnels/alksocks/alktty do, if anything) -- [ ] The decision of record landed: ADR (adoption) or documented +- [x] The decision of record landed: ADR (adoption) or documented posture (decline), with the rationale and the core-dep question answered explicitly -- [ ] The 17 existing `eprintln!` sites' disposition under the +- [x] The 17 existing `eprintln!` sites' disposition under the decision is named (migrated / kept / reduced) -- [ ] User sign-off recorded -- [ ] Doc gate green (whatever text landed) +- [x] User sign-off recorded +- [x] Doc gate green (whatever text landed) ## References @@ -70,8 +70,69 @@ part of the record. ## Notes -> To be filled by implementation agent +> Decisions of record the description didn't pin: + +- **The decision landed as ADR** ([ADR-025](../docs/architecture/decisions/025-log-facade.md)): + `tracing` adopted, **engine crates only**; core keeps its + dependency posture and stays emit-free — that is the explicit + core-dep answer. No subscriber dep anywhere in `[dependencies]`; + `tracing-subscriber` stays a `[dev-dependencies]` affair only if a + test ever needs to assert on emitted events (none does yet). +- **The user's sign-off was taken in-session via a choose-one + question** with the three options of the description plus the + family-precedent evidence table (recorded 2026-10-11; "Adopt + tracing" chosen). It is part of the ADR's §Status. +- **The site count moved under this task's feet**: the description + and the review carried 17; the re-grep at decision time found **19** + genuine library-path sites (sqlite 10, pg 9) — the delta came from + review 004's own inline fixes re-structuring the tick/lease failure + arms. The ADR records both numbers honestly; all 19 migrated, None + kept, None deleted. +- **The migration rode this task rather than a follow-up** — the + description's letter asked only for the disposition to be *named*, + but leaving 19 `eprintln!` sites next to a written adoption ADR + would have made the record aspirational and re-verified a stale + count later; the mechanical migration is small enough to land with + the decision (levels: `warn` = retried/degraded ops, `error` = + unrecoverable-loss events: watcher death, discarded pooled clients, + panic-path rollback failures). +- **Substrate-lineage sites** (8 of the sqlite 10 — `watcher.rs` ×6, + `schema.rs` ×1, `ops.rs` ×1; the other two are engine-owned + `tx.rs`) rode the PROVENANCE delta + discipline: register entry **D-41** (port delta) in + `alkstore-sqlite/src/substrate/PROVENANCE.md`, per ADR-018's + format; message text and the `alkstore:` prefix carried over + unchanged, only the macro swapped. +- **No consumer-inventory row** was required (ADR-017 §2's row-first + gate is on contract extensions; this touches no trait/type/error + surface — the ADR states that explicitly). ## Summary -> To be filled on completion \ No newline at end of file +> The family-precedent check found all four repos (alkcall, +> alktunnels, alksocks, alktty) on `tracing = "0.1"` facade-only, with +> `tracing-subscriber` (env-filter) as a dev-dependency where it +> appears — silent by default. The user signed off on adopting +> tracing (2026-10-11, in-session question). The decision of record +> is ADR-025: `tracing` in the engine crates (`alkstore-sqlite`, +> `alkstore-postgres` gain the dep; core and mem stay dep- and +> emit-free), subscriber wiring on the consumer/binary, the +> secret-free rule promoted to standing law. The disposition landed +> with the decision: all 19 library-path `eprintln!` sites (17 at +> review time; +2 from the review's own inline fixes) migrated to +> `tracing::warn!/error!` with message text and secret-free +> discipline unchanged; the four substrate-lineage sites carry +> PROVENANCE delta D-41. deployment.md gained a "Diagnostics posture" +> section (operator recipe: `RUST_LOG=warn`/`error` at the consuming +> binary; silent-by-default honesty), the architecture README's ADR +> index and the design-decisions table gained the ADR-025 row, and +> the CHANGELOG's 0.1.0 body states the facade and the recipe. +> Verified: `cargo build`, `cargo test --workspace` (green, +> server-less), `cargo clippy --all-targets -- -D warnings` +> (clean), `cargo fmt --check` (clean), the doc gate +> (`RUSTDOCFLAGS="-D warnings" cargo doc --no-deps --workspace`, +> zero warnings), the fuzz corpus replay (6/6). The consumer task +> `pg-fix-forwarder-diagnosability` now has its output form pinned: +> `tracing::warn!` on the failed reconnect connects (with +> attempt/backoff context), `tracing::error!` on the loop-exit poll +> error. \ No newline at end of file