diff --git a/internal/hook/item_hook_handler.go b/internal/hook/item_hook_handler.go index 38c982c550..6d0d9e894d 100644 --- a/internal/hook/item_hook_handler.go +++ b/internal/hook/item_hook_handler.go @@ -48,6 +48,8 @@ type hookPhase string const ( PhasePre hookPhase = "pre" PhasePost hookPhase = "post" + // HookErrLogPrefix is prepended to each error message logged from a hook, which helps distinguish hook error logs from other logs. + HookErrLogPrefix string = "hook error:" ) const ( @@ -229,6 +231,7 @@ func (h *DefaultItemHookHandler) HandleHooks( }, ) if err := h.PodCommandExecutor.ExecutePodCommand(hookLog, obj.UnstructuredContent(), namespace, name, "", hookFromAnnotations); err != nil { + err = fmt.Errorf("%s %v", HookErrLogPrefix, err.Error()) hookLog.WithError(err).Error("Error executing hook") if hookFromAnnotations.OnError == velerov1api.HookErrorModeFail { return err @@ -263,6 +266,7 @@ func (h *DefaultItemHookHandler) HandleHooks( ) err := h.PodCommandExecutor.ExecutePodCommand(hookLog, obj.UnstructuredContent(), namespace, name, resourceHook.Name, hook.Exec) if err != nil { + err = fmt.Errorf("%s %v", HookErrLogPrefix, err.Error()) hookLog.WithError(err).Error("Error executing hook") if hook.Exec.OnError == velerov1api.HookErrorModeFail { return err diff --git a/pkg/cmd/util/output/backup_describer.go b/pkg/cmd/util/output/backup_describer.go index 039f9d6531..de0b2b81a7 100644 --- a/pkg/cmd/util/output/backup_describer.go +++ b/pkg/cmd/util/output/backup_describer.go @@ -97,11 +97,14 @@ func DescribeBackup( } } + resultMap, resultErr := downloadResult(ctx, kbClient, backup.Namespace, backup.Name, velerov1api.DownloadTargetKindBackupResults, downloadRequestTimeout, insecureSkipTLSVerify, caCertFile) + hookFailed := hookFailed(resultMap, resultErr) + d.Println() - DescribeBackupResults(ctx, kbClient, d, backup, insecureSkipTLSVerify, caCertFile) + DescribeBackupResults(ctx, kbClient, d, backup, resultMap, resultErr) d.Println() - DescribeBackupSpec(d, backup.Spec) + DescribeBackupSpec(d, backup.Spec, hookFailed) d.Println() DescribeBackupStatus(ctx, kbClient, d, backup, details, insecureSkipTLSVerify, caCertFile) @@ -131,7 +134,7 @@ func DescribeResourcePolicies(d *Describer, resPolicies *v1.TypedLocalObjectRefe } // DescribeBackupSpec describes a backup spec in human-readable format. -func DescribeBackupSpec(d *Describer, spec velerov1api.BackupSpec) { +func DescribeBackupSpec(d *Describer, spec velerov1api.BackupSpec, hookFailed string) { // TODO make a helper for this and use it in all the describers. d.Printf("Namespaces:\n") var s string @@ -232,6 +235,8 @@ func DescribeBackupSpec(d *Describer, spec velerov1api.BackupSpec) { d.Printf("ItemOperationTimeout:\t%s\n", spec.ItemOperationTimeout.Duration) d.Println() + d.Printf("Hook Failed:\t%s\n", hookFailed) + if len(spec.Hooks.Resources) == 0 { d.Printf("Hooks:\t" + emptyDisplay + "\n") } else { @@ -694,28 +699,17 @@ func DescribeVSC(d *Describer, details bool, vsc snapshotv1api.VolumeSnapshotCon } // DescribeBackupResults describes errors and warnings in human-readable format. -func DescribeBackupResults(ctx context.Context, kbClient kbclient.Client, d *Describer, backup *velerov1api.Backup, insecureSkipTLSVerify bool, caCertPath string) { +func DescribeBackupResults(ctx context.Context, kbClient kbclient.Client, d *Describer, backup *velerov1api.Backup, resultMap map[string]results.Result, resultErr error) { if backup.Status.Warnings == 0 && backup.Status.Errors == 0 { return } - var buf bytes.Buffer - var resultMap map[string]results.Result - - // If err 'ErrNotFound' occurs, it means the backup bundle in the bucket has already been there before the backup-result file is introduced. - // We only display the count of errors and warnings in this case. - err := downloadrequest.Stream(ctx, kbClient, backup.Namespace, backup.Name, velerov1api.DownloadTargetKindBackupResults, &buf, downloadRequestTimeout, insecureSkipTLSVerify, caCertPath) - if err == downloadrequest.ErrNotFound { + if resultErr == downloadrequest.ErrNotFound { d.Printf("Errors:\t%d\n", backup.Status.Errors) d.Printf("Warnings:\t%d\n", backup.Status.Warnings) return - } else if err != nil { - d.Printf("Warnings:\t\n\nErrors:\t\n", err, err) - return - } - - if err := json.NewDecoder(&buf).Decode(&resultMap); err != nil { - d.Printf("Warnings:\t\n\nErrors:\t\n", err, err) + } else if resultErr != nil { + d.Printf("Warnings:\t\n\nErrors:\t\n", resultErr, resultErr) return } diff --git a/pkg/cmd/util/output/backup_describer_test.go b/pkg/cmd/util/output/backup_describer_test.go index b0f78a917e..790c9bddb9 100644 --- a/pkg/cmd/util/output/backup_describer_test.go +++ b/pkg/cmd/util/output/backup_describer_test.go @@ -104,6 +104,7 @@ TTL: 72h0m0s CSISnapshotTimeout: 10m0s ItemOperationTimeout: 0s +Hook Failed: False Hooks: Resources: hook-1: @@ -168,7 +169,8 @@ TTL: 72h0m0s CSISnapshotTimeout: 10m0s ItemOperationTimeout: 0s -Hooks: +Hook Failed: False +Hooks: ` input3 := builder.ForBackup("test-ns", "test-backup-3"). @@ -225,6 +227,7 @@ TTL: 0s CSISnapshotTimeout: 0s ItemOperationTimeout: 0s +Hook Failed: False Hooks: Resources: hook-1: @@ -284,7 +287,7 @@ OrderedResources: buf: &bytes.Buffer{}, } d.out.Init(d.buf, 0, 8, 2, ' ', 0) - DescribeBackupSpec(d, tc.input) + DescribeBackupSpec(d, tc.input, hookFailedFalse) d.out.Flush() assert.Equal(tt, tc.expect, d.buf.String()) }) diff --git a/pkg/cmd/util/output/backup_structured_describer.go b/pkg/cmd/util/output/backup_structured_describer.go index 4a69fc057c..8a90b159f3 100644 --- a/pkg/cmd/util/output/backup_structured_describer.go +++ b/pkg/cmd/util/output/backup_structured_describer.go @@ -64,9 +64,12 @@ func DescribeBackupInSF( d.Describe("validationErrors", status.ValidationErrors) } - DescribeBackupResultsInSF(ctx, kbClient, d, backup, insecureSkipTLSVerify, caCertFile) + resultMap, resultErr := downloadResult(ctx, kbClient, backup.Namespace, backup.Name, velerov1api.DownloadTargetKindBackupResults, downloadRequestTimeout, insecureSkipTLSVerify, caCertFile) + hookFailed := hookFailed(resultMap, resultErr) - DescribeBackupSpecInSF(d, backup.Spec) + DescribeBackupResultsInSF(ctx, kbClient, d, backup, resultMap, resultErr) + + DescribeBackupSpecInSF(d, backup.Spec, hookFailed) DescribeBackupStatusInSF(ctx, kbClient, d, backup, details, insecureSkipTLSVerify, caCertFile) @@ -85,7 +88,7 @@ func DescribeBackupInSF( } // DescribeBackupSpecInSF describes a backup spec in structured format. -func DescribeBackupSpecInSF(d *StructuredDescriber, spec velerov1api.BackupSpec) { +func DescribeBackupSpecInSF(d *StructuredDescriber, spec velerov1api.BackupSpec, hookFailed string) { backupSpecInfo := make(map[string]interface{}) var s string @@ -152,6 +155,7 @@ func DescribeBackupSpecInSF(d *StructuredDescriber, spec velerov1api.BackupSpec) backupSpecInfo["CSISnapshotTimeout"] = spec.CSISnapshotTimeout.Duration.String() // describe hooks + backupSpecInfo["hookFailed"] = hookFailed hooksInfo := make(map[string]interface{}) hooksResources := make(map[string]interface{}) for _, backupResourceHookSpec := range spec.Hooks.Resources { @@ -468,36 +472,24 @@ func DescribeVSCInSF(details bool, vsc snapshotv1api.VolumeSnapshotContent, vscD } // DescribeBackupResultsInSF describes errors and warnings in structured format. -func DescribeBackupResultsInSF(ctx context.Context, kbClient kbclient.Client, d *StructuredDescriber, backup *velerov1api.Backup, insecureSkipTLSVerify bool, caCertPath string) { +func DescribeBackupResultsInSF(ctx context.Context, kbClient kbclient.Client, d *StructuredDescriber, backup *velerov1api.Backup, resultMap map[string]results.Result, resultErr error) { if backup.Status.Warnings == 0 && backup.Status.Errors == 0 { return } - var buf bytes.Buffer - var resultMap map[string]results.Result - errors, warnings := make(map[string]interface{}), make(map[string]interface{}) defer func() { d.Describe("errors", errors) d.Describe("warnings", warnings) }() - // If 'ErrNotFound' occurs, it means the backup bundle in the bucket has already been there before the backup-result file is introduced. - // We only display the count of errors and warnings in this case. - err := downloadrequest.Stream(ctx, kbClient, backup.Namespace, backup.Name, velerov1api.DownloadTargetKindBackupResults, &buf, downloadRequestTimeout, insecureSkipTLSVerify, caCertPath) - if err == downloadrequest.ErrNotFound { + if resultErr == downloadrequest.ErrNotFound { errors["count"] = backup.Status.Errors warnings["count"] = backup.Status.Warnings return - } else if err != nil { - errors["errorGettingErrors"] = fmt.Errorf("", err) - warnings["errorGettingWarnings"] = fmt.Errorf("", err) - return - } - - if err := json.NewDecoder(&buf).Decode(&resultMap); err != nil { - errors["errorGettingErrors"] = fmt.Errorf("", err) - warnings["errorGettingWarnings"] = fmt.Errorf("", err) + } else if resultErr != nil { + errors["errorGettingErrors"] = fmt.Errorf("", resultErr) + warnings["errorGettingWarnings"] = fmt.Errorf("", resultErr) return } diff --git a/pkg/cmd/util/output/backup_structured_describer_test.go b/pkg/cmd/util/output/backup_structured_describer_test.go index 2a0247bf74..d8af176141 100644 --- a/pkg/cmd/util/output/backup_structured_describer_test.go +++ b/pkg/cmd/util/output/backup_structured_describer_test.go @@ -82,6 +82,7 @@ func TestDescribeBackupInSF(t *testing.T) { "TTL": "72h0m0s", "CSISnapshotTimeout": "10m0s", "veleroSnapshotMoveData": "auto", + "hookFailed": "True", "hooks": map[string]interface{}{ "resources": map[string]interface{}{ "hook-1": map[string]interface{}{ @@ -115,7 +116,7 @@ func TestDescribeBackupInSF(t *testing.T) { }, }, } - DescribeBackupSpecInSF(sd, backupBuilder1.Result().Spec) + DescribeBackupSpecInSF(sd, backupBuilder1.Result().Spec, hookFailedTrue) assert.True(t, reflect.DeepEqual(sd.output, expect1)) backupBuilder2 := builder.ForBackup("test-ns-2", "test-backup-2"). @@ -167,6 +168,7 @@ func TestDescribeBackupInSF(t *testing.T) { "TTL": "0s", "CSISnapshotTimeout": "0s", "veleroSnapshotMoveData": "auto", + "hookFailed": "True", "hooks": map[string]interface{}{ "resources": map[string]interface{}{ "hook-1": map[string]interface{}{ @@ -204,7 +206,7 @@ func TestDescribeBackupInSF(t *testing.T) { }, }, } - DescribeBackupSpecInSF(sd, backupBuilder2.Result().Spec) + DescribeBackupSpecInSF(sd, backupBuilder2.Result().Spec, hookFailedTrue) assert.True(t, reflect.DeepEqual(sd.output, expect2)) } diff --git a/pkg/cmd/util/output/describe.go b/pkg/cmd/util/output/describe.go index d4f6e9e4f1..11da2afb9c 100644 --- a/pkg/cmd/util/output/describe.go +++ b/pkg/cmd/util/output/describe.go @@ -18,14 +18,27 @@ package output import ( "bytes" + "context" "encoding/json" "fmt" "sort" "strings" "text/tabwriter" + "time" "github.com/fatih/color" + "github.com/vmware-tanzu/velero/internal/hook" + velerov1api "github.com/vmware-tanzu/velero/pkg/apis/velero/v1" + "github.com/vmware-tanzu/velero/pkg/cmd/util/downloadrequest" + "github.com/vmware-tanzu/velero/pkg/util/results" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" + kbclient "sigs.k8s.io/controller-runtime/pkg/client" +) + +const ( + hookFailedUnknown = "Unknown" + hookFailedTrue = "True" + hookFailedFalse = "False" ) type Describer struct { @@ -167,3 +180,41 @@ func (d *StructuredDescriber) JSONEncode() string { _ = encoder.Encode(d.output) return byteBuffer.String() } + +func downloadResult(ctx context.Context, kbClient kbclient.Client, namespace, name string, kind velerov1api.DownloadTargetKind, timeout time.Duration, insecureSkipTLSVerify bool, caCertFile string) (map[string]results.Result, error) { + var buf bytes.Buffer + var resultMap map[string]results.Result + + // If 'ErrNotFound' occurs, it means the backup bundle in the bucket was already there before the backup-result file was introduced. + // We only display the count of errors and warnings instead. + err := downloadrequest.Stream(ctx, kbClient, namespace, name, kind, &buf, timeout, insecureSkipTLSVerify, caCertFile) + if err != nil { + return resultMap, err + } + if err := json.NewDecoder(&buf).Decode(&resultMap); err != nil { + return resultMap, err + } + return resultMap, nil +} + +func hookFailed(resultMap map[string]results.Result, resultErr error) string { + if resultErr != nil { + return hookFailedUnknown + } + if len(resultMap) == 0 { + return hookFailedFalse + } + + if _, ok := resultMap["errors"]; !ok { + return hookFailedFalse + } + + for _, msgs := range resultMap["errors"].Namespaces { + for _, msg := range msgs { + if strings.Contains(msg, hook.HookErrLogPrefix) { + return hookFailedTrue + } + } + } + return hookFailedFalse +} diff --git a/pkg/cmd/util/output/describe_test.go b/pkg/cmd/util/output/describe_test.go index 45becf8733..9edb177d5d 100644 --- a/pkg/cmd/util/output/describe_test.go +++ b/pkg/cmd/util/output/describe_test.go @@ -2,6 +2,7 @@ package output import ( "bytes" + "errors" "fmt" "reflect" "testing" @@ -9,6 +10,8 @@ import ( "github.com/fatih/color" "github.com/stretchr/testify/assert" + "github.com/vmware-tanzu/velero/internal/hook" + "github.com/vmware-tanzu/velero/pkg/util/results" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" ) @@ -166,3 +169,50 @@ func TestStructuredDescriber_DescribeMetadata(t *testing.T) { assert.True(t, reflect.DeepEqual(expect, d.output)) } + +// hookFailed(resultMap map[string]results.Result, resultErr error) string +func TestHookFailed(t *testing.T) { + resultMap1 := map[string]results.Result{ + "warns": {}, + } + resultMap2 := map[string]results.Result{ + "errors": {Namespaces: map[string][]string{"ns": {hook.HookErrLogPrefix + "hook failed"}}}, + } + testcases := []struct { + name string + resultMap map[string]results.Result + resultErr error + expect string + }{ + { + name: "err is not nil", + resultMap: nil, + resultErr: errors.New("result error"), + expect: hookFailedUnknown, + }, + { + name: "resultMap is empty", + resultMap: nil, + resultErr: nil, + expect: hookFailedFalse, + }, + { + name: "resultMap doesn't contain errors", + resultMap: resultMap1, + resultErr: nil, + expect: hookFailedFalse, + }, + { + name: "resultMap contains errors", + resultMap: resultMap2, + resultErr: nil, + expect: hookFailedTrue, + }, + } + for _, tc := range testcases { + t.Run(tc.name, func(t *testing.T) { + actual := hookFailed(tc.resultMap, tc.resultErr) + assert.Equal(t, tc.expect, actual) + }) + } +} diff --git a/pkg/cmd/util/output/restore_describer.go b/pkg/cmd/util/output/restore_describer.go index c64c1a88a5..9b88566565 100644 --- a/pkg/cmd/util/output/restore_describer.go +++ b/pkg/cmd/util/output/restore_describer.go @@ -96,7 +96,10 @@ func DescribeRestore(ctx context.Context, kbClient kbclient.Client, restore *vel } } - describeRestoreResults(ctx, kbClient, d, restore, insecureSkipTLSVerify, caCertFile) + resultMap, resultErr := downloadResult(ctx, kbClient, restore.Namespace, restore.Name, velerov1api.DownloadTargetKindRestoreResults, downloadRequestTimeout, insecureSkipTLSVerify, caCertFile) + hookFailed := hookFailed(resultMap, resultErr) + + describeRestoreResults(ctx, kbClient, d, restore, resultMap, resultErr) d.Println() d.Printf("Backup:\t%s\n", restore.Spec.BackupName) @@ -136,6 +139,9 @@ func DescribeRestore(ctx context.Context, kbClient kbclient.Client, restore *vel d.Printf("\tCluster-scoped:\t%s\n", BoolPointerString(restore.Spec.IncludeClusterResources, "excluded", "included", "auto")) + d.Println() + d.Printf("Hook Failed:\t%s\n", hookFailed) + d.Println() d.DescribeMap("Namespace mappings", restore.Spec.NamespaceMapping) @@ -214,21 +220,13 @@ func describeRestoreItemOperations(ctx context.Context, kbClient kbclient.Client } } -func describeRestoreResults(ctx context.Context, kbClient kbclient.Client, d *Describer, restore *velerov1api.Restore, insecureSkipTLSVerify bool, caCertPath string) { +func describeRestoreResults(ctx context.Context, kbClient kbclient.Client, d *Describer, restore *velerov1api.Restore, resultMap map[string]results.Result, resultErr error) { if restore.Status.Warnings == 0 && restore.Status.Errors == 0 { return } - var buf bytes.Buffer - var resultMap map[string]results.Result - - if err := downloadrequest.Stream(ctx, kbClient, restore.Namespace, restore.Name, velerov1api.DownloadTargetKindRestoreResults, &buf, downloadRequestTimeout, insecureSkipTLSVerify, caCertPath); err != nil { - d.Printf("Warnings:\t\n\nErrors:\t\n", err, err) - return - } - - if err := json.NewDecoder(&buf).Decode(&resultMap); err != nil { - d.Printf("Warnings:\t\n\nErrors:\t\n", err, err) + if resultErr != nil { + d.Printf("Warnings:\t\n\nErrors:\t\n", resultErr, resultErr) return } diff --git a/pkg/cmd/util/output/schedule_describe_test.go b/pkg/cmd/util/output/schedule_describe_test.go index 7123199ec4..3296642591 100644 --- a/pkg/cmd/util/output/schedule_describe_test.go +++ b/pkg/cmd/util/output/schedule_describe_test.go @@ -51,7 +51,8 @@ Backup Template: CSISnapshotTimeout: 0s ItemOperationTimeout: 0s - Hooks: + Hook Failed: Unknown + Hooks: Last Backup: ` @@ -97,7 +98,8 @@ Backup Template: CSISnapshotTimeout: 0s ItemOperationTimeout: 0s - Hooks: + Hook Failed: Unknown + Hooks: Last Backup: 2023-06-25 15:04:05 +0000 UTC ` diff --git a/pkg/cmd/util/output/schedule_describer.go b/pkg/cmd/util/output/schedule_describer.go index 57bd1726d3..838e54dbcd 100644 --- a/pkg/cmd/util/output/schedule_describer.go +++ b/pkg/cmd/util/output/schedule_describer.go @@ -74,7 +74,7 @@ func DescribeScheduleSpec(d *Describer, spec v1.ScheduleSpec) { d.Println() d.Println("Backup Template:") d.Prefix = "\t" - DescribeBackupSpec(d, spec.Template) + DescribeBackupSpec(d, spec.Template, hookFailedUnknown) d.Prefix = "" } diff --git a/pkg/restore/restore.go b/pkg/restore/restore.go index ea0af47c97..b60d6d0daf 100644 --- a/pkg/restore/restore.go +++ b/pkg/restore/restore.go @@ -1955,8 +1955,9 @@ func (ctx *restoreContext) waitExec(createdObj *unstructured.Unstructured) { podNs := createdObj.GetNamespace() pod := new(v1.Pod) if err := runtime.DefaultUnstructuredConverter.FromUnstructured(createdObj.UnstructuredContent(), &pod); err != nil { - ctx.log.WithError(err).Error("error converting unstructured pod") - ctx.hooksErrs <- hook.HookErrInfo{Namespace: podNs, Err: err} + msg := "error converting unstructured pod" + ctx.log.WithError(err).Error(msg) + ctx.hooksErrs <- hook.HookErrInfo{Namespace: podNs, Err: errors.New(hook.HookErrLogPrefix + msg + err.Error())} return } execHooksByContainer, err := hook.GroupRestoreExecHooks( @@ -1965,18 +1966,20 @@ func (ctx *restoreContext) waitExec(createdObj *unstructured.Unstructured) { ctx.log, ) if err != nil { - ctx.log.WithError(err).Errorf("error getting exec hooks for pod %s/%s", pod.Namespace, pod.Name) - ctx.hooksErrs <- hook.HookErrInfo{Namespace: podNs, Err: err} + msg := fmt.Sprintf("error getting exec hooks for pod %s/%s", pod.Namespace, pod.Name) + ctx.log.WithError(err).Errorf(msg) + ctx.hooksErrs <- hook.HookErrInfo{Namespace: podNs, Err: errors.New(hook.HookErrLogPrefix + msg + err.Error())} return } if errs := ctx.waitExecHookHandler.HandleHooks(ctx.hooksContext, ctx.log, pod, execHooksByContainer); len(errs) > 0 { - ctx.log.WithError(kubeerrs.NewAggregate(errs)).Error("unable to successfully execute post-restore hooks") + msg := "unable to successfully execute post-restore hooks" + ctx.log.WithError(kubeerrs.NewAggregate(errs)).Error(msg) ctx.hooksCancelFunc() for _, err := range errs { // Errors are already logged in the HandleHooks method. - ctx.hooksErrs <- hook.HookErrInfo{Namespace: podNs, Err: err} + ctx.hooksErrs <- hook.HookErrInfo{Namespace: podNs, Err: errors.New(hook.HookErrLogPrefix + msg + err.Error())} } } }()