#30323 closed Bug (fixed)
Django 2.2 autoreloader is failing intermittently (not using watchman)
Reported by: | Mark Chackerian | Owned by: | Tom Forbes |
---|---|---|---|
Component: | Utilities | Version: | 2.2 |
Severity: | Release blocker | Keywords: | autoreloader |
Cc: | Sammie S. Taunton, Keryn Knight, Tom Forbes | Triage Stage: | Ready for checkin |
Has patch: | yes | Needs documentation: | no |
Needs tests: | no | Patch needs improvement: | no |
Easy pickings: | no | UI/UX: | no |
Description
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.
Attachments (1)
Change History (21)
comment:2 by , 6 years ago
Cc: | added |
---|
Anecdotal datapoint: Saw 3 separate usernames on IRC yesterday (other than Sammie, who I think was also around?) 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.
comment:3 by , 6 years ago
Cc: | added |
---|
Hmmm... Not sure what to make of this yet. So is this just a docs issue? Is there a change in behaviour without Watchman, i.e. what should be the old behaviour? (Adding Tom, since he knows most about it.)
comment:4 by , 6 years ago
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.
comment:5 by , 6 years ago
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.
comment:6 by , 6 years ago
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.
comment:7 by , 6 years ago
Component: | Uncategorized → Utilities |
---|---|
Severity: | Normal → Release blocker |
Type: | Uncategorized → Bug |
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.)
comment:8 by , 6 years ago
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.
comment:9 by , 6 years ago
Triage Stage: | Unreviewed → Accepted |
---|
comment:10 by , 6 years ago
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.
by , 6 years ago
Attachment: | debug_last.log added |
---|
comment:11 by , 6 years ago
Has patch: | set |
---|
comment:12 by , 6 years ago
I've spoken with one of the people experiencing issues and he confirmed that the patch above seems to have stopped the reloading issues.
comment:13 by , 5 years ago
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.
comment:14 by , 5 years ago
Owner: | changed from | to
---|---|
Status: | new → assigned |
comment:15 by , 5 years ago
Triage Stage: | Accepted → Ready for checkin |
---|
I had the exact same problem and finally figured out it was my PyCharm editor. Perhaps this may help others...
If you are using PyCharm, check your deployment settings.
PyCharm has an option: "Preserve file timestamps" on save. Once this box is unchecked, every file update caused watchman to reload as expected.