Original Xiaomi motion sensor error during pairing

Question

Original Xiaomi motion sensor error during pairing

Closed this issue 6 years ago · 9 comments

I'm attempting to get an original Xiaomi motion sensor (the cylindrical "smart human body sensor") to pair.
I confirmed hass isn't reverting your versions of bellows and zigpy when it starts, I also just applied the latest commit to zigpy you pushed a few hours ago.

Package                 Version
----------------------- -----------
bellows                 0.6.0-YD
zigpy                   0.1.1-Y

My existing ZigBee devices (Osram bulbs and Centralite pocket sockets) all work with zha_new as they did under zha with the added attributes for rssi and such so for the most part things are working correctly.

Log:

May 10 22:25:24 serverbox hass[26771]: 2018-05-10 22:25:24 INFO (MainThread) [custom_components.zha_new] Permitting joins for 60s
May 10 22:25:24 serverbox hass[26771]: 2018-05-10 22:25:24 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=zha_new.controller, old_state=<state zha_new.controller=Run; friendly_name=Controller, no_of_entities=0, neighborCount=5, no_devices=6 @ 2018-05-10T22:24:59.714036-04:00>, new_state=<state zha_new.controller=Permit; friendly_name=Controller, no_of_entities=0, neighborCount=5, no_devices=6 @ 2018-05-10T22:25:24.442745-04:00>>
May 10 22:25:24 serverbox hass[26771]: 2018-05-10 22:25:24 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=140169523529656-18>
May 10 22:25:25 serverbox hass[26771]: 2018-05-10 22:25:25 WARNING (MainThread) [bellows.zigbee.application] Unexpected message send notification
May 10 22:25:25 serverbox hass[26771]: 2018-05-10 22:25:25 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1526005525.4156659, level=WARNING, message=Unexpected message send notification, exception=, source=core.py>
May 10 22:25:38 serverbox hass[26771]: 2018-05-10 22:25:38 INFO (MainThread) [zigpy.application] Device 0xef7c (00:15:8d:00:01:4d:d5:6c) joined the network
May 10 22:25:38 serverbox hass[26771]: 2018-05-10 22:25:38 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=zha_new.controller, old_state=<state zha_new.controller=Permit; friendly_name=Controller, no_of_entities=0, neighborCount=5, no_devices=6 @ 2018-05-10T22:25:24.442745-04:00>, new_state=<state zha_new.controller=Joined 00:15:8d:00:01:4d:d5:6c; friendly_name=Controller, no_of_entities=0, neighborCount=5, no_devices=6 @ 2018-05-10T22:25:38.068460-04:00>>
May 10 22:25:38 serverbox hass[26771]: 2018-05-10 22:25:38 INFO (MainThread) [zigpy.device] [0xef7c] Discovering endpoints
May 10 22:25:38 serverbox hass[26771]: 2018-05-10 22:25:38 INFO (MainThread) [zigpy.application] Device 0xef7c (00:15:8d:00:01:4d:d5:6c) joined the network
May 10 22:25:38 serverbox hass[26771]: 2018-05-10 22:25:38 ERROR (MainThread) [bellows.ezsp] Exception running handler
May 10 22:25:38 serverbox hass[26771]: Traceback (most recent call last):
May 10 22:25:38 serverbox hass[26771]:   File "/opt/homeassistant/lib/python3.6/site-packages/bellows/ezsp.py", line 194, in handle_callback
May 10 22:25:38 serverbox hass[26771]:     handler(*args)
May 10 22:25:38 serverbox hass[26771]:   File "/opt/homeassistant/lib/python3.6/site-packages/bellows/zigbee/application.py", line 144, in ezsp_callback_handler
May 10 22:25:38 serverbox hass[26771]:     self._handle_frame(*args)
May 10 22:25:38 serverbox hass[26771]:   File "/opt/homeassistant/lib/python3.6/site-packages/bellows/zigbee/application.py", line 165, in _handle_frame
May 10 22:25:38 serverbox hass[26771]:     tsn, command_id, is_reply, args = self.deserialize(device, aps_frame.sourceEndpoint, aps_frame.clusterId, message)
May 10 22:25:38 serverbox hass[26771]:   File "/opt/homeassistant/lib/python3.6/site-packages/zigpy/application.py", line 69, in deserialize
May 10 22:25:38 serverbox hass[26771]:     return sender.deserialize(endpoint_id, cluster_id, data)
May 10 22:25:38 serverbox hass[26771]:   File "/opt/homeassistant/lib/python3.6/site-packages/zigpy/device.py", line 97, in deserialize
May 10 22:25:38 serverbox hass[26771]:     return self.endpoints[endpoint_id].deserialize(cluster_id, data)
May 10 22:25:38 serverbox hass[26771]: KeyError: 1
May 10 22:25:38 serverbox hass[26771]: 2018-05-10 22:25:38 ERROR (MainThread) [bellows.ezsp] Exception running handler
May 10 22:25:38 serverbox hass[26771]: Traceback (most recent call last):
May 10 22:25:38 serverbox hass[26771]:   File "/opt/homeassistant/lib/python3.6/site-packages/bellows/ezsp.py", line 194, in handle_callback
May 10 22:25:38 serverbox hass[26771]:     handler(*args)
May 10 22:25:38 serverbox hass[26771]:   File "/opt/homeassistant/lib/python3.6/site-packages/bellows/zigbee/application.py", line 144, in ezsp_callback_handler
May 10 22:25:38 serverbox hass[26771]:     self._handle_frame(*args)
May 10 22:25:38 serverbox hass[26771]:   File "/opt/homeassistant/lib/python3.6/site-packages/bellows/zigbee/application.py", line 165, in _handle_frame
May 10 22:25:38 serverbox hass[26771]:     tsn, command_id, is_reply, args = self.deserialize(device, aps_frame.sourceEndpoint, aps_frame.clusterId, message)
May 10 22:25:38 serverbox hass[26771]:   File "/opt/homeassistant/lib/python3.6/site-packages/zigpy/application.py", line 69, in deserialize
May 10 22:25:38 serverbox hass[26771]:     return sender.deserialize(endpoint_id, cluster_id, data)
May 10 22:25:38 serverbox hass[26771]:   File "/opt/homeassistant/lib/python3.6/site-packages/zigpy/device.py", line 97, in deserialize
May 10 22:25:38 serverbox hass[26771]:     return self.endpoints[endpoint_id].deserialize(cluster_id, data)

