homebridge-z2m: [Bug] Innr SP 222 socket reports incorrect state to HomeKit
🎉 ✨ 🚨 Update: there’s a workaround, as @itavero says in https://github.com/itavero/homebridge-z2m/issues/383#issuecomment-1086782658 …
As reported in the issue on the Homebridge repository, a workaround seems to be to turn off
cache_statein Zigbee2MQTT.
Describe the bug
This socket has to be switched on or off twice in the Apple Home app for the state in HomeKit to sync with the state of the device.
The first time it is switched the device state changes, but the HomeKit state immediately resets to what it was before. The second time it is switched, the device state doesn’t change, and the HomeKit state is updated to reflect the real state of the device.
This is an intermittent bug: it happens almost every time, but very occasionally it will work as expected, or the Home app will catch up on its own (e.g. switch on, HomeKit immediately toggles off, and then toggles back on within a second).
Related devices
Innr SP 222
To Reproduce
Starting with the socket “off” and shown as “off” in the Home app:
- Switch the socket to “on” in the Home App.
- Log shows two MQTT messages being published immediately after each other on topic
zigbee2mqtt/Front bedroom socket:{"last_seen":"2022-02-12T13:20:54.237Z","linkquality":255,"state":"OFF"}{"last_seen":"2022-02-12T13:20:54.237Z","linkquality":255,"state":"ON"}
- The device switches on, as expected.
- The state of the switch in the Home app briefly changes to “on,” but then rapidly switches back to “off.”
The device is now “on,” and the state shown in the zigbee2mqtt Web UI includes {"state": "ON"}, but the state in the Home app is “off.”
Starting with the socket “on” and shown as “off” in the Home app, it is possible to get them back in sync:
- Switch the socket to “on” in the Home App.
- Log shows one MQTT message being published on topic
zigbee2mqtt/Front bedroom socket:{"last_seen":"2022-02-12T13:26:32.776Z","linkquality":255,"state":"ON"}
- The state of the device does not change: it remains on.
- The state of the switch in the Home app changes to “on” and stays there.
All of this then happens in reverse when starting with the device “on” and trying to turn it to “off.”
Expected behavior
Expect the device and HomeKit to stay in sync.
Wild speculation
The multiple messages, and the intermittent nature of the bug, make me wonder if there is a race condition somewhere.
The first message contains the current state of the device, and the second message the desired state of the device (e.g. when switching on, the messages are “off” then “on”). The three behaviours I’m seeing seem to map to:
- The buggy behaviour I see most of the time could reflect only the first message getting passed on to HomeKit, i.e. the state in HomeKit is changed by me pressing the button, but then changed back to the previous state by the first message.
- The more rate behaviour I see where the state in HomeKit changes twice could reflect both messages getting passed on to HomeKit, i.e. the state in HomeKit is changed by me pressing the button, but then changed back to the previous state by the first message, and then changed again to the correct state by the second message.
- The correct behaviour which I see very occasionally could reflect only the second message getting passed on to HomeKit, i.e. the state in HomeKit is changed by me pressing the button, and the second message agrees with that state so nothing changes.
Take all of this with a large grain of salt: I’ve looked at the code a bit, but nowhere near enough to be confident in this theory, it just kinda feels like a race condition 🙂
Debugging attempts
- Switching the device from the zigbee2mqtt Web UI consistently works as expected.
- Switching the device from its hardware switch consistently works as expected.
- The zigbee2mqtt
“eager”“optimistic” option is switched off. With this option switched on, the behaviour is the same but with an extra MQTT message (e.g. switching to “on” would produce “off, on, on” messages instead of just “off, on” messages) - The zigbee2mqtt “debounce” options don’t seem to make any difference.
- Disabling “reporting” for the device in zigbee2mqtt results in the first time the switch is toggled turning the device “on” but the state in both HomeKit and zigbee2mqtt remains “off”. Any further attempts to switch the device in the Home app produce a single “off” message.
MQTT messages
The device entry from zigbee2mqtt/bridge/devices
{
"date_code": "20190418-20",
"definition": {
"description": "Smart plug",
"exposes": [
{
"features": [
{
"access": 7,
"description": "On/off state of the switch",
"name": "state",
"property": "state",
"type": "binary",
"value_off": "OFF",
"value_on": "ON",
"value_toggle": "TOGGLE"
}
],
"type": "switch"
},
{
"access": 1,
"description": "Link quality (signal strength)",
"name": "linkquality",
"property": "linkquality",
"type": "numeric",
"unit": "lqi",
"value_max": 255,
"value_min": 0
}
],
"model": "SP 222",
"options": [],
"supports_ota": false,
"vendor": "Innr"
},
"endpoints": {
"1": {
"bindings": [
{
"cluster": "genOnOff",
"target": {
"endpoint": 1,
"ieee_address": "0x00212effff06f016",
"type": "endpoint"
}
}
],
"clusters": {
"input":[
"genBasic",
"genIdentify",
"genGroups",
"genScenes",
"genOnOff",
"genLevelCtrl",
"haDiagnostic",
"touchlink",
"heimanSpecificInfraRedRemote"
],
"output": [
"genTime",
"genOta"
]
},
"configured_reportings":[
{
"attribute": "onOff",
"cluster": "genOnOff",
"maximum_report_interval": 3600,
"minimum_report_interval": "0",
"reportable_change": 0
}
],
"scenes": []
},
"242": {
"bindings": [],
"clusters": {
"input" :[],
"output": ["greenPower"]
},
"configured_reportings": [],
"scenes":[]
}
},
"friendly_name": "Front bedroom socket",
"ieee_address": "0x8cf681fffe012251",
"interview_completed": true,
"interviewing": false,
"manufacturer": "innr",
"model_id": "SP 222",
"network_address": 57551,
"power_source": "Mains (single phase)",
"software_build_id": "2.1",
"supported": true,
"type":"Router"
}
Status update from zigbee2mqtt/Front bedroom socket
A series of messages from repeatedly toggling the lamp on and off via the Home app.
{"last_seen":"2022-02-12T13:52:24.527Z","linkquality":255,"state":"ON"}
{"last_seen":"2022-02-12T13:52:24.527Z","linkquality":255,"state":"OFF"}
{"last_seen":"2022-02-12T13:52:27.496Z","linkquality":255,"state":"OFF"}
{"last_seen":"2022-02-12T13:52:29.312Z","linkquality":255,"state":"OFF"}
{"last_seen":"2022-02-12T13:52:29.321Z","linkquality":255,"state":"ON"}
{"last_seen":"2022-02-12T13:52:31.194Z","linkquality":255,"state":"ON"}
{"last_seen":"2022-02-12T13:52:31.220Z","linkquality":255,"state":"OFF"}
{"last_seen":"2022-02-12T13:52:32.766Z","linkquality":255,"state":"OFF"}
{"last_seen":"2022-02-12T13:52:33.770Z","linkquality":255,"state":"OFF"}
{"last_seen":"2022-02-12T13:52:33.797Z","linkquality":255,"state":"ON"}
{"last_seen":"2022-02-12T13:52:35.135Z","linkquality":255,"state":"ON"}
{"last_seen":"2022-02-12T13:52:36.482Z","linkquality":255,"state":"ON"}
{"last_seen":"2022-02-12T13:52:36.509Z","linkquality":255,"state":"OFF"}
{"last_seen":"2022-02-12T13:52:37.794Z","linkquality":255,"state":"OFF"}
Messages published by this plugin that might be related to your issue
Logs from running homebridge -D and toggling the switch on and off.
Interestingly in this configuration, I couldn’t reproduce the typical behaviour where the device and HomeKit get out of sync, instead I consistently saw the behaviour where HomeKit would toggle twice and end up in the correct state (e.g. I switch the device “on”, the Home app immediately changes back to “off”, and then quickly changes back to “on”).
I think this lends credence to the theory that part of this is a race condition on the basis that adding more logging to code with race conditions often adds enough I/O delay to change the outcome of the race.
[12/02/2022, 13:57:27] [zigbee2mqtt] Pending data: {"state":"ON"}
[12/02/2022, 13:57:27] [zigbee2mqtt] Publish to 'zigbee2mqtt/0x8cf681fffe012251/set': '{"state":"ON"}'
[12/02/2022, 13:57:27] [zigbee2mqtt] Handled device update for Front bedroom socket: {"last_seen":"2022-02-12T13:57:27.361Z","linkquality":255,"state":"OFF"}
[12/02/2022, 13:57:28] [zigbee2mqtt] Handled device update for Front bedroom socket: {"last_seen":"2022-02-12T13:57:27.390Z","linkquality":255,"state":"ON"}
[12/02/2022, 13:57:31] [zigbee2mqtt] Pending data: {"state":"OFF"}
[12/02/2022, 13:57:31] [zigbee2mqtt] Publish to 'zigbee2mqtt/0x8cf681fffe012251/set': '{"state":"OFF"}'
[12/02/2022, 13:57:31] [zigbee2mqtt] Handled device update for Front bedroom socket: {"last_seen":"2022-02-12T13:57:31.455Z","linkquality":255,"state":"ON"}
[12/02/2022, 13:57:32] [zigbee2mqtt] Handled device update for Front bedroom socket: {"last_seen":"2022-02-12T13:57:31.482Z","linkquality":255,"state":"OFF"}
[12/02/2022, 13:57:35] [zigbee2mqtt] Pending data: {"state":"ON"}
[12/02/2022, 13:57:35] [zigbee2mqtt] Publish to 'zigbee2mqtt/0x8cf681fffe012251/set': '{"state":"ON"}'
[12/02/2022, 13:57:35] [zigbee2mqtt] Handled device update for Front bedroom socket: {"last_seen":"2022-02-12T13:57:35.780Z","linkquality":255,"state":"OFF"}
[12/02/2022, 13:57:36] [zigbee2mqtt] Handled device update for Front bedroom socket: {"last_seen":"2022-02-12T13:57:35.807Z","linkquality":255,"state":"ON"}
[12/02/2022, 13:57:39] [zigbee2mqtt] Pending data: {"state":"OFF"}
[12/02/2022, 13:57:39] [zigbee2mqtt] Publish to 'zigbee2mqtt/0x8cf681fffe012251/set': '{"state":"OFF"}'
[12/02/2022, 13:57:39] [zigbee2mqtt] Handled device update for Front bedroom socket: {"last_seen":"2022-02-12T13:57:39.954Z","linkquality":255,"state":"ON"}
[12/02/2022, 13:57:40] [zigbee2mqtt] Handled device update for Front bedroom socket: {"last_seen":"2022-02-12T13:57:39.978Z","linkquality":255,"state":"OFF"}
Versions used Please provide the version of the following pieces of software:
- This plugin 1.6.2
- Homebridge 1.4.0
- Zigbee2MQTT 1.23.0 (commit 6ea61bae2cf441e15612dc68c257797fba46312b)
- Homebridge Config UI X 4.42.0
About this issue
- Original URL
- State: closed
- Created 2 years ago
- Comments: 17 (7 by maintainers)
As reported in the issue on the Homebridge repository, a workaround seems to be to turn off
cache_statein Zigbee2MQTT.I think I actually already had this off in my setup, so that could explain why I’m not seeing this behavior.
Something changed in Homebridge, which is now making this behavior evident. Previously events would get “merged”, if they were occuring in a very short timespan (which Zigbee2MQTT can apparently trigger with the cache). This is no longer the case, resulting in two events now (one with the cached state, one with the new state) being published by Homebridge at the same time for the same attribute. The Home.app doesn’t seem to like that though.
Initially I thought adding filtering where the data comes in would solve this, but I think I actually expect the same value to be received at least twice in a row in some locations (e.g. for covers to determine that it moving). I’m now thinking about a mechanism to ensure a minimum time between the processing of MQTT messages for the same accessory.
This work around is working for me. Thanks! ✨
Leaving this issue open, since it sounds like you’re working on a deeper fix, but I’ll update the issue description with the work around for other folk who search for this issue.
I am consistently running into this bug with my setup: zigbee2mqtt + homebridge + homebridge-z2m. All lamps and switches are affected It all started with simultaneous upgrade of z2m (1.22.2 -> 1.23.0) and hb (v1.3.9 -> v1.4.0) ten days ago, but homebridge-z2m version has not changed (1.6.2)
Here you go. Note that with debug turned on it was harder to make it go wrong. Turning off seemed to trigger it the most. I can see that in 0.10.0 there are two events in the Sending HAP event message. Hope this helps:
Turn On Accessory 0.9.8
Turn Off Accessory 0.9.8
Turn On Accessory 0.10.0
Turn Off Accessory 0.10.0