詭異的druid鏈接池鏈接斷開故障經驗總結

• 背景
• 癥狀
• 排查
• 修復

背景

最近在陸續做機房升級相關工作，配合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 timeout主動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 10s

1.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 方法。

作者：王清培(滬江網資深架構師)