docs: exploratory pass on grace under origin 5xx and PURGE variants

docs/exploratory-testing/2026-10-24-grace-and-purge.md

@@ -0,0 +1,89 @@
+# Exploratory testing: grace under origin errors, origin freshness, and PURGE (2026-10-24)
+
+I ran this exploratory pass without supervision. I drove the image through real HTTP requests with `curl`, Docker container lifecycles, a scriptable origin, and a loopback sidecar for PURGE. I did not use mocks.
+
+## Setup
+
+- Build: `master` @ `8c9a304`, image `varnish-et-20261024:run` (`sha256:e46d9a85…`, [`build.txt`](2026-10-24-grace-and-purge/build.txt)). Varnish 7.1.1 on OrbStack, aarch64.
+- Topology ([`up.sh`](2026-10-24-grace-and-purge/up.sh)):
+  - network `vx24-net`
+  - origin `vx24-origin`: `python:3.13-alpine` running [`origin.py`](2026-10-24-grace-and-purge/origin.py). The origin sets the status and headers for each path at runtime through `/__set`, and numbers each response with `X-Origin-N`.
+  - standalone `vx24-varnish` on `127.0.0.1:18824` with `VARNISH_BACKEND_HOST/PORT/PROBE_PATH`.
+- PURGE is sent from loopback with `docker run --network container:vx24-varnish`, the same way `test/e2e/assert-compose-purge.sh` does it.
+- Every replay starts from fresh containers.
+- Evidence: [`2026-10-24-grace-and-purge/`](2026-10-24-grace-and-purge/).
+
+## Confirmed bugs
+
+| # | Bug | Issue |
+|---|---|---|
+| 1 | A 5xx from the origin replaces a graced dynamic page, so grace does not cover 500/502/503 outages | [#161](https://github.com/jonbaldie/varnish/issues/161) |
+| 2 | PURGE leaves the deflate copy of a page in cache; no PURGE can reach it | [#162](https://github.com/jonbaldie/varnish/issues/162) |
+
+### 1. A 5xx replaces a graced page — #161
+
+- **User impact:** When the application fails behind its web server, the origin returns 500/502/503. Visitors get one stale page and then the error, and every request goes back to the failing origin. Grace only helps when the origin cannot be reached at all.
+- **Starting conditions:** `GET /news` returns 200 with `Cache-Control: max-age=2`. Policy grace for non-static content is 1h.
+- **Replay:** [`repro-5xx-replaces-grace.sh`](2026-10-24-grace-and-purge/repro-5xx-replaces-grace.sh) with `STATUS=500|502|503`. Cache the page, switch the origin to 5xx, wait 3 s, then request once a second.
+- **Expected:** a cached 200 on every request while the origin fails. This is what happens when the origin is stopped ([`control-origin-stopped.txt`](2026-10-24-grace-and-purge/control-origin-stopped.txt)).
+- **Actual:** the first request is a grace HIT (200). Every later request is a MISS that returns the origin's 5xx ([`repro-5xx-replaces-grace.txt`](2026-10-24-grace-and-purge/repro-5xx-replaces-grace.txt)). varnishlog shows the background fetch storing the 500 as `TTL VCL 0 86400 … cacheable` ([`varnishlog-5xx-bgfetch.txt`](2026-10-24-grace-and-purge/varnishlog-5xx-bgfetch.txt)). The 5xx branch in `vcl_backend_response` sets `ttl=0s, grace=24h` and delivers. The new object replaces the graced 200 but is never served from lookup.
+- **Repeats:** 6 of 6: 500, 502 and 503, each in two series from clean containers. The recorded output is from the second series, after I removed a no-op line from the driver.
+
+### 2. PURGE leaves the deflate copy — #162
+
+- **User impact:** an operator purges an updated page and gets `200 Purged`, but clients that only accept deflate keep receiving the old content until the TTL expires.
+- **Starting conditions:** `GET /article` returns 200 with `Cache-Control: max-age=600`. It has been fetched with `Accept-Encoding: gzip` and with `Accept-Encoding: deflate`, which produces two objects (#146 fix).
+- **Replay:** [`repro-purge-deflate.sh`](2026-10-24-grace-and-purge/repro-purge-deflate.sh).
+- **Expected:** after the PURGE, every encoding is a MISS.
+- **Actual:** gzip is a MISS. Deflate is still a HIT serving the response from before the purge (`X-Origin-N: 4`). Identity HITs the fresh gzip object ([`repro-purge-deflate.txt`](2026-10-24-grace-and-purge/repro-purge-deflate.txt)).
+  - Variation: a PURGE carrying `Accept-Encoding: deflate` also leaves the deflate object. `vcl_recv` returns `purge` before the Accept-Encoding normalization that sets `X-Normalized-AE`, so `vcl_hash` never adds `"deflate"` for a PURGE.
+  - `POST /article` invalidates both copies because it uses a ban ([`variation-purge-deflate.txt`](2026-10-24-grace-and-purge/variation-purge-deflate.txt)).
+- **Repeats:** 3 of 3 from clean containers. The variation was run once.
+
+## Journeys exercised
+
+### Journey 1: the site stays up when the origin fails
+
+**Goal:** a visitor keeps getting the cached page during an origin failure, as the README's grace and "Grace period (backend down)" test promise.
+
+- **Ordinary path:** cache `/news`, then stop the origin container. The stale 200 is served with a growing `Age`. Passed.
+- **Variation:** the origin stays up but answers 500/502/503. Failed (bug 1).
+- **Static assets:** `/site.css` with an origin 500 after caching stayed a HIT. The asset gets a 1-day TTL whatever the origin sends, so the 5xx path is not reached within 3 s.
+- **Lasting effect checked:** the evicted object did not come back. All later requests went to the origin.
+
+### Journey 2: dynamic pages honour origin freshness
+
+**Goal:** pages the origin marks as zero-freshness are not served from cache ([`zero-freshness-dynamic.txt`](2026-10-24-grace-and-purge/zero-freshness-dynamic.txt)).
+
+- `max-age=0`, `s-maxage=0`, a past `Expires`, `no-cache`, `max-age=0, must-revalidate`, and static `app.css` with `max-age=0`: all MISS on every request. Passed.
+- `max-age=1`: MISS, then HIT. The third request at about 2.4 s was a HIT with content from a background refresh. This is the documented 1h grace, so it is not counted as a bug (see observations).
+
+### Journey 3: an operator purges an updated page
+
+**Goal:** after a PURGE, every client gets fresh content, and PURGE from outside is refused.
+
+- **Ordinary path:** PURGE through the published port gives `405`, as expected. PURGE from loopback gives `200 Purged`, and gzip and identity clients then MISS. Passed.
+- **Variation:** deflate clients after the PURGE, and a PURGE carrying `Accept-Encoding: deflate`. Failed (bug 2).
+- **Control:** POST invalidation removed both copies.
+
+## Rejected or unresolved candidates
+
+- **Rejected: a 5xx on a page with no cached copy gets cached.** Each request was a new MISS to the origin (`ttl=0` objects are not served).
+- **Unresolved:** the `grace = 24h` given to 5xx objects appears to have no serving effect, because a `ttl=0` object is skipped at lookup. I did not check whether it holds storage for 24h under memory pressure.
+
+## Usability observations
+
+- **Observation:** the image has no `curl`, `wget`, or `bash`. Sending a PURGE from an allowed address needs a sidecar container in the Varnish network namespace, as the project's own test does. The README's PURGE ACL line does not say how an operator is meant to send one.
+  - **Suggestion:** document a one-line PURGE command, or use `varnishadm ban` instead.
+- **Observation:** with `max-age=1`, a page was served up to 1h past the origin's freshness lifetime without `stale-while-revalidate` from the origin. This matches the README ("1 hour grace for other content"), but origin authors may not expect it.
+
+## Not explored
+
+- The Compose sample stack (covered on 2026-10-17), the TLS topology, WebSocket/`Upgrade`, `Range` requests, and `varnishadm ban` as an alternative purge path.
+
+## Limitations and cleanup
+
+- Host port 18824, not 80. The origin is Python's `http.server`, not nginx.
+- Run on OrbStack on macOS. Timing-based steps use 1 s sleeps against a 2 s TTL.
+- At the end of the pass I removed the containers `vx24-*`, the network `vx24-net`, and the image tag `varnish-et-20261024:run`. Every build step was a cache hit (`build.txt`), so the build added no layers or build cache. `python:3.13-alpine` was already on the host and was kept.
+- The image declares `VOLUME /var/lib/varnish`, so each container start creates an anonymous volume, and `docker rm -f` without `-v` leaves it behind. The first drivers leaked 16 of these. I identified them by creation time and by their contents (`varnishd` workdir), removed them, and changed `up.sh`/`down.sh` to `docker rm -fv`. A final replay of `repro-purge-deflate.sh` left the volume count unchanged.

docs/exploratory-testing/2026-10-24-grace-and-purge/build.txt

@@ -0,0 +1,51 @@
+#0 building with "orbstack" instance using docker driver
+
+#1 [internal] load build definition from Dockerfile
+#1 transferring dockerfile: 782B done
+#1 DONE 0.1s
+
+#2 [internal] load metadata for docker.io/library/debian:bookworm-slim
+#2 DONE 0.0s
+
+#3 [internal] load .dockerignore
+#3 transferring context:
+#3 transferring context: 2B done
+#3 DONE 0.1s
+
+#4 [1/9] FROM docker.io/library/debian:bookworm-slim
+#4 DONE 0.0s
+
+#5 [internal] load build context
+#5 transferring context: 24.00kB done
+#5 DONE 0.1s
+
+#6 [2/9] ADD embedded-default.vcl embedded-default.vcl
+#6 CACHED
+
+#7 [3/9] ADD cache-policy.vcl cache-policy.vcl
+#7 CACHED
+
+#8 [4/9] ADD render-vcl.sh render-vcl.sh
+#8 CACHED
+
+#9 [5/9] ADD install.sh install.sh
+#9 CACHED
+
+#10 [7/9] RUN chown -R varnish:varnish /etc/varnish /var/lib/varnish
+#10 CACHED
+
+#11 [6/9] RUN chmod +x install.sh render-vcl.sh && sh ./install.sh && rm install.sh embedded-default.vcl cache-policy.vcl render-vcl.sh
+#11 CACHED
+
+#12 [8/9] ADD start.sh /start.sh
+#12 CACHED
+
+#13 [9/9] RUN chown varnish:varnish /start.sh && chmod +x /start.sh
+#13 CACHED
+
+#14 exporting to image
+#14 exporting layers done
+#14 writing image sha256:e46d9a85926a6b634008b9c21bc13a1741f8ce22077c7e7e308371077b8c277a done
+#14 naming to docker.io/library/varnish-et-20261024:run done
+#14 DONE 0.0s
+docker build -t varnish-et-20261024:run .  0.08s user 0.08s system 21% cpu 0.764 total

docs/exploratory-testing/2026-10-24-grace-and-purge/control-origin-stopped.sh

@@ -0,0 +1,26 @@
+#!/bin/bash
+# Control: same page, but the origin is stopped (connection refused) rather
+# than answering 5xx. Also captures varnishlog for the 5xx background fetch.
+set -u
+EV=$(cd "$(dirname "$0")" && pwd)
+B=http://127.0.0.1:18824
+req(){ printf '%-28s ' "$1"; curl -s -o "${TMPDIR:-/tmp}/vx24body" -D - "$B$2" | grep -iE '^(x-cache|x-origin-n|age):' | tr -d '\r' | tr '\n' ' '; printf ' code=%s\n' "$(head -c 60 "${TMPDIR:-/tmp}/vx24body" | grep -o '"status": [0-9]*' | cut -d' ' -f2)"; }
+"$EV/up.sh"
+docker exec vx24-origin wget -qO- "http://127.0.0.1:8080/__set?path=/news&h_Cache-Control=max-age%3D2" >/dev/null
+req "good page cached" /news
+docker stop vx24-origin >/dev/null; echo "-- origin stopped"
+sleep 3
+for i in 1 2 3 4; do req "t+${i}s after expiry" /news; sleep 1; done
+"$EV/down.sh"
+echo "##### varnishlog of 5xx background fetch (static asset /site.css)"
+"$EV/up.sh"
+docker exec -d vx24-varnish sh -c 'varnishlog -g request -b -i BereqURL,BerespStatus,TTL,VCL_call,VCL_return,Begin > /tmp/vlog.txt'
+sleep 1
+docker exec vx24-origin wget -qO- "http://127.0.0.1:8080/__set?path=/site.css&h_Cache-Control=max-age%3D2" >/dev/null
+req "static cached" /site.css
+docker exec vx24-origin wget -qO- "http://127.0.0.1:8080/__set?path=/site.css&status=500&h_Cache-Control=max-age%3D2" >/dev/null
+echo "-- origin now answers /site.css with 500"
+sleep 3
+for i in 1 2 3; do req "t+${i}s" /site.css; sleep 1; done
+docker exec vx24-varnish cat /tmp/vlog.txt
+"$EV/down.sh"

docs/exploratory-testing/2026-10-24-grace-and-purge/control-origin-stopped.txt

@@ -0,0 +1,26 @@
+up: 200
+good page cached             X-Origin-N: 3 Age: 0 X-Cache: MISS  code=200
+-- origin stopped
+t+1s after expiry            X-Origin-N: 3 Age: 13 X-Cache: HIT  code=200
+t+2s after expiry            X-Origin-N: 3 Age: 14 X-Cache: HIT  code=200
+t+3s after expiry            X-Origin-N: 3 Age: 15 X-Cache: HIT  code=200
+t+4s after expiry            X-Origin-N: 3 Age: 16 X-Cache: HIT  code=200
+##### varnishlog of 5xx background fetch (static asset /site.css)
+up: 200
+static cached                X-Origin-N: 3 Age: 0 X-Cache: MISS  code=200
+-- origin now answers /site.css with 500
+t+1s                         X-Origin-N: 3 Age: 3 X-Cache: HIT  code=200
+t+2s                         X-Origin-N: 3 Age: 4 X-Cache: HIT  code=200
+t+3s                         X-Origin-N: 3 Age: 5 X-Cache: HIT  code=200
+**  << BeReq    >> 6         
+--  Begin          bereq 5 fetch
+--  BereqURL       /site.css
+--  VCL_call       BACKEND_FETCH
+--  VCL_return     fetch
+--  BerespStatus   200
+--  TTL            RFC 2 10 0 1792802640 1792802640 1792802640 0 2 cacheable
+--  VCL_call       BACKEND_RESPONSE
+--  TTL            VCL 86400 10 0 1792802640 cacheable
+--  TTL            VCL 86400 604800 0 1792802640 cacheable
+--  VCL_return     deliver
+

docs/exploratory-testing/2026-10-24-grace-and-purge/down.sh

@@ -0,0 +1,3 @@
+#!/bin/bash
+docker rm -fv vx24-varnish vx24-origin >/dev/null 2>&1 || true
+docker network rm vx24-net >/dev/null 2>&1 || true

docs/exploratory-testing/2026-10-24-grace-and-purge/origin.py

@@ -0,0 +1,53 @@
+"""Scriptable origin. Query params h_<Name>=v set response headers, status=N
+sets status. POST /__set?path=/p&status=N&h_X=v overrides later responses for
+path /p (any query) until /__clear. Each response carries X-Origin-N."""
+import http.server, itertools, json, threading, urllib.parse
+
+ctr = itertools.count(1)
+overrides = {}
+lock = threading.Lock()
+
+class H(http.server.BaseHTTPRequestHandler):
+    protocol_version = "HTTP/1.1"
+
+    def any(self):
+        u = urllib.parse.urlsplit(self.path)
+        q = urllib.parse.parse_qs(u.query, keep_blank_values=True)
+        ln = int(self.headers.get("Content-Length") or 0)
+        if ln:
+            self.rfile.read(ln)
+        if u.path == "/__set":
+            with lock:
+                overrides[q["path"][0]] = q
+            return self.reply(200, {}, b"set\n")
+        if u.path == "/__clear":
+            with lock:
+                overrides.clear()
+            return self.reply(200, {}, b"clear\n")
+        with lock:
+            o = overrides.get(u.path)
+        if o:
+            q = {**q, **o}
+        n = next(ctr)
+        status = int(q.get("status", [200])[0])
+        hdrs = {k[2:].replace("_", "-"): v[0] for k, v in q.items() if k.startswith("h_")}
+        body = json.dumps({"n": n, "method": self.command, "path": self.path,
+                           "status": status,
+                           "headers": dict(self.headers)}).encode() + b"\n"
+        self.reply(status, hdrs, body, n)
+
+    def reply(self, status, hdrs, body, n=0):
+        self.send_response(status)
+        for k, v in hdrs.items():
+            self.send_header(k, v)
+        self.send_header("X-Origin-N", str(n))
+        self.send_header("Content-Type", "text/html")
+        self.send_header("Content-Length", str(len(body)))
+        self.end_headers()
+        if self.command != "HEAD":
+            self.wfile.write(body)
+
+    do_GET = do_POST = do_PUT = do_DELETE = do_HEAD = do_PURGE = any
+    def log_message(self, *a): pass
+
+http.server.ThreadingHTTPServer(("0.0.0.0", 8080), H).serve_forever()

docs/exploratory-testing/2026-10-24-grace-and-purge/repro-5xx-replaces-grace.sh

@@ -0,0 +1,16 @@
+#!/bin/bash
+# A good cached page (max-age=2) must keep being served from grace while the
+# origin returns 500, rather than the 500 replacing it.
+set -u
+EV=$(cd "$(dirname "$0")" && pwd)
+"$EV/up.sh"
+B=http://127.0.0.1:18824
+req(){ printf '%-28s ' "$1"; curl -s -o "${TMPDIR:-/tmp}/vx24body" -D - "$B/news" | grep -iE '^(HTTP/|x-cache|x-origin-n|age):' | tr -d '\r' | tr '\n' ' '; printf ' body.status=%s\n' "$(grep -o '"status": [0-9]*' "${TMPDIR:-/tmp}/vx24body" | cut -d' ' -f2)"; }
+docker exec vx24-origin wget -qO- "http://127.0.0.1:8080/__set?path=/news&h_Cache-Control=max-age%3D2" >/dev/null
+req "t0 good page cached"
+req "t0 repeat"
+docker exec vx24-origin wget -qO- "http://127.0.0.1:8080/__set?path=/news&status=${STATUS:-500}&h_Cache-Control=max-age%3D2" >/dev/null
+echo "-- origin now answers /news with ${STATUS:-500}"
+sleep 3
+for i in 1 2 3 4 5; do req "t+$((i))s after expiry"; sleep 1; done
+"$EV/down.sh"

docs/exploratory-testing/2026-10-24-grace-and-purge/repro-5xx-replaces-grace.txt

@@ -0,0 +1,30 @@
+##### STATUS=500
+up: 200
+t0 good page cached          X-Origin-N: 3 Age: 0 X-Cache: MISS  body.status=200
+t0 repeat                    X-Origin-N: 3 Age: 0 X-Cache: HIT  body.status=200
+-- origin now answers /news with 500
+t+1s after expiry            X-Origin-N: 3 Age: 3 X-Cache: HIT  body.status=200
+t+2s after expiry            X-Origin-N: 5 Age: 0 X-Cache: MISS  body.status=500
+t+3s after expiry            X-Origin-N: 7 Age: 0 X-Cache: MISS  body.status=500
+t+4s after expiry            X-Origin-N: 8 Age: 0 X-Cache: MISS  body.status=500
+t+5s after expiry            X-Origin-N: 9 Age: 0 X-Cache: MISS  body.status=500
+##### STATUS=502
+up: 200
+t0 good page cached          X-Origin-N: 3 Age: 0 X-Cache: MISS  body.status=200
+t0 repeat                    X-Origin-N: 3 Age: 0 X-Cache: HIT  body.status=200
+-- origin now answers /news with 502
+t+1s after expiry            X-Origin-N: 3 Age: 3 X-Cache: HIT  body.status=200
+t+2s after expiry            X-Origin-N: 5 Age: 0 X-Cache: MISS  body.status=502
+t+3s after expiry            X-Origin-N: 7 Age: 0 X-Cache: MISS  body.status=502
+t+4s after expiry            X-Origin-N: 8 Age: 0 X-Cache: MISS  body.status=502
+t+5s after expiry            X-Origin-N: 9 Age: 0 X-Cache: MISS  body.status=502
+##### STATUS=503
+up: 200
+t0 good page cached          X-Origin-N: 3 Age: 0 X-Cache: MISS  body.status=200
+t0 repeat                    X-Origin-N: 3 Age: 0 X-Cache: HIT  body.status=200
+-- origin now answers /news with 503
+t+1s after expiry            X-Origin-N: 3 Age: 3 X-Cache: HIT  body.status=200
+t+2s after expiry            X-Origin-N: 5 Age: 0 X-Cache: MISS  body.status=503
+t+3s after expiry            X-Origin-N: 7 Age: 0 X-Cache: MISS  body.status=503
+t+4s after expiry            X-Origin-N: 8 Age: 0 X-Cache: MISS  body.status=503
+t+5s after expiry            X-Origin-N: 9 Age: 0 X-Cache: MISS  body.status=503

docs/exploratory-testing/2026-10-24-grace-and-purge/repro-purge-deflate.sh

@@ -0,0 +1,20 @@
+#!/bin/bash
+# Operator updates /article at origin and PURGEs it from inside the container
+# (an allowed localhost client). Every client should then get fresh content.
+set -u
+EV=$(cd "$(dirname "$0")" && pwd)
+B=http://127.0.0.1:18824
+"$EV/up.sh"
+get(){ printf '%-34s ' "$1"; curl -s -o /dev/null -D - -H "Accept-Encoding: $2" $B/article | grep -iE '^(x-cache|x-origin-n):' | tr -d '\r' | tr '\n' ' '; echo; }
+docker exec vx24-origin wget -qO- "http://127.0.0.1:8080/__set?path=/article&h_Cache-Control=max-age%3D600" >/dev/null
+for ae in gzip deflate identity; do get "fill AE=$ae" $ae; get "repeat AE=$ae" $ae; done
+echo "-- PURGE from host via published port (expected: denied)"
+curl -s -o /dev/null -w '%{http_code}\n' -X PURGE $B/article
+echo "-- PURGE from inside the container (localhost)"
+docker run --rm --network container:vx24-varnish python:3.13-alpine python -c '
+import http.client
+c = http.client.HTTPConnection("127.0.0.1", 80)
+c.request("PURGE", "/article", headers={"Host": "127.0.0.1:18824"})
+r = c.getresponse(); print(r.status, r.reason)'
+for ae in gzip deflate identity; do get "after purge AE=$ae" $ae; done
+"$EV/down.sh"