Log request and upstream model names in errors

Author: yym68686

main.py

@@ -1590,10 +1590,13 @@ async def execute_attempt(attempt):
 
         def after_failure(attempt, exc, status_code, error_message):
             _ = exc
+            request_model, actual_model = _log_model_names(request_data.model, attempt.original_model)
             logger.error(
-                "Error %s with provider %s API key: %s: %s",
+                "Error %s with provider %s request_model=%s actual_model=%s API key: %s: %s",
                 status_code,
                 attempt.provider_name,
+                request_model,
+                actual_model,
                 attempt.provider_api_key_raw,
                 error_message,
             )
@@ -1654,6 +1657,11 @@ def _normalize_responses_compact_upstream_url(base_url: str, engine: str) -> str
 
     return f"{base}/compact"
 
+def _log_model_names(request_model_name: Any, actual_model_name: Any = None) -> tuple[str, str]:
+    request_model = str(request_model_name or "-")
+    actual_model = str(actual_model_name or request_model)
+    return request_model, actual_model
+
 def _responses_request_id(current_info: Any) -> str:
     if isinstance(current_info, dict):
         request_id = current_info.get("request_id")
@@ -2100,13 +2108,15 @@ async def proxy_stream():
                         except RESPONSES_STREAM_NETWORK_ERRORS as e:
                             stream_stage = "post-commit" if stream_committed else "preflight"
                             error_text = str(e) or type(e).__name__
