U-038 fix: http_health polls for startup readiness instead of one-shot

Attempts 7 and 11 both failed at exactly the same spot: process_alive read 'ok' within milliseconds of Popen, then http_health hit ECONNREFUSED in the same second and gave up. Real cause: process_alive only confirms the process EXISTS, not that backend_server.py has finished importing modules and actually bound its listen socket -- a real, non-zero startup gap. The old check_http_health did one urlopen(timeout=X) call; that timeout only bounds how long to wait for a response once connected, not how long to wait for the port to start accepting connections at all -- ECONNREFUSED fires essentially instantly when nothing's listening yet, regardless of timeout. This touches an explicit 03-C design statement ("不重试——重试属于给坏版本第二次机会"), so confirmed with the user before changing it rather than just reinterpreting the policy unilaterally. Resolution: tolerating normal startup latency within ONE health-check pass isn't "retrying a failed check" -- check_process_alive already does exactly this (polls up to 30s for the pid to exist). http_health now does the same, polling within its own timeout for connection-refused-class errors specifically. A genuine non-2xx HTTP response is still a definitive answer from a live server and still fails immediately, no polling -- that boundary is unchanged. Two new real regression tests: a real server that starts listening 0.3s late is correctly waited for and passes; a real 500 response still fails immediately without being mistaken for "not up yet". 564 tests green (441 src + 123 supervisor). Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>

U-038 fix: http_health polls for startup readiness instead of one-shot
Attempts 7 and 11 both failed at exactly the same spot: process_alive read 'ok' within milliseconds of Popen, then http_health hit ECONNREFUSED in the same second and gave up. Real cause: process_alive only confirms the process EXISTS, not that backend_server.py has finished importing modules and actually bound its listen socket -- a real, non-zero startup gap. The old check_http_health did one urlopen(timeout=X) call; that timeout only bounds how long to wait for a response once connected, not how long to wait for the port to start accepting connections at all -- ECONNREFUSED fires essentially instantly when nothing's listening yet, regardless of timeout. This touches an explicit 03-C design statement ("不重试——重试属于给坏版本第二次机会"), so confirmed with the user before changing it rather than just reinterpreting the policy unilaterally. Resolution: tolerating normal startup latency within ONE health-check pass isn't "retrying a failed check" -- check_process_alive already does exactly this (polls up to 30s for the pid to exist). http_health now does the same, polling within its own timeout for connection-refused-class errors specifically. A genuine non-2xx HTTP response is still a definitive answer from a live server and still fails immediately, no polling -- that boundary is unchanged. Two new real regression tests: a real server that starts listening 0.3s late is correctly waited for and passes; a real 500 response still fails immediately without being mistaken for "not up yet". 564 tests green (441 src + 123 supervisor). Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
bboonnee
1 parent 2ffa71fa
Showing 4 changed files with 84 additions and 21 deletions
docs/development-plan.md
docs/sdd/unit_matrix.json
supervisor/deploy_health_check.py
supervisor/test_deploy_health_check.py
@@ -375,6 +375,7 @@ PH2-S1/S2/S3/S4 之间除标注的依赖外相互独立，可并行推进。
   - 依赖：U-037
   - Done：三项检查全部通过 → `status=health_check_passed`；任一失败/超时 → `status=health_check_failed`，Live 全程未受影响（对应回滚路径 A）
   - **实现补充（2026-08-02）**：新增 `supervisor/deploy_health_check.py`。`process_alive` 复用 U-036 `deploy_supervisor.is_alive()`（`os.kill(pid,0)`），按 `HEALTH_CHECK_STARTUP_TIMEOUT` 轮询；`http_health` 请求候选的 `/api/health`——**这个端点 U-037 当时特意留空，这里补上**：`backend_server.py` 新增 `GET /api/health`，不只是"进程活着就 200"，还真的执行一次 `SELECT 1` 确认 sqlite 连接本身没卡死（连接卡死但进程还活着的场景，只测 `process_alive` 会漏检，这正是"health check"要抓的那类问题）；`canary_task` 是design doc §6"结果可预期的最小任务"字面实现——对候选发起一次真实的"建临时 project（临时目录 `git init` + 一个空提交）+ 建一个 goal 任务 + 读回确认 `status=queued`/`goal_text` 匹配"，不跑真实 Org Graph（不产生真实 `claude` 调用/花费），因为 `c_task_create` 本身落 `queued` 就是同步、确定性、"已知会通过"的最小验证，够用。三项检查按 03-C 原文"任一 fail 立即整体判定，不等其余项跑完"实现，`run_health_check()` 用 tuple-of-lambda 顺序短路，每项检查结果都真实写一条 `deploy_health_signal`（哪怕后续项因为短路没跑，已跑的那几条也留痕）。
