生产程序报错

com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 5000, active 1

从报错信息来看，是数据库连接池获取连接池在规定时间内无法获取到有效连接，然后报错了。当前的druid版本为1.0.5

<dependency>
    <groupId>com.alibaba</groupId>
    <artifactId>druid</artifactId>
    <version>1.0.5</version>
</dependency>

一般来说，一个程序根据并发度需要设置一个合理的连接池大小，如果连接池最大连接数比实际需要的连接数少，以上异常是很容易出现的。所以首先看下配置的最大连接池大小。而当前项目当中最大连接数设置为60，当前程序并发度并不是很高，60个最大连接也是合理的。

如果最大连接数没有问题，一般来说，连接泄漏也有可能造成连接池中没有连接可用。啥是连接泄漏呢？就是某处获取了连接池中的连接，但是没有释放。现在直接操作JDBC的Connection的机会可能比较少了，更多的是操作第三方的ORM框架。比如以下获取一个MyBatis的会话，然后进行各种操作，再关闭会话。如下所示

SqlSession sqlSession = sqlSessionFactory.openSession();
// .... 执行业务操作
sqlSession.close();

但是在这里可能会出现一些问题，如果执行业务操作时因为异常或者其他问题导致会话没有关闭，这样这个会话就会失去关闭的机会，而会话对应的是数据库的连接，这个连接就会一直存在（而不是正常回收），导致线程泄漏。所以对于这种资源回收必须仔细考虑，一般都是按照以下处理，将会话关闭的代码放到finally代码块当中。

SqlSession sqlSession = sqlSessionFactory.openSession();
try {
   // .... 执行业务操作
} finally {
    sqlSession.close();
}

通过版本工具查看了最近上线的代码，并没有发现有导致连接泄漏的代码。另外如果是线程泄漏导致的，报错信息里面的active 1应该是active 60。当然有些博客里面分析说，这里active的值不精确，
参考博客：记druid 连接池没满,但超时问题

但是，从现场报错来说，每次报错都是1，而且我们的程序并发度不高，因为并发问题导致active的计数出错不合理。

那么从这个点出发，我们认为目前正在使用（active）的连接数为1，并没有达到最大的线程数（maxActive），有点匪夷所思，所以研究一下源码。

@Override
public DruidPooledConnection getConnection() throws SQLException {
    return getConnection(maxWait);
}

public DruidPooledConnection getConnection(long maxWaitMillis) throws SQLException {
    init();

    if (filters.size() > 0) {
        FilterChainImpl filterChain = new FilterChainImpl(this);
        return filterChain.dataSource_connect(this, maxWaitMillis);
    } else {
        return getConnectionDirect(maxWaitMillis);
    }
}

这个获取连接的地方有一个init方法用于初始化（这个方法只会执行一次），getConnectionDirect用于获取连接。
在初始化方法中注意以下两个点：

1. 根据配置参数initialSize创建连接存放到连接数组当中，比如我们程序当中设置为1，那么初始化就会往connections数组中放入一个连接，如果此时获取连接失败，会打印init datasource error日志信息。

try {
    // init connections
    for (int i = 0, size = getInitialSize(); i < size; ++i) {
        Connection conn = createPhysicalConnection();
        DruidConnectionHolder holder = new DruidConnectionHolder(this, conn);
        connections[poolingCount++] = holder;
    }

    if (poolingCount > 0) {
        poolingPeak = poolingCount;
        poolingPeakTime = System.currentTimeMillis();
    }
} catch (SQLException ex) {
    LOG.error("init datasource error", ex);
    connectError = ex;
}

2. 会创建三个线程分别用于打印日志、连接创建线程和连接销毁线程。如下所示

createAndLogThread();
createAndStartCreatorThread();
createAndStartDestroyThread();

这里只考虑创建线程的逻辑

