Refactor Router Logger (#17308)

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

[BREAKING]
This PR substantially changes the logging format of the router logger. If you use this logging for monitoring e.g. fail2ban you will need to update this to match the new format.

Author: wxiaoguang

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))
 		}
 	}()
 

custom/conf/app.example.ini

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

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.
@@ -752,11 +751,16 @@ Default templates for project boards:
 - `MODE`: **console**: Logging mode. For multiple modes, use a comma to separate values. You can configure each mode in per mode log subsections `\[log.modename\]`. By default the file mode will log to `$ROOT_PATH/gitea.log`.
 - `LEVEL`: **Info**: General log level. \[Trace, Debug, Info, Warn, Error, Critical, Fatal, None\]
 - `STACKTRACE_LEVEL`: **None**: Default log level at which to log create stack traces. \[Trace, Debug, Info, Warn, Error, Critical, Fatal, None\]
-- `ROUTER_LOG_LEVEL`: **Info**: The log level that the router should log at. (If you are setting the access log, its recommended to place this at Debug.)
+- `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\]`.
+
+### 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:
@@ -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.*`)
 

docs/content/doc/advanced/logging-documentation.en-us.md

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

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 converts the provided time to a ColoredValue for logging. The duration is always formatted in milliseconds.
 func ColoredTime(duration time.Duration) *ColoredValue {
+	// the output of duration in Millisecond is more readable:
+	// * before: "100.1ms" "100.1μs" "100.1s"
+	// * better: "100.1ms" "0.1ms"   "100100.0ms", readers can compare the values at first glance.
+	str := fmt.Sprintf("%.1fms", float64(duration.Microseconds())/1000)
 	for i, k := range durations {
 		if duration < k {
-			return NewColoredValueBytes(duration, &durationColors[i])
+			return NewColoredValueBytes(str, &durationColors[i])
 		}
 	}
-	return NewColoredValueBytes(duration, &wayTooLong)
+	return NewColoredValueBytes(str, &wayTooLong)
 }

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("unable to detect correct package prefix, please update file: " + filename)
+	}
 }

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

modules/setting/log.go

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

modules/setting/setting.go

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