5 Replies Latest reply on Oct 9, 2012 12:21 PM by jsightler

JTA, Hibernate Session Open Count

sage84 Sep 3, 2012 12:38 PM

Hello,

I am using Jboss 7.1.1 Final, XA-Datasource with Oracle 10g, JPA with JTA and Hibernate.

The Application does not use any User Transactions or a manually created EntityManager.

Under heavy load I always experienced resource problems, so I activated hibernate statistics in persistence.xml.

This is what my session statistics look like after a few minutes processing 10000 messages from a queue.

Session Open Count:	250003
Sesison Close Count:	6454	3%
Connection Count:	6424

How can it be that the session open count is that high and they are not closes? I don't think this is normal behavior???

Please help me guys, the application is finished and I can not release because of this problem

This is the log output with all debug loggers enabled:

18:35:43,678 INFO [at.dimoco.payperiodic.ejb.TransactionTest] (http-127.0.0.1-127.0.0.1-8080-1) test called...

18:35:43,727 INFO [at.dimoco.payperiodic.ejb.jms.CaptureFillerMessageConsumer] (Thread-2 (HornetQ-client-global-threads-1169382875)) Received message with subscriptionId: 1

18:35:43,728 INFO [at.dimoco.payperiodic.ejb.data.SubscriptionFacade] (Thread-2 (HornetQ-client-global-threads-1169382875)) getSubscription 1

18:35:43,729 DEBUG [org.hibernate.internal.SessionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Opened session at timestamp: 13466901437

18:35:43,730 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Skipping JTA sync registration due to auto join checking

18:35:43,731 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) successfully registered Synchronization

18:35:43,733 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Looking for a JTA transaction to join

18:35:43,734 DEBUG [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) Thread-2 (HornetQ-client-global-threads-1169382875):[transaction scoped EntityManager]: created entity manager session TransactionImple < ac, BasicAction: 0:ffffc0a81944:712186c4:5044dc4a:27 status: ActionStatus.RUNNING >

18:35:43,737 TRACE [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) createQuery resultClass 'at.dimoco.payperiodic.ejb.model.Subscription' took 8ms

18:35:43,739 TRACE [org.jboss.as.jpa] (http-127.0.0.1-127.0.0.1-8080-1) pu search for name 'periodic' inside of payperiodic-ejb.jar

18:35:43,740 TRACE [org.jboss.as.jpa] (http-127.0.0.1-127.0.0.1-8080-1) findWithinDeployment check 'periodic' against pu 'periodic_msg'

18:35:43,741 TRACE [org.jboss.as.jpa] (http-127.0.0.1-127.0.0.1-8080-1) findWithinDeployment check 'periodic' against pu 'periodic'

18:35:43,742 TRACE [org.jboss.as.jpa] (http-127.0.0.1-127.0.0.1-8080-1) findWithinDeployment matched 'periodic' against pu 'periodic'

18:35:43,743 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtaining JDBC connection

18:35:43,743 TRACE [org.jboss.as.jpa] (http-127.0.0.1-127.0.0.1-8080-1) pu search found payperiodic-ear.ear/payperiodic-ejb.jar#periodic

18:35:43,747 DEBUG [org.hibernate.internal.SessionImpl] (http-127.0.0.1-127.0.0.1-8080-1) Opened session at timestamp: 13466901437

18:35:43,747 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (http-127.0.0.1-127.0.0.1-8080-1) Skipping JTA sync registration due to auto join checking

18:35:43,749 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (http-127.0.0.1-127.0.0.1-8080-1) successfully registered Synchronization

18:35:43,750 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] (http-127.0.0.1-127.0.0.1-8080-1) Looking for a JTA transaction to join

18:35:43,752 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtained JDBC connection

18:35:43,752 DEBUG [org.jboss.as.jpa] (http-127.0.0.1-127.0.0.1-8080-1) http-127.0.0.1-127.0.0.1-8080-1:[transaction scoped EntityManager]: created entity manager session TransactionImple < ac, BasicAction: 0:ffffc0a81944:712186c4:5044dc4a:2b status: ActionStatus.RUNNING >

18:35:43,753 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) select * from ( select subscripti0_.id as id11_, subscripti0_.closed as closed11_, subscripti0_.config_set as config3_11_, subscripti0_.failure as failure11_, subscripti0_.import_date as import5_11_, subscripti0_.in_progress as in6_11_, subscripti0_.last_update as last7_11_, subscripti0_.max_retry as max8_11_, subscripti0_.next_capture_fill as next9_11_, subscripti0_.retry_counter as retry10_11_, subscripti0_.retry_lifecycle as retry11_11_, subscripti0_.retry_start as retry12_11_, subscripti0_.subscription_id as subscri13_11_ from subscription subscripti0_ where subscripti0_.subscription_id=? ) where rownum <= ? for update

18:35:43,754 TRACE [org.jboss.as.jpa] (http-127.0.0.1-127.0.0.1-8080-1) getDelegate took 8ms

18:35:43,759 INFO [at.dimoco.payperiodic.ejb.util.HibernateUtils] (http-127.0.0.1-127.0.0.1-8080-1) Session Open Count: 4

18:35:43,759 INFO [at.dimoco.payperiodic.ejb.util.HibernateUtils] (http-127.0.0.1-127.0.0.1-8080-1) Session Close Count: 2

18:35:43,760 DEBUG [org.jboss.as.jpa] (http-127.0.0.1-127.0.0.1-8080-1) http-127.0.0.1-127.0.0.1-8080-1:[transaction scoped EntityManager]: closing entity managersession

18:35:43,762 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (http-127.0.0.1-127.0.0.1-8080-1) Aggressively releasing JDBC connection

18:35:43,762 DEBUG [org.hibernate.loader.Loader] (Thread-2 (HornetQ-client-global-threads-1169382875)) Result set row: 0

