From 5eb5cb8620c3349038ebcff3382f61a615b0aab0 Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Tue, 29 Sep 2026 14:39:15 +0000 Subject: [PATCH] chore(buglog): bug-1890 fixed (8b561547); log bug-1891 (snapshot sent to the wrong standby) Co-Authored-By: Claude Opus 5.5 (1M context) --- .wolf/buglog.json | 43 ++++++++++++++++++++++++++----- .wolf/bugs/bug-1890.md | 21 +++++++++------ .wolf/bugs/bug-1891.md | 58 ++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 108 insertions(+), 14 deletions(-) create mode 100644 .wolf/bugs/bug-1891.md diff --git a/.wolf/buglog.json b/.wolf/buglog.json index bf81c8bb..716a3e56 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -16446,18 +16446,18 @@ }, { "id": "bug-1890", - "status": "open", + "status": "fixed", "status_updated": "2026-09-29", - "status_note": "newly logged", + "status_note": "", "component": "lib", "severity": "noise", "timestamp": "2026-09-29T14:01:08Z", "last_seen": "2026-09-29T14:01:08Z", "occurrences": 1, - "error_message": "netio sockets leave Nagle on: last TLS records of a message burst arrive ~40 ms late\n\n**Observed:** a 9-chunk HA snapshot transfer is fully written by the primary within 1 ms, but the standby reads the last chunks ~40 ms later. Primary trace (xce-1871-fs1, ctrl-1) shows the final send drained at 13:20:33.967 (`bug1871 upd ... 0x5->0x1 outq_empty=1 fsm_out=5`); the standby logs:\n```\n[2026-09-29 13:20:33,969] ... ha_handle_snapshot_chunk: chunk crc32 checkpoint_lsn=114 chunk_index=6 ...\n[2026-09-29 13:20:34,010] ... ha_handle_snapshot_chunk: chunk crc32 checkpoint_lsn=114 chunk_index=7 ...\n```\n\n**Expected:** on loopback the whole burst arrives within a few ms (most runs: max inter-chunk gap 1-4 ms).\n**Impact:** latency only, ~40 ms on the tail of a burst (snapshot/WAL batches, request-reply pairs after bulk data); no loss. `grep -rn TCP_NODELAY src/lib` finds nothing, so every netio TCP socket runs with Nagle, and a small trailing TLS record waits for the receiver's delayed ACK.\n**Found by:** soak -- bug-1871's instrumented force-snapshot runs, 2026-09-29. Suspected (not yet proven with TCP_NODELAY on): Nagle + delayed ACK.", + "error_message": "netio sockets leave Nagle on: last TLS records of a message burst arrive ~40 ms late\n\n**Observed:** a 9-chunk HA snapshot transfer is fully written by the primary within 1 ms, but the standby reads the last chunks ~40 ms later. Primary trace (xce-1871-fs1, ctrl-1) shows the final send drained at 13:20:33.967 (`bug1871 upd ... 0x5->0x1 outq_empty=1 fsm_out=5`); the standby logs:\n```\n[2026-09-29 13:20:33,969] ... ha_handle_snapshot_chunk: chunk crc32 checkpoint_lsn=114 chunk_index=6 ...\n[2026-09-29 13:20:34,010] ... ha_handle_snapshot_chunk: chunk crc32 checkpoint_lsn=114 chunk_index=7 ...\n```\n\n**Expected:** on loopback the whole burst arrives within a few ms (most runs: max inter-chunk gap 1-4 ms).\n**Impact:** latency only, ~40 ms on the tail of a burst (snapshot/WAL batches, request-reply pairs after bulk data); no loss. `grep -rn TCP_NODELAY src/lib` finds nothing, so every netio TCP socket runs with Nagle, and a small trailing TLS record waits for the receiver's delayed ACK.\n**Found by:** soak -- bug-1871's instrumented force-snapshot runs, 2026-09-29. Suspected (not yet proven with TCP_NODELAY on): Nagle + delayed ACK.\n\nUPDATE (2026-09-29): confirmed -- with TCP_NODELAY set the ~40 ms tail gaps disappear (see Verification), so the Nagle + delayed-ACK suspicion was right.", "file": "src/lib/netio.c (socket_create, socket_connect, endpoint_accept)", - "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": "netio never set TCP_NODELAY (socket_create() and socket_accept() in src/lib/netio.c set only SO_REUSEADDR/FD_CLOEXEC), so every controller/worker/scheduler/apiserver TCP connection ran with Nagle's algorithm. netio writes a message as separate TLS records (an 8-byte size header, then the body split into <=16 KB records); when a small record follows data the peer has not ACKed yet, Nagle holds it until the ACK arrives, and the receiver delays that ACK (Linux delayed ACK, ~40 ms). The tail of a burst -- the last short chunk of a snapshot, a header, a reply -- therefore arrived ~40 ms after the sender had finished writing.", + "fix": "src/lib/netio.c: new socket_set_nodelay() sets TCP_NODELAY; socket_create() calls it for AF_INET stream sockets (outbound endpoints from endpoint_init, and listeners) and socket_accept() for every accepted connection. Small records are sent immediately instead of waiting for the peer's delayed ACK. Best effort: a failure leaves the socket working as before.\n\nVerification:\n- Test: test_outbound_socket_has_nodelay and test_accepted_socket_has_nodelay in src/lib/testsuite/test_netio_nodelay.c check TCP_NODELAY on an endpoint_init socket and an endpoint_accept socket: RED before the fix (`bug-1890: outbound netio socket runs with Nagle on`, same for accepted), GREEN after\n- Suites: xcelib_test 699/699 and controller 1256/1256, asan, no sanitizer errors\n- Live: xce-test-ha --force-snapshot, 16 runs (2026-09-29, xce-1890-nd1..16): 40/40 snapshot transfers complete, max inter-chunk gap 4 ms, 0 gaps >= 20 ms -- versus 5/40 transfers with a 39-41 ms gap before the fix. 15/16 PASS; the one FAIL (nd5) is bug-1891 (snapshot sent to the wrong standby), unrelated to this change and seen before it", "tags": [ "netio", "tcp", @@ -16468,10 +16468,41 @@ "related_bugs": [ "bug-1871" ], - "fix_commits": [], + "fix_commits": [ + "8b561547" + ], "record": ".wolf/bugs/bug-1890.md", "gitea_issue": 336, "gitea_synced_status": "open" + }, + { + "id": "bug-1891", + "status": "open", + "status_updated": "2026-09-29", + "status_note": "newly logged", + "component": "controller", + "severity": "hang", + "timestamp": "2026-09-29T14:33:30Z", + "last_seen": "2026-09-29T14:33:30Z", + "occurrences": 1, + "error_message": "xce_controller primary sends a rejoining standby's snapshot to a different standby\n\n**Observed:** after a standby (ctrl-2) is killed, wiped and rejoins empty, the primary decides a snapshot is needed from ctrl-2's state but the transfer lands on the OTHER, already caught-up standby (ctrl-3). Primary (ctrl-1), xce-1890-nd5:\n```\n[2026-09-29 14:28:20,377] ... on_standby_connected] HA: repl registered late-joiner standby peer[1] (slot 2, localhost:9992)\n[2026-09-29 14:28:44,429] ... ha_process_standby_state] HA: standby[1] converged: config_tag=7302089038923290268 applied_lsn=114 (committed_tag=... committed_lsn=114)\n[2026-09-29 14:28:44,429] ... ha_dispatch_repl_action_for_standby] HA repl: standby[1] lsn=0 < oldest_wal_lsn=112 → requesting snapshot transfer\n[2026-09-29 14:28:44,437] ... ha_send_snapshot_to_standby: snapshot transfer start checkpoint_lsn=114 size=528825\n```\nEvery such transfer (14:28:41, :44, :47, :56) was received and installed by ctrl-3 (`HA: snapshot loaded lsn=114`, 7 installs); ctrl-2 received none. The same standby[1] alternates every heartbeat between `converged ... applied_lsn=114` (ctrl-2's pre-wipe position, or ctrl-3's) and `lsn=0 → requesting snapshot`, and each request is logged twice.\n\n**Expected:** the snapshot is sent on the rejoining standby's own connection, and its status reflects only that live connection.\n**Impact:** a wiped/rejoining standby never catches up while the misrouting persists; the other standby reinstalls the same snapshot every few seconds; ctrlstatus/soak convergence is reported from stale state (the soak printed `cluster reconverged (3-of-3)` and then failed `ctrl-2's log shows NO snapshot install`).\n**Found by:** soak -- xce-test-ha --force-snapshot while verifying bug-1890, 2026-09-29. Suspected: two repl slots for peer[1] after kill+rejoin (the late-joiner slot 2 plus the pre-kill slot, cf. bug-1819/bug-1474), with state read from one slot and the send going to an endpoint that belongs to another peer.", + "file": "src/controller/ha.c (ha_dispatch_repl_action_for_standby), src/controller/config_repl.c (ha_send_snapshot_to_standby)", + "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", + "snapshot", + "standby", + "repl", + "soak" + ], + "related_bugs": [ + "bug-1871", + "bug-1819", + "bug-1474" + ], + "fix_commits": [], + "record": ".wolf/bugs/bug-1891.md" } ] } diff --git a/.wolf/bugs/bug-1890.md b/.wolf/bugs/bug-1890.md index 2dea22d6..2496bcfc 100644 --- a/.wolf/bugs/bug-1890.md +++ b/.wolf/bugs/bug-1890.md @@ -1,8 +1,8 @@ --- id: "bug-1890" -status: "open" +status: "fixed" status_updated: "2026-09-29" -status_note: "newly logged" +status_note: "" component: "lib" severity: "noise" timestamp: "2026-09-29T14:01:08Z" @@ -11,6 +11,7 @@ occurrences: 1 files: ["src/lib/netio.c (socket_create, socket_connect, endpoint_accept)"] tags: ["netio", "tcp", "latency", "ha", "snapshot"] related: ["bug-1871"] +fix_commits: ["8b561547"] gitea_issue: 336 gitea_synced_status: "open" gitea_synced_hash: "f30c67d1bb31" @@ -29,6 +30,8 @@ gitea_synced_hash: "f30c67d1bb31" **Impact:** latency only, ~40 ms on the tail of a burst (snapshot/WAL batches, request-reply pairs after bulk data); no loss. `grep -rn TCP_NODELAY src/lib` finds nothing, so every netio TCP socket runs with Nagle, and a small trailing TLS record waits for the receiver's delayed ACK. **Found by:** soak -- bug-1871's instrumented force-snapshot runs, 2026-09-29. Suspected (not yet proven with TCP_NODELAY on): Nagle + delayed ACK. +UPDATE (2026-09-29): confirmed -- with TCP_NODELAY set the ~40 ms tail gaps disappear (see Verification), so the Nagle + delayed-ACK suspicion was right. + ## 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) @@ -44,15 +47,17 @@ gitea_synced_hash: "f30c67d1bb31" - Evidence: /home/claude/tmp/xce-1871-fs1, /home/claude/tmp/xce-1871-fs5, /home/claude/tmp/xce-1871-fs16 (ctrl-*.log) ## Root cause -TODO: required for fixed/partial +netio never set TCP_NODELAY (socket_create() and socket_accept() in src/lib/netio.c set only SO_REUSEADDR/FD_CLOEXEC), so every controller/worker/scheduler/apiserver TCP connection ran with Nagle's algorithm. netio writes a message as separate TLS records (an 8-byte size header, then the body split into <=16 KB records); when a small record follows data the peer has not ACKed yet, Nagle holds it until the ACK arrives, and the receiver delays that ACK (Linux delayed ACK, ~40 ms). The tail of a burst -- the last short chunk of a snapshot, a header, a reply -- therefore arrived ~40 ms after the sender had finished writing. ## Fix -TODO: required for fixed/partial +src/lib/netio.c: new socket_set_nodelay() sets TCP_NODELAY; socket_create() calls it for AF_INET stream sockets (outbound endpoints from endpoint_init, and listeners) and socket_accept() for every accepted connection. Small records are sent immediately instead of waiting for the peer's delayed ACK. Best effort: a failure leaves the socket working as before. ## 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: test_outbound_socket_has_nodelay and test_accepted_socket_has_nodelay in src/lib/testsuite/test_netio_nodelay.c check TCP_NODELAY on an endpoint_init socket and an endpoint_accept socket: RED before the fix (`bug-1890: outbound netio socket runs with Nagle on`, same for accepted), GREEN after +- Suites: xcelib_test 699/699 and controller 1256/1256, asan, no sanitizer errors +- Live: xce-test-ha --force-snapshot, 16 runs (2026-09-29, xce-1890-nd1..16): 40/40 snapshot transfers complete, max inter-chunk gap 4 ms, 0 gaps >= 20 ms -- versus 5/40 transfers with a 39-41 ms gap before the fix. 15/16 PASS; the one FAIL (nd5) is bug-1891 (snapshot sent to the wrong standby), unrelated to this change and seen before it ## References -- Related: none +- Fix commit: 8b561547 +- Related: bug-1871 (found while instrumenting it), bug-1891 +- Gitea: #336 diff --git a/.wolf/bugs/bug-1891.md b/.wolf/bugs/bug-1891.md new file mode 100644 index 00000000..798a69ac --- /dev/null +++ b/.wolf/bugs/bug-1891.md @@ -0,0 +1,58 @@ +--- +id: "bug-1891" +status: "open" +status_updated: "2026-09-29" +status_note: "newly logged" +component: "controller" +severity: "hang" +timestamp: "2026-09-29T14:33:30Z" +last_seen: "2026-09-29T14:33:30Z" +occurrences: 1 +files: ["src/controller/ha.c (ha_dispatch_repl_action_for_standby)", "src/controller/config_repl.c (ha_send_snapshot_to_standby)"] +tags: ["ha", "snapshot", "standby", "repl", "soak"] +related: ["bug-1871", "bug-1819", "bug-1474"] +--- + +# bug-1891: xce_controller primary sends a rejoining standby's snapshot to a different standby + +## Description +**Observed:** after a standby (ctrl-2) is killed, wiped and rejoins empty, the primary decides a snapshot is needed from ctrl-2's state but the transfer lands on the OTHER, already caught-up standby (ctrl-3). Primary (ctrl-1), xce-1890-nd5: +``` +[2026-09-29 14:28:20,377] ... on_standby_connected] HA: repl registered late-joiner standby peer[1] (slot 2, localhost:9992) +[2026-09-29 14:28:44,429] ... ha_process_standby_state] HA: standby[1] converged: config_tag=7302089038923290268 applied_lsn=114 (committed_tag=... committed_lsn=114) +[2026-09-29 14:28:44,429] ... ha_dispatch_repl_action_for_standby] HA repl: standby[1] lsn=0 < oldest_wal_lsn=112 → requesting snapshot transfer +[2026-09-29 14:28:44,437] ... ha_send_snapshot_to_standby: snapshot transfer start checkpoint_lsn=114 size=528825 +``` +Every such transfer (14:28:41, :44, :47, :56) was received and installed by ctrl-3 (`HA: snapshot loaded lsn=114`, 7 installs); ctrl-2 received none. The same standby[1] alternates every heartbeat between `converged ... applied_lsn=114` (ctrl-2's pre-wipe position, or ctrl-3's) and `lsn=0 → requesting snapshot`, and each request is logged twice. + +**Expected:** the snapshot is sent on the rejoining standby's own connection, and its status reflects only that live connection. +**Impact:** a wiped/rejoining standby never catches up while the misrouting persists; the other standby reinstalls the same snapshot every few seconds; ctrlstatus/soak convergence is reported from stale state (the soak printed `cluster reconverged (3-of-3)` and then failed `ctrl-2's log shows NO snapshot install`). +**Found by:** soak -- xce-test-ha --force-snapshot while verifying bug-1890, 2026-09-29. Suspected: two repl slots for peer[1] after kill+rejoin (the late-joiner slot 2 plus the pre-kill slot, cf. bug-1819/bug-1474), with state read from one slot and the send going to an endpoint that belongs to another peer. + +## 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 (src/xce.build.bug1871; netio TCP_NODELAY patch for bug-1890 applied, uncommitted) +- Code: scheduler-framework @ 3061df14-dirty +- Deployment: local 3-node HA controller cluster (xce-test-ha --force-snapshot), localhost:9991-9993, 32 CPUs + +## Reproduction +1. `nix develop ./src --command bash .claude/skills/xce-test-ha/run-ha-soak.sh --force-snapshot ` +2. Compare the primary's `snapshot transfer start` timestamps with `ha_handle_snapshot_chunk: chunk crc32 ... chunk_index=0` in each standby log: a transfer the primary started for the rejoining target that arrives on the other standby is the bug; the soak FAILs when none reach the target within its 30 s poll. +- Frequency: 1/9 runs failed outright (xce-1890-nd5), 2026-09-29; misrouted transfers also seen without failing in xce-1871-fs16 (13:36:18 and 13:36:48 went to ctrl-3 before the target got one at 13:36:51), i.e. pre-dates the bug-1871 and bug-1890 changes +- Evidence: /home/claude/tmp/xce-1890-nd5 (failing run, logs/ctrl-*.log, ../xce-1890-nd5.out), /home/claude/tmp/xce-1871-fs16 + +## 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