fix(postgres): fail a backup job as soon as its cnpg Backup fails

A failed cnpg.io/Backup kept its BackupJob Running for 30 minutes as a
"transient" failure, on the premise that CloudNativePG may move a
Backup out of the failed phase. It does not: its backup controller
returns early on any Backup already failed or completed, so the wait
only delayed the verdict and hid it behind a misleading reason.

A failed Backup now fails the BackupJob at once with the error CNPG
recorded, pointing to the plugin-barman-cloud sidecar log when that
error is only the plugin's exit status. A Backup in any other phase
keeps the BackupJob waiting as before, now with a WaitingForCNPGBackup
condition naming the Backup and its phase instead of no condition at
all. It is still not capped: CloudNativePG keeps a healthy Backup
pending while another backup of the same Cluster runs or while it
restarts one, and a fixed deadline would fail those.

Assisted-by: LLM
Signed-off-by: Alexey Artamonov <aleksei.artamonov@aenix.io>

internal/backupcontroller/cnpgstrategy_controller.go

@@ -175,13 +175,11 @@ const (
 	// against an unreachable target reproduces the same FATAL.
 	cnpgRecoveryMaxInspectPods = 5
 
-	// Cap on the wall-clock time a BackupJob can spend observing a
-	// cnpg.io/Backup stuck in phase=failed before the driver gives up and
-	// marks the BackupJob Failed. CNPG can transition out of "failed" on
-	// internal retries (e.g. transient instance-manager restart), so we
-	// don't fail on the first observation. But without this cap, a
-	// permanently-broken Backup would pin the BackupJob in Running forever,
-	// blocking later runs and wedging the Plan-controller queue.
+	// Cap on the wall-clock time a BackupJob waits for the barman-cloud
+	// plugin rollout before the cnpg.io/Backup exists. A Backup that exists
+	// is not capped: CloudNativePG keeps a healthy one pending while another
+	// backup of the same Cluster runs, or while it restarts one on another
+	// instance, so no fixed deadline tells those apart from a stuck one.
 	cnpgDefaultBackupDeadline = 30 * time.Minute
 
 	cnpgClusterHealthyPhase = "Cluster in healthy state"
@@ -453,44 +451,46 @@ func (r *BackupJobReconciler) reconcileCNPG(ctx context.Context, j *backupsv1alp
 		return ctrl.Result{}, nil
 
 	case cnpgBackupPhaseFailed:
-		// CNPG can transition the same Backup CR back out of "failed" when it
-		// retries internally (e.g., after a transient instance-manager
-		// restart), so we don't fail the BackupJob on the first observation.
-		// But without a cap a permanently-broken Backup would pin the
-		// BackupJob in Running forever; once StartedAt + cnpgDefaultBackupDeadline
-		// has elapsed and the cnpg.io/Backup is still failed, we give up.
-		if cnpgBackupDeadlineExceeded(j.Status.StartedAt) {
-			final := message
-			if final == "" {
-				final = fmt.Sprintf(
-					"cnpg.io Backup remained in phase=failed past %s deadline",
-					cnpgDefaultBackupDeadline)
-			}
-			return r.markBackupJobFailed(ctx, j, final)
-		}
-		if message == "" {
-			message = "cnpg.io Backup reported phase=failed; awaiting recovery or retry"
-		}
-		apimeta.SetStatusCondition(&j.Status.Conditions, metav1.Condition{
-			Type:    "Ready",
-			Status:  metav1.ConditionFalse,
-			Reason:  "CNPGBackupTransientFailure",
-			Message: message,
-		})
-		if err := r.Status().Update(ctx, j); err != nil {
-			return ctrl.Result{}, err
-		}
-		return ctrl.Result{RequeueAfter: cnpgPollInterval}, nil
+		// CloudNativePG does not reconcile a Backup out of a terminal phase,
+		// so waiting on a failed one cannot change the outcome.
+		return r.markBackupJobFailed(ctx, j, cnpgBackupFailedMessage(cnpgBackup, message))
 
 	default:
+		waiting := fmt.Sprintf("waiting for cnpg.io/Backup %s/%s, phase %q",
+			cnpgBackup.Namespace, cnpgBackup.Name, phase)
+		if apimeta.SetStatusCondition(&j.Status.Conditions, metav1.Condition{
+			Type:    "Ready",
+			Status:  metav1.ConditionFalse,
+			Reason:  "WaitingForCNPGBackup",
+			Message: waiting,
+		}) {
+			if err := r.Status().Update(ctx, j); err != nil {
+				return ctrl.Result{}, err
+			}
+		}
 		return ctrl.Result{RequeueAfter: cnpgPollInterval}, nil
 	}
 }
 
