From 6a83257ecf73669013ff8b4a230fddbf1d95ac9f Mon Sep 17 00:00:00 2001 From: yibo Date: Thu, 20 Aug 2026 16:36:10 +0800 Subject: [PATCH] fix(budget): 墙钟只算 run 真的在跑的时间，不算挂起等人的时间 --- server/services/graph-engine.js | 67 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++----- server/services/graph-run-sse.js | 9 +++++++++ server/tests/unit/budget-wallclock-active.test.js | 128 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ server/tests/unit/goal-task-acceptance.test.js | 20 +++++++++++++++++--- 4 files changed, 216 insertions(+), 8 deletions(-) create mode 100644 server/tests/unit/budget-wallclock-active.test.js diff --git a/server/services/graph-engine.js b/server/services/graph-engine.js index de4b226..d1b3777 100644 --- a/server/services/graph-engine.js +++ b/server/services/graph-engine.js @@ -2248,6 +2248,64 @@ function readBudget(run) { } /** + * 墙钟已用时长 = **已结算的活跃时长** + 当前这一段还没结算的。 + * + * ── 为什么不是「now - 第一次花钱的时刻」 ────────────────────────────────── + * 原来就是那么算的，它和 blocked 的语义直接对撞：预算耗尽 / 节点判罚都会把 run 打到 + * `blocked`，而 blocked 的定义就是**挂起等人工**。人隔夜再来处置时，墙钟把这段等待 + * 一并算进了「已用」，于是一起跑就报 `wallclock_ms` 耗尽 → 再 blocked → 再等人。 + * **一条过夜的 run 从此永远醒不过来**，而报出来的原因是「跑太久」，实际是「等人等太久」。 + * + * 实例：`run_9168bd24f46c`（e2e-demo 做官网）2026-08-18 15:48 起跑，预算 2h， + * 只花了 7/100 次调用、69,961/5,000,000 tokens，08-18 16:19 判 blocked 之后就再没能起来。 + * + * ponytail: 只认 `running` 一个态。manual 模式下两次点击之间 run 也停在 running， + * 那段人类思考时间仍会计入 —— 上限已知，比原来跨天累计小几个数量级。 + * 要更准就得按 agent 调用的起止配对计时，那是另一套账。 + */ +function wallclockElapsedMs(spent = {}) { + const settled = spent.active_ms || 0; + if (!spent.started_at) return settled; + return settled + Math.max(0, Date.now() - Date.parse(spent.started_at)); +} + +/** + * 墙钟的起止结算。挂在 `graph-run-sse.afterRunTransition` 这个**单一漏斗**上， + * 而不是去枚举「哪些地方会让 run 停下来」—— 那种枚举漏一条就是静默少算。 + * + * 进 running：开一段新的计时。离开 running：把这一段并进 active_ms 并断开锚点。 + * + * **存量行**（`active_ms` 缺失）：旧锚点里混着等待时间，真实活跃时长已经复原不出来了。 + * 这里把它按 0 起算，等于把过去那段一笔勾销 —— 有意为之：另外两维（调用次数 / tokens） + * 是精确的、且没受影响，真正兜住花钱的是那两维；墙钟只是跑飞保护。 + */ +function settleWallclock(runId, to) { + const run = getRun(runId); + if (!run || run.parent_run_id) return null; // 预算只挂在 root run 那一行 + const held = readBudget(run); + if (!held || held.budget.wallclock_ms == null) return null; + + const b = held.budget; + if (!b.spent) b.spent = {}; + const s = b.spent; + + if (to === 'running') { + s.active_ms = s.active_ms || 0; + s.started_at = now(); // 无条件重锚：进 running 就是新一段的开始 + } else { + if (s.started_at) { + s.active_ms = (s.active_ms || 0) + Math.max(0, Date.now() - Date.parse(s.started_at)); + } + s.active_ms = s.active_ms || 0; + s.started_at = null; + } + getDb() + .prepare(`UPDATE graph_runs SET budget_json = ?, updated_at = ? WHERE id = ?`) + .run(JSON.stringify(b), now(), held.rootRunId); + return s; +} + +/** * 余额检查。任何一层发起 agent 调用前都要过这一关（advanceOne 拾取节点之后立刻查）。 * @returns {{ok: boolean, exhausted: string[], rootRunId?: string, budget?: object}} */ @@ -2262,10 +2320,7 @@ function checkBudget(run) { exhausted.push('total_agent_calls'); } if (b.total_tokens != null && (spent.tokens || 0) >= b.total_tokens) exhausted.push('total_tokens'); - if ( - b.wallclock_ms != null && spent.started_at && - Date.now() - Date.parse(spent.started_at) >= b.wallclock_ms - ) { + if (b.wallclock_ms != null && wallclockElapsedMs(spent) >= b.wallclock_ms) { exhausted.push('wallclock_ms'); } return { ok: exhausted.length === 0, exhausted, rootRunId: held.rootRunId, budget: b }; @@ -2284,7 +2339,7 @@ function spendBudget(run, { agentCalls = 0, tokens = 0 } = {}) { if (!b.spent) b.spent = {}; b.spent.agent_calls = (b.spent.agent_calls || 0) + agentCalls; b.spent.tokens = (b.spent.tokens || 0) + tokens; - if (!b.spent.started_at) b.spent.started_at = now(); // 墙钟从第一次真花钱开始算 + // 墙钟不在这里锚 —— 它按「run 处于 running 的时长」累计，起止都归 settleWallclock 管。 getDb() .prepare(`UPDATE graph_runs SET budget_json = ?, updated_at = ? WHERE id = ?`) .run(JSON.stringify(b), now(), held.rootRunId); @@ -3842,6 +3897,8 @@ module.exports = { // 任务级总预算（§四.A.3） checkBudget, spendBudget, + settleWallclock, + wallclockElapsedMs, suspendRunTree, // 重试级联判据（§四.C 末段） diff --git a/server/services/graph-run-sse.js b/server/services/graph-run-sse.js index 0ebb368..810624c 100644 --- a/server/services/graph-run-sse.js +++ b/server/services/graph-run-sse.js @@ -343,6 +343,15 @@ const { ACTIVE_ROOT_RUN_STATUS } = workGraphDb; * 两件事各自 try/catch：settle 炸了不能连累调度，否则一次回写异常就把整个队列冻住。 */ function afterRunTransition(runId, to) { + // 墙钟起止结算 —— 必须在下面那个 early return **之前**：进 `running` 既不是收敛、 + // 也不空坑，两个条件都不满足，放在后面等于「只结算停下来、从不开始计时」。 + try { + // 惰性 require：graph-engine → 本模块，顶层 require 必成环（与下面两处同理） + require('./graph-engine').settleWallclock(runId, to); + } catch (err) { + console.error(`[graphRunSse] 墙钟结算异常 run=${runId} → ${to}: ${err.message}`); + } + const settled = ROOT_RUN_SETTLED_STATUS.has(to); const freedSlot = !ACTIVE_ROOT_RUN_STATUS.includes(to); if (!settled && !freedSlot) return; diff --git a/server/tests/unit/budget-wallclock-active.test.js b/server/tests/unit/budget-wallclock-active.test.js new file mode 100644 index 0000000..77a4f2f --- /dev/null +++ b/server/tests/unit/budget-wallclock-active.test.js @@ -0,0 +1,128 @@ +/** + * Unit Tests — 墙钟预算只算「真的在跑」的时间，不算挂起等人的时间 + * + * ── 挡的是什么 ───────────────────────────────────────────────────────── + * 原实现按 `now - spent.started_at` 算，而 started_at 是「第一次花钱的绝对时刻」。 + * 这与 blocked 的语义直接对撞：预算耗尽、节点判罚都会把 run 打到 blocked， + * 而 blocked 的定义就是**挂起等人工**。人隔夜再来处置 →「等待」被算成「已用」→ + * 一起跑就报 wallclock_ms 耗尽 → 再 blocked → 再等人。**过夜的 run 永远醒不过来。** + * + * 而且报出来的原因具有误导性：写着 `wallclock_ms`（跑太久），实际是等人等太久。 + * + * 真事：run_9168bd24f46c（e2e-demo 做官网）2026-08-18 15:48 起跑、16:19 判 blocked， + * 只花了 7/100 次调用、69,961/5,000,000 tokens，两天后仍卡死 —— 用掉的预算不到 2%。 + */ +import { describe, it, expect, beforeAll, afterAll, beforeEach } from 'vitest'; +import fs from 'fs'; +import os from 'os'; +import path from 'path'; + +const TMP = fs.mkdtempSync(path.join(os.tmpdir(), 'lemonboss-wallclock-')); +process.env.GRAPH_DB_PATH = path.join(TMP, 'graph.sqlite'); + +const engine = require('../../services/graph-engine'); +const wdb = require('../../services/work-graph-db'); + +const HOUR = 3600_000; +const budget = (spent) => JSON.stringify({ wallclock_ms: 2 * HOUR, total_agent_calls: 100, spent }); + +/** 直接落一行 root run，只为拿一个带 budget_json 的载体（不走图定义那一整套） */ +function seedRun(id, spentObj, status = 'running') { + const db = wdb.getDb(); + const t = '2026-08-18T15:48:00.000Z'; + db.prepare(`INSERT INTO graph_runs + (id, graph_kind, graph_id, company_id, root_run_id, execution_mode, run_status, budget_json, created_at, updated_at) + VALUES (?, 'org', 'g1', 'co1', ?, 'manual', ?, ?, ?, ?)`) + .run(id, id, status, budget(spentObj), t, t); + return wdb.getRun(id); +} + +describe('预算 · 墙钟只算活跃时长', () => { + afterAll(() => fs.rmSync(TMP, { recursive: true, force: true })); + beforeEach(() => wdb.getDb().prepare('DELETE FROM graph_runs').run()); + + it('挂起期间墙钟不走：两天前 blocked 的 run，余额照旧', () => { + // 这一条就是 run_9168bd24f46c 的形态：active_ms 只有 31 分钟，started_at 已断开 + const run = seedRun('r_old', { agent_calls: 7, tokens: 69961, active_ms: 31 * 60_000, started_at: null }, 'blocked'); + const gate = engine.checkBudget(run); + expect(gate.exhausted).toEqual([]); + expect(gate.ok).toBe(true); + }); + + it('旧算法下这条 run 必然耗尽 —— 证明这个测试真的在量东西', () => { + // 反例对照：起点是两天前的绝对时刻、没有 active_ms（存量行的原始形态） + const spent = { agent_calls: 7, tokens: 69961, started_at: '2026-08-18T15:48:17.630Z' }; + const legacyElapsed = Date.now() - Date.parse(spent.started_at); + expect(legacyElapsed).toBeGreaterThan(2 * HOUR); // 旧判据：早就超了 + // 新判据看的是 active_ms，started_at 断开后就不再累加 + expect(engine.wallclockElapsedMs({ ...spent, started_at: null, active_ms: 31 * 60_000 })).toBeLessThan(2 * HOUR); + }); + + it('活跃段分次累加：三段各 40 分钟 → 第三段跑到一半就该耗尽', () => { + expect(engine.wallclockElapsedMs({ active_ms: 80 * 60_000, started_at: null })).toBe(80 * 60_000); + const run = seedRun('r_acc', { active_ms: 119 * 60_000, started_at: null }, 'blocked'); + expect(engine.checkBudget(run).ok).toBe(true); + wdb.getDb().prepare('UPDATE graph_runs SET budget_json = ? WHERE id = ?') + .run(budget({ active_ms: 121 * 60_000, started_at: null }), 'r_acc'); + expect(engine.checkBudget(wdb.getRun('r_acc')).exhausted).toEqual(['wallclock_ms']); + }); + + it('settleWallclock：进 running 开始计时，离开 running 把这一段并进 active_ms', () => { + seedRun('r_settle', { active_ms: 5 * 60_000, started_at: null }, 'running'); + const started = engine.settleWallclock('r_settle', 'running'); + expect(started.started_at).toBeTruthy(); + expect(started.active_ms).toBe(5 * 60_000); + + const stopped = engine.settleWallclock('r_settle', 'blocked'); + expect(stopped.started_at).toBeNull(); + expect(stopped.active_ms).toBeGreaterThanOrEqual(5 * 60_000); // 只增不减 + expect(stopped.active_ms).toBeLessThan(6 * 60_000); // 这一段是毫秒级，不该凭空多出一分钟 + }); + + it('存量行（没有 active_ms）进 running 时按 0 起算，不把旧锚点当活跃时长', () => { + // 旧锚点里混着等待时间、复原不出来 —— 一笔勾销是有意的：真正兜住花钱的是调用次数与 tokens + seedRun('r_legacy', { agent_calls: 7, started_at: '2026-08-18T15:48:17.630Z' }, 'running'); + const s = engine.settleWallclock('r_legacy', 'running'); + expect(s.active_ms).toBe(0); + expect(Date.parse(s.started_at)).toBeGreaterThan(Date.parse('2026-08-19T00:00:00Z')); + expect(engine.checkBudget(wdb.getRun('r_legacy')).ok).toBe(true); + }); + + it('子 run 不动预算：结算只写 root 那一行', () => { + seedRun('r_root', { active_ms: 0, started_at: null }, 'running'); + const db = wdb.getDb(); + db.prepare(`INSERT INTO graph_runs + (id, graph_kind, graph_id, company_id, root_run_id, parent_run_id, execution_mode, run_status, budget_json, created_at, updated_at) + VALUES ('r_child','work','wg1','co1','r_root','r_root','manual','running', NULL, ?, ?)`) + .run('2026-08-18T15:49:00.000Z', '2026-08-18T15:49:00.000Z'); + expect(engine.settleWallclock('r_child', 'blocked')).toBeNull(); + const root = JSON.parse(wdb.getRun('r_root').budget_json); + expect(root.spent.started_at).toBeNull(); // 没被子 run 的转换改动 + }); + + it('挂在漏斗上：走 sse.transitionRun 就会结算，不需要调用方记得调', () => { + // 这一条守的是钩子的**位置**：进 running 既不是收敛、也不空坑， + // 放在 afterRunTransition 那个 early return 后面就变成「只结算停下来、从不开始计时」—— + // 症状是 active_ms 永远 0，墙钟形同虚设，而且照样全绿。 + const sse = require('../../services/graph-run-sse'); + seedRun('r_funnel', { active_ms: 0, started_at: null }, 'ready'); + + expect(sse.transitionRun('r_funnel', 'ready', 'running')).toBeTruthy(); + expect(JSON.parse(wdb.getRun('r_funnel').budget_json).spent.started_at).toBeTruthy(); + + expect(sse.transitionRun('r_funnel', 'running', 'blocked')).toBeTruthy(); + const spent = JSON.parse(wdb.getRun('r_funnel').budget_json).spent; + expect(spent.started_at).toBeNull(); + expect(spent.active_ms).toBeGreaterThanOrEqual(0); + }); + + it('没配 wallclock_ms 的 run：结算是 no-op，不许凭空造出 active_ms 字段', () => { + const db = wdb.getDb(); + db.prepare(`INSERT INTO graph_runs + (id, graph_kind, graph_id, company_id, root_run_id, execution_mode, run_status, budget_json, created_at, updated_at) + VALUES ('r_nowc','org','g1','co1','r_nowc','manual','running', ?, ?, ?)`) + .run(JSON.stringify({ total_agent_calls: 10, spent: { agent_calls: 1 } }), '2026-08-18T15:48:00.000Z', '2026-08-18T15:48:00.000Z'); + expect(engine.settleWallclock('r_nowc', 'blocked')).toBeNull(); + expect(JSON.parse(wdb.getRun('r_nowc').budget_json).spent).toEqual({ agent_calls: 1 }); + }); +}); diff --git a/server/tests/unit/goal-task-acceptance.test.js b/server/tests/unit/goal-task-acceptance.test.js index 5420600..3e5d9fc 100644 --- a/server/tests/unit/goal-task-acceptance.test.js +++ b/server/tests/unit/goal-task-acceptance.test.js @@ -1251,6 +1251,17 @@ describe('27-P3C 批 1 验收（§八 4 / 5 / 6 / 10 / 11 / 12b）', () => { // 缺陷 F3 / F6 · dispatch 那条路上被丢掉和被违反的两个约定 // ────────────────────────────────────────────────────────────── + /** + * 只比「申报的额度」，剥掉 spent。 + * + * spent 是**运行期账本**：run 一进 running，墙钟就往里写 active_ms / started_at + * （见 budget-wallclock-active.test.js）。整个对象 deepEqual 会让这条用例在账本 + * 新增字段时红，而它守的是「用户填的额度没被静默换成默认值」—— 跟账本长什么样无关。 + * 账本本身另有断言：起跑那一刻还没花钱，agent_calls / tokens 必须仍是 0。 + */ + const limitsOf = (o) => { const { spent, ...limits } = typeof o === 'string' ? JSON.parse(o) : o; return limits; }; + const spentOf = (o) => (typeof o === 'string' ? JSON.parse(o) : o).spent || {}; + it('草稿上申报的 budget 能活到 dispatch，run 拿到的不是默认额度（缺陷 F3）', async () => { const cid = newCompany(); const budget = { total_agent_calls: 3, total_tokens: 5000000, wallclock_ms: 60000, spent: { agent_calls: 0, tokens: 0 } }; @@ -1265,7 +1276,9 @@ describe('27-P3C 批 1 验收（§八 4 / 5 / 6 / 10 / 11 / 12b）', () => { expect(s2).toBe(201); // 修之前这里是 DEFAULT_TASK_BUDGET（100 次调用）：用户填的 3 次被静默丢弃， // 他只会看到任务跑到一半 blocked，而没有任何地方说过预算被换掉了 - expect(JSON.parse(wdb.getRun(dispatched.started.runId).budget_json)).toEqual(budget); + const dispatchedBudget = wdb.getRun(dispatched.started.runId).budget_json; + expect(limitsOf(dispatchedBudget)).toEqual(limitsOf(budget)); + expect(spentOf(dispatchedBudget)).toMatchObject({ agent_calls: 0, tokens: 0 }); // 起跑那一刻还没花钱 // 本次 dispatch 的 body 仍然覆盖草稿上的申报值（优先级：body > 草稿 > 默认） const cid2 = newCompany(); @@ -1273,7 +1286,7 @@ describe('27-P3C 批 1 验收（§八 4 / 5 / 6 / 10 / 11 / 12b）', () => { const override = { total_agent_calls: 9, spent: { agent_calls: 0, tokens: 0 } }; const [s3, d2] = await call('POST', `/api/company/${cid2}/goals/${goal2.goalId}/dispatch`, { budget: override }); expect(s3).toBe(201); - expect(JSON.parse(wdb.getRun(d2.started.runId).budget_json)).toEqual(override); + expect(limitsOf(wdb.getRun(d2.started.runId).budget_json)).toEqual(limitsOf(override)); }); it('坑被占着时 POST /tasks 不再 409 而是入队，申报的 budget 一路带到出队（批 3 · 缺陷 F3 的现场）', async () => { @@ -1311,7 +1324,8 @@ describe('27-P3C 批 1 验收（§八 4 / 5 / 6 / 10 / 11 / 12b）', () => { expect(ok).toBe(201); expect(started.started.runId).toBe(body.runId); // 不是新起一条，是把排着的那条拉起来 const runBudget = JSON.parse(wdb.getRun(body.runId).budget_json); - expect(runBudget).toEqual(budget); + expect(limitsOf(runBudget)).toEqual(limitsOf(budget)); + expect(spentOf(runBudget)).toMatchObject({ agent_calls: 0, tokens: 0 }); expect(runBudget.total_agent_calls).not.toBe(100); // DEFAULT_TASK_BUDGET 的值，钉住「不是默认额度」 }); -- libgit2 0.21.4