[[258854]]

一、引子：Redis client library 連接 Redis server 超時

差不多一兩年前，在阿里云上遇到一個奇怪的 Redis 連接問題，每隔十來分鐘，服務里的 Redis client 庫就報告連接 Redis server 超時，當時花了很大功夫，發現是阿里云會斷開長時間閑置的 TCP 連接，不給兩頭發 FIN or RST 包。當時我們的 Redis server 沒有打開 tcp_keepalive 選項， Redis server 側那個連接還存在于 Linux conntrack table 里，而 Redis client 側由于連接池重用連接進行 get、set 發現連接壞掉就關閉了，所以 client 側的對應 local port 回收了。

當接下來 Redis 重用這個 local port 向 Redis server 發起連接時，由于 Redis server 側的 conntrack table 里四元組對應狀態是 ESTABLISHED，所以自然客戶端發來的 TCP SYN packet 被丟棄，Redis client 看到的現象就是連接超時。

解決這個問題很簡單，打開 Redis server 的 tcp_keepalive 選項就行。 然而當時沒想到這個問題深層次的原因影響很重大，后果很嚴重!

二、孽債：”SELECT 1” 觸發的 jdbc4.CommunicationsException

最近生產環境的 Java 服務幾乎每分鐘都報告類似下面這種錯誤：

[main] ERROR jdbc.audit - 2. Statement.execute(select 1) select 1  
 
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure 
 
The last packet successfully received from the server was 576,539 milliseconds ago.  The last packet sent successfully to the server was 5 milliseconds ago. 
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) 
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) 
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) 
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423) 
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:425) 
        at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:990) 
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3559) 
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3459) 
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3900) 
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2527) 
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2680) 
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2480) 
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2438) 
        at com.mysql.jdbc.StatementImpl.executeInternal(StatementImpl.java:845) 
        at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:745) 
        at net.sf.log4jdbc.StatementSpy.execute(StatementSpy.java:842) 
        at com.zaxxer.hikari.pool.PoolBase.isConnectionAlive(PoolBase.java:158) 
        at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:172) 
        at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:148) 
        at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:100) 
        at cn.yingmi.hikari.Main.main(Main.java:30) 
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost. 
        at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3011) 
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3469) 
        ... 14 more 

由于有之前調查 Redis 連接被阿里云異常中斷的先例，所以懷疑是類似問題，花了大量時間比對客戶端和服務端的 conntrack table，然而并沒有引子中描述的問題。

后來又去比對多個 MySQL 服務器的 sysctl 設置，研究 iptables TRACE，研究 tcpdump 抓到的報文，試驗 tw_reuse, tw_recyle 等參數，調整 Aliyun 負載均衡器后面掛載的 MySQL 服務器個數，都沒效果。

反而意外發現一個新問題，在用如下命令不經過阿里云 SLB 直接連接數據庫時，有的數據庫可以在 600s 時返回，有的則客戶端一直掛著，半個多小時了都退不出來，按 ctrl-c 中斷都不行。

mysql -h mysql-server-ip -u mysql-user -p -e 'SELECT sleep(1000)' 

當時檢查了一個正常的數據庫和一個不正常的數據庫，發現兩者的 wait_timeout 和 interactive_timeout 都是 600s，思索良苦，沒明白怎么回事，然后偶然發現另外一個數據庫的 wait_timeout=60s，卻一下子明白了原始的 “select 1” 問題怎么回事。

我們的服務使用了 Hikari JDBC 連接池，它的 idleTimeout 默認是 600s, maxLifetime 默認是 1800s，前者表示 idle JDBC connection 數量超過 minimumIdle 數目并且閑置時間超過 idleTimeout 則關閉此 idle connection，后者表示連接池里的 connection 其生存時間不能超過 maxLifetime，到點了會被關掉。

在發現 “select 1” 問題后，我們以為是這倆參數比數據庫的 wait_timeout=600s 大的緣故，所以把這兩個參數縮小了，idleTimeout=570s, maxLifetime=585s，并且設置了 minimumIdle=5。

但這兩個時間設置依然大于其中一個數據庫失誤設置的 wait_timeout=60s，所以閑置連接在 60s 后被 MySQL server 主動關閉，而 JDBC 并沒有什么事件觸發回調機制去關閉 JDBC connection，時間上也不夠 Hikari 觸發 idleTimeout 和 maxLifetime 清理邏輯，所以 Hikari 拿著這個“已經關閉”的連接，發了 “select 1” SQL 給服務器檢查連接有效性，于是觸發了上面的異常。

解決辦法很簡單，把那個錯誤配置的數據庫里 wait_timeout 從 60s 修正成 600s 就行了。

下面繼續講述 “SELECT sleep(1000)” 會掛住退不出來的問題。

三、緣起：阿里云安全組與 TCP KeepAlive

最近看了一點佛教常識，對”諸法由因緣而起“的緣起論很是感慨，在調查 “SELECT sleep(1000)” 問題中，真實感受到了“由因緣而起” 的意思😄

首先解釋下，為什么有的數據庫服務器對 “SELECT sleep(1000)” 可以返回，有的卻掛著退不出來。 其實 wait_timeout 和 interactive_timeout 兩個參數只對 “閑置” 的數據庫連接，也即沒有 SQL 正在執行的連接生效，對于 “SELECT sleep(1000)”，這是有一個正在執行的 SQL，其***執行時間受 MySQL Server 的 max_execution_time 限制，這個參數在我司一般設置為 600s，這就是 “正常的數據庫” 在 600s 時 “SELECT sleep(1000)” 中斷執行而退出了。

但不走運的是(可以說又是個失誤配置😓)，我們有的數據庫 max_execution_time 是 6000s，所以 “SELECT sleep(1000)” 在 MySQL server 服務端會在 1000s 時正常執行結束——但問題是，通過二分查找以及 tcpdump、iptables TRACE，發現阿里云會”靜默“丟棄 >=910s idle TCP connection，不給客戶端、服務端發送 FIN or RST 以強行斷掉連接。

于是 MySQL server 在 1000s 結束時發給客戶端的 ACK+PSH TCP packet 到達不了客戶端，然后再過 wait_timeout=600s，MySQL server 就斷開了這個閑置連接——可憐的是，mysql client 這個命令行程序還一無所知，它很執著的等待 MySQL server 返回，Linux 內核的 conntrack table 顯示這個連接一直是 ESTABLISHED，哪怕 MySQL server 端已經關閉對應的連接了，只是這個關閉動作的 FIN TCP packet 到不了客戶端!

下面是 iptables TRACE 日志對這個問題的實錘證明。

mysql 命令行所在機器的 iptables TRACE 日志表明，mysql client 在 23:58:25 連接上了 mysql server，開始執行 SELECT sleep(1000)，然后一直收不到服務器消息，***在 00:41:20 的時候我手動 kill 了 mysql 客戶端命令行進程，mysql 客戶端給 mysql server 發 FIN 包但收不到響應(此時 mysql server 端早關閉連接了)。

Dec 14 23:58:25 client-host kernel: [3156060.500323] TRACE: raw:OUTPUT:policy:3 IN= OUT=eth0 SRC=10.66.94.67 DST=10.31.76.36 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=43069 DF PROTO=TCP SPT=38870 DPT=3306 SEQ=2419961697 ACK=0 WINDOW=29200 RES=0x00 SYN URGP=0 OPT (020405B40402080A2F06075C0000000001030307) UID=0 GID=0  
Dec 14 23:58:25 client-host kernel: [3156060.500334] TRACE: nat:OUTPUT:rule:1 IN= OUT=eth0 SRC=10.66.94.67 DST=10.31.76.36 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=43069 DF PROTO=TCP SPT=38870 DPT=3306 SEQ=2419961697 ACK=0 WINDOW=29200 RES=0x00 SYN URGP=0 OPT (020405B40402080A2F06075C0000000001030307) UID=0 GID=0  
Dec 14 23:58:25 client-host kernel: [3156060.500419] TRACE: nat:KUBE-SERVICES:return:86 IN= OUT=eth0 SRC=10.66.94.67 DST=10.31.76.36 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=43069 DF PROTO=TCP SPT=38870 DPT=3306 SEQ=2419961697 ACK=0 WINDOW=29200 RES=0x00 SYN URGP=0 OPT (020405B40402080A2F06075C0000000001030307) UID=0 GID=0  
.... 
Dec 14 23:58:25 client-host kernel: [3156060.539844] TRACE: filter:KUBE-FIREWALL:return:2 IN=eth0 OUT= MAC=00:16:3e:12:09:f0:44:6a:2e:94:ef:00:08:00 SRC=10.31.76.36 DST=10.66.94.67 LEN=52 TOS=0x00 PREC=0x00 TTL=61 ID=9283 DF PROTO=TCP SPT=3306 DPT=38870 SEQ=2025462702 ACK=2419961951 WINDOW=235 RES=0x00 ACK URGP=0 OPT (0101080AFF6B3EAF2F06075D) UID=0 GID=0  
Dec 14 23:58:25 client-host kernel: [3156060.539849] TRACE: filter:INPUT:policy:3 IN=eth0 OUT= MAC=00:16:3e:12:09:f0:44:6a:2e:94:ef:00:08:00 SRC=10.31.76.36 DST=10.66.94.67 LEN=52 TOS=0x00 PREC=0x00 TTL=61 ID=9283 DF PROTO=TCP SPT=3306 DPT=38870 SEQ=2025462702 ACK=2419961951 WINDOW=235 RES=0x00 ACK URGP=0 OPT (0101080AFF6B3EAF2F06075D) UID=0 GID=0  
 
Dec 15 00:41:20 client-host kernel: [3158634.985792] TRACE: raw:OUTPUT:policy:3 IN= OUT=eth0 SRC=10.66.94.67 DST=10.31.76.36 LEN=52 TOS=0x00 PREC=0x00 TTL=64 ID=43075 DF PROTO=TCP SPT=38870 DPT=3306 SEQ=2419961951 ACK=2025462702 WINDOW=237 RES=0x00 ACK FIN URGP=0 OPT (0101080A2F0FD975FF6B3EAF) UID=0 GID=0  
Dec 15 00:41:20 client-host kernel: [3158634.985805] TRACE: filter:OUTPUT:rule:1 IN= OUT=eth0 SRC=10.66.94.67 DST=10.31.76.36 LEN=52 TOS=0x00 PREC=0x00 TTL=64 ID=43075 DF PROTO=TCP SPT=38870 DPT=3306 SEQ=2419961951 ACK=2025462702 WINDOW=237 RES=0x00 ACK FIN URGP=0 OPT (0101080A2F0FD975FF6B3EAF) UID=0 GID=0  
Dec 15 00:41:20 client-host kernel: [3158634.985812] TRACE: filter:KUBE-SERVICES:return:5 IN= OUT=eth0 SRC=10.66.94.67 DST=10.31.76.36 LEN=52 TOS=0x00 PREC=0x00 TTL=64 ID=43075 DF PROTO=TCP SPT=38870 DPT=3306 SEQ=2419961951 ACK=2025462702 WINDOW=237 RES=0x00 ACK FIN URGP=0 OPT (0101080A2F0FD975FF6B3EAF) UID=0 GID=0  
.... 
Dec 15 00:42:13 client-host kernel: [3158688.341777] TRACE: filter:KUBE-FIREWALL:return:2 IN= OUT=eth0 SRC=10.66.94.67 DST=10.31.76.36 LEN=52 TOS=0x00 PREC=0x00 TTL=64 ID=43084 DF PROTO=TCP SPT=38870 DPT=3306 SEQ=2419961951 ACK=2025462702 WINDOW=237 RES=0x00 ACK FIN URGP=0 OPT (0101080A2F100D90FF6B3EAF)  
Dec 15 00:42:13 client-host kernel: [3158688.341782] TRACE: filter:OUTPUT:policy:3 IN= OUT=eth0 SRC=10.66.94.67 DST=10.31.76.36 LEN=52 TOS=0x00 PREC=0x00 TTL=64 ID=43084 DF PROTO=TCP SPT=38870 DPT=3306 SEQ=2419961951 ACK=2025462702 WINDOW=237 RES=0x00 ACK FIN URGP=0 OPT (0101080A2F100D90FF6B3EAF)  

Ok，現在知道是阿里云對 >= 910s 沒有發生 TCP packet 傳輸的虛擬機之間直連閑置 TCP 連接會“靜默”丟包，那么是任意虛擬機之間嗎?是任意端口嗎?要求服務器掛到負載均衡器后面嗎?要求對應端口的并發連接到一定數目嗎?

在阿里云提交工單詢問后，沒得到什么有價值信息，在經過艱苦卓絕的試驗后——每一次試驗要等近二十分鐘啊——終于功夫不負有心人，我發現一個穩定復現問題的規律了：

1. 兩臺虛擬機分別處于不同安全組，沒有共同安全組;
2. 服務端的安全組開放端口 P 允許客戶端的安全組連接，客戶端不開放端口給服務端(按照一般有狀態防火墻的配置規則，都是只開服務端端口，不用開客戶端端口);
3. 客戶端和服務端連接上后，閑置 >= 910s，不傳輸任何數據，也不傳輸有 keep alive 用途的 ack 包;
4. 然后服務端在此長連接上發給客戶端的 TCP 包會在網絡上丟棄，到不了客戶端;
5. 但如果客戶端此時給服務端發點數據，那么會重新“激活”這條長鏈接，但此時還是單工狀態，客戶端能給服務端發包，服務端的包還到不了客戶端(大概是在服務端 OS 內核里重試中);
6. 激活后，服務端再給客戶端發數據時，之前發送不出去的數據(如果還在內核里的 TCP/IP 協議棧重試中)，加上新發的數據，會一起到達客戶端，此后這條長連接進入正常的雙工工作狀態;

下圖是用 nc 試驗的結果。

服務端

客戶端

在跟網友討論后，認識到這應該是阿里云安全組基于“集中式防火墻”實現導致的，因為集中式防火墻處于網絡中心樞紐，它要應付海量連接，因此其內存里的 conntrack table 需要比較短的 idle timeout(目前是 910s)，以把長時間沒活躍的 conntrack record 清理掉節約內存，所以上面問題的根源就清晰了：

client 連接 server，安全組(其實是防火墻)發現規則允許，于是加入一個記錄到 conntrack table;

client 和 server 到了 910s 還沒數據往來，所以安全組把 conntrack 里那條記錄去掉了;

server 在 910s 之后給 client 發數據，數據包到了安全組那里，它一看 conntrack table 里沒記錄，而 client 側安全組又不允許這個端口的包通過，所以丟包了，于是 server -> client 不通;

client 在同一個長連接上給 server 發點數據，安全組一看規則允許，于是加入 conntrack table 里;

server 重試的數據包，或者新數據包，通過安全組時，由于已經有 conntrack record 了，所以放行，于是能到達客戶端了。

原因知道了，怎么繞過這個問題呢?阿里云給了我兩個無法接受的 workaround：

把 server、client 放進同一個安全組;

修改 client 所在安全組，開放所有端口給 server 所在安全組;

再琢磨下，通過 netstat -o 發現我們的 Java 服務使用的 Jedis 庫和 mysql JDBC 庫都對 socket 文件句柄打開了 SO_KEEPALIVE 選項：

而 MySQL server 也對其打開的 socket 文件句柄打開了 SO_KEEPALIVE 選項，所以我只用修改下服務端和客戶端至少其中一側的對應 sysctl 選項即可，下面是我司服務端的默認配置，表示 TCP 連接閑置 1800s 后，每隔 30s 給對方發一個 ACK 包，最多發 3 次，如果在此期間對方回復了，則計時器重置，再等 1800s 閑置條件，如果發了 3 次后對方沒反應，那么會給對端發 RST 包同時關閉本地的 socket 文件句柄，也即關閉這條長連接。

net.ipv4.tcp_keepalive_intvl = 30 
net.ipv4.tcp_keepalive_probes = 3 
net.ipv4.tcp_keepalive_time = 1800 

由于阿里云跨安全組的 910s idle timeout 限制，所以需要把 net.ipv4.tcp_keepalive_time 設置成小于 910s，比如 300s。

默認的 tcp_keepalive_time 特別大，這也解釋了為什么當初 Redis client 設置了 SO_KEEPALIVE 選項后還是被阿里云靜默斷開。

如果某些網絡庫封裝之后沒有提供 setsockopt() 調用的機會，那么需要用 LD_PRELOAD 之類的黑科技強行設置了，只有打開了 socket 文件句柄的 SO_KEEPALIVE 選項，上面三個 sysctl 才對這個 socket 文件句柄生效，當然，代碼里可以用 setsockopt() 函數進一步設置 keep_alive_intvl 和 keepalive_probes，不用 Linux 內核的全局默認設置。

***，除了 Java 家對 SO_KEEPALIVE 處理的很好，利用 netstat -o 檢查得知，對門的 NodeJS 家，其著名 Redis client library 開了 SO_KEEPALIVE 但其著名 mysql client library 并沒有開，而 Go lang 家則嚴謹多了，兩個庫都開了 SO_KEEPALIVE。

為什么引子里說這個問題很嚴重呢?因為但凡服務端處理的慢點，比如 OLAP 場景，不經過阿里云 SLB 直連服務端在 910s 之內沒返回數據的話，就有可能沒機會返回數據給客戶端了啊，這個問題查死人有沒有! 你可能問我為啥不通過阿里云 SLB 中轉，SLB 不會靜默丟包啊——但它的 idle timeout 上限是 900s 啊!!!