search

tejasjadhav / django-scheduler

Django app for scheduling tasks
GNU General Public License v3.0
6 stars 3 forks source link

Scheduler not firing #5

Closed ebadros closed 6 years ago

ebadros commented 6 years ago

I've got a celery worker running with RabbitMQ and have been able to test with celery-beat that the tasks will run using periodic tasks and intervals as well as crontabs. I don't want to use those because rrule is so much nicer.

The Task is being created as far as I can tell in the database.

task_id = TaskScheduler.schedule(say_hello, description="finally", rrule_string='RRULE:FREQ=HOURLY;INTERVAL=2')

And here's the task:

@shared_task(base=RepeatTask, name='say_hello')
def say_hello():
    print("sayingHello")

Any ideas why this might not be picking it up?

tejasjadhav commented 6 years ago

Thanks a lot @ebadros for reporting in your issue. Since this project is still in alpha stage, I wasn't expecting many people to use this.

Anyways, have you checked the following,

  1. RabbitMQ is running
  2. Celery worker is running
  3. Added scheduler in INSTALLED_APPS
  4. Added your app in INSTALLED_APPS

Can you provide the following details,

  1. What's your Django version?
  2. What's your Celery version?
  3. If you open the Django admin panel, can you see your tasks under Scheduler › Scheduled tasks?
  4. Can you run Celery worker in foreground with debug log level (ex. celery -A apple worker -l debug) and then check if you're getting any error?
tejasjadhav commented 6 years ago

I've added an example. You can have a look to ensure that your setup is fine.

ebadros commented 6 years ago

Hi Tejas,

Thank you very much for getting back to me. It's a very useful project as Periodic Task and Crontab are not very flexible.

I've answered you inline below.

On 6/9/18 9:08 AM, Tejas Jadhav wrote:

Thanks a lot @ebadros https://github.com/ebadros for reporting in your issue. Since this project is still in alpha stage, I wasn't expecting many people to use this.

Anyways, have you checked the following,

  1. RabbitMQ is running

Eric: Confirmed.

  1. Celery worker is running

Eric: Confirmed.

  1. Added |scheduler| in |INSTALLED_APPS|

|Eric: Confirmed.|

  1. Added your app in |INSTALLED_APPS|

|Eric: Confirmed.|

Can you provide the following details,

  1. What's your Django version?

Django==1.10.7

  1. What's your Celery version?

celery==4.1.0

  1. If you open the Django admin panel, can you see your tasks under /Scheduler › Scheduled tasks/?

Eric: Yes.

  1. Can you run Celery worker in foreground with |debug| log level (ex. |celery -A apple worker -l debug|) and then check if you're getting any error?

Eric: Not getting any error it doesn't seem.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/tejasjadhav/django-scheduler/issues/5#issuecomment-395980392, or mute the thread https://github.com/notifications/unsubscribe-auth/AKUgA2WiNywqaLkPxMCYrg7zz0fH5X0eks5t6_MGgaJpZM4UhGEV.

-- Eric Badros ebadros@gmail.com

ebadros commented 6 years ago

It looks like everything is the same. The scheduled task certainly exists in the database. Any reason it wouldn't fire?

On 6/9/18 10:00 AM, Tejas Jadhav wrote:

I've added an example https://github.com/tejasjadhav/django-scheduler/tree/master/examples/basic. You can have a look to ensure that your setup is fine.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/tejasjadhav/django-scheduler/issues/5#issuecomment-395984041, or mute the thread https://github.com/notifications/unsubscribe-auth/AKUgA4Ct-uqR6Fh1C4Mq_tLfEMTRWwFZks5t6_8ggaJpZM4UhGEV.

-- Eric Badros ebadros@gmail.com

ebadros commented 6 years ago

I feel I might be getting somewhere. While when I start the worker, kiterope.tasks.say_hello is listed, I'm getting this error in my log:

[2018-06-11 14:33:58,860: ERROR/MainProcess] Received unregistered task of type 'kiterope.tasks.say_hello'. The message has been ignored and discarded.

Did you remember to import the module containing this task? Or maybe you're using relative imports?

Please see http://docs.celeryq.org/en/latest/internals/protocol.html for more information.

