Browse Source

fix(logger): fix data race in InitLogger

Replace the package logger variable with an atomic.Pointer so InitLogger swapping the handle no longer races with concurrent Debug/Info/Warning/Error calls from other goroutines. Also guard fileRotate with a mutex, and add a regression test that reproduces the race under concurrent logging.
Sanaei 11 hours ago
parent
commit
7ef22f94c9
2 changed files with 62 additions and 17 deletions
  1. 32 17
      internal/logger/logger.go
  2. 30 0
      internal/logger/logger_test.go

+ 32 - 17
internal/logger/logger.go

@@ -8,6 +8,7 @@ import (
 	"path/filepath"
 	"runtime"
 	"sync"
+	"sync/atomic"
 	"time"
 
 	"github.com/op/go-logging"
@@ -30,10 +31,13 @@ const (
 )
 
 var (
-	// Initialized to a usable default so logging never nil-derefs before InitLogger
-	// runs — the "migrate" and "setting" CLI subcommands log without calling it.
-	logger     = logging.MustGetLogger("x-ui")
-	fileRotate *lumberjack.Logger // nil when file backend disabled
+	// InitLogger swaps the handle while other goroutines are logging, so it is
+	// published atomically — a plain assignment is an unsafe publication.
+	logger atomic.Pointer[logging.Logger]
+
+	// fileRotateMu guards fileRotate against a concurrent InitLogger/CloseLogger.
+	fileRotateMu sync.Mutex
+	fileRotate   *lumberjack.Logger // nil when file backend disabled
 
 	// logBuffer maintains recent log entries in memory for web UI retrieval;
 	// logBufferMu guards it — written from many goroutines, read by the web UI.
@@ -45,6 +49,12 @@ var (
 	}
 )
 
+// A usable default so logging never nil-derefs before InitLogger runs — the
+// "migrate" and "setting" CLI subcommands log without calling it.
+func init() {
+	logger.Store(logging.MustGetLogger("x-ui"))
+}
+
 // InitLogger initializes dual logging backends: console/syslog and file.
 // Console logging uses the specified level, file logging always uses DEBUG level.
 func InitLogger(level logging.Level) {
@@ -66,7 +76,7 @@ func InitLogger(level logging.Level) {
 
 	multiBackend := logging.MultiLogger(backends...)
 	newLogger.SetBackend(multiBackend)
-	logger = newLogger
+	logger.Store(newLogger)
 }
 
 // initDefaultBackend creates the console/syslog logging backend.
@@ -104,7 +114,7 @@ func initFileBackend() logging.Backend {
 	}
 
 	logPath := filepath.Join(logDir, logFileName)
-	fileRotate = &lumberjack.Logger{
+	rotate := &lumberjack.Logger{
 		Filename:   logPath,
 		MaxSize:    maxLogFileMB,
 		MaxBackups: maxLogBackups,
@@ -112,8 +122,11 @@ func initFileBackend() logging.Backend {
 		LocalTime:  true,
 		Compress:   compressRotated,
 	}
+	fileRotateMu.Lock()
+	fileRotate = rotate
+	fileRotateMu.Unlock()
 
-	backend := logging.NewLogBackend(fileRotate, "", 0)
+	backend := logging.NewLogBackend(rotate, "", 0)
 	return logging.NewBackendFormatter(backend, newFormatter(true))
 }
 
@@ -129,6 +142,8 @@ func newFormatter(withTime bool) logging.Formatter {
 // CloseLogger closes the rotating log writer and cleans up resources.
 // Should be called during application shutdown.
 func CloseLogger() {
+	fileRotateMu.Lock()
+	defer fileRotateMu.Unlock()
 	if fileRotate != nil {
 		_ = fileRotate.Close()
 		fileRotate = nil
@@ -137,61 +152,61 @@ func CloseLogger() {
 
 // Debug logs a debug message and adds it to the log buffer.
 func Debug(args ...any) {
-	logger.Debug(args...)
+	logger.Load().Debug(args...)
 	addToBuffer("DEBUG", fmt.Sprint(args...))
 }
 
 // Debugf logs a formatted debug message and adds it to the log buffer.
 func Debugf(format string, args ...any) {
-	logger.Debugf(format, args...)
+	logger.Load().Debugf(format, args...)
 	addToBuffer("DEBUG", fmt.Sprintf(format, args...))
 }
 
 // Info logs an info message and adds it to the log buffer.
 func Info(args ...any) {
-	logger.Info(args...)
+	logger.Load().Info(args...)
 	addToBuffer("INFO", fmt.Sprint(args...))
 }
 
 // Infof logs a formatted info message and adds it to the log buffer.
 func Infof(format string, args ...any) {
-	logger.Infof(format, args...)
+	logger.Load().Infof(format, args...)
 	addToBuffer("INFO", fmt.Sprintf(format, args...))
 }
 
 // Notice logs a notice message and adds it to the log buffer.
 func Notice(args ...any) {
-	logger.Notice(args...)
+	logger.Load().Notice(args...)
 	addToBuffer("NOTICE", fmt.Sprint(args...))
 }
 
 // Noticef logs a formatted notice message and adds it to the log buffer.
 func Noticef(format string, args ...any) {
-	logger.Noticef(format, args...)
+	logger.Load().Noticef(format, args...)
 	addToBuffer("NOTICE", fmt.Sprintf(format, args...))
 }
 
 // Warning logs a warning message and adds it to the log buffer.
 func Warning(args ...any) {
-	logger.Warning(args...)
+	logger.Load().Warning(args...)
 	addToBuffer("WARNING", fmt.Sprint(args...))
 }
 
 // Warningf logs a formatted warning message and adds it to the log buffer.
 func Warningf(format string, args ...any) {
-	logger.Warningf(format, args...)
+	logger.Load().Warningf(format, args...)
 	addToBuffer("WARNING", fmt.Sprintf(format, args...))
 }
 
 // Error logs an error message and adds it to the log buffer.
 func Error(args ...any) {
-	logger.Error(args...)
+	logger.Load().Error(args...)
 	addToBuffer("ERROR", fmt.Sprint(args...))
 }
 
 // Errorf logs a formatted error message and adds it to the log buffer.
 func Errorf(format string, args ...any) {
-	logger.Errorf(format, args...)
+	logger.Load().Errorf(format, args...)
 	addToBuffer("ERROR", fmt.Sprintf(format, args...))
 }
 

+ 30 - 0
internal/logger/logger_test.go

@@ -2,7 +2,10 @@ package logger
 
 import (
 	"fmt"
+	"sync"
 	"testing"
+
+	golog "github.com/op/go-logging"
 )
 
 // TestGetLogs_ReturnsAtMostC guards the documented "up to c entries" contract.
@@ -28,3 +31,30 @@ func TestGetLogs_ReturnsAtMostC(t *testing.T) {
 		}
 	}
 }
+
+// InitLogger replaces the package logger while other goroutines are already
+// logging — CI caught that as a data race between InitLogger and Warningf.
+func TestInitLoggerConcurrentWithLogging(t *testing.T) {
+	t.Setenv("XUI_LOG_FOLDER", t.TempDir())
+
+	stop := make(chan struct{})
+	var logging sync.WaitGroup
+	logging.Add(1)
+	go func() {
+		defer logging.Done()
+		for {
+			select {
+			case <-stop:
+				return
+			default:
+				Warningf("concurrent %s", "log")
+			}
+		}
+	}()
+
+	for range 10 {
+		InitLogger(golog.CRITICAL)
+	}
+	close(stop)
+	logging.Wait()
+}