Django

Code

Ticket #937 (reopened)

Opened 3 years ago

Last modified 2 months ago

Autoreload reloads for every request.

Reported by: richie@entrian.com Assigned to: adrian
Milestone: Component: django-admin.py runserver
Version: SVN Keywords:
Cc: Triage Stage: Accepted
Has patch: 0 Needs documentation: 0
Needs tests: 0 Patch needs improvement: 0

Description

I've just updated to the current trunk, and the autoreload code is firing on every request I make to my developent server. The timestamps it's reading differ by one hour between reads, even though the file hasn't changed. I added this to autoreload.py at the point it decides something has changed:

print filename, time.ctime(mtime), time.ctime(mtimes[filename])

and it's printing something like this:

C:\...\utils\html.py Fri Oct 28 20:24:02 2005 Fri Oct 28 19:24:02 2005

for every request.

I'm running on Windows, which has a nasty habit of applying the current DST settings to stat() results, so you get a different timestamp for the same file depending on when you ask for it. Maybe something's happening during startup that's changing the DST setting? (I'm in the UK, where we're not in DST, but the file that is triggering autoreload was last modified in DST.)

Attachments

django.autoreload.patch (1.3 kB) - added by eugene@lazutkin.com on 12/09/05 00:35:11.

Change History

12/09/05 00:34:40 changed by eugene@lazutkin.com

  • summary changed from Autoreload reloads for every request. to [patch] Autoreload reloads for every request..

It looks like somewhere during execution of reloader_thread() Django switches local time zone. On Windows platform it causes a change in returned values of file modification time, which becomes shifted according to time difference with GMT (e.g., 6 hours for 'America/Chicago').

Unfortunately Python doesn't work with time zones properly on Windows:

  • time.timezone is always 0.
  • time.tzname is some constant garbage: ('Ame', 'ric').
  • It always assumes that initial timezone is GMT.

It makes it impossible to detect time zone changes.

Instead of modification time (st_mtime), my patch saves and checks the difference between st_mtime and creation time (st_ctime), which is unaffected by time shifts. It is done only for Windows, because this algorithm is not applicable for Unix.

Miscellaneous notes:

  • reloadFiles variable is deleted - it was not used anywhere.
  • *.pyo check is added.
  • file existence check is moved after filename calculation.
  • Any time modification causes a reload to support file reverts, when file metadata is restored along with file content.

12/09/05 00:35:11 changed by eugene@lazutkin.com

  • attachment django.autoreload.patch added.

12/15/05 22:59:35 changed by adrian

  • status changed from new to closed.
  • resolution set to fixed.

(In [1686]) Fixed #937 -- autoreload no longer reloads on every request on Windows. Thanks for the patch, Eugene

02/01/06 15:39:51 changed by richie@entrian.com

  • status changed from closed to reopened.
  • resolution deleted.

I've updated to the head (revision 2216) and I'm still seeing spontanous reloads, even though I've verified that Eugene's patch has been applied to my checkout. I've narrowed down the problem - I noticed that the reloads would happen after I'd accessed my MySQL database, and not before. I can make the problem go away by adding these lines:

        import MySQLdb
        MySQLdb.connect()

at the start of the if os.environ.get("RUN_MAIN") == "true" section of autoreload.py. MySQLdb is doing something fishy with the timezone at the point it connects to the database, and adding that code makes it happen before autoreload has got going. (Simply importing MySQLdb has no effect.) Googling for timezone-related problems with MySQLdb didn't turn up anything useful.

02/27/06 17:46:34 changed by jacob

  • status changed from reopened to closed.
  • resolution set to worksforme.

I can't reproduce this; Richie, if you have more information please reopen with it.

03/26/06 06:36:02 changed by marcink

  • status changed from closed to reopened.
  • resolution deleted.

I am experiencing the same problem Richie described. I use Python 2.3.4 on Windows XP. The workaround Richie described works for me too. Another workaround is to change django/conf/settings.py and remove the assignment to os.environTZ? -- it does not seem to work on Windows anyway. See also #1480.

It looks to me that on Windows setting TZ to pretty much anything before 'import time' makes Python fall back to GMT and MySQLdb.connect has the side-effect of changing the time zone back to local. Whatever the change is, it is not reflected by any variable in the time module -- tzname, daylight or altzone. Even with Eugene's patch the autoreloader gets values that differ by 1 hour for some files.

04/05/06 10:32:48 changed by jacob

  • summary changed from [patch] Autoreload reloads for every request. to Autoreload reloads for every request..

(removing [patch] from the title since the given patch apparently doesn't work)

04/23/06 20:11:26 changed by adrian

  • status changed from reopened to closed.
  • resolution set to fixed.

Is this still happening with magic-removal? If so, please reopen with more information.

06/12/08 04:09:22 changed by gruffudd@gmail.com

  • status changed from closed to reopened.
  • resolution deleted.

This is happening for me after moving from CentOS 4 to CentOS 5. The file causing the reload seems to be _mysql.so - If I add richie's print statement above, I get:

Validating models...
/root/.python-eggs/MySQL_python-1.2.2-py2.4-linux-i686.egg-tmp/_mysql.so Mon Jun  2 13:56:50 2008 Mon Jun  2 14:56:50 2008
Validating models...
0 errors found

Django version 0.97-pre-SVN-7624, using settings 'AGD_dev1.settings'
Development server is running at http://0.0.0.0:80/
Quit the server with CONTROL-C.
/root/.python-eggs/MySQL_python-1.2.2-py2.4-linux-i686.egg-tmp/_mysql.so Mon Jun  2 13:56:50 2008 Mon Jun  2 14:56:50 2008
Validating models...
/root/.python-eggs/MySQL_python-1.2.2-py2.4-linux-i686.egg-tmp/_mysql.so Mon Jun  2 13:56:50 2008 Mon Jun  2 14:56:50 2008
Validating models...
/root/.python-eggs/MySQL_python-1.2.2-py2.4-linux-i686.egg-tmp/_mysql.so Mon Jun  2 13:56:50 2008 Mon Jun  2 14:56:50 2008

..ad infinitum

If I ignore files ending in .so then the problem goes away:

def reloader_thread():
    mtimes = {}
    win = (sys.platform == "win32")
    while RUN_RELOADER:
        for filename in filter(lambda v: v, map(lambda m: getattr(m, "__file__", None), sys.modules.values())):
            if filename.endswith('.so'):
                continue
            if filename.endswith(".pyc") or filename.endswith("*.pyo"):
                filename = filename[:-1]
            if not os.path.exists(filename):
                continue # File might be in an egg, so it can't be reloaded.
            stat = os.stat(filename)
            mtime = stat.st_mtime
            if win:
                mtime -= stat.st_ctime
            if filename not in mtimes:
                mtimes[filename] = mtime
                continue
            if mtime != mtimes[filename]:
                print filename, time.ctime(mtime), time.ctime(mtimes[filename])
                sys.exit(3) # force reload
        time.sleep(1)

(follow-up: ↓ 10 ) 06/14/08 01:31:29 changed by Simon Greenhill

  • stage changed from Unreviewed to Accepted.

So it's just the .so files getting reloaded?

(in reply to: ↑ 9 ) 06/14/08 07:08:04 changed by anonymous

Replying to Simon Greenhill:

So it's just the .so files getting reloaded?

Bizarrely, the modified time is being reported correctly now.

/root/.python-eggs/MySQL_python-1.2.2-py2.4-linux-i686.egg-tmp/_mysql.so Mon Jun  2 14:56:50 2008 Mon Jun  2 14:56:50 2008

So, I can't reproduce the bug today. Come to think of it the problem is intermittent, but it does occur on two separate CentOS 5 VMWare instances.

The only change is that I updated from 7624 to 7631, but those changes don't look as if they'd make a difference:

# svn up
U    django/core/management/commands/dumpdata.py
U    tests/modeltests/many_to_one/models.py
U    docs/db-api.txt
Updated to revision 7631.

06/16/08 06:33:16 changed by gruffudd@gmail.com

The problem is happening again today.

It is definitely the modified timestamp of _mysql.so that is causing the problem. The mod time is shown as 15:56 if I do ls -l, but stat.st_mtime is reporting it as 15:56 and 14:56 in autoreload.py which makes it think it needs to be reloaded.

# ls -l /root/.python-eggs/MySQL_python-1.2.2-py2.4-linux-i686.egg-tmp/_mysql.so
-rw------- 1 root root 118173 Jun  2 15:56 /root/.python-eggs/MySQL_python-1.2.2-py2.4-linux-i686.egg-tmp/_mysql.so

and ...

                print filename, time.ctime(mtime), time.ctime(mtimes[filename])

... gives :

/root/.python-eggs/MySQL_python-1.2.2-py2.4-linux-i686.egg-tmp/_mysql.so Mon Jun  2 15:56:50 2008 Mon Jun  2 14:56:50 2008

There doesn't seem to be a pattern as to when the problem is showing and when it is not. I've tried restarting mysql, but no difference.

If I don't use django and do os.stat on the file, the time is shown as 15:56, which is correct:

Python 2.4.3 (#1, May  9 2006, 12:17:31) 
[GCC 3.3.2 20031022 (Red Hat Linux 3.3.2-1)] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import os, time
>>> s=os.stat('/root/.python-eggs/MySQL_python-1.2.2-py2.4-linux-i686.egg-tmp/_mysql.so')
>>> time.ctime(s.st_mtime)
'Mon Jun  2 15:56:50 2008'

..so it seems that mtimes[filename] is always (intermittently..) storing the incorrect mod time for _mysql.so

09/10/08 00:19:54 changed by adrian

  • component changed from Tools to django-admin.py runserver.

(in reply to: ↑ description ) 10/07/08 03:14:25 changed by anonymous

Replying to richie@entrian.com:

I've just updated to the current trunk, and the autoreload code is firing on every request I make to my developent server. The timestamps it's reading differ by one hour between reads, even though the file hasn't changed. I added this to autoreload.py at the point it decides something has changed: print filename, time.ctime(mtime), time.ctime(mtimes[filename]) and it's printing something like this: C:\...\utils\html.py Fri Oct 28 20:24:02 2005 Fri Oct 28 19:24:02 2005 for every request. I'm running on Windows, which has a nasty habit of applying the current DST settings to stat() results, so you get a different timestamp for the same file depending on when you ask for it. Maybe something's happening during startup that's changing the DST setting? (I'm in the UK, where we're not in DST, but the file that is triggering autoreload was last modified in DST.)

Hello from Russia!

10/10/08 16:55:53 changed by lgastako

I am experiencing this problem (.so files getting incorrect mtime results and causing reloads on every request) on Django 1.0 on Leopard. I am working around it by adding a check to exclude .so files for now, but I would love to see this fixed. I am happy to provide more information if it would be helpful.


Add/Change #937 (Autoreload reloads for every request.)




Change Properties
Action