Defect #1819
closedFailed provisioning during attribute recalculation
90%
Description
Version 9.7.4
We removed a testing role which filled an attribute with Merge strategy.
At the same time a provisioning from some other asynchronous event was attempted. (The user didn't have this role.) The provisioning failed.
Full error:
org.springframework.transaction.TransactionSystemException: Could not commit JPA transaction; nested exception is javax.persistence.RollbackException: Transaction marked as rollbackOnly at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:526) at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:761) at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:730) at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:484) at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:291) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:655) at eu.bcvsolutions.idm.core.model.service.impl.DefaultEntityEventManager$$EnhancerBySpringCGLIB$$90d022c9.process(<generated>) at eu.bcvsolutions.idm.acc.service.impl.DefaultProvisioningExecutor.executeInternal(DefaultProvisioningExecutor.java:164) at eu.bcvsolutions.idm.acc.service.impl.DefaultProvisioningExecutor$$FastClassBySpringCGLIB$$68607120.invoke(<generated>) at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:720) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99) at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:655) at eu.bcvsolutions.idm.acc.service.impl.DefaultProvisioningExecutor$$EnhancerBySpringCGLIB$$b5a081c.executeInternal(<generated>) at sun.reflect.GeneratedMethodAccessor1298.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.springframework.context.event.ApplicationListenerMethodAdapter.doInvoke(ApplicationListenerMethodAdapter.java:223) at org.springframework.context.event.ApplicationListenerMethodAdapter.processEvent(ApplicationListenerMethodAdapter.java:144) at org.springframework.transaction.event.ApplicationListenerMethodTransactionalAdapter$TransactionSynchronizationEventAdapter.processEvent(ApplicationListenerMethodTransactionalAdapter.java:133) at org.springframework.transaction.event.ApplicationListenerMethodTransactionalAdapter$TransactionSynchronizationEventAdapter.afterCompletion(ApplicationListenerMethodTransactionalAdapter.java:120) at org.springframework.transaction.support.TransactionSynchronizationUtils.invokeAfterCompletion(TransactionSynchronizationUtils.java:168) at org.springframework.transaction.support.AbstractPlatformTransactionManager.invokeAfterCompletion(AbstractPlatformTransactionManager.java:1001) at org.springframework.transaction.support.AbstractPlatformTransactionManager.triggerAfterCompletion(AbstractPlatformTransactionManager.java:976) at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:806) at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:730) at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:484) at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:291) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:655) at eu.bcvsolutions.idm.core.model.service.impl.DefaultEntityEventManager$$EnhancerBySpringCGLIB$$90d022c9.process(<generated>) at eu.bcvsolutions.idm.core.model.event.processor.event.EntityEventExecuteProcessor.process(EntityEventExecuteProcessor.java:52) at eu.bcvsolutions.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent(AbstractEntityEventProcessor.java:238) at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:166) at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:138) at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:381) at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:348) at eu.bcvsolutions.idm.core.model.service.impl.DefaultEntityEventManager.process(DefaultEntityEventManager.java:247) at eu.bcvsolutions.idm.core.model.service.impl.DefaultEntityEventManager.process(DefaultEntityEventManager.java:177) at eu.bcvsolutions.idm.core.model.service.impl.DefaultEntityEventManager$2.run(DefaultEntityEventManager.java:536) at org.springframework.security.concurrent.DelegatingSecurityContextRunnable.run(DelegatingSecurityContextRunnable.java:80) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) Caused by: javax.persistence.RollbackException: Transaction marked as rollbackOnly at org.hibernate.jpa.internal.TransactionImpl.commit(TransactionImpl.java:74) at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:517) ... 50 more
Application log:
2019-08-22 21:16:44.910 INFO 20935 --- [task-executor-2] e.b.i.c.a.e.AbstractEntityEventProcessor : Processor [prepare-connector-object-processor]([acc]) start for [CoreEvent [type: UPDATE , content: eu.bcvsolutions.idm.acc.dto.SysProvisioningOperationDto [id=df5d2e85-06ce-419d-9ffe-c438e5c4b568], properties: {}]] with order [-1000]. 2019-08-22 21:16:45.066 INFO 20935 --- [task-executor-1] somethingGetDepartment : End 'somethingGetDepartment' script. 2019-08-22 21:16:45.105 INFO 20935 --- [task-executor-4] somethingGetDepartment : Start 'somethingGetDepartment' script. 2019-08-22 21:16:45.221 INFO 20935 --- [task-executor-4] somethingGetDepartment : End 'somethingGetDepartment' script. 2019-08-22 21:16:45.242 INFO 20935 --- [task-executor-4] somethingAdGetDepartmentNumber : Start 'somethingAdGetDepartmentNumber' script. 2019-08-22 21:16:45.316 INFO 20935 --- [task-executor-4] somethingAdGetDepartmentNumber : End 'somethingAdGetDepartmentNumber' script. 2019-08-22 21:16:45.338 INFO 20935 --- [task-executor-4] somethingGetDepartment : Start 'somethingGetDepartment' script. 2019-08-22 21:16:45.402 INFO 20935 --- [task-executor-4] somethingGetDepartment : End 'somethingGetDepartment' script. 2019-08-22 21:16:50.086 INFO 20935 --- [task-executor-3] e.b.i.c.m.s.i.DefaultEntityEventManager : Publishing event [CoreEvent [type: DELETE, content: eu.bcvsolutions.idm.acc.dto.SysAttributeControlledValueDto [id=d3517e1a-ea79-4c29-ad01-2e6199f00b27], properties: {}]] 2019-08-22 21:16:50.088 INFO 20935 --- [task-executor-3] e.b.i.c.a.e.AbstractEntityEventProcessor : Processor [attribute-controlled-value-delete-processor]([acc]) start for [CoreEvent [type: DELETE, content: eu.bcvsolutions.idm.acc.dto.SysAttributeControlledValueDto [id=d3517e1a-ea79-4c29-ad01-2e6199f00b27], properties: {}]] with order [0]. 2019-08-22 21:16:50.089 INFO 20935 --- [task-executor-3] e.b.i.c.a.e.AbstractEntityEventProcessor : Processor [attribute-controlled-value-delete-processor]([acc]) end for [CoreEvent [type: DELETE, content: eu.bcvsolutions.idm.acc.dto.SysAttributeControlledValueDto [id=d3517e1a-ea79-4c29-ad01-2e6199f00b27], properties: {}]] with order [0]. 2019-08-22 21:16:50.089 INFO 20935 --- [task-executor-3] e.b.i.c.m.s.i.DefaultEntityEventManager : Event [CoreEvent [type: DELETE, content: eu.bcvsolutions.idm.acc.dto.SysAttributeControlledValueDto [id=d3517e1a-ea79-4c29-ad01-2e6199f00b27], properties: {}]] is completed 2019-08-22 21:16:50.089 INFO 20935 --- [task-executor-3] e.b.i.c.m.s.i.DefaultEntityEventManager : Publishing event [CoreEvent [type: CREATE, content: eu.bcvsolutions.idm.acc.dto.SysAttributeControlledValueDto [id=null], properties: {}]] 2019-08-22 21:16:50.089 INFO 20935 --- [task-executor-3] e.b.i.c.a.e.AbstractEntityEventProcessor : Processor [core-entity-generate-values-processor]([core]) start for [CoreEvent [type: CREATE, content: eu.bcvsolutions.idm.acc.dto.SysAttributeControlledValueDto [id=null], properties: {}]] with order [-100]. 2019-08-22 21:16:50.089 INFO 20935 --- [task-executor-3] e.b.i.c.a.e.AbstractEntityEventProcessor : Processor [core-entity-generate-values-processor]([core]) end for [CoreEvent [type: CREATE, content: eu.bcvsolutions.idm.acc.dto.SysAttributeControlledValueDto [id=null], properties: {}]] with order [-100]. 2019-08-22 21:16:50.089 INFO 20935 --- [task-executor-3] e.b.i.c.a.e.AbstractEntityEventProcessor : Processor [attribute-controlled-value-save-processor]([acc]) start for [CoreEvent [type: CREATE, content: eu.bcvsolutions.idm.acc.dto.SysAttributeControlledValueDto [id=null], properties: {}]] with order [0]. 2019-08-22 21:16:50.109 INFO 20935 --- [task-executor-3] e.b.i.c.a.e.AbstractEntityEventProcessor : Processor [attribute-controlled-value-save-processor]([acc]) end for [CoreEvent [type: CREATE, content: eu.bcvsolutions.idm.acc.dto.SysAttributeControlledValueDto [id=ac21a786-6224-4b8d-a26c-32a0aca35ee9], properties: {}]] with order [0]. 2019-08-22 21:16:50.109 INFO 20935 --- [task-executor-3] e.b.i.c.m.s.i.DefaultEntityEventManager : Event [CoreEvent [type: CREATE, content: eu.bcvsolutions.idm.acc.dto.SysAttributeControlledValueDto [id=ac21a786-6224-4b8d-a26c-32a0aca35ee9], properties: {}]] is completed 2019-08-22 21:16:51.563 INFO 20935 --- [task-executor-2] e.b.i.c.m.s.i.DefaultEntityEventManager : Publishing event [CoreEvent [type: DELETE, content: eu.bcvsolutions.idm.acc.dto.SysAttributeControlledValueDto [id=d3517e1a-ea79-4c29-ad01-2e6199f00b27], properties: {}]] 2019-08-22 21:16:51.565 INFO 20935 --- [task-executor-2] e.b.i.c.a.e.AbstractEntityEventProcessor : Processor [attribute-controlled-value-delete-processor]([acc]) start for [CoreEvent [type: DELETE, content: eu.bcvsolutions.idm.acc.dto.SysAttributeControlledValueDto [id=d3517e1a-ea79-4c29-ad01-2e6199f00b27], properties: {}]] with order [0]. 2019-08-22 21:16:51.565 INFO 20935 --- [task-executor-2] e.b.i.c.a.e.AbstractEntityEventProcessor : Processor [attribute-controlled-value-delete-processor]([acc]) end for [CoreEvent [type: DELETE, content: eu.bcvsolutions.idm.acc.dto.SysAttributeControlledValueDto [id=d3517e1a-ea79-4c29-ad01-2e6199f00b27], properties: {}]] with order [0]. 2019-08-22 21:16:51.565 INFO 20935 --- [task-executor-2] e.b.i.c.m.s.i.DefaultEntityEventManager : Event [CoreEvent [type: DELETE, content: eu.bcvsolutions.idm.acc.dto.SysAttributeControlledValueDto [id=d3517e1a-ea79-4c29-ad01-2e6199f00b27], properties: {}]] is completed 2019-08-22 21:16:51.566 INFO 20935 --- [task-executor-2] e.b.i.c.m.s.i.DefaultEntityEventManager : Publishing event [CoreEvent [type: CREATE, content: eu.bcvsolutions.idm.acc.dto.SysAttributeControlledValueDto [id=null], properties: {}]] 2019-08-22 21:16:51.566 INFO 20935 --- [task-executor-2] e.b.i.c.a.e.AbstractEntityEventProcessor : Processor [core-entity-generate-values-processor]([core]) start for [CoreEvent [type: CREATE, content: eu.bcvsolutions.idm.acc.dto.SysAttributeControlledValueDto [id=null], properties: {}]] with order [-100]. 2019-08-22 21:16:51.566 INFO 20935 --- [task-executor-2] e.b.i.c.a.e.AbstractEntityEventProcessor : Processor [core-entity-generate-values-processor]([core]) end for [CoreEvent [type: CREATE, content: eu.bcvsolutions.idm.acc.dto.SysAttributeControlledValueDto [id=null], properties: {}]] with order [-100]. 2019-08-22 21:16:51.566 INFO 20935 --- [task-executor-2] e.b.i.c.a.e.AbstractEntityEventProcessor : Processor [attribute-controlled-value-save-processor]([acc]) start for [CoreEvent [type: CREATE, content: eu.bcvsolutions.idm.acc.dto.SysAttributeControlledValueDto [id=null], properties: {}]] with order [0]. 2019-08-22 21:16:51.595 ERROR 20935 --- [task-executor-2] e.b.i.c.a.e.AbstractEntityEventProcessor : [core:EVENT_EXECUTE_PROCESSOR_FAILED:6d2621a6-77f9-452c-bdbc-77bafb43ff35] Event [null] failed in processor [attribute-controlled-value-save-processor]. ({eventId=null, processor=attribute-controlled-value-save-processor}) 2019-08-22 21:16:51.599 ERROR 20935 --- [task-executor-2] i.DefaultSysProvisioningOperationService : [acc:PROVISIONING_FAILED:000aabb3-34cf-49dd-8624-177b97bee57e] Provisioning operation for object with uid [xxxxxxx] on system [AD uživatelé], operation type [UPDATE], object class [__ACCOUNT__] failed. ({name=xxxxxx, system=AD uživatelé, operationType=UPDATE, objectClass=__ACCOUNT__}) 2019-08-22 21:16:51.604 INFO 20935 --- [task-executor-3] ontrolledValuesRecalculationTaskExecutor : End: Merge - attribute controlled values recalculation for system [6d33e1f9-a24c-430c-ad32-860d640b3a29]
Files
Related issues
Updated by Vít Švanda over 5 years ago
- Status changed from In Progress to Needs feedback
- Assignee changed from Vít Švanda to Radek Tomiška
I was not able simulated this problem locally, but I trust the problem exists. Problem is in paralel running of more recalulations of controlled values (first run on delete the role and second during provisioning).
I removed execution of LRT for recalculation of the controlled values after attribute on role was changed/deleted. Attribute on system is marked as evicted only now.
Recalculation will be processed during first using of controlled values. This is typically on first update provisioning. Beware if new account is created and create provisioning is executed, then recalculation is not executed, because in this situation are controlled values not needed!
For prevent collision of more recalculations in same time I made method DefaultSysSystemAttributeMappingService.recalculateAttributeControlledValues synchornized.
Commit: https://github.com/bcvsolutions/CzechIdMng/commit/77a35e7973f008b51d6af71b557ad995b22aa27a
Documentation modified: https://wiki.czechidm.com/devel/documentation/systems/dev/system-mapping#merge_merge
Updated by Vít Švanda over 5 years ago
- Related to Defect #1818: Duplicate values in controlled values for Merge strategy added
Updated by Radek Tomiška over 5 years ago
- Status changed from Needs feedback to Resolved
- Assignee changed from Radek Tomiška to Vít Švanda
- % Done changed from 0 to 90
I did test and review, code looks nice!
This simplification helps on all places, i like it.