4

Ok, I got a weird one here. I have a application set up that is using hibernate configured for multi tenancy and C3P0 for connection pooling.

Everthing works fine except that in my logs an exception is thrown and i cannct get to the cause of it... The weird thing is that this exception is in no way bothering my Application it is just working fine even with the exception being thrown (always 4 times and even if I do nothing but start the server and wait. After some seconds they pop up in the log and that is it)

Here is the exception and some basic config that might be useful:

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)

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>

The 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 instantiates the 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));
    }

Even if there is no direct answer available I am happy with any remark or direction that might help my investigation, so just post anything you got. Thank you in advance

Edit:

I found the error at hand for the failing initial connections it was just a misconfiguration of the dbuserpassword for the passwordproperty of the DBConnectionPool....

This solves part of the question and leaves ony the duplicate initaly which if following the discussion below the answer from @Steve Waldman is most likely just a log4j misconfiguration.

Carsten
  • 1,511
  • 2
  • 13
  • 24

1 Answers1

4

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

so, given that you observe this on server restarts, there is nothing very weird about it. while the server is down and restarting, c3p0 tries but fails to acquire database Connections. eventually (by default after ~30 seconds) c3p0 declares a failure, logs the Exception you see, and signals an error to Threads wait()ing on Connections. it sounds like your server restarts take more than ~30 seconds.

that you see this four times probably means that you have four active Connection pools, ie that there are four different dbusers active (including the default user). each c3p0 DataSource potentially manages multiple pools, one for each set of authentication credentials.

if you want to make these messages go away, just increase the time it takes for c3p0 to declare an acquisition failure. see here and acquireRetryAttempts and acquireRetryDelay. if you want to prevent occasional SQLExceptions thrown to clients during the restarts, lengthen the client timeout, checkoutTimeout, which you currently have set to 30 seconds.

a miscellaneous comment: you are using the slow default Connection test. i see you experimented with automatic test table but undid it. you might try setting a preferredTestQuery. maybe just SELECT 1 would be fine as recommended for SQL Server here. this may not matter much, as you are doing all your Connection testing asynchronously, but at least it may reduce the overhead of the tests.

good luck!

Community
  • 1
  • 1
Steve Waldman
  • 13,689
  • 1
  • 35
  • 45
  • Thank you for the comprehensive answer. This sounds logical but still posses some questions. 1.) The error occurs ~20sec after server restart (which takes around 10sec according to eclipse) so this matches with the 30sec default timeout you mentioned. But shouldn't c3p0 be able to get the connection after the 10sec? 2.) Are there any reasons you could think up why i would have four connection pools with the same dbuser open? Because this error is always for the same user. So there should only be one pool. I know that is not really visible from the snippets. But any hint will help. – Carsten May 28 '13 at 10:26
  • if you want to, you can follow along quite directly. configure the logger com.mchange.v2.resourcepool.BasicResourcePool to FINE (java.util.logging) or DEBUG (e.g. log4j). you'll see each individual failure to acquire a Connection logged, one by one. if there really is just one dbuser and four failures, you should see 120 of these failures over a two minute period before the first success. that's puzzling, if the db restart takes only 10 seconds. that's not what your c3p0 DataSource seems to be experiencing. – Steve Waldman May 28 '13 at 10:57
  • you might also try to observe in real-time with jconsole or (better) VisualVM + MBean plugin. you can see very directly how many pools you have open. – Steve Waldman May 28 '13 at 10:58
  • I just watched it fine grained and there are 4 failures for the same dbuser every second. Also I am not even restarting the DB server but simply the application server. The DB server is up and running all the time. In addition to the weird failure four pools seem to be instantiated somehow.... and now I want to know why my application behaves that way internally even if it is running just fine xD Thanks for the help and patience so far. :) – Carsten May 28 '13 at 11:19
  • do you see four distinct initialization banners? c3p0 pools, when they start up, emit a message like "Initializing c3p0 pool... com.mchange.v2.c3p0.ComboPooledDataSource" and then lots of configuration info. do you see four of those? – Steve Waldman May 28 '13 at 11:40
  • is it possible that you have more than one application sharing this config in your application server, and the appserver is instantiating one MultiTenantConnectionProviderImpl() per application? (i'm just thinking out loud here. it's not at all obvious why you should have 4 pools. you might want to log that stack traces that construct them.) – Steve Waldman May 28 '13 at 11:55
  • I am only seeing two initializations both with the exact same settings and ids. Also of the four connections failing each two are sharing the same clientConnectionId. Another thing I noticed is that in the initialization banners the user property is set but the i can't find a password property. I also tried to set the number of initial connections to one but this does not help but rather throw a Apparent Deadlock showing me that there are 3 active and one pending tasks in 3 different threads. – Carsten May 28 '13 at 11:57
  • I only have one application running there is nothing else in my development environment. Could this be caused by some configuration overlap leading to basicaly two application context being initialized as described here? hhttp://stackoverflow.com/a/16751322/2319179 – Carsten May 28 '13 at 12:01
  • in the banner, both user & password should be redacted like this: "properties -> {user=******, password=******}". the two banners both have the same value for identityToken? (compare the last few characters). that's not so good. i don't know much about SQLServer, but the doubled ClientConnectionId makes me wonder whether there aren't in fact just two pools here and log messages are somehow being duplicated (messages get sent to two appenders or something.) initialPoolSize should always be between minPoolSize and maxPoolSize, though a misconfiguration should fail gracefully (min should be used) – Steve Waldman May 28 '13 at 12:06
  • Edited the solution into my question. Thank you for your extensive help troubleshooting. I accepted your answer as it's comments are leading to the solution. – Carsten May 28 '13 at 12:17