From 4b3bd78e5d911aabb7c616f9a7aaaf03a2c39718 Mon Sep 17 00:00:00 2001 From: Yati Padia Date: Tue, 13 Feb 2024 13:59:33 +0530 Subject: [PATCH] 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 --- internal/csi-addons/rbd/replication.go | 21 ++++++++++++++------- internal/csi-addons/rbd/replication_test.go | 6 ++++-- 2 files changed, 18 insertions(+), 9 deletions(-) diff --git a/internal/csi-addons/rbd/replication.go b/internal/csi-addons/rbd/replication.go index a5c400de32fc..3272369fdff3 100644 --- a/internal/csi-addons/rbd/replication.go +++ b/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,7 +862,7 @@ 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()) @@ -870,7 +870,7 @@ func (rs *ReplicationServer) GetVolumeReplicationInfo(ctx context.Context, } 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,11 +886,14 @@ 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 != "" { ss = gmis.SiteStatuses[i] @@ -906,7 +909,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 +927,10 @@ func getLastSyncInfo(description string) (*replication.GetVolumeReplicationInfoR if description == "" { return nil, fmt.Errorf("empty description: %w", corerbd.ErrLastSyncTimeNotFound) } + log.DebugLog( + ctx, + "description=%q", + description) splittedString := strings.SplitN(description, ",", 2) if len(splittedString) == 1 { return nil, fmt.Errorf("no snapshot details: %w", corerbd.ErrLastSyncTimeNotFound) @@ -968,13 +975,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) } diff --git a/internal/csi-addons/rbd/replication_test.go b/internal/csi-addons/rbd/replication_test.go index 4b74112a5475..433c5395627b 100644 --- a/internal/csi-addons/rbd/replication_test.go +++ b/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",