Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Argument being ignored in OS X #351

Closed
fxn opened this issue Nov 1, 2015 · 23 comments
Closed

Argument being ignored in OS X #351

fxn opened this issue Nov 1, 2015 · 23 comments
Assignees

Comments

@fxn
Copy link

fxn commented Nov 1, 2015

This may be something known but did not find it.

I am working on merging the new file system monitor for app reloading in Rails. The monitor works fine on Linux, but on OS X it does nothing at all. Listen is configured properly with the list of directories to watch (a bunch of them), but the callback does not get called.

I tried to reproduce outside Rails, and it seems to be related to the number of arguments. Strange... maybe that is a red herring, but this is the dummy reproduction:

Setup directories foo, bar, and baz. Then try this script in their parent directory:

require 'listen'

Listen.to('foo', 'bar', 'baz') do |*args|
  p args
end.start

sleep

OK, touching foo/foo.txt and baz/baz.txt triggers events, but touching bar/bar.txt does not.

Tested with 3.0.3.

@e2
Copy link
Contributor

e2 commented Nov 2, 2015

I don't have OSX, so I can't check really.

I created a branch that shows the directories passed to rb-fsevent.

In your Gemfile

gem 'listen', github: 'guard/listen', branch: 'add_fsevent_debug'

Then, run with Bundler and the environment variable LISTEN_GEM_DEBUGGING=2.

If the directory is properly passed, there should be a fsevent: watching: message for each directory.

If that doesn't help, can you check various combinations?

E.g.

  • foo+baz and modify something in bar (you shouldn't get an event)
  • change the order, e.g. bar+baz+foo and see if things work in all

And ideally, display the output after using LISTEN_GEM_DEBUGGING=2, because it can give extra info and clues.

Thanks.

@fxn
Copy link
Author

fxn commented Nov 2, 2015

I did three tests, they seem to suggest a conjecture mentioned at the end of this comment.

First, the same script as above yielded this output:

fxn@yeager:~/tmp/listen-issue $ LISTEN_GEM_DEBUGGING=2 bundle exec ruby foo.rb 
I, [2015-11-02T22:04:27.901039 #31807]  INFO -- : Listen loglevel set to: 0
I, [2015-11-02T22:04:27.901121 #31807]  INFO -- : Listen version: 3.0.3
D, [2015-11-02T22:04:27.901282 #31807] DEBUG -- : Adapter: considering polling ...
D, [2015-11-02T22:04:27.901323 #31807] DEBUG -- : Adapter: considering optimized backend...
D, [2015-11-02T22:04:27.904000 #31807] DEBUG -- : fsevent: watching: "/Users/fxn/tmp/listen-issue/foo"
D, [2015-11-02T22:04:27.904105 #31807] DEBUG -- : fsevent: watching: "/Users/fxn/tmp/listen-issue/bar"
D, [2015-11-02T22:04:27.904146 #31807] DEBUG -- : fsevent: watching: "/Users/fxn/tmp/listen-issue/baz"
I, [2015-11-02T22:04:27.904703 #31807]  INFO -- : Record.build(): 0.00023 seconds
I, [2015-11-02T22:04:27.904981 #31807]  INFO -- : Record.build(): 0.00021 seconds
I, [2015-11-02T22:04:27.905186 #31807]  INFO -- : Record.build(): 0.00016 seconds
D, [2015-11-02T22:04:27.906766 #31807] DEBUG -- : Waiting for processing to start...
D, [2015-11-02T22:04:59.248422 #31807] DEBUG -- : fsevent: /Users/fxn/tmp/listen-issue/foo
D, [2015-11-02T22:04:59.249718 #31807] DEBUG -- : unknown: dir:/Users/fxn/tmp/listen-issue/foo ({:recursive=>true})
D, [2015-11-02T22:04:59.250330 #31807] DEBUG -- : Scanning: .({:recursive=>true}): {"foo.txt"=>{:mtime=>1446404092.0, :mode=>33188}} -> #<Set: {#<Pathname:/Users/fxn/tmp/listen-issue/foo/foo.txt>}>
D, [2015-11-02T22:04:59.251062 #31807] DEBUG -- : unknown: file:/Users/fxn/tmp/listen-issue/foo/foo.txt ({})
D, [2015-11-02T22:04:59.356015 #31807] DEBUG -- : listen: raw changes: [[:modified, "/Users/fxn/tmp/listen-issue/foo/foo.txt"]]
D, [2015-11-02T22:04:59.356197 #31807] DEBUG -- : listen: final changes: {:modified=>["/Users/fxn/tmp/listen-issue/foo/foo.txt"], :added=>[], :removed=>[]}
[["/Users/fxn/tmp/listen-issue/foo/foo.txt"], [], []]
D, [2015-11-02T22:04:59.356428 #31807] DEBUG -- : Callback took 0.0001068115234375 sec
D, [2015-11-02T22:05:29.865863 #31807] DEBUG -- : fsevent: /Users/fxn/tmp/listen-issue/baz
D, [2015-11-02T22:05:29.866644 #31807] DEBUG -- : unknown: dir:/Users/fxn/tmp/listen-issue/baz ({:recursive=>true})
D, [2015-11-02T22:05:29.867092 #31807] DEBUG -- : Scanning: .({:recursive=>true}): {"baz.txt"=>{:mtime=>1446404115.0, :mode=>33188}} -> #<Set: {#<Pathname:/Users/fxn/tmp/listen-issue/baz/baz.txt>}>
D, [2015-11-02T22:05:29.867674 #31807] DEBUG -- : unknown: file:/Users/fxn/tmp/listen-issue/baz/baz.txt ({})
D, [2015-11-02T22:05:29.971418 #31807] DEBUG -- : listen: raw changes: [[:modified, "/Users/fxn/tmp/listen-issue/baz/baz.txt"]]
D, [2015-11-02T22:05:29.971636 #31807] DEBUG -- : listen: final changes: {:modified=>["/Users/fxn/tmp/listen-issue/baz/baz.txt"], :added=>[], :removed=>[]}
[["/Users/fxn/tmp/listen-issue/baz/baz.txt"], [], []]
D, [2015-11-02T22:05:29.971878 #31807] DEBUG -- : Callback took 9.202957153320312e-05 sec

Then I moved "foo" to the end:

Listen.to('bar', 'baz', 'foo') do |*args|
  p args
end.start

In this case the directory that was not reacting was "baz":

fxn@yeager:~/tmp/listen-issue $ LISTEN_GEM_DEBUGGING=2 bundle exec ruby foo.rb 
I, [2015-11-02T22:06:39.292633 #31899]  INFO -- : Listen loglevel set to: 0
I, [2015-11-02T22:06:39.292718 #31899]  INFO -- : Listen version: 3.0.3
D, [2015-11-02T22:06:39.292900 #31899] DEBUG -- : Adapter: considering polling ...
D, [2015-11-02T22:06:39.292944 #31899] DEBUG -- : Adapter: considering optimized backend...
D, [2015-11-02T22:06:39.294228 #31899] DEBUG -- : fsevent: watching: "/Users/fxn/tmp/listen-issue/bar"
D, [2015-11-02T22:06:39.294309 #31899] DEBUG -- : fsevent: watching: "/Users/fxn/tmp/listen-issue/baz"
D, [2015-11-02T22:06:39.294419 #31899] DEBUG -- : fsevent: watching: "/Users/fxn/tmp/listen-issue/foo"
I, [2015-11-02T22:06:39.295011 #31899]  INFO -- : Record.build(): 0.00022 seconds
D, [2015-11-02T22:06:39.295048 #31899] DEBUG -- : Waiting for processing to start...
I, [2015-11-02T22:06:39.295239 #31899]  INFO -- : Record.build(): 0.00014 seconds
I, [2015-11-02T22:06:39.295614 #31899]  INFO -- : Record.build(): 0.00012 seconds
D, [2015-11-02T22:06:47.645948 #31899] DEBUG -- : fsevent: /Users/fxn/tmp/listen-issue/foo
D, [2015-11-02T22:06:47.647302 #31899] DEBUG -- : unknown: dir:/Users/fxn/tmp/listen-issue/foo ({:recursive=>true})
D, [2015-11-02T22:06:47.647912 #31899] DEBUG -- : Scanning: .({:recursive=>true}): {"foo.txt"=>{:mtime=>1446498298.0, :mode=>33188}} -> #<Set: {#<Pathname:/Users/fxn/tmp/listen-issue/foo/foo.txt>}>
D, [2015-11-02T22:06:47.648444 #31899] DEBUG -- : unknown: file:/Users/fxn/tmp/listen-issue/foo/foo.txt ({})
D, [2015-11-02T22:06:47.753889 #31899] DEBUG -- : listen: raw changes: [[:modified, "/Users/fxn/tmp/listen-issue/foo/foo.txt"]]
D, [2015-11-02T22:06:47.754069 #31899] DEBUG -- : listen: final changes: {:modified=>["/Users/fxn/tmp/listen-issue/foo/foo.txt"], :added=>[], :removed=>[]}
[["/Users/fxn/tmp/listen-issue/foo/foo.txt"], [], []]
D, [2015-11-02T22:06:47.754383 #31899] DEBUG -- : Callback took 0.00014209747314453125 sec
D, [2015-11-02T22:06:56.525527 #31899] DEBUG -- : fsevent: /Users/fxn/tmp/listen-issue/bar
D, [2015-11-02T22:06:56.526299 #31899] DEBUG -- : unknown: dir:/Users/fxn/tmp/listen-issue/bar ({:recursive=>true})
D, [2015-11-02T22:06:56.526764 #31899] DEBUG -- : Scanning: .({:recursive=>true}): {"bar.txt"=>{:mtime=>1446498338.0, :mode=>33188}} -> #<Set: {#<Pathname:/Users/fxn/tmp/listen-issue/bar/bar.txt>}>
D, [2015-11-02T22:06:56.527356 #31899] DEBUG -- : unknown: file:/Users/fxn/tmp/listen-issue/bar/bar.txt ({})
D, [2015-11-02T22:06:56.633360 #31899] DEBUG -- : listen: raw changes: [[:modified, "/Users/fxn/tmp/listen-issue/bar/bar.txt"]]
D, [2015-11-02T22:06:56.633595 #31899] DEBUG -- : listen: final changes: {:modified=>["/Users/fxn/tmp/listen-issue/bar/bar.txt"], :added=>[], :removed=>[]}
[["/Users/fxn/tmp/listen-issue/bar/bar.txt"], [], []]
D, [2015-11-02T22:06:56.633907 #31899] DEBUG -- : Callback took 6.699562072753906e-05 sec

Observation: in both cases the directory in the middle is the one not firing events.

Then I tried with five arguments:

Listen.to('foo', 'bar', 'baz', 'woo', 'zoo') do |*args|
  p args
end.start

and touched files in each directory in the same order they were passed:

fxn@yeager:~/tmp/listen-issue $ LISTEN_GEM_DEBUGGING=2 bundle exec ruby foo.rb 
I, [2015-11-02T22:15:57.905542 #31978]  INFO -- : Listen loglevel set to: 0
I, [2015-11-02T22:15:57.905630 #31978]  INFO -- : Listen version: 3.0.3
D, [2015-11-02T22:15:57.905765 #31978] DEBUG -- : Adapter: considering polling ...
D, [2015-11-02T22:15:57.905825 #31978] DEBUG -- : Adapter: considering optimized backend...
D, [2015-11-02T22:15:57.908393 #31978] DEBUG -- : fsevent: watching: "/Users/fxn/tmp/listen-issue/foo"
D, [2015-11-02T22:15:57.908556 #31978] DEBUG -- : fsevent: watching: "/Users/fxn/tmp/listen-issue/bar"
D, [2015-11-02T22:15:57.908679 #31978] DEBUG -- : fsevent: watching: "/Users/fxn/tmp/listen-issue/baz"
D, [2015-11-02T22:15:57.908722 #31978] DEBUG -- : fsevent: watching: "/Users/fxn/tmp/listen-issue/woo"
D, [2015-11-02T22:15:57.908802 #31978] DEBUG -- : fsevent: watching: "/Users/fxn/tmp/listen-issue/zoo"
I, [2015-11-02T22:15:57.909548 #31978]  INFO -- : Record.build(): 0.00032 seconds
I, [2015-11-02T22:15:57.909776 #31978]  INFO -- : Record.build(): 0.00016 seconds
I, [2015-11-02T22:15:57.909971 #31978]  INFO -- : Record.build(): 0.00014 seconds
I, [2015-11-02T22:15:57.910109 #31978]  INFO -- : Record.build(): 0.00010 seconds
I, [2015-11-02T22:15:57.910226 #31978]  INFO -- : Record.build(): 0.00008 seconds
D, [2015-11-02T22:15:57.912382 #31978] DEBUG -- : Waiting for processing to start...
D, [2015-11-02T22:16:02.718827 #31978] DEBUG -- : fsevent: /Users/fxn/tmp/listen-issue/foo
D, [2015-11-02T22:16:02.720121 #31978] DEBUG -- : unknown: dir:/Users/fxn/tmp/listen-issue/foo ({:recursive=>true})
D, [2015-11-02T22:16:02.720870 #31978] DEBUG -- : Scanning: .({:recursive=>true}): {"foo.txt"=>{:mtime=>1446498808.0, :mode=>33188}} -> #<Set: {#<Pathname:/Users/fxn/tmp/listen-issue/foo/foo.txt>}>
D, [2015-11-02T22:16:02.721297 #31978] DEBUG -- : unknown: file:/Users/fxn/tmp/listen-issue/foo/foo.txt ({})
D, [2015-11-02T22:16:02.823568 #31978] DEBUG -- : listen: raw changes: [[:modified, "/Users/fxn/tmp/listen-issue/foo/foo.txt"]]
D, [2015-11-02T22:16:02.823776 #31978] DEBUG -- : listen: final changes: {:modified=>["/Users/fxn/tmp/listen-issue/foo/foo.txt"], :added=>[], :removed=>[]}
[["/Users/fxn/tmp/listen-issue/foo/foo.txt"], [], []]
D, [2015-11-02T22:16:02.823997 #31978] DEBUG -- : Callback took 0.00010013580322265625 sec
D, [2015-11-02T22:16:14.346098 #31978] DEBUG -- : fsevent: /Users/fxn/tmp/listen-issue/zoo
D, [2015-11-02T22:16:14.346621 #31978] DEBUG -- : unknown: dir:/Users/fxn/tmp/listen-issue/zoo ({:recursive=>true})
D, [2015-11-02T22:16:14.347083 #31978] DEBUG -- : Scanning: .({:recursive=>true}): {} -> #<Set: {#<Pathname:/Users/fxn/tmp/listen-issue/zoo/zoo.txt>}>
D, [2015-11-02T22:16:14.349510 #31978] DEBUG -- : unknown: file:/Users/fxn/tmp/listen-issue/zoo/zoo.txt ({})
D, [2015-11-02T22:16:14.453347 #31978] DEBUG -- : listen: raw changes: [[:added, "/Users/fxn/tmp/listen-issue/zoo/zoo.txt"]]
D, [2015-11-02T22:16:14.453516 #31978] DEBUG -- : listen: final changes: {:modified=>[], :added=>["/Users/fxn/tmp/listen-issue/zoo/zoo.txt"], :removed=>[]}
[[], ["/Users/fxn/tmp/listen-issue/zoo/zoo.txt"], []]
D, [2015-11-02T22:16:14.453733 #31978] DEBUG -- : Callback took 4.76837158203125e-05 sec

So the hypothesis is that all but the first and last directories are not firing events.

What a weird behaviour, does it ring any bell?

@e2
Copy link
Contributor

e2 commented Nov 3, 2015

No, I've never heard of an issue like this before.

I'm almost 100% certain it's a rb-fsevent bug. I don't have OSX to check it out.

Instead of using listen, try to reproduce the problem directly using rb-fsevent:

https://github.com/thibaudgg/rb-fsevent

Here's how Listen uses rb-fsevent:

https://github.com/guard/listen/blob/master/lib/listen/adapter/darwin.rb#L22

As you can see, it creates one watcher for every directory. This is because I need a separate callback for every directory.

I could probably create a workaround in Listen, but I need very specific info about what isn't working.

@e2
Copy link
Contributor

e2 commented Nov 3, 2015

I think it would be something like this:

require 'rb-fsevent'

fs = %w(foo bar baz).map do |dir|
  FSEvent.new.tap do |ev|
    ev.watch(dir) do |directories|
      puts "Change in #{dir}: #{directories.inspect}"
    end
  end
end

threads = []

fs.map do |fs|
  threads << Thread.new do
    fs.run
  end
end

threads.map(&:join)

@rymai
Copy link
Member

rymai commented Nov 3, 2015

@fxn I can reproduce the really weird behavior using Listen 3.0.3 on OSX

@e2 Testing bare rb-fsevent with your script above, every change is detected properly so the issue is definitely in Listen... :/

I'll try with your add_fsevent_debug branch...

@e2
Copy link
Contributor

e2 commented Nov 3, 2015

@fxn, @rymai - I've pushed a new branch with more debugs.

I'm guessing not all the workers are being run. Probably a bug in the weird iteration I wrote.

@rymai
Copy link
Member

rymai commented Nov 3, 2015

Ok. It's becoming weirder:

› LISTEN_GEM_DEBUGGING=2 ruby listen.rb
I, [2015-11-03T15:14:12.867130 #7738]  INFO -- : Listen loglevel set to: 0
I, [2015-11-03T15:14:12.867201 #7738]  INFO -- : Listen version: 3.0.3
D, [2015-11-03T15:14:12.867665 #7738] DEBUG -- : Adapter: considering polling ...
D, [2015-11-03T15:14:12.867753 #7738] DEBUG -- : Adapter: considering optimized backend...
D, [2015-11-03T15:14:12.868298 #7738] DEBUG -- : fsevent: watching: "/Volumes/Code/Dailymotion/dailymotion/foo"
D, [2015-11-03T15:14:12.868407 #7738] DEBUG -- : fsevent: watching: "/Volumes/Code/Dailymotion/dailymotion/bar"
D, [2015-11-03T15:14:12.868461 #7738] DEBUG -- : fsevent: watching: "/Volumes/Code/Dailymotion/dailymotion/baz"
I, [2015-11-03T15:14:12.874315 #7738]  INFO -- : Record.build(): 0.00019 seconds
D, [2015-11-03T15:14:12.874362 #7738] DEBUG -- : Waiting for processing to start...
I, [2015-11-03T15:14:12.874594 #7738]  INFO -- : Record.build(): 0.00016 seconds
I, [2015-11-03T15:14:12.874935 #7738]  INFO -- : Record.build(): 0.00015 seconds
D, [2015-11-03T15:14:12.874967 #7738] DEBUG -- : fsevent: workers: 3
D, [2015-11-03T15:14:12.875205 #7738] DEBUG -- : fsevent: running first worker: #<FSEvent:0x007f9c701834e0 @paths=["/Volumes/Code/Dailymotion/dailymotion/baz"], @callback=#<Proc:0x007f9c70183558@/Users/remy/.gem/ruby/2.2.3/bundler/gems/listen-9dde04508a52/lib/listen/adapter/base.rb:41 (lambda)>, @options=["--latency", "0.1"]>
D, [2015-11-03T15:14:12.875293 #7738] DEBUG -- : fsevent: running worker: #<FSEvent:0x007f9c701834e0 @paths=["/Volumes/Code/Dailymotion/dailymotion/baz"], @callback=#<Proc:0x007f9c70183558@/Users/remy/.gem/ruby/2.2.3/bundler/gems/listen-9dde04508a52/lib/listen/adapter/base.rb:41 (lambda)>, @options=["--latency", "0.1"]>
D, [2015-11-03T15:14:12.875366 #7738] DEBUG -- : fsevent: running worker: #<FSEvent:0x007f9c701834e0 @paths=["/Volumes/Code/Dailymotion/dailymotion/baz"], @callback=#<Proc:0x007f9c70183558@/Users/remy/.gem/ruby/2.2.3/bundler/gems/listen-9dde04508a52/lib/listen/adapter/base.rb:41 (lambda)>, @options=["--latency", "0.1"]>

Then I touch foo/a.txt, the following output is printed by Listen:

D, [2015-11-03T15:14:17.568535 #7738] DEBUG -- : fsevent: processing event: ["/Volumes/Code/Dailymotion/dailymotion/foo/"]
D, [2015-11-03T15:14:17.568724 #7738] DEBUG -- : fsevent: /Volumes/Code/Dailymotion/dailymotion/foo
D, [2015-11-03T15:14:17.569602 #7738] DEBUG -- : unknown: dir:/Volumes/Code/Dailymotion/dailymotion/foo ({:recursive=>true})
D, [2015-11-03T15:14:17.570069 #7738] DEBUG -- : Scanning: .({:recursive=>true}): {"a.txt"=>{:mtime=>1446560007.0, :mode=>33188}} -> #<Set: {#<Pathname:/Volumes/Code/Dailymotion/dailymotion/foo/a.txt>}>
D, [2015-11-03T15:14:17.570413 #7738] DEBUG -- : unknown: file:/Volumes/Code/Dailymotion/dailymotion/foo/a.txt ({})
D, [2015-11-03T15:14:17.671152 #7738] DEBUG -- : listen: raw changes: [[:modified, "/Volumes/Code/Dailymotion/dailymotion/foo/a.txt"]]
D, [2015-11-03T15:14:17.671271 #7738] DEBUG -- : listen: final changes: {:modified=>["/Volumes/Code/Dailymotion/dailymotion/foo/a.txt"], :added=>[], :removed=>[]}
D, [2015-11-03T15:14:17.671348 #7738] DEBUG -- : Callback took 1.0013580322265625e-05 sec

Then I touch bar/b.txt, no output is printed by Listen.

Then I touch baz/c.txt, the following output is printed by Listen:

D, [2015-11-03T15:14:25.657057 #7738] DEBUG -- : fsevent: processing event: ["/Volumes/Code/Dailymotion/dailymotion/baz/"]
D, [2015-11-03T15:14:25.657186 #7738] DEBUG -- : fsevent: /Volumes/Code/Dailymotion/dailymotion/baz
D, [2015-11-03T15:14:25.657452 #7738] DEBUG -- : unknown: dir:/Volumes/Code/Dailymotion/dailymotion/baz ({:recursive=>true})
D, [2015-11-03T15:14:25.657769 #7738] DEBUG -- : Scanning: .({:recursive=>true}): {"c.txt"=>{:mtime=>1446560019.0, :mode=>33188}} -> #<Set: {#<Pathname:/Volumes/Code/Dailymotion/dailymotion/baz/c.txt>}>
D, [2015-11-03T15:14:25.658009 #7738] DEBUG -- : unknown: file:/Volumes/Code/Dailymotion/dailymotion/baz/c.txt ({})
D, [2015-11-03T15:14:25.759181 #7738] DEBUG -- : listen: raw changes: [[:modified, "/Volumes/Code/Dailymotion/dailymotion/baz/c.txt"]]
D, [2015-11-03T15:14:25.759269 #7738] DEBUG -- : listen: final changes: {:modified=>["/Volumes/Code/Dailymotion/dailymotion/baz/c.txt"], :added=>[], :removed=>[]}
D, [2015-11-03T15:14:25.759325 #7738] DEBUG -- : Callback took 4.0531158447265625e-06 sec

So in my case, only modifications in a file in the first and last folders are reported.

Also, from the output above, there seem to be a an issue with the fsevent workers:

D, [2015-11-03T15:14:12.868298 #7738] DEBUG -- : fsevent: watching: "/Volumes/Code/Dailymotion/dailymotion/foo"
D, [2015-11-03T15:14:12.868407 #7738] DEBUG -- : fsevent: watching: "/Volumes/Code/Dailymotion/dailymotion/bar"
D, [2015-11-03T15:14:12.868461 #7738] DEBUG -- : fsevent: watching: "/Volumes/Code/Dailymotion/dailymotion/baz"
[...]
D, [2015-11-03T15:14:12.874967 #7738] DEBUG -- : fsevent: workers: 3
D, [2015-11-03T15:14:12.875205 #7738] DEBUG -- : fsevent: running first worker: #<FSEvent:0x007f9c701834e0 @paths=["/Volumes/Code/Dailymotion/dailymotion/baz"], @callback=#<Proc:0x007f9c70183558@/Users/remy/.gem/ruby/2.2.3/bundler/gems/listen-9dde04508a52/lib/listen/adapter/base.rb:41 (lambda)>, @options=["--latency", "0.1"]>
D, [2015-11-03T15:14:12.875293 #7738] DEBUG -- : fsevent: running worker: #<FSEvent:0x007f9c701834e0 @paths=["/Volumes/Code/Dailymotion/dailymotion/baz"], @callback=#<Proc:0x007f9c70183558@/Users/remy/.gem/ruby/2.2.3/bundler/gems/listen-9dde04508a52/lib/listen/adapter/base.rb:41 (lambda)>, @options=["--latency", "0.1"]>
D, [2015-11-03T15:14:12.875366 #7738] DEBUG -- : fsevent: running worker: #<FSEvent:0x007f9c701834e0 @paths=["/Volumes/Code/Dailymotion/dailymotion/baz"], @callback=#<Proc:0x007f9c70183558@/Users/remy/.gem/ruby/2.2.3/bundler/gems/listen-9dde04508a52/lib/listen/adapter/base.rb:41 (lambda)>, @options=["--latency", "0.1"]>

Actually, there seem to be only one worker (and callback) for the three watchers:

  • FSEvent worker: FSEvent:0x007f9c701834e0
  • Callback: Proc:0x007f9c70183558

That's probably the issue...

@e2
Copy link
Contributor

e2 commented Nov 3, 2015

@fxn , @rymai - yeah, I screwed up.

Should be fixed on that branch now.

I'll probably have to clean up, add tests and release a fix.

@fxn
Copy link
Author

fxn commented Nov 3, 2015

Awesome @e2 anything I can help with having OS X just tell me!

@e2
Copy link
Contributor

e2 commented Nov 3, 2015

@fxn - if you can confirm it works, I'll release tomorrow. (Ping me if I happen to forget. Unlikely).

@fxn
Copy link
Author

fxn commented Nov 3, 2015

Affirmatifve! Checked a few changes in a hello world Rails app and they are all being detected now.

@rymai
Copy link
Member

rymai commented Nov 4, 2015

I confirm this fixes the issue for me too! Thanks @e2!

@e2
Copy link
Contributor

e2 commented Nov 4, 2015

Guys, this is getting weirder and weirder every minute. I refactored the code at a bit ... and basically ended up with the same thing as in the current released version.

Please let me know if the branch works.

The only things I've "changed" to get the fixed you guys confirmed are:

  1. moving the require statement to the top of the file
  2. Collecting workers from the Thread::Queue into an array before iterating

I'm guessing that by adding the debugs I've avoided a race condition of some kind. This doesn't make any sense, since rb-fsevent uses pipes.

Can you try with and without debugging if it works? Please included a debug dump if not (because I had debugs messed up before).

I could release the fix, but I want to be sure it's really fixed (which I doubt).

I'm guessing the problem occurs with more than 2 directory arguments. E.g. I don't know how it would be different with e.g. 5 or more directory arguments.

The first directory should always work.

Maybe rb-fsevent doesn't like opening new connections in multiple threads simultaneously?

I could provide a minor "sleep" option, but that's a lame solution, really.

If this last commit on that branch works (@efe6b86), I'm baffled, because there's just some refactoring: https://github.com/guard/listen/compare/add_fsevent_debug

@rymai
Copy link
Member

rymai commented Nov 4, 2015

Indeed @e2, the issue is back!

Using your branch, I'm watching foo, foo2, foo3, bar and baz with debugging enabled:

› LISTEN_GEM_DEBUGGING=2 ruby sync-to-dev.rb
I, [2015-11-04T13:56:24.779282 #18802]  INFO -- : Listen loglevel set to: 0
I, [2015-11-04T13:56:24.779355 #18802]  INFO -- : Listen version: 3.0.3
D, [2015-11-04T13:56:24.779616 #18802] DEBUG -- : Adapter: considering polling ...
D, [2015-11-04T13:56:24.779660 #18802] DEBUG -- : Adapter: considering optimized backend...
D, [2015-11-04T13:56:24.780025 #18802] DEBUG -- : fsevent: watching: "/Volumes/Code/Dailymotion/dailymotion/foo"
D, [2015-11-04T13:56:24.780086 #18802] DEBUG -- : fsevent: watching: "/Volumes/Code/Dailymotion/dailymotion/foo2"
D, [2015-11-04T13:56:24.780140 #18802] DEBUG -- : fsevent: watching: "/Volumes/Code/Dailymotion/dailymotion/foo3"
D, [2015-11-04T13:56:24.780188 #18802] DEBUG -- : fsevent: watching: "/Volumes/Code/Dailymotion/dailymotion/bar"
D, [2015-11-04T13:56:24.780231 #18802] DEBUG -- : fsevent: watching: "/Volumes/Code/Dailymotion/dailymotion/baz"
I, [2015-11-04T13:56:24.785954 #18802]  INFO -- : Record.build(): 0.00025 seconds
D, [2015-11-04T13:56:24.786002 #18802] DEBUG -- : Waiting for processing to start...
I, [2015-11-04T13:56:24.786222 #18802]  INFO -- : Record.build(): 0.00017 seconds
I, [2015-11-04T13:56:24.786588 #18802]  INFO -- : Record.build(): 0.00011 seconds
I, [2015-11-04T13:56:24.786736 #18802]  INFO -- : Record.build(): 0.00012 seconds
I, [2015-11-04T13:56:24.786837 #18802]  INFO -- : Record.build(): 0.00008 seconds
D, [2015-11-04T13:56:24.787091 #18802] DEBUG -- : fsevent: running worker: #<FSEvent:0x007ffe14e83f90 @paths=["/Volumes/Code/Dailymotion/dailymotion/foo"], @callback=#<Proc:0x007ffe14e88108@/Users/remy/.gem/ruby/2.2.3/bundler/gems/listen-efe6b864b52a/lib/listen/adapter/base.rb:41 (lambda)>, @options=["--latency", "0.1"]>
D, [2015-11-04T13:56:24.789067 #18802] DEBUG -- : fsevent: running worker: #<FSEvent:0x007ffe14e82af0 @paths=["/Volumes/Code/Dailymotion/dailymotion/baz"], @callback=#<Proc:0x007ffe14e82b68@/Users/remy/.gem/ruby/2.2.3/bundler/gems/listen-efe6b864b52a/lib/listen/adapter/base.rb:41 (lambda)>, @options=["--latency", "0.1"]>
D, [2015-11-04T13:56:24.790821 #18802] DEBUG -- : fsevent: running worker: #<FSEvent:0x007ffe14e82af0 @paths=["/Volumes/Code/Dailymotion/dailymotion/baz"], @callback=#<Proc:0x007ffe14e82b68@/Users/remy/.gem/ruby/2.2.3/bundler/gems/listen-efe6b864b52a/lib/listen/adapter/base.rb:41 (lambda)>, @options=["--latency", "0.1"], @pipe=#<IO:fd 10>, @running=true>
D, [2015-11-04T13:56:24.792763 #18802] DEBUG -- : fsevent: running worker: #<FSEvent:0x007ffe14e82af0 @paths=["/Volumes/Code/Dailymotion/dailymotion/baz"], @callback=#<Proc:0x007ffe14e82b68@/Users/remy/.gem/ruby/2.2.3/bundler/gems/listen-efe6b864b52a/lib/listen/adapter/base.rb:41 (lambda)>, @options=["--latency", "0.1"], @pipe=#<IO:fd 11>, @running=true>
D, [2015-11-04T13:56:24.796443 #18802] DEBUG -- : fsevent: running worker: #<FSEvent:0x007ffe14e82af0 @paths=["/Volumes/Code/Dailymotion/dailymotion/baz"], @callback=#<Proc:0x007ffe14e82b68@/Users/remy/.gem/ruby/2.2.3/bundler/gems/listen-efe6b864b52a/lib/listen/adapter/base.rb:41 (lambda)>, @options=["--latency", "0.1"], @pipe=#<IO:fd 12>, @running=true>
D, [2015-11-04T13:56:28.943408 #18802] DEBUG -- : fsevent: processing event: ["/Volumes/Code/Dailymotion/dailymotion/foo/"]
D, [2015-11-04T13:56:28.943723 #18802] DEBUG -- : fsevent: /Volumes/Code/Dailymotion/dailymotion/foo
D, [2015-11-04T13:56:28.944649 #18802] DEBUG -- : unknown: dir:/Volumes/Code/Dailymotion/dailymotion/foo ({:recursive=>true})
D, [2015-11-04T13:56:28.945289 #18802] DEBUG -- : Scanning: .({:recursive=>true}): {"a.txt"=>{:mtime=>1446641362.0, :mode=>33188}} -> #<Set: {#<Pathname:/Volumes/Code/Dailymotion/dailymotion/foo/a.txt>}>
D, [2015-11-04T13:56:28.945704 #18802] DEBUG -- : unknown: file:/Volumes/Code/Dailymotion/dailymotion/foo/a.txt ({})
D, [2015-11-04T13:56:29.047778 #18802] DEBUG -- : listen: raw changes: [[:modified, "/Volumes/Code/Dailymotion/dailymotion/foo/a.txt"]]
D, [2015-11-04T13:56:29.047878 #18802] DEBUG -- : listen: final changes: {:modified=>["/Volumes/Code/Dailymotion/dailymotion/foo/a.txt"], :added=>[], :removed=>[]}
/Volumes/Code/Dailymotion/dailymotion/foo/a.txt
D, [2015-11-04T13:56:29.047970 #18802] DEBUG -- : Callback took 2.288818359375e-05 sec
D, [2015-11-04T13:56:37.699061 #18802] DEBUG -- : fsevent: processing event: ["/Volumes/Code/Dailymotion/dailymotion/baz/"]
D, [2015-11-04T13:56:37.699209 #18802] DEBUG -- : fsevent: /Volumes/Code/Dailymotion/dailymotion/baz
D, [2015-11-04T13:56:37.699717 #18802] DEBUG -- : unknown: dir:/Volumes/Code/Dailymotion/dailymotion/baz ({:recursive=>true})
D, [2015-11-04T13:56:37.700103 #18802] DEBUG -- : Scanning: .({:recursive=>true}): {"c.txt"=>{:mtime=>1446641380.0, :mode=>33188}} -> #<Set: {#<Pathname:/Volumes/Code/Dailymotion/dailymotion/baz/c.txt>}>
D, [2015-11-04T13:56:37.700654 #18802] DEBUG -- : unknown: file:/Volumes/Code/Dailymotion/dailymotion/baz/c.txt ({})
D, [2015-11-04T13:56:37.802427 #18802] DEBUG -- : listen: raw changes: [[:modified, "/Volumes/Code/Dailymotion/dailymotion/baz/c.txt"]]
D, [2015-11-04T13:56:37.802515 #18802] DEBUG -- : listen: final changes: {:modified=>["/Volumes/Code/Dailymotion/dailymotion/baz/c.txt"], :added=>[], :removed=>[]}
/Volumes/Code/Dailymotion/dailymotion/baz/c.txt
D, [2015-11-04T13:56:37.802588 #18802] DEBUG -- : Callback took 1.52587890625e-05 sec

No without the degugging flag:

› ruby sync-to-dev.rb                       
/Volumes/Code/Dailymotion/dailymotion/foo/a.txt
/Volumes/Code/Dailymotion/dailymotion/baz/c.txt

Only the first and last changes are detected in both cases, it's totally logical when looking at the worker initialization debug messages:

D, [2015-11-04T13:56:24.787091 #18802] DEBUG -- : fsevent: running worker: #<FSEvent:0x007ffe14e83f90 @paths=["/Volumes/Code/Dailymotion/dailymotion/foo"], @callback=#<Proc:0x007ffe14e88108@/Users/remy/.gem/ruby/2.2.3/bundler/gems/listen-efe6b864b52a/lib/listen/adapter/base.rb:41 (lambda)>, @options=["--latency", "0.1"]>
D, [2015-11-04T13:56:24.789067 #18802] DEBUG -- : fsevent: running worker: #<FSEvent:0x007ffe14e82af0 @paths=["/Volumes/Code/Dailymotion/dailymotion/baz"], @callback=#<Proc:0x007ffe14e82b68@/Users/remy/.gem/ruby/2.2.3/bundler/gems/listen-efe6b864b52a/lib/listen/adapter/base.rb:41 (lambda)>, @options=["--latency", "0.1"]>
D, [2015-11-04T13:56:24.790821 #18802] DEBUG -- : fsevent: running worker: #<FSEvent:0x007ffe14e82af0 @paths=["/Volumes/Code/Dailymotion/dailymotion/baz"], @callback=#<Proc:0x007ffe14e82b68@/Users/remy/.gem/ruby/2.2.3/bundler/gems/listen-efe6b864b52a/lib/listen/adapter/base.rb:41 (lambda)>, @options=["--latency", "0.1"], @pipe=#<IO:fd 10>, @running=true>
D, [2015-11-04T13:56:24.792763 #18802] DEBUG -- : fsevent: running worker: #<FSEvent:0x007ffe14e82af0 @paths=["/Volumes/Code/Dailymotion/dailymotion/baz"], @callback=#<Proc:0x007ffe14e82b68@/Users/remy/.gem/ruby/2.2.3/bundler/gems/listen-efe6b864b52a/lib/listen/adapter/base.rb:41 (lambda)>, @options=["--latency", "0.1"], @pipe=#<IO:fd 11>, @running=true>
D, [2015-11-04T13:56:24.796443 #18802] DEBUG -- : fsevent: running worker: #<FSEvent:0x007ffe14e82af0 @paths=["/Volumes/Code/Dailymotion/dailymotion/baz"], @callback=#<Proc:0x007ffe14e82b68@/Users/remy/.gem/ruby/2.2.3/bundler/gems/listen-efe6b864b52a/lib/listen/adapter/base.rb:41 (lambda)>, @options=["--latency", "0.1"], @pipe=#<IO:fd 12>, @running=true>

Workers 2 to 5 are actually a single worker FSEvent:0x007ffe14e82af0 watching the last path given to Listen (i.e. /Volumes/Code/Dailymotion/dailymotion/baz) with the same callback (i.e. Proc:0x007ffe14e82b68).

The only things I've "changed" to get the fixed you guys confirmed are:

  1. moving the require statement to the top of the file
  2. Collecting workers from the Thread::Queue into an array before iterating

I think the second change was fixing the issue.

@e2
Copy link
Contributor

e2 commented Nov 4, 2015

Yeah, I worked it out again. Weird. I just happened to work it out at first, and today I forgot what the problem was.

The issue is using the local variable worker from multiple threads. I keep forgetting passing blocks to threads is dangerous.

@fxn
Copy link
Author

fxn commented Nov 4, 2015

If I am not mistaken, the patch that fixed the issue in the branch yesterday was 155c86b. I don't know listen internals, but at first sight the patch matched what we were seeing, the iteration only stored the first and last stuff.

Wasn't it enough?

@e2
Copy link
Contributor

e2 commented Nov 4, 2015

@fxn - fix coming soon. That patch works, but it hides the problem - so I just need to clean up a little.

(The fact that it worked was a side-effect of the iteration).

@fxn
Copy link
Author

fxn commented Nov 4, 2015

@e2 awesome :).

@e2
Copy link
Contributor

e2 commented Nov 4, 2015

Ok, I couldn't create a test for this (because it's all about thread initialization speed - not to easy to simulate).

But, I'll release this. Can you confirm it works? (Just to make sure ...)

@fxn
Copy link
Author

fxn commented Nov 4, 2015

👍 over here!

@e2 e2 closed this as completed in 104ef72 Nov 4, 2015
e2 added a commit that referenced this issue Nov 4, 2015
stop sharing mutable var among threads [fix #351]
@e2
Copy link
Contributor

e2 commented Nov 4, 2015

Released as 3.0.4 Thanks guys!

@fxn
Copy link
Author

fxn commented Nov 4, 2015

Thanks a lot for your quick support @e2!

@rymai
Copy link
Member

rymai commented Nov 4, 2015

Awesome work @e2, thanks for the quick fix!!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants