chore(buglog): bug-1890 fixed (8b561547); log bug-1891 (snapshot sent to the wrong standby)
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
This commit is contained in:
parent
8b561547dd
commit
5eb5cb8620
GPG key ID:
80533536B0EB651C
3 changed files with 108 additions and 14 deletions
|
|
@ -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"
|
||||
}
|
||||
]
|
||||
}
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
58
.wolf/bugs/bug-1891.md
Normal file
58
.wolf/bugs/bug-1891.md
Normal file
|
|
@ -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 <dir>`
|
||||
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
|
||||
Loading…
Add table
Add a link
Reference in a new issue