The error repeats each time I press the reset button on the sensor. Any tips for debugging?
As far as I can interpret from the log, the sensor successfully joins the network but falls flat discovering endpoints. If I hold the reset button down for a long time it will also successfully report leaving the network.

Answer 1 · 2018-05-11T03:08:27.000Z

Tried again holding the reset button down until it blinked three time and then pressing it briefly once every couple seconds as recommended in the wiki. Got it to join but it is detected as a light made by "LUMI":

May 10 23:00:44 serverbox hass[27316]: 2018-05-10 23:00:44 INFO (MainThread) [custom_components.zha_new] Permitting joins for 60s
May 10 23:00:44 serverbox hass[27316]: 2018-05-10 23:00:44 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=zha_new.controller, old_state=<state zha_new.controller=Run; friendly_name=Controller, no_of_entities=0, neighborCount=4, no_devices=7 @ 2018-05-10T22:58:46.783355-04:00>, new_state=<state zha_new.controller=Permit; friendly_name=Controller, no_of_entities=0, neighborCount=4, no_devices=7 @ 2018-05-10T23:00:44.783251-04:00>>
May 10 23:00:44 serverbox hass[27316]: 2018-05-10 23:00:44 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139763732768696-19>
May 10 23:00:45 serverbox hass[27316]: 2018-05-10 23:00:45 WARNING (MainThread) [bellows.zigbee.application] Unexpected message send notification
May 10 23:00:45 serverbox hass[27316]: 2018-05-10 23:00:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1526007645.7860868, level=WARNING, message=Unexpected message send notification, exception=, source=core.py>
Device 0xe824 (00:15:8d:00:01:4d:d5:6c) joined the network
May 10 23:01:04 serverbox hass[27316]: 2018-05-10 23:01:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=zha_new.controller, old_state=<state zha_new.controller=Permit; friendly_name=Controller, no_of_entities=0, neighborCount=4, no_devices=7 @ 2018-05-10T23:00:44.783251-04:00>, new_state=<state zha_new.controller=Joined 00:15:8d:00:01:4d:d5:6c; friendly_name=Controller, no_of_entities=0, neighborCount=4, no_devices=7 @ 2018-05-10T23:01:04.609436-04:00>>
May 10 23:01:04 serverbox hass[27316]: 2018-05-10 23:01:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=zha_new.controller, old_state=<state zha_new.controller=Joined 00:15:8d:00:01:4d:d5:6c; friendly_name=Controller, no_of_entities=0, neighborCount=4, no_devices=7 @ 2018-05-10T23:01:04.609436-04:00>, new_state=<state zha_new.controller=Device init 00:15:8d:00:01:4d:d5:6c; friendly_name=Controller, no_of_entities=0, neighborCount=4, no_devices=7 @ 2018-05-10T23:01:04.651243-04:00>>
May 10 23:01:04 serverbox hass[27316]: 2018-05-10 23:01:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event platform_discovered[L]: service=load_platform.light, platform=zha_new, discovered=discovery_key=00:15:8d:00:01:4d:d5:6c-1>
May 10 23:01:04 serverbox hass[27316]: 2018-05-10 23:01:04 INFO (MainThread) [homeassistant.components.light] Setting up light.zha_new
May 10 23:01:04 serverbox hass[27316]: 2018-05-10 23:01:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.lumi_lumisensor_motion_014dd56c_1, old_state=<state light.lumi_lumisensor_motion_014dd56c_1=off; friendly_name=LUMI lumi.sensor_motion, model=lumi.sensor_motion, manufacturer=LUMI, lqi=None, rssi=None, supported_features=0 @ 2018-05-10T22:58:47.539319-04:00>, new_state=None>
May 10 23:01:04 serverbox hass[27316]: 2018-05-10 23:01:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.lumi_lumisensor_motion_014dd56c_1, old_state=None, new_state=<state light.lumi_lumisensor_motion_014dd56c_1=off; friendly_name=LUMI lumi.sensor_motion, model=lumi.sensor_motion, manufacturer=LUMI, lqi=None, rssi=None, supported_features=0 @ 2018-05-10T23:01:04.687917-04:00>>
May 10 23:01:04 serverbox hass[27316]: 2018-05-10 23:01:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=group, service=set, service_data=object_id=all_lights, name=all lights, entities=['light.computer_room_lights', 'light.kitchen_dining_room_light', 'light.kitchen_kitchen_lights', 'light.porch_light_level', 'light.porch_lights', 'light.centralite_3210l_0594bc3e_1', 'light.centralite_3210l_0a90f532_1', 'light.centralite_4257050rzhac_04483356_1', 'light.lumi_lumisensor_motion_014dd56c_1', 'light.osram_lightify_a19_rgbw_00a43d4e_3', 'light.osram_lightify_a19_rgbw_00a47201_3', 'light.osram_lightify_a19_tunable_white_0004c837_3'], visible=False, service_call_id=139763732768696-20>
May 10 23:01:04 serverbox hass[27316]: 2018-05-10 23:01:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139763732768696-20>
May 10 23:01:04 serverbox hass[27316]: 2018-05-10 23:01:04 WARNING (MainThread) [zigpy.util] Error calling listener.attribute_updated: Error binding parameter 4 - probably unsupported type.
May 10 23:01:04 serverbox hass[27316]: 2018-05-10 23:01:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1526007664.9279027, level=WARNING, message=Error calling listener.attribute_updated: Error binding parameter 4 - probably unsupported type., exception=, source=core.py>
May 10 23:01:04 serverbox hass[27316]: 2018-05-10 23:01:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.lumi_lumisensor_motion_014dd56c_1, old_state=<state light.lumi_lumisensor_motion_014dd56c_1=off; friendly_name=LUMI lumi.sensor_motion, model=lumi.sensor_motion, manufacturer=LUMI, lqi=None, rssi=None, supported_features=0 @ 2018-05-10T23:01:04.687917-04:00>, new_state=<state light.lumi_lumisensor_motion_014dd56c_1=on; min_mireds=153, max_mireds=500, friendly_name=LUMI lumi.sensor_motion, model=lumi.sensor_motion, manufacturer=LUMI, lqi=240, rssi=-75, supported_features=0 @ 2018-05-10T23:01:04.935508-04:00>>
May 10 23:01:04 serverbox hass[27316]: 2018-05-10 23:01:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=off; entity_id=('light.computer_room_lights', 'light.kitchen_dining_room_light', 'light.kitchen_kitchen_lights', 'light.porch_light_level', 'light.porch_lights', 'light.centralite_3210l_0594bc3e_1', 'light.centralite_3210l_0a90f532_1', 'light.centralite_4257050rzhac_04483356_1', 'light.lumi_lumisensor_motion_014dd56c_1', 'light.osram_lightify_a19_rgbw_00a43d4e_3', 'light.osram_lightify_a19_rgbw_00a47201_3', 'light.osram_lightify_a19_tunable_white_0004c837_3'), order=15, auto=True, friendly_name=all lights, hidden=True @ 2018-05-10T22:58:45.777084-04:00>, new_state=<state group.all_lights=on; entity_id=('light.computer_room_lights', 'light.kitchen_dining_room_light', 'light.kitchen_kitchen_lights', 'light.porch_light_level', 'light.porch_lights', 'light.centralite_3210l_0594bc3e_1', 'light.centralite_3210l_0a90f532_1', 'light.centralite_4257050rzhac_04483356_1', 'light.lumi_lumisensor_motion_014dd56c_1', 'light.osram_lightify_a19_rgbw_00a43d4e_3', 'light.osram_lightify_a19_rgbw_00a47201_3', 'light.osram_lightify_a19_tunable_white_0004c837_3'), order=15, auto=True, friendly_name=all lights, hidden=True @ 2018-05-10T23:01:04.946608-04:00>>
May 10 23:01:10 serverbox hass[27316]: 2018-05-10 23:01:10 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.lumi_lumisensor_motion_014dd56c_1, old_state=<state light.lumi_lumisensor_motion_014dd56c_1=on; min_mireds=153, max_mireds=500, friendly_name=LUMI lumi.sensor_motion, model=lumi.sensor_motion, manufacturer=LUMI, lqi=240, rssi=-75, supported_features=0 @ 2018-05-10T23:01:04.935508-04:00>, new_state=<state light.lumi_lumisensor_motion_014dd56c_1=on; min_mireds=153, max_mireds=500, friendly_name=LUMI lumi.sensor_motion, model=lumi.sensor_motion, manufacturer=LUMI, lqi=232, rssi=-76, supported_features=0 @ 2018-05-10T23:01:04.935508-04:00>>
May 10 23:01:16 serverbox hass[27316]: 2018-05-10 23:01:16 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.lumi_lumisensor_motion_014dd56c_1, old_state=<state light.lumi_lumisensor_motion_014dd56c_1=on; min_mireds=153, max_mireds=500, friendly_name=LUMI lumi.sensor_motion, model=lumi.sensor_motion, manufacturer=LUMI, lqi=232, rssi=-76, supported_features=0 @ 2018-05-10T23:01:04.935508-04:00>, new_state=<state light.lumi_lumisensor_motion_014dd56c_1=on; min_mireds=153, max_mireds=500, friendly_name=LUMI lumi.sensor_motion, model=lumi.sensor_motion, manufacturer=LUMI, lqi=255, rssi=-75, supported_features=0 @ 2018-05-10T23:01:04.935508-04:00>>
May 10 23:01:21 serverbox hass[27316]: 2018-05-10 23:01:21 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.lumi_lumisensor_motion_014dd56c_1, old_state=<state light.lumi_lumisensor_motion_014dd56c_1=on; min_mireds=153, max_mireds=500, friendly_name=LUMI lumi.sensor_motion, model=lumi.sensor_motion, manufacturer=LUMI, lqi=255, rssi=-75, supported_features=0 @ 2018-05-10T23:01:04.935508-04:00>, new_state=<state light.lumi_lumisensor_motion_014dd56c_1=on; min_mireds=153, max_mireds=500, friendly_name=LUMI lumi.sensor_motion, model=lumi.sensor_motion, manufacturer=LUMI, lqi=255, rssi=-76, supported_features=0 @ 2018-05-10T23:01:04.935508-04:00>>

Answer 2 · 2018-05-11T23:43:26.000Z

I added a patch today, which fixed some things in zha_new. if it not helps, please enable debug for zha_new and send over the output.
thanks

Answer 3 · 2018-05-12T00:07:23.000Z

Updated zha_new but it still detects the motion sensor as a LUMI light of some sort. It calls it a lumi_sensor_motion... but it gets placed under the light platform.
Here's the debug log for the join process:

May 11 20:03:31 serverbox hass[11984]: 2018-05-11 20:03:31 INFO (MainThread) [custom_components.zha_new] Permitting joins for 60s
May 11 20:03:31 serverbox hass[11984]: 2018-05-11 20:03:31 WARNING (MainThread) [bellows.zigbee.application] Unexpected message send notification
May 11 20:03:32 serverbox hass[11984]: 2018-05-11 20:03:32 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=11 command=266 args=b'\x00\x00\x18\x01'
May 11 20:03:32 serverbox hass[11984]: 2018-05-11 20:03:32 WARNING (MainThread) [zigpy.endpoint] [0x9ea3:1] Message on unknown cluster 0x0406
May 11 20:03:37 serverbox hass[11984]: 2018-05-11 20:03:37 DEBUG (MainThread) [custom_components.zha_new] buffer: b'\xf9'
May 11 20:03:42 serverbox hass[11984]: 2018-05-11 20:03:42 DEBUG (MainThread) [custom_components.zha_new] Device joined: 00:15:8d:00:01:4d:d5:6c:
May 11 20:03:42 serverbox hass[11984]: 2018-05-11 20:03:42 DEBUG (MainThread) [custom_components.zha_new] Device initialized: 00:15:8d:00:01:4d:d5:6c:
May 11 20:03:42 serverbox hass[11984]: 2018-05-11 20:03:42 DEBUG (MainThread) [custom_components.zha_new] [0x264c] device init 00:15:8d:00:01:4d:d5:6c: [0, 1]
May 11 20:03:42 serverbox hass[11984]: 2018-05-11 20:03:42 DEBUG (MainThread) [custom_components.zha_new] [0x264c] endpoint init 0
May 11 20:03:42 serverbox hass[11984]: 2018-05-11 20:03:42 DEBUG (MainThread) [custom_components.zha_new] [0x264c] endpoint init 1
May 11 20:03:42 serverbox hass[11984]: 2018-05-11 20:03:42 DEBUG (MainThread) [custom_components.zha_new] [0x264c] node config for 00:15:8d:00:01:4d:d5:6c-1: {}
May 11 20:03:42 serverbox hass[11984]: 2018-05-11 20:03:42 DEBUG (MainThread) [custom_components.zha_new] single read attribute model <[108, 117, 109, 105, 46, 115, 101, 110, 115, 111, 114, 95, 109, 111, 116, 105, 111, 110]>
May 11 20:03:42 serverbox hass[11984]: 2018-05-11 20:03:42 DEBUG (MainThread) [custom_components.zha_new] [0x264c] pre call _custom_endpoint_init: {'module': <module 'custom_components.device.lumi_sensor_motion' from '/opt/homeassistant/config/custom_components/device/lumi_sensor_motion.py'>, '_custom_endpoint_init': <function _custom_endpoint_init at 0x7fe7d138b6a8>, '_custom_cluster_command': None, '_parse_attribute': <function _parse_attribute at 0x7fe7d138b7b8>, 'custom_parameters': None}
May 11 20:03:42 serverbox hass[11984]: 2018-05-11 20:03:42 DEBUG (MainThread) [custom_components.zha_new] [0x264c] call _custom_endpoint_init: lumi.sensor_motion
May 11 20:03:42 serverbox hass[11984]: 2018-05-11 20:03:42 DEBUG (MainThread) [custom_components.zha_new] [0x264c] node config for 00:15:8d:00:01:4d:d5:6c-1: {'config_report': [[1030, 0, 10, 1800, 1]], 'in_cluster': [0]}
May 11 20:03:42 serverbox hass[11984]: 2018-05-11 20:03:42 DEBUG (MainThread) [custom_components.zha_new] [0x264c] 2:profile 260, component: light cluster:({768, 4096, 0, 4, 5, 6, 7, 8}, {768, 4, 5, 6, 8})
May 11 20:03:42 serverbox hass[11984]: 2018-05-11 20:03:42 DEBUG (MainThread) [custom_components.zha_new] [0x264c] Output clusters:[4, 5, 6, 8]
May 11 20:03:42 serverbox hass[11984]: 2018-05-11 20:03:42 DEBUG (MainThread) [custom_components.zha_new] [0x264c] Return from component general entity:00:15:8d:00:01:4d:d5:6c
May 11 20:03:42 serverbox hass[11984]: 2018-05-11 20:03:42 DEBUG (MainThread) [custom_components.zha_new] dir entity:['__class__', '__delattr__', '__dict__', '__dir__', '__doc__', '__eq__', '__format__', '__ge__', '__getattribute__', '__gt__', '__hash__', '__init__', '__init_subclass__', '__le__', '__lt__', '__module__', '__ne__', '__new__', '__reduce__', '__reduce_ex__', '__repr__', '__setattr__', '__sizeof__', '__str__', '__subclasshook__', '__weakref__', '_application', '_custom_cluster_command', '_custom_module', '_device_state_attributes', '_domain', '_endpoint', '_in_clusters', '_model', '_out_clusters', '_parse_attribute', '_slow_reported', '_state', '_update_staged', 'assumed_state', 'async_device_update', 'async_registry_updated', 'async_remove', 'async_schedule_update_ha_state', 'async_toggle', 'async_turn_off', 'async_turn_on', 'async_update', 'async_update_ha_state', 'attribute_updated', 'available', 'brightness', 'cluster_command', 'color_temp', 'device_class', 'device_state_attributes', 'effect', 'effect_list', 'entity_connect', 'entity_id', 'entity_picture', 'force_update', 'hass', 'hidden', 'hs_color', 'icon', 'is_on', 'max_mireds', 'min_mireds', 'name', 'parallel_updates', 'platform', 'registry_name', 'schedule_update_ha_state', 'should_poll', 'state', 'state_attributes', 'supported_features', 'toggle', 'turn_off', 'turn_on', 'uid', 'unique_id', 'unit_of_measurement', 'update', 'white_value', 'xy_color', 'zdo_command']
May 11 20:03:43 serverbox hass[11984]: 2018-05-11 20:03:43 WARNING (MainThread) [zigpy.util] Error calling listener.attribute_updated: Error binding parameter 4 - probably unsupported type.
May 11 20:03:47 serverbox hass[11984]: 2018-05-11 20:03:47 ERROR (MainThread) [custom_components.zha_new] [0x264c:1] bind output-cluster exception 4
May 11 20:03:47 serverbox hass[11984]: 2018-05-11 20:03:47 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
May 11 20:03:47 serverbox hass[11984]: Traceback (most recent call last):
May 11 20:03:47 serverbox hass[11984]:   File "/opt/homeassistant/config/custom_components/zha_new.py", line 571, in async_device_initialized
May 11 20:03:47 serverbox hass[11984]:     if v[0]:
May 11 20:03:47 serverbox hass[11984]: UnboundLocalError: local variable 'v' referenced before assignment
May 11 20:03:51 serverbox hass[11984]: 2018-05-11 20:03:51 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=85 command=32801 args=[0]
May 11 20:03:53 serverbox hass[11984]: 2018-05-11 20:03:53 DEBUG (MainThread) [custom_components.zha_new] buffer: b'\xf9'

Answer 4 · 2018-05-12T11:14:57.000Z

ok, found some other error for new joining devices. please update and try again

Answer 5 · 2018-05-13T20:21:52.000Z

I think we're getting closer! It looks like it is detecting as a motion sensor now but still some errors.
The ones near the end with 'NoneType' object has no attribute 'data' occur whenever I put my hand in front of the sensor to trigger it.

May 13 16:15:07 serverbox hass[14245]: 2018-05-13 16:15:07 INFO (MainThread) [custom_components.zha_new] Permitting joins for 60s
May 13 16:15:08 serverbox hass[14245]: 2018-05-13 16:15:08 DEBUG (MainThread) [custom_components.zha_new] buffer: b'\xf7'
May 13 16:15:08 serverbox hass[14245]: 2018-05-13 16:15:08 WARNING (MainThread) [bellows.zigbee.application] Unexpected message send notification
May 13 16:15:18 serverbox hass[14245]: 2018-05-13 16:15:18 DEBUG (MainThread) [custom_components.zha_new] Device joined: 00:15:8d:00:01:4d:d5:6c:
May 13 16:15:18 serverbox hass[14245]: 2018-05-13 16:15:18 ERROR (MainThread) [bellows.ezsp] Exception running handler
May 13 16:15:18 serverbox hass[14245]: Traceback (most recent call last):
May 13 16:15:18 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/bellows/ezsp.py", line 194, in handle_callback
May 13 16:15:18 serverbox hass[14245]:     handler(*args)
May 13 16:15:18 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/bellows/zigbee/application.py", line 144, in ezsp_callback_handler
May 13 16:15:18 serverbox hass[14245]:     self._handle_frame(*args)
May 13 16:15:18 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/bellows/zigbee/application.py", line 165, in _handle_frame
May 13 16:15:18 serverbox hass[14245]:     tsn, command_id, is_reply, args = self.deserialize(device, aps_frame.sourceEndpoint, aps_frame.clusterId, message)
May 13 16:15:18 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/zigpy/application.py", line 69, in deserialize
May 13 16:15:18 serverbox hass[14245]:     return sender.deserialize(endpoint_id, cluster_id, data)
May 13 16:15:18 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/zigpy/device.py", line 97, in deserialize
May 13 16:15:18 serverbox hass[14245]:     return self.endpoints[endpoint_id].deserialize(cluster_id, data)
May 13 16:15:18 serverbox hass[14245]: KeyError: 1
May 13 16:15:18 serverbox hass[14245]: 2018-05-13 16:15:18 ERROR (MainThread) [bellows.ezsp] Exception running handler
May 13 16:15:18 serverbox hass[14245]: Traceback (most recent call last):
May 13 16:15:18 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/bellows/ezsp.py", line 194, in handle_callback
May 13 16:15:18 serverbox hass[14245]:     handler(*args)
May 13 16:15:18 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/bellows/zigbee/application.py", line 144, in ezsp_callback_handler
May 13 16:15:18 serverbox hass[14245]:     self._handle_frame(*args)
May 13 16:15:18 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/bellows/zigbee/application.py", line 165, in _handle_frame
May 13 16:15:18 serverbox hass[14245]:     tsn, command_id, is_reply, args = self.deserialize(device, aps_frame.sourceEndpoint, aps_frame.clusterId, message)
May 13 16:15:18 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/zigpy/application.py", line 69, in deserialize
May 13 16:15:18 serverbox hass[14245]:     return sender.deserialize(endpoint_id, cluster_id, data)
May 13 16:15:18 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/zigpy/device.py", line 97, in deserialize
May 13 16:15:18 serverbox hass[14245]:     return self.endpoints[endpoint_id].deserialize(cluster_id, data)
May 13 16:15:18 serverbox hass[14245]: KeyError: 1
May 13 16:15:18 serverbox hass[14245]: 2018-05-13 16:15:18 ERROR (MainThread) [bellows.ezsp] Exception running handler
May 13 16:15:18 serverbox hass[14245]: Traceback (most recent call last):
May 13 16:15:18 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/bellows/ezsp.py", line 194, in handle_callback
May 13 16:15:18 serverbox hass[14245]:     handler(*args)
May 13 16:15:18 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/bellows/zigbee/application.py", line 144, in ezsp_callback_handler
May 13 16:15:18 serverbox hass[14245]:     self._handle_frame(*args)
May 13 16:15:18 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/bellows/zigbee/application.py", line 165, in _handle_frame
May 13 16:15:18 serverbox hass[14245]:     tsn, command_id, is_reply, args = self.deserialize(device, aps_frame.sourceEndpoint, aps_frame.clusterId, message)
May 13 16:15:18 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/zigpy/application.py", line 69, in deserialize
May 13 16:15:18 serverbox hass[14245]:     return sender.deserialize(endpoint_id, cluster_id, data)
May 13 16:15:18 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/zigpy/device.py", line 97, in deserialize
May 13 16:15:18 serverbox hass[14245]:     return self.endpoints[endpoint_id].deserialize(cluster_id, data)
May 13 16:15:18 serverbox hass[14245]: KeyError: 1
May 13 16:15:22 serverbox hass[14245]: 2018-05-13 16:15:22 ERROR (MainThread) [bellows.ezsp] Exception running handler
May 13 16:15:22 serverbox hass[14245]: Traceback (most recent call last):
May 13 16:15:22 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/bellows/ezsp.py", line 194, in handle_callback
May 13 16:15:22 serverbox hass[14245]:     handler(*args)
May 13 16:15:22 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/bellows/zigbee/application.py", line 144, in ezsp_callback_handler
May 13 16:15:22 serverbox hass[14245]:     self._handle_frame(*args)
May 13 16:15:22 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/bellows/zigbee/application.py", line 165, in _handle_frame
May 13 16:15:22 serverbox hass[14245]:     tsn, command_id, is_reply, args = self.deserialize(device, aps_frame.sourceEndpoint, aps_frame.clusterId, message)
May 13 16:15:22 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/zigpy/application.py", line 69, in deserialize
May 13 16:15:22 serverbox hass[14245]:     return sender.deserialize(endpoint_id, cluster_id, data)
May 13 16:15:22 serverbox hass[14245]:   File "/opt/homeassistant/lib/python3.6/site-packages/zigpy/device.py", line 97, in deserialize
May 13 16:15:22 serverbox hass[14245]:     return self.endpoints[endpoint_id].deserialize(cluster_id, data)
May 13 16:15:22 serverbox hass[14245]: KeyError: 1
May 13 16:15:24 serverbox hass[14245]: 2018-05-13 16:15:24 DEBUG (MainThread) [custom_components.zha_new] buffer: b'\xf7'
May 13 16:15:25 serverbox hass[14245]: 2018-05-13 16:15:25 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=4 command=266 args=b'\x05\x00B\x12lumi.sensor_motion'
May 13 16:15:25 serverbox hass[14245]: 2018-05-13 16:15:25 WARNING (MainThread) [zigpy.endpoint] [0xa501:1] Message on unknown cluster 0x0000
May 13 16:15:28 serverbox hass[14245]: 2018-05-13 16:15:28 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=5 command=266 args=b'\x05\x00B\x12lumi.sensor_motion'
May 13 16:15:28 serverbox hass[14245]: 2018-05-13 16:15:28 WARNING (MainThread) [zigpy.endpoint] [0xa501:1] Message on unknown cluster 0x0000
May 13 16:15:29 serverbox hass[14245]: 2018-05-13 16:15:29 DEBUG (MainThread) [custom_components.zha_new] Device initialized: 00:15:8d:00:01:4d:d5:6c:
May 13 16:15:29 serverbox hass[14245]: 2018-05-13 16:15:29 DEBUG (MainThread) [custom_components.zha_new] [0xa501] device init 00:15:8d:00:01:4d:d5:6c: [0, 1]
May 13 16:15:29 serverbox hass[14245]: 2018-05-13 16:15:29 DEBUG (MainThread) [custom_components.zha_new] [0xa501] endpoint init 0
May 13 16:15:29 serverbox hass[14245]: 2018-05-13 16:15:29 DEBUG (MainThread) [custom_components.zha_new] [0xa501] endpoint init 1
May 13 16:15:29 serverbox hass[14245]: 2018-05-13 16:15:29 DEBUG (MainThread) [custom_components.zha_new] [0xa501] node config for 00:15:8d:00:01:4d:d5:6c-1: {}
May 13 16:15:38 serverbox hass[14245]: 2018-05-13 16:15:38 DEBUG (MainThread) [custom_components.zha_new] single read attribute model <[108, 117, 109, 105, 46, 115, 101, 110, 115, 111, 114, 95, 109, 111, 116, 105, 111, 110]>
May 13 16:15:40 serverbox hass[14245]: 2018-05-13 16:15:40 DEBUG (MainThread) [custom_components.zha_new] buffer: b'\xf7'
May 13 16:15:46 serverbox hass[14245]: 2018-05-13 16:15:46 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=8 command=266 args=b'\x00\x00\x18\x01'
May 13 16:15:46 serverbox hass[14245]: 2018-05-13 16:15:46 WARNING (MainThread) [zigpy.endpoint] [0xa501:1] Message on unknown cluster 0x0406
May 13 16:15:51 serverbox hass[14245]: 2018-05-13 16:15:51 DEBUG (MainThread) [custom_components.zha_new] single read attribute failed: manufacturer,
May 13 16:15:51 serverbox hass[14245]: 2018-05-13 16:15:51 DEBUG (MainThread) [custom_components.zha_new] [0xa501] pre call _custom_endpoint_init: {'module': <module 'custom_components.device.lumi_sensor_motion' from '/opt/homeassistant/config/custom_components/device/lumi_sensor_motion.py'>, '_custom_endpoint_init': <function _custom_endpoint_init at 0x7fb5ed7c5ea0>, '_custom_cluster_command': None, '_parse_attribute': <function _parse_attribute at 0x7fb5ed7cb048>, 'custom_parameters': None}
May 13 16:15:51 serverbox hass[14245]: 2018-05-13 16:15:51 DEBUG (MainThread) [custom_components.zha_new] [0xa501] call _custom_endpoint_init: lumi.sensor_motion
May 13 16:15:51 serverbox hass[14245]: 2018-05-13 16:15:51 DEBUG (MainThread) [custom_components.zha_new] [0xa501] node config for 00:15:8d:00:01:4d:d5:6c-1: {'config_report': [[1030, 0, 10, 1800, 1]], 'in_cluster': [0], 'type': 'binary_sensor'}
May 13 16:15:55 serverbox hass[14245]: 2018-05-13 16:15:55 DEBUG (MainThread) [custom_components.zha_new] [0xa501] 00:15:8d:00:01:4d:d5:6c-1: set config report 1030 status: 6
May 13 16:15:55 serverbox hass[14245]: 2018-05-13 16:15:55 DEBUG (MainThread) [custom_components.zha_new] [0xa501] 2:profile 260, component: binary_sensor cluster:({0, 7}, {768, 4, 5, 6, 8})
May 13 16:15:55 serverbox hass[14245]: 2018-05-13 16:15:55 DEBUG (MainThread) [custom_components.zha_new] [0xa501] Output clusters:[4, 5, 6, 8]
May 13 16:15:55 serverbox hass[14245]: 2018-05-13 16:15:55 DEBUG (MainThread) [custom_components.zha_new] [0xa501] Return from component general entity:00:15:8d:00:01:4d:d5:6c
May 13 16:15:55 serverbox hass[14245]: 2018-05-13 16:15:55 DEBUG (MainThread) [custom_components.zha_new] [0xa501:1] Call single-cluster entity: 1030
May 13 16:15:56 serverbox hass[14245]: 2018-05-13 16:15:56 DEBUG (MainThread) [custom_components.zha_new] buffer: b'\xf3'
May 13 16:16:05 serverbox hass[14245]: 2018-05-13 16:16:05 WARNING (MainThread) [homeassistant.components.binary_sensor] Setup of platform zha_new is taking over 10 seconds.
May 13 16:16:05 serverbox hass[14245]: 2018-05-13 16:16:05 WARNING (MainThread) [homeassistant.components.binary_sensor] Setup of platform zha_new is taking over 10 seconds.
May 13 16:16:12 serverbox hass[14245]: 2018-05-13 16:16:12 DEBUG (MainThread) [custom_components.zha_new] buffer: b'\xf3'
May 13 16:16:13 serverbox hass[14245]: 2018-05-13 16:16:13 DEBUG (MainThread) [custom_components.zha_new] dir entity:['__class__', '__delattr__', '__dict__', '__dir__', '__doc__', '__eq__', '__format__', '__ge__', '__getattribute__', '__gt__', '__hash__', '__init__', '__init_subclass__', '__le__', '__lt__', '__module__', '__ne__', '__new__', '__reduce__', '__reduce_ex__', '__repr__', '__setattr__', '__sizeof__', '__str__', '__subclasshook__', '__weakref__', '_application', '_custom_cluster_command', '_custom_module', '_device_state_attributes', '_domain', '_endpoint', '_in_clusters', '_model', '_out_clusters', '_parse_attribute', '_slow_reported', '_state', '_update_staged', 'assumed_state', 'async_device_update', 'async_registry_updated', 'async_remove', 'async_schedule_update_ha_state', 'async_update_ha_state', 'attribute_updated', 'available', 'cluster_command', 'cluster_key', 'device_class', 'device_state_attributes', 'entity_connect', 'entity_id', 'entity_picture', 'force_update', 'hass', 'hidden', 'icon', 'is_on', 'name', 'parallel_updates', 'platform', 'registry_name', 'schedule_update_ha_state', 'should_poll', 'state', 'state_attributes', 'supported_features', 'uid', 'unique_id', 'unit_of_measurement', 'update', 'value_attribute', 'zdo_command']
May 13 16:16:13 serverbox hass[14245]: 2018-05-13 16:16:13 DEBUG (MainThread) [custom_components.zha_new] dir entity:['__class__', '__delattr__', '__dict__', '__dir__', '__doc__', '__eq__', '__format__', '__ge__', '__getattribute__', '__gt__', '__hash__', '__init__', '__init_subclass__', '__le__', '__lt__', '__module__', '__ne__', '__new__', '__reduce__', '__reduce_ex__', '__repr__', '__setattr__', '__sizeof__', '__str__', '__subclasshook__', '__weakref__', '_application', '_custom_cluster_command', '_custom_module', '_device_state_attributes', '_domain', '_endpoint', '_in_clusters', '_model', '_out_clusters', '_parse_attribute', '_slow_reported', '_state', '_update_staged', 'assumed_state', 'async_device_update', 'async_registry_updated', 'async_remove', 'async_schedule_update_ha_state', 'async_update_ha_state', 'attribute_updated', 'available', 'cluster_command', 'cluster_key', 'device_class', 'device_state_attributes', 'entity_connect', 'entity_id', 'entity_picture', 'force_update', 'hass', 'hidden', 'icon', 'invalidate_after', 'is_on', 'name', 'parallel_updates', 'platform', 're_arm_sec', 'registry_name', 'schedule_update_ha_state', 'should_poll', 'state', 'state_attributes', 'supported_features', 'uid', 'unique_id', 'unit_of_measurement', 'update', 'value_attribute', 'zdo_command']
May 13 16:16:16 serverbox hass[14245]: 2018-05-13 16:16:16 ERROR (MainThread) [custom_components.zha_new] [0xa501:1] bind output-cluster exception 5
May 13 16:16:16 serverbox hass[14245]: 2018-05-13 16:16:16 WARNING (MainThread) [zigpy.util] Error calling listener.attribute_updated: 'NoneType' object has no attribute 'data'
May 13 16:16:23 serverbox hass[14245]: 2018-05-13 16:16:23 WARNING (MainThread) [zigpy.util] Error calling listener.attribute_updated: 'NoneType' object has no attribute 'data'
May 13 16:16:28 serverbox hass[14245]: 2018-05-13 16:16:28 DEBUG (MainThread) [custom_components.zha_new] buffer: b'\xf7'
May 13 16:16:30 serverbox hass[14245]: 2018-05-13 16:16:30 ERROR (MainThread) [custom_components.zha_new] [0xa501:1] bind output-cluster exception 8
May 13 16:16:30 serverbox hass[14245]: 2018-05-13 16:16:30 DEBUG (MainThread) [custom_components.zha_new] [0xa501] Exit device init 00:15:8d:00:01:4d:d5:6c
May 13 16:16:36 serverbox hass[14245]: 2018-05-13 16:16:36 WARNING (MainThread) [zigpy.util] Error calling listener.attribute_updated: 'NoneType' object has no attribute 'data'
May 13 16:16:44 serverbox hass[14245]: 2018-05-13 16:16:44 DEBUG (MainThread) [custom_components.zha_new] buffer: b'\xf9'
May 13 16:17:00 serverbox hass[14245]: 2018-05-13 16:17:00 DEBUG (MainThread) [custom_components.zha_new] buffer: b'\xf9'
May 13 16:17:16 serverbox hass[14245]: 2018-05-13 16:17:16 DEBUG (MainThread) [custom_components.zha_new] buffer: b'\xf9'
May 13 16:17:32 serverbox hass[14245]: 2018-05-13 16:17:32 DEBUG (MainThread) [custom_components.zha_new] buffer: b'\xf9'
May 13 16:17:37 serverbox hass[14245]: 2018-05-13 16:17:37 WARNING (MainThread) [zigpy.util] Error calling listener.attribute_updated: 'NoneType' object has no attribute 'data'
May 13 16:17:48 serverbox hass[14245]: 2018-05-13 16:17:48 DEBUG (MainThread) [custom_components.zha_new] buffer: b'\xf9'

