Zigbee2mqtt lights in group turn on immediately after turning off

[denysdovhan]

The problem

I have 4 Aqara Bulbs joined in a group called main_light. Sometimes, when I turn off lights they turn off, but immediately turn on after.

I didn't find a reliable way to reproduce this problem. It just happens from time to time, usually, after lights weren't turned on for a long time. Other bulbs that aren't joined into groups work fine.

I opened an issue in Koenkk/zigbee2mqtt#7816 repo, but the maintainer said it doesn't look like a z2m bug. Seems like HA (or MQTT integration), for some reason, turns the light group back on.

What is version of Home Assistant Core has the issue?

2021.6.6

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Container

Integration causing the issue

MQTT

Link to integration documentation on our website

https://www.home-assistant.io/integrations/mqtt/

Example YAML snippet

mqtt:
  broker: localhost
  port: 1888
  discovery: true
  discovery_prefix: homeassistant
  username: !secret mqtt_username
  password: !secret mqtt_password
  birth_message:
    topic: 'hass/status'
    payload: 'online'
  will_message:
    topic: 'hass/status'
    payload: 'offline'

Anything in the logs that might be useful for us?

Zigbee2MQTT logs reproducing this issue:

• https://pastebin.com/ynVdH2KC
• https://pastebin.com/K1XZ0Hrw

Additional information

Here is a video of how this happens: https://user-images.githubusercontent.com/3459374/122544137-2b1b8500-d035-11eb-8dbf-1a1cf9bb2c4c.MOV

My setup is described here: https://denysdovhan.com/smart-home/hardware/#zigbee-network
docker-compose is here: https://github.com/denysdovhan/smart-home/blob/master/docker-compose.yaml

[probot-home-assistant]

mqtt documentation
mqtt source
_{^{(message by IssueLinks)}}

[probot-home-assistant]

Hey there @emontnemery, mind taking a look at this issue as its been labeled with an integration (mqtt) you are listed as a codeowner for? Thanks!
_{^{(message by CodeOwnersMention)}}

[snippem]

Hi having the same problem and posted this as a problem in the zigbee2mqtt GitHub.

What happened
Lights goes off and on again

What did you expect to happen
That my lights stay on when they supposed to

How to reproduce it (minimal and precise)
Happens out off the bleu

Debug info
Zigbee2MQTT version:1.20.0-1
Adapter hardware: CC2531, CC2530, CC26X2R1, CC1352P-2, Conbee II
Adapter firmware version:dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_4F_3F_95-if00-port0

This happens frequently see screenshots any idea on what is the cause?

Hope this can be solved koenk closed my problem as this is a home assistant problem he said.

[emontnemery]

There are two ways in which this can happen which are not bugs, but which may still be surprising:

• An automation which is forgotten or executes unexpectedly turns on the light group. Please check the logbook in Home Assistant at the time when the lights unexpectedly turned on.
• A retained MQTT message which will be re-received if zigbee2mqtt for some reason reconnects to the MQTT broker. You can check this by using some graphical MQTT tool, or from command line by subscribing to mosquitto_sub -v -h <broker> -t zigbee2mqtt/#, any retained message will immediately be displayed. Home Assistant should not send light on commands retained, but it could perhaps have been done by some other tool when testing.

Please give some more details on the problem, you mention that:

Sometimes, when I turn off lights they turn off, but immediately turn on after.

How did you turn the lights off, from Home Assistant or in some other way?

Please also enable Home Assistant debug logging with the settings below, then share a log once the issue reproduces. Please make sure to note the exact point in time where the lights were unexpectedly turned off.

Log settings:

 logger:
   default: info
   logs:
     homeassistant.components.automation: debug
     homeassistant.core: debug
     homeassistant.components.mqtt: debug

[frenck]

Considering this part of the screenshot:

The actor is the Supervisor, indicating a third-party add-on making these changes. Possibly Node-RED or AppDaemon. That is not Home Assistant.

[snippem]

Considering this part of the screenshot:

The actor is the Supervisor, indicating a third-party add-on making these changes. Possibly Node-RED or AppDaemon. That is not Home Assistant.

So for me if I change the entity name a fault would appear that the entity is not found.
That way if a automation which I programmed wrong or forgotten would appear in the log.
Glad thi probably is not a bug when i find a error on my side I'll post it
For me i will rework my setup and go bug finding

[denysdovhan]

Hey @frenck, @emontnemery

I have finally caught this effect once again. I had asked google home to turn off the light. I did, but then the lights have turned on immediately.

Here's my log: https://pastebin.com/WMdvTx9b

[frenck]

I do think it is an upstream bug. Let me try to explain.

You call to turn the lights of @ Google, the assistant call comes in. Looks good: 'on': False, so lights off.

2021-07-21 21:59:50 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event google_assistant_command[L]: request_id=488603497386854345, entity_id=['light.living_room_main_light'], execution=[{'command': 'action.devices.commands.OnOff', 'params': {'on': False}}], source=cloud>

