Core: ZHA Light platform group fails to control all lights in group

[StyxyDog]

Home Assistant release with the issue:

0.88.1

Last working Home Assistant release (if known):

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

Hass.io on Raspberry Pi 3 with a conbee USB zigbee coordinator
Component/platform:

ZHA

Description of problem:
I've had a few issues and several errors since moving from 0.87.1 to 0.88 (and now 0.88.1).
I think that I have found the source of some of my problems.
I have a light configured as a group (see YAML below). Physically this is 5 Tradfri bulbs all on a single switch - they are grouped (light: -platform: group) to behave as a single light, in this case light.stairs_light.
All the light seem to work individually, but only one will work when controlled by the light.stairs_light group. However turning on any one of the lights will effect the state of the group.
e.g.

• Turn on the group, only light 1 turns on (could be any light after each reboot, currently its light 5). Turn off the group only light 1 turns off.
• Turn on light 3 - group shows as on. Turn off light 3 group shows as off.
• Turn on light 3, group shows as on. Turn off the group - nothing happens.

In version 0.87.1 (which I have tried restoring to confirm), all lights are controlled by the light.stairs_light group. I think this is something to do with the light being initially unavailable in version 0.88.1, when that group is created. Only the first light is correctly added, perhaps?

I can get around this by not using this configuration, but it seems like there is a bug somewhere.

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

light:
  - platform: group
    name: Stairs Light
    entities:
      - light.stairs_1
      - light.stairs_2 
      - light.stairs_3
      - light.stairs_4
      - light.stairs_5

Traceback (if applicable):

Various errors - not sure which are relevant or helpful... These are from around the time I was switching lights on and off.

2019-02-26 14:18:13 WARNING (MainThread) [zigpy_deconz.zigbee.application] Failed to receive transmit confirm for request id: 117
2019-02-26 14:18:13 WARNING (MainThread) [zigpy_deconz.zigbee.application] Failed to receive transmit confirm for request id: 118
2019-02-26 14:18:13 WARNING (MainThread) [zigpy_deconz.zigbee.application] Failed to receive transmit confirm for request id: 119
2019-02-26 14:18:14 INFO (MainThread) [homeassistant.components.http.view] Serving /api/history/period/2019-02-25T14:18:13.549Z to 192.168.1.70 (auth: True)
2019-02-26 14:18:14 INFO (SyncWorker_17) [homeassistant.components.device_tracker.nmap_tracker] nmap scan successful
2019-02-26 14:18:22 WARNING (MainThread) [zigpy_deconz.zigbee.application] Failed to receive transmit confirm for request id: 120
2019-02-26 14:18:22 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/homeassistant/helpers/service.py", line 289, in _handle_service_platform_call
    await getattr(entity, func)(**data)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/zha/light.py", line 206, in async_turn_off
    success = await self._on_off_channel.off()
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/zha/core/channels/__init__.py", line 48, in wrapper
    result = await command(*args, **kwds)
  File "/usr/local/lib/python3.7/site-packages/zigpy/device.py", line 89, in request
    expect_reply=expect_reply,
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 97, in request
    r = await asyncio.wait_for(send_fut, SEND_CONFIRM_TIMEOUT)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 423, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
2019-02-26 14:18:23 INFO (MainThread) [homeassistant.components.http.view] Serving /api/history/period/2019-02-26T14:18:05.113Z to 192.168.1.70 (auth: True)
2019-02-26 14:18:30 INFO (SyncWorker_18) [homeassistant.components.device_tracker.nmap_tracker] Scanning...
2019-02-26 14:18:33 WARNING (MainThread) [zigpy_deconz.zigbee.application] Failed to receive transmit confirm for request id: 121
2019-02-26 14:18:33 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/homeassistant/helpers/service.py", line 289, in _handle_service_platform_call
    await getattr(entity, func)(**data)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/zha/light.py", line 206, in async_turn_off
    success = await self._on_off_channel.off()
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/zha/core/channels/__init__.py", line 48, in wrapper
    result = await command(*args, **kwds)
  File "/usr/local/lib/python3.7/site-packages/zigpy/device.py", line 89, in request
    expect_reply=expect_reply,
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 97, in request
    r = await asyncio.wait_for(send_fut, SEND_CONFIRM_TIMEOUT)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 423, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

Additional information:

[jurriaan]

