net/http: server does not send response on timeout

[holiman]

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

go1.16.4 linux/amd64

Does this issue reproduce with the latest release?

I think so.

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=""
GOFLAGS=""
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/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.16.4"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/user/go/src/github.com/ethereum/go-ethereum/go.mod"
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-build2314802959=/tmp/go-build -gno-record-gcc-switches"

Background

The attached code shows an example of setting up an http server with a WriteTimeout which is smaller than the processing time of the requests. This is a minimal repro of an issue we've encountered in go-etherem: ethereum/go-ethereum#21430

The used timeout is 1s, and any request containing the word sleep will take 2s to complete.

package main

import (
	"fmt"
	"net"
	"net/http"
	"os"
	"os/signal"
	"strings"
	"time"
)

func main() {
	if err := setup(); err != nil {
		fmt.Fprintf(os.Stderr, "Error: %v\n", err)
		os.Exit(1)
	}
}

type dummyHandler struct{}

// ServeHTTP sleeps for 2 seconds in case the request contains the magic word 'sleep',
// and always answers with "Oll Korrekt".
func (d dummyHandler) ServeHTTP(writer http.ResponseWriter, request *http.Request) {
	if strings.Contains(request.RequestURI, "sleep") {
		fmt.Fprintf(os.Stderr, "sleeping\n")
		time.Sleep(2 * time.Second)
	}
	fmt.Fprintf(os.Stderr, "Writing response\n")
	n, err := writer.Write([]byte("Oll korrekt"))
	fmt.Fprintf(os.Stderr, "Wrote response, %d bytes written, error: %v\n", n, err)
}

func setup() error {
	server := &http.Server{Handler: dummyHandler{},
		WriteTimeout: time.Second}
	if listener, err := net.Listen("tcp", "localhost:9999"); err != nil {
		return err
	} else {
		go server.Serve(listener)
		fmt.Fprintf(os.Stderr, "Opened http server at localhost:9999\n")
	}
	abortChan := make(chan os.Signal, 1)
	signal.Notify(abortChan, os.Interrupt)
	<-abortChan
	fmt.Fprintf(os.Stderr, "Shutting down\n")
	return nil
}

Expected behaviour

I expect the following things to happen:

1. Server-side: Writing to the http.ResponseWriter, the Write method should should return an error.
2. Client-side: The client should, after 1s, receive a HTTP error response, such as 500 Internal Server Error or 504 Gateway Timeout.

Actual behaviour

1. The Write method does not return an error.
2. After 2s, the server shuts down the connection without sending a reply.

• Note: This occurs not after 1 second, when the timeout hits, but when the response internally is actually finished and ready to be delivered.

Example run:

An example run where I make two requests, one which times out and one which does not.

Server side:

[user@work web]$ go run . 
Opened http server at localhost:9999
Writing response
Wrote response, 11 bytes written, error: <nil>
sleeping
Writing response
Wrote response, 11 bytes written, error: <nil>

Client side:

[user@work web]$ time curl -v http://localhost:9999/test
*   Trying ::1:9999...
* connect to ::1 port 9999 failed: Connection refused
*   Trying 127.0.0.1:9999...
* Connected to localhost (127.0.0.1) port 9999 (#0)
> GET /test HTTP/1.1
> Host: localhost:9999
> User-Agent: curl/7.71.1
> Accept: */*
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< Date: Thu, 15 Jul 2021 19:55:28 GMT
< Content-Length: 11
< Content-Type: text/plain; charset=utf-8
< 
* Connection #0 to host localhost left intact
Oll korrekt
real	0m0.007s
user	0m0.006s
sys	0m0.001s
[user@work web]$ time curl -v http://localhost:9999/sleep
*   Trying ::1:9999...
* connect to ::1 port 9999 failed: Connection refused
*   Trying 127.0.0.1:9999...
* Connected to localhost (127.0.0.1) port 9999 (#0)
> GET /sleep HTTP/1.1
> Host: localhost:9999
> User-Agent: curl/7.71.1
> Accept: */*
> 
* Empty reply from server
* Connection #0 to host localhost left intact
curl: (52) Empty reply from server

real	0m2.007s
user	0m0.004s
sys	0m0.002s

[cherrymui]

cc @neild

[neild]

Duplicate of #21389

(Commenting there.)