File watcher problems on Mac

[gvanrossum]

Occasionally VS Code on Mac gets in a state for me where the mechanism used to update edit buffers when the on-disk file is modified stops working. The problem applies to all files, and it doesn't matter whether I have previously edited the file or not.

What I expect:

• I open a file in a VS Code buffer
• I change that file using a command line tool
• The changes are reflected in the VS Code edit buffer

What I see (once in this state):

• The changes aren't reflected in the VS Code edit buffer until I close and re-open the file

Once it is in this state it remains broken until I close and reopen the workspace.

I presume you are using some kind of file watcher daemon and the daemon dies. Maybe you can direct me to a window where I can find the logs to help you further debug this?

I don't know what triggers this -- I only observe it when I do a command line git operation like git checkout <file> that changes a file on disk.

I have auto-save on with a 100 msec delay.

I should mention that the workspace I tend to use (almost exclusively) is my checkout of the cpython repo, which is fairly large but not excessively so (5000 files under git control, and I have over 25,000 files total in that repo). My home directory is, let me say, rather much larger.

This is a Mac M3 running macOS Sonoma 14.4.1. In case it matters for the watcher, I am using a Dropbox client.

I'll gladly provide more information if you have subsequent questions, but it may take days before the problem pops up again.

[bpasero]

👋 thanks for reaching out on this issue. Yes, VS Code is using a 3rd party file watcher (https://github.com/parcel-bundler/watcher) that in the end will utilise fsevents APIs on macOS for file watching matters. The watcher itself runs in a separate process to isolate from other processes and there is 1 of these processes per window:

We do have some code in place to restart the watcher process if it happens to crash, but that is limited to a few times.

I suggest to start with providing the logs of VS Code, to see if the crash is reported in there. We have a command to open the logs folder for the current session:

If you go up 2 levels, it would be a logs folder containing the last 10 sessions. Could you share that with me? E-Mail is also fine: benjpas@microsoft.com

Thanks!

[stoefln]

What happened to chokidar? Was it replaced by parcel?

[bpasero]

Yes, already a long time ago, parcel replaced our 2 solutions (chokidar, nsfw).

[gvanrossum]

Hi @bpasero, I'm not much further, but I noticed something. I believe this also doesn't normally happening, but it started happening just now. (Still on Mac.) I have a file (Makefile) that is being regenerated by a script. Code is now in a state where when I have a window open on that file, and in a terminal window (also in Code) I run the regeneration script, the Makefile does not get refreshed. However, when I click in another app (e.g. my web browser, Firefox) and then back in Code, the Makefile window refreshes. How strange is that?

[bpasero]

@gvanrossum we do have logic in place to automatically reload the opened buffers as well as the file explorer when focus moves into the VS Code application, assuming that files might have changed as a result of the user using another application.

When you are in the state that a file does not refresh when its changed from the terminal, can you do this:

• open the command palette (Cmd+Shift+P) and select "Set Log Level" [1]
• pick "Trace"
• open the "Output" panel and pick the "File Watcher" channel [2]
• make a change in a buffer and observe file events getting reported, for example:

2024-04-30 07:33:34.008 [trace] [File Watcher (parcel)] [CHANGED] /Users/bpasero/Development/Microsoft/vscode/src/vs/workbench/services/history/browser/historyService.ts <4> 
2024-04-30 07:33:34.009 [trace] [File Watcher (parcel)] [CHANGED] /Users/bpasero/Development/Microsoft/vscode/src/vs/workbench/services/history/browser/historyService.ts
2024-04-30 07:33:34.087 [trace] [File Watcher (parcel)]  >> ignored (filtered) /Users/bpasero/Development/Microsoft/vscode/src/vs/workbench/services/history/browser/historyService.ts <4> 
2024-04-30 07:33:34.087 [trace] [File Watcher (parcel)]  >> normalized [CHANGED] /Users/bpasero/Development/Microsoft/vscode/src/vs/workbench/services/history/browser/historyService.ts

See if you get events reported for when Makefile changes. If you could please also test making changes in the buffer to see if maybe the terminal application changes it in a way that the fail to generate the file change event?

[1]

[2]

[gvanrossum]

Thanks -- it's still happening, I can trigger it by following the same procedure, I set the log level to Trace, but when I go to the Output window, there's no File watcher channel?!

[gvanrossum]

Also, when I try to edit the file in the buffer (before forcing a sync by going to another app and back) it refuses to do so, popping up an error box saying "Failed to save 'Makefile': The content of the file is newer." (Etc. -- I can send a screenshot but I imagine you know what error box I'm talking about and it's complicated for me to send screenshots here, as I don't have access to this tracker from the Mac where it's happening.)

[bpasero]

@gvanrossum sorry I forgot that the file watcher channel is something we only introduced in April and is not yet released to stable. With your version (which I assume is 1.89.0) after you have set the log level to trace, the output would appear from the "Window" channel:

As for the error you see when saving: that actually makes sense, given the issue at hand. When you save a buffer in VS Code we do a quick check if the file has changed on disk by comparing the mtime with the one we have in memory. If mtime advanced (which is the case for you when the file changed from the terminal), we tell the user and ask for review of the changes in the buffer vs. the changes on disk (see also our documentation on this topic).

To workaround this issue for now, it should be sufficient for you to close all instances of the buffer in VS Code and open it again and then try to make changes and save it. Re-opening the buffer should make sure to fetch latest from disk. Please then see if after saving there is anything logged to the "Window" output channel. It would contain a lot more than just file event related entries so please just send me the logs or copy it here.

Thanks!

[gvanrossum]

Okay, here's the log file. Ignore the events for files other than Makefile.
log.txt

[bpasero]

@gvanrossum interesting, so this seems relevant:

2024-05-01 07:05:32.928 [trace] [File Watcher (node.js)] [raw] ["change"] Makefile
2024-05-01 07:05:32.928 [trace] [File Watcher (node.js)] [CHANGED] /Users/guido/cpython/Makefile
2024-05-01 07:05:32.928 [trace] [File Watcher (node.js)]  >> ignored (not included) /Users/guido/cpython/Makefile

So our file watcher does detect the change, but decides to ignore it due to some rules that are in place for this watcher.

When this happens, are you in a VS Code window with a folder opened or is it an empty VS Code instance? And if a folder is opened, would that be /Users/guido/cpython or a different path?

I am curious how you end up with a watcher that is configured with this include rule because I think there is a bug in there. I suspect that it might be an extension that installs a file watcher (we have extension API for that) that triggers this (for example the Python extension itself). For that to confirm it would be helpful to:

• stop VSCode with the Makefile being the opened active buffer
• from the command line launch it code --verbose to immediately have the trace log information
• wait until VS Code has opened, extensions have activated and the buffer shows
• send me the entire "Window" log

This would include information about how file watchers are setup initially 🙏

[gvanrossum]

When this happens, are you in a VS Code window with a folder opened or is it an empty VS Code instance? And if a folder is opened, would that be /Users/guido/cpython or a different path?

The VS Code window is open on the cpython repo that you see. It may help to know that /Makefile is mentioned in the .gitignore (which is itself checked into the repo).

Here's the log you asked for:
log2.txt

[gvanrossum]

(Did you want the output from the Terminal window where I started code --verbose too?)

[bpasero]

Thank you, that is the log that is helpful:

2024-05-01 09:14:19.559 [trace] [File Watcher (parcel)] Request to start watching: /Users/guido/cpython (excludes: **/.git/objects/**,**/.git/subtree-cache/**,**/node_modules/*/**,**/.hg/store/**, includes: <all>, correlationId: <none>)
2024-05-01 09:14:19.563 [trace] [File Watcher (parcel)] Started watching: '/Users/guido/cpython' with backend 'fs-events'

This is a full, recursive, file watcher that uses macOS fsevents. It should have captured the changes to /Users/guido/cpython/Makefile. Even if the other one that I indicated in #210422 (comment) was ignored, this one should have triggered and then should have updated the opened buffer 😞.

Curious how you make changes to Makefile in the terminal, maybe that process involves some file system operations that make the watcher fail to recognise it in this case?

And then, if you could share me with a list of the extensions you have installed, then I can try to simulate in a similar setup on my machine to see if it reproduces for me.

[gvanrossum]

The Makefile is written by a script that does sed ... >Makefile, so that looks pretty vanilla. (EDIT: After that there's another thing that gets appended using >>Makefile.)

How do I send you the list of extensions? Does it help to know that this is an M3 Mac (so, ARM architecture)?

There is still something unexplained going on. I just quit VS Code using cmd-Q and then restarted it, and now all is well. Just before I did that, I learned that the problem is not limited to files mentioned in .gitignore -- I could reproduce it by opening Makefile.pre.in (which is under git control) in a buffer, made an edit to it, and ran git checkout in the Terminal, which should undo the changes I made. This was not picked up until I clicked in another app and then back in VS Code. But after the restart, behavior went back to normal/expected.

I think that earlier today as I was experimenting, I may have closed the VS Code window, but there might have been another window open, or there may have been a window-less "Application" instance still running -- I noticed that at some point I had a VS Code app with a truncated menu and no open windows.

In any case I suspect it won't be easy to reproduce this. :-(

[bpasero]

How do I send you the list of extensions? Does it help to know that this is an M3 Mac (so, ARM architecture)?

We miss a direct command to do so I believe, but here is what works easily:

• in VS Code: Help > Report Issue
• at the bottom there is a "Include my enabled extensions" with a "show" button (see [1])
• click "show" and select the contents of the table you see (see [2])
• copy the contents and paste it here

Does it help to know that this is an M3 Mac (so, ARM architecture)?

I think that should not make much of a difference, most of our team is using ARM by now and many of our users are likely as well.

There is still something unexplained going on...

Yeah, the fact that this issue does not reproduce after a clean restart will probably make it hard for me to reproduce easily. It seems to happen only after some time of usage.

Its interesting that this also reproduces using git checkout because that is a very typical operation that we run many times, even from the VS Code Git UI, not just terminal.

I think that earlier today as I was experimenting, I may have closed the VS Code window...

We do reserve 1 file watcher process per opened window, so in theory they should all be isolated from each other. If you close a window and open it again - even if VS Code was still running without window - you should see a fresh file watcher being created. The same is true for when you reload the active window ("Developer: Reload Window" in the command palette).

Once I get the list of extensions, I will investigate if any of your extensions triggers creation of file watchers, it may still be related.

[1]

[2]

[gvanrossum]

Okay, here are my extensions. Sorry about the formatting, I had to copy/paste between computers via a GMail draft.

copilot Git 1.186.0
copilot-chat Git 0.14.2024032901
language-cython guy 0.0.8
dotnet-interactive-vscode ms- 1.0.5229040
debugpy ms- 2024.4.0
python ms- 2024.4.1
vscode-pylance ms- 2024.4.1
jupyter ms- 2024.3.1
jupyter-keymap ms- 1.1.2
jupyter-renderers ms- 1.0.17
vscode-jupyter-cell-tags ms- 0.1.9
vscode-jupyter-slideshow ms- 0.1.6
remote-ssh ms- 0.110.1
remote-ssh-edit ms- 0.86.0
cpptools ms- 1.19.9
cpptools-extension-pack ms- 1.3.0
rst-vscode tht 3.0.1

We do reserve 1 file watcher process per opened window, so in theory they should all be isolated from each other. If you close a window and open it again - even if VS Code was still running without window - you should see a fresh file watcher being created. The same is true for when you reload the active window ("Developer: Reload Window" in the command palette).

I believe it -- and yet, I feel that the thing was reproducible across window close/reopen (e.g. you asked me to start from the command line using code --verbose and it still reproduced), but once I closed the app and reopened it was gone.

It hasn't come back yet -- alas, it may be several weeks before I see it again. Will keep you posted!

[bpasero]

Thanks, I now have a VS Code profile with the same set of extensions and the same repository (https://github.com/python/cpython) cloned to my user home folder. I can see the same output you reported, for when the buffer properly updates:

2024-05-07 21:21:50.443 [trace] [File Watcher (node.js)] [raw] ["change"] Makefile
2024-05-07 21:21:50.444 [trace] [File Watcher (node.js)] [CHANGED] /Users/bpasero/cpython/Makefile
2024-05-07 21:21:50.444 [trace] [File Watcher (node.js)]  >> ignored (not included) /Users/bpasero/cpython/Makefile
2024-05-07 21:21:50.453 [trace] [File Watcher (parcel)] [CHANGED] /Users/bpasero/cpython/Makefile
2024-05-07 21:21:50.533 [trace] [File Watcher (parcel)]  >> normalized [CHANGED] /Users/bpasero/cpython/Makefile

(the line [File Watcher (node.js)] >> ignored (not included can be ignored for this issue, its only an indication that we avoid sending 2 events instead of 1)

So at one point, for you, for some reason, the File Watcher (parcel) stops reporting events. I see Makefile being .gitignored, but for our file watcher that should not matter, we do not support git ignores for file watching (yet).

@gvanrossum curious, when this happens, are all buffers refusing to update when changes are made from the integrated terminal (for example change another file using VI from integrated terminal). Or is it really only the top level Makefile?

[gvanrossum]

curious, when this happens, are all buffers refusing to update when changes are made from the integrated terminal (for example change another file using VI from integrated terminal). Or is it really only the top level Makefile?

It's all files, AFAICT. I've definitely seen it happen to other files, files that were under git control. I think once it starts happening it happens to every buffer in ever window.

[bpasero]

Got it. Btw the cpython repository is quite large and probably produces build output files that you would never open in a buffer. We provide a setting files.watcherExclude that allows to add glob patterns that should not be file watched and is meant for large output folders:

I am not sure this would help in your case, but configuring this setting may improve things and reduce load from file watching in general for this folder in VS Code.

[gvanrossum]

I am not sure this would help in your case, but configuring this setting may improve things and reduce load from file watching in general for this folder in VS Code.

I am happy with the performance of the watcher except for the state where it enters this buggy state. I'd rather help you track down what gets it in that state than configure a workaround.

[brandonheyer]

I was having a similar issue, would get no refreshing at all, ever, unless I left the VSCode window and came back in. This issue helped to some degree. While I had no errors showing up in my trace logs for File Watcher, I did start adding some git-ignored directories to my files.watcherExclude" setting. I had several coverage report directories in my repository, and adding /coverage/` to be ignored seems to have fixed the issue entirely.

I was able to reproduce easily by mv some/directory/somewhere some/directory/elsewhere and would note that the Explorer didn't update. Once I switched window focus away and back, it would update the directory tree. After the chages, the mv command immediately results in the directory tree updating.