From 5155ec35c571de8df62318df78c78cebc20e1aa0 Mon Sep 17 00:00:00 2001 From: sillyguodong <33891828+sillyguodong@users.noreply.github.com> Date: Fri, 10 Mar 2023 23:54:32 +0800 Subject: [PATCH] Parse external request id from request headers, and print it in access log (#22906) Close: #22890. --- ### Configure in .ini file: ```ini [log] REQUEST_ID_HEADERS = X-Request-ID, X-Trace-Id ``` ### Params in Request Header ``` X-Trace-ID: trace-id-1q2w3e4r ``` ![image](https://user-images.githubusercontent.com/33891828/218665296-8fd19a0f-ada6-4236-8bdb-f99201c703e8.png) ### Log output: ![image](https://user-images.githubusercontent.com/33891828/218665225-cc242a57-4ffc-449a-a1f6-f45ded0ead60.png) --- custom/conf/app.example.ini | 16 +++++++++ .../doc/advanced/config-cheat-sheet.en-us.md | 6 ++++ .../doc/advanced/config-cheat-sheet.zh-cn.md | 17 +++++++++- modules/context/access_log.go | 34 +++++++++++++++++++ modules/setting/log.go | 2 ++ 5 files changed, 74 insertions(+), 1 deletion(-) diff --git a/custom/conf/app.example.ini b/custom/conf/app.example.ini index b7875c12d..c3c20a216 100644 --- a/custom/conf/app.example.ini +++ b/custom/conf/app.example.ini @@ -576,6 +576,22 @@ ROUTER = console ;; The routing level will default to that of the system but individual router level can be set in ;; [log..router] LEVEL ;; +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; +;; +;; Print request id which parsed from request headers in access log, when access log is enabled. +;; * E.g: +;; * In request Header: X-Request-ID: test-id-123 +;; * Configuration in app.ini: REQUEST_ID_HEADERS = X-Request-ID +;; * Print in log: 127.0.0.1:58384 - - [14/Feb/2023:16:33:51 +0800] "test-id-123" +;; +;; If you configure more than one in the .ini file, it will match in the order of configuration, +;; and the first match will be finally printed in the log. +;; * E.g: +;; * In reuqest Header: X-Trace-ID: trace-id-1q2w3e4r +;; * Configuration in app.ini: REQUEST_ID_HEADERS = X-Request-ID, X-Trace-ID, X-Req-ID +;; * Print in log: 127.0.0.1:58384 - - [14/Feb/2023:16:33:51 +0800] "trace-id-1q2w3e4r" +;; +;; REQUEST_ID_HEADERS = ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; ;; 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 c4ff8bafb..a5ef977f1 100644 --- a/docs/content/doc/advanced/config-cheat-sheet.en-us.md +++ b/docs/content/doc/advanced/config-cheat-sheet.en-us.md @@ -881,7 +881,13 @@ Default templates for project boards: - `Identity`: the SignedUserName or `"-"` if not logged in. - `Start`: the start time of the request. - `ResponseWriter`: the responseWriter from the request. + - `RequestID`: the value matching REQUEST_ID_HEADERS（default: `-`, if not matched）. - 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. +- `REQUEST_ID_HEADERS`: **\**: You can configure multiple values that are splited by comma here. It will match in the order of configuration, and the first match will be finally printed in the access log. + - e.g. + - In the Request Header: X-Request-ID: **test-id-123** + - Configuration in app.ini: REQUEST_ID_HEADERS = X-Request-ID + - Print in log: 127.0.0.1:58384 - - [14/Feb/2023:16:33:51 +0800] "**test-id-123**" ... ### Log subsections (`log.name`, `log.name.*`) diff --git a/docs/content/doc/advanced/config-cheat-sheet.zh-cn.md b/docs/content/doc/advanced/config-cheat-sheet.zh-cn.md index aae64d97b..84186d0e9 100644 --- a/docs/content/doc/advanced/config-cheat-sheet.zh-cn.md +++ b/docs/content/doc/advanced/config-cheat-sheet.zh-cn.md @@ -262,7 +262,22 @@ test01.xls: application/vnd.ms-excel; charset=binary - `ROOT_PATH`: 日志文件根目录。 - `MODE`: 日志记录模式，默认是为 `console`。如果要写到多个通道，用逗号分隔 -- `LEVEL`: 日志级别，默认为`Trace`。 +- `LEVEL`: 日志级别，默认为 `Trace`。 +- `DISABLE_ROUTER_LOG`: 关闭日志中的路由日志。 +- `ENABLE_ACCESS_LOG`: 是否开启 Access Log, 默认为 false。 +- `ACCESS_LOG_TEMPLATE`: `access.log` 输出内容的模板，默认模板：**`{{.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}}"`** + 模板支持以下参数: + - `Ctx`: 请求上下文。 + - `Identity`: 登录用户名，默认: “`-`”。 + - `Start`: 请求开始时间。 + - `ResponseWriter`: + - `RequestID`: 从请求头中解析得到的与 `REQUEST_ID_HEADERS` 匹配的值，默认: “`-`”。 + - 一定要谨慎配置该模板，否则可能会引起panic. +- `REQUEST_ID_HEADERS`: 从 Request Header 中匹配指定 Key，并将匹配到的值输出到 `access.log` 中(需要在 `ACCESS_LOG_TEMPLATE` 中指定输出位置)。如果在该参数中配置多个 Key， 请用逗号分割，程序将按照配置的顺序进行匹配。 + - 示例： + - 请求头： X-Request-ID: **test-id-123** + - 配置文件： REQUEST_ID_HEADERS = X-Request-ID + - 日志输出： 127.0.0.1:58384 - - [14/Feb/2023:16:33:51 +0800] "**test-id-123**" ... ## Cron (`cron`) diff --git a/modules/context/access_log.go b/modules/context/access_log.go index 1aaba9dc2..515682b64 100644 --- a/modules/context/access_log.go +++ b/modules/context/access_log.go @@ -6,7 +6,9 @@ package context import ( "bytes" "context" + "fmt" "net/http" + "strings" "text/template" "time" @@ -20,13 +22,39 @@ type routerLoggerOptions struct { Start *time.Time ResponseWriter http.ResponseWriter Ctx map[string]interface{} + RequestID *string } var signedUserNameStringPointerKey interface{} = "signedUserNameStringPointerKey" +const keyOfRequestIDInTemplate = ".RequestID" + +// According to: +// TraceId: A valid trace identifier is a 16-byte array with at least one non-zero byte +// MD5 output is 16 or 32 bytes: md5-bytes is 16, md5-hex is 32 +// SHA1: similar, SHA1-bytes is 20, SHA1-hex is 40. +// UUID is 128-bit, 32 hex chars, 36 ASCII chars with 4 dashes +// So, we accept a Request ID with a maximum character length of 40 +const maxRequestIDByteLength = 40 + +func parseRequestIDFromRequestHeader(req *http.Request) string { + requestID := "-" + for _, key := range setting.Log.RequestIDHeaders { + if req.Header.Get(key) != "" { + requestID = req.Header.Get(key) + break + } + } + if len(requestID) > maxRequestIDByteLength { + requestID = fmt.Sprintf("%s...", requestID[:maxRequestIDByteLength]) + } + return requestID +} + // AccessLogger returns a middleware to log access logger func AccessLogger() func(http.Handler) http.Handler { logger := log.GetLogger("access") + needRequestID := len(setting.Log.RequestIDHeaders) > 0 && strings.Contains(setting.Log.AccessLogTemplate, keyOfRequestIDInTemplate) logTemplate, _ := template.New("log").Parse(setting.Log.AccessLogTemplate) return func(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { @@ -34,6 +62,11 @@ func AccessLogger() func(http.Handler) http.Handler { identity := "-" r := req.WithContext(context.WithValue(req.Context(), signedUserNameStringPointerKey, &identity)) + var requestID string + if needRequestID { + requestID = parseRequestIDFromRequestHeader(req) + } + next.ServeHTTP(w, r) rw := w.(ResponseWriter) @@ -47,6 +80,7 @@ func AccessLogger() func(http.Handler) http.Handler { "RemoteAddr": req.RemoteAddr, "Req": req, }, + RequestID: &requestID, }) if err != nil { log.Error("Could not set up chi access logger: %v", err.Error()) diff --git a/modules/setting/log.go b/modules/setting/log.go index 5448650aa..dabdb543a 100644 --- a/modules/setting/log.go +++ b/modules/setting/log.go @@ -38,6 +38,7 @@ var Log struct { EnableAccessLog bool AccessLogTemplate string BufferLength int64 + RequestIDHeaders []string } // GetLogDescriptions returns a race safe set of descriptions @@ -153,6 +154,7 @@ func loadLogFrom(rootCfg ConfigProvider) { Log.AccessLogTemplate = sec.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}}"`, ) + Log.RequestIDHeaders = sec.Key("REQUEST_ID_HEADERS").Strings(",") // the `MustString` updates the default value, and `log.ACCESS` is used by `generateNamedLogger("access")` later _ = rootCfg.Section("log").Key("ACCESS").MustString("file")