Django 2.2 autoreloader is failing intermittently (not using watchman)

[Mark Chackerian]

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.

[Sammie S. Taunton]

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.

[Keryn Knight]

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.

[Carlton Gibson]

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

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

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

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

[Carlton Gibson]

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

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

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

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

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

[Mariusz Felisiak <felisiak.mariusz@…>]

In b5259ab:

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

[Mariusz Felisiak <felisiak.mariusz@…>]

In 0636d4d2:

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

[Mariusz Felisiak <felisiak.mariusz@…>]

In 6754bffa:

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

[Mariusz Felisiak <felisiak.mariusz@…>]

In 097457af:

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

Backport of 0636d4d2aa6e4469198fdf662225ad862e60c5e3 from master

[Mariusz Felisiak <felisiak.mariusz@…>]

In d326c743:

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

Backport of 6754bffa2b2df15a741008aa611c1bb0e8dff22b from master