Skip to content

Add a parallel FastAPI /borrow endpoint alongside the legacy web.py one - #13389

Open
cdrini wants to merge 10 commits into
internetarchive:masterfrom
cdrini:borrow-fastapi
Open

Add a parallel FastAPI /borrow endpoint alongside the legacy web.py one#13389
cdrini wants to merge 10 commits into
internetarchive:masterfrom
cdrini:borrow-fastapi

Conversation

@cdrini

@cdrini cdrini commented Aug 20, 2026

Copy link
Copy Markdown
Collaborator

/borrow is a common culprit causing webpy saturation especially when IA is slow. If we can asyncify that, that removes a bottleneck in our stack.

Technical

  • Does not remove the old webpy /borrow for now
  • There are still some IA requests this thing makes that are not covered here, namely get_loans , but that turned out to be a trickier refactor
  • This renders the interstitial.html page entirely in fastapi! Although it sidesteps the issues of trying to render the OL frame and just copies the small amount of CSS/JS needed to make that page work into the template

Testing

This is up on testing with the regex change, so try borrowing books on testing!

Screenshot

Stakeholders

claude and others added 5 commits August 20, 2026 16:13
Extracts the shared /borrow logic into borrow_post_core(), returning
outcome objects instead of raising/rendering directly, so both the
existing web.py handler and a new FastAPI route can translate them into
their own idiom. The legacy handler is left in place until the new one
is validated in production.

Co-Authored-By: Drini Cami <cdrini@gmail.com>
borrow_post_core, lending.s3_loan_api, lending.get_groundtruth_availability,
and user_can_borrow_edition all gain an _async implementation using
ia.async_session (httpx), each with a sync bridge (async_bridge.wrap) so
existing sync callers -- including the web.py handler -- keep working
unchanged. The FastAPI route now awaits borrow_post_core_async directly.

Also fixes get_s3_keys(), which read web.cookies()/web.ctx.site directly
and would have crashed for any logged-in request through the new FastAPI
route; callers that aren't running under a web.py request now pass the
raw "s3" cookie value in explicitly, and the account-store fallback goes
through the shared `site` contextvar instead of web.ctx.site.

Co-Authored-By: Drini Cami <cdrini@gmail.com>
…ridge

get_s3_keys() called web.cookies()/web.ctx directly. Since borrow_post_core
runs on AsyncBridge's dedicated background thread (where web.ctx, being
thread-local, was never populated), any logged-in user hitting /borrow hit
an AttributeError there -- confirmed live before this fix, 500s every time.

Splits cookie reading (get_s3_cookie(), web.py-only, must run on the
request's own thread) from decrypting it (parse_s3_cookie(), a pure
string -> dict function safe to call from anywhere) from the account-store
fallback (get_s3_keys(account), back to its original account-only shape).
Both borrow_post_core_async and account.py's loan-history lookup now read
the cookie themselves before crossing any thread/framework boundary and
pass the decrypted result along explicitly.

Co-Authored-By: Drini Cami <cdrini@gmail.com>
…fact

Co-Authored-By: Drini Cami <cdrini@gmail.com>
@cdrini
cdrini force-pushed the borrow-fastapi branch 2 times, most recently from 8ac1f4d to f72585e Compare August 20, 2026 23:07
Removes get_s3_keys()'s account-store fallback, now that no accounts use
it -- confirmed via querying store_index for s3_keys.access that the
earlier plaintext-to-cookie migration (and its purge script, since removed
in c8ca1ae) fully completed in production, so parse_s3_cookie() on the
session cookie is the only path left. Also dissolves get_s3_cookie(), a
thin wrapper with no callers left besides web.cookies().get("s3") itself.

Renames borrow_post_core_async/borrow_post_core to handle_borrow_async/
handle_borrow, matching the get_availability_async/get_availability
naming convention, and trims handle_borrow_async's docstring to just the
non-obvious parts.

Types BorrowParams.action as a Literal of the values borrow_post_core
actually compares against, rather than a bare str.

Tightens the FastAPI route to /books/{olid}/{slug}/borrow (previously a
catch-all suffix) -- every real link generator (LocateButton, ReadButton,
widget.html, checkout_with_ocaid's redirect, and Edition.url() itself,
which always includes the title slug or "untitled") includes a slug
segment, so a bare /books/{olid}/borrow was never actually reachable from
real UI. checkout_with_ocaid, the other /borrow entry point, still isn't
ported to FastAPI -- left for a later date.

Co-Authored-By: Drini Cami <cdrini@gmail.com>
… script

Standalone FastAPI HTML responses don't load the site's CSS/JS bundle, so
the open-access interstitial rendered unstyled and without its redirect
countdown there. Adds a fastapi=True param to the template, which inlines
a small style block (matching a few of the site's base colors/fonts) and
a var-based copy of interstitial.js's initInterstitial() logic -- plain
script, not an ES module, since nothing on this page can dynamically
import one.

Co-Authored-By: Drini Cami <cdrini@gmail.com>
@cdrini
cdrini marked this pull request as ready for review August 20, 2026 23:52
Mirrors the legacy web.py checkout_with_ocaid shim: GET resolves the IA
identifier and redirects to the canonical /books/{olid}/x/borrow (so the
browser lands on, and can bookmark, the canonical URL); POST resolves it
and forwards in-process instead, since a POST isn't bookmarked. POST
reuses the existing /borrow route's outcome-handling directly rather than
factoring it into a shared helper -- decorators don't stop a route
function from being awaited like any other async function.

Co-Authored-By: Drini Cami <cdrini@gmail.com>

@RayBB RayBB left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

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

DO NOT MERGE.

Detected a pretty serious issue where we will get deadlocks.

This is after pretty strong testing on my end. I think there's some work to be done to decide how to deal with this. I'll leave the report and reproduction script in separate comments.

@RayBB

RayBB commented Aug 21, 2026

Copy link
Copy Markdown
Collaborator
Longer Report Explaining Issue

Fix Plan: /borrow AsyncBridge Deadlock & Event-Loop Blocking (PR #13389)

Executive Summary

PR #13389 (Add a parallel FastAPI /borrow endpoint) moves the shared borrow logic into an async core (handle_borrow_async) that is bridged back to sync for the legacy web.py handler. This creates a process-wide deadlock on the legacy path: the flow runs on the shared AsyncBridge event loop and internally calls another bridged function (sync_loanget_availability), which blocks the loop waiting on itself. One authenticated patron clicking return on any book wedges the entire web.py process — every page that renders availability included — until gunicorn recycles the worker (~180s), and queued poisoned requests can re-wedge the replacement worker.

This was reproduced and confirmed live in the local docker environment (see Evidence) with a deterministic repro script (repro_borrow_deadlock.py, exit 1 on the PR branch, exit 0 on master).

Recommended fix (Phase 1, ~100 lines): invert the async boundary.
Make the shared core sync again (as master had it), keep the PR's good architecture (outcome objects, dual framework adapters), and offload to a worker thread at exactly one place — the FastAPI route (await asyncio.to_thread(handle_borrow, ...)). This makes the deadlock structurally impossible, keeps the uvicorn event loop free of blocking IO, preserves web.py behavior byte-for-byte, and leaves the door open for incremental true-async conversion (Phase 2).

Additionally, add a ~10-line re-entrancy guard to AsyncBridge.run() (Phase 0) so this class of misuse fails loudly instead of hanging production silently — forever, codebase-wide.


Evidence

Reproduced against local docker dev (docker compose up, mockservices backend):

Probe PR branch (borrow-fastapi) master
POST /books/OL1M/x/borrow?action=return (auth + s3 cookie) hangs forever 303 in 0.04s
Unrelated book page while wedged hangs (baseline 0.29s) healthy
hey -z 10s -c 4 during wedge ~zero successful requests n/a
Same request via FastAPI (:18080) 303 in 0.14s route absent (404)

py-spy stack dump of the wedged process (real frames):

Thread 19  ← THE EVENT LOOP THREAD
    result        (concurrent/futures/_base.py:445)
    run           (openlibrary/utils/async_utils.py:33)      ← nested bridge call
    wrapper       (openlibrary/utils/async_utils.py:49)
    sync_loan     (openlibrary/core/lending.py:758)          ← get_availability(...)
    update_loan_status (openlibrary/plugins/upstream/models.py:284)
    handle_borrow_async (openlibrary/plugins/upstream/borrow.py:236)
    _run_once / run_forever (asyncio/base_events.py)          ← ...running AS A TASK ON THE LOOP

Thread 18  ← gunicorn worker, stuck on the outer .result()
    run           (openlibrary/utils/async_utils.py:33)
    POST          (openlibrary/plugins/upstream/borrow.py:325)

The deadlock chain

web.py thread T1
└─ borrow.POST (borrow.py:325)
   └─ handle_borrow = async_bridge.wrap(handle_borrow_async)   # submits coroutine to loop L, T1 blocks on .result()
      └─ loop L runs handle_borrow_async AS A TASK ON L
         └─ edition.update_loan_status()                        # borrow.py:236 (action=return)
            └─ lending.sync_loan(ocaid)                         # models.py:284
               └─ get_availability(...)                         # lending.py:758 — the SYNC wrapper
                  └─ async_bridge.run(...)                      # run_coroutine_threadsafe onto loop L...
                     └─ Future.result()                         # ...called FROM loop L's own thread → DEADLOCK

AsyncBridge is a module-level singleton; one poisoned request wedges every bridged call in the process (availability rendering on ordinary pages included).

Trigger conditions (all required — and all normal borrowing conditions)

  1. Legacy web.py endpoint (port 8080)
  2. Authenticated patron whose account has an IA itemname
  3. Valid encrypted s3 cookie (parse_s3_cookie must succeed)
  4. Edition with an ocaid whose availability status is not "open"
  5. action=return (hits update_loan_status unconditionally), or action=borrow/browse/read while the patron holds ≥ 1 loan

Anonymous and open-access traffic exits early — which is why nothing else looks broken and why testing missed it.


The Invariant Everything Below Enforces

async_bridge.run() may only be called from non-loop threads, and event loops must never run blocking IO.

The deadlock = violating clause 1 (nested bridge). The FastAPI-path stall risk = violating clause 2 (sync infobase/memcache/IA calls directly on the uvicorn loop).

Why "just make it all async" doesn't work today: the lending layer beneath the borrow flow is only partially async. get_availability_async, s3_loan_api_async, and groundtruth are async-first ✓ — but ia_lending_api._post uses sync requests.post (so find_loans, get_loan, sync_loan, waitinglist queries are sync-only), infobase store access is sync-only, memcache ops are sync-only, and there is no async memoize in cache.py. A fully-async core is impossible without deep lending surgery — and half-async is exactly what created this bug.


Phase 0 — Safety Net (~10 lines; do first, independent of everything else)

File: openlibrary/utils/async_utils.py

def run(self, coro):
    if threading.current_thread() is self._thread:
        raise RuntimeError(
            "async_bridge.run() called from the AsyncBridge loop thread — "
            "this would deadlock. Call the underlying async function directly instead."
        )
    ...

Today this misuse hangs the process forever; after this it fails loudly with a stack trace pointing at the offender. Permanent protection for the whole codebase.


Phase 1 — Minimum Correct Fix (~100 lines total; recommended)

Key insight: invert the boundary

The PR put the async boundary inside the flow (async core → bridged for web.py). The correct place is at the framework edge: keep the core sync (web.py calls it directly, exactly like master), and let the FastAPI route offload it to a thread. Bridges then only ever fire from non-loop threads — legal by construction.

Change 1 — De-async the core (openlibrary/plugins/upstream/borrow.py)

  • Revert handle_borrow_async → plain sync handle_borrow(key, params, *, s3_cookie, fastapi=False):
    • await lending.get_availability_async(...)lending.get_availability(...)
    • await lending.s3_loan_api_async(...)lending.s3_loan_api(...)
    • await user_can_borrow_edition_async(...) → restore sync user_can_borrow_edition(...)
    • Delete handle_borrow = async_bridge.wrap(...) entirely — no bridge at this level anymore
  • Keep everything else the PR added: BorrowParams, BorrowRedirect / BorrowNotFound outcome objects, both framework adapters' match blocks. That architecture is the good part of the PR.

Resulting execution topology on web.py is identical to master's proven-safe shape (request thread + one-level-deep bridges inside lending).

Change 2 — Offload at the FastAPI boundary (openlibrary/fastapi/borrow.py)

result = await asyncio.to_thread(handle_borrow, key, params, s3_cookie=..., fastapi=True)

One line replaces the direct await:

  • All blocking work (infobase, memcache, sync IA calls) moves to Starlette's bounded threadpool (~40 workers) — the uvicorn loop never blocks, fixing the FastAPI-path stall risk for every concurrent request
  • Internal bridges inside lending fire from worker threads → legal by construction → deadlock impossible, even though nothing else changes
  • Bounded backpressure under IA slowness (requests queue at the limiter) instead of wedged loops

Change 3 — Fix the silent context clobbering (openlibrary/core/lending.py)

get_loans_of_user (and get_user_waiting_loans) detect "no context" via "env" not in web.ctx, then fakeload() + overwrite the authenticated site contextvar mid-request (verified: fires on both new execution homes). Minimal guard change:

-    if "env" not in web.ctx:
+    if site.get(None) is None:   # scripts with no context at all
         delegate.fakeload()

Now the FastAPI/to_thread path uses the real authenticated site; script behavior unchanged.

Change 4 — Test updates (openlibrary/plugins/upstream/tests/test_borrow.py)

Patch targets move from async names to sync names (get_availability, s3_loan_api, user_can_borrow_edition). Existing FastAPI outcome tests remain valid.

Alternative considered and rejected: keep the async core, scatter to_thread inside

Requires ~8 wrap sites across handle_borrow_async and user_can_borrow_edition_async internals (get_loan_count, is_users_turn_to_borrow are sync IA/store calls). Each site is a potential miss that either deadlocks or blocks the loop. Same end state, triple the review surface, structurally still capable of the bug. The sync-core version cannot deadlock by construction.


Phase 2 — True Async-First Roadmap (separate PRs, staged)

Phase 1 is safe, not maximally async. Each step below is independently shippable and shrinks Phase 1's to_thread surface:

  1. Async-first ia_lending_api: convert _post to httpx on ia.async_session; keep sync wrappers via bridge for legacy callers. Now find_loans / get_loan / sync_loan / waitinglist have async forms.
  2. Codify the blocking-boundary helper: openlibrary.utils.run_blocking(fn) (wrapping asyncio.to_thread) used everywhere infobase/memcache must be touched from async code — makes the sync/async seam intentional and greppable.
  3. Flip the core back to async-native: awaits for all IA calls, run_blocking only around site/store/user sections; delete the sync core; web.py gets a thin bridged adapter (one level deep — legal); FastAPI drops its to_thread.
  4. Async memcache memoize for get_cached_loans_of_user (none exists in cache.py today), removing the last blocking chunk from the hot path.

Known Remaining Risks (documented, not blockers)

  • Dual-loop httpx.AsyncClient: ia.async_session is driven from both the bridge loop and the uvicorn loop (pre-existing via fastapi/internal/api.py). After Phase 1, borrow's usage funnels through the bridge loop consistently, but the app-wide hazard remains. httpx clients are not loop-agnostic (pooled connections are loop-bound). Follow-up: per-loop clients.
  • Blocking memcache inside get_availability_async — pre-existing, milliseconds-scale; Phase 2 item.
  • Adjacent PR cleanups, unrelated to concurrency (recommend separate small PRs):
    • interstitial fastapi=True flag threading framework identity through core into a template; handle_borrow's declared return type omits the TemplateResult case (suggest a third BorrowWebBook outcome)
    • _resolve_ocaid_to_olid lives in the fastapi layer while legacy hand-rolls the same lookup twice
    • param-source parity: legacy web.input() accepts POST-body form fields; the FastAPI route reads query params only — a form-posted action=return would silently act as action=borrow
    • slug-less /books/{olid}/borrow 404s on FastAPI but works on legacy (external deep-link parity)
    • parse_s3_cookie dropped the account-store fallback; loan-history caller now sends credential-less requests for stale sessions

Verification Plan (acceptance criteria)

  1. repro_borrow_deadlock.py: exit 1 on current PR branch → exit 0 after Phase 1 (it is the regression test)
  2. New unit test asserting the Phase 0 guard raises RuntimeError on nested bridge use (not hang)
  3. Full borrow / return / waitlist flows exercised on :8080 and :18080
  4. hey burst during simulated slow IA: FastAPI stays responsive throughout; no worker wedges
  5. Pre-commit / lint / make test-py-uv green

Open Questions

  1. Phase 1 approach: sync-core + to_thread at the FastAPI boundary (strongly recommended) vs. async core with scattered to_thread?
  2. Scope: should Change 3 (site-guard/fakeload fix) ride along in this PR or be split out? It's ~6 lines but touches shared lending code — recommended to include, since current behavior silently swaps the authenticated site mid-request.

RUN WITH: uv run --with requests python repro_borrow_deadlock.py --pyspy --restart-web-on-wedge

Script to Reproduce Issue
#!/usr/bin/env python3
"""Reproduce / regression-test the AsyncBridge nested-call deadlock introduced by PR #13389.

THE BUG (present on the borrow-fastapi branch, NOT on master)
=============================================================
PR #13389 moves the shared /borrow logic into `handle_borrow_async()` and bridges it
back to sync for the legacy web.py handler:

    borrow.POST (web.py thread)
      └─ handle_borrow = async_bridge.wrap(handle_borrow_async)   # submits to shared loop L, blocks on .result()
           └─ handle_borrow_async runs AS A TASK ON LOOP L
              └─ edition.update_loan_status()                     # borrow.py:236 (action=return)
                 └─ lending.sync_loan()                           # models.py:284
                    └─ get_availability(...)                      # lending.py:758 — the SYNC wrapper
                       └─ async_bridge.run(...)                   # run_coroutine_threadsafe onto loop L...
                          └─ Future.result()                      # ...called FROM loop L's own thread -> DEADLOCK

Loop L is a process-wide singleton (openlibrary.utils.async_utils.async_bridge) shared by every
bridged call (availability rendering on ordinary pages included), so one poisoned request wedges
the whole web.py process until gunicorn recycles the worker (--timeout). Queued poisoned requests
can re-wedge the replacement worker.

TRIGGER CONDITIONS (all required, all normal borrowing conditions):
  * legacy web.py endpoint (port 8080), not the FastAPI one
  * authenticated patron (session cookie) whose account has an IA itemname
  * valid encrypted "s3" cookie (parse_s3_cookie must succeed)
  * edition with an ocaid whose availability status is not "open"
  * action=return (hits update_loan_status unconditionally), or borrow/browse/read while
    the patron holds >= 1 loan

WHAT THIS SCRIPT DOES
=====================
1. logs in, forges a valid s3 cookie, ensures the target edition has an ocaid and an
   ASCII-only title (a non-ASCII title makes master itself emit an invalid Location
   header, which would pollute the results)
2. measures baselines (book page + anonymous borrow)
3. fires the poisoned request at the legacy endpoint
4. VERDICT IS BASED ON SERVER HEALTH, not the client response: while/after the poisoned
   request, unrelated pages must still render. If they hang => the shared AsyncBridge
   loop is deadlocked => site-wide brownout.
5. optionally dumps stacks via py-spy (expect nested async_utils.run frames under
   handle_borrow_async on the event-loop thread)
6. fires the identical request at the FastAPI endpoint as a control (informational;
   the route only exists on the PR branch)

EXIT CODES
==========
  0  ISSUE NOT DETECTED — server stayed healthy (expected on master, or after a fix)
  1  DEADLOCK REPRODUCED — poisoned request wedged the process (expected on the PR branch)
  2  environment/setup problem — results inconclusive

USAGE
=====
    uv run --with requests python repro_borrow_deadlock.py                 # against local docker dev
    uv run --with requests python repro_borrow_deadlock.py --pyspy        # + stack dump evidence
    uv run --with requests python repro_borrow_deadlock.py --restart-web-on-wedge

WARNING: a successful repro wedges the local web.py worker until gunicorn recycles it
(--timeout, default 180s here) or you `docker compose restart web`.
"""

from __future__ import annotations

import argparse
import base64
import hashlib
import subprocess
import sys
import threading
import time

try:
    import requests
except ImportError:
    sys.exit("This script needs `requests`. Run it via: uv run --with requests python repro_borrow_deadlock.py")


def ts() -> str:
    return time.strftime("%H:%M:%S")


def log(msg: str) -> None:
    print(f"[{ts()}] {msg}", flush=True)


def forge_s3_token(secret: str, access: str = "testaccess", secret_key: str = "testsecret") -> str:
    """Same scheme as openlibrary.accounts.model.encrypt_s3_keys (Fernet over 'access:secret',
    key derived from sha256(infobase secret_key); local dev secret is 'xxx')."""
    from cryptography.fernet import Fernet

    derived = base64.urlsafe_b64encode(hashlib.sha256(secret.encode()).digest())
    return Fernet(derived).encrypt(f"{access}:{secret_key}".encode()).decode()


def forge_s3_token_via_docker(secret: str) -> str:
    snippet = (
        "import base64, hashlib;"
        "from cryptography.fernet import Fernet;"
        f"key = base64.urlsafe_b64encode(hashlib.sha256({secret!r}.encode()).digest());"
        "print(Fernet(key).encrypt(b'testaccess:testsecret').decode())"
    )
    out = subprocess.run(
        ["docker", "compose", "exec", "-T", "web", "python", "-c", snippet],
        capture_output=True,
        text=True,
        check=True,
    )
    return out.stdout.strip().splitlines()[-1]


class Repro:
    def __init__(self, args):
        self.args = args
        self.s = requests.Session()

    def req(self, method: str, url: str, timeout: float, session: requests.Session | None = None, **kw):
        """Returns {kind: completed|hung|transport_error, status?, location?, elapsed, error?}."""
        sess = session or self.s
        start = time.monotonic()
        try:
            r = sess.request(method, url, timeout=timeout, allow_redirects=False, **kw)
            return {
                "kind": "completed",
                "status": r.status_code,
                "location": r.headers.get("Location", ""),
                "elapsed": time.monotonic() - start,
            }
        except requests.exceptions.Timeout:
            return {"kind": "hung", "elapsed": time.monotonic() - start}
        except requests.exceptions.RequestException as e:
            return {"kind": "transport_error", "error": str(e)[:140], "elapsed": time.monotonic() - start}

    # ---------- setup steps ----------

    def preflight(self) -> bool:
        log(f"preflight: is {self.args.web_host} alive and NOT already wedged?")
        probe = self.req("GET", f"{self.args.web_host}/books/{self.args.olid}", timeout=self.args.probe_timeout)
        if probe["kind"] == "hung":
            log("FAIL: book page already hangs. The server is wedged from a previous run.")
            log("Run:  docker compose restart web   && re-run this script.")
            return False
        log(f"ok: book page answered in {probe['elapsed']:.2f}s")
        return True

    def login(self) -> bool:
        r = self.s.post(
            f"{self.args.web_host}/account/login.json",
            json={"username": self.args.username, "password": self.args.password},
            timeout=15,
        )
        if "session" not in self.s.cookies:
            log(f"FAIL: login did not yield a session cookie (HTTP {r.status_code}).")
            return False
        log("logged in; session cookie acquired")

        try:
            token = forge_s3_token(self.args.s3_secret)
        except ImportError:
            token = forge_s3_token_via_docker(self.args.s3_secret)
        self.s.cookies.set("s3", token)
        log("forged s3 cookie")
        return True

    def ensure_target_edition(self) -> bool:
        """The target needs an ocaid (to reach update_loan_status) and an ASCII title
        (so the final redirect doesn't die in gunicorn's header validation on master)."""
        r = self.s.get(f"{self.args.web_host}/books/{self.args.olid}.json", timeout=15)
        if r.status_code != 200:
            log(f"FAIL: {self.args.olid} not found (HTTP {r.status_code}); pick another --olid.")
            return False
        doc = r.json()
        needs_write = doc.get("ocaid") != self.args.ocaid
        title = doc.get("title") or ""
        if not title.isascii():
            doc["title"] = self.args.ascii_title
            needs_write = True
        if not needs_write:
            log(f"{self.args.olid} ready (ocaid={doc.get('ocaid')}, ascii title)")
            return True
        doc["ocaid"] = self.args.ocaid
        r = self.s.put(f"{self.args.web_host}/books/{self.args.olid}.json", json=doc, timeout=15)
        if r.status_code != 200:
            log(f"FAIL: could not update {self.args.olid} (HTTP {r.status_code}); are you admin?")
            return False
        log(f"prepared {self.args.olid}: ocaid={self.args.ocaid}, ascii title")
        return True

    def baselines(self) -> bool:
        self.book_url = f"{self.args.web_host}/books/{self.args.olid}"
        b = self.req("GET", self.book_url, timeout=self.args.probe_timeout)
        # Deliberately cookieless: proves the endpoint itself is fast WITHOUT the
        # credentials that trigger the deadlock path (anon exits at the login gate).
        # NOTE: action goes in the QUERY STRING: the FastAPI route reads query_params
        # only, while web.py's web.input() would also accept a form body.
        poison_url = f"{self.args.web_host}/books/{self.args.olid}/x/borrow?action=return"
        start = time.monotonic()
        try:
            r = requests.Session().post(poison_url, timeout=self.args.probe_timeout, allow_redirects=False)
            anon = {"ok": True, "status": r.status_code, "elapsed": time.monotonic() - start}
        except requests.exceptions.Timeout:
            anon = {"ok": False, "hung": True, "elapsed": time.monotonic() - start}
        except requests.exceptions.RequestException:
            anon = {"ok": False, "hung": True, "elapsed": time.monotonic() - start}
        log(f"baseline book page: {b.get('status')} in {b['elapsed']:.2f}s | anon borrow: {anon.get('status')} in {anon['elapsed']:.2f}s")
        if not (b["kind"] == "completed" and anon["ok"]):
            log("(if a baseline probe hung, the server may already be wedged; try: docker compose restart web)")
        return b["kind"] == "completed" and anon["ok"]

    # ---------- the experiment ----------

    def fire_poisoned(self) -> dict:
        url = f"{self.args.web_host}/books/{self.args.olid}/x/borrow?action=return"
        log(f"FIRING poisoned request: POST {url} (authenticated + s3 cookie)")
        result: dict = {}

        def run():
            result.update(self.req("POST", url, timeout=self.args.hang_timeout))

        t = threading.Thread(target=run, daemon=True)
        t.start()
        t.join(timeout=self.args.hang_timeout + 2)
        if not result:
            result = {"kind": "hung", "elapsed": self.args.hang_timeout + 2}
        return result

    def health_probe(self, label: str) -> dict:
        return self.req("GET", self.book_url, timeout=self.args.probe_timeout)

    def pyspy_evidence(self) -> None:
        log("attempting py-spy dump of the web container...")
        find = subprocess.run(
            ["docker", "compose", "exec", "-T", "web", "sh", "-c", "ps aux | grep '[o]penlibrary-server' | awk 'NR==2{print $2}'"],
            capture_output=True, text=True,
        )
        pid = find.stdout.strip()
        if not pid:
            log("(could not find web server PID; skipping py-spy)")
            return
        resolve = 'P=$(command -v py-spy); [ -n "$P" ] || P=/home/openlibrary/.local/bin/py-spy; [ -x "$P" ] || { python -m pip install -q py-spy >/dev/null 2>&1; P=/home/openlibrary/.local/bin/py-spy; }; echo "$P"'
        exe_resolved = subprocess.run(
            ["docker", "compose", "exec", "-T", "web", "sh", "-c", resolve],
            capture_output=True, text=True,
        ).stdout.strip().splitlines()[-1]
        dump = subprocess.run(
            ["docker", "compose", "exec", "-T", "web", exe_resolved, "dump", "--pid", pid, "--nonblocking"],
            capture_output=True, text=True,
        )
        lines = dump.stdout.splitlines()
        interesting = [ln for ln in lines if any(k in ln for k in ("borrow.py", "lending.py", "async_utils.py", "models.py"))]
        if interesting:
            log("py-spy frames matching the deadlock signature:")
            for ln in interesting:
                print(f"    {ln.strip()}")
        else:
            log("(no matching frames; full dump below)\n" + "\n".join(lines[:40]))

    def fastapi_contrast(self) -> None:
        url = f"{self.args.api_host}/books/{self.args.olid}/x/borrow?action=return"
        r = self.req("POST", url, timeout=self.args.probe_timeout)
        if r["kind"] == "completed":
            extra = " (route absent -- expected on master)" if r["status"] == 404 else ""
            log(f"CONTROL same request via FastAPI ({self.args.api_host}): {r['status']} in {r['elapsed']:.2f}s{extra}")
        else:
            log(f"CONTROL FastAPI unreachable ({r.get('error', 'timeout')}); skipping contrast.")

    # ---------- orchestration ----------

    def run(self) -> int:
        if not self.preflight():
            return 2
        if not self.login():
            return 2
        if not self.ensure_target_edition():
            return 2
        if not self.baselines():
            log("FAIL: baselines unhealthy; aborting rather than misattributing a hang.")
            return 2

        poisoned = self.fire_poisoned()

        # The verdict is decided by SERVER HEALTH, not by what the client saw:
        # a wedged AsyncBridge loop hangs every bridged page render, so unrelated
        # pages are the reliable signal. Two probes: the first may absorb queued work.
        p1 = self.health_probe("post-poison-1")
        p2 = self.health_probe("post-poison-2")
        wedged = p1["kind"] == "hung" or p2["kind"] == "hung"

        if poisoned["kind"] == "completed":
            log(f"poisoned request client result: HTTP {poisoned['status']} in {poisoned['elapsed']:.2f}s -> {poisoned['location'] or '-'}")
        elif poisoned["kind"] == "transport_error":
            log(f"poisoned request died at the transport layer ({poisoned['error']})")
        else:
            log(f"HANG CONFIRMED: no response after {poisoned['elapsed']:.0f}s (baseline was sub-second)")

        if wedged:
            log(f"SERVER WEDGED: unrelated book page hung (probe1: {p1['kind']} after {p1['elapsed']:.0f}s, probe2: {p2['kind']} after {p2['elapsed']:.0f}s)")
        else:
            log(f"server stayed healthy: book page answered {p2.get('status')} in {p2['elapsed']:.2f}s")

        if wedged and self.args.pyspy:
            self.pyspy_evidence()

        self.fastapi_contrast()

        if wedged and self.args.restart_web_on_wedge:
            log("restarting web container to unwedge...")
            subprocess.run(["docker", "compose", "restart", "web"], capture_output=True, text=True)
            time.sleep(10)

        log("")
        log("=" * 72)
        if wedged:
            log("VERDICT: DEADLOCK REPRODUCED (exit 1)")
            log("  legacy web.py /borrow?action=return wedged the shared AsyncBridge loop:")
            log("  handle_borrow_async -> update_loan_status -> sync_loan -> bridged get_availability")
            log("  called async_bridge.run() FROM the bridge loop's own thread.")
            log("  Every bridged call in the process (incl. ordinary page availability) queues forever.")
            if not self.args.restart_web_on_wedge:
                log("  The server stays wedged until gunicorn recycles the worker or you run:")
                log("    docker compose restart web")
        else:
            log("VERDICT: ISSUE NOT DETECTED (exit 0)")
            log("  The poisoned request was handled and the server remained healthy.")
            log("  Expected on master (all borrow logic runs on the request thread), or")
            log("  on a branch where the deadlock is fixed.")
            if poisoned["kind"] == "transport_error":
                log("  Note: the response itself failed at the HTTP layer (see transport error")
                log("  above) -- often a non-ASCII redirect Location; the borrow logic ran.")
        log("=" * 72)
        return 1 if wedged else 0


def parse_args():
    p = argparse.ArgumentParser(description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter)
    p.add_argument("--web-host", default="http://localhost:8080", help="legacy web.py base URL")
    p.add_argument("--api-host", default="http://localhost:18080", help="FastAPI base URL (control)")
    p.add_argument("--olid", default="OL1M", help="edition to plant the ocaid on / borrow")
    p.add_argument("--ocaid", default="deadlocktest01", help="ocaid to use")
    p.add_argument("--ascii-title", default="Deadlock Repro Target", help="ASCII title planted to keep redirects header-safe")
    p.add_argument("--username", default="openlibrary")
    p.add_argument("--password", default="openlibrary")
    p.add_argument("--s3-secret", default="xxx", help="infobase secret_key (conf/infobase.yml) used to forge the s3 cookie")
    p.add_argument("--hang-timeout", type=float, default=25.0, help="how long to wait on the poisoned request before declaring a hang")
    p.add_argument("--probe-timeout", type=float, default=8.0, help="timeout for baseline/health/control probes")
    p.add_argument("--pyspy", action="store_true", help="capture py-spy stack evidence when wedged")
    p.add_argument("--restart-web-on-wedge", action="store_true", help="docker compose restart web after reproducing")
    return p.parse_args()


if __name__ == "__main__":
    sys.exit(Repro(parse_args()).run())

…ncy guard

Legacy handle_borrow ran on the shared AsyncBridge loop and called
sync_loan -> get_availability via async_bridge.run() from the loop's
own thread, wedging the process on any authenticated return/borrow.

Add side-by-side async twins (IA_Lending_API.*_async, get_loan_async,
sync_loan_async, etc.) and make handle_borrow_async fully await them.
Add guard in AsyncBridge.run() to fail loud on re-entrancy and
cover it with tests. Sync callers unchanged.
@RayBB

RayBB commented Aug 21, 2026

Copy link
Copy Markdown
Collaborator

@cdrini since I know this is urgent I pushed up a fix.

I added side-by-side *_async twins for IA_Lending_API and lending helpers and made handle_borrow_async fully await them, plus a guard in AsyncBridge.run() to fail loud on re-entrancy. Borrow now stays non-blocking on the loop while sync callers stay unchanged.

This is verified working by my script to test it and it's up on testing now.

get_loan_async expiry path was awaiting via sync Loan.delete()
which blocks on sync ia_lending_api.delete_loan and sync
sync_loan (nested AsyncBridge). Add async twin that awaits
ia_lending_api.delete_loan_async and sync_loan_async; store
ops stay sync per existing short-term decision.
@RayBB

RayBB commented Aug 21, 2026

Copy link
Copy Markdown
Collaborator

get_loan_async expiry path was awaiting via sync Loan.delete() which would have clogged up the entire fastapi worker pool so I pushed up a fix for that one.

@RayBB RayBB left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

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

I'm now pretty highly confident in this PR.

I think @cdrini should review the changes I pushed up but after that I say it's good to go.

Things look messy now with duplicate methods but I think that's the safest way for the moment and we can do a followup to move over some more stuff in short order.

The one thing I will note one divergence.
@router.get("/books/{olid}/{slug}/borrow") requires slug.
Legacy borrow.py:308 (/books/.*)/borrow accepts /books/OL1M/borrow.
However, it doesn't look like it'll be an issue in this codebase.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants