This commit is contained in:
@@ -7,15 +7,21 @@ import (
|
||||
"context"
|
||||
"net/http"
|
||||
|
||||
"code.gitea.io/gitea/modules/gtprof"
|
||||
"code.gitea.io/gitea/modules/log"
|
||||
"code.gitea.io/gitea/modules/reqctx"
|
||||
"gitea.dev/modules/gtprof"
|
||||
"gitea.dev/modules/log"
|
||||
"gitea.dev/modules/reqctx"
|
||||
"gitea.dev/modules/web/types"
|
||||
)
|
||||
|
||||
type contextKeyType struct{}
|
||||
|
||||
var contextKey contextKeyType
|
||||
|
||||
func getRequestRecord(ctx context.Context) *requestRecord {
|
||||
record, _ := ctx.Value(contextKey).(*requestRecord)
|
||||
return record
|
||||
}
|
||||
|
||||
// RecordFuncInfo records a func info into context
|
||||
func RecordFuncInfo(ctx context.Context, funcInfo *FuncInfo) (end func()) {
|
||||
end = func() {}
|
||||
@@ -24,7 +30,7 @@ func RecordFuncInfo(ctx context.Context, funcInfo *FuncInfo) (end func()) {
|
||||
traceSpan, end = gtprof.GetTracer().StartInContext(reqCtx, "http.func")
|
||||
traceSpan.SetAttributeString("func", funcInfo.shortName)
|
||||
}
|
||||
if record, ok := ctx.Value(contextKey).(*requestRecord); ok {
|
||||
if record := getRequestRecord(ctx); record != nil {
|
||||
record.lock.Lock()
|
||||
record.funcInfo = funcInfo
|
||||
record.lock.Unlock()
|
||||
@@ -32,22 +38,39 @@ func RecordFuncInfo(ctx context.Context, funcInfo *FuncInfo) (end func()) {
|
||||
return end
|
||||
}
|
||||
|
||||
// MarkLongPolling marks the request is a long-polling request, and the logger may output different message for it
|
||||
func MarkLongPolling(resp http.ResponseWriter, req *http.Request) {
|
||||
record, ok := req.Context().Value(contextKey).(*requestRecord)
|
||||
if !ok {
|
||||
return
|
||||
func GetRequestRecordInfo(reqCtx context.Context) (ret struct {
|
||||
HasRecord bool
|
||||
IsLongPolling bool
|
||||
},
|
||||
) {
|
||||
record := getRequestRecord(reqCtx)
|
||||
if record == nil {
|
||||
return ret
|
||||
}
|
||||
ret.HasRecord = true
|
||||
record.lock.RLock()
|
||||
ret.IsLongPolling = record.isLongPolling
|
||||
record.lock.RUnlock()
|
||||
return ret
|
||||
}
|
||||
|
||||
record.lock.Lock()
|
||||
record.isLongPolling = true
|
||||
record.logLevel = log.TRACE
|
||||
record.lock.Unlock()
|
||||
// MarkLongPolling marks the request is a long-polling request, and the logger may output different message for it
|
||||
func MarkLongPolling() types.PreMiddlewareProvider {
|
||||
return func(next http.Handler) http.Handler {
|
||||
return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
|
||||
record := getRequestRecord(req.Context()) // it must exist
|
||||
record.lock.Lock()
|
||||
record.isLongPolling = true
|
||||
record.logLevel = log.TRACE
|
||||
record.lock.Unlock()
|
||||
next.ServeHTTP(w, req)
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
func MarkLogLevelTrace(resp http.ResponseWriter, req *http.Request) {
|
||||
record, ok := req.Context().Value(contextKey).(*requestRecord)
|
||||
if !ok {
|
||||
record := getRequestRecord(req.Context())
|
||||
if record == nil {
|
||||
return
|
||||
}
|
||||
|
||||
@@ -58,8 +81,8 @@ func MarkLogLevelTrace(resp http.ResponseWriter, req *http.Request) {
|
||||
|
||||
// UpdatePanicError updates a context's error info, a panic may be recovered by other middlewares, but we still need to know that.
|
||||
func UpdatePanicError(ctx context.Context, err error) {
|
||||
record, ok := ctx.Value(contextKey).(*requestRecord)
|
||||
if !ok {
|
||||
record := getRequestRecord(ctx)
|
||||
if record == nil {
|
||||
return
|
||||
}
|
||||
|
||||
|
||||
@@ -130,7 +130,7 @@ func copyFuncInfo(l *FuncInfo) *FuncInfo {
|
||||
}
|
||||
}
|
||||
|
||||
// shortenFilename generates a short source code filename from a full package path, eg: "code.gitea.io/routers/common/logger_context.go" => "common/logger_context.go"
|
||||
// shortenFilename generates a short source code filename from a full package path, eg: "gitea.dev/routers/common/logger_context.go" => "common/logger_context.go"
|
||||
func shortenFilename(filename, fallback string) string {
|
||||
if filename == "" {
|
||||
return fallback
|
||||
|
||||
@@ -17,7 +17,7 @@ func Test_shortenFilename(t *testing.T) {
|
||||
expected string
|
||||
}{
|
||||
{
|
||||
"code.gitea.io/routers/common/logger_context.go",
|
||||
"gitea.dev/routers/common/logger_context.go",
|
||||
"NO_FALLBACK",
|
||||
"common/logger_context.go",
|
||||
},
|
||||
|
||||
@@ -7,23 +7,10 @@ import (
|
||||
"net/http"
|
||||
"time"
|
||||
|
||||
"code.gitea.io/gitea/modules/log"
|
||||
"code.gitea.io/gitea/modules/web/types"
|
||||
"gitea.dev/modules/log"
|
||||
"gitea.dev/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
|
||||
|
||||
@@ -6,13 +6,12 @@ package routing
|
||||
import (
|
||||
"context"
|
||||
"fmt"
|
||||
"net/http"
|
||||
"sync"
|
||||
"time"
|
||||
|
||||
"code.gitea.io/gitea/modules/graceful"
|
||||
"code.gitea.io/gitea/modules/log"
|
||||
"code.gitea.io/gitea/modules/process"
|
||||
"gitea.dev/modules/graceful"
|
||||
"gitea.dev/modules/log"
|
||||
"gitea.dev/modules/process"
|
||||
)
|
||||
|
||||
// Event indicates when the printer is triggered
|
||||
@@ -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)
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@@ -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"
|
||||
|
||||
"gitea.dev/modules/log"
|
||||
"gitea.dev/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)
|
||||
})
|
||||
}
|
||||
}
|
||||
@@ -8,24 +8,24 @@ import (
|
||||
"sync"
|
||||
"time"
|
||||
|
||||
"code.gitea.io/gitea/modules/log"
|
||||
"gitea.dev/modules/log"
|
||||
)
|
||||
|
||||
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
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user