Skip to content

Commit

Permalink
logging: added log rotation and improved predictability of log sweep (#…
Browse files Browse the repository at this point in the history 
…1562)

* logging: added log rotation and improved predictability of log sweep

With this change logs will be rotated every 50 MB, which prevents
accumulation of giant files while server is running.

This change will also guarantee that log sweep completes at least once
before each invocation of Kopia finishes. Previously it was a goroutine
that was not monitored for completion.

Flags can be used to override default behaviors:

* `--max-log-file-segment-size`
* `--no-wait-for-log-sweep` - disables waiting for full log sweep

Fixes #1561

* logging: added --log-dir-max-total-size-mb flag

This limits the total size of all logs in a directory to 1 GB.
  • Loading branch information
@jkowalski
jkowalski committed Dec 4, 2021
1 parent 920341c commit 2cb05f7
Show file tree
Hide file tree
Showing 3 changed files with 259 additions and 38 deletions.
23 changes: 20 additions & 3 deletions cli/app.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -122,7 +122,8 @@ type App struct {
disableInternalLog bool
AdvancedCommands string

currentAction string
currentAction string
onExitCallbacks []func()

// subcommands
blob commandBlob
Expand Down Expand Up @@ -170,6 +171,18 @@ func (c *App) SetLoggerFactory(loggerForModule logging.LoggerFactory) {
c.loggerFactory = loggerForModule
}

// RegisterOnExit registers the provided function to run before app exits.
func (c *App) RegisterOnExit(f func()) {
c.onExitCallbacks = append(c.onExitCallbacks, f)
}

// runOnExit runs all registered on-exit callbacks.
func (c *App) runOnExit() {
for _, f := range c.onExitCallbacks {
f()
}
}

func (c *App) passwordPersistenceStrategy() passwordpersist.Strategy {
if !c.persistCredentials {
return passwordpersist.None
Expand Down Expand Up @@ -405,7 +418,7 @@ func (c *App) maybeRepositoryAction(act func(ctx context.Context, rep repo.Repos
return func(kpc *kingpin.ParseContext) error {
ctx0 := c.rootContext()

if err := c.pf.withProfiling(func() error {
err := c.pf.withProfiling(func() error {
ctx, finishMemoryTracking := c.mt.startMemoryTracking(ctx0)
defer finishMemoryTracking()

Expand Down Expand Up @@ -461,7 +474,11 @@ func (c *App) maybeRepositoryAction(act func(ctx context.Context, rep repo.Repos
}

return err
}); err != nil {
})

c.runOnExit()

if err != nil {
// print error in red
log(ctx0).Errorf("%v", err.Error())
c.osExit(1)
Expand Down
158 changes: 123 additions & 35 deletions internal/logfile/logfile.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,7 @@ import (

"github.com/alecthomas/kingpin"
"github.com/fatih/color"
"github.com/pkg/errors"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"

Expand All @@ -30,21 +31,25 @@ const logsDirMode = 0o700
var logLevels = []string{"debug", "info", "warning", "error"}

type loggingFlags struct {
logFile string
contentLogFile string
logDir string
logDirMaxFiles int
logDirMaxAge time.Duration
contentLogDirMaxFiles int
contentLogDirMaxAge time.Duration
logLevel string
fileLogLevel string
fileLogLocalTimezone bool
jsonLogFile bool
jsonLogConsole bool
forceColor bool
disableColor bool
consoleLogTimestamps bool
logFile string
contentLogFile string
logDir string
logDirMaxFiles int
logDirMaxAge time.Duration
logDirMaxTotalSizeMB float64
contentLogDirMaxFiles int
contentLogDirMaxAge time.Duration
contentLogDirMaxTotalSizeMB float64
logFileMaxSegmentSize int
logLevel string
fileLogLevel string
fileLogLocalTimezone bool
jsonLogFile bool
jsonLogConsole bool
forceColor bool
disableColor bool
consoleLogTimestamps bool
waitForLogSweep bool

cliApp *cli.App
}
Expand All @@ -56,8 +61,12 @@ func (c *loggingFlags) setup(cliApp *cli.App, app *kingpin.Application) {
app.Flag("log-dir", "Directory where log files should be written.").Envar("KOPIA_LOG_DIR").Default(ospath.LogsDir()).StringVar(&c.logDir)
app.Flag("log-dir-max-files", "Maximum number of log files to retain").Envar("KOPIA_LOG_DIR_MAX_FILES").Default("1000").Hidden().IntVar(&c.logDirMaxFiles)
app.Flag("log-dir-max-age", "Maximum age of log files to retain").Envar("KOPIA_LOG_DIR_MAX_AGE").Hidden().Default("720h").DurationVar(&c.logDirMaxAge)
app.Flag("log-dir-max-total-size-mb", "Maximum total size of log files to retain").Envar("KOPIA_LOG_DIR_MAX_SIZE_MB").Hidden().Default("1000").Float64Var(&c.logDirMaxTotalSizeMB)
app.Flag("max-log-file-segment-size", "Maximum size of a single log file segment").Envar("KOPIA_LOG_FILE_MAX_SEGMENT_SIZE").Default("50000000").Hidden().IntVar(&c.logFileMaxSegmentSize)
app.Flag("wait-for-log-sweep", "Wait for log sweep before program exit").Default("true").Hidden().BoolVar(&c.waitForLogSweep)
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("content-log-dir-max-total-size-mb", "Maximum total size of log files to retain").Envar("KOPIA_CONTENT_LOG_DIR_MAX_SIZE_MB").Hidden().Default("1000").Float64Var(&c.contentLogDirMaxTotalSizeMB)
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)
Expand Down Expand Up @@ -177,7 +186,7 @@ func (c *loggingFlags) setupConsoleCore() zapcore.Core {
)
}

func (c *loggingFlags) setupLogFileBasedLogger(now time.Time, subdir, suffix, logFileOverride string, maxFiles int, maxAge time.Duration) zapcore.WriteSyncer {
func (c *loggingFlags) setupLogFileBasedLogger(now time.Time, subdir, suffix, logFileOverride string, maxFiles int, maxSizeMB float64, maxAge time.Duration) zapcore.WriteSyncer {
var logFileName, symlinkName string

if logFileOverride != "" {
Expand All @@ -202,16 +211,42 @@ func (c *loggingFlags) setupLogFileBasedLogger(now time.Time, subdir, suffix, lo
fmt.Fprintln(os.Stderr, "Unable to create logs directory:", err)
}

sweepLogWG := &sync.WaitGroup{}
doSweep := func() {}

// do not scrub directory if custom log file has been provided.
if logFileOverride == "" && shouldSweepLog(maxFiles, maxAge) {
go sweepLogDir(context.TODO(), logDir, maxFiles, maxAge)
doSweep = func() {
sweepLogDir(context.TODO(), logDir, maxFiles, maxSizeMB, maxAge)
}
}

return &onDemandFile{
odf := &onDemandFile{
logDir: logDir,
logFileBaseName: logFileBaseName,
symlinkName: symlinkName,
maxSegmentSize: c.logFileMaxSegmentSize,
startSweep: func() {
sweepLogWG.Add(1)

go func() {
defer sweepLogWG.Done()

doSweep()
}()
},
}

if c.waitForLogSweep {
// wait for log sweep at the end
c.cliApp.RegisterOnExit(odf.closeSegmentAndSweep)
c.cliApp.RegisterOnExit(sweepLogWG.Wait)
} else {
// old behavior: start log sweep in parallel to program but don't wait at the end.
odf.startSweep()
}

return odf
}

func (c *loggingFlags) setupLogFileCore(now time.Time, suffix string) zapcore.Core {
Expand All @@ -227,7 +262,7 @@ func (c *loggingFlags) setupLogFileCore(now time.Time, suffix string) zapcore.Co
EncodeDuration: zapcore.StringDurationEncoder,
ConsoleSeparator: " ",
}, c.jsonLogFile),
c.setupLogFileBasedLogger(now, "cli-logs", suffix, c.logFile, c.logDirMaxFiles, c.logDirMaxAge),
c.setupLogFileBasedLogger(now, "cli-logs", suffix, c.logFile, c.logDirMaxFiles, c.logDirMaxTotalSizeMB, c.logDirMaxAge),
logLevelFromFlag(c.fileLogLevel),
)
}
Expand All @@ -250,15 +285,15 @@ func (c *loggingFlags) setupContentLogFileBackend(now time.Time, suffix string)
EncodeDuration: zapcore.StringDurationEncoder,
ConsoleSeparator: " ",
}),
c.setupLogFileBasedLogger(now, "content-logs", suffix, c.contentLogFile, c.contentLogDirMaxFiles, c.contentLogDirMaxAge),
c.setupLogFileBasedLogger(now, "content-logs", suffix, c.contentLogFile, c.contentLogDirMaxFiles, c.contentLogDirMaxTotalSizeMB, c.contentLogDirMaxAge),
zap.DebugLevel)
}

func shouldSweepLog(maxFiles int, maxAge time.Duration) bool {
return maxFiles > 0 || maxAge > 0
}

func sweepLogDir(ctx context.Context, dirname string, maxCount int, maxAge time.Duration) {
func sweepLogDir(ctx context.Context, dirname string, maxCount int, maxSizeMB float64, maxAge time.Duration) {
var timeCutoff time.Time
if maxAge > 0 {
timeCutoff = clock.Now().Add(-maxAge)
Expand All @@ -268,6 +303,8 @@ func sweepLogDir(ctx context.Context, dirname string, maxCount int, maxAge time.
maxCount = math.MaxInt32
}

maxTotalSizeBytes := int64(maxSizeMB * 1e6)

entries, err := os.ReadDir(dirname)
if err != nil {
log(ctx).Errorf("unable to read log directory: %v", err)
Expand Down Expand Up @@ -296,6 +333,7 @@ func sweepLogDir(ctx context.Context, dirname string, maxCount int, maxAge time.
})

cnt := 0
totalSize := int64(0)

for _, fi := range fileInfos {
if !strings.HasPrefix(fi.Name(), logFileNamePrefix) {
Expand All @@ -308,7 +346,9 @@ func sweepLogDir(ctx context.Context, dirname string, maxCount int, maxAge time.

cnt++

if cnt > maxCount || fi.ModTime().Before(timeCutoff) {
totalSize += fi.Size()

if cnt > maxCount || totalSize > maxTotalSizeBytes || fi.ModTime().Before(timeCutoff) {
if err = os.Remove(filepath.Join(dirname, fi.Name())); err != nil && !os.IsNotExist(err) {
log(ctx).Errorf("unable to remove log file: %v", err)
}
Expand All @@ -332,13 +372,19 @@ func logLevelFromFlag(levelString string) zapcore.LevelEnabler {
}

type onDemandFile struct {
segmentCounter int // number of segments written
currentSegmentSize int // number of bytes written to current segment
maxSegmentSize int
currentSegmentFilename string

logDir string
logFileBaseName string
symlinkName string

f *os.File
startSweep func()

once sync.Once
mu sync.Mutex
f *os.File
}

func (w *onDemandFile) Sync() error {
Expand All @@ -350,28 +396,70 @@ func (w *onDemandFile) Sync() error {
return w.f.Sync()
}

func (w *onDemandFile) closeSegmentAndSweep() {
w.mu.Lock()
defer w.mu.Unlock()

w.closeSegmentAndSweepLocked()
}

func (w *onDemandFile) closeSegmentAndSweepLocked() {
if w.f != nil {
if err := w.f.Close(); err != nil {
fmt.Fprintf(os.Stderr, "warning: unable to close log segment: %v", err)
}

w.f = nil
}

w.startSweep()
}

func (w *onDemandFile) Write(b []byte) (int, error) {
w.once.Do(func() {
lf := filepath.Join(w.logDir, w.logFileBaseName)
w.mu.Lock()
defer w.mu.Unlock()

// close current file if we'd overflow on next write.
if w.f != nil && w.currentSegmentSize+len(b) > w.maxSegmentSize {
w.closeSegmentAndSweepLocked()
}

// open file if we don't have it yet
if w.f == nil {
var baseName, ext string

p := strings.LastIndex(w.logFileBaseName, ".")
if p < 0 {
ext = ""
baseName = w.logFileBaseName
} else {
ext = w.logFileBaseName[p:]
baseName = w.logFileBaseName[0:p]
}

w.currentSegmentFilename = fmt.Sprintf("%s.%d%s", baseName, w.segmentCounter, ext)
w.segmentCounter++
w.currentSegmentSize = 0

lf := filepath.Join(w.logDir, w.currentSegmentFilename)

f, err := os.Create(lf)
if err != nil {
fmt.Fprintf(os.Stderr, "unable to open log file: %v\n", err)
return
return 0, errors.Wrap(err, "unable to open log file")
}

w.f = f

if w.symlinkName != "" {
symlink := filepath.Join(w.logDir, w.symlinkName)
_ = os.Remove(symlink) // best-effort remove
_ = os.Symlink(w.logFileBaseName, symlink) // best-effort symlink
_ = os.Remove(symlink) // best-effort remove
_ = os.Symlink(w.currentSegmentFilename, symlink) // best-effort symlink
}
})

if w.f == nil {
return 0, nil
}

n, err := w.f.Write(b)
w.currentSegmentSize += n

// nolint:wrapcheck
return w.f.Write(b)
return n, err
}

0 comments on commit 2cb05f7

Please sign in to comment.