Hikaricp: Failed to obtain connection from factory method

Created on 12 Jan 2018 · 7Comments · Source: brettwooldridge/HikariCP

Environment

```
HikariCP version: 2.7.4 (even 2.7.5 :) )
JDK version : 1.8.0_152
Database : DB2
Driver version : 3.69.24
Log4j2 version : 2.10.0

I wanted to optimize the application, so trying to migrate to Hikari from BasicDataSource(apache commons) :)
Hikari worked great with log4j2 and oracle and informix jdbc drivers.
But I had issue with DB2.
Log4j2 is using this code for JDBCAppender.

`public class ConnectionFactory {
private static interface Singleton {
final ConnectionFactory INSTANCE = new ConnectionFactory();
}

private final DataSource dataSource;

private ConnectionFactory() {

    HikariConfig hikariConfig = new HikariConfig();
    hikariConfig.setUsername(user);
    hikariConfig.setPassword(pass);
    hikariConfig.setJdbcUrl(jdbcUrl);
    hikariConfig.setDriverClassName(driver);
    this.dataSource = new HikariDataSource(hikariConfig);
}

public static Connection getDatabaseConnection() throws SQLException {
     return Singleton.INSTANCE.dataSource.getConnection();
}

}`

`2018-01-12 00:55:41,578 localhost-startStop-1 ERROR JdbcDatabaseManager JdbcManager{name=databaseAppender, bufferSize=0, tableName=LOG_LOG4J, columnConfigs=[{ name=LOGDATE, layout=null, literal=null, timestamp=true }, { name=EVTIME, layout=null, literal=null, timestamp=true }, { name=PRIORITY, layout=%level, literal=null, timestamp=false }, { name=LOGGER, layout=%logger, literal=null, timestamp=false }, { name=MSG, layout=%message, literal=null, timestamp=false }, { name=THROW, layout=%ex{full}, literal=null, timestamp=false }, { name=NDC, layout=%NDC, literal=null, timestamp=false }, { name=USERNAME, layout=%MDC{USERNAME}, literal=null, timestamp=false }], columnMappings=[]} Could not perform database startup operations: java.sql.SQLException: Failed to obtain connection from factory method. java.sql.SQLException: Failed to obtain connection from factory method.
at org.apache.logging.log4j.core.appender.db.jdbc.FactoryMethodConnectionSource$1.getConnection(FactoryMethodConnectionSource.java:108)
at org.apache.logging.log4j.core.appender.db.jdbc.FactoryMethodConnectionSource.getConnection(FactoryMethodConnectionSource.java:54)
at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.startupInternal(JdbcDatabaseManager.java:74)
at org.apache.logging.log4j.core.appender.db.AbstractDatabaseManager.startup(AbstractDatabaseManager.java:65)
at org.apache.logging.log4j.core.appender.db.AbstractDatabaseAppender.start(AbstractDatabaseAppender.java:89)
at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:265)
at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:545)
at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:617)
at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:634)
at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:229)
at org.apache.logging.log4j.core.async.AsyncLoggerContext.start(AsyncLoggerContext.java:76)
at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:153)
at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:45)
at org.apache.logging.log4j.LogManager.getContext(LogManager.java:194)
at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:581)
at com.mis.common.log.LogHelper.getInstance(LogHelper.java:54)
at com.mis.dokumenti.biznis.DokumentBL.(DokumentBL.java:67)
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
at java.lang.reflect.Constructor.newInstance(Unknown Source)
at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:147)
at org.springframework.beans.factory.support.SimpleInstantiationStrategy.instantiate(SimpleInstantiationStrategy.java:89)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.instantiateBean(AbstractAutowireCapableBeanFactory.java:1098)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1050)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:510)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:482)
at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:305)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:301)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:196)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:772)
at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:834)
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:537)
at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:446)
at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:328)
at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:107)
at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:5110)
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5633)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:145)
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1700)
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1690)
at java.util.concurrent.FutureTask.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
Caused by: java.lang.reflect.InvocationTargetException
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.apache.logging.log4j.core.appender.db.jdbc.FactoryMethodConnectionSource$1.getConnection(FactoryMethodConnectionSource.java:106)
... 45 more
Caused by: java.lang.AbstractMethodError: com.ibm.db2.jcc.t4.b.isValid(I)Z
at com.zaxxer.hikari.pool.PoolBase.checkDriverSupport(PoolBase.java:455)
at com.zaxxer.hikari.pool.PoolBase.setupConnection(PoolBase.java:422)
at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:380)
at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:204)
at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:459)
at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:533)
at com.zaxxer.hikari.pool.HikariPool.(HikariPool.java:114)
at com.zaxxer.hikari.HikariDataSource.(HikariDataSource.java:82)
at com.mis.conn.ConnectionFactory.(ConnectionFactory.java:54)
at com.mis.conn.ConnectionFactory.(ConnectionFactory.java:20)
at com.mis.conn.ConnectionFactory$Singleton.(ConnectionFactory.java:15)
at com.mis.conn.ConnectionFactory.getDatabaseConnection(ConnectionFactory.java:58)

