Skip to content

Plain sockets: a send cut short by the send timeout ends the write; TestClientStalledReader measures the session's end - #377

Merged
go-while merged 7 commits into
mainfrom
fix/stalled-reader-test-from-spool
Nov 12, 2026
Merged

go-while merged 7 commits into
mainfrom
fix/stalled-reader-test-from-spool

Conversation

@go-while

@go-while go-while commented Nov 11, 2026 •

Copy link
Copy Markdown
Owner

Bug found by the new test, fixed here (21e5d48, reworked in fa0d23f):
with the session's end now measured without /proc too, FreeBSD CI failed:
OVER 6.088 s, XOVER 6.044 s after the request, bound 4.5 s (ClientTimeout
3): two send timeouts. When SO_SNDTIMEO runs out after send() has taken
part of the data, the kernel returns that part instead of EAGAIN (FreeBSD
and Linux alike: on Linux 1774 of 4096 bytes after 1 s, then EAGAIN after
another second), and sockstreambuf::sync() sent the rest with a second
wait. Now, after a short send, the rest goes out only if the socket
becomes writable (poll) within what is left of the socket's send timeout,
counted from the start of the send call that returned short (read with
getsockopt: a client's is set on its socket, not through set_io_timeout);
otherwise the write fails like a failed send. A short count from a signal
therefore never ends the write early, and the timeout never runs twice.
Not during a reply deadline (non-blocking socket): unchanged. (21e5d48
used a 90 %-of-the-timeout guess instead; Terra pointed out that it
could cut a write short after a late signal and counted EINTR retries.)

New check in cReplyBudget: loopback TCP with a small window, SO_SNDTIMEO
1 s, a peer that reads nothing; the write must fail within 1.5 s.
main's sockstream: 2.06-2.07 s, FAIL 3/3; with the fix 1.00-1.06 s, pass.
Linux: the stall/timeout e2e tests pass; full suite passed on 21e5d48,
running again on fa0d23f. FreeBSD CI must now pass.

Old: client A asked for OVER/XOVER 1-40000 (served from the fake
upstream, which runs in the race-instrumented test process) and stopped
reading; after 2 s client B's GROUP and ARTICLE 39999 had to be
answered within 20 s. Nothing checked when A's session ended. Since
#274 writes the records with the group's lock released, B is served
even when A's session stays blocked in send() for good, so the test no
longer saw what 3cefac9 (ClientTimeout for each write) and 763126c
(drop the buffer after a failed send) fixed.

New, as #369 did for the TLS test: a first client fills the cache, so
A's reply comes from the spool and its socket fills at once; A's
session pid is the daemon's only child, and a goroutine records when
it is gone, measured from just before A's request (through
daemonChildren from #369: /proc, or pgrep -P without /proc; no t.Fatal
from the goroutine, and it stops with the test). The session must be
gone within 1.5 ClientTimeouts (4.5 s); in a file-log build "can't be
written to, session ended" must be logged too, as a check of why it
ended (not of when: that line comes at the first failed write, 3 s
before the end with 763126c reverted). B's part is unchanged. Skips only
where neither /proc nor pgrep exists.

Measured (12 cores, ClientTimeout 3): the session ended 3.04-3.10 s
after the request (5 runs x OVER/XOVER), 3.27-3.37 s with -race; all
pass.

Mutants (scratch only):

  1. 763126c reverted (sockstream.cc: the buffer kept after a failed
    send): the new test fails, OVER and XOVER:
    stalled reader's session 2064767 ended 6.035s after the request,
    want within 4.5s
  2. no SO_SNDTIMEO on the client's output (set_socket_timeouts, the
    core of 3cefac9): the new test fails:
    stalled reader's session 2065805 still running 14.501s after the
    request, want it gone within 4.5s
    The test from origin/main passes against both mutants.

