chore: improve image worker logging

apps/api/management/commands/run_image_tasks.py

@@ -4,6 +4,7 @@ import uuid
 from django.conf import settings
 from django.core.management.base import BaseCommand
 
+from apps.api.models import ImageGenerationTask
 from apps.api.image_tasks import reap_stale_image_tasks, run_one_image_task
 
 
@@ -56,7 +57,7 @@ class Command(BaseCommand):
 
             task = run_one_image_task(worker_id=worker_id)
             if task is not None:
-                self.stdout.write(f"task={task.task_id} status={task.status}")
+                self.stdout.write(format_task_log_line(task, started_at=now))
                 if once:
                     return
                 continue
@@ -64,3 +65,18 @@ class Command(BaseCommand):
             if once:
                 return
             time.sleep(sleep_seconds)
+
+
+def format_task_log_line(task: ImageGenerationTask, *, started_at: float) -> str:
+    duration_ms = max(0, int((time.monotonic() - started_at) * 1000))
+    alias = str((task.request_payload or {}).get("model") or "")
+    fields = {
+        "event": "image_task_processed",
+        "task_id": str(task.task_id),
+        "status": task.status,
+        "alias": alias,
+        "duration_ms": str(duration_ms),
+    }
+    if task.status in {ImageGenerationTask.Status.FAILED, ImageGenerationTask.Status.EXPIRED}:
+        fields["error_code"] = task.error_code or "upstream_error"
+    return " ".join(f"{key}={value}" for key, value in fields.items())

apps/api/tests.py

@@ -1,5 +1,6 @@
 import uuid
 import base64
+import io
 import json
 import tempfile
 from datetime import timedelta
@@ -13,6 +14,7 @@ from django.conf import settings
 from django.contrib import admin
 from django.contrib.auth import get_user_model
 from django.core.cache import cache
+from django.core.management import call_command
 from django.test import TestCase, override_settings
 from django.urls import path
 from django.utils import timezone
@@ -1585,6 +1587,34 @@ class GenerateApiTests(TestCase):
         self.assertEqual(poll.data["status"], ImageGenerationTask.Status.FAILED)
         self.assertEqual(poll.data["error"]["code"], "upstream_timeout")
 
