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
2026-05-24 14:44:47 -04:00 · 2021-10-12 22:52:24 -07:00
parent 6a991c180b
commit 4a47bc3210
28 changed files with 374 additions and 207 deletions
--- 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
 }

--- 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()

--- 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
--- 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=
--- 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%;
--- 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{}
+)
--- 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,
--- 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 {
--- 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
 	}

--- 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)
 }
--- a/internal/logfile/logfile_test.go
+++ 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())
+	}
+}
--- 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
--- 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)
 }
--- 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)
--- 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")
--- 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{}
--- 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,
 	}
 }
--- 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 {
--- 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),
 	}
 }
--- 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.
--- 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 {
--- 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{})
 }

--- 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{}
--- 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...)
--- 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.
--- 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)
 		}
 	}

--- 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,
--- 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...))
 }