FSEV stopped every time Mac OS High Sierra sleeps

[ms-ati]

This appears to be a similar issue to #262, however the current behavior is on 4.6.4 on High Sierra and with a slightly different error log, please see below.

On Mac OS High Sierra, using Dinghy version 4.6.4, nearly every time that my laptop wakes from sleep, I see the following:

---

Dinghy status

$ dinghy status
   VM: running
  NFS: running
 FSEV: stopped
  DNS: running
PROXY: running

FsEvents failed to run
details available in log file: /usr/local/Cellar/dinghy/4.6.4/local/var/dinghy-FsEvents.output

Your environment variables are already set correctly.

---

FsEvents Error Log

$ cat /usr/local/Cellar/dinghy/4.6.4/local/var/dinghy-FsEvents.output

=== Starting FsEvents at 2018-06-20T11:05:35-04:00 ===

`rror running command `gtouch -m -c -d 2018-06-20T22:39:10.137628790Z /Users/username/Dropbox/Icon\
Errno::EHOSTUNREACH: No route to host - recvfrom(2)
    /usr/local/Cellar/dinghy/4.6.4/cli/net-ssh/lib/net/ssh/buffered_io.rb:65:in `recv'
    /usr/local/Cellar/dinghy/4.6.4/cli/net-ssh/lib/net/ssh/buffered_io.rb:65:in `fill'
    /usr/local/Cellar/dinghy/4.6.4/cli/net-ssh/lib/net/ssh/connection/session.rb:272:in `block in ev_do_handle_events'
    /usr/local/Cellar/dinghy/4.6.4/cli/net-ssh/lib/net/ssh/connection/session.rb:268:in `each'
    /usr/local/Cellar/dinghy/4.6.4/cli/net-ssh/lib/net/ssh/connection/session.rb:268:in `ev_do_handle_events'
    /usr/local/Cellar/dinghy/4.6.4/cli/net-ssh/lib/net/ssh/connection/event_loop.rb:110:in `ev_select_and_postprocess'
    /usr/local/Cellar/dinghy/4.6.4/cli/net-ssh/lib/net/ssh/connection/event_loop.rb:29:in `process'
    /usr/local/Cellar/dinghy/4.6.4/cli/net-ssh/lib/net/ssh/connection/session.rb:225:in `process'
    /usr/local/Cellar/dinghy/4.6.4/cli/net-ssh/lib/net/ssh/connection/session.rb:178:in `block in loop'
    /usr/local/Cellar/dinghy/4.6.4/cli/net-ssh/lib/net/ssh/connection/session.rb:178:in `loop'
    /usr/local/Cellar/dinghy/4.6.4/cli/net-ssh/lib/net/ssh/connection/session.rb:178:in `loop'
    /usr/local/Cellar/dinghy/4.6.4/cli/net-ssh/lib/net/ssh/connection/channel.rb:269:in `wait'
    /usr/local/Cellar/dinghy/4.6.4/cli/net-ssh/lib/net/ssh/connection/session.rb:425:in `exec!'
    /usr/local/Cellar/dinghy/4.6.4/cli/fsevents_to_vm/lib/fsevents_to_vm/ssh_exec.rb:15:in `exec!'
    /usr/local/Cellar/dinghy/4.6.4/cli/fsevents_to_vm/lib/fsevents_to_vm/ssh_emit.rb:12:in `emit!'
    /usr/local/Cellar/dinghy/4.6.4/cli/fsevents_to_vm/lib/fsevents_to_vm/cli.rb:34:in `block in start'
    /usr/local/Cellar/dinghy/4.6.4/cli/fsevents_to_vm/lib/fsevents_to_vm/watch.rb:14:in `block (2 levels) in run'
    /usr/local/Cellar/dinghy/4.6.4/cli/fsevents_to_vm/lib/fsevents_to_vm/watch.rb:12:in `each'
    /usr/local/Cellar/dinghy/4.6.4/cli/fsevents_to_vm/lib/fsevents_to_vm/watch.rb:12:in `block in run'
    /usr/local/Cellar/dinghy/4.6.4/cli/rb-fsevent/lib/rb-fsevent/fsevent.rb:77:in `run'
    /usr/local/Cellar/dinghy/4.6.4/cli/fsevents_to_vm/lib/fsevents_to_vm/watch.rb:17:in `run'
    /usr/local/Cellar/dinghy/4.6.4/cli/fsevents_to_vm/lib/fsevents_to_vm/cli.rb:28:in `start'
    /usr/local/Cellar/dinghy/4.6.4/cli/thor/lib/thor/command.rb:27:in `run'
    /usr/local/Cellar/dinghy/4.6.4/cli/thor/lib/thor/invocation.rb:126:in `invoke_command'
    /usr/local/Cellar/dinghy/4.6.4/cli/thor/lib/thor.rb:359:in `dispatch'
    /usr/local/Cellar/dinghy/4.6.4/cli/thor/lib/thor/base.rb:440:in `start'
    /usr/local/Cellar/dinghy/4.6.4/cli/dinghy/fsevents_to_vm.rb:39:in `run'
    /usr/local/Cellar/dinghy/4.6.4/cli/daemons/lib/daemons/application.rb:270:in `call'
    /usr/local/Cellar/dinghy/4.6.4/cli/daemons/lib/daemons/application.rb:270:in `block in start_proc'
    /usr/local/Cellar/dinghy/4.6.4/cli/daemons/lib/daemons/daemonize.rb:84:in `call_as_daemon'
    /usr/local/Cellar/dinghy/4.6.4/cli/daemons/lib/daemons/application.rb:274:in `start_proc'
    /usr/local/Cellar/dinghy/4.6.4/cli/daemons/lib/daemons/application.rb:300:in `start'
    /usr/local/Cellar/dinghy/4.6.4/cli/dinghy/daemon.rb:73:in `start'
    /usr/local/Cellar/dinghy/4.6.4/cli/dinghy/daemon.rb:14:in `up'
    /usr/local/Cellar/dinghy/4.6.4/cli/dinghy/fsevents_to_vm.rb:14:in `up'
    /usr/local/Cellar/dinghy/4.6.4/cli/cli.rb:283:in `start_services'
    /usr/local/Cellar/dinghy/4.6.4/cli/cli.rb:93:in `up'
    /usr/local/Cellar/dinghy/4.6.4/cli/thor/lib/thor/command.rb:27:in `run'
    /usr/local/Cellar/dinghy/4.6.4/cli/thor/lib/thor/invocation.rb:126:in `invoke_command'
    /usr/local/Cellar/dinghy/4.6.4/cli/thor/lib/thor.rb:359:in `dispatch'
    /usr/local/Cellar/dinghy/4.6.4/cli/thor/lib/thor/base.rb:440:in `start'
    /usr/local/bin/_dinghy_command:12:in `<main>'

