詭異的druid鏈接池鏈接斷開故障經驗總結
背景
最近在陸續做機房升級相關工作，配合DBA對產線數據庫鏈接方式做個調整，將原來直接鏈接讀庫的地址切換到統一的讀負載均衡的代理 haproxy 上，方便機櫃和服務器的搬遷。
切換之後線上時不時的會發生 discard connection 錯誤，導致程序報 500 錯誤，但不是每次都必現的。
開發框架: spring boot+mybatis+druid+shardingJDBC
網絡架構:
appserver->mysql(master) 寫
appserver->haproxy->mysql(slave)/n 讀
第一反應肯定是因為這次的讀庫地址的變動引起的問題，覺得問題應該是 druid
這個問題排查的很坎坷，一次次的吐血，最終我們定位到問題並且優雅的修復了，我們一起來體驗下這個一次一次讓你絕望一次一次打臉的過程。
癥狀
先說故障癥狀，經常出現如下錯誤：
discard connection
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failureThe last packet successfully received from the server was 72,557 milliseconds ago. The last packet sent successfully to the server was 0 milliseconds ago.
根據錯誤日誌初步判斷肯定是與 db 之間的鏈接已經斷開，嘗試使用了一個已經斷開的鏈接才會引起這個錯誤發生。但是根據我們對 druid 了解，druid 有鏈接檢查功能，按理不會拿到一個無效鏈接才對，帶著這個線索我們上路了。
排查
為了準確的知道 db 的鏈接的存活時間，了解到 haproxy 對轉發的 db tcp 鏈接空閑時間在 1m 之內，超過 1m 不活動就會被關掉。也就說我們與 db 之間的原來的長鏈接在 1m 之內會被斷開。我們先不管這個時間設置的是否符合所有的大並發場景，至少在 druid 的鏈接池裏會有有效鏈接檢查，應該不會拿到無效鏈接才對，我們做了配置調整。
我們看下 druid
datasource.druid.validationQuery=SELECT 1
datasource.druid.validationQueryTimeout=2000
datasource.druid.testWhileIdle=true
datasource.druid.minEvictableIdleTimeMillis=100000
datasource.druid.timeBetweenEvictionRunsMillis=20000配置的每項的意思這裏就不解釋了。
我們啟用了 testWhileIdle 配置，讓每次拿取鏈接的時候發起檢查。根據 timeBetweenEvictionRunsMillis 的配置只有大於這個時間 druid 才會發起檢查，所以可能的場景是拿到一個即將過期的鏈接，根據這個線索我們調整這個時間為 20000ms，也就是超過 20s 會檢查當前拿取的鏈接確定是否有效，檢查的方式應該是使用 validationQuery 配置的 sql 語句才對，但是發現我們並找不到任何有關於 SELECT 1 的痕跡。
為什麽你死活找不到 SELECT 1
首先要搞清楚 validationQuery 為什麽沒起作用，帶著這個疑問開始 debug druid 源碼。
if (isTestWhileIdle()) {
final long currentTimeMillis = System.currentTimeMillis();
final long lastActiveTimeMillis = poolableConnection.getConnectionHolder().getLastActiveTimeMillis();
final long idleMillis = currentTimeMillis - lastActiveTimeMillis;
long timeBetweenEvictionRunsMillis = this.getTimeBetweenEvictionRunsMillis();
if (timeBetweenEvictionRunsMillis <= 0) {
timeBetweenEvictionRunsMillis = DEFAULT_TIME_BETWEEN_EVICTION_RUNS_MILLIS;
}
if (idleMillis >= timeBetweenEvictionRunsMillis) {
boolean validate = testConnectionInternal(poolableConnection.getConnection());
if (!validate) {
if (LOG.isDebugEnabled()) {
LOG.debug("skip not validate connection.");
}
discardConnection(realConnection);
continue;
}
}
}
}閑置時間肯定會有大於 timeBetweenEvictionRunsMillis 時間的，會發起 testConnectionInternal 方法檢查。我們繼續跟進去看，
protected boolean testConnectionInternal(DruidConnectionHolder holder, Connection conn) {
boolean valid = validConnectionChecker.isValidConnection(conn, validationQuery, validationQueryTimeout);
內部會使用 validConnectionChecker 檢查對象發起檢查。
public boolean isValidConnection(Connection conn, String validateQuery, int validationQueryTimeout) throws Exception {
if (conn.isClosed()) {
return false;
}
if (usePingMethod) {
if (conn instanceof DruidPooledConnection) {
conn = ((DruidPooledConnection) conn).getConnection();
}
if (conn instanceof ConnectionProxy) {
conn = ((ConnectionProxy) conn).getRawObject();
}
if (clazz.isAssignableFrom(conn.getClass())) {
if (validationQueryTimeout < 0) {
validationQueryTimeout = DEFAULT_VALIDATION_QUERY_TIMEOUT;
}
try {
ping.invoke(conn, true, validationQueryTimeout * 1000);
} catch (InvocationTargetException e) {
Throwable cause = e.getCause();
if (cause instanceof SQLException) {
throw (SQLException) cause;
}
throw e;
}
return true;
}
}
String query = validateQuery;
if (validateQuery == null || validateQuery.isEmpty()) {
query = DEFAULT_VALIDATION_QUERY;
}
Statement stmt = null;
ResultSet rs = null;
try {
stmt = conn.createStatement();
if (validationQueryTimeout > 0) {
stmt.setQueryTimeout(validationQueryTimeout);
}
rs = stmt.executeQuery(query);
return true;
} finally {
JdbcUtils.close(rs);
JdbcUtils.close(stmt);
}
}debug 這裏才發現，druid 默認采用的是 mysql.ping 來做鏈接有效性檢查。
druid 默認采用msyql.ping 協議檢查
那是不是用 msyql.ping 協議並不會讓 mysql 重新滑動 session 閑置時間，帶著這個問題打開 __information_schema.processlist__ 進程列表查看會不會刷新會話時間，通過 debug發現是會刷新時間的，說明沒有問題，這條線索算是斷了。
haproxy tiemout主動close上下遊鏈接
調整方向，開始懷疑是不是 haproxy 的一些策略導致鏈接失效，開始初步懷疑 haproxy 的輪訓轉發後端鏈接是不是有相關會話保持方式，是不是我們配置有誤導致 haproxy 的鏈接和 mysql 鏈接篡位了。
當然這個猜想有點誇張，但是沒辦法，技術人員就要有懷疑一切的態度。
為了還原產線的網絡路線，我在本地搭了一個 haproxy，了解下他的工作原理和配置，圖方便我就用了yum順手裝了一個，版本是 HA-Proxy version 1.5.18 不知道是我本地環境問題還是這個版本的 bug，我們配置的 mode tcp 活動檢查一直不生效。
listen service 127.0.0.1:60020
mode tcp
balance roundrobin
option tcplog
server server1 192.168.36.66:3306 check inter 2000 rise 2 fall 3
server server2 192.168.36.66:3306 check inter 2000 rise 2 fall 3由於 haproxy 活動檢查一直不通過，所以無法轉發我的鏈接，搞了半天我只能手動裝了一個低版本的 haproxy HA-Proxy version 1.4.14 。
完整的配置：
defaults
mode tcp
retries 3
option redispatch
option abortonclose
maxconn 32000
timeout connect 2s
timeout client 5m
timeout server 5m
listen test1
bind 0.0.0.0:60000
mode tcp
balance roundrobin
server s1 192.168.36.66:3306 weight 1 maxconn 10000 check inter 10s
server s2 192.168.36.66:3306 weight 1 maxconn 10000 check inter 10s
server s3 192.168.36.66:3306 weight 1 maxconn 10000 check inter 10s1.4 的版本順利完成活動檢查。
我使用 haproxy 進行debug，調試下來也都沒有問題，也翻了下 haproxy 如何轉發鏈接的，內部通過會話的方式保持兩個鏈接的關系，如果是 tcp 長鏈接應該不會出現什麽問題。haproxy 在 http 模式下有會話保持方式，tcp 應該是直接捆綁的方式，一旦到 timeout 時間會主動 close 和 mysql 的鏈接，而且沒有出現篡位的問題。到這裏線索又斷了。
自定義 ValidConnectionChecker 埋點日誌
沒有辦法，只能試著埋點 druid 的檢查日誌，排查內部上一次的 check和報錯之間的時間差和 connectionId 是不是一致的。
public class MySqlValidConnectionCheckerDebug extends MySqlValidConnectionChecker {
@Override
public boolean isValidConnection(Connection conn, String validateQuery, int validationQueryTimeout) {
Long connId = 0L;
try {
Field connField = ConnectionImpl.class.getDeclaredField("connectionId");
connField.setAccessible(true);
connId = (Long) connField.get(((ConnectionProxyImpl) conn).getConnectionRaw());
} catch (Exception e) {
log.error("valid connection error", e);
} finally {
log.info("valid connection ok. conn:" + connId);
}
return true;
}為了拿到 connectionId 只能反射獲取，在本地debug下沒問題，能正常拿到 connectionId，但是發到驗證環境進行驗證的時候報錯了，覺得奇怪，仔細看了下原來開發環境的配置和驗證和生產的不一樣，開發環境沒有走讀寫分離。
驗證和生產都是使用了 mysql 的 replication 的機制，所以導致我反射獲取的代碼報錯。
datasource.druid.url=jdbc:mysql:replication通過debug發現，原來 druid的 connection 是 JDBC4Connection ，變成了 ReplicationConnection ，而且裏面包裝了兩個 connection ，一個 masterconnection ，一個 slaveconnection ，似乎問題有點浮現了。
通過debug發現 druid 的檢查還是會正常走到，當走到 ReplicationConnection 內部的時候 ReplicationConnection 有一個 currentConnection ，這個鏈接是會在 masterConnection 和 slaveConnection 之間切換，切換的依據是 readOnly 參數。
在檢查的時候由於 druid 並不感知上層的參數，readOnly 也就不會設置。所以走的是 masterConnection ，但是在程序裏用的時候通過 spring 的 TransactionManager 將 readOnly 傳播到了 ShardingJDBC ， ShardingJDBC 在設置到 ReplicationConnection 上，最後導致真正在使用的時候其實使用的是 slaveConnection。
找到這個問題之後去 druid github Issues 搜索了下果然有人提過這個問題，在高版本的 druid 中已經修復這個問題了。
修復
修復這個問題有兩個方法，第一個方法，建議升級 druid，裏面已經有 MySqlReplicationValidConnectionChecker 檢查器專門用來解決這個問題。第二個方法就是自己實現 ValidConnectionChecker 檢查器，但是會有在將來出現bug的可能性。
由於時間關系文章只講了主要的排查路線，事實上我們陸續花了一周多時間，再加上周末連續趴上十幾個小時才找到這根本問題。
這個問題之所以難定位的原因主要是牽扯的東西太多，框架層面、網絡鏈接層面、mysql服務器層面，haproxy代理等等，當然其中也繞了很多彎路。。
下面分享在這個整個排查過程中的一些技術收獲。
相關技術問題
1.mysqlConenction提供了ping方法用來做活動檢查，默認MySqlValidConnectionChecker使用的是pinginternal。
ping = clazz.getMethod("pingInternal", boolean.class, int.class);2.低版本的druid不支持自定義 ValidConnectionChecker 來做個性化的檢查。
3.druid 的test方法使用註意事項，testOnBorrow 在獲取鏈接的時候進行檢查，與testWhileIdle是護持關系。
if (isTestOnBorrow()) {
} else {
if (isTestWhileIdle()) {3.kill mysql processlist 進程會話到鏈接端tcp狀態有延遲，這是tcp的四次斷開延遲。
4.haproxy 1.5.18 版本 mode tcp check不執行，健康檢查設置無效。
5.mysql replication connection master/slave切換邏輯需要註意，會不會跟上下油的鏈接池組合使用出現bug，尤其是分庫不表、讀寫分離、自定義分片。
6.排查mysql服務器的問題時，打開各種日誌，操作日誌，binlog日誌。
7.springtransactionmanagenent 事務傳播特性會影響下遊數據源的選擇，setreadonly、setautocommit。
8.低版本的 druid MySqlValidConnectionChecker 永遠執行不到 ReplicationConnection ping 方法。
作者：王清培(滬江網資深架構師)
詭異的druid鏈接池鏈接斷開故障經驗總結