Discriminator tests: time the sixteen-thousand-cookie requests without wall time (closes #308)

The two tests that send sixteen thousand cookies now ask discriminator in
a synctest bubble. There only waiting moves the clock, so a busy host no
longer fails them. The check that the Core Rule Set never read the
request still covers the work that would take over a second.

askDirectly now returns the whole answer, so these tests keep checking
the disposition header.

Model: opus-5-5

Dockerfile

@@ -42,35 +42,20 @@ RUN go mod tidy -diff || \
 # Go's build cache is kept on a tmpfs, out of the image: nothing uses it
 # after this step, and writing it into the image takes seconds. The tests
 # are built with the no_fs_access tag, as the binary is in the build stage.
-#
-# The race detector finds bugs only in code that runs in several goroutines
-# at once. Of the Core Rule Set's tests, this pass runs only those written
-# to check concurrent inspection, whose names start with TestConcurrent.
-# The second pass runs the rest.
 FROM test-setup AS test-race
 
 RUN --mount=type=tmpfs,target=/root/.cache/go-build \
-    others="$(go list ./... | grep -vxF sneak.berlin/go/smallwebwaf/internal/coreruleset)"; \
-    { go test -tags no_fs_access -timeout 90s -race -cover $others && \
-      go test -tags no_fs_access -timeout 90s -race -cover \
-        -run '^TestConcurrent' ./internal/coreruleset; } || \
+    go test -tags no_fs_access -timeout 90s -race -cover ./... || \
     { echo "--- Rerunning with -v for details ---"; \
-      go test -tags no_fs_access -timeout 90s -race -v $others; \
-      go test -tags no_fs_access -timeout 90s -race -v \
-        -run '^TestConcurrent' ./internal/coreruleset; \
-      exit 1; }
+      go test -tags no_fs_access -timeout 90s -race -v ./...; exit 1; }
 
-# Second pass: every other test of the Core Rule Set, the recorded requests
-# among them, without the race detector.
+# Second pass: the recorded requests, too slow for make test under -race.
 FROM test-setup AS test-recorded
 
 RUN --mount=type=tmpfs,target=/root/.cache/go-build \
-    go test -tags no_fs_access,recorded -timeout 90s -cover \
-        -skip '^TestConcurrent' ./internal/coreruleset || \
+    go test -tags no_fs_access,recorded -timeout 90s -cover -run '^TestOrdinary' ./internal/coreruleset/... || \
     { echo "--- Rerunning with -v for details ---"; \
-      go test -tags no_fs_access,recorded -timeout 90s -v \
-        -skip '^TestConcurrent' ./internal/coreruleset; \
-      exit 1; }
+      go test -tags no_fs_access,recorded -timeout 90s -run '^TestOrdinary' -v ./internal/coreruleset/...; exit 1; }
 
 # The test phase that script/test and the build stage name. Nothing is
 # wanted from the two passes; the copies are what make BuildKit run them.

README.md

@@ -702,12 +702,8 @@ on the host.
 - `script/projectname`: prints `smallwebwaf`, which the other scripts tag their
   images with.
 - `script/test`: checks that `go.mod` and `go.sum` are tidy, then runs the
-  tests, as the `test` phase of the `Dockerfile`, in two passes. `make test`.
-    - The first runs every package's tests with the race detector. Of the Core
-      Rule Set's tests, it runs only those written to check concurrent
-      inspection, whose names start with `TestConcurrent`.
-    - The second runs the Core Rule Set's other tests without the race detector,
-      the recorded requests among them.
+  tests, as the `test` phase of the `Dockerfile`. It runs them twice: once with
+  the race detector, and once without it for the recorded requests. `make test`.
 - `script/tidy`: writes `go.mod` and `go.sum` as `go mod tidy` writes them, in
   the `tidy` stage of the `Dockerfile`. `make tidy`.
 - `script/lint`: runs golangci-lint, as the `lint` phase of the `Dockerfile`.

internal/discriminator/answertime_test.go

@@ -67,18 +67,45 @@ func fillHeaders(req *http.Request, total int) {
 	}
 }
 
