search

zigpy / bellows

A Python 3 project to implement EZSP for EmberZNet devices
GNU General Public License v3.0
182 stars 86 forks source link

Invalid EmberOutgoingMessageType on permit (EZSP 5) #18

Closed rcloran closed 7 years ago

rcloran commented 7 years ago

https://community.home-assistant.io/t/one-zigbee-gateway-to-rule-them-all/16803/30

Exception:

ERROR:homeassistant.core:Error doing job: Exception in callback SerialTransport.readready()
Traceback (most recent call last):
File "/usr/lib/python3.4/asyncio/events.py", line 120, in _run
self._callback(*self.args)
File "/opt/hass/.homeassistant/deps/serial_asyncio/__init__.py", line 106, in readready
self.protocol.data_received(data)
File "/opt/hass/.homeassistant/deps/bellows/uart.py", line 61, in data_received
self.frame_received(frame)
File "/opt/hass/.homeassistant/deps/bellows/uart.py", line 73, in frame_received
self.data_frame_received(data)
File "/opt/hass/.homeassistant/deps/bellows/uart.py", line 94, in data_frame_received
self._application.frame_received(self._randomize(data[1:-3]))
File "/opt/hass/.homeassistant/deps/bellows/ezsp.py", line 179, in frame_received
result, data = t.deserialize(data, schema)
File "/opt/hass/.homeassistant/deps/bellows/types/__init__.py", line 9, in deserialize
value, data = type_.deserialize(data)
File "/opt/hass/.homeassistant/deps/bellows/types/basic.py", line 13, in deserialize
r = cls(int.from_bytes(data[:cls._size], 'little', signed=cls._signed))
File "/usr/lib/python3.4/enum.py", line 222, in __call__
return cls.__new__(cls, value)
File "/usr/lib/python3.4/enum.py", line 457, in __new__
raise ValueError("%r is not a valid %s" % (value, cls.__name__))
ValueError: 6 is not a valid EmberOutgoingMessageType
MindrustUK commented 7 years ago

Hi,

As requested output below:

