Plugin data: the three loops that ask data-owning plugins swallow failures unlogged, and a failing eraser makes erasing a contact a 500 #371

New issue

Closed

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

tiagoagueda commented

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

Owner

Found on 2026-09-29 in a read-only review of postulo at 95348908d, by reading every loop that calls a plugin's export_for or erase_for and running the erasure with a stand-in plugin that owns rows. Related to #297 (closed), which added the data-subject export and the erasure and promised one loop "rather than two"; this issue covers what that work left: three copies of the loop, none of which logs, and an erasure that a failing plugin can break.

Checked again on 2026-10-01 against main at 0a5cad587: still present. The three loops and core/export.py are where they were; the code is now at plugins/registry.py:364-365 for the logger.exception used as the comparison, and at CONTRIBUTING.md line 618 for "What a plugin that owns a model has to do".

Three functions walk every plugin that declares owns_models and call its export_for or erase_for inside a bare except Exception:. None of them logs, although docs/THREAT-MODEL.md:17 promises that "a plugin that raises is logged and skipped". None of them gives the plugin a savepoint either, so in the erasure a plugin whose failure comes out of an ORM write poisons the transaction: the contact is not erased and the person gets a 500. No plugin Postulo ships owns rows today (plugins/data.py:3, plugins/data.py:50-52), so all of this is latent, but the contract is written for plugins that will (CONTRIBUTING.md, "A plugin that owns a model").

Where:
- core/gdpr.py:250-276 (_erase_plugin_rows): except Exception: not_erased.append(str(plugin.label)), called at core/gdpr.py:292 inside the transaction.atomic() of erase_contact (core/gdpr.py:279-310), reached from ContactDeleteView.form_valid in jobs/views.py:793-802 while the GDPR feature is offered.
- plugins/data.py:146-175 (export_sections_for, used by the account archive and by the subject export at core/gdpr.py:159-161): except Exception: # pragma: no cover, then missing.extend(...).
- jobs/merging.py:522-545 (_held_by_plugins, "Asked the way the archive asks"): except Exception: holds = True.
- core/export.py:490-496 (_plugin_data) wraps the whole section in a second silent except.
- For comparison, notifications/service.py:85-88 and plugins/registry.py:382-383 call logger.exception.

1. A failing plugin leaves nothing in the log

A plugin that owns a table raises in export_for or erase_for, because of a bug or an unapplied migration. The archive names its models under not_carried, the merge dialog says it holds rows, and the erasure lists it under not_erased, but nothing reaches the log. The operator cannot tell a crashing plugin from one that simply does not answer, and the plugin's author has no traceback. The fail-safe answers are right; the silence is what breaks the stated rule.

The # pragma: no cover on plugins/data.py:170 is also untrue: tests/test_plugin_data.py:261 (test_a_plugin_that_raises_while_exporting_is_named_rather_than_fatal) runs that branch.

2. The erasure has no savepoint around the plugin

erase_contact calls every eraser inside one transaction.atomic() and catches what it raises. When the failure comes out of an ORM write (a save() that violates a constraint, or a delete() whose pre_delete handler raises), Django has already marked the transaction for rollback, and the next query, contact.phone_numbers.count() at core/gdpr.py:294, raises TransactionManagementError: An error occurred in the current transaction. Reproduced in the snapshot on SQLite with a stand-in plugin that owns core.Tag: the contact survives, the request is a 500, and the log is empty. The first plugin whose eraser fails this way makes every contact impossible to delete while the feature is offered, with no trace of why.

The two read loops have the same shape. Every request is a transaction (config/settings/base.py:140 sets ATOMIC_REQUESTS), and on PostgreSQL a statement that fails, such as a query against a table whose migration was not applied, aborts the transaction until it is rolled back, so the caught exception would be followed by a failure at the next query of the export or the merge plan. This part was not run; SQLite does not behave that way.

3. The docstring and the code disagree about the rows left behind

_erase_plugin_rows says a failing plugin's "rows stay: deleting the contact underneath it would leave rows pointing at nothing". erase_contact then calls contact.delete() whatever not_erased holds. When the eraser fails with a plain Python exception the erasure completes, the contact is deleted, and the summary reads "These still hold rows Postulo could not reach: ...", which are now rows about a person who no longer exists: the outcome the docstring says the function prevents. Reproduced in the snapshot.

4. Three copies of one loop, and an undocumented half of the contract

plugins/data.py:139-141 says that "one loop rather than two is what keeps the two from drifting apart (#297)", yet jobs/merging.py and core/gdpr.py each carry their own copy of the walk over GROUPS, the owned_labels test and the getattr. They have drifted already: one names a plugin by plugin.label, one by getattr(plugin, "label", plugin.name), one by its model labels.

