fix(update): give the mute update process a voice, and stop two safety states going unrecorded (#5244)

[sanity]

Problem

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. Full analysis in #5244.

Solution

1. Give the process a voice

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 Post-update probation commit is invisible in the journal, and has no regression test #5232. Every warn! would start "working" and the journal would stay 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.

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 one 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.

This fixes the class — on systemd. Every other tracing::warn! in the update path (the blocked-version refusal, the rate-limit exits, the install-gate counter) becomes visible without touching its call site.

It does NOT reach the field on Windows or the macOS tray path. spawn_update_command nulls stdio on every platform (load-bearing on Windows: the wrapper has called FreeConsole(), and inheriting invalid handles fails spawn() with os error 6). So under those supervisors the new subscriber output and both unconditional messages go to the bit bucket. Its doc comment also claimed nulling was harmless because "--quiet already suppresses all output", which this PR makes false; that comment is corrected here with the shape of the real fix recorded. The fix itself is deliberately NOT in this PR: it needs a log dir threaded through five call sites plus a stdio change on the code path behind three prior os-error-6 incidents, and I cannot exercise Windows or macOS from here. Tracked in #5244.

2. Two messages 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 also get an unconditional eprintln! — 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: --quiet controls chattiness, never whether a safety event is recorded.

A 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.

3. A fail-open on the lockout (second commit, reviewable on its own)

get_update_failure_count_at matched Err(_) => 0, catching every read error and not just NotFound. A counter made unreadable — EACCES, EIO, a directory in its place — read as "no failures" and silently reset the #3934 lockout.

The doc comment directly above the function already promised the opposite and named the threat ("an amplification vector for any process that can partially overwrite the file"). Only the parse path was defended; making the file unreadable defeats it more easily than partially overwriting it. read_github_poll_bucket_at, twenty lines away in the same file, already makes this distinction and explains why. Same file, same intent, opposite behaviour.

Note the states that reach this arm are anomalous ones — a chmod'd or wrong-owner file, a directory in its place, a failing mount — not the read-only/full state dir case, where reads still succeed or report NotFound. Treating them as fully-failed is self-healing: the gate re-reads every time and recovers the moment the file is readable again.

Why these compound

One bad state directory disabled all three guards at once: rollback never arms (silent), the failure counter can neither persist nor read back (silent, and fails open), and the line that would say the node is locked out was compiled out. The whole sequence ran without one line in the journal.

Testing

All deterministic and offline. The runtime tests seed the installer's GitHub cooldown file, so probe_latest_tag defers with exactly one known WARN before any HTTP — no network dependency, no quota spent, and the assertion is on a WARN rather than a TRACE so it survives release_max_level_info (an earlier revision asserted TRACE and would have passed in CI's debug build while failing on the build we ship).

Test	Holds
a_warning_from_the_update_process_reaches_stderr	A WARN reaches stderr and stdout stays clean. Before the fix both streams were empty whatever RUST_LOG said.
the_update_process_does_not_write_ansi_escapes_to_a_pipe	journald stores bytes verbatim, so escapes must not reach a non-tty.
the_update_arm_installs_the_cli_logger_at_warn_and_not_a_file_logger	The wiring AND the level — differences no runtime test can see, since a log-dir subscriber still shows output on a terminal, and nothing on this path logs at INFO so a "quiet at default" test would pass under a level promotion.
an_unreadable_failure_counter_does_not_reset_the_lockout	The fail-open. Uses a directory rather than a chmod so it fails for root too and cannot degrade into a no-op in a container.
an_unreadable_counter_is_never_persisted_as_a_count	The regression review caught: an unreadable counter must write nothing, or one transient EIO locks the node out permanently.
an_absent_failure_counter_reads_as_no_failures	The legitimate case still reads zero, so a fresh node is not born locked out.

Mutation-tested; each kills the guard that names it:

Mutation	Result
Remove the subscriber from the Update arm	runtime test FAILED, pin FAILED
set_logger instead of set_cli_logger (the trap)	runtime test FAILED, pin FAILED
Restore Err(_) => 0 on the counter	unit test FAILED

The second is the one worth noting: it is the implementation a reasonable person would write, it compiles, it makes warn! "work" — and both guards reject it, because the runtime test finds the output on stdout instead of stderr and the pin sees the wrong call.

The source pin is 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 documented in .claude/rules/bug-prevention-patterns.md.

Also verified by hand: RUST_LOG=trace freenet update --check --quiet now writes 24 lines to stderr and 0 to stdout, and is silent at the default level.

Not in scope

#5244 lists further sites in the same class that this PR does not touch — the install-gate threshold moment, the rate-limit denies with no log at any level, the swallowed counter write, and the !quiet-gated unsigned-release allowance. Most become visible through the subscriber; the ones with no logging at all still need their own lines.

Closes #5244

[AI-assisted - Claude]

[github-actions]

Rule Review: mostly solid, one misattached doc comment

Rules checked: git-workflow.md, code-style.md, testing.md
Files reviewed: 7

Warnings

