Opened 10 years ago

Closed 21 months ago

#937 closed Bug (worksforme)

Autoreload reloads for every request.

Reported by: richie@… Owned by: adrian
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@… 10 years ago.

Download all attachments as: .zip

Change History (23)

comment:1 Changed 10 years ago by eugene@…

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

Changed 10 years ago by eugene@…

comment:2 Changed 10 years ago by adrian

  • Resolution set to fixed
  • Status changed from new to closed

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

comment:3 Changed 9 years ago by richie@…

  • Resolution fixed deleted
  • Status changed from closed to reopened

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 Changed 9 years ago by jacob

  • Resolution set to worksforme
  • Status changed from reopened to closed

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

comment:5 Changed 9 years ago by marcink

  • Resolution worksforme deleted
  • Status changed from closed to reopened

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 Changed 9 years ago 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)

comment:7 Changed 9 years ago by adrian

  • Resolution set to fixed
  • Status changed from reopened to closed

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

comment:8 Changed 7 years ago by gruffudd@…

  • Resolution fixed deleted
  • Status changed from closed to reopened

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 follow-up: Changed 7 years ago by Simon Greenhill

  • Triage Stage changed from Unreviewed to Accepted

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

comment:10 in reply to: ↑ 9 Changed 7 years ago 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.

comment:11 Changed 7 years ago by 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

comment:12 Changed 7 years ago by adrian

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

comment:13 in reply to: ↑ description Changed 7 years ago 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!

comment:14 Changed 7 years ago 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.

comment:16 Changed 6 years ago by anonymous

  • Version changed from SVN to 1.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 Changed 6 years ago by 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).

comment:18 Changed 4 years ago by gabrielhurley

  • Component changed from django-admin.py runserver to Core (Management commands)

comment:19 Changed 4 years ago by lrekucki

  • Severity changed from normal to Normal
  • Type changed from defect to Bug

comment:20 Changed 3 years ago by aaugustin

  • UI/UX unset

Change UI/UX from NULL to False.

comment:21 Changed 3 years ago by aaugustin

  • Easy pickings unset

Change Easy pickings from NULL to False.

comment:22 Changed 2 years ago by aaugustin

  • Status changed from reopened to new

comment:23 Changed 21 months ago by claudep

  • Resolution set to worksforme
  • Status changed from new to closed

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