debug: Using selector: EpollSelector
debug: Loading application state from zigbee.db
debug: Sending: b'1ac038bc7e'
debug: RSTACK Version: 2 Reason: RESET_SOFTWARE frame: b'c1020b0a527e'
debug: Send command version
debug: Sending: b'004221a850ed2c7e'
debug: Data frame: b'0142a1a8512805ebd87b7e'
debug: Sending: b'8160597e'
debug: Application frame 0 (version) received
debug: Switching to eszp version 5
debug: Send command version
debug: Sending: b'7d31432157542a1025c57e'
debug: Data frame: b'1243a157542a10b049cd89937e'
debug: Sending: b'82503a7e'
debug: Application frame 0 (version) received
debug: Send command setConfigurationValue
debug: Sending: b'22402157547919b059c46e7e'
debug: Data frame: b'2340a157547915fbd27e'
debug: Sending: b'83401b7e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command setConfigurationValue
debug: Sending: b'3341215754797d38b75995c77e'
debug: Data frame: b'3441a157547915904d7e'
debug: Sending: b'8430fc7e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command setConfigurationValue
debug: Sending: b'44462157547938b35902ad7e'
debug: Data frame: b'4546a157547915640c7e'
debug: Sending: b'8520dd7e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command setConfigurationValue
debug: Sending: b'55472157547938b359fda37e'
debug: Data frame: b'5647a157547915ce557e'
debug: Sending: b'8610be7e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command setConfigurationValue
debug: Sending: b'6644215754793fb1590f627e'
debug: Data frame: b'6744a157547915e1597e'
debug: Sending: b'87009f7e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command setConfigurationValue
debug: Sending: b'7745215754790cb0595fa87e'
debug: Data frame: b'7045a1575479158ac67e'
debug: Sending: b'8070787e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command setConfigurationValue
debug: Sending: b'004a21575479144d597d33457e'
debug: Data frame: b'014aa15754791573c57e'
debug: Sending: b'8160597e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command networkInit
debug: Sending: b'7d314b2157543d7d33827e'
debug: Data frame: b'124ba557543d1591927e'
debug: Sending: b'82503a7e'
debug: Application frame 23 (networkInit) received
debug: Data frame: b'224bb157543385e5f57e'
debug: Sending: b'83401b7e'
debug: Application frame 25 (stackStatusHandler) received
debug: Send command getNetworkParameters
debug: Sending: b'2348215754029e207e'
debug: Data frame: b'3348a157540215b35e64e824545a9fdc873dd9a5edce678bfd3e9c8e338b7e'
debug: Sending: b'8430fc7e'
debug: Application frame 40 (getNetworkParameters) received
debug: Send command setPolicy
debug: Sending: b'34492157547f10e2190d7e'
debug: Data frame: b'4449a157547f15b3c87e'
debug: Sending: b'8520dd7e'
debug: Application frame 85 (setPolicy) received
debug: Send command setPolicy
debug: Sending: b'454e2157547f7d33d384b77e'
debug: Data frame: b'554ea157547f15f4937e'
debug: Sending: b'8610be7e'
debug: Application frame 85 (setPolicy) received
debug: Send command setPolicy
debug: Sending: b'564f2157547f15b30f177e'
debug: Data frame: b'664fa157547f15303c7e'
debug: Sending: b'87009f7e'
debug: Application frame 85 (setPolicy) received
debug: Send command getNodeId
debug: Sending: b'674c2157540d8a787e'
debug: Data frame: b'774ca157540d15b299477e'
debug: Sending: b'8070787e'
debug: Application frame 39 (getNodeId) received
debug: Send command getEui64
debug: Sending: b'704d2157540ce2cd7e'
debug: Data frame: b'004da157540ccf0450944a86885562477e'
debug: Sending: b'8160597e'
debug: Application frame 38 (getEui64) received
debug: Send command permitJoining
debug: Sending: b'0152215754080b8e447e'
debug: Data frame: b'1152a15754081568107e'
debug: Sending: b'82503a7e'
debug: Application frame 34 (permitJoining) received
Joins are permitted for the next 30s...
debug: Data frame: b'2152b157546f11b259874a25aa5593499c7dd84d0af29874f11a84b5058df1a7eb40cb6f0167d97e'
debug: Sending: b'83401b7e'
debug: Application frame 69 (incomingMessageHandler) received
debug: [0x3ce7:zdo] ZDO request 0x0013: [15591, 00:15:8d:00:00:ce:f3:f9, 142]
debug: Data frame: b'3152b157546f10b2598b4a25aa5592499c4fd8abedce9874f7476287ee47c158bcc6de711d7e'
debug: Sending: b'8430fc7e'
debug: Application frame 69 (incomingMessageHandler) received
debug: No such device 0
warning: Unknown ZDO cluster 0x1f
warning: Message on unknown device 0x0000
debug: Data frame: b'4152b1575415134ea6944a3aaa5592499c4e27aaedce67b8cd7e'
debug: Sending: b'8520dd7e'
debug: Application frame 63 (messageSentHandler) received
Exception in callback SerialTransport._read_ready()
handle: <Handle SerialTransport._read_ready()>
Traceback (most recent call last):
  File "/usr/lib/python3.4/asyncio/events.py", line 120, in _run
    self._callback(*self._args)
  File "/usr/local/lib/python3.4/dist-packages/pyserial_asyncio-0.4-py3.4.egg/serial_asyncio/__init__.py", line 106, in _read_ready
    self._protocol.data_received(data)
  File "/usr/local/lib/python3.4/dist-packages/bellows-0.2.7-py3.4.egg/bellows/uart.py", line 61, in data_received
    self.frame_received(frame)
  File "/usr/local/lib/python3.4/dist-packages/bellows-0.2.7-py3.4.egg/bellows/uart.py", line 73, in frame_received
    self.data_frame_received(data)
  File "/usr/local/lib/python3.4/dist-packages/bellows-0.2.7-py3.4.egg/bellows/uart.py", line 94, in data_frame_received
    self._application.frame_received(self._randomize(data[1:-3]))
  File "/usr/local/lib/python3.4/dist-packages/bellows-0.2.7-py3.4.egg/bellows/ezsp.py", line 179, in frame_received
    result, data = t.deserialize(data, schema)
  File "/usr/local/lib/python3.4/dist-packages/bellows-0.2.7-py3.4.egg/bellows/types/__init__.py", line 9, in deserialize
    value, data = type_.deserialize(data)
  File "/usr/local/lib/python3.4/dist-packages/bellows-0.2.7-py3.4.egg/bellows/types/basic.py", line 13, in deserialize
    r = cls(int.from_bytes(data[:cls._size], 'little', signed=cls._signed))
  File "/usr/lib/python3.4/enum.py", line 222, in __call__
    return cls.__new__(cls, value)
  File "/usr/lib/python3.4/enum.py", line 457, in __new__
    raise ValueError("%r is not a valid %s" % (value, cls.__name__))