Without /proc (scratch change hiding it, pgrep path): main 3.10-3.14 s,
pass; 763126c reverted 6.14-6.16 s, fails. (An earlier head used the
log line as the end without /proc, which didn't check the bound there:
Terra's finding.)

Part of the review of weakened tests that go-while asked for. Shown to fail with the guarded defect (scratch mutant; not committed).

NEWS: changes/fix-stalled-reader-test-from-spool.md.

🤖 Generated with Claude Code

go-while and others added 5 commits November 11, 2026 13:37
Old: client A asked for OVER/XOVER 1-40000 (served from the fake
upstream, which runs in the race-instrumented test process) and stopped
reading; after 2 s client B's GROUP and ARTICLE 39999 had to be
answered within 20 s. Nothing checked when A's session ended. Since
#274 writes the records with the group's lock released, B is served
even when A's session stays blocked in send() for good, so the test no
longer saw what 3cefac9 (ClientTimeout for each write) and 763126c
(drop the buffer after a failed send) fixed.

New, as #369 did for the TLS test: a first client fills the cache, so
A's reply comes from the spool and its socket fills at once; A's
session pid is the daemon's only child, and a goroutine records when
it is gone, measured from just before A's request (it reads
/proc/<pid>/task/<pid>/children itself, no t.Fatal from the goroutine,
and stops with the test). The session must be gone within 1.5
ClientTimeouts (4.5 s); in a file-log build "can't be written to,
session ended" must be logged. B's part is unchanged. Needs /proc or
the log file, like the TLS test.

Measured (12 cores, ClientTimeout 3): the session ended 3.04-3.10 s
after the request (5 runs x OVER/XOVER), 3.27-3.37 s with -race; all
pass.

Mutants (scratch only):
1. 763126c reverted (sockstream.cc: the buffer kept after a failed
   send): the new test fails, OVER and XOVER:
     stalled reader's session 2064767 ended 6.035s after the request,
     want within 4.5s
2. no SO_SNDTIMEO on the client's output (set_socket_timeouts, the
   core of 3cefac9): the new test fails:
     stalled reader's session 2065805 still running 14.501s after the
     request, want it gone within 4.5s
The test from origin/main passes against both mutants.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Without /proc the test fell back to the log line "can't be written to,
session ended", which is logged at the first failed write, not when the
session ends: with 763126c reverted it comes 3 s before the end, so the
bound wasn't checked there (Terra's finding). The session end now always
comes from the daemon's children, through daemonChildren (/proc, or
pgrep -P, from #369); the log line stays as a check of why the session
ended. The test skips only where neither /proc nor pgrep exists.

With /proc hidden (scratch change): main 3.10-3.14 s, pass; 763126c
reverted 6.14-6.16 s, fails.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
When SO_SNDTIMEO runs out after send() has taken part of the data,
FreeBSD returns that part instead of EAGAIN (kern_sendit turns
EWOULDBLOCK into a short count). sync() took the short count for
progress and sent the rest, which waited for a second timeout: the
session of a client that stopped reading ended after two ClientTimeouts.
FreeBSD CI showed it with the new TestClientStalledReader: 6.088 s
(OVER) and 6.044 s (XOVER) with ClientTimeout 3, bound 4.5 s.

A blocking send returns short only when it was cut off, by a signal or
by the timeout. When it has waited for the socket's whole send timeout
(read with getsockopt, since a client's is set on its socket, not
through set_io_timeout), the rest is dropped and the write fails, as
after a failed send. A short count after a shorter wait (a signal)
still goes on.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@go-while go-while changed the title e2e: TestClientStalledReader measures the session's end from the spool Plain sockets: a send cut short by the send timeout ends the write; TestClientStalledReader measures the session's end Nov 11, 2026
go-while and others added 2 commits November 11, 2026 19:36
…eout

Terra's review of 21e5d48: the 90 % check guessed from the elapsed time
whether the timeout or a signal cut the send short, and t0 was taken
before the EINTR retries. Now a short send waits until the socket can
take more for what is left of the send timeout (poll), from the start of
the send call that returned short: nothing left or still full ends the
write, so a signal never ends it early and the timeout never runs twice.
Not during a reply deadline (non-blocking socket, short counts at once):
that path is unchanged.

Linux returns short counts at the timeout too (1774 of 4096 bytes after
1 s, then EAGAIN after another second), so cReplyBudget gets a check:
loopback TCP with a small window, SO_SNDTIMEO 1 s, a peer that reads
nothing; the write must fail within 1.5 s. main's sockstream: 2.06-2.07 s,
fails 3/3; with this: 1.00-1.06 s.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
On a failed socket() or connect() it went on to accept(), which waits
for good with no peer coming (Terra's review). Now it reports the
failure and returns; a failed accept() too.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@go-while
go-while merged commit 4db6ce7 into main Nov 12, 2026
31 checks passed
@go-while
go-while deleted the fix/stalled-reader-test-from-spool branch November 12, 2026 01:27
go-while added a commit that referenced this pull request Nov 12, 2026
REVIEW.md: test review of 2026-11-11 and #367 to #377
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant