Snapshots & scrubs scheduled tasks not working - double issue #1560

Closed
MFlyer opened this Issue Nov 30, 2016 · 6 comments

Projects

None yet

3 participants

@MFlyer
Member
MFlyer commented Nov 30, 2016 edited

Hi @schakrava ,
once again we have an issue on separate services like on #1556
Issue found by Mahmoud user forum on https://forum.rockstor.com/t/scheduled-snapshots-stopped-running/2434
He tried to get further info (once again thanks Mahmoud! 😃 ), but didn't get any useful log - not his fault, check this:

  • had a 1 minute snapshot task scheduled and had errors on every task
  • no logging on rockstor.log
  • had a check on mail and 🎉

Issue part 1 - no LOGGING

Message  1:
[omitted]
Subject: Cron <root@rockstone> /opt/build/bin/st-snapshot 6 \*-*-*-*-*-*
Content-Type: text/plain; charset=UTF-8
Auto-Submitted: auto-generated
Precedence: bulk
X-Cron-Env: <XDG_SESSION_ID=91>
X-Cron-Env: <XDG_RUNTIME_DIR=/run/user/0>
X-Cron-Env: <LANG=it_IT.UTF-8>
X-Cron-Env: <SHELL=/bin/bash>
X-Cron-Env: <PATH=/sbin:/bin:/usr/sbin:/usr/bin>
X-Cron-Env: <MAILTO=root>
[omitted]X-Cron-Env: <HOME=/root>
X-Cron-Env: <LOGNAME=root>
X-Cron-Env: <USER=root>
Date: Wed, 30 Nov 2016 23:33:01 +0100 (CET)
Status: RO

No handlers could be found for logger "scripts.scheduled_tasks.snapshot" <------ NO LOGGING!

Issue part 2, missing models again:

  • had all logger.something moved to logging.something to avoid no logger handlers error and checked a suspicion
    snapshot has always had same data_collector "bad habit" to use ORM and manually running ./st-snapshot 6 \*-*-*-*-*-* confirmed it
ERROR:root:Failed to create snapshot at shares/storage/snapshots/testsnap_201612010043
ERROR:root:Models aren't loaded yet.
Traceback (most recent call last):
  File "/opt/build/src/rockstor/scripts/scheduled_tasks/snapshot.py", line 103, in main
    if(delete(aw, share, stype, prefix, max_count)):
  File "/opt/build/src/rockstor/scripts/scheduled_tasks/snapshot.py", line 64, in delete
    name__startswith=prefix).order_by('-id')
  File "/opt/build/eggs/Django-1.8.16-py2.7.egg/django/db/models/manager.py", line 127, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/opt/build/eggs/Django-1.8.16-py2.7.egg/django/db/models/query.py", line 679, in filter
    return self._filter_or_exclude(False, *args, **kwargs)
  File "/opt/build/eggs/Django-1.8.16-py2.7.egg/django/db/models/query.py", line 697, in _filter_or_exclude
    clone.query.add_q(Q(*args, **kwargs))
  File "/opt/build/eggs/Django-1.8.16-py2.7.egg/django/db/models/sql/query.py", line 1310, in add_q
    clause, require_inner = self._add_q(where_part, self.used_aliases)
  File "/opt/build/eggs/Django-1.8.16-py2.7.egg/django/db/models/sql/query.py", line 1338, in _add_q
    allow_joins=allow_joins, split_subq=split_subq,
  File "/opt/build/eggs/Django-1.8.16-py2.7.egg/django/db/models/sql/query.py", line 1150, in build_filter
    lookups, parts, reffed_expression = self.solve_lookup_type(arg)
  File "/opt/build/eggs/Django-1.8.16-py2.7.egg/django/db/models/sql/query.py", line 1036, in solve_lookup_type
    _, field, _, lookup_parts = self.names_to_path(lookup_splitted, self.get_meta())
  File "/opt/build/eggs/Django-1.8.16-py2.7.egg/django/db/models/sql/query.py", line 1373, in names_to_path
    if field.is_relation and not field.related_model:
  File "/opt/build/eggs/Django-1.8.16-py2.7.egg/django/utils/functional.py", line 59, in __get__
    res = instance.__dict__[self.name] = self.func(instance)
  File "/opt/build/eggs/Django-1.8.16-py2.7.egg/django/db/models/fields/related.py", line 110, in related_model
    apps.check_models_ready()
  File "/opt/build/eggs/Django-1.8.16-py2.7.egg/django/apps/registry.py", line 131, in check_models_ready
    raise AppRegistryNotReady("Models aren't loaded yet.")
AppRegistryNotReady: Models aren't loaded yet.

I suppose scrubs tasks suffer same issues too /EDIT : replica too?? I don't know, never had it running

M.

@MFlyer
Member
MFlyer commented Dec 1, 2016 edited

Like on #1556 obviously

import django
django.setup()

loads django env and grants logging + ORM & snapshots working

ADD: Editing a scheduled task seems failing with an endless loading #1561 SOLVED
M.

@Mahmoud87

@MFlyer no worries at all mate, it will be so great if we can get separate logging for the snapshots but surely it's your call guys :).

@MFlyer
Member
MFlyer commented Dec 1, 2016

Hi @Mahmoud87 , nice idea having scheduled tasks logging it a separate file
M.

@MFlyer
Member
MFlyer commented Dec 1, 2016 edited

To @schakrava , having official Django documentation on standalone scripts we should have the import django way:
https://docs.djangoproject.com/en/dev/releases/1.7/#standalone-scripts
On Django 1.10 too
https://docs.djangoproject.com/en/1.10/topics/settings/#calling-django-setup-is-required-for-standalone-django-usage

Alternative (testing on /scripts/scheduled_tasks/snapshot.py):
import os
os.environ['DJANGO_SETTINGS_MODULE'] = 'settings'
from django.core.wsgi import get_wsgi_application <--- load wsgi
application = get_wsgi_application()

@schakrava
Member

Funny I noticed all your comments after I ran into this bug myself and figured out exactly that fix!

@schakrava schakrava added the bug label Dec 3, 2016
@schakrava schakrava added this to the Pinnacles milestone Dec 3, 2016
@schakrava schakrava self-assigned this Dec 3, 2016
@schakrava schakrava added a commit to schakrava/rockstor-core that referenced this issue Dec 4, 2016
@schakrava schakrava configure loggers to propagate. #1560 bca406f
@schakrava schakrava added a commit to schakrava/rockstor-core that referenced this issue Dec 4, 2016
@schakrava schakrava delete an extraneous file mistakenly checked in a while ago. #1560 112001d
@schakrava schakrava added a commit to schakrava/rockstor-core that referenced this issue Dec 4, 2016
@schakrava schakrava change allow_syncdb to allow_migrate as per django 1.9 deprecation wa…
…rning. #1560
e1832fb
@schakrava schakrava added a commit that closed this issue Dec 4, 2016
@schakrava schakrava djagon app registry setup refactor. Fixes #1560
We moved to django 1.8 recently from 1.6. As of 1.7, however, we have to
explicitly populate app registry. Since most scripts, if not all use the ORM,
do the django.setup in scripts.__init__.py
2038c04
@schakrava schakrava closed this in 2038c04 Dec 4, 2016
@schakrava
Member

Thanks a bunch @Mahmoud87, you certainly get the glory points for finding/reporting it first!

@schakrava schakrava changed the title from [Bug] Snapshots & scrubs scheduled tasks not working - double issue to Snapshots & scrubs scheduled tasks not working - double issue Dec 13, 2016
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment