diff --git a/modules/log/event_writer_base.go b/modules/log/event_writer_base.go index 1d45d579c0..c9df9fdb24 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 38a3ad60a5..3fb5200ad7 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 abd72d326f..903d8cefc2 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 b5d6cbf8e1..0417bbe6e9 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 25d503c594..56908c0408 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