chore(buglog): bug-1871 fixed (754d5bcf); log bug-1890 (Nagle tail latency)
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
This commit is contained in:
parent
754d5bcf3e
commit
715c08f03b
GPG key ID:
80533536B0EB651C
3 changed files with 125 additions and 21 deletions
|
|
@ -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"
|
||||
}
|
||||
]
|
||||
}
|
||||
|
|
|
|||
|
|
@ -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 <dir>` (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
|
||||
|
|
|
|||
55
.wolf/bugs/bug-1890.md
Normal file
55
.wolf/bugs/bug-1890.md
Normal file
|
|
@ -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 <dir>`
|
||||
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
|
||||
Loading…
Add table
Add a link
Reference in a new issue