+// cnpgBackupFailedMessage carries the error CloudNativePG recorded. When the
+// plugin run itself failed that is only its exit status, and the storage
+// error behind it is logged by the plugin-barman-cloud sidecar.
+func cnpgBackupFailedMessage(b *cnpgtypes.Backup, errText string) string {
+	if errText == "" {
+		errText = "no error recorded"
+	}
+	message := fmt.Sprintf("cnpg.io/Backup %s/%s failed: %s", b.Namespace, b.Name, errText)
+	if strings.Contains(errText, "exit status") {
+		message += "; the cause is in the log of the plugin-barman-cloud sidecar of the instance that ran it"
+	}
+	return message
+}
+
 // cnpgBackupDeadlineExceeded reports whether enough wall-clock time has
-// elapsed since the BackupJob started that we should stop polling a stuck
-// cnpg.io/Backup and fail the run. Returns false when StartedAt is nil so
-// the very first reconcile (which sets StartedAt) does not trip the gate.
+// elapsed since the BackupJob started that we should stop waiting for the
+// barman-cloud plugin rollout and fail the run. Returns false when
+// StartedAt is nil so the very first reconcile (which sets StartedAt) does
+// not trip the gate.
 func cnpgBackupDeadlineExceeded(startedAt *metav1.Time) bool {
 	if startedAt == nil {
 		return false

internal/backupcontroller/cnpgstrategy_controller_test.go

@@ -2332,6 +2332,154 @@ func TestReconcileCNPG_StartedAtReturnsEarlyToAvoidStaleResourceVersion(t *testi
 	}
 }
 
+// CloudNativePG never reconciles a Backup out of a terminal phase (the
+// backup controller returns early on failed and completed), so a failed
+// Backup fails the BackupJob at once. Any other phase keeps the BackupJob
+// waiting past the backup deadline: CNPG keeps a healthy Backup pending
+// while another backup of the Cluster runs or while it restarts one.
+func TestReconcileCNPG_BackupPhaseOutcome(t *testing.T) {
+	apiGroup := backupsv1alpha1.DefaultApplicationAPIGroup
+	strategyGroup := strategyv1alpha1.GroupVersion.Group
+	const ns, appName = "tenant", "pg"
+	clusterName := cnpgClusterNameForApp(appName)
+	expired := time.Now().Add(-(cnpgDefaultBackupDeadline + time.Minute))
+
+	cases := []struct {
+		name         string
+		phase        string
+		errText      string
+		startedAt    time.Time
+		wantPhase    backupsv1alpha1.BackupJobPhase
+		wantMessage  []string
+		notInMessage []string
+	}{
+		{name: "failed fails at once", phase: cnpgBackupPhaseFailed, errText: "rpc error: code = Unknown desc = exit status 1", startedAt: time.Now(),
+			wantPhase: backupsv1alpha1.BackupJobPhaseFailed, wantMessage: []string{"bj-cnpg", "exit status 1", "plugin-barman-cloud"}},
+		{name: "failed without an error text fails at once", phase: cnpgBackupPhaseFailed, startedAt: time.Now(),
+			wantPhase: backupsv1alpha1.BackupJobPhaseFailed, wantMessage: []string{"bj-cnpg", "no error recorded"}, notInMessage: []string{"plugin-barman-cloud"}},
+		{name: "failed before the plugin ran points nowhere else", phase: cnpgBackupPhaseFailed, errText: "cannot backup a hibernated cluster", startedAt: time.Now(),
+			wantPhase: backupsv1alpha1.BackupJobPhaseFailed, wantMessage: []string{"bj-cnpg", "hibernated"}, notInMessage: []string{"plugin-barman-cloud"}},
+		{name: "pending keeps waiting", phase: "pending", startedAt: time.Now(),
+			wantPhase: backupsv1alpha1.BackupJobPhaseRunning, wantMessage: []string{"bj-cnpg", "pending"}},
+		{name: "pending is not capped by the backup deadline", phase: "pending", startedAt: expired,
+			wantPhase: backupsv1alpha1.BackupJobPhaseRunning, wantMessage: []string{"bj-cnpg", "pending"}},
+		{name: "no phase yet keeps waiting", phase: "", startedAt: expired,
+			wantPhase: backupsv1alpha1.BackupJobPhaseRunning, wantMessage: []string{"bj-cnpg"}},
+		{name: "started keeps running", phase: "started", startedAt: expired,
+			wantPhase: backupsv1alpha1.BackupJobPhaseRunning, wantMessage: []string{"bj-cnpg", "started"}},
+		{name: "walArchivingFailing keeps waiting", phase: "walArchivingFailing", startedAt: expired,
+			wantPhase: backupsv1alpha1.BackupJobPhaseRunning, wantMessage: []string{"bj-cnpg", "walArchivingFailing"}},
+		{name: "completed succeeds", phase: cnpgBackupPhaseComplete, startedAt: expired,
+			wantPhase: backupsv1alpha1.BackupJobPhaseSucceeded},
+	}
+	for _, tc := range cases {
+		t.Run(tc.name, func(t *testing.T) {
+			startedAt := metav1.NewTime(tc.startedAt)
+			job := &backupsv1alpha1.BackupJob{
+				ObjectMeta: metav1.ObjectMeta{Namespace: ns, Name: "bj"},
+				Spec: backupsv1alpha1.BackupJobSpec{
+					ApplicationRef: corev1.TypedLocalObjectReference{APIGroup: &apiGroup, Kind: postgresAppKind, Name: appName},
+				},
+				Status: backupsv1alpha1.BackupJobStatus{StartedAt: &startedAt},
+			}
+			strategy := &strategyv1alpha1.CNPG{
+				ObjectMeta: metav1.ObjectMeta{Name: "cnpg-strategy"},
+				Spec: strategyv1alpha1.CNPGSpec{
+					Template: strategyv1alpha1.CNPGTemplate{
+						BarmanObjectStore: strategyv1alpha1.BarmanObjectStoreTemplate{DestinationPath: "s3://bucket/"},
+					},
+				},
+			}
+			cluster := &cnpgtypes.Cluster{
+				ObjectMeta: metav1.ObjectMeta{Namespace: ns, Name: clusterName, UID: "cluster-uid"},
+			}
+			cnpgBackup := &cnpgtypes.Backup{
+				ObjectMeta: metav1.ObjectMeta{Namespace: ns, Name: "bj-cnpg", Labels: map[string]string{
+					backupsv1alpha1.OwningJobNameLabel:      job.Name,
+					backupsv1alpha1.OwningJobNamespaceLabel: job.Namespace,
+				}},
+				Spec:   cnpgtypes.BackupSpec{Cluster: cnpgtypes.ClusterReference{Name: clusterName}},
+				Status: cnpgtypes.BackupStatus{Phase: tc.phase, Error: tc.errText},
+			}
+			c := newCNPGStrategyTestClient(t, job, strategy, newPostgresApp(appName, ns), cluster, cnpgBackup)
+			r := &BackupJobReconciler{Client: c, Interface: cnpgDynamicFor(t, cluster)}
+			resolved := &ResolvedBackupConfig{
+				StrategyRef: corev1.TypedLocalObjectReference{APIGroup: &strategyGroup, Kind: strategyv1alpha1.CNPGStrategyKind, Name: strategy.Name},
+			}
+
+			j := &backupsv1alpha1.BackupJob{}
+			if err := c.Get(context.Background(), client.ObjectKeyFromObject(job), j); err != nil {
+				t.Fatalf("get BackupJob: %v", err)
+			}
+			res, err := r.reconcileCNPG(context.Background(), j, resolved)
+			if err != nil {
+				t.Fatalf("reconcileCNPG: %v", err)
+			}
+			if j.Status.Phase != tc.wantPhase {
+				t.Fatalf("BackupJob phase = %q (%s), want %q", j.Status.Phase, j.Status.Message, tc.wantPhase)
+			}
+
+			message := j.Status.Message
+			if tc.wantPhase == backupsv1alpha1.BackupJobPhaseRunning {
+				if res.RequeueAfter == 0 {
+					t.Errorf("expected a requeue while the cnpg.io/Backup is in progress, got %+v", res)
+				}
+				persisted := &backupsv1alpha1.BackupJob{}
+				if err := c.Get(context.Background(), client.ObjectKeyFromObject(job), persisted); err != nil {
+					t.Fatalf("get BackupJob after reconcile: %v", err)
+				}
+				ready := apimeta.FindStatusCondition(persisted.Status.Conditions, "Ready")
+				if ready == nil || ready.Status != metav1.ConditionFalse || ready.Reason != "WaitingForCNPGBackup" {
+					t.Fatalf("expected Ready=False/WaitingForCNPGBackup while waiting, got %+v", ready)
+				}
+				message = ready.Message
+
+				// A pass that observes the same phase again must not write the
+				// BackupJob status: the driver polls every few seconds.
+				statusWrites := 0
+				r.Client = interceptor.NewClient(c.(client.WithWatch), interceptor.Funcs{
+					SubResourceUpdate: func(ctx context.Context, cl client.Client, sub string, obj client.Object, opts ...client.SubResourceUpdateOption) error {
+						statusWrites++
+						return cl.SubResource(sub).Update(ctx, obj, opts...)
+					},
+					SubResourcePatch: func(ctx context.Context, cl client.Client, sub string, obj client.Object, patch client.Patch, opts ...client.SubResourcePatchOption) error {
+						statusWrites++
+						return cl.SubResource(sub).Patch(ctx, obj, patch, opts...)
+					},
+				})
+				if _, err := r.reconcileCNPG(context.Background(), persisted, resolved); err != nil {
+					t.Fatalf("second reconcileCNPG: %v", err)
+				}
+				if statusWrites != 0 {
+					t.Errorf("an unchanged phase wrote the BackupJob status %d time(s)", statusWrites)
+				}
+			}
+			for _, want := range tc.wantMessage {
+				if !strings.Contains(message, want) {
+					t.Errorf("message %q does not mention %q", message, want)
+				}
+			}
+			for _, unwanted := range tc.notInMessage {
+				if strings.Contains(message, unwanted) {
+					t.Errorf("message %q mentions %q", message, unwanted)
+				}
+			}
+
+			artifacts := &backupsv1alpha1.BackupList{}
+			if err := c.List(context.Background(), artifacts, client.InNamespace(ns)); err != nil {
+				t.Fatalf("list Backups: %v", err)
+			}
+			wantArtifacts := 0
+			if tc.wantPhase == backupsv1alpha1.BackupJobPhaseSucceeded {
+				wantArtifacts = 1
+			}
+			if len(artifacts.Items) != wantArtifacts {
+				t.Errorf("got %d Backup artifacts, want %d", len(artifacts.Items), wantArtifacts)
+			}
+		})
+	}
+}
+
 // cnpgRolloutFixture drives reconcileCNPG against one Postgres app whose
 // Cluster and instance pods a test swaps between passes, standing in for
 // CNPG rolling the instances.
@@ -2516,8 +2664,8 @@ func TestReconcileCNPG_WaitsForPluginRolloutBeforeBackup(t *testing.T) {
 	if !apimeta.IsStatusConditionTrue(j.Status.Conditions, backupCondPluginRolledOut) {
 		t.Errorf("%s condition = %+v, want True", backupCondPluginRolledOut, apimeta.FindStatusCondition(j.Status.Conditions, backupCondPluginRolledOut))
 	}
-	if cond := apimeta.FindStatusCondition(j.Status.Conditions, "Ready"); cond != nil {
-		t.Errorf("Ready condition = %+v left over from the wait while the backup runs", cond)
+	if cond := apimeta.FindStatusCondition(j.Status.Conditions, "Ready"); cond == nil || cond.Reason != "WaitingForCNPGBackup" {
+		t.Errorf("Ready condition = %+v, want the wait on the cnpg.io/Backup rather than one left over from the rollout", cond)
 	}
 }