net/http: client errors on server graceful shutdown

[pugachAG]

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

go version go1.10rc2 linux/amd64

Does this issue reproduce with the latest release?

Yes

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

GOARCH="amd64"                                                                                                                                                
GOBIN=""
GOCACHE="/home/apuhach/.cache/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/usr/local/git_tree/go/"
GORACE=""
GOROOT="/home/apuhach/sdk/go1.10rc2"
GOTMPDIR=""
GOTOOLDIR="/home/apuhach/sdk/go1.10rc2/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
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-build506882789=/tmp/go-build -gno-record-gcc-switches"

What did you do?

package main

import (
	"flag"
	"fmt"
	"io/ioutil"
	"net/http"
	"time"
	"context"
)

var cmd = flag.String("cmd", "", "cmd")

func serverCmd() {
	mux := http.NewServeMux()
	mux.HandleFunc("/",
		func(w http.ResponseWriter, r *http.Request) {
			w.Write([]byte("hello world\n"))
		})


	for {
		server := &http.Server{
			Addr:    "127.0.0.1:9228",
			Handler: mux,
		}
		go func() {
			if err := server.ListenAndServe(); err != nil {
				fmt.Printf("ListenAndServe done: %v\n", err)
			}
		}()
		time.Sleep(2 * time.Second)
		server.Shutdown(context.Background())
	}
}

func clientCmd() {
	client := http.Client{}
	for {
		request, _ := http.NewRequest("POST", "http://127.0.0.1:9228", nil)
		resp, err := client.Do(request)
		if err != nil {
			fmt.Printf("http.Post failed: %v\n", err)
			time.Sleep(1 * time.Second)
		} else {
			ioutil.ReadAll(resp.Body)
			resp.Body.Close()
		}
	}
}

func main() {
	flag.Parse()
	switch *cmd {
	case "server":
		serverCmd()
	case "client":
		clientCmd()
	default:
		fmt.Printf("unknown cmd %v", *cmd)
	}
}

run server: go run main.go -cmd server
and client: go run main.go -cmd client

What did you expect to see?

client gets only connection refused errors:

http.Post failed: Post http://127.0.0.1:9228: dial tcp 127.0.0.1:9228: getsockopt: connection refused

What did you see instead?

mix of connection refused, EOF and connection reset by peer errors:

http.Post failed: Post http://127.0.0.1:9228: dial tcp 127.0.0.1:9228: getsockopt: connection refused                                                         
http.Post failed: Post http://127.0.0.1:9228: read tcp 127.0.0.1:57730->127.0.0.1:9228: read: connection reset by peer                     
http.Post failed: Post http://127.0.0.1:9228: dial tcp 127.0.0.1:9228: getsockopt: connection refused                                                         
http.Post failed: Post http://127.0.0.1:9228: EOF                                                                                                             
http.Post failed: Post http://127.0.0.1:9228: EOF                                                                                                             
http.Post failed: Post http://127.0.0.1:9228: EOF                                                                                                             
http.Post failed: Post http://127.0.0.1:9228: dial tcp 127.0.0.1:9228: getsockopt: connection refused                                                         
http.Post failed: Post http://127.0.0.1:9228: dial tcp 127.0.0.1:9228: getsockopt: connection refused                                                         
http.Post failed: Post http://127.0.0.1:9228: EOF                                                                                                             
http.Post failed: Post http://127.0.0.1:9228: EOF                                                                                                             
http.Post failed: Post http://127.0.0.1:9228: dial tcp 127.0.0.1:9228: getsockopt: connection refused                                                         
http.Post failed: Post http://127.0.0.1:9228: EOF                                                                                                             
http.Post failed: Post http://127.0.0.1:9228: dial tcp 127.0.0.1:9228: getsockopt: connection refused                                                         
http.Post failed: Post http://127.0.0.1:9228: EOF                                                                                                             
http.Post failed: Post http://127.0.0.1:9228: EOF                                                                                                             
http.Post failed: Post http://127.0.0.1:9228: dial tcp 127.0.0.1:9228: getsockopt: connection refused                                                         
http.Post failed: Post http://127.0.0.1:9228: EOF                                                                                                             
http.Post failed: Post http://127.0.0.1:9228: EOF                                                                                                             
http.Post failed: Post http://127.0.0.1:9228: EOF                                                                                                             
http.Post failed: Post http://127.0.0.1:9228: dial tcp 127.0.0.1:9228: getsockopt: connection refused                                                         
http.Post failed: Post http://127.0.0.1:9228: EOF                                                                                                             
http.Post failed: Post http://127.0.0.1:9228: dial tcp 127.0.0.1:9228: getsockopt: connection refused                                                         
http.Post failed: Post http://127.0.0.1:9228: EOF                                                                                                             
http.Post failed: Post http://127.0.0.1:9228: EOF                                                                                                             
http.Post failed: Post http://127.0.0.1:9228: dial tcp 127.0.0.1:9228: getsockopt: connection refused                                                         

Server suppose to shutdown gracefully without causing EOF or connection reset by peer errors on client side

[bradfitz]

Server suppose to shutdown gracefully without causing EOF or connection reset by peer errors on client side

That is not what graceful shutdown means.

Graceful shutdown means the server stops accepting new connections and closes idle keep-alive connections while not interrupting a response that's already in flight.

If anything, there might be a bug report (for an opt-in feature request) here about the retry policy for the HTTP Transport on non-idempotent requests in the presence of mid-air collisions of client writing (bytes in flight) while server is shutting down an idle connection. HTTP/2 handles that better than HTTP/1, and we don't do any auto-retries for you in HTTP/1.

In any case, I'm going to close this bug. Feel free to open a new one about retries if that's what you want, but search for duplicates first (searching for stuff like "Transport" and "Client" and "idempotent" and "POST" and "retry"/"retries").

[sethvargo]

I see a few things here:

1. You are discarding the error from the POST request. Probably not the issue, but you really shouldn't:

   request, err := http.NewRequest("POST", "http://127.0.0.1:9228", nil)
   if err != nil {
     log.Printf("failed to create request: %v", err)
     continue
   }

2. You probably want to specifically exclude http.ErrServerClosed from your checking:

   go func() {
     if err := server.ListenAndServe(); err != nil && err != http.ErrServerClosed {
       log.Fatalf("[ERR] server exited with: %s", err)
     }
   }()

3. Use a timeout and catch the error from shutdown:

   time.Sleep(2 * time.Second)
   
   ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
   defer cancel()
   
   if err := server.Shutdown(ctx); err != nil {
     log.Fatalf("[ERR] failed to shutdown server: %s", err)
   }

4. As @bradfitz said while I was typing this out, the default http client has shared internal state and caching. You can use something like cleanhttp and create a new client per request to alleviate this.

Here is a Gist I put together that incorporates all these changes and does not produce an EOF.

[pugachAG]

@sethvargo

Thanks for the remarks. This happens only with keep-alive connections, so simply adding request.Close = true solves it. But that is not the point, since I want to have persistent connections in production.

[pugachAG]

@bradfitz

What I tried to show here is not the client issue, but server. Let me give you another example with server.SetKeepAlivesEnabled(false) dropping active connections. Consider following code for serverCmd:

func serverCmd() {
	mux := http.NewServeMux()
	mux.HandleFunc("/",
		func(w http.ResponseWriter, r *http.Request) {
			w.Write([]byte("hello world\n"))
		})

	server := &http.Server{
		Addr:    "127.0.0.1:9228",
		Handler: mux,
	}
	go func() {
		if err := server.ListenAndServe(); err != nil {
			fmt.Printf("ListenAndServe done: %v\n", err)
		}
	}()


	for {
		time.Sleep(1 * time.Second)
		server.SetKeepAlivesEnabled(false)
		time.Sleep(1 * time.Second)
		server.SetKeepAlivesEnabled(true)
	}
}

This causes the same errors. Is it expected behavior as well?

As far as I see it happens because of race condition when checking connection state https://github.com/golang/go/blob/master/src/net/http/server.go#L2607
State might change in between this and c.rwc.Close()

[jonathanbeber]

any update?

[jonathanbeber]

It shouldn't be closed