laantungir/routstr-core
1
0
Fork 0
mirror of https://github.com/Routstr/routstr-core.git synced 2026-10-05 12:28:22 +00:00
Code Issues Packages Projects Releases Wiki Activity

fix: let stream finalizers settle billing and remove repro artifacts

Browse Source
This commit is contained in:
9qeklajc
2026-09-30 21:47:47 +02:00
parent 2b24342a72
commit 53a4f3216c
28 changed files with 298 additions and 1725 deletions
Download Patch File Download Diff File Expand all files Collapse all files
.env.example
+6
View File
@@ -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
RESERVED_BALANCE.md
-541
View File
@@ -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.
pyproject.toml
+1 -2
View File
@@ -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 }
repro/IMPLEMENTATION.md
-46
View File
@@ -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.
repro/dummy_upstream.py
-45
View File
@@ -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')
repro/probe.py
-60
View File
@@ -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())
repro/results-final.txt
-19
View File
@@ -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}]
repro/results.txt
-19
View File
@@ -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}]
repro/router-final.log
-108
View File
@@ -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
repro/router-first.log
-115
View File
@@ -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
reservation-repro-main/README.md
-106
View File
@@ -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.
reservation-repro-main/after-upstream-stop.json
-1
View File
@@ -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]]}
reservation-repro-main/connections.txt
-7
View File
@@ -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))
reservation-repro-main/control-results.txt
-5
View File
@@ -1,5 +0,0 @@
endless-control 200
keepalive-control 200
[('endless-control', 12), ('keepalive-control', 12)]
[('endless-control', 'active'), ('keepalive-control', 'active')]
reservation-repro-main/control-router.log
-43
View File
@@ -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
reservation-repro-main/dummy_upstream.py
-45
View File
@@ -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')
reservation-repro-main/final-before-stop.json
-1
View File
@@ -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]]}
reservation-repro-main/no_logging_app.py
-4
View File
@@ -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]
reservation-repro-main/probe.py
-60
View File
@@ -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())
reservation-repro-main/results.txt
-27
View File
@@ -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}]
reservation-repro-main/router.log
-114
View File
@@ -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
reservation-repro-main/starlette-source.txt
-169
View File
@@ -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()
reservation-repro-main/upstream.log
-23
View File
@@ -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)
reservation-repro-main/uvicorn-source.txt
-125
View File
@@ -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
routstr/auth.py
+5 -6
View File
@@ -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:
routstr/core/lifecycle.py
+30 -33
View File
@@ -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)
tests/unit/test_request_lifecycle.py
+227
View File
@@ -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()
tests/unit/test_stale_reservations.py
+29 -1
View File
@@ -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(