From 4405feeaa7e7d8c940b3edef12793ae10eeceb19 Mon Sep 17 00:00:00 2001 From: Jakub Zych Date: Sat, 10 Oct 2026 18:35:36 +0200 Subject: [PATCH] test(16.2-07): full coverage of the site cache purge - TestSiteCachePurgeConfig: every refused configuration names its key and never the token; https anywhere and http to loopback are accepted - TestSiteCachePurgeRequest: the contract request, Info and Warn lines, the 2 s timeout, a cancelled parent context, no token in any log line - Postgres: category create, update and delete and post create, untouched update (D-03 bytes kept), failing and unreachable purges and delete each purge once after the commit; failed saves send none --- classes/site_cache_test.go | 293 +++++++++++++++++++++++++++++++++++++ site_cache_admin_test.go | 213 +++++++++++++++++++++------ 2 files changed, 464 insertions(+), 42 deletions(-) create mode 100644 classes/site_cache_test.go diff --git a/classes/site_cache_test.go b/classes/site_cache_test.go new file mode 100644 index 0000000..a692bae --- /dev/null +++ b/classes/site_cache_test.go @@ -0,0 +1,293 @@ +package classes + +import ( + "bytes" + "context" + "encoding/json" + "io" + "log/slog" + "net/http" + "net/http/httptest" + "strconv" + "strings" + "sync" + "testing" + "time" +) + +const ( + purgeToken32 = "0123456789abcdef0123456789abcdef" + purgeToken40 = "site-cache-unit-token-0123456789abcdefgh" +) + +// captureLogs routes slog.Default to a text handler on a buffer for the +// test and returns the buffer. +func captureLogs(t *testing.T) *syncBuffer { + t.Helper() + buf := &syncBuffer{} + prev := slog.Default() + slog.SetDefault(slog.New(slog.NewTextHandler(buf, &slog.HandlerOptions{Level: slog.LevelDebug}))) + t.Cleanup(func() { slog.SetDefault(prev) }) + return buf +} + +type syncBuffer struct { + mu sync.Mutex + buf bytes.Buffer +} + +func (b *syncBuffer) Write(p []byte) (int, error) { + b.mu.Lock() + defer b.mu.Unlock() + return b.buf.Write(p) +} + +func (b *syncBuffer) lines() []string { + b.mu.Lock() + defer b.mu.Unlock() + var out []string + for _, line := range strings.Split(strings.TrimSpace(b.buf.String()), "\n") { + if line != "" { + out = append(out, line) + } + } + return out +} + +func TestSiteCachePurgeConfig(t *testing.T) { + refused := []struct { + name, url, token, key string + }{ + {"only the URL", "http://127.0.0.1:3016/api/__journal__/cache/purge", "", SiteCachePurgeTokenKey}, + {"only the token", "", purgeToken40, SiteCachePurgeURLKey}, + {"a bad scheme", "ftp://127.0.0.1/purge", purgeToken40, SiteCachePurgeURLKey}, + {"no scheme", "127.0.0.1:3016/purge", purgeToken40, SiteCachePurgeURLKey}, + {"no host", "http:///purge", purgeToken40, SiteCachePurgeURLKey}, + {"user info", "http://user:secret@127.0.0.1/purge", purgeToken40, SiteCachePurgeURLKey}, + {"a fragment", "http://127.0.0.1/purge#top", purgeToken40, SiteCachePurgeURLKey}, + {"an empty fragment", "http://127.0.0.1/purge#", purgeToken40, SiteCachePurgeURLKey}, + {"http to a non-loopback host", "http://example.test/purge", purgeToken40, SiteCachePurgeURLKey}, + {"http to a private address", "http://10.0.0.5:3016/purge", purgeToken40, SiteCachePurgeURLKey}, + {"a 31-character token", "http://127.0.0.1/purge", purgeToken32[:31], SiteCachePurgeTokenKey}, + } + for _, tc := range refused { + t.Run("refuses "+tc.name, func(t *testing.T) { + p, err := NewSiteCachePurger(tc.url, tc.token) + if err == nil || p != nil { + t.Fatalf("NewSiteCachePurger(%q) = %v, %v; want an error", tc.url, p, err) + } + if !strings.Contains(err.Error(), tc.key) { + t.Fatalf("error %q does not name %s", err, tc.key) + } + if tc.token != "" && strings.Contains(err.Error(), tc.token) { + t.Fatalf("error %q carries the token", err) + } + }) + } + + t.Run("both empty disables the purge", func(t *testing.T) { + p, err := NewSiteCachePurger("", "") + if p != nil || err != nil { + t.Fatalf("NewSiteCachePurger(\"\", \"\") = %v, %v; want nil, nil", p, err) + } + }) + + accepted := []struct { + url, endpoint string + }{ + {"https://cache.example.test/api/__journal__/cache/purge", "cache.example.test/api/__journal__/cache/purge"}, + {"http://127.0.0.1:3016/api/__journal__/cache/purge", "127.0.0.1:3016/api/__journal__/cache/purge"}, + {"http://127.9.8.7/purge", "127.9.8.7/purge"}, + {"http://[::1]:3000/purge", "[::1]:3000/purge"}, + {"http://localhost:3000/purge?x=1", "localhost:3000/purge"}, + } + for _, tc := range accepted { + t.Run("accepts "+tc.url, func(t *testing.T) { + p, err := NewSiteCachePurger(tc.url, purgeToken32) + if err != nil || p == nil { + t.Fatalf("NewSiteCachePurger(%q) = %v, %v; want a purger", tc.url, p, err) + } + if p.Endpoint() != tc.endpoint { + t.Fatalf("Endpoint() = %q, want %q", p.Endpoint(), tc.endpoint) + } + }) + } + + var nilPurger *SiteCachePurger + if nilPurger.Endpoint() != "" { + t.Fatal("a nil purger has an endpoint") + } +} + +// purgeHit is one request the test receiver got. +type purgeHit struct { + method, path, auth, contentType string + body map[string]string +} + +func purgeReceiver(t *testing.T, handle func(w http.ResponseWriter, r *http.Request)) (*httptest.Server, func() []purgeHit) { + t.Helper() + var mu sync.Mutex + var hits []purgeHit + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + raw, _ := io.ReadAll(r.Body) + var body map[string]string + _ = json.Unmarshal(raw, &body) + mu.Lock() + hits = append(hits, purgeHit{r.Method, r.URL.Path, r.Header.Get("Authorization"), r.Header.Get("Content-Type"), body}) + mu.Unlock() + handle(w, r) + })) + t.Cleanup(srv.Close) + return srv, func() []purgeHit { + mu.Lock() + defer mu.Unlock() + return append([]purgeHit(nil), hits...) + } +} + +func newTestPurger(t *testing.T, srv *httptest.Server) *SiteCachePurger { + t.Helper() + p, err := NewSiteCachePurger(srv.URL+"/api/__journal__/cache/purge", purgeToken40) + if err != nil { + t.Fatal(err) + } + return p +} + +func assertNoToken(t *testing.T, logs *syncBuffer) { + t.Helper() + for _, line := range logs.lines() { + if strings.Contains(line, purgeToken40) || strings.Contains(line, "Bearer") || strings.Contains(line, "Authorization") { + t.Fatalf("log line carries the token or the Authorization header: %s", line) + } + } +} + +func TestSiteCachePurgeRequest(t *testing.T) { + t.Run("sends the contract request and logs the purged count", func(t *testing.T) { + logs := captureLogs(t) + srv, hits := purgeReceiver(t, func(w http.ResponseWriter, _ *http.Request) { + w.Header().Set("Content-Type", "application/json") + _, _ = w.Write([]byte(`{"purged":7}`)) + }) + newTestPurger(t, srv).Purge(context.Background(), "category", "cordyceps") + got := hits() + if len(got) != 1 { + t.Fatalf("%d requests, want 1", len(got)) + } + h := got[0] + if h.method != http.MethodPost || h.path != "/api/__journal__/cache/purge" { + t.Fatalf("request %s %s", h.method, h.path) + } + if h.auth != "Bearer "+purgeToken40 || !strings.HasPrefix(h.contentType, "application/json") { + t.Fatalf("Authorization %q, Content-Type %q", h.auth, h.contentType) + } + if len(h.body) != 2 || h.body["kind"] != "category" || h.body["slug"] != "cordyceps" { + t.Fatalf("body = %#v", h.body) + } + lines := logs.lines() + if len(lines) != 1 || !strings.Contains(lines[0], "level=INFO") || !strings.Contains(lines[0], `msg="journal: site cache purged"`) || + !strings.Contains(lines[0], "kind=category") || !strings.Contains(lines[0], "slug=cordyceps") || + !strings.Contains(lines[0], "status=200") || !strings.Contains(lines[0], "purged=7") { + t.Fatalf("log = %q", lines) + } + assertNoToken(t, logs) + }) + + t.Run("an answer without purged logs the status only", func(t *testing.T) { + logs := captureLogs(t) + srv, _ := purgeReceiver(t, func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusNoContent) }) + newTestPurger(t, srv).Purge(context.Background(), "post", "hello") + lines := logs.lines() + if len(lines) != 1 || !strings.Contains(lines[0], "level=INFO") || !strings.Contains(lines[0], "status=204") || strings.Contains(lines[0], "purged=") { + t.Fatalf("log = %q", lines) + } + }) + + for _, status := range []int{http.StatusInternalServerError, http.StatusUnauthorized} { + t.Run("a "+http.StatusText(status)+" answer logs one warning", func(t *testing.T) { + logs := captureLogs(t) + srv, hits := purgeReceiver(t, func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(status) }) + newTestPurger(t, srv).Purge(context.Background(), "post", "hello") + if len(hits()) != 1 { + t.Fatalf("%d requests, want 1", len(hits())) + } + lines := logs.lines() + if len(lines) != 1 || !strings.Contains(lines[0], "level=WARN") || !strings.Contains(lines[0], `msg="journal: site cache purge failed"`) || + !strings.Contains(lines[0], "kind=post") || !strings.Contains(lines[0], "slug=hello") { + t.Fatalf("log = %q", lines) + } + if !strings.Contains(lines[0], "status="+strconv.Itoa(status)) { + t.Fatalf("log %q lacks status=%d", lines[0], status) + } + assertNoToken(t, logs) + }) + } + + t.Run("a slow receiver is abandoned after the timeout", func(t *testing.T) { + logs := captureLogs(t) + release := make(chan struct{}) + srv, _ := purgeReceiver(t, func(_ http.ResponseWriter, r *http.Request) { + select { + case <-release: + case <-r.Context().Done(): + } + }) + defer close(release) + start := time.Now() + newTestPurger(t, srv).Purge(context.Background(), "post", "slow") + elapsed := time.Since(start) + if elapsed < SiteCachePurgeTimeout-200*time.Millisecond || elapsed > SiteCachePurgeTimeout+1500*time.Millisecond { + t.Fatalf("Purge returned after %s, want about %s", elapsed, SiteCachePurgeTimeout) + } + lines := logs.lines() + if len(lines) != 1 || !strings.Contains(lines[0], "level=WARN") || !strings.Contains(lines[0], "error=timeout") { + t.Fatalf("log = %q", lines) + } + assertNoToken(t, logs) + }) + + t.Run("an unreachable receiver logs one warning without the URL's token", func(t *testing.T) { + logs := captureLogs(t) + srv, _ := purgeReceiver(t, func(http.ResponseWriter, *http.Request) {}) + p := newTestPurger(t, srv) + srv.Close() + p.Purge(context.Background(), "category", "gone") + lines := logs.lines() + if len(lines) != 1 || !strings.Contains(lines[0], "level=WARN") || !strings.Contains(lines[0], "kind=category") { + t.Fatalf("log = %q", lines) + } + assertNoToken(t, logs) + }) + + t.Run("a cancelled parent context still sends", func(t *testing.T) { + captureLogs(t) + srv, hits := purgeReceiver(t, func(w http.ResponseWriter, _ *http.Request) { _, _ = w.Write([]byte(`{"purged":1}`)) }) + ctx, cancel := context.WithCancel(context.Background()) + cancel() + newTestPurger(t, srv).Purge(ctx, "post", "after-cancel") + if got := hits(); len(got) != 1 || got[0].body["slug"] != "after-cancel" { + t.Fatalf("requests = %#v, want one", got) + } + }) + + t.Run("a nil purger sends nothing", func(t *testing.T) { + logs := captureLogs(t) + var p *SiteCachePurger + p.Purge(context.Background(), "post", "nil") + PurgeSiteCacheAfterCommit(context.Background(), nil, nil, "post", "nil") + if lines := logs.lines(); len(lines) != 0 { + t.Fatalf("log = %q, want nothing", lines) + } + }) + + t.Run("outside a transaction the after-commit purge runs at once", func(t *testing.T) { + captureLogs(t) + srv, hits := purgeReceiver(t, func(w http.ResponseWriter, _ *http.Request) { _, _ = w.Write([]byte(`{"purged":2}`)) }) + PurgeSiteCacheAfterCommit(context.Background(), nil, newTestPurger(t, srv), "category", "now") + if got := hits(); len(got) != 1 || got[0].body["kind"] != "category" || got[0].body["slug"] != "now" { + t.Fatalf("requests = %#v, want one", got) + } + }) +} diff --git a/site_cache_admin_test.go b/site_cache_admin_test.go index 005cd37..f940fe5 100644 --- a/site_cache_admin_test.go +++ b/site_cache_admin_test.go @@ -91,6 +91,12 @@ func (r *purgeReceiver) take() []purgeRequest { return got } +func (r *purgeReceiver) setStatus(status int) { + r.mu.Lock() + r.status = status + r.mu.Unlock() +} + func (r *purgeReceiver) setProbe(probe func() string) { r.mu.Lock() r.probe = probe @@ -121,14 +127,30 @@ func (r *purgeReceiver) expectOnePurge(t *testing.T, stage, kind, slug string) p return req } -// TestCategoriesAdminPurgesSiteCache proves an admin update of a category -// sends one authorized purge request to the host site after the save -// transaction commits (G-16.2-2, D-19). +// TestCategoriesAdminPurgesSiteCache proves every admin write of a category +// sends one authorized purge request with kind category after the save +// transaction commits, and a failed save sends none (G-16.2-2, D-19). func TestCategoriesAdminPurgesSiteCache(t *testing.T) { recv := newPurgeReceiver(t) env := newPostsEnv(t, recv.env()...) token := env.admin(t, controllers.PermissionAccessCategories) + // The probe reads the committed row through the pool while the purge + // request is in flight: "" or "missing". + recv.setProbe(func() string { + var cat models.Category + if err := env.gdb.Where("slug = ?", "purge-news").Limit(1).Find(&cat).Error; err != nil { + return "error: " + err.Error() + } + if cat.ID == 0 { + return "missing" + } + if cat.Content == nil { + return "" + } + return *cat.Content + }) + rec := env.expect(t, http.StatusCreated, http.MethodPost, adminAPI(adminCategoriesPath), token, map[string]any{ "name": map[string]any{"en": "Purge news", "pl": "Wiadomości"}, "slug": map[string]any{"en": "purge-news", "pl": "wiadomosci"}, @@ -136,43 +158,71 @@ func TestCategoriesAdminPurgesSiteCache(t *testing.T) { }) id := adminCreatedID(t, rec) itemPath := adminAPI(fmt.Sprintf("%s/%d", adminCategoriesPath, id)) - recv.take() + if req := recv.expectOnePurge(t, "create", "category", "purge-news"); req.Seen != "

Before

\n" { + t.Fatalf("create: the purge saw %q, want the committed row", req.Seen) + } - content := func() string { - var cat models.Category - if err := env.gdb.First(&cat, id).Error; err != nil { - return "error: " + err.Error() + served := func(t *testing.T) map[string]json.RawMessage { + t.Helper() + rec := env.expect(t, http.StatusOK, http.MethodGet, itemPath, token, nil) + var data map[string]json.RawMessage + if err := json.Unmarshal(adminDecode(t, rec).Data, &data); err != nil { + t.Fatal(err) } - if cat.Content == nil { - return "" + return data + } + + t.Run("update", func(t *testing.T) { + const edited = "

After the edit

\n" + body := servedBody(served(t), "name", "slug") + body["content"] = edited + env.expect(t, http.StatusOK, http.MethodPut, itemPath, token, body) + if req := recv.expectOnePurge(t, "update", "category", "purge-news"); req.Seen != edited { + t.Fatalf("the purge saw content %q, want the committed %q (purge before commit)", req.Seen, edited) } - return *cat.Content - } - recv.setProbe(content) + }) - rec = env.expect(t, http.StatusOK, http.MethodGet, itemPath, token, nil) - var served map[string]json.RawMessage - if err := json.Unmarshal(adminDecode(t, rec).Data, &served); err != nil { - t.Fatal(err) - } - const edited = "

