From 7314726babecb04da7f5e38db79c2115f8eedafe Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Sat, 27 May 2023 18:55:24 +0800 Subject: [PATCH] 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 --- modules/log/event_writer_base.go | 2 +- modules/log/init.go | 24 ++++++++--------------- modules/log/logger_impl.go | 2 +- modules/log/manager.go | 2 +- modules/process/manager.go | 33 ++++++++++++++++++++++++-------- 5 files changed, 36 insertions(+), 27 deletions(-) diff --git a/modules/log/event_writer_base.go b/modules/log/event_writer_base.go index 1d45d579c..c9df9fdb2 100644 --- a/modules/log/event_writer_base.go +++ b/modules/log/event_writer_base.go @@ -149,7 +149,7 @@ func eventWriterStartGo(ctx context.Context, w EventWriter, shared bool) { if shared { ctxDesc = "Logger: EventWriter (shared): " + w.GetWriterName() } - writerCtx, writerCancel := newContext(ctx, ctxDesc) + writerCtx, writerCancel := newProcessTypedContext(ctx, ctxDesc) go func() { defer writerCancel() defer close(w.Base().stopped) diff --git a/modules/log/init.go b/modules/log/init.go index 38a3ad60a..3fb5200ad 100644 --- a/modules/log/init.go +++ b/modules/log/init.go @@ -7,16 +7,12 @@ import ( "context" "runtime" "strings" - "sync/atomic" "code.gitea.io/gitea/modules/process" "code.gitea.io/gitea/modules/util/rotatingfilewriter" ) -var ( - projectPackagePrefix string - processTraceDisabled atomic.Int64 -) +var projectPackagePrefix string func init() { _, filename, _, _ := runtime.Caller(0) @@ -28,25 +24,21 @@ func init() { rotatingfilewriter.ErrorPrintf = FallbackErrorf - process.Trace = func(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 - } + process.TraceCallback = func(skip int, start bool, pid process.IDType, description string, parentPID process.IDType, typ string) { 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 { - 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 { - 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 - processTraceDisabled.Add(1) - defer processTraceDisabled.Add(-1) + process.TraceLogDisable(true) + defer process.TraceLogDisable(false) ctx, _, cancel = process.GetManager().AddTypedContext(parent, desc, process.SystemProcessType, false) return ctx, cancel } diff --git a/modules/log/logger_impl.go b/modules/log/logger_impl.go index abd72d326..903d8cefc 100644 --- a/modules/log/logger_impl.go +++ b/modules/log/logger_impl.go @@ -230,7 +230,7 @@ func (l *LoggerImpl) GetLevel() Level { func NewLoggerWithWriters(ctx context.Context, name string, writer ...EventWriter) *LoggerImpl { l := &LoggerImpl{} - l.ctx, l.ctxCancel = newContext(ctx, "Logger: "+name) + l.ctx, l.ctxCancel = newProcessTypedContext(ctx, "Logger: "+name) l.LevelLogger = BaseLoggerToGeneralLogger(l) l.eventWriters = map[string]EventWriter{} l.syncLevelInternal() diff --git a/modules/log/manager.go b/modules/log/manager.go index b5d6cbf8e..0417bbe6e 100644 --- a/modules/log/manager.go +++ b/modules/log/manager.go @@ -137,6 +137,6 @@ func GetManager() *LoggerManager { func NewManager() *LoggerManager { 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 } diff --git a/modules/process/manager.go b/modules/process/manager.go index 25d503c59..56908c040 100644 --- a/modules/process/manager.go +++ b/modules/process/manager.go @@ -6,10 +6,10 @@ package process import ( "context" - "log" "runtime/pprof" "strconv" "sync" + "sync/atomic" "time" ) @@ -44,18 +44,35 @@ type IDType string // - it is simply an alias for context.CancelFunc and is only for documentary purposes 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) { - if start && parentPID != "" { - 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) +// defaultTraceCallback is a no-op. Without a proper TraceCallback (provided by the logger system), this "Trace" level messages shouldn't be outputted. +func defaultTraceCallback(skip int, start bool, pid IDType, description string, parentPID IDType, typ string) { +} + +// 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 { - 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. type Manager struct { mutex sync.Mutex