Java連接配接池你用對了嗎?一次Unexpected end of stream異常的排查

能收獲什麼？

1. 更加了解TCP協定
2. Redis與用戶端關閉連接配接的機制
3. 基于Apache Common連接配接池的參數調優
4. Linux網絡抓包

情況簡介

近期遷移了部分應用到K8s中，業務開發人員回報說，會發現頻繁出現 :

redis.clients.jedis.exceptions.JedisConnectionException: Unexpected end of stream.

堆棧如下圖：

發生這個問題的應用的環境如下：

• Java8
• Jedis 2.9.0

排查

由于開發人員說近期才出現這個情況，我們首先懷疑是不是K8s環境的問題，進行了一輪K8s的網絡環境問題排查。

我們首先利用tcpdump在node節點和容器内進行抓包。

tcpdump -i <interfaceName> -C 100 -s0 -n -w node.pcap tcp           

不出意外我們确實發現了大量由Redis伺服器響應給用戶端的RST（TCP Reset）包，連接配接重置。

至此我們還是懷疑是網絡不穩定引起的。

我們搜尋了TCP RST相關内容，可以看到RST一般由下列的幾個情況引起：

• 到不存在的端口的連接配接請求
• 異常終止一個連接配接
• 檢測半打開連接配接

極客的Redis，不按規矩出牌的"RST"？

随後我們又對網絡又進行了幾輪的測試。

突然覺得有點不對勁，我們點開了RST包之前的包檢視了包的内容。

結果發現大部分是用戶端發起

quit

資料，Redis服務端傳回

ok RST

。

雖然包的狀态是

RST

，但包内容确又是跟商量好的一樣是正常的"用戶端說退出，服務端說ok"。

帶着這個問題，我們查了下Redis的相關文檔，确實在預設情況下Redis是這麼限制的，quit之後傳回一個

RST

包。

按照常理當連接配接不需要在使用的時候應該關閉連接配接，這種情況不是應該是我們了解的"TCP的4次揮手"來進行這個連接配接的告别（關閉）儀式嗎？

為什麼Redis的連接配接關閉使用"RST"？

我的猜想是 不進行繁雜的4次揮手來提升性能。

這麼做的好處是避免了4次揮手。

在網絡情況差，用戶端不穩定等情況下，能極大減少time_wait、close_wait等問題。

Redis利用了TCP機制重新限制了用戶端和服務端來進行連接配接關閉，流程如下。

• 用戶端發送 "quit"
• 服務端傳回 "ok" + RST
• 服務端直接強制關閉連接配接
• 用戶端收到 "ok" 後自己關閉這個連接配接，并自己保證後續不在使用這個連接配接進行通信

既然傳回"RST"是正常的，那麼是哪裡出了問題呢？

我們根據堆棧抛出的時間具體檢視對應的RST包後發現，這種RST的情況與上面的不一緻，這一次用戶端發送的并不是 "quit" 資料，而Redis确傳回了

RST

這時我覺得是Jedis這邊的問題，去看了Jedis的release notes和issue，發現并沒有相關的BUG。

我們重新看一下TCP流的記錄，發現這一次互動間隔了9分鐘，最後一次互動為04:10:59秒的keepalive包，而發生問題的包的時間為04:19:57，我們又把傳回

RST

可能的原因放在了"檢測半打開連接配接"這點上。

我又一次檢視了業務使用的場景，發現了JedisPool按如下情況設定：

config.setNumTestsPerEvictionRun(3);
config.setTimeBetweenEvictionRunsMillis(Duration.ofMinutes(5).toMillis());
config.setMinIdle(5);
config.setMaxTotal(20);
config.setTestOnBorrow(false);
config.setTestWhileIdle(true);           

根據上面的配置我們可知：

1. 每次最多檢測3個連接配接
2. 每隔5分鐘檢測一次
3. 最小空閑連接配接數為5
4. 最大連接配接數為20
5. 關閉擷取連接配接時檢查連接配接可用
6. 開啟空閑連接配接檢測
7. 最大連接配接空閑數為8（這邊沒有明确設定，是Pool的預設值）

帶着這些已知的情況，我們去詢問了DBA Redis的keepalive的設定。

DBA回複我們說：5分鐘

至此我們知道了原因，那就是Pool的設定和Redis的配置不比對引起的。

我們設定一個場景來推演：

1. 并發10次使用Pool操作Redis
2. 當操作完成後Pool中應該還有8個空閑連接配接（最大連接配接空閑數為8，是以這邊不是10）
3. 當5分鐘過後再次進行并發10次的Redis操作
4. 應該會出現5次

   Unexpected end of stream

   異常（5個新連接配接被建立，5個舊連接配接抛出異常）

為什麼會出現5次異常？

  因為根據Pool的設定，每5分鐘才會檢查池中的3個Redis連接配接是否正常，但當時池中有8個空閑的連接配接，也就是說還有5個連接配接在用戶端是未知狀态（8-3=5），這5個連接配接可能是可用的，也可能是不可用的，這取決于Redis的設定。

  而當下Redis設定的也是5分鐘，也就是說這8個連接配接全是不可用的，Pool根據空閑檢查機制幫我們剔除了3個，那麼還有5個連接配接是會被直接使用的，那麼就會抛出5次異常。

重制問題以驗證推演

驗證代碼如下：

JedisPoolConfig config = new JedisPoolConfig();
config.setNumTestsPerEvictionRun(3);
config.setTimeBetweenEvictionRunsMillis(Duration.ofMinutes(5).toMillis());
config.setMinIdle(5);
config.setMaxTotal(20);
config.setTestOnBorrow(false);
config.setTestWhileIdle(true);

JedisPool pool = new JedisPool(config, "x.x.x.x", 6379, 5000, "123456", 0);

List<Integer> connectionNumbers = Stream.of(0, 1, 2, 3, 4, 5, 6, 7, 8, 9).collect(Collectors.toList());

// 從池中擷取10個連接配接後并一起關閉
connectionNumbers.stream().map(i -> pool.getResource()).collect(Collectors.toList())
        .forEach(Jedis::close);

System.out.println(String.format("active: %d", pool.getNumActive()));
System.out.println(String.format("idle: %d", pool.getNumIdle()));

// 等待5分鐘 + 5秒鐘（避免剛好卡在5分鐘時間點）
Thread.sleep(Duration.ofMinutes(5).toMillis() + 5000);

System.out.println(LocalDateTime.now());
System.out.println(String.format("active: %d", pool.getNumActive()));
System.out.println(String.format("idle: %d", pool.getNumIdle()));

// 從Pool中取出10個連接配接，來進行redis操作
connectionNumbers.stream()
        .map(i -> pool.getResource())
        .collect(Collectors.toList())
        .forEach(resource -> {
            try {
                resource.get("key");
            } catch (Exception e) {
                e.printStackTrace();
            }
        });           

結果如下：

确實發生了5次

Unexpected end of stream

異常。

寫在最後

Jedis的連接配接池基于Apache Common中的連接配接池，大多數java中的連接配接池都是基于Apache。

是以該問題同樣适用于常見的JDBC連接配接池。

關于TCP

可以發現，TCP協定"一廂情願"總會出問題，更多時候得"你知我知"才能正常的使用。

TCP協定是真的很複雜的一個通信協定，不單單是三次握手4次揮手這麼簡單的内容。