From 63b9fd16a58f5cc3fa84b00893a929b9242e1cf1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marcos=20M=C3=A9ndez?= Date: Sat, 10 Oct 2026 17:37:02 +0000 Subject: [PATCH] docs: evidence of the keel 0.23.13 rollout on the real nodes Four of five nodes upgraded (web-2 on BR2 was down). Unplanned failover 31.4 s, 0 acknowledged rows lost; findings N6 to N10. --- docs/evidence/2026-10-10-rollout-0.23.13.md | 951 ++++++++++++++++++++ 1 file changed, 951 insertions(+) create mode 100644 docs/evidence/2026-10-10-rollout-0.23.13.md diff --git a/docs/evidence/2026-10-10-rollout-0.23.13.md b/docs/evidence/2026-10-10-rollout-0.23.13.md new file mode 100644 index 0000000..fc20694 --- /dev/null +++ b/docs/evidence/2026-10-10-rollout-0.23.13.md @@ -0,0 +1,951 @@ +# Evidence: rollout of keel 0.23.13 on the real mesh + +Date: 2026-10-10 17:09 to 17:34 UTC. Host: hw12-br1 (Proxmox). +Nodes: CT 124 web-1, CT 125 web-3, CT 9003 db-1, CT 9004 db-2 (all BR1); +web-2 (BR2, normally reached over the overlay through a Python TCP relay in +CT 124). Mesh 9fe71b35, overlay fd11:a58a:88ef::/64, VIP +fd11:a58a:88ef::ffff:1. The pair is cloud simple. Public uplink addresses are +written as ``. + +The appendix gives every command and its trimmed output in time order. + +## Important: web-2 was down for the whole run + +At 17:09 web-2 was unreachable. It was still unreachable at 17:33. + +``` +web-1 keel mesh status: o+GK... fd11:a58a:88ef::2/128 []:51820 handshake 28757 s ago +etcd: keel-fd11-a58a-88ef--2 fd11:a58a:88ef::2 voter context deadline exceeded +web-1: ping -6 fd11:a58a:88ef::2: 3 packets transmitted, 0 received, 100% packet loss +host: ping of both uplink addresses known for web-2: no ping +relay to web-2 port 22: Connection timed out during banner exchange (5 tries, 17:09 to 17:33) +``` + +The last handshake of web-2 with web-1, web-3 and db-2 was about 28,700 s +(8 h) before 17:09, so web-2 went away at about 09:10 UTC. We cannot reach +BR2, so we did not repair it. etcd ran on 2 of 3 voters (web-1, web-3) with +quorum the whole time. Because of this: web-2 was not upgraded, item 3 could +not be tested, and the web-2 part of item 2 could not be tested. + +## Summary + +| Item | Result | Numbers | +| --- | --- | --- | +| 1. Upgrade one at a time | PASS (4 of 5 nodes) | web-1, web-3, db-1, db-2 on keel 0.23.13. web-2 skipped (down). etcd: 0 failed samples of 1388 (web-1) and 1397 (web-3), 0 "lost leader". Writer at the VIP during both db upgrades: 1016 ok, 0 failed, longest gap 0.20 s, 0 lost. | +| 2. Full mesh, handshakes, MTU 1280 | PARTIAL | db-1, db-2 and web-3 are peers of each other with handshakes (10 to 120 s). The web-2 links are not testable. `keel diff` names only web-2 as handshake drift. MTU 1280 on web-1, web-3, db-1, db-2, but only after a one-time `wg-quick down/up` (web nodes) or a boot (db nodes); see bug N7. No sync caused a bounce. | +| 3. BR2 channel, 10 syncs | NOT TESTED | web-2 down. Every sync on the other nodes: `member fd11:a58a:88ef::2 did not answer: [fd11:a58a:88ef::2]:51821 through wg0: timed out`. | +| 4. Planned promote and back | PASS on data, FAIL on gap | 0 acknowledged rows lost in 5 promotes. Write gaps: 10.98 s, (not measured, the writer stopped), 1.27 s, 4.77 s, 15.26 s. Each `keel vip promote` took 20.7 to 20.9 s (two 10 s timeouts to web-2). See N8 and N9. | +| 5. Unplanned | PASS | Promote with `--old-primary-gone` took 30.8 s (17:28:11.9 to 17:28:42.8); db-1 writable at 17:28:43.3, 31.4 s after the promote started. The writer saw 37.75 s with no ack (from 17:28:05.6), because the promote started 3.9 s after the stop ended (planned: 2 s). The new holder refused writes (1290) for only about 1.7 s. 381 acked, 0 lost. Old primary: 240 boot samples, 0 with read_only=0, 0 with the VIP; rejoined by GTID at 17:29:49. | +| 6. 3306 and keys | PASS | 3306 on both db uplinks: `ConnectionRefusedError`. `mariadb.socket` masked on both. `git ls-files` in `/etc`: 0 key files on web-1, web-3, db-1, db-2. | + +## 1. Upgrade + +Before: keel 0.23.7 on all reachable nodes, keel-overlay-installer 0.2.0, +keel-overlay-etcd 0.4.0, keel-overlay-vip 0.2.0, keel-mariadb 0.1.1 on db, +wg0 MTU 1420 everywhere. An etcd health loop (`http://[::1]:2381/health`, +every second) ran on web-1 and web-3 from 17:10:17 to 17:34:04. + +| Node | Upgrade (UTC) | After | +| --- | --- | --- | +| web-1 | 17:10:20 to 17:10:28 | keel 0.23.13, `keel --version` 0.23.13; 20 s after: voters web-1 and web-3 healthy, web-2 "context deadline exceeded", leader web-3; 0 FAIL | +| web-3 | 17:11:07 to 17:11:15 | the same | +| web-2 | not done | unreachable | +| db-1 (replica) | 17:12:29.1 to 17:12:38.3 | keel 0.23.13, keel-mariadb 0.1.1, read_only 1 | +| db-2 (primary) | 17:12:50.5 to 17:12:59.8 | keel 0.23.13, read_only 0 | + +Writer on db-1 for 150 s across both db upgrades: `writes: 1016 ok, 0 failed; +longest gap 0.20 s`, `acked 1016, missing on db-1: 0`. + +etcd totals: web-1 1388 samples, web-3 1397 samples, 0 not healthy; +`journalctl -u etcd` since 17:09: 0 "lost leader" or "no leader" on both. +No voter loss in this run. web-2 was already lost as a voter before the run. + +## 2. Full mesh, handshakes, MTU + +Start state (17:09): db-1, db-2 and web-3 already had each other as peers. +They were added before this run, sometime after 0.23.7. Handshakes at 17:09: +db-1 to web-3 17 s, db-2 to web-3 117 s, web-3 to db-1 20 s, web-3 to db-2 +119 s. web-2 never handshook with db-1. + +`keel mesh sync` on db-1 (17:14:59) and db-2 (17:15:11): "no member this node +does not know", rc=0, 10 s each (the time-out to web-2). + +`keel diff` on db-1 after a sync: + +``` +peers.1bSg... (web-1).handshake: same (a handshake (12 s ago)) +peers.o9tG... (db-2).handshake: same (a handshake (24 s ago)) +peers.8Tjk... (web-3).handshake: same (a handshake (12 s ago)) +peers.o+GK... (web-2).handshake: drift (declared a handshake, observed none; no handshake since wg0 came up: it comes once that member has this node as a peer too (keel mesh sync on that member)) +``` + +On db-2, before its reboot: `peers.o+GK....handshake: same (a handshake (29057 s ago))`. +An 8 h old handshake counts as "same" (N6). + +MTU: + +- db-1 and db-2: after the upgrade, `/etc/wireguard/wg0.conf` had `MTU = 1280` + (written 17:13:26 on db-1), but the live wg0 stayed at `mtu 1420`. + `keel spec apply --system-only` on both (17:15:55, 17:16:03): rc=0, no + overlay change, still `mtu 1420`. `keel diff` gave no MTU line (N7). A + writer ran for 330 s: 2278 ok, 0 failed, gap 0.19 s. +- web-3: the dry run planned "bring the overlay wg0 up on a new + /etc/wireguard/wg0.conf". `keel spec apply --system-only` 17:22:09.4 to + 17:22:10.4: `done with wg-quick down, then up`; `mtu 1280`; + `keel network confirm` at 17:22:18: "confirmed from a process attached from + the container's host". etcd 0 FAIL. +- web-1: the same at 17:22:29.3 to 17:22:30.3, confirmed 17:22:31, `mtu + 1280`, etcd 0 FAIL, 3 voters listed, leader web-3. +- db-1: `pct reboot 9003` 17:23:11.3 to 17:23:18.8, `mtu 1280`, read_only 1, + replication IO Yes at 17:23:30. +- db-2: `mtu 1280` after its boot in item 5 (17:29). + +End: `mtu 1280` on web-1, web-3, db-1 and db-2. + +Bounces: the only `wg-quick down/up` were the two one-time MTU applies on web-1 +and web-3, which the changelog of 0.23.11 says will happen, and the +reboot/boot of db-1 and db-2. No `keel mesh sync` bounced wg0 in this run. + +## 3. BR2 channel + +Not tested: web-2 is down (see above). + +## 4. Planned promote (writer on db-1, one new connection per INSERT) + +| Promote | Command time | Write gap | Lost | +| --- | --- | --- | --- | +| db-2 to db-1 (epoch 7) | 17:24:13.8 to 17:24:34.9 (21.0 s); db-1 writable 17:24:35.5 | 10.98 s (17:24:24.5 to 17:24:35.5): 8x 2002 can't connect, 3x 1290 | 0 of 358 | +| db-1 to db-2 (epoch 8) | 17:25:02.8 to 17:25:23.5 (20.7 s); db-2 writable 17:25:24.1 | not measured (the writer ended at 17:25:23) | 0 | +| db-2 to db-1 (epoch 9) | 17:25:55.1 to 17:26:16.0 (20.9 s) | 1.27 s | 0 of 658 | +| db-1 to db-2 (epoch 10) | 17:26:47.6 to 17:27:08.3 (20.7 s) | 4.77 s | 0 (same run) | +| db-1 to db-2 (epoch 12, after item 5) | 17:31:48.6 to 17:32:09.5 (20.9 s) | 15.26 s | 0 of 217 | + +Every promote printed `fd11:a58a:88ef::2: [fd11:a58a:88ef::2]:51821 through +wg0: timed out` twice: once when it asked for the epoch, once when it sent the +claim. + +Timeline of the 15.26 s gap (epoch 12): + +``` +17:31:59 db-1: vip ...: released by this node; it is no longer the primary +17:31:59.289 writer seq 128 sent; it hung until the wrapper's 15 s timeout (rc 124) +17:31:59.34 row pl3-128 committed on db-1 (at = 17:31:59.343611); on both nodes after the promote +17:31:59 db-2: keel-database-follow.service starts +17:32:00 db-1: set read_only ON; rejoined: no errant GTID +17:32:09 db-2: drained and promoted: this node replicates from nobody and takes writes +17:32:14.404 writer seq 129 ok on keel-db-2 +``` + +## 5. Unplanned + +``` +pct stop 9004 at 17:28:04.050; stopped at 17:28:08.056 +keel vip promote --old-primary-gone (db-1) 17:28:11.926 to 17:28:42.766, rc=0, epoch 11, + "taken by 2 of 2 peer(s)"; db-2 and web-2: through wg0: timed out +db-1 writable at 17:28:43.337 +writer: 381 ok, 25 failed; longest gap 37.75 s (last ok 17:28:05.641, next ok 17:28:43.387) +errors: 1x 2013 (17:28:05.747), 2002 can't connect from 17:28:05.884, 1290 from 17:28:41.633 +acked 381, missing on db-1: 0 +pct start 9004 at 17:28:55.720; started at 17:29:02.116 +``` + +The writes came back 31.4 s after the promote started. The coordinator +expects about 32 s by design for cloud simple. The promote started 3.9 s +after `pct stop` ended, not 2 s, so the writer saw 37.75 s. + +db-2 boot probe (0.5 s, 240 samples): + +``` +17:29:04.382 read_only=down no-VIP +17:29:07.810 read_only=1 no-VIP (unchanged to the end) +samples 240, read_only=0: 0, VIP on wg0: 0 +17:29:25 read only: this node's claim of fd11:a58a:88ef::ffff:1, not proven (the VIP is not on wg0) ... +17:29:48 vip ...: epoch 11, held by li08... this node no longer holds it +17:29:49 a dump ... /var/backups/keel/mariadb/rejoin-20261010T172949Z.sql.zst +17:29:49 rejoined: no errant GTID, replicating from [fd11:a58a:88ef:0:382f:45b:553c:f11]:3306 over TLS from 0-650213503-7321 +``` + +Then the planned promote back to db-2 (epoch 12, item 4 table). + +## 6. 3306 and keys + +``` + 3306: ConnectionRefusedError [Errno 111] Connection refused + 3306: ConnectionRefusedError [Errno 111] Connection refused +web-1, web-3, db-1, db-2: tracked keys: 0 +db-1, db-2: mariadb.socket masked +``` + +## Final state + +- db-2 (CT 9004): primary, VIP epoch 12, 1 replica acknowledging, wg0 MTU 1280. +- db-1 (CT 9003): replica, read_only 1, IO/SQL Yes, lag 0, TLS Yes, MTU 1280. +- `keel diff` on both, rc=14, two drifts: `overlays.vip` (B5, still open) and + web-2 handshake (web-2 down). +- Test leftovers: writer and probe logs in `/root` of the db nodes; probe + units removed; etcd monitors stopped and their logs deleted. + +## Bugs + +| ID | Severity | Bug | Exact output | +| --- | --- | --- | --- | +| N8 | High | In cloud simple, one unreachable mesh member (web-2, not in the pair) adds two 10 s timeouts to every `keel vip promote` (epoch query, claim). A planned promote takes about 21 s, not about 1 s, and the write gap goes up to 11 s. | `fd11:a58a:88ef::2: [fd11:a58a:88ef::2]:51821 through wg0: timed out` (twice per promote); 17:24:13.8 to 17:24:34.9; gap 10.98 s | +| N9 | Medium | A write in flight at the release waits for the semi-sync timeout on the old primary. It commits there, so it is not lost, but the client waits 15 s with no answer. The new primary's follow then takes 10 s, not about 1 s, which looks like the old order of keel#118. | seq 128 sent 17:31:59.289, rc 124 at 17:32:14.299; row `pl3-128` at 17:31:59.343611 on both nodes; db-2 follow 17:31:59 to `17:32:09 drained and promoted` | +| N7 | Medium | After the upgrade, `MTU = 1280` is in `wg0.conf` but the live wg0 stays at 1420. `keel spec apply` plans no overlay change, and `keel diff` does not report the MTU. Only a boot fixed it on the db nodes. On the web nodes the file had no MTU line, so apply did the bounce. | db-1: `MTU = 1280` in file (17:13:26), `ip link: mtu 1420`; apply `4 change(s), 0 failed`, no network.overlay line; diff: no MTU line | +| N6 | Low | `keel diff` reports a handshake 8 h old as "same". | `peers.o+GK....handshake: same (a handshake (29057 s ago))` | +| N10 | Low | The handshake drift message says to run sync on the other member, also when that member is down. | `it comes once that member has this node as a peer too (keel mesh sync on that member)` | +| B5 | Medium (open) | `overlays.vip` drift in cloud simple. | `overlays.vip: drift (declared enabled, observed keel-vip.service enabled and inactive)` | +| B9 | Low (open) | "the primary's address" names the other member. | db-2 as primary: `the primary's address: fd11:a58a:88ef:0:382f:45b:553c:f11` | + +Fixed and confirmed in this run: keel#118 (new holder refuses writes for only +about 1.7 s, not 11.7 s, after an unplanned promote), keel#120 (apply says +"done with wg-quick down, then up" / "kept"), #104 still holds, B3 and the +key tracking still hold. + +Single site: all tested nodes are on BR1. + +## Appendix: commands and outputs + +```text +=== [124] 2026-10-10T17:08:19Z rc=0 +$ hostname; apt-get update -q 2>&1 | tail -1; dpkg-query -W keel keel-overlay-installer keel-mariadb keel-overlay-vip keel-overlay-etcd 2>/dev/null | tr "\n" " "; echo; apt-cache policy keel | grep Candidate; curl -s -m2 http://[::1]:2381/health 2>/dev/null; ip -o link show wg0 | grep -o "mtu [0-9]*"; wg show wg0 allowed-ips | cut -c1-12 | tr "\n" " "; echo +keel-web-1 +Reading package lists... +keel 0.23.7 keel-overlay-etcd 0.4.0 keel-overlay-installer 0.2.0 keel-overlay-vip 0.2.0 + Candidate: 0.23.13 +{"health":"true","reason":""}mtu 1420 +o+GK/71E+YK/ 8Tjk29fOsZmT li08e1grPY0X o9tGVm/IKImy + +=== [125] 2026-10-10T17:08:21Z rc=0 +$ hostname; apt-get update -q 2>&1 | tail -1; dpkg-query -W keel keel-overlay-installer keel-mariadb keel-overlay-vip keel-overlay-etcd 2>/dev/null | tr "\n" " "; echo; apt-cache policy keel | grep Candidate; curl -s -m2 http://[::1]:2381/health 2>/dev/null; ip -o link show wg0 | grep -o "mtu [0-9]*"; wg show wg0 allowed-ips | cut -c1-12 | tr "\n" " "; echo +keel-web-3 +Reading package lists... +keel 0.23.7 keel-overlay-etcd 0.4.0 keel-overlay-installer 0.2.0 keel-overlay-vip 0.2.0 + Candidate: 0.23.13 +{"health":"true","reason":""}mtu 1420 +1bSgAuDppyY3 o+GK/71E+YK/ li08e1grPY0X o9tGVm/IKImy + +=== [web2] 2026-10-10T17:08:41Z rc=255 +$ hostname; apt-get update -q 2>&1 | tail -1; dpkg-query -W keel keel-overlay-installer keel-mariadb keel-overlay-vip keel-overlay-etcd 2>/dev/null | tr "\n" " "; echo; apt-cache policy keel | grep Candidate; curl -s -m2 http://[::1]:2381/health 2>/dev/null; ip -o link show wg0 | grep -o "mtu [0-9]*"; wg show wg0 allowed-ips | cut -c1-12 | tr "\n" " "; echo +Connection timed out during banner exchange +Connection to UNKNOWN port 65535 timed out + +=== [9003] 2026-10-10T17:08:44Z rc=0 +$ hostname; apt-get update -q 2>&1 | tail -1; dpkg-query -W keel keel-overlay-installer keel-mariadb keel-overlay-vip keel-overlay-etcd 2>/dev/null | tr "\n" " "; echo; apt-cache policy keel | grep Candidate; curl -s -m2 http://[::1]:2381/health 2>/dev/null; ip -o link show wg0 | grep -o "mtu [0-9]*"; wg show wg0 allowed-ips | cut -c1-12 | tr "\n" " "; echo +keel-db-1 +Reading package lists... +keel 0.23.7 keel-mariadb 0.1.1 keel-overlay-etcd 0.4.0 keel-overlay-installer 0.2.0 keel-overlay-vip 0.2.0 + Candidate: 0.23.13 +mtu 1420 +1bSgAuDppyY3 o9tGVm/IKImy o+GK/71E+YK/ 8Tjk29fOsZmT + +=== [9004] 2026-10-10T17:08:47Z rc=0 +$ hostname; apt-get update -q 2>&1 | tail -1; dpkg-query -W keel keel-overlay-installer keel-mariadb keel-overlay-vip keel-overlay-etcd 2>/dev/null | tr "\n" " "; echo; apt-cache policy keel | grep Candidate; curl -s -m2 http://[::1]:2381/health 2>/dev/null; ip -o link show wg0 | grep -o "mtu [0-9]*"; wg show wg0 allowed-ips | cut -c1-12 | tr "\n" " "; echo +keel-db-2 +Reading package lists... +keel 0.23.7 keel-mariadb 0.1.1 keel-overlay-etcd 0.4.0 keel-overlay-installer 0.2.0 keel-overlay-vip 0.2.0 + Candidate: 0.23.13 +mtu 1420 +1bSgAuDppyY3 li08e1grPY0X o+GK/71E+YK/ 8Tjk29fOsZmT + +=== [web2] 2026-10-10T17:09:16Z rc=255 +$ hostname; dpkg-query -W keel | tr "\n" " "; ip -o link show wg0 | grep -o "mtu [0-9]*"; wg show wg0 allowed-ips | cut -c1-12 | tr "\n" " "; echo; curl -s -m2 http://[::1]:2381/health +Connection timed out during banner exchange +Connection to UNKNOWN port 65535 timed out + +=== [9003] 2026-10-10T17:09:18Z rc=0 +$ wg show wg0 latest-handshakes | while read k t; do echo "${k:0:12} $([ $t = 0 ] && echo never || echo $(( $(date +%s) - t ))s)"; done +1bSgAuDppyY3 17s +o9tGVm/IKImy 82s +o+GK/71E+YK/ never +8Tjk29fOsZmT 17s + +=== [9004] 2026-10-10T17:09:19Z rc=0 +$ wg show wg0 latest-handshakes | while read k t; do echo "${k:0:12} $([ $t = 0 ] && echo never || echo $(( $(date +%s) - t ))s)"; done +1bSgAuDppyY3 52s +li08e1grPY0X 83s +o+GK/71E+YK/ 28682s +8Tjk29fOsZmT 117s + +=== [125] 2026-10-10T17:09:21Z rc=0 +$ wg show wg0 latest-handshakes | while read k t; do echo "${k:0:12} $([ $t = 0 ] && echo never || echo $(( $(date +%s) - t ))s)"; done +1bSgAuDppyY3 43s +o+GK/71E+YK/ 28634s +li08e1grPY0X 20s +o9tGVm/IKImy 119s + +=== [124] 2026-10-10T17:09:45Z rc=0 +$ date -u; keel mesh status 2>&1 | grep -vE "^ (li08|o9tG)"; wg show wg0 latest-handshakes | while read k t; do echo "${k:0:12} $([ $t = 0 ] && echo never || echo $(( $(date +%s) - t ))s)"; done; wg show wg0 endpoints | grep o+GK | sed -E "s/2804:[0-9a-f:]+//"; ping -6 -c3 -W2 fd11:a58a:88ef::2 | tail -2 +Sat Oct 10 05:09:31 PM UTC 2026 +this node: fd11:a58a:88ef::1/64 on wg0, WireGuard on UDP 51820 +mesh identity: 9fe71b35b8d35c5869faacc57ed2bc30 +public key: 1bSgAuDppyY36XfEH2zxXeT5altQGehlT7Se2AVZyAg= +peers: 4 + o+GK/71E+YK/TO/pUkonxFP0DLcFdpPEm2ZlxJJ/VBc= fd11:a58a:88ef::2/128 :51820 handshake 28757 s ago + 8Tjk29fOsZmTJ61L3LfEI2mm/LHFzAy+roHC49woQnc= fd11:a58a:88ef:0:47d1:8a55:262c:33ed/128 :51820 handshake 53 s ago +pending invites: 0 +etcd: 3 voter(s), 0 learner(s) + keel-fd11-a58a-88ef-0-47d1-8a55-262c-33ed fd11:a58a:88ef:0:47d1:8a55:262c:33ed voter healthy + keel-fd11-a58a-88ef--2 fd11:a58a:88ef::2 voter context deadline exceeded + keel-fd11-a58a-88ef--1 fd11:a58a:88ef::1 voter healthy +leader: keel-fd11-a58a-88ef-0-47d1-8a55-262c-33ed +etcd: this member's certificate expires 2026-11-07 09:45 UTC +vip fd11:a58a:88ef::ffff:1: another pair's, routed + epoch 6, held by o9tGVm/IKImyW2kgn22YjiWdEXpAr28T6WF9uc4yW1Q= at fd11:a58a:88ef:0:cd53:dda9:f0cb:b889 + carried here: no + routed to: o9tGVm/IKImyW2kgn22YjiWdEXpAr28T6WF9uc4yW1Q= +o+GK/71E+YK/ 28767s +8Tjk29fOsZmT 63s +li08e1grPY0X 40s +o9tGVm/IKImy 74s +o+GK/71E+YK/TO/pUkonxFP0DLcFdpPEm2ZlxJJ/VBc= []:51820 +3 packets transmitted, 0 received, 100% packet loss, time 2089ms + +=== [host] 2026-10-10T17:10:00Z rc=0 +$ for a in ; do ping -6 -c2 -W2 $a >/dev/null 2>&1 && echo "$a answers ping" || echo "$a no ping"; done + no ping + no ping + +=== [125] 2026-10-10T17:10:02Z rc=0 +$ wg show wg0 endpoints | grep o+GK; grep -A1 "o+GK" /etc/keel/instance.yaml | tail -1 +o+GK/71E+YK/TO/pUkonxFP0DLcFdpPEm2ZlxJJ/VBc= :51820 + endpoint: ':51820' + +=== [124] 2026-10-10T17:10:17Z rc=0 +$ rm -f /root/etcdmon3.log; systemd-run --unit=keeltest-etcdmon3 --collect bash -c "for i in \$(seq 1 5400); do h=\$(curl -s -m 1 http://[::1]:2381/health | grep -o true || echo FAIL); echo \"\$(date -u +%T) \$h\" >> /root/etcdmon3.log; sleep 1; done" +Running as unit: keeltest-etcdmon3.service; invocation ID: b2a1895589904c289df1ec8323b6f9df + +=== [125] 2026-10-10T17:10:19Z rc=0 +$ rm -f /root/etcdmon3.log; systemd-run --unit=keeltest-etcdmon3 --collect bash -c "for i in \$(seq 1 5400); do h=\$(curl -s -m 1 http://[::1]:2381/health | grep -o true || echo FAIL); echo \"\$(date -u +%T) \$h\" >> /root/etcdmon3.log; sleep 1; done" +Running as unit: keeltest-etcdmon3.service; invocation ID: 01af17a61f9f4b549c1763f53a3caa4f + +=== [124] 2026-10-10T17:10:59Z rc=0 +$ date -u +%T; DEBIAN_FRONTEND=noninteractive apt-get install -y -q --only-upgrade keel 2>&1 | grep -E "Unpacking|Setting up|rror|arning"; date -u +%T; dpkg-query -W keel keel-overlay-installer keel-overlay-etcd keel-overlay-vip | tr "\n" " "; echo; keel --version; ip -o link show wg0 | grep -o "mtu [0-9]*"; sleep 20; keel mesh status 2>&1 | grep -E "voter|leader"; echo "FAIL so far: $(grep -c FAIL /root/etcdmon3.log)" +17:10:20 +Unpacking keel (0.23.13) over (0.23.7) ... +Setting up keel (0.23.13) ... +17:10:28 +keel 0.23.13 keel-overlay-etcd 0.4.0 keel-overlay-installer 0.2.0 keel-overlay-vip 0.2.0 +0.23.13 +mtu 1420 +etcd: 3 voter(s), 0 learner(s) + keel-fd11-a58a-88ef-0-47d1-8a55-262c-33ed fd11:a58a:88ef:0:47d1:8a55:262c:33ed voter healthy + keel-fd11-a58a-88ef--2 fd11:a58a:88ef::2 voter context deadline exceeded + keel-fd11-a58a-88ef--1 fd11:a58a:88ef::1 voter healthy +leader: keel-fd11-a58a-88ef-0-47d1-8a55-262c-33ed +FAIL so far: 0 + +=== [125] 2026-10-10T17:11:46Z rc=0 +$ date -u +%T; DEBIAN_FRONTEND=noninteractive apt-get install -y -q --only-upgrade keel 2>&1 | grep -E "Unpacking|Setting up|rror|arning"; date -u +%T; dpkg-query -W keel keel-overlay-installer keel-overlay-etcd keel-overlay-vip | tr "\n" " "; echo; keel --version; ip -o link show wg0 | grep -o "mtu [0-9]*"; sleep 20; keel mesh status 2>&1 | grep -E "voter|leader"; echo "FAIL so far: $(grep -c FAIL /root/etcdmon3.log)" +17:11:07 +Unpacking keel (0.23.13) over (0.23.7) ... +Setting up keel (0.23.13) ... +17:11:15 +keel 0.23.13 keel-overlay-etcd 0.4.0 keel-overlay-installer 0.2.0 keel-overlay-vip 0.2.0 +0.23.13 +mtu 1420 +etcd: 3 voter(s), 0 learner(s) + keel-fd11-a58a-88ef-0-47d1-8a55-262c-33ed fd11:a58a:88ef:0:47d1:8a55:262c:33ed voter healthy + keel-fd11-a58a-88ef--2 fd11:a58a:88ef::2 voter context deadline exceeded + keel-fd11-a58a-88ef--1 fd11:a58a:88ef::1 voter healthy +leader: keel-fd11-a58a-88ef-0-47d1-8a55-262c-33ed +FAIL so far: 0 + +=== [web2] 2026-10-10T17:12:15Z rc=255 +$ hostname +Connection timed out during banner exchange +Connection to UNKNOWN port 65535 timed out + +=== [9003] 2026-10-10T17:12:17Z rc=0 +$ systemd-run --unit=keeltest-writer-up3 --collect /root/writer.sh up3 150 +Running as unit: keeltest-writer-up3.service; invocation ID: dbc169f017b948478aeea213552ca962 + +=== [9003] 2026-10-10T17:12:38Z rc=0 +$ sleep 10; date -u +%T.%3N; DEBIAN_FRONTEND=noninteractive apt-get install -y -q --only-upgrade keel 2>&1 | grep -E "Unpacking|Setting up|rror|arning"; date -u +%T.%3N; dpkg-query -W keel keel-mariadb keel-overlay-installer keel-overlay-vip | tr "\n" " "; echo; keel --version; ip -o link show wg0 | grep -o "mtu [0-9]*"; mariadb -N -e "select @@read_only" +17:12:29.086 +Unpacking keel (0.23.13) over (0.23.7) ... +Setting up keel (0.23.13) ... +17:12:38.290 +keel 0.23.13 keel-mariadb 0.1.1 keel-overlay-installer 0.2.0 keel-overlay-vip 0.2.0 +0.23.13 +mtu 1420 +1 + +=== [9004] 2026-10-10T17:13:00Z rc=0 +$ sleep 10; date -u +%T.%3N; DEBIAN_FRONTEND=noninteractive apt-get install -y -q --only-upgrade keel 2>&1 | grep -E "Unpacking|Setting up|rror|arning"; date -u +%T.%3N; dpkg-query -W keel keel-mariadb keel-overlay-installer keel-overlay-vip | tr "\n" " "; echo; keel --version; ip -o link show wg0 | grep -o "mtu [0-9]*"; mariadb -N -e "select @@read_only" +17:12:50.533 +Unpacking keel (0.23.13) over (0.23.7) ... +Setting up keel (0.23.13) ... +17:12:59.830 +keel 0.23.13 keel-mariadb 0.1.1 keel-overlay-installer 0.2.0 keel-overlay-vip 0.2.0 +0.23.13 +mtu 1420 +0 + +=== [9003] 2026-10-10T17:14:48Z rc=0 +$ while systemctl is-active -q keeltest-writer-up3; do sleep 2; done; python3 /root/gap.py /root/writer-up3.log; awk "\$4==0{print \"up3-\"\$3}" /root/writer-up3.log | sort > /tmp/a; mariadb -N -e "select note from keeltest.t where note like \"up3-%\"" | sort > /tmp/b; echo "acked $(wc -l seq 102 on keel-db-2) +acked 1016, missing on db-1: 0 + +=== [9003] 2026-10-10T17:15:09Z rc=0 +$ date -u +%T; timeout 400 keel mesh sync 2>&1 | grep -vE "unchanged|^database|^derived|^instance" | tail -15; echo sync rc=${PIPESTATUS[0]}; date -u +%T; ip -o link show wg0 | grep -o "mtu [0-9]*"; wg show wg0 latest-handshakes | while read k t; do echo "${k:0:12} $([ $t = 0 ] && echo never || echo $(( $(date +%s) - t ))s)"; done +17:14:59 +member fd11:a58a:88ef::2 did not answer: [fd11:a58a:88ef::2]:51821 through wg0: timed out +no member this node does not know: it is a peer of every admitted member its peers know +sync rc=0 +17:15:09 +mtu 1420 +1bSgAuDppyY3 113s +o9tGVm/IKImy 73s +o+GK/71E+YK/ never +8Tjk29fOsZmT 113s + +=== [9004] 2026-10-10T17:15:21Z rc=0 +$ date -u +%T; timeout 400 keel mesh sync 2>&1 | grep -vE "unchanged|^database|^derived|^instance" | tail -15; echo sync rc=${PIPESTATUS[0]}; date -u +%T; ip -o link show wg0 | grep -o "mtu [0-9]*"; wg show wg0 latest-handshakes | while read k t; do echo "${k:0:12} $([ $t = 0 ] && echo never || echo $(( $(date +%s) - t ))s)"; done +17:15:11 +member fd11:a58a:88ef::2 did not answer: [fd11:a58a:88ef::2]:51821 through wg0: timed out +no member this node does not know: it is a peer of every admitted member its peers know +sync rc=0 +17:15:21 +mtu 1420 +1bSgAuDppyY3 24s +li08e1grPY0X 85s +o+GK/71E+YK/ 29044s +8Tjk29fOsZmT 89s + +=== [9003] 2026-10-10T17:15:32Z rc=0 +$ keel diff 2>&1 | grep -E "handshake|mtu|MTU|drift|^diff"; keel mesh status 2>&1 | grep -iE "drift|handshake" | sed -E "s/2804:[0-9a-f:]+//" +overlays.vip: drift (declared enabled, observed keel-vip.service enabled and inactive) +network.overlay.wireguard.peers.1bSgAuDppyY36XfEH2zxXeT5altQGehlT7Se2AVZyAg=.handshake: same (a handshake (10 s ago)) +network.overlay.wireguard.peers.o9tGVm/IKImyW2kgn22YjiWdEXpAr28T6WF9uc4yW1Q=.handshake: same (a handshake (95 s ago)) +network.overlay.wireguard.peers.o+GK/71E+YK/TO/pUkonxFP0DLcFdpPEm2ZlxJJ/VBc=.handshake: drift (declared a handshake, observed none; no handshake since wg0 came up: it comes once that member has this node as a peer too (keel mesh sync on that member)) +network.overlay.wireguard.peers.8Tjk29fOsZmTJ61L3LfEI2mm/LHFzAy+roHC49woQnc=.handshake: same (a handshake (10 s ago)) +diff: 24 same, 2 drift, 0 unknown, 14 not declared, 7 not compared; drift found + 1bSgAuDppyY36XfEH2zxXeT5altQGehlT7Se2AVZyAg= fd11:a58a:88ef::1/128 []:51820 handshake 11 s ago + o9tGVm/IKImyW2kgn22YjiWdEXpAr28T6WF9uc4yW1Q= fd11:a58a:88ef:0:cd53:dda9:f0cb:b889/128 []:51820 handshake 96 s ago + o+GK/71E+YK/TO/pUkonxFP0DLcFdpPEm2ZlxJJ/VBc= fd11:a58a:88ef::2/128 []:51820 no handshake yet + 8Tjk29fOsZmTJ61L3LfEI2mm/LHFzAy+roHC49woQnc= fd11:a58a:88ef:0:47d1:8a55:262c:33ed/128 []:51820 handshake 11 s ago +drift: peer o+GK/71E+YK/TO/pUkonxFP0DLcFdpPEm2ZlxJJ/VBc= has no handshake since wg0 came up: it comes once that member has this node as a peer too (keel mesh sync on that member) + +=== [9004] 2026-10-10T17:15:35Z rc=0 +$ keel diff 2>&1 | grep -E "handshake|mtu|MTU|drift|^diff"; keel mesh status 2>&1 | grep -iE "drift|handshake" | sed -E "s/2804:[0-9a-f:]+//" +overlays.vip: drift (declared enabled, observed keel-vip.service enabled and inactive) +network.overlay.wireguard.peers.1bSgAuDppyY36XfEH2zxXeT5altQGehlT7Se2AVZyAg=.handshake: same (a handshake (37 s ago)) +network.overlay.wireguard.peers.li08e1grPY0Xz9OGzLYeJ56RX6C+jSZmB/I1tKq5lmY=.handshake: same (a handshake (98 s ago)) +network.overlay.wireguard.peers.o+GK/71E+YK/TO/pUkonxFP0DLcFdpPEm2ZlxJJ/VBc=.handshake: same (a handshake (29057 s ago)) +network.overlay.wireguard.peers.8Tjk29fOsZmTJ61L3LfEI2mm/LHFzAy+roHC49woQnc=.handshake: same (a handshake (102 s ago)) +diff: 26 same, 1 drift, 0 unknown, 13 not declared, 6 not compared; drift found + 1bSgAuDppyY36XfEH2zxXeT5altQGehlT7Se2AVZyAg= fd11:a58a:88ef::1/128 []:51820 handshake 38 s ago + li08e1grPY0Xz9OGzLYeJ56RX6C+jSZmB/I1tKq5lmY= fd11:a58a:88ef:0:382f:45b:553c:f11/128 []:51820 handshake 99 s ago + o+GK/71E+YK/TO/pUkonxFP0DLcFdpPEm2ZlxJJ/VBc= fd11:a58a:88ef::2/128 []:51820 handshake 29058 s ago + 8Tjk29fOsZmTJ61L3LfEI2mm/LHFzAy+roHC49woQnc= fd11:a58a:88ef:0:47d1:8a55:262c:33ed/128 []:51820 handshake 103 s ago + +=== [9003] 2026-10-10T17:15:49Z rc=0 +$ systemd-run --unit=keeltest-writer-mtu --collect /root/writer.sh mtu 330 +Running as unit: keeltest-writer-mtu.service; invocation ID: 9133bb5f57d34b6692e7b1cd93306578 + +=== [9003] 2026-10-10T17:15:57Z rc=0 +$ sleep 5; date -u +%T.%3N; timeout 400 keel spec apply --system-only 2>&1 | grep -vE "unchanged|kept" | sed -E "s/2804:[0-9a-f:]+//g"; echo rc=${PIPESTATUS[0]}; date -u +%T.%3N; ip -o link show wg0 | grep -o "mtu [0-9]*"; grep -i mtu /etc/wireguard/wg0.conf +17:15:55.658 +apply --system-only: /etc/inithooks.conf not read or written +database.server.replication.allowed_from: authorize replication from fd11:a58a:88ef:0:cd53:dda9:f0cb:b889 with the certificate /CN=keel-fd11-a58a-88ef-0-cd53-dda9-f0cb-b889 mariadb of the mesh's root, outside the binary log (runuser -u mysql -- mariadb --batch, 5 statement(s) on standard input): done +database.server.role: the role is the VIP's: replica here (epoch known, held at fd11:a58a:88ef:0:cd53:dda9:f0cb:b889); the declared primary is the installation's (0020) +database.server.role: make the server follow the pair's VIP (keel database follow): the holder writable, the other node read only and replicating from the holder over TLS, an old primary rejoined by GTID when it holds nothing the holder lacks: done +overlays.vip: start keel-vip.service (systemctl start keel-vip.service): done +apply --system-only: 4 change(s), 0 failed +rc=0 +17:15:57.116 +mtu 1420 +MTU = 1280 + +=== [9004] 2026-10-10T17:16:05Z rc=0 +$ sleep 5; date -u +%T.%3N; timeout 400 keel spec apply --system-only 2>&1 | grep -vE "unchanged|kept" | sed -E "s/2804:[0-9a-f:]+//g"; echo rc=${PIPESTATUS[0]}; date -u +%T.%3N; ip -o link show wg0 | grep -o "mtu [0-9]*"; grep -i mtu /etc/wireguard/wg0.conf +17:16:03.774 +apply --system-only: /etc/inithooks.conf not read or written +database.server.replication.allowed_from: authorize replication from fd11:a58a:88ef:0:382f:45b:553c:f11 with the certificate /CN=keel-fd11-a58a-88ef-0-382f-45b-553c-f11 mariadb of the mesh's root, outside the binary log (runuser -u mysql -- mariadb --batch, 5 statement(s) on standard input): done +database.server.role: the role is the VIP's: primary here (epoch known, held at fd11:a58a:88ef:0:382f:45b:553c:f11); the declared replica is the installation's (0020) +database.server.role: make the server follow the pair's VIP (keel database follow): the holder writable, the other node read only and replicating from the holder over TLS, an old primary rejoined by GTID when it holds nothing the holder lacks: done +overlays.vip: start keel-vip.service (systemctl start keel-vip.service): done +apply --system-only: 4 change(s), 0 failed +rc=0 +17:16:05.173 +mtu 1420 +MTU = 1280 + +=== [9003] 2026-10-10T17:21:20Z rc=0 +$ while systemctl is-active -q keeltest-writer-mtu; do sleep 2; done; python3 /root/gap.py /root/writer-mtu.log; awk "\$4!=0{e=substr(\$0, index(\$0,\"ERROR\"), 10); print strftime(\"%T\",\$1/1000)\".\"\$1%1000, e}" /root/writer-mtu.log | awk "{if (\$2\$3!=p) {print; p=\$2\$3}}"; awk "\$4==0{print \"mtu-\"\$3}" /root/writer-mtu.log | sort > /tmp/a; mariadb -N -e "select note from keeltest.t where note like \"mtu-%\"" | sort > /tmp/b; echo "acked $(wc -l seq 1470 on keel-db-2) +acked 2278, missing on db-1: 0 + +=== [9003] 2026-10-10T17:21:39Z rc=1 +$ stat -c "%y %n" /etc/wireguard/wg0.conf; grep -i mtu /etc/wireguard/wg0.conf; ip -o link show wg0 | grep -o "mtu [0-9]*"; cd /etc && git log --format="%ci %s" -3 -- wireguard/wg0.conf; keel diff 2>&1 | grep -iE "mtu"; keel inspect 2>/dev/null | grep -i -B1 -A1 mtu +2026-10-10 17:13:26.798646635 +0000 /etc/wireguard/wg0.conf +MTU = 1280 +mtu 1420 +2026-10-10 17:12:30 +0000 saving uncommitted changes in /etc prior to apt run +2026-10-09 00:12:38 +0000 daily autocommit +2026-10-08 23:44:09 +0000 saving uncommitted changes in /etc prior to apt run + +=== [124] 2026-10-10T17:21:42Z rc=1 +$ stat -c "%y %n" /etc/wireguard/wg0.conf; grep -i mtu /etc/wireguard/wg0.conf; ip -o link show wg0 | grep -o "mtu [0-9]*"; cd /etc && git log --format="%ci %s" -3 -- wireguard/wg0.conf; keel diff 2>&1 | grep -iE "mtu"; keel inspect 2>/dev/null | grep -i -B1 -A1 mtu +2026-10-09 04:26:43.530637964 +0000 /etc/wireguard/wg0.conf +mtu 1420 +2026-10-09 04:11:04 +0000 saving uncommitted changes in /etc prior to apt run +2026-10-08 23:42:28 +0000 saving uncommitted changes in /etc prior to apt run +2026-10-04 03:02:26 +0000 saving uncommitted changes in /etc prior to apt run + +=== [125] 2026-10-10T17:21:56Z rc=0 +$ keel spec apply --system-only --dry-run 2>&1 | grep -vE "unchanged|kept" | sed -E "s/2804:[0-9a-f:]+//g"; echo rc=${PIPESTATUS[0]} +apply --system-only: /etc/inithooks.conf not read or written +network.overlay: would bring the overlay wg0 up on a new /etc/wireguard/wg0.conf; it reverts in 120 s unless `keel network confirm` is run from a new session, over the overlay or the uplink +dry run: 1 change(s) planned, nothing written +rc=0 + +=== [124] 2026-10-10T17:21:58Z rc=0 +$ keel spec apply --system-only --dry-run 2>&1 | grep -vE "unchanged|kept" | sed -E "s/2804:[0-9a-f:]+//g"; echo rc=${PIPESTATUS[0]} +apply --system-only: /etc/inithooks.conf not read or written +network.overlay: would bring the overlay wg0 up on a new /etc/wireguard/wg0.conf; it reverts in 120 s unless `keel network confirm` is run from a new session, over the overlay or the uplink +dry run: 1 change(s) planned, nothing written +rc=0 + +=== [125] 2026-10-10T17:22:10Z rc=0 +$ date -u +%T.%3N; timeout 300 keel spec apply --system-only 2>&1 | grep -vE "unchanged|kept" | sed -E "s/2804:[0-9a-f:]+//g"; echo rc=${PIPESTATUS[0]}; date -u +%T.%3N; ip -o link show wg0 | grep -o "mtu [0-9]*"; systemctl list-timers "keel-network-window*" --no-legend | cut -c1-80 +17:22:09.428 +apply --system-only: /etc/inithooks.conf not read or written +network.overlay: bring the overlay wg0 up on a new /etc/wireguard/wg0.conf; it reverts in 120 s unless `keel network confirm` is run from a new session, over the overlay or the uplink: done with wg-quick down, then up +apply --system-only: 1 change(s), 0 failed +rc=0 +17:22:10.384 +mtu 1280 +Sat 2026-10-10 17:24:10 UTC 1min 59s - - keel-network-window.timer keel-n +Sat 2026-10-10 17:25:10 UTC 2min 59s - - keel-network-window-safety.timer keel-n + +=== [125] 2026-10-10T17:22:19Z rc=0 +$ date -u +%T; keel network confirm 2>&1 | sed -E "s/2804:[0-9a-f:]+//g"; echo rc=$?; systemctl list-timers "keel-network-window*" --no-legend | cut -c1-60; ip -o link show wg0 | grep -o "mtu [0-9]*"; wg show wg0 latest-handshakes | while read k t; do echo "${k:0:12} $([ $t = 0 ] && echo never || echo $(( $(date +%s) - t ))s)"; done; awk "\$1>=\"17:21:00\"" /root/etcdmon3.log | grep -c FAIL; grep FAIL /root/etcdmon3.log | head -2; grep FAIL /root/etcdmon3.log | tail -1 +17:22:18 +confirmed from a process attached from the container's host +wg-quick@wg0 enabled: the overlay comes back up at boot +the network change stays; the revert is cancelled +rc=0 +mtu 1280 +1bSgAuDppyY3 9s +o+GK/71E+YK/ never +li08e1grPY0X never +o9tGVm/IKImy never +0 + +=== [124] 2026-10-10T17:22:30Z rc=0 +$ date -u +%T.%3N; timeout 300 keel spec apply --system-only 2>&1 | grep -vE "unchanged|kept" | sed -E "s/2804:[0-9a-f:]+//g"; echo rc=${PIPESTATUS[0]}; date -u +%T.%3N +17:22:29.340 +apply --system-only: /etc/inithooks.conf not read or written +network.overlay: bring the overlay wg0 up on a new /etc/wireguard/wg0.conf; it reverts in 120 s unless `keel network confirm` is run from a new session, over the overlay or the uplink: done with wg-quick down, then up +apply --system-only: 1 change(s), 0 failed +rc=0 +17:22:30.293 + +=== [124] 2026-10-10T17:22:58Z rc=0 +$ date -u +%T; keel network confirm 2>&1; echo rc=$?; ip -o link show wg0 | grep -o "mtu [0-9]*"; sleep 15; wg show wg0 latest-handshakes | while read k t; do echo "${k:0:12} $([ $t = 0 ] && echo never || echo $(( $(date +%s) - t ))s)"; done; wg show wg0 allowed-ips | grep -c ffff:1; keel mesh status 2>&1 | grep -E "voter|leader"; echo "FAIL total $(grep -c FAIL /root/etcdmon3.log)" +17:22:31 +confirmed from a process attached from the container's host +wg-quick@wg0 enabled: the overlay comes back up at boot +the network change stays; the revert is cancelled +rc=0 +mtu 1280 +o+GK/71E+YK/ never +8Tjk29fOsZmT 17s +li08e1grPY0X 1s +o9tGVm/IKImy never +1 +etcd: 3 voter(s), 0 learner(s) + keel-fd11-a58a-88ef-0-47d1-8a55-262c-33ed fd11:a58a:88ef:0:47d1:8a55:262c:33ed voter healthy + keel-fd11-a58a-88ef--2 fd11:a58a:88ef::2 voter context deadline exceeded + keel-fd11-a58a-88ef--1 fd11:a58a:88ef::1 voter healthy +leader: keel-fd11-a58a-88ef-0-47d1-8a55-262c-33ed +FAIL total 0 + +=== [125] 2026-10-10T17:22:59Z rc=0 +$ echo "web-3 FAIL total $(grep -c FAIL /root/etcdmon3.log)" +web-3 FAIL total 0 + +=== [host] 2026-10-10T17:23:18Z rc=0 +$ echo "pct reboot 9003 at $(date -u +%T.%3N)"; pct reboot 9003; echo "back at $(date -u +%T.%3N)" +pct reboot 9003 at 17:23:11.288 +back at 17:23:18.824 + +=== [9003] 2026-10-10T17:23:22Z rc=0 +$ for i in $(seq 1 60); do s=$(mariadb -e "show replica status\G" 2>/dev/null | grep -E "Slave_SQL_Running:" | awk "{print \$2}"); [ "$s" = Yes ] && break; sleep 2; done; date -u +%T; ip -o link show wg0 | grep -o "mtu [0-9]*"; mariadb -N -e "select @@read_only"; mariadb -e "show replica status\G" | grep -E "IO_Running|SQL_Running:|SSL_Allowed|Seconds_Behind"; wg show wg0 latest-handshakes | while read k t; do echo "${k:0:12} $([ $t = 0 ] && echo never || echo $(( $(date +%s) - t ))s)"; done +17:23:22 +mtu 1280 +1 + Slave_IO_Running: Connecting + Slave_SQL_Running: Yes + Master_SSL_Allowed: Yes + Seconds_Behind_Master: NULL +1bSgAuDppyY3 never +o9tGVm/IKImy never +o+GK/71E+YK/ never +8Tjk29fOsZmT never + +=== [9003] 2026-10-10T17:23:30Z rc=0 +$ for i in $(seq 1 60); do s=$(mariadb -e "show replica status\G" | grep -E "Slave_IO_Running:" | awk "{print \$2}"); [ "$s" = Yes ] && break; sleep 2; done; date -u +%T; mariadb -e "show replica status\G" | grep -E "IO_Running|SQL_Running:|SSL_Allowed|Seconds_Behind|Last_IO_Error"; wg show wg0 latest-handshakes | while read k t; do echo "${k:0:12} $([ $t = 0 ] && echo never || echo $(( $(date +%s) - t ))s)"; done +17:23:30 + Slave_IO_Running: Yes + Slave_SQL_Running: Yes + Master_SSL_Allowed: Yes + Seconds_Behind_Master: 0 + Last_IO_Error: +1bSgAuDppyY3 never +o9tGVm/IKImy 3s +o+GK/71E+YK/ never +8Tjk29fOsZmT never + +=== [9003] 2026-10-10T17:23:51Z rc=0 +$ timeout 300 keel mesh sync 2>&1 | tail -3; wg show wg0 latest-handshakes | while read k t; do echo "${k:0:12} $([ $t = 0 ] && echo never || echo $(( $(date +%s) - t ))s)"; done; keel diff 2>&1 | grep -E "handshake|^diff" | sed -E "s/peers\.(.{12})[^.]*\./peers.\1...\./"; grep -i persistent /etc/wireguard/wg0.conf | head -2 +member fd11:a58a:88ef::2 did not answer: [fd11:a58a:88ef::2]:51821 through wg0: timed out +no member this node does not know: it is a peer of every admitted member its peers know +1bSgAuDppyY3 10s +o9tGVm/IKImy 22s +o+GK/71E+YK/ never +8Tjk29fOsZmT 10s +network.overlay.wireguard.peers.1bSgAuDppyY3....handshake: same (a handshake (12 s ago)) +network.overlay.wireguard.peers.o9tGVm/IKImy....handshake: same (a handshake (24 s ago)) +network.overlay.wireguard.peers.o+GK/71E+YK/....handshake: drift (declared a handshake, observed none; no handshake since wg0 came up: it comes once that member has this node as a peer too (keel mesh sync on that member)) +network.overlay.wireguard.peers.8Tjk29fOsZmT....handshake: same (a handshake (12 s ago)) +diff: 24 same, 2 drift, 0 unknown, 14 not declared, 7 not compared; drift found + +=== [9003] 2026-10-10T17:24:35Z rc=0 +$ systemd-run --unit=keeltest-writer-pl --collect /root/writer.sh pl 80; sleep 10; date -u +%T.%3N; timeout 120 keel vip promote 2>&1; echo rc=$?; date -u +%T.%3N; for i in $(seq 1 60); do [ "$(mariadb -N -e "select @@read_only")" = 0 ] && break; sleep 0.2; done; echo "db-1 writable at $(date -u +%T.%3N)" +Running as unit: keeltest-writer-pl.service; invocation ID: 292e3013c5d84d71ba1200fb59c654c5 +17:24:13.827 + fd11:a58a:88ef::2: [fd11:a58a:88ef::2]:51821 through wg0: timed out +asking the primary, o9tGVm/IKImyW2kgn22YjiWdEXpAr28T6WF9uc4yW1Q= at fd11:a58a:88ef:0:cd53:dda9:f0cb:b889, to release fd11:a58a:88ef::ffff:1… +released by fd11:a58a:88ef:0:cd53:dda9:f0cb:b889 + fd11:a58a:88ef:0:47d1:8a55:262c:33ed: applied + fd11:a58a:88ef:0:cd53:dda9:f0cb:b889: applied + fd11:a58a:88ef::1: applied + fd11:a58a:88ef::2: unreachable: [fd11:a58a:88ef::2]:51821 through wg0: timed out +1 peer(s) did not take the claim now; each takes it at its next keel vip check, and routes the VIP to the old primary until then +this node holds fd11:a58a:88ef::ffff:1 at epoch 7, on wg0, taken by 3 of 3 peer(s) +rc=0 +17:24:34.855 +db-1 writable at 17:24:35.518 + +=== [9004] 2026-10-10T17:25:24Z rc=0 +$ sleep 25; date -u +%T.%3N; timeout 120 keel vip promote 2>&1; echo rc=$?; date -u +%T.%3N; for i in $(seq 1 60); do [ "$(mariadb -N -e "select @@read_only")" = 0 ] && break; sleep 0.2; done; echo "db-2 writable at $(date -u +%T.%3N)" +17:25:02.799 + fd11:a58a:88ef::2: [fd11:a58a:88ef::2]:51821 through wg0: timed out +asking the primary, li08e1grPY0Xz9OGzLYeJ56RX6C+jSZmB/I1tKq5lmY= at fd11:a58a:88ef:0:382f:45b:553c:f11, to release fd11:a58a:88ef::ffff:1… +released by fd11:a58a:88ef:0:382f:45b:553c:f11 + fd11:a58a:88ef:0:382f:45b:553c:f11: applied + fd11:a58a:88ef:0:47d1:8a55:262c:33ed: applied + fd11:a58a:88ef::1: applied + fd11:a58a:88ef::2: unreachable: [fd11:a58a:88ef::2]:51821 through wg0: timed out +1 peer(s) did not take the claim now; each takes it at its next keel vip check, and routes the VIP to the old primary until then +this node holds fd11:a58a:88ef::ffff:1 at epoch 8, on wg0, taken by 3 of 3 peer(s) +rc=0 +17:25:23.527 +db-2 writable at 17:25:24.112 + +=== [9003] 2026-10-10T17:25:26Z rc=0 +$ while systemctl is-active -q keeltest-writer-pl; do sleep 2; done; python3 /root/gap.py /root/writer-pl.log; awk "{print \$5}" /root/writer-pl.log | uniq -c; awk "\$4!=0{print strftime(\"%T\",\$1/1000)\".\"\$1%1000, substr(\$0, index(\$0,\"ERROR\"), 60)}" /root/writer-pl.log; awk "\$4==0" /root/writer-pl.log | awk "BEGIN{p=0}{ if (p && \$1-p>800) print \"gap\", (\$2-p)/1000 \" s: last ok\", strftime(\"%T\",p/1000)\".\"p%1000, \"next ok\", strftime(\"%T\",\$2/1000)\".\"\$2%1000; p=\$2}"; awk "\$4==0{print \"pl-\"\$3}" /root/writer-pl.log | sort > /tmp/a; mariadb -N -e "select note from keeltest.t where note like \"pl-%\"" | sort > /tmp/b; echo "acked $(wc -l seq 143 on keel-db-1) + 131 keel-db-2 + 8 ERROR + 3 -------------- + 227 keel-db-1 + 5 ERROR +17:24:24.626 ERROR 2013 (HY000): Lost connection to server at 'handshake: +17:24:26.747 ERROR 2002 (HY000): Can't connect to server on 'fd11:a58a:88 +17:24:27.873 ERROR 2002 (HY000): Can't connect to server on 'fd11:a58a:88 +17:24:29.24 ERROR 2002 (HY000): Can't connect to server on 'fd11:a58a:88 +17:24:30.176 ERROR 2002 (HY000): Can't connect to server on 'fd11:a58a:88 +17:24:31.332 ERROR 2002 (HY000): Can't connect to server on 'fd11:a58a:88 +17:24:32.479 ERROR 2002 (HY000): Can't connect to server on 'fd11:a58a:88 +17:24:33.640 ERROR 2002 (HY000): Can't connect to server on 'fd11:a58a:88 +17:24:34.789 ERROR 1290 (HY000) at line 1: The MariaDB server is running +17:24:35.17 ERROR 1290 (HY000) at line 1: The MariaDB server is running +17:24:35.197 ERROR 1290 (HY000) at line 1: The MariaDB server is running +17:25:13.366 ERROR 2002 (HY000): Can't connect to server on 'fd11:a58a:88 +17:25:15.491 ERROR 2002 (HY000): Can't connect to server on 'fd11:a58a:88 +17:25:17.614 ERROR 2002 (HY000): Can't connect to server on 'fd11:a58a:88 +17:25:19.737 ERROR 2002 (HY000): Can't connect to server on 'fd11:a58a:88 +17:25:21.860 ERROR 2002 (HY000): Can't connect to server on 'fd11:a58a:88 +gap 10.981 s: last ok 17:24:24.520 next ok 17:24:35.501 +acked 358, missing on db-1: 0 + +=== [9004] 2026-10-10T17:25:27Z rc=0 +$ mariadb -N -e "select count(*) from keeltest.t where note like \"pl-%\"" +358 + +=== [9003] 2026-10-10T17:26:16Z rc=0 +$ systemd-run --unit=keeltest-writer-pl2 --collect /root/writer.sh pl2 110; sleep 10; date -u +%T.%3N; timeout 120 keel vip promote 2>&1 | tail -1; echo rc=$?; date -u +%T.%3N +Running as unit: keeltest-writer-pl2.service; invocation ID: 0086b626c0e04b6b8c9d28512323c60c +17:25:55.111 +this node holds fd11:a58a:88ef::ffff:1 at epoch 9, on wg0, taken by 3 of 3 peer(s) +rc=0 +17:26:16.004 + +=== [9004] 2026-10-10T17:27:08Z rc=0 +$ sleep 30; date -u +%T.%3N; timeout 120 keel vip promote 2>&1 | tail -1; echo rc=$?; date -u +%T.%3N +17:26:47.567 +this node holds fd11:a58a:88ef::ffff:1 at epoch 10, on wg0, taken by 3 of 3 peer(s) +rc=0 +17:27:08.312 + +=== [9003] 2026-10-10T17:27:37Z rc=0 +$ while systemctl is-active -q keeltest-writer-pl2; do sleep 2; done; python3 /root/gap.py /root/writer-pl2.log; awk "{print \$5}" /root/writer-pl2.log | uniq -c | awk "{print \$1, \$2}"; awk "\$4==0" /root/writer-pl2.log | awk "BEGIN{p=0}{ if (p && \$1-p>800) print \"gap\", (\$2-p)/1000 \" s: last ok\", strftime(\"%T\",p/1000)\".\"p%1000, \"next ok\", strftime(\"%T\",\$2/1000)\".\"\$2%1000; p=\$2}"; awk "\$4==0{print \"pl2-\"\$3}" /root/writer-pl2.log | sort > /tmp/a; mariadb -N -e "select note from keeltest.t where note like \"pl2-%\"" | sort > /tmp/b; echo "acked $(wc -l seq 482 on keel-db-2) +135 keel-db-2 +1 ERROR +5 -------------- +336 keel-db-1 +2 ERROR +2 -------------- +187 keel-db-2 +gap 1.27 s: last ok 17:26:05.723 next ok 17:26:06.993 +gap 4.766 s: last ok 17:26:58.103 next ok 17:27:02.869 +acked 658, missing on db-1: 0 + +=== [9004] 2026-10-10T17:27:52Z rc=0 +$ rm -f /root/probe-boot.log; printf "[Unit]\nDescription=test probe (remove after the test)\n[Service]\nType=simple\nExecStart=/root/probe.sh\n[Install]\nWantedBy=multi-user.target\n" > /etc/systemd/system/keeltest-probe.service; systemctl daemon-reload; systemctl enable keeltest-probe.service 2>&1 | tail -1 +Created symlink '/etc/systemd/system/multi-user.target.wants/keeltest-probe.service' → '/etc/systemd/system/keeltest-probe.service'. + +=== [host] 2026-10-10T17:28:43Z rc=0 +$ pct exec 9003 -- systemd-run --unit=keeltest-writer-c4 --collect /root/writer.sh crash4 100; sleep 10; echo "pct stop 9004 at $(date -u +%T.%3N)"; pct stop 9004; echo "stopped at $(date -u +%T.%3N)"; sleep 2; pct exec 9003 -- bash -c "date -u +%T.%3N; timeout 120 keel vip promote --old-primary-gone 2>&1; echo rc=\$?; date -u +%T.%3N; for i in \$(seq 1 150); do [ \"\$(mariadb -N -e \"select @@read_only\")\" = 0 ] && break; sleep 0.2; done; echo \"db-1 writable at \$(date -u +%T.%3N)\"" +Running as unit: keeltest-writer-c4.service; invocation ID: 6412d322984645ea8e8f67dc1855cd8b +pct stop 9004 at 17:28:04.050 +stopped at 17:28:08.056 +17:28:11.926 + fd11:a58a:88ef:0:cd53:dda9:f0cb:b889: [fd11:a58a:88ef:0:cd53:dda9:f0cb:b889]:51821 through wg0: timed out + fd11:a58a:88ef::2: [fd11:a58a:88ef::2]:51821 through wg0: timed out +asking the primary, o9tGVm/IKImyW2kgn22YjiWdEXpAr28T6WF9uc4yW1Q= at fd11:a58a:88ef:0:cd53:dda9:f0cb:b889, to release fd11:a58a:88ef::ffff:1… +the primary at fd11:a58a:88ef:0:cd53:dda9:f0cb:b889 did not answer ([fd11:a58a:88ef:0:cd53:dda9:f0cb:b889]:51821 through wg0: timed out); --old-primary-gone: it will drop the VIP when it learns the newer claim + fd11:a58a:88ef:0:47d1:8a55:262c:33ed: applied + fd11:a58a:88ef:0:cd53:dda9:f0cb:b889: unreachable: [fd11:a58a:88ef:0:cd53:dda9:f0cb:b889]:51821 through wg0: timed out + fd11:a58a:88ef::1: applied + fd11:a58a:88ef::2: unreachable: [fd11:a58a:88ef::2]:51821 through wg0: timed out +2 peer(s) did not take the claim now; each takes it at its next keel vip check, and routes the VIP to the old primary until then +this node holds fd11:a58a:88ef::ffff:1 at epoch 11, on wg0, taken by 2 of 2 peer(s) +rc=0 +17:28:42.766 +db-1 writable at 17:28:43.337 + +=== [host] 2026-10-10T17:29:02Z rc=0 +$ echo "pct start 9004 at $(date -u +%T.%3N)"; pct start 9004; echo "started at $(date -u +%T.%3N)" +pct start 9004 at 17:28:55.720 +started at 17:29:02.116 + +=== [9003] 2026-10-10T17:29:34Z rc=0 +$ while systemctl is-active -q keeltest-writer-c4; do sleep 2; done; python3 /root/gap.py /root/writer-crash4.log; awk "\$4==0" /root/writer-crash4.log | awk "BEGIN{p=0}{ if (p && \$1-p>800) print \"gap\", (\$2-p)/1000 \" s: last ok\", strftime(\"%T\",p/1000)\".\"p%1000, \"next ok\", strftime(\"%T\",\$2/1000)\".\"\$2%1000; p=\$2}"; awk "\$4!=0{e=substr(\$0, index(\$0,\"ERROR\"), 10); print strftime(\"%T\",\$1/1000)\".\"\$1%1000, e}" /root/writer-crash4.log | awk "{if (\$2\$3!=p) {print; p=\$2\$3}}"; awk "\$4==0{print \"crash4-\"\$3}" /root/writer-crash4.log | sort > /tmp/a; mariadb -N -e "select note from keeltest.t where note like \"crash4-%\"" | sort > /tmp/b; echo "acked $(wc -l seq 96 on keel-db-1) +gap 37.746 s: last ok 17:28:05.641 next ok 17:28:43.387 +17:28:05.747 ERROR 2013 +17:28:05.884 ERROR 2002 +17:28:41.633 ERROR 1290 +acked 381, missing on db-1: 0 + +=== [9004] 2026-10-10T17:31:18Z rc=0 +$ for i in $(seq 1 90); do s=$(mariadb -e "show replica status\G" 2>/dev/null | grep -E "Slave_SQL_Running:" | awk "{print \$2}"); [ "$s" = Yes ] && break; sleep 2; done; while systemctl is-active -q keeltest-probe; do sleep 2; done; awk "{k=\$2\" \"\$3; if (k!=p) {print; p=k}}" /root/probe-boot.log; echo "samples $(wc -l < /root/probe-boot.log), read_only=0: $(grep -c read_only=0 /root/probe-boot.log), VIP on wg0: $(grep -c VIP-on-wg0 /root/probe-boot.log)"; ip -o link show wg0 | grep -o "mtu [0-9]*"; journalctl -b --no-pager -o short-iso | grep keel\\[ | grep -E "read_only|read only|rejoin|epoch|dump" | head -6; mariadb -e "show replica status\G" | grep -E "Master_Host|IO_Running|SQL_Running:|SSL_Allowed"; systemctl disable keeltest-probe 2>&1 | tail -1; rm -f /etc/systemd/system/keeltest-probe.service; systemctl daemon-reload; cp /root/probe-boot.log /root/probe-crash4-db2.log +17:29:04.382 read_only=down no-VIP +17:29:07.810 read_only=1 no-VIP +samples 240, read_only=0: 0, VIP on wg0: 0 +mtu 1280 +2026-10-10T17:29:25+00:00 keel-db-2 keel[682]: database.server.role: read only: this node's claim of fd11:a58a:88ef::ffff:1, not proven (the VIP is not on wg0). It takes writes once keel vip check, keel vip promote or, with etcd, the controller carries the VIP; a newer claim makes it a replica +2026-10-10T17:29:48+00:00 keel-db-2 keel[1379]: vip fd11:a58a:88ef::ffff:1: epoch 11, held by li08e1grPY0Xz9OGzLYeJ56RX6C+jSZmB/I1tKq5lmY= at fd11:a58a:88ef:0:382f:45b:553c:f11; this node no longer holds it +2026-10-10T17:29:48+00:00 keel-db-2 keel[1379]: vip fd11:a58a:88ef::ffff:1: took epoch 11, held by li08e1grPY0Xz9OGzLYeJ56RX6C+jSZmB/I1tKq5lmY= +2026-10-10T17:29:49+00:00 keel-db-2 keel[1587]: database.server.role: a dump of what this node holds is kept at /var/backups/keel/mariadb/rejoin-20261010T172949Z.sql.zst +2026-10-10T17:29:49+00:00 keel-db-2 keel[1587]: database.server.role: rejoined: no errant GTID, replicating from [fd11:a58a:88ef:0:382f:45b:553c:f11]:3306 over TLS from 0-650213503-7321 + Master_Host: fd11:a58a:88ef:0:382f:45b:553c:f11 + Slave_IO_Running: Yes + Slave_SQL_Running: Yes + Master_SSL_Allowed: Yes +Removed '/etc/systemd/system/multi-user.target.wants/keeltest-probe.service'. + +=== [9003] 2026-10-10T17:31:38Z rc=0 +$ systemd-run --unit=keeltest-writer-pl3 --collect /root/writer.sh pl3 50 +Running as unit: keeltest-writer-pl3.service; invocation ID: 3a38ca9fdad0486a8073c619f202fd18 + +=== [9004] 2026-10-10T17:32:09Z rc=0 +$ sleep 8; date -u +%T.%3N; timeout 120 keel vip promote 2>&1 | tail -1; echo rc=$?; date -u +%T.%3N +17:31:48.583 +this node holds fd11:a58a:88ef::ffff:1 at epoch 12, on wg0, taken by 3 of 3 peer(s) +rc=0 +17:32:09.510 + +=== [9003] 2026-10-10T17:32:29Z rc=0 +$ while systemctl is-active -q keeltest-writer-pl3; do sleep 2; done; python3 /root/gap.py /root/writer-pl3.log; awk "\$4==0{print \"pl3-\"\$3}" /root/writer-pl3.log | sort > /tmp/a; mariadb -N -e "select note from keeltest.t where note like \"pl3-%\"" | sort > /tmp/b; echo "acked $(wc -l seq 129 on keel-db-2) +acked 217, missing on db-1: 0 + +=== [9003] 2026-10-10T17:32:38Z rc=0 +$ awk "\$3>=125 && \$3<=130{print strftime(\"%T\",\$1/1000)\".\"\$1%1000, strftime(\"%T\",\$2/1000)\".\"\$2%1000, \$3, \$4, substr(\$0, index(\$0,\$5), 90)}" /root/writer-pl3.log +17:31:58.788 17:31:58.857 125 0 keel-db-1 +17:31:58.968 17:31:59.23 126 0 keel-db-1 +17:31:59.132 17:31:59.183 127 0 keel-db-1 +17:31:59.289 17:32:14.299 128 124 1791653519289 1791653534299 128 124 +17:32:14.404 17:32:14.447 129 0 keel-db-2 +17:32:14.552 17:32:14.597 130 0 keel-db-2 + +=== [9004] 2026-10-10T17:32:40Z rc=0 +$ journalctl -S "2026-10-10 17:31:45" -U "2026-10-10 17:32:15" --no-pager -o short-iso | grep -E "keel\[" | cut -c1-220 | head; journalctl -u keel-database-follow -S "2026-10-10 17:31:45" --no-pager -o short-iso | grep -E "Starting|promoted|Finished" | head -4 +2026-10-10T17:31:50+00:00 keel-db-2 keel[3101]: database.server.role: unchanged (a replica of [fd11:a58a:88ef:0:382f:45b:553c:f11]:3306) +2026-10-10T17:32:09+00:00 keel-db-2 keel[3171]: database.server.role: drained and promoted: this node replicates from nobody and takes writes +2026-10-10T17:32:09+00:00 keel-db-2 keel[3171]: database.server.role: READ_ONLY ADMIN given back to the accounts the replica took it from +2026-10-10T17:32:10+00:00 keel-db-2 keel[3222]: database watch: role primary, semi-synchronous on (was on) +2026-10-10T17:32:10+00:00 keel-db-2 keel[3222]: database watch: the server does not match the VIP's role; keel database follow +2026-10-10T17:32:10+00:00 keel-db-2 keel[3222]: unchanged (the primary, writable) +2026-10-10T17:31:48+00:00 keel-db-2 systemd[1]: Starting keel-database-follow.service - keel database: the server follows the pair's VIP... +2026-10-10T17:31:50+00:00 keel-db-2 systemd[1]: Finished keel-database-follow.service - keel database: the server follows the pair's VIP. +2026-10-10T17:31:59+00:00 keel-db-2 systemd[1]: Starting keel-database-follow.service - keel database: the server follows the pair's VIP... +2026-10-10T17:32:09+00:00 keel-db-2 keel[3171]: database.server.role: drained and promoted: this node replicates from nobody and takes writes + +=== [9003] 2026-10-10T17:32:41Z rc=0 +$ journalctl -S "2026-10-10 17:31:45" -U "2026-10-10 17:32:15" --no-pager -o short-iso | grep -E "keel\[" | cut -c1-200 | head -8 +2026-10-10T17:31:45+00:00 keel-db-1 keel[14249]: database watch: role primary, semi-synchronous on (was on) +2026-10-10T17:31:59+00:00 keel-db-1 keel[269]: vip fd11:a58a:88ef::ffff:1: released by this node; it is no longer the primary +2026-10-10T17:31:59+00:00 keel-db-1 keel[269]: vip fd11:a58a:88ef::ffff:1: epoch 12, held by o9tGVm/IKImyW2kgn22YjiWdEXpAr28T6WF9uc4yW1Q= at fd11:a58a:88ef:0:cd53:dda9:f0cb:b889 +2026-10-10T17:32:00+00:00 keel-db-1 keel[15007]: database.server.role: set read_only ON: a replica takes no writes of its own +2026-10-10T17:32:00+00:00 keel-db-1 keel[15007]: database.server.role: a dump of what this node holds is kept at /var/backups/keel/mariadb/rejoin-20261010T173200Z.sql.zst +2026-10-10T17:32:00+00:00 keel-db-1 keel[15007]: database.server.role: rejoined: no errant GTID, replicating from [fd11:a58a:88ef:0:cd53:dda9:f0cb:b889]:3306 over TLS from 0-388044305-7760 + +=== [9003] 2026-10-10T17:32:54Z rc=0 +$ mariadb -N -e "select id,node,note,at from keeltest.t where note in (\"pl3-127\",\"pl3-128\",\"pl3-129\")"; mariadb -N -e "select @@gtid_binlog_state" +7747 keel-db-1 pl3-127 2026-10-10 17:31:59.173228 +7748 keel-db-1 pl3-128 2026-10-10 17:31:59.343611 +7749 keel-db-2 pl3-129 2026-10-10 17:32:14.438806 +0-388044305-7760,0-650213503-7850 + +=== [9004] 2026-10-10T17:32:56Z rc=0 +$ mariadb -N -e "select id,node,note,at from keeltest.t where note in (\"pl3-127\",\"pl3-128\",\"pl3-129\")"; mariadb -N -e "select @@gtid_binlog_state" +7747 keel-db-1 pl3-127 2026-10-10 17:31:59.173228 +7748 keel-db-1 pl3-128 2026-10-10 17:31:59.343611 +7749 keel-db-2 pl3-129 2026-10-10 17:32:14.438806 +0-388044305-7760,0-650213503-7850 + +=== [9004] 2026-10-10T17:32:57Z rc=0 +$ journalctl -u keel-database-follow -u keel-vip-check -S "2026-10-10 17:31:58" -U "2026-10-10 17:32:12" --no-pager -o short-iso | grep -v pam_unix | cut -c1-200 +2026-10-10T17:31:59+00:00 keel-db-2 systemd[1]: Starting keel-database-follow.service - keel database: the server follows the pair's VIP... +2026-10-10T17:32:09+00:00 keel-db-2 keel[3171]: database.server.role: drained and promoted: this node replicates from nobody and takes writes +2026-10-10T17:32:09+00:00 keel-db-2 keel[3171]: database.server.role: READ_ONLY ADMIN given back to the accounts the replica took it from +2026-10-10T17:32:09+00:00 keel-db-2 systemd[1]: keel-database-follow.service: Deactivated successfully. +2026-10-10T17:32:09+00:00 keel-db-2 systemd[1]: Finished keel-database-follow.service - keel database: the server follows the pair's VIP. +2026-10-10T17:32:09+00:00 keel-db-2 systemd[1]: keel-database-follow.service: Consumed 1.647s CPU time, 31.1M memory peak. + +=== [host] 2026-10-10T17:33:10Z rc=0 +$ for a in ; do timeout 5 python3 -c " +import socket,sys +try: + s=socket.create_connection((sys.argv[1],3306),3); print(\"3306 OPEN\") +except Exception as e: print(\"3306:\", type(e).__name__, e)" $a | sed "s/^/$a /"; done + 3306: ConnectionRefusedError [Errno 111] Connection refused + 3306: ConnectionRefusedError [Errno 111] Connection refused + +=== [124] 2026-10-10T17:33:12Z rc=4 +$ hostname; cd /etc && echo "tracked keys: $(git ls-files | grep -cE "\.key$|wg0.key|keel-tls/server.key")"; ip -o link show wg0 | grep -o "mtu [0-9]*"; systemctl is-enabled mariadb.socket 2>/dev/null +keel-web-1 +tracked keys: 0 +mtu 1280 +not-found + +=== [125] 2026-10-10T17:33:13Z rc=4 +$ hostname; cd /etc && echo "tracked keys: $(git ls-files | grep -cE "\.key$|wg0.key|keel-tls/server.key")"; ip -o link show wg0 | grep -o "mtu [0-9]*"; systemctl is-enabled mariadb.socket 2>/dev/null +keel-web-3 +tracked keys: 0 +mtu 1280 +not-found + +=== [9003] 2026-10-10T17:33:15Z rc=1 +$ hostname; cd /etc && echo "tracked keys: $(git ls-files | grep -cE "\.key$|wg0.key|keel-tls/server.key")"; ip -o link show wg0 | grep -o "mtu [0-9]*"; systemctl is-enabled mariadb.socket 2>/dev/null +keel-db-1 +tracked keys: 0 +mtu 1280 +masked + +=== [9004] 2026-10-10T17:33:17Z rc=1 +$ hostname; cd /etc && echo "tracked keys: $(git ls-files | grep -cE "\.key$|wg0.key|keel-tls/server.key")"; ip -o link show wg0 | grep -o "mtu [0-9]*"; systemctl is-enabled mariadb.socket 2>/dev/null +keel-db-2 +tracked keys: 0 +mtu 1280 +masked + +=== [web2] 2026-10-10T17:33:37Z rc=255 +$ hostname +Connection timed out during banner exchange +Connection to UNKNOWN port 65535 timed out + +=== [9003] 2026-10-10T17:33:48Z rc=0 +$ keel database status | head -7; keel diff 2>&1 | grep -E "drift|^diff" | sed -E "s/peers\.(.{12})[^.]*\./peers.\1...\./" +pair: VIP fd11:a58a:88ef::ffff:1; role here replica + other member: fd11:a58a:88ef:0:cd53:dda9:f0cb:b889 (o9tGVm/IKImyW2kgn22YjiWdEXpAr28T6WF9uc4yW1Q=) + the primary's address: fd11:a58a:88ef:0:cd53:dda9:f0cb:b889 +server: replica (mariadb --batch --execute SHOW REPLICA STATUS\G) + read_only: true + semi-synchronous: master ON, slave ON, 0 replica(s) acknowledging, 689 commits acknowledged, 926 not + replicating from: [fd11:a58a:88ef:0:cd53:dda9:f0cb:b889]:3306; IO Yes, SQL Yes; lag 0; TLS Yes; GTID IO position 0-650213503-7850 +overlays.vip: drift (declared enabled, observed keel-vip.service enabled and inactive) +network.overlay.wireguard.peers.o+GK/71E+YK/....handshake: drift (declared a handshake, observed none; no handshake since wg0 came up: it comes once that member has this node as a peer too (keel mesh sync on that member)) +diff: 24 same, 2 drift, 0 unknown, 14 not declared, 7 not compared; drift found + +=== [9004] 2026-10-10T17:33:51Z rc=0 +$ keel database status | head -7; keel diff 2>&1 | grep -E "drift|^diff" | sed -E "s/peers\.(.{12})[^.]*\./peers.\1...\./" +pair: VIP fd11:a58a:88ef::ffff:1; role here primary + other member: fd11:a58a:88ef:0:382f:45b:553c:f11 (li08e1grPY0Xz9OGzLYeJ56RX6C+jSZmB/I1tKq5lmY=) + the primary's address: fd11:a58a:88ef:0:382f:45b:553c:f11 +server: primary (mariadb --batch --skip-column-names --execute SHOW REPLICA HOSTS lists 1 replica(s) connected) + read_only: false + semi-synchronous: master ON, slave OFF, 1 replica(s) acknowledging, 90 commits acknowledged, 439 not + replicating from: nobody +overlays.vip: drift (declared enabled, observed keel-vip.service enabled and inactive) +network.overlay.wireguard.peers.o+GK/71E+YK/....handshake: drift (declared a handshake, observed none; no handshake since wg0 came up: it comes once that member has this node as a peer too (keel mesh sync on that member)) +diff: 25 same, 2 drift, 0 unknown, 13 not declared, 6 not compared; drift found + +=== [124] 2026-10-10T17:34:04Z rc=0 +$ systemctl stop keeltest-etcdmon3; echo "$(hostname): samples $(wc -l < /root/etcdmon3.log), $(head -1 /root/etcdmon3.log | cut -d" " -f1) to $(tail -1 /root/etcdmon3.log | cut -d" " -f1), not healthy $(grep -c FAIL /root/etcdmon3.log)"; rm -f /root/etcdmon3.log; journalctl -u etcd -S "2026-10-10 17:09" --no-pager -o cat | grep -cE "lost leader|no leader"; keel mesh status 2>&1 | grep -E "voter|leader" +keel-web-1: samples 1388, 17:10:17 to 17:33:52, not healthy 0 +0 +etcd: 3 voter(s), 0 learner(s) + keel-fd11-a58a-88ef-0-47d1-8a55-262c-33ed fd11:a58a:88ef:0:47d1:8a55:262c:33ed voter healthy + keel-fd11-a58a-88ef--2 fd11:a58a:88ef::2 voter context deadline exceeded + keel-fd11-a58a-88ef--1 fd11:a58a:88ef::1 voter healthy +leader: keel-fd11-a58a-88ef-0-47d1-8a55-262c-33ed + +=== [125] 2026-10-10T17:34:16Z rc=0 +$ systemctl stop keeltest-etcdmon3; echo "$(hostname): samples $(wc -l < /root/etcdmon3.log), $(head -1 /root/etcdmon3.log | cut -d" " -f1) to $(tail -1 /root/etcdmon3.log | cut -d" " -f1), not healthy $(grep -c FAIL /root/etcdmon3.log)"; rm -f /root/etcdmon3.log; journalctl -u etcd -S "2026-10-10 17:09" --no-pager -o cat | grep -cE "lost leader|no leader"; keel mesh status 2>&1 | grep -E "voter|leader" +keel-web-3: samples 1397, 17:10:19 to 17:34:04, not healthy 0 +0 +etcd: 3 voter(s), 0 learner(s) + keel-fd11-a58a-88ef-0-47d1-8a55-262c-33ed fd11:a58a:88ef:0:47d1:8a55:262c:33ed voter healthy + keel-fd11-a58a-88ef--2 fd11:a58a:88ef::2 voter context deadline exceeded + keel-fd11-a58a-88ef--1 fd11:a58a:88ef::1 voter healthy +leader: keel-fd11-a58a-88ef-0-47d1-8a55-262c-33ed + +=== [124] 2026-10-10T17:34:25Z rc=0 +$ hostname; journalctl -S "2026-10-10 17:09" --no-pager -o short-iso | grep -E "wg-quick\[|\[#\] ip link delete" | cut -c1-110 | grep "ip link delete"; journalctl -S "2026-10-10 17:09" --no-pager -o short-iso | grep -E "done with wg" | cut -c1-60,220-300 +keel-web-1 + +=== [125] 2026-10-10T17:34:27Z rc=0 +$ hostname; journalctl -S "2026-10-10 17:09" --no-pager -o short-iso | grep -E "wg-quick\[|\[#\] ip link delete" | cut -c1-110 | grep "ip link delete"; journalctl -S "2026-10-10 17:09" --no-pager -o short-iso | grep -E "done with wg" | cut -c1-60,220-300 +keel-web-3 + +=== [9003] 2026-10-10T17:34:29Z rc=0 +$ hostname; journalctl -S "2026-10-10 17:09" --no-pager -o short-iso | grep -E "wg-quick\[|\[#\] ip link delete" | cut -c1-110 | grep "ip link delete"; journalctl -S "2026-10-10 17:09" --no-pager -o short-iso | grep -E "done with wg" | cut -c1-60,220-300 +keel-db-1 +2026-10-10T17:23:12+00:00 keel-db-1 wg-quick[223969]: [#] ip link delete dev wg0 + +=== [9004] 2026-10-10T17:34:31Z rc=0 +$ hostname; journalctl -S "2026-10-10 17:09" --no-pager -o short-iso | grep -E "wg-quick\[|\[#\] ip link delete" | cut -c1-110 | grep "ip link delete"; journalctl -S "2026-10-10 17:09" --no-pager -o short-iso | grep -E "done with wg" | cut -c1-60,220-300 +keel-db-2 + +=== [9003] 2026-10-10T17:35:40Z rc=0 +$ keel spec apply --system-only --dry-run 2>&1 | grep -iE "certificate" +database.server: would make or renew the database certificate for fd11:a58a:88ef:0:382f:45b:553c:f11 and fd11:a58a:88ef::ffff:1, signed by the mesh's root CA (here, or asked of its holder over the members' channel), under /etc/mysql/keel-tls +database.server.replication.allowed_from: would authorize replication from fd11:a58a:88ef:0:cd53:dda9:f0cb:b889 with the certificate /CN=keel-fd11-a58a-88ef-0-cd53-dda9-f0cb-b889 mariadb of the mesh's root, outside the binary log (runuser -u mysql -- mariadb --batch, 5 statement(s) on standard input) + +=== [9003] 2026-10-10T17:35:57Z rc=0 +$ timeout 300 keel spec apply --system-only 2>&1 | grep -iE "database certificate|^apply"; echo rc=${PIPESTATUS[0]} +apply --system-only: /etc/inithooks.conf not read or written +database.server: make or renew the database certificate for fd11:a58a:88ef:0:382f:45b:553c:f11 and fd11:a58a:88ef::ffff:1, signed by the mesh's root CA (here, or asked of its holder over the members' channel), under /etc/mysql/keel-tls: kept: the certificate is not due for renewal, and no file changed +apply --system-only: 4 change(s), 0 failed +rc=0 + +```