乐趣区

关于golang:Golang之微服务为什么发现不了

李乐

问题引入

  2020-12-25 日晚,忽然接管到大量谬误日志报警『failed to dial server: dial tcp xxxx:yy: i/o timeout』。原来是微服务客户端申请服务端,连贯失败。

  简略介绍下服务现状:咱们的服务部署在 k8s 环境,微服务框架咱们应用的是 smallnest/rpcx,注册核心基于 zookeeper,链路如下图所示:

  • 第一步:这些连贯超时的 pod(一个 pod 相当于一台虚拟机)是有什么异样吗?依据连贯超时的 IP 地址查找对应的 pod,发现没有一个 pod 是这个 IP 地址;那这个 IP 地址是从哪来的呢?难道是在某个隐秘的角落启动的?
  • 第二步:连贯注册核心,查看该服务注册的 IP 列表,发现也不存在下面超时的 IP 地址。
  • 进一步:这个异样 IP 地址,k8s 环境历史的确调配过;猜想服务端重启后,IP 地址变了,然而客户端却没有更新 IP 列表,导致还申请老的 IP 地址。

  另外,谬误日志只集中在一个 pod,即只有一个 pod 没有更新服务端的 IP 列表。初步猜想可能有两种起因:1)这个客户端与 zookeeper 之间连贯存在异样,所以 zookeeper 无奈告诉数据变更;2)服务发现框架存在代码异样,且只在某些场景触发,导致无奈更新本地 IP 列表,或者是没有 watch 数据变更。

  针对第一种猜想,很简略登录到该异样 pod,查看与 zookeeper 之间的连贯即可:

# netstat -anp | grep 2181
tcp        0      0 xxxx:51970     yyyy:2181        ESTABLISHED 9/xxxx
tcp        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 12
23:01:58.363780 IP yyyy.2181 > xxxx.51970: Flags [P.], seq 453590484:453590504, ack 2951753851, win 57, length 20
23:01:58.363814 IP xxxx.51970 > yyyy.2181: Flags [.], ack 453590504, win 356, length 0

……

  下面省略了抓包的内容局部。留神 zookeeper 点采纳二进制协定,不太不便辨认然而根本能够确信,这是 ping-pong 心跳包(定时交互,且每次数据统一)。并且,两条连贯都有失常的心跳包频繁交互。

  pod 与 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 开启抓包,服务端杀死一个 pod,剖析抓包数据如下:

//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    xxxxxxxxxxxxxxx
23: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                        xxxxxxx
23: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

  咱们的微服务框架应用的是 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 事件告诉。留神从第一步到第三步,是有耗时的,特地是服务端节点数目过多时候,屡次申请耗时必然更高,那么在这之间的数据变更客户端是感知不到的。再联合代码降级流程,是滚动降级,即启动如干新版本 pod(目前配置 25% 数目),如果这些 pod 失常启动,则杀掉局部老版本 pod;以此类推。

  如果从第一局部新版本 pod 启动,到最初一部分新版本 pod 启动以及杀掉最初一些老版本 pod,之间距离十分短呢?小于下面第一步到第三步耗时呢?这样就会导致,客户端即存在老的 IP 列表,也存在新的 IP 列表。(上一大节模仿验证时候,只是杀死一个 pod 验证数据监听机制,并没有模仿大量 pod 重启过程并剖析数据交互,因而无奈确定这类场景是否存在问题)

  持续剖析日志,发现客户端申请所有服务端的 IP 地址都是谬误的,即客户端并不存在新的 IP 地址,不合乎该场景。另外,再回首剖析下模仿验证时候抓的数据包,第一步到第三步的工夫距离是十分十分小的,毕竟服务端机器数目不多,内网拜访 zookeeper 也比拟快,而滚动公布过程个别很慢,远大于该距离。

// 第一步获取子节点列表,没有设置监听器;留神最初一个字节为 0x00,即 watch=false
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.
    
// 第一步获取子节点列表,并设置监听器;留神最初一个字节为 0x01,即 watch=true
23: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 左右 

  不过,zookeeper 监听器一次性机制还是须要关注,以防呈现数据变更无奈同步问题。

柳暗花明

  还能有什么起因呢?只能持续扒代码了,既然 rpcx 获取到了最新的 IP 列表,为什么没有更新呢?这就须要重点剖析 rpcx 数据更新逻辑了。

  如图所示,ZookeeperDiscovery 监听到服务端 IP 变更时候,将最新的 IP 列表写入 chan,rpcxClient 通过 chan 可获取最新的 IP 列表,并更新 selector(selector 提供负载平衡能力)。这个逻辑能够说是非常简单了,没有理由会出现异常。然而事实证明,异样大概率就在这块逻辑。难道是 rpcxClient 读取 chan 数据的协程有异样了?看看协程栈帧,也并没有问题。

// 客户端毕竟不止是只拜访一个微服务,所以会存在多个 rpcxClient;// 这至多阐明 ZookeeperDiscovery 监听协程与 rpcxClient 读 chan 协程数目是统一的。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: /xxxx
Access: 2020-12-24 22:06:16.000000000
Modify: 2020-12-29 23:02:14.000000000
Change: 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 main

import (
    "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 

  至此,问题根本明了。解决方案也很简略,去掉服务发现灾备逻辑即可。

总结

  首次遇到这问题时候,感觉匪夷所思。基于现状,沉着剖析问题产生状况,一个一个去排查或者排除,切记浮躁。

  抓包验证,二进制协定又不不便剖析,只能去钻研 zookeeper 通信协议了。最终还是须要一遍一遍 Review 代码,寻找蛛丝马迹,不要漠视任何可能产生的异样。

  最初,Golang 并发问题的确是很容易漠视,却又很容易产生,平时开发还需多留神多思考。

退出移动版