[Backend] Wiki suggestions are written twice: the consolidate step's wait-retry is caught and retried again #609

Closed
opened 2026-09-11 21:41:50 +00:00 by claude-bot · 2 comments
Collaborator

What happens

A session's pending wiki suggestions can each be stored twice. On dev, the replay session 5b0d6ac1 has 24 pending suggestions: 12 titles, each stored twice with identical bodies. Two separate calls wrote them about 9.5 ms apart: bot_proposed_at is 18:42:23.104039 on one copy and .113589 on the other, and the two transactions started 4.5 ms apart.

Cause

lore_consolidate_proposals (reminder_tasks.py) waits for the match tasks with raise self.retry(countdown=30 * 2**retries, exc=RuntimeError("Waiting for match tasks")), called inside _run(). Two things then go wrong:

  • Two retries get queued. self.retry() publishes a retry message, then raises celery.exceptions.Retry. That is an Exception subclass, so the task's outer except Exception catches it and passes it to _retry_unless_permanent. That calls task.retry(countdown=default_retry_delay * 2**retries), which is the same 30·2ⁿ, so the second message has the same due time.
  • Both copies write. They wake together and both find every match row present. Both then call create_bot_lore_proposals. Under READ COMMITTED, its delete-then-insert gives no protection against a concurrent twin, because neither delete sees the other's uncommitted inserts.
  • It compounds. Each further wait cycle doubles the copies again, up to max_retries=3.

It happens whenever the match phase outlasts the consolidate step's first 60 s countdown. With the local model that is the normal case.

Only this site is affected. The ASR queue wait (around line 3491) catches _CeleryRetry deliberately, and every other self.retry is raised from inside an except block.

Fix

  1. Let Retry through. Add except Retry: raise ahead of the broad except, or move the readiness check outside the try.
  2. Make the write idempotent in its own right, since Celery delivers at least once regardless. Lock the session row (SELECT … FOR UPDATE) before the delete and insert. Return early if another delivery has already finished the run.
  3. Regression tests:
    • a consolidate that has to wait once queues exactly one retry
    • two concurrent consolidates write one set of suggestions
  4. Clean up existing doubles.
    • On dev, the replay session.
    • On prod, count first with a read-only query (blocked from the agent session; needs the owner). Then run a one-off dedupe of pending bot rows by (linked_session_id, entry_type, title), keeping the earliest copy.

Found while answering "what happens to suggested wiki updates after corrections?", a follow-up to #424 and #607.

## What happens A session's pending wiki suggestions can each be stored twice. On dev, the replay session 5b0d6ac1 has **24 pending suggestions: 12 titles, each stored twice** with identical bodies. Two separate calls wrote them about 9.5 ms apart: `bot_proposed_at` is 18:42:23.104039 on one copy and .113589 on the other, and the two transactions started 4.5 ms apart. ## Cause `lore_consolidate_proposals` (`reminder_tasks.py`) waits for the match tasks with `raise self.retry(countdown=30 * 2**retries, exc=RuntimeError("Waiting for match tasks"))`, called inside `_run()`. Two things then go wrong: - **Two retries get queued.** `self.retry()` publishes a retry message, then raises `celery.exceptions.Retry`. That is an `Exception` subclass, so the task's outer `except Exception` catches it and passes it to `_retry_unless_permanent`. That calls `task.retry(countdown=default_retry_delay * 2**retries)`, which is the same 30·2ⁿ, so the second message has the same due time. - **Both copies write.** They wake together and both find every match row present. Both then call `create_bot_lore_proposals`. Under READ COMMITTED, its delete-then-insert gives no protection against a concurrent twin, because neither delete sees the other's uncommitted inserts. - **It compounds.** Each further wait cycle doubles the copies again, up to `max_retries=3`. It happens whenever the match phase outlasts the consolidate step's first 60 s countdown. With the local model that is the normal case. **Only this site is affected.** The ASR queue wait (around line 3491) catches `_CeleryRetry` deliberately, and every other `self.retry` is raised from inside an `except` block. ## Fix 1. **Let `Retry` through.** Add `except Retry: raise` ahead of the broad `except`, or move the readiness check outside the `try`. 2. **Make the write idempotent in its own right**, since Celery delivers at least once regardless. Lock the session row (`SELECT … FOR UPDATE`) before the delete and insert. Return early if another delivery has already finished the run. 3. **Regression tests:** - a consolidate that has to wait once queues exactly one retry - two concurrent consolidates write one set of suggestions 4. **Clean up existing doubles.** - On dev, the replay session. - On prod, count first with a read-only query (blocked from the agent session; needs the owner). Then run a one-off dedupe of pending bot rows by `(linked_session_id, entry_type, title)`, keeping the earliest copy. Found while answering "what happens to suggested wiki updates after corrections?", a follow-up to #424 and #607.
Author
Collaborator

Picking this up now, ahead of #610, because every re-run keeps writing duplicates until it is fixed.

Prod, measured read-only: 24 pending bot suggestions, of which 12 are extra copies across 12 doubled groups, on one session. Every pending suggestion that session has is doubled, and no other session has pending suggestions at all.

Cleanup: the delete is a write to prod, so the owner runs or approves it. Planned shape, keeping the earliest copy of each group:

delete from lore_entries l
using lore_entries keep
where l.proposed_by_bot and l.deleted_at is null
  and keep.proposed_by_bot and keep.deleted_at is null
  and keep.linked_session_id = l.linked_session_id
  and keep.entry_type = l.entry_type
  and keep.title = l.title
  and (keep.bot_proposed_at, keep.id) < (l.bot_proposed_at, l.id);

Run as a select count(*) first. Alternatively, once the fix is deployed, the owner can simply press "Look for wiki updates again" on that session, which replaces the whole pending set for it — at the cost of one fresh extraction.

Picking this up now, ahead of #610, because every re-run keeps writing duplicates until it is fixed. **Prod, measured read-only:** 24 pending bot suggestions, of which **12 are extra copies across 12 doubled groups, on one session**. Every pending suggestion that session has is doubled, and no other session has pending suggestions at all. **Cleanup:** the delete is a write to prod, so the owner runs or approves it. Planned shape, keeping the earliest copy of each group: ```sql delete from lore_entries l using lore_entries keep where l.proposed_by_bot and l.deleted_at is null and keep.proposed_by_bot and keep.deleted_at is null and keep.linked_session_id = l.linked_session_id and keep.entry_type = l.entry_type and keep.title = l.title and (keep.bot_proposed_at, keep.id) < (l.bot_proposed_at, l.id); ``` Run as a `select count(*)` first. Alternatively, once the fix is deployed, the owner can simply press "Look for wiki updates again" on that session, which replaces the whole pending set for it — at the cost of one fresh extraction.
Author
Collaborator

Fixed in PR #611, merged to main as e2e6616 and deployed to dev.

Verified on dev:

  • _retry_unless_permanent re-raises Retry untouched, so a waiting consolidate queues exactly one retry.
  • The consolidate step takes a row lock and returns early when a twin delivery has already written.
  • Backend suite: 3404 passed, 13 skipped. Lint clean under CI's pinned ruff.

Still outstanding: the existing duplicates on prod — 12 extra copies on one session. Two ways to clear them, owner's choice:

  1. Press "Look for wiki updates again" on that session once the release reaches prod. It replaces the whole pending set for the session, and with this fix in place the replacement is written once. Costs one fresh extraction and needs no SQL.
  2. Run the delete in the comment above, after checking it with select count(*) first.

Closing the defect itself. The prod cleanup is tracked in the release notes rather than holding this open — reopen if the doubling is ever seen again after e2e6616.

Fixed in PR #611, merged to main as `e2e6616` and deployed to dev. **Verified on dev:** - `_retry_unless_permanent` re-raises `Retry` untouched, so a waiting consolidate queues exactly one retry. - The consolidate step takes a row lock and returns early when a twin delivery has already written. - Backend suite: 3404 passed, 13 skipped. Lint clean under CI's pinned ruff. **Still outstanding: the existing duplicates on prod** — 12 extra copies on one session. Two ways to clear them, owner's choice: 1. Press **"Look for wiki updates again"** on that session once the release reaches prod. It replaces the whole pending set for the session, and with this fix in place the replacement is written once. Costs one fresh extraction and needs no SQL. 2. Run the delete in the comment above, after checking it with `select count(*)` first. Closing the defect itself. The prod cleanup is tracked in the release notes rather than holding this open — reopen if the doubling is ever seen again after `e2e6616`.
rbrooks referenced this issue from a commit 2026-09-11 23:46:58 +00:00
Sign in to join this conversation.
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference
rbrooks/Quest-Board#609
No description provided.