http2: send "http/1.1" ALPN in TLS dial in addition to "h2"

RFC 7301 defines the ALPN protocol "http/1.1".

We weren't sending that, so at least one site (dav.box.com) was
rejecting our connection, since they didn't support the only protocol
we advertised ("h2").  Had we advertised nothing, they would've
assumed http/1.1 implicitly.

This CL also hooks up the verbose logging knob to the GODEBUG
environment variable.

Updates golang/go#13598 (fixed when this is copied into std)

Change-Id: I6ea1231d0d0f0bc767caa0458237eefd943d9d3d
Reviewed-on: https://go-review.googlesource.com/17754
Reviewed-by: Ian Lance Taylor <iant@golang.org>

http2/configure_transport.go

@@ -24,6 +24,9 @@ func configureTransport(t1 *http.Transport) error {
 	if !strSliceContains(t1.TLSClientConfig.NextProtos, "h2") {
 		t1.TLSClientConfig.NextProtos = append([]string{"h2"}, t1.TLSClientConfig.NextProtos...)
 	}
+	if !strSliceContains(t1.TLSClientConfig.NextProtos, "http/1.1") {
+		t1.TLSClientConfig.NextProtos = append(t1.TLSClientConfig.NextProtos, "http/1.1")
+	}
 	upgradeFn := func(authority string, c *tls.Conn) http.RoundTripper {
 		cc, err := t2.NewClientConn(c)
 		if err != nil {

http2/http2.go

@@ -20,11 +20,13 @@ import (
 	"fmt"
 	"io"
 	"net/http"
+	"os"
 	"strconv"
+	"strings"
 	"sync"
 )
 
-var VerboseLogs = false
+var VerboseLogs = strings.Contains(os.Getenv("GODEBUG"), "h2debug=1")
 
 const (
 	// ClientPreface is the string that must be sent by new

http2/transport.go

@@ -228,6 +228,7 @@ func (t *Transport) RoundTripOpt(req *http.Request, opt RoundTripOpt) (*http.Res
 	for {
 		cc, err := t.connPool().GetClientConn(req, addr)
 		if err != nil {
+			t.vlogf("failed to get client conn: %v", err)
 			return nil, err
 		}
 		res, err := cc.RoundTrip(req)
@@ -235,6 +236,7 @@ func (t *Transport) RoundTripOpt(req *http.Request, opt RoundTripOpt) (*http.Res
 			continue
 		}
 		if err != nil {
+			t.vlogf("RoundTrip failure: %v", err)
 			return nil, err
 		}
 		return res, nil
@@ -314,7 +316,11 @@ func (t *Transport) dialTLSDefault(network, addr string, cfg *tls.Config) (net.C
 }
 
 func (t *Transport) NewClientConn(c net.Conn) (*ClientConn, error) {
+	if VerboseLogs {
+		t.vlogf("creating client conn to %v", c.RemoteAddr())
+	}
 	if _, err := c.Write(clientPreface); err != nil {
+		t.vlogf("client preface write error: %v", err)
 		return nil, err
 	}
 
@@ -805,6 +811,9 @@ func (rl *clientConnReadLoop) run() error {
 	cc := rl.cc
 	for {
 		f, err := cc.fr.ReadFrame()
+		if err != nil {
+			cc.vlogf("Transport readFrame error: (%T) %v", err, err)
+		}
 		if se, ok := err.(StreamError); ok {
 			// TODO: deal with stream errors from the framer.
 			return se

http2/transport_test.go

@@ -437,10 +437,11 @@ func TestConfigureTransport(t *testing.T) {
 		// Laziness, to avoid buildtags.
 		t.Errorf("stringification of HTTP/1 transport didn't contain \"h2\": %v", got)
 	}
+	wantNextProtos := []string{"h2", "http/1.1"}
 	if t1.TLSClientConfig == nil {
 		t.Errorf("nil t1.TLSClientConfig")
-	} else if !reflect.DeepEqual(t1.TLSClientConfig.NextProtos, []string{"h2"}) {
-		t.Errorf("TLSClientConfig.NextProtos = %q; want just 'h2'", t1.TLSClientConfig.NextProtos)
+	} else if !reflect.DeepEqual(t1.TLSClientConfig.NextProtos, wantNextProtos) {
+		t.Errorf("TLSClientConfig.NextProtos = %q; want %q", t1.TLSClientConfig.NextProtos, wantNextProtos)
 	}
 	if err := ConfigureTransport(t1); err == nil {
 		t.Error("unexpected success on second call to ConfigureTransport")