feat(log): 前后端共用 request_id 与四时间点时钟校准

- X-Request-Id 请求头带合法 UUID 则沿用为 request_id（严格格式白名单防注入），否则自生成 12 位 hex - 响应头新增 X-Server-Received-Ms / X-Server-Sent-Ms 供前端时钟校准 - CORS Allow-Headers 增加 X-Request-Id，Expose-Headers 显式列出（credentials 下不认 *） Co-authored-by: Cursor <cursoragent@cursor.com>
2026-07-27 07:46:38 +08:00
parent e22df36d3f
commit d3e71decf4
4 changed files with 157 additions and 9 deletions
@@ -208,6 +208,30 @@ func truncateUA(s string, max int) string {
 	return string(r[:max])
 }

+// normalizeRequestId 校验前端传入的 X-Request-Id。
+// 仅接受标准 UUID 形态（36 位，8-4-4-4-12，hex+连字符），统一转小写；
+// 其余（超长、控制符、任意注入串）一律丢弃返回空，保证日志字段安全且低基数可控。
+func normalizeRequestId(v string) string {
+	if len(v) != 36 {
+		return ""
+	}
+	for i := 0; i < 36; i++ {
+		c := v[i]
+		switch i {
+		case 8, 13, 18, 23:
+			if c != '-' {
+				return ""
+			}
+		default:
+			isHex := (c >= '0' && c <= '9') || (c >= 'a' && c <= 'f') || (c >= 'A' && c <= 'F')
+			if !isHex {
+				return ""
+			}
+		}
+	}
+	return strings.ToLower(v)
+}
+
 // shortID 生成 n 字节随机 hex（n=6 → 12 位）
 func shortID(n int) string {
 	b := make([]byte, n)
@@ -557,13 +581,20 @@ func (that *Application) handler(w http.ResponseWriter, req *http.Request) {
 		unescapeUrl = req.RequestURI
 	}

-	// 请求级追踪：sid=sessionId 前 12 位（脱敏），request_id 回写响应头
-	requestId := shortID(6)
+	// 请求级追踪：sid=sessionId 前 12 位（脱敏），request_id 回写响应头。
+	// 前后端共用一个 request_id：前端带合法 X-Request-Id（UUID）则沿用，非法/缺失才服务端自生成，
+	// 严格格式校验杜绝日志注入。
+	requestId := normalizeRequestId(req.Header.Get("X-Request-Id"))
+	if requestId == "" {
+		requestId = shortID(6)
+	}
 	sid := sessionId
 	if len(sid) > 12 {
 		sid = sid[:12]
 	}
 	w.Header().Set("X-Request-Id", requestId)
+	// 服务端接收时间（ms），与 View() 写出的 X-Server-Sent-Ms 组成四时间点时钟校准
+	w.Header().Set("X-Server-Received-Ms", strconv.FormatInt(nowUnixTime.UnixMilli(), 10))
 	reqLog := that.Log.WithFields("sid", sid, "request_id", requestId)
 	dbCopy := that.Db
 	dbCopy.Log = reqLog
@@ -716,8 +747,9 @@ func (that *Application) crossDomain(context *Context, sessionId string) {
 		//header.Set("Access-Control-Allow-Origin", "*")
 		header.Set("Access-Control-Allow-Methods", "GET,POST,OPTIONS,PUT,DELETE")
 		header.Set("Access-Control-Allow-Credentials", "true")
-		header.Set("Access-Control-Expose-Headers", "*")
-		header.Set("Access-Control-Allow-Headers", "X-Requested-With,Content-Type,Access-Token,Authorization,Cookie,Set-Cookie")
+		// credentials 模式下浏览器不认 "*"，必须显式列出可读响应头
+		header.Set("Access-Control-Expose-Headers", "X-Request-Id,X-Server-Received-Ms,X-Server-Sent-Ms")
+		header.Set("Access-Control-Allow-Headers", "X-Requested-With,Content-Type,Access-Token,Authorization,Cookie,Set-Cookie,X-Request-Id")

 		if sessionId != "" {
 			//跨域允许需要设置cookie的允许跨域https才有效果
@@ -763,8 +795,9 @@ func (that *Application) crossDomain(context *Context, sessionId string) {

 	header.Set("Access-Control-Allow-Methods", "GET,POST,OPTIONS,PUT,DELETE")
 	header.Set("Access-Control-Allow-Credentials", "true")
-	header.Set("Access-Control-Expose-Headers", "*")
-	header.Set("Access-Control-Allow-Headers", "X-Requested-With,Content-Type,Access-Token,Authorization,Cookie,Set-Cookie")
+	// credentials 模式下浏览器不认 "*"，必须显式列出可读响应头
+	header.Set("Access-Control-Expose-Headers", "X-Request-Id,X-Server-Received-Ms,X-Server-Sent-Ms")
+	header.Set("Access-Control-Allow-Headers", "X-Requested-With,Content-Type,Access-Token,Authorization,Cookie,Set-Cookie,X-Request-Id")

 	if sessionId != "" {
 		//跨域允许需要设置cookie的允许跨域https才有效果
@@ -6,6 +6,7 @@ import (
 	"io"
 	"mime/multipart"
 	"net/http"
+	"strconv"
 	"sync"
 	"time"

@@ -127,6 +128,9 @@ func (that *Context) View() {
 	}
 	that.DataSize = len(d)
 	that.RespData = nil
+	// 服务端发送时间（ms）：与 X-Server-Received-Ms 组成四时间点，供前端时钟校准；
+	// 必须在首次 Write 之前设置，否则 header 已锁定
+	that.Resp.Header().Set("X-Server-Sent-Ms", strconv.FormatInt(time.Now().UnixMilli(), 10))
 	that.Resp.Write(d)
 }

@@ -23,13 +23,31 @@ HoTime 框架内置 Seq 日志推送支持。通过在 `config.json` 填写 `seq

 激活后每个 HTTP 请求会自动：

- 生成 `request_id`（12 位 hex），回写响应头 `X-Request-Id`
+- 确定 `request_id`（前端带合法 UUID 则沿用，否则自生成 12 位 hex），回写响应头 `X-Request-Id`
 - 将 `sessionId` 前 12 位作为 `sid` 写入请求级日志（脱敏，避免把登录凭据写进 Seq）
 - 业务日志、SQL 日志、访问日志均携带 `sid` / `request_id`
 - **控制台自动降噪**（零额外配置）：业务日志（`that.Log`）控制台放宽到 **Info+**（Debug/SQL 不上控制台），访问日志（`that.WebConnectLog`）控制台保持 **Warn+**（量大不上控制台）；Debug/SQL/访问日志（Info 级）仍全量进 Seq 与文件

 ---

+## 请求追踪与前端串联（共用 request_id）
+
+前后端**共用一个 `request_id`**：前端为每次请求生成 UUID 并经 `X-Request-Id` 请求头带上，服务端严格校验（36 位 8-4-4-4-12 hex+连字符，统一小写）通过则直接沿用为本请求 `request_id`；非法或缺失（含浏览器直接访问、老前端）则服务端自生成 12 位 hex。最终值回写响应头 `X-Request-Id`，业务/SQL/访问日志统一携带——Seq 里一条 `request_id = '<uuid>'` 即可同时串出前端事件与后端全链路日志。
+
+- 严格格式白名单杜绝日志注入（换行/引号/超长一律丢弃走自生成分支）
+- 前端伪造/重复 UUID 只污染其自身请求的串联，不影响其他请求；接受该风险换取单字段简洁
+
+同时每个请求回写**服务端收发时间**响应头，供前端做四时间点时钟校准（前端日志的 `@t` 对齐服务器时间轴）：
+
+- `X-Server-Received-Ms`：handler 入口时间（ms）
+- `X-Server-Sent-Ms`：响应体写出前时间（ms，`context.View()` 设置；静态文件不带）
+
+CORS 已相应放行/暴露：`Access-Control-Allow-Headers` 增加 `X-Request-Id`；`Access-Control-Expose-Headers` 由 `*` 改为显式 `X-Request-Id,X-Server-Received-Ms,X-Server-Sent-Ms`（credentials 模式下浏览器不认 `*`）。
+
+**怎么测**：`request_trace_test.go` — `go test . -count=1 -run 'TestNormalizeRequestId|TestRequestIdSharing|TestViewSetsServerSentMsHeader'`。
+
+---
+
 ## 会话追踪与 LogBind

 框架在 `handler` 入口派生请求级 Logger，并浅拷贝 `Db` 将其 `Log` 指向同一 Logger，因此 **SQL 日志自动带会话字段**。字段会出现在同条日志的控制台/文件/Seq 出口上。
@@ -122,7 +140,7 @@ multiWriter（hotimev1.5/log/logger.go）
 | `message` / `msg` | `@m` | 消息正文（不用 `@mt`，避免 `{xxx}` 被当模板） |
 | `caller` | `caller` | 调用位置 |
 | `sid` | `sid` | sessionId 前 12 位 |
-| `request_id` | `request_id` | 单次请求 id |
+| `request_id` | `request_id` | 单次请求 id（前端合法 UUID 沿用，否则服务端 12 位 hex） |
 | `ip` | `ip` | 客户端最佳 IP |
 | `ip_chain` | `ip_chain` | 多源去重链路（与 `ip` 不同时才有） |
 | `ip_country` | `ip_country` | 有 `EO-Client-IPCountry` 时 |
@@ -138,7 +156,7 @@ multiWriter（hotimev1.5/log/logger.go）
 | 目标 | 查询语句 |
 |---|---|
 | 按会话追踪 | `sid = 'abc123def456'` |
-| 按单次请求 | `request_id = 'fedcba987654'` |
+| 按单次请求（前后端同 id 串联） | `request_id = '6f0a1b2c-3d4e-4f5a-8b6c-7d8e9f0a1b2c'`（服务端自生成时为 12 位 hex） |
 | 关键词 | 直接输入，如 `支付失败` |
 | 日志级别 | `@l = 'Error'` |
 | 特定实例 | `instance = '192.168.1.10:8085'` |
@@ -0,0 +1,93 @@
+package hotime
+
+import (
+	"net/http/httptest"
+	"strconv"
+	"strings"
+	"testing"
+	"time"
+
+	. "code.hoteas.com/golang/hotime/common"
+)
+
+func TestNormalizeRequestId_Valid(t *testing.T) {
+	cases := []struct{ in, want string }{
+		{"6f0a1b2c-3d4e-4f5a-8b6c-7d8e9f0a1b2c", "6f0a1b2c-3d4e-4f5a-8b6c-7d8e9f0a1b2c"},
+		// 大写归一为小写
+		{"6F0A1B2C-3D4E-4F5A-8B6C-7D8E9F0A1B2C", "6f0a1b2c-3d4e-4f5a-8b6c-7d8e9f0a1b2c"},
+	}
+	for _, c := range cases {
+		if got := normalizeRequestId(c.in); got != c.want {
+			t.Fatalf("normalizeRequestId(%q)=%q want %q", c.in, got, c.want)
+		}
+	}
+}
+
+func TestNormalizeRequestId_Invalid(t *testing.T) {
+	cases := []string{
+		"",
+		"abc",
+		// 12 位短 hex（服务端自生成格式，不接受为前端传入 id）
+		"a1b2c3d4e5f6",
+		// 长度对但连字符位置错
+		"6f0a1b2c3-d4e-4f5a-8b6c-7d8e9f0a1b2c",
+		// 非 hex 字符
+		"6f0a1b2c-3d4e-4f5a-8b6c-7d8e9f0a1bzz",
+		// 注入尝试：换行/引号
+		"6f0a1b2c-3d4e-4f5a-8b6c-7d8e9f0a1\n2c",
+		"\"};alert(1);//-4f5a-8b6c-7d8e9f0a1b2c",
+		// 超长
+		"6f0a1b2c-3d4e-4f5a-8b6c-7d8e9f0a1b2c0",
+	}
+	for _, c := range cases {
+		if got := normalizeRequestId(c); got != "" {
+			t.Fatalf("normalizeRequestId(%q)=%q want empty", c, got)
+		}
+	}
+}
+
+// 共用 request_id 行为：前端带合法 UUID 沿用，非法/缺失服务端自生成 12 位 hex
+func TestRequestIdSharing(t *testing.T) {
+	// 合法 UUID → 沿用（归一小写）
+	if got := normalizeRequestId("6F0A1B2C-3D4E-4F5A-8B6C-7D8E9F0A1B2C"); got != "6f0a1b2c-3d4e-4f5a-8b6c-7d8e9f0a1b2c" {
+		t.Fatalf("合法 UUID 应沿用为 request_id，got %q", got)
+	}
+	// 非法 → 走服务端自生成分支
+	if normalizeRequestId("evil\ninjection") != "" {
+		t.Fatal("非法值应被丢弃并触发服务端自生成")
+	}
+	id := shortID(6)
+	if len(id) != 12 {
+		t.Fatalf("服务端自生成 request_id 应为 12 位 hex，got %q", id)
+	}
+	for i := 0; i < len(id); i++ {
+		c := id[i]
+		if !((c >= '0' && c <= '9') || (c >= 'a' && c <= 'f')) {
+			t.Fatalf("服务端自生成 request_id 含非 hex 字符: %q", id)
+		}
+	}
+}
+
+func TestViewSetsServerSentMsHeader(t *testing.T) {
+	rec := httptest.NewRecorder()
+	ctx := &Context{Resp: rec, RespData: Map{"status": 0}}
+
+	before := time.Now().UnixMilli()
+	ctx.View()
+	after := time.Now().UnixMilli()
+
+	h := rec.Header().Get("X-Server-Sent-Ms")
+	if h == "" {
+		t.Fatal("X-Server-Sent-Ms 未设置")
+	}
+	ms, err := strconv.ParseInt(h, 10, 64)
+	if err != nil {
+		t.Fatalf("X-Server-Sent-Ms=%q 非毫秒时间戳: %v", h, err)
+	}
+	if ms < before || ms > after {
+		t.Fatalf("X-Server-Sent-Ms=%d 不在 [%d,%d] 区间", ms, before, after)
+	}
+	if !strings.Contains(rec.Body.String(), "\"status\":0") {
+		t.Fatalf("响应体异常: %s", rec.Body.String())
+	}
+}