Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Lots of log messages and devices become unavailable after several hours #55

Closed
bckthomas opened this issue Sep 29, 2020 · 23 comments
Closed

Comments

@bckthomas
Copy link

bckthomas commented Sep 29, 2020

Hi
I have profalux covers and a zigate to connect them to homeassistant.
Since the last version, I have a lots of message in logs and my devices become unavailable after 5-6 hours.
I have to open the zigbee network and click on the "device reconfiguration" for all covers to work again. But after 5-6 hours, they all became unavailable again.

Let me know if I can help you with more logs, tests...
Thanks

Related issues :
home-assistant/core#40707
home-assistant/core#40729

Here are the logs when the devices become unavailable : (below, all the logs messages)

2020-09-29 01:01:35 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xFBB2](unk_model): Attempting to checkin with device - missed checkins: 1
2020-09-29 01:01:35 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0xFBB2, 260, 0, 1, 1, 35, b'\x00#\x00\x04\x00', True, False)
2020-09-29 01:01:35 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:01:35 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:01:35 DEBUG (MainThread) [zigpy.device] [0xfbb2] Delivery error for seq # 0x23, on endpoint id 1 cluster 0x0000: Message send failure 166
2020-09-29 01:01:35 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x75A3](unk_model): Attempting to checkin with device - missed checkins: 1
2020-09-29 01:01:35 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0x75A3, 260, 0, 1, 1, 37, b'\x00%\x00\x04\x00', True, False)
2020-09-29 01:01:35 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:01:35 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:01:35 DEBUG (MainThread) [zigpy.device] [0x75a3] Delivery error for seq # 0x25, on endpoint id 1 cluster 0x0000: Message send failure 166
2020-09-29 01:01:43 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xBAC9](unk_model): Attempting to checkin with device - missed checkins: 1
2020-09-29 01:01:43 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0xBAC9, 260, 0, 1, 1, 39, b"\x00'\x00\x04\x00", True, False)
2020-09-29 01:01:43 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:01:43 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:01:43 DEBUG (MainThread) [zigpy.device] [0xbac9] Delivery error for seq # 0x27, on endpoint id 1 cluster 0x0000: Message send failure 166
2020-09-29 01:02:05 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xD490](unk_model): Attempting to checkin with device - missed checkins: 1
2020-09-29 01:02:05 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0xD490, 260, 0, 1, 1, 41, b'\x00)\x00\x04\x00', True, False)
2020-09-29 01:02:05 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:02:05 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:02:05 DEBUG (MainThread) [zigpy.device] [0xd490] Delivery error for seq # 0x29, on endpoint id 1 cluster 0x0000: Message send failure 166
2020-09-29 01:02:15 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x1EE6](unk_model): Attempting to checkin with device - missed checkins: 1
2020-09-29 01:02:15 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0x1EE6, 260, 0, 1, 1, 43, b'\x00+\x00\x04\x00', True, False)
2020-09-29 01:02:15 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:02:15 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:02:15 DEBUG (MainThread) [zigpy.device] [0x1ee6] Delivery error for seq # 0x2b, on endpoint id 1 cluster 0x0000: Message send failure 166
2020-09-29 01:02:24 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xF341](unk_model): Attempting to checkin with device - missed checkins: 1
2020-09-29 01:02:24 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0xF341, 260, 0, 1, 1, 45, b'\x00-\x00\x04\x00', True, False)
2020-09-29 01:02:24 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:02:24 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:02:24 DEBUG (MainThread) [zigpy.device] [0xf341] Delivery error for seq # 0x2d, on endpoint id 1 cluster 0x0000: Message send failure 166
2020-09-29 01:02:39 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x75A3](unk_model): Attempting to checkin with device - missed checkins: 2
2020-09-29 01:02:39 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0x75A3, 260, 0, 1, 1, 47, b'\x00/\x00\x04\x00', True, False)
2020-09-29 01:02:39 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:02:39 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:02:39 DEBUG (MainThread) [zigpy.device] [0x75a3] Delivery error for seq # 0x2f, on endpoint id 1 cluster 0x0000: Message send failure 166
2020-09-29 01:02:43 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xBAC9](unk_model): Attempting to checkin with device - missed checkins: 2
2020-09-29 01:02:43 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0xBAC9, 260, 0, 1, 1, 49, b'\x001\x00\x04\x00', True, False)
2020-09-29 01:02:43 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:02:43 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:02:43 DEBUG (MainThread) [zigpy.device] [0xbac9] Delivery error for seq # 0x31, on endpoint id 1 cluster 0x0000: Message send failure 166
2020-09-29 01:02:54 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xFBB2](unk_model): Attempting to checkin with device - missed checkins: 2
2020-09-29 01:02:54 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0xFBB2, 260, 0, 1, 1, 51, b'\x003\x00\x04\x00', True, False)
2020-09-29 01:02:54 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:02:54 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:02:54 DEBUG (MainThread) [zigpy.device] [0xfbb2] Delivery error for seq # 0x33, on endpoint id 1 cluster 0x0000: Message send failure 166
2020-09-29 01:03:34 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xD490](unk_model): Attempting to checkin with device - missed checkins: 2
2020-09-29 01:03:34 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0xD490, 260, 0, 1, 1, 53, b'\x005\x00\x04\x00', True, False)
2020-09-29 01:03:34 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:03:34 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:03:34 DEBUG (MainThread) [zigpy.device] [0xd490] Delivery error for seq # 0x35, on endpoint id 1 cluster 0x0000: Message send failure 166
2020-09-29 01:03:41 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x1EE6](unk_model): Attempting to checkin with device - missed checkins: 2
2020-09-29 01:03:41 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0x1EE6, 260, 0, 1, 1, 55, b'\x007\x00\x04\x00', True, False)
2020-09-29 01:03:41 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:03:41 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:03:41 DEBUG (MainThread) [zigpy.device] [0x1ee6] Delivery error for seq # 0x37, on endpoint id 1 cluster 0x0000: Message send failure 166
2020-09-29 01:03:47 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xF341](unk_model): Attempting to checkin with device - missed checkins: 2
2020-09-29 01:03:47 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0xF341, 260, 0, 1, 1, 57, b'\x009\x00\x04\x00', True, False)
2020-09-29 01:03:47 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:03:47 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:03:47 DEBUG (MainThread) [zigpy.device] [0xf341] Delivery error for seq # 0x39, on endpoint id 1 cluster 0x0000: Message send failure 166
2020-09-29 01:04:51 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xCE11](unk_model): Attempting to checkin with device - missed checkins: 1
2020-09-29 01:04:51 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0xCE11, 260, 0, 1, 1, 59, b'\x00;\x00\x04\x00', True, False)
2020-09-29 01:04:51 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:04:51 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:04:51 DEBUG (MainThread) [zigpy.device] [0xce11] Delivery error for seq # 0x3b, on endpoint id 1 cluster 0x0000: Message send failure 166
2020-09-29 01:06:13 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xCE11](unk_model): Attempting to checkin with device - missed checkins: 2
2020-09-29 01:06:13 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0xCE11, 260, 0, 1, 1, 61, b'\x00=\x00\x04\x00', True, False)
2020-09-29 01:06:13 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:06:13 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:06:13 DEBUG (MainThread) [zigpy.device] [0xce11] Delivery error for seq # 0x3d, on endpoint id 1 cluster 0x0000: Message send failure 166
2020-09-29 01:12:58 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xF7EF](unk_model): Attempting to checkin with device - missed checkins: 1
2020-09-29 01:12:58 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0xF7EF, 260, 0, 1, 1, 63, b'\x00?\x00\x04\x00', True, False)
2020-09-29 01:12:58 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:12:58 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:12:58 DEBUG (MainThread) [zigpy.device] [0xf7ef] Delivery error for seq # 0x3f, on endpoint id 1 cluster 0x0000: Message send failure 166
2020-09-29 01:13:37 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x3F0D](unk_model): Attempting to checkin with device - missed checkins: 1
2020-09-29 01:13:37 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0x3F0D, 260, 0, 1, 1, 65, b'\x00A\x00\x04\x00', True, False)
2020-09-29 01:13:37 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:13:37 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:13:37 DEBUG (MainThread) [zigpy.device] [0x3f0d] Delivery error for seq # 0x41, on endpoint id 1 cluster 0x0000: Message send failure 166
2020-09-29 01:13:43 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x06EA](unk_model): Attempting to checkin with device - missed checkins: 1
2020-09-29 01:13:43 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0x06EA, 260, 0, 1, 1, 67, b'\x00C\x00\x04\x00', True, False)
2020-09-29 01:13:43 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:13:43 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:13:43 DEBUG (MainThread) [zigpy.device] [0x06ea] Delivery error for seq # 0x43, on endpoint id 1 cluster 0x0000: Message send failure 166
2020-09-29 01:14:03 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xF7EF](unk_model): Attempting to checkin with device - missed checkins: 2
2020-09-29 01:14:03 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0xF7EF, 260, 0, 1, 1, 69, b'\x00E\x00\x04\x00', True, False)
2020-09-29 01:14:03 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:14:03 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:14:03 DEBUG (MainThread) [zigpy.device] [0xf7ef] Delivery error for seq # 0x45, on endpoint id 1 cluster 0x0000: Message send failure 166
2020-09-29 01:14:43 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x06EA](unk_model): Attempting to checkin with device - missed checkins: 2
2020-09-29 01:14:43 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0x06EA, 260, 0, 1, 1, 71, b'\x00G\x00\x04\x00', True, False)
2020-09-29 01:14:43 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:14:43 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:14:43 DEBUG (MainThread) [zigpy.device] [0x06ea] Delivery error for seq # 0x47, on endpoint id 1 cluster 0x0000: Message send failure 166
2020-09-29 01:14:55 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x3F0D](unk_model): Attempting to checkin with device - missed checkins: 2
2020-09-29 01:14:55 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0x3F0D, 260, 0, 1, 1, 73, b'\x00I\x00\x04\x00', True, False)
2020-09-29 01:14:55 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-09-29 01:14:55 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-09-29 01:14:55 DEBUG (MainThread) [zigpy.device] [0x3f0d] Delivery error for seq # 0x49, on endpoint id 1 cluster 0x0000: Message send failure 166`

