[FIXED] Hibernate EntityManager.merge() does not update database

Issue

I have a Spring MVC webapp using Hibernate, and my problem is that em.merge doesn't respond after the call.

Here is my Controller

@RequestMapping(value = "/updDep", method = RequestMethod.PUT)
      @ResponseBody
      public String updDeps(@RequestBody Department department ) {
        departmentService.addDepartment(department);
        System.out.println("after merge;  in controller");
        return "Success";
    }

And Department Service class with addDepartment() method:

@Repository
public class DepartmentServiceImpl implements  DepartmentService {

    @PersistenceContext(unitName = "MyPersistenceUnit")
    private EntityManager entityManager;
....
//getter/setter entityManager....
...
 @Override
    @Transactional
    public void addDepartment(Department department) {
        System.out.println(department.getName() + " merge: " + department.getId());
        getEntityManager().merge(department);
        getEntityManager().flush();
        System.out.println("after");
    }

So i try to explain problem: After addDepartment(Department department) method is called from my Controllers updDeps(..) method. I see this in my servers log:

SECURITY23 merge: 3
Hibernate:
    select
        department0_.id as
        department0_.name a
    from
        departments departm
    where
        department0_.id=?
Hibernate:
    update
        departments
    set
        name=?
    where
        id=?

And that's all! Why did
System.out.println("after"); and System.out.println("after merge; in controller"); not execute? After em.merge was called nothing happened.

And data in MySQL table still not updated. But if I add

department.setId(null);   

before, like that

@Transactional
    public void addDepartment(Department department) {
        department.setId(null);
        System.out.println(department.getName() + " merge: " + department.getId());
        getEntityManager().merge(department);
        getEntityManager().flush();
        System.out.println("after");
    }

All works and it created new instance in db, but I want update current. What's the problem? UPDATE 1 Project Structure:

PERSISTENCE.XML

 <persistence-unit name="MyPersistenceUnit" transaction-type="RESOURCE_LOCAL">
        <provider>org.hibernate.ejb.HibernatePersistence</provider>
        <properties>
            <property name="hibernate.connection.url" value="jdbc:mysql://localhost:3306/testbd"/>
            <property name="hibernate.connection.driver_class" value="com.mysql.jdbc.Driver"/>
            <property name="hibernate.connection.username" value="root"/>
            <property name="hibernate.connection.password" value="root"/>
            <!--<property name="hibernate.hbm2ddl.import_files" value= "import.sql"/>-->
            <property name="hibernate.show_sql" value="true"/>
            <property name="hibernate.format_sql" value="true"/>
            <property name="hibernate.hbm2ddl.auto" value="update"/>
            <property name="hibernate.dialect" value="org.hibernate.dialect.MySQLDialect"/>
        </properties>
    </persistence-unit>

</persistence>

SPRING CONFIG

 <mvc:annotation-driven />

    <context:annotation-config />
    <context:component-scan base-package="epam.rest" />

    <bean class="org.springframework.web.servlet.view.InternalResourceViewResolver">
        <property name="prefix">
            <value>/WEB-INF/pages/</value>
        </property>
        <property name="suffix">
            <value>.jsp</value>
        </property>
    </bean>

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

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

    </bean>

    <bean id="entityManagerFactory" class="org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean">
         <property name="persistenceUnitName" value="MyPersistenceUnit"/>
    </bean>

