Files
seaweedfs/weed/s3api/s3api_versioning_reconciler.go
T
Chris LuandGitHub 79859fc21d feat(s3/versioning): grep-able heal logs + scan-anomaly diagnostics + audit cmd (#9468)
* feat(s3/versioning): grep-able heal logs + scan-anomaly diagnostics + audit cmd

Three diagnostic additions on top of #9460, all aimed at making the next
production incident faster to triage than the one we just spent hours on.

1. [versioning-heal] grep prefix on every heal-related log line, with a
   small fixed event vocabulary (produced / surfaced / healed / enqueue /
   drain / retry / gave_up / anomaly / clear_failed / heal_persist_failed
   / teardown_failed / queue_full). One grep gives operators a single
   event stream across the produce-to-drain lifecycle.

2. Escalate the "scanned N>0 entries but no valid latest" case in
   updateLatestVersionAfterDeletion from V(1) Infof to a Warning that
   names the orphan entries it saw. This is the listing-after-rm
   inconsistency signature that pinned down 259064a8's failure — it
   should not be invisible at default log levels.

3. New weed shell command `s3.versions.audit -prefix <path> [-v] [-heal]`
   that walks .versions/ directories under a prefix and reports the
   stranded population. With -heal it clears the latest-version pointer
   in place on stranded directories so subsequent reads return a clean
   NoSuchKey instead of replaying the 10-retry self-heal loop.

* fix(s3/versioning): audit pagination, exclusive categories, ctx-aware retry

Address PR review:

1. s3.versions.audit walked only the first 1024-entry page of each
   .versions/ directory, false-positiving "stranded" on large dirs.
   Loop until the page returns < 1024 entries, advancing startName.

2. clean and orphan-only categories double-counted when a directory
   had no pointer and at least one orphan: incremented both. Make them
   mutually exclusive so report totals sum to versionsDirs.

3. retryFilerOp's worst-case ~6.3s backoff was a bare time.Sleep,
   non-interruptible by ctx. A server shutdown / client disconnect
   would wait out the budget per in-flight delete. Thread ctx through
   deleteSpecificObjectVersion -> repointLatestBeforeDeletion /
   updateLatestVersionAfterDeletion -> retryFilerOp; backoff now uses
   a select{<-ctx.Done(), <-timer.C}. HTTP handlers pass r.Context();
   gRPC lifecycle handlers pass the stream ctx.

   New test pins the behavior: cancelling ctx mid-backoff returns
   ctx.Err() in <500ms instead of blocking ~6.3s.

* fix(s3/versioning): clearStale outcome + escape grep-able log fields

Two coderabbit follow-ups:

1. Successful pointer clear should suppress `produced`.
   updateLatestVersionAfterDeletion's transient-rm fallback called
   clearStaleLatestVersionPointer best-effort, then unconditionally
   returned retryErr. The caller (deleteSpecificObjectVersion) saw the
   error and emitted `event=produced` + enqueued the reconciler, even
   though clearStaleLatestVersionPointer had just driven the pointer to
   consistency and the next reader would get NoSuchKey via the
   clean-miss path. Make clearStaleLatestVersionPointer return cleared
   bool; on success the caller returns nil so neither produced nor the
   reconciler enqueue fires. Concurrent-writer aborts, re-scan errors,
   and CAS mismatches still report false so genuinely stranded state
   keeps surfacing.

2. Escape user-controlled fields in heal log lines.
   versioningHealInfof / Warningf / Errorf interpolated raw bucket /
   key / filename / err text into a single-space-separated line. An S3
   key (or error string from gRPC) containing whitespace, newlines, or
   `event=...` could split one event into multiple tokens and spoof
   fake fields downstream. Sanitize each arg in the helper: safe
   values pass through; anything with whitespace, quotes, control
   chars, or backslashes is replaced with its strconv.Quote form. No
   caller changes — the format strings remain unchanged.

Tests pin both behaviors: sanitization table covers the field
boundary cases; an end-to-end shape test confirms a key containing
`event=spoof` stays inside a single quoted token.
2026-05-13 10:48:58 -07:00

289 lines
10 KiB
Go

package s3api
import (
"context"
"errors"
"fmt"
"strconv"
"sync"
"time"
"github.com/seaweedfs/seaweedfs/weed/glog"
"github.com/seaweedfs/seaweedfs/weed/pb/filer_pb"
"github.com/seaweedfs/seaweedfs/weed/s3api/s3_constants"
"google.golang.org/grpc/codes"
"google.golang.org/grpc/status"
)
// versioningHealLogPrefix is the grep-able tag every line in the .versions/
// pointer recovery lifecycle carries. Operators correlating produced /
// surfaced / drained / gave-up events can pull a single stream across
// hosts with `grep '\[versioning-heal\]'`. Keep this constant — log
// aggregators (Loki, Splunk, journalctl filters) may match on it.
const versioningHealLogPrefix = "[versioning-heal]"
// versioningHealInfof / Warningf / Errorf emit a log line stamped with
// the grep prefix and an event tag. Use event names from a small fixed
// vocabulary so dashboards can aggregate by event:
//
// event=produced — stranded state was created (or would have been before this PR's fixes)
// event=surfaced — read-path heal triggered for an already-stranded key
// event=healed — pointer was successfully repaired or cleared
// event=enqueue — reconciler queued a candidate
// event=drain — reconciler successfully drained a candidate
// event=retry — reconciler attempt failed, will retry
// event=gave_up — reconciler exhausted retries on a candidate
// event=anomaly — listing-after-rm inconsistency detected
// event=summary — periodic heartbeat (counters + queue depth)
//
// All string/error arguments are sanitized so user-controlled bucket
// names, object keys, filenames, and error text can't split the line
// into multiple grep tokens or inject fake event=/bucket=/key= fields.
// Safe values pass through unchanged; anything containing whitespace,
// quotes, control chars, or backslashes is replaced with its
// strconv.Quote form so the field boundary stays one space.
func versioningHealInfof(event, format string, args ...interface{}) {
glog.Infof("%s event=%s %s", versioningHealLogPrefix, event, fmt.Sprintf(format, sanitizeHealArgs(args)...))
}
func versioningHealWarningf(event, format string, args ...interface{}) {
glog.Warningf("%s event=%s %s", versioningHealLogPrefix, event, fmt.Sprintf(format, sanitizeHealArgs(args)...))
}
func versioningHealErrorf(event, format string, args ...interface{}) {
glog.Errorf("%s event=%s %s", versioningHealLogPrefix, event, fmt.Sprintf(format, sanitizeHealArgs(args)...))
}
// sanitizeHealArgs walks args and replaces string/error values that
// would break the single-space field separator (whitespace, newlines,
// control chars, quotes, backslashes) with their strconv.Quote form.
// Non-string args are returned untouched.
func sanitizeHealArgs(args []interface{}) []interface{} {
out := make([]interface{}, len(args))
for i, v := range args {
out[i] = sanitizeHealArg(v)
}
return out
}
func sanitizeHealArg(v interface{}) interface{} {
var s string
switch t := v.(type) {
case nil:
return v
case string:
s = t
case error:
s = t.Error()
default:
return v
}
if !needsHealQuote(s) {
return s
}
return strconv.Quote(s)
}
func needsHealQuote(s string) bool {
for _, r := range s {
if r == ' ' || r == '\t' || r == '\n' || r == '\r' || r == '"' || r == '\\' || r < 0x20 || r == 0x7f {
return true
}
}
return false
}
// Background reconciler for .versions/ directories whose latest-version
// pointer references a missing file. The inline delete path
// (deleteSpecificObjectVersion -> updateLatestVersionAfterDeletion) can
// leave this state behind if the second step (pointer update / dir rm)
// fails after the first (blob rm) succeeded. Read-path self-heal already
// recovers on the next GET, but that surfaces NoSuchKey to the client.
// The reconciler drains stranded entries proactively so a passing health
// check or an idle key gets repaired without waiting for a client read.
const (
versionsHealQueueCapacity = 4096
versionsHealPollInterval = 5 * time.Second
versionsHealMaxRetries = 6
versionsHealBaseBackoff = 200 * time.Millisecond
versionsHealMaxBackoff = 30 * time.Second
)
type versionsHealCandidate struct {
bucket string
object string
enqueued time.Time
attempts int
nextRetry time.Time
}
type versionsHealQueue struct {
mu sync.Mutex
pending map[string]*versionsHealCandidate
}
func newVersionsHealQueue() *versionsHealQueue {
return &versionsHealQueue{
pending: make(map[string]*versionsHealCandidate),
}
}
func versionsHealKey(bucket, object string) string {
return bucket + "/" + object
}
// Enqueue records that bucket/object's .versions/ directory may be in a
// stranded state and needs the reconciler to verify and heal it. Bounded
// by versionsHealQueueCapacity so a stuck filer can't grow the map
// without limit; on overflow we drop the newest candidate (the heal will
// run on the next read or the next delete-failure for that key).
func (q *versionsHealQueue) Enqueue(bucket, object string) {
q.mu.Lock()
defer q.mu.Unlock()
key := versionsHealKey(bucket, object)
if _, ok := q.pending[key]; ok {
return
}
if len(q.pending) >= versionsHealQueueCapacity {
versioningHealWarningf("queue_full", "bucket=%s key=%s capacity=%d (candidate dropped; read-path heal still covers it)", bucket, object, versionsHealQueueCapacity)
return
}
q.pending[key] = &versionsHealCandidate{
bucket: bucket,
object: object,
enqueued: time.Now(),
nextRetry: time.Now(),
}
versioningHealInfof("enqueue", "bucket=%s key=%s queue_depth=%d", bucket, object, len(q.pending))
}
// popReady returns candidates whose nextRetry is in the past, removing
// them from the queue. Callers reinsert via requeue() if the heal failed.
func (q *versionsHealQueue) popReady(now time.Time) []*versionsHealCandidate {
q.mu.Lock()
defer q.mu.Unlock()
var out []*versionsHealCandidate
for k, c := range q.pending {
if !c.nextRetry.After(now) {
out = append(out, c)
delete(q.pending, k)
}
}
return out
}
// requeue re-inserts a candidate with an updated retry schedule. Drops
// candidates that have hit the attempt cap so they don't loop forever
// against a deterministically broken state; the read-path heal remains
// as a last-resort safety net.
func (q *versionsHealQueue) requeue(c *versionsHealCandidate, backoff time.Duration) {
if c.attempts >= versionsHealMaxRetries {
versioningHealWarningf("gave_up", "bucket=%s key=%s attempts=%d (read-path heal will still recover)", c.bucket, c.object, c.attempts)
return
}
q.mu.Lock()
defer q.mu.Unlock()
c.nextRetry = time.Now().Add(backoff)
q.pending[versionsHealKey(c.bucket, c.object)] = c
}
// Len returns the current queued size. Used in tests and by metrics.
func (q *versionsHealQueue) Len() int {
q.mu.Lock()
defer q.mu.Unlock()
return len(q.pending)
}
// startVersioningReconciler launches the background worker. Returns a
// stop function that the server's Shutdown calls to cancel the loop.
func (s3a *S3ApiServer) startVersioningReconciler() (stop func()) {
if s3a.versionsHealQueue == nil {
s3a.versionsHealQueue = newVersionsHealQueue()
}
ctx, cancel := context.WithCancel(context.Background())
go s3a.runVersioningReconciler(ctx)
return cancel
}
func (s3a *S3ApiServer) runVersioningReconciler(ctx context.Context) {
ticker := time.NewTicker(versionsHealPollInterval)
defer ticker.Stop()
for {
select {
case <-ctx.Done():
return
case <-ticker.C:
s3a.drainVersionsHealQueue()
}
}
}
func (s3a *S3ApiServer) drainVersionsHealQueue() {
q := s3a.versionsHealQueue
if q == nil {
return
}
ready := q.popReady(time.Now())
for _, c := range ready {
c.attempts++
if err := s3a.healVersionsPointer(c.bucket, c.object); err != nil {
backoff := versionsHealBaseBackoff << uint(c.attempts-1)
if backoff > versionsHealMaxBackoff {
backoff = versionsHealMaxBackoff
}
versioningHealInfof("retry", "bucket=%s key=%s attempt=%d retry_in=%v err=%v", c.bucket, c.object, c.attempts, backoff, err)
q.requeue(c, backoff)
continue
}
versioningHealInfof("drain", "bucket=%s key=%s attempts=%d queued_for=%v", c.bucket, c.object, c.attempts, time.Since(c.enqueued))
}
}
// healVersionsPointer reads the .versions directory entry for the given
// object and, if its latest-version pointer references a file that does
// not exist, invokes the same self-heal path used by the read flow. A
// genuinely-missing .versions directory or an already-consistent pointer
// is treated as success — the candidate either healed itself via another
// path or was never in trouble.
//
// Transient errors from the filer (timeout, brief unreachability) are
// returned so the reconciler retries with backoff rather than silently
// evicting the candidate. Swallowing them as "no stranded state" would
// defeat the reconciler for exactly the failure modes the PR targets.
func (s3a *S3ApiServer) healVersionsPointer(bucket, object string) error {
bucketDir := s3a.bucketDir(bucket)
versionsObjectPath := object + s3_constants.VersionsFolder
versionsEntry, err := s3a.getEntry(bucketDir, versionsObjectPath)
if err != nil {
if errors.Is(err, filer_pb.ErrNotFound) || status.Code(err) == codes.NotFound {
// Directory is gone — no stranded state to heal.
return nil
}
return fmt.Errorf("read .versions entry %s/%s: %w", bucket, object, err)
}
if versionsEntry == nil || versionsEntry.Extended == nil {
return nil
}
fileBytes, hasFile := versionsEntry.Extended[s3_constants.ExtLatestVersionFileNameKey]
if !hasFile || len(fileBytes) == 0 {
// No pointer => no stranded state.
return nil
}
latestFile := string(fileBytes)
if _, probeErr := s3a.getEntry(bucketDir+"/"+versionsObjectPath, latestFile); probeErr == nil {
// Pointer is consistent.
return nil
} else if !errors.Is(probeErr, filer_pb.ErrNotFound) && status.Code(probeErr) != codes.NotFound {
// Transient — surface so the reconciler retries with backoff
// rather than invoking heal on a possibly-incomplete listing
// (which could rewrite the pointer to an older version).
return fmt.Errorf("probe latest version %s/%s/%s: %w", bucket, object, latestFile, probeErr)
}
// Reuse the read-path heal so behaviour stays identical: it will
// repair the pointer to the newest remaining version, or clear it
// when nothing valid remains.
_, healErr := s3a.healStaleLatestVersionPointer(bucket, object, versionsEntry, latestFile)
return healErr
}