rbd: improve logging for rpc calls

added logging of reqID for volume group rpc calls.
Also, added logs for replication rpc calls
which are helpful during debugging of issues related to
failover/relocate.

Signed-off-by: Nikhil-Ladha <nikhilladha1999@gmail.com>

internal/csi-addons/rbd/replication.go

@@ -306,6 +306,7 @@ func (rs *ReplicationServer) EnableVolumeReplication(ctx context.Context,
 
 		return nil, status.Error(codes.Internal, err.Error())
 	}
+	log.UsefulLog(ctx, "mirror state is %s", info.GetState())
 	if info.GetState() != librbd.MirrorImageEnabled.String() {
 		err = rbdVol.HandleParentImageExistence(ctx, flattenMode)
 		if err != nil {
@@ -371,6 +372,7 @@ func (rs *ReplicationServer) DisableVolumeReplication(ctx context.Context,
 
 		return nil, status.Error(codes.Internal, err.Error())
 	}
+	log.UsefulLog(ctx, "mirror state is %s", info.GetState())
 	switch info.GetState() {
 	// image is already in disabled state
 	case librbd.MirrorImageDisabled.String():
@@ -433,6 +435,7 @@ func (rs *ReplicationServer) PromoteVolume(ctx context.Context,
 
 		return nil, status.Error(codes.Internal, err.Error())
 	}
+	log.UsefulLog(ctx, "mirror state is %s, primary: %s", info.GetState(), info.IsPrimary())
 
 	if info.GetState() != librbd.MirrorImageEnabled.String() {
 		return nil, status.Errorf(
@@ -533,6 +536,7 @@ func (rs *ReplicationServer) DemoteVolume(ctx context.Context,
 
 		return nil, status.Error(codes.Internal, err.Error())
 	}
+	log.UsefulLog(ctx, "mirror state is %s, primary: %s", info.GetState(), info.IsPrimary())
 
 	if info.GetState() != librbd.MirrorImageEnabled.String() {
 		return nil, status.Errorf(

internal/csi-common/utils.go

@@ -29,6 +29,7 @@ import (
 
 	"github.com/container-storage-interface/spec/lib/go/csi"
 	"github.com/csi-addons/spec/lib/go/replication"
+	"github.com/csi-addons/spec/lib/go/volumegroup"
 	grpc_middleware "github.com/grpc-ecosystem/go-grpc-middleware"
 	"github.com/kubernetes-csi/csi-lib-utils/protosanitizer"
 	"google.golang.org/grpc"
@@ -222,18 +223,23 @@ func getReqID(req interface{}) string {
 		reqID = r.GetGroupSnapshotId()
 
 	// Replication
-	case *replication.EnableVolumeReplicationRequest:
+	case *replication.EnableVolumeReplicationRequest,
-		reqID = GetIDFromReplication(r)
+		*replication.DisableVolumeReplicationRequest,
-	case *replication.DisableVolumeReplicationRequest:
+		*replication.PromoteVolumeRequest,
-		reqID = GetIDFromReplication(r)
+		*replication.DemoteVolumeRequest,
-	case *replication.PromoteVolumeRequest:
+		*replication.ResyncVolumeRequest,
-		reqID = GetIDFromReplication(r)
+		*replication.GetVolumeReplicationInfoRequest:
-	case *replication.DemoteVolumeRequest:
-		reqID = GetIDFromReplication(r)
-	case *replication.ResyncVolumeRequest:
-		reqID = GetIDFromReplication(r)
-	case *replication.GetVolumeReplicationInfoRequest:
 		reqID = GetIDFromReplication(r)
+
+	// VolumeGroup
+	case *volumegroup.CreateVolumeGroupRequest:
+		reqID = r.GetName()
+	case *volumegroup.ModifyVolumeGroupMembershipRequest:
+		reqID = r.GetVolumeGroupId()
+	case *volumegroup.DeleteVolumeGroupRequest:
+		reqID = r.GetVolumeGroupId()
+	case *volumegroup.ControllerGetVolumeGroupRequest:
+		reqID = r.GetVolumeGroupId()
 	}
 
 	return reqID

internal/rbd/mirror.go

@@ -120,6 +120,8 @@ func (rm *rbdMirror) EnableMirroring(ctx context.Context, mode librbd.ImageMirro
 		return fmt.Errorf("failed to enable mirroring on %q with error: %w", rm, err)
 	}
 
+	log.DebugLog(ctx, "mirroring is enabled on the image %q", rm)
+
 	return nil
 }
 
@@ -141,6 +143,8 @@ func (rm *rbdMirror) DisableMirroring(ctx context.Context, force bool) error {
 		return fmt.Errorf("failed to disable mirroring on %q with error: %w", rm, err)
 	}
 
+	log.DebugLog(ctx, "mirroring is disabled on the image %q", rm)
+
 	return nil
 }
 
@@ -183,6 +187,8 @@ func (rm *rbdMirror) Promote(ctx context.Context, force bool) error {
 		return fmt.Errorf("failed to promote image %q with error: %w", rm, err)
 	}
 
+	log.DebugLog(ctx, "image %q has been promoted", rm)
+
 	return nil
 }
 
@@ -213,6 +219,8 @@ func (rm *rbdMirror) ForcePromote(ctx context.Context, cr *util.Credentials) err
 		return fmt.Errorf("failed to promote image %q with stderror: %s", rm, stderr)
 	}
 
+	log.DebugLog(ctx, "image %q has been force promoted", rm)
+
 	return nil
 }
 
@@ -234,6 +242,8 @@ func (rm *rbdMirror) Demote(ctx context.Context) error {
 		return fmt.Errorf("failed to demote image %q with error: %w", rm, err)
 	}
 
+	log.DebugLog(ctx, "image %q has been demoted", rm)
+
 	return nil
 }
 
@@ -259,6 +269,8 @@ func (rm *rbdMirror) Resync(ctx context.Context) error {
 		return fmt.Errorf("failed to resync image %q with error: %w", rm, err)
 	}
 
+	log.DebugLog(ctx, "issued resync on image %q", rm)
+
 	// delay until the state is syncing, or until 1+2+4+8+16 seconds passed
 	delay := 1 * time.Second
 	for {