Edit: The sensor does show up in the UI and update state to Clear or Detected when I do this, looks like it's working correctly!

Answer 6 · 2018-05-14T14:09:46.000Z

Do you still get this NoneType exceptions while it's working now? I will check if I see the same errors with my xiaomi motion sensor and where they come from.

Answer 7 · 2018-05-14T15:31:56.000Z

It looks like it isn't actually related to motion sensing but it does happen almost exactly every 55 minutes. IIRC that was the regular heartbeat/status message from the device?

May 14 04:09:50 serverbox hass[15326]: 2018-05-14 04:09:50 WARNING (MainThread) [zigpy.util] Error calling listener.attribute_updated: 'NoneType' object has no attribute 'data'
May 14 05:04:50 serverbox hass[15326]: 2018-05-14 05:04:50 WARNING (MainThread) [zigpy.util] Error calling listener.attribute_updated: 'NoneType' object has no attribute 'data'
May 14 05:59:50 serverbox hass[15326]: 2018-05-14 05:59:50 WARNING (MainThread) [zigpy.util] Error calling listener.attribute_updated: 'NoneType' object has no attribute 'data'
May 14 06:56:51 serverbox hass[15326]: 2018-05-14 06:56:51 WARNING (MainThread) [zigpy.util] Error calling listener.attribute_updated: 'NoneType' object has no attribute 'data'
May 14 07:53:01 serverbox hass[15326]: 2018-05-14 07:53:01 WARNING (MainThread) [zigpy.util] Error calling listener.attribute_updated: 'NoneType' object has no attribute 'data'
May 14 08:48:02 serverbox hass[15326]: 2018-05-14 08:48:02 WARNING (MainThread) [zigpy.util] Error calling listener.attribute_updated: 'NoneType' object has no attribute 'data'
May 14 09:43:02 serverbox hass[15326]: 2018-05-14 09:43:02 WARNING (MainThread) [zigpy.util] Error calling listener.attribute_updated: 'NoneType' object has no attribute 'data'

Other than these messages the two sensors I paired are detecting motion as they should.
I was a little curious why it creates both an occupancy sensor which changes from clear to detected on motion, but it also creates an open/close switch which seems to do nothing regardless of motion? I just hid these from my UI so not really a concern, just a curiosity.

Thank you for the quick fixes to get these paired. The pairing process itself is still annoying, some of the issues I faced were because I didn't repeatedly press the reset button until the component completely finished setting up the device. They have stayed paired since the weekend which is a big improvement as they started to drop off my SmartThings hub every day.

Answer 8 · 2018-05-15T11:28:55.000Z

I need to check which update fails.
The second open/close switch is normal. zha and also zha_new, create extra entities for some sensor types.
This "useless" sensor contains information like battery usages and other attributes, where it's unclear what they mean. Thus, you are absolutely fine to hide them from the status view., as they have no benefit to see them.

Answer 9 · 2018-05-17T22:27:41.000Z

I modified the code to reduce the number of created entities.
this useless "switch" is now integrated in the real sensor. Give it a try. just restart after the update.
I found also the reason for the warnings above. the heartbeat sends a list of values in one attribute. writing this list to the database fails, as a list is not one of the native supported type for sqlite
Nothing to worry about. as it not really used for something useful. It is also in the main zha code. If I see a fix from rcloran I may port it.