From f9c380d45bbd0b370325cc0808a4f79ade7d418a Mon Sep 17 00:00:00 2001 From: Jakob Borg Date: Thu, 28 Nov 2019 12:26:14 +0100 Subject: [PATCH] cmd/syncthing: Implement log rotation (fixes #6104) (#6198) Since we've taken upon ourselves to create a log file by default on Windows, this adds proper management of that log file. There are two new options: -log-max-old-files="3" Number of old files to keep (zero to keep only current). -log-max-size="10485760" Maximum size of any file (zero to disable log rotation). The default values result in four files (syncthing.log, synchting.0.log, ..., syncthing.3.log) each up to 10 MiB in size. To not use log rotation at all, the user can say --log-max-size=0. --- cmd/syncthing/main.go | 6 ++ cmd/syncthing/monitor.go | 87 ++++++++++++++++++++++++- cmd/syncthing/monitor_test.go | 118 ++++++++++++++++++++++++++++++++++ 3 files changed, 210 insertions(+), 1 deletion(-) diff --git a/cmd/syncthing/main.go b/cmd/syncthing/main.go index 2f2fb49bd..965632d99 100644 --- a/cmd/syncthing/main.go +++ b/cmd/syncthing/main.go @@ -154,6 +154,8 @@ type RuntimeOptions struct { browserOnly bool hideConsole bool logFile string + logMaxSize int + logMaxFiles int auditEnabled bool auditFile string paused bool @@ -180,6 +182,8 @@ func defaultRuntimeOptions() RuntimeOptions { cpuProfile: os.Getenv("STCPUPROFILE") != "", stRestarting: os.Getenv("STRESTART") != "", logFlags: log.Ltime, + logMaxSize: 10 << 20, // 10 MiB + logMaxFiles: 3, // plus the current one } if os.Getenv("STTRACE") != "" { @@ -222,6 +226,8 @@ func parseCommandLineOptions() RuntimeOptions { flag.BoolVar(&options.paused, "paused", false, "Start with all devices and folders paused") flag.BoolVar(&options.unpaused, "unpaused", false, "Start with all devices and folders unpaused") flag.StringVar(&options.logFile, "logfile", options.logFile, "Log file name (still always logs to stdout). Cannot be used together with -no-restart/STNORESTART environment variable.") + flag.IntVar(&options.logMaxSize, "log-max-size", options.logMaxSize, "Maximum size of any file (zero to disable log rotation).") + flag.IntVar(&options.logMaxFiles, "log-max-old-files", options.logMaxFiles, "Number of old files to keep (zero to keep only current).") flag.StringVar(&options.auditFile, "auditfile", options.auditFile, "Specify audit file (use \"-\" for stdout, \"--\" for stderr)") flag.BoolVar(&options.allowNewerConfig, "allow-newer-config", false, "Allow loading newer than current config version") if runtime.GOOS == "windows" { diff --git a/cmd/syncthing/monitor.go b/cmd/syncthing/monitor.go index 76eb38e31..72986e8d0 100644 --- a/cmd/syncthing/monitor.go +++ b/cmd/syncthing/monitor.go @@ -9,10 +9,12 @@ package main import ( "bufio" "context" + "fmt" "io" "os" "os/exec" "os/signal" + "path/filepath" "runtime" "strings" "syscall" @@ -48,7 +50,15 @@ func monitorMain(runtimeOptions RuntimeOptions) { logFile := runtimeOptions.logFile if logFile != "-" { - var fileDst io.Writer = newAutoclosedFile(logFile, logFileAutoCloseDelay, logFileMaxOpenTime) + var fileDst io.Writer + if runtimeOptions.logMaxSize > 0 { + open := func(name string) (io.WriteCloser, error) { + return newAutoclosedFile(name, logFileAutoCloseDelay, logFileMaxOpenTime), nil + } + fileDst = newRotatedFile(logFile, open, int64(runtimeOptions.logMaxSize), runtimeOptions.logMaxFiles) + } else { + fileDst = newAutoclosedFile(logFile, logFileAutoCloseDelay, logFileMaxOpenTime) + } if runtime.GOOS == "windows" { // Translate line breaks to Windows standard @@ -317,6 +327,81 @@ func restartMonitorWindows(args []string) error { return cmd.Start() } +// rotatedFile keeps a set of rotating logs. There will be the base file plus up +// to maxFiles rotated ones, each ~ maxSize bytes large. +type rotatedFile struct { + name string + create createFn + maxSize int64 // bytes + maxFiles int + currentFile io.WriteCloser + currentSize int64 +} + +// the createFn should act equivalently to os.Create +type createFn func(name string) (io.WriteCloser, error) + +func newRotatedFile(name string, create createFn, maxSize int64, maxFiles int) *rotatedFile { + return &rotatedFile{ + name: name, + create: create, + maxSize: maxSize, + maxFiles: maxFiles, + } +} + +func (r *rotatedFile) Write(bs []byte) (int, error) { + // Check if we're about to exceed the max size, and if so close this + // file so we'll start on a new one. + if r.currentSize+int64(len(bs)) > r.maxSize { + r.currentFile.Close() + r.currentFile = nil + r.currentSize = 0 + } + + // If we have no current log, rotate old files out of the way and create + // a new one. + if r.currentFile == nil { + r.rotate() + fd, err := r.create(r.name) + if err != nil { + return 0, err + } + r.currentFile = fd + } + + n, err := r.currentFile.Write(bs) + r.currentSize += int64(n) + return n, err +} + +func (r *rotatedFile) rotate() { + // The files are named "name", "name.0", "name.1", ... + // "name.(r.maxFiles-1)". Increase the numbers on the + // suffixed ones. + for i := r.maxFiles - 1; i > 0; i-- { + from := numberedFile(r.name, i-1) + to := numberedFile(r.name, i) + err := os.Rename(from, to) + if err != nil && !os.IsNotExist(err) { + fmt.Println("LOG: Rotating logs:", err) + } + } + + // Rename the base to base.0 + err := os.Rename(r.name, numberedFile(r.name, 0)) + if err != nil && !os.IsNotExist(err) { + fmt.Println("LOG: Rotating logs:", err) + } +} + +// numberedFile adds the number between the file name and the extension. +func numberedFile(name string, num int) string { + ext := filepath.Ext(name) // contains the dot + withoutExt := name[:len(name)-len(ext)] + return fmt.Sprintf("%s.%d%s", withoutExt, num, ext) +} + // An autoclosedFile is an io.WriteCloser that opens itself for appending on // Write() and closes itself after an interval of no writes (closeDelay) or // when the file has been open for too long (maxOpenTime). A call to Write() diff --git a/cmd/syncthing/monitor_test.go b/cmd/syncthing/monitor_test.go index b6c9c4a66..b53620885 100644 --- a/cmd/syncthing/monitor_test.go +++ b/cmd/syncthing/monitor_test.go @@ -7,6 +7,7 @@ package main import ( + "io" "io/ioutil" "os" "path/filepath" @@ -14,6 +15,123 @@ import ( "time" ) +func TestRotatedFile(t *testing.T) { + // Verify that log rotation happens. + + dir, err := ioutil.TempDir("", "syncthing") + if err != nil { + t.Fatal(err) + } + defer os.RemoveAll(dir) + + open := func(name string) (io.WriteCloser, error) { + return os.Create(name) + } + + logName := filepath.Join(dir, "log.txt") + testData := []byte("12345678\n") + maxSize := int64(len(testData) + len(testData)/2) + + // We allow the log file plus two rotated copies. + rf := newRotatedFile(logName, open, maxSize, 2) + + // Write some bytes. + if _, err := rf.Write(testData); err != nil { + t.Fatal(err) + } + // They should be in the log. + checkSize(t, logName, len(testData)) + checkNotExist(t, logName+".0") + + // Write some more bytes. We should rotate and write into a new file as the + // new bytes don't fit. + if _, err := rf.Write(testData); err != nil { + t.Fatal(err) + } + checkSize(t, logName, len(testData)) + checkSize(t, numberedFile(logName, 0), len(testData)) + checkNotExist(t, logName+".1") + + // Write another byte. That should fit without causing an extra rotate. + _, _ = rf.Write([]byte{42}) + checkSize(t, logName, len(testData)+1) + checkSize(t, numberedFile(logName, 0), len(testData)) + checkNotExist(t, numberedFile(logName, 1)) + + // Write some more bytes. We should rotate and write into a new file as the + // new bytes don't fit. + if _, err := rf.Write(testData); err != nil { + t.Fatal(err) + } + checkSize(t, logName, len(testData)) + checkSize(t, numberedFile(logName, 0), len(testData)+1) // the one we wrote extra to, now rotated + checkSize(t, numberedFile(logName, 1), len(testData)) + checkNotExist(t, numberedFile(logName, 2)) + + // Write some more bytes. We should rotate and write into a new file as the + // new bytes don't fit. + if _, err := rf.Write(testData); err != nil { + t.Fatal(err) + } + checkSize(t, logName, len(testData)) + checkSize(t, numberedFile(logName, 0), len(testData)) + checkSize(t, numberedFile(logName, 1), len(testData)+1) + checkNotExist(t, numberedFile(logName, 2)) // exceeds maxFiles so deleted +} + +func TestNumberedFile(t *testing.T) { + // Mostly just illustrates where the number ends up and makes sure it + // doesn't crash without an extension. + + cases := []struct { + in string + num int + out string + }{ + { + in: "syncthing.log", + num: 42, + out: "syncthing.42.log", + }, + { + in: filepath.Join("asdfasdf", "syncthing.log.txt"), + num: 42, + out: filepath.Join("asdfasdf", "syncthing.log.42.txt"), + }, + { + in: "syncthing-log", + num: 42, + out: "syncthing-log.42", + }, + } + + for _, tc := range cases { + res := numberedFile(tc.in, tc.num) + if res != tc.out { + t.Errorf("numberedFile(%q, %d) => %q, expected %q", tc.in, tc.num, res, tc.out) + } + } +} + +func checkSize(t *testing.T, name string, size int) { + t.Helper() + info, err := os.Lstat(name) + if err != nil { + t.Fatal(err) + } + if info.Size() != int64(size) { + t.Errorf("%s wrong size: %d != expected %d", name, info.Size(), size) + } +} + +func checkNotExist(t *testing.T, name string) { + t.Helper() + _, err := os.Lstat(name) + if !os.IsNotExist(err) { + t.Errorf("%s should not exist", name) + } +} + func TestAutoClosedFile(t *testing.T) { os.RemoveAll("_autoclose") defer os.RemoveAll("_autoclose")