-->
These old forums are deprecated now and set to read-only. We are waiting for you on our new forums!
More modern, Discourse-based and with GitHub/Google/Twitter authentication built-in.

View unanswered posts | View active topics


Board index » Hibernate & Java Persistence » Hibernate Users

All times are UTC - 5 hours [ DST ]


Forum locked This topic is locked, you cannot edit posts or make further replies.  Page 1 of 1
  [ 3 posts ] 
  Previous topic | Next topic 
Author Message
jongilmore
 Post subject: entityInterceptor postFlush not inserting when part of a Tx
PostPosted: Thu Dec 13, 2007 11:38 am 
Newbie

Joined: Tue Sep 13, 2005 3:57 am
Posts: 5
Hello,

I have added an entityInterceptor to my session factory to insert audit logs for changes to my business model objects. The interceptor works great until I add transaction control to my application, then I the following output in my log..
Quote:
2007-12-13 14:33:21,631 INFO [STDOUT] Hibernate: update CUSTOMER set CUSTOMER_ID=?, GLOBAL_ID=?, CUSTOMER_NAME=?, EMAIL=?, CUSTOMER_TYPE=?, ACCOUNT_MANAGER_ID=?, SALES_MANAGER_ID=?, STATUS_ID=?, EFFECTIVE_DATE=?, TEST_PERIOD=?, SUPPORT_LOCATION=?, LICENCES=?, REGION_ID=?, SUBREGION_ID=?, ADDRESS_ID=?, VIEW_PROFILE_ID=?, SERVICE_DETAILS_ID=?, UNIVERSE_DETAILS_ID=? where ID=?
2007-12-13 14:33:21,631 INFO [STDOUT] Hibernate: update ADDRESS set ADD_LINE_1=?, ADD_LINE_2=?, ADD_LINE_3=?, ADD_LINE_4=?, ADD_LINE_5=?, NOTES=?, TELEPHONE=?, FAX=? where ADDRESS_ID=?
2007-12-13 14:33:21,631 INFO [STDOUT] Hibernate: update CONTACT set CONTACT_NAME=?, TELEPHONE=?, EMAIL=?, NOTES=? where CONTACT_ID=?
2007-12-13 14:33:21,631 INFO [STDOUT] 14:33:21,631 DEBUG [AbstractSaveEventListener] transient instance of: com.ftid.custadmin.model.AuditLog
2007-12-13 14:33:21,631 INFO [STDOUT] 14:33:21,631 DEBUG [DefaultSaveOrUpdateEventListener] saving transient instance
2007-12-13 14:33:21,631 INFO [STDOUT] 14:33:21,631 DEBUG [IncrementGenerator] fetching initial value: select max(ID) from AUDIT_LOG
2007-12-13 14:33:21,631 INFO [STDOUT] 14:33:21,631 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-12-13 14:33:21,631 INFO [STDOUT] 14:33:21,631 DEBUG [SQL] select max(ID) from AUDIT_LOG
2007-12-13 14:33:21,631 INFO [STDOUT] Hibernate: select max(ID) from AUDIT_LOG
2007-12-13 14:33:21,631 INFO [STDOUT] 14:33:21,631 DEBUG [AbstractBatcher] preparing statement
2007-12-13 14:33:21,631 INFO [STDOUT] 14:33:21,631 DEBUG [IncrementGenerator] first free id: 10
2007-12-13 14:33:21,631 INFO [STDOUT] 14:33:21,631 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-12-13 14:33:21,631 INFO [STDOUT] 14:33:21,631 DEBUG [AbstractBatcher] closing statement
2007-12-13 14:33:21,631 INFO [STDOUT] 14:33:21,631 DEBUG [AbstractSaveEventListener] generated identifier: 10, using strategy: org.hibernate.id.IncrementGenerator
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,631 DEBUG [AbstractSaveEventListener] saving [com.ftid.custadmin.model.AuditLog#10]
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,647 DEBUG [Cascade] processing cascade ACTION_SAVE_UPDATE for: com.ftid.custadmin.model.AuditLog
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,647 DEBUG [Cascade] done processing cascade ACTION_SAVE_UPDATE for: com.ftid.custadmin.model.AuditLog
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,647 DEBUG [WrapVisitor] Wrapped collection in role: com.ftid.custadmin.model.AuditLog.auditItems
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,647 DEBUG [Cascade] processing cascade ACTION_SAVE_UPDATE for: com.ftid.custadmin.model.AuditLog
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,647 DEBUG [Cascade] cascade ACTION_SAVE_UPDATE for collection: com.ftid.custadmin.model.AuditLog.auditItems
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,647 DEBUG [CascadingAction] cascading to saveOrUpdate: com.ftid.custadmin.model.AuditItem
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,647 DEBUG [AbstractSaveEventListener] transient instance of: com.ftid.custadmin.model.AuditItem
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,647 DEBUG [DefaultSaveOrUpdateEventListener] saving transient instance
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,647 DEBUG [IncrementGenerator] fetching initial value: select max(ID) from AUDIT_ITEM
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,647 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,647 DEBUG [SQL] select max(ID) from AUDIT_ITEM
2007-12-13 14:33:21,647 INFO [STDOUT] Hibernate: select max(ID) from AUDIT_ITEM
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,647 DEBUG [AbstractBatcher] preparing statement
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,647 DEBUG [IncrementGenerator] first free id: 33
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,647 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,647 DEBUG [AbstractBatcher] closing statement
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,647 DEBUG [AbstractSaveEventListener] generated identifier: 33, using strategy: org.hibernate.id.IncrementGenerator
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,647 DEBUG [AbstractSaveEventListener] saving [com.ftid.custadmin.model.AuditItem#33]
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,647 DEBUG [Cascade] done cascade ACTION_SAVE_UPDATE for collection: com.ftid.custadmin.model.AuditLog.auditItems
2007-12-13 14:33:21,647 INFO [STDOUT] 14:33:21,647 DEBUG [Cascade] done processing cascade ACTION_SAVE_UPDATE for: com.ftid.custadmin.model.AuditLog



As you can see above, Customer, Address and Contact are updated. Then you can see the hibernate tries to do something with Audit_Log and Audit_Item table but doesn't actually insert anything. This audit stuff is occuring in my entityInterceptor postFlush method.

Here is my Spring config. Note that if I disable the transaction manager stuff then my entity interceptor works like a charm i.e. audit records are inserted.

Code:
    <!-- managers -->
    <bean id="customerManager" class="com.ftid.custadmin.manager.CustomerManagerImpl">
        <property name="customerDao" ref="customerDao"/>
        <property name="viewProfileDao" ref="viewProfileDao"/>
        <property name="vmsDao" ref="vmsDao"/>
        <property name="serviceDetailsDao" ref="serviceDetailsDao"/>
    </bean>
   
    <!-- ensure that the above transactional advice runs for any execution
      of an operation defined by the FooService interface -->
    <aop:config>
        <aop:pointcut id="custManagerOperation" expression="execution(* com.ftid.custadmin.manager.CustomerManager.*(..))"/>
        <aop:advisor advice-ref="txAdvice" pointcut-ref="custManagerOperation"/>
    </aop:config>

    <!-- the transactional advice (i.e. what 'happens'; see the <aop:advisor/> bean below) -->
    <tx:advice id="txAdvice" transaction-manager="txManager">
        <!-- the transactional semantics... -->
        <tx:attributes>
            <tx:method name="*"/>
        </tx:attributes>
    </tx:advice>
   
    <bean id="txManager" class="org.springframework.orm.hibernate3.HibernateTransactionManager">
        <property name="sessionFactory" ref="mySessionFactory"/>
    </bean>   

    <!-- DAOs -->
    <bean id="customerDao" class="com.ftid.custadmin.dao.CustomerDao">
        <property name="sessionFactory" ref="mySessionFactory"/>
    </bean>     
    <bean id="auditLogDao" class="com.ftid.custadmin.dao.AuditLogDao">
        <property name="sessionFactory" ref="sessionFactoryForLogs"/>
    </bean>   
   
    <!-- Hibernate Connection -->
    <bean id="myDataSource" class="org.springframework.jdbc.datasource.DriverManagerDataSource">
        <property name="driverClassName" value="org.postgresql.Driver"/>
        <property name="url" value="jdbc:postgresql://localhost:5432/clientadmin"/>
        <property name="username" value="postgres"/>
        <property name="password" value="P@ssword1"/>
    </bean>
   
    <bean id="mySessionFactory" class="org.springframework.orm.hibernate3.LocalSessionFactoryBean">
        <property name="dataSource" ref="myDataSource"/>
        <property name="mappingDirectoryLocations">
            <list>
                <value>classpath:/com/ftid/custadmin/model/mapping/</value>
            </list>
        </property>
        <property name="hibernateProperties">
            <value>
                hibernate.dialect=org.hibernate.dialect.PostgreSQLDialect
                hibernate.show_sql=true
            </value>           
        </property>
        <property name="entityInterceptor">
            <ref local="auditLogInterceptor"/>
        </property>       
    </bean>
   
    <bean id="auditLogInterceptor" class="com.ftid.custadmin.dao.AuditLogInterceptor">
        <property name="auditLogDao" ref="auditLogDao"/>
    </bean>       
   
    <bean id="sessionFactoryForLogs" class="org.springframework.orm.hibernate3.LocalSessionFactoryBean">
        <property name="dataSource" ref="myDataSource"/>
        <property name="mappingDirectoryLocations">
            <list>
                <value>classpath:/com/ftid/custadmin/model/mapping/</value>
            </list>
        </property>
        <property name="hibernateProperties">
            <value>
                hibernate.dialect=org.hibernate.dialect.PostgreSQLDialect
                hibernate.show_sql=true
            </value>           
        </property>
    </bean>   

and for completeness, here is my postFlush method of my AuditLogInterceptor..

Code:
    public void postFlush(Iterator arg0) throws CallbackException {
        logger.getLogger("org.hibernate").setLevel(Level.DEBUG);
        logger.info("In postFlush of AuditLogInterceptor..");

        ArrayList logs = new ArrayList();
       
        try {
            getAuditLogDao().save(logs);
        } catch (Throwable e) {
            logger.error("Exception thrown in postFlush of auditLogInterceptor", e);
            throw e;
        } finally {
            getLogs().clear();
            logger.getLogger("org.hibernate").setLevel(Level.INFO);           
        }
    }


Any ideas why my transaction control is messing up my audit log interceptor?
Top
 Profile  
 
jongilmore
 Post subject:
PostPosted: Fri Dec 14, 2007 7:42 am 
Newbie

Joined: Tue Sep 13, 2005 3:57 am
Posts: 5
I have found the problem. The save method of my auditLogDao was missing a session.flush() call. This is obviously required when inside a transaction.

i.e.
Quote:
public class AuditLogDao extends HibernateDaoSupport {

public void save(AuditLog object) {
Session session = getSession(false);
try {
System.out.println("saving audit item: " + elem);
session.save(object);
System.out.println("saved audit item!!: " + elem);
}
finally {
session.flush();
releaseSession(session);
}
}
}
Top
 Profile  
 
panth13
 Post subject:
PostPosted: Fri Dec 14, 2007 10:09 am 
Beginner
Beginner

Joined: Tue Apr 24, 2007 12:53 pm
Posts: 28
I have a little hesitation in saying that that is the right solution. I would try to configure the TransactionManager to also wrap the Audit functionality (set it to Transaction Supports). Since you do (or at least should) want the audit trail to be rolled back, if the other changes are rolled back.

Also I'm not really sure that if you did have an error, your transaction would be rolled back. I could be wrong and maybe it does work, but I would still ensure everything is associated with a transation manager.

-B
Top
 Profile  
 
Display posts from previous:  Sort by  
Forum locked This topic is locked, you cannot edit posts or make further replies.  Page 1 of 1
  [ 3 posts ] 

Board index » Hibernate & Java Persistence » Hibernate Users

All times are UTC - 5 hours [ DST ]

You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.