feat: give the output of a job a limit, and keep both of its ends

[stephenc]

Closes part of #10 (the item "a limit on the output of a job").

What it does

A new [logs] section with max_bytes. It is the space that ONE STREAM of ONE
JOB can use, and it accepts the size syntax of the other fields
(max_bytes = "64MB"). "0", "none" and "unlimited" remove the limit.

[logs]
max_bytes = "32MB"

A job that writes more keeps the first part of its output and the last part,
with a line between them:

1
2
3
[qex] The output of this job reached the limit `[logs] max_bytes` = 64KB. qex keeps the last part of the output beside this file. It writes that part here when the job stops.
[qex] ---- 1.2MB and 189773 line(s) of the output are not in this file ----
[qex] The limit is `[logs] max_bytes` = 64KB. qex kept the first 16KB and the last 46KB. To keep more, make max_bytes larger in the configuration file.
193272
...
200000

qex status, qex logs and qex logs --follow all say what went, and
status.json holds the numbers in the new field logs_dropped. A job never
fails because of the limit.

What I decided, and why

The supervisor writes the file through a pipe. It does not correct the file
afterwards. The requirement is that the disk cannot fill, so the limit must
operate while the job writes. A correction afterwards lets the disk fill first,
which is the fault itself. The supervisor thus gives the job Stdio::piped()
and copies each stream in a thread of its own.

The default is 32MB for each stream. No limit is not an acceptable default,
because that is the fault. A real build or test run writes a few megabytes, so
32MB never touches an honest job. It is also small enough that a day of runaway
jobs costs some gigabytes and not some hundreds of gigabytes. A user who needs
more writes one line.

The tail stays on the disk, and not in the memory. The supervisor puts
itself in the cgroup of the job, so memory that the supervisor holds counts
against the memory claim of the job. A tail of 24MB in memory would stop a job
that operates at its claim, and qex status would show an out-of-memory event
that the job did not cause. qex writes the overflow into a circular file of a
fixed size (stdout.log.tail): the writer returns to the start when it reaches
the end, so that file never grows, and this module holds one buffer of 64KB.
The file goes when the job stops, and qex clean deletes the directory anyway.

The parts of the limit: head = max/4, tail = the rest, less 2KB for the two
notes. The head file and the circular file are the only files, so the disk
that one stream uses stays below max_bytes AT EACH MOMENT, and not at the end
only. The tail is three times the head, because the head needs the start of the
output only and the failure is at the end.

A note goes into the file when the limit is reached, and not at the end
only. A reader who opens the file while the job operates would otherwise see
a file that stops at the head and reads as complete. qex logs --follow gives
that line as it arrives. The follower then sees no new line until the job
stops, and the last part arrives then. That is documented.

The limit belongs to the stream of the job, and not to one attempt. A job
with --retries adds to the same file. When a later attempt goes above the
head budget, qex counts and removes what is above it, so three attempts do not
hold three times the limit.

A fault of this code never fails the job. A write that the disk refuses
goes into supervisor.log and the copy continues to read the pipe, so the job
never blocks. If a process that left the process group holds a pipe open, the
supervisor waits 30 seconds, writes the record, and says that the last part of
a log file can be missing. A record that arrives is worth more than a wait with
no end.

The refusal of a limit below 16KB. A limit of a few hundred bytes cannot
hold a head, a tail and the note, so the configuration refuses it and names the
remedy ("0" for no limit).

What I measured

With max_bytes = "64KB", a job that writes seq 1 500000 (about 3.4MB, 50
times the limit):

• stdout.log is 63891 bytes. It holds the line 1 and the line 500000, and
  not the line 250000.
• logs_dropped says 1.2MB and 189773 lines for the 200000-line variant that I
  ran by hand; the job exits with its own code and the state is completed.
• No file stays beside the log file.
• The unit test the_disk_stays_below_the_limit_while_the_job_writes measures
  every file of the directory after each 100 lines, so a limit that operates
  only at the end fails it.

What I tested

