From 10710b3298dc69499b8a1407fb8d35ab11f2b69e Mon Sep 17 00:00:00 2001 From: Tim Penhey Date: Thu, 26 Mar 2020 16:40:38 +1300 Subject: [PATCH 1/3] Ensure that the millRun goroutine terminates when Close called. Currently the millRun goroutines leaks. This is very noticable if a Logger is constructed periodically, used and then closed. This change ensures that the millCh channel is closed if it exists. --- lumberjack.go | 22 +++++++++++++--------- 1 file changed, 13 insertions(+), 9 deletions(-) diff --git a/lumberjack.go b/lumberjack.go index a47b7f0..edc8162 100644 --- a/lumberjack.go +++ b/lumberjack.go @@ -111,8 +111,7 @@ type Logger struct { file *os.File mu sync.Mutex - millCh chan bool - startMill sync.Once + millCh chan struct{} } var ( @@ -175,6 +174,10 @@ func (l *Logger) close() error { } err := l.file.Close() l.file = nil + if l.millCh != nil { + close(l.millCh) + l.millCh = nil + } return err } @@ -375,8 +378,8 @@ func (l *Logger) millRunOnce() error { // millRun runs in a goroutine to manage post-rotation compression and removal // of old log files. -func (l *Logger) millRun() { - for _ = range l.millCh { +func (l *Logger) millRun(ch <-chan struct{}) { + for range ch { // what am I going to do, log this? _ = l.millRunOnce() } @@ -385,12 +388,13 @@ func (l *Logger) millRun() { // mill performs post-rotation compression and removal of stale log files, // starting the mill goroutine if necessary. func (l *Logger) mill() { - l.startMill.Do(func() { - l.millCh = make(chan bool, 1) - go l.millRun() - }) + // It is safe to check the millCh here as we are inside the mutex lock. + if l.millCh == nil { + l.millCh = make(chan struct{}, 1) + go l.millRun(l.millCh) + } select { - case l.millCh <- true: + case l.millCh <- struct{}{}: default: } } From 6dba5813cb60fba6673bcccf83d7e1c4b080b8d7 Mon Sep 17 00:00:00 2001 From: Tim Penhey Date: Fri, 27 Mar 2020 15:36:04 +1300 Subject: [PATCH 2/3] Fix the test synchronisation and race errors. While fixing the tests I noticed that the original patch closed the millRun goroutine in the wrong place. I didn't realise that the `close` method was called internally as well as part of the `rotate` method. The closing of the mill signalling channel is now done in the `Close` method. There were a bunch of race errors detected, mostly around the updating of the time, and the `fakeFS`. Synchronisation is added to these. All of the `time.After` calls have been removed from the tests and the execution time has gone from 700ms to 7ms on my machine. Two different notify channels were added to the `Logger` internals. These are only ever set in the tests, and no notification is done for any normal `Logger` use. In order to avoid spurious errors the `Close` method needed to wait for the `millRun` goroutine to complete, otherwise there was potential for the `millRunOnce` method to return errors. I temporarily added a panic to that method while testing. I use a wait group to wait for the goroutine to be complete. However due to the way the `sync.WaitGroup` works, you can't reuse them, so we have a pointer to a `sync.WaitGroup`. This patch does introduce a change in behaviour, which is in evidence due to the deleted test. Effectively I was left with two choices: allow the compression of existing old log files as part of writing to a new logger (which wouldn't rotate the files yet); or have a race in the `TestCleanupExistingBackups`. This test failure was intermittent, due to the race. I decided on determinism as the likelihood of having old uncompressed files around that needed to be compressed was small. --- linux_test.go | 49 +++++++++------ lumberjack.go | 47 ++++++++++++--- lumberjack_test.go | 144 ++++++++++++++++----------------------------- 3 files changed, 120 insertions(+), 120 deletions(-) diff --git a/linux_test.go b/linux_test.go index 2bd1684..a922f74 100644 --- a/linux_test.go +++ b/linux_test.go @@ -4,9 +4,9 @@ package lumberjack import ( "os" + "sync" "syscall" "testing" - "time" ) func TestMaintainMode(t *testing.T) { @@ -97,11 +97,13 @@ func TestCompressMaintainMode(t *testing.T) { isNil(err, t) f.Close() + notify := make(chan struct{}) l := &Logger{ - Compress: true, - Filename: filename, - MaxBackups: 1, - MaxSize: 100, // megabytes + Compress: true, + Filename: filename, + MaxBackups: 1, + MaxSize: 100, // megabytes + notifyCompressed: notify, } defer l.Close() b := []byte("boo!") @@ -114,16 +116,14 @@ func TestCompressMaintainMode(t *testing.T) { err = l.Rotate() isNil(err, t) - // we need to wait a little bit since the files get compressed on a different - // goroutine. - <-time.After(10 * time.Millisecond) + waitForNotify(notify, t) // a compressed version of the log file should now exist with the correct // mode. filename2 := backupFile(dir) info, err := os.Stat(filename) isNil(err, t) - info2, err := os.Stat(filename2+compressSuffix) + info2, err := os.Stat(filename2 + compressSuffix) isNil(err, t) equals(mode, info.Mode(), t) equals(mode, info2.Mode(), t) @@ -147,11 +147,13 @@ func TestCompressMaintainOwner(t *testing.T) { isNil(err, t) f.Close() + notify := make(chan struct{}) l := &Logger{ - Compress: true, - Filename: filename, - MaxBackups: 1, - MaxSize: 100, // megabytes + Compress: true, + Filename: filename, + MaxBackups: 1, + MaxSize: 100, // megabytes + notifyCompressed: notify, } defer l.Close() b := []byte("boo!") @@ -164,15 +166,14 @@ func TestCompressMaintainOwner(t *testing.T) { err = l.Rotate() isNil(err, t) - // we need to wait a little bit since the files get compressed on a different - // goroutine. - <-time.After(10 * time.Millisecond) + waitForNotify(notify, t) // a compressed version of the log file should now exist with the correct // owner. filename2 := backupFile(dir) - equals(555, fakeFS.files[filename2+compressSuffix].uid, t) - equals(666, fakeFS.files[filename2+compressSuffix].gid, t) + uid, gid := fakeFS.fileOwners(filename2 + compressSuffix) + equals(555, uid, t) + equals(666, gid, t) } type fakeFile struct { @@ -182,18 +183,30 @@ type fakeFile struct { type fakeFS struct { files map[string]fakeFile + mu sync.Mutex } func newFakeFS() *fakeFS { return &fakeFS{files: make(map[string]fakeFile)} } +func (fs *fakeFS) fileOwners(name string) (int, int) { + fs.mu.Lock() + defer fs.mu.Unlock() + result := fs.files[name] + return result.uid, result.gid +} + func (fs *fakeFS) Chown(name string, uid, gid int) error { + fs.mu.Lock() + defer fs.mu.Unlock() fs.files[name] = fakeFile{uid: uid, gid: gid} return nil } func (fs *fakeFS) Stat(name string) (os.FileInfo, error) { + fs.mu.Lock() + defer fs.mu.Unlock() info, err := os.Stat(name) if err != nil { return nil, err diff --git a/lumberjack.go b/lumberjack.go index edc8162..42b21a6 100644 --- a/lumberjack.go +++ b/lumberjack.go @@ -111,7 +111,18 @@ type Logger struct { file *os.File mu sync.Mutex + wg *sync.WaitGroup millCh chan struct{} + + // notifyCompressed is only set and used for tests. It is signalled when + // millRunOnce compresses some files. If no files are compressed, + // notifyCompressed is not signalled. + notifyCompressed chan struct{} + + // notifyRemoved is only set and used for tests. It is signalled when the + // millRunOnce method removes some old log files. If no files are removed, + // notifyRemoved is not signalled. + notifyRemoved chan struct{} } var ( @@ -164,7 +175,16 @@ func (l *Logger) Write(p []byte) (n int, err error) { func (l *Logger) Close() error { l.mu.Lock() defer l.mu.Unlock() - return l.close() + if err := l.close(); err != nil { + return err + } + if l.millCh != nil { + close(l.millCh) + l.wg.Wait() + l.millCh = nil + l.wg = nil + } + return nil } // close closes the file if it is open. @@ -174,10 +194,6 @@ func (l *Logger) close() error { } err := l.file.Close() l.file = nil - if l.millCh != nil { - close(l.millCh) - l.millCh = nil - } return err } @@ -265,8 +281,6 @@ func backupName(name string, local bool) string { // would not put it over MaxSize. If there is no such file or the write would // put it over the MaxSize, a new file is created. func (l *Logger) openExistingOrNew(writeLen int) error { - l.mill() - filename := l.filename() info, err := os_Stat(filename) if os.IsNotExist(err) { @@ -359,20 +373,30 @@ func (l *Logger) millRunOnce() error { } } + filesRemoved := false for _, f := range remove { errRemove := os.Remove(filepath.Join(l.dir(), f.Name())) if err == nil && errRemove != nil { err = errRemove } + filesRemoved = true + } + if filesRemoved && l.notifyRemoved != nil { + l.notifyRemoved <- struct{}{} } + + filesCompressed := false for _, f := range compress { fn := filepath.Join(l.dir(), f.Name()) errCompress := compressLogFile(fn, fn+compressSuffix) if err == nil && errCompress != nil { err = errCompress } + filesCompressed = true + } + if filesCompressed && l.notifyCompressed != nil { + l.notifyCompressed <- struct{}{} } - return err } @@ -391,7 +415,12 @@ func (l *Logger) mill() { // It is safe to check the millCh here as we are inside the mutex lock. if l.millCh == nil { l.millCh = make(chan struct{}, 1) - go l.millRun(l.millCh) + l.wg = &sync.WaitGroup{} + l.wg.Add(1) + go func() { + l.millRun(l.millCh) + l.wg.Done() + }() } select { case l.millCh <- struct{}{}: diff --git a/lumberjack_test.go b/lumberjack_test.go index 484ee9d..5f33613 100644 --- a/lumberjack_test.go +++ b/lumberjack_test.go @@ -8,6 +8,7 @@ import ( "io/ioutil" "os" "path/filepath" + "sync" "testing" "time" @@ -24,9 +25,14 @@ import ( // Since all the tests uses the time to determine filenames etc, we need to // control the wall clock as much as possible, which means having a wall clock // that doesn't change unless we want it to. -var fakeCurrentTime = time.Now() +var ( + fakeCurrentTime = time.Now() + fakeTimeMu sync.Mutex +) func fakeTime() time.Time { + fakeTimeMu.Lock() + defer fakeTimeMu.Unlock() return fakeCurrentTime } @@ -202,11 +208,13 @@ func TestMaxBackups(t *testing.T) { dir := makeTempDir("TestMaxBackups", t) defer os.RemoveAll(dir) + notify := make(chan struct{}) filename := logFile(dir) l := &Logger{ - Filename: filename, - MaxSize: 10, - MaxBackups: 1, + Filename: filename, + MaxSize: 10, + MaxBackups: 1, + notifyRemoved: notify, } defer l.Close() b := []byte("boo!") @@ -248,9 +256,7 @@ func TestMaxBackups(t *testing.T) { existsWithContent(filename, b3, t) - // we need to wait a little bit since the files get deleted on a different - // goroutine. - <-time.After(time.Millisecond * 10) + waitForNotify(notify, t) // should only have two files in the dir still fileCount(dir, 2, t) @@ -298,9 +304,7 @@ func TestMaxBackups(t *testing.T) { existsWithContent(fourthFilename, b3, t) existsWithContent(fourthFilename+compressSuffix, []byte("compress"), t) - // we need to wait a little bit since the files get deleted on a different - // goroutine. - <-time.After(time.Millisecond * 10) + waitForNotify(notify, t) // We should have four things in the directory now - the 2 log files, the // not log file, and the directory @@ -354,11 +358,12 @@ func TestCleanupExistingBackups(t *testing.T) { filename := logFile(dir) err = ioutil.WriteFile(filename, data, 0644) isNil(err, t) - + notify := make(chan struct{}) l := &Logger{ - Filename: filename, - MaxSize: 10, - MaxBackups: 1, + Filename: filename, + MaxSize: 10, + MaxBackups: 1, + notifyRemoved: notify, } defer l.Close() @@ -369,9 +374,7 @@ func TestCleanupExistingBackups(t *testing.T) { isNil(err, t) equals(len(b2), n, t) - // we need to wait a little bit since the files get deleted on a different - // goroutine. - <-time.After(time.Millisecond * 10) + waitForNotify(notify, t) // now we should only have 2 files left - the primary and one backup fileCount(dir, 2, t) @@ -385,12 +388,15 @@ func TestMaxAge(t *testing.T) { defer os.RemoveAll(dir) filename := logFile(dir) + notify := make(chan struct{}) l := &Logger{ - Filename: filename, - MaxSize: 10, - MaxAge: 1, + Filename: filename, + MaxSize: 10, + MaxAge: 1, + notifyRemoved: notify, } defer l.Close() + b := []byte("boo!") n, err := l.Write(b) isNil(err, t) @@ -408,10 +414,6 @@ func TestMaxAge(t *testing.T) { equals(len(b2), n, t) existsWithContent(backupFile(dir), b, t) - // we need to wait a little bit since the files get deleted on a different - // goroutine. - <-time.After(10 * time.Millisecond) - // We should still have 2 log files, since the most recent backup was just // created. fileCount(dir, 2, t) @@ -430,9 +432,7 @@ func TestMaxAge(t *testing.T) { equals(len(b3), n, t) existsWithContent(backupFile(dir), b2, t) - // we need to wait a little bit since the files get deleted on a different - // goroutine. - <-time.After(10 * time.Millisecond) + waitForNotify(notify, t) // We should have 2 log files - the main log file, and the most recent // backup. The earlier backup is past the cutoff and should be gone. @@ -539,11 +539,12 @@ func TestRotate(t *testing.T) { defer os.RemoveAll(dir) filename := logFile(dir) - + notify := make(chan struct{}) l := &Logger{ - Filename: filename, - MaxBackups: 1, - MaxSize: 100, // megabytes + Filename: filename, + MaxBackups: 1, + MaxSize: 100, // megabytes + notifyRemoved: notify, } defer l.Close() b := []byte("boo!") @@ -559,10 +560,6 @@ func TestRotate(t *testing.T) { err = l.Rotate() isNil(err, t) - // we need to wait a little bit since the files get deleted on a different - // goroutine. - <-time.After(10 * time.Millisecond) - filename2 := backupFile(dir) existsWithContent(filename2, b, t) existsWithContent(filename, []byte{}, t) @@ -572,9 +569,7 @@ func TestRotate(t *testing.T) { err = l.Rotate() isNil(err, t) - // we need to wait a little bit since the files get deleted on a different - // goroutine. - <-time.After(10 * time.Millisecond) + waitForNotify(notify, t) filename3 := backupFile(dir) existsWithContent(filename3, []byte{}, t) @@ -597,11 +592,13 @@ func TestCompressOnRotate(t *testing.T) { dir := makeTempDir("TestCompressOnRotate", t) defer os.RemoveAll(dir) + notify := make(chan struct{}) filename := logFile(dir) l := &Logger{ - Compress: true, - Filename: filename, - MaxSize: 10, + Compress: true, + Filename: filename, + MaxSize: 10, + notifyCompressed: notify, } defer l.Close() b := []byte("boo!") @@ -621,9 +618,7 @@ func TestCompressOnRotate(t *testing.T) { // nothing in it. existsWithContent(filename, []byte{}, t) - // we need to wait a little bit since the files get compressed on a different - // goroutine. - <-time.After(300 * time.Millisecond) + waitForNotify(notify, t) // a compressed version of the log file should now exist and the original // should have been removed. @@ -639,55 +634,6 @@ func TestCompressOnRotate(t *testing.T) { fileCount(dir, 2, t) } -func TestCompressOnResume(t *testing.T) { - currentTime = fakeTime - megabyte = 1 - - dir := makeTempDir("TestCompressOnResume", t) - defer os.RemoveAll(dir) - - filename := logFile(dir) - l := &Logger{ - Compress: true, - Filename: filename, - MaxSize: 10, - } - defer l.Close() - - // Create a backup file and empty "compressed" file. - filename2 := backupFile(dir) - b := []byte("foo!") - err := ioutil.WriteFile(filename2, b, 0644) - isNil(err, t) - err = ioutil.WriteFile(filename2+compressSuffix, []byte{}, 0644) - isNil(err, t) - - newFakeTime() - - b2 := []byte("boo!") - n, err := l.Write(b2) - isNil(err, t) - equals(len(b2), n, t) - existsWithContent(filename, b2, t) - - // we need to wait a little bit since the files get compressed on a different - // goroutine. - <-time.After(300 * time.Millisecond) - - // The write should have started the compression - a compressed version of - // the log file should now exist and the original should have been removed. - bc := new(bytes.Buffer) - gz := gzip.NewWriter(bc) - _, err = gz.Write(b) - isNil(err, t) - err = gz.Close() - isNil(err, t) - existsWithContent(filename2+compressSuffix, bc.Bytes(), t) - notExist(filename2, t) - - fileCount(dir, 2, t) -} - func TestJson(t *testing.T) { data := []byte(` { @@ -802,6 +748,8 @@ func fileCount(dir string, exp int, t testing.TB) { // newFakeTime sets the fake "current time" to two days later. func newFakeTime() { + fakeTimeMu.Lock() + defer fakeTimeMu.Unlock() fakeCurrentTime = fakeCurrentTime.Add(time.Hour * 24 * 2) } @@ -814,3 +762,13 @@ func exists(path string, t testing.TB) { _, err := os.Stat(path) assertUp(err == nil, t, 1, "expected file to exist, but got error from os.Stat: %v", err) } + +func waitForNotify(notify <-chan struct{}, t testing.TB) { + select { + case <-notify: + // All good. + case <-time.After(2 * time.Second): + fmt.Println("logger notify not signalled") + t.FailNow() + } +} From c81c01400b91ac5087fbb9179b4847ff1f1865b1 Mon Sep 17 00:00:00 2001 From: Tim Penhey Date: Fri, 27 Mar 2020 17:08:35 +1300 Subject: [PATCH 3/3] Bring back the compress on resume functionality. --- lumberjack.go | 2 ++ lumberjack_test.go | 55 +++++++++++++++++++++++++++++++++++++++++++++- 2 files changed, 56 insertions(+), 1 deletion(-) diff --git a/lumberjack.go b/lumberjack.go index 42b21a6..e137b0d 100644 --- a/lumberjack.go +++ b/lumberjack.go @@ -281,6 +281,8 @@ func backupName(name string, local bool) string { // would not put it over MaxSize. If there is no such file or the write would // put it over the MaxSize, a new file is created. func (l *Logger) openExistingOrNew(writeLen int) error { + l.mill() + filename := l.filename() info, err := os_Stat(filename) if os.IsNotExist(err) { diff --git a/lumberjack_test.go b/lumberjack_test.go index 5f33613..6a34add 100644 --- a/lumberjack_test.go +++ b/lumberjack_test.go @@ -369,7 +369,11 @@ func TestCleanupExistingBackups(t *testing.T) { newFakeTime() - b2 := []byte("foooooo!") + // Don't write enough to trigger a rotate or there is + // a race between whether or not there is one notification + // or two depending on how far through the millRunOnce method + // gets before the Write method calls rotate. + b2 := []byte("foo") n, err := l.Write(b2) isNil(err, t) equals(len(b2), n, t) @@ -634,6 +638,55 @@ func TestCompressOnRotate(t *testing.T) { fileCount(dir, 2, t) } +func TestCompressOnResume(t *testing.T) { + currentTime = fakeTime + megabyte = 1 + + dir := makeTempDir("TestCompressOnResume", t) + defer os.RemoveAll(dir) + + notify := make(chan struct{}) + filename := logFile(dir) + l := &Logger{ + Compress: true, + Filename: filename, + MaxSize: 10, + notifyCompressed: notify, + } + defer l.Close() + + // Create a backup file and empty "compressed" file. + filename2 := backupFile(dir) + b := []byte("foo!") + err := ioutil.WriteFile(filename2, b, 0644) + isNil(err, t) + err = ioutil.WriteFile(filename2+compressSuffix, []byte{}, 0644) + isNil(err, t) + + newFakeTime() + + b2 := []byte("boo!") + n, err := l.Write(b2) + isNil(err, t) + equals(len(b2), n, t) + existsWithContent(filename, b2, t) + + waitForNotify(notify, t) + + // The write should have started the compression - a compressed version of + // the log file should now exist and the original should have been removed. + bc := new(bytes.Buffer) + gz := gzip.NewWriter(bc) + _, err = gz.Write(b) + isNil(err, t) + err = gz.Close() + isNil(err, t) + existsWithContent(filename2+compressSuffix, bc.Bytes(), t) + notExist(filename2, t) + + fileCount(dir, 2, t) +} + func TestJson(t *testing.T) { data := []byte(` {