erase_for itself appears nowhere but core/gdpr.py: CONTRIBUTING.md ("What a plugin that owns a model has to do", line 616) shows owns_models and export_for only, and no test defines a plugin with erase_for. A plugin author following the guide ships a plugin that is always named under not_erased.

Why it matters: the promise that a plugin that raises is logged is not kept in the three places where a plugin handles a person's own data; an erasure can be made to fail for every contact by one faulty plugin; and a report can say a person "is gone" while a plugin still holds rows about them.
Fix:
- Give plugins/data.py one iterator over data-owning plugins, and beside export_sections_for two helpers, for example holds_rows_for(subject) and erase_rows_for(subject); use them from jobs/merging.py and core/gdpr.py and delete the copies.
- In that one place, call each plugin inside its own with transaction.atomic(): (a savepoint), and call logger.exception(...) in the except, naming the plugin and the subject's model and primary key. Keep the fail-safe answers as they are, and log in core/export.py:495 as well.
- Decide the question of the rows left behind and make the docstring and the code agree: either refuse the erasure while a plugin that owns rows could not erase them, saying which, or keep deleting and correct the docstring to say that the rows are left behind and named.
- Remove the # pragma: no cover at plugins/data.py:170, and document erase_for (what it receives, that it returns the number of rows removed) beside export_for in CONTRIBUTING.md.

Done when

tests/test_gdpr.py has a test with a stand-in plugin that owns core.Tag and whose erase_for performs a failing ORM write; it asserts that erase_contact does not raise, that the plugin is named in not_erased, and that the failure is logged (caplog). It fails today with TransactionManagementError.
tests/test_gdpr.py has a test for the outcome chosen in section 3: with an eraser that raises, either the contact is still there and the refusal names the plugin, or the contact is gone and the docstring says so.
tests/test_plugin_data.py registers a data-owning plugin whose export_for and erase_for raise, and asserts with caplog that the archive export, the merge plan and the erasure each write an error record naming the plugin, while their answers (not_carried, held, not_erased) stay as they are. It fails today because nothing is logged.
A search of src/postulo for owned_labels(plugin) inside a loop over GROUPS finds it in plugins/data.py only.

