Fix backup queue permanently stuck when a dequeued backup completes during the patch (#10521)

* Fix backup queue permanently stuck when a dequeued backup completes during the patch

Motivation: backupQueueReconciler patched a dequeued backup to ReadyToStart and
only called backupTracker.AddReadyToStart on the next line. If backupReconciler
picked up that patch and completed the backup (e.g. immediate FailedValidation
while a BackupStorageLocation is briefly unavailable) before the queue
controller reached that line, backupReconciler's Add + deferred Delete ran
first, and the later AddReadyToStart re-inserted a tracker key nothing would
ever delete again. backupTracker is in-memory and never reconciled against
actual Backup phases, so RunningCount() stayed stuck at concurrentBackups and
every later reconcile, including the periodic recheck, was refused at that
gate -- the queue stopped dequeuing permanently until the deployment restarted.

Approach: record the backup as ReadyToStart in the tracker before patching it,
and roll that back if the patch itself fails, so the tracker entry always
exists before the backup can become visible to any other reconciler. Also
folds in two related fixes: the concurrency-refusal log line is now Info
instead of Debug so a stuck queue is visible at the default log level, and the
queue-position renumbering loop's error log (which built a logrus.Entry via
log.WithError(errors.Wrapf(...)) but never called a terminal method on it, so
it never actually logged anything) now emits properly.

Validation: go build ./pkg/controller/..., go vet ./pkg/controller/..., and
gofmt -l on both changed files are all clean. golangci-lint run
./pkg/controller/... reports no findings. go mod tidy produces a zero diff to
go.mod/go.sum, matching this repo's verify-modules check. Mirrored this repo's
own hack/test.sh invocation for this package (-short -vet=... -skip TestAPIs)
and it passes; TestAPIs is a separate envtest suite that needs a local
kubebuilder etcd binary not installed on this machine and fails identically on
an unmodified checkout, so it is a pre-existing environment gap, not a
regression. Added TestBackupQueueReconcilerTrackerNotLeakedWhenBackupCompletesDuringPatch,
which uses a controller-runtime fake client with a Patch interceptor to
simulate a racing reconciler completing the backup right after the
ReadyToStart patch lands; it fails (RunningCount leaks to 1) against the
pre-fix ordering and passes (RunningCount returns to 0) against the fix.

Report: https://github.com/velero-io/velero/issues/10519
Signed-off-by: Pujitha Paladugu <10557236+pujitha24@users.noreply.github.com>
Assisted-by: claude-sonnet-5 (via Claude Code)

* Add changelog file for PR #10521

Signed-off-by: Pujitha Paladugu <10557236+pujitha24@users.noreply.github.com>

* Add test covering tracker rollback when ReadyToStart patch fails

Addresses review comment: verify backupTracker.RunningCount() returns
to 0 when the ReadyToStart patch itself errors, covering the Delete
rollback path alongside the existing race-condition regression test.

Signed-off-by: Tiger Kaovilai <tkaovila@redhat.com>

---------

Signed-off-by: Pujitha Paladugu <10557236+pujitha24@users.noreply.github.com>
Signed-off-by: Tiger Kaovilai <tkaovila@redhat.com>
Co-authored-by: Pujitha Paladugu <10557236+pujitha24@users.noreply.github.com>
Co-authored-by: Tiger Kaovilai <tkaovila@redhat.com>

changelogs/unreleased/10521-pujitha24

@@ -0,0 +1 @@
+Fix backup queue permanently stuck when a dequeued backup completes during the patch

pkg/controller/backup_queue_controller.go

@@ -272,7 +272,7 @@ func (r *backupQueueReconciler) Reconcile(ctx context.Context, req ctrl.Request)
 		}
 		lister := r.newQueuedBackupsLister(allBackups)
 		if r.backupTracker.RunningCount() >= r.concurrentBackups {
-			log.Debugf("%v concurrent backups are already running, leaving %v queued", r.concurrentBackups, backup.Name)
+			log.Infof("%v concurrent backups are already running, leaving %v queued", r.concurrentBackups, backup.Name)
 			return ctrl.Result{}, nil
 		}
 		earlierBackups := lister.earlierThan(backup.Status.QueuePosition)
@@ -294,10 +294,15 @@ func (r *backupQueueReconciler) Reconcile(ctx context.Context, req ctrl.Request)
 		original := backup.DeepCopy()
 		backup.Status.Phase = velerov1api.BackupPhaseReadyToStart
 		backup.Status.QueuePosition = 0
+		// Record ReadyToStart before patching: patching first would let
+		// backupReconciler pick up the change and complete the backup
+		// (Add then deferred Delete) before this call, leaking a
+		// tracker entry that nothing would ever clean up.
+		r.backupTracker.AddReadyToStart(backup.Namespace, backup.Name)
 		if err := kube.PatchResource(original, backup, r.Client); err != nil {
+			r.backupTracker.Delete(backup.Namespace, backup.Name)
 			return ctrl.Result{}, errors.Wrapf(err, "error updating Backup status to %s", backup.Status.Phase)
 		}
-		r.backupTracker.AddReadyToStart(backup.Namespace, backup.Name)
 		log.Debug("Updating queuePosition for remaining queued backups")
 		queuedBackups := lister.orderedQueued()
 		newQueuePos := 1
@@ -306,7 +311,7 @@ func (r *backupQueueReconciler) Reconcile(ctx context.Context, req ctrl.Request)
 				original := queuedBackup.DeepCopy()
 				queuedBackup.Status.QueuePosition = newQueuePos
 				if err := kube.PatchResource(original, &queuedBackup, r.Client); err != nil {
-					log.WithError(errors.Wrapf(err, "error updating Backup %s queuePosition to %v", queuedBackup.Name, newQueuePos))
+					log.WithError(err).Errorf("error updating Backup %s queuePosition to %v", queuedBackup.Name, newQueuePos)
 					return ctrl.Result{}, nil
 				}
 				newQueuePos++

pkg/controller/backup_queue_controller_test.go

@@ -17,6 +17,8 @@ limitations under the License.
 package controller
 
 import (
+	"context"
+	"errors"
 	"testing"
 
 	"github.com/sirupsen/logrus"
@@ -27,8 +29,10 @@ import (
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/types"
 	ctrl "sigs.k8s.io/controller-runtime"
+	ctrlClient "sigs.k8s.io/controller-runtime/pkg/client"
 
 	//"sigs.k8s.io/controller-runtime/pkg/client/fake"
+	"sigs.k8s.io/controller-runtime/pkg/client/interceptor"
 
 	velerov1api "github.com/vmware-tanzu/velero/pkg/apis/velero/v1"
 	"github.com/vmware-tanzu/velero/pkg/builder"
@@ -239,3 +243,81 @@ func TestBackupQueueReconciler(t *testing.T) {
 		})
 	}
 }
+
+// TestBackupQueueReconcilerTrackerNotLeakedWhenBackupCompletesDuringPatch verifies the fix for
+// https://github.com/velero-io/velero/issues/10519: if backupReconciler picks up the
+// ReadyToStart phase change (e.g. because the backup fails validation immediately) and calls
+// BackupTracker.Add/Delete before backupQueueReconciler reaches its own AddReadyToStart call,
+// the queue controller must not re-insert a tracker entry nobody will ever delete.
+func TestBackupQueueReconcilerTrackerNotLeakedWhenBackupCompletesDuringPatch(t *testing.T) {
+	scheme := runtime.NewScheme()
+	require.NoError(t, velerov1api.AddToScheme(scheme))
+
+	backup := builder.ForBackup(velerov1api.DefaultNamespace, "backup-11").Phase(velerov1api.BackupPhaseQueued).QueuePosition(1).Result()
+	backupTracker := NewBackupTracker()
+
+	fakeClient := velerotest.NewFakeControllerRuntimeClientBuilder(t).
+		WithRuntimeObjects(backup).
+		WithInterceptorFuncs(interceptor.Funcs{
+			Patch: func(ctx context.Context, c ctrlClient.WithWatch, obj ctrlClient.Object, patch ctrlClient.Patch, opts ...ctrlClient.PatchOption) error {
+				if err := c.Patch(ctx, obj, patch, opts...); err != nil {
+					return err
+				}
+				// Simulate backupReconciler racing ahead of this goroutine: it sees
+				// the ReadyToStart patch land, runs, and immediately completes the
+				// backup (e.g. FailedValidation), calling Add then its deferred
+				// Delete before backupQueueReconciler's next statement executes.
+				if b, ok := obj.(*velerov1api.Backup); ok && b.Status.Phase == velerov1api.BackupPhaseReadyToStart {
+					backupTracker.Add(b.Namespace, b.Name)
+					backupTracker.Delete(b.Namespace, b.Name)
+				}
+				return nil
+			},
+		}).
+		Build()
+
+	logger := logrus.New()
+	log := logger.WithField("controller", "backup-queue-test")
+	r := NewBackupQueueReconciler(fakeClient, scheme, log, 1, backupTracker)
+	req := ctrl.Request{NamespacedName: types.NamespacedName{Namespace: backup.Namespace, Name: backup.Name}}
+	_, err := r.Reconcile(t.Context(), req)
+	require.NoError(t, err)
+
+	assert.Equal(t, 0, backupTracker.RunningCount(),
+		"tracker entry must not be leaked when a racing reconcile completes the backup before AddReadyToStart runs")
+}
+
+// TestBackupQueueReconcilerTrackerRolledBackWhenPatchFails verifies that if the
+// ReadyToStart patch itself fails, the AddReadyToStart call made just before it is
+// rolled back via Delete, so a failed patch doesn't itself permanently consume a
+// concurrency slot.
+func TestBackupQueueReconcilerTrackerRolledBackWhenPatchFails(t *testing.T) {
+	scheme := runtime.NewScheme()
+	require.NoError(t, velerov1api.AddToScheme(scheme))
+
+	backup := builder.ForBackup(velerov1api.DefaultNamespace, "backup-11").Phase(velerov1api.BackupPhaseQueued).QueuePosition(1).Result()
+	backupTracker := NewBackupTracker()
+
+	patchErr := errors.New("simulated patch failure")
+	fakeClient := velerotest.NewFakeControllerRuntimeClientBuilder(t).
+		WithRuntimeObjects(backup).
+		WithInterceptorFuncs(interceptor.Funcs{
+			Patch: func(ctx context.Context, c ctrlClient.WithWatch, obj ctrlClient.Object, patch ctrlClient.Patch, opts ...ctrlClient.PatchOption) error {
+				if b, ok := obj.(*velerov1api.Backup); ok && b.Status.Phase == velerov1api.BackupPhaseReadyToStart {
+					return patchErr
+				}
+				return c.Patch(ctx, obj, patch, opts...)
+			},
+		}).
+		Build()
+
+	logger := logrus.New()
+	log := logger.WithField("controller", "backup-queue-test")
+	r := NewBackupQueueReconciler(fakeClient, scheme, log, 1, backupTracker)
+	req := ctrl.Request{NamespacedName: types.NamespacedName{Namespace: backup.Namespace, Name: backup.Name}}
+	_, err := r.Reconcile(t.Context(), req)
+	require.Error(t, err)
+
+	assert.Equal(t, 0, backupTracker.RunningCount(),
+		"tracker entry must be rolled back when the ReadyToStart patch fails")
+}