Rotate logs on a daily basis: Fixes #97

src/github.com/matrix-org/go-neb/goneb.go

@@ -224,6 +224,7 @@ func main() {
 			filepath.Join(e.LogDir, "info.log"),
 			filepath.Join(e.LogDir, "warn.log"),
 			filepath.Join(e.LogDir, "error.log"),
+			nil, &dugong.DailyRotationSchedule{},
 		))
 	}
 

vendor/manifest

@@ -132,7 +132,7 @@
 		{
 			"importpath": "github.com/matrix-org/dugong",
 			"repository": "https://github.com/matrix-org/dugong",
-			"revision": "6b893e5ef2dd0ddcbfdf00aafe0278237456512b",
+			"revision": "07b01e0bea3c53627f5a3fc9c5f36ad145a4b086",
 			"branch": "master"
 		},
 		{
@@ -314,4 +314,4 @@
 			"branch": "v2"
 		}
 	]
-}
+}

vendor/src/github.com/matrix-org/dugong/fshook.go

@@ -2,21 +2,73 @@ package dugong
 
 import (
 	"fmt"
+	log "github.com/Sirupsen/logrus"
 	"os"
 	"sync/atomic"
-
-	log "github.com/Sirupsen/logrus"
+	"time"
 )
 
-// NewFSHook makes a logging hook that writes JSON formatted
+// RotationScheduler determines when files should be rotated.
+type RotationScheduler interface {
+	// ShouldRotate returns true if the file should be rotated. The suffix to apply
+	// to the filename is returned as the 2nd arg.
+	ShouldRotate() (bool, string)
+}
+
+// DailyRotationSchedule rotates log files daily. Logs are only rotated
+// when midnight passes *whilst the process is running*. E.g: if you run
+// the process on Day 4 then stop it and start it on Day 7, no rotation will
+// occur when the process starts.
+type DailyRotationSchedule struct {
+	rotateAfter *time.Time
+}
+
+var currentTime = time.Now // exclusively for testing
+
+func dayOffset(t time.Time, offsetDays int) time.Time {
+	// GoDoc:
+	//   The month, day, hour, min, sec, and nsec values may be outside their
+	//   usual ranges and will be normalized during the conversion.
+	//   For example, October 32 converts to November 1.
+	return time.Date(
+		t.Year(), t.Month(), t.Day()+offsetDays, 0, 0, 0, 0, t.Location(),
+	)
+}
+
+func (rs *DailyRotationSchedule) ShouldRotate() (bool, string) {
+	now := currentTime()
+	if rs.rotateAfter == nil {
+		nextRotate := dayOffset(now, 1)
+		rs.rotateAfter = &nextRotate
+		return false, ""
+	}
+	if now.After(*rs.rotateAfter) {
+		// the suffix should be actually the date of the complete day being logged
+		actualDay := dayOffset(*rs.rotateAfter, -1)
+		suffix := "." + actualDay.Format("2006-01-02") // YYYY-MM-DD
+		nextRotate := dayOffset(now, 1)
+		rs.rotateAfter = &nextRotate
+		return true, suffix
+	}
+	return false, ""
+}
+
+// NewFSHook makes a logging hook that writes formatted
 // log entries to info, warn and error log files. Each log file
