Kqueue refactoring regression

[ottob]

I've spent the entire day trying to reproduce the error reported in https://github.com/go-fsnotify/fsnotify/pull/43 in a consistent fashion. But I can't...

I've tried with a tiny revel app (just revel new) - no issue. I've tried with a slightly larger (booking) - no issue. But with our large-ish revel app I still have the issue.

I tried the following with an instrumented revel watcher[1]:

1. Launch the app. revel run ourapp
2. Go to /robots.txt and wait for revel to rebuild and serve the file.
3. Without touching any files of the project, refresh the browser (f5) and see what happens.

With the kqueue branch (71b4293) I got this output the first time I tried:
http://paste2.org/MaDA2xsn
and this the second time:
http://paste2.org/Ih9zspp4

So it behaves differently in two different runs even though I'm doing the exact same thing. 😢

Then I switched back to the master branch (ca50e73) and I consistently get the following:
http://paste2.org/Fmm6pvVn

So with the master branch there are no rebuilds triggered by changes to tmp/main.go or routes/routes.go. With master the only events are the folder changes to app/tmp and app/routes. Can this give you any clue?

[1] Where https://github.com/revel/revel/blob/develop/watcher.go#L174-L176 was changed to this:

case ev := <-watcher.Events:
    fmt.Println("ev", ev.String())
    if w.rebuildRequired(ev, listener) {
        fmt.Println("rb", ev.String())
        refresh = true

[nathany]

Hi Otto. Sorry for not digging into this sooner. I've never used Revel before, but I got the booking sample running with some additional logging (on the develop branch).

Your previous bisect had pointed to 4a0d1ae being the culprit. Most of those changes are to addWatch, so I added some logging there and compared against ca50e73. With the result you're seeing, it seems plausible that it was watching more than it was previously.

So far I haven't figured it out. Still digging. It might be worth confirming that bisect, since you said it wasn't 100% reproducible. If it was a commit before, that could change things quite a lot.

If there was a medium sized open source Revel app that we could reproduce this on, that would make it much easier. It might even be reproducible with a similar file structure to your app, even if those files don't contain the same code. /cc @robfig

[nathany]

@ottob I hope you have Spotlight disabled for your folder, which can randomly decide to create events. https://github.com/go-fsnotify/fsnotify/wiki/FAQ.

Though if not disabled, I'd expect you'd see the same problems on v1.0.4 as well.

[nathany]

[ottob]

Feel free to close this. I will re-open if I ever manage to write a test that triggers the issue.

[nathany]

I've ran into a very similar issue here. nathany/looper#18 It is reliably reproducible. Looking into a fix now.

[nathany]

@ottob I believe this to be fixed on master. Stupid mistake on my part. Sorry for all the trouble.

[nathany]

Feel free to reopen this issue if you still see the issue.

[ottob]

👏 thanks for tracking it down.