x/net/http2: Long running http2 requests are closed immediately on server.Shutdown

[callum-oakley]

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

I can reproduce this on go version go1.11.4 darwin/amd64 but not on go version go1.10.7 darwin/amd64.

Does this issue reproduce with the latest release?

Yes.

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

go env Output

GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/callum/Library/Caches/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/callum/code/go"
GORACE=""
GOROOT="/usr/local/go"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
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 -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/d0/4p54ddg926g_6y9b1zklsdvw0000gn/T/go-build253335297=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

This snippet starts a server that responds to every request by counting for 10 seconds. On SIGINT we initiate graceful shutdown of the server, waiting for all connections to be idle. This should block shutdown as long as there are in flight requests.

create cert.pem and key.pem with something like

$ go run crypto/tls/generate_cert.go --host localhost

then run

package main

import (
	"context"
	"fmt"
	"io"
	"log"
	"math"
	"net/http"
	"os"
	"os/signal"
	"time"
)

func main() {
	s := &http.Server{
		Addr: ":5000",
		Handler: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			log.Println("handling connection")

			for i := 0; i < 10; i++ {
				log.Printf("writing tick %v", i)
				if _, err := io.WriteString(w, fmt.Sprintf("tick %v\n", i)); err != nil {
					log.Printf("io.WriteString: %v", err)
					return
				}
				w.(http.Flusher).Flush()
				time.Sleep(time.Second)
			}
		}),
	}

	shutdownFinished := make(chan struct{})
	go func() {
		sigint := make(chan os.Signal, 1)
		signal.Notify(sigint, os.Interrupt)
		<-sigint

		log.Println("shutting down")
		startedShutdown := time.Now()

		if err := s.Shutdown(context.Background()); err != nil {
			log.Printf("s.Shutdown: %v", err)
		}

		log.Printf(
			"shut down complete after %vms",
			math.Round(time.Since(startedShutdown).Seconds()*1000),
		)

		close(shutdownFinished)
	}()

	if err := s.ListenAndServeTLS("cert.pem", "key.pem"); err != nil {
		log.Printf("s.ListenAndServeTLS: %#v", err)
	}

	<-shutdownFinished
}

Make an HTTP/2 request, with curl built with HTTP/2 support, nghttp, etc and then send SIGINT to the go process.

What did you expect to see?

Shutdown blocks until all in flight requests have finished counting to 10.

What did you see instead?

For HTTP/1.1 connections Shutdown does block until all in flight requests have finished counting to 10, but HTTP/2 connections older than 5s are closed immediately (younger connections are closed as soon as they reach 5s old).

Sample output sending SIGINT 5s in to a HTTP/1.1 request

$ curl -k https://localhost:5000 --http1.1
tick 0
tick 1
tick 2
tick 3
tick 4
tick 5
tick 6
tick 7
tick 8
tick 9

$ go run main.go
2019/01/15 16:18:56 handling connection
2019/01/15 16:18:56 writing tick 0
2019/01/15 16:18:57 writing tick 1
2019/01/15 16:18:58 writing tick 2
2019/01/15 16:18:59 writing tick 3
2019/01/15 16:19:00 writing tick 4
2019/01/15 16:19:01 writing tick 5
^C2019/01/15 16:19:01 shutting down
2019/01/15 16:19:01 s.ListenAndServeTLS: &errors.errorString{s:"http: Server closed"}
2019/01/15 16:19:02 writing tick 6
2019/01/15 16:19:03 writing tick 7
2019/01/15 16:19:04 writing tick 8
2019/01/15 16:19:05 writing tick 9
2019/01/15 16:19:06 shut down complete after 5005ms

Sample output sending SIGINT 5s in to a HTTP/2 request

$ curl -k https://localhost:5000
tick 0
tick 1
tick 2
tick 3
tick 4
tick 5
curl: (56) Unexpected EOF

$ go run main.go
2019/01/15 16:19:16 handling connection
2019/01/15 16:19:16 writing tick 0
2019/01/15 16:19:17 writing tick 1
2019/01/15 16:19:18 writing tick 2
2019/01/15 16:19:19 writing tick 3
2019/01/15 16:19:20 writing tick 4
2019/01/15 16:19:21 writing tick 5
^C2019/01/15 16:19:21 shutting down
2019/01/15 16:19:21 s.ListenAndServeTLS: &errors.errorString{s:"http: Server closed"}
2019/01/15 16:19:22 shut down complete after 504ms

Observations from digging around in the code

This seems to happen because HTTP/2 connections remain in StateNew even though data is being written to them. Then when they are 5s old closeIdleConns (called by Shutdown) considers them idle and closes them. This behaviour was introduced here.

[mdpye]

Further observation: There is a state to represent hijacked connections, but it is not applied to connections hijacked by the http2 library.

[callum-oakley]

More digging: h2_bundle has a method to set connection state to active when there is at least one active stream but it only calls sc.hc.ConnState which is just an optional hook and doesn't update the state of the connection in http/server.

Keeping a reference to the http conn in the http2serverConn and setting the state on that as well fixes the above issue.

diff --git a/src/net/http/h2_bundle.go b/src/net/http/h2_bundle.go
index 676eebdfdf..4e1a87ee76 100644
--- a/src/net/http/h2_bundle.go
+++ b/src/net/http/h2_bundle.go
@@ -3913,6 +3913,12 @@ func (s *http2Server) ServeConn(c net.Conn, opts *http2ServeConnOpts) {
 		pushEnabled:                 true,
 	}
 
+	for hc := range opts.baseConfig().activeConn {
+		if hc.rwc == c {
+			sc.hconn = hc
+		}
+	}
+
 	s.state.registerConn(sc)
 	defer s.state.unregisterConn(sc)
 
@@ -4018,6 +4024,7 @@ type http2serverConn struct {
 	srv              *http2Server
 	hs               *Server
 	conn             net.Conn
+	hconn            *conn
 	bw               *http2bufferedWriter // writing to conn
 	handler          Handler
 	baseCtx          context.Context
@@ -4159,7 +4166,10 @@ func (sc *http2serverConn) state(streamID uint32) (http2streamState, *http2strea
 // Note that the net/http package does StateNew and StateClosed for us.
 // There is currently no plan for StateHijacked or hijacking HTTP/2 connections.
 func (sc *http2serverConn) setConnState(state ConnState) {
-	if sc.hs.ConnState != nil {
+	if sc.hconn != nil {
+		sc.hconn.setState(sc.hconn.rwc, state)
+	} else if sc.hs.ConnState != nil {
+		// If we setState on the http connection above, it calls ConnState for us
 		sc.hs.ConnState(sc.conn, state)
 	}
 }

If this looks like a reasonable approach I can write some tests and submit a PR? scratch that, just realised that we don't have access to the private types in the non-bundled code, something along these lines might do the trick though. Maybe the ConnState hook (or a new, similar one) can update the state of its connections and then delegate to the provided hook if it exists.

[gopherbot]

Change https://golang.org/cl/158840 mentions this issue: net/http: track the state of HTTP/2 connections

[bcmills]

CC @bradfitz @tombergan for http2.

[callum-oakley]

Best effort workaround: github.com/callum-oakley/polite-http-server.

[AlexanderYastrebov]

Looks like duplicate of #39776 fixed by https://go-review.googlesource.com/c/go/+/240278

The provided example now waits for full countdown.

[bcmills]

Duplicate of #39776