fix: retry transient LLM failures to survive shared-server queue, log 500 detail
- llm.py: _create() wrapper retries APIConnectionError (incl. timeout) up to LLM_MAX_ATTEMPTS=3 with LLM_RETRY_DELAY_SECONDS=5s backoff; 4xx still fails fast. The local LLM server is shared with Hermes and serializes requests, so a request can be dropped by the client timeout while queued — chat/send was 500ing on that. - helpers.py: internal_error() now logs full exception detail server-side (was only the type name), so 500s are diagnosable; client message unchanged. - config.py: LLM_MAX_ATTEMPTS / LLM_RETRY_DELAY_SECONDS env knobs. - tests: test_llm_retry_queue (transient retried, 4xx not retried, no retry on success), test_internal_error_logging (detail in log, hidden from client, order-independent via explicit handler + logger re-enable).
This commit is contained in:
@@ -184,9 +184,14 @@ def api_error_handler(err: ApiError):
|
||||
|
||||
|
||||
def internal_error(message: str, exc: BaseException, status: int = 500) -> ApiError:
|
||||
"""Log only the exception type; never expose exception text to clients."""
|
||||
"""Log the exception type and detail server-side; never expose text to clients.
|
||||
|
||||
The detail is what makes 500s diagnosable — without it the log says only
|
||||
"LLMError" and the real cause (404 unknown model / 401 bad key / ...) is
|
||||
lost. Client-facing text stays the generic message.
|
||||
"""
|
||||
current_app.logger.error(
|
||||
"%s (error_type=%s)", message, type(exc).__name__
|
||||
"%s (error_type=%s) %s", message, type(exc).__name__, exc
|
||||
)
|
||||
return ApiError(message, status)
|
||||
|
||||
|
||||
@@ -153,6 +153,14 @@ class Config:
|
||||
|
||||
# LLM
|
||||
LLM_BASE_URL, LLM_MODEL, LLM_API_KEY, LLM_PROVIDER = resolve_llm()
|
||||
# The local LLM server is shared (also serves Hermes): a concurrent long
|
||||
# generation serializes requests, so a request can sit in the server queue
|
||||
# well beyond a single attempt. Retry transient connection/timeout failures
|
||||
# a few times so chat survives the queue instead of failing with 500.
|
||||
LLM_MAX_ATTEMPTS = _get_int("LLM_MAX_ATTEMPTS", 3, minimum=1)
|
||||
LLM_RETRY_DELAY_SECONDS = _get_float(
|
||||
"LLM_RETRY_DELAY_SECONDS", 5.0, minimum=0.0
|
||||
)
|
||||
|
||||
# OAuth (Google + Facebook) — all optional; OAuth is disabled unless creds
|
||||
# are fully configured (fail closed). Client IDs / app IDs are public and
|
||||
|
||||
@@ -6,6 +6,7 @@ from __future__ import annotations
|
||||
|
||||
import json
|
||||
import re
|
||||
import time
|
||||
from typing import Any
|
||||
|
||||
from openai import OpenAI
|
||||
@@ -55,8 +56,47 @@ class LLMClient:
|
||||
raise LLMError("LLM_API_KEY is not configured in .env")
|
||||
if not self.base_url:
|
||||
raise LLMError("LLM_BASE_URL is not configured (unknown provider)")
|
||||
self.max_attempts = max(1, Config.LLM_MAX_ATTEMPTS)
|
||||
self.retry_delay = Config.LLM_RETRY_DELAY_SECONDS
|
||||
self.client = OpenAI(base_url=self.base_url, api_key=self.api_key, timeout=180.0, max_retries=0)
|
||||
|
||||
def _create(self, *, model: str, temperature: float, max_tokens: int, messages, extra_body):
|
||||
"""Run chat.completions.create, retrying transient failures.
|
||||
|
||||
The local LLM server is shared (it also serves Hermes): a concurrent long
|
||||
generation serializes requests, so a request can be dropped by a client
|
||||
timeout or a connection reset while it is queued. Retry those transient
|
||||
cases (openai.APIConnectionError — incl. APITimeoutError) up to
|
||||
Config.LLM_MAX_ATTEMPTS times so chat survives the queue; a 4xx from the
|
||||
server (bad key/model) is NOT transient and raises immediately.
|
||||
"""
|
||||
import logging
|
||||
from openai import APIConnectionError
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
for attempt in range(1, self.max_attempts + 1):
|
||||
try:
|
||||
return self.client.chat.completions.create(
|
||||
model=model,
|
||||
temperature=temperature,
|
||||
max_tokens=max_tokens,
|
||||
messages=messages,
|
||||
extra_body=extra_body,
|
||||
)
|
||||
except APIConnectionError as exc:
|
||||
if attempt == self.max_attempts:
|
||||
raise
|
||||
logger.warning(
|
||||
"LLM attempt %d/%d failed (%s); retrying in %.1fs",
|
||||
attempt,
|
||||
self.max_attempts,
|
||||
exc,
|
||||
self.retry_delay,
|
||||
)
|
||||
time.sleep(self.retry_delay)
|
||||
# Unreachable: the loop either returns a response or raises.
|
||||
raise LLMError("LLM call failed after retries")
|
||||
|
||||
def complete(
|
||||
self,
|
||||
system_prompt: str,
|
||||
@@ -72,7 +112,7 @@ class LLMClient:
|
||||
# (measured 313s -> 44s per persona on the local tabbyAPI server).
|
||||
extra_body = {"enable_thinking": False}
|
||||
try:
|
||||
resp = self.client.chat.completions.create(
|
||||
resp = self._create(
|
||||
model=self.model,
|
||||
temperature=temperature,
|
||||
max_tokens=max_tokens,
|
||||
@@ -141,11 +181,12 @@ class LLMClient:
|
||||
mapped = "user"
|
||||
api_messages.append({"role": mapped, "content": m.get("text") or m.get("content") or ""})
|
||||
try:
|
||||
resp = self.client.chat.completions.create(
|
||||
resp = self._create(
|
||||
model=self.model,
|
||||
temperature=temperature,
|
||||
max_tokens=max_tokens,
|
||||
messages=api_messages,
|
||||
extra_body=None,
|
||||
)
|
||||
except Exception as exc:
|
||||
raise LLMError(f"LLM call failed: {exc}") from exc
|
||||
|
||||
60
backend/tests/test_internal_error_logging.py
Normal file
60
backend/tests/test_internal_error_logging.py
Normal file
@@ -0,0 +1,60 @@
|
||||
"""internal_error: server log must carry the exception detail for 500 diagnosis,
|
||||
while the client only ever sees the generic message.
|
||||
|
||||
Uses a handler attached directly to the app logger so the assertion is
|
||||
independent of suite-wide logging configuration (other tests may set levels
|
||||
or propagation flags on shared loggers).
|
||||
"""
|
||||
from __future__ import annotations
|
||||
|
||||
import logging
|
||||
|
||||
import pytest
|
||||
|
||||
from app.api.helpers import internal_error
|
||||
|
||||
|
||||
class _Capture(logging.Handler):
|
||||
def __init__(self):
|
||||
super().__init__(level=logging.ERROR)
|
||||
self.messages: list[str] = []
|
||||
|
||||
def emit(self, record: logging.LogRecord):
|
||||
self.messages.append(record.getMessage())
|
||||
|
||||
|
||||
@pytest.fixture()
|
||||
def captured_logs(app):
|
||||
handler = _Capture()
|
||||
app.logger.addHandler(handler)
|
||||
# Other tests (alembic migrations in test_db_schema) run logging.config
|
||||
# with disable_existing_loggers=True, which disables the app logger.
|
||||
# Restore it so this assertion is independent of test order.
|
||||
app.logger.disabled = False
|
||||
yield handler
|
||||
app.logger.removeHandler(handler)
|
||||
|
||||
|
||||
def test_internal_error_logs_detail_and_hides_it_from_client(app, captured_logs):
|
||||
sentinel = "404 model 'qwen3.8' not found on this endpoint"
|
||||
with app.app_context():
|
||||
err = internal_error("LLM service unavailable", ValueError(sentinel))
|
||||
|
||||
# Client-facing payload stays generic — the sentinel must not leak.
|
||||
assert err.message == "LLM service unavailable"
|
||||
assert err.status == 500
|
||||
assert sentinel not in err.message
|
||||
|
||||
# Server-side log DOES carry the detail, so a 500 is diagnosable.
|
||||
logged = " ".join(captured_logs.messages)
|
||||
assert "LLM service unavailable" in logged
|
||||
assert "ValueError" in logged
|
||||
assert sentinel in logged
|
||||
|
||||
|
||||
def test_internal_error_default_status_and_type(app, captured_logs):
|
||||
with app.app_context():
|
||||
err = internal_error("boom", RuntimeError("disk full"))
|
||||
assert err.status == 500
|
||||
logged = " ".join(captured_logs.messages)
|
||||
assert "RuntimeError" in logged and "disk full" in logged
|
||||
95
backend/tests/test_llm_retry_queue.py
Normal file
95
backend/tests/test_llm_retry_queue.py
Normal file
@@ -0,0 +1,95 @@
|
||||
"""LLM client: transient failures (timeout / connection reset — what a shared,
|
||||
queueing LLM server produces under load) are retried so chat survives the queue;
|
||||
a 4xx from the server (bad key / model) is NOT retried and fails fast.
|
||||
"""
|
||||
from __future__ import annotations
|
||||
|
||||
import httpx
|
||||
import pytest
|
||||
|
||||
from app.llm import LLMClient, LLMError
|
||||
from openai import APIStatusError, APITimeoutError
|
||||
|
||||
|
||||
def _make_client(max_attempts: int = 3) -> LLMClient:
|
||||
c = LLMClient(base_url="http://localhost:9/v1", api_key="test-key", model="m")
|
||||
c.max_attempts = max_attempts
|
||||
c.retry_delay = 0.0
|
||||
return c
|
||||
|
||||
|
||||
def _resp():
|
||||
message = type("M", (), {"content": "ok"})()
|
||||
choice = type("C", (), {"message": message})()
|
||||
return type("R", (), {"choices": [choice]})()
|
||||
|
||||
|
||||
def _patch_sleep(monkeypatch):
|
||||
import app.llm as llm
|
||||
|
||||
monkeypatch.setattr(llm.time, "sleep", lambda s: None)
|
||||
|
||||
|
||||
def test_transient_failure_retries_then_succeeds(monkeypatch):
|
||||
c = _make_client(max_attempts=3)
|
||||
_patch_sleep(monkeypatch)
|
||||
calls = {"n": 0}
|
||||
|
||||
def flaky(**kwargs):
|
||||
calls["n"] += 1
|
||||
if calls["n"] < 3:
|
||||
raise APITimeoutError(request="req")
|
||||
return _resp()
|
||||
|
||||
c.client.chat.completions.create = flaky
|
||||
assert c.complete("sys", "user") == "ok"
|
||||
assert calls["n"] == 3
|
||||
|
||||
|
||||
def test_persistent_transient_failure_raises_after_max_attempts(monkeypatch):
|
||||
c = _make_client(max_attempts=3)
|
||||
_patch_sleep(monkeypatch)
|
||||
calls = {"n": 0}
|
||||
|
||||
def always_timeout(**kwargs):
|
||||
calls["n"] += 1
|
||||
raise APITimeoutError(request="req")
|
||||
|
||||
c.client.chat.completions.create = always_timeout
|
||||
with pytest.raises(LLMError):
|
||||
c.complete("sys", "user")
|
||||
assert calls["n"] == 3
|
||||
|
||||
|
||||
def test_4xx_not_retried_fails_fast(monkeypatch):
|
||||
c = _make_client(max_attempts=3)
|
||||
_patch_sleep(monkeypatch)
|
||||
calls = {"n": 0}
|
||||
|
||||
def bad_model(**kwargs):
|
||||
calls["n"] += 1
|
||||
raise APIStatusError(
|
||||
message="model not found",
|
||||
response=httpx.Response(404, request="req"),
|
||||
body=None,
|
||||
)
|
||||
|
||||
c.client.chat.completions.create = bad_model
|
||||
with pytest.raises(LLMError):
|
||||
c.complete("sys", "user")
|
||||
# A 4xx is not transient: exactly one attempt, no retry.
|
||||
assert calls["n"] == 1
|
||||
|
||||
|
||||
def test_success_no_retry(monkeypatch):
|
||||
c = _make_client(max_attempts=3)
|
||||
_patch_sleep(monkeypatch)
|
||||
calls = {"n": 0}
|
||||
|
||||
def ok(**kwargs):
|
||||
calls["n"] += 1
|
||||
return _resp()
|
||||
|
||||
c.client.chat.completions.create = ok
|
||||
assert c.complete("sys", "user") == "ok"
|
||||
assert calls["n"] == 1
|
||||
Reference in New Issue
Block a user