Slow requests: views that wait on a remote host still hold SQLite's write lock (the fix for #220 missed them) #357

New issue

Closed

opened 2026-10-01 10:46:06 +00:00 by tiagoagueda · 0 comments

tiagoagueda commented

2026-10-01 10:46:06 +00:00

Owner

Found on 2026-09-29 in a read-only review of postulo at 95348908d, by listing every view that reaches postulo.plugins.http, SMTP or a plugin's network call and resolving each address to see whether its callback carries _non_atomic_requests.

Checked again on 2026-10-01 against main at 0a5cad587: still present. The code is now at jobs/forms.py:308-313 (CompanyForm.apply_logo); accounts/forms.py:445 (ProfileForm._save_picture); api/api.py:605-614 (_read), :422-450 (create_capture, the Capture create at :482, the errands.send calls at :508-533), :567-574 (preview_capture) and :826 (OUTSIDE_A_TRANSACTION); plugins/views.py:307-342 (ConnectionConsentCallbackView), :361-411 (ConnectionTestView) and :446-459 (ConnectionSyncNowView); core/server_views.py:766 (EmailConnectionTestView), :877 (EmailTestView), :1304 (PluginActionView), :1369 (_confirm), :1408 (_refresh) and :1438 (_install); plugins/fetching.py:50-52 (the capture timeouts) and plugins/http.py:22 (MAX_REDIRECTS). The other places are where they were, and none of these views has been marked transaction.non_atomic_requests since.

ATOMIC_REQUESTS is on (config/settings/base.py:140) and a SQLite file is opened with transaction_mode: IMMEDIATE (config/sqlite.py:49), so a request takes the database's write lock before its view runs and keeps it until the response. config/sqlite.py:20-30 states the rule that follows: "a view which does something slow does not belong in a request-long transaction at all". A dozen views that wait on somebody else's server are still inside one. While one of them waits, every other request (read-only pages included), the scheduler and db_worker queue behind it, and whatever waits past the twenty-second busy timeout fails with database is locked.

Related to #220, which is closed: it moved capture, Find logo, PDF drawing and the export out of the request's transaction, and #247 then turned several of them into errands. This issue adds the views neither reached. Two of them were named before and closed over: #206 said "LogoFormMixin also runs logos.from_url inside the request transaction", and #247 ("Not in this") deferred the capture API as "a change of its own"; no open issue carries either.

