Defect #3029
closedRemoving multiple automatic roles by tree node - some of the tasks fail (Warning or Waiting)
100%
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
Updated by Alena Peterová about 2 years ago
- Description updated (diff)
Added note about automatic role requests.
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
Updated by Roman Kučera almost 2 years ago
- Target version changed from 12.2.0 to 13.0.0
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.
Updated by Tomáš Doischer over 1 year ago
- Status changed from New to In Progress
- Assignee changed from Peter Štrunc to Tomáš Doischer
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.
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.
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?
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
Updated by Tomáš Doischer about 1 year ago
- Status changed from Resolved to Closed