ZHA Zigbee stops sending events and are generally fairly unstable

maxandersen commented 3 years ago

The problem

I moved from using conbee directly to zha some months ago - everything was great.

In the latest updates (not sure which) zha/zigbee integration stops sending zigbee events (zha_event) and all automation stops functioning.

Environment

Home Assistant Core release with the issue: Home Assistant 2021.1.1
Last working Home Assistant Core release (if known): best guess is this worked before the new versioning scheme.
Operating environment (OS/Container/Supervised/Core): raspberry 4 supervised
Integration causing this issue: zha/zigbee
Link to integration documentation on our website: https://www.home-assistant.io/integrations/zha/

Problem-relevant `configuration.yaml`

<no yaml, all via integrations>

Traceback/Error logs

2021-01-14_13-30-47

sorry for the screengrab but just couldn't get copy/paste working in homeassistant terminal via browser.

Additional information

probot-home-assistant[bot] commented 3 years ago

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

maxandersen commented 3 years ago

This is now happen daily - I see nothing reacts/works; restart homeassistant then a few hours later I notice it again.

maxandersen commented 3 years ago

I can see that if I click "reload" on zigbee component in integrations it starts working again.

I guess I can setup a regular reload of that as a workaround

Adminiuga commented 3 years ago

https://www.home-assistant.io/integrations/zha/#reporting-issues

maxandersen commented 3 years ago

Ack - I've enabled the logging, restarted and now I wait for it to happen again.

hackex commented 3 years ago

Ack - I've enabled the logging, restarted and now I wait for it to happen again.

Any news? My ZHA also seems to be quite unstable. I also enabled logging now.

Stefano0042 commented 3 years ago

I can see that if I click "reload" on zigbee component in integrations it starts working again.

I guess I can setup a regular reload of that as a workaround

Exactly same issues here on release 2021.1.3; 2021.1.4 (Conbee II as coordinator), I've been forced to roll back to the deprecated now 2020.12.2 where ZHA is running flawless.

ybjlus commented 3 years ago

Same here, conbee 2 and since update to 2021.1.4 all problems have starten. Really instable and at a server restart all my zigbee devices are unavailable. I have to restart the whole system to get is back online again.

If logs are needed, let me know.

Adminiuga commented 3 years ago

Check https://github.com/home-assistant/core/issues/45144#issuecomment-760967380

Adminiuga commented 3 years ago

If you have deCONZ add-on installed, uninstall it

ybjlus commented 3 years ago

I don't have any other zigbee add-ons installed. And it used to work perfectly.

But now even with a system restart my devices will not load.

Running on virtualbox: Conbee 2 core-2021.1.4 supervisor-2021.01.5

2021-01-19 01:44:26 WARNING (MainThread) [zigpy_deconz.api] No response to 'Command.read_parameter' command with seq id '0x02'
2021-01-19 01:44:26 ERROR (MainThread) [zigpy.application] Couldn't start application
2021-01-19 01:44:26 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start deCONZ = dresden elektronik deCONZ protocol: ConBee I/II, RaspBee I/II coordinator
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 157, in async_initialize
self.application_controller = await app_controller_cls.new(
File "/usr/local/lib/python3.8/site-packages/zigpy/application.py", line 69, in new
await app.startup(auto_form)
File "/usr/local/lib/python3.8/site-packages/zigpy_deconz/zigbee/application.py", line 66, in startup
self.version = await self._api.version()
File "/usr/local/lib/python3.8/site-packages/zigpy_deconz/api.py", line 444, in version
(self._proto_ver,) = await self[NetworkParameter.protocol_version]
File "/usr/local/lib/python3.8/site-packages/zigpy_deconz/api.py", line 409, in read_parameter
r = await self._command(Command.read_parameter, 1 + len(data), param, data)
File "/usr/local/lib/python3.8/site-packages/zigpy_deconz/api.py", line 305, in _command
return await asyncio.wait_for(fut, timeout=COMMAND_TIMEOUT)
File "/usr/local/lib/python3.8/asyncio/tasks.py", line 501, in wait_for
raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError
2021-01-19 01:44:26 WARNING (MainThread) [homeassistant.config_entries] Config entry for zha not ready yet. Retrying in 10 seconds
2021-01-19 01:44:36 DEBUG (MainThread) [zigpy.appdb] Loading application state from %s
2021-01-19 01:44:36 WARNING (MainThread) [zigpy.zcl] Unknown cluster 61184
2021-01-19 01:44:36 WARNING (MainThread) [zigpy.zcl] Unknown cluster 61184

full log: https://pastebin.com/ZV8XNiqm

Adminiuga commented 3 years ago

Can you also enable debug for zigpy_deconz.uart: debug
Physically un-plug and plug back in the ConBee stick
reboot the host in this order and post the logs

ashar38 commented 3 years ago

Same issue. The update to 2021 version broke ZHA. I have a feeling it is not necessarily an issue with ZHA, but something else which has broken with either Docker or HomeAssistant itself. This is because I tried to test if I could get Zigbee2Mqtt to get working but that failed with timeouts as well. Here are logs from ZHA if they help. As you would notice, tha Conbee stick was last seen some 40 mins ago. If I delete the ZHA integration and create it again, it correctly picks the conbee stick in dropdown list, and configures it, but LQI remains unknown.

2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.appdb] Loading application state from %s 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Checking quirks for None None (00:21:2e:ff:ff:06:65:4e) 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xbee.xbee_io.XBeeSensor'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {232, 230} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xbee.xbee3_io.XBee3Sensor'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {232, 230} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.smartthings.tag_v4.SmartThingsTagV4'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.smartthings.multi.SmartthingsMultiPurposeSensor'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rwl021.PhilipsRWL021'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1, 2} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rwl020.PhilipsRWL020'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1, 2} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rom001.PhilipsROM001'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.netvox.z308e3ed.Z308E3ED'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.gledopto.soposhgu10.SoposhGU10'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {11, 13} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'bellows.zigbee.application.EZSPCoordinator'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xbee.xbee_io.XBeeSensor'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {232, 230} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xbee.xbee3_io.XBee3Sensor'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {232, 230} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.smartthings.tag_v4.SmartThingsTagV4'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.smartthings.multi.SmartthingsMultiPurposeSensor'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rwl021.PhilipsRWL021'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1, 2} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rwl020.PhilipsRWL020'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1, 2} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rom001.PhilipsROM001'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.netvox.z308e3ed.Z308E3ED'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.gledopto.soposhgu10.SoposhGU10'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {11, 13} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'bellows.zigbee.application.EZSPCoordinator'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xbee.xbee_io.XBeeSensor'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {232, 230} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xbee.xbee3_io.XBee3Sensor'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {232, 230} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.smartthings.tag_v4.SmartThingsTagV4'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.smartthings.multi.SmartthingsMultiPurposeSensor'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rwl021.PhilipsRWL021'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1, 2} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rwl020.PhilipsRWL020'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1, 2} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rom001.PhilipsROM001'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.netvox.z308e3ed.Z308E3ED'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.gledopto.soposhgu10.SoposhGU10'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {11, 13} {1, 242} 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'bellows.zigbee.application.EZSPCoordinator'> 2021-01-19 00:27:25 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 242} 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Connection made 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Command Command.read_parameter (1, <NetworkParameter.protocol_version: 34>, b'') 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x0a02000800010022 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0a02000a000300220c01 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Read parameter protocol_version response: [268] 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Command Command.version (0,) 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x0d0300090000000000 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0d0300090000076626 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Version response: 26660700 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Command Command.device_state (0, 0, 0) 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x0704000800000000 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0704000800a20066 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Device state response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 162>, 0, 102] 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Network state transition: OFFLINE -> CONNECTED 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Command Command.read_parameter (1, <NetworkParameter.mac_address: 1>, b'') 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x0a05000800010001 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0a050010000900014e6506ffff2e2100 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Read parameter mac_address response: [00:21:2e:ff:ff:06:65:4e] 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Command Command.read_parameter (1, <NetworkParameter.aps_designed_coordinator: 9>, b'') 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x0a06000800010009 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0a0600090002000901 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Read parameter aps_designed_coordinator response: [1] 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Command Command.write_parameter (5, <NetworkParameter.watchdog_ttl: 38>, b'X\x02\x00\x00') 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x0b07000c0005002658020000 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0b07000800010026 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Write parameter watchdog_ttl: SUCCESS 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Command Command.device_state (0, 0, 0) 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x0708000800000000 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0708000800a20026 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Device state response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 162>, 0, 38] 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Command Command.read_parameter (1, <NetworkParameter.nwk_panid: 5>, b'') 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x0a09000800010005 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0a09000a00030005fb6d 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Read parameter nwk_panid response: [0x6dfb] 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Command Command.read_parameter (1, <NetworkParameter.nwk_address: 7>, b'') 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x0a0a000800010007 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0a0a000a000300070000 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Read parameter nwk_address response: [0x0000] 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Command Command.read_parameter (1, <NetworkParameter.nwk_extended_panid: 8>, b'') 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x0a0b000800010008 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0a0b0010000900084e6506ffff2e2100 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Read parameter nwk_extended_panid response: [00:21:2e:ff:ff:06:65:4e] 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Command Command.read_parameter (1, <NetworkParameter.channel_mask: 10>, b'') 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x0a0c00080001000a 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0a0c000c0005000a00080000 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Read parameter channel_mask response: [<Channels.CHANNEL_11: 2048>] 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Command Command.read_parameter (1, <NetworkParameter.aps_extended_panid: 11>, b'') 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x0a0d00080001000b 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0a0d00100009000b0000000000000000 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Read parameter aps_extended_panid response: [00:00:00:00:00:00:00:00] 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Command Command.read_parameter (1, <NetworkParameter.trust_center_address: 14>, b'') 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x0a0e00080001000e 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0a0e00100009000e4e6506ffff2e2100 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Read parameter trust_center_address response: [00:21:2e:ff:ff:06:65:4e] 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Command Command.read_parameter (1, <NetworkParameter.security_mode: 16>, b'') 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x0a0f000800010010 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0a0f00090002001003 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Read parameter security_mode response: [3] 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Command Command.read_parameter (1, <NetworkParameter.current_channel: 28>, b'') 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x0a1000080001001c 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0a1000090002001c0b 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Read parameter current_channel response: [11] 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Command Command.read_parameter (1, <NetworkParameter.protocol_version: 34>, b'') 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x0a11000800010022 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0a11000a000300220c01 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Read parameter protocol_version response: [268] 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Command Command.read_parameter (1, <NetworkParameter.nwk_update_id: 36>, b'') 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x0a12000800010024 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0a1200090002002401 2021-01-19 00:27:26 DEBUG (MainThread) [zigpy_deconz.api] Read parameter nwk_update_id response: [1] 2021-01-19 00:27:26 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event device_registry_updated[L]: action=update, device_id=81b5ae34e51456b8cefd9a3f98fc8c08> 2021-01-19 00:27:26 DEBUG (MainThread) [homeassistant.components.zha.core.gateway] [0x0000](dresden elektronik ConBee II) restored as 'available', last seen: 0:38:39 ago

maxandersen commented 3 years ago

I can report mine is still Failing eventually.

I haven't done much since at same time all my automations disappeared so haven't been able to test properly to get decent logs.

I'll try some more. But it definitely zha just breaking constantly.

MattWestb commented 3 years ago

I think @Indybeak is on the right track then the deconz radio part is not changed (only the code tests is changed not the running code if the code was OK written before the test change) for over 2 months. And other radios is not having problems using there comports. Can being dependencies in HA or changes in the docker part :-((

Do users that is running in native (no docker environment like linux) also facing the same problems ??

Adminiuga commented 3 years ago

As you would notice, tha Conbee stick was last seen some 40 mins ago.

Don't rely on the last seen for the conbee stick itself, it is not updated reliably and is known to be marked as offline eventually. That is not indication of the problem. In log you provided all commands received response, so it looks functional. Need to see when it starts getting no response to the commands and what leads to it, if there's consistency between installations.

ashar38 commented 3 years ago

As you would notice, tha Conbee stick was last seen some 40 mins ago.

Don't rely on the last seen for the conbee stick itself, it is not updated reliably and is known to be marked as offline eventually. That is not indication of the problem. In log you provided all commands received response, so it looks functional. Need to see when it starts getting no response to the commands and what leads to it, if there's consistency between installations.

Thank you for taking a look. Some more logs from just now, when I try to do an "Add Device". Once again, my feeling is that the issue is likely not with ZHA but something else. I formatted and did a fresh install of Docker and HomeAssistant last night. With no success.

2021-01-19 09:46:08 DEBUG (MainThread) [zigpy_znp.zigbee.application] Probing /dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2255798-if00 2021-01-19 09:46:08 DEBUG (MainThread) [zigpy_znp.uart] Connecting to /dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2255798-if00 at 115200 baud 2021-01-19 09:46:08 DEBUG (MainThread) [zigpy_znp.uart] Opened /dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2255798-if00 serial port 2021-01-19 09:46:08 DEBUG (MainThread) [zigpy_znp.uart] Toggling RTS/CTS to skip CC2652R bootloader 2021-01-19 09:46:09 DEBUG (MainThread) [zigpy_znp.uart] Connected to /dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2255798-if00 at 115200 baud 2021-01-19 09:46:09 DEBUG (MainThread) [zigpy_znp.api] Waiting 1s before sending anything 2021-01-19 09:46:10 DEBUG (MainThread) [zigpy_znp.api] Sending bootloader skip byte 2021-01-19 09:46:10 DEBUG (MainThread) [zigpy_znp.uart] Sending data: b'\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF' 2021-01-19 09:46:10 DEBUG (MainThread) [zigpy_znp.api] Waiting 1s or until a reset indication is received 2021-01-19 09:46:10 DEBUG (MainThread) [zigpy_znp.api] Creating one-shot listener OneShotResponseListener(matching_commands=(SYS.ResetInd.Callback(Reason=None, TransportRev=None, ProductId=None, MajorRel=None, MinorRel=None, MaintRel=None),), future=<Future pending cb=[ZNP.wait_for_responses..() at /usr/local/lib/python3.8/site-packages/zigpy_znp/api.py:436, <TaskWakeupMethWrapper object at 0xb2d59dc0>()]>) 2021-01-19 09:46:11 DEBUG (MainThread) [zigpy_znp.api] Removing listener OneShotResponseListener(matching_commands=(SYS.ResetInd.Callback(Reason=None, TransportRev=None, ProductId=None, MajorRel=None, MinorRel=None, MaintRel=None),), future=) 2021-01-19 09:46:11 DEBUG (MainThread) [zigpy_znp.api] Cleaning up empty listener list for header CommandHeader(id=0x80, subsystem=Subsystem.SYS, type=CommandType.AREQ) 2021-01-19 09:46:11 DEBUG (MainThread) [zigpy_znp.api] There are 0 callbacks and 0 one-shot listeners remaining 2021-01-19 09:46:11 DEBUG (MainThread) [zigpy_znp.api] Testing connection to /dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2255798-if00 2021-01-19 09:46:11 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Version.Req() 2021-01-19 09:46:11 DEBUG (MainThread) [zigpy_znp.api] Creating one-shot listener OneShotResponseListener(matching_commands=(SYS.Version.Rsp(TransportRev=None, ProductId=None, MajorRel=None, MinorRel=None, MaintRel=None, CodeRevision=None, BootloaderBuildType=None, BootloaderRevision=None), RPCError.CommandNotRecognized.Rsp(ErrorCode=None, RequestHeader=CommandHeader(id=0x02, subsystem=Subsystem.SYS, type=CommandType.SREQ))), future=<Future pending cb=[ZNP.wait_for_responses..() at /usr/local/lib/python3.8/site-packages/zigpy_znp/api.py:436, <TaskWakeupMethWrapper object at 0xac1fdb80>()]>) 2021-01-19 09:46:11 DEBUG (MainThread) [zigpy_znp.uart] Sending data: b'\xFE\x00\x21\x02\x23' 2021-01-19 09:46:13 DEBUG (MainThread) [zigpy_znp.api] Removing listener OneShotResponseListener(matching_commands=(SYS.Version.Rsp(TransportRev=None, ProductId=None, MajorRel=None, MinorRel=None, MaintRel=None, CodeRevision=None, BootloaderBuildType=None, BootloaderRevision=None), RPCError.CommandNotRecognized.Rsp(ErrorCode=None, RequestHeader=CommandHeader(id=0x02, subsystem=Subsystem.SYS, type=CommandType.SREQ))), future=) 2021-01-19 09:46:13 DEBUG (MainThread) [zigpy_znp.api] Cleaning up empty listener list for header CommandHeader(id=0x00, subsystem=Subsystem.RPCError, type=CommandType.SRSP) 2021-01-19 09:46:13 DEBUG (MainThread) [zigpy_znp.api] Cleaning up empty listener list for header CommandHeader(id=0x02, subsystem=Subsystem.SYS, type=CommandType.SRSP) 2021-01-19 09:46:13 DEBUG (MainThread) [zigpy_znp.api] There are 0 callbacks and 0 one-shot listeners remaining 2021-01-19 09:46:13 WARNING (MainThread) [zigpy_znp.zigbee.application] Failed to probe ZNP radio with config {'path': '/dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2255798-if00', 'flow_control': None, 'baudrate': 115200} Traceback (most recent call last): File "/usr/local/lib/python3.8/site-packages/zigpy_znp/zigbee/application.py", line 167, in probe await znp.connect() File "/usr/local/lib/python3.8/site-packages/zigpy_znp/api.py", line 234, in connect self._version = await self.request(c.SYS.Version.Req()) File "/usr/local/lib/python3.8/site-packages/zigpy_znp/api.py", line 507, in request response = await response_future asyncio.exceptions.CancelledError During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/local/lib/python3.8/site-packages/zigpy_znp/zigbee/application.py", line 167, in probe await znp.connect() File "/usr/local/lib/python3.8/site-packages/async_timeout/init.py", line 55, in aexit self._do_exit(exc_type) File "/usr/local/lib/python3.8/site-packages/async_timeout/init.py", line 92, in _do_exit raise asyncio.TimeoutError asyncio.exceptions.TimeoutError 2021-01-19 09:46:13 DEBUG (MainThread) [zigpy_znp.uart] Closing serial port 2021-01-19 09:46:13 DEBUG (MainThread) [zigpy_znp.api] We were disconnected from /dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2255798-if00: None 2021-01-19 09:46:13 DEBUG (MainThread) [bellows.ezsp] Resetting EZSP 2021-01-19 09:46:16 DEBUG (MainThread) [bellows.ezsp] Unsuccessful radio probe of '/dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2255798-if00' port Traceback (most recent call last): File "/usr/local/lib/python3.8/site-packages/bellows/ezsp/init.py", line 55, in probe await asyncio.wait_for(ezsp._probe(), timeout=PROBE_TIMEOUT) File "/usr/local/lib/python3.8/asyncio/tasks.py", line 501, in wait_for raise exceptions.TimeoutError() asyncio.exceptions.TimeoutError

ybjlus commented 3 years ago

I've noticed it's a bit random... I'm running the deconz_uart log now and no problems at all. I'll keep monitoring it for now.

Adminiuga commented 3 years ago

there seem to be a similar report for deCONZ integration https://github.com/home-assistant/core/issues/45316

Adminiuga commented 3 years ago

@Indybeak the log you provided doesn't really seem consistent the screenshot, as per logs it looks like "autodetection" of ZHA integration, which only happens when there's no ZHA integration configured at all. I wonder if somehow there are two different HA instances running???

ashar38 commented 3 years ago

@Indybeak the log you provided doesn't really seem consistent the screenshot, as per logs it looks like "autodetection" of ZHA integration, which only happens when there's no ZHA integration configured at all. I wonder if somehow there are two different HA instances running???

Hi @Adminiuga, it should not be as it is a fresh install of everything. I also re-verified and I just have one container running for HA. I even deleted and recreated the ZHA integration (not from Yaml file, through the UI flow), and for some weird reason, ended up having an unknown device. This device does not go even after deleting it and restarting home assistant.

I will try downgrading the Supervisor as you have suggested somewhere and see if that helps.

MattWestb commented 3 years ago

The "unk_manufacturer unk_model" you is getting if ZHA cant initiating the coordinator OK. I was getting it for some days ago then "hot swapping" coordinator after have updated the firmware on them and was putting the wrong one in my raspberry pi (It was having the wrong IEEE and all the zigbee data was not matching the installed in the database).

Its dont disappearing must being deleted in the config files by hand or deleting the HA installation.

ashar38 commented 3 years ago

The "unk_manufacturer unk_model" you is getting if ZHA cant initiating the coordinator OK. I was getting it for some days ago then "hot swapping" coordinator after have updated the firmware on them and was putting the wrong one in my raspberry pi (It was having the wrong IEEE and all the zigbee data was not matching the installed in the database).

Its dont disappearing must being deleted in the config files by hand or deleting the HA installation.

Thanks. Would you know which config file should be edited? I believe deleting and creating ZHA integration is not enough. Will it be okay to delete Zigbee.db file and reboot HA?

Adminiuga commented 3 years ago

Looks like it's gone from zigbee.db. not knowing the ieee address would be hard to cleanup .storage/zha.storage file Check if you have any dangling entities. Or click on the cog wheel and disable that device?

MattWestb commented 3 years ago

From VNC /usr/share/hassio/homeassistant/.storage/core.device_registry In the end you have somthing like that:

            {
                "config_entries": [
                    "204e8190abb946a485f72ca7c26fbf1e"
                ],
                "connections": [],
                "identifiers": [
                    [
                        "deconz",
                        "00212E02A019-/groups/2"
                    ]
                ],
                "manufacturer": "Dresden Elektronik",
                "model": "deCONZ group",
                "name": "TRADFRI on/off switch ",
                "sw_version": null,
                "entry_type": null,
                "id": "6b3b2b949636e4fc62f56023f6e25a54",
                "via_device_id": "90c4aa5cfad64d27940b28163197af4b",
                "area_id": null,
                "name_by_user": null,
                "disabled_by": null
            }
        ],
        "deleted_devices": []
    }
}

