Skip to content

Change events only fire once #33

Closed
hbmartin opened this Issue Feb 11, 2013 · 31 comments
@hbmartin

I'm having a problem change events are only fired once for a given file. I'm running node v0.8.9 on Mac OS X 10.8 Mountain Lion.
Here's sample output from the included example script:
watching everything completed
a log message occured: { '0': 'debug',
'1': 'watch event triggered on ui-resizable.css:',
'2': [ 'change', null ] }
a log message occured: { '0': 'debug',
'1': 'determined update:',
'2': 'ui-resizable.css' }
a change event occured: ui-resizable.css

Subsequent updates to the css file display none of these message.
What am I doing wrong?

@balupton
Bevry member

By default the same change is not fired if it happens within 1 second of the previous one. But sounds like for you it is indefinite, rather than one second. So could be a bug in https://github.com/bevry/watchr/blob/master/src/lib/watchr.coffee#L250-L284 however I am not affected by it.

Will look into this, if you can look into it too that'll be appreciated. Thanks!

@dweldon
dweldon commented Feb 15, 2013

I'm having the same issue in my Cakefile. Everything was working fine for me with node 0.8.18, but broke around the time I transitioned to 0.8.19. I'm uncertain if it's related however. The node change log doesn't indicate any changes to fs.

@dweldon
dweldon commented Feb 15, 2013

Looks like this doesn't have anything to do with the node version - that was coincidental. I experimented with different versions of watchr and found that 2.3.3 works great, but versions >= 2.3.4 have this problem. Could this be related to the switch to fs.watch? I'm running Ubuntu 12.10 if that helps.

@oscar-broman

Same problem here. 2.3.3 behaves as it should. I'm on OS X 10.8.2 with Node v0.8.19.

It seems to work just fine when duplicateDelay is 0, however.

@dweldon
dweldon commented Feb 22, 2013

I tried setting duplicateDelay to 0, but that did not fix it for me. Bummer.

@tapio
tapio commented Feb 26, 2013

I'm too affected by this. My work-around is to change the method back to preferring watchFile over watch with this parameter: preferredMethods: [ 'watchFile', 'watch' ]. I also needed to lower the interval parameter as nowadays its default is 5007 milliseconds, which is too long for my purposes.

@hermiteu

Same problem using node v0.10.0, DocPad v6.26.0, Watch 2.3.7, latest OS X Mountain Lion. I can change every file once, so one change to index.html.md, 1 change to scripts.js, etc. After that no detection of changes, no matter how big the change is. I'm new to node and docpad, I'm not sure how to check if watchr 2.3.3 works.

@tapio
tapio commented Mar 14, 2013

@hermiteu: If you have a package.json in your project, specify "watchr": "2.3.3" in the dependencies section and do npm install. If, on the other hand, you manage dependencies manually, you can command this: npm install watchr@2.3.3

@hermiteu

Thanks tapio! Using Watchr 2.3.3 everything works fine.

@caseywebdev

Running into this also. The culprit is in 770cd65 somewhere but @balupton would know best where exactly it is.

@balupton
Bevry member

Thanks for all the feedback everyone.

While we could set the default preferredMethods back to ['watchFile','watch'] it would introduce the same problems we had before; large memory loads, large CPU load, longer detection delays, under certain circumstances.

Ideally, it would be great if we could use the watch method for environments that support it, and watchFile for environments that don't, and detect this automatically. Unfortunately, I'm not yet able to reproduce this issue, even on shared drives. I'm on OSX Mountain Lion and tried with Node 0.8 and Node 0.10.

For those of you who are able, and want to help out with the fix, I'll need the following from you, it'll be a great help:

  1. The operating system you are on
  2. The node version you are using
  3. The watchr version you are using

Next, we need to do some debugging, I need the result of the following command:

node -e "require('fs').lstat(process.cwd()+'/THEFILENAME',console.log.bind(console))"

Please run this twice and provide the result for both. Once on a file that watchr works fine on. Again on a file that watchr doesn't work fine on. Make sure you are using the latest version of watchr with the default configuration. Change the THEFILENAME portion with the name of the file.

