BTM unable to provide a valid connection when a firewall drops idle connections

When the AcquisitionInterval is set to 0, the program just waits for the connection to be returned from the pool forever.

I will look into this.

There were a few minor bugs in the acquisition timeout and acquisition interval handling of the XAPool which I fixed.

A few remarks:

When connections in the pool are invalid (like when you kill your DB or your firewall kills the connection) BTM detects this situation and retries with another connection of the pool every 1 second by default, and spends at most 30 seconds acquiring a connection.

This means that if there are 100 invalid connections in your pool, BTM will give up after cleaning up 30 of them with the default config.

Problem #1: the 30 seconds timeout isn't respected due to an obscure bug. BTM waits much less than that, about 8 seconds in the scenario of your example app but this can vary.

Problem #2: you cannot configure BTM to wait less than 1 second between connection tests or it will make the thread hang.

I've fixed both problems and committed the fix to the 2.1.x branch. I'd be glad if you could try it out and report the outcome. If you need help building the code, let me know and I'll be happy to publish a snapshot release containing the fixes.

If you can't wait for the 2.1.3 release that will contain fixes for those problems, I recommend you to raise the acquisitionTimeout property of your PoolingDataSource to a much higher number, say 120, 180 or 240 even. Try different values until you find a satisfying one.

I had the similar issue explained above. I reran the test "BTMTest.zip" with BTM 2.1.3 version, but I see the same error. Looks like this error is not this fixed in 2.1.3. can you check?
Error I see is:

Max Idle Connection time in seconds: 200
AcquireIncrement: 1
AcquisitionInterval: 1
AcquisitionTimeout time in seconds: 30
Current Pool statistics----------------
free connections:5
in use connections:0
total connections:5
Acquiring connections from Pool ----------------
Connection 1:a JdbcConnectionHandle of a JdbcPooledConnection from datasource jdbc/BPMSDB in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@1434234 on a JDBC LrcConnectionHandle on a JDBC LrcXAResource in state NO_TX
Connection 2:a JdbcConnectionHandle of a JdbcPooledConnection from datasource jdbc/BPMSDB in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@f7f540 on a JDBC LrcConnectionHandle on a JDBC LrcXAResource in state NO_TX
Connection 3:a JdbcConnectionHandle of a JdbcPooledConnection from datasource jdbc/BPMSDB in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@c8f6f8 on a JDBC LrcConnectionHandle on a JDBC LrcXAResource in state NO_TX
Connection 4:a JdbcConnectionHandle of a JdbcPooledConnection from datasource jdbc/BPMSDB in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@1ef9157 on a JDBC LrcConnectionHandle on a JDBC LrcXAResource in state NO_TX
Connection 5:a JdbcConnectionHandle of a JdbcPooledConnection from datasource jdbc/BPMSDB in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@3ecfff on a JDBC LrcConnectionHandle on a JDBC LrcXAResource in state NO_TX
Current Pool statistics----------------
free connections:0
in use connections:5
total connections:5
Closing acquired connections from Pool ----------------
Closing remaining connections:5
Connection:a JdbcConnectionHandle of a JdbcPooledConnection from datasource jdbc/BPMSDB in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@1434234 on a JDBC LrcConnectionHandle on a JDBC LrcXAResource in state NO_TX
Connection:a JdbcConnectionHandle of a JdbcPooledConnection from datasource jdbc/BPMSDB in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@f7f540 on a JDBC LrcConnectionHandle on a JDBC LrcXAResource in state NO_TX
Connection:a JdbcConnectionHandle of a JdbcPooledConnection from datasource jdbc/BPMSDB in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@c8f6f8 on a JDBC LrcConnectionHandle on a JDBC LrcXAResource in state NO_TX
Connection:a JdbcConnectionHandle of a JdbcPooledConnection from datasource jdbc/BPMSDB in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@1ef9157 on a JDBC LrcConnectionHandle on a JDBC LrcXAResource in state NO_TX
Connection:a JdbcConnectionHandle of a JdbcPooledConnection from datasource jdbc/BPMSDB in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@3ecfff on a JDBC LrcConnectionHandle on a JDBC LrcXAResource in state NO_TX
Connections closed---------------
Current Pool statistics----------------
free connections:5
in use connections:0
total connections:5
Thread Sleeping for 110 seconds, during this time kill all the database connections on the database server side-----------------
Thread Woke up---------------------------------
Current Pool statistics----------------
free connections:5
in use connections:0
total connections:5
Now trying to get a connection from Pool-----------------
SQLException Exception occurred:unable to get a connection from pool of a PoolingDataSource containing an XAPool of resource jdbc/BPMSDB with 3 connection(s) (3 still available)
Closing remaining connections:0
Connections closed---------------
java.sql.SQLException: unable to get a connection from pool of a PoolingDataSource containing an XAPool of resource jdbc/BPMSDB with 3 connection(s) (3 still available)
at bitronix.tm.resource.jdbc.PoolingDataSource.getConnection(PoolingDataSource.java:262)
at test.BTMTest.acquireConnections(BTMTest.java:58)
at test.BTMTest.main(BTMTest.java:100)
Caused by: bitronix.tm.internal.BitronixRuntimeException: cannot get valid connection from an XAPool of resource jdbc/BPMSDB with 3 connection(s) (3 still available) after trying for 30s
at bitronix.tm.resource.common.XAPool.getConnectionHandle(XAPool.java:160)
at bitronix.tm.resource.common.XAPool.getConnectionHandle(XAPool.java:91)
at bitronix.tm.resource.jdbc.PoolingDataSource.getConnection(PoolingDataSource.java:258)
... 2 more
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 151,225 milliseconds ago. The last packet sent successfully to the server was 18,901 milliseconds ago.
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 com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1116)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3102)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2991)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3532)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2002)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2163)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2624)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2127)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2293)
at bitronix.tm.resource.jdbc.JdbcPooledConnection.testConnection(JdbcPooledConnection.java:215)
at bitronix.tm.resource.jdbc.JdbcPooledConnection.getConnectionHandle(JdbcPooledConnection.java:299)
at bitronix.tm.resource.common.XAPool.getConnectionHandle(XAPool.java:130)
... 4 more
Caused by: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(Unknown Source)
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2549)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3002)
... 14 more

Hi Ludovic,

Thanks for the quick fix. This fix has to go with Apache ODE.

1) We need to test this fix, can you please provide a snapshot build with these 2 fixes.
2) Can you please let us know when is the next stable release schedule for.

regards,
sathwik

This fix was integrated in stable version 2.1.3 that was released yesterday.