2
0
Files
lumberjack/lumberjack_test.go
T
Joel Sing a96e63847d Add support for log file compression (#43)
* Check test file content, not just length.

It is insufficient to just check the length of test files,
especially given that many of the tests result in multiple files
that have the same content/length. Instead, actually check that
the file content is what it is expected to be. Vary the content
that is being written so that the test failures become apparent.

This also fixes a case where the length of the wrong value is
checked following a write (it happens to work since the length
of the value checked is the same as that written).

* Make timeFromName actually return a time.

Simplify the timeFromName parsing (we only need to slice once,
not twice) and actually parse the extracted time in the
timeFromName function rather than returning an abitrary string
that may or may not be a time. Also conver the timeFromName
tests into table driven tests.

* Add support for compressing log files.

Rather than scanning for old log files (under lock) when a rotation
occurs, a goroutine is started when we first open or create a log
file. Post-rotation compression (if enabled) and removal of stale
log files is now designated to this goroutine.

Scanning, removal and compression are run in the same goroutine in
order to minimise background disk I/O, with removals being processed
prior to compression in order to free up disk space.

This results in a small change in existing behaviour - previously
only logs would be removed when the first rotation occurs, whereas
now logs will potentially be removed when logging first starts.

* Rework file ownership test.

Previously the test only verified that the code called Chown
but failed to verify what it actually called Chown on. This
reworks the code so that we have a fake file system that tracks
file ownership.

This also simplifies upcoming additional tests.

* Clone file owner and mode on compressed log.

Clone the log file owner and the log file mode to the compressed
log file. Add tests to ensure that this is handled correctly.
2017-05-31 12:03:50 -04:00

817 lines
18 KiB
Go

package lumberjack
import (
"bytes"
"compress/gzip"
"encoding/json"
"fmt"
"io/ioutil"
"os"
"path/filepath"
"testing"
"time"
"github.com/BurntSushi/toml"
"gopkg.in/yaml.v2"
)
// !!!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.
// 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 TestNewFile(t *testing.T) {
currentTime = fakeTime
dir := makeTempDir("TestNewFile", t)
defer os.RemoveAll(dir)
l := &Logger{
Filename: logFile(dir),
}
defer l.Close()
b := []byte("boo!")
n, err := l.Write(b)
isNil(err, t)
equals(len(b), n, t)
existsWithContent(logFile(dir), b, t)
fileCount(dir, 1, t)
}
func TestOpenExisting(t *testing.T) {
currentTime = fakeTime
dir := makeTempDir("TestOpenExisting", t)
defer os.RemoveAll(dir)
filename := logFile(dir)
data := []byte("foo!")
err := ioutil.WriteFile(filename, data, 0644)
isNil(err, t)
existsWithContent(filename, data, t)
l := &Logger{
Filename: filename,
}
defer l.Close()
b := []byte("boo!")
n, err := l.Write(b)
isNil(err, t)
equals(len(b), n, t)
// make sure the file got appended
existsWithContent(filename, append(data, b...), t)
// make sure no other files were created
fileCount(dir, 1, t)
}
func TestWriteTooLong(t *testing.T) {
currentTime = fakeTime
megabyte = 1
dir := makeTempDir("TestWriteTooLong", t)
defer os.RemoveAll(dir)
l := &Logger{
Filename: logFile(dir),
MaxSize: 5,
}
defer l.Close()
b := []byte("booooooooooooooo!")
n, err := l.Write(b)
notNil(err, t)
equals(0, n, t)
equals(err.Error(),
fmt.Sprintf("write length %d exceeds maximum file size %d", len(b), l.MaxSize), t)
_, err = os.Stat(logFile(dir))
assert(os.IsNotExist(err), t, "File exists, but should not have been created")
}
func TestMakeLogDir(t *testing.T) {
currentTime = fakeTime
dir := time.Now().Format("TestMakeLogDir" + backupTimeFormat)
dir = filepath.Join(os.TempDir(), dir)
defer os.RemoveAll(dir)
filename := logFile(dir)
l := &Logger{
Filename: filename,
}
defer l.Close()
b := []byte("boo!")
n, err := l.Write(b)
isNil(err, t)
equals(len(b), n, t)
existsWithContent(logFile(dir), b, t)
fileCount(dir, 1, t)
}
func TestDefaultFilename(t *testing.T) {
currentTime = fakeTime
dir := os.TempDir()
filename := filepath.Join(dir, filepath.Base(os.Args[0])+"-lumberjack.log")
defer os.Remove(filename)
l := &Logger{}
defer l.Close()
b := []byte("boo!")
n, err := l.Write(b)
isNil(err, t)
equals(len(b), n, t)
existsWithContent(filename, b, t)
}
func TestAutoRotate(t *testing.T) {
currentTime = fakeTime
megabyte = 1
dir := makeTempDir("TestAutoRotate", t)
defer os.RemoveAll(dir)
filename := logFile(dir)
l := &Logger{
Filename: filename,
MaxSize: 10,
}
defer l.Close()
b := []byte("boo!")
n, err := l.Write(b)
isNil(err, t)
equals(len(b), n, t)
existsWithContent(filename, b, t)
fileCount(dir, 1, t)
newFakeTime()
b2 := []byte("foooooo!")
n, err = l.Write(b2)
isNil(err, t)
equals(len(b2), n, t)
// the old logfile should be moved aside and the main logfile should have
// only the last write in it.
existsWithContent(filename, b2, t)
// the backup file will use the current fake time and have the old contents.
existsWithContent(backupFile(dir), b, t)
fileCount(dir, 2, t)
}
func TestFirstWriteRotate(t *testing.T) {
currentTime = fakeTime
megabyte = 1
dir := makeTempDir("TestFirstWriteRotate", t)
defer os.RemoveAll(dir)
filename := logFile(dir)
l := &Logger{
Filename: filename,
MaxSize: 10,
}
defer l.Close()
start := []byte("boooooo!")
err := ioutil.WriteFile(filename, start, 0600)
isNil(err, t)
newFakeTime()
// this would make us rotate
b := []byte("fooo!")
n, err := l.Write(b)
isNil(err, t)
equals(len(b), n, t)
existsWithContent(filename, b, t)
existsWithContent(backupFile(dir), start, t)
fileCount(dir, 2, t)
}
func TestMaxBackups(t *testing.T) {
currentTime = fakeTime
megabyte = 1
dir := makeTempDir("TestMaxBackups", t)
defer os.RemoveAll(dir)
filename := logFile(dir)
l := &Logger{
Filename: filename,
MaxSize: 10,
MaxBackups: 1,
}
defer l.Close()
b := []byte("boo!")
n, err := l.Write(b)
isNil(err, t)
equals(len(b), n, t)
existsWithContent(filename, b, t)
fileCount(dir, 1, t)
newFakeTime()
// this will put us over the max
b2 := []byte("foooooo!")
n, err = l.Write(b2)
isNil(err, t)
equals(len(b2), n, t)
// this will use the new fake time
secondFilename := backupFile(dir)
existsWithContent(secondFilename, b, t)
// make sure the old file still exists with the same content.
existsWithContent(filename, b2, t)
fileCount(dir, 2, t)
newFakeTime()
// this will make us rotate again
b3 := []byte("baaaaaar!")
n, err = l.Write(b3)
isNil(err, t)
equals(len(b3), n, t)
// this will use the new fake time
thirdFilename := backupFile(dir)
existsWithContent(thirdFilename, b2, 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)
// should only have two files in the dir still
fileCount(dir, 2, t)
// second file name should still exist
existsWithContent(thirdFilename, b2, t)
// should have deleted the first backup
notExist(secondFilename, t)
// now test that we don't delete directories or non-logfile files
newFakeTime()
// create a file that is close to but different from the logfile name.
// It shouldn't get caught by our deletion filters.
notlogfile := logFile(dir) + ".foo"
err = ioutil.WriteFile(notlogfile, []byte("data"), 0644)
isNil(err, t)
// Make a directory that exactly matches our log file filters... it still
// shouldn't get caught by the deletion filter since it's a directory.
notlogfiledir := backupFile(dir)
err = os.Mkdir(notlogfiledir, 0700)
isNil(err, t)
newFakeTime()
// this will use the new fake time
fourthFilename := backupFile(dir)
// Create a log file that is/was being compressed - this should
// not be counted since both the compressed and the uncompressed
// log files still exist.
compLogFile := fourthFilename+compressSuffix
err = ioutil.WriteFile(compLogFile, []byte("compress"), 0644)
isNil(err, t)
// this will make us rotate again
b4 := []byte("baaaaaaz!")
n, err = l.Write(b4)
isNil(err, t)
equals(len(b4), n, 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)
// We should have four things in the directory now - the 2 log files, the
// not log file, and the directory
fileCount(dir, 5, t)
// third file name should still exist
existsWithContent(filename, b4, t)
existsWithContent(fourthFilename, b3, t)
// should have deleted the first filename
notExist(thirdFilename, t)
// the not-a-logfile should still exist
exists(notlogfile, t)
// the directory
exists(notlogfiledir, t)
}
func TestCleanupExistingBackups(t *testing.T) {
// test that if we start with more backup files than we're supposed to have
// in total, that extra ones get cleaned up when we rotate.
currentTime = fakeTime
megabyte = 1
dir := makeTempDir("TestCleanupExistingBackups", t)
defer os.RemoveAll(dir)
// make 3 backup files
data := []byte("data")
backup := backupFile(dir)
err := ioutil.WriteFile(backup, data, 0644)
isNil(err, t)
newFakeTime()
backup = backupFile(dir)
err = ioutil.WriteFile(backup+compressSuffix, data, 0644)
isNil(err, t)
newFakeTime()
backup = backupFile(dir)
err = ioutil.WriteFile(backup, data, 0644)
isNil(err, t)
// now create a primary log file with some data
filename := logFile(dir)
err = ioutil.WriteFile(filename, data, 0644)
isNil(err, t)
l := &Logger{
Filename: filename,
MaxSize: 10,
MaxBackups: 1,
}
defer l.Close()
newFakeTime()
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(time.Millisecond * 10)
// now we should only have 2 files left - the primary and one backup
fileCount(dir, 2, t)
}
func TestMaxAge(t *testing.T) {
currentTime = fakeTime
megabyte = 1
dir := makeTempDir("TestMaxAge", t)
defer os.RemoveAll(dir)
filename := logFile(dir)
l := &Logger{
Filename: filename,
MaxSize: 10,
MaxAge: 1,
}
defer l.Close()
b := []byte("boo!")
n, err := l.Write(b)
isNil(err, t)
equals(len(b), n, t)
existsWithContent(filename, b, t)
fileCount(dir, 1, t)
// two days later
newFakeTime()
b2 := []byte("foooooo!")
n, err = l.Write(b2)
isNil(err, 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)
existsWithContent(filename, b2, t)
// we should have deleted the old file due to being too old
existsWithContent(backupFile(dir), b, t)
// two days later
newFakeTime()
b3 := []byte("baaaaar!")
n, err = l.Write(b3)
isNil(err, 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)
// 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.
fileCount(dir, 2, t)
existsWithContent(filename, b3, t)
// we should have deleted the old file due to being too old
existsWithContent(backupFile(dir), b2, t)
}
func TestOldLogFiles(t *testing.T) {
currentTime = fakeTime
megabyte = 1
dir := makeTempDir("TestOldLogFiles", t)
defer os.RemoveAll(dir)
filename := logFile(dir)
data := []byte("data")
err := ioutil.WriteFile(filename, data, 07)
isNil(err, t)
// This gives us a time with the same precision as the time we get from the
// timestamp in the name.
t1, err := time.Parse(backupTimeFormat, fakeTime().UTC().Format(backupTimeFormat))
isNil(err, t)
backup := backupFile(dir)
err = ioutil.WriteFile(backup, data, 07)
isNil(err, t)
newFakeTime()
t2, err := time.Parse(backupTimeFormat, fakeTime().UTC().Format(backupTimeFormat))
isNil(err, t)
backup2 := backupFile(dir)
err = ioutil.WriteFile(backup2, data, 07)
isNil(err, t)
l := &Logger{Filename: filename}
files, err := l.oldLogFiles()
isNil(err, t)
equals(2, len(files), t)
// should be sorted by newest file first, which would be t2
equals(t2, files[0].timestamp, t)
equals(t1, files[1].timestamp, t)
}
func TestTimeFromName(t *testing.T) {
l := &Logger{Filename: "/var/log/myfoo/foo.log"}
prefix, ext := l.prefixAndExt()
tests := []struct {
filename string
want time.Time
wantErr bool
}{
{"foo-2014-05-04T14-44-33.555.log", time.Date(2014, 5, 4, 14, 44, 33, 555000000, time.UTC), false},
{"foo-2014-05-04T14-44-33.555", time.Time{}, true},
{"2014-05-04T14-44-33.555.log", time.Time{}, true},
{"foo.log", time.Time{}, true},
}
for _, test := range tests {
got, err := l.timeFromName(test.filename, prefix, ext)
equals(got, test.want, t)
equals(err != nil, test.wantErr, t)
}
}
func TestLocalTime(t *testing.T) {
currentTime = fakeTime
megabyte = 1
dir := makeTempDir("TestLocalTime", t)
defer os.RemoveAll(dir)
l := &Logger{
Filename: logFile(dir),
MaxSize: 10,
LocalTime: true,
}
defer l.Close()
b := []byte("boo!")
n, err := l.Write(b)
isNil(err, t)
equals(len(b), n, t)
b2 := []byte("fooooooo!")
n2, err := l.Write(b2)
isNil(err, t)
equals(len(b2), n2, t)
existsWithContent(logFile(dir), b2, t)
existsWithContent(backupFileLocal(dir), b, t)
}
func TestRotate(t *testing.T) {
currentTime = fakeTime
dir := makeTempDir("TestRotate", t)
defer os.RemoveAll(dir)
filename := logFile(dir)
l := &Logger{
Filename: filename,
MaxBackups: 1,
MaxSize: 100, // megabytes
}
defer l.Close()
b := []byte("boo!")
n, err := l.Write(b)
isNil(err, t)
equals(len(b), n, t)
existsWithContent(filename, b, t)
fileCount(dir, 1, t)
newFakeTime()
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)
fileCount(dir, 2, t)
newFakeTime()
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)
filename3 := backupFile(dir)
existsWithContent(filename3, []byte{}, t)
existsWithContent(filename, []byte{}, t)
fileCount(dir, 2, t)
b2 := []byte("foooooo!")
n, err = l.Write(b2)
isNil(err, t)
equals(len(b2), n, t)
// this will use the new fake time
existsWithContent(filename, b2, t)
}
func TestCompressOnRotate(t *testing.T) {
currentTime = fakeTime
megabyte = 1
dir := makeTempDir("TestCompressOnRotate", t)
defer os.RemoveAll(dir)
filename := logFile(dir)
l := &Logger{
Compress: true,
Filename: filename,
MaxSize: 10,
}
defer l.Close()
b := []byte("boo!")
n, err := l.Write(b)
isNil(err, t)
equals(len(b), n, t)
existsWithContent(filename, b, t)
fileCount(dir, 1, t)
newFakeTime()
err = l.Rotate()
isNil(err, t)
// the old logfile should be moved aside and the main logfile should have
// 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(10 * time.Millisecond)
// 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(backupFile(dir)+compressSuffix, bc.Bytes(), t)
notExist(backupFile(dir), 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(10 * 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(`
{
"filename": "foo",
"maxsize": 5,
"maxage": 10,
"maxbackups": 3,
"localtime": true,
"compress": true
}`[1:])
l := Logger{}
err := json.Unmarshal(data, &l)
isNil(err, t)
equals("foo", l.Filename, t)
equals(5, l.MaxSize, t)
equals(10, l.MaxAge, t)
equals(3, l.MaxBackups, t)
equals(true, l.LocalTime, t)
equals(true, l.Compress, t)
}
func TestYaml(t *testing.T) {
data := []byte(`
filename: foo
maxsize: 5
maxage: 10
maxbackups: 3
localtime: true
compress: true`[1:])
l := Logger{}
err := yaml.Unmarshal(data, &l)
isNil(err, t)
equals("foo", l.Filename, t)
equals(5, l.MaxSize, t)
equals(10, l.MaxAge, t)
equals(3, l.MaxBackups, t)
equals(true, l.LocalTime, t)
equals(true, l.Compress, t)
}
func TestToml(t *testing.T) {
data := `
filename = "foo"
maxsize = 5
maxage = 10
maxbackups = 3
localtime = true
compress = true`[1:]
l := Logger{}
md, err := toml.Decode(data, &l)
isNil(err, t)
equals("foo", l.Filename, t)
equals(5, l.MaxSize, t)
equals(10, l.MaxAge, t)
equals(3, l.MaxBackups, t)
equals(true, l.LocalTime, t)
equals(true, l.Compress, t)
equals(0, len(md.Undecoded()), 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.
func makeTempDir(name string, t testing.TB) string {
dir := time.Now().Format(name + backupTimeFormat)
dir = filepath.Join(os.TempDir(), dir)
isNilUp(os.Mkdir(dir, 0700), t, 1)
return dir
}
// existsWithContent checks that the given file exists and has the correct content.
func existsWithContent(path string, content []byte, t testing.TB) {
info, err := os.Stat(path)
isNilUp(err, t, 1)
equalsUp(int64(len(content)), info.Size(), t, 1)
b, err := ioutil.ReadFile(path)
isNilUp(err, t, 1)
equalsUp(content, b, t, 1)
}
// logFile returns the log file name in the given directory for the current fake
// time.
func logFile(dir string) string {
return filepath.Join(dir, "foobar.log")
}
func backupFile(dir string) string {
return filepath.Join(dir, "foobar-"+fakeTime().UTC().Format(backupTimeFormat)+".log")
}
func backupFileLocal(dir string) string {
return filepath.Join(dir, "foobar-"+fakeTime().Format(backupTimeFormat)+".log")
}
// 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(backupTimeFormat))
}
// fileCount checks that the number of files in the directory is exp.
func fileCount(dir string, exp int, t testing.TB) {
files, err := ioutil.ReadDir(dir)
isNilUp(err, t, 1)
// Make sure no other files were created.
equalsUp(exp, len(files), t, 1)
}
// newFakeTime sets the fake "current time" to two days later.
func newFakeTime() {
fakeCurrentTime = fakeCurrentTime.Add(time.Hour * 24 * 2)
}
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 %v", err)
}
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)
}