Core: No zha_event in HA log

Created on 11 Feb 2020 · 20Comments · Source: home-assistant/core

The problem

I don't see any zha_event entries in my log even when debug is enabled (see logger info below). I have a Bitron Video ZigBee USB Funkstick device which is configured with ZHA integration. I have an IKEA bulb, the IKEA Fyrtur blinds and two IKEA 2btn remotes and none of these seem to generate events. The devices work fine otherwise and I can control the bulb/blind with the remotes via the group binding feature in the UI.

Environment

Home Assistant release with the issue: 0.105.3
Last working Home Assistant release (if known): Unknown
Operating environment (Hass.io/Docker/Windows/etc.): Hass.io in Docker on RPi4
Integration causing this issue: ZHA
Link to integration documentation on our website:

Problem-relevant `configuration.yaml`

logger:
  default: info
  logs:
    asyncio: debug
    homeassistant.core: debug
    homeassistant.components.zha: debug
    bellows: debug
    zigpy: debug

Traceback/Error logs

Additional information

This is the output from lsusb for the USB stick. Let me know if I should get som cluster attributes for the stick instead.

Bus 001 Device 003: ID 10c4:8b34 Cygnal Integrated Products, Inc. Device Descriptor: bLength 18 bDescriptorType 1 bcdUSB 2.00 bDeviceClass 0 bDeviceSubClass 0 bDeviceProtocol 0 bMaxPacketSize0 64 idVendor 0x10c4 Cygnal Integrated Products, Inc. idProduct 0x8b34 bcdDevice 1.00 iManufacturer 1 Silicon Labs iProduct 2 BV 2010/10 iSerial 3 01241E84 bNumConfigurations 1 Configuration Descriptor: bLength 9 bDescriptorType 2 wTotalLength 0x0020 bNumInterfaces 1 bConfigurationValue 1 iConfiguration 0 bmAttributes 0x80 (Bus Powered) MaxPower 100mA Interface Descriptor: bLength 9 bDescriptorType 4 bInterfaceNumber 0 bAlternateSetting 0 bNumEndpoints 2 bInterfaceClass 255 Vendor Specific Class bInterfaceSubClass 0 bInterfaceProtocol 0 iInterface 2 BV 2010/10 Endpoint Descriptor: bLength 7 bDescriptorType 5 bEndpointAddress 0x01 EP 1 OUT bmAttributes 2 Transfer Type Bulk Synch Type None Usage Type Data wMaxPacketSize 0x0040 1x 64 bytes bInterval 0 Endpoint Descriptor: bLength 7 bDescriptorType 5 bEndpointAddress 0x82 EP 2 IN bmAttributes 2 Transfer Type Bulk Synch Type None Usage Type Data wMaxPacketSize 0x0040 1x 64 bytes bInterval 0 can't get device qualifier: Resource temporarily unavailable can't get debug descriptor: Resource temporarily unavailable Device Status: 0x0000 (Bus Powered)

zha

Source

nicjo814

Most helpful comment

Go to developers tools panel -> Event, Enter zha_event and start listening to zha_event. Press button on the remote.
If nothing get shown on button press, remove and re-pair the device.
Ask in #zigbee discord channel
Enable debug logging and open an issue, provide details and post the logs.

Adminiuga on 6 May 2020

👀1 ❤1 👍1

All 20 comments

Just to clarify, I get other events in the log but no zha_event.

nicjo814 on 11 Feb 2020

Hey there @dmulcahey, @adminiuga, mind taking a look at this issue as its been labeled with a integration (zha) you are listed as a codeowner for? Thanks!

probot-home-assistant[bot] on 11 Feb 2020

Bulbs and Blinds do not generate zha_event's only "remote" device types like button generate zha_events on occasion.

Are the buttons paired?
Do you see ZHA button devices in ZHA device list? (screenshots?)
debug logs when clicking button. Is there any traffic in the logs from the buttons?
What's the exact model of the buttons?

Adminiuga on 11 Feb 2020

Ok, I don't get anything in the log when I press the remote(s).

Are the buttons paired?
Yes the remote(s) are paired and control the bulb/blind respectively (via group binding).

Do you see ZHA button devices in ZHA device list? (screenshots?)
Yes, see screenshot. https://imgur.com/a/14ap79h

debug logs when clicking button. Is there any traffic in the logs from the buttons?
Nothing is written to the log when button is pressed.

What's the exact model of the buttons?
https://www.ikea.com/us/en/p/tradfri-wireless-dimmer-white-10408598/

nicjo814 on 11 Feb 2020

There seems to be something wrong with my installation as well.
Previously able to have zha_event listening very responsive as I was doing lots of testing with appdaemon for ikea remotes using controllerx.
Since 0.105.3 there is now quite a delay in zha_events showing and very few events are actually coming through. I'm also getting lots of deserializing errors in my HA log.

2020-02-14 21:01:38 WARNING (MainThread) [zigpy.zcl] Data remains after deserializing ZCL frame
2020-02-14 21:01:42 WARNING (MainThread) [zigpy.zcl] Data remains after deserializing ZCL frame
2020-02-14 21:01:43 WARNING (MainThread) [zigpy.zcl] Data remains after deserializing ZCL frame
2020-02-14 21:01:44 WARNING (MainThread) [zigpy.zcl] Data remains after deserializing ZCL frame
2020-02-14 21:02:14 WARNING (MainThread) [zigpy.zcl] Data remains after deserializing ZCL frame
2020-02-14 21:03:34 WARNING (MainThread) [zigpy.zcl] Data remains after deserializing ZCL frame
2020-02-14 21:03:54 WARNING (MainThread) [zigpy.zcl] Data remains after deserializing ZCL frame
2020-02-14 21:03:55 WARNING (MainThread) [zigpy.zcl] Data remains after deserializing ZCL frame

Mostly Ikea remotes. I did just turn on OTA with this version. Will so some poking around...

sreknob on 15 Feb 2020

Is there anything I can do on my end to help troubleshoot?
Any more info I can provide?

nicjo814 on 15 Feb 2020

Here is a log from when I'm waking the on/off remote up from sleep:
2020-02-15 11:19:41 DEBUG (MainThread) [bellows.ezsp] Send command nop: () 2020-02-15 11:19:41 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'147d3321ad1e357e' 2020-02-15 11:19:41 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4213a1ad570f7e' 2020-02-15 11:19:41 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e' 2020-02-15 11:19:41 DEBUG (MainThread) [bellows.ezsp] Application frame 5 (nop) received: b'' 2020-02-15 11:19:45 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.motion_tv_up, old_state=<state binary_sensor.motion_tv_up=off; friendly_name=motion_tv_up @ 2020-02-15T11:18:58.006221+01:00>, new_state=<state binary_sensor.motion_tv_up=on; friendly_name=motion_tv_up @ 2020-02-15T11:19:45.414002+01:00>> 2020-02-15 11:19:51 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.motion_tv_up, old_state=<state binary_sensor.motion_tv_up=on; friendly_name=motion_tv_up @ 2020-02-15T11:19:45.414002+01:00>, new_state=<state binary_sensor.motion_tv_up=off; friendly_name=motion_tv_up @ 2020-02-15T11:19:51.008248+01:00>> 2020-02-15 11:19:51 DEBUG (MainThread) [bellows.ezsp] Send command nop: () 2020-02-15 11:19:51 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'251021ad1d387e' 2020-02-15 11:19:51 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5310a1ad634c7e' 2020-02-15 11:19:51 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e' 2020-02-15 11:19:51 DEBUG (MainThread) [bellows.ezsp] Application frame 5 (nop) received: b'' 2020-02-15 11:19:54 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6310b1ed542e14b359954b25ab55924563f24a8d1231608392cc4289dc4229b97e' 2020-02-15 11:19:54 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e' 2020-02-15 11:19:54 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received: b'00040101000101000100000cffbc6d26ffff07086f0a2100203c' 2020-02-15 11:19:54 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=1 sourceEndpoint=1 destinationEndpoint=1 options=256 groupId=0 sequence=12>, 255, -68, 0x266d, 255, 255, b'\x08o\n!\x00 <'] 2020-02-15 11:19:54 DEBUG (MainThread) [zigpy.zcl] [0x266d:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=111 command_id=Command.Report_Attributes> 2020-02-15 11:19:54 DEBUG (MainThread) [zigpy.zcl] [0x266d:1:0x0001] ZCL request 0x000a: [[<Attribute attrid=33 value=<TypeValue type=uint8_t, value=60>>]] 2020-02-15 11:19:54 DEBUG (MainThread) [zigpy.zcl] [0x266d:1:0x0001] Attribute report received: battery_percentage_remaining=60 2020-02-15 11:19:55 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x266d](TRADFRI on/off switch): started initialization 2020-02-15 11:19:55 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x266d:ZDO](TRADFRI on/off switch): entry loaded from storage: ZhaDeviceEntry(name='IKEA of Sweden TRADFRI on/off switch', ieee='14:b4:57:ff:fe:91:8e:59', last_seen=1581751814.4110985) 2020-02-15 11:19:55 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x266d:ZDO](TRADFRI on/off switch): channel: 'async_initialize' stage succeeded 2020-02-15 11:19:55 DEBUG (MainThread) [zigpy.device] [0x266d] Extending timeout for 0x15 request 2020-02-15 11:19:55 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:91:8e:59/0x266d 2020-02-15 11:19:55 DEBUG (MainThread) [bellows.ezsp] Send command setExtendedTimeout: (14:b4:57:ff:fe:91:8e:59, True) 2020-02-15 11:19:55 DEBUG (MainThread) [zigpy.device] [0x266d] Extending timeout for 0x17 request 2020-02-15 11:19:55 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'377d3121d60da4844ca6c3fe31ab375d7e' 2020-02-15 11:19:55 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:91:8e:59/0x266d 2020-02-15 11:19:55 DEBUG (MainThread) [bellows.ezsp] Send command setExtendedTimeout: (14:b4:57:ff:fe:91:8e:59, True) 2020-02-15 11:19:55 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x266d:1:0x1000]: initializing channel: from_cache: False 2020-02-15 11:19:55 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x266d:1:0x1000]: channel: 'async_initialize' stage succeeded 2020-02-15 11:19:55 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7411a1d6fde37e' 2020-02-15 11:19:55 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x266d:1:0x0006]: initializing channel: from_cache: False 2020-02-15 11:19:55 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e' 2020-02-15 11:19:55 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x266d:1:0x0006]: channel: 'async_initialize' stage succeeded 2020-02-15 11:19:55 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'401621d60da4844ca6c3fe31ab94127e' 2020-02-15 11:19:55 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x266d:1:0x0008]: initializing channel: from_cache: False 2020-02-15 11:19:55 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x266d:1:0x0008]: channel: 'async_initialize' stage succeeded 2020-02-15 11:19:55 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.ikea_of_sweden_tradfri_on_off_switch_598e91fe_power, old_state=<state sensor.ikea_of_sweden_tradfri_on_off_switch_598e91fe_power=unavailable; unit_of_measurement=%, friendly_name=Wakeup Light Remote Battery, device_class=battery @ 2020-02-15T11:15:11.558700+01:00>, new_state=<state sensor.ikea_of_sweden_tradfri_on_off_switch_598e91fe_power=60; unit_of_measurement=%, friendly_name=Wakeup Light Remote Battery, device_class=battery @ 2020-02-15T11:19:55.058786+01:00>> 2020-02-15 11:19:55 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0516a1d64cb27e' 2020-02-15 11:19:55 DEBUG (MainThread) [bellows.ezsp] Application frame 126 (setExtendedTimeout) received: b'' 2020-02-15 11:19:55 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e' 2020-02-15 11:19:55 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x266d, <EmberApsFrame profileId=260 clusterId=0 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=21>, 22, b'\x00\x15\x00\x07\x00') 2020-02-15 11:19:55 DEBUG (MainThread) [bellows.ezsp] Application frame 126 (setExtendedTimeout) received: b'' 2020-02-15 11:19:55 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'5117219c544733b658944a24ab1593499c5b31aeeddb678cfd66bf7e' 2020-02-15 11:19:55 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x266d, <EmberApsFrame profileId=260 clusterId=1 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=23>, 24, b'\x00\x17\x001\x00') 2020-02-15 11:19:55 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1617a19c5435cfec7e' 2020-02-15 11:19:55 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e' 2020-02-15 11:19:55 DEBUG (MainThread) [bellows.ezsp] Application frame 52 (sendUnicast) received: b'001f' 2020-02-15 11:19:55 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'6214219c544733b658954a24ab1593499c593faeedd967bafd8a7b7e' 2020-02-15 11:19:55 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2714a19c540a8cae7e' 2020-02-15 11:19:55 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e' 2020-02-15 11:19:55 DEBUG (MainThread) [bellows.ezsp] Application frame 52 (sendUnicast) received: b'0020' 2020-02-15 11:19:55 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3714b1ed542e14b359954b25ab5592477af44a8d123160838ccc4389dc6524157e' 2020-02-15 11:19:55 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e' 2020-02-15 11:19:55 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received: b'00040101000101000100000ee6ba6d26ffff0708710a2000201b' 2020-02-15 11:19:55 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=1 sourceEndpoint=1 destinationEndpoint=1 options=256 groupId=0 sequence=14>, 230, -70, 0x266d, 255, 255, b'\x08q\n \x00 \x1b'] 2020-02-15 11:19:55 DEBUG (MainThread) [zigpy.zcl] [0x266d:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=113 command_id=Command.Report_Attributes> 2020-02-15 11:19:55 DEBUG (MainThread) [zigpy.zcl] [0x266d:1:0x0001] ZCL request 0x000a: [[<Attribute attrid=32 value=<TypeValue type=uint8_t, value=27>>]] 2020-02-15 11:19:55 DEBUG (MainThread) [zigpy.zcl] [0x266d:1:0x0001] Attribute report received: battery_voltage=27 2020-02-15 11:19:55 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.ikea_of_sweden_tradfri_on_off_switch_598e91fe_power, old_state=<state sensor.ikea_of_sweden_tradfri_on_off_switch_598e91fe_power=60; unit_of_measurement=%, friendly_name=Wakeup Light Remote Battery, device_class=battery @ 2020-02-15T11:19:55.058786+01:00>, new_state=<state sensor.ikea_of_sweden_tradfri_on_off_switch_598e91fe_power=60; battery_voltage=2.7, unit_of_measurement=%, friendly_name=Wakeup Light Remote Battery, device_class=battery @ 2020-02-15T11:19:55.058786+01:00>> 2020-02-15 11:19:56 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4714b1ed542e14b259954b65ab559259638d4a8d12316f93e8c76489fc4e3cc4107e' 2020-02-15 11:19:56 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e' 2020-02-15 11:19:56 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received: b'000401000001014001000010ffc36d26ffff081815010700003003' 2020-02-15 11:19:56 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=0 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=16>, 255, -61, 0x266d, 255, 255, b'\x18\x15\x01\x07\x00\x000\x03'] 2020-02-15 11:19:56 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5714b197544733b658944a24ab1593499c5131abeda2a37e' 2020-02-15 11:19:56 DEBUG (MainThread) [zigpy.zcl] [0x266d:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=21 command_id=Command.Read_Attributes_rsp> 2020-02-15 11:19:56 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e' 2020-02-15 11:19:56 DEBUG (MainThread) [bellows.ezsp] Application frame 63 (messageSentHandler) received: b'006d26040100000101400100001f160000' 2020-02-15 11:19:56 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 9837, <EmberApsFrame profileId=260 clusterId=0 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=31>, 22, <EmberStatus.SUCCESS: 0>, b''] 2020-02-15 11:19:56 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6714b1ed542e14b359954b65ab559258638d4a8d12316193eac752897a418b7e' 2020-02-15 11:19:56 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e' 2020-02-15 11:19:56 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7714b197544733b658954a24ab1593499c6e3fabed4f6b7e' 2020-02-15 11:19:56 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e' 2020-02-15 11:19:56 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x266d:1:0x0000]: initializing channel: from_cache: False 2020-02-15 11:19:56 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x266d:1:0x0000]: channel: 'async_initialize' stage succeeded 2020-02-15 11:19:56 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received: b'000401010001014001000011ffc36d26ffff06181701310086' 2020-02-15 11:19:56 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=1 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=17>, 255, -61, 0x266d, 255, 255, b'\x18\x17\x011\x00\x86'] 2020-02-15 11:19:56 DEBUG (MainThread) [zigpy.zcl] [0x266d:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=23 command_id=Command.Read_Attributes_rsp> 2020-02-15 11:19:56 DEBUG (MainThread) [bellows.ezsp] Application frame 63 (messageSentHandler) received: b'006d260401010001014001000020180000' 2020-02-15 11:19:56 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 9837, <EmberApsFrame profileId=260 clusterId=1 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=32>, 24, <EmberStatus.SUCCESS: 0>, b''] 2020-02-15 11:19:56 DEBUG (MainThread) [zigpy.device] [0x266d] Extending timeout for 0x19 request 2020-02-15 11:19:56 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:91:8e:59/0x266d 2020-02-15 11:19:56 DEBUG (MainThread) [bellows.ezsp] Send command setExtendedTimeout: (14:b4:57:ff:fe:91:8e:59, True) 2020-02-15 11:19:56 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'701521d60da4844ca6c3fe31abaa517e' 2020-02-15 11:19:56 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0015a1d6a9a77e' 2020-02-15 11:19:56 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e' 2020-02-15 11:19:56 DEBUG (MainThread) [bellows.ezsp] Application frame 126 (setExtendedTimeout) received: b'' 2020-02-15 11:19:56 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x266d, <EmberApsFrame profileId=260 clusterId=1 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=25>, 26, b'\x00\x19\x00!\x00') 2020-02-15 11:19:56 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'017d3a219c544733b658954a24ab1593499c573daeedd767aafd59d77e' 2020-02-15 11:19:56 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'111aa19c540bf14a7e' 2020-02-15 11:19:56 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e' 2020-02-15 11:19:56 DEBUG (MainThread) [bellows.ezsp] Application frame 52 (sendUnicast) received: b'0021' 2020-02-15 11:19:59 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'211ab1ed542e14b359954b65ab55925b638b4a8d12316f93e4c74289fc5e1d2b297e' 2020-02-15 11:19:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e' 2020-02-15 11:19:59 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received: b'000401010001014001000012ffc56d26ffff081819012100002022' 2020-02-15 11:19:59 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=1 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=18>, 255, -59, 0x266d, 255, 255, b'\x18\x19\x01!\x00\x00 "'] 2020-02-15 11:19:59 DEBUG (MainThread) [zigpy.zcl] [0x266d:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=25 command_id=Command.Read_Attributes_rsp> 2020-02-15 11:20:01 DEBUG (MainThread) [bellows.ezsp] Send command nop: () 2020-02-15 11:20:01 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'7d331b21ade6b97e' 2020-02-15 11:20:01 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'321ba1adbcdb7e' 2020-02-15 11:20:01 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e' 2020-02-15 11:20:01 DEBUG (MainThread) [bellows.ezsp] Application frame 5 (nop) received: b''

nicjo814 on 15 Feb 2020

Wake up device and press reconfigure button in zha config panel for this device and submit the logs. I don't see anything wrong but could be either it lost its configuration or it is sending updates via group id.

Adminiuga on 15 Feb 2020

Ok, here is the log from when I reconfigure the device:
2020-02-16 12:30:35 DEBUG (MainThread) [homeassistant.components.zha.api] Reconfiguring node with ieee_address: 14:b4:57:ff:fe:91:8e:59 2020-02-16 12:30:35 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x266d](TRADFRI on/off switch): started configuration 2020-02-16 12:30:35 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x266d:ZDO](TRADFRI on/off switch): channel: 'async_configure' stage succeeded 2020-02-16 12:30:35 DEBUG (MainThread) [zigpy.device] [0x266d] Extending timeout for 0x83 request 2020-02-16 12:30:35 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:91:8e:59/0x266d 2020-02-16 12:30:35 DEBUG (MainThread) [bellows.ezsp] Send command setExtendedTimeout: (14:b4:57:ff:fe:91:8e:59, True) 2020-02-16 12:30:35 DEBUG (MainThread) [zigpy.device] [0x266d] Extending timeout for 0x85 request 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'419e21d60da4844ca6c3fe31ab60787e' 2020-02-16 12:30:35 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:91:8e:59/0x266d 2020-02-16 12:30:35 DEBUG (MainThread) [bellows.ezsp] Send command setExtendedTimeout: (14:b4:57:ff:fe:91:8e:59, True) 2020-02-16 12:30:35 DEBUG (MainThread) [bellows.ezsp] Send command setMulticastTableEntry: (0, <EmberMulticastTableEntry multicastId=0x0000 endpoint=1 networkIndex=0>) 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'159ea1d6c5ee7e' 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e' 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'529f21d60da4844ca6c3fe31abba1c7e' 2020-02-16 12:30:35 DEBUG (MainThread) [bellows.ezsp] Application frame 126 (setExtendedTimeout) received: b'' 2020-02-16 12:30:35 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x266d, <EmberApsFrame profileId=0 clusterId=33 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=131>, 132, b'\x83Y\x8e\x91\xfe\xffW\xb4\x14\x01\x00\x00\x03\xa2\xc5\xd1\r\x00o\r\x00\x01') 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'269fa1d645eb7e' 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e' 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'639c21cc542a15b35994157e' 2020-02-16 12:30:35 DEBUG (MainThread) [bellows.ezsp] Application frame 126 (setExtendedTimeout) received: b'' 2020-02-16 12:30:35 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x266d, <EmberApsFrame profileId=0 clusterId=33 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=133>, 134, b'\x85Y\x8e\x91\xfe\xffW\xb4\x14\x01\x01\x00\x03\xa2\xc5\xd1\r\x00o\r\x00\x01') 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'379ca1cc54307f7e' 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e' 2020-02-16 12:30:35 DEBUG (MainThread) [bellows.ezsp] Application frame 100 (setMulticastTableEntry) received: b'00' 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'749d219c544733b259b54a25aa1593499ccda3bd6e97e97d3a0339343de87f3fa7e86f1bbe82ffa8d6d5d3f3147e' 2020-02-16 12:30:35 DEBUG (MainThread) [bellows.multicast] Set MulticastTableEntry #0 for 0x0000 multicast id: [<EmberStatus.SUCCESS: 0>] 2020-02-16 12:30:35 DEBUG (MainThread) [zigpy.group] Adding group: 0, None 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'409da19c54f1cf2f7e' 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e' 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'05a2219c544733b259b54a25aa1593499ccba1bd6897e97d3a0339343de87f3ea7e86f1bbe82ffa8d6d5d312507e' 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'51a2a19c54f689fb7e' 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e' 2020-02-16 12:30:35 INFO (MainThread) [homeassistant.components.zha.core.group] [No name group 0x0000](0x0000): group_added 2020-02-16 12:30:35 INFO (MainThread) [homeassistant.components.zha.core.group] [No name group 0x0000](0x0000): group_member_added - endpoint: <bellows.zigbee.application.EZSPCoordinator.EZSPEndpoint object at 0xb0f31170> 2020-02-16 12:30:35 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x266d:1:0x1000]: bound 'lightlink' cluster: None 2020-02-16 12:30:35 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x266d:1:0x1000]: finished channel configuration 2020-02-16 12:30:35 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x266d:1:0x1000]: channel: 'async_configure' stage succeeded 2020-02-16 12:30:35 DEBUG (MainThread) [bellows.ezsp] Application frame 52 (sendUnicast) received: b'00db' 2020-02-16 12:30:35 DEBUG (MainThread) [bellows.ezsp] Application frame 52 (sendUnicast) received: b'00dc' 2020-02-16 12:30:35 DEBUG (MainThread) [zigpy.device] [0x266d] Extending timeout for 0x87 request 2020-02-16 12:30:35 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:91:8e:59/0x266d 2020-02-16 12:30:35 DEBUG (MainThread) [bellows.ezsp] Send command setExtendedTimeout: (14:b4:57:ff:fe:91:8e:59, True) 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'16a321d60da4844ca6c3fe31abaaed7e' 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'62a3a1d651427e' 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e' 2020-02-16 12:30:35 DEBUG (MainThread) [bellows.ezsp] Application frame 126 (setExtendedTimeout) received: b'' 2020-02-16 12:30:35 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x266d, <EmberApsFrame profileId=0 clusterId=33 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=135>, 136, b'\x87Y\x8e\x91\xfe\xffW\xb4\x14\x01\x06\x00\x03\xa2\xc5\xd1\r\x00o\r\x00\x01') 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'27a0219c544733b259b54a25aa1593499cc9afbd6a97e97d3a0339343de87f39a7e86f1bbe82ffa8d6d5d3e5cf7e' 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'73a0a19c54f763117e' 2020-02-16 12:30:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e' 2020-02-16 12:30:35 DEBUG (MainThread) [bellows.ezsp] Application frame 52 (sendUnicast) received: b'00dd' 2020-02-16 12:30:37 DEBUG (MainThread) [bellows.ezsp] Send command nop: () 2020-02-16 12:30:37 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'30a121ad73157e' 2020-02-16 12:30:37 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'04a1a1ad8e957e' 2020-02-16 12:30:37 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e' 2020-02-16 12:30:37 DEBUG (MainThread) [bellows.ezsp] Application frame 5 (nop) received: b''

