From e9a134ac480d93d291760df82fce916f7316de17 Mon Sep 17 00:00:00 2001 From: Ivan Kozlovic Date: Tue, 19 Nov 2019 20:08:48 -0700 Subject: [PATCH] [ADDED] LogSizeLimit option Allow auto-rotation of log files when the size is greater than configured limit. The backup files have the same name than the original log file name with the following suffix: .yyyy.mm.dd.hh.mm.ss.micros where: - yyyy is the year - mm is the month - dd is the day - hh is the hour - mm is the minute - ss is the second - micros is the number of microseconds (to help avoid duplicates) Resolves #1197 Signed-off-by: Ivan Kozlovic --- logger/log.go | 175 +++++++++++++++++++++++++++++++++++++++++---- logger/log_test.go | 150 ++++++++++++++++++++++++++++++++++++++ server/log.go | 5 ++ server/opts.go | 4 ++ 4 files changed, 319 insertions(+), 15 deletions(-) diff --git a/logger/log.go b/logger/log.go index 267c8a9d..57cab62f 100644 --- a/logger/log.go +++ b/logger/log.go @@ -18,10 +18,14 @@ import ( "fmt" "log" "os" + "sync" + "sync/atomic" + "time" ) // Logger is the server logger type Logger struct { + sync.Mutex logger *log.Logger debug bool trace bool @@ -31,7 +35,7 @@ type Logger struct { fatalLabel string debugLabel string traceLabel string - logFile *os.File // file pointer for the file logger. + fl *fileLogger } // NewStdLogger creates a logger with output directed to Stderr @@ -63,12 +67,6 @@ func NewStdLogger(time, debug, trace, colors, pid bool) *Logger { // NewFileLogger creates a logger with output directed to a file func NewFileLogger(filename string, time, debug, trace, pid bool) *Logger { - fileflags := os.O_WRONLY | os.O_APPEND | os.O_CREATE - f, err := os.OpenFile(filename, fileflags, 0660) - if err != nil { - log.Fatalf("error opening file: %v", err) - } - flags := 0 if time { flags = log.LstdFlags | log.Lmicroseconds @@ -79,17 +77,165 @@ func NewFileLogger(filename string, time, debug, trace, pid bool) *Logger { pre = pidPrefix() } - l := &Logger{ - logger: log.New(f, pre, flags), - debug: debug, - trace: trace, - logFile: f, + fl, err := newFileLogger(filename, pre, time) + if err != nil { + log.Fatalf("error opening file: %v", err) + return nil } + l := &Logger{ + logger: log.New(fl, pre, flags), + debug: debug, + trace: trace, + fl: fl, + } + fl.Lock() + fl.l = l + fl.Unlock() + setPlainLabelFormats(l) return l } +type writerAndCloser interface { + Write(b []byte) (int, error) + Close() error + Name() string +} + +type fileLogger struct { + out int64 + canRotate int32 + sync.Mutex + l *Logger + f writerAndCloser + limit int64 + olimit int64 + pid string + time bool + closed bool +} + +func newFileLogger(filename, pidPrefix string, time bool) (*fileLogger, error) { + fileflags := os.O_WRONLY | os.O_APPEND | os.O_CREATE + f, err := os.OpenFile(filename, fileflags, 0660) + if err != nil { + return nil, err + } + stats, err := f.Stat() + if err != nil { + f.Close() + return nil, err + } + fl := &fileLogger{ + canRotate: 0, + f: f, + out: stats.Size(), + pid: pidPrefix, + time: time, + } + return fl, nil +} + +func (l *fileLogger) setLimit(limit int64) { + l.Lock() + l.olimit, l.limit = limit, limit + atomic.StoreInt32(&l.canRotate, 1) + rotateNow := l.out > l.limit + l.Unlock() + if rotateNow { + l.l.Noticef("Rotating logfile...") + } +} + +func (l *fileLogger) logDirect(label, format string, v ...interface{}) int { + var entrya = [256]byte{} + var entry = entrya[:0] + if l.pid != "" { + entry = append(entry, l.pid...) + } + if l.time { + now := time.Now() + year, month, day := now.Date() + hour, min, sec := now.Clock() + microsec := now.Nanosecond() / 1000 + entry = append(entry, fmt.Sprintf("%04d/%02d/%02d %02d:%02d:%02d.%06d ", + year, month, day, hour, min, sec, microsec)...) + } + entry = append(entry, label...) + entry = append(entry, fmt.Sprintf(format, v...)...) + entry = append(entry, '\r', '\n') + l.f.Write(entry) + return len(entry) +} + +func (l *fileLogger) Write(b []byte) (int, error) { + if atomic.LoadInt32(&l.canRotate) == 0 { + n, err := l.f.Write(b) + if err == nil { + atomic.AddInt64(&l.out, int64(n)) + } + return n, err + } + l.Lock() + n, err := l.f.Write(b) + if err == nil { + l.out += int64(n) + if l.out > l.limit { + if err := l.f.Close(); err != nil { + l.limit *= 2 + l.logDirect(l.l.errorLabel, "Unable to close logfile for rotation (%v), will attempt next rotation at size %v", err, l.limit) + l.Unlock() + return n, err + } + fname := l.f.Name() + now := time.Now() + bak := fmt.Sprintf("%s.%04d.%02d.%02d.%02d.%02d.%02d.%09d", fname, + now.Year(), now.Month(), now.Day(), now.Hour(), now.Minute(), + now.Second(), now.Nanosecond()) + os.Rename(fname, bak) + fileflags := os.O_WRONLY | os.O_APPEND | os.O_CREATE + f, err := os.OpenFile(fname, fileflags, 0660) + if err != nil { + l.Unlock() + panic(fmt.Sprintf("Unable to re-open the logfile %q after rotation: %v", fname, err)) + } + l.f = f + n := l.logDirect(l.l.infoLabel, "Rotated log, backup saved as %q", bak) + l.out = int64(n) + l.limit = l.olimit + } + } + l.Unlock() + return n, err +} + +func (l *fileLogger) close() error { + l.Lock() + if l.closed { + l.Unlock() + return nil + } + l.closed = true + l.Unlock() + return l.f.Close() +} + +// SetSizeLimit sets the size of a logfile after which a backup +// is created with the file name + "year.month.day.hour.min.sec.nanosec" +// and the current log is truncated. +func (l *Logger) SetSizeLimit(limit int64) error { + l.Lock() + if l.fl == nil { + l.Unlock() + return fmt.Errorf("can set log size limit only for file logger") + } + fl := l.fl + l.Unlock() + fl.setLimit(limit) + return nil +} + // NewTestLogger creates a logger with output directed to Stderr with a prefix. // Useful for tracing in tests when multiple servers are in the same pid func NewTestLogger(prefix string, time bool) *Logger { @@ -110,9 +256,8 @@ func NewTestLogger(prefix string, time bool) *Logger { // resources in the server's logger implementation. // Caller must ensure threadsafety. func (l *Logger) Close() error { - if f := l.logFile; f != nil { - l.logFile = nil - return f.Close() + if l.fl != nil { + return l.fl.close() } return nil } diff --git a/logger/log_test.go b/logger/log_test.go index 0e29b2b3..9bd46d91 100644 --- a/logger/log_test.go +++ b/logger/log_test.go @@ -20,6 +20,7 @@ import ( "io/ioutil" "log" "os" + "path/filepath" "regexp" "strings" "testing" @@ -115,6 +116,7 @@ func TestFileLogger(t *testing.T) { file.Close() logger := NewFileLogger(file.Name(), false, false, false, false) + defer logger.Close() logger.Noticef("foo") buf, err := ioutil.ReadFile(file.Name()) @@ -136,6 +138,7 @@ func TestFileLogger(t *testing.T) { file.Close() logger = NewFileLogger(file.Name(), true, true, true, true) + defer logger.Close() logger.Errorf("foo") buf, err = ioutil.ReadFile(file.Name()) @@ -172,6 +175,153 @@ func TestFileLogger(t *testing.T) { } } +func TestFileLoggerSizeLimit(t *testing.T) { + // Create std logger + logger := NewStdLogger(true, false, false, false, true) + if err := logger.SetSizeLimit(1000); err == nil || + !strings.Contains(err.Error(), "only for file logger") { + t.Fatalf("Expected error about being able to use only for file logger, got %v", err) + } + logger.Close() + + tmpDir, err := ioutil.TempDir("", "nats-server") + if err != nil { + t.Fatal("Could not create tmp dir") + } + defer os.RemoveAll(tmpDir) + + file, err := ioutil.TempFile(tmpDir, "log_") + if err != nil { + t.Fatalf("Could not create the temp file: %v", err) + } + file.Close() + + logger = NewFileLogger(file.Name(), true, false, false, true) + defer logger.Close() + logger.SetSizeLimit(1000) + + for i := 0; i < 50; i++ { + logger.Noticef("This is a line in the log file") + } + + files, err := ioutil.ReadDir(tmpDir) + if err != nil { + t.Fatalf("Error reading logs dir: %v", err) + } + if len(files) == 1 { + t.Fatalf("Expected file to have been rotated") + } + lastBackup := files[len(files)-1] + if err := logger.Close(); err != nil { + t.Fatalf("Error closing log: %v", err) + } + content, err := ioutil.ReadFile(file.Name()) + if err != nil { + t.Fatalf("Error loading latest log: %v", err) + } + if !bytes.Contains(content, []byte("Rotated log")) || + !bytes.Contains(content, []byte(lastBackup.Name())) { + t.Fatalf("Should be statement about rotated log and backup name, got %s", content) + } + + // Remove all files + os.RemoveAll(tmpDir) + tmpDir, err = ioutil.TempDir("", "nats-server") + if err != nil { + t.Fatal("Could not create tmp dir") + } + defer os.RemoveAll(tmpDir) + + // Recreate logger and don't set a limit + file, err = ioutil.TempFile(tmpDir, "log_") + if err != nil { + t.Fatalf("Could not create the temp file: %v", err) + } + file.Close() + logger = NewFileLogger(file.Name(), true, false, false, true) + defer logger.Close() + for i := 0; i < 50; i++ { + logger.Noticef("This is line %d in the log file", i+1) + } + files, err = ioutil.ReadDir(tmpDir) + if err != nil { + t.Fatalf("Error reading logs dir: %v", err) + } + if len(files) != 1 { + t.Fatalf("Expected file to not be rotated") + } + + // Now set a limit that is below current size + logger.SetSizeLimit(1000) + // Should have triggered rotation + files, err = ioutil.ReadDir(tmpDir) + if err != nil { + t.Fatalf("Error reading logs dir: %v", err) + } + if len(files) <= 1 { + t.Fatalf("Expected file to have been rotated") + } + if err := logger.Close(); err != nil { + t.Fatalf("Error closing log: %v", err) + } + lastBackup = files[len(files)-1] + content, err = ioutil.ReadFile(file.Name()) + if err != nil { + t.Fatalf("Error loading latest log: %v", err) + } + if !bytes.Contains(content, []byte("Rotated log")) || + !bytes.Contains(content, []byte(lastBackup.Name())) { + t.Fatalf("Should be statement about rotated log and backup name, got %s", content) + } + + logger = NewFileLogger(file.Name(), true, false, false, true) + defer logger.Close() + logger.SetSizeLimit(1000) + + // Check error on rotate. + logger.Lock() + logger.fl.Lock() + failClose := &fileLogFailClose{logger.fl.f, true} + logger.fl.f = failClose + logger.fl.Unlock() + logger.Unlock() + // Write a big line that will force rotation. + // Since we fail to close the log file, we should have bumped the limit to 2000 + logger.Noticef("This is a big line: %v", make([]byte, 1000)) + + // Remove the failure + failClose.fail = false + // Write a big line that makes rotation happen + logger.Noticef("This is a big line: %v", make([]byte, 2000)) + // Close + logger.Close() + + files, err = ioutil.ReadDir(tmpDir) + if err != nil { + t.Fatalf("Error reading logs dir: %v", err) + } + lastBackup = files[len(files)-1] + content, err = ioutil.ReadFile(filepath.Join(tmpDir, lastBackup.Name())) + if err != nil { + t.Fatalf("Error reading backup file: %v", err) + } + if !bytes.Contains(content, []byte("on purpose")) || !bytes.Contains(content, []byte("size 2000")) { + t.Fatalf("Expected error that file could not rotated and max size bumped to 2000, got %s", content) + } +} + +type fileLogFailClose struct { + writerAndCloser + fail bool +} + +func (l *fileLogFailClose) Close() error { + if l.fail { + return fmt.Errorf("on purpose") + } + return l.writerAndCloser.Close() +} + func expectOutput(t *testing.T, f func(), expected string) { old := os.Stderr // keep backup of the real stderr r, w, _ := os.Pipe() diff --git a/server/log.go b/server/log.go index d36dfa7f..762cce95 100644 --- a/server/log.go +++ b/server/log.go @@ -65,6 +65,11 @@ func (s *Server) ConfigureLogger() { if opts.LogFile != "" { log = srvlog.NewFileLogger(opts.LogFile, opts.Logtime, opts.Debug, opts.Trace, true) + if opts.LogSizeLimit > 0 { + if l, ok := log.(*srvlog.Logger); ok { + l.SetSizeLimit(opts.LogSizeLimit) + } + } } else if opts.RemoteSyslog != "" { log = srvlog.NewRemoteSysLogger(opts.RemoteSyslog, opts.Debug, opts.Trace) } else if syslog { diff --git a/server/opts.go b/server/opts.go index c8830218..7aa322bb 100644 --- a/server/opts.go +++ b/server/opts.go @@ -180,6 +180,7 @@ type Options struct { PidFile string `json:"-"` PortsFileDir string `json:"-"` LogFile string `json:"-"` + LogSizeLimit int64 `json:"-"` Syslog bool `json:"-"` RemoteSyslog string `json:"-"` Routes []*url.URL `json:"-"` @@ -549,6 +550,8 @@ func (o *Options) ProcessConfigFile(configFile string) error { } case "logfile", "log_file": o.LogFile = v.(string) + case "logfile_size_limit", "log_size_limit": + o.LogSizeLimit = v.(int64) case "syslog": o.Syslog = v.(bool) trackExplicitVal(o, &o.inConfig, "Syslog", o.Syslog) @@ -2940,6 +2943,7 @@ func ConfigureOptions(fs *flag.FlagSet, args []string, printVersion, printHelp, fs.StringVar(&opts.PortsFileDir, "ports_file_dir", "", "Creates a ports file in the specified directory (_.ports)") fs.StringVar(&opts.LogFile, "l", "", "File to store logging output.") fs.StringVar(&opts.LogFile, "log", "", "File to store logging output.") + fs.Int64Var(&opts.LogSizeLimit, "log_size_limit", 0, "Logfile size limit being auto-rotated") fs.BoolVar(&opts.Syslog, "s", false, "Enable syslog as log method.") fs.BoolVar(&opts.Syslog, "syslog", false, "Enable syslog as log method..") fs.StringVar(&opts.RemoteSyslog, "r", "", "Syslog server addr (udp://127.0.0.1:514).")