Session Data Race Condition Leading to Dropped Sessions

[Simon Blanchard]

Symptom:

SESSION_SAVE_EVERY_REQUEST = True

SESSION_ENGINE = 'django.contrib.sessions.backends.file'

With the settings as above we observe that the session cookie changes on every request.

Cause:

The save() method calls the load() method after it has truncated the file.

The SessionStore.save() method writes back the cached session dict to storage. If the session dict (SessionBase._session_cache) is not already cached, a cache is attempted via accessing the session._session attribute. That is, for uncached sessions the save() method will (indirectly) call the load method. The problem (in the file backend) is that this happens after the session file store has been open with 'wb' - i.e. truncated. So it loads an empty file, triggering a SuspiciousOperation exception form SessionBase.decode() which cause a new session key to be generated and sent, which means a new file and hence all the session data gone.

Solution:

Make sure the session is cached before the store is written in the save method. One way to do this is in the attached patch.

Discussion:

This was a devil to track down. My client's log in sessions where getting dropped randomly. I set up a duplicate test server and (of course) the problem did not manifest itself. I instrumented the code with debug logging - the problem went away. Don't you just love it when that happens. It does at least point to a race/timing problem. Finally, I inserted flocks around access to the session file store. This lead to the response hanging as the load method (called via save()) could never lock the file since the save() method had it locked and was not finished with it yet.

I was using the database as session storage and seeing the same errors. I switched to the file backend to try to track the problem. So this problem seems to be endemic to the session backends. Though it is much easier to track on the file backend. It is also, because it is a timing issue, dependant on the server setup hw/sw so it may not manifest everywhere.

Other notes:

The attached patch also corrects a spelling error in the comments of the Session middleware

This error message: raise SuspiciousOperation("User tampered with session cookie.") from sessions/backends/base.py is mis-leading. Actually the exposed tamper is with the session data as stored on the server not with the cookie per se. Of course, to do that someone would have to have access to the session store. Perhaps a better message would be "Invalid session data"

[mrts]

This should be in scope for 1.0.

[mrts]

Code duplication isn't good. Perhaps something in the lines of the following?

base.py:
...
    def save(self):
        """
        Saves the session data.
        """
        self._get_session()
        self._save()

    def _save(self):
        raise NotImplementedError
...

And backends override _save() instead of save().

[mrts]

The DRY version. Note that this is backwards-incompatible for custom backends. Tested with r8187

[Malcolm Tredinnick]

The logic described here is only applicable to the filesystem backend (where the truncation before loading is a real bug). I'll fix that case similar to the given patch.

If you're seeing a similar problem with the db backend, it isn't because of the reasoning given here. The session data is fully loaded from the database before the write update happens in the save() method (it's part of the ACID property of databases). Similarly for the cache backend. It's only the filesystem case where the state of the storage medium is changed before the read of session data.

I'll close this ticket with the above patch and there will be some other session-related fixes going in at the same time. I'm not going to apply anything like this for the db and cache backends because it shouldn't have any effect there and will only complicate the code. It's possible I'm wrong about this (although I can't see it), so reopen if there's some step I've missed, but "appears to fix it" for the db backend isn't a reason to apply this patch. All that's happened is the symptom would have been hidden. So if this still happens with the DB backend, open a new ticket with some information about how to repeat the problem (which I realise might be hard if it only appears periodically).

[Malcolm Tredinnick]

Fixed in [8344]

[Jacob]

Milestone 1.0 deleted