After the edit

\n" - body := servedBody(served, "name", "slug") - body["content"] = edited - env.expect(t, http.StatusOK, http.MethodPut, itemPath, token, body) + t.Run("a failed update sends none", func(t *testing.T) { + body := servedBody(served(t), "slug") + body["name"] = map[string]any{"en": "", "pl": ""} + body["content"] = "

Refused

\n" + if rec := env.call(t, http.MethodPut, itemPath, token, body); rec.Code != http.StatusUnprocessableEntity { + t.Fatalf("update without a name = %d, want 422: %s", rec.Code, rec.Body.String()) + } + if got := recv.take(); len(got) != 0 { + t.Fatalf("a failed update sent %d purge requests: %+v", len(got), got) + } + }) - req := recv.expectOnePurge(t, "update", "category", "purge-news") - if req.Seen != edited { - t.Fatalf("the purge saw content %q, want the committed %q (purge before commit)", req.Seen, edited) - } + t.Run("delete", func(t *testing.T) { + env.expect(t, http.StatusOK, http.MethodDelete, itemPath, token, nil) + if req := recv.expectOnePurge(t, "delete", "category", "purge-news"); req.Seen != "missing" { + t.Fatalf("the purge saw %q, want the row already deleted", req.Seen) + } + }) } -// TestPostsAdminPurgesSiteCache proves an admin update of a post sends one -// authorized purge request with kind post after the save commits. +// TestPostsAdminPurgesSiteCache proves every admin write of a post sends one +// authorized purge request with kind post after the commit, that an +// untouched save still purges and keeps both content columns byte for byte +// (D-03), that a refused, failing or unreachable purge never changes the +// save response, and that a failed save sends none. func TestPostsAdminPurgesSiteCache(t *testing.T) { recv := newPurgeReceiver(t) env := newPostsEnv(t, recv.env()...) token := env.admin(t, controllers.PermissionAccessPosts) + recv.setProbe(func() string { + var post models.Post + if err := env.gdb.Where("slug = ?", "purge-post").Limit(1).Find(&post).Error; err != nil { + return "error: " + err.Error() + } + if post.ID == 0 { + return "missing" + } + return post.ContentHTML + }) + rec := env.expect(t, http.StatusCreated, http.MethodPost, adminAPI(adminPostsPath), token, map[string]any{ "title": map[string]any{"en": "Purge post", "pl": "Wpis"}, "slug": map[string]any{"en": "purge-post", "pl": "wpis"}, @@ -180,23 +230,102 @@ func TestPostsAdminPurgesSiteCache(t *testing.T) { "excerpt": map[string]any{"en": "Excerpt", "pl": "Wyjątek"}, }) id := adminCreatedID(t, rec) - recv.take() + itemPath := adminAPI(fmt.Sprintf("%s/%d", adminPostsPath, id)) + if req := recv.expectOnePurge(t, "create", "post", "purge-post"); req.Seen != "

