cacheops fails at runtime on 4th version

[thakryptex]

Hello.
On cacheops 3.2.1 there is no runtime errors.
But after I upgrade to 4th version (I tried all four subversions), I get this error at runtime:

Unhandled exception in thread started by <_pydev_bundle.pydev_monkey._NewThreadStartupWithTrace object at 0x1114cb898>
Traceback (most recent call last):
  File "/Users/***/lib/python3.6/site-packages/funcy/calc.py", line 41, in wrapper
    return memory[key]
KeyError: (<class 'moderator.models.moderator.Moderator'>,)

During handling of the above exception, another exception occurred:


Traceback (most recent call last):
  File "/Applications/PyCharm.app/Contents/helpers/pydev/_pydev_bundle/pydev_monkey.py", line 589, in __call__
    return self.original_func(*self.args, **self.kwargs)
  ........
  File "/Users/***/lib/python3.6/site-packages/django/core/checks/urls.py", line 13, in check_url_config
    return check_resolver(resolver)
  File "/Users/***/lib/python3.6/site-packages/django/core/checks/urls.py", line 23, in check_resolver
    return check_method()
  ........
  File "/Users/***/lib/python3.6/site-packages/django/urls/resolvers.py", line 529, in urlconf_module
    return import_module(self.urlconf_name)
  File "/Users/***/lib/python3.6/importlib/__init__.py", line 126, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
  ........
  File "/Users/***/moderator/models/moderator.py", line 10, in <module>
    class Moderator(auth_models.AbstractBaseUser, auth_models.PermissionsMixin):
  File "/Users/***/lib/python3.6/site-packages/django/db/models/base.py", line 152, in __new__
    new_class.add_to_class(obj_name, obj)
  File "/Users/***/lib/python3.6/site-packages/django/db/models/base.py", line 315, in add_to_class
    value.contribute_to_class(cls, name)
  File "/Users/***/lib/python3.6/site-packages/cacheops/query.py", line 422, in contribute_to_class
    if cls.__module__ != '__fake__' and family_has_profile(cls):
  File "/Users/***/lib/python3.6/site-packages/funcy/calc.py", line 44, in wrapper
    value = memory[key] = func(*args, **kwargs)
  File "/Users/***/lib/python3.6/site-packages/cacheops/utils.py", line 38, in family_has_profile
    return any(model_profile, model_family(cls))
  File "/Users/***/lib/python3.6/site-packages/cacheops/utils.py", line 33, in model_family
    return class_tree(model._meta.concrete_model)
  File "/Users/***/lib/python3.6/site-packages/cacheops/utils.py", line 29, in class_tree
    return [cls] + lmapcat(class_tree, cls.__subclasses__())

AttributeError: 'NoneType' object has no attribute '__subclasses__'

Settings are very easy:

CACHEOPS_ENABLED = True
CACHEOPS_DEGRADE_ON_FAILURE = True
CACHEOPS_REDIS = CACHES['default']['LOCATION']
CACHEOPS_DEFAULTS = {
    'timeout': 60 * 60,
    'db_agnostic': False
}
CACHEOPS = {
    '*.*': {'ops': 'all'},  # only manual caching
}

Have no idea what's wrong here.
Anybody knows?

[Suor]

Should be fixed now.

BTW, CACHEOPS_ENABLED = False disables cacheops entirely, including QuerySet.cache(), @cached_as(), template, simple, file caches and any invalidation. To enable cache and not enable any automatic (implicit) caching set 'ops' to empty set or list or tuple, which is default:

CACHEOPS = {
    '*.*': {},  # only manual caching
}

Manual caching, which will be enabled after this, includes:

• Queryset.cache()
• @cached_as() and @cached_view_as()
• template fragment caching
• simple and file cache (both decorators and .set() calls)

Another thing is that if you only cache queries to some models you should avoid using '*.*'. Writing this you force cacheops to bind handlers to all models pre_save, post_save, post_delete and m2m_changed signals, and while signal handlers are fast this prevents certain Django optimizations, like fast path mass delete.

[thakryptex]

@Suor, so, you'll publish new version soon?

About setting CACHEOPS_ENABLED - yeah, I know, I just forgot to change it to True while pasting here after some experiments.

Actually, I found another thing. When I add any settings to CACHEOPS (for example, '*.*': {}), I get error while sending requests to Django: TypeError: _clone() got an unexpected keyword argument '_cacheprofile'.
Found nothing in Google, idk.

[Suor]

What Django version you have?

[thakryptex]

@Suor, oh, yeah, forgot to mention.
Django 2.0.1

[Suor]

Have no idea about clone thing. Do you have a stack trace?

[thakryptex]

@Suor,

Traceback (most recent call last):
  File "/Users/***/lib/python3.6/site-packages/django/core/handlers/exception.py", line 35, in inner
    response = get_response(request)
  File "/Users/***/lib/python3.6/site-packages/django/utils/deprecation.py", line 93, in __call__
    response = self.process_request(request)

  File "/Users/***/backend/middleware/token.py", line 60, in process_request
    request.jwt_token = get_valid_token_model(request)
  File "/Users/***/backend/middleware/token.py", line 25, in get_valid_token_model
    request._cached_token = JWTToken.objects.get_valid_token(jwt_token_value, get_related_user=get_related_user)
  File "/Users/***/backend/managers/jwt.py", line 17, in get_valid_token
    **({'user_id': user_id} if user_id else {})

  File "/Users/***/lib/python3.6/site-packages/django/db/models/query.py", line 836, in filter
    return self._filter_or_exclude(False, *args, **kwargs)
  File "/Users/***/lib/python3.6/site-packages/django/db/models/query.py", line 850, in _filter_or_exclude
    clone = self._chain()
  File "/Users/***/lib/python3.6/site-packages/django/db/models/query.py", line 1156, in _chain
    obj = self._clone()
  File "/Users/***/lib/python3.6/site-packages/cacheops/query.py", line 225, in _clone
    return self.clone(**kwargs)
  File "/Users/***/lib/python3.6/site-packages/cacheops/query.py", line 235, in clone
    clone = self._no_monkey._clone(self, **kwargs)

TypeError: _clone() got an unexpected keyword argument '_cacheprofile'

[thakryptex]

@Suor, great.
Latest commits fixed all described problems.
Thank you.

[thakryptex]

@Suor, sadly, I found new things.
Cacheops confilcts with my Celery. Don't know how is it possible, because they use different redis dbs.
My tests fails when cacheops enabled with error pop from empty list on the line _task_stack.pop() of celery's task.py file.
When I remove 'cacheops' line from INSTALLED_APPS (setting CACHEOPS_ENABLED to False doesn't work), then everything starts to work as it should be.

don't know if it's just my problem, but I just share this observation with you.

p.s. only manual caching was enabled.

[Suor]

Looks like, you have some weird setup there) I used cacheops with celery and it worked fine. And the bug with ._clone() it only applies to Django 1.8 code path, which I changed. Is it possible that you just have broken virtualenv or smth?

[thakryptex]

@Suor, we went deeper...
An we found a piece of code in cacheops that raise that pop from empty list (so, it's not celery problem as I thought first).
It located in class TransactionState(list): in transaction.py

def commit(self):
    context = self.pop()
    if self:
        # savepoint
        self[-1]['cbs'].extend(context['cbs'])
        self[-1]['dirty'] = self[-1]['dirty'] or context['dirty']
    else:
        # transaction
        for func, args, kwargs in context['cbs']:
            func(*args, **kwargs)

We tried this simple fix:

def commit(self):
    if len(self) > 0:
        context = self.pop()
        if self:
            # savepoint
            self[-1]['cbs'].extend(context['cbs'])
            self[-1]['dirty'] = self[-1]['dirty'] or context['dirty']
        else:
            # transaction
            for func, args, kwargs in context['cbs']:
                func(*args, **kwargs)

and it helps, all tests works after that.

So, you know better how the whole code works and if this fix is OK and won't be a reason for another bugs, then cool.

P.S. But strange thing that when I tried to commit, list was empty, so exception raised. That leads us to rollback function, where list was already NOT empty.

[thakryptex]

And as far as I understand, setting CACHEOPS_ENABLED doesn't fully turn off cacheops, but just turn off cache usage.
Am I right?

[Suor]

Are you changing CACHEOPS_ENABLED dynamically?

[thakryptex]

@Suor, I set this only in base settings file and don't check or change it anywhere else.

[thakryptex]

@Suor, and what do you think about that fix that checks if list is empty before trying to pop()?
Will you merge/commit this or something's wrong there?
(after this, my project work fine with cache)

[Suor]

This is not a fix. It's a hack that avoids exception with unknown side effects like leaving the system in undefined state.

[Suor]

CACHEOPS_ENABLED turns of both caching and invalidation but not transaction bookkeeping. If in some process you don't need cacheops at all you might try to just remove cacheops from INSTALLED_APPS for that one.

[thakryptex]

@Suor, well, maybe it's a hack... but function calls .pop() without checking if it's empty. so this transaction list have to be not empty every time when commit() function executing?
.
.
about CACHEOPS_ENABLED - yeah, I notice that and when these problems appeared, I had to remove cacheops from INSTALLED_APPS rather than just turn of cacheops..

[Suor]

As long as calls to TransactionState.begin() and .commit()/.rollback() are paired this shouldn't happen, if that is not the case then we should investigate under what circumstances does that happen and fix it. Fixing symptom is not a fix.

[Suor]

I can only think of one scenario for now how those calls might not be paired - if cacheops is installed and patches Atomic when some transaction is already in process. Hmm.

[thakryptex]

@Suor, ok, I'll try to describe:
In project I call Celery task (synchronously) that has two decorators:

@shared_task
@transaction.atomic

In this task I move objects of few tables to another DB (archive).
To avoid db constraints while copying to archive db, I set:

transaction.set_autocommit(False, using=archive_alias)

Then I just move and save everything.
In the end of the task I have this code:

transaction.commit(using=archive_alias)
transaction.set_autocommit(True, using=archive_alias)

So, on the last line that error appeared (pop from empty list) and the task crashed.

Hope this helps to understand what is the reason of this bug.

[Suor]

So you have unpaired transaction.commit() here. Why do you use low level API anyway why don't:

@shared_task
@transaction.atomic
@transaction.atomic(archive_alias)
def some_task(...):
    # ... do your thing

[Suor]

Also can you please post a full stack trace leading to pop from empty list.

[thakryptex]

@Suor, damn, you're right. Don't know why I went low level way.
Adding @transaction.atomic(archive_alias) solved this exception.

Anyway, here is the stack trace:

dictionary changed size during iteration

Traceback (most recent call last):
  File "/Users/***/venv/lib/python3.6/site-packages/raven/utils/serializer/manager.py", line 69, in transform
    return serializer.serialize(value, **kwargs)
  File "/Users/***/venv/lib/python3.6/site-packages/raven/utils/serializer/base.py", line 95, in serialize
    iteritems(value)))
  File "/Users/***/venv/lib/python3.6/site-packages/raven/utils/serializer/base.py", line 92, in <genexpr>
    (self.make_key(self.recurse(k, **kwargs)), self.recurse(v, **kwargs))
