nodemon: Bug report: Execution option run twice instead of one

You got it! It doesn’t happen with v4.2.3 LTS.

However, I dug a bit deeper and found out that it might have to do something with the kqueue filesystem event system. Why? I used fswatch (https://github.com/emcrisostomo/fswatch) which allows to observe file changes and to choose different ways to do so depending on the OS you are running. On OS X, it’s FSevents, kqueue and polling. I used these steps to reproduce this nodemon issue’s behavior exactly with fswatch:

fswatch -o foo.js will print “1” and a newline for each detected change event.

So I piped this to xargs and called date to get a timestamp for each event:

macy:testdir jens$ fswatch -o foo.js | xargs -P8 -I'{}' -n1 date
Fri Dec  4 11:31:26 CET 2015
Fri Dec  4 11:31:30 CET 2015
Fri Dec  4 11:31:34 CET 2015

Okay, I saved it 3 times in 4 seconds intervals. That’s what I did, no problem here.

On OS X, fswatch uses FSEvents as default monitor. Now let’s change this to polling:

macy:testdir jens$ fswatch --monitor=poll_monitor -o foo.js | xargs -P8 -I'{}' -n1 date
Fri Dec  4 11:40:46 CET 2015
Fri Dec  4 11:40:50 CET 2015
Fri Dec  4 11:40:54 CET 2015

Again, the output shows exactly what I did. No problem here, too.

Now let’s see what using kqueue as monitor will result in:

macy:testdir jens$ fswatch --monitor=kqueue_monitor -o foo.js | xargs -P8 -I'{}' -n1 date
Fri Dec  4 11:43:11 CET 2015 <-- file saved here
Fri Dec  4 11:43:11 CET 2015
Fri Dec  4 11:43:12 CET 2015
Fri Dec  4 11:43:14 CET 2015 <-- file saved here
Fri Dec  4 11:43:14 CET 2015
Fri Dec  4 11:43:15 CET 2015
Fri Dec  4 11:43:17 CET 2015 <-- file saved here
Fri Dec  4 11:43:17 CET 2015
Fri Dec  4 11:43:18 CET 2015

Whoops, there we go! I modified the file at second 11, 14 and 17 but we got 9 events from that monitor.

Now I wanted to see the timestamp of those events in a more detailed resolution but I couldn’t find a way to see milliseconds using the OS X’s date tool. So I created my own unix timestamp tool:

// this is getTimestamp.c
#include <stdio.h>
#include <sys/time.h>

int main(void) {
    struct timeval time;
    gettimeofday(&time, NULL);
    printf("%lds %03ums %03uus\r\n", time.tv_sec,
        time.tv_usec/1000, time.tv_usec-time.tv_usec/1000*1000);
    return 0;
}

Compile with gcc getTimestamp.c -o getTimestamp It tells us the current time as Unix time including milliseconds and microseconds:

macy:testdir jens$ ./getTimestamp 
1449222463s 216ms 388us
macy:testdir jens$ 

Now, let’s use this with fswatch and the kqueue monitor:

macy:testdir jens$ fswatch --monitor=kqueue_monitor -o foo.js | xargs -P8 -I'{}' -n1 getTimestamp
1449226110s 019ms 329us <-- file saved here
1449226110s 019ms 972us
1449226111s 060ms 956us
1449226114s 082ms 690us <-- file saved here
1449226114s 083ms 394us
1449226115s 286ms 731us
1449226118s 755ms 309us <-- file saved here
1449226118s 755ms 928us
1449226119s 960ms 446us

There we have a nice timing sequence of the events. The annoying ‘ghost’-event comes twice. First within less than 1 millisecond and then again after a second. The latter one is what we notice here with nodemon regularly. The first one is so fast, that it appears only sometimes affects nodemon sometimes but not always and not for everyone . This fits 100% to my nodemon behavior with Node.js 5.

Paradoxically, according to the documentation, Node 4.2.3 as well as 5.1.1 are using kqueue for files on OS X: https://nodejs.org/docs/v5.1.1/api/fs.html#fs_availability https://nodejs.org/docs/v4.2.3/api/fs.html#fs_availability

This might be a single symptom with multiple roots. Of course, the backup-file by Vim users is another root and maybe there are more. But looks like I can’t proof kqueue is a root, even if that’s the case for fswatch. Maybe the Node.js docs for 5.1.1 are not correct?