Hanging connections using BTM + Spring + PostgreSQL 8.3.7

[Martin Schmied]

Hi everybody,

we're using BTM with Spring's declarative transaction demarcation (@Transactional annotation). Transactions are newer handled directly through APIs. We have problems with pooled connections that stay in the ACCESSIBLE state forever, preventing them to be used by other thransactions. One case we are able to reproduce is when the transaction times out - according to logs it is rolled back, but the connection is never released. Version of postgresql driver used is 8.3.603

Many thanks for any advice!
Martin

[Ludovic Orban]

Hi,

Can you give more details about the problem ? Which version of BTM are you running ? What is your Spring configuration looking like ?

How about enabling debug logs on bitronix.tm.BitronixTransaction ? This should give you a very good overview of how transactions are being handled under the cover.

[Martin Schmied]

Hi Ludovic,

thanks for your quick response! It's BTM 1.3.2, Spring configuration is:

       <bean id="transactionManager" class="org.springframework.transaction.jta.JtaTransactionManager">
                <property name="transactionManager" ref="bitronixTransactionManager" />
                <property name="userTransaction" ref="bitronixTransactionManager" />
        </bean>

        <bean id="btmConfig" factory-method="getConfiguration" class="bitronix.tm.TransactionManagerServices"/>

        <bean id="bitronixTransactionManager" factory-method="getTransactionManager"
                class="bitronix.tm.TransactionManagerServices" depends-on="btmConfig"
                destroy-method="shutdown" />

        <bean id="postgresDataSource" class="bitronix.tm.resource.jdbc.PoolingDataSource"
                init-method="init" destroy-method="close">
                <property name="className" value="org.postgresql.xa.PGXADataSource" />
                <property name="uniqueName" value="pxa1" />
                <property name="maxPoolSize" value="20" />
                <property name="driverProperties">
                        <props>
                                ...
                        </props>
                </property>
                <property name="allowLocalTransactions" value="true" />
        </bean>
       
        <bean id="msSqlDataSource" class="bitronix.tm.resource.jdbc.PoolingDataSource"
                init-method="init" destroy-method="close">
                <property name="className" value="net.sourceforge.jtds.jdbcx.JtdsDataSource" />
                <property name="uniqueName" value="pxa2" />
                <property name="maxPoolSize" value="20" />
                <property name="driverProperties">
                        <props>
                                ...
                        </props>
                </property>
                <property name="allowLocalTransactions" value="true" />
        </bean>

Part of the debug log:

82978 [2009-06-18 17:19:44,543][http-8080-2] DEBUG bitronix.tm.BitronixTransactionManager  - beginning a new transaction
82978 [2009-06-18 17:19:44,543][http-8080-2] DEBUG bitronix.tm.BitronixTransactionManager  - dumping 0 transaction context(s)
82978 [2009-06-18 17:19:44,543][http-8080-2] DEBUG bitronix.tm.BitronixTransactionManager  - creating new thread context
82978 [2009-06-18 17:19:44,543][http-8080-2] DEBUG bitronix.tm.BitronixTransactionManager  - changing current thread context to a ThreadContext with transaction null, default timeout 60s
82979 [2009-06-18 17:19:44,544][http-8080-2] DEBUG bitronix.tm.BitronixTransaction  - creating new transaction with GTRID [31302E302E302E32303200000121F3F3B8A000000007]
82979 [2009-06-18 17:19:44,544][http-8080-2] DEBUG bitronix.tm.internal.ThreadContext  - assigning  to
82980 [2009-06-18 17:19:44,545][http-8080-2] DEBUG bitronix.tm.BitronixTransaction  - changing transaction status to ACTIVE
143244 [2009-06-18 17:20:44,809][bitronix-scheduler] DEBUG bitronix.tm.BitronixTransaction  - changing transaction status to MARKED_ROLLBACK
143245 [2009-06-18 17:20:44,810][bitronix-scheduler] DEBUG bitronix.tm.journal.TransactionLogAppender  - between 1047460 and 1047519, writing a Bitronix TransactionLogRecord with status=MARKED_ROLLBACK, recordLength=51, headerLength=28, time=1245338444810, sequenceNumber=9, crc32=-346603019, gtrid=31302E302E302E32303200000121F3F3B8A000000007, uniqueNames=
143245 [2009-06-18 17:20:44,810][bitronix-scheduler] DEBUG bitronix.tm.journal.TransactionLogAppender  - disk journal appender now at position 1047519
143245 [2009-06-18 17:20:44,810][bitronix-scheduler] DEBUG bitronix.tm.timer.TaskScheduler  - successfully ran a TransactionTimeoutTask on a Bitronix Transaction with GTRID [31302E302E302E32303200000121F3F3B8A000000007], status=MARKED_ROLLBACK, 0 resource(s) enlisted (started Thu Jun 18 17:19:44 CEST 2009) scheduled for Thu Jun 18 17:20:44 CEST 2009
143245 [2009-06-18 17:20:44,810][bitronix-scheduler] DEBUG bitronix.tm.timer.TaskScheduler  - total task(s) still queued: 3
157305 [2009-06-18 17:20:58,870][http-8080-2] DEBUG bitronix.tm.resource.jdbc.PoolingDataSource  - acquiring connection from a PoolingDataSource containing an XAPool of resource pxa1 with 1 connection(s) (1 still available)
157311 [2009-06-18 17:20:58,876][http-8080-2] DEBUG bitronix.tm.resource.common.XAPool  - trying to recycle a NOT_ACCESSIBLE connection of an XAPool of resource pxa1 with 1 connection(s) (1 still available)
157312 [2009-06-18 17:20:58,877][http-8080-2] DEBUG bitronix.tm.resource.common.XAPool  - current transaction GTRID is [31302E302E302E32303200000121F3F3B8A000000007]
157312 [2009-06-18 17:20:58,877][http-8080-2] DEBUG bitronix.tm.resource.common.XAPool  - no NOT_ACCESSIBLE connection enlisted in this transaction
157313 [2009-06-18 17:20:58,878][http-8080-2] DEBUG bitronix.tm.resource.common.XAPool  - getting a IN_POOL connection from an XAPool of resource pxa1 with 1 connection(s) (1 still available)
157314 [2009-06-18 17:20:58,879][http-8080-2] DEBUG bitronix.tm.resource.common.XAPool  - waiting for IN_POOL connections count to be > 0, currently is 1
157314 [2009-06-18 17:20:58,879][http-8080-2] DEBUG bitronix.tm.resource.common.XAPool  - found IN_POOL connection a JdbcPooledConnection from datasource pxa1 in state IN_POOL wrapping org.postgresql.xa.PGXAConnection@106d4ea from an XAPool of resource pxa1 with 1 connection(s) (1 still available)
157315 [2009-06-18 17:20:58,880][http-8080-2] DEBUG bitronix.tm.resource.jdbc.JdbcPooledConnection  - getting connection handle from a JdbcPooledConnection from datasource pxa1 in state IN_POOL wrapping org.postgresql.xa.PGXAConnection@106d4ea
157316 [2009-06-18 17:20:58,881][http-8080-2] DEBUG bitronix.tm.resource.common.AbstractXAStatefulHolder  - notifying 2 stateChangeEventListener(s) about state changing from IN_POOL to ACCESSIBLE in a JdbcPooledConnection from datasource pxa1 in state IN_POOL wrapping org.postgresql.xa.PGXAConnection@106d4ea
157317 [2009-06-18 17:20:58,882][http-8080-2] DEBUG bitronix.tm.resource.common.AbstractXAStatefulHolder  - state changing from IN_POOL to ACCESSIBLE in a JdbcPooledConnection from datasource pxa1 in state IN_POOL wrapping org.postgresql.xa.PGXAConnection@106d4ea
157318 [2009-06-18 17:20:58,883][http-8080-2] DEBUG bitronix.tm.resource.common.AbstractXAStatefulHolder  - notifying 2 stateChangeEventListener(s) about state changed from IN_POOL to ACCESSIBLE in a JdbcPooledConnection from datasource pxa1 in state ACCESSIBLE wrapping org.postgresql.xa.PGXAConnection@106d4ea
157318 [2009-06-18 17:20:58,883][http-8080-2] DEBUG bitronix.tm.resource.jdbc.JdbcPooledConnection  - connection org.postgresql.xa.PGXAConnection@106d4ea was in state STATE_IN_POOL, testing it
157319 [2009-06-18 17:20:58,884][http-8080-2] DEBUG bitronix.tm.resource.jdbc.JdbcPooledConnection  - no query to test connection of a JdbcPooledConnection from datasource pxa1 in state ACCESSIBLE wrapping org.postgresql.xa.PGXAConnection@106d4ea, skipping test
157320 [2009-06-18 17:20:58,885][http-8080-2] DEBUG bitronix.tm.resource.jdbc.JdbcPooledConnection  - got connection handle from a JdbcPooledConnection from datasource pxa1 in state ACCESSIBLE wrapping org.postgresql.xa.PGXAConnection@106d4ea
157321 [2009-06-18 17:20:58,886][http-8080-2] DEBUG bitronix.tm.resource.jdbc.PoolingDataSource  - acquired connection from a PoolingDataSource containing an XAPool of resource pxa1 with 1 connection(s) (0 still available)
157322 [2009-06-18 17:20:58,887][http-8080-2] DEBUG org.hibernate.SQL  - select nextval ('hibernate_sequence')
157323 [2009-06-18 17:20:58,888][http-8080-2] DEBUG bitronix.tm.resource.common.TransactionContextHelper  - enlisting a JdbcPooledConnection from datasource pxa1 in state ACCESSIBLE wrapping org.postgresql.xa.PGXAConnection@106d4ea into a Bitronix Transaction with GTRID [31302E302E302E32303200000121F3F3B8A000000007], status=MARKED_ROLLBACK, 0 resource(s) enlisted (started Thu Jun 18 17:19:44 CEST 2009)
157337 [2009-06-18 17:20:58,902][http-8080-2] WARN  org.hibernate.util.JDBCExceptionReporter  - SQL Error: 0, SQLState: null
157338 [2009-06-18 17:20:58,903][http-8080-2] ERROR org.hibernate.util.JDBCExceptionReporter  - error enlisting a JdbcConnectionHandle of a JdbcPooledConnection from datasource pxa1 in state ACCESSIBLE wrapping org.postgresql.xa.PGXAConnection@106d4ea on Pooled connection wrapping physical connection org.postgresql.jdbc4.Jdbc4Connection@ad962c
157341 [2009-06-18 17:20:58,906][http-8080-2] DEBUG bitronix.tm.BitronixTransactionManager  - marking transaction as rollback only: a Bitronix Transaction with GTRID [31302E302E302E32303200000121F3F3B8A000000007], status=MARKED_ROLLBACK, 0 resource(s) enlisted (started Thu Jun 18 17:19:44 CEST 2009)
157344 [2009-06-18 17:20:58,909][http-8080-2] DEBUG bitronix.tm.BitronixTransaction  - changing transaction status to MARKED_ROLLBACK
215026 [2009-06-18 17:21:56,591][http-8080-2] DEBUG bitronix.tm.BitronixTransactionManager  - rolling back transaction a Bitronix Transaction with GTRID [31302E302E302E32303200000121F3F3B8A000000007], status=MARKED_ROLLBACK, 0 resource(s) enlisted (started Thu Jun 18 17:19:44 CEST 2009)
215026 [2009-06-18 17:21:56,591][http-8080-2] DEBUG bitronix.tm.timer.TaskScheduler  - cancelling transaction timeout task on a Bitronix Transaction with GTRID [31302E302E302E32303200000121F3F3B8A000000007], status=MARKED_ROLLBACK, 0 resource(s) enlisted (started Thu Jun 18 17:19:44 CEST 2009)
215026 [2009-06-18 17:21:56,591][http-8080-2] DEBUG bitronix.tm.timer.TaskScheduler  - removing task by a Bitronix Transaction with GTRID [31302E302E302E32303200000121F3F3B8A000000007], status=MARKED_ROLLBACK, 0 resource(s) enlisted (started Thu Jun 18 17:19:44 CEST 2009)
215027 [2009-06-18 17:21:56,592][http-8080-2] DEBUG bitronix.tm.timer.TaskScheduler  - no task found based on object a Bitronix Transaction with GTRID [31302E302E302E32303200000121F3F3B8A000000007], status=MARKED_ROLLBACK, 0 resource(s) enlisted (started Thu Jun 18 17:19:44 CEST 2009)
215027 [2009-06-18 17:21:56,592][http-8080-2] DEBUG bitronix.tm.BitronixTransaction  - rolling back, 0 enlisted resource(s)
215027 [2009-06-18 17:21:56,592][http-8080-2] DEBUG bitronix.tm.BitronixTransaction  - changing transaction status to ROLLING_BACK
215028 [2009-06-18 17:21:56,593][http-8080-2] DEBUG bitronix.tm.BitronixTransaction  - changing transaction status to ROLLEDBACK
215029 [2009-06-18 17:21:56,594][http-8080-2] DEBUG bitronix.tm.BitronixTransaction  - successfully rolled back a Bitronix Transaction with GTRID [31302E302E302E32303200000121F3F3B8A000000007], status=ROLLEDBACK, 0 resource(s) enlisted (started Thu Jun 18 17:19:44 CEST 2009)
215029 [2009-06-18 17:21:56,594][http-8080-2] DEBUG bitronix.tm.BitronixTransaction  - after completion, 1 synchronization(s) to execute
215029 [2009-06-18 17:21:56,594][http-8080-2] DEBUG bitronix.tm.BitronixTransaction  - executing synchronization a ClearContextSynchronization for a Bitronix Transaction with GTRID [31302E302E302E32303200000121F3F3B8A000000007], status=ROLLEDBACK, 0 resource(s) enlisted (started Thu Jun 18 17:19:44 CEST 2009) with status=ROLLEDBACK
215029 [2009-06-18 17:21:56,594][http-8080-2] DEBUG bitronix.tm.BitronixTransactionManager  - clearing thread context: a ThreadContext with transaction a Bitronix Transaction with GTRID [31302E302E302E32303200000121F3F3B8A000000007], status=ROLLEDBACK, 0 resource(s) enlisted (started Thu Jun 18 17:19:44 CEST 2009), default timeout 60s
Jun 18, 2009 5:21:56 PM org.apache.catalina.core.StandardWrapperValve invoke
SEVERE: Servlet.service() for servlet Spring WEB servlet threw exception
bitronix.tm.internal.BitronixSystemException: transaction timed out
        at bitronix.tm.resource.common.TransactionContextHelper.enlistInCurrentTransaction(TransactionContextHelper.java:45)
        at bitronix.tm.resource.jdbc.JdbcConnectionHandle.enlistResource(JdbcConnectionHandle.java:59)
        at bitronix.tm.resource.jdbc.JdbcConnectionHandle.prepareStatement(JdbcConnectionHandle.java:200)
        at org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:505)
        at org.hibernate.jdbc.AbstractBatcher.prepareSelectStatement(AbstractBatcher.java:123)
        at org.hibernate.id.SequenceGenerator.generate(SequenceGenerator.java:73)
        ...
        at biz.pageup.messenger.base.dao.MessengerDao.merge(MessengerDao.java:100)
        ...
