OptimisticLockException in ServiceRegistry dispatchJob

Steps to reproduce

2018-10-04 01:51:05,978 | WARN | (JavaLog:300) -
Exception [EclipseLink-5006] (Eclipse Persistence Services - 2.6.4.v20160829-44060b6): org.eclipse.persistence.exceptions.OptimisticLockException
Exception Description: The object [Job

{id:42269, operation:Inspect, status:QUEUED}
] cannot be updated because it has changed or been deleted since it was last read.
Class> org.opencastproject.job.jpa.JpaJob Primary Key> 42,269
at org.eclipse.persistence.exceptions.OptimisticLockException.objectChangedSinceLastReadWhenUpdating(OptimisticLockException.java:144)
at org.eclipse.persistence.descriptors.VersionLockingPolicy.validateUpdate(VersionLockingPolicy.java:790)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.internal.queries.DatabaseQueryMechanism.updateObjectForWriteWithChangeSet(DatabaseQueryMechanism.java:1086)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.queries.UpdateObjectQuery.executeCommitWithChangeSet(UpdateObjectQuery.java:84)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.internal.queries.DatabaseQueryMechanism.executeWriteWithChangeSet(DatabaseQueryMechanism.java:301)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.queries.WriteObjectQuery.executeDatabaseQuery(WriteObjectQuery.java:58)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:904)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.queries.DatabaseQuery.executeInUnitOfWork(DatabaseQuery.java:803)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.queries.ObjectLevelModifyQuery.executeInUnitOfWorkObjectLevelModifyQuery(ObjectLevelModifyQuery.java:108)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.queries.ObjectLevelModifyQuery.executeInUnitOfWork(ObjectLevelModifyQuery.java:85)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:2896)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1857)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1839)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1790)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.internal.sessions.CommitManager.commitChangedObjectsForClassWithChangeSet(CommitManager.java:273)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.internal.sessions.CommitManager.commitAllObjectsWithChangeSet(CommitManager.java:131)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.internal.sessions.AbstractSession.writeAllObjectsWithChangeSet(AbstractSession.java:4264)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.commitToDatabase(UnitOfWorkImpl.java:1441)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.commitToDatabaseWithChangeSet(UnitOfWorkImpl.java:1531)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.internal.sessions.RepeatableWriteUnitOfWork.commitRootUnitOfWork(RepeatableWriteUnitOfWork.java:278)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.commitAndResume(UnitOfWorkImpl.java:1169)[314:org.eclipse.persistence.core:2.6.4.v20160829-44060b6]
at org.eclipse.persistence.internal.jpa.transaction.EntityTransactionImpl.commit(EntityTransactionImpl.java:134)[315:org.eclipse.persistence.jpa:2.6.4.v20160829-44060b6]
at org.opencastproject.serviceregistry.impl.ServiceRegistryJpaImpl.updateInternal(ServiceRegistryJpaImpl.java:1003)[141:opencast-serviceregistry:5.0.0.SNAPSHOT]
at org.opencastproject.serviceregistry.impl.ServiceRegistryJpaImpl$JobDispatcher.dispatchJob(ServiceRegistryJpaImpl.java:3158)[141:opencast-serviceregistry:5.0.0.SNAPSHOT]
at org.opencastproject.serviceregistry.impl.ServiceRegistryJpaImpl$JobDispatcher.dispatchDispatchableJobs(ServiceRegistryJpaImpl.java:3079)[141:opencast-serviceregistry:5.0.0.SNAPSHOT]
at org.opencastproject.serviceregistry.impl.ServiceRegistryJpaImpl$JobDispatcher.run(ServiceRegistryJpaImpl.java:2973)[141:opencast-serviceregistry:5.0.0.SNAPSHOT]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_171]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)[:1.8.0_171]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)[:1.8.0_171]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)[:1.8.0_171]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)[:1.8.0_171]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)[:1.8.0_171]
at java.lang.Thread.run(Thread.java:748)[:1.8.0_171]
2018-10-04 01:51:05,981 | ERROR | (ServiceRegistryJpaImpl:1027) - JPA status mismatch: DISPATCHING vs QUEUED
2018-10-04 01:51:05,981 | ERROR | (ServiceRegistryJpaImpl:1029) - originalJob.getProcessorServiceRegistration() is null

It happens when an encode operation (multiencode, process-smil, etc) creates inspection sub-jobs: the parent job needs to be suspended and the child jobs need to be updated with the job blocked on them and vice-versa.

This is the sequence:
1) On worker, encode finishes and asks inspection service to create the job(s). Inspection job is created as QUEUED. At this point, it is already ready to be dispatched by the service registry dispatcher on admin.
2) Admin node dispatcher reads the inspection job in QUEUED state, changes it state to DISPATCHING in memory. The jpa version is, for instance, v1.
3) Meanwhile, the encode job is updated (status, blocking jobs) and the inspection job(s) is updated (blocked job) on the worker. The jpa version is incremented to v2 in the db.
4) The dispatcher on admin tries to update the inspection job in the database and gets the optimistic lock exception because it read version v1, but now the db has version v2.

Assignee

Rute Santos

Reporter

Rute Santos

Severity

Incorrectly Functioning With Workaround

Tags (folksonomy)

None

Components

Affects versions

Priority

Major
Configure