ValueError: 6 is not a valid EmberOutgoingMessageType

Done
rcloran commented 7 years ago

Should be fixed by #24. Thanks @AndreasBomholtz!

MindrustUK commented 7 years ago

Looks like it's still failing to me:

bellows -v debug -d /dev/ttyUSB1 permit -D zigbee.db
debug: Using selector: EpollSelector
debug: Loading application state from zigbee.db
debug: Sending: b'1ac038bc7e'
debug: RSTACK Version: 2 Reason: RESET_SOFTWARE frame: b'c1020b0a527e'
debug: Send command version
debug: Sending: b'004221a850ed2c7e'
debug: Data frame: b'0142a1a8512805ebd87b7e'
debug: Sending: b'8160597e'
debug: Application frame 0 (version) received
debug: Switching to eszp version 5
debug: Send command version
debug: Sending: b'7d31432157542a1025c57e'
debug: Data frame: b'1243a157542a10b049cd89937e'
debug: Sending: b'82503a7e'
debug: Application frame 0 (version) received
debug: Send command setConfigurationValue
debug: Sending: b'22402157547919b059c46e7e'
debug: Data frame: b'2340a157547915fbd27e'
debug: Sending: b'83401b7e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command setConfigurationValue
debug: Sending: b'3341215754797d38b75995c77e'
debug: Data frame: b'3441a157547915904d7e'
debug: Sending: b'8430fc7e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command setConfigurationValue
debug: Sending: b'44462157547938b35902ad7e'
debug: Data frame: b'4546a157547915640c7e'
debug: Sending: b'8520dd7e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command setConfigurationValue
debug: Sending: b'5547215754793fb1591e517e'
debug: Data frame: b'5647a157547915ce557e'
debug: Sending: b'8610be7e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command setConfigurationValue
debug: Sending: b'6644215754790cb059a0a67e'
debug: Data frame: b'6744a157547915e1597e'
debug: Sending: b'87009f7e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command setConfigurationValue
debug: Sending: b'774521575479144d59d0f77e'
debug: Data frame: b'7045a1575479158ac67e'
debug: Sending: b'8070787e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command networkInit
debug: Sending: b'004a2157543de6f77e'
debug: Data frame: b'014aa557543d153bcb7e'
debug: Sending: b'8160597e'
debug: Application frame 23 (networkInit) received
debug: Data frame: b'114ab157543385215a7e'
debug: Sending: b'82503a7e'
debug: Application frame 25 (stackStatusHandler) received
debug: Send command getNetworkParameters
debug: Sending: b'124b215754027d3ade7e'
debug: Data frame: b'224ba157540215b35e64e824545a9fdc873dd9a5edce678bfd3e9c8e41b77e'
debug: Sending: b'83401b7e'
debug: Application frame 40 (getNetworkParameters) received
debug: Send command setPolicy
debug: Sending: b'23482157547f10e25bc07e'
debug: Data frame: b'3348a157547f156b4d7e'
debug: Sending: b'8430fc7e'
debug: Application frame 85 (setPolicy) received
debug: Send command setPolicy
debug: Sending: b'34492157547f7d33d36a2c7e'
debug: Data frame: b'4449a157547f15b3c87e'
debug: Sending: b'8520dd7e'
debug: Application frame 85 (setPolicy) received
debug: Send command setPolicy
debug: Sending: b'454e2157547f15b342b77e'
debug: Data frame: b'554ea157547f15f4937e'
debug: Sending: b'8610be7e'
debug: Application frame 85 (setPolicy) received
debug: Send command getNodeId
debug: Sending: b'564f2157540d0e867e'
debug: Data frame: b'664fa157540d15b23ba27e'
debug: Sending: b'87009f7e'
debug: Application frame 39 (getNodeId) received
debug: Send command getEui64
debug: Sending: b'674c2157540c9a597e'
debug: Data frame: b'774ca157540ccf0450944a86885527a57e'
debug: Sending: b'8070787e'
debug: Application frame 38 (getEui64) received
debug: Send command permitJoining
debug: Sending: b'704d215754080b6dc37e'
debug: Data frame: b'004da157540815388d7e'
debug: Sending: b'8160597e'
debug: Application frame 34 (permitJoining) received
Joins are permitted for the next 30s...
debug: Data frame: b'104db157546f11b259874a25aa5593499c18d84d0af29874f12584b5058df1a7eb40cb6f01ae497e'
debug: Sending: b'82503a7e'
debug: Application frame 69 (incomingMessageHandler) received
debug: No such device 15591
warning: Message on unknown device 0x3ce7
debug: Data frame: b'204db157546f10b2598b4a25aa5592499cb1d8abedce9874f7476287ee47c158bcc6def9d87e'
debug: Sending: b'83401b7e'
debug: Application frame 69 (incomingMessageHandler) received
debug: No such device 0
warning: Unknown ZDO cluster 0x1f
warning: Message on unknown device 0x0000
debug: Data frame: b'304db1575415134ea6944a3aaa5592499c4e2754edce67835f7e'
debug: Sending: b'8430fc7e'
debug: Application frame 63 (messageSentHandler) received
warning: Unexpected message send notification
^C
Aborted!

From HASS

DEBUG:bellows.zigbee.appdb:Loading application state from /opt/hass/zigbee.db
DEBUG:bellows.uart:Sending: b'1ac038bc7e'
DEBUG:bellows.uart:RSTACK Version: 2 Reason: RESET_SOFTWARE frame: b'c1020b0a527e'
DEBUG:bellows.ezsp:Send command version
DEBUG:bellows.uart:Sending: b'004221a850ed2c7e'
DEBUG:bellows.uart:Data frame: b'0142a1a8512805ebd87b7e'
DEBUG:bellows.uart:Sending: b'8160597e'
DEBUG:bellows.ezsp:Application frame 0 (version) received
DEBUG:bellows.ezsp:Switching to eszp version 5
DEBUG:bellows.ezsp:Send command version
DEBUG:bellows.uart:Sending: b'7d31432157542a1025c57e'
DEBUG:bellows.uart:Data frame: b'1243a157542a10b049cd89937e'
DEBUG:bellows.uart:Sending: b'82503a7e'
DEBUG:bellows.ezsp:Application frame 0 (version) received
DEBUG:bellows.ezsp:Send command setConfigurationValue
DEBUG:bellows.uart:Sending: b'22402157547919b059c46e7e'
DEBUG:bellows.uart:Data frame: b'2340a157547915fbd27e'
DEBUG:bellows.uart:Sending: b'83401b7e'
DEBUG:bellows.ezsp:Application frame 83 (setConfigurationValue) received
DEBUG:bellows.ezsp:Send command setConfigurationValue
DEBUG:bellows.uart:Sending: b'3341215754797d38b75995c77e'
DEBUG:bellows.uart:Data frame: b'3441a157547915904d7e'
DEBUG:bellows.uart:Sending: b'8430fc7e'
DEBUG:bellows.ezsp:Application frame 83 (setConfigurationValue) received
DEBUG:bellows.ezsp:Send command setConfigurationValue
DEBUG:bellows.uart:Sending: b'44462157547938b35902ad7e'
DEBUG:bellows.uart:Data frame: b'4546a157547915640c7e'
DEBUG:bellows.uart:Sending: b'8520dd7e'
DEBUG:bellows.ezsp:Application frame 83 (setConfigurationValue) received
DEBUG:bellows.ezsp:Send command setConfigurationValue
DEBUG:bellows.uart:Sending: b'55472157547938b359fda37e'
DEBUG:bellows.uart:Data frame: b'5647a157547915ce557e'
DEBUG:bellows.uart:Sending: b'8610be7e'
DEBUG:bellows.ezsp:Application frame 83 (setConfigurationValue) received
DEBUG:bellows.ezsp:Send command setConfigurationValue
DEBUG:bellows.uart:Sending: b'6644215754793fb1590f627e'
DEBUG:bellows.uart:Data frame: b'6744a157547915e1597e'
DEBUG:bellows.uart:Sending: b'87009f7e'
DEBUG:bellows.ezsp:Application frame 83 (setConfigurationValue) received
DEBUG:bellows.ezsp:Send command setConfigurationValue
DEBUG:bellows.uart:Sending: b'7745215754790cb0595fa87e'
DEBUG:bellows.uart:Data frame: b'7045a1575479158ac67e'
DEBUG:bellows.uart:Sending: b'8070787e'
DEBUG:bellows.ezsp:Application frame 83 (setConfigurationValue) received
DEBUG:bellows.ezsp:Send command setConfigurationValue
DEBUG:bellows.uart:Sending: b'004a21575479144d597d33457e'
DEBUG:bellows.uart:Data frame: b'014aa15754791573c57e'
DEBUG:bellows.uart:Sending: b'8160597e'
DEBUG:bellows.ezsp:Application frame 83 (setConfigurationValue) received
DEBUG:bellows.ezsp:Send command networkInit
DEBUG:bellows.uart:Sending: b'7d314b2157543d7d33827e'
DEBUG:bellows.uart:Data frame: b'124ba557543d1591927e'
DEBUG:bellows.uart:Sending: b'82503a7e'
DEBUG:bellows.ezsp:Application frame 23 (networkInit) received
DEBUG:bellows.uart:Data frame: b'224bb157543385e5f57e'
DEBUG:bellows.uart:Sending: b'83401b7e'
DEBUG:bellows.ezsp:Application frame 25 (stackStatusHandler) received
DEBUG:bellows.ezsp:Send command getNetworkParameters
DEBUG:bellows.uart:Sending: b'2348215754029e207e'
DEBUG:bellows.uart:Data frame: b'3348a157540215b35e64e824545a9fdc873dd9a5edce678bfd3e9c8e338b7e'
DEBUG:bellows.uart:Sending: b'8430fc7e'
DEBUG:bellows.ezsp:Application frame 40 (getNetworkParameters) received
DEBUG:bellows.ezsp:Send command setPolicy
DEBUG:bellows.uart:Sending: b'34492157547f10e2190d7e'
DEBUG:bellows.uart:Data frame: b'4449a157547f15b3c87e'
DEBUG:bellows.uart:Sending: b'8520dd7e'
DEBUG:bellows.ezsp:Application frame 85 (setPolicy) received
DEBUG:bellows.ezsp:Send command setPolicy
DEBUG:bellows.uart:Sending: b'454e2157547f7d33d384b77e'
DEBUG:bellows.uart:Data frame: b'554ea157547f15f4937e'
DEBUG:bellows.uart:Sending: b'8610be7e'
DEBUG:bellows.ezsp:Application frame 85 (setPolicy) received
DEBUG:bellows.ezsp:Send command setPolicy
DEBUG:bellows.uart:Sending: b'564f2157547f15b30f177e'
DEBUG:bellows.uart:Data frame: b'664fa157547f15303c7e'
DEBUG:bellows.uart:Sending: b'87009f7e'
DEBUG:bellows.ezsp:Application frame 85 (setPolicy) received
DEBUG:bellows.ezsp:Send command getNodeId
DEBUG:bellows.uart:Sending: b'674c2157540d8a787e'
DEBUG:bellows.uart:Data frame: b'774ca157540d15b299477e'
DEBUG:bellows.uart:Sending: b'8070787e'
DEBUG:bellows.ezsp:Application frame 39 (getNodeId) received
DEBUG:bellows.ezsp:Send command getEui64
DEBUG:bellows.uart:Sending: b'704d2157540ce2cd7e'
DEBUG:bellows.uart:Data frame: b'004da157540ccf0450944a86885562477e'
DEBUG:bellows.uart:Sending: b'8160597e'
DEBUG:bellows.ezsp:Application frame 38 (getEui64) received
INFO:homeassistant.core:Bus:Handling <Event service_registered[L]: service=permit, domain=zha>
INFO:homeassistant.core:Bus:Handling <Event component_loaded[L]: component=zha>
DEBUG:bellows.ezsp:Send command sendUnicast
DEBUG:bellows.uart:Sending: b'01522157541e155565ca8a25aa5493099d4e27aaecc9678afdc2638cfc45067e'
DEBUG:bellows.uart:Data frame: b'1152a157541e1549d5807e'
DEBUG:bellows.uart:Sending: b'82503a7e'
DEBUG:bellows.ezsp:Application frame 52 (sendUnicast) received
DEBUG:bellows.uart:Data frame: b'2152b1575415155565ca8a25aa5493099c4e2750eca867e9227e'
DEBUG:bellows.uart:Sending: b'83401b7e'
DEBUG:bellows.ezsp:Application frame 63 (messageSentHandler) received
ERROR:homeassistant.core:Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/lib/python3.4/asyncio/tasks.py", line 233, in _step
    result = coro.throw(exc)
  File "/usr/local/lib/python3.4/dist-packages/homeassistant/components/zha/__init__.py", line 142, in async_device_initialized
    discovered_info = yield from _discover_endpoint_info(endpoint)
  File "/usr/local/lib/python3.4/dist-packages/homeassistant/components/zha/__init__.py", line 269, in _discover_endpoint_info
    allow_cache=True,
  File "/opt/hass/.homeassistant/deps/bellows/zigbee/zcl/__init__.py", line 182, in read_attributes
    result = yield from self.read_attributes_raw(to_read)
  File "/opt/hass/.homeassistant/deps/bellows/zigbee/zcl/__init__.py", line 149, in read_attributes_raw
    v = yield from self.request(True, 0x00, schema, attributes)
  File "/opt/hass/.homeassistant/deps/bellows/zigbee/application.py", line 257, in request
    v = yield from send_fut
  File "/usr/lib/python3.4/asyncio/futures.py", line 388, in __iter__
    yield self  # This tells Task to wait for completion.
  File "/usr/lib/python3.4/asyncio/tasks.py", line 286, in _wakeup
    value = future.result()
  File "/usr/lib/python3.4/asyncio/futures.py", line 277, in result
    raise self._exception
