rproxy: leave no visitor without an answer as the response time runs out (closes #295)

A visitor could get a closed connection and no answer when
SWRP_MAX_RESPONSE_TIME_MS ran out about when the answer started: the
write deadline passed before the first byte was written.

- An answer rproxy gives itself has at least 10 seconds to be sent.
- An app's answer that arrives once the time has run out is answered
  504.
- Otherwise the app's status and headers are sent at once, before the
  body is read, with at least 10 seconds. The exact limit applies to
  the rest.

Model: opus-5-5

internal/rproxy/bodies.go

@@ -163,6 +163,8 @@ type responseWriter struct {
 	// status is the final status sent, or zero before one is.
 	status int
 	bytes  int64
+	// afterStatus, if set, is called once the final status has been written.
+	afterStatus func()
 }
 
 // WriteHeader sends the status and headers. An informational 1xx status is
@@ -173,6 +175,10 @@ func (w *responseWriter) WriteHeader(status int) {
 	}
 
 	w.ResponseWriter.WriteHeader(status)
+
+	if status >= http.StatusOK && w.afterStatus != nil {
+		w.afterStatus()
+	}
 }
 
 // Write sends part of the body.

internal/rproxy/limits_test.go

@@ -481,6 +481,30 @@ func TestAnAnswerRProxyGivesItselfHasTheResponseTimeToBeSent(t *testing.T) {
 	}
 }
 
+func TestAnAnswerRProxyGivesItselfHasTenSecondsToBeSentAtLeast(t *testing.T) {
+	t.Parallel()
+
+	const least = 10 * time.Second
+
+	standIn := startDiscriminator(t, deny)
+	app := startApp(t, greet)
+	_, _, server := startServer(t, standIn.URL, app.URL, map[string]string{
+		maxResponseTime: "300",
+	})
+
+	req := httptest.NewRequestWithContext(t.Context(), http.MethodGet, "/", http.NoBody)
+	w := &deadlineRecorder{ResponseRecorder: httptest.NewRecorder()}
+
+	before := time.Now()
+
+	server.Handler.ServeHTTP(w, req)
+
+	if w.writeDeadline.Before(before.Add(least)) {
+		t.Errorf("the time limit on sending ends at %s, want %s from the answer at least",
+			w.writeDeadline, least)
+	}
+}
+
 func TestAVisitorTooSlowToSendTheRestIsAnswered408(t *testing.T) {
 	t.Parallel()
 
@@ -601,6 +625,68 @@ func TestAnAppTooSlowToAnswerIsAnswered504(t *testing.T) {
 	}
 }
 
+func TestAVisitorGetsAnAnswerWhenTheAppAnswersAsTheTimeRunsOut(t *testing.T) {
+	t.Parallel()
+
+	// Four visitors at a time, each with an app and rproxy of its own, send more
+	// requests in the same time.
+	for visitor := range 4 {
+		t.Run(strconv.Itoa(visitor), func(t *testing.T) {
+			t.Parallel()
+
+			visitAsTheTimeRunsOut(t)
+		})
+	}
+}
+
+// visitAsTheTimeRunsOut sends requests to an app that answers about as
+// SWRP_MAX_RESPONSE_TIME_MS runs out, and checks that each is answered with the
+// app's 200 or a 504.
+func visitAsTheTimeRunsOut(t *testing.T) {
+	t.Helper()
+
+	const limit = 50 * time.Millisecond
+
+	// answerAfter is how long the app waits before it answers.
+	var answerAfter atomic.Int64
+
+	backend := startDiscriminatorAnsweringReports(t, allow,
+		func(w http.ResponseWriter, _ *http.Request) {
+			w.WriteHeader(http.StatusNoContent)
+		})
+	app := startApp(t, func(w http.ResponseWriter, _ *http.Request) {
+		time.Sleep(time.Duration(answerAfter.Load()))
+
+		_, _ = io.WriteString(w, greeting)
+	})
+	addr, _ := startRProxy(t, backend, app.URL, map[string]string{
+		maxResponseTime: strconv.FormatInt(limit.Milliseconds(), 10),
+	})
+
+	// After each 200 the app answers a little later, and after each 504 a little
+	// sooner, so that most of its answers arrive as the time runs out.
+	delay, step := limit/2, limit/4
+
+	for range 60 {
+		answerAfter.Store(int64(delay))
+
+		conn := dial(t, addr)
+		send(t, conn, "GET / HTTP/1.1\r\nHost: site.example\r\n\r\n")
+
+		switch status := readStatus(t, conn); status {
+		case http.StatusOK:
+			delay += step
+		case http.StatusGatewayTimeout:
+			delay -= step
+		default:
+			t.Fatalf("status %d, want the app's 200 or 504", status)
+		}
+
+		_ = conn.Close()
+		step = max(step/2, 20*time.Microsecond)
+	}
+}
+
 func TestAnAppTooSlowToFinishItsAnswerIsCutOff(t *testing.T) {
 	t.Parallel()
 

internal/rproxy/request.go

@@ -32,6 +32,17 @@ const reportStatusMax = 599
 // plainText is the Content-Type of the answers rproxy gives itself.
 const plainText = "text/plain; charset=utf-8"
 
+// minSendTime is the least time to send an answer rproxy gives itself, or the
+// status and headers of the app's answer. A shorter time can run out before the
+// first byte is written, on a busy host or as SWRP_MAX_RESPONSE_TIME_MS runs out,
+// and the visitor then gets a closed connection and no answer.
+const minSendTime = 10 * time.Second
+
+// errResponseTooLate refuses an app's answer that arrives once
+// SWRP_MAX_RESPONSE_TIME_MS has run out.
+var errResponseTooLate = errors.New(
+	"the answer arrived after SWRP_MAX_RESPONSE_TIME_MS ran out")
+
 // request is one request on its way through rproxy, from the moment its headers
 // have been read to its log line and report.
 type request struct {
@@ -237,6 +248,17 @@ func (rq *request) modifyResponse(res *http.Response) error {
 		return nil
 	}
 
+	requestEnd := rq.endRequest()
+
+	// An answer that arrives once SWRP_MAX_RESPONSE_TIME_MS has run out is not
+	// passed on: the visitor is answered 504.
+	limit := rq.h.config.MaxResponseTime
+	if limit > 0 && !time.Now().Before(requestEnd.Add(limit)) {
+		rq.refuse(http.StatusGatewayTimeout)
+
+		return errResponseTooLate
+	}
+
 	maxBytes := rq.h.config.MaxResponseSize
 	if maxBytes > 0 && res.Body != http.NoBody && res.ContentLength > maxBytes {
 		rq.refuse(http.StatusBadGateway)
@@ -252,7 +274,7 @@ func (rq *request) modifyResponse(res *http.Response) error {
 	}
 
 	res.Body = &responseBody{body: limitBody(res.Body, maxBytes), rq: rq}
-	rq.setResponseDeadline()
+	rq.out.afterStatus = rq.setResponseDeadline
 
 	return nil
 }
@@ -326,14 +348,14 @@ func (rq *request) send(status int, body []byte) {
 // 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
-// used that time up first.
+// used that time up first, and at least minSendTime.
 func (rq *request) prepareOwnAnswer(deadline time.Time) {
 	rq.stopReadingBody(deadline)
 	rq.endRequest()
 
 	limit := rq.h.config.MaxResponseTime
 	if limit > 0 {
-		_ = rq.rc.SetWriteDeadline(time.Now().Add(limit))
+		_ = rq.rc.SetWriteDeadline(time.Now().Add(max(limit, minSendTime)))
 	}
 }
 
@@ -549,16 +571,20 @@ func (rq *request) responseReceived() {
 	rq.stopTimers()
 }
 
-// setResponseDeadline sets SWRP_MAX_RESPONSE_TIME_MS on the connection to the
-// visitor: the app's answer must reach the visitor within it of the end of the
-// request.
+// setResponseDeadline sends the status and headers of the app's answer, with
+// at least minSendTime, before ReverseProxy reads the answer's body, and then
+// the rest has until SWRP_MAX_RESPONSE_TIME_MS after the end of the request.
 func (rq *request) setResponseDeadline() {
-	requestEnd := rq.endRequest()
-
 	limit := rq.h.config.MaxResponseTime
-	if limit > 0 {
-		_ = rq.rc.SetWriteDeadline(requestEnd.Add(limit))
+	if limit == 0 {
+		return
 	}
+
+	deadline := rq.endRequest().Add(limit)
+
+	_ = rq.rc.SetWriteDeadline(time.Now().Add(max(time.Until(deadline), minSendTime)))
+	_ = rq.rc.Flush()
+	_ = rq.rc.SetWriteDeadline(deadline)
 }
 
 // endRequest notes now as the end of the request, unless an end is noted, and