... 50 more`

I have db2jcc JDBC driver and db2jcc_license_cu for it. ( tried newer db2jcc4 , application was starting fine, but Driver wasn't working well with querries)
I also tried to configure Hikari with dataSourceClassName (instead of jdbcUrl).
Even driverType configuration didn't help.
@brettwooldridge Could anyone help me, please ?

Source

Anonymous12356

Most helpful comment

Looks like your JDBC driver is only JDBC 3.0 compliant (Connection.isValid() is a JDBC 4.0 API).

For a JDBC 3.0 driver you have to set connectionTestQuery in HikariConfig so that Hikari executes that configured query to figure out if a connection is still valid. Usually a "SELECT 1" will do it.

jnehlmeier on 12 Jan 2018

👍4

All 7 comments

Looks like your JDBC driver is only JDBC 3.0 compliant (Connection.isValid() is a JDBC 4.0 API).

jnehlmeier on 12 Jan 2018

👍4

@jnehlmeier Thank you for replay. That passed. But now, i have another problem. :)

AsyncLogger error handling event seq=0, value='[ERROR calling class org.apache.logging.log4j.core.async.RingBufferLogEvent.toString(): java.lang.NullPointerException]':
java.lang.AbstractMethodError: Method com/ibm/db2/jcc/am/zo.isClosed()Z is abstract
at com.ibm.db2.jcc.am.zo.isClosed(Unknown Source)
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.isClosed(HikariProxyPreparedStatement.java)
at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.writeInternal(JdbcDatabaseManager.java:105)
at org.apache.logging.log4j.core.appender.db.AbstractDatabaseManager.write(AbstractDatabaseManager.java:172)
at org.apache.logging.log4j.core.appender.db.AbstractDatabaseAppender.append(AbstractDatabaseAppender.java:108)
at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:448)
at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:433)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:79)
at org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:380)
at org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:152)
at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:45)
at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:29)
at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:137)
at java.lang.Thread.run(Unknown Source)

Anonymous12356 on 12 Jan 2018

java.lang.AbstractMethodError: Method com/ibm/db2/jcc/am/zo.isClosed()Z is abstract
at com.ibm.db2.jcc.am.zo.isClosed(Unknown Source)
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.isClosed(HikariProxyPreparedStatement.java)
at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.writeInternal(JdbcDatabaseManager.java:105)
at org.apache.logging.log4j.core.appender.db.AbstractDatabaseManager.write(AbstractDatabaseManager.java:172)
at org.apache.logging.log4j.core.appender.db.AbstractDatabaseAppender.append(AbstractDatabaseAppender.java:108)

As you can see your Log4J configuration uses some database log appender which uses a JdbcDatabaseManager which in turn calls PreparedStatement.isClosed(). This method is JDBC 4.0 API and thus not available in your JDBC 3.x driver.

That is not a HikariCP issue anymore.

jnehlmeier on 12 Jan 2018

👍1

@jnehlmeier Thank you very much.
If somebody has any solution, please post. :)

Anonymous12356 on 12 Jan 2018

Use JDBC 4 ;)

jnehlmeier on 12 Jan 2018

http://www-01.ibm.com/support/docview.wss?uid=swg21363866

Use the db2jcc4.jar.

brettwooldridge on 13 Jan 2018

Looks like your JDBC driver is only JDBC 3.0 compliant (Connection.isValid() is a JDBC 4.0 API).

For a JDBC 3.0 driver you have to set connectionTestQuery in HikariConfig so that Hikari executes that configured query to figure out if a connection is still valid. Usually a "SELECT 1" will do it.

Spot on!! Thanks a ton