search

AlexGustafsson / homebridge-wol

A Wake on Lan plugin for Homebridge
MIT License
301 stars 30 forks source link

Shutting Down Status Issue #31

Closed hawkefly closed 6 years ago

hawkefly commented 6 years ago

When Shutting Down fail , I mean command execute successful, but actually fail ,the network still active, the status will maintain Shutting Down, and the pinger cannot change back the status to Online again. I think it should change to the actual status after a timeout

AlexGustafsson commented 6 years ago

When the shutdown command is issued, the status is shown to be turned off and a timer starts to count down depending on the shutdown grace time configured. When the grace time is over, the actual status is shown once again.

Have you tried changing the shutdown grace time to a lower value in your configuration? Lowering the value will return the actual status of the device faster, but may also show the device as on during the shutdown process (when it works).

hawkefly commented 6 years ago

I config "shutdownCommand:date" to reproduce my issue(command execute successful but actually fail) { "accessory": "NetworkDevice", "name": "Mac", "mac": "00:11:22:33:44:55", "ip": "192.168.1.236", "pingInterval": 10, "shutdownCommand": "date", "shutdownGraceTime": 15, "logPinger": true } Add this line in pingerCallback(newState) function to print more log this.log('currentState: %s, newState: %s, this.status: %s', this.getValueOfSymbol(currentState), this.getValueOfSymbol(newState), this.getValueOfSymbol(this.status));

and this is the output

[3/3/2018, 10:13:19 PM] Homebridge is running on port 51826. [3/3/2018, 10:13:19 PM] [Mac] currentState: false, newState: true, this.status: Offline [3/3/2018, 10:13:19 PM] [Mac] Pinger toggled state change [3/3/2018, 10:13:19 PM] [Mac] NetworkDevice "Mac" (192.168.1.236) went from status "Offline" to "Online" [3/3/2018, 10:13:24 PM] [Mac] NetworkDevice shutdown cycle started for "Mac" (192.168.1.236) [3/3/2018, 10:13:24 PM] [Mac] Stopping pinger [3/3/2018, 10:13:24 PM] [Mac] Starting pinger again in 15000 milli seconds [3/3/2018, 10:13:24 PM] [Mac] Attempting to shut down "Mac" (192.168.1.236) using "date" [3/3/2018, 10:13:24 PM] [Mac] NetworkDevice "Mac" (192.168.1.236) went from status "Online" to "Shutting Down" [3/3/2018, 10:13:39 PM] [Mac] Stopping pinger [3/3/2018, 10:13:39 PM] [Mac] Starting pinger at an interval of 10000 milli seconds [3/3/2018, 10:13:39 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:13:49 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:13:59 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:14:09 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:14:19 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:14:29 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:14:39 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:14:49 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:14:59 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:15:09 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:15:19 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:15:29 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:15:39 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:15:49 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:15:59 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:16:09 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:16:19 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:16:29 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:16:39 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:16:49 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down [3/3/2018, 10:16:59 PM] [Mac] currentState: true, newState: true, this.status: Shutting Down

AlexGustafsson commented 6 years ago

Now I see what you mean. In lib/network-device.js try to change lines 81-88 (pingerCallback(newState)) to the following:

pingerCallback(newState) {
   // The line under this comment has been changed - make sure both Offline and ShuttingDown is thought of as the host being down
    const currentState = this.status !== Status.Offline && this.status !== Status.ShuttingDown;
    // Debouncing - only react to a change if it has actually changed
    if (newState !== currentState) {
      this.pingLog('Pinger toggled state change');
      this.setStatus(newState ? Status.Online : Status.Offline);
    }
  }

The fault seems to be in the code thinking that everything that is not Offline is on. When the shutdownCommand is called, the host is put in the ShuttingDown mode. After 15 seconds the pinger starts to ping the host and realizes it is turned on. The pinger tells the server that the device is on, but it doesn't listen - it already thinks that the host is up since it's in ShuttingDown mode. This change makes the server listen to when the pinger says the host is up.

Please test the change and post any logs just like you did above.

hawkefly commented 6 years ago

Yes, this resolved my issue.Thanks.

[3/5/2018, 9:06:39 PM] Homebridge is running on port 51826. [3/5/2018, 9:06:39 PM] [Mac] currentState: false, newState: true, this.status: Offline [3/5/2018, 9:06:39 PM] [Mac] Pinger toggled state change [3/5/2018, 9:06:39 PM] [Mac] NetworkDevice "Mac" (192.168.1.236) went from status "Offline" to "Online" [3/5/2018, 9:06:46 PM] [Mac] NetworkDevice shutdown cycle started for "Mac" (192.168.1.236) [3/5/2018, 9:06:46 PM] [Mac] Stopping pinger [3/5/2018, 9:06:46 PM] [Mac] Starting pinger again in 15000 milli seconds [3/5/2018, 9:06:46 PM] [Mac] Attempting to shut down "Mac" (192.168.1.236) using "date" [3/5/2018, 9:06:46 PM] [Mac] NetworkDevice "Mac" (192.168.1.236) went from status "Online" to "Shutting Down" [3/5/2018, 9:07:01 PM] [Mac] Stopping pinger [3/5/2018, 9:07:01 PM] [Mac] Starting pinger at an interval of 10000 milli seconds [3/5/2018, 9:07:01 PM] [Mac] currentState: false, newState: true, this.status: Shutting Down [3/5/2018, 9:07:01 PM] [Mac] Pinger toggled state change [3/5/2018, 9:07:01 PM] [Mac] NetworkDevice "Mac" (192.168.1.236) went from status "Shutting Down" to "Online" [3/5/2018, 9:07:11 PM] [Mac] currentState: true, newState: true, this.status: Online [3/5/2018, 9:07:21 PM] [Mac] currentState: true, newState: true, this.status: Online

AlexGustafsson commented 6 years ago

Thank you, @hawkefly for helping me fix that bug! It's fixed in 3.2.1 which is now released to NPM so that you can safely use the latest available version.

cr3ative commented 6 years ago

Hi, this means that the status can never go from Shutting Down to Offline. This means subsequent attempts to power it on are ignored as it's in an intermediate state.

I'm preparing a PR which should address this.