From b26579531e58ffba9aab1ed0d1cca9a9cc841d8b Mon Sep 17 00:00:00 2001 From: NoahLan <6995syu@163.com> Date: Thu, 20 Jul 2023 17:20:30 +0800 Subject: [PATCH] chore: improve logx gzip --- nlog/fs.go | 40 +++++ nlog/rotatelogger.go | 33 ++-- nlog/rotatelogger_test.go | 315 ++++++++++++++++++++++++++++++++++---- 3 files changed, 345 insertions(+), 43 deletions(-) create mode 100644 nlog/fs.go diff --git a/nlog/fs.go b/nlog/fs.go new file mode 100644 index 0000000..69337fa --- /dev/null +++ b/nlog/fs.go @@ -0,0 +1,40 @@ +package nlog + +import ( + "io" + "os" +) + +var fileSys realFileSystem + +type ( + fileSystem interface { + Close(closer io.Closer) error + Copy(writer io.Writer, reader io.Reader) (int64, error) + Create(name string) (*os.File, error) + Open(name string) (*os.File, error) + Remove(name string) error + } + + realFileSystem struct{} +) + +func (fs realFileSystem) Close(closer io.Closer) error { + return closer.Close() +} + +func (fs realFileSystem) Copy(writer io.Writer, reader io.Reader) (int64, error) { + return io.Copy(writer, reader) +} + +func (fs realFileSystem) Create(name string) (*os.File, error) { + return os.Create(name) +} + +func (fs realFileSystem) Open(name string) (*os.File, error) { + return os.Open(name) +} + +func (fs realFileSystem) Remove(name string) error { + return os.Remove(name) +} diff --git a/nlog/rotatelogger.go b/nlog/rotatelogger.go index f5627fe..22c25c1 100644 --- a/nlog/rotatelogger.go +++ b/nlog/rotatelogger.go @@ -5,7 +5,6 @@ import ( "errors" "fmt" "git.noahlan.cn/noahlan/ntool/nfs" - "io" "log" "os" "path" @@ -404,7 +403,7 @@ func (l *RotateLogger) write(v []byte) { func compressLogFile(file string) { start := time.Now() Infof("compressing log file: %s", file) - if err := gzipFile(file); err != nil { + if err := gzipFile(file, fileSys); err != nil { Errorf("compress error: %s", err) } else { Infof("compressed log file: %s, took %s", file, time.Since(start)) @@ -419,25 +418,37 @@ func getNowDateInRFC3339Format() string { return time.Now().Format(fileTimeFormat) } -func gzipFile(file string) error { - in, err := os.Open(file) +func gzipFile(file string, fsys fileSystem) error { + in, err := fsys.Open(file) if err != nil { return err } - defer in.Close() + defer func() { + if e := fsys.Close(in); e != nil { + Errorf("failed to close file: %s, error: %v", file, e) + } + if err == nil { + // only remove the original file when compression is successful + err = fsys.Remove(file) + } + }() - out, err := os.Create(fmt.Sprintf("%s%s", file, gzipExt)) + out, err := fsys.Create(fmt.Sprintf("%s%s", file, gzipExt)) if err != nil { return err } - defer out.Close() + defer func() { + e := fsys.Close(out) + if err == nil { + err = e + } + }() w := gzip.NewWriter(out) - if _, err = io.Copy(w, in); err != nil { - return err - } else if err = w.Close(); err != nil { + if _, err = fsys.Copy(w, in); err != nil { + // failed to copy, no need to close w return err } - return os.Remove(file) + return fsys.Remove(file) } diff --git a/nlog/rotatelogger_test.go b/nlog/rotatelogger_test.go index b0704e5..1e1d77b 100644 --- a/nlog/rotatelogger_test.go +++ b/nlog/rotatelogger_test.go @@ -1,30 +1,74 @@ package nlog import ( + "errors" "git.noahlan.cn/noahlan/ntool/nfs" "git.noahlan.cn/noahlan/ntool/nrandom" + "io" "os" + "path" "path/filepath" + "sync/atomic" "syscall" "testing" "time" - "git.noahlan.cn/noahlan/ntool/ntest/assert" + "github.com/stretchr/testify/assert" ) func TestDailyRotateRuleMarkRotated(t *testing.T) { - var rule DailyRotateRule - rule.MarkRotated() - assert.Equal(t, getNowDate(), rule.rotatedTime) + t.Run("daily rule", func(t *testing.T) { + var rule DailyRotateRule + rule.MarkRotated() + assert.Equal(t, getNowDate(), rule.rotatedTime) + }) + + t.Run("daily rule", func(t *testing.T) { + rule := DefaultRotateRule("test", "-", 1, false) + _, ok := rule.(*DailyRotateRule) + assert.True(t, ok) + }) } func TestDailyRotateRuleOutdatedFiles(t *testing.T) { - var rule DailyRotateRule - assert.Empty(t, rule.OutdatedFiles()) - rule.days = 1 - assert.Empty(t, rule.OutdatedFiles()) - rule.gzip = true - assert.Empty(t, rule.OutdatedFiles()) + t.Run("no files", func(t *testing.T) { + var rule DailyRotateRule + assert.Empty(t, rule.OutdatedFiles()) + rule.days = 1 + assert.Empty(t, rule.OutdatedFiles()) + rule.gzip = true + assert.Empty(t, rule.OutdatedFiles()) + }) + + t.Run("bad files", func(t *testing.T) { + rule := DailyRotateRule{ + filename: "[a-z", + } + assert.Empty(t, rule.OutdatedFiles()) + rule.days = 1 + assert.Empty(t, rule.OutdatedFiles()) + rule.gzip = true + assert.Empty(t, rule.OutdatedFiles()) + }) + + t.Run("temp files", func(t *testing.T) { + boundary := time.Now().Add(-time.Hour * time.Duration(hoursPerDay) * 2).Format(dateFormat) + f1, err := os.CreateTemp(os.TempDir(), "go-zero-test-"+boundary) + assert.NoError(t, err) + _ = f1.Close() + f2, err := os.CreateTemp(os.TempDir(), "go-zero-test-"+boundary) + assert.NoError(t, err) + _ = f2.Close() + t.Cleanup(func() { + _ = os.Remove(f1.Name()) + _ = os.Remove(f2.Name()) + }) + rule := DailyRotateRule{ + filename: path.Join(os.TempDir(), "go-zero-test-"), + days: 1, + } + assert.NotEmpty(t, rule.OutdatedFiles()) + }) } func TestDailyRotateRuleShallRotate(t *testing.T) { @@ -34,20 +78,101 @@ func TestDailyRotateRuleShallRotate(t *testing.T) { } func TestSizeLimitRotateRuleMarkRotated(t *testing.T) { - var rule SizeLimitRotateRule - rule.MarkRotated() - assert.Equal(t, getNowDateInRFC3339Format(), rule.rotatedTime) + t.Run("size limit rule", func(t *testing.T) { + var rule SizeLimitRotateRule + rule.MarkRotated() + assert.Equal(t, getNowDateInRFC3339Format(), rule.rotatedTime) + }) + + t.Run("size limit rule", func(t *testing.T) { + rule := NewSizeLimitRotateRule("foo", "-", 1, 1, 1, false) + rule.MarkRotated() + assert.Equal(t, getNowDateInRFC3339Format(), rule.(*SizeLimitRotateRule).rotatedTime) + }) } func TestSizeLimitRotateRuleOutdatedFiles(t *testing.T) { - var rule SizeLimitRotateRule - assert.Empty(t, rule.OutdatedFiles()) - rule.days = 1 - assert.Empty(t, rule.OutdatedFiles()) - rule.gzip = true - assert.Empty(t, rule.OutdatedFiles()) - rule.maxBackups = 0 - assert.Empty(t, rule.OutdatedFiles()) + t.Run("no files", func(t *testing.T) { + var rule SizeLimitRotateRule + assert.Empty(t, rule.OutdatedFiles()) + rule.days = 1 + assert.Empty(t, rule.OutdatedFiles()) + rule.gzip = true + assert.Empty(t, rule.OutdatedFiles()) + rule.maxBackups = 0 + assert.Empty(t, rule.OutdatedFiles()) + }) + + t.Run("bad files", func(t *testing.T) { + rule := SizeLimitRotateRule{ + DailyRotateRule: DailyRotateRule{ + filename: "[a-z", + }, + } + assert.Empty(t, rule.OutdatedFiles()) + rule.days = 1 + assert.Empty(t, rule.OutdatedFiles()) + rule.gzip = true + assert.Empty(t, rule.OutdatedFiles()) + }) + + t.Run("temp files", func(t *testing.T) { + boundary := time.Now().Add(-time.Hour * time.Duration(hoursPerDay) * 2).Format(dateFormat) + f1, err := os.CreateTemp(os.TempDir(), "go-zero-test-"+boundary) + assert.NoError(t, err) + f2, err := os.CreateTemp(os.TempDir(), "go-zero-test-"+boundary) + assert.NoError(t, err) + boundary1 := time.Now().Add(time.Hour * time.Duration(hoursPerDay) * 2).Format(dateFormat) + f3, err := os.CreateTemp(os.TempDir(), "go-zero-test-"+boundary1) + assert.NoError(t, err) + t.Cleanup(func() { + _ = f1.Close() + _ = os.Remove(f1.Name()) + _ = f2.Close() + _ = os.Remove(f2.Name()) + _ = f3.Close() + _ = os.Remove(f3.Name()) + }) + rule := SizeLimitRotateRule{ + DailyRotateRule: DailyRotateRule{ + filename: path.Join(os.TempDir(), "go-zero-test-"), + days: 1, + }, + maxBackups: 3, + } + assert.NotEmpty(t, rule.OutdatedFiles()) + }) + + t.Run("no backups", func(t *testing.T) { + boundary := time.Now().Add(-time.Hour * time.Duration(hoursPerDay) * 2).Format(dateFormat) + f1, err := os.CreateTemp(os.TempDir(), "go-zero-test-"+boundary) + assert.NoError(t, err) + f2, err := os.CreateTemp(os.TempDir(), "go-zero-test-"+boundary) + assert.NoError(t, err) + boundary1 := time.Now().Add(time.Hour * time.Duration(hoursPerDay) * 2).Format(dateFormat) + f3, err := os.CreateTemp(os.TempDir(), "go-zero-test-"+boundary1) + assert.NoError(t, err) + t.Cleanup(func() { + _ = f1.Close() + _ = os.Remove(f1.Name()) + _ = f2.Close() + _ = os.Remove(f2.Name()) + _ = f3.Close() + _ = os.Remove(f3.Name()) + }) + rule := SizeLimitRotateRule{ + DailyRotateRule: DailyRotateRule{ + filename: path.Join(os.TempDir(), "go-zero-test-"), + days: 1, + }, + } + assert.NotEmpty(t, rule.OutdatedFiles()) + + logger := new(RotateLogger) + logger.rule = &rule + logger.maybeDeleteOutdatedFiles() + assert.Empty(t, rule.OutdatedFiles()) + }) } func TestSizeLimitRotateRuleShallRotate(t *testing.T) { @@ -61,14 +186,26 @@ func TestSizeLimitRotateRuleShallRotate(t *testing.T) { } func TestRotateLoggerClose(t *testing.T) { - filename, err := nfs.OSTempFilenameWithContent("foo") - assert.Nil(t, err) - if len(filename) > 0 { - defer os.Remove(filename) - } - logger, err := NewLogger(filename, new(DailyRotateRule), false) - assert.Nil(t, err) - assert.Nil(t, logger.Close()) + t.Run("close", func(t *testing.T) { + filename, err := nfs.OSTempFilenameWithContent("foo") + assert.Nil(t, err) + if len(filename) > 0 { + defer os.Remove(filename) + } + logger, err := NewLogger(filename, new(DailyRotateRule), false) + assert.Nil(t, err) + _, err = logger.Write([]byte("foo")) + assert.Nil(t, err) + assert.Nil(t, logger.Close()) + }) + + t.Run("close and write", func(t *testing.T) { + logger := new(RotateLogger) + logger.done = make(chan struct{}) + close(logger.done) + _, err := logger.Write([]byte("foo")) + assert.ErrorIs(t, err, ErrLogFileClosed) + }) } func TestRotateLoggerGetBackupFilename(t *testing.T) { @@ -179,7 +316,7 @@ func TestRotateLoggerWithSizeLimitRotateRuleClose(t *testing.T) { } logger, err := NewLogger(filename, new(SizeLimitRotateRule), false) assert.Nil(t, err) - assert.Nil(t, logger.Close()) + _ = logger.Close() } func TestRotateLoggerGetBackupWithSizeLimitRotateRuleFilename(t *testing.T) { @@ -240,12 +377,12 @@ func TestRotateLoggerWithSizeLimitRotateRuleMayCompressFileFailed(t *testing.T) os.Stdout = old }() - filename := nrandom.NewUUIDV7().String() + filename := nrandom.RandString(8) logger, err := NewLogger(filename, new(SizeLimitRotateRule), true) defer os.Remove(filename) if assert.NoError(t, err) { assert.NotPanics(t, func() { - logger.maybeCompressFile(nrandom.NewUUIDV7().String()) + logger.maybeCompressFile(nrandom.RandString(8)) }) } } @@ -295,6 +432,70 @@ func TestRotateLoggerWithSizeLimitRotateRuleWrite(t *testing.T) { logger.write([]byte(`baz`)) } +func TestGzipFile(t *testing.T) { + err := errors.New("any error") + + t.Run("gzip file open failed", func(t *testing.T) { + fsys := &fakeFileSystem{ + openFn: func(name string) (*os.File, error) { + return nil, err + }, + } + assert.ErrorIs(t, err, gzipFile("any", fsys)) + assert.False(t, fsys.Removed()) + }) + + t.Run("gzip file create failed", func(t *testing.T) { + fsys := &fakeFileSystem{ + createFn: func(name string) (*os.File, error) { + return nil, err + }, + } + assert.ErrorIs(t, err, gzipFile("any", fsys)) + assert.False(t, fsys.Removed()) + }) + + t.Run("gzip file copy failed", func(t *testing.T) { + fsys := &fakeFileSystem{ + copyFn: func(writer io.Writer, reader io.Reader) (int64, error) { + return 0, err + }, + } + assert.ErrorIs(t, err, gzipFile("any", fsys)) + assert.False(t, fsys.Removed()) + }) + + t.Run("gzip file last close failed", func(t *testing.T) { + var called int32 + fsys := &fakeFileSystem{ + closeFn: func(closer io.Closer) error { + if atomic.AddInt32(&called, 1) > 2 { + return err + } + return nil + }, + } + assert.NoError(t, gzipFile("any", fsys)) + assert.True(t, fsys.Removed()) + }) + + t.Run("gzip file remove failed", func(t *testing.T) { + fsys := &fakeFileSystem{ + removeFn: func(name string) error { + return err + }, + } + assert.Error(t, err, gzipFile("any", fsys)) + assert.True(t, fsys.Removed()) + }) + + t.Run("gzip file everything ok", func(t *testing.T) { + fsys := &fakeFileSystem{} + assert.NoError(t, gzipFile("any", fsys)) + assert.True(t, fsys.Removed()) + }) +} + func BenchmarkRotateLogger(b *testing.B) { filename := "./test.log" filename2 := "./test2.log" @@ -346,3 +547,53 @@ func BenchmarkRotateLogger(b *testing.B) { } }) } + +type fakeFileSystem struct { + removed int32 + closeFn func(closer io.Closer) error + copyFn func(writer io.Writer, reader io.Reader) (int64, error) + createFn func(name string) (*os.File, error) + openFn func(name string) (*os.File, error) + removeFn func(name string) error +} + +func (f *fakeFileSystem) Close(closer io.Closer) error { + if f.closeFn != nil { + return f.closeFn(closer) + } + return nil +} + +func (f *fakeFileSystem) Copy(writer io.Writer, reader io.Reader) (int64, error) { + if f.copyFn != nil { + return f.copyFn(writer, reader) + } + return 0, nil +} + +func (f *fakeFileSystem) Create(name string) (*os.File, error) { + if f.createFn != nil { + return f.createFn(name) + } + return nil, nil +} + +func (f *fakeFileSystem) Open(name string) (*os.File, error) { + if f.openFn != nil { + return f.openFn(name) + } + return nil, nil +} + +func (f *fakeFileSystem) Remove(name string) error { + atomic.AddInt32(&f.removed, 1) + + if f.removeFn != nil { + return f.removeFn(name) + } + return nil +} + +func (f *fakeFileSystem) Removed() bool { + return atomic.LoadInt32(&f.removed) > 0 +}