寫在前面：這個分析記錄其實是在2019年做的，當時被MQ問題折騰的挺慘，好在最終在和幾個同事攻關(guān)后，問題得到解決。近期忙碌于各種材料，回頭看看自己曾經(jīng)處理過的問題，略有所感，發(fā)出來共勉
記一次OpenStack RPC斷連問題分析過程
一、 問題背景
(一) 問題表現(xiàn)
- cinder-volume日志中，出現(xiàn)RabbitMQ連接異常中斷并觸發(fā)重連的日志，
日志內(nèi)容類似IOError: Socket closed - cinder-volume日志中，出現(xiàn)reset by peer日志，error: [Errno 104] Connection reset by peer
- cinder-volume日志中，出現(xiàn)Too many heartbeat missed日志, 日志內(nèi)容類似A recoverable connection/channel error occurred, trying to reconnect: Too many heartbeats missed
- cinder-volume進程無法消費MQ消息，無法提供服務
(二) 現(xiàn)網(wǎng)日志
結(jié)合現(xiàn)網(wǎng)下載的cinder-volume日志進行分析，日志時間為1月20日 03:18:11 至 1月29日 19:55:42之間。
由于問題4未保留現(xiàn)場日志，且無現(xiàn)場狀態(tài)記錄，分析難度較大，本文檔會根據(jù)已掌握信息對問題進行推測。
二、 問題初步分析
(一) 問題1、2
針對問題1中報Errno 32, Broken pipe，此問題常見原因有以下：
當?shù)谝淮蜗蛞粋€對端已經(jīng)close的socket寫數(shù)據(jù)的時候會收到reset報文。當再次向這個socket寫數(shù)據(jù)的時候，就會拋出Broken pipe。根據(jù)TCP的約定，當收到reset包的時候，上層必須要做出處理，將socket文件描述符進行關(guān)閉，其實也意味著pipe會關(guān)閉，因此會拋出這個異常。
針對問題2中報connection reset by peer，此問題常見的原因有以下2點：
- 建立了socket連接的兩端A和B，其中一端主動關(guān)閉或因異常原因crash，但另外一段依然在發(fā)送數(shù)據(jù)，所發(fā)送的第一個數(shù)據(jù)包會引發(fā)該異常（即問題1中的reset）
- Socket一端退出，但退出時未主動關(guān)閉連接，另一端從連接中讀取數(shù)據(jù)時拋出該異常
問題1和2從原理層面分析具有相似性，均為socket連接中某一端關(guān)閉，而另一端依舊進行數(shù)據(jù)讀或?qū)憰r觸發(fā)。
OpenStack組件通過oslo-messaging庫（調(diào)用kombu）與RabbitMQ Server進行交互。在問題1和2中，RabbitMQ Server進程及cinder volume進程均正常，因此排除某一端進程crash而觸發(fā)以上報錯的場景。推測是一端因為某些原因主動關(guān)閉了連接，而對方未明確感知時觸發(fā)以上錯誤。
而從RabbitMQ自身機制及oslo.messaging連接維護機制來看，只有Heartbeat異常時，才會觸發(fā)某一端主動關(guān)閉連接。
(二) 問題3
該錯誤日志，由oslo.messaging庫暴露。觸發(fā)該問題的原因在heartbeat_check時，拋出異常，而導致發(fā)生該錯誤。
cinder volume每初始化一個rpc send類型的連接時，oslo.messaging都會啟動一個heartbeat協(xié)程，該協(xié)程周期性執(zhí)行heartbeat_check： 包括發(fā)送heartbeat消息給服務端，從服務端接收heartbeat消息等，以確保與RabbitMQ Server的連接正常。這些協(xié)程歸屬于cinder-volume主線程，由cinder-volume主線程統(tǒng)一調(diào)度運行。
oslo.messaging heartbeat_check機制，程序調(diào)用棧為：oslo.messaging:heartbeat_check ->> kombu:heartbeat_check ->> py-amqp:heartbeat_tick。heartbeat_check執(zhí)行周期為15秒（與生產(chǎn)環(huán)境配置有關(guān)），在執(zhí)行周期內(nèi)如果發(fā)現(xiàn)滿足發(fā)送heartbeat消息的條件，則會向服務端發(fā)送heartbeat；如果在規(guī)定時間內(nèi)，沒有收到服務端發(fā)的heartbeat或未消費成功，則認為heartbeat丟失。
發(fā)送heartbeat流程為：每間隔heartbeat時間發(fā)送一個heartbeat數(shù)據(jù)包，heartbeat數(shù)據(jù)包為8 byte的空數(shù)據(jù)；判斷服務端heartbeat是否正常邏輯為：如果超過兩個heartbeat周期沒有收到heartbeat數(shù)據(jù)，則會報Too many heartbeats missed錯誤。
三、 日志分析
由于生產(chǎn)環(huán)境出問題的進程為后端是ceph存儲的cinder-volume進程，因此從日志文件中過濾出ceph相關(guān)進程的日志進行分析。涉及到的進程數(shù)有3個
以報錯較多的22998子進程為例來進行分析。
(一) Too many heartbeats missed
從日志開始有大量“A recoverable connection/channel error occurred, trying to reconnect: Too many heartbeats missed”報錯，比較有規(guī)律，基本間隔在15s執(zhí)行一次，每次涉及到27行此類日志。日志內(nèi)容如下：
由于每個connection在進行heartbeat，會按照配置指定時間(算法為：heartbeat_timeout_threshold/rate/2 = 15秒)休眠。在相同時間點內(nèi)，共有27行此類日志，因此可以確定共有27個connection正在進行heartbeat_check，且heartbeat失敗。說明已經(jīng)超過heartbeat超時時間沒有接收到或處理服務端heartbeat信息。造成該問題發(fā)生的主要原因有兩方面： 一為RabbitMQ server壓力較大，未能及時發(fā)送heartbeat消息。不過從生產(chǎn)環(huán)境運行情況來看，RabbitMQ server運行良好，發(fā)生這種情況的可能性不大，除非RabbitMQ本身存在缺陷，這個有待于進一步分析。二是cinder-volume未及時處理heartbeat消息。分析py-amqp的源碼可知，cinder-volume與RabbitMQ server的每個connection，py-amqp都會為其維護一個讀計數(shù)器。當從queue中讀取到新的數(shù)據(jù)幀時，則計數(shù)器加1。heartbeat_tick在處理時，如果發(fā)現(xiàn)計數(shù)器計數(shù)發(fā)生了變化，則認為從server端正常接收到了heartbeat消息；反之則認為沒有收到消息。因此，造成未及時處理或讀取heartbeat消息的關(guān)鍵在于，觸發(fā)計數(shù)器值發(fā)生變化的read_frame邏輯沒有執(zhí)行成功。
由以上代碼段可以看出，在執(zhí)行read_frame時報異常，會導致循環(huán)退出，從而造成bytes_recv計數(shù)器不增加。
read_frame邏輯如下：
正常情況下，在出現(xiàn)上述報錯后，oslo.messaging會進行ensure_connection操作，以保證連接恢復，并在恢復成功后打印“Reconnected to AMQP server on xx”日志。但從生產(chǎn)環(huán)境日志來看，在出現(xiàn)大量heartbeats missed日志后，在較長時間內(nèi)沒有reconnect成功，因此導致了周期性刷heartbeat missed日志。
(二) Broken pipe
以上有規(guī)律的日志，從日志開始一直持續(xù)到09:51分，發(fā)生了如下錯誤：
結(jié)合日志及cinder-volume處理邏輯，可以分析出此處收到了刪除volume的請求，在刪除成且更新完數(shù)據(jù)庫后，會有notify消息通知卷刪除事件，需要發(fā)送rpc消息，正好發(fā)現(xiàn)連接已經(jīng)處于不可用狀態(tài)，因此報了截圖錯誤。oslo.messaging自身具備自愈機制，會在發(fā)生以上錯誤時，觸發(fā)重連。并在1秒重連成功后重新發(fā)送消息。
因此，在發(fā)生heartbeat missed的事件時，由于oslo.messaging自身具備重試機制，一般情況下不會影響cinder-volume的正常運行。
在之后的日志中，可以觀察到，打印“A recoverable connection/channel error occurred, trying to reconnect: Too many heartbeats missed”的日志連接變?yōu)?6個。代碼邏輯與日志表現(xiàn)一致。
觀察后續(xù)日志，在09:56:50時，也觸發(fā)了2個Socket closed錯誤，并且觸發(fā)2條重連成功的日志。在此后，heartbeat missed的日志連接數(shù)變?yōu)?4個。截止10:02:17，共發(fā)生4次錯誤及重連，因此剩余23個異常連接。
(三) Connection reset by peer
在00:08:07--00:10:01中間，沒有任何日志打印，說明heartbeat_check沒有正常進行，因為如正常進行時，異常連接的heartbeat_check會繼續(xù)打印heartbeat missed日志。結(jié)合RabbitMQ Heartbeat原理[見附1]來看，客戶端超過2個周期沒有發(fā)送heartbeat消息，會導致connection被服務端close或reset掉。結(jié)合cinder-volume運行原理[見附2]及協(xié)程機制，推測此時可能存在非協(xié)程友好類且耗時較長的業(yè)務邏輯正在處理，導致heartbeat協(xié)程無法獲取到執(zhí)行權(quán)而超時，客戶端無法發(fā)送heartbeat消息給服務端（如前序描述，heartbeat_check邏輯中包含了客戶端向服務端發(fā)送heartbeat消息，也包含判斷服務端向客戶端發(fā)送的heartbeat消息），從而導致服務端主動reset了連接。因此在協(xié)程獲得執(zhí)行權(quán)后報了reset by peer日志。
reset之后，后續(xù)的too many heartbeat missed日志條數(shù)，恢復到了27條，說明在heartbeat超時而導致heatbeat reset后，27個connection又重新恢復到了無法接收或處理服務端heartbeat消息的狀態(tài)。因此推測“Too many heartbeat missed”與connection reset有一定關(guān)系。
四、 解決方法
（一）初步結(jié)論
問題1：與問題3有關(guān)，當向一個狀態(tài)不正常的connection里面寫入數(shù)據(jù)時，會報socket closed。
問題2：與python協(xié)程調(diào)度機制有關(guān)，處理非協(xié)程友好、且耗時較長的邏輯，導致其他包括heartbeat在內(nèi)的協(xié)程無法被調(diào)度。
問題3：oslo.messaging ensure_connection存在bug，導致無法ensure成功。
（二）測試驗證
問題 1：問題3解決后，不會向斷連的connection中發(fā)送數(shù)據(jù)，因此不會報問題1。
問題 2：通過編寫demo程序來嘗試觸發(fā)該錯誤。實現(xiàn)思路為在cinder-volume周期性任務重，添加一個超過200秒（大于3個heartbeat超時周期）的計算型任務，此時cinder-volume其他業(yè)務邏輯處理被阻塞。同時，達到heartbeat超時時間后，rabbitmq-server主動關(guān)閉連接。當周期性任務運行結(jié)束后，重新使用前期所建立的connection時，報問題1或2。
問題3：通過在測試環(huán)境加壓，會出現(xiàn)大量heartbeat missed報錯，合并修復ensure connection的bug后問題解決。
（三）解決思路
問題1、3：通過代碼修復
問題2：生產(chǎn)環(huán)境中不可避免會出現(xiàn)耗時較長的非協(xié)程友好任務，基于oslo.messaging自身較為完備的自愈機制，在重新獲取執(zhí)行權(quán)后可恢復連接（基于問題1、3的代碼修復）。
五、 遺留問題
問題4:未保留現(xiàn)場日志及錯誤狀態(tài)，推測與協(xié)程任務阻塞主線程有關(guān)，待再次遇到此問題時，保留一段時間現(xiàn)場及日志供分析。
附1 RabbitMQ Heartbeat機制
在理解RabbitMQ之前，先簡單說下TCP的KeepAlive機制，與RabbitMQ的Heartbeat機制有異曲同工之妙。
(一) TCP KeepAlive
TCP Keepalive為確保連接對端存活狀態(tài)的一種方法。當客戶端等待（空閑）超過一定時間后，自動給服務端發(fā)送一個空報文，如果對方回復，則說明連接存活；如果對方?jīng)]有報文，且多次嘗試結(jié)果一樣，那么可認為此連接已丟失，客戶端沒有必要繼續(xù)保持連接，后續(xù)也不再使用此連接。
- KeepAlive默認情況下是關(guān)閉的，可被上層應用關(guān)閉和打開（設置SO_KEEPALIVE）
- Tcp_keepalive_time：KeepAlive的空閑時長，也可以理解為心跳周期
- Tcp_keepalive_intvl: KeepAlive探測包的發(fā)送間隔
- Tcp_keepalive_probes: 在tcp_keepalive_time之后，未收到對端確認，繼續(xù)發(fā)送探測包的次數(shù)
在使用linux內(nèi)核時，可以通過以下參數(shù)，對tcp keepalive進行配置：
Linux 7.2默認配置分別為1，5, 5
Linux 7.3 默認配置分比為3, 8, 30
注：TCP KeepAlive和HTTP協(xié)議的Keep-Alive不一樣，前者在于心跳、錯誤檢測等；后者在于連接復用
(二) RabbitMQ Heartbeat
- RabbitMQ基于AMQP協(xié)議實現(xiàn)，AMQP在0.9.1版本提供了heartbeat機制。該機制主要是確保應用層能夠及時發(fā)現(xiàn)中斷的連接或者完全沒有響應的對等點，還可以防止某些網(wǎng)絡設備在一定時間內(nèi)沒有活動時終止空閑的TCP連接。
- 心跳超時值定義了RabbitMQ的兩端認為對等TCP連接在多長時間無傳輸之后需要發(fā)送心跳包，目前最新版本的默認值是60s，之前是580s，再前面的版本是600s。
- 系統(tǒng)的心跳超時值由客戶端和服務端共同商定：
(1) 如果都不設置，那就定為默認值
(2) 當兩個值都不為0時，將使用請求值的較低值
(3) 如果一方使用零值(試圖禁用心跳)，而另一方不使用，則使用非零值。
(4) 如果時間間隔配置為0，則表示不啟用heartbeat檢測
(5) 將心跳超時值設置得太小可能會導致由于臨時網(wǎng)絡擁塞、短暫的服務器流控制等原因?qū)е碌恼`判，認為對端不可用。 - 任何流量交互（例如協(xié)議操作、發(fā)布的消息、確認)都可以算作有效的心跳。根據(jù)客戶端的不同，可以選擇發(fā)送心跳包，而不管連接上是否有其他流量，也可以只在必要時發(fā)送心跳包。
- 在進行了兩次心跳檢測都沒有回應后，對端就被認為是不可聯(lián)系的，此時，TCP連接將被關(guān)閉。
- 要想讓heartbeat機制失效，有兩個方式：
(1) 將時間間隔配置為0，表示不啟動heartbeat檢測
(2) 將超時值設置得足夠大
(3) 不推薦在實際環(huán)境中使用這兩種配置方式，除非環(huán)境中使用了TCP KeepAlive
一些網(wǎng)絡工具(如HAproxy, AWS ELB)和設備(硬件負載均衡器)可能在一段時間內(nèi)沒有活動時終止環(huán)境中空閑的TCP連接。而當在連接上啟用心跳檢測時，它會導致周期性的輕網(wǎng)絡流量。因此，心跳檢測有一個副作用，就是保護客戶機連接，防止代理和負載均衡器提前關(guān)閉這些連接，這些連接可能在一段時間內(nèi)處于空閑狀態(tài)。
關(guān)于為什么不采用TCP KeepAlive而是重新開發(fā)heartbeat機制---TCP KeepAlive在不同內(nèi)核或操作系統(tǒng)版本中的配置方式不一致，對應用層不友好，因此存在了heartbeat機制。
附2 cinder volume進程運行原理
cinder volume在啟動時，首先會有一個父進程，然后針對每種后端存儲啟動一個子進程，每個子進程包含一個MainThread。MainThread中又包含了大量的_GreenThread（協(xié)程）。采用協(xié)程可大大提升程序處理效率，對disk io、網(wǎng)絡密集型任務的提升尤其明顯（處理python友好的io等請求時會讓出cpu執(zhí)行權(quán)，其他獲取到cpu執(zhí)行權(quán)的協(xié)程繼續(xù)執(zhí)行）；但對CPU密集型任務，與順序處理無區(qū)別。
周期性任務：cinder volume中啟動的周期性任務periodic task,如果有多個，會按照順序執(zhí)行。當某一個周期性任務，長時間運行，不釋放CPU執(zhí)行權(quán)時，其他周期性任務的運行要進行等待，直到前序周期性任務釋放CPU執(zhí)行權(quán)。
RPC Client：cinder volume在啟動時，rpcserver會一并啟動。RPC server初始化設定使用協(xié)程的消息處理方式。
在cinder volume作為消費者時，會監(jiān)聽自己的queue，當有RPC請求到來時，使用協(xié)程來處理RPC請求。
cinder-volume通過rpc.call或rpc.cast來與其他組件進行交互，而每當調(diào)用rpc.call或cast時，其背后的原理為通過oslo.messaging的連接池機制拿到一個可用連接，并進行后續(xù)的消息發(fā)送。如果連接池中的連接不夠用時，則會新聲明一個連接供其調(diào)用，直到連接數(shù)到達節(jié)點配置的上限（一般為30個）。達到上限后，后續(xù)的連接會排隊等待。
