Test failures in django.contrib.sessions on default project when memcached used as CACHE_BACKEND

[Jim Dalton]

When running the test management command on a basic, default project, with django.contrib.sessions as the only app in INSTALLED_APPS, and memcached as the CACHE_BACKEND I'm getting the following test failures:

FAIL: test_invalid_key (django.contrib.sessions.tests.CacheDBSessionTests)
FAIL: test_invalid_key (django.contrib.sessions.tests.CacheSessionTests)

The tests run fine (no failures) the first time they are run after memcached is restarted. The next time the tests are run, however, the failures occur.

Here's a more detailed rundown:

# settings.py

...

INSTALLED_APPS = (
    #'django.contrib.contenttypes',
    #'django.contrib.auth',
    'django.contrib.sessions',
    #'django.contrib.sites',
    #'django.contrib.messages',
    #'django.contrib.staticfiles',
    # Uncomment the next line to enable the admin:
    # 'django.contrib.admin',
    # Uncomment the next line to enable admin documentation:
    # 'django.contrib.admindocs',
)

...

CACHE_BACKEND = 'memcached://127.0.0.1:11211/'

# first,  make sure to restart memcached
$ ./manage.py test
Creating test database for alias 'default'...
.....................................................................................................
----------------------------------------------------------------------
Ran 101 tests in 0.188s

OK
Destroying test database for alias 'default'...

# now run the tests another time
$ ./manage.py test
Creating test database for alias 'default'...
.............F.................................................F.....................................
======================================================================
FAIL: test_invalid_key (django.contrib.sessions.tests.CacheDBSessionTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/jsdalton/webs/testproject/src/django/django/contrib/sessions/tests.py", line 165, in test_invalid_key
    self.assertNotEqual(session.session_key, '1')
AssertionError: '1' == '1'

======================================================================
FAIL: test_invalid_key (django.contrib.sessions.tests.CacheSessionTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/jsdalton/webs/testproject/src/django/django/contrib/sessions/tests.py", line 165, in test_invalid_key
    self.assertNotEqual(session.session_key, '1')
AssertionError: '1' == '1'

----------------------------------------------------------------------
Ran 101 tests in 0.159s

FAILED (failures=2)
Destroying test database for alias 'default'...

I have not yet investigated the possible causes for this bug, though it appears as though the cache is perhaps not being flushed appropriately during some portion of the testing and thus values are hanging around in the cache when the test is run next. If I have a chance later, I'll take a closer look.

[Jim Dalton]

I found some time to investigate this more closely, and it would appear that this is a bug in the test code.

In a brief nutshell, this is the body of the test method being run:

    def test_invalid_key(self):
        # Submitting an invalid session key (either by guessing, or if the db has
        # removed the key) results in a new key being generated.
        session = self.backend('1')
        session.save()
        self.assertNotEqual(session.session_key, '1')
        self.assertEqual(session.get('cat'), None)
        session.delete()

When the save() method is called, a new session object is created with that original session_key and saved to the backend. For example, this is what happens in the db store backend:

1. The session with session_key of '1' is saved via save(). A new Session object is then created. The session_data attribute of that objects is populated by an encoded version of the underlying session data, which is retrieved via _get_session(). _get_session() looks for a value in _session_cache, and seeing nothing, calls load(). load() checks the DB to see if an object with that original session_key of '1' exists. Seeing that this object does not exit, load() calls create(). At this point, a new session_key is generated, replacing the original value of '1' with an autogenerated string.

1. save() is now called again, this time with must_create set to True. Another Session object is now created, this time with the new session_key value. The session_data attribute is once again set as the encoded version of the underlying session data, again retrieved via _get_session(), however this time _get_session() is called with no_load set to True. As a result, load() is not called and the session_cache is set to {}, which is what _get_session() ultimately returns. Now we have actually saved a new Session record to the database meaning the original call to create() in step 1 has finally returned. That original call was in the load() method, which, after having finished the create process, now returns {} back to the original _get_session() call from way above. _get_session() sets the cache once again to {} and returns that value to the original original Session object being created when we first called save(). This, importantly, is our original object with session_key of '1'. That object is now in the database as well.

The end result is that we now have *two* new Session objects in the database: one being the Session with key of '1', the other being the Session with the newly generated key. Importantly, only the newly created key exists in the Session object in memory (i.e. this is the value of _session_key). The old key of '1' is gone.

So....where does that leave us? Well, at the end of the test method above, we call session.delete(). This deletes the Session with our newly generated key, but it leaves the Session object with session_key of '1' sitting in the database.

Now, thanks to the django test suite, that object is erased from the DB when the db is flushed at the end of each test method, so it never comes back to bite us. For the file-backed session backend, there is a tearDown() method which flushes the file cache after each test, which is effectively the same result.

For the cache however, we're not so lucky. The cache is not flushed after each test, so the problem is that session "record" with session_key of '1' is still sitting in the cache. In the save() sequence described above (which is pretty similar to what happens for the db), there is a call to load()which we would expect to find nothing in the cache. Here, it does find the old record hanging around. It returns this record instead of calling create(). create() is what generates the new session_key, and since it never gets called, a new key is never created.

Thus, the tests fails.

Being unfamiliar with the sessions application internals for the most part, I'm not certain what to conclude here. One conclusion and easy fix is just to add a tearDown() method to the cache-backed session store tests that flushes the cache after each test. This does "solve" the problem and all the tests pass. Essentially, this is the equivalent as what is happening in the db store and the file store test cases.

The other conclusion is that perhaps something deeper is amiss? Maybe this is such an edge case that it doesn't matter, but it would appear that two records are being created when a session is saved and that one of them is being orphaned? Honestly my brain hurts too much from putting all of the above together to be sure of this at the moment. But I am fairly certain right now that the result of this test method is that records are being orphaned, and the only reason why this isn't apparent is that the test suite flushes the db and file set.

If it's just a matter of fixing the tests by flushing the cache, that's a one-line patch I could upload. Anything more, someone more familiar with the sessions app might want to take a closer look.

[Russell Keith-Magee]

Seems like a good diagnosis, and the patch proposal seems good too. Since it's a one line fix (call to cache.flush() in tearDown) I'll mark this RFC.

[Jim Dalton]

Actually, I thought about it a bit more this a.m. It occurred to me that calling cache.clear() will clear the entire cache, not just the keys set during the test run: "Be careful with this; clear() will remove everything from the cache, not just the keys set by your application."

I've submitted what I think is a better approach, which is just to ensure that both of the session records created specifically during test_invalid_key are deleted. I wrapped the code in a try/finally block since an AssertionError might prevent those records from being deleted.

I flipped this back to "Design decision needed" just to ensure a committer reviewed this slightly different approach, rather than assuming the new patch was ready for checkin.

[Paul McMillan]

Design Decision Needed is the wrong status for this ticket. We agree that the problem needs to be fixed, the specific way the patch goes about doing it isn't the subject of debate among core devs. I'm moving this back to accepted status, since I haven't specifically applied and tested the new patch yet.

I agree that avoiding cache.clear() is the polite thing to do here.

In the proposed patch, is there a reason we aren't doing the delete at the start of every test run? It's better to write test code that can take the database from any state (including a previous test that failed somewhere unusual or odd) than to require our clean up code to run successfully for the next test run. I'm not familiar enough with the code that this is testing to know if that's particularly difficult here, but it seems like a better option.

[Jim Dalton]

Thanks for fixing the status.

To answer your question regarding the patch:

I basically took the "do the least possible that works" route and essentially just improved what was in the existing test code. This test function was already attempting to delete the session it created via session.delete(), but that command was leaving an orphan session record in the cache with a key of '1'. So all I really did here was explicitly remove that orphaned session as well, and wrapped it up in a try/finally block to ensure it was executed. I think that's indeed sufficient to clean up this particular test, and there are no other session tests involving the cache that create these orphaned records. Note that this test (test_invalid_key) is the only test to create it's own session in a local variable. The rest in general use the instance variable self.session which is deleted in the tearDown method.

That said:

I would agree that tear down for the cache is not being handled very well in comparison with the database and the file backends. For the database, it's already getting cleaned at the end of every test in the Django test suite. For the file backend, there is some extra code in the tearDown method that basically just deletes all the files created. The cache backend tests have no such method, so basically anything that is not being explicitly deleted *is* being left in around in the cache. Ideally, we'd create a tearDown method for the cache backend tests that cleared out all the junk we had put in there. However, to my knowledge at least, there is no good way of cleaning up the cache easily. (Using cache.clear() was the quick and dirty solution, but I discarded that idea for the reasons cited in my other comment.)

Anyhow, I don't have any great ideas for how to remove what was created in the cache during these runs without specifically targeting the records created. If you think there's another approach that might work, I'd be happy to consider it and submit a patch if there was a feasible way to implement it.

[Russell Keith-Magee]

(In [15235]) Fixed #15026 -- Added cleanup to the invalid key session tests; when using Memcached as a cache backend, the cache-backed session backends would fail on the second run due to leftover cache artefacts. Thanks to jsdalton for the report and patch.

[Jacob]

Milestone 1.3 deleted