From 715c08f03b8eee26388d2aa491e686c00054bd39 Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Tue, 29 Sep 2026 14:01:48 +0000 Subject: [PATCH] chore(buglog): bug-1871 fixed (754d5bcf); log bug-1890 (Nagle tail latency) Co-Authored-By: Claude Opus 5.5 (1M context) --- .wolf/buglog.json | 51 ++++++++++++++++++++++++++++++--------- .wolf/bugs/bug-1871.md | 40 ++++++++++++++++++++++-------- .wolf/bugs/bug-1890.md | 55 ++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 125 insertions(+), 21 deletions(-) create mode 100644 .wolf/bugs/bug-1890.md diff --git a/.wolf/buglog.json b/.wolf/buglog.json index 0c31e457..0c77901a 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -15886,30 +15886,32 @@ }, { "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", + "status": "fixed", + "status_updated": "2026-09-29", + "status_note": "", "component": "lib", - "severity": "unknown", + "severity": "hang", "timestamp": "2026-09-27T07:03:48Z", "last_seen": "2026-09-27T07:03:48Z", "occurrences": 1, - "error_message": "HA snapshot transfer to a rejoining standby stalls mid-stream: primary queues all chunks at once…\n\nHA 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": "_Not recorded (migrated from buglog.json)._", + "error_message": "HA snapshot transfer to a rejoining standby stalls mid-stream: primary queues all chunks at once…\n\nHA 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)\n\nUPDATE (2026-09-29): Root-caused: the \"stall\" is the standby tearing the stream down. Receiver-side trace (fs16, ctrl-2): `bug1871 rd-block ep=0x7d1ff5c06440 fd=6 st=2 cnt=49304 err=1 errno=11` followed by `unmon ep=0x7d1ff5c06440 fd=6` -- a would-block read (EAGAIN) classified as SSL_ERROR_SSL, so the connection was dropped; the standby recovered only after `HA: liveness poll: no primary activity for 10s` and a reconnect, when a new transfer completed. The earlier \"edge-triggered epoll\" suspicion was wrong: netio registers level-triggered interest and the primary had written all 9 chunks (no write ever blocked).", + "file": "src/lib/netio.c (io_fsm_do, handle_ssl_handshake)", + "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.\n\nUPDATE (2026-09-29): OpenSSL error queues are per thread, and SSL_get_error() returns SSL_ERROR_SSL whenever the queue is non-empty, regardless of what the call being classified did. netio never cleared it. io_worker serves every endpoint from one thread, so when a ctrlstatus client closed its connection, OpenSSL 3 queued `unexpected eof while reading` on that thread (trace: `rd-block ... err=1 errno=0` for the client fd). The next SSL_read on the HA snapshot stream that merely found the socket drained mid-chunk (errno=11) was then reported as SSL_ERROR_SSL; io_classify_io_error() returned a negative error and handle_input() -> handle_error() unmonitored the endpoint. The primary kept the connection as healthy, the standby stopped reading, and the transfer resumed only after the standby's 10 s liveness failover reconnected. The handshake path was not affected in practice because the TLS state machine clears the queue itself; the application-data read path does not.", + "fix": "UPDATE (2026-09-29): src/lib/netio.c: ERR_clear_error() before each SSL_read/SSL_write in io_fsm_do() and before SSL_do_handshake() in handle_ssl_handshake(), so SSL_get_error() only reflects the call it classifies. A stale error from another connection can no longer turn a would-block into a teardown.\n\nVerification:\n- Test: test_stale_thread_error_does_not_kill_endpoint in src/lib/testsuite/test_netio_err_queue.c drives io_handler on an established TLS session whose read would block, with a stale SSL error on the thread queue: RED before the fix (`Expected 0 Was 1 ... reported as a connection error`), GREEN after; the sibling test_would_block_read_is_not_an_error (clean queue) passes both ways\n- Suites: xcelib_test 697/697 and controller 1256/1256, asan, no sanitizer errors\n- Live: xce-test-ha --force-snapshot, 16 runs with the fixed controller (2026-09-29): 16/16 PASS and 24/24 snapshot transfers complete (9 chunks + load), 0 truncated -- versus 3 truncated transfers in 16 runs before the fix on the same commit", "tags": [ "netio", - "epoll", + "openssl", + "tls", "snapshot", - "latency", "ha", "soak" ], "related_bugs": [ "bug-1870" ], - "fix_commits": [], + "fix_commits": [ + "754d5bcf" + ], "record": ".wolf/bugs/bug-1871.md", "gitea_issue": 297, "gitea_synced_status": "investigating" @@ -16441,6 +16443,33 @@ "9c51de88" ], "record": ".wolf/bugs/bug-1889.md" + }, + { + "id": "bug-1890", + "status": "open", + "status_updated": "2026-09-29", + "status_note": "newly logged", + "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.", + "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", + "tags": [ + "netio", + "tcp", + "latency", + "ha", + "snapshot" + ], + "related_bugs": [ + "bug-1871" + ], + "fix_commits": [], + "record": ".wolf/bugs/bug-1890.md" } ] } diff --git a/.wolf/bugs/bug-1871.md b/.wolf/bugs/bug-1871.md index 23e2e611..4d94720b 100644 --- a/.wolf/bugs/bug-1871.md +++ b/.wolf/bugs/bug-1871.md @@ -1,16 +1,17 @@ --- 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" +status: "fixed" +status_updated: "2026-09-29" +status_note: "" component: "lib" -severity: "unknown" +severity: "hang" timestamp: "2026-09-27T07:03:48Z" last_seen: "2026-09-27T07:03:48Z" occurrences: 1 -files: ["src/lib/netio.c (endpoint_block_tasks/unblock", "handle_input)", "src/controller/ha.c ha_handle_snapshot_chunk"] -tags: ["netio", "epoll", "snapshot", "latency", "ha", "soak"] +files: ["src/lib/netio.c (io_fsm_do, handle_ssl_handshake)"] +tags: ["netio", "openssl", "tls", "snapshot", "ha", "soak"] related: ["bug-1870"] +fix_commits: ["754d5bcf"] legacy: true gitea_issue: 297 gitea_synced_status: "investigating" @@ -22,21 +23,40 @@ gitea_synced_hash: "e0ba41ca7ee9" ## Description 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) +UPDATE (2026-09-29): Root-caused: the "stall" is the standby tearing the stream down. Receiver-side trace (fs16, ctrl-2): `bug1871 rd-block ep=0x7d1ff5c06440 fd=6 st=2 cnt=49304 err=1 errno=11` followed by `unmon ep=0x7d1ff5c06440 fd=6` -- a would-block read (EAGAIN) classified as SSL_ERROR_SSL, so the connection was dropped; the standby recovered only after `HA: liveness poll: no primary activity for 10s` and a reconnect, when a new transfer completed. The earlier "edge-triggered epoll" suspicion was wrong: netio registers level-triggered interest and the primary had written all 9 chunks (no write ever blocked). + ## Environment -_Not recorded (migrated from buglog.json)._ +UPDATE (2026-09-29): - 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; OpenSSL 3.6.0 +- Build: asan (src/xce.build.bug1871; netio TRACE instrumentation added for the repro only, not committed) +- Code: scheduler-framework @ 3444cf16 (repro), original sighting 154a169f-dirty (2026-09-27) +- Deployment: local 3-node HA controller cluster (xce-test-ha --force-snapshot), localhost:9991-9993, 32 CPUs ## Reproduction -_Not recorded (migrated from buglog.json)._ +UPDATE (2026-09-29): 1. `nix develop ./src --command bash .claude/skills/xce-test-ha/run-ha-soak.sh --force-snapshot ` (the soak polls ctrlstatus with short-lived client connections while a wiped standby rejoins and receives a 9-chunk snapshot). +2. In each ctrl-N.log, split `ha_handle_snapshot_chunk: chunk crc32` lines per transfer (chunk_index=0 starts one); a transfer with fewer than 9 chunks and no `HA: snapshot loaded` is the bug. The soak itself still PASSes because its 30 s install poll outlasts the 10 s liveness timeout + retransfer. +- Frequency: 3/16 runs had a truncated transfer (1, 1 and 4 of 9 chunks), 2026-09-29 on 3444cf16; originally 2/4 runs, 2026-09-27. +- Smaller repro: `xcelib_test` test_netio_err_queue (deterministic): an established TLS session on a socketpair, a stale SSL error on the thread queue, one EPOLLIN dispatch through io_handler. +- Evidence: /home/claude/tmp/xce-1871-fs5, -fs12, -fs16 (instrumented logs); /home/claude/tmp/xce-ha-final-force-snapshot (original). ## 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. +UPDATE (2026-09-29): OpenSSL error queues are per thread, and SSL_get_error() returns SSL_ERROR_SSL whenever the queue is non-empty, regardless of what the call being classified did. netio never cleared it. io_worker serves every endpoint from one thread, so when a ctrlstatus client closed its connection, OpenSSL 3 queued `unexpected eof while reading` on that thread (trace: `rd-block ... err=1 errno=0` for the client fd). The next SSL_read on the HA snapshot stream that merely found the socket drained mid-chunk (errno=11) was then reported as SSL_ERROR_SSL; io_classify_io_error() returned a negative error and handle_input() -> handle_error() unmonitored the endpoint. The primary kept the connection as healthy, the standby stopped reading, and the transfer resumed only after the standby's 10 s liveness failover reconnected. The handshake path was not affected in practice because the TLS state machine clears the queue itself; the application-data read path does not. + ## Fix -_Not recorded (migrated from buglog.json)._ +UPDATE (2026-09-29): src/lib/netio.c: ERR_clear_error() before each SSL_read/SSL_write in io_fsm_do() and before SSL_do_handshake() in handle_ssl_handshake(), so SSL_get_error() only reflects the call it classifies. A stale error from another connection can no longer turn a would-block into a teardown. ## Verification -_Not recorded (migrated from buglog.json)._ +- Test: test_stale_thread_error_does_not_kill_endpoint in src/lib/testsuite/test_netio_err_queue.c drives io_handler on an established TLS session whose read would block, with a stale SSL error on the thread queue: RED before the fix (`Expected 0 Was 1 ... reported as a connection error`), GREEN after; the sibling test_would_block_read_is_not_an_error (clean queue) passes both ways +- Suites: xcelib_test 697/697 and controller 1256/1256, asan, no sanitizer errors +- Live: xce-test-ha --force-snapshot, 16 runs with the fixed controller (2026-09-29): 16/16 PASS and 24/24 snapshot transfers complete (9 chunks + load), 0 truncated -- versus 3 truncated transfers in 16 runs before the fix on the same commit ## References - Related: bug-1870 - Gitea: #297 + +UPDATE (2026-09-29): - Fix commit: 754d5bcf +- Related: bug-1870 (force-snapshot soak), bug-648 (io_classify_io_error EOF handling) +- Gitea: #297 diff --git a/.wolf/bugs/bug-1890.md b/.wolf/bugs/bug-1890.md new file mode 100644 index 00000000..428e1994 --- /dev/null +++ b/.wolf/bugs/bug-1890.md @@ -0,0 +1,55 @@ +--- +id: "bug-1890" +status: "open" +status_updated: "2026-09-29" +status_note: "newly logged" +component: "lib" +severity: "noise" +timestamp: "2026-09-29T14:01:08Z" +last_seen: "2026-09-29T14:01:08Z" +occurrences: 1 +files: ["src/lib/netio.c (socket_create, socket_connect, endpoint_accept)"] +tags: ["netio", "tcp", "latency", "ha", "snapshot"] +related: ["bug-1871"] +--- + +# bug-1890: netio sockets leave Nagle on: last TLS records of a message burst arrive ~40 ms late + +## Description +**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: +``` +[2026-09-29 13:20:33,969] ... ha_handle_snapshot_chunk: chunk crc32 checkpoint_lsn=114 chunk_index=6 ... +[2026-09-29 13:20:34,010] ... ha_handle_snapshot_chunk: chunk crc32 checkpoint_lsn=114 chunk_index=7 ... +``` + +**Expected:** on loopback the whole burst arrives within a few ms (most runs: max inter-chunk gap 1-4 ms). +**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. + +## 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, with temporary netio TRACE instrumentation) +- Code: scheduler-framework @ 3444cf16 +- 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. On the rejoined standby's log, compute the gap between consecutive `ha_handle_snapshot_chunk: chunk crc32` lines of one transfer; a ~40 ms gap (while the primary finished sending 1 ms earlier) is the symptom. +- Frequency: 5/40 transfers had a 39-41 ms gap, 2026-09-29 (xce-1871-fs1..fs16) +- 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 + +## 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