Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Yet another threading issue with m2m (v2.2.1) #131

Closed
pySilver opened this issue Jan 10, 2015 · 16 comments
Closed

Yet another threading issue with m2m (v2.2.1) #131

pySilver opened this issue Jan 10, 2015 · 16 comments

Comments

@pySilver
Copy link

Hello,

I'm experiencing a serious problems with m2m fields when cacheops is enabled. I belive the problem is somewhere in threading support because it does not appear with development server (and as a result tests passes but features gets broken on production).

See the code:

model (simplified):

class WebsiteCategory(models.Model):

    code = models.CharField(
        verbose_name=_(u'category'),
        max_length=80,
        choices=WEBSITE_CATEGORIES,
        unique=True,
    )

    class Meta:
        ordering = ['code']
        verbose_name = _(u"category")
        verbose_name_plural = _(u"categories")

    def __unicode__(self):
        return self.get_code_display()

class Website(VersionMixin):
    url = models.URLField(
        verbose_name=_(u"URL"),
        max_length=255)

    description = models.CharField(
        blank=True,
        default="",
        max_length=500)

    categories = models.ManyToManyField(
        'categories.WebsiteCategory',
        related_name='websites')

settings.py:

########## CACHEOPS CONFIGURATION
CACHEOPS_DEFAULTS = {
    'timeout': 60 * 60 * 24  # 24 hours
}

CACHEOPS = {
    # ... skipped unrelated apps

    # Categories
    'categories.websitecategory': {'ops': 'all'},

    # Websites
    'websites.website': {'ops': 'all'},

    ### THIRD PARTY APPS ###
    'auth.*': {'ops': 'all'},
    'sites.*': {'ops': 'all'},
    'authtoken.*': {'ops': 'all'},
    'notification.*': {'ops': 'all'},
    'oauth2.*': {'ops': 'all'},
}
########## END CACHEOPS CONFIGURATION

Here is how problem appears to the end user: User fills the website creation form by providing url, description and selecting few categories and hits "SAVE" button. Website is now in cache and in db.
User tries to update created object and there is a failure – he can update everything but not a categories m2m field.

So I've tried to do a couple of experiments.

I run ./manage.py shell_plus to get into console, loaded a Website object there and changed categories. Refreshed page on a website – categories were updated. NEXT PART IS STRANGE. Then I've immediately tried to update categories using website – categories field were updated on db lvl, but reading still returns old m2m set on a web interface (console returns fresh results). Subsequent attempts to update object using web interface does not hit db any more. At this point I've tried to invalite_obj, invalite_model from console, but web interface still output old categories set. I belive this has nothing to do with a browser cache, nor with UI.

I'm mostly positive it has something to do with threading support and has nothing do to with UI (In my case it's DRF API, so I've tried to update object using same serializer inside a console and it works fine, same as if I update an object directly without serializer layer).

Once I set CACHEOPS_FAKE to True all problems with m2m gone away. So it's for sure something related to cacheops.

@Suor can you please give any directions how may I find out the source of this problem? Thank you very much for your work!

@pySilver
Copy link
Author

quick update: this behaviour is only appears on production servers where django project is running under uwsgi. no problems appears when local dev server is used.

@pySilver
Copy link
Author

update 2: disabling cache for categories.websitecategory by removing it from CACHEOPS config also fixes issue. But that cannot be called a fix in fact ...

Problematic environment:
Production server runs with 1 uwsgi process with 10 threads.

@pySilver
Copy link
Author