The full contents of the message body was: '[[], {"first_eta": "2018-06-11 21:33:58+0000", "scheduled_task_id": "0482632a-925d-460e-ba74-ba599fba9109", "until": null, "rrule_string": "RRULE:FREQ=SECONDLY;INTERVAL=2", "eta": "2018-06-11 21:33:58+0000"}, {"errbacks": null, "callbacks": null, "chord": null, "chain": null}]' (277b) Traceback (most recent call last): File "/Users/eric/kr-env/lib/python3.4/site-packages/celery/worker/consumer/consumer.py", line 561, in on_taskreceived strategy = strategies[type] KeyError: 'kiterope.tasks.say_hello'

On 6/9/18 10:00 AM, Tejas Jadhav wrote:

I've added an example https://github.com/tejasjadhav/django-scheduler/tree/master/examples/basic. You can have a look to ensure that your setup is fine.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/tejasjadhav/django-scheduler/issues/5#issuecomment-395984041, or mute the thread https://github.com/notifications/unsubscribe-auth/AKUgA4Ct-uqR6Fh1C4Mq_tLfEMTRWwFZks5t6_8ggaJpZM4UhGEV.

-- Eric Badros ebadros@gmail.com

tejasjadhav commented 6 years ago

I had a similar issue before. It happened because I didn't specify the app in INSTALLED_APPS.

It seems that while registering all tasks from tasks.py, Celery is unable to find your task. So, during execution, it fails.

Are your other Celery tasks running fine? Can you show your celery.py file? You can take a look at the celery.py file in the example.

ebadros commented 6 years ago

Now I've got it completing the task the first time I create the Scheduled task, but then I get the same error (Received unregistered task of type 'kiterope.tasks.say_hello'. The message has been ignored and discarded.)

Here's my celery_setup.py file contents:

from __future__ import absolute_import, unicode_literals
import os
from celery import Celery
from django.conf import settings

#settings.configure()

os.environ.setdefault('DJANGO_SETTINGS_MODULE', 'kiterope.settings.settingsConfiguration')

app = Celery('kiterope')
app.config_from_object('kiterope.celeryconfigDev', namespace='CELERY')
app.autodiscover_tasks()

if __name__ == '__main__':
    app.start()

I've got a development and production server that's switched on the fly with the 'kiterope.settings.settingsConfiguration' file so right now, I'm just testing the development configuration.

I have gotten it firing with celery-beat using the PersistentScheduler which suggests it might not being Received for just django-scheduler, but I get this error:

[2018-06-13 23:34:00,003: INFO/MainProcess] Received task: kiterope.tasks.say_hello[04712904-fc2a-404f-ab75-ded69b236468]  
[2018-06-13 23:34:00,024: ERROR/ForkPoolWorker-7] Task kiterope.tasks.say_hello[04712904-fc2a-404f-ab75-ded69b236468] raised unexpected: KeyError('scheduled_task_id',)
Traceback (most recent call last):
  File "/Users/eric/kr-env/lib/python3.4/site-packages/celery/app/trace.py", line 382, in trace_task
    R = retval = fun(*args, **kwargs)
  File "/Users/eric/kr-env/lib/python3.4/site-packages/scheduler/tasks.py", line 29, in __call__
    scheduled_task_id = kwargs.pop('scheduled_task_id')
KeyError: 'scheduled_task_id'

Don't know if that is helpful, I think it's just a symptom of it not having been created through django-scheduler's system.

tejasjadhav commented 6 years ago

Thank you for the effort @ebadros. I still can't think of what might have gone wrong here.

From what I can understand the way Celery works, it scans all the tasks.py files, picks up functions with a @task decorator and registers them with a key or something. When you call a func.delay(), it gets the arguments and keyword-arguments passed to the func, encodes it (I guess it uses pickling) and puts it in RabbitMQ along with the key and the encoded arguments.

