zha light: polling broken. Cannot read/update state

[kdjordjev]

Home Assistant release with the issue:

Haas.io 0.70 / 0.70.1

Last working Home Assistant release (if known):

I think 0.68/0.69 was ok

Operating environment (Hass.io/Docker/Windows/etc.):

Hass.io

Component/platform:

light / zha

Description of problem:

Polling got broken with the new release. No matter the current state of the light result = await zha.safe_read(self._endpoint.on_off, ['on_off']) @ async def async_update(self): always returns the light is OFF

I suspect the issue came with the upgrade of the zigpy / bellows @ 0.70 release

zha: Bump to zigpy 0.1.0 (@rcloran - #14305) (zha docs)

I can turn the light ON/Off through Home assistant if the polling is disabled should_poll = False However if polling is enabled the should_poll = True, Home Assistant always reports light is off (when async def async_update(self): gets called)

Problem-relevant configuration.yaml entries and (fill out even if it seems unimportant):

Traceback (if applicable):

Additional information:

[dmulcahey]

Did you modify this yourself? The zha light entity has should_poll set to false...

[kdjordjev]

Yes. I have GE 45857 dimmer switch. This switch does not report state (i.e. when you manually operate of the switch), unless you poll it I have been using polling with it for many months, but this got broken 0.70 release

[ciotlosm]

I also have some weird problem on startup:

2018-06-09 19:19:02 ERROR (MainThread) [homeassistant.components.switch] Error while setting up platform zha
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/homeassistant/helpers/entity_platform.py", line 129, in _async_setup_platform
    SLOW_SETUP_MAX_WAIT, loop=hass.loop)
  File "/usr/lib/python3.6/asyncio/tasks.py", line 358, in wait_for
    return fut.result()
  File "/usr/lib/python3.6/site-packages/homeassistant/components/switch/zha.py", line 27, in async_setup_platform
    await cluster.bind()
  File "/usr/lib/python3.6/site-packages/zigpy/device.py", line 89, in request
    expect_reply=expect_reply,
  File "/usr/lib/python3.6/site-packages/bellows/zigbee/application.py", line 241, in request
    v = await send_fut
zigpy.exceptions.DeliveryError: Message send failure: EmberStatus.DELIVERY_FAILED
2018-06-09 19:19:12 WARNING (MainThread) [bellows.zigbee.application] Unexpected message send notification

Running zha: using Elelabs RPI Hat on 0.71.0

[dmulcahey]

@ciotlosm these aren’t always errors... this can be a direct side effect of trying to grab state for devices that may not have rejoined the network yet or that may be sleeping. All of the existing update_before_add usage in ZHA really needs a new solution. I’m planning on spending some time this weekend to attempt to make the user experience better here.

[kdjordjev]

From my limited understanding every time we call async def async_update(self) and result = await zha.safe_read(self._endpoint.on_off, ['on_off']) we will get incorrect result. I am always getting off. This is called during polling and also on initial boot, and probably other use cases.

[DomiStyle]

I just recently started using the zha component so I can't say much about previous versions or expected behavior but I'm seeing the same/similar symptoms here.

Toggling the light from Home Assistant updates the state just fine but toggling the light via the wall switch to simulate a power failure leads to an incorrect state that's never corrected.

Additionally, turn on events by the lamp get ignored. I can see it show up in the logs as shown below but the state will forever be stuck on "off", even though the lamp turned on when it got power again. Not entirely sure what the expected behavior is but doing nothing certainly seems like the wrong thing to do, especially with polling being broken too.

Here's the output when the light gets turned on manually:

2018-06-18 22:12:33 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received
2018-06-18 22:12:33 DEBUG (MainThread) [zigpy.zdo] [0xc61d:zdo] ZDO request 0x0013: [50717, 00:00:00:00:00:00:00:00, 142]

Here's a snippet of the "chatter" that's going on with no action on the network. I don't know anything about the ZigBee protocol though, so no idea if this means anything but maybe it's important:

2018-06-18 22:35:19 DEBUG (MainThread) [bellows.uart] Data frame: b'6358b1575473240e6ba8ae26abdd8549638e25b62b22c6790d7e'
2018-06-18 22:35:19 DEBUG (MainThread) [bellows.uart] Sending: b'87009f7e'
2018-06-18 22:35:19 DEBUG (MainThread) [bellows.ezsp] Application frame 89 (incomingRouteRecordHandler) received
2018-06-18 22:35:19 DEBUG (MainThread) [bellows.uart] Data frame: b'7358b157546f15b658924a24ab5593499cded86bdc729874fec75288fa0a647e'
2018-06-18 22:35:19 DEBUG (MainThread) [bellows.uart] Sending: b'8070787e'
2018-06-18 22:35:19 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received
2018-06-18 22:35:20 DEBUG (MainThread) [bellows.uart] Data frame: b'0358b1575473240e6ba8ae26abdd8549628e25b62b22c660587e'
2018-06-18 22:35:20 DEBUG (MainThread) [bellows.uart] Sending: b'8160597e'
2018-06-18 22:35:20 DEBUG (MainThread) [bellows.ezsp] Application frame 89 (incomingRouteRecordHandler) received
2018-06-18 22:35:20 DEBUG (MainThread) [bellows.uart] Data frame: b'1358b157546f15b658924a24ab5593499cdfd96bdc729874f8c751c9fc7e39cdc97e'
2018-06-18 22:35:20 DEBUG (MainThread) [bellows.uart] Sending: b'82503a7e'
2018-06-18 22:35:20 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received
2018-06-18 22:35:20 WARNING (MainThread) [zigpy.zcl] Data remains after deserializing ZCL frame
2018-06-18 22:36:41 DEBUG (MainThread) [bellows.uart] Data frame: b'2358b157546f11b259924a25aa5592499cc3d71ff0089874f4c79e76a2be3ebeebcdda27697e'
2018-06-18 22:36:41 DEBUG (MainThread) [bellows.uart] Sending: b'83401b7e'
2018-06-18 22:36:41 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received
2018-06-18 22:36:41 DEBUG (MainThread) [zigpy.zdo] [0xc61d:zdo] ZDO request 0x0006: [65533, 49246, [25], []]
2018-06-18 22:36:41 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast
2018-06-18 22:36:41 DEBUG (MainThread) [bellows.uart] Sending: b'33592157541e15af9f944a232a5592099d4e27adebcb618bfdc66354b77e'
2018-06-18 22:36:41 DEBUG (MainThread) [bellows.uart] Data frame: b'3459a157541e15557ec47e'
2018-06-18 22:36:41 DEBUG (MainThread) [bellows.uart] Sending: b'8430fc7e'
2018-06-18 22:36:41 DEBUG (MainThread) [bellows.ezsp] Application frame 52 (sendUnicast) received
2018-06-18 22:36:41 DEBUG (MainThread) [bellows.uart] Data frame: b'4459b157541515af9f944a232a5592099d4e274cebce671a477e'
2018-06-18 22:36:41 DEBUG (MainThread) [bellows.uart] Sending: b'8520dd7e'
2018-06-18 22:36:41 DEBUG (MainThread) [bellows.ezsp] Application frame 63 (messageSentHandler) received

Since I'm using Docker I tried reverting a few versions but saw no improvement until 0.69.1 at which point support for Innr lights breaks so I couldn't test any further unfortunately.

I'm using an Elelabs USB stick configured like this:

zha:
  usb_path: /dev/ttyUSB0
  database_path: /config/zigbee.db
  baudrate: 57600

Device is passed through to the container and the container is running in privileged mode. Running 0.71.0 currently.

[balloobbot]

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 :+1:

[tbrock47]

Having this problem with Sengled bulbs on 0.80.3. I just migrated my devices from Vera to the HUSBZB-1.

My lights stay in sync when operated from HA only. After a HA reboot, or operation at the wall, the status toggles to off and never comes back on unless toggled via HA.

I did not have this issue when Vera was running as the controller.

Edit: I should mention all configuration was done according to the documentation, and the bulbs work as expected with this exception.

[wmbaum]

I'm having the same issue with a Tradfri bulb via HUSBZB-1. After a few hours or whenever I restart HA, it goes "offline". Is there a way to manually send a polling request to update status? As a workaround for now I've set an HA startup automation to send an ON with 50% brightness_pct command, which is the bulb's normal state. That wakes it up for a few hours..

[dmulcahey]

for people having issues with bulbs please try this: https://github.com/dmulcahey/home-assistant/commit/857294ed19aaa441dc20e044ffb9337662c510e1

you have to remove and rejoin the bulb for this change to take effect. Please let me know how this works out and I'll get a cleaned up PR open with the changes.

[w1ll1am23]

@dmulcahey I am not sure what I am trying to test here, but I will explain what I am seeing when running your changes.

My setup: Running on a dev instance with one freshly paired GE bulb Using the HUSBZB-1 I will indicate what I consider a pass/fail for each of the below tests based on how I would like it to work, or how it worked when I was on the Wink platform.

Test 1: Turn light on via HA and reboot Result: Light is still on after reboot PASS (This doesn't work in dev) corresponding ZHA entity shows as offline until I toggle the light. Would be nice for the ZHA entity to update to online without the toggle. Maybe it will if I waited long enough?

Test 2: Turn light off via HA and reboot Result: Light is still off after reboot PASS corresponding ZHA entity shows as offline until I toggle the light

Test 3: Turn light off via HA and then off/on via power Result: Light comes on in HA! PASS (this doesn't work in dev)

Test 4: Turn light on via HA and then off/on via power Result: Light is still on in HA and responses immediately responds to command. PASS

Test 5: Light is on, turn light off via power Result: Light is still on in HA and doesn't respond to commands (duh) the following log entry is generated

2018-12-16 11:29:09 ERROR (MainThread) [homeassistant.components.light.zha] light.ge_appliances_zll_light_00023ed9_1: Unable to turn the light off: Message send failure: EmberStatus.DELIVERY_FAILED

The ZHA entity for the light remains online. FAIL. I would expect the ERROR in the log to result in the zha entity moving to the offline state.

Test 6: Restart HA while light is off via power Result: Light is in last state prior to reboot (see test 1 and 2 above) ZHA entity shows offline and stays that way. PASS

Things seem to be better for sure than dev which I am very excited about. Can you elaborate as to while everything would need re-paired? Would it be possible to mark the light as offline when the corresponding ZHA entity is offline? I don't think most people show the ZHA entity via the frontend so knowing it's state via the light would be super helpful.

These were all of the tests I could think of, let me know if you would like me to try anything else.

[dmulcahey]

The repairing is because attribute reporting wasn’t initially done with the existing code for level control or on/off.

Sengled bulbs are actually reporting off on their own when the power is cut! That surprised me for sure... It sucks that GE isn’t doing the same but I’m not surprised because their z-wave devices aren’t nearly as full featured when compared to their competitors.

Delivery can fail when the device is online based on several factors. We’ll get that cleaned up eventually but I don’t want to handle it like that here.

Thanks for such thorough testing!!

Can I have the full log snippet from you cutting power to the light from the switch while HA is on? There may be multiple things happening (I think the class needs more refinement with these changes) and this actually may be working

[w1ll1am23]

@dmulcahey entire log is here https://hastebin.com/gidinexuha.coffeescript

I turned the light on then off and then on again via HA. Then turned off the switch, and then turned the switch back on. Stopped HA and collected logs.

[kdjordjev]

I have not tested the changes here. But for me it seems functional if i enable the light polling. I copy the zha.py from the repository into the \config\custom_components\light\zha.py I only manually enable the polling (it is disabled by default) and everything seems functional. It seems GE is not sending status update after manually toggling the light, so poling is fixing the issue.

Perhaps we need to enable this by default ? I have to manually copy the zha.py and modify with new HA releases.

def should_poll(self) -> bool:
    """Return True if entity has to be polled for state.
    False if entity pushes its state to HA.
    """
    return True

[w1ll1am23]

It seems GE is not sending status update after manually toggling the light, so poling is fixing the issue.

Based on these changes @dmulcahey made and the tests I did, GE is sending a state when the bulb is toggled on after being powered off. I just think it wasn't being handled properly.

[dmulcahey]

@w1ll1am23 are you on discord?

[w1ll1am23]

@dmulcahey yes, just w1ll1am over there.