docs(buglog): bug-1913 and bug-1916 fixed; log bug-1915, bug-1917, bug-1918
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
This commit is contained in:
parent
0fb2e14cc7
commit
acf78f9a94
GPG key ID:
80533536B0EB651C
6 changed files with 346 additions and 12 deletions
|
|
@ -17126,9 +17126,9 @@
|
|||
},
|
||||
{
|
||||
"id": "bug-1913",
|
||||
"status": "open",
|
||||
"status": "fixed",
|
||||
"status_updated": "2026-10-03",
|
||||
"status_note": "newly logged",
|
||||
"status_note": "",
|
||||
"component": "controller",
|
||||
"severity": "wrong-result",
|
||||
"timestamp": "2026-10-03T14:18:58Z",
|
||||
|
|
@ -17136,8 +17136,8 @@
|
|||
"occurrences": 1,
|
||||
"error_message": "after a late-joiner election the primary cannot commit client writes for ~2 heartbeat cycles\n\n**Observed:**\n```\nrepl_broadcast: no standbys registered ... not replicated\n...\nWAL NACK from standby lsn=2 ... marking catch-up\nrepl_wait_majority_ack: timeout ... OP_upgradeConfig rejected (status=-110)\n```\nIn some elections the vote connections are not converted into standby channels (`raft_cb_become_leader`), so both standbys register later through `on_standby_connected` (ha.c ~9643-9660). `ha_arm_own_term_gate` (ha.c ~5178) has already appended the own-term WAL_NOOP (lsn 1) while no standby was registered (repl.c ~306-311), and `repl_add_standby` does not resend it. Catch-up then runs from the 3 s heartbeat, one action per standby per cycle (config push first, WAL stream on the next cycle), so `committed_lsn` stays 0 for ~6 s. Any client write in that window (e.g. `OP_upgradeConfig`) is NACKed by both standbys and fails with -ETIMEDOUT after the 500 ms majority wait.\n\n**Expected:** a newly elected primary commits its own-term no-op, and so accepts client writes, promptly after its standbys register, not two heartbeat cycles later.\n**Impact:** for ~6 s after such an election every client write is rejected with -110 (fail-loud, no data loss, no false success). Clients retry, but tests and operators see spurious failures right after failover (the root cause of bug-1485's versionTag=0 flake). A fix must respect the async-I/O rules (no blocking on the delaymgr/heartbeat path; streaming offloaded) in `.kiro/steering/ha-async-io.md`.\n**Found by:** test (root cause of bug-1485)",
|
||||
"file": "src/controller/ha.c, src/controller/repl.c, src/controller/config_repl.c",
|
||||
"root_cause": "TODO: required for fixed/partial",
|
||||
"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",
|
||||
"root_cause": "Nothing asked a late-registered standby for its state, so its catch-up waited for the heartbeat clock. `ha_arm_own_term_gate` (ha.c ~5180) appends the own-term no-op while no standby is registered; `repl_broadcast` drops it (repl.c:306-311) and `repl_add_standby` never resends it. `on_standby_connected` (ha.c ~9511-9690) sends only a ctrlhello (no reply) and sets `last_push_time = now`. Catch-up is driven solely by a heartbeat reply's state report → `repl_ack_decode_and_dispatch` (peer-control vtask) → `ha_dispatch_repl_action_for_standby` (ha.c:4455), one action per report (config push if the tag is behind, else WAL stream). A standby rejoining with tag 0 therefore got the config push on the next 3 s tick and the WAL stream carrying the no-op on the tick after: ~6 s with committed_lsn below the no-op and every client write NACKed. The config-before-WAL order is a pacing rule of the ha-repl-hardening design (\"no further decisions until the next state report confirms\"), not a correctness requirement. Why the vote connections were not promoted in the first place is tracked separately (bug-1915).",
|
||||
"fix": "Make the state report arrive sooner; the decision loop and its one-action-per-report pacing are unchanged. New `ha_send_catchup_probe()` (ha.c) sends the ordinary `xce_ha_heartbeat_req` (same fields, read the same way as `primary_heartbeat_fn`), only while `CTRL_PRIMARY`, encode + enqueue only (same non-blocking path as the ctrlhello and the delaymgr tick); a send failure is a WARN and the periodic tick stays the fallback. Triggers: (1) once at the end of `on_standby_connected` (iomgr connect callback, after `msg_handler` is set), which also arms `ha->catchup_kick_armed[peer]` (ha.h); (2) the accepted config-push-ACK branch of `repl_ack_decode_and_dispatch` (peer-control vtask) after a 1→0 CAS on the arm, so the WAL stream follows the config push at ~RTT while keeping config-before-WAL. The arm is cleared on the standby's disconnect (`standby_ep_err_handler_primary`) and on every `raft_cb_become_leader` / `raft_cb_become_follower`, so it never outlives its registration or leadership; at most two probes per connect. No new executor, opcode or protocol change; heartbeat interval unchanged; WAL streaming still runs only on the vtask.\n\nVerification:\n- Test: `src/controller/testsuite/test_late_joiner_catchup_kick.c` — `test_late_joiner_registration_probes_standby_state`, `test_config_ack_after_registration_reprobes_once`, `test_rejected_config_ack_does_not_probe` RED before the fix (Expected 1 Was 0), GREEN after; `test_step_down_clears_catchup_arm` RED with the become_follower clear removed (Expected 0 Was 1); guards for no-registration and non-primary.\n- Suites: controller 5/5 meson suites, main 1285/0 (asan); `xce-build.sh all --incremental` green (C tests 127/0, scheduler 16/0, xceadmin 373), 2026-10-03.\n- Live: `/xce-test-ha` sequential 20 rounds PASS (63 jobs, zero loss, all 3 led, SIMVERIFY 21/0); chaotic 6 rounds PASS (zero committed divergence/loss); sequential 8 rounds under 40 busy loops PASS (with the bug-1916 fix; earlier loaded runs aborted on bug-1916). In those soaks catch-up started 0-6 ms after each late standby registration and a restarted standby was fully caught up 46 ms after registering (was up to ~6 s). Proxy (wiped standby) before/after: WAL stream at +5.8 s → +18-60 ms. Live HA push tests 6/6 under load; promoted-vote elections commit the no-op in median 6 ms (max 16 ms). Observation, not a regression: after catch-up the decision loop re-streams already-acked ranges on later stale state reports (harmless; standby discards duplicates).",
|
||||
"tags": [
|
||||
"ha",
|
||||
"raft",
|
||||
|
|
@ -17147,7 +17147,9 @@
|
|||
"related_bugs": [
|
||||
"bug-1485"
|
||||
],
|
||||
"fix_commits": [],
|
||||
"fix_commits": [
|
||||
"2aefa939"
|
||||
],
|
||||
"record": ".wolf/bugs/bug-1913.md"
|
||||
},
|
||||
{
|
||||
|
|
@ -17176,6 +17178,113 @@
|
|||
],
|
||||
"fix_commits": [],
|
||||
"record": ".wolf/bugs/bug-1914.md"
|
||||
},
|
||||
{
|
||||
"id": "bug-1915",
|
||||
"status": "investigating",
|
||||
"status_updated": "2026-10-03",
|
||||
"status_note": "single log sample; reproduce under load and check election/term handling around elect_ctx replacement",
|
||||
"component": "controller",
|
||||
"severity": "wrong-result",
|
||||
"timestamp": "2026-10-03T16:10:25Z",
|
||||
"last_seen": "2026-10-03T16:10:25Z",
|
||||
"occurrences": 1,
|
||||
"error_message": "two PreVote wins in one election replace elect_ctx; term-2 leader then finds no vote eps to promote\n\n**Observed:**\nIn one primary log captured during the bug-1913 investigation (late-joiner election under 40-spinner CPU load), \"PreVote round WON\" appears twice (prospective terms 2 and 3). The second real election replaced `ha->elect_ctx`, and the term-2 `raft_cb_become_leader` then found no vote endpoints to promote into standby channels, so both standbys had to register later as late joiners (bug-1913). A term-2 leader was also logged after the term-3 election had started.\n\n**Expected:** one election round per prospective term; a node that becomes leader promotes the vote connections from the election that elected it (or the stale election cannot complete leadership).\n**Impact:** unconfirmed (single sample). It is the trigger for late-joiner elections (bug-1913, now mitigated by an immediate catch-up probe), and a leader logged for an older term after a newer election started needs a Raft-safety check (term monotonicity, which election's votes made it leader).\n**Found by:** test (bug-1913 investigation, 2026-10-03)",
|
||||
"file": "src/controller/ha.c",
|
||||
"root_cause": "TODO: required for fixed/partial",
|
||||
"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": [
|
||||
"ha",
|
||||
"raft",
|
||||
"election",
|
||||
"prevote"
|
||||
],
|
||||
"related_bugs": [
|
||||
"bug-1913"
|
||||
],
|
||||
"fix_commits": [],
|
||||
"record": ".wolf/bugs/bug-1915.md"
|
||||
},
|
||||
{
|
||||
"id": "bug-1916",
|
||||
"status": "fixed",
|
||||
"status_updated": "2026-10-03",
|
||||
"status_note": "",
|
||||
"component": "lib",
|
||||
"severity": "crash",
|
||||
"timestamp": "2026-10-03T16:48:14Z",
|
||||
"last_seen": "2026-10-03T16:48:14Z",
|
||||
"occurrences": 1,
|
||||
"error_message": "ASAN heap-use-after-free in free_packet via endpoint_fini <- xce_ctx_reconnect on client failover\n\n**Observed:**\n```\n==729084==ERROR: AddressSanitizer: heap-use-after-free ... READ of size 8 ... thread T10\n #0 free_packet ../lib/netio.c:463\n #1 endpoint_fini ../lib/netio.c:1210\n #2 xce_ctx_reconnect ../lib/xcectx.c:366\n #3 xce_failover_rotate ../lib/client_failover.c:160\n #4 xcecli_retry_next ../lib/client_failover.c:388\n #5 xcecli_join ../lib/client.c:307\n #6 perform_pending_rejoin ../worker/src/controller_connector.c:442\nfreed by: xce_decode ../lib/request.c:284 <- vtask_entry ../lib/xcectx.c:139 (vtask thread)\nallocated by: handle_input ../lib/netio.c:479 <- io_handler (iomgr)\n```\nThe worker (`xcecd_virtual`, a libxce client) was rejoining after the primary was killed. It failed over to ctrl-2, which was still a standby and redirected the role-1 join to the dead old primary (`handle_join_ standby redirecting ... to localhost:9991`) and closed the endpoint. The client's failover rotation then ran `xce_ctx_reconnect` → `endpoint_fini` → `free_packet`, reading a packet that a vtask had already freed in `xce_decode` while decoding a reply on the same endpoint.\n\n**Expected:** client failover tears down the old endpoint only after (or without racing) in-flight decode vtasks, as the controller-side teardown does since bug-352/bug-1839 (deferred, per-endpoint FIFO teardown).\n**Impact:** crash of any libxce client (worker, scheduler, xce_test, apiserver backend) during controller failover when a reply decode races the failover rotation; the worker aborts, so its jobs' rejoin-resync never happens. Pre-existing client-library race, independent of bug-1913 (no controller code in the stack).\n**Found by:** soak (`/xce-test-ha` sequential, 8 rounds, under 40 busy loops on 32 cores, validating bug-1913)\n\nUPDATE (2026-10-03): Second loaded soak (2026-10-03, round 2): the same heap-use-after-free (free_packet <- endpoint_fini <- xce_ctx_reconnect <- xce_failover_rotate <- xcecli_join; freed by xce_decode on a vtask) hit BOTH the worker and the scheduler (scheduler.stderr), so every libxce client is exposed. Now 2/2 loaded soak runs. ASAN reports kept in the session scratchpad as uaf-worker-2.stderr / uaf-scheduler-2.stderr.",
|
||||
"file": "src/lib/netio.c, src/lib/xcectx.c, src/lib/client_failover.c, src/lib/request.c",
|
||||
"root_cause": "Packet handoff without detach. `vtask_handle_msg` (src/lib/vtaskmgr.c ~606) copied `ep->fsm_in.pkt` into the VTASK_IO task and published it with `vtask_enq`, but left `ep->fsm_in.pkt` set; `INVOKE_MSG_HANDLER` (src/include/netio.h:148-158) clears it only after the handler returns. In that window a vcpu ran xcectx `vtask_entry` → `xce_decode`, which frees the packet (request.c:283-284), then woke the client caller; the caller's `xcecli_join` → failover rotation → `xce_ctx_reconnect` → `endpoint_fini` freed the dangling slot again (netio.c:1210 → `free_packet` netio.c:463). The io_worker must be preempted between `vtask_enq` and its post-handler NULL store, which is why only heavily loaded soaks hit it. The controller's peer-control path already took the packet and cleared the slot first (bug-352 pattern); the shared `vtask_handle_msg` never did, and the vtaskmgr.h comment calling the client-path packet endpoint-owned was wrong.",
|
||||
"fix": "`vtask_handle_msg` sets `ep->fsm_in.pkt = NULL` before `vtask_enq` publishes the task and sets `task->owns_io_pkt = 1`, so the task is the packet's sole owner: a never-run task's packet is freed by `taskq_item_killer` at `vtaskmgr_fini`, and an enqueue failure frees packet, data and task (previously leaked). xcectx `vtask_entry` frees the packet on its early -EINVAL exits and NULLs `data->pkt` after `xce_decode`. Comments in vtaskmgr.h / vtaskmgr.c corrected. Both entries that receive such packets (xcectx `vtask_entry`, controller cluster.c `myreq_handler`) already consume them unconditionally via `xce_decode`. Fix commit 0fb2e14c. Remaining, separate: bug-1917 (reconnect vs io_worker race), bug-1918 (early-exit packet leak).\n\nVerification:\n- Test: `test_endpoint_fini_after_vtask_freed_pkt` in `src/lib/testsuite/test_vtask_pkt_handoff.c` — RED before the fix: ASAN heap-use-after-free in `free_packet` (netio.c:463) ← `endpoint_fini` (netio.c:1210), freed by `xce_decode` (request.c:284), the soak's exact stack (reviewer reproduced it again with only the NULL-before-enqueue line reverted); GREEN after. Companions `test_handoff_detaches_before_task_runs`, `test_handoff_rejects_incomplete_fsm`.\n- Suites: libxce 733/0; controller 5/5 (1285/0), worker 15/15, scheduler 97/97, harness 7/7 (asan); `xce-build.sh all --incremental` green, 2026-10-03.\n- Live: `/xce-test-ha` sequential 8 rounds under 40 busy loops on 32 cores PASS (30 jobs, zero loss, 8 worker-resync jobs reconciled) with no ASAN report in any process; the same soak aborted on this bug 2/2 before the fix.",
|
||||
"tags": [
|
||||
"asan",
|
||||
"uaf",
|
||||
"failover",
|
||||
"client",
|
||||
"worker"
|
||||
],
|
||||
"related_bugs": [
|
||||
"bug-352",
|
||||
"bug-610"
|
||||
],
|
||||
"fix_commits": [
|
||||
"0fb2e14c"
|
||||
],
|
||||
"record": ".wolf/bugs/bug-1916.md"
|
||||
},
|
||||
{
|
||||
"id": "bug-1917",
|
||||
"status": "investigating",
|
||||
"status_updated": "2026-10-03",
|
||||
"status_note": "code-review finding from bug-1916; watch loaded soaks for reconnect stacks without free_packet",
|
||||
"component": "lib",
|
||||
"severity": "crash",
|
||||
"timestamp": "2026-10-03T22:55:30Z",
|
||||
"last_seen": "2026-10-03T22:55:30Z",
|
||||
"occurrences": 1,
|
||||
"error_message": "xce_ctx_reconnect re-inits the endpoint on the caller thread while the io_worker may still use it\n\n**Observed:**\nNot yet observed as a crash -- found by code review while fixing bug-1916. `xce_ctx_reconnect` (src/lib/xcectx.c ~366) calls `endpoint_fini` / `endpoint_init` on the client's caller thread for an endpoint embedded in the context, while the io_worker may still be dispatching the same endpoint (still monitored). Exposed operations: the io_worker's post-handler store into `ep->fsm_in.pkt` and `endpoint_unref` (harmless after the bug-1916 fix), a concurrent `SSL_read` / `handle_error` on the old fd/SSL against `SSL_free` / `close`, and `fsm_out.pkt` freed while `handle_output` is writing it. `vtask_entry` also reads `ep->owner` without a lock while reconnect rewrites it.\n\n**Expected:** reconnect first unmonitors the old endpoint and waits for the io_worker to finish any in-flight dispatch on it (quiesce), then tears it down, as the controller side does with deferred per-endpoint teardown (bug-1839).\n**Impact:** potential use-after-free / crash in OpenSSL or `handle_output` stacks under `xce_ctx_reconnect` during client failover (worker, scheduler, xce_test, apiserver backend), most likely under heavy CPU load, like bug-1916.\n**Found by:** review (bug-1916 fix, 2026-10-03)\n\nUPDATE (2026-10-03): Review of the bug-1916 fix (2026-10-03) adds a second hazard: a reply task from the OLD connection still queued when xce_ctx_reconnect re-arms ep->owner can run against the NEW session (ep->owner read unsynchronised in xcectx.c vtask_entry ~134-135).",
|
||||
"file": "src/lib/xcectx.c, src/lib/netio.c",
|
||||
"root_cause": "TODO: required for fixed/partial",
|
||||
"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": [
|
||||
"race",
|
||||
"failover",
|
||||
"client",
|
||||
"ssl"
|
||||
],
|
||||
"related_bugs": [
|
||||
"bug-1916"
|
||||
],
|
||||
"fix_commits": [],
|
||||
"record": ".wolf/bugs/bug-1917.md"
|
||||
},
|
||||
{
|
||||
"id": "bug-1918",
|
||||
"status": "open",
|
||||
"status_updated": "2026-10-03",
|
||||
"status_note": "newly logged",
|
||||
"component": "lib",
|
||||
"severity": "leak",
|
||||
"timestamp": "2026-10-03T23:04:08Z",
|
||||
"last_seen": "2026-10-03T23:04:08Z",
|
||||
"occurrences": 1,
|
||||
"error_message": "handle_msg / vtask_handle_msg early -EINVAL/-ENOMEM exits leak the received packet\n\n**Observed:**\nNot yet observed at runtime -- found reviewing the bug-1916 fix. When `handle_msg` (src/lib/xcectx.c ~196-198, src/controller/cluster.c ~1371-1373) or `vtask_handle_msg` (src/lib/vtaskmgr.c ~617-629) returns early with -EINVAL/-ENOMEM, the received packet is still in `ep->fsm_in.pkt`; `INVOKE_MSG_HANDLER` (src/include/netio.h:148-158) then stores NULL into the slot without freeing it, so the packet leaks.\n\n**Expected:** on every early exit the packet is freed exactly once (either the handler frees it, or the slot keeps it and the endpoint teardown frees it).\n**Impact:** small per-message leak on rare error paths (allocation failure, missing context); pre-existing, not a crash.\n**Found by:** review (bug-1916 fix, 2026-10-03)",
|
||||
"file": "src/lib/xcectx.c, src/lib/vtaskmgr.c, src/controller/cluster.c",
|
||||
"root_cause": "TODO: required for fixed/partial",
|
||||
"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": [
|
||||
"leak",
|
||||
"vtask",
|
||||
"netio"
|
||||
],
|
||||
"related_bugs": [
|
||||
"bug-1916"
|
||||
],
|
||||
"fix_commits": [],
|
||||
"record": ".wolf/bugs/bug-1918.md"
|
||||
}
|
||||
]
|
||||
}
|
||||
|
|
|
|||
|
|
@ -1,8 +1,8 @@
|
|||
---
|
||||
id: "bug-1913"
|
||||
status: "open"
|
||||
status: "fixed"
|
||||
status_updated: "2026-10-03"
|
||||
status_note: "newly logged"
|
||||
status_note: ""
|
||||
component: "controller"
|
||||
severity: "wrong-result"
|
||||
timestamp: "2026-10-03T14:18:58Z"
|
||||
|
|
@ -11,6 +11,7 @@ occurrences: 1
|
|||
files: ["src/controller/ha.c", "src/controller/repl.c", "src/controller/config_repl.c"]
|
||||
tags: ["ha", "raft", "replication", "latency"]
|
||||
related: ["bug-1485"]
|
||||
fix_commits: ["2aefa939"]
|
||||
---
|
||||
|
||||
# bug-1913: after a late-joiner election the primary cannot commit client writes for ~2 heartbeat cycles
|
||||
|
|
@ -45,15 +46,15 @@ In some elections the vote connections are not converted into standby channels (
|
|||
- Evidence: not kept (scratchpad loop logs from the bug-1485 investigation).
|
||||
|
||||
## Root cause
|
||||
TODO: required for fixed/partial
|
||||
Nothing asked a late-registered standby for its state, so its catch-up waited for the heartbeat clock. `ha_arm_own_term_gate` (ha.c ~5180) appends the own-term no-op while no standby is registered; `repl_broadcast` drops it (repl.c:306-311) and `repl_add_standby` never resends it. `on_standby_connected` (ha.c ~9511-9690) sends only a ctrlhello (no reply) and sets `last_push_time = now`. Catch-up is driven solely by a heartbeat reply's state report → `repl_ack_decode_and_dispatch` (peer-control vtask) → `ha_dispatch_repl_action_for_standby` (ha.c:4455), one action per report (config push if the tag is behind, else WAL stream). A standby rejoining with tag 0 therefore got the config push on the next 3 s tick and the WAL stream carrying the no-op on the tick after: ~6 s with committed_lsn below the no-op and every client write NACKed. The config-before-WAL order is a pacing rule of the ha-repl-hardening design ("no further decisions until the next state report confirms"), not a correctness requirement. Why the vote connections were not promoted in the first place is tracked separately (bug-1915).
|
||||
|
||||
## Fix
|
||||
TODO: required for fixed/partial
|
||||
Make the state report arrive sooner; the decision loop and its one-action-per-report pacing are unchanged. New `ha_send_catchup_probe()` (ha.c) sends the ordinary `xce_ha_heartbeat_req` (same fields, read the same way as `primary_heartbeat_fn`), only while `CTRL_PRIMARY`, encode + enqueue only (same non-blocking path as the ctrlhello and the delaymgr tick); a send failure is a WARN and the periodic tick stays the fallback. Triggers: (1) once at the end of `on_standby_connected` (iomgr connect callback, after `msg_handler` is set), which also arms `ha->catchup_kick_armed[peer]` (ha.h); (2) the accepted config-push-ACK branch of `repl_ack_decode_and_dispatch` (peer-control vtask) after a 1→0 CAS on the arm, so the WAL stream follows the config push at ~RTT while keeping config-before-WAL. The arm is cleared on the standby's disconnect (`standby_ep_err_handler_primary`) and on every `raft_cb_become_leader` / `raft_cb_become_follower`, so it never outlives its registration or leadership; at most two probes per connect. No new executor, opcode or protocol change; heartbeat interval unchanged; WAL streaming still runs only on the vtask.
|
||||
|
||||
## 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
|
||||
- Test: `src/controller/testsuite/test_late_joiner_catchup_kick.c` — `test_late_joiner_registration_probes_standby_state`, `test_config_ack_after_registration_reprobes_once`, `test_rejected_config_ack_does_not_probe` RED before the fix (Expected 1 Was 0), GREEN after; `test_step_down_clears_catchup_arm` RED with the become_follower clear removed (Expected 0 Was 1); guards for no-registration and non-primary.
|
||||
- Suites: controller 5/5 meson suites, main 1285/0 (asan); `xce-build.sh all --incremental` green (C tests 127/0, scheduler 16/0, xceadmin 373), 2026-10-03.
|
||||
- Live: `/xce-test-ha` sequential 20 rounds PASS (63 jobs, zero loss, all 3 led, SIMVERIFY 21/0); chaotic 6 rounds PASS (zero committed divergence/loss); sequential 8 rounds under 40 busy loops PASS (with the bug-1916 fix; earlier loaded runs aborted on bug-1916). In those soaks catch-up started 0-6 ms after each late standby registration and a restarted standby was fully caught up 46 ms after registering (was up to ~6 s). Proxy (wiped standby) before/after: WAL stream at +5.8 s → +18-60 ms. Live HA push tests 6/6 under load; promoted-vote elections commit the no-op in median 6 ms (max 16 ms). Observation, not a regression: after catch-up the decision loop re-streams already-acked ranges on later stale state reports (harmless; standby discards duplicates).
|
||||
|
||||
## References
|
||||
- Related: none
|
||||
|
|
|
|||
52
.wolf/bugs/bug-1915.md
Normal file
52
.wolf/bugs/bug-1915.md
Normal file
|
|
@ -0,0 +1,52 @@
|
|||
---
|
||||
id: "bug-1915"
|
||||
status: "investigating"
|
||||
status_updated: "2026-10-03"
|
||||
status_note: "single log sample; reproduce under load and check election/term handling around elect_ctx replacement"
|
||||
component: "controller"
|
||||
severity: "wrong-result"
|
||||
timestamp: "2026-10-03T16:10:25Z"
|
||||
last_seen: "2026-10-03T16:10:25Z"
|
||||
occurrences: 1
|
||||
files: ["src/controller/ha.c"]
|
||||
tags: ["ha", "raft", "election", "prevote"]
|
||||
related: ["bug-1913"]
|
||||
---
|
||||
|
||||
# bug-1915: two PreVote wins in one election replace elect_ctx; term-2 leader then finds no vote eps to promote
|
||||
|
||||
## Description
|
||||
**Observed:**
|
||||
In one primary log captured during the bug-1913 investigation (late-joiner election under 40-spinner CPU load), "PreVote round WON" appears twice (prospective terms 2 and 3). The second real election replaced `ha->elect_ctx`, and the term-2 `raft_cb_become_leader` then found no vote endpoints to promote into standby channels, so both standbys had to register later as late joiners (bug-1913). A term-2 leader was also logged after the term-3 election had started.
|
||||
|
||||
**Expected:** one election round per prospective term; a node that becomes leader promotes the vote connections from the election that elected it (or the stale election cannot complete leadership).
|
||||
**Impact:** unconfirmed (single sample). It is the trigger for late-joiner elections (bug-1913, now mitigated by an immediate catch-up probe), and a leader logged for an older term after a newer election started needs a Raft-safety check (term monotonicity, which election's votes made it leader).
|
||||
**Found by:** test (bug-1913 investigation, 2026-10-03)
|
||||
|
||||
## 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 @ 6d9ef3d0-dirty
|
||||
- Deployment: local 3-node HA (xceadmin live HA fixture), 40 busy loops on 32 cores
|
||||
|
||||
## Reproduction
|
||||
1. Loop `src/xceadmin/tests/test_e2e_live_ha_push.py` under heavy CPU load with `XCE_KEEP_DEPLOY_DIR=1`.
|
||||
2. In the elected primary's log, look for two "PreVote round WON" lines in one election and a `raft_cb_become_leader` that promotes no vote endpoints.
|
||||
- Frequency: 1/40 runs, 2026-10-03 (single log sample under 40-spinner load; not yet reproduced deliberately)
|
||||
- Evidence: not kept (scratchpad loop logs from the bug-1913 investigation)
|
||||
|
||||
## Root cause
|
||||
TODO: required for fixed/partial
|
||||
|
||||
## 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: none
|
||||
68
.wolf/bugs/bug-1916.md
Normal file
68
.wolf/bugs/bug-1916.md
Normal file
|
|
@ -0,0 +1,68 @@
|
|||
---
|
||||
id: "bug-1916"
|
||||
status: "fixed"
|
||||
status_updated: "2026-10-03"
|
||||
status_note: ""
|
||||
component: "lib"
|
||||
severity: "crash"
|
||||
timestamp: "2026-10-03T16:48:14Z"
|
||||
last_seen: "2026-10-03T16:48:14Z"
|
||||
occurrences: 1
|
||||
files: ["src/lib/netio.c", "src/lib/xcectx.c", "src/lib/client_failover.c", "src/lib/request.c"]
|
||||
tags: ["asan", "uaf", "failover", "client", "worker"]
|
||||
related: ["bug-352", "bug-610"]
|
||||
fix_commits: ["0fb2e14c"]
|
||||
---
|
||||
|
||||
# bug-1916: ASAN heap-use-after-free in free_packet via endpoint_fini <- xce_ctx_reconnect on client failover
|
||||
|
||||
## Description
|
||||
**Observed:**
|
||||
```
|
||||
==729084==ERROR: AddressSanitizer: heap-use-after-free ... READ of size 8 ... thread T10
|
||||
#0 free_packet ../lib/netio.c:463
|
||||
#1 endpoint_fini ../lib/netio.c:1210
|
||||
#2 xce_ctx_reconnect ../lib/xcectx.c:366
|
||||
#3 xce_failover_rotate ../lib/client_failover.c:160
|
||||
#4 xcecli_retry_next ../lib/client_failover.c:388
|
||||
#5 xcecli_join ../lib/client.c:307
|
||||
#6 perform_pending_rejoin ../worker/src/controller_connector.c:442
|
||||
freed by: xce_decode ../lib/request.c:284 <- vtask_entry ../lib/xcectx.c:139 (vtask thread)
|
||||
allocated by: handle_input ../lib/netio.c:479 <- io_handler (iomgr)
|
||||
```
|
||||
The worker (`xcecd_virtual`, a libxce client) was rejoining after the primary was killed. It failed over to ctrl-2, which was still a standby and redirected the role-1 join to the dead old primary (`handle_join_ standby redirecting ... to localhost:9991`) and closed the endpoint. The client's failover rotation then ran `xce_ctx_reconnect` → `endpoint_fini` → `free_packet`, reading a packet that a vtask had already freed in `xce_decode` while decoding a reply on the same endpoint.
|
||||
|
||||
**Expected:** client failover tears down the old endpoint only after (or without racing) in-flight decode vtasks, as the controller-side teardown does since bug-352/bug-1839 (deferred, per-endpoint FIFO teardown).
|
||||
**Impact:** crash of any libxce client (worker, scheduler, xce_test, apiserver backend) during controller failover when a reply decode races the failover rotation; the worker aborts, so its jobs' rejoin-resync never happens. Pre-existing client-library race, independent of bug-1913 (no controller code in the stack).
|
||||
**Found by:** soak (`/xce-test-ha` sequential, 8 rounds, under 40 busy loops on 32 cores, validating bug-1913)
|
||||
|
||||
UPDATE (2026-10-03): Second loaded soak (2026-10-03, round 2): the same heap-use-after-free (free_packet <- endpoint_fini <- xce_ctx_reconnect <- xce_failover_rotate <- xcecli_join; freed by xce_decode on a vtask) hit BOTH the worker and the scheduler (scheduler.stderr), so every libxce client is exposed. Now 2/2 loaded soak runs. ASAN reports kept in the session scratchpad as uaf-worker-2.stderr / uaf-scheduler-2.stderr.
|
||||
|
||||
## 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 @ 6d9ef3d0-dirty
|
||||
- Deployment: local 3-node HA (`/xce-test-ha`), one `xcecd_virtual` worker + scheduler, 40 `yes` busy loops on 32 cores
|
||||
|
||||
## Reproduction
|
||||
1. Start 40 `yes >/dev/null` busy loops on a 32-core host.
|
||||
2. `XCE_HA_ROUNDS=8 nix develop ./src --command bash .claude/skills/xce-test-ha/run-ha-soak.sh 8 <scratch dir>`.
|
||||
3. Round 1 fails `worker never logged a fresh rejoin after the failover`; `logs/soak-worker.stderr` holds the ASAN report above. The slow election under load (new primary 7.4 s after the kill) leaves the worker failing over to a still-standby node that redirects and closes the endpoint.
|
||||
- Frequency: 2/2 runs, 2026-10-03 (loaded 8-round soaks; worker both times, scheduler once); 0 in unloaded 20-round sequential and 6-round chaotic soaks the same day
|
||||
- Evidence: ASAN report kept at the session scratchpad `uaf-worker.stderr`; deploy dir /home/claude/tmp/xce-ha-load-1913/logs (ctrl-*.log, xcecd-soak-worker.log)
|
||||
|
||||
## Root cause
|
||||
Packet handoff without detach. `vtask_handle_msg` (src/lib/vtaskmgr.c ~606) copied `ep->fsm_in.pkt` into the VTASK_IO task and published it with `vtask_enq`, but left `ep->fsm_in.pkt` set; `INVOKE_MSG_HANDLER` (src/include/netio.h:148-158) clears it only after the handler returns. In that window a vcpu ran xcectx `vtask_entry` → `xce_decode`, which frees the packet (request.c:283-284), then woke the client caller; the caller's `xcecli_join` → failover rotation → `xce_ctx_reconnect` → `endpoint_fini` freed the dangling slot again (netio.c:1210 → `free_packet` netio.c:463). The io_worker must be preempted between `vtask_enq` and its post-handler NULL store, which is why only heavily loaded soaks hit it. The controller's peer-control path already took the packet and cleared the slot first (bug-352 pattern); the shared `vtask_handle_msg` never did, and the vtaskmgr.h comment calling the client-path packet endpoint-owned was wrong.
|
||||
|
||||
## Fix
|
||||
`vtask_handle_msg` sets `ep->fsm_in.pkt = NULL` before `vtask_enq` publishes the task and sets `task->owns_io_pkt = 1`, so the task is the packet's sole owner: a never-run task's packet is freed by `taskq_item_killer` at `vtaskmgr_fini`, and an enqueue failure frees packet, data and task (previously leaked). xcectx `vtask_entry` frees the packet on its early -EINVAL exits and NULLs `data->pkt` after `xce_decode`. Comments in vtaskmgr.h / vtaskmgr.c corrected. Both entries that receive such packets (xcectx `vtask_entry`, controller cluster.c `myreq_handler`) already consume them unconditionally via `xce_decode`. Fix commit 0fb2e14c. Remaining, separate: bug-1917 (reconnect vs io_worker race), bug-1918 (early-exit packet leak).
|
||||
|
||||
## Verification
|
||||
- Test: `test_endpoint_fini_after_vtask_freed_pkt` in `src/lib/testsuite/test_vtask_pkt_handoff.c` — RED before the fix: ASAN heap-use-after-free in `free_packet` (netio.c:463) ← `endpoint_fini` (netio.c:1210), freed by `xce_decode` (request.c:284), the soak's exact stack (reviewer reproduced it again with only the NULL-before-enqueue line reverted); GREEN after. Companions `test_handoff_detaches_before_task_runs`, `test_handoff_rejects_incomplete_fsm`.
|
||||
- Suites: libxce 733/0; controller 5/5 (1285/0), worker 15/15, scheduler 97/97, harness 7/7 (asan); `xce-build.sh all --incremental` green, 2026-10-03.
|
||||
- Live: `/xce-test-ha` sequential 8 rounds under 40 busy loops on 32 cores PASS (30 jobs, zero loss, 8 worker-resync jobs reconciled) with no ASAN report in any process; the same soak aborted on this bug 2/2 before the fix.
|
||||
|
||||
## References
|
||||
- Related: none
|
||||
53
.wolf/bugs/bug-1917.md
Normal file
53
.wolf/bugs/bug-1917.md
Normal file
|
|
@ -0,0 +1,53 @@
|
|||
---
|
||||
id: "bug-1917"
|
||||
status: "investigating"
|
||||
status_updated: "2026-10-03"
|
||||
status_note: "code-review finding from bug-1916; watch loaded soaks for reconnect stacks without free_packet"
|
||||
component: "lib"
|
||||
severity: "crash"
|
||||
timestamp: "2026-10-03T22:55:30Z"
|
||||
last_seen: "2026-10-03T22:55:30Z"
|
||||
occurrences: 1
|
||||
files: ["src/lib/xcectx.c", "src/lib/netio.c"]
|
||||
tags: ["race", "failover", "client", "ssl"]
|
||||
related: ["bug-1916"]
|
||||
---
|
||||
|
||||
# bug-1917: xce_ctx_reconnect re-inits the endpoint on the caller thread while the io_worker may still use it
|
||||
|
||||
## Description
|
||||
**Observed:**
|
||||
Not yet observed as a crash -- found by code review while fixing bug-1916. `xce_ctx_reconnect` (src/lib/xcectx.c ~366) calls `endpoint_fini` / `endpoint_init` on the client's caller thread for an endpoint embedded in the context, while the io_worker may still be dispatching the same endpoint (still monitored). Exposed operations: the io_worker's post-handler store into `ep->fsm_in.pkt` and `endpoint_unref` (harmless after the bug-1916 fix), a concurrent `SSL_read` / `handle_error` on the old fd/SSL against `SSL_free` / `close`, and `fsm_out.pkt` freed while `handle_output` is writing it. `vtask_entry` also reads `ep->owner` without a lock while reconnect rewrites it.
|
||||
|
||||
**Expected:** reconnect first unmonitors the old endpoint and waits for the io_worker to finish any in-flight dispatch on it (quiesce), then tears it down, as the controller side does with deferred per-endpoint teardown (bug-1839).
|
||||
**Impact:** potential use-after-free / crash in OpenSSL or `handle_output` stacks under `xce_ctx_reconnect` during client failover (worker, scheduler, xce_test, apiserver backend), most likely under heavy CPU load, like bug-1916.
|
||||
**Found by:** review (bug-1916 fix, 2026-10-03)
|
||||
|
||||
UPDATE (2026-10-03): Review of the bug-1916 fix (2026-10-03) adds a second hazard: a reply task from the OLD connection still queued when xce_ctx_reconnect re-arms ep->owner can run against the NEW session (ep->owner read unsynchronised in xcectx.c vtask_entry ~134-135).
|
||||
|
||||
## 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 @ 6d9ef3d0-dirty
|
||||
- Deployment: any libxce client failing over during a controller failover (seen context: /xce-test-ha under 40 busy loops on 32 cores)
|
||||
|
||||
## Reproduction
|
||||
1. Not reproduced yet. Candidate: loaded `/xce-test-ha` soaks (40 busy loops on 32 cores) with the bug-1916 fix in place; look for ASAN reports with `xce_ctx_reconnect` in the stack but not `free_packet` (e.g. SSL_read/SSL_free or handle_output frames).
|
||||
- Frequency: 0/2 runs, 2026-10-03 (code-review finding; the 2 loaded soaks crashed on bug-1916 first)
|
||||
- Evidence: code reading of src/lib/xcectx.c xce_ctx_reconnect and src/lib/netio.c endpoint_fini / handle_input / handle_output
|
||||
|
||||
## Root cause
|
||||
TODO: required for fixed/partial
|
||||
|
||||
## 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: none
|
||||
51
.wolf/bugs/bug-1918.md
Normal file
51
.wolf/bugs/bug-1918.md
Normal file
|
|
@ -0,0 +1,51 @@
|
|||
---
|
||||
id: "bug-1918"
|
||||
status: "open"
|
||||
status_updated: "2026-10-03"
|
||||
status_note: "newly logged"
|
||||
component: "lib"
|
||||
severity: "leak"
|
||||
timestamp: "2026-10-03T23:04:08Z"
|
||||
last_seen: "2026-10-03T23:04:08Z"
|
||||
occurrences: 1
|
||||
files: ["src/lib/xcectx.c", "src/lib/vtaskmgr.c", "src/controller/cluster.c"]
|
||||
tags: ["leak", "vtask", "netio"]
|
||||
related: ["bug-1916"]
|
||||
---
|
||||
|
||||
# bug-1918: handle_msg / vtask_handle_msg early -EINVAL/-ENOMEM exits leak the received packet
|
||||
|
||||
## Description
|
||||
**Observed:**
|
||||
Not yet observed at runtime -- found reviewing the bug-1916 fix. When `handle_msg` (src/lib/xcectx.c ~196-198, src/controller/cluster.c ~1371-1373) or `vtask_handle_msg` (src/lib/vtaskmgr.c ~617-629) returns early with -EINVAL/-ENOMEM, the received packet is still in `ep->fsm_in.pkt`; `INVOKE_MSG_HANDLER` (src/include/netio.h:148-158) then stores NULL into the slot without freeing it, so the packet leaks.
|
||||
|
||||
**Expected:** on every early exit the packet is freed exactly once (either the handler frees it, or the slot keeps it and the endpoint teardown frees it).
|
||||
**Impact:** small per-message leak on rare error paths (allocation failure, missing context); pre-existing, not a crash.
|
||||
**Found by:** review (bug-1916 fix, 2026-10-03)
|
||||
|
||||
## 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 @ 6d9ef3d0-dirty
|
||||
- Deployment: any libxce client or the controller's client-request path
|
||||
|
||||
## Reproduction
|
||||
1. Not reproduced; force `vtask_handle_msg` to fail (e.g. allocation failure via a test hook) and check LeakSanitizer for the packet.
|
||||
- Frequency: 0/1 runs, 2026-10-03 (code-review finding)
|
||||
- Evidence: code reading of the cited lines
|
||||
|
||||
## Root cause
|
||||
TODO: required for fixed/partial
|
||||
|
||||
## 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: none
|
||||
Loading…
Add table
Add a link
Reference in a new issue