BTM

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

Details

  • Type: Bug Bug
  • Status: Closed Closed
  • Priority: Major Major
  • Resolution: Fixed
  • Affects Version/s: 2.1.2
  • Fix Version/s: 2.1.3
  • Labels:
    None
  • Environment:
    Ubuntu 11.04, Mysql 5.1, BTM 2.1.2, Mysql-connector 5.1.18
  • Number of attachments :
    1

Description

I am seeing that when a firewall drops the idle connection bitronix is not able to provide a valid connection. I am attaching a sample eclipse project BTMTest.zip.

Environment: Ubuntu 11.04, Mysql 5.1, BTM 2.1.2, mysql-connector 5.1.18

The sample program creates 10 min pool connections acquires them and releases them, then the current execution thread is made to sleep for 110 seconds. While the thread is sleeping, using the Mysql Administrator kill all the 10 connections. When the thread wakes up a request is made to acquire a connection and then error occurs. I see that there are about 8 tries made to get a valid connection from the pool and then BTM throws an error as shown below. I am not sure why it only tries for 8 times, in my opinion it should try till AcquisitionTimeout (30 sec). What is strange is that when I increase the thread sleep time to 120 seconds, a valid connection is obtained.

Here is the error printed on the eclipse console. For btm log please refer the log director with in the project.

java.sql.SQLException: unable to get a connection from pool of a PoolingDataSource containing an XAPool of resource jdbc/BPMSDB with 2 connection(s) (2 still available)
at bitronix.tm.resource.jdbc.PoolingDataSource.getConnection(PoolingDataSource.java:252)
at test.BTMTest.acquireConnections(BTMTest.java:57)
at test.BTMTest.main(BTMTest.java:99)
Caused by: bitronix.tm.internal.BitronixRuntimeException: cannot get valid connection from an XAPool of resource jdbc/BPMSDB with 2 connection(s) (2 still available) after trying for 30s
at bitronix.tm.resource.common.XAPool.getConnectionHandle(XAPool.java:162)
at bitronix.tm.resource.common.XAPool.getConnectionHandle(XAPool.java:97)
at bitronix.tm.resource.jdbc.PoolingDataSource.getConnection(PoolingDataSource.java:248)
... 2 more
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 117,142 milliseconds ago. The last packet sent successfully to the server was 0 milliseconds ago.
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
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:200)
at bitronix.tm.resource.jdbc.JdbcPooledConnection.getConnectionHandle(JdbcPooledConnection.java:286)
at bitronix.tm.resource.common.XAPool.getConnectionHandle(XAPool.java:136)
... 4 more
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2552)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3002)
... 14 more

regards,
sathwik

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Sathwik BP added a comment -

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

Show
Sathwik BP added a comment - When the AcquisitionInterval is set to 0, the program just waits for the connection to be returned from the pool forever.
Hide
Permalink
Ludovic Orban added a comment -

I will look into this.

Show
Ludovic Orban added a comment - I will look into this.
Hide
Permalink
Ludovic Orban added a comment -

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.

Show
Ludovic Orban added a comment - 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.
Hide
Permalink
hareendra added a comment -

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

Show
hareendra added a comment - 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
Hide
Permalink
Sathwik BP added a comment -

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

Show
Sathwik BP added a comment - 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
Hide
Permalink
Ludovic Orban added a comment -

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

Show
Ludovic Orban added a comment - This fix was integrated in stable version 2.1.3 that was released yesterday.

People

  • Assignee:
    Ludovic Orban
    Reporter:
    Sathwik BP
Vote (0)
Watch (3)

Dates

  • Created:
    Updated:
    Resolved: