- 背景
- 症狀
- 排查
- 修復
背景
最近在陸續做機房升級相關工作，配合DBA對產線資料庫連結方式做個調整，將原來直接連結讀庫的地址切換到統一的讀負載均衡的代理 haproxy 上，方便機櫃和伺服器的搬遷。
切換之後線上時不時的會發生 discard connection 錯誤，導致程式報 500 錯誤，但不是每次都必現的。
開發框架: spring boot+mybatis+druid+shardingJDBC
網路架構:
appserver->mysql(master) 寫
appserver->haproxy->mysql(slave)/n 讀
第一反應肯定是因為這次的讀庫地址的變動引起的問題，覺得問題應該是 druid 連結池中的 connection 保活策略沒起作用，只要做下配置修改應該就可以了。結果這個問題讓我們排查了好幾天，我們竟然踩到了千年難遇的深坑。
這個問題排查的很坎坷，一次次的吐血，最終我們定位到問題並且優雅的修復了，我們一起來體驗下這個一次一次讓你絕望一次一次打臉的過程。
症狀
先說故障症狀，經常出現如下錯誤：
discard connection
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
The 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 方法。
作者：王清培(滬江網資深架構師)