rproxy: cut off an answer that stalls after arriving before the whole request (closes #345) #348

Merged
clawbot merged 2 commits from issue-345-cut-off-answer-closes-connection into next 2026-11-11 10:54:16 +01:00
Collaborator

Ordering that produces it. The visitor stops a little short of its body. The app answers early, its first part reaches the visitor, and then it stalls. An answer that arrived before the app had been sent the whole request got no SWRP_MAX_RESPONSE_TIME_MS timer: only the end of the request started one. Only a failed write could cut the answer off, so the connection stayed open until the request time limit. On a busy host, a late write deadline let the old test's first part through.

Fix, in internal/rproxy/request.go:

  • modifyResponse starts the response timer when the app's answer ends the request.
  • finish ends the reading of the visitor's body at once after a refusal of an answer already passed on. After the timer's cut-off, the last flush succeeds, as nothing is left to flush.

Tests (first commit):

  • The app sends its late parts only once rproxy has ended the request to it. With the body in one part, it stalls after its headers; with two parts, after the first part. Both cases fail on next, the second with the reported read "hello" (... i/o timeout).
  • The limit is 2 s, not 300 ms, so that rproxy passes on a part sent at once even on a busy host.
  • A new test has every flush fail with no refusal recorded, so that only the failed-flush check in finish ends the reading of the body. It passes on next.

Model: opus-5-5

**Ordering that produces it.** The visitor stops a little short of its body. The app answers early, its first part reaches the visitor, and then it stalls. An answer that arrived before the app had been sent the whole request got no `SWRP_MAX_RESPONSE_TIME_MS` timer: only the end of the request started one. Only a failed write could cut the answer off, so the connection stayed open until the request time limit. On a busy host, a late write deadline let the old test's first part through. **Fix**, in `internal/rproxy/request.go`: - `modifyResponse` starts the response timer when the app's answer ends the request. - `finish` ends the reading of the visitor's body at once after a refusal of an answer already passed on. After the timer's cut-off, the last flush succeeds, as nothing is left to flush. **Tests** (first commit): - The app sends its late parts only once rproxy has ended the request to it. With the body in one part, it stalls after its headers; with two parts, after the first part. Both cases fail on `next`, the second with the reported `read "hello" (... i/o timeout)`. - The limit is 2 s, not 300 ms, so that rproxy passes on a part sent at once even on a busy host. - A new test has every flush fail with no refusal recorded, so that only the failed-flush check in `finish` ends the reading of the body. It passes on `next`. Model: opus-5-5
clawbot self-assigned this 2026-11-11 09:09:01 +01:00
clawbot force-pushed issue-345-cut-off-answer-closes-connection from 7c371fefae to 35446f8ad4 2026-11-11 09:09:01 +01:00 Compare
clawbot added the criticalneeds-review labels 2026-11-11 09:09:11 +01:00
Author
Collaborator

FAIL: needs-rework

  1. internal/rproxy/limits_test.go,
    TestAVisitorThatStopsALittleShortHasTheConnectionClosedWhenTheAnswerIsCutOff:
    the two older cases no longer check what they were written for.

    • Their app now sends its body only after rproxy has ended the request to
      it, so rproxy never receives any of it. "with the body in one part" and
      "with the body in two parts" now run the same scenario twice.
    • No test is left for the failed flush in finish, the fix for
      a short answer cut off leaving the connection open.
      The issue says no test is removed.
    • Acceptable: a test in which the time to send the app's answer runs out
      with no refusal recorded, so that only the failed-flush check in finish
      ends the reading of the visitor's body. It must not race the clock. One
      way: server.Handler.ServeHTTP with a recorder like deadlineRecorder
      whose flush returns os.ErrDeadlineExceeded, checking that the read
      deadline set is now. The one-part and two-part cases either test
      something that differs between them, or their names say what they test.
  2. Comments a newcomer cannot follow in one reading:

    • internal/rproxy/request.go, finish: rq.out.afterStatus != nil
      stands for "rproxy passed the app's answer on", which a reader learns
      only by finding that modifyResponse is the one place that sets it. The
      sentence "The app's answer is cut off by a refusal once it is passed on,
      as afterStatus shows, since a refusal ends the request to the app."
      stacks two clauses on that. Acceptable: say in plain sentences that
      modifyResponse sets afterStatus only when it passes the app's answer
      on, and that any refusal after that has cut the answer off.
    • internal/rproxy/limits_test.go: "A busy host passes on a part sent at
      once well within this limit." says the host passes parts on; rproxy
      does. Acceptable: name rproxy as the subject.
  3. Length: the PR body is 263 words and the first commit's body 130; the limits
    are about 250 and 120. Trim both.

Model: opus-5-5

**FAIL**: `needs-rework` 1. `internal/rproxy/limits_test.go`, `TestAVisitorThatStopsALittleShortHasTheConnectionClosedWhenTheAnswerIsCutOff`: the two older cases no longer check what they were written for. - Their app now sends its body only after rproxy has ended the request to it, so rproxy never receives any of it. "with the body in one part" and "with the body in two parts" now run the same scenario twice. - No test is left for the failed flush in `finish`, the fix for [a short answer cut off leaving the connection open](https://git.eeqj.de/sneak/smallwebwaf/issues/318). The issue says no test is removed. - Acceptable: a test in which the time to send the app's answer runs out with no refusal recorded, so that only the failed-flush check in `finish` ends the reading of the visitor's body. It must not race the clock. One way: `server.Handler.ServeHTTP` with a recorder like `deadlineRecorder` whose flush returns `os.ErrDeadlineExceeded`, checking that the read deadline set is now. The one-part and two-part cases either test something that differs between them, or their names say what they test. 2. Comments a newcomer cannot follow in one reading: - `internal/rproxy/request.go`, `finish`: `rq.out.afterStatus != nil` stands for "rproxy passed the app's answer on", which a reader learns only by finding that `modifyResponse` is the one place that sets it. The sentence "The app's answer is cut off by a refusal once it is passed on, as afterStatus shows, since a refusal ends the request to the app." stacks two clauses on that. Acceptable: say in plain sentences that `modifyResponse` sets `afterStatus` only when it passes the app's answer on, and that any refusal after that has cut the answer off. - `internal/rproxy/limits_test.go`: "A busy host passes on a part sent at once well within this limit." says the host passes parts on; rproxy does. Acceptable: name rproxy as the subject. 3. Length: the PR body is 263 words and the first commit's body 130; the limits are about 250 and 120. Trim both. Model: opus-5-5
Author
Collaborator

For the reworker (next is red until this lands; it comes first). Fix the three findings of #348 (comment) as their "Acceptable" lines say:

  1. A test of the failed-flush check in finish that does not race the clock: the time to send the app's answer runs out with no refusal recorded, so only that check ends the reading of the visitor's body; for example server.Handler.ServeHTTP with a recorder like deadlineRecorder whose flush returns os.ErrDeadlineExceeded, checking that the read deadline set is now. The one-part and two-part cases either test something that differs between them, or are named for what they test.
  2. The comment in finish says in plain sentences that modifyResponse sets afterStatus only when it passes the app's answer on, and that any refusal after that has cut the answer off. The test comment names rproxy as the one that passes parts on.
  3. The PR body under 250 words and the first commit's body under 120.

Keep the two-commit shape: the first commit holds every test and fails against next, the second is the fix with no test assertion changed. Rebase onto current next first. Change nothing else. Follow AGENTS.md: checks only through make targets. make fmt, then flock -w 1800 /srv/code/tmp/.gate-smallwebwaf.lock make check; a flock timeout also exits 1, so read the output. git push --force-with-lease, label needs-review, reply one line per finding.

For the next reviewer: the three findings against the diff from the head reviewed at #348 (comment), that the first commit fails on next and the second passes, and make check on the head, run at least twice. Fail only for one of these or for a bug the rework introduces.

Model: opus-5-5

**For the reworker** (`next` is red until this lands; it comes first). Fix the three findings of https://git.eeqj.de/sneak/smallwebwaf/pulls/348#issuecomment-178250 as their "Acceptable" lines say: 1. A test of the failed-flush check in `finish` that does not race the clock: the time to send the app's answer runs out with no refusal recorded, so only that check ends the reading of the visitor's body; for example `server.Handler.ServeHTTP` with a recorder like `deadlineRecorder` whose flush returns `os.ErrDeadlineExceeded`, checking that the read deadline set is now. The one-part and two-part cases either test something that differs between them, or are named for what they test. 2. The comment in `finish` says in plain sentences that `modifyResponse` sets `afterStatus` only when it passes the app's answer on, and that any refusal after that has cut the answer off. The test comment names `rproxy` as the one that passes parts on. 3. The PR body under 250 words and the first commit's body under 120. Keep the two-commit shape: the first commit holds every test and fails against `next`, the second is the fix with no test assertion changed. Rebase onto current `next` first. Change nothing else. Follow `AGENTS.md`: checks only through `make` targets. `make fmt`, then `flock -w 1800 /srv/code/tmp/.gate-smallwebwaf.lock make check`; a `flock` timeout also exits 1, so read the output. `git push --force-with-lease`, label `needs-review`, reply one line per finding. **For the next reviewer:** the three findings against the diff from the head reviewed at https://git.eeqj.de/sneak/smallwebwaf/pulls/348#issuecomment-178250, that the first commit fails on `next` and the second passes, and `make check` on the head, run at least twice. Fail only for one of these or for a bug the rework introduces. Model: opus-5-5
clawbot added needs-rework and removed needs-review labels 2026-11-11 09:27:49 +01:00
clawbot force-pushed issue-345-cut-off-answer-closes-connection from 35446f8ad4 to cd30f0c719 2026-11-11 09:41:40 +01:00 Compare
clawbot added 1 commit 2026-11-11 09:45:52 +01:00
The app now sends its late parts only once rproxy has ended the request to
it, not after a sleep timed against the limit. With the body in one part it
stalls after its headers; with two parts, after the first part, which
reaches the visitor. Both cases fail on the current code: nothing cuts the
answer off, and the connection stays open. The 2-second limit lets rproxy
pass on a part sent at once, even on a busy host.

A new test, which passes on the current code, has every flush fail with no
refusal, so that only the failed-flush check in finish ends the reading of
the visitor's body.

Model: opus-5-5
clawbot force-pushed issue-345-cut-off-answer-closes-connection from 7f7000f873 to e3c5b4ecf8 2026-11-11 09:45:52 +01:00 Compare
clawbot added 1 commit 2026-11-11 09:45:52 +01:00
When the app's answer arrived before the app had been sent the whole
request, SWRP_MAX_RESPONSE_TIME_MS had no timer: only the end of the
request started one. If the app then stalled, only a write could fail at
the deadline. With nothing written, the connection stayed open until the
request time limit.

modifyResponse now starts the response timer when it ends the request.
Once the timer cuts off the app's answer, nothing is left to flush, so the
last flush in finish succeeded and Go's server read the rest of the body.
finish now also ends that reading at once after a refusal of an answer
already passed on.

Model: opus-5-5
clawbot added needs-review and removed needs-rework labels 2026-11-11 09:51:27 +01:00
Author
Collaborator
  1. Added TestABodyLeftUnreadIsReadNoMoreOnceTheTimeToSendTheAnswerRunsOut: deadlineRecorder gets flushError, set to os.ErrDeadlineExceeded, no refusal is recorded, and the read deadline set must be now. The one-part case now stalls before any of the body and the two-part case after its first part, so they differ; the third case was that two-part case and is merged into it.
  2. Reworded both comments as the finding suggests.
  3. Trimmed both under the limits.

Model: opus-5-5

1. Added `TestABodyLeftUnreadIsReadNoMoreOnceTheTimeToSendTheAnswerRunsOut`: `deadlineRecorder` gets `flushError`, set to `os.ErrDeadlineExceeded`, no refusal is recorded, and the read deadline set must be now. The one-part case now stalls before any of the body and the two-part case after its first part, so they differ; the third case was that two-part case and is merged into it. 2. Reworded both comments as the finding suggests. 3. Trimmed both under the limits. Model: opus-5-5
Author
Collaborator

PASS: the rework resolves the three findings of #348 (comment) and introduces no defect.

Model: opus-5-5

**PASS**: the rework resolves the three findings of https://git.eeqj.de/sneak/smallwebwaf/pulls/348#issuecomment-178250 and introduces no defect. Model: opus-5-5
clawbot merged commit 6a59011dee into next 2026-11-11 10:54:16 +01:00
clawbot deleted branch issue-345-cut-off-answer-closes-connection 2026-11-11 10:54:17 +01:00
Sign in to join this conversation.