Modify

Opened 3 years ago

Last modified 18 months ago

#8561 new defect

TracCron doesn't kill processes

Reported by: adam@… Owned by: t2y
Priority: normal Component: TracCronPlugin
Severity: major Keywords:
Cc: Trac Release: 0.12

Description

Have the TracCron running every 5 minutes, but it doesn't appear to kill the processes once the cron process runs, so an additional process is launching every 5 minutes and they're all trying to perform the action.

Attachments (3)

heartbeattask.JPG (50.5 KB) - added by tbressure 3 years ago.
Heart Beat Task for testing purpose
traccronlog.txt (23.0 KB) - added by anonymous 3 years ago.
traclogwithheartbeat.txt (229.7 KB) - added by anonymous 3 years ago.

Download all attachments as: .zip

Change History (25)

comment:1 Changed 3 years ago by anonymous

  • Owner changed from tbressure to anonymous
  • Status changed from new to assigned

Yes, this is a real defect.
I'll work on it.
Thank's for reporting this bug.

comment:2 Changed 3 years ago by tbressure

  • Owner changed from anonymous to tbressure
  • Status changed from assigned to new

comment:3 in reply to: ↑ description Changed 3 years ago by tbressure

  • Status changed from new to assigned

Replying to adam@terrerouge.ca:

Have the TracCron running every 5 minutes, but it doesn't appear to kill the processes once the cron process runs, so an additional process is launching every 5 minutes and they're all trying to perform the action.

I've look up at the code on core.py at line 257. As you can see the Ticker never spawn a new timer if it has not finished with all task (line 267). Then it compute and adjuste the delay to match the schedule.

What is the schedule you are using ? What sort of task are you doing ? if the task spawn a new thread, then TracCronPlugin is not aware of that fact, so it believe (line 264) that all task is finished. ARe you in this case ?

comment:4 Changed 3 years ago by anonymous

I'm using the hourly schedule, with the values as "0, 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55". The task checks an external system for records matching a certain criteria using a web services API, then inserts/updates the Trac DB with certain values.

I'm not using the thread modules, no.

comment:5 Changed 3 years ago by tbressure

@adam : do you think the task take more than 5 minutes to complete ?

If so, the Ticket.wake_up() method will take more than 5 minutes to return from self.callback() and, only after returning from the task execution, the Ticker will respawn a new Timer for next wake_up (not exactely next schedule). Even in this case i don't see how a task can execute while another is processing

How do you think the task is currently executed while another one is processing ? Do you have any error warning you that a concurrent access is done ?

I'm trying to understand how the bug you've reported can happend. Nevertheless, TracCronPlugin do not kill any existing task execution and this may be an enhancement i will done if current TracConPlugin can lead to overlapping task execution.

Thank's for your quick reply.

comment:6 Changed 3 years ago by adam

The task takes about a minute, maybe less. I don't have any error notifying me of concurrent access. Would running the callback at the end of my process help? At the moment I'm just relying on EOF to break the task called. I didn't notice any callback in the example, so wasn't sure.

The reason I think the task is executing multiple times is because the value of a specific custom field, which is appended with a new value when the task runs successfully, appends multiple times. I can allow for this in my code, but the multiple tasks running is still a significant resource strain.

comment:7 Changed 3 years ago by tbressure

@adam: for a running exemple you can take a look at task.py and there is no need to call callback and i will say you must not do so. You just have to implement wake_up() method

To know if the task is executing multiple time you can use administration panel under the Trac Cron entry on the left panel. There are 2 views. In Listener view (sub-entry) be sure you 've checked history_task_event. In History view you will see all task execution Trac Cron Plugin have done. Let'me know what you see.

What do you mean by EOF to break the called task. Do you kill the python process running Trac or your task is actually openning a shell to do is job ?

comment:8 Changed 3 years ago by anonymous

The Listener history_task_event is active, but no tasks are recorded.

I neither end the python process nor use a shell command. My db executions happen through the trac.db module and through the api module for the system i'm connecting to - by EOF I just meant that the end of the wake_up function.

comment:9 Changed 3 years ago by tbressure

@adam: thank you for this information.

If the history listener is empty that means either the history listener is bugy either the task you run never end.

Can you try the HeartBeatTask ? I've specially done heat for testing purpose: go to admministration page, then under Plugins, then under the group traccron.task you can activate HeartBeatTask.

