summaryrefslogtreecommitdiffstats
path: root/modules/web/routing
diff options
context:
space:
mode:
Diffstat (limited to '')
-rw-r--r--modules/web/routing/context.go49
-rw-r--r--modules/web/routing/funcinfo.go172
-rw-r--r--modules/web/routing/funcinfo_test.go80
-rw-r--r--modules/web/routing/logger.go109
-rw-r--r--modules/web/routing/logger_manager.go124
-rw-r--r--modules/web/routing/requestrecord.go28
6 files changed, 562 insertions, 0 deletions
diff --git a/modules/web/routing/context.go b/modules/web/routing/context.go
new file mode 100644
index 0000000..c5e85a4
--- /dev/null
+++ b/modules/web/routing/context.go
@@ -0,0 +1,49 @@
+// Copyright 2021 The Gitea Authors. All rights reserved.
+// SPDX-License-Identifier: MIT
+
+package routing
+
+import (
+ "context"
+ "net/http"
+)
+
+type contextKeyType struct{}
+
+var contextKey contextKeyType
+
+// UpdateFuncInfo updates a context's func info
+func UpdateFuncInfo(ctx context.Context, funcInfo *FuncInfo) {
+ record, ok := ctx.Value(contextKey).(*requestRecord)
+ if !ok {
+ return
+ }
+
+ record.lock.Lock()
+ record.funcInfo = funcInfo
+ record.lock.Unlock()
+}
+
+// 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
+ }
+
+ record.lock.Lock()
+ record.isLongPolling = true
+ 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 any) {
+ record, ok := ctx.Value(contextKey).(*requestRecord)
+ if !ok {
+ return
+ }
+
+ record.lock.Lock()
+ record.panicError = err
+ record.lock.Unlock()
+}
diff --git a/modules/web/routing/funcinfo.go b/modules/web/routing/funcinfo.go
new file mode 100644
index 0000000..f4e9731
--- /dev/null
+++ b/modules/web/routing/funcinfo.go
@@ -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: "code.gitea.io/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
+}
diff --git a/modules/web/routing/funcinfo_test.go b/modules/web/routing/funcinfo_test.go
new file mode 100644
index 0000000..2ab5960
--- /dev/null
+++ b/modules/web/routing/funcinfo_test.go
@@ -0,0 +1,80 @@
+// Copyright 2021 The Gitea Authors. All rights reserved.
+// SPDX-License-Identifier: MIT
+
+package routing
+
+import (
+ "fmt"
+ "testing"
+)
+
+func Test_shortenFilename(t *testing.T) {
+ tests := []struct {
+ filename string
+ fallback string
+ expected string
+ }{
+ {
+ "code.gitea.io/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) {
+ if gotShort := shortenFilename(tt.filename, tt.fallback); gotShort != tt.expected {
+ t.Errorf("shortenFilename('%s'), expect '%s', but get '%s'", tt.filename, 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) {
+ if got := trimAnonymousFunctionSuffix(tt.name); got != tt.want {
+ t.Errorf("trimAnonymousFunctionSuffix() = %v, want %v", got, tt.want)
+ }
+ })
+ }
+}
diff --git a/modules/web/routing/logger.go b/modules/web/routing/logger.go
new file mode 100644
index 0000000..5f3a759
--- /dev/null
+++ b/modules/web/routing/logger.go
@@ -0,0 +1,109 @@
+// Copyright 2021 The Gitea Authors. All rights reserved.
+// SPDX-License-Identifier: MIT
+
+package routing
+
+import (
+ "net/http"
+ "strings"
+ "time"
+
+ "code.gitea.io/gitea/modules/log"
+ "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()...)
+ 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) {
+ 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
+ logger.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
+ logf := logger.Warn
+ if isLongPolling {
+ logf = logger.Info
+ message = pollingMessage
+ }
+ logf("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 {
+ logger.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.responseWriter.(types.ResponseStatusProvider); ok {
+ status = v.WrittenStatus()
+ }
+ logf := logger.Info
+ if strings.HasPrefix(req.RequestURI, "/assets/") {
+ logf = logger.Trace
+ }
+ message := completedMessage
+ if isUnknownHandler {
+ logf = logger.Error
+ message = unknownHandlerMessage
+ }
+
+ logf("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,
+ )
+ }
+}
diff --git a/modules/web/routing/logger_manager.go b/modules/web/routing/logger_manager.go
new file mode 100644
index 0000000..aa25ec3
--- /dev/null
+++ b/modules/web/routing/logger_manager.go
@@ -0,0 +1,124 @@
+// Copyright 2021 The Gitea Authors. All rights reserved.
+// SPDX-License-Identifier: MIT
+
+package routing
+
+import (
+ "context"
+ "net/http"
+ "sync"
+ "time"
+
+ "code.gitea.io/gitea/modules/graceful"
+ "code.gitea.io/gitea/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
+)
+
+// Printer is used to output the log for a request
+type Printer func(trigger Event, record *requestRecord)
+
+type requestRecordsManager struct {
+ print Printer
+
+ lock sync.Mutex
+
+ requestRecords map[uint64]*requestRecord
+ count uint64
+}
+
+func (manager *requestRecordsManager) 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()
+
+ 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)
+ }
+ }
+ }
+ })
+}
+
+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,
+ }
+
+ // 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()
+
+ 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 = localPanicErr
+ 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)
+ })
+}
diff --git a/modules/web/routing/requestrecord.go b/modules/web/routing/requestrecord.go
new file mode 100644
index 0000000..cc61fc4
--- /dev/null
+++ b/modules/web/routing/requestrecord.go
@@ -0,0 +1,28 @@
+// Copyright 2021 The Gitea Authors. All rights reserved.
+// SPDX-License-Identifier: MIT
+
+package routing
+
+import (
+ "net/http"
+ "sync"
+ "time"
+)
+
+type requestRecord struct {
+ // index of the record in the records map
+ index uint64
+
+ // immutable fields
+ startTime time.Time
+ request *http.Request
+ responseWriter http.ResponseWriter
+
+ // mutex
+ lock sync.RWMutex
+
+ // mutable fields
+ isLongPolling bool
+ funcInfo *FuncInfo
+ panicError any
+}