"Run Exclusive" does not stop future tasks

dev support
1

I think there is a bug with the “Run Exclusive” option of scheduled tasks.
I have a scheduled task that is set to run every 90 seconds.
I would expect that if an instance of this task takes longer than 90 seconds to complete - then the “Run Exclusive” checkbox SHOULD stop the “next” iteration from running.

This is not the case.

Our scheduled task processes data in a table - where the status is set to “Pending”.
For every Pending row, it sends an email, then sets the status to “Sent”.
Thus the next iteration of the scheduled task - does not send another email, to a previously “seen” row.

TEST 1:
I create a CSV with 3 rows of data to import and run the scheduled task.

The following is a log output of a task that completes in a about 8 seconds.
Note: the second run starts 90 seconds after the first, confirming there are no new rows to process.
(And I confirm that I received 3 emails from this process)

"INFO","http-nio-8080-exec-8","04/17/2023","22:39:55","surveyEngine","Requesting to send for ALL surveys."
"INFO","http-nio-8080-exec-8","04/17/2023","22:39:55","surveyEngine","3 survey recipient(s) will be emailed"
"INFO","http-nio-8080-exec-8","04/17/2023","22:39:55","surveyEngine","S ID: 1382 - SR ID: 279172 - GavinFirst_1 GavinLast_1 gavin.baumanis@centracx.com"
"INFO","http-nio-8080-exec-8","04/17/2023","22:39:58","surveyEngine","thisHTMLBody - done"
"INFO","http-nio-8080-exec-8","04/17/2023","22:39:58","surveyEngine","thisPlainBody - done"
"INFO","http-nio-8080-exec-8","04/17/2023","22:39:58","surveyEngine","mailer.send() - done"
"INFO","http-nio-8080-exec-8","04/17/2023","22:39:58","surveyEngine","Email sent! debug=3170:27:4"
"INFO","http-nio-8080-exec-8","04/17/2023","22:39:58","surveyEngine","S ID: 1382 - SR ID: 279173 - GavinFirst_2 GavinLast_2 gavin.baumanis@centracx.com"
"INFO","http-nio-8080-exec-8","04/17/2023","22:40:00","surveyEngine","thisHTMLBody - done"
"INFO","http-nio-8080-exec-8","04/17/2023","22:40:00","surveyEngine","thisPlainBody - done"
"INFO","http-nio-8080-exec-8","04/17/2023","22:40:00","surveyEngine","mailer.send() - done"
"INFO","http-nio-8080-exec-8","04/17/2023","22:40:00","surveyEngine","Email sent! debug=2729:8:1"
"INFO","http-nio-8080-exec-8","04/17/2023","22:40:01","surveyEngine","S ID: 1382 - SR ID: 279174 - GavinFirst_3 GavinLast_3 gavin.baumanis@centracx.com"
"INFO","http-nio-8080-exec-8","04/17/2023","22:40:03","surveyEngine","thisHTMLBody - done"
"INFO","http-nio-8080-exec-8","04/17/2023","22:40:03","surveyEngine","thisPlainBody - done"
"INFO","http-nio-8080-exec-8","04/17/2023","22:40:03","surveyEngine","mailer.send() - done"
"INFO","http-nio-8080-exec-8","04/17/2023","22:40:03","surveyEngine","Email sent! debug=2794:2:1"
"INFO","http-nio-8080-exec-8","04/17/2023","22:40:03","surveyEngine","Run completed (runAgain=false)."
"INFO","http-nio-8080-exec-7","04/17/2023","22:41:25","surveyEngine","Ready to run!"
"INFO","http-nio-8080-exec-7","04/17/2023","22:41:25","surveyEngine","Requesting to send for ALL surveys."
"INFO","http-nio-8080-exec-7","04/17/2023","22:41:25","surveyEngine","0 survey recipient(s) will be emailed"
"INFO","http-nio-8080-exec-7","04/17/2023","22:41:25","surveyEngine","No progress made!"
"INFO","http-nio-8080-exec-7","04/17/2023","22:41:25","surveyEngine","Run completed (runAgain=false)."

Test 2:
To prove the bug…
I have altered the CFM template used by the schedule task to include a 62 second sleep - in each iteration of the processing loop.

I have created a new CSV with 3 records.
3 x 62 = 186 seconds.
Thus the scheduled task will fire 2 EXTRA times while THIS iteration is running.

You can see by the log below the data is the same as the first CSV - but with a “0” appended to each cell.
(E.g. GavinFirst_1, becomes GavinFirst10)

From the log below - you can see the scheduled task does NOT honour the “Run Exclusive” checkbox and does indeed run the scheduled task 2 EXTRA times.

We noticed this issue today when a email recipient complained that we had sent them dozens of emails.

This instance (of the scheduled task) had ~800 rows to process and took nearly an hour to complete.
With a new schedule firing off, every 90 seconds, over the course of the initial request, taking 60 minutes - This resulted in the task actually rerunning over 40 (restarted) times.
A single row’s email address being emailed 40 times, not such a great look for us.

"INFO","http-nio-8080-exec-3","04/17/2023","22:56:25","surveyEngine","Ready to run!"
"INFO","http-nio-8080-exec-3","04/17/2023","22:56:25","surveyEngine","Requesting to send for ALL surveys."
"INFO","http-nio-8080-exec-3","04/17/2023","22:56:25","surveyEngine","3 survey recipient(s) will be emailed"
"INFO","http-nio-8080-exec-3","04/17/2023","22:56:25","surveyEngine","S ID: 1382 - SR ID: 279175 - GavinFirst_10 GavinLast_10 gavin.baumanis@centracx.com"
"INFO","http-nio-8080-exec-3","04/17/2023","22:56:27","surveyEngine","thisHTMLBody - done"
"INFO","http-nio-8080-exec-3","04/17/2023","22:56:27","surveyEngine","thisPlainBody - done"
"INFO","http-nio-8080-exec-3","04/17/2023","22:56:27","surveyEngine","mailer.send() - done"
"INFO","http-nio-8080-exec-3","04/17/2023","22:56:27","surveyEngine","Email sent! debug=2553:6:4"
"INFO","http-nio-8080-exec-3","04/17/2023","22:57:29","surveyEngine","S ID: 1382 - SR ID: 279176 - GavinFirst_20 GavinLast_20 gavin.baumanis@centracx.com"
"INFO","http-nio-8080-exec-3","04/17/2023","22:57:32","surveyEngine","thisHTMLBody - done"
"INFO","http-nio-8080-exec-3","04/17/2023","22:57:32","surveyEngine","thisPlainBody - done"
"INFO","http-nio-8080-exec-3","04/17/2023","22:57:32","surveyEngine","mailer.send() - done"
"INFO","http-nio-8080-exec-3","04/17/2023","22:57:32","surveyEngine","Email sent! debug=2563:2:1"
"INFO","http-nio-8080-exec-4","04/17/2023","22:57:55","surveyEngine","Ready to run!"
"INFO","http-nio-8080-exec-4","04/17/2023","22:57:55","surveyEngine","Requesting to send for ALL surveys."
"INFO","http-nio-8080-exec-4","04/17/2023","22:57:55","surveyEngine","2 survey recipient(s) will be emailed"
"INFO","http-nio-8080-exec-4","04/17/2023","22:57:55","surveyEngine","S ID: 1382 - SR ID: 279176 - GavinFirst_20 GavinLast_20 gavin.baumanis@centracx.com"
"INFO","http-nio-8080-exec-4","04/17/2023","22:57:57","surveyEngine","thisHTMLBody - done"
"INFO","http-nio-8080-exec-4","04/17/2023","22:57:57","surveyEngine","thisPlainBody - done"
"INFO","http-nio-8080-exec-4","04/17/2023","22:57:57","surveyEngine","mailer.send() - done"
"INFO","http-nio-8080-exec-4","04/17/2023","22:57:57","surveyEngine","Email sent! debug=2751:2:1"
"INFO","http-nio-8080-exec-3","04/17/2023","22:58:34","surveyEngine","S ID: 1382 - SR ID: 279177 - GavinFirst_30 GavinLast_30 gavin.baumanis@centracx.com"
"INFO","http-nio-8080-exec-3","04/17/2023","22:58:36","surveyEngine","thisHTMLBody - done"
"INFO","http-nio-8080-exec-3","04/17/2023","22:58:36","surveyEngine","thisPlainBody - done"
"INFO","http-nio-8080-exec-3","04/17/2023","22:58:36","surveyEngine","mailer.send() - done"
"INFO","http-nio-8080-exec-3","04/17/2023","22:58:36","surveyEngine","Email sent! debug=2460:2:0"
"INFO","http-nio-8080-exec-4","04/17/2023","22:58:59","surveyEngine","S ID: 1382 - SR ID: 279177 - GavinFirst_30 GavinLast_30 gavin.baumanis@centracx.com"
"INFO","http-nio-8080-exec-4","04/17/2023","22:59:02","surveyEngine","thisHTMLBody - done"
"INFO","http-nio-8080-exec-4","04/17/2023","22:59:02","surveyEngine","thisPlainBody - done"
"INFO","http-nio-8080-exec-4","04/17/2023","22:59:02","surveyEngine","mailer.send() - done"
"INFO","http-nio-8080-exec-4","04/17/2023","22:59:02","surveyEngine","Email sent! debug=2806:2:1"
"INFO","http-nio-8080-exec-2","04/17/2023","22:59:25","surveyEngine","Ready to run!"
"INFO","http-nio-8080-exec-2","04/17/2023","22:59:25","surveyEngine","Requesting to send for ALL surveys."
"INFO","http-nio-8080-exec-2","04/17/2023","22:59:25","surveyEngine","1 survey recipient(s) will be emailed"
"INFO","http-nio-8080-exec-2","04/17/2023","22:59:25","surveyEngine","S ID: 1382 - SR ID: 279177 - GavinFirst_30 GavinLast_30 gavin.baumanis@centracx.com"
"INFO","http-nio-8080-exec-2","04/17/2023","22:59:27","surveyEngine","thisHTMLBody - done"
"INFO","http-nio-8080-exec-2","04/17/2023","22:59:27","surveyEngine","thisPlainBody - done"
"INFO","http-nio-8080-exec-2","04/17/2023","22:59:27","surveyEngine","mailer.send() - done"
"INFO","http-nio-8080-exec-2","04/17/2023","22:59:27","surveyEngine","Email sent! debug=2665:2:1"
"INFO","http-nio-8080-exec-3","04/17/2023","22:59:38","surveyEngine","Run completed (runAgain=false)."
"INFO","http-nio-8080-exec-4","04/17/2023","23:00:04","surveyEngine","Run completed (runAgain=false)."
"INFO","http-nio-8080-exec-2","04/17/2023","23:00:29","surveyEngine","Run completed (runAgain=false)."

In the case of our second test CSV it means multiple emails being sent per row’s email address / per iteration.
1 for the first row
2 for the second row
3 for the third row of data
(I did indeed receive 6 emails instead of 3)

We haven’t noticed it previously because the files sent to us are hardly ever large like this and the processing nearly always complete within the 90 second interval of the Scheduled Task.

So I have no idea how long the Run Exclusive checkbox has not been working - or if it ever actually did.

Don’t forget to tell us about your stack!

OS: AWS Linux 2
Java Version: 11
Tomcat Version: 8.X
Lucee Version: 5.3.10.97

2

yikes, that’s frustrating

did you try increasing the log level for schedule.log in the web admin, that should provide a bit more insight into what lucee is doing under the hood. I’ll have a look into the code now

3

Anything in the schedule.log with extra detail?

I’d be using a cflock to enforce that too.

Also does your webserver support such long running connections? Sometimes the webserver will drop the connection while lucee keeps chugging, which the scheduler is unaware of

4

HI @Zackster ,
The scheduler.log in all contexts is empty - but for the header row.
Setting the level to debug - and restarting Lucee does not get anything added to the scheduler log, either.

The webserver timeout does not come into play - according to the (webserver) logs.

5

I haven’t really solved it - as such - but using a named lock does stop the repeats.
So I am moving along…

But it is still a bug : in that the run exclusive flag in the administrator is broken.
Shall I add it Jira?

6

Seems a red flag that you’re not seeing any logging from the scheduler?

Can u reproduce this in a fresh standalone instance?