I had quite some problems with getting the conbee to work as well. After a while, or some switching of groups these 'Failed to receive transmit confirm for request id:' messages start to appear.

When you restart home assistant it looks like it does receive these confirms (you get errors about unexpected confirms after a restart).

I went back to deCONZ for now.

[dmulcahey]

@StyxyDog @jurriaan this is being tracked in several tickets already. #21422 #21423 The core of the issue is the same for all of them.

@StyxyDog can you try something for me? can you get it so that all the lights respond to individual commands (to ensure they are all connected and available) then issue a reconfigure node command from the ZHA configuration panel for each one? wait about 30 seconds between each command to give them time to finish. After this is done, restart HA and see if the problem is any better. if that doesn't work please try this branch: https://github.com/dmulcahey/home-assistant/tree/dm/zha-forgive-missing-basic and let me know if that helps at all. I need feedback to determine if these changes help because the Sengled bulbs that I have do not exhibit this behavior.

[StyxyDog]

@dmulcahey I'd been keeping an eye on those issues -I thought this might all be related, maybe this will help shed some light on the problem :)

All lights in the set of 5 were responsive (although I noticed some had gone out of sync with their current actual state). However they all responded when toggled.

Reconfigure gave me this on bulb 1...

2019-02-26 15:14:00 WARNING (MainThread) [zigpy_deconz.zigbee.application] Failed to receive transmit confirm for request id: 225
2019-02-26 15:14:00 WARNING (MainThread) [zigpy_deconz.zigbee.application] Failed to receive transmit confirm for request id: 226
2019-02-26 15:14:00 WARNING (MainThread) [zigpy_deconz.zigbee.application] Failed to receive transmit confirm for request id: 227
2019-02-26 15:14:00 ERROR (MainThread) [zigpy.zcl] [0x1d70:1:0x1000] 0 is not a valid attribute id
2019-02-26 15:14:00 WARNING (MainThread) [homeassistant.components.zha.core.device] IKEA of Sweden TRADFRI bulb E27 opal 1000lm channel: attribute-0x1d70:1:0x1000 async_configure stage failed ex: object NoneType can't be used in 'await' expression
2019-02-26 15:14:00 WARNING (MainThread) [zigpy_deconz.zigbee.application] Failed to receive transmit confirm for request id: 228

this on bulb 2...

2019-02-26 15:17:00 WARNING (MainThread) [zigpy_deconz.zigbee.application] Failed to receive transmit confirm for request id: 231
2019-02-26 15:17:00 WARNING (MainThread) [zigpy_deconz.zigbee.application] Failed to receive transmit confirm for request id: 232
2019-02-26 15:17:00 WARNING (MainThread) [zigpy_deconz.zigbee.application] Failed to receive transmit confirm for request id: 233
2019-02-26 15:17:00 ERROR (MainThread) [zigpy.zcl] [0x5a14:1:0x1000] 0 is not a valid attribute id
2019-02-26 15:17:00 WARNING (MainThread) [homeassistant.components.zha.core.device] IKEA of Sweden TRADFRI bulb E27 opal 1000lm channel: attribute-0x5a14:1:0x1000 async_configure stage failed ex: object NoneType can't be used in 'await' expression
2019-02-26 15:17:00 WARNING (MainThread) [zigpy_deconz.zigbee.application] Failed to receive transmit confirm for request id: 234
2019-02-26 15:17:15 WARNING (MainThread) [zigpy_deconz.zigbee.application] Failed to receive transmit confirm for request id: 235
2019-02-26 15:17:15 WARNING (MainThread) [zigpy_deconz.zigbee.application] Failed to receive transmit confirm for request id: 236

and something similar on the others.
Then I restarted HASS.
2 of the 5 came up immediately the rest were unavailable.
So rather than wait - they can be a very long time if at all, I powered all 5 bulbs off and on.
All 5 lights are now working and responsive.
The group light also seems to control all 5 lights.

So that appears to have been successful :) Thank you! I'll keep an eye on it and let you know if that changes in time.

[dmulcahey]

Yeah I’ll keep looking at this too. Something is definitely up here.

[StyxyDog]

They all seem to have gone unresponsive I'm afraid. I have turned them all on, and they lit, but the status didn't change in home assistant. i.e. turned on, but looked like they are still off in HA.

