x/net/http2: Transport returning "http2: no cached connection was available"

[russ-]

1. What version of Go are you using (go version)?
   go version go1.7rc3 darwin/amd64
2. What operating system and processor architecture are you using (go env)?
   GOARCH="amd64"
   GOBIN=""
   GOEXE=""
   GOHOSTARCH="amd64"
   GOHOSTOS="darwin"
   GOOS="darwin"
   GOPATH="/Users/rra/dev"
   GORACE=""
   GOROOT="/Users/rra/opt/homebrew/Cellar/go/1.7rc3/libexec"
   GOTOOLDIR="/Users/rra/opt/homebrew/Cellar/go/1.7rc3/libexec/pkg/tool/darwin_amd64"
   CC="clang"
   GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/00/1m160000h01000cxqpysvccm006h4r/T/go-build956765444=/tmp/go-build -gno-record-gcc-switches -fno-common"
   CXX="clang++"
   CGO_ENABLED="1"
3. What did you do?
   I'm seeing "http2: no cached connection was available" failures from http.Client when I start many (~hundreds) requests at once.

Run https://play.golang.org/p/zKthX7Y9RW with GODEBUG=http2client=0 and GODEBUG=http2client=1 to see the behavior difference.

1. What did you expect to see?
   With http2 enabled, I expect to see requests queue up and eventually succeed.
2. What did you see instead?
   Some requests fail with "http2: no cached connection was available".

See also https://groups.google.com/d/msg/golang-nuts/aw0vboyE1pA/DkOdf_5tDgAJ

[bradfitz]

Even with 500 parallel requests (using your code exactly), I find it hard to reproduce this. I did see it, though.

I see what's happening, though.

After a connection negotiates ALPN protocol "h2", the upgrade function runs,

https://github.com/golang/net/blob/e2ba55e4e78399d85f2a0e0b92396b81ed410633/http2/configure_transport.go#L34

which returns a RoundTripper to use for that request, and also gets a new connection (c *tls.Conn) to use if it wants to:

    upgradeFn := func(authority string, c *tls.Conn) http.RoundTripper {
        addr := authorityAddr("https", authority)
        if used, err := connPool.addConnIfNeeded(addr, t2, c); err != nil {
            go c.Close()
            return erringRoundTripper{err}
        } else if !used {
            // Turns out we don't need this c.
            // For example, two goroutines made requests to the same host
            // at the same time, both kicking off TCP dials. (since protocol
            // was unknown)
            go c.Close()
        }
        return t2
    }

The error message you're seeing is coming from t2 at the bottom there, which is configured to return the error if it doesn't have a usable connection.

The problem is that in addConnIfNeeded,

https://github.com/golang/net/blob/e2ba55e4e78399d85f2a0e0b92396b81ed410633/http2/client_conn_pool.go#L127

It only makes it this far:

func (p *clientConnPool) addConnIfNeeded(key string, t *Transport, c *tls.Conn) (used bool, err error) {
    p.mu.Lock()
    for _, cc := range p.conns[key] {
        if cc.CanTakeNewRequest() {
            p.mu.Unlock()
            return false, nil
        }
    }

It sees that it has a connection and decides to use it, figuring that it'll be usable immediately.

But CanTakeNewRequest accounts for MAX_CONCURRENT_STREAMS:

https://github.com/golang/net/blob/e2ba55e4e78399d85f2a0e0b92396b81ed410633/http2/transport.go#L496

And google.com allows 100 concurrent streams:

$ h2i www.google.com
Connecting to www.google.com:443 ...
Connected to [2607:f8b0:4005:805::2004]:443
[FrameHeader SETTINGS len=24]
  [MAX_CONCURRENT_STREAMS = 100]
  [INITIAL_WINDOW_SIZE = 1048576]
  [MAX_FRAME_SIZE = 16384]
  [MAX_HEADER_LIST_SIZE = 16384]
[FrameHeader WINDOW_UPDATE len=4]
  Window-Increment = 983041

h2i> 

So if you have over 100 goroutines in that codepath at once, all deciding they'll "soon" have an available connection, and without doing any dead-reckoning that they'll soon be taking one of those available slots, then Transport.CanTakeNewRequest returns false later when it's time to actually send a request, the http2.Transport tries to get a new connection, but its connection pool is configured to return ErrNoCachedConn thinking that return value will only be used by the upgrade function to decide whether to use keep the new TLS connection or not.

This is basically #13957 and #13774

[bradfitz]

I think 7a62274 was sufficient to close this bug.

Follow-up work can be done in #13957 and #13774

[WillSewell]

I am still receiving this error on Go 1.9 when performing a large number of concurrent requests (400). Looking at the http2 verbose logs, I can see a large number of http2: no cached connection was available, but only a small % of these bubble up to http.Client.Do. I was looking through the source code to see why these were not being caught by the fix in 7a62274.

The only other place I can see RoundTripper.RoundTrip being called where http2ErrNoCachedConn is not being handled is on this line: https://github.com/golang/go/blob/master/src/net/http/transport.go#L371. I believe the concrete implementation here is noDialH2RoundTripper since we are configuring the client with https://github.com/golang/net/blob/master/http2/transport.go#L125. So my suspicion is this is where the error is being returned from. Is there a reason there is no retrying performed after a error on https://github.com/golang/go/blob/master/src/net/http/transport.go#L371?