Adding upstream version 9.0.3.

Signed-off-by: Daniel Baumann <daniel@debian.org>

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
+}