diff --git a/.claude/skills/xce-test-ha/run-ha-soak.sh b/.claude/skills/xce-test-ha/run-ha-soak.sh index 8dd55921..5491d2c3 100755 --- a/.claude/skills/xce-test-ha/run-ha-soak.sh +++ b/.claude/skills/xce-test-ha/run-ha-soak.sh @@ -1727,6 +1727,14 @@ run_force_snapshot_round() { # appears, the forcing mechanism did not work and the round proves # nothing — fail loud instead of reporting a false PASS. snap_log="$TOP/logs/$target.log" + # Poll rather than check once: 3-of-3 convergence (ctrlstatus) can be + # reported before the last snapshot chunks are read and installed -- a + # single grep right after convergence raced the install and failed + # spuriously (2026-09-27: 5 of 9 chunks read at check time). + for _i in $(seq 1 30); do + grep -q "HA: snapshot" "$snap_log" 2>/dev/null && break + sleep 1 + done if ! grep -q "HA: snapshot" "$snap_log" 2>/dev/null; then fail "force-snapshot: $target's log shows NO snapshot install (grep 'HA: snapshot' $snap_log) — the forced scenario did not actually exercise a checkpoint catch-up; this round proves nothing" fi diff --git a/.wolf/buglog.json b/.wolf/buglog.json index a541cecf..df7868cd 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -15906,9 +15906,9 @@ }, { "id": "bug-1433", - "status": "partial", - "status_updated": "2026-09-24", - "status_note": "fdatasync removed (40f510fb); pread in persist_apply_pump_run_sync still on become-leader path (ha.c)", + "status": "fixed", + "status_updated": "2026-09-27", + "status_note": "255b0faa: peer-control traffic while CTRL_ELECTING classified VTASK_LIVE_BLOCK (become-leader tail preads)", "timestamp": "2026-07-10T10:59:00Z", "error_message": "controller-invariant-audit (2026-07-10, /xce-audit-invariants) async-I/O-thread-role dimension: bug-1431 round-2 force-flush fix (persist_promotion_advance_committed calling flusher_flush_once, a blocking fdatasync) is reachable via the real multi-node winning-vote-reply dispatch path on a VTASK_LIVENESS-classified vtask worker -- a task class the design documents as never admission-gated / never expected to block. This is the same bug class as bug-1198 (HA_REPL_SEND_SNAPSHOT persist_checkpoint on VTASK_LIVENESS), which was previously closed by offloading the blocking work off that worker class entirely.", "file": "src/controller/persist.c, src/controller/ha.c", @@ -16415,9 +16415,9 @@ { "id": "bug-1450", "gitea_synced_status": "partial", - "status": "partial", - "status_updated": "2026-09-24", - "status_note": "slow-lane offload exists (f88e4ef4) but flag defaults OFF (ha_convergence.c)", + "status": "fixed", + "status_updated": "2026-09-27", + "status_note": "7aac018c: demotion-convergence offload ON by default; inline fallback when slow lane not started", "timestamp": "2026-07-18", "error_message": "xce-audit-invariants controller pass (dim: async I/O thread-role) found ha_demotion_convergence_fn scheduled directly as a delaymgr task body with no vtask/slow-lane hop: it truncates the WAL (persist_truncate_wal_above, file I/O under p->lock) then calls ha_self_restart (tlog_exit synchronous log flush + execv) -- all inline on the delaymgr thread, the SAME single thread that drives heartbeats and election timeouts cluster-wide for the whole cluster.", "file": "src/controller/ha_convergence.c, src/controller/ha.h", @@ -16447,9 +16447,9 @@ { "id": "bug-1451", "gitea_synced_status": "partial", - "status": "partial", - "status_updated": "2026-09-24", - "status_note": "slow-lane offload exists (f88e4ef4) but flag defaults OFF (config_repl.c)", + "status": "fixed", + "status_updated": "2026-09-27", + "status_note": "7aac018c: catch-up offload ON by default; inline fallback when slow lane not started", "timestamp": "2026-07-18", "error_message": "xce-audit-invariants controller pass (dim: async I/O thread-role) found ha_catchup_continuation_fn scheduled directly as a delaymgr task body with no vtask/slow-lane hop: catchup_stream_range -> ha_stream_wal_to_standby does blocking WAL file reads + socket writes to a standby directly on the delaymgr thread. Flagged as the MORE URGENT of the two violations -- catch-up can stream a variable, potentially large amount of WAL data, so it can block delaymgr (and therefore heartbeats to every OTHER peer) for an unbounded, unpredictable time, a real spurious-election risk.", "file": "src/controller/config_repl.c, src/controller/ha.h", @@ -16934,9 +16934,9 @@ }, { "id": "bug-1469", - "status": "partial", - "status_updated": "2026-09-24", - "status_note": "reorder fixed (959b0cda); queue added by upgrade still needs restart (build_queues only at boot)", + "status": "fixed", + "status_updated": "2026-09-27", + "status_note": "154a169f: reconcile_config_queues on activation creates added queues without restart", "timestamp": "2026-07-25T13:05:00Z", "error_message": "config-upgrade-snapshot task 8.6's live soak (--config-upgrade, run-ha-soak.sh) FAILED on its first real run: after a config upgrade committed successfully and genuinely interleaved with a 3-round chaotic kill/restart sequence (all 6 jobs survived, upgrade confirmed committed), the post-convergence materialized-state identity check failed -- snapdiff reported ctrl-1's latest checkpoint (snap-000000000000000b.capnp, LSN 11) as 51569 bytes vs ctrl-2/ctrl-3's identical 51621-byte file. This is a live, empirical reproduction of bug-857's originally-hypothesized failure mode (config upgrade leaves members with divergent materialized state), which bug-857's own buglog entry explicitly flagged as 'NOT empirically reproduced yet' and task 8.5 could only address at the unit level (test_bug857_regression.c, a DIFFERENT and already-fixed mechanism -- schedule_checkpoint's WAL-threshold trigger racing the marker boundary). This is a third, distinct mechanism, first observed here.", "file": "src/controller/config_repl.c do_upgrade_config_with_bytes (~1611-1770)", @@ -17089,9 +17089,9 @@ }, { "id": "bug-1474", - "status": "partial", - "status_updated": "2026-09-24", - "status_note": "slot hardening c0b0c7d1; spurious duplicate reconnect (angle a) re-observed live 2026-09-16", + "status": "fixed", + "status_updated": "2026-09-27", + "status_note": "c3a17b19: root cause of angle (a) -- standby_endpoints loops bounded by count skipped entries past zarray_del holes (lost heartbeats, spurious re-dial); now scan caps", "timestamp": "2026-07-25T20:50:00Z", "error_message": "config-upgrade-snapshot task 8.9's new live --config-upgrade-wal-trim soak (run-ha-soak.sh, run_config_upgrade_wal_trim_round): the marker-triggered checkpoint's WAL-segment trim (persist_checkpoint_marker_triggered -> trim_wal_segments -> repl_trim_lsn, bug-1147's guard) strands a genuinely mid-catch-up standby's still-needed WAL segment -- but NOT because bug-1147's guard logic itself is wrong. Reproduced identically on 2/2 independent live 3-node runs: a killed, still-down standby's disconnect-guard (last_disconnected_lsn) is silently DESTROYED before the trim ever runs, because an UNRELATED, already-connected peer's redundant reconnect attempt reuses the dead standby's just-freed replicator slot.", "file": "src/controller/ha.c (primary_heartbeat_fn's 'reconnect to any peer missing from standby_endpoints' loop, ~9219-9253; on_standby_connected, ~8658-8708; raft_cb_become_leader's vote-ep promotion, ~1888-1921); src/controller/repl.c (repl_add_standby's first-empty-slot allocation, ~85-133, and its memset(s,0,...) which wipes last_disconnected_lsn on reuse)", @@ -24060,9 +24060,9 @@ }, { "id": "bug-1728", - "status": "open", - "status_updated": "2026-09-24", - "status_note": "spurious \"incorrect worker idx -1\" ERROR after worker-join commit timeout (cluster.c)", + "status": "fixed", + "status_updated": "2026-09-27", + "status_note": "33c4f28c: failed join barrier unbinds w->ep (was dangling); idx -1 teardown now WARN", "timestamp": "2026-08-28T10:25:14Z", "error_message": "Controller logs `ERROR [handle_endpoint_error] incorrect worker idx -1` in all 3 nodes of a live HA cluster (ctrl-1.log, ctrl-2.log, ctrl-3.log), always immediately after the same two-line sequence: `WARN [commit_submit] commit: WAIT deadline expired without commit (lsn=X committed_lsn=Y writable_lsn=1 timeout_ms=500)` then `WARN [handle_worker_join] handle_worker_join commit barrier failed for pc13v, rc -110`. All three occurrences in the sampled log correlate exactly with an in-progress PreVote/failover window (liveness poll timeout -> primary_ctrl_fd RDHUP -> PreVote begin, immediately preceding each ERROR).", "file": "src/controller/cluster.c (handle_endpoint_error, ~line 52-77); src/controller/worker.c or join.c (handle_worker_join, commit-barrier caller -- not yet located)", @@ -24443,9 +24443,9 @@ }, { "id": "bug-1741", - "status": "partial", - "status_updated": "2026-09-24", - "status_note": "rejoin resync recovers stuck jobs (165fc158); fire-and-forget finish notify still not retried", + "status": "fixed", + "status_updated": "2026-09-27", + "status_note": "0cad6850: OPCode_notifyAcked -- job start/finish/fail acknowledged after commit, resent until acked; FF fallback for old controllers", "timestamp": "2026-08-31T23:45:00Z", "error_message": "User-reported live deployment (/tmp/xce-ha-deploy, 3-node HA cluster + xcecd_virtual worker, build.dbg): after submitting a 50-element array job (jobsub -a 50 -c hostname) immediately following a fresh primary election, `xce_test`'s `joblist` shows array elements [6] through [12] (7 consecutive elements) permanently stuck in state RUN (FinishTime=0) while every other element (0-5, 13-49) correctly reached DONE with real FinishTimes, including elements submitted/dispatched both before and after the stuck range and well after the cluster had fully stabilized (up to ~46s post-submit). The user confirmed via repeated `joblist` checks over several minutes that elements 6-12 never progress -- not a transient lag.", "file": "src/worker/src/controller_connector.c (xcecd_job_finished), src/lib/client.c (xcecli_notify, xcecli_notify_jobfinish), src/lib/client_internal.h (XCECLI_FF_CALL), src/controller/job.c (on_job_finish, never invoked for the 6 lost reports), src/controller/cluster.c (do_notify/handle_notify)", @@ -28169,7 +28169,7 @@ "error_message": "xce-test-ha --force-snapshot FAIL: 'could not submit 110 jobs to trigger a checkpoint' -- writes stall right after the first max-wal-records checkpoint. The primary's WAL holds a CHECKPOINT entry (plen 0) at the checkpoint LSN that no standby ever receives (primary ctrl-1: 109 JOB_SUBMIT, 110 CHECKPOINT, 111 JOB_SUBMIT; standbys stop at 109). Every later AppendEntries carries prevIdx=, standbys reply ae_reject_logmismatch, the primary marks catch-up and re-sends the last common entry forever: 'commit: async continuation deadline expired without commit', 'HA quorum lost: connected=0'.", "file": "src/controller/persist.c (checkpoint marker append), src/controller/repl.c / config_repl.c (broadcast / catch-up)", "root_cause": "Not yet root-caused. The checkpoint marker is appended to the local WAL (and consumes an LSN in the replicated log) without being broadcast to / streamed to standbys, so the log has a hole standbys can never fill. Reproduced on a565779d (baseline, 2026-09-26) and on the bug-1867 working tree -- independent of both. Repro: nix develop ./src --command bash .claude/skills/xce-test-ha/run-ha-soak.sh --force-snapshot (max-wal-records=100, wal-segment-bytes=4096).", - "fix": "", + "fix": "UPDATE (2026-09-27): follow-up cb1415d7: load_snapshot seeded current_lsn = checkpoint_lsn (off by one, hidden by the removed marker) -- broke --config-upgrade soak; fixed", "tags": [ "ha", "replication", @@ -28182,6 +28182,30 @@ "related_bugs": [], "occurrences": 1, "last_seen": "2026-09-26T09:55:09Z" + }, + { + "id": "bug-1871", + "status": "investigating", + "status_updated": "2026-09-27", + "status_note": "found while soak-verifying the HA group; logs in /home/claude/tmp/xce-ha-final-force-snapshot", + "timestamp": "2026-09-27T07:03:48Z", + "error_message": "HA snapshot transfer to a rejoining standby stalls mid-stream: primary queues all chunks at once (528KB, 9 chunks); the standby reads a few (1 or 5 of 9 in two runs), its endpoint is unblocked after the last processed chunk, and then no further input event arrives on that connection for 3s+ although the primary has more chunks queued -- --force-snapshot soak's single post-convergence check saw no install (2 of 4 runs, 2026-09-27)", + "file": "src/lib/netio.c (endpoint_block_tasks/unblock, handle_input), src/controller/ha.c ha_handle_snapshot_chunk", + "root_cause": "Not root-caused. Suspect: edge-triggered epoll input + per-endpoint task blocking (netio endpoint_block_tasks): data that arrives while the endpoint is blocked is not re-signalled after endpoint_unblock_tasks, so reading resumes only on the next write from the peer (e.g. the next heartbeat). Likely delays, not loses, the transfer; the soak check was changed to poll 30s.", + "fix": "", + "tags": [ + "netio", + "epoll", + "snapshot", + "latency", + "ha", + "soak" + ], + "related_bugs": [ + "bug-1870" + ], + "occurrences": 1, + "last_seen": "2026-09-27T07:03:48Z" } ] }