Scheduled Tasks running several times within seconds - why?

Report · Feb 12, 2012

Hi

We have a number of scheduled tasks set to run overnight. After running once daily (as expected) for a couple of months, some of the tasks started running up to seven times daily, with the subsequent tasks usually running within 10 seconds of the previous one, often running within 1 second or within the second!

The server is CF 9.0.1 running on Win 2008 R2 (SP1) 64-bit.

Here is an example from the scheduler.log file:

"Information","jrpp-175","02/11/12","01:01:16","DELIUMCRON","Drop Temp Tables"

"Information","jrpp-174","02/11/12","01:01:16","DELIUMCRON","Drop Temp Tables"

"Information","jrpp-169","02/11/12","01:01:32","DELIUMCRON","Drop Temp Tables"

"Information","jrpp-175","02/11/12","01:01:47","DELIUMCRON","Drop Temp Tables"

"Information","jrpp-169","02/11/12","01:02:01","DELIUMCRON","Drop Temp Tables"

"Information","jrpp-175","02/11/12","01:02:15","DELIUMCRON","Drop Temp Tables"

"Information","jrpp-175","02/11/12","01:02:30","DELIUMCRON","Drop Temp Tables"

We created the tasks using cfschedule. An example is:

The URLs that get run do not recreate any tasks.

We can't understand why they would be running multiple times. Anyone have any ideas?

I am about to post another post here that may be related whereby a CF datasource stops being able to connect to the database and we get the error "Datasource [NameOfDatasource] could not be found". I don't know if these are related but they seemed to have started happening around the same time.

I didn't know whether this should be classed as a 'Question' or not, so ticked it just in case.

Nathan

Report · Feb 13, 2012

There may not be a mistake and ColdFusion might just have done what was asked of it. The trouble is likely with the dynamic variable, startTime. You have to investigate why 7 values of startTime were passed to the cfschedule tag on February 11, 2012.

Report · Feb 13, 2012

Thanks BKBK. The scheduled tasks are set up once to run daily at a set time. They are not set/created every day. A task only appears once in the CF Administrator listing and it has the correct time.

Here is the code for creating one of the tasks running multiple times.

TaskName = "CronTempTables";

TaskURL = "#ListLast(REQUEST.HTTPS, "|")#://#REQUEST.Domain#/~cron/cron_drop_temp_tables.cfm";

StartDate = DateFormat(now(), "YYYY/MM/DD");

StartTime = "01:00";

Interval = "Daily";

</cfscript>

So each task should only run once, but they are running multiple times.

Report · Feb 14, 2012

Threading issues between the 2 cfschedule tags perhaps? The schedule-delete tag seems to me to be redundant. What happens when you leave it out?

Report · Feb 14, 2012

Good point - I agree that the delete action is redundant but suspect it may have been added for a reason (this is quite old code - may have been an issue with CF6 or 7). Will remove it and see if it makes a difference.

I should point out that this application is running without this issue on other servers at different sites. Any suggestions on why it works on all but this one server?

Report · Feb 14, 2012

I should point out that this application is running without this issue on other servers at different sites. Any suggestions on why it works on all but this one server?

Presumably, there's something different about this server, or how you're running this application on this server. Maybe you're accidentally running your script multiple times?

Dave Watts, CTO, Fig Leaf Software

Dave Watts, Eidolon LLC

Report · Feb 14, 2012

Thanks for you response Dave.

ColdFusion is configured the same on this server as other servers running our application. The application is essentially the same as others with the exception of some different settings like support email address.

Something unexpected occurred overnight though. I reset the scheduled tasks to run at a different time (early evening) so that I could check that the problem datasource could still connect to the DB immediately after each task had run. The tasks ran at the expected time and only ran once each, plus the datasource could connect to DB after each task. Just what we were hoping for. However, the tasks also still ran multiple times overnight (early morning) just like they had previously. So even thought the tasks list in the CF Administrator only once and at the correct time (early evening), the tasks still ran multiple times in the early morning.

We turned on the Enable logging for scheduled tasks setting in the CF Admin and it logged the tasks running at the correct time but not the 'rogue' tasks. The \lib\neo-cron.xml only contains one instance of each tasks as does remote.servers.ListScheduledTasks(). Even so, I think there is something strange going on with CF that is causing these tasks to run at the wrong time multiple times. I don't know how nor why, but it's looking more likely we will have to do a fresh install of CF I am sure that there isn't some other code that is running these tasks in the early morning - the only reference to the templates in question is in the cfm file that creates the tasks and the times are hard coded (example code posted previously). It is also highly unlikely a user is running these tasks by putting the URL in the browser - someone would have to be doing this at 1am, 1.30am, 2am and 2.30 on the dot.