update 3: switching from threads to processes did not make any difference to described problem. still curious why this issue does not happen on a local development server. (runserver) :(

@pySilver
Copy link
Author

@Suor can you please take a look at this?

@Suor
Copy link
Owner

Suor commented Jan 12, 2015

I will take a look tomorrow

@pySilver
Copy link
Author

@Suor thanks! I'm still digging into a problem and using oldschool "print" debugging I've found out that m2m_changed is not called while running inside uwsgi, but is called while workin with devserver.

which does not solve my problem, but well can help futher invetigation

@pySilver
Copy link
Author

@once
def install_cacheops():
    """
    Installs cacheops by numerous monkey patches
    """
    print "INSTALL CACHEOPS 1"

    monkey_mix(Manager, ManagerMixin)
    monkey_mix(QuerySet, QuerySetMixin)
    QuerySet._cacheprofile = QuerySetMixin._cacheprofile
    QuerySet._cloning = QuerySetMixin._cloning
    monkey_mix(ValuesQuerySet, QuerySetMixin, ['iterator'])
    monkey_mix(ValuesListQuerySet, QuerySetMixin, ['iterator'])
    monkey_mix(DateQuerySet, QuerySetMixin, ['iterator'])

    print "INSTALL CACHEOPS 2"

    # Install profile and signal handlers for any earlier created models
    from django.db.models import get_models
    for model in get_models(include_auto_created=True):
        model._default_manager._install_cacheops(model)

    print "INSTALL CACHEOPS 3"

    # Turn off caching in admin
    try:
        # Use app registry in Django 1.7
        from django.apps import apps
        admin_used = apps.is_installed('django.contrib.admin')
    except ImportError:
        # Introspect INSTALLED_APPS in older djangos
        from django.conf import settings
        admin_used = 'django.contrib.admin' in settings.INSTALLED_APPS

    print "INSTALL CACHEOPS 4"
    if admin_used:
        from django.contrib.admin.options import ModelAdmin

        # Renamed queryset to get_queryset in Django 1.6
        method_name = 'get_queryset' if hasattr(ModelAdmin, 'get_queryset') else 'queryset'

        @monkey(ModelAdmin, name=method_name)
        def get_queryset(self, request):
            return get_queryset.original(self, request).nocache()

    # Bind m2m changed handler
    print "INSTALL CACHEOPS 5"
    m2m_changed.connect(invalidate_m2m)

    # Make buffers/memoryviews pickleable to serialize binary field data
    if six.PY2:
        import copy_reg
        copy_reg.pickle(buffer, lambda b: (buffer, (bytes(b),)))
    if six.PY3:
        import copyreg
        copyreg.pickle(memoryview, lambda b: (memoryview, (bytes(b),)))

while running with uwsgi (1 process / 0 threads) I've noticed that code is not executing after this line
print "INSTALL CACHEOPS 2"

settings.INSTALLED_APPS while execution install_cacheops is the following:

('cacheops', 'django.contrib.auth', 'django.contrib.contenttypes', 'django.contrib.sites', 'django.contrib.staticfiles', 'provider', 'provider.oauth2', 'rest_framework', 'rest_framework.authtoken', 'rest_framework_swagger', 'corsheaders', 'south', 'constance', 'constance.backends.database', 'djcelery', 'djkombu', 'django_extensions', 'notification', 'passwords', 'sorl.thumbnail', 'storages', 'django_user_agents', 'modeltranslation', 'djrill', 'elasticutils', 'django_countries', 'rolepermissions', 'core', 'fileuploads', 'currency', 'notificator', 'dynsettings', 'categories', 'accounts', 'billing', 'websites', 'offers', 'coupons', 'conversions', 'dwh', 'reporter', 'invoices', 'products')

@pySilver
Copy link
Author

Still no luck :(

  1. install_cacheops at some point imports from django.db.models import get_models
  2. get_models itself while importing somehow calls django.db.models.loading.AppCache#_populate
  3. somehow install_cacheops stays at this points and does not proceed (no prints were stdouted)

so as a result – m2m_changed signal was not attached (and probably cacheops were not installed correctly) and all my problems were caused by this.

@pySilver
Copy link
Author

what is working:
import cacheops as soon as possible (in settings.py lets say)

@Suor
Copy link
Owner

Suor commented Jan 13, 2015

Since I don't have full failing project I can only guess. The best guess is you messed up with import path in uwsgi configuration, so some model can't load. And error is swallowed by Django. Exception is the only way installation procedure could be broken in between as you describe.

You was on the right track with your print debugging though. You can continue by checking for exceptions in failing code section. E.g. like:

# Add this before install_cacheops() procedure
import traceback
from contextlib import contextmanager

@contextmanager
def print_errors(label):
    try:
        yield
    except Exception as e:
        print('%s    raised in %s' % (traceback.format_exc(), label))
        raise

# Change a sections between 2 and 3 to
    with print_errors('import'):
        from django.db.models import get_models
    for model in get_models(include_auto_created=True):
        print('Loading models for', model)
        with print_errors('cacheops for %s' % model):
            model._default_manager._install_cacheops(model)

Run it and see what import causes failure. If this doesn't lead to solution then step into. Thanks open source, Django code is available :)

P.S. If this leads to nothing then please say what Django version you are using and your sys.path in uwsgi use case.

@pySilver
Copy link
Author

@Suor thx for update!

I've made a local modifitication for cacheops/query.py like this:

import traceback
from contextlib import contextmanager
@contextmanager
def print_errors(label):
    try:
        yield
    except Exception as e:
        print('%s raised in %s' % (traceback.format_exc(), label))
        raise

@once
def install_cacheops():
    """
    Installs cacheops by numerous monkey patches
    """
    monkey_mix(Manager, ManagerMixin)
    monkey_mix(QuerySet, QuerySetMixin)
    QuerySet._cacheprofile = QuerySetMixin._cacheprofile
    QuerySet._cloning = QuerySetMixin._cloning
    monkey_mix(ValuesQuerySet, QuerySetMixin, ['iterator'])
    monkey_mix(ValuesListQuerySet, QuerySetMixin, ['iterator'])
    monkey_mix(DateQuerySet, QuerySetMixin, ['iterator'])

    print "BEGIN INSTALL"
    # Change a sections between 2 and 3 to
    with print_errors('import'):
        from django.db.models import get_models
    for model in get_models(include_auto_created=True):
        print('Loading models for', model)
        with print_errors('cacheops for %s' % model):
            model._default_manager._install_cacheops(model)

    print "END INSTALL"
    # rest is ommite as not interesting and never reached

Restarted UWSGI, made a request to a service and here is the output:

➜  myproject-server git:(develop) ✗ uwsgi --ini /Users/Silver/Projects/myproject-server/var/uwsgi.ini
[uWSGI] getting INI configuration from /Users/Silver/Projects/myproject-server/var/uwsgi.ini
*** Starting uWSGI 2.0.9 (64bit) on [Tue Jan 13 17:35:34 2015] ***
compiled with version: 4.2.1 Compatible Apple LLVM 6.0 (clang-600.0.56) on 12 January 2015 11:52:44
os: Darwin-14.0.0 Darwin Kernel Version 14.0.0: Fri Sep 19 00:26:44 PDT 2014; root:xnu-2782.1.97~2/RELEASE_X86_64
nodename: MacBook-Pro.lan
machine: x86_64
clock source: unix
pcre jit disabled
detected number of CPU cores: 8
current working directory: /Users/Silver/Projects/myproject-server
writing pidfile to /Users/Silver/Projects/myproject-server/var/myproject-master.pid
detected binary path: /Users/Silver/.virtualenvs/myproject-server/bin/uwsgi
chdir() to /Users/Silver/Projects/myproject-server
your processes number limit is 709
your memory page size is 4096 bytes
 *** WARNING: you have enabled harakiri without post buffering. Slow upload could be rejected on post-unbuffered webservers ***
detected max file descriptor number: 2048
lock engine: OSX spinlocks
thunder lock: disabled (you can enable it with --thunder-lock)
uwsgi socket 0 bound to UNIX address /Users/Silver/Projects/myproject-server/var/uwsgi.sock fd 3
Python version: 2.7.9 (default, Dec 19 2014, 06:00:59)  [GCC 4.2.1 Compatible Apple LLVM 6.0 (clang-600.0.56)]
Set PythonHome to /Users/Silver/.virtualenvs/myproject-server
Python main interpreter initialized at 0x7fa58b40de70
python threads support enabled
your server socket listen backlog is limited to 100 connections
your mercy for graceful operations on workers is 60 seconds
mapped 207296 bytes (202 KB) for 4 cores
*** Operational MODE: threaded ***
added /Users/Silver/Projects/myproject-server/myproject/apps/ to pythonpath.
WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x7fa58b40de70 pid: 31994 (default app)
*** uWSGI is running in multiple interpreter mode ***
spawned uWSGI master process (pid: 31994)
spawned uWSGI worker 1 (pid: 31997, cores: 4)
*** Stats server enabled on /Users/Silver/Projects/myproject-server/var/uwsgi-stats.sock fd: 16 ***
Raven is not configured (logging is disabled). Please see the documentation for more information.
BEGIN INSTALL

So clearly END INSTALL was not reached. I've tried to put more prints inside get_models. I'm sure it was called by install_cacheops since I was using inspector there like this:

# inside django.db.models.loading.AppCache#get_models
import inspect
caller = inspect.stack()[1][3]
if caller == 'install_cacheops':
    print "OK, I've been called from install_cacheops"

get_models stops at line self._populate() which has interesting docs, which I'm not sure I understand correctly:

# django.db.models.loading.AppCache#_populate
def _populate(self):
        """
        Fill in all the cache information. This method is threadsafe, in the
        sense that every caller will see the same state upon return, and if the
        cache is already initialised, it does no work.
        """
        if self.loaded:
            return
        # Note that we want to use the import lock here - the app loading is
        # in many cases initiated implicitly by importing, and thus it is
        # possible to end up in deadlock when one thread initiates loading
        # without holding the importer lock and another thread then tries to
        # import something which also launches the app loading. For details of
        # this situation see #18251.
        imp.acquire_lock()
        try:
            if self.loaded:
                return
            for app_name in settings.INSTALLED_APPS:
                if app_name in self.handled:
                    continue
                self.load_app(app_name, True)
            if not self.nesting_level:
                for app_name in self.postponed:
                    self.load_app(app_name)
                self.loaded = True
        finally:
            imp.release_lock()

So I'm still nowhere (well fixed my issue with an early import in settings). Django ==1.6.8, sys.path (from print inside install_cacheops):

['/Users/Silver/Projects/myproject-server/myproject/apps/', '.', '', '/Users/Silver/.virtualenvs/myproject-server/lib/python27.zip', '/Users/Silver/.virtualenvs/myproject-server/lib/python2.7', '/Users/Silver/.virtualenvs/myproject-server/lib/python2.7/plat-darwin', '/Users/Silver/.virtualenvs/myproject-server/lib/python2.7/plat-mac', '/Users/Silver/.virtualenvs/myproject-server/lib/python2.7/plat-mac/lib-scriptpackages', '/Users/Silver/.virtualenvs/myproject-server/lib/python2.7/lib-tk', '/Users/Silver/.virtualenvs/myproject-server/lib/python2.7/lib-old', '/Users/Silver/.virtualenvs/myproject-server/lib/python2.7/lib-dynload', '/usr/local/Cellar/python/2.7.9/Frameworks/Python.framework/Versions/2.7/lib/python2.7', '/usr/local/Cellar/python/2.7.9/Frameworks/Python.framework/Versions/2.7/lib/python2.7/plat-darwin', '/usr/local/Cellar/python/2.7.9/Frameworks/Python.framework/Versions/2.7/lib/python2.7/lib-tk', '/usr/local/Cellar/python/2.7.9/Frameworks/Python.framework/Versions/2.7/lib/python2.7/plat-mac', '/usr/local/Cellar/python/2.7.9/Frameworks/Python.framework/Versions/2.7/lib/python2.7/plat-mac/lib-scriptpackages', '/Users/Silver/.virtualenvs/myproject-server/lib/python2.7/site-packages', '/Users/Silver/.virtualenvs/myproject-server/lib/python2.7/site-packages/newrelic-2.38.0.31', '/Users/Silver/Projects/myproject-server', '/Users/Silver/Projects/myproject-server/myproject', '/Users/Silver/Projects/myproject-server/myproject/apps', '/Users/Silver/Projects/myproject-server']

@pySilver
Copy link
Author

UPD: Tried to apply this with statement inside get_models and here are the results :)

Traceback (most recent call last):
  File "/Users/Silver/.virtualenvs/myproject-server/lib/python2.7/site-packages/django/db/models/loading.py", line 24, in print_errors
    yield
  File "/Users/Silver/.virtualenvs/myproject-server/lib/python2.7/site-packages/django/db/models/loading.py", line 246, in get_models
    self._populate()
  File "/Users/Silver/.virtualenvs/myproject-server/lib/python2.7/site-packages/django/db/models/loading.py", line 90, in _populate
    self.load_app(app_name)
  File "/Users/Silver/.virtualenvs/myproject-server/lib/python2.7/site-packages/django/db/models/loading.py", line 111, in load_app
    models = import_module('%s.models' % app_name)
  File "/Users/Silver/.virtualenvs/myproject-server/lib/python2.7/site-packages/django/utils/importlib.py", line 40, in import_module
    __import__(name)
  File "/Users/Silver/Projects/myproject-server/myproject/apps/billing/models.py", line 14, in <module>
    from .managers import TransactionManager, AggregationManager
  File "/Users/Silver/Projects/myproject-server/myproject/apps/billing/managers.py", line 12, in <module>
    from accounts.models import User
ImportError: cannot import name User
 raised in _populate

@Suor
Copy link
Owner

Suor commented Jan 13, 2015

So you got your error now. Investigate why you can't import User there.

@Suor
Copy link
Owner

Suor commented Jan 13, 2015

And check your sys.path with:

import sys
print sys.path

@pySilver
Copy link
Author

@Suor thats kinda strange. It always complains about importing custom user model (accounts.User in my case). If I move import statment in a problematic location into a function, it just starts complaining about from accounts.models import User in some other file (model or manager of another app). Looks like circular import problem, but in fact there is no references from accounts.models to other app's models so it's safe to import anything from accounts.models in other apps.

Interesting why there is no problems when:

  • CACHEOPS_FAKE = True (dev or production server)
  • no cacheops installed at all (dev or production server)
  • devserver
  • when I use import cacheops from my settings.py (dev or production server)

My assumption:

  • it has something to-do with custom user model
  • or install_cacheops starts before some inner django machinery bootstraps project

@pySilver
Copy link
Author

OK. Solved. For other people that might find this issue – read this article carefully: http://www.caktusgroup.com/blog/2013/08/07/migrating-custom-user-model-django/

  • If you are using custom user model – never import it directly in your models.py or files that are imported by your models.py
  • Try to use get_user_model() instead whenever possible, or make an import in desired function
  • User = get_user_model() on a module level won't work either.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants