Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Bug] Innr SP 222 socket reports incorrect state to HomeKit #383

Closed
georgebrock opened this issue Feb 12, 2022 · 17 comments
Closed

[Bug] Innr SP 222 socket reports incorrect state to HomeKit #383

georgebrock opened this issue Feb 12, 2022 · 17 comments
Labels
bug Something isn't working stale

Comments

@georgebrock
Copy link

georgebrock commented Feb 12, 2022

🎉 ✨ 🚨 Update: there’s a workaround, as @itavero says in #383 (comment)

As reported in the issue on the Homebridge repository, a workaround seems to be to turn off cache_state in 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:

  1. Switch the socket to “on” in the Home App.
  2. Log shows two MQTT messages being published immediately after each other on topic zigbee2mqtt/Front bedroom socket:
    1. {"last_seen":"2022-02-12T13:20:54.237Z","linkquality":255,"state":"OFF"}
    2. {"last_seen":"2022-02-12T13:20:54.237Z","linkquality":255,"state":"ON"}
  3. The device switches on, as expected.
  4. 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:

  1. Switch the socket to “on” in the Home App.
  2. Log shows one MQTT message being published on topic zigbee2mqtt/Front bedroom socket:
    1. {"last_seen":"2022-02-12T13:26:32.776Z","linkquality":255,"state":"ON"}
  3. The state of the device does not change: it remains on.
  4. 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
@georgebrock georgebrock added the bug Something isn't working label Feb 12, 2022
@itavero
Copy link
Owner

itavero commented Feb 12, 2022

Never seen this before myself. It does sound that somehow messages are being handled out of order.
I've always assumed that it would handle the messages coming in over MQTT as FIFO.

When I've time I'll see if I can somehow reproduce this.

Strange though that the debounce doesn't help. Have you also tried changing optimistic to false?

@georgebrock
Copy link
Author

When I've time I'll see if I can somehow reproduce this.

Thanks, I appreciate you looking into it!

Strange though that the debounce doesn't help. Have you also tried changing optimistic to false?

Yes, I mentioned eager somewhere in my wall of text (corrected now), but I meant optimistic: when it’s set to true I get three messages instead of two, with the same outcome.

@satter
Copy link

satter commented Feb 13, 2022

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)

@itavero
Copy link
Owner

itavero commented Feb 13, 2022

I'm still running Zigbee2MQTT 1.22.2. I'm also on Homebridge 1.4.0.

I'll see what happens if I update Zigbee2MQTT.

@georgebrock
Copy link
Author

georgebrock commented Feb 13, 2022

I tried downgrading back to Zigbee2MQTT 1.22.2, but I didn’t see any difference in behaviour.

@itavero
Copy link
Owner

itavero commented Feb 20, 2022

I've updated Zigbee2MQTT to 1.23.0, but I don't see similar behavior with any of the smart plugs I have, unfortunately.

@itavero
Copy link
Owner

itavero commented Feb 20, 2022

I wonder if this might be related to #358

@GerSant
Copy link

GerSant commented Feb 22, 2022

Hi folks! Same behaviour here with a Tuya TS130F blind cover switch, all works fine using the Zigbee2MQTT UI, but the state reported to Homekit is incorrect (swapped). When the blinds are closed (covering the window) Homekit says "Open" and viceversa.

Thanks in advance

@itavero
Copy link
Owner

itavero commented Mar 7, 2022

Did anyone try downgrading Homebridge to an older version (from before v1.4.0, i.e. v1.3.9)?

In #395, it is indicated that this improved the user experience. If so, it might be a regression in Homebridge (as mentioned in homebridge/homebridge#3073).

If anyone else gives this a try, please share your results.

@lyonanderson
Copy link

I just downgraded Homebridge from1.4.0 to 1.3.9 and it fixed the issue for me. I'm using homebridge-z2m v1.7.0.

@lyonanderson
Copy link

Interestingly I upgraded homebridge back to 1.4.0 and was able to repeat the issue. I then downgraded hap-nodejs to 0.9.8 and it fixed the issue. Homebridge 1.4.0 saw hap-nodejs upgraded from 0.9.8 to 0.10.0.

@itavero
Copy link
Owner

itavero commented Mar 15, 2022

@lyonanderson Would you be able to provide some HAP-NodeJS logs (as mentioned in the issue on the Homebridge repo)?

@lyonanderson
Copy link

lyonanderson commented Mar 15, 2022

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

2022-03-15T14:45:39.270Z HAP-NodeJS:EventedHTTPServer:Connection [::ffff:192.168.5.24] HTTP request: /characteristics
2022-03-15T14:45:39.270Z HAP-NodeJS:HAPServer [0E:5F:CE:A3:AA:E9] HAP Request: PUT /characteristics
2022-03-15T14:45:39.271Z HAP-NodeJS:Accessory [Homebridge AAE9 EBC0] Processing characteristic set: {"characteristics":[{"aid":112,"iid":11,"value":1}]}
2022-03-15T14:45:39.272Z HAP-NodeJS:EventedHTTPServer [::ffff:192.168.5.24] Muting event '112.11' notification for this connection since it originated here.
2022-03-15T14:45:39.274Z HAP-NodeJS:Accessory [Homebridge AAE9 EBC0] Setting Characteristic "On" to value 1
2022-03-15T14:45:39.276Z HAP-NodeJS:EventedHTTPServer:Connection [::ffff:192.168.5.24] HTTP Response is finished
[3/15/2022, 2:45:39 PM] [zigbee2mqtt] Publish to 'zigbee2mqtt/0x680ae2fffe598667/set': '{"state":"ON"}'
2022-03-15T14:45:39.644Z HAP-NodeJS:EventedHTTPServer:Connection [::ffff:192.168.5.24] Sending HAP event notifications [ { aid: 112, iid: 11, value: 1 } ]

