fix(ilm): count and trace a read-time expiry the all-pools recheck skips

GET and HEAD recheck a local expiry decision against the versions of
the object in all pools before they hide the version or queue its
expiry. When that recheck failed, because the history of another pool
could not be read, or found that the rule no longer applies with the
versions in all pools, the read was served and nothing was queued,
without a trace or a count. During a degraded pool a version that is
due kept reading and never reached the expiry workers, and the operator
could learn of it only from the scanner's own counts.

recheckReadExpiry now reports such a read as the scanner reports an
expiry it did not complete: it counts expiry_incomplete_total by the
reason ilmExpiryNotDone gives the error, history_unavailable for a read
quorum failure, not_applicable when the version is no longer due, and
publishes an ILM trace with result=skipped and that reason. The reasons
are the existing label values; the response, the version read and the
decision not to queue are unchanged.

TestPoolsLifecycleReadHTTP now asserts the counter delta and the trace
of every case the recheck skips; before this change it counted nothing
for the unreadable-pool and the not-applicable cases.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Signed-off-by: Feng Ruohang <rh@vonng.com>

cmd/erasure-server-pool-lifecycle.go

@@ -767,7 +767,10 @@ func (z *erasureServerPools) expiryNeedsAllPools(opts ObjectOptions) bool {
 // recheckReadExpiry only rechecks a local ordinary-delete candidate. The
 // global latest expiring does not authorize hiding a different version that
 // GET/HEAD has already read. On an incomplete or rejected recheck, keep that
-// successful read and do not queue an expiry. Leave response metadata intact.
+// successful read and do not queue an expiry, and count and trace the
+// expiry as skipped by why, as the scanner reports an expiry it did not
+// complete: the history could not be read, or the rule no longer applies
+// with the versions in all pools. Leave response metadata intact.
 func recheckReadExpiry(ctx context.Context, objectAPI ObjectLayer, oi ObjectInfo, evt lifecycle.Event) (ObjectInfo, lifecycle.Event) {
 	z, ok := objectAPI.(*erasureServerPools)
 	if !ok || !evt.Action.Delete() || evt.Action.DeleteRestored() || !z.expiryNeedsAllPools(ObjectOptions{
@@ -779,6 +782,7 @@ func recheckReadExpiry(ctx context.Context, objectAPI ObjectLayer, oi ObjectInfo
 	}) {
 		return oi, evt
 	}
+	traceFn := globalLifecycleSys.trace(oi)
 	versions, events, err := z.lifecycleEventsAllPools(ctx, oi.Bucket, encodeDirObject(oi.Name))
 	if err == nil {
 		versionID := oi.VersionID
@@ -798,6 +802,12 @@ func recheckReadExpiry(ctx context.Context, objectAPI ObjectLayer, oi ObjectInfo
 			}
 		}
 	}
+	reason, counted := ilmExpiryNotDone(err)
+	if !counted {
+		reason = ilmIncompleteNotApplicable
+	}
+	globalILMIncomplete.add(reason)
+	traceFn(ILMExpiry, map[string]string{"result": "skipped", "reason": reason, "version-id": oi.VersionID}, err)
 	return oi, lifecycle.Event{Action: lifecycle.NoneAction}
 }
 

cmd/object-lifecycle-read_test.go

@@ -98,15 +98,18 @@ func TestPoolsLifecycleReadHTTP(t *testing.T) {
 				local        lifecycle.Action
 				fault        error
 				wantScan     bool
+				// skipped is the reason the recheck counts and traces when
+				// it serves the read instead of the local expiry.
+				skipped string
 			}{
-				{name: "old-version-new-latest", prefix: "exp-", latestAge: 0.01, local: lifecycle.DeleteAction, wantScan: true},
-				{name: "old-version-expired-latest", prefix: "exp-", latestAge: 3, local: lifecycle.DeleteAction, wantScan: true},
-				{name: "old-version-delete-all-latest", prefix: "eav-", latestAge: 3, local: lifecycle.DeleteAllVersionsAction, wantScan: true},
+				{name: "old-version-new-latest", prefix: "exp-", latestAge: 0.01, local: lifecycle.DeleteAction, wantScan: true, skipped: ilmIncompleteNotApplicable},
+				{name: "old-version-expired-latest", prefix: "exp-", latestAge: 3, local: lifecycle.DeleteAction, wantScan: true, skipped: ilmIncompleteNotApplicable},
+				{name: "old-version-delete-all-latest", prefix: "eav-", latestAge: 3, local: lifecycle.DeleteAllVersionsAction, wantScan: true, skipped: ilmIncompleteNotApplicable},
 				{name: "expired-current", prefix: "exp-", latestAge: 3, readLatest: true, local: lifecycle.DeleteAction, action: lifecycle.DeleteAction, wantScan: true},
 				{name: "expired-current-implicit", prefix: "exp-", latestAge: 3, readLatest: true, implicit: true, local: lifecycle.DeleteAction, action: lifecycle.DeleteAction, wantScan: true},
 				{name: "expired-noncurrent", prefix: "both-", latestAge: 3, local: lifecycle.DeleteAction, action: lifecycle.DeleteVersionAction, wantScan: true},
-				{name: "extra-read-quorum-error", prefix: "exp-", latestAge: 3, local: lifecycle.DeleteAction, fault: errDiskNotFound, wantScan: true},
-				{name: "read-version-missing-from-recheck", prefix: "exp-", latestAge: 3, local: lifecycle.DeleteAction, fault: errFileNotFound, wantScan: true},
+				{name: "extra-read-quorum-error", prefix: "exp-", latestAge: 3, local: lifecycle.DeleteAction, fault: errDiskNotFound, wantScan: true, skipped: ilmIncompleteHistoryUnavailable},
+				{name: "read-version-missing-from-recheck", prefix: "exp-", latestAge: 3, local: lifecycle.DeleteAction, fault: errFileNotFound, wantScan: true, skipped: ilmIncompleteNotApplicable},
 				{name: "local-none-global-expired", prefix: "ncv-", latestAge: 3, local: lifecycle.NoneAction},
 			} {
 				for _, null := range []bool{false, true} {
@@ -148,6 +151,7 @@ func TestPoolsLifecycleReadHTTP(t *testing.T) {
 								t.Fatal("fixture must be globally expired but locally NoneAction")
 							}
 							scans := lifecycleReadDisks(t, s, key, oldPool, tc.fault)
+							observer := observePurges(t)
 							for _, method := range []string{http.MethodGet, http.MethodHead} {
 								t.Run(method, func(t *testing.T) {
 									scans.Store(0)
@@ -155,7 +159,27 @@ func TestPoolsLifecycleReadHTTP(t *testing.T) {
 									if tc.implicit {
 										requestID = ""
 									}
-									rec := consistencyRequest(t, router, method, s.bucket, key, requestID)
+									observer.drain()
+									var rec *httptest.ResponseRecorder
+									delta := incompleteDelta(func() { rec = consistencyRequest(t, router, method, s.bucket, key, requestID) })
+									// A read the recheck serves instead of the local
+									// expiry is counted and traced as skipped, by why.
+									_, traces := observer.drain()
+									var skipped []map[string]string
+									for _, tr := range traces {
+										if tr["result"] == "skipped" {
+											skipped = append(skipped, tr)
+										}
+									}
+									switch {
+									case tc.skipped == "" && (len(delta) != 0 || len(skipped) != 0):
+										t.Errorf("counted %v and traced %v, want nothing skipped", delta, skipped)
+									case tc.skipped != "" && (len(delta) != 1 || delta[tc.skipped] != 1):
+										t.Errorf("counted %v, want one %s", delta, tc.skipped)
+									case tc.skipped != "" && (len(skipped) != 1 || skipped[0]["reason"] != tc.skipped ||
+										s.key(key, skipped[0]["version-id"]) != s.key(key, vid)):
+										t.Errorf("traced %v, want one skipped expiry of %s for %s", skipped, vid, tc.skipped)
+									}
 									want := http.StatusOK
 									if tc.action.Delete() {
 										want = http.StatusNotFound