From 48d48778cf71034bf5f3a550fdda8469087bf25a Mon Sep 17 00:00:00 2001 From: Tim Penhey Date: Thu, 26 Mar 2020 16:40:38 +1300 Subject: [PATCH 1/4] 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 | 26 +++++++++++++++----------- 1 file changed, 15 insertions(+), 11 deletions(-) diff --git a/lumberjack.go b/lumberjack.go index 3447cdc..3b910fe 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,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 1524e41e57d01242be7e1dfce43acfb0bdd24e50 Mon Sep 17 00:00:00 2001 From: Tim Penhey Date: Fri, 27 Mar 2020 15:36:04 +1300 Subject: [PATCH 2/4] 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 | 48 +++++++++------ lumberjack.go | 47 ++++++++++++--- lumberjack_test.go | 144 ++++++++++++++++----------------------------- 3 files changed, 120 insertions(+), 119 deletions(-) diff --git a/linux_test.go b/linux_test.go index 61dff04..ea96fae 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) { @@ -97,11 +98,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,9 +117,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(notify, t) // a compressed version of the log file should now exist with the correct // mode. @@ -147,11 +148,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 +167,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 +184,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 3b910fe..015fe1b 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 := osStat(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 f89756c..4ce82ae 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,11 +355,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() @@ -366,9 +371,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) @@ -382,12 +385,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 +411,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 +429,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 +536,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 +557,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 +566,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 +589,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 +615,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. @@ -636,55 +631,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(` { @@ -758,6 +704,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 +718,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 0dc8bb3658db1bd0d8454e641fac38bdf7f4d3ee Mon Sep 17 00:00:00 2001 From: Tim Penhey Date: Fri, 27 Mar 2020 17:08:35 +1300 Subject: [PATCH 3/4] 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 015fe1b..d7a8842 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 := osStat(filename) if os.IsNotExist(err) { diff --git a/lumberjack_test.go b/lumberjack_test.go index 4ce82ae..34b8b4c 100644 --- a/lumberjack_test.go +++ b/lumberjack_test.go @@ -366,7 +366,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) @@ -631,6 +635,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(` { From 012c0c2b9ae22f2cf0ab58ceba99758879637165 Mon Sep 17 00:00:00 2001 From: Simon Richardson Date: Wed, 22 May 2024 12:46:04 +0100 Subject: [PATCH 4/4] Use internal channels As feedback from a code review, use the struct channels as a way of self documenting the code. This makes the code more readable. --- linux_test.go | 10 ++++------ lumberjack.go | 18 +++++++++++------- lumberjack_test.go | 5 +++-- 3 files changed, 18 insertions(+), 15 deletions(-) diff --git a/linux_test.go b/linux_test.go index ea96fae..445b48d 100644 --- a/linux_test.go +++ b/linux_test.go @@ -98,13 +98,12 @@ 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 - notifyCompressed: notify, + notifyCompressed: make(chan struct{}), } defer l.Close() b := []byte("boo!") @@ -117,7 +116,7 @@ func TestCompressMaintainMode(t *testing.T) { err = l.Rotate() isNil(err, t) - waitForNotify(notify, t) + waitForNotify(l.notifyCompressed, t) // a compressed version of the log file should now exist with the correct // mode. @@ -148,13 +147,12 @@ 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 - notifyCompressed: notify, + notifyCompressed: make(chan struct{}), } defer l.Close() b := []byte("boo!") @@ -167,7 +165,7 @@ func TestCompressMaintainOwner(t *testing.T) { err = l.Rotate() isNil(err, t) - waitForNotify(notify, t) + waitForNotify(l.notifyCompressed, t) // a compressed version of the log file should now exist with the correct // owner. diff --git a/lumberjack.go b/lumberjack.go index d7a8842..0ab8a50 100644 --- a/lumberjack.go +++ b/lumberjack.go @@ -175,16 +175,20 @@ func (l *Logger) Write(p []byte) (n int, err error) { func (l *Logger) Close() error { l.mu.Lock() defer l.mu.Unlock() - if err := l.close(); err != nil { - return err - } + + // 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 nil + + // Return the result of the file close. + return err } // close closes the file if it is open. @@ -404,8 +408,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(ch <-chan struct{}) { - for range ch { +func (l *Logger) millRun() { + for range l.millCh { // what am I going to do, log this? _ = l.millRunOnce() } @@ -420,7 +424,7 @@ func (l *Logger) mill() { l.wg = &sync.WaitGroup{} l.wg.Add(1) go func() { - l.millRun(l.millCh) + l.millRun() l.wg.Done() }() } diff --git a/lumberjack_test.go b/lumberjack_test.go index 34b8b4c..4bde675 100644 --- a/lumberjack_test.go +++ b/lumberjack_test.go @@ -773,11 +773,12 @@ func exists(path string, t testing.TB) { } func waitForNotify(notify <-chan struct{}, t testing.TB) { + t.Helper() + select { case <-notify: // All good. case <-time.After(2 * time.Second): - fmt.Println("logger notify not signalled") - t.FailNow() + t.Fatal("logger notify not signalled") } }