Discriminator tests: stop timing the sixteen-thousand-cookie requests (closes #308)

The two tests that send sixteen thousand cookies checked the answer time
on the wall clock, which a busy host can push past the bound. They no
longer check how long the answer took. The first is renamed to say what
it checks: a 431 before the Core Rule Set reads the request.

TestARefusedRequestDoesNotWaitForASlowGeoJS still checks that a refusal
over the header limits waits on nothing.

Model: opus-5-5

Dockerfile

@@ -42,20 +42,35 @@ 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 \
-    go test -tags no_fs_access -timeout 90s -race -cover ./... || \
+    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; } || \
     { echo "--- Rerunning with -v for details ---"; \
-      go test -tags no_fs_access -timeout 90s -race -v ./...; exit 1; }
+      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; }
 
-# Second pass: the recorded requests, too slow for make test under -race.
+# Second pass: every other test of the Core Rule Set, the recorded requests
+# among them, without the race detector.
 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 -run '^TestOrdinary' ./internal/coreruleset/... || \
+    go test -tags no_fs_access,recorded -timeout 90s -cover \
+        -skip '^TestConcurrent' ./internal/coreruleset || \
     { echo "--- Rerunning with -v for details ---"; \
-      go test -tags no_fs_access,recorded -timeout 90s -run '^TestOrdinary' -v ./internal/coreruleset/...; exit 1; }
+      go test -tags no_fs_access,recorded -timeout 90s -v \
+        -skip '^TestConcurrent' ./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,8 +702,12 @@ 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`. It runs them twice: once with
-  the race detector, and once without it for the recorded requests. `make test`.
+  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.
 - `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,45 +67,18 @@ func fillHeaders(req *http.Request, total int) {
 	}
 }
 
-// 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) {
+func TestSixteenThousandCookiesAreRefusedBeforeTheCoreRuleSetReadsThem(t *testing.T) {
 	t.Parallel()
 
-	got, took, line := askWithSixteenThousandCookies(t, map[string]string{wafMode: block})
+	s := startDiscriminator(t, "", map[string]string{wafMode: block})
+	req := s.question(siteA, client, "/")
+	req.Header.Set(cookieHeader, strings.Repeat("a;", 16000))
 
-	if took >= answerTimeLimit/2 {
-		t.Errorf("answered after %s, want well within %s", took, answerTimeLimit)
-	}
+	got := do(t, req)
 
 	wantDisposition(t, got, tooLarge, discriminator.DispositionDeny)
+
+	line := s.out.requestLine(t)
 	wantLine(t, line, tooLarge, requestlog.ActionRequestHeaderTooLarge)
 
 	if line.DurationCoreRuleSetMS != nil {
@@ -227,15 +200,15 @@ func TestClientInTheAllowNetsSkipsTheHeaderLimits(t *testing.T) {
 func TestObserveModeAllowsARequestOverTheHeaderLimitsUnread(t *testing.T) {
 	t.Parallel()
 
-	got, took, line := askWithSixteenThousandCookies(t,
-		map[string]string{mode: observe, wafMode: block})
+	s := startDiscriminator(t, "", map[string]string{mode: observe, wafMode: block})
+	req := s.question(siteA, client, "/")
+	req.Header.Set(cookieHeader, strings.Repeat("a;", 16000))
 
-	if took >= answerTimeLimit/2 {
-		t.Errorf("answered after %s, want well within %s", took, answerTimeLimit)
-	}
+	got := do(t, req)
 
 	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",
@@ -363,10 +336,10 @@ func newDiscriminatorInBubble(
 }
 
 // askDirectly hands a question about a request from client straight to server,
-// as change leaves it, and returns the answer and how long it took.
+// as change leaves it, and returns the answer's status and how long it took.
 func askDirectly(
 	t *testing.T, server *discriminator.Server, change func(*http.Request),
-) (answer, time.Duration) {
+) (int, time.Duration) {
 	t.Helper()
 
 	req := httptest.NewRequestWithContext(t.Context(), http.MethodGet, "/", http.NoBody)
@@ -380,9 +353,7 @@ func askDirectly(
 
 	server.Handler.ServeHTTP(recorder, req)
 
-	took := time.Since(began)
-
-	return readAnswer(recorder.Result()), took
+	return recorder.Code, time.Since(began)
 }
 
 // banClient bans client at now.
@@ -475,13 +446,13 @@ func TestARefusedRequestDoesNotWaitForASlowGeoJS(t *testing.T) {
 				server, out := newDiscriminatorInBubble(t, tc.env)
 				tc.prepare(t, server, time.Now())
 
-				got, took := askDirectly(t, server, func(req *http.Request) {
+				status, took := askDirectly(t, server, func(req *http.Request) {
 					req.Header.Set(cookieHeader, tc.cookie)
 				})
 
-				if got.status != tc.status || took != 0 {
+				if status != tc.status || took != 0 {
 					t.Errorf("answered %d after %s, want %d at once; output:\n%s",
-						got.status, took, tc.status, out.text())
+						status, took, tc.status, out.text())
 				}
 
 				wantLine(t, out.requestLine(t), tc.status, tc.action)
@@ -532,11 +503,11 @@ func TestAQuestionWaitsForASlowGeoJSOnlyAsLongAsTheDefaultSays(t *testing.T) {
 				server, out := newDiscriminatorInBubble(t, tc.env)
 				tc.prepare(t, server, time.Now())
 
-				got, took := askDirectly(t, server, func(*http.Request) {})
+				status, took := askDirectly(t, server, func(*http.Request) {})
 
-				if got.status != tc.status || took != defaultLookupWait {
+				if status != tc.status || took != defaultLookupWait {
 					t.Errorf("answered %d after %s, want %d after %s; output:\n%s",
-						got.status, took, tc.status, defaultLookupWait, out.text())
+						status, took, tc.status, defaultLookupWait, out.text())
 				}
 
 				wantLine(t, out.requestLine(t), tc.status, tc.action)
@@ -580,15 +551,15 @@ func TestDiscriminatorAnswersWithinTheTimeLimitWhileEveryOutsideSourceHangs(
 
 	go server.Lists.Run(t.Context())
 
-	got, took := askDirectly(t, server, func(req *http.Request) {
+	status, took := askDirectly(t, server, func(req *http.Request) {
 		req.Header.Set("User-Agent", "test")
 		req.Header.Set("Accept", "*/*")
 		req.Host = siteA
 	})
 
-	if got.status != http.StatusOK || took >= answerTimeLimit {
+	if status != http.StatusOK || took >= answerTimeLimit {
 		t.Errorf("answered %d after %s, want %d within %s; output:\n%s",
-			got.status, took, http.StatusOK, answerTimeLimit, out.text())
+			status, took, http.StatusOK, answerTimeLimit, out.text())
 	}
 
 	// Each outside source was asked, and none has answered. The stand-in for