fix

Author: wxiaoguang

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)

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
 }

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()

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
 }

modules/process/manager.go

@@ -6,10 +6,10 @@ package process
 
 import (
 	"context"
-	"log"
 	"runtime/pprof"
 	"strconv"
 	"sync"
+	"sync/atomic"
 	"time"
 )
 
@@ -44,16 +44,33 @@ 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
+)
+
+// 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) {
+}
 
-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)
+// 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.