Why is Hibernate Optimistic Locking Failure Exception thrown when saving a new entity?

Hibernate ORM
1

Hello, I hope someone can help me with this issue as I’ve spent at least 3 days.

The entity a parent and child entity and when I save the entity (i.e. the parent and at the same time the children are also saved), however with normal execution (in debug mode every time) I get a HibernateOptimisticLockingFailureException thrown soon after the session is flushed. Please note, the testing is done on my local machine, single thread, and nobody is changing the entity as I’m also saving it.

We are using the following:

  1. MySQL v5.5.x
  2. Hibernate 4.3.11
  3. Java 8
  4. Spring 4.1.0

Key points:

  1. The relationship between the parent and child is bi-directional one-to-many.
  2. We use optimistic locking with the version column being a timestamp created by MySQL either during insert or during update. On the version field we specify Generated(GenerationTime.ALWAYS) to ensure that the version details are obtained from the database automatically (avoid the time precision issue between Java and MySQL)
  3. During saving a new entity (id = 0), I can see the logs that the entity is being inserted into the database, I can also see the child entities being inserted in the database (via the Hibernate logs). During this process, I can also see the a select is done to get the version details from the database.
  4. Soon after the entities are inserted and the session is being flushed, there is a dirty checking is done on the collection and I see a message in the log that the collection is (). Straight after this, I see an update statement on the parent entity’s table and this is where the problem occurs as the version value used in the update statement is different to what is in the database, the exception is thrown.

Question: Why is there an update date on the parent table? How can I avoid this update from happening? Is there something wrong with the way my one-to-many mapping is setup?

The Hibernate Code (executed)
getHibernateTemplate().saveOrUpdate(parentEntity);
getHibernateTemplate().flush(); // NB is a put a break point here and wait for 1 sec before executing I will always get the HibernateOptimisticLockingFailureException

The mapping (parent)
Access(AccessType.FIELD)
OneToMany(mappedBy=“servicePoint”, fetch=FetchType.EAGER, cascade={CascadeType.ALL}, orphanRemoval=true, targetEntity=ServicingMeter.class)
private List meters = new ArrayList();

The mapping (child)
Access(AccessType.FIELD)
ManyToOne(fetch=FetchType.EAGER, targetEntity=ServicePoint.class)
JoinColumn(name=“service_point_id”, nullable=false)
private ServicePoint servicePoint;

I have the annotated version of the logs below that shows what is happening from the save starts to where the exception is thrown.

Your prompt assistance would be very much appreciated.

Regards
Attila

--------- LOG FILE --------

** ENTITY IS VALIDATED AT THE BUSINESS LAYOUR **

19:56:32,879 DEBUG (com.bb.engine.common.mediator.CommonMediator 136) (main ) (W) validation successful (ElectricityServicePoint id=0, site_detail=Electricity, service_address=(Service Address tenancyNumber=MSB1A, streetNumber=245, streetName=Rosamond, streetType=RD, suburb=Maribyrnong, state=VIC, postcode=3032, country=null), meters=((ElectricityServicingMeter: meter=(UtilityMeter: id=11, serialNumber=66888_1, multiplier=1, registerFormulae=(null)), description=null, formula_variable=null, consumption_ratio=1, period=(Period: startDate=Tue Mar 01 00:00:00 AEDT 2005, endDate=null), withinNetwork=false, onMarket=true, marketIdentifier=com.bb.engine.bb.vo.utility.meter.NMI@81e8f5a5)), gateMeter=true, useParentLossFactorCodes=false, lossFactorCode=(LossFactorCode tni=LV1, dlf=RT2)

** SAVING THE PARENT ENTITY VIA getHibernateTemplate().saveOrUpdate(parentEntity); **

19:56:35,791 DEBUG (com.bb.engine.common.dao.util.hibernate.EntityAuditInterceptor 84) (main ) (W) onSave entity=(ElectricityServicePoint id=0, site_detail=Electricity, service_address=(Service Address tenancyNumber=MSB1A, streetNumber=245, streetName=Rosamond, streetType=RD, suburb=Maribyrnong, state=VIC, postcode=3032, country=null), meters=((ElectricityServicingMeter: meter=(UtilityMeter: id=11, serialNumber=66888_1, multiplier=1, registerFormulae=(null)), description=null, formula_variable=null, consumption_ratio=1, period=(Period: startDate=Tue Mar 01 00:00:00 AEDT 2005, endDate=null), withinNetwork=false, onMarket=true, marketIdentifier=com.bb.engine.bb.vo.utility.meter.NMI@81e8f5a5)), gateMeter=true, useParentLossFactorCodes=false, lossFactorCode=(LossFactorCode tni=LV1, dlf=RT2), id=null,
state()=1234567890,Thu Mar 08 19:56:26 AEDT 2018,Thu Mar 08 19:56:26 AEDT 2018,false,1234567890,bc94b32fdb1652c4b50b0c63fd8bec7559c965005c090e0fc4b006d44f9ea3fa,((ElectricityServicingMeter: meter=(UtilityMeter: id=11, serialNumber=66888_1, multiplier=1, registerFormulae=(null)), description=null, formula_variable=null, consumption_ratio=1, period=(Period: startDate=Tue Mar 01 00:00:00 AEDT 2005, endDate=null), withinNetwork=false, onMarket=true, marketIdentifier=com.bb.engine.bb.vo.utility.meter.NMI@81e8f5a5)),(Service Address tenancyNumber=MSB1A, streetNumber=245, streetName=Rosamond, streetType=RD, suburb=Maribyrnong, state=VIC, postcode=3032, country=null),0,(ElectricitySiteProfile id=9, site=10000 (Test Site 01), faultContact=(Contact: , name=Fault Contact for electricity, phoneNumber=9873 8480, faxNumber=9879 9886), billFrequency=MONTHLY, paymentPeriod=(PaymentPeriod days=14, method=CALENDAR), defaultMeterDataProvider=null, networkArea=NTWRK_ELECTRICITY),true,0,(LossFactorCode tni=LV1, dlf=RT2,C,0,false,
propertyNames()=createdByUser,dateCreated,dateModified,deleted,modifiedByUser,version,annualCnsmp,category,closeDate,cnsmpProfile,defaultChargeProfileId,hashCode,meters,openDate,serviceAddress,serviceFormula,servicePoints,siteProfile,supportedAccount,dataProvider,gateMeter,lifeSupports,lossFactorCode,marketIdentifier,onMarket,onMarketServicePoints,parentServicePoint,useParentLossFactorCodes,
types()=org.hibernate.type.StringType@20749d9,org.hibernate.type.CustomType@7882f2e2,org.hibernate.type.CustomType@40fd518f,org.hibernate.type.BooleanType@64b70919,org.hibernate.type.StringType@20749d9,org.hibernate.type.TimestampType@bd1111a,org.hibernate.type.ComponentType@1dafe1d2,org.hibernate.type.StringType@20749d9,org.hibernate.type.DateType@ce9b9a9,org.hibernate.type.StringType@20749d9,org.hibernate.type.IntegerType@6482eef,org.hibernate.type.StringType@20749d9,org.hibernate.type.BagType(com.bb.engine.bb.vo.common.site.service.ServicePoint.meters),org.hibernate.type.DateType@ce9b9a9,org.hibernate.type.ComponentType@77e86a53,org.hibernate.type.StringType@20749d9,org.hibernate.type.IntegerType@6482eef,org.hibernate.type.ManyToOneType(com.bb.engine.bb.vo.common.site.profile.bbSiteProfile),org.hibernate.type.CustomType@189283ae,org.hibernate.type.StringType@20749d9,org.hibernate.type.TrueFalseType@363f0ba0,org.hibernate.type.IntegerType@6482eef,org.hibernate.type.ComponentType@3249c81a,org.hibernate.type.ComponentType@508a1ef0,org.hibernate.type.CustomType@64845c40,org.hibernate.type.IntegerType@6482eef,org.hibernate.type.ManyToOneType(com.bb.engine.bb.vo.utility.site.service.UtilityServicePoint),org.hibernate.type.TrueFalseType@363f0ba0

** PARENT ENTITY IS BEING INSERTED **

19:56:35,794 DEBUG (hb.engine.spi.ActionQueue 196) (main ) (W) Executing identity-insert immediately
19:56:35,795 DEBUG (hb.engine.jdbc.spi.SqlStatementLogger 109) (main ) (W) insert into bbeng_service_points (created_by, date_entered, date_modified, deleted, modified_user_id, category_name, charge_profile_id, hash_code, tenancy_street_name, tenancy_street_number, tenancy_street_type, snp_tenancy_address, tenancy_number, tenancy_country, tenancy_postcode, tenancy_state, tenancy_suburb, service_formula, snp_service_points, site_profile_id, account_type, snp_data_provider, gate_meter, snp_life_support, dlf_code, tni_code, snp_market_identifier, snp_on_market_status, snp_on_market_pnts, parent_id, use_parent_tni_dlf, type) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ‘electricity’)
19:56:35,832 TRACE (hb…BasicBinder 81) (main ) (W) bind param (1) as (VARCHAR) - (1234567890)
19:56:35,834 TRACE (hb…BasicBinder 81) (main ) (W) bind param (4) as (BOOLEAN) - (false)
19:56:35,835 TRACE (hb…BasicBinder 81) (main ) (W) bind param (5) as (VARCHAR) - (1234567890)
19:56:35,836 TRACE (hb…BasicBinder 69) (main ) (W) bind param (6) as (VARCHAR) - (null)
19:56:35,837 TRACE (hb…BasicBinder 69) (main ) (W) bind param (7) as (INTEGER) - (null)
19:56:35,838 TRACE (hb…BasicBinder 81) (main ) (W) bind param (8) as (VARCHAR) - (bc94b32fdb1652c4b50b0c63fd8bec7559c965005c090e0fc4b006d44f9ea3fa)
19:56:35,839 TRACE (hb…BasicBinder 81) (main ) (W) bind param (9) as (VARCHAR) - (Rosamond)
19:56:35,840 TRACE (hb…BasicBinder 81) (main ) (W) bind param (10) as (VARCHAR) - (245)
19:56:35,841 TRACE (hb…BasicBinder 81) (main ) (W) bind param (11) as (VARCHAR) - (RD)
19:56:35,842 TRACE (hb…BasicBinder 81) (main ) (W) bind param (12) as (VARCHAR) - (MSB1A 245 Rosamond RD)
19:56:35,843 TRACE (hb…BasicBinder 81) (main ) (W) bind param (13) as (VARCHAR) - (MSB1A)
19:56:35,844 TRACE (hb…BasicBinder 69) (main ) (W) bind param (14) as (VARCHAR) - (null)
19:56:35,845 TRACE (hb…BasicBinder 81) (main ) (W) bind param (15) as (VARCHAR) - (3032)
19:56:35,846 TRACE (hb…BasicBinder 81) (main ) (W) bind param (16) as (VARCHAR) - (VIC)
19:56:35,847 TRACE (hb…BasicBinder 81) (main ) (W) bind param (17) as (VARCHAR) - (Maribyrnong)
19:56:35,847 TRACE (hb…BasicBinder 69) (main ) (W) bind param (18) as (VARCHAR) - (null)
19:56:35,848 TRACE (hb…BasicBinder 81) (main ) (W) bind param (19) as (INTEGER) - (0)
19:56:35,849 TRACE (hb…BasicBinder 81) (main ) (W) bind param (20) as (INTEGER) - (9)
19:56:35,850 TRACE (hb…BasicBinder 69) (main ) (W) bind param (22) as (VARCHAR) - (null)
19:56:35,851 TRACE (hb…BasicBinder 81) (main ) (W) bind param (23) as (CHAR) - (true)
19:56:35,852 TRACE (hb…BasicBinder 81) (main ) (W) bind param (24) as (INTEGER) - (0)
19:56:35,853 TRACE (hb…BasicBinder 81) (main ) (W) bind param (25) as (VARCHAR) - (RT2)
19:56:35,854 TRACE (hb…BasicBinder 81) (main ) (W) bind param (26) as (VARCHAR) - (LV1)
19:56:35,855 TRACE (hb…BasicBinder 69) (main ) (W) bind param (27) as (VARCHAR) - (null)
19:56:35,856 TRACE (hb…BasicBinder 81) (main ) (W) bind param (29) as (INTEGER) - (0)
19:56:35,857 TRACE (hb…BasicBinder 69) (main ) (W) bind param (30) as (BIGINT) - (null)
19:56:35,858 TRACE (hb…BasicBinder 81) (main ) (W) bind param (31) as (CHAR) - (false)
19:56:35,861 DEBUG (hb.id.IdentifierGeneratorHelper 94) (main ) (W) Natively generated identity: 8

** PARENT ENTITY’S VERSION TIMESTAMP OBTAINED FROM THE DATABASE **

19:56:35,862 DEBUG (hb.engine.jdbc.spi.SqlStatementLogger 109) (main ) (W) select electricit_.version as version8_83_ from bbeng_service_points electricit_ where electricit_.id=?
19:56:35,864 TRACE (hb…BasicBinder 81) (main ) (W) bind param (1) as (BIGINT) - (8)
19:56:35,867 TRACE (hb…BasicExtractor 78) (main ) (W) extracted value ((version8_83_) : (TIMESTAMP)) - (2018-03-08 19:56:35.0)

** INSERTING THE CHILD ENTITY INTO THE DATABASE **

19:56:35,870 DEBUG (com.bb.engine.common.dao.util.hibernate.EntityAuditInterceptor 84) (main ) (W) onSave entity=(ElectricityServicingMeter: meter=(UtilityMeter: id=11, serialNumber=66888_1, multiplier=1, registerFormulae=(null)), description=null, formula_variable=null, consumption_ratio=1, period=(Period: startDate=Tue Mar 01 00:00:00 AEDT 2005, endDate=null), withinNetwork=false, onMarket=true, marketIdentifier=com.bb.engine.bb.vo.utility.meter.NMI@81e8f5a5), id=null,
state()=,false,false,1,Electricity,(UtilityMeter: id=11, serialNumber=66888_1, multiplier=1, registerFormulae=(null)),INDEXED_THEN_INTERVAL,Tue Mar 01 00:00:00 AEDT 2005,(ElectricityServicePoint id=8, site_detail=Electricity, service_address=(Service Address tenancyNumber=MSB1A, streetNumber=245, streetName=Rosamond, streetType=RD, suburb=Maribyrnong, state=VIC, postcode=3032, country=null), meters=((ElectricityServicingMeter: meter=(UtilityMeter: id=11, serialNumber=66888_1, multiplier=1, registerFormulae=(null)), description=null, formula_variable=null, consumption_ratio=1, period=(Period: startDate=Tue Mar 01 00:00:00 AEDT 2005, endDate=null), withinNetwork=false, onMarket=true, marketIdentifier=com.bb.engine.bb.vo.utility.meter.NMI@81e8f5a5)), gateMeter=true, useParentLossFactorCodes=false, lossFactorCode=(LossFactorCode tni=LV1, dlf=RT2),com.bb.engine.bb.vo.utility.meter.NMI@81e8f5a5,true,1,false,
propertyNames()=createdByUser,dateCreated,dateModified,deleted,modifiedByUser,version,cancelled,closeDate,consumptionRatio,description,formulaVariable,meter,meterReadingsType,openDate,servicePoint,marketIdentifier,onMarket,parentServicePoint,streamId,withinNetwork,
types()=org.hibernate.type.StringType@20749d9,org.hibernate.type.CustomType@cb38d26,org.hibernate.type.CustomType@72efffa4,org.hibernate.type.BooleanType@64b70919,org.hibernate.type.StringType@20749d9,org.hibernate.type.TimestampType@bd1111a,org.hibernate.type.TrueFalseType@363f0ba0,org.hibernate.type.DateType@ce9b9a9,org.hibernate.type.BigDecimalType@2e2f720,org.hibernate.type.StringType@20749d9,org.hibernate.type.StringType@20749d9,org.hibernate.type.ManyToOneType(com.bb.engine.common.vo.meter.AbstractMeter),org.hibernate.type.CustomType@3f1543ca,org.hibernate.type.DateType@ce9b9a9,org.hibernate.type.ManyToOneType(com.bb.engine.bb.vo.common.site.service.ServicePoint),org.hibernate.type.ComponentType@167e559c,org.hibernate.type.TrueFalseType@363f0ba0,org.hibernate.type.ManyToOneType(com.bb.engine.bb.vo.utility.site.service.UtilityServicePoint),org.hibernate.type.StringType@20749d9,org.hibernate.type.TrueFalseType@363f0ba0
19:56:35,871 DEBUG (hb.engine.spi.ActionQueue 196) (main ) (W) Executing identity-insert immediately
19:56:35,872 DEBUG (hb.engine.jdbc.spi.SqlStatementLogger 109) (main ) (W) insert into bbeng_service_points_meters (created_by, date_entered, date_modified, deleted, modified_user_id, cancelled, close_date, consumption_ratio, description, formula_variable, meter_id, readings_type, open_date, service_point_id, market_identifier, on_market, parent_id, stream_number, within_network, type) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ‘electricity’)
19:56:35,895 TRACE (hb…BasicBinder 69) (main ) (W) bind param (1) as (VARCHAR) - (null)
19:56:35,896 TRACE (hb…BasicBinder 69) (main ) (W) bind param (2) as (TIMESTAMP) - (null)
19:56:35,897 TRACE (hb…BasicBinder 69) (main ) (W) bind param (3) as (TIMESTAMP) - (null)
19:56:35,898 TRACE (hb…BasicBinder 81) (main ) (W) bind param (4) as (BOOLEAN) - (false)
19:56:35,899 TRACE (hb…BasicBinder 69) (main ) (W) bind param (5) as (VARCHAR) - (null)
19:56:35,900 TRACE (hb…BasicBinder 81) (main ) (W) bind param (6) as (CHAR) - (false)
19:56:35,901 TRACE (hb…BasicBinder 69) (main ) (W) bind param (7) as (DATE) - (null)
19:56:35,902 TRACE (hb…BasicBinder 81) (main ) (W) bind param (8) as (NUMERIC) - (1)
19:56:35,903 TRACE (hb…BasicBinder 81) (main ) (W) bind param (9) as (VARCHAR) - (Electricity)
19:56:35,904 TRACE (hb…BasicBinder 69) (main ) (W) bind param (10) as (VARCHAR) - (null)
19:56:35,905 TRACE (hb…BasicBinder 81) (main ) (W) bind param (11) as (BIGINT) - (11)
19:56:35,906 TRACE (hb…BasicBinder 81) (main ) (W) bind param (13) as (DATE) - (Tue Mar 01 00:00:00 AEDT 2005)
19:56:35,907 TRACE (hb…BasicBinder 81) (main ) (W) bind param (14) as (BIGINT) - (8)
19:56:35,909 TRACE (hb…BasicBinder 81) (main ) (W) bind param (15) as (VARCHAR) - (2001985728)
19:56:35,910 TRACE (hb…BasicBinder 81) (main ) (W) bind param (16) as (CHAR) - (true)
19:56:35,911 TRACE (hb…BasicBinder 69) (main ) (W) bind param (17) as (BIGINT) - (null)
19:56:35,912 TRACE (hb…BasicBinder 81) (main ) (W) bind param (18) as (VARCHAR) - (1)
19:56:35,913 TRACE (hb…BasicBinder 81) (main ) (W) bind param (19) as (CHAR) - (false)
19:56:35,916 DEBUG (hb.id.IdentifierGeneratorHelper 94) (main ) (W) Natively generated identity: 6

** CHILD ENTITY’S VERSION TIMESTAMP OBTAINED FROM THE DATABASE **

19:56:35,917 DEBUG (hb.engine.jdbc.spi.SqlStatementLogger 109) (main ) (W) select electricit_.version as version8_84_ from bbeng_service_points_meters electricit_ where electricit_.id=?
19:56:35,919 TRACE (hb…BasicBinder 81) (main ) (W) bind param (1) as (BIGINT) - (6)
19:56:35,922 TRACE (hb…BasicExtractor 78) (main ) (W) extracted value ((version8_84_) : (TIMESTAMP)) - (2018-03-08 19:56:35.0)

** FLUSHING THE SESSION WHERE THERE IS A DIRTY CHECKING IS DONE ON THE COLLECTION **
** I’VE PAUSE THE EXECUTION BEFORE EXECUTION GOT HERE TO SEE THE ERROR OTHERWISE THE PROBLEM IS INTERMITTENT **

19:56:43,192 DEBUG (com.bb.engine.common.dao.util.hibernate.EntityAuditInterceptor 114) (main ) (W) preFlush entities=org.hibernate.internal.util.collections.LazyIterator@3f851ccf
19:56:43,193 DEBUG (hb.event.internal.AbstractFlushingEventListener 149) (main ) (W) Processing flush-time cascades
19:56:43,194 DEBUG (hb.event.internal.AbstractFlushingEventListener 189) (main ) (W) Dirty checking collections
19:56:43,233 DEBUG (com.bb.engine.common.dao.util.hibernate.EntityAuditInterceptor 61) (main ) (W) onFlushDirty entity=(ElectricityServicePoint id=8, site_detail=Electricity, service_address=(Service Address tenancyNumber=MSB1A, streetNumber=245, streetName=Rosamond, streetType=RD, suburb=Maribyrnong, state=VIC, postcode=3032, country=null), meters=((ElectricityServicingMeter: meter=(UtilityMeter: id=11, serialNumber=66888_1, multiplier=1, registerFormulae=(null)), description=Electricity, formula_variable=null, consumption_ratio=1, period=(Period: startDate=Tue Mar 01 00:00:00 AEDT 2005, endDate=null), withinNetwork=false, onMarket=true, marketIdentifier=com.bb.engine.bb.vo.utility.meter.NMI@81e8f5a5)), gateMeter=true, useParentLossFactorCodes=false, lossFactorCode=(LossFactorCode tni=LV1, dlf=RT2), id=8,
currentState()=1234567890,Thu Mar 08 19:56:26 AEDT 2018,Thu Mar 08 19:56:26 AEDT 2018,false,1234567890,2018-03-08 19:56:35.0,bc94b32fdb1652c4b50b0c63fd8bec7559c965005c090e0fc4b006d44f9ea3fa,((ElectricityServicingMeter: meter=(UtilityMeter: id=11, serialNumber=66888_1, multiplier=1, registerFormulae=(null)), description=Electricity, formula_variable=null, consumption_ratio=1, period=(Period: startDate=Tue Mar 01 00:00:00 AEDT 2005, endDate=null), withinNetwork=false, onMarket=true, marketIdentifier=com.bb.engine.bb.vo.utility.meter.NMI@81e8f5a5)),(Service Address tenancyNumber=MSB1A, streetNumber=245, streetName=Rosamond, streetType=RD, suburb=Maribyrnong, state=VIC, postcode=3032, country=null),0,(ElectricitySiteProfile id=9, site=10000 (Test Site 01), faultContact=(Contact: , name=Fault Contact for electricity, phoneNumber=9873 8480, faxNumber=9879 9886), billFrequency=MONTHLY, paymentPeriod=(PaymentPeriod days=14, method=CALENDAR), defaultMeterDataProvider=null, networkArea=NTWRK_ELECTRICITY),true,0,(LossFactorCode tni=LV1, dlf=RT2,C,0,false,
previousState()=1234567890,Thu Mar 08 19:56:26 AEDT 2018,Thu Mar 08 19:56:26 AEDT 2018,false,1234567890,2018-03-08 19:56:35.0,bc94b32fdb1652c4b50b0c63fd8bec7559c965005c090e0fc4b006d44f9ea3fa,((ElectricityServicingMeter: meter=(UtilityMeter: id=11, serialNumber=66888_1, multiplier=1, registerFormulae=(null)), description=Electricity, formula_variable=null, consumption_ratio=1, period=(Period: startDate=Tue Mar 01 00:00:00 AEDT 2005, endDate=null), withinNetwork=false, onMarket=true, marketIdentifier=com.bb.engine.bb.vo.utility.meter.NMI@81e8f5a5)),(Service Address tenancyNumber=MSB1A, streetNumber=245, streetName=Rosamond, streetType=RD, suburb=Maribyrnong, state=VIC, postcode=3032, country=null),0,(ElectricitySiteProfile id=9, site=10000 (Test Site 01), faultContact=(Contact: , name=Fault Contact for electricity, phoneNumber=9873 8480, faxNumber=9879 9886), billFrequency=MONTHLY, paymentPeriod=(PaymentPeriod days=14, method=CALENDAR), defaultMeterDataProvider=null, networkArea=NTWRK_ELECTRICITY),true,0,(LossFactorCode tni=LV1, dlf=RT2,C,0,false,
propertyNames()=createdByUser,dateCreated,dateModified,deleted,modifiedByUser,version,annualCnsmp,category,closeDate,cnsmpProfile,defaultChargeProfileId,hashCode,meters,openDate,serviceAddress,serviceFormula,servicePoints,siteProfile,supportedAccount,dataProvider,gateMeter,lifeSupports,lossFactorCode,marketIdentifier,onMarket,onMarketServicePoints,parentServicePoint,useParentLossFactorCodes,
types()=org.hibernate.type.StringType@20749d9,org.hibernate.type.CustomType@7882f2e2,org.hibernate.type.CustomType@40fd518f,org.hibernate.type.BooleanType@64b70919,org.hibernate.type.StringType@20749d9,org.hibernate.type.TimestampType@bd1111a,org.hibernate.type.ComponentType@1dafe1d2,org.hibernate.type.StringType@20749d9,org.hibernate.type.DateType@ce9b9a9,org.hibernate.type.StringType@20749d9,org.hibernate.type.IntegerType@6482eef,org.hibernate.type.StringType@20749d9,org.hibernate.type.BagType(com.bb.engine.bb.vo.common.site.service.ServicePoint.meters),org.hibernate.type.DateType@ce9b9a9,org.hibernate.type.ComponentType@77e86a53,org.hibernate.type.StringType@20749d9,org.hibernate.type.IntegerType@6482eef,org.hibernate.type.ManyToOneType(com.bb.engine.bb.vo.common.site.profile.bbSiteProfile),org.hibernate.type.CustomType@189283ae,org.hibernate.type.StringType@20749d9,org.hibernate.type.TrueFalseType@363f0ba0,org.hibernate.type.IntegerType@6482eef,org.hibernate.type.ComponentType@3249c81a,org.hibernate.type.ComponentType@508a1ef0,org.hibernate.type.CustomType@64845c40,org.hibernate.type.IntegerType@6482eef,org.hibernate.type.ManyToOneType(com.bb.engine.bb.vo.utility.site.service.UtilityServicePoint),org.hibernate.type.TrueFalseType@363f0ba0
19:56:43,248 DEBUG (hb.engine.internal.Collections 194) (main ) (W) Collection found: (com.bb.engine.bb.vo.common.site.service.ServicePoint.meters#8), was: () (initialized)
19:56:43,256 DEBUG (hb.event.internal.AbstractFlushingEventListener 123) (main ) (W) Flushed: 0 insertions, 1 updates, 0 deletions to 3 objects
19:56:43,257 DEBUG (hb.event.internal.AbstractFlushingEventListener 130) (main ) (W) Flushed: 1 (re)creations, 0 updates, 0 removals to 1 collections
19:56:43,258 DEBUG (hb.internal.util.EntityPrinter 114) (main ) (W) Listing entities:
19:56:43,259 DEBUG (hb.internal.util.EntityPrinter 121) (main ) (W) com.bb.engine.bb.vo.utility.site.service.ElectricityServicingMeter{formulaVariable=null, streamId=1, createdByUser=null, meter=com.bb.engine.common.vo.meter.AbstractMeter#11, parentServicePoint=null, description=Electricity, dateModified=null, withinNetwork=false, version=2018-03-08 19:56:35.0, consumptionRatio=1, closeDate=null, dateCreated=null, deleted=false, meterReadingsType=INDEXED_THEN_INTERVAL, modifiedByUser=null, cancelled=false, onMarket=true, id=6, servicePoint=com.bb.engine.bb.vo.common.site.service.ServicePoint#8, openDate=Tue Mar 01 00:00:00 AEDT 2005, marketIdentifier=component(value){value=2001985728}}
19:56:43,264 DEBUG (hb.internal.util.EntityPrinter 121) (main ) (W) com.bb.engine.bb.vo.utility.site.service.ElectricityServicePoint{createdByUser=1234567890, servicePoints=0, gateMeter=true, meters=(com.bb.engine.bb.vo.common.site.service.ServicingMeter#6), supportedAccount=null, dateCreated=2018-03-08 08:56:26, useParentLossFactorCodes=false, defaultChargeProfileId=null, hashCode=bc94b32fdb1652c4b50b0c63fd8bec7559c965005c090e0fc4b006d44f9ea3fa, modifiedByUser=1234567890, siteProfile=com.bb.engine.bb.vo.common.site.profile.bbSiteProfile#9, lifeSupports=0, id=8, marketIdentifier=null, annualCnsmp=null, onMarketServicePoints=0, parentServicePoint=null, serviceAddress=component(streetName,streetNumber,streetType,tenancyAddress,tenancyNumber,country,postcode,state,suburb){tenancyNumber=MSB1A, country=null, streetName=Rosamond, streetType=RD, streetNumber=245, tenancyAddress=MSB1A 245 Rosamond RD, postcode=3032, suburb=Maribyrnong, state=VIC}, dateModified=2018-03-08 08:56:26, version=2018-03-08 19:56:43.234, serviceFormula=null, closeDate=null, deleted=false, lossFactorCode=component(dlfCode,tniCode){dlfCode=RT2, tniCode=LV1}, onMarket=C, dataProvider=null, category=null, openDate=null, cnsmpProfile=null}
19:56:43,265 DEBUG (hb.internal.util.EntityPrinter 121) (main ) (W) com.bb.engine.bb.vo.common.site.bbSiteDetail{createdByUser=null, siteName=Test Site 01, commonAddresses=null, lastInvoiceNumber=0, dateCreated=null, activeGateMeters=0, modifiedByUser=null, complex=Test Site 01 (10000), siteNumber=10000, id=9, state=VIC, agencyDetail=null, activeAccounts=0, cutoverDate=2005-03-01, commonSuburb=null, clientIdentifier=TstCnt, complexType=null, firstBillDate=Tue Mar 01 00:00:00 AEDT 2005, dateModified=null, activeServicePoints=0, version=2018-03-08 19:56:26.0, activeServices=null, closeDate=null, deleted=false, lastAccountNumber=0, openDate=null}

** THE PROBLEM IS WITH THIS UPDATE AS THE VERSION HAS CHANGE IN THE DATABASE BUT THE QUERY IS USING AN NEW VERSION TIMESTAMP THAT IS NO LONGER THE SAME AS WHAT IS IN THE DB AS THE UPDATE WAS CALLED **

** WHY IS THIS UPDATE IS DONE IN THE FIRST PLACE, THE PARENT ENTITY HAS NOT CHANGED, IT WAS JUST INSERTED **

19:56:43,290 DEBUG (hb.engine.jdbc.spi.SqlStatementLogger 109) (main ) (W) update bbeng_service_points set date_modified=?, deleted=?, modified_user_id=?, category_name=?, charge_profile_id=?, hash_code=?, tenancy_street_name=?, tenancy_street_number=?, tenancy_street_type=?, snp_tenancy_address=?, tenancy_number=?, tenancy_country=?, tenancy_postcode=?, tenancy_state=?, tenancy_suburb=?, service_formula=?, account_type=?, snp_data_provider=?, gate_meter=?, dlf_code=?, tni_code=?, snp_market_identifier=?, snp_on_market_status=?, parent_id=?, use_parent_tni_dlf=? where id=? and version=?
19:56:43,293 TRACE (hb…BasicBinder 81) (main ) (W) bind param (2) as (BOOLEAN) - (false)
19:56:43,294 TRACE (hb…BasicBinder 81) (main ) (W) bind param (3) as (VARCHAR) - (1234567890)
19:56:43,295 TRACE (hb…BasicBinder 69) (main ) (W) bind param (4) as (VARCHAR) - (null)
19:56:43,296 TRACE (hb…BasicBinder 69) (main ) (W) bind param (5) as (INTEGER) - (null)
19:56:43,297 TRACE (hb…BasicBinder 81) (main ) (W) bind param (6) as (VARCHAR) - (bc94b32fdb1652c4b50b0c63fd8bec7559c965005c090e0fc4b006d44f9ea3fa)
19:56:43,298 TRACE (hb…BasicBinder 81) (main ) (W) bind param (7) as (VARCHAR) - (Rosamond)
19:56:43,299 TRACE (hb…BasicBinder 81) (main ) (W) bind param (8) as (VARCHAR) - (245)
19:56:43,300 TRACE (hb…BasicBinder 81) (main ) (W) bind param (9) as (VARCHAR) - (RD)
19:56:43,301 TRACE (hb…BasicBinder 81) (main ) (W) bind param (10) as (VARCHAR) - (MSB1A 245 Rosamond RD)
19:56:43,302 TRACE (hb…BasicBinder 81) (main ) (W) bind param (11) as (VARCHAR) - (MSB1A)
19:56:43,303 TRACE (hb…BasicBinder 69) (main ) (W) bind param (12) as (VARCHAR) - (null)
19:56:43,304 TRACE (hb…BasicBinder 81) (main ) (W) bind param (13) as (VARCHAR) - (3032)
19:56:43,305 TRACE (hb…BasicBinder 81) (main ) (W) bind param (14) as (VARCHAR) - (VIC)
19:56:43,305 TRACE (hb…BasicBinder 81) (main ) (W) bind param (15) as (VARCHAR) - (Maribyrnong)
19:56:43,306 TRACE (hb…BasicBinder 69) (main ) (W) bind param (16) as (VARCHAR) - (null)
19:56:43,307 TRACE (hb…BasicBinder 69) (main ) (W) bind param (18) as (VARCHAR) - (null)
19:56:43,308 TRACE (hb…BasicBinder 81) (main ) (W) bind param (19) as (CHAR) - (true)
19:56:43,309 TRACE (hb…BasicBinder 81) (main ) (W) bind param (20) as (VARCHAR) - (RT2)
19:56:43,310 TRACE (hb…BasicBinder 81) (main ) (W) bind param (21) as (VARCHAR) - (LV1)
19:56:43,311 TRACE (hb…BasicBinder 69) (main ) (W) bind param (22) as (VARCHAR) - (null)
19:56:43,312 TRACE (hb…BasicBinder 69) (main ) (W) bind param (24) as (BIGINT) - (null)
19:56:43,313 TRACE (hb…BasicBinder 81) (main ) (W) bind param (25) as (CHAR) - (false)
19:56:43,313 TRACE (hb…BasicBinder 81) (main ) (W) bind param (26) as (BIGINT) - (8)
19:56:43,315 TRACE (hb…BasicBinder 81) (main ) (W) bind param (27) as (TIMESTAMP) - (2018-03-08 19:56:43.234)

**** THE EXCEPTION IS THROWN ****

19:56:44,826 FATAL (com.bb.engine.bb.dao.common.site.impl.hibernate.bbSiteHibernateDAO 859) (main ) (W) addOrUpdateServicePoint
org.springframework.orm.hibernate4.HibernateOptimisticLockingFailureException: Object of class (com.bb.engine.bb.vo.utility.site.service.ElectricityServicePoint) with identifier (8): optimistic locking failed; nested exception is org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect) : (com.bb.engine.bb.vo.utility.site.service.ElectricityServicePoint#8)

1 Like
2

As explained in this article, there is no reason to use the TIMESTAMP-based optimistic locking. Use the numeric-based one.

The problem comes from MySQL, which until version 5.6.4, did not offer subsecond timestamp granularity. So, if you generate two updates fast enough, you can get this issue.

You should switch to a Long or an Integer @Version column.

Another problem is the use of Generated(GenerationTime.ALWAYS) for optimistic locking which is not needed. That’s for DB-generated columns, while optimistic locking is for client-side version increments.

1 Like