Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
callum-oakley opened this issue Jan 16, 2019 · 7 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@callum-oakley
Copy link

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
Copy link

mdpye commented Jan 16, 2019

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

@callum-oakley
Copy link
Author

callum-oakley commented Jan 16, 2019

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.

callum-oakley added a commit to callum-oakley/go that referenced this issue Jan 22, 2019
The state of HTTP/2 connections is currently never set to StateActive,
causing them to be closed immediately on server.Shutdown if they are at
least 5 seconds old. This change modifies the Shutdown tests so that the
h2 version fails with the existing implementation, and introduces a
method on the http Server to set the state from within the http2
bundle/package.

This is a proof of concept and illustration of the issue. The new
exported method on the Server type is probably a Very Bad Idea and a
naive implementation to boot. I'd love suggestions for a better
solution.

Fixes golang#29764
@gopherbot
Copy link

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

@bcmills
Copy link
Contributor

bcmills commented Jan 29, 2019

CC @bradfitz @tombergan for http2.

@bcmills bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jan 29, 2019
@bcmills bcmills added this to the Go1.13 milestone Jan 29, 2019
@andybons andybons modified the milestones: Go1.13, Go1.14 Jul 8, 2019
@rsc rsc modified the milestones: Go1.14, Backlog Oct 9, 2019
@callum-oakley
Copy link
Author

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

@AlexanderYastrebov
Copy link
Contributor

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

The provided example now waits for full countdown.

@bcmills
Copy link
Contributor

bcmills commented Mar 14, 2023

Duplicate of #39776

@bcmills bcmills marked this as a duplicate of #39776 Mar 14, 2023
@bcmills bcmills closed this as not planned Won't fix, can't repro, duplicate, stale Mar 14, 2023
@golang golang locked and limited conversation to collaborators Mar 13, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

7 participants