Installing a plugin: the request may run past gunicorn's 120 s timeout, and a killed worker skips the restore #604

New issue

Closed

opened 2026-10-01 10:48:12 +00:00 by tiagoagueda · 0 comments

tiagoagueda commented

2026-10-01 10:48:12 +00:00

Owner

Found on 2026-09-29 in a read-only review of postulo at 95348908d, by comparing the install path's time budgets with the image's gunicorn settings and following what runs when the worker is aborted.

Checked again on 2026-10-01 against main at 0a5cad587: still present. The code is now at plugins/installing.py:89-93 (the two budgets), plugins/installing.py:725-814 (install_wheel: take_snapshot() at :756, except InstallError at :761, verify_imports at :773, write_record at :810), and core/server_views.py:1369-1406 (_confirm) and :1438-1453 (_install); plugins/catalogue.py:296 and docker/Dockerfile:354 have not moved.

Confirming an upload or installing from a catalogue runs the whole install inside a sync gunicorn worker: a wheel download allowed 120 s per read, a snapshot copy of the whole plugins directory, an installer subprocess allowed 300 s (it resolves and downloads the dependency tree from PyPI), and an import check allowed 60 s. The image kills a worker whose request passes 120 s. The 300-second budget can therefore never be used, and when the worker is killed the install's own clean-up does not run.

Where: plugins/installing.py:76-80 (INSTALL_TIMEOUT = 300, VERIFY_TIMEOUT = 60); plugins/installing.py:899-988 (install_wheel: take_snapshot() at :930, except InstallError at :935, verify_imports at :947, write_record at :984); plugins/catalogue.py:296 (download, timeout=120.0); core/server_views.py:1368-1405 (_confirm) and :1437-1452 (_install); docker/Dockerfile:354 (GUNICORN_CMD_ARGS="--timeout 120 ...").
What happens: past 120 s the arbiter sends the worker SIGABRT, which gunicorn turns into sys.exit(1), and then SIGKILL. SystemExit is not an InstallError, so neither restore_snapshot() nor give_back_snapshot() runs; subprocess.run kills the half-finished installer on its way out. Depending on the moment:
1. during the installer: the live directory may hold a partial install, and .previous.held (the way back to the state before the last successful install) is left behind and is deleted by the next take_snapshot();
2. during or after the import check: the new plugin is fully on the volume but has no line in plugins.json. Every worker started afterwards loads it at ready() (the registry reads every entry point on the path, not the record), while Disable and Remove answer "is not installed", because both look it up in the record.
  The administrator sees only a 502 or a reset connection.
