Skip to content

Node model: Don't lose locks when lock_many hits a DB error - #154

Merged
djgalloway merged 2 commits into
mainfrom
wip-lock-many-lost-locks
Oct 9, 2026
Merged

djgalloway merged 2 commits into
mainfrom
wip-lock-many-lost-locks

Conversation

@djgalloway

Copy link
Copy Markdown
Contributor

Fixes the double allocation of test nodes tracked in https://tracker.ceph.com/issues/74774 (most recent instance: https://tracker.ceph.com/issues/80969).

The bug

Node.update() is wrapped in retryOperation, which handles a DB error by rolling back the session and calling update() again. Node.lock_many() locks every node it found in one transaction, so when the flush for node K fails:

  1. the rollback undoes nodes 1..K-1 as well,
  2. only node K is retried, then K+1..N follow,
  3. the request commits and returns all N nodes.

The response claims N nodes; only N-K+1 are locked in the database. teuthology starts the job, and the next lock_many is handed the nodes that are still free. Two jobs then reimage and run cephlab.yml on the same machines at once.

lock_many runs at SERIALIZABLE, so serialization failures are expected whenever other requests are writing to nodes, which is exactly when a run is being dispatched.

Evidence

In job skanta-2026-09-20_02:51:43-rados-wip-bharath22-testing-20260920.002814-main-distro-default-trial/570050, paddles returned trial029, trial120, trial143 and trial177. Two seconds later job 570051 was given trial029 and trial177. 570050's own check_lock output shows those two nodes with 570051's archive path as the lock description.

I went through the incidents on 74774 and its 2026 duplicates that still have records. Nine are real double allocations, and all nine have the same shape:

Job that lost nodes Requested Lost Kept Taken by
19873 2 1 1 19874
42101 4 1 3 42102
44743 2 1 1 44744
199239 4 1 3 199240
215660 2 1 1 215661
400591 2 1 1 400594
407382 4 2 2 407383
518538 3 1 2 518540
570050 4 2 2 570051

Every job that lost nodes had asked for at least two and kept at least one. None was a single-node job, although four of the nine jobs that took the nodes were. That is what a partial rollback inside a multi-node transaction produces, and this bug cannot affect a one-node request.

The paddles log already on 74774 (2026-02-11) fits too: the same pod logged Locked trial190 trial137 for 44743 and then Locked trial190 for 44744 half a second later.

The change

  • Node.update() keeps its retry; the body moves to Node._update().
  • Node.lock_many() calls _update(), so a DB error propagates to the retryOperation that already wraps lock_many_post, which rolls back and redoes the whole query and update.
  • retryOperation logs a warning each time it rolls back and retries. Until now a retry that succeeded left nothing in the logs, which is why this went unseen.

Testing

  • New test_lock_many_db_error_mid_request injects an OperationalError while the third of four nodes is being locked. On main it fails with ['n2', 'n3'] == ['n0', 'n1', 'n2', 'n3']: four nodes claimed, two locked. With this change it passes.
  • New test_retry_is_logged.
  • Full suite: 189 passed, 3 skipped. flake8 --select=F is clean.

Limits

  • The DB error itself has not been observed in production. The injected error is synthetic and the suite runs on SQLite; nothing here reproduces a real PostgreSQL serialization failure under load. The new warning will show whether that is what happens.
  • If the error persists through all 10 attempts the request fails with a 500. teuthology treats any non-OK response as a failed lock and tries again.
  • Two reports filed under 74774 (jobs 465960 and 520644) are reimage failures with no overlapping job recorded on the node. This does not address them.
  • SQLAlchemy v2: production fixes on top of #150 #153 is not affected in its current form, because update() no longer flushes there. It still carries the decorator and has no test for this; the test should be ported once this merges.

Merging deploys this to Sepia through the ImageStream within a few minutes. There is no migration, so it is an ordinary rolling restart.


Prepared with Claude Fable 5.1.

Node.update() is wrapped in retryOperation, which handles a DB error by
rolling back the session and calling update() again. That is fine when
the transaction only changes one node, but Node.lock_many() locks all of
the nodes it found in a single transaction. If the flush for the third
of four nodes fails (e.g. with a serialization failure, since lock_many
runs SERIALIZABLE), the rollback also undoes the first two, only the
third is retried, and the fourth follows. The request then commits and
returns all four nodes, two of which are still unlocked in the database.

teuthology believes it holds all four and starts the job; the next
lock_many request is handed the two that are still free. Both jobs then
reimage and run ansible on the same machines at the same time, which
shows up as reimages landing on the wrong OS, LVM/dmsetup errors in
zap_disks, lost ssh connections and so on.

Every double allocation with surviving records on the tracker has this
shape: the job that lost nodes had asked for at least two, kept at least
one of them, and the job that took the others was dispatched within
seconds.

Split the retry out of update() so that lock_many can update nodes
without it. A DB error now propagates to the retryOperation that already
wraps lock_many_post, which rolls back and redoes the whole query and
update.

Fixes: https://tracker.ceph.com/issues/74774
Fixes: https://tracker.ceph.com/issues/80969
Signed-off-by: David Galloway <[email protected]>
Assisted-by: Claude Fable 5.1 (claude-fable-5-1)
retryOperation only logged once it had run out of attempts. A retry that
succeeded left no trace, even though it rolls back the session first and
so discards everything the transaction had done up to that point. That
made the lost node locks in https://tracker.ceph.com/issues/74774
impossible to see in the logs.

Log a warning with the function and the error each time we roll back and
retry.

Signed-off-by: David Galloway <[email protected]>
Assisted-by: Claude Fable 5.1 (claude-fable-5-1)
@djgalloway
djgalloway requested a review from dmick September 28, 2026 21:40
@djgalloway
djgalloway merged commit ea8c54f into main Oct 9, 2026
6 checks passed
djgalloway added a commit that referenced this pull request Oct 9, 2026
Resolves the conflicts with the lock_many lost-locks fix (#154):

- decorators.py: keep main's retry logging, roll back request.session
  (the SQLAlchemy 2 per-request session) instead of the removed
  paddles.models.Session.
- models/nodes.py: lock_many uses the unretried _update() per node, as
  on main, so a DB error propagates and the whole request is retried.
  No commit() in the model; the controller commits the request session.
- test_nodes.py: port test_lock_many_db_error_mid_request to the
  pytest-fixture style. Nothing flushes per node on this branch, so the
  injected OperationalError fires on the first flush that carries dirty
  objects instead of on a flush call count.
- test_decorators.py: test_retry_is_logged patches
  paddles.decorators.request like the other retry tests, since the
  retry path now touches request.session.

Assisted-by: Claude Fable 5
Signed-off-by: David Galloway <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants