Zigbee2mqtt: After 1.12.2 upgrade, dimmer lights ON won't turn on until dimmer UP

[tthk]

Bug Report

What happened

Light won't turn on on command from Home Assistant, need to dimmer up for light to turn on.

What did you expect to happen

Light turn on on command from Home Assistant.

How to reproduce it (minimal and precise)

Turning on ZigBee dimmer (GE inwall dimmer) first time after upgrade of Zigbee2mqtt works. Off works. On again doesn't work, light stays off. Need to increase dimmer at this point for light to go on. If dimmer was already at 100%, reduce to less (light remains off), increase dimmer, then light goes on. From now on, off (light goes off), on (light stays off), dimmer down (light stays off), dimmer up (light goes on).
Appliance switches without dimming work fine.
Switching on via remote source (not at physical switch) doesn't work after the first time.

Latest version 1.12.2 has this problem, downgraded to 1.12.0 (last hassio snapshot) problem went away.
Running CC2531_SOURCE_ROUTING_20190619 on CC2531

Debug Info

zigbee2mqtt version: 1.12.2
CC253X firmware version: CC2531_SOURCE_ROUTING_20190619

Debug log: https://pastebin.com/N9wfRkpK
In above debug log, I restarted ZigBee2MQTT from Home Assistant, turn off then on dimmer inwall switch from Home Assistant. Light never turned on on first ON, had to dimmer down then up for light to go on.

Downgrading back (by restoring Home Assistant snapshot) to ZigBee2MQTT 1.12.0 allowed dimmer lights to work again normally. Tried upgrading to ZigBee2MQTT 1.12.2, had the problem again. This was when I got the above debug log file.

[wreality]

I'm seeing a very similar problem. From my experience:

Set brightness to 100%: Toggle on and off works as expected
Set brightness to anything else: Toggle OFF works, Toggle ON does nothing, Toggle OFF flashes the light and it dims to off.

In any of these conditions where the light isn't able to toggle on, adjusting the brightness will make the light come on.

I didn't think to make a snapshot before upgrading, so I'm unable to roll back to confirm that the problem goes away with a downgrade.

[Koenkk]

• Could you add some annotations at the log were things go wrong
• Could you also include the herdsman debug logging

To enable herdsman debug logging, see https://www.zigbee2mqtt.io/information/debug.html#zigbee-herdsman-debug-logging

[tthk]

Turned on herdsman debug as requested and had a quick look at the the logs for turning on light 0x0022a300000a119a:
Zigbee2MQTT 1.12.0: https://pastebin.com/e1yiJYbv
Zigbee2MQTT 1.12.2: https://pastebin.com/emf0S2j0

As I annotated in the log files above, looks like 1.12.0 called genOnOff.on() (which did the right thing) while 1.12.2 called genLevelCtrl.moveToLevelWithOnOff() (which did not not turn on the light as expected).

[Koenkk]

Thanks for the good logging, exactly what I need. In your OP you mentioned that it works the first time after starting zigbee2mqtt, could you provide the same log for all the commands published to this device?

It goes somewhere wrong here: https://github.com/Koenkk/zigbee-herdsman-converters/blob/master/converters/toZigbee.js#L334 but I need to know how to end up in that state.

[tthk]

Thanks for looking into this issue.

Can you give me a hint on how to get the full log which includes zigbee-herdsman debugging turned on? The log file in docker instance at /share/zigbee2mqtt/log does not have the zigbee-herdsman logging while the browser hass.io addon page for zigbee2mqtt does. However, the browser page cuts off most of the log, missing early crucial info.

[Koenkk]

@tthk this is indeed a limitation, try to work around it by copying the log after every command send (because that what I need).

[wreality]

Here's my logs of what seems to be the same issue:

1.12.0: https://pastebin.com/0QEcTA44
1.12.2: https://pastebin.com/kLqtVb8b

The logs are annotated with ### blocks. Hope this helps!

[wreality]

I can confirm that the issue is present in 1.12.1 as well.

[Koenkk]

Thanks for the well annotated logging, with this I could easily reproduce the bug on one of my lights. Fixed in the latest dev branch (if not let me know and I'll reopen).

[tthk]

Here's my logs of what seems to be the same issue:
1.12.0: https://pastebin.com/0QEcTA44
1.12.2: https://pastebin.com/kLqtVb8b
The logs are annotated with ### blocks. Hope this helps!

Thanks for this fix, @Koenkk. I've been holding off on updating since 1.12.0 due to this issue. Looking forward to testing fix.

Nice logs @wreality . For future, can you tell me how you were able to capture the log with herdsman debugging on from the beginning? I couldn't get a good log with herdsman debugging enabled. I'm running hassio in a docker container, with zigbee2mqtt as an addon, and can only see the herdsman logging on hassio browser, and past entries get cut off too soon once the problem occurs.

[Koenkk]

@tthk this is indeed a limitation of the hassio addon, with a docker or bare metal setup it can easily be done.

[tthk]

Just wanted to confirm that 1.13.0 fixed my issue with GE ZigBee dimmer lights not turning on. Thank you @Koenkk !

[wreality]

@tthk I made a local build of the addon and changed the Dockerfile to capture the debug info.

@Koenkk i made a pull request for the change I made to the addon for debug logging: https://github.com/danielwelch/hassio-zigbee2mqtt/pull/333