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

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
 }

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

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