diff --git a/zcash_local_net/src/container.rs b/zcash_local_net/src/container.rs index c0fd5e5..e848b93 100644 --- a/zcash_local_net/src/container.rs +++ b/zcash_local_net/src/container.rs @@ -234,11 +234,19 @@ impl ArtifactSource { /// caller appends the binary's own arguments afterwards, identical /// in both modes. pub(crate) fn command(&self, spec: &LaunchSpec<'_>) -> Command { - match self { + let mut command = match self { Self::HostProcess { binary: None } => pick_command(spec.executable_name, false), Self::HostProcess { binary: Some(path) } => Command::new(path), - Self::Container(image) => container_run_command(image, spec), + Self::Container(image) => return container_run_command(image, spec), + }; + // Container mode returned above: its env rides as `--env` run + // flags. Host mode pins the env on the child directly. Either + // way the spec's env overrides the harness's own ambient + // values for those names, by design. + for (name, value) in spec.env { + command.env(name, value); } + command } } @@ -260,17 +268,59 @@ pub(crate) struct LaunchSpec<'a> { /// (the wallet's `init` receives its mnemonic on stdin). Ignored /// in host mode — a host `Command` pipes stdin without ceremony. pub interactive: bool, + /// Environment pinned on the child in both modes (host: set on the + /// `Command`; container: `--env` run flags). Entries OVERRIDE the + /// harness's own ambient environment for those names — this is the + /// mechanism by which a launcher owns a child's env instead of + /// letting ambient values leak through (see the zainod logging + /// contract in `indexer::zainod`). + pub env: &'a [(&'static str, &'a str)], } impl<'a> LaunchSpec<'a> { - /// A spec with no mounts, no name, and no stdin — version traces - /// and other one-shot probes. + /// A spec with no mounts, no name, no stdin, and no pinned env — + /// version traces and other one-shot probes. pub(crate) fn bare(executable_name: &'static str) -> Self { Self { executable_name, container_name: None, mounts: &[], interactive: false, + env: &[], + } + } + + /// The daemon shape shared by every long-running launcher: named + /// container when containerized (so `stop` can force-remove it), + /// non-interactive, with the caller's mounts and pinned env. + pub(crate) fn daemon( + executable_name: &'static str, + container: Option<&'a ContainerInstance>, + mounts: &'a [&'a Path], + env: &'a [(&'static str, &'a str)], + ) -> Self { + Self { + executable_name, + container_name: container.map(|c| c.name()), + mounts, + interactive: false, + env, + } + } + + /// The one-shot (wallet-op) shape: unnamed `--rm` container, + /// interactive when stdin will be piped, no pinned env. + pub(crate) fn one_shot( + executable_name: &'static str, + mounts: &'a [&'a Path], + interactive: bool, + ) -> Self { + Self { + executable_name, + container_name: None, + mounts, + interactive, + env: &[], } } } @@ -297,6 +347,9 @@ fn container_run_command(image: &ContainerImage, spec: &LaunchSpec<'_>) -> Comma if spec.interactive { command.arg("--interactive"); } + for (name, value) in spec.env { + command.arg("--env").arg(format!("{name}={value}")); + } command .arg("--entrypoint") .arg(image.entrypoint.as_deref().unwrap_or(spec.executable_name)); @@ -463,6 +516,7 @@ mod tests { container_name: Some("zcash-local-net-zebrad-1-0"), mounts, interactive: false, + env: &[("RUST_LOG", "info")], }); assert_eq!(command.get_program(), "docker"); @@ -482,6 +536,8 @@ mod tests { } expected.extend( [ + "--env", + "RUST_LOG=info", "--entrypoint", "zebrad", "--volume", @@ -510,6 +566,7 @@ mod tests { container_name: None, mounts, interactive: true, + env: &[], }); let args = rendered_args(&command); diff --git a/zcash_local_net/src/error.rs b/zcash_local_net/src/error.rs index e8581e2..55e8e27 100644 --- a/zcash_local_net/src/error.rs +++ b/zcash_local_net/src/error.rs @@ -84,6 +84,35 @@ pub enum LaunchError { /// Captured stdout at the time discovery gave up. stdout: String, }, + /// `launch::wait`'s indicator scan saw neither a success nor an + /// error indicator within the readiness budget. Before this + /// variant the scan looped forever, so a child whose logging was + /// silenced hung the launch unboundedly (the launch indicators are + /// log lines) — the zingolib#2488 failure shape. The message names + /// the silenced-logging suspect because an empty log from a live + /// process is exactly what a starved log filter looks like. + #[error( + "{process_name} produced neither a success nor an error indicator within {waited_secs}s.\n\ + Expected one of: {success_indicators}.\n\ + An empty log from a live process usually means the child's logging was silenced — \ + the harness pins the child's logging env at spawn; check that recent changes kept \ + that pin intact.\nStdout: {stdout}\nStderr: {stderr}\nAdditional log: {additional_log:?}" + )] + ReadinessTimeout { + /// Process name + process_name: String, + /// How long the scan waited before giving up + waited_secs: u64, + /// The success indicators the scan was looking for, rendered + /// for the message. + success_indicators: String, + /// Captured stdout up to the timeout + stdout: String, + /// Captured stderr up to the timeout + stderr: String, + /// Additional log content if `launch::wait` was reading one. + additional_log: Option, + }, /// RPC endpoint did not respond within the readiness budget #[error( "{process_name} RPC endpoint at {address} did not respond within {timeout:?}: {last_error}" @@ -246,6 +275,29 @@ pub enum IndexerSyncError { /// diagnosing why it stalled. log_tail: String, }, + /// The convergence wait timed out over a log carrying no sync + /// marker at all — not a lagging indexer but a starved observation + /// channel. The launcher pins the child's `RUST_LOG` precisely so + /// this cannot happen (zingolib#2488); a markerless log therefore + /// means the pin was defeated or the zainod log contract moved, + /// and the error names that diagnosis instead of presenting as an + /// anonymous timeout. + #[error( + "the indexer log contains no sync markers at all after {waited_secs}s waiting for \ + height {target}. zainod emits the markers at info level from the `zaino_state` \ + target, and the harness pins the child's RUST_LOG at spawn (debug values ride \ + `ZLN_ZAINOD_RUST_LOG`, which keeps the guard directives) — a markerless log means \ + that pin was defeated or the zainod log contract moved.\nIndexer log tail:\n{log_tail}" + )] + IndexerSilent { + /// The validator tip height the wait was for. + target: u32, + /// How long the wait ran before giving up. + waited_secs: u64, + /// The final lines of the indexer's log (ANSI-stripped) — + /// typically empty or launch chatter only. + log_tail: String, + }, } impl LaunchError { @@ -275,6 +327,12 @@ impl LaunchError { stderr, additional_log, .. + } + | Self::ReadinessTimeout { + stdout, + stderr, + additional_log, + .. } => { let extra_len = additional_log.as_deref().map_or(0, str::len); let mut combined = diff --git a/zcash_local_net/src/indexer/zainod.rs b/zcash_local_net/src/indexer/zainod.rs index ca69460..2ff0514 100644 --- a/zcash_local_net/src/indexer/zainod.rs +++ b/zcash_local_net/src/indexer/zainod.rs @@ -34,6 +34,35 @@ const SYNC_MARKER: &str = "Syncing block, "; /// The field prefix carrying the block height inside a marker line. const SYNC_HEIGHT_FIELD: &str = "height: "; +/// Debug knob for the zainod child's log filter: when set and +/// non-empty, its value seeds the `RUST_LOG` the launcher pins on the +/// child (with [`GUARD_DIRECTIVES`] appended so the log contract stays +/// alive). The harness otherwise pins plain `info` — the ambient +/// `RUST_LOG` never reaches zainod, because the harness READS the +/// child's log as an API (both the launch readiness line and +/// [`SYNC_MARKER`]) and an ambient filter that silences those targets +/// turns every convergence wait into a hang (zingolib#2488). +pub const ZAINOD_RUST_LOG_ENV: &str = "ZLN_ZAINOD_RUST_LOG"; + +/// The tracing directives the log contract depends on, appended after +/// any [`ZAINOD_RUST_LOG_ENV`] value so they win for their targets: +/// `zainodlib` emits the launch readiness line ("Zaino Indexer started +/// successfully.") and `zaino_state` emits the [`SYNC_MARKER`] lines +/// (module `zaino_state::chain_index::non_finalised_state`, per the +/// captured line pinned in this file's tests). Both at info level. +const GUARD_DIRECTIVES: &str = "zainodlib=info,zaino_state=info"; + +/// The `RUST_LOG` value pinned on the zainod child: `info` by default, +/// or the debug knob's value with [`GUARD_DIRECTIVES`] appended so no +/// passthrough filter — however restrictive — can silence the lines +/// the harness's launch wait and convergence barrier parse. +fn pinned_rust_log(passthrough: Option<&str>) -> String { + match passthrough { + Some(value) if !value.trim().is_empty() => format!("{value},{GUARD_DIRECTIVES}"), + _ => "info".to_string(), + } +} + /// Remove ANSI escape sequences (CSI `ESC [ … ` and two-byte /// `ESC `) from a log line. zainod colors its logs even on a piped /// stdout, and the escapes sit between a marker line's words, so @@ -316,12 +345,20 @@ impl Zainod { if let Some(cache) = config.chain_cache.as_ref() { mounts.push(cache.as_path()); } - let mut command = config.source.command(&crate::container::LaunchSpec { + // The launcher owns the child's logging env: the harness reads + // zainod's log as an API (readiness line, sync markers), so an + // ambient RUST_LOG must never reach the child — a set-but-empty + // or restrictive ambient filter silences the contract and turns + // the launch wait and every convergence wait into a hang + // (zingolib#2488). Debugging goes through the guarded + // ZLN_ZAINOD_RUST_LOG knob instead. + let rust_log = pinned_rust_log(std::env::var(ZAINOD_RUST_LOG_ENV).ok().as_deref()); + let mut command = config.source.command(&crate::container::LaunchSpec::daemon( executable_name, - container_name: container.as_ref().map(|c| c.name()), - mounts: &mounts, - interactive: false, - }); + container.as_ref(), + &mounts, + &[("RUST_LOG", rust_log.as_str())], + )); command.args([ "start", "--config", @@ -514,6 +551,32 @@ mod tests { ); } + #[test] + fn unset_passthrough_pins_plain_info() { + assert_eq!(pinned_rust_log(None), "info"); + } + + #[test] + fn empty_or_blank_passthrough_pins_plain_info() { + // Set-but-empty is the zingolib#2488 trigger: an empty + // EnvFilter has zero directives and silences everything, so it + // must never reach the child. + assert_eq!(pinned_rust_log(Some("")), "info"); + assert_eq!(pinned_rust_log(Some(" ")), "info"); + } + + #[test] + fn restrictive_passthrough_keeps_the_guard_directives() { + // A wallet-side debug filter must not silence the launch + // readiness line (`zainodlib`) or the sync markers + // (`zaino_state`); the guard directives are appended after the + // passthrough so they win for those targets. + assert_eq!( + pinned_rust_log(Some("pepper_sync=debug")), + "pepper_sync=debug,zainodlib=info,zaino_state=info" + ); + } + #[test] fn drifted_marker_line_fails_loud() { let drifted = "Syncing block, tallness: 7"; diff --git a/zcash_local_net/src/launch.rs b/zcash_local_net/src/launch.rs index 07eb234..c8dfce5 100644 --- a/zcash_local_net/src/launch.rs +++ b/zcash_local_net/src/launch.rs @@ -7,6 +7,14 @@ use crate::{ProcessId, error::LaunchError, logs, utils::executable_finder::EXPEC /// Retry budget shared by every daemon's `Process::launch`. pub(crate) const MAX_LAUNCH_ATTEMPTS: u32 = 3; +/// How long [`wait`]'s indicator scan runs before giving up with +/// [`LaunchError::ReadinessTimeout`]. The indicators are log lines, so +/// an unbounded scan hangs forever on a child whose logging is +/// silenced (zingolib#2488). Generous, because a container-mode launch +/// may pull an image inside the same `run` invocation on a cold +/// machine; a healthy local launch observes its indicator in seconds. +pub(crate) const READINESS_TIMEOUT: std::time::Duration = std::time::Duration::from_secs(300); + /// A launch config whose listen-port pins the collision-retry helper can /// enumerate (for the fast-path bind pre-check) and re-roll. Clearing /// always drops *every* pin, not just a conflicting one — partial @@ -113,7 +121,24 @@ async fn wait( // wait for stdout log entry that indicates daemon is ready let interval = std::time::Duration::from_millis(100); + let readiness_deadline = std::time::Instant::now() + READINESS_TIMEOUT; loop { + // Bounded: the indicators are log lines, so a child whose + // logging is silenced would otherwise hang this scan forever + // (zingolib#2488). Generous because a container-mode launch + // may pull an image inside the same `run` invocation. + if std::time::Instant::now() >= readiness_deadline { + stdout_log.read_to_string(&mut stdout).unwrap(); + stderr_log.read_to_string(&mut stderr).unwrap(); + return Err(LaunchError::ReadinessTimeout { + process_name: process.to_string(), + waited_secs: READINESS_TIMEOUT.as_secs(), + success_indicators: format!("{success_indicators:?}"), + stdout, + stderr, + additional_log: snapshot_additional_log(additional_log_path.as_ref()), + }); + } match handle.try_wait() { Ok(Some(exit_status)) => { stdout_log.read_to_string(&mut stdout).unwrap(); diff --git a/zcash_local_net/src/lib.rs b/zcash_local_net/src/lib.rs index d0163a0..4fc8ffb 100644 --- a/zcash_local_net/src/lib.rs +++ b/zcash_local_net/src/lib.rs @@ -273,15 +273,27 @@ where } tokio::time::sleep(Self::INDEXER_CONVERGENCE_POLL_INTERVAL).await; } - Err(IndexerSyncError::ConvergenceTimeout { - target, - last_observed, - waited_secs: started.elapsed().as_secs(), - log_tail: self - .indexer() - .stripped_log_tail(15) - .unwrap_or_else(|error| format!("")), - }) + let waited_secs = started.elapsed().as_secs(); + let log_tail = self + .indexer() + .stripped_log_tail(15) + .unwrap_or_else(|error| format!("")); + // A timeout with no marker EVER seen is not a lagging indexer + // but a starved observation channel — report it as the + // contract violation it is (see `IndexerSyncError::IndexerSilent`). + match last_observed { + None => Err(IndexerSyncError::IndexerSilent { + target, + waited_secs, + log_tail, + }), + Some(_) => Err(IndexerSyncError::ConvergenceTimeout { + target, + last_observed, + waited_secs, + log_tail, + }), + } } /// Mine `n` blocks and wait for Indexer convergence: when this diff --git a/zcash_local_net/src/validator/zebrad.rs b/zcash_local_net/src/validator/zebrad.rs index 5e1076d..3a27661 100644 --- a/zcash_local_net/src/validator/zebrad.rs +++ b/zcash_local_net/src/validator/zebrad.rs @@ -485,12 +485,12 @@ impl Zebrad { if let Some(cache) = config.chain_cache.as_ref() { mounts.push(cache.as_path()); } - let mut command = config.source.command(&crate::container::LaunchSpec { + let mut command = config.source.command(&crate::container::LaunchSpec::daemon( executable_name, - container_name: container.as_ref().map(|c| c.name()), - mounts: &mounts, - interactive: false, - }); + container.as_ref(), + &mounts, + &[], + )); command.args([ "--config", config_file_path.to_str().expect("should be valid UTF-8"), diff --git a/zcash_local_net/src/wallet/zcash_devtool.rs b/zcash_local_net/src/wallet/zcash_devtool.rs index a579a13..631ce90 100644 --- a/zcash_local_net/src/wallet/zcash_devtool.rs +++ b/zcash_local_net/src/wallet/zcash_devtool.rs @@ -319,12 +319,11 @@ impl ZcashDevtool { // The wallet dir is bind-mounted at an identical path in // container mode, so `-w` and the identity/heights paths under // it are valid verbatim inside the one-shot container. - let mut command = self.config.source.command(&crate::container::LaunchSpec { - executable_name: EXECUTABLE_NAME, - container_name: None, - mounts: &[self.wallet_dir.path()], - interactive: stdin_line.is_some(), - }); + let mut command = self.config.source.command(&crate::container::LaunchSpec::one_shot( + EXECUTABLE_NAME, + &[self.wallet_dir.path()], + stdin_line.is_some(), + )); command .arg("wallet") .arg("-w") diff --git a/zingolib-zainod-logging-env-spec.md b/zingolib-zainod-logging-env-spec.md new file mode 100644 index 0000000..702a181 --- /dev/null +++ b/zingolib-zainod-logging-env-spec.md @@ -0,0 +1,151 @@ +# Spec: the Zainod launcher must own its child's logging environment + +Requested by zingolib after the 2026-07-17..20 chain-build stall forensics +(zingolabs/zingolib#2487, evidence chain in that PR's +`.agent-plans/chain-build-stall-forensics.md`). Context: the harness-contract +family in zingolabs/zaino#1386. Zingolib currently pins `zcash_local_net` at +rev `537f84d3d81b228c06ae82365f306ff364e164da`; the tested zainod binary +self-identifies as `0.4.3-ironwood.1`. + +## Problem + +The indexer-convergence barrier is documented as a log-format contract +(`zcash_local_net/src/indexer/zainod.rs`, `SYNC_MARKER = "Syncing block, "`), +but it is implicitly also a log-level contract, and the launcher does not +enforce it. The barrier learns zainod's sync height by polling the child's +stdout log for marker lines (`logged_sync_height` → `last_sync_height_in`). +A marker line that exists but is malformed fails loudly +(`IndexerSyncError::SyncMarkerDrift`), by design. A log with no marker lines +at all, however, returns `Ok(None)` — indistinguishable from "not synced +yet" — so the barrier waits forever. + +zainod emits the markers at info level, and its `init_logging` +(`zainod/src/lib.rs`) builds its filter as +`EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"))`. +The launcher spawns zainod inheriting the ambient environment, so any ambient +`RUST_LOG` that does not enable zainod's info events starves the contract: + +- `RUST_LOG` set but empty parses to a filter with zero directives, which + disables all logging. Verified empirically against the pinned binary: + `podman run -e RUST_LOG= … zainod start` prints nothing where the unset + control prints the info startup line. +- Any restrictive-but-nonempty value (for example `RUST_LOG=pepper_sync=debug`, + the natural choice when instrumenting the wallet under test) likewise + disables the unlisted zainod targets and silences the markers. + +Either way every scenario setup that awaits the barrier hangs unboundedly, +and the failure presents as a mystery stall far from its cause. In zingolib +this cost three days of forensics: the set-but-empty form was manufactured by +an innocent-looking `-e "RUST_LOG=${RUST_LOG:-}"` in a container task, and the +stall was successively misattributed to a wallet-side scan hardening, to +provisioning images, and to nondeterminism before the environment delta was +isolated. Zingolib has fixed its own forwarding (#2487), but the trap remains +armed for every other consumer: harness correctness currently depends on an +ambient variable the harness neither sets nor checks. + +## Requested change + +Two independent hardenings, both in `zcash_local_net`; the first is the fix +and the second is the backstop that keeps the whole failure class loud. + +1. **Pin the child's logging environment at spawn.** The Zainod launcher sets + `RUST_LOG` explicitly on the child process it spawns, unconditionally, + rather than letting the ambient value flow through. The recommended policy + is the simplest one: force the child's `RUST_LOG` to `info`, and document + that zainod verbosity is owned by the harness because the convergence + barrier reads the log. For debugging zainod itself, accept a dedicated + passthrough variable (suggested name `ZLN_ZAINOD_RUST_LOG`) whose value, + when set and non-empty, replaces the pinned default; the launcher should + reject (or append `zainodlib=info` to) a passthrough value that would + silence the marker target, so even the debug knob cannot starve the + barrier. + +2. **Detect silence and fail loudly.** `SyncMarkerDrift` already converts a + drifted format into an error; silence deserves the same treatment. If the + barrier has observed zero marker lines after a bounded wait while the + validator reports a tip ahead of genesis, it should return an error naming + the logging contract (the env pinning, the marker, and the passthrough + knob) instead of polling forever. This converts any future starvation — + a zainod that changes its log target, a launcher regression, a consumer + that finds a new way to scrub the env — into a diagnosis that names + itself. + +## Acceptance + +- With ambient `RUST_LOG` unset, set-but-empty, and set to + `pepper_sync=debug`, a launched net converges identically: the barrier + completes and the markers are present in the child's stdout log. The + existing `zainod_converges_to_validator_tip_after_generate_blocks` pin + test grows siblings (or parameters) covering the three ambient states. +- With the passthrough variable set to a verbose value, the child logs at + that verbosity and the barrier still completes. +- With the silence detector artificially triggered (for example by pointing + the barrier at an empty log in a unit test), the returned error names the + logging contract rather than timing out anonymously. + +## Known unknowns to check while implementing + +- The exact target under which the `Syncing block` markers are emitted + (the startup line uses `zainodlib`); the pinned default and the + passthrough guard must name the real target. +- Whether other launchers in the crate (zebrad, lightwalletd under + `legacy-stack`) parse child logs for anything load-bearing; if so, the + same pinning policy should extend to them in the same change or be + explicitly deferred with a note. +- The right bound for the silence detector, given the slowest observed + legitimate first-marker latency on a cold launch. + +## Out of scope + +- zainod's own `init_logging` (its unset-fallback to `info` is reasonable; + the defect is inheriting ambient env into a child whose logs are an API). +- Zingolib's container-task forwarding, already fixed in + zingolabs/zingolib#2487. +- The other zaino#1386 items (reorg-window serving, hard-exit-on-transient, + the `:0`-address-logging gap), except insofar as this spec's launcher + change lands beside them. + +## Delivery + +A branch off `bump_to_NU6.3` in this repository, PR'd against it, with the +acceptance tests in `zcash_local_net`. Zingolib consumes the change by +advancing its rev pin; no zingolib-side code change is required beyond the +pin. + +## Delivery note (2026-07-20) + +Implemented on `feat/zainod-logging-env-contract`, branched from and PR'd +against `dev` at the requester's direction (`bump_to_NU6.3` had already +merged to `dev` as #278, and `dev`'s tip is the rev zingolib pins). The +known unknowns resolved as follows: + +- The markers' targets are `zainodlib` (the launch readiness line) and + `zaino_state` (the `Syncing block` lines, module + `zaino_state::chain_index::non_finalised_state` per the captured line + pinned in the zainod launcher's tests). The guard directives are + therefore `zainodlib=info,zaino_state=info`, appended after any + `ZLN_ZAINOD_RUST_LOG` passthrough value so they win for those targets; + rejection was not needed. +- The env pin rides `LaunchSpec` (host mode: set on the `Command`; + container mode: `--env` run flags), so both artifact sources are + covered by the same seam. The other launchers were not given pins — + none of them parses child logs for anything load-bearing beyond launch + indicators — but the seam now exists for them. +- The convergence barrier was already bounded (120 s); the truly + unbounded wait was the launch readiness scan in `launch::wait`, whose + indicators are themselves log lines. That scan now carries a 300 s + bound (generous for container-mode image pulls) returning the new + `LaunchError::ReadinessTimeout`, which names the silenced-logging + suspect. The barrier-side silence detector became + `IndexerSyncError::IndexerSilent`: a convergence timeout over a log + with no marker ever seen reports the starved observation channel and + names the pin and the passthrough knob, instead of presenting as an + anonymous timeout. +- The ambient-state acceptance matrix (unset / set-but-empty / + restrictive) is enforced by construction — the pin overrides the + inherited environment in both modes — and pinned by unit tests on the + spawn-command seam (`--env RUST_LOG=…` in the container shape test, + `pinned_rust_log` composition tests). In-process ambient-env + manipulation for an integration matrix was rejected: `std::env::set_var` + is unsafe in edition 2024 and the override makes the ambient state + unreachable regardless.