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)

Author: sillyguodong

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.<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 = 
 
 ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
 ;;

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`: **\<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.*`)
 

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

modules/context/access_log.go

@@ -6,7 +6,9 @@ package context
 import (
 	"bytes"
 	"context"
+	"fmt"
 	"net/http"
+	"strings"
 	"text/template"
 	"time"
 
@@ -20,20 +22,51 @@ 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) {
 			start := time.Now()
 			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())

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