· code
golang zk大量disconnected event
背景
在容器平台上我们提供了zk做白名单功能，Pod启动时 sidecar 会自动注册zk。昨天遇到zk server抖动，sidecar容器输出大量StateDisconnected事件，zk 正常后仍无法恢复，由于大量日志造成sidecar容器 cpu 占用过高，进而引发dockerdcpu 占用过高，严重时影响 dockerd 正常调用。
问题分析
问题复现
正常情况下，sidecar启动后会去注册zk：
# docker logs -f 01a1a4a74785
I0302 15:04:05.476463 1 manager.go:116] start run plugin zk
2021/03/02 15:04:05 Connected to 10.38.161.60:11000
I0302 15:04:05.488006 1 zk.go:152] zookeeper connect succeed: zk.srv:11000
2021/03/02 15:04:05 authenticated: id=33746806328105493, timeout=30000
2021/03/02 15:04:05 re-submitting `0` credentials after reconnect
I0302 15:04:05.516446 1 zk.go:220] watching zk node:[/tasks/cluster.xxx_default_deployment.htool/10.46.12.72] in cluster[xxx] #注册成功，开始watch
通过iptables 来模拟异常，首先进入到容器network namesapce
pod=htool-6875bcb898-w7llc
containerid=$(docker ps |grep $pod|awk '{print $1}'|head -n 1)
pid=$(docker inspect -f {{.State.Pid}} $containerid)
nsenter -n --target $pid
使用iptables drop掉发往zk的请求(11000 为 zk server 端口)
iptables -A OUTPUT -p tcp -m tcp --dport 11000 -j DROP
zk client 自动重试（1s 一次），日志显示Failed to connect to 10.38.161.54:11000: dial tcp 10.38.161.54:11000: i/o timeout
I0302 15:04:05.516446 1 zk.go:220] watching zk node:[/tasks/cluster.xxx_default_deployment.htool/10.46.12.72] in cluster[xxx]
2021/03/02 15:08:55 recv loop terminated: err=failed to read from connection: read tcp 10.46.12.72:36884->10.38.161.60:11000: i/o timeout
2021/03/02 15:08:55 send loop terminated: err=<nil>
2021/03/02 15:08:56 Failed to connect to 10.38.161.54:11000: dial tcp 10.38.161.54:11000: i/o timeout
网络恢复，删除iptables
iptables -D OUTPUT -p tcp -m tcp --dport 11000 -j DROP
出现大量StateDisconnected日志
I0302 15:09:50.951897 1 zk.go:232] Unknown zk event[StateDisconnected] for znode:[/tasks/cluster.xxx_default_deployment.htool/10.46.12.72]
I0302 15:09:50.951893 1 zk.go:232] Unknown zk event[StateDisconnected] for znode:[/tasks/cluster.xxx_default_deployment.htool/10.46.12.72]
...
问题分析
sidecar中 zk watch 代码如下：
exist, _, eventCh, err := conn.ExistsW(node) //监听zk事件
watcher:
for {
select {
case e := <-eventCh:
switch e.State {
case zk.StateExpired:
return fmt.Errorf("node[%v] expired", node)
case zk.StateConnected, zk.StateHasSession:
return fmt.Errorf("Get zk event: %v ", e.State)
default:
klog.Infof("Get zk event[%v] for znode:[%v]", e.State, node) // 出错位置
}
case <-ctx.Done():
// we close the conn in caller
break watcher
}
}
ExistsW函数由github.com/samuel/go-zookeeper/zk库提供，监听 zk 给定目录的事件
func (c *Conn) ExistsW(path string) (bool, *Stat, <-chan Event, error) {
var ech <-chan Event
...
ech = c.addWatcher(path, watchTypeData)
return exists, &res.Stat, ech, err
}
当 zk 异常恢复后，c.addWatcher中的channel被close，即sidecar中eventCh关闭，进入死循环。
修复验证
知道了原因，修复很简单，判断下 eventCh 状态即可
for {
select {
case e, ok := <-eventCh:
if !ok {
return fmt.Errorf("event channel closed")
}
if e.Err != nil {
return fmt.Errorf("Get zk event: %v, err: %v", e.State, e.Err)
}
switch e.State {
case zk.StateExpired:
return fmt.Errorf("node[%v] expired", node)
case zk.StateConnected, zk.StateHasSession:
return fmt.Errorf("Get zk event: %v ", e.State)
default:
klog.Infof("Get zk event[%v] for znode:[%v]", e.State, node)
}
}
在修复代码后，再次验证可正常注册
2021/03/02 15:13:40 Failed to connect to 10.38.161.60:11000: dial tcp 10.38.161.60:11000: i/o timeout
2021/03/02 15:13:40 Connected to 10.38.161.55:11000
2021/03/02 15:13:40 authentication failed: zk: session has been expired by the server
W0302 15:13:40.222923 1 zk.go:300] meet error when watching node path: Get zk event: StateDisconnected, err: zk: session has been expired by the server
2021/03/02 15:13:40 Connected to 10.38.161.54:11000
2021/03/02 15:13:40 authenticated: id=177861994644216038, timeout=30000
2021/03/02 15:13:40 re-submitting `1` credentials after reconnect
I0302 15:13:41.238524 1 zk.go:220] watching zk node:[/tasks/cluster.xxx_default_deployment.htool/10.46.12.72] in cluster[xxx]
总结
这个问题其实与zk没关系，是由于没有判断channel状态，陷入死循环。通常情况下大部分应用只有退出时才会关闭channel，不需要特殊处理。