Logs : 
`2020-09-28 15:14:42 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0x06EA, 260, 8, 1, 1, 5, b'\x01\x05\x04\xff\x01\x00', True, False)
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'005c0530' LQI:0
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [0, 92, 1328, b'']
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8002 b'000104000601010206ea02000018430a00001001' LQI:60
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [0, 260, 6, 1, 1, <Address address_mode=ADDRESS_MODE.NWK address=0x06ea>, <Address address_mode=ADDRESS_MODE.NWK address=0x0000>, b'\x18C\n\x00\x00\x10\x01']
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy.zcl] [0x06ea:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=67 command_id=Command.Report_Attributes>
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy.zcl] [0x06ea:1:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=Bool, value=Bool.true>)]]
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy.zcl] [0x06ea:1:0x0006] Attribute report received: on_off=1
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8002 b'000104000601010206ea02000018430a00001001' LQI:60
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [0, 260, 6, 1, 1, <Address address_mode=ADDRESS_MODE.NWK address=0x06ea>, <Address address_mode=ADDRESS_MODE.NWK address=0x0000>, b'\x18C\n\x00\x00\x10\x01']
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy.zcl] [0x06ea:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=67 command_id=Command.Report_Attributes>
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy.zcl] [0x06ea:1:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=Bool, value=Bool.true>)]]
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy.zcl] [0x06ea:1:0x0006] Attribute report received: on_off=1
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8002 b'000104000801010206ea02000018440a000020bc' LQI:57
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [0, 260, 8, 1, 1, <Address address_mode=ADDRESS_MODE.NWK address=0x06ea>, <Address address_mode=ADDRESS_MODE.NWK address=0x0000>, b'\x18D\n\x00\x00 \xbc']
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy.zcl] [0x06ea:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=68 command_id=Command.Report_Attributes>
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy.zcl] [0x06ea:1:0x0008] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint8_t, value=188>)]]
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy.zcl] [0x06ea:1:0x0008] Attribute report received: current_level=188
2020-09-28 15:14:42 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x06EA:1:0x0008]: received attribute: 0 update with value: 188
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8002 b'000104000801010206ea02000018440a000020bc' LQI:57
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [0, 260, 8, 1, 1, <Address address_mode=ADDRESS_MODE.NWK address=0x06ea>, <Address address_mode=ADDRESS_MODE.NWK address=0x0000>, b'\x18D\n\x00\x00 \xbc']
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy.zcl] [0x06ea:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=68 command_id=Command.Report_Attributes>
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy.zcl] [0x06ea:1:0x0008] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint8_t, value=188>)]]
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy.zcl] [0x06ea:1:0x0008] Attribute report received: current_level=188
2020-09-28 15:14:42 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x06EA:1:0x0008]: received attribute: 0 update with value: 188
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8002 b'000104000801010206ea02000008050b0400' LQI:60
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [0, 260, 8, 1, 1, <Address address_mode=ADDRESS_MODE.NWK address=0x06ea>, <Address address_mode=ADDRESS_MODE.NWK address=0x0000>, b'\x08\x05\x0b\x04\x00']
2020-09-28 15:14:42 DEBUG (MainThread) [zigpy.zcl] [0x06ea:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=5 command_id=Command.Default_Response>
2020-09-28 15:14:42 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x06EA:1:0x0008]: executed 'move_to_level_with_on_off' command with args: '(255.0, 1)' kwargs: '{}' result: [4, <Status.SUCCESS: 0>]
2020-09-28 15:14:47 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8002 b'000104000801010206ea02000018450a000020fe' LQI:60
2020-09-28 15:14:47 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [0, 260, 8, 1, 1, <Address address_mode=ADDRESS_MODE.NWK address=0x06ea>, <Address address_mode=ADDRESS_MODE.NWK address=0x0000>, b'\x18E\n\x00\x00 \xfe']
2020-09-28 15:14:47 DEBUG (MainThread) [zigpy.zcl] [0x06ea:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=69 command_id=Command.Report_Attributes>
2020-09-28 15:14:47 DEBUG (MainThread) [zigpy.zcl] [0x06ea:1:0x0008] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint8_t, value=254>)]]
2020-09-28 15:14:47 DEBUG (MainThread) [zigpy.zcl] [0x06ea:1:0x0008] Attribute report received: current_level=254
2020-09-28 15:14:47 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x06EA:1:0x0008]: received attribute: 0 update with value: 254
2020-09-28 15:14:47 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8002 b'000104000801010206ea02000018450a000020fe' LQI:60
2020-09-28 15:14:47 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [0, 260, 8, 1, 1, <Address address_mode=ADDRESS_MODE.NWK address=0x06ea>, <Address address_mode=ADDRESS_MODE.NWK address=0x0000>, b'\x18E\n\x00\x00 \xfe']
2020-09-28 15:14:47 DEBUG (MainThread) [zigpy.zcl] [0x06ea:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=69 command_id=Command.Report_Attributes>
2020-09-28 15:14:47 DEBUG (MainThread) [zigpy.zcl] [0x06ea:1:0x0008] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint8_t, value=254>)]]
2020-09-28 15:14:47 DEBUG (MainThread) [zigpy.zcl] [0x06ea:1:0x0008] Attribute report received: current_level=254
2020-09-28 15:14:47 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x06EA:1:0x0008]: received attribute: 0 update with value: 254
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8002 b'0001040008010102d49002000018410a00002001' LQI:87
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [0, 260, 8, 1, 1, <Address address_mode=ADDRESS_MODE.NWK address=0xd490>, <Address address_mode=ADDRESS_MODE.NWK address=0x0000>, b'\x18A\n\x00\x00 \x01']
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy.zcl] [0xd490:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=65 command_id=Command.Report_Attributes>
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy.zcl] [0xd490:1:0x0008] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint8_t, value=1>)]]
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy.zcl] [0xd490:1:0x0008] Attribute report received: current_level=1
2020-09-28 15:14:55 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xD490:1:0x0008]: received attribute: 0 update with value: 1
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8002 b'0001040008010102d49002000018410a00002001' LQI:87
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [0, 260, 8, 1, 1, <Address address_mode=ADDRESS_MODE.NWK address=0xd490>, <Address address_mode=ADDRESS_MODE.NWK address=0x0000>, b'\x18A\n\x00\x00 \x01']
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy.zcl] [0xd490:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=65 command_id=Command.Report_Attributes>
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy.zcl] [0xd490:1:0x0008] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint8_t, value=1>)]]
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy.zcl] [0xd490:1:0x0008] Attribute report received: current_level=1
2020-09-28 15:14:55 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xD490:1:0x0008]: received attribute: 0 update with value: 1
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8002 b'0001040006010102d49002000018420a00001000' LQI:90
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [0, 260, 6, 1, 1, <Address address_mode=ADDRESS_MODE.NWK address=0xd490>, <Address address_mode=ADDRESS_MODE.NWK address=0x0000>, b'\x18B\n\x00\x00\x10\x00']
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy.zcl] [0xd490:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=66 command_id=Command.Report_Attributes>
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy.zcl] [0xd490:1:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=Bool, value=Bool.false>)]]
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy.zcl] [0xd490:1:0x0006] Attribute report received: on_off=0
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8002 b'0001040006010102d49002000018420a00001000' LQI:90
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [0, 260, 6, 1, 1, <Address address_mode=ADDRESS_MODE.NWK address=0xd490>, <Address address_mode=ADDRESS_MODE.NWK address=0x0000>, b'\x18B\n\x00\x00\x10\x00']
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy.zcl] [0xd490:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=66 command_id=Command.Report_Attributes>
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy.zcl] [0xd490:1:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=Bool, value=Bool.false>)]]
2020-09-28 15:14:55 DEBUG (MainThread) [zigpy.zcl] [0xd490:1:0x0006] Attribute report received: on_off=0
2020-09-28 15:15:08 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f104' LQI:0
2020-09-28 15:15:08 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:15:08 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f103' LQI:0
2020-09-28 15:15:08 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:15:10 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f102' LQI:0
2020-09-28 15:15:10 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:15:10 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f104' LQI:0
2020-09-28 15:15:10 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:15:10 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f101' LQI:0
2020-09-28 15:15:10 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:15:10 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f103' LQI:0
2020-09-28 15:15:10 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:15:10 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f103' LQI:0
2020-09-28 15:15:10 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:15:10 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f102' LQI:0
2020-09-28 15:15:10 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:15:10 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f104' LQI:0
2020-09-28 15:15:10 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:15:10 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f103' LQI:0
2020-09-28 15:15:10 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:15:55 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f102' LQI:0
2020-09-28 15:15:55 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:15:55 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f104' LQI:0
2020-09-28 15:15:55 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:15:55 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f101' LQI:0
2020-09-28 15:15:55 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:15:55 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f103' LQI:0
2020-09-28 15:15:55 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:15:55 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f103' LQI:0
2020-09-28 15:15:55 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:15:55 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f102' LQI:0
2020-09-28 15:15:55 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:15:55 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f104' LQI:0
2020-09-28 15:15:55 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:15:55 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f103' LQI:0
2020-09-28 15:15:55 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:18:42 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f104' LQI:0
2020-09-28 15:18:42 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:18:42 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f103' LQI:0
2020-09-28 15:18:42 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:18:55 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f102' LQI:0
2020-09-28 15:18:55 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:18:56 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f104' LQI:0
2020-09-28 15:18:56 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:18:56 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f101' LQI:0
2020-09-28 15:18:56 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:18:56 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f103' LQI:0
2020-09-28 15:18:56 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:18:56 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f103' LQI:0
2020-09-28 15:18:56 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:18:56 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f102' LQI:0
2020-09-28 15:18:56 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:18:56 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f104' LQI:0
2020-09-28 15:18:56 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:18:56 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f103' LQI:0
2020-09-28 15:18:56 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:19:37 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f104' LQI:0
2020-09-28 15:19:37 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:19:37 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f103' LQI:0
2020-09-28 15:19:37 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:21:11 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f102' LQI:0
2020-09-28 15:21:11 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:21:11 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f104' LQI:0
2020-09-28 15:21:11 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:21:11 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f101' LQI:0
2020-09-28 15:21:11 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:21:11 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f103' LQI:0
2020-09-28 15:21:11 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:21:11 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f103' LQI:0
2020-09-28 15:21:11 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:21:11 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f102' LQI:0
2020-09-28 15:21:11 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:21:11 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f104' LQI:0
2020-09-28 15:21:11 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:21:11 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f103' LQI:0
2020-09-28 15:21:11 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:22:39 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f104' LQI:0
2020-09-28 15:22:39 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:22:39 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f103' LQI:0
2020-09-28 15:22:39 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:23:41 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f102' LQI:0
2020-09-28 15:23:41 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:23:41 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f104' LQI:0
2020-09-28 15:23:41 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:23:41 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f101' LQI:0
2020-09-28 15:23:41 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:23:41 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f103' LQI:0
2020-09-28 15:23:41 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:23:41 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f103' LQI:0
2020-09-28 15:23:41 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:23:41 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f102' LQI:0
2020-09-28 15:23:41 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:23:41 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f104' LQI:0
2020-09-28 15:23:41 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
2020-09-28 15:23:41 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8035 b'030000f103' LQI:0
2020-09-28 15:23:41 ERROR (MainThread) [zigpy_zigate.api] Received unhandled response 0x8035
@doudz
Copy link
Collaborator

doudz commented Sep 29, 2020

The message 8035 probably means the pdm of the Zigate is corrupted.
Maybe you will have to erase your Zigate and restart from scratch

@doudz
Copy link
Collaborator

doudz commented Sep 29, 2020

@Maxouwell
Copy link

@doudz Does my problem on home-assistant/core#40729 is the same that this bug ?

@doudz
Copy link
Collaborator

doudz commented Oct 1, 2020

no I don't think it's related

@Adminiuga
Copy link
Contributor

when it stop working, it is always the same message to every request sent to zigate. Trying to turn on two different lights, which were working previously.

2020-10-02 19:25:28 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.ikea_of_sweden_tradfri_bulb_e26_ws_clear_806lm_f14a95fe_level_light_color_on_off>
2020-10-02 19:25:28 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0x59A3, 260, 6, 1, 1, 3, b'\x01\x03\x01', True, False)
2020-10-02 19:25:28 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x530 b'0259a3010100060104000003010301'
2020-10-02 19:25:28 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x0f\xc1\x02Y\xa3\x01\x01\x00\x06\x01\x04\x00\x00\x03\x01\x03\x01'
2020-10-02 19:25:28 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x02\x1f\xc1\x02\x12Y\xa3\x02\x11\x02\x11\x02\x10\x02\x16\x02\x11\x02\x14\x02\x10\x02\x10\x02\x13\x02\x11\x02\x13\x02\x11'
2020-10-02 19:25:28 DEBUG (MainThread) [zigpy_zigate.uart] Frame received: 8000000516a600053000
2020-10-02 19:25:28 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-10-02 19:25:28 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-10-02 19:25:28 DEBUG (MainThread) [zigpy.device] [0x59a3] Delivery error for seq # 0x03, on endpoint id 1 cluster 0x0006: Message send failure 166
2020-10-02 19:25:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x59A3:1:0x0006]: command failed: on exception: [0x59a3:1:0x0006]: Message send failure
2020-10-02 19:25:28 DEBUG (MainThread) [homeassistant.components.zha.entity] light.ikea_of_sweden_tradfri_bulb_e26_ws_clear_806lm_f14a95fe_level_light_color_on_off: turned on: {'on_off': DeliveryError('[0x59a3:1:0x0006]: Message send failure')}
2020-10-02 19:25:30 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.con_zbt_cctlight_gls0109_ff5093fe_level_light_color_on_off>
2020-10-02 19:25:30 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0x91B7, 260, 6, 1, 1, 5, b'\x01\x05\x01', True, False)
2020-10-02 19:25:30 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x530 b'0291b7010100060104000003010501'
2020-10-02 19:25:30 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x0f\x1b\x02\x91\xb7\x01\x01\x00\x06\x01\x04\x00\x00\x03\x01\x05\x01'
2020-10-02 19:25:30 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x02\x1f\x1b\x02\x12\x91\xb7\x02\x11\x02\x11\x02\x10\x02\x16\x02\x11\x02\x14\x02\x10\x02\x10\x02\x13\x02\x11\x02\x15\x02\x11'
2020-10-02 19:25:30 DEBUG (MainThread) [zigpy_zigate.uart] Frame received: 8000000516a600053000
2020-10-02 19:25:30 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-10-02 19:25:30 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-10-02 19:25:30 DEBUG (MainThread) [zigpy.device] [0x91b7] Delivery error for seq # 0x05, on endpoint id 1 cluster 0x0006: Message send failure 166
2020-10-02 19:25:30 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x91B7:1:0x0006]: command failed: on exception: [0x91b7:1:0x0006]: Message send failure

@Adminiuga
Copy link
Contributor

per log it did stop working after scanning neighbours on the coordinator. I have only two routers on the network and 1st scan was successful, but the 2nd one failed and after that all outbound requests are failing with [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0. I also stop receiving any traffic from the zigate.

Here's the log of the failure. Scans are done every 20min, HA was started at 17:16:xx

2020-10-02 17:58:30 DEBUG (MainThread) [zigpy.neighbor] [0x0000] request status: Status.SUCCESS. response: Neighbors(entries=
4, start_index=0, neighbor_table_list=[Neighbor(extended_pan_id=6b:8d:38:ae:84:a4:2b:8e, ieee=00:15:8d:00:02:4e:61:a2, nwk=0x
612C, packed=18, permit_joining=<PermitJoins.Unknown: 2>, depth=1, lqi=234), Neighbor(extended_pan_id=6b:8d:38:ae:84:a4:2b:8e
, ieee=ec:1b:bd:ff:fe:3f:6c:97, nwk=0x0FD8, packed=18, permit_joining=<PermitJoins.Unknown: 2>, depth=1, lqi=238)])
2020-10-02 17:58:32 DEBUG (MainThread) [zigpy.neighbor] [0x0000] Querying next starting at 2
2020-10-02 17:58:32 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2020-10-02 17:58:32 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0x0000, 0, <ZDOCmd.Mgmt_Lqi_req: 0x0031>, 0
, 0, 89, b'Y\x02', True, False)
2020-10-02 17:58:32 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x530 b'0200000000003100000000025902'
2020-10-02 17:58:32 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x0eQ\x02\x00\x00\x00\x00\x001\x00\x00\x
00\x00\x02Y\x02'
2020-10-02 17:58:32 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x02\x1eQ\x02\x12\x02\x10\x02\x1
0\x02\x10\x02\x10\x02\x101\x02\x10\x02\x10\x02\x10\x02\x10\x02\x12Y\x02\x12'
2020-10-02 17:58:32 DEBUG (MainThread) [zigpy_zigate.uart] Frame received: 8000000516a600053000
2020-10-02 17:58:32 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-10-02 17:58:32 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 1328, b'']
2020-10-02 17:58:32 DEBUG (MainThread) [zigpy.device] [0x0000] Delivery error for seq # 0x59, on endpoint id 0 cluster 0x0031
: Message send failure 166
2020-10-02 17:58:33 DEBUG (MainThread) [zigpy.util] Tries remaining: 2
2020-10-02 17:58:33 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0x0000, 0, <ZDOCmd.Mgmt_Lqi_req: 0x0031>, 0
, 0, 91, b'[\x02', True, False)
2020-10-02 17:58:33 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x530 b'0200000000003100000000025b02'
2020-10-02 17:58:33 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x0eS\x02\x00\x00\x00\x00\x001\x00\x00\x
00\x00\x02[\x02'
2020-10-02 17:58:33 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x02\x1eS\x02\x12\x02\x10\x02\x1
0\x02\x10\x02\x10\x02\x101\x02\x10\x02\x10\x02\x10\x02\x10\x02\x12[\x02\x12'
2020-10-02 17:58:33 DEBUG (MainThread) [zigpy_zigate.uart] Frame received: 8000000516a600053000
2020-10-02 17:58:33 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0

Going to disable scanning of the coordinator.

@Adminiuga
Copy link
Contributor

Adminiuga commented Oct 3, 2020

seems like scanning any device on the network causes problem. Still not clear if the problem is with the zigate itself or the library.
This time was not scanning coordinator at all, but only devices on the network and it still locked up. It did two successful scans of all devices (2x routers) and after that locked out

2020-10-02 21:30:41 DEBUG (MainThread) [zigpy.neighbor] [0x91b7] request status: Status.SUCCESS. response:
 Neighbors(entries=2, start_index=0, neighbor_table_list=[Neighbor(extended_pan_id=6b:8d:38:ae:84:a4:2b:8e
, ieee=00:15:8d:00:03:af:5e:85, nwk=0x0000, packed=4, permit_joining=<PermitJoins.Unknown: 2>, depth=0, lq
i=229), Neighbor(extended_pan_id=6b:8d:38:ae:84:a4:2b:8e, ieee=14:b4:57:ff:fe:95:4a:f1, nwk=0x59A3, packed
=37, permit_joining=<PermitJoins.Unknown: 2>, depth=15, lqi=226)])
2020-10-02 21:30:41 DEBUG (MainThread) [zigpy.neighbor] [0x91b7] Done scanning. Total 2 neighbours
2020-10-02 21:30:44 DEBUG (MainThread) [zigpy.topology] Scanning neighbors of 14:b4:57:ff:fe:95:4a:f1/0x59
a3 device
2020-10-02 21:30:44 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2020-10-02 21:30:44 DEBUG (MainThread) [zigpy_zigate.zigbee.application] request (0x59A3, 0, <ZDOCmd.Mgmt_
Lqi_req: 0x0031>, 0, 0, 65, b'A\x00', True, False)
2020-10-02 21:30:44 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x530 b'0259a30000003100000000024100'
2020-10-02 21:30:44 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x050\x00\x0e\xb1\x02Y\xa3\x00
\x00\x001\x00\x00\x00\x00\x02A\x00'
2020-10-02 21:30:44 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x150\x02\x10\x02\x1e\xb1\
x02\x12Y\xa3\x02\x10\x02\x10\x02\x101\x02\x10\x02\x10\x02\x10\x02\x10\x02\x12A\x02\x10'
2020-10-02 21:30:44 DEBUG (MainThread) [zigpy_zigate.uart] Frame received: 8000000516a600053000
2020-10-02 21:30:44 DEBUG (MainThread) [zigpy_zigate.api] data received 0x8000 b'a6000530' LQI:0
2020-10-02 21:30:44 DEBUG (MainThread) [zigpy_zigate.zigbee.application] zigate_callback_handler [166, 0, 
1328, b'']
2020-10-02 21:30:44 DEBUG (MainThread) [zigpy.device] [0x59a3] Delivery error for seq # 0x41, on endpoint 
id 0 cluster 0x0031: Message send failure 166

@Adminiuga
Copy link
Contributor

@doudz I can confirm, sending ZDO Mgmt_Lqi_req request to routers on a regular basis is enough to trigger this issue. I suspect something is happening with zigate, as I stop receiving any trafic from zigate. Initially I thought that scanning the Zigate was the problem, but turns out it locks up even if I only scan devices on the network.
With ZDO Mgmt_Lqi_req scanning disabled, zigate works fine, for at least 6 hours. With scans, it locks up under 1 hour, max 2 -3 successful scans every 20 min.

@bckthomas what zigate version are you running?
as a work around, disable topology scanner completely. see home-assistant/core#40729 (comment)

@doudz
Copy link
Collaborator

doudz commented Oct 5, 2020

Could you try something when you get error 166 : Put ZiGate in permit join mode by clicking on "+" button just like you want to pair a new device and see if it's working again ?

@Adminiuga
Copy link
Contributor

it actually does get it working again.
Had scanning disabled, it worked without issues for 2 days.
Enabled scanning -> couldn't control lights after approx 1 hour
ran through joining a device, without actually joining anything and could control lights again

@pipiche38
Copy link

pipiche38 commented Oct 6, 2020 via email

@doudz
Copy link
Collaborator

doudz commented Oct 6, 2020

Thank you, we're investigating, it could be an internal ZiGate firmware bug

@pipiche38
Copy link

@doudz, @Adminiuga I would be interested, as we are using the the LQI Management Request ( 0x004e) in our plugin and do not saw any issues. That is why I'm interested to understand what the Zigpy lib could be doing different to fall into a firmware issue !

@doudz
Copy link
Collaborator

doudz commented Oct 6, 2020

The difference is that zigpy doesn't use the ZiGate command 0x004E, all is done using the command 0x0530.
Using the command 0x0530 we call the zigbee request 0x0031 which is LQI Management Request

@doudz
Copy link
Collaborator

doudz commented Oct 6, 2020

Really not sure but maybe we could try to force source endpoint to 1

https://github.com/zigpy/zigpy-zigate/blob/dev/zigpy_zigate/zigbee/application.py#L135
Try to replace
src_ep = 1 if dst_ep else 0
by
src_ep = 1

@Adminiuga
Copy link
Contributor

I could give it a try, but Mgmt_lqi_req is a ZDO command and AFAIK all zdo commands are using endpoint id 0 for both src and destination ep id.

@fairecasoimeme
Copy link

yep, endpoint must be 0 for ZDO command in Zigbee.

@fairecasoimeme
Copy link

I manage to reproduce the problem. It seems to be linked to the raw mode
I'll try to find with debug firmware where it's not ok.

@fairecasoimeme
Copy link

fairecasoimeme commented Oct 7, 2020

Hi,
I solved the problem. There was a memory leak in RAW mode. I sent to you the new firmware which fix the issue.
Tell me if it's ok for you.
Fred

@Adminiuga
Copy link
Contributor

Just updated the PiZigate. It's on HassOS so had to jump through some hoops.
Well keep you posted.
Thank you for the quick fix!

@Adminiuga
Copy link
Contributor

so far so good. about 1hr 45min uptime. Before it would go down in about 50min -1 hour

@Adminiuga
Copy link
Contributor

ok, it's been almost 24 hours and it is still running strong. Can control my two test light bulbs just fine.

Thanks again for a quick fix. Any ETA when it's going to be generally available?

@fairecasoimeme
Copy link

I think next monday

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

6 participants