The worker on other side pulls a task from the queue at a time, gets the key, finds the func based on key (this is where you're getting KeyError: 'kiterope.tasks.say_hello'), unpickles the argument and passes it to the func. So, there might be something wrong with Celery not able to find your function.

If you want to run the task directly (using func.delay()),

  1. You need to have an entry in ScheduledTask model in your database. Get its ID. (/admin/scheduler/scheduledtask/, if you use the admin dashboard).
  2. You need to set its status as Created or Running.
  3. Execute the task as follows, 
    
from uuid import UUID
from kiterope.tasks import say_hello

uid = UUID('') say_hello.delay(scheduled_task_id=uid, rrule_string=None, first_eta=None, eta=None, until=None)


Make sure you have a Celery worker running.
ebadros commented 6 years ago

Thank you again for building this @tejasjadhav. I think we're getting closer. I've got it so it's being called with:

task_id = TaskScheduler.schedule(say_hello, description="finally", until=None, trigger_at=None,
                                     rrule_string='RRULE:FREQ=MINUTELY;INTERVAL=5')

This produces the below info from call to the task being called to the calculate_next_eta to the kwargs call at the end of the call function. 

[2018-06-14 22:29:19,837: INFO/MainProcess] Received task: kiterope.tasks.say_hello[13bfb381-6787-41fe-aa93-d8d4e0a1f604]  
[2018-06-14 22:29:19,947: WARNING/ForkPoolWorker-5] I've been called
[2018-06-14 22:29:19,948: WARNING/ForkPoolWorker-5] first_eta
[2018-06-14 22:29:19,948: WARNING/ForkPoolWorker-5] 2018-06-14 22:29:19+00:00
[2018-06-14 22:29:19,948: WARNING/ForkPoolWorker-5] eta
[2018-06-14 22:29:19,948: WARNING/ForkPoolWorker-5] 2018-06-14 22:29:19+00:00
[2018-06-14 22:29:19,948: WARNING/ForkPoolWorker-5] until
[2018-06-14 22:29:19,948: WARNING/ForkPoolWorker-5] scheduled_task
[2018-06-14 22:29:19,948: WARNING/ForkPoolWorker-5] say_hello
[2018-06-14 22:29:20,044: WARNING/ForkPoolWorker-5] say_hello is running
[2018-06-14 22:29:20,084: WARNING/ForkPoolWorker-5] the rrule
[2018-06-14 22:29:20,085: WARNING/ForkPoolWorker-5] DTSTART:20180614T222919
RRULE:FREQ=MINUTELY;INTERVAL=5
[2018-06-14 22:29:20,085: WARNING/ForkPoolWorker-5] the datetime
[2018-06-14 22:29:20,085: WARNING/ForkPoolWorker-5] 2018-06-14 22:29:19+00:00
[2018-06-14 22:29:20,085: WARNING/ForkPoolWorker-5] the rrule
[2018-06-14 22:29:20,085: WARNING/ForkPoolWorker-5] DTSTART:20180614T222919
RRULE:FREQ=MINUTELY;INTERVAL=5
[2018-06-14 22:29:20,085: WARNING/ForkPoolWorker-5] the datetime
[2018-06-14 22:29:20,085: WARNING/ForkPoolWorker-5] 2018-06-14 22:34:19+00:00
[2018-06-14 22:29:20,086: WARNING/ForkPoolWorker-5] next_eta from return of calculate_next_eta
[2018-06-14 22:29:20,086: WARNING/ForkPoolWorker-5] 2018-06-14 22:34:19+00:00
[2018-06-14 22:29:20,086: WARNING/ForkPoolWorker-5] kwargs
[2018-06-14 22:29:20,086: WARNING/ForkPoolWorker-5] {'until': None, 'first_eta': '2018-06-14 22:29:19+0000', 'rrule_string': 'RRULE:FREQ=MINUTELY;INTERVAL=5', 'scheduled_task_id': UUID('59d8162f-c9b2-483b-9790-ab0c9bf8a53b'), 'eta': '2018-06-14 22:34:19+0000'}
[2018-06-14 22:29:20,105: INFO/ForkPoolWorker-5] Task kiterope.tasks.say_hello[13bfb381-6787-41fe-aa93-d8d4e0a1f604] succeeded in 0.2658709500101395s: None

When I check the ScheduledTasks database, this scheduledTask has a status of Success. I don't know if it's being switched over before it's finished, but that might be a culprit. Let me know if you have any thoughts.

Eric

tejasjadhav commented 6 years ago

@ebadros I really appreciate that you're actively trying to identify the issue. Thank you so much! And special thanks for those logs.

The task runs even if the status is set as Success. It stops only if there's not next_eta or if the task status is set as Cancelled. Did the task execute after 5 minutes?

It's great to see that, in your case, next_eta is being set correctly. I executed your task on my local environment and it did execute every five minutes. Check this log,

[2018-06-15 15:19:30,001: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7f7560f17268> (args:('banana.tasks.say_hello', '27c18bce-c850-4957-9156-d422c73c3104', {'lang': 'py', 'task': 'banana.tasks.say_hello', 'id': '27c18bce-c850-4957-9156-d422c73c3104', 'eta': '2018-06-15T15:19:30+00:00', 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': '8e19afa1-cb96-4378-b11f-82e21086a0a0', 'parent_id': '8e19afa1-cb96-4378-b11f-82e21086a0a0', 'argsrepr': '()', 'kwargsrepr': "{'fruit': 'Apple', 'scheduled_task_id': UUID('ef632741-cafd-451f-956b-697bb6a9a3d6'), 'rrule_string': 'RRULE:FREQ=MINUTELY;INTERVAL=5', 'first_eta': '2018-06-15 15:14:30+0000', 'eta': '2018-06-15 15:19:30+0000', 'until': None}", 'origin': 'gen32382@tejas-arch', 'reply_to': '823f1f12-37bd-3d1e-a86b-6c96798b3c61', 'correlation_id': '27c18bce-c850-4957-9156-d422c73c3104', 'delivery_info': {'exchange': '', 'routing_key': 'celery', 'priority': 0, 'redelivered': False}}, '[[], {"fruit": "Apple", "scheduled_task_id": "ef632741-cafd-451f-956b-697bb6a9a3d6", "rrule_string": "RRULE:FREQ=MINUTELY;INTERVAL=5",... kwargs:{})
[2018-06-15 15:19:30,711: DEBUG/MainProcess] basic.qos: prefetch_count->16
[2018-06-15 15:19:30,713: DEBUG/MainProcess] Task accepted: banana.tasks.say_hello[27c18bce-c850-4957-9156-d422c73c3104] pid:32381
[2018-06-15 15:19:31,017: WARNING/ForkPoolWorker-1] Hello, I ate Apple today.
[2018-06-15 15:19:31,151: DEBUG/ForkPoolWorker-1] Start from server, version: 0.9, properties: {'capabilities': {'publisher_confirms': True, 'exchange_exchange_bindings': True, 'basic.nack': True, 'consumer_cancel_notify': True, 'connection.blocked': True, 'consumer_priorities': True, 'authentication_failure_close': True, 'per_consumer_qos': True, 'direct_reply_to': True}, 'cluster_name': 'rabbit@tejas-arch.localdomain', 'copyright': 'Copyright (C) 2007-2018 Pivotal Software, Inc.', 'information': 'Licensed under the MPL.  See http://www.rabbitmq.com/', 'platform': 'Erlang/OTP 20.3.2', 'product': 'RabbitMQ', 'version': '3.7.5'}, mechanisms: [b'PLAIN', b'AMQPLAIN'], locales: ['en_US']
[2018-06-15 15:19:31,152: DEBUG/ForkPoolWorker-1] using channel_id: 1
[2018-06-15 15:19:31,153: DEBUG/ForkPoolWorker-1] Channel open
[2018-06-15 15:19:31,155: INFO/ForkPoolWorker-1] Task banana.tasks.say_hello[27c18bce-c850-4957-9156-d422c73c3104] succeeded in 0.44159864699940954s: None
[2018-06-15 15:19:31,156: INFO/MainProcess] Received task: banana.tasks.say_hello[cf4f9474-b8d7-4c8f-9339-68528441e985]  ETA:[2018-06-15 15:24:30+00:00] 
[2018-06-15 15:19:31,156: DEBUG/MainProcess] basic.qos: prefetch_count->17
[2018-06-15 15:24:30,000: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7f7560f17268> (args:('banana.tasks.say_hello', 'cf4f9474-b8d7-4c8f-9339-68528441e985', {'lang': 'py', 'task': 'banana.tasks.say_hello', 'id': 'cf4f9474-b8d7-4c8f-9339-68528441e985', 'eta': '2018-06-15T15:24:30+00:00', 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': '8e19afa1-cb96-4378-b11f-82e21086a0a0', 'parent_id': '27c18bce-c850-4957-9156-d422c73c3104', 'argsrepr': '()', 'kwargsrepr': "{'fruit': 'Apple', 'scheduled_task_id': UUID('ef632741-cafd-451f-956b-697bb6a9a3d6'), 'rrule_string': 'RRULE:FREQ=MINUTELY;INTERVAL=5', 'first_eta': '2018-06-15 15:14:30+0000', 'eta': '2018-06-15 15:24:30+0000', 'until': None}", 'origin': 'gen32381@tejas-arch', 'reply_to': 'b4702297-22f7-38c1-93bb-ee004e79ded0', 'correlation_id': 'cf4f9474-b8d7-4c8f-9339-68528441e985', 'delivery_info': {'exchange': '', 'routing_key': 'celery', 'priority': 0, 'redelivered': False}}, '[[], {"fruit": "Apple", "scheduled_task_id": "ef632741-cafd-451f-956b-697bb6a9a3d6", "rrule_string": "RRULE:FREQ=MINUTELY;INTERVAL=5",... kwargs:{})
[2018-06-15 15:24:30,790: DEBUG/MainProcess] basic.qos: prefetch_count->16
[2018-06-15 15:24:30,792: DEBUG/MainProcess] Task accepted: banana.tasks.say_hello[cf4f9474-b8d7-4c8f-9339-68528441e985] pid:32382
[2018-06-15 15:24:31,108: WARNING/ForkPoolWorker-2] Hello, I ate Apple today.
[2018-06-15 15:24:31,222: INFO/ForkPoolWorker-2] Task banana.tasks.say_hello[cf4f9474-b8d7-4c8f-9339-68528441e985] succeeded in 0.4296802460012259s: None
[2018-06-15 15:24:31,223: INFO/MainProcess] Received task: banana.tasks.say_hello[e37e04ba-ae55-4c24-8f8a-47ca6be56398]  ETA:[2018-06-15 15:29:30+00:00] 
[2018-06-15 15:29:30,002: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7f7560f17268> (args:('banana.tasks.say_hello', 'e37e04ba-ae55-4c24-8f8a-47ca6be56398', {'lang': 'py', 'task': 'banana.tasks.say_hello', 'id': 'e37e04ba-ae55-4c24-8f8a-47ca6be56398', 'eta': '2018-06-15T15:29:30+00:00', 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': '8e19afa1-cb96-4378-b11f-82e21086a0a0', 'parent_id': 'cf4f9474-b8d7-4c8f-9339-68528441e985', 'argsrepr': '()', 'kwargsrepr': "{'fruit': 'Apple', 'scheduled_task_id': UUID('ef632741-cafd-451f-956b-697bb6a9a3d6'), 'rrule_string': 'RRULE:FREQ=MINUTELY;INTERVAL=5', 'first_eta': '2018-06-15 15:14:30+0000', 'eta': '2018-06-15 15:29:30+0000', 'until': None}", 'origin': 'gen32382@tejas-arch', 'reply_to': '823f1f12-37bd-3d1e-a86b-6c96798b3c61', 'correlation_id': 'e37e04ba-ae55-4c24-8f8a-47ca6be56398', 'delivery_info': {'exchange': '', 'routing_key': 'celery', 'priority': 0, 'redelivered': False}}, '[[], {"fruit": "Apple", "scheduled_task_id": "ef632741-cafd-451f-956b-697bb6a9a3d6", "rrule_string": "RRULE:FREQ=MINUTELY;INTERVAL=5",... kwargs:{})
[2018-06-15 15:29:30,262: DEBUG/MainProcess] basic.qos: prefetch_count->16
[2018-06-15 15:29:30,265: DEBUG/MainProcess] Task accepted: banana.tasks.say_hello[e37e04ba-ae55-4c24-8f8a-47ca6be56398] pid:32381
[2018-06-15 15:29:30,486: WARNING/ForkPoolWorker-1] Hello, I ate Apple today.
[2018-06-15 15:29:30,608: INFO/ForkPoolWorker-1] Task banana.tasks.say_hello[e37e04ba-ae55-4c24-8f8a-47ca6be56398] succeeded in 0.3436251679995621s: None
[2018-06-15 15:29:30,610: INFO/MainProcess] Received task: banana.tasks.say_hello[fc9acaa0-7026-45fa-86db-127f082b00e1]  ETA:[2018-06-15 15:34:30+00:00]

change scheduled task django site admin

Can you try again with interval as SECONDLY, just to reduce your testing time?

Also, how did you resolve KeyError issue?

ebadros commented 6 years ago

@tejasjadhav,

My computer had to be restarted and now is having no problems. Thank you for all your help and I'll let you know how my testing goes.

tejasjadhav commented 6 years ago

Thank you for your patience @ebadros. I'm closing this issue for now. If the problem happens again, feel free to create a new issue, or let me know and I'll re-open this issue.