Payara: JDBC connection attempt does not time out

[chrjohn]

We are using Payara 4.1.152.1 and recently had the following problem: the connection to our data base went down (network problem). When we tried to get a connection from the pool the components of our application were hanging until Payara was restarted about eight minutes later. The stack trace on shutdown shows that several components were waiting for a connection from the pool. Example:

"p: thread-pool-1; w: 9" #373 daemon prio=5 os_prio=0 tid=0x00007f12f6a73000 nid=0x4233 waiting on condition [0x00007f12e09f0000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000853c6460> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared(AbstractQueuedSynchronizer.java:967)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(AbstractQueuedSynchronizer.java:1283)
        at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(ReentrantReadWriteLock.java:727)
        at com.sun.enterprise.resource.pool.datastructure.RWLockDataStructure.getResource(RWLockDataStructure.java:116)
        at com.sun.enterprise.resource.pool.ConnectionPool.getResourceFromPool(ConnectionPool.java:716)
        at com.sun.enterprise.resource.pool.ConnectionPool.getUnenlistedResource(ConnectionPool.java:632)
        at com.sun.enterprise.resource.pool.ConnectionPool.internalGetResource(ConnectionPool.java:526)
        at com.sun.enterprise.resource.pool.ConnectionPool.getResource(ConnectionPool.java:381)
        at com.sun.enterprise.resource.pool.PoolManagerImpl.getResourceFromPool(PoolManagerImpl.java:245)
        at com.sun.enterprise.resource.pool.PoolManagerImpl.getResource(PoolManagerImpl.java:171)
        at com.sun.enterprise.connectors.ConnectionManagerImpl.getResource(ConnectionManagerImpl.java:360)
        at com.sun.enterprise.connectors.ConnectionManagerImpl.internalGetConnection(ConnectionManagerImpl.java:307)
        at com.sun.enterprise.connectors.ConnectionManagerImpl.allocateConnection(ConnectionManagerImpl.java:196)
        at com.sun.enterprise.connectors.ConnectionManagerImpl.allocateConnection(ConnectionManagerImpl.java:171)
        at com.sun.enterprise.connectors.ConnectionManagerImpl.allocateConnection(ConnectionManagerImpl.java:166)
        at com.sun.gjc.spi.base.AbstractDataSource.getConnection(AbstractDataSource.java:115)
        at org.eclipse.persistence.sessions.JNDIConnector.connect(JNDIConnector.java:135)
        at org.eclipse.persistence.sessions.DatasourceLogin.connectToDatasource(DatasourceLogin.java:162)
        at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.connectInternal(DatasourceAccessor.java:346)
        at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.connectInternal(DatabaseAccessor.java:309)
        at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.reconnect(DatasourceAccessor.java:581)
        at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.reconnect(DatabaseAccessor.java:1634)
        at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.incrementCallCount(DatasourceAccessor.java:321)
        - locked <0x00000000d7b879d8> (a org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor)
        at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:615)
        at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:560)
        at org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:2055)
        at org.eclipse.persistence.sessions.server.ServerSession.executeCall(ServerSession.java:570)
....

Around the same time the following entries were shown in the log file:
RAR5038:Unexpected exception while creating resource for pool postgresql-dbpra2-pool. Exception : javax.resource.spi.ResourceAllocationException: Connection could not be allocated because: The connection attempt failed.

I checked the JDBC connection pool parameters. There is a "max-wait-time-in-millis" of 10000ms configured. Doesn't this mean that I should get an exception of some sort after that time? I would prefer to fail fast instead of forever waiting for a connection. We also have connection validation enabled (might be related to #1013 and/or #769 ).
So to sum this up: connections in the pool were waiting forever, new connections could not be allocated because the connection attempts failed.

[anaelcarvalho]

Do you have a connection timeout specified in your driver settings (actual network connection)? This is just speculation on my part, but maybe some condition caused the application to wait for a connection indefinitely because the pool was waiting on a network connection with the database first.

I've had this situation occur sometimes - everything went back to normal once the db was up again.

[chrjohn]

Hi @anaelcarvalho , thanks for your message.
No, I did not specify any timeout values in the driver settings. I take it that you are referring to the "Additional Properties" when editing the "JDBC Connection Pool Properties"?

[anaelcarvalho]

Yup! Your JDBC driver documentation should have some property to set the connection timeout (if you're using the PostgreSQL JDBC driver you can set loginTimeout, connectTimeout and socketTimeout). I'd try playing with these and check if this behavior happens again.

[retoo]

@chrjohn that's exactly the bug from #769, see our patch #770 (for 4.1.152) and #1148 (for 4.1.1.163).

When errors occur during some phases (begin/commit/rollback) the error handling code will crash immediately again (due to the same problem) and the connection will end up back in the connection pool. See the diff in the two pull requests, the new version is more robust during the finally {} call.

We have the new version running for several months now.

[chrjohn]

@retoo Thanks for the pointer. Although we don't have our log files flooded with Exceptions. There were only the aforementioned lines:

RAR5038:Unexpected exception while creating resource for pool postgresql-dbpra2-pool. Exception : javax.resource.spi.ResourceAllocationException: Connection could not be allocated because: The connection attempt failed.

But sounds like the same problem, though. Thank you

[retoo]

@chrjohn i think it depends how often the broken connection gets handed out. Under load the problem worsened in our case.

[lprimak]

Fixed