1 Reply Latest reply on Jun 1, 2009 7:18 AM by taranis

    Problem Using Annotated Beans with JTA. Data is not written

    taranis

      Hi,

      When i try to use JPA Annotated beans with JTA, data is not saved to DB.
      There are no exceptions but data is not committed to DB, it is like my bean is transient but i have annotated it with @Entity and it must not be Transient.
      I have created a war file and deployed to JBoss, tested this in a simple Servlet in that war file.

      JBoss version: 4.2.2.GA

      Here is SessionFactory configuration:

      myConf.setProperty("hibernate.connection.driver_class", "oracle.jdbc.driver.OracleDriver");
       myConf.setProperty("hibernate.connection.url", "jdbc:oracle:thin:@47.168.58.53:5121:mcpdb");
       myConf.setProperty("hibernate.connection.username", "polguc_1");
       myConf.setProperty("hibernate.connection.password", "pwdPin_1_2pwdPin_1_2");
       myConf.setProperty("hibernate.connection.pool_size", "10");
       myConf.setProperty("hibernate.dialect", "org.hibernate.dialect.Oracle10gDialect");
       myConf.setProperty("hibernate.transaction.factory_class", "org.hibernate.transaction.JTATransactionFactory");
       myConf.setProperty("hibernate.transaction.manager_lookup_class","org.hibernate.transaction.JBossTransactionManagerLookup");
       myConf.setProperty("jta.UserTransaction","java:comp/UserTransaction");
       myConf.setProperty("hibernate.session_factory_name","hibernate/HibernateFactory");
       myConf.setProperty("hibernate.current_session_context_class", "jta");
       myConf.setProperty("hibernate.show_sql", "true");
       myConf.setProperty("hibernate.hbm2ddl.auto", "create");
       myConf.addAnnotatedClass(Flight.class);


      This is the Annotated Bean:
      @Entity
      @Table(name="tbl_flight")
      public class Flight implements Serializable {
      
       Long id;
       String name;
      
       public Flight ()
       {
      
       }
      
       @Id @GeneratedValue(strategy=GenerationType.SEQUENCE)
       public Long getId() { return id; }
      
       private void setId(Long id) { this.id = id; }
      
       @Column
       public String getName() {
       return name;
       }
      
       public void setName(String name) {
       this.name = name;
       }
      }


      This is the JTA Transaction and data persist code:

      UserTransaction tx = null;
       try {
       Properties hibernateCfg = HibernateUtil.getConfiguration().getProperties();
       Context jndiContext =
       NamingHelper.getInitialContext( NamingHelper.getJndiProperties(hibernateCfg));
       TransactionManagerLookup tmLookup =
       TransactionManagerLookupFactory.getTransactionManagerLookup(hibernateCfg);
       javax.transaction.TransactionManager tm = tmLookup.getTransactionManager(hibernateCfg);
       String userTxName = tmLookup.getUserTransactionName();
       tx = (javax.transaction.UserTransaction) (new InitialContext()).lookup(userTxName);
      
       try {
       tx.begin();
      
       Flight entity = new Flight();
       entity.setName("flightName");
       HibernateUtil.getSessFact().getCurrentSession().persist(entity);
       HibernateUtil.getSessFact().getCurrentSession().flush();
       tx.commit();
      
      
       } catch (HibernateException e) {
       // TODO Auto-generated catch block
       tx.rollback
       e.printStackTrace();
       }
      ..........
      .....
      


      Jboss logs, you can see insert statement is used at the end of the logs


      23:21:53,418 INFO [Server] JBoss (MX MicroKernel) [4.2.2.GA (build: SVNTag=JBoss_4_2_2_GA date=200710221139)] Started in 17s:906ms
      23:22:28,433 INFO [Version] Hibernate Annotations 3.2.1.GA
      23:22:28,558 INFO [Environment] Hibernate 3.2.4.sp1
      23:22:28,637 INFO [Environment] hibernate.properties not found
      23:22:28,652 INFO [Environment] Bytecode provider name : javassist
      23:22:28,699 INFO [Environment] using JDK 1.4 java.sql.Timestamp handling
      23:22:30,043 INFO [AnnotationBinder] Binding entity from annotated class: test.Flight
      23:22:30,652 INFO [EntityBinder] Bind entity test.Flight on table tbl_flight
      23:22:32,012 INFO [DriverManagerConnectionProvider] Using Hibernate built-in connection pool (not for production use!)
      23:22:32,027 INFO [DriverManagerConnectionProvider] Hibernate connection pool size: 10
      23:22:32,027 INFO [DriverManagerConnectionProvider] autocommit mode: false
      23:22:32,043 INFO [DriverManagerConnectionProvider] using driver: oracle.jdbc.driver.OracleDriver at URL: jdbc:oracle:thin:@47.168.58.53:5121:mcpdb
      23:22:32,043 INFO [DriverManagerConnectionProvider] connection properties: {user=polguc_1, password=pwdPin_1_2pwdPin_1_2}
      23:22:32,527 INFO [SettingsFactory] RDBMS: Oracle, version: Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production
      With the Partitioning, OLAP, Data Mining and Real Application Testing options
      23:22:32,527 INFO [SettingsFactory] JDBC driver: Oracle JDBC driver, version: 10.2.0.1.0
      23:22:32,699 INFO [Dialect] Using dialect: org.hibernate.dialect.Oracle10gDialect
      23:22:32,762 INFO [TransactionFactoryFactory] Transaction strategy: org.hibernate.transaction.JTATransactionFactory
      23:22:32,824 INFO [NamingHelper] JNDI InitialContext properties:{}
      23:22:32,840 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup
      23:22:32,855 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup
      23:22:32,871 INFO [SettingsFactory] Automatic flush during beforeCompletion(): disabled
      23:22:32,871 INFO [SettingsFactory] Automatic session close at end of transaction: disabled
      23:22:32,871 INFO [SettingsFactory] JDBC batch size: 15
      23:22:32,871 INFO [SettingsFactory] JDBC batch updates for versioned data: disabled
      23:22:32,871 INFO [SettingsFactory] Scrollable result sets: enabled
      23:22:32,871 INFO [SettingsFactory] JDBC3 getGeneratedKeys(): disabled
      23:22:32,887 INFO [SettingsFactory] Connection release mode: auto
      23:22:32,887 INFO [SettingsFactory] Default batch fetch size: 1
      23:22:32,887 INFO [SettingsFactory] Generate SQL with comments: disabled
      23:22:32,887 INFO [SettingsFactory] Order SQL updates by primary key: disabled
      23:22:32,887 INFO [SettingsFactory] Order SQL inserts for batching: disabled
      23:22:32,887 INFO [SettingsFactory] Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
      23:22:32,933 INFO [ASTQueryTranslatorFactory] Using ASTQueryTranslatorFactory
      23:22:32,933 INFO [SettingsFactory] Query language substitutions: {}
      23:22:32,933 INFO [SettingsFactory] JPA-QL strict compliance: disabled
      23:22:32,933 INFO [SettingsFactory] Second-level cache: enabled
      23:22:32,933 INFO [SettingsFactory] Query cache: disabled
      23:22:32,933 INFO [SettingsFactory] Cache provider: org.hibernate.cache.NoCacheProvider
      23:22:32,933 INFO [SettingsFactory] Optimize cache for minimal puts: disabled
      23:22:32,949 INFO [SettingsFactory] Structured second-level cache entries: disabled
      23:22:32,996 INFO [SettingsFactory] Echoing all SQL to stdout
      23:22:33,012 INFO [SettingsFactory] Statistics: disabled
      23:22:33,012 INFO [SettingsFactory] Deleted entity synthetic identifier rollback: disabled
      23:22:33,012 INFO [SettingsFactory] Default entity-mode: pojo
      23:22:33,012 INFO [SettingsFactory] Named query checking : enabled
      23:22:33,246 INFO [SessionFactoryImpl] building session factory
      23:22:34,699 INFO [SessionFactoryObjectFactory] Factory name: hibernate/HibernateFactory
      23:22:34,699 INFO [NamingHelper] JNDI InitialContext properties:{}
      23:22:34,715 INFO [NamingHelper] Creating subcontext: hibernate
      23:22:34,730 INFO [SessionFactoryObjectFactory] Bound factory to JNDI name: hibernate/HibernateFactory
      23:22:34,730 WARN [SessionFactoryObjectFactory] InitialContext did not implement EventContext
      23:22:34,793 INFO [SchemaExport] Running hbm2ddl schema export
      23:22:34,840 INFO [SchemaExport] exporting generated schema to database
      23:22:35,215 INFO [SchemaExport] schema export complete
      23:22:35,230 INFO [NamingHelper] JNDI InitialContext properties:{}
      23:22:51,512 INFO [NamingHelper] JNDI InitialContext properties:{}
      23:22:52,480 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup
      23:22:52,480 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup
      23:22:53,621 INFO [NamingHelper] JNDI InitialContext properties:{}
      23:23:10,652 INFO [STDOUT] Hibernate: select hibernate_sequence.nextval from dual
      23:23:12,496 INFO [STDOUT] Hibernate: insert into tbl_flight (name, id) values (?, ?)
      Listening for transport dt_socket at address: 8787


      Do you think this is a bug? Or am i missing something? Any idea will be appreciated.. Thanks in advance.

        • 1. Re: Problem Using Annotated Beans with JTA. Data is not writ
          taranis

          Here is Hibernate Trace, it seems like Hibernate thinks that the Entity is Transient in these lines, but i can't understand why.

          [org.hibernate.event.def.AbstractSaveEventListener] transient instance of: test.Flight
          2009-06-01 14:11:08,466 TRACE [org.hibernate.event.def.DefaultPersistEventListener] saving transient instance


          2009-06-01 14:11:08,404 DEBUG [org.hibernate.impl.SessionFactoryImpl] obtaining JTA TransactionManager
          2009-06-01 14:11:08,404 INFO [org.hibernate.util.NamingHelper] JNDI InitialContext properties:{}
          2009-06-01 14:11:08,404 DEBUG [org.hibernate.impl.SessionFactoryImpl] Checking 0 named HQL queries
          2009-06-01 14:11:08,404 DEBUG [org.hibernate.impl.SessionFactoryImpl] Checking 0 named SQL queries
          2009-06-01 14:11:08,419 INFO [org.hibernate.util.NamingHelper] JNDI InitialContext properties:{}
          2009-06-01 14:11:08,419 INFO [org.hibernate.transaction.TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup
          2009-06-01 14:11:08,419 INFO [org.hibernate.transaction.TransactionManagerLookupFactory] instantiated TransactionManagerLookup
          2009-06-01 14:11:08,419 INFO [org.hibernate.util.NamingHelper] JNDI InitialContext properties:{}
          2009-06-01 14:11:08,451 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
          2009-06-01 14:11:08,451 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 12438546684
          2009-06-01 14:11:08,466 TRACE [org.hibernate.event.def.AbstractSaveEventListener] transient instance of: test.Flight
          2009-06-01 14:11:08,466 TRACE [org.hibernate.event.def.DefaultPersistEventListener] saving transient instance
          2009-06-01 14:11:08,466 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
          2009-06-01 14:11:08,466 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
          2009-06-01 14:11:08,466 TRACE [org.hibernate.connection.DriverManagerConnectionProvider] total checked-out connections: 0
          2009-06-01 14:11:08,466 TRACE [org.hibernate.connection.DriverManagerConnectionProvider] using pooled JDBC connection, pool size: 0
          2009-06-01 14:11:08,466 DEBUG [org.hibernate.SQL] select hibernate_sequence.nextval from dual
          2009-06-01 14:11:08,466 INFO [STDOUT] Hibernate: select hibernate_sequence.nextval from dual
          2009-06-01 14:11:08,466 TRACE [org.hibernate.jdbc.AbstractBatcher] preparing statement
          2009-06-01 14:11:08,748 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 1
          2009-06-01 14:11:08,748 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
          2009-06-01 14:11:08,748 TRACE [org.hibernate.jdbc.AbstractBatcher] closing statement
          2009-06-01 14:11:08,748 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
          2009-06-01 14:11:08,748 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
          2009-06-01 14:11:08,748 TRACE [org.hibernate.connection.DriverManagerConnectionProvider] returning connection to pool, pool size: 1
          2009-06-01 14:11:08,748 DEBUG [org.hibernate.id.SequenceHiLoGenerator] new hi value: 1
          2009-06-01 14:11:08,748 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 10, using strategy: org.hibernate.id.SequenceHiLoGenerator
          2009-06-01 14:11:08,748 TRACE [org.hibernate.event.def.AbstractSaveEventListener] saving [test.Flight#10]
          2009-06-01 14:11:08,763 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] flushing session
          2009-06-01 14:11:08,763 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] processing flush-time cascades
          2009-06-01 14:11:08,763 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] dirty checking collections
          2009-06-01 14:11:08,763 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] Flushing entities and processing referenced collections
          2009-06-01 14:11:08,763 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] Processing unreferenced collections
          2009-06-01 14:11:08,763 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] Scheduling collection removes/(re)creates/updates
          2009-06-01 14:11:08,763 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 1 insertions, 0 updates, 0 deletions to 1 objects
          2009-06-01 14:11:08,763 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
          2009-06-01 14:11:08,763 DEBUG [org.hibernate.pretty.Printer] listing entities:
          2009-06-01 14:11:08,763 DEBUG [org.hibernate.pretty.Printer] test.Flight{id=10, name=flightName}
          2009-06-01 14:11:08,763 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] executing flush
          2009-06-01 14:11:08,763 TRACE [org.hibernate.jdbc.ConnectionManager] registering flush begin
          2009-06-01 14:11:08,763 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Inserting entity: [test.Flight#10]
          2009-06-01 14:11:08,763 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
          2009-06-01 14:11:08,763 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
          2009-06-01 14:11:08,763 TRACE [org.hibernate.connection.DriverManagerConnectionProvider] total checked-out connections: 0
          2009-06-01 14:11:08,763 TRACE [org.hibernate.connection.DriverManagerConnectionProvider] using pooled JDBC connection, pool size: 0
          2009-06-01 14:11:08,763 DEBUG [org.hibernate.SQL] insert into tbl_flight (name, id) values (?, ?)
          2009-06-01 14:11:08,763 INFO [STDOUT] Hibernate: insert into tbl_flight (name, id) values (?, ?)
          2009-06-01 14:11:08,763 TRACE [org.hibernate.jdbc.AbstractBatcher] preparing statement
          2009-06-01 14:11:08,763 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Dehydrating entity: [test.Flight#10]
          2009-06-01 14:11:08,779 TRACE [org.hibernate.type.StringType] binding 'flightName' to parameter: 1
          2009-06-01 14:11:08,779 TRACE [org.hibernate.type.LongType] binding '10' to parameter: 2
          2009-06-01 14:11:08,779 DEBUG [org.hibernate.jdbc.AbstractBatcher] Executing batch size: 1
          2009-06-01 14:11:08,779 DEBUG [org.hibernate.jdbc.Expectations] success of batch update unknown: 0
          2009-06-01 14:11:08,779 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
          2009-06-01 14:11:08,779 TRACE [org.hibernate.jdbc.AbstractBatcher] closing statement
          2009-06-01 14:11:08,779 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
          2009-06-01 14:11:08,779 TRACE [org.hibernate.jdbc.ConnectionManager] registering flush end
          2009-06-01 14:11:08,779 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
          2009-06-01 14:11:08,779 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
          2009-06-01 14:11:08,779 TRACE [org.hibernate.connection.DriverManagerConnectionProvider] returning connection to pool, pool size: 1
          2009-06-01 14:11:08,779 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] post flush
          2009-06-01 14:11:08,779 TRACE [org.hibernate.transaction.CacheSynchronization] transaction before completion callback
          2009-06-01 14:11:08,779 TRACE [org.hibernate.transaction.CacheSynchronization] automatically flushing session
          2009-06-01 14:11:08,779 TRACE [org.hibernate.impl.SessionImpl] automatically flushing session
          2009-06-01 14:11:08,779 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] flushing session
          2009-06-01 14:11:08,779 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] processing flush-time cascades
          2009-06-01 14:11:08,779 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] dirty checking collections
          2009-06-01 14:11:08,779 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] Flushing entities and processing referenced collections
          2009-06-01 14:11:08,779 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] Processing unreferenced collections
          2009-06-01 14:11:08,779 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] Scheduling collection removes/(re)creates/updates
          2009-06-01 14:11:08,779 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
          2009-06-01 14:11:08,779 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
          2009-06-01 14:11:08,779 DEBUG [org.hibernate.pretty.Printer] listing entities:
          2009-06-01 14:11:08,779 DEBUG [org.hibernate.pretty.Printer] test.Flight{id=10, name=flightName}
          2009-06-01 14:11:08,779 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] executing flush
          2009-06-01 14:11:08,779 TRACE [org.hibernate.jdbc.ConnectionManager] registering flush begin
          2009-06-01 14:11:08,779 TRACE [org.hibernate.jdbc.ConnectionManager] registering flush end
          2009-06-01 14:11:08,779 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
          2009-06-01 14:11:08,779 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] post flush
          2009-06-01 14:11:08,779 TRACE [org.hibernate.jdbc.JDBCContext] before transaction completion
          2009-06-01 14:11:08,779 TRACE [org.hibernate.impl.SessionImpl] before transaction completion
          2009-06-01 14:11:08,779 TRACE [org.hibernate.transaction.CacheSynchronization] transaction after completion callback, status: 3
          2009-06-01 14:11:08,779 TRACE [org.hibernate.jdbc.JDBCContext] after transaction completion
          2009-06-01 14:11:08,779 TRACE [org.hibernate.impl.SessionImpl] after transaction completion
          2009-06-01 14:11:08,779 TRACE [org.hibernate.transaction.CacheSynchronization] automatically closing session
          2009-06-01 14:11:08,779 TRACE [org.hibernate.impl.SessionImpl] automatically closing session
          2009-06-01 14:11:08,779 TRACE [org.hibernate.impl.SessionImpl] closing session
          2009-06-01 14:11:08,779 TRACE [org.hibernate.jdbc.ConnectionManager] connection already null in cleanup : no action