more tests and fixed a bug the tests found. Cleaned up the documentation. Renamed Backups to MaxBackups.

lumberjack.go

@@ -15,12 +15,16 @@
 //       Dir: "/var/log/myapp/"
 //       NameFormat: time.RFC822+".log",
 //       MaxSize: lumberjack.Gigabyte,
-//       Backups: 3,
+//       MaxBackups: 3,
 //       MaxAge: lumberjack.Week * 4,
 //   ))
 //
 // Note that lumberjack assumes whatever is writing to it will use locks to
 // prevent concurrent writes. Lumberjack does not implement its own lock.
+//
+// Lumberjack also assumes that only one process is writing to the output files.
+// Using the same lumberjack configuration from multiple processes on the same
+// machine will result in improper behavior.
 package lumberjack
 
 import (
@@ -52,13 +56,18 @@ var _ io.WriteCloser = &Logger{}
 
 // Logger is an io.WriteCloser that writes to a log file in the given directory
 // with the given NameFormat.  NameFormat should include a time formatting
-// layout in it that produces a valid filename for the OS.  For more about time
+// layout in it that produces a valid unique filename for the OS.  For more
-// formatting layouts, read http://golang.org/pkg/time/#pkg-constants.
+// about time formatting layouts, read http://golang.org/pkg/time/#pkg-
+// constants.
 //
-// Logger opens or creates the logfile on first Write.  If the most recently
+// The date encoded in the filename by NameFormat is used to determine which log
-// modified file in the log file directory that matches the NameFormat is less
+// files are most recent in several situations.
-// than MaxSize, that file will be appended to.  If no file such exists, a new
+//
-// file is created using the current time to generate the filename.
+// Logger opens or creates a logfile on first Write.  It looks for files in the
+// directory that match its name format, and if the one with the most recent
+// NameFormat date is less than MaxSize, it will open and append to that file.
+// If no such file exists, or the file is >= MaxSize, a new file is created
+// using the current time with NameFormat to generate the filename.
 //
 // Whenever a write would cause the current log file exceed MaxSize, a new file
 // is created using the current time.
@@ -66,29 +75,13 @@ var _ io.WriteCloser = &Logger{}
 // Cleaning Up Old Log Files
 //
 // Whenever a new file gets created, old log files may be deleted.  The log file
-// directory is scanned for files that match NameFormat.  The most recently
+// directory is scanned for files that match NameFormat.  The most recent files
-// modified files which are newer than MaxAge (up to a number of files equal to
+// according to their NameFormat date will be retained, up to a number equal to
-// Backups) are retained, all other log files are deleted.
+// MaxBackups (or all of them if MaxBackups is 0).  Any files with a last
+// modified time (based on FileInfo.ModTime) older than MaxAge are deleted,
+// regardless of MaxBackups.
 //
-// Defaults
+// If MaxBackups and MaxAge are both 0, no old log files will be deleted.
-//
-// If Dir is empty, the files will be created in os.TempDir().
-//
-// If NameFormat is empty,  will be used as the
-// name format.
-//
-// If MaxSize is 0, 100 megabytes will be used as the max size.
-//
-// if MaxAge is 0, last modification time will not be used to delete old log
-// files.
-//
-// If Backups is 0, there's no limit to the number of old log files that will be
-// retained, as long as they're newer than MaxAge.
-//
-// If MaxAge and Backups are both 0, no old log files will be deteled.
-//
-// Thus, an default lumberjack.Logger struct will log to os.TempDir() with a 100
-// megabyte max size and never delete old log files.
 type Logger struct {
 	// Dir determines the directory in which to store log files.
 	// It defaults to os.TempDir() if empty.
@@ -102,14 +95,15 @@ type Logger struct {
 	// rolled. It defaults to 100 megabytes.
 	MaxSize int64
 
-	// MaxAge is the maximum time to retain old log files.  The default is not
+	// MaxAge is the maximum time to retain old log files based on
-	// to remove old log files based on age.
+	// FileInfo.ModTime.  The default is not to remove old log files based on
+	// age.
 	MaxAge time.Duration
 
-	// Backups is the maximum number of old log files to retain.  The default is
+	// MaxBackups is the maximum number of old log files to retain.  The default
-	// to retain all old log files (though MaxAge may still cause them to get
+	// is to retain all old log files (though MaxAge may still cause them to get
 	// deleted.)
-	Backups int
+	MaxBackups int
 
 	// LocalTime determines if the time used for formatting the filename is the
 	// computer's local time.  The default is to use UTC time.
@@ -148,16 +142,17 @@ func (l *Logger) Write(p []byte) (n int, err error) {
 	n, err = f.Write(p)
 	l.size += int64(n)
 
+	if l.file != nil && rotate {
+		l.file.Close()
+	}
+	l.file = f
+
 	if rotate {
 		if err := l.cleanup(); err != nil {
 			return 0, err
 		}
 	}
 
-	if l.file != nil && rotate {
-		l.file.Close()
-	}
-	l.file = f
 	return n, err
 }
 
@@ -229,10 +224,10 @@ func (l *Logger) genFilename() string {
 	return filepath.Join(l.dir(), t.Format(l.format()))
 }
 
-// cleanup deletes old log files, keeping at most l.Backups files, as long as
+// cleanup deletes old log files, keeping at most l.MaxBackups files, as long as
 // none of them are older than MaxAge.
 func (l *Logger) cleanup() error {
-	if l.Backups == 0 && l.MaxAge == 0 {
+	if l.MaxBackups == 0 && l.MaxAge == 0 {
 		return nil
 	}
 
@@ -243,13 +238,13 @@ func (l *Logger) cleanup() error {
 
 	var deletes []os.FileInfo
 
-	if l.Backups > 0 {
+	if l.MaxBackups > 0 {
-		deletes = files[l.Backups:]
+		deletes = files[l.MaxBackups:]
-		files = files[:l.Backups]
+		files = files[:l.MaxBackups]
 	}
-
 	if l.MaxAge > 0 {
 		cutoff := currentTime().Add(-1 * l.MaxAge)
+
 		for _, f := range files {
 			if f.ModTime().Before(cutoff) {
 				deletes = append(deletes, f)

lumberjack_test.go

@@ -8,26 +8,27 @@ import (
 	"time"
 )
 
+// !!!NOTE!!!
+//
+// Running these tests in parallel will almost certainly cause sporadic (or even
+// regular) failures, because they're all messing with the same global variable
+// that controls the logic's mocked time.Now.  So... don't do that.
+
 // make sure we set the format to something safe for windows, too.
 const format = "2006-01-02T15-04-05.000"
 
-// this is the expected format for faketime goven the
+// Since all the tests uses the time to determine filenames etc, we need to
-const timeString = "2009-11-10T13-22-33.444"
+// 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.Date(2009, time.November, 10, 13, 22, 33, 444000000, time.UTC)
+var fakeCurrentTime = time.Now()
 
 func fakeTime() time.Time {
 	return fakeCurrentTime
 }
 
-func TestFakeTime(t *testing.T) {
-	// test the tests
-	s := fakeTime().Format(format)
-	equals(timeString, s, t)
-}
-
 func TestNewFile(t *testing.T) {
 	currentTime = fakeTime
+
 	dir := makeTempDir("TestNewFile", t)
 	defer os.RemoveAll(dir)
 	l := &Logger{
@@ -113,7 +114,7 @@ func TestRotate(t *testing.T) {
 	fileCount(dir, 1, t)
 
 	// set the current time one day later
-	defer newFakeTime()()
+	defer newFakeTime(Day)()
 
 	b2 := []byte("foooooo!")
 	n, err = l.Write(b2)
@@ -130,16 +131,16 @@ func TestRotate(t *testing.T) {
 	fileCount(dir, 2, t)
 }
 
-func TestBackups(t *testing.T) {
+func TestMaxBackups(t *testing.T) {
 	currentTime = fakeTime
-	dir := makeTempDir("TestBackups", t)
+	dir := makeTempDir("TestMaxBackups", t)
 	defer os.RemoveAll(dir)
 
 	l := &Logger{
 		Dir:        dir,
 		NameFormat: format,
 		MaxSize:    10,
-		Backups:    1,
+		MaxBackups: 1,
 	}
 	defer l.Close()
 	b := []byte("boo!")
@@ -152,7 +153,7 @@ func TestBackups(t *testing.T) {
 	fileCount(dir, 1, t)
 
 	// set the current time one day later
-	defer newFakeTime()()
+	defer newFakeTime(Day)()
 
 	// this will put us over the max
 	b2 := []byte("foooooo!")
@@ -170,7 +171,7 @@ func TestBackups(t *testing.T) {
 	fileCount(dir, 2, t)
 
 	// set the current time one day later
-	defer newFakeTime()()
+	defer newFakeTime(Day)()
 
 	// this will make us rotate again
 	n, err = l.Write(b2)
@@ -195,6 +196,76 @@ func TestBackups(t *testing.T) {
 	notExist(firstFilename, t)
 }
 
+func TestMaxAge(t *testing.T) {
+	currentTime = fakeTime
+	// This test uses ModTime on files, and so we need to make sure we're using
+	// the most current time possible.
+	fakeCurrentTime = time.Now()
+	dir := makeTempDir("TestMaxAge", t)
+	defer os.RemoveAll(dir)
+
+	l := &Logger{
+		Dir:        dir,
+		NameFormat: format,
+		MaxSize:    10,
+		MaxAge:     10 * time.Millisecond,
+	}
+	defer l.Close()
+	b := []byte("boo!")
+	n, err := l.Write(b)
+	isNil(err, t)
+	equals(len(b), n, t)
+
+	filename := logFile(dir)
+	existsWithLen(filename, n, t)
+	fileCount(dir, 1, t)
+
+	// We need to wait for wall clock time since MaxAge uses file ModTime, which
+	// can't be mocked.
+	<-time.After(50 * time.Millisecond)
+	fakeCurrentTime = time.Now()
+
+	b2 := []byte("foooooo!")
+	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(10 * time.Millisecond)
+
+	// We should have just one log file
+	fileCount(dir, 1, t)
+
+	// this will use the new fake time
+	newFilename := logFile(dir)
+	existsWithLen(newFilename, n, t)
+
+	// we should have deleted the old file due to being too old
+	notExist(filename, t)
+}
+
+func TestLocalTime(t *testing.T) {
+	currentTime = fakeTime
+
+	dir := makeTempDir("TestMaxAge", t)
+	defer os.RemoveAll(dir)
+
+	l := &Logger{
+		Dir:        dir,
+		NameFormat: format,
+		LocalTime:  true,
+	}
+	defer l.Close()
+	b := []byte("boo!")
+	n, err := l.Write(b)
+	isNil(err, t)
+	equals(len(b), n, t)
+
+	filename := logFileLocal(dir)
+	existsWithLen(filename, n, t)
+}
+
 // makeTempDir creates a file with a semi-unique name in the OS temp directory.
 // It should be based on the name of the test, to keep parallel tests from
 // colliding, and must be cleaned up after the test is finished.
@@ -215,6 +286,12 @@ func existsWithLen(path string, length int, t testing.TB) {
 // logFile returns the log file name in the given directory for the current fake
 // time.
 func logFile(dir string) string {
+	return filepath.Join(dir, fakeTime().UTC().Format(format))
+}
+
+// logFileLocal returns the log file name in the given directory for the current
+// fake time using the local timezone.
+func logFileLocal(dir string) string {
 	return filepath.Join(dir, fakeTime().Format(format))
 }
 
@@ -227,9 +304,9 @@ func fileCount(dir string, exp int, t testing.TB) {
 }
 
 // newFakeTime sets the fake "current time" to one day later.
-func newFakeTime() func() {
+func newFakeTime(later time.Duration) func() {
 	old := fakeCurrentTime
-	fakeCurrentTime = fakeCurrentTime.Add(Day)
+	fakeCurrentTime = fakeCurrentTime.Add(later)
 	return func() {
 		fakeCurrentTime = old
 	}
@@ -237,5 +314,5 @@ func newFakeTime() func() {
 
 func notExist(path string, t testing.TB) {
 	_, err := os.Stat(path)
-	assertUp(os.IsNotExist(err), t, 1, "expected to get os.IsNotExist, but instead got %s", err)
+	assertUp(os.IsNotExist(err), t, 1, "expected to get os.IsNotExist, but instead got %v", err)
 }

testing_test.go

@@ -8,10 +8,14 @@ import (
 	"testing"
 )
 
+// assert will log the given message if condition is false.
 func assert(condition bool, t testing.TB, msg string, v ...interface{}) {
 	assertUp(condition, t, 1, msg, v...)
 }
 
+// assertUp is like assert, but used inside helper functions, to ensure that
+// the file and line number reported by failures corresponds to one or more
+// levels up the stack.
 func assertUp(condition bool, t testing.TB, caller int, msg string, v ...interface{}) {
 	if !condition {
 		_, file, line, _ := runtime.Caller(caller + 1)
@@ -21,10 +25,14 @@ func assertUp(condition bool, t testing.TB, caller int, msg string, v ...interfa
 	}
 }
 
+// equals tests that the two values are equal according to reflect.DeepEqual.
 func equals(exp, act interface{}, t testing.TB) {
 	equalsUp(exp, act, t, 1)
 }
 
+// equalsUp is like equals, but used inside helper functions, to ensure that the
+// file and line number reported by failures corresponds to one or more levels
+// up the stack.
 func equalsUp(exp, act interface{}, t testing.TB, caller int) {
 	if !reflect.DeepEqual(exp, act) {
 		_, file, line, _ := runtime.Caller(caller + 1)
@@ -34,10 +42,15 @@ func equalsUp(exp, act interface{}, t testing.TB, caller int) {
 	}
 }
 
+// isNil reports a failure if the given value is not nil.  Note that values
+// which cannot be nil will always fail this check.
 func isNil(obtained interface{}, t testing.TB) {
 	isNilUp(obtained, t, 1)
 }
 
+// isNilUp is like isNil, but used inside helper functions, to ensure that the
+// file and line number reported by failures corresponds to one or more levels
+// up the stack.
 func isNilUp(obtained interface{}, t testing.TB, caller int) {
 	if !_isNil(obtained) {
 		_, file, line, _ := runtime.Caller(caller + 1)
@@ -46,10 +59,14 @@ func isNilUp(obtained interface{}, t testing.TB, caller int) {
 	}
 }
 
+// notNil reports a failure if the given value is nil.
 func notNil(obtained interface{}, t testing.TB) {
 	notNilUp(obtained, t, 1)
 }
 
+// notNilUp is like notNil, but used inside helper functions, to ensure that the
+// file and line number reported by failures corresponds to one or more levels
+// up the stack.
 func notNilUp(obtained interface{}, t testing.TB, caller int) {
 	if _isNil(obtained) {
 		_, file, line, _ := runtime.Caller(caller + 1)
@@ -58,6 +75,8 @@ func notNilUp(obtained interface{}, t testing.TB, caller int) {
 	}
 }
 
+// _isNil is a helper function for isNil and notNil, and should not be used
+// directly.
 func _isNil(obtained interface{}) bool {
 	if obtained == nil {
 		return true