felhom.eu/hub/internal/accesslog/accesslog_test.go

package accesslog

import (
	"net/http"
	"net/http/httptest"
	"os"
	"path/filepath"
	"sort"
	"strings"
	"sync"
	"testing"
	"time"
)

type clock struct {
	mu sync.Mutex
	t  time.Time
}

func (c *clock) now() time.Time  { c.mu.Lock(); defer c.mu.Unlock(); return c.t }
func (c *clock) set(t time.Time) { c.mu.Lock(); c.t = t; c.mu.Unlock() }

func readAll(t *testing.T, dir string) string {
	t.Helper()
	ents, _ := os.ReadDir(dir)
	var b strings.Builder
	for _, e := range ents {
		raw, err := os.ReadFile(filepath.Join(dir, e.Name()))
		if err != nil {
			t.Fatal(err)
		}
		b.Write(raw)
	}
	return b.String()
}

func serve(h http.Handler, r *http.Request) *httptest.ResponseRecorder {
	w := httptest.NewRecorder()
	h.ServeHTTP(w, r)
	return w
}

// A request is logged: one line, in today's file, with method, path, status, the socket peer, the forwarded-for hop and
// the identity kind the handler's auth helper marked.
func TestAccessLog_ARequestIsLogged(t *testing.T) {
	dir := t.TempDir()
	c := &clock{t: time.Date(2026, 10, 17, 20, 35, 16, 0, time.UTC)}
	l := New(Options{Dir: dir, Now: c.now})
	h := l.Middleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		Mark(r.Context(), "customer")
		w.WriteHeader(http.StatusAccepted)
	}))
	r := httptest.NewRequest(http.MethodPost, "/api/v1/report", nil)
	r.RemoteAddr = "10.42.0.31:51234"
	r.Header.Set("X-Forwarded-For", "192.168.0.149")
	r.Header.Set("Authorization", "Bearer 0123")
	if w := serve(h, r); w.Code != http.StatusAccepted {
		t.Fatalf("status %d", w.Code)
	}
	l.Close()
	raw, err := os.ReadFile(filepath.Join(dir, "access-2026-10-17.log"))
	if err != nil {
		t.Fatalf("today's file: %v", err)
	}
	want := "2026-10-17T20:35:16Z POST /api/v1/report 202 0ms remote=10.42.0.31 xff=192.168.0.149 cred=bearer auth=customer\n"
	if string(raw) != want {
		t.Fatalf("line =\n%q\nwant\n%q", raw, want)
	}
	if fi, _ := os.Stat(filepath.Join(dir, "access-2026-10-17.log")); fi.Mode().Perm() != 0o600 {
		t.Fatalf("file mode %v, want 0600", fi.Mode().Perm())
	}
}

// NO SECRET REACHES THE FILE: a bearer token, an operator access token, Basic credentials, a session cookie, a
// retrieval passphrase, a token in the query string, a self-bind capability in the path, a long secret-shaped path
// segment, and a secret stuffed into X-Forwarded-For. Positive control: the same line's path and method ARE there.
// RED-PROOF (2026-10-17 night): with SafePath returning r.URL.RequestURI() (the raw URL), this fails with
// `secrets written to the access log: [bind query segment]`.
func TestAccessLog_NeverWritesASecret(t *testing.T) {
	secrets := map[string]string{
		"bearer":     "4f1c9e2b7a60d38e5b9c0a1f2e3d4c5b6a7980f1e2d3c4b5a69788f0e1d2c3b4",
		"fhp":        "fhp_abcdefghijklmnopqrstuvwxyz234567abcdefghijklmnopqrst",
		"basic":      "operator-password-Xy9",
		"cookie":     "c0ffee0123456789c0ffee0123456789c0ffee0123456789c0ffee0123456789",
		"passphrase": "korte-alma-szilva-barack",
		"query":      "QUERYTOKEN-5d2a9f",
		"bind":       "BINDTOKEN-77aa88bb99cc",
		"segment":    "Zm9vYmFyYmF6cXV4cXV1eHF1dXhxdXV4cXV1eA",
		"xff":        "XFFSECRET-123",
	}
	dir := t.TempDir()
	l := New(Options{Dir: dir})
	h := l.Middleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {}))
	reqs := []*http.Request{
		httptest.NewRequest(http.MethodGet, "/api/v1/wait?gen=4&token="+secrets["query"], nil),
		httptest.NewRequest(http.MethodGet, "/bind/"+secrets["bind"], nil),
		httptest.NewRequest(http.MethodPost, "/bind/"+secrets["bind"]+"/resend", nil),
		httptest.NewRequest(http.MethodGet, "/api/v1/assets/file/"+secrets["segment"], nil),
		httptest.NewRequest(http.MethodGet, "/configuration", nil),
	}
	reqs[0].Header.Set("Authorization", "Bearer "+secrets["bearer"])
	reqs[1].Header.Set("Authorization", "Bearer "+secrets["fhp"])
	reqs[2].SetBasicAuth("operator", secrets["basic"])
	reqs[3].AddCookie(&http.Cookie{Name: "__Host-hub_session", Value: secrets["cookie"]})
	reqs[4].Header.Set("X-Retrieval-Password", secrets["passphrase"])
	reqs[4].Header.Set("X-Forwarded-For", secrets["xff"]+", 192.168.0.149")
	for _, r := range reqs {
		serve(h, r)
	}
	l.Close()
	got := readAll(t, dir)
	var leaked []string
	for name, v := range secrets {
		if strings.Contains(got, v) {
			leaked = append(leaked, name)
		}
	}
	sort.Strings(leaked)
	if len(leaked) > 0 {
		t.Fatalf("secrets written to the access log: %v\n%s", leaked, got)
	}
	for _, want := range []string{"GET /api/v1/wait 200", "GET /bind/[redacted] 200", "POST /bind/[redacted]/resend",
		"/api/v1/assets/file/[redacted]", "cred=token", "cred=basic", "cred=session-cookie", "cred=passphrase", "xff=?,192.168.0.149"} {
		if !strings.Contains(got, want) {
			t.Errorf("positive control missing %q in\n%s", want, got)
		}
	}
	if n := strings.Count(got, "\n"); n != len(reqs) {
		t.Errorf("%d line(s), want %d", n, len(reqs))
	}
}

// Day files older than 90 days are removed — at start and at each new day — and nothing else in the directory is.
func TestAccessLog_Keeps90DaysThenDeletes(t *testing.T) {
	dir := t.TempDir()
	for _, n := range []string{"access-2026-07-18.log", "access-2026-07-19.log", "access-2026-10-16.log", "notes.txt", "access-2026-07-01.log.keep"} {
		if err := os.WriteFile(filepath.Join(dir, n), []byte("x\n"), 0o600); err != nil {
			t.Fatal(err)
		}
	}
	c := &clock{t: time.Date(2026, 10, 17, 1, 0, 0, 0, time.UTC)}
	l := New(Options{Dir: dir, Now: c.now})
	h := l.Middleware(http.HandlerFunc(func(http.ResponseWriter, *http.Request) {}))
	serve(h, httptest.NewRequest(http.MethodGet, "/", nil))
	// The next day: the first line of 2026-10-18 opens a new file and prunes again (2026-07-19 is now 91 days old).
	// Let the writer take the first line on 10-17 before the clock moves (poll the file, never a bare sleep).
	for i := 0; ; i++ {
		if _, err := os.Stat(filepath.Join(dir, "access-2026-10-17.log")); err == nil {
			break
		}
		if i == 200 {
			t.Fatal("the 10-17 line was never written")
		}
		time.Sleep(10 * time.Millisecond)
	}
	c.set(time.Date(2026, 10, 18, 0, 0, 5, 0, time.UTC))
	serve(h, httptest.NewRequest(http.MethodGet, "/", nil))
	l.Close()
	var names []string
	ents, _ := os.ReadDir(dir)
	for _, e := range ents {
		names = append(names, e.Name())
	}
	sort.Strings(names)
	want := []string{"access-2026-07-01.log.keep", "access-2026-10-16.log", "access-2026-10-17.log", "access-2026-10-18.log", "notes.txt"}
	if strings.Join(names, " ") != strings.Join(want, " ") {
		t.Fatalf("files = %v\nwant    %v", names, want)
	}
}

// A logging failure never fails the request: the directory cannot be created, the handler's answer is unchanged, and
// the failure is reported (once a minute at most) to the hub's own log.
func TestAccessLog_FailureNeverFailsTheRequest(t *testing.T) {
	blocker := filepath.Join(t.TempDir(), "file-not-dir")
	if err := os.WriteFile(blocker, nil, 0o600); err != nil {
		t.Fatal(err)
	}
	var mu sync.Mutex
	var reported []string
	l := New(Options{Dir: filepath.Join(blocker, "access-log"), Logf: func(f string, a ...any) {
		mu.Lock()
		reported = append(reported, f)
		mu.Unlock()
	}})
	h := l.Middleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		w.WriteHeader(http.StatusTeapot)
		_, _ = w.Write([]byte("served"))
	}))
	for i := 0; i < 3; i++ {
		w := serve(h, httptest.NewRequest(http.MethodGet, "/x", nil))
		if w.Code != http.StatusTeapot || w.Body.String() != "served" {
			t.Fatalf("request %d altered by the log failure: %d %q", i, w.Code, w.Body.String())
		}
	}
	l.Close()
	mu.Lock()
	defer mu.Unlock()
	if len(reported) != 1 || !strings.Contains(reported[0], "request was served") {
		t.Fatalf("failure reports = %q, want exactly one (rate-limited)", reported)
	}
}

// The long-poll keeps working through the recorder: http.ResponseController reaches Flush through Unwrap/Flush.
func TestAccessLog_FlushPassesThrough(t *testing.T) {
	l := New(Options{Dir: t.TempDir()})
	defer l.Close()
	var ferr error
	h := l.Middleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		w.WriteHeader(http.StatusOK)
		ferr = http.NewResponseController(w).Flush()
	}))
	w := serve(h, httptest.NewRequest(http.MethodGet, "/api/v1/wait", nil))
	if ferr != nil || !w.Flushed {
		t.Fatalf("flush through the access log: err=%v flushed=%v", ferr, w.Flushed)
	}
}

// kube-probe's own /healthz is not logged; one that came through the ingress is.
func TestAccessLog_SkipsOnlyTheKubeletProbe(t *testing.T) {
	dir := t.TempDir()
	l := New(Options{Dir: dir})
	h := l.Middleware(http.HandlerFunc(func(http.ResponseWriter, *http.Request) {}))
	probe := httptest.NewRequest(http.MethodGet, "/healthz", nil)
	probe.Header.Set("User-Agent", "kube-probe/1.31")
	serve(h, probe)
	viaIngress := httptest.NewRequest(http.MethodGet, "/healthz", nil)
	viaIngress.Header.Set("User-Agent", "kube-probe/1.31")
	viaIngress.Header.Set("X-Forwarded-For", "37.191.56.193")
	serve(h, viaIngress)
	l.Close()
	got := readAll(t, dir)
	if strings.Count(got, "/healthz") != 1 || !strings.Contains(got, "xff=37.191.56.193") {
		t.Fatalf("want exactly the ingress /healthz logged, got:\n%s", got)
	}
}