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

The race pass runs TestConcurrentRequestsKeepTheirOwnExclusions alone of
internal/coreruleset's tests; 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

@@ -44,20 +44,20 @@ RUN go mod tidy -diff || \
 # 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.
+# at once. Of the Core Rule Set's tests, only
+# TestConcurrentRequestsKeepTheirOwnExclusions inspects requests that way,
+# so it is the only one of them in this pass. 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; } || \
+        -run '^TestConcurrentRequestsKeepTheirOwnExclusions$' ./internal/coreruleset; } || \
     { 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; \
+        -run '^TestConcurrentRequestsKeepTheirOwnExclusions$' ./internal/coreruleset; \
       exit 1; }
 
 # Second pass: every other test of the Core Rule Set, the recorded requests
@@ -66,10 +66,10 @@ 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 || \
+        -skip '^TestConcurrentRequestsKeepTheirOwnExclusions$' ./internal/coreruleset || \
     { echo "--- Rerunning with -v for details ---"; \
       go test -tags no_fs_access,recorded -timeout 90s -v \
-        -skip '^TestConcurrent' ./internal/coreruleset; \
+        -skip '^TestConcurrentRequestsKeepTheirOwnExclusions$' ./internal/coreruleset; \
       exit 1; }
 
 # The test phase that script/test and the build stage name. Nothing is

README.md

@@ -704,8 +704,8 @@ on the host.
 - `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`.
+      Rule Set's tests, it runs only the one that inspects requests from several
+      goroutines at once.
     - 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

SPEC.md

@@ -2355,10 +2355,6 @@ 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 TestAVisitorThatStopsALittleShortGetsAnAnswerRProxyGivesAtOnce(t *testing.T) {
+func TestAVisitorThatStopsSendingGetsAnAnswerRProxyGivesByTheDeadline(t *testing.T) {
 	t.Parallel()
 
 	for _, tc := range []struct {
@@ -993,15 +993,14 @@ func TestAVisitorThatStopsALittleShortGetsAnAnswerRProxyGivesAtOnce(t *testing.T
 
 			standIn := startDiscriminator(t, deny)
 			app := startApp(t, greet)
-			// The request time limit is longer than the 10 seconds an answer rproxy
-			// gives itself has to be sent, and than dial's deadline.
+			// The time limit is long enough for a loaded host to read the first part of
+			// the body before it runs out.
 			addr, _ := startRProxy(t, standIn.URL, app.URL, map[string]string{
-				maxRequestTime:  "15000",
-				maxResponseTime: "300",
+				maxRequestTime: "3000",
 			})
 
-			// The body stops 100 bytes short, less than Go's server reads of a body
-			// left unread before it answers.
+			// 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.
 			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 requestEnd, from its
-	// own; once timersStopped is set, neither time limit acts any more.
+	// 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.
 	mu            sync.Mutex
 	timersStopped bool
 	requestTimer  *time.Timer
@@ -92,6 +92,8 @@ 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
@@ -175,7 +177,8 @@ func (rq *request) forward(ctx context.Context) {
 
 	rq.cancel = cancel
 	ctx = httptrace.WithClientTrace(ctx, &httptrace.ClientTrace{
-		WroteRequest: rq.wroteRequest,
+		WroteRequest:         rq.wroteRequest,
+		GotFirstResponseByte: rq.gotFirstResponseByte,
 	})
 
 	out := rq.in.WithContext(ctx)
@@ -270,7 +273,12 @@ func (rq *request) modifyResponse(res *http.Response) error {
 		rq.out.Header()["Content-Type"] = nil
 	}
 
-	rq.closeAfterAnswer()
+	// 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")
+	}
 
 	res.Body = &responseBody{body: limitBody(res.Body, maxBytes), rq: rq}
 	rq.out.afterStatus = rq.setResponseDeadline
@@ -339,22 +347,11 @@ 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
@@ -520,6 +517,16 @@ 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
@@ -532,6 +539,15 @@ 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) {