+  - **真实 bug（2026-08-03，U-042 第七/十一次真实压测都在这里失败）**：候选进程真实拉起后连续两次都在同一秒内卡在 `http_health` 检查——`process_alive` 已经判定"活着"，但 `urlopen` 立刻拿到 `Connection refused`。真实原因：`process_alive` 判定的是"进程存在"，不是"HTTP 服务已经真正绑定端口开始监听"——候选进程从 `Popen` 到 `backend_server.py` 完成 import、真正调用 `serve_forever()` 之间有一段真实存在的启动延迟，`check_http_health` 原来的实现是一次性 `urlopen(timeout=X)`，这个 `timeout` 只控制"连上之后等响应等多久"，对"端口压根还没开始监听"这种情况完全不起作用——`ECONNREFUSED` 是操作系统立刻拒绝的，不会等 timeout。这条修复本身涉及一处 03-C 明确写的设计决策（"不重试——重试属于给坏版本第二次机会"），**没有直接动手改，先跟用户确认了这算不算违反那条策略**：结论是"容忍启动延迟"和"给一个已经失败的检查第二次机会"是两回事——`check_process_alive` 自己早就在做前者（轮询到 30s 上限），只是 `http_health` 没跟上同一个模式而已；一次真实的非 2xx 响应仍然是"服务已经起来但判定为不健康"，依旧立刻失败不重试，这条界线没有被打破。`check_http_health` 现在改成和 `check_process_alive` 一样在自己的 timeout 窗口内轮询，只对连接类错误（`URLError`/`OSError`，即"还没开始监听"）重试，真实收到的非 2xx 响应仍然立即失败。补了两个真实回归测试：`test_connection_refused_polls_until_server_actually_listening`（真实起一个延迟 0.3 秒才开始监听的服务器，验证轮询最终能等到它）、`test_real_http_error_response_fails_immediately_without_polling`（确认真实的 500 响应不会被误当成"还没起来"而重试）。
   - 覆盖：03-C `c_deploy_supervisor_health_check`；`backend_server.py` 新增 `GET /api/health`（U-037 留空的口子，这里补上）；01-M `deploy_health_signal`（首次被真正写入）
  
 - **U-039 [Risk Gate]** `c_deploy_supervisor_cutover`：蓝绿切换本体（Live 停止接受新触发 → 候选切换到生产端口/生产库 → 旧 Live checkout 保留为 `previous_instance_dir`）
@@ -55,7 +55,7 @@
     {"id": "U-035", "phase": "PH5", "sub_phase": "PH5-S1", "name": "self-target worktree 无条件强制 + core_engine 分类审计（见 development-plan.md 2026-08-02 实现补充）", "classification": "Risk Gate", "depends_on": ["U-013", "U-016", "U-034"], "coverage": {"model": [], "view": [], "controller": [], "process": [], "requirement": ["REQ-03"]}, "done": "self-target 时无条件走 worktree（work_graph_orchestrate.run_graph 内强制）；core_engine 分类（src/core_engine_classify.py，路径规则）在 self-target 任务 PASS 收尾时记一条审计用 bug_record；且改动落地后重跑 U-013/REQ-03（worktree 隔离）现有回归用例全部通过。**2026-08-02 用户决策修正**：Deploy Supervisor 触发条件按 supervisor-auto-rollback-design.md §1 字面设计（self-target+PASS 即触发，bug_record 是旁路产物不是前提），而非 03-C/04-P 字面文本要求的\"先有 core_engine bug_record\"——后者会让从不产生 bug_record 的 goal 型自我改进任务永远触发不了 Deploy Supervisor，已用 AskUserQuestion 与用户确认此订正。c_org_loop_route 未改动（fast_lane/full_replan 是 FAIL 路径重试路由，与此处 PASS 路径的蓝绿触发正交），deployment 行创建仍是 U-037 的范围，不在本 Unit 提前做"},
     {"id": "U-036", "phase": "PH5", "sub_phase": "PH5-S2", "name": "supervisor/isolation 补齐单测 + Deploy Supervisor 进程骨架（见 development-plan.md 2026-08-02 实现补充）", "classification": "Enabler", "depends_on": [], "coverage": {"model": [], "view": [], "controller": [], "process": [], "requirement": []}, "done": "四模块各有 test_*.py（供 python3 -m unittest discover -s supervisor/isolation 运行，52 测试全绿）；Deploy Supervisor 骨架（supervisor/deploy_supervisor.py）独立进程可启停（真实子进程验证，非 mock），不受 Live/Candidate 崩溃影响；本 Unit 只做进程生命周期骨架，不含任何真实部署决策逻辑（U-037+ 的 poll_fn 挂载点）"},
     {"id": "U-037", "phase": "PH5", "sub_phase": "PH5-S2", "name": "c_deploy_supervisor_stage（见 development-plan.md 2026-08-02/03 实现补充）", "classification": "Risk Gate", "depends_on": ["U-034", "U-036"], "coverage": {"model": ["deployment"], "view": [], "controller": ["c_deploy_supervisor_stage"], "process": [], "requirement": []}, "done": "能生成 deployment 记录并拉起监听临时端口、连一次性 DB 副本的候选进程（supervisor/deploy_stage.py，真实 git worktree + 真实子进程验证过）；顺带补上 deployment.candidate_instance_dir 缺字段 + backend_server.py 首个 CLI 入口。2026-08-03：U-042 第三次真实自举压测发现 _copy_prod_db() 没有处理 prod_db_path 首次不存在的引导期场景（真实 FileNotFoundError），已修复为自动新建带 schema 的空库并补测试"},
-    {"id": "U-038", "phase": "PH5", "sub_phase": "PH5-S2", "name": "c_deploy_supervisor_health_check（见 development-plan.md 2026-08-02 实现补充）", "classification": "Risk Gate", "depends_on": ["U-037"], "coverage": {"model": ["deploy_health_signal"], "view": [], "controller": ["c_deploy_supervisor_health_check"], "process": [], "requirement": []}, "done": "process_alive/http_health/canary_task 三项检查全过 -> health_check_passed；任一失败 -> health_check_failed 且 Live 未受影响（supervisor/deploy_health_check.py，真实 HTTP+真实 project/task 创建验证过）；backend_server.py 新增 GET /api/health（真查一次 SELECT 1，不只是进程存活）"},
+    {"id": "U-038", "phase": "PH5", "sub_phase": "PH5-S2", "name": "c_deploy_supervisor_health_check（见 development-plan.md 2026-08-02/03 实现补充）", "classification": "Risk Gate", "depends_on": ["U-037"], "coverage": {"model": ["deploy_health_signal"], "view": [], "controller": ["c_deploy_supervisor_health_check"], "process": [], "requirement": []}, "done": "process_alive/http_health/canary_task 三项检查全过 -> health_check_passed；任一失败 -> health_check_failed 且 Live 未受影响（supervisor/deploy_health_check.py，真实 HTTP+真实 project/task 创建验证过）；backend_server.py 新增 GET /api/health（真查一次 SELECT 1，不只是进程存活）。2026-08-03：U-042 第七/十一次真实压测均卡在 http_health（进程已存活但端口还没真正开始监听，ECONNREFUSED 立即触发、原实现单次尝试不重试），已跟用户确认不违反 03-C\"不重试\"策略后，改成和 process_alive 一样轮询等待端口就绪，真实非 2xx 响应仍立即失败"},
     {"id": "U-039", "phase": "PH5", "sub_phase": "PH5-S2", "name": "c_deploy_supervisor_cutover（见 development-plan.md 2026-08-02 实现补充）", "classification": "Risk Gate", "depends_on": ["U-038"], "coverage": {"model": ["deployment"], "view": [], "controller": ["c_deploy_supervisor_cutover"], "process": [], "requirement": []}, "done": "健康检查通过后完成真实切换（supervisor/deploy_cutover.py，真实进程停止+重启验证过）；在途 work_node_execution 重启后可恢复（复用既有 REQ-06 机制）；previous_instance_dir 保留至监控窗口结束；新增 LIVE_PORT=8420 常量（05 §5.9 缺的一个字段）；真实测试发现并修复 deploy_supervisor.is_alive() 的僵尸进程判活缺陷（新增 reap_if_exited()）"},
     {"id": "U-040", "phase": "PH5", "sub_phase": "PH5-S3", "name": "c_deploy_supervisor_monitor（见 development-plan.md 2026-08-02 实现补充）", "classification": "Risk Gate", "depends_on": ["U-039"], "coverage": {"model": ["deploy_health_signal"], "view": [], "controller": ["c_deploy_supervisor_monitor"], "process": [], "requirement": []}, "done": "四类信号采样正常（supervisor/deploy_monitor.py）；validator_approval_rate 偏离基线阈值时触发 anomaly_detected；approve 占比算法基于对 scheduler.finish_task_lifecycle 真实代码逻辑的核实（PASS 从不产生 bug_record，FAIL 必然产生），非字面 SDD 定义"},
     {"id": "U-041", "phase": "PH5", "sub_phase": "PH5-S3", "name": "c_deploy_supervisor_rollback（见 development-plan.md 2026-08-02/03 实现补充）", "classification": "Risk Gate", "depends_on": ["U-038", "U-040"], "coverage": {"model": ["deployment"], "view": [], "controller": ["c_deploy_supervisor_rollback"], "process": [], "requirement": []}, "done": "回滚路径 A/B 各跑通一次（supervisor/deploy_rollback.py，真实进程+真实 git 仓库验证）；旧版本也起不来时正确终态到 blocked_pending_human（真实场景验证，非假设）；git revert 冲突有明确处理（真实构造冲突历史验证过，含 --abort 清理）。2026-08-03：U-042 第七次真实压测第一次真正走到 health_check 环节，发现 rollback_path_a 从未清理候选的 git worktree 检出目录（永久留在磁盘+git worktree list），已修复并补真实回归测试"},
