diff --git a/cli/config.go b/cli/config.go index 773fb8493..73663e7f8 100644 --- a/cli/config.go +++ b/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 { diff --git a/internal/epoch/epoch_manager_test.go b/internal/epoch/epoch_manager_test.go index 4854d06a8..b695215e0 100644 --- a/internal/epoch/epoch_manager_test.go +++ b/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, diff --git a/internal/logfile/logfile.go b/internal/logfile/logfile.go index 53f4f3c45..5d852bee0 100644 --- a/internal/logfile/logfile.go +++ b/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: " ", diff --git a/internal/testlogging/ctx.go b/internal/testlogging/ctx.go index d97426f44..fd53f1c17 100644 --- a/internal/testlogging/ctx.go +++ b/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 diff --git a/internal/uitask/uitask.go b/internal/uitask/uitask.go index 1ee0ad84d..3cb8aea81 100644 --- a/internal/uitask/uitask.go +++ b/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) } diff --git a/repo/blob/logging/logging_storage.go b/repo/blob/logging/logging_storage.go index c5dad3cc5..45dee6e41 100644 --- a/repo/blob/logging/logging_storage.go +++ b/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} } diff --git a/repo/blob/logging/logging_storage_test.go b/repo/blob/logging/logging_storage_test.go index ce0d9aabc..80bb33ea0 100644 --- a/repo/blob/logging/logging_storage_test.go +++ b/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) } diff --git a/repo/blob/rclone/rclone_storage_test.go b/repo/blob/rclone/rclone_storage_test.go index 5f89092c9..fff2b7ffd 100644 --- a/repo/blob/rclone/rclone_storage_test.go +++ b/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) }) } diff --git a/repo/content/committed_content_index_cache_test.go b/repo/content/committed_content_index_cache_test.go index eb2ccb06f..82ce4502c 100644 --- a/repo/content/committed_content_index_cache_test.go +++ b/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) { diff --git a/repo/content/content_manager_test.go b/repo/content/content_manager_test.go index 1f62e2635..0fdd8997b 100644 --- a/repo/content/content_manager_test.go +++ b/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) diff --git a/repo/content/index_blob_manager_v0_test.go b/repo/content/index_blob_manager_v0_test.go index a6cb0bca0..754a5dad7 100644 --- a/repo/content/index_blob_manager_v0_test.go +++ b/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, diff --git a/repo/content/internal_logger.go b/repo/content/internal_logger.go index f5a3c9c2f..5918dfbd5 100644 --- a/repo/content/internal_logger.go +++ b/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: " ", diff --git a/repo/logging/broadcast.go b/repo/logging/broadcast.go index 3b448ee96..24df11c5b 100644 --- a/repo/logging/broadcast.go +++ b/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 { diff --git a/repo/logging/logging.go b/repo/logging/logging.go index 025bc62d9..f4c800d3a 100644 --- a/repo/logging/logging.go +++ 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{}) diff --git a/repo/logging/logging_test.go b/repo/logging/logging_test.go index 0681661c6..9d8dd721d 100644 --- a/repo/logging/logging_test.go +++ b/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() diff --git a/repo/logging/null_logger.go b/repo/logging/null_logger.go index 1f71fb06f..191f5b976 100644 --- a/repo/logging/null_logger.go +++ b/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{} diff --git a/repo/logging/prefix.go b/repo/logging/prefix.go index d73566613..e96bed838 100644 --- a/repo/logging/prefix.go +++ b/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...) diff --git a/repo/logging/printf_logger.go b/repo/logging/printf_logger.go index b3815dd19..e4b6f4ed9 100644 --- a/repo/logging/printf_logger.go +++ b/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 + "] "} } diff --git a/repo/maintenance/maintenance_safety_test.go b/repo/maintenance/maintenance_safety_test.go index 5edea4385..4e69516d9 100644 --- a/repo/maintenance/maintenance_safety_test.go +++ b/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() }, }) diff --git a/repo/open.go b/repo/open.go index 8efad4ed8..5e6e163cc 100644 --- a/repo/open.go +++ b/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 { diff --git a/tests/repository_stress_test/repository_stress_test.go b/tests/repository_stress_test/repository_stress_test.go index 4361cc8bf..aa19d34cf 100644 --- a/tests/repository_stress_test/repository_stress_test.go +++ b/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 {