fix: run_work_node() reuse existing execution_log_file row instead of re-INSERT

Real incident (2026-08-13, task b243dfe8): run_work_node() unconditionally INSERTed a new execution_log_file row every call. Fine the first time, but if the process crashed/restarted between that INSERT and execute_work_graph() genuinely returning, work_node_execution.status is left at 'running' (not 'done', not a fresh node) and an execution_log_file row already exists for that node_exec_id. The next run_work_node() call for the SAME node_exec_id (REQ-06 requires this to be resumable) hit 'sqlite3.IntegrityError: UNIQUE constraint failed: execution_log_file.node_exec_id' and could never recover -- this exact bug is what task 2084590a's own (still-blocked) goal describes. Reuses the existing row (log_file_id, file_path) instead of re-inserting, same "resume must reuse what already exists" pattern this function already applies to git_worktree_ref a few lines below. New test confirms the exact production traceback on the pre-fix code and passes post-fix. Also adds docs/todo/2026-08-13-blocked-pending-human-incident-retrospective.md, today's consolidated retrospective + fix/execution-order plan for the 6 tasks that were blocking on various independent real causes. 815/815 tests. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>

fix: run_work_node() reuse existing execution_log_file row instead of re-INSERT
Real incident (2026-08-13, task b243dfe8): run_work_node() unconditionally INSERTed a new execution_log_file row every call. Fine the first time, but if the process crashed/restarted between that INSERT and execute_work_graph() genuinely returning, work_node_execution.status is left at 'running' (not 'done', not a fresh node) and an execution_log_file row already exists for that node_exec_id. The next run_work_node() call for the SAME node_exec_id (REQ-06 requires this to be resumable) hit 'sqlite3.IntegrityError: UNIQUE constraint failed: execution_log_file.node_exec_id' and could never recover -- this exact bug is what task 2084590a's own (still-blocked) goal describes. Reuses the existing row (log_file_id, file_path) instead of re-inserting, same "resume must reuse what already exists" pattern this function already applies to git_worktree_ref a few lines below. New test confirms the exact production traceback on the pre-fix code and passes post-fix. Also adds docs/todo/2026-08-13-blocked-pending-human-incident-retrospective.md, today's consolidated retrospective + fix/execution-order plan for the 6 tasks that were blocking on various independent real causes. 815/815 tests. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
bboonnee
1 parent ad3c45ec
Showing 3 changed files with 131 additions and 7 deletions
docs/todo/2026-08-13-blocked-pending-human-incident-retrospective.md
src/test_work_node_run.py
src/work_node_run.py
+# 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 面对的"原因分类"依然是残缺的，建议这两条修复优先。
@@ -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
@@ -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()