    <bean id="transactionManager" class="org.springframework.orm.jpa.JpaTransactionManager">
        <property name="dataSource" ref="dataSource" />
        <property name="entityManagerFactory" ref="entityManagerFactory" />
    </bean>
    <tx:annotation-driven transaction-manager="transactionManager" proxy-target-class="true" />
</beans>

UPDATE 3 ADD MY LOG4J log in period of em.merge() transaction, where I founded ROLLBACK log but I dont know whats the problem?:

08:54:28,291 DEBUG LogicalConnectionImpl:218 - Obtained JDBC connection
08:54:28,291 DEBUG JdbcTransaction:69 - initial autocommit status: true
08:54:28,292 DEBUG JdbcTransaction:71 - disabling autocommit
08:54:28,301 TRACE IdentifierValue:139 - ID unsaved-value: null
08:54:28,302 TRACE AbstractSaveEventListener:504 - Detached instance of: epam.rest.entity.Department
08:54:28,304 TRACE DefaultMergeEventListener:245 - Merging detached instance
08:54:28,310 TRACE DefaultLoadEventListener:240 - Loading entity: [epam.rest.entity.Department#16]
08:54:28,311 TRACE DefaultLoadEventListener:403 - Attempting to resolve: [epam.rest.entity.Department#16]
08:54:28,311 TRACE DefaultLoadEventListener:427 - Object not resolved in any cache: [epam.rest.entity.Department#16]
08:54:28,312 TRACE AbstractEntityPersister:3923 - Fetching entity: [epam.rest.entity.Department#16]
08:54:28,312 DEBUG Loader:2109 - Loading entity: [epam.rest.entity.Department#16]
08:54:28,312 DEBUG SQL:104 - 
    select
        department0_.id as id1_0_0_,
        department0_.name as name2_0_0_ 
    from
        departments department0_ 
    where
        department0_.id=?
08:54:28,314 TRACE JdbcCoordinatorImpl:319 - Registering statement [com.mysql.jdbc.JDBC4PreparedStatement@6c31a161: select department0_.id as id1_0_0_, department0_.name as name2_0_0_ from departments department0_ where department0_.id=** NOT SPECIFIED **]
08:54:28,314 TRACE JdbcCoordinatorImpl:329 - Registering last query statement [com.mysql.jdbc.JDBC4PreparedStatement@6c31a161: select department0_.id as id1_0_0_, department0_.name as name2_0_0_ from departments department0_ where department0_.id=** NOT SPECIFIED **]
08:54:28,320 TRACE BasicBinder:84 - binding parameter [1] as [BIGINT] - 16
08:54:28,320 TRACE Loader:1909 - Bound [2] parameters total
08:54:28,321 TRACE JdbcCoordinatorImpl:374 - Registering result set [com.mysql.jdbc.JDBC4ResultSet@4e1d82e2]
08:54:28,322 TRACE Loader:937 - Processing result set
08:54:28,322 DEBUG Loader:942 - Result set row: 0
08:54:28,323 DEBUG Loader:1476 - Result row: EntityKey[epam.rest.entity.Department#16]
08:54:28,323 TRACE Loader:1652 - Initializing object from ResultSet: [epam.rest.entity.Department#16]
08:54:28,333 TRACE AbstractEntityPersister:2844 - Hydrating entity: [epam.rest.entity.Department#16]
08:54:28,334 TRACE BasicExtractor:74 - Found [REWQQ] as column [name2_0_0_]
08:54:28,337 TRACE Loader:962 - Done processing result set (1 rows)
08:54:28,338 TRACE Loader:1106 - Total objects hydrated: 1
08:54:28,338 DEBUG TwoPhaseLoad:158 - Resolving associations for [epam.rest.entity.Department#16]
08:54:28,343 DEBUG TwoPhaseLoad:277 - Done materializing entity [epam.rest.entity.Department#16]
08:54:28,344 TRACE JdbcCoordinatorImpl:358 - Releasing statement [com.mysql.jdbc.JDBC4PreparedStatement@6c31a161: select department0_.id as id1_0_0_, department0_.name as name2_0_0_ from departments department0_ where department0_.id=16]
08:54:28,344 TRACE JdbcCoordinatorImpl:519 - Closing result set [com.mysql.jdbc.JDBC4ResultSet@4e1d82e2]
08:54:28,345 TRACE JdbcCoordinatorImpl:476 - Closing prepared statement [com.mysql.jdbc.JDBC4PreparedStatement@6c31a161: select department0_.id as id1_0_0_, department0_.name as name2_0_0_ from departments department0_ where department0_.id=16]
08:54:28,345 TRACE JdbcCoordinatorImpl:249 - Starting after statement execution processing [ON_CLOSE]
08:54:28,345 TRACE StatefulPersistenceContext:1022 - Initializing non-lazy collections
08:54:28,346 DEBUG Loader:2133 - Done entity load
08:54:28,352 TRACE UnresolvedEntityInsertActions:121 - No entity insert actions have non-nullable, transient entity dependencies.
08:54:28,353 DEBUG AbstractTransactionImpl:173 - committing
08:54:28,353 TRACE SessionImpl:403 - Automatically flushing session
08:54:28,353 TRACE AbstractFlushingEventListener:82 - Flushing session
08:54:28,355 DEBUG AbstractFlushingEventListener:144 - Processing flush-time cascades
08:54:28,358 TRACE Cascade:151 - Processing cascade ACTION_PERSIST_ON_FLUSH for: epam.rest.entity.Department
08:54:28,359 TRACE Cascade:188 - Done processing cascade ACTION_PERSIST_ON_FLUSH for: epam.rest.entity.Department
08:54:28,359 DEBUG AbstractFlushingEventListener:185 - Dirty checking collections
08:54:28,360 TRACE AbstractFlushingEventListener:200 - Flushing entities and processing referenced collections
08:54:28,365 TRACE AbstractEntityPersister:4097 - epam.rest.entity.Department.name is dirty
08:54:28,366 TRACE DefaultFlushEntityEventListener:642 - Found dirty properties [[epam.rest.entity.Department#16]] : [Ljava.lang.String;@3aa8208a
08:54:28,366 TRACE DefaultFlushEntityEventListener:281 - Updating entity: [epam.rest.entity.Department#16]
08:54:28,371 TRACE AbstractFlushingEventListener:242 - Processing unreferenced collections
08:54:28,371 TRACE AbstractFlushingEventListener:254 - Scheduling collection removes/(re)creates/updates
08:54:28,372 DEBUG AbstractFlushingEventListener:118 - Flushed: 0 insertions, 1 updates, 0 deletions to 1 objects
08:54:28,372 DEBUG AbstractFlushingEventListener:125 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
08:54:28,373 DEBUG EntityPrinter:114 - Listing entities:
08:54:28,373 DEBUG EntityPrinter:121 - epam.rest.entity.Department{id=16, name=REWQQ112}
08:54:28,373 TRACE AbstractFlushingEventListener:327 - Executing flush
08:54:28,383 TRACE AbstractEntityPersister:3166 - Updating entity: [epam.rest.entity.Department#16]
08:54:28,384 TRACE AbstractServiceRegistryImpl:146 - Initializing service [role=org.hibernate.engine.jdbc.batch.spi.BatchBuilder]
08:54:28,391 TRACE AbstractServiceRegistryImpl:146 - Initializing service [role=org.hibernate.service.jmx.spi.JmxService]
08:54:28,393 TRACE BatchBuilderImpl:68 - Building batch [size=1]
08:54:28,395 DEBUG SQL:104 - 
    update
        departments 
    set
        name=? 
    where
        id=?
08:54:28,397 TRACE JdbcCoordinatorImpl:319 - Registering statement [com.mysql.jdbc.JDBC4PreparedStatement@15f07169: update departments set name=** NOT SPECIFIED ** where id=** NOT SPECIFIED **]
08:54:28,397 TRACE AbstractEntityPersister:2780 - Dehydrating entity: [epam.rest.entity.Department#16]
08:54:28,399 TRACE BasicBinder:84 - binding parameter [1] as [VARCHAR] - REWQQ112
08:54:28,400 TRACE BasicBinder:84 - binding parameter [2] as [BIGINT] - 16
08:54:28,436 TRACE JdbcCoordinatorImpl:358 - Releasing statement [com.mysql.jdbc.JDBC4PreparedStatement@15f07169: update departments set name='REWQQ112' where id=16]
08:54:28,437 TRACE JdbcCoordinatorImpl:476 - Closing prepared statement [com.mysql.jdbc.JDBC4PreparedStatement@15f07169: update departments set name='REWQQ112' where id=16]
08:54:28,437 TRACE JdbcCoordinatorImpl:249 - Starting after statement execution processing [ON_CLOSE]
08:54:28,439 TRACE JdbcCoordinatorImpl:249 - Starting after statement execution processing [ON_CLOSE]
08:54:28,440 DEBUG AbstractTransactionImpl:203 - rolling back
08:54:28,480 DEBUG JdbcTransaction:164 - rolled JDBC Connection
08:54:28,481 DEBUG JdbcTransaction:126 - re-enabling autocommit
08:54:28,482 TRACE TransactionCoordinatorImpl:136 - after transaction completion
08:54:28,486 TRACE SessionImpl:624 - after transaction completion
08:54:28,488 TRACE SessionImpl:342 - Closing session
08:54:28,489 TRACE JdbcCoordinatorImpl:171 - Closing JDBC container [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl@26d77937]
08:54:28,490 DEBUG JdbcCoordinatorImpl:173 - HHH000420: Closing un-released batch
08:54:28,490 TRACE LogicalConnectionImpl:164 - Closing logical connection
08:54:28,491 DEBUG LogicalConnectionImpl:232 - Releasing JDBC connection
08:54:28,492 TRACE DriverManagerConnectionProviderImpl:233 - Returning connection to pool, pool size: 1
08:54:28,493 DEBUG LogicalConnectionImpl:250 - Released JDBC connection
08:54:28,493 TRACE LogicalConnectionImpl:176 - Logical connection closed

Solution

I am not sure but I think that's problem with 'detached' objects. Look at this link http://www.objectdb.com/java/jpa/persistence/detach

Answered By - zhurlik
Answer Checked By - Senaida (JavaFixing Volunteer)