Why nothing happens when I persist?

Question

I hope I does not ask a question you already answered, but I am not able to understand my problem... I explain :

I work with Spring and Hibernate, I have a Manager interface, and a Manager that implements my interface. Manager is like this :

@Service
@Transactional
public class ManagerImpl implements Manager {
    @PersistenceContext(type = PersistenceContextType.TRANSACTION, unitName="Service")
    private EntityManager em;

    public void storeHistoricMessage(...params...) throws DBException{
        HistoricMessage historicMessage = new HistoricMessage(); 
        // ... initialization of historicMessage
        try {
            em.persist(historicMessage);
        }
        catch (Exception e){
            // process the exception if exists... 
        }
    }
}

I call my service like this :

@Service
public class OtherManager {
    @Autowired
    private Manager manager;

    public void storeHistoricMessage(...params...) {
        manager.storeHistoricMessage(...params...);
    }
}

My application context is defined like this :

<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans"
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:aop="http://www.springframework.org/schema/aop"
    xmlns:context="http://www.springframework.org/schema/context" xmlns:tx="http://www.springframework.org/schema/tx"
    xsi:schemaLocation="http://www.springframework.org/schema/beans
           http://www.springframework.org/schema/beans/spring-beans-2.5.xsd
           http://www.springframework.org/schema/aop
           http://www.springframework.org/schema/aop/spring-aop-2.5.xsd
           http://www.springframework.org/schema/context
           http://www.springframework.org/schema/context/spring-context-2.5.xsd
           http://www.springframework.org/schema/tx 
           http://www.springframework.org/schema/tx/spring-tx-2.5.xsd">

    <context:component-scan base-package="package" />

    <bean id="JDBCPropertyConfigurer_service"
        class="org.springframework.beans.factory.config.PropertyPlaceholderConfigurer">
        <property name="properties" ref="JDBCProperties_service" />
        <property name="ignoreUnresolvablePlaceholders" value="true" />
    </bean>

    <bean id="JDBCProperties_service"
        class="org.springframework.beans.factory.config.PropertiesFactoryBean">
        <property name="location" value="classpath:jdbc.properties" />
    </bean>

    <tx:annotation-driven transaction-manager="transactionManager_service"/>

    <bean id="transactionManager_service" class="org.springframework.orm.jpa.JpaTransactionManager">
        <property name="entityManagerFactory" ref="entityManagerFactory_service" />
    </bean>

    <!-- datasource -->
    <bean id="dataSource_service"
        class="org.springframework.jdbc.datasource.DriverManagerDataSource">
        <property name="driverClassName" value="${database_service.driverClassName}" />
        <property name="url" value="${database_service.url}" />
        <property name="username" value="${database_service.username}" />
        <property name="password" value="${database_service.password}" />
    </bean>

    <!-- JPA config -->
    <bean id="entityManagerFactory_service"
        class="org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean">
        <property name="dataSource" ref="dataSource_service" />
        <property name="persistenceXmlLocation" value="classpath*:META-INF/persistence.xml" />
        <property name="persistenceUnitName" value="Service" />
        <property name="jpaVendorAdapter">
            <bean class="org.springframework.orm.jpa.vendor.HibernateJpaVendorAdapter">
                <!--
                    <property name="generateDdl" value="${jpa.generateDdl}" />
                    <property name="showSql" value="${jpa.showSql}" /> <property
                    name="hbm2ddl.auto" value="${jpa.hbm2ddl}" />
                -->
            </bean>
        </property>
    </bean>

    <bean class="org.springframework.orm.jpa.support.PersistenceAnnotationBeanPostProcessor" />
</beans>

And Finally, my persistence.xml is like this :

