[[258854]]

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

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

當(dāng)接下來 Redis 重用這個 local port 向 Redis server 發(fā)起連接時，由于 Redis server 側(cè)的 conntrack table 里四元組對應(yīng)狀態(tài)是 ESTABLISHED，所以自然客戶端發(fā)來的 TCP SYN packet 被丟棄，Redis client 看到的現(xiàn)象就是連接超時。

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

二、孽債：”SELECT 1” 觸發(fā)的 jdbc4.CommunicationsException

最近生產(chǎn)環(huán)境的 Java 服務(wù)幾乎每分鐘都報告類似下面這種錯誤：

[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 

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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，現(xiàn)在知道是阿里云對 >= 910s 沒有發(fā)生 TCP packet 傳輸?shù)奶摂M機之間直連閑置 TCP 連接會“靜默”丟包，那么是任意虛擬機之間嗎?是任意端口嗎?要求服務(wù)器掛到負(fù)載均衡器后面嗎?要求對應(yīng)端口的并發(fā)連接到一定數(shù)目嗎?

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

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

下圖是用 nc 試驗的結(jié)果。

服務(wù)端

客戶端

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

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

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

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

client 在同一個長連接上給 server 發(fā)點數(shù)據(jù)，安全組一看規(guī)則允許，于是加入 conntrack table 里;

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

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

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

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

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

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

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 設(shè)置成小于 910s，比如 300s。

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

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

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

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