Memcached backend: possible issue with cache keys

[jeff@…]

I'm using django trunk, revision 15284. There appears to be some issue with the memcache backend, as I'm able to set cache items, but not get them. It seems as though the problem may be that items are being set with the wrong cache key. Documentation of my issue is in this gist:

​https://gist.github.com/792466

[Jannis Leidel]

Trying to reproduce the problem, this is what I got:

>>> from django.core.cache import cache
>>> cache.clear()
>>> cache.get('testing_yo')
>>> cache.set('testing_yo', 'testing, yo!', 300)
>>> cache.key_prefix
'barstar_'
>>> # Using Django's cache framework's get method
>>> cache.get('testing_yo')
'testing, yo!'
>>> cache.get('%stesting_yo' % cache.key_prefix)
>>> 
>>> # Using the underlying memcached instance
>>> cache._cache.get('testing_yo')
>>> cache._cache.get('%stesting_yo' % cache.key_prefix)
>>> 

I know it sounds awful to ask, but can you validate that the memcache server is running? Also what Python and OS?

[anonymous]

I've just validated that this problem does NOT happen if I roll back to revision 13794 (right before this commit: ​http://code.djangoproject.com/ticket/13795).

Memcached definitely running. I can telnet to it with no problem. Python 2.6.2.

Thanks!

[Jeff Croft]

I've also verified that this problem only applies to the memcached backend -- locmem, for example, works fine.

[mmcnickle]

I cannot reproduce this either:

Python: 2.6.5
Django: SVN
python-memcached: 1.47
memcached: 1.4.2

>>> django.VERSION
(1, 3, 0, 'beta', 1)
>>> from django.core.cache import cache
>>> cache.clear()
>>> cache.get('testing_yo')
>>> cache.set('testing_yo', 'testing, yo!', 300)
>>> cache.key_prefix
'barstar_'
>>> cache.get('testing_yo')
'testing, yo!'

And the corresponding memcached -vv output:

<30 new auto-negotiating client connection
30: Client using the ascii protocol
<30 flush_all
>30 OK
<30 connection closed.
<30 new auto-negotiating client connection
30: Client using the ascii protocol
<30 get barstar_:1:testing_yo
>30 END
<30 connection closed.
<30 new auto-negotiating client connection
30: Client using the ascii protocol
<30 set barstar_:1:testing_yo 0 300 12
>30 STORED
<30 connection closed.
<30 new auto-negotiating client connection
30: Client using the ascii protocol
<30 get barstar_:1:testing_yo
>30 sending key barstar_:1:testing_yo
>30 END
<30 connection closed.

Can you give the version numbers for memcached and python-memcached too?

[Jeff Croft]

I'm on:

Django: SVN (Rev. 15284)
Python: 2.6.2
python-memcached: 1.4.7
memcached: 1.2.2

I noticed in writing this post that my memcached was pretty old, so I installed 1.4.5 just to see if it made a difference: it didn't. :(

Very strange. It's clearly something about my configuration, since others aren't experiencing, it, but it also changed with recent commmits to Django (it worked fine pre-13795). Thanks for looking it it, guys.

[Russell Keith-Magee]

Additional debug for caching problems

[Russell Keith-Magee]

@Jeff -- First theory -- this may be a problem that was resolved with r15285. Could you update your trunk checkout and see if the problem persists.

Failing that -- could you please apply the t15149-debug patch I've just uploaded, re-run your test case and show us the output. That patch will give a bit more debug info to shed some light on what is going on.

If you could also please provide your cache settings, and the logs produced by memcached -vv while you run the tests, that would be helpful.

[jeff@…]

Thanks for your help, Russell. Updating my trunk didn't help. So I applied the path you provided, and got these results:

>>> from django.core.cache import cache
>>> cache.clear()
>>> cache.get('testing_yo')
get base key = testing_yo
get base version = None
get key = lendle_:1:testing_yo
get val = None
>>> cache.set('testing_yo', 'testing, yo!', 300)
>>> cache.key_prefix
'lendle_'
>>> 
>>> # Using Django's cache framework's get method - THIS IS THE REAL ISSUE
>>> cache.get('testing_yo')
get base key = testing_yo
get base version = None
get key = lendle_:1:testing_yo
get val = None
>>> 
>>> # Using the underlying memcached instance - THIS IS JUST HERE TO GIVE MORE INFO
>>> cache._cache.get('testing_yo')
'testing, yo!'
>>> cache._cache.get('%stesting_yo' % cache.key_prefix)
>>> cache._cache.get('%s:1:testing_yo' % cache.key_prefix)
>>> 

My cache settings are as follows:

CACHES = {
  'default': {
    'BACKEND': 'django.core.cache.backends.memcached.MemcachedCache',
    'LOCATION': '127.0.0.1:11211',
    'KEY_PREFIX': 'lendle_',
  }
}

And the memcached -vv output is thus:

<28 new auto-negotiating client connection
28: Client using the ascii protocol
<28 flush_all
>28 OK
<28 connection closed.
<28 new auto-negotiating client connection
28: Client using the ascii protocol
<28 get lendle_:1:testing_yo
>28 END
<28 connection closed.
<28 new auto-negotiating client connection
28: Client using the ascii protocol
<28 set testing_yo 0 300 12
>28 STORED
<28 connection closed.
<28 new auto-negotiating client connection
28: Client using the ascii protocol
<28 get lendle_:1:testing_yo
>28 END
<28 connection closed.
<28 new auto-negotiating client connection
28: Client using the ascii protocol
<28 get testing_yo
>28 sending key testing_yo
>28 END
<28 connection closed.
<28 new auto-negotiating client connection
28: Client using the ascii protocol
<28 get lendle_testing_yo
>28 END
<28 connection closed.
<28 new auto-negotiating client connection
28: Client using the ascii protocol
<28 get lendle_:1:testing_yo
>28 END
<28 connection closed.

From all of this, it's clear to me that the cache is getting set with the key "testing_yo", not "lendle_:1:testing_yo". But I can't, for the life of me, figure out why.

Thanks again for all your help.

P.S. You'll notice that I switched projects, here -- from barstar to lendle, but the results are the same, either way.

[jeff@…]

You know, I just noticed that it's not even printing the debug info from your patch on the "set" method. Very strange.

[Russell Keith-Magee]

The fact that the set debug isn't being printed is *very* suspect. When combined with the fact that the set() calls are evidently calling the caching functions without any prefixes, it suggests that some old caching code is being invoked for some reason.

Could you try purging all the .pyc files from your django directory, and rerun the tests. I have no idea how you'd be getting half an updated class (updated gets, but not sets), but it's worth a try.

Failing that - Do you get the same results if:

• You use get_cache() directly, instead of the default cache object. i.e.:

  from django.core.cache import get_cache
  mycache = get_cache('default')
  mycache.get('testing_yo')
  ...
  

• You use a manually instantiated cache object:

  from django.core.cache.backends.memcached.MemcachedCache
  mycache = MemcachedCache('127.0.0.1:11211', KEY_PREFIX='lendle_')
  mycache.get('testing_yo')
  ...
  

[jeff@…]

Purging .pyc files didn't help. I even tried a totally fresh checkout of Django trunk. Here's the results:

>>> from django.core.cache import cache
>>> cache.clear()
>>> cache.get('testing_yo')
>>> cache.set('testing_yo', 'testing, yo!', 300)
>>> cache.key_prefix
'lendle_'
>>> 
>>> # Using Django's cache framework's get method - THIS IS THE REAL ISSUE
>>> cache.get('testing_yo')
>>> 
>>> # Using the underlying memcached instance - THIS IS JUST HERE TO GIVE MORE INFO
>>> cache._cache.get('testing_yo')
'testing, yo!'
>>> cache._cache.get('%stesting_yo' % cache.key_prefix)
>>> cache._cache.get('%s:1:testing_yo' % cache.key_prefix)

However, it DOES seem to work if I use get_cache() directly:

>>> from django.core.cache import cache
>>> mycache = get_cache('default')
>>> mycache.clear()
>>> mycache.get('testing_yo')
>>> mycache.set('testing_yo', 'testing, yo!', 300)
>>> mycache.key_prefix
'lendle_'
>>> 
>>> # Using Django's cache framework's get method - THIS IS THE REAL ISSUE
>>> mycache.get('testing_yo')
'testing, yo!'
>>> 
>>> # Using the underlying memcached instance - THIS IS JUST HERE TO GIVE MORE INFO
>>> mycache._cache.get('testing_yo')
>>> mycache._cache.get('%stesting_yo' % cache.key_prefix)
>>> mycache._cache.get('%s:1:testing_yo' % cache.key_prefix)
'testing, yo!'

And if I use a manually instantiated cache object:

>>> from django.core.cache.backends.memcached import MemcachedCache
>>> mycache = MemcachedCache('127.0.0.1:11211', {'KEY_PREFIX': 'lendle_'})
>>> mycache.clear()
>>> mycache.get('testing_yo')
>>> mycache.set('testing_yo', 'testing, yo!', 300)
>>> mycache.key_prefix
'lendle_'
>>> 
>>> # Using Django's cache framework's get method - THIS IS THE REAL ISSUE
>>> mycache.get('testing_yo')
'testing, yo!'
>>> 
>>> # Using the underlying memcached instance - THIS IS JUST HERE TO GIVE MORE INFO
>>> mycache._cache.get('testing_yo')
>>> mycache._cache.get('%stesting_yo' % cache.key_prefix)
>>> mycache._cache.get('%s:1:testing_yo' % cache.key_prefix)
'testing, yo!'

PROGRESS!

[Russell Keith-Magee]

@Jeff -- Two more checks:

• Can you reproduce this problem in a clean project, or just inside the lendle/barstar projects? I'm wondering if there might be something in your code that is gumming up the works. For example, I can reproduce your results if I do the following:

  from django.core import cache
  cache.set = cache._cache.set
  

I can't think of any reason that your code would actually be doing this (or anything like it), but that's the only way that I can reproduce the results you've reported (i.e., no prefix on cache key, debug prints not being shown, manually instantiated caches work correctly). If we can confirm that you are also seeing this problem in a vanilla project, then we can narrow down the search from "something fundamentally wrong with caching" to "something in your usage of caching that indicates a subtle backwards compatibility problem".

• Do the cache tests in Django's test suite pass? To test this out, create a dummy settings file in the Django test directory (the same directory as runtests.py, not the django.tests package), and include a memcache setting:

  DATABASES = {
      'default': {
          'ENGINE': 'django.db.backends.sqlite3'
      },
      'other': {
          'ENGINE': 'django.db.backends.sqlite3',
      }
  }
  
  CACHES = {
    'default': {
      'BACKEND': 'django.core.cache.backends.memcached.MemcachedCache',
      'LOCATION': '127.0.0.1:11211',
      'KEY_PREFIX': 'lendle_',
    }
  }
  

then run ./runtests.py --settings=jeff cache (where 'jeff.py' is the name of your settings module). If you're correctly configured, this should run 175 tests, with no skips or failures. If Memcache isn't configured at all, you'll see 32 skipped tests. If there is something wrong with memcache, you'll see 32 errors/failures.

[Jacob]

(This certainly isn't "unreviewed" any more. Moving it out of the queue...)

[Christian Hammond]

Jeff, did you ever figure out the cause? We have one user of our software reporting something suspiciously similar to this, and yet nobody else has hit it.

[jeff@…]

No, I've never figured it out.

[Aymeric Augustin]

Debugging stalled after comment 12 by Russell, and we don't have enough info to reproduce this problem.