I know its unlikely, but anyone got any other ideas?

Thanks

Report · Feb 15, 2012

Yes, I've got another idea. It's all about one word which you, too, have just used: rogue. Rogue threads, that is.

It is clear that multiple requests are being initiated. The Application file might be involved. You should show us the scheduler log. What you posted earlier,

"Information","jrpp-175","02/11/12","01:01:16","DELIUMCRON","Drop Temp Tables"

"Information","jrpp-174","02/11/12","01:01:16","DELIUMCRON","Drop Temp Tables"

...

does not seem to me to be from the scheduler log. However, it gives us some information about JRun request threads generated by the web server.

The 2 threads jrpp-175 and jrpp-174 are logged in action at the same time. Moreover, jrpp-175 appears 4 times, within two minutes. This all seems to suggest that JRun is re-using pooled threads, and that the application is being constantly restarted -- !!??. So, what is the value of applicationTimeout and sessionTimeout?

In the meantime, here is a suggestion for a temporary fix. Place the following code in the file cron_drop_temp_tables.cfm:

In the task page, replace the 2 scheduler tags with this code:

</cfif>

Report · Feb 15, 2012

Thanks BKBK. I really appreciate the time and effort you're putting into this.

The applicationTimeout for these cron jobs is 20 mins as is the sessionTimeout. It uses a different application name compared with the rest of the application.

Regarding the thread re-use, these tasks generally finish within a minute, sometimes within seconds, so I'm not really surprised that the same thread is being reused for some subsequent calls.

The enable tasks page does not get rerun daily as it sets the tasks to run daily at a set time. It only gets run once when the application is installed and only subsequently if our configuration check (a manual process that is rarely run) finds that a task is not scheduled. I re-ran it after changing the times to set the tasks to run in the early evening, but it should not have been run other than when the application was installed for this client back in October.

Below is the latest from the scheduler log file for the relevant tasks. It includes the tasks run in the early evening and those running in the early morning which shouldn't be. The DELIUMCRON entries are cflogs from within the template being run for the task. We also wrapped each task in a named lock set to timeout after 1 second so that subsequent calls won't run if it is already running. The cflog is outside the lock so we know if it attempted to run or not. CronSessionStats (which doesn't seem to be a problem) run every hour on the half hour. I don't think there is any link or conflict between them, but looking at the log entries makes me wonder if we should change the tasks times so that CronSessionStats doesn't run at the same time as CronImportsCleanup.

"Information","scheduler-1","02/15/12","18:00:00",,"[CronTempTables] Executing at Wed Feb 15 18:00:00 NZDT 2012"

"Information","jrpp-199","02/15/12","18:01:20","DELIUMCRON","Drop Temp Tables"

"Information","scheduler-1","02/15/12","18:01:21",,"[CronTempTables] Rescheduling for :Thu Feb 16 18:00:00 NZDT 2012 Now: Wed Feb 15 18:01:21 NZDT 2012"

"Information","jrpp-203","02/15/12","18:29:59","DELIUMCRON","Session Tracking"

"Information","scheduler-0","02/15/12","18:30:00",,"[CronImportsCleanup] Executing at Wed Feb 15 18:30:00 NZDT 2012"

"Information","scheduler-1","02/15/12","18:30:00",,"[CronSessionStats] Executing at Wed Feb 15 18:30:00 NZDT 2012"

"Information","jrpp-204","02/15/12","18:30:00","DELIUMCRON","Session Tracking"

"Information","scheduler-1","02/15/12","18:30:00",,"[CronSessionStats] Rescheduling for :Wed Feb 15 19:30:00 NZDT 2012 Now: Wed Feb 15 18:30:00 NZDT 2012"

"Information","jrpp-203","02/15/12","18:30:00","DELIUMCRON","Import Cleanup"

"Information","scheduler-0","02/15/12","19:00:00",,"[CronEmailSubscriptions] Executing at Wed Feb 15 19:00:00 NZDT 2012"

"Information","jrpp-207","02/15/12","19:00:00","DELIUMCRON","Special Interest Email Subscriptions"

"Information","scheduler-0","02/15/12","19:01:27",,"[CronEmailSubscriptions] Rescheduling for :Thu Feb 16 19:00:00 NZDT 2012 Now: Wed Feb 15 19:01:27 NZDT 2012"

"Information","scheduler-3","02/15/12","19:30:00",,"[CronSessionStats] Executing at Wed Feb 15 19:30:00 NZDT 2012"

"Information","scheduler-1","02/15/12","19:30:00",,"[CronAuditHistoryTransfer] Executing at Wed Feb 15 19:30:00 NZDT 2012"

"Information","jrpp-209","02/15/12","19:30:00","DELIUMCRON","Audit History Transfer"

"Information","jrpp-212","02/15/12","19:30:00","DELIUMCRON","Session Tracking"

"Information","scheduler-3","02/15/12","19:30:00",,"[CronSessionStats] Rescheduling for :Wed Feb 15 20:30:00 NZDT 2012 Now: Wed Feb 15 19:30:00 NZDT 2012"

"Information","jrpp-213","02/15/12","19:30:00","DELIUMCRON","Session Tracking"

"Information","scheduler-1","02/15/12","19:31:16",,"[CronAuditHistoryTransfer] Rescheduling for :Thu Feb 16 19:30:00 NZDT 2012 Now: Wed Feb 15 19:31:16 NZDT 2012"

:

"Information","jrpp-246","02/16/12","01:00:01","DELIUMCRON","Drop Temp Tables"

"Information","jrpp-247","02/16/12","01:01:08","DELIUMCRON","Drop Temp Tables"

"Information","jrpp-247","02/16/12","01:01:17","DELIUMCRON","Drop Temp Tables"

"Information","jrpp-247","02/16/12","01:01:26","DELIUMCRON","Drop Temp Tables"

"Information","jrpp-246","02/16/12","01:01:35","DELIUMCRON","Drop Temp Tables"

"Information","jrpp-247","02/16/12","01:01:42","DELIUMCRON","Drop Temp Tables"

"Information","scheduler-2","02/16/12","01:30:00",,"[CronSessionStats] Executing at Thu Feb 16 01:30:00 NZDT 2012"

"Information","jrpp-250","02/16/12","01:30:00","DELIUMCRON","Session Tracking"

"Information","scheduler-2","02/16/12","01:30:00",,"[CronSessionStats] Rescheduling for :Thu Feb 16 02:30:00 NZDT 2012 Now: Thu Feb 16 01:30:00 NZDT 2012"

"Information","jrpp-251","02/16/12","01:30:01","DELIUMCRON","Import Cleanup"

"Information","jrpp-250","02/16/12","01:30:01","DELIUMCRON","Session Tracking"

"Information","jrpp-250","02/16/12","01:30:39","DELIUMCRON","Import Cleanup"

"Information","jrpp-250","02/16/12","01:30:50","DELIUMCRON","Import Cleanup"

"Information","jrpp-250","02/16/12","01:30:59","DELIUMCRON","Import Cleanup"

"Information","jrpp-250","02/16/12","01:31:08","DELIUMCRON","Import Cleanup"

"Information","jrpp-250","02/16/12","01:31:17","DELIUMCRON","Import Cleanup"

"Information","jrpp-254","02/16/12","02:00:01","DELIUMCRON","Special Interest Email Subscriptions"

"Information","jrpp-255","02/16/12","02:01:42","DELIUMCRON","Special Interest Email Subscriptions"

"Information","jrpp-255","02/16/12","02:02:07","DELIUMCRON","Special Interest Email Subscriptions"

"Information","jrpp-255","02/16/12","02:02:30","DELIUMCRON","Special Interest Email Subscriptions"

"Information","jrpp-255","02/16/12","02:02:55","DELIUMCRON","Special Interest Email Subscriptions"

"Information","jrpp-255","02/16/12","02:03:08","DELIUMCRON","Special Interest Email Subscriptions"

Report · Feb 17, 2012

N Drury wrote:
The applicationTimeout for these cron jobs is 20 mins as is the sessionTimeout.

In my opinion, an application timeout of 20 minutes can already cause problems. Your application is scheduled to run a task daily, yet you set the application to restart (if there is no activity) every 20 minutes. I would set the applicationTimeout to 1.5 or 2 days. That is,

applicationTimeout="#createTimeSpan(1,12,0,0)#"

or

applicationTimeout="#createTimeSpan(2,0,0,0)#"