search

zizi4n5 / homebridge-switchbot-for-mac

Homebridge SwitchBot is plugin for Homebridge that allows you to manage SwitchBot.
MIT License
18 stars 3 forks source link

Failing to turn on #13

Closed benjaminbogdanovic closed 4 years ago

benjaminbogdanovic commented 4 years ago

After about two days of HomeBridge running, the plugin fails to turn on any of my SwitchBot’s. The official app is able to turn them on.

Does the plugin only ‘discover’ devices at startup, or does it do it periodically to check that they are still available while running?

zizi4n5 commented 4 years ago

In my environment, I have never failed to operate a device that was successfully discovered. For this reason, I now try to discover the device only at startup.

Once the operation fails, does it always fail thereafter? Can you provide me with a log of the errors?

benjaminbogdanovic commented 4 years ago

It sometimes continues to fail and then needs restarting, but sometimes it recovers and starts working again.

Failures seem to start after a turn on command is sent, but there is no response, so I try to turn on again. This is highlighted in bold.

Example of when it fails, but then recovers:

[7/9/2020, 11:26:34 AM] [Bathroom Lights] Turning on... [7/9/2020, 11:26:57 AM] [Bathroom Lights] Turning on... [7/9/2020, 11:26:57 AM] [Bathroom Lights] WoHand (FF:3C:1E:80:2B:C7) was failed turning on [7/9/2020, 11:27:12 AM] [Bathroom Lights] Turning on... [7/9/2020, 11:27:12 AM] [Bathroom Lights] WoHand (FF:3C:1E:80:2B:C7) was failed turning on [7/9/2020, 11:27:17 AM] [Bathroom Fan] Turning on... [7/9/2020, 11:27:17 AM] [Bathroom Lights] Turning on... [7/9/2020, 11:27:17 AM] [Bathroom Fan] WoHand (E6:4C:11:57:38:6D) was failed turning on [7/9/2020, 11:27:17 AM] [Bathroom Lights] WoHand (FF:3C:1E:80:2B:C7) was failed turning on [7/9/2020, 11:27:19 AM] [Bathroom Fan] Turning on... [7/9/2020, 11:27:19 AM] [Bathroom Lights] Turning on... [7/9/2020, 11:27:19 AM] [Bathroom Fan] WoHand (E6:4C:11:57:38:6D) was failed turning on [7/9/2020, 11:27:19 AM] [Bathroom Lights] WoHand (FF:3C:1E:80:2B:C7) was failed turning on [7/9/2020, 11:27:20 AM] [Bathroom Lights] Turning on... [7/9/2020, 11:27:20 AM] [Bathroom Lights] WoHand (FF:3C:1E:80:2B:C7) was failed turning on [7/9/2020, 11:27:25 AM] [Bathroom Lights] Turning on... [7/9/2020, 11:27:25 AM] [Bathroom Lights] WoHand (FF:3C:1E:80:2B:C7) was failed turning on [7/9/2020, 11:27:32 AM] [Bathroom Fan] WoHand (E6:4C:11:57:38:6D) was turned on [7/9/2020, 11:27:33 AM] [Bathroom Lights] WoHand (FF:3C:1E:80:2B:C7) was turned on [7/9/2020, 12:39:24 PM] [Bathroom Lights] Turning off... [7/9/2020, 12:39:25 PM] [Bathroom Lights] WoHand (FF:3C:1E:80:2B:C7) was turned off [7/9/2020, 12:41:23 PM] [Bathroom Lights] Turning on...

An example of a failure requiring a restart:

[7/7/2020, 6:30:55 PM] [Entrance Door] Turning on... [7/7/2020, 6:31:13 PM] [Entrance Door] Turning on... [7/7/2020, 6:31:13 PM] [Entrance Door] WoHand (F1:C2:FB:BE:95:70) was failed turning on [7/7/2020, 6:31:41 PM] [Entrance Door] Turning on... [7/7/2020, 6:31:41 PM] [Entrance Door] WoHand (F1:C2:FB:BE:95:70) was failed turning on [7/7/2020, 6:31:47 PM] [Bathroom Fan] Turning off... [7/7/2020, 6:32:56 PM] [Entrance Door] Turning on... [7/7/2020, 6:32:56 PM] [Entrance Door] WoHand (F1:C2:FB:BE:95:70) was failed turning on [7/7/2020, 6:34:17 PM] [Entrance Door] Turning on... [7/7/2020, 6:34:17 PM] [Entrance Door] WoHand (F1:C2:FB:BE:95:70) was failed turning on [7/7/2020, 6:34:38 PM] [Entrance Door] Turning on... [7/7/2020, 6:34:38 PM] [Entrance Door] WoHand (F1:C2:FB:BE:95:70) was failed turning on [7/7/2020, 6:34:44 PM] [Bathroom Fan] Turning off... [7/7/2020, 6:34:44 PM] [Bathroom Fan] WoHand (E6:4C:11:57:38:6D) was failed turning off [7/7/2020, 6:34:51 PM] [Config] Homebridge restart request received

zizi4n5 commented 4 years ago

What is the OS version of macOS?

benjaminbogdanovic commented 4 years ago

10.15.5 Supplemental Update (19F101)

zizi4n5 commented 4 years ago

Released 0.1.4, which 3 retries when a turn fails. Please check if this problem has been fixed in 0.1.4.

If the problem still occurs, please reopen this Issue and provide the logs collected with homebridge in DEBUG mode.

benjaminbogdanovic commented 4 years ago

It was working fine until there was a failure. I didn't manage to get it in debug mode. I will post if I do.

[7/12/2020, 10:15:06 PM] [Bathroom Lights] Turning on... [7/12/2020, 10:15:06 PM] [Bathroom Lights] WoHand (FF:3C:1E:80:2B:C7) was failed turning on [7/12/2020, 10:15:06 PM] [Bathroom Lights] Error: Now connecting. Wait for a few seconds then try again. at /usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:103:16 at new Promise (:null:null) at SwitchbotDeviceWoHand._connect (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:96:12) at /usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:401:12 at new Promise (:null:null) at SwitchbotDeviceWoHand._command (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:393:12) at /usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device-wohand.js:91:12 at new Promise (:null:null) at SwitchbotDeviceWoHand._operateBot (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device-wohand.js:89:12) at SwitchbotDeviceWoHand.turnOn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device-wohand.js:40:17) at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:76:54) at runMicrotasks (:null:null) at processTicksAndRejections (internal/process/task_queues.js:97:5) at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:86:17) at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:86:17) at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:86:17) at SwitchBotAccessory.setOn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:170:13)

zizi4n5 commented 4 years ago

Thank you for providing the log.

The BLE connection process was failing in the OSS used in the plugin. It seems to be difficult to fix the problem because it is a problem of OSS side.

Is it possible to set a schedule to reboot mac once a day?

benjaminbogdanovic commented 4 years ago

I can schedule a reboot.

Should I revert to the pervious version of the plugin, or will the current one be okay?

zizi4n5 commented 4 years ago

You should be fine with the latest version. Version 0.1.4 just adding retries on errors, so the errors that can be handled by retries should be improved.

benjaminbogdanovic commented 4 years ago

Was this delay addressed in previous fixes?

image

zizi4n5 commented 4 years ago

I haven't had a delay of more than a minute in my environment, but I improved the retry process when bluetooth is temporarily disconnected at version 0.2.0, so that may be the effect.

https://github.com/zizi4n5/homebridge-switchbot-for-mac/releases/tag/v0.2.0

Added support for retry to device detection when a device is not found.

benjaminbogdanovic commented 4 years ago

I haven't had a delay of more than a minute in my environment, but I improved the retry process when bluetooth is temporarily disconnected at version 0.2.0, so that may be the effect.

https://github.com/zizi4n5/homebridge-switchbot-for-mac/releases/tag/v0.2.0

Added support for retry to device detection when a device is not found.

Thanks. Good to know.

benjaminbogdanovic commented 4 years ago

Thank you for providing the log.

The BLE connection process was failing in the OSS used in the plugin.

It seems to be difficult to fix the problem because it is a problem of OSS side.

Is it possible to set a schedule to reboot mac once a day?

I am still occasionally getting the failures despite restarting daily.

How does the retry feature work? From looking at the code, it just retries sending the command, but not rediscovering/reconnecting to the device. I find that it always successfully discovers and does not fail after restarting HomeBridge. If it is not using the method of discovery/connection used at startup, would it be possible to trigger that method after a failure?

zizi4n5 commented 4 years ago

In version 0.2.0, if a device is not found at turning, plugin retry to discover() again. https://github.com/zizi4n5/homebridge-switchbot-for-mac/blob/b161db0fbe5cb2b14535254f902cea95a8eea4c4/src/accessory.ts#L88-L92

For the following, I have forked the OSS and changed it to use my own modified version. https://github.com/zizi4n5/node-switchbot

Thank you for providing the log. The BLE connection process was failing in the OSS used in the plugin. It seems to be difficult to fix the problem because it is a problem of OSS side.

See below for the differences from the original. https://github.com/futomi/node-switchbot/compare/master...zizi4n5:develop

Is the error log in debug mode the same as last time? If not, please provide a log.

It was working fine until there was a failure. I didn't manage to get it in debug mode. I will post if I do.

[7/12/2020, 10:15:06 PM] [Bathroom Lights] Turning on... [7/12/2020, 10:15:06 PM] [Bathroom Lights] WoHand (FF:3C:1E:80:2B:C7) was failed turning on [7/12/2020, 10:15:06 PM] [Bathroom Lights] Error: Now connecting. Wait for a few seconds then try again. at /usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:103:16 at new Promise (:null:null) at SwitchbotDeviceWoHand._connect (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:96:12) at /usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:401:12 at new Promise (:null:null) at SwitchbotDeviceWoHand._command (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:393:12) at /usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device-wohand.js:91:12 at new Promise (:null:null) at SwitchbotDeviceWoHand._operateBot (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device-wohand.js:89:12) at SwitchbotDeviceWoHand.turnOn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device-wohand.js:40:17) at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:76:54) at runMicrotasks (:null:null) at processTicksAndRejections (internal/process/task_queues.js:97:5) at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:86:17) at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:86:17) at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:86:17) at SwitchBotAccessory.setOn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:170:13)

benjaminbogdanovic commented 4 years ago

See below for the differences from the original. futomi/node-switchbot@master...zizi4n5:develop

Thank you for the clarification.

Is the error log in debug mode the same as last time? If not, please provide a log.

It was not running in debug at the time unfortunately. I forgot to turn it back on after a rebuild of HomeBridge.

Here is the log, it retried 3 times as set in the config:

[7/26/2020, 11:29:05 AM] [Bathroom Fan] Turning on...
[7/26/2020, 11:29:05 AM] [Bathroom Fan] WoHand (E6:4C:11:57:38:6D) was failed turning on
[7/26/2020, 11:29:05 AM] [Bathroom Fan] Error: Now connecting. Wait for a few seconds then try again.
    at /usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:116:16
    at new Promise (<anonymous>:null:null)
    at SwitchbotDeviceWoHand._connect (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:103:12)
    at /usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:416:12
    at new Promise (<anonymous>:null:null)
    at SwitchbotDeviceWoHand._command (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:408:12)
    at /usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device-wohand.js:91:12
    at new Promise (<anonymous>:null:null)
    at SwitchbotDeviceWoHand._operateBot (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device-wohand.js:89:12)
    at SwitchbotDeviceWoHand.turnOn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device-wohand.js:40:17)
    at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:91:54)
    at runMicrotasks (<anonymous>:null:null)
    at processTicksAndRejections (internal/process/task_queues.js:97:5)
    at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:101:17)
    at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:101:17)
    at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:101:17)
    at SwitchBotAccessory.setOn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:185:13)

[7/26/2020, 11:29:06 AM] [Bathroom Lights] Turning on...
[7/26/2020, 11:29:06 AM] [Bathroom Lights] WoHand (FF:3C:1E:80:2B:C7) was failed turning on
[7/26/2020, 11:29:06 AM] [Bathroom Lights] Error: Now connecting. Wait for a few seconds then try again.
    at /usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:116:16
    at new Promise (<anonymous>:null:null)
    at SwitchbotDeviceWoHand._connect (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:103:12)
    at /usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:416:12
    at new Promise (<anonymous>:null:null)
    at SwitchbotDeviceWoHand._command (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:408:12)
    at /usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device-wohand.js:91:12
    at new Promise (<anonymous>:null:null)
    at SwitchbotDeviceWoHand._operateBot (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device-wohand.js:89:12)
    at SwitchbotDeviceWoHand.turnOn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device-wohand.js:40:17)
    at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:91:54)
    at runMicrotasks (<anonymous>:null:null)
    at processTicksAndRejections (internal/process/task_queues.js:97:5)
    at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:101:17)
    at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:101:17)
    at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:101:17)
    at SwitchBotAccessory.setOn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:185:13)
benjaminbogdanovic commented 4 years ago

This has also started happening: image

zizi4n5 commented 4 years ago

It has been improved to try-catch when an exception is thrown when discover() is executed, so I think that's why.

https://github.com/zizi4n5/homebridge-switchbot-for-mac/blob/b161db0fbe5cb2b14535254f902cea95a8eea4c4/src/accessory.ts#L70-L84

What happens if you turn on/off after this error?

benjaminbogdanovic commented 4 years ago

This happened on a later attempt after turning on/off:

 [7/27/2020, 4:49:17 AM]   [Entrance Door]  WoHand (F1:C2:FB:BE:95:70) was not found 
 [7/27/2020, 4:49:17 AM]   [Bathroom Lights]  WoHand (FF:3C:1E:80:2B:C7) was not found 
 [7/27/2020, 4:49:17 AM]   [Bathroom Fan]   WoHand (E6:4C:11:57:38:6D) was not found 
 [7/27/2020, 4:51:06 AM]   [Entrance Door]  Turning on...
 [7/27/2020, 4:51:14 AM]   [Entrance Door]  WoHand (F1:C2:FB:BE:95:70) was not found 
 [7/27/2020, 4:51:14 AM]   [Entrance Door]  WoHand (F1:C2:FB:BE:95:70) was not found. so retry discover.
 [7/27/2020, 4:51:49 AM]   [Entrance Door]  WoHand (F1:C2:FB:BE:95:70) was discovered
 [7/27/2020, 4:51:49 AM]   [Entrance Door]  WoHand (F1:C2:FB:BE:95:70) was failed turning on 
 [7/27/2020, 4:51:49 AM]   [Entrance Door]  Error: Now connecting. Wait for a few seconds then try again. 
     at /usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:116:16 
     at new Promise (<anonymous>:null:null) 
     at SwitchbotDeviceWoHand._connect (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:103:12) 
     at /usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:416:12 
     at new Promise (<anonymous>:null:null) 
     at SwitchbotDeviceWoHand._command (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device.js:408:12) 
     at /usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device-wohand.js:91:12 
     at new Promise (<anonymous>:null:null) 
     at SwitchbotDeviceWoHand._operateBot (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device-wohand.js:89:12) 
     at SwitchbotDeviceWoHand.turnOn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/node_modules/node-switchbot/lib/switchbot-device-wohand.js:40:17) 
     at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:91:54) 
     at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:101:17) 
     at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:101:17) 
     at WoHand.turn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:101:17) 
     at SwitchBotAccessory.setOn (/usr/local/lib/node_modules/homebridge-switchbot-for-mac/dist/accessory.js:185:13) 
 [7/27/2020, 4:51:50 AM]   [Entrance Door]  WoHand (F1:C2:FB:BE:95:70) was turned on

Is that the expected behaviour?

zizi4n5 commented 4 years ago

Let me check your situation.

Did updating to version 0.2.0 make things worse? Or are you saying that the situation is almost identical to version 0.1.4, but the error messages have changed?

benjaminbogdanovic commented 4 years ago

It has gotten worse in 0.2.0. There seem to be more failures requiring rediscovery, so it takes longer to carry out the command as it has to rediscover. When operated through Siri, it says that the device has not responded, then when it does eventually reconnect and turn on the device, in the home app it says that it is not on. Pressing it to turn on changes the state in the home app, and on the log it says the device is already on, which is correct.

On a side note, is it possible to extend the period of time Siri waits/the point it is told there is a failure before saying the devices has not responded? Perhaps until all the retires are complete?

zizi4n5 commented 4 years ago

The same error occurred in my environment and I'll investigate it over the weekend.

On a side note, is it possible to extend the period of time Siri waits/the point it is told there is a failure before saying the devices has not responded? Perhaps until all the retires are complete?

Sorry, I don't know how to extend the time that Siri is waiting.

benjaminbogdanovic commented 4 years ago

The same error occurred in my environment and I'll investigate it over the weekend.

That would be great.

Sorry, I don't know how to extend the time that Siri is waiting.

That's okay.