From e36c252f6e0b43d3324141a844e499b9f32ebd5a Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Mon, 28 Sep 2026 07:12:31 +0000 Subject: [PATCH] chore(buglog): log bug-1878 (ctrlstatus appliedLsn 0 on primary) and bug-1879 (cold boot ~10 s without primary) Co-Authored-By: Claude Opus 5.5 (1M context) --- .wolf/buglog.json | 53 ++++++++++++++++++++++++++++++++++++ .wolf/bugs/bug-1878.md | 61 ++++++++++++++++++++++++++++++++++++++++++ .wolf/bugs/bug-1879.md | 61 ++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 175 insertions(+) create mode 100644 .wolf/bugs/bug-1878.md create mode 100644 .wolf/bugs/bug-1879.md diff --git a/.wolf/buglog.json b/.wolf/buglog.json index 966d1f50..9fd9ef50 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -16085,6 +16085,59 @@ "record": ".wolf/bugs/bug-1877.md", "gitea_issue": 315, "gitea_synced_status": "fixed" + }, + { + "id": "bug-1878", + "status": "open", + "status_updated": "2026-09-28", + "status_note": "logged 2026-09-28; reproduced locally; fix not started", + "component": "controller", + "severity": "wrong-result", + "timestamp": "2026-09-28T07:11:38Z", + "last_seen": "2026-09-28T07:11:38Z", + "occurrences": 1, + "error_message": "ctrlstatus reports appliedLsn 0 on the primary (standby-only counter)\n\n**Observed:**\n```\nxce/client>ctrlstatus\nPrimary: ctrl-1\n...\nanswered by ctrl-1 (primary)\nterm: 2\ncommittedLsn: 4900\nappliedLsn: 0\n```\n(pc13v, 2026-09-28 14:56; locally: committedLsn 2, appliedLsn 0)\n**Expected:** the primary's real apply position, next to its committed position.\n**Impact:** every primary's ctrlstatus says it has applied nothing, which reads like a stalled apply pump; operators and scripts comparing applied vs committed get a false alarm. The data path itself is fine.\n**Found by:** user running xce_test ctrlstatus on pc13v after the bug-1872..1877 retest", + "file": "src/controller/ctrlstatus.c", + "root_cause": "ctrlstatus_fill() (src/controller/ctrlstatus.c:178) sets appliedLsn from ha->applied_lsn for every role. That counter (ha.h:161, \"Standby: last applied WAL LSN\") is only advanced when a standby applies replicated entries; ha_init() zeroes it and nothing advances it on a primary. The primary's apply cursor is persist->last_applied_lsn, which ctrlstatus never reads. The two use different conventions: ha->applied_lsn is the NEXT lsn to apply (entry->lsn+1, ha.h:969), persist->last_applied_lsn the last applied entry -- a fix has to report one convention for both roles.", + "fix": "TODO: required for fixed/partial\n\nVerification:\n- Test: TODO: name + file; RED before the fix, GREEN after\n- Suites: TODO: suite results and build profile\n- Live: TODO: soak/deploy run, or n/a and why", + "tags": [ + "controller", + "ctrlstatus", + "ha", + "display" + ], + "related_bugs": [ + "bug-1819" + ], + "fix_commits": [], + "record": ".wolf/bugs/bug-1878.md" + }, + { + "id": "bug-1879", + "status": "open", + "status_updated": "2026-09-28", + "status_note": "logged 2026-09-28; reproduced locally; fix not started", + "component": "controller", + "severity": "hang", + "timestamp": "2026-09-28T07:11:39Z", + "last_seen": "2026-09-28T07:11:39Z", + "occurrences": 1, + "error_message": "fresh HA cluster has no primary for ~10 s: first election lost, not retried until liveness timeout\n\n**Observed:**\n```\n[14:47:32,960] ctrl-1 HA FSM: -> CTRL_ELECTING (async, n_peers=3)\n[14:47:32,962] ctrl-1 HA FSM (raft): -> CTRL_STANDBY (term=1, first_boot=1)\n[14:47:32,962] ctrl-1 myapp_run: CTRL_STANDBY — waiting for primary to connect and push config\n[14:47:44,368] ctrl-1 WARN liveness_poll_fn: HA: liveness poll: no primary activity for 11s (timeout=10s) -> failover\n[14:47:44,661] ctrl-1 HA FSM (raft): -> CTRL_PRIMARY (term=2, first_boot=0)\n```\n(pc13v; locally ctrl-2/ctrl-3 log `ha_start_election_async: no local config (tag=0, n_peers=3) — participating as voter only`)\n**Expected:** a fresh cluster elects its primary as soon as a quorum of nodes is up (about a second with start-all.sh's 0.5-1 s stagger).\n**Impact:** every cold start of an HA cluster has no primary for about 10 s (the standby liveness timeout): no job submission, config push or scheduling in that window, a spurious failover WARN, and the cluster always starts at term 2. Also the cause of the 10 s of standby 'waiting for config' seen in bug-1876.\n**Found by:** user reading ctrl-1's boot log and ctrlstatus (electedTerm 2) on pc13v after the bug-1872..1877 retest", + "file": "src/controller/ha.c, src/controller/myapp.c", + "root_cause": "Established from both runs: ctrl-1, the only node with a local config, starts its term-1 election before its peers are running, cannot reach a quorum, and drops to CTRL_STANDBY (\"waiting for primary\") within ~50 ms. ctrl-2 and ctrl-3 have no local config, so ha_start_election_async() makes them voters only -- they never stand. That is by design (confirmed by the user, 2026-09-28): on a cold boot only the node holding the initial configuration (ctrl-1) may become primary, so the retry has to come from ctrl-1. Nothing starts another election until ctrl-1's standby liveness poll (10 s) treats the missing primary as a failure and runs PreVote, which it then wins at once.\n\nUnconfirmed: why the lost first-boot election leaves ctrl-1 in CTRL_STANDBY with only the 10 s liveness poll as a retry, instead of retrying after a short (randomized) election timeout as Raft does for a candidate that fails to win -- to be read in ha.c's raft_cb_become_follower()/first_boot path and myapp_run().", + "fix": "Proposed: when the config-holding node loses its first-boot election for lack of quorum, keep it a candidate and retry its own election after a short randomized election timeout (well under the 10 s standby liveness timeout) until it wins or another primary appears -- instead of settling into CTRL_STANDBY with only the liveness poll as a retry. Nodes without a config stay voters only.\n\nVerification:\n- Test: TODO: name + file; RED before the fix, GREEN after\n- Suites: TODO: suite results and build profile\n- Live: TODO: soak/deploy run, or n/a and why", + "tags": [ + "controller", + "ha", + "election", + "cold-boot" + ], + "related_bugs": [ + "bug-1876", + "bug-606" + ], + "fix_commits": [], + "record": ".wolf/bugs/bug-1879.md" } ] } diff --git a/.wolf/bugs/bug-1878.md b/.wolf/bugs/bug-1878.md new file mode 100644 index 00000000..856537d6 --- /dev/null +++ b/.wolf/bugs/bug-1878.md @@ -0,0 +1,61 @@ +--- +id: "bug-1878" +status: "open" +status_updated: "2026-09-28" +status_note: "logged 2026-09-28; reproduced locally; fix not started" +component: "controller" +severity: "wrong-result" +timestamp: "2026-09-28T07:11:38Z" +last_seen: "2026-09-28T07:11:38Z" +occurrences: 1 +files: ["src/controller/ctrlstatus.c"] +tags: ["controller", "ctrlstatus", "ha", "display"] +related: ["bug-1819"] +--- + +# bug-1878: ctrlstatus reports appliedLsn 0 on the primary (standby-only counter) + +## Description +**Observed:** +``` +xce/client>ctrlstatus +Primary: ctrl-1 +... +answered by ctrl-1 (primary) +term: 2 +committedLsn: 4900 +appliedLsn: 0 +``` +(pc13v, 2026-09-28 14:56; locally: committedLsn 2, appliedLsn 0) +**Expected:** the primary's real apply position, next to its committed position. +**Impact:** every primary's ctrlstatus says it has applied nothing, which reads like a stalled apply pump; operators and scripts comparing applied vs committed get a false alarm. The data path itself is fine. +**Found by:** user running xce_test ctrlstatus on pc13v after the bug-1872..1877 retest + +## Environment +- OS: no /etc/os-release; Docker container; NixOS kernel; kernel Linux 6.18.33 x86_64 +- libc: glibc 2.42-47 (interpreter /nix/store/wb6rhpznjfczwlwx23zmdrrw74bayxw4-glibc-2.42-47/lib/ld-linux-x86-64.so.2) +- Toolchain: gcc (GCC) 15.2.0, meson 1.9.1 +- Build: asan (xce.build) +- Code: scheduler-framework @ 44173f74 (controller unchanged since; pc13v ran 4c134127) +- Deployment: local 3-node HA (localhost:9991-9993, src/tools/deploy-ha.sh, nodes started 1 s apart by start-all.sh, xcecd_virtual) on this dev host; first seen on pc13v: NixOS 26.05, kernel 6.18.33, glibc 2.42-47, debug build, 3-node HA (ctrl-1..3, localhost:9901-9903) + scheduler + apiserver + real root xcecd, /tmp/xce-ha-deploy, 2026-09-28 14:47 +0800 + +## Reproduction +1. Deploy and start a 3-node HA cluster (`/xce-deploy-ha`, then `scripts/start-all.sh`) +2. `xce_test --norc`, then `set masters ctrl1=localhost:9991,ctrl2=localhost:9992,ctrl3=localhost:9993`, `client`, `ctrlstatus` +- Frequency: deterministic (any primary) +- Evidence: the ctrlstatus output quoted above (pc13v, pasted in the user's report) and the local run, 2026-09-28 + +## Root cause +ctrlstatus_fill() (src/controller/ctrlstatus.c:178) sets appliedLsn from ha->applied_lsn for every role. That counter (ha.h:161, "Standby: last applied WAL LSN") is only advanced when a standby applies replicated entries; ha_init() zeroes it and nothing advances it on a primary. The primary's apply cursor is persist->last_applied_lsn, which ctrlstatus never reads. The two use different conventions: ha->applied_lsn is the NEXT lsn to apply (entry->lsn+1, ha.h:969), persist->last_applied_lsn the last applied entry -- a fix has to report one convention for both roles. + +## Fix +TODO: required for fixed/partial + +## Verification +- Test: TODO: name + file; RED before the fix, GREEN after +- Suites: TODO: suite results and build profile +- Live: TODO: soak/deploy run, or n/a and why + +## References +- Related: bug-1819 (ctrlstatus_fill stale-slot bug, same function) +- Docs: .kiro/specs/controller-status/requirements.md (Req 6.2 commit/apply positions; lines 102-107) diff --git a/.wolf/bugs/bug-1879.md b/.wolf/bugs/bug-1879.md new file mode 100644 index 00000000..b9f5fd3b --- /dev/null +++ b/.wolf/bugs/bug-1879.md @@ -0,0 +1,61 @@ +--- +id: "bug-1879" +status: "open" +status_updated: "2026-09-28" +status_note: "logged 2026-09-28; reproduced locally; fix not started" +component: "controller" +severity: "hang" +timestamp: "2026-09-28T07:11:39Z" +last_seen: "2026-09-28T07:11:39Z" +occurrences: 1 +files: ["src/controller/ha.c", "src/controller/myapp.c"] +tags: ["controller", "ha", "election", "cold-boot"] +related: ["bug-1876", "bug-606"] +--- + +# bug-1879: fresh HA cluster has no primary for ~10 s: first election lost, not retried until liveness timeout + +## Description +**Observed:** +``` +[14:47:32,960] ctrl-1 HA FSM: -> CTRL_ELECTING (async, n_peers=3) +[14:47:32,962] ctrl-1 HA FSM (raft): -> CTRL_STANDBY (term=1, first_boot=1) +[14:47:32,962] ctrl-1 myapp_run: CTRL_STANDBY — waiting for primary to connect and push config +[14:47:44,368] ctrl-1 WARN liveness_poll_fn: HA: liveness poll: no primary activity for 11s (timeout=10s) -> failover +[14:47:44,661] ctrl-1 HA FSM (raft): -> CTRL_PRIMARY (term=2, first_boot=0) +``` +(pc13v; locally ctrl-2/ctrl-3 log `ha_start_election_async: no local config (tag=0, n_peers=3) — participating as voter only`) +**Expected:** a fresh cluster elects its primary as soon as a quorum of nodes is up (about a second with start-all.sh's 0.5-1 s stagger). +**Impact:** every cold start of an HA cluster has no primary for about 10 s (the standby liveness timeout): no job submission, config push or scheduling in that window, a spurious failover WARN, and the cluster always starts at term 2. Also the cause of the 10 s of standby 'waiting for config' seen in bug-1876. +**Found by:** user reading ctrl-1's boot log and ctrlstatus (electedTerm 2) on pc13v after the bug-1872..1877 retest + +## Environment +- OS: no /etc/os-release; Docker container; NixOS kernel; kernel Linux 6.18.33 x86_64 +- libc: glibc 2.42-47 (interpreter /nix/store/wb6rhpznjfczwlwx23zmdrrw74bayxw4-glibc-2.42-47/lib/ld-linux-x86-64.so.2) +- Toolchain: gcc (GCC) 15.2.0, meson 1.9.1 +- Build: asan (xce.build) +- Code: scheduler-framework @ 44173f74 (controller unchanged since; pc13v ran 4c134127) +- Deployment: local 3-node HA (localhost:9991-9993, src/tools/deploy-ha.sh, nodes started 1 s apart by start-all.sh, xcecd_virtual) on this dev host; first seen on pc13v: NixOS 26.05, kernel 6.18.33, glibc 2.42-47, debug build, 3-node HA (ctrl-1..3, localhost:9901-9903) + scheduler + apiserver + real root xcecd, /tmp/xce-ha-deploy, 2026-09-28 14:47 +0800 + +## Reproduction +1. `/xce-deploy-ha` (fresh deploy; only ctrl-1 gets the cluster config) +2. `scripts/start-all.sh` (starts ctrl-1, ctrl-2, ctrl-3 about 1 s apart) +3. `grep -E 'CTRL_|liveness poll|voter only' logs/ctrl-*.log`: ctrl-1 goes CTRL_STANDBY within ~50 ms, ctrl-2/3 are voter-only, and the first primary appears ~10 s later at term 2 +- Frequency: 2/2 cold starts (pc13v 14:47 and the local run 07:10, 2026-09-28) +- Evidence: logs quoted above; the local deploy's logs were in /tmp/claude-1000/xce-deploy-coldboot/logs (not kept) + +## Root cause +Established from both runs: ctrl-1, the only node with a local config, starts its term-1 election before its peers are running, cannot reach a quorum, and drops to CTRL_STANDBY ("waiting for primary") within ~50 ms. ctrl-2 and ctrl-3 have no local config, so ha_start_election_async() makes them voters only -- they never stand. That is by design (confirmed by the user, 2026-09-28): on a cold boot only the node holding the initial configuration (ctrl-1) may become primary, so the retry has to come from ctrl-1. Nothing starts another election until ctrl-1's standby liveness poll (10 s) treats the missing primary as a failure and runs PreVote, which it then wins at once. + +Unconfirmed: why the lost first-boot election leaves ctrl-1 in CTRL_STANDBY with only the 10 s liveness poll as a retry, instead of retrying after a short (randomized) election timeout as Raft does for a candidate that fails to win -- to be read in ha.c's raft_cb_become_follower()/first_boot path and myapp_run(). + +## Fix +Proposed: when the config-holding node loses its first-boot election for lack of quorum, keep it a candidate and retry its own election after a short randomized election timeout (well under the 10 s standby liveness timeout) until it wins or another primary appears -- instead of settling into CTRL_STANDBY with only the liveness poll as a retry. Nodes without a config stay voters only. + +## Verification +- Test: TODO: name + file; RED before the fix, GREEN after +- Suites: TODO: suite results and build profile +- Live: TODO: soak/deploy run, or n/a and why + +## References +- Related: bug-1876 (the standby 'waiting for config' warnings this caused), bug-606 (PreVote staggering)