-// contains the messages with that severity or higher.
-func NewFSHook(infoPath, warnPath, errorPath string) log.Hook {
+// contains the messages with that severity or higher. If a formatter is
+// not specified, they will be logged using a JSON formatter. If a
+// RotationScheduler is set, the files will be cycled according to its rules.
+func NewFSHook(infoPath, warnPath, errorPath string, formatter log.Formatter, rotSched RotationScheduler) log.Hook {
+	if formatter == nil {
+		formatter = &log.JSONFormatter{}
+	}
 	hook := &fsHook{
 		entries:   make(chan log.Entry, 1024),
 		infoPath:  infoPath,
 		warnPath:  warnPath,
 		errorPath: errorPath,
+		formatter: formatter,
+		scheduler: rotSched,
 	}
 
 	go func() {
@@ -37,7 +89,8 @@ type fsHook struct {
 	infoPath  string
 	warnPath  string
 	errorPath string
-	formatter log.JSONFormatter
+	formatter log.Formatter
+	scheduler RotationScheduler
 }
 
 func (hook *fsHook) Fire(entry *log.Entry) error {
@@ -52,6 +105,14 @@ func (hook *fsHook) writeEntry(entry *log.Entry) error {
 		return nil
 	}
 
+	if hook.scheduler != nil {
+		if should, suffix := hook.scheduler.ShouldRotate(); should {
+			if err := hook.rotate(suffix); err != nil {
+				return err
+			}
+		}
+	}
+
 	if entry.Level <= log.ErrorLevel {
 		if err := logToFile(hook.errorPath, msg); err != nil {
 			return err
@@ -83,6 +144,23 @@ func (hook *fsHook) Levels() []log.Level {
 	}
 }
 
+// rotate all the log files to the given suffix.
+// If error path is "err.log" and suffix is "1" then move
+// the contents to "err.log1".
+// This requires no locking as the goroutine calling this is the same
+// one which does the logging. Since we don't hold open a handle to the
+// file when writing, a simple Rename is all that is required.
+func (hook *fsHook) rotate(suffix string) error {
+	for _, fpath := range []string{hook.errorPath, hook.warnPath, hook.infoPath} {
+		if err := os.Rename(fpath, fpath+suffix); err != nil {
+			// e.g. because there were no errors in error.log for this day
+			fmt.Fprintf(os.Stderr, "Error rotating file %s: %v\n", fpath, err)
+		}
+
+	}
+	return nil
+}
+
 func logToFile(path string, msg []byte) error {
 	fd, err := os.OpenFile(path, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0600)
 	if err != nil {

vendor/src/github.com/matrix-org/dugong/fshook_test.go

@@ -3,6 +3,7 @@ package dugong
 import (
 	"bufio"
 	"encoding/json"
+	log "github.com/Sirupsen/logrus"
 	"io/ioutil"
 	"os"
 	"path/filepath"
@@ -10,8 +11,7 @@ import (
 	"sync"
 	"sync/atomic"
 	"testing"
-
-	log "github.com/Sirupsen/logrus"
+	"time"
 )
 
 const (
@@ -163,6 +163,108 @@ func TestFSHookConcurrent(t *testing.T) {
 	}
 }
 
+func TestDailySchedule(t *testing.T) {
+	loc, err := time.LoadLocation("UTC")
+	if err != nil {
+		t.Fatalf("Failed to load location UTC: %s", err)
+	}
+
+	logger, hook, wait, teardown := setupLogHook(t)
+	defer teardown()
+	hook.scheduler = &DailyRotationSchedule{}
+
+	// Time ticks from 23:50 to 00:10 in 1 minute increments. Log each tick as 'counter'.
+	minutesGoneBy := 0
+	currentTime = func() time.Time {
+		minutesGoneBy += 1
+		return time.Date(2016, 10, 26, 23, 50+minutesGoneBy, 00, 0, loc)
+	}
+	for i := 0; i < 20; i++ {
+		t := time.Date(2016, 10, 26, 23, 50+i, 00, 0, loc)
+		logger.WithField("counter", i).Info("BASE " + t.Format(time.ANSIC))
+	}
+
+	wait()
+
+	// info.log.2016-10-26 should have 0 -> 9
+	checkFileHasSequentialCounts(t, hook.infoPath+".2016-10-26", 0, 9)
+
+	// info.log should have 10 -> 19 inclusive
+	checkFileHasSequentialCounts(t, hook.infoPath, 10, 19)
+}
+
+func TestDailyScheduleMultipleRotations(t *testing.T) {
+	loc, err := time.LoadLocation("UTC")
+	if err != nil {
+		t.Fatalf("Failed to load location UTC: %s", err)
+	}
+
+	logger, hook, wait, teardown := setupLogHook(t)
+	defer teardown()
+	hook.scheduler = &DailyRotationSchedule{}
+
+	// Time ticks every 12 hours from 13:37 -> 01:37 -> 13:37 -> ...
+	hoursGoneBy := 0
+	currentTime = func() time.Time {
+		hoursGoneBy += 12
+		// Start from 10/29 01:37
+		return time.Date(2016, 10, 28, 13+hoursGoneBy, 37, 00, 0, loc)
+	}
+	// log 2 lines per file, to 4 files (so 8 log lines)
+	for i := 0; i < 8; i++ {
+		ts := time.Date(2016, 10, 28, 13+((i+1)*12), 37, 00, 0, loc)
+		logger.WithField("counter", i).Infof("The time is now %s", ts)
+	}
+
+	wait()
+
+	// info.log.2016-10-29 should have 0-1
+	checkFileHasSequentialCounts(t, hook.infoPath+".2016-10-29", 0, 1)
+
+	// info.log.2016-10-30 should have 2-3
+	checkFileHasSequentialCounts(t, hook.infoPath+".2016-10-30", 2, 3)
+
+	// info.log.2016-10-31 should have 4-5
+	checkFileHasSequentialCounts(t, hook.infoPath+".2016-10-31", 4, 5)
+
+	// info.log should have 6-7 (current day is 11/01)
+	checkFileHasSequentialCounts(t, hook.infoPath, 6, 7)
+}
+
+// checkFileHasSequentialCounts based on a JSON "counter" key being a monotonically
+// incrementing integer. from and to are both inclusive.
+func checkFileHasSequentialCounts(t *testing.T, filepath string, from, to int) {
+	t.Logf("checkFileHasSequentialCounts(%s,%d,%d)", filepath, from, to)
+
+	file, err := os.Open(filepath)
+	if err != nil {
+		t.Fatalf("Failed to open file: %v", err)
+		return
+	}
+
+	defer file.Close()
+	scanner := bufio.NewScanner(file)
+	count := from
+	for scanner.Scan() {
+		data := make(map[string]interface{})
+		if err := json.Unmarshal([]byte(scanner.Text()), &data); err != nil {
+			t.Fatalf("%s : Failed to parse JSON: %v", file.Name(), err)
+		}
+		dataCounter := int(data["counter"].(float64))
+		t.Logf("%s want %d got %d", file.Name(), count, dataCounter)
+		if count != dataCounter {
+			t.Fatalf("%s : Counter: want %d got %d", file.Name(), count, dataCounter)
+		}
+
+		count++
+	}
+	count-- // never hit the next value
+
+	if count != to {
+		t.Fatalf("%s EOF: Want count %d got %d", file.Name(), to, count)
+	}
+}
+
 func setupLogHook(t *testing.T) (logger *log.Logger, hook *fsHook, wait func(), teardown func()) {
 	dir, err := ioutil.TempDir("", "TestFSHook")
 	if err != nil {
@@ -173,7 +275,7 @@ func setupLogHook(t *testing.T) (logger *log.Logger, hook *fsHook, wait func(),
 	warnPath := filepath.Join(dir, "warn.log")
 	errorPath := filepath.Join(dir, "error.log")
 
-	hook = NewFSHook(infoPath, warnPath, errorPath).(*fsHook)
+	hook = NewFSHook(infoPath, warnPath, errorPath, nil, nil).(*fsHook)
 
 	logger = log.New()
 	logger.Hooks.Add(hook)