Check if the listener record each theart beat execution.

If so that means that your task never end because the history listener record only complete execution (add the information only when the task has finished)

Let me kown the result Best regard.

Changed 3 years ago by tbressure

Heart Beat Task for testing purpose

comment:10 Changed 3 years ago by anonymous

Thanks - actually, I checked the history again and it is now showing my task as completed successfully, and it completes in the same minute it is called. It was showing one for every 5 minutes from 8h00 Eastern to 9 15 Eastern. I then refreshed the history page and all entries are gone (I did not press "Clear")

comment:11 Changed 3 years ago by tbressure

@adam: very good, the history show us that you task is running quite good and take less than 1 minute to complete. Be awaere that the history is only in-memory so every time you restart Trac or every time Trac reload its environment (trac.ini modification, or python file modification in dev mode), the history is lost.

With information you gave me I can say that your task is not concurrently run (for a given Trac instance).

Be sure you've only activate one schedule for your task (ex: hourly scheduler)

Are you sure there is only one Trac instance is accessing the "specific custom field" you mentionned ? Nobody around you are using the same database ?

For the moment killing the task do not make any sens because there is no concurrent task execution.

The purpose of TracCronPlugin is to run a task at the specified schedule you tell him. If you use hourly schedule with 0,5,10,15,...,55 you wan to run the task every five minute and that is it actually does. Do you agree ?

I wait for your feedback before putting this issue as invalid.

Best regard.

comment:12 Changed 3 years ago by anonymous

There is only one trac instance running, and nothing else is accessing the database.

The trac.log is showing the same logs from trac[core] at the same point in time, and the number of repeated instances of the trac[core] logs for an execution is the same as the number of times the data gets repeated in the database - this would definitely indicate concurrent tasks running, when none have been requested. Attached is an example of the traccron plugin, in a minute where no activity is required, so one would expect a single check, but instead i see 5 instances of it.

Changed 3 years ago by anonymous

comment:13 Changed 3 years ago by tbressure

@adam: thank you for the log. It definitly show that you had more than one Timer running.

Unfortunatly i don't know how this state have been raised the 15th february. Can you reproduce it now ?

Which version of TracCronPlugin are you using ? Can you tell me what is your version of python . What is you OS (where the bug occured) ?

I'am waiting for those informations.

Regards

comment:14 Changed 3 years ago by anonymous

I can reproduce it now, I just don't have a copy of the logs at the moment, can pass those along in an hour or two.

using r9398 (0.3), os is Linux. Python is 2.6

comment:15 Changed 3 years ago by tbressure

@adam: i need to determinate if this is an plateform specific issue (regarding thread management) or a task issue or a special case i did not see in TracCronPlugin (e.g a bug in TracCronPlugin)

Please can you enable the HearBeatTask and tell me if you still have multiple instance of the heartBeatTask ?

I dare reproducing this bug.

Best regard.

comment:16 Changed 3 years ago by anonymous

I'll check the logs, will know in a bit over an hour.

comment:17 Changed 3 years ago by anonymous

attached new log from 11:25 eastern today to 11:41 eastern today, is showing 2 instances of the scheduled tasks per minute instead of one.

Changed 3 years ago by anonymous

comment:18 Changed 3 years ago by tbressure

@adam: i've looked at the attachment log. HearBeatTask is checked twice so the issue is not task specific.

The Ticker is currently running more than on Timer object at the same time. It is like there are more than on instance of Core object. This is not reproducible on any environment i've got acces to:

  • Windows, python2.7
  • Linux, Python 2.6.6

I will made another release of TracCronPlugin with more debug trace of instanciation. You'll find this version next Monday.

comment:19 Changed 3 years ago by anonymous

@tbressure - Checked for change yesterday, release still seems to be the same. Should I download from another location?

comment:20 Changed 3 years ago by smcbutler

hi - is this plugin still being maintained?

comment:21 Changed 2 years ago by anonymous

Hi, any news about this bug?
I'm have created a mail reminder job and mails are sent mutiple times.

Thanks

comment:22 Changed 18 months ago by t2y

  • Owner changed from tbressure to t2y
  • Status changed from assigned to new

Add Comment

Modify Ticket

Action
as new .
Author


E-mail address and user name can be saved in the Preferences.

 
Note: See TracTickets for help on using tickets.