From b1dce0eddb2beba588db9991e8b953a6b45f86a8 Mon Sep 17 00:00:00 2001 From: xarmian Date: Sat, 24 Oct 2026 10:32:10 -0400 Subject: [PATCH] feat(server): log every unguarded content write the PLAN-3555 counter counts (TASK-4062) (#2301) pad_content_writes_unguarded_total and pad_collab_append_failures_total are in-process counters with no scraper, zeroed by every restart, so the week PLAN-3555 phase 2 waits on cannot be read from them. Log each event instead, so the count survives restarts in the server log. - handlers_items.go: one slog.Info("content write unguarded") per Inc(), outside the metrics guard, carrying door, kind, item ref and id, workspace id, actor kind and actor user id. Never the body, the title or a field value. - Collab needs no new line: "collab: append op-log" already sits in the same branch as the counter. Its test now pins one line per counted failure. Claude-Session: https://claude.ai/code/session_01Hk4vxsaKDm3E1LvsoHtHeV --- .../collab/task3574_append_failure_test.go | 50 +++++++++++ internal/server/handlers_items.go | 14 +++ .../task4062_unguarded_write_log_test.go | 85 +++++++++++++++++++ 3 files changed, 149 insertions(+) create mode 100644 internal/server/task4062_unguarded_write_log_test.go diff --git a/internal/collab/task3574_append_failure_test.go b/internal/collab/task3574_append_failure_test.go index 513408bc7..01f8c0fab 100644 --- a/internal/collab/task3574_append_failure_test.go +++ b/internal/collab/task3574_append_failure_test.go @@ -1,6 +1,10 @@ package collab import ( + "bytes" + "log/slog" + "strings" + "sync" "sync/atomic" "testing" @@ -18,7 +22,12 @@ func (o *appendFailureCounter) AppendFailed() { o.fails.Add(1) } // failed batch, and a clean append does not. Driven through a real Join so the // count vouches for the Room's binding to the manager, not only the callback // (CONVE-19). The barrier ack orders each read after its frame's append. +// +// TASK-4062: the counter has no scraper and every restart zeroes it, so its +// week is read from the log instead: each counted failure is also exactly one +// "collab: append op-log" line, and a clean append is none. func TestTASK3574_AFailedAppendIsCounted(t *testing.T) { + logs := captureCollabLogs(t) fake := &fakeOpLog{} bus := NewMemoryOpBus() defer bus.Close() @@ -40,6 +49,9 @@ func TestTASK3574_AFailedAppendIsCounted(t *testing.T) { if got := obs.fails.Load(); got != 0 { t.Fatalf("a clean append counted %d failures, want 0", got) } + if got := logs.count(`msg="collab: append op-log"`); got != 0 { + t.Fatalf("a clean append logged %d failure lines, want 0", got) + } fake.mu.Lock() fake.failOn = "db down" @@ -54,4 +66,42 @@ func TestTASK3574_AFailedAppendIsCounted(t *testing.T) { if got := obs.fails.Load(); got != 1 { t.Fatalf("a failed append counted %d failures, want 1", got) } + if got := logs.count(`msg="collab: append op-log"`); got != 1 { + t.Fatalf("a failed append logged %d failure lines, want 1 (one per count):\n%s", got, logs.String()) + } + if !logs.has(`item_id=item-append-fail`) { + t.Fatalf("the failure line does not name the item:\n%s", logs.String()) + } +} + +// collabLogs is the default slog output while a test runs. Locked: the room +// logs from its connection goroutines. +type collabLogs struct { + mu sync.Mutex + buf bytes.Buffer +} + +func (c *collabLogs) Write(p []byte) (int, error) { + c.mu.Lock() + defer c.mu.Unlock() + return c.buf.Write(p) +} + +func (c *collabLogs) String() string { + c.mu.Lock() + defer c.mu.Unlock() + return c.buf.String() +} + +func (c *collabLogs) count(sub string) int { return strings.Count(c.String(), sub) } + +func (c *collabLogs) has(sub string) bool { return strings.Contains(c.String(), sub) } + +func captureCollabLogs(t *testing.T) *collabLogs { + t.Helper() + c := &collabLogs{} + prev := slog.Default() + slog.SetDefault(slog.New(slog.NewTextHandler(c, nil))) + t.Cleanup(func() { slog.SetDefault(prev) }) + return c } diff --git a/internal/server/handlers_items.go b/internal/server/handlers_items.go index e4c16034d..bbc335949 100644 --- a/internal/server/handlers_items.go +++ b/internal/server/handlers_items.go @@ -2339,6 +2339,20 @@ func (s *Server) updateItem(w http.ResponseWriter, r *http.Request, b *builtinIt if s.metrics != nil { s.metrics.ContentWritesUnguardedTotal.WithLabelValues(door, kind).Inc() } + // TASK-4062: the counter is zeroed by every restart and has no + // scraper, so the same event is logged once per Inc() and the + // week's count is read from the log. Identifiers only: never the + // body, the title or a field value. + actorKind, _ := actorFromRequest(r) + slog.Info("content write unguarded", + "door", door, + "kind", kind, + "item_ref", item.Ref, + "item_id", item.ID, + "workspace_id", workspaceID, + "actor_kind", actorKind, + "actor_user_id", currentUserID(r), + ) unguardedContentWrite = kind == writeKindContent && door != writeDoorWeb } } diff --git a/internal/server/task4062_unguarded_write_log_test.go b/internal/server/task4062_unguarded_write_log_test.go new file mode 100644 index 000000000..e6d8c7f6e --- /dev/null +++ b/internal/server/task4062_unguarded_write_log_test.go @@ -0,0 +1,85 @@ +package server + +import ( + "net/http" + "strings" + "testing" +) + +// TASK-4062: every unguarded update the PLAN-3555 counter counts is also +// logged, one line per Inc(), with the counter's door and kind; a guarded +// write logs nothing; the line carries identifiers only, never the body or +// the title. Metrics are left unset on purpose: the counter has no scraper +// on a self-host box, so the log must not depend on it being wired. +func TestTASK4062_UnguardedWriteIsLoggedLikeItIsCounted(t *testing.T) { + srv := testServer(t) + slug := createWSWithCollections(t, srv) + item := createTaskWithFields(t, srv, slug, "Item", `{"status":"open"}`) + path := "/api/v1/workspaces/" + slug + "/items/" + item.Slug + cli := map[string]string{"X-Pad-Client": "cli"} + read, err := srv.store.GetItem(item.ID) + if err != nil { + t.Fatal(err) + } + if read.Ref == "" { + t.Fatal("premise: the item has no ref to log") + } + logs := captureLogs(t) + + const bodySentinel = "body-sentinel-4062" + const titleSentinel = "Title sentinel 4062" + patch := func(body map[string]any) { + t.Helper() + if rr := doRequestWithHeaders(srv, "PATCH", path, body, cli); rr.Code != http.StatusOK { + t.Fatalf("PATCH %v: %d %s", body, rr.Code, rr.Body.String()) + } + } + lines := func() []string { + t.Helper() + var out []string + for _, l := range strings.Split(logs.String(), "\n") { + if strings.Contains(l, `msg="content write unguarded"`) { + out = append(out, l) + } + } + return out + } + + patch(map[string]any{"content": bodySentinel}) + got := lines() + if len(got) != 1 { + t.Fatalf("an unguarded content write logged %d lines, want 1:\n%s", len(got), logs.String()) + } + for _, want := range []string{" door=cli ", " kind=content ", " item_ref=" + read.Ref + " ", " item_id=" + item.ID + " ", " actor_kind=user "} { + if !strings.Contains(got[0]+" ", want) { + t.Fatalf("content line lacks %q: %s", want, got[0]) + } + } + + now, err := srv.store.GetItem(item.ID) + if err != nil { + t.Fatal(err) + } + patch(map[string]any{"content": "guarded", "expected_seq": now.Seq}) + if got := lines(); len(got) != 1 { + t.Fatalf("a seq-guarded write was logged as unguarded: %d lines", len(got)) + } + + // Last: a rename moves the slug the path above is built from. + patch(map[string]any{"title": titleSentinel}) + got = lines() + if len(got) != 2 { + t.Fatalf("an unguarded field-only write logged %d lines in total, want 2:\n%s", len(got), logs.String()) + } + if !strings.Contains(got[1]+" ", " kind=fields ") || strings.Contains(got[1], "kind=content") { + t.Fatalf("the field-only line does not say kind=fields: %s", got[1]) + } + + for _, sentinel := range []string{bodySentinel, titleSentinel, "Title", "sentinel"} { + for _, l := range got { + if strings.Contains(l, sentinel) { + t.Fatalf("a log line carries written text %q: %s", sentinel, l) + } + } + } +}