diff --git a/internal/runtime/trace/errortoken.go b/internal/runtime/trace/errortoken.go index 59da7f3..7852719 100644 --- a/internal/runtime/trace/errortoken.go +++ b/internal/runtime/trace/errortoken.go @@ -2,10 +2,10 @@ package trace import "strings" -// 本文件是「上游错误信封里的自由文本字段能不能出镜」的唯一守卫。 +// 本文件是「上游错误字段能不能出镜」的唯一守卫。 // -// 背景：UpstreamErrorInfo 只解析 error.code / error.type 两个字段，而它们是**自由 -// 文本面** —— 主流上游里它们确实是枚举（invalid_request_error、overloaded_error、 +// 背景：UpstreamErrorInfo 只解析 error.code / error.type 两个字段，而它们**可能**是 +// 自由文本面 —— 主流上游里它们确实是枚举（invalid_request_error、overloaded_error、 // Throttling.RateQuota …），但网关、代理与兼容层可以往里面塞任何东西，包括回显的 // 用户原文。因此这两个字段出镜前必须像令牌：短、只含标识符字符。 // @@ -15,9 +15,25 @@ import "strings" // // 🔴 M49 收口：守卫的**应用点**同样收进本包 —— UpstreamError 构造时对 error.code / // error.type 各调一次（构造即安全，调用点不必也不该再守），构造后的注入走 -// UpstreamErrorInfo.SetCode / SetType（同一道守卫）。因此本包之外的 Go 代码里 -// **不应出现 ErrorToken 调用**：出现了就意味着又回到「调用方逐点补」的漂移形态 -// （M48 复审的 finding 正是这么漏的：httpclient / vision / embedding / weixin 四处）。 +// UpstreamErrorInfo.SetCode / SetType（同一道守卫）。 +// +// 🔴 M50 修正口径（**取代**原先「本包之外的 Go 代码里不应出现 ErrorToken 调用」的说法； +// 那条已被证伪：M50 之后本包外确有正当调用点）。判据是**字段的类别**，不是调用点的位置： +// +// - **协议枚举字段**（信封的 status / code / type、DashScope 的 request_id 这类 +// 「一格一个值」的字段）**可以**在渲染点调用本守卫后再出镜。真实取值是短令牌 ⇒ +// 原样通过；上游若在枚举位上塞散文 ⇒ 整体变空串。现行调用点： +// `plugins/channels/qq_obv11`（信封 status，两处）、`plugins/channels/weixin_ilink` +// （扫码 status 与 redirect_host）、`runtime/multimodal/voice/dashscope_error.go` +// （request_id —— M50 之前就存在的正当例外）。 +// - **自由文本字段**（message / description / msg / wording / 服务端错误说明头 …） +// **不得**靠本守卫出镜。它们的问题不是形状（短的人话照样像令牌），而是取值的 +// 控制权：上游想写什么就写什么，而它写的常常是被拒的请求正文 —— 也就是她的话。 +// 这类字段的口径是**默认不带**；要带必须显式 opt-in，并在保留时过 RedactText +// （见 trace.UpstreamError 的 WithUpstreamMessage 与 +// internal/channel/adapter/httpclient 的 WithEnvelopeMessage）。 +// +// 简言之：本守卫回答「这个令牌形状的枚举值能不能露」，不回答「这段人话能不能露」。 // maxErrorTokenBytes 是 error.code / error.type / request_id 允许出镜的长度上限。 // 64 字节足够容纳任何真实的枚举与 UUID 形状，又远小于「一段话」。 diff --git a/plugins/channels/weixin_ilink/login.go b/plugins/channels/weixin_ilink/login.go index 74cb479..04372a0 100644 --- a/plugins/channels/weixin_ilink/login.go +++ b/plugins/channels/weixin_ilink/login.go @@ -10,6 +10,8 @@ import ( "net/url" "strconv" "time" + + "git.yeij.top/AskaEth/Cyrene_v2/internal/runtime/trace" ) // loginPollInterval 是 Connect 轮询二维码确认状态的默认间隔。它是文档记录的约 1s @@ -86,10 +88,17 @@ func (a *Adapter) runLogin(sess *loginSession, sessCtx context.Context) { } // 跟踪线上的原始阶段，便于 StartLogin 保护「已扫描/确认中」的绑定不被重新取码。 // 仅在状态变化时打日志以避免噪声，且绝不记录 qrcode 标识符或 token。 + // + // 🔴 status 是**上游字段**：进日志前过令牌守卫（trace.ErrorToken）。真实取值 + // （wait / scaned / confirmed / scaned_but_redirect / …）全是短令牌 ⇒ 原样通过； + // 上游若在这一栏塞散文，这一行就是空串 —— 与 qq_obv11 的 status、 + // trace.UpstreamError 的 code/type 同一道守卫（M50 复审的第五个出口）。 + // **控制流仍用原值**：setPhase 与下面的 switch 都读 status.Status，渲染口径 + // 不参与判定。 sess.setPhase(status.Status) if status.Status != prevStatus { prevStatus = status.Status - a.log.Info("weixin_ilink: get_qrcode_status", "status", status.Status) + a.log.Info("weixin_ilink: get_qrcode_status", "status", trace.ErrorToken(status.Status)) } switch status.Status { @@ -115,8 +124,13 @@ func (a *Adapter) runLogin(sess *loginSession, sessCtx context.Context) { a.setLoginState(LoginStatusWaiting, loginScannedDetail) case "scaned_but_redirect": if status.RedirectHost != "" { + // 🔴 路由用**原值**（下一行），日志只留守卫后的形态：redirect_host 是上游 + // 字段，与上面的 status 同一道令牌守卫（trace.ErrorToken）。真实主机名通过； + // 带端口（`h:8443`）或散文的整体丢弃 —— 宁可日志少一个字段，也不让这一栏 + // 成为第二个正文通道。 a.setPollBaseURL(status.RedirectHost) - a.log.Info("weixin_ilink: idc redirect, switching polling host", "host", status.RedirectHost) + a.log.Info("weixin_ilink: idc redirect, switching polling host", + "host", trace.ErrorToken(status.RedirectHost)) } else { a.log.Warn("weixin_ilink: scaned_but_redirect without redirect_host, continuing on current host") } @@ -240,7 +254,12 @@ func (a *Adapter) fetchQRCode(ctx context.Context) (qrcodeResp, error) { } // 只记录可渲染的二维码 URL，绝不记录原始 qrcode 标识符（它是回传给 // get_qrcode_status 的密钥）。时间戳由 logger 附加。 - a.log.Info("weixin_ilink: get_bot_qrcode ok", "url", out.QrcodeImgContent) + // + // 🔴 URL 一律走 trace.MaskQuery（M50 复审补扫）：它是**上游给的**串，可能是带签名 + // 的图片地址，也可能整段是 `data:` 内联图 —— 原样落日志等于把二维码（扫码即绑定） + // 抄进一个会被 tail、采集、粘进工单的面。MaskQuery 打码凭据类 query 值并保留路径， + // 解析不出 host（data: URI、畸形串）时回空串而**不**回原串。 + a.log.Info("weixin_ilink: get_bot_qrcode ok", "url", trace.MaskQuery(out.QrcodeImgContent)) return out, nil } diff --git a/plugins/channels/weixin_ilink/login_admin.go b/plugins/channels/weixin_ilink/login_admin.go index aebcaaf..d6d3235 100644 --- a/plugins/channels/weixin_ilink/login_admin.go +++ b/plugins/channels/weixin_ilink/login_admin.go @@ -11,6 +11,8 @@ import ( "fmt" "sync" "time" + + "git.yeij.top/AskaEth/Cyrene_v2/internal/runtime/trace" ) // Adapter.LoginStatus 上报的登录状态取值。 @@ -119,7 +121,10 @@ func (a *Adapter) StartLogin(ctx context.Context) (LoginQR, error) { // 无条件复用当前二维码加以保护。只有仍未被扫描、且已过那个极小复用窗口的 // 二维码才会被重新生成，使显式的「刷新二维码」能拿到全新码。 if sess.confirmingPhase() { - a.log.Info("weixin_ilink: login in progress, reusing qrcode", "phase", sess.currentPhase()) + // phase 是**上游字段**（`get_qrcode_status` 的 status 原值经 setPhase 存下）， + // 因此进日志前过令牌守卫 —— 与 login.go 里那一行同一道（M50 复审：同一字段 + // 的第二个出口）。`confirmingPhase()` 的判定用的是原值，不受渲染口径影响。 + a.log.Info("weixin_ilink: login in progress, reusing qrcode", "phase", trace.ErrorToken(sess.currentPhase())) return LoginQR{Qrcode: sess.qrcode, Image: sess.image}, nil } // 码仍然新鲜或已被扫描时都返回同一个码——一律复用、绝不替换，使进行中的 @@ -127,7 +132,7 @@ func (a *Adapter) StartLogin(ctx context.Context) (LoginQR, error) { // 用户扫码期间取消会话。只有真正过期（超过服务端 60s TTL）且从未被扫描的码 // 才会重新生成。 if time.Since(sess.startedAt) < 60*time.Second { - a.log.Info("weixin_ilink: login in progress, reusing qrcode", "phase", sess.currentPhase()) + a.log.Info("weixin_ilink: login in progress, reusing qrcode", "phase", trace.ErrorToken(sess.currentPhase())) return LoginQR{Qrcode: sess.qrcode, Image: sess.image}, nil } // 码已过期（>60s）且从未被扫描：生成新码，并取消旧的那次（已过期、未扫描的） diff --git a/plugins/channels/weixin_ilink/login_log_redaction_test.go b/plugins/channels/weixin_ilink/login_log_redaction_test.go new file mode 100644 index 0000000..613979a --- /dev/null +++ b/plugins/channels/weixin_ilink/login_log_redaction_test.go @@ -0,0 +1,218 @@ +package weixin_ilink + +// 本文件钉住扫码登录期**上游字段进日志**的边界（M50 复审的第五个出口）： +// +// - `get_qrcode_status` 的 `status` 与 `scaned_but_redirect` 的 `redirect_host` 此前 +// 原样写进 INFO —— 两个都是上游字段，此前不过 `trace.ErrorToken`、不过 +// `RedactText`、也没有长度上限。现在两者都过令牌守卫后才出镜。 +// - 🔴 **控制流仍用原值**：状态机读 `status.Status`、路由读 `status.RedirectHost`。 +// 这条比「日志干净」更容易被修坏 —— 一个图省事的修法是把守卫后的值喂给 +// `setPollBaseURL`，那会让带端口的合法重定向主机整体失效。 +// +// 两条用例的变异方向各一：把守卫从日志里去掉 ⇒ 哨兵出现（红）；把守卫**挪进**控制流 +// ⇒ 第二条用例的重定向落不到上游给的主机上（红）。 + +import ( + "bytes" + "context" + "log/slog" + "net/http" + "strings" + "sync" + "testing" + "time" +) + +// loginProse 是一段「像人话、不像协议令牌」的上游字段值：它若出现在日志里，就说明这一栏 +// 又是一个不受控的正文通道。 +const loginProse = "她刚才说的那句话" + +// syncBuffer 让后台登录 goroutine 的日志写入与测试的读取不打架（-race 下也成立）。 +type syncBuffer struct { + mu sync.Mutex + b bytes.Buffer +} + +func (s *syncBuffer) Write(p []byte) (int, error) { + s.mu.Lock() + defer s.mu.Unlock() + return s.b.Write(p) +} + +func (s *syncBuffer) String() string { + s.mu.Lock() + defer s.mu.Unlock() + return s.b.String() +} + +// newLoggingScriptedAdapter 与 newScriptedAdapter 相同，但把日志收进 buf 供断言。 +func newLoggingScriptedAdapter(t *testing.T, cfg Config, tr http.RoundTripper, buf *syncBuffer) *Adapter { + t.Helper() + ad, err := New(cfg, &http.Client{Transport: tr}, slog.New(slog.NewJSONHandler(buf, nil))) + if err != nil { + t.Fatalf("New: %v", err) + } + return ad +} + +// TestStartLogin_ProseStatusNeverReachesLog status 喂散文 ⇒ 日志里那一栏是空串， +// 哨兵一个字都搜不到；而控制流照旧（散文不匹配任何 case ⇒ 继续轮询，直到窗口结束）。 +func TestStartLogin_ProseStatusNeverReachesLog(t *testing.T) { + t.Parallel() + var buf syncBuffer + tr := &scriptedTransport{ + qr: []byte(scriptedQR), + statusFn: func(int) []byte { return []byte(`{"status":"` + loginProse + `"}`) }, + } + ad := newLoggingScriptedAdapter(t, Config{ + BaseURL: scriptedBaseURL, LoginInterval: time.Millisecond, LoginTimeout: 300 * time.Millisecond, + }, tr, &buf) + + if _, err := ad.StartLogin(context.Background()); err != nil { + t.Fatalf("StartLogin: %v", err) + } + waitFor(t, func() bool { + s, _ := ad.LoginStatus(context.Background()) + return s == LoginStatusFailed + }) + + line := buf.String() + if line == "" { + t.Fatal("扫码轮询一条日志都没有（静默即缺陷）") + } + if strings.Contains(line, loginProse) { + t.Fatalf("上游 status 原文进了日志：%s", line) + } + // 守卫的实际效果：散文 ⇒ 空串（不是「截断」也不是「保留前几个字」）。 + if !strings.Contains(line, `"status":""`) { + t.Fatalf("散文 status 没有收敛成空串（令牌守卫没生效？）：%s", line) + } + // 控制流不受影响：散文不匹配任何 case ⇒ 一直轮询到窗口结束（≥2 次），而不是 + // 被当成某个阶段直接失败/确认。 + if n := len(tr.hosts()); n < 2 { + t.Fatalf("status 轮询 %d 次, want >= 2（散文 status 不该改变控制流）", n) + } + if ad.IsConnected() { + t.Fatal("散文 status 被当成了成功（控制流被渲染口径污染）") + } +} + +// TestStartLogin_ProseRedirectHostNeverReachesLog redirect_host 喂散文 ⇒ 日志里没有它， +// 而路由**照旧**切到上游给的那个主机（证明守卫只作用于渲染，没有混进控制流）。 +func TestStartLogin_ProseRedirectHostNeverReachesLog(t *testing.T) { + t.Parallel() + var buf syncBuffer + tr := &scriptedTransport{ + qr: []byte(scriptedQR), + statusFn: func(n int) []byte { + if n == 1 { + return []byte(`{"status":"scaned_but_redirect","redirect_host":"` + loginProse + `"}`) + } + return []byte(`{"status":"confirmed","bot_token":"tok-x","ilink_bot_id":"bot-x",` + + `"ilink_user_id":"o-1","baseurl":"https://ilinkai.weixin.qq.com"}`) + }, + } + ad := newLoggingScriptedAdapter(t, Config{ + BaseURL: scriptedBaseURL, LoginInterval: time.Millisecond, LoginTimeout: 5 * time.Second, + }, tr, &buf) + + if _, err := ad.StartLogin(context.Background()); err != nil { + t.Fatalf("StartLogin: %v", err) + } + waitFor(t, func() bool { + s, _ := ad.LoginStatus(context.Background()) + return s == LoginStatusConfirmed + }) + + line := buf.String() + if strings.Contains(line, loginProse) { + t.Fatalf("上游 redirect_host 原文进了日志：%s", line) + } + if !strings.Contains(line, `"host":""`) { + t.Fatalf("散文 redirect_host 没有收敛成空串（令牌守卫没生效？）：%s", line) + } + // 🔴 控制流仍用原值：第二次轮询必须落在上游给的那个主机上。 + hosts := tr.hosts() + if len(hosts) < 2 { + t.Fatalf("status 轮询 %d 次, want >= 2", len(hosts)) + } + if hosts[1] != loginProse { + t.Fatalf("第二次轮询的主机 = %q, want 上游给的 redirect_host 原值（控制流被守卫污染）", hosts[1]) + } +} + +// TestStartLogin_ProsePhaseNeverReachesLog 同一个上游 status 还有**第二个日志出口**： +// 复用二维码时那条 INFO 打的是 `sess.currentPhase()`（setPhase 存下的上游原值）。它现在 +// 过同一道令牌守卫。变异：把守卫从这一行去掉 ⇒ 本用例红。 +func TestStartLogin_ProsePhaseNeverReachesLog(t *testing.T) { + t.Parallel() + var buf syncBuffer + tr := &scriptedTransport{ + qr: []byte(scriptedQR), + statusFn: func(int) []byte { return []byte(`{"status":"` + loginProse + `"}`) }, + } + ad := newLoggingScriptedAdapter(t, Config{ + BaseURL: scriptedBaseURL, LoginInterval: time.Millisecond, LoginTimeout: 300 * time.Millisecond, + }, tr, &buf) + + if _, err := ad.StartLogin(context.Background()); err != nil { + t.Fatalf("StartLogin: %v", err) + } + // 等后台轮询把 phase 填成上游原值，再点第二次「扫码登录」走复用分支。 + waitFor(t, func() bool { return len(tr.hosts()) >= 1 }) + if _, err := ad.StartLogin(context.Background()); err != nil { + t.Fatalf("StartLogin (reuse): %v", err) + } + waitFor(t, func() bool { + s, _ := ad.LoginStatus(context.Background()) + return s == LoginStatusFailed + }) + + line := buf.String() + if strings.Contains(line, loginProse) { + t.Fatalf("上游 status 经 currentPhase() 进了第二条日志：%s", line) + } + if !strings.Contains(line, `"phase":""`) { + t.Fatalf("复用二维码那条 INFO 的 phase 没有过令牌守卫：%s", line) + } + // 控制流不受影响：散文 phase 不满足 confirmingPhase，复用走的是「码仍新鲜」那一支， + // 返回的仍是同一个码。 + if qr := ad.loginSession; qr != nil && qr.qrcode != "qr-r" { + t.Fatalf("复用分支返回的 qrcode = %q, want qr-r", qr.qrcode) + } +} + +// TestStartLogin_QrcodeURLLogIsMasked get_bot_qrcode 的 `qrcode_img_content` 也是 +// **上游给的串**（可能是带签名的图片地址，也可能整段是 data: 内联图）。它进日志前走 +// trace.MaskQuery：凭据类 query 值打码、路径保留；解析不出 host 时回空串（data: URI +// 就是这么被整体挡掉的）。变异：改回原串 ⇒ 本用例立刻红。 +func TestStartLogin_QrcodeURLLogIsMasked(t *testing.T) { + t.Parallel() + const sig = "SIG-SECRET-123" + var buf syncBuffer + tr := &scriptedTransport{ + qr: []byte(`{"qrcode":"qr-1","qrcode_img_content":"https://img.example/qr.png?sig=` + sig + `&size=200"}`), + statusFn: func(int) []byte { + return []byte(`{"status":"confirmed","bot_token":"tok-x","ilink_bot_id":"bot-x","ilink_user_id":"o-1"}`) + }, + } + ad := newLoggingScriptedAdapter(t, Config{ + BaseURL: scriptedBaseURL, LoginInterval: time.Millisecond, LoginTimeout: 5 * time.Second, + }, tr, &buf) + + if _, err := ad.StartLogin(context.Background()); err != nil { + t.Fatalf("StartLogin: %v", err) + } + waitFor(t, func() bool { + s, _ := ad.LoginStatus(context.Background()) + return s == LoginStatusConfirmed + }) + + line := buf.String() + if strings.Contains(line, sig) { + t.Fatalf("二维码图片地址的签名参数原样进了日志：%s", line) + } + if !strings.Contains(line, "https://img.example/qr.png") || !strings.Contains(line, "sig=***") { + t.Fatalf("打码后把可读的路径也丢了（诊断面）：%s", line) + } +}