diff --git a/pkg/apis/ark/v1/restore.go b/pkg/apis/ark/v1/restore.go index f8101ea3d..ac230fca5 100644 --- a/pkg/apis/ark/v1/restore.go +++ b/pkg/apis/ark/v1/restore.go @@ -85,6 +85,10 @@ const ( // RestorePhaseCompleted means the restore has finished executing. // Any relevant warnings or errors will be captured in the Status. RestorePhaseCompleted RestorePhase = "Completed" + + // RestorePhaseFailed means the restore was unable to execute. + // The failing error is recorded in status.FailureReason. + RestorePhaseFailed RestorePhase = "Failed" ) // RestoreStatus captures the current status of an Ark restore @@ -103,6 +107,9 @@ type RestoreStatus struct { // Errors is a count of all error messages that were generated during // execution of the restore. The actual errors are stored in object storage. Errors int `json:"errors"` + + // FailureReason is an error that caused the entire restore to fail. + FailureReason string `json:"failureReason"` } // RestoreResult is a collection of messages that were generated diff --git a/pkg/cmd/server/server.go b/pkg/cmd/server/server.go index 91b673272..4f2eec767 100644 --- a/pkg/cmd/server/server.go +++ b/pkg/cmd/server/server.go @@ -726,6 +726,7 @@ func (s *server) runControllers(config *api.Config) error { s.snapshotService != nil, s.logger, s.pluginManager, + s.metrics, ) wg.Add(1) go func() { diff --git a/pkg/controller/restore_controller.go b/pkg/controller/restore_controller.go index 7af63bf81..6eae4ee55 100644 --- a/pkg/controller/restore_controller.go +++ b/pkg/controller/restore_controller.go @@ -45,6 +45,7 @@ import ( arkv1client "github.com/heptio/ark/pkg/generated/clientset/versioned/typed/ark/v1" informers "github.com/heptio/ark/pkg/generated/informers/externalversions/ark/v1" listers "github.com/heptio/ark/pkg/generated/listers/ark/v1" + "github.com/heptio/ark/pkg/metrics" "github.com/heptio/ark/pkg/plugin" "github.com/heptio/ark/pkg/restore" "github.com/heptio/ark/pkg/util/boolptr" @@ -84,6 +85,7 @@ type restoreController struct { queue workqueue.RateLimitingInterface logger logrus.FieldLogger pluginManager plugin.Manager + metrics *metrics.ServerMetrics } func NewRestoreController( @@ -98,6 +100,7 @@ func NewRestoreController( pvProviderExists bool, logger logrus.FieldLogger, pluginManager plugin.Manager, + metrics *metrics.ServerMetrics, ) Interface { c := &restoreController{ namespace: namespace, @@ -114,6 +117,7 @@ func NewRestoreController( queue: workqueue.NewNamedRateLimitingQueue(workqueue.DefaultControllerRateLimiter(), "restore"), logger: logger, pluginManager: pluginManager, + metrics: metrics, } c.syncHandler = c.processRestore @@ -255,13 +259,17 @@ func (c *restoreController) processRestore(key string) error { // don't modify items in the cache restore = restore.DeepCopy() - // complete & validate restore + // validation if restore.Status.ValidationErrors = c.completeAndValidate(restore); len(restore.Status.ValidationErrors) > 0 { restore.Status.Phase = api.RestorePhaseFailedValidation } else { restore.Status.Phase = api.RestorePhaseInProgress } + backupScheduleName := restore.Spec.ScheduleName + // Register attempts after validation so we don't have to fetch the backup multiple times + c.metrics.RegisterRestoreAttempt(backupScheduleName) + // update status updatedRestore, err := patchRestore(original, restore, c.restoreClient) if err != nil { @@ -272,12 +280,12 @@ func (c *restoreController) processRestore(key string) error { restore = updatedRestore.DeepCopy() if restore.Status.Phase == api.RestorePhaseFailedValidation { + c.metrics.RegisterRestoreValidationFailed(backupScheduleName) return nil } - logContext.Debug("Running restore") // execution & upload of restore - restoreWarnings, restoreErrors := c.runRestore(restore, c.bucket) + restoreWarnings, restoreErrors, restoreFailure := c.runRestore(restore, c.bucket) restore.Status.Warnings = len(restoreWarnings.Ark) + len(restoreWarnings.Cluster) for _, w := range restoreWarnings.Namespaces { @@ -289,8 +297,17 @@ func (c *restoreController) processRestore(key string) error { restore.Status.Errors += len(e) } - logContext.Debug("restore completed") - restore.Status.Phase = api.RestorePhaseCompleted + if restoreFailure != nil { + logContext.Debug("restore failed") + restore.Status.Phase = api.RestorePhaseFailed + restore.Status.FailureReason = restoreFailure.Error() + c.metrics.RegisterRestoreFailed(backupScheduleName) + } else { + logContext.Debug("restore completed") + // We got through the restore process without failing validation or restore execution + restore.Status.Phase = api.RestorePhaseCompleted + c.metrics.RegisterRestoreSuccess(backupScheduleName) + } logContext.Debug("Updating Restore final status") if _, err = patchRestore(original, restore, c.restoreClient); err != nil { @@ -308,7 +325,6 @@ func (c *restoreController) completeAndValidate(restore *api.Restore) []string { restore.Spec.ExcludedResources = append(restore.Spec.ExcludedResources, nonrestorable) } } - var validationErrors []string // validate that included resources don't contain any non-restorable resources @@ -361,11 +377,19 @@ func (c *restoreController) completeAndValidate(restore *api.Restore) []string { } } - // validate that we can fetch the source backup - if _, err := c.fetchBackup(c.bucket, restore.Spec.BackupName); err != nil { + var ( + backup *api.Backup + err error + ) + if backup, err = c.fetchBackup(c.bucket, restore.Spec.BackupName); err != nil { return append(validationErrors, fmt.Sprintf("Error retrieving backup: %v", err)) } + // Fill in the ScheduleName so it's easier to consume for metrics. + if restore.Spec.ScheduleName == "" { + restore.Spec.ScheduleName = backup.GetLabels()["ark-schedule"] + } + return validationErrors } @@ -433,7 +457,7 @@ func (c *restoreController) fetchBackup(bucket, name string) (*api.Backup, error return backup, nil } -func (c *restoreController) runRestore(restore *api.Restore, bucket string) (restoreWarnings, restoreErrors api.RestoreResult) { +func (c *restoreController) runRestore(restore *api.Restore, bucket string) (restoreWarnings, restoreErrors api.RestoreResult, restoreFailure error) { logContext := c.logger.WithFields( logrus.Fields{ "restore": kubeutil.NamespaceAndName(restore), @@ -453,6 +477,7 @@ func (c *restoreController) runRestore(restore *api.Restore, bucket string) (res if err != nil { logContext.WithError(err).Error("Error downloading backup") restoreErrors.Ark = append(restoreErrors.Ark, err.Error()) + restoreFailure = err return } tempFiles = append(tempFiles, backupFile) @@ -461,6 +486,7 @@ func (c *restoreController) runRestore(restore *api.Restore, bucket string) (res if err != nil { logContext.WithError(errors.WithStack(err)).Error("Error creating log temp file") restoreErrors.Ark = append(restoreErrors.Ark, err.Error()) + restoreFailure = err return } tempFiles = append(tempFiles, logFile) @@ -469,6 +495,7 @@ func (c *restoreController) runRestore(restore *api.Restore, bucket string) (res if err != nil { logContext.WithError(errors.WithStack(err)).Error("Error creating results temp file") restoreErrors.Ark = append(restoreErrors.Ark, err.Error()) + restoreFailure = err return } tempFiles = append(tempFiles, resultsFile) @@ -477,10 +504,12 @@ func (c *restoreController) runRestore(restore *api.Restore, bucket string) (res for _, file := range tempFiles { if err := file.Close(); err != nil { logContext.WithError(errors.WithStack(err)).WithField("file", file.Name()).Error("Error closing file") + restoreFailure = err } if err := os.Remove(file.Name()); err != nil { logContext.WithError(errors.WithStack(err)).WithField("file", file.Name()).Error("Error removing file") + restoreFailure = err } } }() @@ -492,6 +521,8 @@ func (c *restoreController) runRestore(restore *api.Restore, bucket string) (res } defer c.pluginManager.CloseRestoreItemActions(restore.Name) + // Any return statement above this line means a total restore failure + // Some failures after this line *may* be a total restore failure logContext.Info("starting restore") restoreWarnings, restoreErrors = c.restorer.Restore(restore, backup, backupFile, logFile, actions) logContext.Info("restore completed") diff --git a/pkg/controller/restore_controller_test.go b/pkg/controller/restore_controller_test.go index a9a15c504..b1b5aa53c 100644 --- a/pkg/controller/restore_controller_test.go +++ b/pkg/controller/restore_controller_test.go @@ -37,6 +37,7 @@ import ( api "github.com/heptio/ark/pkg/apis/ark/v1" "github.com/heptio/ark/pkg/generated/clientset/versioned/fake" informers "github.com/heptio/ark/pkg/generated/informers/externalversions" + "github.com/heptio/ark/pkg/metrics" "github.com/heptio/ark/pkg/restore" "github.com/heptio/ark/pkg/util/collections" arktest "github.com/heptio/ark/pkg/util/test" @@ -95,6 +96,7 @@ func TestFetchBackup(t *testing.T) { false, logger, pluginManager, + metrics.NewServerMetrics(), ).(*restoreController) for _, itm := range test.informerBackups { @@ -118,19 +120,21 @@ func TestFetchBackup(t *testing.T) { func TestProcessRestore(t *testing.T) { tests := []struct { - name string - restoreKey string - restore *api.Restore - backup *api.Backup - restorerError error - allowRestoreSnapshots bool - expectedErr bool - expectedPhase string - expectedValidationErrors []string - expectedRestoreErrors int - expectedRestorerCall *api.Restore - backupServiceGetBackupError error - uploadLogError error + name string + restoreKey string + restore *api.Restore + backup *api.Backup + restorerError error + allowRestoreSnapshots bool + expectedErr bool + expectedPhase string + expectedValidationErrors []string + expectedRestoreErrors int + expectedRestorerCall *api.Restore + backupServiceGetBackupError error + uploadLogError error + backupServiceDownloadBackupError error + expectedFinalPhase string }{ { name: "invalid key returns error", @@ -298,6 +302,14 @@ func TestProcessRestore(t *testing.T) { "Invalid included/excluded resource lists: excludes list cannot contain an item in the includes list: restores.ark.heptio.com", }, }, + { + name: "backup download error results in failed restore", + restore: NewRestore("foo", "bar", "backup-1", "ns-1", "", api.RestorePhaseNew).Restore, + expectedPhase: string(api.RestorePhaseInProgress), + expectedFinalPhase: string(api.RestorePhaseFailed), + backupServiceDownloadBackupError: errors.New("Couldn't download backup"), + backup: arktest.NewTestBackup().WithName("backup-1").Backup, + }, } for _, test := range tests { @@ -326,6 +338,7 @@ func TestProcessRestore(t *testing.T) { test.allowRestoreSnapshots, logger, pluginManager, + metrics.NewServerMetrics(), ).(*restoreController) if test.restore != nil { @@ -400,6 +413,10 @@ func TestProcessRestore(t *testing.T) { backupSvc.On("GetBackup", "bucket", mock.Anything).Return(nil, test.backupServiceGetBackupError) } + if test.backupServiceDownloadBackupError != nil { + backupSvc.On("DownloadBackup", "bucket", test.restore.Spec.BackupName).Return(nil, test.backupServiceDownloadBackupError) + } + if test.restore != nil { pluginManager.On("GetRestoreItemActions", test.restore.Name).Return(nil, nil) pluginManager.On("CloseRestoreItemActions", test.restore.Name).Return(nil) @@ -410,7 +427,6 @@ func TestProcessRestore(t *testing.T) { restorer.AssertExpectations(t) assert.Equal(t, test.expectedErr, err != nil, "got error %v", err) - actions := client.Actions() if test.expectedPhase == "" { @@ -475,6 +491,15 @@ func TestProcessRestore(t *testing.T) { Errors: test.expectedRestoreErrors, }, } + // Override our default expectations if the case requires it + if test.expectedFinalPhase != "" { + expected = Patch{ + Status: StatusPatch{ + Phase: api.RestorePhaseCompleted, + Errors: test.expectedRestoreErrors, + }, + } + } arktest.ValidatePatch(t, actions[1], expected, decode) @@ -505,6 +530,7 @@ func TestCompleteAndValidateWhenScheduleNameSpecified(t *testing.T) { false, logger, nil, + nil, ).(*restoreController) restore := &api.Restore{ diff --git a/pkg/metrics/metrics.go b/pkg/metrics/metrics.go index 75115c564..1a4c6c7e6 100644 --- a/pkg/metrics/metrics.go +++ b/pkg/metrics/metrics.go @@ -30,12 +30,18 @@ type ServerMetrics struct { const ( metricNamespace = "ark" backupTarballSizeBytesGauge = "backup_tarball_size_bytes" - backupAttemptCount = "backup_attempt_total" - backupSuccessCount = "backup_success_total" - backupFailureCount = "backup_failure_total" - backupDurationSeconds = "backup_duration_seconds" + // TODO: Rename the Count variables to match their strings + backupAttemptCount = "backup_attempt_total" + backupSuccessCount = "backup_success_total" + backupFailureCount = "backup_failure_total" + backupDurationSeconds = "backup_duration_seconds" + restoreAttemptTotal = "restore_attempt_total" + restoreValidationFailedTotal = "restore_validation_failed_total" + restoreSuccessTotal = "restore_success_total" + restoreFailedTotal = "restore_failed_total" - scheduleLabel = "schedule" + scheduleLabel = "schedule" + backupNameLabel = "backupName" secondsInMinute = 60.0 ) @@ -95,6 +101,38 @@ func NewServerMetrics() *ServerMetrics { }, []string{scheduleLabel}, ), + restoreAttemptTotal: prometheus.NewCounterVec( + prometheus.CounterOpts{ + Namespace: metricNamespace, + Name: restoreAttemptTotal, + Help: "Total number of attempted restores", + }, + []string{scheduleLabel}, + ), + restoreSuccessTotal: prometheus.NewCounterVec( + prometheus.CounterOpts{ + Namespace: metricNamespace, + Name: restoreSuccessTotal, + Help: "Total number of successful restores", + }, + []string{scheduleLabel}, + ), + restoreFailedTotal: prometheus.NewCounterVec( + prometheus.CounterOpts{ + Namespace: metricNamespace, + Name: restoreFailedTotal, + Help: "Total number of failed restores", + }, + []string{scheduleLabel}, + ), + restoreValidationFailedTotal: prometheus.NewCounterVec( + prometheus.CounterOpts{ + Namespace: metricNamespace, + Name: restoreValidationFailedTotal, + Help: "Total number of failed restores failing validations", + }, + []string{scheduleLabel}, + ), }, } } @@ -116,6 +154,18 @@ func (m *ServerMetrics) InitSchedule(scheduleName string) { if c, ok := m.metrics[backupFailureCount].(*prometheus.CounterVec); ok { c.WithLabelValues(scheduleName).Set(0) } + if c, ok := m.metrics[restoreAttemptTotal].(*prometheus.CounterVec); ok { + c.WithLabelValues(scheduleName).Set(0) + } + if c, ok := m.metrics[restoreFailedTotal].(*prometheus.CounterVec); ok { + c.WithLabelValues(scheduleName).Set(0) + } + if c, ok := m.metrics[restoreSuccessTotal].(*prometheus.CounterVec); ok { + c.WithLabelValues(scheduleName).Set(0) + } + if c, ok := m.metrics[restoreValidationFailedTotal].(*prometheus.CounterVec); ok { + c.WithLabelValues(scheduleName).Set(0) + } } // SetBackupTarballSizeBytesGauge records the size, in bytes, of a backup tarball. @@ -158,3 +208,31 @@ func (m *ServerMetrics) RegisterBackupDuration(backupSchedule string, seconds fl func toSeconds(d time.Duration) float64 { return float64(d / time.Second) } + +// RegisterRestoreAttempt records an attempt to restore a backup. +func (m *ServerMetrics) RegisterRestoreAttempt(backupSchedule string) { + if c, ok := m.metrics[restoreAttemptTotal].(*prometheus.CounterVec); ok { + c.WithLabelValues(backupSchedule).Inc() + } +} + +// RegisterRestoreSuccess records a successful (maybe partial) completion of a restore. +func (m *ServerMetrics) RegisterRestoreSuccess(backupSchedule string) { + if c, ok := m.metrics[restoreSuccessTotal].(*prometheus.CounterVec); ok { + c.WithLabelValues(backupSchedule).Inc() + } +} + +// RegisterRestoreFailed records a restore that failed. +func (m *ServerMetrics) RegisterRestoreFailed(backupSchedule string) { + if c, ok := m.metrics[restoreFailedTotal].(*prometheus.CounterVec); ok { + c.WithLabelValues(backupSchedule).Inc() + } +} + +// RegisterRestoreValidationFailed records a restore that failed validation. +func (m *ServerMetrics) RegisterRestoreValidationFailed(backupSchedule string) { + if c, ok := m.metrics[restoreValidationFailedTotal].(*prometheus.CounterVec); ok { + c.WithLabelValues(backupSchedule).Inc() + } +} diff --git a/pkg/util/test/comparisons.go b/pkg/util/test/comparisons.go index 68b7a2edc..5e15e0b09 100644 --- a/pkg/util/test/comparisons.go +++ b/pkg/util/test/comparisons.go @@ -103,6 +103,8 @@ func AssertDeepEqual(t *testing.T, expected, actual interface{}) bool { } if !equality.Semantic.DeepEqual(expected, actual) { + fmt.Printf("expected = %+v\n", expected) + fmt.Printf("actual = %+v\n", actual) return assert.Fail(t, fmt.Sprintf("Objects not equal")) }