Before

" { + t.Fatalf("create: the purge saw %q, want the committed row", req.Seen) + } - recv.setProbe(func() string { + put := func(t *testing.T, content string) *httptest.ResponseRecorder { + t.Helper() + body := servedBody(servedForm(t, env, token, id), "title", "slug", "excerpt") + body["content"] = map[string]any{"en": content} + return env.call(t, http.MethodPut, itemPath, token, body) + } + stored := func(t *testing.T) models.Post { + t.Helper() var post models.Post if err := env.gdb.First(&post, id).Error; err != nil { - return "error: " + err.Error() + t.Fatal(err) } - return post.ContentHTML - }) - served := servedForm(t, env, token, id) - const edited = "

After the edit

" - body := servedBody(served, "title", "slug", "excerpt") - body["content"] = map[string]any{"en": edited} - env.expect(t, http.StatusOK, http.MethodPut, adminAPI(fmt.Sprintf("%s/%d", adminPostsPath, id)), token, body) - - req := recv.expectOnePurge(t, "update", "post", "purge-post") - if req.Seen != edited { - t.Fatalf("the purge saw content_html %q, want the committed %q (purge before commit)", req.Seen, edited) + return post } + + t.Run("update", func(t *testing.T) { + const edited = "

After the edit

" + if rec := put(t, edited); rec.Code != http.StatusOK { + t.Fatalf("update = %d: %s", rec.Code, rec.Body.String()) + } + if req := recv.expectOnePurge(t, "update", "post", "purge-post"); req.Seen != edited { + t.Fatalf("the purge saw content_html %q, want the committed %q (purge before commit)", req.Seen, edited) + } + }) + + t.Run("an untouched update purges and keeps both columns", func(t *testing.T) { + const imported = "\n\n

