Repository navigation
198: Track client-closed requests as 499 in usage logging #199
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: main
Are you sure you want to change the base?
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,63 @@ | ||
| """Tests for non-streaming client-disconnect handling in ``log_request``. | ||
|
|
||
| When a client disconnects while the view is still awaiting the upstream LLM | ||
| (before any response has been returned), Django's ASGI handler cancels the | ||
| request task, which raises ``asyncio.CancelledError`` inside the view. | ||
| ``log_request`` catches that and records status 499 on the request log. | ||
|
|
||
| This asserts the non-streaming behaviour, complementing the streaming tests | ||
| in ``test_stream_status.py`` (which exercise ``_openai_stream`` directly). | ||
| """ | ||
|
|
||
| import asyncio | ||
| import time | ||
| from types import SimpleNamespace | ||
| from typing import ClassVar | ||
|
|
||
| from asgiref.sync import async_to_sync | ||
| from django.test import TestCase | ||
|
|
||
| from gateway.views.decorators import log_request | ||
| from management.models import Request, Token | ||
|
|
||
|
|
||
| def _make_request(path: str = "/v1/chat/completions") -> SimpleNamespace: | ||
| """Minimal stand-in for an ASGI request, exposing only what log_request reads.""" | ||
| return SimpleNamespace( | ||
| path=path, | ||
| method="POST", | ||
| headers=SimpleNamespace(get=lambda key, default="": default), | ||
| META=SimpleNamespace(get=lambda key, default="": default), | ||
| ) | ||
|
|
||
|
|
||
| class LogRequestCancelTests(TestCase): | ||
| fixtures: ClassVar[list[str]] = ["gateway_data.json"] | ||
|
|
||
| def setUp(self): | ||
| self.token = Token.objects.get(name="My Token") | ||
|
|
||
| def test_non_streaming_client_disconnect_records_499(self): | ||
| """A disconnect while awaiting the upstream is recorded as 499.""" | ||
| started = asyncio.Event() | ||
|
|
||
| async def hanging_view(request, *args, **kwargs): | ||
| started.set() | ||
| await asyncio.sleep(3600) # simulate awaiting the upstream LLM | ||
|
|
||
| wrapped = log_request(hanging_view) | ||
|
|
||
| async def run(): | ||
| task = asyncio.create_task( | ||
| wrapped(_make_request(), token=self.token, request_start=time.monotonic()) | ||
| ) | ||
| await started.wait() | ||
| task.cancel() | ||
| with self.assertRaises(asyncio.CancelledError): | ||
| await task | ||
|
|
||
| async_to_sync(run)() | ||
|
|
||
| request_log = Request.objects.get(token=self.token) | ||
| self.assertEqual(request_log.status_code, 499) | ||
| self.assertIsNotNone(request_log.response_time_ms) |
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,93 @@ | ||
| """Tests for the streaming status-code recording in the request log. | ||
|
|
||
| Covers the mapping the stream generator writes to ``Request.status_code``: | ||
|
|
||
| - Clean completion -> 200 | ||
| - Client closes -> 499 (client-closed-request) | ||
| - Upstream failure -> 500 | ||
| """ | ||
|
|
||
| import json | ||
| from typing import ClassVar | ||
|
|
||
| from asgiref.sync import async_to_sync | ||
| from django.test import TestCase | ||
|
|
||
| from gateway.views.utils import _openai_stream | ||
| from management.models import Request, Token | ||
|
|
||
|
|
||
| class _Chunk: | ||
| """Minimal stand-in for a streamed chunk that only needs model_dump_json.""" | ||
|
|
||
| def model_dump_json(self, *args, **kwargs) -> str: | ||
| return json.dumps({"choices": [{"delta": {"content": "hi"}}]}) | ||
|
|
||
|
|
||
| class OpenAIStreamStatusTests(TestCase): | ||
| fixtures: ClassVar[list[str]] = ["gateway_data.json"] | ||
|
|
||
| def setUp(self): | ||
| self.token = Token.objects.get(name="My Token") | ||
|
|
||
| def _request_log(self) -> Request: | ||
| request_log = Request(token=self.token, model="gpt-4.1-nano") | ||
| request_log.save() | ||
| return request_log | ||
|
|
||
| def test_clean_completion_records_200(self): | ||
| async def fake_stream(): | ||
| yield _Chunk() | ||
| yield _Chunk() | ||
|
|
||
| request_log = self._request_log() | ||
| stream = _openai_stream(fake_stream(), request_log) | ||
|
|
||
| async def consume_all(): | ||
| async for _ in stream: | ||
| pass | ||
|
|
||
| async_to_sync(consume_all)() | ||
| request_log.refresh_from_db() | ||
| self.assertEqual(request_log.status_code, 200) | ||
|
|
||
| def test_client_close_records_499(self): | ||
| """When the client closes the connection mid-stream we record 499.""" | ||
|
|
||
| async def fake_stream(): | ||
| yield _Chunk() | ||
| yield _Chunk() | ||
| yield _Chunk() | ||
|
|
||
| request_log = self._request_log() | ||
| stream = _openai_stream(fake_stream(), request_log) | ||
|
|
||
| async def consume_then_disconnect(): | ||
| it = stream.__aiter__() | ||
| await it.__anext__() | ||
| await it.__anext__() | ||
| await stream.aclose() | ||
|
|
||
| async_to_sync(consume_then_disconnect)() | ||
| request_log.refresh_from_db() | ||
| self.assertEqual(request_log.status_code, 499) | ||
|
|
||
| def test_upstream_failure_records_500(self): | ||
| """An upstream error part-way through the stream is recorded as 500.""" | ||
|
|
||
| async def failing_stream(): | ||
| yield _Chunk() | ||
| raise RuntimeError("upstream exploded") | ||
|
|
||
| request_log = self._request_log() | ||
| stream = _openai_stream(failing_stream(), request_log) | ||
|
|
||
| async def consume_until_failure(): | ||
| async for _ in stream: | ||
| pass | ||
|
|
||
| with self.assertRaises(RuntimeError): | ||
| async_to_sync(consume_until_failure)() | ||
|
|
||
| request_log.refresh_from_db() | ||
| self.assertEqual(request_log.status_code, 500) |
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -1,3 +1,4 @@ | ||
| import asyncio | ||
| import base64 | ||
| import io | ||
| import json | ||
|
|
@@ -419,15 +420,25 @@ async def wrapper(request: ASGIRequest, *args: Any, **kwargs: Any) -> ViewResult | |
| log.debug("Initial request log object created.") | ||
|
|
||
| response_start_time = time.monotonic() | ||
| result: HttpResponse | StreamingHttpResponse = await view_func(request, *args, **kwargs) | ||
|
|
||
| try: | ||
| result: HttpResponse | StreamingHttpResponse = await view_func(request, *args, **kwargs) | ||
| except asyncio.CancelledError: | ||
| request_log.status_code = 499 | ||
| request_log.response_time_ms = int((time.monotonic() - response_start_time) * 1000) | ||
| await request_log.asave() | ||
| raise | ||
|
|
||
| end_time = time.monotonic() | ||
|
|
||
| assert "request_start" in kwargs, ( | ||
| "`log_request` decorator can only be used with the `token_authenticated` decorator" | ||
| ) | ||
| request_log.processing_time_ms = int((response_start_time - kwargs["request_start"]) * 1000) | ||
| request_log.response_time_ms = int((end_time - response_start_time) * 1000) | ||
| request_log.status_code = result.status_code | ||
|
|
||
|
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Maybe I am misunderstanding but should we not set
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Or can non-streaming requests never lead to a disconnect this way? What happens if a client disconnects in a non streaming request before the result is returned? I guess we still wait for a response and then just take that status code? But I guess the whole request in Django is then closed so do we even listen to the response then?
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I may be wrong, but I'm not sure if client disconnects are handled at all for non-streaming responses. The docs only mention it for
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I don't know about this one that much, but I studied with deepseek 🐳 for a while, as far as I understand :
|
||
| if not isinstance(result, StreamingHttpResponse): | ||
| request_log.status_code = result.status_code | ||
|
|
||
| await request_log.asave() | ||
| return result | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -1,3 +1,4 @@ | ||
| import asyncio | ||
| import json | ||
| import logging | ||
| import time | ||
|
|
@@ -61,27 +62,29 @@ def _openai_stream( | |
|
|
||
| async def _stream() -> AsyncGenerator[str, None]: | ||
| token_usage = Usage(0, 0) | ||
| async for chunk in stream: | ||
| chunk_str = chunk.model_dump_json(exclude_none=True, exclude_unset=True) | ||
| try: | ||
| async for chunk in stream: | ||
| chunk_str = chunk.model_dump_json(exclude_none=True, exclude_unset=True) | ||
|
|
||
| # Extract token usage from this chunk | ||
| chunk_usage = _get_token_usage(chunk_str.encode("utf-8")) | ||
| chunk_usage = _get_token_usage(chunk_str.encode("utf-8")) | ||
|
|
||
| # Only update if we got actual usage data (non-zero tokens) | ||
| if chunk_usage.input_tokens > 0 or chunk_usage.output_tokens > 0: | ||
| token_usage = chunk_usage | ||
| if chunk_usage.input_tokens > 0 or chunk_usage.output_tokens > 0: | ||
| token_usage = chunk_usage | ||
|
|
||
| try: | ||
| yield f"data: {chunk_str}\n\n" | ||
| except Exception as e: | ||
| yield f"data: {e!s}\n\n" | ||
|
|
||
| end_time = time.monotonic() | ||
| request_log.token_usage = token_usage | ||
| request_log.response_time_ms = int((end_time - start_time) * 1000) | ||
| await request_log.asave() | ||
| # Streaming is done, yield the [DONE] chunk | ||
| yield "data: [DONE]\n\n" | ||
|
|
||
| request_log.status_code = 200 | ||
| yield "data: [DONE]\n\n" | ||
| except (asyncio.CancelledError, GeneratorExit): | ||
|
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
|
||
| request_log.status_code = 499 | ||
| raise | ||
| except Exception: | ||
| request_log.status_code = 500 | ||
| raise | ||
| finally: | ||
| request_log.token_usage = token_usage | ||
| request_log.response_time_ms = int((time.monotonic() - start_time) * 1000) | ||
| await request_log.asave() | ||
|
|
||
| return _stream() | ||
|
|
||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,61 @@ | ||
| """Tests the usage dashboard counts 499 (client-closed) as a failed request. | ||
|
|
||
| A 499 status code is >= 400, so the dashboard's ``failed_requests`` stat | ||
| (``status_code__gte=400``) must include it — confirming client-closed requests | ||
| show up in the dashboard's failed-requests count. | ||
| """ | ||
|
|
||
| from pathlib import Path | ||
|
|
||
| from django.contrib.auth import get_user_model | ||
| from django.contrib.auth.models import Group | ||
| from django.test import TestCase, override_settings | ||
| from django.urls import reverse | ||
|
|
||
| from management.models import Org, Request, Token, UserGroup, UserProfile | ||
|
|
||
| User = get_user_model() | ||
|
|
||
| ROOT = Path(__file__).resolve().parents[3] | ||
|
|
||
| ALLOWED_MODEL = "gpt-4.1-nano" | ||
|
|
||
|
|
||
| @override_settings(LITELLM_ROUTER_CONFIG_FILE_PATH=str(ROOT / "example_router_config.yaml")) | ||
| class UsageDashboardFailedRequestTests(TestCase): | ||
| def setUp(self): | ||
| self.org = Org.objects.create(name="usage-org") | ||
| self.user = User.objects.create_user(username="usageuser", email="usage@example.com") | ||
| UserProfile.objects.create(user=self.user, org=self.org) | ||
| Group.objects.get_or_create(name=UserGroup.USER.value) | ||
| self.token = Token(name="usage-token", user=self.user) | ||
| self.token._set_new_key() | ||
| self.token.save() | ||
| self.client.force_login(self.user) | ||
|
|
||
| def _add_request(self, status_code: int) -> Request: | ||
| return Request.objects.create( | ||
| token=self.token, | ||
| model=ALLOWED_MODEL, | ||
| status_code=status_code, | ||
| user_id=self.user.email, | ||
| path="/chat/completions", | ||
| ) | ||
|
|
||
| def test_499_counts_as_failed_request(self): | ||
| self._add_request(status_code=499) | ||
|
|
||
| resp = self.client.get(reverse("usage")) | ||
| self.assertEqual(resp.status_code, 200) | ||
| self.assertEqual(resp.context["failed_requests"], 1) | ||
| self.assertEqual(resp.context["total_requests"], 1) | ||
|
|
||
| def test_499_and_500_both_count_as_failed(self): | ||
| self._add_request(status_code=200) | ||
| self._add_request(status_code=499) | ||
| self._add_request(status_code=500) | ||
|
|
||
| resp = self.client.get(reverse("usage")) | ||
| self.assertEqual(resp.status_code, 200) | ||
| self.assertEqual(resp.context["total_requests"], 3) | ||
| self.assertEqual(resp.context["failed_requests"], 2) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I add try, except for non-streaming requests to save 499 status code and stop running Django logic.