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

@@ -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

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{}{}: