emrg: LLM attempt log only on retry — first attempt silent

Agent.md

@@ -118,7 +118,7 @@ Community needs voiced in HN agent-UI discussions map directly to EMRG's design:
 pkill -f "emrg.server"; rm -f ~/.emrg/emrgd.port; python -m emrg
 ```
 
-Python: `uv run pytest tests/ -v` (871) — import check: `uv run python -c "from emrg.client.app import run_client"`
+Python: `uv run pytest tests/ -v` (875) — import check: `uv run python -c "from emrg.client.app import run_client"`
 GUI: `cd emrg/gui && npm test` (257: 45 daemon_client + 19 conn-manager + 22 app-commands + 129 renderer smoke + 16 i18n + 7 integration + 3 commands + 7 build-config + 7 gui-state + 2 tool-group) — syntax: `node --check main.js preload.js daemon_client.js renderer/js/*.js`
 CI: `uv run pytest` (ubuntu + **windows-2025 matrix** — Windows pytest 回归在 PR CI 即失败，v0.2.29 教训 #725) + GUI tests + **actionlint workflow lint** (`rhysd/actionlint@v1.7.12` gate, #444 — workflow 解析错误在 PR CI 即失败，如 `if:` secrets 上下文)
 Re-trigger: `scripts/re-trigger-ci.sh [branch]` (workflow_dispatch, #527 — 替代空 commit 重触发：Actions outage 会整段丢弃 push 事件，dispatch 走 API 路径不受影响)

emrg/server/llm.py

@@ -137,8 +137,13 @@ async def chat(
 
  last_error = None
  for attempt in range(MAX_RETRIES + 1):
- logger.debug("LLM request: url=%s model=%s (attempt %d/%d)",
- _redact_text(url), self.config.model, attempt + 1, MAX_RETRIES + 1)
+ # First attempt is the normal path — log nothing (rant
+ # 2026-08-17T14:27:39: 1/4 on every request is noise); retries
+ # already log via the "transient error ... retrying" warning,
+ # this debug line only adds the attempt counter for retries.
+ if attempt > 0:
+ logger.debug("LLM request: url=%s model=%s (attempt %d/%d)",
+ _redact_text(url), self.config.model, attempt + 1, MAX_RETRIES + 1)
 
  resp = await client.post(url, headers=headers, json=payload)
 
@@ -236,7 +241,10 @@ async def chat_stream(
 
  last_error = None
  for attempt in range(MAX_RETRIES + 1):
- logger.debug("LLM stream attempt %d/%d", attempt + 1, MAX_RETRIES + 1)
+ # First attempt silent (rant 2026-08-17T14:27:39) — the retrying
+ # warning already logs the retry; this adds the attempt counter.
+ if attempt > 0:
+ logger.debug("LLM stream attempt %d/%d", attempt + 1, MAX_RETRIES + 1)
  # Reset accumulators before each attempt
  content_parts[:] = []
  tc_by_index.clear()

tests/test_llm.py

@@ -207,6 +207,7 @@ def __init__(self, status_code: int, content: bytes, headers=None):
  self.status_code = status_code
  self.content = content
  self.headers = headers or {}
+ self.text = content.decode("utf-8", "replace")
 
 
 class _FakeHttpClient:
@@ -267,4 +268,148 @@ def test_chat_malformed_body_exhausts_retries(monkeypatch, client):
  client._client = fake
  with pytest.raises(RuntimeError, match="unparseable"):
  asyncio.run(client.chat([{"role": "user", "content": "hi"}]))
- assert fake.calls == 4 # 1 initial + 3 retries
+
+
+class _FakeStreamResponse:
+ def __init__(self, status_code: int):
+ self.status_code = status_code
+
+ async def __aenter__(self):
+ return self
+
+ async def __aexit__(self, *exc):
+ return False
+
+ async def aread(self):
+ return b"stream body"
+
+
+class _FakeStreamClient:
+ def __init__(self, responses):
+ self.responses = list(responses)
+ self.calls = 0
+
+ def stream(self, method, url, headers=None, json=None):
+ self.calls += 1
+ return self.responses.pop(0)
+
+
+def _drain_stream(client, fake) -> list[str]:
+ """Run one chat_stream call to exhaustion, returning accumulated chunks."""
+ import asyncio
+ parts: list[str] = []
+
+ async def _run():
+ async for chunk in client.chat_stream([{"role": "user", "content": "hi"}]):
+ if chunk.get("content"):
+ parts.append(chunk["content"])
+
+ asyncio.run(_run())
+ return parts
+
+
+def test_first_attempt_silent_no_retry(monkeypatch, client, caplog):
+ """First-attempt (normal) requests log NO attempt line (rant
+ 2026-08-17T14:27:39) — 1/4 on every request was noise."""
+ import logging
+ import asyncio
+ caplog.set_level(logging.DEBUG, logger="emrg.server.llm")
+ body = b'{"choices": [{"message": {"content": "ok"}}]}'
+ fake = _FakeHttpClient([_FakeResponse(200, body)])
+ client._client = fake
+ asyncio.run(client.chat([{"role": "user", "content": "hi"}]))
+ assert fake.calls == 1
+ # no attempt counter for the first attempt
+ assert "attempt 1/4" not in caplog.text
+ assert "LLM request: url=" not in caplog.text
+ assert "LLM stream attempt" not in caplog.text
+
+
+def test_retry_logs_attempt_counter(monkeypatch, client, caplog):
+ """Retries DO log the attempt counter (attempt 2/4+) alongside the
+ existing transient-error warning — the retry path stays traceable."""
+ import logging
+ import asyncio
+ _patch_fast_sleep(monkeypatch)
+ caplog.set_level(logging.DEBUG, logger="emrg.server.llm")
+ good = b'{"choices": [{"message": {"content": "recovered"}}]}'
+ fake = _FakeHttpClient([
+ _FakeResponse(500, b"boom"),
+ _FakeResponse(200, good),
+ ])
+ client._client = fake
+ asyncio.run(client.chat([{"role": "user", "content": "hi"}]))
+ assert fake.calls == 2
+ # first attempt silent; retry logs the attempt counter + transient warning
+ assert "attempt 1/4" not in caplog.text
+ assert "LLM transient error 500" in caplog.text
+ assert "attempt 2/4" in caplog.text
+
+
+def test_stream_first_attempt_silent(monkeypatch, client, caplog):
+ """chat_stream's first attempt is also silent (rant 2026-08-17T14:27:39)."""
+ import logging
+ _patch_fast_sleep(monkeypatch)
+ caplog.set_level(logging.DEBUG, logger="emrg.server.llm")
+
+ class _GoodStream:
+ status_code = 200
+ headers = {}
+
+ async def __aenter__(self):
+ return self
+
+ async def __aexit__(self, *exc):
+ return False
+
+ async def aiter_lines(self):
+ import json
+ for obj in (
+ {"choices": [{"delta": {"content": "hi"}}]},
+ {"choices": [{"delta": {}, "finish_reason": "stop"}]},
+ ):
+ yield "data: " + json.dumps(obj)
+
+ fake = _FakeStreamClient([_GoodStream()])
+ client._client = fake
+ parts = _drain_stream(client, fake)
+ assert parts == ["hi"]
+ assert fake.calls == 1
+ assert "LLM stream attempt" not in caplog.text
+
+
+def test_stream_retry_logs_attempt_counter(monkeypatch, client, caplog):
+ """chat_stream retry logs the attempt counter (attempt 2/4)."""
+ import logging
+ _patch_fast_sleep(monkeypatch)
+ caplog.set_level(logging.DEBUG, logger="emrg.server.llm")
+
+ class _GoodStream:
+ status_code = 200
+ headers = {}
+
+ async def __aenter__(self):
+ return self
+
+ async def __aexit__(self, *exc):
+ return False
+
+ async def aiter_lines(self):
+ import json
+ for obj in (
+ {"choices": [{"delta": {"content": "hi"}}]},
+ {"choices": [{"delta": {}, "finish_reason": "stop"}]},
+ ):
+ yield "data: " + json.dumps(obj)
+
+ fake = _FakeStreamClient([
+ _FakeStreamResponse(500), # first attempt → retry
+ _GoodStream(), # second attempt → success
+ ])
+ client._client = fake
+ parts = _drain_stream(client, fake)
+ assert parts == ["hi"]
+ assert fake.calls == 2
+ assert "LLM stream attempt 2/4" in caplog.text
+ assert "attempt 1/4" not in caplog.text
+ assert "LLM stream transient error 500" in caplog.text