I'm sure I'm doing something stupid, but I can't for the life of me figure out what it is. All I want to do is update the availableQuantity property on the Purchaseable persistent class. I load a Product subclass of it, update the property, then commit the transaction, but Hibernate issues no SQL update even though the code is executing within a transaction and the property is dirty. Even the Printer prints out the updated value:
16:43:27,790 DEBUG Printer:90 - com.xxx.commerce.model.Product{fileAssets=<uninitialized>, width=24.0, manufacturer=com.xxx.commerce.model.Manufacturer#4, lastUpdateBy=admin, categories=<uninitialized>, thumbnailName=1135824976532.jpg, id=1, height=12.0, backorderMaxQuantity=5, name=Test Product, orderedQuantity=5, productCode=1234, active=true, group=false, bargainPrice=1299.0, depth=35.0, notes=These are some arbitary internal notes that can be sent., createdBy=admin, availableQuantity=3, retailPrice=1599.99, version=4, individuallyPurchaseable=true, groups=<uninitialized>, description=Test Product Description., lastUpdate=2005-12-30 00:01:50, createdOn=2005-12-28 21:56:02, weight=125.0}
Somebody please tell me I'm doing something stupid. My test case:
Code:
public void testSimple() throws Exception {
Transaction tx = session.beginTransaction();
Purchaseable p = (Purchaseable)session.load(Purchaseable.class, new Long(1));
p.decrementAvailableCount(new Integer(2));
tx.commit();
}
Where decrementAvailableQuantity() looks like this:
Code:
public void decrementAvailableCount(Integer ordered) {
if(ordered.intValue() > getOrderableQuantity().intValue())
throw new InsufficientInventoryAvailableException("Requested quantity exceeds orderable quantity for Purchaseable [" + getId() + "]");
logger.info("Decrementing available quantity for Purchaseable#" + getId() + " by " + ordered.intValue());
setAvailableQuantity(new Integer(getAvailableQuantity().intValue() - ordered.intValue()));
}
And setAvailableQuantity(Integer ordered) looks like this:
Code:
public void setAvailableQuantity(Integer ordered) {
logger.info("Setting available quantity for Purchaseable#" + getId() + " to " + ordered);
this.availableQuantity = ordered;
}
Hibernate version: 3.0.3
Mapping documents:Code:
=======================================
Purchaseable.hbm.xml
=======================================
<?xml version="1.0"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd" >
<hibernate-mapping package="com.xxx.commerce.model">
<class name="Purchaseable" table="purchaseable" lazy="false">
<id
name="id"
type="long"
column="purchaseable_id"
access="field"
>
<generator class="native"/>
</id>
<discriminator column="group_flag"/>
<version name="version" column="version" access="field"/>
<property
name="group"
type="yes_no"
column="group_flag"
not-null="true"
length="1"
insert="false"
update="false"
/>
<property
name="name"
type="java.lang.String"
column="name"
not-null="true"
/>
<property
name="description"
type="text"
column="description"
/>
<property
name="notes"
type="text"
column="notes"
/>
<property
name="active"
type="yes_no"
column="active_flag"
/>
<property
name="individuallyPurchaseable"
type="yes_no"
column="individually_purchaseable_flag"
/>
<property
name="thumbnailName"
type="java.lang.String"
column="thumbnail"
/>
<property
name="productCode"
type="java.lang.String"
column="code"
/>
<property
name="weight"
type="com.xxx.commerce.persistence.customtype.CommerceDoubleTypeCustom"
column="weight"
/>
<property
name="bargainPrice"
type="com.xxx.commerce.persistence.customtype.CommerceDoubleTypeCustom"
column="bargain_price"
not-null="true"
/>
<property
name="retailPrice"
type="com.xxx.commerce.persistence.customtype.CommerceDoubleTypeCustom"
column="retail_price"
/>
<property
name="orderedQuantity"
type="int"
column="ordered_qty"
not-null="true"
/>
<property
name="availableQuantity"
type="int"
column="available_qty"
not-null="true"
/>
<property
name="backorderMaxQuantity"
type="int"
column="backorder_max_qty"
/>
<property
name="createdBy"
type="java.lang.String"
column="created_by"
not-null="true"
/>
<property
name="createdOn"
type="java.sql.Timestamp"
column="created_on"
not-null="true"
/>
<property
name="lastUpdate"
type="java.sql.Timestamp"
column="last_update"
/>
<property
name="lastUpdateBy"
type="java.lang.String"
column="last_update_by"
/>
<!-- Associations -->
<set name="fileAssets"
table="purchaseable_asset"
lazy="true"
inverse="false"
cascade="save-update"
>
<key column="purchaseable_id"/>
<many-to-many class="FileAsset" column="file_asset_id"/>
</set>
<many-to-one
name="manufacturer"
class="Manufacturer"
not-null="true"
>
<column name="manufacturer_id"/>
</many-to-one>
<set name="categories"
lazy="true"
cascade="save-update"
table="purchaseable_category_entry"
inverse="false"
>
<key column="purchaseable_id"/>
<many-to-many class="PurchaseableCategory" column="purchaseable_category_id"/>
</set>
</class>
</hibernate-mapping>
=======================================
Product.hbm.xml
=======================================
<?xml version="1.0"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd" >
<hibernate-mapping package="com.xxx.commerce.model">
<subclass name="Product"
extends="Purchaseable"
discriminator-value="N"
>
<property
name="height"
type="com.xxx.commerce.persistence.customtype.CommerceDoubleTypeCustom"
column="height"
/>
<property
name="width"
type="com.xxx.commerce.persistence.customtype.CommerceDoubleTypeCustom"
column="width"
/>
<property
name="depth"
type="com.xxx.commerce.persistence.customtype.CommerceDoubleTypeCustom"
column="depth"
/>
<set
name="groups"
lazy="true"
cascade="save-update"
table="purchaseable_group_entry"
inverse="false"
>
<key column="child_id"/>
<many-to-many class="ProductGroup">
<column name="parent_id"/>
</many-to-many>
</set>
</subclass>
</hibernate-mapping>
Code between sessionFactory.openSession() and session.close():Code:
public void testSimple() throws Exception {
Session session = SessionFactoryUtils.getNewSession((SessionFactory)ObjectFactory.getBean(Constants.SESSION_FACTORY));
Transaction tx = session.beginTransaction();
Purchaseable p = (Purchaseable)session.load(Purchaseable.class, new Long(1));
p.decrementAvailableCount(new Integer(2));
tx.commit();
}
Full stack trace of any exception that occurs: No exception.
Name and version of the database you are using: mySQL 4.1.11
The generated SQL (show_sql=true):Code:
16:43:27,619 DEBUG SQL:311 - select purchaseab0_.purchaseable_id as purchase1_0_, purchaseab0_.version as version8_0_, purchaseab0_.group_flag as group2_8_0_, purchaseab0_.name as name8_0_, purchaseab0_.description as descript5_8_0_, purchaseab0_.notes as notes8_0_, purchaseab0_.active_flag as active7_8_0_, purchaseab0_.individually_purchaseable_flag as individu8_8_0_, purchaseab0_.thumbnail as thumbnail8_0_, purchaseab0_.code as code8_0_, purchaseab0_.weight as weight8_0_, purchaseab0_.bargain_price as bargain12_8_0_, purchaseab0_.retail_price as retail13_8_0_, purchaseab0_.ordered_qty as ordered14_8_0_, purchaseab0_.available_qty as available15_8_0_, purchaseab0_.backorder_max_qty as backorder16_8_0_, purchaseab0_.created_by as created17_8_0_, purchaseab0_.created_on as created18_8_0_, purchaseab0_.last_update as last19_8_0_, purchaseab0_.last_update_by as last20_8_0_, purchaseab0_.manufacturer_id as manufac21_8_0_, purchaseab0_.height as height8_0_, purchaseab0_.width as width8_0_, purchaseab0_.depth as depth8_0_, purchaseab0_.separable_flag as separable25_8_0_, purchaseab0_.group_flag as group2_0_ from purchaseable purchaseab0_ where purchaseab0_.purchaseable_id=?
Debug level Hibernate log excerpt:Code:
16:43:27,599 DEBUG SessionImpl:248 - opened session at timestamp: 4655447275802624
=========> begin test
16:43:27,609 DEBUG JDBCTransaction:46 - begin
16:43:27,609 DEBUG AbstractBatcher:422 - opening JDBC connection
16:43:27,609 DEBUG JDBCTransaction:50 - current autocommit status: true
16:43:27,609 DEBUG JDBCTransaction:52 - disabling autocommit
16:43:27,619 DEBUG DefaultLoadEventListener:143 - loading entity: [com.xxx.commerce.model.Purchaseable#1]
16:43:27,619 DEBUG DefaultLoadEventListener:289 - attempting to resolve: [com.xxx.commerce.model.Purchaseable#1]
16:43:27,619 DEBUG DefaultLoadEventListener:325 - object not resolved in any cache: [com.xxx.commerce.model.Purchaseable#1]
16:43:27,619 DEBUG BasicEntityPersister:2457 - Materializing entity: [com.xxx.commerce.model.Purchaseable#1]
16:43:27,619 DEBUG Loader:1307 - loading entity: [com.xxx.commerce.model.Purchaseable#1]
16:43:27,619 DEBUG AbstractBatcher:277 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
16:43:27,619 DEBUG SQL:311 - select purchaseab0_.purchaseable_id as purchase1_0_, purchaseab0_.version as version8_0_, purchaseab0_.group_flag as group2_8_0_, purchaseab0_.name as name8_0_, purchaseab0_.description as descript5_8_0_, purchaseab0_.notes as notes8_0_, purchaseab0_.active_flag as active7_8_0_, purchaseab0_.individually_purchaseable_flag as individu8_8_0_, purchaseab0_.thumbnail as thumbnail8_0_, purchaseab0_.code as code8_0_, purchaseab0_.weight as weight8_0_, purchaseab0_.bargain_price as bargain12_8_0_, purchaseab0_.retail_price as retail13_8_0_, purchaseab0_.ordered_qty as ordered14_8_0_, purchaseab0_.available_qty as available15_8_0_, purchaseab0_.backorder_max_qty as backorder16_8_0_, purchaseab0_.created_by as created17_8_0_, purchaseab0_.created_on as created18_8_0_, purchaseab0_.last_update as last19_8_0_, purchaseab0_.last_update_by as last20_8_0_, purchaseab0_.manufacturer_id as manufac21_8_0_, purchaseab0_.height as height8_0_, purchaseab0_.width as width8_0_, purchaseab0_.depth as depth8_0_, purchaseab0_.separable_flag as separable25_8_0_, purchaseab0_.group_flag as group2_0_ from purchaseable purchaseab0_ where purchaseab0_.purchaseable_id=?
16:43:27,630 DEBUG AbstractBatcher:365 - preparing statement
16:43:27,640 DEBUG LongType:59 - binding '1' to parameter: 1
16:43:27,650 DEBUG AbstractBatcher:293 - about to open ResultSet (open ResultSets: 0, globally: 0)
16:43:27,650 DEBUG Loader:388 - processing result set
16:43:27,650 DEBUG Loader:393 - result set row: 0
16:43:27,650 DEBUG Loader:795 - result row: EntityKey[com.xxx.commerce.model.Purchaseable#1]
16:43:27,660 DEBUG StringType:86 - returning 'N' as column: group2_0_
16:43:27,660 DEBUG Loader:945 - Initializing object from ResultSet: [com.xxx.commerce.model.Product#1]
16:43:27,670 DEBUG BasicEntityPersister:1641 - Hydrating entity: [com.xxx.commerce.model.Product#1]
16:43:27,670 DEBUG IntegerType:86 - returning '4' as column: version8_0_
16:43:27,670 DEBUG YesNoType:86 - returning 'false' as column: group2_8_0_
16:43:27,670 DEBUG StringType:86 - returning 'Test Product' as column: name8_0_
16:43:27,670 DEBUG TextType:86 - returning 'Test Product Description.' as column: descript5_8_0_
16:43:27,670 DEBUG TextType:86 - returning 'These are some arbitary internal notes that can be sent.' as column: notes8_0_
16:43:27,670 DEBUG YesNoType:86 - returning 'true' as column: active7_8_0_
16:43:27,670 DEBUG YesNoType:86 - returning 'true' as column: individu8_8_0_
16:43:27,680 DEBUG StringType:86 - returning '1135824976532.jpg' as column: thumbnail8_0_
16:43:27,680 DEBUG StringType:86 - returning '1234' as column: code8_0_
16:43:27,680 DEBUG IntegerType:86 - returning '5' as column: ordered14_8_0_
16:43:27,680 DEBUG IntegerType:86 - returning '5' as column: available15_8_0_
16:43:27,680 DEBUG IntegerType:86 - returning '5' as column: backorder16_8_0_
16:43:27,680 DEBUG StringType:86 - returning 'admin' as column: created17_8_0_
16:43:27,690 DEBUG TimestampType:86 - returning '2005-12-28 21:56:02' as column: created18_8_0_
16:43:27,700 DEBUG TimestampType:86 - returning '2005-12-30 00:01:50' as column: last19_8_0_
16:43:27,700 DEBUG StringType:86 - returning 'admin' as column: last20_8_0_
16:43:27,700 DEBUG LongType:86 - returning '4' as column: manufac21_8_0_
16:43:27,700 DEBUG TwoPhaseLoad:67 - Version: 4
16:43:27,700 DEBUG Loader:412 - done processing result set (1 rows)
16:43:27,700 DEBUG AbstractBatcher:300 - about to close ResultSet (open ResultSets: 1, globally: 1)
16:43:27,700 DEBUG AbstractBatcher:285 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
16:43:27,710 DEBUG AbstractBatcher:403 - closing statement
16:43:27,710 DEBUG Loader:508 - total objects hydrated: 1
16:43:27,710 DEBUG TwoPhaseLoad:96 - resolving associations for [com.xxx.commerce.model.Product#1]
16:43:27,730 DEBUG CollectionLoadContext:134 - creating collection wrapper:[com.xxx.commerce.model.Purchaseable.fileAssets#1]
16:43:27,740 DEBUG DefaultLoadEventListener:143 - loading entity: [com.xxx.commerce.model.Manufacturer#4]
16:43:27,740 DEBUG DefaultLoadEventListener:216 - creating new proxy for entity
16:43:27,740 DEBUG CollectionLoadContext:134 - creating collection wrapper:[com.xxx.commerce.model.Purchaseable.categories#1]
16:43:27,740 DEBUG CollectionLoadContext:134 - creating collection wrapper:[com.xxx.commerce.model.Product.groups#1]
16:43:27,740 INFO Product:137 - Setting available quantity for Purchaseable#1 to 5
16:43:27,740 INFO Product:137 - Setting available quantity for Purchaseable#1 to 5
16:43:27,740 DEBUG TwoPhaseLoad:167 - done materializing entity [com.xxx.commerce.model.Product#1]
16:43:27,750 DEBUG PersistenceContext:789 - initializing non-lazy collections
16:43:27,750 DEBUG Loader:1335 - done entity load
16:43:27,750 INFO Product:273 - Decrementing available quantity for Purchaseable#1 by 2
16:43:27,750 INFO Product:137 - Setting available quantity for Purchaseable#1 to 3
16:43:27,750 DEBUG JDBCTransaction:83 - commit
16:43:27,750 DEBUG SessionImpl:319 - automatically flushing session
16:43:27,750 DEBUG AbstractFlushingEventListener:52 - flushing session
16:43:27,750 DEBUG AbstractFlushingEventListener:102 - processing flush-time cascades
16:43:27,760 DEBUG Cascades:836 - processing cascade ACTION_SAVE_UPDATE for: com.xxx.commerce.model.Product
16:43:27,760 DEBUG Cascades:890 - cascade ACTION_SAVE_UPDATE for collection: com.xxx.commerce.model.Purchaseable.fileAssets
16:43:27,760 DEBUG Cascades:908 - done cascade ACTION_SAVE_UPDATE for collection: com.xxx.commerce.model.Purchaseable.fileAssets
16:43:27,760 DEBUG Cascades:890 - cascade ACTION_SAVE_UPDATE for collection: com.xxx.commerce.model.Purchaseable.categories
16:43:27,760 DEBUG Cascades:908 - done cascade ACTION_SAVE_UPDATE for collection: com.xxx.commerce.model.Purchaseable.categories
16:43:27,760 DEBUG Cascades:890 - cascade ACTION_SAVE_UPDATE for collection: com.xxx.commerce.model.Product.groups
16:43:27,760 DEBUG Cascades:908 - done cascade ACTION_SAVE_UPDATE for collection: com.xxx.commerce.model.Product.groups
16:43:27,760 DEBUG Cascades:861 - done processing cascade ACTION_SAVE_UPDATE for: com.xxx.commerce.model.Product
16:43:27,760 DEBUG AbstractFlushingEventListener:150 - dirty checking collections
16:43:27,760 DEBUG AbstractFlushingEventListener:167 - Flushing entities and processing referenced collections
16:43:27,780 DEBUG Collections:140 - Collection found: [com.xxx.commerce.model.Purchaseable.fileAssets#1], was: [com.xxx.commerce.model.Purchaseable.fileAssets#1] (uninitialized)
16:43:27,780 DEBUG Collections:140 - Collection found: [com.xxx.commerce.model.Purchaseable.categories#1], was: [com.xxx.commerce.model.Purchaseable.categories#1] (uninitialized)
16:43:27,780 DEBUG Collections:140 - Collection found: [com.xxx.commerce.model.Product.groups#1], was: [com.xxx.commerce.model.Product.groups#1] (uninitialized)
16:43:27,780 DEBUG AbstractFlushingEventListener:203 - Processing unreferenced collections
16:43:27,780 DEBUG AbstractFlushingEventListener:217 - Scheduling collection removes/(re)creates/updates
16:43:27,790 DEBUG AbstractFlushingEventListener:79 - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
16:43:27,790 DEBUG AbstractFlushingEventListener:85 - Flushed: 0 (re)creations, 0 updates, 0 removals to 3 collections
16:43:27,790 DEBUG Printer:83 - listing entities:
16:43:27,790 DEBUG Printer:90 - com.xxx.commerce.model.Product{fileAssets=<uninitialized>, width=24.0, manufacturer=com.xxx.commerce.model.Manufacturer#4, lastUpdateBy=admin, categories=<uninitialized>, thumbnailName=1135824976532.jpg, id=1, height=12.0, backorderMaxQuantity=5, name=Test Product, orderedQuantity=5, productCode=1234, active=true, group=false, bargainPrice=1299.0, depth=35.0, notes=These are some arbitary internal notes that can be sent., createdBy=admin, availableQuantity=3, retailPrice=1599.99, version=4, individuallyPurchaseable=true, groups=<uninitialized>, description=Test Product Description., lastUpdate=2005-12-30 00:01:50, createdOn=2005-12-28 21:56:02, weight=125.0}
16:43:27,790 DEBUG AbstractFlushingEventListener:267 - executing flush
16:43:27,790 DEBUG AbstractFlushingEventListener:294 - post flush
16:43:27,800 DEBUG JDBCContext:238 - before transaction completion
16:43:27,800 DEBUG SessionImpl:368 - before transaction completion
16:43:27,800 DEBUG JDBCTransaction:173 - re-enabling autocommit
16:43:27,800 DEBUG JDBCTransaction:96 - committed JDBC Connection
16:43:27,800 DEBUG JDBCContext:243 - after transaction completion
16:43:27,800 DEBUG AbstractBatcher:437 - closing JDBC connection (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)
16:43:27,810 DEBUG SessionImpl:399 - after transaction completion
=========> end test