Having trouble with change listening using rsync

[Paul BH]

Hey all,

 so I'm using Guard / Guard-rspec and have run into an issue that I'm trying to isolate.

The setup I have:

developing on Mac OS 10.9

running Vagrant with rysnc-auto to push changes into my Virtual Machine (Ubuntu 12.04)

What I find is that about half of the time things work, but sometimes the specs dont get run. This seems to be down to the way that listener is reporting filesystem changes and the resolution of this bug: https://github.com/guard/guard/issues/495

Basically - it looks like listener is reporting the file change as an addition not a modification, and because guard-rspec is currently setup to only fire on modifications (because of above issue). Below is the debug output with listener gem debugging switched on too...

My current workaround is to use polling, but I'm wondering if you guys have an idea how I might go about resolving this. Trying to figure out if it's an issue with rsync, listener, guard-rspec or what?

Any suggestions?

Cheers!

Paul

I, [2014-09-04T14:40:35.996557 #31999]  INFO -- : Celluloid loglevel set to: 1
14:40:36 - DEBUG - Command execution: which notify-send

14:40:36 - DEBUG - Command execution: emacsclient --eval '1' 2> /dev/null || echo 'N/A'

14:40:36 - INFO - Guard is using NotifySend to send notifications.

14:40:36 - INFO - Guard is using TerminalTitle to send notifications.

14:40:36 - DEBUG - Command execution: hash stty

14:40:36 - DEBUG - Guard starts all plugins

14:40:36 - DEBUG - Hook :start_begin executed for Guard::RSpec

14:40:36 - INFO - Guard::RSpec is running

14:40:36 - DEBUG - Hook :start_end executed for Guard::RSpec

14:40:36 - INFO - Guard is now watching at '/app'

I, [2014-09-04T14:40:36.259714 #31999]  INFO -- : Record.build took 0.002643108367919922 seconds

14:40:36 - DEBUG - Start interactor

[1] guard(main)> I, [2014-09-04T14:40:43.867556 #31999]  INFO -- : listen: raw changes: [[:added, "/app/config/routes.rb"], [nil, "/app/config/.routes.rb.Okdfbz"]]

I, [2014-09-04T14:40:43.867710 #31999]  INFO -- : listen: final changes: {:modified=>[], :added=>["/app/config/routes.rb"], :removed=>[]}

14:40:43 - DEBUG - Stop interactor

14:40:43 - DEBUG - Trying to run Guard::RSpec#run_on_additions with ["spec/routing"]

14:40:43 - DEBUG - Trying to run Guard::RSpec#run_on_changes with ["spec/routing"]

14:40:43 - DEBUG - Trying to run Guard::RSpec#run_on_change with ["spec/routing"]

14:40:43 - DEBUG - Start interactor

[1] guard(main)> I, [2014-09-04T14:40:52.224413 #31999]  INFO -- : listen: raw changes: [[:added, "/app/config/routes.rb"], [nil, "/app/config/.routes.rb.Yzacjn"]]

I, [2014-09-04T14:40:52.224717 #31999]  INFO -- : listen: final changes: {:modified=>[], :added=>["/app/config/routes.rb"], :removed=>[]}

14:40:52 - DEBUG - Stop interactor

14:40:52 - DEBUG - Trying to run Guard::RSpec#run_on_additions with ["spec/routing"]

14:40:52 - DEBUG - Trying to run Guard::RSpec#run_on_changes with ["spec/routing"]

14:40:52 - DEBUG - Trying to run Guard::RSpec#run_on_change with ["spec/routing"]

14:40:52 - DEBUG - Start interactor

[1] guard(main)> I, [2014-09-04T14:40:55.583645 #31999]  INFO -- : listen: raw changes: [[nil, "/app/config/.routes.rb.TsiciV"], [:added, "/app/config/routes.rb"]]

I, [2014-09-04T14:40:55.583904 #31999]  INFO -- : listen: final changes: {:modified=>[], :added=>["/app/config/routes.rb"], :removed=>[]}

14:40:55 - DEBUG - Stop interactor

14:40:55 - DEBUG - Trying to run Guard::RSpec#run_on_additions with ["spec/routing"]

14:40:55 - DEBUG - Trying to run Guard::RSpec#run_on_changes with ["spec/routing"]

14:40:55 - DEBUG - Trying to run Guard::RSpec#run_on_change with ["spec/routing"]

14:40:55 - DEBUG - Start interactor

[1] guard(main)> I, [2014-09-04T14:40:55.712311 #31999]  INFO -- : listen: raw changes: [[:modified, "/app/config/routes.rb"]]

I, [2014-09-04T14:40:55.712470 #31999]  INFO -- : listen: final changes: {:modified=>["/app/config/routes.rb"], :added=>[], :removed=>[]}

14:40:55 - DEBUG - Stop interactor

14:40:55 - DEBUG - Hook :run_on_modifications_begin executed for Guard::RSpec

14:40:55 - INFO - Running: spec/routing

[Paul BH]

In case this helps anyone, I ended up solving this by changing guard-rspec to run_on_changes instead of run_on_modifications (would reintroduce issue 495, but at the moment I just need this working for me), and running guard with the listen wait_on_delay set to a second (guard -y 1)

If anyone wants to use my branch, you can get at it here: https://github.com/eyefodder/guard-rspec/tree/run_on_additions

Would love to figure out a more robust solution that works for everyone's setup though

[Cezary Baginski]

Hi Paul,

It's best to post issues like directly on Github (I don't watch this group that often).

In fact, move this there, since others may have the same issue.

My first impression:

Yes, this seems to be a problem with Listen detecting modified files as added. 

This is a tricky issue, because editors usually implement a "save" as a complex set of file operations.

I got this working reasonably well on Linux, due to some magic "editor support" that's baked into Listen.

This magic wasn't ever implemented on MacOS (I haven't touched a Mac in years - I'm Linux-only), so while I can't test it, I could help get this working.

Polling works because it gives enough of a delay that it never realizes the file was ever deleted. Mac OS is faster, so it catches the "disappearance" and concludes the file was added.

So basically you should be able to reproduce the problem using Listen locally on a MacOS (you shouldn't be getting any "added" events).

If you can, run the binary included with listen, with the '-v' flag, and set the environment variable `LISTEN_GEM_DEBUGGING=2`, modify a file in the editor (are you using Emacs?) and paste the output in a gist.

If I can get enough info to reproduce this in a test case, I can likely fix it quickly.

So just post a new issue in Listen with the output dump - and I'll try and take it from there.

[Paul BH]

will do, thanks Cezary!