轉(zhuǎn)載:https://www.cnblogs.com/devilwind/p/6865750.html
一、問(wèn)題現(xiàn)象

• redis服務(wù)端的sentinel模塊存在大量的established狀態(tài)的連接，并且這些連接一直不被釋放，而客戶(hù)端的連接數(shù)正常。

二、問(wèn)題排查過(guò)程

1、根據(jù)連接狀態(tài)進(jìn)行推斷

• 服務(wù)端存在大量的連接的狀態(tài)為established，而客戶(hù)端連接數(shù)正常，這說(shuō)明客戶(hù)端連接是被非正常的方式關(guān)閉的，因?yàn)楦鶕?jù)TCP關(guān)閉連接的四次握手協(xié)議來(lái)看，只要客戶(hù)端正常發(fā)起了關(guān)閉動(dòng)作，服務(wù)端的狀態(tài)只可能為CLOSE_WAIT/LAST_ACK/CLOSED中的一種。
• 非正常關(guān)閉連接的情況有斷電、斷網(wǎng)后服務(wù)器重啟等等，但這些場(chǎng)景出現(xiàn)的次數(shù)較少，不會(huì)造成這么多連接，究竟是怎樣被正常關(guān)閉，到這一步還無(wú)法判斷，只能先從其它方面入手。

2、檢查業(yè)務(wù)系統(tǒng)的redis配置和程序邏輯

• 檢查redis配置，看是否有不規(guī)范的配置和不規(guī)范的使用redis的代碼，經(jīng)過(guò)排查，確定openapi有直接使用JedisSentinelPool類(lèi)，但并未在spring中配置destroy-method=”destroy”，即在停止應(yīng)用時(shí)釋放連接。
• 排查其它系統(tǒng)，未發(fā)現(xiàn)有不正常使用redis的情況，JedisSentinelPool造成的連接數(shù)增長(zhǎng)也是有限的，即只在啟動(dòng)時(shí)才創(chuàng)建sentinel連接，此處暫時(shí)排查是業(yè)務(wù)代碼使用redis不規(guī)范的問(wèn)題。

3、從網(wǎng)絡(luò)尋找線(xiàn)索

• 通過(guò)百度搜索，找不到關(guān)于sentinel的該問(wèn)題的文章。
• 查看redis、jedis、spring-data-redis官方網(wǎng)站的issues及releaseNotes，均未發(fā)現(xiàn)有提及該問(wèn)題。

4、重新思考產(chǎn)生連接的根源

• 通過(guò)閱讀jedis源碼，發(fā)現(xiàn)連接sentinel的代碼只有1處，即系統(tǒng)啟動(dòng)時(shí)會(huì)先建立一個(gè)短連接查詢(xún)sentinel的主節(jié)點(diǎn)，然后開(kāi)啟3(業(yè)務(wù)系統(tǒng)配置了3個(gè)地址)個(gè)線(xiàn)程創(chuàng)建3個(gè)長(zhǎng)連接與3個(gè)sentinel相連。短連接會(huì)立即釋放，而長(zhǎng)連接的創(chuàng)建放在循環(huán)中，問(wèn)題可能出現(xiàn)在該處，以下是源碼：

  public void run() {
        running.set(true);
        while (running.get()) {
          j = new Jedis(host, port);
          try {
            j.subscribe(new JedisPubSub() {
              @Override
              public void onMessage(String channel, String message) {
                log.fine("Sentinel " + host + ":" + port + " published: " + message + ".");
                String[] switchMasterMsg = message.split(" ");
                if (switchMasterMsg.length > 3) {
                  if (masterName.equals(switchMasterMsg[0])) {
                    initPool(toHostAndPort(Arrays.asList(switchMasterMsg[3], switchMasterMsg[4])));
                  } else {
                    log.fine("Ignoring message on +switch-master for master name "
                       + switchMasterMsg[0] + ", our master name is " + masterName);
                  }
                } else {
                  log.severe("Invalid message received on Sentinel " + host + ":" + port
                      + " on channel +switch-master: " + message);
                }
              }
            }, "+switch-master");
          } catch (JedisConnectionException e) {
            if (running.get()) {
              log.severe("Lost connection to Sentinel at " + host + ":" + port
                  + ". Sleeping 5000ms and retrying.");
              try {
                Thread.sleep(subscribeRetryWaitTimeMillis);
              } catch (InterruptedException e1) {
                e1.printStackTrace();
              }
            } else {
              log.fine("Unsubscribing from Sentinel at " + host + ":" + port);
            }
          }
        }
      }
  

正常情況下 j.subscribe會(huì)產(chǎn)生阻塞，而出現(xiàn)異常時(shí)會(huì)重新創(chuàng)建連接并且打印日志“Lost connection to Sentinel at……”

• 在業(yè)務(wù)系統(tǒng)搜索“Lost connection to Sentinel at”日志，把所有業(yè)務(wù)日志都搜索一遍，沒(méi)有找到該日志，最后終于在nohub日志中找到了(nohub日志在weblogic啟動(dòng)時(shí)會(huì)被清理，也導(dǎo)致找了幾次才找到該日志)，通過(guò)UltraEdit提取所有該內(nèi)容的日志，發(fā)現(xiàn)了28條日志，將這些日志導(dǎo)出到excel比較，發(fā)現(xiàn)日志出現(xiàn)的時(shí)間間隔均為2小時(shí)11分15秒到2小時(shí)11分20秒左右，該日志出現(xiàn)的時(shí)間間隔非常有規(guī)律，這種規(guī)律一定與該問(wèn)題存在某種聯(lián)系。