Turn Off Accessory 0.9.8

2022-03-15T14:46:17.693Z HAP-NodeJS:EventedHTTPServer:Connection [::ffff:192.168.5.24] HTTP request: /characteristics
2022-03-15T14:46:17.693Z HAP-NodeJS:HAPServer [0E:5F:CE:A3:AA:E9] HAP Request: PUT /characteristics
2022-03-15T14:46:17.694Z HAP-NodeJS:Accessory [Homebridge AAE9 EBC0] Processing characteristic set: {"characteristics":[{"aid":112,"iid":11,"value":0}]}
2022-03-15T14:46:17.695Z HAP-NodeJS:EventedHTTPServer [::ffff:192.168.5.24] Muting event '112.11' notification for this connection since it originated here.
[3/15/2022, 2:46:17 PM] [zigbee2mqtt] Publish to 'zigbee2mqtt/0x680ae2fffe598667/set': '{"state":"OFF"}'
2022-03-15T14:46:17.698Z HAP-NodeJS:Accessory [Homebridge AAE9 EBC0] Setting Characteristic "On" to value 0
2022-03-15T14:46:17.699Z HAP-NodeJS:EventedHTTPServer:Connection [::ffff:192.168.5.24] HTTP Response is finished
2022-03-15T14:46:18.070Z HAP-NodeJS:EventedHTTPServer:Connection [::ffff:192.168.5.24] Sending HAP event notifications [ { aid: 112, iid: 11, value: 0 } ]

Turn On Accessory 0.10.0

2022-03-15T14:51:25.905Z HAP-NodeJS:EventedHTTPServer:Connection [::ffff:192.168.5.24] HTTP request: /characteristics
2022-03-15T14:51:25.906Z HAP-NodeJS:HAPServer [0E:5F:CE:A3:AA:E9] HAP Request: PUT /characteristics
2022-03-15T14:51:25.907Z HAP-NodeJS:Accessory [Homebridge AAE9 EBC0] Processing characteristic set: {"characteristics":[{"aid":112,"iid":11,"value":1}]}
2022-03-15T14:51:25.909Z HAP-NodeJS:EventedHTTPServer [::ffff:192.168.5.24] Muting event '112.11' notification for this connection since it originated here.
[3/15/2022, 2:51:25 PM] [zigbee2mqtt] Publish to 'zigbee2mqtt/0x680ae2fffe598667/set': '{"state":"ON"}'
2022-03-15T14:51:25.911Z HAP-NodeJS:Accessory [Homebridge AAE9 EBC0] Setting Characteristic "On" to value 1
2022-03-15T14:51:25.912Z HAP-NodeJS:EventedHTTPServer:Connection [::ffff:192.168.5.24] HTTP Response is finished
2022-03-15T14:51:26.275Z HAP-NodeJS:EventedHTTPServer:Connection [::ffff:192.168.5.24] Sending HAP event notifications [ { aid: 112, iid: 11, value: 0 }, { aid: 112, iid: 11, value: 1 } ]

Turn Off Accessory 0.10.0

2022-03-15T14:50:47.052Z HAP-NodeJS:EventedHTTPServer:Connection [::ffff:192.168.5.24] HTTP request: /characteristics
2022-03-15T14:50:47.052Z HAP-NodeJS:HAPServer [0E:5F:CE:A3:AA:E9] HAP Request: PUT /characteristics
2022-03-15T14:50:47.053Z HAP-NodeJS:Accessory [Homebridge AAE9 EBC0] Processing characteristic set: {"characteristics":[{"aid":112,"iid":11,"value":0}]}
2022-03-15T14:50:47.054Z HAP-NodeJS:EventedHTTPServer [::ffff:192.168.5.24] Muting event '112.11' notification for this connection since it originated here.
[3/15/2022, 2:50:47 PM] [zigbee2mqtt] Publish to 'zigbee2mqtt/0x680ae2fffe598667/set': '{"state":"OFF"}'
2022-03-15T14:50:47.058Z HAP-NodeJS:Accessory [Homebridge AAE9 EBC0] Setting Characteristic "On" to value 0
2022-03-15T14:50:47.060Z HAP-NodeJS:EventedHTTPServer:Connection [::ffff:192.168.5.24] HTTP Response is finished
2022-03-15T14:50:47.433Z HAP-NodeJS:EventedHTTPServer:Connection [::ffff:192.168.5.24] Sending HAP event notifications [ { aid: 112, iid: 11, value: 1 }, { aid: 112, iid: 11, value: 0 } ]


@itavero
Copy link
Owner

itavero commented Apr 3, 2022

As reported in the issue on the Homebridge repository, a workaround seems to be to turn off cache_state in 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.

@georgebrock
Copy link
Author

As reported in the issue on the Homebridge repository, a workaround seems to be to turn off cache_state in Zigbee2MQTT.

This work around is working for me. Thanks! ✨

I'm now thinking about a mechanism to ensure a minimum time between the processing of MQTT messages for the same accessory.

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.

@stale
Copy link

stale bot commented May 30, 2022

It appears that this issue did not have an update in quite some time. Please check if you can provide any additional information to help resolve this issue. If there isn't any activity in the next two weeks, this issue will be closed automatically. Thank you for your contributions!

@guillochon
Copy link

Vote to reopen this issue as disabling the cache state is not a great workaround (my device states toggle like crazy when caching is disabled).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working stale
Projects
None yet
Development

No branches or pull requests

6 participants