Debug LoggingWith a carefully crafted logging policy, we can exactly trace what is happening without having to reproduce the problem locally. This would helps help a lot in troubleshooting reported problems. Our logging has been revised for the 3.8 release. Here is an commented example of what another transaction manager logs on a simple transaction spanning 2 derby databases: tm.begin() 2007-07-13 20:03:49,734 [pool-1-thread-1] DEBUG - beginning a new transaction 2007-07-13 20:03:49,734 [pool-1-thread-1] DEBUG - dumping 0 transaction context(s) 2007-07-13 20:03:49,750 [pool-1-thread-1] DEBUG - creating new transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000] 2007-07-13 20:03:49,750 [pool-1-thread-1] DEBUG - creating new thread context 2007-07-13 20:03:49,750 [pool-1-thread-1] DEBUG - changing current thread context to a ThreadContext with transaction null, default timeout 60s 2007-07-13 20:03:49,750 [pool-1-thread-1] DEBUG - assigning <a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=NO_TRANSACTION, 0 resource(s) enlisted> to <a ThreadContext with transaction null, default timeout 60s> 2007-07-13 20:03:49,750 [pool-1-thread-1] DEBUG - changing transaction timeout on a BitronixTransactionManager with 1 in-flight transaction(s) 2007-07-13 20:03:49,750 [pool-1-thread-1] DEBUG - scheduling transaction timeout task on a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=NO_TRANSACTION, 0 resource(s) enlisted for Fri Jul 13 20:04:49 CEST 2007 2007-07-13 20:03:49,750 [pool-1-thread-1] DEBUG - scheduled a TransactionTimeoutTask on a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=NO_TRANSACTION, 0 resource(s) enlisted scheduled for Fri Jul 13 20:04:49 CEST 2007, total task(s) queued: 1 2007-07-13 20:03:49,750 [pool-1-thread-1] DEBUG - changing transaction status to ACTIVE 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - writing a Bitronix TransactionLogRecord with status=ACTIVE, recordLength=63, headerLength=28, time=1184349829765, sequenceNumber=1, crc32=1230614836, gtrid=737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000, uniqueNames= 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - disk journal appender now at position 92 c1 = ds1.getConnection() 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - acquiring connection from a PoolingDataSource with uniqueName derby1 and an XAPool of resource derby1 with 10 connection(s) (10 still available) 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - trying to recycle a NOT_ACCESSIBLE connection of an XAPool of resource derby1 with 10 connection(s) (10 still available) 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - current transaction GTRID is [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000] 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - no NOT_ACCESSIBLE connection enlisted in this transaction 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - getting a IN_POOL connection from an XAPool of resource derby1 with 10 connection(s) (10 still available) 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - waiting for IN_POOL connections count to be > 0, currently is 10 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - found IN_POOL connection a JdbcPooledConnection from datasource derby1 in state IN_POOL wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) from an XAPool of resource derby1 with 10 connection(s) (10 still available) 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - getting connection handle from a JdbcPooledConnection from datasource derby1 in state IN_POOL wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - state changing from IN_POOL to ACCESSIBLE in a JdbcPooledConnection from datasource derby1 in state IN_POOL wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - notifying 2 stateChangeEventListener(s) about state change from IN_POOL to ACCESSIBLE in a JdbcPooledConnection from datasource derby1 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - no query to test connection of a JdbcPooledConnection from datasource derby1 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) , skipping test 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - got connection handle from a JdbcPooledConnection from datasource derby1 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - acquired connection from a PoolingDataSource with uniqueName derby1 and an XAPool of resource derby1 with 10 connection(s) (9 still available) c2 = ds2.getConnection() 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - acquiring connection from a PoolingDataSource with uniqueName derby2 and an XAPool of resource derby2 with 10 connection(s) (10 still available) 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - trying to recycle a NOT_ACCESSIBLE connection of an XAPool of resource derby2 with 10 connection(s) (10 still available) 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - current transaction GTRID is [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000] 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - no NOT_ACCESSIBLE connection enlisted in this transaction 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - getting a IN_POOL connection from an XAPool of resource derby2 with 10 connection(s) (10 still available) 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - waiting for IN_POOL connections count to be > 0, currently is 10 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - found IN_POOL connection a JdbcPooledConnection from datasource derby2 in state IN_POOL wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) from an XAPool of resource derby2 with 10 connection(s) (10 still available) 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - getting connection handle from a JdbcPooledConnection from datasource derby2 in state IN_POOL wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - state changing from IN_POOL to ACCESSIBLE in a JdbcPooledConnection from datasource derby2 in state IN_POOL wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - notifying 2 stateChangeEventListener(s) about state change from IN_POOL to ACCESSIBLE in a JdbcPooledConnection from datasource derby2 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - no query to test connection of a JdbcPooledConnection from datasource derby2 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) , skipping test 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - got connection handle from a JdbcPooledConnection from datasource derby2 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - acquired connection from a PoolingDataSource with uniqueName derby2 and an XAPool of resource derby2 with 10 connection(s) (9 still available) c1.prepareStatement() 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - enlisting a JdbcPooledConnection from datasource derby1 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) into a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=ACTIVE, 0 resource(s) enlisted 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - enlisting resource an XAResourceHolderState with uniqueName=derby1 XAResource=org.apache.derby.jdbc.EmbedXAResource@1e67e6a with XID null into a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=ACTIVE, 0 resource(s) enlisted 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - XAResource org.apache.derby.jdbc.EmbedXAResource@1e67e6a belongs to a JdbcPooledConnection from datasource derby1 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) that itself belongs to a PoolingDataSource with uniqueName derby1 and an XAPool of resource derby1 with 10 connection(s) (9 still available) 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - creating new branch with a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A8500000002] 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - assigning <a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A8500000002]> to <an XAResourceHolderState with uniqueName=derby1 XAResource=org.apache.derby.jdbc.EmbedXAResource@1e67e6a with XID null> 2007-07-13 20:03:49,765 [pool-1-thread-1] DEBUG - starting an XAResourceHolderState with uniqueName=derby1 XAResource=org.apache.derby.jdbc.EmbedXAResource@1e67e6a with XID a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A8500000002] c2.prepareStatement() 2007-07-13 20:03:50,187 [pool-1-thread-1] DEBUG - enlisting a JdbcPooledConnection from datasource derby2 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) into a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=ACTIVE, 1 resource(s) enlisted 2007-07-13 20:03:50,187 [pool-1-thread-1] DEBUG - enlisting resource an XAResourceHolderState with uniqueName=derby2 XAResource=org.apache.derby.jdbc.EmbedXAResource@19ecd80 with XID null into a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=ACTIVE, 1 resource(s) enlisted 2007-07-13 20:03:50,187 [pool-1-thread-1] DEBUG - XAResource org.apache.derby.jdbc.EmbedXAResource@19ecd80 does not belong to any resource of a PoolingDataSource with uniqueName derby1 and an XAPool of resource derby1 with 10 connection(s) (9 still available) 2007-07-13 20:03:50,187 [pool-1-thread-1] DEBUG - XAResource org.apache.derby.jdbc.EmbedXAResource@19ecd80 belongs to a JdbcPooledConnection from datasource derby2 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) that itself belongs to a PoolingDataSource with uniqueName derby2 and an XAPool of resource derby2 with 10 connection(s) (9 still available) 2007-07-13 20:03:50,187 [pool-1-thread-1] DEBUG - creating new branch with a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03C2B00000003] 2007-07-13 20:03:50,187 [pool-1-thread-1] DEBUG - assigning <a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03C2B00000003]> to <an XAResourceHolderState with uniqueName=derby2 XAResource=org.apache.derby.jdbc.EmbedXAResource@19ecd80 with XID null> 2007-07-13 20:03:50,187 [pool-1-thread-1] DEBUG - starting an XAResourceHolderState with uniqueName=derby2 XAResource=org.apache.derby.jdbc.EmbedXAResource@19ecd80 with XID a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03C2B00000003] c1.close() 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - closing a JdbcConnectionHandle of a JdbcPooledConnection from datasource derby1 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) on org.apache.derby.iapi.jdbc.BrokeredConnection40@21720045, Wrapped Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - releasing to pool a JdbcPooledConnection from datasource derby1 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - delisting a JdbcPooledConnection from datasource derby1 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) from a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=ACTIVE, 2 resource(s) enlisted 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - current transaction GTRID is [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000] 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - resource GTRID is [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000] 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - resource is in enlisting global transaction context: a JdbcPooledConnection from datasource derby1 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - requeuing a JdbcPooledConnection from datasource derby1 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) from a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=ACTIVE, 2 resource(s) enlisted 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - current transaction GTRID is [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000] 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - resource GTRID is [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000] 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - resource is in enlisting global transaction context: a JdbcPooledConnection from datasource derby1 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - deferring release to pool of a JdbcPooledConnection from datasource derby1 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - state changing from ACCESSIBLE to NOT_ACCESSIBLE in a JdbcPooledConnection from datasource derby1 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - notifying 2 stateChangeEventListener(s) about state change from ACCESSIBLE to NOT_ACCESSIBLE in a JdbcPooledConnection from datasource derby1 in state NOT_ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - a JdbcPooledConnection from datasource derby1 in state NOT_ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) is not already registered for deferred release in a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=ACTIVE, 2 resource(s) enlisted 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - registering deferred release synchronization for a JdbcPooledConnection from datasource derby1 in state NOT_ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - released to pool a JdbcPooledConnection from datasource derby1 in state NOT_ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) c2.close() 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - closing a JdbcConnectionHandle of a JdbcPooledConnection from datasource derby2 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) on org.apache.derby.iapi.jdbc.BrokeredConnection40@20870565, Wrapped Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - releasing to pool a JdbcPooledConnection from datasource derby2 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - delisting a JdbcPooledConnection from datasource derby2 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) from a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=ACTIVE, 2 resource(s) enlisted 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - current transaction GTRID is [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000] 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - resource GTRID is [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000] 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - resource is in enlisting global transaction context: a JdbcPooledConnection from datasource derby2 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - requeuing a JdbcPooledConnection from datasource derby2 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) from a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=ACTIVE, 2 resource(s) enlisted 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - current transaction GTRID is [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000] 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - resource GTRID is [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000] 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - resource is in enlisting global transaction context: a JdbcPooledConnection from datasource derby2 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - deferring release to pool of a JdbcPooledConnection from datasource derby2 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - state changing from ACCESSIBLE to NOT_ACCESSIBLE in a JdbcPooledConnection from datasource derby2 in state ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - notifying 2 stateChangeEventListener(s) about state change from ACCESSIBLE to NOT_ACCESSIBLE in a JdbcPooledConnection from datasource derby2 in state NOT_ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - a JdbcPooledConnection from datasource derby2 in state NOT_ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) is not already registered for deferred release in a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=ACTIVE, 2 resource(s) enlisted 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - registering deferred release synchronization for a JdbcPooledConnection from datasource derby2 in state NOT_ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - released to pool a JdbcPooledConnection from datasource derby2 in state NOT_ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) tm.commit() 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - committing transaction a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=ACTIVE, 2 resource(s) enlisted 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - before completion, 2 synchronization(s) to execute beforeCompletion() 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - executing synchronization a DeferredReleaseSynchronization of a JdbcPooledConnection from datasource derby1 in state NOT_ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - executing synchronization a DeferredReleaseSynchronization of a JdbcPooledConnection from datasource derby2 in state NOT_ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) delistment 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - found unclosed resource an XAResourceHolderState with uniqueName=derby1 XAResource=org.apache.derby.jdbc.EmbedXAResource@1e67e6a (started) with XID a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A8500000002] 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - XAResource org.apache.derby.jdbc.EmbedXAResource@1e67e6a belongs to a JdbcPooledConnection from datasource derby1 in state NOT_ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) that itself belongs to a PoolingDataSource with uniqueName derby1 and an XAPool of resource derby1 with 10 connection(s) (9 still available) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - delisting resource an XAResourceHolderState with uniqueName=derby1 XAResource=org.apache.derby.jdbc.EmbedXAResource@1e67e6a (started) with XID a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A8500000002] 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - ending an XAResourceHolderState with uniqueName=derby1 XAResource=org.apache.derby.jdbc.EmbedXAResource@1e67e6a (started) with XID a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A8500000002] 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - found unclosed resource an XAResourceHolderState with uniqueName=derby2 XAResource=org.apache.derby.jdbc.EmbedXAResource@19ecd80 (started) with XID a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03C2B00000003] 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - XAResource org.apache.derby.jdbc.EmbedXAResource@19ecd80 does not belong to any resource of a PoolingDataSource with uniqueName derby1 and an XAPool of resource derby1 with 10 connection(s) (9 still available) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - XAResource org.apache.derby.jdbc.EmbedXAResource@19ecd80 belongs to a JdbcPooledConnection from datasource derby2 in state NOT_ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) that itself belongs to a PoolingDataSource with uniqueName derby2 and an XAPool of resource derby2 with 10 connection(s) (9 still available) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - delisting resource an XAResourceHolderState with uniqueName=derby2 XAResource=org.apache.derby.jdbc.EmbedXAResource@19ecd80 (started) with XID a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03C2B00000003] 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - ending an XAResourceHolderState with uniqueName=derby2 XAResource=org.apache.derby.jdbc.EmbedXAResource@19ecd80 (started) with XID a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03C2B00000003] phase 1 prepare 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - committing, 2 enlisted resource(s) 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - changing transaction status to PREPARING 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - writing a Bitronix TransactionLogRecord with status=PREPARING, recordLength=79, headerLength=28, time=1184349830234, sequenceNumber=4, crc32=-437983951, gtrid=737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000, uniqueNames=derby1,derby2 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - disk journal appender now at position 179 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - 2 resource(s) enlisted, preparing 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - preparing resource an XAResourceHolderState with uniqueName=derby1 XAResource=org.apache.derby.jdbc.EmbedXAResource@1e67e6a (ended) with XID a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A8500000002] 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - prepared resource an XAResourceHolderState with uniqueName=derby1 XAResource=org.apache.derby.jdbc.EmbedXAResource@1e67e6a (ended) with XID a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A8500000002] voted XA_OK 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - preparing resource an XAResourceHolderState with uniqueName=derby2 XAResource=org.apache.derby.jdbc.EmbedXAResource@19ecd80 (ended) with XID a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03C2B00000003] 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - prepared resource an XAResourceHolderState with uniqueName=derby2 XAResource=org.apache.derby.jdbc.EmbedXAResource@19ecd80 (ended) with XID a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03C2B00000003] voted XA_OK 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - changing transaction status to PREPARED 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - writing a Bitronix TransactionLogRecord with status=PREPARED, recordLength=79, headerLength=28, time=1184349830234, sequenceNumber=5, crc32=868568212, gtrid=737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000, uniqueNames=derby1,derby2 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - disk journal appender now at position 266 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - successfully prepared 2 resource(s) phase 2 commit 2007-07-13 20:03:50,234 [pool-1-thread-1] DEBUG - 2 interested resource(s) 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - changing transaction status to COMMITTING (forced) 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - writing a Bitronix TransactionLogRecord with status=COMMITTING, recordLength=79, headerLength=28, time=1184349830250, sequenceNumber=6, crc32=807001703, gtrid=737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000, uniqueNames=derby1,derby2 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - disk journal appender now at position 353 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - enqueued a TransactionLogAppender on btm1.tlog, 1 TransactionLogAppender waiting for a disk force 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - batching disk force, there are 1 TransactionLogAppender in the wait queue 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - waiting for a TransactionLogAppender on btm1.tlog to get dequeued 2007-07-13 20:03:50,250 [bitronix-disk-force-batcher] DEBUG - wait queue is not empty anymore (1 in queue) 2007-07-13 20:03:50,250 [bitronix-disk-force-batcher] DEBUG - forcing... 2007-07-13 20:03:50,250 [bitronix-disk-force-batcher] DEBUG - returning head TransactionLogAppender 2007-07-13 20:03:50,250 [bitronix-disk-force-batcher] DEBUG - forcing log writing 2007-07-13 20:03:50,250 [bitronix-disk-force-batcher] DEBUG - done forcing log 2007-07-13 20:03:50,250 [bitronix-disk-force-batcher] DEBUG - clearing list of waiting TransactionLogAppender 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - wait queue got emptied, disk force is done 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - executing commit phase, 2 interested resource(s) 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - committing resource an XAResourceHolderState with uniqueName=derby1 XAResource=org.apache.derby.jdbc.EmbedXAResource@1e67e6a (ended) with XID a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A8500000002] 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - onePhase commit ? false 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - committed resource an XAResourceHolderState with uniqueName=derby1 XAResource=org.apache.derby.jdbc.EmbedXAResource@1e67e6a (ended) with XID a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A8500000002] 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - committing resource an XAResourceHolderState with uniqueName=derby2 XAResource=org.apache.derby.jdbc.EmbedXAResource@19ecd80 (ended) with XID a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03C2B00000003] 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - onePhase commit ? false 2007-07-13 20:03:50,250 [bitronix-disk-force-batcher] DEBUG - waiting for the wait queue to fill up 2007-07-13 20:03:50,250 [bitronix-disk-force-batcher] DEBUG - waiting for some TransactionLogAppender to get enqueued 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - committed resource an XAResourceHolderState with uniqueName=derby2 XAResource=org.apache.derby.jdbc.EmbedXAResource@19ecd80 (ended) with XID a Bitronix XID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000 : 737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03C2B00000003] 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - changing transaction status to COMMITTED 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - writing a Bitronix TransactionLogRecord with status=COMMITTED, recordLength=79, headerLength=28, time=1184349830250, sequenceNumber=7, crc32=-1224281554, gtrid=737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000, uniqueNames=derby1,derby2 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - disk journal appender now at position 440 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - successfully committed a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=COMMITTED, 2 resource(s) enlisted afterCompletion 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - after completion, 2 synchronization(s) to execute release connections to pool 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - executing synchronization a DeferredReleaseSynchronization of a JdbcPooledConnection from datasource derby1 in state NOT_ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) with status=COMMITTED 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - DeferredReleaseSynchronization requeuing a JdbcPooledConnection from datasource derby1 in state NOT_ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - state changing from NOT_ACCESSIBLE to IN_POOL in a JdbcPooledConnection from datasource derby1 in state NOT_ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - notifying 2 stateChangeEventListener(s) about state change from NOT_ACCESSIBLE to IN_POOL in a JdbcPooledConnection from datasource derby1 in state IN_POOL wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - a connection's state changed to IN_POOL, notifying a thread eventually waiting for a connection 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - DeferredReleaseSynchronization requeued a JdbcPooledConnection from datasource derby1 in state IN_POOL wrapping org.apache.derby.jdbc.EmbedXAConnection@20712275 (ID = 0), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@17298525 (XID = 131), (SESSIONID = 1), (DATABASE = users1), (DRDAID = null) 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - executing synchronization a DeferredReleaseSynchronization of a JdbcPooledConnection from datasource derby2 in state NOT_ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) with status=COMMITTED 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - DeferredReleaseSynchronization requeuing a JdbcPooledConnection from datasource derby2 in state NOT_ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - state changing from NOT_ACCESSIBLE to IN_POOL in a JdbcPooledConnection from datasource derby2 in state NOT_ACCESSIBLE wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - notifying 2 stateChangeEventListener(s) about state change from NOT_ACCESSIBLE to IN_POOL in a JdbcPooledConnection from datasource derby2 in state IN_POOL wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - a connection's state changed to IN_POOL, notifying a thread eventually waiting for a connection 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - DeferredReleaseSynchronization requeued a JdbcPooledConnection from datasource derby2 in state IN_POOL wrapping org.apache.derby.jdbc.EmbedXAConnection@27096558 (ID = 10), Physical Connection = org.apache.derby.impl.jdbc.EmbedConnection40@33402317 (XID = 131), (SESSIONID = 1), (DATABASE = users2), (DRDAID = null) cleanup 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - clearing current thread context: a ThreadContext with transaction a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=COMMITTED, 2 resource(s) enlisted, default timeout 60s 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - unregistering in-flight transaction a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=COMMITTED, 2 resource(s) enlisted 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - cancelling transaction timeout task on a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=COMMITTED, 2 resource(s) enlisted 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - cancelled a TransactionTimeoutTask on a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=COMMITTED, 2 resource(s) enlisted scheduled for Fri Jul 13 20:04:49 CEST 2007, total task(s) still queued: 0 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - clearing a ThreadContext with transaction a Bitronix Transaction with GTRID [737072696E672D62746D2D6A6462632D73616D706C6500000113C0C03A7600000000], status=COMMITTED, 2 resource(s) enlisted, default timeout 60s 2007-07-13 20:03:50,250 [pool-1-thread-1] DEBUG - cleared current thread context: a ThreadContext with transaction null, default timeout 60s all done !  |