fix: close per request, soak the daemon, kill five soak-found leaks (Tasks 5+6)

- Task 5: net.close on every path out of a serve iteration (400
  included) and the listener on stop; measured 4 -> 54 fds over 50
  requests before, 4 -> 4 over 200 after. The loop's comment claimed
  the iteration-end drop IS the close -- wrong twice (net.Conn is a
  scalar, and a drop would not close an fd); it now says what is true
- Task 6: LW_SOAK=<seconds> in the acceptance script -- each mode under
  load, resident+descriptor deltas against a WARMED baseline (warm-up
  includes load: cold-to-high-water is not growth), 256 KiB / zero
  tolerance; LW_ACCEPT_WOVM soaks another build
- the soak caught ~1.6 MiB/min of in-arena leaks ASan cannot see (the
  arena is one allocation to LeakSanitizer); an arena size-class
  census + pointer trace attributed five bugs:
  - jparse_string sized every decoded string at "rest of the input"
    and relabeled len after -- blocks filed on free lists their next
    allocation never reads (fs.read_all's mis-size, again); copy out
    exact, free at the taken size
  - `!=` never dropped fresh operands (headers["authorization"] !=
    "Bearer ${key}" leaked both sides per request); Ne now reaps as Eq
  - an Int interpolation segment is a fresh int_to_text, not a borrow;
    is_borrowed_value_t asks the segment's type
  - json.encode(Ctor{...}) had no owner -- record + both field copies
    leaked per tool call; its bespoke lowering now drops the argument
  - a discarded expression statement owns its result: `pop(lines);`
    leaked the popped element; reader builtins excluded
- after: arena live bytes flat per request on every handler; release
  soak 30 s per mode watch 0 / run 0 / mcp +20 KiB, descriptors flat;
  ASan build flat at 14600 KiB across 601686 requests in 90 s past its
  ~1200-request quarantine warm-up
- gates: oop-accept ALL CRITERIA MET, oop-e2e 71/0, woc-test 565/0,
  wovm-test green, log-watcher 7/0 (soak opt-in, fast path <1 min)

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
shoney.arickathil 2026-08-15 00:32:49 +02:00
parent d30ad04bd9
commit e1f31cf75d
7 changed files with 243 additions and 34 deletions

View file

@ -119,6 +119,16 @@ register holds a **copy**, so it needs no second copy at a boundary and does
need a drop), a loop's iterable, the record a projection reads a field of, and
any of those escaped by a `return` from inside the statement that built them.
The soak (Task 6) widened the list with four more, all the same sentence:
a `!=`'s operands (its lowering is separate from `==`'s and missed the reap);
an Int-typed interpolation segment (`"${resp.status}"` LOOKS like a place
wrapped in Interp, but lowers to a fresh int_to_text — is_borrowed_value_t
asks the type); the argument of `json.encode` (its bespoke lowering bypassed
the stdlib-member drop); and a discarded expression statement (`pop(lines);`
REMOVES the element — the caller owns what it then ignores). The finding tool
was an arena size-class census plus a pointer trace, not ASan: an in-arena
leak is invisible to LeakSanitizer, because the arena is one allocation.
Two rules the measurements imposed, both easy to get backwards:
- **Never drop an argument register after a `CALL`.** The callee's frame

View file

