[OFBIZ-11204] Remove unwanted error log by `ServiceSemaphore` waiting process

• Type: Improvement
• Status: Closed
• Priority: Minor
• Resolution: Fixed
• Affects Version/s: Trunk
• Fix Version/s: Trunk
• Component/s: framework
• Assignee: Gil Portenseigne
• Reporter: Gil Portenseigne
• Created: 19/Sep/19 15:58
• Updated: 25/May/20 07:47
• Resolved: 25/Oct/19 15:25

Description

When a lot of semaphore configured service instances are running in a short period, multiple errors of this type are logged :

// | 2019-09-19 14:47:44.000 | 2019-09-19 16:47:44,692 |OFBiz-JobQueue-2     |GenericDelegator              |E| Failure in create operation for entity [ServiceSemaphore]: org.apache.ofbiz.entity.GenericEntityException: Error while inserting: [GenericEntity:ServiceSemaphore][createdStamp,2019-09-19 16:47:44.678(java.sql.Timestamp)][createdTxStamp,2019-09-19 16:47:44.678(java.sql.Timestamp)][lastUpdatedStamp,2019-09-19 16:47:44.678(java.sql.Timestamp)][lastUpdatedTxStamp,2019-09-19 16:47:44.678(java.sql.Timestamp)][lockThread,OFBiz-JobQueue-2(java.lang.String)][lockTime,2019-09-19 16:47:44.676(java.sql.Timestamp)][lockedByInstanceId,emb-ofbiz-prd-technical-asg-20171209-01-eu-west-1b(java.lang.String)][serviceName,xxx(java.lang.String)] (SQL Exception while executing the following:INSERT INTO public.SERVICE_SEMAPHORE (SERVICE_NAME, LOCKED_BY_INSTANCE_ID, LOCK_THREAD, LOCK_TIME, LAST_UPDATED_STAMP, LAST_UPDATED_TX_STAMP, CREATED_STAMP, CREATED_TX_STAMP) VALUES (?, ?, ?, ?, ?, ?, ?, ?) (ERROR: duplicate key value violates unique constraint "pk_service_semaphore"   Detail: Key (service_name)=(xxx) already exists.)). Rolling back transaction.                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                      |
| 2019-09-19 14:47:44.000 | 2019-09-19 16:47:44,692 |OFBiz-JobQueue-2     |ServiceSemaphore              |E| null 
|
| 2019-09-19 14:47:44.000 | org.apache.ofbiz.entity.GenericEntityException: org.apache.ofbiz.entity.GenericEntityException: Error while inserting: [GenericEntity:ServiceSemaphore][createdStamp,2019-09-19 16:47:44.678(java.sql.Timestamp)][createdTxStamp,2019-09-19 16:47:44.678(java.sql.Timestamp)][lastUpdatedStamp,2019-09-19 16:47:44.678(java.sql.Timestamp)][lastUpdatedTxStamp,2019-09-19 16:47:44.678(java.sql.Timestamp)][lockThread,OFBiz-JobQueue-2(java.lang.String)][lockTime,2019-09-19 16:47:44.676(java.sql.Timestamp)][lockedByInstanceId,emb-ofbiz-prd-technical-asg-20171209-01-eu-west-1b(java.lang.String)][serviceName,xxx(java.lang.String)] (SQL Exception while executing the following:INSERT INTO public.SERVICE_SEMAPHORE (SERVICE_NAME, LOCKED_BY_INSTANCE_ID, LOCK_THREAD, LOCK_TIME, LAST_UPDATED_STAMP, LAST_UPDATED_TX_STAMP, CREATED_STAMP, CREATED_TX_STAMP) VALUES (?, ?, ?, ?, ?, ?, ?, ?) (ERROR: duplicate key value violates unique constraint "pk_service_semaphore"   Detail: Key (service_name)=(xxx) already exists.)) (Error while inserting: [GenericEntity:ServiceSemaphore][createdStamp,2019-09-19 16:47:44.678(java.sql.Timestamp)][createdTxStamp,2019-09-19 16:47:44.678(java.sql.Timestamp)][lastUpdatedStamp,2019-09-19 16:47:44.678(java.sql.Timestamp)][lastUpdatedTxStamp,2019-09-19 16:47:44.678(java.sql.Timestamp)][lockThread,OFBiz-JobQueue-2(java.lang.String)][lockTime,2019-09-19 16:47:44.676(java.sql.Timestamp)][lockedByInstanceId,emb-ofbiz-prd-technical-asg-20171209-01-eu-west-1b(java.lang.String)][serviceName,xxx(java.lang.String)] (SQL Exception while executing the following:INSERT INTO public.SERVICE_SEMAPHORE (SERVICE_NAME, LOCKED_BY_INSTANCE_ID, LOCK_THREAD, LOCK_TIME, LAST_UPDATED_STAMP, LAST_UPDATED_TX_STAMP, CREATED_STAMP, CREATED_TX_STAMP) VALUES (?, ?, ?, ?, ?, ?, ?, ?) (ERROR: duplicate key value violates unique constraint "pk_service_semaphore"   Detail: Key (service_name)=(xxx) already exists.)))  at org.apache.ofbiz.entity.GenericDelegator.create(GenericDelegator.java:896) ~[ofbiz.jar:?]  at org.apache.ofbiz.entity.GenericValue.create(GenericValue.java:76) ~[ofbiz.jar:?]  at org.apache.ofbiz.service.semaphore.ServiceSemaphore.dbWrite(ServiceSemaphore.java:172) [ofbiz.jar:?]  at org.apache.ofbiz.service.semaphore.ServiceSemaphore.checkLockNeedToWait(ServiceSemaphore.java:137) [ofbiz.jar:?]  at org.apache.ofbiz.service.semaphore.ServiceSemaphore.acquire(ServiceSemaphore.java:70) [ofbiz.jar:?]  at org.apache.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:284) [ofbiz.jar:?]  at org.apache.ofbiz.service.ServiceDispatcher.runSync(ServiceDispatcher.java:240) [ofbiz.jar:?]  at org.apache.ofbiz.service.GenericDispatcherFactory$GenericDispatcher.runSync(GenericDispatcherFactory.java:88) [ofbiz.jar:?]  at org.apache.ofbiz.service.job.GenericServiceJob.exec(GenericServiceJob.java:70) [ofbiz.jar:?]  at org.apache.ofbiz.service.job.AbstractJob.run(AbstractJob.java:87) [ofbiz.jar:?]  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]  at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222] |

With lot of activity this can spam the logs reducing visibility of real errors in production logs.

For this, i proposed to add a last check within the synchronized method before inserting the lock, on which the fk constraint error is thrown.

This avoiding the error, if no other method in OFBiz insert data in `ServiceSemaphore` table...

A second patch is provided to add javadoc and trivial refoctoring