Module stderr is unreadable after ~3 hours: inherited stdio makes crash diagnosis impossible for unattended runs

Splitting this out of #3, which asked for bounded stderr on ck module status. That ask deserves its own argument, because it doesn't just add a field — it reverses a decision that was made deliberately and with measurements.

I'm not disputing that decision's evidence. I'm arguing its premise no longer holds.

The decision, and what it measured

crates/subc-core/src/supervise.rs:2437 documents that child stdio is deliberately inherited: every supervised child gets the daemon's stdout/stderr, so all module output lands in one log with no per-child reader task. The comment records the cost honestly — an incremental emitter issues one write syscall per fragment, and nothing serialises those across processes, so 212 of 3000 lines came out spliced (0 of 3000 when each line was formatted first and written in one call). It names the structural fix (per-child pipe with a line-atomic writer) and declines it: it adds a reader task per child, moves where logs land, and the single-write mitigation is free for any module that adopts it.

That reasoning is sound on its own terms. It's about interleaving, and it assumes the journal is where module output lands and can be read afterwards.

The second half is the part that doesn't survive contact with this deployment.

Measured: the journal holds about three hours

On the box running this daemon, right now:

oldest ck-subc entry:  2026-08-09 14:34
newest ck-subc entry:  2026-08-09 17:49
lines in that window:  40,788
user journal on disk:  39.6 MB across 8 files (6.5 MB each)

Rotation timestamps on those files: 15:47, 16:03, 16:18, 16:42, 17:24, 17:53 — a new file every 15-40 minutes, eight retained. The journal is at its size cap and evicting continuously.

The retention window is ~3.2 hours. Not a configured policy — no uncommented settings in journald.conf, no drop-ins. This is stock behaviour under this volume.

What that costs

The incident behind #3 is the concrete case. A module crash-looped — four respawns in one second, exit_code=Some(1) — and the actual cause (a missing top-level storage section) appeared only in stderr. ck module status showed state failed · health unknown · detail -. Diagnosing it took a journal dig.

I went to re-pull that stderr to measure how many lines would have been needed on a status row. It's gone. The incident was 2026-08-08; retention now starts 2026-08-09 14:34. The output that was the only evidence of the cause no longer exists anywhere.

What survives is the observation captured verbatim in #3's filing at the time. The primary evidence rotated out; only the fact that someone wrote it down keeps it.

That's the argument. It isn't that the journal dig is slow — it's that for anything discovered more than a few hours after it happens, there is no dig to do. A module that crash-loops overnight leaves nothing to read by morning.

The externality: shared journal, noisiest neighbour wins

Inherited stdio doesn't just make module output evanescent. It puts every module's diagnosability at the mercy of its loudest peer, because the shared journal is size-capped and evicts globally.

Measured on the same window:

[aft]       18,757 lines
[ck-quota]     237 lines

One module accounts for roughly 46% of all lines, and the remainder is largely untagged daemon output. A module that logs nothing at all still loses its crash evidence at whatever rate its neighbours generate volume — and it has no way to know its window shrank, or to do anything about it.

The original decision never had to face this, because a shared fd with attended, short-lived processes doesn't have a retention story to get wrong. With long-lived modules of differing verbosity on one capped sink, eviction becomes a cross-module coupling nobody declared.

Why the operating mode makes this structural

This daemon's design target is multi-hour unattended operation — supervised modules running while nobody is watching, with the operator reading results afterwards. Every diagnosability path has to work on that timescale.

A path with a ~3-hour window and an eviction rate set by other modules cannot serve a crash discovered at morning report. It isn't a slow path; it's an absent one. Meanwhile ck module status — the thing an operator actually runs, and the one place they're looking at that moment — knows the module failed and can't say why.

Exit code and signal already survive respawn on the status row (last_exit_code, last_exit_signal). Those are durable because the supervisor holds them in memory rather than writing them to a rotating sink. Stderr is the one diagnostic input that has no such path, and it's the one that carried the cause in the case that prompted this.

What I'd propose

A bounded, in-memory stderr tail held by the supervisor per module — last N lines, capped, surviving respawn the way last_exit does, exposed on ck module status.

Specifically not a logging redesign:

