Reloader using watchman initiates reloads despite no file changed

[Julien Chol]

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

[Julien Chol]

Dockerfile for test build

[Julien Chol]

Full traceback with logs activated

[Carlton Gibson]

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, or else an issue with watchman+docker.

Very happy to re-open if we can demonstrate an issue in Django.

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

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

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

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

[James Addison]

@Julien - I ran into this issue as well running Django 3.1.x in a docker container (python3.6-slim, which is Debian-based, I believe). I set up my .watchmanconfig file with the following (note the "/" at the beginning of the array):

{
    "ignore_dirs": ["/", "node_modules", ".envs", "bin", "lib", "include", ".git", ".idea", ".venv", "venv", "dockerdata"]
}

Seemed to address the issue with the most recent Watchman build for me.

Ignore the above, it did not work.

[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? I think this is a non-issue, after installing Watchman 4.9.0, Django still collects the same roots (this step doesn't involve Watchman, obviously) , but the autoreloading works as expected with 4.9.0.