244294 [2009-06-18 17:22:25,859][bitronix-scheduler] DEBUG bitronix.tm.timer.TaskScheduler  - running a PoolShrinkingTask scheduled for Thu Jun 18 17:22:25 CEST 2009 on an XAPool of resource pxa1 with 1 connection(s) (0 still available)
244294 [2009-06-18 17:22:25,859][bitronix-scheduler] DEBUG bitronix.tm.resource.common.XAPool  - shrinking an XAPool of resource pxa1 with 1 connection(s) (0 still available)
244294 [2009-06-18 17:22:25,859][bitronix-scheduler] DEBUG bitronix.tm.resource.common.XAPool  - closed 0 idle connection(s)

After this, the connection is available never more.

Ludovic Orban wrote:

Hi,

Can you give more details about the problem ? Which version of BTM are you running ? What is your Spring configuration looking like ?

How about enabling debug logs on bitronix.tm.BitronixTransaction ? This should give you a very good overview of how transactions are being handled under the cover.

[Ludovic Orban]

Martin,

Is there a reason why you enabled allowLocalTransactions ? This setting usually isn't recommended unless you exactly know what you're doing.

The debug log fragment you sent isn't complete enough to give you a definitive answer. To me it looks like you have transactions timing out an not being actively rolled back but it's just a guess.

If you can reproduce the issue then please try to collect a complete debug logs file of the issue.

The transaction management part of your Spring config will certainly help as well.

[Martin Schmied]

Ludovic,

we had allowLocalTransactions turned on because we were used to using JPA without transactions for read-only operations on one database. It seemed to work fine with BTM for quite some time until this issue with hanging connections. However, after switching the allowLocalTransactions flag off (and adding transaction demarcation to the read-only operations), the above described issue is no longer reproducible. Thanks for your help!

Martin

[Ludovic Orban]

Martin,

There indeed is a race condition in BTM 1.3.2 which can happen in very rare cases when you mix local and global transactions: http://jira.codehaus.org/browse/BTM-43

This bug (and some other related ones it uncovered) have been fixed in the trunk so you can either build it yourself if you want to keep mixing local and global transactions or stop using local transactions as you just did, the later being the option I recommend.