Skip to content

refactor(logging): one logcode-to-stream funnel mirroring rwrite - #7252

Draft
oferchen wants to merge 2 commits into
masterfrom
fix/logcode-stream-funnel
Draft

refactor(logging): one logcode-to-stream funnel mirroring rwrite#7252
oferchen wants to merge 2 commits into
masterfrom
fix/logcode-stream-funnel

Conversation

@oferchen

@oferchen oferchen commented Aug 7, 2026

Copy link
Copy Markdown
Owner

The defect, stated structurally

#352/#7236 and #357/#7242 were not two bugs. They were one missing funnel, found twice in independent code paths, and a per-fix regression test on either would not have caught the other.

Upstream cannot have this defect. Every message reaches a stream through rprintf (log.c:406) or rsyserr (log.c:453) and lands in rwrite (log.c:251), the sole function that picks a FILE *.

Correcting the premise (it makes the case stronger, not weaker)

The brief said "zero direct fprintf(stderr,...) in the message path". Measured, that is not literally true — there are 47 in the tree. The accurate shape is more useful:

count
rprintf(F*) call sites funnelling into rwrite 606 (FINFO 240, FERROR 217, FLOG 59, FERROR_XFER 32, FCLIENT 22, FWARNING 11, FERROR_UTF8 1, +24 computed)
direct fprintf(stderr) in the real message path 5
...in standalone helpers/test binaries (tls.c, t_*.c, testrun.c, getfsdev.c) 42

All five exceptions are principled and every one exits immediately:

  • log.c:325rwrite's own bad-logcode arm, then exit_cleanup(RERR_MESSAGEIO).
  • clientserver.c:1520,1563 — fork failure and config-parse failure, both before logging exists.
  • io.c:596,614 — reporting that the message subsystem's own circular buffer is undersized, then exit_cleanup(RERR_PROTOCOL).

So the rule is not "never write to a stream directly". It is: the funnel decides, except where the funnel is unavailable or is itself broken — and there you exit. A blanket ban would be un-mirrorable and would push a panic path through a broken funnel.

What oc actually had

crates/logging owns LogCode and documents the routing rule in nine separate doc comments. It implements it zero times. The only implementation was client_stream() in crates/cli/src/frontend/progress/diagnostic.rs — a leaf crate.

The shared crate documented the rule; a leaf owned the only implementation. Every other crate that needed it had to re-derive or guess. That is the whole mechanism behind two independent instances.

The change

logging::message_stream is now the single place a diagnostic message's destination is chosen, mirroring rwrite's dispatch in upstream's own order (the normalisations happen before the switch, which is load-bearing). The cli copy is deleted and its renderer delegates.

Two things the existing mapper did not model, both load-bearing:

  • quiet suppresses FINFO inside rwrite (log.c:318-319). oc folds --quiet into verbosity = 0 at parse time (cli/frontend/arguments/parser/entry.rs:780), which only silences verbosity-gated output — a non-gated FINFO still prints. That is exactly open task Add protocol version FromStr parity tests #346, and the funnel now has the seam for it.
  • msgs2stderr is a tri-state, not a bool (options.c:98, default 2). rwrite's stream default keys on == 1 (log.c:253) while the server-forwarding gate distinguishes all three (log.c:328). Modelling it as a bool at the one canonical site would have baked a lossy representation into the choke point — the same mistake class as everything else this task exists to prevent.

Proof: every assertion made to fail

Non-negotiable, so here it is. Each mutation reintroduces a real defect; each hits its intended assertion; green restores.

mutation tests red
warning-class routed to stdout — the #352/#357 defect 2
unknown code silently defaults to stdout 1
FCLIENT normalisation dropped 2
msgs2stderr collapsed to a bool 1
cli renderer re-derives the rule for FWARNING 5

The class test quantifies over the full quiet × msgs2stderr × log_destination cross-product, so a rule that only holds in the default configuration cannot pass. The warning-class list is derived independently from rwrite's structure rather than from this module — that is what makes it an oracle instead of a restatement.

The cli test that pinned the classification in the leaf is replaced by one asserting the renderer delegates: for every code, where the bytes actually land agrees with what the funnel decided. Re-deriving the rule there, however faithfully, fails it.

The site census (the deliverable, and it revises the ~400 figure)

Measured on this tree, crates/*/src only, excluding test files, #[cfg(test)] bodies, the test-support crate, and doc-comment examples:

count
real production stream-write sites 92
excluded: doc-comment examples (/// println!(...)) 89
excluded: inside #[cfg(test)] 89
excluded: test files 942

Not ~400. That figure counted test code and doc examples. Roughly 5 of the 92 are io::stderr() used as an is_terminal() probe rather than a write.

By crate: engine 18, transfer 15, rsync_io 15, daemon 14, metadata 13, core 11, platform 3, protocol 2, batch 1, cli 0.

Diagnostic vs payload: the payload half is small — essentially the itemize row emitters (transfer/receiver/itemize.rs, core/client/remote/itemize_sink.rs) plus a couple of listing paths, call it ~9 sites. The remaining ~78 are diagnostic: metadata's "cannot preserve X" warnings, daemon listener/config warnings, ssh/auth diagnostics, engine env-var parse warnings, platform privilege-drop warnings (#157).

That answers the scoping question directly: the payload half is not worth a separate campaign. It is ~9 sites and can be folded in cheaply once the diagnostic half is routed. The funnel is shaped to absorb it — MessageStream already carries the LogOnly/Suppressed outcomes payload routing would need.

Scope

Diagnostic routing only, and this PR routes one consumer (the cli diagnostic queue) onto the funnel. The remaining ~78 diagnostic sites are follow-on work, now mechanical: each becomes a call to one function instead of a judgement call.

This PR is deliberately the structural half — one definition, one class test, proven red. Landing the funnel before the migration means every subsequent site moves onto something already gated.

Verification

  • cargo fmt --all -- --check clean
  • cargo clippy --locked --workspace --all-targets --all-features --no-deps -- -D warnings clean
  • cargo nextest run --workspace --all-features -E 'package(logging) or package(cli) or package(core) or package(transfer) or package(daemon)'11359 passed, 81 skipped

#352/#7236 and #357/#7242 were not two bugs. They were one missing funnel,
found twice in independent code paths, and a per-fix regression test on
either would not have caught the other.

Upstream cannot have this defect structurally. Every message reaches a
stream through rprintf (log.c:406) or rsyserr (log.c:453) and lands in
rwrite (log.c:251), which is the sole function that picks a FILE *. That is
606 rprintf(F*) call sites against one chooser.

The "zero direct fprintf(stderr)" framing is not quite right and the real
shape is more useful: 47 exist in the tree, but only 5 are in the message
path - rwrite's own bad-logcode arm (log.c:325), two pre-log_init failures
(clientserver.c:1520,1563), and two reports that the message subsystem's own
circular buffer is undersized (io.c:596,614). Every one of the five exits
immediately. So the rule is not "never write to a stream directly", it is
"the funnel decides, except where the funnel itself is unavailable or
broken, and there you exit".

oc had the rule written down in nine doc comments on LogCode in
crates/logging and implemented exactly once, in
crates/cli/src/frontend/progress/diagnostic.rs - a leaf crate. The shared
crate documented the rule; a leaf owned the only implementation. Every other
crate that needed it had to re-derive or guess.

This moves the decision into crates/logging as `message_stream`, the single
place a diagnostic message's destination is chosen, and collapses the cli
copy onto it.

Two things the existing mapper did not model, both load-bearing in rwrite:

- `quiet` suppresses FINFO INSIDE rwrite (log.c:318-319). oc folds --quiet
  into `verbosity = 0` at parse time (cli parser/entry.rs:780), which only
  silences verbosity-gated output; a non-gated FINFO still prints. That is
  the mechanism task #346 needs and the funnel now has the seam for it.
- `msgs2stderr` is a TRI-state (options.c:98, default 2), not a bool.
  rwrite's stream default keys on `== 1` (log.c:253) while the
  server-forwarding gate distinguishes all three (log.c:328). Modelling it
  as a bool at the one canonical site would have baked a lossy
  representation into the choke point.

The class test is six assertions on one function, quantified over the full
quiet x msgs2stderr x log_destination cross-product, so a rule that only
holds in the default configuration cannot pass. The warning-class list is
derived independently from rwrite's structure rather than from this module,
which is what makes it an oracle instead of a restatement.

Proven red, each mutation hitting its intended assertion and green
restoring:
  warning-class routed to stdout (the #352/#357 defect) -> 2 fail
  unknown code silently defaults to stdout               -> 1 fail
  FCLIENT normalisation dropped                          -> 2 fail
  msgs2stderr collapsed to a bool                        -> 1 fail
  cli renderer re-derives the rule for FWARNING          -> 5 fail

The cli test that pinned the classification in the leaf is replaced by one
that asserts the renderer DELEGATES: for every code, where the bytes
actually land agrees with what the funnel decided. Re-deriving the rule
there, however faithfully, fails it.

Diagnostic routing only. Payload output (listings, --list-only, help,
itemize rows) is untouched and the funnel is shaped to absorb it later.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant