K8SPSMD-1015: Log backup operations (#1505)

* Enhance backup logging.

* Update pkg/apis/psmdb/v1/psmdb_types.go

Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com>

* Fix

* Improve logs.

---------

Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com>
Co-authored-by: Viacheslav Sarzhan <slava.sarzhan@percona.com>

Author: 3 people

pkg/apis/psmdb/v1/psmdb_types.go

@@ -1,6 +1,7 @@
 package v1
 
 import (
+	"context"
 	"fmt"
 	"os"
 	"strconv"
@@ -20,6 +21,7 @@ import (
 	"k8s.io/apimachinery/pkg/util/sets"
 	k8sversion "k8s.io/apimachinery/pkg/version"
 	"sigs.k8s.io/controller-runtime/pkg/client/apiutil"
+	logf "sigs.k8s.io/controller-runtime/pkg/log"
 
 	"github.com/percona/percona-backup-mongodb/pbm/compress"
 	"github.com/percona/percona-backup-mongodb/pbm/defs"
@@ -968,7 +970,9 @@ func (cr *PerconaServerMongoDB) MongosNamespacedName() types.NamespacedName {
 	return types.NamespacedName{Name: cr.Name + "-" + "mongos", Namespace: cr.Namespace}
 }
 
-func (cr *PerconaServerMongoDB) CanBackup() error {
+func (cr *PerconaServerMongoDB) CanBackup(ctx context.Context) error {
+	logf.FromContext(ctx).V(1).Info("checking if backup is allowed", "backup", cr.Name)
+
 	if cr.Spec.Unmanaged {
 		return errors.Errorf("backups are not allowed on unmanaged clusters")
 	}

pkg/controller/perconaservermongodbbackup/backup.go

@@ -43,6 +43,9 @@ func (r *ReconcilePerconaServerMongoDBBackup) newBackup(ctx context.Context, clu
 
 // Start requests backup on PBM
 func (b *Backup) Start(ctx context.Context, k8sclient client.Client, cluster *api.PerconaServerMongoDB, cr *api.PerconaServerMongoDBBackup) (api.PerconaServerMongoDBBackupStatus, error) {
+	log := logf.FromContext(ctx)
+	log.Info("Starting backup", "backup", cr.Name, "storage", cr.Spec.StorageName)
+
 	var status api.PerconaServerMongoDBBackupStatus
 
 	stg, ok := b.spec.Storages[cr.Spec.StorageName]
@@ -63,15 +66,17 @@ func (b *Backup) Start(ctx context.Context, k8sclient client.Client, cluster *ap
 		compLevel = &l
 	}
 
-	err = b.pbm.SendCmd(ctx, ctrl.Cmd{
+	cmd := ctrl.Cmd{
 		Cmd: ctrl.CmdBackup,
 		Backup: &ctrl.BackupCmd{
 			Name:             name,
 			Type:             cr.Spec.Type,
 			Compression:      cr.Spec.Compression,
 			CompressionLevel: compLevel,
 		},
-	})
+	}
+	log.Info("Sending backup command", "backupCmd", cmd)
+	err = b.pbm.SendCmd(ctx, cmd)
 	if err != nil {
 		return status, err
 	}

pkg/controller/perconaservermongodbbackup/perconaservermongodbbackup_controller.go

@@ -211,7 +211,7 @@ func (r *ReconcilePerconaServerMongoDBBackup) reconcile(
 		return status, errors.New("cluster not found")
 	}
 
-	if err := cluster.CanBackup(); err != nil {
+	if err := cluster.CanBackup(ctx); err != nil {
 		return status, errors.Wrap(err, "failed to run backup")
 	}
 

pkg/controller/perconaservermongodbrestore/logical.go

@@ -160,6 +160,9 @@ func reEnablePITR(ctx context.Context, pbm backup.PBM, backup psmdbv1.BackupSpec
 }
 
 func runRestore(ctx context.Context, backup string, pbmc backup.PBM, pitr *psmdbv1.PITRestoreSpec) (string, error) {
+	log := logf.FromContext(ctx)
+	log.Info("Starting logical restore", "backup", backup)
+
 	e := pbmc.Logger().NewEvent(string(ctrl.CmdResync), "", "", primitive.Timestamp{})
 	err := pbmc.ResyncStorage(ctx, e)
 	if err != nil {
@@ -211,6 +214,7 @@ func runRestore(ctx context.Context, backup string, pbmc backup.PBM, pitr *psmdb
 		}
 	}
 
+	log.Info("Sending restore command", "restoreCmd", cmd.Restore)
 	if err = pbmc.SendCmd(ctx, cmd); err != nil {
 		return "", errors.Wrap(err, "send restore cmd")
 	}

pkg/psmdb/backup/backup.go

@@ -47,6 +47,7 @@ func NewRestoreJob(cr *api.PerconaServerMongoDBRestore) Job {
 // in given cluster and namespace
 func HasActiveJobs(ctx context.Context, newPBMFunc NewPBMFunc, cl client.Client, cluster *api.PerconaServerMongoDB, current Job, allowLock ...LockHeaderPredicate) (bool, error) {
 	l := log.FromContext(ctx)
+	l.V(1).Info("Checking for active jobs", "currentJob", current)
 
 	bcps := &api.PerconaServerMongoDBBackupList{}
 	err := cl.List(ctx,

pkg/psmdb/backup/pbm.go

@@ -16,6 +16,7 @@ import (
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/types"
 	client "sigs.k8s.io/controller-runtime/pkg/client"
+	logf "sigs.k8s.io/controller-runtime/pkg/log"
 
 	"github.com/percona/percona-backup-mongodb/pbm/backup"
 	"github.com/percona/percona-backup-mongodb/pbm/config"
@@ -320,6 +321,9 @@ func (b *pbmC) Conn() *mongo.Client {
 // SetConfig sets the pbm config with storage defined in the cluster CR
 // by given storageName
 func (b *pbmC) SetConfig(ctx context.Context, k8sclient client.Client, cluster *api.PerconaServerMongoDB, stg api.BackupStorageSpec) error {
+	log := logf.FromContext(ctx)
+	log.Info("Setting PBM config", "backup", cluster.Name)
+
 	conf, err := GetPBMConfig(ctx, k8sclient, cluster, stg)
 	if err != nil {
 		return errors.Wrap(err, "get PBM config")