Defect #2207
closed
LRT: Warning about task already running is logged repetitively
100%
Description
I started LTR DeleteProvisioningArchiveTaskExecutor to delete multiple records.
Task was not finished before another scheduled run.
From new scheduled run the LTR is constantly trying to start again and fills the log with errors.
Tested on version 9.7.14
Updated by Petr Michal about 4 years ago
eu.bcvsolutions.idm.core.scheduler.api.exception.ConcurrentExecutionException: Task [acc-delete-provisioning-archive-long-running-task] is already running - can not be started twice.
at eu.bcvsolutions.idm.core.scheduler.api.service.AbstractLongRunningTaskExecutor.validate(AbstractLongRunningTaskExecutor.java:193)
at eu.bcvsolutions.idm.core.scheduler.service.impl.DefaultLongRunningTaskManager.execute(DefaultLongRunningTaskManager.java:197)
at eu.bcvsolutions.idm.core.scheduler.service.impl.DefaultLongRunningTaskManager.processCreated(DefaultLongRunningTaskManager.java:177)
at eu.bcvsolutions.idm.core.scheduler.service.impl.DefaultLongRunningTaskManager.lambda$processCreated$0(DefaultLongRunningTaskManager.java:141)
at java.util.ArrayList.forEach(ArrayList.java:1257)
at eu.bcvsolutions.idm.core.scheduler.service.impl.DefaultLongRunningTaskManager.processCreated(DefaultLongRunningTaskManager.java:137)
at eu.bcvsolutions.idm.core.scheduler.service.impl.DefaultLongRunningTaskManager.scheduleProcessCreated(DefaultLongRunningTaskManager.java:121)
at eu.bcvsolutions.idm.core.scheduler.service.impl.DefaultLongRunningTaskManager$$FastClassBySpringCGLIB$$3b41f3cc.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:720)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:655)
at eu.bcvsolutions.idm.core.scheduler.service.impl.DefaultLongRunningTaskManager$$EnhancerBySpringCGLIB$$c08678a7.scheduleProcessCreated(<generated>)
at sun.reflect.GeneratedMethodAccessor1413.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65)
at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor
Updated by Radek Tomiška about 4 years ago
- Related to Defect #2054: Scheduler: scheduled task is skipped added
Updated by Radek Tomiška about 4 years ago
- Related to deleted (Defect #2054: Scheduler: scheduled task is skipped)
Updated by Radek Tomiška about 4 years ago
- Status changed from New to Needs feedback
- Assignee changed from Radek Tomiška to Petr Michal
- Priority changed from Normal to Low
- Target version deleted (
Rhyolite (9.7.17))
When LRT is wrongly scheduled and the same task is already running, then this warning is logged, when task cannot be started.
I consulted this with team and we think this behavior is correct - you need to know, you task cannot be processed. When previous task ends, then newly scheduled task is correctly started.
As improvement, the log about the same task is already running, can be logged just once, is it ok?
On the other hand, I hope this logging impovement will not lead to ignore the wrong schedule at all (or some wrong system state, when a right schedule is configured, but tasks are not finished in time), because is a less aggresive.
As the other solution (or quick workaround), the log has warning (WARN) level and if you don't want to log it, configure:
# for CzechIdm >=10 in GUI
idm.sec.core.logger.eu.bcvsolutions.idm.core.scheduler.service.impl.DefaultLongRunningTaskManager=ERROR
# for LTS in logback-spring.xml for you profile
...
<logger name="eu.bcvsolutions.idm.core.scheduler.service.impl.DefaultLongRunningTaskManager" level="ERROR"/>
...
Please confirm the solution above, if improvement is needed.
Updated by Petr Michal almost 4 years ago
Radek Tomiška wrote:
As improvement, the log about the same task is already running, can be logged just once, is it ok?
This is definitely a good improvement for my case. I don't know if it was obvious, but idm was constantly logging, so log almost filled the disk in few hours.
As the other solution (or quick workaround), the log has warning (WARN) level and if you don't want to log it, configure:
This workaround is fine for me, thank you.
Updated by Radek Tomiška almost 4 years ago
- Status changed from Needs feedback to New
- Assignee changed from Petr Michal to Radek Tomiška
- Target version set to 10.4.0
Updated by Radek Tomiška almost 4 years ago
- Subject changed from Some LRT are constantly trying to start again to LRT: Warning about task already running is logged repetitively
- Status changed from New to In Progress
Updated by Radek Tomiška almost 4 years ago
- Status changed from In Progress to Needs feedback
- Assignee changed from Radek Tomiška to Vít Švanda
- % Done changed from 0 to 90
When starting scheduled task failed, then exception is logged once, commit:
https://github.com/bcvsolutions/CzechIdMng/commit/eee3a74eebbbb9a9e5ab7a1422bc86a87b81ed06
Could you provide me a feedback, please?
Updated by Vít Švanda almost 4 years ago
- Status changed from Needs feedback to Resolved
- Assignee changed from Vít Švanda to Radek Tomiška
- % Done changed from 90 to 100
I did reivew and tested it. Thanks for this feature.
Updated by Radek Tomiška almost 4 years ago
- Status changed from Resolved to Closed