fs.watch says every single file in my folder changed, randomly

[voltuer]

• Version:
  10.5
• Platform:
  Windows 10

I have a development environment in which I use browserSync and Nodemon to accomplish automatic reloading of my client and server respetively. I recently migrated from macOS to Windows, and my setup worked fine in macOS, but now the pages reload randomly when I click something or just open the folder in Explorer.

I decided to dig a little deeper and make a separate script to watch the 'change' event and see what happens. To my surprise, it gets triggered with anything!. I'm guess it's something to do with Windows marking files as "last accessed" or something like that, but the contents aren't changing so this shouldn't happen!

Here's my script:

fs=require('fs')
fs.watch('dev/elder', {recursive:true}, (eventType, filename) => {
  if (eventType === 'change') console.log(filename, 'changed.');
});

Here's a sample output:

dev\elder\app\directives\mapaTematicoField\template.html changed.
dev\elder\app\directives\selectField\template.html changed.
dev\elder\app\directives\popup\assets changed.
dev\elder\app\directives\textField\style.css changed.
dev\elder\app\directives\mapaTematico\assets changed.
dev\elder\app\directives\mapaTematico\controllers changed.
dev\elder\app\directives\mapaTematico\interactivo.html changed.
dev\elder\app\directives\sideTabsOrganizaciones\assets changed.
dev\elder\app\directives\toggler\assets changed.
dev\elder\app\directives\filePreview\assets changed.
dev\elder\app\directives\filePreview\template.html changed.
dev\elder\app\directives\datePicker\assets\angular-moment-picker.min.css changed.
dev\elder\app\directives\colorPicker\assets\colorpicker.css changed.
dev\elder\app\directives\mapaTematicoField\assets\descriptores.css changed.
dev\elder\app\directives\multiSelect\assets\ms.css changed.
dev\elder\app\directives\fileUploader\assets\dropzone.css changed.
dev\elder\app\directives\fileUploader\assets\fileUploader.css changed.
dev\elder\app\directives\popup\assets\popup.css changed.
dev\elder\app\directives\autoCompleter\assets\css changed.

[bzoz]

Cannot reproduce.

Can you provide specific Windows version that you are using? Do you have any AV software running?

[voltuer]

Can you please try creating an entire new project with something like angular generator, then rebooting and using my watch script on that folder, and opening the folder in Windows Explorer?

That should trigger it.

My Windows version is 10.0.17134.112 and no Antivurs whatsoever

[bzoz]

I still can't reproduce.

I've followed this guide, made sample app, rebooted, and started the app (which made your script print quite some "... changed" messages). Accessing the files by opening them in notepad or browsing through the folders in Explorer does not trigger the message.

Does this also happen with folders not generated by some app generator? Under the hood, Node just uses ReadDirectoryChangesW with very little extra logic. If those files are getting reported, then something is accessing them somehow. If you feel like it, you can try commenting out some of the "watch options" in https://github.com/nodejs/node/blob/v10.5.0/deps/uv/src/win/fs-event.c#L47-L54, rebuild Node and see if it still reproduces.

[voltuer]

@bzoz thanks for doing such a thorough test. I rebooted in Safe Mode just in case, and the issue still persists.

If you can, please try with a moderately big project (at least 5 folders and a 3rd level depth on some of them, with actual files) and open some of them in Windows Explorer while the watch script is running.

In my computer, the "change" event triggers with simply opening folders in Windows Explorer, I just checked if any date changed but none of them is current (creation date, last accessed, modification date, and something called just "date"), judging by the enablable columns in detail view.

[voltuer]

@bzoz fyi, i just found a PowerShell script to watch the folder at the same time than the nodejs's fs.watch script and the results are quite interesting. It only shows actual changes to files (made by myself using a text editor)

### SET FOLDER TO WATCH + FILES TO WATCH + SUBFOLDERS YES/NO
    $watcher = New-Object System.IO.FileSystemWatcher
    $watcher.Path = "C:\Users\Seb\dev\elder"
    $watcher.Filter = "*.*"
    $watcher.IncludeSubdirectories = $true
    $watcher.EnableRaisingEvents = $true  

### DEFINE ACTIONS AFTER AN EVENT IS DETECTED
    $action = { $path = $Event.SourceEventArgs.FullPath
                $changeType = $Event.SourceEventArgs.ChangeType
                $logline = "$(Get-Date), $changeType, $path"
                Add-content "D:\log.txt" -value $logline
              }    
### DECIDE WHICH EVENTS SHOULD BE WATCHED 
    Register-ObjectEvent $watcher "Created" -Action $action
    Register-ObjectEvent $watcher "Changed" -Action $action
    Register-ObjectEvent $watcher "Deleted" -Action $action
    Register-ObjectEvent $watcher "Renamed" -Action $action
    while ($true) {sleep 5}