nicjo814 on 16 Feb 2020

I finally got zha_events from the remote. After unbinding the remote from all devices/groups in the ZHA config UI I got the events in the log. I was 100% sure I've done that before, but I'm no so sure anymore :-)
Thanks for all your support!

nicjo814 on 16 Feb 2020

@dmulcahey could it be that remote stops sending updates on Group_id == 0x0000 if you bind it to any group? Just like Opple Remotes stop sending broadcasts?

Adminiuga on 17 Feb 2020

@nicjo814 can you test the following:

bind the remote to a group and confirm you stop receiving zha_events
Add your EZSP coordinator as a member to the same group you bound the remote

Adminiuga on 17 Feb 2020

Could be

dmulcahey on 17 Feb 2020

@Adminiuga When I bind the remote to a group with a single lamp I don't get zha_events any longer. Adding the coordinator to the group makes the events appear in the log again.

Is there any way to see current device/group bindings?

nicjo814 on 17 Feb 2020

thanks. So this confirms those remotes use group_id 0x0000 when not bound to any groups.
Currently there's no way to see device bindings. I guess that leaves it up to the user to do extra configuration step if you bind the remote.

Adminiuga on 17 Feb 2020

Hi, can you please explain the extra configuration step as I am unable to make the remote work? I have the remote added to ZHA and I can see it in the configuration but I am unable to get zha_event triggered by the remote.

Botap on 6 May 2020

Adminiuga on 6 May 2020

👀1 ❤1 👍1

Thanks for your reply. I was hoping may be you can provide some more details on how to bind the device and the coordinator to a group as that should solve the issue but I don't know how to do that as I am very new to Zigbee

Botap on 6 May 2020

Check #zigbee channel on HA discord server

Adminiuga on 6 May 2020

Same issue here, tried two different IKEA trådfri on/off switches and four different 5-button remotes. I've asked in the discord channel, see if someone has any ideas.