问题引入
某个夜黑风高的早晨，忽然接管到大量谬误日志报警『failed to dial server: dial tcp xxxx:yy: i/o timeout』。原来是微服务客户端申请服务端，连贯失败。
简略介绍下服务现状：咱们的服务部署在k8s环境，微服务框架咱们应用的是smallnest/rpcx，注册核心基于zookeeper，链路如下图所示：
接下来初步剖析下问题现状：
- 第一步：这些连贯超时的服务端是有什么异样吗？依据连贯超时的IP地址查找对应的容器服务，发现没有一个容器服务是这个IP地址；那这个IP地址是从哪来的呢？难道是在某个隐秘的角落启动的？
- 第二步：连贯注册核心，查看该服务端注册的IP列表，发现也不存在下面超时的IP地址。
- 进一步：这个异样IP地址，k8s环境历史的确调配过；猜想服务端重启后，IP地址变了，然而客户端却没有更新IP列表，导致还申请老的IP地址。
另外，谬误日志只集中在一个客户端实例，即只有一个客户端容器服务没有更新服务端的IP列表。初步猜想可能有两种起因：1）这个客户端与zookeeper之间连贯存在异样，所以zookeeper无奈告诉数据变更；2）服务发现框架存在代码异样，且只在某些场景触发，导致无奈更新本地IP列表，或者是没有watch数据变更。
针对第一种猜想，很简略就能验证，登录到该异样pod，查看与zookeeper之间的连贯即可：
# netstat -anp | grep 2181tcp 0 0 xxxx:51970 yyyy:2181 ESTABLISHED 9/xxxxtcp 0 0 xxxx:40510 yyyy:2181 ESTABLISHED 9/xxxx能够看到存在两条失常的TCP连贯，为什么是两条呢？因为该过程不止作为客户端拜访其余服务，还作为服务端供其余客户端调用，其中一条连贯是用来注册服务，另外一条连贯用来发现服务。tcpdump抓包看看这两条连贯的数据交互：
23:01:58.363413 IP xxxx.51970 > yyyy.2181: Flag [P.], seq 2951753839:2951753851, ack 453590484, win 356, length 1223:01:58.363780 IP yyyy.2181 > xxxx.51970: Flags [P.], seq 453590484:453590504, ack 2951753851, win 57, length 2023:01:58.363814 IP xxxx.51970 > yyyy.2181: Flags [.], ack 453590504, win 356, length 0……下面省略了抓包的内容局部。留神zookeeper点采纳二进制协定，不太不便辨认然而根本能够确信，这是ping-pong心跳包（定时交互，且每次数据统一）。并且，两条连贯都有失常的心跳包频繁交互。也就是说客户端与zookeeper之间连贯失常，那么很可能就是服务发现框架的代码问题了。
模仿验证
通过下面的剖析，可能的起因是：服务发现框架存在代码异样，且只在某些场景触发，导致无奈更新本地IP列表，或者是没有watch数据变更。
客户端有没有watch数据变更，这一点非常容易验证；只须要重启一台服务，客户端tcpdump抓包就行。只不过zookeeper点采纳二进制协定，不好剖析数据包内容。
所以咱们先简略介绍下zookeeper通信协议；如下图所示，图中4B示意该字段长度为4Byte。
能够看到，每一个申请（响应），头部都有4字节标识该申请体的长度；另外，申请头部Opcode标识该申请类型，比方获取节点数据，创立节点等。watch事件告诉是没有申请，只有响应，其中Type标识事件类型，Path为产生事件的节点门路。
从zookeeper SDK能够找到所有申请类型，以及事件类型的定义。
const ( opNotify = 0 opCreate = 1 opDelete = 2 opExists = 3 opGetData = 4 //获取节点数据，这是咱们须要关注的 opSetData = 5 opGetAcl = 6 opSetAcl = 7 opGetChildren = 8 opSync = 9 opPing = 11 opGetChildren2 = 12 //获取子节点列表，这是咱们须要关注的 opCheck = 13 opMulti = 14 opClose = -11 opSetAuth = 100 opSetWatches = 101)const ( EventNodeCreated EventType = 1 EventNodeDeleted EventType = 2 EventNodeDataChanged EventType = 3 EventNodeChildrenChanged EventType = 4 //子节点列表变动，这是咱们须要关注的)上面能够开始操作了，客户端tcpdump开启抓包，服务端杀死一个容器服务，剖析抓包数据如下：
//zookeeper数据变更事件告诉23:02:02.717505 IP xxxx.2181 > xxxx.51970: Flags [P.], seq 453590524:453590585, ack 2951753863, win 57, length 61 0000 0039 ffff ffff ffff ffff ffff .....9.......... 0x0050: ffff 0000 0000 0000 0004 0000 0003 0000 ................ 0x0060: 001d xxxx xxxx xxxx xxxx xxxx xxxx xxxx ../xxxxxxxxxxxxx 0x0070: xxxx xxxx xxxx xxxx xxxx xxxx xxxx xx xxxxxxxxxxxxxxx23:02:02.717540 IP xxxx.51970 > xxxx.2181: Flags [.], ack 453590585, win 356, length 0//客户端发动申请，获取子节点列表23:02:02.717752 IP xxxx.51970 > xxxx.2181: Flags [P.], seq 2951753863:2951753909, ack 453590585, win 356, length 46 0000 002a 0000 4b2f 0000 000c 0000 .....*..K/...... 0x0050: 001d xxxx xxxx xxxx xxxx xxxx xxxx xxxx ../xxxxxxxxxxxxx 0x0060: xxxx xxxx xxxx xxxx xxxx xxxx xxxx xx00 xxxxxxxxxxxxxxx.//zookeeper响应，蕴含服务端所有节点（IP）23:02:02.718500 IP xxxx.2181 > xxxx.51970: Flags [P.], seq 453590585:453591858, ack 2951753909, win 57, length 1273//遍历所有节点（IP），获取数据（metadata）23:02:02.718654 IP xxxx.51970 > xxxx.2181: Flags [P.], seq 2951753909:2951753978, ack 453591858, win 356, length 69 0000 0041 0000 4b30 0000 0004 0000 .....A..K0...... 0x0050: 0034 xxxx xxxx xxxx xxxx xxxx xxxx xxxx .4/xxxxxxxxxxxxx 0x0060: xxxx xxxx xxxx xxxx xxxx xxxx xxxx xxxx xxxxxxxxxxxxxxxx 0x0070: xxxx xxxx xxxx xxxx xxxx xxxx xxxx xxxx xxxxxxxxxxxxxxxx 0x0080: xxxx xxxx xxxx 00 xxxxxxx23:02:02.720273 IP xxxx.2181 > xxxx.51970: Flags [P.], seq 453591858:453591967, ack 2951753978, win 57, length 109 0000 0069 0000 4b30 0000 0003 0ab3 .....i..K0...... 0x0050: ad90 0000 0000 0000 0011 6772 6f75 703d ..........group= 0x0060: 6f6e 6c69 6e65 2674 7073 3d00 0000 030a online&tps=..... 0x0070: b2ff ed00 0000 030a b3ad 5800 0001 76ae ..........X...v. 0x0080: d003 dd00 0001 76af 051d 6d00 0000 3a00 ......v...m...:. 0x0090: 0000 0000 0000 0001 703f 90a3 f679 ce00 ........p?...y.. 0x00a0: 0000 1100 0000 0000 0000 030a b2ff ed ............... ……整个过程的交互流程如下图所示：
能够看到，zookeeper在数据变更时告诉客户端了，而客户端也拉取最新节点列表了，而且获取到的节点IP列表都是正确的。这就奇怪了，都曾经获取到最新的IP列表了，为什么还申请老的IP地址？是没有更新内存中的数据吗？这就review代码了。
代码Review
咱们的微服务框架应用的是smallnest/rpcx，监听zookeeper数据变更的逻辑，如下所示：
//死循环监听数据变动，通过管道返回数据到下层业务for { _, _, eventCh, err := s.client.ChildrenW(s.normalize(directory)) select { case e := <-eventCh: if e.Type == zk.EventNodeChildrenChanged { keys, stat, err := s.client.Children(s.normalize(directory)) //循环获取所有节点数据 for _, key := range keys { pair, err := s.Get(strings.TrimSuffix(directory, "/") + s.normalize(key)) } } }}留神获取子节点列表的两个办法，ChildrenW以及Children；这两是有区别的：
func (c *Conn) Children(path string) ([]string, *Stat, error) { _, err := c.request(opGetChildren2, &getChildren2Request{Path: path, Watch: false}, res, nil) return res.Children, &res.Stat, err}func (c *Conn) ChildrenW(path string) ([]string, *Stat, <-chan Event, error) { _, err := c.request(opGetChildren2, &getChildren2Request{Path: path, Watch: true}, res, func(req *request, res *responseHeader, err error) { return res.Children, &res.Stat, ech, err}原来，办法的后缀『W』代表着是否设置监听器。这里读者须要晓得，zookeeper的监听器是一次性的。即客户端设置监听器后，数据变更时候，zookeeper查问监听器告诉客户端，同时会删除该监听器。这就导致下次数据变更时候不会告诉客户端了。
这有什么问题吗？兴许会有问题。客户端接管到数据变更后次要有三步逻辑：1）获取子节点列表，留神这时候并没有设置监听器；2）遍历所有节点获取数据；3）获取子节点列表，设置监听器，期待zookeeper事件告诉。留神从第一步到第三步，是有耗时的，特地是服务端节点数目过多时候，屡次申请耗时必然更高，那么在这之间的数据变更客户端是感知不到的。再联合代码降级流程，是滚动降级，即启动如干新版本容器服务（目前配置25%数目），如果这些容器服务失常启动，则杀掉局部老版本容器服务；顺次类推。
如果从第一局部新版本容器服务启动，到最初一部分新版本容器服务启动以及杀掉最初一些老版本容器服务，之间距离十分短呢？小于下面第一步到第三步耗时呢？这样就会导致，客户端既存在老的IP列表，也存在新的IP列表。（上一大节模仿验证时候，只是杀死一个容器服务验证数据监听机制，并没有模仿大量容器服务重启过程并剖析数据交互，因而无奈确定这类场景是否存在问题）。整个过程如下图所示：
持续剖析日志，发现客户端申请所有服务端的IP地址都是谬误的，即客户端并不存在新的IP地址，不合乎该场景。不过，zookeeper监听器一次性机制还是须要关注，以防呈现数据变更无奈同步问题。
柳暗花明
还能有什么起因呢？只能持续扒代码了，既然rpcx获取到了最新的IP列表，为什么没有更新呢？这就须要重点剖析rpcx数据更新逻辑了。
如图所示，ZookeeperDiscovery监听到服务端IP变更时候，将最新的IP列表写入chan，rpcxClient通过chan可获取最新的IP列表，并更新selector（selector提供负载平衡能力）。这个逻辑能够说是非常简单了，没有理由会出现异常。然而事实证明，异样大概率就在这块逻辑。难道是rpcxClient读取chan数据的协程有异样了？看看协程栈帧，也并没有问题。
通过pprof工具，剖析服务协程状况，rpcxClient协程调用栈失常，ZookeeperDiscovery协程调用栈失常，两者数目保持一致（客户端毕竟不止是只拜访一个微服务，所以会存在多个rpcxClient）。监听的两个子协程都没有问题。
go tool pprof http://localhost:17009/debug/pprof/goroutine(pprof) traces 5 runtime.gopark runtime.goparkunlock runtime.chanrecv runtime.chanrecv2 github.com/smallnest/rpcx/client.(*xClient).watch-----------+-------------------------------------------------------5 runtime.gopark runtime.selectgo github.com/smallnest/rpcx/client.(*ZookeeperDiscovery).watch只能持续摸索。。。
联想到之前还增加了服务发现灾备逻辑（避免zookeeper出现异常或者客户端到zookeeper之间链路异样），在监听到zookeeper数据变动时，还会将该数据写入本地文件。服务启动时，如果zookeeper无奈连贯，能够从本地文件读取服务端IP列表。这时候的流程应该是如下图所示：
查看文件中的IP列表以及文件更新工夫，发现都没有任何问题：
# stat /xxxx File: /xxxxAccess: 2020-12-24 22:06:16.000000000Modify: 2020-12-29 23:02:14.000000000Change: 2020-12-29 23:02:14.000000000这就不堪设想了，文件中都是正确的IP列表，rpcxClient却不是？而rpcxClient更新数据的逻辑简略的不能再简略了，根本没有出错的可能性啊。难道是基于chan的数据通信有问题？再钻研钻研chan相干逻辑。
rpcxClient与LocalWrapClient是通过WatchService办法获取通信的chan。能够看到，这里新建chan，并append到d.chans切片中。那如果两个协程同时WatchService呢？就可能呈现并发问题，切片中最终可能只会有一个chan！这就解释了为什么本地文件能够失常更新，rpcxClient始终无奈更新。
func (d *ZookeeperDiscovery) WatchService() chan []*KVPair { ch := make(chan []*KVPair, 10) d.chans = append(d.chans, ch) return ch}咱们再写个小例子模仿一下这种case，验证并发append问题：
package mainimport ( "fmt" "sync")func main() { ok := true for i := 0; i <1000; i ++ { var arr []int wg := sync.WaitGroup{} for j := 0; j <2; j ++ { wg.Add(1) go func() { defer wg.Done() arr = append(arr, i) }() } wg.Wait() if len(arr) < 2 { fmt.Printf("error:%d \n", i) ok = false break } } if ok { fmt.Println("ok") }}//error:261 至此，问题根本明了。解决方案也很简略，去掉服务发现灾备逻辑即可。
后记
下面提到，客户端接管到注册核心数据变更后次要有三步逻辑：1）获取子节点列表，留神这时候并没有设置监听器；2）遍历所有节点获取数据；3）获取子节点列表，设置监听器，期待zookeeper事件告诉。留神从第一步到第三步，是有耗时的，特地是服务端节点数目过多时候，屡次申请耗时必然更高，那么在这之间的数据变更客户端是感知不到的。参考上面的抓包数据，从第一次收到数据变更事件获取节点列表，到下一次设置监听器之间，大略有几十毫秒左右的时间差。
//第一步获取子节点列表，没有设置监听器；留神最初一个字节为0x00，即watch=false23:02:02.717752 IP xxxx.51970 > xxxx.2181: Flags [P.], seq 2951753863:2951753909, ack 453590585, win 356, length 46 0000 002a 0000 4b2f 0000 000c 0000 .....*..K/...... 0x0050: 001d xxxx xxxx xxxx xxxx xxxx xxxx xxxx ../xxxxxxxxxxxxx 0x0060: xxxx xxxx xxxx xxxx xxxx xxxx xxxx xx00 xxxxxxxxxxxxxxx. //第一步获取子节点列表，并设置监听器；留神最初一个字节为0x01，即watch=true23:02:02.768422 IP xxxx.51970 > xxxx.2181: Flags [P.], seq 2951757025:2951757071, ack 453596850, win 356, length 46 0000 002a 0000 4b5d 0000 000c 0000 .....*..K]...... 0x0050: 001d xxxx xxxx xxxx xxxx xxxx xxxx xxxx ../xxxxxxxxxxxxx 0x0060: xxxx xxxx xxxx xxxx xxxx xxxx xxxx xx01 xxxxxxxxxxxxxxx. //距离50ms左右另外服务降级流程，是滚动降级，即启动如干新版本容器服务（目前配置25%数目），如果这些容器服务失常启动，则杀掉局部老版本容器服务；顺次类推。这也是有可能导致问题的，如果两个容器服务启动并注册到zookeeper注册核心，距离十分短？甚至小于50ms，那么后一个注册的服务，客户端就收不到该变更事件，无奈更新服务端IP。
事实证明，这一剖析是正确的，某一天在服务降级之后，的确呈现了这种场景，客户端申请的服务端局部正确，局部IP超时（上一版本容器服务的IP）。
总结
首次遇到这问题时候，感觉匪夷所思。基于现状，沉着剖析问题产生状况，一个一个去排查或者排除，切记浮躁。
抓包验证，二进制协定又不不便剖析，只能去钻研zookeeper通信协议了。最终还是须要一遍一遍Review代码，寻找蛛丝马迹，不要漠视任何可能产生的异样。
最初，Golang并发问题的确是很容易漠视，却又很容易产生，平时开发还需多留神多思考。