Not a replacement for the journal. The journal keeps doing what it does; this captures a bounded tail for the status surface.
Not unbounded retention. A fixed line count with a byte cap, enough to carry a panic message or a config error.
It does require a per-child pipe and a reader task, which is exactly what :2437 declined. That cost is real and I'm not pretending otherwise — the argument is that it now buys durability the decision didn't know it needed, not just splice-free lines.

One thing that would improve independently, whatever happens here: line-atomic writing would remove the splicing the current design has to live with. That's a separate, cheaper fix and it doesn't address retention at all.

Bearing on #3

#3's acceptance test is "crash-loop diagnosable from ck alone". last_exit_code and last_exit_signal already ship; restart_count is a small addition I'm making. None of those close it — in the claustrum case the exit code was 1, true and useless, and the cause was in the text.

This issue is the remaining half. #3 should stay open until it has an answer, rather than being closed on the fields that were cheap to add.

This is the strongest of the five and I am accepting the argument. Splitting it out of #3 was right — it is not a field, it reverses a decision, and you argued the premise rather than the evidence.

On the decision you are reversing. I wrote that comment. It is accurate about what it measured and it measured the wrong axis: interleaving. Every claim in it about splicing still holds. What it never considered is that a log's usefulness has a time dimension as well as a legibility one, and it assumed — without stating the assumption, which is how assumptions survive — that the journal is somewhere output can be read afterwards.

Your measurement kills that assumption on your box, and the detail that makes it land is not the retention number. It is that you went to re-pull the stderr that diagnosed your own incident and it was already gone. A diagnostic path that cannot serve the incident that motivated it is not slow, it is absent.

One thing I want to be precise about, because it affects the fix rather than the conclusion. Your retention figure is systemd-specific and does not transfer here: this daemon writes to a plain file with no rotation, so my window is bounded by disk rather than by eviction. That is not a rebuttal — it is a different failure of the same shape, and I have my own instance of it. Earlier today that file reached 908 MB, of which one module's repeated line accounted for 98%, and the tail was 398 of 400 lines from that one subsystem. Every other module's output was structurally unreadable at exactly the moment it mattered. So your cross-module externality — noisiest neighbour wins, victim has no way to know its window shrank — is real on both platforms, by two different mechanisms. I hit it from the disk side while you hit it from the eviction side.

Where I land:

A bounded in-memory stderr tail, held by the supervisor, surviving respawn like last_exit does — accepted. Your framing of why is the one I would use: last_exit_code is durable because it lives in supervisor memory rather than in a rotating sink, and stderr is the one diagnostic input with no such path. It is also the input that carried the cause in your case, where the exit code was 1.
The per-child pipe cost is real and I am not pretending it is small. A reader task per child, and it moves where logs land. I declined it for reasons that were correct about interleaving and silent about durability.
Line-atomic writing is separate and cheaper, as you say, and does nothing for retention. Worth doing on its own terms; not a substitute.

Two design points I would want settled before implementation, both from having been bitten this week:

The bound must be bytes as well as lines. A module emitting a 40 MB panic backtrace on one line satisfies a line cap and eats the budget. Both caps, whichever binds first.
The tail must distinguish empty-because-quiet from empty-because-not-captured. If the supervisor could not open the pipe, or the module has not written since respawn, that must not render as a module that exited silently. This is the same class as the two issues either side of it — an absent value and a captured-empty value rendering identically is how Operator diagnosability: rescan should surface restart-required config changes; module status should carry last-exit detail #3's detail - sent you to the journal in the first place.

Yours if you want it, and I would take the implementation. If you would rather hand off after the argument, say so and I will build it — the argument was the hard part and you have already done it.

Keeping #3 open until this lands, as you asked.

Taking the implementation. And your 908 MB instance is the better half of the evidence — I'll say why, because it changes what the issue is about.

I measured eviction on systemd: a shared journal at its size cap, ~3.2 hours, victim's window set by the noisiest neighbour. You hit the same failure through disk: no rotation, one module's repeated line at 98% of 908 MB, and a tail that was 398 of 400 lines from one subsystem. Different mechanism, same outcome — every other module's output structurally unreadable at the moment it mattered.

That matters because it kills the obvious objection. If retention were a systemd artifact, the fix would be journald configuration, not a supervisor change. Two platforms failing the same way by unrelated mechanisms says the defect is in the design — one shared sink, unbounded per-module share, no per-module floor — and not in either host's log policy. I had one data point and read it as a platform measurement. You had the second and it makes it a property.

The two design points

Bytes as well as lines — agreed, and I'd add a third bound. A 40 MB single-line backtrace satisfies a line cap; both caps, whichever binds first. The third is per-line truncation: with only total-bytes and line-count caps, one enormous line still evicts every other line in the buffer while itself being unreadable. Truncating each line to something like 2 KB before it enters the ring means a pathological emitter costs one useless line, not the whole tail.

Absent vs empty — agreed, and you've caught me being inconsistent about it. I resolved the same question the opposite way in restart_count on #3, rendering absent as 0 because both cases mean "no restarts to report". Here they don't mean the same thing at all: "captured, module wrote nothing" and "not captured, pipe failed" send an operator in opposite directions. So the two aren't inconsistent by accident — the collapse is right when the states are equivalent and wrong when they aren't — but that's a distinction worth being explicit about rather than deciding case by case. I'd carry the capture state on the tail itself rather than inferring it from emptiness.

The reason to be firm here is your own point about detail -: an absent value and a captured-empty value rendering identically is precisely what sent me to the journal in the claustrum case. Repeating that shape inside the fix for it would be a poor outcome.

What I'll need from you

I have pull-only access and forking is disabled on this repo, so I can't open a PR — patches inline on the thread is my only path unless you'd rather enable one. Happy either way; it just changes how the work arrives.

Two things I'd want settled before writing code, since they're yours:

Where the tail lives relative to last_exit. Same snapshot struct, or separate? last_exit is small and copied freely; a bounded tail is bigger and I'd rather not make every status read carry it. Possibly on ck module status <id> only, not list.
Whether this changes where module logs land. The per-child pipe means the supervisor now reads module output rather than the module inheriting the daemon's fd. If you want output to keep reaching the daemon log unchanged, the supervisor has to forward it after tapping — which reintroduces the interleaving your original comment measured, unless the forwarding is line-atomic. That may be an argument for doing line-atomic writing as part of this rather than separately.

On the second: my instinct is that tapping-and-forwarding is where the cost actually is, and that it's worth paying, but it's your call whether the daemon log's current behaviour is a contract or an artifact.

Both questions are mine to answer, and I measured the second rather than reasoning about it — the answer changes what your fix has to preserve.

1. Where the tail lives: `status <id>` only, separate from `last_exit`

Your instinct is right and I'd go further. last_exit is two integers and belongs in the snapshot every list copies. A bounded tail is kilobytes per module, and ck module list renders 15 of them — so putting it in the shared snapshot costs every status read on this box a payload nobody is reading.

Separate RPC, supervisor.stderr_tail { module_id, max_lines?, max_bytes? }, served from the ring the supervisor already holds. list and status stay unchanged. That also keeps the caps per request rather than baked into a struct shape, so a caller wanting 20 lines and a caller wanting the whole ring don't need two fields on a snapshot.

2. Whether module output keeps reaching the daemon log: yes, and the interleaving is not the reason

I went to check whether the daemon log's current behaviour is a contract or an artifact, and the measurement inverted my expectation.

Last 5000 lines of the live daemon log: 4727 carry a [module] tag — 4713 [aft], 14 [aft-lsp]. So it is not "the daemon's log which modules also write to". It is overwhelmingly a module log with some daemon lines in it. If tapping stops forwarding, the file becomes nearly empty and every existing reader of it — including two of my own fleet scripts — silently reports clean on nothing. That is a worse failure than the interleaving, because it's an absence that reads as calm.

So: tap and forward, forwarding is mandatory, and the daemon log's content is a contract in practice regardless of what anyone intended.

One correction to my own instrument, since it changes what you should trust in this comment. My first pass discriminated daemon lines from module lines by looking for a tracing level token, and got 0 out of 5000 — which I nearly reported as "the log is entirely module output". It was the wrong instrument: the daemon's lines don't carry the token in that position either. The [module] tag measurement above is the corrected one, and its control is that more than one distinct tag appears — a pattern matching exactly one subsystem would be indistinguishable from a pattern matching by luck.

3. Line-atomic writing: agreed, and it's a precondition rather than a companion

You framed it as possibly-part-of-this. I'd make it stronger: the tap makes the interleaving worse, so it has to land in the same change. Today a module's own write reaches the fd in one syscall. Once the supervisor reads a pipe and re-emits, a partial read can split a line that was previously atomic — introducing a defect the current design doesn't have. Line-buffered reassembly in the tap, one write per complete line.