This is what each console showed at the exact time when I created the "hola" file and renamed it to "wapa":

PowerShell script:

tail -f /d/log.txt
07/04/2018 17:42:52, Created, C:\Users\Seb\dev\elder\.git\modules\app\index.lock
07/04/2018 17:42:52, Deleted, C:\Users\Seb\dev\elder\.git\modules\app\index.lock
07/04/2018 17:45:27, Deleted, C:\Users\Seb\dev\elder\.git\modules\launcher\core\index.lock
07/04/2018 17:45:27, Changed, C:\Users\Seb\dev\elder\hola
07/04/2018 17:45:27, Changed, C:\Users\Seb\dev\elder\.git\modules\app
07/04/2018 17:46:33, Renamed, C:\Users\Seb\dev\elder\wapa
07/04/2018 17:46:33, Changed, C:\Users\Seb\dev\elder\.git\modules\app

NodeJS fs.watch (trimmed, because it pretty much showed the entire folder tree):

node_modules\union-value\node_modules changed
node_modules\unset-value\node_modules changed
node_modules\vinyl-fs changed
node_modules\vinyl-fs\lib changed
node_modules\vinyl-fs\node_modules changed
node_modules\websocket-extensions\lib changed
node_modules\which changed
node_modules\yargs changed
node_modules\yargs-parser changed
hola changed
.git changed
.git\modules\app changed
.git\modules\launcher\core changed
.git changed
wapa changed
.git changed
.git\modules\app changed
.git\modules\launcher\core changed
.git changed

[bzoz]

Are you 100% sure you do not have any extension (or maybe malware) that accesses this files? Normally, when you write something to a file you get two notifications - one for file content change and one for attributes (mtime) change. You are getting only one, so most likely something is messing with attributes.

What we could do is try with Python: in http://timgolden.me.uk/python/win32_how_do_i/watch_directory_for_changes.html at the very bottom there is ReadDirectoryChanges exapmle. It uses the same WinAPI as Node for this. Can you try to reproduce using this script? Can you also try disabling some FILE_NOTIFY_CHANGE_* flags to see what changes exactly are causing those files to be reported?

[voltuer]

@bzoz I just checked with that script and it works perfectly fine, here's an screenshot of both scripts workingat the same time, while creating and renaming "hola" to "wapa". As you can see, in Python it works fine as intended, as it also does in PowerShell, but Node's fs.watch is working absurdly wrong.

Top window is my NodeJS script, bottom window is the Python script you linked. As I told you, I also tested on Safe Mode so it's not an external problem.

PS: I want to add that I browsed the folders with Windows Explorer while running the script,, in order to trigger fs.watch's bug (which also gets triggered with Node's fs.fileReadSync which is the core of the problem)

[lundibundi]

Just a random passerby. In libuv as @bzoz pointed out there is this, which notes that libuv listens to FILE_NOTIFY_CHANGE_LAST_ACCESS and moreso, it will be repoted as change (doc see FILE_ACTION_MODIFIED) which leads us to the fact that probably your directory timestamps somehow change.
As to why this is strange - it is because starting from windows vista and up (in win 10 as well) last access timestamps are disabled by default. So I'd recommend you do one of the following to prove or disprove my point (first one should be easier):

• Try to change your settings and manually disable access time changes (smth like this tutorial or any else, basically fsutil behavior set disablelastaccess 1) and then trying to test the problem. Because maybe some program have changed this behavior (some backup or security programs may need this).
• Removing FILE_NOTIFY_CHANGE_LAST_ACCESS from https://github.com/nodejs/node/blob/v10.5.0/deps/uv/src/win/fs-event.c#L47-L54 and https://github.com/nodejs/node/blob/v10.5.0/deps/uv/src/win/fs-event.c#L291 in node and then recompiling node and trying to test the bug.
• You may also try to add analogue of FILE_NOTIFY_CHANGE_LAST_ACCESS to that python script, that may indicate that it is the problem, but I don't know if it is present there, though it should be.

But indeed it would probably it be better if there was 2 events for change (contents and timestamp), though based on win api docs there is no way to differentiate those, so maybe ability to specify what to watch for (this may only me a intersection of supported features across the OSs, but it shouldn't be that hard to implement, though I'm not familiar with libuv codebase so I cannot be sure)?

[voltuer]

Thanks, @lundibundi, that fixed the problem for good. ❤

fsutil behavior set disablelastaccess 1

[blaine]

For the record, this is affecting me on Windows (in the Linux subsystem), and the disablelastaccess change isn't helping. I'm going to try with the native Windows node, but it's a little tricky to do so. I don't really see why node is monitoring for accessed files at all, particularly when that is not the behaviour on Linux.