fix(router): record retries and fallback hops past a request's first logged failure (#50445)

litellm/router_rust/core.py

@@ -4378,6 +4378,9 @@ class _Driver:
         self._hop_first: Final[dict[int, BaseException]] = {}  # mutable-ok: filled as the call runs
         # Each level's latest pick error: the one object it logged, recorded and raises.
         self._level_picks: Final[dict[int, BaseException]] = {}  # mutable-ok: filled as the call runs
+        # Failures a retry or a later hop raised past the request's first logged failure, which the
+        # attempt itself recorded: the failed hop's fallback cooldown leaves them alone.
+        self._recorded_blocked: Final[set[int]] = set()  # mutable-ok: filled as the call runs
         self._served: tuple[str | None, Mapping[str, object]] = (None, MappingProxyType({}))
         # The latest attempt's deployment and call, which a blocked response is raised from.
         self._latest_call: tuple[Mapping[str, object], AttemptCall] | None = None
@@ -4804,7 +4807,10 @@ class _Driver:
                     self._level_errors.get(at + 1),
                     self._walk.hop_kwargs(event),
                 )
-                if event.get("succeeded") is not True:
+                if (
+                    event.get("succeeded") is not True
+                    and id(self._level_errors.get(at + 1)) not in self._recorded_blocked
+                ):
                     self._core.trigger_fallback_cooldown(
                         self._request,
                         self._level_errors.get(at + 1),
@@ -4967,6 +4973,28 @@ class _Driver:
             or _raised_before_provider(error),
         }
 
+    def _records_blocked(
+        self, failed: Mapping[str, object], call: "AttemptCall | None", error: BaseException, in_call: bool
+    ) -> bool:
+        """Record a failure the shared logging object skipped (a retry or later hop), like the first one."""
+        from litellm.router_utils.fallback_event_handlers import (
+            _failure_callbacks_blocked_logging_object,  # pyright: ignore[reportPrivateUsage]  # the fallback path's own rule
+        )
+
+        if not in_call or call is None or failed.get("outside_deployment") is True:
+            return False
+        if self._plan.sync:
+            if not failure_already_logged(call.kwargs, "sync_failure"):
+                return False
+        elif _failure_callbacks_blocked_logging_object(call.kwargs) is None:
+            return False
+        if not self._core.outcome_callbacks(call.kwargs, sync=self._plan.sync).get("failure", True):
+            return False
+        if self._core.blocked_failure_exempt(error, call.kwargs, self._plan.kind in _GENERIC_API_KINDS):
+            return False
+        self._recorded_blocked.add(id(error))
+        return True
+
     def _caller_entra_failure(self, error: BaseException, sent: Mapping[str, object], deployment_id: object) -> bool:
         """``is_caller_entra_credential_failure``: Entra ID rejected a credential the caller sent, not
         the deployment's own, so the failure is the caller's."""
@@ -5128,6 +5156,7 @@ class _Driver:
         # Whether a failure raised now runs the failure callbacks: none raised before the litellm
         # call or after it answered does, nor any but the first on a shared logging object.
         logs_failure: bool = False  # rebind-ok: set around the litellm call
+        in_call: bool = False  # rebind-ok: set around the litellm call, whichever attempt logs its failure
         reading_stream: StreamAttempt | None = None  # rebind-ok: set while the first chunk is read
         refused_call: Final = self._default_call_error(step)
         if refused_call is not None:
@@ -5160,6 +5189,7 @@ class _Driver:
                         return await self._refused(step, deployment, call, refused)
                 first_to_log: Final = not failure_already_logged(call.kwargs, "async_failure")
                 logs_failure = first_to_log  # rebind-ok: whether a failure here is this attempt's to log
