Repository: minio/minio (language: go)

Issue:
Background healing newer finish when changing server by new.
Hello

I'm observing strange behaviour of background healing when changing server fleet of minio service. The background healing newer finish for us and I need to force it by some manual "tricks" (restarting services repeatedly, running multiple time "mc admin heal -r alias").

Can you please check what is wrong with the healing in minio? I can easily reproduce it and run test as needed.

## Expected Behavior
* Change server by new with empty disks,
* background healing is running by "constant speed" and finish without manual operation tasks.

## Current Behavior
I would like to show it of attached "[healing.png](https://drive.google.com/file/d/19ro1nQh6MxICRKZ6WjiieJ5peVkUtgoD/view?usp=sharing)" graph. The graph reports how the disk are filled so it shows how healing is working in time:
0 - The healing is expected to finish when disks are having ~2TiB of free space.
1 - One server is replaced with new disks in each Minio pool (the disk are empty and havin ~4 TiB free)
2 - Background healing starts for almost all disks == OK
3 - Few disks do not start healing == WRONG
4 - The haling stops at ~3TiB for all disks == WRONG
now I need to manually restart the minio service  ```minio admin service alias restart```
5 - The few disks from (step 3) start to heal, but not all (disks from step4) == WRONG
after few hours later it stops the helaing of all disks again, the space free us still about ~3TiB.
6 - I have to run ```minio admin heal -r alias``` to enforce healing.

## Steps to Reproduce (for bugs)
1. Replace minio server in a pool by new with empty disks. 
2. Wait and observe storage usage by healing process. It shows "Estimated: 1 day" for few hours.
3. The healing stops to fill disks after few hours and the estimated healing time of disks start to grow like to days at first, then grows to months.

## Context

How has this issue affected you?
* Healings of new disks newer finish automatically. We must run manual restarts of service and run foreground healing process repeatedly (manually).

## Your Environment

* Version used 
minio version RELEASE.2023-02-17T17-52-43Z (commit-id=84bb7d05a998a096b96acd68ea94053d28a87eb3)
Runtime: go1.19.6 linux/amd64
License: GNU AGPLv3 <https://www.gnu.org/licenses/agpl-3.0.html>
Copyright: 2015-2023 MinIO, Inc.

* Server setup:
Two pools, each pool of 16 servers, each server 4 disks.

* Operating System and version:
CentOS 9 Stream



Discussion / hints:
@pulchart does manual healing successfully finish ? can you upload all logs that you have ?
> @pulchart does manual healing successfully finish ?

Yes the manual healing was successful. Example of one last run see here [one_from_the_loop.png](https://drive.google.com/file/d/1VDrSBT7sVQdo84jck1mzuSJdhauNrevv/view?usp=sharing) 

> can you upload all logs that you have ?

They are full of the manual restarts / updates etc... as I try to trigger the healing. Are you interested in some period of the time from healing or after some action?
Hello, I replaced more servers from each pool and observed the healing.

**For context:**

We can replace up to 16 disks (up to 4x servers) per each pool by new ones at any time in parallel as we have 16x servers per each pool and each server has 4x disks.

My initial report shows healing for case when 1x server is replaced (with new dicks) from each pool. 

**Now:**

I replaced +2x servers from each pool and the healing is now running at 3x servers from each pool (12x disks in each pool) in parallel.

**Report:**

See sections in linked png graph [slow_healing.png](https://drive.google.com/file/d/1ABNSkcMcV5jvl8m2xNtgN-G4gNpz-XBU). It shows space usage going down by healing process. I mark there five sections:

Section 1) my original report

Section 2) replaced +2x server in each pool

Background healing was going well for pool 2 disks but slow for pool 1 disks. However it slow down for pool 2 after +7h and not mowing forward.

Section 3) I restart the service ```mc admin service alias restart```

Healing was going well for pool 1, but just for few minutes. Both pools healing is super slow again.

Section 4) I run foreground healing ```mc admin heal -r -v alias```

Foreground healing was going well for pool 1 but was slow for pool 2. It slowdown after +7h again for all disks. **The healing scanned just ~3k object from ~16M in ~2 hours**.

Section 5) I run multiple ```mc admin heal -r -v alias/pathXY```

I kill previous ```mc admin heal -r -v alias``` and instead of it I parallelized it by command like this:
```
mc admin heal -r -v alias/<path1>
mc admin heal -r -v alias/<path2>
mc admin heal -r -v alias/<path3>
...
mc admin heal -r -v alias/<path15>
```

**Healing sped up however again pool by pool. Not in parallel,**



