I have a parent class (called MasterProduct) that has a OneToMany relationship to a set of children (class called Variant). The mapping of the objects
if done using hibernate annotations, see below:
Annotation on many to one side:
Code:
@ManyToOne(cascade = {CascadeType.PERSIST, CascadeType.REFRESH}, fetch = FetchType.LAZY)
@JoinColumn(name = Columns.MASTER_PRODUCT, nullable = false)
private MasterProduct masterProduct;
Annotation on one to many side:
Code:
@OneToMany(fetch = FetchType.LAZY, mappedBy = Variant.Attributes.MASTER_PRODUCT)
@OnDelete(action=OnDeleteAction.CASCADE)
@Cascade(value={CascadeType.ALL, CascadeType.DELETE_ORPHAN})
private Set<Variant> variants;
I have a scenario that I have written a JUnit test for which fails. This is what I want to do:
1. Load a Master Product through hibernate from the database
2. Remove a single variant from its set of children
3. Create a new variant passing the master product as the parent to the constructor
4. Call merge() on the variant to persist it to the database.
5. Re-load the Master product from the database
NOTE: I am only calling merge on the new Variant. I have not called merge or any form of persist on the Master Product.
I expect the reloaded MasterProduct to contain the new Variant and also the removed Variant. The removal of the variant should never have been persisted
since I only merged the Variant, not the parent Master Product.
i.e. The test does not save the modified master product and saving the variant should not cascade to the master product.
Unfortunately the JUnit test fails - the master product once reloaded contains the new variant and not the removed variant. Basically the merge() of the
variant cascaded to the master product and then to it's children and persisted the variant remove.
The following line of code is where the test fails[b]
Code:
// we expect the variant count to be one greater than before since we added a new variant.
// the variant we removed should not have been persisted to the database. Therefore it shouldn't
// be removed.
assertEquals("Unexpected number of variants for the CP650.", expectedVariantCount + 1, reloadedVariants.size());
I expect I have made an error in my annotations, but I cannot spot it. Any help would be much appreciated.
[b]Hibernate version:3.2.0.cr2 (annotations 3.2.0.cr1) The junit test code failing:Code:
/**
* Test that the creation of a new variant with a master product does not
* save other changes to the master product. 1. Load a Master Product 2.
* Remove a variant from it 3. Add a new variant to the master product 4.
* Save the new variant 5. Re-load the Master product from the database Post
* condition: Check that the re-loaded master product contains the new
* variant, and the one that was removed. i.e. The test does not save the
* modified master product and saving the variant should not cascade to the
* master product.
* @throws UpdateException
* @throws ValidationException
*/
public void testCreationOfVariantDoesntChangeMP() throws UpdateException, ValidationException
{
this.logExecutingTest(LOG);
final String id = MasterProductDataSetValues.CP650.ID;
final int expectedVariantCount = VariantDataSetValues.CP650_VARIANTS.COUNT;
IGenericCrudDAO<MasterProduct, String> dao = this.getDao();
// load CP650 Master Product
MasterProduct mp = dao.findById(id);
assertNotNull("Looking up the CP650 returned null.", mp);
final Set<Variant> variants = mp.getVariants();
assertEquals("Unexpected number of variants for the CP650.", expectedVariantCount, variants.size());
// Remove a variant from the Master Product
Iterator<Variant> varItr = variants.iterator();
final Variant varToRemove = varItr.next();
final String varToRemoveId = varToRemove.getId();
boolean removed = variants.remove(varToRemove);
// Create a new Variant attached to the Master Product
final String variantName = "CP650-NEW";
final Variant newVariant = new Variant(mp, variantName, "Test variant for CP650 MP");
final IVariantDAO varDao = PicsDAOFactory.HIBERNATE.getVariantDAO();
HibernateUtil.beginTransaction();
Variant savedVariant;
try
{
// save the new variant but not the Master Product
savedVariant = varDao.merge(newVariant);
HibernateUtil.commitTransaction();
}
catch (UpdateException e)
{
HibernateUtil.rollbackTransaction();
throw (e);
}
catch (ValidationException e)
{
HibernateUtil.rollbackTransaction();
throw (e);
}
finally
{
HibernateUtil.closeSession();
}
final String varAddedId = savedVariant.getId();
assertNotNull("Check that the variant was persisted", varAddedId);
dao = this.getDao();
// reload the Master Product
mp = dao.findById(id);
assertNotNull("Looking up the CP650 returned null.", mp);
final Set<Variant> reloadedVariants = mp.getVariants();
// we expect the variant count to be one greater than before since we added a new variant.
// the variant we removed should not have been persisted to the database. Therefore it shouldn't
// be removed.
assertEquals("Unexpected number of variants for the CP650.", expectedVariantCount + 1, reloadedVariants.size());
boolean foundRemovedVar = false;
boolean foundAddedVar = false;
for(Variant var : reloadedVariants)
{
// set whether the variant we removed still exists as we expect
foundRemovedVar = varToRemoveId.equals(var.getId()) || foundRemovedVar;
foundAddedVar = varAddedId.equals(var.getId()) || foundRemovedVar;
}
assertTrue("Unexpectedy does not contain the variant we removed (which in the end was not persisted)", foundRemovedVar);
assertTrue("Unexpectedy does not contain the variant we added", foundAddedVar);
}
Name and version of the database you are using: Derby 10.1The generated SQL (show_sql=true):Code:
Hibernate: insert into ZCOREINV.VARIANT_PROD (LC_CRT_BY_USER, LC_CRT_BY_SYSTEM, LC_CRT_TIMESTAMP, VERSION, VAR_NAME, VAR_DESC, VAR_MPRD_ID, VAR_LAST_REV, ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?)
Hibernate: update ZCOREINV.MASTER_PRODUCT set LC_UPD_BY_USER=?, LC_UPD_BY_SYSTEM=?, LC_UPD_TIMESTAMP=?, VERSION=?, MPRD_DESC=?, MPRD_REF=? where ID=? and VERSION=?
Hibernate: delete from ZCOREINV.VARIANT_PROD where ID=? and VERSION=?
Debug level Hibernate log excerpt:Code:
2006-07-13 15:02:879 [main] DEBUG org.hibernate.transaction.JDBCTransaction [begin() :54] - begin
2006-07-13 15:02:882 [main] DEBUG org.hibernate.jdbc.ConnectionManager [openConnection() :415] - opening JDBC connection
2006-07-13 15:02:885 [main] DEBUG org.hibernate.connection.DriverManagerConnectionProvider [getConnection() :93] - total checked-out connections: 0
2006-07-13 15:02:890 [main] DEBUG org.hibernate.connection.DriverManagerConnectionProvider [getConnection() :99] - using pooled JDBC connection, pool size: 0
2006-07-13 15:02:893 [main] DEBUG org.hibernate.transaction.JDBCTransaction [begin() :59] - current autocommit status: false
2006-07-13 15:02:895 [main] DEBUG org.hibernate.jdbc.JDBCContext [afterTransactionBegin() :203] - after transaction begin
2006-07-13 15:02:831 [main] DEBUG org.hibernate.event.def.AbstractSaveEventListener [getEntityState() :489] - transient instance of: com.dolby.pics.model.impl.Variant
2006-07-13 15:02:834 [main] DEBUG org.hibernate.event.def.DefaultMergeEventListener [entityIsTransient() :139] - merging transient instance
2006-07-13 15:02:837 [main] DEBUG org.hibernate.event.def.DefaultLoadEventListener [proxyOrLoad() :154] - loading entity: [com.dolby.pics.model.impl.MasterProduct#CP650]
2006-07-13 15:02:841 [main] DEBUG org.hibernate.event.def.DefaultLoadEventListener [createProxyIfNecessary() :227] - entity found in session cache
2006-07-13 15:02:846 [main] DEBUG org.hibernate.event.def.AbstractSaveEventListener [saveWithGeneratedId() :113] - generated identifier: ff8080810c683199010c68323f7e0004, using strategy: org.hibernate.id.UUIDHexGenerator
2006-07-13 15:02:849 [main] DEBUG org.hibernate.event.def.AbstractSaveEventListener [performSave() :152] - saving [com.dolby.pics.model.impl.Variant#ff8080810c683199010c68323f7e0004]
2006-07-13 15:02:852 [main] DEBUG org.hibernate.engine.Versioning [seedVersion() :67] - using initial version: 0
2006-07-13 15:02:856 [main] DEBUG org.hibernate.event.def.DefaultLoadEventListener [proxyOrLoad() :154] - loading entity: [com.dolby.pics.model.impl.Variant#ff8080810c683199010c68323f7e0004]
2006-07-13 15:02:859 [main] DEBUG org.hibernate.event.def.DefaultLoadEventListener [doLoad() :309] - attempting to resolve: [com.dolby.pics.model.impl.Variant#ff8080810c683199010c68323f7e0004]
2006-07-13 15:02:862 [main] DEBUG org.hibernate.event.def.DefaultLoadEventListener [doLoad() :318] - resolved object in session cache: [com.dolby.pics.model.impl.Variant#ff8080810c683199010c68323f7e0004]
2006-07-13 15:02:797 [main] DEBUG org.hibernate.transaction.JDBCTransaction [commit() :103] - commit
2006-07-13 15:02:800 [main] DEBUG org.hibernate.impl.SessionImpl [managedFlush() :339] - automatically flushing session
2006-07-13 15:02:803 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener [flushEverythingToExecutions() :58] - flushing session
2006-07-13 15:02:806 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener [prepareEntityFlushes() :111] - processing flush-time cascades
2006-07-13 15:02:809 [main] DEBUG org.hibernate.engine.Cascade [cascade() :237] - processing cascade ACTION_SAVE_UPDATE for: com.dolby.pics.model.impl.DolbyMasterProduct
2006-07-13 15:02:812 [main] DEBUG org.hibernate.engine.Cascade [cascadeCollectionElements() :285] - cascade ACTION_SAVE_UPDATE for collection: com.dolby.pics.model.impl.MasterProduct.variants
2006-07-13 15:02:815 [main] DEBUG org.hibernate.engine.CascadingAction [cascade() :133] - cascading to saveOrUpdate: com.dolby.pics.model.impl.Variant
2006-07-13 15:02:819 [main] DEBUG org.hibernate.event.def.AbstractSaveEventListener [getEntityState() :463] - persistent instance of: com.dolby.pics.model.impl.Variant
2006-07-13 15:02:824 [main] DEBUG org.hibernate.event.def.DefaultSaveOrUpdateEventListener [entityIsPersistent() :105] - ignoring persistent instance
2006-07-13 15:02:828 [main] DEBUG org.hibernate.event.def.DefaultSaveOrUpdateEventListener [entityIsPersistent() :142] - object already associated with session: [com.dolby.pics.model.impl.Variant#CP650SX]
2006-07-13 15:02:832 [main] DEBUG org.hibernate.engine.CascadingAction [cascade() :133] - cascading to saveOrUpdate: com.dolby.pics.model.impl.Variant
2006-07-13 15:02:835 [main] DEBUG org.hibernate.event.def.AbstractSaveEventListener [getEntityState() :463] - persistent instance of: com.dolby.pics.model.impl.Variant
2006-07-13 15:02:839 [main] DEBUG org.hibernate.event.def.DefaultSaveOrUpdateEventListener [entityIsPersistent() :105] - ignoring persistent instance
2006-07-13 15:02:843 [main] DEBUG org.hibernate.event.def.DefaultSaveOrUpdateEventListener [entityIsPersistent() :142] - object already associated with session: [com.dolby.pics.model.impl.Variant#CP650D]
2006-07-13 15:02:847 [main] DEBUG org.hibernate.engine.CascadingAction [cascade() :133] - cascading to saveOrUpdate: com.dolby.pics.model.impl.Variant
2006-07-13 15:02:851 [main] DEBUG org.hibernate.event.def.AbstractSaveEventListener [getEntityState() :463] - persistent instance of: com.dolby.pics.model.impl.Variant
2006-07-13 15:02:855 [main] DEBUG org.hibernate.event.def.DefaultSaveOrUpdateEventListener [entityIsPersistent() :105] - ignoring persistent instance
2006-07-13 15:02:859 [main] DEBUG org.hibernate.event.def.DefaultSaveOrUpdateEventListener [entityIsPersistent() :142] - object already associated with session: [com.dolby.pics.model.impl.Variant#CP650XO]
2006-07-13 15:02:863 [main] DEBUG org.hibernate.engine.CascadingAction [cascade() :133] - cascading to saveOrUpdate: com.dolby.pics.model.impl.Variant
2006-07-13 15:02:867 [main] DEBUG org.hibernate.event.def.AbstractSaveEventListener [getEntityState() :463] - persistent instance of: com.dolby.pics.model.impl.Variant
2006-07-13 15:02:872 [main] DEBUG org.hibernate.event.def.DefaultSaveOrUpdateEventListener [entityIsPersistent() :105] - ignoring persistent instance
2006-07-13 15:02:877 [main] DEBUG org.hibernate.event.def.DefaultSaveOrUpdateEventListener [entityIsPersistent() :142] - object already associated with session: [com.dolby.pics.model.impl.Variant#CP650SA]
2006-07-13 15:02:882 [main] DEBUG org.hibernate.engine.CascadingAction [cascade() :133] - cascading to saveOrUpdate: com.dolby.pics.model.impl.Variant
2006-07-13 15:02:886 [main] DEBUG org.hibernate.event.def.AbstractSaveEventListener [getEntityState() :463] - persistent instance of: com.dolby.pics.model.impl.Variant
2006-07-13 15:02:891 [main] DEBUG org.hibernate.event.def.DefaultSaveOrUpdateEventListener [entityIsPersistent() :105] - ignoring persistent instance
2006-07-13 15:02:895 [main] DEBUG org.hibernate.event.def.DefaultSaveOrUpdateEventListener [entityIsPersistent() :142] - object already associated with session: [com.dolby.pics.model.impl.Variant#CP650SR]
2006-07-13 15:02:900 [main] DEBUG org.hibernate.engine.CascadingAction [cascade() :133] - cascading to saveOrUpdate: com.dolby.pics.model.impl.Variant
2006-07-13 15:02:904 [main] DEBUG org.hibernate.event.def.AbstractSaveEventListener [getEntityState() :463] - persistent instance of: com.dolby.pics.model.impl.Variant
2006-07-13 15:02:908 [main] DEBUG org.hibernate.event.def.DefaultSaveOrUpdateEventListener [entityIsPersistent() :105] - ignoring persistent instance
2006-07-13 15:02:911 [main] DEBUG org.hibernate.event.def.DefaultSaveOrUpdateEventListener [entityIsPersistent() :142] - object already associated with session: [com.dolby.pics.model.impl.Variant#CP650-SF]
2006-07-13 15:02:916 [main] DEBUG org.hibernate.engine.CascadingAction [cascade() :133] - cascading to saveOrUpdate: com.dolby.pics.model.impl.Variant
2006-07-13 15:02:919 [main] DEBUG org.hibernate.event.def.AbstractSaveEventListener [getEntityState() :463] - persistent instance of: com.dolby.pics.model.impl.Variant
2006-07-13 15:02:923 [main] DEBUG org.hibernate.event.def.DefaultSaveOrUpdateEventListener [entityIsPersistent() :105] - ignoring persistent instance
2006-07-13 15:02:927 [main] DEBUG org.hibernate.event.def.DefaultSaveOrUpdateEventListener [entityIsPersistent() :142] - object already associated with session: [com.dolby.pics.model.impl.Variant#CP650-F]
2006-07-13 15:02:931 [main] DEBUG org.hibernate.engine.Cascade [cascadeCollectionElements() :300] - done cascade ACTION_SAVE_UPDATE for collection: com.dolby.pics.model.impl.MasterProduct.variants
2006-07-13 15:02:938 [main] DEBUG org.hibernate.engine.Cascade [cascadeCollectionElements() :311] - deleting orphans for collection: com.dolby.pics.model.impl.MasterProduct.variants
2006-07-13 15:02:942 [main] DEBUG org.hibernate.engine.Cascade [deleteOrphans() :349] - deleting orphaned entity instance: com.dolby.pics.model.impl.Variant
2006-07-13 15:02:950 [main] DEBUG org.hibernate.event.def.DefaultDeleteEventListener [onDelete() :90] - deleting a persistent instance
2006-07-13 15:02:954 [main] DEBUG org.hibernate.event.def.DefaultDeleteEventListener [deleteEntity() :127] - deleting [com.dolby.pics.model.impl.Variant#CP650D-SF]
2006-07-13 15:02:958 [main] DEBUG org.hibernate.impl.SessionImpl [setCacheMode() :1301] - setting cache mode to: GET
2006-07-13 15:02:962 [main] DEBUG org.hibernate.impl.SessionImpl [setCacheMode() :1301] - setting cache mode to: NORMAL
2006-07-13 15:02:968 [main] DEBUG org.hibernate.impl.SessionImpl [setCacheMode() :1301] - setting cache mode to: GET
2006-07-13 15:02:972 [main] DEBUG org.hibernate.impl.SessionImpl [setCacheMode() :1301] - setting cache mode to: NORMAL
2006-07-13 15:02:976 [main] DEBUG org.hibernate.engine.Cascade [cascadeCollectionElements() :321] - done deleting orphans for collection: com.dolby.pics.model.impl.MasterProduct.variants
2006-07-13 15:02:980 [main] DEBUG org.hibernate.engine.Cascade [cascade() :259] - done processing cascade ACTION_SAVE_UPDATE for: com.dolby.pics.model.impl.DolbyMasterProduct
2006-07-13 15:02:984 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener [prepareCollectionFlushes() :153] - dirty checking collections
2006-07-13 15:02:987 [main] DEBUG org.hibernate.engine.CollectionEntry [preFlush() :177] - Collection dirty: [com.dolby.pics.model.impl.MasterProduct.variants#CP650]
2006-07-13 15:02:991 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener [flushEntities() :170] - Flushing entities and processing referenced collections
2006-07-13 15:02:995 [main] DEBUG org.hibernate.event.def.DefaultFlushEntityEventListener [scheduleUpdate() :229] - Updating entity: [com.dolby.pics.model.impl.DolbyMasterProduct#CP650]
2006-07-13 15:02:998 [main] DEBUG org.hibernate.engine.Versioning [increment() :27] - Incrementing: 1 to 2
2006-07-13 15:02:02 [main] DEBUG org.hibernate.engine.Collections [processReachableCollection() :176] - Collection found: [com.dolby.pics.model.impl.MasterProduct.variants#CP650], was: [com.dolby.pics.model.impl.MasterProduct.variants#CP650] (initialized)
2006-07-13 15:02:07 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener [flushCollections() :209] - Processing unreferenced collections
2006-07-13 15:02:10 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener [flushCollections() :223] - Scheduling collection removes/(re)creates/updates
2006-07-13 15:02:16 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener [flushEverythingToExecutions() :85] - Flushed: 1 insertions, 1 updates, 1 deletions to 10 objects
2006-07-13 15:02:19 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener [flushEverythingToExecutions() :91] - Flushed: 0 (re)creations, 1 updates, 0 removals to 1 collections
2006-07-13 15:02:22 [main] DEBUG org.hibernate.pretty.Printer [toString() :83] - listing entities:
2006-07-13 15:02:26 [main] DEBUG org.hibernate.pretty.Printer [toString() :90] - com.dolby.pics.model.impl.Variant{description=CP650D Variant of CP650, lastRevision=0, lifecycle=component[createdByUser,createdBySystem,createdTimestamp,updatedByUser,updatedBySystem,updatedTimestamp]{updatedBySystem=*TEST, updatedByUser=DJB, updatedTimestamp=2005-01-01 12:30:00, createdTimestamp=2005-01-01 12:30:00, createdBySystem=*TEST, createdByUser=DJB}, masterProduct=com.dolby.pics.model.impl.MasterProduct#CP650, name=CP650D, id=CP650D, version=1}
2006-07-13 15:02:30 [main] DEBUG org.hibernate.pretty.Printer [toString() :90] - com.dolby.pics.model.impl.Variant{description=CP650SR Variant of CP650, lastRevision=0, lifecycle=component[createdByUser,createdBySystem,createdTimestamp,updatedByUser,updatedBySystem,updatedTimestamp]{updatedBySystem=*TEST, updatedByUser=DJB, updatedTimestamp=2005-01-01 12:30:00, createdTimestamp=2005-01-01 12:30:00, createdBySystem=*TEST, createdByUser=DJB}, masterProduct=com.dolby.pics.model.impl.MasterProduct#CP650, name=CP650SR, id=CP650SR, version=1}
2006-07-13 15:02:34 [main] DEBUG org.hibernate.pretty.Printer [toString() :90] - com.dolby.pics.model.impl.Variant{description=Test variant for CP650 MP, lastRevision=0, lifecycle=null, masterProduct=com.dolby.pics.model.impl.MasterProduct#CP650, name=CP650-NEW, id=ff8080810c683199010c68323f7e0004, version=0}
2006-07-13 15:02:38 [main] DEBUG org.hibernate.pretty.Printer [toString() :90] - com.dolby.pics.model.impl.Variant{description=CP650D-SF Variant of CP650, lastRevision=0, lifecycle=component[createdByUser,createdBySystem,createdTimestamp,updatedByUser,updatedBySystem,updatedTimestamp]{updatedBySystem=*TEST, updatedByUser=DJB, updatedTimestamp=2005-01-01 12:30:00, createdTimestamp=2005-01-01 12:30:00, createdBySystem=*TEST, createdByUser=DJB}, masterProduct=com.dolby.pics.model.impl.MasterProduct#CP650, name=CP650D-SF, id=CP650D-SF, version=1}
2006-07-13 15:02:42 [main] DEBUG org.hibernate.pretty.Printer [toString() :90] - com.dolby.pics.model.impl.Variant{description=CP650SX Variant of CP650, lastRevision=0, lifecycle=component[createdByUser,createdBySystem,createdTimestamp,updatedByUser,updatedBySystem,updatedTimestamp]{updatedBySystem=*TEST, updatedByUser=DJB, updatedTimestamp=2005-01-01 12:30:00, createdTimestamp=2005-01-01 12:30:00, createdBySystem=*TEST, createdByUser=DJB}, masterProduct=com.dolby.pics.model.impl.MasterProduct#CP650, name=CP650SX, id=CP650SX, version=1}
2006-07-13 15:02:48 [main] DEBUG org.hibernate.pretty.Printer [toString() :90] - com.dolby.pics.model.impl.Variant{description=CP650-SF Variant of CP650, lastRevision=0, lifecycle=component[createdByUser,createdBySystem,createdTimestamp,updatedByUser,updatedBySystem,updatedTimestamp]{updatedBySystem=*TEST, updatedByUser=DJB, updatedTimestamp=2005-01-01 12:30:00, createdTimestamp=2005-01-01 12:30:00, createdBySystem=*TEST, createdByUser=DJB}, masterProduct=com.dolby.pics.model.impl.MasterProduct#CP650, name=CP650-SF, id=CP650-SF, version=1}
2006-07-13 15:02:52 [main] DEBUG org.hibernate.pretty.Printer [toString() :90] - com.dolby.pics.model.impl.Variant{description=CP650-F Variant of CP650, lastRevision=0, lifecycle=component[createdByUser,createdBySystem,createdTimestamp,updatedByUser,updatedBySystem,updatedTimestamp]{updatedBySystem=*TEST, updatedByUser=DJB, updatedTimestamp=2005-01-01 12:30:00, createdTimestamp=2005-01-01 12:30:00, createdBySystem=*TEST, createdByUser=DJB}, masterProduct=com.dolby.pics.model.impl.MasterProduct#CP650, name=CP650-F, id=CP650-F, version=1}
2006-07-13 15:02:56 [main] DEBUG org.hibernate.pretty.Printer [toString() :90] - com.dolby.pics.model.impl.Variant{description=CP650XO Variant of CP650, lastRevision=0, lifecycle=component[createdByUser,createdBySystem,createdTimestamp,updatedByUser,updatedBySystem,updatedTimestamp]{updatedBySystem=*TEST, updatedByUser=DJB, updatedTimestamp=2005-01-01 12:30:00, createdTimestamp=2005-01-01 12:30:00, createdBySystem=*TEST, createdByUser=DJB}, masterProduct=com.dolby.pics.model.impl.MasterProduct#CP650, name=CP650XO, id=CP650XO, version=1}
2006-07-13 15:02:61 [main] DEBUG org.hibernate.pretty.Printer [toString() :90] - com.dolby.pics.model.impl.DolbyMasterProduct{variants=[com.dolby.pics.model.impl.Variant#CP650SX, com.dolby.pics.model.impl.Variant#CP650D, com.dolby.pics.model.impl.Variant#CP650XO, com.dolby.pics.model.impl.Variant#CP650SA, com.dolby.pics.model.impl.Variant#CP650SR, com.dolby.pics.model.impl.Variant#CP650-SF, com.dolby.pics.model.impl.Variant#CP650-F], productReference=CP650, description=CP650 Description, lifecycle=component[createdByUser,createdBySystem,createdTimestamp,updatedByUser,updatedBySystem,updatedTimestamp]{updatedBySystem=*TEST, updatedByUser=DJB, updatedTimestamp=2005-01-01 12:30:00, createdTimestamp=2005-01-01 12:30:00, createdBySystem=*TEST, createdByUser=DJB}, id=CP650, version=1}
2006-07-13 15:02:65 [main] DEBUG org.hibernate.pretty.Printer [toString() :90] - com.dolby.pics.model.impl.Variant{description=CP650SA Variant of CP650, lastRevision=0, lifecycle=component[createdByUser,createdBySystem,createdTimestamp,updatedByUser,updatedBySystem,updatedTimestamp]{updatedBySystem=*TEST, updatedByUser=DJB, updatedTimestamp=2005-01-01 12:30:00, createdTimestamp=2005-01-01 12:30:00, createdBySystem=*TEST, createdByUser=DJB}, masterProduct=com.dolby.pics.model.impl.MasterProduct#CP650, name=CP650SA, id=CP650SA, version=1}
2006-07-13 15:02:68 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener [performExecutions() :289] - executing flush
2006-07-13 15:02:71 [main] DEBUG org.hibernate.jdbc.ConnectionManager [flushBeginning() :463] - registering flush begin
2006-07-13 15:02:75 [main] DEBUG org.hibernate.cache.UpdateTimestampsCache [preinvalidate() :51] - Pre-invalidating space [ZCOREINV.VARIANT_PROD]
2006-07-13 15:02:78 [main] DEBUG org.hibernate.persister.entity.AbstractEntityPersister [insert() :2090] - Inserting entity: [com.dolby.pics.model.impl.Variant#ff8080810c683199010c68323f7e0004]
2006-07-13 15:02:81 [main] DEBUG org.hibernate.persister.entity.AbstractEntityPersister [insert() :2092] - Version: 0
2006-07-13 15:02:85 [main] DEBUG org.hibernate.jdbc.AbstractBatcher [logOpenPreparedStatement() :358] - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-07-13 15:02:88 [main] DEBUG org.hibernate.SQL [log() :393] - insert into ZCOREINV.VARIANT_PROD (LC_CRT_BY_USER, LC_CRT_BY_SYSTEM, LC_CRT_TIMESTAMP, VERSION, VAR_NAME, VAR_DESC, VAR_MPRD_ID, VAR_LAST_REV, ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?)
Hibernate: insert into ZCOREINV.VARIANT_PROD (LC_CRT_BY_USER, LC_CRT_BY_SYSTEM, LC_CRT_TIMESTAMP, VERSION, VAR_NAME, VAR_DESC, VAR_MPRD_ID, VAR_LAST_REV, ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?)
2006-07-13 15:02:95 [main] DEBUG org.hibernate.jdbc.AbstractBatcher [getPreparedStatement() :476] - preparing statement
2006-07-13 15:02:100 [main] DEBUG org.hibernate.persister.entity.AbstractEntityPersister [dehydrate() :1905] - Dehydrating entity: [com.dolby.pics.model.impl.Variant#ff8080810c683199010c68323f7e0004]
2006-07-13 15:02:105 [main] DEBUG org.hibernate.type.StringType [nullSafeSet() :80] - binding '*LIFECYCLE' to parameter: 1
2006-07-13 15:02:108 [main] DEBUG org.hibernate.type.StringType [nullSafeSet() :80] - binding '*SYS' to parameter: 2
2006-07-13 15:02:112 [main] DEBUG org.hibernate.type.TimestampType [nullSafeSet() :80] - binding '2006-07-13 15:02:43' to parameter: 3
2006-07-13 15:02:116 [main] DEBUG org.hibernate.type.IntegerType [nullSafeSet() :80] - binding '0' to parameter: 4
2006-07-13 15:02:120 [main] DEBUG org.hibernate.type.StringType [nullSafeSet() :80] - binding 'CP650-NEW' to parameter: 5
2006-07-13 15:02:124 [main] DEBUG org.hibernate.type.StringType [nullSafeSet() :80] - binding 'Test variant for CP650 MP' to parameter: 6
2006-07-13 15:02:127 [main] DEBUG org.hibernate.type.StringType [nullSafeSet() :80] - binding 'CP650' to parameter: 7
2006-07-13 15:02:131 [main] DEBUG org.hibernate.type.IntegerType [nullSafeSet() :80] - binding '0' to parameter: 8
2006-07-13 15:02:135 [main] DEBUG org.hibernate.type.StringType [nullSafeSet() :80] - binding 'ff8080810c683199010c68323f7e0004' to parameter: 9
2006-07-13 15:02:140 [main] DEBUG org.hibernate.jdbc.AbstractBatcher [logClosePreparedStatement() :366] - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-07-13 15:02:143 [main] DEBUG org.hibernate.jdbc.AbstractBatcher [closePreparedStatement() :525] - closing statement
2006-07-13 15:02:146 [main] DEBUG org.hibernate.cache.UpdateTimestampsCache [preinvalidate() :51] - Pre-invalidating space [ZCOREINV.MASTER_PRODUCT]
2006-07-13 15:02:150 [main] DEBUG org.hibernate.persister.entity.AbstractEntityPersister [update() :2211] - Updating entity: [com.dolby.pics.model.impl.DolbyMasterProduct#CP650]
2006-07-13 15:02:153 [main] DEBUG org.hibernate.persister.entity.AbstractEntityPersister [update() :2213] - Existing version: 1 -> New version: 2
2006-07-13 15:02:157 [main] DEBUG org.hibernate.jdbc.AbstractBatcher [logOpenPreparedStatement() :358] - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-07-13 15:02:162 [main] DEBUG org.hibernate.SQL [log() :393] - update ZCOREINV.MASTER_PRODUCT set LC_UPD_BY_USER=?, LC_UPD_BY_SYSTEM=?, LC_UPD_TIMESTAMP=?, VERSION=?, MPRD_DESC=?, MPRD_REF=? where ID=? and VERSION=?
Hibernate: update ZCOREINV.MASTER_PRODUCT set LC_UPD_BY_USER=?, LC_UPD_BY_SYSTEM=?, LC_UPD_TIMESTAMP=?, VERSION=?, MPRD_DESC=?, MPRD_REF=? where ID=? and VERSION=?
2006-07-13 15:02:165 [main] DEBUG org.hibernate.jdbc.AbstractBatcher [getPreparedStatement() :476] - preparing statement
2006-07-13 15:02:171 [main] DEBUG org.hibernate.persister.entity.AbstractEntityPersister [dehydrate() :1905] - Dehydrating entity: [com.dolby.pics.model.impl.DolbyMasterProduct#CP650]
2006-07-13 15:02:175 [main] DEBUG org.hibernate.type.StringType [nullSafeSet() :80] - binding '*LIFECYCLE' to parameter: 1
2006-07-13 15:02:179 [main] DEBUG org.hibernate.type.StringType [nullSafeSet() :80] - binding '*SYS' to parameter: 2
2006-07-13 15:02:184 [main] DEBUG org.hibernate.type.TimestampType [nullSafeSet() :80] - binding '2006-07-13 15:02:43' to parameter: 3
2006-07-13 15:02:188 [main] DEBUG org.hibernate.type.IntegerType [nullSafeSet() :80] - binding '2' to parameter: 4
2006-07-13 15:02:191 [main] DEBUG org.hibernate.type.StringType [nullSafeSet() :80] - binding 'CP650 Description' to parameter: 5
2006-07-13 15:02:195 [main] DEBUG org.hibernate.type.StringType [nullSafeSet() :80] - binding 'CP650' to parameter: 6
2006-07-13 15:02:199 [main] DEBUG org.hibernate.type.StringType [nullSafeSet() :80] - binding 'CP650' to parameter: 7
2006-07-13 15:02:202 [main] DEBUG org.hibernate.type.IntegerType [nullSafeSet() :80] - binding '1' to parameter: 8
2006-07-13 15:02:207 [main] DEBUG org.hibernate.jdbc.AbstractBatcher [logClosePreparedStatement() :366] - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-07-13 15:02:216 [main] DEBUG org.hibernate.jdbc.AbstractBatcher [closePreparedStatement() :525] - closing statement
2006-07-13 15:02:220 [main] DEBUG org.hibernate.cache.UpdateTimestampsCache [preinvalidate() :51] - Pre-invalidating space [ZCOREINV.VARIANT_PROD]
2006-07-13 15:02:223 [main] DEBUG org.hibernate.cache.UpdateTimestampsCache [preinvalidate() :51] - Pre-invalidating space [ZCOREINV.VARIANT_PROD]
2006-07-13 15:02:229 [main] DEBUG org.hibernate.persister.entity.AbstractEntityPersister [delete() :2319] - Deleting entity: [com.dolby.pics.model.impl.Variant#CP650D-SF]
2006-07-13 15:02:232 [main] DEBUG org.hibernate.persister.entity.AbstractEntityPersister [delete() :2321] - Version: 1
2006-07-13 15:02:235 [main] DEBUG org.hibernate.jdbc.AbstractBatcher [logOpenPreparedStatement() :358] - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-07-13 15:02:239 [main] DEBUG org.hibernate.SQL [log() :393] - delete from ZCOREINV.VARIANT_PROD where ID=? and VERSION=?
Hibernate: delete from ZCOREINV.VARIANT_PROD where ID=? and VERSION=?
2006-07-13 15:02:243 [main] DEBUG org.hibernate.jdbc.AbstractBatcher [getPreparedStatement() :476] - preparing statement
2006-07-13 15:02:247 [main] DEBUG org.hibernate.type.StringType [nullSafeSet() :80] - binding 'CP650D-SF' to parameter: 1
2006-07-13 15:02:251 [main] DEBUG org.hibernate.type.IntegerType [nullSafeSet() :80] - binding '1' to parameter: 2
2006-07-13 15:02:255 [main] DEBUG org.hibernate.jdbc.AbstractBatcher [logClosePreparedStatement() :366] - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-07-13 15:02:259 [main] DEBUG org.hibernate.jdbc.AbstractBatcher [closePreparedStatement() :525] - closing statement
2006-07-13 15:02:264 [main] DEBUG org.hibernate.jdbc.ConnectionManager [flushEnding() :472] - registering flush end
2006-07-13 15:02:267 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener [postFlush() :320] - post flush
2006-07-13 15:02:271 [main] DEBUG org.hibernate.jdbc.JDBCContext [beforeTransactionCompletion() :194] - before transaction completion
2006-07-13 15:02:274 [main] DEBUG org.hibernate.impl.SessionImpl [beforeTransactionCompletion() :395] - before transaction completion
2006-07-13 15:02:287 [main] DEBUG org.hibernate.transaction.JDBCTransaction [commit() :116] - committed JDBC Connection
2006-07-13 15:02:290 [main] DEBUG org.hibernate.jdbc.JDBCContext [afterTransactionCompletion() :208] - after transaction completion
2006-07-13 15:02:292 [main] DEBUG org.hibernate.jdbc.ConnectionManager [aggressiveRelease() :398] - aggressively releasing JDBC connection
2006-07-13 15:02:315 [main] DEBUG org.hibernate.jdbc.ConnectionManager [closeConnection() :435] - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2006-07-13 15:02:318 [main] DEBUG org.hibernate.connection.DriverManagerConnectionProvider [closeConnection() :129] - returning connection to pool, pool size: 1
2006-07-13 15:02:321 [main] DEBUG org.hibernate.impl.SessionImpl [afterTransactionCompletion() :424] - after transaction completion
2006-07-13 15:02:487 [main] DEBUG org.hibernate.cache.UpdateTimestampsCache [invalidate() :64] - Invalidating space [ZCOREINV.VARIANT_PROD], timestamp: 4721866192842752
2006-07-13 15:02:490 [main] DEBUG org.hibernate.cache.UpdateTimestampsCache [invalidate() :64] - Invalidating space [ZCOREINV.MASTER_PRODUCT], timestamp: 4721866192855040
2006-07-13 15:02:493 [main] DEBUG org.hibernate.cache.UpdateTimestampsCache [invalidate() :64] - Invalidating space [ZCOREINV.VARIANT_PROD], timestamp: 4721866192867328
2006-07-13 15:02:512 [main] DEBUG org.hibernate.cache.UpdateTimestampsCache [invalidate() :64] - Invalidating space [ZCOREINV.VARIANT_PROD], timestamp: 4721866192945152
2006-07-13 15:02:747 [main] DEBUG org.hibernate.impl.SessionImpl [close() :275] - closing session
2006-07-13 15:02:750 [main] DEBUG org.hibernate.jdbc.ConnectionManager [cleanup() :369] - connection already null in cleanup : no action