rbd: log sitestatuses and description

This commit logs sitestatues and description in
GetVolumeReplicationInfo RPC call for better
debuging.

Fixes: #4430

Signed-off-by: Yati Padia <ypadia@redhat.com>

internal/csi-addons/rbd/replication.go

@@ -718,7 +718,7 @@ func (rs *ReplicationServer) ResyncVolume(ctx context.Context,
 	}
 
 	if !ready {
-		err = checkVolumeResyncStatus(localStatus)
+		err = checkVolumeResyncStatus(ctx, localStatus)
 		if err != nil {
 			return nil, status.Error(codes.Internal, err.Error())
 		}
@@ -862,15 +862,15 @@ func (rs *ReplicationServer) GetVolumeReplicationInfo(ctx context.Context,
 		return nil, status.Error(codes.Internal, err.Error())
 	}
 
-	remoteStatus, err := RemoteStatus(mirrorStatus)
+	remoteStatus, err := RemoteStatus(ctx, mirrorStatus)
 	if err != nil {
 		log.ErrorLog(ctx, err.Error())
 
 		return nil, status.Errorf(codes.Internal, "failed to get remote status: %v", err)
 	}
 
 	description := remoteStatus.Description
-	resp, err := getLastSyncInfo(description)
+	resp, err := getLastSyncInfo(ctx, description)
 	if err != nil {
 		if errors.Is(err, corerbd.ErrLastSyncTimeNotFound) {
 			return nil, status.Errorf(codes.NotFound, "failed to get last sync info: %v", err)
@@ -886,18 +886,33 @@ func (rs *ReplicationServer) GetVolumeReplicationInfo(ctx context.Context,
 // RemoteStatus returns one SiteMirrorImageStatus item from the SiteStatuses
 // slice that corresponds to the remote site's status. If the remote status
 // is not found than the error ErrNotExist will be returned.
-func RemoteStatus(gmis *librbd.GlobalMirrorImageStatus) (librbd.SiteMirrorImageStatus, error) {
+func RemoteStatus(ctx context.Context, gmis *librbd.GlobalMirrorImageStatus) (librbd.SiteMirrorImageStatus, error) {
 	var (
 		ss  librbd.SiteMirrorImageStatus
 		err error = librbd.ErrNotExist
 	)
+	log.DebugLog(
+		ctx,
+		"Site Statuses: %s", gmis.SiteStatuses)
 	for i := range gmis.SiteStatuses {
 		if gmis.SiteStatuses[i].MirrorUUID != "" {
+			log.DebugLog(
+				ctx,
+				"Site Status of MirrorUUID %s: %s", gmis.SiteStatuses[i].MirrorUUID,
+				fmt.Sprintf("%s %s %v %t", gmis.SiteStatuses[i].State,
+					gmis.SiteStatuses[i].Description, gmis.SiteStatuses[i].LastUpdate,
+					gmis.SiteStatuses[i].Up))
 			ss = gmis.SiteStatuses[i]
 			err = nil
 
 			break
 		}
+		log.DebugLog(
+			ctx,
+			"Site Status: %s",
+			fmt.Sprintf("%s %s %v %t", gmis.SiteStatuses[i].State,
+				gmis.SiteStatuses[i].Description, gmis.SiteStatuses[i].LastUpdate,
+				gmis.SiteStatuses[i].Up))
 	}
 
 	return ss, err
@@ -906,7 +921,7 @@ func RemoteStatus(gmis *librbd.GlobalMirrorImageStatus) (librbd.SiteMirrorImageS
 // This function gets the local snapshot time, last sync snapshot seconds
 // and last sync bytes from the description of localStatus and convert
 // it into required types.
-func getLastSyncInfo(description string) (*replication.GetVolumeReplicationInfoResponse, error) {
+func getLastSyncInfo(ctx context.Context, description string) (*replication.GetVolumeReplicationInfoResponse, error) {
 	// Format of the description will be as followed:
 	// description = `replaying, {"bytes_per_second":0.0,"bytes_per_snapshot":81920.0,
 	// "last_snapshot_bytes":81920,"last_snapshot_sync_seconds":0,
@@ -924,6 +939,10 @@ func getLastSyncInfo(description string) (*replication.GetVolumeReplicationInfoR
 	if description == "" {
 		return nil, fmt.Errorf("empty description: %w", corerbd.ErrLastSyncTimeNotFound)
 	}
+	log.DebugLog(
+		ctx,
+		"description: %s",
+		description)
 	splittedString := strings.SplitN(description, ",", 2)
 	if len(splittedString) == 1 {
 		return nil, fmt.Errorf("no snapshot details: %w", corerbd.ErrLastSyncTimeNotFound)
@@ -968,13 +987,13 @@ func getLastSyncInfo(description string) (*replication.GetVolumeReplicationInfoR
 	return &response, nil
 }
 
-func checkVolumeResyncStatus(localStatus librbd.SiteMirrorImageStatus) error {
+func checkVolumeResyncStatus(ctx context.Context, localStatus librbd.SiteMirrorImageStatus) error {
 	// we are considering local snapshot timestamp to check if the resync is
 	// started or not, if we dont see local_snapshot_timestamp in the
 	// description of localStatus, we are returning error. if we see the local
 	// snapshot timestamp in the description we return resyncing started.
 	description := localStatus.Description
-	resp, err := getLastSyncInfo(description)
+	resp, err := getLastSyncInfo(ctx, description)
 	if err != nil {
 		return fmt.Errorf("failed to get last sync info: %w", err)
 	}

internal/csi-addons/rbd/replication_test.go

@@ -218,6 +218,7 @@ func TestGetSchedulingDetails(t *testing.T) {
 }
 
 func TestCheckVolumeResyncStatus(t *testing.T) {
+	ctx := context.TODO()
 	t.Parallel()
 	tests := []struct {
 		name    string
@@ -253,7 +254,7 @@ func TestCheckVolumeResyncStatus(t *testing.T) {
 		ts := tt
 		t.Run(ts.name, func(t *testing.T) {
 			t.Parallel()
-			if err := checkVolumeResyncStatus(ts.args); (err != nil) != ts.wantErr {
+			if err := checkVolumeResyncStatus(ctx, ts.args); (err != nil) != ts.wantErr {
 				t.Errorf("checkVolumeResyncStatus() error = %v, expect error = %v", err, ts.wantErr)
 			}
 		})
@@ -399,6 +400,7 @@ func TestCheckRemoteSiteStatus(t *testing.T) {
 
 func TestValidateLastSyncInfo(t *testing.T) {
 	t.Parallel()
+	ctx := context.TODO()
 	duration, err := time.ParseDuration(strconv.Itoa(int(56743)) + "s")
 	if err != nil {
 		t.Errorf("failed to parse duration)")
@@ -502,7 +504,7 @@ func TestValidateLastSyncInfo(t *testing.T) {
 		tt := tt
 		t.Run(tt.name, func(t *testing.T) {
 			t.Parallel()
-			teststruct, err := getLastSyncInfo(tt.description)
+			teststruct, err := getLastSyncInfo(ctx, tt.description)
 			if err != nil && !strings.Contains(err.Error(), tt.expectedErr) {
 				// returned error
 				t.Errorf("getLastSyncInfo() returned error, expected: %v, got: %v",