2019-02-26 16:27:27 WARNING (MainThread) [zigpy_deconz.zigbee.application] Failed to receive transmit confirm for request id: 216
2019-02-26 16:27:33 WARNING (MainThread) [zigpy_deconz.zigbee.application] Failed to receive transmit confirm for request id: 217
2019-02-26 16:27:40 WARNING (MainThread) [zigpy_deconz.zigbee.application] Failed to receive transmit confirm for request id: 218

I'm going to try dropping the forgive-missing-basic branch you mentioned before.

[dmulcahey]

by dropping do you mean using? or are you already using it? and can you do me a favor? go in to the history or logbook and tell me when they became available initially and then when they became unavailable? I need the full times please. Thanks for helping to track this down!

[StyxyDog]

Ah I meant I dropped the zha directory from your branch into custom_components :) i.e. I am now using it, I wasn't before. Sorry I'll try to be clearer.

So before when I did the reconfigure and restart on the standard 0.88.1 it seemed to work for about 1 hour 19 minutes, but I think the reason that they went offline is because I rebooted - the lights had become unresponsive but were still showing as available (eg the zha.stairs_1). I don't know exactly when they became unresponsive.

Now (from about 16:52 GMT) I am using your forgive_missing_basic branch. After a reboot and power-cycling the 5 lights, and the light group that controls them together, all seem to be working again. I'll monitor this and let you know any timings.
Thank you for helping!

[dmulcahey]

1 hr 20 was what I was expecting. That means the lights aren’t sending any traffic for 2 hours... do you know what the signature is for these (endpoints, input and output clusters)

[StyxyDog]

OK at little more information at 17:54 (so almost an hour after restart I'm getting errors).

2019-02-26 17:53:06 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 6, Status: 0x00, 6
2019-02-26 17:53:21 WARNING (MainThread) [zigpy_deconz.zigbee.application] Failed to receive transmit confirm for request id: 6
2019-02-26 17:53:21 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/homeassistant/helpers/service.py", line 289, in _handle_service_platform_call
    await getattr(entity, func)(**data)
  File "/config/custom_components/zha/switch.py", line 78, in async_turn_off
    await self._on_off_channel.off()
  File "/config/custom_components/zha/core/channels/__init__.py", line 48, in wrapper
    result = await command(*args, **kwds)
  File "/config/deps/lib/python3.7/site-packages/zigpy/device.py", line 90, in request
    expect_reply=expect_reply,
  File "/config/deps/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 104, in request
    r = await asyncio.wait_for(send_fut, SEND_CONFIRM_TIMEOUT)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 423, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

and also these errors

2019-02-26 17:54:18 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/homeassistant/helpers/service.py", line 289, in _handle_service_platform_call
    await getattr(entity, func)(**data)
  File "/config/custom_components/zha/switch.py", line 74, in async_turn_on
    await self._on_off_channel.on()
  File "/config/custom_components/zha/core/channels/__init__.py", line 48, in wrapper
    result = await command(*args, **kwds)
  File "/config/deps/lib/python3.7/site-packages/zigpy/device.py", line 90, in request
    expect_reply=expect_reply,
  File "/config/deps/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 83, in request
    assert sequence not in self._pending
AssertionError

2019-02-26 17:54:18 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.1813127632] Error handling message: {'type': 'call_service', 'domain': 'light', 'service': 'turn_on', 'service_data': {'entity_id': 'light.living_room_lights'}, 'id': 32}
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/websocket_api/decorators.py", line 17, in _handle_async_response
    await func(hass, connection, msg)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/websocket_api/commands.py", line 147, in handle_call_service
    connection.context(msg))
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1133, in async_call
    self._execute_service(handler, service_call))
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1155, in _execute_service
    await handler.func(service_call)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/light/__init__.py", line 288, in async_handle_light_on_service
    await light.async_turn_on(**pars)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/light/group.py", line 180, in async_turn_on
    light.DOMAIN, light.SERVICE_TURN_ON, data, blocking=True)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1133, in async_call
    self._execute_service(handler, service_call))
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1155, in _execute_service
    await handler.func(service_call)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/light/__init__.py", line 288, in async_handle_light_on_service
    await light.async_turn_on(**pars)
  File "/config/custom_components/zha/light.py", line 179, in async_turn_on
    duration
  File "/config/custom_components/zha/core/channels/__init__.py", line 48, in wrapper
    result = await command(*args, **kwds)
  File "/config/deps/lib/python3.7/site-packages/zigpy/device.py", line 90, in request
    expect_reply=expect_reply,
  File "/config/deps/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 83, in request
    assert sequence not in self._pending
