diff --git a/docs/zh/toolcall-parallel-execution-plan.md b/docs/zh/toolcall-parallel-execution-plan.md index 02855cc..b9e61c1 100644 --- a/docs/zh/toolcall-parallel-execution-plan.md +++ b/docs/zh/toolcall-parallel-execution-plan.md @@ -503,3 +503,72 @@ waiter 有**两条**设备桥启动路径: 脚本本身完全正常、备份逻辑没问题,只是"明明喂了 yes 却什么也没发生"。 已给 5 处 `ssh` 统一加 `-n`。 + +--- + +## 附:生产日志里的两个 toolcall 告警(2026-09-27 21:0x 排查) + +部署后逐条核对了 `homeagent.service` 的告警。结论:**适配器无缺陷; +toolcall 侧一个真缺陷(已修)、一个插件侧 bug(内核自愈,非内核缺陷)。** + +### 适配器:干净 + +| 检查项 | 次数 | +| --- | --- | +| `finish_reason=length`(输出截断) | **0** | +| `unmarshal unified response` 失败 | **0** | +| 流式分片解析错误 | **0** | +| `非法 JSON 帧` | 11,**全在 19:46:03–09 启动握手期**,此后 3 小时零发生 | + +`stream_index` 透传亦已核实:生产 `adapters/openai.lua:122` 与仓库版一致。 + +### ① `has empty arguments` —— 真缺陷,已修 + +原始响应里参数**完好**: + +```json +"tool_calls":[{"function":{"arguments":"{}","name":"clawhubadapter_list"},...}] +``` + +根因:诊断条件用 `len(tc.Arguments)==0 && RawArguments==""`,而 +`parseToolArguments("{}")` 返回**非 nil 的空 map** ⇒ 零参数工具 +(`seq_list` / `*_list` / `seq_help`,其 `properties` 本就是 `{}`)全部误报。 +部署后共 **14 次**。 + +**危害不是"日志吵"**,而是这条诊断的本职是抓「上游/适配器真的丢了参数」—— +真发生时会被这堆噪音淹没。**诊断日志失去信噪比就等于没有。** + +修法:新增 `argsLookDropped(rawArgs)`,判 `RawArguments` 原文而非解析后的 map: +空串/空白 ⇒ 真丢;能解析成 JSON(哪怕是 `{}`)⇒ 没丢;解析失败(半截 JSON)⇒ 等同丢失。 + +判据 3 条,其中 `TestArgsLookDroppedEndToEnd` 用**日志里出现过的真实 body** +走 `normalizeOpenAIToolCalls` 到判定的完整接缝 —— 单测过了但接缝不对的情况, +只有端到端才抓得到。 + +### ② `重复申请 stage 锁` —— 插件侧 bug,内核自愈正常 + +``` +stage.go:106 qq stage before_toolcall 失败后强制释放其持有的 stage 锁 +stages.go:260 before_toolcall handler error: 插件 qq 重复申请 stage 锁(handler 内不应嵌套加锁) +``` + +**不要当内核缺陷去修。** 链路是: + +1. `proc_main.go.tmpl:1569` —— SDK 生成的模板在**每个** stage handler 入口 + **自动**调 `callCoreVoid("stage.lock", nil)`(跨进程写锁,内核仲裁) +2. `lock.go:51` —— 锁**不可重入**:`l.held && l.owner == plugin` 即报错 +3. 所以只要**同一次 `before_toolcall` 被触发两次且首次未释放**,就会命中 + +已排查并排除的可能:qq 的 `beforeToolcall`(`plugin.go:1303-1350`)函数体里 +只有 `ctx.Lock()`(SDK **数据**锁,与 proc stage 锁是两把锁)与 +`currentToolAllowed` / `clearPreviousDenial` 等纯本地调用,**无任何再次触发 stage 的路径**。 + +⇒ 成因在**插件进程侧的运行时**(编译进 `plugin.bin`),不在 example/qq 的业务代码里。 +生产 `plugin.bin` 是 **9月14日**的独立构建产物,**不随 homed 部署** —— +要修需改 SDK 模板并重编该二进制,改动面比内核大得多。 + +**内核这边的行为是正确的**:`stage.go:102-106` 在插件持锁失败时强制释放, +注释写明这是"锁仲裁回内核"的自愈机制(实验 9),目的正是**避免后续插件死锁**; +`stages.go:258` 把错误收进 `ctx.Errors` 而不中断流程,所以那轮 212 秒正常跑完。 + +⇒ 5 次告警全部有惊无险。**唯一风险**是:哪天自愈逻辑变动,就是真死锁。 diff --git a/internal/agent/api/emptyargs_diag_test.go b/internal/agent/api/emptyargs_diag_test.go new file mode 100644 index 0000000..ff8a28b --- /dev/null +++ b/internal/agent/api/emptyargs_diag_test.go @@ -0,0 +1,92 @@ +package api + +import ( + "encoding/json" + "testing" +) + +// `has empty arguments` 诊断日志在部署后的生产日志里出现了 14 次, +// 全部是误报。原始响应(从日志里扒出来的)参数**完好**: +// +// "tool_calls":[{"function":{"arguments":"{}","name":"clawhubadapter_list"},...}] +// +// 根因:`parseToolArguments("{}")` 走 string 分支 → `json.Unmarshal("{}", &m)` +// 成功且 `m != nil`(**非 nil 的空 map**)⇒ 返回空 map。而诊断条件是 +// `len(args)==0 && RawArguments==""`,于是命中。 +// +// 被点名的全是**零参数工具**(seq_list / *_list / seq_help,它们的 +// `properties` 本来就是 `{}`)。 +// +// ## 为什么要紧 +// +// 不是"日志吵",是它**占用了本该报真问题的位置**:这条诊断存在的意义 +// 是抓「上游/适配器真的把参数丢了」,真发生时会被这堆噪音淹没。 +// 诊断日志一旦失去信噪比就等于没有。 +func TestEmptyArgumentsDiagnosticIgnoresExplicitEmptyObject(t *testing.T) { + cases := []struct { + name string + rawArgs string + wantLog bool + }{ + // 上游明确给了空对象 ⇒ 参数没丢,是零参数工具的正常形态 + {"显式空对象 {}", "{}", false}, + {"显式空对象带空格 { }", " { } ", false}, + // 真正丢了参数:连 "{}" 都没有 + {"完全缺失", "", true}, + {"只有空白", " ", true}, + } + for _, c := range cases { + t.Run(c.name, func(t *testing.T) { + got := argsLookDropped(c.rawArgs) + if got != c.wantLog { + t.Errorf("argsLookDropped(%q) = %v,期望 %v", c.rawArgs, got, c.wantLog) + } + }) + } +} + +// 上游给的是**非空**参数时,当然不能报。 +func TestArgsLookDroppedIgnoresNonEmpty(t *testing.T) { + for _, raw := range []string{`{"a":1}`, `{"device_id":"x"}`, `{"path":"/tmp"}`} { + if argsLookDropped(raw) { + t.Errorf("argsLookDropped(%q) = true,非空参数不应被判为丢失", raw) + } + } +} + +// 端到端:从真实的 tool_call 形态走到判定,确认零参数工具不报、 +// 真丢失要报。这是防止"单测过了但接缝不对"。 +func TestArgsLookDroppedEndToEnd(t *testing.T) { + // 日志里出现过的真实 body + const zeroParamBody = `{"choices":[{"message":{"tool_calls":[ + {"function":{"arguments":"{}","name":"seq_list"},"id":"a","type":"function"}]}}]}` + const droppedBody = `{"choices":[{"message":{"tool_calls":[ + {"function":{"name":"seq_list"},"id":"a","type":"function"}]}}]}` + + // 用 openAIToolCall —— normalizeOpenAIToolCalls 的真实入参类型。 + // (先前误用 apiToolCall,那是**非流式**路径的结构,接缝不对。) + normalize := func(body string) []ToolCall { + var resp struct { + Choices []struct { + Message struct { + ToolCalls []openAIToolCall `json:"tool_calls"` + } `json:"message"` + } `json:"choices"` + } + if err := json.Unmarshal([]byte(body), &resp); err != nil { + t.Fatalf("解析失败: %v", err) + } + return normalizeOpenAIToolCalls(resp.Choices[0].Message.ToolCalls) + } + + for _, tc := range normalize(zeroParamBody) { + if argsLookDropped(tc.RawArguments) { + t.Errorf("零参数工具 %q 被误报为参数丢失", tc.Name) + } + } + for _, tc := range normalize(droppedBody) { + if !argsLookDropped(tc.RawArguments) { + t.Errorf("真丢失参数的 %q 未被报出 —— 这条诊断会失效", tc.Name) + } + } +} diff --git a/internal/agent/api/provider.go b/internal/agent/api/provider.go index 2788e08..5a2a247 100644 --- a/internal/agent/api/provider.go +++ b/internal/agent/api/provider.go @@ -408,9 +408,16 @@ func (p *LuaAdaptedProvider) Chat(ctx context.Context, req *CompletionRequest) ( return nil, fmt.Errorf("unmarshal unified response: %w (body: %s)", err, unifiedJSON) } - // 诊断:tool_calls 存在但参数为空——上游/适配器丢参数,打印原始响应片段定位 + // 诊断:tool_calls 存在但参数为空——上游/适配器丢参数,打印原始响应片段定位。 + // + // ★ 判据是 argsLookDropped(tc.RawArguments),不是 len(tc.Arguments)==0。 + // + // 零参数工具(seq_list / *_list / seq_help,properties 本来就是 {}) + // 上游会明确回 "arguments":"{}"。旧判定把"空 map"当"丢了参数", + // 部署后误报 14 次 —— 而这条诊断的本职是抓**真丢参数**, + // 噪音会把真信号淹掉。详见 argsLookDropped。 for _, tc := range result.ToolCalls { - if len(tc.Arguments) == 0 && tc.RawArguments == "" { + if argsLookDropped(tc.RawArguments) { log.Printf("[provider:%s] tool_call %s (%s) has empty arguments; raw body head: %s", p.name, tc.Name, tc.ID, string(rawResp[:min(len(rawResp), 400)])) } @@ -660,6 +667,31 @@ func normalizeStreamToolCall(tc openAIToolCall) ToolCall { } } +// argsLookDropped 报告「上游/适配器把 tool_call 的参数丢了」。 +// +// 上游 JSON 里 arguments 有三种形态,只有第一种是真丢参数: +// +// "arguments":"{}" → 零参数工具的正常形态,不是丢失(生产误报 14 次) +// "arguments":"{\"a\":1}" → 正常 +// 无 arguments 键 / 空串 → 真的丢了 +// +// 刻意**不看**解析后的 Arguments map:`parseToolArguments("{}")` 返回的是 +// 非 nil 的空 map,用 len()==0 判定必然误伤零参数工具。 +func argsLookDropped(rawArgs string) bool { + trimmed := strings.TrimSpace(rawArgs) + // 上游没给 arguments 键时 Go 侧拿到空串;给空白也等价于没给。 + if trimmed == "" { + return true + } + // 显式的空 JSON 对象:解析成功但没有字段 ⇒ 上游确实回了参数。 + var probe map[string]json.RawMessage + if err := json.Unmarshal([]byte(trimmed), &probe); err == nil { + return false + } + // 解析失败(如 arguments 是一段半截 JSON)——参数本身就是坏的,等同于丢失。 + return true +} + func parseToolArguments(v interface{}) map[string]interface{} { switch x := v.(type) { case nil: @@ -750,6 +782,7 @@ func pickFirstInt(a, b int) int { } return b } + // streamHTTPClient 返回专用的流式 HTTP client(懒初始化)。 // SSE 长连接不能套整体超时(非流式 180s 会在长流中途报断), // 只保留拨号/握手超时。