2

In very short, my dao session.save method does not commit (UPDATE: and nor does the related service method) unless I manually specify session.flush().

This problem has been discussed once before on stackoverflow here. But there is no satisfactory answer yet, and I believe to force flush programmatically is bad practice. Help with diagnoses would be helpful.

My Service Layer:

@Transactional(readOnly = false, propagation = Propagation.REQUIRES_NEW)
public void saveTestType(TestType tt) throws TestStructureException
{
    SS.getLogger().debug("Saving tt: Id before saving is"+tt.getId());

    testTypeDao.saveNewTestType(tt);
    SS.getLogger().debug("Saving tt: Id after saving is"+tt.getId());

}

My Dao Layer

@Transactional(propagation = Propagation.MANDATORY)
public void saveNewTestType(TestType tt)  throws TestStructureException
{
    Session session = this.sessionFactory.openSession();
    try
    {
        SS.getLogger().debug("Saving TT: "+tt);
        session.saveOrUpdate(tt);
        session.flush();

    }
    catch(Exception e)
    {
        SS.getLogger().error(e.getMessage(),e);
        throw new TestStructureException(e.getMessage(),e.getStackTrace());
    }
}

My appContext.xml (I expect I have a bit of overkill in here)

<beans xmlns="http://www.springframework.org/schema/beans"
 xmlns:context="http://www.springframework.org/schema/context"
 xmlns:mvc="http://www.springframework.org/schema/mvc" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
 xmlns:tx="http://www.springframework.org/schema/tx"
 xsi:schemaLocation="  
   http://www.springframework.org/schema/beans 
   http://www.springframework.org/schema/beans/spring-beans-3.2.xsd
   http://www.springframework.org/schema/aop 
   http://www.springframework.org/schema/aop/spring-aop-3.2.xsd 
   http://www.springframework.org/schema/context
   http://www.springframework.org/schema/context/spring-context-3.1.xsd 
   http://www.springframework.org/schema/tx
   http://www.springframework.org/schema/tx/spring-tx-3.2.xsd 
   http://www.springframework.org/schema/mvc
   http://www.springframework.org/schema/mvc/spring-mvc-3.2.xsd">