Found on 2026-09-29 in a read-only review of postulo at 95348908d, by reading every loop that calls a plugin's `export_for` or `erase_for` and running the erasure with a stand-in plugin that owns rows. Related to #297 (closed), which added the data-subject export and the erasure and promised one loop "rather than two"; this issue covers what that work left: three copies of the loop, none of which logs, and an erasure that a failing plugin can break. Checked again on 2026-10-01 against `main` at `0a5cad587`: still present. The three loops and `core/export.py` are where they were; the code is now at `plugins/registry.py:364-365` for the `logger.exception` used as the comparison, and at `CONTRIBUTING.md` line 618 for "What a plugin that owns a model has to do". Three functions walk every plugin that declares `owns_models` and call its `export_for` or `erase_for` inside a bare `except Exception:`. None of them logs, although `docs/THREAT-MODEL.md:17` promises that "a plugin that raises is logged and skipped". None of them gives the plugin a savepoint either, so in the erasure a plugin whose failure comes out of an ORM write poisons the transaction: the contact is not erased and the person gets a 500. No plugin Postulo ships owns rows today (`plugins/data.py:3`, `plugins/data.py:50-52`), so all of this is latent, but the contract is written for plugins that will (`CONTRIBUTING.md`, "A plugin that owns a model"). - **Where:** - `core/gdpr.py:250-276` (`_erase_plugin_rows`): `except Exception: not_erased.append(str(plugin.label))`, called at `core/gdpr.py:292` inside the `transaction.atomic()` of `erase_contact` (`core/gdpr.py:279-310`), reached from `ContactDeleteView.form_valid` in `jobs/views.py:793-802` while the GDPR feature is offered. - `plugins/data.py:146-175` (`export_sections_for`, used by the account archive and by the subject export at `core/gdpr.py:159-161`): `except Exception: # pragma: no cover`, then `missing.extend(...)`. - `jobs/merging.py:522-545` (`_held_by_plugins`, "Asked the way the archive asks"): `except Exception: holds = True`. - `core/export.py:490-496` (`_plugin_data`) wraps the whole section in a second silent `except`. - For comparison, `notifications/service.py:85-88` and `plugins/registry.py:382-383` call `logger.exception`. ## 1. A failing plugin leaves nothing in the log A plugin that owns a table raises in `export_for` or `erase_for`, because of a bug or an unapplied migration. The archive names its models under `not_carried`, the merge dialog says it holds rows, and the erasure lists it under `not_erased`, but nothing reaches the log. The operator cannot tell a crashing plugin from one that simply does not answer, and the plugin's author has no traceback. The fail-safe answers are right; the silence is what breaks the stated rule. The `# pragma: no cover` on `plugins/data.py:170` is also untrue: `tests/test_plugin_data.py:261` (`test_a_plugin_that_raises_while_exporting_is_named_rather_than_fatal`) runs that branch. ## 2. The erasure has no savepoint around the plugin `erase_contact` calls every eraser inside one `transaction.atomic()` and catches what it raises. When the failure comes out of an ORM write (a `save()` that violates a constraint, or a `delete()` whose `pre_delete` handler raises), Django has already marked the transaction for rollback, and the next query, `contact.phone_numbers.count()` at `core/gdpr.py:294`, raises `TransactionManagementError: An error occurred in the current transaction`. Reproduced in the snapshot on SQLite with a stand-in plugin that owns `core.Tag`: the contact survives, the request is a 500, and the log is empty. The first plugin whose eraser fails this way makes every contact impossible to delete while the feature is offered, with no trace of why. The two read loops have the same shape. Every request is a transaction (`config/settings/base.py:140` sets `ATOMIC_REQUESTS`), and on PostgreSQL a statement that fails, such as a query against a table whose migration was not applied, aborts the transaction until it is rolled back, so the caught exception would be followed by a failure at the next query of the export or the merge plan. This part was not run; SQLite does not behave that way. ## 3. The docstring and the code disagree about the rows left behind `_erase_plugin_rows` says a failing plugin's "rows stay: deleting the contact underneath it would leave rows pointing at nothing". `erase_contact` then calls `contact.delete()` whatever `not_erased` holds. When the eraser fails with a plain Python exception the erasure completes, the contact is deleted, and the summary reads "These still hold rows Postulo could not reach: ...", which are now rows about a person who no longer exists: the outcome the docstring says the function prevents. Reproduced in the snapshot. ## 4. Three copies of one loop, and an undocumented half of the contract `plugins/data.py:139-141` says that "one loop rather than two is what keeps the two from drifting apart (#297)", yet `jobs/merging.py` and `core/gdpr.py` each carry their own copy of the walk over `GROUPS`, the `owned_labels` test and the `getattr`. They have drifted already: one names a plugin by `plugin.label`, one by `getattr(plugin, "label", plugin.name)`, one by its model labels. `erase_for` itself appears nowhere but `core/gdpr.py`: `CONTRIBUTING.md` ("What a plugin that owns a model has to do", line 616) shows `owns_models` and `export_for` only, and no test defines a plugin with `erase_for`. A plugin author following the guide ships a plugin that is always named under `not_erased`. - **Why it matters:** the promise that a plugin that raises is logged is not kept in the three places where a plugin handles a person's own data; an erasure can be made to fail for every contact by one faulty plugin; and a report can say a person "is gone" while a plugin still holds rows about them. - **Fix:** - Give `plugins/data.py` one iterator over data-owning plugins, and beside `export_sections_for` two helpers, for example `holds_rows_for(subject)` and `erase_rows_for(subject)`; use them from `jobs/merging.py` and `core/gdpr.py` and delete the copies. - In that one place, call each plugin inside its own `with transaction.atomic():` (a savepoint), and call `logger.exception(...)` in the `except`, naming the plugin and the subject's model and primary key. Keep the fail-safe answers as they are, and log in `core/export.py:495` as well. - Decide the question of the rows left behind and make the docstring and the code agree: either refuse the erasure while a plugin that owns rows could not erase them, saying which, or keep deleting and correct the docstring to say that the rows are left behind and named. - Remove the `# pragma: no cover` at `plugins/data.py:170`, and document `erase_for` (what it receives, that it returns the number of rows removed) beside `export_for` in `CONTRIBUTING.md`. ## Done when - `tests/test_gdpr.py` has a test with a stand-in plugin that owns `core.Tag` and whose `erase_for` performs a failing ORM write; it asserts that `erase_contact` does not raise, that the plugin is named in `not_erased`, and that the failure is logged (`caplog`). It fails today with `TransactionManagementError`. - `tests/test_gdpr.py` has a test for the outcome chosen in section 3: with an eraser that raises, either the contact is still there and the refusal names the plugin, or the contact is gone and the docstring says so. - `tests/test_plugin_data.py` registers a data-owning plugin whose `export_for` and `erase_for` raise, and asserts with `caplog` that the archive export, the merge plan and the erasure each write an error record naming the plugin, while their answers (`not_carried`, held, `not_erased`) stay as they are. It fails today because nothing is logged. - A search of `src/postulo` for `owned_labels(plugin)` inside a loop over `GROUPS` finds it in `plugins/data.py` only.

tiagoagueda added this to the 0.6.0 milestone

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

tiagoagueda added the

observability

bug

labels

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

tiagoagueda referenced this issue from a commit

2026-10-02 00:05:32 +00:00

Ask data-owning plugins in one place, in a savepoint, and say when one fails

tiagoagueda closed this issue

2026-10-02 00:05:32 +00:00