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

    JTA, Hibernate Session Open Count

    Gerald Scharaditsch Newbie

      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: 'at'

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

          |           |  |  |  \-[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