Opened 9 months ago

Closed 8 months ago

Last modified 8 months 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 8 months ago.

Download all attachments as: .zip

Change History (21)

comment:1 Changed 9 months ago by Sammie S. Taunton

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 9 months ago by Sammie S. Taunton (previous) (diff)

comment:2 Changed 8 months ago by Keryn Knight

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 8 months ago by Keryn Knight (previous) (diff)

comment:3 Changed 8 months ago by Carlton Gibson

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 8 months ago by Carlton Gibson (previous) (diff)

comment:4 Changed 8 months ago 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.

comment:5 Changed 8 months ago 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.

comment:6 Changed 8 months ago 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.

comment:7 Changed 8 months ago by Carlton Gibson

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 Changed 8 months ago 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.

comment:9 Changed 8 months ago by Carlton Gibson

Triage Stage: UnreviewedAccepted

comment:10 Changed 8 months ago 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.

Changed 8 months ago by Tom Forbes

Attachment: debug_last.log added

comment:11 Changed 8 months ago by Tom Forbes

Has patch: set

comment:12 Changed 8 months ago 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.

comment:13 Changed 8 months ago 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.

comment:14 Changed 8 months ago by Tom Forbes

Owner: changed from nobody to Tom Forbes
Status: newassigned

comment:15 Changed 8 months ago by felixxm

Triage Stage: AcceptedReady for checkin

comment:16 Changed 8 months ago by Mariusz Felisiak <felisiak.mariusz@…>

In b5259ab:

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

comment:17 Changed 8 months ago by Mariusz Felisiak <felisiak.mariusz@…>

In 0636d4d2:

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

comment:18 Changed 8 months ago by Mariusz Felisiak <felisiak.mariusz@…>

Resolution: fixed
Status: assignedclosed

In 6754bffa:

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

comment:19 Changed 8 months ago by 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

comment:20 Changed 8 months ago by Mariusz Felisiak <felisiak.mariusz@…>

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