But with one device after the "deleted_devices":. Deleting the record but you must keeping the "}}" in ight place or ZHA is not starting (make one copy before editing the file.

Edit: Stop HA before doing any editing or you is getting corruptions in the system !!

ashar38 commented 3 years ago

Found it. It was actually under the zha.storage file. Also managed to find which exact device was that. It is an Ikea outlet which I believe got stuck in interview phase during one of my attempts to pair devices. I have at the moment paired two outlets and a bulb and will check stability before I go on pairing everything back.

MattWestb commented 3 years ago

@Indybeak I think the phenomene with "half saved" device is becos ZHA is saving all new devices after they is completely configured but with one delay up to 2 min and the same then deleting one device it can taking up to 2 minutes before its "real" deleted in the database. Then restarting HA it can being all things is not done completely and its finding "ghosts devices". I think your was being OK if paring the same plug and ZHA have picking it up and correcting all records of it. In my case it was deleted (the second coordinator by the system and was not coming back) and was flagged deleted but not done between restart. By the way the "jumping" between different system yor corbee can getting problem then its have network keys stored in the NVR that is not in sync with the host system and you is getting mutch problems. You can "hot swap" one TI CC-253X with HA1.2 firmware between hosts but with zigbee 3 coordinators its much more tricky then they is pared to the network and relaying on the integrity of the information and the host system is doing the same.

ashar38 commented 3 years ago

@Indybeak I think the phenomene with "half saved" device is becos ZHA is saving all new devices after they is completely configured but with one delay up to 2 min and the same then deleting one device it can taking up to 2 minutes before its "real" deleted in the database. Then restarting HA it can being all things is not done completely and its finding "ghosts devices". I think your was being OK if paring the same plug and ZHA have picking it up and correcting all records of it. In my case it was deleted (the second coordinator by the system and was not coming back) and was flagged deleted but not done between restart. By the way the "jumping" between different system yor corbee can getting problem then its have network keys stored in the NVR that is not in sync with the host system and you is getting mutch problems. You can "hot swap" one TI CC-253X with HA1.2 firmware between hosts but with zigbee 3 coordinators its much more tricky then they is pared to the network and relaying on the integrity of the information and the host system is doing the same.

Hmmm. I have just one Conbee stick so should not be a problem with jumping. I am keeping an eye on my current devices to see how they are behaving. Between, the Ikea outlet is already un-responsive. I performed some tests

Try to turn off Ikea outlet.
Try it again
Turn On Sengled Bulb
Turn Off Segled Bulb.

Here are the logs, followed by my current network visualization. All devices except the one named "Shelf Light" are in same room as the Cordinator. Within few feet of distance.

-- Failed Turn OFF Ikea Outlet - Router

2021-01-20 11:40:32 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=switch, service=turn_off, service_data=entity_id=switch.upstairs_floor_lamp_on_off> 2021-01-20 11:40:32 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 62 under 63 request id, data: b'013e00' 2021-01-20 11:40:32 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (18, 63, 0, , 260, 6, 1, b'\x01>\x00', 2, 0) 2021-01-20 11:40:32 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x126b00190012003f0002efb00104010600010300013e000200 2021-01-20 11:40:32 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x126b0009000200223f 2021-01-20 11:40:32 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, 63] 2021-01-20 11:40:32 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e6c000700a600 2021-01-20 11:40:32 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 166>, 0] 2021-01-20 11:40:32 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,) 2021-01-20 11:40:32 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x046c0007000000 2021-01-20 11:40:32 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x046c0013000c00223f02efb001010000000000 2021-01-20 11:40:32 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 63: 00 2021-01-20 11:40:32 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0x3f 'aps_data_confirm' for , status: 0x00 2021-01-20 11:40:34 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x85F7:1:0x0003]: command failed: 'trigger_effect' args: '(2, 0)' kwargs '{}' exception: ''

