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

@@ -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" {

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

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