Autoreload reloads for every request.

[richie@…]

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

[eugene@…]

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.

[Adrian Holovaty]

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

[richie@…]

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.

[Jacob]

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

[marcink]

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.

[Jacob]

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

[Adrian Holovaty]

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

[gruffudd@…]

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)

[Simon Greenhill]

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

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

[gruffudd@…]

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

[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!

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

[anonymous]

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.

[anonymous]

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

[Aymeric Augustin]

Change UI/UX from NULL to False.

[Aymeric Augustin]

Change Easy pickings from NULL to False.

[Claude Paroz]

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