+                            request_model, actual_model = _log_model_names(request_model_name, original_model)
                             trace_logger.warning(
-                                "%s upstream stream aborted stage=%s error_type=%s request_id=%s model=%s provider=%s key=%s upstream_url=%s: %s",
+                                "%s upstream stream aborted stage=%s error_type=%s request_id=%s request_model=%s actual_model=%s provider=%s key=%s upstream_url=%s: %s",
                                 endpoint,
                                 stream_stage,
                                 type(e).__name__,
                                 request_id,
-                                request_model_name,
+                                request_model,
+                                actual_model,
                                 provider_name,
                                 attempt.provider_api_key_raw,
                                 upstream_url,
@@ -2173,12 +2183,14 @@ def after_failure(attempt, exc, status_code, error_message):
 
             upstream_url = attempt.state.get("upstream_url", "")
             failure_stage = attempt.state.get("failure_stage")
+            request_model, actual_model = _log_model_names(request_model_name, attempt.original_model)
             if failure_stage == "auth" and isinstance(exc, ValueError):
                 trace_logger.error(
-                    "%s invalid codex api key request_id=%s model=%s provider=%s key=%s upstream_url=%s: %s",
+                    "%s invalid codex api key request_id=%s request_model=%s actual_model=%s provider=%s key=%s upstream_url=%s: %s",
                     endpoint,
                     request_id,
-                    request_model_name,
+                    request_model,
+                    actual_model,
                     attempt.provider_name,
                     attempt.provider_api_key_raw,
                     upstream_url,
@@ -2187,10 +2199,11 @@ def after_failure(attempt, exc, status_code, error_message):
                 return
             if failure_stage == "auth" and isinstance(exc, HTTPException):
                 trace_logger.error(
-                    "%s codex token refresh failed request_id=%s model=%s provider=%s key=%s upstream_url=%s: %s",
+                    "%s codex token refresh failed request_id=%s request_model=%s actual_model=%s provider=%s key=%s upstream_url=%s: %s",
                     endpoint,
                     request_id,
-                    request_model_name,
+                    request_model,
+                    actual_model,
                     attempt.provider_name,
                     attempt.provider_api_key_raw,
                     upstream_url,
@@ -2199,12 +2212,13 @@ def after_failure(attempt, exc, status_code, error_message):
                 return
 
             trace_logger.error(
-                "%s upstream error status=%s error_type=%s request_id=%s model=%s provider=%s key=%s upstream_url=%s: %s",
+                "%s upstream error status=%s error_type=%s request_id=%s request_model=%s actual_model=%s provider=%s key=%s upstream_url=%s: %s",
                 endpoint,
                 status_code,
                 type(exc).__name__,
                 request_id,
-                request_model_name,
+                request_model,
+                actual_model,
                 attempt.state.get("channel_id", attempt.provider_name),
                 attempt.provider_api_key_raw,
                 upstream_url,

test/test_refactor_routing.py

@@ -6,6 +6,7 @@
 
 import main
 from fastapi import BackgroundTasks
+from fastapi import HTTPException
 from starlette.responses import Response
 from core.models import RequestModel
 from routing import build_api_key_models_map
@@ -147,3 +148,81 @@ async def run_test():
         assert response.status_code == 200
 
     asyncio.run(run_test())
+
+
+def test_model_request_handler_error_log_includes_request_and_actual_model(monkeypatch):
+    provider_name = "provider-a"
+
+    class DummyCircularList:
+        async def is_all_rate_limited(self, model):
+            return False
+
+        async def next(self, model):
+            return "provider-key-1"
+
+        def get_items_count(self):
+            return 1
+
+    async def fake_get_right_order_providers(request_model_name, config, api_index, scheduling_algorithm):
+        return [
+            {
+                "provider": provider_name,
+                "_model_dict_cache": {"friendly-model": "gpt-4.1"},
+                "base_url": "https://example.com/v1/chat/completions",
+                "api": ["provider-key-1"],
+                "preferences": {},
+            }
+        ]
+
+    async def fake_process_request(
+        request,
+        provider,
+        background_tasks,
+        endpoint=None,
+        role=None,
+        timeout_value=0,
+        keepalive_interval=None,
+        provider_api_key_raw=None,
+    ):
+        raise HTTPException(status_code=502, detail="bad gateway")
+
+    error_logs = []
+
+    def fake_error(msg, *args, **kwargs):
+        _ = kwargs
+        error_logs.append(msg % args if args else msg)
+
+    monkeypatch.setitem(main.provider_api_circular_list, provider_name, DummyCircularList())
+    monkeypatch.setattr(main, "get_right_order_providers", fake_get_right_order_providers)
+    monkeypatch.setattr(main, "process_request", fake_process_request)
+    monkeypatch.setattr(main.logger, "error", fake_error)
+
+    main.app.state.config = {
+        "api_keys": [
+            {
+                "api": "sk-test",
+                "model": ["friendly-model"],
+                "preferences": {"AUTO_RETRY": False},
+            }
+        ]
+    }
+    main.app.state.provider_timeouts = {"global": {"default": 30}}
+    main.app.state.keepalive_interval = {"global": {"default": 99999}}
+
+    async def run_test():
+        handler = main.ModelRequestHandler()
+        response = await handler.request_model(
+            RequestModel(
+                model="friendly-model",
+                messages=[{"role": "user", "content": "hello"}],
+                stream=False,
+            ),
+            0,
+            BackgroundTasks(),
+        )
+        assert response.status_code == 502
+
+    asyncio.run(run_test())
+
+    assert any("request_model=friendly-model" in log for log in error_logs)
+    assert any("actual_model=gpt-4.1" in log for log in error_logs)

test/test_responses_retry.py

@@ -445,7 +445,7 @@ async def fake_get_right_order_providers(request_model_name, config, api_index,
         return [
             {
                 "provider": provider_name,
-                "_model_dict_cache": {"gpt-5.4": "gpt-5.4"},
+                "_model_dict_cache": {"friendly-model": "gpt-5.4"},
                 "base_url": "https://provider-a.example/v1/responses",
                 "api": ["key-a"],
                 "preferences": {},
@@ -467,7 +467,7 @@ def fake_error(msg, *args, **kwargs):
         "api_keys": [
             {
                 "api": "sk-test",
-                "model": ["gpt-5.4"],
+                "model": ["friendly-model"],
                 "preferences": {"AUTO_RETRY": False},
             }
         ]
@@ -490,7 +490,7 @@ def fake_error(msg, *args, **kwargs):
 
     response = _run_responses_request(
         ResponsesRequest(
-            model="gpt-5.4",
+            model="friendly-model",
             input=[{"role": "user", "content": "hello"}],
         ),
         endpoint="/v1/responses/compact",
@@ -499,6 +499,8 @@ def fake_error(msg, *args, **kwargs):
     assert response.status_code == 404
     assert any("/v1/responses/compact upstream error status=404" in log for log in error_logs)
     assert any("request_id=req-test" in log for log in error_logs)
+    assert any("request_model=friendly-model" in log for log in error_logs)
+    assert any("actual_model=gpt-5.4" in log for log in error_logs)
     assert any("upstream_url=https://provider-a.example/v1/responses/compact" in log for log in error_logs)
 
 
@@ -950,7 +952,7 @@ async def fake_get_right_order_providers(request_model_name, config, api_index,
         return [
             {
                 "provider": provider_name,
-                "_model_dict_cache": {"gpt-5.4": "gpt-5.4"},
+                "_model_dict_cache": {"friendly-model": "gpt-5.4"},
                 "base_url": "https://provider-a.example/v1/responses",
                 "api": ["key-a"],
                 "preferences": {},
@@ -972,7 +974,7 @@ def fake_warning(msg, *args, **kwargs):
         "api_keys": [
             {
                 "api": "sk-test",
-                "model": ["gpt-5.4"],
+                "model": ["friendly-model"],
                 "preferences": {"AUTO_RETRY": False},
             }
         ]
@@ -996,7 +998,7 @@ def fake_warning(msg, *args, **kwargs):
 
     response, body = _run_responses_request_with_stream_body(
         ResponsesRequest(
-            model="gpt-5.4",
+            model="friendly-model",
             input=[{"role": "user", "content": "hello"}],
             stream=True,
         ),
@@ -1008,6 +1010,8 @@ def fake_warning(msg, *args, **kwargs):
     assert body.endswith("data: [DONE]\n\n")
     assert any("/v1/responses/compact upstream stream aborted stage=post-commit" in log for log in warning_logs)
     assert any("error_type=RemoteProtocolError" in log for log in warning_logs)
+    assert any("request_model=friendly-model" in log for log in warning_logs)
+    assert any("actual_model=gpt-5.4" in log for log in warning_logs)
     assert any("request_id=req-test" in log for log in warning_logs)
     assert any("upstream_url=https://provider-a.example/v1/responses/compact" in log for log in warning_logs)