introduced structural debug logging and optional JSON output (#1475)

* logging: added Logger.Debugw(message, key1, value1, ..., keyN, valueN)

This is based on ZAP and allows structural logs to be emitted.

* cli: added --json-log-console and --json-log-file flags

* logging: updated storage logging wrapper to use structural logging

* pr feedback

cli/config.go

@@ -60,15 +60,10 @@ func (c *App) openRepository(ctx context.Context, required bool) (repo.Repositor
 }
 
 func (c *App) optionsFromFlags(ctx context.Context) *repo.Options {
-	var opts repo.Options
-
-	if c.traceStorage {
-		opts.TraceStorage = log(ctx).Debugf
+	return &repo.Options{
+		TraceStorage:       c.traceStorage,
+		DisableInternalLog: c.disableInternalLog,
 	}
-
-	opts.DisableInternalLog = c.disableInternalLog
-
-	return &opts
 }
 
 func (c *App) repositoryConfigFileName() string {

internal/epoch/epoch_manager_test.go

@@ -91,7 +91,7 @@ func newTestEnv(t *testing.T) *epochManagerTestEnv {
 		Base: st,
 	}
 	st = fs
-	st = logging.NewWrapper(st, t.Logf, "[STORAGE] ")
+	st = logging.NewWrapper(st, testlogging.NewTestLogger(t), "[STORAGE] ")
 	te := &epochManagerTestEnv{unloggedst: unloggedst, st: st, ft: ft}
 	m := NewManager(te.st, Parameters{
 		Enabled:                 true,

internal/logfile/logfile.go

@@ -41,6 +41,8 @@ type loggingFlags struct {
 	logLevel              string
 	fileLogLevel          string
 	fileLogLocalTimezone  bool
+	jsonLogFile           bool
+	jsonLogConsole        bool
 	forceColor            bool
 	disableColor          bool
 	consoleLogTimestamps  bool
@@ -58,6 +60,8 @@ func (c *loggingFlags) setup(cliApp *cli.App, app *kingpin.Application) {
 	app.Flag("content-log-dir-max-files", "Maximum number of content log files to retain").Envar("KOPIA_CONTENT_LOG_DIR_MAX_FILES").Default("5000").Hidden().IntVar(&c.contentLogDirMaxFiles)
 	app.Flag("content-log-dir-max-age", "Maximum age of content log files to retain").Envar("KOPIA_CONTENT_LOG_DIR_MAX_AGE").Default("720h").Hidden().DurationVar(&c.contentLogDirMaxAge)
 	app.Flag("log-level", "Console log level").Default("info").EnumVar(&c.logLevel, logLevels...)
+	app.Flag("json-log-console", "JSON log file").Hidden().BoolVar(&c.jsonLogConsole)
+	app.Flag("json-log-file", "JSON log file").Hidden().BoolVar(&c.jsonLogFile)
 	app.Flag("file-log-level", "File log level").Default("debug").EnumVar(&c.fileLogLevel, logLevels...)
 	app.Flag("file-log-local-tz", "When logging to a file, use local timezone").Hidden().Envar("KOPIA_FILE_LOG_LOCAL_TZ").BoolVar(&c.fileLogLocalTimezone)
 	app.Flag("force-color", "Force color output").Hidden().Envar("KOPIA_FORCE_COLOR").BoolVar(&c.forceColor)
@@ -126,9 +130,9 @@ func (c *loggingFlags) initialize(ctx *kingpin.ParseContext) error {
 }
 
 func (c *loggingFlags) setupConsoleCore() zapcore.Core {
-	ec := zapcore.EncoderConfig{
-		LevelKey:         "L",
-		MessageKey:       "M",
+	ec := &zapcore.EncoderConfig{
+		LevelKey:         "l",
+		MessageKey:       "m",
 		LineEnding:       zapcore.DefaultLineEnding,
 		EncodeTime:       zapcore.RFC3339NanoTimeEncoder,
 		EncodeDuration:   zapcore.StringDurationEncoder,
@@ -137,28 +141,38 @@ func (c *loggingFlags) setupConsoleCore() zapcore.Core {
 	}
 
 	if c.consoleLogTimestamps {
-		ec.TimeKey = "T"
-		// always log local timestamps to the console, not UTC
-		ec.EncodeTime = zaplogutil.TimezoneAdjust(zapcore.TimeEncoderOfLayout("15:04:05.000"), true)
-	}
+		ec.TimeKey = "t"
 
-	ec.EncodeLevel = func(l zapcore.Level, pae zapcore.PrimitiveArrayEncoder) {
-		if l == zap.InfoLevel {
-			// info log does not have a prefix.
-			return
-		}
-
-		if c.disableColor {
-			zapcore.CapitalLevelEncoder(l, pae)
+		if c.jsonLogConsole {
+			ec.EncodeTime = zapcore.RFC3339NanoTimeEncoder
 		} else {
-			zapcore.CapitalColorLevelEncoder(l, pae)
+			// always log local timestamps to the console, not UTC
+			ec.EncodeTime = zaplogutil.TimezoneAdjust(zapcore.TimeEncoderOfLayout("15:04:05.000"), true)
 		}
 	}
 
-	consoleFormat := zapcore.NewConsoleEncoder(ec)
+	if c.jsonLogConsole {
+		ec.EncodeLevel = zapcore.CapitalLevelEncoder
+
+		ec.NameKey = "n"
+		ec.EncodeName = zapcore.FullNameEncoder
+	} else {
+		ec.EncodeLevel = func(l zapcore.Level, pae zapcore.PrimitiveArrayEncoder) {
+			if l == zap.InfoLevel {
+				// info log does not have a prefix.
+				return
+			}
+
+			if c.disableColor {
+				zapcore.CapitalLevelEncoder(l, pae)
+			} else {
+				zapcore.CapitalColorLevelEncoder(l, pae)
+			}
+		}
+	}
 
 	return zapcore.NewCore(
-		consoleFormat,
+		c.jsonOrConsoleEncoder(ec, c.jsonLogConsole),
 		zapcore.AddSync(c.cliApp.Stderr()),
 		logLevelFromFlag(c.logLevel),
 	)
@@ -203,28 +217,36 @@ func (c *loggingFlags) setupLogFileBasedLogger(now time.Time, subdir, suffix, lo
 
 func (c *loggingFlags) setupLogFileCore(now time.Time, suffix string) zapcore.Core {
 	return zapcore.NewCore(
-		zapcore.NewConsoleEncoder(zapcore.EncoderConfig{
+		c.jsonOrConsoleEncoder(&zapcore.EncoderConfig{
 			TimeKey:          "t",
-			MessageKey:       "msg",
-			NameKey:          "logger",
-			LevelKey:         "lvl",
+			MessageKey:       "m",
+			NameKey:          "n",
+			LevelKey:         "l",
 			EncodeName:       zapcore.FullNameEncoder,
 			EncodeLevel:      zapcore.CapitalLevelEncoder,
 			EncodeTime:       zaplogutil.TimezoneAdjust(zaplogutil.PreciseTimeEncoder, c.fileLogLocalTimezone),
 			EncodeDuration:   zapcore.StringDurationEncoder,
 			ConsoleSeparator: " ",
-		}),
+		}, c.jsonLogFile),
 		c.setupLogFileBasedLogger(now, "cli-logs", suffix, c.logFile, c.logDirMaxFiles, c.logDirMaxAge),
 		logLevelFromFlag(c.fileLogLevel),
 	)
 }
 
+func (c *loggingFlags) jsonOrConsoleEncoder(ec *zapcore.EncoderConfig, isJSON bool) zapcore.Encoder {
+	if isJSON {
+		return zapcore.NewJSONEncoder(*ec)
+	}
+
+	return zapcore.NewConsoleEncoder(*ec)
+}
+
 func (c *loggingFlags) setupContentLogFileBackend(now time.Time, suffix string) zapcore.Core {
 	return zapcore.NewCore(
 		zapcore.NewConsoleEncoder(zapcore.EncoderConfig{
 			TimeKey:          "t",
-			MessageKey:       "msg",
-			NameKey:          "logger",
+			MessageKey:       "m",
+			NameKey:          "n",
 			EncodeTime:       zaplogutil.TimezoneAdjust(zaplogutil.PreciseTimeEncoder, false),
 			EncodeDuration:   zapcore.StringDurationEncoder,
 			ConsoleSeparator: " ",

internal/testlogging/ctx.go

@@ -41,6 +41,15 @@ func (l *testLogger) Debugf(msg string, args ...interface{}) {
 	l.t.Logf(l.prefix+msg, args...)
 }
 
+func (l *testLogger) Debugw(msg string, keyValuePairs ...interface{}) {
+	if l.minLevel > LevelDebug {
+		return
+	}
+
+	l.t.Helper()
+	l.t.Logf(logging.DebugMessageWithKeyValuePairs(msg, keyValuePairs))
+}
+
 func (l *testLogger) Infof(msg string, args ...interface{}) {
 	if l.minLevel > LevelInfo {
 		return

internal/uitask/uitask.go

@@ -177,6 +177,10 @@ func (l runningTaskLogger) Debugf(msg string, args ...interface{}) {
 	l.r.addLogEntry(l.module, LogLevelDebug, msg, args)
 }
 
+func (l runningTaskLogger) Debugw(msg string, keyValuePairs ...interface{}) {
+	l.r.addLogEntry(l.module, LogLevelDebug, logging.DebugMessageWithKeyValuePairs(msg, keyValuePairs), nil)
+}
+
 func (l runningTaskLogger) Infof(msg string, args ...interface{}) {
 	l.r.addLogEntry(l.module, LogLevelInfo, msg, args)
 }

repo/blob/logging/logging_storage.go

@@ -7,14 +7,13 @@ import (
 
 	"github.com/kopia/kopia/internal/timetrack"
 	"github.com/kopia/kopia/repo/blob"
+	"github.com/kopia/kopia/repo/logging"
 )
 
-const maxLoggedBlobLength = 20 // maximum length of the blob to log contents of
-
 type loggingStorage struct {
 	base   blob.Storage
-	printf func(string, ...interface{})
 	prefix string
+	logger logging.Logger
 }
 
 func (s *loggingStorage) GetBlob(ctx context.Context, id blob.ID, offset, length int64, output blob.OutputBuffer) error {
@@ -22,11 +21,14 @@ func (s *loggingStorage) GetBlob(ctx context.Context, id blob.ID, offset, length
 	err := s.base.GetBlob(ctx, id, offset, length, output)
 	dt := timer.Elapsed()
 
-	if output.Length() < maxLoggedBlobLength {
-		s.printf(s.prefix+"GetBlob(%q,%v,%v)=(%v, %#v) took %v", id, offset, length, output, err, dt)
-	} else {
-		s.printf(s.prefix+"GetBlob(%q,%v,%v)=({%v bytes}, %#v) took %v", id, offset, length, output.Length(), err, dt)
-	}
+	s.logger.Debugw(s.prefix+"GetBlob",
+		"blobID", id,
+		"offset", offset,
+		"length", length,
+		"outputLength", output.Length(),
+		"error", err,
+		"duration", dt,
+	)
 
 	// nolint:wrapcheck
 	return err
@@ -37,7 +39,12 @@ func (s *loggingStorage) GetMetadata(ctx context.Context, id blob.ID) (blob.Meta
 	result, err := s.base.GetMetadata(ctx, id)
 	dt := timer.Elapsed()
 
-	s.printf(s.prefix+"GetMetadata(%q)=(%v, %#v) took %v", id, result, err, dt)
+	s.logger.Debugw(s.prefix+"GetMetadata",
+		"blobID", id,
+		"result", result,
+		"error", err,
+		"duration", dt,
+	)
 
 	// nolint:wrapcheck
 	return result, err
@@ -47,7 +54,13 @@ func (s *loggingStorage) PutBlob(ctx context.Context, id blob.ID, data blob.Byte
 	timer := timetrack.StartTimer()
 	err := s.base.PutBlob(ctx, id, data)
 	dt := timer.Elapsed()
-	s.printf(s.prefix+"PutBlob(%q,len=%v)=%#v took %v", id, data.Length(), err, dt)
+
+	s.logger.Debugw(s.prefix+"PutBlob",
+		"blobID", id,
+		"length", data.Length(),
+		"error", err,
+		"duration", dt,
+	)
 
 	// nolint:wrapcheck
 	return err
@@ -57,7 +70,13 @@ func (s *loggingStorage) SetTime(ctx context.Context, id blob.ID, t time.Time) e
 	timer := timetrack.StartTimer()
 	err := s.base.SetTime(ctx, id, t)
 	dt := timer.Elapsed()
-	s.printf(s.prefix+"SetTime(%q,%v)=%#v took %v", id, t, err, dt)
+
+	s.logger.Debugw(s.prefix+"SetTime",
+		"blobID", id,
+		"time", t,
+		"error", err,
+		"duration", dt,
+	)
 
 	// nolint:wrapcheck
 	return err
@@ -67,8 +86,12 @@ func (s *loggingStorage) DeleteBlob(ctx context.Context, id blob.ID) error {
 	timer := timetrack.StartTimer()
 	err := s.base.DeleteBlob(ctx, id)
 	dt := timer.Elapsed()
-	s.printf(s.prefix+"DeleteBlob(%q)=%#v took %v", id, err, dt)
 
+	s.logger.Debugw(s.prefix+"DeleteBlob",
+		"blobID", id,
+		"error", err,
+		"duration", dt,
+	)
 	// nolint:wrapcheck
 	return err
 }
@@ -80,7 +103,14 @@ func (s *loggingStorage) ListBlobs(ctx context.Context, prefix blob.ID, callback
 		cnt++
 		return callback(bi)
 	})
-	s.printf(s.prefix+"ListBlobs(%q)=%v returned %v items and took %v", prefix, err, cnt, timer.Elapsed())
+	dt := timer.Elapsed()
+
+	s.logger.Debugw(s.prefix+"ListBlobs",
+		"prefix", prefix,
+		"resultCount", cnt,
+		"error", err,
+		"duration", dt,
+	)
 
 	// nolint:wrapcheck
 	return err
@@ -90,7 +120,11 @@ func (s *loggingStorage) Close(ctx context.Context) error {
 	timer := timetrack.StartTimer()
 	err := s.base.Close(ctx)
 	dt := timer.Elapsed()
-	s.printf(s.prefix+"Close()=%#v took %v", err, dt)
+
+	s.logger.Debugw(s.prefix+"Close",
+		"error", err,
+		"duration", dt,
+	)
 
 	// nolint:wrapcheck
 	return err
@@ -108,13 +142,17 @@ func (s *loggingStorage) FlushCaches(ctx context.Context) error {
 	timer := timetrack.StartTimer()
 	err := s.base.FlushCaches(ctx)
 	dt := timer.Elapsed()
-	s.printf(s.prefix+"FlushCaches()=%#v took %v", err, dt)
+
+	s.logger.Debugw(s.prefix+"FlushCaches",
+		"error", err,
+		"duration", dt,
+	)
 
 	// nolint:wrapcheck
 	return err
 }
 
 // NewWrapper returns a Storage wrapper that logs all storage commands.
-func NewWrapper(wrapped blob.Storage, printf func(msg string, args ...interface{}), prefix string) blob.Storage {
-	return &loggingStorage{base: wrapped, printf: printf, prefix: prefix}
+func NewWrapper(wrapped blob.Storage, logger logging.Logger, prefix string) blob.Storage {
+	return &loggingStorage{base: wrapped, logger: logger, prefix: prefix}
 }

repo/blob/logging/logging_storage_test.go

@@ -9,6 +9,7 @@ import (
 	"github.com/kopia/kopia/internal/blobtesting"
 	"github.com/kopia/kopia/internal/testlogging"
 	"github.com/kopia/kopia/repo/blob"
+	"github.com/kopia/kopia/repo/logging"
 )
 
 func TestLoggingStorage(t *testing.T) {
@@ -27,7 +28,7 @@ func TestLoggingStorage(t *testing.T) {
 	kt := map[blob.ID]time.Time{}
 	underlying := blobtesting.NewMapStorage(data, kt, nil)
 
-	st := NewWrapper(underlying, myOutput, myPrefix)
+	st := NewWrapper(underlying, logging.Printf(myOutput, ""), myPrefix)
 	if st == nil {
 		t.Fatalf("unexpected result: %v", st)
 	}

repo/blob/rclone/rclone_storage_test.go

@@ -231,7 +231,7 @@ func TestRCloneProviders(t *testing.T) {
 			// at the end of a test delete all blobs that were created.
 			defer cleanupAllBlobs(ctx, t, st, 0)
 
-			blobtesting.VerifyStorage(ctx, t, logging.NewWrapper(st, t.Logf, "[RCLONE-STORAGE] "))
+			blobtesting.VerifyStorage(ctx, t, logging.NewWrapper(st, testlogging.NewTestLogger(t), "[RCLONE-STORAGE] "))
 			blobtesting.AssertConnectionInfoRoundTrips(ctx, t, st)
 		})
 	}

repo/content/committed_content_index_cache_test.go

@@ -20,7 +20,7 @@ func TestCommittedContentIndexCache_Disk(t *testing.T) {
 
 	ta := faketime.NewClockTimeWithOffset(0)
 
-	testCache(t, &diskCommittedContentIndexCache{testutil.TempDirectory(t), ta.NowFunc(), 3, logging.Printf(t.Logf)("test")}, ta)
+	testCache(t, &diskCommittedContentIndexCache{testutil.TempDirectory(t), ta.NowFunc(), 3, logging.Printf(t.Logf, "test")}, ta)
 }
 
 func TestCommittedContentIndexCache_Memory(t *testing.T) {

repo/content/content_manager_test.go

@@ -1916,7 +1916,7 @@ func (s *contentManagerSuite) TestReadsOwnWritesWithEventualConsistencyPersisten
 	cacheKeyTime := map[blob.ID]time.Time{}
 	cacheSt := blobtesting.NewMapStorage(cacheData, cacheKeyTime, timeNow)
 	ecst := blobtesting.NewEventuallyConsistentStorage(
-		logging.NewWrapper(st, t.Logf, "[STORAGE] "),
+		logging.NewWrapper(st, testlogging.NewTestLogger(t), "[STORAGE] "),
 		3*time.Second,
 		timeNow)
 

repo/content/index_blob_manager_v0_test.go

@@ -192,9 +192,9 @@ func TestIndexBlobManagerStress(t *testing.T) {
 
 	for actorID := 0; actorID < numActors; actorID++ {
 		actorID := actorID
-		loggedSt := logging.NewWrapper(st, func(m string, args ...interface{}) {
+		loggedSt := logging.NewWrapper(st, repologging.Printf(func(m string, args ...interface{}) {
 			t.Logf(fmt.Sprintf("@%v actor[%v]:", fakeTimeFunc().Format("150405.000"), actorID)+m, args...)
-		}, "")
+		}, ""), "")
 		contentPrefix := fmt.Sprintf("a%v", actorID)
 
 		eg.Go(func() error {
@@ -284,9 +284,9 @@ func TestCompactionCreatesPreviousIndex(t *testing.T) {
 
 	st := blobtesting.NewMapStorage(storageData, nil, fakeTimeFunc)
 	st = blobtesting.NewEventuallyConsistentStorage(st, testEventualConsistencySettleTime, fakeTimeFunc)
-	st = logging.NewWrapper(st, func(msg string, args ...interface{}) {
+	st = logging.NewWrapper(st, repologging.Printf(func(msg string, args ...interface{}) {
 		t.Logf("[store] "+fakeTimeFunc().Format("150405.000")+" "+msg, args...)
-	}, "store: ")
+	}, ""), "")
 	m := newIndexBlobManagerForTesting(t, st, fakeTimeFunc)
 
 	numWritten := 0
@@ -364,9 +364,9 @@ func verifyIndexBlobManagerPreventsResurrectOfDeletedContents(t *testing.T, dela
 
 	st := blobtesting.NewMapStorage(storageData, nil, fakeTimeFunc)
 	st = blobtesting.NewEventuallyConsistentStorage(st, testEventualConsistencySettleTime, fakeTimeFunc)
-	st = logging.NewWrapper(st, func(msg string, args ...interface{}) {
-		t.Logf("[store] "+fakeTimeFunc().Format("150405.000")+" "+msg, args...)
-	}, "store: ")
+	st = logging.NewWrapper(st, repologging.Printf(func(msg string, args ...interface{}) {
+		t.Logf(fakeTimeFunc().Format("150405.000")+" "+msg, args...)
+	}, ""), "")
 	m := newIndexBlobManagerForTesting(t, st, fakeTimeFunc)
 
 	numWritten := 0
@@ -782,7 +782,7 @@ func newIndexBlobManagerForTesting(t *testing.T, st blob.Storage, localTimeNow f
 		15*time.Minute,
 	)
 
-	log := repologging.Printf(t.Logf)("test")
+	log := repologging.Printf(t.Logf, "test")
 
 	m := &indexBlobManagerV0{
 		st: st,

repo/content/internal_logger.go

@@ -82,8 +82,8 @@ func (m *internalLogManager) NewLogger() *zap.SugaredLogger {
 	return zap.New(zapcore.NewCore(
 		zapcore.NewConsoleEncoder(zapcore.EncoderConfig{
 			TimeKey:          "t",
-			MessageKey:       "msg",
-			NameKey:          "logger",
+			MessageKey:       "m",
+			NameKey:          "n",
 			EncodeTime:       zaplogutil.TimezoneAdjust(zaplogutil.PreciseTimeEncoder, false),
 			EncodeDuration:   zapcore.StringDurationEncoder,
 			ConsoleSeparator: " ",

repo/logging/broadcast.go

@@ -10,6 +10,13 @@ func (b Broadcast) Debugf(msg string, args ...interface{}) {
 	}
 }
 
+// Debugw implements Logger.
+func (b Broadcast) Debugw(msg string, keyValuePairs ...interface{}) {
+	for _, l := range b {
+		l.Debugw(msg, keyValuePairs...)
+	}
+}
+
 // Infof implements Logger.
 func (b Broadcast) Infof(msg string, args ...interface{}) {
 	for _, l := range b {

repo/logging/logging.go

@@ -11,6 +11,7 @@ type LoggerFactory func(module string) Logger
 // Logger is an interface used by Kopia to output logs.
 type Logger interface {
 	Debugf(msg string, args ...interface{})
+	Debugw(msg string, keyValuePairs ...interface{})
 	Infof(msg string, args ...interface{})
 	Warnf(msg string, args ...interface{})
 	Errorf(msg string, args ...interface{})

repo/logging/logging_test.go

@@ -1,6 +1,7 @@
 package logging_test
 
 import (
+	"bytes"
 	"context"
 	"fmt"
 	"testing"
@@ -15,17 +16,21 @@ func TestPrefix(t *testing.T) {
 
 	l0 := logging.Printf(func(msg string, args ...interface{}) {
 		lines = append(lines, fmt.Sprintf(msg, args...))
-	})("module1")
+	}, "[module1] ")
 
 	l := logging.WithPrefix("PREFIX:", l0)
 	l.Debugf("A")
+	l.Debugw("S", "a", 1, "b", true, "c", 3.14, "d", "eee")
 	l.Infof("B")
 	l.Errorf("C")
+	l.Warnf("W")
 
 	require.Equal(t, []string{
 		"[module1] PREFIX:A",
+		"[module1] PREFIX:S a:1 b:true c:3.14 d:\"eee\"",
 		"[module1] PREFIX:B",
 		"[module1] PREFIX:C",
+		"[module1] PREFIX:W",
 	}, lines)
 }
 
@@ -34,30 +39,92 @@ func TestBroadcast(t *testing.T) {
 
 	l0 := logging.Printf(func(msg string, args ...interface{}) {
 		lines = append(lines, fmt.Sprintf(msg, args...))
-	})("first")
+	}, "[first] ")
 
 	l1 := logging.Printf(func(msg string, args ...interface{}) {
 		lines = append(lines, fmt.Sprintf(msg, args...))
-	})("second")
+	}, "[second] ")
 
 	l := logging.Broadcast{l0, l1}
 	l.Debugf("A")
+	l.Debugw("S", "b", 123)
 	l.Infof("B")
 	l.Errorf("C")
+	l.Warnf("W")
 
 	require.Equal(t, []string{
 		"[first] A",
 		"[second] A",
+		"[first] S b:123",
+		"[second] S b:123",
 		"[first] B",
 		"[second] B",
 		"[first] C",
 		"[second] C",
+		"[first] W",
+		"[second] W",
 	}, lines)
 }
 
+func TestDebugMessageWithKeyValuePairs(t *testing.T) {
+	cases := []struct {
+		msg           string
+		keysAndValues []interface{}
+		want          string
+	}{
+		{"msg", nil, "msg"},
+		{"msg", []interface{}{"foo", 1, "bar", true, "baz", 3.14, "str", "string value"}, "msg foo:1 bar:true baz:3.14 str:\"string value\""},
+		{"msg", []interface{}{"foo", 1}, "msg foo:1"},
+		{"msg", []interface{}{"foo"}, "msg malformed-foo"},
+		{"msg", []interface{}{1, 2}, "msg malformed-1:2"},
+	}
+
+	for _, tc := range cases {
+		require.Equal(t, tc.want, logging.DebugMessageWithKeyValuePairs(tc.msg, tc.keysAndValues))
+	}
+}
+
+func TestWriter(t *testing.T) {
+	var buf bytes.Buffer
+
+	l := logging.Writer(&buf)("module1")
+	l.Debugf("A")
+	l.Debugw("S", "b", 123)
+	l.Infof("B")
+	l.Errorf("C")
+	l.Warnf("W")
+
+	require.Equal(t, "A\nS b:123\nB\nC\nW\n", buf.String())
+}
+
+func TestNullWriterModule(t *testing.T) {
+	l := logging.Module("mod1")(context.Background())
+
+	l.Debugf("A")
+	l.Debugw("S", "b", 123)
+	l.Infof("B")
+	l.Errorf("C")
+	l.Warnf("W")
+}
+
+func TestNonNullWriterModule(t *testing.T) {
+	var buf bytes.Buffer
+
+	ctx := logging.WithLogger(context.Background(), logging.Writer(&buf))
+	l := logging.Module("mod1")(ctx)
+
+	l.Debugf("A")
+	l.Debugw("S", "b", 123)
+	l.Infof("B")
+	l.Errorf("C")
+	l.Warnf("W")
+
+	require.Equal(t, "A\nS b:123\nB\nC\nW\n", buf.String())
+}
+
 func BenchmarkLogger(b *testing.B) {
 	mod1 := logging.Module("mod1")
-	ctx := logging.WithLogger(context.Background(), logging.Printf(b.Logf))
+	ctx := logging.WithLogger(context.Background(), logging.PrintfFactory(b.Logf))
 
 	b.ResetTimer()
 

repo/logging/null_logger.go

@@ -2,10 +2,11 @@ package logging
 
 type nullLogger struct{}
 
-func (nullLogger) Debugf(msg string, args ...interface{}) {}
-func (nullLogger) Infof(msg string, args ...interface{})  {}
-func (nullLogger) Warnf(msg string, args ...interface{})  {}
-func (nullLogger) Errorf(msg string, args ...interface{}) {}
+func (nullLogger) Debugf(msg string, args ...interface{})          {}
+func (nullLogger) Debugw(msg string, keyValuePairs ...interface{}) {}
+func (nullLogger) Infof(msg string, args ...interface{})           {}
+func (nullLogger) Warnf(msg string, args ...interface{})           {}
+func (nullLogger) Errorf(msg string, args ...interface{})          {}
 
 var nullLoggerInstance = nullLogger{}
 

repo/logging/prefix.go

@@ -11,6 +11,11 @@ func (p *prefixLogger) Debugf(msg string, args ...interface{}) {
 	p.inner.Debugf(p.prefixFunc()+msg, args...)
 }
 
+// Debugw implements Logger.
+func (p *prefixLogger) Debugw(msg string, keyValuePairs ...interface{}) {
+	p.inner.Debugw(p.prefixFunc()+msg, keyValuePairs...)
+}
+
 // Infof implements Logger.
 func (p *prefixLogger) Infof(msg string, args ...interface{}) {
 	p.inner.Infof(p.prefixFunc()+msg, args...)

repo/logging/printf_logger.go

@@ -6,18 +6,55 @@ import (
 	"strings"
 )
 
+// DebugMessageWithKeyValuePairs returns a debug string consisting of alternating key:value separated by spaces and prefixed with a space.
+func DebugMessageWithKeyValuePairs(msg string, keyValuePairs []interface{}) string {
+	var sb strings.Builder
+
+	sb.WriteString(msg)
+
+	for i := 0; i+1 < len(keyValuePairs); i += 2 {
+		if key, ok := keyValuePairs[i].(string); ok {
+			value := keyValuePairs[i+1]
+
+			if stringValue, ok := keyValuePairs[i+1].(string); ok {
+				fmt.Fprintf(&sb, " %v:%q", key, stringValue)
+			} else {
+				fmt.Fprintf(&sb, " %v:%v", key, value)
+			}
+		} else {
+			fmt.Fprintf(&sb, " malformed-%v:%v", keyValuePairs[i], keyValuePairs[i+1])
+		}
+	}
+
+	if len(keyValuePairs)%2 == 1 {
+		fmt.Fprintf(&sb, " malformed-%v", keyValuePairs[len(keyValuePairs)-1])
+	}
+
+	return sb.String()
+}
+
 type printfLogger struct {
 	printf func(msg string, args ...interface{})
 	prefix string
 }
 
 func (l *printfLogger) Debugf(msg string, args ...interface{}) { l.printf(l.prefix+msg, args...) }
+
+func (l *printfLogger) Debugw(msg string, keyValuePairs ...interface{}) {
+	l.printf(DebugMessageWithKeyValuePairs(l.prefix+msg, keyValuePairs))
+}
+
 func (l *printfLogger) Infof(msg string, args ...interface{})  { l.printf(l.prefix+msg, args...) }
 func (l *printfLogger) Warnf(msg string, args ...interface{})  { l.printf(l.prefix+msg, args...) }
 func (l *printfLogger) Errorf(msg string, args ...interface{}) { l.printf(l.prefix+msg, args...) }
 
-// Printf returns LoggerForModuleFunc that uses given printf-style function to print log output.
-func Printf(printf func(msg string, args ...interface{})) LoggerFactory {
+// Printf returns a logger that uses given printf-style function to print log output.
+func Printf(printf func(msg string, args ...interface{}), prefix string) Logger {
+	return &printfLogger{printf, prefix}
+}
+
+// PrintfFactory returns LoggerForModuleFunc that uses given printf-style function to print log output.
+func PrintfFactory(printf func(msg string, args ...interface{})) LoggerFactory {
 	return func(module string) Logger {
 		return &printfLogger{printf, "[" + module + "] "}
 	}

repo/maintenance/maintenance_safety_test.go

@@ -21,7 +21,7 @@ func (s *formatSpecificTestSuite) TestMaintenanceSafety(t *testing.T) {
 
 	ctx, env := repotesting.NewEnvironment(t, s.formatVersion, repotesting.Options{
 		OpenOptions: func(o *repo.Options) {
-			o.TraceStorage = t.Logf
+			o.TraceStorage = true
 			o.TimeNowFunc = ft.NowFunc()
 		},
 	})

repo/open.go

@@ -53,9 +53,9 @@ var log = logging.Module("kopia/repo")
 
 // Options provides configuration parameters for connection to a repository.
 type Options struct {
-	TraceStorage       func(f string, args ...interface{}) // Logs all storage access using provided Printf-style function
-	TimeNowFunc        func() time.Time                    // Time provider
-	DisableInternalLog bool                                // Disable internal log
+	TraceStorage       bool             // Logs all storage access using provided Printf-style function
+	TimeNowFunc        func() time.Time // Time provider
+	DisableInternalLog bool             // Disable internal log
 }
 
 // ErrInvalidPassword is returned when repository password is invalid.
@@ -146,8 +146,8 @@ func openDirect(ctx context.Context, configFile string, lc *LocalConfig, passwor
 		return nil, errors.Wrap(err, "cannot open storage")
 	}
 
-	if options.TraceStorage != nil {
-		st = loggingwrapper.NewWrapper(st, options.TraceStorage, "[STORAGE] ")
+	if options.TraceStorage {
+		st = loggingwrapper.NewWrapper(st, log(ctx), "[STORAGE] ")
 	}
 
 	if lc.ReadOnly {

tests/repository_stress_test/repository_stress_test.go

@@ -266,7 +266,7 @@ func runStress(t *testing.T, opt *StressOptions) {
 				log := logging.WithPrefix(fmt.Sprintf("%v::o%v", filepath.Base(configFile), i), logging.Broadcast{
 					logging.Printf(func(msg string, args ...interface{}) {
 						fmt.Fprintf(logFile, clock.Now().Format("2006-01-02T15:04:05.000000Z07:00")+" "+msg+"\n", args...)
-					})("test"),
+					}, ""),
 				})
 
 				ctx2 := logging.WithLogger(ctx, func(module string) logging.Logger {