New unit tests in src/logcap.rs (both ends stay, the disk stays below the
limit during the run, the temporary file goes, output below the limit is
untouched, no limit keeps everything, a reader sees the limit before the job
stops, a second attempt shares the limit, one write larger than the tail keeps
its end, the parts fit the limit) and in src/config.rs (a default limit
exists, the sizes and the words parse, a limit that is too small is refused).

New end-to-end test
a_job_that_writes_more_than_the_limit_keeps_the_head_and_the_tail.

cargo fmt --all
cargo clippy --all-targets -- -D warnings     clean
cargo test --bins                             184 passed
cargo test --test e2e -- --test-threads=2      72 passed

Documentation: docs/reference.md, qex help config, qex help output, the
status JSON Schema (logs_dropped), and a line in qex config show.
Cargo.toml moves to 0.8.0.

🤖 Generated with Claude Code

https://claude.ai/code/session_01KNvagiMEU3myn8EXGaGEM9

[stephenc]

Review addressed in 2141fe8. All six items are fixed, and each of the two blocking defects has a unit test and an end-to-end test.

BLOCKING 1 — a tail with no line end went completely. Ring::walk now takes the trim decision from the caller, and finish() computes it with the new Ring::has_line_end(): qex removes the incomplete first line only when the tail HOLDS a line end. When it does not, the tail stays whole and the file says so:

[qex] The last part has no line end in it. The text that follows starts in the middle of a line.

Measured with max_bytes = "1MB" and dd if=/dev/zero bs=1M count=200 | tr "\0" "A"; printf ZZEND: stdout.log is 1,047,024 bytes (the limit is 1,048,576), it ends with ZZEND, and logs_dropped.stdout_bytes is 208,668,677. Before the fix the same job gave the head only.

BLOCKING 2 — a retry removed output that fits in the limit. Parts gains fill (max less the room for the notes). The bytes go into the file itself until the stream passes max, and only then does qex cut back to the head budget and open the circular file. A job that writes less than max_bytes therefore keeps every byte in one piece, with no note, and so does a second attempt.

Measured with max_bytes = "1MB", --retries 1, two attempts of about 228KB: the file is 457,827 bytes, it holds no [qex] note, both attempts keep their last line, and logs_dropped is null. This also fixes item 6: the --- attempt 2 --- mark is present.

While writing the test for this I found one more fault of my own in the same place: after the cut back to the head budget, head_len was below fill again, so the next bytes filled the file a SECOND time and the file then held the middle of the output in place of its end. write() now closes the head for ever once the stream passes the limit. The unit test the_disk_stays_below_the_limit_while_the_job_writes catches it, at 35,041 bytes against a 32,768 limit.

3 — a tail file that the machine refuses. A new overflowing flag replaces the test of the ring, so the note is written one time whatever follows; and finish() now adds the overflow to dropped on that path, so the record says that the output is not complete. Test: a_tail_file_that_the_machine_refuses_still_stops_the_output makes the tail path a directory (EISDIR) and requires one note, a file inside the limit, and a count above zero.

4 — the escape hatch left an orphan and reported nothing. On a timeout the supervisor now removes stdout.log.tail and stderr.log.tail (an unlink does not stop a copy that continues), and it puts the cause in status.error, where qex status shows it. The collection loop also keeps the counts of a stream that did report. I could NOT reproduce the orphan on this machine: with sh -c 'seq 1 300000; setsid --fork sleep 45 & exit 0' the escaped child did not hold the pipe here, and the job completed at once with a full logs_dropped. The fix is therefore by inspection of that path only.

5 — the 30 second budget covered the merge. pump now reports Report::Eof before it writes the tail, and Report::Done after. The supervisor keeps the short limit for the end of the output, which a process outside the process group can hold open for ever, and gives the copy that follows its own long limit. A merge of some gigabytes no longer cuts the log of a well-behaved job.