+                in_call = True  # rebind-ok: see above
                 pending: Final[object] = (
                     self._core._endpoints.create_file_everywhere(  # pyright: ignore[reportPrivateUsage]  # see above
                         _with_target_order(call.kwargs, step.get("target_order")),
@@ -5173,12 +5203,15 @@ class _Driver:
                 awaited: Final = self._plan.kind == "generic" or inspect.isawaitable(pending)
                 answered: Final[object] = await pending if awaited else pending  # pyright: ignore[reportGeneralTypeIssues, reportUnknownVariableType]  # see above
                 logs_failure = False  # rebind-ok: see above
+                in_call = False  # rebind-ok: see above
                 self._core._endpoints.check_response(self._plan, answered, call)  # pyright: ignore[reportPrivateUsage, reportUnknownArgumentType]  # see above
                 stream: Final = self._stream_attempt(step, call.kwargs, slot)
                 logs_failure = first_to_log  # rebind-ok: the stream's own failure logging, for its first chunk
+                in_call = True  # rebind-ok: see above
                 reading_stream = stream  # rebind-ok: None until the attempt opens a stream
                 response: Final = await open_attempt_stream(stream, answered)  # pyright: ignore[reportUnknownArgumentType]  # see above
                 logs_failure = False  # rebind-ok: see above
+                in_call = False  # rebind-ok: see above
                 # `self.success_calls[model_name] += 1`, inside the try: a counter replaced with a
                 # plain dict fails the attempt.
                 self._core._endpoints.counters.succeeded(self._plan, call)  # pyright: ignore[reportPrivateUsage]  # see above
@@ -5194,7 +5227,10 @@ class _Driver:
                     )
             failed: Final = self._failed(step, deployment, call, error)
             if reading_stream is None or not logs_failure:
-                return {**failed, "recorded": not logs_failure}
+                return {
+                    **failed,
+                    "recorded": not logs_failure and not self._records_blocked(failed, call, error, in_call),
+                }
             # `_dispatch_stream_failure`: the stream logs its failure in a task of its own.
             reading_stream.report_first_chunk_failure(error)
             return {**failed, "recorded": True}
@@ -5212,6 +5248,7 @@ class _Driver:
         deployment: Mapping[str, object] = as_str_mapping(step.get("deployment")) or {}  # rebind-ok: see attempt
         call: AttemptCall | None = None  # rebind-ok: see attempt
         logs_failure: bool = False  # rebind-ok: see attempt
+        in_call: bool = False  # rebind-ok: see attempt
         self._reading_first_chunk = False
         refused_call: Final = self._default_call_error(step)
         if refused_call is not None:
@@ -5228,22 +5265,27 @@ class _Driver:
                 return {**self._failed(step, deployment, call, refused), "recorded": True}
             first_to_log: Final = not failure_already_logged(call.kwargs, "sync_failure")
             logs_failure = first_to_log  # rebind-ok: see attempt
+            in_call = True  # rebind-ok: see attempt
             answered: Final = self._core._host.invoke(call.host_op)(**call.kwargs)  # pyright: ignore[reportPrivateUsage]  # a sync endpoint
             logs_failure = False  # rebind-ok: see attempt
+            in_call = False  # rebind-ok: see attempt
             if inspect.isawaitable(answered):
                 raise _NotSynchronous(f"the host's {call.host_op} endpoint is not synchronous")
             self._core._endpoints.check_response(self._plan, answered, call)  # pyright: ignore[reportPrivateUsage]  # see above
             stream: Final = self._stream_attempt(step, call.kwargs)
             logs_failure = first_to_log  # rebind-ok: see attempt
+            in_call = True  # rebind-ok: see attempt
             self._reading_first_chunk = True
             response: Final = open_attempt_stream_sync(stream, answered)
             self._reading_first_chunk = False
             logs_failure = False  # rebind-ok: see attempt
+            in_call = False  # rebind-ok: see attempt
             self._core._endpoints.counters.succeeded(self._plan, call)  # pyright: ignore[reportPrivateUsage]  # see attempt
         except _NotSynchronous:
             raise
         except Exception as error:  # noqa: BLE001  # see attempt
-            return {**self._failed(step, deployment, call, error), "recorded": not logs_failure}
+            failed: Final = self._failed(step, deployment, call, error)
+            return {**failed, "recorded": not logs_failure and not self._records_blocked(failed, call, error, in_call)}
         return self._succeeded(call, response, "", stream)
 
     async def select(self, step: Mapping[str, object]) -> object:

litellm/router_rust/surface/health.py

@@ -298,6 +298,33 @@ class RustHealthCallbacks:
             "caller_scoped": _is_per_user_provider_request(logged) or self.per_user_deployment(deployment_id),
         }
 
+    def blocked_failure_exempt(self, exception: BaseException, kwargs: Mapping[str, object], generic: bool) -> bool:
+        """The exits of ``_trigger_cooldown_for_failed_deployment`` for a failure the request's shared
+        logging object does not log: the selection tag is not one of them; a stream stall and a
+        generic call's 404 are."""
+        from litellm.litellm_core_utils.litellm_logging import Logging
+        from litellm.router_utils.cooldown_handlers import (
+            cast_exception_status_to_int,
+            is_advisor_orchestration_failure,
+            is_caller_timeout_408,
+            is_stream_stall,
+        )
+        from litellm.router_utils.fallback_event_handlers import (
+            _REQUEST_SCOPED_STATUS_CODES,  # pyright: ignore[reportPrivateUsage]  # the fallback path's own rule
+        )
+
+        exception_status: Final[object] = getattr(exception, "status_code", "")
+        logging_obj: Final = kwargs.get("litellm_logging_obj")
+        details: Final[Mapping[str, object]] = (
+            logging_obj.model_call_details if isinstance(logging_obj, Logging) else {}
+        )
+        return (
+            (isinstance(exception, Exception) and is_advisor_orchestration_failure(exception))
+            or is_stream_stall(exception)
+            or (generic and cast_exception_status_to_int(exception_status) in _REQUEST_SCOPED_STATUS_CODES)  # pyright: ignore[reportArgumentType]  # the status as raised
+            or is_caller_timeout_408(details, exception_status, ended=datetime.now())  # pyright: ignore[reportArgumentType]  # noqa: DTZ005  # see logged_call
+        )
+
     def trigger_fallback_cooldown(
         self, kwargs: Mapping[str, object], exception: object, generic: bool, *, own_loop: bool = False
     ) -> None:

tests/unit/test_router/core/test_usage_and_failure_counting_parity.py

@@ -81,6 +81,16 @@ class SharedLoggingHost(EndpointHost):
         details["async_failure_logged_attempt"] = details.get("current_attempt_api_call_start_time")
         await super().log_async(call, error, response)
 
+    def log_sync(self, call: Call, error: BaseException | None, response: object) -> None:
+        logging_obj: Final = call.kwargs.get("litellm_logging_obj")
+        if error is None or not isinstance(logging_obj, LiteLLMLogging):
+            super().log_sync(call, error, response)
+            return
+        if logging_obj.model_call_details.get("has_logged_sync_failure") is True:
+            return
+        logging_obj.model_call_details["has_logged_sync_failure"] = True
+        super().log_sync(call, error, response)
+
 
 @pytest.fixture
 def host() -> SharedLoggingHost:
@@ -165,7 +175,7 @@ async def test_a_realtime_session_counts_no_request_against_a_limited_deployment
 # --- P3: what a shared logging object lets through -------------------------------------------------
 
 
