From 2eb7b3c7da65cc0ceeeb0de6d16fa8ab571579db Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Mon, 11 May 2026 22:39:50 +0800 Subject: [PATCH] refactor: routing info middleware (#37653) fix #37650 --- modules/web/routing/logger.go | 15 +--- modules/web/routing/logger_manager.go | 100 +++++++++----------------- modules/web/routing/requestinfo.go | 43 +++++++++++ modules/web/routing/requestrecord.go | 20 +++--- routers/common/middleware.go | 4 +- 5 files changed, 87 insertions(+), 95 deletions(-) create mode 100644 modules/web/routing/requestinfo.go diff --git a/modules/web/routing/logger.go b/modules/web/routing/logger.go index cd139df66b..818766fbd2 100644 --- a/modules/web/routing/logger.go +++ b/modules/web/routing/logger.go @@ -11,19 +11,6 @@ import ( "code.gitea.io/gitea/modules/web/types" ) -// NewLoggerHandler is a handler that will log routing to the router log taking account of -// routing information -func NewLoggerHandler() func(next http.Handler) http.Handler { - manager := requestRecordsManager{ - requestRecords: map[uint64]*requestRecord{}, - } - manager.startSlowQueryDetector(3 * time.Second) - - logger := log.GetLogger("router") - manager.print = logPrinter(logger) - return manager.handler -} - var ( startMessage = log.NewColoredValue("started ", log.DEBUG.ColorAttributes()...) slowMessage = log.NewColoredValue("slow ", log.WARN.ColorAttributes()...) @@ -89,7 +76,7 @@ func logPrinter(logger log.Logger) func(trigger Event, record *requestRecord) { } var status int - if v, ok := record.responseWriter.(types.ResponseStatusProvider); ok { + if v, ok := record.respWriter.(types.ResponseStatusProvider); ok { status = v.WrittenStatus() } logLevel := record.logLevel diff --git a/modules/web/routing/logger_manager.go b/modules/web/routing/logger_manager.go index 2f767c3d66..e63c73994f 100644 --- a/modules/web/routing/logger_manager.go +++ b/modules/web/routing/logger_manager.go @@ -6,7 +6,6 @@ package routing import ( "context" "fmt" - "net/http" "sync" "time" @@ -29,26 +28,21 @@ const ( EndEvent ) -// Printer is used to output the log for a request -type Printer func(trigger Event, record *requestRecord) +// logPrinterFunc is used to output the log for a request +type logPrinterFunc func(trigger Event, record *requestRecord) -type requestRecordsManager struct { - print Printer - - lock sync.Mutex - - requestRecords map[uint64]*requestRecord - count uint64 +type loggerRequestManager struct { + logPrint logPrinterFunc + reqRecords sync.Map // it only contains the active requests which haven't been detected as "slow" } -func (manager *requestRecordsManager) startSlowQueryDetector(threshold time.Duration) { +func (manager *loggerRequestManager) startSlowQueryDetector(threshold time.Duration) { go graceful.GetManager().RunWithShutdownContext(func(ctx context.Context) { ctx, _, finished := process.GetManager().AddTypedContext(ctx, "Service: SlowQueryDetector", process.SystemProcessType, true) defer finished() // This go-routine checks all active requests every second. // If a request has been running for a long time (eg: /user/events), we also print a log with "still-executing" message // After the "still-executing" log is printed, the record will be removed from the map to prevent from duplicated logs in future - // We do not care about accurate duration here. It just does the check periodically, 0.5s or 1.5s are all OK. t := time.NewTicker(time.Second) for { @@ -58,69 +52,39 @@ func (manager *requestRecordsManager) startSlowQueryDetector(threshold time.Dura case <-t.C: now := time.Now() - var slowRequests []*requestRecord - - // find all slow requests with lock - manager.lock.Lock() - for index, record := range manager.requestRecords { - if now.Sub(record.startTime) < threshold { - continue - } - - slowRequests = append(slowRequests, record) - delete(manager.requestRecords, index) - } - manager.lock.Unlock() - // print logs for slow requests - for _, record := range slowRequests { - manager.print(StillExecutingEvent, record) - } + manager.reqRecords.Range(func(key, value any) bool { + index, record := key.(uint64), value.(*requestRecord) + if now.Sub(record.startTime) >= threshold { + manager.logPrint(StillExecutingEvent, record) + manager.reqRecords.Delete(index) + } + return true + }) } } }) } -func (manager *requestRecordsManager) handler(next http.Handler) http.Handler { - return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { - record := &requestRecord{ - startTime: time.Now(), - request: req, - responseWriter: w, +func (manager *loggerRequestManager) handleRequestRecord(record *requestRecord) func() { + manager.reqRecords.Store(record.index, record) + manager.logPrint(StartEvent, record) + + return func() { + // just in case there is a panic. now the panics are all recovered in middleware.go + localPanicErr := recover() + if localPanicErr != nil { + record.lock.Lock() + record.panicError = fmt.Errorf("%v\n%s", localPanicErr, log.Stack(2)) + record.lock.Unlock() } - // generate a record index an insert into the map - manager.lock.Lock() - record.index = manager.count - manager.count++ - manager.requestRecords[record.index] = record - manager.lock.Unlock() + manager.reqRecords.Delete(record.index) + manager.logPrint(EndEvent, record) - defer func() { - // just in case there is a panic. now the panics are all recovered in middleware.go - localPanicErr := recover() - if localPanicErr != nil { - record.lock.Lock() - record.panicError = fmt.Errorf("%v\n%s", localPanicErr, log.Stack(2)) - record.lock.Unlock() - } - - // remove from the record map - manager.lock.Lock() - delete(manager.requestRecords, record.index) - manager.lock.Unlock() - - // log the end of the request - manager.print(EndEvent, record) - - if localPanicErr != nil { - // the panic wasn't recovered before us, so we should pass it up, and let the framework handle the panic error - panic(localPanicErr) - } - }() - - req = req.WithContext(context.WithValue(req.Context(), contextKey, record)) - manager.print(StartEvent, record) - next.ServeHTTP(w, req) - }) + if localPanicErr != nil { + // the panic wasn't recovered before us, so we should pass it up, and let the framework handle the panic error + panic(localPanicErr) + } + } } diff --git a/modules/web/routing/requestinfo.go b/modules/web/routing/requestinfo.go new file mode 100644 index 0000000000..a88b541008 --- /dev/null +++ b/modules/web/routing/requestinfo.go @@ -0,0 +1,43 @@ +// Copyright 2026 The Gitea Authors. All rights reserved. +// SPDX-License-Identifier: MIT + +package routing + +import ( + "context" + "net/http" + "sync/atomic" + "time" + + "code.gitea.io/gitea/modules/log" + "code.gitea.io/gitea/modules/setting" +) + +// NewRequestInfoHandler is a handler that saves request info into request context. +// If router logger is enabled, it will also print request logs and detect slow requests. +func NewRequestInfoHandler() func(next http.Handler) http.Handler { + var reqLogger *loggerRequestManager + if setting.IsRouteLogEnabled() { + reqLogger = &loggerRequestManager{ + logPrint: logPrinter(log.GetLogger("router")), + } + reqLogger.startSlowQueryDetector(3 * time.Second) + } + var requestCounter atomic.Uint64 + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { + record := &requestRecord{ + index: requestCounter.Add(1), + startTime: time.Now(), + respWriter: w, + } + req = req.WithContext(context.WithValue(req.Context(), contextKey, record)) + record.request = req + if reqLogger != nil { + end := reqLogger.handleRequestRecord(record) + defer end() + } + next.ServeHTTP(w, req) + }) + } +} diff --git a/modules/web/routing/requestrecord.go b/modules/web/routing/requestrecord.go index 898e2f6d47..5ef6feac7e 100644 --- a/modules/web/routing/requestrecord.go +++ b/modules/web/routing/requestrecord.go @@ -12,20 +12,20 @@ import ( ) type requestRecord struct { - // index of the record in the records map - index uint64 - // immutable fields - startTime time.Time - request *http.Request - responseWriter http.ResponseWriter + index uint64 // unique number (per process) for the request + startTime time.Time + request *http.Request + respWriter http.ResponseWriter // mutex lock sync.RWMutex - // mutable fields + // below are mutable fields + funcInfo *FuncInfo + // * for "mark as long polling" isLongPolling bool - logLevel log.Level - funcInfo *FuncInfo - panicError error + // * for router logger + logLevel log.Level + panicError error } diff --git a/routers/common/middleware.go b/routers/common/middleware.go index 3932a84b6d..d1802c6e35 100644 --- a/routers/common/middleware.go +++ b/routers/common/middleware.go @@ -34,9 +34,7 @@ func ProtocolMiddlewares() (handlers []any) { handlers = append(handlers, ForwardedHeadersHandler(setting.ReverseProxyLimit, setting.ReverseProxyTrustedProxies)) } - if setting.IsRouteLogEnabled() { - handlers = append(handlers, routing.NewLoggerHandler()) - } + handlers = append(handlers, routing.NewRequestInfoHandler()) if setting.IsAccessLogEnabled() { handlers = append(handlers, context.AccessLogger())