-- Failed Turn OFF Ikea Outlet - Router

2021-01-20 11:43:11 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=switch, service=turn_off, service_data=entity_id=switch.upstairs_floor_lamp_on_off> 2021-01-20 11:43:11 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 66 under 67 request id, data: b'014200' 2021-01-20 11:43:11 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (18, 67, 0, , 260, 6, 1, b'\x01B\x00', 2, 0) 2021-01-20 11:43:11 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x12710019001200430002efb001040106000103000142000200 2021-01-20 11:43:11 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x127100090002002243 2021-01-20 11:43:11 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, 67] 2021-01-20 11:43:11 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e72000700a600 2021-01-20 11:43:11 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 166>, 0] 2021-01-20 11:43:11 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,) 2021-01-20 11:43:11 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x04720007000000 2021-01-20 11:43:11 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x04720013000c00224302efb001010000000000 2021-01-20 11:43:11 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 67: 00 2021-01-20 11:43:11 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0x43 'aps_data_confirm' for , status: 0x00 2021-01-20 11:43:16 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xB0EF:1:0x0006]: command failed: 'off' args: '()' kwargs '{}' exception: ''

---- Successful turn ON -- End Device Light

2021-01-20 11:44:00 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.office_lamp_level_on_off> 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy.device] [0x4a59] Extending timeout for 0x44 request 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 68 under 69 request id, data: b'014401' 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (18, 69, 0, , 260, 6, 1, b'\x01D\x01', 2, 0) 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x12730019001200450002594a01040106000103000144010200 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x127300090002002245 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, 69] 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e74000700a600 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 166>, 0] 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,) 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x04740007000000 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x04740013000c00224502594a01010000000000 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 69: 00 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0x45 'aps_data_confirm' for , status: 0x00 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e75000700aa00 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 0] 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1) 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x1775000800010001 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x17750023001c002a0200000102594a0104010600050008440b010000afffbe2f0100cf 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [28, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 42>, , 1, , 1, 260, 6, b'\x08D\x0b\x01\x00', 0, 175, 255, 190, 47, 1, 0, -49] 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy.zcl] [0x4a59:1:0x0006] ZCL deserialize: <ZCLHeader frame_control= manufacturer=None tsn=68 command_id=Command.Default_Response> 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from , ep: 1, profile: 0x0104, cluster_id: 0x0006, data: b'08440b0100' 2021-01-20 11:44:00 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x4A59:1:0x0006]: executed 'on' command with args: '()' kwargs: '{}' result: [1, <Status.SUCCESS: 0>] 2021-01-20 11:44:00 DEBUG (MainThread) [homeassistant.components.zha.entity] light.office_lamp_level_on_off: turned on: {'on_off': [1, <Status.SUCCESS: 0>]} 2021-01-20 11:44:00 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.office_lamp_level_on_off, old_state=<state light.office_lamp_level_on_off=off; off_brightness=None, friendly_name=Office Lamp level, on_off, supported_features=41 @ 2021-01-20T11:40:18.307579-05:00>, new_state=<state light.office_lamp_level_on_off=on; brightness=255, off_brightness=None, friendly_name=Office Lamp level, on_off, supported_features=41 @ 2021-01-20T11:44:00.241655-05:00>> 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1) 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x1776000800010001 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x17760025001e00220200000102594a01040106000700184c0a0000100100afffab2f0100cf 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [30, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, , 1, , 1, 260, 6, b'\x18L\n\x00\x00\x10\x01', 0, 175, 255, 171, 47, 1, 0, -49] 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy.zcl] [0x4a59:1:0x0006] ZCL deserialize: <ZCLHeader frame_control= manufacturer=None tsn=76 command_id=Command.Report_Attributes> 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy.zcl] [0x4a59:1:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=)]] 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy.zcl] [0x4a59:1:0x0006] Attribute report received: on_off=1 2021-01-20 11:44:00 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from , ep: 1, profile: 0x0104, cluster_id: 0x0006, data: b'184c0a00001001'

