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

[kapvode]

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

-----BEGIN PRIVATE KEY-----
MIICdgIBADANBgkqhkiG9w0BAQEFAASCAmAwggJcAgEAAoGBAPeY8x5BXyLcCwgn
J+SDL83Ur5fyyxvNL2w0cytYh38ggCMh1Eo2BgY9maVKAqqew3r2pmxQWWMh1+QM
1wxZpwc5vN9fwISxO1flm/J8yEG/RXM8CAlf/z/Jka8jUj9Iql2ZFVaQjfRvyQqo
NckRxPcHbvjms0J9yj7r8Sabj1lfAgMBAAECgYEAmHH8ppE7YTw4MqHhJwo6wbGF
F7ouogR4gVfd3T9Z1cUOABORIMwYc3k0A5gJAkJUO35nw2LJVob85PWe5oTAmDVF
387ZnYxZWr54sQbujGVyenOwXSQz1KEm6+ZoxlDjL1WL7MwwdWKuxZwO3kwdfz87
OiW9q2PA767wTUVuc1kCQQD9FDtuaXDFQcuNBdn4s8wCV/o24xoyard2ionHbpaw
yTnI5sMdze4Ib74vYW0Y6clmNW/olkIizvJ7VvhOIWojAkEA+nSFb0J7SkcLKfcl
7IRAUZuWTfC1d2jKGJl4oEvAb/oPG2YOEHmODqdz4LCC9UXeVxAZEPHFMrzMP0TU
TBLRlQJALYw9ogKCFE5iJxBdiYA6gFV7J/O5nEdOm5wVbfo+TrT4nGrDxRJx+7y4
uuhK7UfuQmHtsSuR3ZfnVkFx0QX8hwJANaqgKP4K4xikCML/qlWQXqxDIcJRcBvR
KkJAecChpJzlfc55dwhE61jwWJYaCaqGAQvfAyV7RurzrR73irGBnQJAcnPv9f0b
y0YYssMdiVyrLsXiCFQcAGRiPeXhyJ3/nf+mkDVKoXlbF1jHOV3c50Fd6lAYaeV+
xrVUqXwKPIlMcg==
-----END PRIVATE KEY-----

cert.pem

-----BEGIN CERTIFICATE-----
MIICZjCCAc+gAwIBAgIUFFhvn/KLCQcb4i6YxvJuxeiA4cswDQYJKoZIhvcNAQEL
BQAwRTELMAkGA1UEBhMCQVUxEzARBgNVBAgMClNvbWUtU3RhdGUxITAfBgNVBAoM
GEludGVybmV0IFdpZGdpdHMgUHR5IEx0ZDAeFw0yMjA0MDUxMDU1NTVaFw0yMzA0
MDUxMDU1NTVaMEUxCzAJBgNVBAYTAkFVMRMwEQYDVQQIDApTb21lLVN0YXRlMSEw
HwYDVQQKDBhJbnRlcm5ldCBXaWRnaXRzIFB0eSBMdGQwgZ8wDQYJKoZIhvcNAQEB
BQADgY0AMIGJAoGBAPeY8x5BXyLcCwgnJ+SDL83Ur5fyyxvNL2w0cytYh38ggCMh
1Eo2BgY9maVKAqqew3r2pmxQWWMh1+QM1wxZpwc5vN9fwISxO1flm/J8yEG/RXM8
CAlf/z/Jka8jUj9Iql2ZFVaQjfRvyQqoNckRxPcHbvjms0J9yj7r8Sabj1lfAgMB
AAGjUzBRMB0GA1UdDgQWBBTCS9lhp2OMBymBDZSWW7p7JoS2bzAfBgNVHSMEGDAW
gBTCS9lhp2OMBymBDZSWW7p7JoS2bzAPBgNVHRMBAf8EBTADAQH/MA0GCSqGSIb3
DQEBCwUAA4GBAHNjy1A+K1oSi2GlnMJiQEqUAy2F9Wil6kZWzOVjkdDRT7LuE/FA
DB0RdJmv/I5Tg7c+jIv9xcukg6kRmM+IJZ5xMBqmN6N6Z50YRG35kjXyO7a2/ls+
7w2jIlST4hj4XidfM890HcbbYHei6Q8D++h4ZHWpo3UDO2LavbxGoUwp
-----END CERTIFICATE-----

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.

[seankhliao]

cc @neild