From ba6e5e88620a35ed893f31e45294e683ac7b67d6 Mon Sep 17 00:00:00 2001 From: Kegan Dougal Date: Thu, 27 Oct 2016 13:09:22 +0100 Subject: [PATCH] Rotate logs on a daily basis: Fixes #97 --- src/github.com/matrix-org/go-neb/goneb.go | 1 + vendor/manifest | 4 +- .../github.com/matrix-org/dugong/fshook.go | 90 ++++++++++++++- .../matrix-org/dugong/fshook_test.go | 108 +++++++++++++++++- 4 files changed, 192 insertions(+), 11 deletions(-) diff --git a/src/github.com/matrix-org/go-neb/goneb.go b/src/github.com/matrix-org/go-neb/goneb.go index ad70572..6f1e75f 100644 --- a/src/github.com/matrix-org/go-neb/goneb.go +++ b/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{}, )) } diff --git a/vendor/manifest b/vendor/manifest index ee53bc1..0f2e1da 100644 --- a/vendor/manifest +++ b/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" } ] -} \ No newline at end of file +} diff --git a/vendor/src/github.com/matrix-org/dugong/fshook.go b/vendor/src/github.com/matrix-org/dugong/fshook.go index c72e42f..8081dc1 100644 --- a/vendor/src/github.com/matrix-org/dugong/fshook.go +++ b/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 { diff --git a/vendor/src/github.com/matrix-org/dugong/fshook_test.go b/vendor/src/github.com/matrix-org/dugong/fshook_test.go index 48929c7..a51a51f 100644 --- a/vendor/src/github.com/matrix-org/dugong/fshook_test.go +++ b/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)