From 1a2baa0211e95f7c012d5796f240de6cb43c328c Mon Sep 17 00:00:00 2001 From: bboonnee Date: Thu, 13 Aug 2026 19:07:15 +0800 Subject: [PATCH] fix: run_work_node() reuse existing execution_log_file row instead of re-INSERT --- docs/todo/2026-08-13-blocked-pending-human-incident-retrospective.md | 80 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ src/test_work_node_run.py | 26 ++++++++++++++++++++++++++ src/work_node_run.py | 32 +++++++++++++++++++++++++------- 3 files changed, 131 insertions(+), 7 deletions(-) create mode 100644 docs/todo/2026-08-13-blocked-pending-human-incident-retrospective.md diff --git a/docs/todo/2026-08-13-blocked-pending-human-incident-retrospective.md b/docs/todo/2026-08-13-blocked-pending-human-incident-retrospective.md new file mode 100644 index 0000000..b417149 --- /dev/null +++ b/docs/todo/2026-08-13-blocked-pending-human-incident-retrospective.md @@ -0,0 +1,80 @@ +# 2026-08-13 复盘：5 个自举任务反复卡在 blocked_pending_human + +**日期**: 2026-08-13 +**性质**: 复盘文档 + 修复/执行顺序 todo，不是需求文档——真正的需求已经拆成三份独立文档（见 §2）， +这份文档负责把"今天到底发生了什么、为什么会看起来像是全线报错、接下来按什么顺序处理"讲清楚。 + +## 1. 表面现象 vs 真实情况 + +用户观察："现在所有任务都报错了" —— 表面上确实如此：5 个目标任务（`2084590a`/`911861fe`/ +`b243dfe8`/`bfd3ee82`/`71868db6`）加上新提交的 `6b823b35`，全部落在 `blocked_pending_human`， +`blocked_reason` 也全部显示同一个词 `execution_error`。 + +**但这不是一个共同根因导致的连锁故障**——逐个查真实 `execution_event` 记录后，是 **6 个互相独立 +的真实原因**，只是都被同一个粗粒度的兜底桶盖住了，表面上看起来像"全线崩溃"： + +| 任务 | 真实原因 | 类别 | +|---|---|---| +| `b243dfe8` | 孤儿 `work_graph_run`（有 manifest 无 artifact）撞 `ux_work_graph_run_active` 唯一索引 | 基础设施 bug，**已修复**（`_existing_active_run_id`） | +| `71868db6` | `max_concurrent_goals` 并发上限——本来就不是错误 | 机制设计缺陷，**已修复**（并发上限不再阻塞） | +| `911861fe` | Coder 和 Validator 的建议节点目录都收敛到 `node_type=test_script`，共享 run 里 `node_id` 撞名 | 基础设施 bug，**未修复**（`docs/todo/append-run-node-id-collision-across-org-nodes-requirements.md`） | +| `bfd3ee82` | 大 prompt 的 Validator 规划调用跑满固定 300 秒超时 | 基础设施 bug，**未修复**（`docs/todo/agent-call-liveness-not-fixed-duration-timeout-requirements.md`） | +| `2084590a` | Planner 自规划的 `graph_manifest` 里 `on_fail.action='loop_back'` 但缺对应 `on_failure` 边 | 内容/自规划质量问题，不是代码 bug——校验本身是对的，只是这次规划产出有缺陷 | +| `6b823b35` | Planner 的响应是叙述性文字，没能提取出结构化 `content` 字段 | 内容质量问题，跟 `docs/done/validator-test-script-narrative-output-issue.md` 记录过的同一类问题 | + +## 2. 这次复盘真正的结论 + +这不是"系统今天特别不稳定"，是**一个一直存在、只是今天才被真正看清楚的设计缺陷**：`task_execution.py::_mark_blocked` 的兜底逻辑——任何不在一个很小的白名单（`_ROUTABLE_EXCEPTIONS`）里的异常， +不管性质是什么，一律扣上同一个 `execution_error` 帽子、状态打成 `blocked_pending_human`。这把 +"系统自己造成的正常排队"（并发上限）、"真实但可自动恢复的 bug"（run_id/node_id 撞名）、"需要更长 +等待时间的正常调用"（超时）、"这次规划质量不够好，换一次也许就好了"（内容问题）**全部混成了一种 +表象**："报错，需要人工点 Resume"。 + +三份独立的需求文档（不在这份文档里重复内容，只列出关系）： + +1. `docs/todo/boss-agent-autonomous-blocked-task-arbiter-requirements.md`——**长期**方案：一个 + 自主监控 `blocked_pending_human`、做真实诊断、有权限边界地自主处理的角色。 +2. `docs/todo/agent-call-liveness-not-fixed-duration-timeout-requirements.md`——**根因之一**： + agent 调用不该用固定时长判断超时，只能用"是否还活着"。已作为 Goal 提交（`6b823b35`，但这个 + Goal 自己又撞上了另一个独立的内容质量问题，见上表——这本身也是个真实的、略带讽刺的例子，说明 + "内容质量问题"和"基础设施 bug"是两条完全独立的故障轴）。 +3. `docs/todo/append-run-node-id-collision-across-org-nodes-requirements.md`——**根因之一**： + 共享 `work_graph_run` 下跨 org_node 的节点命名撞名问题。 + +今天已经**直接**修复（不经过 graphlemon 自己的 Coder，原因见下方"实施方式"说明）： +- `_existing_active_run_id()`（`src/e2e_pipeline.py`，commit 已提交）——修复孤儿 run 撞名。 +- `_mark_blocked` 对 `ConcurrencyLimitReachedError` 的特判（`src/task_execution.py`，commit + 已提交）——并发上限不再报错阻塞，只是正常留在 `queued` 等下一轮调度。 +- `task.execution_priority` 列 + `v_task_board` 新增"执行顺序"列（commit 已提交）——见 §3。 + +**实施方式说明**：以上三处修复都是本次会话直接改代码 + 写真实回归测试 + 跑全量测试套件验证后 +提交，不是走 graphlemon 自己的 Planner→Coder→Validator 闭环——因为这些是阻塞 graphlemon 自身 +基础设施的 bug（同类前例见 `docs/implementation-gap-analysis.md` 里"人工直接改代码修的，不是走 +自举流程验证的"那几条），跟"喂给 graphlemon 自己实现"的三份需求文档（更大范围的设计工作）性质 +不同，不要混为一谈。 + +## 3. 6 个任务的执行顺序 + +新增的 `task.execution_priority` 列已经把下面这个顺序写入了每个任务（串行用整数、并行用同一个 +整数部分的小数——比如 `2.1`/`2.2`/`2.3` 表示这三个可以同时跑，都在"第 2 步"）： + +| 顺序 | task_id | 为什么是这个顺序 | +|---|---|---| +| **1** | `b243dfe8` | 阻塞它的 bug 已修复（`_existing_active_run_id`），且这是验证今天这个修复本身是否真的生效的第一手真实信号——先单独跑，确认不再复现同一个 `IntegrityError`，再放心批量恢复其余任务。 | +| **2.1** | `71868db6` | 阻塞它的并发上限 bug 已修复，且这个修复本身不需要等任何东西——它甚至不需要手动 resume，下一轮 `new_goal_dispatch` 循环（45 秒）会自动重新拾取。 | +| **2.2** | `2084590a` | 阻塞它的是内容质量问题（自规划图结构有缺陷），不依赖任何未完成的基础设施修复——直接重试，让 Planner 有机会规划出结构正确的图。 | +| **2.3** | `6b823b35` | 同上，叙述性输出问题，不依赖未完成的修复——直接重试。 | +| **3.1** | `911861fe` | **暂不恢复**——阻塞它的 node_id 撞名 bug 还没修（`docs/todo/append-run-node-id-collision-across-org-nodes-requirements.md`），现在重试大概率原样复现同一个撞名。 | +| **3.2** | `bfd3ee82` | **暂不恢复**——阻塞它的固定时长超时问题还没修（`docs/todo/agent-call-liveness-not-fixed-duration-timeout-requirements.md`），现在重试大概率再次跑满 300 秒被杀。这条**不接受**"先把 300 秒改成一个更大的数字"这种临时缓解——用户已经明确过这个决定：判断逻辑本身错了（固定时长 vs 是否还活着），不是数字选小了，改数字治标不治本，还是要等真正的心跳判断机制落地。 | + +3.1 和 3.2 之间没有依赖关系（各自阻塞在不同的、互相独立的基础设施 bug 上），标成并列的 +"第 3 步"两条分支，不是先后关系——哪个对应的修复先做完，哪个就先重试，不用等另一个。 + +## 4. 下一步 todo + +- [ ] 按上表恢复 `b243dfe8`（第 1 步），验证不再复现 `IntegrityError`。 +- [ ] 确认 `71868db6` 被下一轮 `new_goal_dispatch` 自动拾取（第 2.1 步，预期不需要手动操作）。 +- [ ] 恢复 `2084590a`/`6b823b35`（第 2.2/2.3 步）。 +- [ ] 设计并实现 node_id 撞名修复（`docs/todo/append-run-node-id-collision-across-org-nodes-requirements.md`），完成后恢复 `911861fe`（第 3.1 步）。 +- [ ] 设计并实现 agent 调用心跳超时判断（`docs/todo/agent-call-liveness-not-fixed-duration-timeout-requirements.md`），完成后恢复 `bfd3ee82`（第 3.2 步）。 +- [ ] 上述两条修复都落地后，重新评估 Boss Agent（`docs/todo/boss-agent-autonomous-blocked-task-arbiter-requirements.md`）该由谁实现——它本身也是喂给 graphlemon 自己的 Goal，但两条基础设施修复没做完之前，Boss Agent 面对的"原因分类"依然是残缺的，建议这两条修复优先。 diff --git a/src/test_work_node_run.py b/src/test_work_node_run.py index 640d868..22c18a5 100644 --- a/src/test_work_node_run.py +++ b/src/test_work_node_run.py @@ -115,6 +115,32 @@ class HappyPathTest(WorkNodeRunTestBase): final_status = self.conn.execute("SELECT status FROM execution_log_file").fetchone()[0] self.assertEqual(final_status, "closed") + def test_reruns_a_process_crash_survivor_reusing_its_existing_log_file(self): + """Real incident (2026-08-13, task b243dfe8): if the whole process + was killed/restarted between run_work_node()'s execution_log_file + INSERT and execute_work_graph() genuinely returning, work_node_ + execution.status is left at 'running' and an execution_log_file row + already exists for this node_exec_id. Calling run_work_node() again + for the SAME node_exec_id (REQ-06: must be able to resume) used to + unconditionally re-INSERT, hitting 'sqlite3.IntegrityError: UNIQUE + constraint failed: execution_log_file.node_exec_id' -- the node + could never recover. Must instead reuse the existing row.""" + self.conn.execute("UPDATE work_node_execution SET status = 'running' WHERE node_exec_id = 'node-1'") + self.conn.execute( + "INSERT INTO execution_log_file (log_file_id, node_exec_id, project_id, file_path, format, status) " + "VALUES ('log-orig', 'node-1', 'proj-1', '/some/pre-existing/path.jsonl', 'jsonl', 'active')" + ) + self.conn.commit() + + output = work_node_run.run_work_node( + self.conn, "node-1", {"goal": "x"}, _IN_SCHEMA, _OUT_SCHEMA, run_fn=lambda cwd, model=None: {"value": 1} + ) + self.assertEqual(output, {"value": 1}) + + rows = self.conn.execute("SELECT log_file_id, file_path, status FROM execution_log_file").fetchall() + self.assertEqual(len(rows), 1) # no second row inserted + self.assertEqual(rows[0], ("log-orig", "/some/pre-existing/path.jsonl", "closed")) + def test_unretryable_run_fn_failure_marks_node_blocked_not_stuck_running(self): # any exception from run_fn other than a recognized usage-limit # signal (e.g. CLASSIFIER_BLOCKED surfacing from diff --git a/src/work_node_run.py b/src/work_node_run.py index 44c23e8..ff95fab 100644 --- a/src/work_node_run.py +++ b/src/work_node_run.py @@ -269,13 +269,31 @@ def run_work_node( "work_node_execution {} is status=waiting_for_quota but has no quota_wait_started_at".format(node_exec_id) ) - log_file_id = str(uuid.uuid4()) - log_path = paths.log_file_path(project_id, task_id, node_exec_id, node_exec_id) - conn.execute( - "INSERT INTO execution_log_file (log_file_id, node_exec_id, project_id, file_path, format, status) " - "VALUES (?, ?, ?, ?, 'jsonl', 'active')", - (log_file_id, node_exec_id, project_id, log_path), - ) + # 2026-08-13 (real incident, task b243dfe8): this used to unconditionally + # INSERT a new execution_log_file row every call -- fine the first time, + # but if the process crashed/restarted between this INSERT and + # execute_work_graph() genuinely returning (not a clean 'done' state, + # not a fresh node either), the next run_work_node() call for the SAME + # node_exec_id hit 'sqlite3.IntegrityError: UNIQUE constraint failed: + # execution_log_file.node_exec_id' and could never recover -- exactly + # the REQ-06 broken-continuity gap this fixes. node_exec_id already has + # a UNIQUE constraint on this table for good reason (one log file per + # node, ever), so reuse the existing row instead of re-inserting, same + # "resume must reuse what already exists, not recreate it" pattern this + # function already applies to git_worktree_ref just below. + existing_log_file = conn.execute( + "SELECT log_file_id, file_path FROM execution_log_file WHERE node_exec_id = ?", (node_exec_id,) + ).fetchone() + if existing_log_file: + log_file_id, log_path = existing_log_file + else: + log_file_id = str(uuid.uuid4()) + log_path = paths.log_file_path(project_id, task_id, node_exec_id, node_exec_id) + conn.execute( + "INSERT INTO execution_log_file (log_file_id, node_exec_id, project_id, file_path, format, status) " + "VALUES (?, ?, ?, ?, 'jsonl', 'active')", + (log_file_id, node_exec_id, project_id, log_path), + ) conn.execute("UPDATE work_node_execution SET status = 'running' WHERE node_exec_id = ?", (node_exec_id,)) conn.commit() -- libgit2 0.21.4