docs(buglog): bug-1922 fixed; bug-1917 follow-up; soak coverage for bug-1919/1920
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
This commit is contained in:
parent
5cf923350c
commit
8dab1f2065
GPG key ID:
80533536B0EB651C
5 changed files with 100 additions and 5 deletions
|
|
@ -17259,7 +17259,7 @@
|
|||
"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": "`xce_ctx_reconnect` (src/lib/xcectx.c) ran `endpoint_fini`/`endpoint_init` on `ctx->ep` straight away, while work dispatched for the old connection could still be running: the io_worker inside its epoll batch (it holds an endpoint reference for the whole batch: `SSL_read`/`handle_output` on the fd and SSL being freed), and VTASK_IO reply tasks still queued on the context's pool (each holds a reference and reads `ep->owner` without a lock). A queued reply task of the old connection that ran after the reconnect found `ep->owner` re-armed to the context and was delivered to the new session.",
|
||||
"fix": "`xce_ctx_reconnect` first calls `xce_ctx_quiesce_ep`: unmonitor the old fd (no further io_worker events), clear `ep->owner` under `ep->lock` (stale reply tasks are dropped; `vtask_entry` frees their packet), then wait until the endpoint's reference count is back at its base value (0 for the embedded client endpoint, 1 for a heap one), polling every 1 ms. The wait is bounded at 2000 ms: if the caller is itself a task of this endpoint its own reference never drains, and the reconnect then proceeds as before with a WARN (\"reconnecting anyway\") rather than deadlocking. `vtask_entry` now reads `ep->owner` under `ep->lock`.\n\nVerification:\n- Test: `test_reconnect_drains_old_connection_tasks` (new src/lib/testsuite/test_ctx_reconnect_quiesce.c): reconnect to a local listener, queue an old-connection packet via INVOKE_MSG_HANDLER -> handle_msg with the pool stopped, reconnect again while a helper starts the pool 100 ms in. RED before the fix (the stale task reached the context's request handler: expected 0 calls, was 1), GREEN and LSan-clean after.\n- Suites: `xce-build.sh all` asan, 127/127 meson suites OK, Go tests ok (2026-10-04).\n- Live: loaded `/xce-test-ha` sequential 30 rounds (40 busy loops on 32 cores), 2026-10-04: PASS, zero job loss, all 3 nodes led, no ASAN report in any controller/worker/scheduler log; client failover reconnects in worker/scheduler/xce_test throughout, and the quiesce never needed its timeout (no \"reconnecting anyway\" WARN).\n\nUPDATE (2026-10-05): Live observation (2026-10-05, bug-1736 E2E): the xce_test fake worker hit the bounded-wait path -- a vtask handler of its own connection timed out waiting for a reply queued behind it (-110), failed over through xce_ctx_reconnect, and the quiesce logged 'old connection still has 2 in-flight reference(s) after 2000 ms; reconnecting anyway' and proceeded, as designed; no crash or ASAN report.",
|
||||
"fix": "`xce_ctx_reconnect` first calls `xce_ctx_quiesce_ep`: unmonitor the old fd (no further io_worker events), clear `ep->owner` under `ep->lock` (stale reply tasks are dropped; `vtask_entry` frees their packet), then wait until the endpoint's reference count is back at its base value (0 for the embedded client endpoint, 1 for a heap one), polling every 1 ms. The wait is bounded at 2000 ms: if the caller is itself a task of this endpoint its own reference never drains, and the reconnect then proceeds as before with a WARN (\"reconnecting anyway\") rather than deadlocking. `vtask_entry` now reads `ep->owner` under `ep->lock`.\n\nUPDATE (2026-10-08): Follow-up (2026-10-08, f26a2d45): a reconnect made from inside a task of the endpoint it re-establishes no longer waits out the 2 s bound (vtaskmgr tracks the endpoint whose VTASK_IO task the thread runs; xce_ctx_quiesce_ep returns at once in that case), and old-connection tasks queued behind it can no longer reach the new session: each VTASK_IO task records ep->reconnect_gen when queued and vtask_entry drops a task with a stale generation.\n\nVerification:\n- Test: `test_reconnect_drains_old_connection_tasks` (new src/lib/testsuite/test_ctx_reconnect_quiesce.c): reconnect to a local listener, queue an old-connection packet via INVOKE_MSG_HANDLER -> handle_msg with the pool stopped, reconnect again while a helper starts the pool 100 ms in. RED before the fix (the stale task reached the context's request handler: expected 0 calls, was 1), GREEN and LSan-clean after.\n- Suites: `xce-build.sh all` asan, 127/127 meson suites OK, Go tests ok (2026-10-04).\n- Live: loaded `/xce-test-ha` sequential 30 rounds (40 busy loops on 32 cores), 2026-10-04: PASS, zero job loss, all 3 nodes led, no ASAN report in any controller/worker/scheduler log; client failover reconnects in worker/scheduler/xce_test throughout, and the quiesce never needed its timeout (no \"reconnecting anyway\" WARN).\n\nUPDATE (2026-10-05): Live observation (2026-10-05, bug-1736 E2E): the xce_test fake worker hit the bounded-wait path -- a vtask handler of its own connection timed out waiting for a reply queued behind it (-110), failed over through xce_ctx_reconnect, and the quiesce logged 'old connection still has 2 in-flight reference(s) after 2000 ms; reconnecting anyway' and proceeded, as designed; no crash or ASAN report.\n\nUPDATE (2026-10-08): Follow-up: test_reconnect_from_own_task_does_not_wait_or_leak (test_ctx_reconnect_quiesce.c) -- a reconnect from the endpoint's own task with a stale message queued behind it: RED before (took the full 2 s bound), GREEN after (under 500 ms, the queued stale message never reaches the handler), LSan clean; xce-build all asan 127/127 (2026-10-07).",
|
||||
"tags": [
|
||||
"race",
|
||||
"failover",
|
||||
|
|
@ -17270,7 +17270,8 @@
|
|||
"bug-1916"
|
||||
],
|
||||
"fix_commits": [
|
||||
"431a6d70"
|
||||
"431a6d70",
|
||||
"f26a2d45"
|
||||
],
|
||||
"record": ".wolf/bugs/bug-1917.md",
|
||||
"gitea_issue": 342,
|
||||
|
|
@ -17318,7 +17319,7 @@
|
|||
"error_message": "promotion fence never releases on a node that booted RECOVER_TRUNCATED, even after full catch-up\n\n**Observed:**\n```\n05:57:15,308 HA: promotion REFUSED (decision=1 ...) — recovery_truncated=1 durable_floor=360 cluster_hwm=360 peer_reachable=1; fencing + arming catch-up re-alert window, staying ALIVE\n05:57:15,308 HA: promotion FENCED + catch-up re-alert window armed (30000 ms) — recovery_truncated=1 durable_floor=360 < cluster HWM=360\n05:57:45,483 HA: promotion fence catch-up window elapsed but progress is possible (peer_reachable=0 durable_floor=375 baseline=360 HWM=360) — remaining fenced, catching up\n[xce-test-ha] FAIL: leadership-coverage: cluster did not reconverge before maneuver\n```\n`promotion_fence_timeout_fn` (src/controller/ha.c ~1546-1640) releases the fence only if `!truncated && !below_hwm && ...`, where `truncated = persist_recovery_truncated()` = `recovery_verdict == RECOVER_TRUNCATED` (persist.c:7005) — the BOOT-time recovery verdict, which never changes at runtime. So for a node that booted truncated the release branch is unreachable however far it catches up (here durable_floor 375 >= HWM 360). In the \"progress is possible\" branch the timer frees itself and returns WITHOUT re-arming, so the fence is never re-evaluated. `in_catch_up` stays 1, `ctrlstatus` reports `fenced: true` (ctrlstatus.c:193) forever, and `/xce-test-ha`'s `cluster_committed_converged` (a fenced member is not converged) never succeeds.\n\n**Expected:** once the fenced member has caught up to a committed-consistent state (durable floor >= the cluster HWM the fence was armed with, as a standby of the live primary), the fence is released (ha-commit-durability Req 2.6) and the node is promotable and reported converged; the re-check keeps running until that happens.\n**Impact:** a controller that was killed as primary, rebooted with a truncated WAL tail, and later attempted promotion stays fenced (non-promotable, `fenced: true`) until restarted, even though it is fully caught up: the cluster loses one promotion candidate (in a 3-node cluster, the next failover may then have only one eligible node), and soak convergence gates fail. No data loss (fail-safe direction).\n**Found by:** soak (`/xce-test-ha` sequential 20 rounds, validating bug-1915, 2026-10-04)",
|
||||
"file": "src/controller/ha.c, src/controller/persist.c, src/controller/ctrlstatus.c",
|
||||
"root_cause": "Two defects in `promotion_fence_timeout_fn` (src/controller/ha.c):\n1. The release branch requires `!persist_recovery_truncated()`, which read the boot-time `recovery_verdict` only. Nothing at runtime ever cleared it, so a member that booted RECOVER_TRUNCATED could never pass the release check, however far it caught up. The existing unit test `test_promotion_fence_released_on_catchup` hid this by writing `recovery_verdict = RECOVER_CLEAN` directly, which production never does.\n2. The \"progress is possible\" branch (peer reachable or durable floor advanced) freed the timer ctx without re-arming, citing \"existing catch-up machinery\" that would release the fence. No such path exists (the only other releases are the election gate, which itself refuses a truncated node, and `ha_evaluate_promotion_fence`, which has no production caller on this path). So once that branch ran, the fence was never re-evaluated.",
|
||||
"fix": "- `persist_t.recovery_truncation_healed` (src/include/persist.h): a runtime latch, reset by `persist_init`/`persist_recover`, set by the new `persist_mark_recovery_truncation_healed()`. `persist_recovery_truncated()` now returns `verdict == RECOVER_TRUNCATED && !healed`. `persist_recovery_verdict()` still returns the raw boot verdict for diagnostics.\n- `promotion_fence_timeout_fn`: if the member is truncated AND `durable_floor >= target_hwm` AND `durable_floor > baseline` (contiguous entries replicated from the live primary on top of the truncated log; a fenced member is never primary), mark the truncation healed and fall through to the release check. Without progress nothing proves the log matches the primary's, so the fence stays (conservative).\n- The \"progress is possible\" branch re-arms the timer with the SAME baseline and HWM, so re-evaluation continues until the release.\n\nVerification:\n- Test: `test_promotion_fence_truncated_boot_released_after_catchup` and `test_promotion_fence_rechecks_while_catching_up` (src/controller/testsuite/test_commit_durability.c) were RED before the fix (fence never released) and GREEN after; `test_promotion_fence_truncated_no_progress_stays_fenced` pins the conservative no-progress rule (GREEN before and after).\n- Suites: `xce-build.sh all` asan, 127/127 meson suites OK, Go tests ok (2026-10-04).\n- Live: 4x `/xce-test-ha` sequential 20 rounds, 2026-10-04. Run 2 hit the exact path: ctrl boot RECOVER_TRUNCATED → promotion REFUSED (durable_floor=323, HWM=323) → 30 s later \"recovery-truncated log healed by catch-up — durable_floor=338 (baseline=323)\" + \"promotion fence RELEASED\", and the soak PASSed (all 3 nodes led). Runs 1 and 4 PASS (path not hit). Run 3 FAILed on an unrelated replication catch-up stall (logged separately, no fence/truncation in that run).",
|
||||
"fix": "- `persist_t.recovery_truncation_healed` (src/include/persist.h): a runtime latch, reset by `persist_init`/`persist_recover`, set by the new `persist_mark_recovery_truncation_healed()`. `persist_recovery_truncated()` now returns `verdict == RECOVER_TRUNCATED && !healed`. `persist_recovery_verdict()` still returns the raw boot verdict for diagnostics.\n- `promotion_fence_timeout_fn`: if the member is truncated AND `durable_floor >= target_hwm` AND `durable_floor > baseline` (contiguous entries replicated from the live primary on top of the truncated log; a fenced member is never primary), mark the truncation healed and fall through to the release check. Without progress nothing proves the log matches the primary's, so the fence stays (conservative).\n- The \"progress is possible\" branch re-arms the timer with the SAME baseline and HWM, so re-evaluation continues until the release.\n\nVerification:\n- Test: `test_promotion_fence_truncated_boot_released_after_catchup` and `test_promotion_fence_rechecks_while_catching_up` (src/controller/testsuite/test_commit_durability.c) were RED before the fix (fence never released) and GREEN after; `test_promotion_fence_truncated_no_progress_stays_fenced` pins the conservative no-progress rule (GREEN before and after).\n- Suites: `xce-build.sh all` asan, 127/127 meson suites OK, Go tests ok (2026-10-04).\n- Live: 4x `/xce-test-ha` sequential 20 rounds, 2026-10-04. Run 2 hit the exact path: ctrl boot RECOVER_TRUNCATED → promotion REFUSED (durable_floor=323, HWM=323) → 30 s later \"recovery-truncated log healed by catch-up — durable_floor=338 (baseline=323)\" + \"promotion fence RELEASED\", and the soak PASSed (all 3 nodes led). Runs 1 and 4 PASS (path not hit). Run 3 FAILed on an unrelated replication catch-up stall (logged separately, no fence/truncation in that run).\n\nUPDATE (2026-10-08): Repeatable live coverage (2026-10-08, 5cf92335): run-ha-soak.sh --truncated-fence breaks ctrl-1's WAL tail CRC (RECOVER_TRUNCATED boot), makes it win an election (promotion REFUSED), and requires 'healed by catch-up' + 'promotion fence RELEASED' and then leadership: PASS -- refused on attempt 1, fence released after 30 s (the re-check window), healed ctrl-1 led at term 9, zero job loss.",
|
||||
"tags": [
|
||||
"ha",
|
||||
"fence",
|
||||
|
|
@ -17347,7 +17348,7 @@
|
|||
"error_message": "new primary's WAL catch-up stalls after log-mismatch NACK; standby never advances, commits stuck\n\n**Observed:**\n```\n# new primary ctrl-2 (term 21), its only reachable standby ctrl-1 (ctrl-3 killed):\n07:06:45,520 ctrl-2 HA repl: standby[0] lsn=323 < stream_ceiling_lsn=342 (committed_lsn=341) → stream WAL batches\n07:06:45,522 ctrl-2 ha_stream_wal_to_standby: streamed WAL [323+1..342] to standby\n07:06:45,520 ctrl-1 ha_consume_append_entries: leader_idx=-1 term=21 prevIdx=341 n=1 -> success=0 match=0 (ae_reject_logmismatch)\n07:06:45,523 ctrl-2 repl_ack_decode_and_dispatch: WAL NACK from standby lsn=342 success=0 — marking catch-up\n07:06:48,603 ctrl-2 HA repl: standby[0] lsn=340 < stream_ceiling_lsn=342 (committed_lsn=341) → stream WAL batches\n07:06:48,603 ctrl-2 ha_stream_wal_to_standby: streamed WAL [340+1..342] to standby\n07:06:48,602 ctrl-1 ha_consume_append_entries: leader_idx=-1 term=21 prevIdx=323 n=0 -> success=1 match=323 (nop heartbeat)\n... same pair every 3 s for >60 s; ctrl-1 never logs another walCatchupEntry ...\n07:07:47,044 ctrl-2 commit: WAIT deadline expired without commit (lsn=343 committed_lsn=341 writable_lsn=342 timeout_ms=500)\nworker: xcecli failover: cluster not ready after 21 attempts (last status=-10013)\n[xce-test-ha] FAIL: round 19: worker-resync job ...: worker never logged a fresh rejoin after the failover (pre=18 post=18)\n```\nAfter the term-21 election the standby's Raft log matched only to 323. The first catch-up stream reached ctrl-1 only as a single entry (prevIdx=341, n=1), which was rejected. The bug-1479 NACK backoff then set the standby's catch-up join position to 340 (one below the rejected index) instead of 323. From then on the primary \"streams [341..342]\" every heartbeat, yet ctrl-1 receives only nop heartbeats (no walCatchupEntry), so no further NACK arrives to walk the position back. ctrl-1 stays at 323, the 2-of-3 cluster cannot commit (committed_lsn stuck at 341), and every client request gets -10013 not ready.\n\n**Expected:** the primary walks its catch-up position back to the standby's real match index (323) and streams [324..], so the standby catches up and commits resume, as bug-1479 intended.\n**Impact:** after a failover, the new primary is unavailable (no commits, clients get not-ready) for as long as the only other live member stays stalled. Observed for >60 s, unresolved until the soak tore the cluster down.\n**Found by:** soak (`/xce-test-ha` sequential 20 rounds, validating bug-1919, 2026-10-04)",
|
||||
"file": "src/controller/ha.c, src/controller/config_repl.c, src/controller/repl.c",
|
||||
"root_cause": "Three layers; the first is the defect, the other two let it turn into a stall:\n1. **Pre-recovery WAL writes corrupt the segment layout.** A restarted standby accepts the primary's connection during its startup delay, before `cluster_init_phase2`/`persist_recover` runs (bug-849's \"phase2 before cluster_run accepts replication\" does not hold: ctrl-2 got the primary hello at 07:05:47.806, phase2 ran at 07:05:48.18). In that window the primary streams catch-up from the advertised `applied_lsn=0`, and `persist_wal_write_replicated` wrote into the un-recovered `persist_t` (`current_lsn=1`, no open segment): `open_new_segment` O_TRUNC'd the existing `seg-0000000000000001.wal` and rewrote LSNs 1..234 into it. `persist_recover` then set `current_lsn=306` but left that fd open as the append segment, so LSNs 306..348 were filed under `seg-...0001`. Found on disk: ctrl-2's seg-1 = 1..234 then 306..348; no `seg-...0132`. The bug-1416 `recovery_complete` gate already closed this window for apply, but not for WAL writes.\n2. **The catch-up streamer silently sends nothing.** `ha_stream_wal_to_standby` orders segments by filename start LSN and skips any segment whose successor starts at or below the standby's position, so it skipped seg-1 and found no entry above 305. It still logged \"streamed WAL [..] to standby\" with zero entries sent.\n3. **The catch-up start position runs above the standby's log.** After a log-mismatch NACK (prevIdx=341), `ha_raft_on_repl_nack` set the join position to next_index-1 = 340, and `ha_dispatch_repl_action_for_standby` let it override the standby's own report (323). From 340, even a correct stream needs one rejected round per heartbeat to walk back 17 entries.\n\nScan of the four 2026-10-04 soaks: 3 nodes in 2 runs had a misfiled seg-1. It stalls only when that node later becomes primary and a standby needs catch-up from the misfiled range.",
|
||||
"fix": "- `persist_wal_write_replicated` returns `-EBUSY` while `!persist_recovery_complete(p)` (the bug-1416 gate that myapp closes before any network traffic and that `persist_recover` reopens). This is the backstop for every replicated-write path.\n- `ha_apply_wal_catchup_entry` and `ha_handle_snapshot_chunk` drop replication traffic silently before recovery: no persist, no ACK, no NACK (a NACK would walk the primary's next_index back past entries this node really holds). One INFO line per process.\n- `ha_dispatch_repl_action_for_standby` streams from min(join position, standby report): a lower join position (a bug-1479 conflicted suffix) still wins.\n- `ha_stream_wal_to_standby` WARNs \"found NO entries\" when a non-empty range yields nothing, and logs the entry count on success.\n\nVerification:\n- Test: `test_replicated_write_refused_before_recovery` (src/controller/testsuite/test_commit_durability.c: a pre-recovery replicated write leaves seg-1 intact and the first post-recovery append opens seg-<its LSN>), `test_intake_dropped_before_recovery` (test_term_safety_adapter.c: neither ACK nor NACK, nothing persisted), `test_dispatch_streams_from_min_of_join_and_report` (test_convergence_verification.c: streams from 323 rather than 340; a lower join position still wins). All three RED before the fix (write returned 0 / ACK sent / streamed from 340), GREEN after.\n- Suites: `xce-build.sh all` asan, 127/127 meson suites OK, Go tests ok (2026-10-04).\n- Live: 4x `/xce-test-ha` sequential 20 rounds, 2026-10-04: 4/4 PASS. The pre-recovery drop fired 14 times (3-5 per run), no \"found NO entries\" warning, and a scan of every node's WAL found every segment's first LSN equal to its filename with no LSN jumps. Before the fix, the same scan found misfiled seg-1 on 3 nodes in 2 of 4 runs. Longer runs, 2026-10-04: sequential 50 rounds PASS, chaotic 50 rounds PASS (zero committed divergence), sequential 30 rounds under 40 CPU spinners on 32 cores PASS. The drop fired 7/10/5 times, there was no \"found NO entries\" warning, the WAL layout was clean on every node, and there were no ASAN reports.",
|
||||
"fix": "- `persist_wal_write_replicated` returns `-EBUSY` while `!persist_recovery_complete(p)` (the bug-1416 gate that myapp closes before any network traffic and that `persist_recover` reopens). This is the backstop for every replicated-write path.\n- `ha_apply_wal_catchup_entry` and `ha_handle_snapshot_chunk` drop replication traffic silently before recovery: no persist, no ACK, no NACK (a NACK would walk the primary's next_index back past entries this node really holds). One INFO line per process.\n- `ha_dispatch_repl_action_for_standby` streams from min(join position, standby report): a lower join position (a bug-1479 conflicted suffix) still wins.\n- `ha_stream_wal_to_standby` WARNs \"found NO entries\" when a non-empty range yields nothing, and logs the entry count on success.\n\nVerification:\n- Test: `test_replicated_write_refused_before_recovery` (src/controller/testsuite/test_commit_durability.c: a pre-recovery replicated write leaves seg-1 intact and the first post-recovery append opens seg-<its LSN>), `test_intake_dropped_before_recovery` (test_term_safety_adapter.c: neither ACK nor NACK, nothing persisted), `test_dispatch_streams_from_min_of_join_and_report` (test_convergence_verification.c: streams from 323 rather than 340; a lower join position still wins). All three RED before the fix (write returned 0 / ACK sent / streamed from 340), GREEN after.\n- Suites: `xce-build.sh all` asan, 127/127 meson suites OK, Go tests ok (2026-10-04).\n- Live: 4x `/xce-test-ha` sequential 20 rounds, 2026-10-04: 4/4 PASS. The pre-recovery drop fired 14 times (3-5 per run), no \"found NO entries\" warning, and a scan of every node's WAL found every segment's first LSN equal to its filename with no LSN jumps. Before the fix, the same scan found misfiled seg-1 on 3 nodes in 2 of 4 runs. Longer runs, 2026-10-04: sequential 50 rounds PASS, chaotic 50 rounds PASS (zero committed divergence), sequential 30 rounds under 40 CPU spinners on 32 cores PASS. The drop fired 7/10/5 times, there was no \"found NO entries\" warning, the WAL layout was clean on every node, and there were no ASAN reports.\n\nUPDATE (2026-10-08): Permanent gate (2026-10-08, 5cf92335): the sequential, chaotic and truncated-fence soak modes now run wal-layout-check.py before PASS; it flags the pre-fix runs' misfiled seg-...0001 and passed a sequential 20-round soak (25 segments, 0 problems).",
|
||||
"tags": [
|
||||
"ha",
|
||||
"repl",
|
||||
|
|
@ -17394,6 +17395,33 @@
|
|||
"record": ".wolf/bugs/bug-1921.md",
|
||||
"gitea_issue": 345,
|
||||
"gitea_synced_status": "fixed"
|
||||
},
|
||||
{
|
||||
"id": "bug-1922",
|
||||
"status": "fixed",
|
||||
"status_updated": "2026-10-08",
|
||||
"status_note": "",
|
||||
"component": "harness",
|
||||
"severity": "wrong-result",
|
||||
"timestamp": "2026-10-08T02:32:58Z",
|
||||
"last_seen": "2026-10-08T02:32:58Z",
|
||||
"occurrences": 1,
|
||||
"error_message": "xce_test fake worker ignores jobStateQuery; each join waits out the 15 s reconciliation timeout\n\n**Observed:**\n```\ncontroller, after an xce_test fake worker joins:\n WARN resync_on_timeout: resync: worker fakew5 reconciliation round 1 timed out after 15000ms -- resolving so dispatch is not withheld indefinitely (Req 5.3 ...\n```\nOn every worker join the controller sends `OPCode_jobStateQuery` (worker-rejoin-resync) and withholds dispatch to that worker until the `OPCode_jobStateReport` answer arrives. `xce_test`'s worker context has no case for `OPCode_jobStateQuery` in its request switch, so it never answers and the controller resolves the round only by its 15 s timeout.\n\n**Expected:** the fake worker answers the query like xcecd does (xcecd_resync.c): every queried job ID once, in order -- running if it is running one of its jobs, otherwise unrecognized -- plus an entry for each running job that was not queried.\n**Impact:** harness only: every fake-worker join (and re-join, bug-1921) delays dispatch to that worker by 15 s, and the reconciliation never sees the jobs the fake worker is really running, so the controller's resync logic is untested with fake workers.\n**Found by:** test (bug-1921 live verification, 2026-10-06)",
|
||||
"file": "src/harness/test.c",
|
||||
"root_cause": "`xce_test`'s worker-context request switch (`handle_startjob`/`handle_notify`/`handle_jobcontrol`/`handle_runtasks` in src/harness/test.c) had no case for `OPCode_jobStateQuery`, the worker-rejoin-resync query the controller sends on every worker join. The query was silently ignored, so the controller could only resolve its reconciliation round by the 15 s timeout (Req 5.3), withholding dispatch to the fake worker until then.",
|
||||
"fix": "- New `src/harness/fake_resync.{c,h}`: `fr_add_page` reassembles a paginated query (an empty query is one complete page; a page that overflows the announced total resets the accumulator); `fr_build_report` builds the report entries like xcecd's `xcecd_resync_build_report` -- every queried ID once, in order, `running` when the fake worker runs it, otherwise `unrecognized`, then each running job that was not queried (`queried = 0`). The fake worker keeps no finished-job retention, so a finished job is reported unrecognized.\n- `test.c`: `OPCode_jobStateQuery` -> `handle_jobstatequery`, which answers with `xce_job_state_report_req` (a non-blocking request with no reply to wait for, so it is safe in the handler context, unlike bug-1921's notifies).\n\nVerification:\n- Test: `test_fake_resync` (src/harness/testsuite/test_fake_resync.c, harness_unit_test): single-page and multi-page reassembly, empty query, overflowing page rejected, report = queried in order (running/unrecognized) + unqueried running extras. RED before (module absent: link failure), GREEN after, LSan clean.\n- Suites: `xce-build.sh all` asan, 127/127 meson suites OK, Go tests ok (2026-10-07).\n- Live: single controller + scheduler + apiserver (`run-resource-verify.sh --keep-running`), 2026-10-08: an `xce_test` fake worker joined, a job was dispatched to it, and the worker joined again (a round is armed only for a host with non-terminal jobs): the worker printed `job state query answered: 1 job(s)` and the controller logged no reconciliation timeout for it (before the fix: 'reconciliation round 1 timed out after 15000ms').",
|
||||
"tags": [
|
||||
"harness",
|
||||
"worker",
|
||||
"resync"
|
||||
],
|
||||
"related_bugs": [
|
||||
"bug-1921"
|
||||
],
|
||||
"fix_commits": [
|
||||
"c06798b2"
|
||||
],
|
||||
"record": ".wolf/bugs/bug-1922.md"
|
||||
}
|
||||
]
|
||||
}
|
||||
|
|
|
|||
|
|
@ -11,7 +11,7 @@ occurrences: 1
|
|||
files: ["src/lib/xcectx.c", "src/lib/netio.c"]
|
||||
tags: ["race", "failover", "client", "ssl"]
|
||||
related: ["bug-1916"]
|
||||
fix_commits: ["431a6d70"]
|
||||
fix_commits: ["431a6d70", "f26a2d45"]
|
||||
gitea_issue: 342
|
||||
gitea_synced_status: "fixed"
|
||||
gitea_synced_hash: "a66ad5a922dd"
|
||||
|
|
@ -48,6 +48,8 @@ UPDATE (2026-10-03): Review of the bug-1916 fix (2026-10-03) adds a second hazar
|
|||
## Fix
|
||||
`xce_ctx_reconnect` first calls `xce_ctx_quiesce_ep`: unmonitor the old fd (no further io_worker events), clear `ep->owner` under `ep->lock` (stale reply tasks are dropped; `vtask_entry` frees their packet), then wait until the endpoint's reference count is back at its base value (0 for the embedded client endpoint, 1 for a heap one), polling every 1 ms. The wait is bounded at 2000 ms: if the caller is itself a task of this endpoint its own reference never drains, and the reconnect then proceeds as before with a WARN ("reconnecting anyway") rather than deadlocking. `vtask_entry` now reads `ep->owner` under `ep->lock`.
|
||||
|
||||
UPDATE (2026-10-08): Follow-up (2026-10-08, f26a2d45): a reconnect made from inside a task of the endpoint it re-establishes no longer waits out the 2 s bound (vtaskmgr tracks the endpoint whose VTASK_IO task the thread runs; xce_ctx_quiesce_ep returns at once in that case), and old-connection tasks queued behind it can no longer reach the new session: each VTASK_IO task records ep->reconnect_gen when queued and vtask_entry drops a task with a stale generation.
|
||||
|
||||
## Verification
|
||||
- Test: `test_reconnect_drains_old_connection_tasks` (new src/lib/testsuite/test_ctx_reconnect_quiesce.c): reconnect to a local listener, queue an old-connection packet via INVOKE_MSG_HANDLER -> handle_msg with the pool stopped, reconnect again while a helper starts the pool 100 ms in. RED before the fix (the stale task reached the context's request handler: expected 0 calls, was 1), GREEN and LSan-clean after.
|
||||
- Suites: `xce-build.sh all` asan, 127/127 meson suites OK, Go tests ok (2026-10-04).
|
||||
|
|
@ -55,5 +57,7 @@ UPDATE (2026-10-03): Review of the bug-1916 fix (2026-10-03) adds a second hazar
|
|||
|
||||
UPDATE (2026-10-05): Live observation (2026-10-05, bug-1736 E2E): the xce_test fake worker hit the bounded-wait path -- a vtask handler of its own connection timed out waiting for a reply queued behind it (-110), failed over through xce_ctx_reconnect, and the quiesce logged 'old connection still has 2 in-flight reference(s) after 2000 ms; reconnecting anyway' and proceeded, as designed; no crash or ASAN report.
|
||||
|
||||
UPDATE (2026-10-08): Follow-up: test_reconnect_from_own_task_does_not_wait_or_leak (test_ctx_reconnect_quiesce.c) -- a reconnect from the endpoint's own task with a stale message queued behind it: RED before (took the full 2 s bound), GREEN after (under 500 ms, the queued stale message never reaches the handler), LSan clean; xce-build all asan 127/127 (2026-10-07).
|
||||
|
||||
## References
|
||||
- Related: none
|
||||
|
|
|
|||
|
|
@ -63,5 +63,7 @@ Two defects in `promotion_fence_timeout_fn` (src/controller/ha.c):
|
|||
- Suites: `xce-build.sh all` asan, 127/127 meson suites OK, Go tests ok (2026-10-04).
|
||||
- Live: 4x `/xce-test-ha` sequential 20 rounds, 2026-10-04. Run 2 hit the exact path: ctrl boot RECOVER_TRUNCATED → promotion REFUSED (durable_floor=323, HWM=323) → 30 s later "recovery-truncated log healed by catch-up — durable_floor=338 (baseline=323)" + "promotion fence RELEASED", and the soak PASSed (all 3 nodes led). Runs 1 and 4 PASS (path not hit). Run 3 FAILed on an unrelated replication catch-up stall (logged separately, no fence/truncation in that run).
|
||||
|
||||
UPDATE (2026-10-08): Repeatable live coverage (2026-10-08, 5cf92335): run-ha-soak.sh --truncated-fence breaks ctrl-1's WAL tail CRC (RECOVER_TRUNCATED boot), makes it win an election (promotion REFUSED), and requires 'healed by catch-up' + 'promotion fence RELEASED' and then leadership: PASS -- refused on attempt 1, fence released after 30 s (the re-check window), healed ctrl-1 led at term 9, zero job loss.
|
||||
|
||||
## References
|
||||
- Related: none
|
||||
|
|
|
|||
|
|
@ -75,5 +75,7 @@ Scan of the four 2026-10-04 soaks: 3 nodes in 2 runs had a misfiled seg-1. It st
|
|||
- Suites: `xce-build.sh all` asan, 127/127 meson suites OK, Go tests ok (2026-10-04).
|
||||
- Live: 4x `/xce-test-ha` sequential 20 rounds, 2026-10-04: 4/4 PASS. The pre-recovery drop fired 14 times (3-5 per run), no "found NO entries" warning, and a scan of every node's WAL found every segment's first LSN equal to its filename with no LSN jumps. Before the fix, the same scan found misfiled seg-1 on 3 nodes in 2 of 4 runs. Longer runs, 2026-10-04: sequential 50 rounds PASS, chaotic 50 rounds PASS (zero committed divergence), sequential 30 rounds under 40 CPU spinners on 32 cores PASS. The drop fired 7/10/5 times, there was no "found NO entries" warning, the WAL layout was clean on every node, and there were no ASAN reports.
|
||||
|
||||
UPDATE (2026-10-08): Permanent gate (2026-10-08, 5cf92335): the sequential, chaotic and truncated-fence soak modes now run wal-layout-check.py before PASS; it flags the pre-fix runs' misfiled seg-...0001 and passed a sequential 20-round soak (25 segments, 0 problems).
|
||||
|
||||
## References
|
||||
- Related: none
|
||||
|
|
|
|||
59
.wolf/bugs/bug-1922.md
Normal file
59
.wolf/bugs/bug-1922.md
Normal file
|
|
@ -0,0 +1,59 @@
|
|||
---
|
||||
id: "bug-1922"
|
||||
status: "fixed"
|
||||
status_updated: "2026-10-08"
|
||||
status_note: ""
|
||||
component: "harness"
|
||||
severity: "wrong-result"
|
||||
timestamp: "2026-10-08T02:32:58Z"
|
||||
last_seen: "2026-10-08T02:32:58Z"
|
||||
occurrences: 1
|
||||
files: ["src/harness/test.c"]
|
||||
tags: ["harness", "worker", "resync"]
|
||||
related: ["bug-1921"]
|
||||
fix_commits: ["c06798b2"]
|
||||
---
|
||||
|
||||
# bug-1922: xce_test fake worker ignores jobStateQuery; each join waits out the 15 s reconciliation timeout
|
||||
|
||||
## Description
|
||||
**Observed:**
|
||||
```
|
||||
controller, after an xce_test fake worker joins:
|
||||
WARN resync_on_timeout: resync: worker fakew5 reconciliation round 1 timed out after 15000ms -- resolving so dispatch is not withheld indefinitely (Req 5.3 ...
|
||||
```
|
||||
On every worker join the controller sends `OPCode_jobStateQuery` (worker-rejoin-resync) and withholds dispatch to that worker until the `OPCode_jobStateReport` answer arrives. `xce_test`'s worker context has no case for `OPCode_jobStateQuery` in its request switch, so it never answers and the controller resolves the round only by its 15 s timeout.
|
||||
|
||||
**Expected:** the fake worker answers the query like xcecd does (xcecd_resync.c): every queried job ID once, in order -- running if it is running one of its jobs, otherwise unrecognized -- plus an entry for each running job that was not queried.
|
||||
**Impact:** harness only: every fake-worker join (and re-join, bug-1921) delays dispatch to that worker by 15 s, and the reconciliation never sees the jobs the fake worker is really running, so the controller's resync logic is untested with fake workers.
|
||||
**Found by:** test (bug-1921 live verification, 2026-10-06)
|
||||
|
||||
## 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 @ 6a42631b-dirty
|
||||
- Deployment: single controller + scheduler + apiserver (`run-resource-verify.sh --keep-running`), one `xce_test` fake worker
|
||||
|
||||
## Reproduction
|
||||
1. `bash .claude/skills/xce-test-resources/run-resource-verify.sh --keep-running --dir <D>`
|
||||
2. `printf 'set masters localhost:9991\nset myname fakew\nworker\njoin\n!sleep 30\nquit\n' | xce_test --norc`
|
||||
3. `<D>/logs/ctrl-1.log` shows "reconciliation round 1 timed out after 15000ms" for fakew ~15 s after the join.
|
||||
- Frequency: deterministic, every fake-worker join, 2026-10-06
|
||||
- Evidence: not kept (session scratchpad logs)
|
||||
|
||||
## Root cause
|
||||
`xce_test`'s worker-context request switch (`handle_startjob`/`handle_notify`/`handle_jobcontrol`/`handle_runtasks` in src/harness/test.c) had no case for `OPCode_jobStateQuery`, the worker-rejoin-resync query the controller sends on every worker join. The query was silently ignored, so the controller could only resolve its reconciliation round by the 15 s timeout (Req 5.3), withholding dispatch to the fake worker until then.
|
||||
|
||||
## Fix
|
||||
- New `src/harness/fake_resync.{c,h}`: `fr_add_page` reassembles a paginated query (an empty query is one complete page; a page that overflows the announced total resets the accumulator); `fr_build_report` builds the report entries like xcecd's `xcecd_resync_build_report` -- every queried ID once, in order, `running` when the fake worker runs it, otherwise `unrecognized`, then each running job that was not queried (`queried = 0`). The fake worker keeps no finished-job retention, so a finished job is reported unrecognized.
|
||||
- `test.c`: `OPCode_jobStateQuery` -> `handle_jobstatequery`, which answers with `xce_job_state_report_req` (a non-blocking request with no reply to wait for, so it is safe in the handler context, unlike bug-1921's notifies).
|
||||
|
||||
## Verification
|
||||
- Test: `test_fake_resync` (src/harness/testsuite/test_fake_resync.c, harness_unit_test): single-page and multi-page reassembly, empty query, overflowing page rejected, report = queried in order (running/unrecognized) + unqueried running extras. RED before (module absent: link failure), GREEN after, LSan clean.
|
||||
- Suites: `xce-build.sh all` asan, 127/127 meson suites OK, Go tests ok (2026-10-07).
|
||||
- Live: single controller + scheduler + apiserver (`run-resource-verify.sh --keep-running`), 2026-10-08: an `xce_test` fake worker joined, a job was dispatched to it, and the worker joined again (a round is armed only for a host with non-terminal jobs): the worker printed `job state query answered: 1 job(s)` and the controller logged no reconciliation timeout for it (before the fix: 'reconciliation round 1 timed out after 15000ms').
|
||||
|
||||
## References
|
||||
- Related: none
|
||||
Loading…
Add table
Add a link
Reference in a new issue