Project

General

Profile

Actions

Defect #3029

closed

Removing multiple automatic roles by tree node - some of the tasks fail (Warning or Waiting)

Added by Alena Peterová about 2 years ago. Updated about 1 year ago.

Status:
Closed
Priority:
High
Assignee:
Tomáš Doischer
Category:
Automatic roles
Target version:
Start date:
01/05/2022
Due date:
% Done:

100%

Estimated time:
Affected versions:
Owner:

Description

This happened on 11.2.1
One role (AD group) was automatic for a lot of organizations without recursion. (Maybe more than 100 tree nodes.)
The administrator removed all these automatic roles.
It started processing and removing the role from users, but some of the tasks RemoveAutomaticRoleTaskExecutor didn't finish correctly. Now after 1 day, some are Warning, some Waiting.

The error in the failed tasks (Warning) looks like this:

Role is used by concurrent task
Automatic role is processed by concurrent task [6d4ff27b-4dfd-424f-ac02-75fc44f91f5b], wait for task completion.

eu.bcvsolutions.idm.core.api.exception.AcceptedException: Automatic role is processed in concurent task [6d4ff27b-4dfd-424f-ac02-75fc44f91f5b], wait for task is complete.
    at eu.bcvsolutions.idm.core.scheduler.task.impl.RemoveAutomaticRoleTaskExecutor.validate(RemoveAutomaticRoleTaskExecutor.java:129)
    at eu.bcvsolutions.idm.core.scheduler.api.service.AbstractLongRunningTaskExecutor.start(AbstractLongRunningTaskExecutor.java:162)
    at eu.bcvsolutions.idm.core.scheduler.task.impl.RemoveAutomaticRoleTaskExecutor.start(RemoveAutomaticRoleTaskExecutor.java:197)
    at eu.bcvsolutions.idm.core.scheduler.api.service.AbstractLongRunningTaskExecutor.call(AbstractLongRunningTaskExecutor.java:263)
    at eu.bcvsolutions.idm.core.scheduler.api.service.AbstractLongRunningTaskExecutor$$FastClassBySpringCGLIB$$f9eae371.invoke(<generated>)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:687)
    at eu.bcvsolutions.idm.core.scheduler.task.impl.RemoveAutomaticRoleTaskExecutor$$EnhancerBySpringCGLIB$$6f0e68ff.call(<generated>)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at eu.bcvsolutions.idm.core.config.DelegatingTransactionContextRunnable.run(DelegatingTransactionContextRunnable.java:39)
    at org.springframework.security.concurrent.DelegatingSecurityContextRunnable.run(DelegatingSecurityContextRunnable.java:84)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:829)

The message is misleading in my opinion, because the "concurrent" task processes some other automatic role. In the code, RemoveAutomaticRoleTaskExecutor doesn't look for specifically the same automatic role.

The result was probably not deleted automatic role and opened Requests for automatic roles for Remove. But administrators deleted the automatic roles again and cancelled the requests, so it's hard to tell.

The error messages in catalina out didn't help me, but for completeness:

(automatic role request byl 0e7ea8ae-923a-4628-b7e1-246831d94274
role tree node byl 2056a5f8-be4b-4873-bac1-4003e0cc76e7
failed task byl ced755e5-58cc-4d13-a490-09c42f35634c )
cat /data/logs/czechidm/czechidm.log-20220105 | grep '0e7ea8ae-923a-4628-b7e1-246831d94274\|2056a5f8-be4b-4873-bac1-4003e0cc76e7\|ced755e5-58cc-4d13-a490-09c42f35634c'  
+ pridana jedina chyba, ktera se tam objevila

