Refactor Router Logger (#17308)

Make router logger more friendly, show the related function name/file/line.

[BREAKING]
This PR substantially changes the logging format of the router logger. If you use this logging for monitoring e.g. fail2ban you will need to update this to match the new format.
This commit is contained in:
wxiaoguang 2022-01-20 19:41:25 +08:00 committed by GitHub
parent bbd30787d3
commit 5bf8d5445e
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
23 changed files with 912 additions and 267 deletions

View File

@ -88,7 +88,7 @@ func runWeb(ctx *cli.Context) error {
}
defer func() {
if panicked := recover(); panicked != nil {
log.Fatal("PANIC: %v\n%s", panicked, string(log.Stack(2)))
log.Fatal("PANIC: %v\n%s", panicked, log.Stack(2))
}
}()

View File

@ -455,26 +455,35 @@ APP_ID = ; e.g. http://localhost:3000/
;; Use comma to separate multiple modes, e.g. "console, file"
MODE = console
;;
;; Either "Trace", "Debug", "Info", "Warn", "Error", "Critical", default is "Trace"
;; Either "Trace", "Debug", "Info", "Warn", "Error", "Critical" or "None", default is "Info"
LEVEL = Info
;;
;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
;; Router Logger
;;
;; Switch off the router log
;DISABLE_ROUTER_LOG= ; false
;DISABLE_ROUTER_LOG=false
;;
;; Set the log "modes" for the router log (if file is set the log file will default to router.log)
ROUTER = console
;;
;; The level at which the router logs
;ROUTER_LOG_LEVEL = Info
;; The router will log different things at different levels.
;;
;; * started messages will be logged at TRACE level
;; * polling/completed routers will be logged at INFO
;; * slow routers will be logged at WARN
;; * failed routers will be logged at WARN
;;
;; The routing level will default to that of the system but individual router level can be set in
;; [log.<mode>.router] LEVEL
;;
;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
;;
;; Access Logger (Creates log in NCSA common log format)
;;
;ENABLE_ACCESS_LOG = false
;;
;; Set the log "modes" for the access log (if file is set the log file will default to access.log)
;ACCESS = file
;;

View File

@ -291,7 +291,6 @@ The following configuration set `Content-Type: application/vnd.android.package-a
- `MINIMUM_KEY_SIZE_CHECK`: **true**: Indicate whether to check minimum key size with corresponding type.
- `OFFLINE_MODE`: **false**: Disables use of CDN for static files and Gravatar for profile pictures.
- `DISABLE_ROUTER_LOG`: **false**: Mute printing of the router log.
- `CERT_FILE`: **https/cert.pem**: Cert file path used for HTTPS. When chaining, the server certificate must come first, then intermediate CA certificates (if any). From 1.11 paths are relative to `CUSTOM_PATH`.
- `KEY_FILE`: **https/key.pem**: Key file path used for HTTPS. From 1.11 paths are relative to `CUSTOM_PATH`.
- `STATIC_ROOT_PATH`: **./**: Upper level of template and static files path.
@ -752,11 +751,16 @@ Default templates for project boards:
- `MODE`: **console**: Logging mode. For multiple modes, use a comma to separate values. You can configure each mode in per mode log subsections `\[log.modename\]`. By default the file mode will log to `$ROOT_PATH/gitea.log`.
- `LEVEL`: **Info**: General log level. \[Trace, Debug, Info, Warn, Error, Critical, Fatal, None\]
- `STACKTRACE_LEVEL`: **None**: Default log level at which to log create stack traces. \[Trace, Debug, Info, Warn, Error, Critical, Fatal, None\]
- `ROUTER_LOG_LEVEL`: **Info**: The log level that the router should log at. (If you are setting the access log, its recommended to place this at Debug.)
- `ROUTER`: **console**: The mode or name of the log the router should log to. (If you set this to `,` it will log to default Gitea logger.)
NB: You must have `DISABLE_ROUTER_LOG` set to `false` for this option to take effect. Configure each mode in per mode log subsections `\[log.modename.router\]`.
- `ENABLE_ACCESS_LOG`: **false**: Creates an access.log in NCSA common log format, or as per the following template
- `ENABLE_SSH_LOG`: **false**: save ssh log to log file
- `ENABLE_XORM_LOG`: **true**: Set whether to perform XORM logging. Please note SQL statement logging can be disabled by setting `LOG_SQL` to false in the `[database]` section.
### Router Log (`log`)
- `DISABLE_ROUTER_LOG`: **false**: Mute printing of the router log.
- `ROUTER`: **console**: The mode or name of the log the router should log to. (If you set this to `,` it will log to default Gitea logger.)
NB: You must have `DISABLE_ROUTER_LOG` set to `false` for this option to take effect. Configure each mode in per mode log subsections `\[log.modename.router\]`.
### Access Log (`log`)
- `ENABLE_ACCESS_LOG`: **false**: Creates an access.log in NCSA common log format, or as per the following template
- `ACCESS`: **file**: Logging mode for the access logger, use a comma to separate values. Configure each mode in per mode log subsections `\[log.modename.access\]`. By default the file mode will log to `$ROOT_PATH/access.log`. (If you set this to `,` it will log to the default Gitea logger.)
- `ACCESS_LOG_TEMPLATE`: **`{{.Ctx.RemoteAddr}} - {{.Identity}} {{.Start.Format "[02/Jan/2006:15:04:05 -0700]" }} "{{.Ctx.Req.Method}} {{.Ctx.Req.URL.RequestURI}} {{.Ctx.Req.Proto}}" {{.ResponseWriter.Status}} {{.ResponseWriter.Size}} "{{.Ctx.Req.Referer}}\" \"{{.Ctx.Req.UserAgent}}"`**: Sets the template used to create the access log.
- The following variables are available:
@ -765,7 +769,6 @@ NB: You must have `DISABLE_ROUTER_LOG` set to `false` for this option to take ef
- `Start`: the start time of the request.
- `ResponseWriter`: the responseWriter from the request.
- You must be very careful to ensure that this template does not throw errors or panics as this template runs outside of the panic/recovery script.
- `ENABLE_XORM_LOG`: **true**: Set whether to perform XORM logging. Please note SQL statement logging can be disabled by setting `LOG_SQL` to false in the `[database]` section.
### Log subsections (`log.name`, `log.name.*`)

View File

@ -68,16 +68,23 @@ multiple subloggers that will log to files.
### The "Router" logger
You can disable Router log by setting `DISABLE_ROUTER_LOG`.
The Router logger has been substantially changed in v1.17. If you are using the router logger for fail2ban or other monitoring
you will need to update this configuration.
You can disable Router log by setting `DISABLE_ROUTER_LOG` or by setting all of its sublogger configurations to `none`.
You can configure the outputs of this
router log by setting the `ROUTER` value in the `[log]` section of the
configuration. `ROUTER` will default to `console` if unset. The Gitea
Router logs at the `Info` level by default, but this can be
changed if desired by setting the `ROUTER_LOG_LEVEL` value.
configuration. `ROUTER` will default to `console` if unset and will default to same level as main logger.
Please note, setting the `LEVEL` of this logger to a level above
`ROUTER_LOG_LEVEL` will result in no router logs.
The Router logger logs the following:
- `started` messages will be logged at TRACE level
- `polling`/`completed` routers will be logged at INFO
- `slow` routers will be logged at WARN
- `failed` routers will be logged at WARN
The logging level for the router will default to that of the main configuration. Set `[log.<mode>.router]` `LEVEL` to change this.
Each output sublogger for this logger is configured in
`[log.sublogger.router]` sections. There are certain default values

View File

@ -5,6 +5,7 @@
package log
import (
"fmt"
"time"
)
@ -72,12 +73,16 @@ var (
wayTooLong = ColorBytes(BgMagenta)
)
// ColoredTime adds colors for time on log
// ColoredTime converts the provided time to a ColoredValue for logging. The duration is always formatted in milliseconds.
func ColoredTime(duration time.Duration) *ColoredValue {
// the output of duration in Millisecond is more readable:
// * before: "100.1ms" "100.1μs" "100.1s"
// * better: "100.1ms" "0.1ms" "100100.0ms", readers can compare the values at first glance.
str := fmt.Sprintf("%.1fms", float64(duration.Microseconds())/1000)
for i, k := range durations {
if duration < k {
return NewColoredValueBytes(duration, &durationColors[i])
return NewColoredValueBytes(str, &durationColors[i])
}
}
return NewColoredValueBytes(duration, &wayTooLong)
return NewColoredValueBytes(str, &wayTooLong)
}

View File

@ -288,4 +288,8 @@ func (l *LoggerAsWriter) Log(msg string) {
func init() {
_, filename, _, _ := runtime.Caller(0)
prefix = strings.TrimSuffix(filename, "modules/log/log.go")
if prefix == filename {
// in case the source code file is moved, we can not trim the suffix, the code above should also be updated.
panic("unable to detect correct package prefix, please update file: " + filename)
}
}

View File

@ -23,8 +23,11 @@ type Options struct {
CorsHandler func(http.Handler) http.Handler
}
// AssetsHandler implements the static handler for serving custom or original assets.
func AssetsHandler(opts *Options) func(next http.Handler) http.Handler {
// AssetsURLPathPrefix is the path prefix for static asset files
const AssetsURLPathPrefix = "/assets/"
// AssetsHandlerFunc implements the static handler for serving custom or original assets.
func AssetsHandlerFunc(opts *Options) http.HandlerFunc {
var custPath = filepath.Join(setting.CustomPath, "public")
if !filepath.IsAbs(custPath) {
custPath = filepath.Join(setting.AppWorkPath, custPath)
@ -36,12 +39,7 @@ func AssetsHandler(opts *Options) func(next http.Handler) http.Handler {
opts.Prefix += "/"
}
return func(next http.Handler) http.Handler {
return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) {
if !strings.HasPrefix(req.URL.Path, opts.Prefix) {
next.ServeHTTP(resp, req)
return
}
return func(resp http.ResponseWriter, req *http.Request) {
if req.Method != "GET" && req.Method != "HEAD" {
resp.WriteHeader(http.StatusNotFound)
return
@ -81,7 +79,6 @@ func AssetsHandler(opts *Options) func(next http.Handler) http.Handler {
}
resp.WriteHeader(http.StatusNotFound)
})
}
}

View File

@ -126,6 +126,7 @@ func getStacktraceLogLevel(section *ini.Section, key, defaultValue string) strin
func generateLogConfig(sec *ini.Section, name string, defaults defaultLogOptions) (mode, jsonConfig, levelName string) {
level := getLogLevel(sec, "LEVEL", LogLevel)
levelName = level.String()
stacktraceLevelName := getStacktraceLogLevel(sec, "STACKTRACE_LEVEL", StacktraceLogLevel)
stacktraceLevel := log.FromString(stacktraceLevelName)
mode = name
@ -254,8 +255,10 @@ func generateNamedLogger(key string, options defaultLogOptions) *LogDescription
func newAccessLogService() {
EnableAccessLog = Cfg.Section("log").Key("ENABLE_ACCESS_LOG").MustBool(false)
AccessLogTemplate = Cfg.Section("log").Key("ACCESS_LOG_TEMPLATE").MustString(
`{{.Ctx.RemoteAddr}} - {{.Identity}} {{.Start.Format "[02/Jan/2006:15:04:05 -0700]" }} "{{.Ctx.Req.Method}} {{.Ctx.Req.URL.RequestURI}} {{.Ctx.Req.Proto}}" {{.ResponseWriter.Status}} {{.ResponseWriter.Size}} "{{.Ctx.Req.Referer}}\" \"{{.Ctx.Req.UserAgent}}"`)
Cfg.Section("log").Key("ACCESS").MustString("file")
`{{.Ctx.RemoteAddr}} - {{.Identity}} {{.Start.Format "[02/Jan/2006:15:04:05 -0700]" }} "{{.Ctx.Req.Method}} {{.Ctx.Req.URL.RequestURI}} {{.Ctx.Req.Proto}}" {{.ResponseWriter.Status}} {{.ResponseWriter.Size}} "{{.Ctx.Req.Referer}}\" \"{{.Ctx.Req.UserAgent}}"`,
)
// the `MustString` updates the default value, and `log.ACCESS` is used by `generateNamedLogger("access")` later
_ = Cfg.Section("log").Key("ACCESS").MustString("file")
if EnableAccessLog {
options := newDefaultLogOptions()
options.filename = filepath.Join(LogRootPath, "access.log")

View File

@ -333,13 +333,14 @@ var (
LogLevel log.Level
StacktraceLogLevel string
LogRootPath string
DisableRouterLog bool
RouterLogLevel log.Level
EnableAccessLog bool
EnableSSHLog bool
AccessLogTemplate string
EnableXORMLog bool
DisableRouterLog bool
EnableAccessLog bool
AccessLogTemplate string
// Time settings
TimeFormat string
// UILocation is the location on the UI, so that we can display the time on UI.
@ -601,7 +602,6 @@ func loadFromConf(allowEmpty bool, extraConfig string) {
StacktraceLogLevel = getStacktraceLogLevel(Cfg.Section("log"), "STACKTRACE_LEVEL", "None")
LogRootPath = Cfg.Section("log").Key("ROOT_PATH").MustString(path.Join(AppWorkPath, "log"))
forcePathSeparator(LogRootPath)
RouterLogLevel = log.FromString(Cfg.Section("log").Key("ROUTER_LOG_LEVEL").MustString("Info"))
sec := Cfg.Section("server")
AppName = Cfg.Section("").Key("APP_NAME").MustString("Gitea: Git with a cup of tea")

View File

@ -18,144 +18,6 @@ import (
chi "github.com/go-chi/chi/v5"
)
// Wrap converts all kinds of routes to standard library one
func Wrap(handlers ...interface{}) http.HandlerFunc {
if len(handlers) == 0 {
panic("No handlers found")
}
for _, handler := range handlers {
switch t := handler.(type) {
case http.HandlerFunc, func(http.ResponseWriter, *http.Request),
func(ctx *context.Context),
func(ctx *context.Context) goctx.CancelFunc,
func(*context.APIContext),
func(*context.APIContext) goctx.CancelFunc,
func(*context.PrivateContext),
func(*context.PrivateContext) goctx.CancelFunc,
func(http.Handler) http.Handler:
default:
panic(fmt.Sprintf("Unsupported handler type: %#v", t))
}
}
return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) {
for i := 0; i < len(handlers); i++ {
handler := handlers[i]
switch t := handler.(type) {
case http.HandlerFunc:
t(resp, req)
if r, ok := resp.(context.ResponseWriter); ok && r.Status() > 0 {
return
}
case func(http.ResponseWriter, *http.Request):
t(resp, req)
if r, ok := resp.(context.ResponseWriter); ok && r.Status() > 0 {
return
}
case func(ctx *context.Context) goctx.CancelFunc:
ctx := context.GetContext(req)
cancel := t(ctx)
if cancel != nil {
defer cancel()
}
if ctx.Written() {
return
}
case func(*context.APIContext) goctx.CancelFunc:
ctx := context.GetAPIContext(req)
cancel := t(ctx)
if cancel != nil {
defer cancel()
}
if ctx.Written() {
return
}
case func(*context.PrivateContext) goctx.CancelFunc:
ctx := context.GetPrivateContext(req)
cancel := t(ctx)
if cancel != nil {
defer cancel()
}
if ctx.Written() {
return
}
case func(ctx *context.Context):
ctx := context.GetContext(req)
t(ctx)
if ctx.Written() {
return
}
case func(*context.APIContext):
ctx := context.GetAPIContext(req)
t(ctx)
if ctx.Written() {
return
}
case func(*context.PrivateContext):
ctx := context.GetPrivateContext(req)
t(ctx)
if ctx.Written() {
return
}
case func(http.Handler) http.Handler:
var next = http.HandlerFunc(func(http.ResponseWriter, *http.Request) {})
if len(handlers) > i+1 {
next = Wrap(handlers[i+1:]...)
}
t(next).ServeHTTP(resp, req)
return
default:
panic(fmt.Sprintf("Unsupported handler type: %#v", t))
}
}
})
}
// Middle wrap a context function as a chi middleware
func Middle(f func(ctx *context.Context)) func(netx http.Handler) http.Handler {
return func(next http.Handler) http.Handler {
return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) {
ctx := context.GetContext(req)
f(ctx)
if ctx.Written() {
return
}
next.ServeHTTP(ctx.Resp, ctx.Req)
})
}
}
// MiddleCancel wrap a context function as a chi middleware
func MiddleCancel(f func(ctx *context.Context) goctx.CancelFunc) func(netx http.Handler) http.Handler {
return func(next http.Handler) http.Handler {
return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) {
ctx := context.GetContext(req)
cancel := f(ctx)
if cancel != nil {
defer cancel()
}
if ctx.Written() {
return
}
next.ServeHTTP(ctx.Resp, ctx.Req)
})
}
}
// MiddleAPI wrap a context function as a chi middleware
func MiddleAPI(f func(ctx *context.APIContext)) func(netx http.Handler) http.Handler {
return func(next http.Handler) http.Handler {
return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) {
ctx := context.GetAPIContext(req)
f(ctx)
if ctx.Written() {
return
}
next.ServeHTTP(ctx.Resp, ctx.Req)
})
}
}
// Bind binding an obj to a handler
func Bind(obj interface{}) http.HandlerFunc {
var tp = reflect.TypeOf(obj)

View File

@ -0,0 +1,51 @@
// Copyright 2021 The Gitea Authors. All rights reserved.
// Use of this source code is governed by a MIT-style
// license that can be found in the LICENSE file.
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 reuqest 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 interface{}) {
record, ok := ctx.Value(contextKey).(*requestRecord)
if !ok {
return
}
record.lock.Lock()
record.panicError = err
record.lock.Unlock()
}

View File

@ -0,0 +1,171 @@
// Copyright 2021 The Gitea Authors. All rights reserved.
// Use of this source code is governed by a MIT-style
// license that can be found in the LICENSE file.
package routing
import (
"fmt"
"reflect"
"runtime"
"strings"
"sync"
)
var funcInfoMap = map[uintptr]*FuncInfo{}
var funcInfoNameMap = map[string]*FuncInfo{}
var 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 interface{}, 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
}

View File

@ -0,0 +1,81 @@
// Copyright 2021 The Gitea Authors. All rights reserved.
// Use of this source code is governed by a MIT-style
// license that can be found in the LICENSE file.
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)
}
})
}
}

View File

@ -0,0 +1,106 @@
// Copyright 2021 The Gitea Authors. All rights reserved.
// Use of this source code is governed by a MIT-style
// license that can be found in the LICENSE file.
package routing
import (
"net/http"
"time"
"code.gitea.io/gitea/modules/context"
"code.gitea.io/gitea/modules/log"
)
// 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.NewColoredValueBytes("started ", log.DEBUG.Color())
slowMessage = log.NewColoredValueBytes("slow ", log.WARN.Color())
pollingMessage = log.NewColoredValueBytes("polling ", log.INFO.Color())
failedMessage = log.NewColoredValueBytes("failed ", log.WARN.Color())
completedMessage = log.NewColoredValueBytes("completed", log.INFO.Color())
unknownHandlerMessage = log.NewColoredValueBytes("completed", log.ERROR.Color())
)
func logPrinter(logger log.Logger) func(trigger Event, record *requestRecord) {
return func(trigger Event, record *requestRecord) {
if trigger == StartEvent {
if !logger.IsTrace() {
// 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
level := log.WARN
if isLongPolling {
level = log.INFO
message = pollingMessage
}
_ = logger.Log(0, level, "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.Log(0, log.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.(context.ResponseWriter); ok {
status = v.Status()
}
level := log.INFO
message := completedMessage
if isUnknownHandler {
level = log.ERROR
message = unknownHandlerMessage
}
_ = logger.Log(0, level, "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,
)
}
}

View File

@ -0,0 +1,122 @@
// Copyright 2021 The Gitea Authors. All rights reserved.
// Use of this source code is governed by a MIT-style
// license that can be found in the LICENSE file.
package routing
import (
"context"
"net/http"
"sync"
"time"
"code.gitea.io/gitea/modules/graceful"
)
// 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(baseCtx context.Context) {
// 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 <-baseCtx.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)
})
}

View File

@ -0,0 +1,29 @@
// Copyright 2021 The Gitea Authors. All rights reserved.
// Use of this source code is governed by a MIT-style
// license that can be found in the LICENSE file.
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 interface{}
}

117
modules/web/wrap.go Normal file
View File

@ -0,0 +1,117 @@
// Copyright 2021 The Gitea Authors. All rights reserved.
// Use of this source code is governed by a MIT-style
// license that can be found in the LICENSE file.
package web
import (
goctx "context"
"net/http"
"strings"
"code.gitea.io/gitea/modules/context"
"code.gitea.io/gitea/modules/web/routing"
)
// Wrap converts all kinds of routes to standard library one
func Wrap(handlers ...interface{}) http.HandlerFunc {
if len(handlers) == 0 {
panic("No handlers found")
}
ourHandlers := make([]wrappedHandlerFunc, 0, len(handlers))
for _, handler := range handlers {
ourHandlers = append(ourHandlers, convertHandler(handler))
}
return wrapInternal(ourHandlers)
}
func wrapInternal(handlers []wrappedHandlerFunc) http.HandlerFunc {
return func(resp http.ResponseWriter, req *http.Request) {
var defers []func()
defer func() {
for i := len(defers) - 1; i >= 0; i-- {
defers[i]()
}
}()
for i := 0; i < len(handlers); i++ {
handler := handlers[i]
others := handlers[i+1:]
done, deferrable := handler(resp, req, others...)
if deferrable != nil {
defers = append(defers, deferrable)
}
if done {
return
}
}
}
}
// Middle wrap a context function as a chi middleware
func Middle(f func(ctx *context.Context)) func(next http.Handler) http.Handler {
funcInfo := routing.GetFuncInfo(f)
return func(next http.Handler) http.Handler {
return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) {
routing.UpdateFuncInfo(req.Context(), funcInfo)
ctx := context.GetContext(req)
f(ctx)
if ctx.Written() {
return
}
next.ServeHTTP(ctx.Resp, ctx.Req)
})
}
}
// MiddleCancel wrap a context function as a chi middleware
func MiddleCancel(f func(ctx *context.Context) goctx.CancelFunc) func(netx http.Handler) http.Handler {
funcInfo := routing.GetFuncInfo(f)
return func(next http.Handler) http.Handler {
return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) {
routing.UpdateFuncInfo(req.Context(), funcInfo)
ctx := context.GetContext(req)
cancel := f(ctx)
if cancel != nil {
defer cancel()
}
if ctx.Written() {
return
}
next.ServeHTTP(ctx.Resp, ctx.Req)
})
}
}
// MiddleAPI wrap a context function as a chi middleware
func MiddleAPI(f func(ctx *context.APIContext)) func(next http.Handler) http.Handler {
funcInfo := routing.GetFuncInfo(f)
return func(next http.Handler) http.Handler {
return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) {
routing.UpdateFuncInfo(req.Context(), funcInfo)
ctx := context.GetAPIContext(req)
f(ctx)
if ctx.Written() {
return
}
next.ServeHTTP(ctx.Resp, ctx.Req)
})
}
}
// WrapWithPrefix wraps a provided handler function at a prefix
func WrapWithPrefix(pathPrefix string, handler http.HandlerFunc, friendlyName ...string) func(next http.Handler) http.Handler {
funcInfo := routing.GetFuncInfo(handler, friendlyName...)
return func(next http.Handler) http.Handler {
return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) {
if !strings.HasPrefix(req.URL.Path, pathPrefix) {
next.ServeHTTP(resp, req)
return
}
routing.UpdateFuncInfo(req.Context(), funcInfo)
handler(resp, req)
})
}
}

101
modules/web/wrap_convert.go Normal file
View File

@ -0,0 +1,101 @@
// Copyright 2021 The Gitea Authors. All rights reserved.
// Use of this source code is governed by a MIT-style
// license that can be found in the LICENSE file.
package web
import (
goctx "context"
"fmt"
"net/http"
"code.gitea.io/gitea/modules/context"
"code.gitea.io/gitea/modules/web/routing"
)
type wrappedHandlerFunc func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func())
func convertHandler(handler interface{}) wrappedHandlerFunc {
funcInfo := routing.GetFuncInfo(handler)
switch t := handler.(type) {
case http.HandlerFunc:
return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func()) {
routing.UpdateFuncInfo(req.Context(), funcInfo)
t(resp, req)
if r, ok := resp.(context.ResponseWriter); ok && r.Status() > 0 {
done = true
}
return
}
case func(http.ResponseWriter, *http.Request):
return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func()) {
routing.UpdateFuncInfo(req.Context(), funcInfo)
t(resp, req)
if r, ok := resp.(context.ResponseWriter); ok && r.Status() > 0 {
done = true
}
return
}
case func(ctx *context.Context):
return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func()) {
routing.UpdateFuncInfo(req.Context(), funcInfo)
ctx := context.GetContext(req)
t(ctx)
done = ctx.Written()
return
}
case func(ctx *context.Context) goctx.CancelFunc:
return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func()) {
routing.UpdateFuncInfo(req.Context(), funcInfo)
ctx := context.GetContext(req)
deferrable = t(ctx)
done = ctx.Written()
return
}
case func(*context.APIContext):
return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func()) {
routing.UpdateFuncInfo(req.Context(), funcInfo)
ctx := context.GetAPIContext(req)
t(ctx)
done = ctx.Written()
return
}
case func(*context.APIContext) goctx.CancelFunc:
return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func()) {
routing.UpdateFuncInfo(req.Context(), funcInfo)
ctx := context.GetAPIContext(req)
deferrable = t(ctx)
done = ctx.Written()
return
}
case func(*context.PrivateContext):
return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func()) {
routing.UpdateFuncInfo(req.Context(), funcInfo)
ctx := context.GetPrivateContext(req)
t(ctx)
done = ctx.Written()
return
}
case func(*context.PrivateContext) goctx.CancelFunc:
return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func()) {
routing.UpdateFuncInfo(req.Context(), funcInfo)
ctx := context.GetPrivateContext(req)
deferrable = t(ctx)
done = ctx.Written()
return
}
case func(http.Handler) http.Handler:
return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func()) {
var next = http.HandlerFunc(func(http.ResponseWriter, *http.Request) {})
if len(others) > 0 {
next = wrapInternal(others)
}
routing.UpdateFuncInfo(req.Context(), funcInfo)
t(next).ServeHTTP(resp, req)
return
}
default:
panic(fmt.Sprintf("Unsupported handler type: %#v", t))
}
}

View File

@ -1,33 +0,0 @@
// Copyright 2021 The Gitea Authors. All rights reserved.
// Use of this source code is governed by a MIT-style
// license that can be found in the LICENSE file.
package common
import (
"net/http"
"time"
"code.gitea.io/gitea/modules/context"
"code.gitea.io/gitea/modules/log"
)
// LoggerHandler is a handler that will log the routing to the default gitea log
func LoggerHandler(level log.Level) func(next http.Handler) http.Handler {
return func(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
start := time.Now()
_ = log.GetLogger("router").Log(0, level, "Started %s %s for %s", log.ColoredMethod(req.Method), req.URL.RequestURI(), req.RemoteAddr)
next.ServeHTTP(w, req)
var status int
if v, ok := w.(context.ResponseWriter); ok {
status = v.Status()
}
_ = log.GetLogger("router").Log(0, level, "Completed %s %s %v %s in %v", log.ColoredMethod(req.Method), req.URL.RequestURI(), log.ColoredStatus(status), log.ColoredStatus(status, http.StatusText(status)), log.ColoredTime(time.Since(start)))
})
}
}

View File

@ -13,6 +13,7 @@ import (
"code.gitea.io/gitea/modules/log"
"code.gitea.io/gitea/modules/process"
"code.gitea.io/gitea/modules/setting"
"code.gitea.io/gitea/modules/web/routing"
"github.com/chi-middleware/proxy"
"github.com/go-chi/chi/v5/middleware"
@ -49,11 +50,10 @@ func Middlewares() []func(http.Handler) http.Handler {
handlers = append(handlers, middleware.StripSlashes)
if !setting.DisableRouterLog && setting.RouterLogLevel != log.NONE {
if log.GetLogger("router").GetLevel() <= setting.RouterLogLevel {
handlers = append(handlers, LoggerHandler(setting.RouterLogLevel))
}
if !setting.DisableRouterLog {
handlers = append(handlers, routing.NewLoggerHandler())
}
if setting.EnableAccessLog {
handlers = append(handlers, context.AccessLogger())
}
@ -63,10 +63,11 @@ func Middlewares() []func(http.Handler) http.Handler {
// Why we need this? The Recovery() will try to render a beautiful
// error page for user, but the process can still panic again, and other
// middleware like session also may panic then we have to recover twice
// and send a simple error page that should not panic any more.
// and send a simple error page that should not panic anymore.
defer func() {
if err := recover(); err != nil {
combinedErr := fmt.Sprintf("PANIC: %v\n%s", err, string(log.Stack(2)))
routing.UpdatePanicError(req.Context(), err)
combinedErr := fmt.Sprintf("PANIC: %v\n%s", err, log.Stack(2))
log.Error("%v", combinedErr)
if setting.IsProd {
http.Error(resp, http.StatusText(500), 500)

View File

@ -38,8 +38,8 @@ func installRecovery() func(next http.Handler) http.Handler {
// should not panic any more.
defer func() {
if err := recover(); err != nil {
combinedErr := fmt.Sprintf("PANIC: %v\n%s", err, string(log.Stack(2)))
log.Error(combinedErr)
combinedErr := fmt.Sprintf("PANIC: %v\n%s", err, log.Stack(2))
log.Error("%s", combinedErr)
if setting.IsProd {
http.Error(w, http.StatusText(500), 500)
} else {
@ -49,8 +49,8 @@ func installRecovery() func(next http.Handler) http.Handler {
}()
if err := recover(); err != nil {
combinedErr := fmt.Sprintf("PANIC: %v\n%s", err, string(log.Stack(2)))
log.Error("%v", combinedErr)
combinedErr := fmt.Sprintf("PANIC: %v\n%s", err, log.Stack(2))
log.Error("%s", combinedErr)
lc := middleware.Locale(w, req)
var store = dataStore{
@ -85,10 +85,10 @@ func Routes() *web.Route {
r.Use(middle)
}
r.Use(public.AssetsHandler(&public.Options{
r.Use(web.WrapWithPrefix(public.AssetsURLPathPrefix, public.AssetsHandlerFunc(&public.Options{
Directory: path.Join(setting.StaticRootPath, "public"),
Prefix: "/assets",
}))
Prefix: public.AssetsURLPathPrefix,
}), "InstallAssetsHandler"))
r.Use(session.Sessioner(session.Options{
Provider: setting.SessionConfig.Provider,
@ -106,8 +106,11 @@ func Routes() *web.Route {
r.Use(Init)
r.Get("/", Install)
r.Post("/", web.Bind(forms.InstallForm{}), SubmitInstall)
r.NotFound(func(w http.ResponseWriter, req *http.Request) {
http.Redirect(w, req, setting.AppURL, http.StatusFound)
})
r.NotFound(web.Wrap(installNotFound))
return r
}
func installNotFound(w http.ResponseWriter, req *http.Request) {
http.Redirect(w, req, setting.AppURL, http.StatusFound)
}

View File

@ -21,12 +21,14 @@ import (
"code.gitea.io/gitea/modules/storage"
"code.gitea.io/gitea/modules/templates"
"code.gitea.io/gitea/modules/web/middleware"
"code.gitea.io/gitea/modules/web/routing"
"code.gitea.io/gitea/services/auth"
"gitea.com/go-chi/session"
)
func storageHandler(storageSetting setting.Storage, prefix string, objStore storage.ObjectStorage) func(next http.Handler) http.Handler {
funcInfo := routing.GetFuncInfo(storageHandler, prefix)
return func(next http.Handler) http.Handler {
if storageSetting.ServeDirect {
return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
@ -39,6 +41,7 @@ func storageHandler(storageSetting setting.Storage, prefix string, objStore stor
next.ServeHTTP(w, req)
return
}
routing.UpdateFuncInfo(req.Context(), funcInfo)
rPath := strings.TrimPrefix(req.URL.RequestURI(), "/"+prefix)
u, err := objStore.URL(rPath, path.Base(rPath))
@ -73,6 +76,7 @@ func storageHandler(storageSetting setting.Storage, prefix string, objStore stor
next.ServeHTTP(w, req)
return
}
routing.UpdateFuncInfo(req.Context(), funcInfo)
rPath := strings.TrimPrefix(req.URL.EscapedPath(), "/"+prefix+"/")
rPath = strings.TrimPrefix(rPath, "/")
@ -126,8 +130,9 @@ func Recovery() func(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
defer func() {
if err := recover(); err != nil {
combinedErr := fmt.Sprintf("PANIC: %v\n%s", err, string(log.Stack(2)))
log.Error("%v", combinedErr)
routing.UpdatePanicError(req.Context(), err)
combinedErr := fmt.Sprintf("PANIC: %v\n%s", err, log.Stack(2))
log.Error("%s", combinedErr)
sessionStore := session.GetSession(req)

View File

@ -21,6 +21,7 @@ import (
"code.gitea.io/gitea/modules/templates"
"code.gitea.io/gitea/modules/validation"
"code.gitea.io/gitea/modules/web"
"code.gitea.io/gitea/modules/web/routing"
"code.gitea.io/gitea/routers/api/v1/misc"
"code.gitea.io/gitea/routers/web/admin"
"code.gitea.io/gitea/routers/web/auth"
@ -73,11 +74,11 @@ func CorsHandler() func(next http.Handler) http.Handler {
func Routes(sessioner func(http.Handler) http.Handler) *web.Route {
routes := web.NewRoute()
routes.Use(public.AssetsHandler(&public.Options{
routes.Use(web.WrapWithPrefix(public.AssetsURLPathPrefix, public.AssetsHandlerFunc(&public.Options{
Directory: path.Join(setting.StaticRootPath, "public"),
Prefix: "/assets",
Prefix: public.AssetsURLPathPrefix,
CorsHandler: CorsHandler(),
}))
}), "AssetsHandler"))
routes.Use(sessioner)
@ -293,7 +294,7 @@ func RegisterRoutes(m *web.Route) {
})
}, reqSignOut)
m.Any("/user/events", events.Events)
m.Any("/user/events", routing.MarkLongPolling, events.Events)
m.Group("/login/oauth", func() {
m.Get("/authorize", bindIgnErr(forms.AuthorizationForm{}), auth.AuthorizeOAuth)