diff --git a/pkg/backup/backup.go b/pkg/backup/backup.go index 112ff27ff7..85e03e6df9 100644 --- a/pkg/backup/backup.go +++ b/pkg/backup/backup.go @@ -20,12 +20,12 @@ import ( "archive/tar" "compress/gzip" "encoding/json" - "fmt" "io" "strings" "time" "github.com/pkg/errors" + "github.com/sirupsen/logrus" "k8s.io/apimachinery/pkg/api/meta" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" @@ -58,11 +58,11 @@ var _ Backupper = &kubernetesBackupper{} // ActionContext contains contextual information for actions. type ActionContext struct { - logger *logger + logger *logrus.Logger } -func (ac ActionContext) log(msg string, args ...interface{}) { - ac.logger.log(msg, args...) +func (ac ActionContext) infof(msg string, args ...interface{}) { + ac.logger.Infof(msg, args...) } // Action is an actor that performs an operation on an individual item being backed up. @@ -117,7 +117,7 @@ func (ctx *backupContext) getResourceIncludesExcludes(helper discovery.Helper, i func(item string) string { gr, err := helper.ResolveGroupResource(item) if err != nil { - ctx.log("Unable to resolve resource %q: %v", item, err) + ctx.infof("Unable to resolve resource %q: %v", item, err) return "" } @@ -132,20 +132,10 @@ func getNamespaceIncludesExcludes(backup *api.Backup) *collections.IncludesExclu return collections.NewIncludesExcludes().Includes(backup.Spec.IncludedNamespaces...).Excludes(backup.Spec.ExcludedNamespaces...) } -type logger struct { - w io.Writer -} - -func (l *logger) log(msg string, args ...interface{}) { - // TODO use a real logger that supports writing to files - now := time.Now().Format(time.RFC3339) - fmt.Fprintf(l.w, now+" "+msg+"\n", args...) -} - type backupContext struct { backup *api.Backup w tarWriter - logger *logger + logger *logrus.Logger namespaceIncludesExcludes *collections.IncludesExcludes resourceIncludesExcludes *collections.IncludesExcludes // deploymentsBackedUp marks whether we've seen and are backing up the deployments resource, from @@ -158,8 +148,8 @@ type backupContext struct { networkPoliciesBackedUp bool } -func (ctx *backupContext) log(msg string, args ...interface{}) { - ctx.logger.log(msg, args...) +func (ctx *backupContext) infof(msg string, args ...interface{}) { + ctx.logger.Infof(msg, args...) } // Backup backs up the items specified in the Backup, placing them in a gzip-compressed tar file @@ -176,19 +166,22 @@ func (kb *kubernetesBackupper) Backup(backup *api.Backup, backupFile, logFile io var errs []error + log := logrus.New() + log.Out = gzippedLog + ctx := &backupContext{ backup: backup, w: tw, - logger: &logger{w: gzippedLog}, + logger: log, namespaceIncludesExcludes: getNamespaceIncludesExcludes(backup), } - ctx.log("Starting backup") + ctx.infof("Starting backup") ctx.resourceIncludesExcludes = ctx.getResourceIncludesExcludes(kb.discoveryHelper, backup.Spec.IncludedResources, backup.Spec.ExcludedResources) for _, group := range kb.discoveryHelper.Resources() { - ctx.log("Processing group %s", group.GroupVersion) + ctx.infof("Processing group %s", group.GroupVersion) if err := kb.backupGroup(ctx, group); err != nil { errs = append(errs, err) } @@ -196,9 +189,9 @@ func (kb *kubernetesBackupper) Backup(backup *api.Backup, backupFile, logFile io err := kuberrs.NewAggregate(errs) if err == nil { - ctx.log("Backup completed successfully") + ctx.infof("Backup completed successfully") } else { - ctx.log("Backup completed with errors: %v", err) + ctx.infof("Backup completed with errors: %v", err) } return err @@ -215,7 +208,7 @@ func (kb *kubernetesBackupper) backupGroup(ctx *backupContext, group *metav1.API var errs []error for _, resource := range group.APIResources { - ctx.log("Processing resource %s/%s", group.GroupVersion, resource.Name) + ctx.infof("Processing resource %s/%s", group.GroupVersion, resource.Name) if err := kb.backupResource(ctx, group, resource); err != nil { errs = append(errs, err) } @@ -248,7 +241,7 @@ func (kb *kubernetesBackupper) backupResource( grString := gr.String() if !ctx.resourceIncludesExcludes.ShouldInclude(grString) { - ctx.log("Resource %s is excluded", grString) + ctx.infof("Resource %s is excluded", grString) return nil } @@ -260,7 +253,7 @@ func (kb *kubernetesBackupper) backupResource( } else { other = appsDeploymentsResource } - ctx.log("Skipping resource %q because it's a duplicate of %q", grString, other) + ctx.infof("Skipping resource %q because it's a duplicate of %q", grString, other) return nil } @@ -275,7 +268,7 @@ func (kb *kubernetesBackupper) backupResource( } else { other = networkingNetworkPoliciesResource } - ctx.log("Skipping resource %q because it's a duplicate of %q", grString, other) + ctx.infof("Skipping resource %q because it's a duplicate of %q", grString, other) return nil } @@ -377,13 +370,13 @@ func (*realItemBackupper) backupItem(ctx *backupContext, item map[string]interfa namespace, err := collections.GetString(metadata, "namespace") if err == nil { if !ctx.namespaceIncludesExcludes.ShouldInclude(namespace) { - ctx.log("Excluding item %s because namespace %s is excluded", name, namespace) + ctx.infof("Excluding item %s because namespace %s is excluded", name, namespace) return nil } } if action != nil { - ctx.log("Executing action on %s, ns=%s, name=%s", groupResource, namespace, name) + ctx.infof("Executing action on %s, ns=%s, name=%s", groupResource, namespace, name) actionCtx := ActionContext{logger: ctx.logger} if err := action.Execute(actionCtx, item, ctx.backup); err != nil { @@ -391,7 +384,7 @@ func (*realItemBackupper) backupItem(ctx *backupContext, item map[string]interfa } } - ctx.log("Backing up resource=%s, ns=%s, name=%s", groupResource, namespace, name) + ctx.infof("Backing up resource=%s, ns=%s, name=%s", groupResource, namespace, name) var filePath string if namespace != "" { diff --git a/pkg/backup/backup_test.go b/pkg/backup/backup_test.go index 8905634935..60794f54b8 100644 --- a/pkg/backup/backup_test.go +++ b/pkg/backup/backup_test.go @@ -29,6 +29,11 @@ import ( "testing" "time" + testlogger "github.com/sirupsen/logrus/hooks/test" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/mock" + "github.com/stretchr/testify/require" + "k8s.io/apimachinery/pkg/api/meta" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/apis/meta/v1/unstructured" @@ -39,9 +44,6 @@ import ( "github.com/heptio/ark/pkg/apis/ark/v1" "github.com/heptio/ark/pkg/util/collections" . "github.com/heptio/ark/pkg/util/test" - "github.com/stretchr/testify/assert" - "github.com/stretchr/testify/mock" - "github.com/stretchr/testify/require" ) type fakeAction struct { @@ -189,9 +191,10 @@ func TestGetResourceIncludesExcludes(t *testing.T) { }, } - b := new(bytes.Buffer) + log, _ := testlogger.NewNullLogger() + ctx := &backupContext{ - logger: &logger{w: b}, + logger: log, } actual := ctx.getResourceIncludesExcludes(dh, test.includes, test.excludes) @@ -758,6 +761,9 @@ func TestBackupResource(t *testing.T) { require.NoError(t, err) labelSelector = s } + + log, _ := testlogger.NewNullLogger() + ctx := &backupContext{ backup: &v1.Backup{ Spec: v1.BackupSpec{ @@ -768,7 +774,7 @@ func TestBackupResource(t *testing.T) { namespaceIncludesExcludes: test.namespaceIncludesExcludes, deploymentsBackedUp: test.deploymentsBackedUp, networkPoliciesBackedUp: test.networkPoliciesBackedUp, - logger: &logger{w: new(bytes.Buffer)}, + logger: log, } group := &metav1.APIResourceList{ @@ -992,11 +998,14 @@ func TestBackupItem(t *testing.T) { actionParam = action backup = &v1.Backup{} } + + log, _ := testlogger.NewNullLogger() + ctx := &backupContext{ backup: backup, namespaceIncludesExcludes: namespaces, w: w, - logger: &logger{w: new(bytes.Buffer)}, + logger: log, } b := &realItemBackupper{} err = b.backupItem(ctx, item, "resource.group", actionParam) diff --git a/pkg/backup/volume_snapshot_action.go b/pkg/backup/volume_snapshot_action.go index 3f477ff2aa..44ebd4690a 100644 --- a/pkg/backup/volume_snapshot_action.go +++ b/pkg/backup/volume_snapshot_action.go @@ -59,7 +59,7 @@ func NewVolumeSnapshotAction(snapshotService cloudprovider.SnapshotService) (Act func (a *volumeSnapshotAction) Execute(ctx ActionContext, volume map[string]interface{}, backup *api.Backup) error { backupName := fmt.Sprintf("%s/%s", backup.Namespace, backup.Name) if backup.Spec.SnapshotVolumes != nil && !*backup.Spec.SnapshotVolumes { - ctx.log("Backup %q has volume snapshots disabled; skipping volume snapshot action.", backupName) + ctx.infof("Backup %q has volume snapshots disabled; skipping volume snapshot action.", backupName) return nil } @@ -68,12 +68,12 @@ func (a *volumeSnapshotAction) Execute(ctx ActionContext, volume map[string]inte var pvFailureDomainZone string if labelsMap, err := collections.GetMap(metadata, "labels"); err != nil { - ctx.log("error getting labels on PersistentVolume %q for backup %q: %v", name, backupName, err) + ctx.infof("error getting labels on PersistentVolume %q for backup %q: %v", name, backupName, err) } else { if labelsMap[zoneLabel] != nil { pvFailureDomainZone = labelsMap[zoneLabel].(string) } else { - ctx.log("label %q is not present on PersistentVolume %q for backup %q.", zoneLabel, name, backupName) + ctx.infof("label %q is not present on PersistentVolume %q for backup %q.", zoneLabel, name, backupName) } } @@ -84,23 +84,23 @@ func (a *volumeSnapshotAction) Execute(ctx ActionContext, volume map[string]inte } // no volumeID / nil error means unsupported PV source if volumeID == "" { - ctx.log("Backup %q: PersistentVolume %q is not a supported volume type for snapshots, skipping.", backupName, name) + ctx.infof("Backup %q: PersistentVolume %q is not a supported volume type for snapshots, skipping.", backupName, name) return nil } expiration := a.clock.Now().Add(backup.Spec.TTL.Duration) - ctx.log("Backup %q: snapshotting PersistentVolume %q, volume-id %q, expiration %v", backupName, name, volumeID, expiration) + ctx.infof("Backup %q: snapshotting PersistentVolume %q, volume-id %q, expiration %v", backupName, name, volumeID, expiration) snapshotID, err := a.snapshotService.CreateSnapshot(volumeID, pvFailureDomainZone) if err != nil { - ctx.log("error creating snapshot for backup %q, volume %q, volume-id %q: %v", backupName, name, volumeID, err) + ctx.infof("error creating snapshot for backup %q, volume %q, volume-id %q: %v", backupName, name, volumeID, err) return err } volumeType, iops, err := a.snapshotService.GetVolumeInfo(volumeID, pvFailureDomainZone) if err != nil { - ctx.log("error getting volume info for backup %q, volume %q, volume-id %q: %v", backupName, name, volumeID, err) + ctx.infof("error getting volume info for backup %q, volume %q, volume-id %q: %v", backupName, name, volumeID, err) return err } diff --git a/pkg/backup/volume_snapshot_action_test.go b/pkg/backup/volume_snapshot_action_test.go index 99df26bf80..d9f210b33f 100644 --- a/pkg/backup/volume_snapshot_action_test.go +++ b/pkg/backup/volume_snapshot_action_test.go @@ -17,11 +17,11 @@ limitations under the License. package backup import ( - "bytes" "reflect" "testing" "time" + testlogger "github.com/sirupsen/logrus/hooks/test" "github.com/stretchr/testify/require" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" @@ -198,7 +198,9 @@ func TestVolumeSnapshotAction(t *testing.T) { t.Fatal(err) } - actionCtx := ActionContext{logger: &logger{w: new(bytes.Buffer)}} + log, _ := testlogger.NewNullLogger() + + actionCtx := ActionContext{logger: log} err = action.Execute(actionCtx, pv, backup) gotErr := err != nil diff --git a/pkg/restore/restore.go b/pkg/restore/restore.go index 8886aab595..646e266dac 100644 --- a/pkg/restore/restore.go +++ b/pkg/restore/restore.go @@ -26,7 +26,6 @@ import ( "path" "path/filepath" "sort" - "time" "github.com/sirupsen/logrus" @@ -206,13 +205,16 @@ func (kr *kubernetesRestorer) Restore(restore *api.Restore, backup *api.Backup, gzippedLog := gzip.NewWriter(logFile) defer gzippedLog.Close() + log := logrus.New() + log.Out = gzippedLog + ctx := &context{ backup: backup, backupReader: backupReader, restore: restore, prioritizedResources: prioritizedResources, selector: selector, - logger: &logger{w: gzippedLog}, + logger: log, dynamicFactory: kr.dynamicFactory, fileSystem: kr.fileSystem, namespaceClient: kr.namespaceClient, @@ -222,39 +224,29 @@ func (kr *kubernetesRestorer) Restore(restore *api.Restore, backup *api.Backup, return ctx.execute() } -type logger struct { - w io.Writer -} - -func (l *logger) log(msg string, args ...interface{}) { - // TODO use a real logger that supports writing to files - now := time.Now().Format(time.RFC3339) - fmt.Fprintf(l.w, now+" "+msg+"\n", args...) -} - type context struct { backup *api.Backup backupReader io.Reader restore *api.Restore prioritizedResources []schema.GroupResource selector labels.Selector - logger *logger + logger *logrus.Logger dynamicFactory client.DynamicFactory fileSystem FileSystem namespaceClient corev1.NamespaceInterface restorers map[schema.GroupResource]restorers.ResourceRestorer } -func (ctx *context) log(msg string, args ...interface{}) { - ctx.logger.log(msg, args...) +func (ctx *context) infof(msg string, args ...interface{}) { + ctx.logger.Infof(msg, args...) } func (ctx *context) execute() (api.RestoreResult, api.RestoreResult) { - ctx.log("Starting restore of backup %s", kube.NamespaceAndName(ctx.backup)) + ctx.infof("Starting restore of backup %s", kube.NamespaceAndName(ctx.backup)) dir, err := ctx.unzipAndExtractBackup(ctx.backupReader) if err != nil { - ctx.log("error unzipping and extracting: %v", err) + ctx.infof("error unzipping and extracting: %v", err) return api.RestoreResult{}, api.RestoreResult{Ark: []string{err.Error()}} } defer ctx.fileSystem.RemoveAll(dir) @@ -304,7 +296,7 @@ func (ctx *context) restoreFromDir(dir string) (api.RestoreResult, api.RestoreRe nsPath := path.Join(namespacesPath, ns.Name()) if !namespaceFilter.ShouldInclude(ns.Name()) { - ctx.log("Skipping namespace %s", ns.Name()) + ctx.infof("Skipping namespace %s", ns.Name()) continue } @@ -354,9 +346,9 @@ func (ctx *context) restoreNamespace(nsName, nsPath string) (api.RestoreResult, warnings, errors := api.RestoreResult{}, api.RestoreResult{} if nsName == "" { - ctx.log("Restoring cluster-scoped resources") + ctx.infof("Restoring cluster-scoped resources") } else { - ctx.log("Restoring namespace %s", nsName) + ctx.infof("Restoring namespace %s", nsName) } resourceDirs, err := ctx.fileSystem.ReadDir(nsPath) @@ -413,7 +405,7 @@ func (ctx *context) restoreResourceForNamespace(namespace string, resourcePath s warnings, errors := api.RestoreResult{}, api.RestoreResult{} resource := path.Base(resourcePath) - ctx.log("Restoring resource %v into namespace %v", resource, namespace) + ctx.infof("Restoring resource %v into namespace %v", resource, namespace) files, err := ctx.fileSystem.ReadDir(resourcePath) if err != nil { @@ -446,7 +438,7 @@ func (ctx *context) restoreResourceForNamespace(namespace string, resourcePath s if restorer == nil { // initialize client & restorer for this Resource. we need // metadata from an object to do this. - ctx.log("Getting client for %v", obj.GroupVersionKind()) + ctx.infof("Getting client for %v", obj.GroupVersionKind()) resource := metav1.APIResource{ Namespaced: len(namespace) > 0, @@ -462,10 +454,10 @@ func (ctx *context) restoreResourceForNamespace(namespace string, resourcePath s restorer = ctx.restorers[groupResource] if restorer == nil { - ctx.log("Using default restorer for %v", &groupResource) + ctx.infof("Using default restorer for %v", &groupResource) restorer = restorers.NewBasicRestorer(true) } else { - ctx.log("Using custom restorer for %v", &groupResource) + ctx.infof("Using custom restorer for %v", &groupResource) } if restorer.Wait() { @@ -486,7 +478,7 @@ func (ctx *context) restoreResourceForNamespace(namespace string, resourcePath s } if hasControllerOwner(obj.GetOwnerReferences()) { - ctx.log("%s/%s has a controller owner - skipping", obj.GetNamespace(), obj.GetName()) + ctx.infof("%s/%s has a controller owner - skipping", obj.GetNamespace(), obj.GetName()) continue } @@ -511,14 +503,14 @@ func (ctx *context) restoreResourceForNamespace(namespace string, resourcePath s // add an ark-restore label to each resource for easy ID addLabel(unstructuredObj, api.RestoreLabelKey, ctx.restore.Name) - ctx.log("Restoring %s: %v", obj.GroupVersionKind().Kind, unstructuredObj.GetName()) + ctx.infof("Restoring %s: %v", obj.GroupVersionKind().Kind, unstructuredObj.GetName()) _, err = resourceClient.Create(unstructuredObj) if apierrors.IsAlreadyExists(err) { addToResult(&warnings, namespace, err) continue } if err != nil { - ctx.log("error restoring %s: %v", unstructuredObj.GetName(), err) + ctx.infof("error restoring %s: %v", unstructuredObj.GetName(), err) addToResult(&errors, namespace, fmt.Errorf("error restoring %s: %v", fullPath, err)) continue } @@ -584,7 +576,7 @@ func (ctx *context) unmarshal(filePath string) (*unstructured.Unstructured, erro func (ctx *context) unzipAndExtractBackup(src io.Reader) (string, error) { gzr, err := gzip.NewReader(src) if err != nil { - ctx.log("error creating gzip reader: %v", err) + ctx.infof("error creating gzip reader: %v", err) return "", err } defer gzr.Close() @@ -597,7 +589,7 @@ func (ctx *context) unzipAndExtractBackup(src io.Reader) (string, error) { func (ctx *context) readBackup(tarRdr *tar.Reader) (string, error) { dir, err := ctx.fileSystem.TempDir("", "") if err != nil { - ctx.log("error creating temp dir: %v", err) + ctx.infof("error creating temp dir: %v", err) return "", err } @@ -608,7 +600,7 @@ func (ctx *context) readBackup(tarRdr *tar.Reader) (string, error) { break } if err != nil { - ctx.log("error reading tar: %v", err) + ctx.infof("error reading tar: %v", err) return "", err } @@ -618,7 +610,7 @@ func (ctx *context) readBackup(tarRdr *tar.Reader) (string, error) { case tar.TypeDir: err := ctx.fileSystem.MkdirAll(target, header.FileInfo().Mode()) if err != nil { - ctx.log("mkdirall error: %v", err) + ctx.infof("mkdirall error: %v", err) return "", err } @@ -626,7 +618,7 @@ func (ctx *context) readBackup(tarRdr *tar.Reader) (string, error) { // make sure we have the directory created err := ctx.fileSystem.MkdirAll(path.Dir(target), header.FileInfo().Mode()) if err != nil { - ctx.log("mkdirall error: %v", err) + ctx.infof("mkdirall error: %v", err) return "", err } @@ -638,7 +630,7 @@ func (ctx *context) readBackup(tarRdr *tar.Reader) (string, error) { defer file.Close() if _, err := io.Copy(file, tarRdr); err != nil { - ctx.log("error copying: %v", err) + ctx.infof("error copying: %v", err) return "", err } } diff --git a/pkg/restore/restore_test.go b/pkg/restore/restore_test.go index 09eaab7d0b..5a44b9351e 100644 --- a/pkg/restore/restore_test.go +++ b/pkg/restore/restore_test.go @@ -19,11 +19,11 @@ package restore import ( "encoding/json" "io" - "io/ioutil" "os" "testing" "github.com/sirupsen/logrus/hooks/test" + testlogger "github.com/sirupsen/logrus/hooks/test" "github.com/spf13/afero" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -174,11 +174,13 @@ func TestRestoreMethod(t *testing.T) { for _, test := range tests { t.Run(test.name, func(t *testing.T) { + log, _ := testlogger.NewNullLogger() + ctx := &context{ restore: test.restore, namespaceClient: &fakeNamespaceClient{}, fileSystem: test.fileSystem, - logger: &logger{w: ioutil.Discard}, + logger: log, } warnings, errors := ctx.restoreFromDir(test.baseDir) @@ -266,12 +268,14 @@ func TestRestoreNamespace(t *testing.T) { for _, test := range tests { t.Run(test.name, func(t *testing.T) { + log, _ := testlogger.NewNullLogger() + ctx := &context{ restore: test.restore, namespaceClient: &fakeNamespaceClient{}, fileSystem: test.fileSystem, prioritizedResources: test.prioritizedResources, - logger: &logger{w: ioutil.Discard}, + logger: log, } warnings, errors := ctx.restoreNamespace(test.namespace, test.path) @@ -407,6 +411,8 @@ func TestRestoreResourceForNamespace(t *testing.T) { gvk := schema.GroupVersionKind{Group: "", Version: "v1", Kind: "ConfigMap"} dynamicFactory.On("ClientForGroupVersionKind", gvk, resource, test.namespace).Return(resourceClient, nil) + log, _ := testlogger.NewNullLogger() + ctx := &context{ dynamicFactory: dynamicFactory, restorers: test.restorers, @@ -419,7 +425,7 @@ func TestRestoreResourceForNamespace(t *testing.T) { }, }, backup: &api.Backup{}, - logger: &logger{w: ioutil.Discard}, + logger: log, } warnings, errors := ctx.restoreResourceForNamespace(test.namespace, test.resourcePath)