Add JSON as an option for log output (#1654)

* Add JSON as an option for log output

Signed-off-by: Donovan Carthew <donovan.carthew@gmail.com>

changelogs/unreleased/1654-carthewd

@@ -0,0 +1 @@
+enhancement: allow option to choose JSON log output 

pkg/cmd/cli/restic/server.go

@@ -47,6 +47,7 @@ import (
 
 func NewServerCommand(f client.Factory) *cobra.Command {
 	logLevelFlag := logging.LogLevelFlag(logrus.InfoLevel)
+	formatFlag := logging.NewFormatFlag()
 
 	command := &cobra.Command{
 		Use:    "server",
@@ -57,7 +58,7 @@ func NewServerCommand(f client.Factory) *cobra.Command {
 			logLevel := logLevelFlag.Parse()
 			logrus.Infof("Setting log-level to %s", strings.ToUpper(logLevel.String()))
 
-			logger := logging.DefaultLogger(logLevel)
+			logger := logging.DefaultLogger(logLevel, formatFlag.Parse())
 			logger.Infof("Starting Velero restic server %s (%s)", buildinfo.Version, buildinfo.FormattedGitSHA())
 
 			s, err := newResticServer(logger, fmt.Sprintf("%s-%s", c.Parent().Name(), c.Name()))
@@ -68,6 +69,7 @@ func NewServerCommand(f client.Factory) *cobra.Command {
 	}
 
 	command.Flags().Var(logLevelFlag, "log-level", fmt.Sprintf("the level at which to log. Valid values are %s.", strings.Join(logLevelFlag.AllowedValues(), ", ")))
+	command.Flags().Var(formatFlag, "log-format", fmt.Sprintf("the format for log output. Valid values are %s.", strings.Join(formatFlag.AllowedValues(), ", ")))
 
 	return command
 }

pkg/cmd/server/server.go

@@ -119,6 +119,7 @@ type serverConfig struct {
 	clientQPS                                                               float32
 	clientBurst                                                             int
 	profilerAddress                                                         string
+	formatFlag                                                              *logging.FormatFlag
 }
 
 type controllerRunInfo struct {
@@ -143,6 +144,7 @@ func NewCommand() *cobra.Command {
 			clientBurst:                    defaultClientBurst,
 			profilerAddress:                defaultProfilerAddress,
 			resourceTerminatingTimeout:     defaultResourceTerminatingTimeout,
+			formatFlag:                     logging.NewFormatFlag(),
 		}
 	)
 
@@ -157,12 +159,16 @@ func NewCommand() *cobra.Command {
 			log.SetOutput(os.Stdout)
 
 			logLevel := logLevelFlag.Parse()
+			format := config.formatFlag.Parse()
+
 			// Make sure we log to stdout so cloud log dashboards don't show this as an error.
 			logrus.SetOutput(os.Stdout)
-			logrus.Infof("setting log-level to %s", strings.ToUpper(logLevel.String()))
 
 			// Velero's DefaultLogger logs to stdout, so all is good there.
-			logger := logging.DefaultLogger(logLevel)
+			logger := logging.DefaultLogger(logLevel, format)
+
+			logger.Infof("setting log-level to %s", strings.ToUpper(logLevel.String()))
+
 			logger.Infof("Starting Velero server %s (%s)", buildinfo.Version, buildinfo.FormattedGitSHA())
 
 			// NOTE: the namespace flag is bound to velero's persistent flags when the root velero command
@@ -191,6 +197,7 @@ func NewCommand() *cobra.Command {
 	}
 
 	command.Flags().Var(logLevelFlag, "log-level", fmt.Sprintf("the level at which to log. Valid values are %s.", strings.Join(logLevelFlag.AllowedValues(), ", ")))
+	command.Flags().Var(config.formatFlag, "log-format", fmt.Sprintf("the format for log output. Valid values are %s.", strings.Join(config.formatFlag.AllowedValues(), ", ")))
 	command.Flags().StringVar(&config.pluginDir, "plugin-dir", config.pluginDir, "directory containing Velero plugins")
 	command.Flags().StringVar(&config.metricsAddress, "metrics-address", config.metricsAddress, "the address to expose prometheus metrics")
 	command.Flags().DurationVar(&config.backupSyncPeriod, "backup-sync-period", config.backupSyncPeriod, "how often to ensure all Velero backups in object storage exist as Backup API objects in the cluster")
@@ -602,6 +609,7 @@ func (s *server) runControllers(defaultVolumeSnapshotLocations map[string]string
 			s.sharedInformerFactory.Velero().V1().VolumeSnapshotLocations(),
 			defaultVolumeSnapshotLocations,
 			s.metrics,
+			s.config.formatFlag.Parse(),
 		)
 
 		return controllerRunInfo{
@@ -692,6 +700,7 @@ func (s *server) runControllers(defaultVolumeSnapshotLocations map[string]string
 			newPluginManager,
 			s.config.defaultBackupLocation,
 			s.metrics,
+			s.config.formatFlag.Parse(),
 		)
 
 		return controllerRunInfo{

pkg/controller/backup_controller.go

@@ -70,6 +70,7 @@ type backupController struct {
 	defaultSnapshotLocations map[string]string
 	metrics                  *metrics.ServerMetrics
 	newBackupStore           func(*velerov1api.BackupStorageLocation, persistence.ObjectStoreGetter, logrus.FieldLogger) (persistence.BackupStore, error)
+	formatFlag               logging.Format
 }
 
 func NewBackupController(
@@ -86,6 +87,7 @@ func NewBackupController(
 	volumeSnapshotLocationInformer informers.VolumeSnapshotLocationInformer,
 	defaultSnapshotLocations map[string]string,
 	metrics *metrics.ServerMetrics,
+	formatFlag logging.Format,
 ) Interface {
 	c := &backupController{
 		genericController:        newGenericController("backup", logger),
@@ -102,6 +104,7 @@ func NewBackupController(
 		snapshotLocationLister:   volumeSnapshotLocationInformer.Lister(),
 		defaultSnapshotLocations: defaultSnapshotLocations,
 		metrics:                  metrics,
+		formatFlag:               formatFlag,
 
 		newBackupStore: persistence.NewObjectBackupStore,
 	}
@@ -448,7 +451,7 @@ func (c *backupController) runBackup(backup *pkgbackup.Request) error {
 
 	// Log the backup to both a backup log file and to stdout. This will help see what happened if the upload of the
 	// backup log failed for whatever reason.
-	logger := logging.DefaultLogger(c.backupLogLevel)
+	logger := logging.DefaultLogger(c.backupLogLevel, c.formatFlag)
 	logger.Out = io.MultiWriter(os.Stdout, gzippedLogFile)
 
 	logCounter := logging.NewLogCounterHook()

pkg/controller/backup_controller_test.go

@@ -98,14 +98,16 @@ func TestProcessBackupNonProcessedItems(t *testing.T) {
 
 	for _, test := range tests {
 		t.Run(test.name, func(t *testing.T) {
+			formatFlag := logging.FormatText
 			var (
 				sharedInformers = informers.NewSharedInformerFactory(fake.NewSimpleClientset(), 0)
-				logger          = logging.DefaultLogger(logrus.DebugLevel)
+				logger          = logging.DefaultLogger(logrus.DebugLevel, formatFlag)
 			)
 
 			c := &backupController{
 				genericController: newGenericController("backup-test", logger),
 				lister:            sharedInformers.Velero().V1().Backups().Lister(),
+				formatFlag:        formatFlag,
 			}
 
 			if test.backup != nil {
@@ -159,10 +161,11 @@ func TestProcessBackupValidationFailures(t *testing.T) {
 
 	for _, test := range tests {
 		t.Run(test.name, func(t *testing.T) {
+			formatFlag := logging.FormatText
 			var (
 				clientset       = fake.NewSimpleClientset(test.backup)
 				sharedInformers = informers.NewSharedInformerFactory(clientset, 0)
-				logger          = logging.DefaultLogger(logrus.DebugLevel)
+				logger          = logging.DefaultLogger(logrus.DebugLevel, formatFlag)
 			)
 
 			c := &backupController{
@@ -173,6 +176,7 @@ func TestProcessBackupValidationFailures(t *testing.T) {
 				snapshotLocationLister: sharedInformers.Velero().V1().VolumeSnapshotLocations().Lister(),
 				defaultBackupLocation:  defaultBackupLocation.Name,
 				clock:                  &clock.RealClock{},
+				formatFlag:             formatFlag,
 			}
 
 			require.NotNil(t, test.backup)
@@ -225,10 +229,12 @@ func TestBackupLocationLabel(t *testing.T) {
 
 	for _, test := range tests {
 		t.Run(test.name, func(t *testing.T) {
+			formatFlag := logging.FormatText
+
 			var (
 				clientset       = fake.NewSimpleClientset(test.backup)
 				sharedInformers = informers.NewSharedInformerFactory(clientset, 0)
-				logger          = logging.DefaultLogger(logrus.DebugLevel)
+				logger          = logging.DefaultLogger(logrus.DebugLevel, formatFlag)
 			)
 
 			c := &backupController{
@@ -239,6 +245,7 @@ func TestBackupLocationLabel(t *testing.T) {
 				snapshotLocationLister: sharedInformers.Velero().V1().VolumeSnapshotLocations().Lister(),
 				defaultBackupLocation:  test.backupLocation.Name,
 				clock:                  &clock.RealClock{},
+				formatFlag:             formatFlag,
 			}
 
 			res := c.prepareBackupRequest(test.backup)
@@ -279,9 +286,10 @@ func TestDefaultBackupTTL(t *testing.T) {
 	}
 
 	for _, test := range tests {
+		formatFlag := logging.FormatText
 		var (
 			clientset       = fake.NewSimpleClientset(test.backup)
-			logger          = logging.DefaultLogger(logrus.DebugLevel)
+			logger          = logging.DefaultLogger(logrus.DebugLevel, formatFlag)
 			sharedInformers = informers.NewSharedInformerFactory(clientset, 0)
 		)
 
@@ -292,6 +300,7 @@ func TestDefaultBackupTTL(t *testing.T) {
 				snapshotLocationLister: sharedInformers.Velero().V1().VolumeSnapshotLocations().Lister(),
 				defaultBackupTTL:       defaultBackupTTL.Duration,
 				clock:                  clock.NewFakeClock(now),
+				formatFlag:             formatFlag,
 			}
 
 			res := c.prepareBackupRequest(test.backup)
@@ -528,10 +537,11 @@ func TestProcessBackupCompletions(t *testing.T) {
 
 	for _, test := range tests {
 		t.Run(test.name, func(t *testing.T) {
+			formatFlag := logging.FormatText
 			var (
 				clientset       = fake.NewSimpleClientset(test.backup)
 				sharedInformers = informers.NewSharedInformerFactory(clientset, 0)
-				logger          = logging.DefaultLogger(logrus.DebugLevel)
+				logger          = logging.DefaultLogger(logrus.DebugLevel, formatFlag)
 				pluginManager   = new(pluginmocks.Manager)
 				backupStore     = new(persistencemocks.BackupStore)
 				backupper       = new(fakeBackupper)
@@ -551,7 +561,8 @@ func TestProcessBackupCompletions(t *testing.T) {
 				newBackupStore: func(*velerov1api.BackupStorageLocation, persistence.ObjectStoreGetter, logrus.FieldLogger) (persistence.BackupStore, error) {
 					return backupStore, nil
 				},
-				backupper: backupper,
+				backupper:  backupper,
+				formatFlag: formatFlag,
 			}
 
 			pluginManager.On("GetBackupItemActions").Return(nil, nil)

pkg/controller/restore_controller.go

@@ -84,6 +84,7 @@ type restoreController struct {
 	restoreLogLevel        logrus.Level
 	defaultBackupLocation  string
 	metrics                *metrics.ServerMetrics
+	logFormat              logging.Format
 
 	newPluginManager func(logger logrus.FieldLogger) clientmgmt.Manager
 	newBackupStore   func(*api.BackupStorageLocation, persistence.ObjectStoreGetter, logrus.FieldLogger) (persistence.BackupStore, error)
@@ -103,6 +104,7 @@ func NewRestoreController(
 	newPluginManager func(logrus.FieldLogger) clientmgmt.Manager,
 	defaultBackupLocation string,
 	metrics *metrics.ServerMetrics,
+	logFormat logging.Format,
 ) Interface {
 	c := &restoreController{
 		genericController:      newGenericController("restore", logger),
@@ -117,6 +119,7 @@ func NewRestoreController(
 		restoreLogLevel:        restoreLogLevel,
 		defaultBackupLocation:  defaultBackupLocation,
 		metrics:                metrics,
+		logFormat:              logFormat,
 
 		// use variables to refer to these functions so they can be
 		// replaced with fakes for testing.
@@ -412,7 +415,7 @@ func (c *restoreController) fetchBackupInfo(backupName string, pluginManager cli
 func (c *restoreController) runValidatedRestore(restore *api.Restore, info backupInfo) error {
 	// instantiate the per-restore logger that will output both to a temp file
 	// (for upload to object storage) and to stdout.
-	restoreLog, err := newRestoreLogger(restore, c.logger, c.restoreLogLevel)
+	restoreLog, err := newRestoreLogger(restore, c.logger, c.restoreLogLevel, c.logFormat)
 	if err != nil {
 		return err
 	}
@@ -555,14 +558,14 @@ type restoreLogger struct {
 	w    *gzip.Writer
 }
 
-func newRestoreLogger(restore *api.Restore, baseLogger logrus.FieldLogger, logLevel logrus.Level) (*restoreLogger, error) {
+func newRestoreLogger(restore *api.Restore, baseLogger logrus.FieldLogger, logLevel logrus.Level, logFormat logging.Format) (*restoreLogger, error) {
 	file, err := ioutil.TempFile("", "")
 	if err != nil {
 		return nil, errors.Wrap(err, "error creating temp file")
 	}
 	w := gzip.NewWriter(file)
 
-	logger := logging.DefaultLogger(logLevel)
+	logger := logging.DefaultLogger(logLevel, logFormat)
 	logger.Out = io.MultiWriter(os.Stdout, w)
 
 	return &restoreLogger{

pkg/controller/restore_controller_test.go

@@ -47,6 +47,7 @@ import (
 	pluginmocks "github.com/heptio/velero/pkg/plugin/mocks"
 	"github.com/heptio/velero/pkg/plugin/velero"
 	pkgrestore "github.com/heptio/velero/pkg/restore"
+	"github.com/heptio/velero/pkg/util/logging"
 	velerotest "github.com/heptio/velero/pkg/util/test"
 	"github.com/heptio/velero/pkg/volume"
 )
@@ -85,6 +86,8 @@ func TestFetchBackupInfo(t *testing.T) {
 		},
 	}
 
+	formatFlag := logging.FormatText
+
 	for _, test := range tests {
 		t.Run(test.name, func(t *testing.T) {
 			var (
@@ -113,6 +116,7 @@ func TestFetchBackupInfo(t *testing.T) {
 				func(logrus.FieldLogger) clientmgmt.Manager { return pluginManager },
 				"default",
 				metrics.NewServerMetrics(),
+				formatFlag,
 			).(*restoreController)
 
 			c.newBackupStore = func(*api.BackupStorageLocation, persistence.ObjectStoreGetter, logrus.FieldLogger) (persistence.BackupStore, error) {
@@ -183,6 +187,8 @@ func TestProcessQueueItemSkips(t *testing.T) {
 		},
 	}
 
+	formatFlag := logging.FormatText
+
 	for _, test := range tests {
 		t.Run(test.name, func(t *testing.T) {
 			var (
@@ -206,6 +212,7 @@ func TestProcessQueueItemSkips(t *testing.T) {
 				nil,
 				"default",
 				metrics.NewServerMetrics(),
+				formatFlag,
 			).(*restoreController)
 
 			if test.restore != nil {
@@ -378,6 +385,8 @@ func TestProcessQueueItem(t *testing.T) {
 		},
 	}
 
+	formatFlag := logging.FormatText
+
 	for _, test := range tests {
 		t.Run(test.name, func(t *testing.T) {
 			var (
@@ -406,6 +415,7 @@ func TestProcessQueueItem(t *testing.T) {
 				func(logrus.FieldLogger) clientmgmt.Manager { return pluginManager },
 				"default",
 				metrics.NewServerMetrics(),
+				formatFlag,
 			).(*restoreController)
 
 			c.newBackupStore = func(*api.BackupStorageLocation, persistence.ObjectStoreGetter, logrus.FieldLogger) (persistence.BackupStore, error) {
@@ -607,6 +617,8 @@ func TestProcessQueueItem(t *testing.T) {
 }
 
 func TestvalidateAndCompleteWhenScheduleNameSpecified(t *testing.T) {
+	formatFlag := logging.FormatText
+
 	var (
 		client          = fake.NewSimpleClientset()
 		sharedInformers = informers.NewSharedInformerFactory(client, 0)
@@ -628,6 +640,7 @@ func TestvalidateAndCompleteWhenScheduleNameSpecified(t *testing.T) {
 		nil,
 		"default",
 		nil,
+		formatFlag,
 	).(*restoreController)
 
 	restore := &api.Restore{
@@ -705,7 +718,6 @@ func TestBackupXorScheduleProvided(t *testing.T) {
 	r.Spec.BackupName = ""
 	r.Spec.ScheduleName = "schedule-1"
 	assert.True(t, backupXorScheduleProvided(r))
-
 }
 
 func TestMostRecentCompletedBackup(t *testing.T) {

pkg/discovery/helper_test.go

@@ -180,10 +180,12 @@ func TestRefreshServerPreferredResources(t *testing.T) {
 		},
 	}
 
+	formatFlag := logging.FormatText
+
 	for _, test := range tests {
 		fakeServer := velerotest.NewFakeServerResourcesInterface(test.resourceList, test.failedGroups, test.returnError)
 		t.Run(test.name, func(t *testing.T) {
-			resources, err := refreshServerPreferredResources(fakeServer, logging.DefaultLogger(logrus.DebugLevel))
+			resources, err := refreshServerPreferredResources(fakeServer, logging.DefaultLogger(logrus.DebugLevel, formatFlag))
 			if test.returnError != nil {
 				assert.NotNil(t, err)
 			} else {

pkg/util/logging/default_logger.go

@@ -1,5 +1,5 @@
 /*
-Copyright 2018 the Velero contributors.
+Copyright 2019 the Velero contributors.
 
 Licensed under the Apache License, Version 2.0 (the "License");
 you may not use this file except in compliance with the License.
@@ -32,10 +32,14 @@ func DefaultHooks() []logrus.Hook {
 }
 
 // DefaultLogger returns a Logger with the default properties
-// and hooks.
-func DefaultLogger(level logrus.Level) *logrus.Logger {
+// and hooks. The desired output format is passed as a LogFormat Enum.
+func DefaultLogger(level logrus.Level, format Format) *logrus.Logger {
 	logger := logrus.New()
 
+	if format == FormatJSON {
+		logger.Formatter = new(logrus.JSONFormatter)
+	}
+
 	// Make sure the output is set to stdout so log messages don't show up as errors in cloud log dashboards.
 	logger.Out = os.Stdout