diff --git a/changelogs/unreleased/9481-Lyndon-Li b/changelogs/unreleased/9481-Lyndon-Li new file mode 100644 index 000000000..6cadfe64f --- /dev/null +++ b/changelogs/unreleased/9481-Lyndon-Li @@ -0,0 +1 @@ +Fix issue #9478, add diagnose info on expose peek fails \ No newline at end of file diff --git a/pkg/controller/data_download_controller.go b/pkg/controller/data_download_controller.go index 6ad64c956..a7c6112a8 100644 --- a/pkg/controller/data_download_controller.go +++ b/pkg/controller/data_download_controller.go @@ -292,8 +292,14 @@ func (r *DataDownloadReconciler) Reconcile(ctx context.Context, req ctrl.Request return ctrl.Result{}, nil } else if dd.Status.Phase == velerov2alpha1api.DataDownloadPhaseAccepted { if peekErr := r.restoreExposer.PeekExposed(ctx, getDataDownloadOwnerObject(dd)); peekErr != nil { - r.tryCancelDataDownload(ctx, dd, fmt.Sprintf("found a datadownload %s/%s with expose error: %s. mark it as cancel", dd.Namespace, dd.Name, peekErr)) log.Errorf("Cancel dd %s/%s because of expose error %s", dd.Namespace, dd.Name, peekErr) + + diags := strings.Split(r.restoreExposer.DiagnoseExpose(ctx, getDataDownloadOwnerObject(dd)), "\n") + for _, diag := range diags { + log.Warnf("[Diagnose DD expose]%s", diag) + } + + r.tryCancelDataDownload(ctx, dd, fmt.Sprintf("found a datadownload %s/%s with expose error: %s. mark it as cancel", dd.Namespace, dd.Name, peekErr)) } else if dd.Status.AcceptedTimestamp != nil { if time.Since(dd.Status.AcceptedTimestamp.Time) >= r.preparingTimeout { r.onPrepareTimeout(ctx, dd) diff --git a/pkg/controller/data_download_controller_test.go b/pkg/controller/data_download_controller_test.go index 7f11188ce..397f931c0 100644 --- a/pkg/controller/data_download_controller_test.go +++ b/pkg/controller/data_download_controller_test.go @@ -561,6 +561,7 @@ func TestDataDownloadReconcile(t *testing.T) { ep.On("GetExposed", mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(nil, nil) } else if test.isPeekExposeErr { ep.On("PeekExposed", mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(errors.New("fake-peek-error")) + ep.On("DiagnoseExpose", mock.Anything, mock.Anything).Return("") } if !test.notMockCleanUp { diff --git a/pkg/controller/data_upload_controller.go b/pkg/controller/data_upload_controller.go index 37dec0b6f..13be03994 100644 --- a/pkg/controller/data_upload_controller.go +++ b/pkg/controller/data_upload_controller.go @@ -298,8 +298,14 @@ func (r *DataUploadReconciler) Reconcile(ctx context.Context, req ctrl.Request) return ctrl.Result{}, nil } else if du.Status.Phase == velerov2alpha1api.DataUploadPhaseAccepted { if peekErr := ep.PeekExposed(ctx, getOwnerObject(du)); peekErr != nil { - r.tryCancelDataUpload(ctx, du, fmt.Sprintf("found a du %s/%s with expose error: %s. mark it as cancel", du.Namespace, du.Name, peekErr)) log.Errorf("Cancel du %s/%s because of expose error %s", du.Namespace, du.Name, peekErr) + + diags := strings.Split(ep.DiagnoseExpose(ctx, getOwnerObject(du)), "\n") + for _, diag := range diags { + log.Warnf("[Diagnose DU expose]%s", diag) + } + + r.tryCancelDataUpload(ctx, du, fmt.Sprintf("found a du %s/%s with expose error: %s. mark it as cancel", du.Namespace, du.Name, peekErr)) } else if du.Status.AcceptedTimestamp != nil { if time.Since(du.Status.AcceptedTimestamp.Time) >= r.preparingTimeout { r.onPrepareTimeout(ctx, du) diff --git a/pkg/controller/pod_volume_backup_controller.go b/pkg/controller/pod_volume_backup_controller.go index be8ff3f8e..0bcbfa6d2 100644 --- a/pkg/controller/pod_volume_backup_controller.go +++ b/pkg/controller/pod_volume_backup_controller.go @@ -260,6 +260,12 @@ func (r *PodVolumeBackupReconciler) Reconcile(ctx context.Context, req ctrl.Requ } else if pvb.Status.Phase == velerov1api.PodVolumeBackupPhaseAccepted { if peekErr := r.exposer.PeekExposed(ctx, getPVBOwnerObject(pvb)); peekErr != nil { log.Errorf("Cancel PVB %s/%s because of expose error %s", pvb.Namespace, pvb.Name, peekErr) + + diags := strings.Split(r.exposer.DiagnoseExpose(ctx, getPVBOwnerObject(pvb)), "\n") + for _, diag := range diags { + log.Warnf("[Diagnose PVB expose]%s", diag) + } + r.tryCancelPodVolumeBackup(ctx, pvb, fmt.Sprintf("found a PVB %s/%s with expose error: %s. mark it as cancel", pvb.Namespace, pvb.Name, peekErr)) } else if pvb.Status.AcceptedTimestamp != nil { if time.Since(pvb.Status.AcceptedTimestamp.Time) >= r.preparingTimeout { diff --git a/pkg/controller/pod_volume_restore_controller.go b/pkg/controller/pod_volume_restore_controller.go index 71b9d234e..068f1414a 100644 --- a/pkg/controller/pod_volume_restore_controller.go +++ b/pkg/controller/pod_volume_restore_controller.go @@ -274,6 +274,12 @@ func (r *PodVolumeRestoreReconciler) Reconcile(ctx context.Context, req ctrl.Req } else if pvr.Status.Phase == velerov1api.PodVolumeRestorePhaseAccepted { if peekErr := r.exposer.PeekExposed(ctx, getPVROwnerObject(pvr)); peekErr != nil { log.Errorf("Cancel PVR %s/%s because of expose error %s", pvr.Namespace, pvr.Name, peekErr) + + diags := strings.Split(r.exposer.DiagnoseExpose(ctx, getPVROwnerObject(pvr)), "\n") + for _, diag := range diags { + log.Warnf("[Diagnose PVR expose]%s", diag) + } + _ = r.tryCancelPodVolumeRestore(ctx, pvr, fmt.Sprintf("found a PVR %s/%s with expose error: %s. mark it as cancel", pvr.Namespace, pvr.Name, peekErr)) } else if pvr.Status.AcceptedTimestamp != nil { if time.Since(pvr.Status.AcceptedTimestamp.Time) >= r.preparingTimeout { diff --git a/pkg/controller/pod_volume_restore_controller_test.go b/pkg/controller/pod_volume_restore_controller_test.go index 525f8168b..9f2fe7a7f 100644 --- a/pkg/controller/pod_volume_restore_controller_test.go +++ b/pkg/controller/pod_volume_restore_controller_test.go @@ -1024,6 +1024,7 @@ func TestPodVolumeRestoreReconcile(t *testing.T) { ep.On("GetExposed", mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(nil, nil) } else if test.isPeekExposeErr { ep.On("PeekExposed", mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(errors.New("fake-peek-error")) + ep.On("DiagnoseExpose", mock.Anything, mock.Anything).Return("") } if !test.notMockCleanUp { diff --git a/pkg/exposer/csi_snapshot_test.go b/pkg/exposer/csi_snapshot_test.go index d419b6126..b4dd92c3f 100644 --- a/pkg/exposer/csi_snapshot_test.go +++ b/pkg/exposer/csi_snapshot_test.go @@ -1307,6 +1307,7 @@ func Test_csiSnapshotExposer_DiagnoseExpose(t *testing.T) { Message: "fake-pod-message", }, }, + Message: "fake-pod-message-1", }, } @@ -1501,7 +1502,7 @@ end diagnose CSI exposer`, &backupVSWithoutStatus, }, expected: `begin diagnose CSI exposer -Pod velero/fake-backup, phase Pending, node name +Pod velero/fake-backup, phase Pending, node name , message fake-pod-message-1 Pod condition Initialized, status True, reason , message fake-pod-message PVC velero/fake-backup, phase Pending, binding to VS velero/fake-backup, bind to , readyToUse false, errMessage @@ -1518,7 +1519,7 @@ end diagnose CSI exposer`, &backupVSWithoutVSC, }, expected: `begin diagnose CSI exposer -Pod velero/fake-backup, phase Pending, node name +Pod velero/fake-backup, phase Pending, node name , message fake-pod-message-1 Pod condition Initialized, status True, reason , message fake-pod-message PVC velero/fake-backup, phase Pending, binding to VS velero/fake-backup, bind to , readyToUse false, errMessage @@ -1535,7 +1536,7 @@ end diagnose CSI exposer`, &backupVSWithoutVSC, }, expected: `begin diagnose CSI exposer -Pod velero/fake-backup, phase Pending, node name fake-node +Pod velero/fake-backup, phase Pending, node name fake-node, message Pod condition Initialized, status True, reason , message fake-pod-message node-agent is not running in node fake-node, err: daemonset pod not found in running state in node fake-node PVC velero/fake-backup, phase Pending, binding to @@ -1554,7 +1555,7 @@ end diagnose CSI exposer`, &backupVSWithoutVSC, }, expected: `begin diagnose CSI exposer -Pod velero/fake-backup, phase Pending, node name fake-node +Pod velero/fake-backup, phase Pending, node name fake-node, message Pod condition Initialized, status True, reason , message fake-pod-message PVC velero/fake-backup, phase Pending, binding to VS velero/fake-backup, bind to , readyToUse false, errMessage @@ -1572,7 +1573,7 @@ end diagnose CSI exposer`, &backupVSWithoutVSC, }, expected: `begin diagnose CSI exposer -Pod velero/fake-backup, phase Pending, node name fake-node +Pod velero/fake-backup, phase Pending, node name fake-node, message Pod condition Initialized, status True, reason , message fake-pod-message PVC velero/fake-backup, phase Pending, binding to fake-pv error getting backup pv fake-pv, err: persistentvolumes "fake-pv" not found @@ -1592,7 +1593,7 @@ end diagnose CSI exposer`, &backupVSWithoutVSC, }, expected: `begin diagnose CSI exposer -Pod velero/fake-backup, phase Pending, node name fake-node +Pod velero/fake-backup, phase Pending, node name fake-node, message Pod condition Initialized, status True, reason , message fake-pod-message PVC velero/fake-backup, phase Pending, binding to fake-pv PV fake-pv, phase Pending, reason , message fake-pv-message @@ -1612,7 +1613,7 @@ end diagnose CSI exposer`, &backupVSWithVSC, }, expected: `begin diagnose CSI exposer -Pod velero/fake-backup, phase Pending, node name fake-node +Pod velero/fake-backup, phase Pending, node name fake-node, message Pod condition Initialized, status True, reason , message fake-pod-message PVC velero/fake-backup, phase Pending, binding to fake-pv PV fake-pv, phase Pending, reason , message fake-pv-message @@ -1634,7 +1635,7 @@ end diagnose CSI exposer`, &backupVSC, }, expected: `begin diagnose CSI exposer -Pod velero/fake-backup, phase Pending, node name fake-node +Pod velero/fake-backup, phase Pending, node name fake-node, message Pod condition Initialized, status True, reason , message fake-pod-message PVC velero/fake-backup, phase Pending, binding to fake-pv PV fake-pv, phase Pending, reason , message fake-pv-message @@ -1698,7 +1699,7 @@ end diagnose CSI exposer`, &backupVSC, }, expected: `begin diagnose CSI exposer -Pod velero/fake-backup, phase Pending, node name fake-node +Pod velero/fake-backup, phase Pending, node name fake-node, message Pod condition Initialized, status True, reason , message fake-pod-message Pod event reason reason-2, message message-2 Pod event reason reason-6, message message-6 diff --git a/pkg/exposer/generic_restore_test.go b/pkg/exposer/generic_restore_test.go index 9f32ce1d1..799719a50 100644 --- a/pkg/exposer/generic_restore_test.go +++ b/pkg/exposer/generic_restore_test.go @@ -664,6 +664,7 @@ func Test_ReastoreDiagnoseExpose(t *testing.T) { Message: "fake-pod-message", }, }, + Message: "fake-pod-message-1", }, } @@ -815,7 +816,7 @@ end diagnose restore exposer`, &restorePVCWithoutVolumeName, }, expected: `begin diagnose restore exposer -Pod velero/fake-restore, phase Pending, node name +Pod velero/fake-restore, phase Pending, node name , message fake-pod-message-1 Pod condition Initialized, status True, reason , message fake-pod-message PVC velero/fake-restore, phase Pending, binding to end diagnose restore exposer`, @@ -828,7 +829,7 @@ end diagnose restore exposer`, &restorePVCWithoutVolumeName, }, expected: `begin diagnose restore exposer -Pod velero/fake-restore, phase Pending, node name +Pod velero/fake-restore, phase Pending, node name , message fake-pod-message-1 Pod condition Initialized, status True, reason , message fake-pod-message PVC velero/fake-restore, phase Pending, binding to end diagnose restore exposer`, @@ -841,7 +842,7 @@ end diagnose restore exposer`, &restorePVCWithoutVolumeName, }, expected: `begin diagnose restore exposer -Pod velero/fake-restore, phase Pending, node name fake-node +Pod velero/fake-restore, phase Pending, node name fake-node, message Pod condition Initialized, status True, reason , message fake-pod-message node-agent is not running in node fake-node, err: daemonset pod not found in running state in node fake-node PVC velero/fake-restore, phase Pending, binding to @@ -856,7 +857,7 @@ end diagnose restore exposer`, &nodeAgentPod, }, expected: `begin diagnose restore exposer -Pod velero/fake-restore, phase Pending, node name fake-node +Pod velero/fake-restore, phase Pending, node name fake-node, message Pod condition Initialized, status True, reason , message fake-pod-message PVC velero/fake-restore, phase Pending, binding to end diagnose restore exposer`, @@ -870,7 +871,7 @@ end diagnose restore exposer`, &nodeAgentPod, }, expected: `begin diagnose restore exposer -Pod velero/fake-restore, phase Pending, node name fake-node +Pod velero/fake-restore, phase Pending, node name fake-node, message Pod condition Initialized, status True, reason , message fake-pod-message PVC velero/fake-restore, phase Pending, binding to fake-pv error getting restore pv fake-pv, err: persistentvolumes "fake-pv" not found @@ -886,7 +887,7 @@ end diagnose restore exposer`, &nodeAgentPod, }, expected: `begin diagnose restore exposer -Pod velero/fake-restore, phase Pending, node name fake-node +Pod velero/fake-restore, phase Pending, node name fake-node, message Pod condition Initialized, status True, reason , message fake-pod-message PVC velero/fake-restore, phase Pending, binding to fake-pv PV fake-pv, phase Pending, reason , message fake-pv-message @@ -902,7 +903,7 @@ end diagnose restore exposer`, &nodeAgentPod, }, expected: `begin diagnose restore exposer -Pod velero/fake-restore, phase Pending, node name fake-node +Pod velero/fake-restore, phase Pending, node name fake-node, message Pod condition Initialized, status True, reason , message fake-pod-message PVC velero/fake-restore, phase Pending, binding to fake-pv error getting restore pv fake-pv, err: persistentvolumes "fake-pv" not found @@ -922,7 +923,7 @@ end diagnose restore exposer`, &nodeAgentPod, }, expected: `begin diagnose restore exposer -Pod velero/fake-restore, phase Pending, node name fake-node +Pod velero/fake-restore, phase Pending, node name fake-node, message Pod condition Initialized, status True, reason , message fake-pod-message PVC velero/fake-restore, phase Pending, binding to fake-pv PV fake-pv, phase Pending, reason , message fake-pv-message @@ -975,7 +976,7 @@ end diagnose restore exposer`, }, }, expected: `begin diagnose restore exposer -Pod velero/fake-restore, phase Pending, node name fake-node +Pod velero/fake-restore, phase Pending, node name fake-node, message Pod condition Initialized, status True, reason , message fake-pod-message Pod event reason reason-2, message message-2 Pod event reason reason-5, message message-5 diff --git a/pkg/exposer/pod_volume_test.go b/pkg/exposer/pod_volume_test.go index ebf76efe9..d65030e22 100644 --- a/pkg/exposer/pod_volume_test.go +++ b/pkg/exposer/pod_volume_test.go @@ -592,6 +592,7 @@ func TestPodVolumeDiagnoseExpose(t *testing.T) { Message: "fake-pod-message", }, }, + Message: "fake-pod-message-1", }, } @@ -691,7 +692,7 @@ end diagnose pod volume exposer`, &backupPodWithoutNodeName, }, expected: `begin diagnose pod volume exposer -Pod velero/fake-backup, phase Pending, node name +Pod velero/fake-backup, phase Pending, node name , message fake-pod-message-1 Pod condition Initialized, status True, reason , message fake-pod-message end diagnose pod volume exposer`, }, @@ -702,7 +703,7 @@ end diagnose pod volume exposer`, &backupPodWithoutNodeName, }, expected: `begin diagnose pod volume exposer -Pod velero/fake-backup, phase Pending, node name +Pod velero/fake-backup, phase Pending, node name , message fake-pod-message-1 Pod condition Initialized, status True, reason , message fake-pod-message end diagnose pod volume exposer`, }, @@ -713,7 +714,7 @@ end diagnose pod volume exposer`, &backupPodWithNodeName, }, expected: `begin diagnose pod volume exposer -Pod velero/fake-backup, phase Pending, node name fake-node +Pod velero/fake-backup, phase Pending, node name fake-node, message Pod condition Initialized, status True, reason , message fake-pod-message node-agent is not running in node fake-node, err: daemonset pod not found in running state in node fake-node end diagnose pod volume exposer`, @@ -726,7 +727,7 @@ end diagnose pod volume exposer`, &nodeAgentPod, }, expected: `begin diagnose pod volume exposer -Pod velero/fake-backup, phase Pending, node name fake-node +Pod velero/fake-backup, phase Pending, node name fake-node, message Pod condition Initialized, status True, reason , message fake-pod-message end diagnose pod volume exposer`, }, @@ -739,7 +740,7 @@ end diagnose pod volume exposer`, &nodeAgentPod, }, expected: `begin diagnose pod volume exposer -Pod velero/fake-backup, phase Pending, node name fake-node +Pod velero/fake-backup, phase Pending, node name fake-node, message Pod condition Initialized, status True, reason , message fake-pod-message PVC velero/fake-backup-cache, phase Pending, binding to fake-pv-cache error getting cache pv fake-pv-cache, err: persistentvolumes "fake-pv-cache" not found @@ -755,7 +756,7 @@ end diagnose pod volume exposer`, &nodeAgentPod, }, expected: `begin diagnose pod volume exposer -Pod velero/fake-backup, phase Pending, node name fake-node +Pod velero/fake-backup, phase Pending, node name fake-node, message Pod condition Initialized, status True, reason , message fake-pod-message PVC velero/fake-backup-cache, phase Pending, binding to fake-pv-cache PV fake-pv-cache, phase Pending, reason , message fake-pv-message @@ -797,7 +798,7 @@ end diagnose pod volume exposer`, }, }, expected: `begin diagnose pod volume exposer -Pod velero/fake-backup, phase Pending, node name fake-node +Pod velero/fake-backup, phase Pending, node name fake-node, message Pod condition Initialized, status True, reason , message fake-pod-message Pod event reason reason-2, message message-2 Pod event reason reason-4, message message-4 diff --git a/pkg/util/kube/pod.go b/pkg/util/kube/pod.go index 86aa2e47b..2aeb45a1c 100644 --- a/pkg/util/kube/pod.go +++ b/pkg/util/kube/pod.go @@ -140,7 +140,13 @@ func EnsureDeletePod(ctx context.Context, podGetter corev1client.CoreV1Interface func IsPodUnrecoverable(pod *corev1api.Pod, log logrus.FieldLogger) (bool, string) { // Check the Phase field if pod.Status.Phase == corev1api.PodFailed || pod.Status.Phase == corev1api.PodUnknown { - message := GetPodTerminateMessage(pod) + message := "" + if pod.Status.Message != "" { + message += pod.Status.Message + "/" + } + + message += GetPodTerminateMessage(pod) + log.Warnf("Pod is in abnormal state %s, message [%s]", pod.Status.Phase, message) return true, fmt.Sprintf("Pod is in abnormal state [%s], message [%s]", pod.Status.Phase, message) } @@ -269,7 +275,7 @@ func ToSystemAffinity(loadAffinities []*LoadAffinity) *corev1api.Affinity { } func DiagnosePod(pod *corev1api.Pod, events *corev1api.EventList) string { - diag := fmt.Sprintf("Pod %s/%s, phase %s, node name %s\n", pod.Namespace, pod.Name, pod.Status.Phase, pod.Spec.NodeName) + diag := fmt.Sprintf("Pod %s/%s, phase %s, node name %s, message %s\n", pod.Namespace, pod.Name, pod.Status.Phase, pod.Spec.NodeName, pod.Status.Message) for _, condition := range pod.Status.Conditions { diag += fmt.Sprintf("Pod condition %s, status %s, reason %s, message %s\n", condition.Type, condition.Status, condition.Reason, condition.Message) diff --git a/pkg/util/kube/pod_test.go b/pkg/util/kube/pod_test.go index ba930019e..6751e8b6e 100644 --- a/pkg/util/kube/pod_test.go +++ b/pkg/util/kube/pod_test.go @@ -925,9 +925,10 @@ func TestDiagnosePod(t *testing.T) { Message: "fake-message-2", }, }, + Message: "fake-message-3", }, }, - expected: "Pod fake-ns/fake-pod, phase Pending, node name fake-node\nPod condition Initialized, status True, reason fake-reason-1, message fake-message-1\nPod condition PodScheduled, status False, reason fake-reason-2, message fake-message-2\n", + expected: "Pod fake-ns/fake-pod, phase Pending, node name fake-node, message fake-message-3\nPod condition Initialized, status True, reason fake-reason-1, message fake-message-1\nPod condition PodScheduled, status False, reason fake-reason-2, message fake-message-2\n", }, { name: "pod with all info and empty event list", @@ -955,10 +956,11 @@ func TestDiagnosePod(t *testing.T) { Message: "fake-message-2", }, }, + Message: "fake-message-3", }, }, events: &corev1api.EventList{}, - expected: "Pod fake-ns/fake-pod, phase Pending, node name fake-node\nPod condition Initialized, status True, reason fake-reason-1, message fake-message-1\nPod condition PodScheduled, status False, reason fake-reason-2, message fake-message-2\n", + expected: "Pod fake-ns/fake-pod, phase Pending, node name fake-node, message fake-message-3\nPod condition Initialized, status True, reason fake-reason-1, message fake-message-1\nPod condition PodScheduled, status False, reason fake-reason-2, message fake-message-2\n", }, { name: "pod with all info and events", @@ -987,6 +989,7 @@ func TestDiagnosePod(t *testing.T) { Message: "fake-message-2", }, }, + Message: "fake-message-3", }, }, events: &corev1api.EventList{Items: []corev1api.Event{ @@ -1027,7 +1030,7 @@ func TestDiagnosePod(t *testing.T) { Message: "message-6", }, }}, - expected: "Pod fake-ns/fake-pod, phase Pending, node name fake-node\nPod condition Initialized, status True, reason fake-reason-1, message fake-message-1\nPod condition PodScheduled, status False, reason fake-reason-2, message fake-message-2\nPod event reason reason-3, message message-3\nPod event reason reason-6, message message-6\n", + expected: "Pod fake-ns/fake-pod, phase Pending, node name fake-node, message fake-message-3\nPod condition Initialized, status True, reason fake-reason-1, message fake-message-1\nPod condition PodScheduled, status False, reason fake-reason-2, message fake-message-2\nPod event reason reason-3, message message-3\nPod event reason reason-6, message message-6\n", }, }