Core Rule Set tests: only the concurrency test runs with the race detector (closes #306)

Of internal/coreruleset's tests, the race pass runs only those written to
check concurrent inspection, selected by the name prefix TestConcurrent.
Every other test of the package moves to the pass that runs the recorded
requests, without the race detector. Other packages run under -race as
before. The 90-second limit stays.

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`.

SPEC.md

@@ -2355,6 +2355,10 @@ These limits apply per request, in both directions:
   than 10 seconds. The status and headers of the app's answer also have at least
   10 seconds to be sent.
 
+`rproxy` may give its own answer, such as a refusal, before the visitor has sent
+its whole body. The visitor gets that answer at once, and the connection closes
+after it.
+
 The largest request line and headers is 32 KiB. A kept-open connection is closed
 after 120 seconds idle. Neither has a setting. traefik, by default, closes an
 unused connection after 90 seconds. So traefik closes first, and never sends a

internal/rproxy/limits_test.go

@@ -974,7 +974,7 @@ func TestTheRequestTimeLimitDoesNotCutAnAnswerOnceTheAppHasTheRequest(t *testing
 	}
 }
 
-func TestAVisitorThatStopsSendingGetsAnAnswerRProxyGivesByTheDeadline(t *testing.T) {
+func TestAVisitorThatStopsALittleShortGetsAnAnswerRProxyGivesAtOnce(t *testing.T) {
 	t.Parallel()
 
 	for _, tc := range []struct {
@@ -993,14 +993,15 @@ func TestAVisitorThatStopsSendingGetsAnAnswerRProxyGivesByTheDeadline(t *testing
 
 			standIn := startDiscriminator(t, deny)
 			app := startApp(t, greet)
-			// The time limit is long enough for a loaded host to read the first part of
-			// the body before it runs out.
+			// The request time limit is longer than the 10 seconds an answer rproxy
+			// gives itself has to be sent, and than dial's deadline.
 			addr, _ := startRProxy(t, standIn.URL, app.URL, map[string]string{
-				maxRequestTime: "3000",
+				maxRequestTime:  "15000",
+				maxResponseTime: "300",
 			})
 
-			// Go's server waits for a little of the body left before it sends an answer,
-			// and the time for sending the request ends that wait.
+			// The body stops 100 bytes short, less than Go's server reads of a body
+			// left unread before it answers.
 			conn := dial(t, addr)
 			send(t, conn, tc.start+announcedLength(questionBodyMaxBytes+100)+
 				strings.Repeat("x", questionBodyMaxBytes))

internal/rproxy/request.go

@@ -83,8 +83,8 @@ type request struct {
 	upgraded *upgradedConn
 
 	// mu guards what follows. The time limits run on goroutines of their own,
-	// and the transport starts and stops them, and notes the times below, from
-	// its own; once timersStopped is set, neither time limit acts any more.
+	// and the transport starts and stops them, and notes requestEnd, from its
+	// own; once timersStopped is set, neither time limit acts any more.
 	mu            sync.Mutex
 	timersStopped bool
 	requestTimer  *time.Timer
@@ -92,8 +92,6 @@ type request struct {
 	// requestEnd is when the app had been sent the whole request, or the answer
 	// started, if that was sooner.
 	requestEnd time.Time
-	// answerStarted is when the first byte of the app's answer arrived.
-	answerStarted time.Time
 }
 
 // newRequest starts handling r: it notes the time, works out the visitor from
@@ -177,8 +175,7 @@ func (rq *request) forward(ctx context.Context) {
 
 	rq.cancel = cancel
 	ctx = httptrace.WithClientTrace(ctx, &httptrace.ClientTrace{
-		WroteRequest:         rq.wroteRequest,
-		GotFirstResponseByte: rq.gotFirstResponseByte,
+		WroteRequest: rq.wroteRequest,
 	})
 
 	out := rq.in.WithContext(ctx)
@@ -273,12 +270,7 @@ func (rq *request) modifyResponse(res *http.Response) error {
 		rq.out.Header()["Content-Type"] = nil
 	}
 
-	// Go's server reads up to 256 KiB of a body left unread before it sends an
-	// answer, and so waits on a visitor that has stopped sending. With this
-	// header it sends the answer at once, and closes the connection after it.
-	if rq.body != nil && !rq.body.received.Load() {
-		rq.out.Header().Set("Connection", "close")
-	}
+	rq.closeAfterAnswer()
 
 	res.Body = &responseBody{body: limitBody(res.Body, maxBytes), rq: rq}
 	rq.out.afterStatus = rq.setResponseDeadline
@@ -347,11 +339,22 @@ func (rq *request) send(status int, body []byte) {
 		rq.out.Header().Set("Content-Length", strconv.Itoa(len(body)))
 	}
 
+	rq.closeAfterAnswer()
 	rq.out.WriteHeader(status)
 	_, _ = rq.out.Write(body)
 	_ = rq.rc.Flush()
 }
 
+// closeAfterAnswer has Go's server send the answer at once, and close the
+// connection after it, when the visitor's body has not arrived whole. Without
+// it, Go's server reads up to 256 KiB of the body left before it sends an
+// answer, and so waits on a visitor that has stopped sending.
+func (rq *request) closeAfterAnswer() {
+	if rq.body != nil && !rq.body.received.Load() {
+		rq.out.Header().Set("Connection", "close")
+	}
+}
+
 // prepareOwnAnswer readies the connection for an answer rproxy gives itself: the
 // reading of a body that has not arrived whole ends at deadline, and the answer
 // has SWRP_MAX_RESPONSE_TIME_MS from now to reach the visitor, even when the app
@@ -517,16 +520,6 @@ func (rq *request) requestTimedOut() {
 	}
 
 	if rq.body == nil || !rq.body.waiting.Load() {
-		// Once the app has answered, Go's server can read what is left of a body
-		// under 256 KiB without requestBody.Read, before an answer rproxy gives
-		// itself, so waiting is false while that read waits for the visitor.
-		// That read ends now, before refuse:
-		// should rproxy still answer itself, answer then sets the deadline it
-		// gives its own answers.
-		if !rq.answerStarted.IsZero() {
-			rq.stopReadingBody(time.Now())
-		}
-
 		rq.refuse(http.StatusGatewayTimeout)
 
 		return
@@ -539,15 +532,6 @@ func (rq *request) requestTimedOut() {
 	_ = rq.rc.SetReadDeadline(time.Now())
 }
 
-// gotFirstResponseByte is called once the first byte of the app's answer has
-// arrived.
-func (rq *request) gotFirstResponseByte() {
-	rq.mu.Lock()
-	defer rq.mu.Unlock()
-
-	rq.answerStarted = time.Now()
-}
-
 // wroteRequest is called once the app has been sent the whole request:
 // SWRP_MAX_REQUEST_TIME_MS ends and SWRP_MAX_RESPONSE_TIME_MS starts.
 func (rq *request) wroteRequest(info httptrace.WroteRequestInfo) {