Editors on OSX result in random events

[robfig]

I apologize ahead of time for this bug report.

I'm using fsnotify to watch templates during development as a trigger to reload them into the program. However, for whatever reason, I get a miscellaneous mix of events fired on save. It's always one of MODIFY, MODIFY|ATTRIB, or RENAME, and sometimes it is combinations of them, or multiple of one.

For example, repeatedly adding a byte to a file with Emacs and saving the file, results in these events being fired (separated to denote batches related to one save):

"/Users/robfig/.../views/features.soy": MODIFY|ATTRIB
--
"/Users/robfig/.../views/features.soy": MODIFY|ATTRIB
--
"/Users/robfig/.../views/features.soy": MODIFY|ATTRIB
"/Users/robfig/.../views/features.soy": MODIFY
"/Users/robfig/.../views/features.soy": MODIFY
--
"/Users/robfig/.../views/features.soy": MODIFY|ATTRIB
"/Users/robfig/.../views/features.soy": MODIFY
--
"/Users/robfig/.../views/features.soy": MODIFY|ATTRIB

Notes:

• Most commonly, there is a single MODIFY|ATTRIB event on save.
• After a RENAME appears, fsnotify stops watching the file so no more events come out.
• Frequently, exactly 1 second after the save, another MODIFY|ATTRIB event is fired.

I am working around this behavior with these techniques:

• Treat MODIFY|ATTRIB as MODIFY
• Drain the Event channel after each event, to avoid duplicating work on multi-events.
• Re-adding the watch if the event is a RENAME, after sleeping for 10ms. (adding the watch immediately results in an error: lstat /Users/robfig/.../testfile.soy: no such file or directory)

I think this results in decent behavior for me, so this problem is not urgent from my point of view. But since it's going into Go standard library (with the specific goal of watching for changes to code), I thought that it would be useful for me to file an issue.

Debugging notes:

• fsnotify is not doing anything obviously incorrect -- it accurately reports the events coming out kqueue.
• I tried to write a program to reproduce this behavior, and I couldn't. So, I suppose it has something to do with how editors interact with OSX filesystem. However, it happens both for me (Mavericks, Emacs) and my coworker (Lion, Sublime), so I don't think it's too specific to my setup.
• DTrace (e.g. iosnoop, etc) suggested everything was fine. Saving resulted in one "Write" DTrace event.

I can reproduce by NewWatcher().Watch(FILENAME) and editing that file with my editor while printing events from that watcher in the obvious way.

I'm not really sure how to debug it further. Happy to investigate more if anyone has ideas.

[nathany]

@robfig Thanks for the report.

This could be related Spotlight. #62 If you haven't already, try adding your folder to the Privacy section in Spotlight preferences and see if that improves matters. I was hoping the Attrib option would help filter these out, but your example indicates otherwise.

I've done some (unmerged) work on filtering out repeated events on the same file, but Spotlight will sometimes generate events on several other files as well.

It could also be related to an "atomic saves" option in emacs.

[robfig]

Yeah, I found that by googling and tried it, but didn't notice a difference (unless I did it wrong). But also, I don't think that's a reasonable requirement for fsnotify to work properly...

I've never seen an event not for the file I've changed, although I haven't looked at it as closely as you have. No idea.. wouldn't surprise me if each editor had its own little save dance.

Seems like a tough problem.

[thebyrd]

I'm having the same issue as @robfig. Specifically when I update a file in sublime text 3 it will emit a delete right after the update event.

[nathany]

@thebyrd From Preferences.sublime-settings:

// Save via writing to an alternate file, and then renaming it over the
// original file.
"atomic_save": true

When I was working with the fsnotify API, I didn't find a need to track deletes:

watcher.WatchFlags(folder, fsnotify.FSN_CREATE|fsnotify.FSN_MODIFY)

Removing multiple events on the same file isn't that difficult.

For go.exp/fsnotify we've talked about a simpler Event structure so events can be easily coalesced.

[robfig]

Even if you don't track deletes, won't it still cause the watcher to remove its watch?

Also, that throttling routine looks like an explanation for the behavior of getting an event on save and then exactly one second after the save. Shouldn't throttling discard events that are "throttled", not save them for later? At least in the case of code watching, I'm not sure the current behavior makes a lot of sense -- I would rather have all the events at once so I can drain and ignore. There is no way to ignore a throttled, delayed event.

[nathany]

@robfig Fyi, the throttling code is not on master. If it were, it would send the leading event and then discards additional events on that file for a second (forward = false means it doesn't forward the event along).

[robfig]

I see.. in that case, I still have no idea :)

[thebyrd]

Our work around was just to stat the file on every delete event and if it failed we knew it was a valid delete, if not we would ignore the event. Kind of a pain, but this is the approach node.js uses.

[ghost]

I don't think this should be called a bug. If a text editor (for example), does a file saving process that looks like this:

1. Write to temp file
2. Move old file out of the way
3. Move temp file onto new file

Then you should rightfully expect that there are multiple notifications yes?

By the way, there are sound reasons for doing this. If you simply overwrite a file in place, there is a tiny chance something could read your file when you are halfway through re-writing data into that file. This is especially a problem with a larger file. A good example is a web server, if you are writing a 100k text file, and a user is trying to load that text file over http at the same time, what will the user see? sure it might only take 0.1s to write that 100k text file, but what if you are serving 1000 hits per second on that page?