FastProxy appends "Internal Server Error" to the response body when the backend fails mid-response

Welcome!

• Yes, I've searched similar issues on GitHub and didn't find any.
• Yes, I've searched similar issues on the Traefik community forum and didn't find any.

What did you do?

With experimental.fastProxy enabled, I proxied a backend that starts a chunked response and then goes away before finishing it, which is what a pod being rolled during a long-lived stream looks like.

Here is a self-contained reproduction. It runs against the package's own test helpers, so it needs only a checkout: drop it in pkg/proxy/fast/ as repro_test.go and run go test -run TestRepro -v ./pkg/proxy/fast/.

package fast

import (
	"bufio"
	"io"
	"net"
	"net/http/httptest"
	"testing"

	"github.com/stretchr/testify/require"
	"github.com/traefik/traefik/v3/pkg/config/static"
	"github.com/traefik/traefik/v3/pkg/testhelpers"
)

func TestRepro(t *testing.T) {
	// A backend that commits a chunked 200, writes one chunk,
	// then goes away without the terminating chunk.
	listener, err := net.Listen("tcp", "127.0.0.1:0")
	require.NoError(t, err)
	t.Cleanup(func() { _ = listener.Close() })

	go func() {
		for {
			conn, err := listener.Accept()
			if err != nil {
				return
			}

			go func() {
				defer conn.Close()

				reader := bufio.NewReader(conn)
				for {
					line, err := reader.ReadString('\n')
					if err != nil || line == "\r\n" {
						break
					}
				}

				_, _ = io.WriteString(conn, "HTTP/1.1 200 OK\r\nTransfer-Encoding: chunked\r\n\r\n")
				_, _ = io.WriteString(conn, "5\r\nchunk\r\n")
			}()
		}
	}()

	builder := NewProxyBuilder(&transportManagerMock{}, static.FastProxyConfig{})

	proxyHandler, err := builder.Build("", testhelpers.MustParseURL("http://"+listener.Addr().String()), true, true)
	require.NoError(t, err)

	proxyServer := httptest.NewServer(proxyHandler)
	t.Cleanup(proxyServer.Close)

	res, err := proxyServer.Client().Get(proxyServer.URL)
	require.NoError(t, err)

	t.Cleanup(func() { _ = res.Body.Close() })

	body, readErr := io.ReadAll(res.Body)
	t.Logf("body=%q readErr=%v", string(body), readErr)
}

I expected the client to receive the five bytes the backend managed to send, plus an error telling it the response is incomplete. That is what the default proxy does: the same backend behind httputil.NewProxyBuilder(...).Build(..., 0) gives:

body="chunk" readErr=unexpected EOF

What did you see instead?

body="chunkInternal Server Error" readErr=<nil>

Two things go wrong:

1. The string Internal Server Error is appended to the response body, inside the payload the client is already reading.
2. readErr is nil. The response is terminated as if it were complete, so the client has no way to detect that it is truncated.

A JSON parser will choke on the trailing bytes. Anything more forgiving just accepts a payload that is missing data.

The cause is in ReverseProxy.ServeHTTP (pkg/proxy/fast/proxy.go#L237):

if err := p.roundTrip(rw, req, outReq, reqUpType); err != nil {
	proxyhttputil.ErrorHandler(rw, req, err)
}

roundTrip returns errors from both before and after the response has started, but ErrorHandler is only valid before. handleResponse calls r.RW.WriteHeader(res.StatusCode()) (connpool.go#L212) and only then copies the body, so a copy failure arrives with the status line already sent. ErrorHandler's WriteHeader(500) is ignored at that point, but its Write([]byte("Internal Server Error")) is not, so those bytes land in the body. ServeHTTP then returns normally, and the server finishes the response cleanly.

net/http/httputil.ReverseProxy handles the same case by aborting the request instead (reverseproxy.go#L613), and Traefik's own recovery middleware documents the same rule (recovery.go#L123):

If headers have been sent this is not possible to respond with an HTTP error, and we let the server abort the response silently thanks to the http.ErrAbortHandler sentinel panic value.

The same path is hit when it is the client that goes away instead of the backend, which on an SSE route is just a browser closing a tab. The injected bytes go to a stream nobody is reading, so the client is unaffected, but the 500 still reaches captureResponseWriter.WriteHeader, which keeps the last status it is given (capture.go#L180). Traefik then logs and counts the request as a 500. On a route serving long-lived streams, that is every ordinary disconnect.

None of this needs HTTP/2 or SSE: the reproduction above is HTTP/1.1 end to end.

What version of Traefik are you using?

v3.6.24 and v3.7.9. The code path is unchanged on v3.6, v3.7 and master (fd5a576df), so all three are affected.

What is your environment & configuration?

experimental:
  fastProxy: true

The reproduction needs nothing else: no TLS and no middleware. Only experimental.fastProxy matters, since smart_builder.go otherwise routes the request to the httputil proxy, which is unaffected.

If applicable, please paste the log output in DEBUG level

At --log.level=DEBUG the exchange produces two lines and nothing at INFO or above. ErrorHandler logs the underlying error as 500 Internal Server Error, and net/http reports the write that was ignored:

http: superfluous response.WriteHeader call from github.com/traefik/traefik/v3/pkg/proxy/httputil.ErrorHandlerWithContext (proxy.go:168)

With the access log enabled the request is recorded as a 500, which is the only signal at default log level, and it does not match the 200 the client received.

Related

• #10807 and #10819 covered access log correctness for streaming responses aborted by the client, in the access log middleware. The wrong status here has a different origin: the fast proxy writes a 500 after the response has started.
• #11728 reports a fastProxy streaming failure that may share this root cause; I have not been able to confirm it.