---- Successful turn OFF -- End Device Light

2021-01-20 11:46:55 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_off, service_data=entity_id=light.office_lamp_level_on_off> 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy.device] [0x4a59] Extending timeout for 0x4a request 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 74 under 75 request id, data: b'014a00' 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (18, 75, 0, , 260, 6, 1, b'\x01J\x00', 2, 0) 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x128000190012004b0002594a0104010600010300014a000200 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x12800009000200224b 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, 75] 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e81000700a600 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 166>, 0] 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,) 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x04810007000000 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x04810013000c00224b02594a01010000000000 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 75: 00 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0x4b 'aps_data_confirm' for , status: 0x00 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e82000700aa00 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 0] 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1) 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x1782000800010001 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x17820023001c002a0200000102594a01040106000500084a0b000000afffe42f0100cf 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [28, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 42>, , 1, , 1, 260, 6, b'\x08J\x0b\x00\x00', 0, 175, 255, 228, 47, 1, 0, -49] 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy.zcl] [0x4a59:1:0x0006] ZCL deserialize: <ZCLHeader frame_control= manufacturer=None tsn=74 command_id=Command.Default_Response> 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from , ep: 1, profile: 0x0104, cluster_id: 0x0006, data: b'084a0b0000' 2021-01-20 11:46:55 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x4A59:1:0x0006]: executed 'off' command with args: '()' kwargs: '{}' result: [0, <Status.SUCCESS: 0>] 2021-01-20 11:46:55 DEBUG (MainThread) [homeassistant.components.zha.entity] light.office_lamp_level_on_off: turned off: [0, <Status.SUCCESS: 0>] 2021-01-20 11:46:55 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.office_lamp_level_on_off, old_state=<state light.office_lamp_level_on_off=on; brightness=254, off_brightness=None, friendly_name=Office Lamp level, on_off, supported_features=41 @ 2021-01-20T11:44:00.241655-05:00>, new_state=<state light.office_lamp_level_on_off=off; off_brightness=None, friendly_name=Office Lamp level, on_off, supported_features=41 @ 2021-01-20T11:46:55.470943-05:00>> 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1) 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x1783000800010001 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x17830025001e00220200000102594a01040106000700184e0a0000100000afffe02f0100cf 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [30, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, , 1, , 1, 260, 6, b'\x18N\n\x00\x00\x10\x00', 0, 175, 255, 224, 47, 1, 0, -49] 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy.zcl] [0x4a59:1:0x0006] ZCL deserialize: <ZCLHeader frame_control= manufacturer=None tsn=78 command_id=Command.Report_Attributes> 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy.zcl] [0x4a59:1:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=)]] 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy.zcl] [0x4a59:1:0x0006] Attribute report received: on_off=0 2021-01-20 11:46:55 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from , ep: 1, profile: 0x0104, cluster_id: 0x0006, data: b'184e0a00001000'

