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)
This commit is contained in:
sillyguodong 2023-03-10 23:54:32 +08:00 committed by GitHub
parent cf29ee6dd2
commit 5155ec35c5
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
5 changed files with 74 additions and 1 deletions

View File

@ -576,6 +576,22 @@ ROUTER = console
;; The routing level will default to that of the system but individual router level can be set in ;; The routing level will default to that of the system but individual router level can be set in
;; [log.<mode>.router] LEVEL ;; [log.<mode>.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 =
;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
;; ;;

View File

@ -881,7 +881,13 @@ Default templates for project boards:
- `Identity`: the SignedUserName or `"-"` if not logged in. - `Identity`: the SignedUserName or `"-"` if not logged in.
- `Start`: the start time of the request. - `Start`: the start time of the request.
- `ResponseWriter`: the responseWriter from the request. - `ResponseWriter`: the responseWriter from the request.
- `RequestID`: the value matching REQUEST_ID_HEADERSdefault: `-`, 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. - 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`: **\<empty\>**: 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.*`) ### Log subsections (`log.name`, `log.name.*`)

View File

@ -262,7 +262,22 @@ test01.xls: application/vnd.ms-excel; charset=binary
- `ROOT_PATH`: 日志文件根目录。 - `ROOT_PATH`: 日志文件根目录。
- `MODE`: 日志记录模式,默认是为 `console`。如果要写到多个通道,用逗号分隔 - `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`) ## Cron (`cron`)

View File

@ -6,7 +6,9 @@ package context
import ( import (
"bytes" "bytes"
"context" "context"
"fmt"
"net/http" "net/http"
"strings"
"text/template" "text/template"
"time" "time"
@ -20,13 +22,39 @@ type routerLoggerOptions struct {
Start *time.Time Start *time.Time
ResponseWriter http.ResponseWriter ResponseWriter http.ResponseWriter
Ctx map[string]interface{} Ctx map[string]interface{}
RequestID *string
} }
var signedUserNameStringPointerKey interface{} = "signedUserNameStringPointerKey" 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 // AccessLogger returns a middleware to log access logger
func AccessLogger() func(http.Handler) http.Handler { func AccessLogger() func(http.Handler) http.Handler {
logger := log.GetLogger("access") logger := log.GetLogger("access")
needRequestID := len(setting.Log.RequestIDHeaders) > 0 && strings.Contains(setting.Log.AccessLogTemplate, keyOfRequestIDInTemplate)
logTemplate, _ := template.New("log").Parse(setting.Log.AccessLogTemplate) logTemplate, _ := template.New("log").Parse(setting.Log.AccessLogTemplate)
return func(next http.Handler) http.Handler { return func(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
@ -34,6 +62,11 @@ func AccessLogger() func(http.Handler) http.Handler {
identity := "-" identity := "-"
r := req.WithContext(context.WithValue(req.Context(), signedUserNameStringPointerKey, &identity)) r := req.WithContext(context.WithValue(req.Context(), signedUserNameStringPointerKey, &identity))
var requestID string
if needRequestID {
requestID = parseRequestIDFromRequestHeader(req)
}
next.ServeHTTP(w, r) next.ServeHTTP(w, r)
rw := w.(ResponseWriter) rw := w.(ResponseWriter)
@ -47,6 +80,7 @@ func AccessLogger() func(http.Handler) http.Handler {
"RemoteAddr": req.RemoteAddr, "RemoteAddr": req.RemoteAddr,
"Req": req, "Req": req,
}, },
RequestID: &requestID,
}) })
if err != nil { if err != nil {
log.Error("Could not set up chi access logger: %v", err.Error()) log.Error("Could not set up chi access logger: %v", err.Error())

View File

@ -38,6 +38,7 @@ var Log struct {
EnableAccessLog bool EnableAccessLog bool
AccessLogTemplate string AccessLogTemplate string
BufferLength int64 BufferLength int64
RequestIDHeaders []string
} }
// GetLogDescriptions returns a race safe set of descriptions // GetLogDescriptions returns a race safe set of descriptions
@ -153,6 +154,7 @@ func loadLogFrom(rootCfg ConfigProvider) {
Log.AccessLogTemplate = sec.Key("ACCESS_LOG_TEMPLATE").MustString( 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}}"`, `{{.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 // the `MustString` updates the default value, and `log.ACCESS` is used by `generateNamedLogger("access")` later
_ = rootCfg.Section("log").Key("ACCESS").MustString("file") _ = rootCfg.Section("log").Key("ACCESS").MustString("file")