From 58d44fde84fce0e1ecefb2eb40b747d904737b79 Mon Sep 17 00:00:00 2001 From: go-while Date: Wed, 11 Nov 2026 13:25:54 +0000 Subject: [PATCH 1/2] e2e: TestXoverStalledClientDoesNotHoldGroupLock waits for A to block Old (#274): after A's XOVER 1-40000 status line the test slept 700 ms "for A's reply to fill the socket", then measured B's ARTICLE store (bound 1.5 s). If A's session had not reached the records yet (slow or loaded machine), B took the lock first and passed whatever the code did with the lock. New: after the warm-up, wait until the daemon has no child, so that A's session is its only child; after A's 224, poll /proc//syscall until the session sleeps in sendto/sendmsg/write (state S), then start B. Linux only now (skips elsewhere, and if /proc//syscall can't be read); the code under test is the same on every system. The warm cache and the 1.5 s bound stay. Measured (12 cores): A blocked in send() 5-27 ms after the request, 128-142 ms with -race; B waited 0 s in all 5 + 5 runs. Mutants (scratch only), NVNewsgroup::printoverdb_stored: 1. flush_chunk() before guard.release() (each chunk written with the shared lock held): new test fails, 3/3: the second session waited 3.042975562s for the group lock while the first client stopped reading; ... (the old test fails too, with 2.31 s, as the stall had begun 0.7 s before B). 2. the same plus usleep(1 s) before the first chunk (a slow machine): the old test passes ("second session waited 0s"); the new one waits for the block (1.032 s) and fails with 2.99 s. Co-Authored-By: Claude Opus 5.5 --- changes/fix-xover-stall-test-wait.md | 8 ++++ tests/e2e/daemon_test.go | 58 ++++++++++++++++++++++++++-- 2 files changed, 62 insertions(+), 4 deletions(-) create mode 100644 changes/fix-xover-stall-test-wait.md diff --git a/changes/fix-xover-stall-test-wait.md b/changes/fix-xover-stall-test-wait.md new file mode 100644 index 0000000..74b3682 --- /dev/null +++ b/changes/fix-xover-stall-test-wait.md @@ -0,0 +1,8 @@ +Other changes: +* TestXoverStalledClientDoesNotHoldGroupLock starts the second client + only once the first client's session is seen blocked in send() + (/proc//syscall), instead of after a fixed 700 ms. On a slow + machine the first session could still be before its XOVER, and the + second client passed without testing anything: with the lock held + across the write and the session one second late, the old test + passed and this one fails. It needs Linux now. diff --git a/tests/e2e/daemon_test.go b/tests/e2e/daemon_test.go index 5cc8ad4..2bd25a3 100644 --- a/tests/e2e/daemon_test.go +++ b/tests/e2e/daemon_test.go @@ -2050,13 +2050,19 @@ func TestSIGTERMUpdatenewsPosting(t *testing.T) { // XOVER and then stops reading used to hold the group's shared lock until its // send timed out (ClientTimeout), and every session that needed the exclusive // lock - storing an article or an overview record - waited that long. The -// records are now formatted in chunks under a shortened lock. +// records are now formatted in chunks under a shortened lock. B starts only +// once A's session is seen blocked in send() (Linux /proc): before, a fixed +// 700 ms let B run before A's session was stalled on a slow machine, and B +// then passed without testing anything. func TestXoverStalledClientDoesNotHoldGroupLock(t *testing.T) { + if runtime.GOOS != "linux" { + t.Skip("needs /proc to see that the first session is blocked writing") + } const group = "alt.binaries.lockhold" e := newEnv(t) e.ClientTimeout = 3 e.Store.AddGenerated(group, "", fakeserver.Generator{Low: 1, High: 40000}) - e.standalone() + daemon := e.standalone().Pid() // Fill the group's overview first, with a client that reads it all: // fetching it holds the group's exclusive lock (freshen), and on a @@ -2073,6 +2079,8 @@ func TestXoverStalledClientDoesNotHoldGroupLock(t *testing.T) { t.Fatalf("XOVER (warm-up): %d records, want 40000", n) } w.Cmd("QUIT") + // A's session is then the daemon's only child + waitForNoLinuxChildren(t, daemon, 10*time.Second) a, err := net.Dial("tcp", e.Listen) if err != nil { @@ -2091,8 +2099,14 @@ func TestXoverStalledClientDoesNotHoldGroupLock(t *testing.T) { if l, err := ra.ReadString('\n'); err != nil || !strings.HasPrefix(l, "224") { t.Fatalf("XOVER: %q %v", l, err) } - // A reads nothing more; give its reply time to fill the socket. - time.Sleep(700 * time.Millisecond) + // A reads nothing more. Wait until its session is blocked in send() + // with the reply's rest not sent: then, with the old code, it held the + // group's lock until the send timed out (ClientTimeout). + kids := linuxProcChildren(t, daemon) + if len(kids) != 1 { + t.Fatalf("daemon children %v, want only A's session", kids) + } + waitBlockedInSend(t, kids[0], 20*time.Second) b := e.dial() b.Deadline = 30 * time.Second @@ -2114,6 +2128,42 @@ func TestXoverStalledClientDoesNotHoldGroupLock(t *testing.T) { } } +// waitBlockedInSend waits until process pid sleeps in a send syscall +// (/proc//syscall: the syscall number first; "running" while it +// runs). It skips when that file can't be read (another user, or a +// restricted /proc). +func waitBlockedInSend(t *testing.T, pid string, timeout time.Duration) { + t.Helper() + send := map[string]bool{ + strconv.Itoa(syscall.SYS_SENDTO): true, + strconv.Itoa(syscall.SYS_SENDMSG): true, + strconv.Itoa(syscall.SYS_WRITE): true, + } + start := time.Now() + for { + b, err := os.ReadFile("/proc/" + pid + "/syscall") + if err != nil { + t.Skipf("cannot see what the session does: %v", err) + } + f := strings.Fields(string(b)) + if len(f) > 0 && send[f[0]] { + st, err := os.ReadFile("/proc/" + pid + "/stat") + if err != nil { + t.Fatal(err) + } + s := string(st) + if fs := strings.Fields(s[strings.LastIndex(s, ")")+1:]); len(fs) > 0 && fs[0] == "S" { + t.Logf("session %s blocked in send() %v after the request", pid, time.Since(start).Round(time.Millisecond)) + return + } + } + if time.Since(start) > timeout { + t.Fatalf("session %s not blocked in send() within %v (syscall %q)", pid, timeout, b) + } + time.Sleep(5 * time.Millisecond) + } +} + // cpuTicks returns the user and system CPU time (clock ticks) of a process. func cpuTicks(t *testing.T, pid int) int { t.Helper() From 4e179cca57f0932990b2c8d74f0053fd354a7ea4 Mon Sep 17 00:00:00 2001 From: go-while Date: Wed, 11 Nov 2026 18:41:44 +0000 Subject: [PATCH 2/2] e2e: the XOVER lock test stores until the stalled session has ended The previous version waited for /proc//syscall to show the first session in send() and skipped where that file doesn't exist, FreeBSD included, where main still ran the test. Now the second client stores one uncached article after the other (each needs the group's exclusive lock) from the first client's 224 until the first session has ended. That session reads nothing and ends only when a send times out, ClientTimeout after it blocked, so the stores cover the whole stall on any system: with the lock held across the write one of them waits until the session ends. The session is found with daemonChildren (/proc or pgrep). Mutants (scratch builds, not committed), NVNewsgroup::printoverdb_stored: flush_chunk() before guard.release() fails 3/3 (waits 3.01-3.04 s); the same plus usleep(1 s) first, a slow machine, fails 3/3 (3.01-3.05 s), also with -race and with /proc hidden (pgrep). main passes, longest wait 10-90 ms (20-220 ms with -race). Co-Authored-By: Claude Opus 5.5 --- changes/fix-xover-stall-test-wait.md | 16 +++-- tests/e2e/daemon_test.go | 104 ++++++++++++--------------- 2 files changed, 56 insertions(+), 64 deletions(-) diff --git a/changes/fix-xover-stall-test-wait.md b/changes/fix-xover-stall-test-wait.md index 74b3682..0e5c90e 100644 --- a/changes/fix-xover-stall-test-wait.md +++ b/changes/fix-xover-stall-test-wait.md @@ -1,8 +1,10 @@ Other changes: -* TestXoverStalledClientDoesNotHoldGroupLock starts the second client - only once the first client's session is seen blocked in send() - (/proc//syscall), instead of after a fixed 700 ms. On a slow - machine the first session could still be before its XOVER, and the - second client passed without testing anything: with the lock held - across the write and the session one second late, the old test - passed and this one fails. It needs Linux now. +* TestXoverStalledClientDoesNotHoldGroupLock: the second client stores + one article after the other from the first client's XOVER until the + first client's session has ended, instead of storing one article after + a fixed 700 ms. On a slow machine the first session could still be + before its XOVER's records then, and the second client passed without + testing anything: with the lock held across the write and the session + one second late, the old test passed and this one fails. The first + session ends only when its send times out, so the stores cover the + whole time it is stalled, on every system that has /proc or pgrep. diff --git a/tests/e2e/daemon_test.go b/tests/e2e/daemon_test.go index e076f28..bf07aac 100644 --- a/tests/e2e/daemon_test.go +++ b/tests/e2e/daemon_test.go @@ -14,6 +14,7 @@ import ( "path/filepath" "regexp" "runtime" + "slices" "strconv" "strings" "sync" @@ -2056,13 +2057,17 @@ func TestSIGTERMUpdatenewsPosting(t *testing.T) { // XOVER and then stops reading used to hold the group's shared lock until its // send timed out (ClientTimeout), and every session that needed the exclusive // lock - storing an article or an overview record - waited that long. The -// records are now formatted in chunks under a shortened lock. B starts only -// once A's session is seen blocked in send() (Linux /proc): before, a fixed -// 700 ms let B run before A's session was stalled on a slow machine, and B -// then passed without testing anything. +// records are now formatted in chunks under a shortened lock. +// +// B stores one article after the other, from A's 224 until A's session has +// ended. A reads nothing, so its session ends only when a send times out, +// ClientTimeout after it blocked: B's stores cover that whole time, with the +// old code one of them waits for the lock until A's session ends. Before, B +// stored one article after a fixed 700 ms, and on a slow machine that could +// be before A's session had blocked: B then passed without testing anything. func TestXoverStalledClientDoesNotHoldGroupLock(t *testing.T) { - if runtime.GOOS != "linux" { - t.Skip("needs /proc to see that the first session is blocked writing") + if _, ok := daemonChildren(os.Getpid()); !ok { + t.Skip("can't list a process's children (no /proc, no pgrep)") } const group = "alt.binaries.lockhold" e := newEnv(t) @@ -2105,68 +2110,53 @@ func TestXoverStalledClientDoesNotHoldGroupLock(t *testing.T) { if l, err := ra.ReadString('\n'); err != nil || !strings.HasPrefix(l, "224") { t.Fatalf("XOVER: %q %v", l, err) } - // A reads nothing more. Wait until its session is blocked in send() - // with the reply's rest not sent: then, with the old code, it held the - // group's lock until the send timed out (ClientTimeout). kids := linuxProcChildren(t, daemon) if len(kids) != 1 { t.Fatalf("daemon children %v, want only A's session", kids) } - waitBlockedInSend(t, kids[0], 20*time.Second) + sessionA := kids[0] + aRunning := func() bool { + return slices.Contains(linuxProcChildren(t, daemon), sessionA) + } + // A reads nothing more. The articles aren't cached yet: each one is + // fetched and then stored, which needs the group's exclusive lock. b := e.dial() b.Deadline = 30 * time.Second if code, line := b.Cmd("GROUP %s", group); code != 211 { t.Fatalf("B GROUP: %q", line) } - // ARTICLE 1 is not cached yet: it is fetched and then stored, which - // needs the group's exclusive lock. - start := time.Now() - code, line := b.Cmd("ARTICLE 1") - elapsed := time.Since(start) - if code != 220 { - t.Fatalf("B ARTICLE 1: %q, want 220", line) - } - b.ReadDotLines() - t.Logf("second session waited %v (ClientTimeout %d s)", elapsed.Round(10*time.Millisecond), e.ClientTimeout) - if elapsed > 1500*time.Millisecond { - t.Errorf("the second session waited %v for the group lock while the first client stopped reading; the lock is held across the write to the client", elapsed) - } -} - -// waitBlockedInSend waits until process pid sleeps in a send syscall -// (/proc//syscall: the syscall number first; "running" while it -// runs). It skips when that file can't be read (another user, or a -// restricted /proc). -func waitBlockedInSend(t *testing.T, pid string, timeout time.Duration) { - t.Helper() - send := map[string]bool{ - strconv.Itoa(syscall.SYS_SENDTO): true, - strconv.Itoa(syscall.SYS_SENDMSG): true, - strconv.Itoa(syscall.SYS_WRITE): true, - } start := time.Now() - for { - b, err := os.ReadFile("/proc/" + pid + "/syscall") - if err != nil { - t.Skipf("cannot see what the session does: %v", err) - } - f := strings.Fields(string(b)) - if len(f) > 0 && send[f[0]] { - st, err := os.ReadFile("/proc/" + pid + "/stat") - if err != nil { - t.Fatal(err) - } - s := string(st) - if fs := strings.Fields(s[strings.LastIndex(s, ")")+1:]); len(fs) > 0 && fs[0] == "S" { - t.Logf("session %s blocked in send() %v after the request", pid, time.Since(start).Round(time.Millisecond)) - return - } - } - if time.Since(start) > timeout { - t.Fatalf("session %s not blocked in send() within %v (syscall %q)", pid, timeout, b) - } - time.Sleep(5 * time.Millisecond) + var worst time.Duration + stores := 0 + for n := 1; aRunning(); n++ { + // a hang guard: A's session ends ClientTimeout after it blocked + if time.Since(start) > 60*time.Second { + t.Fatalf("A's session %s still runs after %v", sessionA, time.Since(start).Round(time.Second)) + } + if n > 40000 { + t.Fatalf("no uncached article left after %d stores", n-1) + } + // pacing only (at most about 1500 stores in A's 3 s): a store that + // starts while A holds the lock waits until A's session ends + time.Sleep(2 * time.Millisecond) + s := time.Now() + code, line := b.Cmd("ARTICLE %d", n) + took := time.Since(s) + if code != 220 { + t.Fatalf("B ARTICLE %d: %q, want 220", n, line) + } + b.ReadDotLines() + stores++ + worst = max(worst, took) + } + if stores == 0 { + t.Fatalf("A's session %s ended before B stored an article", sessionA) + } + t.Logf("A's session ended %v after its XOVER; B stored %d articles meanwhile, the longest wait %v (ClientTimeout %d s)", + time.Since(start).Round(10*time.Millisecond), stores, worst.Round(10*time.Millisecond), e.ClientTimeout) + if worst > 1500*time.Millisecond { + t.Errorf("the second session waited %v for the group lock while the first client stopped reading; the lock is held across the write to the client", worst) } }