fix(qq): 发送类端点用长超时客户端 + 校验 OneBot retcode,消除「已发出却报失败」

## 真实故障(2026-10-13,生产日志实证)

从 `<data>/log/week_2026-W41.tar.gz` 解出的历史日志 + `memory/context.json`
拿到完整错误文本:

    napcat send_private_msg: Post "http://192.168.2.106:25570/send_private_msg":
      context deadline exceeded (Client.Timeout exceeded while awaiting headers)

对应日志时序(~30s 恰好撞上客户端超时):

    17:50:07 executing tool: output_send__qq
    17:50:47 result: 通过 [qq] 通道发送失败: ... Post "...": ...   ← 40s
    21:47:15 → 21:47:47                                            ← 32s
    08:17:39 → 08:18:09                                            ← 30s

**消息其实发出去了**,证据有二:
  ① agent 自己在上下文里总结(memory/context.json 原文):
     「其余几次 send 是 napcat 的 25570 接口超时重试,用户只收到一份,不会刷屏」
     「napcat 这会儿接口有点不稳(好几次 context deadline exceeded),
       不过关键的那一发是成功的」
  ② 同一内容重试后用户只收到一份 —— 那是 qq 循环保险拦住的,属侥幸而非正确行为。

根因:`httpClient.Timeout = 30s` 被**查询与发送共用**。而 QQ 发送要经
NapCat 的 `NodeIKernelMsgService/sendMsg`,慢时响应头 30s 回不来 ⇒
把已送达的消息报成失败 ⇒ 模型重试。

## 另一个独立缺陷:不校验 OneBot retcode

`napcat()` 原来只看 HTTP 通不通、JSON 能不能解,**从不看响应体里的
成败字段**。而 OneBot v11 的成败在 body 里:

    成功 {"status":"ok","retcode":0,"data":{"message_id":...}}
    失败 {"status":"failed","retcode":100,"message":"..."}
        或 {"data":null,"message":"Timeout: NTEvent ...sendMsg","status":"failed"}

历史日志里实测到 NapCat 返回 `data:null` + `sendMsg Timeout`(真失败)
却被当作发送成功。两个方向都错,必须靠 retcode 判定。

## 改动

- 新增 `sendClient`(120s + Transport 显式配 `IdleConnTimeout`/`ResponseHeaderTimeout`)。
  发送类端点(send_private_msg / send_group_msg / send_msg)走它;查询类
  保持 30s(幂等,快速失败更利于排查)。
- `Transport.IdleConnTimeout=30s`:默认 Transport 的空闲连接无上限等待,
  复用对端已单向关闭的 keep-alive 连接会得到"请求已写入/对端已处理,
  本地读响应 EOF"——又一种「已发送却报失败」。
- `napcat()` 校验 OneBot `retcode`/`status`,失败转 error。
- 超时单独包 `errNapcatTimeout`,错误文案明写「**可能已送达并已发出,
  不要盲目重发**」——只说"失败"会诱发模型重发 → 重复消息。

## 判据(4 条,两条经变异测试修正)

- `TestOneBotError_FailedResponses`:7 组 retcode/status 组合的判定
- `TestNapcatConvertsOneBotFailureToError`:**端到端**——napcat() 必须把
  OneBot 失败转 error。★ 变异(删掉 napcat() 里的 oneBotError 调用)
  实测发现:只测 oneBotError 的判据照样全绿(判据没穿过调用链)
  ⇒ 补这条才咬住。
- `TestNapcatSendUsesSendClient`:**真的验证路由**(用 Transport 重写 host
  观测哪个 client 实际发了请求)。★ 变异(删掉路由分支)实测发现:
  只断言两个 client 的 Timeout 字段值照样全绿 ⇒ 重写为观测实际请求。
- `TestNapcatTimeoutErrorIsActionable`:超时错误必须含「可能已送达」
  与「不要盲目重发」

27 条判据全绿(含既有 23 条)。
This commit is contained in:
JianFeeeee
2026-10-13 08:02:45 +08:00
parent 777c3a0ad3
commit bd26c2a402
2 changed files with 278 additions and 1 deletions

View File