AssertionError

2019-02-26 17:54:22 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/homeassistant/helpers/service.py", line 289, in _handle_service_platform_call
    await getattr(entity, func)(**data)
  File "/config/custom_components/zha/switch.py", line 74, in async_turn_on
    await self._on_off_channel.on()
  File "/config/custom_components/zha/core/channels/__init__.py", line 48, in wrapper
    result = await command(*args, **kwds)
  File "/config/deps/lib/python3.7/site-packages/zigpy/device.py", line 90, in request
    expect_reply=expect_reply,
  File "/config/deps/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 83, in request
    assert sequence not in self._pending
AssertionError
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/homeassistant/helpers/service.py", line 289, in _handle_service_platform_call
    await getattr(entity, func)(**data)
  File "/config/custom_components/zha/switch.py", line 74, in async_turn_on
    await self._on_off_channel.on()
  File "/config/custom_components/zha/core/channels/__init__.py", line 48, in wrapper
    result = await command(*args, **kwds)
  File "/config/deps/lib/python3.7/site-packages/zigpy/device.py", line 90, in request
    expect_reply=expect_reply,
  File "/config/deps/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 83, in request
    assert sequence not in self._pending
AssertionError

2019-02-26 17:54:22 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.1852975056] Error handling message: {'type': 'call_service', 'domain': 'light', 'service': 'turn_on', 'service_data': {'entity_id': 'light.living_room_lights'}, 'id': 107}
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/websocket_api/decorators.py", line 17, in _handle_async_response
    await func(hass, connection, msg)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/websocket_api/commands.py", line 147, in handle_call_service
    connection.context(msg))
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1133, in async_call
    self._execute_service(handler, service_call))
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1155, in _execute_service
    await handler.func(service_call)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/light/__init__.py", line 288, in async_handle_light_on_service
    await light.async_turn_on(**pars)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/light/group.py", line 180, in async_turn_on
    light.DOMAIN, light.SERVICE_TURN_ON, data, blocking=True)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1133, in async_call
    self._execute_service(handler, service_call))
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1155, in _execute_service
    await handler.func(service_call)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/light/__init__.py", line 288, in async_handle_light_on_service
    await light.async_turn_on(**pars)
  File "/config/custom_components/zha/light.py", line 179, in async_turn_on
    duration
  File "/config/custom_components/zha/core/channels/__init__.py", line 48, in wrapper
    result = await command(*args, **kwds)
  File "/config/deps/lib/python3.7/site-packages/zigpy/device.py", line 90, in request
    expect_reply=expect_reply,
  File "/config/deps/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 83, in request
    assert sequence not in self._pending
AssertionError

Now the light.stairs_light group only seems to control the light.stairs_5 entity. I'm seeing a similar error on another group, same Tradfri type of device.

Nothing is showing as unavailable or offline.

And without me taking any action apart from trying to turn things on or off in HA everything is working normally again. Just a few minutes.

This is using your forgive_missing_basic branch. I am generally seeing far fewer errors logged on this branch. The only one is this that crops up every 10 minutes or so...

2019-02-26 17:45:43 WARNING (MainThread) [zigpy_deconz.zigbee.application] Error while sending frame: 0xd0
2019-02-26 17:45:53 WARNING (MainThread) [zigpy_deconz.zigbee.application] Error while sending frame: 0xd0

Ah just seen your message whilst typing this
"do you know what the signature is for these (endpoints, input and output clusters)"
I don't know How would I find that information?
Screenshot of the device zha information attached

[StyxyDog]

And another failure just a few minutes later...

2019-02-26 18:14:24 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/homeassistant/helpers/service.py", line 289, in _handle_service_platform_call
    await getattr(entity, func)(**data)
  File "/config/custom_components/zha/light.py", line 206, in async_turn_off
    success = await self._on_off_channel.off()
  File "/config/custom_components/zha/core/channels/__init__.py", line 48, in wrapper
    result = await command(*args, **kwds)
  File "/config/deps/lib/python3.7/site-packages/zigpy/device.py", line 90, in request
    expect_reply=expect_reply,
  File "/config/deps/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 83, in request
    assert sequence not in self._pending