MattWestb commented 3 years ago

Something looks strange with "Shelf Light". Can you please post the "zigbee device signature" from the device card ?

Adminiuga commented 3 years ago

the commands were sent successfuly:

2021-01-20 11:43:11 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 67: 00
2021-01-20 11:43:11 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0x43 'aps_data_confirm' for , status: 0x00
2021-01-20 11:43:16 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xB0EF:1:0x0006]: command failed: 'off' args: '()' kwargs '{}' exception: ''

But you are not getting a response from the device, that's why it thinks the command has failed. Don't know why you are not getting a response. For Ikea, it could be ikea bug when it becomes a black hole and only answers to group commands. Physically power cycle that ikea plug

ashar38 commented 3 years ago

Something looks strange with "Shelf Light". Can you please post the "zigbee device signature" from the device card ?

That is in a different room with a couple of walls in between. So understandably, link is not that great.

MattWestb commented 3 years ago

@Adminiuga The Quirk looks strange on the network map.

@Indybeak First repower it and if its not helping try moving it "temporary" ner the coordinate and / or the other routers and see if you can sending commands to it.

ashar38 commented 3 years ago

the commands were sent successfuly:
2021-01-20 11:43:11 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 67: 00
2021-01-20 11:43:11 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0x43 'aps_data_confirm' for , status: 0x00
2021-01-20 11:43:16 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xB0EF:1:0x0006]: command failed: 'off' args: '()' kwargs '{}' exception: ''
But you are not getting a response from the device, that's why it thinks the command has failed. Don't know why you are not getting a response. For Ikea, it could be ikea bug when it becomes a black hole and only answers to group commands. Physically power cycle that ikea plug

Tried that already a few times. Gave it another try, but this time kept it unplugged for a minute before putting it back in. It is back to life now. I also noticed a ZDOCmd.Device_annce log. So looks good, at least for now.

MattWestb commented 3 years ago

Then deleting in and waiting 2 minutes. Resetting it with pressing the button in the small reset hole for 10 seconds (can being tricky, Its toggling and start flashing the LED then being reseted). Then pairing it one more time. And then posting the "zigbee device signature".

The device signature souls looks like the other control outlet you is having.

ashar38 commented 3 years ago

For Ikea, it could be ikea bug when it becomes a black hole and only answers to group commands. Physically power cycle that ikea plug

@Adminiuga Looks like this is the case. Paired one more outlet and tried On/Off a few times. It stopped responding after 3 or 4 successful operations. Do you know if there a fix to this bug?

Stefano0042 commented 3 years ago

@Adminiuga hello Alexei, I performed another test, on a 2nd machine based on RPI/HA core installation rel. 2021.1.4 this time with TI CC2652RB as Zigbee coordinator and not Conbee II, ZHA integration is running flawless. So the issue belong in between 2020.12.2 and 2021.1.1 releases.. a bumped up ZHA dependency (zigpy-deconz library..?) Python version: 3.7.3 (both machines)