7 — documentation. docs/reference.md and qex help output now have "What the job sees": the output is a pipe, lseek gives ESPIPE, stat gives a FIFO, two children that write more than 4096 bytes in one operation can mix in the middle of a line, isatty does not change, and a program that needs a regular file gets one with qex submit -- sh -c 'my-program > out.txt'.

New tests: output_with_no_line_end_keeps_its_last_part, a_second_attempt_that_fits_the_limit_loses_nothing, a_tail_file_that_the_machine_refuses_still_stops_the_output, a_job_that_writes_one_enormous_line_keeps_its_end (e2e), a_retry_that_fits_the_limit_keeps_the_output_of_both_attempts (e2e). the_disk_stays_below_the_limit_while_the_job_writes stays: it is the test that holds the real-time promise.

cargo fmt --all
cargo clippy --all-targets -- -D warnings   clean
cargo test --bins                           187 passed; 0 failed
cargo test --test e2e -- --test-threads=2    74 passed; 0 failed (35.79s)

[stephenc]

Second review addressed in e4f7d2d.

BLOCKING — qex logs --follow lost everything after the truncation point. The follow loop now keeps a high_water mark for each stream. When metadata().len() falls below it, the command writes a notice, seeks to the new end, and clears the partial line:

... qex reached the limit `[logs] max_bytes` and removed the middle of this file.
    This command continues at the new end of the file. Read the file again when the job stops.

The new length becomes the new reference — without that, the test would find the file short at every turn and the merged tail (which is smaller than the pre-cut length) would never reach the reader.

A job can also pass the limit and stop between two reads of the loop, and then there is no short file to find. For that case the loop reads logs_dropped from the record when the job reaches a terminal state and gives the notice there. A reader now always gets a word, by one path or the other.

New e2e test follow_does_not_lose_the_output_of_a_job_that_passes_the_limit. The job writes ~61KB (under the limit), waits 2s so the follower reaches that position, writes 6KB more (the file is cut to ~17KB), waits, then writes THE-FINAL-LINE. The final file is far smaller than the follower's old position, so the defect is visible. I confirmed the test discriminates: with the length test disabled the follower's output stops at line-177 and THE-FINAL-LINE is absent; with it, the test passes.

Late line end cost almost the whole tail. Ring::has_line_end became Ring::first_line_end, which gives the position. qex now removes the incomplete first line only when it is at most one quarter of the tail budget; in every other case it keeps the fragment and writes [qex] The text that follows starts in the middle of a line. Measured with a 64KB limit, 40000 lines then 4000 \r progress writes then BUILD FAILED: the tail is 47,104 bytes and holds the progress run before the failure (it was 57 bytes), and the file is 63,953 B against the 65,536 limit.

logs_dropped was null when both pumps were cut off. New field LogsDropped.incomplete (in the struct, the status schema, qex status and the qex logs notice). The supervisor sets it on the escape-hatch path and now writes the record whenever drops.any(). The text says that the output did not close, that the counts are the counts that arrived, and that the file can be missing more. Unit test a_log_file_that_qex_could_not_complete_gives_a_notice.

A tail that did not wrap started mid-line with no warning. The test is no longer ring.wrapped; it is now "qex removed bytes between the head and the tail" (ring.wrapped || dropped.bytes > 0), which is the true condition. Unit test a_tail_that_starts_in_the_middle_of_a_line_says_so.

The cliff below max_bytes. Prose only, as advised. docs/reference.md and qex help output now say "less than max_bytes, less the room that qex keeps for the notes (2KB)", and add why the cliff exists: qex writes the file while the job runs, so at the moment of the cut nobody knows how much output follows. The docs also now state that the log file becomes shorter at that moment and that --follow handles it.

the_disk_stays_below_the_limit_while_the_job_writes is unchanged and still present.

cargo fmt --all
cargo clippy --all-targets -- -D warnings   clean
cargo test --bins                           190 passed; 0 failed
cargo test --test e2e -- --test-threads=2    75 passed; 0 failed (61.23s)

Disk after the large-write experiments: 356G free on the state volume, and every experiment directory was removed.