Apache Time Issue

Question

I currently have a django site that is using cookie sessions. Ive noticed that the session is randomly being logged out. When debugging this I found it was due to the logic within my code looking at the age of the session. However I then noticed that during the periods that there were no issues the correct time showed in the Apache timestamp. But then the tiemstamp went back 5 hours when then caused my Django program to believe the session had expired and log it out.

Below shows you an example,

[Wed Jul 31 16:12:45 2013] [error] DEBUG ok elapsed time 7
[Wed Jul 31 16:12:45 2013] [error] DEBUG ok elapsed time 1
[Wed Jul 31 10:12:46 2013] [error] DEBUG : request.user.is_authenticated()
[Wed Jul 31 10:12:46 2013] [error] DEBUG ok elapsed time 64809
[Wed Jul 31 10:12:46 2013] [error] DEBUG  since begin . elapsedTime.seconds 64809
[Wed Jul 31 10:12:46 2013] [error] DEBUG request.session\\['deginRequest'\\]
[Wed Jul 31 10:12:46 2013] [error] DEBUG ok elapsed time 64801
[Wed Jul 31 10:12:46 2013] [error] DEBUG  since last req . elapsedTime.seconds 64801
[Wed Jul 31 10:12:46 2013] [error] DEBUG request.session\\['lastRequest'\\]
[Wed Jul 31 10:12:47 2013] [error] DEBUG : shouldLogout

The issue also randomly happens. Any ideas ?

Also here is the middleware Im using (which generates these logs),

class timeOutMiddleware(object):

    def process_request(self, request):

        shouldLogout = False

        if request.user.is_authenticated():
            print "DEBUG :request.user.is_authenticated()"
            if 'beginSession' in request.session:
                elapsedTime = datetime.datetime.now() - \
                              request.session['beginSession']
                print "DEBUG ok elapsed time",elapsedTime.seconds
                if elapsedTime.seconds > 12*3600:
                    print "DEBUG  since begin . elapsedTime.seconds",elapsedTime.seconds
                    del request.session['beginSession']
                    print "DEBUG  request.session\[\'deginRequest\'\]"

                    shouldLogout = True
            else:
                request.session['beginSession'] = datetime.datetime.now()

            if 'lastRequest' in request.session:
                elapsedTime = datetime.datetime.now() - \
                              request.session['lastRequest']
                print "DEBUG ok elapsed time",elapsedTime.seconds
                if elapsedTime.seconds > 2*3600:
                    print "DEBUG   since last req . elapsedTime.seconds",elapsedTime.seconds
                    del request.session['lastRequest']
                    shouldLogout = True

            request.session['lastRequest'] = datetime.datetime.now()


            username = request.user
            if ####.objects.get(username=username).token:
                print "DEBUG : ####.objects.get(username=username).token"

                try:
                    token = ####.objects.get(username=username).token
                    url = 'https://############/%s' % (token)
                    response = requests.get(url)
                    answer = json.loads(response.text)
                    #print "DEBUG answer",answer
                    if not answer["valid"]:
                        shouldLogout = True
                        print "DEBUG",datetime.now(),"not answer[\"valid\"]"
                except:
                    shouldLogout = True
                    print "DEBUG except"
            else:
                shouldLogout = True
                print "DEBUG else"

            if shouldLogout:
                print "DEBUG : ",datetime.datetime.now(),"shouldLogout"
                logout(request)

        else:
            if 'beginSession' in request.session:
                del request.session['beginSession']
            if 'lastRequest' in request.session:
                del request.session['lastRequest']

        return None

Answer 1

The difference in time stamps in the log file is usually because your system time zone is different to what Django has been configured to use. If using embedded mode of Apache/mod_wsgi you can also have problems where you are also hosting PHP applications on the same Apache server and PHP is using a different time zone.

Answer 2

The Apache logs indicate a very discrete time step of 5 hours so this is unlikely to be an underlying system time adjustment by a time keeping daemon such as ntp. I'd guess that it's almost certain to be related to a timezone setting.

If you're using mod_wsgi to serve your app in non-daemon mode, there could be shared state between processes from the environment. In particular, you should take note of the information in the following link: https://code.google.com/p/modwsgi/wiki/ApplicationIssues#Timezone_and_Locale_Settings

As suggested in other answers, it's a good idea to always store time in UTC and only convert to a specific time zone up presentation.

Consider running your application in wsgi daemon mode. From the mod_wsgi docs

Although embedded mode can technically perform better, daemon mode would generally be the safest choice to use.

Daemon mode ensure that you have an isolated process handling your application with no possibility for environment contamination from other wsgi processes. eg TZ environment variable changes.

Answer 3

This seems an OS/HW misconfiguration.

I suspect that some times your network fails and OS (Operating Sistem) need to get data from hardware clock but ntp.

You should ensure than BIOS clock UTC configuration match with /etc/default/rcS parameters:

# assume that the BIOS clock is set to UTC time (recommended)
UTC=no

Also, ensure your timezone configuration is right:

root@egg-v3:/etc# cat /etc/timezone 
Europe/Barcelona

Some easy tests:

• start machine without ntp. If system data is not right, try it changing UTC parameter.
• Play with hwclock command:

Sample:

root@egg-v3:/etc# hwclock 
Fri 02 Aug 2013 04:30:54 PM CEST  -0.609670 seconds
root@egg-v3:/etc# date
Fri Aug  2 14:30:55 CEST 2013

Answer 4

This may not solve your issue, but worth suggesting. And putting that in comment doesn't look appropriate.

---

Use timezone aware datetime objects instead of naive objects (datetime.datetime.now() gives you that.)

And use datetime.datetime.utcnow() rather than .now() when working with date/times.

So from django timezones

import datetime
from django.utils.timezone import utc

now = datetime.datetime.utcnow().replace(tzinfo=utc)

It might be case that when django applying timezones when converting time stored in request.session['beginSession'] from naive to timezone aware objects incorrectly.