[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_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**

<details>
<summary>The device entry from <code>zigbee2mqtt/bridge/devices</code></summary>

```json
{
  "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"
}
```

</details>

<details>
<summary>Status update from <code>zigbee2mqtt/Front bedroom socket</code></summary>

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"}
```

</details>

<details>
<summary>Messages published by this plugin that might be related to your issue</summary>

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"}
```

</details>

**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