Adminiuga commented 3 years ago

Python support 3.7.3 was dropped afaik on 2021.1 releases

Adminiuga commented 3 years ago

Debug logs when it goes down and prior to it going down.

ybjlus commented 3 years ago

An update from my side, last 2 days everything was running great. Today somehow HA restarted suddenly and again this issue... Here is the full log: https://pastebin.com/89iMtyMc

Stefano0042 commented 3 years ago

@Adminiuga Home Assistant 2021.1.3 is still compatible with Python 3.7 and an upgrade is possible.

Adminiuga commented 3 years ago

Or they forgot to deprecate it.

ashar38 commented 3 years ago

Quick update from me as well. So now I have 3 type of devices .Couple of Sengled Bulbs .Couple of cheap Orvibo receptacles .Couple of Ikea outlets and one Ikea signal repeater

Behavior so far: All these devices paired with relative ease.

Sengled bulbs are so far responsive and react immediately to commands.

Ikea outlets pair, and react to commands a couple of times, and then go into a black hole as Alexei mentioned earlier. Tried to do an OTA update of the firmware as well, but it got stuck and died around 12%. Most likely these outlets stop responding to ZHA and firmware update fails.

Ikea Signal Repeater: There is no ON/Off functionality on this. So no way to tell if they are still alive or no. However, the firmware update got stuck at around 0.7%, so I imagine this is dead as well.

Orvibo receptacles: Continued to work fine over extended period. However, a HA restart killed them all as well. So looks like they do not persist across restarts.

I have few more Orvibo contact and motion sensors, but I am not going to pair them until I make some progress with stability.

@Adminiuga Sorry to trouble you again, but are you aware of any method to solve the issue with Ikea outlets. They are key components of my setup to be able to extend the mesh on different floors. I was hoping a firmware update will help it. But these outlets do not even stay awake for that. At this point I am hesitant to spend on the Ikea hub/gateway to do firmware updates as there is no guarantee that will solve the problem either.

MattWestb commented 3 years ago

@Indybeak Your Device model E11G13 is no router its one end device. For my its sounds like the IKEA controll outlet is broken that is possible. Your device with name "Scherff light" is having strange device name !!!

Try only adding the signal repeater and you can testing if its working by open the "manage cluster" from the device card. Read the cluster Attributes of the selected cluster sw_build_id (id: 0x4000) from the basic cluster. Then you is getting the version of the device firmware.

ashar38 commented 3 years ago

@Indybeak Your Device model E11G13 is no router its one end device.

Yes. This is correct.

For my its sounds like the IKEA controll outlet is broken that is possible.

Is there a way to get it to work, except for buying the Ikea gateway?

Your device with name "Scherff light" is having strange device name !!!

That is the Orvibo receptacle. The manufacturer/device name is in Chinese/Mandarin when it gets added to the network. You can then rename it to your choice.

Try only adding the signal repeater and you can testing if its working by open the "manage cluster" from the device card. Read the cluster Attributes of the selected cluster sw_build_id (id: 0x4000) from the basic cluster.

Ok, let me try this.

Then you is getting the version of the device firmware.

MattWestb commented 3 years ago

OK the chinese sounds ok :-)

If the IKEA control outlet is broken its real hardware that is broken and cant being prepared with firmware updates. The bug Adminiuga mented can being triggered but then you need having over 50 devices and power half on and of with the power switch = not likely.

If you is getting the signal repeater get working then letting it doing one OTA update if its like / need it. And then restarting HA and see if all is OK before adding all devices. Then adding one device and trying it before adding more ones so you dong getting all being one mess.

ashar38 commented 3 years ago

@MattWestb been 5 miutes, and read attribute did not return anything. So I assume it is already unresponsive.

MattWestb commented 3 years ago

Then you must looking in the logs and if nothing there setting up it to debug and restarting HA so its start using the new debug setting.

(Sounds like your system have stop talking with the zigbee network)

ashar38 commented 3 years ago

If the IKEA control outlet is broken its real hardware that is broken and cant being prepared with firmware updates. The bug Adminiuga mented can being triggered but then you need having over 50 devices and power half on and of with the power switch = not likely.

That is unlikely. I am able to reset and pair the Ikea outlet again, and then it also responds to On/Off command a few times. So unlikely that the hardware is kaput.

MattWestb commented 3 years ago

So then its the coordinator that is stopping to talking to the zigbee network.

LOOOOOOGS :-))

ashar38 commented 3 years ago

So then its the coordinator that is stopping to talking to the zigbee network.

LOOOOOOGS :-))

I have shared the logs a few times already. Not sure how sharing it again will help. Please refer to this post for the logs. https://github.com/home-assistant/core/issues/45144#issuecomment-763784230

@Adminiuga has already taken a look and confirmed that Coordinator is sending the commands correctly, but the plugs are not responding back. And from his last comment, I got a feeling that there is a bug with Ikea outlets around only responding to group commands.

I am hopefully seeking a possible solution/workaround for that.

home-assistant / core