AssertionError

[StyxyDog]

I spammed the button to turn the group on a couple of times and it seemed to break it. Could this be something to do with receiving too many simultaneous requests to switch? If I don't do anything for a minute or so the lights become responsive again. I have quite a lot of zigbee devices approx 25 and two rooms are using these light groups. So the living room has 4 zigbee switches/lightbulbs and the stairway has 5. If these two groups get triggered in short succession it seems to make it fail for a bit. Sorry for all the messages, just thought it might be relevant.

[dmulcahey]

@StyxyDog don't apologize... i'll take all the info I can get. How many bulbs are there total? I guess it could cause an issue... but it really shouldn't. also, it looks like you need a fix that is in development for zigpy_deconz: https://github.com/zigpy/zigpy-deconz/pull/20 based on this log: line 83, in request assert sequence not in self._pending AssertionError is all of this being done through the HA UI?

[StyxyDog]

I have: 8 Tradfri bulbs; 7 Tradfri control outlets (these behave very well); 8 xiaomi motion; 2 xiaomi door.
No errors to report overnight - its the cleanest I've seen the logs in ages. I restarted HASS this morning and started seeing WARNING (MainThread) [zigpy_deconz.zigbee.application] Error while sending frame: 0xd0 However, as soon as all the devices had reported in those warnings stopped. I think this is expected behaviour.
The @dmulcahey forgive_missing_basic branch seems to have resolved the errors. Thanks so much for your work on this.

Just as a test I tried clicking the light group on and off in rapid succession, about 10 times and I did manage to make the group fail with the assert sequence not in self._pending error. Some bulbs recovered from this after a short time, but I had to physically power the others off and back on. After this they worked immediately and without error in HA. But I don't see this occurring under normal circumstances, and I can wait and see what fix comes out of zigy-deconz.

[dmulcahey]

@styxyDog that’s good to know. I’ll get working on a permanent fix.

[dmulcahey]

@StyxyDog if you have some time and don't mind helping... can you try 2 things for me? 1st, try the HA dev branch. it has some other changes that may make the other branch unnecessary. if that doesn't work i'll give you another branch to try if you're up for it :)

[StyxyDog]

Happy to help, if it helps you get to the bottom of the problem. I don't think I can get on the dev branch as I'm running hass.io. Had a quick google around but couldn't find anything, do you know if that's possible?

I can easily try your other branch by dropping the files into my custom_components directory. That's how I'm currently running the forgive_missing_basic branch.

[dmulcahey]

You can do that with the dev branch too. Just do the same thing.

[Adminiuga]

@StyxyDog

Just as a test I tried clicking the light group on and off in rapid succession, about 10 times and I did manage to make the group fail with the assert sequence not in self._pending error.

If you are still able to reproduce assert sequence not in self._pending with the fixed zigpy-deconz then collect the logs and report it to zigpy-deconz existing issue. The sooner the authors get feedback, means faster you could get it fixed.

[StyxyDog]

@dmulcahey Ok, just taking a back up.
Is the fix you're wanting to test in zha or somewhere deeper in HA? I mean is this just the zha component from the home assistant dev branch i.e. https://github.com/home-assistant/home-assistant/tree/dev/homeassistant/components/zha
or is the entire dev branch of HA?

[StyxyDog]

Thanks @Adminiuga I will do, but I've not properly tried the fixed zigpy-deconz yet. I'll move on to that next. I did briefly try it, but I was getting too many errors at the time and I didn't want to complicate the issue with too many changes. The 10 clicks and error was with the un-fixed version of zigpy-deconz.

[dmulcahey]

@StyxyDog just ZHA

[StyxyDog]

@dmulcahey Looks good. No errors appearing - just the start-up warnings. I can leave it running for the evening and let you know tomorrow how its going. I would certainly have seen issues within that time frame previously.
Is there anything specific you would like me to do to test? Let me know.
Cheers

[dmulcahey]

Nope, thx man

[StyxyDog]

@dmulcahey FYI a couple of warnings in the logs. I think some of these are new to me. Nothing was happening at the time, apart from maybe a dog moving around the house and triggering the motion sensors/lights. Things seem to be working correctly.

Quite a few of WARNING (MainThread) [zigpy_deconz.zigbee.application] Error while sending frame:followed by various values in the format 0xe9