18:35:43,763 DEBUG [org.hibernate.loader.Loader] (Thread-2 (HornetQ-client-global-threads-1169382875)) Result row: EntityKey[at.dimoco.payperiodic.ejb.model.Subscription#1]

18:35:43,773 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Releasing JDBC connection

18:35:43,779 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Released JDBC connection

18:35:43,780 DEBUG [org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler] (Thread-2 (HornetQ-client-global-threads-1169382875)) HHH000163: Logical connection releasing its physical connection

18:35:43,782 DEBUG [org.hibernate.engine.internal.TwoPhaseLoad] (Thread-2 (HornetQ-client-global-threads-1169382875)) Resolving associations for [at.dimoco.payperiodic.ejb.model.Subscription#1]

18:35:43,784 DEBUG [org.hibernate.engine.internal.TwoPhaseLoad] (Thread-2 (HornetQ-client-global-threads-1169382875)) Done materializing entity [at.dimoco.payperiodic.ejb.model.Subscription#1]

18:35:43,786 DEBUG [org.hibernate.engine.internal.StatefulPersistenceContext] (Thread-2 (HornetQ-client-global-threads-1169382875)) Initializing non-lazy collections

18:35:43,787 DEBUG [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) HHH000117: HQL: FROM Subscription WHERE subscriptionId = :subscriptionId, time: 48ms, rows: 1

18:35:43,789 INFO [at.dimoco.payperiodic.ejb.data.SubscriptionFacade] (Thread-2 (HornetQ-client-global-threads-1169382875)) getSubscription 1

18:35:43,790 DEBUG [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) Thread-2 (HornetQ-client-global-threads-1169382875):[transaction scoped EntityManager]: reuse entity manager session already in tx TransactionImple < ac, BasicAction: 0:ffffc0a81944:712186c4:5044dc4a:27 status: ActionStatus.RUNNING >

18:35:43,792 TRACE [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) createQuery resultClass 'at.dimoco.payperiodic.ejb.model.Subscription' took 2ms

18:35:43,794 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Processing flush-time cascades

18:35:43,795 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Dirty checking collections

18:35:43,796 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects

18:35:43,798 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections

18:35:43,801 DEBUG [org.hibernate.internal.util.EntityPrinter] (Thread-2 (HornetQ-client-global-threads-1169382875)) Listing entities:

18:35:43,807 DEBUG [org.hibernate.internal.util.EntityPrinter] (Thread-2 (HornetQ-client-global-threads-1169382875)) at.dimoco.payperiodic.ejb.model.Subscription{nextCaptureFill=2012-09-17 13:15:00.935, lastUpdate=2012-09-03 16:12:01.042, inProgress=false, retryCounter=0, subscriptionId=1, retryLifecycle=0, id=1, failure=0, configSet={"configMap":{"REPORTING_URL":"http://localhost:8080/payperiodic/test/callbackServlet","CAPTURE_VALIDITY_LENGTH":"2","HAS_BILLING_LIMIT":"0","PERIOD_FILL_LENGTH":"3","RETRY_INTERVAL_DIVISOR":"2","MAX_RETRY_LIFECYCLE":"60","EARLIEST_HOUR":"8","MAX_FAILED_CAPTURES":"20","LATEST_HOUR":"16","CHARGINGS_PER_DAY":"5","RENEWAL_MODE":"REGULAR"}}, maxRetry=20, retryStart=null, importDate=2012-09-03 18:11:53.0, closed=false}

18:35:43,813 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtaining JDBC connection

18:35:43,814 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtained JDBC connection

18:35:43,816 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) select * from ( select subscripti0_.id as id11_, subscripti0_.closed as closed11_, subscripti0_.config_set as config3_11_, subscripti0_.failure as failure11_, subscripti0_.import_date as import5_11_, subscripti0_.in_progress as in6_11_, subscripti0_.last_update as last7_11_, subscripti0_.max_retry as max8_11_, subscripti0_.next_capture_fill as next9_11_, subscripti0_.retry_counter as retry10_11_, subscripti0_.retry_lifecycle as retry11_11_, subscripti0_.retry_start as retry12_11_, subscripti0_.subscription_id as subscri13_11_ from subscription subscripti0_ where subscripti0_.subscription_id=? ) where rownum <= ? for update

18:35:43,825 DEBUG [org.hibernate.loader.Loader] (Thread-2 (HornetQ-client-global-threads-1169382875)) Result set row: 0

18:35:43,826 DEBUG [org.hibernate.loader.Loader] (Thread-2 (HornetQ-client-global-threads-1169382875)) Result row: EntityKey[at.dimoco.payperiodic.ejb.model.Subscription#1]

18:35:43,828 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Releasing JDBC connection

18:35:43,829 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Released JDBC connection

18:35:43,830 DEBUG [org.hibernate.engine.internal.StatefulPersistenceContext] (Thread-2 (HornetQ-client-global-threads-1169382875)) Initializing non-lazy collections

18:35:43,831 DEBUG [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) HHH000117: HQL: FROM Subscription WHERE subscriptionId = :subscriptionId, time: 19ms, rows: 1

18:35:43,835 INFO [at.dimoco.payperiodic.ejb.data.SubscriptionFacade] (Thread-2 (HornetQ-client-global-threads-1169382875)) getSubscription 1

18:35:43,835 DEBUG [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) Thread-2 (HornetQ-client-global-threads-1169382875):[transaction scoped EntityManager]: reuse entity manager session already in tx TransactionImple < ac, BasicAction: 0:ffffc0a81944:712186c4:5044dc4a:27 status: ActionStatus.RUNNING >

18:35:43,837 TRACE [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) createQuery resultClass 'at.dimoco.payperiodic.ejb.model.Subscription' took 2ms

18:35:43,838 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Processing flush-time cascades

18:35:43,839 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Dirty checking collections

18:35:43,840 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects

18:35:43,842 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections

18:35:43,843 DEBUG [org.hibernate.internal.util.EntityPrinter] (Thread-2 (HornetQ-client-global-threads-1169382875)) Listing entities:

18:35:43,843 DEBUG [org.hibernate.internal.util.EntityPrinter] (Thread-2 (HornetQ-client-global-threads-1169382875)) at.dimoco.payperiodic.ejb.model.Subscription{nextCaptureFill=2012-09-17 13:15:00.935, lastUpdate=2012-09-03 16:12:01.042, inProgress=false, retryCounter=0, subscriptionId=1, retryLifecycle=0, id=1, failure=0, configSet={"configMap":{"REPORTING_URL":"http://localhost:8080/payperiodic/test/callbackServlet","CAPTURE_VALIDITY_LENGTH":"2","HAS_BILLING_LIMIT":"0","PERIOD_FILL_LENGTH":"3","RETRY_INTERVAL_DIVISOR":"2","MAX_RETRY_LIFECYCLE":"60","EARLIEST_HOUR":"8","MAX_FAILED_CAPTURES":"20","LATEST_HOUR":"16","CHARGINGS_PER_DAY":"5","RENEWAL_MODE":"REGULAR"}}, maxRetry=20, retryStart=null, importDate=2012-09-03 18:11:53.0, closed=false}

18:35:43,848 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtaining JDBC connection

18:35:43,850 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtained JDBC connection

18:35:43,852 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) select * from ( select subscripti0_.id as id11_, subscripti0_.closed as closed11_, subscripti0_.config_set as config3_11_, subscripti0_.failure as failure11_, subscripti0_.import_date as import5_11_, subscripti0_.in_progress as in6_11_, subscripti0_.last_update as last7_11_, subscripti0_.max_retry as max8_11_, subscripti0_.next_capture_fill as next9_11_, subscripti0_.retry_counter as retry10_11_, subscripti0_.retry_lifecycle as retry11_11_, subscripti0_.retry_start as retry12_11_, subscripti0_.subscription_id as subscri13_11_ from subscription subscripti0_ where subscripti0_.subscription_id=? ) where rownum <= ? for update

18:35:43,858 DEBUG [org.hibernate.loader.Loader] (Thread-2 (HornetQ-client-global-threads-1169382875)) Result set row: 0

18:35:43,859 DEBUG [org.hibernate.loader.Loader] (Thread-2 (HornetQ-client-global-threads-1169382875)) Result row: EntityKey[at.dimoco.payperiodic.ejb.model.Subscription#1]

18:35:43,860 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Releasing JDBC connection

18:35:43,861 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Released JDBC connection

18:35:43,862 DEBUG [org.hibernate.engine.internal.StatefulPersistenceContext] (Thread-2 (HornetQ-client-global-threads-1169382875)) Initializing non-lazy collections

18:35:43,862 DEBUG [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) HHH000117: HQL: FROM Subscription WHERE subscriptionId = :subscriptionId, time: 14ms, rows: 1

18:35:43,863 INFO [at.dimoco.payperiodic.ejb.data.SubscriptionFacade] (Thread-2 (HornetQ-client-global-threads-1169382875)) getSubscription 1

18:35:43,864 DEBUG [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) Thread-2 (HornetQ-client-global-threads-1169382875):[transaction scoped EntityManager]: reuse entity manager session already in tx TransactionImple < ac, BasicAction: 0:ffffc0a81944:712186c4:5044dc4a:27 status: ActionStatus.RUNNING >

18:35:43,867 TRACE [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) createQuery resultClass 'at.dimoco.payperiodic.ejb.model.Subscription' took 3ms

18:35:43,869 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Processing flush-time cascades

18:35:43,870 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Dirty checking collections

18:35:43,871 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects

18:35:43,872 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections

18:35:43,874 DEBUG [org.hibernate.internal.util.EntityPrinter] (Thread-2 (HornetQ-client-global-threads-1169382875)) Listing entities:

18:35:43,875 DEBUG [org.hibernate.internal.util.EntityPrinter] (Thread-2 (HornetQ-client-global-threads-1169382875)) at.dimoco.payperiodic.ejb.model.Subscription{nextCaptureFill=2012-09-17 13:15:00.935, lastUpdate=2012-09-03 16:12:01.042, inProgress=false, retryCounter=0, subscriptionId=1, retryLifecycle=0, id=1, failure=0, configSet={"configMap":{"REPORTING_URL":"http://localhost:8080/payperiodic/test/callbackServlet","CAPTURE_VALIDITY_LENGTH":"2","HAS_BILLING_LIMIT":"0","PERIOD_FILL_LENGTH":"3","RETRY_INTERVAL_DIVISOR":"2","MAX_RETRY_LIFECYCLE":"60","EARLIEST_HOUR":"8","MAX_FAILED_CAPTURES":"20","LATEST_HOUR":"16","CHARGINGS_PER_DAY":"5","RENEWAL_MODE":"REGULAR"}}, maxRetry=20, retryStart=null, importDate=2012-09-03 18:11:53.0, closed=false}

18:35:43,878 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtaining JDBC connection

18:35:43,879 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtained JDBC connection

18:35:43,880 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) select * from ( select subscripti0_.id as id11_, subscripti0_.closed as closed11_, subscripti0_.config_set as config3_11_, subscripti0_.failure as failure11_, subscripti0_.import_date as import5_11_, subscripti0_.in_progress as in6_11_, subscripti0_.last_update as last7_11_, subscripti0_.max_retry as max8_11_, subscripti0_.next_capture_fill as next9_11_, subscripti0_.retry_counter as retry10_11_, subscripti0_.retry_lifecycle as retry11_11_, subscripti0_.retry_start as retry12_11_, subscripti0_.subscription_id as subscri13_11_ from subscription subscripti0_ where subscripti0_.subscription_id=? ) where rownum <= ? for update

18:35:43,887 DEBUG [org.hibernate.loader.Loader] (Thread-2 (HornetQ-client-global-threads-1169382875)) Result set row: 0

18:35:43,888 DEBUG [org.hibernate.loader.Loader] (Thread-2 (HornetQ-client-global-threads-1169382875)) Result row: EntityKey[at.dimoco.payperiodic.ejb.model.Subscription#1]

18:35:43,889 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Releasing JDBC connection

18:35:43,890 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Released JDBC connection

18:35:43,890 DEBUG [org.hibernate.engine.internal.StatefulPersistenceContext] (Thread-2 (HornetQ-client-global-threads-1169382875)) Initializing non-lazy collections

18:35:43,891 DEBUG [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) HHH000117: HQL: FROM Subscription WHERE subscriptionId = :subscriptionId, time: 13ms, rows: 1

18:35:43,897 DEBUG [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) created new TransactionScopedEntityManager for unit name=payperiodic-ear.ear/payperiodic-ejb.jar#periodic_msg

18:35:43,898 WARN [at.dimoco.payperiodic.ejb.data.SubscriptionDataFacade] (Thread-2 (HornetQ-client-global-threads-1169382875)) Return Demo SubscriptionData for SubscriptionId=1

18:35:43,902 DEBUG [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) created new TransactionScopedEntityManager for unit name=payperiodic-ear.ear/payperiodic-ejb.jar#periodic_msg

18:35:43,904 DEBUG [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) created new TransactionScopedEntityManager for unit name=payperiodic-ear.ear/payperiodic-ejb.jar#periodic

18:35:43,906 INFO [at.dimoco.payperiodic.ejb.data.MerchantFacade] (Thread-2 (HornetQ-client-global-threads-1169382875)) Get Merchant with ID[556] from PSS.

18:35:43,906 DEBUG [org.hibernate.internal.SessionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Opened session at timestamp: 13466901439

18:35:43,907 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Skipping JTA sync registration due to auto join checking

18:35:43,909 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) successfully registered Synchronization

18:35:43,910 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Looking for a JTA transaction to join

18:35:43,911 DEBUG [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) Thread-2 (HornetQ-client-global-threads-1169382875):[transaction scoped EntityManager]: created entity manager session TransactionImple < ac, BasicAction: 0:ffffc0a81944:712186c4:5044dc4a:27 status: ActionStatus.RUNNING >

18:35:43,914 DEBUG [org.hibernate.hql.internal.ast.QueryTranslatorImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) parse() - HQL: FROM at.dimoco.payperiodic.ejb.model.Merchant WHERE merchantId = :merchantId

18:35:43,917 DEBUG [org.hibernate.hql.internal.ast.QueryTranslatorImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) --- HQL AST ---

\-[QUERY] Node: 'query'

+-[SELECT_FROM] Node: 'SELECT_FROM'

| \-[FROM] Node: 'FROM'

| \-[RANGE] Node: 'RANGE'

| \-[DOT] Node: '.'

| +-[DOT] Node: '.'

| | +-[DOT] Node: '.'

| | | +-[DOT] Node: '.'

| | | | +-[DOT] Node: '.'

| | | | \-[IDENT] Node: 'payperiodic'

| | | \-[IDENT] Node: 'ejb'

| | \-[IDENT] Node: 'model'

| \-[IDENT] Node: 'Merchant'

\-[WHERE] Node: 'WHERE'

\-[EQ] Node: '='

+-[IDENT] Node: 'merchantId'

\-[COLON] Node: ':'

\-[IDENT] Node: 'merchantId'

18:35:43,923 DEBUG [org.hibernate.hql.internal.ast.ErrorCounter] (Thread-2 (HornetQ-client-global-threads-1169382875)) throwQueryException() : no errors

18:35:43,924 DEBUG [org.hibernate.hql.internal.antlr.HqlSqlBaseWalker] (Thread-2 (HornetQ-client-global-threads-1169382875)) select << begin [level=1, statement=select]

18:35:43,926 DEBUG [org.hibernate.hql.internal.ast.tree.FromElement] (Thread-2 (HornetQ-client-global-threads-1169382875)) FromClause{level=1} : at.dimoco.payperiodic.ejb.model.Merchant (<no alias>) -> merchant0_

18:35:43,928 DEBUG [org.hibernate.hql.internal.ast.tree.FromReferenceNode] (Thread-2 (HornetQ-client-global-threads-1169382875)) Resolved : {synthetic-alias} -> {synthetic-alias}

18:35:43,929 DEBUG [org.hibernate.hql.internal.ast.tree.DotNode] (Thread-2 (HornetQ-client-global-threads-1169382875)) getDataType() : merchantId -> org.hibernate.type.StringType@dbef6cd

18:35:43,930 DEBUG [org.hibernate.hql.internal.ast.tree.FromReferenceNode] (Thread-2 (HornetQ-client-global-threads-1169382875)) Resolved : {synthetic-alias}.merchantId -> merchant0_.merchant_id

18:35:43,931 DEBUG [org.hibernate.hql.internal.antlr.HqlSqlBaseWalker] (Thread-2 (HornetQ-client-global-threads-1169382875)) select : finishing up [level=1, statement=select]

18:35:43,932 DEBUG [org.hibernate.hql.internal.ast.HqlSqlWalker] (Thread-2 (HornetQ-client-global-threads-1169382875)) processQuery() : ( SELECT ( FromClause{level=1} ( SELECT * FROM MERCHANT_VIEW ) merchant0_ ) ( WHERE ( = ( merchant0_.merchant_id {synthetic-alias} merchantId ) ? ) ) )

18:35:43,934 DEBUG [org.hibernate.hql.internal.ast.HqlSqlWalker] (Thread-2 (HornetQ-client-global-threads-1169382875)) Derived SELECT clause created.

18:35:43,935 DEBUG [org.hibernate.hql.internal.ast.util.JoinProcessor] (Thread-2 (HornetQ-client-global-threads-1169382875)) Using FROM fragment [( SELECT * FROM MERCHANT_VIEW ) merchant0_]

18:35:43,936 DEBUG [org.hibernate.hql.internal.antlr.HqlSqlBaseWalker] (Thread-2 (HornetQ-client-global-threads-1169382875)) select >> end [level=1, statement=select]

18:35:43,937 DEBUG [org.hibernate.hql.internal.ast.QueryTranslatorImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) --- SQL AST ---

\-[SELECT] QueryNode: 'SELECT' querySpaces (( SELECT * FROM MERCHANT_VIEW ))

+-[SELECT_CLAUSE] SelectClause: '{derived select clause}'

| +-[SELECT_EXPR] SelectExpressionImpl: 'merchant0_.merchant_id as merchant1_3_' {FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=null,role=null,tableName=( SELECT * FROM MERCHANT_VIEW ),tableAlias=merchant0_,origin=null,columns={,className=at.dimoco.payperiodic.ejb.model.Merchant}}}

| \-[SQL_TOKEN] SqlFragment: 'merchant0_.active as active3_, merchant0_.name as name3_, merchant0_.password as password3_'

+-[FROM] FromClause: 'FROM' FromClause{level=1, fromElementCounter=1, fromElements=1, fromElementByClassAlias=[], fromElementByTableAlias=[merchant0_], fromElementsByPath=[], collectionJoinFromElementsByPath=[], impliedElements=[]}

| \-[FROM_FRAGMENT] FromElement: '( SELECT * FROM MERCHANT_VIEW ) merchant0_' FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=null,role=null,tableName=( SELECT * FROM MERCHANT_VIEW ),tableAlias=merchant0_,origin=null,columns={,className=at.dimoco.payperiodic.ejb.model.Merchant}}

\-[WHERE] SqlNode: 'WHERE'

\-[EQ] BinaryLogicOperatorNode: '='

+-[DOT] DotNode: 'merchant0_.merchant_id' {propertyName=merchantId,dereferenceType=ALL,propertyPath=merchantId,path={synthetic-alias}.merchantId,tableAlias=merchant0_,className=at.dimoco.payperiodic.ejb.model.Merchant,classAlias=null}

| +-[IDENT] IdentNode: '{synthetic-alias}' {originalText={synthetic-alias}}

| \-[IDENT] IdentNode: 'merchantId' {originalText=merchantId}

\-[NAMED_PARAM] ParameterNode: '?' {name=merchantId, expectedType=org.hibernate.type.StringType@dbef6cd}

18:35:43,946 DEBUG [org.hibernate.hql.internal.ast.ErrorCounter] (Thread-2 (HornetQ-client-global-threads-1169382875)) throwQueryException() : no errors

18:35:43,947 DEBUG [org.hibernate.hql.internal.ast.QueryTranslatorImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) HQL: FROM at.dimoco.payperiodic.ejb.model.Merchant WHERE merchantId = :merchantId

18:35:43,949 DEBUG [org.hibernate.hql.internal.ast.QueryTranslatorImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) SQL: select merchant0_.merchant_id as merchant1_3_, merchant0_.active as active3_, merchant0_.name as name3_, merchant0_.password as password3_ from ( SELECT * FROM MERCHANT_VIEW ) merchant0_ where merchant0_.merchant_id=?

18:35:43,951 DEBUG [org.hibernate.hql.internal.ast.ErrorCounter] (Thread-2 (HornetQ-client-global-threads-1169382875)) throwQueryException() : no errors

18:35:43,951 TRACE [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) createQuery resultClass 'at.dimoco.payperiodic.ejb.model.Merchant' took 45ms

18:35:43,953 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtaining JDBC connection

18:35:43,969 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtained JDBC connection

18:35:43,970 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) select * from ( select merchant0_.merchant_id as merchant1_3_, merchant0_.active as active3_, merchant0_.name as name3_, merchant0_.password as password3_ from ( SELECT * FROM MERCHANT_VIEW ) merchant0_ where merchant0_.merchant_id=? ) where rownum <= ?

