worker: prestart stage logging for dispatch stalls

Claim-to-dispatch stalls (cf. 2026-10-29 task A: 61s to interrupted
with zero detail) were invisible because docker run blocks with
captured output and watchdog kills were silent. Add three layers:
- worker_exec_start/done/error audit rows in _run_attempt (PG,
  survives --rm), start/done pairing shows whether an attempt died
  inside the executor call;
- docker_run_start/done/error log lines in DockerExecutor (container
  + image only, never the inner command/prompt);
- stdout tail (last 2000 chars) to the worker log on failed or
  interrupted results, and a log line on both watchdog kill paths.
Tests: cloud/tests/test_prestart_stages.py, 6 cases incl. a
no-prompt-in-logs assertion.
This commit is contained in:
host committed 2026-10-29 17:07:53 +08:00
1 parent 0129b0149a
commit 9d90d97046
3 files changed
+251

No files matched your search

+65
View File
@@ -1983,6 +1983,11 @@ class Worker:
kill = getattr(self.executor, "kill_container", None)
if kill is not None and container_name:
kill(container_name)
log_event(self.logger, "worker_docker_killed",
task_id=task_id,
message="cancel watchdog killed container "
"%s (task interrupted/cancelled)"
% container_name)
except Exception:
pass
return
@@ -2018,6 +2023,10 @@ class Worker:
kill = getattr(self.executor, "kill_container", None)
if kill is not None and container_name:
kill(container_name)
log_event(self.logger, "worker_docker_killed",
task_id=task_id,
message="quota watchdog killed container %s "
"(quota exceeded)" % container_name)
except Exception:
pass
return
@@ -3534,6 +3543,33 @@ class Worker:
_watchdog_stop, quota_check),
daemon=True)
_quota_watchdog_thread.start()
# 启动前分段日志(2026-10-29 任务 A):认领后 61 秒中断,
# 但阻塞的 docker run 中途没有任何标记、容器 --rm 后输出
# 也没了,事后完全无法定位卡在哪一段。派发开始/结束进
# 审计(PG 落盘,容器没了也丢不了),下次卡死时最后一个
# 标记直接说明卡在哪一段;kind/容器名/超时不含 prompt/key。
_exec_kind = ("goal-resume-breakpoint"
if task.get("_goal_resume_breakpoint")
else "goal-resume" if task.get("_resume")
else "goal" if goal_mode else "dispatch")
_exec_container = None
if hasattr(self.executor, "container_name"):
try:
_exec_container = self.executor.container_name(task)
except Exception:
_exec_container = None
_exec_t0 = time.time()
_exec_error = None
_exec_detail = "kind=%s executor=%s timeout=%s" % (
_exec_kind, self._executor_name(),
"None" if _effective_task_timeout is None
else _effective_task_timeout)
if _exec_container:
_exec_detail += " container=%s" % _exec_container
self._audit(task.get("project_id"), "worker_exec_start",
_exec_detail)
log_event(self.logger, "worker_exec_start", task_id=task_id,
message="worker exec start: %s" % _exec_detail)
try:
gateway_provider, gateway_env = self._ensure_gateway(task)
if self._use_popen():
@@ -3726,6 +3762,7 @@ class Worker:
"status": "failed", "stdout": "", "returncode": None,
"host_status": None, "stderr": ""}
error = str(exc)
_exec_error = exc
finally:
if _watchdog_stop is not None:
_watchdog_stop.set()
@@ -3753,6 +3790,34 @@ class Worker:
entry = self._running_snapshot().get(task_id) or {}
if entry.get("proc") is None:
self._running_clear(task_id)
# 启动前分段日志(续):派发结束标记与失败输出尾巴。结束
# 标记与开始标记配对:只有开始没有结束 = 卡在执行器调用
# 里;失败/中断时的容器输出尾巴记进 worker 日志——任务 A
# 当时这部分输出随 --rm 消失,是事后无法定位的另一半。
_exec_elapsed_ms = int((time.time() - _exec_t0) * 1000)
if _exec_error is not None:
self._audit(task.get("project_id"), "worker_exec_error",
"elapsed_ms=%d error=%s"
% (_exec_elapsed_ms,
_exec_error.__class__.__name__))
log_event(self.logger, "worker_exec_error", task_id=task_id,
message="worker exec error: elapsed_ms=%d error=%s"
% (_exec_elapsed_ms,
_exec_error.__class__.__name__))
else:
self._audit(task.get("project_id"), "worker_exec_done",
"elapsed_ms=%d status=%s returncode=%s"
% (_exec_elapsed_ms, result.get("status"),
result.get("returncode")))
log_event(self.logger, "worker_exec_done", task_id=task_id,
status=result.get("status"),
message="worker exec done: elapsed_ms=%d status=%s"
% (_exec_elapsed_ms, result.get("status")))
_exec_out = result.get("stdout", "") or ""
if result.get("status") in ("failed", "interrupted") and _exec_out:
self.logger.info(
"worker_exec_stdout_tail task_id=%s tail=%s",
task_id, _exec_out[-2000:])
# Docker 超时标记:执行器已在超时时 kill+rm 容器并返回
# failed(stdout 含 timeout),这里把状态统一成 timeout,
# 调用方据此置 failed 并记 worker_timeout 审计。