summercms/modules/sunscreen/sunscreen_test.go

package sunscreen

import (
	"bytes"
	"errors"
	"log"
	"log/slog"
	"net/http"
	"strings"
	"testing"
)

const (
	skKey   = "sk-abcdefghijklmnopqrstuvwxyz123456"
	antKey  = "sk-ant-api03-abcdefghijklmnopqrstuvwxyz"
	bearer  = "eyJhbGciOiJIUzI1NiJ9.payload.sig"
	apiKey  = "live-api-key-value"
	passwd  = "hunter2-secret-pass"
	nested  = "nested-token-value"
	valuerV = "valuer-secret-value"
)

type secretValuer struct{}

func (secretValuer) LogValue() slog.Value {
	return slog.GroupValue(slog.String("Token", valuerV), slog.String("name", "alice"))
}

type config struct {
	Endpoint string
	Header   string
}

func newTestLogger(buf *bytes.Buffer) *slog.Logger {
	return slog.New(Wrap(slog.NewTextHandler(buf, &slog.HandlerOptions{Level: slog.LevelDebug})))
}

func TestRedactHandler(t *testing.T) {
	var buf bytes.Buffer
	logger := newTestLogger(&buf)

	logger.With("API_KEY", apiKey, slog.Group("ctx", slog.String("password", passwd))).
		WithGroup("req").
		Info("calling vendor with Bearer "+bearer,
			"Authorization", "Bearer "+bearer,
			"user", 7,
			slog.Group("deep", slog.Group("deeper", slog.String("Secret", nested), slog.String("note", "key "+skKey))),
			"valuer", secretValuer{},
			"err", errors.New("upstream said: x-api-key: "+apiKey+", retry"),
			"headers", http.Header{"Authorization": {"Bearer " + bearer}, "Accept": {"application/json"}},
			"payload", map[string]any{"OpenAI_API_Key": skKey, "inner": map[string]string{"webhook_secret": nested, "ok": "fine"}},
			"cfg", config{Endpoint: "https://api.example.com", Header: "x-api-key: " + apiKey},
			"raw", []byte("token sk-"+strings.Repeat("Z", 24)),
			"anthropic", antKey,
		)
	out := buf.String()
	for _, secret := range []string{skKey, antKey, bearer, apiKey, passwd, nested, valuerV, strings.Repeat("Z", 24)} {
		if strings.Contains(out, secret) {
			t.Fatalf("log leaks %q:\n%s", secret, out)
		}
	}
	for _, want := range []string{
		"API_KEY=[REDACTED]",
		"ctx.password=[REDACTED]",
		"req.Authorization=[REDACTED]",
		"req.user=7",
		"req.deep.deeper.Secret=[REDACTED]",
		`req.deep.deeper.note="key sk-[REDACTED]"`,
		"req.valuer.Token=[REDACTED]",
		"req.valuer.name=alice",
		`x-api-key: [REDACTED]`,
		"Bearer [REDACTED]",
		"ok:fine",
		"https://api.example.com",
	} {
		if !strings.Contains(out, want) {
			t.Fatalf("log missing %q:\n%s", want, out)
		}
	}

	// Enabled follows the wrapped handler; wrapping twice is a no-op.
	quiet := Wrap(slog.NewTextHandler(&buf, &slog.HandlerOptions{Level: slog.LevelWarn}))
	if quiet.Enabled(t.Context(), slog.LevelInfo) || !quiet.Enabled(t.Context(), slog.LevelError) {
		t.Fatal("Enabled must follow the wrapped handler")
	}
	if Wrap(quiet) != quiet {
		t.Fatal("Wrap of a sunscreen handler must return it unchanged")
	}

	keys := RedactedKeys()
	keys[0] = "mutated"
	if RedactedKeys()[0] != "api_key" || len(keys) != 12 {
		t.Fatalf("RedactedKeys must return a copy of the 12 keys: %v", RedactedKeys())
	}

	buf.Reset()
	logger.Info("plain", "nil", nil, "count", 3, "ok", true)
	if !strings.Contains(buf.String(), "nil=<nil>") || !strings.Contains(buf.String(), "count=3") {
		t.Fatalf("non-secret values changed: %s", buf.String())
	}
}

