From 81fc293711c8c02766fb7b7d68668b19278df878 Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Mon, 18 Oct 2021 15:09:40 +0800 Subject: [PATCH 01/29] introduce router log handler v2 --- cmd/web.go | 2 +- custom/conf/app.example.ini | 3 + .../doc/advanced/config-cheat-sheet.en-us.md | 3 +- .../advanced/logging-documentation.en-us.md | 7 + modules/markup/markdown/markdown.go | 4 +- modules/public/public.go | 89 ++++--- modules/setting/log.go | 1 + modules/setting/setting.go | 2 + modules/web/route.go | 2 + routers/common/logger.go | 4 +- routers/common/logger_contxt.go | 229 ++++++++++++++++++ routers/common/logger_v2.go | 73 ++++++ routers/common/middleware.go | 17 +- routers/install/routes.go | 21 +- routers/web/base.go | 6 +- routers/web/web.go | 7 +- 16 files changed, 402 insertions(+), 68 deletions(-) create mode 100644 routers/common/logger_contxt.go create mode 100644 routers/common/logger_v2.go diff --git a/cmd/web.go b/cmd/web.go index 963c816207475..2342230e8718d 100644 --- a/cmd/web.go +++ b/cmd/web.go @@ -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)) } }() diff --git a/custom/conf/app.example.ini b/custom/conf/app.example.ini index 1753ed2330706..7e40ed030ef2f 100644 --- a/custom/conf/app.example.ini +++ b/custom/conf/app.example.ini @@ -459,6 +459,9 @@ ROUTER = console ;; The level at which the router logs ;ROUTER_LOG_LEVEL = Info ;; +;; The handler for router logs, it controls the log format +;ROUTER_LOG_HANDLER = v2 +;; ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; ;; ;; Access Logger (Creates log in NCSA common log format) diff --git a/docs/content/doc/advanced/config-cheat-sheet.en-us.md b/docs/content/doc/advanced/config-cheat-sheet.en-us.md index 91c62dbec34ae..206e40f38b8dd 100644 --- a/docs/content/doc/advanced/config-cheat-sheet.en-us.md +++ b/docs/content/doc/advanced/config-cheat-sheet.en-us.md @@ -704,7 +704,8 @@ 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_LOG_LEVEL`: **Info**: The log level that the router should log at. (If you are setting the access log, it's recommended to set this to Debug.) +- `ROUTER_LOG_HANDLER`: **v2**: The log handler that controls the log output format. Before 1.16 the router logs are outputted by handler `v1`. From 1.16, the default handler is `v2` which is more meaningful and friendly. - `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 diff --git a/docs/content/doc/advanced/logging-documentation.en-us.md b/docs/content/doc/advanced/logging-documentation.en-us.md index 478b6418c6cbf..04e3074c59a7a 100644 --- a/docs/content/doc/advanced/logging-documentation.en-us.md +++ b/docs/content/doc/advanced/logging-documentation.en-us.md @@ -79,6 +79,13 @@ changed if desired by setting the `ROUTER_LOG_LEVEL` value. Please note, setting the `LEVEL` of this logger to a level above `ROUTER_LOG_LEVEL` will result in no router logs. +You can control the output format by setting a log handler to `ROUTER_LOG_HANDLER`. +Now Gitea has two log handlers: +* `v1` is the default handler for Gitea before 1.16 +* `v2` is the default handler for Gitea from 1.16, it's more meaningful and friendly. + +If you have applications depending on the log format (eg: fail2ban), please make sure you use the correct log handler and log format. + Each output sublogger for this logger is configured in `[log.sublogger.router]` sections. There are certain default values which will not be inherited from the `[log]` or relevant diff --git a/modules/markup/markdown/markdown.go b/modules/markup/markdown/markdown.go index 554ee0d4be8cf..a7182681a9e88 100644 --- a/modules/markup/markdown/markdown.go +++ b/modules/markup/markdown/markdown.go @@ -181,7 +181,7 @@ func actualRender(ctx *markup.RenderContext, input io.Reader, output io.Writer) log.Warn("Unable to render markdown due to panic in goldmark: %v", err) if log.IsDebug() { - log.Debug("Panic in markdown: %v\n%s", err, string(log.Stack(2))) + log.Debug("Panic in markdown: %v\n%s", err, log.Stack(2)) } _ = lw.CloseWithError(fmt.Errorf("%v", err)) }() @@ -214,7 +214,7 @@ func render(ctx *markup.RenderContext, input io.Reader, output io.Writer) error log.Warn("Unable to render markdown due to panic in goldmark - will return sanitized raw bytes") if log.IsDebug() { - log.Debug("Panic in markdown: %v\n%s", err, string(log.Stack(2))) + log.Debug("Panic in markdown: %v\n%s", err, log.Stack(2)) } ret := markup.SanitizeReader(input, "") _, err = io.Copy(output, ret) diff --git a/modules/public/public.go b/modules/public/public.go index a58709d86fc9c..f4a769f27aef5 100644 --- a/modules/public/public.go +++ b/modules/public/public.go @@ -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,52 +39,46 @@ 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 - } - if req.Method != "GET" && req.Method != "HEAD" { - resp.WriteHeader(http.StatusNotFound) - return - } - - file := req.URL.Path - file = file[len(opts.Prefix):] - if len(file) == 0 { - resp.WriteHeader(http.StatusNotFound) - return - } - if strings.Contains(file, "\\") { - resp.WriteHeader(http.StatusBadRequest) - return - } - file = "/" + file - - var written bool - if opts.CorsHandler != nil { - written = true - opts.CorsHandler(http.HandlerFunc(func(http.ResponseWriter, *http.Request) { - written = false - })).ServeHTTP(resp, req) - } - if written { - return - } - - // custom files - if opts.handle(resp, req, http.Dir(custPath), file) { - return - } - - // internal files - if opts.handle(resp, req, fileSystem(opts.Directory), file) { - return - } + return func(resp http.ResponseWriter, req *http.Request) { + if req.Method != "GET" && req.Method != "HEAD" { + resp.WriteHeader(http.StatusNotFound) + return + } + file := req.URL.Path + file = file[len(opts.Prefix):] + if len(file) == 0 { resp.WriteHeader(http.StatusNotFound) - }) + return + } + if strings.Contains(file, "\\") { + resp.WriteHeader(http.StatusBadRequest) + return + } + file = "/" + file + + var written bool + if opts.CorsHandler != nil { + written = true + opts.CorsHandler(http.HandlerFunc(func(http.ResponseWriter, *http.Request) { + written = false + })).ServeHTTP(resp, req) + } + if written { + return + } + + // custom files + if opts.handle(resp, req, http.Dir(custPath), file) { + return + } + + // internal files + if opts.handle(resp, req, fileSystem(opts.Directory), file) { + return + } + + resp.WriteHeader(http.StatusNotFound) } } diff --git a/modules/setting/log.go b/modules/setting/log.go index ecf07114847cd..5ea8918d943dc 100644 --- a/modules/setting/log.go +++ b/modules/setting/log.go @@ -126,6 +126,7 @@ func getStacktraceLogLevel(section *ini.Section, key string, defaultValue string 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 diff --git a/modules/setting/setting.go b/modules/setting/setting.go index 2133184cfc40d..7f574bfa03df3 100644 --- a/modules/setting/setting.go +++ b/modules/setting/setting.go @@ -332,6 +332,7 @@ var ( LogRootPath string DisableRouterLog bool RouterLogLevel log.Level + RouterLogHandler string EnableAccessLog bool EnableSSHLog bool AccessLogTemplate string @@ -579,6 +580,7 @@ func NewContext() { 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")) + RouterLogHandler = Cfg.Section("log").Key("ROUTER_LOG_HANDLER").MustString("v2") sec := Cfg.Section("server") AppName = Cfg.Section("").Key("APP_NAME").MustString("Gitea: Git with a cup of tea") diff --git a/modules/web/route.go b/modules/web/route.go index ad9cea8bb6e14..8b0efc597943c 100644 --- a/modules/web/route.go +++ b/modules/web/route.go @@ -13,6 +13,7 @@ import ( "code.gitea.io/gitea/modules/context" "code.gitea.io/gitea/modules/web/middleware" + "code.gitea.io/gitea/routers/common" "gitea.com/go-chi/binding" chi "github.com/go-chi/chi/v5" @@ -40,6 +41,7 @@ func Wrap(handlers ...interface{}) http.HandlerFunc { return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) { for i := 0; i < len(handlers); i++ { handler := handlers[i] + common.UpdateContextHandlerFuncInfo(req.Context(), handler) switch t := handler.(type) { case http.HandlerFunc: t(resp, req) diff --git a/routers/common/logger.go b/routers/common/logger.go index bc1149543c94e..fd39e070d549e 100644 --- a/routers/common/logger.go +++ b/routers/common/logger.go @@ -12,8 +12,8 @@ import ( "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 { +// NewLoggerHandlerV1 is a handler that will log the routing to the default gitea log +func NewLoggerHandlerV1(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() diff --git a/routers/common/logger_contxt.go b/routers/common/logger_contxt.go new file mode 100644 index 0000000000000..7ce0c6931c38d --- /dev/null +++ b/routers/common/logger_contxt.go @@ -0,0 +1,229 @@ +// 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 ( + "context" + "net/http" + "reflect" + "runtime" + "strings" + "sync" + "time" + + "code.gitea.io/gitea/modules/graceful" + "code.gitea.io/gitea/modules/log" +) + +// LogRequestTrigger indicates when the logger is triggered +type LogRequestTrigger int + +const ( + //LogRequestStart at the beginning of a request + LogRequestStart LogRequestTrigger = iota + + //LogRequestExecuting the request is still executing + LogRequestExecuting + + //LogRequestOver the request is over (either completed or failed) + LogRequestOver +) + +// LogPrinter is used to output the log for a request +type LogPrinter func(trigger LogRequestTrigger, reqRec *logRequestRecord) + +type logRequestRecord struct { + recordIndex uint64 + startTime time.Time + httpRequest *http.Request + responseWriter http.ResponseWriter + funcInfo *logFuncInfo + funcInfoMu sync.RWMutex + panicError interface{} +} + +type logContextHandler struct { + logLevel log.Level + printLog LogPrinter + requestRecordMap map[uint64]*logRequestRecord + requestRecordMapMu sync.Mutex + reqRecordCount uint64 +} + +type logFuncInfo struct { + funcFile string + funcFileShort string + funcLine int + funcName string + funcNameShort string +} + +var funcInfoMap = map[uintptr]*logFuncInfo{} +var funcInfoMapMu sync.RWMutex + +func runtimeFuncToInfo(f *runtime.Func) *logFuncInfo { + file, line := f.FileLine(f.Entry()) + fi := &logFuncInfo{ + funcFile: strings.ReplaceAll(file, "\\", "/"), + funcLine: line, + funcName: f.Name(), + } + + // only keep last 2 names in path + p1 := strings.LastIndexByte(fi.funcFile, '/') + if p1 >= 0 { + p2 := strings.LastIndexByte(fi.funcFile[:p1], '/') + if p2 >= 0 { + fi.funcFileShort = fi.funcFile[p2+1:] + } + } + if fi.funcFileShort == "" { + fi.funcFileShort = fi.funcName + } + + // remove package prefix. eg: "xxx.com/pkg1/pkg2.foo" => "pkg2.foo" + p1 = strings.LastIndexByte(fi.funcName, '/') + if p1 >= 0 { + fi.funcNameShort = fi.funcName[p1+1:] + } else { + fi.funcNameShort = fi.funcName + } + + // remove ".func?" suffix for anonymous func + // usually we do not have more than 10 anonymous functions in one function, so this check is enough and fast. + if len(fi.funcNameShort) > 6 { + if fi.funcNameShort[len(fi.funcNameShort)-6:len(fi.funcNameShort)-1] == ".func" { + fi.funcNameShort = fi.funcNameShort[:len(fi.funcNameShort)-6] + } + } + return fi +} + +var contextKeyLogRequestRecord interface{} = "logRequestRecord" + +//UpdateContextHandlerFuncInfo updates a context's func info by a real handler func `v` +func UpdateContextHandlerFuncInfo(ctx context.Context, v interface{}, friendlyName ...string) { + if reqRec, ok := ctx.Value(contextKeyLogRequestRecord).(*logRequestRecord); ok { + var fi *logFuncInfo + ptr := reflect.ValueOf(v).Pointer() + + funcInfoMapMu.RLock() + fi, ok = funcInfoMap[ptr] + funcInfoMapMu.RUnlock() + + if !ok { + f := runtime.FuncForPC(ptr) + if f != nil { + fi = runtimeFuncToInfo(f) + if len(friendlyName) == 1 { + fi.funcNameShort = friendlyName[0] + } + + funcInfoMapMu.Lock() + funcInfoMap[ptr] = fi + funcInfoMapMu.Unlock() + } + } + + reqRec.funcInfoMu.Lock() + reqRec.funcInfo = fi + reqRec.funcInfoMu.Unlock() + } +} + +// WrapContextHandler wraps a log context handler for a router handler +func WrapContextHandler(pathSuffix string, handler http.HandlerFunc, friendlyName ...string) func(next http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) { + if !strings.HasPrefix(req.URL.Path, pathSuffix) { + next.ServeHTTP(resp, req) + return + } + UpdateContextHandlerFuncInfo(req.Context(), handler, friendlyName...) + handler(resp, req) + }) + } +} + +//UpdateContextHandlerPanicError updates a context's error info, a panic may be recovered by other middlewares, but we still need to know that. +func UpdateContextHandlerPanicError(ctx context.Context, err interface{}) { + if reqRec, ok := ctx.Value(contextKeyLogRequestRecord).(*logRequestRecord); ok { + reqRec.panicError = err + } +} + +func (lh *logContextHandler) startSlowQueryDetector(threshold time.Duration) { + graceful.GetManager().RunWithShutdownContext(func(baseCtx context.Context) { + go func() { + // 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 + t := time.NewTicker(time.Second) + for { + select { + case <-baseCtx.Done(): + return + case <-t.C: + now := time.Now() + var slows []*logRequestRecord + // find all slow requests with lock + lh.requestRecordMapMu.Lock() + for i, r := range lh.requestRecordMap { + d := now.Sub(r.startTime) + if d >= threshold { + slows = append(slows, r) + delete(lh.requestRecordMap, i) + } + } + lh.requestRecordMapMu.Unlock() + + // print logs for slow requests + if len(slows) > 0 { + for _, reqRec := range slows { + lh.printLog(LogRequestExecuting, reqRec) + } + } + } + } + }() + }) +} + +func (lh *logContextHandler) handler(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { + reqRec := &logRequestRecord{} + reqRec.startTime = time.Now() + reqRec.httpRequest = req + reqRec.responseWriter = w + + lh.requestRecordMapMu.Lock() + reqRec.recordIndex = lh.reqRecordCount + lh.reqRecordCount++ + lh.requestRecordMap[reqRec.recordIndex] = reqRec + lh.requestRecordMapMu.Unlock() + + defer func() { + // just in case there is a panic. now the panics are all recovered in middleware.go + localPanicErr := recover() + if localPanicErr != nil { + reqRec.panicError = localPanicErr + } + + lh.requestRecordMapMu.Lock() + delete(lh.requestRecordMap, reqRec.recordIndex) + lh.requestRecordMapMu.Unlock() + + lh.printLog(LogRequestOver, reqRec) + + if localPanicErr != nil { + // we do not recover any panic, so let the framework handle the panic error + panic(localPanicErr) + } + }() + req = req.WithContext(context.WithValue(req.Context(), contextKeyLogRequestRecord, reqRec)) + lh.printLog(LogRequestStart, reqRec) + next.ServeHTTP(w, req) + }) +} diff --git a/routers/common/logger_v2.go b/routers/common/logger_v2.go new file mode 100644 index 0000000000000..6d44381024a8c --- /dev/null +++ b/routers/common/logger_v2.go @@ -0,0 +1,73 @@ +// 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" + + giteaContext "code.gitea.io/gitea/modules/context" + "code.gitea.io/gitea/modules/log" +) + +// NewLoggerHandlerV2 is a handler that will log the routing to the default gitea log +func NewLoggerHandlerV2(level log.Level) func(next http.Handler) http.Handler { + lh := logContextHandler{ + logLevel: level, + requestRecordMap: map[uint64]*logRequestRecord{}, + } + lh.startSlowQueryDetector(3 * time.Second) + + lh.printLog = func(trigger LogRequestTrigger, reqRec *logRequestRecord) { + if trigger == LogRequestStart { + return + } + + funcFileShort := "" + funcLine := 0 + funcNameShort := "" + + reqRec.funcInfoMu.RLock() + if reqRec.funcInfo != nil { + funcFileShort, funcLine, funcNameShort = reqRec.funcInfo.funcFileShort, reqRec.funcInfo.funcLine, reqRec.funcInfo.funcNameShort + } else { + // we might not find all handlers, so if a handler is not processed by our `UpdateContextHandlerFuncInfo`, we won't know its information + // in such case, we should debug to find what handler it is and use `UpdateContextHandlerFuncInfo` to report its information + funcFileShort = "unknown-handler" + } + reqRec.funcInfoMu.RUnlock() + + var status int + if v, ok := reqRec.responseWriter.(giteaContext.ResponseWriter); ok { + status = v.Status() + } + + logger := log.GetLogger("router") + req := reqRec.httpRequest + if trigger == LogRequestExecuting { + _ = logger.Log(0, lh.logLevel, "handler: %s:%d(%s) still-executing %v %s for %s, elapsed %v", + funcFileShort, funcLine, funcNameShort, + log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr, + log.ColoredTime(time.Since(reqRec.startTime)), + ) + } else { + if reqRec.panicError != nil { + _ = logger.Log(0, lh.logLevel, "handler: %s:%d(%s) failed %v %s for %s, panic in %v, err=%v", + funcFileShort, funcLine, funcNameShort, + log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr, + log.ColoredTime(time.Since(reqRec.startTime)), + reqRec.panicError, + ) + } else { + _ = logger.Log(0, lh.logLevel, "handler: %s:%d(%s) completed %v %s for %s, %v %v in %v", + funcFileShort, funcLine, funcNameShort, + log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr, + log.ColoredStatus(status), log.ColoredStatus(status, http.StatusText(status)), log.ColoredTime(time.Since(reqRec.startTime))) + } + } + } + + return lh.handler +} diff --git a/routers/common/middleware.go b/routers/common/middleware.go index 1d96522dd9d19..cd0b1309fad81 100644 --- a/routers/common/middleware.go +++ b/routers/common/middleware.go @@ -45,7 +45,17 @@ func Middlewares() []func(http.Handler) http.Handler { if !setting.DisableRouterLog && setting.RouterLogLevel != log.NONE { if log.GetLogger("router").GetLevel() <= setting.RouterLogLevel { - handlers = append(handlers, LoggerHandler(setting.RouterLogLevel)) + var routerLogHandler func(http.Handler) http.Handler + if setting.RouterLogHandler == "v1" { + routerLogHandler = NewLoggerHandlerV1(setting.RouterLogLevel) + } else if setting.RouterLogHandler == "v2" { + routerLogHandler = NewLoggerHandlerV2(setting.RouterLogLevel) + } + if routerLogHandler == nil { + log.Warn("unknown router log handler '%s', fall back to v2") + routerLogHandler = NewLoggerHandlerV2(setting.RouterLogLevel) + } + handlers = append(handlers, routerLogHandler) } } if setting.EnableAccessLog { @@ -57,10 +67,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))) + UpdateContextHandlerPanicError(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) diff --git a/routers/install/routes.go b/routers/install/routes.go index e9aca85d8edd6..0e2467da3aa91 100644 --- a/routers/install/routes.go +++ b/routers/install/routes.go @@ -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(common.WrapContextHandler(public.AssetsURLPathPrefix, public.AssetsHandlerFunc(&public.Options{ Directory: path.Join(setting.StaticRootPath, "public"), - Prefix: "/assets", - })) + Prefix: public.AssetsURLPathPrefix, + }), "AssetsHandler")) r.Use(session.Sessioner(session.Options{ Provider: setting.SessionConfig.Provider, @@ -106,8 +106,13 @@ 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) { + + handlerNotFound := func(w http.ResponseWriter, req *http.Request) { http.Redirect(w, req, setting.AppURL, http.StatusFound) + } + r.NotFound(func(w http.ResponseWriter, req *http.Request) { + common.UpdateContextHandlerFuncInfo(req.Context(), handlerNotFound) + handlerNotFound(w, req) }) return r } diff --git a/routers/web/base.go b/routers/web/base.go index f50c5229b1d23..96975fc7734e1 100644 --- a/routers/web/base.go +++ b/routers/web/base.go @@ -21,6 +21,7 @@ import ( "code.gitea.io/gitea/modules/storage" "code.gitea.io/gitea/modules/templates" "code.gitea.io/gitea/modules/web/middleware" + "code.gitea.io/gitea/routers/common" "code.gitea.io/gitea/services/auth" "gitea.com/go-chi/session" @@ -126,8 +127,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) + common.UpdateContextHandlerPanicError(req.Context(), err) + combinedErr := fmt.Sprintf("PANIC: %v\n%s", err, log.Stack(2)) + log.Error("%s", combinedErr) sessionStore := session.GetSession(req) if sessionStore == nil { diff --git a/routers/web/web.go b/routers/web/web.go index caec0676714c4..e344911531e45 100644 --- a/routers/web/web.go +++ b/routers/web/web.go @@ -23,6 +23,7 @@ import ( "code.gitea.io/gitea/modules/validation" "code.gitea.io/gitea/modules/web" "code.gitea.io/gitea/routers/api/v1/misc" + "code.gitea.io/gitea/routers/common" "code.gitea.io/gitea/routers/web/admin" "code.gitea.io/gitea/routers/web/dev" "code.gitea.io/gitea/routers/web/events" @@ -74,11 +75,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(common.WrapContextHandler(public.AssetsURLPathPrefix, public.AssetsHandlerFunc(&public.Options{ Directory: path.Join(setting.StaticRootPath, "public"), - Prefix: "/assets", + Prefix: public.AssetsURLPathPrefix, CorsHandler: CorsHandler(), - })) + }), "AssetsHandler")) routes.Use(sessioner) From 9a7017e823652ed8b7170752e3cdeab89a1475e9 Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Mon, 18 Oct 2021 17:37:34 +0800 Subject: [PATCH 02/29] add comment about performance --- routers/common/logger_v2.go | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/routers/common/logger_v2.go b/routers/common/logger_v2.go index 6d44381024a8c..3179b740d3933 100644 --- a/routers/common/logger_v2.go +++ b/routers/common/logger_v2.go @@ -13,6 +13,13 @@ import ( ) // NewLoggerHandlerV2 is a handler that will log the routing to the default gitea log +// About performance: +// In v1, every request outputs 2 logs (Started/Completed) +// In v2 (this), every request only outputs one log, +// all runtime reflections of handler functions are cached +// the mutexes work in fast path for most cases (atomic incr) because there is seldom concurrency writings. +// So generally speaking, the `logger context` doesn't cost much, using v2 with `logger context` will not affect performance +// Instead, the performance may be improved because now only 1 log is outputted for each request. func NewLoggerHandlerV2(level log.Level) func(next http.Handler) http.Handler { lh := logContextHandler{ logLevel: level, From ce63306e5fd588e89b5d3ccd2029ea5525cc029f Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Tue, 19 Oct 2021 19:27:10 +0800 Subject: [PATCH 03/29] fix --- routers/common/logger_v2.go | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/routers/common/logger_v2.go b/routers/common/logger_v2.go index 3179b740d3933..c04eb8cc54fb3 100644 --- a/routers/common/logger_v2.go +++ b/routers/common/logger_v2.go @@ -46,11 +46,6 @@ func NewLoggerHandlerV2(level log.Level) func(next http.Handler) http.Handler { } reqRec.funcInfoMu.RUnlock() - var status int - if v, ok := reqRec.responseWriter.(giteaContext.ResponseWriter); ok { - status = v.Status() - } - logger := log.GetLogger("router") req := reqRec.httpRequest if trigger == LogRequestExecuting { @@ -68,6 +63,10 @@ func NewLoggerHandlerV2(level log.Level) func(next http.Handler) http.Handler { reqRec.panicError, ) } else { + var status int + if v, ok := reqRec.responseWriter.(giteaContext.ResponseWriter); ok { + status = v.Status() + } _ = logger.Log(0, lh.logLevel, "handler: %s:%d(%s) completed %v %s for %s, %v %v in %v", funcFileShort, funcLine, funcNameShort, log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr, From 22b13f2f15f3454e9635fee4511881305cafde81 Mon Sep 17 00:00:00 2001 From: Andrew Thornton Date: Tue, 19 Oct 2021 22:15:31 +0100 Subject: [PATCH 04/29] Add some comments and a test Signed-off-by: Andrew Thornton --- routers/common/logger_context.go | 272 ++++++++++++++++++++++++++ routers/common/logger_context_test.go | 79 ++++++++ routers/common/logger_contxt.go | 229 ---------------------- 3 files changed, 351 insertions(+), 229 deletions(-) create mode 100644 routers/common/logger_context.go create mode 100644 routers/common/logger_context_test.go delete mode 100644 routers/common/logger_contxt.go diff --git a/routers/common/logger_context.go b/routers/common/logger_context.go new file mode 100644 index 0000000000000..fc6261eb2dbec --- /dev/null +++ b/routers/common/logger_context.go @@ -0,0 +1,272 @@ +// 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 ( + "context" + "net/http" + "reflect" + "runtime" + "strings" + "sync" + "time" + + "code.gitea.io/gitea/modules/graceful" + "code.gitea.io/gitea/modules/log" +) + +// LogRequestTrigger indicates when the logger is triggered +type LogRequestTrigger int + +const ( + //LogRequestStart at the beginning of a request + LogRequestStart LogRequestTrigger = iota + + //LogRequestExecuting the request is still executing + LogRequestExecuting + + //LogRequestOver the request is over (either completed or failed) + LogRequestOver +) + +// LogPrinter is used to output the log for a request +type LogPrinter func(trigger LogRequestTrigger, reqRec *logRequestRecord) + +type logRequestRecord struct { + recordIndex uint64 + startTime time.Time + httpRequest *http.Request + responseWriter http.ResponseWriter + funcInfo *logFuncInfo + funcInfoMu sync.RWMutex + panicError interface{} +} + +type logContextHandler struct { + logLevel log.Level + printLog LogPrinter + requestRecordMap map[uint64]*logRequestRecord + requestRecordMapMu sync.Mutex + reqRecordCount uint64 +} + +type logFuncInfo struct { + funcFile string + funcFileShort string + funcLine int + funcName string + funcNameShort string +} + +var funcInfoMap = map[uintptr]*logFuncInfo{} +var funcInfoMapMu sync.RWMutex + +// shortenFilename from code.gitea.io/routers/common/logger_context.go to common/logger_context.go +func shortenFilename(filename, fallback string) (short string) { + if lastIndex := strings.LastIndexByte(filename, '/'); lastIndex >= 0 { + if secondLastIndex := strings.LastIndexByte(filename[:lastIndex], '/'); secondLastIndex >= 0 { + short = filename[secondLastIndex+1:] // This may be empty so we cannot return yet + } + } + if short == "" { + short = fallback + } + return +} + +// trimAnonymousFunctionSuffix trims .func[0-9]*() from the end of function names +func trimAnonymousFunctionSuffix(name string) string { + if len(name) < 7 { + return name + } + + funcSuffixIndex := strings.LastIndex(name, ".func") + if funcSuffixIndex < 0 { + return name + } + + hasFuncSuffix := true + for i := funcSuffixIndex + 5; i < len(name)-2; i++ { + if name[i] < '0' || name[i] > '9' { + hasFuncSuffix = false + break + } + } + if hasFuncSuffix { + return name[:funcSuffixIndex] + } + return name +} + +// convertToLogFuncInfo take a runtime.Func and convert it to a logFuncInfo +func convertToLogFuncInfo(f *runtime.Func) *logFuncInfo { + file, line := f.FileLine(f.Entry()) + + info := &logFuncInfo{ + funcFile: strings.ReplaceAll(file, "\\", "/"), + funcLine: line, + funcName: f.Name(), + } + + // only keep last 2 names in path faling back to funcName if not + info.funcFileShort = shortenFilename(info.funcFile, info.funcName) + + // remove package prefix. eg: "xxx.com/pkg1/pkg2.foo" => "pkg2.foo" + p1 := strings.LastIndexByte(info.funcName, '/') + if p1 >= 0 { + info.funcNameShort = info.funcName[p1+1:] + } else { + info.funcNameShort = info.funcName + } + + // remove ".func[0-9]*()" suffix for anonymous func + info.funcNameShort = trimAnonymousFunctionSuffix(info.funcNameShort) + + return info +} + +var contextKeyLogRequestRecord interface{} = "logRequestRecord" + +//UpdateContextHandlerFuncInfo updates a context's func info by a real handler func `v` +func UpdateContextHandlerFuncInfo(ctx context.Context, v interface{}, friendlyName ...string) { + record, ok := ctx.Value(contextKeyLogRequestRecord).(*logRequestRecord) + if !ok { + return + } + + var info *logFuncInfo + + // 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(v).Pointer() + + // Attempt get pre-cached information for this function pointer + funcInfoMapMu.RLock() + info, ok = funcInfoMap[ptr] + funcInfoMapMu.RUnlock() + + if !ok { + // 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 = convertToLogFuncInfo(f) + + // if we have been provided with a friendlyName override the short name we've generated + if len(friendlyName) == 1 { + info.funcNameShort = friendlyName[0] + } + + // cache this info globally + funcInfoMapMu.Lock() + funcInfoMap[ptr] = info + funcInfoMapMu.Unlock() + } + } + + // update our current record + record.funcInfoMu.Lock() + record.funcInfo = info + record.funcInfoMu.Unlock() +} + +// WrapContextHandler wraps a log context handler for a router handler +func WrapContextHandler(pathPrefix string, handler http.HandlerFunc, friendlyName ...string) func(next http.Handler) http.Handler { + 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 + } + UpdateContextHandlerFuncInfo(req.Context(), handler, friendlyName...) + handler(resp, req) + }) + } +} + +//UpdateContextHandlerPanicError updates a context's error info, a panic may be recovered by other middlewares, but we still need to know that. +func UpdateContextHandlerPanicError(ctx context.Context, err interface{}) { + if reqRec, ok := ctx.Value(contextKeyLogRequestRecord).(*logRequestRecord); ok { + reqRec.panicError = err + } +} + +func (lh *logContextHandler) 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 + for { + select { + case <-baseCtx.Done(): + return + case <-time.After(time.Second): + now := time.Now() + + var slowRequests []*logRequestRecord + + // find all slow requests with lock + lh.requestRecordMapMu.Lock() + for index, reqRecord := range lh.requestRecordMap { + if now.Sub(reqRecord.startTime) < threshold { + continue + } + + slowRequests = append(slowRequests, reqRecord) + delete(lh.requestRecordMap, index) + } + lh.requestRecordMapMu.Unlock() + + // print logs for slow requests + for _, reqRecord := range slowRequests { + lh.printLog(LogRequestExecuting, reqRecord) + } + } + } + }) +} + +func (lh *logContextHandler) handler(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { + record := &logRequestRecord{ + startTime: time.Now(), + httpRequest: req, + responseWriter: w, + } + + // generate a record index an insert into the map + lh.requestRecordMapMu.Lock() + record.recordIndex = lh.reqRecordCount + lh.reqRecordCount++ + lh.requestRecordMap[record.recordIndex] = record + lh.requestRecordMapMu.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.panicError = localPanicErr + } + + // remove from the record map + lh.requestRecordMapMu.Lock() + delete(lh.requestRecordMap, record.recordIndex) + lh.requestRecordMapMu.Unlock() + + // log the end of the request + lh.printLog(LogRequestOver, 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(), contextKeyLogRequestRecord, record)) + lh.printLog(LogRequestStart, record) + next.ServeHTTP(w, req) + }) +} diff --git a/routers/common/logger_context_test.go b/routers/common/logger_context_test.go new file mode 100644 index 0000000000000..fb4ebb70fba58 --- /dev/null +++ b/routers/common/logger_context_test.go @@ -0,0 +1,79 @@ +// 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 ( + "testing" +) + +func Test_shortenFilename(t *testing.T) { + tests := []struct { + name string + filename string + funcName string + wantShort string + }{ + { + "code.gitea.io/routers/common/logger_context.go to common/logger_context.go", + "code.gitea.io/routers/common/logger_context.go", + "FUNC_NAME", + "common/logger_context.go", + }, + { + "common/logger_context.go to shortenFilename()", + "common/logger_context.go", + "shortenFilename()", + "shortenFilename()", + }, + { + "logger_context.go to shortenFilename()", + "logger_context.go", + "shortenFilename()", + "shortenFilename()", + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + if gotShort := shortenFilename(tt.filename, tt.funcName); gotShort != tt.wantShort { + t.Errorf("shortenFilename() = %v, want %v", gotShort, tt.wantShort) + } + }) + } +} + +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/routers/common/logger_contxt.go b/routers/common/logger_contxt.go deleted file mode 100644 index 7ce0c6931c38d..0000000000000 --- a/routers/common/logger_contxt.go +++ /dev/null @@ -1,229 +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 ( - "context" - "net/http" - "reflect" - "runtime" - "strings" - "sync" - "time" - - "code.gitea.io/gitea/modules/graceful" - "code.gitea.io/gitea/modules/log" -) - -// LogRequestTrigger indicates when the logger is triggered -type LogRequestTrigger int - -const ( - //LogRequestStart at the beginning of a request - LogRequestStart LogRequestTrigger = iota - - //LogRequestExecuting the request is still executing - LogRequestExecuting - - //LogRequestOver the request is over (either completed or failed) - LogRequestOver -) - -// LogPrinter is used to output the log for a request -type LogPrinter func(trigger LogRequestTrigger, reqRec *logRequestRecord) - -type logRequestRecord struct { - recordIndex uint64 - startTime time.Time - httpRequest *http.Request - responseWriter http.ResponseWriter - funcInfo *logFuncInfo - funcInfoMu sync.RWMutex - panicError interface{} -} - -type logContextHandler struct { - logLevel log.Level - printLog LogPrinter - requestRecordMap map[uint64]*logRequestRecord - requestRecordMapMu sync.Mutex - reqRecordCount uint64 -} - -type logFuncInfo struct { - funcFile string - funcFileShort string - funcLine int - funcName string - funcNameShort string -} - -var funcInfoMap = map[uintptr]*logFuncInfo{} -var funcInfoMapMu sync.RWMutex - -func runtimeFuncToInfo(f *runtime.Func) *logFuncInfo { - file, line := f.FileLine(f.Entry()) - fi := &logFuncInfo{ - funcFile: strings.ReplaceAll(file, "\\", "/"), - funcLine: line, - funcName: f.Name(), - } - - // only keep last 2 names in path - p1 := strings.LastIndexByte(fi.funcFile, '/') - if p1 >= 0 { - p2 := strings.LastIndexByte(fi.funcFile[:p1], '/') - if p2 >= 0 { - fi.funcFileShort = fi.funcFile[p2+1:] - } - } - if fi.funcFileShort == "" { - fi.funcFileShort = fi.funcName - } - - // remove package prefix. eg: "xxx.com/pkg1/pkg2.foo" => "pkg2.foo" - p1 = strings.LastIndexByte(fi.funcName, '/') - if p1 >= 0 { - fi.funcNameShort = fi.funcName[p1+1:] - } else { - fi.funcNameShort = fi.funcName - } - - // remove ".func?" suffix for anonymous func - // usually we do not have more than 10 anonymous functions in one function, so this check is enough and fast. - if len(fi.funcNameShort) > 6 { - if fi.funcNameShort[len(fi.funcNameShort)-6:len(fi.funcNameShort)-1] == ".func" { - fi.funcNameShort = fi.funcNameShort[:len(fi.funcNameShort)-6] - } - } - return fi -} - -var contextKeyLogRequestRecord interface{} = "logRequestRecord" - -//UpdateContextHandlerFuncInfo updates a context's func info by a real handler func `v` -func UpdateContextHandlerFuncInfo(ctx context.Context, v interface{}, friendlyName ...string) { - if reqRec, ok := ctx.Value(contextKeyLogRequestRecord).(*logRequestRecord); ok { - var fi *logFuncInfo - ptr := reflect.ValueOf(v).Pointer() - - funcInfoMapMu.RLock() - fi, ok = funcInfoMap[ptr] - funcInfoMapMu.RUnlock() - - if !ok { - f := runtime.FuncForPC(ptr) - if f != nil { - fi = runtimeFuncToInfo(f) - if len(friendlyName) == 1 { - fi.funcNameShort = friendlyName[0] - } - - funcInfoMapMu.Lock() - funcInfoMap[ptr] = fi - funcInfoMapMu.Unlock() - } - } - - reqRec.funcInfoMu.Lock() - reqRec.funcInfo = fi - reqRec.funcInfoMu.Unlock() - } -} - -// WrapContextHandler wraps a log context handler for a router handler -func WrapContextHandler(pathSuffix string, handler http.HandlerFunc, friendlyName ...string) func(next http.Handler) http.Handler { - return func(next http.Handler) http.Handler { - return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) { - if !strings.HasPrefix(req.URL.Path, pathSuffix) { - next.ServeHTTP(resp, req) - return - } - UpdateContextHandlerFuncInfo(req.Context(), handler, friendlyName...) - handler(resp, req) - }) - } -} - -//UpdateContextHandlerPanicError updates a context's error info, a panic may be recovered by other middlewares, but we still need to know that. -func UpdateContextHandlerPanicError(ctx context.Context, err interface{}) { - if reqRec, ok := ctx.Value(contextKeyLogRequestRecord).(*logRequestRecord); ok { - reqRec.panicError = err - } -} - -func (lh *logContextHandler) startSlowQueryDetector(threshold time.Duration) { - graceful.GetManager().RunWithShutdownContext(func(baseCtx context.Context) { - go func() { - // 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 - t := time.NewTicker(time.Second) - for { - select { - case <-baseCtx.Done(): - return - case <-t.C: - now := time.Now() - var slows []*logRequestRecord - // find all slow requests with lock - lh.requestRecordMapMu.Lock() - for i, r := range lh.requestRecordMap { - d := now.Sub(r.startTime) - if d >= threshold { - slows = append(slows, r) - delete(lh.requestRecordMap, i) - } - } - lh.requestRecordMapMu.Unlock() - - // print logs for slow requests - if len(slows) > 0 { - for _, reqRec := range slows { - lh.printLog(LogRequestExecuting, reqRec) - } - } - } - } - }() - }) -} - -func (lh *logContextHandler) handler(next http.Handler) http.Handler { - return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { - reqRec := &logRequestRecord{} - reqRec.startTime = time.Now() - reqRec.httpRequest = req - reqRec.responseWriter = w - - lh.requestRecordMapMu.Lock() - reqRec.recordIndex = lh.reqRecordCount - lh.reqRecordCount++ - lh.requestRecordMap[reqRec.recordIndex] = reqRec - lh.requestRecordMapMu.Unlock() - - defer func() { - // just in case there is a panic. now the panics are all recovered in middleware.go - localPanicErr := recover() - if localPanicErr != nil { - reqRec.panicError = localPanicErr - } - - lh.requestRecordMapMu.Lock() - delete(lh.requestRecordMap, reqRec.recordIndex) - lh.requestRecordMapMu.Unlock() - - lh.printLog(LogRequestOver, reqRec) - - if localPanicErr != nil { - // we do not recover any panic, so let the framework handle the panic error - panic(localPanicErr) - } - }() - req = req.WithContext(context.WithValue(req.Context(), contextKeyLogRequestRecord, reqRec)) - lh.printLog(LogRequestStart, reqRec) - next.ServeHTTP(w, req) - }) -} From be8af1a22a98434ad3221e7bced87264d4b03ded Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Wed, 20 Oct 2021 10:44:18 +0800 Subject: [PATCH 05/29] apply suggestion --- routers/common/logger_contxt.go | 56 ++++++++++++++++----------------- 1 file changed, 27 insertions(+), 29 deletions(-) diff --git a/routers/common/logger_contxt.go b/routers/common/logger_contxt.go index 7ce0c6931c38d..d9357a8ac33ab 100644 --- a/routers/common/logger_contxt.go +++ b/routers/common/logger_contxt.go @@ -155,40 +155,38 @@ func UpdateContextHandlerPanicError(ctx context.Context, err interface{}) { } func (lh *logContextHandler) startSlowQueryDetector(threshold time.Duration) { - graceful.GetManager().RunWithShutdownContext(func(baseCtx context.Context) { - go func() { - // 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 - t := time.NewTicker(time.Second) - for { - select { - case <-baseCtx.Done(): - return - case <-t.C: - now := time.Now() - var slows []*logRequestRecord - // find all slow requests with lock - lh.requestRecordMapMu.Lock() - for i, r := range lh.requestRecordMap { - d := now.Sub(r.startTime) - if d >= threshold { - slows = append(slows, r) - delete(lh.requestRecordMap, i) - } + go 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 + t := time.NewTicker(time.Second) + for { + select { + case <-baseCtx.Done(): + return + case <-t.C: + now := time.Now() + var slows []*logRequestRecord + // find all slow requests with lock + lh.requestRecordMapMu.Lock() + for i, r := range lh.requestRecordMap { + d := now.Sub(r.startTime) + if d >= threshold { + slows = append(slows, r) + delete(lh.requestRecordMap, i) } - lh.requestRecordMapMu.Unlock() + } + lh.requestRecordMapMu.Unlock() - // print logs for slow requests - if len(slows) > 0 { - for _, reqRec := range slows { - lh.printLog(LogRequestExecuting, reqRec) - } + // print logs for slow requests + if len(slows) > 0 { + for _, reqRec := range slows { + lh.printLog(LogRequestExecuting, reqRec) } } } - }() - }) + } + }(graceful.GetManager().ShutdownContext()) } func (lh *logContextHandler) handler(next http.Handler) http.Handler { From 3eff51e60c24e9850bca13f71aa764ce62a3c776 Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Thu, 28 Oct 2021 14:31:44 +0800 Subject: [PATCH 06/29] tune comments --- routers/common/logger_context.go | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/routers/common/logger_context.go b/routers/common/logger_context.go index fc6261eb2dbec..86a36a391e5c8 100644 --- a/routers/common/logger_context.go +++ b/routers/common/logger_context.go @@ -63,7 +63,7 @@ type logFuncInfo struct { var funcInfoMap = map[uintptr]*logFuncInfo{} var funcInfoMapMu sync.RWMutex -// shortenFilename from code.gitea.io/routers/common/logger_context.go to common/logger_context.go +// 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) (short string) { if lastIndex := strings.LastIndexByte(filename, '/'); lastIndex >= 0 { if secondLastIndex := strings.LastIndexByte(filename[:lastIndex], '/'); secondLastIndex >= 0 { @@ -76,7 +76,7 @@ func shortenFilename(filename, fallback string) (short string) { return } -// trimAnonymousFunctionSuffix trims .func[0-9]*() from the end of function names +// 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 len(name) < 7 { return name @@ -100,7 +100,7 @@ func trimAnonymousFunctionSuffix(name string) string { return name } -// convertToLogFuncInfo take a runtime.Func and convert it to a logFuncInfo +// convertToLogFuncInfo take a runtime.Func and convert it to a logFuncInfo, fill in shorten filename, etc func convertToLogFuncInfo(f *runtime.Func) *logFuncInfo { file, line := f.FileLine(f.Entry()) @@ -114,9 +114,9 @@ func convertToLogFuncInfo(f *runtime.Func) *logFuncInfo { info.funcFileShort = shortenFilename(info.funcFile, info.funcName) // remove package prefix. eg: "xxx.com/pkg1/pkg2.foo" => "pkg2.foo" - p1 := strings.LastIndexByte(info.funcName, '/') - if p1 >= 0 { - info.funcNameShort = info.funcName[p1+1:] + pos := strings.LastIndexByte(info.funcName, '/') + if pos >= 0 { + info.funcNameShort = info.funcName[pos+1:] } else { info.funcNameShort = info.funcName } @@ -129,8 +129,8 @@ func convertToLogFuncInfo(f *runtime.Func) *logFuncInfo { var contextKeyLogRequestRecord interface{} = "logRequestRecord" -//UpdateContextHandlerFuncInfo updates a context's func info by a real handler func `v` -func UpdateContextHandlerFuncInfo(ctx context.Context, v interface{}, friendlyName ...string) { +//UpdateContextHandlerFuncInfo updates a context's func info by a real handler func `fn` +func UpdateContextHandlerFuncInfo(ctx context.Context, fn interface{}, friendlyName ...string) { record, ok := ctx.Value(contextKeyLogRequestRecord).(*logRequestRecord) if !ok { return @@ -140,7 +140,7 @@ func UpdateContextHandlerFuncInfo(ctx context.Context, v interface{}, friendlyNa // 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(v).Pointer() + ptr := reflect.ValueOf(fn).Pointer() // Attempt get pre-cached information for this function pointer funcInfoMapMu.RLock() @@ -260,7 +260,7 @@ func (lh *logContextHandler) handler(next http.Handler) http.Handler { lh.printLog(LogRequestOver, 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 + // the panic wasn't recovered before us, so we should pass it up, and let the framework handle the panic error panic(localPanicErr) } }() From cca722cb85aee6f94cfdda29026cdf573182c82c Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Thu, 28 Oct 2021 14:36:16 +0800 Subject: [PATCH 07/29] we can use `time.NewTicker` safely and it reduces memory allocations. --- routers/common/logger_context.go | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/routers/common/logger_context.go b/routers/common/logger_context.go index 86a36a391e5c8..bfdbd85abf0e0 100644 --- a/routers/common/logger_context.go +++ b/routers/common/logger_context.go @@ -199,11 +199,14 @@ func (lh *logContextHandler) startSlowQueryDetector(threshold time.Duration) { // 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.5ms are all OK. + t := time.NewTicker(time.Second) for { select { case <-baseCtx.Done(): return - case <-time.After(time.Second): + case <-t.C: now := time.Now() var slowRequests []*logRequestRecord From 05de541284401e7b7ee998fcaa4a33cec3746f33 Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Thu, 28 Oct 2021 15:15:52 +0800 Subject: [PATCH 08/29] tune tests --- routers/common/logger_context.go | 22 +++++++------ routers/common/logger_context_test.go | 46 ++++++++++++++------------- 2 files changed, 37 insertions(+), 31 deletions(-) diff --git a/routers/common/logger_context.go b/routers/common/logger_context.go index bfdbd85abf0e0..855890b6a8feb 100644 --- a/routers/common/logger_context.go +++ b/routers/common/logger_context.go @@ -64,20 +64,21 @@ var funcInfoMap = map[uintptr]*logFuncInfo{} var funcInfoMapMu sync.RWMutex // 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) (short string) { +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 { - short = filename[secondLastIndex+1:] // This may be empty so we cannot return yet + return filename[secondLastIndex+1:] } } - if short == "" { - short = fallback - } - return + 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 } @@ -88,12 +89,15 @@ func trimAnonymousFunctionSuffix(name string) string { } hasFuncSuffix := true - for i := funcSuffixIndex + 5; i < len(name)-2; i++ { + + // 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] } @@ -110,7 +114,7 @@ func convertToLogFuncInfo(f *runtime.Func) *logFuncInfo { funcName: f.Name(), } - // only keep last 2 names in path faling back to funcName if not + // only keep last 2 names in path, fall back to funcName if not info.funcFileShort = shortenFilename(info.funcFile, info.funcName) // remove package prefix. eg: "xxx.com/pkg1/pkg2.foo" => "pkg2.foo" @@ -121,7 +125,7 @@ func convertToLogFuncInfo(f *runtime.Func) *logFuncInfo { info.funcNameShort = info.funcName } - // remove ".func[0-9]*()" suffix for anonymous func + // remove ".func[0-9]*" suffix for anonymous func info.funcNameShort = trimAnonymousFunctionSuffix(info.funcNameShort) return info diff --git a/routers/common/logger_context_test.go b/routers/common/logger_context_test.go index fb4ebb70fba58..2f12cc557ffe5 100644 --- a/routers/common/logger_context_test.go +++ b/routers/common/logger_context_test.go @@ -5,39 +5,41 @@ package common import ( + "fmt" "testing" ) func Test_shortenFilename(t *testing.T) { tests := []struct { - name string - filename string - funcName string - wantShort string + filename string + fallback string + expected string }{ { - "code.gitea.io/routers/common/logger_context.go to common/logger_context.go", "code.gitea.io/routers/common/logger_context.go", - "FUNC_NAME", + "NO_FALLBACK", "common/logger_context.go", }, { - "common/logger_context.go to shortenFilename()", "common/logger_context.go", - "shortenFilename()", - "shortenFilename()", + "NO_FALLBACK", + "common/logger_context.go", }, { - "logger_context.go to shortenFilename()", "logger_context.go", - "shortenFilename()", - "shortenFilename()", + "NO_FALLBACK", + "logger_context.go", + }, + { + "", + "USE_FALLBACK", + "USE_FALLBACK", }, } for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - if gotShort := shortenFilename(tt.filename, tt.funcName); gotShort != tt.wantShort { - t.Errorf("shortenFilename() = %v, want %v", gotShort, tt.wantShort) + 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) } }) } @@ -49,23 +51,23 @@ func Test_trimAnonymousFunctionSuffix(t *testing.T) { want string }{ { - "notAnonymous()", - "notAnonymous()", + "notAnonymous", + "notAnonymous", }, { - "anonymous.func1()", + "anonymous.func1", "anonymous", }, { - "notAnonymous.funca()", - "notAnonymous.funca()", + "notAnonymous.funca", + "notAnonymous.funca", }, { - "anonymous.func100()", + "anonymous.func100", "anonymous", }, { - "anonymous.func100.func6()", + "anonymous.func100.func6", "anonymous.func100", }, } From c2032bde421db91fcc62bd521bed84597f84aead Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Wed, 1 Dec 2021 15:56:43 +0800 Subject: [PATCH 09/29] Fix merge --- docs/content/doc/advanced/config-cheat-sheet.en-us.md | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/docs/content/doc/advanced/config-cheat-sheet.en-us.md b/docs/content/doc/advanced/config-cheat-sheet.en-us.md index 030ca7b36b8c9..49b2a935e1042 100644 --- a/docs/content/doc/advanced/config-cheat-sheet.en-us.md +++ b/docs/content/doc/advanced/config-cheat-sheet.en-us.md @@ -750,7 +750,8 @@ 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_LOG_LEVEL`: **Info**: The log level that the router should log at. (If you are setting the access log, it's recommended to place this at Debug.) +- `ROUTER_LOG_HANDLER`: **v2**: The log handler that controls the log output format. Before 1.16 the router logs are outputted by handler `v1`. From 1.16, the default handler is `v2` which is more meaningful and friendly. - `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 From afd32000bf0309054e1603d6eeac5757f7b550ee Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Wed, 1 Dec 2021 17:58:55 +0800 Subject: [PATCH 10/29] make the duration more readable --- modules/log/colors_router.go | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/modules/log/colors_router.go b/modules/log/colors_router.go index 3064e005cfa9d..af51d1ad12e59 100644 --- a/modules/log/colors_router.go +++ b/modules/log/colors_router.go @@ -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 adds colors for time on log, it always formats the duration in Millisecond unit func ColoredTime(duration time.Duration) *ColoredValue { + // the output of 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) } From 8dafc18e8b963f954c7336f2954f13137dba1d07 Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Wed, 22 Dec 2021 16:49:59 +0800 Subject: [PATCH 11/29] show "started" message in DEBUG level, show long-polling message --- custom/conf/app.example.ini | 3 ++- modules/log/level.go | 6 ++++++ modules/log/level_test.go | 10 ++++++++++ modules/log/log.go | 4 ++++ routers/common/logger_context.go | 14 +++++++++++--- routers/common/logger_v2.go | 32 ++++++++++++++++++++++---------- routers/common/middleware.go | 24 +++++++++++------------- routers/web/web.go | 2 +- 8 files changed, 67 insertions(+), 28 deletions(-) diff --git a/custom/conf/app.example.ini b/custom/conf/app.example.ini index dc6cb85a25314..6550d1773e766 100644 --- a/custom/conf/app.example.ini +++ b/custom/conf/app.example.ini @@ -469,7 +469,8 @@ ROUTER = console ;; The level at which the router logs ;ROUTER_LOG_LEVEL = Info ;; -;; The handler for router logs, it controls the log format +;; The handler for router logs, it controls the router log format, mainly for debug purpose +;; For v2 (1.16 and later), developers could set both `LEVEL=Debug` and `ROUTER_LOG_LEVEL=Debug` to get the "started" request messages ;ROUTER_LOG_HANDLER = v2 ;; ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; diff --git a/modules/log/level.go b/modules/log/level.go index 5964ed8f8b956..4420f73584961 100644 --- a/modules/log/level.go +++ b/modules/log/level.go @@ -74,6 +74,12 @@ func (l Level) String() string { return "info" } +// IsEnabledOn checks whether the log level is enabled on targetLevel. +// eg: INFO logs are enabled (outputted) on DEBUG / INFO, but not WARN / ERROR +func (l Level) IsEnabledOn(targetLevel Level) bool { + return l >= targetLevel && l != NONE +} + // Color returns the color string for this Level func (l Level) Color() *[]byte { color, ok := levelToColor[l] diff --git a/modules/log/level_test.go b/modules/log/level_test.go index 47f77738c5f14..e8c0b9c683bc5 100644 --- a/modules/log/level_test.go +++ b/modules/log/level_test.go @@ -54,3 +54,13 @@ func TestLevelMarshalUnmarshalJSON(t *testing.T) { func makeTestLevelBytes(level string) []byte { return []byte(fmt.Sprintf(`{"level":"%s"}`, level)) } + +func TestLevelIsEnabled(t *testing.T) { + assert.True(t, INFO.IsEnabledOn(DEBUG)) + assert.True(t, INFO.IsEnabledOn(INFO)) + assert.False(t, INFO.IsEnabledOn(ERROR)) + + assert.False(t, ERROR.IsEnabledOn(NONE)) + assert.False(t, NONE.IsEnabledOn(ERROR)) + assert.False(t, NONE.IsEnabledOn(NONE)) +} diff --git a/modules/log/log.go b/modules/log/log.go index cae24f53d87f2..5f1020a784b7d 100644 --- a/modules/log/log.go +++ b/modules/log/log.go @@ -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("can not detect correct package prefix, please update file: " + filename) + } } diff --git a/routers/common/logger_context.go b/routers/common/logger_context.go index 855890b6a8feb..91ccd3cdc7f55 100644 --- a/routers/common/logger_context.go +++ b/routers/common/logger_context.go @@ -14,7 +14,6 @@ import ( "time" "code.gitea.io/gitea/modules/graceful" - "code.gitea.io/gitea/modules/log" ) // LogRequestTrigger indicates when the logger is triggered @@ -37,6 +36,7 @@ type LogPrinter func(trigger LogRequestTrigger, reqRec *logRequestRecord) type logRequestRecord struct { recordIndex uint64 startTime time.Time + isLongPolling bool httpRequest *http.Request responseWriter http.ResponseWriter funcInfo *logFuncInfo @@ -45,7 +45,6 @@ type logRequestRecord struct { } type logContextHandler struct { - logLevel log.Level printLog LogPrinter requestRecordMap map[uint64]*logRequestRecord requestRecordMapMu sync.Mutex @@ -131,7 +130,16 @@ func convertToLogFuncInfo(f *runtime.Func) *logFuncInfo { return info } -var contextKeyLogRequestRecord interface{} = "logRequestRecord" +type contextKeyLogRequestRecordStruct struct {} +var contextKeyLogRequestRecord contextKeyLogRequestRecordStruct + +func MarkLongPolling(resp http.ResponseWriter, req *http.Request) { + record, ok := req.Context().Value(contextKeyLogRequestRecord).(*logRequestRecord) + if !ok { + return + } + record.isLongPolling = true +} //UpdateContextHandlerFuncInfo updates a context's func info by a real handler func `fn` func UpdateContextHandlerFuncInfo(ctx context.Context, fn interface{}, friendlyName ...string) { diff --git a/routers/common/logger_v2.go b/routers/common/logger_v2.go index c04eb8cc54fb3..83e2b95487fa7 100644 --- a/routers/common/logger_v2.go +++ b/routers/common/logger_v2.go @@ -8,8 +8,9 @@ import ( "net/http" "time" - giteaContext "code.gitea.io/gitea/modules/context" + gitea_context "code.gitea.io/gitea/modules/context" "code.gitea.io/gitea/modules/log" + "code.gitea.io/gitea/modules/setting" ) // NewLoggerHandlerV2 is a handler that will log the routing to the default gitea log @@ -20,23 +21,24 @@ import ( // the mutexes work in fast path for most cases (atomic incr) because there is seldom concurrency writings. // So generally speaking, the `logger context` doesn't cost much, using v2 with `logger context` will not affect performance // Instead, the performance may be improved because now only 1 log is outputted for each request. -func NewLoggerHandlerV2(level log.Level) func(next http.Handler) http.Handler { +func NewLoggerHandlerV2() func(next http.Handler) http.Handler { lh := logContextHandler{ - logLevel: level, requestRecordMap: map[uint64]*logRequestRecord{}, } lh.startSlowQueryDetector(3 * time.Second) lh.printLog = func(trigger LogRequestTrigger, reqRec *logRequestRecord) { - if trigger == LogRequestStart { + if trigger == LogRequestStart && !log.DEBUG.IsEnabledOn(setting.RouterLogLevel) { + // for performance, if the START message shouldn't be logged, we just return as early as possible + // developers could set both `log.LEVEL=debug` and `log.ROUTER_LOG_LEVEL=debug` to get the "started" request messages. return } funcFileShort := "" funcLine := 0 funcNameShort := "" - reqRec.funcInfoMu.RLock() + isLongPolling := reqRec.isLongPolling if reqRec.funcInfo != nil { funcFileShort, funcLine, funcNameShort = reqRec.funcInfo.funcFileShort, reqRec.funcInfo.funcLine, reqRec.funcInfo.funcNameShort } else { @@ -48,15 +50,25 @@ func NewLoggerHandlerV2(level log.Level) func(next http.Handler) http.Handler { logger := log.GetLogger("router") req := reqRec.httpRequest - if trigger == LogRequestExecuting { - _ = logger.Log(0, lh.logLevel, "handler: %s:%d(%s) still-executing %v %s for %s, elapsed %v", + if trigger == LogRequestStart { + // when a request starts, we have no information about the handler function information, we only have the request path + _ = logger.Log(0, log.DEBUG, "router: started %v %s for %s", log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr) + } else if trigger == LogRequestExecuting { + message := "still-executing" + level := log.WARN + if isLongPolling { + level = log.INFO + message = "long-polling" + } + _ = logger.Log(0, level, "router: %s:%d(%s) %s %v %s for %s, elapsed %v", funcFileShort, funcLine, funcNameShort, + message, log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr, log.ColoredTime(time.Since(reqRec.startTime)), ) } else { if reqRec.panicError != nil { - _ = logger.Log(0, lh.logLevel, "handler: %s:%d(%s) failed %v %s for %s, panic in %v, err=%v", + _ = logger.Log(0, log.WARN, "router: %s:%d(%s) failed %v %s for %s, panic in %v, err=%v", funcFileShort, funcLine, funcNameShort, log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr, log.ColoredTime(time.Since(reqRec.startTime)), @@ -64,10 +76,10 @@ func NewLoggerHandlerV2(level log.Level) func(next http.Handler) http.Handler { ) } else { var status int - if v, ok := reqRec.responseWriter.(giteaContext.ResponseWriter); ok { + if v, ok := reqRec.responseWriter.(gitea_context.ResponseWriter); ok { status = v.Status() } - _ = logger.Log(0, lh.logLevel, "handler: %s:%d(%s) completed %v %s for %s, %v %v in %v", + _ = logger.Log(0, log.INFO, "router: %s:%d(%s) completed %v %s for %s, %v %v in %v", funcFileShort, funcLine, funcNameShort, log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr, log.ColoredStatus(status), log.ColoredStatus(status, http.StatusText(status)), log.ColoredTime(time.Since(reqRec.startTime))) diff --git a/routers/common/middleware.go b/routers/common/middleware.go index 7bcb4740975ed..7b70e110c66bf 100644 --- a/routers/common/middleware.go +++ b/routers/common/middleware.go @@ -46,20 +46,18 @@ 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 { - var routerLogHandler func(http.Handler) http.Handler - if setting.RouterLogHandler == "v1" { - routerLogHandler = NewLoggerHandlerV1(setting.RouterLogLevel) - } else if setting.RouterLogHandler == "v2" { - routerLogHandler = NewLoggerHandlerV2(setting.RouterLogLevel) - } - if routerLogHandler == nil { - log.Warn("unknown router log handler '%s', fall back to v2") - routerLogHandler = NewLoggerHandlerV2(setting.RouterLogLevel) - } - handlers = append(handlers, routerLogHandler) + if !setting.DisableRouterLog { + var routerLogHandler func(http.Handler) http.Handler + if setting.RouterLogHandler == "v1" { + routerLogHandler = NewLoggerHandlerV1(setting.RouterLogLevel) + } else if setting.RouterLogHandler == "v2" { + routerLogHandler = NewLoggerHandlerV2() + } + if routerLogHandler == nil { + log.Warn("unknown router log handler '%s', fall back to v2") + routerLogHandler = NewLoggerHandlerV2() } + handlers = append(handlers, routerLogHandler) } if setting.EnableAccessLog { handlers = append(handlers, context.AccessLogger()) diff --git a/routers/web/web.go b/routers/web/web.go index 044b14dac092b..1c1c7447f6f0b 100644 --- a/routers/web/web.go +++ b/routers/web/web.go @@ -298,7 +298,7 @@ func RegisterRoutes(m *web.Route) { }) }, reqSignOut) - m.Any("/user/events", events.Events) + m.Any("/user/events", common.MarkLongPolling, events.Events) m.Group("/login/oauth", func() { m.Get("/authorize", bindIgnErr(forms.AuthorizationForm{}), user.AuthorizeOAuth) From cb989fec47d190e057d18b73ff600b73e259548e Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Wed, 22 Dec 2021 16:53:59 +0800 Subject: [PATCH 12/29] fix lint --- routers/common/logger_context.go | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/routers/common/logger_context.go b/routers/common/logger_context.go index 91ccd3cdc7f55..d4d8c17ba752b 100644 --- a/routers/common/logger_context.go +++ b/routers/common/logger_context.go @@ -130,7 +130,8 @@ func convertToLogFuncInfo(f *runtime.Func) *logFuncInfo { return info } -type contextKeyLogRequestRecordStruct struct {} +type contextKeyLogRequestRecordStruct struct{} + var contextKeyLogRequestRecord contextKeyLogRequestRecordStruct func MarkLongPolling(resp http.ResponseWriter, req *http.Request) { From 81ca64a85b69159f0e68f3170a3694b0ff9738a1 Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Wed, 22 Dec 2021 17:01:15 +0800 Subject: [PATCH 13/29] add comment --- routers/common/logger_context.go | 1 + 1 file changed, 1 insertion(+) diff --git a/routers/common/logger_context.go b/routers/common/logger_context.go index d4d8c17ba752b..421b9f3359c58 100644 --- a/routers/common/logger_context.go +++ b/routers/common/logger_context.go @@ -134,6 +134,7 @@ type contextKeyLogRequestRecordStruct struct{} var contextKeyLogRequestRecord contextKeyLogRequestRecordStruct +// 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(contextKeyLogRequestRecord).(*logRequestRecord) if !ok { From bce08751695d2602f679f16d02fc36e591dddec8 Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Wed, 22 Dec 2021 18:13:39 +0800 Subject: [PATCH 14/29] better format --- routers/common/logger_v2.go | 21 ++++++++++++++------- 1 file changed, 14 insertions(+), 7 deletions(-) diff --git a/routers/common/logger_v2.go b/routers/common/logger_v2.go index 83e2b95487fa7..95752e3e8d836 100644 --- a/routers/common/logger_v2.go +++ b/routers/common/logger_v2.go @@ -5,6 +5,7 @@ package common import ( + "fmt" "net/http" "time" @@ -53,25 +54,30 @@ func NewLoggerHandlerV2() func(next http.Handler) http.Handler { if trigger == LogRequestStart { // when a request starts, we have no information about the handler function information, we only have the request path _ = logger.Log(0, log.DEBUG, "router: started %v %s for %s", log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr) - } else if trigger == LogRequestExecuting { + return + } + + handlerFuncInfo := fmt.Sprintf("%s:%d(%s)", funcFileShort, funcLine, funcNameShort) + if trigger == LogRequestExecuting { message := "still-executing" level := log.WARN if isLongPolling { level = log.INFO message = "long-polling" } - _ = logger.Log(0, level, "router: %s:%d(%s) %s %v %s for %s, elapsed %v", - funcFileShort, funcLine, funcNameShort, + _ = 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(reqRec.startTime)), + handlerFuncInfo, ) } else { if reqRec.panicError != nil { - _ = logger.Log(0, log.WARN, "router: %s:%d(%s) failed %v %s for %s, panic in %v, err=%v", + _ = logger.Log(0, log.WARN, "router: failed %v %s for %s, panic in %v @ %s, err=%v", funcFileShort, funcLine, funcNameShort, log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr, log.ColoredTime(time.Since(reqRec.startTime)), + handlerFuncInfo, reqRec.panicError, ) } else { @@ -79,10 +85,11 @@ func NewLoggerHandlerV2() func(next http.Handler) http.Handler { if v, ok := reqRec.responseWriter.(gitea_context.ResponseWriter); ok { status = v.Status() } - _ = logger.Log(0, log.INFO, "router: %s:%d(%s) completed %v %s for %s, %v %v in %v", - funcFileShort, funcLine, funcNameShort, + _ = logger.Log(0, log.INFO, "router: completed %v %s for %s, %v %v in %v @ %s", log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr, - log.ColoredStatus(status), log.ColoredStatus(status, http.StatusText(status)), log.ColoredTime(time.Since(reqRec.startTime))) + log.ColoredStatus(status), log.ColoredStatus(status, http.StatusText(status)), log.ColoredTime(time.Since(reqRec.startTime)), + handlerFuncInfo, + ) } } } From 65a48bd443879825f6d7290bf73c842e6887785a Mon Sep 17 00:00:00 2001 From: Andrew Thornton Date: Wed, 22 Dec 2021 21:46:19 +0000 Subject: [PATCH 15/29] Generate FuncInfo outside of handlers and pre-wrap handlers Instead of using reflection at the time of request handling, generate the funcinfo when we're building the router. Also take the opportunity to wrap our handlers at the same time - thus preventing reflection from having to occur similarly. Signed-off-by: Andrew Thornton --- modules/web/route.go | 130 ----------------------------- modules/web/wrap.go | 94 +++++++++++++++++++++ modules/web/wrap_convert.go | 93 +++++++++++++++++++++ routers/common/logger_context.go | 135 ++++++++++++++++++++----------- routers/common/logger_v2.go | 6 +- routers/install/routes.go | 14 ++-- routers/web/base.go | 3 + 7 files changed, 288 insertions(+), 187 deletions(-) create mode 100644 modules/web/wrap.go create mode 100644 modules/web/wrap_convert.go diff --git a/modules/web/route.go b/modules/web/route.go index 6e684edfc12dd..86e407701c3c6 100644 --- a/modules/web/route.go +++ b/modules/web/route.go @@ -13,141 +13,11 @@ import ( "code.gitea.io/gitea/modules/context" "code.gitea.io/gitea/modules/web/middleware" - "code.gitea.io/gitea/routers/common" "gitea.com/go-chi/binding" 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.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] - common.UpdateContextHandlerFuncInfo(req.Context(), handler) - 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.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) diff --git a/modules/web/wrap.go b/modules/web/wrap.go new file mode 100644 index 0000000000000..fab7684bdbf8e --- /dev/null +++ b/modules/web/wrap.go @@ -0,0 +1,94 @@ +// 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" + + "code.gitea.io/gitea/modules/context" + "code.gitea.io/gitea/routers/common" +) + +// 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([]ourHandlerFunc, 0, len(handlers)) + + for _, handler := range handlers { + ourHandlers = append(ourHandlers, convertHandler(handler)) + } + return wrapInternal(ourHandlers) +} + +func wrapInternal(handlers []ourHandlerFunc) http.HandlerFunc { + return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) { + for i := 0; i < len(handlers); i++ { + handler := handlers[i] + others := handlers[i+1:] + done, deferable := handler(resp, req, others...) + if deferable != nil { + defer deferable() + } + if done { + return + } + } + }) +} + +// Middle wrap a context function as a chi middleware +func Middle(f func(ctx *context.Context)) func(netx http.Handler) http.Handler { + funcInfo := common.GetFuncInfo(f) + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) { + common.UpdateContextHandler(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 := common.GetFuncInfo(f) + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) { + common.UpdateContextHandler(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(netx http.Handler) http.Handler { + funcInfo := common.GetFuncInfo(f) + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) { + common.UpdateContextHandler(req.Context(), funcInfo) + ctx := context.GetAPIContext(req) + f(ctx) + if ctx.Written() { + return + } + next.ServeHTTP(ctx.Resp, ctx.Req) + }) + } +} diff --git a/modules/web/wrap_convert.go b/modules/web/wrap_convert.go new file mode 100644 index 0000000000000..33df0ee01e553 --- /dev/null +++ b/modules/web/wrap_convert.go @@ -0,0 +1,93 @@ +// 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/routers/common" +) + +type ourHandlerFunc func(resp http.ResponseWriter, req *http.Request, others ...ourHandlerFunc) (done bool, deferable func()) + +func convertHandler(handler interface{}) ourHandlerFunc { + funcInfo := common.GetFuncInfo(handler) + switch t := handler.(type) { + case http.HandlerFunc: + return func(resp http.ResponseWriter, req *http.Request, others ...ourHandlerFunc) (done bool, deferable func()) { + common.UpdateContextHandler(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 ...ourHandlerFunc) (done bool, deferable func()) { + common.UpdateContextHandler(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 ...ourHandlerFunc) (done bool, deferable func()) { + common.UpdateContextHandler(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 ...ourHandlerFunc) (done bool, deferable func()) { + common.UpdateContextHandler(req.Context(), funcInfo) + ctx := context.GetContext(req) + deferable = t(ctx) + done = ctx.Written() + return + } + case func(*context.APIContext): + return func(resp http.ResponseWriter, req *http.Request, others ...ourHandlerFunc) (done bool, deferable func()) { + common.UpdateContextHandler(req.Context(), funcInfo) + ctx := context.GetAPIContext(req) + t(ctx) + done = ctx.Written() + return + } + case func(*context.PrivateContext): + return func(resp http.ResponseWriter, req *http.Request, others ...ourHandlerFunc) (done bool, deferable func()) { + common.UpdateContextHandler(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 ...ourHandlerFunc) (done bool, deferable func()) { + common.UpdateContextHandler(req.Context(), funcInfo) + ctx := context.GetPrivateContext(req) + deferable = t(ctx) + done = ctx.Written() + return + } + case func(http.Handler) http.Handler: + return func(resp http.ResponseWriter, req *http.Request, others ...ourHandlerFunc) (done bool, deferable func()) { + var next = http.HandlerFunc(func(http.ResponseWriter, *http.Request) {}) + if len(others) > 0 { + next = wrapInternal(others) + } + common.UpdateContextHandler(req.Context(), funcInfo) + t(next).ServeHTTP(resp, req) + return + } + default: + panic(fmt.Sprintf("Unsupported handler type: %#v", t)) + } +} diff --git a/routers/common/logger_context.go b/routers/common/logger_context.go index 421b9f3359c58..cdae9cc0e4064 100644 --- a/routers/common/logger_context.go +++ b/routers/common/logger_context.go @@ -39,7 +39,7 @@ type logRequestRecord struct { isLongPolling bool httpRequest *http.Request responseWriter http.ResponseWriter - funcInfo *logFuncInfo + funcInfo *LogFuncInfo funcInfoMu sync.RWMutex panicError interface{} } @@ -51,15 +51,17 @@ type logContextHandler struct { reqRecordCount uint64 } -type logFuncInfo struct { - funcFile string - funcFileShort string - funcLine int - funcName string - funcNameShort string +// LogFuncInfo contains information about the function to be logged by the router log +type LogFuncInfo struct { + file string + shortFile string + line int + name string + shortName string } -var funcInfoMap = map[uintptr]*logFuncInfo{} +var funcInfoMap = map[uintptr]*LogFuncInfo{} +var funcInfoNameMap = map[string]*LogFuncInfo{} var funcInfoMapMu sync.RWMutex // 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" @@ -104,32 +106,42 @@ func trimAnonymousFunctionSuffix(name string) string { } // convertToLogFuncInfo take a runtime.Func and convert it to a logFuncInfo, fill in shorten filename, etc -func convertToLogFuncInfo(f *runtime.Func) *logFuncInfo { +func convertToLogFuncInfo(f *runtime.Func) *LogFuncInfo { file, line := f.FileLine(f.Entry()) - info := &logFuncInfo{ - funcFile: strings.ReplaceAll(file, "\\", "/"), - funcLine: line, - funcName: f.Name(), + info := &LogFuncInfo{ + file: strings.ReplaceAll(file, "\\", "/"), + line: line, + name: f.Name(), } // only keep last 2 names in path, fall back to funcName if not - info.funcFileShort = shortenFilename(info.funcFile, info.funcName) + info.shortFile = shortenFilename(info.file, info.name) // remove package prefix. eg: "xxx.com/pkg1/pkg2.foo" => "pkg2.foo" - pos := strings.LastIndexByte(info.funcName, '/') + pos := strings.LastIndexByte(info.name, '/') if pos >= 0 { - info.funcNameShort = info.funcName[pos+1:] + info.shortName = info.name[pos+1:] } else { - info.funcNameShort = info.funcName + info.shortName = info.name } // remove ".func[0-9]*" suffix for anonymous func - info.funcNameShort = trimAnonymousFunctionSuffix(info.funcNameShort) + info.shortName = trimAnonymousFunctionSuffix(info.shortName) return info } +func copyInfo(l *LogFuncInfo) *LogFuncInfo { + return &LogFuncInfo{ + file: l.file, + shortFile: l.shortFile, + line: l.line, + name: l.name, + shortName: l.shortName, + } +} + type contextKeyLogRequestRecordStruct struct{} var contextKeyLogRequestRecord contextKeyLogRequestRecordStruct @@ -143,59 +155,90 @@ func MarkLongPolling(resp http.ResponseWriter, req *http.Request) { record.isLongPolling = true } -//UpdateContextHandlerFuncInfo updates a context's func info by a real handler func `fn` -func UpdateContextHandlerFuncInfo(ctx context.Context, fn interface{}, friendlyName ...string) { - record, ok := ctx.Value(contextKeyLogRequestRecord).(*logRequestRecord) - if !ok { - return - } - - var info *logFuncInfo - +// GetFuncInfo returns the LogFuncInfo for a provided function and friendlyname +func GetFuncInfo(fn interface{}, friendlyName ...string) *LogFuncInfo { // 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() - // Attempt get pre-cached information for this function 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] + info, ok := funcInfoMap[ptr] funcInfoMapMu.RUnlock() - if !ok { - // 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 = convertToLogFuncInfo(f) - - // if we have been provided with a friendlyName override the short name we've generated - if len(friendlyName) == 1 { - info.funcNameShort = friendlyName[0] - } + if ok { + if len(friendlyName) == 1 { + name := friendlyName[0] + info = copyInfo(info) + info.shortName = name - // cache this info globally + funcInfoNameMap[name] = info + funcInfoMapMu.Lock() + funcInfoNameMap[name] = info funcInfoMapMu.Lock() - funcInfoMap[ptr] = 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 = convertToLogFuncInfo(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 = copyInfo(info) + info.shortName = name + funcInfoNameMap[name] = info + } + funcInfoMapMu.Unlock() + } + return info +} + +//UpdateContextHandler updates a context's func info by a real handler func `fn` +func UpdateContextHandler(ctx context.Context, funcInfo *LogFuncInfo) { + record, ok := ctx.Value(contextKeyLogRequestRecord).(*logRequestRecord) + if !ok { + return } // update our current record record.funcInfoMu.Lock() - record.funcInfo = info + record.funcInfo = funcInfo record.funcInfoMu.Unlock() + } // WrapContextHandler wraps a log context handler for a router handler func WrapContextHandler(pathPrefix string, handler http.HandlerFunc, friendlyName ...string) func(next http.Handler) http.Handler { + funcInfo := 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 } - UpdateContextHandlerFuncInfo(req.Context(), handler, friendlyName...) + UpdateContextHandler(req.Context(), funcInfo) handler(resp, req) }) } diff --git a/routers/common/logger_v2.go b/routers/common/logger_v2.go index 95752e3e8d836..fa0d1d759ae81 100644 --- a/routers/common/logger_v2.go +++ b/routers/common/logger_v2.go @@ -41,10 +41,10 @@ func NewLoggerHandlerV2() func(next http.Handler) http.Handler { reqRec.funcInfoMu.RLock() isLongPolling := reqRec.isLongPolling if reqRec.funcInfo != nil { - funcFileShort, funcLine, funcNameShort = reqRec.funcInfo.funcFileShort, reqRec.funcInfo.funcLine, reqRec.funcInfo.funcNameShort + funcFileShort, funcLine, funcNameShort = reqRec.funcInfo.shortFile, reqRec.funcInfo.line, reqRec.funcInfo.shortName } else { - // we might not find all handlers, so if a handler is not processed by our `UpdateContextHandlerFuncInfo`, we won't know its information - // in such case, we should debug to find what handler it is and use `UpdateContextHandlerFuncInfo` to report its information + // we might not find all handlers, so if a handler is not processed by our `UpdateContextHandler`, we won't know its information + // in such case, we should debug to find what handler it is and use `UpdateContextHandler` to report its information funcFileShort = "unknown-handler" } reqRec.funcInfoMu.RUnlock() diff --git a/routers/install/routes.go b/routers/install/routes.go index 0c4138cb3d0c2..2e9cce294aa51 100644 --- a/routers/install/routes.go +++ b/routers/install/routes.go @@ -88,7 +88,7 @@ func Routes() *web.Route { r.Use(common.WrapContextHandler(public.AssetsURLPathPrefix, public.AssetsHandlerFunc(&public.Options{ Directory: path.Join(setting.StaticRootPath, "public"), Prefix: public.AssetsURLPathPrefix, - }), "AssetsHandler")) + }), "InstallAssetsHandler")) r.Use(session.Sessioner(session.Options{ Provider: setting.SessionConfig.Provider, @@ -107,12 +107,10 @@ func Routes() *web.Route { r.Get("/", Install) r.Post("/", web.Bind(forms.InstallForm{}), SubmitInstall) - handlerNotFound := func(w http.ResponseWriter, req *http.Request) { - http.Redirect(w, req, setting.AppURL, http.StatusFound) - } - r.NotFound(func(w http.ResponseWriter, req *http.Request) { - common.UpdateContextHandlerFuncInfo(req.Context(), handlerNotFound) - handlerNotFound(w, req) - }) + r.NotFound(web.Wrap(installNotFound)) return r } + +func installNotFound(w http.ResponseWriter, req *http.Request) { + http.Redirect(w, req, setting.AppURL, http.StatusFound) +} diff --git a/routers/web/base.go b/routers/web/base.go index ca93ed1f6c74c..512c5e7d35a85 100644 --- a/routers/web/base.go +++ b/routers/web/base.go @@ -28,6 +28,7 @@ import ( ) func storageHandler(storageSetting setting.Storage, prefix string, objStore storage.ObjectStorage) func(next http.Handler) http.Handler { + funcInfo := common.GetFuncInfo(storageHandler, prefix) return func(next http.Handler) http.Handler { if storageSetting.ServeDirect { return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { @@ -40,6 +41,7 @@ func storageHandler(storageSetting setting.Storage, prefix string, objStore stor next.ServeHTTP(w, req) return } + common.UpdateContextHandler(req.Context(), funcInfo) rPath := strings.TrimPrefix(req.URL.RequestURI(), "/"+prefix) u, err := objStore.URL(rPath, path.Base(rPath)) @@ -74,6 +76,7 @@ func storageHandler(storageSetting setting.Storage, prefix string, objStore stor next.ServeHTTP(w, req) return } + common.UpdateContextHandler(req.Context(), funcInfo) rPath := strings.TrimPrefix(req.URL.EscapedPath(), "/"+prefix+"/") rPath = strings.TrimPrefix(rPath, "/") From 24760edc9b634bb6a7f07a37c380184ed401b82a Mon Sep 17 00:00:00 2001 From: Andrew Thornton Date: Wed, 22 Dec 2021 21:52:39 +0000 Subject: [PATCH 16/29] Update messages Signed-off-by: Andrew Thornton --- modules/log/colors_router.go | 2 +- modules/log/log.go | 2 +- routers/common/logger_context.go | 34 ++++++++++++++++---------------- 3 files changed, 19 insertions(+), 19 deletions(-) diff --git a/modules/log/colors_router.go b/modules/log/colors_router.go index af51d1ad12e59..fa19f030b6981 100644 --- a/modules/log/colors_router.go +++ b/modules/log/colors_router.go @@ -73,7 +73,7 @@ var ( wayTooLong = ColorBytes(BgMagenta) ) -// ColoredTime adds colors for time on log, it always formats the duration in Millisecond unit +// 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 in Millisecond is more readable: // * before: "100.1ms" "100.1μs" "100.1s" diff --git a/modules/log/log.go b/modules/log/log.go index 5f1020a784b7d..f805a36231bd8 100644 --- a/modules/log/log.go +++ b/modules/log/log.go @@ -290,6 +290,6 @@ func init() { 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("can not detect correct package prefix, please update file: " + filename) + panic("unable to detect correct package prefix, please update file: " + filename) } } diff --git a/routers/common/logger_context.go b/routers/common/logger_context.go index cdae9cc0e4064..49919b179b8f7 100644 --- a/routers/common/logger_context.go +++ b/routers/common/logger_context.go @@ -39,7 +39,7 @@ type logRequestRecord struct { isLongPolling bool httpRequest *http.Request responseWriter http.ResponseWriter - funcInfo *LogFuncInfo + funcInfo *FuncInfo funcInfoMu sync.RWMutex panicError interface{} } @@ -51,8 +51,8 @@ type logContextHandler struct { reqRecordCount uint64 } -// LogFuncInfo contains information about the function to be logged by the router log -type LogFuncInfo struct { +// FuncInfo contains information about the function to be logged by the router log +type FuncInfo struct { file string shortFile string line int @@ -60,8 +60,8 @@ type LogFuncInfo struct { shortName string } -var funcInfoMap = map[uintptr]*LogFuncInfo{} -var funcInfoNameMap = map[string]*LogFuncInfo{} +var funcInfoMap = map[uintptr]*FuncInfo{} +var funcInfoNameMap = map[string]*FuncInfo{} var funcInfoMapMu sync.RWMutex // 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" @@ -105,11 +105,11 @@ func trimAnonymousFunctionSuffix(name string) string { return name } -// convertToLogFuncInfo take a runtime.Func and convert it to a logFuncInfo, fill in shorten filename, etc -func convertToLogFuncInfo(f *runtime.Func) *LogFuncInfo { +// 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 := &LogFuncInfo{ + info := &FuncInfo{ file: strings.ReplaceAll(file, "\\", "/"), line: line, name: f.Name(), @@ -132,8 +132,8 @@ func convertToLogFuncInfo(f *runtime.Func) *LogFuncInfo { return info } -func copyInfo(l *LogFuncInfo) *LogFuncInfo { - return &LogFuncInfo{ +func copyFuncInfo(l *FuncInfo) *FuncInfo { + return &FuncInfo{ file: l.file, shortFile: l.shortFile, line: l.line, @@ -155,8 +155,8 @@ func MarkLongPolling(resp http.ResponseWriter, req *http.Request) { record.isLongPolling = true } -// GetFuncInfo returns the LogFuncInfo for a provided function and friendlyname -func GetFuncInfo(fn interface{}, friendlyName ...string) *LogFuncInfo { +// 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() @@ -180,13 +180,13 @@ func GetFuncInfo(fn interface{}, friendlyName ...string) *LogFuncInfo { if ok { if len(friendlyName) == 1 { name := friendlyName[0] - info = copyInfo(info) + info = copyFuncInfo(info) info.shortName = name funcInfoNameMap[name] = info funcInfoMapMu.Lock() funcInfoNameMap[name] = info - funcInfoMapMu.Lock() + funcInfoMapMu.Unlock() } return info } @@ -196,7 +196,7 @@ func GetFuncInfo(fn interface{}, friendlyName ...string) *LogFuncInfo { // Get the runtime.func for this function (if we can) f := runtime.FuncForPC(ptr) if f != nil { - info = convertToLogFuncInfo(f) + info = convertToFuncInfo(f) // cache this info globally funcInfoMapMu.Lock() @@ -205,7 +205,7 @@ func GetFuncInfo(fn interface{}, friendlyName ...string) *LogFuncInfo { // if we have been provided with a friendlyName override the short name we've generated if len(friendlyName) == 1 { name := friendlyName[0] - info = copyInfo(info) + info = copyFuncInfo(info) info.shortName = name funcInfoNameMap[name] = info } @@ -215,7 +215,7 @@ func GetFuncInfo(fn interface{}, friendlyName ...string) *LogFuncInfo { } //UpdateContextHandler updates a context's func info by a real handler func `fn` -func UpdateContextHandler(ctx context.Context, funcInfo *LogFuncInfo) { +func UpdateContextHandler(ctx context.Context, funcInfo *FuncInfo) { record, ok := ctx.Value(contextKeyLogRequestRecord).(*logRequestRecord) if !ok { return From 142957faaa30ba236b32146681bc7952c3a9762b Mon Sep 17 00:00:00 2001 From: Andrew Thornton Date: Thu, 23 Dec 2021 01:41:56 +0000 Subject: [PATCH 17/29] ourHandlerFunc -> wrappedHandlerFunc Signed-off-by: Andrew Thornton --- modules/web/wrap.go | 4 ++-- modules/web/wrap_convert.go | 20 ++++++++++---------- 2 files changed, 12 insertions(+), 12 deletions(-) diff --git a/modules/web/wrap.go b/modules/web/wrap.go index fab7684bdbf8e..000cfe202e24e 100644 --- a/modules/web/wrap.go +++ b/modules/web/wrap.go @@ -18,7 +18,7 @@ func Wrap(handlers ...interface{}) http.HandlerFunc { panic("No handlers found") } - ourHandlers := make([]ourHandlerFunc, 0, len(handlers)) + ourHandlers := make([]wrappedHandlerFunc, 0, len(handlers)) for _, handler := range handlers { ourHandlers = append(ourHandlers, convertHandler(handler)) @@ -26,7 +26,7 @@ func Wrap(handlers ...interface{}) http.HandlerFunc { return wrapInternal(ourHandlers) } -func wrapInternal(handlers []ourHandlerFunc) http.HandlerFunc { +func wrapInternal(handlers []wrappedHandlerFunc) http.HandlerFunc { return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) { for i := 0; i < len(handlers); i++ { handler := handlers[i] diff --git a/modules/web/wrap_convert.go b/modules/web/wrap_convert.go index 33df0ee01e553..41af0562ba7f8 100644 --- a/modules/web/wrap_convert.go +++ b/modules/web/wrap_convert.go @@ -13,13 +13,13 @@ import ( "code.gitea.io/gitea/routers/common" ) -type ourHandlerFunc func(resp http.ResponseWriter, req *http.Request, others ...ourHandlerFunc) (done bool, deferable func()) +type wrappedHandlerFunc func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) -func convertHandler(handler interface{}) ourHandlerFunc { +func convertHandler(handler interface{}) wrappedHandlerFunc { funcInfo := common.GetFuncInfo(handler) switch t := handler.(type) { case http.HandlerFunc: - return func(resp http.ResponseWriter, req *http.Request, others ...ourHandlerFunc) (done bool, deferable func()) { + return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { common.UpdateContextHandler(req.Context(), funcInfo) t(resp, req) if r, ok := resp.(context.ResponseWriter); ok && r.Status() > 0 { @@ -28,7 +28,7 @@ func convertHandler(handler interface{}) ourHandlerFunc { return } case func(http.ResponseWriter, *http.Request): - return func(resp http.ResponseWriter, req *http.Request, others ...ourHandlerFunc) (done bool, deferable func()) { + return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { common.UpdateContextHandler(req.Context(), funcInfo) t(resp, req) if r, ok := resp.(context.ResponseWriter); ok && r.Status() > 0 { @@ -38,7 +38,7 @@ func convertHandler(handler interface{}) ourHandlerFunc { } case func(ctx *context.Context): - return func(resp http.ResponseWriter, req *http.Request, others ...ourHandlerFunc) (done bool, deferable func()) { + return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { common.UpdateContextHandler(req.Context(), funcInfo) ctx := context.GetContext(req) t(ctx) @@ -46,7 +46,7 @@ func convertHandler(handler interface{}) ourHandlerFunc { return } case func(ctx *context.Context) goctx.CancelFunc: - return func(resp http.ResponseWriter, req *http.Request, others ...ourHandlerFunc) (done bool, deferable func()) { + return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { common.UpdateContextHandler(req.Context(), funcInfo) ctx := context.GetContext(req) deferable = t(ctx) @@ -54,7 +54,7 @@ func convertHandler(handler interface{}) ourHandlerFunc { return } case func(*context.APIContext): - return func(resp http.ResponseWriter, req *http.Request, others ...ourHandlerFunc) (done bool, deferable func()) { + return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { common.UpdateContextHandler(req.Context(), funcInfo) ctx := context.GetAPIContext(req) t(ctx) @@ -62,7 +62,7 @@ func convertHandler(handler interface{}) ourHandlerFunc { return } case func(*context.PrivateContext): - return func(resp http.ResponseWriter, req *http.Request, others ...ourHandlerFunc) (done bool, deferable func()) { + return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { common.UpdateContextHandler(req.Context(), funcInfo) ctx := context.GetPrivateContext(req) t(ctx) @@ -70,7 +70,7 @@ func convertHandler(handler interface{}) ourHandlerFunc { return } case func(*context.PrivateContext) goctx.CancelFunc: - return func(resp http.ResponseWriter, req *http.Request, others ...ourHandlerFunc) (done bool, deferable func()) { + return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { common.UpdateContextHandler(req.Context(), funcInfo) ctx := context.GetPrivateContext(req) deferable = t(ctx) @@ -78,7 +78,7 @@ func convertHandler(handler interface{}) ourHandlerFunc { return } case func(http.Handler) http.Handler: - return func(resp http.ResponseWriter, req *http.Request, others ...ourHandlerFunc) (done bool, deferable func()) { + return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { var next = http.HandlerFunc(func(http.ResponseWriter, *http.Request) {}) if len(others) > 0 { next = wrapInternal(others) From e506e3ef46e33d41c38b53d65ec7c1573c147aa3 Mon Sep 17 00:00:00 2001 From: Andrew Thornton Date: Thu, 23 Dec 2021 01:48:21 +0000 Subject: [PATCH 18/29] move wrap to web Signed-off-by: Andrew Thornton --- modules/web/wrap.go | 20 +++++++++++++++++++- routers/common/logger_context.go | 16 ---------------- routers/install/routes.go | 2 +- routers/web/web.go | 2 +- 4 files changed, 21 insertions(+), 19 deletions(-) diff --git a/modules/web/wrap.go b/modules/web/wrap.go index 000cfe202e24e..67c6c826d98fe 100644 --- a/modules/web/wrap.go +++ b/modules/web/wrap.go @@ -7,6 +7,7 @@ package web import ( goctx "context" "net/http" + "strings" "code.gitea.io/gitea/modules/context" "code.gitea.io/gitea/routers/common" @@ -78,7 +79,7 @@ func MiddleCancel(f func(ctx *context.Context) goctx.CancelFunc) func(netx http. } // MiddleAPI wrap a context function as a chi middleware -func MiddleAPI(f func(ctx *context.APIContext)) func(netx http.Handler) http.Handler { +func MiddleAPI(f func(ctx *context.APIContext)) func(next http.Handler) http.Handler { funcInfo := common.GetFuncInfo(f) return func(next http.Handler) http.Handler { return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) { @@ -92,3 +93,20 @@ func MiddleAPI(f func(ctx *context.APIContext)) func(netx http.Handler) http.Han }) } } + +// 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 := common.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 + } + common.UpdateContextHandler(req.Context(), funcInfo) + handler(resp, req) + }) + } + +} diff --git a/routers/common/logger_context.go b/routers/common/logger_context.go index 49919b179b8f7..67c25fcb0c10c 100644 --- a/routers/common/logger_context.go +++ b/routers/common/logger_context.go @@ -228,22 +228,6 @@ func UpdateContextHandler(ctx context.Context, funcInfo *FuncInfo) { } -// WrapContextHandler wraps a log context handler for a router handler -func WrapContextHandler(pathPrefix string, handler http.HandlerFunc, friendlyName ...string) func(next http.Handler) http.Handler { - funcInfo := 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 - } - UpdateContextHandler(req.Context(), funcInfo) - handler(resp, req) - }) - } -} - //UpdateContextHandlerPanicError updates a context's error info, a panic may be recovered by other middlewares, but we still need to know that. func UpdateContextHandlerPanicError(ctx context.Context, err interface{}) { if reqRec, ok := ctx.Value(contextKeyLogRequestRecord).(*logRequestRecord); ok { diff --git a/routers/install/routes.go b/routers/install/routes.go index 2e9cce294aa51..d7d8527cf5e63 100644 --- a/routers/install/routes.go +++ b/routers/install/routes.go @@ -85,7 +85,7 @@ func Routes() *web.Route { r.Use(middle) } - r.Use(common.WrapContextHandler(public.AssetsURLPathPrefix, public.AssetsHandlerFunc(&public.Options{ + r.Use(web.WrapWithPrefix(public.AssetsURLPathPrefix, public.AssetsHandlerFunc(&public.Options{ Directory: path.Join(setting.StaticRootPath, "public"), Prefix: public.AssetsURLPathPrefix, }), "InstallAssetsHandler")) diff --git a/routers/web/web.go b/routers/web/web.go index 1c1c7447f6f0b..dabc03ee1c1ef 100644 --- a/routers/web/web.go +++ b/routers/web/web.go @@ -74,7 +74,7 @@ func CorsHandler() func(next http.Handler) http.Handler { func Routes(sessioner func(http.Handler) http.Handler) *web.Route { routes := web.NewRoute() - routes.Use(common.WrapContextHandler(public.AssetsURLPathPrefix, public.AssetsHandlerFunc(&public.Options{ + routes.Use(web.WrapWithPrefix(public.AssetsURLPathPrefix, public.AssetsHandlerFunc(&public.Options{ Directory: path.Join(setting.StaticRootPath, "public"), Prefix: public.AssetsURLPathPrefix, CorsHandler: CorsHandler(), From 4836f06b24478ff2d6b39f23a10ce6f03fdaaacc Mon Sep 17 00:00:00 2001 From: Andrew Thornton Date: Thu, 23 Dec 2021 02:13:11 +0000 Subject: [PATCH 19/29] Remove IsEnabledOn Signed-off-by: Andrew Thornton --- modules/log/level_test.go | 10 ---------- routers/common/logger_v2.go | 2 +- 2 files changed, 1 insertion(+), 11 deletions(-) diff --git a/modules/log/level_test.go b/modules/log/level_test.go index e8c0b9c683bc5..47f77738c5f14 100644 --- a/modules/log/level_test.go +++ b/modules/log/level_test.go @@ -54,13 +54,3 @@ func TestLevelMarshalUnmarshalJSON(t *testing.T) { func makeTestLevelBytes(level string) []byte { return []byte(fmt.Sprintf(`{"level":"%s"}`, level)) } - -func TestLevelIsEnabled(t *testing.T) { - assert.True(t, INFO.IsEnabledOn(DEBUG)) - assert.True(t, INFO.IsEnabledOn(INFO)) - assert.False(t, INFO.IsEnabledOn(ERROR)) - - assert.False(t, ERROR.IsEnabledOn(NONE)) - assert.False(t, NONE.IsEnabledOn(ERROR)) - assert.False(t, NONE.IsEnabledOn(NONE)) -} diff --git a/routers/common/logger_v2.go b/routers/common/logger_v2.go index fa0d1d759ae81..17f5e90e25635 100644 --- a/routers/common/logger_v2.go +++ b/routers/common/logger_v2.go @@ -29,7 +29,7 @@ func NewLoggerHandlerV2() func(next http.Handler) http.Handler { lh.startSlowQueryDetector(3 * time.Second) lh.printLog = func(trigger LogRequestTrigger, reqRec *logRequestRecord) { - if trigger == LogRequestStart && !log.DEBUG.IsEnabledOn(setting.RouterLogLevel) { + if trigger == LogRequestStart && setting.RouterLogLevel > log.DEBUG { // for performance, if the START message shouldn't be logged, we just return as early as possible // developers could set both `log.LEVEL=debug` and `log.ROUTER_LOG_LEVEL=debug` to get the "started" request messages. return From bf085384bb9fdb105a5f3686fdbe6855d0194201 Mon Sep 17 00:00:00 2001 From: Andrew Thornton Date: Thu, 23 Dec 2021 03:17:58 +0000 Subject: [PATCH 20/29] Move the requestrecord infrastructure to modules/web/routing Signed-off-by: Andrew Thornton --- modules/log/level.go | 6 - modules/web/routing/context.go | 52 +++ modules/web/routing/funcinfo.go | 162 +++++++++ .../web/routing/funcinfo_test.go | 2 +- .../web/routing/logger_v1.go | 2 +- modules/web/routing/logger_v2.go | 97 ++++++ modules/web/routing/logger_v2_manager.go | 122 +++++++ modules/web/routing/requestrecord.go | 29 ++ modules/web/wrap.go | 18 +- modules/web/wrap_convert.go | 20 +- routers/common/logger_context.go | 316 ------------------ routers/common/logger_v2.go | 98 ------ routers/common/middleware.go | 9 +- routers/web/base.go | 10 +- routers/web/web.go | 4 +- 15 files changed, 495 insertions(+), 452 deletions(-) create mode 100644 modules/web/routing/context.go create mode 100644 modules/web/routing/funcinfo.go rename routers/common/logger_context_test.go => modules/web/routing/funcinfo_test.go (98%) rename routers/common/logger.go => modules/web/routing/logger_v1.go (98%) create mode 100644 modules/web/routing/logger_v2.go create mode 100644 modules/web/routing/logger_v2_manager.go create mode 100644 modules/web/routing/requestrecord.go delete mode 100644 routers/common/logger_context.go delete mode 100644 routers/common/logger_v2.go diff --git a/modules/log/level.go b/modules/log/level.go index 4420f73584961..5964ed8f8b956 100644 --- a/modules/log/level.go +++ b/modules/log/level.go @@ -74,12 +74,6 @@ func (l Level) String() string { return "info" } -// IsEnabledOn checks whether the log level is enabled on targetLevel. -// eg: INFO logs are enabled (outputted) on DEBUG / INFO, but not WARN / ERROR -func (l Level) IsEnabledOn(targetLevel Level) bool { - return l >= targetLevel && l != NONE -} - // Color returns the color string for this Level func (l Level) Color() *[]byte { color, ok := levelToColor[l] diff --git a/modules/web/routing/context.go b/modules/web/routing/context.go new file mode 100644 index 0000000000000..0059129f2c954 --- /dev/null +++ b/modules/web/routing/context.go @@ -0,0 +1,52 @@ +// 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 contextKeyStruct struct{} + +var contextKey contextKeyStruct + +//UpdateFuncInfo updates a context's func info +func UpdateFuncInfo(ctx context.Context, funcInfo *FuncInfo) { + record, ok := ctx.Value(contextKey).(*requestRecord) + if !ok { + return + } + + // update our current record + 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() +} diff --git a/modules/web/routing/funcinfo.go b/modules/web/routing/funcinfo.go new file mode 100644 index 0000000000000..a3ee8a59d1c79 --- /dev/null +++ b/modules/web/routing/funcinfo.go @@ -0,0 +1,162 @@ +// 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 ( + "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 +} + +// 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 +} diff --git a/routers/common/logger_context_test.go b/modules/web/routing/funcinfo_test.go similarity index 98% rename from routers/common/logger_context_test.go rename to modules/web/routing/funcinfo_test.go index 2f12cc557ffe5..9cea7e2817891 100644 --- a/routers/common/logger_context_test.go +++ b/modules/web/routing/funcinfo_test.go @@ -2,7 +2,7 @@ // Use of this source code is governed by a MIT-style // license that can be found in the LICENSE file. -package common +package routing import ( "fmt" diff --git a/routers/common/logger.go b/modules/web/routing/logger_v1.go similarity index 98% rename from routers/common/logger.go rename to modules/web/routing/logger_v1.go index fd39e070d549e..10d57903e39c0 100644 --- a/routers/common/logger.go +++ b/modules/web/routing/logger_v1.go @@ -2,7 +2,7 @@ // Use of this source code is governed by a MIT-style // license that can be found in the LICENSE file. -package common +package routing import ( "net/http" diff --git a/modules/web/routing/logger_v2.go b/modules/web/routing/logger_v2.go new file mode 100644 index 0000000000000..4ccdb2e38e6a5 --- /dev/null +++ b/modules/web/routing/logger_v2.go @@ -0,0 +1,97 @@ +// 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" + "net/http" + "time" + + "code.gitea.io/gitea/modules/context" + "code.gitea.io/gitea/modules/log" + "code.gitea.io/gitea/modules/setting" +) + +// NewLoggerHandlerV2 is a handler that will log routing to the router log taking account of +// routing information +func NewLoggerHandlerV2() 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 +} + +func logPrinter(logger log.Logger) func(trigger Event, record *requestRecord) { + return func(trigger Event, record *requestRecord) { + if trigger == StartEvent && setting.RouterLogLevel > log.DEBUG { + // for performance, if the START message shouldn't be logged, we just return as early as possible + // developers could set both `log.LEVEL=debug` and `log.ROUTER_LOG_LEVEL=debug` to get the "started" request messages. + return + } + + shortFilename := "" + line := 0 + shortName := "" + + record.lock.RLock() + isLongPolling := record.isLongPolling + if record.funcInfo != nil { + shortFilename, line, shortName = record.funcInfo.shortFile, record.funcInfo.line, record.funcInfo.shortName + } else { + // we might not find all handlers, so if a handler has not called `UpdateFuncInfo`, we won't know its information + // in such case, we should debug to find what handler it is and use `UpdateFuncInfo` to report its information + shortFilename = "unknown-handler" + } + record.lock.RUnlock() + + req := record.request + + if trigger == StartEvent { + // when a request starts, we have no information about the handler function information, we only have the request path + logger.Debug("router: started %v %s for %s", log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr) + return + } + + handlerFuncInfo := fmt.Sprintf("%s:%d(%s)", shortFilename, line, shortName) + if trigger == StillExecutingEvent { + message := "still-executing" + level := log.WARN + if isLongPolling { + level = log.INFO + message = "long-polling" + } + _ = 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, + ) + } else { + if record.panicError != nil { + logger.Warn("router: failed %v %s for %s, panic in %v @ %s, err=%v", + shortFilename, line, shortName, + log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr, + log.ColoredTime(time.Since(record.startTime)), + handlerFuncInfo, + record.panicError, + ) + } else { + var status int + if v, ok := record.responseWriter.(context.ResponseWriter); ok { + status = v.Status() + } + logger.Info("router: completed %v %s for %s, %v %v in %v @ %s", + 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_v2_manager.go b/modules/web/routing/logger_v2_manager.go new file mode 100644 index 0000000000000..f5262497dce04 --- /dev/null +++ b/modules/web/routing/logger_v2_manager.go @@ -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.5ms 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) + }) +} diff --git a/modules/web/routing/requestrecord.go b/modules/web/routing/requestrecord.go new file mode 100644 index 0000000000000..5e225f32e4e4e --- /dev/null +++ b/modules/web/routing/requestrecord.go @@ -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{} +} diff --git a/modules/web/wrap.go b/modules/web/wrap.go index 67c6c826d98fe..1be5d3dafa22e 100644 --- a/modules/web/wrap.go +++ b/modules/web/wrap.go @@ -10,7 +10,7 @@ import ( "strings" "code.gitea.io/gitea/modules/context" - "code.gitea.io/gitea/routers/common" + "code.gitea.io/gitea/modules/web/routing" ) // Wrap converts all kinds of routes to standard library one @@ -45,10 +45,10 @@ func wrapInternal(handlers []wrappedHandlerFunc) http.HandlerFunc { // Middle wrap a context function as a chi middleware func Middle(f func(ctx *context.Context)) func(netx http.Handler) http.Handler { - funcInfo := common.GetFuncInfo(f) + funcInfo := routing.GetFuncInfo(f) return func(next http.Handler) http.Handler { return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) { - common.UpdateContextHandler(req.Context(), funcInfo) + routing.UpdateFuncInfo(req.Context(), funcInfo) ctx := context.GetContext(req) f(ctx) if ctx.Written() { @@ -61,10 +61,10 @@ func Middle(f func(ctx *context.Context)) func(netx http.Handler) http.Handler { // 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 := common.GetFuncInfo(f) + funcInfo := routing.GetFuncInfo(f) return func(next http.Handler) http.Handler { return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) { - common.UpdateContextHandler(req.Context(), funcInfo) + routing.UpdateFuncInfo(req.Context(), funcInfo) ctx := context.GetContext(req) cancel := f(ctx) if cancel != nil { @@ -80,10 +80,10 @@ func MiddleCancel(f func(ctx *context.Context) goctx.CancelFunc) func(netx http. // MiddleAPI wrap a context function as a chi middleware func MiddleAPI(f func(ctx *context.APIContext)) func(next http.Handler) http.Handler { - funcInfo := common.GetFuncInfo(f) + funcInfo := routing.GetFuncInfo(f) return func(next http.Handler) http.Handler { return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) { - common.UpdateContextHandler(req.Context(), funcInfo) + routing.UpdateFuncInfo(req.Context(), funcInfo) ctx := context.GetAPIContext(req) f(ctx) if ctx.Written() { @@ -96,7 +96,7 @@ func MiddleAPI(f func(ctx *context.APIContext)) func(next http.Handler) http.Han // 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 := common.GetFuncInfo(handler, friendlyName...) + funcInfo := routing.GetFuncInfo(handler, friendlyName...) return func(next http.Handler) http.Handler { return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) { @@ -104,7 +104,7 @@ func WrapWithPrefix(pathPrefix string, handler http.HandlerFunc, friendlyName .. next.ServeHTTP(resp, req) return } - common.UpdateContextHandler(req.Context(), funcInfo) + routing.UpdateFuncInfo(req.Context(), funcInfo) handler(resp, req) }) } diff --git a/modules/web/wrap_convert.go b/modules/web/wrap_convert.go index 41af0562ba7f8..2f085a78c9fc1 100644 --- a/modules/web/wrap_convert.go +++ b/modules/web/wrap_convert.go @@ -10,17 +10,17 @@ import ( "net/http" "code.gitea.io/gitea/modules/context" - "code.gitea.io/gitea/routers/common" + "code.gitea.io/gitea/modules/web/routing" ) type wrappedHandlerFunc func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) func convertHandler(handler interface{}) wrappedHandlerFunc { - funcInfo := common.GetFuncInfo(handler) + funcInfo := routing.GetFuncInfo(handler) switch t := handler.(type) { case http.HandlerFunc: return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { - common.UpdateContextHandler(req.Context(), funcInfo) + routing.UpdateFuncInfo(req.Context(), funcInfo) t(resp, req) if r, ok := resp.(context.ResponseWriter); ok && r.Status() > 0 { done = true @@ -29,7 +29,7 @@ func convertHandler(handler interface{}) wrappedHandlerFunc { } case func(http.ResponseWriter, *http.Request): return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { - common.UpdateContextHandler(req.Context(), funcInfo) + routing.UpdateFuncInfo(req.Context(), funcInfo) t(resp, req) if r, ok := resp.(context.ResponseWriter); ok && r.Status() > 0 { done = true @@ -39,7 +39,7 @@ func convertHandler(handler interface{}) wrappedHandlerFunc { case func(ctx *context.Context): return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { - common.UpdateContextHandler(req.Context(), funcInfo) + routing.UpdateFuncInfo(req.Context(), funcInfo) ctx := context.GetContext(req) t(ctx) done = ctx.Written() @@ -47,7 +47,7 @@ func convertHandler(handler interface{}) wrappedHandlerFunc { } case func(ctx *context.Context) goctx.CancelFunc: return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { - common.UpdateContextHandler(req.Context(), funcInfo) + routing.UpdateFuncInfo(req.Context(), funcInfo) ctx := context.GetContext(req) deferable = t(ctx) done = ctx.Written() @@ -55,7 +55,7 @@ func convertHandler(handler interface{}) wrappedHandlerFunc { } case func(*context.APIContext): return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { - common.UpdateContextHandler(req.Context(), funcInfo) + routing.UpdateFuncInfo(req.Context(), funcInfo) ctx := context.GetAPIContext(req) t(ctx) done = ctx.Written() @@ -63,7 +63,7 @@ func convertHandler(handler interface{}) wrappedHandlerFunc { } case func(*context.PrivateContext): return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { - common.UpdateContextHandler(req.Context(), funcInfo) + routing.UpdateFuncInfo(req.Context(), funcInfo) ctx := context.GetPrivateContext(req) t(ctx) done = ctx.Written() @@ -71,7 +71,7 @@ func convertHandler(handler interface{}) wrappedHandlerFunc { } case func(*context.PrivateContext) goctx.CancelFunc: return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { - common.UpdateContextHandler(req.Context(), funcInfo) + routing.UpdateFuncInfo(req.Context(), funcInfo) ctx := context.GetPrivateContext(req) deferable = t(ctx) done = ctx.Written() @@ -83,7 +83,7 @@ func convertHandler(handler interface{}) wrappedHandlerFunc { if len(others) > 0 { next = wrapInternal(others) } - common.UpdateContextHandler(req.Context(), funcInfo) + routing.UpdateFuncInfo(req.Context(), funcInfo) t(next).ServeHTTP(resp, req) return } diff --git a/routers/common/logger_context.go b/routers/common/logger_context.go deleted file mode 100644 index 67c25fcb0c10c..0000000000000 --- a/routers/common/logger_context.go +++ /dev/null @@ -1,316 +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 ( - "context" - "net/http" - "reflect" - "runtime" - "strings" - "sync" - "time" - - "code.gitea.io/gitea/modules/graceful" -) - -// LogRequestTrigger indicates when the logger is triggered -type LogRequestTrigger int - -const ( - //LogRequestStart at the beginning of a request - LogRequestStart LogRequestTrigger = iota - - //LogRequestExecuting the request is still executing - LogRequestExecuting - - //LogRequestOver the request is over (either completed or failed) - LogRequestOver -) - -// LogPrinter is used to output the log for a request -type LogPrinter func(trigger LogRequestTrigger, reqRec *logRequestRecord) - -type logRequestRecord struct { - recordIndex uint64 - startTime time.Time - isLongPolling bool - httpRequest *http.Request - responseWriter http.ResponseWriter - funcInfo *FuncInfo - funcInfoMu sync.RWMutex - panicError interface{} -} - -type logContextHandler struct { - printLog LogPrinter - requestRecordMap map[uint64]*logRequestRecord - requestRecordMapMu sync.Mutex - reqRecordCount uint64 -} - -// 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 -} - -var funcInfoMap = map[uintptr]*FuncInfo{} -var funcInfoNameMap = map[string]*FuncInfo{} -var funcInfoMapMu sync.RWMutex - -// 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 -} - -// 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, - } -} - -type contextKeyLogRequestRecordStruct struct{} - -var contextKeyLogRequestRecord contextKeyLogRequestRecordStruct - -// 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(contextKeyLogRequestRecord).(*logRequestRecord) - if !ok { - return - } - record.isLongPolling = true -} - -// 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 -} - -//UpdateContextHandler updates a context's func info by a real handler func `fn` -func UpdateContextHandler(ctx context.Context, funcInfo *FuncInfo) { - record, ok := ctx.Value(contextKeyLogRequestRecord).(*logRequestRecord) - if !ok { - return - } - - // update our current record - record.funcInfoMu.Lock() - record.funcInfo = funcInfo - record.funcInfoMu.Unlock() - -} - -//UpdateContextHandlerPanicError updates a context's error info, a panic may be recovered by other middlewares, but we still need to know that. -func UpdateContextHandlerPanicError(ctx context.Context, err interface{}) { - if reqRec, ok := ctx.Value(contextKeyLogRequestRecord).(*logRequestRecord); ok { - reqRec.panicError = err - } -} - -func (lh *logContextHandler) 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.5ms are all OK. - t := time.NewTicker(time.Second) - for { - select { - case <-baseCtx.Done(): - return - case <-t.C: - now := time.Now() - - var slowRequests []*logRequestRecord - - // find all slow requests with lock - lh.requestRecordMapMu.Lock() - for index, reqRecord := range lh.requestRecordMap { - if now.Sub(reqRecord.startTime) < threshold { - continue - } - - slowRequests = append(slowRequests, reqRecord) - delete(lh.requestRecordMap, index) - } - lh.requestRecordMapMu.Unlock() - - // print logs for slow requests - for _, reqRecord := range slowRequests { - lh.printLog(LogRequestExecuting, reqRecord) - } - } - } - }) -} - -func (lh *logContextHandler) handler(next http.Handler) http.Handler { - return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { - record := &logRequestRecord{ - startTime: time.Now(), - httpRequest: req, - responseWriter: w, - } - - // generate a record index an insert into the map - lh.requestRecordMapMu.Lock() - record.recordIndex = lh.reqRecordCount - lh.reqRecordCount++ - lh.requestRecordMap[record.recordIndex] = record - lh.requestRecordMapMu.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.panicError = localPanicErr - } - - // remove from the record map - lh.requestRecordMapMu.Lock() - delete(lh.requestRecordMap, record.recordIndex) - lh.requestRecordMapMu.Unlock() - - // log the end of the request - lh.printLog(LogRequestOver, 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(), contextKeyLogRequestRecord, record)) - lh.printLog(LogRequestStart, record) - next.ServeHTTP(w, req) - }) -} diff --git a/routers/common/logger_v2.go b/routers/common/logger_v2.go deleted file mode 100644 index 17f5e90e25635..0000000000000 --- a/routers/common/logger_v2.go +++ /dev/null @@ -1,98 +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 ( - "fmt" - "net/http" - "time" - - gitea_context "code.gitea.io/gitea/modules/context" - "code.gitea.io/gitea/modules/log" - "code.gitea.io/gitea/modules/setting" -) - -// NewLoggerHandlerV2 is a handler that will log the routing to the default gitea log -// About performance: -// In v1, every request outputs 2 logs (Started/Completed) -// In v2 (this), every request only outputs one log, -// all runtime reflections of handler functions are cached -// the mutexes work in fast path for most cases (atomic incr) because there is seldom concurrency writings. -// So generally speaking, the `logger context` doesn't cost much, using v2 with `logger context` will not affect performance -// Instead, the performance may be improved because now only 1 log is outputted for each request. -func NewLoggerHandlerV2() func(next http.Handler) http.Handler { - lh := logContextHandler{ - requestRecordMap: map[uint64]*logRequestRecord{}, - } - lh.startSlowQueryDetector(3 * time.Second) - - lh.printLog = func(trigger LogRequestTrigger, reqRec *logRequestRecord) { - if trigger == LogRequestStart && setting.RouterLogLevel > log.DEBUG { - // for performance, if the START message shouldn't be logged, we just return as early as possible - // developers could set both `log.LEVEL=debug` and `log.ROUTER_LOG_LEVEL=debug` to get the "started" request messages. - return - } - - funcFileShort := "" - funcLine := 0 - funcNameShort := "" - reqRec.funcInfoMu.RLock() - isLongPolling := reqRec.isLongPolling - if reqRec.funcInfo != nil { - funcFileShort, funcLine, funcNameShort = reqRec.funcInfo.shortFile, reqRec.funcInfo.line, reqRec.funcInfo.shortName - } else { - // we might not find all handlers, so if a handler is not processed by our `UpdateContextHandler`, we won't know its information - // in such case, we should debug to find what handler it is and use `UpdateContextHandler` to report its information - funcFileShort = "unknown-handler" - } - reqRec.funcInfoMu.RUnlock() - - logger := log.GetLogger("router") - req := reqRec.httpRequest - if trigger == LogRequestStart { - // when a request starts, we have no information about the handler function information, we only have the request path - _ = logger.Log(0, log.DEBUG, "router: started %v %s for %s", log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr) - return - } - - handlerFuncInfo := fmt.Sprintf("%s:%d(%s)", funcFileShort, funcLine, funcNameShort) - if trigger == LogRequestExecuting { - message := "still-executing" - level := log.WARN - if isLongPolling { - level = log.INFO - message = "long-polling" - } - _ = 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(reqRec.startTime)), - handlerFuncInfo, - ) - } else { - if reqRec.panicError != nil { - _ = logger.Log(0, log.WARN, "router: failed %v %s for %s, panic in %v @ %s, err=%v", - funcFileShort, funcLine, funcNameShort, - log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr, - log.ColoredTime(time.Since(reqRec.startTime)), - handlerFuncInfo, - reqRec.panicError, - ) - } else { - var status int - if v, ok := reqRec.responseWriter.(gitea_context.ResponseWriter); ok { - status = v.Status() - } - _ = logger.Log(0, log.INFO, "router: completed %v %s for %s, %v %v in %v @ %s", - log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr, - log.ColoredStatus(status), log.ColoredStatus(status, http.StatusText(status)), log.ColoredTime(time.Since(reqRec.startTime)), - handlerFuncInfo, - ) - } - } - } - - return lh.handler -} diff --git a/routers/common/middleware.go b/routers/common/middleware.go index 7b70e110c66bf..d3faaec8adebb 100644 --- a/routers/common/middleware.go +++ b/routers/common/middleware.go @@ -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,13 +50,13 @@ func Middlewares() []func(http.Handler) http.Handler { if !setting.DisableRouterLog { var routerLogHandler func(http.Handler) http.Handler if setting.RouterLogHandler == "v1" { - routerLogHandler = NewLoggerHandlerV1(setting.RouterLogLevel) + routerLogHandler = routing.NewLoggerHandlerV1(setting.RouterLogLevel) } else if setting.RouterLogHandler == "v2" { - routerLogHandler = NewLoggerHandlerV2() + routerLogHandler = routing.NewLoggerHandlerV2() } if routerLogHandler == nil { log.Warn("unknown router log handler '%s', fall back to v2") - routerLogHandler = NewLoggerHandlerV2() + routerLogHandler = routing.NewLoggerHandlerV2() } handlers = append(handlers, routerLogHandler) } @@ -71,7 +72,7 @@ func Middlewares() []func(http.Handler) http.Handler { // and send a simple error page that should not panic anymore. defer func() { if err := recover(); err != nil { - UpdateContextHandlerPanicError(req.Context(), err) + routing.UpdatePanicError(req.Context(), err) combinedErr := fmt.Sprintf("PANIC: %v\n%s", err, log.Stack(2)) log.Error("%v", combinedErr) if setting.IsProd { diff --git a/routers/web/base.go b/routers/web/base.go index 512c5e7d35a85..fd942d3c87861 100644 --- a/routers/web/base.go +++ b/routers/web/base.go @@ -21,14 +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/routers/common" + "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 := common.GetFuncInfo(storageHandler, prefix) + 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) { @@ -41,7 +41,7 @@ func storageHandler(storageSetting setting.Storage, prefix string, objStore stor next.ServeHTTP(w, req) return } - common.UpdateContextHandler(req.Context(), funcInfo) + routing.UpdateFuncInfo(req.Context(), funcInfo) rPath := strings.TrimPrefix(req.URL.RequestURI(), "/"+prefix) u, err := objStore.URL(rPath, path.Base(rPath)) @@ -76,7 +76,7 @@ func storageHandler(storageSetting setting.Storage, prefix string, objStore stor next.ServeHTTP(w, req) return } - common.UpdateContextHandler(req.Context(), funcInfo) + routing.UpdateFuncInfo(req.Context(), funcInfo) rPath := strings.TrimPrefix(req.URL.EscapedPath(), "/"+prefix+"/") rPath = strings.TrimPrefix(rPath, "/") @@ -130,7 +130,7 @@ 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 { - common.UpdateContextHandlerPanicError(req.Context(), err) + routing.UpdatePanicError(req.Context(), err) combinedErr := fmt.Sprintf("PANIC: %v\n%s", err, log.Stack(2)) log.Error("%s", combinedErr) diff --git a/routers/web/web.go b/routers/web/web.go index dabc03ee1c1ef..e244da59d13cc 100644 --- a/routers/web/web.go +++ b/routers/web/web.go @@ -22,8 +22,8 @@ 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/common" "code.gitea.io/gitea/routers/web/admin" "code.gitea.io/gitea/routers/web/dev" "code.gitea.io/gitea/routers/web/events" @@ -298,7 +298,7 @@ func RegisterRoutes(m *web.Route) { }) }, reqSignOut) - m.Any("/user/events", common.MarkLongPolling, events.Events) + m.Any("/user/events", routing.MarkLongPolling, events.Events) m.Group("/login/oauth", func() { m.Get("/authorize", bindIgnErr(forms.AuthorizationForm{}), user.AuthorizeOAuth) From 37d79284b2b576d6c9373b801fb43cdb6ba4725e Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Thu, 23 Dec 2021 14:22:51 +0800 Subject: [PATCH 21/29] fix comment for logger v1 --- modules/web/routing/logger_v1.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/modules/web/routing/logger_v1.go b/modules/web/routing/logger_v1.go index 10d57903e39c0..999802ae39a0b 100644 --- a/modules/web/routing/logger_v1.go +++ b/modules/web/routing/logger_v1.go @@ -12,7 +12,7 @@ import ( "code.gitea.io/gitea/modules/log" ) -// NewLoggerHandlerV1 is a handler that will log the routing to the default gitea log +// NewLoggerHandlerV1 is a handler that will log the routing logs func NewLoggerHandlerV1(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) { From 6d14aacefe68ffca85efc32db0844b73c1255256 Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Thu, 23 Dec 2021 16:10:58 +0800 Subject: [PATCH 22/29] Improve app.example.ini and document, refactor wrap and router logger --- custom/conf/app.example.ini | 15 ++++++------- .../doc/advanced/config-cheat-sheet.en-us.md | 17 ++++++++------ .../advanced/logging-documentation.en-us.md | 4 +--- modules/setting/log.go | 4 ++-- modules/setting/setting.go | 14 +++++++----- modules/web/routing/logger_v2.go | 10 ++++----- modules/web/wrap.go | 19 ++++++++++------ modules/web/wrap_convert.go | 22 +++++++++---------- routers/common/middleware.go | 6 ++--- 9 files changed, 59 insertions(+), 52 deletions(-) diff --git a/custom/conf/app.example.ini b/custom/conf/app.example.ini index 6550d1773e766..e29064a9d19b5 100644 --- a/custom/conf/app.example.ini +++ b/custom/conf/app.example.ini @@ -454,32 +454,31 @@ TRUSTED_FACETS = ; 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 +;; The log level that the router should log at. (If you are setting the access log, it's recommended to place this at Debug.) ;ROUTER_LOG_LEVEL = Info ;; -;; The handler for router logs, it controls the router log format, mainly for debug purpose -;; For v2 (1.16 and later), developers could set both `LEVEL=Debug` and `ROUTER_LOG_LEVEL=Debug` to get the "started" request messages -;ROUTER_LOG_HANDLER = v2 +;; The handler for router logs, it controls the router log format, mainly for debug purpose, two log handlers: +;; router_logger_v1: default for before 1.16 +;; router_logger_v2: default for 1.16 and later. Developers could set both `LEVEL=Debug` to get the "started" router messages +;ROUTER_LOG_HANDLER = router_logger_v2 ;; ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; ;; ;; 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 ;; ;; Sets the template used to create the access log. ;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}}" diff --git a/docs/content/doc/advanced/config-cheat-sheet.en-us.md b/docs/content/doc/advanced/config-cheat-sheet.en-us.md index 74460086f8e7d..ee2b63ffe05a0 100644 --- a/docs/content/doc/advanced/config-cheat-sheet.en-us.md +++ b/docs/content/doc/advanced/config-cheat-sheet.en-us.md @@ -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. @@ -751,13 +750,18 @@ 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, it's recommended to place this at Debug.) -- `ROUTER_LOG_HANDLER`: **v2**: The log handler that controls the log output format. Before 1.16 the router logs are outputted by handler `v1`. From 1.16, the default handler is `v2` which is more meaningful and friendly. +- `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\]`. + 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\]`. +- `ROUTER_LOG_LEVEL`: **Info**: The log level that the router should log at. (If you are setting the access log, it's recommended to place this at Debug.) +- `ROUTER_LOG_HANDLER`: **router_logger_v2**: The log handler that controls the log output format. Before 1.16 the router logs are outputted by handler `router_logger_v1`. From 1.16, the default handler is `router_logger_v2` which is more meaningful and friendly. + +### Access Log (`log`) - `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 -- `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: - `Ctx`: the `context.Context` of the request. @@ -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.*`) diff --git a/docs/content/doc/advanced/logging-documentation.en-us.md b/docs/content/doc/advanced/logging-documentation.en-us.md index cf9603d1fb323..21fef1fb81325 100644 --- a/docs/content/doc/advanced/logging-documentation.en-us.md +++ b/docs/content/doc/advanced/logging-documentation.en-us.md @@ -107,9 +107,7 @@ should be taken when changing its template. The main benefit of this logger is that Gitea can now log accesses in a standard log format so standard tools may be used. -You can enable this logger using `ENABLE_ACCESS_LOG`. Its outputs are -configured by setting the `ACCESS` value in the `[log]` section of the -configuration. `ACCESS` defaults to `file` if unset. +You can enable this logger using `ENABLE_ACCESS_LOG`. Each output sublogger for this logger is configured in `[log.sublogger.access]` sections. There are certain default values diff --git a/modules/setting/log.go b/modules/setting/log.go index a32570044de86..ef902cfdc09d3 100644 --- a/modules/setting/log.go +++ b/modules/setting/log.go @@ -255,8 +255,8 @@ 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}}"`, + ) if EnableAccessLog { options := newDefaultLogOptions() options.filename = filepath.Join(LogRootPath, "access.log") diff --git a/modules/setting/setting.go b/modules/setting/setting.go index 148a44096a483..51c0f7e7af89d 100644 --- a/modules/setting/setting.go +++ b/modules/setting/setting.go @@ -334,14 +334,16 @@ var ( LogLevel log.Level StacktraceLogLevel string LogRootPath string - DisableRouterLog bool - RouterLogLevel log.Level - RouterLogHandler string - EnableAccessLog bool EnableSSHLog bool - AccessLogTemplate string EnableXORMLog bool + DisableRouterLog bool + RouterLogLevel log.Level + RouterLogHandler string + + EnableAccessLog bool + AccessLogTemplate string + // Time settings TimeFormat string // UILocation is the location on the UI, so that we can display the time on UI. @@ -605,7 +607,7 @@ func loadFromConf(allowEmpty bool, extraConfig string) { 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")) - RouterLogHandler = Cfg.Section("log").Key("ROUTER_LOG_HANDLER").MustString("v2") + RouterLogHandler = Cfg.Section("log").Key("ROUTER_LOG_HANDLER").MustString("router_logger_v2") sec := Cfg.Section("server") AppName = Cfg.Section("").Key("APP_NAME").MustString("Gitea: Git with a cup of tea") diff --git a/modules/web/routing/logger_v2.go b/modules/web/routing/logger_v2.go index 4ccdb2e38e6a5..b42cca06eeaef 100644 --- a/modules/web/routing/logger_v2.go +++ b/modules/web/routing/logger_v2.go @@ -29,9 +29,9 @@ func NewLoggerHandlerV2() func(next http.Handler) http.Handler { func logPrinter(logger log.Logger) func(trigger Event, record *requestRecord) { return func(trigger Event, record *requestRecord) { - if trigger == StartEvent && setting.RouterLogLevel > log.DEBUG { - // for performance, if the START message shouldn't be logged, we just return as early as possible - // developers could set both `log.LEVEL=debug` and `log.ROUTER_LOG_LEVEL=debug` to get the "started" request messages. + if trigger == StartEvent && setting.LogLevel > log.DEBUG { + // for performance, if the "started" message shouldn't be logged, we just return as early as possible + // developers could set both `log.LEVEL=Debug` to get the "started" request messages. return } @@ -74,7 +74,7 @@ func logPrinter(logger log.Logger) func(trigger Event, record *requestRecord) { ) } else { if record.panicError != nil { - logger.Warn("router: failed %v %s for %s, panic in %v @ %s, err=%v", + _ = logger.Log(0, log.WARN, "router: failed %v %s for %s, panic in %v @ %s, err=%v", shortFilename, line, shortName, log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr, log.ColoredTime(time.Since(record.startTime)), @@ -86,7 +86,7 @@ func logPrinter(logger log.Logger) func(trigger Event, record *requestRecord) { if v, ok := record.responseWriter.(context.ResponseWriter); ok { status = v.Status() } - logger.Info("router: completed %v %s for %s, %v %v in %v @ %s", + _ = logger.Log(0, setting.RouterLogLevel, "router: completed %v %s for %s, %v %v in %v @ %s", 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/wrap.go b/modules/web/wrap.go index 1be5d3dafa22e..b55b87606983a 100644 --- a/modules/web/wrap.go +++ b/modules/web/wrap.go @@ -28,23 +28,29 @@ func Wrap(handlers ...interface{}) http.HandlerFunc { } func wrapInternal(handlers []wrappedHandlerFunc) http.HandlerFunc { - return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) { + 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, deferable := handler(resp, req, others...) - if deferable != nil { - defer deferable() + 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(netx http.Handler) http.Handler { +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) { @@ -108,5 +114,4 @@ func WrapWithPrefix(pathPrefix string, handler http.HandlerFunc, friendlyName .. handler(resp, req) }) } - } diff --git a/modules/web/wrap_convert.go b/modules/web/wrap_convert.go index 2f085a78c9fc1..221a3c664ac4e 100644 --- a/modules/web/wrap_convert.go +++ b/modules/web/wrap_convert.go @@ -13,13 +13,13 @@ import ( "code.gitea.io/gitea/modules/web/routing" ) -type wrappedHandlerFunc func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) +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, deferable func()) { + 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 { @@ -28,7 +28,7 @@ func convertHandler(handler interface{}) wrappedHandlerFunc { return } case func(http.ResponseWriter, *http.Request): - return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { + 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 { @@ -38,7 +38,7 @@ func convertHandler(handler interface{}) wrappedHandlerFunc { } case func(ctx *context.Context): - return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { + 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) @@ -46,15 +46,15 @@ func convertHandler(handler interface{}) wrappedHandlerFunc { return } case func(ctx *context.Context) goctx.CancelFunc: - return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { + return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func()) { routing.UpdateFuncInfo(req.Context(), funcInfo) ctx := context.GetContext(req) - deferable = t(ctx) + deferrable = t(ctx) done = ctx.Written() return } case func(*context.APIContext): - return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { + 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) @@ -62,7 +62,7 @@ func convertHandler(handler interface{}) wrappedHandlerFunc { return } case func(*context.PrivateContext): - return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { + 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) @@ -70,15 +70,15 @@ func convertHandler(handler interface{}) wrappedHandlerFunc { return } case func(*context.PrivateContext) goctx.CancelFunc: - return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferable func()) { + return func(resp http.ResponseWriter, req *http.Request, others ...wrappedHandlerFunc) (done bool, deferrable func()) { routing.UpdateFuncInfo(req.Context(), funcInfo) ctx := context.GetPrivateContext(req) - deferable = t(ctx) + 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, deferable func()) { + 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) diff --git a/routers/common/middleware.go b/routers/common/middleware.go index d3faaec8adebb..81633dd149e12 100644 --- a/routers/common/middleware.go +++ b/routers/common/middleware.go @@ -49,13 +49,13 @@ func Middlewares() []func(http.Handler) http.Handler { if !setting.DisableRouterLog { var routerLogHandler func(http.Handler) http.Handler - if setting.RouterLogHandler == "v1" { + if setting.RouterLogHandler == "router_logger_v1" { routerLogHandler = routing.NewLoggerHandlerV1(setting.RouterLogLevel) - } else if setting.RouterLogHandler == "v2" { + } else if setting.RouterLogHandler == "router_logger_v2" { routerLogHandler = routing.NewLoggerHandlerV2() } if routerLogHandler == nil { - log.Warn("unknown router log handler '%s', fall back to v2") + log.Warn("unknown router log handler '%s', fall back to router_logger_v2") routerLogHandler = routing.NewLoggerHandlerV2() } handlers = append(handlers, routerLogHandler) From a284f30e4d6a8a3c5b3a3163b8bb4ee2aec0062d Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Thu, 23 Dec 2021 16:26:08 +0800 Subject: [PATCH 23/29] fix documents and comments --- docs/content/doc/advanced/logging-documentation.en-us.md | 4 ++-- modules/log/colors_router.go | 2 +- modules/web/routing/context.go | 5 ++--- modules/web/routing/logger_v2_manager.go | 2 +- 4 files changed, 6 insertions(+), 7 deletions(-) diff --git a/docs/content/doc/advanced/logging-documentation.en-us.md b/docs/content/doc/advanced/logging-documentation.en-us.md index 21fef1fb81325..a9772ea96754e 100644 --- a/docs/content/doc/advanced/logging-documentation.en-us.md +++ b/docs/content/doc/advanced/logging-documentation.en-us.md @@ -81,8 +81,8 @@ Please note, setting the `LEVEL` of this logger to a level above You can control the output format by setting a log handler to `ROUTER_LOG_HANDLER`. Now Gitea has two log handlers: -* `v1` is the default handler for Gitea before 1.16 -* `v2` is the default handler for Gitea from 1.16, it's more meaningful and friendly. +* `router_logger_v1` is the default handler for Gitea before 1.16 +* `router_logger_v2` is the default handler for Gitea from 1.16, it's more meaningful and friendly. If you have applications depending on the log format (eg: fail2ban), please make sure you use the correct log handler and log format. diff --git a/modules/log/colors_router.go b/modules/log/colors_router.go index fa19f030b6981..888198d4e9aa6 100644 --- a/modules/log/colors_router.go +++ b/modules/log/colors_router.go @@ -75,7 +75,7 @@ var ( // 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 in Millisecond is more readable: + // 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) diff --git a/modules/web/routing/context.go b/modules/web/routing/context.go index 0059129f2c954..f57b2e9026a92 100644 --- a/modules/web/routing/context.go +++ b/modules/web/routing/context.go @@ -9,9 +9,9 @@ import ( "net/http" ) -type contextKeyStruct struct{} +type contextKeyType struct{} -var contextKey contextKeyStruct +var contextKey contextKeyType //UpdateFuncInfo updates a context's func info func UpdateFuncInfo(ctx context.Context, funcInfo *FuncInfo) { @@ -20,7 +20,6 @@ func UpdateFuncInfo(ctx context.Context, funcInfo *FuncInfo) { return } - // update our current record record.lock.Lock() record.funcInfo = funcInfo record.lock.Unlock() diff --git a/modules/web/routing/logger_v2_manager.go b/modules/web/routing/logger_v2_manager.go index f5262497dce04..31fd09f312037 100644 --- a/modules/web/routing/logger_v2_manager.go +++ b/modules/web/routing/logger_v2_manager.go @@ -45,7 +45,7 @@ func (manager *requestRecordsManager) startSlowQueryDetector(threshold time.Dura // 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.5ms are all OK. + // 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 { From 9f347912d1a52c825f579326a1944c3f5e3775a0 Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Fri, 24 Dec 2021 21:27:34 +0800 Subject: [PATCH 24/29] fix log.ACCESS --- custom/conf/app.example.ini | 3 +++ docs/content/doc/advanced/config-cheat-sheet.en-us.md | 1 + modules/setting/log.go | 2 ++ 3 files changed, 6 insertions(+) diff --git a/custom/conf/app.example.ini b/custom/conf/app.example.ini index e29064a9d19b5..75ab51379709f 100644 --- a/custom/conf/app.example.ini +++ b/custom/conf/app.example.ini @@ -480,6 +480,9 @@ ROUTER = console ;; ;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 +;; ;; Sets the template used to create the access log. ;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}}" ;; diff --git a/docs/content/doc/advanced/config-cheat-sheet.en-us.md b/docs/content/doc/advanced/config-cheat-sheet.en-us.md index ee2b63ffe05a0..1aac0230c528d 100644 --- a/docs/content/doc/advanced/config-cheat-sheet.en-us.md +++ b/docs/content/doc/advanced/config-cheat-sheet.en-us.md @@ -762,6 +762,7 @@ Default templates for project boards: ### 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: - `Ctx`: the `context.Context` of the request. diff --git a/modules/setting/log.go b/modules/setting/log.go index ef902cfdc09d3..a53b43119632c 100644 --- a/modules/setting/log.go +++ b/modules/setting/log.go @@ -257,6 +257,8 @@ func newAccessLogService() { 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}}"`, ) + // 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") From f7fe8a7c461e5e98af915e07fa5df328bd6fdd18 Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Fri, 24 Dec 2021 21:31:05 +0800 Subject: [PATCH 25/29] revert document --- docs/content/doc/advanced/logging-documentation.en-us.md | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/docs/content/doc/advanced/logging-documentation.en-us.md b/docs/content/doc/advanced/logging-documentation.en-us.md index a9772ea96754e..98b2154cc5e5d 100644 --- a/docs/content/doc/advanced/logging-documentation.en-us.md +++ b/docs/content/doc/advanced/logging-documentation.en-us.md @@ -107,7 +107,9 @@ should be taken when changing its template. The main benefit of this logger is that Gitea can now log accesses in a standard log format so standard tools may be used. -You can enable this logger using `ENABLE_ACCESS_LOG`. +You can enable this logger using `ENABLE_ACCESS_LOG`. Its outputs are +configured by setting the `ACCESS` value in the `[log]` section of the +configuration. `ACCESS` defaults to `file` if unset. Each output sublogger for this logger is configured in `[log.sublogger.access]` sections. There are certain default values From 4cb7e036a0f8e3e7a5e7ccd23d8cb3a5a27c708a Mon Sep 17 00:00:00 2001 From: Andrew Thornton Date: Sun, 26 Dec 2021 15:21:32 +0000 Subject: [PATCH 26/29] Remove logger v1 Now 1.16.0 is out and we're at the start of the v1.17 cycle we can make more radical breaking changes. In which case we can simply remove the logger v1 changes. Signed-off-by: Andrew Thornton --- custom/conf/app.example.ini | 15 ++- .../doc/advanced/config-cheat-sheet.en-us.md | 2 - .../advanced/logging-documentation.en-us.md | 22 ++-- modules/setting/setting.go | 4 - modules/web/routing/funcinfo.go | 9 ++ modules/web/routing/logger.go | 105 ++++++++++++++++++ ...logger_v2_manager.go => logger_manager.go} | 0 modules/web/routing/logger_v1.go | 33 ------ modules/web/routing/logger_v2.go | 97 ---------------- routers/common/middleware.go | 13 +-- 10 files changed, 136 insertions(+), 164 deletions(-) create mode 100644 modules/web/routing/logger.go rename modules/web/routing/{logger_v2_manager.go => logger_manager.go} (100%) delete mode 100644 modules/web/routing/logger_v1.go delete mode 100644 modules/web/routing/logger_v2.go diff --git a/custom/conf/app.example.ini b/custom/conf/app.example.ini index 75ab51379709f..bab4fd4fcee2f 100644 --- a/custom/conf/app.example.ini +++ b/custom/conf/app.example.ini @@ -466,14 +466,17 @@ LEVEL = Info ;; Set the log "modes" for the router log (if file is set the log file will default to router.log) ROUTER = console ;; -;; The log level that the router should log at. (If you are setting the access log, it's recommended to place this at Debug.) -;ROUTER_LOG_LEVEL = Info +;; The router will log different things at different levels. ;; -;; The handler for router logs, it controls the router log format, mainly for debug purpose, two log handlers: -;; router_logger_v1: default for before 1.16 -;; router_logger_v2: default for 1.16 and later. Developers could set both `LEVEL=Debug` to get the "started" router messages -;ROUTER_LOG_HANDLER = router_logger_v2 +;; * started messages will be logged at DEBUG level +;; * slow routers will be logged at WARN +;; * polling/completed routers will be logged at INFO +;; * 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..router] LEVEL +;; + ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; ;; ;; Access Logger (Creates log in NCSA common log format) diff --git a/docs/content/doc/advanced/config-cheat-sheet.en-us.md b/docs/content/doc/advanced/config-cheat-sheet.en-us.md index 1ece6bb2c0303..45de5e41df309 100644 --- a/docs/content/doc/advanced/config-cheat-sheet.en-us.md +++ b/docs/content/doc/advanced/config-cheat-sheet.en-us.md @@ -757,8 +757,6 @@ Default templates for project boards: - `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\]`. -- `ROUTER_LOG_LEVEL`: **Info**: The log level that the router should log at. (If you are setting the access log, it's recommended to place this at Debug.) -- `ROUTER_LOG_HANDLER`: **router_logger_v2**: The log handler that controls the log output format. Before 1.16 the router logs are outputted by handler `router_logger_v1`. From 1.16, the default handler is `router_logger_v2` which is more meaningful and friendly. ### Access Log (`log`) - `ENABLE_ACCESS_LOG`: **false**: Creates an access.log in NCSA common log format, or as per the following template diff --git a/docs/content/doc/advanced/logging-documentation.en-us.md b/docs/content/doc/advanced/logging-documentation.en-us.md index 98b2154cc5e5d..cca249d7ef53d 100644 --- a/docs/content/doc/advanced/logging-documentation.en-us.md +++ b/docs/content/doc/advanced/logging-documentation.en-us.md @@ -68,23 +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: -You can control the output format by setting a log handler to `ROUTER_LOG_HANDLER`. -Now Gitea has two log handlers: -* `router_logger_v1` is the default handler for Gitea before 1.16 -* `router_logger_v2` is the default handler for Gitea from 1.16, it's more meaningful and friendly. +- `started` messages will be logged at DEBUG level +- `slow` routers will be logged at WARN +- `polling`/`completed` routers will be logged at INFO +- `failed` routers will be logged at WARN -If you have applications depending on the log format (eg: fail2ban), please make sure you use the correct log handler and log format. +The logging level for the router will default to that of the main configuration. Set `[log..router]` `LEVEL` to change this. Each output sublogger for this logger is configured in `[log.sublogger.router]` sections. There are certain default values diff --git a/modules/setting/setting.go b/modules/setting/setting.go index 51c0f7e7af89d..cbc80c73380f8 100644 --- a/modules/setting/setting.go +++ b/modules/setting/setting.go @@ -338,8 +338,6 @@ var ( EnableXORMLog bool DisableRouterLog bool - RouterLogLevel log.Level - RouterLogHandler string EnableAccessLog bool AccessLogTemplate string @@ -606,8 +604,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")) - RouterLogHandler = Cfg.Section("log").Key("ROUTER_LOG_HANDLER").MustString("router_logger_v2") sec := Cfg.Section("server") AppName = Cfg.Section("").Key("APP_NAME").MustString("Gitea: Git with a cup of tea") diff --git a/modules/web/routing/funcinfo.go b/modules/web/routing/funcinfo.go index a3ee8a59d1c79..6d3986e364e7d 100644 --- a/modules/web/routing/funcinfo.go +++ b/modules/web/routing/funcinfo.go @@ -5,6 +5,7 @@ package routing import ( + "fmt" "reflect" "runtime" "strings" @@ -24,6 +25,14 @@ type FuncInfo struct { 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. diff --git a/modules/web/routing/logger.go b/modules/web/routing/logger.go new file mode 100644 index 0000000000000..4659127a97c4c --- /dev/null +++ b/modules/web/routing/logger.go @@ -0,0 +1,105 @@ +// 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 && !logger.IsDebug() { + // 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 DEBUG to get the "started" request messages. + return + } + + req := record.request + if trigger == StartEvent { + // when a request starts, we have no information about the handler function information, we only have the request path + logger.Debug("router: %s %v %s for %s", startMessage, log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr) + return + } + + // 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, + ) + } +} diff --git a/modules/web/routing/logger_v2_manager.go b/modules/web/routing/logger_manager.go similarity index 100% rename from modules/web/routing/logger_v2_manager.go rename to modules/web/routing/logger_manager.go diff --git a/modules/web/routing/logger_v1.go b/modules/web/routing/logger_v1.go deleted file mode 100644 index 999802ae39a0b..0000000000000 --- a/modules/web/routing/logger_v1.go +++ /dev/null @@ -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 routing - -import ( - "net/http" - "time" - - "code.gitea.io/gitea/modules/context" - "code.gitea.io/gitea/modules/log" -) - -// NewLoggerHandlerV1 is a handler that will log the routing logs -func NewLoggerHandlerV1(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))) - }) - } -} diff --git a/modules/web/routing/logger_v2.go b/modules/web/routing/logger_v2.go deleted file mode 100644 index b42cca06eeaef..0000000000000 --- a/modules/web/routing/logger_v2.go +++ /dev/null @@ -1,97 +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 routing - -import ( - "fmt" - "net/http" - "time" - - "code.gitea.io/gitea/modules/context" - "code.gitea.io/gitea/modules/log" - "code.gitea.io/gitea/modules/setting" -) - -// NewLoggerHandlerV2 is a handler that will log routing to the router log taking account of -// routing information -func NewLoggerHandlerV2() 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 -} - -func logPrinter(logger log.Logger) func(trigger Event, record *requestRecord) { - return func(trigger Event, record *requestRecord) { - if trigger == StartEvent && setting.LogLevel > log.DEBUG { - // for performance, if the "started" message shouldn't be logged, we just return as early as possible - // developers could set both `log.LEVEL=Debug` to get the "started" request messages. - return - } - - shortFilename := "" - line := 0 - shortName := "" - - record.lock.RLock() - isLongPolling := record.isLongPolling - if record.funcInfo != nil { - shortFilename, line, shortName = record.funcInfo.shortFile, record.funcInfo.line, record.funcInfo.shortName - } else { - // we might not find all handlers, so if a handler has not called `UpdateFuncInfo`, we won't know its information - // in such case, we should debug to find what handler it is and use `UpdateFuncInfo` to report its information - shortFilename = "unknown-handler" - } - record.lock.RUnlock() - - req := record.request - - if trigger == StartEvent { - // when a request starts, we have no information about the handler function information, we only have the request path - logger.Debug("router: started %v %s for %s", log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr) - return - } - - handlerFuncInfo := fmt.Sprintf("%s:%d(%s)", shortFilename, line, shortName) - if trigger == StillExecutingEvent { - message := "still-executing" - level := log.WARN - if isLongPolling { - level = log.INFO - message = "long-polling" - } - _ = 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, - ) - } else { - if record.panicError != nil { - _ = logger.Log(0, log.WARN, "router: failed %v %s for %s, panic in %v @ %s, err=%v", - shortFilename, line, shortName, - log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr, - log.ColoredTime(time.Since(record.startTime)), - handlerFuncInfo, - record.panicError, - ) - } else { - var status int - if v, ok := record.responseWriter.(context.ResponseWriter); ok { - status = v.Status() - } - _ = logger.Log(0, setting.RouterLogLevel, "router: completed %v %s for %s, %v %v in %v @ %s", - 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/routers/common/middleware.go b/routers/common/middleware.go index 13f536931224f..2b6343b10f28b 100644 --- a/routers/common/middleware.go +++ b/routers/common/middleware.go @@ -51,18 +51,9 @@ func Middlewares() []func(http.Handler) http.Handler { handlers = append(handlers, middleware.StripSlashes) if !setting.DisableRouterLog { - var routerLogHandler func(http.Handler) http.Handler - if setting.RouterLogHandler == "router_logger_v1" { - routerLogHandler = routing.NewLoggerHandlerV1(setting.RouterLogLevel) - } else if setting.RouterLogHandler == "router_logger_v2" { - routerLogHandler = routing.NewLoggerHandlerV2() - } - if routerLogHandler == nil { - log.Warn("unknown router log handler '%s', fall back to router_logger_v2") - routerLogHandler = routing.NewLoggerHandlerV2() - } - handlers = append(handlers, routerLogHandler) + handlers = append(handlers, routing.NewLoggerHandler()) } + if setting.EnableAccessLog { handlers = append(handlers, context.AccessLogger()) } From 8d143fecdfae7d7757f357f7b04247d2417e84a1 Mon Sep 17 00:00:00 2001 From: Andrew Thornton Date: Thu, 20 Jan 2022 10:00:05 +0000 Subject: [PATCH 27/29] fix broken conflicts resolution Signed-off-by: Andrew Thornton --- modules/web/route.go | 138 ------------------------------------ modules/web/wrap_convert.go | 8 +++ 2 files changed, 8 insertions(+), 138 deletions(-) diff --git a/modules/web/route.go b/modules/web/route.go index 19193773d53a4..86e407701c3c6 100644 --- a/modules/web/route.go +++ b/modules/web/route.go @@ -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) diff --git a/modules/web/wrap_convert.go b/modules/web/wrap_convert.go index 221a3c664ac4e..f2e05de7c1d88 100644 --- a/modules/web/wrap_convert.go +++ b/modules/web/wrap_convert.go @@ -61,6 +61,14 @@ func convertHandler(handler interface{}) wrappedHandlerFunc { 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) From f2cfdcf341db210e87eca74a00c859cf0dc035c0 Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Thu, 20 Jan 2022 18:16:35 +0800 Subject: [PATCH 28/29] Use TRACE level to show router started message --- custom/conf/app.example.ini | 4 ++-- modules/web/routing/logger.go | 17 +++++++++-------- 2 files changed, 11 insertions(+), 10 deletions(-) diff --git a/custom/conf/app.example.ini b/custom/conf/app.example.ini index 920bdbdfae95f..3343af95a9752 100644 --- a/custom/conf/app.example.ini +++ b/custom/conf/app.example.ini @@ -469,9 +469,9 @@ ROUTER = console ;; ;; The router will log different things at different levels. ;; -;; * started messages will be logged at DEBUG level -;; * slow routers will be logged at WARN +;; * 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 diff --git a/modules/web/routing/logger.go b/modules/web/routing/logger.go index 4659127a97c4c..cf3b50725d8b1 100644 --- a/modules/web/routing/logger.go +++ b/modules/web/routing/logger.go @@ -36,19 +36,20 @@ var ( func logPrinter(logger log.Logger) func(trigger Event, record *requestRecord) { return func(trigger Event, record *requestRecord) { - if trigger == StartEvent && !logger.IsDebug() { - // 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 DEBUG to get the "started" request messages. - return - } - - req := record.request 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 - logger.Debug("router: %s %v %s for %s", startMessage, log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr) + 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() From 5a3987198cf4ca4f68fb59218fffd2f8ff4801fa Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Thu, 20 Jan 2022 18:31:44 +0800 Subject: [PATCH 29/29] Fix document --- docs/content/doc/advanced/logging-documentation.en-us.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/docs/content/doc/advanced/logging-documentation.en-us.md b/docs/content/doc/advanced/logging-documentation.en-us.md index cca249d7ef53d..dee1dbb6d664a 100644 --- a/docs/content/doc/advanced/logging-documentation.en-us.md +++ b/docs/content/doc/advanced/logging-documentation.en-us.md @@ -79,9 +79,9 @@ configuration. `ROUTER` will default to `console` if unset and will default to s The Router logger logs the following: -- `started` messages will be logged at DEBUG level -- `slow` routers will be logged at WARN +- `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..router]` `LEVEL` to change this.