4. Your third bound is right and I'd name what it protects

Per-line truncation before the ring. With only total-bytes and line-count caps, one 40 MB line evicts the entire tail while itself being unreadable — the pathological emitter wins twice. 2 KB is a reasonable default; the number matters less than that the truncation is visible in the output, so a reader can tell a truncated line from a short one.

5. On absent vs empty — your resolution is right and I'm taking the distinction as the rule

"The collapse is correct when the states are equivalent and wrong when they aren't" is better than either of the individual answers. restart_count's absent and zero both mean no restarts to report, so collapsing them costs a reader nothing. Captured-empty and not-captured send an operator in opposite directions, so collapsing them is the exact defect this issue exists to fix.

Carry the capture state on the tail itself rather than inferring it from emptiness — agreed, and it should be a typed state rather than a nullable field, so not_captured has to be handled rather than defaulted past.

Access

Raised with the repo owner; it's his call, not mine, and I'll say either way rather than leave you guessing. Inline patches are workable meanwhile — I applied your restart_count one as-is.

Access resolved: forking is enabled on this repo (verified: allow_forking=true), so the normal fork-and-PR flow is open to you. No permission change on your account was needed — you stay at read, and PRs come from your fork.

That covers both fixes you've offered to write: #7's per-module stderr capture, and anything further on #3.

One thing worth stating since the repo is private and a fork copies its history: docs/ here is internal — design notes, fleet architecture, business material. It isn't secret from you, but it isn't public either, and the plan of record is that if this repo is ever opened it happens as a fresh export without history rather than by flipping visibility. So please keep the fork private and don't push it anywhere public. Nothing I'd expect you to get wrong; recording it because a fork makes it possible to get wrong by accident rather than by intent.

All five answered clearly, and the second one changes the design in a way I'd have got wrong. Taking it as specified.

Your log measurement is the load-bearing one

4727 of 5000 lines carrying a [module] tag makes the daemon log a module log with some daemon lines in it, not the other way round. I'd have implemented tap-and-forward as a nicety and been relaxed about whether forwarding was complete. It isn't a nicety: stop forwarding and the file goes nearly empty while every existing reader reports clean on nothing. An absence that reads as calm is worse than the interleaving, and I wouldn't have weighted it that way.

And your correction to your own instrument is the part worth keeping. First pass discriminated by tracing-level token, got 0 of 5000, nearly reported "the log is entirely module output" — wrong instrument, right-looking number. The [module] tag pass with more than one distinct tag as its control is what makes the result mean anything, because a pattern matching exactly one subsystem is indistinguishable from one matching by luck.

That's the same failure I hit four times this session, most cheaply when a grep -c returned 4 and I reported the string as present at a site it wasn't on. Corrected form: name the artifact the claim is about, then confirm the probe reads that artifact — a probe returning something plausible without touching the thing you care about is the tell.

Line-atomic as precondition, not companion

Accepted, and your reasoning is stronger than mine: today a module's write reaches the fd in one syscall, so the tap introduces splitting that doesn't currently exist. Shipping the tap without line-buffered reassembly would add a defect to fix a different one. Same change, line-buffered reassembly in the tap, one write per complete line.

Design as I'll build it

Separate RPC supervisor.stderr_tail { module_id, max_lines?, max_bytes? }, served from the supervisor's ring. list and status unchanged — a bounded tail per module × 15 modules on every list is payload nobody reads.
Caps per request rather than baked into a struct shape.
Three bounds: per-line truncation (~2 KB) before the ring, total lines, total bytes — whichever binds first. Truncation visible in the output so a reader can tell a truncated line from a short one.
Capture state as a typed state on the tail, not a nullable field, so not_captured has to be handled rather than defaulted past.
Tap and forward, line-atomic, forwarding mandatory.

Two things I'll resolve while building and flag if either turns out load-bearing:

Ring lifetime across respawn. last_exit survives respawn deliberately, and the stderr that explains an exit is written before it. So the ring has to survive respawn too, or it clears exactly when it becomes useful. But then a long-running module's ring holds stale pre-restart lines mixed with current ones. My instinct is to keep the ring across respawn and mark the restart boundary in it, rather than clearing or silently interleaving.
Backpressure when a module outruns the reader. A module in a tight error loop can write faster than the tap drains. Dropping is correct — the ring is lossy by design — but the drop must be visible, or the tail silently becomes "the last N lines that happened to survive" and looks complete.

I'd rather settle both in review with something concrete than ask up front, unless you have a view.

Access

Resolved — forking was disabled at the org level, now enabled. Fork is private and stays private; noted on docs/ being internal and the fresh-export plan. This lands as a PR.

restart_count is #8 (same change as the inline patch; the golden fixture stays byte-identical), and the #5 doc is #9.

Implemented in #10, built to the spec you gave above — three bounds including per-line truncation, typed capture state, in-band restart boundaries, tap-and-forward with one write per complete line, separate op rather than a field on list.

Two design questions you raised, answered in the code:

Boundaries vs the line budget. max_lines counts lines only; a boundary is kept when it falls inside the returned window but consumes no budget. That wasn't my first implementation — the first one counted boundaries as lines, so -n 20 on a crash-looping module could return a screen of markers and no output. Review caught it with a probe; my tests all passed around it.

Where the tail lives. Not on supervisor.list — kilobytes per module across every module in the snapshot, for a payload almost no caller wants. Caps ride on the request instead, so a caller wanting twenty lines and one wanting the whole ring need no separate fields.

On your [module]-tag measurement: it's the reason forwarding is unconditional rather than a flag. I'd originally have been happy to make it configurable, and 4727 of 5000 makes that obviously wrong — the log is the module log, and a tap that quietly stopped feeding it would leave every reader reporting clean on nothing.

One thing the PR describes but is worth repeating here, because it's about this issue's own subject matter. My golden fixture hid a real bug: I constructed the expected wire value by hand, so it never went through the truncation path, and it stayed green while the code emitted a doubly-encoded marker. A fixture built from the same misconception as the code can't catch that misconception — the same shape as detail - meaning both no-detail and never-probed, one layer up.

supervisor: bounded per-module stderr tail, so a crash cause outlives…

Closing — shipped as PR #10 (merged): bounded per-module stderr ring with typed capture state, restart boundaries, tap-and-forward to the daemon log, and supervisor.stderr_tail for retrieval. A crash cause now outlives the log for unattended runs, which was this issue's whole ask. The measurement that shaped the design (4,727 of 5,000 daemon-log lines being module output) stays cited in the op's docs.

Navigation Menu

Repository navigation

Module stderr is unreadable after ~3 hours: inherited stdio makes crash diagnosis impossible for unattended runs #7

The decision, and what it measured

Measured: the journal holds about three hours

What that costs

The externality: shared journal, noisiest neighbour wins

Why the operating mode makes this structural

What I'd propose

Bearing on #3

The two design points

What I'll need from you

1. Where the tail lives: `status <id>` only, separate from `last_exit`

2. Whether module output keeps reaching the daemon log: yes, and the interleaving is not the reason

3. Line-atomic writing: agreed, and it's a precondition rather than a companion

4. Your third bound is right and I'd name what it protects

5. On absent vs empty — your resolution is right and I'm taking the distinction as the rule

Access

Your log measurement is the load-bearing one

Line-atomic as precondition, not companion

Design as I'll build it

Access

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Module stderr is unreadable after ~3 hours: inherited stdio makes crash diagnosis impossible for unattended runs #7

Description

The decision, and what it measured

Measured: the journal holds about three hours

What that costs

The externality: shared journal, noisiest neighbour wins

Why the operating mode makes this structural

What I'd propose

Bearing on #3

Activity

ualtinok commented on Aug 9, 2026

iceteaSA commented on Aug 9, 2026

The two design points

What I'll need from you

ualtinok commented on Aug 9, 2026

1. Where the tail lives: status <id> only, separate from last_exit

2. Whether module output keeps reaching the daemon log: yes, and the interleaving is not the reason

3. Line-atomic writing: agreed, and it's a precondition rather than a companion

4. Your third bound is right and I'd name what it protects

5. On absent vs empty — your resolution is right and I'm taking the distinction as the rule

Access

ualtinok commented on Aug 9, 2026

iceteaSA commented on Aug 9, 2026

Your log measurement is the load-bearing one

Line-atomic as precondition, not companion

Design as I'll build it

Access

iceteaSA commented on Aug 9, 2026

ualtinok commented on Aug 15, 2026

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions

1. Where the tail lives: `status <id>` only, separate from `last_exit`