func TestScrub(t *testing.T) {
	cases := []struct{ in, want string }{
		{"Authorization: Bearer abc.DEF-123_+/=", "Authorization: Bearer [REDACTED]"},
		{"bearer   lower.case.token", "Bearer [REDACTED]"},
		{"key=" + skKey + " end", "key=sk-[REDACTED] end"},
		{antKey, "sk-[REDACTED]"},
		{"sk-short", "sk-short"},
		{"X-API-KEY: abc123, next", "x-api-key: [REDACTED], next"},
		{"x-api-key:abc", "x-api-key: [REDACTED]"},
		{"nothing secret here: 42 albums", "nothing secret here: 42 albums"},
		{"", ""},
	}
	for _, c := range cases {
		if got := Scrub(c.in); got != c.want {
			t.Errorf("Scrub(%q) = %q, want %q", c.in, got, c.want)
		}
	}
	if Scrub(Scrub("Bearer abc")) != "Bearer [REDACTED]" {
		t.Fatal("Scrub must be idempotent")
	}
}

func TestInstallDefault(t *testing.T) {
	prev := slog.Default()
	prevFlags, prevWriter := log.Flags(), log.Writer()
	t.Cleanup(func() {
		slog.SetDefault(prev)
		log.SetFlags(prevFlags)
		log.SetOutput(prevWriter)
	})
	var buf bytes.Buffer
	InstallDefault(&buf)
	slog.Info("login", "password", passwd)
	log.Printf("legacy log with Bearer %s", bearer)
	out := buf.String()
	if strings.Contains(out, passwd) || strings.Contains(out, bearer) {
		t.Fatalf("default logger leaks:\n%s", out)
	}
	if !strings.Contains(out, "password=[REDACTED]") || !strings.Contains(out, "Bearer [REDACTED]") {
		t.Fatalf("default logger output:\n%s", out)
	}
}

// TestInstallDefaultUnchanged: InstallDefault, the compatibility entry
// point that generated applications no longer call, still installs a
// redacting logfmt TextHandler on the given writer, and each call replaces
// the previous default instead of wrapping it.
func TestInstallDefaultUnchanged(t *testing.T) {
	prev := slog.Default()
	prevFlags, prevWriter := log.Flags(), log.Writer()
	t.Cleanup(func() {
		slog.SetDefault(prev)
		log.SetFlags(prevFlags)
		log.SetOutput(prevWriter)
	})
	var first, second bytes.Buffer
	InstallDefault(&first)
	InstallDefault(&second)
	slog.Debug("below the default level", "token", nested)
	slog.Info("payment for Bearer "+bearer, "api_key", apiKey, slog.Group("g", "Password", passwd))
	if first.Len() != 0 {
		t.Fatalf("the replaced default still receives records:\n%s", first.String())
	}
	out := second.String()
	if strings.Count(out, "\n") != 1 {
		t.Fatalf("want exactly one line (info level, debug dropped):\n%s", out)
	}
	for _, want := range []string{"time=", " level=INFO ", `msg="payment for Bearer [REDACTED]"`, "api_key=[REDACTED]", "g.Password=[REDACTED]"} {
		if !strings.Contains(out, want) {
			t.Errorf("default output lacks %q:\n%s", want, out)
		}
	}
	for _, secret := range []string{bearer, apiKey, passwd, nested} {
		if strings.Contains(out, secret) {
			t.Errorf("default output leaks %q:\n%s", secret, out)
		}
	}
	if strings.HasPrefix(strings.TrimSpace(out), "{") {
		t.Errorf("default output is JSON, want logfmt:\n%s", out)
	}
}