Opened 19 years ago

Closed 11 years ago

#937 closed Bug (worksforme)

Autoreload reloads for every request.

Reported by: richie@… Owned by: Adrian Holovaty
Component: Core (Management commands) Version: 1.0
Severity: Normal Keywords:
Cc: Triage Stage: Accepted
Has patch: no Needs documentation: no
Needs tests: no Patch needs improvement: no
Easy pickings: no UI/UX: no

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 (1)

django.autoreload.patch (1.3 KB ) - added by eugene@… 19 years ago.

Download all attachments as: .zip

Change History (23)

comment:1 by eugene@…, 19 years ago

Summary: Autoreload reloads for every request.[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.

by eugene@…, 19 years ago

Attachment: django.autoreload.patch added

comment:2 by Adrian Holovaty, 19 years ago

Resolution: fixed
Status: newclosed

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

comment:3 by richie@…, 19 years ago

Resolution: fixed
Status: closedreopened

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.

comment:4 by Jacob, 19 years ago

Resolution: worksforme
Status: reopenedclosed

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

comment:5 by marcink, 19 years ago

Resolution: worksforme
Status: closedreopened

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.

comment:6 by Jacob, 19 years ago

Summary: [patch] Autoreload reloads for every request.Autoreload reloads for every request.

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

comment:7 by Adrian Holovaty, 19 years ago

Resolution: fixed
Status: reopenedclosed

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

comment:8 by gruffudd@…, 16 years ago

Resolution: fixed
Status: closedreopened

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)

comment:9 by Simon Greenhill, 16 years ago

Triage Stage: UnreviewedAccepted

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

in reply to:  9 comment:10 by anonymous, 16 years ago

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.

comment:11 by gruffudd@…, 16 years ago

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

comment:12 by Adrian Holovaty, 16 years ago

Component: Toolsdjango-admin.py runserver

in reply to:  description comment:13 by anonymous, 16 years ago

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!

comment:14 by lgastako, 16 years ago

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.

comment:16 by anonymous, 15 years ago

Version: SVN1.0

I'm seeing this now, with Django 1.02, on Leopard.

It doesn't happen for all requests, but for requests for which it does happen, it happens 100% reproducibly.

In my case it's for the file $HOME/.python-eggs/simplejson-2.0.9-py2.5-macosx-10.5-i386.egg-tmp/simplejson/_speedups.so

and excluding .so files (as above) fixes the issue.

comment:17 by anonymous, 15 years ago

(I'm the immediately previous anonymous):
I'm still seeing this, but I've narrowed it down further.

The change in mtime is happening when another process (in this case, a test client) running on localhost, imports simplejson as well.

As soon as the import of _speedups.so is completed by the client, the mtime on that file, as seen by the server, is suddenly displaced by an hour (the client sees the correct mtime).

comment:18 by Gabriel Hurley, 14 years ago

Component: django-admin.py runserverCore (Management commands)

comment:19 by Łukasz Rekucki, 14 years ago

Severity: normalNormal
Type: defectBug

comment:20 by Aymeric Augustin, 13 years ago

UI/UX: unset

Change UI/UX from NULL to False.

comment:21 by Aymeric Augustin, 13 years ago

Easy pickings: unset

Change Easy pickings from NULL to False.

comment:22 by Aymeric Augustin, 12 years ago

Status: reopenednew

comment:23 by Claude Paroz, 11 years ago

Resolution: worksforme
Status: newclosed

I'm going to won't fix this ticket, first because we have not heard reports about this issue for 4 years now, and second because there is now good progress on #9722 to use a different mechanism to track file modifications (through pyinotify).

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