Transactions being ignored without any message

haustier · **Joined:** Tue Aug 08, 2006 11:11 am **Posts:** 7

Hibernate version: 3.2cr2
Hibernate Tools version: 3.2 beta6
Hibernate Annotations version: 3.2cr1
Name and version of the database you are using: HSQL 1.8
<property name="hibernate.connection.url">jdbc:hsqldb:file:/Users/david/work/WebPage</property>
Mapping documents: Annotations

Code between sessionFactory.openSession() and session.close():

Code:

      Session db = HibernateUtil.getSession();
      db.beginTransaction();
      User admin = new User();
      admin.setUsername("admin");
      admin.setPassword("admin");
      db.save(admin);
      PageHeader header = new PageHeader();
      header.setContent("");
      db.save(header);
      PageFooter footer = new PageFooter();
      footer.setContent("");
      db.save(footer);
      PageBody body = new PageBody();
      body.setContent("");
      db.save(body);
      Page aPage = new Page();
      aPage.setHeader(header);
      aPage.setFooter(footer);
      aPage.setBody(body);
      aPage.setName("");
      db.save(aPage);
      db.getTransaction().commit();
      db.close();
      System.out.println("finished");

The generated SQL (show_sql=true):

Code:

Hibernate: insert into User (id, username, password) values (null, ?, ?)
Hibernate: call identity()
Hibernate: insert into PageObject (id) values (null)
Hibernate: call identity()
Hibernate: insert into PageHeader (content, id) values (?, ?)
Hibernate: insert into PageObject (id) values (null)
Hibernate: call identity()
Hibernate: insert into PageFooter (content, id) values (?, ?)
Hibernate: insert into PageObject (id) values (null)
Hibernate: call identity()
Hibernate: insert into PageBody (content, id) values (?, ?)
Hibernate: insert into Page (id, owner_id, name, header_id, footer_id, body_id) values (null, ?, ?, ?, ?, ?)
Hibernate: call identity()

-----------------------------------------

Hi,
i am trying to write a setup routine for a small webapp i'm wrinting. Code is as given above. When i run the setup, i get following output:

Code:

log4j:WARN No appenders could be found for logger (org.hibernate.cfg.annotations.Version).
log4j:WARN Please initialize the log4j system properly.
[b]finished[/b]

But there is nothing inserted into my database. (and there are no exceptions...)

Thanks for your help!

haustier · **Joined:** Tue Aug 08, 2006 11:11 am **Posts:** 7

I'm sorry for the bump, but i didn't make progress on this problem. I would be very thankful for any help.

denis.etienne · **Posted:** Sun Aug 20, 2006 11:30 am

Increase log4.xml threshold to DEBUG for console.

Check you have

Code:

17:31:57,921 DEBUG [SessionImpl] opened session at timestamp: 4735336111484928
17:31:57,921 DEBUG [JDBCTransaction] begin

and

Code:

31:58,328 DEBUG [JDBCTransaction] commit
31:58,328 DEBUG [SessionImpl] automatically flushing session
....
31:58,328 DEBUG [JDBCTransaction] committed JDBC Connection

Adapt your settings for hibernate.transaction.factory_class & hibernate.transaction.manager_lookup_class
<prop key="hibernate.transaction.factory_class">org.hibernate.transaction.JTATransactionFactory</prop>
<prop key="hibernate.transaction.manager_lookup_class">org.hibernate.transaction.JBossTransactionManagerLookup</prop>

For a simple application without any webapp container, I have:

Code:

17:31:56,812 INFO  [TransactionFactoryFactory] Using default transaction strategy (direct JDBC transactions)
17:31:56,812 INFO  [TransactionManagerLookupFactory] No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)

Minimal log4j.xml to put in your classpath:

Code:

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="false">

   <!-- ================================= -->
   <!-- Preserve messages in a local file -->
   <!-- ================================= -->

   <!-- A time/date based rolling appender -->
   <appender name="FILE" class="org.apache.log4j.DailyRollingFileAppender">
      <param name="File" value="debug.log"/>
      <param name="Append" value="false"/>

      <!-- Rollover at midnight each day -->
      <param name="DatePattern" value="'.'yyyy-MM-dd"/>

      <layout class="org.apache.log4j.PatternLayout">
         <!-- The default pattern: Date Priority [Category] Message\n -->
         <param name="ConversionPattern" value="%d %-5p [%c] %m%n"/>

      </layout>
   </appender>

   <!-- ============================== -->
   <!-- Append messages to the console -->
   <!-- ============================== -->

   <appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
      <param name="Target" value="System.out"/>
      <param name="Threshold" value="DEBUG"/>

      <layout class="org.apache.log4j.PatternLayout">
         <!-- The default pattern: Date Priority [Category] Message\n -->
         <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%c{1}] %m%n"/>
      </layout>
   </appender>


   <root>
      <appender-ref ref="CONSOLE"/>
   </root>


</log4j:configuration>

haustier · **Joined:** Tue Aug 08, 2006 11:11 am **Posts:** 7

Relevant part of the log:

Code:

59:47,457 DEBUG [AbstractBatcher] closing statement
59:47,458 DEBUG [JDBCTransaction] commit
59:47,458 DEBUG [SessionImpl] automatically flushing session
59:47,463 DEBUG [AbstractFlushingEventListener] flushing session
59:47,466 DEBUG [AbstractFlushingEventListener] processing flush-time cascades
59:47,483 DEBUG [AbstractFlushingEventListener] dirty checking collections
59:47,484 DEBUG [AbstractFlushingEventListener] Flushing entities and processing referenced collections
59:47,584 DEBUG [AbstractFlushingEventListener] Processing unreferenced collections
59:47,586 DEBUG [AbstractFlushingEventListener] Scheduling collection removes/(re)creates/updates
59:47,587 DEBUG [AbstractFlushingEventListener] Flushed: 0 insertions, 0 updates, 0 deletions to 5 objects
59:47,587 DEBUG [AbstractFlushingEventListener] Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
59:47,606 DEBUG [Printer] listing entities:
59:47,608 DEBUG [Printer] herbipolis.User{password=admin, username=admin, id=1}
59:47,609 DEBUG [Printer] herbipolis.Page{footer=herbipolis.PageFooter#2, owner=null, header=herbipolis.PageHeader#1, name=, body=herbipolis.PageBody#3, id=1}
59:47,610 DEBUG [Printer] herbipolis.PageHeader{content=, id=1}
59:47,610 DEBUG [Printer] herbipolis.PageBody{content=, id=3}
59:47,612 DEBUG [Printer] herbipolis.PageFooter{content=, id=2}
59:47,613 DEBUG [AbstractFlushingEventListener] executing flush
59:47,613 DEBUG [ConnectionManager] registering flush begin
59:47,614 DEBUG [ConnectionManager] registering flush end
59:47,614 DEBUG [AbstractFlushingEventListener] post flush
59:47,616 DEBUG [JDBCContext] before transaction completion
59:47,617 DEBUG [SessionImpl] before transaction completion
59:47,618 DEBUG [JDBCTransaction] committed JDBC Connection
59:47,618 DEBUG [JDBCContext] after transaction completion
59:47,619 DEBUG [ConnectionManager] aggressively releasing JDBC connection
59:47,620 DEBUG [ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
59:47,636 DEBUG [DriverManagerConnectionProvider] returning connection to pool, pool size: 1
59:47,685 DEBUG [SessionImpl] after transaction completion
59:47,748 DEBUG [SessionImpl] closing session
59:47,748 DEBUG [ConnectionManager] connection already null in cleanup : no action
finished

Does this say, that it included my objects? 0 insertions looks like theyre being ignored.

Code:

18:59:47,587 DEBUG [AbstractFlushingEventListener] Flushed: 0 insertions, 0 updates, 0 deletions to 5 objects
18:59:47,587 DEBUG [AbstractFlushingEventListener] Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections

Full log is here: http://herbipolis.eu/downloads/log.txt

Thanks for your help!

PS.: Session opened, etc. are in the full log.

denis.etienne · **Posted:** Sun Aug 20, 2006 3:36 pm

When insertion really works, you get something like this:

Code:

33:26,203 DEBUG [JDBCTransaction] begin
33:26,203 DEBUG [ConnectionManager] opening JDBC connection
33:26,218 DEBUG [DriverManagerConnectionProvider] total checked-out connections: 0
33:26,218 DEBUG [DriverManagerConnectionProvider] using pooled JDBC connection, pool size: 0
33:26,218 DEBUG [JDBCTransaction] current autocommit status: false
33:26,218 DEBUG [JDBCContext] after transaction begin
33:26,218 DEBUG [AbstractSaveEventListener] transient instance of: detienne.org.Person
33:26,218 DEBUG [DefaultPersistEventListener] saving transient instance
33:26,234 DEBUG [AbstractSaveEventListener] saving [detienne.org.Person#<null>]
33:26,234 DEBUG [AbstractSaveEventListener] executing insertions
33:26,234 DEBUG [Cascade] processing cascade ACTION_PERSIST for: detienne.org.Person
33:26,234 DEBUG [Cascade] done processing cascade ACTION_PERSIST for: detienne.org.Person
33:26,250 DEBUG [WrapVisitor] Wrapped collection in role: detienne.org.Person.events
33:26,265 DEBUG [AbstractSaveEventListener] executing identity-insert immediately
33:26,265 DEBUG [AbstractEntityPersister] Inserting entity: detienne.org.Person (native id)
33:26,265 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
33:26,265 DEBUG [SQL] insert into person (age, firstname, lastname) values (?, ?, ?)
Hibernate: insert into person (age, firstname, lastname) values (?, ?, ?)

And you have:

Code:

59:46,279 DEBUG [JDBCTransaction] begin
59:46,280 DEBUG [ConnectionManager] opening JDBC connection
59:46,281 DEBUG [DriverManagerConnectionProvider] total checked-out connections: 0
59:46,281 DEBUG [DriverManagerConnectionProvider] using pooled JDBC connection, pool size: 0
59:46,282 DEBUG [JDBCTransaction] current autocommit status: false
59:46,283 DEBUG [JDBCContext] after transaction begin
59:46,298 DEBUG [DefaultSaveOrUpdateEventListener] saving transient instance
59:46,307 DEBUG [AbstractSaveEventListener] saving [herbipolis.User#<null>]
59:46,308 DEBUG [AbstractSaveEventListener] executing insertions
59:46,516 DEBUG [AbstractSaveEventListener] executing identity-insert immediately
59:46,518 DEBUG [AbstractEntityPersister] Inserting entity: herbipolis.User (native id)
59:46,522 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
59:46,523 DEBUG [SQL] insert into User (id, username, password) values (null, ?, ?)

I can not see any difference except you I used session.persist() [Make a transient instance persistent] and you used session.saveOrUpdate() [Either save() or update() the given instance, depending upon the value of its identifier property] but your object has a null id.
Try session.save() or session.persist() instead.

haustier · **Joined:** Tue Aug 08, 2006 11:11 am **Posts:** 7

I used save() before, changed it to persist() now. Result:

Quote:

23:27:48,871 DEBUG [JDBCTransaction] begin
23:27:48,872 DEBUG [ConnectionManager] opening JDBC connection
23:27:48,872 DEBUG [DriverManagerConnectionProvider] total checked-out connections: 0
23:27:48,873 DEBUG [DriverManagerConnectionProvider] using pooled JDBC connection, pool size: 0
23:27:48,873 DEBUG [JDBCTransaction] current autocommit status: false
23:27:48,874 DEBUG [JDBCContext] after transaction begin
23:27:48,965 DEBUG [AbstractSaveEventListener] transient instance of: herbipolis.User
23:27:48,966 DEBUG [DefaultPersistEventListener] saving transient instance
23:27:48,977 DEBUG [AbstractSaveEventListener] saving [herbipolis.User#<null>]
23:27:48,978 DEBUG [AbstractSaveEventListener] executing insertions
23:27:49,064 DEBUG [AbstractSaveEventListener] executing identity-insert immediately
23:27:49,107 DEBUG [AbstractEntityPersister] Inserting entity: herbipolis.User (native id)
23:27:49,110 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
23:27:49,111 DEBUG [SQL] insert into User (id, username, password) values (null, ?, ?)

Nothing changes but the DefaultPersistEventListener. Btw, i set hibernate SQL logging to off, since its logged with log4j. So there is nearly no difference here.
A difference i see is that in your log the SQL insert has no id column, where it has one in my insert.

Code:

insert into person (age, firstname, lastname) values (?, ?, ?)

Code:

insert into User (id, username, password) values (null, ?, ?)

But id generation should work. I set it to

Code:

   @Id
   @GeneratedValue(strategy=GenerationType.IDENTITY)
   private Long id;

i my User class.

denis.etienne · **Posted:** Mon Aug 21, 2006 1:19 am

http://www.hibernate.org/116.687.html

http://opensource.atlassian.com/project ... e/HHH-1114

The tutorial http://www.hibernate.org/hib_docs/v3/re ... orial.html

uses

Code:

<property name="connection.url">jdbc:hsqldb:hsql://localhost</property>

Code:

   <!-- This mbean should be used only when using tcp connections. Uncomment
   when the tcp based connection-url is used. -->
   <mbean code="org.jboss.jdbc.HypersonicDatabase" 
     name="jboss:service=Hypersonic">
     <attribute name="Port">1701</attribute>
     <attribute name="Silent">true</attribute>
     <attribute name="Database">default</attribute>
     <attribute name="Trace">false</attribute>
     <attribute name="No_system_exit">true</attribute>
   </mbean>
 

   <!-- This mbean can be used when using in process persistent db
   <mbean code="org.jboss.jdbc.HypersonicDatabase" 
     name="jboss:service=Hypersonic,database=localDB">
     <attribute name="Database">localDB</attribute>
     <attribute name="InProcessMode">true</attribute>
   </mbean>
 -->

haustier · **Joined:** Tue Aug 08, 2006 11:11 am **Posts:** 7

Quote:

http://www.hibernate.org/116.687.html

Thank you very much. I didn't test the fix, but i use that setup for testing. I guess thats my problem. Sorry that i overread it in the FAQ.