初始提交: Gitea 项目代码
This commit is contained in:
root
@@ -0,0 +1,92 @@
|
||||
// Copyright 2021 The Gitea Authors. All rights reserved.
|
||||
// SPDX-License-Identifier: MIT
|
||||
|
||||
package routing
|
||||
|
||||
import (
|
||||
"context"
|
||||
"net/http"
|
||||
|
||||
"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() {}
|
||||
if reqCtx := reqctx.FromContext(ctx); reqCtx != nil {
|
||||
var traceSpan *gtprof.TraceSpan
|
||||
traceSpan, end = gtprof.GetTracer().StartInContext(reqCtx, "http.func")
|
||||
traceSpan.SetAttributeString("func", funcInfo.shortName)
|
||||
}
|
||||
if record := getRequestRecord(ctx); record != nil {
|
||||
record.lock.Lock()
|
||||
record.funcInfo = funcInfo
|
||||
record.lock.Unlock()
|
||||
}
|
||||
return end
|
||||
}
|
||||
|
||||
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
|
||||
}
|
||||
|
||||
// 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 := getRequestRecord(req.Context())
|
||||
if record == nil {
|
||||
return
|
||||
}
|
||||
|
||||
record.lock.Lock()
|
||||
record.logLevel = log.TRACE
|
||||
record.lock.Unlock()
|
||||
}
|
||||
|
||||
// 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 := getRequestRecord(ctx)
|
||||
if record == nil {
|
||||
return
|
||||
}
|
||||
|
||||
record.lock.Lock()
|
||||
record.panicError = err
|
||||
record.lock.Unlock()
|
||||
}
|
||||
@@ -0,0 +1,172 @@
|
||||
// Copyright 2021 The Gitea Authors. All rights reserved.
|
||||
// SPDX-License-Identifier: MIT
|
||||
|
||||
package routing
|
||||
|
||||
import (
|
||||
"fmt"
|
||||
"reflect"
|
||||
"runtime"
|
||||
"strings"
|
||||
"sync"
|
||||
)
|
||||
|
||||
var (
|
||||
funcInfoMap = map[uintptr]*FuncInfo{}
|
||||
funcInfoNameMap = map[string]*FuncInfo{}
|
||||
funcInfoMapMu sync.RWMutex
|
||||
)
|
||||
|
||||
// FuncInfo contains information about the function to be logged by the router log
|
||||
type FuncInfo struct {
|
||||
file string
|
||||
shortFile string
|
||||
line int
|
||||
name string
|
||||
shortName string
|
||||
}
|
||||
|
||||
// String returns a string form of the FuncInfo for logging
|
||||
func (info *FuncInfo) String() string {
|
||||
if info == nil {
|
||||
return "unknown-handler"
|
||||
}
|
||||
return fmt.Sprintf("%s:%d(%s)", info.shortFile, info.line, info.shortName)
|
||||
}
|
||||
|
||||
// GetFuncInfo returns the FuncInfo for a provided function and friendlyname
|
||||
func GetFuncInfo(fn any, friendlyName ...string) *FuncInfo {
|
||||
// ptr represents the memory position of the function passed in as v.
|
||||
// This will be used as program counter in FuncForPC below
|
||||
ptr := reflect.ValueOf(fn).Pointer()
|
||||
|
||||
// if we have been provided with a friendlyName look for the named funcs
|
||||
if len(friendlyName) == 1 {
|
||||
name := friendlyName[0]
|
||||
funcInfoMapMu.RLock()
|
||||
info, ok := funcInfoNameMap[name]
|
||||
funcInfoMapMu.RUnlock()
|
||||
if ok {
|
||||
return info
|
||||
}
|
||||
}
|
||||
|
||||
// Otherwise attempt to get pre-cached information for this function pointer
|
||||
funcInfoMapMu.RLock()
|
||||
info, ok := funcInfoMap[ptr]
|
||||
funcInfoMapMu.RUnlock()
|
||||
|
||||
if ok {
|
||||
if len(friendlyName) == 1 {
|
||||
name := friendlyName[0]
|
||||
info = copyFuncInfo(info)
|
||||
info.shortName = name
|
||||
|
||||
funcInfoNameMap[name] = info
|
||||
funcInfoMapMu.Lock()
|
||||
funcInfoNameMap[name] = info
|
||||
funcInfoMapMu.Unlock()
|
||||
}
|
||||
return info
|
||||
}
|
||||
|
||||
// This is likely the first time we have seen this function
|
||||
//
|
||||
// Get the runtime.func for this function (if we can)
|
||||
f := runtime.FuncForPC(ptr)
|
||||
if f != nil {
|
||||
info = convertToFuncInfo(f)
|
||||
|
||||
// cache this info globally
|
||||
funcInfoMapMu.Lock()
|
||||
funcInfoMap[ptr] = info
|
||||
|
||||
// if we have been provided with a friendlyName override the short name we've generated
|
||||
if len(friendlyName) == 1 {
|
||||
name := friendlyName[0]
|
||||
info = copyFuncInfo(info)
|
||||
info.shortName = name
|
||||
funcInfoNameMap[name] = info
|
||||
}
|
||||
funcInfoMapMu.Unlock()
|
||||
}
|
||||
return info
|
||||
}
|
||||
|
||||
// convertToFuncInfo take a runtime.Func and convert it to a logFuncInfo, fill in shorten filename, etc
|
||||
func convertToFuncInfo(f *runtime.Func) *FuncInfo {
|
||||
file, line := f.FileLine(f.Entry())
|
||||
|
||||
info := &FuncInfo{
|
||||
file: strings.ReplaceAll(file, "\\", "/"),
|
||||
line: line,
|
||||
name: f.Name(),
|
||||
}
|
||||
|
||||
// only keep last 2 names in path, fall back to funcName if not
|
||||
info.shortFile = shortenFilename(info.file, info.name)
|
||||
|
||||
// remove package prefix. eg: "xxx.com/pkg1/pkg2.foo" => "pkg2.foo"
|
||||
pos := strings.LastIndexByte(info.name, '/')
|
||||
if pos >= 0 {
|
||||
info.shortName = info.name[pos+1:]
|
||||
} else {
|
||||
info.shortName = info.name
|
||||
}
|
||||
|
||||
// remove ".func[0-9]*" suffix for anonymous func
|
||||
info.shortName = trimAnonymousFunctionSuffix(info.shortName)
|
||||
|
||||
return info
|
||||
}
|
||||
|
||||
func copyFuncInfo(l *FuncInfo) *FuncInfo {
|
||||
return &FuncInfo{
|
||||
file: l.file,
|
||||
shortFile: l.shortFile,
|
||||
line: l.line,
|
||||
name: l.name,
|
||||
shortName: l.shortName,
|
||||
}
|
||||
}
|
||||
|
||||
// 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
|
||||
}
|
||||
if lastIndex := strings.LastIndexByte(filename, '/'); lastIndex >= 0 {
|
||||
if secondLastIndex := strings.LastIndexByte(filename[:lastIndex], '/'); secondLastIndex >= 0 {
|
||||
return filename[secondLastIndex+1:]
|
||||
}
|
||||
}
|
||||
return filename
|
||||
}
|
||||
|
||||
// trimAnonymousFunctionSuffix trims ".func[0-9]*" from the end of anonymous function names, we only want to see the main function names in logs
|
||||
func trimAnonymousFunctionSuffix(name string) string {
|
||||
// if the name is an anonymous name, it should be like "{main-function}.func1", so the length can not be less than 7
|
||||
if len(name) < 7 {
|
||||
return name
|
||||
}
|
||||
|
||||
funcSuffixIndex := strings.LastIndex(name, ".func")
|
||||
if funcSuffixIndex < 0 {
|
||||
return name
|
||||
}
|
||||
|
||||
hasFuncSuffix := true
|
||||
|
||||
// len(".func") = 5
|
||||
for i := funcSuffixIndex + 5; i < len(name); i++ {
|
||||
if name[i] < '0' || name[i] > '9' {
|
||||
hasFuncSuffix = false
|
||||
break
|
||||
}
|
||||
}
|
||||
|
||||
if hasFuncSuffix {
|
||||
return name[:funcSuffixIndex]
|
||||
}
|
||||
return name
|
||||
}
|
||||
@@ -0,0 +1,80 @@
|
||||
// Copyright 2021 The Gitea Authors. All rights reserved.
|
||||
// SPDX-License-Identifier: MIT
|
||||
|
||||
package routing
|
||||
|
||||
import (
|
||||
"fmt"
|
||||
"testing"
|
||||
|
||||
"github.com/stretchr/testify/assert"
|
||||
)
|
||||
|
||||
func Test_shortenFilename(t *testing.T) {
|
||||
tests := []struct {
|
||||
filename string
|
||||
fallback string
|
||||
expected string
|
||||
}{
|
||||
{
|
||||
"gitea.dev/routers/common/logger_context.go",
|
||||
"NO_FALLBACK",
|
||||
"common/logger_context.go",
|
||||
},
|
||||
{
|
||||
"common/logger_context.go",
|
||||
"NO_FALLBACK",
|
||||
"common/logger_context.go",
|
||||
},
|
||||
{
|
||||
"logger_context.go",
|
||||
"NO_FALLBACK",
|
||||
"logger_context.go",
|
||||
},
|
||||
{
|
||||
"",
|
||||
"USE_FALLBACK",
|
||||
"USE_FALLBACK",
|
||||
},
|
||||
}
|
||||
for _, tt := range tests {
|
||||
t.Run(fmt.Sprintf("shortenFilename('%s')", tt.filename), func(t *testing.T) {
|
||||
gotShort := shortenFilename(tt.filename, tt.fallback)
|
||||
assert.Equal(t, tt.expected, gotShort)
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
func Test_trimAnonymousFunctionSuffix(t *testing.T) {
|
||||
tests := []struct {
|
||||
name string
|
||||
want string
|
||||
}{
|
||||
{
|
||||
"notAnonymous",
|
||||
"notAnonymous",
|
||||
},
|
||||
{
|
||||
"anonymous.func1",
|
||||
"anonymous",
|
||||
},
|
||||
{
|
||||
"notAnonymous.funca",
|
||||
"notAnonymous.funca",
|
||||
},
|
||||
{
|
||||
"anonymous.func100",
|
||||
"anonymous",
|
||||
},
|
||||
{
|
||||
"anonymous.func100.func6",
|
||||
"anonymous.func100",
|
||||
},
|
||||
}
|
||||
for _, tt := range tests {
|
||||
t.Run(tt.name, func(t *testing.T) {
|
||||
got := trimAnonymousFunctionSuffix(tt.name)
|
||||
assert.Equal(t, tt.want, got)
|
||||
})
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,104 @@
|
||||
// Copyright 2021 The Gitea Authors. All rights reserved.
|
||||
// SPDX-License-Identifier: MIT
|
||||
|
||||
package routing
|
||||
|
||||
import (
|
||||
"net/http"
|
||||
"time"
|
||||
|
||||
"gitea.dev/modules/log"
|
||||
"gitea.dev/modules/web/types"
|
||||
)
|
||||
|
||||
var (
|
||||
startMessage = log.NewColoredValue("started ", log.DEBUG.ColorAttributes()...)
|
||||
slowMessage = log.NewColoredValue("slow ", log.WARN.ColorAttributes()...)
|
||||
pollingMessage = log.NewColoredValue("polling ", log.INFO.ColorAttributes()...)
|
||||
failedMessage = log.NewColoredValue("failed ", log.WARN.ColorAttributes()...)
|
||||
completedMessage = log.NewColoredValue("completed", log.INFO.ColorAttributes()...)
|
||||
unknownHandlerMessage = log.NewColoredValue("completed", log.ERROR.ColorAttributes()...)
|
||||
)
|
||||
|
||||
func logPrinter(logger log.Logger) func(trigger Event, record *requestRecord) {
|
||||
const callerName = "HTTPRequest"
|
||||
logRequest := func(level log.Level, fmt string, args ...any) {
|
||||
logger.Log(2, &log.Event{Level: level, Caller: callerName}, fmt, args...)
|
||||
}
|
||||
return func(trigger Event, record *requestRecord) {
|
||||
if trigger == StartEvent {
|
||||
if !logger.LevelEnabled(log.TRACE) {
|
||||
// for performance, if the "started" message shouldn't be logged, we just return as early as possible
|
||||
// developers can set the router log level to TRACE to get the "started" request messages.
|
||||
return
|
||||
}
|
||||
// when a request starts, we have no information about the handler function information, we only have the request path
|
||||
req := record.request
|
||||
logRequest(log.TRACE, "router: %s %v %s for %s", startMessage, log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr)
|
||||
return
|
||||
}
|
||||
|
||||
req := record.request
|
||||
|
||||
// Get data from the record
|
||||
record.lock.Lock()
|
||||
handlerFuncInfo := record.funcInfo.String()
|
||||
isLongPolling := record.isLongPolling
|
||||
isUnknownHandler := record.funcInfo == nil
|
||||
panicErr := record.panicError
|
||||
record.lock.Unlock()
|
||||
|
||||
if trigger == StillExecutingEvent {
|
||||
message := slowMessage
|
||||
logLevel := log.WARN
|
||||
if isLongPolling {
|
||||
logLevel = log.INFO
|
||||
message = pollingMessage
|
||||
}
|
||||
logRequest(logLevel, "router: %s %v %s for %s, elapsed %v @ %s",
|
||||
message,
|
||||
log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr,
|
||||
log.ColoredTime(time.Since(record.startTime)),
|
||||
handlerFuncInfo,
|
||||
)
|
||||
return
|
||||
}
|
||||
|
||||
if panicErr != nil {
|
||||
logRequest(log.WARN, "router: %s %v %s for %s, panic in %v @ %s, err=%v",
|
||||
failedMessage,
|
||||
log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr,
|
||||
log.ColoredTime(time.Since(record.startTime)),
|
||||
handlerFuncInfo,
|
||||
panicErr,
|
||||
)
|
||||
return
|
||||
}
|
||||
|
||||
var status int
|
||||
if v, ok := record.respWriter.(types.ResponseStatusProvider); ok {
|
||||
status = v.WrittenStatus()
|
||||
}
|
||||
logLevel := record.logLevel
|
||||
if logLevel == log.UNDEFINED {
|
||||
logLevel = log.INFO
|
||||
}
|
||||
// lower the log level for some specific requests, in most cases these logs are not useful
|
||||
if status > 0 && status < 400 &&
|
||||
req.RequestURI == "/api/actions/runner.v1.RunnerService/FetchTask" /* Actions Runner polling */ {
|
||||
logLevel = log.TRACE
|
||||
}
|
||||
message := completedMessage
|
||||
if isUnknownHandler {
|
||||
logLevel = log.ERROR
|
||||
message = unknownHandlerMessage
|
||||
}
|
||||
|
||||
logRequest(logLevel, "router: %s %v %s for %s, %v %v in %v @ %s",
|
||||
message,
|
||||
log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr,
|
||||
log.ColoredStatus(status), log.ColoredStatus(status, http.StatusText(status)), log.ColoredTime(time.Since(record.startTime)),
|
||||
handlerFuncInfo,
|
||||
)
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,90 @@
|
||||
// Copyright 2021 The Gitea Authors. All rights reserved.
|
||||
// SPDX-License-Identifier: MIT
|
||||
|
||||
package routing
|
||||
|
||||
import (
|
||||
"context"
|
||||
"fmt"
|
||||
"sync"
|
||||
"time"
|
||||
|
||||
"gitea.dev/modules/graceful"
|
||||
"gitea.dev/modules/log"
|
||||
"gitea.dev/modules/process"
|
||||
)
|
||||
|
||||
// Event indicates when the printer is triggered
|
||||
type Event int
|
||||
|
||||
const (
|
||||
// StartEvent at the beginning of a request
|
||||
StartEvent Event = iota
|
||||
|
||||
// StillExecutingEvent the request is still executing
|
||||
StillExecutingEvent
|
||||
|
||||
// EndEvent the request has ended (either completed or failed)
|
||||
EndEvent
|
||||
)
|
||||
|
||||
// logPrinterFunc is used to output the log for a request
|
||||
type logPrinterFunc func(trigger Event, record *requestRecord)
|
||||
|
||||
type loggerRequestManager struct {
|
||||
logPrint logPrinterFunc
|
||||
reqRecords sync.Map // it only contains the active requests which haven't been detected as "slow"
|
||||
}
|
||||
|
||||
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 {
|
||||
select {
|
||||
case <-ctx.Done():
|
||||
return
|
||||
case <-t.C:
|
||||
now := time.Now()
|
||||
|
||||
// print logs for slow requests
|
||||
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 *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()
|
||||
}
|
||||
|
||||
manager.reqRecords.Delete(record.index)
|
||||
manager.logPrint(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)
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -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)
|
||||
})
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,31 @@
|
||||
// Copyright 2021 The Gitea Authors. All rights reserved.
|
||||
// SPDX-License-Identifier: MIT
|
||||
|
||||
package routing
|
||||
|
||||
import (
|
||||
"net/http"
|
||||
"sync"
|
||||
"time"
|
||||
|
||||
"gitea.dev/modules/log"
|
||||
)
|
||||
|
||||
type requestRecord struct {
|
||||
// immutable fields
|
||||
index uint64 // unique number (per process) for the request
|
||||
startTime time.Time
|
||||
request *http.Request
|
||||
respWriter http.ResponseWriter
|
||||
|
||||
// mutex
|
||||
lock sync.RWMutex
|
||||
|
||||
// below are mutable fields
|
||||
funcInfo *FuncInfo
|
||||
// * for "mark as long polling"
|
||||
isLongPolling bool
|
||||
// * for router logger
|
||||
logLevel log.Level
|
||||
panicError error
|
||||
}
|
||||
Reference in New Issue
Block a user