Merge pull request #199 from ncdc/log-enhancements

Log enhancements

examples/minio/10-ark-config.yaml

@@ -23,7 +23,7 @@ backupStorageProvider:
   bucket: ark
   config:
     region: minio
-    s3ForcePathStyle: true
+    s3ForcePathStyle: "true"
     s3Url: http://minio:9000
 backupSyncPeriod: 1m
 gcSyncPeriod: 1m

pkg/backup/backup.go

@@ -35,6 +35,7 @@ import (
 	"github.com/heptio/ark/pkg/discovery"
 	"github.com/heptio/ark/pkg/util/collections"
 	kubeutil "github.com/heptio/ark/pkg/util/kube"
+	"github.com/heptio/ark/pkg/util/logging"
 )
 
 // Backupper performs backups.
@@ -183,6 +184,8 @@ func (kb *kubernetesBackupper) Backup(backup *api.Backup, backupFile, logFile io
 
 	logger := logrus.New()
 	logger.Out = gzippedLog
+	logger.Hooks.Add(&logging.ErrorLocationHook{})
+	logger.Hooks.Add(&logging.LogLocationHook{})
 	log := logger.WithField("backup", kubeutil.NamespaceAndName(backup))
 	log.Info("Starting backup")
 

pkg/controller/backup_controller.go

@@ -316,6 +316,7 @@ func (controller *backupController) runBackup(backup *api.Backup, bucket string)
 		err = kuberrs.NewAggregate(errs)
 	}()
 
+	controller.logger.WithField("backup", kubeutil.NamespaceAndName(backup)).Info("starting backup")
 	if err := controller.backupper.Backup(backup, backupFile, logFile); err != nil {
 		return err
 	}

pkg/controller/restore_controller.go

@@ -391,7 +391,9 @@ func (controller *restoreController) runRestore(restore *api.Restore, bucket str
 		}
 	}()
 
+	logContext.Info("starting restore")
 	restoreWarnings, restoreErrors = controller.restorer.Restore(restore, backup, backupFile, logFile)
+	logContext.Info("restore completed")
 
 	// Try to upload the log file. This is best-effort. If we fail, we'll add to the ark errors.
 

pkg/restore/restore.go

@@ -46,6 +46,7 @@ import (
 	"github.com/heptio/ark/pkg/restore/restorers"
 	"github.com/heptio/ark/pkg/util/collections"
 	"github.com/heptio/ark/pkg/util/kube"
+	"github.com/heptio/ark/pkg/util/logging"
 )
 
 // Restorer knows how to restore a backup.
@@ -207,6 +208,8 @@ func (kr *kubernetesRestorer) Restore(restore *api.Restore, backup *api.Backup,
 
 	log := logrus.New()
 	log.Out = gzippedLog
+	log.Hooks.Add(&logging.ErrorLocationHook{})
+	log.Hooks.Add(&logging.LogLocationHook{})
 
 	ctx := &context{
 		backup:               backup,

pkg/util/logging/log_location_hook.go

@@ -27,6 +27,9 @@ import (
 const (
 	logSourceField          = "logSource"
 	logSourceSetMarkerField = "@logSourceSetBy"
+	logrusPackage           = "github.com/sirupsen/logrus"
+	arkPackage              = "github.com/heptio/ark"
+	arkPackageLen           = len(arkPackage)
 )
 
 // LogLocationHook is a logrus hook that attaches location information
@@ -73,7 +76,7 @@ func (h *LogLocationHook) Fire(entry *logrus.Entry) error {
 	for more {
 		frame, more = frames.Next()
 
-		if strings.Contains(frame.File, "github.com/sirupsen/logrus") {
+		if strings.Contains(frame.File, logrusPackage) {
 			continue
 		}
 
@@ -87,7 +90,13 @@ func (h *LogLocationHook) Fire(entry *logrus.Entry) error {
 		// we're in Ark server and not logging something that has the marker
 		// set (which would indicate the log statement is coming from a plugin).
 		if h.loggerName != "" || getLogSourceSetMarker(entry) == "" {
-			entry.Data[logSourceField] = fmt.Sprintf("%s:%d", frame.File, frame.Line)
+			file := frame.File
+			if index := strings.Index(file, arkPackage); index != -1 {
+				// strip off .../github.com/heptio/ark/ so we just have pkg/...
+				file = frame.File[index+arkPackageLen+1:]
+			}
+
+			entry.Data[logSourceField] = fmt.Sprintf("%s:%d", file, frame.Line)
 		}
 
 		// if we're in the Ark server, remove the marker field since we don't