Do not output "Trace" level logs from process manager by default (#24952)

The old process manager's `Trace` function by default calls `log.Printf`
to output "trace" level logs. That's not ideal because by default the
trace level logs should not be outputted. In history it didn't cause
problems because there was no other call to the process manager before
the logger system's initialization.

But if there is any package using the process manager before the "Trace"
function gets assigned to the logger system's trace function, the
process manager will outputs unexpected verbose messages, this behavior
is not expected in most cases.

Now, the logger system also uses process manager to manage its goroutine
contexts, so it's the time to fix the old "trace" behavior: by default,
do not output the trace level messages. Fix #24951
This commit is contained in:
wxiaoguang 2023-05-27 18:55:24 +08:00 committed by GitHub
parent 4a58a8ca31
commit 7314726bab
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
5 changed files with 36 additions and 27 deletions

View file

@ -149,7 +149,7 @@ func eventWriterStartGo(ctx context.Context, w EventWriter, shared bool) {
if shared { if shared {
ctxDesc = "Logger: EventWriter (shared): " + w.GetWriterName() ctxDesc = "Logger: EventWriter (shared): " + w.GetWriterName()
} }
writerCtx, writerCancel := newContext(ctx, ctxDesc) writerCtx, writerCancel := newProcessTypedContext(ctx, ctxDesc)
go func() { go func() {
defer writerCancel() defer writerCancel()
defer close(w.Base().stopped) defer close(w.Base().stopped)

View file

@ -7,16 +7,12 @@ import (
"context" "context"
"runtime" "runtime"
"strings" "strings"
"sync/atomic"
"code.gitea.io/gitea/modules/process" "code.gitea.io/gitea/modules/process"
"code.gitea.io/gitea/modules/util/rotatingfilewriter" "code.gitea.io/gitea/modules/util/rotatingfilewriter"
) )
var ( var projectPackagePrefix string
projectPackagePrefix string
processTraceDisabled atomic.Int64
)
func init() { func init() {
_, filename, _, _ := runtime.Caller(0) _, filename, _, _ := runtime.Caller(0)
@ -28,25 +24,21 @@ func init() {
rotatingfilewriter.ErrorPrintf = FallbackErrorf rotatingfilewriter.ErrorPrintf = FallbackErrorf
process.Trace = func(start bool, pid process.IDType, description string, parentPID process.IDType, typ string) { process.TraceCallback = func(skip int, start bool, pid process.IDType, description string, parentPID process.IDType, typ string) {
// the logger manager has its own mutex lock, so it's safe to use "Load" here
if processTraceDisabled.Load() != 0 {
return
}
if start && parentPID != "" { if start && parentPID != "" {
Log(1, TRACE, "Start %s: %s (from %s) (%s)", NewColoredValue(pid, FgHiYellow), description, NewColoredValue(parentPID, FgYellow), NewColoredValue(typ, Reset)) Log(skip+1, TRACE, "Start %s: %s (from %s) (%s)", NewColoredValue(pid, FgHiYellow), description, NewColoredValue(parentPID, FgYellow), NewColoredValue(typ, Reset))
} else if start { } else if start {
Log(1, TRACE, "Start %s: %s (%s)", NewColoredValue(pid, FgHiYellow), description, NewColoredValue(typ, Reset)) Log(skip+1, TRACE, "Start %s: %s (%s)", NewColoredValue(pid, FgHiYellow), description, NewColoredValue(typ, Reset))
} else { } else {
Log(1, TRACE, "Done %s: %s", NewColoredValue(pid, FgHiYellow), NewColoredValue(description, Reset)) Log(skip+1, TRACE, "Done %s: %s", NewColoredValue(pid, FgHiYellow), NewColoredValue(description, Reset))
} }
} }
} }
func newContext(parent context.Context, desc string) (ctx context.Context, cancel context.CancelFunc) { func newProcessTypedContext(parent context.Context, desc string) (ctx context.Context, cancel context.CancelFunc) {
// the "process manager" also calls "log.Trace()" to output logs, so if we want to create new contexts by the manager, we need to disable the trace temporarily // the "process manager" also calls "log.Trace()" to output logs, so if we want to create new contexts by the manager, we need to disable the trace temporarily
processTraceDisabled.Add(1) process.TraceLogDisable(true)
defer processTraceDisabled.Add(-1) defer process.TraceLogDisable(false)
ctx, _, cancel = process.GetManager().AddTypedContext(parent, desc, process.SystemProcessType, false) ctx, _, cancel = process.GetManager().AddTypedContext(parent, desc, process.SystemProcessType, false)
return ctx, cancel return ctx, cancel
} }

View file

@ -230,7 +230,7 @@ func (l *LoggerImpl) GetLevel() Level {
func NewLoggerWithWriters(ctx context.Context, name string, writer ...EventWriter) *LoggerImpl { func NewLoggerWithWriters(ctx context.Context, name string, writer ...EventWriter) *LoggerImpl {
l := &LoggerImpl{} l := &LoggerImpl{}
l.ctx, l.ctxCancel = newContext(ctx, "Logger: "+name) l.ctx, l.ctxCancel = newProcessTypedContext(ctx, "Logger: "+name)
l.LevelLogger = BaseLoggerToGeneralLogger(l) l.LevelLogger = BaseLoggerToGeneralLogger(l)
l.eventWriters = map[string]EventWriter{} l.eventWriters = map[string]EventWriter{}
l.syncLevelInternal() l.syncLevelInternal()

View file

@ -137,6 +137,6 @@ func GetManager() *LoggerManager {
func NewManager() *LoggerManager { func NewManager() *LoggerManager {
m := &LoggerManager{writers: map[string]EventWriter{}, loggers: map[string]*LoggerImpl{}} m := &LoggerManager{writers: map[string]EventWriter{}, loggers: map[string]*LoggerImpl{}}
m.ctx, m.ctxCancel = newContext(context.Background(), "LoggerManager") m.ctx, m.ctxCancel = newProcessTypedContext(context.Background(), "LoggerManager")
return m return m
} }

View file

@ -6,10 +6,10 @@ package process
import ( import (
"context" "context"
"log"
"runtime/pprof" "runtime/pprof"
"strconv" "strconv"
"sync" "sync"
"sync/atomic"
"time" "time"
) )
@ -44,18 +44,35 @@ type IDType string
// - it is simply an alias for context.CancelFunc and is only for documentary purposes // - it is simply an alias for context.CancelFunc and is only for documentary purposes
type FinishedFunc = context.CancelFunc type FinishedFunc = context.CancelFunc
var Trace = defaultTrace // this global can be overridden by particular logging packages - thus avoiding import cycles var (
traceDisabled atomic.Int64
TraceCallback = defaultTraceCallback // this global can be overridden by particular logging packages - thus avoiding import cycles
)
func defaultTrace(start bool, pid IDType, description string, parentPID IDType, typ string) { // defaultTraceCallback is a no-op. Without a proper TraceCallback (provided by the logger system), this "Trace" level messages shouldn't be outputted.
if start && parentPID != "" { func defaultTraceCallback(skip int, start bool, pid IDType, description string, parentPID IDType, typ string) {
log.Printf("start process %s: %s (from %s) (%s)", pid, description, parentPID, typ) }
} else if start {
log.Printf("start process %s: %s (%s)", pid, description, typ) // TraceLogDisable disables (or revert the disabling) the trace log for the process lifecycle.
// eg: the logger system shouldn't print the trace log for themselves, that's cycle dependency (Logger -> ProcessManager -> TraceCallback -> Logger ...)
// Theoretically, such trace log should only be enabled when the logger system is ready with a proper level, so the default TraceCallback is a no-op.
func TraceLogDisable(v bool) {
if v {
traceDisabled.Add(1)
} else { } else {
log.Printf("end process %s: %s", pid, description) traceDisabled.Add(-1)
} }
} }
func Trace(start bool, pid IDType, description string, parentPID IDType, typ string) {
if traceDisabled.Load() != 0 {
// the traceDisabled counter is mainly for recursive calls, so no concurrency problem.
// because the counter can't be 0 since the caller function hasn't returned (decreased the counter) yet.
return
}
TraceCallback(1, start, pid, description, parentPID, typ)
}
// Manager manages all processes and counts PIDs. // Manager manages all processes and counts PIDs.
type Manager struct { type Manager struct {
mutex sync.Mutex mutex sync.Mutex