Restore | Raw | History | First | Previous | Next | Last | Close

Debug Logging

With 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 !
spacer
Copyright © 2014 Atomikos BVBA. Transaction Management for Extreme Transaction Processing and SOA Environments serving ISV, Commercial, OEM and Open Source Markets
Site map RSS ATOM