@@ -47,24 +47,46 @@ def check_process_alive(pid, timeout=HEALTH_CHECK_STARTUP_TIMEOUT, sleep=time.sl
     }
  
  
-def check_http_health(port, timeout=HEALTH_CHECK_HTTP_TIMEOUT):
-    try:
-        with urllib.request.urlopen("http://127.0.0.1:{}/api/health".format(port), timeout=timeout) as resp:
-            if resp.status == 200:
-                return {"signal_type": "http_health", "status": "ok", "detail": None}
-            return {
-                "signal_type": "http_health", "status": "fail",
-                "detail": "unexpected HTTP status {}".format(resp.status),
-            }
-    except urllib.error.HTTPError as e:
-        # HTTPError IS the response object (a non-2xx status raises rather
-        # than returning) -- close it explicitly, `except` doesn't run our
-        # `with` block's __exit__ for us.
-        detail = "unexpected HTTP status {}".format(e.code)
-        e.close()
-        return {"signal_type": "http_health", "status": "fail", "detail": detail}
-    except (urllib.error.URLError, OSError) as e:
-        return {"signal_type": "http_health", "status": "fail", "detail": str(e)}
+def check_http_health(port, timeout=HEALTH_CHECK_HTTP_TIMEOUT, sleep=time.sleep, now=time.time):
+    """Polls until `timeout` elapses, same as `check_process_alive` --
+    NOT the "重试属于给坏版本第二次机会" policy this module's own docstring
+    warns against (real self-hosting runs, 2026-08-03, hit this: `pid`
+    reads alive within milliseconds of `Popen`, well before the candidate
+    process has finished importing modules and actually bound its listen
+    socket -- `urlopen` on a port nothing is listening on yet raises
+    ECONNREFUSED essentially instantly, `timeout=` only bounds how long to
+    wait for a RESPONSE once connected, not how long to wait for the port
+    to start accepting connections at all). `check_process_alive` already
+    established the precedent that tolerating normal startup latency
+    within ONE health-check pass isn't "retrying a failed check" -- this
+    just extends the same tolerance to the next check in the same pass.
+    A genuine non-2xx HTTP response IS a definitive answer from a server
+    that's actually up, so that still fails immediately without polling,
+    preserving the real "don't give a bad build a second chance" intent.
+    """
+    deadline = now() + timeout
+    last_detail = None
+    while now() < deadline:
+        try:
+            with urllib.request.urlopen("http://127.0.0.1:{}/api/health".format(port), timeout=1) as resp:
+                if resp.status == 200:
+                    return {"signal_type": "http_health", "status": "ok", "detail": None}
+                return {
+                    "signal_type": "http_health", "status": "fail",
+                    "detail": "unexpected HTTP status {}".format(resp.status),
+                }
+        except urllib.error.HTTPError as e:
+            # HTTPError IS the response object (a non-2xx status raises rather
+            # than returning) -- close it explicitly, `except` doesn't run our
+            # `with` block's __exit__ for us. A real response from a live
+            # server, not a startup race -- fail immediately, no polling.
+            detail = "unexpected HTTP status {}".format(e.code)
+            e.close()
+            return {"signal_type": "http_health", "status": "fail", "detail": detail}
+        except (urllib.error.URLError, OSError) as e:
+            last_detail = str(e)
+            sleep(0.5)
+    return {"signal_type": "http_health", "status": "fail", "detail": last_detail}
  
  
 def _post_json(port, path, payload, timeout):
@@ -154,7 +176,7 @@ def run_health_check(
     signals = []
     checks = (
         lambda: check_process_alive(pid, timeout=startup_timeout, sleep=sleep, now=now),
-        lambda: check_http_health(port, timeout=http_timeout),
+        lambda: check_http_health(port, timeout=http_timeout, sleep=sleep, now=now),
         lambda: check_canary_task(port, timeout=canary_timeout),
     )
     for check in checks:
@@ -74,8 +74,48 @@ class CheckHttpHealthTest(RealServerTestBase):
         self.assertEqual(signal["status"], "fail")
  
     def test_nothing_listening_on_port_returns_fail(self):
-        signal = dhc.check_http_health(1)  # privileged/unbound port, nothing listening
+        clock = {"t": 0.0}
+        signal = dhc.check_http_health(
+            1, timeout=5,  # privileged/unbound port, nothing listening
+            sleep=lambda s: clock.__setitem__("t", clock["t"] + s), now=lambda: clock["t"],
+        )
+        self.assertEqual(signal["status"], "fail")
+
+    def test_connection_refused_polls_until_server_actually_listening(self):
+        # 2026-08-03 regression: a real self-hosting run showed
+        # process_alive can read 'ok' before the candidate has finished
+        # binding its listen socket -- check_http_health must tolerate
+        # that same startup window instead of failing on the first
+        # ECONNREFUSED, same as check_process_alive already tolerates a
+        # not-yet-existing pid.
+        server = backend_server.create_server(db_path=":memory:")
+        real_port = server.server_address[1]
+        self.addCleanup(server.server_close)
+
+        def start_server_after_delay():
+            thread = threading.Thread(target=server.serve_forever, daemon=True)
+            thread.start()
+            self.addCleanup(lambda: (server.shutdown(), thread.join(timeout=5)))
+
+        timer = threading.Timer(0.3, start_server_after_delay)
+        timer.start()
+        self.addCleanup(timer.cancel)
+
+        signal = dhc.check_http_health(real_port, timeout=5)
+        self.assertEqual(signal, {"signal_type": "http_health", "status": "ok", "detail": None})
+
+    def test_real_http_error_response_fails_immediately_without_polling(self):
+        # a genuine non-2xx response IS a definitive answer from a live
+        # server -- must not be treated the same as "not up yet".
+        sleeps = []
+        with patch.object(dhc.urllib.request, "urlopen") as mock_urlopen:
+            error = dhc.urllib.error.HTTPError("url", 500, "Internal Server Error", {}, None)
+            mock_urlopen.side_effect = error
+            signal = dhc.check_http_health(self.port, timeout=5, sleep=lambda s: sleeps.append(s), now=lambda: 0.0)
         self.assertEqual(signal["status"], "fail")
+        self.assertIn("500", signal["detail"])
+        self.assertEqual(sleeps, [])
+        mock_urlopen.assert_called_once()
  
  
 class CheckCanaryTaskTest(RealServerTestBase):