diff --git a/linux_test.go b/linux_test.go index 61dff04..445b48d 100644 --- a/linux_test.go +++ b/linux_test.go @@ -1,12 +1,13 @@ +//go:build linux // +build linux package lumberjack import ( "os" + "sync" "syscall" "testing" - "time" ) func TestMaintainMode(t *testing.T) { @@ -98,10 +99,11 @@ func TestCompressMaintainMode(t *testing.T) { f.Close() l := &Logger{ - Compress: true, - Filename: filename, - MaxBackups: 1, - MaxSize: 100, // megabytes + Compress: true, + Filename: filename, + MaxBackups: 1, + MaxSize: 100, // megabytes + notifyCompressed: make(chan struct{}), } defer l.Close() b := []byte("boo!") @@ -114,9 +116,7 @@ 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(l.notifyCompressed, t) // a compressed version of the log file should now exist with the correct // mode. @@ -148,10 +148,11 @@ func TestCompressMaintainOwner(t *testing.T) { f.Close() l := &Logger{ - Compress: true, - Filename: filename, - MaxBackups: 1, - MaxSize: 100, // megabytes + Compress: true, + Filename: filename, + MaxBackups: 1, + MaxSize: 100, // megabytes + notifyCompressed: make(chan struct{}), } defer l.Close() b := []byte("boo!") @@ -164,15 +165,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(l.notifyCompressed, 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 +182,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 3447cdc..0ab8a50 100644 --- a/lumberjack.go +++ b/lumberjack.go @@ -3,7 +3,7 @@ // Note that this is v2.0 of lumberjack, and should be imported using gopkg.in // thusly: // -// import "gopkg.in/natefinch/lumberjack.v2" +// import "gopkg.in/natefinch/lumberjack.v2" // // The package name remains simply lumberjack, and the code resides at // https://github.com/natefinch/lumberjack under the v2.0 branch. @@ -66,7 +66,7 @@ var _ io.WriteCloser = (*Logger)(nil) // `/var/log/foo/server.log`, a backup created at 6:30pm on Nov 11 2016 would // use the filename `/var/log/foo/server-2016-11-04T18-30-00.000.log` // -// Cleaning Up Old Log Files +// # Cleaning Up Old Log Files // // Whenever a new logfile gets created, old log files may be deleted. The most // recent files according to the encoded timestamp will be retained, up to a @@ -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,20 @@ 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() + + // Always close the mill channel, even if the close fails. This way we + // guarantee that the mill goroutine will exit. + err := l.close() + + if l.millCh != nil { + close(l.millCh) + l.wg.Wait() + l.millCh = nil + l.wg = nil + } + + // Return the result of the file close. + return err } // close closes the file if it is open. @@ -356,20 +379,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 } @@ -385,12 +418,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.wg.Done() + }() + } select { - case l.millCh <- true: + case l.millCh <- struct{}{}: default: } } diff --git a/lumberjack_test.go b/lumberjack_test.go index f89756c..4bde675 100644 --- a/lumberjack_test.go +++ b/lumberjack_test.go @@ -8,6 +8,7 @@ import ( "io/ioutil" "os" "path/filepath" + "sync" "testing" "time" ) @@ -21,9 +22,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 } @@ -199,11 +205,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!") @@ -245,9 +253,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) @@ -295,9 +301,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 @@ -351,24 +355,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) @@ -382,12 +389,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) @@ -405,10 +415,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) @@ -427,9 +433,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. @@ -536,11 +540,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!") @@ -556,10 +561,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) @@ -569,9 +570,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) @@ -594,11 +593,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!") @@ -618,9 +619,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. @@ -643,11 +642,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() @@ -667,9 +668,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. @@ -758,6 +757,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) } @@ -770,3 +771,14 @@ 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) { + t.Helper() + + select { + case <-notify: + // All good. + case <-time.After(2 * time.Second): + t.Fatal("logger notify not signalled") + } +}