rabbitmq消費者「無端消失」

導讀：9月1號17:12左右，發現影子隊列存在大量「unacked」（收到了消息，可是尚未手動確認消息）的消息，一段時間後「unacked」的數量沒有減小，可是觀察消費者端的日誌，並無新消息進來，

緣由竟是。。。

 

關鍵詞：rabbitmq，Tcp Window full

問題背景：

9月1號17:12左右，收到實施人員投訴，有部分設備不能正常升級、收不到控制檯下發的指令等問題，同事查看control工程（後面簡稱control）那邊的日誌，發現control沒有收到設備上報的影子信息，因此沒有下發指令。control工程直接對接設備，根據設備上報的信息對設備下發一些指令及配置信息，包扣升級、上報日誌等，IoT上線以前control依賴心跳上報來獲取設備的當前信息，IoT上線以後依賴設備影子信息

來獲取設備的當前信息，control會訂閱設備的影子信息，但影子信息是由影子服務（簡稱IoT）轉發過去的，它不直接對接設備影子上報，具體流轉細節，請看這下面兩個圖：

應用程序（control）獲取設備狀態

應用程序（control）下發設備指令

 

得知control收不到影子消息之後，我立馬去rabbitmq的控制檯查看是否有消息，肯定兩個事：1.設備是否上報了消息 2.rabbitmq是否正常，下面圖一、圖2是當時截取的rabbitmq控制檯的兩個圖，從圖1能夠很清楚的肯定設備是有消息上報的，可是有不少消息是unacked（說明已經投遞給了消費者，只是消費者沒有ack而已，理論上等待一段時間就能正常）的，具體是哪一個隊列堆積unacked的消息請看圖2，「spacebridgeiot-shadow」正是咱們用來接收設備上報的影子信息的，消息都被堆積到隊列了因此沒有轉發到control也是合理的，觀察了一段時間發現unacked的數量變成了0，可是total的總數確沒有太大變化，給人的感受像是unacked的消息從新回到了消息隊列裏等待投遞，果真過了幾分鐘之後又發現有大量unacked的消息，過了幾分鐘之後這部分unacked的消息從新回到隊列裏，control那邊依然沒有收到消息，這時查看IoT那邊的日誌發現居然沒有影子消息進來，在rabbitmq的控制檯查看「spacebridgeiot-shadow」這個隊列下竟然沒有消費者了，如圖3所示。這時查看rabbitmq的日誌確實有錯誤信息，如圖4所示，rabbitmq主動關閉了鏈接。

圖1：rabbitmq概覽圖

 

 

圖2：rabbitmq隊列統計圖

 

 

圖3： spacebridgeiot-shadow 概覽

 

 

 圖4：rabbitmq報錯信息

 

臨時解決方案：

因爲當時已經有大量投訴過來了，因此採用了比較暴力的解決辦法「將堆積的消息刪除」，刪除之後果真正常了（ 備註：線上問題必須儘快解決，沒有時間容許咱們去分析日誌而後有條不紊的解決，必須快）。

 

經過線下環境復現問題：

1.往10.200.41.166環境的rabbitmq的隊列「mirrorTestQueue」堆積大量消息（起碼萬級）

2.停掉mirrorTestQueue的消費者，待堆積完成之後從新啓動

3.堆積完成，從新啓動消費者

 

和咱們設想的同樣，幾秒內有幾千條消息推給了消費者，持續幾分鐘之後rabbitmq主動關閉了和消費者之間的鏈接，這時從控制檯看不到隊列的消費者。因爲咱們的消費者設置了自動恢復，因此過一陣又會自動連上，

但很快又會被斷連，和咱們線上遇到的問題基本同樣，到底是什麼致使了這個問題呢？說實話當時沒有什麼思路，網上找了一圈也沒找到什麼特別滿意的答案（ 當時沒有抓到問題的本質，搜的關鍵詞太泛了），後來

咱們猜想多是TCP層面出了什麼問題，因此決定抓包試試能不能找到什麼端倪。果真，幸運的事情發生了，話很少說，直接上圖。

 

 

 13:06:25.643428以前rabbitmq還一直在給消費者推消息，直到13:06:25.643428這個時間點，開始出現消費者tcp窗口被打滿的狀況，大概持續了30秒左右，rabbitmq主動斷開了鏈接（發了一個rst包），以後消費者重連，而後窗口又繼續被打滿，又持續30秒左右繼續被斷連。

 

感受還挺有規律，每次持續30s，感受是可配置的一個參數，大概總結一下就是「tcp full window致使了服務端主動rst鏈接，並且還有規律」

此次換了一下搜索的關鍵詞找到了答案，rabbitmq有一個參數叫 tcp_listen_options.send_timeout 是來控制寫超時的一個參數，當寫超時了之後就會觸發tcp的RST( https://github.com/rabbitmq/rabbitmq-java-client/issues/341)，修改一下試試效果如何：

1. 將寫超時時間改爲10s

tcp_listen_options.send_timeout = 10000

 2.抓包看看是否起做用

 

  從窗口滿到關閉鏈接持續10s左右。

 

現象覆盤：

因爲rabbitmq的消費端沒有設置prefetch因此rabbitmq一次性給消費端投遞了過多的消息，從而致使消費端的 tcp 窗口被佔滿，進而觸發了rabbitmq 的tcp_listen_options.send_timeout，這個寫超時達到一個閾值後會觸發rabbitmq斷開消費者的tcp 鏈接。

 

終極解決方案：

        以前刪除消息只是無可奈何的方案，雖然解決了問題但太暴力，咱們須要找到一個優雅的方案來應對，既然是推給消費者的消息太多形成了tcp窗口被打滿，那咱們就應該在接收速率上下點功夫，在鏈接rabbitmq的時候告訴它別給我發太多就行。（ 後面這段話摘自https://blog.csdn.net/james_searcher/article/details/70308565）rabbitmq有一個屬性叫prefetch，prefetch是指單一消費者最多能消費的unacked messages數目。如何理解呢？mq爲每個 consumer設置一個緩衝區，大小就是prefetch。每次收到一條消息，MQ會把消息推送到緩存區中，而後再推送給客戶端。當收到一個ack消息時(consumer 發出baseack指令)，mq會從緩衝區中空出一個位置，而後加入新的消息。可是這時候若是緩衝區是滿的，MQ將進入堵塞狀態。更具體點描述，假設prefetch值設爲10，共有兩個consumer。也就是說每一個consumer每次會從queue中預抓取 10 條消息到本地緩存着等待消費。同時該channel的unacked數變爲20。而Rabbit投遞的順序是，先爲consumer1投遞滿10個message，再往consumer2投遞10個message。若是這時有新message須要投遞，先判斷channel的unacked數是否等於20，若是是則不會將消息投遞到consumer中，message繼續呆在queue中。以後其中consumer對一條消息進行ack，unacked此時等於19，Rabbit就判斷哪一個consumer的unacked少於10，就投遞到哪一個consumer中。

 

具體到代碼裏就是

 

 

如何評估這個值呢，rabbitmq官方有個文章說的很好，就不細說了，咱們的系統中目前設置的是20。

https://www.rabbitmq.com/blog/2012/05/11/some-queuing-theory-throughput-latency-and-bandwidth/

 

 

結束語：

rabbitmq的使用咱們還處於初學者階段，使用以前必定要多看rabbitmq的api，熟悉經常使用api的用法，在線下多作實驗。