Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
15 changes: 6 additions & 9 deletions app/routes/chat.py
Original file line number Diff line number Diff line change
Expand Up @@ -533,19 +533,16 @@ async def _finalize() -> None:
)
from packages.db import session as session_mod

if session_mod._session_factory is not None:
try:
try:
if session_mod._session_factory is not None:
async with session_mod._session_factory() as s:
s.add(log)
await s.commit()
except Exception as commit_err:
logger.warning("request_log_commit_failed", error=str(commit_err))
else:
db.add(log)
try:
else:
db.add(log)
await db.commit()
except Exception as commit_err:
logger.warning("request_log_commit_failed", error=str(commit_err))
except Exception as commit_err:
logger.warning("request_log_commit_failed", error=str(commit_err))
Comment thread
JhaSourav07 marked this conversation as resolved.

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟡 P2 Don't fall back to the request-scoped db session for the streaming request log — it is already closed, so the fallback silently drops the row

This commit's change to _finalize() (lines 536-545) is a fallback for the case session_mod._session_factory is None: instead of the parent commit's behavior (initialize a fresh factory via init_session_factory(get_settings().database_url) — idempotent, bound to the same process-wide singleton engine — and commit through it), it now does db.add(log); await db.commit() on the request-scoped dependency session db. But _finalize() runs inside the streaming SSE generator, i.e. after chat_completions has returned the StreamingResponse and FastAPI has torn down the get_db() dependency — db is closed, which is precisely the root cause the test added in this very commit (docstring: "get_db() yields db and closes it when chat_completions returns StreamingResponse. _finalize() runs post-return during SSE stream output") and the preceding commits 3e94a41/a44be4f were written to fix. So on the exact failure path this commit claims to handle (factory unavailable), the write through the closed db fails; the except only logs request_log_commit_failed and the RequestLog row (token usage, cost_microcents, provider, status) is silently lost for every streaming request. The loss is permanent: log_written was set True at the top of _finalize() before the write, so the second call from the finally block is a no-op and a transient failure (pool exhaustion, connection error, in-memory SQLite losing its tables on reconnect) is never retried. Parent commit 3e94a41 persisted the row reliably in this case. Fix: when _session_factory is None, initialize it (e.g. session_mod.init_session_factory(get_settings().database_url)) and commit through a fresh session from it, as the parent did, rather than using the closed request db.


try:
async for chunk in _aiter(stream_obj):
Expand Down
137 changes: 137 additions & 0 deletions tests/integration/test_stream_log_reliability.py
Original file line number Diff line number Diff line change
@@ -0,0 +1,137 @@
"""Streaming chat completions log persistence and teardown resilience tests.

Validates that streaming completion request logs are reliably persisted to the database
even after the request-scoped dependency session (`get_db()`) has exited and closed.
"""

from __future__ import annotations

import time
from unittest.mock import AsyncMock

import pytest
from httpx import ASGITransport, AsyncClient
from sqlalchemy import select
from sqlalchemy.ext.asyncio import async_sessionmaker, create_async_engine

from app import router_cache
from packages.auth.hashing import hash_api_key
from packages.db import session as session_mod
from packages.db.models.api_key import ApiKey
from packages.db.models.base import Base
from packages.db.models.request_log import RequestLog


@pytest.mark.asyncio
async def test_streaming_log_persistence_when_dependency_session_is_closed(monkeypatch):
"""Verify that streaming request logs are written to the database after get_db() dependency session closes.

Root Cause (Issue #2): get_db() yields `db` and closes it when chat_completions returns
StreamingResponse. _finalize() runs post-return during SSE stream output. Using a dedicated
session from session_factory ensures the RequestLog is successfully saved despite `db` being closed.
"""
engine = create_async_engine("sqlite+aiosqlite:///:memory:", future=True)
async with engine.begin() as conn:
await conn.run_sync(Base.metadata.create_all)

factory = async_sessionmaker(engine, expire_on_commit=False)

# Seed API key into isolated test database
raw_key = "sk-orca-test123456789012345678901234"
key_hash = hash_api_key(raw_key)
async with factory() as s:
s.add(
ApiKey(
id="key_streaming_test",
workspace_id="default",
name="test-key",
key_hash=key_hash,
key_prefix="sk-orca-....1234",
is_active=True,
)
)
await s.commit()

try:
# Set _session_factory for authentication middleware and _finalize()
session_mod._session_factory = factory

chunks = [
{
"id": "chatcmpl-stream-test",
"object": "chat.completion.chunk",
"model": "gpt-4o-mini",
"created": int(time.time()),
"choices": [
{
"index": 0,
"delta": {"role": "assistant", "content": "Test stream chunk"},
"finish_reason": "stop",
}
],
"usage": {"prompt_tokens": 5, "completion_tokens": 5, "total_tokens": 10},
"_orca_meta": {"provider": "openai", "latency_ms": 10},
}
]

fake_client = AsyncMock()

async def _stream_iter(chunk_list):
for c in chunk_list:
yield c

fake_client.acompletion = AsyncMock(
return_value=_stream_iter(chunks)
)

async def _fake_get_router(_session):
return fake_client

monkeypatch.setattr(router_cache, "get_router", _fake_get_router)

from app.deps import get_db

async def _override_get_db_that_closes_on_return():
async with factory() as session:
yield session
# Dependency scope ends here when chat_completions returns StreamingResponse,
# explicitly closing session before _finalize() runs!
await session.close()

from app.main import create_app

app = create_app()
app.dependency_overrides[get_db] = _override_get_db_that_closes_on_return

async with AsyncClient(
transport=ASGITransport(app=app),
base_url="http://test",
headers={"Authorization": f"Bearer {raw_key}"},
) as c:
response = await c.post(
"/v1/chat/completions",
json={
"model": "gpt-4o-mini",
"messages": [{"role": "user", "content": "hi"}],
"stream": True,
},
)
assert response.status_code == 200
body_text = response.text
assert "data: [DONE]" in body_text

# Verify that the streaming request log WAS successfully written to DB via session_factory
async with factory() as check_session:
rows = (await check_session.execute(select(RequestLog))).scalars().all()

assert len(rows) == 1, (

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟡 P2 Test cannot detect that the fallback-to-db path never persists the stream log

The commit is titled "fallback to active db session for request logging if session_factory is unavailable", and the test asserts len(rows) == 1 as proof that streaming logs are reliably persisted. But the test unconditionally sets session_mod._session_factory = factory (line 57), so _finalize() in app/routes/chat.py (lines 537-543) always takes the factory branch; the else: db.add(log); await db.commit() fallback is never executed. The fallback itself cannot work in the streaming case: the test's own docstring (and the comments added in the preceding commits of this series) state that get_db() closes db when chat_completions returns its StreamingResponse, i.e. before _finalize() runs. So whenever _session_factory is actually None at _finalize() time — the exact scenario this commit claims to handle (e.g. a deployment where the auth middleware/lifespan haven't initialized the factory) — db.add(log) on the closed session raises, the exception is swallowed by the except Exception at line 544, and the RequestLog row (usage/cost accounting data) is silently dropped. The test gives false assurance: it would pass with the fallback branch deleted, and it can never observe the broken path. The fallback should either use a freshly-created session (as the pre-series code did via init_session_factory) or the test should cover the factory-None path against a real (non-mock) closed session.

f"Expected 1 RequestLog row for streaming completion, but found {len(rows)}. "
"Streaming log failed to persist when request-scoped db session was closed."
)
log = rows[0]
assert log.is_streaming is True
assert log.input_tokens == 5
assert log.output_tokens == 5
finally:
session_mod._session_factory = None
await engine.dispose()
Loading