<!-- View Resolver -->
 
  <bean id="jspViewResolver"
        class="org.springframework.web.servlet.view.InternalResourceViewResolver">
        <property name="viewClass"
            value="org.springframework.web.servlet.view.JstlView" />
        <property name="prefix" value="/WEB-INF/jsp/" />
        <property name="suffix" value=".jsp" />
    </bean>
 
 <!-- i18n -->
 <bean id="messageSource"
  class="org.springframework.context.support.ReloadableResourceBundleMessageSource">
  <property name="basename" value="classpath:messages" />
  <property name="defaultEncoding" value="UTF-8" />
 </bean>

 <bean id="localeChangeInterceptor"
  class="org.springframework.web.servlet.i18n.LocaleChangeInterceptor">
  <property name="paramName" value="lang" />
 </bean>

 <bean id="localeResolver"
  class="org.springframework.web.servlet.i18n.CookieLocaleResolver">
  <property name="defaultLocale" value="en" />
 </bean>

 <bean id="handlerMapping"
  class="org.springframework.web.servlet.mvc.annotation.DefaultAnnotationHandlerMapping">
  <property name="interceptors">
   <ref bean="localeChangeInterceptor" />
  </property>
 </bean>

 <!-- Hibernate -->
 <bean id="dataSource" class="com.mchange.v2.c3p0.ComboPooledDataSource"
  destroy-method="close">
  <property name="driverClass" value="org.postgresql.Driver" />
  <property name="jdbcUrl" value="jdbc:postgresql://localhost/test" />
  <property name="user" value="testuser" />
  <property name="password" value="buddybuddy" />



  <!-- C3P0 properties refer: http://www.mchange.com/projects/c3p0/ -->

  <property name="acquireIncrement" value="2" />
  <property name="minPoolSize" value="3" />
  <property name="maxPoolSize" value="50" />
  <property name="maxIdleTime" value="600" />
 </bean>



 <!-- Hibernate session factory -->

 <bean id="sfhbmSessionFactory"
  class="org.springframework.orm.hibernate4.LocalSessionFactoryBean">
  <property name="dataSource">
   <ref bean="dataSource" />
  </property>
  <property name="annotatedClasses">
   <list>
    <value>com.prototype2.model.user.UserAdmin</value>
    <value>com.prototype2.model.assessment.MultipleChoiceItem</value>
    ...
    <value>com.prototype2.model.scores.UserRawScore</value>
    <value>com.prototype2.model.scores.UserTrueScore</value>
   </list>
  </property>
  <property name="mappingResources">
   <list>
    <value>hibernatemap.cfg.xml</value>
   </list>
  </property>



  <property name="hibernateProperties">
   <props>
    <prop key="hibernate.dialect">org.hibernate.dialect.PostgreSQLDialect</prop>
    <prop key="hibernate.hbm2ddl.auto">update</prop>
    <prop key="temp.use_jdbc_metadata_defaults">false</prop>
    <prop key="hibernate.archive.autodetection">class</prop>
    <prop key="show_sql">true</prop>
    <prop key="hibernate.format_sql">true</prop>
    <prop key="hibernate.enable_lazy_load_no_trans">true</prop>
   </props>
  </property>


  <property name="packagesToScan">
   <array>
    <value>com.prototype2.model.assessment</value>
    <value>com.prototype2.model.user</value>
    <value>com.prototype2.model.scores</value>
    <value>com.prototype2.model.business</value>
    <value>com.prototype2.dao.factory</value>
    <value>com.prototype2.dao.user</value>
    <value>com.prototype2.dao.testadministration</value>
    <value>com.prototype2.service.user</value>
    <value>com.prototype2.service.testadministration</value>
   </array>
  </property>
 </bean>


 <bean id="transactionManager"
  class="org.springframework.orm.hibernate4.HibernateTransactionManager">
  <property name="sessionFactory" ref="sfhbmSessionFactory" />

 </bean>

 <tx:annotation-driven transaction-manager="transactionManager" />
 
    <context:component-scan base-package="com.prototype2.model.assessment,
    com.prototype2.model.user,
    com.prototype2.model.scores,
    com.prototype2.model.business,
    com.prototype2.dao.factory,
    com.prototype2.dao.user,
    com.prototype2.dao.testadministration,
 com.prototype2.service.user,
    com.prototype2.service.testadministration"/>
    
    
 <!-- DAO beans -->
 <bean id="userDao" class="com.prototype2.dao.user.UserDaoImpl">
  <property name="sessionFactory" ref="sfhbmSessionFactory" />
 </bean>

 <bean id="businessDao" class="com.prototype2.dao.user.BusinessDaoImpl">
  <property name="sessionFactory" ref="sfhbmSessionFactory" />
 </bean>
 
 <bean id="testTypeDao" class="com.prototype2.dao.testadministration.TestTypeDaoImpl">
  <property name="sessionFactory" ref="sfhbmSessionFactory" />
 </bean>



 <!-- Service beans -->
 <bean id="auService" class="com.prototype2.service.user.AdminUserServiceImpl">
  <property name="userDao" ref="userDao" />
 </bean>

 <bean id="businessService" class="com.prototype2.service.user.BusinessServiceImpl">
  <property name="businessDao" ref="businessDao" />
 </bean>
 
 <bean id="testTypeService" class="com.prototype2.service.testadministration.TestTypeServiceImpl">
  <property name="testTypeDao" ref="testTypeDao" />
 </bean>

 <!-- validation -->
 <mvc:annotation-driven validator="validator" />


 <bean id="validator"
  class="org.springframework.validation.beanvalidation.LocalValidatorFactoryBean">
  <property name="providerClass" value="org.hibernate.validator.HibernateValidator" />
 </bean>
</beans>

UPDATE: The insert was not found either with sql query, web view or junit test. The following is the junit test:

package com.prototype2.test.service;

import static org.junit.Assert.assertFalse;
import static org.junit.Assert.assertTrue;
import static org.junit.Assert.fail;

import java.util.ArrayList;
import java.util.List;

import org.junit.Before;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.test.context.ContextConfiguration;
import org.springframework.test.context.junit4.SpringJUnit4ClassRunner;

import com.prototype2.model.assessment.TestType;
import com.prototype2.model.assessment.TestUnitType;
import com.prototype2.service.testadministration.TestTypeService;
import com.prototype2.test.testrunner.TestSS;

@RunWith(SpringJUnit4ClassRunner.class)
@ContextConfiguration("classpath:AssessmentAdmin-servlet.xml")
public class TestUnitServiceCreateTTTest
{

@Autowired
private TestTypeService testTypeService;
private List<TestUnitType> blist = new ArrayList<TestUnitType>();
private int originalTTCount=0;
private int newTTCount=0;


@Before
public void prepTestType()
{
    TestSS.getLogger().info("testGetTuts");
    blist = testTypeService.getTestUnitTypes(TestSS.getBusiness().getId());
    originalTTCount=testTypeService.getTestTypes(TestSS.getBusiness().getId()).size();
    TestSS.getLogger().debug("originalTTCount= "+originalTTCount);
}

@Test
public void testGetTTTuts()
{

    try
    {
        TestType tt = new TestType();
        tt.setBusiness(TestSS.getBusiness());
        tt.setTestTypeName("Basic Personality Test");
        tt.addAssociatedTestTypeTestUnitType(blist.get(0));
        testTypeService.saveTestType(tt);

        newTTCount=testTypeService.getTestTypes(TestSS.getBusiness().getId()).size();


        TestSS.getLogger().info("newTTCount=" + newTTCount);


        assertTrue(newTTCount>originalTTCount);
        assertFalse(null==tt.getId());
    } catch (Exception e)
    {
        TestSS.getLogger().error(e.getMessage(), e);
        fail();
    }
}

}

UPDATE: Logs without and then with session.fluch. Notice the insert takes place with Flush on. Again, I stress, I have this problem whether going through junit test case to service or through webpage and controller to service.

==========LOGS WITHOUT FLUSH ON DAO======================================
*******originalTTCount= 2

[DEBUG] 2015-08-16 14:52:11,511: jake.prototype2.model.assessment.TestType.sortTestUnitTypePosition(TestType.java:427) associatedTestUnitTypes size=0

[DEBUG] 2015-08-16 14:52:11,514: org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:226) Obtaining JDBC connection

[DEBUG] 2015-08-16 14:52:11,514: com.mchange.v2.resourcepool.BasicResourcePool.trace(BasicResourcePool.java:1747) trace com.mchange.v2.resourcepool.BasicResourcePool@4312eb27 [managed: 11, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@5ed4b3e)

[DEBUG] 2015-08-16 14:52:11,515: org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:232) Obtained JDBC connection

[DEBUG] 2015-08-16 14:52:11,515: org.hibernate.engine.transaction.spi.AbstractTransactionImpl.begin(AbstractTransactionImpl.java:160) begin

[DEBUG] 2015-08-16 14:52:11,515: org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:69) initial autocommit status: true

[DEBUG] 2015-08-16 14:52:11,516: org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:71) disabling autocommit

[DEBUG] 2015-08-16 14:52:11,516: jake.prototype2.service.testadministration.TestTypeServiceImpl.saveTestType(TestTypeServiceImpl.java:71) Saving tt: Id before saving is null

[DEBUG] 2015-08-16 14:52:11,517: jake.prototype2.dao.testadministration.TestTypeDaoImpl.saveNewTestType(TestTypeDaoImpl.java:137) Saving TT: TestType [id=null, testTypeName=Basic Personality TestBusiness=jake.prototype2.model.business.Business@20]

With Test Type Test Unit Type Id=null TestUnitTypeId= 81Algebra One

[DEBUG] 2015-08-16 14:52:11,518: org.hibernate.engine.jdbc.spi.SqlStatementLogger.logStatement(SqlStatementLogger.java:109) 
    select
        nextval ('hibernate_sequence')

[DEBUG] 2015-08-16 14:52:11,518: org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:226) Obtaining JDBC connection


[DEBUG] 2015-08-16 14:52:11,520: org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:232) Obtained JDBC connection

[DEBUG] 2015-08-16 14:52:11,524: org.hibernate.id.SequenceGenerator.generateHolder(SequenceGenerator.java:127) Sequence identifier generated: BasicHolder[java.lang.Long[1682]]

[DEBUG] 2015-08-16 14:52:11,524: org.hibernate.event.internal.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:131) Generated identifier: 1682, using strategy: org.hibernate.id.SequenceGenerator

[DEBUG] 2015-08-16 14:52:11,525: org.hibernate.engine.jdbc.spi.SqlStatementLogger.logStatement(SqlStatementLogger.java:109) 
    select
        nextval ('hibernate_sequence')

[DEBUG] 2015-08-16 14:52:11,526: org.hibernate.id.SequenceGenerator.generateHolder(SequenceGenerator.java:127) Sequence identifier generated: BasicHolder[java.lang.Long[1683]]

[DEBUG] 2015-08-16 14:52:11,527: org.hibernate.event.internal.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:131) Generated identifier: 1683, using strategy: org.hibernate.id.SequenceGenerator

[DEBUG] 2015-08-16 14:52:11,528: jake.prototype2.service.testadministration.TestTypeServiceImpl.saveTestType(TestTypeServiceImpl.java:74) Saving tt: Id after saving is1682

[DEBUG] 2015-08-16 14:52:11,528: org.hibernate.engine.transaction.spi.AbstractTransactionImpl.commit(AbstractTransactionImpl.java:175) committing

[DEBUG] 2015-08-16 14:52:11,529: org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doCommit(JdbcTransaction.java:113) committed JDBC Connection

[DEBUG] 2015-08-16 14:52:11,529: org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.releaseManagedConnection(JdbcTransaction.java:126) re-enabling autocommit

[DEBUG] 2015-08-16 14:52:11,529: org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.releaseConnection(LogicalConnectionImpl.java:246) Releasing JDBC connection

[DEBUG] 2015-08-16 14:52:11,530: com.mchange.v2.async.ThreadPoolAsynchronousRunner.postRunnable(ThreadPoolAsynchronousRunner.java:236) com.mchange.v2.async.ThreadPoolAsynchronousRunner@7b3d5973: Adding task to queue -- com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@5ca15100

[DEBUG] 2015-08-16 14:52:11,530: com.mchange.v2.resourcepool.BasicResourcePool.trace(BasicResourcePool.java:1747) trace com.mchange.v2.resourcepool.BasicResourcePool@4312eb27 [managed: 11, unused: 0, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@5ed4b3e)

[DEBUG] 2015-08-16 14:52:11,531: org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.releaseConnection(LogicalConnectionImpl.java:264) Released JDBC connection

[DEBUG] 2015-08-16 14:52:11,532: jake.prototype2.test.service.TestUnitServiceCreateTTTest.testGetTTTuts(TestUnitServiceCreateTTTest.java:54) 






*****finished service
 ================================================================================
===================LOGS WITH FLUSH ON DAO=======================================



*******originalTTCount= 2


[DEBUG] 2015-08-16 14:59:39,732: org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:226) Obtaining JDBC connection

[DEBUG] 2015-08-16 14:59:39,732: com.mchange.v2.resourcepool.BasicResourcePool.trace(BasicResourcePool.java:1747) trace com.mchange.v2.resourcepool.BasicResourcePool@74b41e24 [managed: 10, unused: 0, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@5e81cf0a)

[DEBUG] 2015-08-16 14:59:39,733: org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:232) Obtained JDBC connection

[DEBUG] 2015-08-16 14:59:39,733: org.hibernate.engine.transaction.spi.AbstractTransactionImpl.begin(AbstractTransactionImpl.java:160) begin

[DEBUG] 2015-08-16 14:59:39,733: org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:69) initial autocommit status: true

[DEBUG] 2015-08-16 14:59:39,734: org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:71) disabling autocommit

[DEBUG] 2015-08-16 14:59:39,734: jake.prototype2.service.testadministration.TestTypeServiceImpl.saveTestType(TestTypeServiceImpl.java:71) Saving tt: Id before saving isnull

[DEBUG] 2015-08-16 14:59:39,737: jake.prototype2.dao.testadministration.TestTypeDaoImpl.saveNewTestType(TestTypeDaoImpl.java:137) Saving TT: TestType [id=null, testTypeName=Basic Personality TestBusiness=jake.prototype2.model.business.Business@20]

With Test Type Test Unit Type Id=null TestUnitTypeId= 81Algebra One

[DEBUG] 2015-08-16 14:59:39,738: org.hibernate.engine.jdbc.spi.SqlStatementLogger.logStatement(SqlStatementLogger.java:109) 
    select
        nextval ('hibernate_sequence')

[DEBUG] 2015-08-16 14:59:39,739: org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:226) Obtaining JDBC connection

[DEBUG] 2015-08-16 14:59:39,739: com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:587) acquire test -- pool size: 10; target_pool_size: 11; desired target? 11

[DEBUG] 2015-08-16 14:59:39,740: com.mchange.v2.resourcepool.BasicResourcePool.incrementPendingAcquires(BasicResourcePool.java:450) incremented pending_acquires: 2

[DEBUG] 2015-08-16 14:59:39,740: com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.<init>(BasicResourcePool.java:1788) Starting acquisition series. Incremented pending_acquires [2],  attempts_remaining: 30

[DEBUG] 2015-08-16 14:59:39,741: com.mchange.v2.async.ThreadPoolAsynchronousRunner.postRunnable(ThreadPoolAsynchronousRunner.java:236) com.mchange.v2.async.ThreadPoolAsynchronousRunner@12a57fe: Adding task to queue -- com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@46cf19d4

[DEBUG] 2015-08-16 14:59:39,741: com.mchange.v2.resourcepool.BasicResourcePool.incrementPendingAcquires(BasicResourcePool.java:450) incremented pending_acquires: 3

[DEBUG] 2015-08-16 14:59:39,742: com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.<init>(BasicResourcePool.java:1788) Starting acquisition series. Incremented pending_acquires [3],  attempts_remaining: 30

[DEBUG] 2015-08-16 14:59:39,742: com.mchange.v2.async.ThreadPoolAsynchronousRunner.postRunnable(ThreadPoolAsynchronousRunner.java:236) com.mchange.v2.async.ThreadPoolAsynchronousRunner@12a57fe: Adding task to queue -- com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@7fdc07fa

[DEBUG] 2015-08-16 14:59:39,743: com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1390) awaitAvailable(): com.mchange.v2.c3p0.impl.NewPooledConnection@5e81cf0a

[DEBUG] 2015-08-16 14:59:39,743: com.mchange.v2.resourcepool.BasicResourcePool.trace(BasicResourcePool.java:1747) trace com.mchange.v2.resourcepool.BasicResourcePool@74b41e24 [managed: 10, unused: 0, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@5e81cf0a)

[DEBUG] 2015-08-16 14:59:39,800: com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:283) com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager@1fbcc531.acquireResource() returning. 

[DEBUG] 2015-08-16 14:59:39,801: com.mchange.v2.resourcepool.BasicResourcePool.trace(BasicResourcePool.java:1747) trace com.mchange.v2.resourcepool.BasicResourcePool@74b41e24 [managed: 11, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@5e81cf0a)

[DEBUG] 2015-08-16 14:59:39,801: com.mchange.v2.resourcepool.BasicResourcePool._decrementPendingAcquires(BasicResourcePool.java:471) decremented pending_acquires: 2

[DEBUG] 2015-08-16 14:59:39,801: com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1825) Acquisition series terminated successfully. Decremented pending_acquires [2],  attempts_remaining: 30

[DEBUG] 2015-08-16 14:59:39,806: com.mchange.v2.resourcepool.BasicResourcePool.trace(BasicResourcePool.java:1747) trace com.mchange.v2.resourcepool.BasicResourcePool@74b41e24 [managed: 11, unused: 0, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@5e81cf0a)

[DEBUG] 2015-08-16 14:59:39,809: org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:232) Obtained JDBC connection

[DEBUG] 2015-08-16 14:59:39,816: org.hibernate.id.SequenceGenerator.generateHolder(SequenceGenerator.java:127) Sequence identifier generated: BasicHolder[java.lang.Long[1679]]

[DEBUG] 2015-08-16 14:59:39,817: org.hibernate.event.internal.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:131) Generated identifier: 1679, using strategy: org.hibernate.id.SequenceGenerator

[DEBUG] 2015-08-16 14:59:39,818: org.hibernate.engine.jdbc.spi.SqlStatementLogger.logStatement(SqlStatementLogger.java:109) 
    select
        nextval ('hibernate_sequence')

[DEBUG] 2015-08-16 14:59:39,819: org.hibernate.id.SequenceGenerator.generateHolder(SequenceGenerator.java:127) Sequence identifier generated: BasicHolder[java.lang.Long[1680]]

[DEBUG] 2015-08-16 14:59:39,820: org.hibernate.event.internal.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:131) Generated identifier: 1680, using strategy: org.hibernate.id.SequenceGenerator

[DEBUG] 2015-08-16 14:59:39,821: org.hibernate.event.internal.AbstractFlushingEventListener.prepareEntityFlushes(AbstractFlushingEventListener.java:149) Processing flush-time cascades

[DEBUG] 2015-08-16 14:59:39,822: org.hibernate.event.internal.AbstractFlushingEventListener.prepareCollectionFlushes(AbstractFlushingEventListener.java:189) Dirty checking collections

[DEBUG] 2015-08-16 14:59:39,823: org.hibernate.engine.internal.Collections.processReachableCollection(Collections.java:194) Collection found: [jake.prototype2.model.assessment.TestType.associatedFullTests#1679], was: [<unreferenced>] (initialized)

[DEBUG] 2015-08-16 14:59:39,824: org.hibernate.engine.internal.Collections.processReachableCollection(Collections.java:194) Collection found: [jake.prototype2.model.assessment.TestType.associatedTestTypeTestUnitTypes#1679], was: [<unreferenced>] (initialized)

[DEBUG] 2015-08-16 14:59:39,824: org.hibernate.engine.internal.Collections.processReachableCollection(Collections.java:194) Collection found: [jake.prototype2.model.assessment.TestType.associatedUsers#1679], was: [<unreferenced>] (initialized)

[DEBUG] 2015-08-16 14:59:39,825: org.hibernate.event.internal.AbstractFlushingEventListener.logFlushResults(AbstractFlushingEventListener.java:123) Flushed: 2 insertions, 0 updates, 0 deletions to 2 objects

[DEBUG] 2015-08-16 14:59:39,825: org.hibernate.event.internal.AbstractFlushingEventListener.logFlushResults(AbstractFlushingEventListener.java:130) Flushed: 3 (re)creations, 0 updates, 0 removals to 3 collections

[DEBUG] 2015-08-16 14:59:39,826: org.hibernate.internal.util.EntityPrinter.toString(EntityPrinter.java:114) Listing entities:

[DEBUG] 2015-08-16 14:59:39,826: org.hibernate.internal.util.EntityPrinter.toString(EntityPrinter.java:121) jake.prototype2.model.assessment.TestType{business=jake.prototype2.model.business.Business#1, created=null, testTypeName=Basic Personality Test, associatedUsers=[], id=1679, updated=2015-08-16 14:59:39.818, associatedFullTests=[], associatedTestTypeTestUnitTypes=[jake.prototype2.model.assessment.TestTypeTestUnitType#1680]}

[DEBUG] 2015-08-16 14:59:39,827: org.hibernate.internal.util.EntityPrinter.toString(EntityPrinter.java:121) jake.prototype2.model.assessment.TestTypeTestUnitType{positionInTest=1, testUnitType=jake.prototype2.model.assessment.TestUnitType#81, business=jake.prototype2.model.business.Business#1, created=null, testType=jake.prototype2.model.assessment.TestType#1679, id=1680, updated=Sun Aug 16 14:59:39 PDT 2015}

[DEBUG] 2015-08-16 14:59:39,828: org.hibernate.engine.jdbc.spi.SqlStatementLogger.logStatement(SqlStatementLogger.java:109) 
    insert 
    into
        TestType
        (businessId, created, testTypeName, updated, id) 
    values
        (?, ?, ?, ?, ?)

[DEBUG] 2015-08-16 14:59:39,842: org.hibernate.engine.jdbc.spi.SqlStatementLogger.logStatement(SqlStatementLogger.java:109) 
    insert 
    into
        TestTypeTestUnitType
        (businessId, created, positionInTest, TestTypeId, TestUnitTypeId, updated, id) 
    values
        (?, ?, ?, ?, ?, ?, ?)

[DEBUG] 2015-08-16 14:59:39,868: jake.prototype2.service.testadministration.TestTypeServiceImpl.saveTestType(TestTypeServiceImpl.java:74) Saving tt: Id after saving is1679

[DEBUG] 2015-08-16 14:59:39,868: org.hibernate.engine.transaction.spi.AbstractTransactionImpl.commit(AbstractTransactionImpl.java:175) committing

[DEBUG] 2015-08-16 14:59:39,869: org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doCommit(JdbcTransaction.java:113) committed JDBC Connection

[DEBUG] 2015-08-16 14:59:39,869: org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.releaseManagedConnection(JdbcTransaction.java:126) re-enabling autocommit

[DEBUG] 2015-08-16 14:59:39,869: org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.releaseConnection(LogicalConnectionImpl.java:246) Releasing JDBC connection

[DEBUG] 2015-08-16 14:59:39,870: com.mchange.v2.async.ThreadPoolAsynchronousRunner.postRunnable(ThreadPoolAsynchronousRunner.java:236) com.mchange.v2.async.ThreadPoolAsynchronousRunner@12a57fe: Adding task to queue -- com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@73e16fb6

[DEBUG] 2015-08-16 14:59:39,870: com.mchange.v2.resourcepool.BasicResourcePool.trace(BasicResourcePool.java:1747) trace com.mchange.v2.resourcepool.BasicResourcePool@74b41e24 [managed: 11, unused: 0, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@5e81cf0a)

[DEBUG] 2015-08-16 14:59:39,871: org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.releaseConnection(LogicalConnectionImpl.java:264) Released JDBC connection

[DEBUG] 2015-08-16 14:59:39,871: jake.prototype2.test.service.TestUnitServiceCreateTTTest.testGetTTTuts(TestUnitServiceCreateTTTest.java:54) 






*****finished service

I would very much like to remove my programmatic flush and follow spring convention. Any help, advice, or explanation would be deeply appreciated

Community
  • 1
  • 1
Jake
  • 4,322
  • 6
  • 39
  • 83
  • flush() does not commit. Never. You're confusing flushing and committing. What do you actually expect to happen when not flushing explicitely, and what happens instead? – JB Nizet Aug 16 '15 at 08:03
  • I understand that flush does not commit. I expect that the spring transaction advice will commit once the dao method has exited. However, it does not commit unless I programmatically flush. – Jake Aug 16 '15 at 08:14
  • To be more explicit, I am saving a new parent along with some new children (i.e., new inserts in one to many relation) and also new relations with existing children to a new parent. I need this to happen as soon as the session.save is called, but it is not happening unless the session.flush is called – Jake Aug 16 '15 at 08:18
  • Why would it commit when the dao method exist, since the transaction is started by the saveTestType service method. The transaction will commit once the method which has started it returns. Flushing in the DAO doesn't change that. It flushes (so Hibernate writes the in-memoty changes to the database), but does not commit. The commit still happens after the service method returns. – JB Nizet Aug 16 '15 at 08:18
  • Why do you care about that? The updates will be written eventually, at most before the commit. – JB Nizet Aug 16 '15 at 08:20
  • clearly, I am doing something wrong. It is not committing at the end of the service method. My problem is that I don;t know what I am doing wrong. (I can wait a few milliseconds for the commit, but the commit simply does not happen) – Jake Aug 16 '15 at 08:27
  • 1
    How do you determine if you system issues a commit or not? – Jens Schauder Aug 16 '15 at 08:30
  • direct sqll query on psotgres client, unit testing, and web view....none of these methods saw data in db. – Jake Aug 16 '15 at 08:35
  • NOTE: the logs would show that hibernate had attained a sequence for the pk and added this as the bean id. But nothing went into the db – Jake Aug 16 '15 at 08:36
  • Please post the complete test class. The annotations on the class might matter. – Jens Schauder Aug 16 '15 at 08:52
  • Please also log all the transaction handling of spring and of hibernate. And let us know what you see. – Jens Schauder Aug 16 '15 at 08:58
  • @Jens Schauder full test class posted.The logs are extensive and posting here would be difficult. The key feature was that I saw the sequence was called for pk, but no insert statement made. I did see a commit but only one, which I think was for the sequence retrieval – Jake Aug 16 '15 at 09:04
  • So did you see more or the same commits, when you do a flush? – Jens Schauder Aug 16 '15 at 09:16
  • Does a commit happen before you do the query? – Jens Schauder Aug 16 '15 at 09:17
  • I have added logs with and without flush. The logs are the same whether I run junit test or via browser and controller. Also, either way, without flush, the commit never happens. – Jake Aug 16 '15 at 22:13
  • 4
    The problem is you are using `openSession` instead of `getCurrentSession`. The later integrates properly with springs tx management the first opens a new session outside the scope of the current transaction and as such you have to manage it yourself. In short change the `getCurrentSession` instead. – M. Deinum Aug 17 '15 at 05:53

2 Answers2

3

Judging from your comments, this is what happens:

  • code enters saveTestType starting a transaction

  • code enters saveNewTestType (still using the same transaction)

  • if you flush your session, changes get written to the database. Note that no commit is happening

  • code leaves saveNewTestType; Nothing happens here. No flush, no commit, no change to state of the transaction

  • you query the data you just stored in the database. That query goes against the database (not the session). Since it only sees what is written to the database, it only sees the new entities when you did a flush. Note that still no commit happened so far.

  • code leaves saveTestType. This ends the transaction, issues a commit, which in turn causes a flush to happen.

You have various option to get the behavior you want:

  1. Issue a flush manually. Very flexible, but most of the time way to flexible. And you already said, you don't like that.

  2. Configure your FlushMode to AUTO or ALWAYS, ensuring that your changes get flushed before queries get executed.

  3. Move the queries outside the scope of the initial transaction, into their own transaction.

Jens Schauder
  • 77,657
  • 34
  • 181
  • 348
  • Very informative! Especially your explanation of the role of session. I will look into flushmode. However, prior to my programmatic flush, the code was not committing even after all methods exited. I checked via unit test and web views and database. Even closing the entire webapp did not prompt a commit. – Jake Aug 16 '15 at 08:34
  • Please inlcude your test in the question. Note that the SpringJUnit4ClassRunner changes the behavior of transactions. Especially it does a rollback at the end of the test. – Jens Schauder Aug 16 '15 at 08:36
  • AUTO is the default. BTW, I don't see how flushing would cause the transaction to commit. The only explanation I see to the OP's description of the problem is that the flush mode is set to MANUAL. In that case, the transaction would be committed whether the flush is there or not, but not executing the flush() would not write to the database. – JB Nizet Aug 16 '15 at 08:38
  • @JBNizet my theory so far is that the commit never happens in the scope of what ever test the OP is running, but what he sees are simply the effects of flushing happening or not within a single transaction. – Jens Schauder Aug 16 '15 at 08:41
  • @JB Nizet where do I configure the flush mode? – Jake Aug 16 '15 at 08:43
  • @Jens Schauder. Test case posted. There are three transactions (I think) as each call to the service should be a distinct transaction, right? – Jake Aug 16 '15 at 08:44
  • @Jake you shouldn't have to. AUTO is the default. The Hibernate Sessin has getFlushMode()/setFlushMode() methods. – JB Nizet Aug 16 '15 at 08:48
  • @JBNizet, thanks. As noted, I've been around long enough to know that the best approach is to be as conventional as possible. I won't mess with it if I don't have to (and I haven't used the setFlushMode so I assume it is still on auto) – Jake Aug 16 '15 at 08:51
  • He uses `openSession` instead of `getCurrentSession`, which is the root of the problem he has. – M. Deinum Aug 17 '15 at 05:55
2

Credit for answer goes to @M.Deinem

The problem is you are using openSession instead of getCurrentSession. The later integrates properly with springs tx management the first opens a new session outside the scope of the current transaction and as such you have to manage it yourself. In short change the getCurrentSession instead.

In short, this could have been a critical error had I left the session.flush in. I would have been working outside of Spring tx management without knowing I was working outside the bounds. This is the kind of error that can lead to long term subtle and not so subtle problems on a large scale app.

Thanks a million to M.Deinem in particular and stackoverflow in general for the help.

Jake
  • 4,322
  • 6
  • 39
  • 83