Jan  4 09:03:00 vIDM01 czechidm[1270]: 2022-01-04 09:03:00.867  INFO 1648421075 --- [http-nio-8080-exec-3] e.b.idm.core.model.service.impl.DefaultEntityEventManager.process : Publishing event [AutomaticRoleRequestEvent [type: EXECUTE, content: eu.bcvsolutions.idm.core.api.dto.IdmAutomaticRoleRequestDto [id=0e7ea8ae-923a-4628-b7e1-246831d94274], properties: {checkRight=true}]]
Jan  4 09:03:00 vIDM01 czechidm[1270]: 2022-01-04 09:03:00.867  INFO 1648421075 --- [http-nio-8080-exec-3] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [automatic-role-request-approval-processor]([core]) start for [AutomaticRoleRequestEvent [type: EXECUTE, content: eu.bcvsolutions.idm.core.api.dto.IdmAutomaticRoleRequestDto [id=0e7ea8ae-923a-4628-b7e1-246831d94274], properties: {checkRight=true}]] with order [-1000].
Jan  4 09:03:00 vIDM01 czechidm[1270]: 2022-01-04 09:03:00.868  INFO 1648421076 --- [http-nio-8080-exec-3] e.b.i.c.m.e.p.role.AutomaticRoleRequestApprovalProcessor.process : None approval process definition was found, request [eu.bcvsolutions.idm.core.api.dto.IdmAutomaticRoleRequestDto [id=0e7ea8ae-923a-4628-b7e1-246831d94274]] for automatic role is approved.
Jan  4 09:03:00 vIDM01 czechidm[1270]: 2022-01-04 09:03:00.868  INFO 1648421076 --- [http-nio-8080-exec-3] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [automatic-role-request-approval-processor]([core]) end for [AutomaticRoleRequestEvent [type: EXECUTE, content: eu.bcvsolutions.idm.core.api.dto.IdmAutomaticRoleRequestDto [id=0e7ea8ae-923a-4628-b7e1-246831d94274], properties: {checkRight=true}]] with order [-1000].
Jan  4 09:03:00 vIDM01 czechidm[1270]: 2022-01-04 09:03:00.868  INFO 1648421076 --- [http-nio-8080-exec-3] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [automatic-role-request-realization-processor]([core]) start for [AutomaticRoleRequestEvent [type: EXECUTE, content: eu.bcvsolutions.idm.core.api.dto.IdmAutomaticRoleRequestDto [id=0e7ea8ae-923a-4628-b7e1-246831d94274], properties: {checkRight=true}]] with order [0].
Jan  4 09:03:00 vIDM01 czechidm[1270]: 2022-01-04 09:03:00.871  INFO 1648421079 --- [http-nio-8080-exec-3] e.b.idm.core.model.service.impl.DefaultEntityEventManager.process : Publishing event [CoreEvent [type: DELETE, content: eu.bcvsolutions.idm.core.api.dto.IdmRoleTreeNodeDto [id=2056a5f8-be4b-4873-bac1-4003e0cc76e7], properties: {idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@695613a8}]]
Jan  4 09:03:00 vIDM01 czechidm[1270]: 2022-01-04 09:03:00.872  INFO 1648421080 --- [http-nio-8080-exec-3] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [role-tree-node-delete-processor]([core]) start for [CoreEvent [type: DELETE, content: eu.bcvsolutions.idm.core.api.dto.IdmRoleTreeNodeDto [id=2056a5f8-be4b-4873-bac1-4003e0cc76e7], properties: {idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@695613a8}]] with order [0].
Jan  4 09:03:00 vIDM01 czechidm[1270]: 2022-01-04 09:03:00.876  INFO 1648421084 --- [base-task-executor-1] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [entity-event-save-processor]([core]) end for [CoreEvent [type: CREATE, content: eu.bcvsolutions.idm.core.api.dto.IdmEntityEventDto [id=9bc0502e-56e4-44ca-bfdf-cb67a5235704], properties: {idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@6347ec41}]] with order [0].
Jan  4 09:03:00 vIDM01 czechidm[1270]: 2022-01-04 09:03:00.876  INFO 1648421084 --- [base-task-executor-1] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [role-request-publish-change-processor]([core]) end for [RoleRequestEvent [type: EXCECUTE, content: eu.bcvsolutions.idm.core.api.dto.IdmRoleRequestDto [id=3334a947-3fd4-40e6-b4f3-d94d9533841a], properties: {skipCheckAuthorities=true, idm:super-owner-id=26ce80ab-4ff3-4795-8207-b04558525604, idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@708c4118}]] with order [10000].
Jan  4 09:03:00 vIDM01 czechidm[1270]: 2022-01-04 09:03:00.878  INFO 1648421086 --- [http-nio-8080-exec-3] e.b.idm.core.model.service.impl.DefaultEntityEventManager.process : Publishing event [CoreEvent [type: CREATE, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=null], properties: {idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@58e358d4}]]
Jan  4 09:03:00 vIDM01 czechidm[1270]: 2022-01-04 09:03:00.879  INFO 1648421087 --- [http-nio-8080-exec-3] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [core-entity-generate-values-processor]([core]) start for [CoreEvent [type: CREATE, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=null], properties: {idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@58e358d4}]] with order [-100].
Jan  4 09:03:00 vIDM01 czechidm[1270]: 2022-01-04 09:03:00.879  INFO 1648421087 --- [http-nio-8080-exec-3] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [core-entity-generate-values-processor]([core]) end for [CoreEvent [type: CREATE, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=null], properties: {idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@58e358d4}]] with order [-100].
Jan  4 09:03:00 vIDM01 czechidm[1270]: 2022-01-04 09:03:00.879  INFO 1648421087 --- [http-nio-8080-exec-3] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [core-long-running-task-save-processor]([core]) start for [CoreEvent [type: CREATE, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=null], properties: {idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@58e358d4}]] with order [0].
Jan  4 09:03:00 vIDM01 czechidm[1270]: 2022-01-04 09:03:00.882  INFO 1648421090 --- [http-nio-8080-exec-3] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [core-long-running-task-save-processor]([core]) end for [CoreEvent [type: CREATE, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=ced755e5-58cc-4d13-a490-09c42f35634c], properties: {idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@58e358d4}]] with order [0].
Jan  4 09:03:00 vIDM01 czechidm[1270]: 2022-01-04 09:03:00.934  INFO 1648421142 --- [http-nio-8080-exec-3] e.b.idm.core.model.service.impl.DefaultEntityEventManager.process : Publishing event [CoreEvent [type: UPDATE, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=ced755e5-58cc-4d13-a490-09c42f35634c], properties: {idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@6659a8e8}]]
Jan  4 09:03:00 vIDM01 czechidm[1270]: 2022-01-04 09:03:00.945  INFO 1648421153 --- [http-nio-8080-exec-3] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [core-long-running-task-save-processor]([core]) start for [CoreEvent [type: UPDATE, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=ced755e5-58cc-4d13-a490-09c42f35634c], properties: {idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@6659a8e8}]] with order [0].
Jan  4 09:03:00 vIDM01 czechidm[1270]: 2022-01-04 09:03:00.955  INFO 1648421163 --- [http-nio-8080-exec-3] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [core-long-running-task-save-processor]([core]) end for [CoreEvent [type: UPDATE, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=ced755e5-58cc-4d13-a490-09c42f35634c], properties: {idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@6659a8e8}]] with order [0].
Jan  4 09:03:00 vIDM01 czechidm[1270]: 2022-01-04 09:03:00.967  INFO 1648421175 --- [http-nio-8080-exec-3] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [role-tree-node-delete-processor]([core]) end for [CoreEvent [type: DELETE, content: eu.bcvsolutions.idm.core.api.dto.IdmRoleTreeNodeDto [id=2056a5f8-be4b-4873-bac1-4003e0cc76e7], properties: {idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@695613a8}]] with order [0].

Jan  4 09:03:00 vIDM01 czechidm[1270]: 2022-01-04 09:03:00.971  INFO 1648421179 --- [http-nio-8080-exec-3] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [automatic-role-request-realization-processor]([core]) end for [AutomaticRoleRequestEvent [type: EXECUTE, content: eu.bcvsolutions.idm.core.api.dto.IdmAutomaticRoleRequestDto [id=0e7ea8ae-923a-4628-b7e1-246831d94274], properties: {checkRight=true}]] with order [0].
Jan  4 09:03:01 vIDM01 czechidm[1270]: 2022-01-04 09:03:01.278  INFO 1648421486 --- [scheduling-1] e.b.idm.core.model.service.impl.DefaultEntityEventManager.process : Publishing event [CoreEvent [type: UPDATE, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=ced755e5-58cc-4d13-a490-09c42f35634c], properties: {idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@3f8cabb4}]]
Jan  4 09:03:01 vIDM01 czechidm[1270]: 2022-01-04 09:03:01.290  INFO 1648421498 --- [scheduling-1] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [core-long-running-task-save-processor]([core]) start for [CoreEvent [type: UPDATE, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=ced755e5-58cc-4d13-a490-09c42f35634c], properties:{idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@3f8cabb4}]] with order [0].
Jan  4 09:03:01 vIDM01 czechidm[1270]: 2022-01-04 09:03:01.292  INFO 1648421500 --- [scheduling-1] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [core-long-running-task-save-processor]([core]) end for [CoreEvent [type: UPDATE, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=ced755e5-58cc-4d13-a490-09c42f35634c], properties: {idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@3f8cabb4}]] with order [0].

Jan  4 09:03:01 vIDM01 czechidm[1270]: 2022-01-04 09:03:01.411 ERROR 1648421619 --- [http-nio-8080-exec-4] o.s.transaction.support.TransactionSynchronizationUtils.invokeAfterCompletion : Tran
sactionSynchronization.afterCompletion threw exception
Jan  4 09:03:01 vIDM01 czechidm[1270]: eu.bcvsolutions.idm.core.api.exception.AcceptedException: Automatic role is processed in concurent task [6d4ff27b-4dfd-424f-ac02-75fc44f91f5b], wait for
 task is complete.
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.scheduler.task.impl.RemoveAutomaticRoleTaskExecutor.validate(RemoveAutomaticRoleTaskExecutor.java:129)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.scheduler.task.impl.RemoveAutomaticRoleTaskExecutor$$FastClassBySpringCGLIB$$f2852db5.invoke(<generated>)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:687)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.scheduler.task.impl.RemoveAutomaticRoleTaskExecutor$$EnhancerBySpringCGLIB$$6f0e68ff.validate(<generated>)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.scheduler.service.impl.DefaultLongRunningTaskManager.getValidTask(DefaultLongRunningTaskManager.java:727)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.scheduler.service.impl.DefaultLongRunningTaskManager.executeInternal(DefaultLongRunningTaskManager.java:359)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.scheduler.service.impl.DefaultLongRunningTaskManager$$FastClassBySpringCGLIB$$3b41f3cc.invoke(<generated>)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:752)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:295)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:691)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.scheduler.service.impl.DefaultLongRunningTaskManager$$EnhancerBySpringCGLIB$$ad69c1a4.executeInternal(<generated>)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at jdk.internal.reflect.GeneratedMethodAccessor2123.invoke(Unknown Source)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at java.base/java.lang.reflect.Method.invoke(Method.java:566)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.context.event.ApplicationListenerMethodAdapter.doInvoke(ApplicationListenerMethodAdapter.java:261)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.context.event.ApplicationListenerMethodAdapter.processEvent(ApplicationListenerMethodAdapter.java:179)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.transaction.event.ApplicationListenerMethodTransactionalAdapter$TransactionSynchronizationEventAdapter.processEvent(Applicati
onListenerMethodTransactionalAdapter.java:128)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.transaction.event.ApplicationListenerMethodTransactionalAdapter$TransactionSynchronizationEventAdapter.afterCompletion(Applic
ationListenerMethodTransactionalAdapter.java:117)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.transaction.support.TransactionSynchronizationUtils.invokeAfterCompletion(TransactionSynchronizationUtils.java:171)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.transaction.support.AbstractPlatformTransactionManager.invokeAfterCompletion(AbstractPlatformTransactionManager.java:992)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.transaction.support.AbstractPlatformTransactionManager.triggerAfterCompletion(AbstractPlatformTransactionManager.java:967)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:788)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:714)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:535)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:305)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:691)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.model.service.impl.DefaultIdmAutomaticRoleRequestService$$EnhancerBySpringCGLIB$$710a62a.startRequestNewTransactional(<g
enerated>)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.model.service.impl.DefaultIdmAutomaticRoleRequestService.startRequest(DefaultIdmAutomaticRoleRequestService.java:149)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.model.service.impl.DefaultIdmAutomaticRoleRequestService.startRequest(DefaultIdmAutomaticRoleRequestService.java:84)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.model.service.impl.DefaultIdmAutomaticRoleRequestService$$FastClassBySpringCGLIB$$7a1bc78e.invoke(<generated>)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:752)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:295)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:691)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.model.service.impl.DefaultIdmAutomaticRoleRequestService$$EnhancerBySpringCGLIB$$710a62a.startRequest(<generated>)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.model.service.impl.DefaultIdmAutomaticRoleRequestService.deleteAutomaticRole(DefaultIdmAutomaticRoleRequestService.java:437)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.model.service.impl.DefaultIdmAutomaticRoleRequestService$$FastClassBySpringCGLIB$$7a1bc78e.invoke(<generated>)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:687)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.model.service.impl.DefaultIdmAutomaticRoleRequestService$$EnhancerBySpringCGLIB$$710a62a.deleteAutomaticRole(<generated>)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.rest.impl.IdmRoleTreeNodeController.delete(IdmRoleTreeNodeController.java:216)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.rest.impl.IdmRoleTreeNodeController$$FastClassBySpringCGLIB$$5b4ce8e8.invoke(<generated>)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:752)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.access.intercept.aopalliance.MethodSecurityInterceptor.invoke(MethodSecurityInterceptor.java:69)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:691)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.rest.impl.IdmRoleTreeNodeController$$EnhancerBySpringCGLIB$$c1f4088d.delete(<generated>)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at jdk.internal.reflect.GeneratedMethodAccessor5703.invoke(Unknown Source)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at java.base/java.lang.reflect.Method.invoke(Method.java:566)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:190)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:105)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:892)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:797)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1040)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.servlet.FrameworkServlet.doDelete(FrameworkServlet.java:931)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at javax.servlet.http.HttpServlet.service(HttpServlet.java:764)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:113)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.security.auth.filter.ExtendExpirationFilter.doFilter(ExtendExpirationFilter.java:67)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.security.api.auth.filter.AuthenticationFilter.doFilter(AuthenticationFilter.java:92)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:320)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:127)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:91)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:119)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:137)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:111)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:170)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.security.auth.filter.ExtendExpirationFilter.doFilter(ExtendExpirationFilter.java:67)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.security.api.auth.filter.AuthenticationFilter.doFilter(AuthenticationFilter.java:92)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:113)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:116)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:74)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:215)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:178)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:358)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:271)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:94)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.boot.web.servlet.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:128)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.boot.web.servlet.support.ErrorPageFilter.access$000(ErrorPageFilter.java:66)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.boot.web.servlet.support.ErrorPageFilter$1.doFilterInternal(ErrorPageFilter.java:103)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.boot.web.servlet.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:121)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.security.auth.filter.StartUserTransactionFilter.doFilterInternal(StartUserTransactionFilter.java:39)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.filter.CorsFilter.doFilterInternal(CorsFilter.java:97)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:540)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:382)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:895)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1722)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at java.base/java.lang.Thread.run(Thread.java:829)
Jan  4 09:03:01 vIDM01 czechidm[1270]: 2022-01-04 09:03:01.424  INFO 1648421632 --- [event-task-executor-1] e.b.i.c.m.service.impl.DefaultIdmConceptRoleRequestService.addToLog : 2022-01-04T09:03:01.424558+01:00[Europe/Prague]: IdentityRole [9d68183f-8faa-459a-a4e9-719a70d06445] (reqested in concept [c849e745-f09b-4177-bfc3-a89879e36969]) was deleted (not from this role request)!
Jan  4 09:03:01 vIDM01 czechidm[1270]: 2022-01-04 09:03:01.429 ERROR 1648421637 --- [base-task-executor-2] e.b.i.c.s.api.service.AbstractLongRunningTaskExecutor.end : [core:AUTOMATIC_ROLE_TASK_RUNNING:a26f3575-feca-4acf-93f4-064114dd7043] Automatic role is processed in concurent task [6d4ff27b-4dfd-424f-ac02-75fc44f91f5b], wait for task is complete. ({taskId=6d4ff27b-4dfd-424f-ac02-75fc44f91f5b})
Jan  4 09:03:01 vIDM01 czechidm[1270]: eu.bcvsolutions.idm.core.api.exception.AcceptedException: Automatic role is processed in concurent task [6d4ff27b-4dfd-424f-ac02-75fc44f91f5b], wait for task is complete.
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.scheduler.task.impl.RemoveAutomaticRoleTaskExecutor.validate(RemoveAutomaticRoleTaskExecutor.java:129)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.scheduler.api.service.AbstractLongRunningTaskExecutor.start(AbstractLongRunningTaskExecutor.java:162)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.scheduler.task.impl.RemoveAutomaticRoleTaskExecutor.start(RemoveAutomaticRoleTaskExecutor.java:197)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.scheduler.api.service.AbstractLongRunningTaskExecutor.call(AbstractLongRunningTaskExecutor.java:263)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.scheduler.api.service.AbstractLongRunningTaskExecutor$$FastClassBySpringCGLIB$$f9eae371.invoke(<generated>)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:687)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.scheduler.task.impl.RemoveAutomaticRoleTaskExecutor$$EnhancerBySpringCGLIB$$6f0e68ff.call(<generated>)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at eu.bcvsolutions.idm.core.config.DelegatingTransactionContextRunnable.run(DelegatingTransactionContextRunnable.java:39)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at org.springframework.security.concurrent.DelegatingSecurityContextRunnable.run(DelegatingSecurityContextRunnable.java:84)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Jan  4 09:03:01 vIDM01 czechidm[1270]: #011at java.base/java.lang.Thread.run(Thread.java:829)

Jan  4 09:03:01 vIDM01 czechidm[1270]: 2022-01-04 09:03:01.432  INFO 1648421640 --- [base-task-executor-2] e.b.idm.core.model.service.impl.DefaultEntityEventManager.process : Publishing event [CoreEvent [type: UPDATE, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=ced755e5-58cc-4d13-a490-09c42f35634c], properties: {idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@4672b5d9}]]
Jan  4 09:03:01 vIDM01 czechidm[1270]: 2022-01-04 09:03:01.456  INFO 1648421664 --- [base-task-executor-2] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [core-long-running-task-save-processor]([core]) start for [CoreEvent [type: UPDATE, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=ced755e5-58cc-4d13-a490-09c42f35634c], properties:{idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@4672b5d9}]] with order [0].
Jan  4 09:03:01 vIDM01 czechidm[1270]: 2022-01-04 09:03:01.460  INFO 1648421668 --- [base-task-executor-2] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [core-long-running-task-save-processor]([core]) end for [CoreEvent [type: UPDATE, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=ced755e5-58cc-4d13-a490-09c42f35634c], properties:{idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@4672b5d9}]] with order [0].
Jan  4 09:03:01 vIDM01 czechidm[1270]: 2022-01-04 09:03:01.468  INFO 1648421676 --- [base-task-executor-2] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [long-running-task-end-processor]([core]) start for [LongRunningTaskEvent [type: END, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=ced755e5-58cc-4d13-a490-09c42f35634c], properties: {}]] with order [0].
Jan  4 09:03:01 vIDM01 czechidm[1270]: 2022-01-04 09:03:01.475  INFO 1648421683 --- [base-task-executor-2] e.b.idm.core.model.service.impl.DefaultEntityEventManager.process : Publishing event [CoreEvent [type: UPDATE, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=ced755e5-58cc-4d13-a490-09c42f35634c], properties: {idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@1542a78c}]]
Jan  4 09:03:01 vIDM01 czechidm[1270]: 2022-01-04 09:03:01.481  INFO 1648421689 --- [base-task-executor-2] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [core-long-running-task-save-processor]([core]) start for [CoreEvent [type: UPDATE, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=ced755e5-58cc-4d13-a490-09c42f35634c], properties: {idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@1542a78c}]] with order [0].
Jan  4 09:03:01 vIDM01 czechidm[1270]: 2022-01-04 09:03:01.484  INFO 1648421692 --- [base-task-executor-2] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [core-long-running-task-save-processor]([core]) end for [CoreEvent [type: UPDATE, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=ced755e5-58cc-4d13-a490-09c42f35634c], properties: {idm:permission=[Leu.bcvsolutions.idm.core.security.api.domain.BasePermission;@1542a78c}]] with order [0].
Jan  4 09:03:01 vIDM01 czechidm[1270]: 2022-01-04 09:03:01.493  INFO 1648421701 --- [base-task-executor-2] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [long-running-task-end-processor]([core]) end for [LongRunningTaskEvent [type: END, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=ced755e5-58cc-4d13-a490-09c42f35634c], properties: {}]] with order [0].
Jan  4 09:03:01 vIDM01 czechidm[1270]: 2022-01-04 09:03:01.493  INFO 1648421701 --- [base-task-executor-2] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [long-running-task-execute-dependent-processor]([core]) start for [LongRunningTaskEvent [type: END, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=ced755e5-58cc-4d13-a490-09c42f35634c], properties: {}]] with order [100].
Jan  4 09:03:01 vIDM01 czechidm[1270]: 2022-01-04 09:03:01.498  INFO 1648421706 --- [base-task-executor-2] e.b.idm.core.api.event.AbstractEntityEventProcessor.onApplicationEvent : Processor [long-running-task-execute-dependent-processor]([core]) end for [LongRunningTaskEvent [type: END, content: eu.bcvsolutions.idm.core.scheduler.api.dto.IdmLongRunningTaskDto [id=ced755e5-58cc-4d13-a490-09c42f35634c], properties: {}]] with order [100].

