net/http: HTTP/2 request context sometimes returns no error when the client disconnects #52183

kapvode · 2022-04-06T16:43:10Z

What version of Go are you using (`go version`)?

$ go version
go version go1.17.8 linux/amd64

$ go version
go version go1.18 linux/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (`go env`)?

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/user/.cache/go-build"
GOENV="/home/user/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS="-ldflags=-w"
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/user/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/user/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/lib/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/lib/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.17.8"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/dev/null"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build557012456=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Users sometimes abort file uploads before they finish, which propagates an error up the call stack. I try to see if the HTTP request was aborted by checking request.Context().Err() != nil, in which case I ignore the error. Otherwise, I report it, so it can be investigated. (I am aware there might be rare cases when there is an unrelated error, after which the client disconnects, which will cause the error to be ignored, incorrectly.)

I created an example.

server.go

package main

import (
	"io"
	"log"
	"net/http"
)

func handler(prefix string) http.HandlerFunc {
	return func(w http.ResponseWriter, r *http.Request) {
		_, err := io.Copy(io.Discard, r.Body)
		if err == nil {
			log.Printf("%s | upload: OK", prefix)
		} else {
			log.Printf("%s | err: %v | context err: %v", prefix, err, r.Context().Err())
		}

		// time.Sleep(time.Millisecond * 100)
		// log.Println(r.Context().Err())
	}
}

func main() {
	go func() {
		mux := http.NewServeMux()
		mux.HandleFunc("/", handler("HTTP"))
		http.ListenAndServe(":8001", mux)
	}()

	mux := http.NewServeMux()
	mux.HandleFunc("/", handler("HTTPS"))
	http.ListenAndServeTLS(":8002", "cert.pem", "key.pem", mux)
}

Here is also a self-signed certificate, for convenience.

key.pem

cert.pem

I then try to start a rate-limited upload, and press Ctrl-C at random times before it completes.

HTTP/1.1:

$ curl -v -F profile=@/path/to/image.jpg --limit-rate 10k http://localhost:8001/

HTTP/2:

$ curl -v -k -F profile=@/path/to/image.jpg --limit-rate 10k https://localhost:8002/

What did you expect to see?

I expect request.Context().Err() to always say context canceled. Is this assumption correct?

What did you see instead?

In case of HTTP/1.1, it seems I always get the error unexpected EOF, and request.Context().Err() always returns context canceled.

2022/04/05 13:22:22 HTTP | err: unexpected EOF | context err: context canceled
2022/04/05 13:22:25 HTTP | err: unexpected EOF | context err: context canceled
2022/04/05 13:22:25 HTTP | err: unexpected EOF | context err: context canceled
2022/04/05 13:22:26 HTTP | err: unexpected EOF | context err: context canceled
2022/04/05 13:22:26 HTTP | err: unexpected EOF | context err: context canceled
2022/04/05 13:22:27 HTTP | err: unexpected EOF | context err: context canceled
2022/04/05 13:22:27 HTTP | err: unexpected EOF | context err: context canceled
2022/04/05 13:22:30 HTTP | err: unexpected EOF | context err: context canceled
2022/04/05 13:22:36 HTTP | err: unexpected EOF | context err: context canceled
2022/04/05 13:22:39 HTTP | err: unexpected EOF | context err: context canceled
2022/04/05 13:22:41 HTTP | err: unexpected EOF | context err: context canceled

In case of HTTP/2, it seems the error is always client disconnected, but most of the time request.Context().Err() is nil.

2022/04/05 13:22:46 HTTPS | err: client disconnected | context err: <nil>
2022/04/05 13:22:49 HTTPS | err: client disconnected | context err: <nil>
2022/04/05 13:22:50 HTTPS | err: client disconnected | context err: <nil>
2022/04/05 13:22:53 HTTPS | err: client disconnected | context err: context canceled
2022/04/05 13:22:57 HTTPS | err: client disconnected | context err: <nil>
2022/04/05 13:23:00 HTTPS | err: client disconnected | context err: <nil>
2022/04/05 13:23:00 HTTPS | err: client disconnected | context err: context canceled
2022/04/05 13:23:02 HTTPS | err: client disconnected | context err: <nil>
2022/04/05 13:23:05 HTTPS | err: client disconnected | context err: <nil>

It seems there is some kind of race here. If I add a short sleep at the end of the handler, I get the expected context error.

2022/04/06 18:07:11 HTTPS | err: client disconnected | context err: <nil>
2022/04/06 18:07:11 context canceled
2022/04/06 18:08:05 HTTPS | err: client disconnected | context err: context canceled
2022/04/06 18:08:05 context canceled
2022/04/06 18:08:09 HTTPS | err: client disconnected | context err: <nil>
2022/04/06 18:08:09 context canceled

I found what looks like the error that is returned, but it is unexported, so I cannot check it more directly.

The text was updated successfully, but these errors were encountered:

seankhliao · 2022-04-06T17:56:51Z

cc @neild

kapvode · 2022-11-23T10:18:48Z

I've created a test that reproduces this. The client is now in Go, so there is no need to run curl and press Ctrl-C.

I just make a POST request and abort it before sending any data. On the server side, the request context is cancelled when using HTTP/1.1, but not when using HTTP/2.

I couldn't think of a better way to abort the client request, but this does reproduce the issue.

There are two main differences in the HTTPS version relative to the HTTP one:

Immediately after the connection is closed, the request context is not cancelled most of the time. After a short sleep, it is. This matches my original report.
For some reason, server.Shutdown() doesn't wait for the handler to finish, so I have to explicitly wait manually.

A minor difference is that, in the HTTPS version, the error reported by client.Do varies, whereas it seems to be always the same in the HTTP version.

I tried it with Go versions 1.17.12 and 1.19.3.

It would be useful to know if the request context not being cancelled immediately is normal and maybe I just have incorrect expectations.

server_http_test.go

package main

import (
	"context"
	"errors"
	"io"
	"net"
	"net/http"
	"testing"

	"github.com/stretchr/testify/require"
)

func TestContextErrHTTP(t *testing.T) {
	requestReceived := make(chan struct{})
	connClosed := make(chan struct{})
	serverClosed := make(chan struct{})

	var requestCopyError error
	var requestContextErr error
	var connCloseErr error
	var serverErr error

	mux := http.NewServeMux()
	mux.Handle("/", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		close(requestReceived)

		_, requestCopyError = io.Copy(io.Discard, r.Body)

		<-connClosed

		requestContextErr = r.Context().Err()
	}))

	var server http.Server
	server.Addr = ":8001"
	server.Handler = mux

	go func() {
		serverErr = server.ListenAndServe()
		close(serverClosed)
	}()

	var clientConn net.Conn
	pr, pw := io.Pipe()

	go func() {
		<-requestReceived
		pw.CloseWithError(errors.New("fake abort"))
		connCloseErr = clientConn.Close()
		close(connClosed)
	}()

	assert := require.New(t)
	req, err := http.NewRequest("POST", "http://localhost:8001/", pr)
	assert.NoError(err, "create request")

	customTransport := http.DefaultTransport.(*http.Transport).Clone()
	originalDialContext := customTransport.DialContext
	customTransport.DialContext = func(ctx context.Context, network, addr string) (net.Conn, error) {
		c, err := originalDialContext(ctx, network, addr)
		clientConn = c
		return c, err
	}
	client := &http.Client{Transport: customTransport}

	_, err = client.Do(req)
	assert.ErrorContains(err, "fake abort", "sending the HTTP request should fail")
	pr.Close()

	assert.NoError(connCloseErr, "conn.Close error")

	err = server.Shutdown(context.Background())
	assert.NoError(err, "server shutdown")

	<-serverClosed
	assert.ErrorIs(serverErr, http.ErrServerClosed, "server should be closed")

	assert.Error(requestCopyError, "reading request body should return an error")

	assert.ErrorIs(requestContextErr, context.Canceled, "request context should be cancelled")
}

server_https_test.go

package main

import (
	"context"
	"errors"
	"io"
	"net"
	"net/http"
	"strings"
	"testing"
	"time"

	"github.com/stretchr/testify/require"
)

func TestContextErrHTTPS(t *testing.T) {
	requestReceived := make(chan struct{})
	connClosed := make(chan struct{})
	handlerClosed := make(chan struct{})
	serverClosed := make(chan struct{})

	var requestCopyError error
	var requestContextErr error
	var requestContextAfterSleepErr error
	var connCloseErr error
	var serverErr error

	mux := http.NewServeMux()
	mux.Handle("/", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		close(requestReceived)

		_, requestCopyError = io.Copy(io.Discard, r.Body)

		<-connClosed

		requestContextErr = r.Context().Err()

		time.Sleep(time.Second)

		requestContextAfterSleepErr = r.Context().Err()

		close(handlerClosed)
	}))

	var server http.Server
	server.Addr = ":8002"
	server.Handler = mux

	go func() {
		serverErr = server.ListenAndServeTLS("cert.pem", "key.pem")
		close(serverClosed)
	}()

	var clientConn net.Conn
	pr, pw := io.Pipe()

	go func() {
		<-requestReceived
		pw.CloseWithError(errors.New("fake abort"))
		connCloseErr = clientConn.Close()
		close(connClosed)
	}()

	assert := require.New(t)
	req, err := http.NewRequest("POST", "https://localhost:8002/", pr)
	assert.NoError(err, "create request")

	customTransport := http.DefaultTransport.(*http.Transport).Clone()
	customTransport.TLSClientConfig.InsecureSkipVerify = true
	originalDialContext := customTransport.DialContext
	customTransport.DialContext = func(ctx context.Context, network, addr string) (net.Conn, error) {
		c, err := originalDialContext(ctx, network, addr)
		clientConn = c
		return c, err
	}
	client := &http.Client{Transport: customTransport}

	_, err = client.Do(req)
	match1 := strings.Contains(err.Error(), "fake abort")
	match2 := strings.Contains(err.Error(), "use of closed network connection")
	assert.True(match1 || match2, "sending the HTTP request should fail")
	pr.Close()

	assert.NoError(connCloseErr, "conn.Close error")

	<-handlerClosed

	err = server.Shutdown(context.Background())
	assert.NoError(err, "server shutdown")

	<-serverClosed
	assert.ErrorIs(serverErr, http.ErrServerClosed, "server should be closed")

	assert.Error(requestCopyError, "reading request body should return an error")

	assert.ErrorIs(requestContextAfterSleepErr, context.Canceled, "request context should be cancelled (after sleep)")
	assert.ErrorIs(requestContextErr, context.Canceled, "request context should be cancelled")
}

seankhliao added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Apr 6, 2022

seankhliao added this to the Unplanned milestone Aug 20, 2022

emcfarlane mentioned this issue Dec 4, 2023

Incorrect client disconnection error codes connectrpc/connect-go#645

Closed

midnight-wonderer mentioned this issue Dec 21, 2023

[bug] blank page cached on context canceled darkweak/souin#337

Open

darkweak mentioned this issue Dec 29, 2023

Cache corruption darkweak/souin#429

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

net/http: HTTP/2 request context sometimes returns no error when the client disconnects #52183

net/http: HTTP/2 request context sometimes returns no error when the client disconnects #52183

kapvode commented Apr 6, 2022

seankhliao commented Apr 6, 2022

kapvode commented Nov 23, 2022

net/http: HTTP/2 request context sometimes returns no error when the client disconnects #52183

net/http: HTTP/2 request context sometimes returns no error when the client disconnects #52183

Comments

kapvode commented Apr 6, 2022

What version of Go are you using (go version)?

Does this issue reproduce with the latest release?

What operating system and processor architecture are you using (go env)?

What did you do?

What did you expect to see?

What did you see instead?

seankhliao commented Apr 6, 2022

kapvode commented Nov 23, 2022

What version of Go are you using (`go version`)?

What operating system and processor architecture are you using (`go env`)?