| Re: [jetty-users] Strange connection pool behavior in Jetty 7.5.4 |
On 11/18/2011 04:19 AM, Daniel Murnane wrote:
Did you find a solution for this old problem? I'm seeing something similar with C3P0, except the properties appear in groups rather than one by one. Long story short, I've switched back to DBCP and given up on C3P0. I'm not clear which is better to use, but at least DBCP works. I'm deploying with an embedded 7.6.4 with a WEB-INF/jetty-env.xml like this: <?xml version="1.0" encoding="ISO-8859-1"?> <!DOCTYPE Configure PUBLIC "-//Mort Bay Consulting//DTD Configure//EN" "http://www.eclipse.org/jetty/configure.dtd"> <Configure id="wac" class="org.eclipse.jetty.webapp.WebAppContext"> <New id="my-pool" class="org.eclipse.jetty.plus.jndi.Resource"> <Arg><Ref id="wac" /></Arg> <Arg>jdbc/my-pool</Arg> <Arg> <New class="com.mchange.v2.c3p0.ComboPooledDataSource"> <Set name="description">Foo Bar</Set> <Set name="driverClass">org.gjt.mm.mysql.Driver</Set> <Set name="jdbcUrl">jdbc:mysql://localhost/mydb</Set> <Set name="user">myuser</Set> <Set name="password">mypass<Set> </New> </Arg> </New> </Configure> This is being run from an embedded Jetty Main, where I pull in the Plus configuration classes by name in a webApp.setConfigurationClasses( .. ) call and point Jetty at the WEB-INF folder via webApp.setBaseResource(..). I have seen this same configuration work when compiled into a war and deployed as a traditional webapp and run with "java -jar start.jar". As you describe, the first time the pool tries to initialise, various important properties are null: ===== [java] INFO: jetty-7.6.4.v20120524 [java] 20120625.140729.734 INFO MLog - MLog clients using log4j logging. [java] 20120625.140729.783 INFO C3P0Registry - Initializing c3p0-0.9.1 [built 16-January-2007 14:46:42; debug? true; trace: 10] [java] 20120625.140729.816 DEBUG DynamicPooledDataSourceManagerMBean - MBean: com.mchange.v2.c3p0:type=PooledDataSource[z8kflt8o9k9z6e1gsygqc|6a4cae18] registered. [java] 20120625.140729.822 WARN C3P0Config - named-config with name 'false' does not exist. Using default-config. [java] 20120625.140729.887 DEBUG BasicResourcePool - incremented pending_acquires: 1 [java] 20120625.140729.887 DEBUG BasicResourcePool - incremented pending_acquires: 2 [java] 20120625.140729.887 DEBUG BasicResourcePool - incremented pending_acquires: 3 [java] 20120625.140729.887 DEBUG BasicResourcePool - com.mchange.v2.resourcepool.BasicResourcePool@23aba7b0 config: [start -> 3; min -> 3; max -> 15; inc -> 3; num_acq_attempts -> 30; acq_attempt_delay -> 1000; check_idle_resources_delay -> 0; mox_resource_age -> 0; max_idle_time -> 0; excess_max_idle_time -> 0; destroy_unreturned_resc_time -> 0; expiration_enforcement_delay -> 0; break_on_acquisition_failure -> false; debug_store_checkout_exceptions -> false] [java] 20120625.140729.910 INFO AbstractPoolBackedDataSource - Initializing c3p0 pool... com.mchange.v2.c3p0.ComboPooledDataSource [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, dataSourceName -> false, debugUnreturnedConnectionStackTraces -> false, description -> null, driverClass -> null, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> z8kflt8o9k9z6e1gsygqc|6a4cae18, idleConnectionTestPeriod -> 0, initialPoolSize -> 3, jdbcUrl -> null, lastAcquisitionFailureDefaultUser -> null, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 0, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 15, maxStatements -> 0, maxStatementsPerConnection -> 0, minPoolSize -> 3, numHelperThreads -> 3, numThreadsAwaitingCheckoutDefaultUser -> 0, preferredTestQuery -> null, properties -> {}, propertyCycle -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false ] [java] 20120625.140729.910 DEBUG BasicResourcePool - An exception occurred while acquiring a poolable resource. Will retry. [java] java.lang.NullPointerException [java] at sun.jdbc.odbc.JdbcOdbcDriver.getProtocol(JdbcOdbcDriver.java:524) [java] at sun.jdbc.odbc.JdbcOdbcDriver.knownURL(JdbcOdbcDriver.java:493) [java] at sun.jdbc.odbc.JdbcOdbcDriver.acceptsURL(JdbcOdbcDriver.java:307) [java] at java.sql.DriverManager.getDriver(DriverManager.java:273) ===== Because driverUrl is null, the attempt to call DriverManager.getDriver ends up throwing a NullPointerException. I don't see how the creation of the ComboPooledDataSource defined in jetty-env.xml could have "half completed", to the point where something is trying to instantiate a database connection via c3p0 yet the configuration parameters haven't yet been applied to the c3p0 data source. Surely the way Jetty sets it up from the XML configuration is atomic, i.e. nothing can use the data source until the XML configuration has finished configuring it? There is nothing else in my project that refers to c3p0 except jetty-env.xml. I have used a manual DBCP connection provider before now, this is the first time I've tried to use JNDI and c3p0. I have removed from hibernate.cfg.xml any database configuraiton such as the c3p0 directives that might cause it to try to initialise c3p0 in any way, so I don't think it's trying to create c3p0 objects in parallel, or conflicting, with the JNDI configuration. I did try fetching the c3p0 source and debugging via NetBeans Further down the log, I see another attempt to initialize c3p0. This time, 'description', 'driverClass' and 'driverUrl' have been filled in .. however, the username and password have not. Just below _that_, there is yet another dump of the properties, with the username apparently filled in ('*****') but no password ('using password: NO'). ===== [java] 20120625.140729.969 INFO AbstractPoolBackedDataSource - Initializing c3p0 pool... com.mchange.v2.c3p0.ComboPooledDataSource [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, dataSourceName -> false, debugUnreturnedConnectionStackTraces -> false, description -> Foo Bar, driverClass -> org.gjt.mm.mysql.Driver, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> z8kflt8o9k9z6e1gsygqc|6a4cae18, idleConnectionTestPeriod -> 0, initialPoolSize -> 3, jdbcUrl -> jdbc:mysql://localhost/mydb, lastAcquisitionFailureDefaultUser -> null, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 0, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 15, maxStatements -> 0, maxStatementsPerConnection -> 0, minPoolSize -> 3, numHelperThreads -> 3, numThreadsAwaitingCheckoutDefaultUser -> 0, preferredTestQuery -> null, properties -> {}, propertyCycle -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false ] [java] 20120625.140730.010 DEBUG BasicResourcePool - incremented pending_acquires: 1 [java] 20120625.140730.010 DEBUG BasicResourcePool - incremented pending_acquires: 2 [java] 20120625.140730.010 DEBUG BasicResourcePool - incremented pending_acquires: 3 [java] 20120625.140730.010 DEBUG BasicResourcePool - com.mchange.v2.resourcepool.BasicResourcePool@64c14e1c config: [start -> 3; min -> 3; max -> 15; inc -> 3; num_acq_attempts -> 30; acq_attempt_delay -> 1000; check_idle_resources_delay -> 0; mox_resource_age -> 0; max_idle_time -> 0; excess_max_idle_time -> 0; destroy_unreturned_resc_time -> 0; expiration_enforcement_delay -> 0; break_on_acquisition_failure -> false; debug_store_checkout_exceptions -> false] [java] 20120625.140730.011 INFO AbstractPoolBackedDataSource - Initializing c3p0 pool... com.mchange.v2.c3p0.ComboPooledDataSource [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, dataSourceName -> false, debugUnreturnedConnectionStackTraces -> false, description -> Foo Bar, driverClass -> org.gjt.mm.mysql.Driver, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> z8kflt8o9k9z6e1gsygqc|6a4cae18, idleConnectionTestPeriod -> 0, initialPoolSize -> 3, jdbcUrl -> jdbc:mysql://localhost/mydb, lastAcquisitionFailureDefaultUser -> null, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 0, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 15, maxStatements -> 0, maxStatementsPerConnection -> 0, minPoolSize -> 3, numHelperThreads -> 3, numThreadsAwaitingCheckoutDefaultUser -> 0, preferredTestQuery -> null, properties -> {user=******}, propertyCycle -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false ] [java] Jun 25, 2012 2:07:30 PM org.eclipse.jetty.plus.webapp.PlusConfiguration bindUserTransaction [java] INFO: No Transaction manager found - if your webapp requires one, please configure one. [java] 20120625.140730.089 DEBUG BasicResourcePool - An exception occurred while acquiring a poolable resource. Will retry. [java] java.sql.SQLException: Access denied for user 'myuser'@'localhost' (using password: NO) [java] at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1075) [java] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3562) [java] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3494) [java] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:920) [java] at com.mysql.jdbc.MysqlIO.secureAuth411(MysqlIO.java:4000) [java] at com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:1285) [java] at com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2186) [java] at com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:787) [java] at com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:49) [java] at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [java] at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) [java] at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [java] at java.lang.reflect.Constructor.newInstance(Constructor.java:525) [java] at com.mysql.jdbc.Util.handleNewInstance(Util.java:409) [java] at com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:357) [java] at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:285) [java] at com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:135) [java] at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:182) [java] at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:171) [java] at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:137) [java] at com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1014) [java] at com.mchange.v2.resourcepool.BasicResourcePool.access$800(BasicResourcePool.java:32) [java] at com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask.run(BasicResourcePool.java:1810) [java] at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547) ===== All this is logged on startup, without the app ever becoming usable. I can't tell from the stack trace what is initialising what, when. There are servlets that initialise on startup and use the database but they come in later, and I have mangled the JNDI name they would use via hibernate.connection.datasource so they fail to resolve it. So, I'm sure all this logging is produced during simple startup and initialisation of the JNDI data source. I've been banging away at this problem for hours. I did see it work once, and thought the planets were in alignment and I finally had the config right. Just after that it failed again and hasn't worked since. It stinks of some kind of race condition, as if the XML configuration performed by Jetty as it sets up the data source is not atomic. I then noticed that there is DBCP configuration given on the Jetty JNDI page http://wiki.eclipse.org/Jetty/Howto/Configure_JNDI_Datasource#dbcp which worked first time. I had previously given up on DBCP, because the Connection Provider code given on the wiki http://wiki.apache.org/commons/DBCP/Hibernate is not compatible with the Hibernate 4 release, but employing DBCP via JNDI avoids the need for my project to include the Provider code. Nick |