CBG-3933 allow console logs to be rotated (#7058)

* CBG-3933 allow console logs to be rotated * update log deletion tests - change log deletion to use regex to match all patterns of possible log paths - disable compression for console logs - restore stderr log collation * windows requires no slashes in path names * Apply suggestions from code review Co-authored-by: Ben Brooks <[email protected]> * Update base/logger_console_test.go Co-authored-by: Ben Brooks <[email protected]> * add missing import --------- Co-authored-by: Ben Brooks <[email protected]>
couchbase · Aug 21, 2024 · b24e02a · b24e02a
1 parent 5adf0d6
commit b24e02a
Show file tree

Hide file tree

Showing 9 changed files with 559 additions and 279 deletions.
diff --git a/base/logger.go b/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
 		}
 	}
 }
diff --git a/base/logger_audit_test.go b/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()

diff --git a/base/logger_console.go b/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,9 +69,13 @@ 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,
@@ -83,7 +89,7 @@ func NewConsoleLogger(ctx context.Context, shouldLogLocation bool, config *Conso
 		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
+	if err := lcc.initRotationConfig("console", 0, 0, false); err != nil {
+		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 {

diff --git a/base/logger_console_test.go b/base/logger_console_test.go
@@ -13,9 +13,14 @@ package base
 import (
 	"fmt"
 	"io"
+	"path/filepath"
+	"slices"
+	"sync"
 	"testing"
+	"time"
 
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 )
 
 var consoleShouldLogTests = []struct {
@@ -287,3 +292,109 @@ func TestConsoleLogDefaults(t *testing.T) {
 		})
 	}
 }
+
+func TestConsoleIrregularLogPaths(t *testing.T) {
+	// override min rotation interval for testing
+	originalMinRotationInterval := minLogRotationInterval
+	minLogRotationInterval = time.Millisecond * 10
+	defer func() { minLogRotationInterval = originalMinRotationInterval }()
+
+	testCases := []struct {
+		name    string
+		logPath string
+	}{
+		{
+			name:    ".log extension",
+			logPath: "foo.log",
+			// take foo-2021-01-01T00-00-00.000.log
+		},
+		{
+			name:    "no extension",
+			logPath: "foo",
+			// foo-2021-01-01T00-00-00.000
+		},
+		{
+			name:    "multiple dots",
+			logPath: "two.ext.log",
+			// two.ext-2021-01-01T00-00-00.000.log
+		},
+		{
+			name:    "start with .",
+			logPath: ".hidden.log",
+			// .hidden-2021-01-01T00-00-00.000.log
+		},
+		{
+			name:    "start with ., no ext",
+			logPath: ".hidden",
+			// -2021-01-01T00-00-00.000.hidden
+		},
+	}
+	for _, test := range testCases {
+		t.Run(test.name, func(t *testing.T) {
+			tempdir := lumberjackTempDir(t)
+			config := &ConsoleLoggerConfig{
+				LogLevel:   logLevelPtr(LevelDebug),
+				LogKeys:    []string{"HTTP"},
+				FileOutput: filepath.Join(tempdir, test.logPath),
+				FileLoggerConfig: FileLoggerConfig{
+					Enabled:             BoolPtr(true),
+					CollationBufferSize: IntPtr(0),
+					Rotation: logRotationConfig{
+						RotationInterval: NewConfigDuration(10 * time.Millisecond),
+					},
+				}}
+
+			ctx := TestCtx(t)
+			logger, err := NewConsoleLogger(ctx, false, config)
+			require.NoError(t, err)
+
+			// ensure logging is done before closing the logger
+			wg := sync.WaitGroup{}
+			wg.Add(1)
+			doneChan := make(chan struct{})
+			defer func() {
+				close(doneChan)
+				wg.Wait()
+				assert.NoError(t, logger.Close())
+			}()
+			go func() {
+				for {
+					select {
+					case <-doneChan:
+						wg.Done()
+						return
+					default:
+						logger.logf("some text")
+					}
+				}
+			}()
+			require.EventuallyWithT(t, func(c *assert.CollectT) {
+				filenames := getDirFiles(t, tempdir)
+				assert.Contains(c, filenames, test.logPath)
+				assert.Greater(c, len(filenames), 2)
+			}, time.Second, 10*time.Millisecond)
+
+			// add a few non-matching files to the directory for negative testing
+			nonMatchingFileNames := []string{
+				"console.log",
+				"consoellog",
+				"console.log.txt",
+				".console",
+				"consolelog-2021-01-01T00-00-00.000",
+				"console-2021-01-01T00-00-00.000.log",
+			}
+			for _, name := range nonMatchingFileNames {
+				require.NoError(t, makeTestFile(1, name, tempdir))
+			}
+
+			_, pattern := getDeletionDirAndRegexp(filepath.Join(tempdir, test.logPath))
+			for _, filename := range getDirFiles(t, tempdir) {
+				if slices.Contains(nonMatchingFileNames, filename) {
+					require.NotRegexp(t, pattern, filename)
+				} else {
+					require.Regexp(t, pattern, filename)
+				}
+			}
+		})
+	}
+}