[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: <log name>.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 <ivan@synadia.com>
2026-04-02 03:38:42 -07:00 · 2019-11-19 20:08:48 -07:00
parent 679bedafd9
commit e9a134ac48
4 changed files with 319 additions and 15 deletions
--- 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
 }
--- 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()