-async def test_only_the_first_failure_on_a_shared_logging_object_counts_a_request(
+async def test_every_failure_on_a_shared_logging_object_counts_a_request(
     make_core: MakeCore, host: SharedLoggingHost
 ) -> None:
     core: Final = chain(make_core)
@@ -174,8 +184,8 @@ async def test_only_the_first_failure_on_a_shared_logging_object_counts_a_reques
     _ = await attempt(core, "a", litellm_logging_obj=request_logging())
 
     assert await core.health().usage("a") == (None, 1)
-    assert await core.health().usage("b") == (None, None)
-    assert await core.health().usage("c") == (None, None)
+    assert await core.health().usage("b") == (None, 1)
+    assert await core.health().usage("c") == (None, 1)
 
 
 async def test_every_failure_counts_a_request_when_each_call_logs_on_its_own(
@@ -191,13 +201,55 @@ async def test_every_failure_counts_a_request_when_each_call_logs_on_its_own(
     assert await core.health().usage("c") == (None, 1)
 
 
-async def test_a_blocked_retry_in_the_same_group_records_nothing(make_core: MakeCore, host: SharedLoggingHost) -> None:
+async def test_a_retry_past_the_first_logged_failure_is_recorded(make_core: MakeCore, host: SharedLoggingHost) -> None:
     core: Final = make_core(model_list=[deployment("g", "a"), deployment("g", "b")], num_retries=1, allowed_fails=5)
     host.answer("*", fresh(server_error))
 
     _ = await attempt(core, "g", litellm_logging_obj=request_logging())
 
-    assert core.health().failures_this_minute("a") + core.health().failures_this_minute("b") == 1
+    assert core.health().failures_this_minute("a") + core.health().failures_this_minute("b") == 2
+
+
+def test_a_sync_retry_past_the_first_logged_failure_is_recorded(make_core: MakeCore, host: SharedLoggingHost) -> None:
+    core: Final = make_core(model_list=[deployment("g", "a"), deployment("g", "b")], num_retries=1, allowed_fails=5)
+    host.answer("*", fresh(server_error))
+
+    _ = attempt_sync(core, "g", litellm_logging_obj=request_logging())
+
+    assert core.health().failures_this_minute("a") + core.health().failures_this_minute("b") == 2
+
+
+async def test_a_retried_deployment_is_cooled_down_past_the_first_logged_failure(
+    make_core: MakeCore, host: SharedLoggingHost
+) -> None:
+    core: Final = make_core(
+        model_list=[deployment("g", "a"), deployment("g", "b")], num_retries=1, allowed_fails=0, cooldown_time=60
+    )
+    host.answer("*", fresh(rate_limited))
+
+    _ = await attempt(core, "g", litellm_logging_obj=request_logging())
+
+    assert sorted(cooled_down(core, ["a", "b"])) == ["a", "b"]
+
+
+async def test_a_hop_whose_group_is_cooled_records_its_first_failure(
+    make_core: MakeCore, host: SharedLoggingHost
+) -> None:
+    core: Final = make_core(
+        model_list=[deployment("a", "a"), deployment("b", "b"), deployment("c", "c")],
+        fallbacks=[{"a": ["b"]}, {"b": ["c"]}],
+        num_retries=0,
+        allowed_fails=0,
+        cooldown_time=60,
+    )
+    host.answer("openai/a", fresh(server_error))
+    host.answer("openai/b", fresh(rate_limited))
+    _ = await attempt(core, "a", litellm_logging_obj=request_logging())
+    assert sorted(cooled_down(core, ["a", "b"])) == ["a", "b"]
+
+    _ = await attempt(core, "a", litellm_logging_obj=request_logging())
+
+    assert core.health().failures_this_minute("b") == 1
 
 
 def test_a_sync_failure_counts_no_request(make_core: MakeCore, host: SharedLoggingHost) -> None:
@@ -253,12 +305,22 @@ def selection_failure() -> Exception:
 
 
 @pytest.mark.parametrize(
-    ("builder", "stalled", "counted"),
-    [(server_error, False, 1), (selection_failure, False, 1), (timeout, True, 0), (timeout, False, 1)],
+    ("builder", "stalled", "counted", "requests"),
+    [
+        (server_error, False, 1, 1),
+        (selection_failure, False, 1, None),
+        (timeout, True, 0, None),
+        (timeout, False, 1, 1),
+    ],
     ids=["server-error", "selection-tag-not-exempt", "stream-stall-exempt", "plain-timeout"],
 )
 async def test_a_failed_hop_past_the_first_logged_failure_takes_the_fallback_paths_exits(
-    make_core: MakeCore, host: SharedLoggingHost, builder: ErrorBuilder, stalled: bool, counted: int
+    make_core: MakeCore,
+    host: SharedLoggingHost,
+    builder: ErrorBuilder,
+    stalled: bool,
+    counted: int,
+    requests: int | None,
 ) -> None:
     core: Final = make_core(
         model_list=[deployment("a", "a"), deployment("b", "b")], fallbacks=[{"a": ["b"]}], num_retries=0
@@ -271,7 +333,7 @@ async def test_a_failed_hop_past_the_first_logged_failure_takes_the_fallback_pat
     _ = await attempt(core, "a", litellm_logging_obj=request_logging())
 
     assert core.health().failures_this_minute("b") == counted
-    assert await core.health().usage("b") == (None, None)
+    assert await core.health().usage("b") == (None, requests)
 
 
 @pytest.mark.parametrize(("logged", "counted"), [(True, 0), (False, 1)], ids=["generic", "chat"])