Fix patch:
diff --git a/cmd/background-newdisks-heal-ops.go b/cmd/background-newdisks-heal-ops.go
index 2dc11d9d40036..f904ff4d56229 100644
--- a/cmd/background-newdisks-heal-ops.go
+++ b/cmd/background-newdisks-heal-ops.go
@@ -299,7 +299,7 @@ func healFreshDisk(ctx context.Context, z *erasureServerPools, endpoint Endpoint
 	defer disk.Close()
 	poolIdx := globalEndpoints.GetLocalPoolIdx(disk.Endpoint())
 	if poolIdx < 0 {
-		return fmt.Errorf("unexpected pool index (%d) found in %s", poolIdx, disk.Endpoint())
+		return fmt.Errorf("unexpected pool index (%d) found for %s", poolIdx, disk.Endpoint())
 	}
 
 	// Calculate the set index where the current endpoint belongs
@@ -310,14 +310,15 @@ func healFreshDisk(ctx context.Context, z *erasureServerPools, endpoint Endpoint
 		return err
 	}
 	if setIdx < 0 {
-		return fmt.Errorf("unexpected set index (%d) found in %s", setIdx, disk.Endpoint())
+		return fmt.Errorf("unexpected set index (%d) found for  %s", setIdx, disk.Endpoint())
 	}
 
 	// Prevent parallel erasure set healing
 	locker := z.NewNSLock(minioMetaBucket, fmt.Sprintf("new-drive-healing/%d/%d", poolIdx, setIdx))
 	lkctx, err := locker.GetLock(ctx, newDiskHealingTimeout)
 	if err != nil {
-		return err
+		return fmt.Errorf("Healing of drive '%v' on %s pool, belonging to %s erasure set already in progress: %w",
+			disk, humanize.Ordinal(poolIdx+1), humanize.Ordinal(setIdx+1), err)
 	}
 	ctx = lkctx.Context()
 	defer locker.Unlock(lkctx)
@@ -325,19 +326,20 @@ func healFreshDisk(ctx context.Context, z *erasureServerPools, endpoint Endpoint
 	// Load healing tracker in this disk
 	tracker, err := loadHealingTracker(ctx, disk)
 	if err != nil {
-		// A healing track can be not found when another disk in the same
-		// erasure set and same healing-id successfully finished healing.
-		if err == errFileNotFound {
+		// A healing tracker may be deleted if another disk in the
+		// same erasure set with same healing-id successfully finished
+		// healing.
+		if errors.Is(err, errFileNotFound) {
 			return nil
 		}
-		logger.LogIf(ctx, fmt.Errorf("Unable to load a healing tracker on '%s': %w", disk, err))
+		logger.LogIf(ctx, fmt.Errorf("Unable to load healing tracker on '%s': %w, re-initializing..", disk, err))
 		tracker = newHealingTracker(disk, mustGetUUID())
 	}
 
-	logger.Info(fmt.Sprintf("Proceeding to heal '%s' - 'mc admin heal alias/ --verbose' to check the status.", endpoint))
+	logger.Info(fmt.Sprintf("Healing drive '%s' - 'mc admin heal alias/ --verbose' to check the current status.", endpoint))
 
 	buckets, _ := z.ListBuckets(ctx, BucketOptions{})
-	// Buckets data are dispersed in multiple zones/sets, make
+	// Buckets data are dispersed in multiple pools/sets, make
 	// sure to heal all bucket metadata configuration.
 	buckets = append(buckets, BucketInfo{
 		Name: pathJoin(minioMetaBucket, minioConfigPrefix),
@@ -355,7 +357,7 @@ func healFreshDisk(ctx context.Context, z *erasureServerPools, endpoint Endpoint
 	})
 
 	if serverDebugLog {
-		logger.Info("Healing drive '%v' on %s pool", disk, humanize.Ordinal(poolIdx+1))
+		logger.Info("Healing drive '%v' on %s pool, belonging to %s erasure set", disk, humanize.Ordinal(poolIdx+1), humanize.Ordinal(setIdx+1))
 	}
 
 	// Load bucket totals
@@ -378,9 +380,9 @@ func healFreshDisk(ctx context.Context, z *erasureServerPools, endpoint Endpoint
 	}
 
 	if tracker.ItemsFailed > 0 {
-		logger.Info("Healing drive '%s' failed (healed: %d, failed: %d).", disk, tracker.ItemsHealed, tracker.ItemsFailed)
+		logger.Info("Healing of drive '%s' failed (healed: %d, failed: %d).", disk, tracker.ItemsHealed, tracker.ItemsFailed)
 	} else {
-		logger.Info("Healing drive '%s' complete (healed: %d, failed: %d).", disk, tracker.ItemsHealed, tracker.ItemsFailed)
+		logger.Info("Healing of drive '%s' complete (healed: %d, failed: %d).", disk, tracker.ItemsHealed, tracker.ItemsFailed)
 	}
 
 	if len(tracker.QueuedBuckets) > 0 {
@@ -392,7 +394,7 @@ func healFreshDisk(ctx context.Context, z *erasureServerPools, endpoint Endpoint
 		logger.Info("\n")
 	}
 
-	if tracker.HealID == "" { // HealID is empty only before Feb 2023
+	if tracker.HealID == "" { // HealID was empty only before Feb 2023
 		logger.LogIf(ctx, tracker.delete(ctx))
 		return nil
 	}
@@ -401,7 +403,7 @@ func healFreshDisk(ctx context.Context, z *erasureServerPools, endpoint Endpoint
 	for _, disk := range z.serverPools[poolIdx].sets[setIdx].getDisks() {
 		t, err := loadHealingTracker(ctx, disk)
 		if err != nil {
-			if err != errFileNotFound {
+			if !errors.Is(err, errFileNotFound) {
 				logger.LogIf(ctx, err)
 			}
 			continue
@@ -446,8 +448,7 @@ func monitorLocalDisksAndHeal(ctx context.Context, z *erasureServerPools) {
 			for _, disk := range healDisks {
 				go func(disk Endpoint) {
 					globalBackgroundHealState.setDiskHealingStatus(disk, true)
-					err := healFreshDisk(ctx, z, disk)
-					if err != nil {
+					if err := healFreshDisk(ctx, z, disk); err != nil {
 						globalBackgroundHealState.setDiskHealingStatus(disk, false)
 						printEndpointError(disk, err, false)
 						return
diff --git a/cmd/global-heal.go b/cmd/global-heal.go
index cac79b2552a76..4ed70e14804a1 100644
--- a/cmd/global-heal.go
+++ b/cmd/global-heal.go
@@ -269,7 +269,7 @@ func (er *erasureObjects) healErasureSet(ctx context.Context, buckets []string,
 		}()
 
 		// Note: updates from healEntry to tracker must be sent on results channel.
-		healEntry := func(entry metaCacheEntry) {
+		healEntry := func(bucket string, entry metaCacheEntry) {
 			if entry.name == "" && len(entry.metadata) == 0 {
 				// ignore entries that don't have metadata.
 				return
@@ -278,6 +278,7 @@ func (er *erasureObjects) healErasureSet(ctx context.Context, buckets []string,
 				// ignore healing entry.name's with `/` suffix.
 				return
 			}
+
 			// We might land at .metacache, .trash, .multipart
 			// no need to heal them skip, only when bucket
 			// is '.minio.sys'
@@ -302,6 +303,11 @@ func (er *erasureObjects) healErasureSet(ctx context.Context, buckets []string,
 					versionID: "",
 				}, madmin.HealItemObject)
 				if err != nil {
+					if isErrObjectNotFound(err) {
+						// queueing happens across namespace, ignore
+						// objects that are not found.
+						return
+					}
 					result = healEntryFailure(0)
 					logger.LogIf(ctx, fmt.Errorf("unable to heal object %s/%s: %w", bucket, entry.name, err))
 				} else {
@@ -317,12 +323,19 @@ func (er *erasureObjects) healErasureSet(ctx context.Context, buckets []string,
 				return
 			}
 
+			var versionNotFound int
 			for _, version := range fivs.Versions {
 				if err := bgSeq.queueHealTask(healSource{
 					bucket:    bucket,
 					object:    version.Name,
 					versionID: version.VersionID,
 				}, madmin.HealItemObject); err != nil {
+					if isErrObjectNotFound(err) {
+						// queueing happens across namespace, ignore
+						// objects that are not found.
+						versionNotFound++
+						continue
+					}
 					// If not deleted, assume they failed.
 					result = healEntryFailure(uint64(version.Size))
 					if version.VersionID != "" {
@@ -341,6 +354,10 @@ func (er *erasureObjects) healErasureSet(ctx context.Context, buckets []string,
 				case results <- result:
 				}
 			}
+			// All versions resulted in 'ObjectNotFound'
+			if versionNotFound == len(fivs.Versions) {
+				return
+			}
 			select {
 			case <-ctx.Done():
 				return
@@ -351,22 +368,25 @@ func (er *erasureObjects) healErasureSet(ctx context.Context, buckets []string,
 			waitForLowHTTPReq()
 		}
 
+		actualBucket, prefix := path2BucketObject(bucket)
+
 		// How to resolve partial results.
 		resolver := metadataResolutionParams{
 			dirQuorum: 1,
 			objQuorum: 1,
-			bucket:    bucket,
+			bucket:    actualBucket,
 		}
 
 		err := listPathRaw(ctx, listPathRawOptions{
 			disks:          disks,
-			bucket:         bucket,
+			bucket:         actualBucket,
+			path:           prefix,
 			recursive:      true,
 			forwardTo:      forwardTo,
 			minDisks:       1,
 			reportNotFound: false,
 			agreed: func(entry metaCacheEntry) {
-				healEntry(entry)
+				healEntry(actualBucket, entry)
 			},
 			partial: func(entries metaCacheEntries, _ []error) {
 				entry, ok := entries.resolve(&resolver)
@@ -375,7 +395,7 @@ func (er *erasureObjects) healErasureSet(ctx context.Context, buckets []string,
 					// proceed to heal nonetheless.
 					entry, _ = entries.firstFound()
 				}
-				healEntry(*entry)
+				healEntry(actualBucket, *entry)
 			},
 			finished: nil,
 		})


Test patch: