diff options
Diffstat (limited to '')
| -rw-r--r-- | modules/web/routing/context.go | 49 | ||||
| -rw-r--r-- | modules/web/routing/funcinfo.go | 172 | ||||
| -rw-r--r-- | modules/web/routing/funcinfo_test.go | 80 | ||||
| -rw-r--r-- | modules/web/routing/logger.go | 109 | ||||
| -rw-r--r-- | modules/web/routing/logger_manager.go | 124 | ||||
| -rw-r--r-- | modules/web/routing/requestrecord.go | 28 |
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 +} |