一个Go升级引起的血案

by 伊布

直接现象：使用Go 1.13编译kube-controller-manager，运行一段时间后，发现controller不工作，查看日志，发现打印“http2: no cached connection was available”。

I0328 09:48:59.925056       1 round_trippers.go:383] GET https://10.220.14.10:8443/api/v1/namespaces/kube-system/endpoints/kube-controller-manager
I0328 09:48:59.925085       1 round_trippers.go:390] Request Headers:
I0328 09:48:59.925094       1 round_trippers.go:393]     User-Agent: kube-controller-manager/v1.11.1 (linux/amd64) kubernetes/b1b2997/leader-election
I0328 09:48:59.925102       1 round_trippers.go:393]     Accept: application/vnd.kubernetes.protobuf, */*
I0328 09:48:59.925148       1 round_trippers.go:408] Response Status:  in 0 milliseconds
E0328 09:48:59.925199       1 leaderelection.go:234] error retrieving resource lock kube-system/kube-controller-manager: Get https://10.220.14.10:8443/api/v1/namespaces/kube-system/endpoints/kube-controller-manager: http2: no cached connection was available
I0328 09:48:59.925216       1 leaderelection.go:190] failed to acquire lease kube-system/kube-controller-manager

使用1.13会有上面的现象。使用1.12版本没有问题。k8s版本是1.11。

从go代码查询“no cached connection was available”，可以看到是http2noCachedConnError错误。

// noCachedConnError is the concrete type of ErrNoCachedConn, which
// needs to be detected by net/http regardless of whether it's its
// bundled version (in h2_bundle.go with a rewritten type name) or
// from a user's x/net/http2. As such, as it has a unique method name
// (IsHTTP2NoCachedConnError) that net/http sniffs for via func
// isNoCachedConnError.
type http2noCachedConnError struct{}

func (http2noCachedConnError) IsHTTP2NoCachedConnError() {}

func (http2noCachedConnError) Error() string { return "http2: no cached connection was available" }

// isNoCachedConnError reports whether err is of type noCachedConnError
// or its equivalent renamed type in net/http2's h2_bundle.go. Both types
// may coexist in the same running program.
func http2isNoCachedConnError(err error) bool {
	_, ok := err.(interface{ IsHTTP2NoCachedConnError() })
	return ok
}

var http2ErrNoCachedConn error = http2noCachedConnError{}

由于问题必现，所以不妨使用delve跟踪。

复现方法：配置kube-controller-manage连接1个API Server，当kube-controller-manag正常运行时，将API Server关闭，然后重新启动API Server，之后去查看kube-controller-manager的日志，会打印”http2: no cached connection was available”。

从代码上分析，http2ErrNoCachedConn 只在 src/net/http/h2_bundle.go 中会返回，那么判断可能是在函数getClientConn出错了。来看下Go源码的实现。

func (p *http2clientConnPool) getClientConn(req *Request, addr string, dialOnMiss bool) (*http2ClientConn, error) {
	if http2isConnectionCloseRequest(req) && dialOnMiss {
		// It gets its own connection.
		http2traceGetConn(req, addr)
		const singleUse = true
		cc, err := p.t.dialClientConn(addr, singleUse)
		if err != nil {
			return nil, err
		}
		return cc, nil
	}
	p.mu.Lock()
	for _, cc := range p.conns[addr] {
		if st := cc.idleState(); st.canTakeNewRequest {
			if p.shouldTraceGetConn(st) {
				http2traceGetConn(req, addr)
			}
			p.mu.Unlock()
			return cc, nil
		}
	}
	if !dialOnMiss {
		p.mu.Unlock()
		return nil, http2ErrNoCachedConn
	}

dlv attach pid后，尝试对getClientConn打断点，发现有2个getClientConn，一个在上面看到的在Go源码中，而另一个是在k8s源码的vendor目录下。那么，实际运行中，会调用到哪个呢？没关系，都打上断点。

(dlv) b getClientConn
Command failed: Location "getClientConn" ambiguous: net/http.(*http2clientConnPool).getClientConn, k8s.io/kubernetes/vendor/golang.org/x/net/http2.(*clientConnPool).getClientConn…
(dlv) b net/http.(*http2clientConnPool).getClientConn
Breakpoint 3 (enabled) set at 0x7b6b93 for net/http.(*http2clientConnPool).getClientConn() .usr/local/go/src/net/http/h2_bundle.go:749
(dlv) b k8s.io/kubernetes/vendor/golang.org/x/net/http2.(*clientConnPool).getClientConn
Breakpoint 4 (enabled) set at 0x841a03 for k8s.io/kubernetes/vendor/golang.org/x/net/http2.(*clientConnPool).getClientConn() .export/hubt/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/golang.org/x/net/http2/client_conn_pool.go:55

继续执行，会进入断点，可以看到，调用的是k8s源码vendor目录下的getClientConn。

 0  0x0000000000851ff3 in k8s.io/kubernetes/vendor/golang.org/x/net/http2.(*clientConnPool).getClientConn
    at .Users/hubaotao/Code/GoGo/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/golang.org/x/net/http2/client_conn_pool.go:55
 1  0x000000000085355e in k8s.io/kubernetes/vendor/golang.org/x/net/http2.noDialClientConnPool.GetClientConn
    at .Users/hubaotao/Code/GoGo/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/golang.org/x/net/http2/client_conn_pool.go:255
 2  0x000000000086d985 in k8s.io/kubernetes/vendor/golang.org/x/net/http2.(*Transport).RoundTripOpt
    at .Users/hubaotao/Code/GoGo/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/golang.org/x/net/http2/transport.go:345
 3  0x0000000000853cee in k8s.io/kubernetes/vendor/golang.org/x/net/http2.(*Transport).RoundTrip
    at .Users/hubaotao/Code/GoGo/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/golang.org/x/net/http2/transport.go:313
 4  0x0000000000853cee in k8s.io/kubernetes/vendor/golang.org/x/net/http2.noDialH2RoundTripper.RoundTrip
    at .Users/hubaotao/Code/GoGo/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/golang.org/x/net/http2/configure_transport.go:75
 5  0x00000000008161aa in net/http.(*Transport).roundTrip
    at .usr/local/go/src/net/http/transport.go:486
 6  0x00000000007fc4d5 in net/http.(*Transport).RoundTrip
    at .usr/local/go/src/net/http/roundtrip.go:17
 7  0x0000000000ea9100 in k8s.io/kubernetes/vendor/k8s.io/client-go/transport.(*userAgentRoundTripper).RoundTrip
    at .Users/hubaotao/Code/GoGo/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/client-go/transport/round_trippers.go:162
 8  0x00000000007bfafa in net/http.send
    at .usr/local/go/src/net/http/client.go:250
 9  0x00000000007bf51a in net/http.(*Client).send

来看看它的实现。

var ErrNoCachedConn = errors.New("http2: no cached connection was available")

func (p *clientConnPool) getClientConn(req *http.Request, addr string, dialOnMiss bool) (*ClientConn, error) {
	if isConnectionCloseRequest(req) && dialOnMiss {
		// It gets its own connection.
		const singleUse = true
		cc, err := p.t.dialClientConn(addr, singleUse)
		if err != nil {
			return nil, err
		}
		return cc, nil
	}
	p.mu.Lock()
	for _, cc := range p.conns[addr] {
		if cc.CanTakeNewRequest() {
			p.mu.Unlock()
			return cc, nil
		}
	}
	if !dialOnMiss {
		p.mu.Unlock()
		return nil, ErrNoCachedConn
	}
	call := p.getStartDialLocked(addr)
	p.mu.Unlock()
	<-call.done
	return call.res, call.err
}

可以看到，这里会返回 ErrNoCachedConn（从堆栈上看，rt为noDialH2RoundTripper，所以dialOnMiss值为false），而ErrNoCachedConn的值，的确是kube-controller-manager打印的字符串。

从前面的堆栈看，错误码会一路返回到 configure_transport.go 的 RoundTrip。来看下这块代码。

func (rt noDialH2RoundTripper) RoundTrip(req *http.Request) (*http.Response, error) {
	res, err := rt.t.RoundTrip(req)
	if err == ErrNoCachedConn {
		return nil, http.ErrSkipAltProtocol
	}
	return res, err
}

从这里可以看到，如果返回的错误码是 noDialH2RoundTripper，会把它转为http.ErrSkipAltProtocol再返回。错误不是这里打印的。

继续往回看堆栈，在Go源码的roundTrip中，针对http.ErrSkipAltProtocol的确有特殊处理，针对这种错误不会直接返回报错。

继续单步跟踪下去，可以看到，在pconn的roundTrip中返回了ErrNoCachedConn，但在http2isNoCachedConnError判断时，认为不是同一个错误，没有执行t.removeIdleConn(pconn)，并进入了 pconn.shouldRetryRequest，并最终返回了ErrNoCachedConn。

// roundTrip implements a RoundTripper over HTTP.
func (t *Transport) roundTrip(req *Request) (*Response, error) {
...
	if t.useRegisteredProtocol(req) {
		altProto, _ := t.altProto.Load().(map[string]RoundTripper)
		if altRT := altProto[scheme]; altRT != nil {
			if resp, err := altRT.RoundTrip(req); err != ErrSkipAltProtocol {
				return resp, err
			}
		}
	}
...
	for {
...
      pconn, err := t.getConn(treq, cm)
		if err != nil {
			t.setReqCanceler(req, nil)
			req.closeBody()
			return nil, err
		}

		var resp *Response
		if pconn.alt != nil {
			// HTTP/2 path.
			t.setReqCanceler(req, nil) // not cancelable with CancelRequest
			resp, err = pconn.alt.RoundTrip(req)
		} else {
			resp, err = pconn.roundTrip(treq)
		}
		if err == nil {
			return resp, nil
		}
		if http2isNoCachedConnError(err) {
			t.removeIdleConn(pconn)
		} else if !pconn.shouldRetryRequest(req, err) {
			// Issue 16465: return underlying net.Conn.Read error from peek,
			// as we've historically done.
			if e, ok := err.(transportReadFromServerError); ok {
				err = e.err
			}
			return nil, err
		}

给shouldRetryRequest也打上断点(同样的，它也出现了2处)。

b net/http.(*persistConn).shouldRetryRequest
b k8s.io/kubernetes/vendor/golang.org/x/net/http2.shouldRetryRequest

在复现时查看到堆栈如下，打印下入参 err ，确实是ErrNoCachedConn。

 0  0x0000000000816413 in net/http.(*persistConn).shouldRetryRequest
    at .usr/local/go/src/net/http/transport.go:569
 1  0x0000000000815ce9 in net/http.(*Transport).roundTrip
    at .usr/local/go/src/net/http/transport.go:543
 2  0x00000000007fc4d5 in net/http.(*Transport).RoundTrip
    at .usr/local/go/src/net/http/roundtrip.go:17
 3  0x0000000000ea9100 in k8s.io/kubernetes/vendor/k8s.io/client-go/transport.(*userAgentRoundTripper).RoundTrip
    at .Users/hubaotao/Code/GoGo/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/client-go/transport/round_trippers.go:162
 4  0x00000000007bfafa in net/http.send
    at .usr/local/go/src/net/http/client.go:250
 5  0x00000000007bf51a in net/http.(*Client).send
(dlv) p err
error(*errors.errorString) *{
	s: "http2: no cached connection was available",}

我们来看下shouldRetryRequest的实现。

func (pc *persistConn) shouldRetryRequest(req *Request, err error) bool {
	if http2isNoCachedConnError(err) {
		// Issue 16582: if the user started a bunch of
		// requests at once, they can all pick the same conn
		// and violate the server's max concurrent streams.
		// Instead, match the HTTP/1 behavior for now and dial
		// again to get a new TCP connection, rather than failing
		// this request.
		return true
	}
...
	return false // conservatively

可以看到，如果 no cached conn，是会返回true，即表示应该会retry。但单独跟踪下去发现并没有retry，这样从前面的代码分析，会返回错误码到 http.send，也就是打印出来的日志。

所以，可以看到，问题是出在 http2isNoCachedConnError。前面有贴它的实现，再贴一下。

func http2isNoCachedConnError(err error) bool {
	_, ok := err.(interface{ IsHTTP2NoCachedConnError() })
	return ok
}

写个小代码检查下，ErrNoCachedConn 是否满足 http2isNoCachedConnError(https://play.golang.org/p/fB8ilA6-VPZ)。

package main

import (
	"errors"
	"fmt"
)

type http2noCachedConnError struct{}

func (http2noCachedConnError) IsHTTP2NoCachedConnError() {}

func (http2noCachedConnError) Error() string { return "http2: no cached connection was available" }

// isNoCachedConnError reports whether err is of type noCachedConnError
// or its equivalent renamed type in net/http2's h2_bundle.go. Both types
// may coexist in the same running program.
func http2isNoCachedConnError(err error) bool {
	_, ok := err.(interface{ IsHTTP2NoCachedConnError() })
	return ok
}
func main(){
	var ErrNoCachedConn = errors.New("http2: no cached connection was available")
	res := http2isNoCachedConnError(ErrNoCachedConn)
	fmt.Printf("result 1 %v\n", res)

	var err = http2noCachedConnError{}
	res = http2isNoCachedConnError(err)
	fmt.Printf("result 2 %v\n", res)

	if ErrNoCachedConn.Error() == err.Error() {
		fmt.Printf("same result!")
	}
}

可以看到，虽然他们的值是相同的，但 ErrNoCachedConn 并不符合 http2isNoCachedConnError 的要求，这样也就导致了上面一直报错，没有发起重连。

当然这个问题解决很简单，不要用Go 1.13版本编译，用Go 1.12版本就不会问题。 1.12版本的重连逻辑与1.13不一样，如何不同，有机会再分析。

当然，也可以修改k8s源码里vendor的实现，统一两边错误码的定义，这样可以使用后续版本的Go，不过最好不要改vendor。

事实上，Go在后续版本的实现里，也是这样做的，具体可以看这两个patch：

不过，这个patch考虑不是很周到，要是这样改，向前兼容会更好一些：

func http2isNoCachedConnError(err error) bool {
	_, ok := err.(interface{ IsHTTP2NoCachedConnError() })
	if !ok {
		if err.Error() == http2ErrNoCachedConn.Error() {
			return true
		}
	}
	return ok
}

一个Go升级引起的血案

一个Go升级引起的血案

Recommend

创下MLPerf基准测试记录 NVIDIA AI推理平台首秀创佳绩

东币西输：欧美持续买入亚洲人的比特币

DeFiBox宣布与Bitpie钱包达成战略合作

Timberland整合营销，原来甘蔗也可以很潮酷

四川内江5500万区块链资产盗窃案告破

Square报告：比特币挖矿为何成为“清洁能源未来的关键”？

加速计划与创新大赛欧特克与产业伙伴打造行字数字生态

Taruhan Olahraga Kemungkinan di Pemungutan Suara Alabama pada tahun 2022

美国SEC开始正式审查Kryptoin比特币ETF

Simple library to decompress files .zip, .rar, .cbz, .cbr in React Native

About Joyk