protected void createAndStartCreatorThread() {
    String threadName = "Druid-ConnectionPool-Create-" + System.identityHashCode(this);
    createConnectionThread = new CreateConnectionThread(threadName);
    createConnectionThread.start();
}

    public void run() {
            initedLatch.countDown();

            int errorCount = 0;
            for (;;) {
                // addLast
                try {
                    lock.lockInterruptibly();
                } catch (InterruptedException e2) {
                    break;
                }

                try {
                    // 必须存在线程等待，才创建连接
                    if (poolingCount >= notEmptyWaitThreadCount) {
                        empty.await();
                    }

                    // 防止创建超过maxActive数量的连接
                    if (activeCount + poolingCount >= maxActive) {
                        empty.await();
                        continue;
                    }

                } catch (InterruptedException e) {
                    lastCreateError = e;
                    lastErrorTimeMillis = System.currentTimeMillis();
                    break;
                } finally {
                    lock.unlock();
                }

                Connection connection = null;

                try {
                    connection = createPhysicalConnection();
                } catch (SQLException e) {
                    LOG.error("create connection error", e);

                    errorCount++;

                    if (errorCount > connectionErrorRetryAttempts && timeBetweenConnectErrorMillis > 0) {
                        if (breakAfterAcquireFailure) {
                            break;
                        }

                        try {
                            Thread.sleep(timeBetweenConnectErrorMillis);
                        } catch (InterruptedException interruptEx) {
                            break;
                        }
                    }
                } catch (RuntimeException e) {
                    LOG.error("create connection error", e);
                    continue;
                } catch (Error e) {
                    LOG.error("create connection error", e);
                    break;
                }

                if (connection == null) {
                    continue;
                }

                DruidConnectionHolder holder = null;
                try {
                    holder = new DruidConnectionHolder(DruidDataSource.this, connection);
                } catch (SQLException ex) {
                    LOG.error("create connection holder error", ex);
                    break;
                }

                lock.lock();
                try {
                    connections[poolingCount++] = holder;

                    if (poolingCount > poolingPeak) {
                        poolingPeak = poolingCount;
                        poolingPeakTime = System.currentTimeMillis();
                    }

                    errorCount = 0; // reset errorCount

                    notEmpty.signal();
                    notEmptySignalCount++;
                } finally {
                    lock.unlock();
                }
            }
        }
    }

这里是一个无限循环去获取物理连接（createPhysicalConnection）的过程，开头与结尾的锁和等待逻辑这里不需要关注。主要看返回逻辑，有以下三种方式

1. 正常逻辑，获取连接，然后包装为DruidConnectionHolder
2. 获取连接失败，并不断尝试（connectionErrorRetryAttempts 默认为30次）而且timeBetweenConnectErrorMillis值大于0（默认成立），然后breakAfterAcquireFailure参数为true（默认为false），此处不成立。或者线程在等待着，被打断，此处也不成立。不过无论哪种获取连接失败的情况，会打印create connection error的异常日志
3. 创建包装类失败，此时会打印create connection holder error异常日志。
   以上两种异常都不会往connections数组中存放包装对象，也就是创建连接失败。

看过了连接创建的逻辑，再来看获取连接的逻辑，主要的逻辑在com.alibaba.druid.pool.DruidDataSource#getConnectionInternal方法当中。
获取连接的相关源码

if (maxWait > 0) {
    holder = pollLast(nanos);
} else {
    holder = takeLast();
}

一般来说，都会走到pollLast逻辑当中，

