net/http: ConfigureTransport does not work for Transport with custom DialTLS

[fqrious]

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

$ go version

go version go1.15 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
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/fqrious/.cache/go-build"
GOENV="/home/fqrious/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/fqrious/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/fqrious/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/lib/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/lib/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
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-build996052359=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I'm trying to use a custom dialtls function with http.Transport in order to have flexible support for both HTTP/1.1 and HTTP2 but it seems it's just ignoring my call to http2.ConfigureTransport and all requests go over http/1.1

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

What did you expect to see?

2020/09/05 18:21:23 Method: GET
Protocol: HTTP/2.0
Host: http2.golang.org
RemoteAddr: 105.112.53.130:8895
RequestURI: "/reqinfo"
URL: &url.URL{Scheme:"", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/reqinfo", RawPath:"", ForceQuery:false, RawQuery:"", Fragment:""}
Body.ContentLength: 0 (-1 means unknown)
Close: false (relevant for HTTP/1 only)
TLS: &tls.ConnectionState{Version:0x304, HandshakeComplete:true, DidResume:false, CipherSuite:0x1301, NegotiatedProtocol:"h2", NegotiatedProtocolIsMutual:true, ServerName:"http2.golang.org", PeerCertificates:[]*x509.Certificate(nil), VerifiedChains:[][]*x509.Certificate(nil), SignedCertificateTimestamps:[][]uint8(nil), OCSPResponse:[]uint8(nil), ekm:(func(string, []uint8, int) ([]uint8, error))(0x649f20), TLSUnique:[]uint8(nil)}

Headers:
Accept-Encoding: gzip
User-Agent: Go-http-client/2.0

What did you see instead?

2020/09/05 18:22:18 Method: GET
Protocol: HTTP/1.1
Host: http2.golang.org
RemoteAddr: 105.112.53.130:12405
RequestURI: "/reqinfo"
URL: &url.URL{Scheme:"", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/reqinfo", RawPath:"", ForceQuery:false, RawQuery:"", Fragment:""}
Body.ContentLength: 0 (-1 means unknown)
Close: false (relevant for HTTP/1 only)
TLS: &tls.ConnectionState{Version:0x304, HandshakeComplete:true, DidResume:false, CipherSuite:0x1301, NegotiatedProtocol:"", NegotiatedProtocolIsMutual:true, ServerName:"http2.golang.org", PeerCertificates:[]*x509.Certificate(nil), VerifiedChains:[][]*x509.Certificate(nil), SignedCertificateTimestamps:[][]uint8(nil), OCSPResponse:[]uint8(nil), ekm:(func(string, []uint8, int) ([]uint8, error))(0x649f20), TLSUnique:[]uint8(nil)}

Headers:
Accept-Encoding: gzip
User-Agent: Go-http-client/1.1

[tpaschalis]

I spent some time looking through the code to find why this happens. The code splits here for custom and non-custom DialTLS.

In your example, the custom DialTLS is indeed called, but 1) fails to set up the pconn.tlsState in a way that 2) the NegotiatedProtocol is h2, and thus 3) the alt field is never set, which is required for the HTTP/2.0 path.

I'll leave it for more experienced people to chime in, on whether it's a bug; I understand it might be a little disorienting though.

Extra note

Taking a step back I noticed that the custom DialTLS that HTTP/1.1 and HTTP/2.0 are not compatible with each other.

In HTTP/1.1, DialTLS has been deprecated in favor of DialTLSContext. It has the following signature

DialTLS func(network, addr string) (net.Conn, error)

In HTTP/2.0 though,DialTLS has the following signature

DialTLS func(network, addr string, cfg *tls.Config) (net.Conn, error)

[fqrious]

so, I added log.Print("Negotiated:\t", conn.ConnectionState().NegotiatedProtocol) to the line after the handshake and I discovered that the NegotiatedProtocol is empty, so I changed my config so Config.NextProtos is []string{"h2", "http/1.1"} it behaves in the expected way but when I changed my tls package to utls, I started getting

2020/09/06 16:57:20 Negotiated: h2
2020/09/06 16:57:20 Get "https://http2.golang.org/reqinfo": net/http: HTTP/1.x transport connection broken: malformed HTTP response "\x00\x00\x18\x04\x00\x00\x00\x00\x00\x00\x05\x00\x10\x00\x00\x00\x03\x00\x00\x00\xfa\x00\x06\x00\x10\x01@\x00\x04\x00\x10\x00\x00"

which I think is caused by the server replying with an http2 response while it is expecting an http/1.1 response

---

After setting the GODEBUG env variable to http2debug=2, below is what I got

uTLS

2020/09/06 17:16:14 http2: Transport failed to get client conn for http2.golang.org:443: http2: no cached connection was available
2020/09/06 17:16:15 Negotiated: h2
2020/09/06 17:16:16 Get "https://http2.golang.org/reqinfo": net/http: HTTP/1.x transport connection broken: malformed HTTP response "\x00\x00\x18\x04\x00\x00\x00\x00\x00\x00\x05\x00\x10\x00\x00\x00\x03\x00\x00\x00\xfa\x00\x06\x00\x10\x01@\x00\x04\x00\x10\x00\x00"

goTLS

2020/09/06 17:20:58 http2: Transport failed to get client conn for http2.golang.org:443: http2: no cached connection was available
2020/09/06 17:20:59 Negotiated: h2
2020/09/06 17:20:59 http2: Transport creating client conn 0xc000001b00 to 130.211.116.44:443
2020/09/06 17:20:59 http2: Framer 0xc0001f3dc0: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2020/09/06 17:20:59 http2: Framer 0xc0001f3dc0: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2020/09/06 17:20:59 http2: Transport encoding header ":authority" = "http2.golang.org"
2020/09/06 17:20:59 http2: Transport encoding header ":method" = "GET"
2020/09/06 17:20:59 http2: Transport encoding header ":path" = "/reqinfo"
2020/09/06 17:20:59 http2: Transport encoding header ":scheme" = "https"
2020/09/06 17:20:59 http2: Transport encoding header "accept-encoding" = "gzip"
2020/09/06 17:20:59 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2020/09/06 17:20:59 http2: Framer 0xc0001f3dc0: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=44
2020/09/06 17:21:00 http2: Framer 0xc0001f3dc0: read SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
2020/09/06 17:21:00 http2: Transport received SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
2020/09/06 17:21:00 http2: Framer 0xc0001f3dc0: wrote SETTINGS flags=ACK len=0
2020/09/06 17:21:00 http2: Framer 0xc0001f3dc0: read WINDOW_UPDATE len=4 (conn) incr=983041
2020/09/06 17:21:00 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=983041
2020/09/06 17:21:00 http2: Framer 0xc0001f3dc0: read SETTINGS flags=ACK len=0
2020/09/06 17:21:00 http2: Transport received SETTINGS flags=ACK len=0
2020/09/06 17:21:00 http2: Framer 0xc0001f3dc0: read HEADERS flags=END_HEADERS stream=1 len=39
2020/09/06 17:21:00 http2: decoded hpack field header field ":status" = "200"
2020/09/06 17:21:00 http2: decoded hpack field header field "content-type" = "text/plain"
2020/09/06 17:21:00 http2: decoded hpack field header field "content-length" = "834"
2020/09/06 17:21:00 http2: decoded hpack field header field "date" = "Sun, 06 Sep 2020 16:20:59 GMT"
2020/09/06 17:21:00 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=39
2020/09/06 17:21:00 http2: Framer 0xc0001f3dc0: read DATA flags=END_STREAM stream=1 len=834 data="Method: GET\nProtocol: HTTP/2.0\nHost: http2.golang.org\nRemoteAddr: 105.112.28.156:49711\nRequestURI: \"/reqinfo\"\nURL: &url.URL{Scheme:\"\", Opaque:\"\", User:(*url.Userinfo)(nil), Host:\"\", Path:\"/reqinfo\", RawPath:\"\", ForceQuery:false, RawQuery:\"\", Fragment:\"\"}\nB" (578 bytes omitted)
2020/09/06 17:21:00 http2: Transport received DATA flags=END_STREAM stream=1 len=834 data="Method: GET\nProtocol: HTTP/2.0\nHost: http2.golang.org\nRemoteAddr: 105.112.28.156:49711\nRequestURI: \"/reqinfo\"\nURL: &url.URL{Scheme:\"\", Opaque:\"\", User:(*url.Userinfo)(nil), Host:\"\", Path:\"/reqinfo\", RawPath:\"\", ForceQuery:false, RawQuery:\"\", Fragment:\"\"}\nB" (578 bytes omitted)
2020/09/06 17:21:00 Method: GET
Protocol: HTTP/2.0
Host: http2.golang.org
RemoteAddr: 105.112.28.156:49711
RequestURI: "/reqinfo"
URL: &url.URL{Scheme:"", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/reqinfo", RawPath:"", ForceQuery:false, RawQuery:"", Fragment:""}
Body.ContentLength: 0 (-1 means unknown)

---

After more looking into, I found the issue in http.Transport.dialConn where it tries to cast *utls.Conn into *tls.Conn with tc, ok := pconn.conn.(*tls.Conn); and fail (in gdb, ok evaluates to false) and therefore skipping the part where it's supposed to set pconn.tlsState. This way, the transport ignores the fact that it negotiated h2 with the server and expect http/1.x in return

[andybons]

/cc @FiloSottile

[linxiulei]

I believe this is WAI actually because the custom dialTLS uses its own tls.Config, which should have been modified by http2.ConfigureTransport if you rely ontransport.TLSClientConfig. Specifically, transport.TLSClientConfig.NextProtos will be modified to have "h2" so the client would be configured to be able to upgrade to use http/2. Your own dialTLS doesn't have this info.

https://go.dev/play/p/KXWWjY3gpM1 is the fixed version