[ms-ati]

Things I notice here, in no particular order:

1. Somewhere we are logging "rror" instead of "Error"
2. As the system wakes up, the SSH connection probably needs to be re-established in the case of these sorts of failures, right?

[codekitchen]

That "rror" logging is just because of the weird filename that MacOS uses for its hidden icon files -- it is "Icon\r", so while printing it out we carriage return and overwrite the first part of the line again. We could print the command as a string literal #{command.inspect} to fix.

I'm not sure why this is killing fsevents_to_vm completely though, since it is catching the error and calling SShExec#disconnect! as we'd expect. I'd expect to at least see more error logging, if that subsequent SSH reconnect fails. I'll have to see if I can repro and debug.

[codekitchen]

I was able to repro a very similar error by simply stopping dinghy while running an independent fsevents_to_vm process. The hard failure is in the @ssh.close line which fails when the SSH connection has already failed, so I've added error handling to that.

It appears the reason that second error wasn't getting logged is because the rb-fsevents library we're using to monitor FS events is swallowing that type of error and silently failing, which is disturbing. I'll see if I can do anything about that.

But this particular failure should be fixed by https://github.com/codekitchen/fsevents_to_vm/commit/9a32dbcc2589cea0cbc105b237290b54e17b215a which will be included with the next Dinghy release.

[ms-ati]

Thanks once again @codekitchen !

[ms-ati]

Hi @codekitchen ping on this -- this really makes tools like guard, as well as rails server not as useful, since we must restart dinghy after every laptop sleep? When do you think you might be able to release a new Dinghy version that has this fix?

[codekitchen]

Yeah, I've been waiting for another PR to be completed but I'm not sure where it's at so I just published version 4.6.5.