sm-journal-plugin/classes/site_cache_test.go

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)
		}
	})
}