From 4a47bc32106babaabec9e5a3544fe8592550ae79 Mon Sep 17 00:00:00 2001 From: Jarek Kowalski Date: Tue, 12 Oct 2021 22:52:24 -0700 Subject: [PATCH] logging: switched from go-logging to zap (#1376) This is much more efficient in terms of memory allocations and speeds up backup due to less GC pressure. Fixes #1345 --- cli/app.go | 7 +- cli/inproc.go | 4 +- go.mod | 4 +- go.sum | 8 +- htmlui/src/App.css | 6 +- internal/clock/now.go | 24 ++ internal/epoch/epoch_manager.go | 4 +- internal/gather/gather_write_buffer_chunk.go | 9 +- internal/listcache/listcache.go | 4 +- internal/logfile/logfile.go | 232 ++++++++++--------- internal/logfile/logfile_test.go | 101 ++++++++ internal/testlogging/ctx.go | 10 + internal/uitask/uitask.go | 5 + main.go | 8 +- repo/blob/sftp/sftp_storage.go | 2 +- repo/blob/sharded/sharded.go | 2 +- repo/content/committed_content_index.go | 6 +- repo/content/committed_read_manager.go | 41 ++-- repo/content/content_manager.go | 4 +- repo/content/internal_logger.go | 69 +++--- repo/logging/broadcast.go | 7 + repo/logging/logging.go | 1 + repo/logging/null_logger.go | 1 + repo/logging/prefix.go | 5 + repo/logging/printf_logger.go | 1 + repo/open.go | 2 +- repo/repository.go | 2 +- tests/testenv/cli_inproc_runner.go | 12 +- 28 files changed, 374 insertions(+), 207 deletions(-) create mode 100644 internal/logfile/logfile_test.go diff --git a/cli/app.go b/cli/app.go index 41a53cac4..4dd27ceeb 100644 --- a/cli/app.go +++ b/cli/app.go @@ -56,7 +56,7 @@ func (o *textOutput) stderr() io.Writer { return os.Stderr } - return o.svc.stderr() + return o.svc.Stderr() } func (o *textOutput) printStdout(msg string, args ...interface{}) { @@ -82,7 +82,7 @@ type appServices interface { getProgress() *cliProgress stdout() io.Writer - stderr() io.Writer + Stderr() io.Writer } type advancedAppServices interface { @@ -160,7 +160,8 @@ func (c *App) stdout() io.Writer { return c.stdoutWriter } -func (c *App) stderr() io.Writer { +// Stderr returns the stderr writer. +func (c *App) Stderr() io.Writer { return c.stderrWriter } diff --git a/cli/inproc.go b/cli/inproc.go index 82ec73d5e..d3f195560 100644 --- a/cli/inproc.go +++ b/cli/inproc.go @@ -12,9 +12,7 @@ // RunSubcommand executes the subcommand asynchronously in current process // with flags in an isolated CLI environment and returns standard output and standard error. -func (c *App) RunSubcommand(ctx context.Context, argsAndFlags []string) (stdout, stderr io.Reader, wait func() error, kill func()) { - kpapp := kingpin.New("test", "test") - +func (c *App) RunSubcommand(ctx context.Context, kpapp *kingpin.Application, argsAndFlags []string) (stdout, stderr io.Reader, wait func() error, kill func()) { stdoutReader, stdoutWriter := io.Pipe() stderrReader, stderrWriter := io.Pipe() diff --git a/go.mod b/go.mod index 18c2d731d..fe7ce882a 100644 --- a/go.mod +++ b/go.mod @@ -35,7 +35,6 @@ require ( github.com/minio/minio-go/v7 v7.0.14 github.com/minio/sha256-simd v1.0.0 // indirect github.com/natefinch/atomic v1.0.1 - github.com/op/go-logging v0.0.0-20160315200505-970db520ece7 github.com/pierrec/lz4 v2.6.1+incompatible github.com/pkg/errors v0.9.1 github.com/pkg/profile v1.6.0 @@ -51,6 +50,7 @@ require ( github.com/zalando/go-keyring v0.1.1 github.com/zeebo/blake3 v0.2.1 go.opencensus.io v0.23.0 + go.uber.org/zap v1.19.1 gocloud.dev v0.24.0 golang.org/x/crypto v0.0.0-20210921155107-089bfa567519 golang.org/x/exp v0.0.0-20210916165020-5cb4fee858ee @@ -105,6 +105,8 @@ require ( github.com/prometheus/procfs v0.7.3 // indirect github.com/prometheus/statsd_exporter v0.22.2 // indirect github.com/rs/xid v1.3.0 // indirect + go.uber.org/atomic v1.9.0 // indirect + go.uber.org/multierr v1.7.0 // indirect golang.org/x/text v0.3.7 // indirect golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1 // indirect google.golang.org/appengine v1.6.7 // indirect diff --git a/go.sum b/go.sum index f8142b85c..ac92372f0 100644 --- a/go.sum +++ b/go.sum @@ -170,6 +170,7 @@ github.com/aws/aws-sdk-go-v2/service/sts v1.7.0 h1:1at4e5P+lvHNl2nUktdM2/v+rpICg github.com/aws/aws-sdk-go-v2/service/sts v1.7.0/go.mod h1:0qcSMCyASQPN2sk/1KQLQ2Fh6yq8wm0HSDAimPhzCoM= github.com/aws/smithy-go v1.8.0 h1:AEwwwXQZtUwP5Mz506FeXXrKBe0jA8gVM+1gEcSRooc= github.com/aws/smithy-go v1.8.0/go.mod h1:SObp3lf9smib00L/v3U2eAKG8FyQ7iLrJnQiAmR5n+E= +github.com/benbjohnson/clock v1.1.0 h1:Q92kusRqC1XV2MjkWETPvjJVqKetz1OzxZB7mHJLju8= github.com/benbjohnson/clock v1.1.0/go.mod h1:J11/hYXuz8f4ySSvYwY0FKfm+ezbsZBKZxNJlLklBHA= github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973/go.mod h1:Dwedo/Wpr24TaqPxmxbtue+5NUziq4I4S80YR8gNf3Q= github.com/beorn7/perks v1.0.0/go.mod h1:KWe93zE9D1o94FZ5RNwFwVgaQK1VOXiVxmqh+CedLV8= @@ -556,7 +557,6 @@ github.com/olekukonko/tablewriter v0.0.0-20170122224234-a0225b3f23b5/go.mod h1:v github.com/onsi/ginkgo v1.6.0/go.mod h1:lLunBs/Ym6LB5Z9jYTR76FiuTmxDTDusOGeTQH+WWjE= github.com/onsi/ginkgo v1.7.0/go.mod h1:lLunBs/Ym6LB5Z9jYTR76FiuTmxDTDusOGeTQH+WWjE= github.com/onsi/gomega v1.4.3/go.mod h1:ex+gbHU/CVuBBDIJjb2X0qEXbFg53c61hWP/1CpauHY= -github.com/op/go-logging v0.0.0-20160315200505-970db520ece7 h1:lDH9UUVJtmYCjyT0CI4q8xvlXPxeZ0gYCVvWbmPlp88= github.com/op/go-logging v0.0.0-20160315200505-970db520ece7/go.mod h1:HzydrMdWErDVzsI23lYNej1Htcns9BCg93Dk0bBINWk= github.com/opentracing-contrib/go-observer v0.0.0-20170622124052-a52f23424492/go.mod h1:Ngi6UdF0k5OKD5t5wlmGhe/EDKPoUM3BXZSSfIuJbis= github.com/opentracing/basictracer-go v1.0.0/go.mod h1:QfBfYuafItcjQuMwinw9GhYKwFXS9KnPs5lxoYwgW74= @@ -716,12 +716,16 @@ go.uber.org/atomic v1.3.2/go.mod h1:gD2HeocX3+yG+ygLZcrzQJaqmWj9AIm7n08wl/qW/PE= go.uber.org/atomic v1.5.0/go.mod h1:sABNBOSYdrvTF6hTgEIbc7YasKWGhgEQZyfxyTvoXHQ= go.uber.org/atomic v1.6.0/go.mod h1:sABNBOSYdrvTF6hTgEIbc7YasKWGhgEQZyfxyTvoXHQ= go.uber.org/atomic v1.7.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc= +go.uber.org/atomic v1.9.0 h1:ECmE8Bn/WFTYwEW/bpKD3M8VtR/zQVbavAoalC1PYyE= go.uber.org/atomic v1.9.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc= go.uber.org/goleak v1.1.10/go.mod h1:8a7PlsEVH3e/a/GLqe5IIrQx6GzcnRmZEufDUTk4A7A= +go.uber.org/goleak v1.1.11-0.20210813005559-691160354723 h1:sHOAIxRGBp443oHZIPB+HsUGaksVCXVQENPxwTfQdH4= +go.uber.org/goleak v1.1.11-0.20210813005559-691160354723/go.mod h1:cwTWslyiVhfpKIDGSZEM2HlOvcqm+tG4zioyIeLoqMQ= go.uber.org/multierr v1.1.0/go.mod h1:wR5kodmAFQ0UK8QlbwjlSNy0Z68gJhDJUG5sjR94q/0= go.uber.org/multierr v1.3.0/go.mod h1:VgVr7evmIr6uPjLBxg28wmKNXyqE9akIJ5XnfpiKl+4= go.uber.org/multierr v1.5.0/go.mod h1:FeouvMocqHpRaaGuG9EjoKcStLC43Zu/fmqdUMPcKYU= go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU= +go.uber.org/multierr v1.7.0 h1:zaiO/rmgFjbmCXdSYJWQcdvOCsthmdaHfr3Gm2Kx4Ec= go.uber.org/multierr v1.7.0/go.mod h1:7EAYxJLBy9rStEaz58O2t4Uvip6FSURkq8/ppBp95ak= go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee/go.mod h1:vJERXedbb3MVM5f9Ejo0C68/HhF8uaILCdgjnY+goOA= go.uber.org/zap v1.10.0/go.mod h1:vwi/ZaCAaUcBkycHslxD9B2zi4UTXhF60s6SWpuDF0Q= @@ -729,6 +733,8 @@ go.uber.org/zap v1.13.0/go.mod h1:zwrFLgMcdUuIBviXEYEH1YKNaOBnKXsx2IPda5bBwHM= go.uber.org/zap v1.16.0/go.mod h1:MA8QOfq0BHJwdXa996Y4dYkAqRKB8/1K1QMMZVaNZjQ= go.uber.org/zap v1.18.1/go.mod h1:xg/QME4nWcxGxrpdeYfq7UvYrLh66cuVKdrbD1XF/NI= go.uber.org/zap v1.19.0/go.mod h1:xg/QME4nWcxGxrpdeYfq7UvYrLh66cuVKdrbD1XF/NI= +go.uber.org/zap v1.19.1 h1:ue41HOKd1vGURxrmeKIgELGb3jPW9DMUDGtsinblHwI= +go.uber.org/zap v1.19.1/go.mod h1:j3DNczoxDZroyBnOT1L/Q79cfUMGZxlv/9dzN7SM1rI= gocloud.dev v0.24.0 h1:cNtHD07zQQiv02OiwwDyVMuHmR7iQt2RLkzoAgz7wBs= gocloud.dev v0.24.0/go.mod h1:uA+als++iBX5ShuG4upQo/3Zoz49iIPlYUWHV5mM8w8= golang.org/x/crypto v0.0.0-20180904163835-0709b304e793/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4= diff --git a/htmlui/src/App.css b/htmlui/src/App.css index 1c0868049..960bb1b77 100644 --- a/htmlui/src/App.css +++ b/htmlui/src/App.css @@ -120,10 +120,8 @@ div.tab-body { .loglevel-0 { color: #444; } /* debug */ .loglevel-1 { color: black; } /* info */ -.loglevel-2 { color: blue; font-weight: bold; } /* notice */ -.loglevel-3 { color: rgb(169, 112, 5); font-weight: bold;} /* warning */ -.loglevel-4 { color: red; font-weight: bold; } /* error */ -.loglevel-5 { color: red; font-weight: bold; } /* fatal */ +.loglevel-2 { color: rgb(169, 112, 5); font-weight: bold;} /* warning */ +.loglevel-3 { color: red; font-weight: bold; } /* error */ .counter-badge { font-size: 90%; diff --git a/internal/clock/now.go b/internal/clock/now.go index c2a76a7bf..56355a91d 100644 --- a/internal/clock/now.go +++ b/internal/clock/now.go @@ -14,3 +14,27 @@ func Since(t time.Time) time.Duration { func Until(t time.Time) time.Duration { return t.Sub(Now()) } + +// LocalClock is a structure that implements zap.Clock that returns local clock timestamps. +type LocalClock struct{} + +// Now implements zap.Clock. +func (c LocalClock) Now() time.Time { return Now().Local() } + +// NewTicker implements zap.Clock. +func (c LocalClock) NewTicker(d time.Duration) *time.Ticker { return time.NewTicker(d) } + +// UTCClock is a structure that implements zap.Clock which returns UTC timestamps. +type UTCClock struct{} + +// Now implements zap.Clock. +func (c UTCClock) Now() time.Time { return Now().UTC() } + +// NewTicker implements zap.Clock. +func (c UTCClock) NewTicker(d time.Duration) *time.Ticker { return time.NewTicker(d) } + +// supported clock instances. +var ( + Local = LocalClock{} + UTC = UTCClock{} +) diff --git a/internal/epoch/epoch_manager.go b/internal/epoch/epoch_manager.go index a51969486..7f1ba64b4 100644 --- a/internal/epoch/epoch_manager.go +++ b/internal/epoch/epoch_manager.go @@ -836,9 +836,7 @@ func rangeCheckpointBlobPrefix(epoch1, epoch2 int) blob.ID { } // NewManager creates new epoch manager. -func NewManager(st blob.Storage, params Parameters, compactor CompactionFunc, sharedBaseLogger logging.Logger, timeNow func() time.Time) *Manager { - log := logging.WithPrefix("[epoch-manager] ", sharedBaseLogger) - +func NewManager(st blob.Storage, params Parameters, compactor CompactionFunc, log logging.Logger, timeNow func() time.Time) *Manager { return &Manager{ st: st, log: log, diff --git a/internal/gather/gather_write_buffer_chunk.go b/internal/gather/gather_write_buffer_chunk.go index 1b3a45d93..5ce4e6d17 100644 --- a/internal/gather/gather_write_buffer_chunk.go +++ b/internal/gather/gather_write_buffer_chunk.go @@ -137,20 +137,15 @@ func (a *chunkAllocator) dumpStats(ctx context.Context, prefix string) { a.mu.Lock() defer a.mu.Unlock() - method := log(ctx).Debugf - alive := a.allocated - a.freed - if alive > 0 { - method = log(ctx).Errorf - } - method("%v (%v) - allocated %v(%v) chunks freed %v alive %v max %v free list high water mark: %v", + log(ctx).Debugf("%v (%v) - allocated %v(%v) chunks freed %v alive %v max %v free list high water mark: %v", prefix, units.Base2Bytes(int64(a.chunkSize)), a.allocated, a.slicesAllocated, a.freed, alive, a.allocHighWaterMark, a.freeListHighWaterMark) for _, v := range a.activeChunks { - method("leaked chunk from %v", v) + log(ctx).Debugf("leaked chunk from %v", v) } if trackChunkAllocations && len(a.activeChunks) > 0 { diff --git a/internal/listcache/listcache.go b/internal/listcache/listcache.go index fe3d6566c..0778320b9 100644 --- a/internal/listcache/listcache.go +++ b/internal/listcache/listcache.go @@ -64,12 +64,12 @@ func (s *listCacheStorage) readBlobsFromCache(ctx context.Context, prefix blob.I defer verified.Close() if err := hmac.VerifyAndStrip(data.Bytes(), s.hmacSecret, &verified); err != nil { - log(ctx).Debugf("warning: invalid list cache HMAC for %v, ignoring", prefix) + log(ctx).Warnf("invalid list cache HMAC for %v, ignoring", prefix) return nil } if err := json.NewDecoder(verified.Bytes().Reader()).Decode(&cl); err != nil { - log(ctx).Debugf("warning: cant't unmarshal cached list results for %v, ignoring", prefix) + log(ctx).Warnf("cant't unmarshal cached list results for %v, ignoring", prefix) return nil } diff --git a/internal/logfile/logfile.go b/internal/logfile/logfile.go index a172c5735..def4c1f07 100644 --- a/internal/logfile/logfile.go +++ b/internal/logfile/logfile.go @@ -15,24 +15,18 @@ "github.com/alecthomas/kingpin" "github.com/fatih/color" - logging "github.com/op/go-logging" - "github.com/pkg/errors" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "github.com/kopia/kopia/cli" "github.com/kopia/kopia/internal/clock" "github.com/kopia/kopia/internal/ospath" "github.com/kopia/kopia/repo/content" - repologging "github.com/kopia/kopia/repo/logging" + "github.com/kopia/kopia/repo/logging" ) const logsDirMode = 0o700 -var contentLogFormat = logging.MustStringFormatter( - `%{time:2006-01-02 15:04:05.000000} %{message}`) - -var fileLogFormat = logging.MustStringFormatter( - `%{time:2006-01-02 15:04:05.000000} %{level:.1s} [%{shortfile}] %{message}`) - -// warning is for backwards compatibility, same as error. var logLevels = []string{"debug", "info", "warning", "error"} type loggingFlags struct { @@ -49,9 +43,11 @@ type loggingFlags struct { forceColor bool disableColor bool consoleLogTimestamps bool + + cliApp *cli.App } -func (c *loggingFlags) setup(app *kingpin.Application) { +func (c *loggingFlags) setup(cliApp *cli.App, app *kingpin.Application) { app.Flag("log-file", "Override log file.").StringVar(&c.logFile) app.Flag("content-log-file", "Override content log file.").Hidden().StringVar(&c.contentLogFile) @@ -68,15 +64,16 @@ func (c *loggingFlags) setup(app *kingpin.Application) { app.Flag("console-timestamps", "Log timestamps to stderr.").Hidden().Default("false").Envar("KOPIA_CONSOLE_TIMESTAMPS").BoolVar(&c.consoleLogTimestamps) app.PreAction(c.initialize) + c.cliApp = cliApp } // Attach attaches logging flags to the provided application. -func Attach(app *kingpin.Application) { +func Attach(cliApp *cli.App, app *kingpin.Application) { lf := &loggingFlags{} - lf.setup(app) + lf.setup(cliApp, app) } -var log = repologging.Module("kopia") +var log = logging.Module("kopia") const ( logFileNamePrefix = "kopia-" @@ -101,14 +98,30 @@ func (c *loggingFlags) initialize(ctx *kingpin.ParseContext) error { suffix = strings.ReplaceAll(c.FullCommand(), " ", "-") } - // activate backends - logging.SetBackend( - multiLogger{ - c.setupConsoleBackend(), - c.setupLogFileBackend(now, suffix), - c.setupContentLogFileBackend(now, suffix), - }, - ) + // First, define our level-handling logic. + + var clockOption zap.Option + + if c.fileLogLocalTimezone { + clockOption = zap.WithClock(clock.Local) + } else { + clockOption = zap.WithClock(clock.UTC) + } + + rootLogger := zap.New(zapcore.NewTee( + c.setupConsoleCore(), + c.setupLogFileCore(now, suffix), + ), clockOption) + + contentLogger := zap.New(c.setupContentLogFileBackend(now, suffix), clockOption).Sugar() + + c.cliApp.SetLoggerFactory(func(module string) logging.Logger { + if module == content.FormatLogModule { + return contentLogger + } + + return rootLogger.Named(module).Sugar() + }) if c.forceColor { color.NoColor = false @@ -121,52 +134,45 @@ func (c *loggingFlags) initialize(ctx *kingpin.ParseContext) error { return nil } -type multiLogger []logging.Backend - -func (m multiLogger) Log(l logging.Level, calldepth int, rec *logging.Record) error { - // use clock.Now() which can be overridden in e2e tests. - rec.Time = clock.Now() - - for _, child := range m { - // Shallow copy of the record for the formatted cache on Record and get the - // record formatter from the backend. - r2 := *rec - child.Log(l, calldepth, &r2) //nolint:errcheck +func (c *loggingFlags) setupConsoleCore() zapcore.Core { + ec := zapcore.EncoderConfig{ + LevelKey: "L", + MessageKey: "M", + LineEnding: zapcore.DefaultLineEnding, + EncodeTime: zapcore.RFC3339NanoTimeEncoder, + EncodeDuration: zapcore.StringDurationEncoder, + EncodeCaller: zapcore.ShortCallerEncoder, + ConsoleSeparator: " ", } - return nil -} + if c.consoleLogTimestamps { + ec.TimeKey = "T" + ec.EncodeTime = zapcore.TimeEncoderOfLayout("15:04:05.000") + } -func (c *loggingFlags) setupConsoleBackend() logging.Backend { - var ( - prefix = "%{color}" - suffix = "%{message}%{color:reset}" - maybeTimestamp = "%{time:15:04:05.000} " + 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) + } + } + + consoleFormat := zapcore.NewConsoleEncoder(ec) + + return zapcore.NewCore( + consoleFormat, + zapcore.AddSync(c.cliApp.Stderr()), + logLevelFromFlag(c.logLevel), ) - - if c.disableColor { - prefix = "" - suffix = "%{message}" - } - - if !c.consoleLogTimestamps { - maybeTimestamp = "" - } - - l := logging.AddModuleLevel(logging.NewBackendFormatter( - logging.NewLogBackend(os.Stderr, "", 0), - logging.MustStringFormatter(prefix+maybeTimestamp+suffix))) - - // do not output content logs to the console - l.SetLevel(logging.CRITICAL, content.FormatLogModule) - - // log everything else at a level specified using --log-level - l.SetLevel(logLevelFromFlag(c.logLevel), "") - - return l } -func (c *loggingFlags) setupLogFileBasedLogger(now time.Time, subdir, suffix, logFileOverride string, maxFiles int, maxAge time.Duration) logging.Backend { +func (c *loggingFlags) setupLogFileBasedLogger(now time.Time, subdir, suffix, logFileOverride string, maxFiles int, maxAge time.Duration) zapcore.WriteSyncer { var logFileName, symlinkName string if logFileOverride != "" { @@ -196,42 +202,43 @@ func (c *loggingFlags) setupLogFileBasedLogger(now time.Time, subdir, suffix, lo go sweepLogDir(context.TODO(), logDir, maxFiles, maxAge) } - return &onDemandBackend{ + return &onDemandFile{ logDir: logDir, logFileBaseName: logFileBaseName, symlinkName: symlinkName, - utc: !c.fileLogLocalTimezone, } } -func (c *loggingFlags) setupLogFileBackend(now time.Time, suffix string) logging.Backend { - l := logging.AddModuleLevel( - logging.NewBackendFormatter( - c.setupLogFileBasedLogger(now, "cli-logs", suffix, c.logFile, c.logDirMaxFiles, c.logDirMaxAge), - fileLogFormat)) - - // do not output content logs to the regular log file - l.SetLevel(logging.CRITICAL, content.FormatLogModule) - - // log everything else at a level specified using --file-level - l.SetLevel(logLevelFromFlag(c.fileLogLevel), "") - - return l +func (c *loggingFlags) setupLogFileCore(now time.Time, suffix string) zapcore.Core { + return zapcore.NewCore( + zapcore.NewConsoleEncoder(zapcore.EncoderConfig{ + TimeKey: "t", + MessageKey: "msg", + NameKey: "logger", + LevelKey: "lvl", + EncodeName: zapcore.FullNameEncoder, + EncodeLevel: zapcore.CapitalLevelEncoder, + EncodeTime: zapcore.TimeEncoderOfLayout("2006-01-02T15:04:05.000000Z07:00"), + EncodeDuration: zapcore.StringDurationEncoder, + ConsoleSeparator: " ", + }), + c.setupLogFileBasedLogger(now, "cli-logs", suffix, c.logFile, c.logDirMaxFiles, c.logDirMaxAge), + logLevelFromFlag(c.fileLogLevel), + ) } -func (c *loggingFlags) setupContentLogFileBackend(now time.Time, suffix string) logging.Backend { - l := logging.AddModuleLevel( - logging.NewBackendFormatter( - c.setupLogFileBasedLogger(now, "content-logs", suffix, c.contentLogFile, c.contentLogDirMaxFiles, c.contentLogDirMaxAge), - contentLogFormat)) - - // only log content entries - l.SetLevel(logging.DEBUG, content.FormatLogModule) - - // do not log anything else - l.SetLevel(logging.CRITICAL, "") - - return l +func (c *loggingFlags) setupContentLogFileBackend(now time.Time, suffix string) zapcore.Core { + return zapcore.NewCore( + zapcore.NewConsoleEncoder(zapcore.EncoderConfig{ + TimeKey: "t", + MessageKey: "msg", + NameKey: "logger", + EncodeTime: zapcore.TimeEncoderOfLayout("2006-01-02T15:04:05.000000Z07:00"), + EncodeDuration: zapcore.StringDurationEncoder, + ConsoleSeparator: " ", + }), + c.setupLogFileBasedLogger(now, "content-logs", suffix, c.contentLogFile, c.contentLogDirMaxFiles, c.contentLogDirMaxAge), + zap.DebugLevel) } func shouldSweepLog(maxFiles int, maxAge time.Duration) bool { @@ -279,32 +286,41 @@ func sweepLogDir(ctx context.Context, dirname string, maxCount int, maxAge time. } } -func logLevelFromFlag(levelString string) logging.Level { +func logLevelFromFlag(levelString string) zapcore.LevelEnabler { switch levelString { case "debug": - return logging.DEBUG + return zap.DebugLevel case "info": - return logging.INFO + return zap.InfoLevel case "warning": - return logging.WARNING + return zap.WarnLevel case "error": - return logging.ERROR + return zap.ErrorLevel default: - return logging.CRITICAL + return zap.FatalLevel } } -type onDemandBackend struct { +type onDemandFile struct { logDir string logFileBaseName string symlinkName string - utc bool - backend logging.Backend - once sync.Once + f *os.File + + once sync.Once } -func (w *onDemandBackend) Log(level logging.Level, depth int, rec *logging.Record) error { +func (w *onDemandFile) Sync() error { + if w.f == nil { + return nil + } + + // nolint:wrapcheck + return w.f.Sync() +} + +func (w *onDemandFile) Write(b []byte) (int, error) { w.once.Do(func() { lf := filepath.Join(w.logDir, w.logFileBaseName) f, err := os.Create(lf) @@ -313,7 +329,7 @@ func (w *onDemandBackend) Log(level logging.Level, depth int, rec *logging.Recor return } - w.backend = logging.NewLogBackend(f, "", 0) + w.f = f if w.symlinkName != "" { symlink := filepath.Join(w.logDir, w.symlinkName) @@ -322,16 +338,10 @@ func (w *onDemandBackend) Log(level logging.Level, depth int, rec *logging.Recor } }) - if w.backend == nil { - return errors.New("no backend") - } - - if w.utc { - rec.Time = rec.Time.UTC() - } else { - rec.Time = rec.Time.Local() + if w.f == nil { + return 0, nil } // nolint:wrapcheck - return w.backend.Log(level, depth+1, rec) + return w.f.Write(b) } diff --git a/internal/logfile/logfile_test.go b/internal/logfile/logfile_test.go new file mode 100644 index 000000000..c1223a52d --- /dev/null +++ b/internal/logfile/logfile_test.go @@ -0,0 +1,101 @@ +package logfile_test + +import ( + "bufio" + "os" + "path/filepath" + "regexp" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/require" + + "github.com/kopia/kopia/internal/logfile" + "github.com/kopia/kopia/internal/testutil" + "github.com/kopia/kopia/tests/testenv" +) + +var ( + cliLogFormat = regexp.MustCompile(`^\d{4}-\d\d\-\d\dT\d\d:\d\d:\d\d\.\d{6}Z (DEBUG|INFO) [a-z/]+ .*$`) + contentLogFormat = regexp.MustCompile(`^\d{4}-\d\d\-\d\dT\d\d:\d\d:\d\d\.\d{6}Z .*$`) +) + +func TestLoggingFlags(t *testing.T) { + runner := testenv.NewInProcRunner(t) + runner.CustomizeApp = logfile.Attach + + env := testenv.NewCLITest(t, testenv.RepoFormatNotImportant, runner) + env.RunAndExpectSuccess(t, "repo", "create", "filesystem", "--path", env.RepoDir) + + dir1 := testutil.TempDirectory(t) + + tmpLogDir := testutil.TempDirectory(t) + + // run command that produces a mix of debug and info logs. + _, stderr, err := env.Run(t, false, "snap", "create", dir1, + "--console-timestamps", "--no-progress", "--log-level=debug", "--force-color", + "--no-auto-maintenance", "--log-dir", tmpLogDir) + require.NoError(t, err) + + for _, l := range stderr { + require.NotContains(t, l, "INFO") // INFO is omitted + + if strings.Contains(l, "DEBUG") { + require.Contains(t, l, "\x1b[35mDEBUG\x1b") + } + + // make sure each line is prefixed with a timestamp. + _, perr := time.Parse("15:04:05.000 ", strings.Split(l, " ")[0]) + require.NoError(t, perr) + } + + verifyFileLogFormat(t, filepath.Join(tmpLogDir, "cli-logs", "latest.log"), cliLogFormat) + verifyFileLogFormat(t, filepath.Join(tmpLogDir, "content-logs", "latest.log"), contentLogFormat) + + _, stderr, err = env.Run(t, false, "snap", "create", dir1, + "--file-log-local-tz", "--no-progress", "--log-level=debug", "--disable-color", + "--no-auto-maintenance", "--log-dir", tmpLogDir) + require.NoError(t, err) + + for _, l := range stderr { + require.NotContains(t, l, "INFO") // INFO is omitted + + if strings.Contains(l, "DEBUG") { + require.NotContains(t, l, "\x1b[35mDEBUG") + } + + // make sure each line is NOT prefixed with a timestamp. + _, perr := time.Parse("15:04:05.000 ", strings.Split(l, " ")[0]) + require.Error(t, perr) + } + + // run command with --log-level=warning so no log error is produced on the console + _, stderr, err = env.Run(t, false, "snap", "create", dir1, + "--no-progress", "--log-level=warning", + "--no-auto-maintenance", "--log-dir", tmpLogDir) + require.NoError(t, err) + require.Empty(t, stderr) + + // run command with --log-level=error so no log error is produced on the console + _, stderr, err = env.Run(t, false, "snap", "create", dir1, + "--no-progress", "--log-level=error", + "--no-auto-maintenance", "--log-dir", tmpLogDir) + require.NoError(t, err) + require.Empty(t, stderr) +} + +func verifyFileLogFormat(t *testing.T, fname string, re *regexp.Regexp) { + t.Helper() + + f, err := os.Open(fname) + require.NoError(t, err) + + defer f.Close() + + s := bufio.NewScanner(f) + + for s.Scan() { + require.True(t, re.MatchString(s.Text()), "log line does not match the format: %v", s.Text()) + } +} diff --git a/internal/testlogging/ctx.go b/internal/testlogging/ctx.go index 376936bc8..d97426f44 100644 --- a/internal/testlogging/ctx.go +++ b/internal/testlogging/ctx.go @@ -22,6 +22,7 @@ type testingT interface { const ( LevelDebug Level = iota LevelInfo + LevelWarn LevelError ) @@ -49,6 +50,15 @@ func (l *testLogger) Infof(msg string, args ...interface{}) { l.t.Logf(l.prefix+msg, args...) } +func (l *testLogger) Warnf(msg string, args ...interface{}) { + if l.minLevel > LevelWarn { + return + } + + l.t.Helper() + l.t.Logf(l.prefix+msg, args...) +} + func (l *testLogger) Errorf(msg string, args ...interface{}) { if l.minLevel > LevelError { return diff --git a/internal/uitask/uitask.go b/internal/uitask/uitask.go index ecd8e2f10..1ee0ad84d 100644 --- a/internal/uitask/uitask.go +++ b/internal/uitask/uitask.go @@ -40,6 +40,7 @@ func (s Status) IsFinished() bool { const ( LogLevelDebug LogLevel = iota LogLevelInfo + LogLevelWarning LogLevelError ) @@ -180,6 +181,10 @@ func (l runningTaskLogger) Infof(msg string, args ...interface{}) { l.r.addLogEntry(l.module, LogLevelInfo, msg, args) } +func (l runningTaskLogger) Warnf(msg string, args ...interface{}) { + l.r.addLogEntry(l.module, LogLevelWarning, msg, args) +} + func (l runningTaskLogger) Errorf(msg string, args ...interface{}) { l.r.addLogEntry(l.module, LogLevelError, msg, args) } diff --git a/main.go b/main.go index acaf3edfe..adc5f51f9 100644 --- a/main.go +++ b/main.go @@ -13,12 +13,10 @@ "os" "github.com/alecthomas/kingpin" - gologging "github.com/op/go-logging" "github.com/kopia/kopia/cli" "github.com/kopia/kopia/internal/logfile" "github.com/kopia/kopia/repo" - "github.com/kopia/kopia/repo/logging" ) const usageTemplate = `{{define "FormatCommand"}}\ @@ -69,12 +67,8 @@ func main() { app := cli.NewApp() kp := kingpin.New("kopia", "Kopia - Fast And Secure Open-Source Backup").Author("http://kopia.github.io/") - app.SetLoggerFactory(func(module string) logging.Logger { - return gologging.MustGetLogger(module) - }) - kp.Version(repo.BuildVersion + " build: " + repo.BuildInfo + " from: " + repo.BuildGitHubRepo) - logfile.Attach(kp) + logfile.Attach(app, kp) kp.ErrorWriter(os.Stderr) kp.UsageWriter(os.Stdout) kp.UsageTemplate(usageTemplate) diff --git a/repo/blob/sftp/sftp_storage.go b/repo/blob/sftp/sftp_storage.go index a549fbd02..38af9fad6 100644 --- a/repo/blob/sftp/sftp_storage.go +++ b/repo/blob/sftp/sftp_storage.go @@ -199,7 +199,7 @@ func (s *sftpImpl) PutBlobInPath(ctx context.Context, dirPath, fullPath string, err = sftpClientFromConnection(conn).PosixRename(tempFile, fullPath) if err != nil { if removeErr := sftpClientFromConnection(conn).Remove(tempFile); removeErr != nil { - log(ctx).Errorf("warning: can't remove temp file: %v", removeErr) + log(ctx).Warnf("can't remove temp file: %v", removeErr) } return errors.Wrap(err, "unexpected error renaming file on SFTP") diff --git a/repo/blob/sharded/sharded.go b/repo/blob/sharded/sharded.go index 5eba67705..d25519191 100644 --- a/repo/blob/sharded/sharded.go +++ b/repo/blob/sharded/sharded.go @@ -241,7 +241,7 @@ func (s *Storage) getParameters(ctx context.Context) (*Parameters, error) { } if err := s.Impl.PutBlobInPath(ctx, s.RootPath, dotShardsFile, tmp.Bytes()); err != nil { - log(ctx).Errorf("warning: unable to persist sharding parameters: %v", err) + log(ctx).Warnf("unable to persist sharding parameters: %v", err) } } else { par := &Parameters{} diff --git a/repo/content/committed_content_index.go b/repo/content/committed_content_index.go index 8e15071f8..4e689c220 100644 --- a/repo/content/committed_content_index.go +++ b/repo/content/committed_content_index.go @@ -324,10 +324,8 @@ func newCommittedContentIndex(caching *CachingOptions, v1PerContentOverhead uint32, indexVersion int, fetchOne func(ctx context.Context, blobID blob.ID, output *gather.WriteBuffer) error, - baseLog logging.Logger, + log logging.Logger, ) *committedContentIndex { - log := logging.WithPrefix("[committed-content-index] ", baseLog) - var cache committedContentIndexCache if caching.CacheDirectory != "" { @@ -346,6 +344,6 @@ func newCommittedContentIndex(caching *CachingOptions, v1PerContentOverhead: v1PerContentOverhead, indexVersion: indexVersion, fetchOne: fetchOne, - log: baseLog, + log: log, } } diff --git a/repo/content/committed_read_manager.go b/repo/content/committed_read_manager.go index 51dc76016..ac9791875 100644 --- a/repo/content/committed_read_manager.go +++ b/repo/content/committed_read_manager.go @@ -9,6 +9,7 @@ "time" "github.com/pkg/errors" + "go.uber.org/zap" "github.com/kopia/kopia/internal/cache" "github.com/kopia/kopia/internal/clock" @@ -98,11 +99,10 @@ type SharedManager struct { // logger where logs should be written log logging.Logger - // base logger used by other related components with their own prefixes, - // do not log there directly. - sharedBaseLogger logging.Logger + // logger associated with the context that opened the repository. + contextLogger logging.Logger internalLogManager *internalLogManager - internalLogger *internalLogger // backing logger for 'sharedBaseLogger' + internalLogger *zap.SugaredLogger // backing logger for 'sharedBaseLogger' } // Crypter returns the crypter. @@ -346,6 +346,14 @@ func newCacheBackingStorage(ctx context.Context, caching *CachingOptions, subdir }) } +func (sm *SharedManager) namedLogger(n string) logging.Logger { + if sm.internalLogger != nil { + return logging.Broadcast{sm.contextLogger, sm.internalLogger.Named("[" + n + "]")} + } + + return sm.contextLogger +} + func (sm *SharedManager) setupReadManagerCaches(ctx context.Context, caching *CachingOptions) error { dataCacheStorage, err := cache.NewStorageOrNil(ctx, caching.CacheDirectory, caching.MaxCacheSizeBytes, "contents") if err != nil { @@ -386,7 +394,7 @@ func (sm *SharedManager) setupReadManagerCaches(ctx context.Context, caching *Ca st: cachedSt, crypter: sm.crypter, indexBlobCache: metadataCache, - log: logging.WithPrefix("[encrypted-blob-manager] ", sm.sharedBaseLogger), + log: sm.namedLogger("encrypted-blob-manager"), } // set up legacy index blob manager @@ -397,7 +405,7 @@ func (sm *SharedManager) setupReadManagerCaches(ctx context.Context, caching *Ca maxPackSize: sm.maxPackSize, indexVersion: sm.indexVersion, indexShardSize: sm.indexShardSize, - log: logging.WithPrefix("[index-blob-manager] ", sm.sharedBaseLogger), + log: sm.namedLogger("index-blob-manager"), } // set up new index blob manager @@ -408,9 +416,9 @@ func (sm *SharedManager) setupReadManagerCaches(ctx context.Context, caching *Ca maxPackSize: sm.maxPackSize, indexShardSize: sm.indexShardSize, indexVersion: sm.indexVersion, - log: logging.WithPrefix("[index-blob-manager] ", sm.sharedBaseLogger), + log: sm.namedLogger("index-blob-manager"), } - sm.indexBlobManagerV1.epochMgr = epoch.NewManager(cachedSt, sm.format.EpochParameters, sm.indexBlobManagerV1.compactEpoch, sm.sharedBaseLogger, sm.timeNow) + sm.indexBlobManagerV1.epochMgr = epoch.NewManager(cachedSt, sm.format.EpochParameters, sm.indexBlobManagerV1.compactEpoch, sm.namedLogger("epoch-manager"), sm.timeNow) // select active index blob manager based on parameters if sm.format.EpochParameters.Enabled { @@ -422,7 +430,7 @@ func (sm *SharedManager) setupReadManagerCaches(ctx context.Context, caching *Ca // once everything is ready, set it up sm.contentCache = dataCache sm.metadataCache = metadataCache - sm.committedContents = newCommittedContentIndex(caching, uint32(sm.crypter.Encryptor.Overhead()), sm.indexVersion, sm.enc.getEncryptedBlob, sm.sharedBaseLogger) + sm.committedContents = newCommittedContentIndex(caching, uint32(sm.crypter.Encryptor.Overhead()), sm.indexVersion, sm.enc.getEncryptedBlob, sm.namedLogger("committed-content-index")) return nil } @@ -472,7 +480,7 @@ func (sm *SharedManager) release(ctx context.Context) error { sm.metadataCache.close(ctx) if sm.internalLogger != nil { - sm.internalLogger.Close(ctx) + sm.internalLogger.Sync() // nolint:errcheck } sm.internalLogManager.Close(ctx) @@ -528,14 +536,11 @@ func NewSharedManager(ctx context.Context, st blob.Storage, f *FormattingOptions // sharedBaseLogger writes to the both context and internal log // and is used as a base for all content manager components. - var internalLog *internalLogger + var internalLog *zap.SugaredLogger // capture logger (usually console or log file) associated with current context. - sharedBaseLogger := logging.Module(FormatLogModule)(ctx) - if !opts.DisableInternalLog { internalLog = ilm.NewLogger() - sharedBaseLogger = logging.Broadcast{sharedBaseLogger, internalLog} } sm := &SharedManager{ @@ -555,12 +560,12 @@ func NewSharedManager(ctx context.Context, st blob.Storage, f *FormattingOptions indexShardSize: defaultIndexShardSize, internalLogManager: ilm, internalLogger: internalLog, - sharedBaseLogger: sharedBaseLogger, - - // remember logger defined for the context. - log: logging.WithPrefix("[shared-manager] ", sharedBaseLogger), + contextLogger: logging.Module(FormatLogModule)(ctx), } + // remember logger defined for the context. + sm.log = sm.namedLogger("shared-manager") + caching = caching.CloneOrDefault() if err := sm.setupReadManagerCaches(ctx, caching); err != nil { diff --git a/repo/content/content_manager.go b/repo/content/content_manager.go index ded8cec05..05fa6b646 100644 --- a/repo/content/content_manager.go +++ b/repo/content/content_manager.go @@ -634,7 +634,7 @@ func (bm *WriteManager) getOrCreatePendingPackInfoLocked(ctx context.Context, pr return pp, nil } - bm.internalLogger.enable() + bm.internalLogManager.enable() b := gather.NewWriteBuffer() @@ -877,6 +877,6 @@ func NewWriteManager(ctx context.Context, sm *SharedManager, options SessionOpti sessionHost: options.SessionHost, onUpload: options.OnUpload, - log: logging.WithPrefix(writeManagerID, sm.sharedBaseLogger), + log: sm.namedLogger(writeManagerID), } } diff --git a/repo/content/internal_logger.go b/repo/content/internal_logger.go index 7d5f1f582..37af3d57d 100644 --- a/repo/content/internal_logger.go +++ b/repo/content/internal_logger.go @@ -6,11 +6,13 @@ "crypto/rand" "fmt" "io" - "strings" "sync" "sync/atomic" "time" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "github.com/kopia/kopia/internal/clock" "github.com/kopia/kopia/internal/gather" "github.com/kopia/kopia/repo/blob" @@ -22,6 +24,8 @@ const TextLogBlobPrefix = "_log_" type internalLogManager struct { + enabled int32 // set by enable(), logger is ineffective until called + ctx context.Context st blob.Storage bc *Crypter @@ -64,22 +68,32 @@ func (m *internalLogManager) encryptAndWriteLogBlob(prefix blob.ID, data gather. } // NewLogger creates new logger. -func (m *internalLogManager) NewLogger() *internalLogger { +func (m *internalLogManager) NewLogger() *zap.SugaredLogger { var rnd [2]byte rand.Read(rnd[:]) // nolint:errcheck - return &internalLogger{ + w := &internalLogger{ m: m, prefix: blob.ID(fmt.Sprintf("%v%v_%x", TextLogBlobPrefix, clock.Now().Local().Format("20060102150405"), rnd)), } + + return zap.New(zapcore.NewCore( + zapcore.NewConsoleEncoder(zapcore.EncoderConfig{ + TimeKey: "t", + MessageKey: "msg", + NameKey: "logger", + EncodeTime: zapcore.TimeEncoderOfLayout("2006-01-02T15:04:05.000000Z07:00"), + EncodeDuration: zapcore.StringDurationEncoder, + ConsoleSeparator: " ", + }), + w, zap.DebugLevel), zap.WithClock(clock.UTC)).Sugar() } // internalLogger represents a single log session that saves log files as blobs in the repository. // The logger starts disabled and to actually persist logs enable() must be called. type internalLogger struct { nextChunkNumber int32 // chunk number incremented using atomic.AddInt32() - enabled int32 // set by enable(), logger is ineffective until called m *internalLogManager mu sync.Mutex @@ -89,32 +103,17 @@ type internalLogger struct { prefix blob.ID } -func (l *internalLogger) enable() { - if l == nil { +func (m *internalLogManager) enable() { + if m == nil { return } - atomic.StoreInt32(&l.enabled, 1) + atomic.StoreInt32(&m.enabled, 1) } -// Close closes the log session and saves any pending log. -func (l *internalLogger) Close(ctx context.Context) { - l.mu.Lock() - data, closeFunc := l.flushAndResetLocked() - l.mu.Unlock() - - l.maybeEncryptAndWriteChunkUnlocked(data, closeFunc) -} - -func (l *internalLogger) nowString() string { - return l.m.timeFunc().UTC().Format("2006-01-02T15:04:05.000000Z") -} - -func (l *internalLogger) add(level, msg string, args []interface{}) { - prefix := l.nowString() + " " + level + " " - line := strings.TrimSpace(fmt.Sprintf(prefix+msg, args...)) + "\n" - - l.maybeEncryptAndWriteChunkUnlocked(l.addLineAndMaybeFlush(line)) +func (l *internalLogger) Write(b []byte) (int, error) { + l.maybeEncryptAndWriteChunkUnlocked(l.addAndMaybeFlush(b)) + return len(b), nil } func (l *internalLogger) maybeEncryptAndWriteChunkUnlocked(data gather.Bytes, closeFunc func()) { @@ -123,7 +122,7 @@ func (l *internalLogger) maybeEncryptAndWriteChunkUnlocked(data gather.Bytes, cl return } - if atomic.LoadInt32(&l.enabled) == 0 { + if atomic.LoadInt32(&l.m.enabled) == 0 { closeFunc() return } @@ -137,13 +136,13 @@ func (l *internalLogger) maybeEncryptAndWriteChunkUnlocked(data gather.Bytes, cl l.m.encryptAndWriteLogBlob(prefix, data, closeFunc) } -func (l *internalLogger) addLineAndMaybeFlush(line string) (payload gather.Bytes, closeFunc func()) { +func (l *internalLogger) addAndMaybeFlush(b []byte) (payload gather.Bytes, closeFunc func()) { l.mu.Lock() defer l.mu.Unlock() w := l.ensureWriterInitializedLocked() - _, err := io.WriteString(w, line) + _, err := w.Write(b) l.logUnexpectedError(err) if l.buf.Length() < l.m.flushThreshold { @@ -186,16 +185,14 @@ func (l *internalLogger) logUnexpectedError(err error) { } } -func (l *internalLogger) Debugf(msg string, args ...interface{}) { - l.add("DEBUG", msg, args) -} +func (l *internalLogger) Sync() error { + l.mu.Lock() + data, closeFunc := l.flushAndResetLocked() + l.mu.Unlock() -func (l *internalLogger) Infof(msg string, args ...interface{}) { - l.add("INFO", msg, args) -} + l.maybeEncryptAndWriteChunkUnlocked(data, closeFunc) -func (l *internalLogger) Errorf(msg string, args ...interface{}) { - l.add("ERROR", msg, args) + return nil } // newInternalLogManager creates a new blobLogManager that will emit logs as repository blobs with a given prefix. diff --git a/repo/logging/broadcast.go b/repo/logging/broadcast.go index 58a504b9a..3b448ee96 100644 --- a/repo/logging/broadcast.go +++ b/repo/logging/broadcast.go @@ -17,6 +17,13 @@ func (b Broadcast) Infof(msg string, args ...interface{}) { } } +// Warnf implements Logger. +func (b Broadcast) Warnf(msg string, args ...interface{}) { + for _, l := range b { + l.Warnf(msg, args...) + } +} + // Errorf implements Logger. func (b Broadcast) Errorf(msg string, args ...interface{}) { for _, l := range b { diff --git a/repo/logging/logging.go b/repo/logging/logging.go index 78118a5a6..025bc62d9 100644 --- a/repo/logging/logging.go +++ b/repo/logging/logging.go @@ -12,6 +12,7 @@ type Logger interface { Debugf(msg string, args ...interface{}) Infof(msg string, args ...interface{}) + Warnf(msg string, args ...interface{}) Errorf(msg string, args ...interface{}) } diff --git a/repo/logging/null_logger.go b/repo/logging/null_logger.go index ff96e740c..1f71fb06f 100644 --- a/repo/logging/null_logger.go +++ b/repo/logging/null_logger.go @@ -4,6 +4,7 @@ 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{}) {} var nullLoggerInstance = nullLogger{} diff --git a/repo/logging/prefix.go b/repo/logging/prefix.go index 52da50734..d73566613 100644 --- a/repo/logging/prefix.go +++ b/repo/logging/prefix.go @@ -16,6 +16,11 @@ func (p *prefixLogger) Infof(msg string, args ...interface{}) { p.inner.Infof(p.prefixFunc()+msg, args...) } +// Warnf implements Logger. +func (p *prefixLogger) Warnf(msg string, args ...interface{}) { + p.inner.Warnf(p.prefixFunc()+msg, args...) +} + // Errorf implements Logger. func (p *prefixLogger) Errorf(msg string, args ...interface{}) { p.inner.Errorf(p.prefixFunc()+msg, args...) diff --git a/repo/logging/printf_logger.go b/repo/logging/printf_logger.go index b91815bde..b3815dd19 100644 --- a/repo/logging/printf_logger.go +++ b/repo/logging/printf_logger.go @@ -13,6 +13,7 @@ type printfLogger struct { func (l *printfLogger) Debugf(msg string, args ...interface{}) { l.printf(l.prefix+msg, args...) } 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. diff --git a/repo/open.go b/repo/open.go index 94e2571ba..c5fdd576a 100644 --- a/repo/open.go +++ b/repo/open.go @@ -355,7 +355,7 @@ func readAndCacheFormatBlobBytes(ctx context.Context, st blob.Storage, cacheDire if cacheEnabled { if err := atomicfile.Write(cachedFile, b.Bytes().Reader()); err != nil { - log(ctx).Errorf("warning: unable to write cache: %v", err) + log(ctx).Warnf("unable to write cache: %v", err) } } diff --git a/repo/repository.go b/repo/repository.go index aa6865f0e..9336cbde5 100644 --- a/repo/repository.go +++ b/repo/repository.go @@ -209,7 +209,7 @@ func (r *directRepository) NewWriter(ctx context.Context, opt WriteSessionOption // NewDirectWriter returns new DirectRepositoryWriter session for repository. func (r *directRepository) NewDirectWriter(ctx context.Context, opt WriteSessionOptions) (context.Context, DirectRepositoryWriter, error) { - writeManagerID := fmt.Sprintf("[writer-%v:%v] ", atomic.AddInt32(r.nextWriterID, 1), opt.Purpose) + writeManagerID := fmt.Sprintf("writer-%v:%v", atomic.AddInt32(r.nextWriterID, 1), opt.Purpose) cmgr := content.NewWriteManager(ctx, r.sm, content.SessionOptions{ SessionUser: r.cliOpts.Username, diff --git a/tests/testenv/cli_inproc_runner.go b/tests/testenv/cli_inproc_runner.go index 29747ca3b..86e42f65f 100644 --- a/tests/testenv/cli_inproc_runner.go +++ b/tests/testenv/cli_inproc_runner.go @@ -5,6 +5,8 @@ "os" "testing" + "github.com/alecthomas/kingpin" + "github.com/kopia/kopia/cli" "github.com/kopia/kopia/internal/testlogging" ) @@ -12,6 +14,8 @@ // CLIInProcRunner is a CLIRunner that invokes provided commands in the current process. type CLIInProcRunner struct { RepoPassword string + + CustomizeApp func(a *cli.App, kp *kingpin.Application) } // Start implements CLIRunner. @@ -23,7 +27,13 @@ func (e *CLIInProcRunner) Start(t *testing.T, args []string) (stdout, stderr io. a := cli.NewApp() a.AdvancedCommands = "enabled" - return a.RunSubcommand(ctx, append([]string{ + kpapp := kingpin.New("test", "test") + + if e.CustomizeApp != nil { + e.CustomizeApp(a, kpapp) + } + + return a.RunSubcommand(ctx, kpapp, append([]string{ "--password", e.RepoPassword, }, args...)) }