Project

General

Profile

Actions

Defect #1819

closed

Failed provisioning during attribute recalculation

Added by Alena Peterová over 5 years ago. Updated over 5 years ago.

Status:
Closed
Priority:
Normal
Assignee:
Vít Švanda
Category:
Provisioning
Target version:
Start date:
08/23/2019
Due date:
% Done:

90%

Estimated time:
Affected versions:
Owner:

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

failed_provisioning_overview.png (6.59 KB) failed_provisioning_overview.png Alena Peterová, 08/23/2019 01:31 PM
failed_provisioning.png (52 KB) failed_provisioning.png Alena Peterová, 08/23/2019 01:31 PM
LRT_delete_role_recalculate.png (20.6 KB) LRT_delete_role_recalculate.png Alena Peterová, 08/23/2019 01:31 PM

Related issues

Related to IdStory Identity Manager - Defect #1818: Duplicate values in controlled values for Merge strategyClosedVít Švanda08/23/2019

Actions
Actions #1

Updated by Vít Švanda over 5 years ago

  • Target version set to Rhyolite (9.7.5)
Actions #2

Updated by Vít Švanda over 5 years ago

  • Status changed from New to In Progress
Actions #3

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

Actions #4

Updated by Vít Švanda over 5 years ago

  • Related to Defect #1818: Duplicate values in controlled values for Merge strategy added
Actions #5

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.

Actions #6

Updated by Vít Švanda over 5 years ago

  • Status changed from Resolved to Closed
Actions

Also available in: Atom PDF