Set DualModeLog for both backup prepare and run stages.

The Dual Mode logger(output log to both stdout and file)
was used only for the backup run stage. This makes the backup
preparation stage errors are not recorded for the backup.

Signed-off-by: Xun Jiang <blackpigletbruce@gmail.com>

changelogs/unreleased/7965-blackpiglet

@@ -0,0 +1 @@
+Set DualModeLog for both backup prepare and run stages.

pkg/controller/backup_controller.go

@@ -238,8 +238,21 @@ func (b *backupReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctr
 		return ctrl.Result{}, nil
 	}
 
+	// Log the backup to both a backup log file and to stdout. This will help see what happened if the upload of the
+	// backup log failed for whatever reason.
+	backupLog, err := logging.NewTempFileLogger(
+		b.backupLogLevel,
+		b.formatFlag,
+		logging.NewLogCountHook(),
+		logrus.Fields{Backup: kubeutil.NamespaceAndName(original)},
+	)
+	if err != nil {
+		return ctrl.Result{}, errors.Wrap(err, "error creating dual mode logger for backup")
+	}
+	defer backupLog.Dispose(b.logger.WithField(Backup, kubeutil.NamespaceAndName(original)))
+
 	log.Debug("Preparing backup request")
-	request := b.prepareBackupRequest(original, log)
+	request := b.prepareBackupRequest(original, backupLog)
 	if len(request.Status.ValidationErrors) > 0 {
 		request.Status.Phase = velerov1api.BackupPhaseFailedValidation
 	} else {
@@ -278,7 +291,7 @@ func (b *backupReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctr
 	b.metrics.RegisterBackupAttempt(backupScheduleName)
 
 	// execution & upload of backup
-	if err := b.runBackup(request); err != nil {
+	if err := b.runBackup(request, backupLog); err != nil {
 		// even though runBackup sets the backup's phase prior
 		// to uploading artifacts to object storage, we have to
 		// check for an error again here and update the phase if
@@ -464,7 +477,11 @@ func (b *backupReconciler) prepareBackupRequest(backup *velerov1api.Backup, logg
 	}
 
 	// validate the included/excluded namespaces
-	for _, err := range b.validateNamespaceIncludesExcludes(request.Spec.IncludedNamespaces, request.Spec.ExcludedNamespaces) {
+	for _, err := range b.validateNamespaceIncludesExcludes(
+		request.Spec.IncludedNamespaces,
+		request.Spec.ExcludedNamespaces,
+		logger,
+	) {
 		request.Status.ValidationErrors = append(request.Status.ValidationErrors, fmt.Sprintf("Invalid included/excluded namespace lists: %v", err))
 	}
 
@@ -596,7 +613,7 @@ func (b *backupReconciler) validateAndGetSnapshotLocations(backup *velerov1api.B
 	return providerLocations, nil
 }
 
-func (b *backupReconciler) validateNamespaceIncludesExcludes(includedNamespaces, excludedNamespaces []string) []error {
+func (b *backupReconciler) validateNamespaceIncludesExcludes(includedNamespaces, excludedNamespaces []string, logger logrus.FieldLogger) []error {
 	var errs []error
 	if errs = collections.ValidateNamespaceIncludesExcludes(includedNamespaces, excludedNamespaces); len(errs) > 0 {
 		return errs
@@ -608,7 +625,12 @@ func (b *backupReconciler) validateNamespaceIncludesExcludes(includedNamespaces,
 			continue
 		}
 		if err := b.kbClient.Get(context.Background(), kbclient.ObjectKey{Name: name}, namespace); err != nil {
-			errs = append(errs, err)
+			if apierrors.IsNotFound(err) {
+				logger.Errorf("fail to get namespace %s specified in the includedNamespaces %s",
+					name, strings.Join(includedNamespaces, ","))
+			} else {
+				errs = append(errs, err)
+			}
 		}
 	}
 	return errs
@@ -618,36 +640,28 @@ func (b *backupReconciler) validateNamespaceIncludesExcludes(includedNamespaces,
 // causes the backup to be Failed; if no error is returned, the backup's status's Errors
 // field is checked to see if the backup was a partial failure.
 
-func (b *backupReconciler) runBackup(backup *pkgbackup.Request) error {
-	b.logger.WithField(Backup, kubeutil.NamespaceAndName(backup)).Info("Setting up backup log")
-
-	// Log the backup to both a backup log file and to stdout. This will help see what happened if the upload of the
-	// backup log failed for whatever reason.
-	logCounter := logging.NewLogHook()
-	backupLog, err := logging.NewTempFileLogger(b.backupLogLevel, b.formatFlag, logCounter, logrus.Fields{Backup: kubeutil.NamespaceAndName(backup)})
-	if err != nil {
-		return errors.Wrap(err, "error creating dual mode logger for backup")
-	}
-	defer backupLog.Dispose(b.logger.WithField(Backup, kubeutil.NamespaceAndName(backup)))
-
-	backupLog.Info("Setting up backup temp file")
+func (b *backupReconciler) runBackup(
+	backup *pkgbackup.Request,
+	logger logging.DualModeLogger,
+) error {
+	logger.Info("Setting up backup temp file")
 	backupFile, err := os.CreateTemp("", "")
 	if err != nil {
 		return errors.Wrap(err, "error creating temp file for backup")
 	}
-	defer closeAndRemoveFile(backupFile, backupLog)
+	defer closeAndRemoveFile(backupFile, logger)
 
-	backupLog.Info("Setting up plugin manager")
-	pluginManager := b.newPluginManager(backupLog)
+	logger.Info("Setting up plugin manager")
+	pluginManager := b.newPluginManager(logger)
 	defer pluginManager.CleanupClients()
 
-	backupLog.Info("Getting backup item actions")
+	logger.Info("Getting backup item actions")
 	actions, err := pluginManager.GetBackupItemActionsV2()
 	if err != nil {
 		return err
 	}
-	backupLog.Info("Setting up backup store to check for backup existence")
-	backupStore, err := b.backupStoreGetter.Get(backup.StorageLocation, pluginManager, backupLog)
+	logger.Info("Setting up backup store to check for backup existence")
+	backupStore, err := b.backupStoreGetter.Get(backup.StorageLocation, pluginManager, logger)
 	if err != nil {
 		return err
 	}
@@ -665,7 +679,7 @@ func (b *backupReconciler) runBackup(backup *pkgbackup.Request) error {
 	backupItemActionsResolver := framework.NewBackupItemActionResolverV2(actions)
 
 	var fatalErrs []error
-	if err := b.backupper.BackupWithResolvers(backupLog, backup, backupFile, backupItemActionsResolver, pluginManager); err != nil {
+	if err := b.backupper.BackupWithResolvers(logger, backup, backupFile, backupItemActionsResolver, pluginManager); err != nil {
 		fatalErrs = append(fatalErrs, err)
 	}
 
@@ -677,7 +691,12 @@ func (b *backupReconciler) runBackup(backup *pkgbackup.Request) error {
 			backup.Status.VolumeSnapshotsCompleted++
 		}
 	}
-	volumeSnapshots, volumeSnapshotContents, volumeSnapshotClasses := pkgbackup.GetBackupCSIResources(b.kbClient, b.globalCRClient, backup.Backup, backupLog)
+	volumeSnapshots, volumeSnapshotContents, volumeSnapshotClasses := pkgbackup.GetBackupCSIResources(
+		b.kbClient,
+		b.globalCRClient,
+		backup.Backup,
+		logger,
+	)
 	// Update CSIVolumeSnapshotsAttempted
 	backup.Status.CSIVolumeSnapshotsAttempted = len(volumeSnapshots)
 
@@ -688,25 +707,25 @@ func (b *backupReconciler) runBackup(backup *pkgbackup.Request) error {
 	inProgressOperations, _, opsCompleted, opsFailed, errs := getBackupItemOperationProgress(backup.Backup, pluginManager, *backup.GetItemOperationsList())
 	if len(errs) > 0 {
 		for _, err := range errs {
-			backupLog.Error(err)
+			logger.Error(err)
 		}
 	}
 
 	backup.Status.BackupItemOperationsAttempted = len(*backup.GetItemOperationsList())
 	backup.Status.BackupItemOperationsCompleted = opsCompleted
 	backup.Status.BackupItemOperationsFailed = opsFailed
 
-	backup.Status.Warnings = logCounter.GetCount(logrus.WarnLevel)
-	backup.Status.Errors = logCounter.GetCount(logrus.ErrorLevel)
+	backup.Status.Warnings = logger.GetLogEntryCountByLevel(logrus.WarnLevel)
+	backup.Status.Errors = logger.GetLogEntryCountByLevel(logrus.ErrorLevel)
 
-	backupWarnings := logCounter.GetEntries(logrus.WarnLevel)
-	backupErrors := logCounter.GetEntries(logrus.ErrorLevel)
+	backupWarnings := logger.GetLogEntryByLevel(logrus.WarnLevel)
+	backupErrors := logger.GetLogEntryByLevel(logrus.ErrorLevel)
 	results := map[string]results.Result{
 		"warnings": backupWarnings,
 		"errors":   backupErrors,
 	}
 
-	backupLog.DoneForPersist(b.logger.WithField(Backup, kubeutil.NamespaceAndName(backup)))
+	logger.DoneForPersist(b.logger.WithField(Backup, kubeutil.NamespaceAndName(backup)))
 
 	// Assign finalize phase as close to end as possible so that any errors
 	// logged to backupLog are captured. This is done before uploading the
@@ -715,7 +734,7 @@ func (b *backupReconciler) runBackup(backup *pkgbackup.Request) error {
 	switch {
 	case len(fatalErrs) > 0:
 		backup.Status.Phase = velerov1api.BackupPhaseFailed
-	case logCounter.GetCount(logrus.ErrorLevel) > 0:
+	case logger.GetLogEntryCountByLevel(logrus.ErrorLevel) > 0:
 		if inProgressOperations {
 			backup.Status.Phase = velerov1api.BackupPhaseWaitingForPluginOperationsPartiallyFailed
 		} else {
@@ -735,25 +754,36 @@ func (b *backupReconciler) runBackup(backup *pkgbackup.Request) error {
 		backup.Status.Phase == velerov1api.BackupPhaseCompleted {
 		backup.Status.CompletionTimestamp = &metav1.Time{Time: b.clock.Now()}
 	}
-	recordBackupMetrics(backupLog, backup.Backup, backupFile, b.metrics, false)
+	recordBackupMetrics(logger, backup.Backup, backupFile, b.metrics, false)
 
 	// re-instantiate the backup store because credentials could have changed since the original
 	// instantiation, if this was a long-running backup
-	backupLog.Info("Setting up backup store to persist the backup")
-	backupStore, err = b.backupStoreGetter.Get(backup.StorageLocation, pluginManager, backupLog)
+	logger.Info("Setting up backup store to persist the backup")
+	backupStore, err = b.backupStoreGetter.Get(backup.StorageLocation, pluginManager, logger)
 	if err != nil {
 		return err
 	}
 
-	if logFile, err := backupLog.GetPersistFile(); err != nil {
+	if logFile, err := logger.GetPersistFile(); err != nil {
 		fatalErrs = append(fatalErrs, errors.Wrap(err, "error getting backup log file"))
 	} else {
-		if errs := persistBackup(backup, backupFile, logFile, backupStore, volumeSnapshots, volumeSnapshotContents, volumeSnapshotClasses, results, b.globalCRClient, backupLog); len(errs) > 0 {
+		if errs := persistBackup(
+			backup,
+			backupFile,
+			logFile,
+			backupStore,
+			volumeSnapshots,
+			volumeSnapshotContents,
+			volumeSnapshotClasses,
+			results,
+			b.globalCRClient,
+			logger,
+		); len(errs) > 0 {
 			fatalErrs = append(fatalErrs, errs...)
 		}
 	}
 
-	b.logger.WithField(Backup, kubeutil.NamespaceAndName(backup)).Infof("Initial backup processing complete, moving to %s", backup.Status.Phase)
+	logger.WithField(Backup, kubeutil.NamespaceAndName(backup)).Infof("Initial backup processing complete, moving to %s", backup.Status.Phase)
 
 	// if we return a non-nil error, the calling function will update
 	// the backup's phase to Failed.

pkg/controller/backup_controller_test.go

@@ -194,12 +194,6 @@ func TestProcessBackupValidationFailures(t *testing.T) {
 			backupLocation: defaultBackupLocation,
 			expectedErrs:   []string{"include-resources, exclude-resources and include-cluster-resources are old filter parameters.\ninclude-cluster-scoped-resources, exclude-cluster-scoped-resources, include-namespace-scoped-resources and exclude-namespace-scoped-resources are new filter parameters.\nThey cannot be used together"},
 		},
-		{
-			name:           "nonexisting namespace",
-			backup:         defaultBackup().IncludedNamespaces("non-existing").Result(),
-			backupLocation: defaultBackupLocation,
-			expectedErrs:   []string{"Invalid included/excluded namespace lists: namespaces \"non-existing\" not found"},
-		},
 	}
 
 	for _, test := range tests {
@@ -1575,6 +1569,7 @@ func TestValidateAndGetSnapshotLocations(t *testing.T) {
 }
 
 func TestValidateNamespaceIncludesExcludes(t *testing.T) {
+	logger := logging.DefaultLogger(logrus.DebugLevel, logging.FormatText)
 	namespace := builder.ForNamespace("default").Result()
 	reconciler := &backupReconciler{
 		kbClient: velerotest.NewFakeControllerRuntimeClient(t, namespace),
@@ -1583,31 +1578,32 @@ func TestValidateNamespaceIncludesExcludes(t *testing.T) {
 	// empty string as includedNamespaces
 	includedNamespaces := []string{""}
 	excludedNamespaces := []string{"test"}
-	errs := reconciler.validateNamespaceIncludesExcludes(includedNamespaces, excludedNamespaces)
+	errs := reconciler.validateNamespaceIncludesExcludes(includedNamespaces, excludedNamespaces, logger)
 	assert.Empty(t, errs)
 
 	// "*" as includedNamespaces
 	includedNamespaces = []string{"*"}
 	excludedNamespaces = []string{"test"}
-	errs = reconciler.validateNamespaceIncludesExcludes(includedNamespaces, excludedNamespaces)
+	errs = reconciler.validateNamespaceIncludesExcludes(includedNamespaces, excludedNamespaces, logger)
 	assert.Empty(t, errs)
 
 	// invalid namespaces
 	includedNamespaces = []string{"1@#"}
 	excludedNamespaces = []string{"2@#"}
-	errs = reconciler.validateNamespaceIncludesExcludes(includedNamespaces, excludedNamespaces)
+	errs = reconciler.validateNamespaceIncludesExcludes(includedNamespaces, excludedNamespaces, logger)
 	assert.Len(t, errs, 2)
 
 	// not exist namespaces
 	includedNamespaces = []string{"non-existing-namespace"}
 	excludedNamespaces = []string{}
-	errs = reconciler.validateNamespaceIncludesExcludes(includedNamespaces, excludedNamespaces)
-	assert.Len(t, errs, 1)
+	errs = reconciler.validateNamespaceIncludesExcludes(includedNamespaces, excludedNamespaces, logger)
+	// non-existing namespace error is recorded in the log instead of emit error
+	assert.Len(t, errs, 0)
 
 	// valid namespaces
 	includedNamespaces = []string{"default"}
 	excludedNamespaces = []string{}
-	errs = reconciler.validateNamespaceIncludesExcludes(includedNamespaces, excludedNamespaces)
+	errs = reconciler.validateNamespaceIncludesExcludes(includedNamespaces, excludedNamespaces, logger)
 	assert.Empty(t, errs)
 }
 

pkg/util/logging/dual_mode_logger.go

@@ -23,6 +23,8 @@ import (
 
 	"github.com/pkg/errors"
 	"github.com/sirupsen/logrus"
+
+	"github.com/vmware-tanzu/velero/pkg/util/results"
 )
 
 // DualModeLogger is a thread safe logger interface to write logs to dual targets, one of which
@@ -35,6 +37,10 @@ type DualModeLogger interface {
 	GetPersistFile() (*os.File, error)
 	// Dispose closes the temp file pointer and removes the file
 	Dispose(log logrus.FieldLogger)
+	// GetLogEntryByLevel get the log entries by log level collected by LogCountHook
+	GetLogEntryByLevel(level logrus.Level) results.Result
+	// GetLogEntryCountByLevel get the log count by log level collected by LogCountHook
+	GetLogEntryCountByLevel(level logrus.Level) int
 }
 
 type tempFileLogger struct {
@@ -45,7 +51,7 @@ type tempFileLogger struct {
 }
 
 // NewTempFileLogger creates a DualModeLogger instance that writes logs to both Stdout and a file in the temp folder.
-func NewTempFileLogger(logLevel logrus.Level, logFormat Format, hook *LogHook, fields logrus.Fields) (DualModeLogger, error) {
+func NewTempFileLogger(logLevel logrus.Level, logFormat Format, hook *LogCountHook, fields logrus.Fields) (DualModeLogger, error) {
 	file, err := os.CreateTemp("", "")
 	if err != nil {
 		return nil, errors.Wrap(err, "error creating temp file")
@@ -101,3 +107,29 @@ func closeAndRemoveFile(file *os.File, log logrus.FieldLogger) {
 		log.WithError(err).WithField("file", file.Name()).Warn("error removing temp log file")
 	}
 }
+
+func (p *tempFileLogger) GetLogEntryCountByLevel(level logrus.Level) int {
+	levelHooks := p.logger.Hooks[level]
+	for _, hook := range levelHooks {
+		logCountHook, ok := hook.(*LogCountHook)
+		if ok {
+			return logCountHook.GetCount(level)
+		}
+	}
+
+	return 0
+}
+
+func (p *tempFileLogger) GetLogEntryByLevel(level logrus.Level) results.Result {
+	var result results.Result
+
+	levelHooks := p.logger.Hooks[level]
+	for _, hook := range levelHooks {
+		logCountHook, ok := hook.(*LogCountHook)
+		if ok {
+			return logCountHook.GetEntries(level)
+		}
+	}
+
+	return result
+}