diff --git a/lumberjack.go b/lumberjack.go index 5781f63..30643f7 100644 --- a/lumberjack.go +++ b/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 -// formatting layouts, read http://golang.org/pkg/time/#pkg-constants. +// layout in it that produces a valid unique filename for the OS. For more +// 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 -// modified file in the log file directory that matches the NameFormat is less -// 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. +// The date encoded in the filename by NameFormat is used to determine which log +// files are most recent in several situations. +// +// 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 -// modified files which are newer than MaxAge (up to a number of files equal to -// Backups) are retained, all other log files are deleted. +// directory is scanned for files that match NameFormat. The most recent files +// according to their NameFormat date will be retained, up to a number equal to +// 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 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. +// If MaxBackups and MaxAge are both 0, no old log files will be deleted. 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 - // to remove old log files based on age. + // MaxAge is the maximum time to retain old log files based on + // 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 - // to retain all old log files (though MaxAge may still cause them to get + // MaxBackups is the maximum number of old log files to retain. The default + // 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 { - deletes = files[l.Backups:] - files = files[:l.Backups] + if l.MaxBackups > 0 { + deletes = files[l.MaxBackups:] + 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) diff --git a/lumberjack_test.go b/lumberjack_test.go index 7645507..2907ab2 100644 --- a/lumberjack_test.go +++ b/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 -const timeString = "2009-11-10T13-22-33.444" - -var fakeCurrentTime = time.Date(2009, time.November, 10, 13, 22, 33, 444000000, time.UTC) +// 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() 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) } diff --git a/testing_test.go b/testing_test.go index 2b1b944..8e89c08 100644 --- a/testing_test.go +++ b/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