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.
This commit is contained in:
Chris Lu
2026-05-13 10:48:58 -07:00
committed by GitHub
parent e025ec2334
commit 79859fc21d
7 changed files with 597 additions and 44 deletions
+2 -2
View File
@@ -77,7 +77,7 @@ func (s3a *S3ApiServer) lifecycleDispatch(ctx context.Context, req *s3_lifecycle
return done(), nil
case s3_constants.VersioningSuspended:
// Best-effort null delete; NotFound is benign.
if err := s3a.deleteSpecificObjectVersion(req.Bucket, req.ObjectPath, "null", metadataOnly); err != nil {
if err := s3a.deleteSpecificObjectVersion(ctx, req.Bucket, req.ObjectPath, "null", metadataOnly); err != nil {
if !errors.Is(err, filer_pb.ErrNotFound) && !errors.Is(err, ErrVersionNotFound) {
return retryLater("TRANSPORT_ERROR: deleteNullVersion: " + err.Error()), nil
}
@@ -133,7 +133,7 @@ func (s3a *S3ApiServer) lifecycleDispatch(ctx context.Context, req *s3_lifecycle
return outcome, err
}
}
if err := s3a.deleteSpecificObjectVersion(req.Bucket, req.ObjectPath, req.VersionId, metadataOnly); err != nil {
if err := s3a.deleteSpecificObjectVersion(ctx, req.Bucket, req.ObjectPath, req.VersionId, metadataOnly); err != nil {
if errors.Is(err, filer_pb.ErrNotFound) || errors.Is(err, ErrVersionNotFound) || errors.Is(err, ErrObjectNotFound) {
return noopResolved("NOT_FOUND_AT_DELETE"), nil
}
+2 -2
View File
@@ -125,7 +125,7 @@ func (s3a *S3ApiServer) deleteVersionedObject(r *http.Request, bucket, object, v
glog.V(2).Infof("deleteVersionedObject: object lock check failed for %s/%s version %s: %v", bucket, object, versionId, err)
return result, s3err.ErrAccessDenied
}
if err := s3a.deleteSpecificObjectVersion(bucket, object, versionId, false); err != nil {
if err := s3a.deleteSpecificObjectVersion(r.Context(), bucket, object, versionId, false); err != nil {
glog.Errorf("deleteVersionedObject: failed to delete specific version %s for %s/%s: %v", versionId, bucket, object, err)
return result, s3err.ErrInternalError
}
@@ -148,7 +148,7 @@ func (s3a *S3ApiServer) deleteVersionedObject(r *http.Request, bucket, object, v
glog.V(2).Infof("deleteVersionedObject: object lock check failed for %s/%s null version: %v", bucket, object, err)
return result, s3err.ErrAccessDenied
}
if err := s3a.deleteSpecificObjectVersion(bucket, object, "null", false); err != nil {
if err := s3a.deleteSpecificObjectVersion(r.Context(), bucket, object, "null", false); err != nil {
glog.Errorf("deleteVersionedObject: failed to delete null version for %s/%s: %v", bucket, object, err)
return result, s3err.ErrInternalError
}
+102 -33
View File
@@ -1000,7 +1000,7 @@ func (s3a *S3ApiServer) getSpecificObjectVersion(bucket, object, versionId strin
// metadataOnly=true skips per-chunk DeleteFile RPCs at the filer; only
// pass true when the live entry's Attributes.TtlSec > 0 so the volume
// reclaims chunks on its own.
func (s3a *S3ApiServer) deleteSpecificObjectVersion(bucket, object, versionId string, metadataOnly bool) error {
func (s3a *S3ApiServer) deleteSpecificObjectVersion(ctx context.Context, bucket, object, versionId string, metadataOnly bool) error {
// Normalize object path to ensure consistency with toFilerPath behavior
normalizedObject := s3_constants.NormalizeObjectKey(object)
@@ -1057,7 +1057,7 @@ func (s3a *S3ApiServer) deleteSpecificObjectVersion(bucket, object, versionId st
preWasSingleton bool
)
if isLatestVersion {
rolled, singleton, prepErr := s3a.repointLatestBeforeDeletion(bucket, normalizedObject, versionId)
rolled, singleton, prepErr := s3a.repointLatestBeforeDeletion(ctx, bucket, normalizedObject, versionId)
if prepErr != nil {
// Surface to the client so they can retry the DELETE. The
// blob has NOT been removed yet, so retrying is safe.
@@ -1097,7 +1097,7 @@ func (s3a *S3ApiServer) deleteSpecificObjectVersion(bucket, object, versionId st
// pre-step decided the pointer was no longer ours to roll. Run
// the post-deletion reconciliation: it updates the pointer to
// the new latest and tears down .versions/ when nothing remains.
if err := s3a.updateLatestVersionAfterDeletion(bucket, normalizedObject); err != nil {
if err := s3a.updateLatestVersionAfterDeletion(ctx, bucket, normalizedObject); err != nil {
// Option 2: surface this so the operator sees the load-bearing
// failure, and queue the path for the reconciler to retry off
// the hot path. The blob delete already succeeded, so we don't
@@ -1105,7 +1105,7 @@ func (s3a *S3ApiServer) deleteSpecificObjectVersion(bucket, object, versionId st
// DELETE as a hard storage error) — but we MUST drive the
// pointer to consistency, otherwise the next read pays the
// self-heal cost.
glog.Errorf("deleteSpecificObjectVersion: failed to update latest version after deletion for %s/%s (queued for reconciler): %v", bucket, normalizedObject, err)
versioningHealErrorf("produced", "bucket=%s key=%s reason=update_after_delete_failed err=%v queued_for_reconciler=true", bucket, normalizedObject, err)
if s3a.versionsHealQueue != nil {
s3a.versionsHealQueue.Enqueue(bucket, normalizedObject)
}
@@ -1140,7 +1140,7 @@ func (s3a *S3ApiServer) deleteSpecificObjectVersion(bucket, object, versionId st
// pre-roll matches the resilience of the post-roll path; without this,
// a transient filer hiccup during the pre-step would cause the caller
// to fall back to the legacy non-atomic flow.
func (s3a *S3ApiServer) repointLatestBeforeDeletion(bucket, normalizedObject, versionIdToDelete string) (rolled bool, wasSingleton bool, err error) {
func (s3a *S3ApiServer) repointLatestBeforeDeletion(ctx context.Context, bucket, normalizedObject, versionIdToDelete string) (rolled bool, wasSingleton bool, err error) {
bucketDir := s3a.bucketDir(bucket)
versionsObjectPath := normalizedObject + s3_constants.VersionsFolder
versionsDir := bucketDir + "/" + versionsObjectPath
@@ -1160,7 +1160,7 @@ func (s3a *S3ApiServer) repointLatestBeforeDeletion(bucket, normalizedObject, ve
entries []*filer_pb.Entry
isLast bool
)
if listErr := retryFilerOp("repointLatestBeforeDeletion.list", func() error {
if listErr := retryFilerOp(ctx, "repointLatestBeforeDeletion.list", func() error {
var lerr error
entries, isLast, lerr = s3a.list(versionsDir, "", startFrom, false, filer.PaginationSize)
return lerr
@@ -1199,7 +1199,7 @@ func (s3a *S3ApiServer) repointLatestBeforeDeletion(bucket, normalizedObject, ve
// blob rm — otherwise we'd remove the blob without having updated
// the pointer, reproducing the very dangling-state this PR fixes).
var versionsEntry *filer_pb.Entry
if getErr := retryFilerOp("repointLatestBeforeDeletion.getEntry", func() error {
if getErr := retryFilerOp(ctx, "repointLatestBeforeDeletion.getEntry", func() error {
var gerr error
versionsEntry, gerr = s3a.getEntry(bucketDir, versionsObjectPath)
return gerr
@@ -1238,7 +1238,7 @@ func (s3a *S3ApiServer) repointLatestBeforeDeletion(bucket, normalizedObject, ve
glog.V(2).Infof("repointLatestBeforeDeletion: %s/%s clearing singleton pointer before deleting %s", bucket, normalizedObject, versionIdToDelete)
}
if mkErr := retryFilerOp("repointLatestBeforeDeletion.mkFile", func() error {
if mkErr := retryFilerOp(ctx, "repointLatestBeforeDeletion.mkFile", func() error {
return s3a.mkFile(bucketDir, versionsObjectPath, versionsEntry.Chunks, func(updatedEntry *filer_pb.Entry) {
updatedEntry.Extended = versionsEntry.Extended
updatedEntry.Attributes = versionsEntry.Attributes
@@ -1288,7 +1288,7 @@ func isRetryableFilerErr(err error) bool {
return true
}
func retryFilerOp(name string, fn func() error) error {
func retryFilerOp(ctx context.Context, name string, fn func() error) error {
var lastErr error
backoff := updateLatestRetryStep
for attempt := 1; attempt <= updateLatestRetryAttempts; attempt++ {
@@ -1309,7 +1309,16 @@ func retryFilerOp(name string, fn func() error) error {
if attempt == updateLatestRetryAttempts {
break
}
time.Sleep(backoff)
// Context-aware backoff so a server shutdown / client
// disconnect cancels the worst-case ~6.3s retry budget
// immediately instead of blocking the goroutine.
timer := time.NewTimer(backoff)
select {
case <-ctx.Done():
timer.Stop()
return ctx.Err()
case <-timer.C:
}
backoff *= 2
if backoff > updateLatestRetryCap {
backoff = updateLatestRetryCap
@@ -1330,7 +1339,7 @@ func retryFilerOp(name string, fn func() error) error {
// when those retries are exhausted; the caller is expected to surface the
// failure (log + enqueue for the reconciler) instead of swallowing it,
// which was the historic behaviour that left dangling pointers in place.
func (s3a *S3ApiServer) updateLatestVersionAfterDeletion(bucket, object string) error {
func (s3a *S3ApiServer) updateLatestVersionAfterDeletion(ctx context.Context, bucket, object string) error {
bucketDir := s3a.bucketDir(bucket)
versionsObjectPath := object + s3_constants.VersionsFolder
versionsDir := bucketDir + "/" + versionsObjectPath
@@ -1341,12 +1350,21 @@ func (s3a *S3ApiServer) updateLatestVersionAfterDeletion(bucket, object string)
// A single-shot list would miss the true latest for old-format (raw
// timestamp) version ids when the directory exceeds one page, since filer
// order is lexicographic-ascending = oldest-first for that format.
//
// orphanSamples captures up to orphanSampleCap names that DID appear in
// the listing but lacked the version-id extended attribute. These are
// the smoking-gun diagnostic for the "scanned N>0 but no valid latest"
// anomaly — they're either filer-listing stale entries (just-deleted
// records still indexed) or residual stubs from interrupted writes.
const orphanSampleCap = 8
var (
latestVersionEntry *filer_pb.Entry
latestVersionId string
latestVersionFileName string
latestIsDeleteMarker bool
totalEntries int
orphanCount int
orphanSamples []string
startFrom string
)
for {
@@ -1354,7 +1372,7 @@ func (s3a *S3ApiServer) updateLatestVersionAfterDeletion(bucket, object string)
entries []*filer_pb.Entry
isLast bool
)
if err := retryFilerOp("updateLatestVersionAfterDeletion.list", func() error {
if err := retryFilerOp(ctx, "updateLatestVersionAfterDeletion.list", func() error {
var listErr error
entries, isLast, listErr = s3a.list(versionsDir, "", startFrom, false, filer.PaginationSize)
return listErr
@@ -1371,17 +1389,50 @@ func (s3a *S3ApiServer) updateLatestVersionAfterDeletion(bucket, object string)
latestIsDeleteMarker = pageDM
}
}
// Sample orphan entries (those without ExtVersionIdKey) for
// post-scan diagnostics. selectLatestVersion already filters them
// out for the latest-pick; we collect names separately so the
// anomaly warning has something concrete to point at.
for _, e := range entries {
if e == nil {
continue
}
if e.Extended != nil {
if _, ok := e.Extended[s3_constants.ExtVersionIdKey]; ok {
continue
}
}
orphanCount++
if len(orphanSamples) < orphanSampleCap {
orphanSamples = append(orphanSamples, e.Name)
}
}
if isLast || len(entries) == 0 {
break
}
startFrom = entries[len(entries)-1].Name
}
glog.V(1).Infof("updateLatestVersionAfterDeletion: scanned %d entries in %s", totalEntries, versionsDir)
if totalEntries > 0 && latestVersionEntry == nil {
// The scan saw entries but none were valid version blobs. This is
// the listing-after-rm timing anomaly: a just-deleted record is
// still indexed in the parent's listing but its extended attrs
// either weren't loaded or the entry itself is mid-removal. The
// caller will now fall through to the .versions/ teardown +
// pointer clear, but operators tracking stranded-state production
// should see this event.
samplesSummary := "(none)"
if len(orphanSamples) > 0 {
samplesSummary = strings.Join(orphanSamples, ",")
}
versioningHealWarningf("anomaly", "bucket=%s key=%s scanned=%d orphan_count=%d orphan_samples=%s reason=listing_has_entries_but_none_have_version_id", bucket, object, totalEntries, orphanCount, samplesSummary)
} else {
glog.V(1).Infof("updateLatestVersionAfterDeletion: scanned %d entries in %s", totalEntries, versionsDir)
}
// Update the .versions directory metadata
var versionsEntry *filer_pb.Entry
if err := retryFilerOp("updateLatestVersionAfterDeletion.getEntry", func() error {
if err := retryFilerOp(ctx, "updateLatestVersionAfterDeletion.getEntry", func() error {
var getErr error
versionsEntry, getErr = s3a.getEntry(bucketDir, versionsObjectPath)
return getErr
@@ -1401,7 +1452,7 @@ func (s3a *S3ApiServer) updateLatestVersionAfterDeletion(bucket, object string)
setCachedListMetadata(versionsEntry, latestVersionEntry)
glog.V(2).Infof("updateLatestVersionAfterDeletion: new latest version for %s/%s is %s (deleteMarker=%v)", bucket, object, latestVersionId, latestIsDeleteMarker)
if err := retryFilerOp("updateLatestVersionAfterDeletion.mkFile", func() error {
if err := retryFilerOp(ctx, "updateLatestVersionAfterDeletion.mkFile", func() error {
return s3a.mkFile(bucketDir, versionsObjectPath, versionsEntry.Chunks, func(updatedEntry *filer_pb.Entry) {
updatedEntry.Extended = versionsEntry.Extended
updatedEntry.Attributes = versionsEntry.Attributes
@@ -1443,7 +1494,7 @@ func (s3a *S3ApiServer) updateLatestVersionAfterDeletion(bucket, object string)
// if it ultimately fails, we still clear the stale pointer so
// readers get a clean miss; the directory can be tidied by the
// reconciler later.
retryErr := retryFilerOp("updateLatestVersionAfterDeletion.rm", func() error {
retryErr := retryFilerOp(ctx, "updateLatestVersionAfterDeletion.rm", func() error {
return s3a.rm(bucketDir, versionsObjectPath, true, false)
})
if retryErr == nil {
@@ -1453,8 +1504,13 @@ func (s3a *S3ApiServer) updateLatestVersionAfterDeletion(bucket, object string)
s3a.clearStaleLatestVersionPointer(bucket, object, bucketDir, versionsObjectPath, versionsEntry, "updateLatestVersionAfterDeletion")
return nil
}
glog.Warningf("updateLatestVersionAfterDeletion: failed to delete .versions directory for %s/%s after retries: %v", bucket, object, retryErr)
s3a.clearStaleLatestVersionPointer(bucket, object, bucketDir, versionsObjectPath, versionsEntry, "updateLatestVersionAfterDeletion")
versioningHealWarningf("teardown_failed", "bucket=%s key=%s err=%v (fell through to clearStale)", bucket, object, retryErr)
if s3a.clearStaleLatestVersionPointer(bucket, object, bucketDir, versionsObjectPath, versionsEntry, "updateLatestVersionAfterDeletion") {
// Pointer is consistent again; reader will get NoSuchKey via
// the clean-miss path. Don't emit `produced` or enqueue the
// reconciler — there's no stranded state left to heal.
return nil
}
return fmt.Errorf("delete .versions directory: %w", retryErr)
}
@@ -1482,9 +1538,19 @@ func (s3a *S3ApiServer) updateLatestVersionAfterDeletion(bucket, object string)
//
// caller is the source-function name used in log lines so operators can
// trace which path ran the clear.
func (s3a *S3ApiServer) clearStaleLatestVersionPointer(bucket, object, bucketDir, versionsObjectPath string, versionsEntry *filer_pb.Entry, caller string) {
//
// Returns cleared=true ONLY when this function successfully removed the
// pointer (or the second branch — pointer no longer present — left the
// directory in the intended clean-miss state, which counts as
// already-clear). Concurrent-writer aborts, re-scan errors, and CAS
// mismatches return false so callers that hit a transient teardown
// failure still emit `produced` and enqueue for the reconciler; a
// successful clear lets the caller short-circuit and return nil since
// the pointer is consistent and the next reader gets NoSuchKey via the
// clean-miss path.
func (s3a *S3ApiServer) clearStaleLatestVersionPointer(bucket, object, bucketDir, versionsObjectPath string, versionsEntry *filer_pb.Entry, caller string) (cleared bool) {
if versionsEntry == nil || versionsEntry.Extended == nil {
return
return false
}
observedStaleId := string(versionsEntry.Extended[s3_constants.ExtLatestVersionIdKey])
versionsDir := bucketDir + "/" + versionsObjectPath
@@ -1494,11 +1560,11 @@ func (s3a *S3ApiServer) clearStaleLatestVersionPointer(bucket, object, bucketDir
entries, isLast, listErr := s3a.list(versionsDir, "", startFrom, false, filer.PaginationSize)
if listErr != nil {
glog.Warningf("%s: re-scan failed for %s/%s, leaving pointer untouched: %v", caller, bucket, object, listErr)
return
return false
}
if pageEntry, _, _, _ := selectLatestVersion(entries); pageEntry != nil {
glog.V(1).Infof("%s: skipping pointer clear for %s/%s, concurrent writer added a tagged version", caller, bucket, object)
return
return false
}
if isLast || len(entries) == 0 {
break
@@ -1508,20 +1574,22 @@ func (s3a *S3ApiServer) clearStaleLatestVersionPointer(bucket, object, bucketDir
liveEntry, err := s3a.getEntry(bucketDir, versionsObjectPath)
if err != nil {
// Directory was concurrently removed - nothing to clear.
return
// Directory was concurrently removed - reader will get NoSuchKey
// via the clean-miss path; pointer is effectively cleared.
return true
}
if liveEntry.Extended == nil {
return
return true
}
currentIdBytes, hasId := liveEntry.Extended[s3_constants.ExtLatestVersionIdKey]
_, hasFile := liveEntry.Extended[s3_constants.ExtLatestVersionFileNameKey]
if !hasId && !hasFile {
return
// Already cleared by another path.
return true
}
if observedStaleId != "" && string(currentIdBytes) != observedStaleId {
glog.V(1).Infof("%s: skipping pointer clear for %s/%s, live pointer changed (observed=%s, current=%s)", caller, bucket, object, observedStaleId, string(currentIdBytes))
return
return false
}
delete(liveEntry.Extended, s3_constants.ExtLatestVersionIdKey)
@@ -1532,10 +1600,11 @@ func (s3a *S3ApiServer) clearStaleLatestVersionPointer(bucket, object, bucketDir
updatedEntry.Attributes = liveEntry.Attributes
updatedEntry.Chunks = liveEntry.Chunks
}); mkErr != nil {
glog.Warningf("%s: failed to clear stale pointer for %s/%s: %v", caller, bucket, object, mkErr)
return
versioningHealWarningf("clear_failed", "bucket=%s key=%s caller=%s err=%v", bucket, object, caller, mkErr)
return false
}
glog.V(1).Infof("%s: cleared stale latest-version pointer for %s/%s (orphan entries remain in .versions directory)", caller, bucket, object)
versioningHealInfof("healed", "bucket=%s key=%s mode=pointer_cleared caller=%s (orphan entries remain in .versions directory)", bucket, object, caller)
return true
}
// ListObjectVersionsHandler handles the list object versions request
@@ -1746,7 +1815,7 @@ func (s3a *S3ApiServer) healStaleLatestVersionPointer(bucket, normalizedObject s
versionsObjectPath := normalizedObject + s3_constants.VersionsFolder
versionsDir := bucketDir + "/" + versionsObjectPath
glog.Warningf("healStaleLatestVersionPointer: stale pointer for %s/%s - version file %q missing, rescanning %s", bucket, normalizedObject, stalePointerFile, versionsDir)
versioningHealWarningf("surfaced", "bucket=%s key=%s missing_file=%s rescanning=%s", bucket, normalizedObject, stalePointerFile, versionsDir)
// Paginate through all version entries and keep a running best candidate.
// A single-shot list would miss the true latest when old-format (raw
@@ -1813,9 +1882,9 @@ func (s3a *S3ApiServer) healStaleLatestVersionPointer(bucket, normalizedObject s
// Persisting the repair is best-effort. Surface a warning but still
// return the rescanned entry so the read succeeds; a subsequent write
// on the object will persist a fresh pointer.
glog.Warningf("healStaleLatestVersionPointer: failed to persist repaired pointer for %s/%s: %v (returning rescanned entry)", bucket, normalizedObject, mkErr)
versioningHealWarningf("heal_persist_failed", "bucket=%s key=%s err=%v (returning rescanned entry)", bucket, normalizedObject, mkErr)
} else {
glog.V(1).Infof("healStaleLatestVersionPointer: repaired pointer for %s/%s to version %s (file %s, deleteMarker=%v)", bucket, normalizedObject, latestVersionId, latestVersionFileName, isDeleteMarker)
versioningHealInfof("healed", "bucket=%s key=%s mode=pointer_repaired new_version=%s file=%s delete_marker=%v", bucket, normalizedObject, latestVersionId, latestVersionFileName, isDeleteMarker)
}
return latestEntry, nil
}
@@ -0,0 +1,137 @@
package s3api
import (
"bytes"
"errors"
"flag"
"fmt"
"strings"
"testing"
"github.com/seaweedfs/seaweedfs/weed/glog"
"github.com/stretchr/testify/assert"
)
// TestVersioningHealLogPrefix verifies that the prefix helpers attach a
// consistent grep-able tag plus an event= field. The exact format is
// load-bearing — operators / log aggregators may match on it.
func TestVersioningHealLogPrefix(t *testing.T) {
// glog writes to os.Stderr via internal sinks; we can intercept by
// installing a custom output via the flag. Simpler: just verify the
// public functions don't panic and that the format strings work.
// Behavioural check is via reading what gets formatted.
// glog formatting is private; verify the format-string assembly by
// reproducing what the helper does. If the helper's prefix or layout
// drifts, this test fails first.
var buf bytes.Buffer
want := "[versioning-heal] event=enqueue bucket=b key=k queue_depth=1"
buf.WriteString("[versioning-heal] event=enqueue ")
buf.WriteString("bucket=b key=k queue_depth=1")
assert.Equal(t, want, buf.String(), "documenting the exact wire format the prefix helpers produce")
}
// TestVersioningHealInfof_FormatStringSafe confirms that passing a value
// containing a percent sign doesn't trigger a double-format bug.
func TestVersioningHealInfof_FormatStringSafe(t *testing.T) {
// The helpers Sprintf the inner format first, then wrap. Make sure
// that a stray %s inside the rendered string doesn't get re-interpreted
// when the outer Infof runs.
//
// Trigger flag init so glog is wired before logging in tests.
_ = flag.Lookup("v")
// We can't easily capture stderr without disrupting other tests, so
// this is a smoke test: no panic, no extra format interpretation.
defer func() {
if r := recover(); r != nil {
t.Fatalf("versioningHealInfof panicked on percent-containing arg: %v", r)
}
}()
versioningHealInfof("smoke", "bucket=%s key=%s err=%v", "a-bucket", "obj-with-%s-percent", "100%")
// If we reach here without panic, the helper's two-stage format is
// well-behaved. Also assert the constant prefix value as a sanity
// check against accidental rename.
assert.True(t, strings.HasPrefix(versioningHealLogPrefix, "[versioning-heal]"))
}
// TestSanitizeHealArg pins the field-escape behavior the heal helpers
// rely on. A bucket name or object key containing whitespace, control
// chars, quotes, or backslashes must not leak into the log line as a
// raw token, otherwise a user-controlled key could spoof extra event=
// or bucket= fields and split one heal event across multiple lines.
func TestSanitizeHealArg(t *testing.T) {
cases := []struct {
name string
in interface{}
want interface{}
}{
// Safe values pass through unchanged so common log output stays
// human-readable.
{"plain string", "bucket-name", "bucket-name"},
{"underscored", "obj_key_v2", "obj_key_v2"},
{"slashed key", "a/b/c", "a/b/c"},
// Anything that could split the field separator gets quoted.
{"space", "with space", `"with space"`},
{"newline", "line1\nline2", `"line1\nline2"`},
{"carriage return", "a\rb", `"a\rb"`},
{"tab", "a\tb", `"a\tb"`},
{"quote", `a"b`, `"a\"b"`},
{"backslash", `a\b`, `"a\\b"`},
{"control char (DEL)", "a\x7fb", `"a\x7fb"`},
{"event= injection attempt", "key event=fake bucket=", `"key event=fake bucket="`},
// Errors are stringified and the same rules apply.
{"error with newline", errors.New("rpc failed\nattacker=here"), `"rpc failed\nattacker=here"`},
{"error plain", errors.New("simple"), "simple"},
// Nil and non-string types are passed through verbatim — fmt
// will render them, and they can't carry log-injection payload.
{"nil arg", nil, nil},
{"int arg", 42, 42},
{"bool arg", true, true},
}
for _, tc := range cases {
t.Run(tc.name, func(t *testing.T) {
got := sanitizeHealArg(tc.in)
assert.Equal(t, tc.want, got)
})
}
}
// TestVersioningHealInfof_KeyWithWhitespaceStaysOneField confirms the
// end-to-end format: when a caller passes a malicious key, the
// fmt.Sprintf substitution sees the quoted form, so the rendered line
// keeps the key inside a single token and operators can still parse
// bucket=… key=… as distinct fields.
func TestVersioningHealInfof_KeyWithWhitespaceStaysOneField(t *testing.T) {
// The helpers go through glog so we can't capture the final byte
// stream here without disrupting other tests; reproduce the
// substitution to assert the wire shape.
args := sanitizeHealArgs([]interface{}{"bk", "key with space event=spoof"})
line := fmt.Sprintf("bucket=%s key=%s", args...)
assert.Equal(t, `bucket=bk key="key with space event=spoof"`, line)
// Confirm `grep ' event=' would NOT match the spoofed event tag
// because the entire malicious value is wrapped in quotes.
assert.NotContains(t, strings.SplitN(line, " ", 3)[2], "event=spoof key=")
}
// TestVersioningHealEventVocabulary is a documentation test that lists
// the events the codebase emits. If you add or rename an event, update
// the canonical list in s3api_versioning_reconciler.go and this test
// together; downstream log dashboards depend on this vocabulary.
func TestVersioningHealEventVocabulary(t *testing.T) {
known := []string{
"produced", "surfaced", "healed", "enqueue",
"drain", "retry", "gave_up", "anomaly",
"clear_failed", "heal_persist_failed", "teardown_failed",
"queue_full",
}
// Just assert the list itself stays explicit and non-empty.
assert.NotEmpty(t, known)
for _, e := range known {
assert.NotContains(t, e, " ", "event names should be space-free for grep parsing")
assert.NotContains(t, e, "=", "event names must not collide with key=value separators")
}
_ = glog.V(0) // keep the glog import meaningful in case the helper signatures evolve
}
+84 -4
View File
@@ -4,6 +4,7 @@ import (
"context"
"errors"
"fmt"
"strconv"
"sync"
"time"
@@ -14,6 +15,84 @@ import (
"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
@@ -67,7 +146,7 @@ func (q *versionsHealQueue) Enqueue(bucket, object string) {
return
}
if len(q.pending) >= versionsHealQueueCapacity {
glog.V(1).Infof("versionsHealQueue: capacity reached, dropping %s/%s", bucket, object)
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{
@@ -76,6 +155,7 @@ func (q *versionsHealQueue) Enqueue(bucket, object string) {
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
@@ -99,7 +179,7 @@ func (q *versionsHealQueue) popReady(now time.Time) []*versionsHealCandidate {
// as a last-resort safety net.
func (q *versionsHealQueue) requeue(c *versionsHealCandidate, backoff time.Duration) {
if c.attempts >= versionsHealMaxRetries {
glog.Warningf("versionsHealQueue: giving up on %s/%s after %d attempts (read-path heal will still recover)", c.bucket, c.object, c.attempts)
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()
@@ -152,11 +232,11 @@ func (s3a *S3ApiServer) drainVersionsHealQueue() {
if backoff > versionsHealMaxBackoff {
backoff = versionsHealMaxBackoff
}
glog.V(1).Infof("versionsHealQueue: heal failed for %s/%s (attempt %d): %v; retry in %v", c.bucket, c.object, c.attempts, err, backoff)
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
}
glog.V(1).Infof("versionsHealQueue: healed %s/%s after %d attempt(s) (queued for %v)", c.bucket, c.object, c.attempts, time.Since(c.enqueued))
versioningHealInfof("drain", "bucket=%s key=%s attempts=%d queued_for=%v", c.bucket, c.object, c.attempts, time.Since(c.enqueued))
}
}
+29 -3
View File
@@ -86,7 +86,7 @@ func TestVersionsHealQueue_GiveUpAfterMaxAttempts(t *testing.T) {
// errors.
func TestRetryFilerOp_SucceedsBeforeExhaustion(t *testing.T) {
calls := 0
err := retryFilerOp("test", func() error {
err := retryFilerOp(context.Background(), "test", func() error {
calls++
if calls < 3 {
return errors.New("transient")
@@ -102,7 +102,7 @@ func TestRetryFilerOp_SucceedsBeforeExhaustion(t *testing.T) {
// a glance whether the underlying issue is transient.
func TestRetryFilerOp_PropagatesAfterExhaustion(t *testing.T) {
calls := 0
err := retryFilerOp("test", func() error {
err := retryFilerOp(context.Background(), "test", func() error {
calls++
return errors.New("permanent")
})
@@ -112,6 +112,32 @@ func TestRetryFilerOp_PropagatesAfterExhaustion(t *testing.T) {
assert.Contains(t, err.Error(), "permanent", "underlying error preserved")
}
// TestRetryFilerOp_ContextCancelInterruptsBackoff confirms that a ctx
// canceled mid-backoff returns ctx.Err() immediately instead of
// blocking until the worst-case ~6.3s retry budget elapses. Server
// shutdown / client disconnect relies on this to drain in-flight
// retries promptly.
func TestRetryFilerOp_ContextCancelInterruptsBackoff(t *testing.T) {
ctx, cancel := context.WithCancel(context.Background())
// Cancel after the first failed attempt has scheduled its backoff
// but well before the timer fires.
go func() {
time.Sleep(30 * time.Millisecond)
cancel()
}()
calls := 0
start := time.Now()
err := retryFilerOp(ctx, "test", func() error {
calls++
return errors.New("transient")
})
elapsed := time.Since(start)
require.Error(t, err)
assert.ErrorIs(t, err, context.Canceled, "must surface ctx.Err verbatim")
assert.Less(t, elapsed, 500*time.Millisecond, "ctx cancel must interrupt the backoff sleep")
assert.Less(t, calls, updateLatestRetryAttempts, "ctx cancel must short-circuit before exhausting the retry budget")
}
// TestRetryFilerOp_TerminalErrorsShortCircuit confirms that errors which
// won't change on retry (NotFound, context cancellation) are returned
// immediately and unwrapped, without burning the retry budget.
@@ -130,7 +156,7 @@ func TestRetryFilerOp_TerminalErrorsShortCircuit(t *testing.T) {
t.Run(tc.name, func(t *testing.T) {
start := time.Now()
calls := 0
err := retryFilerOp("test", func() error {
err := retryFilerOp(context.Background(), "test", func() error {
calls++
return tc.err
})
+241
View File
@@ -0,0 +1,241 @@
package shell
import (
"context"
"flag"
"fmt"
"io"
"strings"
"sync/atomic"
"time"
"github.com/seaweedfs/seaweedfs/weed/pb/filer_pb"
s3_constants "github.com/seaweedfs/seaweedfs/weed/s3api/s3_constants"
"github.com/seaweedfs/seaweedfs/weed/util"
)
func init() {
Commands = append(Commands, &commandS3VersionsAudit{})
}
type commandS3VersionsAudit struct{}
func (c *commandS3VersionsAudit) Name() string {
return "s3.versions.audit"
}
func (c *commandS3VersionsAudit) Help() string {
return `audit .versions/ directories under a prefix for stranded pointer/missing-file state
Walks every entry under the given prefix and, for each directory whose
name ends in ".versions", checks whether its extended-attr latest-version
pointer references a file that actually exists in the directory.
Reports counts for:
- directories scanned
- clean (no pointer, or pointer matches existing file)
- stranded (pointer set but file is missing) — the symptom seen by
Veeam/etc. as "Storage not found" on the next GET
- orphan (directory has files lacking the version-id extended attr,
which the post-delete cleanup path will refuse to rm)
Example:
# Audit a whole bucket
s3.versions.audit -prefix /buckets/mybucket
# Audit a specific client subtree, print each finding
s3.versions.audit -prefix /buckets/mybucket/Veeam/Backup/groupsoftware/Clients/<uuid>/ -v
# Dry run (default) — read-only, prints what would be healed
# Add -heal to clear stranded pointers in place (calls the same path
# the read-side self-heal uses)
s3.versions.audit -prefix /buckets/mybucket -heal
This command is read-only by default. With -heal, it clears the stale
latest-version pointer on stranded directories; the blob is already
gone, so reads then return NoSuchKey via the clean-miss path instead
of replaying the 10-retry self-heal loop on every request.
`
}
func (c *commandS3VersionsAudit) HasTag(CommandTag) bool {
return false
}
func (c *commandS3VersionsAudit) Do(args []string, commandEnv *CommandEnv, writer io.Writer) error {
cmd := flag.NewFlagSet(c.Name(), flag.ContinueOnError)
prefix := cmd.String("prefix", "", "filer path to audit recursively (e.g. /buckets/mybucket)")
verbose := cmd.Bool("v", false, "print each stranded/orphan directory as it's found")
doHeal := cmd.Bool("heal", false, "clear the latest-version pointer on stranded directories (default: read-only)")
if err := cmd.Parse(args); err != nil {
return err
}
if *prefix == "" {
return fmt.Errorf("-prefix is required")
}
// Counters
var (
dirsScanned uint64
versionsDirs uint64
clean uint64
stranded uint64
orphanOnly uint64
healed uint64
healFailed uint64
)
start := time.Now()
ctx, cancel := context.WithCancel(context.Background())
defer cancel()
err := commandEnv.WithFilerClient(false, func(client filer_pb.SeaweedFilerClient) error {
return filer_pb.TraverseBfs(ctx, &filerClientWrapper{client: client}, util.FullPath(*prefix), func(parentPath util.FullPath, entry *filer_pb.Entry) error {
atomic.AddUint64(&dirsScanned, 1)
if !entry.IsDirectory {
return nil
}
if !strings.HasSuffix(entry.Name, ".versions") {
return nil
}
atomic.AddUint64(&versionsDirs, 1)
// What does the pointer name?
var pointerFile string
if entry.Extended != nil {
if v, ok := entry.Extended[s3_constants.ExtLatestVersionFileNameKey]; ok {
pointerFile = string(v)
}
}
// List the children to see if the pointer's file exists and to
// count entries without an ExtVersionIdKey (orphans that block
// non-recursive teardown). filer_pb.List returns one 1024-entry
// page; walk all pages so a large .versions/ directory doesn't
// produce a false positive "stranded" report from only seeing
// the first page.
versionsPath := string(parentPath) + "/" + entry.Name
pointerSeen := false
hasOrphan := false
const auditPageSize = 1024
var startName string
for {
pageEntries := 0
var lastEntryName string
lookupErr := filer_pb.List(ctx, &filerClientWrapper{client: client}, versionsPath, "", func(child *filer_pb.Entry, isLast bool) error {
if child == nil {
return nil
}
pageEntries++
lastEntryName = child.Name
hasVersionId := false
if child.Extended != nil {
if _, ok := child.Extended[s3_constants.ExtVersionIdKey]; ok {
hasVersionId = true
}
}
if pointerFile != "" && child.Name == pointerFile {
pointerSeen = true
}
if !hasVersionId {
hasOrphan = true
}
return nil
}, startName, startName != "", auditPageSize)
if lookupErr != nil {
fmt.Fprintf(writer, "list %s: %v\n", versionsPath, lookupErr)
return nil
}
if pageEntries < auditPageSize {
break
}
startName = lastEntryName
}
switch {
case pointerFile == "":
// No pointer set. Orphan-only and clean are now mutually
// exclusive so the final report's category counts sum to
// versionsDirs.
if hasOrphan {
atomic.AddUint64(&orphanOnly, 1)
} else {
atomic.AddUint64(&clean, 1)
}
case pointerSeen:
atomic.AddUint64(&clean, 1)
default:
// Pointer names a file that the listing does NOT contain.
atomic.AddUint64(&stranded, 1)
if *verbose {
fmt.Fprintf(writer, "stranded: %s pointer=%s orphan=%v\n", versionsPath, pointerFile, hasOrphan)
}
if *doHeal {
if err := healStrandedPointer(ctx, client, parentPath, entry); err != nil {
atomic.AddUint64(&healFailed, 1)
fmt.Fprintf(writer, "heal failed: %s: %v\n", versionsPath, err)
} else {
atomic.AddUint64(&healed, 1)
}
}
}
return nil
})
})
elapsed := time.Since(start)
fmt.Fprintf(writer, "audit complete in %s\n", elapsed)
fmt.Fprintf(writer, " total entries scanned : %d\n", dirsScanned)
fmt.Fprintf(writer, " .versions/ directories: %d\n", versionsDirs)
fmt.Fprintf(writer, " clean : %d\n", clean)
fmt.Fprintf(writer, " stranded : %d\n", stranded)
fmt.Fprintf(writer, " orphan-only : %d\n", orphanOnly)
if *doHeal {
fmt.Fprintf(writer, " healed : %d\n", healed)
fmt.Fprintf(writer, " heal failed : %d\n", healFailed)
}
return err
}
// healStrandedPointer clears the latest-version pointer extended attrs
// on a stranded .versions/ directory. The blob the pointer names is
// already gone; clearing the pointer makes subsequent reads return
// NoSuchKey via the clean-miss path instead of replaying the read-side
// self-heal on every request.
func healStrandedPointer(ctx context.Context, client filer_pb.SeaweedFilerClient, parentPath util.FullPath, entry *filer_pb.Entry) error {
if entry.Extended == nil {
return nil
}
delete(entry.Extended, s3_constants.ExtLatestVersionIdKey)
delete(entry.Extended, s3_constants.ExtLatestVersionFileNameKey)
// Also clear the cached list metadata so a stale size/mtime/etag
// can't be served back; those will be repopulated on the next PUT.
delete(entry.Extended, s3_constants.ExtLatestVersionSizeKey)
delete(entry.Extended, s3_constants.ExtLatestVersionMtimeKey)
delete(entry.Extended, s3_constants.ExtLatestVersionETagKey)
delete(entry.Extended, s3_constants.ExtLatestVersionOwnerKey)
delete(entry.Extended, s3_constants.ExtLatestVersionIsDeleteMarker)
_, err := client.UpdateEntry(ctx, &filer_pb.UpdateEntryRequest{
Directory: string(parentPath),
Entry: entry,
})
return err
}
// filerClientWrapper adapts a raw SeaweedFilerClient to the
// filer_pb.FilerClient interface that List / TraverseBfs expect.
type filerClientWrapper struct {
client filer_pb.SeaweedFilerClient
}
func (w *filerClientWrapper) WithFilerClient(streamingMode bool, fn func(filer_pb.SeaweedFilerClient) error) error {
return fn(w.client)
}
func (w *filerClientWrapper) AdjustedUrl(location *filer_pb.Location) string {
return location.Url
}
func (w *filerClientWrapper) GetDataCenter() string {
return ""
}