From fb13d37fa0cb3c8521bd9b34102a3ab63779bc8e Mon Sep 17 00:00:00 2001 From: sneak Date: Tue, 10 Nov 2026 17:11:13 +0000 Subject: [PATCH] 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 | 4 +- docs/settings.md | 5 +- internal/rproxy/bodies.go | 6 +++ internal/rproxy/limits_test.go | 86 ++++++++++++++++++++++++++++++++++ internal/rproxy/request.go | 47 +++++++++++++++---- 5 files changed, 136 insertions(+), 12 deletions(-) diff --git a/SPEC.md b/SPEC.md index 5cdaea5..207400c 100644 --- a/SPEC.md +++ b/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 diff --git a/docs/settings.md b/docs/settings.md index 18b7dee..d6e36de 100644 --- a/docs/settings.md +++ b/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. diff --git a/internal/rproxy/bodies.go b/internal/rproxy/bodies.go index 4bd20d1..4487562 100644 --- a/internal/rproxy/bodies.go +++ b/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. diff --git a/internal/rproxy/limits_test.go b/internal/rproxy/limits_test.go index 57224e7..9b24130 100644 --- a/internal/rproxy/limits_test.go +++ b/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() diff --git a/internal/rproxy/request.go b/internal/rproxy/request.go index 9c7b224..7b6e55c 100644 --- a/internal/rproxy/request.go +++ b/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