1 files changed, 124 insertions, 0 deletions
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)
+	})
+}