"Error while trying to acquire" exception in logs that do not affect the application (Setup: Hibernate + c3p0)

Question

OK, I have a weird one here. I have installed an application that uses sleep mode, configured for multiple leases and C3P0 for pooling.

Everthing works fine, except that an exception is thrown in my logs, and I can understand the reason for this ... It is strange that this exception does not bother my application in any way, it just works fine even with an exception (always 4 times and even if I’m doing nothing but starting the server and waiting. After a few seconds they will appear in the log, and that’s all)

Here is an example and some basic configurations that might be useful:

2013-05-28 09:06:02 WARN BasicResourcePool:1841 - com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask@1d926e 41 -- 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) 

SessionFactory:

 <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> 

Here is the implementation that creates the ConnectionPool instance:

 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)); } 

Even if there is no direct answer, I am pleased with any comment or guidance that could help my investigation, so just post whatever you have. Thank you in advance

Edit:

I found an error at hand for failed initial connections, it was just the wrong dbuserwordword configuration for the DBConnectionPool password property ....

This solves part of the question and leaves only a duplicate of initaly, which if, after discussion below, the answer from @Steve Waldman is most likely the wrong configuration of log4j.

Answer 1

always 4 times and even if I do nothing but start the server and wait.

therefore, given that you are observing this at a server restart, there is nothing strange about this. while the server is down and rebooting, c3p0 tries, but does not get a database connection. ultimately (by default after ~ 30 seconds) c3p0 declares a failure, logs the exception you see, and signals an error for Threads wait () in Connections. It looks like rebooting your server takes more than 30 seconds.

what you see this four times probably means that you have four active connection pools, i.e. There are four different dbusers (including the default user). each c3p0 DataSource potentially manages multiple pools, one for each set of credentials.

if you want these messages to go away, just increase the time it takes for c3p0 to announce the acquisition failure. see here and acquireRetryAttempts and acquireRetryDelay . if you want to prevent random SQLExceptions thrown to clients during a restart, lengthen the client's wait time, checkoutTimeout , which you currently set to 30 seconds.

Comment: You are using the slow connection test by default. I see that you experimented with an automatic test pattern, but unzipped it. you can try installing preferredTestQuery . maybe only SELECT 1 will be fine, as recommended for SQL Server here . this may not matter much since you run all of your connection tests asynchronously, but at least it can reduce the overhead of the tests.

Good luck