Exception: Message send failure: EmberStatus.DELIVERY_FAILED
INFO:homeassistant.bootstrap:Home Assistant initialized in 14.78s
INFO:homeassistant.core:Starting Home Assistant core loop
INFO:homeassistant.core:Starting Home Assistant
INFO:homeassistant.core:Bus:Handling <Event homeassistant_start[L]>
INFO:homeassistant.core:Timer:starting
INFO:homeassistant.components.http:Serving / to 192.168.100.2 (auth: True)
INFO:homeassistant.components.http:Serving /api/websocket to 192.168.100.2 (auth: True)
INFO:homeassistant.core:Bus:Handling <Event call_service[L]: service_call_id=1978791472-1, service_data=, service=permit, domain=zha>
INFO:homeassistant.components.zha:Permitting joins for 60s
DEBUG:bellows.ezsp:Send command permitJoining
DEBUG:bellows.uart:Sending: b'7d33532157540829985c7e'
DEBUG:bellows.uart:Data frame: b'3253a1575408159bc47e'
DEBUG:bellows.uart:Sending: b'8430fc7e'
DEBUG:bellows.ezsp:Application frame 34 (permitJoining) received
INFO:homeassistant.core:Bus:Handling <Event service_executed[L]: service_call_id=1978791472-1>
DEBUG:bellows.uart:Data frame: b'4253b157546f10b2598b4a25aa5592499c4ed8abedce9874f7476287ee47c158bcc6deceb47e'
DEBUG:bellows.uart:Sending: b'8520dd7e'
DEBUG:bellows.ezsp:Application frame 69 (incomingMessageHandler) received
DEBUG:bellows.zigbee.application:No such device 0
WARNING:bellows.zigbee.zdo:Unknown ZDO cluster 0x1f
WARNING:bellows.zigbee.application:Message on unknown device 0x0000
DEBUG:bellows.uart:Data frame: b'5253b1575415134ea6944a3aaa5592499c4e27abeda8679d467e'
DEBUG:bellows.uart:Sending: b'8610be7e'
DEBUG:bellows.ezsp:Application frame 63 (messageSentHandler) received
ERROR:homeassistant.core:Error doing job: Exception in callback SerialTransport._read_ready()
Traceback (most recent call last):
  File "/usr/lib/python3.4/asyncio/events.py", line 120, in _run
    self._callback(*self._args)
  File "/opt/hass/.homeassistant/deps/serial_asyncio/__init__.py", line 106, in _read_ready
    self._protocol.data_received(data)
  File "/opt/hass/.homeassistant/deps/bellows/uart.py", line 61, in data_received
    self.frame_received(frame)
  File "/opt/hass/.homeassistant/deps/bellows/uart.py", line 73, in frame_received
    self.data_frame_received(data)
  File "/opt/hass/.homeassistant/deps/bellows/uart.py", line 94, in data_frame_received
    self._application.frame_received(self._randomize(data[1:-3]))
  File "/opt/hass/.homeassistant/deps/bellows/ezsp.py", line 179, in frame_received
    result, data = t.deserialize(data, schema)
  File "/opt/hass/.homeassistant/deps/bellows/types/__init__.py", line 9, in deserialize
    value, data = type_.deserialize(data)
  File "/opt/hass/.homeassistant/deps/bellows/types/basic.py", line 13, in deserialize
    r = cls(int.from_bytes(data[:cls._size], 'little', signed=cls._signed))
  File "/usr/lib/python3.4/enum.py", line 222, in __call__
    return cls.__new__(cls, value)
  File "/usr/lib/python3.4/enum.py", line 457, in __new__
    raise ValueError("%r is not a valid %s" % (value, cls.__name__))
ValueError: 6 is not a valid EmberOutgoingMessageType
DEBUG:bellows.uart:Data frame: b'6253b157546f11b259874a25aa5593499c36d94e0af29874f1db84b5058df1a7eb40cb6f0143a27e'
DEBUG:bellows.uart:Sending: b'87009f7e'
DEBUG:bellows.ezsp:Application frame 69 (incomingMessageHandler) received
DEBUG:bellows.zigbee.zdo:[0x3ce7:zdo] ZDO request 0x0013: [15591, 00:15:8d:00:00:ce:f3:f9, 142]
^CINFO:homeassistant.core:Bus:Handling <Event homeassistant_stop[L]>
INFO:homeassistant.core:Bus:Handling <Event homeassistant_close[L]>
rcloran commented 7 years ago

653c74b4598090397fe642f944660160f3b44cf6 fixes a typo in the EmberOutgoingMessageType enum. But that shouldn't affect it.

This definitely works for me on Python 3.4,

In [1]: import bellows.types as t

In [2]: t.EmberOutgoingMessageType.deserialize(b'\x06')
Out[2]: (<EmberOutgoingMessageType.OUTGOING_BROADCAST: 6>, b'')

All your line numbers suggest your bellows in /opt/hass/.homeassistant/deps/bellows is up to date, but can you verify this for me, please?