RuntimeError: dictionary changed size during iteration

Traceback (most recent call last):
  File "/Applications/PyCharm.app/Contents/helpers/pydev/pydevd.py", line 1668, in <module>
    main()
  File "/Applications/PyCharm.app/Contents/helpers/pydev/pydevd.py", line 1662, in main
    globals = debugger.run(setup['file'], None, None, is_module)
  File "/Applications/PyCharm.app/Contents/helpers/pydev/pydevd.py", line 1072, in run
    pydev_imports.execfile(file, globals, locals)  # execute the script
  File "/Applications/PyCharm.app/Contents/helpers/pydev/_pydev_imps/_pydev_execfile.py", line 18, in execfile
    exec(compile(contents+"\n", file, 'exec'), glob, loc)
  File "test.py", line 14, in <module>
    test()
  File "test.py", line 12, in test
    task_archive('b5340ea4-8849-43aa-8d6d-f42805206a06')
  File "/Users/***/venv/lib/python3.6/site-packages/celery/local.py", line 191, in __call__
    return self._get_current_object()(*a, **kw)
  File "/Users/***//venv/lib/python3.6/site-packages/celery/app/task.py", line 380, in __call__
    return self.run(*args, **kwargs)
  File "/usr/local/Cellar/python3/3.6.4/Frameworks/Python.framework/Versions/3.6/lib/python3.6/contextlib.py", line 52, in inner
    return func(*args, **kwds)
  File "/Users/***//backend/tasks/profile.py", line 13, in task_archive
    profile.archive_profile()
  File "/Users/***//backend/logic/profile.py", line 66, in archive_profile
    transaction.set_autocommit(True, using=archive_alias)
  File "/Users/***//venv/lib/python3.6/site-packages/django/db/transaction.py", line 30, in set_autocommit
    return get_connection(using).set_autocommit(autocommit)
  File "/Users/***//venv/lib/python3.6/site-packages/django/db/backends/base/base.py", line 409, in set_autocommit
    self.run_and_clear_commit_hooks()
  File "/Users/***//venv/lib/python3.6/site-packages/django/db/backends/base/base.py", line 636, in run_and_clear_commit_hooks
    func()
  File "/Users/***//venv/lib/python3.6/site-packages/cacheops/transaction.py", line 28, in commit
    context = self.pop()
IndexError: pop from empty list

[Suor]

Not sure what should I do here. Error out with unpaired commit error? Warn? Skip silently?

[Suor]

Closing for now

[thakryptex]

@Suor, not sure that I correctly understand your question.
If commit() called than it shouldn't be empty.
This thing doesn't happen if I use atomic decorator, so this means that cacheops can't deal with set_autocommit().
Possible ways: find how to fix this or notice in readme that low level transaction control can cause errors.

[Suor]

If you do it paired then it should work, the issue was caused by an unpaired commit.

[Suor]

Anyway those questions was not directed to you)