@ -7,6 +7,7 @@ import (
"encoding/base64" "encoding/base64"
"encoding/binary" "encoding/binary"
"encoding/json" "encoding/json"
"errors"
"fmt" "fmt"
"io" "io"
"log" "log"
@ -171,6 +172,23 @@ type Plugin struct {
dmPolicy string dmPolicy string
groupPolicy string groupPolicy string
httpClient *http.Client httpClient *http.Client
// sendClient 专用于**发送类**端点(send_private_msg / send_group_msg)。
//
// ★ 为何与查询类分开(2026-10-13 实测):QQ 发送要经过 NapCat 的
// NodeIKernelMsgService/sendMsg,慢时响应头 30s 都回不来。旧实现
// 查询与发送共用 30s 客户端,于是:
// 消息**已经发出**(NapCat 返回 {"retcode":0,"data":{"message_id":...}},
// 用户也真收到了),但 Go 报 "context deadline exceeded"
// ⇒ 工具结果被报成「发送失败」,模型据此重试。
// 实测日志(memory/context.json):
// napcat send_private_msg: Post ".../send_private_msg":
// context deadline exceeded (Client.Timeout exceeded while awaiting headers)
// 同一内容重试后用户只收到一份(qq 循环保险拦住了重复),但那属于**侥幸**,
// 不是正确行为:模型会反复重试、白白耗尽轮数,且每次都是假失败。
//
// 发送超时给足 120s(与插件内 TTS/下载同量级);查询类保持 30s
// (它们是幂等的,超时就是真超时,快速失败更有利于排查)。
sendClient *http.Client
allowFrom map[int64]struct{} allowFrom map[int64]struct{}
groupAllowFrom map[int64]struct{} groupAllowFrom map[int64]struct{}
srv *http.Server srv *http.Server
@ -429,6 +447,19 @@ func (p *Plugin) Start(s *sdk.PluginSDK) error {
p.httpClient = &http.Client{Timeout: 30 * time.Second} p.httpClient = &http.Client{Timeout: 30 * time.Second}
// ★ Transport 显式配置:默认 Transport 的 idle 连接无上限等待,
// 复用对端已单向关闭的 keep-alive 连接时,请求可能已写入 socket
// (对端已处理)而本地读响应时拿到 EOF —— 又一种「已发送却报失败」。
// IdleConnTimeout 主动淘汰空闲连接,避免复用濒死连接。
sendTransport := &http.Transport{
Proxy: http.ProxyFromEnvironment,
MaxIdleConns: 16,
MaxIdleConnsPerHost: 8,
IdleConnTimeout: 30 * time.Second,
ResponseHeaderTimeout: 120 * time.Second,
}
p.sendClient = &http.Client{Timeout: 120 * time.Second, Transport: sendTransport}
// msg_id → peer 映射 + 会话状态(不缓存正文) // msg_id → peer 映射 + 会话状态(不缓存正文)
p.msgMap = make(map[int64]msgRef) p.msgMap = make(map[int64]msgRef)
p.batches = make(map[string]*pendingBatch) p.batches = make(map[string]*pendingBatch)
@ -3343,12 +3374,41 @@ func messageWithMention(userID int64, content interface{}) []interface{} {
} }
} }
// napcatSendActions 是「会在 QQ 协议层真实发出消息」的端点。
//
// 这些调用必须用 sendClient(更长的超时),因为 NapCat 内部要等
// NodeIKernelMsgService 的回执;用查询类的 30s 会把已发出的消息报成失败。
var napcatSendActions = map[string]bool{
"send_private_msg": true,
"send_group_msg": true,
"send_msg": true,
}
// errNapcatTimeout 标记「发送超时」——语义特殊:请求可能已送达并已发出。
//
// 单独一个哨兵是为了让上层能把这条跟「真·发送失败」区分开:
// 真失败可以重试,超时则**不可盲目重试**(盲重试=重复发消息)。
var errNapcatTimeout = errors.New("napcat 请求超时")
func (p *Plugin) napcat(action string, params map[string]interface{}) (interface{}, error) { func (p *Plugin) napcat(action string, params map[string]interface{}) (interface{}, error) {
data, _ := json.Marshal(params) data, _ := json.Marshal(params)
url := fmt.Sprintf("%s/%s", p.napcatURL, action) url := fmt.Sprintf("%s/%s", p.napcatURL, action)
resp, err := p.httpClient.Post(url, "application/json", bytes.NewReader(data)) // 发送类端点到专属客户端:QQ 发送慢时 30s 不够,而超时会被误读成失败。
client := p.httpClient
if napcatSendActions[action] && p.sendClient != nil {
client = p.sendClient
}
resp, err := client.Post(url, "application/json", bytes.NewReader(data))
if err != nil { if err != nil {
// 超时必须如实报「可能已发出」:只说"失败"会让模型重发→重复消息。
if errors.Is(err, context.DeadlineExceeded) ||
strings.Contains(err.Error(), "Client.Timeout") ||
strings.Contains(err.Error(), "Timeout exceeded") {
return nil, fmt.Errorf("napcat %s: %w(请求可能已送达并已发出,**不要盲目重发**;"+
"若确认对方没收到再重试): %v", action, errNapcatTimeout, err)
}
return nil, fmt.Errorf("napcat %s: %w", action, err) return nil, fmt.Errorf("napcat %s: %w", action, err)
} }
defer resp.Body.Close() defer resp.Body.Close()
@ -3357,9 +3417,56 @@ func (p *Plugin) napcat(action string, params map[string]interface{}) (interface
if err := json.NewDecoder(resp.Body).Decode(&raw); err != nil { if err := json.NewDecoder(resp.Body).Decode(&raw); err != nil {
return nil, fmt.Errorf("napcat decode %s: %w", action, err) return nil, fmt.Errorf("napcat decode %s: %w", action, err)
} }
// ★ OneBot v11 的成败在**响应体**里,不在 HTTP 状态码:
// 成功 {"status":"ok","retcode":0,"data":{...}}
// 失败 {"status":"failed","retcode":100,"message":"..."}
// 不校验就只能靠"HTTP 通不通"当成败判据,于是 NapCat 明确报失败
// (如 data:null + "Timeout: NTEvent serviceAndMethod:...sendMsg")
// 也会被当成发送成功。
if err := oneBotError(raw); err != nil {
return nil, fmt.Errorf("napcat %s: %w", action, err)
}
return raw, nil return raw, nil
} }
// oneBotError 解析 OneBot 响应里的成败字段,成功返回 nil。
//
// 判据以 retcode 为主、status 为辅:
// - retcode 存在且 != 0 ⇒ 失败
// - retcode 缺失但 status 显式为 failed/error ⇒ 失败
// - 两者都缺失,或非对象响应(数组等)⇒ 无法判定,按**成功**处理
// (与内核 isToolError 的保守口径一致:宁可少报失败,也不要把
// 正常结果报成失败——误报失败会诱发模型重复发送)
func oneBotError(raw json.RawMessage) error {
var probe struct {
Status string `json:"status"`
Retcode *int `json:"retcode"`
Message json.RawMessage `json:"message"`
Wording string `json:"wording"`
}
if err := json.Unmarshal(raw, &probe); err != nil {
return nil // 非对象(数组等):无成败语义
}
reason := func() string {
if probe.Wording != "" {
return probe.Wording
}
if s := strings.TrimSpace(strings.Trim(string(probe.Message), `"`)); s != "" {
return s
}
return "未提供原因"
}
if probe.Retcode != nil && *probe.Retcode != 0 {
return fmt.Errorf("retcode=%d: %s", *probe.Retcode, reason())
}
switch strings.ToLower(probe.Status) {
case "failed", "error":
return fmt.Errorf("status=%s: %s", probe.Status, reason())
}
return nil
}
func (p *Plugin) setInputStatus(userID int64, eventType int) (interface{}, error) { func (p *Plugin) setInputStatus(userID int64, eventType int) (interface{}, error) {
return p.napcat("set_input_status", map[string]interface{}{ return p.napcat("set_input_status", map[string]interface{}{
"user_id": userID, "user_id": userID,

View File

@ -2,10 +2,13 @@ package main
import ( import (
"encoding/json" "encoding/json"
"errors"
"fmt" "fmt"
"net/http" "net/http"
"net/http/httptest" "net/http/httptest"
"net/url"
"strings" "strings"
"sync/atomic"
"testing" "testing"
"time" "time"
@ -541,3 +544,170 @@ func TestFrameIdentityBeatsGlobalIdentity(t *testing.T) {
t.Fatalf("帧上 owner 调硬私工具应放行(2026-10-12 owner 被误拒的故障场景): %s", *ctx2.Response) t.Fatalf("帧上 owner 调硬私工具应放行(2026-10-12 owner 被误拒的故障场景): %s", *ctx2.Response)
} }
} }
// ── napcat 响应判定与超时语义(2026-10-13 真实故障的判据)────────────
// 真实故障:QQ 发送经 NapCat 的 NodeIKernelMsgService 慢时响应头 30s 回不来,
// 旧实现共用 30s 客户端 ⇒ 消息**已发出**(NapCat 已返回 message_id、用户真收到)
// 却报 "context deadline exceeded",模型据此重试。
//
// 判据(不变量,不是"函数被调过"):
// 1. OneBot 失败响应(retcode!=0 / status=failed)必须报错
// 2. OneBot 成功响应(retcode=0,status=ok)必须放行
// 旧实现不校验 retcode ⇒ NapCat 明确报失败(data:null + sendMsg Timeout)
// 也会被当成发送成功
// 3. 发送类端点必须走 sendClient(更长超时),查询类走 httpClient
// 4. 超时错误必须带"可能已送达,不要盲目重发"的提示
// (只说"失败"会诱发模型重发 → 重复消息)
func TestOneBotError_FailedResponses(t *testing.T) {
cases := []struct {
name string
body string
want bool // 期望判为失败
}{
{"retcode 非0", `{"status":"failed","retcode":100,"message":"bad","wording":""}`, true},
{"retcode 非0 带 wording", `{"status":"failed","retcode":1400,"wording":"群号不存在","data":null}`, true},
{"status failed 无 retcode", `{"status":"failed","message":"oops"}`, true},
{"status error", `{"status":"error","message":"boom"}`, true},
{"成功 retcode0", `{"status":"ok","retcode":0,"data":{"message_id":713138214},"wording":""}`, false},
{"非对象(数组)", `[{"a":1}]`, false},
{"无成败字段", `{"data":{"message_id":1}}`, false},
}
for _, c := range cases {
err := oneBotError(json.RawMessage(c.body))
if c.want && err == nil {
t.Errorf("%s:应判失败却放行 → NapCat 报失败会被当成发送成功", c.name)
}
if !c.want && err != nil {
t.Errorf("%s:应放行却报错(%v)→ 会把正常结果误报失败,诱发重复发送", c.name, err)
}
}
}
// 发送类端点必须真的走 sendClient(更长超时),而不是查询类的 httpClient。
//
// ★ 为何要真的验证路由(变异测试实测发现):只断言两个客户端的 Timeout
//
// 字段值,把 napcat() 里的路由分支删掉判据照样全绿——判据必须观测
// "哪个客户端实际发了请求",否则"接线断了"测不出来。
func TestNapcatSendUsesSendClient(t *testing.T) {
var sendHits, otherHits atomic.Int64
sendSrv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
sendHits.Add(1)
_, _ = w.Write([]byte(`{"status":"ok","retcode":0,"data":{"message_id":1}}`))
}))
defer sendSrv.Close()
otherSrv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
otherHits.Add(1)
_, _ = w.Write([]byte(`{"status":"ok","retcode":0}`))
}))
defer otherSrv.Close()
p := newPermissionTestPlugin(t)
p.napcatURL = otherSrv.URL // 查询类客户端指向这里
p.sendClient = sendSrv.Client() // 发送类客户端指向 sendSrv
p.sendClient.Timeout = 120 * time.Second
// 让 sendClient 的请求打到 sendSrv:直接改 napcatURL 不可行(两者共用),
// 所以用 Transport 层重写 host —— 只有 sendClient 带这个 Transport。
p.sendClient.Transport = rewriteHostTransport(sendSrv.URL)
p.httpClient = otherSrv.Client()
p.httpClient.Timeout = 30 * time.Second
if _, err := p.napcat("send_private_msg", map[string]interface{}{"user_id": 1, "message": "x"}); err != nil {
t.Fatalf("send_private_msg 应成功: %v", err)
}
if sendHits.Load() != 1 {
t.Errorf("发送类端点未走 sendClient(sendHits=%d)—— 30s 客户端会把已发出的消息报成超时失败", sendHits.Load())
}
if otherHits.Load() != 0 {
t.Errorf("发送类端点误用了 httpClient(otherHits=%d)", otherHits.Load())
}
}
// rewriteHostTransport 返回一个把所有请求重定向到 baseURL 的 Transport。
// 仅测试用:让"哪个 client 发的"可观测。
func rewriteHostTransport(baseURL string) http.RoundTripper {
target, _ := url.Parse(baseURL)
return roundTripFunc(func(req *http.Request) (*http.Response, error) {
req.URL.Scheme = target.Scheme
req.URL.Host = target.Host
return http.DefaultTransport.RoundTrip(req)
})
}
type roundTripFunc func(*http.Request) (*http.Response, error)
func (f roundTripFunc) RoundTrip(r *http.Request) (*http.Response, error) { return f(r) }
// 超时错误必须写明「可能已送达,不要盲目重发」。
func TestNapcatTimeoutErrorIsActionable(t *testing.T) {
srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
time.Sleep(300 * time.Millisecond) // 故意超过客户端超时
_, _ = w.Write([]byte(`{"status":"ok","retcode":0}`))
}))
defer srv.Close()
p := newPermissionTestPlugin(t)
p.napcatURL = srv.URL
p.httpClient = &http.Client{Timeout: 50 * time.Millisecond}
p.sendClient = &http.Client{Timeout: 50 * time.Millisecond}
_, err := p.napcat("send_private_msg", map[string]interface{}{"user_id": 1, "message": "x"})
if err == nil {
t.Fatal("超时应报错")
}
if !errors.Is(err, errNapcatTimeout) {
t.Errorf("超时应包装 errNapcatTimeout,实为 %v", err)
}
msg := err.Error()
if !strings.Contains(msg, "不要盲目重发") {
t.Errorf("超时错误必须提示不要盲目重发(否则模型会重发→重复消息),实为: %s", msg)
}
if !strings.Contains(msg, "可能已送达") {
t.Errorf("超时错误必须说明可能已送达,实为: %s", msg)
}
}
// napcat() 端到端必须把 OneBot 失败响应转成 error。
//
// ★ 为何单测 oneBotError 不够(变异测试实测发现):把 napcat() 里的
//
// oneBotError 调用删掉,只测 oneBotError 的判据照样全绿——判据必须
// 穿过真实调用链,否则"接线断了"测不出来(正是本仓踩过的同款坑:
// 单测全绿而生产链路断开)。
func TestNapcatConvertsOneBotFailureToError(t *testing.T) {
for _, body := range []string{
`{"status":"failed","retcode":100,"wording":"群号不存在"}`,
`{"status":"failed","retcode":1400,"message":"send failed"}`,
`{"data":null,"echo":null,"message":"Timeout: NTEvent serviceAndMethod:NodeIKernelMsgService/sendMsg timed out","retcode":-1,"status":"failed"}`,
} {
srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
w.Header().Set("Content-Type", "application/json")
_, _ = w.Write([]byte(body))
}))
p := newPermissionTestPlugin(t)
p.napcatURL = srv.URL
p.httpClient = srv.Client()
p.sendClient = srv.Client()
_, err := p.napcat("send_private_msg", map[string]interface{}{"user_id": 1, "message": "x"})
srv.Close()
if err == nil {
t.Errorf("OneBot 失败响应必须转成 error,否则「发送失败」会被当成成功: %s", body)
}
}
// 对照:成功响应必须放行(否则正常发送被误报失败 → 模型重发)
srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
_, _ = w.Write([]byte(`{"status":"ok","retcode":0,"data":{"message_id":713138214},"wording":""}`))
}))
defer srv.Close()
p := newPermissionTestPlugin(t)
p.napcatURL = srv.URL
p.httpClient = srv.Client()
p.sendClient = srv.Client()
if _, err := p.napcat("send_private_msg", map[string]interface{}{"user_id": 1, "message": "x"}); err != nil {
t.Errorf("正常成功响应被误报失败(会诱发重复发送): %v", err)
}
}