gitea/modules/web/routing/logger_manager.go

// 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, 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)
		}
	}
}