Golang之微服務爲何發現不了
李樂git
問題引入
2020-12-25日晚，忽然接收到少許錯誤日誌報警『failed to dial server: dial tcp xxxx:yy: i/o timeout』。原來是微服務客戶端請求服務端，鏈接失敗。github
簡單介紹下服務現狀：咱們的服務部署在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數據變動。app
針對第一種猜想，很簡單登陸到該異常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心跳包（定時交互，且每次數據一致）。而且，兩條鏈接都有正常的心跳包頻繁交互。tcp
pod與zookeeper之間鏈接正常，那麼極可能就是服務發現框架的代碼問題了。微服務
模擬驗證
經過上面的分析，可能的緣由是：服務發現框架存在代碼異常，且只在某些場景觸發，致使沒法更新本地IP列表，或者是沒有watch數據變動。spa
客戶端有沒有watch數據變動，這一點很是容易驗證；只須要重啓一臺服務，客戶端tcpdump抓包就行。只不過zookeeper點採用二進制協議，很差分析數據包內容。3d
簡單介紹下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併發問題確實是很容易忽視，卻又很容易產生，平時開發還需多注意多思考。
公衆號
該系列文章會同步到如下公衆號
- 1. 微服務之Eureka服務發現
- 2. 微服務之服務註冊發現
- 3. 何爲微服務？
- 4. 十萬個爲何之SOA服務,服務治理,微服務
- 5. 爲何發不了
- 6. golang 實現一個restful微服務
- 7. 永不失聯！如何實現微服務架構中的服務發現？
- 8. 爲何要微服務化
- 9. 爲何會用微服務？？？
- 10. 爲何使用微服務？
- 更多相關文章...
- • 啓動MySQL服務 - MySQL教程
- • Git 服務器搭建 - Git 教程
- • Spring Cloud 微服務實戰(三) - 服務註冊與發現
- • 爲了進字節跳動，我精選了29道Java經典算法題，帶詳細講解
-
每一个你不满意的现在，都有一个你没有努力的曾经。
- 1. 微服務之Eureka服務發現
- 2. 微服務之服務註冊發現
- 3. 何爲微服務？
- 4. 十萬個爲何之SOA服務,服務治理,微服務
- 5. 爲何發不了
- 6. golang 實現一個restful微服務
- 7. 永不失聯！如何實現微服務架構中的服務發現？
- 8. 爲何要微服務化
- 9. 爲何會用微服務？？？
- 10. 爲何使用微服務？