Opened 4 years ago

Closed 4 years ago

Last modified 3 years ago

#31900 closed Bug (worksforme)

Reloader using watchman initiates reloads despite no file changed

Reported by: Julien Chol Owned by: nobody
Component: Utilities Version: 3.1
Severity: Normal Keywords: reloader watchman
Cc: Tom Forbes Triage Stage: Unreviewed
Has patch: no Needs documentation: no
Needs tests: no Patch needs improvement: no
Easy pickings: no UI/UX: no

Description

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

Attachments (3)

Dockerfile (1.4 KB ) - added by Julien Chol 4 years ago.
Dockerfile for test build
traceback.zip (31.4 KB ) - added by Julien Chol 4 years ago.
Full traceback with logs activated
20200905_traceback.zip (28.9 KB ) - added by Julien Chol 4 years ago.

Download all attachments as: .zip

Change History (11)

by Julien Chol, 4 years ago

Attachment: Dockerfile added

Dockerfile for test build

by Julien Chol, 4 years ago

Attachment: traceback.zip added

Full traceback with logs activated

comment:1 by Mariusz Felisiak, 4 years ago

Cc: Tom Forbes added

comment:2 by Carlton Gibson, 4 years ago

Resolution: worksforme
Status: newclosed

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.

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

in reply to:  2 comment:3 by Julien Chol, 4 years ago

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?

comment:4 by Carlton Gibson, 4 years ago

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…

comment:5 by Tom Forbes, 4 years ago

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.

by Julien Chol, 4 years ago

Attachment: 20200905_traceback.zip added

comment:6 by Julien Chol, 4 years ago

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.

Version 0, edited 4 years ago by Julien Chol (next)

comment:7 by James Addison, 3 years ago

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

Last edited 3 years ago by James Addison (previous) (diff)

comment:8 by James Addison, 3 years ago

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.

Last edited 3 years ago by James Addison (previous) (diff)
Note: See TracTickets for help on using tickets.
Back to Top