詭異的druid鏈接池鏈接斷開(kāi)故障經(jīng)驗(yàn)總結(jié)

• 背景
• 癥狀
• 排查
• 修復(fù)

背景

最近在陸續(xù)做機(jī)房升級(jí)相關(guān)工作，配合DBA對(duì)產(chǎn)線(xiàn)數(shù)據(jù)庫(kù)鏈接方式做個(gè)調(diào)整，將原來(lái)直接鏈接讀庫(kù)的地址切換到統(tǒng)一的讀負(fù)載均衡的代理 haproxy 上，方便機(jī)柜和服務(wù)器的搬遷。
切換之后線(xiàn)上時(shí)不時(shí)的會(huì)發(fā)生 discard connection 錯(cuò)誤，導(dǎo)致程序報(bào) 500 錯(cuò)誤，但不是每次都必現(xiàn)的。

開(kāi)發(fā)框架: spring boot+mybatis+druid+shardingJDBC
網(wǎng)絡(luò)架構(gòu):
appserver->mysql(master) 寫(xiě)
appserver->haproxy->mysql(slave)/n 讀

第一反應(yīng)肯定是因?yàn)檫@次的讀庫(kù)地址的變動(dòng)引起的問(wèn)題，覺(jué)得問(wèn)題應(yīng)該是 druid 鏈接池中的 connection ?；畈呗詻](méi)起作用，只要做下配置修改應(yīng)該就可以了。結(jié)果這個(gè)問(wèn)題讓我們排查了好幾天，我們竟然踩到了千年難遇的深坑。

這個(gè)問(wèn)題排查的很坎坷，一次次的吐血，最終我們定位到問(wèn)題并且優(yōu)雅的修復(fù)了，我們一起來(lái)體驗(yàn)下這個(gè)一次一次讓你絕望一次一次打臉的過(guò)程。

癥狀

先說(shuō)故障癥狀，經(jīng)常出現(xiàn)如下錯(cuò)誤：

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.

根據(jù)錯(cuò)誤日志初步判斷肯定是與 db 之間的鏈接已經(jīng)斷開(kāi)，嘗試使用了一個(gè)已經(jīng)斷開(kāi)的鏈接才會(huì)引起這個(gè)錯(cuò)誤發(fā)生。但是根據(jù)我們對(duì) druid 了解，druid 有鏈接檢查功能，按理不會(huì)拿到一個(gè)無(wú)效鏈接才對(duì)，帶著這個(gè)線(xiàn)索我們上路了。

排查

為了準(zhǔn)確的知道 db 的鏈接的存活時(shí)間，了解到 haproxy 對(duì)轉(zhuǎn)發(fā)的 db tcp 鏈接空閑時(shí)間在 1m 之內(nèi)，超過(guò) 1m 不活動(dòng)就會(huì)被關(guān)掉。也就說(shuō)我們與 db 之間的原來(lái)的長(zhǎng)鏈接在 1m 之內(nèi)會(huì)被斷開(kāi)。我們先不管這個(gè)時(shí)間設(shè)置的是否符合所有的大并發(fā)場(chǎng)景，至少在 druid 的鏈接池里會(huì)有有效鏈接檢查，應(yīng)該不會(huì)拿到無(wú)效鏈接才對(duì)，我們做了配置調(diào)整。

我們看下 druid 跟鏈接時(shí)間相關(guān)的配置：

datasource.druid.validationQuery=SELECT 1
datasource.druid.validationQueryTimeout=2000
datasource.druid.testWhileIdle=true
datasource.druid.minEvictableIdleTimeMillis=100000
datasource.druid.timeBetweenEvictionRunsMillis=20000

配置的每項(xiàng)的意思這里就不解釋了。
我們啟用了 testWhileIdle 配置，讓每次拿取鏈接的時(shí)候發(fā)起檢查。根據(jù) timeBetweenEvictionRunsMillis 的配置只有大于這個(gè)時(shí)間 druid 才會(huì)發(fā)起檢查，所以可能的場(chǎng)景是拿到一個(gè)即將過(guò)期的鏈接，根據(jù)這個(gè)線(xiàn)索我們調(diào)整這個(gè)時(shí)間為 20000ms，也就是超過(guò) 20s 會(huì)檢查當(dāng)前拿取的鏈接確定是否有效，檢查的方式應(yīng)該是使用 validationQuery 配置的 sql 語(yǔ)句才對(duì)，但是發(fā)現(xiàn)我們并找不到任何有關(guān)于 SELECT 1 的痕跡。

為什么你死活找不到 SELECT 1

首先要搞清楚 validationQuery 為什么沒(méi)起作用，帶著這個(gè)疑問(wèn)開(kāi)始 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;
                        }
                    }
                }
            }

閑置時(shí)間肯定會(huì)有大于 timeBetweenEvictionRunsMillis 時(shí)間的，會(huì)發(fā)起 testConnectionInternal 方法檢查。我們繼續(xù)跟進(jìn)去看，

protected boolean testConnectionInternal(DruidConnectionHolder holder, Connection conn) {
   boolean valid = validConnectionChecker.isValidConnection(conn, validationQuery, validationQueryTimeout);

內(nèi)部會(huì)使用 validConnectionChecker 檢查對(duì)象發(fā)起檢查。

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 這里才發(fā)現(xiàn)，druid 默認(rèn)采用的是 mysql.ping 來(lái)做鏈接有效性檢查。

druid 默認(rèn)采用msyql.ping 協(xié)議檢查

那是不是用 msyql.ping 協(xié)議并不會(huì)讓 mysql 重新滑動(dòng) session 閑置時(shí)間，帶著這個(gè)問(wèn)題打開(kāi) __information_schema.processlist__ 進(jìn)程列表查看會(huì)不會(huì)刷新會(huì)話(huà)時(shí)間，通過(guò) debug發(fā)現(xiàn)是會(huì)刷新時(shí)間的，說(shuō)明沒(méi)有問(wèn)題，這條線(xiàn)索算是斷了。

haproxy timeout主動(dòng)close上下游鏈接

調(diào)整方向，開(kāi)始懷疑是不是 haproxy 的一些策略導(dǎo)致鏈接失效，開(kāi)始初步懷疑 haproxy 的輪訓(xùn)轉(zhuǎn)發(fā)后端鏈接是不是有相關(guān)會(huì)話(huà)保持方式，是不是我們配置有誤導(dǎo)致 haproxy 的鏈接和 mysql 鏈接篡位了。

當(dāng)然這個(gè)猜想有點(diǎn)夸張，但是沒(méi)辦法，技術(shù)人員就要有懷疑一切的態(tài)度。

為了還原產(chǎn)線(xiàn)的網(wǎng)絡(luò)路線(xiàn)，我在本地搭了一個(gè) haproxy，了解下他的工作原理和配置，圖方便我就用了yum順手裝了一個(gè)，版本是 HA-Proxy version 1.5.18 不知道是我本地環(huán)境問(wèn)題還是這個(gè)版本的 bug，我們配置的 mode tcp 活動(dòng)檢查一直不生效。

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 活動(dòng)檢查一直不通過(guò)，所以無(wú)法轉(zhuǎn)發(fā)我的鏈接，搞了半天我只能手動(dòng)裝了一個(gè)低版本的 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 的版本順利完成活動(dòng)檢查。
我使用 haproxy 進(jìn)行debug，調(diào)試下來(lái)也都沒(méi)有問(wèn)題，也翻了下 haproxy 如何轉(zhuǎn)發(fā)鏈接的，內(nèi)部通過(guò)會(huì)話(huà)的方式保持兩個(gè)鏈接的關(guān)系，如果是 tcp 長(zhǎng)鏈接應(yīng)該不會(huì)出現(xiàn)什么問(wèn)題。haproxy 在 http 模式下有會(huì)話(huà)保持方式，tcp 應(yīng)該是直接捆綁的方式，一旦到 timeout 時(shí)間會(huì)主動(dòng) close 和 mysql 的鏈接，而且沒(méi)有出現(xiàn)篡位的問(wèn)題。到這里線(xiàn)索又?jǐn)嗔恕?/p>

自定義 ValidConnectionChecker 埋點(diǎn)日志

沒(méi)有辦法，只能試著埋點(diǎn) druid 的檢查日志，排查內(nèi)部上一次的 check和報(bào)錯(cuò)之間的時(shí)間差和 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下沒(méi)問(wèn)題，能正常拿到 connectionId，但是發(fā)到驗(yàn)證環(huán)境進(jìn)行驗(yàn)證的時(shí)候報(bào)錯(cuò)了，覺(jué)得奇怪，仔細(xì)看了下原來(lái)開(kāi)發(fā)環(huán)境的配置和驗(yàn)證和生產(chǎn)的不一樣，開(kāi)發(fā)環(huán)境沒(méi)有走讀寫(xiě)分離。