@ -1377,6 +1377,21 @@ let rec is_borrowed_value (e : Ast.expr) : bool =
| Ast.Interp inner -> is_borrowed_value inner
| _ -> false
(* The Interp arm above is only true for a TEXT-typed segment (the emitter
passes those through untouched). An Int-typed one lowers to int_to_text —
a fresh allocation wearing a place's clothes: `"HTTP/1.1 ${resp.status}"`
leaked one three-byte string per MCP response until this looked at the
type. Used wherever the caller has p/f to ask with. *)
let rec is_borrowed_value_t (p : pctx) (f : fstate) (e : Ast.expr) : bool =
match e.Ast.kind with
| Ast.Ident _ | Ast.Field _ | Ast.Index _ -> true
| Ast.Interp inner -> (
(match ty_of_expr p f inner with
| Some t -> ( match unwrap t with Scalar "Text" -> true | _ -> false)
| None -> false)
&& is_borrowed_value_t p f inner)
| _ -> false
(* A value the emitter materialised into a temporary and nobody took ownership
of: a fresh container or record used as an expression rather than bound to a
name — `for raw in split(content, "\n")`, `join(slice(tokens, 0, 5), " ")`,
@ -1388,7 +1403,7 @@ let rec is_borrowed_value (e : Ast.expr) : bool =
straight, which is why this is applied at the specific sites that borrow.
Kinds 1/4/5 are OWNED/MULTI/MAP; Text has its own copy rule above. *)
let is_fresh_owned_temp (p : pctx) (f : fstate) (e : Ast.expr) : bool =
(not (is_borrowed_value e))
(not (is_borrowed_value_t p f e))
&& (match ty_of_expr p f e with
| Some t -> ( match field_kind p t with 1 | 4 | 5 -> true | _ -> false)
| None -> false)
@ -1431,7 +1446,7 @@ let copy_place_text (p : pctx) (f : fstate) (reg : int) (e : Ast.expr) : unit =
if is_place && is_text then put f (ins_abc op_builtin reg reg b_text_copy)
let drop_fresh_text ?keep (p : pctx) (f : fstate) (reg : int) (e : Ast.expr) : unit =
let is_place = is_borrowed_value e && not (is_container_read e) in
let is_place = is_borrowed_value_t p f e && not (is_container_read e) in
let is_text =
match ty_of_expr p f e with Some t -> field_kind p t = 3 (* WO_K_TEXT *) | None -> false
in
@ -1800,10 +1815,17 @@ and emit_binary (p : pctx) (f : fstate) (v : views) ~(dst : int) (op : Ast.binop
nil_compare_into p f v ~dst:t op_eq l r;
f.f_temp <- save
end
else
else begin
let a = emit_operand p f v l in
let b = emit_operand p f v r in
put f (ins_abc (if is_text p f l || is_text p f r then op_eqs else op_eq) t a b));
put f (ins_abc (if is_text p f l || is_text p f r then op_eqs else op_eq) t a b);
(* the same reap `simple` does — `headers["authorization"] !=
"Bearer ${key}"` abandoned both sides, once per MCP request *)
drop_fresh_owned ~keep:t p f a l;
drop_fresh_text ~keep:t p f a l;
drop_fresh_owned ~keep:t p f b r;
drop_fresh_text ~keep:t p f b r
end);
let z = alloc_temp p f pos in
put f (ins_abx op_loadk z (check_bx p f pos "constant" (const_int p 0)));
put f (ins_abc op_eq dst t z)
@ -2590,7 +2612,16 @@ and emit_call (p : pctx) (f : fstate) (v : views) ~(dst : int) ?expected (e : As
put f (ins_abx op_loadk (base + 1) (check_bx p f e.pos "constant" (const_int p kind)));
sync_mask p f v e.id;
f.f_cur_line <- e.pos.line;
put f (ins_abc op_builtin dst base b_json_encode)
put f (ins_abc op_builtin dst base b_json_encode);
(* the value being encoded: a Ctor built in the argument slot
(`json.encode(ToolText { ... })`) had no owner — one record
and both its field copies leaked per MCP tool call. ~keep
covers the tail position where dst IS base (the argument
pointer is already overwritten there; a place argument is
the only shape that reaches it, and places are not
dropped). *)
drop_fresh_owned ~keep:dst p f base a;
drop_fresh_text ~keep:dst p f base a
| _ ->
err p ~code:cannot_lower_code ~file:f.f_file ~pos:e.pos
~message:"`json.encode` takes exactly one argument";
@ -2747,7 +2778,7 @@ and call_window (p : pctx) (f : fstate) (v : views) (e : Ast.expr) ~(recv : Ast.
it returns they hold the callee's leftovers, not the arguments. *)
let fresh_borrowed_value (a : Ast.expr) : bool =
is_fresh_owned_temp p f a
|| ((not (is_borrowed_value a))
|| ((not (is_borrowed_value_t p f a) || is_container_read a)
&& match ty_of_expr p f a with Some t -> field_kind p t = 3 | None -> false)
in
let owned_heap_temp (a : Ast.expr) : bool =
@ -3094,7 +3125,22 @@ and emit_stmt_body (p : pctx) (f : fstate) (v : views) (s : Ast.stmt) : unit =
reserving it: a call then places its own window at that same slot
and needs no MOVE to hand the result back, and nothing later in
this statement can want the register (the statement ends here) *)
ignore (emit_tail p f v e);
let t = emit_tail p f v e in
(* Discarded does not mean unowned: `pop(lines);` REMOVES the element and
hands it to the caller, and a discarded call result is the caller's
too — one empty Text per popped line leaked in the workload's tail
tool. The four reader builtins are excluded the same way fixed_at
excludes them: their result points INTO the container. *)
let reader_call =
match e.kind with
| Ast.Call ({ Ast.kind = Ast.Ident n; _ }, _) ->
List.mem n [ "get"; "latest"; "key_at"; "val_at" ]
| _ -> false
in
if not reader_call then begin
drop_fresh_owned p f t e;
drop_fresh_text p f t e
end;
(match Hashtbl.find_opt v.v_move e.id with
| Some place -> ( match lookup_local f place with Some (sr, _) -> mask_clear f sr | None -> ())
| None -> ())

View file

@ -59,11 +59,22 @@ running", and every item below came from a measurement on the sample itself:
double-free: an **assignment** of a Text place was a move, not a copy, so
`api_key = j.mcp.apiKey` aliased the record — `let` copied, assignment now
does too. `just log-watcher` is 7 checks; the seventh is the stop.
5. **The MCP server never closes an accepted connection** — `net.close` exists
and is unused; every request costs a descriptor.
6. **Nothing soaks** — every check is seconds long, which is exactly the window
where a leak hides. The acceptance script needs a soak mode measuring RSS
and descriptors across a real duration.
5. ~~The MCP server never closes an accepted connection~~ — **done
2026-08-15**. `net.close` on every path out of a serve iteration (and the
listener on stop). Measured: 4 → 4 descriptors across 200 requests, was
one leaked per request.
6. ~~Nothing soaks~~ — **done 2026-08-15**. `LW_SOAK=<seconds>` drives all
three modes under load and fails on resident growth past 256 KiB or any
descriptor growth. The soak immediately caught what every seconds-long
check missed: ~1.6 MiB/min of **in-arena** leaks the ASan report cannot
see (the arena is one allocation to LeakSanitizer). Five bugs fell out:
json decode's worst-case string sizing (free lists poisoned by relabeled
lengths), `!=` never dropping fresh operands, Int interpolation segments
mistaken for borrows, `json.encode(Ctor{...})`'s unowned argument, and
discarded statement results (`pop(lines);`). After: release soak 30 s per
mode — watch 0, run 0, mcp +20 KiB, descriptors flat; ASan build flat at
14 600 KiB across 601 686 requests in 90 s once past its ~1200-request
quarantine warm-up.
Plan: [`plan/compiler/2026-08-14-logwatcher-executable.md`](plan/compiler/2026-08-14-logwatcher-executable.md) ·
Story slice: [`docs/stories/language-runtime-database/07-logwatcher-proof.md`](stories/language-runtime-database/07-logwatcher-proof.md)

View file

@ -109,18 +109,21 @@ class Mcp {
}
-- Blocking accept loop: one HTTP request per connection, respond, close.
-- Localhost only. A bad request never kills the loop. Connections are
-- owned handles: the drop at each iteration's end IS the close — the
-- Haxe try/close/catch bookkeeping (Mcp.hx:101-105) has no equivalent
-- and needs none.
-- Localhost only. A bad request never kills the loop. A connection is a
-- DESCRIPTOR, not an owned heap value: `net.Conn` is a scalar to the
-- ownership pass (nothing to drop, and dropping an fd number would be
-- nonsense), so the close is the source's own job on every path out of an
-- iteration — the 400 included. Measured before this was here: exactly one
-- descriptor leaked per request, so the server died at the process limit.
fn serve(port: Int) -> Int {
let srv = net.listen("127.0.0.1", port);
while true {
if env.stopping() { return 0; }
if env.stopping() { net.close(srv); return 0; }
let c = net.accept(srv);
let req = try self.read_request(c) catch (e) nil;
if req == nil {
try net.write(c, "HTTP/1.1 400 Bad Request\r\nContent-Length: 0\r\nConnection: close\r\n\r\n") catch (e) {}
net.close(c);
continue;
}
let resp = self.handle(req);
@ -128,6 +131,7 @@ class Mcp {
head = head .. "Content-Type: application/json\r\nConnection: close\r\n";
head = head .. "Content-Length: ${len(resp.body)}\r\n\r\n";
try net.write(c, head .. resp.body) catch (e) {}
net.close(c);
}
}

View file

@ -1,8 +1,9 @@
# log-watcher Executable Implementation Plan
> **Status: 🔄 in progress** (story iteration 7) — the sample compiles and its
> three modes run; this plan is everything still between "it runs" and "you can
> leave it running". Board: [00-status.md](../../00-status.md)
> **Status: ✅ done 2026-08-15** (story iteration 7) — all six tasks landed:
> the sample compiles, runs, stops on SIGTERM, holds RSS and descriptors flat
> under sustained load in all three modes, and the soak that proves it is in
> the acceptance script. Board: [00-status.md](../../00-status.md)
> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking.
>
@ -209,7 +210,7 @@ with an event loop anyway.
SIGTERM. Gates: `just oop-accept` ALL CRITERIA MET, `oop-e2e` 71/0,
`woc-test` 565/0, `wovm-test` green, `just log-watcher` 7/0.
### Task 5: The MCP server must close what it accepts
### Task 5 ✅: The MCP server must close what it accepts
**Concept & reason:** `Mcp.serve` accepts a connection per request and never
calls `net.close` — the builtin exists, the sample does not use it. Every
@ -219,12 +220,17 @@ is the acceptance workload. The connection is a value the loop owns for one
iteration; it must be closed on every exit path from that iteration, including
the malformed-request path that answers 400.
- [ ] Failing measurement: descriptor count for the server process across a few
hundred requests.
- [ ] Close the connection on every path out of the serve loop's body.
- [ ] Re-measure: the descriptor count is flat.
- [x] Failing measurement: exactly one descriptor per request — 4 → 54 fds
across 50 requests, read from `/proc/<pid>/fd`.
- [x] `net.close(c)` on both paths out of an iteration (the 400 included) and
`net.close(srv)` on the stop path; the serve loop's comment claimed "the
drop at each iteration's end IS the close", which was wrong twice —
`net.Conn` is a scalar to the ownership pass, so nothing was dropped,
and a drop would not close an fd anyway. The comment now says what is
true.
- [x] Re-measured: 4 → 4 fds across 200 requests.
### Task 6: Soak — the acceptance a daemon actually has to pass
### Task 6 ✅: Soak — the acceptance a daemon actually has to pass
**Concept & reason:** every check today is a few seconds long, which is exactly
the window in which a leak is invisible. The claim this plan exists to support
@ -234,11 +240,38 @@ sample RSS and descriptor count at the start and the end, and fail when either
grows beyond a stated tolerance. Keep it opt-in (an environment variable or a
flag) so the default `just log-watcher` stays fast for the ordinary loop.
- [ ] Soak the three modes with a stated duration, load pattern and tolerance;
report the measured deltas whether it passes or fails.
- [ ] Run the soak against an ASan build once and record the result in the
status board's known-gaps section.
- [ ] `just log-watcher` (fast path) stays green and stays under a minute.
- [x] `LW_SOAK=<seconds>` in the acceptance script: each mode runs under load
(watch: an error line every 200 ms; run: the cron file rewritten every
500 ms so every rescan reparses; mcp: all four tools back to back), with
resident memory and descriptor count compared between a **warmed**
baseline and the end. Warm-up includes load — measuring from before the
first request reported the allocator reaching its working-set high-water
as a leak. Tolerance: 256 KiB resident (the kernel accounts lazily),
**zero** descriptors (a handle has no third state). `LW_ACCEPT_WOVM`
points the whole script at another build.
- [x] **The soak caught what every seconds-long check missed.** The mcp mode
grew ~1.6 MiB/minute with ASan reporting zero leaks — in-arena leaks are
invisible to LeakSanitizer (the arena is one allocation), which is why
the soak measures RSS and not leak reports. Five compiler/runtime bugs
fell out, each found by an arena size-class census and a pointer trace:
`jparse_string` sized every decoded string at "rest of the input" and
shrank `len` after (the fs.read_all mis-size again — blocks filed on
free lists their next allocation never reads); `!=` never dropped its
fresh operands (`headers["authorization"] != "Bearer ${key}"`, twice
per request); an Int-typed interpolation segment (`"${resp.status}"`)
wore a place's clothes but is a fresh int_to_text allocation; a Ctor
handed to `json.encode` had no owner (one record + both field copies
per tool call); and a discarded expression statement (`pop(lines);`)
owns what the callee handed back. After: every handler flat per
request (arena live bytes constant from 4 to 24 requests).
- [x] Release-build soak, 30 s per mode under load: watch delta 0 KiB, run
delta 0 KiB, mcp delta 20 KiB, descriptors 0/0/0. ASan-build soak
recorded: RSS plateaus at ~1200 requests (quarantine + redzone
high-water), then **flat at 14 600 KiB across 601 686 requests in
90 s** — the authoritative ASan number, since bash's ~30 req/s client
cannot warm that high-water inside the script's warm-up.
- [x] `just log-watcher` (fast path) stays 7 checks, green, under a minute;
the soak is opt-in and off by default.
## Out of scope — deferred by name

View file

@ -298,8 +298,18 @@ static wo_str *jparse_string(jp *j) {
return NULL;
}
j->p++; /* closing quote */
s->len = n;
return s;
/* [s] was sized at the worst case (everything to the end of the input) and
* escapes only ever SHRINK the decoded form. wo_str_free sizes a block by
* its len (obj.h keeps no size headers), so relabeling this buffer with
* the decoded length would file it on the wrong free list forever after —
* the same mis-size fs.read_all had, and measured the same way: the MCP
* soak grew ~1.6 MiB a minute with zero malloc-level leaks, because every
* decoded string parked its worst-case block on a list its next
* allocation never reads. Copy out exact, release the buffer at the size
* it was taken. */
wo_str *exact = wo_str_new(j->rt, s->data, n);
wo_str_free(j->rt, s); /* len is still [worst]: the right class */
return exact;
}
/* An object into a fresh instance of [class_id]: keys matched against the

View file

@ -21,7 +21,9 @@ set -uo pipefail
ROOT="$(cd "$(dirname "${BASH_SOURCE[0]}")/.." && pwd)"
WOC="$ROOT/compiler/_build/default/bin/woc"
WOVM="$ROOT/runtime/wovm"
# LW_ACCEPT_WOVM points the whole run at another build — the sanitized one is
# the reason this exists (the soak below is worth a great deal more under ASan).
WOVM="${LW_ACCEPT_WOVM:-$ROOT/runtime/wovm}"
SAMPLE="$ROOT/docs/examples/log-watcher"
# A per-run port by default: a fixed one collides with a server left behind by
# an earlier run (or by hand), and then the checks below silently talk to THAT
@ -225,6 +227,99 @@ else
fi
SRV_PID=""
# ---- 8. soak (opt-in) --------------------------------------------------
# Every check above is seconds long, which is exactly the window a leak hides
# in. The claim this sample exists to support is "you can leave it running",
# so: drive each mode under load for a fixed duration and compare resident
# memory and descriptor count between a warmed-up baseline and the end.
#
# LW_SOAK=1 run it, 20 seconds per mode
# LW_SOAK=<seconds> run it, that long per mode
# LW_SOAK_RSS_KB=<n> resident-growth tolerance, default 256 KiB
# LW_ACCEPT_WOVM=... soak a different build (the ASan one is the point)
#
# The tolerance is not zero for RSS: the allocator may touch a new page at any
# time and the kernel accounts lazily. It IS zero for descriptors — a handle
# is either returned or leaked, there is no third case.
if [[ -n "${LW_SOAK:-}" ]]; then
SOAK_SECS="${LW_SOAK}"
[[ "$SOAK_SECS" == 1 || ! "$SOAK_SECS" =~ ^[0-9]+$ ]] && SOAK_SECS=20
RSS_TOL="${LW_SOAK_RSS_KB:-256}"
echo
echo "soak: ${SOAK_SECS}s per mode, tolerance ${RSS_TOL} KiB resident / 0 descriptors"
rss_of() { awk '/^VmRSS:/ {print $2}' "/proc/$1/status" 2>/dev/null || echo 0; }
fds_of() { ls "/proc/$1/fd" 2>/dev/null | wc -l; }
# start, warm up, sample, drive load, sample again, stop. [load_fn] is
# called repeatedly for the whole duration; it is what makes the mode work.
soak_mode() {
local name="$1" load_fn="$2"
shift 2
"$WOVM" "$IMAGE" "$@" >"$WORK/soak-$name.out" 2>&1 &
local pid=$! rss0 fd0 rss1 fd1 drss dfd deadline i
sleep 3 # first-touch pages and the first work cycle
if ! kill -0 "$pid" 2>/dev/null; then
bad "soak $name" "died during warm-up: $(tr '\n' '|' <"$WORK/soak-$name.out" | cut -c1-160)"
return
fi
# warm-up must include LOAD: the baseline is the steady state, and a cold
# process reaching its working-set high-water is not growth — measuring
# from before the first request reported the allocator's warm-up as a leak
for i in 1 2 3 4 5 6 7 8; do "$load_fn"; done
rss0="$(rss_of "$pid")"
fd0="$(fds_of "$pid")"
deadline=$((SECONDS + SOAK_SECS))
while ((SECONDS < deadline)); do
"$load_fn"
kill -0 "$pid" 2>/dev/null || break
done
if ! kill -0 "$pid" 2>/dev/null; then
bad "soak $name" "died mid-soak: $(tr '\n' '|' <"$WORK/soak-$name.out" | cut -c1-160)"
return
fi
rss1="$(rss_of "$pid")"
fd1="$(fds_of "$pid")"
kill -TERM "$pid" 2>/dev/null
wait "$pid" 2>/dev/null
drss=$((rss1 - rss0))
dfd=$((fd1 - fd0))
if ((drss <= RSS_TOL)) && ((dfd <= 0)); then
ok "soak $name (${SOAK_SECS}s: resident ${rss0}->${rss1} KiB, delta ${drss}; descriptors ${fd0}->${fd1}, delta ${dfd})"
else
bad "soak $name" "resident ${rss0}->${rss1} KiB (delta ${drss}, tolerance ${RSS_TOL}); descriptors ${fd0}->${fd1} (delta ${dfd}, tolerance 0)"
fi
}
SOAK_LOG="$WORK/soak.log"
: >"$SOAK_LOG"
soak_watch_load() {
printf 'error disk full\n' >>"$SOAK_LOG"
sleep 0.2
}
soak_mode watch soak_watch_load watch "$SOAK_LOG" 2 1
# the supervisor re-reads the cron directory every rescan: rewriting the
# file is what makes each rescan do the parsing work being measured
cat >"$WORK/soak-sup.json" <<EOF
{ "pollInterval": 1, "quietPeriod": 2, "rescanInterval": 1, "detections": "$WORK/soak-detections.log" }
EOF
soak_run_load() {
printf '* * * * * root /usr/bin/backup.sh > %s 2>&1\n' "$SOAK_LOG" >"$CRON/backup"
sleep 0.5
}
soak_mode run soak_run_load run "$CRON" "$WORK/soak-sup.json"
# the MCP server under real request load: every tool, back to back
soak_mcp_load() {
http_post '{"jsonrpc":"2.0","id":1,"method":"tools/list"}' s3cret >/dev/null
http_post '{"jsonrpc":"2.0","id":2,"method":"tools/call","params":{"name":"get_running_crons","arguments":{}}}' s3cret >/dev/null
http_post '{"jsonrpc":"2.0","id":3,"method":"tools/call","params":{"name":"list_logs","arguments":{}}}' s3cret >/dev/null
http_post "{\"jsonrpc\":\"2.0\",\"id\":4,\"method\":\"tools/call\",\"params\":{\"name\":\"tail_log\",\"arguments\":{\"path\":\"$SOAK_LOG\",\"lines\":5}}}" s3cret >/dev/null
}
soak_mode mcp soak_mcp_load mcp "$CRON" "$WORK/cfg.json"
fi
echo
printf 'log-watcher-accept: %d checks, %d failures\n' "$((pass + fail))" "$fail"
[[ $fail -eq 0 ]]