• crates/core/src/bin/commands/auto_update.rs:1093-1109 — The new doc block for next_failure_count was inserted directly after the existing 2-line doc comment for record_update_failure_at, with no blank line separating them from the function next_failure_count now sits above. Because there's no blank line before next_failure_count (line 1109), rustdoc attaches the entire 17-line block to next_failure_count, not to record_update_failure_at (line 1117). Two effects: (1) next_failure_count's doc now opens with "Testable variant of record_update_failure that writes into an explicit directory. Missing directories are created on demand." — false for this function, which is a pure decision function that neither writes nor takes a directory; (2) record_update_failure_at, the function that actually does write into a directory, is left with no doc comment at all. (rule: code-style.md "WHEN writing documentation" — comments must accurately describe the item they're attached to)

Info

• commits.txt — All three commit subjects exceed the 72-character guideline (e.g. fix(update): give the update process a voice, and never mute two of them (#5244) is ~81 chars). Not CI-enforced beyond the conventional-commits prefix, but git-workflow.md calls for subjects under 72 chars. (rule: git-workflow.md "WHEN creating a commit message")
• crates/core/src/config.rs:333 (pub fn set_cli_logger) and crates/core/src/tracing/tracer.rs:404 (pub fn init_cli_stderr_tracer) — both are public APIs with thorough prose rationale but no # Errors/# Example sections called for by the public-API doc template. (rule: code-style.md "WHEN writing documentation")
• crates/core/src/bin/commands/auto_update.rs:1109-1115 — next_failure_count's saturating_add(1) boundary at existing == u32::MAX isn't exercised by the new tests, which otherwise cover NotFound/unreadable/parseable/garbage well. Low real-world impact (would require billions of accumulated failures) but is the one boundary case testing.md calls out that's missing. (rule: testing.md "Edge cases and boundary conditions")

---

Rule review against .claude/rules/. WARNING findings block merge. ⚠️ 1 warning(s) — fix or add review-override label

[sanity]

Review response — two lenses, one real regression, two tests that could not fail

Skeptical and code-first, both blind. Between them they found something I had introduced, two assertions that could not fail, and a claim in the body that was true only on Linux. All addressed in d45fe5a2f; the body is corrected too.

The regression I introduced

Making the counter read fail-closed was right for the gate — an unreadable counter suppresses updates 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 would have written 4 to disk and locked auto-update off permanently. 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. Extracting it is what makes it testable at all — the alternative is contriving a filesystem that reads one way and writes another.

I also had an unsupported claim in the doc comment and the body: "an unwritable state dir is what makes installs fail, so the counter is unreadable exactly when it is needed." Not true — EROFS/ENOSPC break writes; reads still succeed or report NotFound. The states that actually reach that arm are anomalous ones (chmod'd file, wrong owner, a directory in its place, a failing mount). Corrected in both places.

Two tests 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.
• The source pin scraped a region that included the arm's own comment block — one editorial pass from being satisfied by a comment about set_cli_logger. Comments are now stripped before matching.

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 throttling a shared CI egress IP, and spent real quota twice per run, which #5102 went to some trouble to conserve. They now seed the installer's GitHub cooldown file, so probe_latest_tag defers with exactly one known WARN before any HTTP. Deterministic, offline, and the whole file now runs in 0.01s.

That fixture fixed a subtler problem too: 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 third test in that revision, on RUST_LOG escalation, rested on a premise that the cooldown fixture invalidates (no HTTP means DEBUG adds nothing). Removed rather than contorted.

A claim that was true only on Linux

"This fixes the class" is systemd-only. spawn_update_command nulls stdio on every platform, 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 because "--quiet already suppresses all output" — which this PR makes false. Comment corrected with the shape of the real fix recorded.

Not fixed here, deliberately: it needs a log dir threaded through five call sites plus a stdio change on the code path behind three prior os-error-6 incidents, and I cannot exercise Windows or macOS from here. Shipping that untested is exactly the kind of change that has bitten this file before. Body now states the limitation; #5244 tracks it.

Also fixed

• ANSI into the journal. The CLI tracer went through init_stdout_tracer's pretty layer, which colours unconditionally and splits each event over several lines. journald stores bytes verbatim. 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 a failed subscriber install must not fail the update, while the only realistic failure panicked inside init_stdout_tracer. The new layer returns the error instead, so the promise holds.
• Operator advice that does not work. The lockout message said to run freenet update to clear the counter — which cannot clear what it cannot read. It now names the file and --force as well.
• CARGO_BIN_EXE_freenet instead of a hand-rolled target/debug lookup that would happily assert against a stale binary — the failure mode this test exists to prevent. LOCKOUT_REPORTED moved next to the branch it guards. Test env hygiene: FREENET_DISABLE_LOGS and friends are now removed so a developer's environment cannot produce a vacuous pass.

Not taken

• Rate-limiting the CLI subscriber. Raised because RUST_LOG=debug in the unit would produce unbounded output. An operator who explicitly asks for debug on a specific node should get it; the default is WARN and the process is short-lived.
• clear_update_failures_at's swallowed remove_file. Real, and it is why the lockout message now names the file directly — but it is one of the several swallowed writes brick-safety: freenet update installs no tracing subscriber, so rollback can fail to arm with no trace anywhere #5244 lists as unfixed, and fixing them piecemeal inside this PR would blur what it is.

[AI-assisted - Claude]