2 Replies Latest reply on Feb 9, 2011 7:20 PM by jamesarobson

    Jboss 6.0.0.Final: Startup singleton postconstructor transaction timeout when trying to perist entity

    jamesarobson

      Hi, I've an application with a start up singleton which queries thet database and attepts to insert default records if the data does not exist.

      On JBoss 6.0.0.Final the transaction times out after haning for five minutes and the initialisation of the container fails.

       

      I've put to gether a sample app which reproduces the persistence problem. I've tried this on Glassfish 3.0.1 and the persistence works.

       

      StartupSingleton.java

       

      @Singleton
      @Startup
      @LocalBean
      //@TransactionManagement(value=TransactionManagementType.CONTAINER)
      public class StartupSingleton {
      
          //private static final Logger logger = Logger.getLogger(StartupSingleton.class);
          @PersistenceContext(unitName="test-unit")
          protected EntityManager em;
      
          @PostConstruct
          //@TransactionAttribute(value=TransactionAttributeType.REQUIRES_NEW)
          public void initialise() {
      
              //logger.info("Entered iniitalise");
              System.out.println("Entered initailise");
              TaskInfo task = new TaskInfo();
              task.setDayOfMonth("*");
              task.setDayOfMonth("*");
              task.setDescription("test task");
              task.setEndDate(null);
              task.setHour("*");
              task.setMinute("*");
              task.setMonth("*");
              task.setNextTimeout(null);
              task.setSecond("*/30");
              task.setStartDate(new Date());
              task.setTaskClassName("app/indexer/somejindiname");
              task.setTaskClassName("EDocument");
              task.setTaskName("TestTask");
              task.setYear("*");
      
              //logger.info("Persisting object");
              System.out.println("Persisting object");
              em.persist(task);
              //logger.info("object persisted");
              System.out.println("Object persisted");
          }
      
      }
      

       

      TaskInfo.java

       

      package sample.startup;
      
      import java.util.Date;
      import javax.persistence.Column;
      import javax.persistence.Entity;
      import javax.persistence.GeneratedValue;
      import javax.persistence.GenerationType;
      import javax.persistence.Id;
      import javax.persistence.Table;
      import javax.persistence.Temporal;
      import javax.persistence.TemporalType;
      
      
      @Entity
      @Table(name="ens_scheduledtasks")
      public class TaskInfo implements java.io.Serializable {
      
      //    private static String format1 = "MM/dd/yyyy";
      //    private static String format2 = "MM/dd/yyyy HH:mm:ss";
      
          @Id
          @GeneratedValue(strategy=GenerationType.AUTO)
          @Column(name="id_task")
          private String taskId;
      
          @Column(name="task_name")
          private String taskName;
      
          @Column(name="task_class_name")
          private String taskClassName;
      
          @Column(name="task_description")
          private String description;
      
          @Column(name="task_start_date")
          @Temporal(TemporalType.TIMESTAMP)
          private Date startDate;
      
          @Column(name="task_end_date")
          @Temporal(TemporalType.TIMESTAMP)
          private Date endDate;
      
          @Column(name="task_second")
          private String second;
      
          @Column(name="task_minute")
          private String minute;
      
          @Column(name="task_hour")
          private String hour;
      
          @Column(name="task_day_of_week")
          private String dayOfWeek;
      
          @Column(name="task_day_of_month")
          private String dayOfMonth;
      
          @Column(name="task_month")
          private String month;
      
          @Column(name="task_year")
          private String year;
      
          @Column(name="task_next_timeout")
          @Temporal(TemporalType.TIMESTAMP)
          private Date nextTimeout;
      
      
          public TaskInfo() {
              //this("<Job ID>", "<Job Name>", "java:module/");
          }
      
          public TaskInfo(String id, String name, String className) {
              this.taskId = id;
              this.taskName = name;
              this.taskClassName = className;
              this.description = "";
              //Default values, every midnight
              this.startDate = new Date();
              this.endDate = null;
              this.second = "0";
              this.minute = "0";
              this.hour = "0";
              this.dayOfMonth = "*";
              this.month = "*";
              this.year = "*";
              this.dayOfWeek = "*";
      
      
          }
      
          public String getExpression() {
              return "sec=" + getSecond() + ";min=" + getMinute() + ";hour=" + getHour()
                  + ";dayOfMonth=" + getDayOfMonth() + ";month=" + getMonth() + ";year=" + getYear()
                  + ";dayOfWeek=" + getDayOfWeek();
          }
      
          @Override
          public boolean equals(Object obj) {
              if (obj instanceof TaskInfo) {
                  return getTaskId().equals(((TaskInfo) obj).getTaskId());
              } else {
                  return false;
              }
          }
      
          @Override
          public String toString() {
              return getTaskId() + "-" + getTaskName() + "-" + getTaskClassName();
          }
      
          /**
           * @return the taskId
           */
          public String getTaskId() {
              return taskId;
          }
      
          /**
           * @param taskId the taskId to set
           */
          public void setTaskId(String jobId) {
              this.taskId = jobId;
          }
      
          /**
           * @return the taskName
           */
          public String getTaskName() {
              return taskName;
          }
      
          /**
           * @param taskName the taskName to set
           */
          public void setTaskName(String jobName) {
              this.taskName = jobName;
          }
      
          /**
           * @return the jobClassName
           */
          public String getTaskClassName() {
              return taskClassName;
          }
      
          /**
           * @param taskClassName the jobClassName to set
           */
          public void setTaskClassName(String taskClassName) {
              this.taskClassName = taskClassName;
          }
      
          /**
           * @return the description
           */
          public String getDescription() {
              return description;
          }
      
          /**
           * @param description the description to set
           */
          public void setDescription(String description) {
              this.description = description;
          }
      
          /**
           * @return the startDate
           */
          public Date getStartDate() {
              return startDate;
          }
      
          /**
           * @param startDate the startDate to set
           */
          public void setStartDate(Date startDate) {
              this.startDate = startDate;
          }
      
          /**
           * @return the endDate
           */
          public Date getEndDate() {
              return endDate;
          }
      
          /**
           * @param endDate the endDate to set
           */
          public void setEndDate(Date endDate) {
              this.endDate = endDate;
          }
      
          /**
           * @return the second
           */
          public String getSecond() {
              return second;
          }
      
          /**
           * @param second the second to set
           */
          public void setSecond(String second) {
              this.second = second;
          }
      
          /**
           * @return the minute
           */
          public String getMinute() {
              return minute;
          }
      
          /**
           * @param minute the minute to set
           */
          public void setMinute(String minute) {
              this.minute = minute;
          }
      
          /**
           * @return the hour
           */
          public String getHour() {
              return hour;
          }
      
          /**
           * @param hour the hour to set
           */
          public void setHour(String hour) {
              this.hour = hour;
          }
      
          /**
           * @return the dayOfWeek
           */
          public String getDayOfWeek() {
              return dayOfWeek;
          }
      
          /**
           * @param dayOfWeek the dayOfWeek to set
           */
          public void setDayOfWeek(String dayOfWeek) {
              this.dayOfWeek = dayOfWeek;
          }
      
          /**
           * @return the dayOfMonth
           */
          public String getDayOfMonth() {
              return dayOfMonth;
          }
      
          /**
           * @param dayOfMonth the dayOfMonth to set
           */
          public void setDayOfMonth(String dayOfMonth) {
              this.dayOfMonth = dayOfMonth;
          }
      
          /**
           * @return the month
           */
          public String getMonth() {
              return month;
          }
      
          /**
           * @param month the month to set
           */
          public void setMonth(String month) {
              this.month = month;
          }
      
          /**
           * @return the year
           */
          public String getYear() {
              return year;
          }
      
          /**
           * @param year the year to set
           */
          public void setYear(String year) {
              this.year = year;
          }
      
          /**
           * @return the nextTimeout
           */
          public Date getNextTimeout() {
              return nextTimeout;
          }
      
          /**
           * @param nextTimeout the nextTimeout to set
           */
          public void setNextTimeout(Date nextTimeout) {
              this.nextTimeout = nextTimeout;
          }
      
      
      }
      

       

      persistence.xml

       

      <?xml version="1.0" encoding="UTF-8"?>
      <persistence version="2.0" xmlns="http://java.sun.com/xml/ns/persistence" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://java.sun.com/xml/ns/persistence http://java.sun.com/xml/ns/persistence/persistence_2_0.xsd">
        <persistence-unit name="test-unit" transaction-type="JTA">
          <jta-data-source>scheduleDS</jta-data-source>
          <class>sample.startup.TaskInfo</class>
          <properties>
            <property name="hibernate.hbm2ddl.auto" value="create-tables"/>
            <!--<property name="eclipselink.ddl-generation" value="create-tables"/>-->
          </properties>
        </persistence-unit>
      </persistence>
      

       

      ejb-jar.xml

       

      <?xml version="1.0" encoding="UTF-8"?>
      
      <ejb-jar xmlns = "http://java.sun.com/xml/ns/javaee" 
               version = "3.1"
               xmlns:xsi = "http://www.w3.org/2001/XMLSchema-instance" 
               xsi:schemaLocation = "http://java.sun.com/xml/ns/javaee http://java.sun.com/xml/ns/javaee/ejb-jar_3_1.xsd">
           <display-name>startup test</display-name>
      </ejb-jar>
      

       

      I'm assuming that I've done everything correctly and that this is a bug. Where should I be raising this? JBoss AS or EJB3 or somewhere else?

       

      Thanks in advance.

        • 1. Jboss 6.0.0.Final: Startup singleton postconstructor transaction timeout when trying to perist entity
          jaikiran

          Which database server is this? Have you tried taking some thread dumps  to see what's going on for those 5 minutes?

          • 2. Re: Jboss 6.0.0.Final: Startup singleton postconstructor transaction timeout when trying to perist entity
            jamesarobson

            Thans for the reply,

            I'm using MSSQLServer 2008 and jTDS JDBC Driver

             

             

            <xa-datasource>
                    <jndi-name>scheduleDS</jndi-name>
                    <use-java-context>false</use-java-context>
                    <xa-datasource-class>net.sourceforge.jtds.jdbcx.JtdsDataSource</xa-datasource-class>
                    <xa-datasource-property name="ServerName">mydb</xa-datasource-property>
                    <xa-datasource-property name="PortNumber">1433</xa-datasource-property>
                    <xa-datasource-property name="DatabaseName">dbname</xa-datasource-property>
                    <xa-datasource-property name="User">myuser</xa-datasource-property>
                    <xa-datasource-property name="Password">password</xa-datasource-property>
                    <min-pool-size>5</min-pool-size>
                    <max-pool-size>100</max-pool-size>
                    <check-valid-connection-sql>SELECT 1 FROM sysobjects</check-valid-connection-sql>
                    <metadata>
                        <type-mapping>MS SQLSERVER2008</type-mapping>
                    </metadata>
                </xa-datasource>
            

             

            Thread dump 1 (relavant thread for insert.)

            "Thread-2" prio=6 tid=0x000000000706e000 nid=0x318c runnable [0x0000000007a9b000]
               java.lang.Thread.State: RUNNABLE
                at java.net.SocketInputStream.socketRead0(Native Method)
                at java.net.SocketInputStream.read(SocketInputStream.java:129)
                at java.io.DataInputStream.readFully(DataInputStream.java:178)
                at java.io.DataInputStream.readFully(DataInputStream.java:152)
                at net.sourceforge.jtds.jdbc.SharedSocket.readPacket(SharedSocket.java:842)
                at net.sourceforge.jtds.jdbc.SharedSocket.getNetPacket(SharedSocket.java:723)
                - locked <0x00000000e6b72480> (a java.util.ArrayList)
                at net.sourceforge.jtds.jdbc.ResponseStream.getPacket(ResponseStream.java:466)
                at net.sourceforge.jtds.jdbc.ResponseStream.read(ResponseStream.java:103)
                at net.sourceforge.jtds.jdbc.ResponseStream.peek(ResponseStream.java:88)
                at net.sourceforge.jtds.jdbc.TdsCore.wait(TdsCore.java:3932)
                at net.sourceforge.jtds.jdbc.TdsCore.executeSQL(TdsCore.java:1046)
                - locked <0x00000000e6b725e0> (a net.sourceforge.jtds.jdbc.TdsCore)
                at net.sourceforge.jtds.jdbc.TdsCore.submitSQL(TdsCore.java:899)
                at net.sourceforge.jtds.jdbc.ConnectionJDBC2.rollback(ConnectionJDBC2.java:2120)
                - locked <0x00000000e6b71fc0> (a net.sourceforge.jtds.jdbc.ConnectionJDBC3)
                at net.sourceforge.jtds.jdbc.XASupport.xa_rollback(XASupport.java:426)
                at net.sourceforge.jtds.jdbcx.JtdsXAResource.rollback(JtdsXAResource.java:95)
                at org.jboss.resource.adapter.jdbc.xa.XAManagedConnection.rollback(XAManagedConnection.java:284)
                at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:336)
                at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2902)
                at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2881)
                at com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1602)
                - locked <0x00000000fe94e6f8> (a com.arjuna.ats.internal.jta.transaction.arjunacore.AtomicAction)
                at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:119)
                at com.arjuna.ats.arjuna.AtomicAction.abort(AtomicAction.java:183)
                at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.rollbackAndDisassociate(TransactionImple.java:1240)
                at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.rollback(BaseTransaction.java:136)
                at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.rollback(BaseTransactionManagerDelegate.java:114)
                at org.hibernate.engine.transaction.Isolater$JtaDelegate.doTheWorkInNewTransaction(Isolater.java:169)
                at org.hibernate.engine.transaction.Isolater$JtaDelegate.delegateWork(Isolater.java:126)
                at org.hibernate.engine.transaction.Isolater.doIsolatedWork(Isolater.java:67)
                at org.hibernate.engine.TransactionHelper.doWorkInNewTransaction(TransactionHelper.java:74)
                at org.hibernate.id.enhanced.TableStructure$1.getNextValue(TableStructure.java:131)
                at org.hibernate.id.enhanced.OptimizerFactory$NoopOptimizer.generate(OptimizerFactory.java:194)
                at org.hibernate.id.enhanced.SequenceStyleGenerator.generate(SequenceStyleGenerator.java:346)
                at org.hibernate.event.def.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:121)
                at org.hibernate.ejb.event.EJB3PersistEventListener.saveWithGeneratedId(EJB3PersistEventListener.java:69)
                at org.hibernate.event.def.DefaultPersistEventListener.entityIsTransient(DefaultPersistEventListener.java:179)
                at org.hibernate.event.def.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:135)
                at org.hibernate.event.def.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:61)
                at org.hibernate.impl.SessionImpl.firePersist(SessionImpl.java:808)
                at org.hibernate.impl.SessionImpl.persist(SessionImpl.java:782)
                at org.hibernate.impl.SessionImpl.persist(SessionImpl.java:786)
                at org.hibernate.ejb.AbstractEntityManagerImpl.persist(AbstractEntityManagerImpl.java:672)
                at org.jboss.jpa.impl.tx.TransactionScopedEntityManager.persist(TransactionScopedEntityManager.java:206)
                at sample.startup.StartupSingleton.initialise(StartupSingleton.java:59)
            

             

            Thread dump 2

            "Thread-2" prio=6 tid=0x000000000706e000 nid=0x318c runnable [0x0000000007a9b000]
               java.lang.Thread.State: RUNNABLE
                at java.net.SocketInputStream.socketRead0(Native Method)
                at java.net.SocketInputStream.read(SocketInputStream.java:129)
                at java.io.DataInputStream.readFully(DataInputStream.java:178)
                at java.io.DataInputStream.readFully(DataInputStream.java:152)
                at net.sourceforge.jtds.jdbc.SharedSocket.readPacket(SharedSocket.java:842)
                at net.sourceforge.jtds.jdbc.SharedSocket.getNetPacket(SharedSocket.java:723)
                - locked <0x00000000e6b72480> (a java.util.ArrayList)
                at net.sourceforge.jtds.jdbc.ResponseStream.getPacket(ResponseStream.java:466)
                at net.sourceforge.jtds.jdbc.ResponseStream.read(ResponseStream.java:103)
                at net.sourceforge.jtds.jdbc.ResponseStream.peek(ResponseStream.java:88)
                at net.sourceforge.jtds.jdbc.TdsCore.wait(TdsCore.java:3932)
                at net.sourceforge.jtds.jdbc.TdsCore.executeSQL(TdsCore.java:1046)
                - locked <0x00000000e6b725e0> (a net.sourceforge.jtds.jdbc.TdsCore)
                at net.sourceforge.jtds.jdbc.TdsCore.submitSQL(TdsCore.java:899)
                at net.sourceforge.jtds.jdbc.ConnectionJDBC2.setAutoCommit(ConnectionJDBC2.java:2259)
                - locked <0x00000000e6b71fc0> (a net.sourceforge.jtds.jdbc.ConnectionJDBC3)
                at net.sourceforge.jtds.jdbc.XASupport.xa_start(XASupport.java:201)
                at net.sourceforge.jtds.jdbcx.JtdsXAResource.start(JtdsXAResource.java:105)
                at org.jboss.resource.adapter.jdbc.xa.XAManagedConnection.start(XAManagedConnection.java:213)
                at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:629)
                at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:390)
                at org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener$TransactionSynchronization.enlist(TxConnectionManager.java:975)
                at org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener.enlist(TxConnectionManager.java:729)
                at org.jboss.resource.connectionmanager.TxConnectionManager.managedConnectionReconnected(TxConnectionManager.java:459)
                at org.jboss.resource.connectionmanager.BaseConnectionManager2.reconnectManagedConnection(BaseConnectionManager2.java:625)
                at org.jboss.resource.connectionmanager.BaseConnectionManager2.allocateConnection(BaseConnectionManager2.java:499)
                at org.jboss.resource.connectionmanager.BaseConnectionManager2$ConnectionManagerProxy.allocateConnection(BaseConnectionManager2.java:941)
                at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:89)
                at org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:71)
                at org.hibernate.engine.transaction.Isolater$JtaDelegate.doTheWork(Isolater.java:191)
                at org.hibernate.engine.transaction.Isolater$JtaDelegate.doTheWorkInNewTransaction(Isolater.java:163)
                at org.hibernate.engine.transaction.Isolater$JtaDelegate.delegateWork(Isolater.java:126)
                at org.hibernate.engine.transaction.Isolater.doIsolatedWork(Isolater.java:67)
                at org.hibernate.engine.TransactionHelper.doWorkInNewTransaction(TransactionHelper.java:74)
                at org.hibernate.id.enhanced.TableStructure$1.getNextValue(TableStructure.java:131)
                at org.hibernate.id.enhanced.OptimizerFactory$NoopOptimizer.generate(OptimizerFactory.java:194)
                at org.hibernate.id.enhanced.SequenceStyleGenerator.generate(SequenceStyleGenerator.java:346)
                at org.hibernate.event.def.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:121)
                at org.hibernate.ejb.event.EJB3PersistEventListener.saveWithGeneratedId(EJB3PersistEventListener.java:69)
                at org.hibernate.event.def.DefaultPersistEventListener.entityIsTransient(DefaultPersistEventListener.java:179)
                at org.hibernate.event.def.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:135)
                at org.hibernate.event.def.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:61)
                at org.hibernate.impl.SessionImpl.firePersist(SessionImpl.java:808)
                at org.hibernate.impl.SessionImpl.persist(SessionImpl.java:782)
                at org.hibernate.impl.SessionImpl.persist(SessionImpl.java:786)
                at org.hibernate.ejb.AbstractEntityManagerImpl.persist(AbstractEntityManagerImpl.java:672)
                at org.jboss.jpa.impl.tx.TransactionScopedEntityManager.persist(TransactionScopedEntityManager.java:206)
                at sample.startup.StartupSingleton.initialise(StartupSingleton.java:59)
            

             

            Thread dumps don't provide much information.

             

            it seems like the app server creates four connections and then just continually checks that they are alive.

            -- there are four of these
            SELECT @@MAX_PRECISION
            SET TRANSACTION ISOLATION LEVEL READ COMMITTED
            SET IMPLICIT_TRANSACTIONS OFF
            SET QUOTED_IDENTIFIER ON
            SET TEXTSIZE 2147483647
            go
            
            -- this goes on adinfinitum
            SELECT 1 FROM sysobjects
            go
            SET IMPLICIT_TRANSACTIONS ON
            go
            IF @@TRANCOUNT > 0 ROLLBACK TRAN
            go
            IF @@TRANCOUNT > 0 COMMIT TRAN
            SET IMPLICIT_TRANSACTIONS OFF
            go
            

             

            I should note that when I deplpy the full application without the component I'm working on, I do not get this problem.