myxce/.wolf/bugs/bug-1871.md
Rongsong Shen 3061df1401
chore(buglog): record Gitea sync state for bug-1871 (#297) and bug-1890 (#336)
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
2026-09-29 14:18:38 +00:00

62 lines
5.8 KiB
Markdown

---
id: "bug-1871"
status: "fixed"
status_updated: "2026-09-29"
status_note: ""
component: "lib"
severity: "hang"
timestamp: "2026-09-27T07:03:48Z"
last_seen: "2026-09-27T07:03:48Z"
occurrences: 1
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: "fixed"
gitea_synced_hash: "cc4b51dead21"
---
# bug-1871: HA snapshot transfer to a rejoining standby stalls mid-stream: primary queues all chunks at once…
## 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
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
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
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
- 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