for (;;) {
     if (poolingCount == 0) {
         empty.signal(); // send signal to CreateThread create connection

         if (estimate <= 0) {
             waitNanosLocal.set(nanos - estimate);
             return null;
         }

         notEmptyWaitThreadCount++;
         if (notEmptyWaitThreadCount > notEmptyWaitThreadPeak) {
             notEmptyWaitThreadPeak = notEmptyWaitThreadCount;
         }

         try {
             long startEstimate = estimate;
             estimate = notEmpty.awaitNanos(estimate); // signal by
                                                       // recycle or
                                                       // creator
             notEmptyWaitCount++;
             notEmptyWaitNanos += (startEstimate - estimate);

             if (!enable) {
                 connectErrorCount.incrementAndGet();
                 throw new DataSourceDisableException();
             }
         } catch (InterruptedException ie) {
             notEmpty.signal(); // propagate to non-interrupted thread
             notEmptySignalCount++;
             throw ie;
         } finally {
             notEmptyWaitThreadCount--;
         }

         if (poolingCount == 0) {
             if (estimate > 0) {
                 continue;
             }

             waitNanosLocal.set(nanos - estimate);
             return null;
         }
     }

     poolingCount--;
     DruidConnectionHolder last = connections[poolingCount];
     connections[poolingCount] = null;

     return last;

这里主要涉及两种情况，

1. 池中存在连接（poolingCount不为0），会直接从池中拿走最后一个连接
2. 池中不存在连接，会通知创建连接的线程（连接创建线程上面介绍过）创建连接。然后进入等待，等待又涉及两种情况，一种是创建连接很快就好了，现场创建线程就会通知获取连接的线程然后拿到连接退出，这也是正常的，但是还有另外一种情况，连接创建使用的时间超过了最大的等待时间（nanos），此时就不会再等待了，而是返回了一个null.对应逻辑

if (estimate <= 0) {
    waitNanosLocal.set(nanos - estimate);
    return null;
}

这个可以参考博客：记一次网络波动导致druid连接池无法创建新连接的BUG

一旦这边返回了null,那么最后都会因为连接为空而进入以下代码，抛出异常

if (holder == null) {
     long waitNanos = waitNanosLocal.get();

     StringBuilder buf = new StringBuilder();
     buf.append("wait millis ")//
     .append(waitNanos / (1000 * 1000))//
     .append(", active " + activeCount)//
     ;

     List<JdbcSqlStatValue> sqlList = this.getDataSourceStat().getRuningSqlList();
     for (int i = 0; i < sqlList.size(); ++i) {
         if (i != 0) {
             buf.append('\n');
         } else {
             buf.append(", ");
         }
         JdbcSqlStatValue sql = sqlList.get(i);
         buf.append("runningSqlCount ");
         buf.append(sql.getRunningCount());
         buf.append(" : ");
         buf.append(sql.getSql());
     }

     String errorMessage = buf.toString();

     if (this.createError != null) {
         throw new GetConnectionTimeoutException(errorMessage, createError);
     } else {
         throw new GetConnectionTimeoutException(errorMessage);
     }
 }

综合报错信息和源码：不难得出一个结论，首先报错信息当中的active一直为1，恰好是初始化创建的连接个数，然后再次获取连接的时候，就进入了获取连接的过程，但是由于连接创建线程中创建线程出了超时问题（网络原因等），最后获取连接的线程等待超时，就抛出了异常。比如在创建物理连接的时候拔掉网线。

又或者在获取连接的时候在连接创建线程上打上断点卡住一段时间，获取连接的线程因为等待超时会抛出GetConnectionTimeoutException异常。


以上这两种情况都不是因为连接池满了或者连接泄漏导致的。

但是要验证以上的结论，就得有一些证明，此时能想到的就是日志。但是现场查找了日志，没有找到create connection error或者"create connection holder error"异常。经过分析发现，项目当中使用了logback日志框架，而这个版本的druid优先使用的是log4j.对应的源码参考com.alibaba.druid.support.logging.LogFactory。

static {
    // TODO add slf4j logging

    // 优先选择log4j,而非Apache Common Logging. 因为后者无法设置真实Log调用者的信息
    tryImplementation("org.apache.log4j.Logger", "com.alibaba.druid.support.logging.Log4jImpl");
    tryImplementation("org.slf4j.Logger", "com.alibaba.druid.support.logging.SLF4JImpl");
    tryImplementation("org.apache.commons.logging.LogFactory",
                      "com.alibaba.druid.support.logging.JakartaCommonsLoggingImpl");
    tryImplementation("java.util.logging.Logger", "com.alibaba.druid.support.logging.Jdk14LoggingImpl");

    if (logConstructor == null) {
        try {
            logConstructor = NoLoggingImpl.class.getConstructor(String.class);
        } catch (Exception e) {
            throw new IllegalStateException(e.getMessage(), e);
        }
    }
}

这段代码完全COPY了MyBatis的逻辑，参考 MyBatis日志模块

如果项目当中没有涉及到Log4j，也不会有问题。但是老项目中，混杂了Log4J和Logback。最后再分析了一下依赖，没有将Log4J桥接到SLF4J的依赖包。添加依赖包

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>log4j-over-slf4j</artifactId>
    <version>1.7.30</version>
</dependency>

此时就可以在日志中看到以下的日志了

2022-06-07 22:10:54,250 [Method=, URI=, IP=] [ERROR] [com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread:1651]-create connection error
java.sql.SQLRecoverableException: IO 错误: The Network Adapter could not establish the connection
	at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:489)
	at oracle.jdbc.driver.PhysicalConnection.<init>(PhysicalConnection.java:553)
	at oracle.jdbc.driver.T4CConnection.<init>(T4CConnection.java:254)
	at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:32)
	at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:528)
	at com.alibaba.druid.filter.FilterChainImpl.connection_connect(FilterChainImpl.java:148)
	at com.alibaba.druid.filter.FilterAdapter.connection_connect(FilterAdapter.java:786)
	at com.alibaba.druid.filter.FilterEventAdapter.connection_connect(FilterEventAdapter.java:38)
	at com.alibaba.druid.filter.FilterChainImpl.connection_connect(FilterChainImpl.java:142)
	at com.alibaba.druid.filter.stat.StatFilter.connection_connect(StatFilter.java:211)
	at com.alibaba.druid.filter.FilterChainImpl.connection_connect(FilterChainImpl.java:142)
	at com.alibaba.druid.pool.DruidAbstractDataSource.createPhysicalConnection(DruidAbstractDataSource.java:1360)
	at com.alibaba.druid.pool.DruidAbstractDataSource.createPhysicalConnection(DruidAbstractDataSource.java:1414)
	at com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread.run(DruidDataSource.java:1649)
Caused by: oracle.net.ns.NetException: The Network Adapter could not establish the connection