CBG-3933 allow console logs to be rotated

Author: torcolvin

base/logger.go

@@ -61,8 +61,7 @@ func FlushLogBuffers() {
 
 // logCollationWorker will take log lines over the given channel, and buffer them until either the buffer is full, or the flushTimeout is exceeded.
 // This is to reduce the number of writes to the log files, in order to batch them up as larger collated chunks, whilst maintaining a low-level of latency with the flush timeout.
-func logCollationWorker(collateBuffer chan string, flushChan chan struct{}, collateBufferWg *sync.WaitGroup, logger *log.Logger, maxBufferSize int, collateFlushTimeout time.Duration) {
-
+func logCollationWorker(loggerClosed chan struct{}, collateBuffer chan string, flushChan chan struct{}, collateBufferWg *sync.WaitGroup, logger *log.Logger, maxBufferSize int, collateFlushTimeout time.Duration) {
 	// The initial duration of the timeout timer doesn't matter,
 	// because we reset it whenever we buffer a log without flushing it.
 	t := time.NewTimer(math.MaxInt64)
@@ -97,6 +96,8 @@ func logCollationWorker(collateBuffer chan string, flushChan chan struct{}, coll
 				logger.Print(strings.Join(logBuffer, "\n"))
 				logBuffer = logBuffer[:0]
 			}
+		case <-loggerClosed:
+			return
 		}
 	}
 }

base/logger_audit_test.go

@@ -132,13 +132,13 @@ func TestAuditLoggerGlobalFields(t *testing.T) {
 	}
 	for _, testCase := range testCases {
 		t.Run(testCase.name, func(t *testing.T) {
+			ResetGlobalTestLogging(t)
 			ctx := TestCtx(t)
 			if testCase.contextFields != nil {
 				ctx = AuditLogCtx(ctx, testCase.contextFields)
 			}
 			logger, err := NewAuditLogger(ctx, &AuditLoggerConfig{FileLoggerConfig: FileLoggerConfig{Enabled: BoolPtr(true)}}, tmpdir, 0, nil, testCase.globalFields)
 			require.NoError(t, err)
-			defer assert.NoError(t, logger.Close())
 			auditLogger.Store(logger)
 
 			startWarnCount := SyncGatewayStats.GlobalStats.ResourceUtilizationStats().WarnCount.Value()

base/logger_console.go

@@ -19,8 +19,6 @@ import (
 	"path/filepath"
 	"strconv"
 	"sync"
-
-	"gopkg.in/natefinch/lumberjack.v2"
 )
 
 // ConsoleLogger is a file logger with a default output of stderr, and tunable log level/keys.
@@ -55,8 +53,12 @@ func NewConsoleLogger(ctx context.Context, shouldLogLocation bool, config *Conso
 		config = &ConsoleLoggerConfig{}
 	}
 
+	cancelCtx, cancelFunc := context.WithCancel(ctx)
+
 	// validate and set defaults
-	if err := config.init(); err != nil {
+	rotationDoneChan, err := config.init(cancelCtx)
+	if err != nil {
+		defer cancelFunc()
 		return nil, err
 	}
 
@@ -67,23 +69,27 @@ func NewConsoleLogger(ctx context.Context, shouldLogLocation bool, config *Conso
 		LogKeyMask:   &logKey,
 		ColorEnabled: *config.ColorEnabled,
 		FileLogger: FileLogger{
-			Enabled: AtomicBool{},
-			logger:  log.New(config.Output, "", 0),
-			config:  config.FileLoggerConfig,
+			Enabled:          AtomicBool{},
+			logger:           log.New(config.Output, "", 0),
+			config:           config.FileLoggerConfig,
+			rotationDoneChan: rotationDoneChan,
+			cancelFunc:       cancelFunc,
+			name:             "console",
+			closed:           make(chan struct{}),
 		},
 		isStderr: config.FileOutput == "" && *config.Enabled,
 		config:   *config,
 	}
 	logger.Enabled.Set(*config.Enabled)
 
 	// Only create the collateBuffer channel and worker if required.
-	if *config.CollationBufferSize > 1 {
+	if *config.CollationBufferSize > 1 && !logger.isStderr {
 		logger.collateBuffer = make(chan string, *config.CollationBufferSize)
 		logger.flushChan = make(chan struct{}, 1)
 		logger.collateBufferWg = &sync.WaitGroup{}
 
 		// Start up a single worker to consume messages from the buffer
-		go logCollationWorker(logger.collateBuffer, logger.flushChan, logger.collateBufferWg, logger.logger, *config.CollationBufferSize, consoleLoggerCollateFlushTimeout)
+		go logCollationWorker(logger.closed, logger.collateBuffer, logger.flushChan, logger.collateBufferWg, logger.logger, *config.CollationBufferSize, consoleLoggerCollateFlushTimeout)
 	}
 
 	// We can only log the console log location itself when logging has previously been set up and is being re-initialized from a config.
@@ -179,29 +185,25 @@ func (l *ConsoleLogger) getConsoleLoggerConfig() *ConsoleLoggerConfig {
 }
 
 // init validates and sets any defaults for the given ConsoleLoggerConfig
-func (lcc *ConsoleLoggerConfig) init() error {
+func (lcc *ConsoleLoggerConfig) init(ctx context.Context) (chan struct{}, error) {
 	if lcc == nil {
-		return errors.New("nil LogConsoleConfig")
+		return nil, errors.New("nil LogConsoleConfig")
 	}
 
 	if err := lcc.initRotationConfig("console", 0, 0); err != nil {
-		return err
+		return nil, err
 	}
 
+	var rotationDoneChan chan struct{}
 	// Default to os.Stderr if alternative output is not set
 	if lcc.Output == nil && lcc.FileOutput == "" {
 		lcc.Output = os.Stderr
 	} else if lcc.FileOutput != "" {
 		// Otherwise check permissions on the given output and create a Lumberjack logger
 		if err := validateLogFileOutput(lcc.FileOutput); err != nil {
-			return err
-		}
-		lcc.Output = &lumberjack.Logger{
-			Filename: filepath.FromSlash(lcc.FileOutput),
-			MaxSize:  *lcc.Rotation.MaxSize,
-			MaxAge:   *lcc.Rotation.MaxAge,
-			Compress: BoolDefault(lcc.Rotation.Compress, false),
+			return nil, err
 		}
+		rotationDoneChan = lcc.initLumberjack(ctx, "console", filepath.FromSlash(lcc.FileOutput))
 	}
 
 	// Default to disabled only when a log key or log level has not been specified
@@ -225,7 +227,7 @@ func (lcc *ConsoleLoggerConfig) init() error {
 		newLevel := LevelInfo
 		lcc.LogLevel = &newLevel
 	} else if *lcc.LogLevel < LevelNone || *lcc.LogLevel > levelCount {
-		return fmt.Errorf("invalid log level: %v", *lcc.LogLevel)
+		return nil, fmt.Errorf("invalid log level: %v", *lcc.LogLevel)
 	}
 
 	// If ColorEnabled is not explicitly set, use the value of $SG_COLOR
@@ -249,7 +251,7 @@ func (lcc *ConsoleLoggerConfig) init() error {
 		lcc.CollationBufferSize = &bufferSize
 	}
 
-	return nil
+	return rotationDoneChan, nil
 }
 
 func mustInitConsoleLogger(ctx context.Context, config *ConsoleLoggerConfig) *ConsoleLogger {

base/logger_file.go

@@ -51,6 +51,7 @@ type FileLogger struct {
 	// collateBuffer is used to store log entries to batch up multiple logs.
 	collateBuffer    chan string
 	collateBufferWg  *sync.WaitGroup
+	closed           chan struct{}
 	flushChan        chan struct{}
 	level            LogLevel
 	name             string
@@ -87,11 +88,11 @@ func NewFileLogger(ctx context.Context, config *FileLoggerConfig, level LogLevel
 		config = &FileLoggerConfig{}
 	}
 
-	rotationDoneChan := make(chan struct{})
 	cancelCtx, cancelFunc := context.WithCancel(ctx)
 
 	// validate and set defaults
-	if err := config.init(cancelCtx, level, name, logFilePath, minAge, rotationDoneChan); err != nil {
+	rotationDoneChan, err := config.init(cancelCtx, level, name, logFilePath, minAge)
+	if err != nil {
 		cancelFunc()
 		return nil, err
 	}
@@ -103,6 +104,7 @@ func NewFileLogger(ctx context.Context, config *FileLoggerConfig, level LogLevel
 		output:           config.Output,
 		logger:           log.New(config.Output, "", 0),
 		config:           *config,
+		closed:           make(chan struct{}),
 		cancelFunc:       cancelFunc,
 		rotationDoneChan: rotationDoneChan,
 	}
@@ -119,7 +121,7 @@ func NewFileLogger(ctx context.Context, config *FileLoggerConfig, level LogLevel
 		logger.collateBufferWg = &sync.WaitGroup{}
 
 		// Start up a single worker to consume messages from the buffer
-		go logCollationWorker(logger.collateBuffer, logger.flushChan, logger.collateBufferWg, logger.logger, *config.CollationBufferSize, fileLoggerCollateFlushTimeout)
+		go logCollationWorker(logger.closed, logger.collateBuffer, logger.flushChan, logger.collateBufferWg, logger.logger, *config.CollationBufferSize, fileLoggerCollateFlushTimeout)
 	}
 
 	return logger, nil
@@ -152,21 +154,26 @@ func (l *FileLogger) Rotate() error {
 
 // Close cancels the log rotation rotation and the underlying file descriptor for the active log file.
 func (l *FileLogger) Close() error {
+	// cancelFunc will stop the log rotionation/deletion goroutine
+	// once all log rotation is done and log output is closed, shut down the logCollationWorker
+	defer close(l.closed)
 	// cancel the log rotation goroutine and wait for it to stop
 	if l.cancelFunc != nil {
 		l.cancelFunc()
 	}
+	// wait for the rotation goroutine to stop
 	if l.rotationDoneChan != nil {
 		<-l.rotationDoneChan
 	}
+
 	if c, ok := l.output.(io.Closer); ok {
 		return c.Close()
 	}
 	return nil
 }
 
 func (l *FileLogger) String() string {
-	return "FileLogger(" + l.level.String() + ")"
+	return "FileLogger(" + l.name + ")"
 }
 
 // logf will put the given message into the collation buffer if it exists,
@@ -210,9 +217,9 @@ func (l *FileLogger) getFileLoggerConfig() *FileLoggerConfig {
 	return &fileLoggerConfig
 }
 
-func (lfc *FileLoggerConfig) init(ctx context.Context, level LogLevel, name string, logFilePath string, minAge int, rotationDoneChan chan struct{}) error {
+func (lfc *FileLoggerConfig) init(ctx context.Context, level LogLevel, name string, logFilePath string, minAge int) (chan struct{}, error) {
 	if lfc == nil {
-		return errors.New("nil LogFileConfig")
+		return nil, errors.New("nil LogFileConfig")
 	}
 
 	if lfc.Enabled == nil {
@@ -221,18 +228,12 @@ func (lfc *FileLoggerConfig) init(ctx context.Context, level LogLevel, name stri
 	}
 
 	if err := lfc.initRotationConfig(name, defaultMaxSize, minAge); err != nil {
-		return err
+		return nil, err
 	}
 
-	var rotateableLogger *lumberjack.Logger
+	var rotationDoneChan chan struct{}
 	if lfc.Output == nil {
-		rotateableLogger = newLumberjackOutput(
-			filepath.Join(filepath.FromSlash(logFilePath), logFilePrefix+name+".log"),
-			*lfc.Rotation.MaxSize,
-			*lfc.Rotation.MaxAge,
-			BoolDefault(lfc.Rotation.Compress, true),
-		)
-		lfc.Output = rotateableLogger
+		rotationDoneChan = lfc.initLumberjack(ctx, name, filepath.Join(filepath.FromSlash(logFilePath), logFilePrefix+name+".log"))
 	}
 
 	if lfc.CollationBufferSize == nil {
@@ -244,9 +245,25 @@ func (lfc *FileLoggerConfig) init(ctx context.Context, level LogLevel, name stri
 		lfc.CollationBufferSize = &bufferSize
 	}
 
+	return rotationDoneChan, nil
+}
+
+// initLumberjack will create a new Lumberjack logger from the given config settings. Returns a doneChan which fires when the log rotation is stopped.
+func (lfc *FileLoggerConfig) initLumberjack(ctx context.Context, name string, lumberjackFilename string) chan struct{} {
+	rotationDoneChan := make(chan struct{})
+	dir, path := filepath.Split(lumberjackFilename)
+	prefix := path[0:strings.Index(path, ".")]
+	rotateableLogger := &lumberjack.Logger{
+		Filename: lumberjackFilename,
+		MaxSize:  *lfc.Rotation.MaxSize,
+		MaxAge:   *lfc.Rotation.MaxAge,
+		Compress: BoolDefault(lfc.Rotation.Compress, true),
+	}
+	lfc.Output = rotateableLogger
+
 	var rotationTicker *time.Ticker
 	var rotationTickerCh <-chan time.Time
-	if i := lfc.Rotation.RotationInterval.Value(); i > 0 && rotateableLogger != nil {
+	if i := lfc.Rotation.RotationInterval.Value(); i > 0 {
 		rotationTicker = time.NewTicker(i)
 		rotationTickerCh = rotationTicker.C
 	}
@@ -268,7 +285,7 @@ func (lfc *FileLoggerConfig) init(ctx context.Context, level LogLevel, name stri
 				close(rotationDoneChan)
 				return
 			case <-logDeletionTicker.C:
-				err := runLogDeletion(ctx, logFilePath, level.String(), int(float64(*lfc.Rotation.RotatedLogsSizeLimit)*rotatedLogsLowWatermarkMultiplier), *lfc.Rotation.RotatedLogsSizeLimit)
+				err := runLogDeletion(ctx, dir, prefix, int(float64(*lfc.Rotation.RotatedLogsSizeLimit)*rotatedLogsLowWatermarkMultiplier), *lfc.Rotation.RotatedLogsSizeLimit)
 				if err != nil {
 					WarnfCtx(ctx, "%s", err)
 				}
@@ -281,10 +298,10 @@ func (lfc *FileLoggerConfig) init(ctx context.Context, level LogLevel, name stri
 			}
 		}
 	}()
-
-	return nil
+	return rotationDoneChan
 }
 
+// initRotationConfig will validate the log rotation settings and set defaults where necessary.
 func (lfc *FileLoggerConfig) initRotationConfig(name string, defaultMaxSize, minAge int) error {
 	if lfc.Rotation.MaxSize == nil {
 		lfc.Rotation.MaxSize = &defaultMaxSize
@@ -322,20 +339,10 @@ func (lfc *FileLoggerConfig) initRotationConfig(name string, defaultMaxSize, min
 	return nil
 }
 
-func newLumberjackOutput(filename string, maxSize, maxAge int, compress bool) *lumberjack.Logger {
-	return &lumberjack.Logger{
-		Filename: filename,
-		MaxSize:  maxSize,
-		MaxAge:   maxAge,
-		Compress: compress,
-	}
-}
-
 // runLogDeletion will delete rotated logs for the supplied logLevel. It will only perform these deletions when the
 // cumulative size of the logs are above the supplied sizeLimitMB.
 // logDirectory is the supplied directory where the logs are stored.
-func runLogDeletion(ctx context.Context, logDirectory string, logLevel string, sizeLimitMBLowWatermark int, sizeLimitMBHighWatermark int) (err error) {
-
+func runLogDeletion(ctx context.Context, logDirectory string, logPrefix string, sizeLimitMBLowWatermark int, sizeLimitMBHighWatermark int) (err error) {
 	sizeLimitMBLowWatermark = sizeLimitMBLowWatermark * 1024 * 1024   // Convert MB input to bytes
 	sizeLimitMBHighWatermark = sizeLimitMBHighWatermark * 1024 * 1024 // Convert MB input to bytes
 
@@ -352,7 +359,7 @@ func runLogDeletion(ctx context.Context, logDirectory string, logLevel string, s
 	willDelete := false
 	for i := len(files) - 1; i >= 0; i-- {
 		file := files[i]
-		if strings.HasPrefix(file.Name(), logFilePrefix+logLevel) && strings.HasSuffix(file.Name(), ".log.gz") {
+		if strings.HasPrefix(file.Name(), logPrefix) && strings.HasSuffix(file.Name(), ".gz") {
 			fi, err := file.Info()
 			if err != nil {
 				InfofCtx(ctx, KeyAll, "Couldn't get size of log file %q: %v - ignoring for cleanup calculation", file.Name(), err)
@@ -373,7 +380,7 @@ func runLogDeletion(ctx context.Context, logDirectory string, logLevel string, s
 	if willDelete {
 		for j := indexDeletePoint; j >= 0; j-- {
 			file := files[j]
-			if strings.HasPrefix(file.Name(), logFilePrefix+logLevel) && strings.HasSuffix(file.Name(), ".log.gz") {
+			if strings.HasPrefix(file.Name(), logPrefix) && strings.HasSuffix(file.Name(), ".gz") {
 				err = os.Remove(filepath.Join(logDirectory, file.Name()))
 				if err != nil {
 					return errors.New(fmt.Sprintf("Error deleting stale log file: %v", err))

base/logger_file_test.go

@@ -129,9 +129,9 @@ func TestRotatedLogDeletion(t *testing.T) {
 	err = makeTestFile(2, logFilePrefix+"info-2019-02-02T12-10-00.log.gz", dir)
 	assert.NoError(t, err)
 	ctx := TestCtx(t)
-	err = runLogDeletion(ctx, dir, "error", 3, 5)
+	err = runLogDeletion(ctx, dir, logFilePrefix+"error", 3, 5)
 	assert.NoError(t, err)
-	err = runLogDeletion(ctx, dir, "info", 5, 7)
+	err = runLogDeletion(ctx, dir, logFilePrefix+"info", 5, 7)
 	assert.NoError(t, err)
 	dirContents, err = os.ReadDir(dir)
 	require.NoError(t, err)
@@ -164,7 +164,7 @@ func TestRotatedLogDeletion(t *testing.T) {
 	dir = t.TempDir()
 	err = makeTestFile(5, logFilePrefix+"error.log.gz", dir)
 	assert.NoError(t, err)
-	err = runLogDeletion(ctx, dir, "error", 2, 4)
+	err = runLogDeletion(ctx, dir, logFilePrefix+"error", 2, 4)
 	assert.NoError(t, err)
 	dirContents, err = os.ReadDir(dir)
 	require.NoError(t, err)
@@ -175,7 +175,7 @@ func TestRotatedLogDeletion(t *testing.T) {
 	dir = t.TempDir()
 	err = makeTestFile(1, logFilePrefix+"error.log.gz", dir)
 	assert.NoError(t, err)
-	err = runLogDeletion(ctx, dir, "error", 2, 4)
+	err = runLogDeletion(ctx, dir, logFilePrefix+"error", 2, 4)
 	assert.NoError(t, err)
 	dirContents, err = os.ReadDir(dir)
 	require.NoError(t, err)
@@ -192,7 +192,7 @@ func TestRotatedLogDeletion(t *testing.T) {
 	assert.NoError(t, err)
 	err = makeTestFile(1, logFilePrefix+"error-2019-01-01T12-00-00.log.gz", dir)
 	assert.NoError(t, err)
-	err = runLogDeletion(ctx, dir, "error", 2, 3)
+	err = runLogDeletion(ctx, dir, logFilePrefix+"error", 2, 3)
 	assert.NoError(t, err)
 
 	dirContents, err = os.ReadDir(dir)

base/logging_config.go

@@ -155,6 +155,7 @@ func NewMemoryLogger(level LogLevel) *FileLogger {
 		Enabled: AtomicBool{1},
 		level:   level,
 		name:    level.String(),
+		closed:  make(chan struct{}),
 	}
 	logger.output = &logger.buffer
 	logger.logger = log.New(&logger.buffer, "", 0)