diff --git a/docs/exploratory-testing/2026-10-10-queue/2026-10-10-report.md b/docs/exploratory-testing/2026-10-10-queue/2026-10-10-report.md new file mode 100644 index 0000000..4c4ccea --- /dev/null +++ b/docs/exploratory-testing/2026-10-10-queue/2026-10-10-report.md @@ -0,0 +1,125 @@ +# Queue exploratory-testing report — 2026-10-10 + +## Outcome + +Two confirmed bugs, both in `--persist` mode when the `PERSIST` volume runs out +of space. Both cause loss of items the API acknowledged with `200`: + +- [#160](https://github.com/jonbaldie/queue/issues/160): short writes are + treated as success and corrupt `persist.dat`. Acknowledged items are lost after + a crash restart, or by a graceful shutdown that exits 0. +- [#161](https://github.com/jonbaldie/queue/issues/161): enqueue and dequeue + return `500` when the persist write fails, but the in-memory queue has already + changed. Rejected items are delivered later, and dequeued items vanish. + +The ordinary worker flow and Docker volume recreation behaved as documented. + +## Setup and evidence + +- Build: `main` at `1c2c3e9`. `deno cache --frozen main.ts`, then + `deno compile --frozen` with the Dockerfile's permission flags, output to the + gitignored `target/queue`. Docker image `qx20261010-queue:local` built from the + repository `Dockerfile`. +- Environment: Deno 2.7.6 (`aarch64-apple-darwin`), Docker 29.4.0 (Linux VM). +- Small volumes: a 2 MiB HFS+ RAM disk + (`hdiutil attach -nomount ram://4096` + `diskutil erasevolume HFS+`) on macOS, + and a 2 MiB `tmpfs` named volume in Docker. This is an intervention that + simulates a full disk. Nothing else was changed. +- Evidence (this directory): + - [run-log.txt](./run-log.txt): build commit and dependency install. + - [journey1_workers.ts](./journey1_workers.ts), + [journey1-transcript.txt](./journey1-transcript.txt) + - [journey2_diskfull.sh](./journey2_diskfull.sh), + [journey2_snapshot_nearfull.sh](./journey2_snapshot_nearfull.sh), + [journey2_enospc_500.sh](./journey2_enospc_500.sh), + [journey2-transcript.txt](./journey2-transcript.txt) + - [journey3_docker.sh](./journey3_docker.sh), + [journey3-transcript.txt](./journey3-transcript.txt) + +## Journeys + +### 1. Publishers and polling workers (compiled binary, default config) + +Goal: 3 producers enqueue 120 jobs while 3 polling workers drain the queue. +Every job is delivered exactly once, in order per producer. + +- Default config: 99 `200`, 94 `429`. Only 41 of 120 jobs were enqueued and + delivered. Producers on the same host share the default 100 requests/minute + per-IP budget, and polling consumers spend it too. +- Variation, `RATE_LIMIT_REQUESTS=100000`: 120 sent, 120 received, 0 duplicates, + per-producer order kept, final length 0. +- Requests with the wrong token also use up the budget (they get `429` before + auth runs). The `429` response has no `Retry-After` header. + +### 2. Persistence when the `PERSIST` volume fills up (compiled binary) + +Goal: items acknowledged with `200` under `--persist` survive a restart. A full +disk should cause visible failures, not silent loss. + +- Crash after a disk-full episode: 3 items acknowledged, 1 recovered after + SIGKILL (2/2 runs). **Confirmed, #160.** +- Variation, graceful SIGTERM after the same episode: all 3 recovered (1/1 run). + The snapshot is rebuilt from memory. +- Graceful SIGTERM with about 100 KiB free: exit 0 and `Goodbye!`, but + `persist.dat` drops from 200123 to 4096 bytes. 1 of 2 items recovered (2/2 + runs). **Confirmed, #160.** +- Disk completely full: `500` enqueues still add the item (length 5 when 2 were + accepted). Each `500` dequeue removes an item (length 5 → 4 → 3). After space + returns, the 3 rejected items are delivered and the 2 accepted ones never are + (2/2 runs). **Confirmed, #161.** + +### 3. Docker deployment per README + +Goal: the README's Docker `--persist` command with a named volume keeps items +across container *recreation*. + +- 3a: enqueue 2 items, dequeue 1, `docker rm -f`, recreate with the same volume. + Length 1, the remaining item was delivered, then `204`. Pass. +- 3b: the default `CMD` (no `--persist`) with `-v ...:/data` loses items across + restart. This matches "Persistency is opt-in", so it is not a bug. See the + usability notes. +- 3c: graceful `docker stop` with a nearly full 2 MiB tmpfs `/data`. Exit 0, and + `persist.dat` drops from 200123 to 102400 bytes. 1 of 2 items recovered. This + reproduces #160 on Linux. + +## Rejected candidates + +- In runs 1–2 of `journey2_enospc_500.sh`, `/length` returned `Internal Server + Error` after a failed dequeue. Cause: the harness wrote the server log onto the + full volume, so the log write failed. Runs 3–4 kept the log elsewhere and + `/length` worked. This is a harness artifact and is annotated in the transcript. + +## Unresolved + +- None. + +## Usability observations + +- The README does not mention the rate limit (`RATE_LIMIT_REQUESTS`, default 100 + requests/minute per client IP), `QUEUE_DEPTH_LIMIT`, `QUEUE_COUNT_LIMIT`, + `/peek`, or `/queues`. A single-host setup that follows the README's + publisher/subscriber advice hits `429` within a minute (journey 1). + *Suggestion:* document these in the README and add `Retry-After` to `429`. +- The image sets `PERSIST=/data/` and declares a `/data` volume, but the default + `CMD` has no `--persist`. Mounting a volume therefore persists nothing + (journey 3b). The README's "Mount a named volume there" sentence does not + repeat that `--persist` is required. *Suggestion:* say so in that sentence. +- The README calls `persist.dat` a "binary log", but it is newline-delimited JSON. + +## Limitations and unexplored areas + +- Disk-full was simulated with RAM disks and tmpfs, not with a real full disk. + Short-write sizes depend on the filesystem (4096 B on HFS+, 102400 B on tmpfs). +- Docker Desktop port mapping makes host clients share one source IP. How that + affects per-IP rate limits behind a real NAT was not measured. +- Not explored this pass: concurrent server instances sharing one `PERSIST` + directory, and signal storms during shutdown. + +## Cleanup + +- Removed Docker containers `qx20261010-c` and `qx20261010-c-holder`, volumes + `qx20261010-data` and `qx20261010-tmpfs`, and image `qx20261010-queue:local`. +- Detached the RAM disk and deleted `target/queue` and the scratch server logs + in `TMPDIR`. +- Docker's shared build cache was not pruned. Pruning it would also remove + cache entries that belong to other projects. diff --git a/docs/exploratory-testing/2026-10-10-queue/journey1-transcript.txt b/docs/exploratory-testing/2026-10-10-queue/journey1-transcript.txt new file mode 100644 index 0000000..202db60 --- /dev/null +++ b/docs/exploratory-testing/2026-10-10-queue/journey1-transcript.txt @@ -0,0 +1,17 @@ +## journey1 default rate limit +{"rateLimit":"default","statuses":{"200":99,"204":1,"429":94},"sent":120,"received":41,"unique":41,"duplicates":0,"perProducerOrdered":true,"finalLength":"Too many requests"} +## journey1 RATE_LIMIT_REQUESTS=100000 +{"rateLimit":"100000","statuses":{"200":240,"204":34},"sent":120,"received":120,"unique":120,"duplicates":0,"perProducerOrdered":true,"finalLength":"0"} +## 429 response headers (RATE_LIMIT_REQUESTS=2) +req 1 -> 200 +req 2 -> 200 +req 3 -> 429 +HTTP/1.1 429 Too Many Requests +content-type: text/plain;charset=UTF-8 +vary: Accept-Encoding +content-length: 17 +date: Sat, 10 Oct 2026 00:40:46 GMT + +Too many requests +## unauthenticated requests consume the same budget +wrong token -> 429 diff --git a/docs/exploratory-testing/2026-10-10-queue/journey1_workers.ts b/docs/exploratory-testing/2026-10-10-queue/journey1_workers.ts new file mode 100644 index 0000000..24197b6 --- /dev/null +++ b/docs/exploratory-testing/2026-10-10-queue/journey1_workers.ts @@ -0,0 +1,87 @@ +// Journey 1: producers and polling workers against the compiled binary. +// Usage: deno run -A journey1_workers.ts [RATE_LIMIT_REQUESTS] +const [bin, portArg, rate] = Deno.args; +const port = Number(portArg); +const token = "qx-token-20261010"; +const base = `http://127.0.0.1:${port}`; +const auth = { Authorization: `Bearer ${token}` }; + +const env: Record = { QUEUE_API_TOKEN: token, PORT: String(port) }; +if (rate) env.RATE_LIMIT_REQUESTS = rate; +const child = new Deno.Command(bin, { env, stdout: "null", stderr: "piped" }).spawn(); + +async function waitReady() { + for (let i = 0; i < 100; i++) { + try { + const r = await fetch(`${base}/health`); + await r.body?.cancel(); + if (r.ok) return; + } catch { /* not up yet */ } + await new Promise((r) => setTimeout(r, 100)); + } + throw new Error("server not ready"); +} + +const statuses: Record = {}; +const count = (s: number) => statuses[s] = (statuses[s] ?? 0) + 1; + +async function produce(id: number, n: number) { + for (let i = 0; i < n; i++) { + const r = await fetch(`${base}/enqueue/jobs`, { + method: "POST", + headers: { ...auth, "Content-Type": "application/json" }, + body: JSON.stringify({ payload: { producer: id, seq: i } }), + }); + count(r.status); + await r.body?.cancel(); + } +} + +const received: { producer: number; seq: number }[] = []; +async function consume(stopAfterEmpty: number) { + let empties = 0; + while (empties < stopAfterEmpty) { + const r = await fetch(`${base}/dequeue/jobs`, { headers: auth }); + count(r.status); + if (r.status === 200) { + received.push(await r.json()); + empties = 0; + } else { + await r.body?.cancel(); + empties++; + await new Promise((res) => setTimeout(res, 20)); + } + } +} + +try { + await waitReady(); + const PRODUCERS = 3, PER = 40; + await Promise.all([ + ...Array.from({ length: PRODUCERS }, (_, i) => produce(i, PER)), + consume(10), consume(10), consume(10), + ]); + // Final drain in case consumers stopped early. + await consume(3); + const len = await (await fetch(`${base}/length/jobs`, { headers: auth })).text(); + const keys = received.map((m) => `${m.producer}:${m.seq}`); + const unique = new Set(keys); + let perProducerOrdered = true; + for (let p = 0; p < PRODUCERS; p++) { + const seqs = received.filter((m) => m.producer === p).map((m) => m.seq); + if (seqs.some((s, i) => i > 0 && s < seqs[i - 1])) perProducerOrdered = false; + } + console.log(JSON.stringify({ + rateLimit: rate ?? "default", + statuses, + sent: PRODUCERS * PER, + received: received.length, + unique: unique.size, + duplicates: received.length - unique.size, + perProducerOrdered, + finalLength: len, + })); +} finally { + child.kill("SIGTERM"); + await child.status; +} diff --git a/docs/exploratory-testing/2026-10-10-queue/journey2-transcript.txt b/docs/exploratory-testing/2026-10-10-queue/journey2-transcript.txt new file mode 100644 index 0000000..cce02ac --- /dev/null +++ b/docs/exploratory-testing/2026-10-10-queue/journey2-transcript.txt @@ -0,0 +1,215 @@ +## run 1: SIGKILL crash after disk-full episode +enqueue q -> 200 +free KiB after filler: 0 +enqueue q -> 200 +length q -> 2 +persist.dat bytes: 4096 +filler removed; free KiB: 1896 +enqueue q -> 200 +length q -> 3 +persist.dat lines: 2 bytes: 4171 +last 120 bytes of persist.dat: +AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA{"queue":"q","payload":"after-space-freed","enqueue":true,"dequeue":false} + +--- stopping server with SIGKILL +--- after restart +length q -> 1 +dequeue q -> 200 "before-full" +dequeue q -> 204 +dequeue q -> 204 +dequeue q -> 204 + +## run 2: replay, SIGKILL crash +enqueue q -> 200 +free KiB after filler: 0 +enqueue q -> 200 +length q -> 2 +persist.dat bytes: 4096 +filler removed; free KiB: 1896 +enqueue q -> 200 +length q -> 3 +persist.dat lines: 2 bytes: 4171 +last 120 bytes of persist.dat: +AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA{"queue":"q","payload":"after-space-freed","enqueue":true,"dequeue":false} + +--- stopping server with SIGKILL +--- after restart +length q -> 1 +dequeue q -> 200 "before-full" +dequeue q -> 204 +dequeue q -> 204 +dequeue q -> 204 + +## run 3: variation, graceful SIGTERM +enqueue q -> 200 +free KiB after filler: 0 +enqueue q -> 200 +length q -> 2 +persist.dat bytes: 4096 +filler removed; free KiB: 1896 +enqueue q -> 200 +length q -> 3 +persist.dat lines: 2 bytes: 4171 +last 120 bytes of persist.dat: +AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA{"queue":"q","payload":"after-space-freed","enqueue":true,"dequeue":false} + +--- stopping server with SIGTERM +--- after restart +length q -> 3 +dequeue q -> 200 "before-full" +dequeue q -> 200 "AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA +dequeue q -> 200 "after-space-freed" +dequeue q -> 204 + +## snapshot near-full run 1 +enqueue q -> 200 +enqueue q -> 200 +length q -> 2 +persist.dat bytes before shutdown: 200123 +free KiB before shutdown: 100 +server exit status: 0 +Flushing data to persist.dat... + +Goodbye! +persist.dat bytes after shutdown: 4096 +--- after restart (space freed) +length q -> 1 +dequeue q -> 200 "small-1" +dequeue q -> 204 +dequeue q -> 204 + +## snapshot near-full run 2 +enqueue q -> 200 +enqueue q -> 200 +length q -> 2 +persist.dat bytes before shutdown: 200123 +free KiB before shutdown: 100 +server exit status: 0 +Flushing data to persist.dat... + +Goodbye! +persist.dat bytes after shutdown: 4096 +--- after restart (space freed) +length q -> 1 +dequeue q -> 200 "small-1" +dequeue q -> 204 +dequeue q -> 204 + +## NOTE: runs 1-2 below wrote the server log onto the full volume. The final +## 'length q -> Internal Server Error' is a harness artifact (log write failed), +## not a product failure. Runs 3-4 keep the log off-volume. +## ENOSPC enqueue/dequeue run 1 +enqueue q "first" -> 200 +free KiB: 0 +enqueue q "pad-1-" -> 200 +enqueue q "pad-2-" -> 500 +enqueue q "pad-3-" -> 500 +enqueue q "during-full" -> 500 +length q -> 5 +dequeue q -> 500 +length q -> Internal Server Error +server log tail: + at writeSync (ext:deno_io/12_io.js:53:15) + at FsFile.writeSync (ext:deno_fs/30_fs.js:609:12) + at FileStore.saveEvent (file:///Users/jonathanbaldie/.fleet/events/scratch/1b63e1b956f0b51cb469524917d2565b246146118f585930ba0103e453bee461/deno-compile-que + at Manager.dequeue (file:///Users/jonathanbaldie/.fleet/events/scratch/1b63e1b956f0b51cb469524917d2565b246146118f585930ba0103e453bee461/deno-compile-queue/s + at Object.handler (file:///Users/jonathanbaldie/.fleet/events/scratch/1b63e1b956f0b51cb469524917d2565b246146118f585930ba0103e453bee461/deno-compile-queue/sr + at handle (file:///Users/jonathanbaldie/.fleet/events/scratch/1b63e1b956f0b51cb469524917d2565b2461461 +## ENOSPC enqueue/dequeue run 2 +enqueue q "first" -> 200 +free KiB: 0 +enqueue q "pad-1-" -> 200 +enqueue q "pad-2-" -> 500 +enqueue q "pad-3-" -> 500 +enqueue q "during-full" -> 500 +length q -> 5 +dequeue q -> 500 +length q -> Internal Server Error +server log tail: + at writeSync (ext:deno_io/12_io.js:53:15) + at FsFile.writeSync (ext:deno_fs/30_fs.js:609:12) + at FileStore.saveEvent (file:///Users/jonathanbaldie/.fleet/events/scratch/1b63e1b956f0b51cb469524917d2565b246146118f585930ba0103e453bee461/deno-compile-que + at Manager.dequeue (file:///Users/jonathanbaldie/.fleet/events/scratch/1b63e1b956f0b51cb469524917d2565b246146118f585930ba0103e453bee461/deno-compile-queue/s + at Object.handler (file:///Users/jonathanbaldie/.fleet/events/scratch/1b63e1b956f0b51cb469524917d2565b246146118f585930ba0103e453bee461/deno-compile-queue/sr + at handle (file:///Users/jonathanbaldie/.fleet/events/scratch/1b63e1b956f0b51cb469524917d2565b2461461 +## ENOSPC enqueue/dequeue run 3 (server log off-volume) +enqueue q "first" -> 200 +free KiB: 0 +enqueue q "pad-1-" -> 200 +enqueue q "pad-2-" -> 500 +enqueue q "pad-3-" -> 500 +enqueue q "during-full" -> 500 +length q -> 5 +dequeue q -> 500 Internal Server Error +length q -> 4 +dequeue q -> 500 Internal Server Error +length q -> 3 +filler removed (space available again) +dequeue q -> 200 "pad-2- +dequeue q -> 200 "pad-3- +dequeue q -> 200 "during-full" +dequeue q -> 204 +dequeue q -> 204 +server log (no stack frames): +GET http://127.0.0.1:39603/health 200 1.74ms +POST http://127.0.0.1:39603/enqueue/q 200 3.90ms +POST http://127.0.0.1:39603/enqueue/q 200 0.64ms +POST http://127.0.0.1:39603/enqueue/q 500 0.55ms +Error: No space left on device (os error 28) +POST http://127.0.0.1:39603/enqueue/q 500 0.57ms +Error: No space left on device (os error 28) +POST http://127.0.0.1:39603/enqueue/q 500 0.23ms +Error: No space left on device (os error 28) +GET http://127.0.0.1:39603/length/q 200 0.18ms +GET http://127.0.0.1:39603/dequeue/q 500 0.33ms +Error: No space left on device (os error 28) +GET http://127.0.0.1:39603/length/q 200 0.11ms +GET http://127.0.0.1:39603/dequeue/q 500 0.13ms +Error: No space left on device (os error 28) +GET http://127.0.0.1:39603/length/q 200 0.08ms +GET http://127.0.0.1:39603/dequeue/q 200 0.15ms +GET http://127.0.0.1:39603/dequeue/q 200 0.11ms +GET http://127.0.0.1:39603/dequeue/q 200 0.07ms +GET http://127.0.0.1:39603/dequeue/q 204 0.04ms +GET http://127.0.0.1:39603/dequeue/q 204 0.03ms + +## ENOSPC enqueue/dequeue run 4 (server log off-volume) +enqueue q "first" -> 200 +free KiB: 0 +enqueue q "pad-1-" -> 200 +enqueue q "pad-2-" -> 500 +enqueue q "pad-3-" -> 500 +enqueue q "during-full" -> 500 +length q -> 5 +dequeue q -> 500 Internal Server Error +length q -> 4 +dequeue q -> 500 Internal Server Error +length q -> 3 +filler removed (space available again) +dequeue q -> 200 "pad-2- +dequeue q -> 200 "pad-3- +dequeue q -> 200 "during-full" +dequeue q -> 204 +dequeue q -> 204 +server log (no stack frames): +GET http://127.0.0.1:39604/health 200 1.24ms +POST http://127.0.0.1:39604/enqueue/q 200 2.32ms +POST http://127.0.0.1:39604/enqueue/q 200 0.55ms +POST http://127.0.0.1:39604/enqueue/q 500 0.54ms +Error: No space left on device (os error 28) +POST http://127.0.0.1:39604/enqueue/q 500 0.44ms +Error: No space left on device (os error 28) +POST http://127.0.0.1:39604/enqueue/q 500 0.25ms +Error: No space left on device (os error 28) +GET http://127.0.0.1:39604/length/q 200 0.20ms +GET http://127.0.0.1:39604/dequeue/q 500 0.29ms +Error: No space left on device (os error 28) +GET http://127.0.0.1:39604/length/q 200 0.13ms +GET http://127.0.0.1:39604/dequeue/q 500 0.13ms +Error: No space left on device (os error 28) +GET http://127.0.0.1:39604/length/q 200 0.07ms +GET http://127.0.0.1:39604/dequeue/q 200 0.17ms +GET http://127.0.0.1:39604/dequeue/q 200 0.10ms +GET http://127.0.0.1:39604/dequeue/q 200 0.11ms +GET http://127.0.0.1:39604/dequeue/q 204 0.06ms +GET http://127.0.0.1:39604/dequeue/q 204 0.05ms diff --git a/docs/exploratory-testing/2026-10-10-queue/journey2_diskfull.sh b/docs/exploratory-testing/2026-10-10-queue/journey2_diskfull.sh new file mode 100755 index 0000000..fbedd49 --- /dev/null +++ b/docs/exploratory-testing/2026-10-10-queue/journey2_diskfull.sh @@ -0,0 +1,48 @@ +#!/usr/bin/env bash +# Journey 2: persistence when the PERSIST volume runs out of space, then recovers. +# Usage: journey2_diskfull.sh +# Needs a small, empty, writable volume (e.g. a macOS RAM disk, see report). +set -u +BIN=$1; VOL=$2; PORT=$3; SIG=${4:-KILL} +TOKEN=qx-token-20261010 +DIR="$VOL/data" +B="http://127.0.0.1:$PORT" +AUTH="Authorization: Bearer $TOKEN" +rm -rf "$DIR" "$VOL/filler"; mkdir -p "$DIR" + +start() { + QUEUE_API_TOKEN=$TOKEN PORT=$PORT PERSIST="$DIR/" "$BIN" --persist >>"$VOL/server.log" 2>&1 & + PID=$! + for _ in $(seq 50); do curl -sf "$B/health" >/dev/null && return; sleep 0.1; done + echo "server did not start"; exit 1 +} +enq() { # enq + printf '%s' "{\"payload\":$2}" | curl -s -o /dev/null -w "enqueue $1 -> %{http_code}\n" \ + -X POST -H "$AUTH" -H 'Content-Type: application/json' --data-binary @- "$B/enqueue/$1" +} +len() { echo "length $1 -> $(curl -s -H "$AUTH" "$B/length/$1")"; } + +start +enq q '"before-full"' +# Fill the volume, leaving a small amount of free space. +dd if=/dev/zero of="$VOL/filler" bs=1024 count=100000 2>/dev/null +FREE=$(df -k "$VOL" | awk 'NR==2{print $4}'); echo "free KiB after filler: $FREE" +# Payload bigger than the remaining space (~200 KB string). +BIG="\"$(head -c 200000 /dev/zero | tr '\0' 'A')\"" +enq q "$BIG" +len q +echo "persist.dat bytes: $(wc -c <"$DIR/persist.dat")" +rm -f "$VOL/filler"; echo "filler removed; free KiB: $(df -k "$VOL" | awk 'NR==2{print $4}')" +enq q '"after-space-freed"' +len q +echo "persist.dat lines: $(wc -l <"$DIR/persist.dat") bytes: $(wc -c <"$DIR/persist.dat")" +echo "last 120 bytes of persist.dat:"; tail -c 120 "$DIR/persist.dat"; echo +echo "--- stopping server with SIG$SIG" +kill -s "$SIG" $PID; wait $PID 2>/dev/null +start +echo "--- after restart" +len q +for _ in 1 2 3 4; do + curl -s -H "$AUTH" -o "$VOL/out" -w "dequeue q -> %{http_code} " "$B/dequeue/q"; head -c 40 "$VOL/out"; echo +done +kill -TERM $PID; wait $PID 2>/dev/null diff --git a/docs/exploratory-testing/2026-10-10-queue/journey2_enospc_500.sh b/docs/exploratory-testing/2026-10-10-queue/journey2_enospc_500.sh new file mode 100755 index 0000000..3f12dae --- /dev/null +++ b/docs/exploratory-testing/2026-10-10-queue/journey2_enospc_500.sh @@ -0,0 +1,36 @@ +#!/usr/bin/env bash +# Journey 2 variation: enqueue/dequeue when the PERSIST volume is already completely full. +# Usage: journey2_enospc_500.sh +# The server log is kept off the small volume so log writes cannot fail. +set -u +BIN=$1; VOL=$2; PORT=$3 +TOKEN=qx-token-20261010 +DIR="$VOL/data" +B="http://127.0.0.1:$PORT" +LOG="${TMPDIR:-/tmp}/qx20261010-enospc-server.log" +AUTH="Authorization: Bearer $TOKEN" +rm -rf "$DIR" "$VOL/filler"; mkdir -p "$DIR" +QUEUE_API_TOKEN=$TOKEN PORT=$PORT PERSIST="$DIR/" "$BIN" --persist >"$LOG" 2>&1 & +PID=$! +for _ in $(seq 50); do curl -sf "$B/health" >/dev/null && break; sleep 0.1; done +enq() { + printf '%s' "{\"payload\":$2}" | curl -s -o /dev/null -w "enqueue $1 $2 -> %{http_code}\n" \ + -X POST -H "$AUTH" -H 'Content-Type: application/json' --data-binary @- "$B/enqueue/$1" +} +enq q '"first"' +dd if=/dev/zero of="$VOL/filler" bs=1024 count=100000 2>/dev/null +echo "free KiB: $(df -k "$VOL" | awk 'NR==2{print $4}')" +# Use up any tail of the last block so the next write fails outright. +for i in 1 2 3; do enq q "\"pad-$i-$(head -c 8000 /dev/zero | tr '\0' 'p')\"" ; done +enq q '"during-full"' +echo "length q -> $(curl -s -H "$AUTH" "$B/length/q")" +for _ in 1 2; do + curl -s -H "$AUTH" -o "$LOG.out" -w "dequeue q -> %{http_code} " "$B/dequeue/q"; head -c 30 "$LOG.out"; echo + echo "length q -> $(curl -s -H "$AUTH" "$B/length/q")" +done +rm -f "$VOL/filler"; echo "filler removed (space available again)" +for _ in 1 2 3 4 5; do + curl -s -H "$AUTH" -o "$LOG.out" -w "dequeue q -> %{http_code} " "$B/dequeue/q"; head -c 30 "$LOG.out"; echo +done +echo "server log (no stack frames):"; grep -v "^ at" "$LOG" | grep -E "^(GET|POST|Error)" | cut -c1-80 +kill -TERM $PID; wait $PID 2>/dev/null diff --git a/docs/exploratory-testing/2026-10-10-queue/journey2_snapshot_nearfull.sh b/docs/exploratory-testing/2026-10-10-queue/journey2_snapshot_nearfull.sh new file mode 100755 index 0000000..4d874b6 --- /dev/null +++ b/docs/exploratory-testing/2026-10-10-queue/journey2_snapshot_nearfull.sh @@ -0,0 +1,43 @@ +#!/usr/bin/env bash +# Journey 2 variation: graceful shutdown snapshot when the PERSIST volume is nearly full. +# Usage: journey2_snapshot_nearfull.sh +set -u +BIN=$1; VOL=$2; PORT=$3 +TOKEN=qx-token-20261010 +DIR="$VOL/data" +B="http://127.0.0.1:$PORT" +AUTH="Authorization: Bearer $TOKEN" +rm -rf "$DIR" "$VOL/filler"; mkdir -p "$DIR" + +start() { + QUEUE_API_TOKEN=$TOKEN PORT=$PORT PERSIST="$DIR/" "$BIN" --persist >>"$VOL/server.log" 2>&1 & + PID=$! + for _ in $(seq 50); do curl -sf "$B/health" >/dev/null && return; sleep 0.1; done + echo "server did not start"; exit 1 +} +enq() { + printf '%s' "{\"payload\":$2}" | curl -s -o /dev/null -w "enqueue $1 -> %{http_code}\n" \ + -X POST -H "$AUTH" -H 'Content-Type: application/json' --data-binary @- "$B/enqueue/$1" +} + +start +enq q '"small-1"' +BIG="\"$(head -c 200000 /dev/zero | tr '\0' 'B')\"" +enq q "$BIG" +echo "length q -> $(curl -s -H "$AUTH" "$B/length/q")" +echo "persist.dat bytes before shutdown: $(wc -c <"$DIR/persist.dat")" +# Leave ~100 KiB free: enough for the small line, not for the 200 KB line. +FREE=$(df -k "$VOL" | awk 'NR==2{print $4}') +dd if=/dev/zero of="$VOL/filler" bs=1024 count=$((FREE - 100)) 2>/dev/null +echo "free KiB before shutdown: $(df -k "$VOL" | awk 'NR==2{print $4}')" +kill -TERM $PID; wait $PID; echo "server exit status: $?" +tail -3 "$VOL/server.log" +echo "persist.dat bytes after shutdown: $(wc -c <"$DIR/persist.dat")" +rm -f "$VOL/filler" +start +echo "--- after restart (space freed)" +echo "length q -> $(curl -s -H "$AUTH" "$B/length/q")" +for _ in 1 2 3; do + curl -s -H "$AUTH" -o "$VOL/out" -w "dequeue q -> %{http_code} " "$B/dequeue/q"; head -c 30 "$VOL/out"; echo +done +kill -TERM $PID; wait $PID 2>/dev/null diff --git a/docs/exploratory-testing/2026-10-10-queue/journey3-transcript.txt b/docs/exploratory-testing/2026-10-10-queue/journey3-transcript.txt new file mode 100644 index 0000000..2c9c383 --- /dev/null +++ b/docs/exploratory-testing/2026-10-10-queue/journey3-transcript.txt @@ -0,0 +1,27 @@ +### 3a: named volume survives container recreation (README Persistency section) +enqueue jobs -> 200 +enqueue jobs -> 200 +dequeue jobs -> 200 {"id":1} +container force-removed (no graceful shutdown) +length jobs -> 1 +dequeue jobs -> 200 {"id":2} +dequeue jobs -> 204 +### 3b: README volume advice without --persist (default CMD) +enqueue nopersist -> 200 +length nopersist after restart -> 0 +### 3c: graceful stop with a nearly full 2 MiB tmpfs volume (Linux) +enqueue q -> 200 +enqueue q -> 200 +length q -> 2 +persist.dat bytes before stop: 200123 +tmpfs 2048 1948 100 96% /data +Flushing data to persist.dat... + +Goodbye! +queue container: exit=0 +persist.dat bytes after stop: 102400 +--- after restart (space freed) +length q -> 1 +dequeue q -> 200 "small-1" +dequeue q -> 204 +dequeue q -> 204 diff --git a/docs/exploratory-testing/2026-10-10-queue/journey3_docker.sh b/docs/exploratory-testing/2026-10-10-queue/journey3_docker.sh new file mode 100755 index 0000000..9cba35d --- /dev/null +++ b/docs/exploratory-testing/2026-10-10-queue/journey3_docker.sh @@ -0,0 +1,60 @@ +#!/usr/bin/env bash +# Journey 3: README Docker deployment with a named volume, container recreation, +# and a small tmpfs /data to check the disk-full path on Linux. +# Usage: journey3_docker.sh +set -u +IMG=$1; TOKEN=qx-token-20261010; PORT=39401 +NAME=qx20261010-c; VOL=qx20261010-data +B="http://127.0.0.1:$PORT"; AUTH="Authorization: Bearer $TOKEN" +wait_up() { for _ in $(seq 50); do curl -sf "$B/health" >/dev/null && return; sleep 0.2; done; echo "not up"; docker logs $NAME; } +enq() { + printf '%s' "{\"payload\":$2}" | curl -s -o /dev/null -w "enqueue $1 -> %{http_code}\n" \ + -X POST -H "$AUTH" -H 'Content-Type: application/json' --data-binary @- "$B/enqueue/$1" +} +deq() { curl -s -H "$AUTH" -o /tmp/qx20261010-out -w "dequeue $1 -> %{http_code} " "$B/dequeue/$1"; head -c 30 /tmp/qx20261010-out; echo; } + +echo "### 3a: named volume survives container recreation (README Persistency section)" +docker run -d --name $NAME -e QUEUE_API_TOKEN=$TOKEN -e PORT=1991 -e HOST=0.0.0.0 \ + -v $VOL:/data -p $PORT:1991 "$IMG" /usr/bin/queue --persist >/dev/null +wait_up +enq jobs '{"id":1}'; enq jobs '{"id":2}'; deq jobs +docker rm -f $NAME >/dev/null; echo "container force-removed (no graceful shutdown)" +docker run -d --name $NAME -e QUEUE_API_TOKEN=$TOKEN -e PORT=1991 -e HOST=0.0.0.0 \ + -v $VOL:/data -p $PORT:1991 "$IMG" /usr/bin/queue --persist >/dev/null +wait_up +echo "length jobs -> $(curl -s -H "$AUTH" "$B/length/jobs")"; deq jobs; deq jobs +docker stop $NAME >/dev/null; docker rm $NAME >/dev/null + +echo "### 3b: README volume advice without --persist (default CMD)" +docker run -d --name $NAME -e QUEUE_API_TOKEN=$TOKEN -e PORT=1991 -e HOST=0.0.0.0 \ + -v $VOL:/data -p $PORT:1991 "$IMG" >/dev/null +wait_up +enq nopersist '"x"' +docker stop $NAME >/dev/null; docker start $NAME >/dev/null; wait_up +echo "length nopersist after restart -> $(curl -s -H "$AUTH" "$B/length/nopersist")" +docker rm -f $NAME >/dev/null + +echo "### 3c: graceful stop with a nearly full 2 MiB tmpfs volume (Linux)" +TVOL=qx20261010-tmpfs +docker volume create --driver local --opt type=tmpfs --opt device=tmpfs --opt o=size=2m,uid=1993,gid=1993 $TVOL >/dev/null +# A sleeper keeps the tmpfs volume mounted so its contents outlive the queue container. +docker run -d --name ${NAME}-holder -v $TVOL:/data --entrypoint sleep "$IMG" 3600 >/dev/null +run_q() { docker run -d --name $NAME -e QUEUE_API_TOKEN=$TOKEN -e PORT=1991 -e HOST=0.0.0.0 \ + -v $TVOL:/data -p $PORT:1991 "$IMG" /usr/bin/queue --persist >/dev/null; wait_up; } +run_q +enq q '"small-1"' +BIG="\"$(head -c 200000 /dev/zero | tr '\0' 'B')\"" +enq q "$BIG" +echo "length q -> $(curl -s -H "$AUTH" "$B/length/q")" +docker exec ${NAME}-holder sh -c 'free=$(df -k /data | awk "NR==2{print \$4}"); dd if=/dev/zero of=/data/filler bs=1024 count=$((free-100)) 2>/dev/null; echo "persist.dat bytes before stop: $(wc -c /dev/null +docker logs $NAME 2>&1 | tail -3 +echo "queue container: $(docker inspect -f 'exit={{.State.ExitCode}}' $NAME)" +docker rm $NAME >/dev/null +docker exec ${NAME}-holder sh -c 'echo "persist.dat bytes after stop: $(wc -c $(curl -s -H "$AUTH" "$B/length/q")" +deq q; deq q; deq q +docker rm -f $NAME ${NAME}-holder >/dev/null +docker volume rm $TVOL >/dev/null diff --git a/docs/exploratory-testing/2026-10-10-queue/run-log.txt b/docs/exploratory-testing/2026-10-10-queue/run-log.txt new file mode 100644 index 0000000..6a7042b --- /dev/null +++ b/docs/exploratory-testing/2026-10-10-queue/run-log.txt @@ -0,0 +1,7 @@ +Sat Oct 10 01:36:57 BST 2026 +1c2c3e9755d3216cdb0146da94b5c8a1cc7f0632 +cache ok +Metadata: 1.96KB +Remote modules: 45.43KB + +sha256:1b7a17d2ab0dd4eab1e988a7bb46e09083b1ad3c5582271762611ef8e8b49ce6 diff --git a/docs/exploratory-testing/README.md b/docs/exploratory-testing/README.md index 9c30439..7251f41 100644 --- a/docs/exploratory-testing/README.md +++ b/docs/exploratory-testing/README.md @@ -13,3 +13,4 @@ evidence. Replay scripts run from the repository root. | 2026-09-19 | [2026-09-19-report.md](./2026-09-19-queue/2026-09-19-report.md) | Docker `--persist` path (#114), snapshot-rewrite data loss (#115), invalid UTF-8 accepted (#116) | | 2026-09-26 | [2026-09-26-report.md](./2026-09-26-queue/2026-09-26-report.md) | None | | 2026-10-03 | [2026-10-03-report.md](./2026-10-03-queue/2026-10-03-report.md) | None | +| 2026-10-10 | [2026-10-10-report.md](./2026-10-10-queue/2026-10-10-report.md) | Full-disk short writes corrupt `persist.dat` (#160), failed persist writes still mutate queues (#161) |