Harden Google self-heal follow-ups: atomic session saves, fast cookie-save retry, paced-repair observability

cmd/google_supervisor.go

@@ -64,6 +64,7 @@ type googleCredentialRepairer struct {
 	clearRepair func()
 	minInterval time.Duration
 	now         func() time.Time
+	logger      zerolog.Logger
 
 	mu           sync.Mutex
 	paceGate     chan struct{}
@@ -77,14 +78,16 @@ func newGoogleCredentialRepairer(
 	refresh func(context.Context, string) error,
 	flagRepair func(),
 	clearRepair func(),
-) bridge.CredentialRepairer {
+	logger zerolog.Logger,
+) *googleCredentialRepairer {
 	return &googleCredentialRepairer{
 		sessionPath: sessionPath,
 		canRepair:   canRepair,
 		refresh:     refresh,
 		flagRepair:  flagRepair,
 		clearRepair: clearRepair,
 		minInterval: googleCredentialRepairMinInterval(),
+		logger:      logger,
 	}
 }
 
@@ -97,6 +100,11 @@ func googleCredentialRepairMinInterval() time.Duration {
 	return interval
 }
 
+// PacedRepairCount reports how many automatic Google credential repairs were
+// delayed to honour the minimum repair interval. It stays 0 through the healthy
+// ~15-minute heal cycle; a climbing count is the production signal that
+// something is revoking the imported cookies within minutes. Also logged as it
+// happens and surfaced as google.repairs_paced in /api/status.
 func (r *googleCredentialRepairer) PacedRepairCount() uint64 {
 	return r.pacedCount.Load()
 }
@@ -145,7 +153,13 @@ func (r *googleCredentialRepairer) waitForRepairCooldown(ctx context.Context) er
 	elapsed := now.Sub(lastRepairAt)
 	if r.minInterval > 0 && !lastRepairAt.IsZero() && elapsed < r.minInterval {
 		wait := r.minInterval - elapsed
-		r.pacedCount.Add(1)
+		paced := r.pacedCount.Add(1)
+		r.logger.Warn().
+			Dur("wait", wait).
+			Dur("since_last_repair", elapsed).
+			Dur("min_interval", r.minInterval).
+			Uint64("paced_total", paced).
+			Msg("Delaying Google credential repair — repairs requested faster than the minimum interval (cookies may be revoked within minutes)")
 
 		select {
 		case <-time.After(wait):

cmd/google_supervisor_test.go

@@ -1,7 +1,9 @@
 package cmd
 
 import (
+	"bytes"
 	"context"
+	"encoding/json"
 	"errors"
 	"os"
 	"path/filepath"
@@ -10,6 +12,8 @@ import (
 	"testing"
 	"time"
 
+	"github.com/rs/zerolog"
+
 	"github.com/maxghenis/openmessage/internal/bridge"
 )
 
@@ -64,6 +68,7 @@ func TestGoogleSupervisorCredentialRepairControlsGenerationStart(t *testing.T) {
 				},
 				func() { flagCalls.Add(1) },
 				func() { clearCalls.Add(1) },
+				zerolog.Nop(),
 			)
 			supervisor, err := bridge.NewSupervisor(
 				googleAccountID,
@@ -187,6 +192,7 @@ func TestGoogleCredentialRepairCooldownPacesTooSoonRepair(t *testing.T) {
 	clock := &googleCredentialRepairTestClock{}
 	var refreshMu sync.Mutex
 	var refreshTimes []time.Time
+	var logs bytes.Buffer
 	repairer := &googleCredentialRepairer{
 		sessionPath: "session.json",
 		canRepair:   func() bool { return true },
@@ -198,6 +204,7 @@ func TestGoogleCredentialRepairCooldownPacesTooSoonRepair(t *testing.T) {
 		},
 		minInterval: minInterval,
 		now:         clock.Now,
+		logger:      zerolog.New(&logs),
 	}
 
 	if err := repairer.RepairCredentials(context.Background(), "", bridge.OpError{}); err != nil {
@@ -222,6 +229,21 @@ func TestGoogleCredentialRepairCooldownPacesTooSoonRepair(t *testing.T) {
 	if got := repairer.PacedRepairCount(); got != 1 {
 		t.Fatalf("paced repair count = %d, want 1", got)
 	}
+	// Pacing is the fast-cookie-revocation signal, so it must not be silent in
+	// production: a delayed repair logs the wait and the running total.
+	var logged map[string]any
+	if err := json.Unmarshal([]byte(logs.String()), &logged); err != nil {
+		t.Fatalf("parse paced repair log %q: %v", logs.String(), err)
+	}
+	if level, _ := logged["level"].(string); level != "warn" {
+		t.Fatalf("paced repair log level = %v, want warn", logged["level"])
+	}
+	if total, _ := logged["paced_total"].(float64); total != 1 {
+		t.Fatalf("paced repair log paced_total = %v, want 1", logged["paced_total"])
+	}
+	if _, ok := logged["wait"]; !ok {
+		t.Fatalf("paced repair log has no wait field: %v", logged)
+	}
 }
 
 func TestGoogleCredentialRepairCooldownAfterIntervalProceedsImmediately(t *testing.T) {

cmd/serve.go

@@ -243,7 +243,11 @@ func RunServe(logger zerolog.Logger, args ...string) error {
 			refreshGoogleSessionCookies,
 			a.FlagGoogleNeedsRepair,
 			a.ClearGoogleRepairFlag,
+			logger,
 		)
+		// Paced repairs are the fast-cookie-revocation signal; publish the count
+		// so /api/status and get_status show churn instead of it being silent.
+		a.SetGoogleRepairPaceCounter(repairer.PacedRepairCount)
 		newGoogleSupervisor := func() (*bridge.Supervisor, error) {
 			supervisorOptions := []bridge.SupervisorOption{
 				bridge.WithCredentialRepairer(repairer),

docs/agent-runbook.md

@@ -211,7 +211,24 @@ session (measured 2026-07-20: 14 clean minutes of 200s, then
 pattern is therefore a **heal cycle**: connected → cookie 401 → watchdog
 refresh from Chrome → reconnect, repeating every ~15 min with sub-minute dips.
 Rotated cookies are also persisted to `session.json` (throttled, ~5 min) so a
-restart resumes from fresh values instead of pair-time snapshots.
+restart resumes from fresh values instead of pair-time snapshots. That write is
+atomic (temp file + fsync + rename), so a crash mid-save can never truncate the
+paired credentials; a failed save retries at a tenth of the interval instead of
+waiting a full one.
+
+**Is revocation running fast?** Automatic repairs are paced to at least
+`OPENMESSAGE_REPAIR_MIN_INTERVAL` (default 90s). Every delayed repair logs
+`Delaying Google credential repair` (with `wait` and `paced_total`) and bumps
+`google.repairs_paced` in `/api/status`:
+
+```bash
+curl -s http://127.0.0.1:7007/api/status | jq '.google.repairs_paced'
+```
+
+Absent/0 is the healthy ~15-minute heal cycle. A climbing count means repairs
+are being requested faster than the floor — i.e. something is revoking the
+imported cookies within minutes, which pacing throttles but does not fix. Read
+it before concluding a heal loop is "just slow".
 
 An `auth_expired` session with its device link intact revives by cookie
 rewrite alone — **do not re-pair** for `needs_repair`; that resets nothing the
@@ -322,6 +339,7 @@ briefly show "reconnecting" before it settles (see throttling note above).
 
 - `curl -s -o /dev/null -w '%{http_code}' http://127.0.0.1:7007/` → 200
 - `/api/status` → `google/whatsapp/signal` connection + `google.needs_repair`
+  (and `google.repairs_paced`, which should stay 0/absent)
 - A real send shows `OUTGOING_DELIVERED` in
   `/api/conversations/<id>/messages`. Don't re-send a user's real message as a
   "test" (duplicate risk on `UNKNOWN`, which is ambiguous about whether it sent);

internal/app/app.go

@@ -166,6 +166,8 @@ type App struct {
 	googlePhoneRespondingSeen atomic.Bool
 	googleLifecycleMu         sync.RWMutex
 	googleLifecycleNotifier   GoogleLifecycleNotifier
+	googleRepairPaceMu        sync.RWMutex
+	googleRepairPaceCount     func() uint64
 	signalLifecycleMu         sync.RWMutex
 	signalLifecycleNotifier   SignalLifecycleNotifier
 	tempDataDir               string
@@ -188,6 +190,11 @@ type GoogleStatusSnapshot struct {
 	// PhoneResponding is false after libgm reports PhoneNotResponding. Before
 	// such an event is observed, unknown is treated as healthy.
 	PhoneResponding bool `json:"phone_responding"`
+	// RepairsPaced counts automatic credential repairs the supervisor delayed
+	// to honour the minimum repair interval. 0 through the healthy ~15-minute
+	// heal cycle; a climbing count means cookies are being revoked within
+	// minutes, which the pacing floor is throttling rather than hiding.
+	RepairsPaced uint64 `json:"repairs_paced,omitempty"`
 }
 
 // googleRepairThreshold is how many consecutive failed Google sends (with no
@@ -751,9 +758,32 @@ func (a *App) GoogleStatus() GoogleStatusSnapshot {
 		LastError:       lastError,
 		AuthExpired:     a.googleAuthExpired.Load(),
 		PhoneResponding: a.GooglePhoneResponding(),
+		RepairsPaced:    a.GoogleRepairsPaced(),
 	}
 }
 
+// SetGoogleRepairPaceCounter installs the supervisor's paced-repair counter so
+// status surfaces can report it. Only the transport-owning daemon builds a
+// credential repairer; everyone else (client mode, demo) reports 0.
+func (a *App) SetGoogleRepairPaceCounter(count func() uint64) {
+	a.googleRepairPaceMu.Lock()
+	a.googleRepairPaceCount = count
+	a.googleRepairPaceMu.Unlock()
+}
+
+// GoogleRepairsPaced reports how many automatic Google credential repairs have
+// been delayed by the minimum-repair-interval floor. See
+// GoogleStatusSnapshot.RepairsPaced.
+func (a *App) GoogleRepairsPaced() uint64 {
+	a.googleRepairPaceMu.RLock()
+	count := a.googleRepairPaceCount
+	a.googleRepairPaceMu.RUnlock()
+	if count == nil {
+		return 0
+	}
+	return count()
+}
+
 func (a *App) AnyConnected() bool {
 	if a.Connected.Load() {
 		return true

internal/app/app_test.go

@@ -217,6 +217,35 @@ func TestGooglePhoneRespondingStatus(t *testing.T) {
 	}
 }
 
+func TestGoogleRepairsPacedStatus(t *testing.T) {
+	a := &App{}
+	a.SessionPath = filepath.Join(t.TempDir(), "session.json")
+	if err := os.WriteFile(a.SessionPath, []byte("{}"), 0o600); err != nil {
+		t.Fatal(err)
+	}
+
+	// Client mode and demo installs never build a repairer; they must report 0
+	// rather than panic on the missing counter.
+	if got := a.GoogleStatus().RepairsPaced; got != 0 {
+		t.Fatalf("RepairsPaced without a counter = %d, want 0", got)
+	}
+
+	var paced uint64
+	a.SetGoogleRepairPaceCounter(func() uint64 { return paced })
+	if got := a.GoogleStatus().RepairsPaced; got != 0 {
+		t.Fatalf("RepairsPaced with an idle counter = %d, want 0", got)
+	}
+	paced = 3
+	if got := a.GoogleStatus().RepairsPaced; got != 3 {
+		t.Fatalf("RepairsPaced = %d, want 3", got)
+	}
+
+	a.SetGoogleRepairPaceCounter(nil)
+	if got := a.GoogleStatus().RepairsPaced; got != 0 {
+		t.Fatalf("RepairsPaced after clearing the counter = %d, want 0", got)
+	}
+}
+
 func TestPhoneOfflineFailuresDoNotMarkGoogleForRepair(t *testing.T) {
 	a := &App{}
 	a.SessionPath = filepath.Join(t.TempDir(), "session.json")

internal/client/events.go

@@ -46,10 +46,16 @@ type EventHandler struct {
 	OnPhoneRespondingChange  func(bool)
 
 	cookieSaveMu     sync.Mutex
-	lastCookieSaveAt time.Time
+	nextCookieSaveAt time.Time
 	lastCookieHash   [32]byte
 }
 
+// cookieSaveRetryDivisor shortens the cookie-persist throttle after a failed
+// save. A transient failure then costs a fraction of the interval instead of a
+// full one, while a persistent failure still cannot turn every inbound event
+// into a write attempt.
+const cookieSaveRetryDivisor = 10
+
 func (h *EventHandler) Handle(rawEvt any) {
 	switch evt := rawEvt.(type) {
 	case *events.ClientReady:
@@ -425,15 +431,24 @@ func (h *EventHandler) maybePersistRotatedCookies() {
 
 	h.cookieSaveMu.Lock()
 	defer h.cookieSaveMu.Unlock()
-	if !h.lastCookieSaveAt.IsZero() && now.Sub(h.lastCookieSaveAt) < interval {
+	if !h.nextCookieSaveAt.IsZero() && now.Before(h.nextCookieSaveAt) {
 		return
 	}
-	h.lastCookieSaveAt = now
+	// The throttle covers every outcome, not just a successful save: these
+	// events arrive per message, so an unthrottled failure path would marshal
+	// and rewrite the session on each one. Failures instead come back after
+	// interval/cookieSaveRetryDivisor and leave lastCookieHash untouched, so
+	// the retry still sees the pending rotation and a transient error does not
+	// cost a full interval of durability.
+	h.nextCookieSaveAt = now.Add(interval)
+	retryAt := now.Add(interval / cookieSaveRetryDivisor)
 
 	authData := h.Client.GM.AuthData
 	authData.CookiesLock.RLock()
 	cookiesJSON, err := json.Marshal(authData.Cookies)
 	if err != nil {
+		// Keeps the full interval on purpose: a marshal failure is deterministic
+		// for these cookies, so an early retry only repeats it.
 		authData.CookiesLock.RUnlock()
 		h.Logger.Warn().Err(err).Msg("Failed to marshal rotated Google cookies")
 		return
@@ -446,10 +461,12 @@ func (h *EventHandler) maybePersistRotatedCookies() {
 	sessionData, err := h.Client.SessionData()
 	authData.CookiesLock.RUnlock()
 	if err != nil {
+		h.nextCookieSaveAt = retryAt
 		h.Logger.Warn().Err(err).Msg("Failed to get session data for rotated cookie save")
 		return
 	}
 	if err := SaveSession(h.SessionPath, sessionData); err != nil {
+		h.nextCookieSaveAt = retryAt
 		h.Logger.Warn().Err(err).Msg("Failed to persist rotated Google cookies")
 		return
 	}