Weird "change" event firing in parent directory of renamed file

[rkyoku]

I am using Windows 7 64b.

Let's say I am watching the "dir1" directory. Inside, I have "dir2", "file1.txt". Inside "dir2" I have "file2.txt".

Whenever I rename "file2.txt" (is it possible to get a "renamed" event btw?), I get a "change" event on "file1.txt", don't know why.

Here is my test log (I am recursively watching the "./data" directory):
[Chokidar] add data\Nouveau document texte.txt // created a file
[Chokidar] add data\test2.txt // renamed
[Chokidar] unlink data\Nouveau document texte.txt // renamed to test2.txt, actually
[Chokidar] change data\blablabla.txt // weird event
[Chokidar] add data\bla\toto222.txt // renamed
[Chokidar] unlink data\bla\toto.txt // renamed to toto222.txt, actually
[Chokidar] change data\blablabla.txt // weird event
[Chokidar] add data\bla\tutu123.txt // renamed
[Chokidar] unlink data\bla\tutu.txt // renamed to tutu123.txt, actually
[Chokidar] change data\bla\toto222.txt // again another weird event
[Chokidar] add data\bla\toto\Nouveau document texte.txt // created a file
[Chokidar] change data\bla\toto222.txt // again another weird event
[Chokidar] add data\bla\toto\test3.txt // renamed
[Chokidar] unlink data\bla\toto\Nouveau document texte.txt // renamed to test3.txt, actually

[senritsu]

Can confirm this issue and expand on the conditions under which it appears.

Given a folder structure of what/ever/else/Foo/Bar/

Condition 1: Anything inside a folder (for example Bar) is changed, no matter if it is a file change, a new folder is added, a file or folder is deleted, etc.

Condition 2: There exists a file in the parent folder (in this example Foo) whose name starts with the name of the subfolder (for example Foo/Barbarian.js or Foo/BarberQuartet.js)

Effect: Whenever chokidar encounters condition 1, it also fires a change event for all items matching condition 2.

So any change inside the folder
what/ever/else/Foo/Bar/
results in change events for all files matching
what/ever/else/Foo/Bar.**

[es128]

Can you please provide the output from listening to the raw event?

[senritsu]

with a file structure of

Scripts/Page/globalization.coffee
Scripts/page.js

The watcher used for the output:

watcher = chokidar.watch './Scripts/**/*.js'
watcher.on 'raw', (event, file, details) ->
    console.log event
    console.log file
    console.log details

A save of page.js in visual studio results in the following output from a raw event listener:

rename
fogomc2k.fqa~
{ watchedPath: 'Scripts' }
change
fogomc2k.fqa~
{ watchedPath: 'Scripts' }
change
fogomc2k.fqa~
{ watchedPath: 'Scripts' }
rename
page.js~RF5860c46.TMP
{ watchedPath: 'Scripts' }
rename
null
{ watchedPath: 'Scripts' }
change
page.js~RF5860c46.TMP
{ watchedPath: 'Scripts' }
rename
null
{ watchedPath: 'Scripts' }
rename
page.js
{ watchedPath: 'Scripts' }
change
page.js
{ watchedPath: 'Scripts' }
rename
null
{ watchedPath: 'Scripts' }
rename
page.js
{ watchedPath: 'Scripts\\page.js' }
rename
page.js
{ watchedPath: 'Scripts\\page.js' }
change
page.js
{ watchedPath: 'Scripts\\page.js' }

A save of Page/globalization.coffee results in the following output:

rename
05cd4tvp.2dm~
{ watchedPath: 'Scripts\\Page' }
change
Page
{ watchedPath: 'Scripts' }
change
page.js
{ watchedPath: 'Scripts\\page.js' }
change
05cd4tvp.2dm~
{ watchedPath: 'Scripts\\Page' }
change
05cd4tvp.2dm~
{ watchedPath: 'Scripts\\Page' }
rename
globalization.coffee~RF586b25a.TMP
{ watchedPath: 'Scripts\\Page' }
rename
null
{ watchedPath: 'Scripts\\Page' }
change
globalization.coffee~RF586b25a.TMP
{ watchedPath: 'Scripts\\Page' }
rename
null
{ watchedPath: 'Scripts\\Page' }
rename
globalization.coffee
{ watchedPath: 'Scripts\\Page' }
change
globalization.coffee
{ watchedPath: 'Scripts\\Page' }
rename
null
{ watchedPath: 'Scripts\\Page' }
change
Page
{ watchedPath: 'Scripts' }
change
Page
{ watchedPath: 'Scripts' }
change
page.js
{ watchedPath: 'Scripts\\page.js' }
change
page.js
{ watchedPath: 'Scripts\\page.js' }
change
Page
{ watchedPath: 'Scripts' }
change
page.js
{ watchedPath: 'Scripts\\page.js' }

[es128]

As you can see, the file system is emitting change events for Scripts\page.js even though you did not (deliberately) touch it. It seems there is an issue somewhere deeper than chokidar, and unless someone else has any ideas, I don't see how chokidar could effectively second-guess the system-level events in order to make adjustments that fix this problem.

[senritsu]

Any ideas where the issue could come from? I am asking from a background of not knowing much about the internals of chokidar, how much of node's fs module it uses, etc.

Would it be possible the bug is on nodes side? Or does it seem more likely it is farther on the OS side of things?

[es128]

For windows chokidar relies on node's fs.watch and just does things to try to smooth out its rough edges (the raw output is what fs.watch is reporting).

The bug could be either in node or lower down in the system API it uses, but it would be worth reporting to node if it could be demonstrated with a simple script that only uses fs.watch() (i.e. cut out chokidar to show output similar to the above from the raw event output).

[es128]

See if setting usePolling: true makes it any better.

[senritsu]

I did a small synthetic test, and could reproduce the issue, both for chokidar and for fs.watch

Anytime a new file was added or removed from the folder Foo, a change event for the file foobar.js was sent as well. Some times (not everytime though) the same behaviour happened for changes to the file using notepad, which contrasts a bit to our problem in visual studio. In VS every change resulted in the buggy behaviour. This might be due to the mechanics VS employs while saving a file, maybe some temp file copying or similar.

Another thing to note is that usePolling: true did seem to work correctly.

Here is the output when adding, changing, changing again, and deleting a new file in Foo.

[10:12:49] fs.watch (folder)  >>> Foo
[10:12:49] fs.watch (file)    >>> foobar.js
[10:12:49] chokidar           >>> TestRoot\foobar.js
[10:12:55] chokidar           >>> TestRoot\Foo\New Text Document.txt
[10:12:55] chokidar (polling) >>> TestRoot\Foo\New Text Document.txt
[10:12:59] chokidar           >>> TestRoot\Foo\New Text Document.txt
[10:12:59] chokidar (polling) >>> TestRoot\Foo\New Text Document.txt
[10:13:08] fs.watch (folder)  >>> Foo
[10:13:08] fs.watch (file)    >>> foobar.js
[10:13:08] chokidar           >>> TestRoot\foobar.js

code below

var chokidar = require('chokidar');
var fs = require('fs');

function zerofill(i){
  return (i < 10 ? '0' : '') + i;
}

function timestamp() {
  var now = new Date();
  return '[' + zerofill(now.getHours()) + ':' + zerofill(now.getMinutes()) + ':' + zerofill(now.getSeconds()) + ']'
}

var watcher = chokidar.watch('./TestRoot/**/*');
watcher.on('change',function(file){console.log(timestamp() + ' chokidar           >>> ' + file);})

watcher = chokidar.watch('./TestRoot/**/*', {usePolling:true});
watcher.on('change',function(file){console.log(timestamp() + ' chokidar (polling) >>> ' + file);})

fs.watch('./TestRoot/', {recursive:true}, function(event, filename){
  if (event === 'change') {
    console.log(timestamp() + ' fs.watch (folder)  >>> ' + filename);
  }
});

fs.watch('./TestRoot/foobar.js', function(event, filename){
  if (event === 'change') {
    console.log(timestamp() + ' fs.watch (file)    >>> ' + filename);
  }
});

[es128]

This phenomenon appears to be caused deeper at the system level. There's no bug in chokidar, nor anything that could be done at this level to correct it. Closing

[wc-matteo]

I have the same issue. Also fixed by using polling.
Could it be related to this?