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 a47b7f0..e137b0d 100644 --- a/lumberjack.go +++ b/lumberjack.go @@ -111,8 +111,18 @@ type Logger struct { file *os.File mu sync.Mutex - millCh chan bool - startMill sync.Once + 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 ( @@ -165,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. @@ -356,27 +375,37 @@ 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 } // 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 +414,18 @@ 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) + l.wg = &sync.WaitGroup{} + l.wg.Add(1) + go func() { + l.millRun(l.millCh) + l.wg.Done() + }() + } select { - case l.millCh <- true: + case l.millCh <- struct{}{}: default: } } diff --git a/lumberjack_test.go b/lumberjack_test.go index 484ee9d..6a34add 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,24 +358,27 @@ 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() 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) - // 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 +392,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 +418,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 +436,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 +543,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 +564,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 +573,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 +596,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 +622,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. @@ -646,11 +645,13 @@ func TestCompressOnResume(t *testing.T) { dir := makeTempDir("TestCompressOnResume", 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() @@ -670,9 +671,7 @@ func TestCompressOnResume(t *testing.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) + 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. @@ -802,6 +801,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 +815,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() + } +}