[Django] #30323: Django 2.2 autoreloader is failing intermittently (not using watchman)
Django
-----------------------------------------+------------------------------
Reporter: picturedots | Owner: nobody
Type: Uncategorized | Status: new
Component: Uncategorized | Version: 2.2
Severity: Normal | Keywords: autoreloader
Triage Stage: Unreviewed | Has patch: 0
Needs documentation: 0 | Needs tests: 0
Patch needs improvement: 0 | Easy pickings: 0
UI/UX: 0 |
-----------------------------------------+------------------------------
Since upgrading to Django 2.2 the autoreloader is working differently and
is not always picking up changes to .py files to reload runserver. It
seems to work consistently once on a file, but multiple changes to the
same file will not necessarily trigger a reload. It's definitely a change
in the behavior to previous versions of Django (up to 2.1.7)
I'm not using watchman.
I'm running runserver in a python 3.7 slim docker container like
./manage.py runserver 0.0.0.0:8001
As a workaround I have tried to add an edit a different .py -- that
doesn't seem to help consistently. I've also noticed that the problem
seems to sometimes go away by itself -- perhaps there is some change to
the timing of the autoreloader which is not clear? For example and ignore
interval of a certain duration.
--
Ticket URL: <https://code.djangoproject.com/ticket/30323>
Django <https://code.djangoproject.com/>
The Web framework for perfectionists with deadlines.
Django
Reporter: Mark Chackerian | Owner: nobody
Type: Uncategorized | Status: new
Component: Uncategorized | Version: 2.2
Keywords: autoreloader | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Sammie S. Taunton):
* cc: Sammie S. Taunton (added)
Comment:
Not sure if this will help you but I also faced this issue when using
PyCharm. I dug down and found that by default PyCharm has an option:
"Preserve file timestamps" on save. Once I unchecked that box, every file
update caused watchman to reload. Either way, your original explanation is
exactly what was happening to me too.
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:1>
Django
Reporter: Mark Chackerian | Owner: nobody
Type: Uncategorized | Status: new
Component: Uncategorized | Version: 2.2
Keywords: autoreloader | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Keryn Knight):
* cc: Keryn Knight (added)
Comment:
Anecdotal datapoint: Saw 3 separate usernames on IRC yesterday suggesting
they'd noted differences/problems with the auto-reloader not picking up
changes in the new version (presumably the stat reloader, as none of them
had watchman installed AFAIK). One of them was on Windows, don't know
about the others.
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:2>
Django
Reporter: Mark Chackerian | Owner: nobody
Type: Uncategorized | Status: new
Component: Uncategorized | Version: 2.2
Keywords: autoreloader | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Carlton Gibson):
* cc: Tom Forbes (added)
Comment:
Hmmm... Not sure what to make of this yet. So is this just a docs issue?
Is there a change in behaviour with Watchman, i.e. what should be the old
behaviour? (Adding Tom, since he knows most about it.)
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:3>
Django
Reporter: Mark Chackerian | Owner: nobody
Type: Uncategorized | Status: new
Component: Uncategorized | Version: 2.2
Keywords: autoreloader | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Tom Forbes):
Ok, this isn't good! Thanks for CCing me Carlton.
I added a fair bit of logging to the autoreloader, if anyone in this
thread could enable the `django.utils.autoreload` logger and set it's
verbosity to DEBUG and paste any logs here then that would be very, very
helpful. It smells like this might be a timestamp resolution issue of some
kind however it's really hard to tell.
Regarding your comment Sammie, are you sure you are using Watchman?
Without Watchman the file modification timestamps are polled, with
Watchman then something more efficient should be used and in theory the
timestamps are not required.
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:4>
Django
Reporter: Mark Chackerian | Owner: nobody
Type: Uncategorized | Status: new
Component: Uncategorized | Version: 2.2
Keywords: autoreloader | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Tom Forbes):
I've just been going through the 2.1 autoreloader code and I noticed an
omission:
{{{
if _win:
mtime -= stat.st_ctime
}}}
It references this ticket: https://code.djangoproject.com/ticket/937. I'm
really not clear on if this is the root cause of any issues on Windows
(the MSDN documentation is pretty unclear), but I will include a PR to
include it anyway: https://github.com/django/django/pull/11176
I have a few more thoughts on potential causes, but the output from the
autoreloader logger is critical if we have any hope of finding out the
root cause.
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:5>
Django
Reporter: Mark Chackerian | Owner: nobody
Type: Uncategorized | Status: new
Component: Uncategorized | Version: 2.2
Keywords: autoreloader | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Sammie S. Taunton):
Tom,
For me this issue was specifically tied with PyCharm not changing
timestamps when saving to a remote location. I've not faced a single issue
since fixing the setting in the IDE. Furthermore, when I upgraded to
Django 2.2, the documentation for what had changed did not mention
anything about having to install watchman and so therefore I have not,
confirmed on system too not to be installed.
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:6>
Django
Reporter: Mark Chackerian | Owner: nobody
Component: Utilities | Version: 2.2
Severity: Release blocker | Resolution:
Keywords: autoreloader | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Carlton Gibson):
* type: Uncategorized => Bug
* component: Uncategorized => Utilities
* severity: Normal => Release blocker
Comment:
Given the multiple reports I'm going to Accept this as a bug ref the
changes related to #27685. (We can recategorise, if needed, when we've
pinned it down further.)
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:7>
Django
Reporter: Mark Chackerian | Owner: nobody
Type: Bug | Status: new
Component: Utilities | Version: 2.2
Severity: Release blocker | Resolution:
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Mark Chackerian):
I turned on the verbose loader as per Tom Forbes' request and here is how
it starts:
{{{
Watching for file changes with StatReloader
Watching for file changes with StatReloader
Waiting for apps ready_event.
Performing system checks...
2019-04-05T16:24:21.447185000Z
Apps ready_event triggered. Sending autoreload_started signal.
Watching dir /code/locale with glob **/*.mo.
Watching dir /usr/local/lib/python3.7/site-
packages/django/contrib/admin/locale with glob **/*.mo.
Watching dir /usr/local/lib/python3.7/site-
packages/django/contrib/auth/locale with glob **/*.mo.
Watching dir /usr/local/lib/python3.7/site-
packages/django/contrib/contenttypes/locale with glob **/*.mo.
Watching dir /usr/local/lib/python3.7/site-
packages/django/contrib/sessions/locale with glob **/*.mo.
Watching dir /usr/local/lib/python3.7/site-
packages/django/contrib/messages/locale with glob **/*.mo.
Watching dir /usr/local/lib/python3.7/site-
packages/django/contrib/staticfiles/locale with glob **/*.mo.
Watching dir /usr/local/lib/python3.7/site-
packages/django/contrib/sites/locale with glob **/*.mo.
Watching dir /usr/local/lib/python3.7/site-packages/corsheaders/locale
with glob **/*.mo.
Watching dir /usr/local/lib/python3.7/site-
packages/django_celery_beat/locale with glob **/*.mo.
Watching dir /usr/local/lib/python3.7/site-
packages/django_extensions/locale with glob **/*.mo.
Watching dir /usr/local/lib/python3.7/site-
packages/django_inlinecss/locale with glob **/*.mo.
Watching dir /usr/local/lib/python3.7/site-packages/django_otp/locale with
glob **/*.mo.
Watching dir /usr/local/lib/python3.7/site-
packages/django_otp/plugins/otp_totp/locale with glob **/*.mo.
Watching dir /usr/local/lib/python3.7/site-
packages/encrypted_model_fields/locale with glob **/*.mo.
Watching dir /usr/local/lib/python3.7/site-packages/graphene_django/locale
with glob **/*.mo.
Watching dir /usr/local/lib/python3.7/site-packages/localflavor/locale
with glob **/*.mo.
Watching dir /usr/local/lib/python3.7/site-packages/polymorphic/locale
with glob **/*.mo.
Watching dir /code/accounts/locale with glob **/*.mo.
Watching dir /code/audits/locale with glob **/*.mo.
Watching dir /code/borrowers/locale with glob **/*.mo.
Watching dir /code/calendars/locale with glob **/*.mo.
Watching dir /code/datarooms/locale with glob **/*.mo.
Watching dir /code/deals/locale with glob **/*.mo.
Watching dir /code/institutions/locale with glob **/*.mo.
Watching dir /code/notifications/locale with glob **/*.mo.
Watching dir /code/payments/locale with glob **/*.mo.
Watching dir /code/widgets/locale with glob **/*.mo.
System check identified no issues (0 silenced).
April 05, 2019 - 16:24:27
Django version 2.2, using settings 'backend.settings'
Starting development server at http://0.0.0.0:8001/
Quit the server with CONTROL-C.
}}}
Here's an example of picking up a change successfully:
{{{
django_1 | File /code/core/domain_utils.py. is_changed: False,
is_new: True
django_1 | File /code/core/domain_utils.py previous mtime: None,
current mtime: 1554481667.0
django_1 | /code/core/domain_utils.py notified as changed. Signal
results: [(<function translation_file_changed at 0x7ffae676e8c8>, None)].
django_1 | /code/core/domain_utils.py changed, reloading.
django_1 | /code/core/domain_utils.py changed, reloading.
django_1 | Watching for file changes with StatReloader
django_1 | Watching for file changes with StatReloader
django_1 | Performing system checks...
}}}
When the auto-reloader fails to detect a change, nothing is logged.
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:8>
Django
Reporter: Mark Chackerian | Owner: nobody
Type: Bug | Status: new
Component: Utilities | Version: 2.2
Severity: Release blocker | Resolution:
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Carlton Gibson):
* stage: Unreviewed => Accepted
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:9>
Django
Reporter: Mark Chackerian | Owner: nobody
Type: Bug | Status: new
Component: Utilities | Version: 2.2
Severity: Release blocker | Resolution:
Keywords: autoreloader | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Tom Forbes):
I will try and fix this tomorrow, but for prosperity's sake the issue as I
can see it is this: In the StatReloader.loop_files, on Windows, seems to
have a condition where all files are treated as new and for some reason
files with changed modification times are not treated as actually changed:
I have a clear debug log from a very helpful chap on IRC that clearly
shows the mtime of a file changing but not triggering as the file being
changed, which can only happen in a particularly weird set of
circumstances. I've attached the full log to the ticket.
I feel the solution is to more faithfully copy the previous stat reloader
as that seemed to work correctly, which means removing some (seemingly
premature) optimizations I tried to add.
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:10>
Django
Reporter: Mark Chackerian | Owner: nobody
Type: Bug | Status: new
Component: Utilities | Version: 2.2
Severity: Release blocker | Resolution:
Keywords: autoreloader | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Tom Forbes):
* Attachment "debug_last.log" added.
Django
Reporter: Mark Chackerian | Owner: nobody
Type: Bug | Status: new
Component: Utilities | Version: 2.2
Severity: Release blocker | Resolution:
Keywords: autoreloader | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Tom Forbes):
* has_patch: 0 => 1
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:11>
Django
Reporter: Mark Chackerian | Owner: nobody
Type: Bug | Status: new
Component: Utilities | Version: 2.2
Severity: Release blocker | Resolution:
Keywords: autoreloader | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Tom Forbes):
I've spoken with one of the people experiencing issues and he confirmed
that the patch above seems to have stopped the reloading issues.
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:12>
Django
Reporter: Mark Chackerian | Owner: nobody
Type: Bug | Status: new
Component: Utilities | Version: 2.2
Severity: Release blocker | Resolution:
Keywords: autoreloader | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Tom Forbes):
Update from the user testing the branch: He's been using the patch I
provided for a week and has experienced no issues reloading at all. While
I'm unable to replicate it locally, and it seems to depend on the
platform, I'd consider this enough of a validation that the fix is
correct.
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:13>
Django
Reporter: Mark Chackerian | Owner: Tom Forbes
Type: Bug | Status: assigned
Component: Utilities | Version: 2.2
Severity: Release blocker | Resolution:
Keywords: autoreloader | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Tom Forbes):
* owner: nobody => Tom Forbes
* status: new => assigned
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:14>
Django
Reporter: Mark Chackerian | Owner: Tom
| Forbes
Type: Bug | Status: assigned
Component: Utilities | Version: 2.2
Severity: Release blocker | Resolution:
| checkin
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by felixxm):
* stage: Accepted => Ready for checkin
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:15>
Django
Reporter: Mark Chackerian | Owner: Tom
| Forbes
Type: Bug | Status: assigned
Component: Utilities | Version: 2.2
Severity: Release blocker | Resolution:
Keywords: autoreloader | Triage Stage: Ready for
| checkin
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Mariusz Felisiak <felisiak.mariusz@…>):
In [changeset:"0636d4d2aa6e4469198fdf662225ad862e60c5e3" 0636d4d2]:
{{{
#!CommitTicketReference repository=""
revision="0636d4d2aa6e4469198fdf662225ad862e60c5e3"
Refs #30323 -- Prevented crash of autoreloader when
get_resolver().urlconf_module raising an exception.
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:17>
Django
Reporter: Mark Chackerian | Owner: Tom
| Forbes
Type: Bug | Status: assigned
Component: Utilities | Version: 2.2
Severity: Release blocker | Resolution:
Keywords: autoreloader | Triage Stage: Ready for
| checkin
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Mariusz Felisiak <felisiak.mariusz@…>):
In [changeset:"b5259ab78054a91f10804de460128879f7948ca4" b5259ab]:
{{{
#!CommitTicketReference repository=""
revision="b5259ab78054a91f10804de460128879f7948ca4"
Refs #30323 -- Simplified utils.autoreload.ensure_echo_on().
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:16>
Django
Reporter: Mark Chackerian | Owner: Tom
| Forbes
Component: Utilities | Version: 2.2
Severity: Release blocker | Resolution: fixed
Keywords: autoreloader | Triage Stage: Ready for
| checkin
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Mariusz Felisiak <felisiak.mariusz@…>):
* status: assigned => closed
* resolution: => fixed
Comment:
In [changeset:"6754bffa2b2df15a741008aa611c1bb0e8dff22b" 6754bffa]:
{{{
#!CommitTicketReference repository=""
revision="6754bffa2b2df15a741008aa611c1bb0e8dff22b"
Fixed #30323 -- Fixed detecting changes by autoreloader when using
StatReloader.
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:18>
Django
Reporter: Mark Chackerian | Owner: Tom
| Forbes
Type: Bug | Status: closed
Component: Utilities | Version: 2.2
Severity: Release blocker | Resolution: fixed
Keywords: autoreloader | Triage Stage: Ready for
| checkin
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Mariusz Felisiak <felisiak.mariusz@…>):
In [changeset:"097457afe47e50e76d53b1cd3312ba8364f866cb" 097457af]:
{{{
#!CommitTicketReference repository=""
revision="097457afe47e50e76d53b1cd3312ba8364f866cb"
[2.2.x] Refs #30323 -- Prevented crash of autoreloader when
get_resolver().urlconf_module raising an exception.
Backport of 0636d4d2aa6e4469198fdf662225ad862e60c5e3 from master
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:19>
Django
Reporter: Mark Chackerian | Owner: Tom
| Forbes
Type: Bug | Status: closed
Component: Utilities | Version: 2.2
Severity: Release blocker | Resolution: fixed
Keywords: autoreloader | Triage Stage: Ready for
| checkin
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Mariusz Felisiak <felisiak.mariusz@…>):
In [changeset:"d326c743ef2052faf1490f59afbc3e7bcf023c69" d326c743]:
{{{
#!CommitTicketReference repository=""
revision="d326c743ef2052faf1490f59afbc3e7bcf023c69"
[2.2.x] Fixed #30323 -- Fixed detecting changes by autoreloader when using
StatReloader.
Backport of 6754bffa2b2df15a741008aa611c1bb0e8dff22b from master
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/30323#comment:20>