Where: none of the following is marked transaction.non_atomic_requests (resolved on the snapshot; jobs:capture_create, jobs:company_logo_action and the API's attach_rendering are).
- Link checks. resume/views.py:353-391, LinkCheckView (resume:link_check, resume:link_check_all). resume/links.py:47-56, check_all, asks every link in turn with no overall deadline; resume/links.py:33 and :67-73 allow 8 seconds per phase for a HEAD, then often a GET, with up to three redirects.
- Company form, logo address. jobs/views.py:364-379, LogoFormMixin.form_valid, calls form.apply_logo(self.object) after the save, on CompanyCreateView and CompanyUpdateView (jobs/views.py:382-408). jobs/forms.py:307-312, CompanyForm.apply_logo, calls logos.from_url; jobs/logos.py:109-121, download, waits up to TIMEOUT = 8.0 (jobs/logos.py:75) per phase and follows up to three redirects (plugins/http.py:23). Only CompanyLogoActionView (jobs/views.py:436) was moved.
- Gravatar. accounts/avatars.py:111-131, fetch_gravatar (http.client(timeout=8.0), then a profile save), called from accounts/views.py:227-243, GravatarRefreshView.post; from accounts/forms.py:444, ProfileForm._save_picture, when Use my Gravatar is switched on, inside the transaction.atomic() of ProfileView.form_valid (accounts/views.py:177); and from accounts/signals.py:82-91, the email_changed receiver, during allauth's email view.
- Capture API. api/api.py:603-612, _read, calls fetch_page when no html is sent (ten seconds for the page, five for robots.txt, up to three redirects: plugins/fetching.py:44-46). It is reached from create_capture (api/api.py:420-448) and preview_capture (api/api.py:565-572). OUTSIDE_A_TRANSACTION (api/api.py:824) holds only attach_rendering. The same request then calls errands.send("notify", ...) (api/api.py:506-531), and with POSTULO_BACKGROUND_WORK off (the default, config/settings/base.py:637) errands.send performs the errand at once (core/errands.py:98-101), so each notifier's network call also happens inside the capture request's transaction, with or without html. tests/security/test_captured_pages.py:590-601, test_a_slow_upload_does_not_hold_the_database, asserts that /api/v1/captures is not non-atomic, so the suite pins the defect.
- Connections. plugins/views.py:360-410, ConnectionTestView.post (a token refresh, then plugin.test: a login or a real request to the connected server); plugins/views.py:445-458, ConnectionSyncNowView.post (a whole sync_connection: a CardDAV, CalDAV or IMAP run); plugins/views.py:306-341, ConnectionConsentCallbackView.get (the OAuth token exchange in consent.finish and mail_auth.finish_consent).
- Document stores. documents/views.py:679, SendCopiesNowView.post (documents:upload_archive, documents:rendered_archive): send_now (documents/archiving.py:224-242) uploads the document to every store it is missing from.
- Staff pages. core/server_views.py:765, EmailConnectionTestView, and :876, EmailTestView (an SMTP connection, a real message); core/server_views.py:1303, PluginActionView: _refresh (:1407) fetches every catalogue, _install (:1437) fetches them again and downloads a release with a 120-second timeout (plugins/catalogue.py:296) before the install and verification subprocesses, and _confirm (:1368) waits on the same subprocesses for an uploaded package.
- The guard that should catch this. tests/test_slow_requests.py:36-45, SLOW, names none of these addresses, and the test settings replace DATABASES without ATOMIC_REQUESTS (config/settings/test.py:13), so nothing in the suite runs these views inside a request's transaction.
What happens: on the default install (SQLite, three gunicorn workers, no errand worker):
1. A person with a dozen links, a few on hosts that do not answer, presses Check them all. Each such link waits out 8 seconds, sometimes twice. For the sum of those waits every other request on the instance waits for the lock, and those that wait more than twenty seconds answer 500. The number of links is unbounded (the candidate-file import adds up to 200 rows at a time, resume/candidate.py:84). If the loop passes gunicorn's --timeout 120 (docker/Dockerfile:354), the worker is killed, the person gets a 502 and the transaction rolls back, so none of the results already fetched are kept.
2. A person saves a company whose logo address is on a slow or trickling host. The lock taken for the company's INSERT or UPDATE is held through the download; the timeout is per network operation, so a host that trickles bytes holds it for longer than one timeout.
3. A token with the captures scope sends POST /api/v1/captures with a url and no html (the wiki's first curl example on The capture API), or POST /api/v1/captures/preview. The lock is held through the robots check, the page and any redirects. POSTULO_CAPTURE_RATE (default 30/h) bounds how often an account can do this, not how long each call holds the lock.
4. The same holds for as long as the remote end takes during Sync now on a slow DAV server, a connection Test, the return from a provider's consent page, Send now to a document store, a Gravatar fetch (ticking the box, Fetch my Gravatar again, or changing the primary address), the Email page's tests and a catalogue refresh or install.
A replay during the review (link checks patched to sleep, the file options of config/sqlite.py, ATOMIC_REQUESTS on) measured a second account's /applications/ at 0.04 s alone, 4.4 s behind one 5-second link check, and a 500 after 22 s behind three 8-second ones.
Who can trigger it: any signed-in person, with a button the page offers on their own data, or any holder of a capture token; the staff pages need an administrator. Nothing is disclosed: the cost falls on everybody else's requests.
Why it matters: one person's ordinary action stalls or breaks every other account's pages and the scheduler's reminders. A 500 in the middle of a form loses what was typed and invites a retry that creates a duplicate (#206). A gunicorn worker is tied up for the same time. On PostgreSQL the cost is smaller: a transaction left open across the network. The docstring of config/sqlite.py says the slow views are out of the request's transaction, which is not yet true. The Gravatar case alone would be minor, since the fetch is rare and opt-in; the link check, the company form and the capture API are not.
Fix: the rule #220 set, applied to each view: mark it transaction.non_atomic_requests and wrap only its writes in short transaction.atomic() blocks, or hand the work to an errand as #247 did for Find logo.
- LinkCheckView: @method_decorator(transaction.non_atomic_requests, name="dispatch"); links.check already saves each link with its own save(), which then commits by itself. Give check_all an overall deadline well inside gunicorn's timeout (about 60 seconds), stop there, and say how many links were not reached.
- Company form: stop fetching in the form. Save the company, and when logo_url changed send the logo errand with a new url action in find_a_logo (jobs/slow.py:130-157) that calls logos.from_url, then redirect to the errand page as CompanyLogoActionView does. If it has to stay inline, mark both views non-atomic and fetch after the transaction.atomic() that CompanyIdentifiersMixin.form_valid (jobs/views.py:350-361) already puts around the company and its identifiers; logos.store writes in a transaction of its own.
- Gravatar: make fetch_gravatar fetch first and write after. Mark GravatarRefreshView non-atomic. Mark ProfileView non-atomic too and fetch after its existing atomic block, which keeps gravatar_outcome for the message. In the email_changed receiver, which runs in allauth's view, schedule the fetch with transaction.on_commit or an errand.
- Capture API: add create_capture and preview_capture to OUTSIDE_A_TRANSACTION. GET /api/v1/captures is answered by the same address function, so it leaves the transaction too; it only reads, and the comment should say so. Wrap the capture's own writes (the Capture create at api/api.py:480, pages.keep_source_quietly, remembered.after_capture, answer.keep) in short atomic blocks. Leave throttle.capture and the errands.send calls outside them: the first for the reason CaptureCreateView's docstring gives, the second so that an inline notifier no longer runs under the lock. idempotency.once already claims its key in a transaction of its own (api/idempotency.py:84).
- Connections, document stores and staff pages: mark the views non-atomic and wrap connection.record_test, the sync's bookkeeping, the copy status and the consent's saves in their own atomic blocks; send_now already does so for schedule_copies. Sync now and the catalogue actions are long enough to be better as new errands.
- Correct the list in the config/sqlite.py docstring if any view is left inside its transaction deliberately.

Not in this: notifications sent through slow.tell from change_status and the other application services also run inline in the caller's transaction when no worker is configured, but their fix is transaction.on_commit in tell, not moving a view out of its transaction; that is a separate issue from this review.

Done when

tests/test_slow_requests.py: SLOW lists resume:link_check, resume:link_check_all, jobs:company_create, jobs:company_update (or a test shows that saving a company with a new logo address sends an errand and does not call logos.download in the request), accounts:avatar_refresh, accounts:profile, connections:test, connections:sync_now, connections:consent_callback, documents:upload_archive, documents:rendered_archive, server:email_test, server:email_connection_test and server:plugin_action; test_the_slow_views_do_not_hold_the_database_while_they_work fails for each today. Each write these views make is shown to sit in a transaction of its own, as test_a_capture_is_written_in_a_transaction_of_its_own does for the web capture.
tests/security/test_captured_pages.py::test_a_slow_upload_does_not_hold_the_database no longer asserts that /api/v1/captures is atomic, and asserts that it and /api/v1/captures/preview carry _non_atomic_requests, as it does for the rendering upload.
A test in tests/test_avatars.py, marked django_db(transaction=True) and run with ATOMIC_REQUESTS on, replaces the HTTP client with one that asserts not connection.in_atomic_block when get() is called, and drives the three paths (a profile save with the tick, Fetch my Gravatar again, a primary address change); it fails today on all three.
A test in tests/test_logos.py, set up the same way, posts the company form with a new logo address with logos.download patched to record whether a transaction is open, and asserts that none is, or that an errand was queued instead.
A test in tests/test_links_and_letters.py with links._ask patched to advance a fake clock shows check_all stopping at its deadline, keeping the results it had, and the page saying how many were left.

Found on 2026-09-29 in a read-only review of postulo at 95348908d, by listing every view that reaches `postulo.plugins.http`, SMTP or a plugin's network call and resolving each address to see whether its callback carries `_non_atomic_requests`. Checked again on 2026-10-01 against `main` at `0a5cad587`: still present. The code is now at `jobs/forms.py:308-313` (`CompanyForm.apply_logo`); `accounts/forms.py:445` (`ProfileForm._save_picture`); `api/api.py:605-614` (`_read`), `:422-450` (`create_capture`, the `Capture` create at `:482`, the `errands.send` calls at `:508-533`), `:567-574` (`preview_capture`) and `:826` (`OUTSIDE_A_TRANSACTION`); `plugins/views.py:307-342` (`ConnectionConsentCallbackView`), `:361-411` (`ConnectionTestView`) and `:446-459` (`ConnectionSyncNowView`); `core/server_views.py:766` (`EmailConnectionTestView`), `:877` (`EmailTestView`), `:1304` (`PluginActionView`), `:1369` (`_confirm`), `:1408` (`_refresh`) and `:1438` (`_install`); `plugins/fetching.py:50-52` (the capture timeouts) and `plugins/http.py:22` (`MAX_REDIRECTS`). The other places are where they were, and none of these views has been marked `transaction.non_atomic_requests` since. `ATOMIC_REQUESTS` is on (`config/settings/base.py:140`) and a SQLite file is opened with `transaction_mode: IMMEDIATE` (`config/sqlite.py:49`), so a request takes the database's write lock before its view runs and keeps it until the response. `config/sqlite.py:20-30` states the rule that follows: "a view which does something slow does not belong in a request-long transaction at all". A dozen views that wait on somebody else's server are still inside one. While one of them waits, every other request (read-only pages included), the scheduler and `db_worker` queue behind it, and whatever waits past the twenty-second busy timeout fails with *database is locked*. Related to #220, which is closed: it moved capture, *Find logo*, PDF drawing and the export out of the request's transaction, and #247 then turned several of them into errands. This issue adds the views neither reached. Two of them were named before and closed over: #206 said "`LogoFormMixin` also runs `logos.from_url` inside the request transaction", and #247 ("Not in this") deferred the capture API as "a change of its own"; no open issue carries either. - **Where:** none of the following is marked `transaction.non_atomic_requests` (resolved on the snapshot; `jobs:capture_create`, `jobs:company_logo_action` and the API's `attach_rendering` are). - **Link checks.** `resume/views.py:353-391`, `LinkCheckView` (`resume:link_check`, `resume:link_check_all`). `resume/links.py:47-56`, `check_all`, asks every link in turn with no overall deadline; `resume/links.py:33` and `:67-73` allow 8 seconds per phase for a `HEAD`, then often a `GET`, with up to three redirects. - **Company form, logo address.** `jobs/views.py:364-379`, `LogoFormMixin.form_valid`, calls `form.apply_logo(self.object)` after the save, on `CompanyCreateView` and `CompanyUpdateView` (`jobs/views.py:382-408`). `jobs/forms.py:307-312`, `CompanyForm.apply_logo`, calls `logos.from_url`; `jobs/logos.py:109-121`, `download`, waits up to `TIMEOUT = 8.0` (`jobs/logos.py:75`) per phase and follows up to three redirects (`plugins/http.py:23`). Only `CompanyLogoActionView` (`jobs/views.py:436`) was moved. - **Gravatar.** `accounts/avatars.py:111-131`, `fetch_gravatar` (`http.client(timeout=8.0)`, then a profile save), called from `accounts/views.py:227-243`, `GravatarRefreshView.post`; from `accounts/forms.py:444`, `ProfileForm._save_picture`, when *Use my Gravatar* is switched on, inside the `transaction.atomic()` of `ProfileView.form_valid` (`accounts/views.py:177`); and from `accounts/signals.py:82-91`, the `email_changed` receiver, during allauth's email view. - **Capture API.** `api/api.py:603-612`, `_read`, calls `fetch_page` when no `html` is sent (ten seconds for the page, five for `robots.txt`, up to three redirects: `plugins/fetching.py:44-46`). It is reached from `create_capture` (`api/api.py:420-448`) and `preview_capture` (`api/api.py:565-572`). `OUTSIDE_A_TRANSACTION` (`api/api.py:824`) holds only `attach_rendering`. The same request then calls `errands.send("notify", ...)` (`api/api.py:506-531`), and with `POSTULO_BACKGROUND_WORK` off (the default, `config/settings/base.py:637`) `errands.send` performs the errand at once (`core/errands.py:98-101`), so each notifier's network call also happens inside the capture request's transaction, with or without `html`. `tests/security/test_captured_pages.py:590-601`, `test_a_slow_upload_does_not_hold_the_database`, asserts that `/api/v1/captures` is *not* non-atomic, so the suite pins the defect. - **Connections.** `plugins/views.py:360-410`, `ConnectionTestView.post` (a token refresh, then `plugin.test`: a login or a real request to the connected server); `plugins/views.py:445-458`, `ConnectionSyncNowView.post` (a whole `sync_connection`: a CardDAV, CalDAV or IMAP run); `plugins/views.py:306-341`, `ConnectionConsentCallbackView.get` (the OAuth token exchange in `consent.finish` and `mail_auth.finish_consent`). - **Document stores.** `documents/views.py:679`, `SendCopiesNowView.post` (`documents:upload_archive`, `documents:rendered_archive`): `send_now` (`documents/archiving.py:224-242`) uploads the document to every store it is missing from. - **Staff pages.** `core/server_views.py:765`, `EmailConnectionTestView`, and `:876`, `EmailTestView` (an SMTP connection, a real message); `core/server_views.py:1303`, `PluginActionView`: `_refresh` (`:1407`) fetches every catalogue, `_install` (`:1437`) fetches them again and downloads a release with a 120-second timeout (`plugins/catalogue.py:296`) before the install and verification subprocesses, and `_confirm` (`:1368`) waits on the same subprocesses for an uploaded package. - **The guard that should catch this.** `tests/test_slow_requests.py:36-45`, `SLOW`, names none of these addresses, and the test settings replace `DATABASES` without `ATOMIC_REQUESTS` (`config/settings/test.py:13`), so nothing in the suite runs these views inside a request's transaction. - **What happens:** on the default install (SQLite, three gunicorn workers, no errand worker): 1. A person with a dozen links, a few on hosts that do not answer, presses *Check them all*. Each such link waits out 8 seconds, sometimes twice. For the sum of those waits every other request on the instance waits for the lock, and those that wait more than twenty seconds answer 500. The number of links is unbounded (the candidate-file import adds up to 200 rows at a time, `resume/candidate.py:84`). If the loop passes gunicorn's `--timeout 120` (`docker/Dockerfile:354`), the worker is killed, the person gets a 502 and the transaction rolls back, so none of the results already fetched are kept. 2. A person saves a company whose logo address is on a slow or trickling host. The lock taken for the company's `INSERT` or `UPDATE` is held through the download; the timeout is per network operation, so a host that trickles bytes holds it for longer than one timeout. 3. A token with the `captures` scope sends `POST /api/v1/captures` with a `url` and no `html` (the wiki's first `curl` example on The capture API), or `POST /api/v1/captures/preview`. The lock is held through the robots check, the page and any redirects. `POSTULO_CAPTURE_RATE` (default `30/h`) bounds how often an account can do this, not how long each call holds the lock. 4. The same holds for as long as the remote end takes during *Sync now* on a slow DAV server, a connection *Test*, the return from a provider's consent page, *Send now* to a document store, a Gravatar fetch (ticking the box, *Fetch my Gravatar again*, or changing the primary address), the Email page's tests and a catalogue refresh or install. A replay during the review (link checks patched to sleep, the file options of `config/sqlite.py`, `ATOMIC_REQUESTS` on) measured a second account's `/applications/` at 0.04 s alone, 4.4 s behind one 5-second link check, and a 500 after 22 s behind three 8-second ones. - **Who can trigger it:** any signed-in person, with a button the page offers on their own data, or any holder of a capture token; the staff pages need an administrator. Nothing is disclosed: the cost falls on everybody else's requests. - **Why it matters:** one person's ordinary action stalls or breaks every other account's pages and the scheduler's reminders. A 500 in the middle of a form loses what was typed and invites a retry that creates a duplicate (#206). A gunicorn worker is tied up for the same time. On PostgreSQL the cost is smaller: a transaction left open across the network. The docstring of `config/sqlite.py` says the slow views are out of the request's transaction, which is not yet true. The Gravatar case alone would be minor, since the fetch is rare and opt-in; the link check, the company form and the capture API are not. - **Fix:** the rule #220 set, applied to each view: mark it `transaction.non_atomic_requests` and wrap only its writes in short `transaction.atomic()` blocks, or hand the work to an errand as #247 did for *Find logo*. - `LinkCheckView`: `@method_decorator(transaction.non_atomic_requests, name="dispatch")`; `links.check` already saves each link with its own `save()`, which then commits by itself. Give `check_all` an overall deadline well inside gunicorn's timeout (about 60 seconds), stop there, and say how many links were not reached. - Company form: stop fetching in the form. Save the company, and when `logo_url` changed send the `logo` errand with a new `url` action in `find_a_logo` (`jobs/slow.py:130-157`) that calls `logos.from_url`, then redirect to the errand page as `CompanyLogoActionView` does. If it has to stay inline, mark both views non-atomic and fetch after the `transaction.atomic()` that `CompanyIdentifiersMixin.form_valid` (`jobs/views.py:350-361`) already puts around the company and its identifiers; `logos.store` writes in a transaction of its own. - Gravatar: make `fetch_gravatar` fetch first and write after. Mark `GravatarRefreshView` non-atomic. Mark `ProfileView` non-atomic too and fetch after its existing atomic block, which keeps `gravatar_outcome` for the message. In the `email_changed` receiver, which runs in allauth's view, schedule the fetch with `transaction.on_commit` or an errand. - Capture API: add `create_capture` and `preview_capture` to `OUTSIDE_A_TRANSACTION`. `GET /api/v1/captures` is answered by the same address function, so it leaves the transaction too; it only reads, and the comment should say so. Wrap the capture's own writes (the `Capture` create at `api/api.py:480`, `pages.keep_source_quietly`, `remembered.after_capture`, `answer.keep`) in short atomic blocks. Leave `throttle.capture` and the `errands.send` calls outside them: the first for the reason `CaptureCreateView`'s docstring gives, the second so that an inline notifier no longer runs under the lock. `idempotency.once` already claims its key in a transaction of its own (`api/idempotency.py:84`). - Connections, document stores and staff pages: mark the views non-atomic and wrap `connection.record_test`, the sync's bookkeeping, the copy status and the consent's saves in their own atomic blocks; `send_now` already does so for `schedule_copies`. *Sync now* and the catalogue actions are long enough to be better as new errands. - Correct the list in the `config/sqlite.py` docstring if any view is left inside its transaction deliberately. Not in this: notifications sent through `slow.tell` from `change_status` and the other application services also run inline in the caller's transaction when no worker is configured, but their fix is `transaction.on_commit` in `tell`, not moving a view out of its transaction; that is a separate issue from this review. ## Done when - `tests/test_slow_requests.py`: `SLOW` lists `resume:link_check`, `resume:link_check_all`, `jobs:company_create`, `jobs:company_update` (or a test shows that saving a company with a new logo address sends an errand and does not call `logos.download` in the request), `accounts:avatar_refresh`, `accounts:profile`, `connections:test`, `connections:sync_now`, `connections:consent_callback`, `documents:upload_archive`, `documents:rendered_archive`, `server:email_test`, `server:email_connection_test` and `server:plugin_action`; `test_the_slow_views_do_not_hold_the_database_while_they_work` fails for each today. Each write these views make is shown to sit in a transaction of its own, as `test_a_capture_is_written_in_a_transaction_of_its_own` does for the web capture. - `tests/security/test_captured_pages.py::test_a_slow_upload_does_not_hold_the_database` no longer asserts that `/api/v1/captures` is atomic, and asserts that it and `/api/v1/captures/preview` carry `_non_atomic_requests`, as it does for the rendering upload. - A test in `tests/test_avatars.py`, marked `django_db(transaction=True)` and run with `ATOMIC_REQUESTS` on, replaces the HTTP client with one that asserts `not connection.in_atomic_block` when `get()` is called, and drives the three paths (a profile save with the tick, *Fetch my Gravatar again*, a primary address change); it fails today on all three. - A test in `tests/test_logos.py`, set up the same way, posts the company form with a new logo address with `logos.download` patched to record whether a transaction is open, and asserts that none is, or that an errand was queued instead. - A test in `tests/test_links_and_letters.py` with `links._ask` patched to advance a fake clock shows `check_all` stopping at its deadline, keeping the results it had, and the page saying how many were left.

tiagoagueda added this to the 0.5.0 milestone

2026-10-01 10:46:06 +00:00

tiagoagueda added the

bug

label

2026-10-01 10:46:06 +00:00

tiagoagueda referenced this issue from a commit

2026-10-04 14:13:26 +00:00

Check links outside the request's transaction

tiagoagueda referenced this issue from a commit

2026-10-04 14:13:26 +00:00

Fetch logos and Gravatars outside the request's transaction