Opened 4 years ago

Closed 2 years ago

#15149 closed Bug (needsinfo)

Memcached backend: possible issue with cache keys

Reported by: jeff@… Owned by: nobody
Component: Core (Cache system) Version: master
Severity: Normal Keywords: memcached
Cc: mmcnickle, jdunck@…, chipx86@… Triage Stage: Accepted
Has patch: no Needs documentation: no
Needs tests: no Patch needs improvement: no
Easy pickings: no UI/UX: no

Description

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

Attachments (1)

t15149-debug.diff (1.1 KB) - added by russellm 4 years ago.
Additional debug for caching problems

Download all attachments as: .zip

Change History (19)

comment:1 Changed 4 years ago by jezdez

  • Needs documentation unset
  • Needs tests unset
  • Patch needs improvement unset

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?

comment:2 Changed 4 years ago by 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!

comment:3 Changed 4 years ago by Jeff Croft

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

comment:4 Changed 4 years ago by 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?

comment:5 Changed 4 years ago by mmcnickle

  • Cc mmcnickle added

comment:6 Changed 4 years ago by 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.

Changed 4 years ago by russellm

Additional debug for caching problems

comment:7 Changed 4 years ago by russellm

@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.

comment:8 Changed 4 years ago by 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.

comment:9 Changed 4 years ago by jeff@…

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

comment:10 Changed 4 years ago by russellm

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')
    ...
    

comment:11 Changed 4 years ago by 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!

comment:12 Changed 4 years ago by russellm

@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.

comment:13 Changed 4 years ago by jdunck

  • Cc jdunck@… added

comment:14 Changed 4 years ago by lrekucki

  • Severity set to Normal
  • Type set to Bug

comment:15 Changed 4 years ago by jacob

  • Triage Stage changed from Unreviewed to Accepted

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

comment:16 Changed 4 years ago by chipx86

  • Cc chipx86@… added
  • Easy pickings unset
  • UI/UX unset

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.

comment:17 Changed 4 years ago by jeff@…

No, I've never figured it out.

comment:18 Changed 2 years ago by aaugustin

  • Resolution set to needsinfo
  • Status changed from new to closed

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

Note: See TracTickets for help on using tickets.
Back to Top