fix(xlog): make Logger prefix updates safe for concurrent logging (#5586)

Logger kept its rendered prefix in a plain string field that was written by
AddPrefix, AppendPrefix and ResetPrefixes and read without synchronization by
Tracef, Spawn and the other logging methods. In frpc the race is reachable on
the service-level logger, which every component of a session shares through
its context: adding the run ID after a login writes the prefix while control,
proxy manager, connector and visitor goroutines keep logging through the same
logger, and a reload that creates proxies calls Spawn on it. A torn string
header can pair a nil data pointer with a non-zero length, and formatting such
a prefix can crash the process when the log call's level is enabled.

Serialize the writers with a per-Logger mutex and publish the rendered prefix
as an immutable string through an atomic pointer, so the log path takes no
lock. Spawn copies the parent prefix list under the same mutex, keeping
children independent snapshots. Logging output is unchanged.
This commit is contained in:
fatedier
2026-10-23 15:52:11 +08:00
committed by GitHub
parent 8d5e9d2b21
commit 93b52799bb
2 changed files with 76 additions and 10 deletions
+29 -10
View File
@@ -17,6 +17,8 @@ package xlog
import ( import (
"cmp" "cmp"
"slices" "slices"
"sync"
"sync/atomic"
"github.com/fatedier/frp/pkg/util/log" "github.com/fatedier/frp/pkg/util/log"
) )
@@ -30,11 +32,13 @@ type LogPrefix struct {
Priority int Priority int
} }
// Logger is not thread safety for operations on prefix // Logger supports concurrent logging and prefix updates.
// A Logger must not be copied after first use.
type Logger struct { type Logger struct {
mu sync.Mutex
prefixes []LogPrefix prefixes []LogPrefix
prefixString string prefixString atomic.Pointer[string]
} }
func New() *Logger { func New() *Logger {
@@ -44,9 +48,11 @@ func New() *Logger {
} }
func (l *Logger) ResetPrefixes() (old []LogPrefix) { func (l *Logger) ResetPrefixes() (old []LogPrefix) {
l.mu.Lock()
defer l.mu.Unlock()
old = l.prefixes old = l.prefixes
l.prefixes = make([]LogPrefix, 0) l.prefixes = make([]LogPrefix, 0)
l.prefixString = "" l.prefixString.Store(nil)
return return
} }
@@ -59,6 +65,8 @@ func (l *Logger) AppendPrefix(prefix string) *Logger {
} }
func (l *Logger) AddPrefix(prefix LogPrefix) *Logger { func (l *Logger) AddPrefix(prefix LogPrefix) *Logger {
l.mu.Lock()
defer l.mu.Unlock()
found := false found := false
if prefix.Priority <= 0 { if prefix.Priority <= 0 {
prefix.Priority = 10 prefix.Priority = 10
@@ -78,39 +86,50 @@ func (l *Logger) AddPrefix(prefix LogPrefix) *Logger {
return l return l
} }
// The caller must hold l.mu or exclusively own an unpublished logger.
func (l *Logger) renderPrefixString() { func (l *Logger) renderPrefixString() {
slices.SortStableFunc(l.prefixes, func(a, b LogPrefix) int { slices.SortStableFunc(l.prefixes, func(a, b LogPrefix) int {
return cmp.Compare(a.Priority, b.Priority) return cmp.Compare(a.Priority, b.Priority)
}) })
l.prefixString = "" var prefixString string
for _, v := range l.prefixes { for _, v := range l.prefixes {
l.prefixString += "[" + v.Value + "] " prefixString += "[" + v.Value + "] "
} }
l.prefixString.Store(&prefixString)
} }
func (l *Logger) Spawn() *Logger { func (l *Logger) Spawn() *Logger {
nl := New() nl := New()
l.mu.Lock()
nl.prefixes = append(nl.prefixes, l.prefixes...) nl.prefixes = append(nl.prefixes, l.prefixes...)
l.mu.Unlock()
nl.renderPrefixString() nl.renderPrefixString()
return nl return nl
} }
func (l *Logger) getPrefixString() string {
if prefix := l.prefixString.Load(); prefix != nil {
return *prefix
}
return ""
}
func (l *Logger) Errorf(format string, v ...any) { func (l *Logger) Errorf(format string, v ...any) {
log.Logger.WithPrefix(l.prefixString).Errorf(format, v...) log.Logger.WithPrefix(l.getPrefixString()).Errorf(format, v...)
} }
func (l *Logger) Warnf(format string, v ...any) { func (l *Logger) Warnf(format string, v ...any) {
log.Logger.WithPrefix(l.prefixString).Warnf(format, v...) log.Logger.WithPrefix(l.getPrefixString()).Warnf(format, v...)
} }
func (l *Logger) Infof(format string, v ...any) { func (l *Logger) Infof(format string, v ...any) {
log.Logger.WithPrefix(l.prefixString).Infof(format, v...) log.Logger.WithPrefix(l.getPrefixString()).Infof(format, v...)
} }
func (l *Logger) Debugf(format string, v ...any) { func (l *Logger) Debugf(format string, v ...any) {
log.Logger.WithPrefix(l.prefixString).Debugf(format, v...) log.Logger.WithPrefix(l.getPrefixString()).Debugf(format, v...)
} }
func (l *Logger) Tracef(format string, v ...any) { func (l *Logger) Tracef(format string, v ...any) {
log.Logger.WithPrefix(l.prefixString).Tracef(format, v...) log.Logger.WithPrefix(l.getPrefixString()).Tracef(format, v...)
} }
+47
View File
@@ -0,0 +1,47 @@
// Copyright 2026 The frp Authors
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
// http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.
package xlog
import (
"sync"
"testing"
)
func TestLoggerConcurrentPrefixAccess(t *testing.T) {
captureLogs(t)
xl := New().AddPrefix(LogPrefix{Name: "runID", Value: "old-run"})
start := make(chan struct{})
var wg sync.WaitGroup
wg.Add(2)
go func() {
defer wg.Done()
<-start
xl.AddPrefix(LogPrefix{Name: "runID", Value: "new-run"})
xl.AppendPrefix("proxy")
xl.ResetPrefixes()
}()
go func() {
defer wg.Done()
<-start
xl.Spawn().Tracef("spawn")
xl.Errorf("error")
xl.Warnf("warn")
xl.Infof("info")
xl.Debugf("debug")
xl.Tracef("trace")
}()
close(start)
wg.Wait()
}