Session loss with psycopg2 db backend

[tomaszswiderski]

Hey,

I have problem with django 1.2 and psycopg2 backend. When django raises http500 error session is dropped too. Also my client's apache server is dropping sessions on every request after one week without restart. It only happen with django 1.2 (django 1.1 works). Django 1.2 works too with sqlite backend (didn't test mysql). So I suspect problems with Django1.2 psycopg2 handler. It's not psycopg2 fault since Django1.1 works on the same version of pyscopg2 module (2.0.8).

I added logging to django.contrib.sessions and here is fragment of the output:

Wed, 20 Oct 2010 06:15:44 DEBUG django.contrib.sessions.backends.base: Returning 2010-10-20 07:15:44.591438

Wed, 20 Oct 2010 06:15:44 DEBUG django.contrib.sessions.backends.db: Session expire date is 2010-10-20 07:15:44.591438

Wed, 20 Oct 2010 06:15:44 DEBUG django.contrib.sessions.models: Pre-save session expire_date: 2010-10-20 07:15:44.591438, current_time: 2010-10-20 06:15:44.5 91438

Wed, 20 Oct 2010 06:15:44 DEBUG django.contrib.sessions.models: Pre-save session expire_date utctimetuple: (2010, 10, 20, 7, 15, 44, 2, 293, 0)

Wed, 20 Oct 2010 06:15:44 DEBUG django.contrib.sessions.models: Post-save session expire_date: 2010-10-20 07:15:44.591438

Wed, 20 Oct 2010 06:15:44 DEBUG django.contrib.sessions.middleware: Setting new cookie data. (/communications/new/feed_item)

Wed, 20 Oct 2010 06:15:44 DEBUG django.contrib.sessions.middleware: Session key in response: 861a43a409c6e9aa4d4e447fe61e5d48 (/communications/new/feed_item)

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.middleware: Session key from cookie: 861a43a409c6e9aa4d4e447fe61e5d48 (/communications/)

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.backends.base: Creating new session object with key 861a43a409c6e9aa4d4e447fe61e5d48

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.middleware: Session key in request: 861a43a409c6e9aa4d4e447fe61e5d48 (/communications/)

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.backends.db: Trying to load session data for 861a43a409c6e9aa4d4e447fe61e5d48

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.backends.db: Session data 861a43a409c6e9aa4d4e447fe61e5d48 does exist but is expired: 2010-10-20 03:15:44.591438, current time is 2010-10-20 06:15:56.256103

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.backends.db: Trying to create new session...

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.backends.base: Trying to create new session key...

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.backends.db: Checking if session exists for key 52f18ba6a3f1a60db1a2cb15bfc44110.

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.backends.db: Session 52f18ba6a3f1a60db1a2cb15bfc44110 does not exist.

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.backends.base: New session key created: 52f18ba6a3f1a60db1a2cb15bfc44110

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.backends.db: New session key 52f18ba6a3f1a60db1a2cb15bfc44110

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.backends.db: Trying to save session data for key 52f18ba6a3f1a60db1a2cb15bfc44110 with must_create=True

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.backends.base: Getting expiry_date...

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.backends.base: Expiry value from session obj is None

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.backends.base: No expiry data in session so using settings value 3600

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.backends.base: Returning 2010-10-20 07:15:56.260103

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.backends.db: Session expire date is 2010-10-20 07:15:56.260103

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.models: Pre-save session expire_date: 2010-10-20 07:15:56.260103, current_time: 2010-10-20 06:15:56.264103

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.models: Pre-save session expire_date utctimetuple: (2010, 10, 20, 7, 15, 56, 2, 293, 0)

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.models: Post-save session expire_date: 2010-10-20 07:15:56.260103

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.middleware: Session key in pre-response: 52f18ba6a3f1a60db1a2cb15bfc44110 (/communications/)

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.middleware: max_age=3600

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.middleware: expires_time=1287573356.28

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.middleware: expires=Wed, 20-Oct-2010 11:15:56 GMT

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.backends.db: Trying to save session data for key 52f18ba6a3f1a60db1a2cb15bfc44110 with must_create=False

The most important line is:

Wed, 20 Oct 2010 06:15:56 DEBUG django.contrib.sessions.backends.db: Session data 861a43a409c6e9aa4d4e447fe61e5d48 does exist but is expired: 2010-10-20 03:15:44.591438, current time is 2010-10-20 06:15:56.256103

So django seems to be setting past expiration date to db?!

My session settings in settings.py are:

SESSION_COOKIE_AGE = 3600

SESSION_SAVE_EVERY_REQUEST = True

I'm attaching sample project. It's basically empty except one app plugged into admin site. To reproduce an error syncdb using psycopg2 backend. Go to admin site and try to save new Boom object. It has bug in save method to produce an server error (None + 1). After server error has been raised, hit Back in your browser and try to click in any link. You will be redirected to login page (session dropped because of error).

[Brett Haydon]

I can't reproduce this error. It works fine for me.

You'll need to do further investigation on why it doesn't work for you. I suggest loading something like django-devserver and having a look at the SQL that is setting the expiry datetime and try executing that statement directly using psycopg2 (outside of django), and then seeing what is stored on the db.

I also can't see that there is any difference in the connection handling of timezones in 1.2 from 1.1. Perhaps you can put some logging on the TIME ZONE settings on connection creation.

[John Hensley]

I think this ticket should be revisited. The test app proves the problem, provided your environment is correct.

The issue only arises when your session lifetime is less than or equal to the offset between the time zone used by the server (or PostgreSQL, if different) and the time zone specified in the Django settings, and the former is east of the latter. If your machine runs in America/New_York, the test app works, because it's using America/Chicago and SESSION_COOKIE_AGE is 3600 seconds (one hour).

What's happening is that when the exception is thrown and the transaction rolled back, PostgreSQL rolls back the SET TIME ZONE call executed when the cursor is built (​http://www.postgresql.org/docs/9.0/static/sql-set.html). The session is updated with a timestamp in the default PostgreSQL timezone, not Django's -- which means it's an hour earlier than it should be and expires that instant.

If the server is west of Django's timezone, or the session lifetime is longer than the offset, the error can go unnoticed, because the session is still valid and the expiration date gets fixed on the next successful request.

The most obvious fix to the current postgresql_psycopg2 backend is to insert the SET TIME ZONE call in CursorWrapper.execute before executing the real query.

There's also the work being done on multiple timezone support (​http://groups.google.com/group/django-developers/browse_thread/thread/cf0423bbb85b1bbf); that may solve this as well.

[John Hensley]

Patch to set time zone before each query

[Aymeric Augustin]

I somehow missed this ticket when I implemented time zone support. I'm going to handle it.

[Aymeric Augustin]

Replying to john:

What's happening is that when the exception is thrown and the transaction rolled back, PostgreSQL rolls back the SET TIME ZONE call executed when the cursor is built (​http://www.postgresql.org/docs/9.0/static/sql-set.html). The session is updated with a timestamp in the default PostgreSQL timezone, not Django's -- which means it's an hour earlier than it should be and expires that instant.

In fact, this ticket is essentially a duplicate of #17062, which was fixed at r17128.

It isn't related to time zone support.