fix: the old primary turns its database read only before it releases the VIP (keel#138)

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 <[email protected]>  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

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

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

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:

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:

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")

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

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"

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