Exception in callback when joining new node

makuser commented 5 years ago

I tried to join an Aqara Human Motion Sensor to my S2B-Pro coordinator. I therefore woke up the device several times, as you might figure from the numerous errors in the log.

2019-01-13 22:28:42 INFO (MainThread) [homeassistant.components.zha] Permitting joins for 60s
2019-01-13 22:28:50 INFO (MainThread) [zigpy.application] Device 0x49f6 (00:15:8d:00:02:b9:58:1e) joined the network
2019-01-13 22:28:50 INFO (MainThread) [zigpy.device] [0x49f6] Discovering endpoints
Config directory: /config
Tries remaining: 3
2019-01-13 22:28:50 ERROR (MainThread) [homeassistant.core] Error doing job: Exception in callback <bound method SerialTransport._read_ready of SerialTransport(<uvloop.Loop running=True closed=False debug=False>, <zigpy_xbee.uart.Gateway object at 0x7f9551a85080>, Serial<id=0x7f9551a85048, open=True>(port='/dev/zigbee', baudrate=57600, bytesize=8, parity='N', stopbits=1, timeout=0, xonxoff=False, rtscts=False, dsrdtr=False))>
Traceback (most recent call last):
  File "uvloop/cbhandles.pyx", line 62, in uvloop.loop.Handle._run
  File "/usr/local/lib/python3.6/site-packages/serial_asyncio/__init__.py", line 106, in _read_ready
    self._protocol.data_received(data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/uart.py", line 43, in data_received
    self.frame_received(frame)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/uart.py", line 48, in frame_received
    self._api.frame_received(frame)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/api.py", line 207, in frame_received
    getattr(self, '_handle_%s' % (command, ))(data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/api.py", line 230, in _handle_explicit_rx_indicator
    self._app.handle_rx(*data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/zigbee/application.py", line 106, in handle_rx
    tsn, command_id, is_reply, args = self.deserialize(device, src_ep, cluster_id, data)
  File "/usr/local/lib/python3.6/site-packages/zigpy/application.py", line 73, in deserialize
    return sender.deserialize(endpoint_id, cluster_id, data)
  File "/usr/local/lib/python3.6/site-packages/zigpy/device.py", line 97, in deserialize
    return self.endpoints[endpoint_id].deserialize(cluster_id, data)
KeyError: 1
2019-01-13 22:28:51 ERROR (MainThread) [homeassistant.core] Error doing job: Exception in callback <bound method SerialTransport._read_ready of SerialTransport(<uvloop.Loop running=True closed=False debug=False>, <zigpy_xbee.uart.Gateway object at 0x7f9551a85080>, Serial<id=0x7f9551a85048, open=True>(port='/dev/zigbee', baudrate=57600, bytesize=8, parity='N', stopbits=1, timeout=0, xonxoff=False, rtscts=False, dsrdtr=False))>
Traceback (most recent call last):
  File "uvloop/cbhandles.pyx", line 62, in uvloop.loop.Handle._run
  File "/usr/local/lib/python3.6/site-packages/serial_asyncio/__init__.py", line 106, in _read_ready
    self._protocol.data_received(data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/uart.py", line 43, in data_received
    self.frame_received(frame)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/uart.py", line 48, in frame_received
    self._api.frame_received(frame)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/api.py", line 207, in frame_received
    getattr(self, '_handle_%s' % (command, ))(data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/api.py", line 230, in _handle_explicit_rx_indicator
    self._app.handle_rx(*data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/zigbee/application.py", line 106, in handle_rx
    tsn, command_id, is_reply, args = self.deserialize(device, src_ep, cluster_id, data)
  File "/usr/local/lib/python3.6/site-packages/zigpy/application.py", line 73, in deserialize
    return sender.deserialize(endpoint_id, cluster_id, data)
  File "/usr/local/lib/python3.6/site-packages/zigpy/device.py", line 97, in deserialize
    return self.endpoints[endpoint_id].deserialize(cluster_id, data)
KeyError: 1
2019-01-13 22:28:53 ERROR (MainThread) [homeassistant.core] Error doing job: Exception in callback <bound method SerialTransport._read_ready of SerialTransport(<uvloop.Loop running=True closed=False debug=False>, <zigpy_xbee.uart.Gateway object at 0x7f9551a85080>, Serial<id=0x7f9551a85048, open=True>(port='/dev/zigbee', baudrate=57600, bytesize=8, parity='N', stopbits=1, timeout=0, xonxoff=False, rtscts=False, dsrdtr=False))>
Traceback (most recent call last):
  File "uvloop/cbhandles.pyx", line 62, in uvloop.loop.Handle._run
  File "/usr/local/lib/python3.6/site-packages/serial_asyncio/__init__.py", line 106, in _read_ready
    self._protocol.data_received(data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/uart.py", line 43, in data_received
    self.frame_received(frame)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/uart.py", line 48, in frame_received
    self._api.frame_received(frame)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/api.py", line 207, in frame_received
    getattr(self, '_handle_%s' % (command, ))(data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/api.py", line 230, in _handle_explicit_rx_indicator
    self._app.handle_rx(*data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/zigbee/application.py", line 106, in handle_rx
    tsn, command_id, is_reply, args = self.deserialize(device, src_ep, cluster_id, data)
  File "/usr/local/lib/python3.6/site-packages/zigpy/application.py", line 73, in deserialize
    return sender.deserialize(endpoint_id, cluster_id, data)
  File "/usr/local/lib/python3.6/site-packages/zigpy/device.py", line 97, in deserialize
    return self.endpoints[endpoint_id].deserialize(cluster_id, data)
KeyError: 1
2019-01-13 22:28:53 ERROR (MainThread) [homeassistant.core] Error doing job: Exception in callback <bound method SerialTransport._read_ready of SerialTransport(<uvloop.Loop running=True closed=False debug=False>, <zigpy_xbee.uart.Gateway object at 0x7f9551a85080>, Serial<id=0x7f9551a85048, open=True>(port='/dev/zigbee', baudrate=57600, bytesize=8, parity='N', stopbits=1, timeout=0, xonxoff=False, rtscts=False, dsrdtr=False))>
Traceback (most recent call last):
  File "uvloop/cbhandles.pyx", line 62, in uvloop.loop.Handle._run
  File "/usr/local/lib/python3.6/site-packages/serial_asyncio/__init__.py", line 106, in _read_ready
    self._protocol.data_received(data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/uart.py", line 43, in data_received
    self.frame_received(frame)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/uart.py", line 48, in frame_received
    self._api.frame_received(frame)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/api.py", line 207, in frame_received
    getattr(self, '_handle_%s' % (command, ))(data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/api.py", line 230, in _handle_explicit_rx_indicator
    self._app.handle_rx(*data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/zigbee/application.py", line 106, in handle_rx
    tsn, command_id, is_reply, args = self.deserialize(device, src_ep, cluster_id, data)
  File "/usr/local/lib/python3.6/site-packages/zigpy/application.py", line 73, in deserialize
    return sender.deserialize(endpoint_id, cluster_id, data)
  File "/usr/local/lib/python3.6/site-packages/zigpy/device.py", line 97, in deserialize
    return self.endpoints[endpoint_id].deserialize(cluster_id, data)
KeyError: 1
2019-01-13 22:28:58 ERROR (MainThread) [homeassistant.core] Error doing job: Exception in callback <bound method SerialTransport._read_ready of SerialTransport(<uvloop.Loop running=True closed=False debug=False>, <zigpy_xbee.uart.Gateway object at 0x7f9551a85080>, Serial<id=0x7f9551a85048, open=True>(port='/dev/zigbee', baudrate=57600, bytesize=8, parity='N', stopbits=1, timeout=0, xonxoff=False, rtscts=False, dsrdtr=False))>
Traceback (most recent call last):
  File "uvloop/cbhandles.pyx", line 62, in uvloop.loop.Handle._run
  File "/usr/local/lib/python3.6/site-packages/serial_asyncio/__init__.py", line 106, in _read_ready
    self._protocol.data_received(data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/uart.py", line 43, in data_received
    self.frame_received(frame)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/uart.py", line 48, in frame_received
    self._api.frame_received(frame)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/api.py", line 207, in frame_received
    getattr(self, '_handle_%s' % (command, ))(data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/api.py", line 230, in _handle_explicit_rx_indicator
    self._app.handle_rx(*data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/zigbee/application.py", line 106, in handle_rx
    tsn, command_id, is_reply, args = self.deserialize(device, src_ep, cluster_id, data)
  File "/usr/local/lib/python3.6/site-packages/zigpy/application.py", line 73, in deserialize
    return sender.deserialize(endpoint_id, cluster_id, data)
  File "/usr/local/lib/python3.6/site-packages/zigpy/device.py", line 97, in deserialize
    return self.endpoints[endpoint_id].deserialize(cluster_id, data)
KeyError: 1
2019-01-13 22:29:01 ERROR (MainThread) [homeassistant.core] Error doing job: Exception in callback <bound method SerialTransport._read_ready of SerialTransport(<uvloop.Loop running=True closed=False debug=False>, <zigpy_xbee.uart.Gateway object at 0x7f9551a85080>, Serial<id=0x7f9551a85048, open=True>(port='/dev/zigbee', baudrate=57600, bytesize=8, parity='N', stopbits=1, timeout=0, xonxoff=False, rtscts=False, dsrdtr=False))>
Traceback (most recent call last):
  File "uvloop/cbhandles.pyx", line 62, in uvloop.loop.Handle._run
  File "/usr/local/lib/python3.6/site-packages/serial_asyncio/__init__.py", line 106, in _read_ready
    self._protocol.data_received(data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/uart.py", line 43, in data_received
    self.frame_received(frame)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/uart.py", line 48, in frame_received
    self._api.frame_received(frame)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/api.py", line 207, in frame_received
    getattr(self, '_handle_%s' % (command, ))(data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/api.py", line 230, in _handle_explicit_rx_indicator
    self._app.handle_rx(*data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/zigbee/application.py", line 106, in handle_rx
    tsn, command_id, is_reply, args = self.deserialize(device, src_ep, cluster_id, data)
  File "/usr/local/lib/python3.6/site-packages/zigpy/application.py", line 73, in deserialize
    return sender.deserialize(endpoint_id, cluster_id, data)
  File "/usr/local/lib/python3.6/site-packages/zigpy/device.py", line 97, in deserialize
    return self.endpoints[endpoint_id].deserialize(cluster_id, data)
KeyError: 1
Tries remaining: 2
2019-01-13 22:29:03 ERROR (MainThread) [homeassistant.core] Error doing job: Exception in callback <bound method SerialTransport._read_ready of SerialTransport(<uvloop.Loop running=True closed=False debug=False>, <zigpy_xbee.uart.Gateway object at 0x7f9551a85080>, Serial<id=0x7f9551a85048, open=True>(port='/dev/zigbee', baudrate=57600, bytesize=8, parity='N', stopbits=1, timeout=0, xonxoff=False, rtscts=False, dsrdtr=False))>
Traceback (most recent call last):
  File "uvloop/cbhandles.pyx", line 62, in uvloop.loop.Handle._run
  File "/usr/local/lib/python3.6/site-packages/serial_asyncio/__init__.py", line 106, in _read_ready
    self._protocol.data_received(data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/uart.py", line 43, in data_received
    self.frame_received(frame)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/uart.py", line 48, in frame_received
    self._api.frame_received(frame)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/api.py", line 207, in frame_received
    getattr(self, '_handle_%s' % (command, ))(data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/api.py", line 230, in _handle_explicit_rx_indicator
    self._app.handle_rx(*data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/zigbee/application.py", line 106, in handle_rx
    tsn, command_id, is_reply, args = self.deserialize(device, src_ep, cluster_id, data)
  File "/usr/local/lib/python3.6/site-packages/zigpy/application.py", line 73, in deserialize
    return sender.deserialize(endpoint_id, cluster_id, data)
  File "/usr/local/lib/python3.6/site-packages/zigpy/device.py", line 97, in deserialize
    return self.endpoints[endpoint_id].deserialize(cluster_id, data)
KeyError: 1
2019-01-13 22:29:08 ERROR (MainThread) [homeassistant.core] Error doing job: Exception in callback <bound method SerialTransport._read_ready of SerialTransport(<uvloop.Loop running=True closed=False debug=False>, <zigpy_xbee.uart.Gateway object at 0x7f9551a85080>, Serial<id=0x7f9551a85048, open=True>(port='/dev/zigbee', baudrate=57600, bytesize=8, parity='N', stopbits=1, timeout=0, xonxoff=False, rtscts=False, dsrdtr=False))>
Traceback (most recent call last):
  File "uvloop/cbhandles.pyx", line 62, in uvloop.loop.Handle._run
  File "/usr/local/lib/python3.6/site-packages/serial_asyncio/__init__.py", line 106, in _read_ready
    self._protocol.data_received(data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/uart.py", line 43, in data_received
    self.frame_received(frame)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/uart.py", line 48, in frame_received
    self._api.frame_received(frame)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/api.py", line 207, in frame_received
    getattr(self, '_handle_%s' % (command, ))(data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/api.py", line 230, in _handle_explicit_rx_indicator
    self._app.handle_rx(*data)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/zigbee/application.py", line 106, in handle_rx
    tsn, command_id, is_reply, args = self.deserialize(device, src_ep, cluster_id, data)
  File "/usr/local/lib/python3.6/site-packages/zigpy/application.py", line 73, in deserialize
    return sender.deserialize(endpoint_id, cluster_id, data)
  File "/usr/local/lib/python3.6/site-packages/zigpy/device.py", line 97, in deserialize
    return self.endpoints[endpoint_id].deserialize(cluster_id, data)
KeyError: 1
2019-01-13 22:29:09 INFO (MainThread) [zigpy.device] [0x49f6] Discovered endpoints: [1]
2019-01-13 22:29:09 INFO (MainThread) [zigpy.endpoint] [0x49f6:1] Discovering endpoint information
Tries remaining: 3
2019-01-13 22:29:15 WARNING (MainThread) [zigpy_xbee.zigbee.application] Unexpected response TSN=8 command=266 args=b'\x05\x00B\x16lumi.sensor_motion.aq2'
2019-01-13 22:29:15 WARNING (MainThread) [zigpy.endpoint] [0x49f6:1] Message on unknown cluster 0x0000
Tries remaining: 2
2019-01-13 22:29:23 INFO (MainThread) [zigpy.endpoint] [0x49f6:1] Discovered endpoint information: <SimpleDescriptor endpoint=1 profile=260 device_type=263 device_version=1 input_clusters=[0, 65535, 1030, 1024, 1280, 1, 3] output_clusters=[0, 25]>

Adminiuga commented 5 years ago

It is expected to see those exceptions if the device start sending messages before Zigpy finishes endpoint/cluster discovery. The log is cut after

Tries remaining: 2
2019-01-13 22:29:23 INFO (MainThread) [zigpy.endpoint] [0x49f6:1] Discovered endpoint information: <SimpleDescriptor endpoint=1 profile=260 device_type=263 device_version=1 input_clusters=[0, 65535, 1030, 1024, 1280, 1, 3] output_clusters=[0, 25]>

So one try was unsuccessful, but apparently on the 2nd try it got the endpoint information. Question is whether zigpy finished endpoint discovery, usually indicated when you see it probing for different quirks for the newly added device.

PS: also make sure you install zigpy-xbee from github master tree.

makuser commented 5 years ago

It is expected to see those exceptions if the device start sending messages before Zigpy finishes endpoint/cluster discovery. Good to know. Thanks. PS: also make sure you install zigpy-xbee from github master tree. Ha :laughing: I made sure explicitly not to use any of the never versions of the lib, because the recent changes made the library unusable on the Xbee Pro S2B platform, due to the commands that you introduced.

2019-01-14 01:05:53 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry /dev/zigbee for zha
Traceback (most recent call last):
  File "/usr/src/app/homeassistant/config_entries.py", line 252, in async_setup
    result = await component.async_setup_entry(hass, self)
  File "/usr/src/app/homeassistant/components/zha/__init__.py", line 158, in async_setup_entry
    await application_controller.startup(auto_form=True)
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/zigbee/application.py", line 54, in startup
    ce = await self._api._at_command('CE')
  File "/usr/local/lib/python3.6/site-packages/zigpy_xbee/api.py", line 220, in _at_command
    timeout=AT_COMMAND_TIMEOUT)
  File "/usr/local/lib/python3.6/asyncio/tasks.py", line 358, in wait_for
    return fut.result()
Exception: 2

Adminiuga commented 5 years ago

Interesting. I don't have S2B to try, but yep, per documentation ATCE is for S2C XBees. However ATCE frame was present in earlier version of the lib as well. If you are willing to troubleshoot, could you enable debug logging for zigpy_xbee and provide some logs?eg in the logger: section of configuration.yaml add

logger:
  logs:
    zigpy_xbee: debug
    zigpy_xbee.zigbee.application: debug
    zigpy_xbee.api: debug
    zigpy_xbee.uart: debug

Adminiuga commented 5 years ago

@makuser do you know if S2 Pro module is functionally identical to S2B-Pro non-programmable version (the one without additional freescale CPU) I see some relatively cheap S2 Pro modules on ebay.

makuser commented 5 years ago

If you are willing to troubleshoot

Yes, I am. I'll do that tomorrow. I could also give you access to one of my Xbee Pro S2B modules here. I have one as coordinator and one as router. Oh, that's one of the fundamental differences between S2 and S3 btw. In S2 you have different firmwares for the ZigBee roles, in S3 the flash memory was increased so that Digi was able to integrate all three network roles into one single firmware, and have the user decide which features to enable by the use of configuration flags.

CE = Coordinator Enable is one of them AFAIK. A few weeks ago I tested the CE command on a S2B and got no reply.

But let's figure that out tomorrow.

@makuser do you know if S2 Pro module is functionally identical to S2B-Pro non-programmable version (the one without additional freescale CPU) I see some relatively cheap S2 Pro modules on ebay.

They are identical, just not in terms of RF power, etc. By the way: there is a programmable and a non-programmable version of the Xbee Pro S2B. The Pro alone does not mean it's programmable. The S2B has a larger supply voltage range than the non-Pro S2 (2.7-3.6V vs 3.0-3.4V), which is great for mobile applications, for which I originally bought it.

So you would need an Xbee Pro S2 or S2B, as all the previous modules don't speak ZigBee, but only 802.15.4.

Adminiuga commented 5 years ago

Thank you for your explanation. The variety of Xbee modules is pretty confusing, but it makes tons of sense now and explains why zigpy-xbee was implemented the way it was. My guess Russell was using S2/S2B version of the modules so it worked for S2B but not really for the newer S2Cs. And my changes essentially reversed the situation. I've got a programmable S2B-Pro on order to play with and as I understand you could put those into bypass mode.

Adminiuga commented 5 years ago

@makuser can you explain me how you configured the module to work with zigpy-xbee for the very 1st time? I've got XBP24-ZB product family module (Xbee-Pro S2 T?) which I've updated with Zigbee Coordinator API. So we know CE AT command is causing issues we can fix it, but my problem is that AI (association status) is always 0 as in "coordinator started", so zigpy-xbee is not executing form_network() which means it doesn't update EE, EO, KY and NK security parameters. Did you set those manually?

Adminiuga commented 5 years ago

Do I understand correctly those older modules in API mode do not support escape to AT command mode? I couldn't escape in the terminal, despite my baudrate being set correctly.

Adminiuga commented 5 years ago

@makuser what version of firmware are you running on XBee? I have 21A7 (for XBP24-ZB) and I get route_record_indicator frames, which I wasn't getting before and there's no handler for those. Just wanted to check if you get those frame or not. I'm working on an update to make library compatible with both S2C and legacy modules.

prairiesnpr commented 5 years ago

Wait, is this not currently compatible with the S2C? I'm running an S2C as a coordinator and it works well except for joining new devices.

Adminiuga commented 5 years ago

For issues related to S2C open a new issue and provide

version of zigpy_xbee you are using, for S2C you need to be running the master tree
firmware version of XBee module
full debug logs reproducing the issue

Adminiuga commented 4 years ago

Closing due to inactivity.

zigpy / zigpy-xbee

Exception in callback when joining new node #22