This is a new one...
2019-02-27 17:23:14 WARNING (MainThread) [zigpy.zdo] Unknown ZDO cluster 0x8038

2019-02-27 17:23:14 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected response TSN=0 command=32824 args=b'\x00\x00\xf8\xff\x07\x1b\x00\x07\x00\x10\xba\x9d\xa5\xa9\x9e\xa2\xa0\xa1\x9c\x9c\x9c\x9c\x9c\x9c\x9c\xb4', 0 2

This is on the dev branch.

[dmulcahey]

The error one is a question for Zigpy deconz. The other happens from time to time and is a warning... safe to ignore.

[StyxyDog]

Morning @dmulcahey , a few errors to report from the dev branch.

The group of 5 'stairs' lights were turned off by a node-red HA automation at 22:23 and became unavailable at 00:29 (just over 2h). This happened to all 5 lights at the same time, but no other lights.
I can't see anything relevant in the log for 00:29 when they were marked as unavailable.

This also happened to one other light different timings, the first time it failed it was a 3 hour gap, the second a 2 hour gap between last operation and unavailable.

One light has behaved itself and is still working this morning.

Happy to change things or continue testing on this branch. At the moment the group is still unavailable and I'll leave it like that for now, can't guarantee someone won't go and physically toggle the switch though.

log messages...

019-02-27 22:09:57 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.1877325680] Error handling message: {'type': 'call_service', 'domain': 'light', 'service': 'turn_on', 'service_data': {'entity_id': 'light.stairs_3', 'transition': '20'}, 'id': 927}
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/websocket_api/decorators.py", line 17, in _handle_async_response
    await func(hass, connection, msg)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/websocket_api/commands.py", line 147, in handle_call_service
    connection.context(msg))
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1133, in async_call
    self._execute_service(handler, service_call))
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1155, in _execute_service
    await handler.func(service_call)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/light/__init__.py", line 288, in async_handle_light_on_service
    await light.async_turn_on(**pars)
  File "/config/custom_components/zha/light.py", line 166, in async_turn_on
    duration
  File "/config/custom_components/zha/core/channels/__init__.py", line 49, in wrapper
    result = await command(*args, **kwds)
  File "/config/deps/lib/python3.7/site-packages/zigpy/device.py", line 90, in request
    expect_reply=expect_reply,
  File "/config/deps/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 83, in request
    assert sequence not in self._pending
AssertionError

2019-02-27 22:22:25 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.1877325680] Error handling message: {'type': 'call_service', 'domain': 'light', 'service': 'turn_on', 'service_data': {'entity_id': 'light.stairs_2', 'transition': '20'}, 'id': 967}
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/websocket_api/decorators.py", line 17, in _handle_async_response
    await func(hass, connection, msg)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/websocket_api/commands.py", line 147, in handle_call_service
    connection.context(msg))
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1133, in async_call
    self._execute_service(handler, service_call))
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1155, in _execute_service
    await handler.func(service_call)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/light/__init__.py", line 288, in async_handle_light_on_service
    await light.async_turn_on(**pars)
  File "/config/custom_components/zha/light.py", line 166, in async_turn_on
    duration
  File "/config/custom_components/zha/core/channels/__init__.py", line 49, in wrapper
    result = await command(*args, **kwds)
  File "/config/deps/lib/python3.7/site-packages/zigpy/device.py", line 90, in request
    expect_reply=expect_reply,
  File "/config/deps/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 83, in request
    assert sequence not in self._pending
AssertionError

2019-02-27 22:22:26 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.1877325680] Error handling message: {'type': 'call_service', 'domain': 'light', 'service': 'turn_on', 'service_data': {'entity_id': 'light.stairs_3', 'transition': '20'}, 'id': 968}
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/websocket_api/decorators.py", line 17, in _handle_async_response
    await func(hass, connection, msg)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/websocket_api/commands.py", line 147, in handle_call_service
    connection.context(msg))
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1133, in async_call
    self._execute_service(handler, service_call))
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1155, in _execute_service
    await handler.func(service_call)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/light/__init__.py", line 288, in async_handle_light_on_service
    await light.async_turn_on(**pars)
  File "/config/custom_components/zha/light.py", line 166, in async_turn_on
    duration
  File "/config/custom_components/zha/core/channels/__init__.py", line 49, in wrapper
    result = await command(*args, **kwds)
  File "/config/deps/lib/python3.7/site-packages/zigpy/device.py", line 90, in request
    expect_reply=expect_reply,
  File "/config/deps/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 83, in request
    assert sequence not in self._pending
