詭異的druid鏈接池鏈接斷開故障經(jīng)驗(yàn)總結(jié)-創(chuàng)新互聯(lián)

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

背景

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

成都創(chuàng)新互聯(lián)是一家專業(yè)從事成都網(wǎng)站建設(shè)、成都網(wǎng)站制作的網(wǎng)絡(luò)公司。作為專業(yè)網(wǎng)站制作公司,成都創(chuàng)新互聯(lián)依托的技術(shù)實(shí)力、以及多年的網(wǎng)站運(yùn)營經(jīng)驗(yàn),為您提供專業(yè)的成都網(wǎng)站建設(shè)、營銷型網(wǎng)站建設(shè)及網(wǎng)站設(shè)計開發(fā)服務(wù)！

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

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

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

癥狀

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

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ù)錯誤日志初步判斷肯定是與 db 之間的鏈接已經(jīng)斷開，嘗試使用了一個已經(jīng)斷開的鏈接才會引起這個錯誤發(fā)生。但是根據(jù)我們對 druid 了解，druid 有鏈接檢查功能，按理不會拿到一個無效鏈接才對，帶著這個線索我們上路了。

排查

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

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

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

配置的每項的意思這里就不解釋了。
我們啟用了 testWhileIdle 配置，讓每次拿取鏈接的時候發(fā)起檢查。根據(jù) timeBetweenEvictionRunsMillis 的配置只有大于這個時間 druid 才會發(fā)起檢查，所以可能的場景是拿到一個即將過期的鏈接，根據(jù)這個線索我們調(diào)整這個時間為 20000ms，也就是超過 20s 會檢查當(dāng)前拿取的鏈接確定是否有效，檢查的方式應(yīng)該是使用 validationQuery 配置的 sql 語句才對，但是發(fā)現(xiàn)我們并找不到任何有關(guān)于 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 時間的，會發(fā)起 testConnectionInternal 方法檢查。我們繼續(xù)跟進(jìn)去看，

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

內(nèi)部會使用 validConnectionChecker 檢查對象發(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 來做鏈接有效性檢查。

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

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

haproxy timeout主動close上下游鏈接

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

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

為了還原產(chǎn)線的網(wǎng)絡(luò)路線，我在本地搭了一個 haproxy，了解下他的工作原理和配置，圖方便我就用了yum順手裝了一個，版本是 HA-Proxy version 1.5.18 不知道是我本地環(huán)境問題還是這個版本的 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 活動檢查一直不通過，所以無法轉(zhuǎn)發(fā)我的鏈接，搞了半天我只能手動裝了一個低版本的 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 進(jìn)行debug，調(diào)試下來也都沒有問題，也翻了下 haproxy 如何轉(zhuǎn)發(fā)鏈接的，內(nèi)部通過會話的方式保持兩個鏈接的關(guān)系，如果是 tcp 長鏈接應(yīng)該不會出現(xiàn)什么問題。haproxy 在 http 模式下有會話保持方式，tcp 應(yīng)該是直接捆綁的方式，一旦到 timeout 時間會主動 close 和 mysql 的鏈接，而且沒有出現(xiàn)篡位的問題。到這里線索又?jǐn)嗔恕?/p>

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

沒有辦法，只能試著埋點(diǎn) druid 的檢查日志，排查內(nèi)部上一次的 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，但是發(fā)到驗(yàn)證環(huán)境進(jìn)行驗(yàn)證的時候報錯了，覺得奇怪，仔細(xì)看了下原來開發(fā)環(huán)境的配置和驗(yàn)證和生產(chǎn)的不一樣，開發(fā)環(huán)境沒有走讀寫分離。

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

datasource.druid.url=jdbc:mysql:replication

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

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

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

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

修復(fù)

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

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

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

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