一般在系統(tǒng)中設(shè)置時(shí)間間隔都會(huì)是個(gè)整數(shù)，2小時(shí)11分15秒顯得有點(diǎn)怪異，然后將時(shí)間換算成秒，看是否為一個(gè)常用的或有規(guī)律的整數(shù)，2小時(shí)=7200秒，突然想到操作系統(tǒng)的keepalive設(shè)置中有一個(gè)7200秒，查一下操作系統(tǒng)默認(rèn)的設(shè)置，參數(shù)如下：

net.ipv4.tcp_keepalive_time = 7200 默認(rèn) tcp空閑時(shí)間

net.ipv4.tcp_keepalive_intvl =75 默認(rèn)心跳檢測(cè)時(shí)間間隔

net.ipv4.tcp_keepalive_probes = 9 默認(rèn)檢測(cè)次數(shù)

如果完成9次心跳，仍然發(fā)現(xiàn)連接無(wú)效的時(shí)間為：7200+9*75=2小時(shí)11分15秒，由此，基本上可以判斷，客戶(hù)端的連接是被操作系統(tǒng)回收的，結(jié)合前面的分析，連接被回收時(shí)并未向服務(wù)端發(fā)送關(guān)閉的報(bào)文。

• 通過(guò)在網(wǎng)絡(luò)上搜索，長(zhǎng)連接被阻斷的原因，看到了防火墻的字樣，進(jìn)一步了解，發(fā)現(xiàn)防火墻基本上都有該項(xiàng)功能，即給長(zhǎng)連接設(shè)置默認(rèn)的超時(shí)時(shí)間。

5、與運(yùn)維進(jìn)行溝通防火墻問(wèn)題

• 剛開(kāi)始問(wèn)運(yùn)行同事A時(shí)，同事A說(shuō)防火墻用的是juniper，但絕對(duì)沒(méi)有為長(zhǎng)連接設(shè)置默認(rèn)的超時(shí)時(shí)間。
• 進(jìn)一步搜索juniper的資料，確定是有默認(rèn)30分鐘的超時(shí)時(shí)間。
• 與運(yùn)維同事B溝通，確認(rèn)有默認(rèn)的超時(shí)時(shí)間。防火墻的策略是，當(dāng)建立連接時(shí)，會(huì)在防火墻保存一條會(huì)話(huà)信息，記錄了源IP、源端口、目的IP、目的端口。當(dāng)在超時(shí)時(shí)間內(nèi)，該會(huì)話(huà)代表的連接未有任何數(shù)據(jù)包時(shí)，就會(huì)清除該會(huì)話(huà)，此后若再有數(shù)據(jù)包過(guò)來(lái)，由于沒(méi)有了會(huì)話(huà)，防火墻會(huì)直接丟棄該會(huì)話(huà)。
• 要同事B將sentinel的端口26379配置一條永不超時(shí)的策略。

6、持續(xù)觀察測(cè)試環(huán)境的日志

• 發(fā)現(xiàn)在更改了防火墻超時(shí)策略后，仍然出現(xiàn)了一條“Lost connection to Sentinel at”日志，此后一直未出現(xiàn)，由此可見(jiàn)，防火墻確實(shí)對(duì)連接造成了影響。

7、初步結(jié)論

• 防火墻每30分鐘將該連接的會(huì)話(huà)信息清除，從而導(dǎo)致客戶(hù)端操作系統(tǒng)檢測(cè)到心跳失敗，隨后操作系統(tǒng)清除了客戶(hù)端連接，使得客戶(hù)端的連接數(shù)能正常釋放，由于報(bào)文被防火墻丟棄，close信息也不會(huì)到達(dá)服務(wù)端，導(dǎo)致服務(wù)端的連接未被及時(shí)關(guān)閉。

8、繼續(xù)思考服務(wù)斷連接不被釋放的問(wèn)題

• 按道理連接被防火墻阻斷后，既然客戶(hù)端的操作系統(tǒng)能正?；厥者B接，服務(wù)端應(yīng)該也可以，但服務(wù)端的keepalive機(jī)制為什么沒(méi)有發(fā)生作用？通過(guò)進(jìn)一步閱讀redis客戶(hù)端-jedis的源碼，發(fā)現(xiàn)jedis默認(rèn)開(kāi)啟了keepalive，繼續(xù)閱讀redis的源碼，發(fā)現(xiàn)redis默認(rèn)關(guān)閉了keepalive，到此所有疑問(wèn)已經(jīng)解決。

以上因素使得防火墻每30分鐘將該連接的會(huì)話(huà)信息清除，從而導(dǎo)致客戶(hù)端操作系統(tǒng)檢測(cè)到心跳失敗，隨后操作系統(tǒng)清除了客戶(hù)端連接，使得客戶(hù)端的連接數(shù)能正常釋放，隨后客戶(hù)端的jedis收到異常后重新創(chuàng)建連接，而服務(wù)端的keepalive并未執(zhí)行，以上過(guò)程不斷循環(huán)，導(dǎo)致服務(wù)端established狀態(tài)的連接不斷增加并得不到釋放。