fix(rollingops): stop etcd integration tests racing the worker poll loop

[tonyandrewmeyer]

The rollingops machine integration tests fail regularly on main and on PRs (#638 has several examples). The dominant signature is test_retry_hold_operation_two_units_single_app seeing only unit_b's events, and it appears in 4 of the last 4 failing runs on main:

FAILED test_etcd_rolling_ops.py::test_retry_hold_operation_two_units_single_app
  - AssertionError: unexpected event sequence: [('test/3', '_restart:start', 'etcd'), ('test/3', '_restart:done', 'etcd')]

test_retry_release_two_units_single_app also fails, in two variants: assert 10 == ((2 * 2) * 3) and assert 'peer' == 'etcd'.

The etcd lock is granted in worker-poll order, not request order

Each unit runs its own etcd worker (_etcd/_rollingops.py), which sleeps NEXT_OP_SLEEP = 30 between idle queue polls and LOCK_ACQUIRE_SLEEP = 15 between acquisition attempts. The lock itself (EtcdLock.try_acquire) is a compare-and-set spinlock, not a FIFO queue. So the time between enqueuing an operation and acquiring the lock is essentially uniform in [0, 30] s per unit, and the order in which units get the lock bears no relation to the order in which the operations were requested.

From the Juju log of a failing run:

22:54:38  test/1  Operation _deferred_restart added to the etcd queue   <- unit_a requests
22:54:43  test/3  Operation _restart added to the etcd queue            <- unit_b requests, 5s later
22:54:48  test/3  Executing callback_id=_restart  ... done 22:54:50     <- unit_b wins the lock
22:54:55          test asserts -> only test/3's events exist -> FAIL
22:55:07  test/1  Executing callback_id=_deferred_restart, attempt=0    <- unit_a, 29s after its request

The test used time.sleep(2) between the two actions to establish ordering, which cannot win against a 30 s poll interval. It now waits until unit_a has actually recorded _deferred_restart:start (holds the lock) before unit_b requests, which is what the test means to exercise.

Likewise, test_retry_release_two_units_single_app used a fixed time.sleep(60 * 3) to bound 12 events whose total duration depends on how the two workers' poll intervals line up. In the assert 10 == 12 failure, 10 events had been recorded and the remaining two arrived roughly 30 s after the sleep expired. Both that test and test_retry_release_alternates_execution in the peer suite now poll for the events they expect.

The library only promises that operations run "at most one unit at a time" — it does not promise request ordering across units — so this is the tests over-specifying, not a backend bug.

Spurious fallback to the peer backend

The assert 'peer' == 'etcd' variant is a library defect. _on_update_status executes the in-progress operation, so the worker's own already-queued lock-granted hook can arrive after another hook has already executed and finalised the claimed operation. The same window exists between the worker's requeue_completed() and claim_next() on a retry. peek_current() is empty then, and mirror_outcome classified that as an etcd/peer inconsistency:

22:55:44  test/1  Lock granted but there is no operation to run.
22:55:45  test/1  Inconsistencies found between peer relation and etcd. Falling back to peer backend.

The unit then processed the rest of the operation on the peer backend, so the recorded processing_backend flipped to peer.

_on_run_with_lock now distinguishes "lock held, work queued, nothing in progress yet" (OPERATION_PENDING, a normal transient) from "etcd has no work at all for this unit" (NO_OPERATION, a genuine divergence). Only the latter falls back. Genuine etcd corruption is still caught by the worker's own consistency check, which dispatches the etcd-failed hook.

Refs #593

[patriciareinoso]

Thank you @tonyandrewmeyer for taking the time on this. This was an annoying error I was not able to reproduce locally. I will take a look

[patriciareinoso]

this is excellent work, thanks a lot for it