Opened 13 years ago

Closed 12 years ago

#14555 closed Bug (fixed)

Session loss with psycopg2 db backend

Reported by: tomaszswiderski Owned by: Aymeric Augustin
Component: contrib.sessions Version: 1.3
Severity: Normal Keywords:
Cc: john@… Triage Stage: Design decision needed
Has patch: yes Needs documentation: no
Needs tests: no Patch needs improvement: yes
Easy pickings: no UI/UX: no

Description

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

Attachments (2)

session_test.tar.gz (6.3 KB ) - added by tomaszswiderski 13 years ago.
pgtz.patch (1.2 KB ) - added by John Hensley 12 years ago.
Patch to set time zone before each query

Download all attachments as: .zip

Change History (6)

by tomaszswiderski, 13 years ago

Attachment: session_test.tar.gz added

comment:1 by Brett Haydon, 13 years ago

Keywords: sprintdec2010 added
Resolution: worksforme
Status: newclosed
Triage Stage: UnreviewedAccepted

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.

comment:2 by John Hensley, 12 years ago

Cc: john@… added
Easy pickings: unset
Has patch: set
Keywords: sprintdec2010 removed
Patch needs improvement: set
Resolution: worksforme
Severity: Normal
Status: closedreopened
Triage Stage: AcceptedDesign decision needed
Type: Bug
UI/UX: unset
Version: 1.21.3

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.

by John Hensley, 12 years ago

Attachment: pgtz.patch added

Patch to set time zone before each query

comment:3 by Aymeric Augustin, 12 years ago

Owner: changed from nobody to Aymeric Augustin
Status: reopenednew

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

in reply to:  2 comment:4 by Aymeric Augustin, 12 years ago

Resolution: fixed
Status: newclosed

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.

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