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