From 8b08ec7277a98a24cc3fa437ab4357b20f46fbba Mon Sep 17 00:00:00 2001 From: Jonathan Baldie Date: Sat, 24 Oct 2026 01:49:55 +0100 Subject: [PATCH] docs: exploratory pass on grace under origin 5xx and PURGE variants Report and replay evidence for #161 and #162, linked from the cache policy PRD. Co-Authored-By: Claude Opus 5.5 --- .../2026-10-24-grace-and-purge.md | 89 +++++++++++++++++++ .../2026-10-24-grace-and-purge/build.txt | 51 +++++++++++ .../control-origin-stopped.sh | 26 ++++++ .../control-origin-stopped.txt | 26 ++++++ .../2026-10-24-grace-and-purge/down.sh | 3 + .../2026-10-24-grace-and-purge/origin.py | 53 +++++++++++ .../repro-5xx-replaces-grace.sh | 16 ++++ .../repro-5xx-replaces-grace.txt | 30 +++++++ .../repro-purge-deflate.sh | 20 +++++ .../repro-purge-deflate.txt | 45 ++++++++++ .../2026-10-24-grace-and-purge/up.sh | 15 ++++ .../variation-purge-deflate.sh | 24 +++++ .../variation-purge-deflate.txt | 13 +++ .../varnishlog-5xx-bgfetch.sh | 15 ++++ .../varnishlog-5xx-bgfetch.txt | 55 ++++++++++++ .../zero-freshness-dynamic.txt | 29 ++++++ docs/prd/cache-policy-module.md | 2 + 17 files changed, 512 insertions(+) create mode 100644 docs/exploratory-testing/2026-10-24-grace-and-purge.md create mode 100644 docs/exploratory-testing/2026-10-24-grace-and-purge/build.txt create mode 100755 docs/exploratory-testing/2026-10-24-grace-and-purge/control-origin-stopped.sh create mode 100644 docs/exploratory-testing/2026-10-24-grace-and-purge/control-origin-stopped.txt create mode 100755 docs/exploratory-testing/2026-10-24-grace-and-purge/down.sh create mode 100644 docs/exploratory-testing/2026-10-24-grace-and-purge/origin.py create mode 100755 docs/exploratory-testing/2026-10-24-grace-and-purge/repro-5xx-replaces-grace.sh create mode 100644 docs/exploratory-testing/2026-10-24-grace-and-purge/repro-5xx-replaces-grace.txt create mode 100755 docs/exploratory-testing/2026-10-24-grace-and-purge/repro-purge-deflate.sh create mode 100644 docs/exploratory-testing/2026-10-24-grace-and-purge/repro-purge-deflate.txt create mode 100755 docs/exploratory-testing/2026-10-24-grace-and-purge/up.sh create mode 100755 docs/exploratory-testing/2026-10-24-grace-and-purge/variation-purge-deflate.sh create mode 100644 docs/exploratory-testing/2026-10-24-grace-and-purge/variation-purge-deflate.txt create mode 100755 docs/exploratory-testing/2026-10-24-grace-and-purge/varnishlog-5xx-bgfetch.sh create mode 100644 docs/exploratory-testing/2026-10-24-grace-and-purge/varnishlog-5xx-bgfetch.txt create mode 100644 docs/exploratory-testing/2026-10-24-grace-and-purge/zero-freshness-dynamic.txt diff --git a/docs/exploratory-testing/2026-10-24-grace-and-purge.md b/docs/exploratory-testing/2026-10-24-grace-and-purge.md new file mode 100644 index 0000000..8e38720 --- /dev/null +++ b/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. diff --git a/docs/exploratory-testing/2026-10-24-grace-and-purge/build.txt b/docs/exploratory-testing/2026-10-24-grace-and-purge/build.txt new file mode 100644 index 0000000..e2b9edb --- /dev/null +++ b/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 diff --git a/docs/exploratory-testing/2026-10-24-grace-and-purge/control-origin-stopped.sh b/docs/exploratory-testing/2026-10-24-grace-and-purge/control-origin-stopped.sh new file mode 100755 index 0000000..2202422 --- /dev/null +++ b/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" diff --git a/docs/exploratory-testing/2026-10-24-grace-and-purge/control-origin-stopped.txt b/docs/exploratory-testing/2026-10-24-grace-and-purge/control-origin-stopped.txt new file mode 100644 index 0000000..5ee3fde --- /dev/null +++ b/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 + diff --git a/docs/exploratory-testing/2026-10-24-grace-and-purge/down.sh b/docs/exploratory-testing/2026-10-24-grace-and-purge/down.sh new file mode 100755 index 0000000..c2aadbb --- /dev/null +++ b/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 diff --git a/docs/exploratory-testing/2026-10-24-grace-and-purge/origin.py b/docs/exploratory-testing/2026-10-24-grace-and-purge/origin.py new file mode 100644 index 0000000..7f5245e --- /dev/null +++ b/docs/exploratory-testing/2026-10-24-grace-and-purge/origin.py @@ -0,0 +1,53 @@ +"""Scriptable origin. Query params h_=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() diff --git a/docs/exploratory-testing/2026-10-24-grace-and-purge/repro-5xx-replaces-grace.sh b/docs/exploratory-testing/2026-10-24-grace-and-purge/repro-5xx-replaces-grace.sh new file mode 100755 index 0000000..19fca0f --- /dev/null +++ b/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" diff --git a/docs/exploratory-testing/2026-10-24-grace-and-purge/repro-5xx-replaces-grace.txt b/docs/exploratory-testing/2026-10-24-grace-and-purge/repro-5xx-replaces-grace.txt new file mode 100644 index 0000000..b09dd51 --- /dev/null +++ b/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 diff --git a/docs/exploratory-testing/2026-10-24-grace-and-purge/repro-purge-deflate.sh b/docs/exploratory-testing/2026-10-24-grace-and-purge/repro-purge-deflate.sh new file mode 100755 index 0000000..5b9c869 --- /dev/null +++ b/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" diff --git a/docs/exploratory-testing/2026-10-24-grace-and-purge/repro-purge-deflate.txt b/docs/exploratory-testing/2026-10-24-grace-and-purge/repro-purge-deflate.txt new file mode 100644 index 0000000..afb7052 --- /dev/null +++ b/docs/exploratory-testing/2026-10-24-grace-and-purge/repro-purge-deflate.txt @@ -0,0 +1,45 @@ +##### run 1 +up: 200 +fill AE=gzip X-Origin-N: 3 X-Cache: MISS +repeat AE=gzip X-Origin-N: 3 X-Cache: HIT +fill AE=deflate X-Origin-N: 4 X-Cache: MISS +repeat AE=deflate X-Origin-N: 4 X-Cache: HIT +fill AE=identity X-Origin-N: 3 X-Cache: HIT +repeat AE=identity X-Origin-N: 3 X-Cache: HIT +-- PURGE from host via published port (expected: denied) +405 +-- PURGE from inside the container (localhost) +200 Purged +after purge AE=gzip X-Origin-N: 5 X-Cache: MISS +after purge AE=deflate X-Origin-N: 4 X-Cache: HIT +after purge AE=identity X-Origin-N: 5 X-Cache: HIT +##### run 2 +up: 200 +fill AE=gzip X-Origin-N: 3 X-Cache: MISS +repeat AE=gzip X-Origin-N: 3 X-Cache: HIT +fill AE=deflate X-Origin-N: 4 X-Cache: MISS +repeat AE=deflate X-Origin-N: 4 X-Cache: HIT +fill AE=identity X-Origin-N: 3 X-Cache: HIT +repeat AE=identity X-Origin-N: 3 X-Cache: HIT +-- PURGE from host via published port (expected: denied) +405 +-- PURGE from inside the container (localhost) +200 Purged +after purge AE=gzip X-Origin-N: 5 X-Cache: MISS +after purge AE=deflate X-Origin-N: 4 X-Cache: HIT +after purge AE=identity X-Origin-N: 5 X-Cache: HIT +##### run 3 +up: 200 +fill AE=gzip X-Origin-N: 3 X-Cache: MISS +repeat AE=gzip X-Origin-N: 3 X-Cache: HIT +fill AE=deflate X-Origin-N: 4 X-Cache: MISS +repeat AE=deflate X-Origin-N: 4 X-Cache: HIT +fill AE=identity X-Origin-N: 3 X-Cache: HIT +repeat AE=identity X-Origin-N: 3 X-Cache: HIT +-- PURGE from host via published port (expected: denied) +405 +-- PURGE from inside the container (localhost) +200 Purged +after purge AE=gzip X-Origin-N: 5 X-Cache: MISS +after purge AE=deflate X-Origin-N: 4 X-Cache: HIT +after purge AE=identity X-Origin-N: 5 X-Cache: HIT diff --git a/docs/exploratory-testing/2026-10-24-grace-and-purge/up.sh b/docs/exploratory-testing/2026-10-24-grace-and-purge/up.sh new file mode 100755 index 0000000..dc9933d --- /dev/null +++ b/docs/exploratory-testing/2026-10-24-grace-and-purge/up.sh @@ -0,0 +1,15 @@ +#!/bin/bash +# Fresh topology: network, origin, varnish (published on 127.0.0.1:18824). +set -eu +EV=$(cd "$(dirname "$0")" && pwd) +IMG=${IMG:-varnish-et-20261024:run} +docker rm -fv vx24-varnish vx24-origin >/dev/null 2>&1 || true +docker network rm vx24-net >/dev/null 2>&1 || true +docker network create vx24-net >/dev/null +docker run -d --name vx24-origin --network vx24-net -v "$EV/origin.py:/origin.py:ro" python:3.13-alpine python -u /origin.py >/dev/null +docker run -d --name vx24-varnish --network vx24-net -p 127.0.0.1:18824:80 \ + -e VARNISH_BACKEND_HOST=vx24-origin -e VARNISH_BACKEND_PORT=8080 -e VARNISH_BACKEND_PROBE_PATH=/probe "$@" "$IMG" >/dev/null +for i in $(seq 1 60); do + curl -s -o /dev/null -w '%{http_code}' http://127.0.0.1:18824/ready 2>/dev/null | grep -q 200 && break; sleep 0.5 +done +echo "up: $(curl -s -o /dev/null -w '%{http_code}' http://127.0.0.1:18824/ready)" diff --git a/docs/exploratory-testing/2026-10-24-grace-and-purge/variation-purge-deflate.sh b/docs/exploratory-testing/2026-10-24-grace-and-purge/variation-purge-deflate.sh new file mode 100755 index 0000000..2dec8d1 --- /dev/null +++ b/docs/exploratory-testing/2026-10-24-grace-and-purge/variation-purge-deflate.sh @@ -0,0 +1,24 @@ +#!/bin/bash +# Variations: (a) PURGE carrying Accept-Encoding: deflate; (b) POST invalidation. +set -u +EV=$(cd "$(dirname "$0")" && pwd) +B=http://127.0.0.1:18824 +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; } +purge(){ docker run --rm --network container:vx24-varnish python:3.13-alpine python -c ' +import http.client, sys +c = http.client.HTTPConnection("127.0.0.1", 80) +h = {"Host": "127.0.0.1:18824"} +if sys.argv[1]: h["Accept-Encoding"] = sys.argv[1] +c.request("PURGE", "/article", headers=h) +r = c.getresponse(); print("PURGE AE=%r ->" % sys.argv[1], r.status, r.reason)' "$1"; } +"$EV/up.sh" +docker exec vx24-origin wget -qO- "http://127.0.0.1:8080/__set?path=/article&h_Cache-Control=max-age%3D600" >/dev/null +get "fill gzip" gzip; get "fill deflate" deflate +purge deflate +get "after deflate-purge gzip" gzip; get "after deflate-purge deflate" deflate +purge "" +get "after plain purge gzip" gzip; get "after plain purge deflate" deflate +echo "-- (b) POST /article" +curl -s -o /dev/null -w 'POST %{http_code}\n' -X POST $B/article +get "after POST gzip" gzip; get "after POST deflate" deflate +"$EV/down.sh" diff --git a/docs/exploratory-testing/2026-10-24-grace-and-purge/variation-purge-deflate.txt b/docs/exploratory-testing/2026-10-24-grace-and-purge/variation-purge-deflate.txt new file mode 100644 index 0000000..de7a61b --- /dev/null +++ b/docs/exploratory-testing/2026-10-24-grace-and-purge/variation-purge-deflate.txt @@ -0,0 +1,13 @@ +up: 200 +fill gzip X-Origin-N: 3 X-Cache: MISS +fill deflate X-Origin-N: 4 X-Cache: MISS +PURGE AE='deflate' -> 200 Purged +after deflate-purge gzip X-Origin-N: 5 X-Cache: MISS +after deflate-purge deflate X-Origin-N: 4 X-Cache: HIT +PURGE AE='' -> 200 Purged +after plain purge gzip X-Origin-N: 6 X-Cache: MISS +after plain purge deflate X-Origin-N: 4 X-Cache: HIT +-- (b) POST /article +POST 200 +after POST gzip X-Origin-N: 8 X-Cache: MISS +after POST deflate X-Origin-N: 9 X-Cache: MISS diff --git a/docs/exploratory-testing/2026-10-24-grace-and-purge/varnishlog-5xx-bgfetch.sh b/docs/exploratory-testing/2026-10-24-grace-and-purge/varnishlog-5xx-bgfetch.sh new file mode 100755 index 0000000..a4123d3 --- /dev/null +++ b/docs/exploratory-testing/2026-10-24-grace-and-purge/varnishlog-5xx-bgfetch.sh @@ -0,0 +1,15 @@ +#!/bin/bash +# varnishlog of the background fetch that replaces a graced /news with a 500. +set -u +EV=$(cd "$(dirname "$0")" && pwd) +B=http://127.0.0.1:18824 +"$EV/up.sh" +docker exec -d vx24-varnish sh -c 'varnishlog -b -q "BereqURL ~ news" -i Begin,BereqURL,BerespStatus,TTL,VCL_call,VCL_return > /tmp/vlog.txt' +sleep 1 +docker exec vx24-origin wget -qO- "http://127.0.0.1:8080/__set?path=/news&h_Cache-Control=max-age%3D2" >/dev/null +curl -s -o /dev/null -w 'cache fill %{http_code}\n' $B/news +docker exec vx24-origin wget -qO- "http://127.0.0.1:8080/__set?path=/news&status=500&h_Cache-Control=max-age%3D2" >/dev/null +sleep 3 +for i in 1 2 3; do curl -s -o /dev/null -w "after expiry #$i %{http_code}\n" $B/news; sleep 1; done +sleep 1; docker exec vx24-varnish cat /tmp/vlog.txt +"$EV/down.sh" diff --git a/docs/exploratory-testing/2026-10-24-grace-and-purge/varnishlog-5xx-bgfetch.txt b/docs/exploratory-testing/2026-10-24-grace-and-purge/varnishlog-5xx-bgfetch.txt new file mode 100644 index 0000000..a8d025e --- /dev/null +++ b/docs/exploratory-testing/2026-10-24-grace-and-purge/varnishlog-5xx-bgfetch.txt @@ -0,0 +1,55 @@ +up: 200 +cache fill 200 +after expiry #1 200 +after expiry #2 500 +after expiry #3 500 +* << BeReq >> 8 +- Begin bereq 7 fetch +- BereqURL /news +- VCL_call BACKEND_FETCH +- VCL_return fetch +- BerespStatus 200 +- TTL RFC 2 10 0 1792802660 1792802660 1792802659 0 2 cacheable +- VCL_call BACKEND_RESPONSE +- TTL VCL 2 3600 0 1792802660 cacheable +- VCL_return deliver + +* << BeReq >> 32771 +- Begin bereq 32770 bgfetch +- BereqURL /news +- VCL_call BACKEND_FETCH +- VCL_return fetch +- BerespStatus 500 +- TTL RFC -1 10 0 1792802663 1792802663 1792802662 0 0 cacheable +- VCL_call BACKEND_RESPONSE +- TTL VCL -1 3600 0 1792802663 cacheable +- TTL VCL 0 3600 0 1792802663 cacheable +- TTL VCL 0 86400 0 1792802663 cacheable +- VCL_return deliver + +* << BeReq >> 11 +- Begin bereq 10 fetch +- BereqURL /news +- VCL_call BACKEND_FETCH +- VCL_return fetch +- BerespStatus 500 +- TTL RFC -1 10 0 1792802664 1792802664 1792802664 0 0 cacheable +- VCL_call BACKEND_RESPONSE +- TTL VCL -1 3600 0 1792802664 cacheable +- TTL VCL 0 3600 0 1792802664 cacheable +- TTL VCL 0 86400 0 1792802664 cacheable +- VCL_return deliver + +* << BeReq >> 65539 +- Begin bereq 65538 fetch +- BereqURL /news +- VCL_call BACKEND_FETCH +- VCL_return fetch +- BerespStatus 500 +- TTL RFC -1 10 0 1792802665 1792802665 1792802665 0 0 cacheable +- VCL_call BACKEND_RESPONSE +- TTL VCL -1 3600 0 1792802665 cacheable +- TTL VCL 0 3600 0 1792802665 cacheable +- TTL VCL 0 86400 0 1792802665 cacheable +- VCL_return deliver + diff --git a/docs/exploratory-testing/2026-10-24-grace-and-purge/zero-freshness-dynamic.txt b/docs/exploratory-testing/2026-10-24-grace-and-purge/zero-freshness-dynamic.txt new file mode 100644 index 0000000..8ce8243 --- /dev/null +++ b/docs/exploratory-testing/2026-10-24-grace-and-purge/zero-freshness-dynamic.txt @@ -0,0 +1,29 @@ +# Journey 2 observations (each URL requested 3 times, ~1.2 s apart), master @ 8c9a304 +== p1?h_Cache-Control=max-age%3D0 +X-Origin-N: 5 Age: 0 X-Cache: MISS +X-Origin-N: 6 Age: 0 X-Cache: MISS +X-Origin-N: 7 Age: 0 X-Cache: MISS +== p2?h_Cache-Control=s-maxage%3D0 +X-Origin-N: 8 Age: 0 X-Cache: MISS +X-Origin-N: 10 Age: 0 X-Cache: MISS +X-Origin-N: 11 Age: 0 X-Cache: MISS +== p3?h_Expires=Fri,%2001%20Jan%202021%2000:00:00%20GMT +X-Origin-N: 12 Age: 0 X-Cache: MISS +X-Origin-N: 14 Age: 0 X-Cache: MISS +X-Origin-N: 15 Age: 0 X-Cache: MISS +== p4?h_Cache-Control=max-age%3D1 +X-Origin-N: 16 Age: 0 X-Cache: MISS +X-Origin-N: 16 Age: 1 X-Cache: HIT +X-Origin-N: 17 Age: 1 X-Cache: HIT +== p5?h_Cache-Control=no-cache +X-Origin-N: 20 Age: 0 X-Cache: MISS +X-Origin-N: 21 Age: 0 X-Cache: MISS +X-Origin-N: 22 Age: 0 X-Cache: MISS +== p6?h_Cache-Control=max-age%3D0,%20must-revalidate +X-Origin-N: 24 Age: 0 X-Cache: MISS +X-Origin-N: 25 Age: 0 X-Cache: MISS +X-Origin-N: 26 Age: 0 X-Cache: MISS +== app.css?h_Cache-Control=max-age%3D0 +X-Origin-N: 27 Age: 0 X-Cache: MISS +X-Origin-N: 29 Age: 0 X-Cache: MISS +X-Origin-N: 30 Age: 0 X-Cache: MISS diff --git a/docs/prd/cache-policy-module.md b/docs/prd/cache-policy-module.md index 9a9c1bb..c2375b3 100644 --- a/docs/prd/cache-policy-module.md +++ b/docs/prd/cache-policy-module.md @@ -49,3 +49,5 @@ This top architecture recommendation protects the repo's deepest module and give Exploratory feedback on cache policy, Surrogate-Control, and mutation invalidation: [2026-10-03 exploratory pass](../exploratory-testing/2026-10-03-cache-policy-surrogate-invalidation.md) (#124). Exploratory feedback on content-encoding reuse and relative-path invalidation: [2026-10-17 exploratory pass](../exploratory-testing/2026-10-17-site-cache-and-preflight.md) (#146, #147). + +Exploratory feedback on grace under origin 5xx and PURGE of encoding variants: [2026-10-24 exploratory pass](../exploratory-testing/2026-10-24-grace-and-purge.md) (#161, #162).