net/http: Shutdown method on http server not working properly when using h2 proto in tls config

[aloababa]

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

$ go version
go version go1.12.7 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
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/ben/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/ben/go"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/go"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
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-build432978780=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Well when using h2 proto in tls config, calling server.Shutdown will not wait for active connections.

Here is the example:

https://play.golang.org/p/kjFfgwHIvIj

Just use tlsConfig() and tlsConfigWithHTTP2() and send SIGINT while doing a curl.

With http/1.1 proto Shutdown works properly but not with h2 proto.

[katiehockman]

@aloababa the example you gave doesn't seem to work. It is throwing an error: "./prog.go:37:38: undefined: syscall.SIGTERM".

[gregory-m]

Is undefined only in playground, try to download code and run it on local unix machine.

[katiehockman]

Gotcha, thanks.
/cc @rsc @FiloSottile as an fyi until I can reproduce this on my linux machine tomorrow.

[fraenkel]

Debugs on both sides show proper shutdown.

Server side

2019/07/29 20:58:10 Shutting down http server...
2019/07/29 20:58:10 http2: Framer 0xc00032e1c0: wrote GOAWAY len=8 LastStreamID=13 ErrCode=NO_ERROR Debug=""
2019/07/29 20:58:11 done

Client side (nghttp)

[  5.369] recv GOAWAY frame <length=8, flags=0x00, stream_id=0>
          (last_stream_id=13, error_code=NO_ERROR(0x00), opaque_data(0)=[])
Some requests were not processed. total=1, processed=0

[aloababa]

I made a new test on a different machine.

And i still got a different behavior between h2 and http/1.1.

When using h2 I got EOF. And when using http/1.1 I got the PID.

I sent a SIGTERM before the request was complete.

cURL output with http:

root@bentest:~# curl -k https://127.0.0.1:8080 -v
* Rebuilt URL to: https://127.0.0.1:8080/
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to 127.0.0.1 (127.0.0.1) port 8080 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
* (304) (OUT), TLS handshake, Client hello (1):
* (304) (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Client hello (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN, server accepted to use http/1.1
* Server certificate:
*  subject: C=FR; L=PAR; O=ORG; CN=bentest
*  start date: Jul 30 08:23:47 2019 GMT
*  expire date: Jul 29 08:23:47 2020 GMT
*  issuer: C=FR; L=PAR; O=ORG; CN=bentest
*  SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
> GET / HTTP/1.1
> Host: 127.0.0.1:8080
> User-Agent: curl/7.58.0
> Accept: */*
> 
< HTTP/1.1 200 OK
< Date: Tue, 30 Jul 2019 08:24:03 GMT
< Content-Length: 11
< Content-Type: text/plain; charset=utf-8
< Connection: close
< 
PID: 69120
* Closing connection 0
* TLSv1.2 (OUT), TLS alert, Client hello (1):

cURL output with http2:

root@bentest:~# curl -k https://127.0.0.1:8080 -v
* Rebuilt URL to: https://127.0.0.1:8080/
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to 127.0.0.1 (127.0.0.1) port 8080 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
* (304) (OUT), TLS handshake, Client hello (1):
* (304) (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Client hello (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=FR; L=PAR; O=ORG; CN=bentest
*  start date: Jul 30 08:24:43 2019 GMT
*  expire date: Jul 29 08:24:43 2020 GMT
*  issuer: C=FR; L=PAR; O=ORG; CN=bentest
*  SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x56330e0294b0)
> GET / HTTP/2
> Host: 127.0.0.1:8080
> User-Agent: curl/7.58.0
> Accept: */*
> 
* Connection state changed (MAX_CONCURRENT_STREAMS updated)!
* TLSv1.2 (IN), TLS alert, Client hello (1):
* Unexpected EOF
* Connection #0 to host 127.0.0.1 left intact
curl: (56) Unexpected EOF

[gregory-m]

@fraenkel this is exactly a bug described by OP, server send GOAWAY without waiting for handlers to finish.

EDIT:
(after reading spec)
Actually GOAWAY is right thing to do is such situation, but still server close connection without waiting for handlers to finish.

[fraenkel]

Actually, I am not convinced any client is sending a GOAWAY. From the traces and from additional debug, the server receives an EOF rather than any more messages to finish the request.

If you do a trace of a clean GET, you will notice that the client does not wait for the GOAWAY from the server.

[gregory-m]

Server send GOAWAY. It happens here:

go/src/net/http/h2_bundle.go

Line 3779 in fbb819e

s.RegisterOnShutdown(conf.state.startGracefulShutdown)

[gregory-m]

Ok, I found some problems:

1. http2 connection never become active (I mean we never call c.setState(c.rwc, StateActive) on http2 connections), so Shutdown() is not waiting for such connection to finish processing.

2. If I add c.setState(c.rwc, StateActive) here:

   go/src/net/http/server.go

   Line 1800 in fbb819e

   fn(c.server, tlsConn, h)

The graceful shutdown works as expected but curl will complain about malformed HTTP2 frames, and maybe this is bug in curl, because I don't see any wrong HTTP2 packets in Wireshark.

UPD:
Definitely curl bug.

with

curl 7.54.0 (x86_64-apple-darwin18.0) libcurl/7.54.0 LibreSSL/2.6.5 zlib/1.2.11 nghttp2/1.24.1
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtsp smb smbs smtp smtps telnet tftp
Features: AsynchDNS IPv6 Largefile GSS-API Kerberos SPNEGO NTLM NTLM_WB SSL libz HTTP2 UnixSockets HTTPS-proxy

I got curl: (16) Error in the HTTP2 framing layer

But with

curl 7.65.3 (x86_64-apple-darwin18.6.0) libcurl/7.65.3 OpenSSL/1.0.2s zlib/1.2.11 brotli/1.0.7 c-ares/1.15.0 libssh2/1.9.0 nghttp2/1.39.1 librtmp/2.3
Release-Date: 2019-07-19
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: AsynchDNS brotli GSS-API HTTP2 HTTPS-proxy IPv6 Kerberos Largefile libz Metalink NTLM NTLM_WB SPNEGO SSL TLS-SRP UnixSockets

I don't get any error messages, also found this: https://bugzilla.redhat.com/show_bug.cgi?id=1690971

HTTP2 is hard :(

[gregory-m]

Bug was introduced here:
In this commit a79fe53, on this line:

go/src/net/http/server.go

Line 2710 in fbb819e

if st == StateNew && unixSec < time.Now().Unix()-5 {

Also if you change Sleep here for more than 5 seconds

go/src/net/http/serve_test.go

Line 5556 in fbb819e

time.Sleep(20 * time.Millisecond)

Test will fail.

[gregory-m]

/cc @bradfitz

[AlexanderYastrebov]

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

[seankhliao]

Duplicate of #39776