grep OUTGOING_ /opt/hass/.homeassistant/deps/bellows/types/named.py

I can't think what could be causing this other than that file not being updated :-/

MindrustUK commented 7 years ago

Ok, just blatted everything and brought it up to date to be sure as I suspect there maybe some version problems, currently getting this error on startup:

INFO:homeassistant.setup:Setting up zha
DEBUG:bellows.zigbee.appdb:Loading application state from /opt/hass/zigbee.db
DEBUG:bellows.uart:Sending: b'\x1a\xc08\xbc~'
DEBUG:bellows.uart:RSTACK frame: b'\xc1\x02\x0b\nR~'
DEBUG:bellows.ezsp:Send command version
DEBUG:bellows.uart:Sending: b'\x00B!\xa8P\xed,~'
DEBUG:bellows.uart:Data frame: b'\x01B\xa1\xa8Q(\x05\xeb\xd8{~'
DEBUG:bellows.uart:Sending: b'\x81`Y~'
DEBUG:bellows.ezsp:Application frame 0 (version) received
DEBUG:bellows.ezsp:Send command setConfigurationValue
DEBUG:bellows.uart:Sending: b"}1C!\xfbX(\x15\xc3'~"
DEBUG:bellows.uart:Data frame: b'\x12C\xa1WT\xa3`~'
DEBUG:bellows.uart:Sending: b'\x82P:~'
ERROR:homeassistant.core:Error doing job: Exception in callback SerialTransport._read_ready()
Traceback (most recent call last):
  File "/usr/lib/python3.4/asyncio/events.py", line 120, in _run
    self._callback(*self._args)
  File "/opt/hass/.homeassistant/deps/serial_asyncio/__init__.py", line 106, in _read_ready
    self._protocol.data_received(data)
  File "/opt/hass/.homeassistant/deps/bellows/uart.py", line 54, in data_received
    self.frame_received(frame)
  File "/opt/hass/.homeassistant/deps/bellows/uart.py", line 64, in frame_received
    self.data_frame_received(data)
  File "/opt/hass/.homeassistant/deps/bellows/uart.py", line 84, in data_frame_received
    self._application.frame_received(self._randomize(data[1:-3]))
  File "/opt/hass/.homeassistant/deps/bellows/ezsp.py", line 144, in frame_received
    frame_name = self.COMMANDS_BY_ID[frame_id][0]