<?xml version="1.0" encoding="UTF-8"?>
<persistence 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_1_0.xsd"
    version="1.0">

    <persistence-unit name="Service" transaction-type="RESOURCE_LOCAL">
        <provider>org.hibernate.ejb.HibernatePersistence</provider>
        <class>package.HistoricMessage</class>

        <properties>
            <property name="hibernate.dialect" value="org.hibernate.dialect.MySQLInnoDBDialect" />
            <property name="hibernate.archive.autodetection" value="class, hbm" />
            <property name="hibernate.show_sql" value="false" />
            <property name="hibernate.format_sql" value="false" />
            <property name="hibernate.hbm2ddl.auto" value="${hibernate.hbm2ddl.auto}" />
        </properties>
    </persistence-unit> 
</persistence>

The problem is that when I persist, nothing happens : no insert in database, no error message, no exception.... I made a lot of tests, and I have perhaps some helps :

• If I try to get back my object with em.find(), I get it... cache optimization ?
• If I trap it, and rename table in database after start service, I have no error, he is always happy...
• If I try em.flush(), it throws a Exception because no transaction is in progress...

Finally, here are TRACE logs I can see :

DEBUG 12-01 10:50:01,362 (SessionImpl.java:<init>:220)  -opened session at timestamp: 13263618013
DEBUG 12-01 10:50:01,362 (JDBCTransaction.java:begin:54)  -begin
DEBUG 12-01 10:50:01,362 (ConnectionManager.java:openConnection:421)  -opening JDBC connection
DEBUG 12-01 10:50:01,363 (DriverManagerDataSource.java:getConnectionFromDriver:163)  -Creating new JDBC DriverManager Connection to [jdbc:mysql://databaseurl]
DEBUG 12-01 10:50:01,378 (JDBCTransaction.java:begin:59)  -current autocommit status: true
DEBUG 12-01 10:50:01,379 (JDBCTransaction.java:begin:62)  -disabling autocommit
TRACE 12-01 10:50:01,380 (JDBCContext.java:afterTransactionBegin:214)  -after transaction begin
DEBUG 12-01 10:50:01,380 (JpaTransactionManager.java:doBegin:348)  -Exposing JPA transaction as JDBC transaction [SimpleConnectionHandle: com.mysql.jdbc.JDBC4Connection@1ff335bb]
TRACE 12-01 10:50:01,381 (TransactionSynchronizationManager.java:bindResource:186)  -Bound value [org.springframework.jdbc.datasource.ConnectionHolder@184c9860] for key [org.springframework.jdbc.datasource.DriverManagerDataSource@65499154] to thread [http-8001-Processor5]
TRACE 12-01 10:50:01,381 (TransactionSynchronizationManager.java:bindResource:186)  -Bound value [org.springframework.orm.jpa.EntityManagerHolder@4ca7d316] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@28ce2c57] to thread [http-8001-Processor5]
TRACE 12-01 10:50:01,381 (TransactionSynchronizationManager.java:initSynchronization:261)  -Initializing transaction synchronization
TRACE 12-01 10:50:01,382 (TransactionAspectSupport.java:prepareTransactionInfo:290)  -Getting transaction for [package.storeHistoricMessage]
storeHistoricMessage (begin of my function)
DEBUG 12-01 10:50:01,382 (EntityManagerFactoryUtils.java:doGetTransactionalEntityManager:194)  -Opening JPA EntityManager
DEBUG 12-01 10:50:01,388 (EntityManagerFactoryUtils.java:doGetTransactionalEntityManager:199)  -Registering transaction synchronization for JPA EntityManager
DEBUG 12-01 10:50:01,389 (SessionImpl.java:<init>:220)  -opened session at timestamp: 13263618013
TRACE 12-01 10:50:01,392 (TransactionSynchronizationManager.java:bindResource:186)  -Bound value [org.springframework.orm.jpa.EntityManagerHolder@69851576] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@20442c19] to thread [http-8001-Processor5]
TRACE 12-01 10:50:01,393 (IdentifierValue.java:isUnsaved:77)  -id unsaved-value strategy UNDEFINED
TRACE 12-01 10:50:01,394 (AbstractSaveEventListener.java:getEntityState:514)  -transient instance of: package.HistoricMessage
TRACE 12-01 10:50:01,394 (DefaultPersistEventListener.java:entityIsTransient:124)  -saving transient instance
DEBUG 12-01 10:50:01,397 (AbstractSaveEventListener.java:saveWithGeneratedId:112)  -generated identifier: ***identifier***, using strategy: org.hibernate.id.Assigned
TRACE 12-01 10:50:01,397 (AbstractSaveEventListener.java:performSave:153)  -saving [package.HistoricMessage#***identifier***]
end of my function
TRACE 12-01 10:50:01,399 (TransactionAspectSupport.java:commitTransactionAfterReturning:319)  -Completing transaction for [package.storeHistoricMessage]
TRACE 12-01 10:50:01,400 (AbstractPlatformTransactionManager.java:triggerBeforeCommit:903)  -Triggering beforeCommit synchronization
TRACE 12-01 10:50:01,400 (AbstractPlatformTransactionManager.java:triggerBeforeCompletion:916)  -Triggering beforeCompletion synchronization
TRACE 12-01 10:50:01,401 (TransactionSynchronizationManager.java:doUnbindResource:232)  -Removed value [org.springframework.orm.jpa.EntityManagerHolder@69851576] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@20442c19] from thread [http-8001-Processor5]
DEBUG 12-01 10:50:01,401 (EntityManagerFactoryUtils.java:closeEntityManager:313)  -Closing JPA EntityManager
TRACE 12-01 10:50:01,401 (SessionImpl.java:close:273)  -closing session
TRACE 12-01 10:50:01,402 (ConnectionManager.java:cleanup:375)  -connection already null in cleanup : no action
DEBUG 12-01 10:50:01,402 (AbstractPlatformTransactionManager.java:processCommit:730)  -Initiating transaction commit
DEBUG 12-01 10:50:01,402 (JpaTransactionManager.java:doCommit:451)  -Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@27b71c12]
DEBUG 12-01 10:50:01,403 (JDBCTransaction.java:commit:103)  -commit
TRACE 12-01 10:50:01,403 (SessionImpl.java:managedFlush:337)  -automatically flushing session
TRACE 12-01 10:50:01,403 (JDBCContext.java:beforeTransactionCompletion:205)  -before transaction completion
TRACE 12-01 10:50:01,404 (SessionImpl.java:beforeTransactionCompletion:393)  -before transaction completion
DEBUG 12-01 10:50:01,405 (JDBCTransaction.java:toggleAutoCommit:193)  -re-enabling autocommit
DEBUG 12-01 10:50:01,406 (JDBCTransaction.java:commit:116)  -committed JDBC Connection
TRACE 12-01 10:50:01,407 (JDBCContext.java:afterTransactionCompletion:219)  -after transaction completion
DEBUG 12-01 10:50:01,407 (ConnectionManager.java:aggressiveRelease:404)  -aggressively releasing JDBC connection
DEBUG 12-01 10:50:01,408 (ConnectionManager.java:closeConnection:441)  -releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
TRACE 12-01 10:50:01,408 (SessionImpl.java:afterTransactionCompletion:422)  -after transaction completion
TRACE 12-01 10:50:01,409 (AbstractPlatformTransactionManager.java:triggerAfterCommit:929)  -Triggering afterCommit synchronization
TRACE 12-01 10:50:01,409 (AbstractPlatformTransactionManager.java:triggerAfterCompletion:945)  -Triggering afterCompletion synchronization
TRACE 12-01 10:50:01,410 (TransactionSynchronizationManager.java:clearSynchronization:315)  -Clearing transaction synchronization
TRACE 12-01 10:50:01,410 (TransactionSynchronizationManager.java:doUnbindResource:232)  -Removed value [org.springframework.orm.jpa.EntityManagerHolder@4ca7d316] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@28ce2c57] from thread [http-8001-Processor5]
TRACE 12-01 10:50:01,410 (TransactionSynchronizationManager.java:doUnbindResource:232)  -Removed value [org.springframework.jdbc.datasource.ConnectionHolder@184c9860] for key [org.springframework.jdbc.datasource.DriverManagerDataSource@65499154] from thread [http-8001-Processor5]
DEBUG 12-01 10:50:01,411 (JpaTransactionManager.java:doCleanupAfterCompletion:534)  -Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@27b71c12] after transaction
DEBUG 12-01 10:50:01,411 (EntityManagerFactoryUtils.java:closeEntityManager:313)  -Closing JPA EntityManager
TRACE 12-01 10:50:01,411 (SessionImpl.java:close:273)  -closing session
TRACE 12-01 10:50:01,412 (ConnectionManager.java:cleanup:375)  -connection already null in cleanup : no action

Thanks a lot for you help !

Edit : I'm very sorry, I understood what happend and you wasn't able to find because I really simplified architecture of my project and I didn't tell you about the reason : In this project, I have several application-context files, and several datasources, so that I use several times.... And with Spring 2.5, you can have only one ! So that I can't use transactions in my second service... To solve that, I used aop like this :

<tx:advice id="txAdviceSelfCare" transaction-manager="transactionManager_service">
    <!-- the transactional semantics... -->
    <tx:attributes>
        <!-- other methods use the default transaction settings (see below) -->
        <tx:method name="*" />
    </tx:attributes>
</tx:advice>

<aop:config>
    <aop:pointcut id="ServiceManagerOperations"
        expression="execution(* package.ServiceManager.*(..))" />
    <aop:advisor advice-ref="txAdviceService"
        pointcut-ref="ServiceManagerOperations" />
</aop:config>

<!-- a PlatformTransactionManager is still required -->
<bean id="transactionManager_service" class="org.springframework.orm.jpa.JpaTransactionManager">
    <property name="entityManagerFactory" ref="entityManagerFactory_service" />
</bean>

Thanks all for your help !

Answer 1

could you try to inspect what really happens on your database ? Try to activate log facilities on that database and if you have such tool installed to sniff network traffic between your Java code and the database server ... it could be useful... You could ask your JPA layer to show SQL generated , it could give you interesting data... My 2 pieces jerome

Answer 2

Change your catch block to do something and watch what it prints.

    try {
        em.persist(historicMessage);
    }
    catch (Exception e){
        e.printStackTrace(); // use a logger if available
    }

You can also change the below property to true to see what's going on.

<property name="hibernate.show_sql" value="true" />

Also, make it a habit to trace method entry/exits using a suitable logging framework such as SLF4J.

Answer 3

Note that the actual insert does not happen in the em.persist statement since the call is transactual, so your try/catch will not do much at all. The actual persist is done when the transaction ends, which is when the service layer call is finished (after return from your method). This knowledge is critical when debugging persistence.

Answer 4

Verify the database where you are looking the details. The log clearly says that commit is done..

DEBUG 12-01 10:50:01,403 (JDBCTransaction.java:commit:103) -commit TRACE 12-01 10:50:01,403 (SessionImpl.java:managedFlush:337) -automatically flushing session TRACE 12-01 10:50:01,403 (JDBCContext.java:beforeTransactionCompletion:205) -before transaction completion TRACE 12-01 10:50:01,404 (SessionImpl.java:beforeTransactionCompletion:393) -before transaction completion DEBUG 12-01 10:50:01,405 (JDBCTransaction.java:toggleAutoCommit:193) -re-enabling autocommit DEBUG 12-01 10:50:01,406 (JDBCTransaction.java:commit:116) -committed JDBC Connection

Answer 5

Place your method call in try catch

public void storeHistoricMessage(...params...) {
    try {
       manager.storeHistoricMessage(...params...);
    } catch (Exception e) {
       e.printStackTrace(); // use a logger if available
    }
}

Data should be persisted at the end of manager.storeHistoricMessage method call (by transaction management proxy) not at em.persist call. You could also try em.flush:

try {
        em.persist(historicMessage);
        em.flush(); //force DB insert
    }...

It looks like you don't see an exception wich is thrown somwhere, problably by transacion manager.