Kept as stored

\n" + const importedHTML = "

Rendered elsewhere

\n" + if err := env.gdb.Model(&models.Post{}).Where("id = ?", id).Updates(map[string]any{"content": imported, "content_html": importedHTML}).Error; err != nil { + t.Fatal(err) + } + served := servedForm(t, env, token, id) + env.expect(t, http.StatusOK, http.MethodPut, itemPath, token, servedBody(served, "title", "slug", "excerpt", "content")) + recv.expectOnePurge(t, "untouched update", "post", "purge-post") + assertHostContent(t, env, id, "untouched update", imported, importedHTML) + }) + + t.Run("a failed save sends none", func(t *testing.T) { + // The admin lacks access_publish: FormBeforeUpdate refuses inside + // the save transaction. + body := servedBody(servedForm(t, env, token, id), "title", "slug", "excerpt") + body["published"] = true + if rec := env.call(t, http.MethodPut, itemPath, token, body); rec.Code != http.StatusForbidden { + t.Fatalf("publish without access_publish = %d, want 403: %s", rec.Code, rec.Body.String()) + } + if got := recv.take(); len(got) != 0 { + t.Fatalf("a failed save sent %d purge requests: %+v", len(got), got) + } + }) + + t.Run("a failing purge never changes the save", func(t *testing.T) { + recv.setStatus(http.StatusInternalServerError) + defer recv.setStatus(http.StatusOK) + const edited = "

Saved while the site answers 500

" + if rec := put(t, edited); rec.Code != http.StatusOK { + t.Fatalf("update with a failing purge = %d: %s", rec.Code, rec.Body.String()) + } + recv.expectOnePurge(t, "failing purge", "post", "purge-post") + if got := stored(t); got.Content != edited || got.ContentHTML != edited { + t.Fatalf("stored = %q / %q, want %q", got.Content, got.ContentHTML, edited) + } + }) + + t.Run("delete", func(t *testing.T) { + spare := env.expect(t, http.StatusCreated, http.MethodPost, adminAPI(adminPostsPath), token, map[string]any{ + "title": map[string]any{"en": "Spare"}, + "slug": map[string]any{"en": "spare-post"}, + "content": map[string]any{"en": "

Spare

"}, + }) + spareID := adminCreatedID(t, spare) + recv.expectOnePurge(t, "spare create", "post", "spare-post") + env.expect(t, http.StatusOK, http.MethodDelete, adminAPI(fmt.Sprintf("%s/%d", adminPostsPath, spareID)), token, nil) + recv.expectOnePurge(t, "delete", "post", "spare-post") + var n int64 + if err := env.gdb.Model(&models.Post{}).Where("id = ?", spareID).Count(&n).Error; err != nil || n != 0 { + t.Fatalf("spare post rows = %d (%v), want 0", n, err) + } + }) + + // Last: closing the receiver ends its use for this env. + t.Run("an unreachable site never changes the save", func(t *testing.T) { + recv.srv.Close() + const edited = "

Saved while nothing listens

" + if rec := put(t, edited); rec.Code != http.StatusOK { + t.Fatalf("update with no receiver = %d: %s", rec.Code, rec.Body.String()) + } + if got := stored(t); got.Content != edited || got.ContentHTML != edited { + t.Fatalf("stored = %q / %q, want %q", got.Content, got.ContentHTML, edited) + } + if got := recv.take(); len(got) != 0 { + t.Fatalf("a closed receiver recorded %d requests", len(got)) + } + }) }