The Cap That Never Ran: A Memory Fix That Fixed Nothing

A previous release added a cap on build logs. Ten thousand lines, eight megabytes, drop the oldest, leave a marker saying how much was thrown away. It shipped green. Under a load test that once OOM-killed the process at 7.3 GB, resident memory now peaked at 201 MB. Case closed.

Then a tester deployed an app whose Dockerfile ran RUN seq 1 2000000 and looked at the database afterward. The build_log column held 13.95 MB across 1,882,590 lines. No marker. The cap that had passed every test and bounded RSS in the load test had, on the path that actually persists logs, done nothing at all.

This is a story about where a value lives, and why "the test passes" and "the fix works" are different claims.

Two consumers, one stream

When sh0 builds a Docker image it reads the daemon's response frame by frame. Each log line goes two places:

rustif let Some(stream) = output.stream {
    let trimmed = stream.trim().to_string();
    if !trimmed.is_empty() {
        if let Some(tx) = log_tx {
            let _ = tx.try_send(trimmed.clone()); // (1) live view
        }
        logs.push(trimmed);                       // (2) capped accumulator
    }
}

Path (2) is a CappedLogs — a bounded deque that drops the oldest line when it exceeds 10k lines or 8 MB, counting the drops. That is the cap the previous release added, and it is correct. build_image returns it as BuildResult.logs.

Path (1) is an mpsc channel feeding a background task — the "flusher" — that writes to the database every 500 ms so the dashboard can tail the build live.

Here is the whole bug, in the flusher:

rustupdate_deployment_field(&pool, &dep_id, move |dep| {
    let existing = dep.build_log.clone().unwrap_or_default();
    dep.build_log = Some(format!("{existing}{batch}\n"));
}).await.ok();

Every tick: read the entire column, clone it, append the new batch, write it back. There is no cap anywhere on this path. The CappedLogs from path (2) — the one with the bound and the marker — is returned to the caller on success and, for the persisted log, ignored. The database is fed by the channel, which is uncapped.

So the cap existed. It was well-written and well-tested. It just guarded a value that the success path threw away.

Why every check missed it

• The unit tests exercised CappedLogs directly. They proved the deque bounds itself. They could not see that the pipeline persists a different string.
• The load test measured RSS, and RSS was bounded — because at 14 MB of accumulated log the per-tick clone transient is ~28 MB, comfortably inside "a couple hundred MB." Memory looked fine precisely because the row wasn't yet catastrophically large; the growth is linear and unbounded, but a few-second build never reaches the cliff. The metric that had caught the original incident was the wrong metric for this defect.
• The marker assertion — a checklist item that grepped the persisted log for [sh0: N earlier lines dropped] — could never pass on a successful build, because that string only exists on the discarded Vec. It had been quietly failing since it was written.

Three green signals, one 14 MB row. None of the signals were lying; they were all answering a question next to the one that mattered.

The fix: cap the thing you keep

The correct move is to make the flusher itself the bounded accumulator. The three streaming call sites (git, Dockerfile, upload) had drifted into three byte-identical copies of the flusher, so they collapsed into one helper, and the append became a re-cap:

rustasync fn flush_build_log_batch(pool: &Arc<DbPool>, dep_id: &str, pending: &mut Vec<String>) {
    if pending.is_empty() { return; }
    let batch = redact_secrets(&std::mem::take(pending).join("\n"));
    update_deployment_field(pool, dep_id, move |dep| {
        let existing = dep.build_log.take().unwrap_or_default();
        dep.build_log = Some(cap_build_log(format!("{existing}{batch}\n")));
    }).await.ok();
}

cap_build_log is a pure function: within budget it returns the string untouched (normal builds are unaffected, prefix [STEP] lines preserved); over budget it drops the oldest lines and prepends a single marker, folding any prior marker's count so re-capping each tick accumulates rather than stacks. Pure means it is trivially testable for the property that actually matters — the persisted string is bounded — instead of a property next to it. The tests now assert on the output of the function the pipeline really calls: ≤ 10,001 lines, < 8 MB, marker present, count accumulates.

The honest residual

There is a second loss the fix does not fully account for. When the channel is full, try_send drops the line silently — under the 2M-line spew, about 117k lines vanished before reaching the flusher. Attributing those exactly would mean threading an atomic counter through three crates' function signatures.

We didn't. The cap marker already announces "1.9M lines dropped to bound memory," so nothing reads as silently complete, and the High-severity problem — the unbounded row and its re-serialization on every API call — is closed. Counting the backpressure drops to the line is real work for a number no user decision depends on. That trade-off is written down in the issue and the release notes, not left for someone to rediscover. A fix that overreaches is its own kind of debt.

What to take from it

A cap is only as good as its position in the dataflow. "Is the value bounded?" is not the same question as "is the value we persist bounded?" — and when a stream fans out to two consumers, a guard on one branch says nothing about the other. When you add a bound, write the test against the exact value that leaves the system, not the nearest convenient proxy. The proxy will pass. The system will still grow.