That triggers a service call in Home Assistant. service=turn_off, so far, so good.

2021-07-21 21:59:50 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_off, service_data=entity_id=light.living_room_main_light>

Home Assistant sends a payload to MQTT (Z2M). The payload is {"state": "OFF"}, which looks good

2021-07-21 21:59:50 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=mqtt, service=publish, service_data=topic=zigbee2mqtt/living_room_main_light/set, qos=0, retain=False, payload={"state": "OFF"}>
2021-07-21 21:59:50 DEBUG (MainThread) [homeassistant.components.mqtt] Transmitting message on zigbee2mqtt/living_room_main_light/set: '{"state": "OFF"}', mid: 246

Next a message comes in from MQTT, that says: "state": "ON", which is incorrect?
Additionally, it says now: "brightness":0

2021-07-21 21:59:50 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on zigbee2mqtt/living_room_main_light: b'{"brightness":0,"color":{"x":0.5267,"y":0.4133},"color_mode":"color_temp","color_temp":500,"state":"ON"}'

This is confirmed by the next action HA takes, where the new light state, turns down the brightness to 0, but the light remains on (as per previous instruction received from MQTT).

2021-07-21 21:59:50 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.living_room_main_light, old_state=<state light.living_room_main_light=on; min_mireds=153, max_mireds=500, supported_color_modes=['color_temp'], color_mode=color_temp, brightness=251, color_temp=500, color=x=0.5267, y=0.4133, friendly_name=Main Light, supported_features=43, icon=mdi:vanity-light @ 2021-07-21T21:49:25.683649+03:00>, new_state=<state light.living_room_main_light=on; min_mireds=153, max_mireds=500, supported_color_modes=['color_temp'], color_mode=color_temp, brightness=0, color_temp=500, color=x=0.5267, y=0.4133, friendly_name=Main Light, supported_features=43, icon=mdi:vanity-light @ 2021-07-21T21:49:25.683649+03:00>>

So, in this case, Home Assistant definitely received an "ON" state after sending an "OFF" state request. Extra curious/weird in this case, is that the brightness in the received message did change to 0.

Hold on, it becomes messier, next to all lights in the group seems to go to 0 brightness, and the state is still "ON". My guess: there is transitioning involved?

Anyways, it continues:

---

So bringing it down to just MQTT messages, cleaned up for readability:

2021-07-21 21:59:50 Transmitting message on zigbee2mqtt/living_room_main_light/set: '{"state": "OFF"}', mid: 246
2021-07-21 21:59:50 Received message on zigbee2mqtt/living_room_main_light: b'{"brightness":0,"color":{"x":0.5267,"y":0.4133},"color_mode":"color_temp","color_temp":500,"state":"ON"}'
2021-07-21 21:59:50 Received message on zigbee2mqtt/living_room_main_light: b'{"brightness":0,"color":{"x":0.5267,"y":0.4133},"color_mode":"color_temp","color_temp":500,"state":"OFF"}'
2021-07-21 21:59:56 Received message on zigbee2mqtt/living_room_main_light: b'{"brightness":251,"color":{"x":0.5267,"y":0.4133},"color_mode":"color_temp","color_temp":500,"state":"OFF"}'
2021-07-21 21:59:57 Received message on zigbee2mqtt/living_room_main_light: b'{"brightness":251,"color":{"x":0.5267,"y":0.4133},"color_mode":"color_temp","color_temp":500,"state":"ON"}'

We definitely are receiving a mixed bag of statuses on this group. The last message (almost 7 seconds after you have turned the light off), is received over MQTT, with the "ON" state, triggering Home Assistant to reflect that. Triggering a whole chain of events again to turn everything on as received in that message.

Edit: Left a message upstream as well. Interesting case!

[denysdovhan]

@frenck Thanks for explaining that piece by piece to me!

[github-actions]

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.
Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍
This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

[denysdovhan]

The issue is still present. It even happened to me an hour ago.

[emontnemery]

I think this issue should be closed in favor of an issue on zigbee2mqtt.
@frenck , @Koenkk is there an issue on zigbee2mqtt tracking this?

[Koenkk]

@emontnemery I've already made an analysis of this issue (Koenkk/zigbee2mqtt#7816 (comment)) and don't think it should be fixed from z2m.

[Try2Fly]

I’m using deconz and have same issue. when I turn off light using light.turn_off with a transition, it turns the light on again after transition period. It’s been doing that for a while now. Used to work correctly

edit: I also have an automation that sets the brightness to certain value when the light is turned on. If I disable this, it the turn_off with transition works correctly again.

[denysdovhan]

The issue was resolved for me by upgrading to a better hardware. I've been using CC2531 which is no longer recommended by zigbee2mqtt developers.

I migrated to SMARTLIGHT CC2652P Zigbee USB Adapter SLZB-02 and it works perfectly stable.