絵を描かせている間の出力を、読みながらログへ流す

communicate() は相手が終わるまで 1 バイトも渡さないので、上限で打ち切って kill すると
そこまでの出力ごと消えていた。実測で、20 分待って 504 になった回のログは「開始」と
「504」の 2 行だけで、描いていたのか・確認を待っていたのか・そもそも動いていなかったのかを
切り分けられなかった。

- 標準出力と標準エラーを読みながらログへ流し、同時に溜める(_pump)。止まっている
  最中でも docker logs で追える
- 打ち切るときも、そこまでの言い分を残す(504 の said とログ)
- readline() は使わない。base64 を吐く相手がいるので、限度超えで落ちて取りこぼす。
  塊で読んでこちらで行に割る
- 標準入力へ渡すのは読み出しと同時に走らせる(_feed)。先に書き切ろうとすると、
  相手が出力を吐き続けたときにパイプが詰まって双方進まなくなる
- 起動のログにモデルを出す。指定しなければ CLI の既定(いちばん重いもの)で走るので、
  遅かったときに何で走っていたのかが分からないと切り分けられない

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

Author: claude

CLAUDE.md

@@ -1460,6 +1460,14 @@ GeoNames 全世界地名辞典 = `geonames`(いずれも 348 言語版・195 か
     (絵を描く口は最初から付けていて、そちらは通っていた)。
     断って 413 を返していた頃は、pta の売買提案(候補ショートリスト込みで 120KiB 超)が
     毎回失敗していた。**書き出したファイルは答えを返す前に必ず消す**(中身はプロンプトそのもの)
+  - **絵を描かせている間の出力は、読みながらログへ流す**(`_pump`)。
+    `communicate()` は相手が終わるまで 1 バイトも渡さないので、**上限で打ち切って
+    kill すると、そこまでの出力ごと消える** —— 実測で、20 分待って 504 になった回の
+    ログは「開始」と「504」の 2 行だけだった(描いていたのか、確認を待っていたのか、
+    そもそも動いていなかったのかを切り分けられない)。**打ち切るときも言い分を残す**
+    (504 の `said`)。**`readline()` は使わない** —— base64 を吐く相手がいるので
+    限度超えで落ちて取りこぼす。標準入力へ渡すのは読み出しと同時に走らせる
+    (先に書き切ろうとすると、相手が出力を吐き続けたときにパイプが詰まる)
   - **CLI の出力は構造化して受け取る**(`_result_of`)。claude と antigravity は
     `--output-format json`、codex は `--json`(JSONL。本文は今までどおり `-o` の
     ファイルから取り、使ったぶんだけ標準出力から読む)。素のテキストは最終的な答えしか

bridge/cli_bridge.py

@@ -2113,6 +2113,56 @@ async def images_generations(body: ImageRequest):
         return await _generate_images(body)
 
 
+# 進捗としてログへ流す 1 行の長さ。溢れた出力でログを埋めないための歯止め。
+PROGRESS_LINE_MAX = 300
+
+
+async def _pump(stream: asyncio.StreamReader, name: str, sink: list[bytes]) -> None:
+    """CLI の出力を読みながらログへ流し、同時に溜める。
+
+    **`communicate()` では、固まったときに何も残らない。** あれは相手が終わるまで
+    1 バイトも渡してくれないので、上限で打ち切って kill すると、そこまでの出力ごと
+    消える —— 実測で、20 分待って 504 になった回のログは「開始」と「504」の 2 行
+    だけで、相手が何をしていたのか(描いていたのか、確認を待っていたのか、
+    そもそも動いていなかったのか)を後から一切たどれなかった。
+
+    読みながら流せば、**止まっている最中でも `docker logs` で追える**。
+
+    `readline()` は使わない。 長い行(base64 を吐く相手がいる)で
+    `ValueError: Separator is not found, and chunk exceed the limit` になり、
+    出力を取りこぼす。塊で読んで、こちらで行に割る。
+    """
+    buf = b""
+    while chunk := await stream.read(8192):
+        sink.append(chunk)
+        buf += chunk
+        *lines, buf = buf.split(b"\n")
+        for raw in lines:
+            if text := raw.decode("utf-8", "replace").strip():
+                log.info("%s image %s| %s", CLI, name, _tail(text, PROGRESS_LINE_MAX))
+        # 改行を打たない相手で溜め込まない(溜めるのは sink の役目)
+        if len(buf) > PROGRESS_LINE_MAX * 4:
+            buf = buf[-PROGRESS_LINE_MAX:]
+    if text := buf.decode("utf-8", "replace").strip():
+        log.info("%s image %s| %s", CLI, name, _tail(text, PROGRESS_LINE_MAX))
+
+
+async def _feed(proc: asyncio.subprocess.Process, payload: bytes) -> None:
+    """標準入力へ渡して閉じる。**読まずに終える相手で落とさない**
+    (codex はプロンプトを標準入力から取るが、先に諦めると受け口が閉じている)。
+
+    読み出しと同時に走らせる。 先に書き切ろうとすると、相手が出力を吐き続けた
+    ときにパイプが詰まって、こちらも相手も進まなくなる。
+    """
+    try:
+        if payload:
+            proc.stdin.write(payload)
+            await proc.stdin.drain()
+        proc.stdin.close()
+    except (BrokenPipeError, ConnectionResetError):
+        pass
+
+
 async def _generate_images(body: ImageRequest) -> dict:
     started = time.time()
     seen = _existing(_shared_root())
@@ -2132,25 +2182,44 @@ async def _generate_images(body: ImageRequest) -> dict:
             cmd = image_command(out_dir, body.model or MODEL)
             payload = prompt.encode("utf-8")
 
-        log.info("running %s image tool (prompt %d bytes)", CLI, len(prompt.encode("utf-8")))
+        # **モデルもログに出す。** 指定しなければ CLI の既定(＝一番重いもの)で走るので、
+        # 遅かったときに「何で走っていたのか」が分からないと切り分けられない。
+        log.info("running %s image tool (prompt %d bytes, model=%s)", CLI,
+                 len(prompt.encode("utf-8")), body.model or MODEL or "(CLI の既定)")
         proc = await asyncio.create_subprocess_exec(
             *cmd,
             cwd=out_dir,
             stdin=asyncio.subprocess.PIPE,
             stdout=asyncio.subprocess.PIPE,
             stderr=asyncio.subprocess.PIPE,
         )
-        try:
-            stdout, stderr = await asyncio.wait_for(
-                proc.communicate(payload),
-                timeout=IMAGE_TIMEOUT,
+        out_chunks: list[bytes] = []
+        err_chunks: list[bytes] = []
+
+        async def _run() -> None:
+            await asyncio.gather(
+                _feed(proc, payload),
+                _pump(proc.stdout, "out", out_chunks),
+                _pump(proc.stderr, "err", err_chunks),
             )
+            await proc.wait()
+
+        try:
+            await asyncio.wait_for(_run(), timeout=IMAGE_TIMEOUT)
         except TimeoutError:
             proc.kill()
             await proc.wait()
-            raise HTTPException(
-                504, {"error": f"{CLI} が {IMAGE_TIMEOUT:.0f}s で終わりませんでした"}
-            ) from None
+            # **打ち切るときこそ、言い分を残す。** ここを捨てていたせいで、
+            # 固まる相手の原因究明が一歩も進まなかった
+            said = failure_detail(b"".join(out_chunks), b"".join(err_chunks))
+            log.error("%s image tool timed out after %.0fs: %s",
+                      CLI, IMAGE_TIMEOUT, said or "(何も言わなかった)")
+            raise HTTPException(504, {
+                "error": f"{CLI} が {IMAGE_TIMEOUT:.0f}s で終わりませんでした",
+                "said": said or "(何も言わなかった)",
+            }) from None
+
+        stdout, stderr = b"".join(out_chunks), b"".join(err_chunks)
 
         if proc.returncode != 0:
             detail = failure_detail(stdout, stderr)

docs/ai.md

@@ -245,6 +245,13 @@ platform.openai.com 側(従量課金)でクレジットが要ります —— 
 覚えて除き、かつブリッジ側で直列化しています。1 枚 1 分以上かかる相手なので、
 並べても速くはなりません。
 
+**戻ってこないときは、ブリッジのログに途中経過が出ます。** CLI の標準出力と標準エラーを
+読みながら流しているので、`docker logs chiezo-bridge-<CLI 名>` に
+`<CLI 名> image out| …` の行が並びます —— 描いているのか、確認を待っているのか、
+そもそも動いていないのかが、止まっている最中に分かります。
+**打ち切ったときも、そこまでに言っていたことを捨てません**(504 の `said` に入ります)。
+上限は `CHIEZO_BRIDGE_IMAGE_TIMEOUT`(既定 1200 秒)。
+
 gpt-image が **403** を返したら、OpenAI の開発者コンソールで**組織の本人確認**を求められて
 いることがあります —— API の話なので、ChatGPT や Codex のサブスクで使えているかは関係しません。
 

tests/test_bridge.py

@@ -840,6 +840,68 @@ def test_text_files_are_not_mistaken_for_images(self, bridge, tmp_path):
         assert server._collect_images(str(tmp_path), _t.time()) == []
 
 
+class TestImageProgressIsVisible:
+    """**固まったときこそ、相手の言い分を残す。**
+
+    以前は `communicate()` で終わるまで溜め、上限で kill していたので、
+    打ち切った回の出力がまるごと消えていた —— 20 分待って 504 になった回の
+    ログは「開始」と「504」の 2 行だけで、描いていたのか・確認を待っていたのか・
+    そもそも動いていなかったのかを後から切り分けられなかった。
+    """
+
+    def test_the_output_is_kept_while_it_runs(self, bridge):
+        import asyncio
+
+        server = bridge(CHIEZO_BRIDGE_CLI="codex")
+
+        async def go() -> list[bytes]:
+            # StreamReader は動いているループの中でしか作れない
+            reader = asyncio.StreamReader()
+            reader.feed_data("考えています\n描いています\n".encode())
+            reader.feed_eof()
+            sink: list[bytes] = []
+            await server._pump(reader, "out", sink)
+            return sink
+
+        assert "描いています" in b"".join(asyncio.run(go())).decode()
+
+    def test_a_long_line_does_not_lose_the_output(self, bridge):
+        """base64 を吐く相手がいる。`readline()` だと限度超えで落ちて取りこぼす。"""
+        import asyncio
+
+        server = bridge(CHIEZO_BRIDGE_CLI="codex")
+
+        async def go() -> list[bytes]:
+            reader = asyncio.StreamReader()
+            reader.feed_data(b"A" * 200_000 + "\n終わりました\n".encode())
+            reader.feed_eof()
+            sink: list[bytes] = []
+            await server._pump(reader, "out", sink)
+            return sink
+
+        got = b"".join(asyncio.run(go()))
+        assert len(got) > 200_000
+        assert "終わりました" in got.decode()
+
+    def test_a_timeout_carries_what_the_cli_said(self, bridge, monkeypatch):
+        import asyncio
+
+        import fastapi
+
+        server = bridge(CHIEZO_BRIDGE_CLI="codex")
+        monkeypatch.setattr(server, "IMAGE_TIMEOUT", 0.5)
+        monkeypatch.setattr(
+            server, "image_command",
+            lambda out_dir, model="": ["sh", "-c", "echo 権限の確認を待っています; sleep 2"],
+        )
+
+        with pytest.raises(fastapi.HTTPException) as got:
+            asyncio.run(server._generate_images(server.ImageRequest(prompt="剣")))
+
+        assert got.value.status_code == 504
+        assert "権限の確認を待っています" in got.value.detail["said"]
+
+
 class TestCredentialFromAnotherApp:
     """認証情報の置き場を共有すれば、Chiezo 以外のアプリからも使える。