From afd6adb12098300418018a24f45a351a372a14ac Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marcos=20M=C3=A9ndez?= Date: Sat, 10 Oct 2026 17:54:49 +0000 Subject: [PATCH] fix: the old primary turns its database read only before it releases the VIP (keel#138) On a real pair, a write in flight at a planned promote waited 15 s for its answer, and the new primary took 10 s to take writes. The 10 s on the new primary: its follow waited for the VIP on wg0, which the promote added only after its announcement to web-2, a member outside the pair that was down, timed out. keel#137 takes that out of the handover. The write: it committed on the old primary and waited for the replica's acknowledgement (semi-synchronous), while the old primary dropped the VIP for the release, so its answer had no address to come from. vipserve.released now calls quiesced() before vipnode.release: on a node that declares a database, SET GLOBAL read_only = ON (dbreadonly.quiesce, at most 15 s) returns once the commits in flight ended, which the replica, still connected, acknowledges; then the address goes. No new write is taken. A failure is logged and the release goes on; the database follows the VIP's state after, as before. With etcd, the first measurement showed a 5.6 s planned write gap at 250 ms: the promote waited for the controller's next lease renewal before the VIP was on wg0. The majority granted the lease and wrote the claim with it after the moment the lease was asked for, as a renewal confirms it; so promoted_etcd now adds the address itself (carry_held with that age), for what is left of the release time, and the controller extends it once it renewed. carried_soon now waits for that renewal (the lease's time to live goes up), so a missing keel-vip.service is still reported. The peers are told as soon as the address is here, not after that check, so they route the VIP to it at once. A primary that released the VIP dropped the address and revoked its own lease before it answered, and the claim's compare-and-swap is on the counter alone: the promote now claims at once on the counter read before the release, and waits for the old lease only with --old-primary-gone when the old primary did not answer (measured: 4.6 s gap with the wait, at 250 ms). Tests: the read only comes before the address is dropped; the promote carries the address at once, a lease too old is left to the controller; a released primary's lease is not waited for; quiesced asks the database only where one is declared, and logs a failure; quiesce's statement, timeout and failures. In mariadb / trixie, two planned promotes (A to B and back) while C writes at the VIP: the longest gap between two acknowledged writes under 3 s, no write waiting 10 s, no acknowledged row lost. --- debian/changelog | 25 ++++++++++ docs/replication.md | 5 +- docs/vip.md | 8 ++- keel/__init__.py | 2 +- keel/mesh/vippromote.py | 66 +++++++++++++++++++++---- keel/mesh/vipserve.py | 32 ++++++++++-- keel/system/dbreadonly.py | 28 +++++++++++ pyproject.toml | 2 +- tests/mariadb_netns.py | 88 ++++++++++++++++++++++++++++++--- tests/test_mariadb_netns.py | 18 +++++++ tests/test_mesh_vipclaim.py | 54 ++++++++++++++++++++ tests/test_mesh_vipetcd.py | 6 ++- tests/test_mesh_vipmove.py | 57 +++++++++++++++++++++ tests/test_system_dbreadonly.py | 27 ++++++++++ 14 files changed, 393 insertions(+), 25 deletions(-) diff --git a/debian/changelog b/debian/changelog index faf736c..74ae3e1 100644 --- a/debian/changelog +++ b/debian/changelog @@ -1,3 +1,28 @@ +keel (0.23.16) unstable; urgency=medium + + * A write in flight at a planned promote waited 15 s for its answer, + and the new primary took 10 s to take writes (keel#138). The 10 s + were the announcement to a member outside the pair that was down, + which keel#137 takes out of the handover. The write: the old primary + dropped the VIP while the commit waited for the replica's + acknowledgement, so the answer had no address to come from. Now the + old primary, when it declares a database, turns it read only before + it releases the VIP: SET GLOBAL read_only = ON returns once the + commits in flight ended, which the replica, still connected, + acknowledges; then the address goes. A failure is logged and the + release goes on. + * With etcd, a planned promote waited for the controller's next lease + renewal before the VIP was on wg0 (a 5.6 s write gap at 250 ms). + The majority granted the lease and wrote the claim with it, as a + renewal confirms it, so the promote now adds the address itself, + for what is left of the release time after the lease was asked for; + the controller extends it once it renewed, and the promote checks + that renewal before it returns. A primary that released the VIP + dropped the address and revoked its own lease first, so the promote + claims at once instead of waiting for that lease to go. + + -- Marcos Méndez Sat, 10 Oct 2026 14:00:00 +0000 + keel (0.23.15) unstable; urgency=medium * In cloud simple, one member outside the pair that is down made every diff --git a/docs/replication.md b/docs/replication.md index fe8664e..d319bda 100644 --- a/docs/replication.md +++ b/docs/replication.md @@ -227,7 +227,10 @@ declared. **`keel database promote [--old-primary-gone]`** on the replica, as today, in this order: `keel vip promote` (release before take; refused without the flag when the old primary does not answer: 0049, second -round, point 3), then the database: drain the relay log, `STOP SLAVE`, +round, point 3; the old primary turns its database read only before it +drops the address, so the commits in flight end, and their clients get +the answer, while the replica is still connected: keel#138), then the +database: drain the relay log, `STOP SLAVE`, `RESET SLAVE ALL`, `read_only = OFF`, `READ_ONLY ADMIN` back. The semi-synchronous roles need no flip (both sides enabled on both nodes). When the old primary is gone, `STOP SLAVE IO_THREAD` takes seconds diff --git a/docs/vip.md b/docs/vip.md index 925ce4e..a67d6b7 100644 --- a/docs/vip.md +++ b/docs/vip.md @@ -206,8 +206,12 @@ record: carries the VIP only when a majority of the peers that answered took it**; with no peer answering (a mesh of the two nodes alone, the other one gone), the operator's flag is the acceptance. With - etcd, the claim is the counter's compare-and-swap, and the controller - adds the address once it renewed the claim's lease. A transaction + etcd, the claim is the counter's compare-and-swap. The promote adds + the address at once, for what is left of the release time after it + asked for the lease (the majority granted it and wrote the claim with + it, as a renewal confirms it), and the controller extends it once it + renewed the claim's lease; the promote checks that renewal before it + returns (keel#138). A transaction that etcd does not answer in time may have committed (keel#135): the counter is read first; this node's own claim at the epoch is the claim made, and is recorded with its lease; another claim ends the diff --git a/keel/__init__.py b/keel/__init__.py index 73036bd..94d620e 100644 --- a/keel/__init__.py +++ b/keel/__init__.py @@ -12,7 +12,7 @@ # an image's tree read offline): debian/changelog's and pyproject.toml's, # which tests/test_version.py keeps in step. Installed, the metadata # dpkg put beside the package answers (keel#98). -FALLBACK_VERSION = "0.23.15" +FALLBACK_VERSION = "0.23.16" def version() -> str: diff --git a/keel/mesh/vippromote.py b/keel/mesh/vippromote.py index 65cb47e..b36cc22 100644 --- a/keel/mesh/vippromote.py +++ b/keel/mesh/vippromote.py @@ -501,8 +501,20 @@ def promoted_etcd(here: Here, vip: str, gone: bool, return exits.OK if holder is not None and not same_key(holder.holder, own): epoch = max(now.epoch.epoch if now.epoch else 0, holder.epoch) + 1 - if not released(here, vip, holder, epoch, gone, out): + why = asked_release(here, vip, holder, epoch, out) + if why and not gone: + out(f"the primary at {holder.address} did not release it: {why}." + " Nothing was changed. Only you know whether that node is" + " gone: if it is, run keel vip promote --old-primary-gone") return exits.MESH_REFUSED + if why is None: + # it dropped the address first and revoked its own lease; the + # compare-and-swap is on the counter alone: claimed at once + # (keel#138), on the counter read before the release + return claimed_etcd(here, vip, now, own, out) + out(f"the primary at {holder.address} did not answer ({why});" + " --old-primary-gone: it will drop the VIP when it learns the" + " newer claim") out("waiting for the primary's lease to go" f" (at most {GONE_WAIT:g} s)…") now = gone_lease(here, vip, holder.lease, GONE_WAIT) @@ -512,6 +524,13 @@ def promoted_etcd(here: Here, vip: str, gone: bool, return exits.MESH_REFUSED if now.epoch is not None and same_key(now.epoch.holder, own): return raced(here, vip, own, out) + return claimed_etcd(here, vip, now, own, out) + + +def claimed_etcd(here: Here, vip: str, now: vipetcd.Seen, own: str, + out: Callable[[str], None]) -> int: + """The claim by compare-and-swap on the counter read in `now`, the + address carried, the peers told""" try: made = vipetcd.claim( here.local(), here.mesh_id(), vip, now, @@ -526,14 +545,25 @@ def promoted_etcd(here: Here, vip: str, gone: bool, vipnode.hold(here, made[0], False, made[1]) out(f"this node holds {vip} at epoch {made[0].epoch}, by etcd's lease" f" {made[1]}") + # the majority granted the lease and wrote the claim with it after + # `asked`, as a renewal would confirm it: the address is carried now, + # for what is left of the release time after that moment, and the + # controller extends it once it renewed (keel#138: the wait for its + # next renewal was most of a planned promote's write gap) + carried = vipnode.carry_held(here, vip, here.monotonic() - made[2]) + # etcd holds the claim; the peers are told in the background (keel#137), + # as soon as the address is here, so they route the VIP to it at once + out("the peers are told in the background") + if carried: + in_background(here, made[0], set()) if not carried_soon(here, vip): - out(f"keel-vip.service did not add {vip} to {here.iface()} within" - f" {CARRY_WAIT:g} s: is it running? Its lease expires" - f" {vipetcd.TTL} s after its last renewal") + out(f"keel-vip.service did not carry {vip} on {here.iface()} and" + f" renew its lease within {CARRY_WAIT:g} s: is it running? The" + f" address goes {vipetcd.RELEASE_AFTER:g} s after the claim, and" + f" the lease {vipetcd.TTL} s after its last renewal") return exits.APPLY_FAILED - # etcd holds the claim; the peers are told in the background (keel#137) - out("the peers are told in the background") - in_background(here, made[0], set()) + if not carried: + in_background(here, made[0], set()) return exits.OK @@ -579,12 +609,30 @@ def raced(here: Here, vip: str, own: str, def carried_soon(here: Here, vip: str) -> bool: + """Whether keel-vip.service carries the VIP within CARRY_WAIT: the + address on wg0 and, for a claim on an etcd lease, a renewal of that + lease by the controller (its time to live goes up), since the promote + adds the address itself for the release time alone (keel#138)""" deadline = here.monotonic() + CARRY_WAIT - while not vipnet.carried(here.iface(), vip, here.node.output): + lease = vipnode.current(here, vip).lease + first = None + while True: + if vipnet.carried(here.iface(), vip, here.node.output): + if lease is None: + return True + try: + left = here.local().time_to_live(lease) + except EtcdError: + left = None + now = here.monotonic() + if left is not None: + if first is None: + first = (now, left) + elif left > first[1] - (now - first[0]) + 1: + return True if here.monotonic() >= deadline: return False here.sleep(POLL) - return True def check(here: Here, out: Callable[[str], None]) -> int: diff --git a/keel/mesh/vipserve.py b/keel/mesh/vipserve.py index 7d0b4e5..ab90064 100644 --- a/keel/mesh/vipserve.py +++ b/keel/mesh/vipserve.py @@ -15,15 +15,19 @@ and the epoch this node knows; - `release` is taken only by a node whose own spec declares that VIP, from the other member its pair record names, fresh, for an epoch - newer than any this node knows: it drops the address, then answers; + newer than any this node knows: it turns its database read only + when it declares one (the commits in flight end first, keel#138), + drops the address, then answers; - `pair` is the other member's pair record (keel.mesh.vippair), signed here too when this node's spec declares that VIP, and kept; - `secret` is answered with a secret the pair shares, only to the other member of the pair record, fresh (keel.system.dbsecret); 404 while this node holds none, and the asker tries again later. -Nothing here applies a change under 0018's window, and nothing waits: -each answer is the time of an `ip` or a `wg set`. +Nothing here applies a change under 0018's window, and nothing waits +but a release on a database: each answer is the time of an `ip` or a +`wg set`, and a release also waits for SET GLOBAL read_only = ON (up to +dbreadonly.QUIESCE_TIMEOUT). """ import json @@ -198,5 +202,27 @@ def released(here: Here, message: vipmsg.Message) -> Answer: def revoke(lease: str) -> None: here.local().revoke(lease) + quiesced(here, vip) vipnode.release(here, vip, revoke) return Answer(200, b'{"released": true}') + + +def quiesced(here: Here, vip: str) -> None: + """The database of a node that declares one made read only before + the VIP goes (keel#138): the commits in flight end first, their + clients get the answer while the address is still here, and no new + write is taken. A failure is logged and the release goes on: the + database follows the VIP's state after, as before""" + try: + doc = here.node.document() + except NodeError: + return + if not (doc.get("database") or {}).get("server"): + return + from keel.system import dbreadonly + problem = dbreadonly.quiesce() + if problem: + here.err(f"vip {vip}: the database could not be made read only" + f" first ({problem}); the release goes on") + return + here.err(f"vip {vip}: the database is read only before the release") diff --git a/keel/system/dbreadonly.py b/keel/system/dbreadonly.py index 53ea51f..4df0b8d 100644 --- a/keel/system/dbreadonly.py +++ b/keel/system/dbreadonly.py @@ -54,6 +54,9 @@ STATUS_QUESTION = mariadb.CLIENT + ("--execute", "SHOW REPLICA STATUS\\G") NO_BINLOG = "SET SESSION sql_log_bin = 0;\n" POLL_SECONDS = 1.0 +# how long the old primary waits for read_only before it releases the +# VIP: the semi-synchronous timeout (10 s) and room +QUIESCE_TIMEOUT = 15 # the lock follow and spec apply take around the replication's statements REPLICATION_LOCK = "var/lib/keel/database/follow.lock" IO_STOP = "STOP SLAVE IO_THREAD" @@ -231,6 +234,31 @@ def promote( return None +def quiesce(runner=subprocess.run) -> str | None: + """read_only on, before the old primary lets the VIP go (keel#138); + None, or why not + + SET GLOBAL read_only = ON returns once the commits in flight ended, + and a commit with semi-synchronous replication ends when the + replica, still connected then, acknowledged it. So a client whose + write was in flight gets its answer before the address goes, and no + new write is taken. Bounded by QUIESCE_TIMEOUT: a replica that does + not acknowledge costs rpl_semi_sync_master_timeout (10 s) at most.""" + statements = mariadb.set_read_only(True) + try: + done = runner(list(mariadb.CLIENT), input=statements.text, + capture_output=True, text=True, check=False, + timeout=QUIESCE_TIMEOUT) + except subprocess.TimeoutExpired: + return f"the server did not turn read only within" \ + f" {QUIESCE_TIMEOUT} s" + except OSError as e: + return f"cannot run {mariadb.CLIENT[0]}: {e.strerror}" + if done.returncode != 0: + return (done.stderr or "").strip() or f"exited {done.returncode}" + return None + + @contextlib.contextmanager def replication_locked(root: str) -> Iterator[None]: """One writer of the replication's statements at a time: keel diff --git a/pyproject.toml b/pyproject.toml index 52c0f48..70e3f49 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -4,7 +4,7 @@ build-backend = "setuptools.build_meta" [project] name = "keel" -version = "0.23.15" +version = "0.23.16" authors = [{name = "KeelLinux maintainers"}] description = "Declarative management of one appliance instance" readme = "README.md" diff --git a/tests/mariadb_netns.py b/tests/mariadb_netns.py index b06989b..230b056 100644 --- a/tests/mariadb_netns.py +++ b/tests/mariadb_netns.py @@ -680,6 +680,8 @@ def play(report: dict, pids: list[int], pairs, roots: list[str], report["b_bypass"] = agent_send( "B", "sql SELECT GRANTEE FROM information_schema.USER_PRIVILEGES" " WHERE PRIVILEGE_TYPE = 'READ_ONLY ADMIN'") + planned(report, pids, pairs, roots, "B", "k138_to_b") + planned(report, pids, pairs, roots, "A", "k138_to_a") crashed(report, pids, roots) report["alerts"] = [one.get("text", "")[:160] for one in HOOKS["alerts"]] for process in vip_netns.AGENTS.values(): @@ -708,8 +710,9 @@ class Writer: """C writes one row at the VIP every 0.1 s, a new connection each time with a 2 s connect timeout, as the real-node test's writer""" - def __init__(self, pid: int): + def __init__(self, pid: int, name: str = "crash"): self.pid = pid + self.name = name self.done: list[dict] = [] self.halt = threading.Event() self.thread = threading.Thread(target=self.run, daemon=True) @@ -733,7 +736,7 @@ def run(self) -> None: "--batch", "--connect-timeout=2", "-h", vip_netns.VIP, "-u", APP_USER, f"--password={APP_PASSWORD}", "--skip-ssl-verify-server-cert", APP_DB, "--execute", - f"INSERT INTO t (v, at) VALUES ('crash-{n}'," + f"INSERT INTO t (v, at) VALUES ('{self.name}-{n}'," f" {started:.3f})"], capture_output=True, text=True, check=False, timeout=30) ok, err = one.returncode == 0, one.stderr.strip()[:12] @@ -806,15 +809,86 @@ def since(at): "acked": len(ok)} -def acked_missing(writer: Writer, agent_send) -> list[str]: - """The rows C had acknowledged that the new primary B lacks""" - acked = {f"crash-{one['n']}" for one in writer.done if one["ok"]} - found = agent_send("B", f"sql SELECT v FROM {APP_DB}.t WHERE v LIKE" - " 'crash-%'") +def acked_missing(writer: Writer, agent_send, + node: str = "B") -> list[str]: + """The rows C had acknowledged that the new primary lacks""" + acked = {f"{writer.name}-{one['n']}" for one in writer.done + if one["ok"]} + found = agent_send(node, f"sql SELECT v FROM {APP_DB}.t WHERE v LIKE" + f" '{writer.name}-%'") held = set((found.get("out") or "").split()) return sorted(acked - held)[:20] +def planned(report: dict, pids: list[int], pairs, roots: list[str], + to: str, key: str) -> None: + """keel#138: a planned promote while C writes at the VIP: the + longest gap between two acknowledged writes, the writes that waited, + and the acknowledged rows the new primary lacks""" + import vip_netns + from vip_netns import NAMES, agent_send, wait_until + writer = Writer(pids[2], key) + writer.start() + report[f"{key}_first_ack_s"] = wait_until( + lambda: any(one["ok"] for one in writer.done), 60, 0.2) + time.sleep(3) + old = "A" if to == "B" else "B" + marks: dict[str, float] = {} + halt = threading.Event() + + def watch() -> None: + """When each step of the handover is seen, every 0.05 s""" + checks = { + "old_read_only": lambda: read_only_of( + roots[NAMES.index(old)]) == "1", + "old_dropped": lambda: not vip_netns.holds( + pids[NAMES.index(old)]), + "new_carries": lambda: vip_netns.holds(pids[NAMES.index(to)]), + "c_routes_new": lambda: vip_netns.routed_to(pids[2]) == + pairs[NAMES.index(to)][1], + "new_writable": lambda: read_only_of( + roots[NAMES.index(to)]) == "0"} + while not halt.is_set(): + for name, check in checks.items(): + if name not in marks and check(): + marks[name] = time.time() + halt.wait(0.05) + watcher = threading.Thread(target=watch, daemon=True) + promote_at = time.time() + watcher.start() + report[key] = agent_send(to, "dbpromote", 300) + promoted_at = time.time() + root = roots[NAMES.index(to)] + report[f"{key}_writable_s"] = wait_until( + lambda: read_only_of(root) == "0", 60, 0.2) + time.sleep(5) + halt.set() + watcher.join() + writer.stop() + report[f"{key}_marks"] = {name: round(at - promote_at, 2) + for name, at in sorted(marks.items(), + key=lambda one: one[1])} + before = [one["end"] for one in writer.done + if one["ok"] and one["end"] < promote_at + 1] + after = [one["end"] for one in writer.done + if one["ok"] and one["t"] > promote_at] + report[f"{key}_marks"]["last_ok"] = round(max(before) - promote_at, 2) \ + if before else None + report[f"{key}_marks"]["first_ok_after"] = round( + min(after) - promote_at, 2) if after else None + ok = sorted(one["end"] for one in writer.done if one["ok"]) + window = [t for t in ok if t >= promote_at - 2] + gaps = [b - a for a, b in zip(window, window[1:])] + report[f"{key}_gap"] = { + "promote_took_s": round(promoted_at - promote_at, 2), + "longest_gap_s": round(max(gaps), 2) if gaps else None, + "longest_write_s": round(max(one["end"] - one["t"] for one in + writer.done), 2), + "failed": sum(1 for one in writer.done if not one["ok"]), + "acked": len(ok)} + report[f"{key}_missing"] = acked_missing(writer, agent_send, to) + + def promote_gone(agent_send) -> dict: """keel database promote --old-primary-gone on B, as an operator runs it: run again when etcd had no leader to answer (A, cut off, may diff --git a/tests/test_mariadb_netns.py b/tests/test_mariadb_netns.py index 49e0d44..8063a39 100644 --- a/tests/test_mariadb_netns.py +++ b/tests/test_mariadb_netns.py @@ -223,6 +223,24 @@ def test_the_unplanned_write_downtime_and_no_acked_row_lost(self): self.assertLess(found["first_ok_after_s"] - found["carried_s"], 3.0, found) + def test_a_planned_promote_s_write_gap_is_under_3_s(self): + """keel#138: a write in flight at the release got its answer + late (the old primary dropped the VIP while the commit waited + for the replica), and the new primary took 10 s to take writes. + Both ways, A to B and back: the longest gap between two + acknowledged writes under 3 s, no write waiting 10 s, no + acknowledged row lost""" + for key in ("k138_to_b", "k138_to_a"): + with self.subTest(promote=key): + found = self.found[f"{key}_gap"] + print(f"{key}: {found} {self.found.get(key + '_marks')}", + file=sys.stderr) + self.assertEqual(self.found[key]["code"], 0, self.found[key]) + self.assertIsNotNone(self.found[f"{key}_writable_s"], found) + self.assertLess(found["longest_gap_s"], 3.0, found) + self.assertLess(found["longest_write_s"], 10.0, found) + self.assertEqual(self.found[f"{key}_missing"], [], found) + def test_no_two_nodes_ever_carry_the_vip(self): self.assertEqual(self.found["max_holders"], 1, self.found["double_holder_samples"]) diff --git a/tests/test_mesh_vipclaim.py b/tests/test_mesh_vipclaim.py index 9bbbe45..0eb4425 100644 --- a/tests/test_mesh_vipclaim.py +++ b/tests/test_mesh_vipclaim.py @@ -262,3 +262,57 @@ def test_a_claim_older_than_the_file_is_not_taken(self): code, said = self.raced() self.assertEqual(code, exits.APPLY_FAILED) self.assertIn("epoch 4 is known", said) + + +class TestThePromoteCarriesItAtOnce(ClaimCase): + """keel#138: after the compare-and-swap the promote waited for the + controller's next renewal before the VIP was on wg0 (5.6 s write gap + at 250 ms). The lease was granted and the claim written with it by + the majority, after the moment `asked`: the promote carries the + address itself, for what is left of the release time after that + moment, and the controller extends it once it renewed""" + + def test_the_address_is_on_wg0_when_the_promote_returns(self): + with mock.patch.object(vippromote, "carried_soon", + side_effect=lambda here, vip: self.carried( + self.all.index(here))): + said: list[str] = [] + code = vippromote.promote(self.all[0], False, said.append) + self.assertEqual(code, exits.OK, said) + self.assertTrue(self.carried(0)) + lifetime = self.nets[0].lifetimes[f"{VIP}/128"] + self.assertIsNotNone(lifetime) + self.assertLessEqual(lifetime, vipetcd.RELEASE_AFTER) + + def test_too_old_a_lease_is_left_to_the_controller(self): + real = vipetcd.claim + + def slow(*args, **kwargs): + made = real(*args, **kwargs) + self.sleep(vipetcd.RELEASE_AFTER) + return made + with mock.patch.object(vipetcd, "claim", side_effect=slow), \ + mock.patch.object(vippromote, "carried_soon", + side_effect=self.carry_soon): + said: list[str] = [] + code = vippromote.promote(self.all[0], False, said.append) + self.assertEqual(code, exits.OK, said) + self.assertTrue(self.carried(0)) + + +class TestAPlannedPromoteDoesNotWaitForTheLease(ClaimCase): + def test_a_released_primary_s_lease_is_not_waited_for(self): + """keel#138: the primary that released dropped the address first + and revoked its own lease; the claim's compare-and-swap is on the + counter alone, so the promote claims at once (a second of etcd + calls at 250 ms)""" + self.promote(0) + self.turn() + self.kv.calls.clear() + code, said = self.promote(1) + self.assertEqual(code, exits.OK, said) + self.assertIn("released by", said) + self.assertNotIn("waiting for the primary's lease", said) + self.assertNotIn("time_to_live", self.kv.calls[:self.kv.calls.index( + "swap")]) + self.assertEqual(self.holds(), [1]) diff --git a/tests/test_mesh_vipetcd.py b/tests/test_mesh_vipetcd.py index a3a99a2..5f07e53 100644 --- a/tests/test_mesh_vipetcd.py +++ b/tests/test_mesh_vipetcd.py @@ -313,14 +313,18 @@ def test_another_node_s_claim_came_first_or_its_own(self): said.append), exits.APPLY_FAILED) def test_promote_finds_its_own_controller_claimed_while_it_waited(self): + """With the old primary gone (a released one is not waited for, + keel#138), the promote waits for its lease, and its own + controller may claim meanwhile""" self.promote(0) self.turn() + self.down.add(address(0)) with mock.patch.object(vippromote, "gone_lease", side_effect=lambda here, vip, lease, wait: self.own_claim(1)): with mock.patch.object(vippromote, "carried_soon", return_value=True): - code, said = self.promote(1) + code, said = self.promote(1, gone=True) self.assertEqual(code, exits.OK, said) self.assertIn("claimed by its controller", said) diff --git a/tests/test_mesh_vipmove.py b/tests/test_mesh_vipmove.py index 5e4105f..fec1e5b 100644 --- a/tests/test_mesh_vipmove.py +++ b/tests/test_mesh_vipmove.py @@ -575,3 +575,60 @@ def test_an_epoch_answer_for_another_vip_or_unverified(self): if __name__ == "__main__": unittest.main() + + +class TestTheReleaseQuiescesTheDatabase(Pair): + """keel#138: a write in flight at the release lost its answer: the + old primary dropped the VIP while the commit waited for the + replica's acknowledgement. The database turns read only first, + which waits for the commits in flight (the replica is still + connected), and only then is the address dropped""" + + def promote(self, index: int) -> tuple[int, str]: + said: list[str] = [] + code = vippromote.promote(self.all[index], False, said.append) + return code, "\n".join(said) + + def test_the_database_is_read_only_before_the_address_goes(self): + from unittest import mock + from keel.mesh import vipserve + self.nodes() + self.promote(0) + order: list[str] = [] + node = self.all[0].node + real = node.run + + def run(argv): + if argv[:4] == ("ip", "-6", "addr", "del"): + order.append("drop") + return real(argv) + node.run = run + with mock.patch.object(vipserve, "quiesced", + side_effect=lambda here, vip: + order.append("read only")): + code, said = self.promote(1) + self.assertEqual(code, exits.OK, said) + self.assertEqual(order[:2], ["read only", "drop"], order) + + def test_quiesced_asks_the_database_only_where_one_is_declared(self): + from unittest import mock + from keel.mesh import vipserve + self.nodes() + here = self.all[0] + with mock.patch("keel.system.dbreadonly.quiesce", + return_value=None) as asked: + vipserve.quiesced(here, VIP) + asked.assert_not_called() + doc = here.node.document() + doc["database"] = {"server": {"engine": "mariadb", + "role": "primary"}} + here.node.write(doc) + with mock.patch("keel.system.dbreadonly.quiesce", + return_value=None) as asked: + vipserve.quiesced(here, VIP) + asked.assert_called_once() + self.assertIn("read only before the release", self.text(0)) + with mock.patch("keel.system.dbreadonly.quiesce", + return_value="ERROR 2002"): + vipserve.quiesced(here, VIP) + self.assertIn("ERROR 2002); the release goes on", self.text(0)) diff --git a/tests/test_system_dbreadonly.py b/tests/test_system_dbreadonly.py index 9e3443f..4dafa34 100644 --- a/tests/test_system_dbreadonly.py +++ b/tests/test_system_dbreadonly.py @@ -603,3 +603,30 @@ def test_the_actions_say_what_they_do(self): self.assertIn(dbreadonly.RECORD, LockReplica(()).describe()) self.assertIn("READ_ONLY ADMIN back", UnlockAccounts().describe()) self.assertIn("wait up to 60 s", PromoteReplica(60).describe()) + + +class TestQuiesce(unittest.TestCase): + """keel#138: read_only on, waited for up to QUIESCE_TIMEOUT: it + waits for the commits in flight, which wait for the replica""" + + def test_read_only_on_by_the_server_s_own_account(self): + runner = Runner() + self.assertIsNone(dbreadonly.quiesce(runner)) + self.assertEqual(runner.calls[0][1], "SET GLOBAL read_only = ON;\n") + self.assertEqual(runner.argv[0][:4], ["runuser", "-u", "mysql", + "--"]) + + def test_a_server_that_does_not_answer_in_time_is_said(self): + def slow(argv, **kwargs): + self.assertEqual(kwargs["timeout"], dbreadonly.QUIESCE_TIMEOUT) + raise subprocess.TimeoutExpired(argv, kwargs["timeout"]) + self.assertIn("did not turn read only within", + dbreadonly.quiesce(slow)) + + def test_a_failure_is_said(self): + self.assertIn("ERROR 2002", dbreadonly.quiesce( + Runner({"other": (1, "", "ERROR 2002")}))) + + def missing(argv, **kwargs): + raise FileNotFoundError(2, "No such file or directory") + self.assertIn("cannot run runuser", dbreadonly.quiesce(missing))