diff --git a/Cargo.lock b/Cargo.lock index 03955de..de9f796 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -152,6 +152,9 @@ name = "arbitrary" version = "1.4.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c3d036a3c4ab069c7b410a2ce876bd74808d2d0888a82667669f8e783a898bf1" +dependencies = [ + "derive_arbitrary", +] [[package]] name = "arc-swap" @@ -1609,6 +1612,15 @@ dependencies = [ "cfg-if", ] +[[package]] +name = "crossbeam-channel" +version = "0.5.16" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d85363c37faeca707aef026efa9f3b34d077bce547e48f770770625c6013679e" +dependencies = [ + "crossbeam-utils", +] + [[package]] name = "crossbeam-deque" version = "0.8.7" @@ -1756,6 +1768,17 @@ version = "0.5.8" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7cd812cc2bc1d69d4764bd80df88b4317eaef9e773c75226407d9bc0876b211c" +[[package]] +name = "derive_arbitrary" +version = "1.4.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1e567bd82dcff979e4b03460c307b3cdc9e96fde3d73bed1496d2bc75d9dd62a" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + [[package]] name = "dig-cert" version = "0.1.0" @@ -1909,6 +1932,27 @@ dependencies = [ "zeroize", ] +[[package]] +name = "dig-logging" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "da9bca4fc6dec932bee48ece7abe7712ccfce2119e6c640c05eef242aa1aef4f" +dependencies = [ + "bip39", + "clap", + "once_cell", + "regex", + "serde", + "serde_json", + "thiserror 2.0.18", + "time", + "tracing", + "tracing-appender", + "tracing-subscriber", + "uuid", + "zip", +] + [[package]] name = "dig-nat" version = "0.1.0" @@ -1983,7 +2027,7 @@ dependencies = [ [[package]] name = "dig-node-service" -version = "0.37.1" +version = "0.38.0" dependencies = [ "axum", "axum-server", @@ -1991,6 +2035,7 @@ dependencies = [ "clap", "dig-cert", "dig-constants 0.3.0", + "dig-logging", "dig-node-core", "dig-wallet", "digstore-core", @@ -2007,6 +2052,8 @@ dependencies = [ "tokio", "tokio-tungstenite", "tower-http", + "tracing", + "tracing-subscriber", "windows-service", "windows-sys 0.61.2", ] @@ -3476,6 +3523,15 @@ dependencies = [ "libc", ] +[[package]] +name = "matchers" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d1525a2a28c7f4fa0fc98bb91ae755d1e2d1505079e05539e35bc876b5d65ae9" +dependencies = [ + "regex-automata", +] + [[package]] name = "matchit" version = "0.7.3" @@ -3573,6 +3629,15 @@ dependencies = [ "minimal-lexical", ] +[[package]] +name = "nu-ansi-term" +version = "0.50.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7957b9740744892f114936ab4a57b3f487491bbeafaf8083688b16841a4240e5" +dependencies = [ + "windows-sys 0.61.2", +] + [[package]] name = "num" version = "0.4.3" @@ -4711,6 +4776,7 @@ version = "1.0.150" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e8014e44b4736ed0538adeecded0fce2a272f22dc9578a7eb6b2d9993c74cfb9" dependencies = [ + "indexmap", "itoa", "memchr", "serde", @@ -4808,6 +4874,15 @@ dependencies = [ "keccak", ] +[[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + [[package]] name = "shlex" version = "1.3.0" @@ -5049,6 +5124,12 @@ version = "2.6.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "13c2bddecc57b384dee18652358fb23172facb8a2c51ccc10d74c157bdea3292" +[[package]] +name = "symlink" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a7973cce6668464ea31f176d85b13c7ab3bba2cb3b77a2ed26abd7801688010a" + [[package]] name = "syn" version = "2.0.118" @@ -5186,6 +5267,15 @@ dependencies = [ "syn", ] +[[package]] +name = "thread_local" +version = "1.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1ad99c4c6d32803332c548b1af0540b357b3f5fc0be8f6c6bfe8b2e6ae784070" +dependencies = [ + "cfg-if", +] + [[package]] name = "threadpool" version = "1.8.1" @@ -5484,6 +5574,19 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-appender" +version = "0.2.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "050686193eb999b4bb3bc2acfa891a13da00f79734704c4b8b4ef1a10b368a3c" +dependencies = [ + "crossbeam-channel", + "symlink", + "thiserror 2.0.18", + "time", + "tracing-subscriber", +] + [[package]] name = "tracing-attributes" version = "0.1.31" @@ -5502,6 +5605,36 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "db97caf9d906fbde555dd62fa95ddba9eecfd14cb388e4f491a66d74cd5fb79a" dependencies = [ "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.23" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "cb7f578e5945fb242538965c2d0b04418d38ec25c79d160cd279bf0731c8d319" +dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex-automata", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", ] [[package]] @@ -5634,6 +5767,23 @@ version = "0.2.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "06abde3611657adf66d383f00b093d7faecc7fa57071cce2578660c9f1010821" +[[package]] +name = "uuid" +version = "1.24.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bf3923a6f5c4c6382e0b653c4117f48d631ea17f38ed86e2a828e6f7412f5239" +dependencies = [ + "getrandom 0.4.3", + "js-sys", + "wasm-bindgen", +] + +[[package]] +name = "valuable" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ba73ea9cf16a25df0c8caa16c51acb937d5712a8429db78a3ee29d5dcacd3a65" + [[package]] name = "vcpkg" version = "0.2.15" @@ -6603,8 +6753,38 @@ dependencies = [ "syn", ] +[[package]] +name = "zip" +version = "2.4.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "fabe6324e908f85a1c52063ce7aa26b68dcb7eb6dbc83a2d148403c9bc3eba50" +dependencies = [ + "arbitrary", + "crc32fast", + "crossbeam-utils", + "displaydoc", + "flate2", + "indexmap", + "memchr", + "thiserror 2.0.18", + "time", + "zopfli", +] + [[package]] name = "zmij" version = "1.0.21" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b8848ee67ecc8aedbaf3e4122217aff892639231befc6a1b58d29fff4c2cabaa" + +[[package]] +name = "zopfli" +version = "0.8.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f05cd8797d63865425ff89b5c4a48804f35ba0ce8d125800027ad6017d2b5249" +dependencies = [ + "bumpalo", + "crc32fast", + "log", + "simd-adler32", +] diff --git a/Cargo.toml b/Cargo.toml index 7b518ec..177e98c 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -31,7 +31,7 @@ edition = "2021" # the ROOT manifest (`[workspace.package].version`), so it MUST be set here for a # release to fire (§3.6). The library crates (dig-node-core/dig-runtime/dig-wallet) # keep their own independent versions — only the released binary tracks the workspace version. -version = "0.37.1" +version = "0.38.0" # Release hardening, matching digstore: keep integer-overflow checks ON in release. # The node parses untrusted serialized input and does offset/length arithmetic over diff --git a/DEVELOPMENT_LOG.md b/DEVELOPMENT_LOG.md index e1841b5..1415d3c 100644 --- a/DEVELOPMENT_LOG.md +++ b/DEVELOPMENT_LOG.md @@ -4,6 +4,24 @@ High-signal realizations from debugging/development: non-obvious cross-system co sharp edges, and gotchas. Concise durable facts with context — NOT a change diary. See `CLAUDE.md` §4.5 for the maintenance contract (a curator periodically re-verifies + prunes). +## The node emitted tracing into the void — no subscriber was ever installed (#553) + +`dig-node-core` and its P2P/TLS stack emit `tracing` events, but `dig-node-service` installed NO +`tracing-subscriber`, so every event was silently DROPPED and a Windows-service run (no console) +produced no log at all. The fix adopts the shared `dig-logging` crate at the SERVE entrypoints +(the foreground `run`/unix daemon in `entrypoint::block_on_serve`, and the Windows service body in +`win_service::run_service` — one-shot CLI commands deliberately do NOT install it). Sharp edges: + +- `tracing` has ONE global subscriber per process, and `dig_logging::LogGuard` is not `Clone` and + must be HELD for the process lifetime (dropping it flushes/detaches the file writer). So the guard + lives in a process-global `OnceLock` in `logging.rs` rather than threaded through `serve`'s + signature + every test caller — that also gives `control.log.setLevel` the reload handle for free. +- Per-request logging (`logging::log_rpc_dispatch`) takes ONLY the method name, never `params` — a + control/pairing body carries the control/paired token (dig-logging SPEC §7 never-log), so the + logger's signature makes leaking it impossible. A `tests/never_log.rs` capture test locks this in. +- Windows MAX_PATH: a deeply-nested worktree overflows 260 chars building `libz-sys`/cmake; set + `CARGO_TARGET_DIR` to a short path (e.g. `C:/t553`) to build/test from such a worktree. + ## Bare-git dependency version pins unify across the WHOLE dependency graph, not per-manifest (#494) A `git`-sourced Cargo dependency with NO `rev`/`branch`/`tag` is identified purely by its URL — diff --git a/SPEC.md b/SPEC.md index 52fb996..64cc843 100644 --- a/SPEC.md +++ b/SPEC.md @@ -993,6 +993,7 @@ lowercase 64-hex; a capsule reference is `storeId:rootHash`. Malformed refs yiel | `control.status` | — | `running`, `service`, `version`, `commit`, `protocol`, `uptime_secs`, `addr`, `upstream`, `cache`, `hosted_store_count`, `cached_capsule_count`, `pinned_store_count`, `sync.available` | | `control.config.get` | — | `addr`, `port`, `upstream`, `upstream_override`, `cache_dir`, `cache_shared`, `config_path`, `sync_available` | | `control.config.setUpstream` | `upstream` (URL string; blank clears) | `upstream` (normalized), `requires_restart: true` — persisted, effective on next start (§3.4) | +| `control.log.setLevel` | `filter` (an `EnvFilter` directive, e.g. `debug` or `info,dig_node_core=debug`) | `filter` (echoed) — live-applied via the `dig-logging` reload handle, effective immediately, NOT persisted (§11); `INVALID_PARAMS` on a missing/malformed directive, `CONTROL_ERROR` when logging is not installed in the process | | `control.cache.get` | — | `cap_bytes`, `used_bytes`, `dir`, `shared` | | `control.cache.setCap` | `cap_bytes` (number) | `cap_bytes` (floored at 64 MiB) | | `control.cache.clear` | — | `cleared: true` | @@ -1286,7 +1287,7 @@ write) is cancelled and reported as a failed kick, so it can never block the pas `run-service` (hidden; the Windows SCM entrypoint, §9.4; behaves as `run` off Windows) · `install` · `uninstall` · `start` · `stop` · `status` · `pair` (§7.11) · `open` (§8.5) · the **control-parity** subcommands `info` · `config` · `cache` · `stores` · `sync` · `updater` · -`subscriptions` (§8.6) · `peers` (§8.7). +`subscriptions` (§8.6) · `peers` (§8.7) · `logs` (§11). The `dign` alias binary (§2.1a) exposes this SAME subcommand set with the SAME semantics — `dign ` is equivalent to `dig-node ` in every respect except the reported program @@ -2714,3 +2715,66 @@ node-side in the interim: Exercising the connected pool end-to-end is gated on the network-genesis bring-up (the pre-launch placeholder genesis is rejected by `GossipService::start`); these behaviors are unit-tested independently of a live pool. + +## 20. Logging — structured JSONL file + human stderr (#553) + +The node adopts the shared `dig-logging` building block (`dig-logging` crate, `dig_ecosystem` #547), +so its sink layout, JSONL schema, log directory, rotation, level control, correlation ids, redaction, +and `logs` verbs are byte-identical to every other DIG service binary. `dig-logging`'s own `SPEC.md` +is the normative contract for those; this section records what dig-node MUST do. + +### 20.1. Where the subscriber is installed + +The node MUST install the `dig-logging` subscriber exactly once, at a SERVE entrypoint, and hold the +returned guard for the process lifetime: + +- the foreground `run` path and the unix daemon (`serve` via the CLI entrypoint) install it as run + context `service` when the process is an installed OS-service run, else `cli`; +- the Windows service body (`run-service`, §9.4) installs it as run context `service` immediately + after marking the process a service, BEFORE building the runtime — a Windows service has no + console, so the JSONL file is the only log. + +A one-shot CLI command (`status`, `pair`, `config`, …) does NOT install the subscriber: it neither +needs a rolling log file nor the maintenance thread. Installation is best-effort — a logging failure +(unwritable dir, subscriber already set) is reported on stderr and MUST NOT stop the node serving. + +The log directory follows `dig-logging` SPEC §3: the machine root `<…>/DigNetwork/logs/dig-node` +(`C:\ProgramData\DigNetwork\logs\dig-node`, `/Library/Logs/DigNetwork/dig-node`, +`/var/log/dig/dig-node`) for a service run, the per-user dev-fallback for an unprivileged `dig-node +run`, and `DIG_LOG_DIR` overrides both — mirroring the #501 daemon/CLI state-dir split. + +### 20.2. Levels — used by MEANING + +Events are emitted at the level that matches their operational meaning, not uniformly: `error!` +(operation failed / broken invariant), `warn!` (recoverable, degraded, or a fallback taken — a +listener that failed to bind non-fatally, a TLS/plaintext downgrade, a control-token persist +falling back to an in-memory token), `info!` (sparse operator lifecycle — the node listening with +its bound addresses + upstream, a listener up, leaf renewed, shutting down), `debug!` (developer +diagnosis — per-request RPC dispatch, a per-tick self-heal pass, a config-disabled surface), +`trace!` (firehose). The default filter is `dig-logging`'s noise-trimmed `info`. + +### 20.3. `control.log.setLevel` — runtime level control + +`control.log.setLevel` (§7.4) live-swaps the process level filter via the `dig-logging` reload +handle (`dig-logging` SPEC §5). It is a gated `control.*` method (loopback + control-token or paired +token, §7.2), takes `params.filter` (an `EnvFilter` directive), applies immediately, and does NOT +persist. A missing/malformed directive is `INVALID_PARAMS`; a process without logging installed is +`CONTROL_ERROR`. + +### 20.4. `dig-node logs …` verbs + +The node mounts `dig-logging`'s shared subcommand verbatim as `dig-node logs …` (also `dign logs +…`), so `logs path`, `logs tail [-f] [-n N] [--level L] [--json]`, `logs level []`, and +`logs bundle [-o out.zip] [--all] [--since ]` behave identically to every DIG binary +(`dig-logging` SPEC §8.1). `logs level ` PERSISTS the directive (effective on the next node +start) AND additionally live-applies it to a running node via `control.log.setLevel` (best-effort — +a node that is not running leaves the persisted level in place and reports it, never an error). `logs +bundle` writes a redacted zip safe to attach to a bug report (`dig-logging` SPEC §8.2). + +### 20.5. Never-log at source (SPEC §7 of dig-logging) + +No secret — a BIP39 mnemonic/seed, a wallet private key, the control token, a paired/session token, +a passphrase — is EVER passed to a `tracing` field or message, at any level. Bundle-time redaction +is only the second line of defence. The transport's per-request logging records ONLY the method name +and a correlation `op_id`, never the request `params` (which for a control/pairing call carry a +token); this is enforced by the request-logger's signature and a never-log regression test. diff --git a/crates/dig-node-service/Cargo.toml b/crates/dig-node-service/Cargo.toml index c1f9e5d..3740249 100644 --- a/crates/dig-node-service/Cargo.toml +++ b/crates/dig-node-service/Cargo.toml @@ -93,6 +93,20 @@ tower-http = { version = "0.6", features = ["cors"] } serde = { version = "1", features = ["derive"] } serde_json = "1" +# Structured logging. The node's engine library (`dig_node_core`) and its transitive +# P2P/TLS stack emit `tracing` events; WITHOUT a subscriber installed here every one is +# silently dropped and a Windows-service run leaves no log at all. `dig-logging` is the +# shared building block (#547) that installs the dual sink — a rolling JSONL file (per-OS +# machine log dir) + human stderr — behind one reloadable level filter, and ships the +# reusable `logs` CLI verbs + the bundle-time redaction engine. Every DIG service binary +# gets logging from HERE rather than hand-rolling a subscriber. Sourced from crates.io (no +# git/path dep) per the ecosystem crates.io policy (#681). +dig-logging = "0.1" +# The logging facade the shell emits through. dig-node-core already depends on `tracing`; +# the service shell now emits its own bring-up/lifecycle events through it, captured by the +# `dig-logging` subscriber installed at the serve entrypoints. +tracing = "0.1" + # CLI + OS-service registration. clap = { version = "4", features = ["derive"] } # Cross-platform service manager: Windows SCM, Linux systemd, macOS launchd behind @@ -146,6 +160,10 @@ windows-sys = { version = "0.61", features = [ # over the wire and reads real frames, mirroring how `tests/server.rs` already # exercises the HTTP surface with `reqwest` end-to-end rather than in-process. [dev-dependencies] +# Capturing subscriber for the never-log regression tests (#553 SPEC §7): a `fmt` layer writing +# into an in-memory buffer so a test can assert emitted records never contain secret values. +# Pinned to the SAME 0.3 line `dig-logging` builds on, so exactly one `tracing-subscriber` resolves. +tracing-subscriber = { version = "0.3", features = ["env-filter"] } # `test-util` unlocks tokio's paused-clock test controls (`#[tokio::test(start_paused = true)]`, # `tokio::time::advance`) so the self-heal per-child timeout (#693) and the TLS leaf-renewal # missed-tick behaviour (#660) are tested deterministically without real waits. diff --git a/crates/dig-node-service/src/control.rs b/crates/dig-node-service/src/control.rs index b85e983..7045a3f 100644 --- a/crates/dig-node-service/src/control.rs +++ b/crates/dig-node-service/src/control.rs @@ -92,6 +92,7 @@ pub const CONTROL_METHODS: &[&str] = &[ "control.status", "control.config.get", "control.config.setUpstream", + "control.log.setLevel", "control.cache.get", "control.cache.setCap", "control.cache.clear", @@ -605,6 +606,7 @@ pub async fn dispatch_control(ctx: &ControlCtx, id: Value, method: &str, params: "control.status" => control_ok(id, status(ctx).await), "control.config.get" => control_ok(id, config_get(ctx)), "control.config.setUpstream" => config_set_upstream(ctx, id, params), + "control.log.setLevel" => log_set_level(id, params), "control.cache.get" => control_ok(id, cache_get()), "control.cache.setCap" => cache_set_cap(id, params), "control.cache.clear" => { @@ -725,6 +727,30 @@ fn cache_get() -> Value { } /// Set the cache cap (bytes, floored at 64 MiB by dig-node). +/// `control.log.setLevel` (#553): live-swap the running node's `tracing` level filter via the +/// `dig-logging` reload handle (SPEC §5). The filter is a standard `EnvFilter` directive, e.g. +/// `debug` or `info,dig_node_core=debug`. This takes effect immediately WITHOUT persisting — the +/// operator persists a level across restarts with `dig-node logs level `. Fails with +/// `InvalidParams` on a missing/invalid directive and `ControlError` when logging is not installed +/// in this process (never a serving node). +fn log_set_level(id: Value, params: &Value) -> Value { + let Some(filter) = params.get("filter").and_then(|v| v.as_str()) else { + return control_error( + id, + ErrorCode::InvalidParams, + "control.log.setLevel requires params.filter (an EnvFilter directive string)", + ); + }; + match crate::logging::set_level(filter) { + Ok(()) => control_ok(id, json!({ "filter": filter })), + Err(e) => control_error( + id, + ErrorCode::ControlError, + format!("failed to set level: {e}"), + ), + } +} + fn cache_set_cap(id: Value, params: &Value) -> Value { let Some(cap) = params.get("cap_bytes").and_then(|v| v.as_u64()) else { return control_error( @@ -1071,6 +1097,26 @@ mod tests { assert!(is_authorized("control.status", Some("secret"), "secret")); } + #[test] + fn log_set_level_rejects_a_missing_filter_param() { + // #553: `control.log.setLevel` needs `params.filter`; an empty body is an InvalidParams + // error, never a silent no-op. + let resp = log_set_level(json!(1), &json!({})); + assert_eq!( + resp["error"]["code"], + json!(ErrorCode::InvalidParams.code()) + ); + } + + #[test] + fn log_set_level_errors_when_logging_is_not_installed() { + // #553: in a plain `cargo test` process no serve path installed the logging guard, so a + // live level change reports a ControlError (rather than pretending it applied). A valid + // directive still parses — the failure is specifically "logging not initialised". + let resp = log_set_level(json!(1), &json!({ "filter": "debug" })); + assert_eq!(resp["error"]["code"], json!(ErrorCode::ControlError.code())); + } + #[test] fn ct_eq_matches_string_equality_but_constant_time() { assert!(ct_eq("abc", "abc")); diff --git a/crates/dig-node-service/src/control_cli.rs b/crates/dig-node-service/src/control_cli.rs index bd225ff..ec74264 100644 --- a/crates/dig-node-service/src/control_cli.rs +++ b/crates/dig-node-service/src/control_cli.rs @@ -178,6 +178,8 @@ pub fn cli_covered_control_methods() -> Vec<&'static str> { store_id: String::new(), } .method(), + // `dig-node logs level ` drives the live level change (#553). + "control.log.setLevel", // `dig-node peers` drives the live peer status (#559). "control.peerStatus", // `dig-node pair …` drives the pairing-admin methods (#280). diff --git a/crates/dig-node-service/src/entrypoint.rs b/crates/dig-node-service/src/entrypoint.rs index 764bb5d..1629ef1 100644 --- a/crates/dig-node-service/src/entrypoint.rs +++ b/crates/dig-node-service/src/entrypoint.rs @@ -350,7 +350,18 @@ pub fn run() -> std::process::ExitCode { // leak. (`bin_name` takes `Into`, so it takes the owned value directly.) let bin = invoked_bin_name(); let bin_static: &'static str = Box::leak(bin.clone().into_boxed_str()); - let matches = Cli::command().name(bin_static).bin_name(bin).get_matches(); + // Mount the shared `logs` verb set (#553) beside the derived subcommands so + // `dig-node logs path|tail|level|bundle` behaves identically to every other DIG service + // binary. It is not part of the derived `Cli` enum, so we intercept it from the raw + // matches BEFORE `from_arg_matches` (which would reject the unknown subcommand). + let matches = Cli::command() + .name(bin_static) + .bin_name(bin) + .subcommand(dig_logging::logs::command()) + .get_matches(); + if let Some(("logs", logs_matches)) = matches.subcommand() { + return run_logs(logs_matches); + } let cli = match Cli::from_arg_matches(&matches) { Ok(c) => c, Err(e) => e.exit(), @@ -564,9 +575,50 @@ fn hint_for(exit: ExitCode) -> Option<&'static str> { } } +/// Run the shared `logs` verb set (#553): `dig-node logs path|tail|level|bundle`. The verbs +/// operate on the on-disk log files (SPEC §8.1); `logs level ` PERSISTS the level (it +/// takes effect on the next node start) and ADDITIONALLY live-applies it to a running node via +/// `control.log.setLevel` (best-effort — a not-running node is not an error for the persist). +fn run_logs(matches: &clap::ArgMatches) -> std::process::ExitCode { + let service = crate::logging::service(crate::logging::run_context()); + if let Err(e) = dig_logging::logs::run(&service, matches) { + eprintln!("error: {e}"); + return std::process::ExitCode::from(ExitCode::IoError.code()); + } + live_apply_level(matches); + std::process::ExitCode::from(ExitCode::Ok.code()) +} + +/// After `logs level ` persisted the directive, push it to a RUNNING node so the change +/// takes effect immediately rather than only on the next start (SPEC §5 runtime reload). Purely +/// best-effort: a node that is not running (or rejects the directive) leaves the persisted level +/// in place and prints an informational note — never a failure, since the persist already +/// succeeded. +fn live_apply_level(logs_matches: &clap::ArgMatches) { + let Some(("level", level_matches)) = logs_matches.subcommand() else { + return; + }; + let Some(filter) = level_matches.get_one::("filter") else { + return; // `logs level` with no argument only READS the level; nothing to apply. + }; + let config = Config::from_env(); + let params = serde_json::json!({ "filter": filter }); + match crate::control_client::call_control(&config, "control.log.setLevel", params) { + Ok(_) => eprintln!("applied to the running node (effective now)"), + Err(_) => eprintln!("(the running node was not reachable; level applies on next start)"), + } +} + /// Build the multi-threaded tokio runtime and serve. Kept here (not in [`crate::server`]) /// so the lib's `serve` stays a plain async fn callers can drive on their own runtime. +/// +/// Installs the structured-logging stack (#553) FIRST so the bring-up narration + every +/// `dig_node_core` event lands in the rolling JSONL file + stderr for the whole serve +/// lifetime. The run context (machine vs dev-fallback log dir) mirrors the #501 daemon/CLI +/// split — an installed service logs to the machine dir, a bare `dig-node run` to the per-user +/// dev dir. fn block_on_serve(config: Config) -> std::io::Result<()> { + crate::logging::init(crate::logging::run_context()); let rt = tokio::runtime::Builder::new_multi_thread() .enable_all() .build()?; diff --git a/crates/dig-node-service/src/lib.rs b/crates/dig-node-service/src/lib.rs index 4da2fb8..6d8852a 100644 --- a/crates/dig-node-service/src/lib.rs +++ b/crates/dig-node-service/src/lib.rs @@ -52,6 +52,10 @@ pub mod entrypoint; /// `dig-node ensure-hosts` (#91/#503): idempotently register the `dig.local` → `127.0.0.2` OS /// hosts entry so `http://dig.local` resolves to the node. Invoked by the native install packages. pub mod hosts; +/// Structured logging (#553): install the shared [`dig_logging`] dual sink (rolling JSONL +/// file + human stderr) at the serve entrypoints and expose the runtime level-reload handle +/// the `control.log.setLevel` method + `logs level` verb drive. See [`logging`]. +pub mod logging; pub mod meta; /// `dig-node open ` (#389): the OS scheme-handler target the /// installer registers for `chia://` + `urn:dig:chia:`. Strictly validates the untrusted diff --git a/crates/dig-node-service/src/logging.rs b/crates/dig-node-service/src/logging.rs new file mode 100644 index 0000000..3a938e9 --- /dev/null +++ b/crates/dig-node-service/src/logging.rs @@ -0,0 +1,128 @@ +//! Structured logging for the `dig-node` binary (#553), built on the shared +//! [`dig_logging`] building block (#547). +//! +//! Before this module the node's engine library ([`dig_node_core`]) and its P2P/TLS stack +//! emitted `tracing` events into the void: no subscriber was ever installed, so every event +//! was silently dropped and a Windows-service run produced no log at all. [`init`] installs +//! the shared dual sink — a rolling daily JSONL file in the per-OS machine log dir plus +//! compact human text on stderr — behind one reloadable level filter, so the node is +//! debuggable in the field. +//! +//! ## One process-wide guard +//! +//! `tracing` has exactly ONE global subscriber per process, so the log guard is a +//! process-global too: [`init`] stores the returned [`dig_logging::LogGuard`] in a +//! [`OnceLock`] that lives for the process lifetime (dropping the guard would flush + detach +//! the file writer). Keeping it here — rather than threading it through `serve`'s signature +//! and every test caller — mirrors the global nature of the subscriber and lets the control +//! plane reach the reload handle ([`set_level`]) without plumbing. +//! +//! ## Where it is initialised +//! +//! Only the SERVE entrypoints call [`init`] (the foreground `run`, the unix daemon, and the +//! Windows service body) — a one-shot CLI command like `status` or `pair` neither needs a +//! rolling log file nor should spawn the maintenance thread. The [`dig_logging::RunContext`] +//! distinguishes an installed-service run (machine log dir) from an interactive `dig-node +//! run` (per-user dev-fallback dir); the crate resolves the actual directory (SPEC §3). + +use std::sync::OnceLock; + +use dig_logging::{LogGuard, RunContext, Service}; + +use crate::meta::{SERVICE_NAME, VERSION}; + +/// The process-global log guard. Set once by [`init`]; holding it here keeps the file writer +/// alive for the process lifetime and gives [`set_level`] the reload handle. +static GUARD: OnceLock = OnceLock::new(); + +/// The [`Service`] identity every `dig-logging` call for this binary uses. `run_context` is a +/// label on each record (and the dev-vs-machine dir hint); the resolved directory itself +/// depends only on `name` + privilege, so the `logs` verbs (which pass [`RunContext::Cli`]) +/// resolve the SAME directory the running service writes to (SPEC §3). +pub fn service(run_context: RunContext) -> Service { + Service { + name: SERVICE_NAME, + version: VERSION, + run_context, + } +} + +/// The run context this process is in: an installed OS-service run logs as +/// [`RunContext::Service`] (machine log dir), a bare `dig-node run` / dev invocation as +/// [`RunContext::Cli`] (per-user dev-fallback dir). Mirrors the #501 daemon/CLI state-dir +/// split so logs land beside the state the same run resolves. +pub fn run_context() -> RunContext { + if crate::state::running_as_service() { + RunContext::Service + } else { + RunContext::Cli + } +} + +/// Install the shared logging stack for a SERVE run (SPEC §1) and hold the guard for the +/// process lifetime. Idempotent + best-effort: a second call (e.g. a test that serves twice +/// in one process) is a silent no-op, and a failure to install — the log dir is unwritable, +/// or a subscriber is already set — is reported on stderr and swallowed, because a logging +/// problem must NEVER stop the node from serving. +pub fn init(run_context: RunContext) { + if GUARD.get().is_some() { + return; + } + match dig_logging::init(service(run_context)) { + Ok(guard) => { + // A `set` race (two serve paths initialising at once) is benign: the first guard + // wins and stays live; a losing guard is dropped, which only detaches a writer + // that was never wired into the global subscriber. + let _ = GUARD.set(guard); + } + Err(e) => { + eprintln!( + "dig-node: WARN could not install structured logging ({e}); \ + continuing without a log file" + ); + } + } +} + +/// Record one JSON-RPC dispatch for per-request diagnosis (SPEC §6), at `DEBUG` so it stays off +/// the default `INFO` operator view. A fresh `op_id` correlates every log line emitted while +/// serving this request. +/// +/// The signature is the never-log guarantee (SPEC §7): it takes ONLY the method NAME, never the +/// request `params`, so a control/pairing body — which carries the control token or a paired +/// token — is structurally unable to reach a log field through the request path. This is the ONE +/// place the transport logs an incoming request. +pub fn log_rpc_dispatch(method: &str) { + tracing::debug!(op_id = %dig_logging::new_run_id(), rpc.method = %method, "rpc dispatch"); +} + +/// Live-swap the global level filter (SPEC §5 runtime reload) — the engine behind +/// `control.log.setLevel` and `dig-node logs level ` against a running node. Returns +/// a human error string when logging was never initialised (this process is not a serving +/// node) or the directive is not a valid `EnvFilter` (e.g. `info,dig_node_core=debug`). +pub fn set_level(directive: &str) -> Result<(), String> { + let guard = GUARD + .get() + .ok_or("logging is not initialised in this process")?; + guard.set_filter(directive).map_err(|e| e.to_string()) +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn service_identity_is_the_canonical_node_name() { + let svc = service(RunContext::Cli); + assert_eq!(svc.name, "dig-node"); + assert_eq!(svc.version, VERSION); + } + + #[test] + fn set_level_errors_before_init() { + // In a plain `cargo test` process no serve path ran, so the guard is unset and a level + // change reports the actionable reason rather than panicking. (This also documents that + // `control.log.setLevel` on a non-serving process fails cleanly.) + assert!(set_level("debug").is_err()); + } +} diff --git a/crates/dig-node-service/src/self_heal.rs b/crates/dig-node-service/src/self_heal.rs index 6acf3b8..5bb24f3 100644 --- a/crates/dig-node-service/src/self_heal.rs +++ b/crates/dig-node-service/src/self_heal.rs @@ -239,10 +239,12 @@ pub async fn reconcile_ext_forcelist() -> KickOutcome { /// Run one self-heal pass: re-arm the beacon schedule, then reconcile the ext-forcelist. Both are /// best-effort and independent — one failing never blocks the other. pub async fn run_once() { + // A per-tick maintenance pass: routine + frequent, so it is DEBUG (developer diagnosis of what + // the self-heal driver did this cycle), not operator-level INFO narrative. let rearm = rearm_beacon_schedule().await; - eprintln!("dig-node: self-heal beacon re-arm: {rearm:?}"); + tracing::debug!(outcome = ?rearm, "self-heal: beacon schedule re-arm"); let reconcile = reconcile_ext_forcelist().await; - eprintln!("dig-node: self-heal ext-forcelist reconcile: {reconcile:?}"); + tracing::debug!(outcome = ?reconcile, "self-heal: ext-forcelist reconcile"); } /// Spawn the always-on self-heal driver as a detached task: one pass immediately, then a pass every diff --git a/crates/dig-node-service/src/server.rs b/crates/dig-node-service/src/server.rs index 461988c..e74c353 100644 --- a/crates/dig-node-service/src/server.rs +++ b/crates/dig-node-service/src/server.rs @@ -321,19 +321,21 @@ fn resolve_state_dir_and_token() -> (std::path::PathBuf, String) { match control::load_or_create_token_at(&dir.join(control::CONTROL_TOKEN_FILE)) { Ok(token) => (dir, token), Err(e) => { - eprintln!( - "dig-node: WARN could not persist the control token in the secured \ - state dir ({e}); using an in-memory token (control.* unauthorizable)" + tracing::warn!( + error = %e, + "could not persist the control token in the secured state dir; using \ + an in-memory token (control.* unauthorizable)" ); ephemeral() } } } Err(e) => { - eprintln!( - "dig-node: WARN could not secure the machine state dir ({e}); refusing to \ - serve the control plane from it — {}", - control::control_token_remedy() + tracing::warn!( + error = %e, + remedy = %control::control_token_remedy(), + "could not secure the machine state dir; refusing to serve the control plane \ + from it" ); ephemeral() } @@ -343,9 +345,10 @@ fn resolve_state_dir_and_token() -> (std::path::PathBuf, String) { match control::load_or_create_token() { Ok(token) => (dir, token), Err(e) => { - eprintln!( - "dig-node: WARN could not persist control token ({e}); using an in-memory \ - token (control.* will be unauthorizable until the state dir is writable)" + tracing::warn!( + error = %e, + "could not persist control token; using an in-memory token (control.* will be \ + unauthorizable until the state dir is writable)" ); ephemeral() } @@ -635,6 +638,12 @@ async fn rpc( .unwrap_or("") .to_string(); + // Per-request diagnostics (SPEC §6). Routed through a helper that takes ONLY the method name + // so the request body — which for a control/pairing call carries tokens (§7 never-log) — is + // structurally unable to reach a log field. DEBUG keeps the per-request trail off the default + // INFO operator view. + crate::logging::log_rpc_dispatch(&method); + // `rpc.discover` is answered by the shell itself (the standard OpenRPC // method-discovery method): return the OpenRPC document so an agent can // introspect the whole surface over the wire with no out-of-band knowledge. @@ -1414,17 +1423,19 @@ where let cert = wallet_cert.clone(); tokio::spawn(async move { if let Err(e) = serve_mtls(backend, l, &cert).await { - eprintln!("dig-node: WARN wallet mTLS listener exited: {e}"); + tracing::warn!(error = %e, "wallet mTLS listener exited"); } }); - eprintln!( - "dig-node: wallet mTLS (Sage-parity) listening on 127.0.0.1:{DEFAULT_MTLS_PORT}" + tracing::info!( + addr = %format!("127.0.0.1:{DEFAULT_MTLS_PORT}"), + "wallet mTLS (Sage-parity) listening" ); } - Err(e) => eprintln!( - "dig-node: WARN could not bind 127.0.0.1:{DEFAULT_MTLS_PORT} for the wallet mTLS \ - listener ({e}); node-class Sage-parity clients unavailable (non-fatal). The wallet \ - is still served on the loopback HTTP surface + /ws." + Err(e) => tracing::warn!( + error = %e, + addr = %format!("127.0.0.1:{DEFAULT_MTLS_PORT}"), + "could not bind the wallet mTLS listener; node-class Sage-parity clients unavailable \ + (non-fatal). The wallet is still served on the loopback HTTP surface + /ws" ), } @@ -1458,7 +1469,7 @@ where let dig_local = match config.dig_local_addr() { Some(dl_addr) => match tokio::net::TcpListener::bind(&dl_addr).await { Ok(l) => { - eprintln!("dig-node: bare http://dig.local enabled (listening on {dl_addr})"); + tracing::info!(addr = %dl_addr, "bare http://dig.local enabled"); Some((dl_addr, l)) } Err(e) => { @@ -1467,7 +1478,9 @@ where } }, None => { - eprintln!("dig-node: bare http://dig.local listener disabled (DIG_NODE_DIGLOCAL=0)"); + // A deliberately-disabled surface (DIG_NODE_DIGLOCAL=0) — a developer-diagnosis detail, + // not operator narrative, so DEBUG. + tracing::debug!("bare http://dig.local listener disabled (DIG_NODE_DIGLOCAL=0)"); None } }; @@ -1483,12 +1496,12 @@ where if dig_local.is_some() { bound_addrs.push("http://dig.local (no port)".to_string()); } - eprintln!( - "dig-node v{VERSION} (local-node) listening on: {}\n \ - upstream: {}\n \ - Point the DIG Chrome extension's \"server host\" at {addr}.", - bound_addrs.join(", "), - config.upstream + tracing::info!( + version = VERSION, + addrs = %bound_addrs.join(", "), + upstream = %config.upstream, + extension_host = %addr, + "dig-node (local-node) listening" ); // A single shutdown signal fanned out to every listener: when it fires, all @@ -1546,11 +1559,12 @@ where /// impossible: IPv6 disabled at the kernel/network-stack level, or a sandboxed/ /// restricted environment without it. fn warn_ipv6_bind_failed(v6_addr: &str, e: &std::io::Error) { - eprintln!( - "dig-node: WARN could not bind {v6_addr} for the IPv6 loopback listener ({e}); \ - continuing IPv4-only on {v6_addr}'s sibling 127.0.0.1 address. This is non-fatal. \ - A client whose `localhost` resolves to `::1` first (e.g. Windows) may need to use \ - 127.0.0.1 explicitly until IPv6 loopback is available on this system." + tracing::warn!( + addr = %v6_addr, + error = %e, + "could not bind the IPv6 loopback listener; continuing IPv4-only on the sibling 127.0.0.1 \ + address (non-fatal). A client whose `localhost` resolves to `::1` first (e.g. Windows) may \ + need to use 127.0.0.1 explicitly until IPv6 loopback is available on this system" ); } @@ -1560,14 +1574,14 @@ fn warn_ipv6_bind_failed(v6_addr: &str, e: &std::io::Error) { /// `:80` is privileged on Linux (root / CAP_NET_BIND_SERVICE) and on macOS also /// needs the `127.0.0.2` loopback alias. fn warn_dig_local_bind_failed(dl_addr: &str, e: &std::io::Error) { - eprintln!( - "dig-node: WARN could not bind {dl_addr} for bare http://dig.local ({e}); \ - continuing with localhost-only (http only via the configured port). \ - This is non-fatal. Causes: the privileged port 80 needs elevation \ - (Linux: run as root or grant CAP_NET_BIND_SERVICE; the installed service \ - runs elevated), the port is already in use, or — on macOS — the 127.0.0.2 \ - loopback alias is missing (sudo ifconfig lo0 alias 127.0.0.2). \ - Set DIG_NODE_DIGLOCAL=0 to silence this and skip the attempt." + tracing::warn!( + addr = %dl_addr, + error = %e, + "could not bind bare http://dig.local; continuing with localhost-only (http via the \ + configured port). Non-fatal. Causes: privileged port 80 needs elevation (Linux: run as \ + root or grant CAP_NET_BIND_SERVICE; the installed service runs elevated), the port is in \ + use, or — on macOS — the 127.0.0.2 loopback alias is missing (sudo ifconfig lo0 alias \ + 127.0.0.2). Set DIG_NODE_DIGLOCAL=0 to silence this and skip the attempt" ); } @@ -1587,9 +1601,10 @@ fn bring_up_local_https(config: &Config, app: &Router, shutdown_notify: &Arc paths, Err(e) => { - eprintln!( - "dig-node: WARN cannot resolve the TLS material root ({e}); \ - https://dig.local disabled, serving plaintext only." + tracing::warn!( + error = %e, + "cannot resolve the TLS material root; https://dig.local disabled, serving \ + plaintext only" ); return; } @@ -1634,20 +1649,22 @@ fn spawn_https_listener( ) { match std::net::TcpListener::bind(addr) { Ok(listener) => { - eprintln!("dig-node: HTTPS (https://dig.local) listening on {addr}"); + tracing::info!(addr = %addr, "HTTPS (https://dig.local) listening"); let shutdown = shutdown_notify.clone(); let addr = addr.to_string(); tokio::spawn(async move { if let Err(e) = serve_https(listener, rustls_config, app, shutdown).await { - eprintln!("dig-node: WARN HTTPS listener on {addr} exited: {e}"); + tracing::warn!(addr = %addr, error = %e, "HTTPS listener exited"); } }); } - Err(e) => eprintln!( - "dig-node: WARN could not bind {addr} for https://dig.local ({e}); non-fatal — \ - plaintext keeps serving. `:443` is privileged (run elevated / grant \ - CAP_NET_BIND_SERVICE; the installed service runs elevated) and the 127.0.0.2 / ::1 \ - loopback address must exist (macOS: sudo ifconfig lo0 alias 127.0.0.2)." + Err(e) => tracing::warn!( + addr = %addr, + error = %e, + "could not bind https://dig.local; non-fatal — plaintext keeps serving. `:443` is \ + privileged (run elevated / grant CAP_NET_BIND_SERVICE; the installed service runs \ + elevated) and the 127.0.0.2 / ::1 loopback address must exist (macOS: sudo ifconfig \ + lo0 alias 127.0.0.2)" ), } } @@ -1700,7 +1717,7 @@ async fn shutdown_signal() { _ = ctrl_c => {} _ = terminate => {} } - eprintln!("dig-node: shutting down"); + tracing::info!("dig-node shutting down"); } #[cfg(test)] diff --git a/crates/dig-node-service/src/tls.rs b/crates/dig-node-service/src/tls.rs index 81173dc..a51e0ba 100644 --- a/crates/dig-node-service/src/tls.rs +++ b/crates/dig-node-service/src/tls.rs @@ -54,11 +54,11 @@ pub fn load_https_material(paths: TlsPaths) -> Option { // `ca.key`, and this service reads that key with privilege. Fail CLOSED to plaintext; the // installer (#623) provisions the root under a privileged owner. if !crate::security::dir_is_privileged(&paths.root) { - eprintln!( - "dig-node: WARN refusing HTTPS — the TLS root {} is not owned by a privileged \ - principal (SYSTEM/Administrators or root) or is user-writable; serving plaintext only. \ - The installer (#623) provisions this root under a privileged owner.", - paths.root.display() + tracing::warn!( + tls_root = %paths.root.display(), + "refusing HTTPS: TLS root is not privileged-owned (SYSTEM/Administrators or root) or is \ + user-writable; serving plaintext only. The installer (#623) provisions this root under \ + a privileged owner" ); return None; } @@ -72,10 +72,11 @@ fn load_leaf_material(paths: TlsPaths) -> Option { // Gate on BOTH files existing before touching rustls — the common "installer hasn't run // yet" case, reported as an informational line (not a warning), since it is expected. if !paths.leaf_cert().exists() || !paths.leaf_key().exists() { - eprintln!( - "dig-node: HTTPS (https://dig.local) unavailable — no TLS leaf under {} yet. \ - The installer provisions the per-machine CA + leaf (#623); serving plaintext only.", - paths.root.display() + // Expected on a machine the installer has not provisioned yet — INFO, not WARN. + tracing::info!( + tls_root = %paths.root.display(), + "https://dig.local unavailable: no TLS leaf yet. The installer provisions the \ + per-machine CA + leaf (#623); serving plaintext only" ); return None; } @@ -86,10 +87,11 @@ fn load_leaf_material(paths: TlsPaths) -> Option { paths, }), Err(e) => { - eprintln!( - "dig-node: WARN could not load the TLS leaf under {} ({e}); serving plaintext \ - only. HTTPS starts once a valid CA + leaf are present (#623).", - paths.root.display() + tracing::warn!( + tls_root = %paths.root.display(), + error = %e, + "could not load the TLS leaf; serving plaintext only. HTTPS starts once a valid \ + CA + leaf are present (#623)" ); None } @@ -142,27 +144,25 @@ async fn run_rotation_pass(manager: Arc, now: OffsetDateTime) { match tokio::task::spawn_blocking(move || manager.maintain(now)).await { Ok(Ok(report)) => { if report.leaf_renewed { - eprintln!( - "dig-node: TLS leaf for https://dig.local renewed and hot-reloaded \ - (attempts={})", - report.attempts + tracing::info!( + attempts = report.attempts, + "TLS leaf for https://dig.local renewed and hot-reloaded" ); } if report.ca_renewal_due { - eprintln!( - "dig-node: WARN the local CA is within its renewal window. CA rotation \ - is installer-coordinated (dig-cert rotate_ca) and re-installs trust — \ - the node does NOT auto-rotate the anchor." + tracing::warn!( + "the local CA is within its renewal window. CA rotation is \ + installer-coordinated (dig-cert rotate_ca) and re-installs trust — the node \ + does NOT auto-rotate the anchor" ); } } - Ok(Err(e)) => eprintln!( - "dig-node: WARN TLS leaf renewal pass failed ({e}); HTTPS keeps serving the \ - current leaf and the next pass retries." + Ok(Err(e)) => tracing::warn!( + error = %e, + "TLS leaf renewal pass failed; HTTPS keeps serving the current leaf and the next pass \ + retries" ), - Err(e) => { - eprintln!("dig-node: WARN TLS leaf renewal task did not complete ({e})") - } + Err(e) => tracing::warn!(error = %e, "TLS leaf renewal task did not complete"), } } diff --git a/crates/dig-node-service/src/win_service.rs b/crates/dig-node-service/src/win_service.rs index 24365a6..b80538e 100644 --- a/crates/dig-node-service/src/win_service.rs +++ b/crates/dig-node-service/src/win_service.rs @@ -47,8 +47,9 @@ define_windows_service!(ffi_service_main, service_main); /// startup leaves the SCM seeing a stopped service with a non-zero exit code). fn service_main(_args: Vec) { if let Err(e) = run_service() { - // Best-effort: nothing to log to, but the non-zero exit is reported below. - eprintln!("dig-node service error: {e}"); + // The service body installs structured logging early (#553), so a failure here is captured + // in the machine log file; the non-zero exit is still reported to the SCM below. + tracing::error!(error = %e, "dig-node service body exited with an error"); } } @@ -64,6 +65,12 @@ fn run_service() -> std::io::Result<()> { crate::state::RUN_CONTEXT_ENV, crate::state::RUN_CONTEXT_SERVICE, ); + + // Install structured logging (#553) NOW — a Windows service has no console, so before this the + // SCM-launched process produced NO log at all. The env above is already set, so this logs as a + // SERVICE run into the machine log dir. Best-effort: a logging failure never blocks the service. + crate::logging::init(dig_logging::RunContext::Service); + let config = Config::from_env(); // Channel the control handler signals on `Stop`; the server's graceful-shutdown diff --git a/crates/dig-node-service/tests/never_log.rs b/crates/dig-node-service/tests/never_log.rs new file mode 100644 index 0000000..c6cc0da --- /dev/null +++ b/crates/dig-node-service/tests/never_log.rs @@ -0,0 +1,115 @@ +//! Never-log regression tests (#553, dig-logging SPEC §7). +//! +//! The node's on-disk logs are operator-readable, so no secret may EVER reach a `tracing` field or +//! message at source (bundle-time redaction is only the second line of defence). The risk surface +//! is the control/pairing token path and the wallet seed path. These tests capture real emitted +//! records into an in-memory buffer and assert curated secret sentinels are absent, so a future +//! edit that logs a token/seed fails HERE. + +use std::io::Write; +use std::sync::{Arc, Mutex}; + +use tracing_subscriber::fmt::MakeWriter; + +/// A sentinel BIP39-style seed that must never surface in a log line. +const SENTINEL_MNEMONIC: &str = + "abandon abandon abandon abandon abandon abandon abandon abandon about test seed leak"; +/// A sentinel control/pairing token value that must never surface in a log line. +const SENTINEL_TOKEN: &str = "deadbeefcafef00d-control-token-sentinel-value"; + +/// An in-memory sink a `tracing_subscriber::fmt` layer writes formatted records into, so a test can +/// read back everything that was logged. +#[derive(Clone, Default)] +struct CaptureBuffer(Arc>>); + +impl CaptureBuffer { + fn contents(&self) -> String { + String::from_utf8_lossy(&self.0.lock().unwrap()).into_owned() + } +} + +impl Write for CaptureBuffer { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + self.0.lock().unwrap().extend_from_slice(buf); + Ok(buf.len()) + } + fn flush(&mut self) -> std::io::Result<()> { + Ok(()) + } +} + +impl<'a> MakeWriter<'a> for CaptureBuffer { + type Writer = CaptureBuffer; + fn make_writer(&'a self) -> Self::Writer { + self.clone() + } +} + +/// Run `body` with a scoped capturing subscriber at `TRACE` (so even the lowest-level events are +/// captured) and return everything it logged. +fn capture(body: impl FnOnce()) -> String { + let buffer = CaptureBuffer::default(); + let subscriber = tracing_subscriber::fmt() + .with_max_level(tracing::Level::TRACE) + .with_writer(buffer.clone()) + .finish(); + tracing::subscriber::with_default(subscriber, body); + buffer.contents() +} + +/// The request-logging path records the METHOD and an op_id — and, by construction, nothing else. +/// Its signature takes only the method name, so a control body's token can never reach it; this +/// test pins that guarantee by logging a control method while the token sentinel is in scope and +/// asserting the sentinel never appears. +#[test] +fn rpc_dispatch_logging_records_method_but_never_the_request_token() { + let logged = capture(|| { + // The token a real caller would carry alongside `control.config.setUpstream`; it must NOT + // be handed to the request logger, and the logger's signature makes that impossible. + let _presented_token = SENTINEL_TOKEN; + dig_node_service::logging::log_rpc_dispatch("control.config.setUpstream"); + }); + + assert!( + logged.contains("control.config.setUpstream"), + "the method name is the useful diagnostic and must be logged: {logged}" + ); + assert!( + logged.contains("rpc dispatch"), + "the dispatch event should be emitted: {logged}" + ); + assert!( + !logged.contains(SENTINEL_TOKEN), + "a control token must NEVER reach a log record (SPEC §7): {logged}" + ); +} + +/// Broad guard: even when secret sentinels are live in the surrounding scope, none of the crate's +/// own emitted records may contain them. Emitting a representative operator event proves the +/// capture harness sees output, and the assertions prove the sentinels are absent from it. +#[test] +fn emitted_records_never_contain_seed_or_token_sentinels() { + let logged = capture(|| { + let _seed = SENTINEL_MNEMONIC; + let _token = SENTINEL_TOKEN; + // A representative lifecycle event (the shape of the real bring-up narration): public, + // non-secret fields only. + tracing::info!( + addr = "127.0.0.1:9778", + upstream = "https://rpc.dig.net", + "listening" + ); + dig_node_service::logging::log_rpc_dispatch("dig.getContent"); + }); + + assert!( + !logged.is_empty(), + "the capture harness must see emitted output" + ); + for sentinel in [SENTINEL_MNEMONIC, SENTINEL_TOKEN] { + assert!( + !logged.contains(sentinel), + "a secret sentinel leaked into a log record (SPEC §7): {logged}" + ); + } +}