KeyError: 255
WARNING:homeassistant.setup:Setup of zha is taking over 10 seconds.

Also output as requested:

    VALUE_MAXIMUM_OUTGOING_TRANSFER_SIZE = 0x06
    OUTGOING_DIRECT = 0x00
    OUTGOING_VIA_ADDRESS_TABLE = 0x01
    OUTGOING_VIA_BINDING = 0x02
    OUTGOING_MULTICAST = 0x03
    OUTGOING_BROADCAST = 0x04
    KEY_HAS_OUTGOING_FRAME_COUNTER = 0x0002
rcloran commented 7 years ago

You now have very old bellows, without any of the fixes. If you want to test whether the fixes work, you have to apply them.

rcloran commented 7 years ago

I will update hass to require 0.3.1 soon - the code for that is at https://github.com/rcloran/home-assistant/tree/bellows-split-cluster - I just need to wait for home-assistant/home-assistant#8308 and home-assistant/home-assistant#8310 to be merged.

MindrustUK commented 7 years ago

Yup I screwed that up, fixed it now. Think the code issue is resolved, looks like a HASS issue now:

DEBUG:bellows.uart:Data frame: b'3348a157547f156b4d7e'
DEBUG:bellows.uart:Sending: b'8430fc7e'
DEBUG:bellows.ezsp:Application frame 85 (setPolicy) received
DEBUG:bellows.ezsp:Send command setPolicy
DEBUG:bellows.uart:Sending: b'34492157547f7d33d36a2c7e'
DEBUG:bellows.uart:Data frame: b'4449a157547f15b3c87e'
DEBUG:bellows.uart:Sending: b'8520dd7e'
DEBUG:bellows.ezsp:Application frame 85 (setPolicy) received
DEBUG:bellows.ezsp:Send command setPolicy
DEBUG:bellows.uart:Sending: b'454e2157547f15b342b77e'
DEBUG:bellows.uart:Data frame: b'554ea157547f15f4937e'
DEBUG:bellows.uart:Sending: b'8610be7e'
DEBUG:bellows.ezsp:Application frame 85 (setPolicy) received
DEBUG:bellows.ezsp:Send command getNodeId
DEBUG:bellows.uart:Sending: b'564f2157540d0e867e'
DEBUG:bellows.uart:Data frame: b'664fa157540d15b23ba27e'
DEBUG:bellows.uart:Sending: b'87009f7e'
DEBUG:bellows.ezsp:Application frame 39 (getNodeId) received
DEBUG:bellows.ezsp:Send command getEui64
DEBUG:bellows.uart:Sending: b'674c2157540c9a597e'
DEBUG:bellows.uart:Data frame: b'774ca157540ccf0450944a86885527a57e'
DEBUG:bellows.uart:Sending: b'8070787e'
DEBUG:bellows.ezsp:Application frame 38 (getEui64) received
INFO:homeassistant.core:Bus:Handling <Event service_registered[L]: domain=zha, service=permit>
INFO:homeassistant.core:Bus:Handling <Event component_loaded[L]: component=zha>
ERROR:homeassistant.core:Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/lib/python3.4/asyncio/tasks.py", line 237, in _step
    result = next(coro)
  File "/usr/local/lib/python3.4/dist-packages/homeassistant/components/zha/__init__.py", line 136, in async_device_initialized
    zha_const.populate_data()
  File "/usr/local/lib/python3.4/dist-packages/homeassistant/components/zha/const.py", line 51, in populate_data
    COMPONENT_CLUSTERS[component].update(clusters)
TypeError: unhashable type: 'list'
INFO:homeassistant.bootstrap:Home Assistant initialized in 7.35s
INFO:homeassistant.core:Starting Home Assistant core loop
INFO:homeassistant.core:Starting Home Assistant
INFO:homeassistant.core:Bus:Handling <Event homeassistant_start[L]>
rcloran commented 7 years ago

Right - 8a999039a5583d4600a1407b7fa5beaab42f7b46 changes the bellows API, and is unfortunately before the EmberOutgoingMessageType fix.

The easiest is going to be to wait for https://github.com/rcloran/home-assistant/tree/bellows-split-cluster in hass, but you should be able to apply it to your hass cleanly.

You could also try to revert 8a999039a5583d4600a1407b7fa5beaab42f7b46 from your bellows.