From b5be1d6b02f732af77c9386abc9d11aa70a118a8 Mon Sep 17 00:00:00 2001 From: Ian Clarke Date: Sat, 8 Aug 2026 11:00:22 -0500 Subject: [PATCH 1/3] fix(update): give the update process a voice, and never mute two of them (#5244) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `freenet update` ran with no tracing subscriber at all. `set_logger` is called only on the node path (`run_node`), so `freenet_main`'s `Update` arm installed nothing and every `tracing::warn!` / `error!` in the installer was a no-op — not just `debug!`. The supervisor invokes it as `freenet update --quiet`, so any site whose only output was a `warn!` plus a `!quiet`-gated `eprintln!` produced nothing anywhere on the automated path. The consequence that matters: an update can install with crash-loop rollback protection never armed, and nothing records it. The trigger is an unwritable or full state directory, which is a fleet condition rather than a freak event. #4073 exists to stop a bad release bricking the fleet, and this is a path where it is off and invisible. Found while investigating #5232, which turned out to be a misreading of the journal caused by this same gap. ## The subscriber `set_cli_logger` installs a stderr-only subscriber at WARN for the `Update` arm. Two traps decided its shape, and both produce a fix that looks done and changes nothing: * Passing a log dir — the natural copy-paste from `run_node` — sets `use_file_logging`, routing everything into the rolling log files. systemd captures stdout/stderr, NOT those files; that asymmetry is the whole of #5232. Every `warn!` would start "working" while the journal stayed exactly as blind. * With no log dir, `init_tracer` still falls through to stdout unless `FREENET_LOG_TO_STDERR` happens to be set. So `init_cli_stderr_tracer` is explicit rather than configuration- dependent: stderr, always. Diagnostics belong there, it leaves the command's `println!` output on stdout, and systemd records both. It is additive rather than a flag on `set_logger`. That function serves the node, where output MUST keep reaching the log files (`freenet service report` collects them, and on Windows nothing captures stdout). Adding a "log to stderr instead" switch to the node's only logging call would put a mis-settable lever on the path that must not lose files. WARN, not INFO: this runs on every non-clean stop, so an INFO default would flood the journal of exactly the crash-looping node whose journal we need to read. ## The two that must never be quiet Both are states where the machinery designed to stop a bad release bricking the fleet is silently OFF, so both get an unconditional `eprintln!` as well — belt-and-braces, surviving any later refactor that drops the subscriber. This follows `handle_post_stop`'s existing precedent, which is why its crash and rollback lines were visible in the field while the rest of the file was not. * "failed to snapshot the known-good binary" — the update is about to land with no rollback target. * "installed the update but FAILED TO ARM crash-loop rollback" — it landed and the marker is absent, so the post-stop hook finds nothing to count. Deliberately only those two. A general de-quieting would leave `--quiet` meaning nothing; the separation this restores is that `--quiet` controls chattiness and never whether a safety event is recorded. The third, "auto-update is LOCKED OUT after repeated failed installs", was `debug!` — compiled out of release builds — and the loud once-per-process warning in `check_if_update_available` is reachable only from the peer-signal triggers, so on a node whose peers all share its version nothing said it would never update again. Now warn + stderr, once per process, mirroring that existing `LOCKOUT_WARNED` pattern: the condition persists until an operator acts, so one line per boot is the right cadence rather than a repeat every 6h forever. Every other `tracing::warn!` in the update path — the blocked-version refusal, the rate-limit exits, the install-gate counter — becomes visible through the subscriber without touching its call site. That is the point of fixing the class rather than the instances. ## Testing * `the_update_process_emits_tracing_to_stderr` runs the real binary at `RUST_LOG=trace` and asserts stderr is non-empty and stdout is empty. Before the fix both were empty whatever `RUST_LOG` said. Not network- dependent despite `--check` reaching for GitHub: the HTTP stack traces its connection attempts on any outcome, including offline. * `the_update_process_is_quiet_when_nothing_is_wrong` pins the WARN default, so nobody quietly promotes it to INFO. * `the_update_arm_installs_the_cli_logger_and_not_a_file_logger` pins the wiring, which is the difference the runtime tests cannot see: a log-dir subscriber would still show output on a terminal. Scraped across files (test in `tests/`, source in `src/bin/`) so it cannot be satisfied by its own assertion strings — the self-matching failure mode in `.claude/rules/bug-prevention-patterns.md`. Verified by hand as well: `RUST_LOG=trace freenet update --check --quiet` now writes 24 lines to stderr and 0 to stdout, and is silent at the default level. Refs #5244, #5232 Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01JHwV1j9kGJEa5D6CxAyb6T --- crates/core/src/bin/commands/update.rs | 35 ++-- crates/core/src/bin/freenet.rs | 39 ++++- crates/core/src/config.rs | 39 +++++ crates/core/src/tracing/tracer.rs | 56 ++++++ .../core/tests/update_command_is_not_mute.rs | 164 ++++++++++++++++++ 5 files changed, 318 insertions(+), 15 deletions(-) create mode 100644 crates/core/tests/update_command_is_not_mute.rs diff --git a/crates/core/src/bin/commands/update.rs b/crates/core/src/bin/commands/update.rs index 6bb77c6fae..3fe4f6b57d 100644 --- a/crates/core/src/bin/commands/update.rs +++ b/crates/core/src/bin/commands/update.rs @@ -706,12 +706,20 @@ impl UpdateCommand { ) { Ok(prepared) => Some(prepared), Err(e) => { - if !self.quiet { - eprintln!( - "Warning: failed to snapshot known-good binary for crash-loop \ - rollback: {e}. Proceeding without rollback protection for this update." - ); - } + // NOT gated on `--quiet` (#5244). This is one of the two states + // where #4073's brick-safety machinery is silently OFF: the + // update is about to land with no rollback target, so a release + // that then crash-loops cannot be reverted. `--quiet` must mean + // "be less chatty", never "do not record safety events". + // Belt-and-braces alongside the subscriber installed in + // `freenet_main`, so this survives a later refactor that drops + // the subscriber. Matches `handle_post_stop`'s precedent above. + eprintln!( + "Freenet: failed to snapshot the known-good binary for crash-loop \ + rollback: {e}. PROCEEDING WITHOUT ROLLBACK PROTECTION for this update — if \ + this version crash-loops it will NOT be auto-reverted. Check the \ + permissions and free space on the Freenet state directory." + ); tracing::warn!(error = %e, "Failed to capture known-good rollback binary (#4073)"); None } @@ -749,12 +757,15 @@ impl UpdateCommand { ¤t_exe, &meta, ) { - if !self.quiet { - eprintln!( - "Warning: installed the update but failed to arm crash-loop rollback \ - protection: {e}. If this version crash-loops it will NOT auto-roll-back." - ); - } + // NOT gated on `--quiet` — see the sibling above (#5244). + // The update HAS landed and the probation marker is absent, so + // the post-stop hook will find nothing to count and this + // version can crash-loop indefinitely without being reverted. + eprintln!( + "Freenet: installed the update but FAILED TO ARM crash-loop rollback \ + protection: {e}. If this version crash-loops it will NOT be auto-reverted. \ + Check the permissions and free space on the Freenet state directory." + ); tracing::warn!(error = %e, "Failed to arm crash-loop rollback probation (#4073)"); } } diff --git a/crates/core/src/bin/freenet.rs b/crates/core/src/bin/freenet.rs index 83261fa712..d157decee3 100644 --- a/crates/core/src/bin/freenet.rs +++ b/crates/core/src/bin/freenet.rs @@ -556,6 +556,12 @@ async fn run_network_node_with_signals( Some((major, minor, patch)) } + // Once-per-process guard for the lockout report below. The lockout + // persists until an operator clears it, so this is a state to announce + // on each boot, not a 6-hourly repeat. + static LOCKOUT_REPORTED: std::sync::atomic::AtomicBool = + std::sync::atomic::AtomicBool::new(false); + const HARD_EXIT_TIMEOUT: std::time::Duration = std::time::Duration::from_secs(6 * 3600); // Stagger timer: random delay 0-4 hours before updating on decentralized discovery. const MAX_STAGGER_SECS: u64 = 4 * 3600; @@ -869,8 +875,25 @@ async fn run_network_node_with_signals( return; } } - } else { - tracing::debug!( + } else if !LOCKOUT_REPORTED.swap(true, std::sync::atomic::Ordering::Relaxed) { + // The second state where the update machinery is silently + // OFF (#5244). This was `debug!`, which release builds + // compile out entirely (`release_max_level_info`), and the + // loud once-per-process warning in `check_if_update_available` + // is only reachable from the PEER-signal triggers — so on a + // node whose peers all share its version, nothing said this + // node would never update again. + // + // Once per process, mirroring that existing `LOCKOUT_WARNED` + // pattern: the condition is permanent until an operator + // acts, so repeating it every 6h forever is noise, and one + // line per restart is enough to find it. + eprintln!( + "Freenet: auto-update is LOCKED OUT on this node after repeated failed \ + installs (#3934). It will not detect or apply any further release until \ + you run `freenet update` manually to clear the counter." + ); + tracing::warn!( "Periodic re-poll: skipped — auto-update locked out after repeated \ failed installs (#3934); run `freenet update` to recover" ); @@ -1188,7 +1211,17 @@ fn freenet_main() -> anyhow::Result<()> { config_paths, ) } - Some(Command::Update(cmd)) => cmd.run(build_info::VERSION), + Some(Command::Update(cmd)) => { + // #5244: this process previously ran with NO subscriber installed — + // `set_logger` is called only on the node path — so every + // `tracing::warn!`/`error!` in the installer was a no-op. That is + // the process the supervisor runs from `ExecStopPost` to drive + // crash-loop rollback, so its warnings are exactly the ones an + // operator needs. WARN (not INFO) because this runs on every + // non-clean stop of a crash-looping node. + freenet::config::set_cli_logger(tracing::level_filters::LevelFilter::WARN); + cmd.run(build_info::VERSION) + } Some(Command::Uninstall(cmd)) => cmd.run(), Some(Command::Secrets(cfg)) => { // CLI utility; uses simple current-thread runtime (no diff --git a/crates/core/src/config.rs b/crates/core/src/config.rs index f1501185b6..e1f1d46708 100644 --- a/crates/core/src/config.rs +++ b/crates/core/src/config.rs @@ -5102,6 +5102,45 @@ impl GlobalTestMetrics { } } +/// Install the logger for a short-lived CLI subcommand: stderr only, at +/// `level`. +/// +/// Separate from [`set_logger`] on purpose. `set_logger` serves the node, where +/// output MUST keep going to the rolling log files (`freenet service report` +/// collects them, and on Windows nothing captures stdout). Adding a "log to +/// stderr instead" flag to that path would put a switch capable of silently +/// disabling file logging on the node's only logging call — so the CLI gets its +/// own entry point rather than a shared, mis-settable one. +/// +/// See `tracing::tracer::init_cli_stderr_tracer` for why stderr specifically +/// (#5244). +pub fn set_cli_logger(level: tracing::level_filters::LevelFilter) { + #[cfg(feature = "trace")] + { + static CLI_LOGGER_SET: AtomicBool = AtomicBool::new(false); + if CLI_LOGGER_SET + .compare_exchange( + false, + true, + std::sync::atomic::Ordering::Release, + std::sync::atomic::Ordering::SeqCst, + ) + .is_err() + { + return; + } + + // Best-effort: a CLI subcommand that cannot install a subscriber must + // still do its job. Failing the update because logging could not start + // would turn a diagnostics problem into an outage. + if let Err(e) = crate::tracing::tracer::init_cli_stderr_tracer(level) { + eprintln!("Warning: could not initialize logging for this command: {e}"); + } + } + #[cfg(not(feature = "trace"))] + let _ = level; +} + pub fn set_logger( level: Option, endpoint: Option, diff --git a/crates/core/src/tracing/tracer.rs b/crates/core/src/tracing/tracer.rs index 6bb8ae4926..5132c64623 100644 --- a/crates/core/src/tracing/tracer.rs +++ b/crates/core/src/tracing/tracer.rs @@ -744,6 +744,62 @@ pub fn init_tracer( ) } +/// Install a stderr-only subscriber for a short-lived CLI subcommand. +/// +/// ## Why this exists (#5244) +/// +/// `freenet update` ran with **no subscriber at all**: `set_logger` is called +/// only on the node path (`run_node`), so every `tracing::warn!` / `error!` in +/// the installer was a no-op. Combined with the supervisor invoking it as +/// `freenet update --quiet`, sites whose only output was a `warn!` plus a +/// `!quiet`-gated `eprintln!` were completely silent in production — including +/// "installed the update but could not arm crash-loop rollback". +/// +/// ## Why not just call [`set_logger`] here +/// +/// Two traps, both of which produce a fix that looks done and changes nothing: +/// +/// 1. Passing a `log_dir` (the natural copy-paste from `run_node`) sets +/// `use_file_logging`, which routes everything into the rolling log files. +/// systemd captures stdout/stderr, NOT those files — that asymmetry is the +/// whole of #5232. Every `warn!` would start "working" and the journal would +/// stay exactly as blind. +/// 2. With no log dir, [`init_tracer`] still falls through to stdout unless the +/// `FREENET_LOG_TO_STDERR` env var happens to be set. +/// +/// So this is explicit rather than configuration-dependent: **stderr, always**. +/// Diagnostics belong there, it leaves the command's human-facing `println!` +/// output on stdout, and systemd records both. +/// +/// Deliberately minimal: no file appenders, no rate limiters. This is a +/// process that runs for seconds and exits, and the output it must not lose is +/// the handful of lines saying a safety mechanism did not engage. +/// +/// `FREENET_DISABLE_LOGS` is still honoured, and `RUST_LOG` still overrides +/// `level` via `from_env_lossy`. +pub fn init_cli_stderr_tracer(level: LevelFilter) -> anyhow::Result<()> { + if std::env::var("FREENET_DISABLE_LOGS").is_ok() { + return Ok(()); + } + let use_json = std::env::var("FREENET_LOG_FORMAT") + .map(|v| v.eq_ignore_ascii_case("json")) + .unwrap_or(false); + let filter_layer = tracing_subscriber::EnvFilter::builder() + .with_default_directive(level.into()) + .from_env_lossy() + .add_directive("moka=off".parse().expect("infallible")) + .add_directive("sqlx=error".parse().expect("infallible")); + init_stdout_tracer( + level, + // The point of the function; see the docs above. + true, + use_json, + filter_layer, + None, + None, + ) +} + fn init_stdout_tracer( _default_filter: LevelFilter, to_stderr: bool, diff --git a/crates/core/tests/update_command_is_not_mute.rs b/crates/core/tests/update_command_is_not_mute.rs new file mode 100644 index 0000000000..a06aaaf8d1 --- /dev/null +++ b/crates/core/tests/update_command_is_not_mute.rs @@ -0,0 +1,164 @@ +//! Guards for #5244: the `freenet update` process must not be mute. +//! +//! `set_logger` is installed only on the node path, so for a long time the +//! `freenet update` process ran with **no tracing subscriber at all** and every +//! `tracing::warn!` / `error!` in the installer was a no-op. The supervisor runs +//! it as `freenet update --quiet`, so sites whose only output was a `warn!` plus +//! a `!quiet`-gated `eprintln!` produced nothing at all in production — +//! including "installed the update but could not arm crash-loop rollback", +//! which is #4073's brick-safety machinery reporting that it is off. +//! +//! Two things need holding, and they fail in different ways, so they are tested +//! separately: +//! +//! 1. A subscriber exists in that process **and writes to stderr**. Tested by +//! running the real binary, because a subscriber is process-global state that +//! an in-process test cannot observe (the harness installs its own). +//! 2. It is wired via `set_cli_logger`, not via `set_logger` with a log dir. +//! That distinction is invisible to the runtime tests but decides whether the +//! output reaches the journal at all — see the pin's own docs. + +#![cfg(unix)] + +use std::path::PathBuf; +use std::process::Command; + +fn workspace_root() -> PathBuf { + PathBuf::from(env!("CARGO_MANIFEST_DIR")) + .parent() + .and_then(|p| p.parent()) + .expect("workspace layout: crates/core/../../ should resolve") + .to_path_buf() +} + +fn freenet_bin() -> PathBuf { + let target = std::env::var_os("CARGO_TARGET_DIR") + .map(PathBuf::from) + .unwrap_or_else(|| workspace_root().join("target")); + let debug = target.join("debug").join("freenet"); + if debug.exists() { + return debug; + } + let release = target.join("release").join("freenet"); + assert!( + release.exists(), + "freenet binary not found at {debug:?} or {release:?}. Build it first: \ + `cargo build --bin freenet`." + ); + release +} + +/// The update process must emit `tracing` output, and it must go to stderr. +/// +/// Runs with `RUST_LOG=trace` so the assertion does not depend on the command +/// happening to log a warning: at TRACE the HTTP stack alone produces output on +/// any outcome, including an offline one (connection attempts are traced), so +/// this is not a network-dependent test even though `--check` does try to reach +/// GitHub. `--check` can never install, so it cannot overwrite the binary under +/// test. +/// +/// Before the fix this produced zero bytes on both streams no matter what +/// `RUST_LOG` said, because there was no subscriber to read it. +#[test] +fn the_update_process_emits_tracing_to_stderr() { + let home = tempfile::tempdir().expect("tempdir"); + + let out = Command::new(freenet_bin()) + .args(["update", "--check", "--quiet"]) + .env("HOME", home.path()) + .env("RUST_LOG", "trace") + .env("FREENET_TELEMETRY_ENABLED", "false") + .output() + .expect("run freenet update --check"); + + let stderr = String::from_utf8_lossy(&out.stderr); + let stdout = String::from_utf8_lossy(&out.stdout); + + assert!( + !stderr.trim().is_empty(), + "#5244: `freenet update` produced no tracing output at RUST_LOG=trace, so it has no \ + subscriber installed and every warn!/error! in the installer is a no-op — including \ + the ones that report crash-loop rollback failing to arm.\nstdout was:\n{stdout}" + ); + assert!( + stderr.contains("TRACE") || stderr.contains("DEBUG") || stderr.contains("INFO"), + "stderr had content but none of it looks like a tracing line; is something else \ + writing here?\nstderr:\n{stderr}" + ); + // Diagnostics on stderr keeps the command's human-facing `println!` output + // on stdout parseable, and systemd records both. + assert!( + stdout.trim().is_empty(), + "tracing output must not land on stdout, which is the command's own output stream:\n\ + {stdout}" + ); +} + +/// At its default level the update process stays quiet, so installing a +/// subscriber does not turn every `ExecStopPost` run of a crash-looping node +/// into a wall of journal noise. +#[test] +fn the_update_process_is_quiet_when_nothing_is_wrong() { + let home = tempfile::tempdir().expect("tempdir"); + + let out = Command::new(freenet_bin()) + .args(["update", "--check", "--quiet"]) + .env("HOME", home.path()) + .env_remove("RUST_LOG") + .env("FREENET_TELEMETRY_ENABLED", "false") + .output() + .expect("run freenet update --check"); + + let stderr = String::from_utf8_lossy(&out.stderr); + assert!( + stderr.trim().is_empty(), + "the default level must be WARN, not INFO: this runs on every non-clean stop, so an \ + INFO default would flood the journal of exactly the crash-looping node whose journal \ + we need to read.\nstderr:\n{stderr}" + ); +} + +/// The `Update` arm must install the CLI logger, and must NOT reach for +/// `set_logger` with a log directory. +/// +/// This is the trap that makes a fix here look done while changing nothing: +/// `set_logger(None, None, Some(log_dir))` — the natural copy-paste from +/// `run_node` — sets `use_file_logging`, which routes everything into the +/// rolling log files. systemd captures stdout/stderr, NOT those files. Every +/// `warn!` would start "working" and the journal would stay exactly as blind as +/// it was, which is the same asymmetry that caused #5232 to be misdiagnosed. +/// +/// The runtime tests above cannot see that difference: with a log dir they +/// would still find output on stderr in a terminal, because `init_tracer` adds +/// a console layer when stdout is a TTY. Only the wiring tells them apart. +/// +/// Scraped ACROSS files on purpose — this test lives in `tests/` and reads +/// `src/bin/freenet.rs`, so it can never be satisfied by its own assertion +/// strings, which is the self-matching failure mode documented in +/// `.claude/rules/bug-prevention-patterns.md`. +#[test] +fn the_update_arm_installs_the_cli_logger_and_not_a_file_logger() { + let src = std::fs::read_to_string(workspace_root().join("crates/core/src/bin/freenet.rs")) + .expect("read bin/freenet.rs"); + + let arm_start = src + .find("Some(Command::Update(cmd)) =>") + .expect("the Update dispatch arm must still exist"); + let arm = &src[arm_start..]; + let arm_end = arm + .find("Some(Command::Uninstall(cmd))") + .expect("the Uninstall arm must still follow Update; re-anchor this pin if it moved"); + let arm = &arm[..arm_end]; + + assert!( + arm.contains("set_cli_logger"), + "#5244: the Update arm must install a subscriber, or every warn!/error! in the \ + installer is a no-op. Arm body:\n{arm}" + ); + assert!( + !arm.contains("set_logger("), + "the Update arm must use `set_cli_logger`, NOT `set_logger`: the latter's log-dir \ + argument routes output into the rolling log files, which systemd does not capture, so \ + the journal would stay exactly as blind while the fix looked done. Arm body:\n{arm}" + ); +} From a09d20a363cece2dad8ed54f9a1eb0d785ffb234 Mon Sep 17 00:00:00 2001 From: Ian Clarke Date: Sat, 8 Aug 2026 11:02:09 -0500 Subject: [PATCH 2/3] fix(update): an unreadable failure counter must not reset the lockout (#5244) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `get_update_failure_count_at` matched `Err(_) => 0`, which catches every read error and not just `NotFound`. A counter file made unreadable — EACCES, EIO, a directory in its place — therefore read as "no failures" and silently reset the #3934 lockout, the mechanism that bounds the exit-42 → failed-install → restart loop. That is a fail-OPEN on safety equipment, and the doc comment directly above the function already promised the opposite: Present but unparseable → MAX_UPDATE_FAILURES (defensive: if the counter file has been truncated or corrupted we must NOT silently reset the lockout — that would be an amplification vector for any process that can partially overwrite the file, defeating the #3934 fix). Only the parse path was defended. Making the file unreadable defeats the lockout more easily than partially overwriting it, which is the attack the comment names. It also fails open at precisely the wrong moment: an unwritable or full state directory is what makes installs fail in the first place, so the counter is unreadable exactly when it is needed. Combined with the two silent paths fixed in the previous commit, one bad state directory disables all three guards at once — rollback never arms, the counter can neither persist nor read back, and nothing says so. `read_github_poll_bucket_at`, twenty lines away in the same file, already makes this distinction and explains why ("Any other read error (permissions, etc.) is treated as corrupt => deny, conservatively, rather than granting a free poll"). Same file, same intent, opposite behaviour; this brings the counter into line with its sibling and with its own docs. Testing - `an_unreadable_failure_counter_does_not_reset_the_lockout` puts a directory where the counter file belongs and asserts both the count and `should_attempt_update_at`. A directory rather than a chmod because it fails for root too, so the test cannot quietly degrade into a no-op in a container. - `an_absent_failure_counter_reads_as_no_failures` keeps the legitimate case working, so a fresh node is not born locked out. Refs #5244, #3934 Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01JHwV1j9kGJEa5D6CxAyb6T --- crates/core/src/bin/commands/auto_update.rs | 63 +++++++++++++++++++-- 1 file changed, 57 insertions(+), 6 deletions(-) diff --git a/crates/core/src/bin/commands/auto_update.rs b/crates/core/src/bin/commands/auto_update.rs index 5724eafc52..d6d31bc09a 100644 --- a/crates/core/src/bin/commands/auto_update.rs +++ b/crates/core/src/bin/commands/auto_update.rs @@ -1046,15 +1046,29 @@ fn get_update_failure_count() -> u32 { /// directory. /// /// * Missing file → `0` (legitimate "no failures yet"). -/// * Present but unparseable → `MAX_UPDATE_FAILURES` (defensive: if the -/// counter file has been truncated or corrupted we must NOT silently -/// reset the lockout — that would be an amplification vector for any -/// process that can partially overwrite the file, defeating the -/// #3934 fix. Users can recover by explicitly deleting the file). +/// * Present but unparseable, OR unreadable for any reason other than being +/// absent → `MAX_UPDATE_FAILURES` (defensive: if the counter file has been +/// truncated, corrupted, or made unreadable we must NOT silently reset the +/// lockout — that would be an amplification vector for any process that can +/// partially overwrite or chmod the file, defeating the #3934 fix. Users can +/// recover by explicitly deleting the file). pub(crate) fn get_update_failure_count_at(dir: &std::path::Path) -> u32 { match fs::read_to_string(dir.join("update_failures")) { Ok(s) => s.trim().parse().unwrap_or(MAX_UPDATE_FAILURES), - Err(_) => 0, + // Genuinely absent: no failures yet. + Err(e) if e.kind() == std::io::ErrorKind::NotFound => 0, + // Present but unreadable (EACCES, EIO, a directory in its place) is the + // same situation as unparseable, and gets the same defensive answer. + // Reading it as zero would silently RESET the lockout — a fail-OPEN on + // the mechanism that bounds the #3934 restart loop, and an easier way to + // defeat it than the partial-overwrite this function's doc already + // guards against. It also fails open at exactly the wrong moment: an + // unwritable state dir is what makes installs fail in the first place, + // so the counter would be unreadable precisely when it is needed. + // + // `read_github_poll_bucket_at` in this file makes the same distinction + // for the same reason. + Err(_) => MAX_UPDATE_FAILURES, } } @@ -1609,6 +1623,43 @@ pub fn jittered_repoll_interval(base: Duration, jitter_fraction: f64, rand_unit: #[cfg(test)] mod tests { + /// An unreadable counter file must NOT read as "no failures". + /// + /// `Err(_) => 0` caught every read error, not just `NotFound`, so a counter + /// made unreadable (EACCES, EIO, a directory in its place) silently reset + /// the #3934 lockout — a fail-OPEN on the mechanism that bounds the + /// exit-42 → failed-install → restart loop. The doc comment above the + /// function promised the opposite and named the threat; only the parse path + /// was actually defended. See #5244. + /// + /// A directory is used rather than a chmod because it fails for root too, + /// so this cannot quietly degrade into a no-op in a container. + #[test] + fn an_unreadable_failure_counter_does_not_reset_the_lockout() { + let dir = tempfile::tempdir().unwrap(); + std::fs::create_dir(dir.path().join("update_failures")).unwrap(); + + assert_eq!( + super::get_update_failure_count_at(dir.path()), + super::MAX_UPDATE_FAILURES, + "an unreadable counter must be treated as fully-failed, not as zero: reading it as \ + zero re-enables the update loop the counter exists to stop" + ); + assert!( + !super::should_attempt_update_at(dir.path()), + "and the lockout it feeds must stay engaged" + ); + } + + /// The legitimate case still reads as zero, so a fresh node is not born + /// locked out. + #[test] + fn an_absent_failure_counter_reads_as_no_failures() { + let dir = tempfile::tempdir().unwrap(); + assert_eq!(super::get_update_failure_count_at(dir.path()), 0); + assert!(super::should_attempt_update_at(dir.path())); + } + use super::*; use freenet::transport::{ set_open_connection_count, signal_version_mismatch, version_mismatch_generation, From d45fe5a2faaf4b1a97da70a145e2b477d28715b0 Mon Sep 17 00:00:00 2001 From: Ian Clarke Date: Sat, 8 Aug 2026 11:34:16 -0500 Subject: [PATCH 3/3] =?UTF-8?q?fix(update):=20address=20review=20=E2=80=94?= =?UTF-8?q?=20a=20regression,=20two=20vacuous=20tests,=20a=20false=20claim?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two independent reviews of #5247. Findings, in the order they matter. **A regression this PR introduced.** Making the counter read fail-closed was right for the GATE — an unreadable counter keeps auto-update suppressed while the condition lasts, and heals by itself because the gate re-reads every time. But `record_update_failure_at` fed that same defensive answer back through `+ 1`, so one transient EIO on a flaky mount would have written 4 to disk and locked auto-update off PERMANENTLY. That is worse than the fail-open it replaced. The decision is now `next_failure_count`, a pure function that writes nothing when the counter is unreadable, with a unit test over all four cases. Extracting it is what makes the case testable at all: the alternative is contriving a filesystem that reads one way and writes another. **A test that could not fail.** `the_update_process_is_quiet_when_nothing_is_wrong` claimed to pin WARN-vs-INFO, but nothing on the `--check` path logs at INFO, so promoting the level would have left it green. Deleted. The level is pinned in the source scrape instead, where it is a fact about the code rather than about which paths happen to log. **Two tests that would have gone red on a network blip.** Both ran `update --check`, which reaches api.github.com — so they depended on the network being up AND GitHub not rate-limiting a shared CI egress IP, and they spent real quota twice per run, which #5102 went to some trouble to conserve. They now seed the installer's GitHub cooldown file, which makes `probe_latest_tag` defer with exactly one known WARN before any HTTP. Deterministic and offline. That fixture also fixes a subtler problem: the old assertion looked for TRACE output from the HTTP stack, which `release_max_level_info` compiles out entirely. It passed only because CI builds debug, and would have failed on the build we ship. A WARN survives both. **A claim that is not true on two platforms.** "This fixes the class" is systemd-only: `spawn_update_command` nulls stdio, so under the Windows wrapper and the macOS tray path the new subscriber output and both unconditional messages go to the bit bucket. Its doc comment also said nulling was "harmless on macOS/Linux because `--quiet` already suppresses all output", which this PR made false. Comment corrected, with the shape of the real fix recorded (point stderr at the wrapper log; the Windows constraint is about INHERITED invalid handles, not about needing null). NOT fixed here: it needs a log dir threaded through five call sites plus a stdio change on the code path that has caused three os-error-6 incidents, and I cannot exercise Windows or macOS from here. Left for a follow-up rather than shipped untested. **Escape sequences into the journal.** The CLI tracer went through `init_stdout_tracer`'s `pretty` layer, which colours unconditionally and splits each event across several lines. journald stores bytes verbatim, so that wrote ANSI into the destination this change exists to reach. It now builds its own compact layer with ANSI gated on `stderr().is_terminal()`, with a test asserting no escapes reach a pipe. **A comment promising something the code did not do.** `set_cli_logger` said failing to install a subscriber must not fail the update, while the only realistic failure — a subscriber already installed — panicked inside `init_stdout_tracer`. The new layer returns the error instead, so the promise now holds. Also from review: the lockout message named a remedy that does not work when the counter is unreadable (`freenet update` cannot clear what it cannot read), so it now names the file and `--force` too; the `LOCKOUT_REPORTED` static moved next to the branch it guards; the source pin strips comments so a comment ABOUT the call cannot satisfy it; and the tests use `CARGO_BIN_EXE_freenet` rather than a hand-rolled `target/debug` lookup that would happily assert against a stale binary — the failure mode this test exists to prevent. Refs #5244 Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01JHwV1j9kGJEa5D6CxAyb6T --- crates/core/src/bin/commands/auto_update.rs | 74 +++++- .../core/src/bin/commands/service/wrapper.rs | 15 +- crates/core/src/bin/freenet.rs | 66 +++-- crates/core/src/tracing/tracer.rs | 45 +++- .../core/tests/update_command_is_not_mute.rs | 232 ++++++++++-------- 5 files changed, 289 insertions(+), 143 deletions(-) diff --git a/crates/core/src/bin/commands/auto_update.rs b/crates/core/src/bin/commands/auto_update.rs index d6d31bc09a..80ba973ef5 100644 --- a/crates/core/src/bin/commands/auto_update.rs +++ b/crates/core/src/bin/commands/auto_update.rs @@ -1062,9 +1062,14 @@ pub(crate) fn get_update_failure_count_at(dir: &std::path::Path) -> u32 { // Reading it as zero would silently RESET the lockout — a fail-OPEN on // the mechanism that bounds the #3934 restart loop, and an easier way to // defeat it than the partial-overwrite this function's doc already - // guards against. It also fails open at exactly the wrong moment: an - // unwritable state dir is what makes installs fail in the first place, - // so the counter would be unreadable precisely when it is needed. + // guards against. + // + // Note this is NOT the read-only/full state dir case: EROFS and ENOSPC + // break writes, while reads still succeed or report NotFound, which is + // handled above. The states that land here are anomalous ones — a + // chmod'd or wrong-owner file, a directory in its place, a failing mount + // — and treating them as fully-failed is self-healing, because the gate + // re-reads every time and recovers the moment the file is readable again. // // `read_github_poll_bucket_at` in this file makes the same distinction // for the same reason. @@ -1087,10 +1092,34 @@ pub fn record_update_failure() { /// Testable variant of [`record_update_failure`] that writes into an /// explicit directory. Missing directories are created on demand. +/// What to persist after an install failure, given the raw read of the existing +/// counter — or `None` to write nothing at all. +/// +/// Split out from [`record_update_failure_at`] so the decision is testable +/// without contriving a filesystem that reads one way and writes another. +/// +/// The subtle case is the unreadable one. [`get_update_failure_count_at`] +/// deliberately reports an unreadable counter as [`MAX_UPDATE_FAILURES`] so the +/// GATE stays closed while the file cannot be read — that is transient and +/// self-healing, because the gate re-reads every time. Feeding that defensive +/// answer back into the file would be neither: it would bake `MAX + 1` into +/// disk and lock the node out of auto-update PERMANENTLY on one transient read +/// error (a flaky network mount, an EIO). That is a worse failure than the +/// fail-open it replaced, so an unreadable counter writes nothing. +fn next_failure_count(existing: std::io::Result) -> Option { + match existing { + Ok(s) => Some(s.trim().parse::().unwrap_or(0).saturating_add(1)), + Err(e) if e.kind() == std::io::ErrorKind::NotFound => Some(1), + Err(_) => None, + } +} + pub(crate) fn record_update_failure_at(dir: &std::path::Path) { let _mkdir = fs::create_dir_all(dir); - let count = get_update_failure_count_at(dir) + 1; - let _write = fs::write(dir.join("update_failures"), count.to_string()); + let path = dir.join("update_failures"); + if let Some(count) = next_failure_count(fs::read_to_string(&path)) { + let _write = fs::write(&path, count.to_string()); + } } /// Clear the update failure count. Called from the update command after a @@ -1623,6 +1652,41 @@ pub fn jittered_repoll_interval(base: Duration, jitter_fraction: f64, rand_unit: #[cfg(test)] mod tests { + /// A transient read error must not be persisted as a permanent lockout. + /// + /// `get_update_failure_count_at` answers MAX_UPDATE_FAILURES when the + /// counter cannot be read, which keeps the GATE closed while the condition + /// lasts and heals by itself. Recording a failure used to feed that answer + /// straight back through `+ 1`, so one transient EIO would write 4 to disk + /// and lock auto-update off forever — turning the fail-CLOSED read into a + /// permanent brick, which is worse than the fail-open it replaced (#5244). + #[test] + fn an_unreadable_counter_is_never_persisted_as_a_count() { + use std::io::{Error, ErrorKind}; + + assert_eq!( + super::next_failure_count(Err(Error::from(ErrorKind::PermissionDenied))), + None, + "an unreadable counter must write NOTHING: we cannot know the real count, and \ + inventing MAX+1 makes a transient error permanent" + ); + assert_eq!( + super::next_failure_count(Err(Error::from(ErrorKind::NotFound))), + Some(1), + "a genuinely absent counter is the first failure" + ); + assert_eq!( + super::next_failure_count(Ok("2".to_string())), + Some(3), + "the ordinary case still increments" + ); + assert_eq!( + super::next_failure_count(Ok("garbage".to_string())), + Some(1), + "an unparseable counter restarts the count rather than inventing a lockout" + ); + } + /// An unreadable counter file must NOT read as "no failures". /// /// `Err(_) => 0` caught every read error, not just `NotFound`, so a counter diff --git a/crates/core/src/bin/commands/service/wrapper.rs b/crates/core/src/bin/commands/service/wrapper.rs index cfcf583935..ff596e641f 100644 --- a/crates/core/src/bin/commands/service/wrapper.rs +++ b/crates/core/src/bin/commands/service/wrapper.rs @@ -630,8 +630,19 @@ pub(super) fn run_wrapper(version: &str) -> Result<()> { /// update subprocess silently fails to start and the wrapper falls into /// the exit-42 / update-failed / backoff-relaunch loop documented in /// #3934 (which was also the root cause of "Check for Updates" being -/// broken in #3933). Null stdio is harmless on macOS/Linux because -/// `--quiet` already suppresses all output. +/// broken in #3933). +/// +/// KNOWN GAP (#5244): nulling stderr also discards everything `freenet update` +/// now reports about brick-safety — the WARN subscriber installed for the +/// subcommand, and the two unconditional messages saying crash-loop rollback +/// failed to arm. Under systemd those reach the journal; under this wrapper +/// (Windows, and the macOS tray path) they go nowhere. `--quiet` no longer +/// suppresses them, so the previous claim that nulling was harmless because +/// "--quiet already suppresses all output" is no longer true. Fixing it means +/// pointing stderr at the wrapper log (`log_wrapper_event`'s file) rather than +/// at null — the Windows constraint above is about INHERITED invalid handles, +/// not about needing null specifically — and threading a log dir through all +/// five call sites. /// /// `post_stop_exit_code` is `Some(code)` ONLY when this update runs as part of /// the node's restart cycle (the node exited `code` and the wrapper is applying diff --git a/crates/core/src/bin/freenet.rs b/crates/core/src/bin/freenet.rs index d157decee3..1f80b9f027 100644 --- a/crates/core/src/bin/freenet.rs +++ b/crates/core/src/bin/freenet.rs @@ -556,12 +556,6 @@ async fn run_network_node_with_signals( Some((major, minor, patch)) } - // Once-per-process guard for the lockout report below. The lockout - // persists until an operator clears it, so this is a state to announce - // on each boot, not a 6-hourly repeat. - static LOCKOUT_REPORTED: std::sync::atomic::AtomicBool = - std::sync::atomic::AtomicBool::new(false); - const HARD_EXIT_TIMEOUT: std::time::Duration = std::time::Duration::from_secs(6 * 3600); // Stagger timer: random delay 0-4 hours before updating on decentralized discovery. const MAX_STAGGER_SECS: u64 = 4 * 3600; @@ -875,28 +869,46 @@ async fn run_network_node_with_signals( return; } } - } else if !LOCKOUT_REPORTED.swap(true, std::sync::atomic::Ordering::Relaxed) { - // The second state where the update machinery is silently - // OFF (#5244). This was `debug!`, which release builds - // compile out entirely (`release_max_level_info`), and the - // loud once-per-process warning in `check_if_update_available` - // is only reachable from the PEER-signal triggers — so on a - // node whose peers all share its version, nothing said this - // node would never update again. - // - // Once per process, mirroring that existing `LOCKOUT_WARNED` - // pattern: the condition is permanent until an operator - // acts, so repeating it every 6h forever is noise, and one - // line per restart is enough to find it. - eprintln!( - "Freenet: auto-update is LOCKED OUT on this node after repeated failed \ - installs (#3934). It will not detect or apply any further release until \ - you run `freenet update` manually to clear the counter." - ); - tracing::warn!( - "Periodic re-poll: skipped — auto-update locked out after repeated \ + } else { + // Once per process, not once per 6h tick: the lockout + // persists until an operator acts, so this is a state to + // announce on each boot rather than a recurring alarm. + // Mirrors the existing `LOCKOUT_WARNED` pattern in + // `check_if_update_available`. + static LOCKOUT_REPORTED: std::sync::atomic::AtomicBool = + std::sync::atomic::AtomicBool::new(false); + if !LOCKOUT_REPORTED.swap(true, std::sync::atomic::Ordering::Relaxed) { + // The second state where the update machinery is silently + // OFF (#5244). This was `debug!`, which release builds + // compile out entirely (`release_max_level_info`), and the + // loud once-per-process warning in `check_if_update_available` + // is only reachable from the PEER-signal triggers — so on a + // node whose peers all share its version, nothing said this + // node would never update again. + // + // Once per process, mirroring that existing `LOCKOUT_WARNED` + // pattern: the condition is permanent until an operator + // acts, so repeating it every 6h forever is noise, and one + // line per restart is enough to find it. + // Names the file as well as the command: the lockout can + // also be reached with the counter UNREADABLE, and in that + // state `freenet update` cannot clear it (the removal is + // best-effort and fails the same way the read did), so + // "run freenet update" alone would be advice that does not + // work. `--force` bypasses the gate for a one-off recovery. + eprintln!( + "Freenet: auto-update is LOCKED OUT on this node (repeated failed \ + installs, #3934, or an unreadable failure counter). It will not detect \ + or apply any further release until this is cleared: run `freenet \ + update` manually, or delete `update_failures` in the Freenet state \ + directory (~/.local/state/freenet on Linux). `freenet update --force` \ + bypasses the gate for a single run." + ); + tracing::warn!( + "Periodic re-poll: skipped — auto-update locked out after repeated \ failed installs (#3934); run `freenet update` to recover" - ); + ); + } } } } diff --git a/crates/core/src/tracing/tracer.rs b/crates/core/src/tracing/tracer.rs index 5132c64623..de9b51f242 100644 --- a/crates/core/src/tracing/tracer.rs +++ b/crates/core/src/tracing/tracer.rs @@ -789,15 +789,42 @@ pub fn init_cli_stderr_tracer(level: LevelFilter) -> anyhow::Result<()> { .from_env_lossy() .add_directive("moka=off".parse().expect("infallible")) .add_directive("sqlx=error".parse().expect("infallible")); - init_stdout_tracer( - level, - // The point of the function; see the docs above. - true, - use_json, - filter_layer, - None, - None, - ) + + // ANSI only for a human at a terminal. journald stores what it is given + // byte for byte, so colouring unconditionally would write escape sequences + // into the journal — which is the destination this whole function exists to + // reach. The file layers in `init_tracer` set `.with_ansi(false)` for the + // same reason. + let ansi = std::io::stderr().is_terminal(); + + use tracing_subscriber::layer::SubscriberExt; + let registry = Registry::default().with(filter_layer); + // `compact` rather than the `pretty` multi-line format `init_stdout_tracer` + // uses: one journal entry per event is far easier to read (and to grep) + // than an event split across several. + let result = if use_json { + tracing::subscriber::set_global_default( + registry.with( + tracing_subscriber::fmt::layer() + .json() + .with_ansi(false) + .with_writer(std::io::stderr), + ), + ) + } else { + tracing::subscriber::set_global_default( + registry.with( + tracing_subscriber::fmt::layer() + .compact() + .with_ansi(ansi) + .with_writer(std::io::stderr), + ), + ) + }; + // Returned, not `expect`ed. `init_stdout_tracer` panics here, which for a + // CLI would turn "a subscriber was already installed" into a failed update + // — trading a diagnostics problem for an outage. + result.map_err(|e| anyhow::anyhow!("could not install the CLI subscriber: {e}")) } fn init_stdout_tracer( diff --git a/crates/core/tests/update_command_is_not_mute.rs b/crates/core/tests/update_command_is_not_mute.rs index a06aaaf8d1..ad6aff2c26 100644 --- a/crates/core/tests/update_command_is_not_mute.rs +++ b/crates/core/tests/update_command_is_not_mute.rs @@ -1,27 +1,32 @@ //! Guards for #5244: the `freenet update` process must not be mute. //! -//! `set_logger` is installed only on the node path, so for a long time the -//! `freenet update` process ran with **no tracing subscriber at all** and every -//! `tracing::warn!` / `error!` in the installer was a no-op. The supervisor runs -//! it as `freenet update --quiet`, so sites whose only output was a `warn!` plus -//! a `!quiet`-gated `eprintln!` produced nothing at all in production — -//! including "installed the update but could not arm crash-loop rollback", -//! which is #4073's brick-safety machinery reporting that it is off. +//! `set_logger` is installed only on the node path, so the `freenet update` +//! process ran with **no tracing subscriber at all** and every `tracing::warn!` +//! / `error!` in the installer was a no-op. The supervisor runs it as `freenet +//! update --quiet`, so sites whose only output was a `warn!` plus a +//! `!quiet`-gated `eprintln!` produced nothing at all in production — including +//! "installed the update but could not arm crash-loop rollback", which is +//! #4073's brick-safety machinery reporting that it is off. //! -//! Two things need holding, and they fail in different ways, so they are tested -//! separately: -//! -//! 1. A subscriber exists in that process **and writes to stderr**. Tested by -//! running the real binary, because a subscriber is process-global state that -//! an in-process test cannot observe (the harness installs its own). -//! 2. It is wired via `set_cli_logger`, not via `set_logger` with a log dir. -//! That distinction is invisible to the runtime tests but decides whether the -//! output reaches the journal at all — see the pin's own docs. +//! `crates/core/src/tracing/tracer.rs::init_cli_stderr_tracer` carries the +//! rationale for the shape of the fix, including the two traps that produce a +//! version of it that looks done and changes nothing. #![cfg(unix)] -use std::path::PathBuf; +use std::path::{Path, PathBuf}; use std::process::Command; +use std::time::{SystemTime, UNIX_EPOCH}; + +/// The binary Cargo built for THIS test run. +/// +/// Deliberately not a hand-rolled `target/debug/...` lookup: those prefer a +/// debug binary even under `--release` and silently assert against whatever was +/// left there by an earlier build. For a test whose entire job is to prove the +/// current binary is not mute, testing a stale one is the "verification that +/// cannot fail" failure mode. `tests/graceful_shutdown_exit_code.rs` uses this +/// same env var for the same reason. +const FREENET_BIN: &str = env!("CARGO_BIN_EXE_freenet"); fn workspace_root() -> PathBuf { PathBuf::from(env!("CARGO_MANIFEST_DIR")) @@ -31,113 +36,127 @@ fn workspace_root() -> PathBuf { .to_path_buf() } -fn freenet_bin() -> PathBuf { - let target = std::env::var_os("CARGO_TARGET_DIR") - .map(PathBuf::from) - .unwrap_or_else(|| workspace_root().join("target")); - let debug = target.join("debug").join("freenet"); - if debug.exists() { - return debug; - } - let release = target.join("release").join("freenet"); - assert!( - release.exists(), - "freenet binary not found at {debug:?} or {release:?}. Build it first: \ - `cargo build --bin freenet`." - ); - release +/// Put the installer's GitHub cooldown far enough in the future that +/// `probe_latest_tag` defers, and near enough that it is not discarded as +/// implausible. +/// +/// This is what makes the test below deterministic and offline. Without it, +/// `update --check` reaches api.github.com, so the test would depend on the +/// network being up AND GitHub not rate-limiting a shared CI egress IP — and it +/// would spend real quota on every run, which #5102 went to some trouble to +/// conserve. With it, the command takes the cooldown branch, emits exactly one +/// known WARN, and exits before any HTTP. +fn arm_github_cooldown(home: &Path) { + let dir = home.join(".local/state/freenet"); + std::fs::create_dir_all(&dir).expect("create state dir"); + let until = SystemTime::now() + .duration_since(UNIX_EPOCH) + .expect("clock after epoch") + .as_secs() + + 600; + std::fs::write(dir.join("github_ratelimit_cooldown"), until.to_string()) + .expect("write cooldown"); } -/// The update process must emit `tracing` output, and it must go to stderr. +fn run_update_check(home: &Path, rust_log: Option<&str>) -> (String, String) { + let mut cmd = Command::new(FREENET_BIN); + cmd.args(["update", "--check", "--quiet"]) + .env("HOME", home) + .env("FREENET_TELEMETRY_ENABLED", "false") + // A developer with any of these set must not get a vacuous pass. + .env_remove("FREENET_DISABLE_LOGS") + .env_remove("FREENET_LOG_FORMAT") + .env_remove("FREENET_LOG_TO_STDERR") + .env_remove("FREENET_POST_STOP_EXIT_CODE"); + match rust_log { + Some(v) => cmd.env("RUST_LOG", v), + None => cmd.env_remove("RUST_LOG"), + }; + let out = cmd.output().expect("run freenet update --check"); + ( + String::from_utf8_lossy(&out.stdout).into_owned(), + String::from_utf8_lossy(&out.stderr).into_owned(), + ) +} + +/// A WARN from the update process must reach stderr. /// -/// Runs with `RUST_LOG=trace` so the assertion does not depend on the command -/// happening to log a warning: at TRACE the HTTP stack alone produces output on -/// any outcome, including an offline one (connection attempts are traced), so -/// this is not a network-dependent test even though `--check` does try to reach -/// GitHub. `--check` can never install, so it cannot overwrite the binary under -/// test. +/// The cooldown fixture guarantees exactly one WARN (`"Update check deferred"`, +/// `commands/update.rs`) on a path that makes no network call. Asserting on a +/// WARN rather than on TRACE matters: release builds set +/// `release_max_level_info`, which compiles `debug!`/`trace!` out entirely, so a +/// TRACE-based assertion would pass in CI's debug build and fail in the build we +/// actually ship. /// -/// Before the fix this produced zero bytes on both streams no matter what -/// `RUST_LOG` said, because there was no subscriber to read it. +/// Before the fix this produced zero bytes on both streams — there was no +/// subscriber to read the event. #[test] -fn the_update_process_emits_tracing_to_stderr() { +fn a_warning_from_the_update_process_reaches_stderr() { let home = tempfile::tempdir().expect("tempdir"); + arm_github_cooldown(home.path()); - let out = Command::new(freenet_bin()) - .args(["update", "--check", "--quiet"]) - .env("HOME", home.path()) - .env("RUST_LOG", "trace") - .env("FREENET_TELEMETRY_ENABLED", "false") - .output() - .expect("run freenet update --check"); - - let stderr = String::from_utf8_lossy(&out.stderr); - let stdout = String::from_utf8_lossy(&out.stdout); + let (stdout, stderr) = run_update_check(home.path(), None); assert!( - !stderr.trim().is_empty(), - "#5244: `freenet update` produced no tracing output at RUST_LOG=trace, so it has no \ - subscriber installed and every warn!/error! in the installer is a no-op — including \ - the ones that report crash-loop rollback failing to arm.\nstdout was:\n{stdout}" + stderr.contains("Update check deferred"), + "#5244: the update process emitted no WARN, so it has no subscriber installed and every \ + warn!/error! in the installer is a no-op — including the ones reporting that crash-loop \ + rollback failed to arm.\nstderr was:\n{stderr}\nstdout was:\n{stdout}" ); assert!( - stderr.contains("TRACE") || stderr.contains("DEBUG") || stderr.contains("INFO"), - "stderr had content but none of it looks like a tracing line; is something else \ - writing here?\nstderr:\n{stderr}" + stderr.contains("WARN"), + "the line reached stderr but without a level, so it came from somewhere other than the \ + subscriber:\n{stderr}" ); - // Diagnostics on stderr keeps the command's human-facing `println!` output - // on stdout parseable, and systemd records both. + // Diagnostics on stderr keeps the command's own output stream clean, and + // systemd records both. assert!( stdout.trim().is_empty(), - "tracing output must not land on stdout, which is the command's own output stream:\n\ - {stdout}" + "tracing output must not land on stdout:\n{stdout}" ); } -/// At its default level the update process stays quiet, so installing a -/// subscriber does not turn every `ExecStopPost` run of a crash-looping node -/// into a wall of journal noise. +/// The subscriber must not colour its output when stderr is not a terminal. +/// +/// journald stores what it is given byte for byte, so ANSI escapes would end up +/// in the journal this change exists to reach. `Command::output` gives the child +/// a pipe, never a tty, so this is the non-interactive case. #[test] -fn the_update_process_is_quiet_when_nothing_is_wrong() { +fn the_update_process_does_not_write_ansi_escapes_to_a_pipe() { let home = tempfile::tempdir().expect("tempdir"); + arm_github_cooldown(home.path()); - let out = Command::new(freenet_bin()) - .args(["update", "--check", "--quiet"]) - .env("HOME", home.path()) - .env_remove("RUST_LOG") - .env("FREENET_TELEMETRY_ENABLED", "false") - .output() - .expect("run freenet update --check"); + let (_stdout, stderr) = run_update_check(home.path(), None); - let stderr = String::from_utf8_lossy(&out.stderr); assert!( - stderr.trim().is_empty(), - "the default level must be WARN, not INFO: this runs on every non-clean stop, so an \ - INFO default would flood the journal of exactly the crash-looping node whose journal \ - we need to read.\nstderr:\n{stderr}" + !stderr.contains('\u{1b}'), + "ANSI escape sequences must not reach a non-terminal stderr — they would be stored \ + verbatim in the journal:\n{stderr:?}" ); } -/// The `Update` arm must install the CLI logger, and must NOT reach for -/// `set_logger` with a log directory. +/// The `Update` arm must install the CLI logger, at WARN, and must NOT reach for +/// `set_logger`. /// -/// This is the trap that makes a fix here look done while changing nothing: -/// `set_logger(None, None, Some(log_dir))` — the natural copy-paste from -/// `run_node` — sets `use_file_logging`, which routes everything into the -/// rolling log files. systemd captures stdout/stderr, NOT those files. Every -/// `warn!` would start "working" and the journal would stay exactly as blind as -/// it was, which is the same asymmetry that caused #5232 to be misdiagnosed. +/// Three separate regressions, none of which the runtime tests above can see: /// -/// The runtime tests above cannot see that difference: with a log dir they -/// would still find output on stderr in a terminal, because `init_tracer` adds -/// a console layer when stdout is a TTY. Only the wiring tells them apart. +/// * No subscriber — they would catch that, but this fails faster and says why. +/// * `set_logger(None, None, Some(log_dir))`, the natural copy-paste from +/// `run_node`, sets `use_file_logging` and routes everything into the rolling +/// log files. systemd captures stdout/stderr, NOT those files — the asymmetry +/// that caused #5232 to be misdiagnosed. A terminal would still show output, +/// so the runtime tests would stay green while the journal stayed blind. +/// * A promotion to INFO or DEBUG. Nothing on the `--check` path logs at INFO +/// today, so a runtime test asserting "quiet at the default level" would pass +/// under that mutation and prove nothing. The level is pinned here, where it +/// is a fact about the code rather than about which paths happen to log. /// -/// Scraped ACROSS files on purpose — this test lives in `tests/` and reads -/// `src/bin/freenet.rs`, so it can never be satisfied by its own assertion -/// strings, which is the self-matching failure mode documented in -/// `.claude/rules/bug-prevention-patterns.md`. +/// Scraped ACROSS files (test in `tests/`, source in `src/bin/`) so it can never +/// be satisfied by its own assertion strings, and with comments stripped so it +/// cannot be satisfied by a comment ABOUT the call — both failure modes are +/// documented in `.claude/rules/bug-prevention-patterns.md`. #[test] -fn the_update_arm_installs_the_cli_logger_and_not_a_file_logger() { +fn the_update_arm_installs_the_cli_logger_at_warn_and_not_a_file_logger() { let src = std::fs::read_to_string(workspace_root().join("crates/core/src/bin/freenet.rs")) .expect("read bin/freenet.rs"); @@ -148,17 +167,30 @@ fn the_update_arm_installs_the_cli_logger_and_not_a_file_logger() { let arm_end = arm .find("Some(Command::Uninstall(cmd))") .expect("the Uninstall arm must still follow Update; re-anchor this pin if it moved"); - let arm = &arm[..arm_end]; + let code: String = arm[..arm_end] + .lines() + .map(|l| match l.find("//") { + Some(i) => &l[..i], + None => l, + }) + .collect::>() + .join("\n"); assert!( - arm.contains("set_cli_logger"), + code.contains("set_cli_logger"), "#5244: the Update arm must install a subscriber, or every warn!/error! in the \ - installer is a no-op. Arm body:\n{arm}" + installer is a no-op. Arm code (comments stripped):\n{code}" ); assert!( - !arm.contains("set_logger("), + !code.contains("set_logger("), "the Update arm must use `set_cli_logger`, NOT `set_logger`: the latter's log-dir \ argument routes output into the rolling log files, which systemd does not capture, so \ - the journal would stay exactly as blind while the fix looked done. Arm body:\n{arm}" + the journal would stay exactly as blind while the fix looked done. Arm code:\n{code}" + ); + assert!( + code.contains("LevelFilter::WARN"), + "the level must stay WARN: this runs on every non-clean stop, so INFO would flood the \ + journal of exactly the crash-looping node whose journal we need to read. Arm code:\n\ + {code}" ); }