+    def test_run_image_tasks_logs_failed_task_alias_error_and_duration(self):
+        self.provider.image_error = requests.Timeout("image upstream deadline exceeded")
+        response = self.post_with_provider(
+            "/api/v1/generate/image/tasks",
+            {"prompt": "生成图片", "model": self.image_alias, "resolution": "1K"},
+        )
+        out = io.StringIO()
+
+        with patch("apps.api.generation.get_provider", return_value=self.provider):
+            call_command(
+                "run_image_tasks",
+                "--once",
+                "--worker-id",
+                "worker-log",
+                stdout=out,
+            )
+
+        task = ImageGenerationTask.objects.get(task_id=response.data["task_id"])
+        output = out.getvalue()
+        self.assertEqual(task.status, ImageGenerationTask.Status.FAILED)
+        self.assertIn("event=image_task_processed", output)
+        self.assertIn(f"task_id={task.task_id}", output)
+        self.assertIn(f"alias={self.image_alias}", output)
+        self.assertIn("status=failed", output)
+        self.assertIn("error_code=upstream_timeout", output)
+        self.assertRegex(output, r"duration_ms=\d+")
+        self.assertNotIn("生成图片", output)
+
     def test_async_image_reaper_fails_stale_running_task_and_refunds(self):
         response = self.post_with_provider(
             "/api/v1/generate/image/tasks",

docs/deployment.md

@@ -281,6 +281,10 @@ python3.12 manage.py run_image_tasks \
 
 建议单独托管为 `cmhub-image-worker.service`。该 worker 从数据库 `image_generation_task` 表抢 `queued` 任务，使用 MySQL `select_for_update(skip_locked)` 标记 `running`，执行成功后写 `succeeded` 和稳定 `result_url`；失败或上游超时会调用计费层退点并写 `failed`。worker 循环会按 `IMAGE_TASK_REAPER_INTERVAL_SECONDS` 扫描租约或心跳过期的 `running` 任务，默认判失败并幂等退点，不默认重排队。
 
+worker 每处理一个任务会向 stdout 输出一行结构化日志，形如 `event=image_task_processed task_id=... status=failed alias=... duration_ms=... error_code=upstream_timeout`。失败日志必须用于区分「还在 queued 未提交给上游」和「已 running 但上游超时 / 失败」；日志不得包含 prompt、`image_base64`、provider raw 或密钥。
+
+多 worker 可以并行运行同一命令，只要 `--worker-id` 不同即可；MySQL 8.4 会通过 `select_for_update(skip_locked)` 避免重复抢同一任务。生产扩容应按 2、4、8、16 逐级观察 `queued` 长度、`duration_ms`、`error_code`、MySQL 连接数、VPS CPU/内存/磁盘写入和上游失败率。不要直接扩到 100 个 worker：这会同时放大 MySQL 连接、上游请求、图片下载和本地写文件压力；如果上游已经频繁 `upstream_timeout`，100 并发通常只会把失败更快放大。
+
 当前 worker 执行前会基于任务快照复跑一次生成准备逻辑，包括 prompt 复审、别名 / Provider 解析和定价检查；账务仍使用 submit 阶段已预扣的 `CallRecord.points_cost`，不会重复扣点。这是短队列下偏安全的取舍：敏感词库变更后，排队任务仍可在执行前被拦截并退款。若生产出现明显排队或频繁切换别名 / 模型，应单独开发“提交时模型配置快照”，让 worker 使用提交时确认的模型执行。
 
 输入方式对 submit 耗时有直接影响：桌面端批量生图应优先传 `image_base64`，submit 阶段只解码并写入输入文件；`image_url` 会在 submit 阶段完成 SSRF 校验、远程下载和大小限制，再保存为输入文件引用，因此可能阻塞提交请求。`image_url` 的好处是任务进入队列后自包含，worker 不再访问调用方外部 URL；生产排查 submit 慢时，应先确认是否有客户端批量使用 `image_url`。

progress.md

@@ -1774,3 +1774,20 @@
 - 验证：仅文档更新；使用 `git diff --check` 检查格式。
 - 决策：当前不改代码。`image_base64` 是桌面端主路径，submit 仍为短请求；`image_url` 阻塞属于边缘兼容路径。模型配置快照不作为热修，待队列积压或多模型价差扩大后单独立任务。
 - 下一步：无需立即编码；继续按生产优先级处理支付回调闭环、客户端发布和线上遥测观察。
+
+## 2026-07-09 热修：异步生图 worker 失败日志与扩容口径
+
+- 状态：DONE。
+- 背景：线上 admin 中多条生图任务停留在“待处理”。排查确认 `POST /api/v1/generate/image/tasks` 已返回 `202`，任务进入 `queued`；当前只有 1 个 `cmhub-image-worker` 串行消费，部分任务在上游 180 秒硬截止后 `upstream_timeout`，导致后续 queued 积压。
+- 代码变更：
+  - `apps/api/management/commands/run_image_tasks.py`：worker 每处理一个任务输出结构化 stdout 行 `event=image_task_processed task_id=... status=... alias=... duration_ms=...`；失败 / 过期任务额外输出 `error_code`。
+  - `apps/api/tests.py`：新增目标测试，覆盖失败任务日志包含 `task_id`、别名、`error_code` 与 `duration_ms`，且不输出 prompt。
+- 文档变更：
+  - `docs/deployment.md`：补充 worker 任务日志、排障口径和扩容策略；明确不要直接扩到 100 个 worker，应按 2、4、8、16 逐级观察。
+  - `docs/current-state.md`：同步当前 worker 日志字段和扩容口径。
+- 验证：
+  - `py -3.12 -m py_compile apps\api\management\commands\run_image_tasks.py apps\api\tests.py`：通过。
+  - `py -3.12 manage.py check`：通过，0 issues。
+  - `py -3.12 manage.py test apps.api.tests.GenerateApiTests.test_run_image_tasks_logs_failed_task_alias_error_and_duration --keepdb --noinput --verbosity 2`：通过，1 test OK。
+  - `py -3.12 manage.py test apps.api.tests.GenerateApiTests --keepdb --noinput --verbosity 1`：通过，32 tests OK。
+- 决策：暂不把线上 `cmhub-image-worker` 直接扩到 100。100 个进程会同时放大 MySQL 连接、上游请求、图片下载和本地写文件压力；在上游已经出现 `upstream_timeout` 时，直接 100 并发更可能放大失败率。建议先用新日志观测后按 2、4、8、16 逐级扩容。