switch to logrus for per-backup/restore logs

Signed-off-by: Steve Kriss <steve@heptio.com>
This commit is contained in:
Steve Kriss
2017-10-10 14:11:21 -07:00
parent df3c51416a
commit fa427ebcfd
6 changed files with 85 additions and 83 deletions
+23 -30
View File
@@ -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 != "" {
+16 -7
View File
@@ -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)
+7 -7
View File
@@ -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
}
+4 -2
View File
@@ -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
+25 -33
View File
@@ -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
}
}
+10 -4
View File
@@ -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)