From 213a0d30422f8add18483fd3ead20c0c7ec1dfbb Mon Sep 17 00:00:00 2001 From: go-while Date: Wed, 11 Nov 2026 13:23:33 +0000 Subject: [PATCH 1/2] e2e: TestSpoolDiskFullDaemon bounds the replies on the full disk again Old (#83): ClientTimeout 600, and every reply and dial had a 180 s deadline, so a lock left held (or any stall) of up to about 170 s passed. The reason: client 2's last command, XOVER 19990-20000, came from the chunk 10000-19999, which couldn't be kept on the full disk, so NewsCache fetched 10000 records twice from the fake upstream, which runs in the race-instrumented test process: 20-21.5 s under -race (3 s without), measured inside client 2's session while client 1 idled, which on a busy machine passed the default ClientTimeout. New: the group has 20010 articles and client 2 asks for XOVER 20000-20010, a last chunk of 11 records that can't be kept either (the log still shows "updating the overview database failed" during client 2's session, and the records are passed on). Client 1's first commands, which fill the cache from the fake upstream, are setup and keep the 180 s hang guard. Everything after, on the full disk (client 1's LIST, client 2's dial and six commands, client 1's two commands afterwards), must be answered completely within 5 s, with the default ClientTimeout 60: client 1 stays connected, so a lock it left held blocks client 2 for good. Measured (12 cores): the commands on the full disk took at most 56 ms (5 runs) and 137 ms with -race (5 runs); all pass. A -race subtest now takes about 20 s instead of 40 s. Mutant (scratch only): ~NVLock() skips release() while an exception unwinds (std::uncaught_exceptions() > 0), i.e. the lock leak e9ac5bd fixed. The new test fails in both subtests after 5 s: client 2: greeting: read tcp 127.0.0.1:42550->127.0.0.1:40337: i/o timeout The test from origin/main fails too, but only after 184 s. Co-Authored-By: Claude Opus 5.5 --- changes/fix-spool-diskfull-test-bounds.md | 10 ++++ tests/e2e/spoolfull_test.go | 63 +++++++++++++---------- 2 files changed, 46 insertions(+), 27 deletions(-) create mode 100644 changes/fix-spool-diskfull-test-bounds.md diff --git a/changes/fix-spool-diskfull-test-bounds.md b/changes/fix-spool-diskfull-test-bounds.md new file mode 100644 index 00000000..6a2099fa --- /dev/null +++ b/changes/fix-spool-diskfull-test-bounds.md @@ -0,0 +1,10 @@ +Other changes: +* TestSpoolDiskFullDaemon wants every reply on the full disk within 5 + seconds again (they take at most 0.14 s, also with the race detector), + with the default ClientTimeout. Since #83 it allowed 180 s per reply + and ClientTimeout 600, so a lock held for nearly three minutes passed: + the second client's last XOVER fetched 10000 records again from the + test's own fake news server (20 s under -race), and the first client + idled that long. The group now ends in a small chunk of 11 records + that can't be kept either, so nothing slow is left in the measured + part; the first client's fill of the cache keeps its 180 s. diff --git a/tests/e2e/spoolfull_test.go b/tests/e2e/spoolfull_test.go index db13e268..c8ceb3b4 100644 --- a/tests/e2e/spoolfull_test.go +++ b/tests/e2e/spoolfull_test.go @@ -247,7 +247,7 @@ exit "$rc"`, tc.kb), // TestSpoolDiskFullDaemon: the daemon on a nearly full spool (tmpfs in a // user namespace), History on. Client 1 reads the active list of an -// upstream with 3000 groups and the overview of a group of 20000 +// upstream with 3000 groups and the overview of a group of 20010 // articles, then an independent filler exhausts any remaining tmpfs space. // Then 2000 new groups make the active list grow on the full disk; client 1 // stays connected. Client 2 (its @@ -276,14 +276,16 @@ func testDiskFullDaemon(t *testing.T, kb int, clean string) { // Timeouts: the active list is due again after a second e.Extra += "History on\nTimeouts 1 3600\n" e.MaxConnections = 4 - // client 1 waits while client 2 works: on a busy machine, and with a - // -race fake upstream, that took longer than the default 60 s, and - // NewsCache rightly ended client 1's session as idle - e.ClientTimeout = 600 for i := 0; i < 3000; i++ { e.Store.AddGroup(fmt.Sprintf("test.many.group-with-a-longer-name.%04d", i), "") } - e.Store.AddGenerated(hugeGroup, "", fakeserver.Generator{Low: 1, High: 20000}) + // 20000 records fill the disk while client 1 reads them; the last + // chunk of overview (20000-20010) is small, so that client 2 can ask + // for one that couldn't be kept without waiting for this process's + // fake upstream (under -race it took 20 s to send the chunk + // 10000-19999 again, and that was inside the measured time) + const last = 20010 + e.Store.AddGenerated(hugeGroup, "", fakeserver.Generator{Low: 1, High: last}) out := filepath.Join(e.Dir, "out") if err := os.MkdirAll(out, 0o755); err != nil { t.Fatal(err) @@ -331,16 +333,22 @@ wait $pid`, kb) o.Path = "unshare" p := proc.StartTCP(t, o, e.Listen) - // each reply must arrive within 180 s (the deadline of the conn, for a - // whole dot block: a -race client and fake upstream on a busy machine - // need well over a minute for 20000 records); a lock left held makes - // a session wait for good, which still fails - const deadline = 180 * time.Second + // Client 1's first commands fill the cache from the fake upstream, + // which runs in this process: setup, with a hang guard of 180 s for a + // -race build on a busy machine. Every command after that, on the + // full disk, must be answered completely within bound: they took at + // most 0.12 s, also with -race, and a lock left held by another + // session makes a session wait until that session ends (client 1 stays + // connected, so for good; before, the 180 s let a held lock or a + // stall of nearly three minutes pass). + const setupDeadline = 180 * time.Second + const bound = 5 * time.Second run := func(name string, c *client.Conn, cmds ...string) { for _, cmd := range cmds { + start := time.Now() code, line, err := c.TryCmd("%s", cmd) if err != nil { - t.Fatalf("%s: %s: no reply within %v (%v)", name, cmd, deadline, err) + t.Fatalf("%s: %s: no reply within %v (%v)", name, cmd, c.Deadline, err) } if strings.HasPrefix(cmd, "ARTICLE") && code != 220 { t.Errorf("%s: %s: %q, want the article (passed on when it can't be kept)", name, cmd, line) @@ -355,14 +363,22 @@ wait $pid`, kb) t.Errorf("%s: %s: %d records, want %d (passed on when they can't be kept)", name, cmd, len(lines), b-a+1) } } - t.Logf("%s: %s -> %.60s", name, cmd, line) + took := time.Since(start) + t.Logf("%s: %s -> %.60s (%v)", name, cmd, line, took.Round(time.Millisecond)) + if c.Deadline == bound && took > bound { + t.Errorf("%s: %s took %v on the full disk, want within %v (a lock held by another session?)", name, cmd, took.Round(time.Millisecond), bound) + } } } - session := func(name string, keep bool, cmds ...string) *client.Conn { + session := func(name string, deadline time.Duration, keep bool, cmds ...string) *client.Conn { + start := time.Now() c, err := client.TryDial(e.Listen, deadline) if err != nil { t.Fatalf("%s: %v", name, err) } + if took := time.Since(start); deadline == bound && took > bound { + t.Errorf("%s: greeting after %v, want within %v", name, took.Round(time.Millisecond), bound) + } c = c.WithTB(t) run(name, c, cmds...) if !keep { @@ -371,8 +387,9 @@ wait $pid`, kb) } return c } - c1 := session("client 1", true, "LIST", "GROUP "+hugeGroup, "XOVER 1-20000", - "ARTICLE 19999") + c1 := session("client 1", setupDeadline, true, "LIST", "GROUP "+hugeGroup, + fmt.Sprintf("XOVER 1-%d", last), fmt.Sprintf("ARTICLE %d", last-1)) + c1.Deadline = bound // The helper fills any remaining tmpfs blocks before the next LIST, // which must grow the active database while the filesystem is full. if err := os.WriteFile(filepath.Join(out, "probe-request"), nil, 0o644); err != nil { @@ -394,17 +411,9 @@ wait $pid`, kb) } time.Sleep(1100 * time.Millisecond) run("client 1", c1, "LIST") - session("client 2", false, "LIST ACTIVE test.many.*.000?", "GROUP "+hugeGroup, - "XOVER 1-100", "ARTICLE 50", "ARTICLE "+hugeID(60), "XOVER 19990-20000") - for _, cmd := range []string{"GROUP " + hugeGroup, "XOVER 1-10"} { - if code, line, err := c1.TryCmd("%s", cmd); err != nil { - t.Fatalf("client 1 afterwards: %s: %v", cmd, err) - } else if code == 224 { - c1.TryReadDotLines() - } else { - t.Logf("client 1 afterwards: %s -> %q", cmd, line) - } - } + session("client 2", bound, false, "LIST ACTIVE test.many.*.000?", "GROUP "+hugeGroup, + "XOVER 1-100", "ARTICLE 50", "ARTICLE "+hugeID(60), fmt.Sprintf("XOVER 20000-%d", last)) + run("client 1 afterwards", c1, "GROUP "+hugeGroup, "XOVER 1-10") c1.TryCmd("QUIT") c1.Close() p.Stop() From 1a7e47b6c3c831dcb75a6ff060b149ddbf941995 Mon Sep 17 00:00:00 2001 From: go-while Date: Wed, 11 Nov 2026 18:24:23 +0000 Subject: [PATCH 2/2] e2e: TestSpoolDiskFullDaemon requires each command's success code An error reply (a 411 GROUP, then 412 for XOVER and ARTICLE) comes at once: the time bound passed without any data being sent, and only ARTICLE and the record count of a 224 XOVER were checked. Now LIST must answer 215, GROUP 211, XOVER 224 and ARTICLE 220. Co-Authored-By: Claude Opus 5.5 --- tests/e2e/spoolfull_test.go | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/tests/e2e/spoolfull_test.go b/tests/e2e/spoolfull_test.go index c8ceb3b4..8d30aa55 100644 --- a/tests/e2e/spoolfull_test.go +++ b/tests/e2e/spoolfull_test.go @@ -343,6 +343,10 @@ wait $pid`, kb) // stall of nearly three minutes pass). const setupDeadline = 180 * time.Second const bound = 5 * time.Second + // Every command must succeed, also on the full disk (what can't be + // kept is passed on from the upstream): an error reply comes at once + // and would pass the time bound without sending the data. + want := map[string]int{"LIST": 215, "GROUP": 211, "XOVER": 224, "ARTICLE": 220} run := func(name string, c *client.Conn, cmds ...string) { for _, cmd := range cmds { start := time.Now() @@ -350,10 +354,13 @@ wait $pid`, kb) if err != nil { t.Fatalf("%s: %s: no reply within %v (%v)", name, cmd, c.Deadline, err) } - if strings.HasPrefix(cmd, "ARTICLE") && code != 220 { - t.Errorf("%s: %s: %q, want the article (passed on when it can't be kept)", name, cmd, line) + verb, _, _ := strings.Cut(cmd, " ") + if w, ok := want[verb]; !ok { + t.Fatalf("%s: %s: no expected reply code for %s", name, cmd, verb) + } else if code != w { + t.Errorf("%s: %s: %q, want %d (passed on when it can't be kept)", name, cmd, line, w) } - if code == 215 || code == 224 || code == 220 || code == 211 && strings.HasPrefix(cmd, "LISTGROUP") { + if code == 215 || code == 224 || code == 220 { lines, err := c.TryReadDotLines() if err != nil { t.Fatalf("%s: %s: %v", name, cmd, err)