diff --git a/changelog.d/3070.fixed.md b/changelog.d/3070.fixed.md new file mode 100644 index 000000000..4365cf5c4 --- /dev/null +++ b/changelog.d/3070.fixed.md @@ -0,0 +1,13 @@ +- **A directory reconcile pass no longer files a false rename conflict from a stale holder read.** + In the shipped code the reconciler read which account held an AD account's new name, then read + the account itself, and refused the rename on the first read. A holder that let the name go in + between still produced an `auth.ad_username_refresh_conflict` audit row and a lockout warning + that nobody faced, and the rename waited for a later pass. Now the holder is read again after the + account, and that check refuses the rename only when another account holds the name at the + second read. The conflict row's `held_by_user_id` then names that account, not the one the first + read saw. A holder whose record fails its integrity check at the second read is still refused + with the lockout warning, naming the holder the first read verified. A store error on the second + read skips that one rename for the pass instead of ending the pass; a store error on the + pass's other rename reads still ends it. A holder that already fails its integrity check at the + first read still reads as no holder there, so the write's guard stops the rename and the + conflict row names no holder, with a warning that a later pass retries it. Vault BACKLOG #3070. diff --git a/messagefoundry/auth/service.py b/messagefoundry/auth/service.py index 7af33f502..f672195c9 100644 --- a/messagefoundry/auth/service.py +++ b/messagefoundry/auth/service.py @@ -2982,8 +2982,10 @@ def __init__( self._reconcile_unkeyed_refused: dict[str, None] = {} if self.directory_reconcile_enabled: # Built now, at startup, so a reconciler's first refused audit write does not import - # the server drivers on the event loop (see `_audit_write_errors`). + # the server drivers on the event loop (see `_audit_write_errors`). The same for the + # rename refresh's holder re-read, which catches `_session_write_errors` (#3070). _audit_write_errors() + _session_write_errors() # Advisory, NON-STICKY federated-IdP health (ADR 0142 AC-8) — see the oidc_available docstring. self._oidc_unavailable_reason: str | None = None self._oidc_client_auth: oidc.ClientAuthentication | None = None @@ -7670,21 +7672,22 @@ async def _refresh_cached_username( ``audit_soft`` is passed by the reconciler alone (BACKLOG #3018), so its audit writes go through :meth:`_audit_reconciler_row`. The login path leaves it off, so there a refused - write still fails the sign-in, as it always has. + write still fails the sign-in, as it always has. It also lets a store fault on the ``held`` + re-read skip the rename rather than raise (BACKLOG #3070; the reason is at that read). **ONE implementation for two callers, deliberately.** The login path (:meth:`_upsert_ad_user`) and the ADR 0079 reconciler pass both reach a renamed account and both must resolve the collision case the same way. Two copies of this decision would be two policies, and the one that ran less often would be the one nobody noticed drifting. - ``held`` is the row currently holding ``new_username``, read by the caller. Passed rather than - re-read for the reason :meth:`_upsert_ad_user` gives about ``by_name``: it puts the dependency - in the signature instead of only in prose, and here it also saves a query the login caller - **provably** already has the answer to. ``_complete_ad_login`` reads that exact row before it - calls down, and refuses outright when it exists with a different id -- so the login path - reaches this method only with ``held=None``, and the collision branch below is reachable from - the **reconciler alone**, which probes an account it has already identified and has no such - guard. + ``held`` is the row holding ``new_username`` when the caller read it. One naming another + row is re-checked, not trusted: the rule is at the ``held`` pre-check below (BACKLOG + #3070). ``held=None`` skips that pre-check, so a holder appearing after the caller's read is + caught only by the write's guard. The login caller **provably** already has the answer: + ``_complete_ad_login`` reads that exact row before it calls down, and refuses outright when + it exists with a different id -- so the login path reaches this method only with + ``held=None``, and the collision branch below is reachable from the **reconciler alone**, + which probes an account it has already identified and has no such guard. **THE CHECK-THEN-ACT RACE IS REAL AND IS ABSORBED BELOW, NOT PREVENTED BY THE STORE.** This docstring used to say the store's in-statement guard made "a row claiming the name between @@ -7882,8 +7885,48 @@ async def _refuse(held_by: str | None, detected: str, holds: str) -> None: ) return if held is not None and held.id != user_id: - await _refuse(held.id, "pre_check", before.username) - return + # BACKLOG #3070. THE ONE STATEMENT OF THIS RULE. The caller read ``held`` before + # ``before``, so its holder may have let the name go since, and filing on that read + # would audit a conflict and warn of a lockout nobody faces. So the holder of + # ``new_username`` is read again here, after ``before``, and only a row that holds the + # name now is refused; the audit names that row. If nobody holds it, or this row does + # (a sign-in renamed it just now, and the compare-and-set below then writes nothing), + # it is no conflict. A verified holder load, not one statement, but only when the + # caller's read named another row. + # + # A holder that fails its seal at this re-read still holds the name, so it is refused + # as the caller's read would have been, with the lockout warning, not left to the + # write-path refusal's "a later pass retries it", which is false while that holder + # stays seal-failed. Its id is not verified, so the audit names ``held``, the last + # verified holder. NOT CLOSED HERE: the reconciler's own ``held`` read, and at least + # the two write-path holder reads below, still read a seal-failed holder as None; and + # ``refused`` also reads true for a holder deleted or re-keyed between the re-read's + # own row and role reads, a narrow window that still files this refusal. + # + # On the reconciler's path (``audit_soft``) a store fault on this re-read skips this + # one rename for this pass rather than raising: a raise would end the pass before the + # renames after this one. Nothing was written; a later pass that probes the account + # retries it. The other store reads in the rename loop still raise. A sign-in re-raises, + # so it fails loud as it does elsewhere in this method. The error tuple is cached and + # built at construction when the reconciler runs, so no driver is imported here. + try: + current = await self._lookup_by_username(new_username) + except _session_write_errors() as exc: + if not audit_soft: + raise + _log.warning( + "AD account %s: re-reading the holder of its new directory name (account %s " + "held it at the first read) raised %s, so its rename was not applied on this " + "pass; a later pass that probes it retries it (BACKLOG #3070)", + user_id, + held.id, + type(exc).__name__, + ) + return + if current.refused or (current.user is not None and current.user.id != user_id): + holder_id = held.id if current.user is None else current.user.id + await _refuse(holder_id, "pre_check", before.username) + return try: # BACKLOG #2290. A compare-and-set on the name just read, so of two refreshes of this # row running at once only one writes. diff --git a/tests/test_ad_session_reconcile.py b/tests/test_ad_session_reconcile.py index 8b90835dd..cab883e29 100644 --- a/tests/test_ad_session_reconcile.py +++ b/tests/test_ad_session_reconcile.py @@ -26,6 +26,7 @@ import uuid from collections.abc import Callable from dataclasses import replace +from pathlib import Path from typing import Any, Literal, get_args import aiosqlite @@ -51,10 +52,12 @@ ) from messagefoundry.auth.permissions import Role from messagefoundry.auth.service import ( + AUTHORITY_SEAL_FAILED_ACTION, AuthService, DirectoryObjectIdMissing, _AuditWatermark, _RevocationApplied, + _UserLookup, ) from messagefoundry.config.settings import AuthSettings from messagefoundry.store.crypto import CipherError, generate_key, make_cipher @@ -68,6 +71,7 @@ ) from tests._admin_account import create_local_user_chosen from tests.test_approval_requester_recheck import _Sink +from tests.test_user_seal import _raw_for PW = "Sup3rSecret!!" @@ -2803,23 +2807,35 @@ async def test_an_unchanged_name_plans_no_rename() -> None: # --- BACKLOG #2017: the holder is told of a directory rename (ASVS 6.3.7) -------------------------- -async def _renamed_service() -> tuple[ - MessageStore, _FakeLdap, AuthService, _CapturingNotifier, str -]: +async def _renamed_service( + keyed_path: Path | None = None, +) -> tuple[MessageStore, _FakeLdap, AuthService, _CapturingNotifier, str]: """A signed-in ``jdoe`` with a known notification address and a capturing notifier, and the - directory already renaming it to ``jdoe-married`` for the next pass. Returns the row's id.""" - store = await MessageStore.open(":memory:") - ldap = _FakeLdap({"jdoe": _principal("jdoe")}) - service = AuthService(store, _ad_settings(), ldap=ldap) # type: ignore[arg-type] - notifier = _CapturingNotifier() - service._security_notifier = notifier - await service.initialize() - await _signed_in_ad_user(service, store, "jdoe") - jdoe = await store.get_user_by_username("jdoe") - assert jdoe is not None - # Set explicitly, so the address assertion below cannot pass on whatever the birth chose. - await store.set_user_notify_email(jdoe.id, email="holder@example.org") - ldap.present = {"jdoe-married": _principal("jdoe-married", object_id=_object_id_for("jdoe"))} + directory already renaming it to ``jdoe-married`` for the next pass. Returns the row's id. + With ``keyed_path`` the store is a keyed file there, so every user read checks its seal.""" + if keyed_path is None: + store = await MessageStore.open(":memory:") + else: + store = await MessageStore.open( + keyed_path, cipher=make_cipher(generate_key(), write_v2=True) + ) + try: + ldap = _FakeLdap({"jdoe": _principal("jdoe")}) + service = AuthService(store, _ad_settings(), ldap=ldap) # type: ignore[arg-type] + notifier = _CapturingNotifier() + service._security_notifier = notifier + await service.initialize() + await _signed_in_ad_user(service, store, "jdoe") + jdoe = await store.get_user_by_username("jdoe") + assert jdoe is not None + # Set explicitly, so the address assertion below cannot pass on whatever the birth chose. + await store.set_user_notify_email(jdoe.id, email="holder@example.org") + ldap.present = { + "jdoe-married": _principal("jdoe-married", object_id=_object_id_for("jdoe")) + } + except BaseException: + await store.close() + raise return store, ldap, service, notifier, jdoe.id @@ -3264,6 +3280,315 @@ async def test_a_stale_held_row_is_not_a_conflict_when_this_row_already_has_the_ await store.close() +async def _refresh_with_stale_held(service: AuthService, store: MessageStore, user_id: str) -> None: + """Run the refresh as the reconciler does (``audit_soft`` on, BACKLOG #3018), with a ``held`` + naming ``gone-holder``: a record of + another row that held the name when the caller read it, and holds it no more (BACKLOG #3070).""" + row = await store.get_user(user_id) + assert row is not None + await service._refresh_cached_username( + user_id=user_id, + old_username="jdoe", + new_username="jdoe-married", + held=replace(row, id="gone-holder", username="jdoe-married"), + from_plan=True, + audit_soft=True, + ) + + +async def test_a_stale_held_row_that_let_the_name_go_files_no_conflict( + caplog: pytest.LogCaptureFixture, +) -> None: + """BACKLOG #3070. The reconciler's ``held`` named another row, and by the refresh no row holds + the name. The rename writes, audits and notifies once, and nothing warns of a lockout. Before + #3070 this filed a ``pre_check`` conflict naming ``gone-holder``.""" + store, _ldap, service, notifier, user_id = await _renamed_service() + try: + caplog.set_level(logging.INFO, logger="messagefoundry.auth.service") + caplog.clear() + + await _refresh_with_stale_held(service, store, user_id) + + after = await store.get_user(user_id) + assert after is not None and after.username == "jdoe-married" + assert [a["action"] for a in await _rename_audits(store)] == [ + "auth.ad_username_refreshed" + ], "a stale held row filed a conflict for a name nobody holds" + assert not [r for r in caplog.records if r.levelno >= logging.WARNING], ( + "a stale held row warned of a lockout nobody faces" + ) + assert len([e for e in notifier.sent if e.event_type == USERNAME_CHANGED]) == 1 + finally: + await store.close() + + +async def test_a_stale_held_row_refusal_names_the_row_that_holds_the_name_now( + caplog: pytest.LogCaptureFixture, +) -> None: + """BACKLOG #3070, the control. The reconciler's ``held`` named ``gone-holder``, and a different + row holds the name now. The refresh still refuses, and the audit and the warning name the + current holder, not the stale ``held``.""" + store, _ldap, service, notifier, user_id = await _renamed_service() + try: + await store.create_user( + user_id="holder-row", + username="jdoe-married", + auth_provider="ad", + password_generated=False, + ) + caplog.set_level(logging.INFO, logger="messagefoundry.auth.service") + caplog.clear() + + await _refresh_with_stale_held(service, store, user_id) + + after = await store.get_user(user_id) + assert after is not None and after.username == "jdoe" + [conflict] = await _rename_audits(store) + assert conflict["action"] == "auth.ad_username_refresh_conflict" + detail = json.loads(conflict["detail"]) + assert detail["detected"] == "pre_check" + assert detail["held_by_user_id"] == "holder-row", ( + "the conflict audit named the caller's stale holder, not the current one" + ) + warnings = [r for r in caplog.records if r.levelno >= logging.WARNING] + assert ["holder-row" in r.getMessage() for r in warnings] == [True] + assert not [e for e in notifier.sent if e.event_type == USERNAME_CHANGED] + finally: + await store.close() + + +async def test_a_pass_whose_holder_read_went_stale_writes_the_rename( + caplog: pytest.LogCaptureFixture, +) -> None: + """BACKLOG #3070, through the real reconciler pass. The pass reads ``held`` and finds + ``gone-holder`` on ``jdoe-married``; before the refresh reads the row, that holder renames itself + away. The hook acts on the first by-name read of ``jdoe-married``, which is the pass's ``held`` + read; the second is the refresh's re-read, which sees the store as it is. Counting both pins + that order. The rename lands once, with no conflict audit and no lockout warning.""" + store, _ldap, service, notifier, user_id = await _renamed_service() + try: + lookup_by_name = service._lookup_by_username + hooked: list[str] = [] + + async def _holder_lets_go(username: str) -> _UserLookup: + if username != "jdoe-married": + return await lookup_by_name(username) + hooked.append(username) + if len(hooked) > 1: + return await lookup_by_name(username) + await store.create_user( + user_id="gone-holder", + username="jdoe-married", + auth_provider="ad", + password_generated=False, + ) + seen = await lookup_by_name(username) + assert seen.user is not None and seen.user.id == "gone-holder" + assert await store.set_user_username( + "gone-holder", "jdoe-retired", expected_username="jdoe-married" + ) + return seen + + service._lookup_by_username = _holder_lets_go # type: ignore[method-assign] + caplog.set_level(logging.INFO, logger="messagefoundry.auth.service") + caplog.clear() + + plan = await service.reconcile_directory_sessions() + + assert plan.aborted is None + assert hooked == ["jdoe-married", "jdoe-married"], ( + "expected the pass's held read and then the refresh's re-read, and nothing else" + ) + after = await store.get_user(user_id) + assert after is not None and after.username == "jdoe-married" + assert [a["action"] for a in await _rename_audits(store)] == [ + "auth.ad_username_refreshed" + ], "a stale held read in the pass filed a conflict" + assert not [r for r in caplog.records if r.levelno >= logging.WARNING], ( + "a stale held read in the pass warned" + ) + assert len([e for e in notifier.sent if e.event_type == USERNAME_CHANGED]) == 1 + finally: + await store.close() + + +async def test_a_stale_held_row_is_no_conflict_when_this_row_took_the_name_since( + caplog: pytest.LogCaptureFixture, +) -> None: + """BACKLOG #3070. ``held`` is stale, and between the refresh's read of the row and its re-read + of the holder a sign-in gives the name to this very row. That is not a conflict against itself: + the compare-and-set on the name read first writes nothing, and the refresh says so at INFO with + no audit row, notice or warning (BACKLOG #2290).""" + store, _ldap, service, notifier, user_id = await _renamed_service() + try: + lookup_by_name = service._lookup_by_username + hooked: list[str] = [] + + async def _sign_in_renames_first(username: str) -> _UserLookup: + hooked.append(username) + if len(hooked) == 1: + assert await store.set_user_username(user_id, username, expected_username="jdoe") + return await lookup_by_name(username) + + service._lookup_by_username = _sign_in_renames_first # type: ignore[method-assign] + caplog.set_level(logging.INFO, logger="messagefoundry.auth.service") + caplog.clear() + + await _refresh_with_stale_held(service, store, user_id) + + assert hooked == ["jdoe-married"], "expected exactly one holder re-read, and nothing else" + after = await store.get_user(user_id) + assert after is not None and after.username == "jdoe-married" + assert not await _rename_audits(store), "this row filed a conflict against itself" + assert not [e for e in notifier.sent if e.event_type == USERNAME_CHANGED] + assert not [r for r in caplog.records if r.levelno >= logging.WARNING] + assert any("BACKLOG #2290" in r.getMessage() for r in caplog.records) + finally: + await store.close() + + +async def test_a_holder_that_fails_its_seal_by_the_re_read_is_refused_with_the_lockout_warning( + tmp_path: Path, caplog: pytest.LogCaptureFixture +) -> None: + """BACKLOG #3070, on a keyed store, so both reads check the holder's seal. The caller's read + verifies ``holder-row`` on ``jdoe-married``; its record is then changed outside the store, so + the refresh's re-read finds the name held by a row that fails its seal. That row still holds + the name, so the refusal is the ``pre_check`` lockout one naming the verified holder, as before + #3070, and not the write path's "no row holds the new name, a later pass retries it".""" + path = tmp_path / "sealed.db" + store, _ldap, service, notifier, user_id = await _renamed_service(path) + try: + await store.create_user( + user_id="holder-row", + username="jdoe-married", + auth_provider="ad", + password_generated=False, + ) + held = await service._load_user_by_username("jdoe-married") + assert held is not None and held.id == "holder-row", "the caller's read must verify" + await _raw_for(path)("UPDATE users SET display_name=? WHERE id=?", ("bent", "holder-row")) + caplog.set_level(logging.INFO, logger="messagefoundry.auth.service") + caplog.clear() + + await service._refresh_cached_username( + user_id=user_id, + old_username="jdoe", + new_username="jdoe-married", + held=held, + from_plan=True, + audit_soft=True, + ) + + after = await store.get_user(user_id) + assert after is not None and after.username == "jdoe" + assert len(await store.list_audit(action=AUTHORITY_SEAL_FAILED_ACTION)) == 1, ( + "the re-read did not check the holder's seal" + ) + [conflict] = await _rename_audits(store) + assert conflict["action"] == "auth.ad_username_refresh_conflict" + detail = json.loads(conflict["detail"]) + assert (detail["detected"], detail["held_by_user_id"]) == ("pre_check", "holder-row") + messages = [r.getMessage() for r in caplog.records if r.levelno >= logging.WARNING] + assert [m for m in messages if "refused at its next sign-in" in m and "holder-row" in m], ( + "a seal-failed holder at the re-read lost the lockout warning" + ) + assert not [m for m in messages if "retries it" in m] + assert not [e for e in notifier.sent if e.event_type == USERNAME_CHANGED] + finally: + await store.close() + + +async def test_a_store_fault_on_the_holder_re_read_skips_only_that_rename( + caplog: pytest.LogCaptureFixture, +) -> None: + """BACKLOG #3070. Two accounts are renamed in one pass. The first rename the pass applies is + handed a ``held`` naming another row, and the refresh's re-read of that holder raises a store + error. That rename is not applied and is logged; the pass goes on and applies the other one. + The first by-name read of either new name is the pass's ``held`` read for the first rename it + applies, so the faulting rename is always the earlier of the two.""" + store = await MessageStore.open(":memory:") + try: + ldap = _FakeLdap({"jdoe": _principal("jdoe"), "asmith": _principal("asmith")}) + service = AuthService(store, _ad_settings(), ldap=ldap) # type: ignore[arg-type] + notifier = _CapturingNotifier() + service._security_notifier = notifier + await service.initialize() + ids: dict[str, str] = {} + for name in ("jdoe", "asmith"): + await _signed_in_ad_user(service, store, name) + row = await store.get_user_by_username(name) + assert row is not None + ids[f"{name}-wed"] = row.id + ldap.present = { + f"{name}-wed": _principal(f"{name}-wed", object_id=_object_id_for(name)) + for name in ("jdoe", "asmith") + } + lookup_by_name = service._lookup_by_username + faulting: list[str] = [] + + async def _first_re_read_faults(username: str) -> _UserLookup: + if username not in ids: + return await lookup_by_name(username) + if not faulting: + faulting.append(username) + own = await service._load_user(ids[username]) + assert own is not None + return _UserLookup(replace(own, id="other-holder", username=username), True) + if username == faulting[0]: + raise sqlite3.OperationalError("database is locked") + return await lookup_by_name(username) + + service._lookup_by_username = _first_re_read_faults # type: ignore[method-assign] + caplog.set_level(logging.INFO, logger="messagefoundry.auth.service") + caplog.clear() + + plan = await service.reconcile_directory_sessions() + + assert plan.aborted is None + assert len(plan.renames) == 2 + [skipped] = faulting + [applied] = set(ids) - {skipped} + still = await store.get_user(ids[skipped]) + assert still is not None and still.username == skipped.removesuffix("-wed") + moved = await store.get_user(ids[applied]) + assert moved is not None and moved.username == applied, "the pass stopped at the fault" + [refreshed] = await _rename_audits(store) + assert refreshed["action"] == "auth.ad_username_refreshed" + assert json.loads(refreshed["detail"])["user_id"] == ids[applied] + [logged] = [r.getMessage() for r in caplog.records if "BACKLOG #3070" in r.getMessage()] + assert ids[skipped] in logged and "OperationalError" in logged + assert "other-holder" in logged, "the skip line dropped the holder the first read saw" + assert [e.username for e in notifier.sent if e.event_type == USERNAME_CHANGED] == [applied] + finally: + await store.close() + + +async def test_a_store_fault_on_the_holder_re_read_still_raises_off_the_reconciler_path() -> None: + """BACKLOG #3070, the control for the skip above. Only the reconciler (``audit_soft``) skips a + rename on a faulting holder re-read; any other caller, such as a sign-in, gets the error.""" + store, _ldap, service, _notifier, user_id = await _renamed_service() + try: + + async def _faults(username: str) -> _UserLookup: + raise sqlite3.OperationalError("database is locked") + + row = await store.get_user(user_id) + assert row is not None + service._lookup_by_username = _faults # type: ignore[method-assign] + with pytest.raises(sqlite3.OperationalError): + await service._refresh_cached_username( + user_id=user_id, + old_username="jdoe", + new_username="jdoe-married", + held=replace(row, id="gone-holder", username="jdoe-married"), + from_plan=False, + ) + after = await store.get_user(user_id) + assert after is not None and after.username == "jdoe" + finally: + await store.close() + + async def test_a_row_gone_refusal_does_not_warn_of_a_lockout( caplog: pytest.LogCaptureFixture, ) -> None: