Power-off-period cronjob runs right after the first power-on-period cronjob ended instead of runs right after celerybeat starts

[celery]

Power-off-period cronjob runs right after the first power-on-period cronjob ended instead of runs right after celerybeat starts

[cryptogun]

Maybe I find out the reason(Edit: No).
Now everything works well and celerybeat act as anacron(Edit: Today 12-11).

[2016-12-11 20:33:11,714: INFO/MainProcess] beat: Starting...
[2016-12-11 20:33:11,715: INFO/MainProcess] Writing entries...
[2016-12-11 20:33:11,827: INFO/MainProcess] Scheduler: Sending due task 3'disclose (homepage.tasks.disclose_today)

Why I need settings in myapp/celery.py? Because settings.CELERY_BROKER_URLleaks your rabbitmq password into traceback on every error page. So I need settings.RABBITMQ_PASSWD inside myapp/celery.py
I should git commit more in order to track changes.
Two more tests then I can close this issue.
Thank you for reading.

---

EDIT 12-13:
Now one task won't run right after another task. But cronjob won't run right after I start celerybeat. Anacron's gone. Sigh. Gotta use interval-based task instead.

[mheppner]

You need to initialize your settings in your celery.py file because Celery needs to initialize your Django project. This is standard for interacting with a Django project. Check out your manage.py script, it's doing this automatically. This step is included in the Celery docs as well.

I'm not sure what you're linking to about leaking the database password into error pages. You shouldn't be running your project in DEBUG mode in production.

If you want to use a database for the result backend, why not use django-celery-result instead? Your setting for CELERY_RESULT_BACKEND would just be django-db.

Can you clarify exactly what issue you're having? Is it just that an old task wasn't sent once you started up celerybeat?

[cryptogun]

@mheppner Thank you for the reply. Sorry that my English is poor :)

1. Yeah, there is (only) one important line in manage.py that is
   os.environ.setdefault("DJANGO_SETTINGS_MODULE", "mysite.settings"),
   for initialize the project as you explained. And I've done that long before this bug occur. I don't think that that's the cause.
   Here is my celery.py , not much differ from docs, which located the same as settings.py:

# in celery.py
# from __future__ import absolute_import
from celery import Celery
import os

os.environ.setdefault("DJANGO_SETTINGS_MODULE", "mysite.settings")
from django.conf import settings
RABBITMQ_USER = settings.RABBITMQ_USER
RABBITMQ_PASSWD = settings.RABBITMQ_PASSWD
del settings

app = Celery('mysite')
app.config_from_object('django.conf:settings', namespace='CELERY')
app.conf.update(
    broker_url='amqp://%s:%[email protected]/vhost'%(RABBITMQ_USER,
    RABBITMQ_PASSWD),# Hide password from error report page, settings section.
    result_expires=3*24*60*60,
)
app.autodiscover_tasks()
@app.task(bind=True)
def debug_task(self):
    print('Request: {0!r}'.format(self.request))

2. As for your 2nd paragraph. Yes, I know that I should set DEBUG=False in production. And my site is not prepared for production yet. But that's not enough. Let's say you made a typo in a view, and then refresh that page in browser, you'll find the following message under the Settings section in error page in browser:

NameError at /
Settings  Using settings module mysite.settings
Setting	                    Value
AUTH_PASSWORD_VALIDATORS  '********************'
CACHE_MIDDLEWARE_KEY_PREFIX  '********************'
CELERY_BROKER_URL  'amqp://mysite:[email protected]/mysite_vhost'
DATABASES   
{'default': {'ATOMIC_REQUESTS': False,
             'AUTOCOMMIT': True,
             'CONN_MAX_AGE': 0,
             'ENGINE': 'django.db.backends.postgresql_psycopg2',
             'HOST': '192.168.1.8',
             'NAME': 'dbname',
             'OPTIONS': {},
             'PASSWORD': '********************',
             'PORT': '',
             'TEST': {'CHARSET': None,
                      'COLLATION': None,
                      'MIRROR': None,
                      'NAME': None},
             'TIME_ZONE': None,
             'USER': 'dbuser'}}
EMAIL_HOST_PASSWORD  '********************'
EMAIL_SSL_KEYFILE  '********************'
PASSWORD_HASHERS  '********************'
RABBITMQ_PASSWD  '********************'
SECRET_KEY	  '********************'
SENDER_EMAIL_PASSWD  '********************'

All password in settings.py are default masked by Django in error page, except for those custom setting variables. And CELERY_BROKER_URL is printed out as plaintext.
I don't feel safe either. Like jnns said on StackOverflow. My solution is:

# celery.py
from django.conf import settings
RABBITMQ_USER = settings.RABBITMQ_USER
RABBITMQ_PASSWD = settings.RABBITMQ_PASSWD
del settings
app.config_from_object('django.conf:settings', namespace='CELERY')
app.conf.update(
    broker_url='amqp://%s:%[email protected]/mysite_vhost'%(RABBITMQ_USER,
    RABBITMQ_PASSWD),# Hide password from error report page, settings section.
)

Sorry, it's RABBITMQ_PASSWD that leaks into error page... And db password leaks too if set

# in settings.py
CELERY_RESULT_BACKEND = 'db+postgresql+psycopg2://%s:%s@localhost:5432/%s'%(
secret_ignore.DB_USER,secret_ignore.DB_PASSWD,secret_ignore.DB_NAME)

not

# in settings.py
CELERY_RESULT_BACKEND = 'django-db'

3. I mean RABBITMQ_PASSWD leaks. I confuse the two, just found that out. So no DB_PASSWD leaks.
   I've used django-celery-result and set CELERY_RESULT_BACKEND = django-db long before. I found this bug by checking the DJANGO_CELERY_RESULTS section on site-admin page. And the problem still occur.
4. Let me explain this bug by example:
   a. You've set two periodic tasks on admin page: home › Django_Celery_Beat › Periodic tasks

celery.prepare_breakfast_for_user: 0 3 * * * (m/h/d/dM/MY)
celery.prepare_lunch_for_user: 0 12 * * * (m/h/d/dM/MY)

b. 22:00 you shutdown your computer and go to sleep.
c. 00:00 a new day.
d. 03:00 celery.prepare_breakfast_for_user won't sent since computer is powered off.
e. 08:00 you wake up and turn on the computer.
f. 08:01 computer is on.
g. 08:01 Supervisor auto started.
h. 08:01 Supervisor spawn two daemoned threads: django-celery and django-celerybeat
i. 08:01 celerybeat starts and do nothing. No task is sent. No breakfast today. I need celery.prepare_breakfast_for_user to be sent as soon as I start my computer. What if, on production, the server is down unexpectedly at 03:00? Not good.
j. 12:00:00 now celerybeat sends celery.prepare_lunch_for_user
k. 12:00:00 and then sends celery.prepare_breakfast_for_user. WTF... That's too late, and is wired. Task prepare_breakfast_for_user will never be sent (before 03:00 tomorrow) if there is no other task like prepare_lunch_for_user.
Now my work around is to set an interval based task. Check Is breakfast prepared today? every 30min, if True: pass, else: do it.
This problem still exists. See log of yesterday:
Note: I add

import traceback
traceback.print_stack()
print(H)

before apply_entry() to print out the caller and task heap.

[2016-12-16 23:12:00,001: WARNING/MainProcess] File "/mysite/myenv/bin/celery", line 10, in <module>
    sys.exit(main())
[2016-12-16 23:12:00,002: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/__main__.py", line 14, in main
    _main()
[2016-12-16 23:12:00,002: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/bin/celery.py", line 326, in main
    cmd.execute_from_commandline(argv)
[2016-12-16 23:12:00,002: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/bin/celery.py", line 488, in execute_from_commandline
    super(CeleryCommand, self).execute_from_commandline(argv)))
[2016-12-16 23:12:00,002: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/bin/base.py", line 278, in execute_from_commandline
    return self.handle_argv(self.prog_name, argv[1:])
[2016-12-16 23:12:00,003: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/bin/celery.py", line 480, in handle_argv
    return self.execute(command, argv)
[2016-12-16 23:12:00,003: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/bin/celery.py", line 412, in execute
    ).run_from_argv(self.prog_name, argv[1:], command=argv[0])
[2016-12-16 23:12:00,003: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/bin/base.py", line 282, in run_from_argv
    sys.argv if argv is None else argv, command)
[2016-12-16 23:12:00,003: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/bin/base.py", line 365, in handle_argv
    return self(*args, **options)
[2016-12-16 23:12:00,004: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/bin/base.py", line 241, in __call__
    ret = self.run(*args, **kwargs)
[2016-12-16 23:12:00,004: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/bin/beat.py", line 107, in run
    return beat().run()
[2016-12-16 23:12:00,004: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/apps/beat.py", line 79, in run
    self.start_scheduler()
[2016-12-16 23:12:00,004: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/apps/beat.py", line 107, in start_scheduler
    service.start()
[2016-12-16 23:12:00,005: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/beat.py", line 541, in start
    interval = self.scheduler.tick()
[2016-12-16 23:12:00,005: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/beat.py", line 268, in tick
    traceback.print_stack()
[2016-12-16 23:12:00,005: WARNING/MainProcess] [
event_t(time=1481885999.225841, priority=5, 
entry=<ModelEntry: 3'disclose homepage.tasks.disclose_today(*[], **{}) <crontab: 0 3 * * * (m/h/d/dM/MY)>>), 

event_t(time=1481918399.989145, priority=5, 
entry=<ModelEntry: 12'greeting homepage.tasks.greeting(*['hello'], **{}) <crontab: 0 12 * * * (m/h/d/dM/MY)>>), 

event_t(time=1481887499.220681, priority=5, 
entry=<ModelEntry: test10 homepage.tasks.greeting(*['test10'], **{}) <crontab: 25 3 * * * (m/h/d/dM/MY)>>), 

event_t(time=1481921999.989126, priority=5, 
entry=<ModelEntry: debug_task mysite.celery.debug_task(*[], **{}) <crontab: 0 13 * * * (m/h/d/dM/MY)>>), 

event_t(time=1481952239.989012, priority=5, 
entry=<ModelEntry: I first mysite.celery.debug_task(*[], **{}) <crontab: 24 21 * * * (m/h/d/dM/MY)>>), 

event_t(time=1481889599.226639, priority=5, 
entry=<ModelEntry: celery.backend_cleanup celery.backend_cleanup(*[], **{}) <crontab: 0 4 * * * (m/h/d/dM/MY)>>), 

event_t(time=1481893439.220242, priority=5, 
entry=<ModelEntry: test11 homepage.tasks.greeting(*['test11'], **{}) <crontab: 4 5 * * * (m/h/d/dM/MY)>>)
]

[2016-12-16 23:12:00,007: INFO/MainProcess] Scheduler: Sending due task test2312 (homepage.tasks.greeting)
--------------------------------------------------------------

[2016-12-16 23:12:00,012: WARNING/MainProcess] File "/mysite/myenv/bin/celery", line 10, in <module>
    sys.exit(main())
[2016-12-16 23:12:00,012: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/__main__.py", line 14, in main
    _main()
[2016-12-16 23:12:00,012: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/bin/celery.py", line 326, in main
    cmd.execute_from_commandline(argv)
[2016-12-16 23:12:00,012: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/bin/celery.py", line 488, in execute_from_commandline
    super(CeleryCommand, self).execute_from_commandline(argv)))
[2016-12-16 23:12:00,012: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/bin/base.py", line 278, in execute_from_commandline
    return self.handle_argv(self.prog_name, argv[1:])
[2016-12-16 23:12:00,012: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/bin/celery.py", line 480, in handle_argv
    return self.execute(command, argv)
[2016-12-16 23:12:00,013: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/bin/celery.py", line 412, in execute
    ).run_from_argv(self.prog_name, argv[1:], command=argv[0])
[2016-12-16 23:12:00,013: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/bin/base.py", line 282, in run_from_argv
    sys.argv if argv is None else argv, command)
[2016-12-16 23:12:00,013: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/bin/base.py", line 365, in handle_argv
    return self(*args, **options)
[2016-12-16 23:12:00,013: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/bin/base.py", line 241, in __call__
    ret = self.run(*args, **kwargs)
[2016-12-16 23:12:00,013: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/bin/beat.py", line 107, in run
    return beat().run()
[2016-12-16 23:12:00,013: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/apps/beat.py", line 79, in run
    self.start_scheduler()
[2016-12-16 23:12:00,013: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/apps/beat.py", line 107, in start_scheduler
    service.start()
[2016-12-16 23:12:00,014: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/beat.py", line 541, in start
    interval = self.scheduler.tick()
[2016-12-16 23:12:00,014: WARNING/MainProcess] File "/mysite/myenv/lib/python3.5/site-packages/celery/beat.py", line 268, in tick
    traceback.print_stack()
[2016-12-16 23:12:00,014: WARNING/MainProcess] [
event_t(time=1481887499.220681, priority=5, 
entry=<ModelEntry: test10 homepage.tasks.greeting(*['test10'], **{}) <crontab: 25 3 * * * (m/h/d/dM/MY)>>), 
event_t(time=1481918399.989145, priority=5, 
entry=<ModelEntry: 12'greeting homepage.tasks.greeting(*['hello'], **{}) <crontab: 0 12 * * * (m/h/d/dM/MY)>>), 
event_t(time=1481889599.226639, priority=5, 
entry=<ModelEntry: celery.backend_cleanup celery.backend_cleanup(*[], **{}) <crontab: 0 4 * * * (m/h/d/dM/MY)>>), 
event_t(time=1481921999.989126, priority=5, 
entry=<ModelEntry: debug_task mysite.celery.debug_task(*[], **{}) <crontab: 0 13 * * * (m/h/d/dM/MY)>>), 
event_t(time=1481952239.989012, priority=5, 
entry=<ModelEntry: I first mysite.celery.debug_task(*[], **{}) <crontab: 24 21 * * * (m/h/d/dM/MY)>>), 
event_t(time=1481958719.989197, priority=5, 
entry=<ModelEntry: test2312 homepage.tasks.greeting(*['test2312'], **{}) <crontab: 12 23 * * * (m/h/d/dM/MY)>>), 
event_t(time=1481893439.220242, priority=5, 
entry=<ModelEntry: test11 homepage.tasks.greeting(*['test11'], **{}) <crontab: 4 5 * * * (m/h/d/dM/MY)>>)
]

[2016-12-16 23:12:00,016: INFO/MainProcess] Scheduler: Sending due task 3'disclose (homepage.tasks.disclose_today)
--------------------------------------------------------------

[mheppner]

1. I see what you’re doing now by updating the settings with the user. However…
2. It doesn’t matter if you think your app is production ready or not, setting DEBUG=False is crucial for exposing any Django app to the public. Your error pages are displaying all of your settings because that’s for development only. This is a feature, not a bug. You should be the only one viewing those error pages. Settings that contain things like API, KEY, PASS, etc will be masked for convince…you don’t leave the password to your email open on your laptop screen for others to see as they walk by, just like you wouldn’t want to leave your database password open on a page of your Django app on your laptop. To clarify, nothing is being "leaked." If you don't feel safe with this feature, then you should setting DEBUG=False.
3. No you weren't using django-celery-results long before, it's a new app that was released with Celery 4. You were using djcelery, the old app for Celery <= 3. And from what I remember, djcelery didn't properly showed results of tasks in the admin.
4. You could have summed this up by saying "a due task wasn’t sent" :) but it’s a bit more clear now. I suspect this is related to #7, since celerybeat seems to not grab a fresh copy of the scheduler. Try updating to celery==4.0.2 since Ask and the core devs made changes recently related to the scheduler.

[cryptogun]

Sorry for the late reply. I missed the notification from GitHub about new reply until I check my email.
2. Advice accepted.
3. I mean I use django-celery-results before this bug occur. I'm new to celery. Oh my English. Sorry.
4. a due task wasn’t sent is not correct. It will be sent tomorrow 03:00 if computer is not powered off. And sent after lunch if computer powered off 03:00 this morning. So my title is long and complicated.
I'll try latest celery and see if bug still exists.

[cryptogun]

Django_Celery_Results › Task results before installing latest celery.

2016-12-22 13:00   SUCCESS
2016-12-22 12:00   SUCCESS
2016-12-21 23:12   SUCCESS bug
2016-12-21 23:12   SUCCESS
2016-12-21 21:24   SUCCESS
2016-12-21 13:00   SUCCESS
2016-12-21 12:00   SUCCESS
2016-12-20 23:12   SUCCESS
2016-12-20 21:24   SUCCESS
2016-12-20 13:00   SUCCESS
2016-12-20 12:00   SUCCESS
2016-12-20 11:44   SUCCESS
2016-12-20 03:25   SUCCESS
2016-12-20 03:00   SUCCESS
2016-12-19 23:12   SUCCESS
2016-12-19 21:24   SUCCESS
2016-12-19 13:00   SUCCESS
2016-12-19 04:00   SUCCESS
2016-12-19 03:25   SUCCESS bug
2016-12-19 03:25   SUCCESS
2016-12-19 03:00   SUCCESS bug
2016-12-19 03:00   SUCCESS 
2016-12-18 23:12   SUCCESS bug
2016-12-18 23:12   SUCCESS
2016-12-18 21:24   SUCCESS
2016-12-18 13:00   SUCCESS
2016-12-18 12:00   SUCCESS
2016-12-17 23:12   SUCCESS bug
2016-12-17 23:12   SUCCESS
2016-12-17 21:24   SUCCESS
2016-12-17 14:45   SUCCESS
2016-12-17 13:00   SUCCESS
2016-12-17 12:00   SUCCESS
2016-12-16 23:12   SUCCESS bug
2016-12-16 23:12   SUCCESS
2016-12-16 21:24   SUCCESS
2016-12-16 13:00   SUCCESS
2016-12-16 12:00   SUCCESS

[mheppner]

Please try to reproduce this in a new, simplified code base using the latest version of Celery. It's difficult figuring out what you mean, since you've changed time zones and still haven't tested with the latest Celery. I'd also suggest posting this on the mailing list until you can narrow down the bug some more.