驗(yàn)證和生產(chǎn)都是使用了 mysql 的 replication 的機(jī)制，所以導(dǎo)致我反射獲取的代碼報(bào)錯(cuò)。

datasource.druid.url=jdbc:mysql:replication

通過(guò)debug發(fā)現(xiàn)，原來(lái) druid的 connection 是 JDBC4Connection ，變成了 ReplicationConnection ，而且里面包裝了兩個(gè) connection ，一個(gè) masterconnection ，一個(gè) slaveconnection ，似乎問(wèn)題有點(diǎn)浮現(xiàn)了。

通過(guò)debug發(fā)現(xiàn) druid 的檢查還是會(huì)正常走到，當(dāng)走到 ReplicationConnection 內(nèi)部的時(shí)候 ReplicationConnection 有一個(gè) currentConnection ，這個(gè)鏈接是會(huì)在 masterConnection 和 slaveConnection 之間切換，切換的依據(jù)是 readOnly 參數(shù)。

在檢查的時(shí)候由于 druid 并不感知上層的參數(shù)，readOnly 也就不會(huì)設(shè)置。所以走的是 masterConnection ，但是在程序里用的時(shí)候通過(guò) spring 的 TransactionManager 將 readOnly 傳播到了 ShardingJDBC ， ShardingJDBC 在設(shè)置到 ReplicationConnection 上，最后導(dǎo)致真正在使用的時(shí)候其實(shí)使用的是 slaveConnection。

找到這個(gè)問(wèn)題之后去 druid github Issues 搜索了下果然有人提過(guò)這個(gè)問(wèn)題，在高版本的 druid 中已經(jīng)修復(fù)這個(gè)問(wèn)題了。

修復(fù)

修復(fù)這個(gè)問(wèn)題有兩個(gè)方法，第一個(gè)方法，建議升級(jí) druid，里面已經(jīng)有 MySqlReplicationValidConnectionChecker 檢查器專(zhuān)門(mén)用來(lái)解決這個(gè)問(wèn)題。第二個(gè)方法就是自己實(shí)現(xiàn) ValidConnectionChecker 檢查器，但是會(huì)有在將來(lái)出現(xiàn)bug的可能性。

由于時(shí)間關(guān)系文章只講了主要的排查路線(xiàn)，事實(shí)上我們陸續(xù)花了一周多時(shí)間，再加上周末連續(xù)趴上十幾個(gè)小時(shí)才找到這根本問(wèn)題。

這個(gè)問(wèn)題之所以難定位的原因主要是牽扯的東西太多，框架層面、網(wǎng)絡(luò)鏈接層面、mysql服務(wù)器層面，haproxy代理等等，當(dāng)然其中也繞了很多彎路。。

下面分享在這個(gè)整個(gè)排查過(guò)程中的一些技術(shù)收獲。

相關(guān)技術(shù)問(wèn)題

1.mysqlConenction提供了ping方法用來(lái)做活動(dòng)檢查，默認(rèn)MySqlValidConnectionChecker使用的是pinginternal。

ping = clazz.getMethod("pingInternal", boolean.class, int.class);

2.低版本的druid不支持自定義 ValidConnectionChecker 來(lái)做個(gè)性化的檢查。

3.druid 的test方法使用注意事項(xiàng)，testOnBorrow 在獲取鏈接的時(shí)候進(jìn)行檢查，與testWhileIdle是互斥關(guān)系。

if (isTestOnBorrow()) {
            } else {
                if (isTestWhileIdle()) {

3.kill mysql processlist 進(jìn)程會(huì)話(huà)到鏈接端tcp狀態(tài)有延遲，這是tcp的四次斷開(kāi)延遲。

4.haproxy 1.5.18 版本 mode tcp check不執(zhí)行，健康檢查設(shè)置無(wú)效。

5.mysql replication connection master/slave切換邏輯需要注意，會(huì)不會(huì)跟上下游的鏈接池組合使用出現(xiàn)bug，尤其是分庫(kù)不表、讀寫(xiě)分離、自定義分片。

6.排查mysql服務(wù)器的問(wèn)題時(shí)，打開(kāi)各種日志，操作日志，binlog日志。

7.springtransactionmanagenent 事務(wù)傳播特性會(huì)影響下游數(shù)據(jù)源的選擇，setreadonly、setautocommit。

8.低版本的 druid MySqlValidConnectionChecker 永遠(yuǎn)執(zhí)行不到 ReplicationConnection ping 方法。

作者：王清培(滬江網(wǎng)資深架構(gòu)師)