Files
OwnCord/Server/admin/multihandler_test.go
T
Claude 0918f859a0 test: close measured test-coverage gaps across server, client and Rust
Audits what actually has tests, then closes the gaps it found. Full write-up
with before/after numbers in docs/audit-test-coverage-2026-07-25.md.

Measurement first: `go test ./... -coverprofile` (what CI runs) instruments
each package only for itself, so code exercised through another package's
tests reads as uncovered — `service` reported 36.7% against a real 85%. All
analysis here uses -coverpkg=./..., and both views now have Makefile targets.

Features that had zero coverage at every layer:
- user blocking (db + service + the /api/v1/blocks routes)
- auth lockout persistence — the DB round-trip that survives a restart
- plugin install/enable/disable/uninstall and the plugin KV namespace
- event replay bounds (GetMaxEventSeq, PruneEventsOlderThan)
- LiveKit participant_joined webhook (replayed-token guard), the room-service
  client, and proxyWebSocket/copyWS
- ws_proxy.rs and livekit_proxy.rs — pure helpers extracted, matching the
  existing tofu.rs pattern, so cert-pin and header-injection checks are testable

Gaps that were hidden rather than absent:
- Server/admin reported 0.3% coverage with 307 tests passing. TestSpawnDetached_*
  re-execs the test binary; the child inherited GOCOVERDIR and the parent's
  stdout, clobbering the profile and printing "[no tests to run]". Now 71.4%,
  and CI's uploaded artifact is correct.
- vitest.config.ts excluded 2.2k LOC unexplained, including two files that
  already had tests. Trimmed to three entries, each justified inline.
- api.HandleLiveKitHealthForTest re-implemented the handler it claimed to
  expose, so eight call sites tested a copy. Added a hook to the real one.

Two bugs found and pinned rather than silently patched: logctx.WithGroup nests
req_id under the group, and drag-reorder.ts takes one listener ref per channel
but releases one per sidebar, so the count never reaches zero.

Coverage: client 92.93% -> 94.87% statements (3371 -> 3572 tests) even after
un-excluding hidden files; Rust 47 -> 74 tests; Go zero-coverage functions
~70 -> 21, with plugin 61->77%, admin 67->86%, db 76->84%, service 85->91%.

Verified: go vet, all four build-tag variants, go test -race, -tags deadlock,
vitest --coverage, cargo test --lib, cargo clippy --all-targets, playwright.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01AEETs3Vh6sAHHb1jMBL75g
2026-07-25 14:47:21 +00:00

302 lines
8.7 KiB
Go

package admin
import (
"bytes"
"context"
"encoding/json"
"log/slog"
"strings"
"testing"
)
// The multiHandler tees every server log record into the admin panel's live
// log stream. Eleven of its functions had no coverage — including Subscribe,
// which is what a connected admin's SSE session hangs off. A silent break here
// makes the log viewer look like a quiet server.
// newTeeLogger wires a logger through NewMultiHandler and returns the logger,
// the ring buffer it feeds, and an accessor for the stdout side.
func newTeeLogger(t *testing.T, minLevel slog.Leveler) (*slog.Logger, *RingBuffer, func() string) {
t.Helper()
var stdout bytes.Buffer
buf := NewRingBuffer(16)
h := NewMultiHandler(
slog.NewTextHandler(&stdout, &slog.HandlerOptions{Level: slog.LevelInfo}),
buf, minLevel,
)
return slog.New(h), buf, stdout.String
}
func TestNewMultiHandler_TeesToBothSinks(t *testing.T) {
logger, buf, stdout := newTeeLogger(t, slog.LevelDebug)
logger.Info("hello admin")
entries := buf.Snapshot()
if len(entries) != 1 {
t.Fatalf("ring buffer has %d entries, want 1", len(entries))
}
if entries[0].Message != "hello admin" {
t.Errorf("Message = %q, want %q", entries[0].Message, "hello admin")
}
if entries[0].Level != "INFO" {
t.Errorf("Level = %q, want INFO", entries[0].Level)
}
if entries[0].Timestamp == "" {
t.Error("Timestamp is empty")
}
if !strings.Contains(stdout(), "hello admin") {
t.Errorf("record did not reach stdout; got %q", stdout())
}
}
func TestMultiHandler_Enabled(t *testing.T) {
// stdout is at Info; the ring buffer is at Debug. Enabled is the union, so
// a Debug record must still be handled — that is how the admin panel can
// show debug lines the console does not.
logger, buf, stdout := newTeeLogger(t, slog.LevelDebug)
logger.Debug("debug only")
if entries := buf.Snapshot(); len(entries) != 1 {
t.Errorf("ring buffer has %d entries, want the debug record", len(entries))
}
if strings.Contains(stdout(), "debug only") {
t.Error("a Debug record reached the Info-level stdout handler")
}
}
func TestMultiHandler_RingLevelFiltersOutLowRecords(t *testing.T) {
logger, buf, _ := newTeeLogger(t, slog.LevelWarn)
logger.Info("below the ring threshold")
logger.Warn("at the ring threshold")
entries := buf.Snapshot()
if len(entries) != 1 {
t.Fatalf("ring buffer has %d entries, want 1", len(entries))
}
if entries[0].Message != "at the ring threshold" {
t.Errorf("Message = %q, want the Warn record", entries[0].Message)
}
}
func TestMultiHandler_WithAttrs(t *testing.T) {
logger, buf, _ := newTeeLogger(t, slog.LevelDebug)
logger.With("user_id", 42).Info("with attrs", "extra", "yes")
entries := buf.Snapshot()
if len(entries) != 1 {
t.Fatalf("ring buffer has %d entries, want 1", len(entries))
}
var attrs map[string]any
if err := json.Unmarshal([]byte(entries[0].Attrs), &attrs); err != nil {
t.Fatalf("unmarshal attrs %q: %v", entries[0].Attrs, err)
}
// Both the WithAttrs-supplied attr and the per-record attr must survive.
if _, ok := attrs["user_id"]; !ok {
t.Errorf("attrs = %v, want user_id from WithAttrs", attrs)
}
if attrs["extra"] != "yes" {
t.Errorf("attrs[extra] = %v, want \"yes\"", attrs["extra"])
}
}
func TestMultiHandler_WithAttrs_DoesNotMutateParent(t *testing.T) {
logger, buf, _ := newTeeLogger(t, slog.LevelDebug)
child := logger.With("scoped", "child")
child.Info("from child")
logger.Info("from parent")
entries := buf.Snapshot()
if len(entries) != 2 {
t.Fatalf("ring buffer has %d entries, want 2", len(entries))
}
// withAttrs copies into a fresh slice; the parent must not inherit them.
for _, e := range entries {
if e.Message == "from parent" && strings.Contains(e.Attrs, "scoped") {
t.Errorf("parent record picked up the child's attrs: %q", e.Attrs)
}
}
}
func TestMultiHandler_WithGroup(t *testing.T) {
logger, buf, _ := newTeeLogger(t, slog.LevelDebug)
logger.WithGroup("req").Info("grouped", "id", "abc")
entries := buf.Snapshot()
if len(entries) != 1 {
t.Fatalf("ring buffer has %d entries, want 1", len(entries))
}
var attrs map[string]any
if err := json.Unmarshal([]byte(entries[0].Attrs), &attrs); err != nil {
t.Fatalf("unmarshal attrs %q: %v", entries[0].Attrs, err)
}
if attrs["req.id"] != "abc" {
t.Errorf("attrs = %v, want the group-qualified key req.id", attrs)
}
}
func TestMultiHandler_NestedGroups(t *testing.T) {
logger, buf, _ := newTeeLogger(t, slog.LevelDebug)
logger.WithGroup("outer").WithGroup("inner").Info("nested", "k", "v")
entries := buf.Snapshot()
if len(entries) != 1 {
t.Fatalf("ring buffer has %d entries, want 1", len(entries))
}
var attrs map[string]any
if err := json.Unmarshal([]byte(entries[0].Attrs), &attrs); err != nil {
t.Fatalf("unmarshal attrs: %v", err)
}
if attrs["outer.inner.k"] != "v" {
t.Errorf("attrs = %v, want outer.inner.k", attrs)
}
}
func TestMultiHandler_NoAttrsLeavesAttrsEmpty(t *testing.T) {
logger, buf, _ := newTeeLogger(t, slog.LevelDebug)
logger.Info("bare message")
entries := buf.Snapshot()
if len(entries) != 1 {
t.Fatalf("ring buffer has %d entries, want 1", len(entries))
}
if entries[0].Attrs != "" {
t.Errorf("Attrs = %q for a record with no attributes, want empty", entries[0].Attrs)
}
}
// ─── RingBuffer.Subscribe ───────────────────────────────────────────────────
func TestRingBuffer_Subscribe_ReceivesWrites(t *testing.T) {
buf := NewRingBuffer(8)
ch, unsubscribe := buf.Subscribe()
defer unsubscribe()
buf.Write(LogEntry{Message: "first"})
select {
case got := <-ch:
if got.Message != "first" {
t.Errorf("Message = %q, want %q", got.Message, "first")
}
default:
t.Fatal("subscriber received nothing")
}
}
func TestRingBuffer_Subscribe_UnsubscribeStopsDelivery(t *testing.T) {
buf := NewRingBuffer(8)
ch, unsubscribe := buf.Subscribe()
unsubscribe()
buf.Write(LogEntry{Message: "after unsubscribe"})
select {
case got := <-ch:
t.Errorf("received %q after unsubscribing", got.Message)
default:
}
}
func TestRingBuffer_Subscribe_MultipleSubscribersEachGetACopy(t *testing.T) {
buf := NewRingBuffer(8)
chA, stopA := buf.Subscribe()
defer stopA()
chB, stopB := buf.Subscribe()
defer stopB()
buf.Write(LogEntry{Message: "fanned out"})
for i, ch := range []<-chan LogEntry{chA, chB} {
select {
case got := <-ch:
if got.Message != "fanned out" {
t.Errorf("subscriber %d got %q, want %q", i, got.Message, "fanned out")
}
default:
t.Errorf("subscriber %d received nothing", i)
}
}
}
func TestRingBuffer_Subscribe_SlowSubscriberDoesNotBlockWrites(t *testing.T) {
buf := NewRingBuffer(8)
_, unsubscribe := buf.Subscribe() // never drained
defer unsubscribe()
// The subscriber channel holds 64; writing well past that must not block
// the logging path — records are dropped for that subscriber instead.
done := make(chan struct{})
go func() {
for i := range 200 {
buf.Write(LogEntry{Message: "flood", Level: "INFO", Timestamp: string(rune('a' + i%26))})
}
close(done)
}()
select {
case <-done:
case <-t.Context().Done():
t.Fatal("Write blocked on a slow subscriber")
}
// The ring itself stays capped at its capacity.
if got := len(buf.Snapshot()); got != 8 {
t.Errorf("ring buffer holds %d entries, want its capacity of 8", got)
}
}
// ─── categorizeSource ───────────────────────────────────────────────────────
func TestCategorizeSource_NoPCIsServer(t *testing.T) {
// A record built without a caller PC cannot be attributed to a package.
if got := categorizeSource(slog.Record{}); got != "server" {
t.Errorf("categorizeSource with PC 0 = %q, want %q", got, "server")
}
}
func TestCategorizeSource_AttributesAdminPackage(t *testing.T) {
logger, buf, _ := newTeeLogger(t, slog.LevelDebug)
// This call site lives in Server/admin, so the runtime frame resolves to
// the admin category.
logger.Info("from the admin package")
entries := buf.Snapshot()
if len(entries) != 1 {
t.Fatalf("ring buffer has %d entries, want 1", len(entries))
}
if entries[0].Source != "admin" {
t.Errorf("Source = %q, want %q", entries[0].Source, "admin")
}
}
func TestMultiHandler_HandleReturnsNil(t *testing.T) {
var stdout bytes.Buffer
buf := NewRingBuffer(4)
h := NewMultiHandler(slog.NewTextHandler(&stdout, nil), buf, slog.LevelDebug)
// Logging must never fail the caller, so Handle always reports success.
rec := slog.Record{Level: slog.LevelInfo, Message: "direct"}
if err := h.Handle(context.Background(), rec); err != nil {
t.Errorf("Handle = %v, want nil", err)
}
if !h.Enabled(context.Background(), slog.LevelInfo) {
t.Error("Enabled(Info) = false")
}
}