-func TestSixteenThousandCookiesAreRefusedBeforeTheCoreRuleSetReadsThem(t *testing.T) {
+// askWithSixteenThousandCookies hands a question about a request with sixteen
+// thousand cookies to a discriminator with env in a synctest bubble. It returns
+// the answer, how long the request waited, and the request's log line. In the
+// bubble only waiting moves the clock, so a busy host cannot fail the test. The
+// Core Rule Set reading every cookie is the work that takes over a second, and
+// the log line shows whether it did.
+func askWithSixteenThousandCookies(
+	t *testing.T, env map[string]string,
+) (answer, time.Duration, logLine) {
+	t.Helper()
+
+	var (
+		got  answer
+		took time.Duration
+		line logLine
+	)
+
+	synctest.Test(t, func(t *testing.T) {
+		server, out, _ := newDiscriminator(t, "", time.Now, env)
+
+		got, took = askDirectly(t, server, func(req *http.Request) {
+			req.Header.Set(cookieHeader, strings.Repeat("a;", 16000))
+		})
+		line = out.requestLine(t)
+	})
+
+	return got, took, line
+}
+
+func TestSixteenThousandCookiesAreRefusedWellWithinTheTimeLimit(t *testing.T) {
 	t.Parallel()
 
-	s := startDiscriminator(t, "", map[string]string{wafMode: block})
-	req := s.question(siteA, client, "/")
-	req.Header.Set(cookieHeader, strings.Repeat("a;", 16000))
+	got, took, line := askWithSixteenThousandCookies(t, map[string]string{wafMode: block})
 
-	got := do(t, req)
+	if took >= answerTimeLimit/2 {
+		t.Errorf("answered after %s, want well within %s", took, answerTimeLimit)
+	}
 
 	wantDisposition(t, got, tooLarge, discriminator.DispositionDeny)
-
-	line := s.out.requestLine(t)
 	wantLine(t, line, tooLarge, requestlog.ActionRequestHeaderTooLarge)
 
 	if line.DurationCoreRuleSetMS != nil {
@@ -200,15 +227,15 @@ func TestClientInTheAllowNetsSkipsTheHeaderLimits(t *testing.T) {
 func TestObserveModeAllowsARequestOverTheHeaderLimitsUnread(t *testing.T) {
 	t.Parallel()
 
-	s := startDiscriminator(t, "", map[string]string{mode: observe, wafMode: block})
-	req := s.question(siteA, client, "/")
-	req.Header.Set(cookieHeader, strings.Repeat("a;", 16000))
+	got, took, line := askWithSixteenThousandCookies(t,
+		map[string]string{mode: observe, wafMode: block})
 
-	got := do(t, req)
+	if took >= answerTimeLimit/2 {
+		t.Errorf("answered after %s, want well within %s", took, answerTimeLimit)
+	}
 
 	wantDisposition(t, got, http.StatusOK, discriminator.DispositionAllow)
 
-	line := s.out.requestLine(t)
 	if line.WouldAction != requestlog.ActionRequestHeaderTooLarge ||
 		line.DurationCoreRuleSetMS != nil {
 		t.Errorf("would_action %q and duration_core_rule_set_ms %v, want %q and none",
@@ -336,10 +363,10 @@ func newDiscriminatorInBubble(
 }
 
 // askDirectly hands a question about a request from client straight to server,
-// as change leaves it, and returns the answer's status and how long it took.
+// as change leaves it, and returns the answer and how long it took.
 func askDirectly(
 	t *testing.T, server *discriminator.Server, change func(*http.Request),
-) (int, time.Duration) {
+) (answer, time.Duration) {
 	t.Helper()
 
 	req := httptest.NewRequestWithContext(t.Context(), http.MethodGet, "/", http.NoBody)
@@ -353,7 +380,9 @@ func askDirectly(
 
 	server.Handler.ServeHTTP(recorder, req)
 
-	return recorder.Code, time.Since(began)
+	took := time.Since(began)
+
+	return readAnswer(recorder.Result()), took
 }
 
 // banClient bans client at now.
@@ -446,13 +475,13 @@ func TestARefusedRequestDoesNotWaitForASlowGeoJS(t *testing.T) {
 				server, out := newDiscriminatorInBubble(t, tc.env)
 				tc.prepare(t, server, time.Now())
 
-				status, took := askDirectly(t, server, func(req *http.Request) {
+				got, took := askDirectly(t, server, func(req *http.Request) {
 					req.Header.Set(cookieHeader, tc.cookie)
 				})
 
-				if status != tc.status || took != 0 {
+				if got.status != tc.status || took != 0 {
 					t.Errorf("answered %d after %s, want %d at once; output:\n%s",
-						status, took, tc.status, out.text())
+						got.status, took, tc.status, out.text())
 				}
 
 				wantLine(t, out.requestLine(t), tc.status, tc.action)
@@ -503,11 +532,11 @@ func TestAQuestionWaitsForASlowGeoJSOnlyAsLongAsTheDefaultSays(t *testing.T) {
 				server, out := newDiscriminatorInBubble(t, tc.env)
 				tc.prepare(t, server, time.Now())
 
-				status, took := askDirectly(t, server, func(*http.Request) {})
+				got, took := askDirectly(t, server, func(*http.Request) {})
 
-				if status != tc.status || took != defaultLookupWait {
+				if got.status != tc.status || took != defaultLookupWait {
 					t.Errorf("answered %d after %s, want %d after %s; output:\n%s",
-						status, took, tc.status, defaultLookupWait, out.text())
+						got.status, took, tc.status, defaultLookupWait, out.text())
 				}
 
 				wantLine(t, out.requestLine(t), tc.status, tc.action)
@@ -551,15 +580,15 @@ func TestDiscriminatorAnswersWithinTheTimeLimitWhileEveryOutsideSourceHangs(
 
 	go server.Lists.Run(t.Context())
 
-	status, took := askDirectly(t, server, func(req *http.Request) {
+	got, took := askDirectly(t, server, func(req *http.Request) {
 		req.Header.Set("User-Agent", "test")
 		req.Header.Set("Accept", "*/*")
 		req.Host = siteA
 	})
 
-	if status != http.StatusOK || took >= answerTimeLimit {
+	if got.status != http.StatusOK || took >= answerTimeLimit {
 		t.Errorf("answered %d after %s, want %d within %s; output:\n%s",
-			status, took, http.StatusOK, answerTimeLimit, out.text())
+			got.status, took, http.StatusOK, answerTimeLimit, out.text())
 	}
 
 	// Each outside source was asked, and none has answered. The stand-in for