Who can trigger it: an administrator installing a plugin with a large dependency tree over a slow link or on slow hardware (the Dockerfile's own comment names the Raspberry Pi); no attacker is involved.
Why it matters: code can end up running on every worker without a record line, unverified and impossible to switch off from the interface, and the rollback that #246 added is lost exactly when it is needed.
Fix: run install, upgrade, removal and rollback as a django-tasks-db task, as #247 did for other slow work, with a "working…" state on the page and the in-request path only for an instance without a worker. Until then, keep the in-request budgets well under the worker timeout (or derive them from it), and make install_wheel restore and give back the snapshot on any BaseException before re-raising.

Related to #220 and #247 (both closed), which moved slow work out of requests but did not list plugin installs.

Done when

A test in tests/test_plugin_install.py that makes run_install (and, separately, verify_imports) raise SystemExit and asserts the plugins directory, .previous and plugins.json are as they were before the attempt.
A test that INSTALL_TIMEOUT + VERIFY_TIMEOUT plus the download budget stays below the worker timeout set in docker/Dockerfile, or that installs are queued rather than run in the request.

Found on 2026-09-29 in a read-only review of postulo at 95348908d, by comparing the install path's time budgets with the image's gunicorn settings and following what runs when the worker is aborted. Checked again on 2026-10-01 against `main` at `0a5cad587`: still present. The code is now at `plugins/installing.py:89-93` (the two budgets), `plugins/installing.py:725-814` (`install_wheel`: `take_snapshot()` at `:756`, `except InstallError` at `:761`, `verify_imports` at `:773`, `write_record` at `:810`), and `core/server_views.py:1369-1406` (`_confirm`) and `:1438-1453` (`_install`); `plugins/catalogue.py:296` and `docker/Dockerfile:354` have not moved. Confirming an upload or installing from a catalogue runs the whole install inside a sync gunicorn worker: a wheel download allowed 120 s per read, a snapshot copy of the whole plugins directory, an installer subprocess allowed 300 s (it resolves and downloads the dependency tree from PyPI), and an import check allowed 60 s. The image kills a worker whose request passes 120 s. The 300-second budget can therefore never be used, and when the worker is killed the install's own clean-up does not run. - **Where:** `plugins/installing.py:76-80` (`INSTALL_TIMEOUT = 300`, `VERIFY_TIMEOUT = 60`); `plugins/installing.py:899-988` (`install_wheel`: `take_snapshot()` at :930, `except InstallError` at :935, `verify_imports` at :947, `write_record` at :984); `plugins/catalogue.py:296` (`download`, `timeout=120.0`); `core/server_views.py:1368-1405` (`_confirm`) and `:1437-1452` (`_install`); `docker/Dockerfile:354` (`GUNICORN_CMD_ARGS="--timeout 120 ..."`). - **What happens:** past 120 s the arbiter sends the worker `SIGABRT`, which gunicorn turns into `sys.exit(1)`, and then `SIGKILL`. `SystemExit` is not an `InstallError`, so neither `restore_snapshot()` nor `give_back_snapshot()` runs; `subprocess.run` kills the half-finished installer on its way out. Depending on the moment: 1. during the installer: the live directory may hold a partial install, and `.previous.held` (the way back to the state before the last successful install) is left behind and is deleted by the next `take_snapshot()`; 2. during or after the import check: the new plugin is fully on the volume but has no line in `plugins.json`. Every worker started afterwards loads it at `ready()` (the registry reads every entry point on the path, not the record), while *Disable* and *Remove* answer "is not installed", because both look it up in the record. The administrator sees only a 502 or a reset connection. - **Who can trigger it:** an administrator installing a plugin with a large dependency tree over a slow link or on slow hardware (the Dockerfile's own comment names the Raspberry Pi); no attacker is involved. - **Why it matters:** code can end up running on every worker without a record line, unverified and impossible to switch off from the interface, and the rollback that #246 added is lost exactly when it is needed. - **Fix:** run install, upgrade, removal and rollback as a `django-tasks-db` task, as #247 did for other slow work, with a "working…" state on the page and the in-request path only for an instance without a worker. Until then, keep the in-request budgets well under the worker timeout (or derive them from it), and make `install_wheel` restore and give back the snapshot on any `BaseException` before re-raising. Related to #220 and #247 (both closed), which moved slow work out of requests but did not list plugin installs. ## Done when - A test in `tests/test_plugin_install.py` that makes `run_install` (and, separately, `verify_imports`) raise `SystemExit` and asserts the plugins directory, `.previous` and `plugins.json` are as they were before the attempt. - A test that `INSTALL_TIMEOUT + VERIFY_TIMEOUT` plus the download budget stays below the worker timeout set in `docker/Dockerfile`, or that installs are queued rather than run in the request.

tiagoagueda added this to the 0.5.0 milestone

2026-10-01 10:48:12 +00:00

tiagoagueda added the

bug

label

2026-10-01 10:48:12 +00:00

tiagoagueda referenced this issue from a commit

2026-10-04 10:04:58 +00:00

Restore the plugins directory when an install is killed

tiagoagueda closed this issue

2026-10-04 10:04:58 +00:00

tiagoagueda referenced this issue from a commit