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

SPEC.md

@@ -2245,7 +2245,9 @@ These limits apply per request, in both directions:
 - `SWRP_MAX_RESPONSE_TIME_MS` runs from the end of the request to the last byte
   of the answer reaching the visitor. The request ends when the app has been
   sent all of it, or when the app's answer arrives if that is sooner. An answer
-  `rproxy` gives itself has the whole time from when it starts.
+  `rproxy` gives itself has the whole time from when it starts, and never less
+  than 10 seconds. The status and headers of the app's answer also have at least
+  10 seconds to be sent.
 
 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

docs/settings.md

@@ -436,8 +436,9 @@ A time here is a whole number of milliseconds above zero, such as `2000`.
   headers, the time until the app has been sent the whole request. A time or
   `off`.
 - `SWRP_MAX_RESPONSE_TIME_MS` (default `1800000`): how long the answer may take,
-  from the end of the request to its last byte reaching the visitor. A time or
-  `off`.
+  from the end of the request to its last byte reaching the visitor. An answer
+  `rproxy` gives itself always has at least 10 seconds to be sent, and so do the
+  status and headers of the app's answer. A time or `off`.
 - `SWRP_LISTEN_ADDR` (default `:8080`): where `rproxy` listens, such as `:9000`.
 - `SWRP_UPSTREAM_URL` (default `http://127.0.0.1:8081`): the app. An `http` or
   `https` URL with a host and an optional port, and nothing more.

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)))
 	}
 }
 
@@ -550,15 +572,22 @@ func (rq *request) responseReceived() {
 }
 
 // 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.
+// visitor once ReverseProxy has written the status of the app's answer: the
+// answer must reach the visitor within it of the end of the request. First it
+// sends the status and headers, with minSendTime at least, before ReverseProxy
+// reads the body: the time running out can still cut the answer off, but the
+// visitor never gets a closed connection with no answer at all.
 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