AssertionError

2019-02-27 22:22:27 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.1877325680] Error handling message: {'type': 'call_service', 'domain': 'light', 'service': 'turn_on', 'service_data': {'entity_id': 'light.stairs_4', 'transition': '20'}, 'id': 969}
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/websocket_api/decorators.py", line 17, in _handle_async_response
    await func(hass, connection, msg)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/websocket_api/commands.py", line 147, in handle_call_service
    connection.context(msg))
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1133, in async_call
    self._execute_service(handler, service_call))
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1155, in _execute_service
    await handler.func(service_call)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/light/__init__.py", line 288, in async_handle_light_on_service
    await light.async_turn_on(**pars)
  File "/config/custom_components/zha/light.py", line 175, in async_turn_on
    success = await self._on_off_channel.on()
  File "/config/custom_components/zha/core/channels/__init__.py", line 49, in wrapper
    result = await command(*args, **kwds)
  File "/config/deps/lib/python3.7/site-packages/zigpy/device.py", line 90, in request
    expect_reply=expect_reply,
  File "/config/deps/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 83, in request
    assert sequence not in self._pending
AssertionError

Light entities

zha. entities

[Adminiuga]

This requires fix for zigpy-deconz which is in the master. Copying it custom_component folder won't do it, as it is not a custom component

[StyxyDog]

No easy way to apply that fix to hass.io then, @Adminiuga?
I don't think I was getting this issue in this branch of zha https://github.com/dmulcahey/home-assistant/tree/dm/zha-forgive-missing-basic, presumably using the same version of zigpy-deconz, or maybe I didn't test for long enough.

[Adminiuga]

No easy way to apply that fix to hass.io then, @Adminiuga?

unfortunately I don't think there's a way to do it on hass.io

I don't think I was getting this issue in this branch of zha https://github.com/dmulcahey/home-assistant/tree/dm/zha-forgive-missing-basic, presumably using the same version of zigpy-deconz, or maybe I didn't test for long enough.

the sequence assertion error is definitely related to zigpy-deconz bug and I'd be really surprised if it has anything to do with the issues the zha-forgive-missing-basic addresses.

@damarco any chance to push zigpy-deconz sequence leak fix before the next HA release?

[StyxyDog]

Thank you @Adminiuga

I've found that in the dev branch I can click reconfigure and the device becomes available without a HA restart or a powercycle.

As a workaround, @dmulcahey, is there any way that we could have the reconfigure button as a service available to HA. I'm thinking that I could automate the process of doing a zha reconfigure when a device becomes unavailable. zha.reconfigure perhaps?

Edit:
Looking at https://github.com/home-assistant/home-assistant/blob/dev/homeassistant/components/zha/services.yaml I see that reconfigure_device: is available already, I'll see if that works.

Nope, it can't find that service. Not sure why. I'll try and check things through later.

[dmulcahey]

@styxyDog I’m working on a better solution. Hopefully will have something for you to try by the end of the weekend.

[StyxyDog]

@dmulcahey thanks you.
Just wanted to say the lights have been really stable on the dev branch, especially since I issued reconfigure commands to all the bulbs. I guess I should be doing that each time I change the zha version.

[dmulcahey]

@StyxyDog I’m working on something to do that automatically.

[StyxyDog]

Slight glitch overnight. The lights became unresponsive - not all, but most. A reconfigure didn't work nor a restart of HASS. A reboot of the PI didn't fix and in the end I had to shutdown and pull the power. HASS has restarted and everything looks fine. The group of lights is working again. Something a bit odd going on there.
Not sure its related to what you've been working on at all could be a hardware glitch. This is the only error I could see that might correspond to the fault.

2019-03-04 07:44:26 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/config/deps/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 104, in request
    r = await asyncio.wait_for(send_fut, SEND_CONFIRM_TIMEOUT)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 423, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

[dmulcahey]

I think that’s zigpy_deconz

[StyxyDog]

I've removed the dev branch and installed HA 0.89.0. Seems to be functioning pretty well - a few errors still, but I think these are with the underlying zigpy_deconz. I'm going to close this issue and open a new issue if problems persists in 0.89.
Thanks very much for your help, it is, and you are, most appreciated.