Hopefully that will provide us with some indication of what the difference is between working and non working files. Thanks.

@balupton
Bevry member

For a little background of this issue, it seems to be a combination of duplicateDelay and preferredMethods.

preferredMethods

The watch method (which is now the preferred method) uses the operating system's watching abilities, whereas the watchFile method used node.js polling, which is the reason why watchFile worked.

The issues with watchFile is that it has increased CPU and memory load as we have to do the polling for every file ourselves, and when the interval option is lower, this can cause severe problems as all our app is doing is polling files!

The issues with watch if that sometimes the operating system's watching abilities aren't that good, however it solves the issues of watchFile when it actually works.

duplicateDelay

The duplicateDelay is that sometimes watching just fires duplicate events for whatever reason, so we do some detection to see if the event is the same as one within the duplicateDelay and if it is, then don't worry. This also takes the size of the file into consideration and the modification date so it should be quite intelligent, but perhaps not. In v2.3.9 I've made it so if duplicateDelay is falsey we don't do any duplicate detection.

conclusion

So it is a rock in a hard place scenario. Hopefully with the feedback from the steps in my previous comment we'll be able to figure out the differences between the situations where watchFile or watch is preferred, and selection the correct one intelligently and automatically. Be it even if we even have to fallback to a whitelist/blacklist of the operating systems.

For now, the best I can recommend is adjusting those two settings for yourself. While I could revert back to v2.3.3 way of doing things, then we'll have a different set of people complaining of issues instead - so that's not an option.

Hope that adds some understanding to the complexity of the situation. Cheers.

@caseywebdev

With OS X 10.8.2, Node.js 0.10.0, and watchr 2.3.9, the first change per file will always trigger, but subsequent changes on the same file will never trigger. This is true for every of the 4 possible preferredMethod/duplicateDelay combinations as well. Here's a stat on one of files

{ dev: 16777218,
  mode: 33188,
  nlink: 1,
  uid: 501,
  gid: 20,
  rdev: 0,
  blksize: 4096,
  ino: 18100802,
  size: 1102,
  blocks: 8,
  atime: Sun Mar 17 2013 12:33:54 GMT-0500 (CDT),
  mtime: Sun Mar 17 2013 12:33:52 GMT-0500 (CDT),
  ctime: Sun Mar 17 2013 12:33:52 GMT-0500 (CDT) }
@dweldon
dweldon commented Mar 17, 2013

It may be worth having a look at how fs-watch-tree is implemented. For me, it doesn't suffer from the same issue, but seems to use fs.watch.

@balupton
Bevry member

Which editor and editor version is everyone using?

@balupton
Bevry member

Can everyone give v2.4.1 a go (just published). It's resolve the issue for me - seems it was due to swap files being used by editors like vim and Sublime Text 3 (not 2). Closing for now, post back and I'll re-open if need be.

@balupton balupton closed this Apr 10, 2013
@caseywebdev

I am using ST3 and v2.4.3 is working, thanks @balupton!

@caseywebdev

After further use, I've found that listening to specific files yields the >= 2.3.4 < 2.4.1 results of just one change fire and then silence on subsequent changes. Listening on full directories, however, is working as intended.

@balupton balupton reopened this Apr 10, 2013
@balupton
Bevry member

@caseywebdev hrmm that figures. The reasoning for this is detailed a bit more in #38 - it turns out the reasoning is that Vim, Textmate, and Sublime Text 3 will use a swap file for saving. As such, the change event doesn't fire on the actual file when using the watch method but on the directory (as there is a create a rename combo on the directory, rather than a change event emitted on the file).

I'll fix the individual file issue by also watching the parent directory if we are on the watch method.

I'll also document the workarounds for these editors in the readme until we have solved the problem.

@balupton
Bevry member

Hrmm, so @adrianolaru still has this issue with vim. He's done up the following logs - https://gist.github.com/adrianolaru/5361131 - and provided this stack overflow answer for details - http://stackoverflow.com/questions/607435/why-does-vim-save-files-with-a-extension

Seems that we can't trust the rename event at all. Will look into this. For now, if you are still experiencing the issue, you can use the workarounds mentioned in the "known issues" section in readme.

@lbv
lbv commented Apr 11, 2013

This bug is making it very painful to work with DocPad right now, so I decided to take a look into it.

To test this, I have the following setup in a dir called watch_test:

watch_test/
  test-node.coffee
  test-watchr.coffee
  mydir/
    myfile.txt

The contents of the test scripts:

# test-node.coffee
fs = require 'fs'
fs.watch 'mydir', (ev, f) ->
    console.log "Event: #{ev} Filename: #{f}"
console.log "Now watching .."
# test-watchr.coffee
watchr = require 'watchr'
watchr.watch
    path : 'mydir'
    listeners :
        watching: ->
            console.log 'Now Watching...'
        change: (t, f) ->
            console.log "Change event, type: #{t} file: #{f}"

The idea is to run test-{node,watchr].coffee, and then make changes to mydir/myfile.txt in my editor ( Gedit ), and save the file a few times, to see what happens in the console.

The results for test-node.coffee:

# coffee test-node.coffee
Now watching ..
Event: rename Filename: .goutputstream-XQECVW
Event: change Filename: .goutputstream-XQECVW
Event: change Filename: .goutputstream-XQECVW
Event: change Filename: .goutputstream-XQECVW
Event: rename Filename: .goutputstream-XQECVW
Event: rename Filename: myfile.txt
Event: rename Filename: .goutputstream-UDBEVW
Event: change Filename: .goutputstream-UDBEVW
Event: change Filename: .goutputstream-UDBEVW
Event: change Filename: .goutputstream-UDBEVW
Event: rename Filename: .goutputstream-UDBEVW
Event: rename Filename: myfile.txt
Event: rename Filename: .goutputstream-B6M4UW
Event: change Filename: .goutputstream-B6M4UW
Event: change Filename: .goutputstream-B6M4UW
Event: change Filename: .goutputstream-B6M4UW
Event: rename Filename: .goutputstream-B6M4UW
Event: rename Filename: myfile.txt

The results for test-watchr.coffee:

# coffee test-watchr.coffee
Now Watching...
Change event, type: create file: mydir/.goutputstream-TPYMVW
Change event, type: update file: mydir/.goutputstream-TPYMVW
Change event, type: delete file: mydir/.goutputstream-TPYMVW
Change event, type: update file: mydir/myfile.txt
Change event, type: create file: mydir/.goutputstream-E72OVW
Change event, type: delete file: mydir/.goutputstream-E72OVW
Change event, type: create file: mydir/.goutputstream-MLFQVW
Change event, type: delete file: mydir/.goutputstream-MLFQVW

What I can gather from this, is that saving myfile.txt produces the following chain of events:

  • A file called .goutputstream-?????? is created, and reported as a rename event by node's fs.watch.
  • This file is changed one or more times (and reported as a change event...
  • Finally it is renamed into myfile.txt. This fires two rename events from fs.watch, one for the temporary file, and one for myfile.txt.

By the way, this is in linux using node v0.10.3 and watchr v2.4.3, so the underlying mechanism is inotify; I don't know about what events would be reported in other systems.

Anyway, after spending some time studying the code from watchr.coffee, I can kind of understanding what is going on, but I'm not sure what would be the correct way to fix it. Judging by some of the comments from the code, it seems like it used to do the right thing (or tried to), but now what the comments say doesn't correspond to what the code does. In line 365, for example, there's the following message:

# So let's check if we are a directory
# as if we are a directory the chances are something actually happened to a child (rename or delete)
# and if we are the same, then we should scan our children to look for renames and deletes

The last line explains correctly what should happen when there's a rapid (create temp file)->(change temp file)->(rename temp file to final file) succession of events inside a directory. But that never happens because just above that comment, in line 359, the whole thing bails as soon as isTheSame returns true. The if on line 369 also goes against what the comment says.

The other interesting point is line 381, where (as I understand it) it's implied that a "change" event should (hopefully) have been fired already (I guess by fs.watch). But that doesn't happen... as illustrated above, fs.watch reports two rename events at the end of the process, and none of those help watchr determine that a change event happened. The temp file is correctly reported as being deleted, but myfile.txt has not been deleted (line 391) nor created (line 409), so the code currently does nothing.

Anyway, hopefully this brings a little more details into this issue. Sorry for the long post, and thanks for the nice software.

@lbv lbv added a commit that referenced this issue Apr 11, 2013
@lbv lbv Possible bugfix for issue #33
Refresh the fswatcher if the inode for a file has changed.
2a51ebd
@lbv
lbv commented Apr 11, 2013

After some more consideration and studying the code, I think I'm fairly confident that the reasonable way to fix this would be checking if the inode of a file has changed when an update has been identified. If this happens, then the internal fswatcher becomes stale, and of course it stops tracking its changes.

So I made a simple patch: lbv/watchr@2a51ebd

Notice the "REVIEW" comments... which I added because I'm not very familiar with the internals of watchr, so I may be doing something silly, but the idea I think is clear.

Now I'll try to get familiar with the test units and create a new test for this...

@balupton
Bevry member

Thanks for the details. Just out of curiosity, does changing this line: https://github.com/bevry/watchr/blob/master/src/lib/watchr.coffee#L382

if typeChecker.isString(args[0]) and args[1] is null

to

if typeChecker.isString(args[0]) and (args[0] isnt 'change' or args[1] is null)

Fix the issue?

@balupton
Bevry member

Now I'll try to get familiar with the test units and create a new test for this...

Please do, if we can get unit tests for this (that being vim with noswapfile, vim without noswapfile, and sublime text 3), I'll be a very happy man. :)

@lbv
lbv commented Apr 12, 2013

Hmmm... the more I investigate, the messier this seems to get :). I tried vim (I was trying just gedit before), and also your suggested change for line 382, but this is trickier than I originally thought. I'll try to summarize what I've learned as best as I can.

First of all, let's agree on the following definition, to help with the discussion.

Let's define an "atomic save" as the occurance in rapid succession of the following events:

  • A file, let's call it F, is about to be updated (probably by a text editor).
  • For this purpose, a temporary file is created first, let's call it tmpF, and filled with the new content for F.
  • tmpF is saved, and then, finally, tmpf is renamed to F.

Apparently this is the default behaviour of editors like TextMate and gedit. vim does something similar, but not quite the same, but I'll get to that in a moment. By the way, the (no)swapfile option in vim is not really related to this type of operation. A "swapfile" to vim is just an auxiliary file to keep some of the editor's internal state in relation to a buffer (not the same thing as a file), but a swapfile is not renamed, nor does it has much to do with that funny atomic business (although it may affect the order in which some of those operations happen). The option that is most related to atomic saves in vim is writebackup. But, in a moment...

Now, the basic challenge for watchr is to map information, from what node's fs.watch tells it (which is limited to two types of events: 'rename' and 'change') to what watchr wants to provide as its own API (including 'create', 'delete', and 'update' events). So right there one can start to imagine why this is not trivial at all. Considering the tricky things that software like text editors end up doing... well, no wonder why we're here.

Saving from text editors: behind the scenes

Using the test-node.coffee and test-watchr.coffee scripts posted above, let's analyze the behaviour from text editors actions more thoroughly. All of the following tests are done by starting one of the scripts, then opening mydir/myfile.txt in a text editor, doing a small change, saving, waiting a couple of seconds, then doing another change and saving again. A blank line will be placed to denote the moment right after the first save and before the second save.

I also ran the test-watchr script in different states: as-is (i.e. in the current git master branch), and with the inode check, and the line-382 change suggested in the comment two posts above (the two changes seem to produce similar results).

Gedit

As mentioned, this editor seems to follow the atomic save pattern.

test-node

$ coffee test-node.coffee
Now watching ..
Event: rename Filename: .goutputstream-P199UW
Event: change Filename: .goutputstream-P199UW
Event: change Filename: .goutputstream-P199UW
Event: rename Filename: .goutputstream-P199UW
Event: rename Filename: myfile.txt

Event: rename Filename: .goutputstream-783FVW
Event: change Filename: .goutputstream-783FVW
Event: change Filename: .goutputstream-783FVW
Event: change Filename: .goutputstream-783FVW
Event: rename Filename: .goutputstream-783FVW
Event: rename Filename: myfile.txt

This suggests that a rename event is reported when a file is created, and then two rename events are fired when a real rename occurs (one for the source, and one for the target).

test-watchr

# watchr 2.4.3 as-is
$ coffee test-watchr.coffee
Now Watching...
Change event, type: create file: mydir/.goutputstream-21XIVW
Change event, type: delete file: mydir/.goutputstream-21XIVW
Change event, type: update file: mydir/myfile.txt

Change event, type: create file: mydir/.goutputstream-5K9KVW
Change event, type: delete file: mydir/.goutputstream-5K9KVW

Everything looks fine, except for the missing "update" for the second save.

# watchr 2.4.3 + inode check or line-382 change
$ coffee test-watchr.coffee
Now Watching...
Change event, type: create file: mydir/.goutputstream-SIZHVW
Change event, type: delete file: mydir/.goutputstream-SIZHVW
Change event, type: update file: mydir/myfile.txt

Change event, type: create file: mydir/.goutputstream-DJ68UW
Change event, type: update file: mydir/.goutputstream-DJ68UW
Change event, type: delete file: mydir/.goutputstream-DJ68UW
Change event, type: update file: mydir/myfile.txt

This now picks up the second update.

vim with 'nowritebackup'

Now let's see what happens when the file is edited with vim, first without the writebackup option. This means the vim will not try an atomic save, or anything like that. It will just update the file in-place.

test-node

$ coffee test-node.coffee
Now watching ..
Event: change Filename: myfile.txt
Event: change Filename: myfile.txt
Event: change Filename: myfile.txt

Event: change Filename: myfile.txt
Event: change Filename: myfile.txt
Event: change Filename: myfile.txt

Pretty straightforward...

test-watchr

# watchr 2.4.3 as-is
$ coffee test-watchr.coffee
Now Watching...
Change event, type: update file: mydir/myfile.txt

Change event, type: update file: mydir/myfile.txt

Very nice... seems to work perfectly. It produces the same output with the inode check, and with the line-382 change.

vim with 'writebackup'

Things get a little bizarre with the writebackup option on:

test-node

$ coffee test-node.coffee
Now watching ..
Event: rename Filename: 4913
Event: change Filename: 4913
Event: rename Filename: 4913
Event: rename Filename: myfile.txt
Event: rename Filename: myfile.txt~
Event: rename Filename: myfile.txt
Event: change Filename: myfile.txt
Event: change Filename: myfile.txt
Event: rename Filename: myfile.txt~

Event: rename Filename: 4913
Event: change Filename: 4913
Event: rename Filename: 4913
Event: rename Filename: myfile.txt
Event: rename Filename: myfile.txt~
Event: rename Filename: myfile.txt
Event: change Filename: myfile.txt
Event: change Filename: myfile.txt
Event: rename Filename: myfile.txt~

I have no idea what's the deal with the 4913 file that apparently is created, filled, and then deleted. I think there's more than meets the eye here, but I can't explain it. After that, what seems to be happening is this: first myfile.txt is moved to myfile.txt~, then myfile.txt is created and filled, and finally myfile.txt~ is erased. As you can see, it has the same flavour of an atomic save, but it's not done the same way we defined above.

test-watchr

# watchr 2.4.3 as-is
$ coffee test-watchr.coffee
Now Watching...
Change event, type: delete file: mydir/myfile.txt
Change event, type: create file: mydir/myfile.txt~
Change event, type: delete file: mydir/myfile.txt~

Change event, type: create file: mydir/myfile.txt~
Change event, type: delete file: mydir/myfile.txt~

The 4913 changes are not picked up... (again, I think there must be a good explanation, but I don't have it), and the output looks kind of reasonable given the process outlined above, but the first save didn't produce an 'update' event for myfile.txt, only a 'delete', and the second save didn't report anything for myfile.txt at all.

Curiously, when the inode check, or the line-382 change is introduced, the output becomes a little unpredictable:

# watchr 2.4.3 + inode check or line-382 change
line-382 change
$ coffee test-watchr.coffee
Now Watching...
Change event, type: delete file: mydir/myfile.txt
Change event, type: create file: mydir/myfile.txt~
Change event, type: create file: mydir/myfile.txt   (*)
Change event, type: delete file: mydir/myfile.txt~

Change event, type: delete file: mydir/myfile.txt   (*)
Change event, type: create file: mydir/myfile.txt~
Change event, type: create file: mydir/myfile.txt   (*)
Change event, type: delete file: mydir/myfile.txt~

The lines I marked with (*) are lines that sometimes show up, and sometimes don't (or maybe they do, but in a different location). Smells like a racing condition or something like that.

I'll mention that I also tried various combinations of opening the file in vim, using 'writebackup', save a few times, then switch to 'nowritebackup', save a few more times, then switch back, etc. The trend is that both the inode check and the line-382 change have similar results, but they are ultimately unpredictable. Sometimes they report the correct events for myfile.txt, sometimes they don't.


In summary, getting this exactly right for all scenarios seems to be very tricky. I need to study watchr's code some more to fully understand the behaviours I observed, but I suspect this may not be a simple thing to fix. What I mean is, maybe a big structural/algorithmic change is required. Or maybe not... I don't know. If you have any insights, I'd be glad to hear them.

Cheers.

@mulyadioey
  1. OS X 10.8.3
  2. Node v0.10.5
  3. watchr 2.4.3

My issue might be related to this, thus I thought I'd write a comment. I got a bunch of log messages e.g.

a log message occured: { '0': 'debug',
  '1': 'close: /Users/admin/tmp/bootstrap/less/grid.less' }

After a while (i.e. changing a watched file 2 times), watchr died.

a log message occured: { '0': 'debug',
  '1': 'watch event triggered on /Users/admin/tmp/bootstrap/less:',
  '2': [ 'rename', 'type.less' ] }
Stop watching our paths
...
(died and returned to the terminal prompt)
@gagle
gagle commented Apr 28, 2013

@lbv Nice investigation. All these temporary files used by vim and gedit can be summarized as:

  var include =
            //gedit
            !beginsWith (basename, ".goutputstream-") &&

            //vim, this should also include "isNaN(basename)" but could filter valid
            //files or directories with a name where all the characters are numbers
            !endsWith (basename, ".swp") && !endsWith (basename, ".swx") &&
            !endsWith (basename, ".swpx") && !endsWith (basename, "~");

These patterns can be easily ignored using a filter. This is how I ignore these files with walkie-watchie. All these lines marked with an asterisk (*) are not produced by the built-in fs.watch() function (if I remember correctly), it heavily depends on how you watch files and directories and how you maintain the necessary stuff to notify the events correctly.

@balupton
Bevry member
balupton commented Oct 9, 2013

I just pushed up v2.4.4, can people please give it a go.

@balupton balupton added a commit that referenced this issue Dec 19, 2013
@balupton balupton v2.4.7. Bugfix.
- v2.4.7 December 19, 2013
	- Fixed: [Text Editor swap files on saving can throw it off](#33)
	- Fixed: [`ENOENT` errors are emitted when dead links a broken symlink is encountered](#42)
	- Updated dependencies
90d089f
@balupton
Bevry member

Can everyone try again with watchr v2.4.7. Will re-open if it is still an issue.

@balupton balupton closed this Dec 19, 2013
@joshcrawmer4

I'm still having this Issue. I tried using v2.4.7. But that did not make any difference. fs.watch only recognizes the first change I make to the file. Then after that, nothing happens. I can use echo " " >> filename.txt, and then it works. Please help!

@tnguyen14

Just wanna say that I ran into this issue with using vim and chokidar, so I switched over to watchr and the issue seems to be gone. Thanks so much for solving it :)

@tnguyen14 tnguyen14 referenced this issue in paulmillr/chokidar Feb 12, 2016
Closed

Change event fired twice, is it by design? #298

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Something went wrong with that request. Please try again.