Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
65 changes: 61 additions & 4 deletions zcash_local_net/src/container.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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
}
}

Expand All @@ -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: &[],
}
}
}
Expand All @@ -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));
Expand Down Expand Up @@ -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");
Expand All @@ -482,6 +536,8 @@ mod tests {
}
expected.extend(
[
"--env",
"RUST_LOG=info",
"--entrypoint",
"zebrad",
"--volume",
Expand Down Expand Up @@ -510,6 +566,7 @@ mod tests {
container_name: None,
mounts,
interactive: true,
env: &[],
});

let args = rendered_args(&command);
Expand Down
58 changes: 58 additions & 0 deletions zcash_local_net/src/error.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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<String>,
},
/// RPC endpoint did not respond within the readiness budget
#[error(
"{process_name} RPC endpoint at {address} did not respond within {timeout:?}: {last_error}"
Expand Down Expand Up @@ -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 {
Expand Down Expand Up @@ -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 =
Expand Down
73 changes: 68 additions & 5 deletions zcash_local_net/src/indexer/zainod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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 [ … <final>` and two-byte
/// `ESC <c>`) from a log line. zainod colors its logs even on a piped
/// stdout, and the escapes sit between a marker line's words, so
Expand Down Expand Up @@ -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",
Expand Down Expand Up @@ -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";
Expand Down
25 changes: 25 additions & 0 deletions zcash_local_net/src/launch.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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();
Expand Down
30 changes: 21 additions & 9 deletions zcash_local_net/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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!("<indexer log unreadable: {error}>")),
})
let waited_secs = started.elapsed().as_secs();
let log_tail = self
.indexer()
.stripped_log_tail(15)
.unwrap_or_else(|error| format!("<indexer log unreadable: {error}>"));
// 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
Expand Down
10 changes: 5 additions & 5 deletions zcash_local_net/src/validator/zebrad.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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"),
Expand Down
Loading
Loading