[Django] #31900: Reloader using watchman initiates reloads despite no file changed
Django
---------------------------------------+-----------------------------------
Reporter: Julien Chol | Owner: nobody
Type: Bug | Status: new
Component: Utilities | Version: 3.1
Severity: Normal | Keywords: reloader watchman
Triage Stage: Unreviewed | Has patch: 0
Needs documentation: 0 | Needs tests: 0
Patch needs improvement: 0 | Easy pickings: 0
UI/UX: 0 |
---------------------------------------+-----------------------------------
While running runserver with watchman, reloader would initiate a server
reload after only a few requests, even without any file modified.
On my main project, it would actually restart after every request,
defeating completely the purpose of watchman.
This bug can be reproduced on a fresh install. It affects versions 2.2.15
and 3.1. I haven't tested other releases.
For convenience, I made a Docker image installing Django, watchman and
pywatchman according to the docs. Docker file is attached.
To experience the bug run `docker run -p 8000:8000 chelou/debug-
watchman:latest`, then visit [http://localhost:8000] and refresh a few
times.
You should then see a server reload being fired, as per the following
output:
{{{
Watching for file changes with WatchmanReloader
Performing system checks...
System check identified no issues (0 silenced).
You have 18 unapplied migration(s). Your project may not work properly
until you apply the migrations for app(s): admin, auth, contenttypes,
sessions.
Run 'python manage.py migrate' to apply them.
August 18, 2020 - 15:16:12
Django version 3.1, using settings 'debug_watchman.settings'
Starting development server at http://0.0.0.0:8000/
Quit the server with CONTROL-C.
[18/Aug/2020 15:16:23] "GET / HTTP/1.1" 200 16351
[18/Aug/2020 15:16:23] "GET /static/admin/css/fonts.css HTTP/1.1" 304 0
[18/Aug/2020 15:16:25] "GET / HTTP/1.1" 200 16351
[18/Aug/2020 15:16:25] "GET /static/admin/css/fonts.css HTTP/1.1" 304 0
[18/Aug/2020 15:16:37] "GET / HTTP/1.1" 200 16351
[18/Aug/2020 15:16:37] "GET /static/admin/css/fonts.css HTTP/1.1" 304 0
[18/Aug/2020 15:16:39] "GET / HTTP/1.1" 200 16351
[18/Aug/2020 15:16:39] "GET /static/admin/css/fonts.css HTTP/1.1" 304 0
[18/Aug/2020 15:16:44] "GET / HTTP/1.1" 200 16351
[18/Aug/2020 15:16:44] "GET /static/admin/css/fonts.css HTTP/1.1" 304 0
[18/Aug/2020 15:16:45] "GET / HTTP/1.1" 200 16351
[18/Aug/2020 15:16:45] "GET /static/admin/css/fonts.css HTTP/1.1" 304 0
[18/Aug/2020 15:16:46] "GET / HTTP/1.1" 200 16351
[18/Aug/2020 15:16:47] "GET /static/admin/css/fonts.css HTTP/1.1" 304 0
[18/Aug/2020 15:16:54] "GET / HTTP/1.1" 200 16351
[18/Aug/2020 15:16:55] "GET /static/admin/css/fonts.css HTTP/1.1" 304 0
[18/Aug/2020 15:16:55] "GET / HTTP/1.1" 200 16351
[18/Aug/2020 15:16:56] "GET /static/admin/css/fonts.css HTTP/1.1" 304 0
[18/Aug/2020 15:16:56] "GET / HTTP/1.1" 200 16351
[18/Aug/2020 15:16:57] "GET /static/admin/css/fonts.css HTTP/1.1" 304 0
[18/Aug/2020 15:16:58] "GET / HTTP/1.1" 200 16351
[18/Aug/2020 15:16:58] "GET /static/admin/css/fonts.css HTTP/1.1" 304 0
[18/Aug/2020 15:16:59] "GET / HTTP/1.1" 200 16351
[18/Aug/2020 15:16:59] "GET /static/admin/css/fonts.css HTTP/1.1" 304 0
[18/Aug/2020 15:17:07] "GET / HTTP/1.1" 200 16351
[18/Aug/2020 15:17:07] "GET /static/admin/css/fonts.css HTTP/1.1" 304 0
[18/Aug/2020 15:17:08] "GET / HTTP/1.1" 200 16351
[18/Aug/2020 15:17:08] "GET /static/admin/css/fonts.css HTTP/1.1" 304 0
[18/Aug/2020 15:17:09] "GET / HTTP/1.1" 200 16351
[18/Aug/2020 15:17:10] "GET /static/admin/css/fonts.css HTTP/1.1" 304 0
[18/Aug/2020 15:17:10] "GET / HTTP/1.1" 200 16351
[18/Aug/2020 15:17:10] "GET /static/admin/css/fonts.css HTTP/1.1" 304 0
/usr/local/lib/python3.7/sqlite3/dbapi2.py changed, reloading.
Watching for file changes with WatchmanReloader
Performing system checks...
System check identified no issues (0 silenced).
You have 18 unapplied migration(s). Your project may not work properly
until you apply the migrations for app(s): admin, auth, contenttypes,
sessions.
Run 'python manage.py migrate' to apply them.
August 18, 2020 - 15:17:13
Django version 3.1, using settings 'debug_watchman.settings'
Starting development server at http://0.0.0.0:8000/
Quit the server with CONTROL-C.
}}}
The full traceback is provided as attachment. It can be reproduced by
using the following command `docker run -p 8000:8000 --env LOG=1 chelou
/debug-watchman:latest`
I have noticed that this problem seems to affect only files in
`/usr/local/lib/python3.7/`, not actual project files.
To ensure that the bug was not linked to `inotify` limits, I have set
`fs.inotify.max_user_instances` `fs.inotify.max_user_watches`
`fs.inotify.max_queued_events` to `1000000`
`pywatchman` version is `1.4.1` and `watchman` version is `2020.08.17.00`
--
Ticket URL: <https://code.djangoproject.com/ticket/31900>
Django <https://code.djangoproject.com/>
The Web framework for perfectionists with deadlines.
Django
Reporter: Julien Chol | Owner: nobody
Type: Bug | Status: new
Component: Utilities | Version: 3.1
Keywords: reloader watchman | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Julien Chol):
* Attachment "Dockerfile" added.
Dockerfile for test build
Django
Reporter: Julien Chol | Owner: nobody
Type: Bug | Status: new
Component: Utilities | Version: 3.1
Keywords: reloader watchman | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Julien Chol):
* Attachment "traceback.zip" added.
Full traceback with logs activated
Django
Reporter: Julien Chol | Owner: nobody
Type: Bug | Status: new
Component: Utilities | Version: 3.1
Keywords: reloader watchman | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by felixxm):
* cc: Tom Forbes (added)
--
Ticket URL: <https://code.djangoproject.com/ticket/31900#comment:1>
Django
Reporter: Julien Chol | Owner: nobody
Component: Utilities | Version: 3.1
Severity: Normal | Resolution: worksforme
Keywords: reloader watchman | 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):
* status: new => closed
* resolution: => worksforme
Comment:
Hi sorry, I can't reproduce this.
I rebuild from your Dockefile and run without any issue.
I strongly suspect this is some Docker config issue.
Very happy to re-open if we can demonstrate an issue in Django.
--
Ticket URL: <https://code.djangoproject.com/ticket/31900#comment:2>
Django
Reporter: Julien Chol | Owner: nobody
Component: Utilities | Version: 3.1
Severity: Normal | Resolution: worksforme
Keywords: reloader watchman | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Julien Chol):
Thanks for looking into the issue. I'm not an expert in either Docker or
Watchman, so I tried to narrow down the issue.
Basically, I have been able to reproduce the issue 100% of the time in
vanilla Debian stable and Ubuntu 20.04 LTS.
To run my tests, I have been using standard images from Digital Ocean (as
a matter of convenience). I assume those droplets run on Docker, but that
the best I could get my hands on. I have then followed the exact steps of
my initial Docker file, installing python packages in venv.
I am able to reliably reproduce the unexpected server reload in the
following context:
* Only occurs when running `python manage.py runserver` as non-root. I
have not been able to reproduce it as root,
* Files found as changed seems to belong to python system folders, such as
`/usr/lib/python3.X` or `/etc/python3.X`. Somehow
`/etc/python3.X/sitecustomize.py` is often shown as changed.
* Somehow files in `venv` or project folder are never found as changed
(but it could be linked to change verification order).
* To reliably reproduce the reload, I would run `for i in {1..10}; do curl
--silent http://localhost:8000/ > /dev/null; done` multiple times, with a
small pause between runs.
I cannot confirm if it is a Django issue. But as I am able to reproduce
the issue on vanilla Debian and Ubuntu, I'd be happy to dig further to
identify the core issue.
Would you have any pointer on where to look for?
--
Ticket URL: <https://code.djangoproject.com/ticket/31900#comment:3>
Django
Reporter: Julien Chol | Owner: nobody
Component: Utilities | Version: 3.1
Severity: Normal | Resolution: worksforme
Keywords: reloader watchman | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Carlton Gibson):
Hi Julian.
Thanks for the follow-up. Good hustle.
I’ll leave closed for now, otherwise we’ll just reopen in order to close
as Needs Info next week.
Happy to re-open if we can see that it’s an issue with Django.
I see Tom, who’s the most knowledgable here, is already CC-d, so maybe
he’ll have guidance…
--
Ticket URL: <https://code.djangoproject.com/ticket/31900#comment:4>
Django
Reporter: Julien Chol | Owner: nobody
Component: Utilities | Version: 3.1
Severity: Normal | Resolution: worksforme
Keywords: reloader watchman | 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):
Thanks for the extra information Julien!
Would it be possible for you to trigger this whilst having the
“django.utils.autoreload” logger set your “DEBUG”? The output from this
will include key details that can help me debut this. It’s quite possible
that there’s an issue relating to a newer watchman release - they’ve been
pumping out releases quite fast.
Sorry about not replying before, my open source time has been constrained
to near 0 recently. If you provide the logs I can put aside some time to
dig into them.
--
Ticket URL: <https://code.djangoproject.com/ticket/31900#comment:5>
Django
Reporter: Julien Chol | Owner: nobody
Component: Utilities | Version: 3.1
Severity: Normal | Resolution: worksforme
Keywords: reloader watchman | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Julien Chol):
* Attachment "20200905_traceback.zip" added.
Django
Reporter: Julien Chol | Owner: nobody
Component: Utilities | Version: 3.1
Severity: Normal | Resolution: worksforme
Keywords: reloader watchman | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Julien Chol):
Thanks Carlton and Tom for the feedback.
I attached traceback with DEBUG ON on file `20200905_traceback.zip`.
I have also explored the pointer regarding versions. I have been able to
reproduce the issue with the "oldest newer version" with binaries aka
`v2020.07.13.00`.
But I could not reproduce the bug when compiling and installing `v4.9.0`
from source.
An easy fix for anyone encountering this issue could thus be to stick to
`v4.9.0`.
--
Ticket URL: <https://code.djangoproject.com/ticket/31900#comment:6>
Django
Reporter: Julien Chol | Owner: nobody
Component: Utilities | Version: 3.1
Severity: Normal | Resolution: worksforme
Keywords: reloader watchman | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by James Addison):
Linking to issue filed on Watchman:
https://github.com/facebook/watchman/issues/865 with more details.
I will note that Django does, for some reason, add these non-project
directories as watchman 'roots' - I'm not sure why?
--
Ticket URL: <https://code.djangoproject.com/ticket/31900#comment:8>