From 103596f2b421d3501143f03e77fe86ddab76ea3b Mon Sep 17 00:00:00 2001 From: redshift <213178690+1ftredsh@users.noreply.github.com> Date: Wed, 30 Sep 2026 20:01:43 +0800 Subject: [PATCH 1/5] fix: bound billed request lifetimes and recover abandoned reservations --- .../a73d19b6c204_reservation_deadlines.py | 42 ++++++ repro/IMPLEMENTATION.md | 46 ++++++ repro/dummy_upstream.py | 45 ++++++ repro/probe.py | 60 ++++++++ repro/results-final.txt | 19 +++ repro/results.txt | 19 +++ repro/router-final.log | 108 ++++++++++++++ repro/router-first.log | 115 +++++++++++++++ routstr/auth.py | 35 ++++- routstr/core/db.py | 12 +- routstr/core/lifecycle.py | 135 ++++++++++++++++++ routstr/core/main.py | 5 + routstr/core/settings.py | 10 ++ routstr/upstream/stream_ownership.py | 7 +- tests/unit/test_request_lifecycle.py | 57 ++++++++ tests/unit/test_stale_reservations.py | 59 ++++++++ 16 files changed, 770 insertions(+), 4 deletions(-) create mode 100644 migrations/versions/a73d19b6c204_reservation_deadlines.py create mode 100644 repro/IMPLEMENTATION.md create mode 100644 repro/dummy_upstream.py create mode 100644 repro/probe.py create mode 100644 repro/results-final.txt create mode 100644 repro/results.txt create mode 100644 repro/router-final.log create mode 100644 repro/router-first.log create mode 100644 routstr/core/lifecycle.py create mode 100644 tests/unit/test_request_lifecycle.py diff --git a/migrations/versions/a73d19b6c204_reservation_deadlines.py b/migrations/versions/a73d19b6c204_reservation_deadlines.py new file mode 100644 index 00000000..74702d61 --- /dev/null +++ b/migrations/versions/a73d19b6c204_reservation_deadlines.py @@ -0,0 +1,42 @@ +"""Immutable reservation start and absolute recovery deadline. + +Revision ID: a73d19b6c204 +Revises: e4c7a1b9d520 +""" + +import time + +import sqlalchemy as sa +from alembic import op + +revision = "a73d19b6c204" +down_revision = "e4c7a1b9d520" +branch_labels = None +depends_on = None + + +def upgrade() -> None: + op.add_column( + "reservation_releases", sa.Column("started_at", sa.Integer(), nullable=True) + ) + op.add_column( + "reservation_releases", sa.Column("expires_at", sa.Integer(), nullable=True) + ) + op.create_index( + "ix_reservation_releases_expires_at", "reservation_releases", ["expires_at"] + ) + # Original ages are unknowable for renewed legacy rows. Give them a finite + # migration grace period; deploy only after draining old workers. + op.execute( + sa.text( + "UPDATE reservation_releases SET expires_at = :expiry WHERE status = 'active'" + ).bindparams(expiry=int(time.time()) + 1830) + ) + + +def downgrade() -> None: + op.drop_index( + "ix_reservation_releases_expires_at", table_name="reservation_releases" + ) + op.drop_column("reservation_releases", "expires_at") + op.drop_column("reservation_releases", "started_at") diff --git a/repro/IMPLEMENTATION.md b/repro/IMPLEMENTATION.md new file mode 100644 index 00000000..1c231f1f --- /dev/null +++ b/repro/IMPLEMENTATION.md @@ -0,0 +1,46 @@ +# Reservation lifecycle implementation and validation + +Branch: fix/reservation-lifecycle. Baseline: 96c8e2f7. + +## Implemented + +- Outermost pure-ASGI lifecycle supervision with one coordinated receive consumer, explicit disconnect monitoring, cancellation, and exact reservation fallback cleanup. +- Finite overall request lifetime (MAX_REQUEST_LIFETIME_SECONDS, default 1800), downstream send timeout (DOWNSTREAM_SEND_TIMEOUT_SECONDS, default 60), and cleanup timeout (REQUEST_CLEANUP_TIMEOUT_SECONDS, default 30). +- Lifecycle identity shared through context across middleware tasks; reservation replacements are registered for exact cleanup. +- Heartbeats stop on lifecycle termination or local maximum age. +- Persistent stream finalization has a finite cleanup budget. +- Durable immutable started_at and expires_at columns; expiry covers remaining request lifetime plus settlement grace, including provider fallback without restarting the original deadline. +- Renewal and charge claims refuse expired reservations. Sweeping can release absolute-expired reservations even when their renewable timestamp is fresh. +- Migration grants legacy active rows 1830 seconds of grace; original ages are not fabricated. Drain old workers before deployment. + +## Verification + +Run from worktree with PYTHONPATH=$PWD because the shared root virtual environment's editable install points at the original checkout: + +PYTHONPATH=$PWD ../../.venv/bin/pytest tests/unit/test_request_lifecycle.py tests/unit/test_stale_reservations.py tests/unit/test_streaming_billing_finalization.py tests/integration/test_negative_available_balance_repro.py -q + +64 tests passed. Ruff checks passed on changed files. Full-project mypy was attempted but did not finish within the tool timeout; no successful typecheck is claimed. + +Final built image: localhost/routstr-reserved-repro:fix, ef81426ad79e3d14ec462a39ab1f7481fd0cb410a9cb93cb42de41e8b3523869. + +Container tests used real TCP, full middleware stack, frozen image dependencies, isolated SQLite and synthetic balances. Read timeout 3s, lifetime 15s, delivery timeout 2s, cleanup timeout 3s, stale timeout 6s. + +Reused the main probe on ports 18100/18101. Results in results-final.txt and router-final.log: + +- Finite and silent streams settled. +- Header wait released its reservation. +- Disconnected endless stream no longer retained its reservation. +- Non-reading flood client hit bounded delivery/cleanup. +- Connected keepalive-only stream terminated at maximum lifetime. +- After the background-sweep interval and all client closures: every key reserved_balance=0, no active durable reservations. Explicit database assertions passed. +- Router shut down within the 10-second grace without SIGKILL. Dummy upstream still required SIGKILL: its fixture deliberately sleeps/open-streams and is not patched router code. + +Actual mint payout was not tested. Protocol errors on already-started streams when deadlines interrupt them are expected; an HTTP status cannot be replaced after headers are sent. + +## Financial policy / limitations + +The lifecycle first lets existing finalization run within a bounded budget. If still active, fallback releases only that reservation; late charge is fenced by terminal state. This can forgo charging observed output on failed settlement. It prioritizes freeing customer funds over leaving them locked; review this policy before deployment. Upstream compute may continue remotely even after local connection closure. + +This implementation does not complete every proposed hardening idea: provider cancellation APIs, full observability, per-record unexpected DB-failure isolation, legacy NULL aggregate background reconciliation, multi-worker/alternate-route network matrix and DB-outage injection remain follow-up work. No dependency upgrade was needed for the tested cases because explicit disconnect supervision avoids relying solely on send errors. + +All reproduction containers are stopped. Original node data/configuration is untouched. Source changes are uncommitted in the worktree for review. diff --git a/repro/dummy_upstream.py b/repro/dummy_upstream.py new file mode 100644 index 00000000..1be75ecc --- /dev/null +++ b/repro/dummy_upstream.py @@ -0,0 +1,45 @@ +"""Loopback-only streaming fixture; no router monkeypatches.""" +import asyncio +import json +import time +from fastapi import FastAPI, Request +from fastapi.responses import StreamingResponse + +app = FastAPI() +events = [] + +@app.get('/events') +async def history(): + return events + +@app.get('/v1/models') +async def models(): + return {'object': 'list', 'data': [{'id': 'gpt-4o-mini', 'object': 'model', 'created': 1, 'owned_by': 'repro'}]} + +@app.post('/v1/chat/completions') +async def completions(request: Request): + body = await request.json() + mode = body.get('messages', [{}])[0].get('content', 'finite') + events.append({'event': 'start', 'mode': mode, 'time': time.time()}) + if mode.startswith('header'): + await asyncio.sleep(3600) + async def stream(): + count = 0 + try: + while True: + if mode.startswith('keepalive'): + yield ': ping\n\n' + else: + chunk = {'id': 'repro', 'object': 'chat.completion.chunk', 'created': int(time.time()), 'model': 'gpt-4o-mini', 'choices': [{'index': 0, 'delta': {'content': 'x' * (65536 if mode.startswith('flood') else 1)}, 'finish_reason': None}]} + yield 'data: ' + json.dumps(chunk) + '\n\n' + count += 1 + if mode == 'finite' and count >= 3: + yield 'data: ' + json.dumps({'id': 'repro', 'object': 'chat.completion.chunk', 'model': 'gpt-4o-mini', 'choices': [], 'usage': {'prompt_tokens': 1, 'completion_tokens': count, 'total_tokens': count + 1}}) + '\n\n' + yield 'data: [DONE]\n\n' + return + await asyncio.sleep(3600 if mode.startswith('silent') else (0.001 if mode.startswith('flood') else 0.5)) + finally: + event = {'event': 'close', 'mode': mode, 'chunks': count, 'time': time.time()} + events.append(event) + print(json.dumps(event), flush=True) + return StreamingResponse(stream(), media_type='text/event-stream') diff --git a/repro/probe.py b/repro/probe.py new file mode 100644 index 00000000..93d71a75 --- /dev/null +++ b/repro/probe.py @@ -0,0 +1,60 @@ +import asyncio +import json +import socket +import subprocess +import time +import httpx + +BASE='http://127.0.0.1:18100' + +def snapshot(): + code="import sqlite3,json,time; c=sqlite3.connect('/tmp/reserved-fix.db'); c.row_factory=sqlite3.Row; print(json.dumps({'time':time.time(),'keys':[dict(r) for r in c.execute(\"select hashed_key,balance,reserved_balance,reserved_at from api_keys where hashed_key like 'main-%'\")],'rows':[dict(r) for r in c.execute(\"select * from reservation_releases where key_hash like 'main-%'\")]}))" + return json.loads(subprocess.check_output(['podman','exec','reserved-router-fix','/.venv/bin/python','-c',code],text=True)) + +async def consume(mode): + try: + async with httpx.AsyncClient(timeout=None) as c: + async with c.stream('POST',BASE+'/v1/chat/completions',headers={'Authorization':'Bearer sk-main-'+mode},json={'model':'gpt-4o-mini','messages':[{'role':'user','content':mode}],'stream':True,'max_tokens':10}) as r: + print('STREAM',mode,r.status_code,flush=True) + async for _ in r.aiter_bytes(): pass + print('ENDED',mode,flush=True) + except asyncio.CancelledError: + print('CLIENT_DISCONNECTED',mode,flush=True) + raise + except Exception as e: + print('CLIENT_ERROR',mode,type(e).__name__,str(e),flush=True) + +async def report(label): + print(label,json.dumps(snapshot()),flush=True) + async with httpx.AsyncClient(timeout=5) as c: + for mode in ['silent-disconnect','endless-disconnect','keepalive','flood','header']: + # Only attempt payout while reserved: avoid requiring a real mint. + if next(k for k in snapshot()['keys'] if k['hashed_key']=='main-'+mode)['reserved_balance']: + r=await c.post(BASE+'/v1/wallet/refund',headers={'Authorization':'Bearer sk-main-'+mode}) + print('REFUND',mode,r.status_code,r.text,flush=True) + print('UPSTREAM_EVENTS',json.dumps((await c.get('http://127.0.0.1:18101/events')).json()),flush=True) + +async def main(): + modes=['finite','silent','silent-disconnect','endless-disconnect','keepalive','header'] + tasks={m:asyncio.create_task(consume(m)) for m in modes} + # Real client with a small receive buffer, never draining the HTTP response. + sock=socket.socket(); sock.setsockopt(socket.SOL_SOCKET,socket.SO_RCVBUF,1024); sock.connect(('127.0.0.1',18100)) + body=json.dumps({'model':'gpt-4o-mini','messages':[{'role':'user','content':'flood'}],'stream':True,'max_tokens':10}).encode() + sock.sendall(b'POST /v1/chat/completions HTTP/1.1\r\nHost: localhost\r\nAuthorization: Bearer sk-main-flood\r\nContent-Type: application/json\r\nContent-Length: '+str(len(body)).encode()+b'\r\n\r\n'+body) + await asyncio.sleep(1) + for m in ['silent-disconnect','endless-disconnect']: + tasks[m].cancel() + await asyncio.gather(tasks['silent-disconnect'],tasks['endless-disconnect'],return_exceptions=True) + await asyncio.sleep(9) + await report('AT_10_SECONDS') + await asyncio.sleep(60) + await report('AFTER_SWEEP') + sock.close() + tasks['keepalive'].cancel() + await asyncio.gather(tasks['keepalive'],return_exceptions=True) + await asyncio.sleep(8) + await report('AFTER_ALL_CLIENTS_CLOSED') + for task in tasks.values(): task.cancel() + await asyncio.gather(*tasks.values(),return_exceptions=True) + +asyncio.run(main()) diff --git a/repro/results-final.txt b/repro/results-final.txt new file mode 100644 index 00000000..6545bf6d --- /dev/null +++ b/repro/results-final.txt @@ -0,0 +1,19 @@ +STREAM endless-disconnect 200 +STREAM keepalive 200 +STREAM finite 200 +STREAM silent 200 +STREAM silent-disconnect 200 +CLIENT_DISCONNECTED silent-disconnect +CLIENT_DISCONNECTED endless-disconnect +ENDED finite +ENDED silent +STREAM header 424 +ENDED header +AT_10_SECONDS {"time": 1790767971.1792026, "keys": [{"hashed_key": "main-finite", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent-disconnect", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-endless-disconnect", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-keepalive", "balance": 1000000000, "reserved_balance": 12, "reserved_at": 1790767960}, {"hashed_key": "main-flood", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-header", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}], "rows": [{"id": "9b5b9063f6f045a290611e4144c897de", "key_hash": "main-flood", "billing_key_hash": "main-flood", "reserved_msats": 12, "status": "released", "created_at": 1790767962, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "efc8563301ba458890ee3ab2335e4e49", "key_hash": "main-endless-disconnect", "billing_key_hash": "main-endless-disconnect", "reserved_msats": 13, "status": "released", "created_at": 1790767960, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "cbed89b7ec444fea9789cf53b3e0f476", "key_hash": "main-keepalive", "billing_key_hash": "main-keepalive", "reserved_msats": 12, "status": "active", "created_at": 1790767971, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "1c56b25265df4743b4cff70dc57544c6", "key_hash": "main-finite", "billing_key_hash": "main-finite", "reserved_msats": 12, "status": "charged", "created_at": 1790767960, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "cc7f113eef004b7ba27bc761c5d9b9a1", "key_hash": "main-silent", "billing_key_hash": "main-silent", "reserved_msats": 12, "status": "charged", "created_at": 1790767963, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "6a1b5506b8ab4747884475075ebc38da", "key_hash": "main-silent-disconnect", "billing_key_hash": "main-silent-disconnect", "reserved_msats": 13, "status": "released", "created_at": 1790767961, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "1dfedc1c2cee407fb2cd1a28b1253c6d", "key_hash": "main-header", "billing_key_hash": "main-header", "reserved_msats": 12, "status": "released", "created_at": 1790767963, "started_at": 1790767960, "expires_at": 1790767978}]} +REFUND keepalive 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"45f783cc-4c0b-4222-be13-8e726fc7cebc"} +UPSTREAM_EVENTS [{"event": "start", "mode": "flood", "time": 1790767717.2871263}, {"event": "start", "mode": "silent-disconnect", "time": 1790767717.2960703}, {"event": "start", "mode": "keepalive", "time": 1790767717.3026786}, {"event": "start", "mode": "header", "time": 1790767717.3104746}, {"event": "start", "mode": "endless-disconnect", "time": 1790767717.318341}, {"event": "start", "mode": "silent", "time": 1790767717.3653235}, {"event": "start", "mode": "finite", "time": 1790767717.3924189}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790767718.397855}, {"event": "start", "mode": "flood", "time": 1790767960.9594278}, {"event": "start", "mode": "endless-disconnect", "time": 1790767961.008998}, {"event": "start", "mode": "keepalive", "time": 1790767961.036595}, {"event": "start", "mode": "finite", "time": 1790767961.060875}, {"event": "start", "mode": "silent", "time": 1790767961.0869172}, {"event": "start", "mode": "silent-disconnect", "time": 1790767961.1580715}, {"event": "start", "mode": "header", "time": 1790767961.1944675}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790767962.064207}] +CLIENT_ERROR keepalive RemoteProtocolError peer closed connection without sending complete message body (incomplete chunked read) +AFTER_SWEEP {"time": 1790768033.9280283, "keys": [{"hashed_key": "main-finite", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent-disconnect", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-endless-disconnect", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-keepalive", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-flood", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-header", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}], "rows": [{"id": "9b5b9063f6f045a290611e4144c897de", "key_hash": "main-flood", "billing_key_hash": "main-flood", "reserved_msats": 12, "status": "released", "created_at": 1790767962, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "efc8563301ba458890ee3ab2335e4e49", "key_hash": "main-endless-disconnect", "billing_key_hash": "main-endless-disconnect", "reserved_msats": 13, "status": "released", "created_at": 1790767960, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "cbed89b7ec444fea9789cf53b3e0f476", "key_hash": "main-keepalive", "billing_key_hash": "main-keepalive", "reserved_msats": 12, "status": "released", "created_at": 1790767975, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "1c56b25265df4743b4cff70dc57544c6", "key_hash": "main-finite", "billing_key_hash": "main-finite", "reserved_msats": 12, "status": "charged", "created_at": 1790767960, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "cc7f113eef004b7ba27bc761c5d9b9a1", "key_hash": "main-silent", "billing_key_hash": "main-silent", "reserved_msats": 12, "status": "charged", "created_at": 1790767963, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "6a1b5506b8ab4747884475075ebc38da", "key_hash": "main-silent-disconnect", "billing_key_hash": "main-silent-disconnect", "reserved_msats": 13, "status": "released", "created_at": 1790767961, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "1dfedc1c2cee407fb2cd1a28b1253c6d", "key_hash": "main-header", "billing_key_hash": "main-header", "reserved_msats": 12, "status": "released", "created_at": 1790767963, "started_at": 1790767960, "expires_at": 1790767978}]} +UPSTREAM_EVENTS [{"event": "start", "mode": "flood", "time": 1790767717.2871263}, {"event": "start", "mode": "silent-disconnect", "time": 1790767717.2960703}, {"event": "start", "mode": "keepalive", "time": 1790767717.3026786}, {"event": "start", "mode": "header", "time": 1790767717.3104746}, {"event": "start", "mode": "endless-disconnect", "time": 1790767717.318341}, {"event": "start", "mode": "silent", "time": 1790767717.3653235}, {"event": "start", "mode": "finite", "time": 1790767717.3924189}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790767718.397855}, {"event": "start", "mode": "flood", "time": 1790767960.9594278}, {"event": "start", "mode": "endless-disconnect", "time": 1790767961.008998}, {"event": "start", "mode": "keepalive", "time": 1790767961.036595}, {"event": "start", "mode": "finite", "time": 1790767961.060875}, {"event": "start", "mode": "silent", "time": 1790767961.0869172}, {"event": "start", "mode": "silent-disconnect", "time": 1790767961.1580715}, {"event": "start", "mode": "header", "time": 1790767961.1944675}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790767962.064207}] +AFTER_ALL_CLIENTS_CLOSED {"time": 1790768044.521246, "keys": [{"hashed_key": "main-finite", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent-disconnect", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-endless-disconnect", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-keepalive", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-flood", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-header", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}], "rows": [{"id": "9b5b9063f6f045a290611e4144c897de", "key_hash": "main-flood", "billing_key_hash": "main-flood", "reserved_msats": 12, "status": "released", "created_at": 1790767962, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "efc8563301ba458890ee3ab2335e4e49", "key_hash": "main-endless-disconnect", "billing_key_hash": "main-endless-disconnect", "reserved_msats": 13, "status": "released", "created_at": 1790767960, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "cbed89b7ec444fea9789cf53b3e0f476", "key_hash": "main-keepalive", "billing_key_hash": "main-keepalive", "reserved_msats": 12, "status": "released", "created_at": 1790767975, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "1c56b25265df4743b4cff70dc57544c6", "key_hash": "main-finite", "billing_key_hash": "main-finite", "reserved_msats": 12, "status": "charged", "created_at": 1790767960, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "cc7f113eef004b7ba27bc761c5d9b9a1", "key_hash": "main-silent", "billing_key_hash": "main-silent", "reserved_msats": 12, "status": "charged", "created_at": 1790767963, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "6a1b5506b8ab4747884475075ebc38da", "key_hash": "main-silent-disconnect", "billing_key_hash": "main-silent-disconnect", "reserved_msats": 13, "status": "released", "created_at": 1790767961, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "1dfedc1c2cee407fb2cd1a28b1253c6d", "key_hash": "main-header", "billing_key_hash": "main-header", "reserved_msats": 12, "status": "released", "created_at": 1790767963, "started_at": 1790767960, "expires_at": 1790767978}]} +UPSTREAM_EVENTS [{"event": "start", "mode": "flood", "time": 1790767717.2871263}, {"event": "start", "mode": "silent-disconnect", "time": 1790767717.2960703}, {"event": "start", "mode": "keepalive", "time": 1790767717.3026786}, {"event": "start", "mode": "header", "time": 1790767717.3104746}, {"event": "start", "mode": "endless-disconnect", "time": 1790767717.318341}, {"event": "start", "mode": "silent", "time": 1790767717.3653235}, {"event": "start", "mode": "finite", "time": 1790767717.3924189}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790767718.397855}, {"event": "start", "mode": "flood", "time": 1790767960.9594278}, {"event": "start", "mode": "endless-disconnect", "time": 1790767961.008998}, {"event": "start", "mode": "keepalive", "time": 1790767961.036595}, {"event": "start", "mode": "finite", "time": 1790767961.060875}, {"event": "start", "mode": "silent", "time": 1790767961.0869172}, {"event": "start", "mode": "silent-disconnect", "time": 1790767961.1580715}, {"event": "start", "mode": "header", "time": 1790767961.1944675}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790767962.064207}] diff --git a/repro/results.txt b/repro/results.txt new file mode 100644 index 00000000..01417f00 --- /dev/null +++ b/repro/results.txt @@ -0,0 +1,19 @@ +STREAM silent-disconnect 200 +STREAM keepalive 200 +STREAM endless-disconnect 200 +STREAM silent 200 +STREAM finite 200 +CLIENT_DISCONNECTED silent-disconnect +CLIENT_DISCONNECTED endless-disconnect +ENDED finite +STREAM header 424 +ENDED header +ENDED silent +AT_10_SECONDS {"time": 1790767727.5333533, "keys": [{"hashed_key": "main-finite", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent-disconnect", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-endless-disconnect", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-keepalive", "balance": 1000000000, "reserved_balance": 12, "reserved_at": 1790767717}, {"hashed_key": "main-flood", "balance": 999893370, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-header", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}], "rows": [{"id": "79c7feb2274140748da2a97180f56d2c", "key_hash": "main-flood", "billing_key_hash": "main-flood", "reserved_msats": 12, "status": "charged", "created_at": 1790767719, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "ecf20c01870b4ce49fc81bd300ee35df", "key_hash": "main-silent-disconnect", "billing_key_hash": "main-silent-disconnect", "reserved_msats": 13, "status": "charged", "created_at": 1790767717, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "ec6f854d6a8647ac8b3bba50752bc647", "key_hash": "main-keepalive", "billing_key_hash": "main-keepalive", "reserved_msats": 12, "status": "active", "created_at": 1790767725, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "6da67d4c5cbd4ab19cc30f2f0fac6aaa", "key_hash": "main-header", "billing_key_hash": "main-header", "reserved_msats": 12, "status": "released", "created_at": 1790767719, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "f4a35c5e89c343bfbe21415dce28a4d5", "key_hash": "main-endless-disconnect", "billing_key_hash": "main-endless-disconnect", "reserved_msats": 13, "status": "released", "created_at": 1790767717, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "50a37cffba7745fa84d03b4070c86066", "key_hash": "main-silent", "billing_key_hash": "main-silent", "reserved_msats": 12, "status": "charged", "created_at": 1790767719, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "63ca23fa71024428baaf8baeb7ee3ede", "key_hash": "main-finite", "billing_key_hash": "main-finite", "reserved_msats": 12, "status": "charged", "created_at": 1790767717, "started_at": 1790767717, "expires_at": 1790767735}]} +REFUND keepalive 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"f0bcc404-dffe-4860-8091-308f721ba053"} +UPSTREAM_EVENTS [{"event": "start", "mode": "flood", "time": 1790767717.2871263}, {"event": "start", "mode": "silent-disconnect", "time": 1790767717.2960703}, {"event": "start", "mode": "keepalive", "time": 1790767717.3026786}, {"event": "start", "mode": "header", "time": 1790767717.3104746}, {"event": "start", "mode": "endless-disconnect", "time": 1790767717.318341}, {"event": "start", "mode": "silent", "time": 1790767717.3653235}, {"event": "start", "mode": "finite", "time": 1790767717.3924189}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790767718.397855}] +CLIENT_ERROR keepalive RemoteProtocolError peer closed connection without sending complete message body (incomplete chunked read) +AFTER_SWEEP {"time": 1790767790.5300848, "keys": [{"hashed_key": "main-finite", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent-disconnect", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-endless-disconnect", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-keepalive", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-flood", "balance": 999893370, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-header", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}], "rows": [{"id": "79c7feb2274140748da2a97180f56d2c", "key_hash": "main-flood", "billing_key_hash": "main-flood", "reserved_msats": 12, "status": "charged", "created_at": 1790767719, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "ecf20c01870b4ce49fc81bd300ee35df", "key_hash": "main-silent-disconnect", "billing_key_hash": "main-silent-disconnect", "reserved_msats": 13, "status": "charged", "created_at": 1790767717, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "ec6f854d6a8647ac8b3bba50752bc647", "key_hash": "main-keepalive", "billing_key_hash": "main-keepalive", "reserved_msats": 12, "status": "released", "created_at": 1790767731, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "6da67d4c5cbd4ab19cc30f2f0fac6aaa", "key_hash": "main-header", "billing_key_hash": "main-header", "reserved_msats": 12, "status": "released", "created_at": 1790767719, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "f4a35c5e89c343bfbe21415dce28a4d5", "key_hash": "main-endless-disconnect", "billing_key_hash": "main-endless-disconnect", "reserved_msats": 13, "status": "released", "created_at": 1790767717, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "50a37cffba7745fa84d03b4070c86066", "key_hash": "main-silent", "billing_key_hash": "main-silent", "reserved_msats": 12, "status": "charged", "created_at": 1790767719, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "63ca23fa71024428baaf8baeb7ee3ede", "key_hash": "main-finite", "billing_key_hash": "main-finite", "reserved_msats": 12, "status": "charged", "created_at": 1790767717, "started_at": 1790767717, "expires_at": 1790767735}]} +UPSTREAM_EVENTS [{"event": "start", "mode": "flood", "time": 1790767717.2871263}, {"event": "start", "mode": "silent-disconnect", "time": 1790767717.2960703}, {"event": "start", "mode": "keepalive", "time": 1790767717.3026786}, {"event": "start", "mode": "header", "time": 1790767717.3104746}, {"event": "start", "mode": "endless-disconnect", "time": 1790767717.318341}, {"event": "start", "mode": "silent", "time": 1790767717.3653235}, {"event": "start", "mode": "finite", "time": 1790767717.3924189}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790767718.397855}] +AFTER_ALL_CLIENTS_CLOSED {"time": 1790767800.920076, "keys": [{"hashed_key": "main-finite", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent-disconnect", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-endless-disconnect", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-keepalive", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-flood", "balance": 999893370, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-header", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}], "rows": [{"id": "79c7feb2274140748da2a97180f56d2c", "key_hash": "main-flood", "billing_key_hash": "main-flood", "reserved_msats": 12, "status": "charged", "created_at": 1790767719, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "ecf20c01870b4ce49fc81bd300ee35df", "key_hash": "main-silent-disconnect", "billing_key_hash": "main-silent-disconnect", "reserved_msats": 13, "status": "charged", "created_at": 1790767717, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "ec6f854d6a8647ac8b3bba50752bc647", "key_hash": "main-keepalive", "billing_key_hash": "main-keepalive", "reserved_msats": 12, "status": "released", "created_at": 1790767731, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "6da67d4c5cbd4ab19cc30f2f0fac6aaa", "key_hash": "main-header", "billing_key_hash": "main-header", "reserved_msats": 12, "status": "released", "created_at": 1790767719, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "f4a35c5e89c343bfbe21415dce28a4d5", "key_hash": "main-endless-disconnect", "billing_key_hash": "main-endless-disconnect", "reserved_msats": 13, "status": "released", "created_at": 1790767717, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "50a37cffba7745fa84d03b4070c86066", "key_hash": "main-silent", "billing_key_hash": "main-silent", "reserved_msats": 12, "status": "charged", "created_at": 1790767719, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "63ca23fa71024428baaf8baeb7ee3ede", "key_hash": "main-finite", "billing_key_hash": "main-finite", "reserved_msats": 12, "status": "charged", "created_at": 1790767717, "started_at": 1790767717, "expires_at": 1790767735}]} +UPSTREAM_EVENTS [{"event": "start", "mode": "flood", "time": 1790767717.2871263}, {"event": "start", "mode": "silent-disconnect", "time": 1790767717.2960703}, {"event": "start", "mode": "keepalive", "time": 1790767717.3026786}, {"event": "start", "mode": "header", "time": 1790767717.3104746}, {"event": "start", "mode": "endless-disconnect", "time": 1790767717.318341}, {"event": "start", "mode": "silent", "time": 1790767717.3653235}, {"event": "start", "mode": "finite", "time": 1790767717.3924189}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790767718.397855}] diff --git a/repro/router-final.log b/repro/router-final.log new file mode 100644 index 00000000..dee5fe67 --- /dev/null +++ b/repro/router-final.log @@ -0,0 +1,108 @@ +/.venv/lib/python3.14/site-packages/anyio/from_thread.py:119: SyntaxWarning: 'return' in a 'finally' block + return result +2026-09-30 11:32:06 WARNING routstr.core.main UI dist directory not found at /app/ui_out; serving API only. Run `make ui-build` to build the static UI served from here, or `make ui-dev` for the Next.js dev server with hot reload on :3000 (it targets this backend on :8000). +2026-09-30 11:32:06 INFO uvicorn.error Started server process [1] +2026-09-30 11:32:06 INFO uvicorn.error Waiting for application startup. +2026-09-30 11:32:06 INFO routstr.core.main Application startup initiated +2026-09-30 11:32:10 INFO routstr.core.db Database migrations completed successfully +2026-09-30 11:32:10 INFO routstr.core.db Reset reserved balances on startup +2026-09-30 11:32:11 INFO routstr.upstream.helpers Seeding custom provider +2026-09-30 11:32:11 INFO routstr.upstream.helpers Seeded 1 upstream providers from settings +2026-09-30 11:32:12 INFO routstr.proxy Initialized 1 upstream providers +2026-09-30 11:32:12 INFO routstr.nostr.listing Nostr private key not configured (NSEC); waiting for one to be set before announcing this provider +2026-09-30 11:32:12 INFO routstr.nostr.analytics Usage analytics sharing task started +2026-09-30 11:32:12 INFO routstr.nostr.analytics NSEC is not configured; skipping analytics sharing to Nostr +2026-09-30 11:32:12 INFO routstr.auth Dead-key pruning disabled (interval <= 0) +2026-09-30 11:32:12 INFO uvicorn.error Application startup complete. +2026-09-30 11:32:12 INFO uvicorn.error Uvicorn running on http://127.0.0.1:18100 (Press CTRL+C to quit) +2026-09-30 11:32:40 INFO routstr.auth Existing sk- API key found +2026-09-30 11:32:40 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:32:40 INFO routstr.auth Processing payment for request +2026-09-30 11:32:40 INFO routstr.auth Existing sk- API key found +2026-09-30 11:32:40 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:32:40 INFO routstr.auth Processing payment for request +2026-09-30 11:32:40 INFO routstr.auth Existing sk- API key found +2026-09-30 11:32:40 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:32:40 INFO routstr.auth Processing payment for request +2026-09-30 11:32:40 INFO routstr.auth Existing sk- API key found +2026-09-30 11:32:40 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:32:40 INFO routstr.auth Processing payment for request +2026-09-30 11:32:40 INFO routstr.auth Existing sk- API key found +2026-09-30 11:32:40 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:32:40 INFO routstr.auth Processing payment for request +2026-09-30 11:32:40 INFO routstr.auth Existing sk- API key found +2026-09-30 11:32:40 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:32:40 INFO routstr.auth Processing payment for request +2026-09-30 11:32:40 INFO routstr.auth Existing sk- API key found +2026-09-30 11:32:40 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:32:40 INFO routstr.auth Processing payment for request +2026-09-30 11:32:40 INFO routstr.auth Payment processed successfully +2026-09-30 11:32:40 INFO routstr.payments RESERVE +2026-09-30 11:32:40 INFO routstr.auth Payment processed successfully +2026-09-30 11:32:40 INFO routstr.payments RESERVE +2026-09-30 11:32:41 INFO routstr.auth Payment processed successfully +2026-09-30 11:32:41 INFO routstr.payments RESERVE +2026-09-30 11:32:41 INFO routstr.auth Payment processed successfully +2026-09-30 11:32:41 INFO routstr.payments RESERVE +2026-09-30 11:32:41 INFO routstr.auth Payment processed successfully +2026-09-30 11:32:41 INFO routstr.payments RESERVE +2026-09-30 11:32:41 INFO routstr.auth Payment processed successfully +2026-09-30 11:32:41 INFO routstr.payments RESERVE +2026-09-30 11:32:41 INFO routstr.auth Payment processed successfully +2026-09-30 11:32:41 INFO routstr.payments RESERVE +2026-09-30 11:32:41 INFO routstr.payment.cost_calculation Applied model-specific pricing +2026-09-30 11:32:41 INFO routstr.payment.cost_calculation Calculated token-based cost +2026-09-30 11:32:41 INFO routstr.payment.cost_calculation Applied model-specific pricing +2026-09-30 11:32:41 INFO routstr.payment.cost_calculation Calculated token-based cost +2026-09-30 11:32:41 INFO routstr.auth Payment settlement finished +2026-09-30 11:32:41 INFO routstr.auth Payment settlement finished +2026-09-30 11:32:42 INFO routstr.payment.cost_calculation Applied model-specific pricing +2026-09-30 11:32:42 INFO routstr.payment.cost_calculation Calculated token-based cost +2026-09-30 11:32:42 INFO routstr.auth Calculated token-based cost +2026-09-30 11:32:42 INFO routstr.auth Refunding excess payment +2026-09-30 11:32:42 INFO routstr.auth Refund processed successfully +2026-09-30 11:32:42 INFO routstr.payments FINALIZE +2026-09-30 11:32:42 INFO routstr.auth Payment settlement finished +2026-09-30 11:32:42 INFO routstr.upstream.auto_topup Auto top-up worker started +2026-09-30 11:32:43 INFO routstr.payment.cost_calculation Applied model-specific pricing +2026-09-30 11:32:43 INFO routstr.payment.cost_calculation Calculated token-based cost +2026-09-30 11:32:43 ERROR routstr.core.exceptions Unhandled exception +asyncio.exceptions.CancelledError + +The above exception was the direct cause of the following exception: + +TimeoutError +2026-09-30 11:32:43 ERROR uvicorn.error Exception in ASGI application +asyncio.exceptions.CancelledError + +The above exception was the direct cause of the following exception: + +TimeoutError +2026-09-30 11:32:43 INFO routstr.auth Payment settlement finished +2026-09-30 11:32:44 WARNING routstr.upstream.base Streaming interrupted; finalizing before closing upstream +2026-09-30 11:32:44 INFO routstr.payment.cost_calculation Applied model-specific pricing +2026-09-30 11:32:44 INFO routstr.payment.cost_calculation Calculated token-based cost +2026-09-30 11:32:44 INFO routstr.auth Calculated token-based cost +2026-09-30 11:32:44 INFO routstr.auth Refunding excess payment +2026-09-30 11:32:44 INFO routstr.auth Refund processed successfully +2026-09-30 11:32:44 INFO routstr.payments FINALIZE +2026-09-30 11:32:44 INFO routstr.auth Payment settlement finished +2026-09-30 11:32:44 ERROR routstr.core.exceptions Unhandled exception +httpcore.ReadTimeout + +The above exception was the direct cause of the following exception: + +httpx.ReadTimeout +2026-09-30 11:32:44 ERROR uvicorn.error Exception in ASGI application +httpcore.ReadTimeout + +The above exception was the direct cause of the following exception: + +httpx.ReadTimeout +2026-09-30 11:32:44 ERROR routstr.upstream.base HTTP request error to upstream +2026-09-30 11:32:44 WARNING routstr.proxy Upstream base failed for model=gpt-4o-mini: Upstream service request timed out +2026-09-30 11:32:52 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. +2026-09-30 11:32:55 INFO routstr.payment.cost_calculation Applied model-specific pricing +2026-09-30 11:32:55 INFO routstr.payment.cost_calculation Calculated token-based cost +2026-09-30 11:32:55 ERROR uvicorn.error ASGI callable returned without completing response. +2026-09-30 11:32:55 INFO routstr.auth Payment settlement finished diff --git a/repro/router-first.log b/repro/router-first.log new file mode 100644 index 00000000..b8979fc0 --- /dev/null +++ b/repro/router-first.log @@ -0,0 +1,115 @@ +/.venv/lib/python3.14/site-packages/anyio/from_thread.py:119: SyntaxWarning: 'return' in a 'finally' block + return result +2026-09-30 11:28:16 WARNING routstr.core.main UI dist directory not found at /app/ui_out; serving API only. Run `make ui-build` to build the static UI served from here, or `make ui-dev` for the Next.js dev server with hot reload on :3000 (it targets this backend on :8000). +2026-09-30 11:28:16 INFO uvicorn.error Started server process [1] +2026-09-30 11:28:16 INFO uvicorn.error Waiting for application startup. +2026-09-30 11:28:16 INFO routstr.core.main Application startup initiated +2026-09-30 11:28:20 INFO routstr.core.db Database migrations completed successfully +2026-09-30 11:28:21 INFO routstr.core.db Reset reserved balances on startup +2026-09-30 11:28:21 INFO routstr.upstream.helpers Seeding custom provider +2026-09-30 11:28:21 INFO routstr.upstream.helpers Seeded 1 upstream providers from settings +2026-09-30 11:28:22 INFO routstr.proxy Initialized 1 upstream providers +2026-09-30 11:28:22 INFO routstr.nostr.listing Nostr private key not configured (NSEC); waiting for one to be set before announcing this provider +2026-09-30 11:28:22 INFO routstr.nostr.analytics Usage analytics sharing task started +2026-09-30 11:28:22 INFO routstr.nostr.analytics NSEC is not configured; skipping analytics sharing to Nostr +2026-09-30 11:28:22 INFO routstr.auth Dead-key pruning disabled (interval <= 0) +2026-09-30 11:28:22 INFO uvicorn.error Application startup complete. +2026-09-30 11:28:22 INFO uvicorn.error Uvicorn running on http://127.0.0.1:18100 (Press CTRL+C to quit) +2026-09-30 11:28:37 INFO routstr.auth Existing sk- API key found +2026-09-30 11:28:37 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:28:37 INFO routstr.auth Processing payment for request +2026-09-30 11:28:37 INFO routstr.auth Existing sk- API key found +2026-09-30 11:28:37 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:28:37 INFO routstr.auth Processing payment for request +2026-09-30 11:28:37 INFO routstr.auth Existing sk- API key found +2026-09-30 11:28:37 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:28:37 INFO routstr.auth Processing payment for request +2026-09-30 11:28:37 INFO routstr.auth Existing sk- API key found +2026-09-30 11:28:37 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:28:37 INFO routstr.auth Processing payment for request +2026-09-30 11:28:37 INFO routstr.auth Payment processed successfully +2026-09-30 11:28:37 INFO routstr.payments RESERVE +2026-09-30 11:28:37 INFO routstr.auth Existing sk- API key found +2026-09-30 11:28:37 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:28:37 INFO routstr.auth Processing payment for request +2026-09-30 11:28:37 INFO routstr.auth Existing sk- API key found +2026-09-30 11:28:37 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:28:37 INFO routstr.auth Processing payment for request +2026-09-30 11:28:37 INFO routstr.auth Existing sk- API key found +2026-09-30 11:28:37 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:28:37 INFO routstr.auth Processing payment for request +2026-09-30 11:28:37 INFO routstr.auth Payment processed successfully +2026-09-30 11:28:37 INFO routstr.payments RESERVE +2026-09-30 11:28:37 INFO routstr.auth Payment processed successfully +2026-09-30 11:28:37 INFO routstr.payments RESERVE +2026-09-30 11:28:37 INFO routstr.auth Payment processed successfully +2026-09-30 11:28:37 INFO routstr.payments RESERVE +2026-09-30 11:28:37 INFO routstr.auth Payment processed successfully +2026-09-30 11:28:37 INFO routstr.payments RESERVE +2026-09-30 11:28:37 INFO routstr.auth Payment processed successfully +2026-09-30 11:28:37 INFO routstr.payments RESERVE +2026-09-30 11:28:37 INFO routstr.auth Payment processed successfully +2026-09-30 11:28:37 INFO routstr.payments RESERVE +2026-09-30 11:28:38 INFO routstr.payment.cost_calculation Applied model-specific pricing +2026-09-30 11:28:38 INFO routstr.payment.cost_calculation Calculated token-based cost +2026-09-30 11:28:38 INFO routstr.payment.cost_calculation Applied model-specific pricing +2026-09-30 11:28:38 INFO routstr.payment.cost_calculation Calculated token-based cost +2026-09-30 11:28:38 INFO routstr.auth Payment settlement finished +2026-09-30 11:28:38 INFO routstr.auth Calculated token-based cost +2026-09-30 11:28:38 INFO routstr.auth Refunding excess payment +2026-09-30 11:28:38 INFO routstr.auth Refund processed successfully +2026-09-30 11:28:38 INFO routstr.payments FINALIZE +2026-09-30 11:28:38 INFO routstr.auth Payment settlement finished +2026-09-30 11:28:38 INFO routstr.payment.cost_calculation Applied model-specific pricing +2026-09-30 11:28:38 INFO routstr.payment.cost_calculation Calculated token-based cost +2026-09-30 11:28:38 INFO routstr.auth Calculated token-based cost +2026-09-30 11:28:38 INFO routstr.auth Refunding excess payment +2026-09-30 11:28:38 INFO routstr.auth Refund processed successfully +2026-09-30 11:28:38 INFO routstr.payments FINALIZE +2026-09-30 11:28:38 INFO routstr.auth Payment settlement finished +2026-09-30 11:28:39 INFO routstr.payment.cost_calculation Applied model-specific pricing +2026-09-30 11:28:39 INFO routstr.payment.cost_calculation Calculated token-based cost +2026-09-30 11:28:39 INFO routstr.auth Calculated token-based cost +2026-09-30 11:28:39 INFO routstr.auth Finalized payment with additional charge +2026-09-30 11:28:39 INFO routstr.payments FINALIZE +2026-09-30 11:28:39 INFO routstr.auth Payment settlement finished +2026-09-30 11:28:39 ERROR routstr.core.exceptions Unhandled exception +asyncio.exceptions.CancelledError + +The above exception was the direct cause of the following exception: + +TimeoutError +2026-09-30 11:28:39 ERROR uvicorn.error Exception in ASGI application +asyncio.exceptions.CancelledError + +The above exception was the direct cause of the following exception: + +TimeoutError +2026-09-30 11:28:40 ERROR routstr.upstream.base HTTP request error to upstream +2026-09-30 11:28:40 WARNING routstr.proxy Upstream base failed for model=gpt-4o-mini: Upstream service request timed out +2026-09-30 11:28:40 WARNING routstr.upstream.base Streaming interrupted; finalizing before closing upstream +2026-09-30 11:28:40 INFO routstr.payment.cost_calculation Applied model-specific pricing +2026-09-30 11:28:40 INFO routstr.payment.cost_calculation Calculated token-based cost +2026-09-30 11:28:40 INFO routstr.auth Calculated token-based cost +2026-09-30 11:28:40 INFO routstr.auth Refunding excess payment +2026-09-30 11:28:40 INFO routstr.auth Refund processed successfully +2026-09-30 11:28:40 INFO routstr.payments FINALIZE +2026-09-30 11:28:40 INFO routstr.auth Payment settlement finished +2026-09-30 11:28:40 ERROR routstr.core.exceptions Unhandled exception +httpcore.ReadTimeout + +The above exception was the direct cause of the following exception: + +httpx.ReadTimeout +2026-09-30 11:28:40 ERROR uvicorn.error Exception in ASGI application +httpcore.ReadTimeout + +The above exception was the direct cause of the following exception: + +httpx.ReadTimeout +2026-09-30 11:28:49 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. +2026-09-30 11:28:52 INFO routstr.payment.cost_calculation Applied model-specific pricing +2026-09-30 11:28:52 INFO routstr.payment.cost_calculation Calculated token-based cost +2026-09-30 11:28:52 ERROR uvicorn.error ASGI callable returned without completing response. +2026-09-30 11:28:52 INFO routstr.auth Payment settlement finished +2026-09-30 11:28:52 INFO routstr.upstream.auto_topup Auto top-up worker started diff --git a/routstr/auth.py b/routstr/auth.py index 9bfc7b3d..b7c8e16a 100644 --- a/routstr/auth.py +++ b/routstr/auth.py @@ -637,6 +637,14 @@ async def pay_for_request( ) # Charge the base cost for the request atomically to avoid race conditions + from .core.lifecycle import request_lifetime + + lifetime = request_lifetime.get() + remaining_lifetime = ( + max(0, lifetime.deadline - asyncio.get_running_loop().time()) + if lifetime is not None + else settings.max_request_lifetime_seconds + ) reserved_at_now = int(time.time()) stmt = ( update(ApiKey) @@ -686,6 +694,9 @@ async def pay_for_request( billing_key_hash=reservation.billing_key_hash, reserved_msats=reservation.reserved_msats, status="active", + started_at=reserved_at_now, + expires_at=reserved_at_now + + math.ceil(remaining_lifetime + settings.request_cleanup_timeout_seconds), ) ) # Publish the identity before commit. If the commit succeeds but its @@ -726,6 +737,11 @@ async def pay_for_request( # The reservation is durable; keep its lease fresh for the whole request # lifetime (upstream header waits, non-streaming and streaming alike). + from .core.lifecycle import request_lifetime + + lifetime = request_lifetime.get() + if lifetime is not None: + lifetime.reservations.append(reservation) _start_reservation_heartbeat(reservation) try: @@ -875,6 +891,10 @@ async def renew_reservation( update(ReservationRelease) .where(col(ReservationRelease.id) == snapshot.release_id) .where(col(ReservationRelease.status) == "active") + .where( + (col(ReservationRelease.expires_at).is_(None)) + | (col(ReservationRelease.expires_at) > int(time.time())) + ) .values(created_at=int(time.time())) ) await session.commit() @@ -902,12 +922,21 @@ def _start_reservation_heartbeat(snapshot: ReservationSnapshot) -> None: """ interval = max(1, settings.stale_reservation_timeout_seconds // 3) owner = asyncio.current_task() + from .core.lifecycle import request_lifetime + + lifetime = request_lifetime.get() + deadline = asyncio.get_running_loop().time() + settings.max_request_lifetime_seconds async def beat() -> None: try: while True: await asyncio.sleep(interval) - if owner is None or owner.done(): + if ( + owner is None + or owner.done() + or (lifetime is not None and lifetime.stopped) + or asyncio.get_running_loop().time() >= deadline + ): # Request control is gone; let the lease expire so the # sweeper can release the reservation if no terminal # transition ever ran. @@ -1091,6 +1120,10 @@ async def _claim_reservation_for_charge( update(ReservationRelease) .where(col(ReservationRelease.id) == snapshot.release_id) .where(col(ReservationRelease.status) == "active") + .where( + col(ReservationRelease.expires_at).is_(None) + | (col(ReservationRelease.expires_at) > int(time.time())) + ) .where(col(ReservationRelease.key_hash) == snapshot.key_hash) .where(col(ReservationRelease.billing_key_hash) == snapshot.billing_key_hash) .where(col(ReservationRelease.reserved_msats) == snapshot.reserved_msats) diff --git a/routstr/core/db.py b/routstr/core/db.py index 500420d5..84307a7e 100644 --- a/routstr/core/db.py +++ b/routstr/core/db.py @@ -174,7 +174,10 @@ async def _transition_stale_reservation( update(ReservationRelease) .where(col(ReservationRelease.id) == reservation_id) .where(col(ReservationRelease.status) == "active") - .where(col(ReservationRelease.created_at) < cutoff) + .where( + (col(ReservationRelease.created_at) < cutoff) + | (col(ReservationRelease.expires_at) <= int(time.time())) + ) .values(status="released") ) return bool(transition.rowcount == 1) @@ -221,7 +224,10 @@ async def release_stale_reservations( query = ( select(ReservationRelease) .where(col(ReservationRelease.status) == "active") - .where(col(ReservationRelease.created_at) < cutoff) + .where( + (col(ReservationRelease.created_at) < cutoff) + | (col(ReservationRelease.expires_at) <= int(time.time())) + ) ) if key_hash is not None: query = query.where( @@ -784,6 +790,8 @@ class ReservationRelease(SQLModel, table=True): # type: ignore key_hash: str = Field(index=True) billing_key_hash: str = Field(index=True) reserved_msats: int + started_at: int | None = Field(default=None) + expires_at: int | None = Field(default=None, index=True) status: str = Field(default="active") created_at: int = Field(default_factory=lambda: int(time.time())) diff --git a/routstr/core/lifecycle.py b/routstr/core/lifecycle.py new file mode 100644 index 00000000..897df5b7 --- /dev/null +++ b/routstr/core/lifecycle.py @@ -0,0 +1,135 @@ +"""Supervise the real downstream connection, outside HTTP middleware wrappers.""" + +from __future__ import annotations + +import asyncio +from contextvars import ContextVar +from dataclasses import dataclass, field +from typing import TYPE_CHECKING + +if TYPE_CHECKING: + from ..auth import ReservationSnapshot + +from starlette.types import ASGIApp, Message, Receive, Scope, Send + +from . import get_logger +from .settings import settings + +logger = get_logger(__name__) + + +@dataclass +class RequestLifetime: + deadline: float = 0 + stopped: bool = False + reservations: list[ReservationSnapshot] = field(default_factory=list) + + +request_lifetime: ContextVar[RequestLifetime | None] = ContextVar( + "request_lifetime", default=None +) + + +class RequestLifecycleMiddleware: + def __init__(self, app: ASGIApp) -> None: + self.app = app + + async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None: + if scope["type"] != "http": + await self.app(scope, receive, send) + return + lifetime = RequestLifetime( + deadline=asyncio.get_running_loop().time() + + settings.max_request_lifetime_seconds + ) + token = request_lifetime.set(lifetime) + disconnected = asyncio.Event() + # One receive consumer. Backpressure uploads until consumed; after the + # final body message, continue listening independently of the app. + messages: asyncio.Queue[Message] = asyncio.Queue(maxsize=1) + response_started = False + + async def pump() -> None: + while True: + message = await receive() + if message["type"] == "http.disconnect": + disconnected.set() + return + await messages.put(message) + + async def downstream_receive() -> Message: + if disconnected.is_set(): + return {"type": "http.disconnect"} + get = asyncio.create_task(messages.get()) + gone = asyncio.create_task(disconnected.wait()) + try: + await asyncio.wait((get, gone), return_when=asyncio.FIRST_COMPLETED) + if disconnected.is_set(): + return {"type": "http.disconnect"} + return get.result() + finally: + for task in (get, gone): + task.cancel() + await asyncio.gather(get, gone, return_exceptions=True) + + async def downstream_send(message: Message) -> None: + nonlocal response_started + if disconnected.is_set() or lifetime.stopped: + raise OSError("Downstream request terminated") + async with asyncio.timeout(settings.downstream_send_timeout_seconds): + await send(message) + if message["type"] == "http.response.start": + response_started = True + + receiver = asyncio.create_task(pump()) + work = asyncio.create_task(self.app(scope, downstream_receive, downstream_send)) + gone = asyncio.create_task(disconnected.wait()) + try: + done, _ = await asyncio.wait( + (work, gone), + timeout=settings.max_request_lifetime_seconds, + return_when=asyncio.FIRST_COMPLETED, + ) + if work in done: + await work + elif not disconnected.is_set() and not response_started: + await downstream_send( + {"type": "http.response.start", "status": 504, "headers": []} + ) + await downstream_send( + {"type": "http.response.body", "body": b"Request deadline exceeded"} + ) + finally: + lifetime.stopped = True + for task in (receiver, gone, work): + task.cancel() + # Cancellation/close is bounded: an uncooperative finalizer must not + # hold ownership or renewal indefinitely. + done, pending = await asyncio.wait( + (receiver, gone, work), timeout=settings.request_cleanup_timeout_seconds + ) + for task in done: + if not task.cancelled(): + task.exception() + for task in pending: + task.cancel() + task.add_done_callback( + lambda t: t.exception() if not t.cancelled() else None + ) + try: + async with asyncio.timeout(settings.request_cleanup_timeout_seconds): + from ..auth import _stop_reservation_heartbeat, release_reservation + from .db import create_session + + for snapshot in lifetime.reservations: + await _stop_reservation_heartbeat(snapshot.release_id) + async with create_session() as session: + await release_reservation( + snapshot, session, snapshot.reserved_msats + ) + except Exception: + logger.exception( + "Request cleanup failed; durable expiry will recover reservations" + ) + finally: + request_lifetime.reset(token) diff --git a/routstr/core/main.py b/routstr/core/main.py index 584fa736..46aad1fc 100644 --- a/routstr/core/main.py +++ b/routstr/core/main.py @@ -45,6 +45,7 @@ from .exceptions import ( http_exception_handler, validation_exception_handler, ) +from .lifecycle import RequestLifecycleMiddleware from .logging import get_logger, setup_logging from .middleware import LoggingMiddleware from .not_found import _NOT_FOUND_HTML, not_found_catch_all # noqa: F401 @@ -315,6 +316,10 @@ app.add_middleware( # Add logging middleware app.add_middleware(LoggingMiddleware) +# Outermost: observe the actual downstream connection, not middleware streams. + +app.add_middleware(RequestLifecycleMiddleware) + # Add exception handlers app.add_exception_handler(HTTPException, http_exception_handler) # type: ignore app.add_exception_handler(RequestValidationError, validation_exception_handler) diff --git a/routstr/core/settings.py b/routstr/core/settings.py index 5dd2d57d..d9324f13 100644 --- a/routstr/core/settings.py +++ b/routstr/core/settings.py @@ -117,6 +117,16 @@ class Settings(BaseSettings): default=604_800, env="DEAD_KEY_MIN_AGE_SECONDS" ) + max_request_lifetime_seconds: float = Field( + default=1800, gt=0, env="MAX_REQUEST_LIFETIME_SECONDS" + ) + downstream_send_timeout_seconds: float = Field( + default=60, gt=0, env="DOWNSTREAM_SEND_TIMEOUT_SECONDS" + ) + request_cleanup_timeout_seconds: float = Field( + default=30, gt=0, env="REQUEST_CLEANUP_TIMEOUT_SECONDS" + ) + # Network cors_origins: list[str] = Field(default_factory=lambda: ["*"], env="CORS_ORIGINS") # Comma-separated METHOD:path pairs adding to the proxy's canonical diff --git a/routstr/upstream/stream_ownership.py b/routstr/upstream/stream_ownership.py index e0e3e51d..ea06e400 100644 --- a/routstr/upstream/stream_ownership.py +++ b/routstr/upstream/stream_ownership.py @@ -10,6 +10,7 @@ from fastapi.responses import StreamingResponse from starlette.types import Receive, Scope, Send from ..core import get_logger +from ..core.settings import settings logger = get_logger(__name__) @@ -74,10 +75,14 @@ class PersistentStreamFinalizer: self._task: asyncio.Future[None] | None = None self._lock = asyncio.Lock() + async def _bounded_finalize(self) -> None: + async with asyncio.timeout(settings.request_cleanup_timeout_seconds): + await self._finalize() + async def run(self) -> None: async with self._lock: if self._task is None: - self._task = asyncio.ensure_future(self._finalize()) + self._task = asyncio.ensure_future(self._bounded_finalize()) task = self._task await asyncio.shield(task) diff --git a/tests/unit/test_request_lifecycle.py b/tests/unit/test_request_lifecycle.py new file mode 100644 index 00000000..03cf9897 --- /dev/null +++ b/tests/unit/test_request_lifecycle.py @@ -0,0 +1,57 @@ +import asyncio +from unittest.mock import patch + +import pytest + +from routstr.core.lifecycle import RequestLifecycleMiddleware +from routstr.core.settings import settings + + +@pytest.mark.asyncio +@pytest.mark.parametrize("reason", ["disconnect", "deadline", "send"]) +async def test_lifecycle_stops_live_work(reason): + closed = asyncio.Event() + receive_queue = asyncio.Queue() + await receive_queue.put({"type": "http.request", "body": b"", "more_body": False}) + sent = [] + + async def app(scope, receive, send): + try: + assert (await receive())["type"] == "http.request" + await send({"type": "http.response.start", "status": 200, "headers": []}) + while True: + await send( + {"type": "http.response.body", "body": b"x", "more_body": True} + ) + await asyncio.sleep(0.01) + finally: + closed.set() + + async def send(message): + sent.append(message) + if reason == "send" and message["type"] == "http.response.body": + await asyncio.sleep(100) + + async def disconnect(): + await asyncio.sleep(0.02) + await receive_queue.put({"type": "http.disconnect"}) + + task = asyncio.create_task(disconnect()) if reason == "disconnect" else None + with ( + patch.object(settings, "max_request_lifetime_seconds", 0.08), + patch.object(settings, "downstream_send_timeout_seconds", 0.03), + patch.object(settings, "request_cleanup_timeout_seconds", 0.1), + ): + try: + await asyncio.wait_for( + RequestLifecycleMiddleware(app)( + {"type": "http"}, receive_queue.get, send + ), + 1, + ) + except TimeoutError: + assert reason == "send" + if task: + await task + assert closed.is_set() + assert sent diff --git a/tests/unit/test_stale_reservations.py b/tests/unit/test_stale_reservations.py index 558fdda5..6cd59682 100644 --- a/tests/unit/test_stale_reservations.py +++ b/tests/unit/test_stale_reservations.py @@ -428,3 +428,62 @@ async def test_proxy_reverts_reservation_on_client_disconnect() -> None: await proxy_module.proxy(request, "v1/chat/completions") revert_mock.assert_awaited_once_with(key, session, 1000, reservation_snapshot) + + +@pytest.mark.asyncio +async def test_absolute_expiry_releases_fresh_lease(session: AsyncSession) -> None: + now = int(time.time()) + key = ApiKey( + hashed_key="expired-deadline", + balance=5000, + reserved_balance=1000, + reserved_at=now, + ) + session.add(key) + session.add( + ReservationRelease( + id="expired", + key_hash=key.hashed_key, + billing_key_hash=key.hashed_key, + reserved_msats=1000, + created_at=now, + started_at=now - 100, + expires_at=now - 1, + ) + ) + await session.commit() + assert await release_stale_reservations(session, 300) == 1 + await session.refresh(key) + assert key.reserved_balance == 0 + assert key.balance == 5000 + + +@pytest.mark.asyncio +async def test_expired_reservation_cannot_renew_or_claim_charge( + session: AsyncSession, +) -> None: + from routstr.auth import ( + ReservationSnapshot, + _claim_reservation_for_charge, + renew_reservation, + ) + + snapshot = ReservationSnapshot( + release_id="fenced", + key_hash="fenced-key", + billing_key_hash="fenced-key", + reserved_msats=1000, + ) + session.add(ApiKey(hashed_key="fenced-key", balance=5000, reserved_balance=1000)) + session.add( + ReservationRelease( + id="fenced", + key_hash="fenced-key", + billing_key_hash="fenced-key", + reserved_msats=1000, + expires_at=int(time.time()) - 1, + ) + ) + await session.commit() + assert not await renew_reservation(snapshot, session) + assert not await _claim_reservation_for_charge(snapshot, session) From 8aa86b8814eedfe0564f3d2c9e372a45ec4989bf Mon Sep 17 00:00:00 2001 From: redshift <213178690+1ftredsh@users.noreply.github.com> Date: Wed, 30 Sep 2026 20:03:24 +0800 Subject: [PATCH 2/5] docs: include reservation diagnosis and original main reproduction with fix --- RESERVED_BALANCE.md | 541 ++++++++++++++++++ reservation-repro-main/README.md | 106 ++++ .../after-upstream-stop.json | 1 + reservation-repro-main/connections.txt | 7 + reservation-repro-main/control-results.txt | 5 + reservation-repro-main/control-router.log | 43 ++ reservation-repro-main/dummy_upstream.py | 45 ++ reservation-repro-main/final-before-stop.json | 1 + reservation-repro-main/no_logging_app.py | 4 + reservation-repro-main/probe.py | 60 ++ reservation-repro-main/results.txt | 27 + reservation-repro-main/router.log | 114 ++++ reservation-repro-main/starlette-source.txt | 169 ++++++ reservation-repro-main/upstream.log | 23 + reservation-repro-main/uvicorn-source.txt | 125 ++++ 15 files changed, 1271 insertions(+) create mode 100644 RESERVED_BALANCE.md create mode 100644 reservation-repro-main/README.md create mode 100644 reservation-repro-main/after-upstream-stop.json create mode 100644 reservation-repro-main/connections.txt create mode 100644 reservation-repro-main/control-results.txt create mode 100644 reservation-repro-main/control-router.log create mode 100644 reservation-repro-main/dummy_upstream.py create mode 100644 reservation-repro-main/final-before-stop.json create mode 100644 reservation-repro-main/no_logging_app.py create mode 100644 reservation-repro-main/probe.py create mode 100644 reservation-repro-main/results.txt create mode 100644 reservation-repro-main/router.log create mode 100644 reservation-repro-main/starlette-source.txt create mode 100644 reservation-repro-main/upstream.log create mode 100644 reservation-repro-main/uvicorn-source.txt diff --git a/RESERVED_BALANCE.md b/RESERVED_BALANCE.md new file mode 100644 index 00000000..a7417bc4 --- /dev/null +++ b/RESERVED_BALANCE.md @@ -0,0 +1,541 @@ +# Reserved balance blocks refunds long after the last request + +## Reported issue + +A client attempting to refund an API key receives: + +> Cannot refund key. There are ongoing requests for this api key. + +The user reports that the key has not been used in a very long time, potentially days. This is not a refund racing with normal request completion. The expected behavior is that reservations left by disconnected, crashed, abandoned, or failed requests eventually expire and the key becomes refundable. + +The error does **not** prove that an upstream inference request is running. In the current implementation, it means the refund endpoint still sees a positive aggregate `reserved_balance` after attempting stale-reservation cleanup. + +This document records a source-code investigation of the current checkout. The affected node's database, logs, runtime tasks, effective configuration, and deployed version have not been inspected. The production root cause remains unconfirmed. + +## Investigation scope and results + +Checkout inspected: `96c8e2f7` (`Merge pull request #790 from Routstr/fix/rename-unsupported-param`). + +The existing cleanup system is implemented and wired into application startup. It protects several important accounting invariants, but it is based on renewable reservation leases rather than a hard maximum request lifetime. + +Verification command: + +```bash +.venv/bin/pytest \ + tests/unit/test_stale_reservations.py \ + tests/unit/test_streaming_billing_finalization.py \ + tests/integration/test_negative_available_balance_repro.py -q +``` + +Result: **59 passed in 10.04 seconds**. + +These passing tests verify existing recovery paths; they do not establish what happened on the affected node or demonstrate recovery from every kind of live-but-hung task. No implementation changes were made during this investigation. + +## Reservation lifecycle + +### 1. Reserve before forwarding + +`pay_for_request()` in `routstr/auth.py` reserves funds before dispatching the billed request upstream. + +It creates a durable `ReservationRelease` identity containing: + +- `id`: the individual reservation identity; +- `key_hash`: the request's key; +- `billing_key_hash`: the key whose balance backs the request; +- `reserved_msats`: the amount owned by this reservation; +- `status`: initially `active`; +- `created_at`: initially the current timestamp. + +The aggregate reserved balance and durable reservation row commit together. The request's reservation identity matters: releasing one request must not erase funds reserved by another concurrent request. + +`ApiKey.reserved_at` is also stamped when funds are reserved. It is an aggregate timestamp, not an independent timestamp for each request. + +### 2. Renew while the owner task remains alive + +`_start_reservation_heartbeat()` in `routstr/auth.py` starts a task for each reservation. Its interval is: + +```python +max(1, settings.stale_reservation_timeout_seconds // 3) +``` + +With the default timeout of 300 seconds, renewal occurs approximately every 100 seconds. + +The heartbeat captures `asyncio.current_task()` as the owner. At each iteration it checks: + +```python +if owner is None or owner.done(): + return +``` + +If the owner is still alive, it calls `renew_reservation()` using a separate database session. Renewal updates the active durable row's `created_at` to the current time. + +Important consequences: + +- Renewal depends on task lifetime, not demonstrated request progress. +- There is no original-age limit in this heartbeat. +- `created_at` is overwritten, so it actually serves as a renewable lease timestamp. +- An owner that has finished cannot keep renewing indefinitely through this heartbeat. +- An owner that is blocked indefinitely may keep renewing indefinitely. + +### 3. Settle or release + +Normal completion settles the charge and releases the reservation. Handled upstream failures revert the reservation. Terminal reservation transitions stop the heartbeat. + +The proxy includes cancellation cleanup. Streaming paths use finalizers and ownership wrappers to improve cleanup across cancellation and downstream-send failures. Relevant code includes: + +- `routstr/auth.py`; +- `routstr/proxy.py`; +- `routstr/upstream/base.py`; +- `routstr/upstream/stream_ownership.py`. + +If a request dies without completing cleanup, its heartbeat is intended to stop once the owning task is done. The reservation can then age out and be released by the sweeper. + +## Existing cleanup mechanisms + +### Background sweep + +`periodic_stale_reservation_sweep()` in `routstr/auth.py` is started by the application lifespan in `routstr/core/main.py`. + +Defaults: + +| Setting/mechanism | Default | Meaning | +| --- | --- | --- | +| `STALE_RESERVATION_TIMEOUT_SECONDS` | 300 seconds | Maximum age of an unrenewed reservation lease before it is stale | +| `STALE_RESERVATION_SWEEP_INTERVAL_SECONDS` | 60 seconds | Interval between background cleanup passes | +| Heartbeat interval | 100 seconds | Approximately one third of the stale timeout | +| `UPSTREAM_READ_TIMEOUT` | 900 seconds | Upstream HTTP read inactivity timeout, not a total request deadline | +| `RESET_RESERVED_BALANCE_ON_STARTUP` | `True` | Explicit startup reset of active reservations and aggregate reserved balances | + +The sweeper calls `release_stale_reservations()` in `routstr/core/db.py`. + +For durable reservations, it selects `active` rows whose `created_at` is older than the cutoff. Its terminal update also checks the timestamp, protecting against a heartbeat that renews between selection and release. + +Each successful release subtracts that reservation's own amount from the relevant aggregates. Healthy releases commit individually so that certain later corruption repairs cannot roll them back. + +Under healthy execution, recovery occurs after the last lease renewal has aged beyond the configured timeout, plus sweep scheduling and database-operation time. This is **not** a guarantee of release 300 seconds after the request originally began. + +### Refund-time cleanup + +`refund_wallet_endpoint()` in `routstr/balance.py` checks for reserved funds before opening the refund claim. + +If `key.reserved_balance > 0`, it: + +1. Calls `release_stale_reservations()` scoped to that key. +2. Refreshes the key from the database. +3. Returns HTTP 400 with the reported message if reserved balance remains. + +Thus, the current refund path does not rely exclusively on the background task having run. A stale durable reservation should also be releasable during refund itself. + +If cleanup raises an unexpected exception instead, that is a separate failure from this specific HTTP 400 branch. + +### Legacy aggregate cleanup + +Older deployments may have aggregate reserved balances without matching durable rows. + +The cleanup function also looks for these legacy aggregates, but only clears them when there is no active durable owner. It uses a compare-and-swap guard on the observed balance and timestamp to avoid erasing a newly created reservation. + +The behavior differs between background and targeted cleanup: + +| Legacy aggregate state, with no active durable owner | Background sweep | Refund-time targeted cleanup | +| --- | --- | --- | +| Old `reserved_at` | Eligible for release | Eligible for release | +| Recent `reserved_at` | Preserved | Preserved | +| `reserved_at = NULL` | Deliberately skipped | Eligible for repair | + +The NULL-timestamp behavior is explicitly covered by existing tests. It is a background-recovery limitation, but **alone it does not explain the reported refund rejection on the current checkout**, because targeted refund cleanup heals it. + +### Startup reset + +When enabled, startup calls `reset_all_reserved_balances()`. It marks active durable reservations released and clears aggregate reserved balances and timestamps. + +This is not a safe universal operational fix. In a shared-database, multi-instance setup, another instance may still own a legitimate in-flight request. Resetting its reservation can break billing. The setting's source comment recommends disabling it for horizontal scaling. + +## Why the 900-second HTTP timeout does not guarantee eventual completion + +The user correctly asks: if the last request was days ago, shouldn't a 900-second upstream timeout have completed or failed the request long before now? + +**For an ordinary request actively waiting for upstream bytes, with no bytes arriving, yes.** It should hit the read timeout and reach failure cleanup. A days-long refund blockage is abnormal, not expected behavior for a silent upstream. + +However, the HTTP read timeout is not an absolute deadline spanning the complete request lifecycle. + +### Upstream continues sending bytes + +A stream can avoid a read inactivity timeout by delivering bytes periodically. Those bytes might be content or keepalive traffic. A stream with no total-duration limit could therefore remain open longer than 900 seconds. + +This is a technical possibility, **not evidence that the affected upstream streamed for days**. It must not be assumed as the production explanation. + +### Router is blocked writing to the downstream client + +If the router has received a chunk and is blocked delivering it to the client, it may not currently be waiting on an upstream HTTP read. The upstream read timeout is not a general bound on downstream ASGI sends. + +Whether a particular blocked send keeps the captured owner task alive depends on the execution path. That behavior needs a runtime trace or regression test, rather than an assumption about all stream paths. + +### Router is blocked after upstream completion + +Database settlement, finalization, or resource cleanup happens outside the upstream read operation. The upstream read timeout does not bound these waits. + +If the heartbeat's owning task remains alive while waiting, renewal may continue. If that owner finishes and only detached cleanup remains, the heartbeat should stop and the sweeper should eventually recover the reservation. + +### Conclusion + +The current code has no common hard lifetime limit found in this investigation that covers reservation creation, upstream dispatch, streaming delivery, and finalization together. + +The missing guarantee is: + +> A live-but-stuck request cannot renew its reservation forever. + +This gap is confirmed by the heartbeat's renewal condition. The specific blocked operation, if any, on the affected node is not known. + +## Findings and hypotheses + +### Confirmed: renewal does not require progress + +An owner task being alive is sufficient to renew the lease. Neither original request age nor meaningful progress is checked. + +This permits indefinite reservation retention in principle, even without new requests using the key. + +### Confirmed: immutable request age is not stored in the reservation row + +`ReservationRelease.created_at` doubles as the last-renewal timestamp. Once renewed, it cannot tell us when the request originally started. + +This impairs diagnostics and prevents enforcing an original-age limit from this field alone. + +### Confirmed: NULL legacy timestamps are not background-cleaned + +Such keys may remain reserved indefinitely in the background. The current refund endpoint has targeted recovery for this state, subject to the absence of an active durable owner. + +### Confirmed: unexpected failures can interrupt a sweep pass + +The background loop catches unexpected exceptions, logs `Error in periodic_stale_reservation_sweep`, and retries after the sweep interval. + +Some aggregate-corruption cases are handled per reservation, but not every database exception is isolated per record. A persistently failing operation could repeatedly interrupt a pass. Whether this prevents a particular key's cleanup depends on the failure and processing order. + +There is no evidence yet that this caused the reported error. + +### Possible: affected deployment differs from this checkout + +The current code includes heartbeat-owner binding, targeted legacy recovery, and corruption handling. The affected node may run older or different code. + +The deployed commit must be established before treating local behavior as proof of production behavior. + +### Possible: future timestamps or unusual effective configuration + +A future-dated lease can remain non-stale unexpectedly. An unusually large configured timeout can also preserve old reservations. + +Clock skew between instances sharing a database can affect lease timestamps and age calculations. These are diagnostic checks, not confirmed causes. + +## Existing verified recovery coverage + +The suites run during this investigation cover, among other cases: + +- Stamping aggregate reservation timestamps on payment. +- Reverting individual reservations without erasing siblings. +- Releasing old reservations and preserving fresh ones. +- Resetting reserved balances during explicit startup reset. +- Refund-time recovery of stale and legacy NULL-timestamp aggregates. +- Refusing refunds while a recent reservation remains. +- Streaming finalization and client-disconnect cleanup. +- Owner task termination allowing recovery of an abandoned reservation. +- Lease renewal across an in-flight request. +- Renewal racing with stale release. +- Legacy aggregate release racing with a new reservation. +- Several accounting-corruption cases and safe terminal repair. +- Preventing late charges after a reservation has reached a released terminal state. + +These tests do not substitute for explicit tests of endless keepalive streams, blocked downstream sends, or finalization that never completes. + +## Production diagnosis: distinguish a renewing lease from failed cleanup + +The most useful initial question is: + +> Is the reservation still being renewed, or is it stale and not being released? + +Do not share the raw API-key secret. Use its stored hash and reservation identifiers in restricted operational diagnostics. + +### 1. Establish deployment and configuration + +Record: + +- Deployed commit/version. +- Effective `STALE_RESERVATION_TIMEOUT_SECONDS`. +- Effective `UPSTREAM_READ_TIMEOUT`. +- Startup-reset setting. +- Number of instances sharing the database. +- Current time on each relevant instance. +- Whether the lifespan/background tasks completed startup. + +Use effective settings, not only environment variables; settings initialization includes persisted configuration. + +### 2. Inspect the key and all related reservations + +Read-only queries: + +```sql +SELECT hashed_key, balance, reserved_balance, reserved_at +FROM api_keys +WHERE hashed_key = :key_hash; + +SELECT id, key_hash, billing_key_hash, + reserved_msats, status, created_at +FROM reservation_releases +WHERE key_hash = :key_hash + OR billing_key_hash = :key_hash; +``` + +Inspect both key relationships, since a reservation may reference the key as request owner or billing owner. + +Take two snapshots approximately 110 seconds apart with default settings, or use an interval longer than the effective heartbeat interval. A pair of snapshots is a useful signal; it is not a substitute for longer observation when renewal is delayed or intermittent. + +### 3. Interpret the results + +| Observation | Investigation direction | +| --- | --- | +| Active reservation timestamp advances | Identify the instance and owning task renewing it; inspect its stack and actual progress | +| Active reservation timestamp is older than the stale cutoff and does not advance | Check sweep execution/errors, refund cleanup, deployed code, and accounting state | +| Reserved balance remains with no active durable rows | Inspect legacy timestamp and aggregate recovery; current targeted refund cleanup should repair stale/NULL state | +| Lease timestamp is in the future | Check clocks and timestamp integrity | +| Some rows are stale and others fresh | Release only stale owners; do not clear the whole key | +| Aggregate amount disagrees with active durable ownership | Investigate accounting drift and safe reconciliation | + +If the lease is genuinely days old and unrenewed, the indefinite-heartbeat explanation does **not** explain that row. Cleanup failure or incompatible deployment becomes the relevant direction. + +### 4. Inspect logs and task state + +Relevant existing log messages include: + +- `Error in periodic_stale_reservation_sweep`. +- `Failed to renew billing reservation lease`. +- `Released stale reservations`. +- `Released corrupt stale reservation without aggregate subtraction`. +- `Released corrupt reservation without aggregate subtraction`. +- `Client disconnected mid-request, reverting reservation`. +- `refund_wallet_endpoint: released stale reservation before refund`. + +For a renewing lease, locate the process with that reservation's heartbeat and inspect the owner's stack. Determine whether it is waiting on upstream input, downstream delivery, database work, finalization, or another operation. + +Also correlate the original request with upstream outcome and billing logs. A heartbeat alone does not demonstrate that inference is still running. + +## Proposed hardening + +These are proposed changes, not completed fixes. + +### 1. Separate original age from renewable lease age + +Keep distinct durable fields for: + +- Immutable reservation/request start time. +- Last lease renewal time. + +Consider additional progress and ownership metadata where justified. Define migration behavior explicitly: existing renewed `created_at` values cannot reconstruct true original start times. + +### 2. Bound the actual request, not just the accounting lease + +Introduce a configurable total billed-request lifetime covering all relevant routes and phases, including streaming delivery. Add appropriate inactivity bounds for upstream waits and downstream delivery, and bounded finalization/cleanup behavior. + +Timeout handling should: + +1. Stop or cancel the owning request and close owned resources. +2. Settle known or estimated delivered usage according to existing billing policy. +3. Release only that request's remaining reservation. +4. Stop heartbeat renewal. +5. Reach a durable terminal state that prevents later charging. + +Do **not** merely stop renewal or zero the key while a request continues running. Releasing funds while upstream work can still finish creates refund/late-charge and provider-cost risks. + +Care is also needed not to cancel legitimate long-running inference accidentally. Request lifetime, inactivity, and lease expiry are different concepts and should have distinct documented policies. + +### 3. Improve stalled-owner detection and observability + +Expose actionable, non-secret diagnostics: + +- Reservation identity and owning instance. +- Immutable age and current lease age. +- Last meaningful progress and current phase, if tracked. +- Reason for terminal transition or refused refund. +- Age and count of active reservations. +- Sweep failures and cleanup duration. + +Do not treat upstream keepalive bytes as necessarily meaningful model progress. Decide deliberately which signals should extend which deadlines. + +### 4. Reconcile legacy and inconsistent aggregates safely + +Define a migration/recovery policy for NULL legacy timestamps, rather than leaving them background-ineligible indefinitely. + +Mixed-version deployments require caution: an aggregate without a durable row might still belong to an older live worker. Any reconciliation must preserve valid durable owners and avoid unsafe whole-key resets. + +Investigate positive residual aggregates even after durable rows become terminal, with concurrency guards and accounting invariants preserved. + +### 5. Make cleanup failures diagnosable and resilient + +Consider bounded database operations, per-record failure isolation where safe, and alerts for repeated sweep failures or reservations exceeding expected age. + +Failure isolation must not weaken atomicity between durable transitions and aggregate updates. A failed release must not partially debit unrelated reservations. + +## Regression tests needed to close the gaps + +Add tests that reproduce and verify recovery for: + +1. A live owner waiting indefinitely without progress. +2. An endless upstream stream sending keepalive bytes below the read-timeout interval. +3. A downstream send blocked indefinitely after receiving an upstream chunk. +4. Finalization or database settlement that stalls. +5. Cancellation before streaming begins, during streaming, and during finalization. +6. Renewing lease older than the new maximum original-age limit. +7. Background legacy NULL-timestamp recovery under the chosen migration policy. +8. Corrupt residual aggregates alongside a healthy active sibling reservation. +9. A failing cleanup operation followed by other recoverable reservations. +10. Multiple workers concurrently renewing, sweeping, timing out, and refunding. +11. Late completion attempting to charge after timeout/release. +12. Future lease timestamps and the chosen clock-skew policy. + +For each timeout/recovery test, assert: + +- The underlying request/resource is stopped or closed as intended. +- No heartbeat can renew indefinitely afterward. +- Only the affected reservation is released. +- Sibling reservations remain intact. +- Balance/reserved accounting remains valid. +- Terminal transitions are idempotent. +- A later completion cannot charge released/refunded funds. +- The key becomes refundable when no legitimate reservations remain. + +## Operational caution + +Do not solve the symptom by manually setting `reserved_balance = 0` while active requests or heartbeat tasks may exist. Durable reservation state and aggregate balances must agree, and late completion must not be allowed to spend refunded funds. + +Any production repair should begin with a read-only snapshot and identification of live ownership, then use an accounting-safe terminal transition or controlled maintenance procedure. + +## Bottom line + +The expected stale cleanup exists. A genuinely dead, unrenewed reservation should recover on the current version with healthy database access, including during a refund attempt. + +The confirmed design gap is that **a task remaining alive is sufficient to renew its reservation indefinitely**, and the upstream 900-second read timeout does not bound every phase of that task's lifetime. + +A days-old refund blockage therefore warrants investigation, not an assumption that normal request processing is still underway. The first decisive evidence is whether the affected reservation's lease timestamp continues advancing. The production root cause and implementation fixes remain open. + +## Release-specific reproduction: v0.4.7 (confirmed) + +The user subsequently confirmed that the affected node runs the released **v0.4.7** tag. Testing that tag revealed an important correction to the initial analysis above: + +**The 900-second upstream read timeout exists in the newer checkout, not in v0.4.7.** The release's forwarding paths construct `httpx.AsyncClient(..., timeout=None)`. It has no `upstream_read_timeout` settings field. Setting `UPSTREAM_READ_TIMEOUT=3` in the reproduction did nothing; importing the release settings confirmed the field is absent. + +Therefore, on this release an upstream can send one chunk and then remain completely silent without triggering an HTTP read timeout. Periodic bytes are not needed to explain indefinite waiting. + +### Environment and isolation + +- Podman: 5.8.4, netavark network backend. +- Release commit: `f32565e2547abbbffd77a01198ef683ecb8e3d4f`. +- Detached worktree: `.worktrees/reserved-balance-v047`. +- Built the release's own Dockerfile (Python 3.11 base), without source patches. +- Image: `localhost/routstr-reserved-repro:v0.4.7`. +- Image ID: `8c3340a33040df37439f7085e369050d3acc2adf0324bc024e1b4288a3601f76`. +- Separate containers, loopback ports 18080/18081, container-local SQLite database. +- No original node database, wallet, secrets, volumes, or image tag were changed. +- Host networking avoided the reported aardvark DNS issue for this experiment; containerized DNS was not tested or repaired. +- Accelerated stale timeout: 6 seconds, heartbeat every 2 seconds. Background sweep retained its actual 60-second interval. +- Synthetic database-funded keys avoided introducing Cashu mint behavior into the reservation test. Actual refund payout success was not tested. + +### Dummy upstream scenarios + +A small local OpenAI-compatible server exposed `/v1/models` and `/v1/chat/completions` using `gpt-4o-mini`: + +1. **Finite:** three chunks, a usage event, and `[DONE]`. +2. **Silent:** one chunk, then sleep for 3600 seconds. +3. **Endless:** a content chunk every 0.5 seconds with no terminal event. + +The test client consumed streams, queried reservation state, attempted refunds, and disconnected. Evidence and reusable scripts are in `reservation-repro-v047/`. + +### Observed results + +| Scenario | Outcome | +| --- | --- | +| Finite stream | Settled normally; reserved balance became zero | +| Silent stream | Did not time out; durable lease kept renewing | +| Endless stream | Lease kept renewing; refund returned the exact reported HTTP 400 | +| Both clients disconnected | Both upstream connections remained established; both reservations remained active and kept renewing | +| After more than a background-sweep interval | The abandoned reservations were still active; their fresh leases prevented stale cleanup | +| Dummy upstream forcibly stopped | Both requests finally reached error/finalization; both reserved balances became zero and rows became `charged` | + +Both streams reserved 11 msats. Their lease timestamps initially advanced from `1790765677` through `1790765685` and `1790765695`. After client termination, a later snapshot at `1790765791` still showed both rows `active` with leases at `1790765789`. This is approximately 116 seconds after their creation and well beyond the accelerated stale timeout and a background-sweep interval. + +At that later point, `ss` showed two established router-to-upstream connections and no test-client connection on port 18080. A refund for the silent key still returned: + +```json +{"detail":"Cannot refund key. There are ongoing requests for this api key."} +``` + +Stopping the dummy upstream broke those connections. Finalization then charged estimated usage and cleared the reservations. The finite and silent keys ended with a 3-msat charge; the endless stream accumulated a 25-msat charge. This also demonstrates that abandoned upstream work can continue affecting billing after the downstream client is gone. + +The first probe run ended with a client-side `TimeoutError` because it expected the silent stream to complete. That timeout was imposed by the probe's `asyncio.wait_for`, not by the router. The saved probe was subsequently adjusted to report this expected observation rather than crash. + +### What this establishes + +We have reproduced a plausible mechanism for a key remaining blocked long after the client last used it on **the exact release tag**: + +1. The upstream stream remains open, even silently. +2. Downstream disconnection does not terminate the upstream-owning request in the tested runtime/path. +3. The owner remains alive, so its heartbeat keeps renewing. +4. Background and refund-time stale cleanup preserve the fresh lease. +5. Refund remains blocked indefinitely unless the upstream closes or another intervention stops the owning work. + +The reproduction lasted minutes, not days. The absence of a read timeout and continuing renewal explain how the state can persist longer; no days-long run was performed. + +This is concrete release-specific evidence, but not proof that the affected production key has this exact state. Production confirmation still requires reservation snapshots and logs. + +### Shutdown symptoms + +The dummy upstream also needed SIGKILL after a short SIGTERM grace period while its streams were open. The router stopped normally after the upstream was stopped and its streams finalized. + +This supports the possibility that outstanding streaming work can delay graceful shutdown. It does not establish that the user's earlier router/UI shutdown warnings share the same cause. The aardvark DNS removal failure is a separate Podman networking symptom; the reproduction does not require it. + +### Next implementation work + +Prioritize fixes/backports appropriate to v0.4.7: + +- Finite upstream transport timeouts, including reads and header waits. +- Reliable downstream-disconnect propagation and deterministic closure/finalization of owned streaming resources in the deployed FastAPI/Starlette/Uvicorn combination. +- A maximum request lifetime independent of renewable leases and keepalive bytes. +- Real-network regression tests that disconnect a client from a silent upstream stream and assert upstream closure, terminal billing state, stopped renewal, and zero residual reservation. + +The newer checkout has transport timeout and stream-ownership changes, but this experiment did not validate the same scenario against that newer checkout. Do not assume an upgrade fully fixes every gap without rerunning the reproduction. + +Both reproduction containers were stopped at the end. Their container-local database and logs were retained for inspection; no original services were restarted. + +## Current main reproduction: timeout does not close every gap + +The same investigation was repeated against unpatched local main commit `96c8e2f77de8e9f8a0979d17dba0a6d20c78fe89` using its own Dockerfile and frozen dependencies. The main image ran Python 3.14, Starlette 1.6.0, and Uvicorn 0.31.1. Detailed commands and evidence are in `reservation-repro-main/README.md`. + +With an effective upstream read timeout of 3 seconds and stale timeout of 6 seconds: + +- Finite completion settled correctly. +- Silent upstream streams reached the read timeout and cleared reservations. +- A header wait timed out with HTTP 424 and released its reservation. +- An endless content stream **after client disconnect** kept renewing and returning the reported refund HTTP 400. +- SSE comment-only keepalives evaded read timeout; renewal persisted even after disconnect. +- A flood stream to a downstream client that never read remained reserved, including after its socket closed. + +The three problematic keys remained active approximately 269 seconds after request start, across multiple background sweeps, with fresh lease timestamps. This is not merely an active client asking for a refund: all downstream test clients were gone well before the final observation. + +### Framework compatibility concern + +Installed framework source provides a specific lead: + +- Uvicorn's httptools protocol advertises ASGI HTTP 2.4. +- Its send function silently returns after downstream disconnection. +- Starlette's ASGI >=2.4 StreamingResponse path expects send to raise OSError for disconnect detection and does not run the older disconnect listener. + +This mismatch is consistent with streams continuing to consume upstream bytes while downstream sends become no-ops. Captured code is in the evidence directory. A runtime task-stack or controlled framework-version comparison is still needed for complete causal validation. + +Removing only LoggingMiddleware in a diagnostic router did not resolve disconnect renewal. Therefore, do not attribute the disconnect problem solely to that middleware. + +### Additional finalization/shutdown observation + +Forcibly stopping the dummy upstream finalized the diagnostic router's streams, but the unmodified router still had active reservations five seconds after upstream termination and required SIGKILL after a ten-second SIGTERM grace period. Its logs showed upstream termination warnings without completed settlement for those three requests in the captured window. The precise blocked operation was not traced. + +This adds a finalization/delivery investigation beyond transport inactivity. In this main reproduction, unlike the release reproduction, upstream termination did not promptly clear every reservation. + +### Updated conclusion + +The newer read timeout fixes silent upstream waits, but **does not eliminate reservation leaks for disconnected clients whose upstream streams keep producing bytes, or stalled downstream delivery**. The stream ownership/finalizer unit tests previously run do not exercise the complete real server/framework/middleware network path that exposed these cases. + +Prioritize real-network regression coverage and disconnect propagation, the installed server/framework compatibility, bounded downstream delivery and finalization, and an absolute request lifetime independent of keepalive traffic. No implementation fix has been made; alternate routes, multi-worker behavior, and database fault injection remain untested. diff --git a/reservation-repro-main/README.md b/reservation-repro-main/README.md new file mode 100644 index 00000000..e3df04b9 --- /dev/null +++ b/reservation-repro-main/README.md @@ -0,0 +1,106 @@ +# Current main: real-network streaming reservation reproductions + +## Tested version and environment + +- Commit: `96c8e2f77de8e9f8a0979d17dba0a6d20c78fe89` (local main at investigation time; no remote fetch was performed). +- Unpatched application built using its Dockerfile and frozen lockfile. +- Image: `localhost/routstr-reserved-repro:main`, ID `a787e603f565f3d34e1cc3999793d9dc2d2e3c968eb0ce0ded2f485450719bd0`. +- Podman 5.8.4; Python 3.14; Starlette 1.6.0; Uvicorn 0.31.1. +- Loopback ports 18090 (router), 18091 (dummy upstream), 18092 (diagnostic control). +- Separate container-local SQLite databases and synthetic balances; no original node data or secrets mounted. +- Read timeout accelerated to 3 seconds (confirmed effective); lease expiry to 6 seconds; heartbeat every 2 seconds. Background sweep remains 60 seconds. + +## Results + +| Scenario | Result | +| --- | --- | +| Finite stream with usage and DONE | Charged normally, zero reservation | +| One chunk then silence, client connected | Read timeout fired, estimated usage charged, zero reservation | +| One chunk then silence, client disconnected after 1 second | Reservation cleared on upstream read timeout; prompt disconnect cleanup was not demonstrated | +| No upstream response headers | Timeout produced HTTP 424; reservation released | +| Endless content stream, client disconnected after 1 second | Continued renewing; exact refund HTTP 400 persisted across background sweep | +| SSE comment-only keepalives every 0.5 seconds | No meaningful content or completion, but lease renewed and refund blocked; remained active after client disconnected | +| Flood stream to client that never reads | Lease renewed while client was stalled; still renewed after client socket closed | + +The three problematic streams retained 11-msat reservations through the full observation window. They began at timestamp 1790766366; at 1790766635, all remained active with lease timestamps 1790766634. Thus renewal continued for roughly 269 seconds, far beyond the 3-second read timeout, 6-second lease timeout, and multiple 60-second sweep intervals. All test clients were gone by approximately 1790766439. + +This proves persistence for minutes, not a measured days-long run. No new inference requests were made for the keys during observation; refund probes did not renew the leases. + +The flood scenario sends 64-KiB content deltas rapidly and uses a 1-KiB client receive buffer. It exercises a real non-reading downstream socket, but no live task-stack capture was collected to establish the precise blocked await at each snapshot. + +## Why the newer timeout is insufficient + +The read timeout is an inactivity timeout for upstream reads. Endless content or SSE keepalive bytes avoid it. A downstream-send wait is not bounded by it. + +More importantly, the runtime did not reliably propagate downstream disconnect into termination of these streams. Closed clients left upstream connections established and reservation owners alive, so heartbeats kept making the durable rows fresh. The sweeper therefore correctly declined to release them under its current policy. + +## Framework evidence and diagnostic control + +Captured sources (`starlette-source.txt`, `uvicorn-source.txt`) show: + +- Uvicorn 0.31.1's httptools protocol advertises ASGI HTTP spec 2.4. +- Its `send()` returns silently when `self.disconnected` is true; it does not raise an OSError. +- Starlette's StreamingResponse for ASGI >=2.4 relies on a send OSError to signal client disconnect, rather than running its older explicit disconnect listener. +- BaseHTTPMiddleware's outer streaming wrapper also does not explicitly listen for disconnect. + +This is a concrete framework compatibility concern consistent with the observations. Deterministic confirmation via a server-version/spec comparison or task instrumentation remains future work. + +A diagnostic second router removed only LoggingMiddleware using `no_logging_app.py`. Endless and keepalive clients still left active reservations after disconnect (`control-results.txt`). Thus LoggingMiddleware alone is not sufficient to explain the disconnect leak in this environment. This control is not a proposed production patch. + +When the dummy upstream was forcibly stopped, the control router finalized both streams. The unmodified main router still showed the three reservations active five seconds afterward and subsequently needed SIGKILL after a ten-second shutdown grace period. Logs showed upstream termination warnings but no completed settlement for those three in the captured window. The exact finalization blockage was not traced; it should be investigated separately, potentially including middleware delivery/backpressure interactions. Do not assert that upstream termination always clears these main reservations. + +## Reproduce + +From project root: + +```bash +podman build --build-arg GIT_COMMIT=$(git rev-parse HEAD) --build-arg GIT_TAG=main \ + -t localhost/routstr-reserved-repro:main . + +podman run -d --name reserved-dummy-main --network host \ + -v "$PWD/reservation-repro-main:/repro:ro,Z" \ + --entrypoint /.venv/bin/python localhost/routstr-reserved-repro:main \ + -m uvicorn dummy_upstream:app --app-dir /repro --host 127.0.0.1 --port 18091 + +podman run -d --name reserved-router-main --network host \ + -e DATABASE_URL=sqlite+aiosqlite:////tmp/reserved-main.db \ + -e UPSTREAM_BASE_URL=http://127.0.0.1:18091/v1 -e UPSTREAM_API_KEY=dummy \ + -e STALE_RESERVATION_TIMEOUT_SECONDS=6 -e UPSTREAM_READ_TIMEOUT=3 \ + -e CASHU_MINTS= -e ENABLE_PRICING_REFRESH=false \ + -e MODELS_REFRESH_INTERVAL_SECONDS=0 -e ADMIN_PASSWORD=local-repro-only \ + --entrypoint /.venv/bin/python localhost/routstr-reserved-repro:main \ + -m uvicorn routstr.core.main:app --host 127.0.0.1 --port 18090 +``` + +Wait for application startup and verify `/v1/models` includes gpt-4o-mini. Model/pricing discovery uses external services; this is not fully offline. + +```bash +podman exec -i reserved-router-main /.venv/bin/python - <<'PY' +import asyncio +from routstr.core.db import ApiKey, create_session +async def main(): + async with create_session() as s: + for k in ['finite','silent','silent-disconnect','endless-disconnect','keepalive','flood','header']: + s.add(ApiKey(hashed_key='main-'+k, balance=1000000000)) + await s.commit() +asyncio.run(main()) +PY + +.venv/bin/python reservation-repro-main/probe.py +``` + +The probe runs approximately 80 seconds, snapshots the DB, attempts refunds only on reserved keys (not actual Cashu payouts), and closes all clients. Later DB snapshots show continued renewal. Use fresh container names/databases on repeats or deliberately remove only the retained reproduction containers first. Do not overwrite original node containers. + +## Evidence and remaining work + +- `results.txt`: scenario matrix snapshots and refund errors. +- `connections.txt`: upstream sockets remained after downstream sockets disappeared. +- `final-before-stop.json`: continued renewal roughly 269 seconds after start. +- `after-upstream-stop.json`: reservations still active in unmodified main five seconds after upstream termination. +- `router.log`, `upstream.log`: application evidence before router shutdown. +- `control-results.txt`, `control-router.log`: comparison without LoggingMiddleware. +- `starlette-source.txt`, `uvicorn-source.txt`: installed framework behavior. + +Need: real-network regression tests, framework compatibility correction/verification, explicit disconnect monitoring that reaches upstream ownership, bounded downstream delivery, total request lifetime, and task-stack diagnostics for finalization stalls. Database fault injection, restart/multi-worker behavior, and alternate API routes were not tested here. + +All three main reproduction containers were stopped. The unmodified main router required SIGKILL; its retained database may contain active reservations. No application source fixes were made. diff --git a/reservation-repro-main/after-upstream-stop.json b/reservation-repro-main/after-upstream-stop.json new file mode 100644 index 00000000..a4c70696 --- /dev/null +++ b/reservation-repro-main/after-upstream-stop.json @@ -0,0 +1 @@ +{"time": 1790766644.5905168, "keys": [["main-finite", 0], ["main-silent", 0], ["main-silent-disconnect", 0], ["main-endless-disconnect", 11], ["main-keepalive", 11], ["main-flood", 11], ["main-header", 0]], "rows": [["main-flood", "active", 1790766636], ["main-keepalive", "active", 1790766636], ["main-endless-disconnect", "active", 1790766636], ["main-silent", "charged", 1790766368], ["main-silent-disconnect", "charged", 1790766368], ["main-header", "released", 1790766368], ["main-finite", "charged", 1790766366]]} diff --git a/reservation-repro-main/connections.txt b/reservation-repro-main/connections.txt new file mode 100644 index 00000000..2911cbec --- /dev/null +++ b/reservation-repro-main/connections.txt @@ -0,0 +1,7 @@ +ESTAB 0 0 127.0.0.1:18091 127.0.0.1:36380 users:(("python",pid=1480010,fd=7)) +ESTAB 0 0 127.0.0.1:36380 127.0.0.1:18091 users:(("python",pid=1480035,fd=31)) +ESTAB 0 0 127.0.0.1:36394 127.0.0.1:18091 users:(("python",pid=1480035,fd=32)) +ESTAB 0 0 127.0.0.1:36402 127.0.0.1:18091 users:(("python",pid=1480035,fd=33)) +CLOSE-WAIT 1 0 127.0.0.1:36456 127.0.0.1:18091 users:(("python",pid=1480035,fd=37)) +ESTAB 0 188 127.0.0.1:18091 127.0.0.1:36402 users:(("python",pid=1480010,fd=9)) +ESTAB 0 0 127.0.0.1:18091 127.0.0.1:36394 users:(("python",pid=1480010,fd=8)) diff --git a/reservation-repro-main/control-results.txt b/reservation-repro-main/control-results.txt new file mode 100644 index 00000000..84aee312 --- /dev/null +++ b/reservation-repro-main/control-results.txt @@ -0,0 +1,5 @@ +endless-control 200 +keepalive-control 200 +[('endless-control', 12), ('keepalive-control', 12)] +[('endless-control', 'active'), ('keepalive-control', 'active')] + diff --git a/reservation-repro-main/control-router.log b/reservation-repro-main/control-router.log new file mode 100644 index 00000000..de3a8147 --- /dev/null +++ b/reservation-repro-main/control-router.log @@ -0,0 +1,43 @@ +/.venv/lib/python3.14/site-packages/anyio/from_thread.py:119: SyntaxWarning: 'return' in a 'finally' block + return result +2026-09-30 11:08:57 WARNING routstr.core.main UI dist directory not found at /app/ui_out; serving API only. Run `make ui-build` to build the static UI served from here, or `make ui-dev` for the Next.js dev server with hot reload on :3000 (it targets this backend on :8000). +2026-09-30 11:08:57 INFO uvicorn.error Started server process [1] +2026-09-30 11:08:57 INFO uvicorn.error Waiting for application startup. +2026-09-30 11:08:57 INFO routstr.core.main Application startup initiated +2026-09-30 11:08:59 INFO routstr.core.db Database migrations completed successfully +2026-09-30 11:08:59 INFO routstr.core.db Reset reserved balances on startup +2026-09-30 11:08:59 INFO routstr.upstream.helpers Seeding custom provider +2026-09-30 11:08:59 INFO routstr.upstream.helpers Seeded 1 upstream providers from settings +2026-09-30 11:09:00 INFO routstr.proxy Initialized 1 upstream providers +2026-09-30 11:09:00 INFO routstr.nostr.listing Nostr private key not configured (NSEC); waiting for one to be set before announcing this provider +2026-09-30 11:09:00 INFO routstr.nostr.analytics Usage analytics sharing task started +2026-09-30 11:09:00 INFO routstr.nostr.analytics NSEC is not configured; skipping analytics sharing to Nostr +2026-09-30 11:09:00 INFO routstr.auth Dead-key pruning disabled (interval <= 0) +2026-09-30 11:09:00 INFO uvicorn.error Application startup complete. +2026-09-30 11:09:00 INFO uvicorn.error Uvicorn running on http://127.0.0.1:18092 (Press CTRL+C to quit) +2026-09-30 11:09:30 INFO routstr.upstream.auto_topup Auto top-up worker started +2026-09-30 11:09:37 INFO routstr.auth Existing sk- API key found +2026-09-30 11:09:37 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:09:37 INFO routstr.auth Processing payment for request +2026-09-30 11:09:37 INFO routstr.auth Existing sk- API key found +2026-09-30 11:09:37 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:09:37 INFO routstr.auth Processing payment for request +2026-09-30 11:09:37 INFO routstr.auth Payment processed successfully +2026-09-30 11:09:37 INFO routstr.payments RESERVE +2026-09-30 11:09:37 INFO routstr.auth Payment processed successfully +2026-09-30 11:09:37 INFO routstr.payments RESERVE +2026-09-30 11:10:38 WARNING routstr.upstream.base Upstream stream ended before the response was complete +2026-09-30 11:10:38 WARNING routstr.upstream.base Upstream stream ended before the response was complete +2026-09-30 11:10:38 INFO routstr.payment.cost_calculation Applied model-specific pricing +2026-09-30 11:10:38 INFO routstr.payment.cost_calculation Calculated token-based cost +2026-09-30 11:10:38 INFO routstr.payment.cost_calculation Applied model-specific pricing +2026-09-30 11:10:38 INFO routstr.payment.cost_calculation Calculated token-based cost +2026-09-30 11:10:38 INFO routstr.auth Calculated token-based cost +2026-09-30 11:10:38 INFO routstr.auth Finalized payment with additional charge +2026-09-30 11:10:38 INFO routstr.payments FINALIZE +2026-09-30 11:10:38 INFO routstr.auth Payment settlement finished +2026-09-30 11:10:38 INFO routstr.auth Calculated token-based cost +2026-09-30 11:10:38 INFO routstr.auth Refunding excess payment +2026-09-30 11:10:38 INFO routstr.auth Refund processed successfully +2026-09-30 11:10:38 INFO routstr.payments FINALIZE +2026-09-30 11:10:38 INFO routstr.auth Payment settlement finished diff --git a/reservation-repro-main/dummy_upstream.py b/reservation-repro-main/dummy_upstream.py new file mode 100644 index 00000000..1be75ecc --- /dev/null +++ b/reservation-repro-main/dummy_upstream.py @@ -0,0 +1,45 @@ +"""Loopback-only streaming fixture; no router monkeypatches.""" +import asyncio +import json +import time +from fastapi import FastAPI, Request +from fastapi.responses import StreamingResponse + +app = FastAPI() +events = [] + +@app.get('/events') +async def history(): + return events + +@app.get('/v1/models') +async def models(): + return {'object': 'list', 'data': [{'id': 'gpt-4o-mini', 'object': 'model', 'created': 1, 'owned_by': 'repro'}]} + +@app.post('/v1/chat/completions') +async def completions(request: Request): + body = await request.json() + mode = body.get('messages', [{}])[0].get('content', 'finite') + events.append({'event': 'start', 'mode': mode, 'time': time.time()}) + if mode.startswith('header'): + await asyncio.sleep(3600) + async def stream(): + count = 0 + try: + while True: + if mode.startswith('keepalive'): + yield ': ping\n\n' + else: + chunk = {'id': 'repro', 'object': 'chat.completion.chunk', 'created': int(time.time()), 'model': 'gpt-4o-mini', 'choices': [{'index': 0, 'delta': {'content': 'x' * (65536 if mode.startswith('flood') else 1)}, 'finish_reason': None}]} + yield 'data: ' + json.dumps(chunk) + '\n\n' + count += 1 + if mode == 'finite' and count >= 3: + yield 'data: ' + json.dumps({'id': 'repro', 'object': 'chat.completion.chunk', 'model': 'gpt-4o-mini', 'choices': [], 'usage': {'prompt_tokens': 1, 'completion_tokens': count, 'total_tokens': count + 1}}) + '\n\n' + yield 'data: [DONE]\n\n' + return + await asyncio.sleep(3600 if mode.startswith('silent') else (0.001 if mode.startswith('flood') else 0.5)) + finally: + event = {'event': 'close', 'mode': mode, 'chunks': count, 'time': time.time()} + events.append(event) + print(json.dumps(event), flush=True) + return StreamingResponse(stream(), media_type='text/event-stream') diff --git a/reservation-repro-main/final-before-stop.json b/reservation-repro-main/final-before-stop.json new file mode 100644 index 00000000..4647ae85 --- /dev/null +++ b/reservation-repro-main/final-before-stop.json @@ -0,0 +1 @@ +{"time": 1790766635.1679196, "keys": [["main-finite", 0], ["main-silent", 0], ["main-silent-disconnect", 0], ["main-endless-disconnect", 11], ["main-keepalive", 11], ["main-flood", 11], ["main-header", 0]], "rows": [["main-flood", "active", 1790766634], ["main-keepalive", "active", 1790766634], ["main-endless-disconnect", "active", 1790766634], ["main-silent", "charged", 1790766368], ["main-silent-disconnect", "charged", 1790766368], ["main-header", "released", 1790766368], ["main-finite", "charged", 1790766366]]} diff --git a/reservation-repro-main/no_logging_app.py b/reservation-repro-main/no_logging_app.py new file mode 100644 index 00000000..16c4cdfc --- /dev/null +++ b/reservation-repro-main/no_logging_app.py @@ -0,0 +1,4 @@ +"""Diagnostic comparison ONLY: remove LoggingMiddleware from unchanged image app.""" +from routstr.core.main import app +from routstr.core.middleware import LoggingMiddleware +app.user_middleware = [m for m in app.user_middleware if m.cls is not LoggingMiddleware] diff --git a/reservation-repro-main/probe.py b/reservation-repro-main/probe.py new file mode 100644 index 00000000..57653e5e --- /dev/null +++ b/reservation-repro-main/probe.py @@ -0,0 +1,60 @@ +import asyncio +import json +import socket +import subprocess +import time +import httpx + +BASE='http://127.0.0.1:18090' + +def snapshot(): + code="import sqlite3,json,time; c=sqlite3.connect('/tmp/reserved-main.db'); c.row_factory=sqlite3.Row; print(json.dumps({'time':time.time(),'keys':[dict(r) for r in c.execute(\"select hashed_key,balance,reserved_balance,reserved_at from api_keys where hashed_key like 'main-%'\")],'rows':[dict(r) for r in c.execute(\"select * from reservation_releases where key_hash like 'main-%'\")]}))" + return json.loads(subprocess.check_output(['podman','exec','reserved-router-main','/.venv/bin/python','-c',code],text=True)) + +async def consume(mode): + try: + async with httpx.AsyncClient(timeout=None) as c: + async with c.stream('POST',BASE+'/v1/chat/completions',headers={'Authorization':'Bearer sk-main-'+mode},json={'model':'gpt-4o-mini','messages':[{'role':'user','content':mode}],'stream':True,'max_tokens':10}) as r: + print('STREAM',mode,r.status_code,flush=True) + async for _ in r.aiter_bytes(): pass + print('ENDED',mode,flush=True) + except asyncio.CancelledError: + print('CLIENT_DISCONNECTED',mode,flush=True) + raise + except Exception as e: + print('CLIENT_ERROR',mode,type(e).__name__,str(e),flush=True) + +async def report(label): + print(label,json.dumps(snapshot()),flush=True) + async with httpx.AsyncClient(timeout=5) as c: + for mode in ['silent-disconnect','endless-disconnect','keepalive','flood','header']: + # Only attempt payout while reserved: avoid requiring a real mint. + if next(k for k in snapshot()['keys'] if k['hashed_key']=='main-'+mode)['reserved_balance']: + r=await c.post(BASE+'/v1/wallet/refund',headers={'Authorization':'Bearer sk-main-'+mode}) + print('REFUND',mode,r.status_code,r.text,flush=True) + print('UPSTREAM_EVENTS',json.dumps((await c.get('http://127.0.0.1:18091/events')).json()),flush=True) + +async def main(): + modes=['finite','silent','silent-disconnect','endless-disconnect','keepalive','header'] + tasks={m:asyncio.create_task(consume(m)) for m in modes} + # Real client with a small receive buffer, never draining the HTTP response. + sock=socket.socket(); sock.setsockopt(socket.SOL_SOCKET,socket.SO_RCVBUF,1024); sock.connect(('127.0.0.1',18090)) + body=json.dumps({'model':'gpt-4o-mini','messages':[{'role':'user','content':'flood'}],'stream':True,'max_tokens':10}).encode() + sock.sendall(b'POST /v1/chat/completions HTTP/1.1\r\nHost: localhost\r\nAuthorization: Bearer sk-main-flood\r\nContent-Type: application/json\r\nContent-Length: '+str(len(body)).encode()+b'\r\n\r\n'+body) + await asyncio.sleep(1) + for m in ['silent-disconnect','endless-disconnect']: + tasks[m].cancel() + await asyncio.gather(tasks['silent-disconnect'],tasks['endless-disconnect'],return_exceptions=True) + await asyncio.sleep(9) + await report('AT_10_SECONDS') + await asyncio.sleep(60) + await report('AFTER_SWEEP') + sock.close() + tasks['keepalive'].cancel() + await asyncio.gather(tasks['keepalive'],return_exceptions=True) + await asyncio.sleep(8) + await report('AFTER_ALL_CLIENTS_CLOSED') + for task in tasks.values(): task.cancel() + await asyncio.gather(*tasks.values(),return_exceptions=True) + +asyncio.run(main()) diff --git a/reservation-repro-main/results.txt b/reservation-repro-main/results.txt new file mode 100644 index 00000000..7f21d733 --- /dev/null +++ b/reservation-repro-main/results.txt @@ -0,0 +1,27 @@ +STREAM keepalive 200 +STREAM endless-disconnect 200 +STREAM silent 200 +STREAM silent-disconnect 200 +STREAM finite 200 +CLIENT_DISCONNECTED silent-disconnect +CLIENT_DISCONNECTED endless-disconnect +ENDED finite +ENDED silent +STREAM header 424 +ENDED header +AT_10_SECONDS {"time": 1790766376.4572322, "keys": [{"hashed_key": "main-finite", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent-disconnect", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-endless-disconnect", "balance": 1000000000, "reserved_balance": 11, "reserved_at": 1790766366}, {"hashed_key": "main-keepalive", "balance": 1000000000, "reserved_balance": 11, "reserved_at": 1790766366}, {"hashed_key": "main-flood", "balance": 1000000000, "reserved_balance": 11, "reserved_at": 1790766366}, {"hashed_key": "main-header", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}], "rows": [{"id": "50569f573caf4d6fb7916da3570493db", "key_hash": "main-flood", "billing_key_hash": "main-flood", "reserved_msats": 11, "status": "active", "created_at": 1790766376}, {"id": "0ffb4d61dc0d4aaf9e518c74b7afd1bb", "key_hash": "main-keepalive", "billing_key_hash": "main-keepalive", "reserved_msats": 11, "status": "active", "created_at": 1790766376}, {"id": "66d5bdd9d9814f6fb1576ed6708f431e", "key_hash": "main-endless-disconnect", "billing_key_hash": "main-endless-disconnect", "reserved_msats": 11, "status": "active", "created_at": 1790766374}, {"id": "a891d80b8db64e488f8896936cd5f2fe", "key_hash": "main-silent", "billing_key_hash": "main-silent", "reserved_msats": 11, "status": "charged", "created_at": 1790766368}, {"id": "6ebb7f0829bd4f569d9d2516dabd9fed", "key_hash": "main-silent-disconnect", "billing_key_hash": "main-silent-disconnect", "reserved_msats": 11, "status": "charged", "created_at": 1790766368}, {"id": "e14358bc6e7249c0ac7335c9d87e7b43", "key_hash": "main-header", "billing_key_hash": "main-header", "reserved_msats": 11, "status": "released", "created_at": 1790766368}, {"id": "26c897009e294f94b75ca51f071d335a", "key_hash": "main-finite", "billing_key_hash": "main-finite", "reserved_msats": 11, "status": "charged", "created_at": 1790766366}]} +REFUND endless-disconnect 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"c272c298-bace-482c-926f-0c56fdaeaa5e"} +REFUND keepalive 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"3c1124f6-1c21-4417-b4fb-2ffdead58c31"} +REFUND flood 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"afca3cab-361a-48f6-85e9-58247c17a5f2"} +UPSTREAM_EVENTS [{"event": "start", "mode": "flood", "time": 1790766366.393702}, {"event": "start", "mode": "keepalive", "time": 1790766366.408879}, {"event": "start", "mode": "endless-disconnect", "time": 1790766366.4305305}, {"event": "start", "mode": "silent", "time": 1790766366.4564564}, {"event": "start", "mode": "silent-disconnect", "time": 1790766366.4789124}, {"event": "start", "mode": "header", "time": 1790766366.5032742}, {"event": "start", "mode": "finite", "time": 1790766366.5216281}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790766367.5249321}] +AFTER_SWEEP {"time": 1790766437.9892845, "keys": [{"hashed_key": "main-finite", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent-disconnect", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-endless-disconnect", "balance": 1000000000, "reserved_balance": 11, "reserved_at": 1790766366}, {"hashed_key": "main-keepalive", "balance": 1000000000, "reserved_balance": 11, "reserved_at": 1790766366}, {"hashed_key": "main-flood", "balance": 1000000000, "reserved_balance": 11, "reserved_at": 1790766366}, {"hashed_key": "main-header", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}], "rows": [{"id": "50569f573caf4d6fb7916da3570493db", "key_hash": "main-flood", "billing_key_hash": "main-flood", "reserved_msats": 11, "status": "active", "created_at": 1790766436}, {"id": "0ffb4d61dc0d4aaf9e518c74b7afd1bb", "key_hash": "main-keepalive", "billing_key_hash": "main-keepalive", "reserved_msats": 11, "status": "active", "created_at": 1790766436}, {"id": "66d5bdd9d9814f6fb1576ed6708f431e", "key_hash": "main-endless-disconnect", "billing_key_hash": "main-endless-disconnect", "reserved_msats": 11, "status": "active", "created_at": 1790766436}, {"id": "a891d80b8db64e488f8896936cd5f2fe", "key_hash": "main-silent", "billing_key_hash": "main-silent", "reserved_msats": 11, "status": "charged", "created_at": 1790766368}, {"id": "6ebb7f0829bd4f569d9d2516dabd9fed", "key_hash": "main-silent-disconnect", "billing_key_hash": "main-silent-disconnect", "reserved_msats": 11, "status": "charged", "created_at": 1790766368}, {"id": "e14358bc6e7249c0ac7335c9d87e7b43", "key_hash": "main-header", "billing_key_hash": "main-header", "reserved_msats": 11, "status": "released", "created_at": 1790766368}, {"id": "26c897009e294f94b75ca51f071d335a", "key_hash": "main-finite", "billing_key_hash": "main-finite", "reserved_msats": 11, "status": "charged", "created_at": 1790766366}]} +REFUND endless-disconnect 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"4a00cdce-d049-4be8-940f-2a652349c1f9"} +REFUND keepalive 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"bcf3b7d4-ae59-494c-8049-bb43476211e8"} +REFUND flood 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"4b459580-84d1-480a-b1cb-28898a04395e"} +UPSTREAM_EVENTS [{"event": "start", "mode": "flood", "time": 1790766366.393702}, {"event": "start", "mode": "keepalive", "time": 1790766366.408879}, {"event": "start", "mode": "endless-disconnect", "time": 1790766366.4305305}, {"event": "start", "mode": "silent", "time": 1790766366.4564564}, {"event": "start", "mode": "silent-disconnect", "time": 1790766366.4789124}, {"event": "start", "mode": "header", "time": 1790766366.5032742}, {"event": "start", "mode": "finite", "time": 1790766366.5216281}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790766367.5249321}] +CLIENT_DISCONNECTED keepalive +AFTER_ALL_CLIENTS_CLOSED {"time": 1790766447.4688976, "keys": [{"hashed_key": "main-finite", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent-disconnect", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-endless-disconnect", "balance": 1000000000, "reserved_balance": 11, "reserved_at": 1790766366}, {"hashed_key": "main-keepalive", "balance": 1000000000, "reserved_balance": 11, "reserved_at": 1790766366}, {"hashed_key": "main-flood", "balance": 1000000000, "reserved_balance": 11, "reserved_at": 1790766366}, {"hashed_key": "main-header", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}], "rows": [{"id": "50569f573caf4d6fb7916da3570493db", "key_hash": "main-flood", "billing_key_hash": "main-flood", "reserved_msats": 11, "status": "active", "created_at": 1790766447}, {"id": "0ffb4d61dc0d4aaf9e518c74b7afd1bb", "key_hash": "main-keepalive", "billing_key_hash": "main-keepalive", "reserved_msats": 11, "status": "active", "created_at": 1790766446}, {"id": "66d5bdd9d9814f6fb1576ed6708f431e", "key_hash": "main-endless-disconnect", "billing_key_hash": "main-endless-disconnect", "reserved_msats": 11, "status": "active", "created_at": 1790766446}, {"id": "a891d80b8db64e488f8896936cd5f2fe", "key_hash": "main-silent", "billing_key_hash": "main-silent", "reserved_msats": 11, "status": "charged", "created_at": 1790766368}, {"id": "6ebb7f0829bd4f569d9d2516dabd9fed", "key_hash": "main-silent-disconnect", "billing_key_hash": "main-silent-disconnect", "reserved_msats": 11, "status": "charged", "created_at": 1790766368}, {"id": "e14358bc6e7249c0ac7335c9d87e7b43", "key_hash": "main-header", "billing_key_hash": "main-header", "reserved_msats": 11, "status": "released", "created_at": 1790766368}, {"id": "26c897009e294f94b75ca51f071d335a", "key_hash": "main-finite", "billing_key_hash": "main-finite", "reserved_msats": 11, "status": "charged", "created_at": 1790766366}]} +REFUND endless-disconnect 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"67367fbb-2fd6-4ce7-a0e3-3b1d0f30cb76"} +REFUND keepalive 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"96f8b70c-584e-476d-aa9c-ea9092e9393f"} +REFUND flood 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"60ac9762-dc92-4e08-9456-77346a70a63d"} +UPSTREAM_EVENTS [{"event": "start", "mode": "flood", "time": 1790766366.393702}, {"event": "start", "mode": "keepalive", "time": 1790766366.408879}, {"event": "start", "mode": "endless-disconnect", "time": 1790766366.4305305}, {"event": "start", "mode": "silent", "time": 1790766366.4564564}, {"event": "start", "mode": "silent-disconnect", "time": 1790766366.4789124}, {"event": "start", "mode": "header", "time": 1790766366.5032742}, {"event": "start", "mode": "finite", "time": 1790766366.5216281}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790766367.5249321}] diff --git a/reservation-repro-main/router.log b/reservation-repro-main/router.log new file mode 100644 index 00000000..f2e7c738 --- /dev/null +++ b/reservation-repro-main/router.log @@ -0,0 +1,114 @@ +/.venv/lib/python3.14/site-packages/anyio/from_thread.py:119: SyntaxWarning: 'return' in a 'finally' block + return result +2026-09-30 11:05:28 WARNING routstr.core.main UI dist directory not found at /app/ui_out; serving API only. Run `make ui-build` to build the static UI served from here, or `make ui-dev` for the Next.js dev server with hot reload on :3000 (it targets this backend on :8000). +2026-09-30 11:05:28 INFO uvicorn.error Started server process [1] +2026-09-30 11:05:28 INFO uvicorn.error Waiting for application startup. +2026-09-30 11:05:28 INFO routstr.core.main Application startup initiated +2026-09-30 11:05:30 INFO routstr.core.db Database migrations completed successfully +2026-09-30 11:05:30 INFO routstr.core.db Reset reserved balances on startup +2026-09-30 11:05:30 INFO routstr.upstream.helpers Seeding custom provider +2026-09-30 11:05:30 INFO routstr.upstream.helpers Seeded 1 upstream providers from settings +2026-09-30 11:05:31 INFO routstr.proxy Initialized 1 upstream providers +2026-09-30 11:05:31 INFO routstr.nostr.listing Nostr private key not configured (NSEC); waiting for one to be set before announcing this provider +2026-09-30 11:05:31 INFO routstr.nostr.analytics Usage analytics sharing task started +2026-09-30 11:05:31 INFO routstr.nostr.analytics NSEC is not configured; skipping analytics sharing to Nostr +2026-09-30 11:05:31 INFO routstr.auth Dead-key pruning disabled (interval <= 0) +2026-09-30 11:05:31 INFO uvicorn.error Application startup complete. +2026-09-30 11:05:31 INFO uvicorn.error Uvicorn running on http://127.0.0.1:18090 (Press CTRL+C to quit) +2026-09-30 11:06:01 INFO routstr.upstream.auto_topup Auto top-up worker started +2026-09-30 11:06:06 INFO routstr.auth Existing sk- API key found +2026-09-30 11:06:06 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:06:06 INFO routstr.auth Processing payment for request +2026-09-30 11:06:06 INFO routstr.auth Existing sk- API key found +2026-09-30 11:06:06 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:06:06 INFO routstr.auth Processing payment for request +2026-09-30 11:06:06 INFO routstr.auth Existing sk- API key found +2026-09-30 11:06:06 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:06:06 INFO routstr.auth Processing payment for request +2026-09-30 11:06:06 INFO routstr.auth Existing sk- API key found +2026-09-30 11:06:06 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:06:06 INFO routstr.auth Processing payment for request +2026-09-30 11:06:06 INFO routstr.auth Existing sk- API key found +2026-09-30 11:06:06 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:06:06 INFO routstr.auth Processing payment for request +2026-09-30 11:06:06 INFO routstr.auth Existing sk- API key found +2026-09-30 11:06:06 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:06:06 INFO routstr.auth Processing payment for request +2026-09-30 11:06:06 INFO routstr.auth Existing sk- API key found +2026-09-30 11:06:06 INFO routstr.proxy Bearer token validated successfully +2026-09-30 11:06:06 INFO routstr.auth Processing payment for request +2026-09-30 11:06:06 INFO routstr.auth Payment processed successfully +2026-09-30 11:06:06 INFO routstr.payments RESERVE +2026-09-30 11:06:06 INFO routstr.auth Payment processed successfully +2026-09-30 11:06:06 INFO routstr.payments RESERVE +2026-09-30 11:06:06 INFO routstr.auth Payment processed successfully +2026-09-30 11:06:06 INFO routstr.payments RESERVE +2026-09-30 11:06:06 INFO routstr.auth Payment processed successfully +2026-09-30 11:06:06 INFO routstr.payments RESERVE +2026-09-30 11:06:06 INFO routstr.auth Payment processed successfully +2026-09-30 11:06:06 INFO routstr.payments RESERVE +2026-09-30 11:06:06 INFO routstr.auth Payment processed successfully +2026-09-30 11:06:06 INFO routstr.payments RESERVE +2026-09-30 11:06:06 INFO routstr.auth Payment processed successfully +2026-09-30 11:06:06 INFO routstr.payments RESERVE +2026-09-30 11:06:07 INFO routstr.payment.cost_calculation Applied model-specific pricing +2026-09-30 11:06:07 INFO routstr.payment.cost_calculation Calculated token-based cost +2026-09-30 11:06:07 INFO routstr.auth Calculated token-based cost +2026-09-30 11:06:07 INFO routstr.auth Refunding excess payment +2026-09-30 11:06:07 INFO routstr.auth Refund processed successfully +2026-09-30 11:06:07 INFO routstr.payments FINALIZE +2026-09-30 11:06:07 INFO routstr.auth Payment settlement finished +2026-09-30 11:06:09 WARNING routstr.upstream.base Streaming interrupted; finalizing before closing upstream +2026-09-30 11:06:09 INFO routstr.payment.cost_calculation Applied model-specific pricing +2026-09-30 11:06:09 INFO routstr.payment.cost_calculation Calculated token-based cost +2026-09-30 11:06:09 INFO routstr.auth Calculated token-based cost +2026-09-30 11:06:09 INFO routstr.auth Refunding excess payment +2026-09-30 11:06:09 WARNING routstr.upstream.base Streaming interrupted; finalizing before closing upstream +2026-09-30 11:06:09 INFO routstr.auth Refund processed successfully +2026-09-30 11:06:09 INFO routstr.payment.cost_calculation Applied model-specific pricing +2026-09-30 11:06:09 INFO routstr.payment.cost_calculation Calculated token-based cost +2026-09-30 11:06:09 INFO routstr.auth Calculated token-based cost +2026-09-30 11:06:09 INFO routstr.auth Refunding excess payment +2026-09-30 11:06:09 ERROR routstr.upstream.base HTTP request error to upstream +2026-09-30 11:06:09 WARNING routstr.proxy Upstream base failed for model=gpt-4o-mini: Upstream service request timed out +2026-09-30 11:06:09 INFO routstr.auth Refund processed successfully +2026-09-30 11:06:09 INFO routstr.payments FINALIZE +2026-09-30 11:06:09 INFO routstr.auth Payment settlement finished +2026-09-30 11:06:09 ERROR routstr.core.exceptions Unhandled exception +httpcore.ReadTimeout + +The above exception was the direct cause of the following exception: + +httpx.ReadTimeout +2026-09-30 11:06:09 ERROR uvicorn.error Exception in ASGI application +httpcore.ReadTimeout + +The above exception was the direct cause of the following exception: + +httpx.ReadTimeout +2026-09-30 11:06:09 INFO routstr.payments FINALIZE +2026-09-30 11:06:09 INFO routstr.auth Payment settlement finished +2026-09-30 11:06:09 ERROR routstr.core.exceptions Unhandled exception +httpcore.ReadTimeout + +The above exception was the direct cause of the following exception: + +httpx.ReadTimeout +2026-09-30 11:06:09 ERROR uvicorn.error Exception in ASGI application +httpcore.ReadTimeout + +The above exception was the direct cause of the following exception: + +httpx.ReadTimeout +2026-09-30 11:06:16 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. +2026-09-30 11:06:17 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. +2026-09-30 11:06:17 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. +2026-09-30 11:07:18 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. +2026-09-30 11:07:18 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. +2026-09-30 11:07:19 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. +2026-09-30 11:07:28 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. +2026-09-30 11:07:28 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. +2026-09-30 11:07:28 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. +2026-09-30 11:10:38 WARNING routstr.upstream.base Upstream stream ended before the response was complete +2026-09-30 11:10:38 WARNING routstr.upstream.base Upstream stream ended before the response was complete +2026-09-30 11:10:38 WARNING routstr.upstream.base Upstream stream ended before the response was complete diff --git a/reservation-repro-main/starlette-source.txt b/reservation-repro-main/starlette-source.txt new file mode 100644 index 00000000..78736b3f --- /dev/null +++ b/reservation-repro-main/starlette-source.txt @@ -0,0 +1,169 @@ + async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None: + if scope["type"] != "http": + await self.app(scope, receive, send) + return + + request = _CachedRequest(scope, receive) + wrapped_receive = request.wrapped_receive + response_sent = anyio.Event() + app_exc: Exception | None = None + exception_already_raised = False + + async def call_next(request: Request) -> Response: + async def receive_or_disconnect() -> Message: + if response_sent.is_set(): + return {"type": "http.disconnect"} + + async with anyio.create_task_group() as task_group: + + async def wrap(func: Callable[[], Awaitable[T]]) -> T: + result = await func() + task_group.cancel_scope.cancel() + return result + + task_group.start_soon(wrap, response_sent.wait) + message = await wrap(wrapped_receive) + + if response_sent.is_set(): + return {"type": "http.disconnect"} + + return message + + async def send_no_error(message: Message) -> None: + try: + await send_stream.send(message) + except anyio.BrokenResourceError: + # recv_stream has been closed, i.e. response_sent has been set. + return + + async def coro() -> None: + nonlocal app_exc + + with send_stream: + try: + await self.app(scope, receive_or_disconnect, send_no_error) + except Exception as exc: + app_exc = exc + + task_group.start_soon(coro) + + try: + message = await recv_stream.receive() + info = message.get("info", None) + if message["type"] == "http.response.debug" and info is not None: + message = await recv_stream.receive() + except anyio.EndOfStream: + if app_exc is not None: + nonlocal exception_already_raised + exception_already_raised = True + # Prevent `anyio.EndOfStream` from polluting app exception context. + # If both cause and context are None then the context is suppressed + # and `anyio.EndOfStream` is not present in the exception traceback. + # If exception cause is not None then it is propagated with + # reraising here. + # If exception has no cause but has context set then the context is + # propagated as a cause with the reraise. This is necessary in order + # to prevent `anyio.EndOfStream` from polluting the exception + # context. + raise app_exc from app_exc.__cause__ or app_exc.__context__ + raise RuntimeError("No response returned.") + + assert message["type"] == "http.response.start" + + async def body_stream() -> BodyStreamGenerator: + async for message in recv_stream: + if message["type"] == "http.response.pathsend": + yield message + break + assert message["type"] == "http.response.body", f"Unexpected message: {message}" + body = message.get("body", b"") + if body: + yield body + if not message.get("more_body", False): + break + + response = _StreamingResponse(status_code=message["status"], content=body_stream(), info=info) + response.raw_headers = message["headers"] + return response + + streams: anyio.create_memory_object_stream[Message] = anyio.create_memory_object_stream() + send_stream, recv_stream = streams + with recv_stream, send_stream: + async with create_collapsing_task_group() as task_group: + response = await self.dispatch_func(request, call_next) + await response(scope, wrapped_receive, send) + response_sent.set() + recv_stream.close() + if app_exc is not None and not exception_already_raised: + raise app_exc + +class _StreamingResponse(Response): + def __init__( + self, + content: AsyncContentStream, + status_code: int = 200, + headers: Mapping[str, str] | None = None, + media_type: str | None = None, + info: Mapping[str, Any] | None = None, + ) -> None: + self.info = info + self.body_iterator = content + self.status_code = status_code + self.media_type = media_type + self.init_headers(headers) + self.background = None + + async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None: + if self.info is not None: + await send({"type": "http.response.debug", "info": self.info}) + await send( + { + "type": "http.response.start", + "status": self.status_code, + "headers": self.raw_headers, + } + ) + + should_close_body = True + async for chunk in self.body_iterator: + if isinstance(chunk, dict): + # We got an ASGI message which is not response body (eg: pathsend) + should_close_body = False + await send(chunk) + continue + await send({"type": "http.response.body", "body": chunk, "more_body": True}) + + if should_close_body: + await send({"type": "http.response.body", "body": b"", "more_body": False}) + + if self.background: + await self.background() + + async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None: + if scope["type"] == "websocket": + send = self._wrap_websocket_denial_send(send) + await self.stream_response(send) + if self.background is not None: + await self.background() + return + + spec_version = tuple(map(int, scope.get("asgi", {}).get("spec_version", "2.0").split("."))) + + if spec_version >= (2, 4): + try: + await self.stream_response(send) + except OSError: + raise ClientDisconnect() + else: + async with create_collapsing_task_group() as task_group: + + async def wrap(func: Callable[[], Awaitable[None]]) -> None: + await func() + task_group.cancel_scope.cancel() + + task_group.start_soon(wrap, partial(self.stream_response, send)) + await wrap(partial(self.listen_for_disconnect, receive)) + + if self.background is not None: + await self.background() + diff --git a/reservation-repro-main/upstream.log b/reservation-repro-main/upstream.log new file mode 100644 index 00000000..2f124bcd --- /dev/null +++ b/reservation-repro-main/upstream.log @@ -0,0 +1,23 @@ +/.venv/lib/python3.14/site-packages/anyio/from_thread.py:119: SyntaxWarning: 'return' in a 'finally' block + return result +INFO: Started server process [1] +INFO: Waiting for application startup. +INFO: Application startup complete. +INFO: Uvicorn running on http://127.0.0.1:18091 (Press CTRL+C to quit) +INFO: 127.0.0.1:59686 - "GET /v1/models HTTP/1.1" 200 OK +INFO: 127.0.0.1:36380 - "POST /v1/chat/completions HTTP/1.1" 200 OK +INFO: 127.0.0.1:36394 - "POST /v1/chat/completions HTTP/1.1" 200 OK +INFO: 127.0.0.1:36402 - "POST /v1/chat/completions HTTP/1.1" 200 OK +INFO: 127.0.0.1:36418 - "POST /v1/chat/completions HTTP/1.1" 200 OK +INFO: 127.0.0.1:36434 - "POST /v1/chat/completions HTTP/1.1" 200 OK +INFO: 127.0.0.1:36456 - "POST /v1/chat/completions HTTP/1.1" 200 OK +{"event": "close", "mode": "finite", "chunks": 3, "time": 1790766367.5249321} +INFO: 127.0.0.1:54322 - "GET /events HTTP/1.1" 200 OK +INFO: 127.0.0.1:51770 - "GET /events HTTP/1.1" 200 OK +INFO: 127.0.0.1:42140 - "GET /events HTTP/1.1" 200 OK +INFO: 127.0.0.1:50608 - "GET /v1/models HTTP/1.1" 200 OK +INFO: 127.0.0.1:46164 - "POST /v1/chat/completions HTTP/1.1" 200 OK +INFO: 127.0.0.1:46178 - "POST /v1/chat/completions HTTP/1.1" 200 OK +INFO: 127.0.0.1:39728 - "GET /events HTTP/1.1" 200 OK +INFO: Shutting down +INFO: Waiting for connections to close. (CTRL+C to force quit) diff --git a/reservation-repro-main/uvicorn-source.txt b/reservation-repro-main/uvicorn-source.txt new file mode 100644 index 00000000..2c5d74b3 --- /dev/null +++ b/reservation-repro-main/uvicorn-source.txt @@ -0,0 +1,125 @@ + async def send(self, message: ASGISendEvent) -> None: + message_type = message["type"] + + if self.flow.write_paused and not self.disconnected: + await self.flow.drain() # pragma: full coverage + + if self.disconnected: + return # pragma: full coverage + + if not self.response_started: + # Sending response status line and headers + if message_type != "http.response.start": + msg = "Expected ASGI message 'http.response.start', but got '%s'." + raise RuntimeError(msg % message_type) + message = cast("HTTPResponseStartEvent", message) + + self.response_started = True + self.waiting_for_100_continue = False + + status_code = message["status"] + headers = self.default_headers + list(message.get("headers", [])) + + if CLOSE_HEADER in self.scope["headers"] and CLOSE_HEADER not in headers: + headers = headers + [CLOSE_HEADER] + + if self.access_log: + self.access_logger.info( + '%s - "%s %s HTTP/%s" %d', + get_client_addr(self.scope), + self.scope["method"], + get_path_with_query_string(self.scope), + self.scope["http_version"], + status_code, + ) + + # Write response status line and headers + content = [STATUS_LINE[status_code]] + + for name, value in headers: + if HEADER_RE.search(name): + raise RuntimeError("Invalid HTTP header name.") # pragma: full coverage + if HEADER_VALUE_RE.search(value): + raise RuntimeError("Invalid HTTP header value.") + + name = name.lower() + if name == b"content-length" and self.chunked_encoding is None: + self.expected_content_length = int(value.decode()) + self.chunked_encoding = False + elif name == b"transfer-encoding" and value.lower() == b"chunked": + self.expected_content_length = 0 + self.chunked_encoding = True + elif name == b"connection" and value.lower() == b"close": + self.keep_alive = False + content.extend([name, b": ", value, b"\r\n"]) + + if self.chunked_encoding is None and self.scope["method"] != "HEAD" and status_code not in (204, 304): + # Neither content-length nor transfer-encoding specified + self.chunked_encoding = True + content.append(b"transfer-encoding: chunked\r\n") + + content.append(b"\r\n") + self.transport.write(b"".join(content)) + + elif not self.response_complete: + # Sending response body + if message_type != "http.response.body": + msg = "Expected ASGI message 'http.response.body', but got '%s'." + raise RuntimeError(msg % message_type) + + body = cast(bytes, message.get("body", b"")) + more_body = message.get("more_body", False) + + # Write response body + if self.scope["method"] == "HEAD": + self.expected_content_length = 0 + elif self.chunked_encoding: + if body: + content = [b"%x\r\n" % len(body), body, b"\r\n"] + else: + content = [] + if not more_body: + content.append(b"0\r\n\r\n") + self.transport.write(b"".join(content)) + else: + num_bytes = len(body) + if num_bytes > self.expected_content_length: + raise RuntimeError("Response content longer than Content-Length") + else: + self.expected_content_length -= num_bytes + self.transport.write(body) + + # Handle response completion + if not more_body: + if self.expected_content_length != 0: + raise RuntimeError("Response content shorter than Content-Length") + self.response_complete = True + self.message_event.set() + if not self.keep_alive: + self.transport.close() + self.on_response() + + else: + # Response already sent + msg = "Unexpected ASGI message '%s' sent, after response already completed." + raise RuntimeError(msg % message_type) + + def connection_lost(self, exc: Exception | None) -> None: + self.connections.discard(self) + + if self.logger.level <= TRACE_LOG_LEVEL: + prefix = "%s:%d - " % self.client if self.client else "" + self.logger.log(TRACE_LOG_LEVEL, "%sHTTP connection lost", prefix) + + if self.cycle and not self.cycle.response_complete: + self.cycle.disconnected = True + if self.cycle is not None: + self.cycle.message_event.set() + if self.flow is not None: + self.flow.resume_writing() + if exc is None: + self.transport.close() + self._unset_keepalive_if_required() + + self.parser = None + From 368ce4247e9cc2751ddceb178d1feb55cd11f068 Mon Sep 17 00:00:00 2001 From: redshift <213178690+1ftredsh@users.noreply.github.com> Date: Wed, 30 Sep 2026 20:29:18 +0800 Subject: [PATCH 3/5] fix: satisfy mypy for ASGI app awaitable in lifecycle middleware ASGIApp.__call__ is typed as returning Awaitable[None], not a Coroutine, so asyncio.create_task rejected it. asyncio.ensure_future accepts any awaitable and returns a Future, which supports every operation the middleware uses (cancel, done, exception, asyncio.wait, await). --- routstr/core/lifecycle.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/routstr/core/lifecycle.py b/routstr/core/lifecycle.py index 897df5b7..dad968ba 100644 --- a/routstr/core/lifecycle.py +++ b/routstr/core/lifecycle.py @@ -82,7 +82,9 @@ class RequestLifecycleMiddleware: response_started = True receiver = asyncio.create_task(pump()) - work = asyncio.create_task(self.app(scope, downstream_receive, downstream_send)) + work: asyncio.Future[None] = asyncio.ensure_future( + self.app(scope, downstream_receive, downstream_send) + ) gone = asyncio.create_task(disconnected.wait()) try: done, _ = await asyncio.wait( From 2b24342a7242acef9849e77e107d5e1ff8c51ed8 Mon Sep 17 00:00:00 2001 From: redshift <213178690+1ftredsh@users.noreply.github.com> Date: Wed, 30 Sep 2026 21:56:21 +0800 Subject: [PATCH 4/5] ci: exclude temporary repro artifacts from ruff/mypy, type new lifecycle test The investigation artifacts under repro/ and reservation-repro-main/ are deliberately kept for review but fail ruff and mypy, and the two directories both define dummy_upstream.py, which makes 'mypy .' abort with a duplicate-module error. Exclude them (mirroring examples/) via ruff extend-exclude and a mypy exclude, and fix the newly-surfaced mypy errors in tests/unit/test_request_lifecycle.py by annotating it. The previous [tool.ruff.lint] exclude was not applied; move it to [tool.ruff] extend-exclude so defaults are preserved. --- pyproject.toml | 5 ++++- tests/unit/test_request_lifecycle.py | 13 +++++++------ 2 files changed, 11 insertions(+), 7 deletions(-) diff --git a/pyproject.toml b/pyproject.toml index 296fab3f..1faf6828 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -72,10 +72,12 @@ build-backend = "setuptools.build_meta" [tool.setuptools] packages = ["routstr"] +[tool.ruff] +extend-exclude = ["examples", "repro", "reservation-repro-main"] + [tool.ruff.lint] select = ["E", "F", "I"] ignore = ["E501"] -exclude = ["examples"] [tool.mypy] python_version = "3.11" @@ -85,6 +87,7 @@ check_untyped_defs = true disallow_untyped_calls = true disallow_incomplete_defs = true disallow_untyped_decorators = true +exclude = ["^repro/", "^reservation-repro-main/"] [tool.uv.sources] routstr = { workspace = true } diff --git a/tests/unit/test_request_lifecycle.py b/tests/unit/test_request_lifecycle.py index 03cf9897..41c76e50 100644 --- a/tests/unit/test_request_lifecycle.py +++ b/tests/unit/test_request_lifecycle.py @@ -2,6 +2,7 @@ import asyncio from unittest.mock import patch import pytest +from starlette.types import Message, Receive, Scope, Send from routstr.core.lifecycle import RequestLifecycleMiddleware from routstr.core.settings import settings @@ -9,13 +10,13 @@ from routstr.core.settings import settings @pytest.mark.asyncio @pytest.mark.parametrize("reason", ["disconnect", "deadline", "send"]) -async def test_lifecycle_stops_live_work(reason): +async def test_lifecycle_stops_live_work(reason: str) -> None: closed = asyncio.Event() - receive_queue = asyncio.Queue() + receive_queue: asyncio.Queue[Message] = asyncio.Queue() await receive_queue.put({"type": "http.request", "body": b"", "more_body": False}) - sent = [] + sent: list[Message] = [] - async def app(scope, receive, send): + async def app(scope: Scope, receive: Receive, send: Send) -> None: try: assert (await receive())["type"] == "http.request" await send({"type": "http.response.start", "status": 200, "headers": []}) @@ -27,12 +28,12 @@ async def test_lifecycle_stops_live_work(reason): finally: closed.set() - async def send(message): + async def send(message: Message) -> None: sent.append(message) if reason == "send" and message["type"] == "http.response.body": await asyncio.sleep(100) - async def disconnect(): + async def disconnect() -> None: await asyncio.sleep(0.02) await receive_queue.put({"type": "http.disconnect"}) From 53a4f3216ca25981fbdb82ca91c9a961da5be03f Mon Sep 17 00:00:00 2001 From: 9qeklajc Date: Wed, 30 Sep 2026 21:47:47 +0200 Subject: [PATCH 5/5] fix: let stream finalizers settle billing and remove repro artifacts --- .env.example | 6 + RESERVED_BALANCE.md | 541 ------------------ pyproject.toml | 3 +- repro/IMPLEMENTATION.md | 46 -- repro/dummy_upstream.py | 45 -- repro/probe.py | 60 -- repro/results-final.txt | 19 - repro/results.txt | 19 - repro/router-final.log | 108 ---- repro/router-first.log | 115 ---- reservation-repro-main/README.md | 106 ---- .../after-upstream-stop.json | 1 - reservation-repro-main/connections.txt | 7 - reservation-repro-main/control-results.txt | 5 - reservation-repro-main/control-router.log | 43 -- reservation-repro-main/dummy_upstream.py | 45 -- reservation-repro-main/final-before-stop.json | 1 - reservation-repro-main/no_logging_app.py | 4 - reservation-repro-main/probe.py | 60 -- reservation-repro-main/results.txt | 27 - reservation-repro-main/router.log | 114 ---- reservation-repro-main/starlette-source.txt | 169 ------ reservation-repro-main/upstream.log | 23 - reservation-repro-main/uvicorn-source.txt | 125 ---- routstr/auth.py | 11 +- routstr/core/lifecycle.py | 63 +- tests/unit/test_request_lifecycle.py | 227 ++++++++ tests/unit/test_stale_reservations.py | 30 +- 28 files changed, 298 insertions(+), 1725 deletions(-) delete mode 100644 RESERVED_BALANCE.md delete mode 100644 repro/IMPLEMENTATION.md delete mode 100644 repro/dummy_upstream.py delete mode 100644 repro/probe.py delete mode 100644 repro/results-final.txt delete mode 100644 repro/results.txt delete mode 100644 repro/router-final.log delete mode 100644 repro/router-first.log delete mode 100644 reservation-repro-main/README.md delete mode 100644 reservation-repro-main/after-upstream-stop.json delete mode 100644 reservation-repro-main/connections.txt delete mode 100644 reservation-repro-main/control-results.txt delete mode 100644 reservation-repro-main/control-router.log delete mode 100644 reservation-repro-main/dummy_upstream.py delete mode 100644 reservation-repro-main/final-before-stop.json delete mode 100644 reservation-repro-main/no_logging_app.py delete mode 100644 reservation-repro-main/probe.py delete mode 100644 reservation-repro-main/results.txt delete mode 100644 reservation-repro-main/router.log delete mode 100644 reservation-repro-main/starlette-source.txt delete mode 100644 reservation-repro-main/upstream.log delete mode 100644 reservation-repro-main/uvicorn-source.txt diff --git a/.env.example b/.env.example index 5688f6c3..e79b7770 100644 --- a/.env.example +++ b/.env.example @@ -72,6 +72,12 @@ ROUTSTR_SECRET_KEY= # UPSTREAM_POOL_TIMEOUT=5 # UPSTREAM_READ_TIMEOUT=900 +# Request and reservation lifetime limits (seconds) +# STALE_RESERVATION_TIMEOUT_SECONDS=300 +# MAX_REQUEST_LIFETIME_SECONDS=1800 +# DOWNSTREAM_SEND_TIMEOUT_SECONDS=60 +# REQUEST_CLEANUP_TIMEOUT_SECONDS=30 + # Logging # LOG_LEVEL=INFO # ENABLE_CONSOLE_LOGGING=true diff --git a/RESERVED_BALANCE.md b/RESERVED_BALANCE.md deleted file mode 100644 index a7417bc4..00000000 --- a/RESERVED_BALANCE.md +++ /dev/null @@ -1,541 +0,0 @@ -# Reserved balance blocks refunds long after the last request - -## Reported issue - -A client attempting to refund an API key receives: - -> Cannot refund key. There are ongoing requests for this api key. - -The user reports that the key has not been used in a very long time, potentially days. This is not a refund racing with normal request completion. The expected behavior is that reservations left by disconnected, crashed, abandoned, or failed requests eventually expire and the key becomes refundable. - -The error does **not** prove that an upstream inference request is running. In the current implementation, it means the refund endpoint still sees a positive aggregate `reserved_balance` after attempting stale-reservation cleanup. - -This document records a source-code investigation of the current checkout. The affected node's database, logs, runtime tasks, effective configuration, and deployed version have not been inspected. The production root cause remains unconfirmed. - -## Investigation scope and results - -Checkout inspected: `96c8e2f7` (`Merge pull request #790 from Routstr/fix/rename-unsupported-param`). - -The existing cleanup system is implemented and wired into application startup. It protects several important accounting invariants, but it is based on renewable reservation leases rather than a hard maximum request lifetime. - -Verification command: - -```bash -.venv/bin/pytest \ - tests/unit/test_stale_reservations.py \ - tests/unit/test_streaming_billing_finalization.py \ - tests/integration/test_negative_available_balance_repro.py -q -``` - -Result: **59 passed in 10.04 seconds**. - -These passing tests verify existing recovery paths; they do not establish what happened on the affected node or demonstrate recovery from every kind of live-but-hung task. No implementation changes were made during this investigation. - -## Reservation lifecycle - -### 1. Reserve before forwarding - -`pay_for_request()` in `routstr/auth.py` reserves funds before dispatching the billed request upstream. - -It creates a durable `ReservationRelease` identity containing: - -- `id`: the individual reservation identity; -- `key_hash`: the request's key; -- `billing_key_hash`: the key whose balance backs the request; -- `reserved_msats`: the amount owned by this reservation; -- `status`: initially `active`; -- `created_at`: initially the current timestamp. - -The aggregate reserved balance and durable reservation row commit together. The request's reservation identity matters: releasing one request must not erase funds reserved by another concurrent request. - -`ApiKey.reserved_at` is also stamped when funds are reserved. It is an aggregate timestamp, not an independent timestamp for each request. - -### 2. Renew while the owner task remains alive - -`_start_reservation_heartbeat()` in `routstr/auth.py` starts a task for each reservation. Its interval is: - -```python -max(1, settings.stale_reservation_timeout_seconds // 3) -``` - -With the default timeout of 300 seconds, renewal occurs approximately every 100 seconds. - -The heartbeat captures `asyncio.current_task()` as the owner. At each iteration it checks: - -```python -if owner is None or owner.done(): - return -``` - -If the owner is still alive, it calls `renew_reservation()` using a separate database session. Renewal updates the active durable row's `created_at` to the current time. - -Important consequences: - -- Renewal depends on task lifetime, not demonstrated request progress. -- There is no original-age limit in this heartbeat. -- `created_at` is overwritten, so it actually serves as a renewable lease timestamp. -- An owner that has finished cannot keep renewing indefinitely through this heartbeat. -- An owner that is blocked indefinitely may keep renewing indefinitely. - -### 3. Settle or release - -Normal completion settles the charge and releases the reservation. Handled upstream failures revert the reservation. Terminal reservation transitions stop the heartbeat. - -The proxy includes cancellation cleanup. Streaming paths use finalizers and ownership wrappers to improve cleanup across cancellation and downstream-send failures. Relevant code includes: - -- `routstr/auth.py`; -- `routstr/proxy.py`; -- `routstr/upstream/base.py`; -- `routstr/upstream/stream_ownership.py`. - -If a request dies without completing cleanup, its heartbeat is intended to stop once the owning task is done. The reservation can then age out and be released by the sweeper. - -## Existing cleanup mechanisms - -### Background sweep - -`periodic_stale_reservation_sweep()` in `routstr/auth.py` is started by the application lifespan in `routstr/core/main.py`. - -Defaults: - -| Setting/mechanism | Default | Meaning | -| --- | --- | --- | -| `STALE_RESERVATION_TIMEOUT_SECONDS` | 300 seconds | Maximum age of an unrenewed reservation lease before it is stale | -| `STALE_RESERVATION_SWEEP_INTERVAL_SECONDS` | 60 seconds | Interval between background cleanup passes | -| Heartbeat interval | 100 seconds | Approximately one third of the stale timeout | -| `UPSTREAM_READ_TIMEOUT` | 900 seconds | Upstream HTTP read inactivity timeout, not a total request deadline | -| `RESET_RESERVED_BALANCE_ON_STARTUP` | `True` | Explicit startup reset of active reservations and aggregate reserved balances | - -The sweeper calls `release_stale_reservations()` in `routstr/core/db.py`. - -For durable reservations, it selects `active` rows whose `created_at` is older than the cutoff. Its terminal update also checks the timestamp, protecting against a heartbeat that renews between selection and release. - -Each successful release subtracts that reservation's own amount from the relevant aggregates. Healthy releases commit individually so that certain later corruption repairs cannot roll them back. - -Under healthy execution, recovery occurs after the last lease renewal has aged beyond the configured timeout, plus sweep scheduling and database-operation time. This is **not** a guarantee of release 300 seconds after the request originally began. - -### Refund-time cleanup - -`refund_wallet_endpoint()` in `routstr/balance.py` checks for reserved funds before opening the refund claim. - -If `key.reserved_balance > 0`, it: - -1. Calls `release_stale_reservations()` scoped to that key. -2. Refreshes the key from the database. -3. Returns HTTP 400 with the reported message if reserved balance remains. - -Thus, the current refund path does not rely exclusively on the background task having run. A stale durable reservation should also be releasable during refund itself. - -If cleanup raises an unexpected exception instead, that is a separate failure from this specific HTTP 400 branch. - -### Legacy aggregate cleanup - -Older deployments may have aggregate reserved balances without matching durable rows. - -The cleanup function also looks for these legacy aggregates, but only clears them when there is no active durable owner. It uses a compare-and-swap guard on the observed balance and timestamp to avoid erasing a newly created reservation. - -The behavior differs between background and targeted cleanup: - -| Legacy aggregate state, with no active durable owner | Background sweep | Refund-time targeted cleanup | -| --- | --- | --- | -| Old `reserved_at` | Eligible for release | Eligible for release | -| Recent `reserved_at` | Preserved | Preserved | -| `reserved_at = NULL` | Deliberately skipped | Eligible for repair | - -The NULL-timestamp behavior is explicitly covered by existing tests. It is a background-recovery limitation, but **alone it does not explain the reported refund rejection on the current checkout**, because targeted refund cleanup heals it. - -### Startup reset - -When enabled, startup calls `reset_all_reserved_balances()`. It marks active durable reservations released and clears aggregate reserved balances and timestamps. - -This is not a safe universal operational fix. In a shared-database, multi-instance setup, another instance may still own a legitimate in-flight request. Resetting its reservation can break billing. The setting's source comment recommends disabling it for horizontal scaling. - -## Why the 900-second HTTP timeout does not guarantee eventual completion - -The user correctly asks: if the last request was days ago, shouldn't a 900-second upstream timeout have completed or failed the request long before now? - -**For an ordinary request actively waiting for upstream bytes, with no bytes arriving, yes.** It should hit the read timeout and reach failure cleanup. A days-long refund blockage is abnormal, not expected behavior for a silent upstream. - -However, the HTTP read timeout is not an absolute deadline spanning the complete request lifecycle. - -### Upstream continues sending bytes - -A stream can avoid a read inactivity timeout by delivering bytes periodically. Those bytes might be content or keepalive traffic. A stream with no total-duration limit could therefore remain open longer than 900 seconds. - -This is a technical possibility, **not evidence that the affected upstream streamed for days**. It must not be assumed as the production explanation. - -### Router is blocked writing to the downstream client - -If the router has received a chunk and is blocked delivering it to the client, it may not currently be waiting on an upstream HTTP read. The upstream read timeout is not a general bound on downstream ASGI sends. - -Whether a particular blocked send keeps the captured owner task alive depends on the execution path. That behavior needs a runtime trace or regression test, rather than an assumption about all stream paths. - -### Router is blocked after upstream completion - -Database settlement, finalization, or resource cleanup happens outside the upstream read operation. The upstream read timeout does not bound these waits. - -If the heartbeat's owning task remains alive while waiting, renewal may continue. If that owner finishes and only detached cleanup remains, the heartbeat should stop and the sweeper should eventually recover the reservation. - -### Conclusion - -The current code has no common hard lifetime limit found in this investigation that covers reservation creation, upstream dispatch, streaming delivery, and finalization together. - -The missing guarantee is: - -> A live-but-stuck request cannot renew its reservation forever. - -This gap is confirmed by the heartbeat's renewal condition. The specific blocked operation, if any, on the affected node is not known. - -## Findings and hypotheses - -### Confirmed: renewal does not require progress - -An owner task being alive is sufficient to renew the lease. Neither original request age nor meaningful progress is checked. - -This permits indefinite reservation retention in principle, even without new requests using the key. - -### Confirmed: immutable request age is not stored in the reservation row - -`ReservationRelease.created_at` doubles as the last-renewal timestamp. Once renewed, it cannot tell us when the request originally started. - -This impairs diagnostics and prevents enforcing an original-age limit from this field alone. - -### Confirmed: NULL legacy timestamps are not background-cleaned - -Such keys may remain reserved indefinitely in the background. The current refund endpoint has targeted recovery for this state, subject to the absence of an active durable owner. - -### Confirmed: unexpected failures can interrupt a sweep pass - -The background loop catches unexpected exceptions, logs `Error in periodic_stale_reservation_sweep`, and retries after the sweep interval. - -Some aggregate-corruption cases are handled per reservation, but not every database exception is isolated per record. A persistently failing operation could repeatedly interrupt a pass. Whether this prevents a particular key's cleanup depends on the failure and processing order. - -There is no evidence yet that this caused the reported error. - -### Possible: affected deployment differs from this checkout - -The current code includes heartbeat-owner binding, targeted legacy recovery, and corruption handling. The affected node may run older or different code. - -The deployed commit must be established before treating local behavior as proof of production behavior. - -### Possible: future timestamps or unusual effective configuration - -A future-dated lease can remain non-stale unexpectedly. An unusually large configured timeout can also preserve old reservations. - -Clock skew between instances sharing a database can affect lease timestamps and age calculations. These are diagnostic checks, not confirmed causes. - -## Existing verified recovery coverage - -The suites run during this investigation cover, among other cases: - -- Stamping aggregate reservation timestamps on payment. -- Reverting individual reservations without erasing siblings. -- Releasing old reservations and preserving fresh ones. -- Resetting reserved balances during explicit startup reset. -- Refund-time recovery of stale and legacy NULL-timestamp aggregates. -- Refusing refunds while a recent reservation remains. -- Streaming finalization and client-disconnect cleanup. -- Owner task termination allowing recovery of an abandoned reservation. -- Lease renewal across an in-flight request. -- Renewal racing with stale release. -- Legacy aggregate release racing with a new reservation. -- Several accounting-corruption cases and safe terminal repair. -- Preventing late charges after a reservation has reached a released terminal state. - -These tests do not substitute for explicit tests of endless keepalive streams, blocked downstream sends, or finalization that never completes. - -## Production diagnosis: distinguish a renewing lease from failed cleanup - -The most useful initial question is: - -> Is the reservation still being renewed, or is it stale and not being released? - -Do not share the raw API-key secret. Use its stored hash and reservation identifiers in restricted operational diagnostics. - -### 1. Establish deployment and configuration - -Record: - -- Deployed commit/version. -- Effective `STALE_RESERVATION_TIMEOUT_SECONDS`. -- Effective `UPSTREAM_READ_TIMEOUT`. -- Startup-reset setting. -- Number of instances sharing the database. -- Current time on each relevant instance. -- Whether the lifespan/background tasks completed startup. - -Use effective settings, not only environment variables; settings initialization includes persisted configuration. - -### 2. Inspect the key and all related reservations - -Read-only queries: - -```sql -SELECT hashed_key, balance, reserved_balance, reserved_at -FROM api_keys -WHERE hashed_key = :key_hash; - -SELECT id, key_hash, billing_key_hash, - reserved_msats, status, created_at -FROM reservation_releases -WHERE key_hash = :key_hash - OR billing_key_hash = :key_hash; -``` - -Inspect both key relationships, since a reservation may reference the key as request owner or billing owner. - -Take two snapshots approximately 110 seconds apart with default settings, or use an interval longer than the effective heartbeat interval. A pair of snapshots is a useful signal; it is not a substitute for longer observation when renewal is delayed or intermittent. - -### 3. Interpret the results - -| Observation | Investigation direction | -| --- | --- | -| Active reservation timestamp advances | Identify the instance and owning task renewing it; inspect its stack and actual progress | -| Active reservation timestamp is older than the stale cutoff and does not advance | Check sweep execution/errors, refund cleanup, deployed code, and accounting state | -| Reserved balance remains with no active durable rows | Inspect legacy timestamp and aggregate recovery; current targeted refund cleanup should repair stale/NULL state | -| Lease timestamp is in the future | Check clocks and timestamp integrity | -| Some rows are stale and others fresh | Release only stale owners; do not clear the whole key | -| Aggregate amount disagrees with active durable ownership | Investigate accounting drift and safe reconciliation | - -If the lease is genuinely days old and unrenewed, the indefinite-heartbeat explanation does **not** explain that row. Cleanup failure or incompatible deployment becomes the relevant direction. - -### 4. Inspect logs and task state - -Relevant existing log messages include: - -- `Error in periodic_stale_reservation_sweep`. -- `Failed to renew billing reservation lease`. -- `Released stale reservations`. -- `Released corrupt stale reservation without aggregate subtraction`. -- `Released corrupt reservation without aggregate subtraction`. -- `Client disconnected mid-request, reverting reservation`. -- `refund_wallet_endpoint: released stale reservation before refund`. - -For a renewing lease, locate the process with that reservation's heartbeat and inspect the owner's stack. Determine whether it is waiting on upstream input, downstream delivery, database work, finalization, or another operation. - -Also correlate the original request with upstream outcome and billing logs. A heartbeat alone does not demonstrate that inference is still running. - -## Proposed hardening - -These are proposed changes, not completed fixes. - -### 1. Separate original age from renewable lease age - -Keep distinct durable fields for: - -- Immutable reservation/request start time. -- Last lease renewal time. - -Consider additional progress and ownership metadata where justified. Define migration behavior explicitly: existing renewed `created_at` values cannot reconstruct true original start times. - -### 2. Bound the actual request, not just the accounting lease - -Introduce a configurable total billed-request lifetime covering all relevant routes and phases, including streaming delivery. Add appropriate inactivity bounds for upstream waits and downstream delivery, and bounded finalization/cleanup behavior. - -Timeout handling should: - -1. Stop or cancel the owning request and close owned resources. -2. Settle known or estimated delivered usage according to existing billing policy. -3. Release only that request's remaining reservation. -4. Stop heartbeat renewal. -5. Reach a durable terminal state that prevents later charging. - -Do **not** merely stop renewal or zero the key while a request continues running. Releasing funds while upstream work can still finish creates refund/late-charge and provider-cost risks. - -Care is also needed not to cancel legitimate long-running inference accidentally. Request lifetime, inactivity, and lease expiry are different concepts and should have distinct documented policies. - -### 3. Improve stalled-owner detection and observability - -Expose actionable, non-secret diagnostics: - -- Reservation identity and owning instance. -- Immutable age and current lease age. -- Last meaningful progress and current phase, if tracked. -- Reason for terminal transition or refused refund. -- Age and count of active reservations. -- Sweep failures and cleanup duration. - -Do not treat upstream keepalive bytes as necessarily meaningful model progress. Decide deliberately which signals should extend which deadlines. - -### 4. Reconcile legacy and inconsistent aggregates safely - -Define a migration/recovery policy for NULL legacy timestamps, rather than leaving them background-ineligible indefinitely. - -Mixed-version deployments require caution: an aggregate without a durable row might still belong to an older live worker. Any reconciliation must preserve valid durable owners and avoid unsafe whole-key resets. - -Investigate positive residual aggregates even after durable rows become terminal, with concurrency guards and accounting invariants preserved. - -### 5. Make cleanup failures diagnosable and resilient - -Consider bounded database operations, per-record failure isolation where safe, and alerts for repeated sweep failures or reservations exceeding expected age. - -Failure isolation must not weaken atomicity between durable transitions and aggregate updates. A failed release must not partially debit unrelated reservations. - -## Regression tests needed to close the gaps - -Add tests that reproduce and verify recovery for: - -1. A live owner waiting indefinitely without progress. -2. An endless upstream stream sending keepalive bytes below the read-timeout interval. -3. A downstream send blocked indefinitely after receiving an upstream chunk. -4. Finalization or database settlement that stalls. -5. Cancellation before streaming begins, during streaming, and during finalization. -6. Renewing lease older than the new maximum original-age limit. -7. Background legacy NULL-timestamp recovery under the chosen migration policy. -8. Corrupt residual aggregates alongside a healthy active sibling reservation. -9. A failing cleanup operation followed by other recoverable reservations. -10. Multiple workers concurrently renewing, sweeping, timing out, and refunding. -11. Late completion attempting to charge after timeout/release. -12. Future lease timestamps and the chosen clock-skew policy. - -For each timeout/recovery test, assert: - -- The underlying request/resource is stopped or closed as intended. -- No heartbeat can renew indefinitely afterward. -- Only the affected reservation is released. -- Sibling reservations remain intact. -- Balance/reserved accounting remains valid. -- Terminal transitions are idempotent. -- A later completion cannot charge released/refunded funds. -- The key becomes refundable when no legitimate reservations remain. - -## Operational caution - -Do not solve the symptom by manually setting `reserved_balance = 0` while active requests or heartbeat tasks may exist. Durable reservation state and aggregate balances must agree, and late completion must not be allowed to spend refunded funds. - -Any production repair should begin with a read-only snapshot and identification of live ownership, then use an accounting-safe terminal transition or controlled maintenance procedure. - -## Bottom line - -The expected stale cleanup exists. A genuinely dead, unrenewed reservation should recover on the current version with healthy database access, including during a refund attempt. - -The confirmed design gap is that **a task remaining alive is sufficient to renew its reservation indefinitely**, and the upstream 900-second read timeout does not bound every phase of that task's lifetime. - -A days-old refund blockage therefore warrants investigation, not an assumption that normal request processing is still underway. The first decisive evidence is whether the affected reservation's lease timestamp continues advancing. The production root cause and implementation fixes remain open. - -## Release-specific reproduction: v0.4.7 (confirmed) - -The user subsequently confirmed that the affected node runs the released **v0.4.7** tag. Testing that tag revealed an important correction to the initial analysis above: - -**The 900-second upstream read timeout exists in the newer checkout, not in v0.4.7.** The release's forwarding paths construct `httpx.AsyncClient(..., timeout=None)`. It has no `upstream_read_timeout` settings field. Setting `UPSTREAM_READ_TIMEOUT=3` in the reproduction did nothing; importing the release settings confirmed the field is absent. - -Therefore, on this release an upstream can send one chunk and then remain completely silent without triggering an HTTP read timeout. Periodic bytes are not needed to explain indefinite waiting. - -### Environment and isolation - -- Podman: 5.8.4, netavark network backend. -- Release commit: `f32565e2547abbbffd77a01198ef683ecb8e3d4f`. -- Detached worktree: `.worktrees/reserved-balance-v047`. -- Built the release's own Dockerfile (Python 3.11 base), without source patches. -- Image: `localhost/routstr-reserved-repro:v0.4.7`. -- Image ID: `8c3340a33040df37439f7085e369050d3acc2adf0324bc024e1b4288a3601f76`. -- Separate containers, loopback ports 18080/18081, container-local SQLite database. -- No original node database, wallet, secrets, volumes, or image tag were changed. -- Host networking avoided the reported aardvark DNS issue for this experiment; containerized DNS was not tested or repaired. -- Accelerated stale timeout: 6 seconds, heartbeat every 2 seconds. Background sweep retained its actual 60-second interval. -- Synthetic database-funded keys avoided introducing Cashu mint behavior into the reservation test. Actual refund payout success was not tested. - -### Dummy upstream scenarios - -A small local OpenAI-compatible server exposed `/v1/models` and `/v1/chat/completions` using `gpt-4o-mini`: - -1. **Finite:** three chunks, a usage event, and `[DONE]`. -2. **Silent:** one chunk, then sleep for 3600 seconds. -3. **Endless:** a content chunk every 0.5 seconds with no terminal event. - -The test client consumed streams, queried reservation state, attempted refunds, and disconnected. Evidence and reusable scripts are in `reservation-repro-v047/`. - -### Observed results - -| Scenario | Outcome | -| --- | --- | -| Finite stream | Settled normally; reserved balance became zero | -| Silent stream | Did not time out; durable lease kept renewing | -| Endless stream | Lease kept renewing; refund returned the exact reported HTTP 400 | -| Both clients disconnected | Both upstream connections remained established; both reservations remained active and kept renewing | -| After more than a background-sweep interval | The abandoned reservations were still active; their fresh leases prevented stale cleanup | -| Dummy upstream forcibly stopped | Both requests finally reached error/finalization; both reserved balances became zero and rows became `charged` | - -Both streams reserved 11 msats. Their lease timestamps initially advanced from `1790765677` through `1790765685` and `1790765695`. After client termination, a later snapshot at `1790765791` still showed both rows `active` with leases at `1790765789`. This is approximately 116 seconds after their creation and well beyond the accelerated stale timeout and a background-sweep interval. - -At that later point, `ss` showed two established router-to-upstream connections and no test-client connection on port 18080. A refund for the silent key still returned: - -```json -{"detail":"Cannot refund key. There are ongoing requests for this api key."} -``` - -Stopping the dummy upstream broke those connections. Finalization then charged estimated usage and cleared the reservations. The finite and silent keys ended with a 3-msat charge; the endless stream accumulated a 25-msat charge. This also demonstrates that abandoned upstream work can continue affecting billing after the downstream client is gone. - -The first probe run ended with a client-side `TimeoutError` because it expected the silent stream to complete. That timeout was imposed by the probe's `asyncio.wait_for`, not by the router. The saved probe was subsequently adjusted to report this expected observation rather than crash. - -### What this establishes - -We have reproduced a plausible mechanism for a key remaining blocked long after the client last used it on **the exact release tag**: - -1. The upstream stream remains open, even silently. -2. Downstream disconnection does not terminate the upstream-owning request in the tested runtime/path. -3. The owner remains alive, so its heartbeat keeps renewing. -4. Background and refund-time stale cleanup preserve the fresh lease. -5. Refund remains blocked indefinitely unless the upstream closes or another intervention stops the owning work. - -The reproduction lasted minutes, not days. The absence of a read timeout and continuing renewal explain how the state can persist longer; no days-long run was performed. - -This is concrete release-specific evidence, but not proof that the affected production key has this exact state. Production confirmation still requires reservation snapshots and logs. - -### Shutdown symptoms - -The dummy upstream also needed SIGKILL after a short SIGTERM grace period while its streams were open. The router stopped normally after the upstream was stopped and its streams finalized. - -This supports the possibility that outstanding streaming work can delay graceful shutdown. It does not establish that the user's earlier router/UI shutdown warnings share the same cause. The aardvark DNS removal failure is a separate Podman networking symptom; the reproduction does not require it. - -### Next implementation work - -Prioritize fixes/backports appropriate to v0.4.7: - -- Finite upstream transport timeouts, including reads and header waits. -- Reliable downstream-disconnect propagation and deterministic closure/finalization of owned streaming resources in the deployed FastAPI/Starlette/Uvicorn combination. -- A maximum request lifetime independent of renewable leases and keepalive bytes. -- Real-network regression tests that disconnect a client from a silent upstream stream and assert upstream closure, terminal billing state, stopped renewal, and zero residual reservation. - -The newer checkout has transport timeout and stream-ownership changes, but this experiment did not validate the same scenario against that newer checkout. Do not assume an upgrade fully fixes every gap without rerunning the reproduction. - -Both reproduction containers were stopped at the end. Their container-local database and logs were retained for inspection; no original services were restarted. - -## Current main reproduction: timeout does not close every gap - -The same investigation was repeated against unpatched local main commit `96c8e2f77de8e9f8a0979d17dba0a6d20c78fe89` using its own Dockerfile and frozen dependencies. The main image ran Python 3.14, Starlette 1.6.0, and Uvicorn 0.31.1. Detailed commands and evidence are in `reservation-repro-main/README.md`. - -With an effective upstream read timeout of 3 seconds and stale timeout of 6 seconds: - -- Finite completion settled correctly. -- Silent upstream streams reached the read timeout and cleared reservations. -- A header wait timed out with HTTP 424 and released its reservation. -- An endless content stream **after client disconnect** kept renewing and returning the reported refund HTTP 400. -- SSE comment-only keepalives evaded read timeout; renewal persisted even after disconnect. -- A flood stream to a downstream client that never read remained reserved, including after its socket closed. - -The three problematic keys remained active approximately 269 seconds after request start, across multiple background sweeps, with fresh lease timestamps. This is not merely an active client asking for a refund: all downstream test clients were gone well before the final observation. - -### Framework compatibility concern - -Installed framework source provides a specific lead: - -- Uvicorn's httptools protocol advertises ASGI HTTP 2.4. -- Its send function silently returns after downstream disconnection. -- Starlette's ASGI >=2.4 StreamingResponse path expects send to raise OSError for disconnect detection and does not run the older disconnect listener. - -This mismatch is consistent with streams continuing to consume upstream bytes while downstream sends become no-ops. Captured code is in the evidence directory. A runtime task-stack or controlled framework-version comparison is still needed for complete causal validation. - -Removing only LoggingMiddleware in a diagnostic router did not resolve disconnect renewal. Therefore, do not attribute the disconnect problem solely to that middleware. - -### Additional finalization/shutdown observation - -Forcibly stopping the dummy upstream finalized the diagnostic router's streams, but the unmodified router still had active reservations five seconds after upstream termination and required SIGKILL after a ten-second SIGTERM grace period. Its logs showed upstream termination warnings without completed settlement for those three requests in the captured window. The precise blocked operation was not traced. - -This adds a finalization/delivery investigation beyond transport inactivity. In this main reproduction, unlike the release reproduction, upstream termination did not promptly clear every reservation. - -### Updated conclusion - -The newer read timeout fixes silent upstream waits, but **does not eliminate reservation leaks for disconnected clients whose upstream streams keep producing bytes, or stalled downstream delivery**. The stream ownership/finalizer unit tests previously run do not exercise the complete real server/framework/middleware network path that exposed these cases. - -Prioritize real-network regression coverage and disconnect propagation, the installed server/framework compatibility, bounded downstream delivery and finalization, and an absolute request lifetime independent of keepalive traffic. No implementation fix has been made; alternate routes, multi-worker behavior, and database fault injection remain untested. diff --git a/pyproject.toml b/pyproject.toml index 1faf6828..7daf7489 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -73,7 +73,7 @@ build-backend = "setuptools.build_meta" packages = ["routstr"] [tool.ruff] -extend-exclude = ["examples", "repro", "reservation-repro-main"] +extend-exclude = ["examples"] [tool.ruff.lint] select = ["E", "F", "I"] @@ -87,7 +87,6 @@ check_untyped_defs = true disallow_untyped_calls = true disallow_incomplete_defs = true disallow_untyped_decorators = true -exclude = ["^repro/", "^reservation-repro-main/"] [tool.uv.sources] routstr = { workspace = true } diff --git a/repro/IMPLEMENTATION.md b/repro/IMPLEMENTATION.md deleted file mode 100644 index 1c231f1f..00000000 --- a/repro/IMPLEMENTATION.md +++ /dev/null @@ -1,46 +0,0 @@ -# Reservation lifecycle implementation and validation - -Branch: fix/reservation-lifecycle. Baseline: 96c8e2f7. - -## Implemented - -- Outermost pure-ASGI lifecycle supervision with one coordinated receive consumer, explicit disconnect monitoring, cancellation, and exact reservation fallback cleanup. -- Finite overall request lifetime (MAX_REQUEST_LIFETIME_SECONDS, default 1800), downstream send timeout (DOWNSTREAM_SEND_TIMEOUT_SECONDS, default 60), and cleanup timeout (REQUEST_CLEANUP_TIMEOUT_SECONDS, default 30). -- Lifecycle identity shared through context across middleware tasks; reservation replacements are registered for exact cleanup. -- Heartbeats stop on lifecycle termination or local maximum age. -- Persistent stream finalization has a finite cleanup budget. -- Durable immutable started_at and expires_at columns; expiry covers remaining request lifetime plus settlement grace, including provider fallback without restarting the original deadline. -- Renewal and charge claims refuse expired reservations. Sweeping can release absolute-expired reservations even when their renewable timestamp is fresh. -- Migration grants legacy active rows 1830 seconds of grace; original ages are not fabricated. Drain old workers before deployment. - -## Verification - -Run from worktree with PYTHONPATH=$PWD because the shared root virtual environment's editable install points at the original checkout: - -PYTHONPATH=$PWD ../../.venv/bin/pytest tests/unit/test_request_lifecycle.py tests/unit/test_stale_reservations.py tests/unit/test_streaming_billing_finalization.py tests/integration/test_negative_available_balance_repro.py -q - -64 tests passed. Ruff checks passed on changed files. Full-project mypy was attempted but did not finish within the tool timeout; no successful typecheck is claimed. - -Final built image: localhost/routstr-reserved-repro:fix, ef81426ad79e3d14ec462a39ab1f7481fd0cb410a9cb93cb42de41e8b3523869. - -Container tests used real TCP, full middleware stack, frozen image dependencies, isolated SQLite and synthetic balances. Read timeout 3s, lifetime 15s, delivery timeout 2s, cleanup timeout 3s, stale timeout 6s. - -Reused the main probe on ports 18100/18101. Results in results-final.txt and router-final.log: - -- Finite and silent streams settled. -- Header wait released its reservation. -- Disconnected endless stream no longer retained its reservation. -- Non-reading flood client hit bounded delivery/cleanup. -- Connected keepalive-only stream terminated at maximum lifetime. -- After the background-sweep interval and all client closures: every key reserved_balance=0, no active durable reservations. Explicit database assertions passed. -- Router shut down within the 10-second grace without SIGKILL. Dummy upstream still required SIGKILL: its fixture deliberately sleeps/open-streams and is not patched router code. - -Actual mint payout was not tested. Protocol errors on already-started streams when deadlines interrupt them are expected; an HTTP status cannot be replaced after headers are sent. - -## Financial policy / limitations - -The lifecycle first lets existing finalization run within a bounded budget. If still active, fallback releases only that reservation; late charge is fenced by terminal state. This can forgo charging observed output on failed settlement. It prioritizes freeing customer funds over leaving them locked; review this policy before deployment. Upstream compute may continue remotely even after local connection closure. - -This implementation does not complete every proposed hardening idea: provider cancellation APIs, full observability, per-record unexpected DB-failure isolation, legacy NULL aggregate background reconciliation, multi-worker/alternate-route network matrix and DB-outage injection remain follow-up work. No dependency upgrade was needed for the tested cases because explicit disconnect supervision avoids relying solely on send errors. - -All reproduction containers are stopped. Original node data/configuration is untouched. Source changes are uncommitted in the worktree for review. diff --git a/repro/dummy_upstream.py b/repro/dummy_upstream.py deleted file mode 100644 index 1be75ecc..00000000 --- a/repro/dummy_upstream.py +++ /dev/null @@ -1,45 +0,0 @@ -"""Loopback-only streaming fixture; no router monkeypatches.""" -import asyncio -import json -import time -from fastapi import FastAPI, Request -from fastapi.responses import StreamingResponse - -app = FastAPI() -events = [] - -@app.get('/events') -async def history(): - return events - -@app.get('/v1/models') -async def models(): - return {'object': 'list', 'data': [{'id': 'gpt-4o-mini', 'object': 'model', 'created': 1, 'owned_by': 'repro'}]} - -@app.post('/v1/chat/completions') -async def completions(request: Request): - body = await request.json() - mode = body.get('messages', [{}])[0].get('content', 'finite') - events.append({'event': 'start', 'mode': mode, 'time': time.time()}) - if mode.startswith('header'): - await asyncio.sleep(3600) - async def stream(): - count = 0 - try: - while True: - if mode.startswith('keepalive'): - yield ': ping\n\n' - else: - chunk = {'id': 'repro', 'object': 'chat.completion.chunk', 'created': int(time.time()), 'model': 'gpt-4o-mini', 'choices': [{'index': 0, 'delta': {'content': 'x' * (65536 if mode.startswith('flood') else 1)}, 'finish_reason': None}]} - yield 'data: ' + json.dumps(chunk) + '\n\n' - count += 1 - if mode == 'finite' and count >= 3: - yield 'data: ' + json.dumps({'id': 'repro', 'object': 'chat.completion.chunk', 'model': 'gpt-4o-mini', 'choices': [], 'usage': {'prompt_tokens': 1, 'completion_tokens': count, 'total_tokens': count + 1}}) + '\n\n' - yield 'data: [DONE]\n\n' - return - await asyncio.sleep(3600 if mode.startswith('silent') else (0.001 if mode.startswith('flood') else 0.5)) - finally: - event = {'event': 'close', 'mode': mode, 'chunks': count, 'time': time.time()} - events.append(event) - print(json.dumps(event), flush=True) - return StreamingResponse(stream(), media_type='text/event-stream') diff --git a/repro/probe.py b/repro/probe.py deleted file mode 100644 index 93d71a75..00000000 --- a/repro/probe.py +++ /dev/null @@ -1,60 +0,0 @@ -import asyncio -import json -import socket -import subprocess -import time -import httpx - -BASE='http://127.0.0.1:18100' - -def snapshot(): - code="import sqlite3,json,time; c=sqlite3.connect('/tmp/reserved-fix.db'); c.row_factory=sqlite3.Row; print(json.dumps({'time':time.time(),'keys':[dict(r) for r in c.execute(\"select hashed_key,balance,reserved_balance,reserved_at from api_keys where hashed_key like 'main-%'\")],'rows':[dict(r) for r in c.execute(\"select * from reservation_releases where key_hash like 'main-%'\")]}))" - return json.loads(subprocess.check_output(['podman','exec','reserved-router-fix','/.venv/bin/python','-c',code],text=True)) - -async def consume(mode): - try: - async with httpx.AsyncClient(timeout=None) as c: - async with c.stream('POST',BASE+'/v1/chat/completions',headers={'Authorization':'Bearer sk-main-'+mode},json={'model':'gpt-4o-mini','messages':[{'role':'user','content':mode}],'stream':True,'max_tokens':10}) as r: - print('STREAM',mode,r.status_code,flush=True) - async for _ in r.aiter_bytes(): pass - print('ENDED',mode,flush=True) - except asyncio.CancelledError: - print('CLIENT_DISCONNECTED',mode,flush=True) - raise - except Exception as e: - print('CLIENT_ERROR',mode,type(e).__name__,str(e),flush=True) - -async def report(label): - print(label,json.dumps(snapshot()),flush=True) - async with httpx.AsyncClient(timeout=5) as c: - for mode in ['silent-disconnect','endless-disconnect','keepalive','flood','header']: - # Only attempt payout while reserved: avoid requiring a real mint. - if next(k for k in snapshot()['keys'] if k['hashed_key']=='main-'+mode)['reserved_balance']: - r=await c.post(BASE+'/v1/wallet/refund',headers={'Authorization':'Bearer sk-main-'+mode}) - print('REFUND',mode,r.status_code,r.text,flush=True) - print('UPSTREAM_EVENTS',json.dumps((await c.get('http://127.0.0.1:18101/events')).json()),flush=True) - -async def main(): - modes=['finite','silent','silent-disconnect','endless-disconnect','keepalive','header'] - tasks={m:asyncio.create_task(consume(m)) for m in modes} - # Real client with a small receive buffer, never draining the HTTP response. - sock=socket.socket(); sock.setsockopt(socket.SOL_SOCKET,socket.SO_RCVBUF,1024); sock.connect(('127.0.0.1',18100)) - body=json.dumps({'model':'gpt-4o-mini','messages':[{'role':'user','content':'flood'}],'stream':True,'max_tokens':10}).encode() - sock.sendall(b'POST /v1/chat/completions HTTP/1.1\r\nHost: localhost\r\nAuthorization: Bearer sk-main-flood\r\nContent-Type: application/json\r\nContent-Length: '+str(len(body)).encode()+b'\r\n\r\n'+body) - await asyncio.sleep(1) - for m in ['silent-disconnect','endless-disconnect']: - tasks[m].cancel() - await asyncio.gather(tasks['silent-disconnect'],tasks['endless-disconnect'],return_exceptions=True) - await asyncio.sleep(9) - await report('AT_10_SECONDS') - await asyncio.sleep(60) - await report('AFTER_SWEEP') - sock.close() - tasks['keepalive'].cancel() - await asyncio.gather(tasks['keepalive'],return_exceptions=True) - await asyncio.sleep(8) - await report('AFTER_ALL_CLIENTS_CLOSED') - for task in tasks.values(): task.cancel() - await asyncio.gather(*tasks.values(),return_exceptions=True) - -asyncio.run(main()) diff --git a/repro/results-final.txt b/repro/results-final.txt deleted file mode 100644 index 6545bf6d..00000000 --- a/repro/results-final.txt +++ /dev/null @@ -1,19 +0,0 @@ -STREAM endless-disconnect 200 -STREAM keepalive 200 -STREAM finite 200 -STREAM silent 200 -STREAM silent-disconnect 200 -CLIENT_DISCONNECTED silent-disconnect -CLIENT_DISCONNECTED endless-disconnect -ENDED finite -ENDED silent -STREAM header 424 -ENDED header -AT_10_SECONDS {"time": 1790767971.1792026, "keys": [{"hashed_key": "main-finite", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent-disconnect", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-endless-disconnect", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-keepalive", "balance": 1000000000, "reserved_balance": 12, "reserved_at": 1790767960}, {"hashed_key": "main-flood", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-header", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}], "rows": [{"id": "9b5b9063f6f045a290611e4144c897de", "key_hash": "main-flood", "billing_key_hash": "main-flood", "reserved_msats": 12, "status": "released", "created_at": 1790767962, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "efc8563301ba458890ee3ab2335e4e49", "key_hash": "main-endless-disconnect", "billing_key_hash": "main-endless-disconnect", "reserved_msats": 13, "status": "released", "created_at": 1790767960, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "cbed89b7ec444fea9789cf53b3e0f476", "key_hash": "main-keepalive", "billing_key_hash": "main-keepalive", "reserved_msats": 12, "status": "active", "created_at": 1790767971, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "1c56b25265df4743b4cff70dc57544c6", "key_hash": "main-finite", "billing_key_hash": "main-finite", "reserved_msats": 12, "status": "charged", "created_at": 1790767960, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "cc7f113eef004b7ba27bc761c5d9b9a1", "key_hash": "main-silent", "billing_key_hash": "main-silent", "reserved_msats": 12, "status": "charged", "created_at": 1790767963, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "6a1b5506b8ab4747884475075ebc38da", "key_hash": "main-silent-disconnect", "billing_key_hash": "main-silent-disconnect", "reserved_msats": 13, "status": "released", "created_at": 1790767961, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "1dfedc1c2cee407fb2cd1a28b1253c6d", "key_hash": "main-header", "billing_key_hash": "main-header", "reserved_msats": 12, "status": "released", "created_at": 1790767963, "started_at": 1790767960, "expires_at": 1790767978}]} -REFUND keepalive 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"45f783cc-4c0b-4222-be13-8e726fc7cebc"} -UPSTREAM_EVENTS [{"event": "start", "mode": "flood", "time": 1790767717.2871263}, {"event": "start", "mode": "silent-disconnect", "time": 1790767717.2960703}, {"event": "start", "mode": "keepalive", "time": 1790767717.3026786}, {"event": "start", "mode": "header", "time": 1790767717.3104746}, {"event": "start", "mode": "endless-disconnect", "time": 1790767717.318341}, {"event": "start", "mode": "silent", "time": 1790767717.3653235}, {"event": "start", "mode": "finite", "time": 1790767717.3924189}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790767718.397855}, {"event": "start", "mode": "flood", "time": 1790767960.9594278}, {"event": "start", "mode": "endless-disconnect", "time": 1790767961.008998}, {"event": "start", "mode": "keepalive", "time": 1790767961.036595}, {"event": "start", "mode": "finite", "time": 1790767961.060875}, {"event": "start", "mode": "silent", "time": 1790767961.0869172}, {"event": "start", "mode": "silent-disconnect", "time": 1790767961.1580715}, {"event": "start", "mode": "header", "time": 1790767961.1944675}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790767962.064207}] -CLIENT_ERROR keepalive RemoteProtocolError peer closed connection without sending complete message body (incomplete chunked read) -AFTER_SWEEP {"time": 1790768033.9280283, "keys": [{"hashed_key": "main-finite", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent-disconnect", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-endless-disconnect", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-keepalive", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-flood", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-header", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}], "rows": [{"id": "9b5b9063f6f045a290611e4144c897de", "key_hash": "main-flood", "billing_key_hash": "main-flood", "reserved_msats": 12, "status": "released", "created_at": 1790767962, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "efc8563301ba458890ee3ab2335e4e49", "key_hash": "main-endless-disconnect", "billing_key_hash": "main-endless-disconnect", "reserved_msats": 13, "status": "released", "created_at": 1790767960, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "cbed89b7ec444fea9789cf53b3e0f476", "key_hash": "main-keepalive", "billing_key_hash": "main-keepalive", "reserved_msats": 12, "status": "released", "created_at": 1790767975, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "1c56b25265df4743b4cff70dc57544c6", "key_hash": "main-finite", "billing_key_hash": "main-finite", "reserved_msats": 12, "status": "charged", "created_at": 1790767960, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "cc7f113eef004b7ba27bc761c5d9b9a1", "key_hash": "main-silent", "billing_key_hash": "main-silent", "reserved_msats": 12, "status": "charged", "created_at": 1790767963, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "6a1b5506b8ab4747884475075ebc38da", "key_hash": "main-silent-disconnect", "billing_key_hash": "main-silent-disconnect", "reserved_msats": 13, "status": "released", "created_at": 1790767961, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "1dfedc1c2cee407fb2cd1a28b1253c6d", "key_hash": "main-header", "billing_key_hash": "main-header", "reserved_msats": 12, "status": "released", "created_at": 1790767963, "started_at": 1790767960, "expires_at": 1790767978}]} -UPSTREAM_EVENTS [{"event": "start", "mode": "flood", "time": 1790767717.2871263}, {"event": "start", "mode": "silent-disconnect", "time": 1790767717.2960703}, {"event": "start", "mode": "keepalive", "time": 1790767717.3026786}, {"event": "start", "mode": "header", "time": 1790767717.3104746}, {"event": "start", "mode": "endless-disconnect", "time": 1790767717.318341}, {"event": "start", "mode": "silent", "time": 1790767717.3653235}, {"event": "start", "mode": "finite", "time": 1790767717.3924189}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790767718.397855}, {"event": "start", "mode": "flood", "time": 1790767960.9594278}, {"event": "start", "mode": "endless-disconnect", "time": 1790767961.008998}, {"event": "start", "mode": "keepalive", "time": 1790767961.036595}, {"event": "start", "mode": "finite", "time": 1790767961.060875}, {"event": "start", "mode": "silent", "time": 1790767961.0869172}, {"event": "start", "mode": "silent-disconnect", "time": 1790767961.1580715}, {"event": "start", "mode": "header", "time": 1790767961.1944675}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790767962.064207}] -AFTER_ALL_CLIENTS_CLOSED {"time": 1790768044.521246, "keys": [{"hashed_key": "main-finite", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent-disconnect", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-endless-disconnect", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-keepalive", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-flood", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-header", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}], "rows": [{"id": "9b5b9063f6f045a290611e4144c897de", "key_hash": "main-flood", "billing_key_hash": "main-flood", "reserved_msats": 12, "status": "released", "created_at": 1790767962, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "efc8563301ba458890ee3ab2335e4e49", "key_hash": "main-endless-disconnect", "billing_key_hash": "main-endless-disconnect", "reserved_msats": 13, "status": "released", "created_at": 1790767960, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "cbed89b7ec444fea9789cf53b3e0f476", "key_hash": "main-keepalive", "billing_key_hash": "main-keepalive", "reserved_msats": 12, "status": "released", "created_at": 1790767975, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "1c56b25265df4743b4cff70dc57544c6", "key_hash": "main-finite", "billing_key_hash": "main-finite", "reserved_msats": 12, "status": "charged", "created_at": 1790767960, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "cc7f113eef004b7ba27bc761c5d9b9a1", "key_hash": "main-silent", "billing_key_hash": "main-silent", "reserved_msats": 12, "status": "charged", "created_at": 1790767963, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "6a1b5506b8ab4747884475075ebc38da", "key_hash": "main-silent-disconnect", "billing_key_hash": "main-silent-disconnect", "reserved_msats": 13, "status": "released", "created_at": 1790767961, "started_at": 1790767960, "expires_at": 1790767978}, {"id": "1dfedc1c2cee407fb2cd1a28b1253c6d", "key_hash": "main-header", "billing_key_hash": "main-header", "reserved_msats": 12, "status": "released", "created_at": 1790767963, "started_at": 1790767960, "expires_at": 1790767978}]} -UPSTREAM_EVENTS [{"event": "start", "mode": "flood", "time": 1790767717.2871263}, {"event": "start", "mode": "silent-disconnect", "time": 1790767717.2960703}, {"event": "start", "mode": "keepalive", "time": 1790767717.3026786}, {"event": "start", "mode": "header", "time": 1790767717.3104746}, {"event": "start", "mode": "endless-disconnect", "time": 1790767717.318341}, {"event": "start", "mode": "silent", "time": 1790767717.3653235}, {"event": "start", "mode": "finite", "time": 1790767717.3924189}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790767718.397855}, {"event": "start", "mode": "flood", "time": 1790767960.9594278}, {"event": "start", "mode": "endless-disconnect", "time": 1790767961.008998}, {"event": "start", "mode": "keepalive", "time": 1790767961.036595}, {"event": "start", "mode": "finite", "time": 1790767961.060875}, {"event": "start", "mode": "silent", "time": 1790767961.0869172}, {"event": "start", "mode": "silent-disconnect", "time": 1790767961.1580715}, {"event": "start", "mode": "header", "time": 1790767961.1944675}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790767962.064207}] diff --git a/repro/results.txt b/repro/results.txt deleted file mode 100644 index 01417f00..00000000 --- a/repro/results.txt +++ /dev/null @@ -1,19 +0,0 @@ -STREAM silent-disconnect 200 -STREAM keepalive 200 -STREAM endless-disconnect 200 -STREAM silent 200 -STREAM finite 200 -CLIENT_DISCONNECTED silent-disconnect -CLIENT_DISCONNECTED endless-disconnect -ENDED finite -STREAM header 424 -ENDED header -ENDED silent -AT_10_SECONDS {"time": 1790767727.5333533, "keys": [{"hashed_key": "main-finite", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent-disconnect", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-endless-disconnect", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-keepalive", "balance": 1000000000, "reserved_balance": 12, "reserved_at": 1790767717}, {"hashed_key": "main-flood", "balance": 999893370, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-header", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}], "rows": [{"id": "79c7feb2274140748da2a97180f56d2c", "key_hash": "main-flood", "billing_key_hash": "main-flood", "reserved_msats": 12, "status": "charged", "created_at": 1790767719, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "ecf20c01870b4ce49fc81bd300ee35df", "key_hash": "main-silent-disconnect", "billing_key_hash": "main-silent-disconnect", "reserved_msats": 13, "status": "charged", "created_at": 1790767717, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "ec6f854d6a8647ac8b3bba50752bc647", "key_hash": "main-keepalive", "billing_key_hash": "main-keepalive", "reserved_msats": 12, "status": "active", "created_at": 1790767725, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "6da67d4c5cbd4ab19cc30f2f0fac6aaa", "key_hash": "main-header", "billing_key_hash": "main-header", "reserved_msats": 12, "status": "released", "created_at": 1790767719, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "f4a35c5e89c343bfbe21415dce28a4d5", "key_hash": "main-endless-disconnect", "billing_key_hash": "main-endless-disconnect", "reserved_msats": 13, "status": "released", "created_at": 1790767717, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "50a37cffba7745fa84d03b4070c86066", "key_hash": "main-silent", "billing_key_hash": "main-silent", "reserved_msats": 12, "status": "charged", "created_at": 1790767719, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "63ca23fa71024428baaf8baeb7ee3ede", "key_hash": "main-finite", "billing_key_hash": "main-finite", "reserved_msats": 12, "status": "charged", "created_at": 1790767717, "started_at": 1790767717, "expires_at": 1790767735}]} -REFUND keepalive 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"f0bcc404-dffe-4860-8091-308f721ba053"} -UPSTREAM_EVENTS [{"event": "start", "mode": "flood", "time": 1790767717.2871263}, {"event": "start", "mode": "silent-disconnect", "time": 1790767717.2960703}, {"event": "start", "mode": "keepalive", "time": 1790767717.3026786}, {"event": "start", "mode": "header", "time": 1790767717.3104746}, {"event": "start", "mode": "endless-disconnect", "time": 1790767717.318341}, {"event": "start", "mode": "silent", "time": 1790767717.3653235}, {"event": "start", "mode": "finite", "time": 1790767717.3924189}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790767718.397855}] -CLIENT_ERROR keepalive RemoteProtocolError peer closed connection without sending complete message body (incomplete chunked read) -AFTER_SWEEP {"time": 1790767790.5300848, "keys": [{"hashed_key": "main-finite", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent-disconnect", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-endless-disconnect", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-keepalive", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-flood", "balance": 999893370, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-header", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}], "rows": [{"id": "79c7feb2274140748da2a97180f56d2c", "key_hash": "main-flood", "billing_key_hash": "main-flood", "reserved_msats": 12, "status": "charged", "created_at": 1790767719, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "ecf20c01870b4ce49fc81bd300ee35df", "key_hash": "main-silent-disconnect", "billing_key_hash": "main-silent-disconnect", "reserved_msats": 13, "status": "charged", "created_at": 1790767717, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "ec6f854d6a8647ac8b3bba50752bc647", "key_hash": "main-keepalive", "billing_key_hash": "main-keepalive", "reserved_msats": 12, "status": "released", "created_at": 1790767731, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "6da67d4c5cbd4ab19cc30f2f0fac6aaa", "key_hash": "main-header", "billing_key_hash": "main-header", "reserved_msats": 12, "status": "released", "created_at": 1790767719, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "f4a35c5e89c343bfbe21415dce28a4d5", "key_hash": "main-endless-disconnect", "billing_key_hash": "main-endless-disconnect", "reserved_msats": 13, "status": "released", "created_at": 1790767717, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "50a37cffba7745fa84d03b4070c86066", "key_hash": "main-silent", "billing_key_hash": "main-silent", "reserved_msats": 12, "status": "charged", "created_at": 1790767719, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "63ca23fa71024428baaf8baeb7ee3ede", "key_hash": "main-finite", "billing_key_hash": "main-finite", "reserved_msats": 12, "status": "charged", "created_at": 1790767717, "started_at": 1790767717, "expires_at": 1790767735}]} -UPSTREAM_EVENTS [{"event": "start", "mode": "flood", "time": 1790767717.2871263}, {"event": "start", "mode": "silent-disconnect", "time": 1790767717.2960703}, {"event": "start", "mode": "keepalive", "time": 1790767717.3026786}, {"event": "start", "mode": "header", "time": 1790767717.3104746}, {"event": "start", "mode": "endless-disconnect", "time": 1790767717.318341}, {"event": "start", "mode": "silent", "time": 1790767717.3653235}, {"event": "start", "mode": "finite", "time": 1790767717.3924189}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790767718.397855}] -AFTER_ALL_CLIENTS_CLOSED {"time": 1790767800.920076, "keys": [{"hashed_key": "main-finite", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent-disconnect", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-endless-disconnect", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-keepalive", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-flood", "balance": 999893370, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-header", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}], "rows": [{"id": "79c7feb2274140748da2a97180f56d2c", "key_hash": "main-flood", "billing_key_hash": "main-flood", "reserved_msats": 12, "status": "charged", "created_at": 1790767719, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "ecf20c01870b4ce49fc81bd300ee35df", "key_hash": "main-silent-disconnect", "billing_key_hash": "main-silent-disconnect", "reserved_msats": 13, "status": "charged", "created_at": 1790767717, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "ec6f854d6a8647ac8b3bba50752bc647", "key_hash": "main-keepalive", "billing_key_hash": "main-keepalive", "reserved_msats": 12, "status": "released", "created_at": 1790767731, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "6da67d4c5cbd4ab19cc30f2f0fac6aaa", "key_hash": "main-header", "billing_key_hash": "main-header", "reserved_msats": 12, "status": "released", "created_at": 1790767719, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "f4a35c5e89c343bfbe21415dce28a4d5", "key_hash": "main-endless-disconnect", "billing_key_hash": "main-endless-disconnect", "reserved_msats": 13, "status": "released", "created_at": 1790767717, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "50a37cffba7745fa84d03b4070c86066", "key_hash": "main-silent", "billing_key_hash": "main-silent", "reserved_msats": 12, "status": "charged", "created_at": 1790767719, "started_at": 1790767717, "expires_at": 1790767735}, {"id": "63ca23fa71024428baaf8baeb7ee3ede", "key_hash": "main-finite", "billing_key_hash": "main-finite", "reserved_msats": 12, "status": "charged", "created_at": 1790767717, "started_at": 1790767717, "expires_at": 1790767735}]} -UPSTREAM_EVENTS [{"event": "start", "mode": "flood", "time": 1790767717.2871263}, {"event": "start", "mode": "silent-disconnect", "time": 1790767717.2960703}, {"event": "start", "mode": "keepalive", "time": 1790767717.3026786}, {"event": "start", "mode": "header", "time": 1790767717.3104746}, {"event": "start", "mode": "endless-disconnect", "time": 1790767717.318341}, {"event": "start", "mode": "silent", "time": 1790767717.3653235}, {"event": "start", "mode": "finite", "time": 1790767717.3924189}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790767718.397855}] diff --git a/repro/router-final.log b/repro/router-final.log deleted file mode 100644 index dee5fe67..00000000 --- a/repro/router-final.log +++ /dev/null @@ -1,108 +0,0 @@ -/.venv/lib/python3.14/site-packages/anyio/from_thread.py:119: SyntaxWarning: 'return' in a 'finally' block - return result -2026-09-30 11:32:06 WARNING routstr.core.main UI dist directory not found at /app/ui_out; serving API only. Run `make ui-build` to build the static UI served from here, or `make ui-dev` for the Next.js dev server with hot reload on :3000 (it targets this backend on :8000). -2026-09-30 11:32:06 INFO uvicorn.error Started server process [1] -2026-09-30 11:32:06 INFO uvicorn.error Waiting for application startup. -2026-09-30 11:32:06 INFO routstr.core.main Application startup initiated -2026-09-30 11:32:10 INFO routstr.core.db Database migrations completed successfully -2026-09-30 11:32:10 INFO routstr.core.db Reset reserved balances on startup -2026-09-30 11:32:11 INFO routstr.upstream.helpers Seeding custom provider -2026-09-30 11:32:11 INFO routstr.upstream.helpers Seeded 1 upstream providers from settings -2026-09-30 11:32:12 INFO routstr.proxy Initialized 1 upstream providers -2026-09-30 11:32:12 INFO routstr.nostr.listing Nostr private key not configured (NSEC); waiting for one to be set before announcing this provider -2026-09-30 11:32:12 INFO routstr.nostr.analytics Usage analytics sharing task started -2026-09-30 11:32:12 INFO routstr.nostr.analytics NSEC is not configured; skipping analytics sharing to Nostr -2026-09-30 11:32:12 INFO routstr.auth Dead-key pruning disabled (interval <= 0) -2026-09-30 11:32:12 INFO uvicorn.error Application startup complete. -2026-09-30 11:32:12 INFO uvicorn.error Uvicorn running on http://127.0.0.1:18100 (Press CTRL+C to quit) -2026-09-30 11:32:40 INFO routstr.auth Existing sk- API key found -2026-09-30 11:32:40 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:32:40 INFO routstr.auth Processing payment for request -2026-09-30 11:32:40 INFO routstr.auth Existing sk- API key found -2026-09-30 11:32:40 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:32:40 INFO routstr.auth Processing payment for request -2026-09-30 11:32:40 INFO routstr.auth Existing sk- API key found -2026-09-30 11:32:40 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:32:40 INFO routstr.auth Processing payment for request -2026-09-30 11:32:40 INFO routstr.auth Existing sk- API key found -2026-09-30 11:32:40 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:32:40 INFO routstr.auth Processing payment for request -2026-09-30 11:32:40 INFO routstr.auth Existing sk- API key found -2026-09-30 11:32:40 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:32:40 INFO routstr.auth Processing payment for request -2026-09-30 11:32:40 INFO routstr.auth Existing sk- API key found -2026-09-30 11:32:40 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:32:40 INFO routstr.auth Processing payment for request -2026-09-30 11:32:40 INFO routstr.auth Existing sk- API key found -2026-09-30 11:32:40 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:32:40 INFO routstr.auth Processing payment for request -2026-09-30 11:32:40 INFO routstr.auth Payment processed successfully -2026-09-30 11:32:40 INFO routstr.payments RESERVE -2026-09-30 11:32:40 INFO routstr.auth Payment processed successfully -2026-09-30 11:32:40 INFO routstr.payments RESERVE -2026-09-30 11:32:41 INFO routstr.auth Payment processed successfully -2026-09-30 11:32:41 INFO routstr.payments RESERVE -2026-09-30 11:32:41 INFO routstr.auth Payment processed successfully -2026-09-30 11:32:41 INFO routstr.payments RESERVE -2026-09-30 11:32:41 INFO routstr.auth Payment processed successfully -2026-09-30 11:32:41 INFO routstr.payments RESERVE -2026-09-30 11:32:41 INFO routstr.auth Payment processed successfully -2026-09-30 11:32:41 INFO routstr.payments RESERVE -2026-09-30 11:32:41 INFO routstr.auth Payment processed successfully -2026-09-30 11:32:41 INFO routstr.payments RESERVE -2026-09-30 11:32:41 INFO routstr.payment.cost_calculation Applied model-specific pricing -2026-09-30 11:32:41 INFO routstr.payment.cost_calculation Calculated token-based cost -2026-09-30 11:32:41 INFO routstr.payment.cost_calculation Applied model-specific pricing -2026-09-30 11:32:41 INFO routstr.payment.cost_calculation Calculated token-based cost -2026-09-30 11:32:41 INFO routstr.auth Payment settlement finished -2026-09-30 11:32:41 INFO routstr.auth Payment settlement finished -2026-09-30 11:32:42 INFO routstr.payment.cost_calculation Applied model-specific pricing -2026-09-30 11:32:42 INFO routstr.payment.cost_calculation Calculated token-based cost -2026-09-30 11:32:42 INFO routstr.auth Calculated token-based cost -2026-09-30 11:32:42 INFO routstr.auth Refunding excess payment -2026-09-30 11:32:42 INFO routstr.auth Refund processed successfully -2026-09-30 11:32:42 INFO routstr.payments FINALIZE -2026-09-30 11:32:42 INFO routstr.auth Payment settlement finished -2026-09-30 11:32:42 INFO routstr.upstream.auto_topup Auto top-up worker started -2026-09-30 11:32:43 INFO routstr.payment.cost_calculation Applied model-specific pricing -2026-09-30 11:32:43 INFO routstr.payment.cost_calculation Calculated token-based cost -2026-09-30 11:32:43 ERROR routstr.core.exceptions Unhandled exception -asyncio.exceptions.CancelledError - -The above exception was the direct cause of the following exception: - -TimeoutError -2026-09-30 11:32:43 ERROR uvicorn.error Exception in ASGI application -asyncio.exceptions.CancelledError - -The above exception was the direct cause of the following exception: - -TimeoutError -2026-09-30 11:32:43 INFO routstr.auth Payment settlement finished -2026-09-30 11:32:44 WARNING routstr.upstream.base Streaming interrupted; finalizing before closing upstream -2026-09-30 11:32:44 INFO routstr.payment.cost_calculation Applied model-specific pricing -2026-09-30 11:32:44 INFO routstr.payment.cost_calculation Calculated token-based cost -2026-09-30 11:32:44 INFO routstr.auth Calculated token-based cost -2026-09-30 11:32:44 INFO routstr.auth Refunding excess payment -2026-09-30 11:32:44 INFO routstr.auth Refund processed successfully -2026-09-30 11:32:44 INFO routstr.payments FINALIZE -2026-09-30 11:32:44 INFO routstr.auth Payment settlement finished -2026-09-30 11:32:44 ERROR routstr.core.exceptions Unhandled exception -httpcore.ReadTimeout - -The above exception was the direct cause of the following exception: - -httpx.ReadTimeout -2026-09-30 11:32:44 ERROR uvicorn.error Exception in ASGI application -httpcore.ReadTimeout - -The above exception was the direct cause of the following exception: - -httpx.ReadTimeout -2026-09-30 11:32:44 ERROR routstr.upstream.base HTTP request error to upstream -2026-09-30 11:32:44 WARNING routstr.proxy Upstream base failed for model=gpt-4o-mini: Upstream service request timed out -2026-09-30 11:32:52 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. -2026-09-30 11:32:55 INFO routstr.payment.cost_calculation Applied model-specific pricing -2026-09-30 11:32:55 INFO routstr.payment.cost_calculation Calculated token-based cost -2026-09-30 11:32:55 ERROR uvicorn.error ASGI callable returned without completing response. -2026-09-30 11:32:55 INFO routstr.auth Payment settlement finished diff --git a/repro/router-first.log b/repro/router-first.log deleted file mode 100644 index b8979fc0..00000000 --- a/repro/router-first.log +++ /dev/null @@ -1,115 +0,0 @@ -/.venv/lib/python3.14/site-packages/anyio/from_thread.py:119: SyntaxWarning: 'return' in a 'finally' block - return result -2026-09-30 11:28:16 WARNING routstr.core.main UI dist directory not found at /app/ui_out; serving API only. Run `make ui-build` to build the static UI served from here, or `make ui-dev` for the Next.js dev server with hot reload on :3000 (it targets this backend on :8000). -2026-09-30 11:28:16 INFO uvicorn.error Started server process [1] -2026-09-30 11:28:16 INFO uvicorn.error Waiting for application startup. -2026-09-30 11:28:16 INFO routstr.core.main Application startup initiated -2026-09-30 11:28:20 INFO routstr.core.db Database migrations completed successfully -2026-09-30 11:28:21 INFO routstr.core.db Reset reserved balances on startup -2026-09-30 11:28:21 INFO routstr.upstream.helpers Seeding custom provider -2026-09-30 11:28:21 INFO routstr.upstream.helpers Seeded 1 upstream providers from settings -2026-09-30 11:28:22 INFO routstr.proxy Initialized 1 upstream providers -2026-09-30 11:28:22 INFO routstr.nostr.listing Nostr private key not configured (NSEC); waiting for one to be set before announcing this provider -2026-09-30 11:28:22 INFO routstr.nostr.analytics Usage analytics sharing task started -2026-09-30 11:28:22 INFO routstr.nostr.analytics NSEC is not configured; skipping analytics sharing to Nostr -2026-09-30 11:28:22 INFO routstr.auth Dead-key pruning disabled (interval <= 0) -2026-09-30 11:28:22 INFO uvicorn.error Application startup complete. -2026-09-30 11:28:22 INFO uvicorn.error Uvicorn running on http://127.0.0.1:18100 (Press CTRL+C to quit) -2026-09-30 11:28:37 INFO routstr.auth Existing sk- API key found -2026-09-30 11:28:37 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:28:37 INFO routstr.auth Processing payment for request -2026-09-30 11:28:37 INFO routstr.auth Existing sk- API key found -2026-09-30 11:28:37 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:28:37 INFO routstr.auth Processing payment for request -2026-09-30 11:28:37 INFO routstr.auth Existing sk- API key found -2026-09-30 11:28:37 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:28:37 INFO routstr.auth Processing payment for request -2026-09-30 11:28:37 INFO routstr.auth Existing sk- API key found -2026-09-30 11:28:37 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:28:37 INFO routstr.auth Processing payment for request -2026-09-30 11:28:37 INFO routstr.auth Payment processed successfully -2026-09-30 11:28:37 INFO routstr.payments RESERVE -2026-09-30 11:28:37 INFO routstr.auth Existing sk- API key found -2026-09-30 11:28:37 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:28:37 INFO routstr.auth Processing payment for request -2026-09-30 11:28:37 INFO routstr.auth Existing sk- API key found -2026-09-30 11:28:37 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:28:37 INFO routstr.auth Processing payment for request -2026-09-30 11:28:37 INFO routstr.auth Existing sk- API key found -2026-09-30 11:28:37 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:28:37 INFO routstr.auth Processing payment for request -2026-09-30 11:28:37 INFO routstr.auth Payment processed successfully -2026-09-30 11:28:37 INFO routstr.payments RESERVE -2026-09-30 11:28:37 INFO routstr.auth Payment processed successfully -2026-09-30 11:28:37 INFO routstr.payments RESERVE -2026-09-30 11:28:37 INFO routstr.auth Payment processed successfully -2026-09-30 11:28:37 INFO routstr.payments RESERVE -2026-09-30 11:28:37 INFO routstr.auth Payment processed successfully -2026-09-30 11:28:37 INFO routstr.payments RESERVE -2026-09-30 11:28:37 INFO routstr.auth Payment processed successfully -2026-09-30 11:28:37 INFO routstr.payments RESERVE -2026-09-30 11:28:37 INFO routstr.auth Payment processed successfully -2026-09-30 11:28:37 INFO routstr.payments RESERVE -2026-09-30 11:28:38 INFO routstr.payment.cost_calculation Applied model-specific pricing -2026-09-30 11:28:38 INFO routstr.payment.cost_calculation Calculated token-based cost -2026-09-30 11:28:38 INFO routstr.payment.cost_calculation Applied model-specific pricing -2026-09-30 11:28:38 INFO routstr.payment.cost_calculation Calculated token-based cost -2026-09-30 11:28:38 INFO routstr.auth Payment settlement finished -2026-09-30 11:28:38 INFO routstr.auth Calculated token-based cost -2026-09-30 11:28:38 INFO routstr.auth Refunding excess payment -2026-09-30 11:28:38 INFO routstr.auth Refund processed successfully -2026-09-30 11:28:38 INFO routstr.payments FINALIZE -2026-09-30 11:28:38 INFO routstr.auth Payment settlement finished -2026-09-30 11:28:38 INFO routstr.payment.cost_calculation Applied model-specific pricing -2026-09-30 11:28:38 INFO routstr.payment.cost_calculation Calculated token-based cost -2026-09-30 11:28:38 INFO routstr.auth Calculated token-based cost -2026-09-30 11:28:38 INFO routstr.auth Refunding excess payment -2026-09-30 11:28:38 INFO routstr.auth Refund processed successfully -2026-09-30 11:28:38 INFO routstr.payments FINALIZE -2026-09-30 11:28:38 INFO routstr.auth Payment settlement finished -2026-09-30 11:28:39 INFO routstr.payment.cost_calculation Applied model-specific pricing -2026-09-30 11:28:39 INFO routstr.payment.cost_calculation Calculated token-based cost -2026-09-30 11:28:39 INFO routstr.auth Calculated token-based cost -2026-09-30 11:28:39 INFO routstr.auth Finalized payment with additional charge -2026-09-30 11:28:39 INFO routstr.payments FINALIZE -2026-09-30 11:28:39 INFO routstr.auth Payment settlement finished -2026-09-30 11:28:39 ERROR routstr.core.exceptions Unhandled exception -asyncio.exceptions.CancelledError - -The above exception was the direct cause of the following exception: - -TimeoutError -2026-09-30 11:28:39 ERROR uvicorn.error Exception in ASGI application -asyncio.exceptions.CancelledError - -The above exception was the direct cause of the following exception: - -TimeoutError -2026-09-30 11:28:40 ERROR routstr.upstream.base HTTP request error to upstream -2026-09-30 11:28:40 WARNING routstr.proxy Upstream base failed for model=gpt-4o-mini: Upstream service request timed out -2026-09-30 11:28:40 WARNING routstr.upstream.base Streaming interrupted; finalizing before closing upstream -2026-09-30 11:28:40 INFO routstr.payment.cost_calculation Applied model-specific pricing -2026-09-30 11:28:40 INFO routstr.payment.cost_calculation Calculated token-based cost -2026-09-30 11:28:40 INFO routstr.auth Calculated token-based cost -2026-09-30 11:28:40 INFO routstr.auth Refunding excess payment -2026-09-30 11:28:40 INFO routstr.auth Refund processed successfully -2026-09-30 11:28:40 INFO routstr.payments FINALIZE -2026-09-30 11:28:40 INFO routstr.auth Payment settlement finished -2026-09-30 11:28:40 ERROR routstr.core.exceptions Unhandled exception -httpcore.ReadTimeout - -The above exception was the direct cause of the following exception: - -httpx.ReadTimeout -2026-09-30 11:28:40 ERROR uvicorn.error Exception in ASGI application -httpcore.ReadTimeout - -The above exception was the direct cause of the following exception: - -httpx.ReadTimeout -2026-09-30 11:28:49 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. -2026-09-30 11:28:52 INFO routstr.payment.cost_calculation Applied model-specific pricing -2026-09-30 11:28:52 INFO routstr.payment.cost_calculation Calculated token-based cost -2026-09-30 11:28:52 ERROR uvicorn.error ASGI callable returned without completing response. -2026-09-30 11:28:52 INFO routstr.auth Payment settlement finished -2026-09-30 11:28:52 INFO routstr.upstream.auto_topup Auto top-up worker started diff --git a/reservation-repro-main/README.md b/reservation-repro-main/README.md deleted file mode 100644 index e3df04b9..00000000 --- a/reservation-repro-main/README.md +++ /dev/null @@ -1,106 +0,0 @@ -# Current main: real-network streaming reservation reproductions - -## Tested version and environment - -- Commit: `96c8e2f77de8e9f8a0979d17dba0a6d20c78fe89` (local main at investigation time; no remote fetch was performed). -- Unpatched application built using its Dockerfile and frozen lockfile. -- Image: `localhost/routstr-reserved-repro:main`, ID `a787e603f565f3d34e1cc3999793d9dc2d2e3c968eb0ce0ded2f485450719bd0`. -- Podman 5.8.4; Python 3.14; Starlette 1.6.0; Uvicorn 0.31.1. -- Loopback ports 18090 (router), 18091 (dummy upstream), 18092 (diagnostic control). -- Separate container-local SQLite databases and synthetic balances; no original node data or secrets mounted. -- Read timeout accelerated to 3 seconds (confirmed effective); lease expiry to 6 seconds; heartbeat every 2 seconds. Background sweep remains 60 seconds. - -## Results - -| Scenario | Result | -| --- | --- | -| Finite stream with usage and DONE | Charged normally, zero reservation | -| One chunk then silence, client connected | Read timeout fired, estimated usage charged, zero reservation | -| One chunk then silence, client disconnected after 1 second | Reservation cleared on upstream read timeout; prompt disconnect cleanup was not demonstrated | -| No upstream response headers | Timeout produced HTTP 424; reservation released | -| Endless content stream, client disconnected after 1 second | Continued renewing; exact refund HTTP 400 persisted across background sweep | -| SSE comment-only keepalives every 0.5 seconds | No meaningful content or completion, but lease renewed and refund blocked; remained active after client disconnected | -| Flood stream to client that never reads | Lease renewed while client was stalled; still renewed after client socket closed | - -The three problematic streams retained 11-msat reservations through the full observation window. They began at timestamp 1790766366; at 1790766635, all remained active with lease timestamps 1790766634. Thus renewal continued for roughly 269 seconds, far beyond the 3-second read timeout, 6-second lease timeout, and multiple 60-second sweep intervals. All test clients were gone by approximately 1790766439. - -This proves persistence for minutes, not a measured days-long run. No new inference requests were made for the keys during observation; refund probes did not renew the leases. - -The flood scenario sends 64-KiB content deltas rapidly and uses a 1-KiB client receive buffer. It exercises a real non-reading downstream socket, but no live task-stack capture was collected to establish the precise blocked await at each snapshot. - -## Why the newer timeout is insufficient - -The read timeout is an inactivity timeout for upstream reads. Endless content or SSE keepalive bytes avoid it. A downstream-send wait is not bounded by it. - -More importantly, the runtime did not reliably propagate downstream disconnect into termination of these streams. Closed clients left upstream connections established and reservation owners alive, so heartbeats kept making the durable rows fresh. The sweeper therefore correctly declined to release them under its current policy. - -## Framework evidence and diagnostic control - -Captured sources (`starlette-source.txt`, `uvicorn-source.txt`) show: - -- Uvicorn 0.31.1's httptools protocol advertises ASGI HTTP spec 2.4. -- Its `send()` returns silently when `self.disconnected` is true; it does not raise an OSError. -- Starlette's StreamingResponse for ASGI >=2.4 relies on a send OSError to signal client disconnect, rather than running its older explicit disconnect listener. -- BaseHTTPMiddleware's outer streaming wrapper also does not explicitly listen for disconnect. - -This is a concrete framework compatibility concern consistent with the observations. Deterministic confirmation via a server-version/spec comparison or task instrumentation remains future work. - -A diagnostic second router removed only LoggingMiddleware using `no_logging_app.py`. Endless and keepalive clients still left active reservations after disconnect (`control-results.txt`). Thus LoggingMiddleware alone is not sufficient to explain the disconnect leak in this environment. This control is not a proposed production patch. - -When the dummy upstream was forcibly stopped, the control router finalized both streams. The unmodified main router still showed the three reservations active five seconds afterward and subsequently needed SIGKILL after a ten-second shutdown grace period. Logs showed upstream termination warnings but no completed settlement for those three in the captured window. The exact finalization blockage was not traced; it should be investigated separately, potentially including middleware delivery/backpressure interactions. Do not assert that upstream termination always clears these main reservations. - -## Reproduce - -From project root: - -```bash -podman build --build-arg GIT_COMMIT=$(git rev-parse HEAD) --build-arg GIT_TAG=main \ - -t localhost/routstr-reserved-repro:main . - -podman run -d --name reserved-dummy-main --network host \ - -v "$PWD/reservation-repro-main:/repro:ro,Z" \ - --entrypoint /.venv/bin/python localhost/routstr-reserved-repro:main \ - -m uvicorn dummy_upstream:app --app-dir /repro --host 127.0.0.1 --port 18091 - -podman run -d --name reserved-router-main --network host \ - -e DATABASE_URL=sqlite+aiosqlite:////tmp/reserved-main.db \ - -e UPSTREAM_BASE_URL=http://127.0.0.1:18091/v1 -e UPSTREAM_API_KEY=dummy \ - -e STALE_RESERVATION_TIMEOUT_SECONDS=6 -e UPSTREAM_READ_TIMEOUT=3 \ - -e CASHU_MINTS= -e ENABLE_PRICING_REFRESH=false \ - -e MODELS_REFRESH_INTERVAL_SECONDS=0 -e ADMIN_PASSWORD=local-repro-only \ - --entrypoint /.venv/bin/python localhost/routstr-reserved-repro:main \ - -m uvicorn routstr.core.main:app --host 127.0.0.1 --port 18090 -``` - -Wait for application startup and verify `/v1/models` includes gpt-4o-mini. Model/pricing discovery uses external services; this is not fully offline. - -```bash -podman exec -i reserved-router-main /.venv/bin/python - <<'PY' -import asyncio -from routstr.core.db import ApiKey, create_session -async def main(): - async with create_session() as s: - for k in ['finite','silent','silent-disconnect','endless-disconnect','keepalive','flood','header']: - s.add(ApiKey(hashed_key='main-'+k, balance=1000000000)) - await s.commit() -asyncio.run(main()) -PY - -.venv/bin/python reservation-repro-main/probe.py -``` - -The probe runs approximately 80 seconds, snapshots the DB, attempts refunds only on reserved keys (not actual Cashu payouts), and closes all clients. Later DB snapshots show continued renewal. Use fresh container names/databases on repeats or deliberately remove only the retained reproduction containers first. Do not overwrite original node containers. - -## Evidence and remaining work - -- `results.txt`: scenario matrix snapshots and refund errors. -- `connections.txt`: upstream sockets remained after downstream sockets disappeared. -- `final-before-stop.json`: continued renewal roughly 269 seconds after start. -- `after-upstream-stop.json`: reservations still active in unmodified main five seconds after upstream termination. -- `router.log`, `upstream.log`: application evidence before router shutdown. -- `control-results.txt`, `control-router.log`: comparison without LoggingMiddleware. -- `starlette-source.txt`, `uvicorn-source.txt`: installed framework behavior. - -Need: real-network regression tests, framework compatibility correction/verification, explicit disconnect monitoring that reaches upstream ownership, bounded downstream delivery, total request lifetime, and task-stack diagnostics for finalization stalls. Database fault injection, restart/multi-worker behavior, and alternate API routes were not tested here. - -All three main reproduction containers were stopped. The unmodified main router required SIGKILL; its retained database may contain active reservations. No application source fixes were made. diff --git a/reservation-repro-main/after-upstream-stop.json b/reservation-repro-main/after-upstream-stop.json deleted file mode 100644 index a4c70696..00000000 --- a/reservation-repro-main/after-upstream-stop.json +++ /dev/null @@ -1 +0,0 @@ -{"time": 1790766644.5905168, "keys": [["main-finite", 0], ["main-silent", 0], ["main-silent-disconnect", 0], ["main-endless-disconnect", 11], ["main-keepalive", 11], ["main-flood", 11], ["main-header", 0]], "rows": [["main-flood", "active", 1790766636], ["main-keepalive", "active", 1790766636], ["main-endless-disconnect", "active", 1790766636], ["main-silent", "charged", 1790766368], ["main-silent-disconnect", "charged", 1790766368], ["main-header", "released", 1790766368], ["main-finite", "charged", 1790766366]]} diff --git a/reservation-repro-main/connections.txt b/reservation-repro-main/connections.txt deleted file mode 100644 index 2911cbec..00000000 --- a/reservation-repro-main/connections.txt +++ /dev/null @@ -1,7 +0,0 @@ -ESTAB 0 0 127.0.0.1:18091 127.0.0.1:36380 users:(("python",pid=1480010,fd=7)) -ESTAB 0 0 127.0.0.1:36380 127.0.0.1:18091 users:(("python",pid=1480035,fd=31)) -ESTAB 0 0 127.0.0.1:36394 127.0.0.1:18091 users:(("python",pid=1480035,fd=32)) -ESTAB 0 0 127.0.0.1:36402 127.0.0.1:18091 users:(("python",pid=1480035,fd=33)) -CLOSE-WAIT 1 0 127.0.0.1:36456 127.0.0.1:18091 users:(("python",pid=1480035,fd=37)) -ESTAB 0 188 127.0.0.1:18091 127.0.0.1:36402 users:(("python",pid=1480010,fd=9)) -ESTAB 0 0 127.0.0.1:18091 127.0.0.1:36394 users:(("python",pid=1480010,fd=8)) diff --git a/reservation-repro-main/control-results.txt b/reservation-repro-main/control-results.txt deleted file mode 100644 index 84aee312..00000000 --- a/reservation-repro-main/control-results.txt +++ /dev/null @@ -1,5 +0,0 @@ -endless-control 200 -keepalive-control 200 -[('endless-control', 12), ('keepalive-control', 12)] -[('endless-control', 'active'), ('keepalive-control', 'active')] - diff --git a/reservation-repro-main/control-router.log b/reservation-repro-main/control-router.log deleted file mode 100644 index de3a8147..00000000 --- a/reservation-repro-main/control-router.log +++ /dev/null @@ -1,43 +0,0 @@ -/.venv/lib/python3.14/site-packages/anyio/from_thread.py:119: SyntaxWarning: 'return' in a 'finally' block - return result -2026-09-30 11:08:57 WARNING routstr.core.main UI dist directory not found at /app/ui_out; serving API only. Run `make ui-build` to build the static UI served from here, or `make ui-dev` for the Next.js dev server with hot reload on :3000 (it targets this backend on :8000). -2026-09-30 11:08:57 INFO uvicorn.error Started server process [1] -2026-09-30 11:08:57 INFO uvicorn.error Waiting for application startup. -2026-09-30 11:08:57 INFO routstr.core.main Application startup initiated -2026-09-30 11:08:59 INFO routstr.core.db Database migrations completed successfully -2026-09-30 11:08:59 INFO routstr.core.db Reset reserved balances on startup -2026-09-30 11:08:59 INFO routstr.upstream.helpers Seeding custom provider -2026-09-30 11:08:59 INFO routstr.upstream.helpers Seeded 1 upstream providers from settings -2026-09-30 11:09:00 INFO routstr.proxy Initialized 1 upstream providers -2026-09-30 11:09:00 INFO routstr.nostr.listing Nostr private key not configured (NSEC); waiting for one to be set before announcing this provider -2026-09-30 11:09:00 INFO routstr.nostr.analytics Usage analytics sharing task started -2026-09-30 11:09:00 INFO routstr.nostr.analytics NSEC is not configured; skipping analytics sharing to Nostr -2026-09-30 11:09:00 INFO routstr.auth Dead-key pruning disabled (interval <= 0) -2026-09-30 11:09:00 INFO uvicorn.error Application startup complete. -2026-09-30 11:09:00 INFO uvicorn.error Uvicorn running on http://127.0.0.1:18092 (Press CTRL+C to quit) -2026-09-30 11:09:30 INFO routstr.upstream.auto_topup Auto top-up worker started -2026-09-30 11:09:37 INFO routstr.auth Existing sk- API key found -2026-09-30 11:09:37 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:09:37 INFO routstr.auth Processing payment for request -2026-09-30 11:09:37 INFO routstr.auth Existing sk- API key found -2026-09-30 11:09:37 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:09:37 INFO routstr.auth Processing payment for request -2026-09-30 11:09:37 INFO routstr.auth Payment processed successfully -2026-09-30 11:09:37 INFO routstr.payments RESERVE -2026-09-30 11:09:37 INFO routstr.auth Payment processed successfully -2026-09-30 11:09:37 INFO routstr.payments RESERVE -2026-09-30 11:10:38 WARNING routstr.upstream.base Upstream stream ended before the response was complete -2026-09-30 11:10:38 WARNING routstr.upstream.base Upstream stream ended before the response was complete -2026-09-30 11:10:38 INFO routstr.payment.cost_calculation Applied model-specific pricing -2026-09-30 11:10:38 INFO routstr.payment.cost_calculation Calculated token-based cost -2026-09-30 11:10:38 INFO routstr.payment.cost_calculation Applied model-specific pricing -2026-09-30 11:10:38 INFO routstr.payment.cost_calculation Calculated token-based cost -2026-09-30 11:10:38 INFO routstr.auth Calculated token-based cost -2026-09-30 11:10:38 INFO routstr.auth Finalized payment with additional charge -2026-09-30 11:10:38 INFO routstr.payments FINALIZE -2026-09-30 11:10:38 INFO routstr.auth Payment settlement finished -2026-09-30 11:10:38 INFO routstr.auth Calculated token-based cost -2026-09-30 11:10:38 INFO routstr.auth Refunding excess payment -2026-09-30 11:10:38 INFO routstr.auth Refund processed successfully -2026-09-30 11:10:38 INFO routstr.payments FINALIZE -2026-09-30 11:10:38 INFO routstr.auth Payment settlement finished diff --git a/reservation-repro-main/dummy_upstream.py b/reservation-repro-main/dummy_upstream.py deleted file mode 100644 index 1be75ecc..00000000 --- a/reservation-repro-main/dummy_upstream.py +++ /dev/null @@ -1,45 +0,0 @@ -"""Loopback-only streaming fixture; no router monkeypatches.""" -import asyncio -import json -import time -from fastapi import FastAPI, Request -from fastapi.responses import StreamingResponse - -app = FastAPI() -events = [] - -@app.get('/events') -async def history(): - return events - -@app.get('/v1/models') -async def models(): - return {'object': 'list', 'data': [{'id': 'gpt-4o-mini', 'object': 'model', 'created': 1, 'owned_by': 'repro'}]} - -@app.post('/v1/chat/completions') -async def completions(request: Request): - body = await request.json() - mode = body.get('messages', [{}])[0].get('content', 'finite') - events.append({'event': 'start', 'mode': mode, 'time': time.time()}) - if mode.startswith('header'): - await asyncio.sleep(3600) - async def stream(): - count = 0 - try: - while True: - if mode.startswith('keepalive'): - yield ': ping\n\n' - else: - chunk = {'id': 'repro', 'object': 'chat.completion.chunk', 'created': int(time.time()), 'model': 'gpt-4o-mini', 'choices': [{'index': 0, 'delta': {'content': 'x' * (65536 if mode.startswith('flood') else 1)}, 'finish_reason': None}]} - yield 'data: ' + json.dumps(chunk) + '\n\n' - count += 1 - if mode == 'finite' and count >= 3: - yield 'data: ' + json.dumps({'id': 'repro', 'object': 'chat.completion.chunk', 'model': 'gpt-4o-mini', 'choices': [], 'usage': {'prompt_tokens': 1, 'completion_tokens': count, 'total_tokens': count + 1}}) + '\n\n' - yield 'data: [DONE]\n\n' - return - await asyncio.sleep(3600 if mode.startswith('silent') else (0.001 if mode.startswith('flood') else 0.5)) - finally: - event = {'event': 'close', 'mode': mode, 'chunks': count, 'time': time.time()} - events.append(event) - print(json.dumps(event), flush=True) - return StreamingResponse(stream(), media_type='text/event-stream') diff --git a/reservation-repro-main/final-before-stop.json b/reservation-repro-main/final-before-stop.json deleted file mode 100644 index 4647ae85..00000000 --- a/reservation-repro-main/final-before-stop.json +++ /dev/null @@ -1 +0,0 @@ -{"time": 1790766635.1679196, "keys": [["main-finite", 0], ["main-silent", 0], ["main-silent-disconnect", 0], ["main-endless-disconnect", 11], ["main-keepalive", 11], ["main-flood", 11], ["main-header", 0]], "rows": [["main-flood", "active", 1790766634], ["main-keepalive", "active", 1790766634], ["main-endless-disconnect", "active", 1790766634], ["main-silent", "charged", 1790766368], ["main-silent-disconnect", "charged", 1790766368], ["main-header", "released", 1790766368], ["main-finite", "charged", 1790766366]]} diff --git a/reservation-repro-main/no_logging_app.py b/reservation-repro-main/no_logging_app.py deleted file mode 100644 index 16c4cdfc..00000000 --- a/reservation-repro-main/no_logging_app.py +++ /dev/null @@ -1,4 +0,0 @@ -"""Diagnostic comparison ONLY: remove LoggingMiddleware from unchanged image app.""" -from routstr.core.main import app -from routstr.core.middleware import LoggingMiddleware -app.user_middleware = [m for m in app.user_middleware if m.cls is not LoggingMiddleware] diff --git a/reservation-repro-main/probe.py b/reservation-repro-main/probe.py deleted file mode 100644 index 57653e5e..00000000 --- a/reservation-repro-main/probe.py +++ /dev/null @@ -1,60 +0,0 @@ -import asyncio -import json -import socket -import subprocess -import time -import httpx - -BASE='http://127.0.0.1:18090' - -def snapshot(): - code="import sqlite3,json,time; c=sqlite3.connect('/tmp/reserved-main.db'); c.row_factory=sqlite3.Row; print(json.dumps({'time':time.time(),'keys':[dict(r) for r in c.execute(\"select hashed_key,balance,reserved_balance,reserved_at from api_keys where hashed_key like 'main-%'\")],'rows':[dict(r) for r in c.execute(\"select * from reservation_releases where key_hash like 'main-%'\")]}))" - return json.loads(subprocess.check_output(['podman','exec','reserved-router-main','/.venv/bin/python','-c',code],text=True)) - -async def consume(mode): - try: - async with httpx.AsyncClient(timeout=None) as c: - async with c.stream('POST',BASE+'/v1/chat/completions',headers={'Authorization':'Bearer sk-main-'+mode},json={'model':'gpt-4o-mini','messages':[{'role':'user','content':mode}],'stream':True,'max_tokens':10}) as r: - print('STREAM',mode,r.status_code,flush=True) - async for _ in r.aiter_bytes(): pass - print('ENDED',mode,flush=True) - except asyncio.CancelledError: - print('CLIENT_DISCONNECTED',mode,flush=True) - raise - except Exception as e: - print('CLIENT_ERROR',mode,type(e).__name__,str(e),flush=True) - -async def report(label): - print(label,json.dumps(snapshot()),flush=True) - async with httpx.AsyncClient(timeout=5) as c: - for mode in ['silent-disconnect','endless-disconnect','keepalive','flood','header']: - # Only attempt payout while reserved: avoid requiring a real mint. - if next(k for k in snapshot()['keys'] if k['hashed_key']=='main-'+mode)['reserved_balance']: - r=await c.post(BASE+'/v1/wallet/refund',headers={'Authorization':'Bearer sk-main-'+mode}) - print('REFUND',mode,r.status_code,r.text,flush=True) - print('UPSTREAM_EVENTS',json.dumps((await c.get('http://127.0.0.1:18091/events')).json()),flush=True) - -async def main(): - modes=['finite','silent','silent-disconnect','endless-disconnect','keepalive','header'] - tasks={m:asyncio.create_task(consume(m)) for m in modes} - # Real client with a small receive buffer, never draining the HTTP response. - sock=socket.socket(); sock.setsockopt(socket.SOL_SOCKET,socket.SO_RCVBUF,1024); sock.connect(('127.0.0.1',18090)) - body=json.dumps({'model':'gpt-4o-mini','messages':[{'role':'user','content':'flood'}],'stream':True,'max_tokens':10}).encode() - sock.sendall(b'POST /v1/chat/completions HTTP/1.1\r\nHost: localhost\r\nAuthorization: Bearer sk-main-flood\r\nContent-Type: application/json\r\nContent-Length: '+str(len(body)).encode()+b'\r\n\r\n'+body) - await asyncio.sleep(1) - for m in ['silent-disconnect','endless-disconnect']: - tasks[m].cancel() - await asyncio.gather(tasks['silent-disconnect'],tasks['endless-disconnect'],return_exceptions=True) - await asyncio.sleep(9) - await report('AT_10_SECONDS') - await asyncio.sleep(60) - await report('AFTER_SWEEP') - sock.close() - tasks['keepalive'].cancel() - await asyncio.gather(tasks['keepalive'],return_exceptions=True) - await asyncio.sleep(8) - await report('AFTER_ALL_CLIENTS_CLOSED') - for task in tasks.values(): task.cancel() - await asyncio.gather(*tasks.values(),return_exceptions=True) - -asyncio.run(main()) diff --git a/reservation-repro-main/results.txt b/reservation-repro-main/results.txt deleted file mode 100644 index 7f21d733..00000000 --- a/reservation-repro-main/results.txt +++ /dev/null @@ -1,27 +0,0 @@ -STREAM keepalive 200 -STREAM endless-disconnect 200 -STREAM silent 200 -STREAM silent-disconnect 200 -STREAM finite 200 -CLIENT_DISCONNECTED silent-disconnect -CLIENT_DISCONNECTED endless-disconnect -ENDED finite -ENDED silent -STREAM header 424 -ENDED header -AT_10_SECONDS {"time": 1790766376.4572322, "keys": [{"hashed_key": "main-finite", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent-disconnect", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-endless-disconnect", "balance": 1000000000, "reserved_balance": 11, "reserved_at": 1790766366}, {"hashed_key": "main-keepalive", "balance": 1000000000, "reserved_balance": 11, "reserved_at": 1790766366}, {"hashed_key": "main-flood", "balance": 1000000000, "reserved_balance": 11, "reserved_at": 1790766366}, {"hashed_key": "main-header", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}], "rows": [{"id": "50569f573caf4d6fb7916da3570493db", "key_hash": "main-flood", "billing_key_hash": "main-flood", "reserved_msats": 11, "status": "active", "created_at": 1790766376}, {"id": "0ffb4d61dc0d4aaf9e518c74b7afd1bb", "key_hash": "main-keepalive", "billing_key_hash": "main-keepalive", "reserved_msats": 11, "status": "active", "created_at": 1790766376}, {"id": "66d5bdd9d9814f6fb1576ed6708f431e", "key_hash": "main-endless-disconnect", "billing_key_hash": "main-endless-disconnect", "reserved_msats": 11, "status": "active", "created_at": 1790766374}, {"id": "a891d80b8db64e488f8896936cd5f2fe", "key_hash": "main-silent", "billing_key_hash": "main-silent", "reserved_msats": 11, "status": "charged", "created_at": 1790766368}, {"id": "6ebb7f0829bd4f569d9d2516dabd9fed", "key_hash": "main-silent-disconnect", "billing_key_hash": "main-silent-disconnect", "reserved_msats": 11, "status": "charged", "created_at": 1790766368}, {"id": "e14358bc6e7249c0ac7335c9d87e7b43", "key_hash": "main-header", "billing_key_hash": "main-header", "reserved_msats": 11, "status": "released", "created_at": 1790766368}, {"id": "26c897009e294f94b75ca51f071d335a", "key_hash": "main-finite", "billing_key_hash": "main-finite", "reserved_msats": 11, "status": "charged", "created_at": 1790766366}]} -REFUND endless-disconnect 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"c272c298-bace-482c-926f-0c56fdaeaa5e"} -REFUND keepalive 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"3c1124f6-1c21-4417-b4fb-2ffdead58c31"} -REFUND flood 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"afca3cab-361a-48f6-85e9-58247c17a5f2"} -UPSTREAM_EVENTS [{"event": "start", "mode": "flood", "time": 1790766366.393702}, {"event": "start", "mode": "keepalive", "time": 1790766366.408879}, {"event": "start", "mode": "endless-disconnect", "time": 1790766366.4305305}, {"event": "start", "mode": "silent", "time": 1790766366.4564564}, {"event": "start", "mode": "silent-disconnect", "time": 1790766366.4789124}, {"event": "start", "mode": "header", "time": 1790766366.5032742}, {"event": "start", "mode": "finite", "time": 1790766366.5216281}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790766367.5249321}] -AFTER_SWEEP {"time": 1790766437.9892845, "keys": [{"hashed_key": "main-finite", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent-disconnect", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-endless-disconnect", "balance": 1000000000, "reserved_balance": 11, "reserved_at": 1790766366}, {"hashed_key": "main-keepalive", "balance": 1000000000, "reserved_balance": 11, "reserved_at": 1790766366}, {"hashed_key": "main-flood", "balance": 1000000000, "reserved_balance": 11, "reserved_at": 1790766366}, {"hashed_key": "main-header", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}], "rows": [{"id": "50569f573caf4d6fb7916da3570493db", "key_hash": "main-flood", "billing_key_hash": "main-flood", "reserved_msats": 11, "status": "active", "created_at": 1790766436}, {"id": "0ffb4d61dc0d4aaf9e518c74b7afd1bb", "key_hash": "main-keepalive", "billing_key_hash": "main-keepalive", "reserved_msats": 11, "status": "active", "created_at": 1790766436}, {"id": "66d5bdd9d9814f6fb1576ed6708f431e", "key_hash": "main-endless-disconnect", "billing_key_hash": "main-endless-disconnect", "reserved_msats": 11, "status": "active", "created_at": 1790766436}, {"id": "a891d80b8db64e488f8896936cd5f2fe", "key_hash": "main-silent", "billing_key_hash": "main-silent", "reserved_msats": 11, "status": "charged", "created_at": 1790766368}, {"id": "6ebb7f0829bd4f569d9d2516dabd9fed", "key_hash": "main-silent-disconnect", "billing_key_hash": "main-silent-disconnect", "reserved_msats": 11, "status": "charged", "created_at": 1790766368}, {"id": "e14358bc6e7249c0ac7335c9d87e7b43", "key_hash": "main-header", "billing_key_hash": "main-header", "reserved_msats": 11, "status": "released", "created_at": 1790766368}, {"id": "26c897009e294f94b75ca51f071d335a", "key_hash": "main-finite", "billing_key_hash": "main-finite", "reserved_msats": 11, "status": "charged", "created_at": 1790766366}]} -REFUND endless-disconnect 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"4a00cdce-d049-4be8-940f-2a652349c1f9"} -REFUND keepalive 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"bcf3b7d4-ae59-494c-8049-bb43476211e8"} -REFUND flood 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"4b459580-84d1-480a-b1cb-28898a04395e"} -UPSTREAM_EVENTS [{"event": "start", "mode": "flood", "time": 1790766366.393702}, {"event": "start", "mode": "keepalive", "time": 1790766366.408879}, {"event": "start", "mode": "endless-disconnect", "time": 1790766366.4305305}, {"event": "start", "mode": "silent", "time": 1790766366.4564564}, {"event": "start", "mode": "silent-disconnect", "time": 1790766366.4789124}, {"event": "start", "mode": "header", "time": 1790766366.5032742}, {"event": "start", "mode": "finite", "time": 1790766366.5216281}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790766367.5249321}] -CLIENT_DISCONNECTED keepalive -AFTER_ALL_CLIENTS_CLOSED {"time": 1790766447.4688976, "keys": [{"hashed_key": "main-finite", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-silent-disconnect", "balance": 999999997, "reserved_balance": 0, "reserved_at": null}, {"hashed_key": "main-endless-disconnect", "balance": 1000000000, "reserved_balance": 11, "reserved_at": 1790766366}, {"hashed_key": "main-keepalive", "balance": 1000000000, "reserved_balance": 11, "reserved_at": 1790766366}, {"hashed_key": "main-flood", "balance": 1000000000, "reserved_balance": 11, "reserved_at": 1790766366}, {"hashed_key": "main-header", "balance": 1000000000, "reserved_balance": 0, "reserved_at": null}], "rows": [{"id": "50569f573caf4d6fb7916da3570493db", "key_hash": "main-flood", "billing_key_hash": "main-flood", "reserved_msats": 11, "status": "active", "created_at": 1790766447}, {"id": "0ffb4d61dc0d4aaf9e518c74b7afd1bb", "key_hash": "main-keepalive", "billing_key_hash": "main-keepalive", "reserved_msats": 11, "status": "active", "created_at": 1790766446}, {"id": "66d5bdd9d9814f6fb1576ed6708f431e", "key_hash": "main-endless-disconnect", "billing_key_hash": "main-endless-disconnect", "reserved_msats": 11, "status": "active", "created_at": 1790766446}, {"id": "a891d80b8db64e488f8896936cd5f2fe", "key_hash": "main-silent", "billing_key_hash": "main-silent", "reserved_msats": 11, "status": "charged", "created_at": 1790766368}, {"id": "6ebb7f0829bd4f569d9d2516dabd9fed", "key_hash": "main-silent-disconnect", "billing_key_hash": "main-silent-disconnect", "reserved_msats": 11, "status": "charged", "created_at": 1790766368}, {"id": "e14358bc6e7249c0ac7335c9d87e7b43", "key_hash": "main-header", "billing_key_hash": "main-header", "reserved_msats": 11, "status": "released", "created_at": 1790766368}, {"id": "26c897009e294f94b75ca51f071d335a", "key_hash": "main-finite", "billing_key_hash": "main-finite", "reserved_msats": 11, "status": "charged", "created_at": 1790766366}]} -REFUND endless-disconnect 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"67367fbb-2fd6-4ce7-a0e3-3b1d0f30cb76"} -REFUND keepalive 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"96f8b70c-584e-476d-aa9c-ea9092e9393f"} -REFUND flood 400 {"detail":"Cannot refund key. There are ongoing requests for this api key.","request_id":"60ac9762-dc92-4e08-9456-77346a70a63d"} -UPSTREAM_EVENTS [{"event": "start", "mode": "flood", "time": 1790766366.393702}, {"event": "start", "mode": "keepalive", "time": 1790766366.408879}, {"event": "start", "mode": "endless-disconnect", "time": 1790766366.4305305}, {"event": "start", "mode": "silent", "time": 1790766366.4564564}, {"event": "start", "mode": "silent-disconnect", "time": 1790766366.4789124}, {"event": "start", "mode": "header", "time": 1790766366.5032742}, {"event": "start", "mode": "finite", "time": 1790766366.5216281}, {"event": "close", "mode": "finite", "chunks": 3, "time": 1790766367.5249321}] diff --git a/reservation-repro-main/router.log b/reservation-repro-main/router.log deleted file mode 100644 index f2e7c738..00000000 --- a/reservation-repro-main/router.log +++ /dev/null @@ -1,114 +0,0 @@ -/.venv/lib/python3.14/site-packages/anyio/from_thread.py:119: SyntaxWarning: 'return' in a 'finally' block - return result -2026-09-30 11:05:28 WARNING routstr.core.main UI dist directory not found at /app/ui_out; serving API only. Run `make ui-build` to build the static UI served from here, or `make ui-dev` for the Next.js dev server with hot reload on :3000 (it targets this backend on :8000). -2026-09-30 11:05:28 INFO uvicorn.error Started server process [1] -2026-09-30 11:05:28 INFO uvicorn.error Waiting for application startup. -2026-09-30 11:05:28 INFO routstr.core.main Application startup initiated -2026-09-30 11:05:30 INFO routstr.core.db Database migrations completed successfully -2026-09-30 11:05:30 INFO routstr.core.db Reset reserved balances on startup -2026-09-30 11:05:30 INFO routstr.upstream.helpers Seeding custom provider -2026-09-30 11:05:30 INFO routstr.upstream.helpers Seeded 1 upstream providers from settings -2026-09-30 11:05:31 INFO routstr.proxy Initialized 1 upstream providers -2026-09-30 11:05:31 INFO routstr.nostr.listing Nostr private key not configured (NSEC); waiting for one to be set before announcing this provider -2026-09-30 11:05:31 INFO routstr.nostr.analytics Usage analytics sharing task started -2026-09-30 11:05:31 INFO routstr.nostr.analytics NSEC is not configured; skipping analytics sharing to Nostr -2026-09-30 11:05:31 INFO routstr.auth Dead-key pruning disabled (interval <= 0) -2026-09-30 11:05:31 INFO uvicorn.error Application startup complete. -2026-09-30 11:05:31 INFO uvicorn.error Uvicorn running on http://127.0.0.1:18090 (Press CTRL+C to quit) -2026-09-30 11:06:01 INFO routstr.upstream.auto_topup Auto top-up worker started -2026-09-30 11:06:06 INFO routstr.auth Existing sk- API key found -2026-09-30 11:06:06 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:06:06 INFO routstr.auth Processing payment for request -2026-09-30 11:06:06 INFO routstr.auth Existing sk- API key found -2026-09-30 11:06:06 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:06:06 INFO routstr.auth Processing payment for request -2026-09-30 11:06:06 INFO routstr.auth Existing sk- API key found -2026-09-30 11:06:06 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:06:06 INFO routstr.auth Processing payment for request -2026-09-30 11:06:06 INFO routstr.auth Existing sk- API key found -2026-09-30 11:06:06 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:06:06 INFO routstr.auth Processing payment for request -2026-09-30 11:06:06 INFO routstr.auth Existing sk- API key found -2026-09-30 11:06:06 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:06:06 INFO routstr.auth Processing payment for request -2026-09-30 11:06:06 INFO routstr.auth Existing sk- API key found -2026-09-30 11:06:06 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:06:06 INFO routstr.auth Processing payment for request -2026-09-30 11:06:06 INFO routstr.auth Existing sk- API key found -2026-09-30 11:06:06 INFO routstr.proxy Bearer token validated successfully -2026-09-30 11:06:06 INFO routstr.auth Processing payment for request -2026-09-30 11:06:06 INFO routstr.auth Payment processed successfully -2026-09-30 11:06:06 INFO routstr.payments RESERVE -2026-09-30 11:06:06 INFO routstr.auth Payment processed successfully -2026-09-30 11:06:06 INFO routstr.payments RESERVE -2026-09-30 11:06:06 INFO routstr.auth Payment processed successfully -2026-09-30 11:06:06 INFO routstr.payments RESERVE -2026-09-30 11:06:06 INFO routstr.auth Payment processed successfully -2026-09-30 11:06:06 INFO routstr.payments RESERVE -2026-09-30 11:06:06 INFO routstr.auth Payment processed successfully -2026-09-30 11:06:06 INFO routstr.payments RESERVE -2026-09-30 11:06:06 INFO routstr.auth Payment processed successfully -2026-09-30 11:06:06 INFO routstr.payments RESERVE -2026-09-30 11:06:06 INFO routstr.auth Payment processed successfully -2026-09-30 11:06:06 INFO routstr.payments RESERVE -2026-09-30 11:06:07 INFO routstr.payment.cost_calculation Applied model-specific pricing -2026-09-30 11:06:07 INFO routstr.payment.cost_calculation Calculated token-based cost -2026-09-30 11:06:07 INFO routstr.auth Calculated token-based cost -2026-09-30 11:06:07 INFO routstr.auth Refunding excess payment -2026-09-30 11:06:07 INFO routstr.auth Refund processed successfully -2026-09-30 11:06:07 INFO routstr.payments FINALIZE -2026-09-30 11:06:07 INFO routstr.auth Payment settlement finished -2026-09-30 11:06:09 WARNING routstr.upstream.base Streaming interrupted; finalizing before closing upstream -2026-09-30 11:06:09 INFO routstr.payment.cost_calculation Applied model-specific pricing -2026-09-30 11:06:09 INFO routstr.payment.cost_calculation Calculated token-based cost -2026-09-30 11:06:09 INFO routstr.auth Calculated token-based cost -2026-09-30 11:06:09 INFO routstr.auth Refunding excess payment -2026-09-30 11:06:09 WARNING routstr.upstream.base Streaming interrupted; finalizing before closing upstream -2026-09-30 11:06:09 INFO routstr.auth Refund processed successfully -2026-09-30 11:06:09 INFO routstr.payment.cost_calculation Applied model-specific pricing -2026-09-30 11:06:09 INFO routstr.payment.cost_calculation Calculated token-based cost -2026-09-30 11:06:09 INFO routstr.auth Calculated token-based cost -2026-09-30 11:06:09 INFO routstr.auth Refunding excess payment -2026-09-30 11:06:09 ERROR routstr.upstream.base HTTP request error to upstream -2026-09-30 11:06:09 WARNING routstr.proxy Upstream base failed for model=gpt-4o-mini: Upstream service request timed out -2026-09-30 11:06:09 INFO routstr.auth Refund processed successfully -2026-09-30 11:06:09 INFO routstr.payments FINALIZE -2026-09-30 11:06:09 INFO routstr.auth Payment settlement finished -2026-09-30 11:06:09 ERROR routstr.core.exceptions Unhandled exception -httpcore.ReadTimeout - -The above exception was the direct cause of the following exception: - -httpx.ReadTimeout -2026-09-30 11:06:09 ERROR uvicorn.error Exception in ASGI application -httpcore.ReadTimeout - -The above exception was the direct cause of the following exception: - -httpx.ReadTimeout -2026-09-30 11:06:09 INFO routstr.payments FINALIZE -2026-09-30 11:06:09 INFO routstr.auth Payment settlement finished -2026-09-30 11:06:09 ERROR routstr.core.exceptions Unhandled exception -httpcore.ReadTimeout - -The above exception was the direct cause of the following exception: - -httpx.ReadTimeout -2026-09-30 11:06:09 ERROR uvicorn.error Exception in ASGI application -httpcore.ReadTimeout - -The above exception was the direct cause of the following exception: - -httpx.ReadTimeout -2026-09-30 11:06:16 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. -2026-09-30 11:06:17 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. -2026-09-30 11:06:17 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. -2026-09-30 11:07:18 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. -2026-09-30 11:07:18 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. -2026-09-30 11:07:19 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. -2026-09-30 11:07:28 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. -2026-09-30 11:07:28 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. -2026-09-30 11:07:28 INFO routstr.core.exceptions HTTP 400 on /v1/wallet/refund: Cannot refund key. There are ongoing requests for this api key. -2026-09-30 11:10:38 WARNING routstr.upstream.base Upstream stream ended before the response was complete -2026-09-30 11:10:38 WARNING routstr.upstream.base Upstream stream ended before the response was complete -2026-09-30 11:10:38 WARNING routstr.upstream.base Upstream stream ended before the response was complete diff --git a/reservation-repro-main/starlette-source.txt b/reservation-repro-main/starlette-source.txt deleted file mode 100644 index 78736b3f..00000000 --- a/reservation-repro-main/starlette-source.txt +++ /dev/null @@ -1,169 +0,0 @@ - async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None: - if scope["type"] != "http": - await self.app(scope, receive, send) - return - - request = _CachedRequest(scope, receive) - wrapped_receive = request.wrapped_receive - response_sent = anyio.Event() - app_exc: Exception | None = None - exception_already_raised = False - - async def call_next(request: Request) -> Response: - async def receive_or_disconnect() -> Message: - if response_sent.is_set(): - return {"type": "http.disconnect"} - - async with anyio.create_task_group() as task_group: - - async def wrap(func: Callable[[], Awaitable[T]]) -> T: - result = await func() - task_group.cancel_scope.cancel() - return result - - task_group.start_soon(wrap, response_sent.wait) - message = await wrap(wrapped_receive) - - if response_sent.is_set(): - return {"type": "http.disconnect"} - - return message - - async def send_no_error(message: Message) -> None: - try: - await send_stream.send(message) - except anyio.BrokenResourceError: - # recv_stream has been closed, i.e. response_sent has been set. - return - - async def coro() -> None: - nonlocal app_exc - - with send_stream: - try: - await self.app(scope, receive_or_disconnect, send_no_error) - except Exception as exc: - app_exc = exc - - task_group.start_soon(coro) - - try: - message = await recv_stream.receive() - info = message.get("info", None) - if message["type"] == "http.response.debug" and info is not None: - message = await recv_stream.receive() - except anyio.EndOfStream: - if app_exc is not None: - nonlocal exception_already_raised - exception_already_raised = True - # Prevent `anyio.EndOfStream` from polluting app exception context. - # If both cause and context are None then the context is suppressed - # and `anyio.EndOfStream` is not present in the exception traceback. - # If exception cause is not None then it is propagated with - # reraising here. - # If exception has no cause but has context set then the context is - # propagated as a cause with the reraise. This is necessary in order - # to prevent `anyio.EndOfStream` from polluting the exception - # context. - raise app_exc from app_exc.__cause__ or app_exc.__context__ - raise RuntimeError("No response returned.") - - assert message["type"] == "http.response.start" - - async def body_stream() -> BodyStreamGenerator: - async for message in recv_stream: - if message["type"] == "http.response.pathsend": - yield message - break - assert message["type"] == "http.response.body", f"Unexpected message: {message}" - body = message.get("body", b"") - if body: - yield body - if not message.get("more_body", False): - break - - response = _StreamingResponse(status_code=message["status"], content=body_stream(), info=info) - response.raw_headers = message["headers"] - return response - - streams: anyio.create_memory_object_stream[Message] = anyio.create_memory_object_stream() - send_stream, recv_stream = streams - with recv_stream, send_stream: - async with create_collapsing_task_group() as task_group: - response = await self.dispatch_func(request, call_next) - await response(scope, wrapped_receive, send) - response_sent.set() - recv_stream.close() - if app_exc is not None and not exception_already_raised: - raise app_exc - -class _StreamingResponse(Response): - def __init__( - self, - content: AsyncContentStream, - status_code: int = 200, - headers: Mapping[str, str] | None = None, - media_type: str | None = None, - info: Mapping[str, Any] | None = None, - ) -> None: - self.info = info - self.body_iterator = content - self.status_code = status_code - self.media_type = media_type - self.init_headers(headers) - self.background = None - - async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None: - if self.info is not None: - await send({"type": "http.response.debug", "info": self.info}) - await send( - { - "type": "http.response.start", - "status": self.status_code, - "headers": self.raw_headers, - } - ) - - should_close_body = True - async for chunk in self.body_iterator: - if isinstance(chunk, dict): - # We got an ASGI message which is not response body (eg: pathsend) - should_close_body = False - await send(chunk) - continue - await send({"type": "http.response.body", "body": chunk, "more_body": True}) - - if should_close_body: - await send({"type": "http.response.body", "body": b"", "more_body": False}) - - if self.background: - await self.background() - - async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None: - if scope["type"] == "websocket": - send = self._wrap_websocket_denial_send(send) - await self.stream_response(send) - if self.background is not None: - await self.background() - return - - spec_version = tuple(map(int, scope.get("asgi", {}).get("spec_version", "2.0").split("."))) - - if spec_version >= (2, 4): - try: - await self.stream_response(send) - except OSError: - raise ClientDisconnect() - else: - async with create_collapsing_task_group() as task_group: - - async def wrap(func: Callable[[], Awaitable[None]]) -> None: - await func() - task_group.cancel_scope.cancel() - - task_group.start_soon(wrap, partial(self.stream_response, send)) - await wrap(partial(self.listen_for_disconnect, receive)) - - if self.background is not None: - await self.background() - diff --git a/reservation-repro-main/upstream.log b/reservation-repro-main/upstream.log deleted file mode 100644 index 2f124bcd..00000000 --- a/reservation-repro-main/upstream.log +++ /dev/null @@ -1,23 +0,0 @@ -/.venv/lib/python3.14/site-packages/anyio/from_thread.py:119: SyntaxWarning: 'return' in a 'finally' block - return result -INFO: Started server process [1] -INFO: Waiting for application startup. -INFO: Application startup complete. -INFO: Uvicorn running on http://127.0.0.1:18091 (Press CTRL+C to quit) -INFO: 127.0.0.1:59686 - "GET /v1/models HTTP/1.1" 200 OK -INFO: 127.0.0.1:36380 - "POST /v1/chat/completions HTTP/1.1" 200 OK -INFO: 127.0.0.1:36394 - "POST /v1/chat/completions HTTP/1.1" 200 OK -INFO: 127.0.0.1:36402 - "POST /v1/chat/completions HTTP/1.1" 200 OK -INFO: 127.0.0.1:36418 - "POST /v1/chat/completions HTTP/1.1" 200 OK -INFO: 127.0.0.1:36434 - "POST /v1/chat/completions HTTP/1.1" 200 OK -INFO: 127.0.0.1:36456 - "POST /v1/chat/completions HTTP/1.1" 200 OK -{"event": "close", "mode": "finite", "chunks": 3, "time": 1790766367.5249321} -INFO: 127.0.0.1:54322 - "GET /events HTTP/1.1" 200 OK -INFO: 127.0.0.1:51770 - "GET /events HTTP/1.1" 200 OK -INFO: 127.0.0.1:42140 - "GET /events HTTP/1.1" 200 OK -INFO: 127.0.0.1:50608 - "GET /v1/models HTTP/1.1" 200 OK -INFO: 127.0.0.1:46164 - "POST /v1/chat/completions HTTP/1.1" 200 OK -INFO: 127.0.0.1:46178 - "POST /v1/chat/completions HTTP/1.1" 200 OK -INFO: 127.0.0.1:39728 - "GET /events HTTP/1.1" 200 OK -INFO: Shutting down -INFO: Waiting for connections to close. (CTRL+C to force quit) diff --git a/reservation-repro-main/uvicorn-source.txt b/reservation-repro-main/uvicorn-source.txt deleted file mode 100644 index 2c5d74b3..00000000 --- a/reservation-repro-main/uvicorn-source.txt +++ /dev/null @@ -1,125 +0,0 @@ - async def send(self, message: ASGISendEvent) -> None: - message_type = message["type"] - - if self.flow.write_paused and not self.disconnected: - await self.flow.drain() # pragma: full coverage - - if self.disconnected: - return # pragma: full coverage - - if not self.response_started: - # Sending response status line and headers - if message_type != "http.response.start": - msg = "Expected ASGI message 'http.response.start', but got '%s'." - raise RuntimeError(msg % message_type) - message = cast("HTTPResponseStartEvent", message) - - self.response_started = True - self.waiting_for_100_continue = False - - status_code = message["status"] - headers = self.default_headers + list(message.get("headers", [])) - - if CLOSE_HEADER in self.scope["headers"] and CLOSE_HEADER not in headers: - headers = headers + [CLOSE_HEADER] - - if self.access_log: - self.access_logger.info( - '%s - "%s %s HTTP/%s" %d', - get_client_addr(self.scope), - self.scope["method"], - get_path_with_query_string(self.scope), - self.scope["http_version"], - status_code, - ) - - # Write response status line and headers - content = [STATUS_LINE[status_code]] - - for name, value in headers: - if HEADER_RE.search(name): - raise RuntimeError("Invalid HTTP header name.") # pragma: full coverage - if HEADER_VALUE_RE.search(value): - raise RuntimeError("Invalid HTTP header value.") - - name = name.lower() - if name == b"content-length" and self.chunked_encoding is None: - self.expected_content_length = int(value.decode()) - self.chunked_encoding = False - elif name == b"transfer-encoding" and value.lower() == b"chunked": - self.expected_content_length = 0 - self.chunked_encoding = True - elif name == b"connection" and value.lower() == b"close": - self.keep_alive = False - content.extend([name, b": ", value, b"\r\n"]) - - if self.chunked_encoding is None and self.scope["method"] != "HEAD" and status_code not in (204, 304): - # Neither content-length nor transfer-encoding specified - self.chunked_encoding = True - content.append(b"transfer-encoding: chunked\r\n") - - content.append(b"\r\n") - self.transport.write(b"".join(content)) - - elif not self.response_complete: - # Sending response body - if message_type != "http.response.body": - msg = "Expected ASGI message 'http.response.body', but got '%s'." - raise RuntimeError(msg % message_type) - - body = cast(bytes, message.get("body", b"")) - more_body = message.get("more_body", False) - - # Write response body - if self.scope["method"] == "HEAD": - self.expected_content_length = 0 - elif self.chunked_encoding: - if body: - content = [b"%x\r\n" % len(body), body, b"\r\n"] - else: - content = [] - if not more_body: - content.append(b"0\r\n\r\n") - self.transport.write(b"".join(content)) - else: - num_bytes = len(body) - if num_bytes > self.expected_content_length: - raise RuntimeError("Response content longer than Content-Length") - else: - self.expected_content_length -= num_bytes - self.transport.write(body) - - # Handle response completion - if not more_body: - if self.expected_content_length != 0: - raise RuntimeError("Response content shorter than Content-Length") - self.response_complete = True - self.message_event.set() - if not self.keep_alive: - self.transport.close() - self.on_response() - - else: - # Response already sent - msg = "Unexpected ASGI message '%s' sent, after response already completed." - raise RuntimeError(msg % message_type) - - def connection_lost(self, exc: Exception | None) -> None: - self.connections.discard(self) - - if self.logger.level <= TRACE_LOG_LEVEL: - prefix = "%s:%d - " % self.client if self.client else "" - self.logger.log(TRACE_LOG_LEVEL, "%sHTTP connection lost", prefix) - - if self.cycle and not self.cycle.response_complete: - self.cycle.disconnected = True - if self.cycle is not None: - self.cycle.message_event.set() - if self.flow is not None: - self.flow.resume_writing() - if exc is None: - self.transport.close() - self._unset_keepalive_if_required() - - self.parser = None - diff --git a/routstr/auth.py b/routstr/auth.py index b7c8e16a..87eb60fd 100644 --- a/routstr/auth.py +++ b/routstr/auth.py @@ -695,8 +695,12 @@ async def pay_for_request( reserved_msats=reservation.reserved_msats, status="active", started_at=reserved_at_now, + # reserved_at_now floors to the second; add 1s margin so a + # finalizer finishing right at the nominal deadline isn't fenced + # out by truncation. expires_at=reserved_at_now - + math.ceil(remaining_lifetime + settings.request_cleanup_timeout_seconds), + + math.ceil(remaining_lifetime + settings.request_cleanup_timeout_seconds) + + 1, ) ) # Publish the identity before commit. If the commit succeeds but its @@ -737,11 +741,6 @@ async def pay_for_request( # The reservation is durable; keep its lease fresh for the whole request # lifetime (upstream header waits, non-streaming and streaming alike). - from .core.lifecycle import request_lifetime - - lifetime = request_lifetime.get() - if lifetime is not None: - lifetime.reservations.append(reservation) _start_reservation_heartbeat(reservation) try: diff --git a/routstr/core/lifecycle.py b/routstr/core/lifecycle.py index dad968ba..039ac046 100644 --- a/routstr/core/lifecycle.py +++ b/routstr/core/lifecycle.py @@ -4,11 +4,7 @@ from __future__ import annotations import asyncio from contextvars import ContextVar -from dataclasses import dataclass, field -from typing import TYPE_CHECKING - -if TYPE_CHECKING: - from ..auth import ReservationSnapshot +from dataclasses import dataclass from starlette.types import ASGIApp, Message, Receive, Scope, Send @@ -18,11 +14,14 @@ from .settings import settings logger = get_logger(__name__) +class DownstreamTerminated(OSError): + """Raised by downstream_send after disconnect; expected, not a server error.""" + + @dataclass class RequestLifetime: deadline: float = 0 stopped: bool = False - reservations: list[ReservationSnapshot] = field(default_factory=list) request_lifetime: ContextVar[RequestLifetime | None] = ContextVar( @@ -75,7 +74,7 @@ class RequestLifecycleMiddleware: async def downstream_send(message: Message) -> None: nonlocal response_started if disconnected.is_set() or lifetime.stopped: - raise OSError("Downstream request terminated") + raise DownstreamTerminated("Downstream request terminated") async with asyncio.timeout(settings.downstream_send_timeout_seconds): await send(message) if message["type"] == "http.response.start": @@ -86,27 +85,35 @@ class RequestLifecycleMiddleware: self.app(scope, downstream_receive, downstream_send) ) gone = asyncio.create_task(disconnected.wait()) + timed_out = False try: done, _ = await asyncio.wait( (work, gone), timeout=settings.max_request_lifetime_seconds, return_when=asyncio.FIRST_COMPLETED, ) + if gone in done and not response_started and work not in done: + # A pre-response wallet or billing operation may have accepted + # funds already. Let it reach its own settlement before closing. + done, _ = await asyncio.wait( + (work,), + timeout=max(0, lifetime.deadline - asyncio.get_running_loop().time()), + ) if work in done: - await work - elif not disconnected.is_set() and not response_started: - await downstream_send( - {"type": "http.response.start", "status": 504, "headers": []} - ) - await downstream_send( - {"type": "http.response.body", "body": b"Request deadline exceeded"} - ) + try: + await work + except DownstreamTerminated: + if not disconnected.is_set(): + raise + logger.debug("Client disconnected before response completed") + elif not disconnected.is_set(): + timed_out = True finally: lifetime.stopped = True for task in (receiver, gone, work): task.cancel() - # Cancellation/close is bounded: an uncooperative finalizer must not - # hold ownership or renewal indefinitely. + # Detached stream finalizers own settlement. The heartbeat stops + # with the request; durable expiry recovers any abandoned row. done, pending = await asyncio.wait( (receiver, gone, work), timeout=settings.request_cleanup_timeout_seconds ) @@ -118,20 +125,10 @@ class RequestLifecycleMiddleware: task.add_done_callback( lambda t: t.exception() if not t.cancelled() else None ) - try: - async with asyncio.timeout(settings.request_cleanup_timeout_seconds): - from ..auth import _stop_reservation_heartbeat, release_reservation - from .db import create_session - - for snapshot in lifetime.reservations: - await _stop_reservation_heartbeat(snapshot.release_id) - async with create_session() as session: - await release_reservation( - snapshot, session, snapshot.reserved_msats - ) - except Exception: - logger.exception( - "Request cleanup failed; durable expiry will recover reservations" + request_lifetime.reset(token) + if timed_out and work.done() and not disconnected.is_set() and not response_started: + async with asyncio.timeout(settings.downstream_send_timeout_seconds): + await send({"type": "http.response.start", "status": 504, "headers": []}) + await send( + {"type": "http.response.body", "body": b"Request deadline exceeded"} ) - finally: - request_lifetime.reset(token) diff --git a/tests/unit/test_request_lifecycle.py b/tests/unit/test_request_lifecycle.py index 41c76e50..1573f074 100644 --- a/tests/unit/test_request_lifecycle.py +++ b/tests/unit/test_request_lifecycle.py @@ -1,10 +1,30 @@ import asyncio +from collections.abc import AsyncGenerator +from contextlib import asynccontextmanager +from pathlib import Path from unittest.mock import patch import pytest +from sqlalchemy.ext.asyncio import create_async_engine +from sqlalchemy.pool import NullPool +from sqlmodel import SQLModel +from sqlmodel.ext.asyncio.session import AsyncSession +from starlette.applications import Starlette +from starlette.requests import Request +from starlette.responses import PlainTextResponse +from starlette.routing import Route from starlette.types import Message, Receive, Scope, Send +import routstr.core.db as db_module +from routstr.auth import ( + ReservationSnapshot, + _claim_reservation_for_charge, + _stop_reservation_heartbeat, + pay_for_request, +) +from routstr.core.db import ApiKey, ReservationRelease from routstr.core.lifecycle import RequestLifecycleMiddleware +from routstr.core.middleware import LoggingMiddleware from routstr.core.settings import settings @@ -56,3 +76,210 @@ async def test_lifecycle_stops_live_work(reason: str) -> None: await task assert closed.is_set() assert sent + + +@pytest.mark.asyncio +async def test_unrelated_oserror_still_propagates() -> None: + receive_queue: asyncio.Queue[Message] = asyncio.Queue() + await receive_queue.put({"type": "http.request", "body": b"", "more_body": False}) + + async def app(scope: Scope, receive: Receive, send: Send) -> None: + await receive() + raise OSError("Connection reset by peer") + + async def send(message: Message) -> None: + pass + + with pytest.raises(OSError, match="Connection reset by peer"): + await asyncio.wait_for( + RequestLifecycleMiddleware(app)({"type": "http"}, receive_queue.get, send), + 1, + ) + + +@pytest.mark.asyncio +async def test_disconnect_before_headers_preserves_wallet_work() -> None: + receive_queue: asyncio.Queue[Message] = asyncio.Queue() + await receive_queue.put({"type": "http.request", "body": b"", "more_body": False}) + entered = asyncio.Event() + finish_wallet = asyncio.Event() + wallet_credited = asyncio.Event() + + async def app(scope: Scope, receive: Receive, send: Send) -> None: + await receive() + entered.set() + await finish_wallet.wait() # The mint accepted the token; credit is still pending. + wallet_credited.set() + await send({"type": "http.response.start", "status": 200, "headers": []}) + + run = asyncio.create_task( + RequestLifecycleMiddleware(app)( + {"type": "http"}, receive_queue.get, lambda message: asyncio.sleep(0) + ) + ) + await asyncio.wait_for(entered.wait(), 1) + await receive_queue.put({"type": "http.disconnect"}) + await asyncio.sleep(0.02) + assert not run.done() + finish_wallet.set() + await asyncio.wait_for(run, 1) # No propagated exception for an expected disconnect. + assert wallet_credited.is_set() + + +@pytest.mark.asyncio +async def test_disconnect_before_headers_with_logging_middleware() -> None: + receive_queue: asyncio.Queue[Message] = asyncio.Queue() + await receive_queue.put({"type": "http.request", "body": b"", "more_body": False}) + entered = asyncio.Event() + finish_wallet = asyncio.Event() + wallet_credited = asyncio.Event() + + async def wallet(request: Request) -> PlainTextResponse: + await request.body() + entered.set() + await finish_wallet.wait() + wallet_credited.set() + return PlainTextResponse("settled") + + app = RequestLifecycleMiddleware( + LoggingMiddleware(Starlette(routes=[Route("/wallet", wallet, methods=["POST"])])) + ) + scope: Scope = { + "type": "http", + "asgi": {"version": "3.0", "spec_version": "2.4"}, + "http_version": "1.1", + "method": "POST", + "scheme": "http", + "path": "/wallet", + "raw_path": b"/wallet", + "root_path": "", + "query_string": b"", + "headers": [], + "client": ("test", 1234), + "server": ("test", 80), + } + + async def send(message: Message) -> None: + pass + + run = asyncio.create_task(app(scope, receive_queue.get, send)) + try: + await asyncio.wait_for(entered.wait(), 1) + await receive_queue.put({"type": "http.disconnect"}) + await asyncio.sleep(0.02) + assert not run.done() + finish_wallet.set() + await asyncio.wait_for(run, 1) # No propagated exception for an expected disconnect. + assert wallet_credited.is_set() + finally: + finish_wallet.set() + if not run.done(): + run.cancel() + await asyncio.gather(run, return_exceptions=True) + + +@pytest.mark.asyncio +async def test_deadline_cancels_app_before_sending_504() -> None: + receive_queue: asyncio.Queue[Message] = asyncio.Queue() + await receive_queue.put({"type": "http.request", "body": b"", "more_body": False}) + sent: list[Message] = [] + app_stopped = asyncio.Event() + + async def app(scope: Scope, receive: Receive, send: Send) -> None: + await receive() + try: + await asyncio.sleep(100) + finally: + with pytest.raises(OSError, match="Downstream request terminated"): + await send({"type": "http.response.start", "status": 200, "headers": []}) + app_stopped.set() + + async def send(message: Message) -> None: + assert app_stopped.is_set() + sent.append(message) + + with ( + patch.object(settings, "max_request_lifetime_seconds", 0.02), + patch.object(settings, "request_cleanup_timeout_seconds", 0.1), + ): + await asyncio.wait_for( + RequestLifecycleMiddleware(app)({"type": "http"}, receive_queue.get, send), + 1, + ) + assert [message["type"] for message in sent] == [ + "http.response.start", + "http.response.body", + ] + assert sent[0]["status"] == 504 + + +@pytest.mark.asyncio +async def test_disconnect_does_not_release_before_stream_settles(tmp_path: Path) -> None: + engine = create_async_engine( + f"sqlite+aiosqlite:///{tmp_path / 'reservations.db'}", poolclass=NullPool + ) + async with engine.begin() as conn: + await conn.run_sync(SQLModel.metadata.create_all) + + @asynccontextmanager + async def session() -> AsyncGenerator[AsyncSession, None]: + async with AsyncSession(engine, expire_on_commit=False) as db: + yield db + + with patch.object(db_module, "create_session", session): + async with session() as db: + db.add(ApiKey(hashed_key="stream-key", balance=10_000)) + await db.commit() + started = asyncio.Event() + finalizer_started = asyncio.Event() + settle = asyncio.Event() + result: asyncio.Future[bool] = asyncio.get_running_loop().create_future() + snapshot: ReservationSnapshot | None = None + receive_queue: asyncio.Queue[Message] = asyncio.Queue() + await receive_queue.put({"type": "http.request", "body": b"", "more_body": False}) + + async def app(scope: Scope, receive: Receive, send: Send) -> None: + nonlocal snapshot + async with session() as db: + key = await db.get(ApiKey, "stream-key") + assert key is not None + snapshot = await pay_for_request(key, 1000, db) + await receive() + await send({"type": "http.response.start", "status": 200, "headers": []}) + started.set() + try: + await asyncio.sleep(100) + finally: + async def finalize() -> None: + assert snapshot is not None + finalizer_started.set() + await settle.wait() + async with session() as db: + claimed = await _claim_reservation_for_charge(snapshot, db) + await db.commit() + await _stop_reservation_heartbeat(snapshot.release_id) + result.set_result(claimed) + + asyncio.create_task(finalize()) + + run = asyncio.create_task( + RequestLifecycleMiddleware(app)( + {"type": "http"}, receive_queue.get, lambda message: asyncio.sleep(0) + ) + ) + try: + await asyncio.wait_for(started.wait(), 1) + await receive_queue.put({"type": "http.disconnect"}) + await asyncio.wait_for(finalizer_started.wait(), 1) + await asyncio.wait_for(run, 1) + settle.set() + assert await asyncio.wait_for(result, 1) + assert snapshot is not None + async with session() as db: + row = await db.get(ReservationRelease, snapshot.release_id) + assert row is not None and row.status == "charged" + finally: + settle.set() + if snapshot is not None: + await _stop_reservation_heartbeat(snapshot.release_id) + await engine.dispose() diff --git a/tests/unit/test_stale_reservations.py b/tests/unit/test_stale_reservations.py index 6cd59682..61a3da5a 100644 --- a/tests/unit/test_stale_reservations.py +++ b/tests/unit/test_stale_reservations.py @@ -9,6 +9,7 @@ Covers: """ import asyncio +import math import time from typing import AsyncGenerator from unittest.mock import AsyncMock, MagicMock, patch @@ -69,7 +70,6 @@ async def test_pay_for_request_sets_reserved_at( payments_info = MagicMock() monkeypatch.setattr(auth_module.logger, "info", logger_info) monkeypatch.setattr(auth_module.payments_logger, "info", payments_info) - before = int(time.time()) await pay_for_request(key, 1_000, session) @@ -87,6 +87,34 @@ async def test_pay_for_request_sets_reserved_at( assert payments_info.call_args.args == ("RESERVE",) +@pytest.mark.asyncio +async def test_pay_for_request_expires_at_has_floor_margin( + session: AsyncSession, monkeypatch: pytest.MonkeyPatch +) -> None: + """reserved_at_now floors to the second; expires_at must add 1s so a + finalizer finishing exactly at the nominal deadline isn't fenced out.""" + key = ApiKey(hashed_key="floorkey", balance=10_000) + session.add(key) + await session.commit() + + fixed_time = 1_700_000_000.9 # fractional second, floors when int()'d + monkeypatch.setattr(auth_module.time, "time", lambda: fixed_time) + + snapshot = await pay_for_request(key, 1_000, session) + + row = await session.get(ReservationRelease, snapshot.release_id) + assert row is not None + expected = ( + int(fixed_time) + + math.ceil( + auth_module.settings.max_request_lifetime_seconds + + auth_module.settings.request_cleanup_timeout_seconds + ) + + 1 + ) + assert row.expires_at == expected + + @pytest.mark.asyncio @pytest.mark.asyncio async def test_pay_for_request_releases_reservation_when_validation_fails(