18:35:43,988 DEBUG [org.hibernate.loader.Loader] (Thread-2 (HornetQ-client-global-threads-1169382875)) Result set row: 0

18:35:43,989 DEBUG [org.hibernate.loader.Loader] (Thread-2 (HornetQ-client-global-threads-1169382875)) Result row: EntityKey[at.dimoco.payperiodic.ejb.model.Merchant#556]

18:35:43,990 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Releasing JDBC connection

18:35:43,991 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Released JDBC connection

18:35:43,991 DEBUG [org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler] (Thread-2 (HornetQ-client-global-threads-1169382875)) HHH000163: Logical connection releasing its physical connection

18:35:43,993 DEBUG [org.hibernate.engine.internal.TwoPhaseLoad] (Thread-2 (HornetQ-client-global-threads-1169382875)) Resolving associations for [at.dimoco.payperiodic.ejb.model.Merchant#556]

18:35:43,994 DEBUG [org.hibernate.engine.internal.TwoPhaseLoad] (Thread-2 (HornetQ-client-global-threads-1169382875)) Done materializing entity [at.dimoco.payperiodic.ejb.model.Merchant#556]

18:35:43,996 DEBUG [org.hibernate.engine.internal.StatefulPersistenceContext] (Thread-2 (HornetQ-client-global-threads-1169382875)) Initializing non-lazy collections

18:35:43,997 DEBUG [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) HHH000117: HQL: FROM Merchant WHERE merchantId = :merchantId, time: 44ms, rows: 1

18:35:44,000 TRACE [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) pu search for name 'periodic' inside of payperiodic-ejb.jar

18:35:44,001 TRACE [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) findWithinDeployment check 'periodic' against pu 'periodic_msg'

18:35:44,002 TRACE [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) findWithinDeployment check 'periodic' against pu 'periodic'

18:35:44,003 TRACE [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) findWithinDeployment matched 'periodic' against pu 'periodic'

18:35:44,004 TRACE [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) pu search found payperiodic-ear.ear/payperiodic-ejb.jar#periodic

18:35:44,042 INFO [at.dimoco.payperiodic.ejb.calc.impl.BaseCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Next capture fill date is: Mon Sep 17 13:15:00 UTC 2012

18:35:44,043 INFO [at.dimoco.payperiodic.ejb.calc.impl.BaseCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Subscription length is: 7

18:35:44,043 INFO [at.dimoco.payperiodic.ejb.calc.impl.BaseCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Period fill length is: 3

18:35:44,044 INFO [at.dimoco.payperiodic.ejb.calc.CaptureFiller] (Thread-2 (HornetQ-client-global-threads-1169382875)) Refill start date: Mon Oct 01 13:15:00 UTC 2012

18:35:44,044 INFO [at.dimoco.payperiodic.ejb.calc.CalculatorFactory] (Thread-2 (HornetQ-client-global-threads-1169382875)) Create new ICalculator instance for subscription 1

18:35:44,045 INFO [at.dimoco.payperiodic.ejb.util.DateTime] (Thread-2 (HornetQ-client-global-threads-1169382875)) SubscriptionStartDate: Mon Oct 01 13:15:00 UTC 2012, Now: Mon Sep 03 16:35:27 UTC 2012

18:35:44,046 DEBUG [at.dimoco.payperiodic.ejb.util.DateTime] (Thread-2 (HornetQ-client-global-threads-1169382875)) WeekDay of Subscription start: 2

18:35:44,046 INFO [at.dimoco.payperiodic.ejb.util.DateTime] (Thread-2 (HornetQ-client-global-threads-1169382875)) Updated year and month: Mon Oct 01 13:15:00 UTC 2012

18:35:44,046 INFO [at.dimoco.payperiodic.ejb.calc.impl.DefaultCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Calculation start date set: Mon Oct 01 13:15:00 UTC 2012

18:35:44,047 INFO [at.dimoco.payperiodic.ejb.calc.impl.DefaultCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Subscription type: day, length: 7, captures: 7

18:35:44,048 INFO [at.dimoco.payperiodic.ejb.calc.CaptureFiller] (Thread-2 (HornetQ-client-global-threads-1169382875)) Calculator: at.dimoco.payperiodic.ejb.calc.impl.DefaultCalculator@2c8a5378

18:35:44,048 DEBUG [at.dimoco.payperiodic.ejb.calc.CaptureFiller] (Thread-2 (HornetQ-client-global-threads-1169382875)) StartDate of SubscriptionData of Subscription (1) : Mon Oct 01 13:15:00 UTC 2012

18:35:44,049 DEBUG [at.dimoco.payperiodic.ejb.calc.impl.DefaultCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Calculate capture dates.

18:35:44,049 INFO [at.dimoco.payperiodic.ejb.calc.impl.BaseCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Parameter period length not set. Setting to default: 1!

18:35:44,049 DEBUG [at.dimoco.payperiodic.ejb.calc.impl.DefaultCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Begindate: Mon Oct 01 13:15:00 UTC 2012, Period length: 1

18:35:44,050 DEBUG [at.dimoco.payperiodic.ejb.calc.impl.DefaultCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Calculating period 1

18:35:44,050 INFO [at.dimoco.payperiodic.ejb.calc.impl.DefaultCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Begindate: Mon Oct 01 13:15:00 UTC 2012

18:35:44,051 DEBUG [at.dimoco.payperiodic.ejb.calc.impl.BaseCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Get Interval List.

18:35:44,051 INFO [at.dimoco.payperiodic.ejb.calc.impl.BaseCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Renewal mode is: REGULAR

18:35:44,052 DEBUG [at.dimoco.payperiodic.ejb.calc.helper.IntervalHelper] (Thread-2 (HornetQ-client-global-threads-1169382875)) RegularInterval: 0 hours.

18:35:44,052 DEBUG [at.dimoco.payperiodic.ejb.calc.helper.IntervalHelper] (Thread-2 (HornetQ-client-global-threads-1169382875)) RegularInterval: 24 hours.

18:35:44,053 DEBUG [at.dimoco.payperiodic.ejb.calc.helper.IntervalHelper] (Thread-2 (HornetQ-client-global-threads-1169382875)) RegularInterval: 48 hours.

18:35:44,053 DEBUG [at.dimoco.payperiodic.ejb.calc.helper.IntervalHelper] (Thread-2 (HornetQ-client-global-threads-1169382875)) RegularInterval: 72 hours.

18:35:44,053 DEBUG [at.dimoco.payperiodic.ejb.calc.helper.IntervalHelper] (Thread-2 (HornetQ-client-global-threads-1169382875)) RegularInterval: 96 hours.

18:35:44,054 DEBUG [at.dimoco.payperiodic.ejb.calc.helper.IntervalHelper] (Thread-2 (HornetQ-client-global-threads-1169382875)) RegularInterval: 120 hours.

18:35:44,054 DEBUG [at.dimoco.payperiodic.ejb.calc.helper.IntervalHelper] (Thread-2 (HornetQ-client-global-threads-1169382875)) RegularInterval: 144 hours.

18:35:44,054 INFO [at.dimoco.payperiodic.ejb.calc.impl.DefaultCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Next capture date: Mon Oct 01 13:15:00 UTC 2012

18:35:44,055 INFO [at.dimoco.payperiodic.ejb.calc.impl.DefaultCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Next capture date: Tue Oct 02 13:15:00 UTC 2012

18:35:44,055 INFO [at.dimoco.payperiodic.ejb.calc.impl.DefaultCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Next capture date: Wed Oct 03 13:15:00 UTC 2012

18:35:44,056 INFO [at.dimoco.payperiodic.ejb.calc.impl.DefaultCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Next capture date: Thu Oct 04 13:15:00 UTC 2012

18:35:44,056 INFO [at.dimoco.payperiodic.ejb.calc.impl.DefaultCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Next capture date: Fri Oct 05 13:15:00 UTC 2012

18:35:44,057 INFO [at.dimoco.payperiodic.ejb.calc.impl.DefaultCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Next capture date: Sat Oct 06 13:15:00 UTC 2012

18:35:44,057 INFO [at.dimoco.payperiodic.ejb.calc.impl.DefaultCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Next capture date: Sun Oct 07 13:15:00 UTC 2012

18:35:44,063 INFO [at.dimoco.payperiodic.ejb.calc.impl.BaseCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Next fire time: Mon Oct 01 13:15:00 UTC 2012

18:35:44,063 INFO [at.dimoco.payperiodic.ejb.calc.impl.BaseCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Next fire time: Tue Oct 02 13:15:00 UTC 2012

18:35:44,064 INFO [at.dimoco.payperiodic.ejb.calc.impl.BaseCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Next fire time: Wed Oct 03 13:15:00 UTC 2012

18:35:44,064 INFO [at.dimoco.payperiodic.ejb.calc.impl.BaseCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Next fire time: Thu Oct 04 13:15:00 UTC 2012

18:35:44,064 INFO [at.dimoco.payperiodic.ejb.calc.impl.BaseCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Next fire time: Fri Oct 05 13:15:00 UTC 2012

18:35:44,065 INFO [at.dimoco.payperiodic.ejb.calc.impl.BaseCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Next fire time: Sat Oct 06 13:15:00 UTC 2012

18:35:44,065 INFO [at.dimoco.payperiodic.ejb.calc.impl.BaseCalculator] (Thread-2 (HornetQ-client-global-threads-1169382875)) Next fire time: Sun Oct 07 13:15:00 UTC 2012

18:35:44,066 DEBUG [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) created new TransactionScopedEntityManager for unit name=payperiodic-ear.ear/payperiodic-ejb.jar#periodic

18:35:44,067 DEBUG [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) Thread-2 (HornetQ-client-global-threads-1169382875):[transaction scoped EntityManager]: reuse entity manager session already in tx TransactionImple < ac, BasicAction: 0:ffffc0a81944:712186c4:5044dc4a:27 status: ActionStatus.RUNNING >

18:35:44,072 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtaining JDBC connection

18:35:44,073 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtained JDBC connection

18:35:44,074 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) select hibernate_sequence.nextval from dual

18:35:44,089 DEBUG [org.hibernate.id.enhanced.SequenceStructure] (Thread-2 (HornetQ-client-global-threads-1169382875)) Sequence value obtained: 200481

18:35:44,090 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Releasing JDBC connection

18:35:44,091 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Released JDBC connection

18:35:44,091 DEBUG [org.hibernate.event.internal.AbstractSaveEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Generated identifier: 200481, using strategy: org.hibernate.id.enhanced.SequenceStyleGenerator

18:35:44,095 TRACE [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) persist entityClass 'at.dimoco.payperiodic.ejb.model.Capture' took 28ms

18:35:44,096 DEBUG [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) Thread-2 (HornetQ-client-global-threads-1169382875):[transaction scoped EntityManager]: reuse entity manager session already in tx TransactionImple < ac, BasicAction: 0:ffffc0a81944:712186c4:5044dc4a:27 status: ActionStatus.RUNNING >

18:35:44,097 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtaining JDBC connection

18:35:44,098 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtained JDBC connection

18:35:44,099 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) select hibernate_sequence.nextval from dual

18:35:44,101 DEBUG [org.hibernate.id.enhanced.SequenceStructure] (Thread-2 (HornetQ-client-global-threads-1169382875)) Sequence value obtained: 200482

18:35:44,102 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Releasing JDBC connection

18:35:44,102 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Released JDBC connection

18:35:44,104 DEBUG [org.hibernate.event.internal.AbstractSaveEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Generated identifier: 200482, using strategy: org.hibernate.id.enhanced.SequenceStyleGenerator

18:35:44,106 TRACE [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) persist entityClass 'at.dimoco.payperiodic.ejb.model.Capture' took 10ms

18:35:44,107 DEBUG [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) Thread-2 (HornetQ-client-global-threads-1169382875):[transaction scoped EntityManager]: reuse entity manager session already in tx TransactionImple < ac, BasicAction: 0:ffffc0a81944:712186c4:5044dc4a:27 status: ActionStatus.RUNNING >

18:35:44,109 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtaining JDBC connection

18:35:44,110 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtained JDBC connection

18:35:44,111 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) select hibernate_sequence.nextval from dual

18:35:44,113 DEBUG [org.hibernate.id.enhanced.SequenceStructure] (Thread-2 (HornetQ-client-global-threads-1169382875)) Sequence value obtained: 200483

18:35:44,114 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Releasing JDBC connection

18:35:44,114 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Released JDBC connection

18:35:44,116 DEBUG [org.hibernate.event.internal.AbstractSaveEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Generated identifier: 200483, using strategy: org.hibernate.id.enhanced.SequenceStyleGenerator

18:35:44,117 TRACE [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) persist entityClass 'at.dimoco.payperiodic.ejb.model.Capture' took 10ms

18:35:44,118 DEBUG [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) Thread-2 (HornetQ-client-global-threads-1169382875):[transaction scoped EntityManager]: reuse entity manager session already in tx TransactionImple < ac, BasicAction: 0:ffffc0a81944:712186c4:5044dc4a:27 status: ActionStatus.RUNNING >

18:35:44,119 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtaining JDBC connection

18:35:44,120 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtained JDBC connection

18:35:44,121 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) select hibernate_sequence.nextval from dual

18:35:44,123 DEBUG [org.hibernate.id.enhanced.SequenceStructure] (Thread-2 (HornetQ-client-global-threads-1169382875)) Sequence value obtained: 200484

18:35:44,123 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Releasing JDBC connection

18:35:44,124 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Released JDBC connection

18:35:44,125 DEBUG [org.hibernate.event.internal.AbstractSaveEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Generated identifier: 200484, using strategy: org.hibernate.id.enhanced.SequenceStyleGenerator

18:35:44,126 TRACE [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) persist entityClass 'at.dimoco.payperiodic.ejb.model.Capture' took 8ms

18:35:44,127 DEBUG [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) Thread-2 (HornetQ-client-global-threads-1169382875):[transaction scoped EntityManager]: reuse entity manager session already in tx TransactionImple < ac, BasicAction: 0:ffffc0a81944:712186c4:5044dc4a:27 status: ActionStatus.RUNNING >

18:35:44,128 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtaining JDBC connection

18:35:44,129 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtained JDBC connection

18:35:44,129 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) select hibernate_sequence.nextval from dual

18:35:44,131 DEBUG [org.hibernate.id.enhanced.SequenceStructure] (Thread-2 (HornetQ-client-global-threads-1169382875)) Sequence value obtained: 200485

18:35:44,132 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Releasing JDBC connection

18:35:44,133 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Released JDBC connection

18:35:44,134 DEBUG [org.hibernate.event.internal.AbstractSaveEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Generated identifier: 200485, using strategy: org.hibernate.id.enhanced.SequenceStyleGenerator

18:35:44,135 TRACE [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) persist entityClass 'at.dimoco.payperiodic.ejb.model.Capture' took 8ms

18:35:44,136 DEBUG [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) Thread-2 (HornetQ-client-global-threads-1169382875):[transaction scoped EntityManager]: reuse entity manager session already in tx TransactionImple < ac, BasicAction: 0:ffffc0a81944:712186c4:5044dc4a:27 status: ActionStatus.RUNNING >

18:35:44,137 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtaining JDBC connection

18:35:44,138 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtained JDBC connection

18:35:44,139 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) select hibernate_sequence.nextval from dual

18:35:44,141 DEBUG [org.hibernate.id.enhanced.SequenceStructure] (Thread-2 (HornetQ-client-global-threads-1169382875)) Sequence value obtained: 200486

18:35:44,141 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Releasing JDBC connection

18:35:44,142 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Released JDBC connection

18:35:44,143 DEBUG [org.hibernate.event.internal.AbstractSaveEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Generated identifier: 200486, using strategy: org.hibernate.id.enhanced.SequenceStyleGenerator

18:35:44,144 TRACE [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) persist entityClass 'at.dimoco.payperiodic.ejb.model.Capture' took 8ms

18:35:44,144 DEBUG [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) Thread-2 (HornetQ-client-global-threads-1169382875):[transaction scoped EntityManager]: reuse entity manager session already in tx TransactionImple < ac, BasicAction: 0:ffffc0a81944:712186c4:5044dc4a:27 status: ActionStatus.RUNNING >

18:35:44,146 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtaining JDBC connection

18:35:44,147 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtained JDBC connection

18:35:44,148 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) select hibernate_sequence.nextval from dual

18:35:44,150 DEBUG [org.hibernate.id.enhanced.SequenceStructure] (Thread-2 (HornetQ-client-global-threads-1169382875)) Sequence value obtained: 200487

18:35:44,151 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Releasing JDBC connection

18:35:44,152 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Released JDBC connection

18:35:44,152 DEBUG [org.hibernate.event.internal.AbstractSaveEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Generated identifier: 200487, using strategy: org.hibernate.id.enhanced.SequenceStyleGenerator

18:35:44,153 TRACE [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) persist entityClass 'at.dimoco.payperiodic.ejb.model.Capture' took 9ms

18:35:44,154 INFO [at.dimoco.payperiodic.ejb.calc.CaptureFiller] (Thread-2 (HornetQ-client-global-threads-1169382875)) Last fill date: Mon Sep 17 13:15:00 UTC 2012

18:35:44,155 INFO [at.dimoco.payperiodic.ejb.calc.CaptureFiller] (Thread-2 (HornetQ-client-global-threads-1169382875)) Next capture fill date is: Mon Sep 24 13:15:00 UTC 2012

18:35:44,155 DEBUG [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) Thread-2 (HornetQ-client-global-threads-1169382875):[transaction scoped EntityManager]: reuse entity manager session already in tx TransactionImple < ac, BasicAction: 0:ffffc0a81944:712186c4:5044dc4a:27 status: ActionStatus.RUNNING >

18:35:44,157 TRACE [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) persist entityClass 'at.dimoco.payperiodic.ejb.model.Subscription' took 2ms

18:35:44,157 INFO [at.dimoco.payperiodic.ejb.jms.CaptureFillerMessageConsumer] (Thread-2 (HornetQ-client-global-threads-1169382875)) Successfully filled up captures for Subscription 1

18:35:44,158 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Processing flush-time cascades

18:35:44,159 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Dirty checking collections

18:35:44,161 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Flushed: 7 insertions, 1 updates, 0 deletions to 8 objects

18:35:44,161 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections

18:35:44,163 DEBUG [org.hibernate.internal.util.EntityPrinter] (Thread-2 (HornetQ-client-global-threads-1169382875)) Listing entities:

18:35:44,164 DEBUG [org.hibernate.internal.util.EntityPrinter] (Thread-2 (HornetQ-client-global-threads-1169382875)) at.dimoco.payperiodic.ejb.model.Capture{validTo=Mon Oct 15 13:15:00 UTC 2012, id=200481, lastStatusChange=null, transactionId=null, subscription=at.dimoco.payperiodic.ejb.model.Subscription#1, status=0, retryCount=0, configSet={"configMap":{"REPORTING_URL":"http://localhost:8080/payperiodic/test/callbackServlet","CAPTURE_VALIDITY_LENGTH":"2","HAS_BILLING_LIMIT":"0","PERIOD_FILL_LENGTH":"3","RETRY_INTERVAL_DIVISOR":"2","MAX_RETRY_LIFECYCLE":"60","EARLIEST_HOUR":"8","MAX_FAILED_CAPTURES":"20","LATEST_HOUR":"16","CHARGINGS_PER_DAY":"5","RENEWAL_MODE":"REGULAR"}}, validFrom=Mon Oct 01 13:15:00 UTC 2012, captureSuccess=false, processedAtFiretime=null, processedAt=null}

18:35:44,167 DEBUG [org.hibernate.internal.util.EntityPrinter] (Thread-2 (HornetQ-client-global-threads-1169382875)) at.dimoco.payperiodic.ejb.model.Subscription{nextCaptureFill=Mon Sep 24 13:15:00 UTC 2012, lastUpdate=Mon Sep 03 16:35:27 UTC 2012, inProgress=false, retryCounter=0, subscriptionId=1, retryLifecycle=0, id=1, failure=0, configSet={"configMap":{"REPORTING_URL":"http://localhost:8080/payperiodic/test/callbackServlet","CAPTURE_VALIDITY_LENGTH":"2","HAS_BILLING_LIMIT":"0","PERIOD_FILL_LENGTH":"3","RETRY_INTERVAL_DIVISOR":"2","MAX_RETRY_LIFECYCLE":"60","EARLIEST_HOUR":"8","MAX_FAILED_CAPTURES":"20","LATEST_HOUR":"16","CHARGINGS_PER_DAY":"5","RENEWAL_MODE":"REGULAR"}}, maxRetry=20, retryStart=null, importDate=2012-09-03 18:11:53.0, closed=false}

18:35:44,170 DEBUG [org.hibernate.internal.util.EntityPrinter] (Thread-2 (HornetQ-client-global-threads-1169382875)) at.dimoco.payperiodic.ejb.model.Capture{validTo=Tue Oct 16 13:15:00 UTC 2012, id=200482, lastStatusChange=null, transactionId=null, subscription=at.dimoco.payperiodic.ejb.model.Subscription#1, status=0, retryCount=0, configSet={"configMap":{"REPORTING_URL":"http://localhost:8080/payperiodic/test/callbackServlet","CAPTURE_VALIDITY_LENGTH":"2","HAS_BILLING_LIMIT":"0","PERIOD_FILL_LENGTH":"3","RETRY_INTERVAL_DIVISOR":"2","MAX_RETRY_LIFECYCLE":"60","EARLIEST_HOUR":"8","MAX_FAILED_CAPTURES":"20","LATEST_HOUR":"16","CHARGINGS_PER_DAY":"5","RENEWAL_MODE":"REGULAR"}}, validFrom=Tue Oct 02 13:15:00 UTC 2012, captureSuccess=false, processedAtFiretime=null, processedAt=null}

18:35:44,174 DEBUG [org.hibernate.internal.util.EntityPrinter] (Thread-2 (HornetQ-client-global-threads-1169382875)) at.dimoco.payperiodic.ejb.model.Capture{validTo=Wed Oct 17 13:15:00 UTC 2012, id=200483, lastStatusChange=null, transactionId=null, subscription=at.dimoco.payperiodic.ejb.model.Subscription#1, status=0, retryCount=0, configSet={"configMap":{"REPORTING_URL":"http://localhost:8080/payperiodic/test/callbackServlet","CAPTURE_VALIDITY_LENGTH":"2","HAS_BILLING_LIMIT":"0","PERIOD_FILL_LENGTH":"3","RETRY_INTERVAL_DIVISOR":"2","MAX_RETRY_LIFECYCLE":"60","EARLIEST_HOUR":"8","MAX_FAILED_CAPTURES":"20","LATEST_HOUR":"16","CHARGINGS_PER_DAY":"5","RENEWAL_MODE":"REGULAR"}}, validFrom=Wed Oct 03 13:15:00 UTC 2012, captureSuccess=false, processedAtFiretime=null, processedAt=null}

18:35:44,178 DEBUG [org.hibernate.internal.util.EntityPrinter] (Thread-2 (HornetQ-client-global-threads-1169382875)) at.dimoco.payperiodic.ejb.model.Capture{validTo=Thu Oct 18 13:15:00 UTC 2012, id=200484, lastStatusChange=null, transactionId=null, subscription=at.dimoco.payperiodic.ejb.model.Subscription#1, status=0, retryCount=0, configSet={"configMap":{"REPORTING_URL":"http://localhost:8080/payperiodic/test/callbackServlet","CAPTURE_VALIDITY_LENGTH":"2","HAS_BILLING_LIMIT":"0","PERIOD_FILL_LENGTH":"3","RETRY_INTERVAL_DIVISOR":"2","MAX_RETRY_LIFECYCLE":"60","EARLIEST_HOUR":"8","MAX_FAILED_CAPTURES":"20","LATEST_HOUR":"16","CHARGINGS_PER_DAY":"5","RENEWAL_MODE":"REGULAR"}}, validFrom=Thu Oct 04 13:15:00 UTC 2012, captureSuccess=false, processedAtFiretime=null, processedAt=null}

18:35:44,181 DEBUG [org.hibernate.internal.util.EntityPrinter] (Thread-2 (HornetQ-client-global-threads-1169382875)) at.dimoco.payperiodic.ejb.model.Capture{validTo=Fri Oct 19 13:15:00 UTC 2012, id=200485, lastStatusChange=null, transactionId=null, subscription=at.dimoco.payperiodic.ejb.model.Subscription#1, status=0, retryCount=0, configSet={"configMap":{"REPORTING_URL":"http://localhost:8080/payperiodic/test/callbackServlet","CAPTURE_VALIDITY_LENGTH":"2","HAS_BILLING_LIMIT":"0","PERIOD_FILL_LENGTH":"3","RETRY_INTERVAL_DIVISOR":"2","MAX_RETRY_LIFECYCLE":"60","EARLIEST_HOUR":"8","MAX_FAILED_CAPTURES":"20","LATEST_HOUR":"16","CHARGINGS_PER_DAY":"5","RENEWAL_MODE":"REGULAR"}}, validFrom=Fri Oct 05 13:15:00 UTC 2012, captureSuccess=false, processedAtFiretime=null, processedAt=null}

18:35:44,184 DEBUG [org.hibernate.internal.util.EntityPrinter] (Thread-2 (HornetQ-client-global-threads-1169382875)) at.dimoco.payperiodic.ejb.model.Capture{validTo=Sat Oct 20 13:15:00 UTC 2012, id=200486, lastStatusChange=null, transactionId=null, subscription=at.dimoco.payperiodic.ejb.model.Subscription#1, status=0, retryCount=0, configSet={"configMap":{"REPORTING_URL":"http://localhost:8080/payperiodic/test/callbackServlet","CAPTURE_VALIDITY_LENGTH":"2","HAS_BILLING_LIMIT":"0","PERIOD_FILL_LENGTH":"3","RETRY_INTERVAL_DIVISOR":"2","MAX_RETRY_LIFECYCLE":"60","EARLIEST_HOUR":"8","MAX_FAILED_CAPTURES":"20","LATEST_HOUR":"16","CHARGINGS_PER_DAY":"5","RENEWAL_MODE":"REGULAR"}}, validFrom=Sat Oct 06 13:15:00 UTC 2012, captureSuccess=false, processedAtFiretime=null, processedAt=null}

18:35:44,189 DEBUG [org.hibernate.internal.util.EntityPrinter] (Thread-2 (HornetQ-client-global-threads-1169382875)) at.dimoco.payperiodic.ejb.model.Capture{validTo=Sun Oct 21 13:15:00 UTC 2012, id=200487, lastStatusChange=null, transactionId=null, subscription=at.dimoco.payperiodic.ejb.model.Subscription#1, status=0, retryCount=0, configSet={"configMap":{"REPORTING_URL":"http://localhost:8080/payperiodic/test/callbackServlet","CAPTURE_VALIDITY_LENGTH":"2","HAS_BILLING_LIMIT":"0","PERIOD_FILL_LENGTH":"3","RETRY_INTERVAL_DIVISOR":"2","MAX_RETRY_LIFECYCLE":"60","EARLIEST_HOUR":"8","MAX_FAILED_CAPTURES":"20","LATEST_HOUR":"16","CHARGINGS_PER_DAY":"5","RENEWAL_MODE":"REGULAR"}}, validFrom=Sun Oct 07 13:15:00 UTC 2012, captureSuccess=false, processedAtFiretime=null, processedAt=null}

18:35:44,209 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtaining JDBC connection

18:35:44,210 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Obtained JDBC connection

18:35:44,211 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) insert into capture (capture_success, config_set, last_status_change, processed_at, processed_at_firetime, retry_count, status, subscription_fk, transaction_id, valid_from, valid_to, id) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)

18:35:44,253 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Skipping aggressive release due to manual disabling

18:35:44,256 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) insert into capture (capture_success, config_set, last_status_change, processed_at, processed_at_firetime, retry_count, status, subscription_fk, transaction_id, valid_from, valid_to, id) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)

18:35:44,267 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Skipping aggressive release due to manual disabling

18:35:44,273 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) insert into capture (capture_success, config_set, last_status_change, processed_at, processed_at_firetime, retry_count, status, subscription_fk, transaction_id, valid_from, valid_to, id) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)

18:35:44,281 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Skipping aggressive release due to manual disabling

18:35:44,284 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) insert into capture (capture_success, config_set, last_status_change, processed_at, processed_at_firetime, retry_count, status, subscription_fk, transaction_id, valid_from, valid_to, id) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)

18:35:44,289 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Skipping aggressive release due to manual disabling

18:35:44,291 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) insert into capture (capture_success, config_set, last_status_change, processed_at, processed_at_firetime, retry_count, status, subscription_fk, transaction_id, valid_from, valid_to, id) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)

18:35:44,296 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Skipping aggressive release due to manual disabling

18:35:44,298 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) insert into capture (capture_success, config_set, last_status_change, processed_at, processed_at_firetime, retry_count, status, subscription_fk, transaction_id, valid_from, valid_to, id) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)

18:35:44,302 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Skipping aggressive release due to manual disabling

18:35:44,304 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) insert into capture (capture_success, config_set, last_status_change, processed_at, processed_at_firetime, retry_count, status, subscription_fk, transaction_id, valid_from, valid_to, id) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)

18:35:44,309 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Skipping aggressive release due to manual disabling

18:35:44,312 DEBUG [org.hibernate.SQL] (Thread-2 (HornetQ-client-global-threads-1169382875)) update subscription set closed=?, config_set=?, failure=?, import_date=?, in_progress=?, last_update=?, max_retry=?, next_capture_fill=?, retry_counter=?, retry_lifecycle=?, retry_start=?, subscription_id=? where id=?

18:35:44,328 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Skipping aggressive release due to manual disabling

18:35:44,330 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Releasing JDBC connection

18:35:44,331 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Released JDBC connection

18:35:44,331 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Processing flush-time cascades

18:35:44,332 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Dirty checking collections

18:35:44,333 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects

18:35:44,334 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-2 (HornetQ-client-global-threads-1169382875)) Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections

18:35:44,335 DEBUG [org.hibernate.internal.util.EntityPrinter] (Thread-2 (HornetQ-client-global-threads-1169382875)) Listing entities:

18:35:44,336 DEBUG [org.hibernate.internal.util.EntityPrinter] (Thread-2 (HornetQ-client-global-threads-1169382875)) at.dimoco.payperiodic.ejb.model.Merchant{name=Dimoco Test, active=true, merchantId=556, password=WTQYBa}

18:35:44,337 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Releasing JDBC connection

18:35:44,397 DEBUG [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) Thread-2 (HornetQ-client-global-threads-1169382875):[transaction scoped EntityManager]: closing entity managersession

18:35:44,398 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Aggressively releasing JDBC connection

18:35:44,399 DEBUG [org.jboss.as.jpa] (Thread-2 (HornetQ-client-global-threads-1169382875)) Thread-2 (HornetQ-client-global-threads-1169382875):[transaction scoped EntityManager]: closing entity managersession

18:35:44,400 DEBUG [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) HHH000420: Closing un-released batch

18:35:44,401 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-2 (HornetQ-client-global-threads-1169382875)) Aggressively releasing JDBC connection

1. Re: JTA, Hibernate Session Open Count

nickarls Sep 3, 2012 5:41 PM (in response to sage84)

What happens with a non-XA-datasource? Can you show the code where the message is processed/stored? Any interceptors etc? Closing all JMS resources? Just guessing here...
Actions
2. Re: JTA, Hibernate Session Open Count

sage84 Sep 10, 2012 3:54 AM (in response to sage84)

I did a few tests and accessed the hibernate statistics through entity manager and the sessions are closed correctly. So I think there is a mistake with the session open count value displayed.
Actions
3. Re: JTA, Hibernate Session Open Count

jaikiran Sep 10, 2012 3:57 AM (in response to sage84)

I don't know how those counts are tracked, but perhaps the session is being opened and garbage collected later, without being closed explicitly?
Actions
4. Re: JTA, Hibernate Session Open Count

smarlow Sep 10, 2012 8:39 AM (in response to jaikiran)

Good point Jaikiran!

Gerald, could you try using the Eclipse Memory Analyzer tool to see if there are a large number of Hibernate sessions (org.hibernate.Session) open.

Scott
Actions
5. Re: JTA, Hibernate Session Open Count

jsightler Oct 9, 2012 12:21 PM (in response to smarlow)

I believe that I am seeing a similar issue. I've filed an issue at:
https://issues.jboss.org/browse/AS7-5714
Actions

Go to original post