Opened 6 years ago

Closed 5 years ago

Last modified 5 years ago

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

debug_last.log (152.6 KB ) - added by Tom Forbes 6 years ago.

Download all attachments as: .zip

Change History (21)

comment:1 by Sammie S. Taunton, 6 years ago

Cc: Sammie S. Taunton added

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.

Last edited 6 years ago by Sammie S. Taunton (previous) (diff)

comment:2 by Keryn Knight, 6 years ago

Cc: Keryn Knight 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.

Last edited 6 years ago by Keryn Knight (previous) (diff)

comment:3 by Carlton Gibson, 6 years ago

Cc: Tom Forbes 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.)

Last edited 6 years ago by Carlton Gibson (previous) (diff)

comment:4 by Tom Forbes, 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 Tom Forbes, 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 Sammie S. Taunton, 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 Carlton Gibson, 6 years ago

Component: UncategorizedUtilities
Severity: NormalRelease blocker
Type: UncategorizedBug

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 Mark Chackerian, 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 Carlton Gibson, 6 years ago

Triage Stage: UnreviewedAccepted

comment:10 by Tom Forbes, 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 Tom Forbes, 6 years ago

Attachment: debug_last.log added

comment:11 by Tom Forbes, 6 years ago

Has patch: set

comment:12 by Tom Forbes, 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 Tom Forbes, 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 Tom Forbes, 5 years ago

Owner: changed from nobody to Tom Forbes
Status: newassigned

comment:15 by Mariusz Felisiak, 5 years ago

Triage Stage: AcceptedReady for checkin

comment:16 by Mariusz Felisiak <felisiak.mariusz@…>, 5 years ago

In b5259ab:

Refs #30323 -- Simplified utils.autoreload.ensure_echo_on().

comment:17 by Mariusz Felisiak <felisiak.mariusz@…>, 5 years ago

In 0636d4d2:

Refs #30323 -- Prevented crash of autoreloader when get_resolver().urlconf_module raising an exception.

comment:18 by Mariusz Felisiak <felisiak.mariusz@…>, 5 years ago

Resolution: fixed
Status: assignedclosed

In 6754bffa:

Fixed #30323 -- Fixed detecting changes by autoreloader when using StatReloader.

comment:19 by Mariusz Felisiak <felisiak.mariusz@…>, 5 years ago

In 097457af:

[2.2.x] Refs #30323 -- Prevented crash of autoreloader when get_resolver().urlconf_module raising an exception.

Backport of 0636d4d2aa6e4469198fdf662225ad862e60c5e3 from master

comment:20 by Mariusz Felisiak <felisiak.mariusz@…>, 5 years ago

In d326c743:

[2.2.x] Fixed #30323 -- Fixed detecting changes by autoreloader when using StatReloader.

Backport of 6754bffa2b2df15a741008aa611c1bb0e8dff22b from master

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