日志中出现“Acquisition Attempt Failed”异常，对应用程序没有影响（设置：Hibernate + c3p0）

Question

好的，我这里有一个奇怪的。我有一个应用程序设置，它使用为多租户配置的休眠和用于连接池的 C3P0。

一切正常，除了在我的日志中抛出异常并且我无法找到它的原因......奇怪的是，这个异常绝不会打扰我的应用程序，即使有异常它也能正常工作被抛出（总是 4 次，即使我什么都不做，只是启动服务器并等待。几秒钟后它们会在日志中弹出，就是这样）

这里是例外和一些可能有用的基本配置：

2013-05-28 09:06:02 WARN  BasicResourcePool:1841 - com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@1d926e41 -- Acquisition Attempt Failed!!! Clearing pending acquires. While trying to acquire a needed new resource, we failed to succeed more than the maximum number of allowed acquisition attempts (30). Last acquisition attempt exception: 
com.microsoft.sqlserver.jdbc.SQLServerException: Login failed for user 'dbuser'. ClientConnectionId:07fa33fd-9de8-4235-b991-ac7e9e1ad437
    at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDatabaseError(SQLServerException.java:216)
    at com.microsoft.sqlserver.jdbc.TDSTokenHandler.onEOF(tdsparser.java:254)
    at com.microsoft.sqlserver.jdbc.TDSParser.parse(tdsparser.java:84)
    at com.microsoft.sqlserver.jdbc.SQLServerConnection.sendLogon(SQLServerConnection.java:2908)
    at com.microsoft.sqlserver.jdbc.SQLServerConnection.logon(SQLServerConnection.java:2234)
    at com.microsoft.sqlserver.jdbc.SQLServerConnection.access$000(SQLServerConnection.java:41)
    at com.microsoft.sqlserver.jdbc.SQLServerConnection$LogonCommand.doExecute(SQLServerConnection.java:2220)
    at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:5696)
    at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:1715)
    at com.microsoft.sqlserver.jdbc.SQLServerConnection.connectHelper(SQLServerConnection.java:1326)
    at com.microsoft.sqlserver.jdbc.SQLServerConnection.login(SQLServerConnection.java:991)
    at com.microsoft.sqlserver.jdbc.SQLServerConnection.connect(SQLServerConnection.java:827)
    at com.microsoft.sqlserver.jdbc.SQLServerDriver.connect(SQLServerDriver.java:1012)
    at com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:134)
    at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:182)
    at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:171)
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:137)
    at com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1014)
    at com.mchange.v2.resourcepool.BasicResourcePool.access$800(BasicResourcePool.java:32)
    at com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask.run(BasicResourcePool.java:1810)
    at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)

会话工厂：

<bean id="sessionFactory" class="org.springframework.orm.hibernate4.LocalSessionFactoryBean">
    <property name="annotatedClasses">
        <list>
            ...
        </list>
    </property>
    <property name="hibernateProperties">
        <value>
            hibernate.multiTenancy=SCHEMA
            hibernate.tenant_identifier_resolver=xxx.xxx.hibernate.CurrentTenantIdentifierResolverImpl
            hibernate.multi_tenant_connection_provider=xxx.xxx.hibernate.MultiTenantConnectionProviderImpl

            hibernate.dialect=${hibernate.dialect}
            hibernate.use_sql_comments=${hibernate.debug}
            hibernate.show_sql=${hibernate.debug}
            hibernate.format_sql=${hibernate.debug}
        </value>
    </property>
</bean>

c3p0-config.xml：

<c3p0-config> 
    <named-config name="c3p0name">  
        <property name="acquireIncrement">3</property>
        <!--property name="automaticTestTable">con_test</property--> 
        <property name="checkoutTimeout">30</property> 
        <property name="idleConnectionTestPeriod">30</property> 
        <property name="initialPoolSize">2</property> 
        <property name="maxIdleTime">18000</property> 
        <property name="maxPoolSize">30</property> 
        <property name="minPoolSize">2</property> 
        <property name="maxStatements">50</property>
        <property name="testConnectionOnCheckin">true</property>
    </named-config>
</c3p0-config>

这是实例化 ConnectionPool 的实现：

public class MultiTenantConnectionProviderImpl implements MultiTenantConnectionProvider  {


    private static final long serialVersionUID = 8074002161278796379L;

    ComboPooledDataSource cpds;

    public MultiTenantConnectionProviderImpl() throws PropertyVetoException {
        cpds = new ComboPooledDataSource("c3p0name");
        cpds.setDriverClass("jdbc.driver"));
        cpds.setJdbcUrl("jdbc.url"));
        cpds.setUser("dbuser");
        cpds.setPassword("dbuserpassword"));
    }


    @Override
    public Connection getAnyConnection() throws SQLException {
        return cpds.getConnection();
    }

    @Override
    public Connection getConnection(String dbuser) throws SQLException {
        return cpds.getConnection(dbuser, PropertyUtil.getCredential(dbuser));
    }

即使没有直接的答案，我对任何可能有助于我调查的评论或指示感到满意，所以只要发布你得到的任何东西。提前谢谢你

编辑：

我发现了初始连接失败的错误，这只是 DBConnectionPool 的密码属性的 dbuserpassword 配置错误......

这解决了部分问题，只留下了重复的 initaly，如果按照下面的讨论，@Steve Waldman 的答案很可能只是 log4j 配置错误。

Answer 1

总是 4 次，即使我什么都不做，只是启动服务器并等待。

所以，鉴于您在服务器重新启动时观察到这一点，这并没有什么奇怪的地方。当服务器关闭并重新启动时，c3p0 尝试但无法获取数据库连接。最终（默认在约 30 秒后）c3p0 声明失败，记录您看到的异常，并向连接上的线程 wait() 发出错误信号。听起来您的服务器重新启动需要超过约 30 秒。

您看到这四次可能意味着您有四个活动连接池，即有四个不同的 dbuser 处于活动状态（包括默认用户）。每个 c3p0 数据源都可能管理多个池，每个池对应一组身份验证凭据。

如果您想让这些消息消失，只需增加 c3p0 声明获取失败所需的时间。见here 和acquireRetryAttempts 和acquireRetryDelay。如果您想防止在重新启动期间偶尔向客户端抛出 SQLExceptions，请延长客户端超时 checkoutTimeout，您当前已将其设置为 30 秒。

杂项评论：您正在使用慢速默认连接测试。我看到您尝试了自动测试表，但取消了它。您可以尝试设置preferredTestQuery。对于 SQL Server here 的建议，也许只有 SELECT 1 就可以了。这可能无关紧要，因为您正在异步进行所有连接测试，但至少它可以减少测试的开销。

祝你好运！