I tried to simulate it locally by removing 3 automatic roles at the same time, but no problems occurred. Probably it can happen only for a lot of data.


Files

removeautomaticrole_tasks.png (174 KB) removeautomaticrole_tasks.png Alena Peterová, 01/05/2022 10:44 AM
Actions #1

Updated by Alena Peterová about 2 years ago

  • Description updated (diff)
Actions #2

Updated by Alena Peterová about 2 years ago

  • Description updated (diff)

Added note about automatic role requests.

Actions #3

Updated by Peter Štrunc about 2 years ago

  • Target version set to 12.2.0
Actions #4

Updated by Alena Peterová about 2 years ago

Reported also by our customer:
- admin wanted to remove multiple automatic roles by some tree node
- some of the roles were removed, some weren't
- the list of processed tasks contains multiple tasks RemoveAutomaticRoleTaskExecutor in the state Warning

Actions #5

Updated by Roman Kučera almost 2 years ago

  • Target version changed from 12.2.0 to 13.0.0
Actions #6

Updated by Alena Peterová over 1 year ago

  • Priority changed from Normal to High

This happens repeatedly to our customer who has to work with many roles.
I was able to simulate it locally quite easily - 1 role which assigns one (virtual system), tree structure with 4 identities in total. 6 automatic roles on the tree node with recursion removed at the same time -> 2 ended as Warning/Waiting and weren't removed.

Note: I tried to increase scheduler.task.executor.corePoolSize but it didn't have any effect on the outcome.

Actions #8

Updated by Tomáš Doischer over 1 year ago

  • Status changed from New to In Progress
  • Assignee changed from Peter Štrunc to Tomáš Doischer
Actions #9

Updated by Tomáš Doischer over 1 year ago

When following the same scenario, I had a different (but not better) result: 3 out of 7 automatic roles were not removed, and the tasks were in the created state.

Actions #10

Updated by Tomáš Doischer over 1 year ago

  • % Done changed from 0 to 70

The tasks were created because in the dev profile, scheduler.task.queue.process is set to one hour for some reason. I changed it to scheduler.task.queue.process=1000 and got the same result as Alena.

The issue is that we do not have a way of deciding whether we can process two automatic roles at the same time. Since this is potentially dangerous, we block this behavior by throwing an AcceptedException. This works fine - the tasks are set as created and then rerun again. During one of the future runs, however, the situation repeats itself and the AcceptedException is caught elsewhere because a generic Exception is being caught. This leads to a strange situation where the accepted exception leads to the task failing.

I added further check for the exception type and if the exception is accepted, I set the task to created. Everything then works as it's supposed to.

PR: https://github.com/bcvsolutions/CzechIdMng/pull/275

I'll need to check the test results and see if this change leads to some issues.

Actions #11

Updated by Tomáš Doischer over 1 year ago

  • Status changed from In Progress to Needs feedback
  • % Done changed from 70 to 80

The tests look fine (some fails are from develop).

@kucerar, can you please give me feedback?

Actions #12

Updated by Roman Kučera over 1 year ago

  • Status changed from Needs feedback to Resolved
  • % Done changed from 80 to 100

LGTM, merged, thx

Actions #13

Updated by Tomáš Doischer about 1 year ago

  • Status changed from Resolved to Closed
Actions

Also available in: Atom PDF