Garage door status gets out of sync
jimcrammond opened this issue · 5 comments
After closing the garage door with the Home app, the garage door status is displayed as closed as soon as the door is closed (and DoorSensor.Alert message is sent) but then after I wake up the app it will show as open. If I close the app and open ithe app again then it shows closed again.
While this is a minor annoyance, there are times when the status changes into a transition state (e.g. "closing") instead. If it does that when I am using CarPlay then I cannot open/close the door. (You can't just open/close CarPlay easily)
The other thing of note is that the report time in the log messages for the door sensor are wrong. When the door sensor is initially queried, it sends back a report-at time which is then never updated in subsequent logs. I don't know if this is significant - e.g. if status update messages are ignored due to a "old" timestamp.
Example Log:
[1/21/2024, 2:22:27 PM] [YoLink] [verbose] RECEIVED:
{"code":"000000","time":1705875747913,"msgid":1705875747913,"method":"GarageDoor.toggle","desc":"Success","data":{"stateChangedAt":1705875747912,"loraInfo":{"netId":"010202","signal":-39,"gatewayId":"d88b4c160301cf20","gateways":1}}}
[1/21/2024, 2:22:27 PM] [YoLink] [verbose] Set garage door timer for 30 seconds with targetState 'closed'
[1/21/2024, 2:22:38 PM] [YoLink] [verbose] MQTT message: yl-home/73cf50a4fdc2447ba26f14fabeb8bf6f/d88b4c0100058915/report
{
"event": "DoorSensor.Alert",
"time": 1705875758687,
"msgid": "1705875758686",
"data": {
"state": "closed",
"alertType": "normal",
"battery": 4,
"version": "060e",
"loraInfo": {
"netId": "010201",
"signal": -21,
"gateways": 1
},
"stateChangedAt": 1705875758686
},
"deviceId": "d88b4c0100058915"
}
[1/21/2024, 2:22:38 PM] [YoLink] [verbose] [YS7706-UC (d88b4c0100058915) Garage Door Sensor] Battery level: 100%
[1/21/2024, 2:22:38 PM] [YoLink] [YS7706-UC (d88b4c0100058915) Garage Door Sensor] At **1/21/2024, 12:01:32 PM**: Device state: DoorSensor: closed, Alert: normal, Battery: 4 (MQTT: DoorSensor.Alert) [lite]
**App shows closed at this point**
[1/21/2024, 2:23:44 PM] [YoLink] [verbose] [YS7706-UC (d88b4c0100058915) Garage Door Sensor] checkDeviceState (refresh after 14500 seconds)
[1/21/2024, 2:23:44 PM] [YoLink] [YS7706-UC (d88b4c0100058915) Garage Door Sensor] At 1/21/2024, 12:01:32 PM: Device state: Sensor: closed, Battery: 4, rc: 1 [lite]
[1/21/2024, 2:23:44 PM] [YoLink] [verbose] [YS4906-UC (d88b4c010005952c) Garage Door Controller] checkDeviceState (refresh after 14500 seconds)
[1/21/2024, 2:23:44 PM] [YoLink] [YS4906-UC (d88b4c010005952c) Garage Door Controller] At 1/21/2024, 2:22:38 PM: Device state updated: Garage Door or Finger: , rc: 1 [lite]
**App shows open at this point**
**Close/Open the App at this point**
[1/21/2024, 2:25:34 PM] [YoLink] [verbose] [YS7706-UC (d88b4c0100058915) Garage Door Sensor] checkDeviceState (refresh after 14500 seconds)
[1/21/2024, 2:25:34 PM] [YoLink] [YS7706-UC (d88b4c0100058915) Garage Door Sensor] At 1/21/2024, 12:01:32 PM: Device state: Sensor: closed, Battery: 4, rc: 1 [lite]
[1/21/2024, 2:25:34 PM] [YoLink] [verbose] [YS4906-UC (d88b4c010005952c) Garage Door Controller] checkDeviceState (refresh after 14500 seconds)
[1/21/2024, 2:25:34 PM] [YoLink] [YS4906-UC (d88b4c010005952c) Garage Door Controller] At 1/21/2024, 2:22:38 PM: Device state: Garage Door or Finger: , rc: 1 [lite]
**App shows closed at this point**
[1/21/2024, 2:25:52 PM] [YoLink] [verbose] [YS7706-UC (d88b4c0100058915) Garage Door Sensor] checkDeviceState (refresh after 14500 seconds)
[1/21/2024, 2:25:52 PM] [YoLink] [YS7706-UC (d88b4c0100058915) Garage Door Sensor] At 1/21/2024, 12:01:32 PM: Device state: Sensor: closed, Battery: 4, rc: 1 [lite]
[1/21/2024, 2:25:52 PM] [YoLink] [verbose] [YS4906-UC (d88b4c010005952c) Garage Door Controller] checkDeviceState (refresh after 14500 seconds)
[1/21/2024, 2:25:52 PM] [YoLink] [YS4906-UC (d88b4c010005952c) Garage Door Controller] At 1/21/2024, 2:22:38 PM: Device state: Garage Door or Finger: , rc: 1 [lite]
[1/21/2024, 2:25:59 PM] [YoLink] [verbose] [YS4906-UC (d88b4c010005952c) Garage Door Controller] checkDeviceState (refresh after 14500 seconds)
[1/21/2024, 2:25:59 PM] [YoLink] [YS4906-UC (d88b4c010005952c) Garage Door Controller] At 1/21/2024, 2:22:38 PM: Device state: Garage Door or Finger: , rc: 1 [lite]
[1/21/2024, 2:25:59 PM] [YoLink] [verbose] [YS7706-UC (d88b4c0100058915) Garage Door Sensor] checkDeviceState (refresh after 14500 seconds)
[1/21/2024, 2:25:59 PM] [YoLink] [YS7706-UC (d88b4c0100058915) Garage Door Sensor] At 1/21/2024, 12:01:32 PM: Device state: Sensor: closed, Battery: 4, rc: 1 [lite]
- Plugin Version: 1.5.4
- Homebridge Version: 1.7.0
- Node.js Version: v18.13.0
- Operating System: QNAP / Docker
Thanks for the report. I'll look into this and see if I can reproduce. I know I have seen device states get out-of-sync myself, not necessarily garage doors and also not necessarily those that connect through this plugin. But there may be something I can do to make it more reliable.
Edited your post to wrap the log in code quotations so it is easier to read.
First thing to note in this is the return code rc: value. It is always showing 1 which means closed. In other words, my plugin is always reporting the door as closed.
Now there are two accessory characteristics that come into play here... Characteristic.CurrentDoorState and Characteristic.TargetDoorState The first of those is only reported by/for the door sensor and it cannot be set (is read only value). The target door state is only applicable for the door controller and it can be both read and written (set).
When Apple Home sets target door state to zero 0 then it means open the door. When set to one 1 it means close the door. So here is the question... once the door has completed the open/close action, how should the plugin respond to Apple Home requests for the value of target door state? At the moment the plugin responds with 1 indicating that the door target state is closed, it also responded that the current door state is 1. All should be happy. But is Apple Home interpreting it differently?
I remember when developing this I had all sorts of issues trying to get the Apple Home app to report correctly... for example it would get stuck in the opening or closing state and not register that the action had completed and door was now open or closed.
Not sure how to solve this, but at your 2:23:44 timestamp I see that the sensor is returning current state as closed, and that the controller is returning target state as closed. So why the app thinks the door is open I do not know.
I have found the source of this issue. The function handleGet in garagedoor.js will call handleGetBlocking to update the door state but will immediately return the currentState of the door. However, this currentState is not updated when the door is toggled, only when the handleGetBlocking function is called. So currentState as returned by handleGet will be out of sync on the first call after a toggle (until handleGetBlocking completes).
A solution is to update the currentState value in the MQTT message handler where the Characteristic.CurrentDoorState value is updated after a DoorSensor.Alert message.
Hah. Thank you. Yes indeed that does look like a problem, thanks for tracking that down for me. I'll fix and publish new version.
The reason for separating handleGet and handleGetBlocking is because the Yolink API / LoRa radio protocol is so slow... and can be error prone, so I may have to retry requesting the data. Homebridge complains when plugins are slow to respond to requests. So, as you observed, I asynchronously call the blocking function and immediately return what I think is the current state... when the blocking function finally completes, the actual state is updated. But, as you have found, I missed the step of keeping currentState, well current, by updating it in the MQTT handler. Oops.
Published an update now, hopefully fixes it.