A few problems with pingCommand

amaisano commented 5 years ago

Backstory

I'm using the pingCommand due to using displaysleep instead of a full sleep or other power state. My code is correctly returning "1" (error) for when the display is off, and "0" for all other states (eg. display is on). I am also providing an IP address in my config, because otherwise there is no status report and the pingCommand isn't fired.

However, when I use pingCommand, there are two major issues manifesting in the homekit app:

After tapping OFF on my mac, a spinner appears for roughly 60 seconds, regardless of my timeout, pingInterval, and grace config times.
When the spinner stops, the device in Homekit is in the wrong state, even though in reality the mac was successfully adjusted by this plugin. Furthermore, an exlamation mark appears for that device in homekit following all switch interactions.

If I wait a few moments, then force quite and re-open homekit, the device properly shows it's homebridge status accurately, and the (!) clears itself. Swiping between rooms until "Updating..." appears on the devices also clears the error and switches the device to the correct status, as well as locking the screen and then returning to HomeKit.

Watch video proof

Why does the spinner take so long?
Why does every interaction in Homekit while using a pingCommand cause a (!) error icon
Why is an IP address required for the pingCommand (which is supposed to be an alternative to the default ping) to function?

Issue

As I said, I tried minimizing all the ping, timeout, and wait times, but it still takes a minute or more in Homekit for the button to update.

NOTE: This issues doesn't seem to happen when just using the default PING method (no pingCommand). Status updates are instantaneous when not using a pingCommand, and just using ping (like when I turn off my Windows 10 machine).

Environment

os & os version: macOS 10.12.6
node version: v10.16.0
homebridge version: 0.4.50
homebridge-wol version: master:e9ed848

Configuration

My configuration looks like this:

...
  "accessories": [
    {
      "accessory": "Chamberlain",
      "name": "Garage",
      "username": "******",
      "password": "****",
      "deviceId": "*****"
    },
    {
      # THIS IS THE HOMEBRIDGE DEVICE
      "accessory": "NetworkDevice",
      "name": "HammerHead",
      "mac": <MACADDR>,
      "ip": "192.168.86.72",
      "wakeGraceTime": 0,
      "wakeCommand": "caffeinate -dsuid -t 10",
      "shutdownCommand": "pmset displaysleepnow",
      "shutdownGraceTime": 5,
      "pingCommand": "/var/homebridge/scripts/pingHostDisplay atwixtor localhost",
      "logPinger": true
    },
    {
      "accessory": "NetworkDevice",
      "name": "Twix",
      "mac": <MACADDR>,
      "ip": "192.168.86.24",
      "wakeGraceTime": 0,
      "wakeCommand": "ssh amaisano@192.168.86.24 -i ~/.ssh/homebridge caffeinate -dsuid -t 10",
      "shutdownCommand": "ssh amaisano@192.168.86.24 -i ~/.ssh/homebridge pmset displaysleepnow",
      "shutdownGraceTime": 5,
      "pingCommand": "/var/homebridge/scripts/pingHostDisplay amaisano 192.168.86.24",
      "logPinger": true
    },
    {
      "accessory": "NetworkDevice",
      "name": "Bebop",
      "mac": <MACADDR>,
      "ip": "192.168.86.71",
      "shutdownCommand": "ssh adamo@192.168.86.71 -i ~/.ssh/homebridge psshutdown -d -t 1",
      "logPinger": true
    }
  ],
...

Log

When I follow these steps:

Run DEBUG=* homebridge
Let it run for five minutes
Tap a switch
Wait one minute
Tap the same switch

I get the following log:

[6/21/2019, 9:38:44 PM] [Twix] NetworkDevice shutdown cycle started for "Twix" (192.168.86.24)
[6/21/2019, 9:38:44 PM] [Twix] Attempting to shut down "Twix" (192.168.86.24) using "ssh amaisano@192.168.86.24 -i ~/.ssh/homebridge pmset displaysleepnow"
[6/21/2019, 9:38:44 PM] [Twix] NetworkDevice "Twix" (192.168.86.24) went from status "Online" to "Shutting Down"
[6/21/2019, 9:38:44 PM] [Twix] Stopping pinger
[6/21/2019, 9:38:44 PM] [Twix] Stopping pinger
[6/21/2019, 9:38:44 PM] [Twix] Starting pinger at an interval of 2000 milli seconds
[6/21/2019, 9:38:45 PM] [Twix] Pinger can't see device; setting to Offline.
[6/21/2019, 9:38:45 PM] [Twix] NetworkDevice "Twix" (192.168.86.24) went from status "Shutting Down" to "Offline"

--- WAIT THEN TAP AGAIN ---

[6/21/2019, 9:42:09 PM] [Twix] NetworkDevice awake cycle started for "Twix" (192.168.86.24)
[6/21/2019, 9:42:09 PM] [Twix] Attempting to wake up "Twix" (192.168.86.24)
[6/21/2019, 9:42:09 PM] [Twix] NetworkDevice "Twix" (192.168.86.24) went from status "Offline" to "Waking Up"
[6/21/2019, 9:42:09 PM] [Twix] Stopping pinger
[6/21/2019, 9:42:09 PM] [Twix] Attempting to wake up "Twix" (192.168.86.24) using "ssh amaisano@192.168.86.24 -i ~/.ssh/homebridge caffeinate -dsuid -t 10"
[6/21/2019, 9:42:09 PM] [Twix] Stopping pinger
[6/21/2019, 9:42:09 PM] [Twix] Starting pinger at an interval of 2000 milli seconds
[6/21/2019, 9:42:10 PM] [Twix] Pinger saw device online; setting to Online.
[6/21/2019, 9:42:10 PM] [Twix] NetworkDevice "Twix" (192.168.86.24) went from status "Waking Up" to "Online"
[6/21/2019, 9:42:19 PM] [Twix] Attempting to wake up "Twix" (192.168.86.24) using "ssh amaisano@192.168.86.24 -i ~/.ssh/homebridge caffeinate -dsuid -t 10"
[6/21/2019, 9:42:19 PM] [Twix] Stopping pinger
[6/21/2019, 9:42:19 PM] [Twix] Starting pinger at an interval of 2000 milli seconds

Note that it happened twice for some reason (the wake up tap).

AlexGustafsson commented 5 years ago

Why does the spinner take so long?

I've had similar issues when using Homebridge my self and do not think this is entirely related to this plugin itself. There have been issues every now and then on the Homebridge repository. Unfortunately I haven't used it for a while so I am unsure of the current state of the issue.

As for this plugin's connection with the issue, this plugins work the same way I've seen other plugins do when it comes to triggering the update. I am yet to see an official way of doing so, so there might be an issue here.

Why does every interaction in Homekit while using a pingCommand cause a (!) error icon There might be issues with the master branch right now. I have not come across the issue you describe previously and there are likely untested, breaking stuff in the master branch.

See the milestone 3.3 for progress.

Why is an IP address required for the pingCommand (which is supposed to be an alternative to the default ping) to function?

That's a mistake on my part. Thank you for telling me about this issue!

AlexGustafsson commented 5 years ago

I've fixed the issue where pingCommand would only be used if and IP was set. The other issues remain unsolved. The change is currently in the master branch, but has not been published to NPM.

amaisano commented 5 years ago

Thanks! Quick work.

While I was waiting, I fooled around with the homebridge-ssh plugin and was able to mostly recreate the functionality I am trying to achieve here:

        {
            "accessory": "SSH",
            "name": "PC",
            "on": "ssh user@localhost \"/usr/local/bin/wakeonlan -i 192.168.86.71 -p 7 ma:ca:dr:es:ss\"",
            "off": "ssh user@localhost \"ssh pc_user@192.168.86.71 psshutdown -d -t 1\"",
            "state": "ping -c1 -t2 192.168.86.71 &>/dev/null && echo 'online' || echo 'offline'",
            "on_value": "online",
            "ssh": {
                "user": "user",
                "host": "localhost",
                "key": "/Users/homebridge/.ssh/homebridge"
            }
        }

^^^ this is operating from the homebridge server machine (Mac), not the target PC machine

I'll go back and try this all again in a couple days after updating my plugins :)

AlexGustafsson commented 4 years ago

I've published 3.2.5 to NPM now. If you don't experience these issues any more, feel free to close this issue.

AlexGustafsson commented 4 years ago

There are known issues with 3.2.5. Try to use the master branch instead or wait for 4.0.0 to be published.

For 4.0.0 I have an updated answer to why the spinner is taking so long:

The plugin uses wake and shutdown grace time to allow a computer to start up and shutdown before polling again for status change. This usually allows for a more consistent appearance in the Home app. During this grace time, the request to either wake or shutdown the device will be pending and as such display a spinner in the Home app.

You can experiment with wakeGraceTime and shutdownGraceTime to fit your needs.

Closing for now. Feel free to open a new issue if you come across any problem.

AlexGustafsson / homebridge-wol