0
0
mirror of https://github.com/go-gitea/gitea.git synced 2026-05-13 15:26:12 +02:00

refactor: routing info middleware (#37653)

fix #37650
This commit is contained in:
wxiaoguang 2026-05-11 22:39:50 +08:00 committed by GitHub
parent 7621b65403
commit 2eb7b3c7da
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
5 changed files with 87 additions and 95 deletions

View File

@ -11,19 +11,6 @@ import (
"code.gitea.io/gitea/modules/web/types" "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 ( var (
startMessage = log.NewColoredValue("started ", log.DEBUG.ColorAttributes()...) startMessage = log.NewColoredValue("started ", log.DEBUG.ColorAttributes()...)
slowMessage = log.NewColoredValue("slow ", log.WARN.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 var status int
if v, ok := record.responseWriter.(types.ResponseStatusProvider); ok { if v, ok := record.respWriter.(types.ResponseStatusProvider); ok {
status = v.WrittenStatus() status = v.WrittenStatus()
} }
logLevel := record.logLevel logLevel := record.logLevel

View File

@ -6,7 +6,6 @@ package routing
import ( import (
"context" "context"
"fmt" "fmt"
"net/http"
"sync" "sync"
"time" "time"
@ -29,26 +28,21 @@ const (
EndEvent EndEvent
) )
// Printer is used to output the log for a request // logPrinterFunc is used to output the log for a request
type Printer func(trigger Event, record *requestRecord) type logPrinterFunc func(trigger Event, record *requestRecord)
type requestRecordsManager struct { type loggerRequestManager struct {
print Printer logPrint logPrinterFunc
reqRecords sync.Map // it only contains the active requests which haven't been detected as "slow"
lock sync.Mutex
requestRecords map[uint64]*requestRecord
count uint64
} }
func (manager *requestRecordsManager) startSlowQueryDetector(threshold time.Duration) { func (manager *loggerRequestManager) startSlowQueryDetector(threshold time.Duration) {
go graceful.GetManager().RunWithShutdownContext(func(ctx context.Context) { go graceful.GetManager().RunWithShutdownContext(func(ctx context.Context) {
ctx, _, finished := process.GetManager().AddTypedContext(ctx, "Service: SlowQueryDetector", process.SystemProcessType, true) ctx, _, finished := process.GetManager().AddTypedContext(ctx, "Service: SlowQueryDetector", process.SystemProcessType, true)
defer finished() defer finished()
// This go-routine checks all active requests every second. // 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 // 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 // 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. // 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) t := time.NewTicker(time.Second)
for { for {
@ -58,69 +52,39 @@ func (manager *requestRecordsManager) startSlowQueryDetector(threshold time.Dura
case <-t.C: case <-t.C:
now := time.Now() 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 // print logs for slow requests
for _, record := range slowRequests { manager.reqRecords.Range(func(key, value any) bool {
manager.print(StillExecutingEvent, record) 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 { func (manager *loggerRequestManager) handleRequestRecord(record *requestRecord) func() {
return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { manager.reqRecords.Store(record.index, record)
record := &requestRecord{ manager.logPrint(StartEvent, record)
startTime: time.Now(),
request: req, return func() {
responseWriter: w, // 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.reqRecords.Delete(record.index)
manager.lock.Lock() manager.logPrint(EndEvent, record)
record.index = manager.count
manager.count++
manager.requestRecords[record.index] = record
manager.lock.Unlock()
defer func() { if localPanicErr != nil {
// just in case there is a panic. now the panics are all recovered in middleware.go // the panic wasn't recovered before us, so we should pass it up, and let the framework handle the panic error
localPanicErr := recover() panic(localPanicErr)
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)
})
} }

View File

@ -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)
})
}
}

View File

@ -12,20 +12,20 @@ import (
) )
type requestRecord struct { type requestRecord struct {
// index of the record in the records map
index uint64
// immutable fields // immutable fields
startTime time.Time index uint64 // unique number (per process) for the request
request *http.Request startTime time.Time
responseWriter http.ResponseWriter request *http.Request
respWriter http.ResponseWriter
// mutex // mutex
lock sync.RWMutex lock sync.RWMutex
// mutable fields // below are mutable fields
funcInfo *FuncInfo
// * for "mark as long polling"
isLongPolling bool isLongPolling bool
logLevel log.Level // * for router logger
funcInfo *FuncInfo logLevel log.Level
panicError error panicError error
} }

View File

@ -34,9 +34,7 @@ func ProtocolMiddlewares() (handlers []any) {
handlers = append(handlers, ForwardedHeadersHandler(setting.ReverseProxyLimit, setting.ReverseProxyTrustedProxies)) handlers = append(handlers, ForwardedHeadersHandler(setting.ReverseProxyLimit, setting.ReverseProxyTrustedProxies))
} }
if setting.IsRouteLogEnabled() { handlers = append(handlers, routing.NewRequestInfoHandler())
handlers = append(handlers, routing.NewLoggerHandler())
}
if setting.IsAccessLogEnabled() { if setting.IsAccessLogEnabled() {
handlers = append(handlers, context.AccessLogger()) handlers = append(handlers, context.AccessLogger())