zigpy / bellows

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

ValueError: 153 is not a valid EzspStatus #58

Closed halkeye closed 6 years ago

halkeye commented 7 years ago

Not sure what is useful for debugging, so including the entire stack trace.

I'm really just playing around with the HUSBZB-1 and seeing if i can't add some random zigbee devices I have.

(homeassistant) homeassistant@hassbian:~/bellows $ bellows -v debug -d /dev/zigbee permit -D ~/.homeassistant/zigb
ee.db
debug: Using selector: EpollSelector
debug: Loading application state from /home/homeassistant/.homeassistant/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'0142a1a8502805e67f627e'
debug: Sending: b'8160597e'
debug: Application frame 0 (version) received
debug: Send command setConfigurationValue
debug: Sending: b'7d314321fb582815c3277e'
debug: Data frame: b'1243a1fb54fb737e'
debug: Sending: b'82503a7e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command setConfigurationValue
debug: Sending: b'224021fb592f15226f7e'
debug: Data frame: b'2340a1fb54c6107e'
debug: Sending: b'83401b7e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command setConfigurationValue
debug: Sending: b'334121fb792b15a2d77e'
debug: Data frame: b'3441a1fb54d32a7e'
debug: Sending: b'8430fc7e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command setConfigurationValue
debug: Sending: b'444621fb7d5e291514417e'
debug: Data frame: b'4546a1fb5435d07e'
debug: Sending: b'8520dd7e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command setConfigurationValue
debug: Sending: b'554721fb4d2815713f7e'
debug: Data frame: b'5647a1fb54a9ec7e'
debug: Sending: b'8610be7e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command setConfigurationValue
debug: Sending: b'664421fb55d515b18f7e'
debug: Data frame: b'6744a1fb54948f7e'
debug: Sending: b'87009f7e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command setConfigurationValue
debug: Sending: b'774521fb4a2b1524a97e'
debug: Data frame: b'7045a1fb5481b57e'
debug: Sending: b'8070787e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command networkInit
debug: Sending: b'004a21bf3d4f7e'
debug: Data frame: b'014aa5bf54ff447e'
debug: Sending: b'8160597e'
debug: Application frame 23 (networkInit) received
debug: Data frame: b'114ab1b1c4c40b7e'
debug: Sending: b'82503a7e'
debug: Application frame 25 (stackStatusHandler) received
debug: Send command getNetworkParameters
debug: Sending: b'124b21803b0c7e'
debug: Data frame: b'224ba180542b55c97796e28907ec5a55944127abedce677302c11fac7e'
debug: Sending: b'83401b7e'
debug: Application frame 40 (getNetworkParameters) received
debug: Send command setPolicy
debug: Sending: b'234821fd517ae4177e'
debug: Data frame: b'3348a1fd54ed2f7e'
debug: Sending: b'8430fc7e'
debug: Application frame 85 (setPolicy) received
debug: Send command setPolicy
debug: Sending: b'344921fd524befa27e'
debug: Data frame: b'4449a1fd54e1c97e'
debug: Sending: b'8520dd7e'
debug: Application frame 85 (setPolicy) received
debug: Send command setPolicy
debug: Sending: b'454e21fd542b4e4a7e'
debug: Data frame: b'554ea1fd541eef7e'
debug: Sending: b'8610be7e'
debug: Application frame 85 (setPolicy) received
debug: Send command getNodeId
debug: Sending: b'564f218fb24e7e'
debug: Data frame: b'664fa18f542a64827e'
debug: Sending: b'87009f7e'
debug: Application frame 39 (getNodeId) received
debug: Send command getEui64
debug: Sending: b'674c218ea1627e'
debug: Data frame: b'4ca18e03cd07b959fb4725aebd7e'
debug: Sending: b'8520dd7e'
debug: Application frame 171 (setValue) 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 "/srv/homeassistant/lib/python3.4/site-packages/serial_asyncio/__init__.py", line 106, in _read_ready
    self._protocol.data_received(data)
  File "/home/homeassistant/bellows/bellows/uart.py", line 61, in data_received
    self.frame_received(frame)
  File "/home/homeassistant/bellows/bellows/uart.py", line 73, in frame_received
    self.data_frame_received(data)
  File "/home/homeassistant/bellows/bellows/uart.py", line 94, in data_frame_received
    self._application.frame_received(self._randomize(data[1:-3]))
  File "/home/homeassistant/bellows/bellows/ezsp.py", line 179, in frame_received
    result, data = t.deserialize(data, schema)
  File "/home/homeassistant/bellows/bellows/types/__init__.py", line 9, in deserialize
    value, data = type_.deserialize(data)
  File "/home/homeassistant/bellows/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: 153 is not a valid EzspStatus
debug: NAK frame: b'a18e03cd07b959fb4725b5157e'
debug: Data frame: b'7f4ca18e03cd07b959fb4725b5157e'
debug: Sending: b'8070787e'
debug: Application frame 38 (getEui64) received
debug: Send command permitJoining
debug: Sending: b'704d218a4af7bb7e'
debug: Data frame: b'004da18a5422987e'
debug: Sending: b'8160597e'
debug: Application frame 34 (permitJoining) received
Joins are permitted for the next 30s...
Done

If i run it again i'm getting

debug: Application frame 83 (setConfigurationValue) received
debug: Send command setConfigurationValue
debug: Sending: b'224021fb592f15226f7e'
debug: Data frame: b'40a1fb54c6107e'
debug: Sending: b'8520dd7e'
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 "/srv/homeassistant/lib/python3.4/site-packages/serial_asyncio/__init__.py", line 106, in _read_ready
    self._protocol.data_received(data)
  File "/home/homeassistant/bellows/bellows/uart.py", line 61, in data_received
    self.frame_received(frame)
  File "/home/homeassistant/bellows/bellows/uart.py", line 73, in frame_received
    self.data_frame_received(data)
  File "/home/homeassistant/bellows/bellows/uart.py", line 94, in data_frame_received
    self._application.frame_received(self._randomize(data[1:-3]))
  File "/home/homeassistant/bellows/bellows/ezsp.py", line 164, in frame_received
    frame_name = self.COMMANDS_BY_ID[frame_id][0]
KeyError: 252
halkeye commented 7 years ago

If i wanted to start writing patches for this, what should i do?

AndreasBomholtz commented 7 years ago

@halkeye Just create a Pull Request.

halkeye commented 7 years ago

Sorry I mean how can I debug this?

Like how do I get started

AndreasBomholtz commented 7 years ago

Check out the code. Run 'python3 setup.py develop'. Try to add some more debug printing. Try to reproduce the problem.

Hope this helps.

rcloran commented 7 years ago
debug: Send command getEui64
debug: Sending: b'674c218ea1627e'
debug: Data frame: b'4ca18e03cd07b959fb4725aebd7e'
debug: Sending: b'8520dd7e'
debug: Application frame 171 (setValue) 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 "/srv/homeassistant/lib/python3.4/site-packages/serial_asyncio/__init__.py", line 106, in _read_ready
    self._protocol.data_received(data)
  File "/home/homeassistant/bellows/bellows/uart.py", line 61, in data_received
    self.frame_received(frame)
  File "/home/homeassistant/bellows/bellows/uart.py", line 73, in frame_received
    self.data_frame_received(data)
  File "/home/homeassistant/bellows/bellows/uart.py", line 94, in data_frame_received
    self._application.frame_received(self._randomize(data[1:-3]))
  File "/home/homeassistant/bellows/bellows/ezsp.py", line 179, in frame_received
    result, data = t.deserialize(data, schema)
  File "/home/homeassistant/bellows/bellows/types/__init__.py", line 9, in deserialize
    value, data = type_.deserialize(data)
  File "/home/homeassistant/bellows/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: 153 is not a valid EzspStatus
debug: NAK frame: b'a18e03cd07b959fb4725b5157e'

Wow, something is very weird here -- the NCP shouldn't be responding to getEUI64 with setValue. If I had to guess, I'd say data is somehow being corrupted on the wire. I haven't decoded the setValue frame that's received by hand to examine what's going on, but I bet that the first improvement here would be to validate the CRC on the frame received from EZSP and act accordingly if it's wrong.

AndreasBomholtz commented 7 years ago

I found a way to reproduce this issue. I will test it tomorrow and try to see if it is a crc issue.

Den 15. okt. 2017 19.45 skrev "Russell Cloran" notifications@github.com:

debug: Send command getEui64 debug: Sending: b'674c218ea1627e' debug: Data frame: b'4ca18e03cd07b959fb4725aebd7e' debug: Sending: b'8520dd7e' debug: Application frame 171 (setValue) 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 "/srv/homeassistant/lib/python3.4/site-packages/serial_asyncio/init.py", line 106, in _read_ready self._protocol.data_received(data) File "/home/homeassistant/bellows/bellows/uart.py", line 61, in data_received self.frame_received(frame) File "/home/homeassistant/bellows/bellows/uart.py", line 73, in frame_received self.data_frame_received(data) File "/home/homeassistant/bellows/bellows/uart.py", line 94, in data_frame_received self._application.frame_received(self._randomize(data[1:-3])) File "/home/homeassistant/bellows/bellows/ezsp.py", line 179, in framereceived result, data = t.deserialize(data, schema) File "/home/homeassistant/bellows/bellows/types/init.py", line 9, in deserialize value, data = type.deserialize(data) File "/home/homeassistant/bellows/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: 153 is not a valid EzspStatus debug: NAK frame: b'a18e03cd07b959fb4725b5157e'

Wow, something is very weird here -- the NCP shouldn't be responding to getEUI64 with setValue. If I had to guess, I'd say data is somehow being corrupted on the wire. I haven't decoded the setValue frame that's received by hand to examine what's going on, but I bet that the first improvement here would be to validate the CRC on the frame received from EZSP and act accordingly if it's wrong.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/rcloran/bellows/issues/58#issuecomment-336728269, or mute the thread https://github.com/notifications/unsubscribe-auth/AIa7l2i3xQleoJ3h-qRUzVMXG9TC4H8Eks5sskTVgaJpZM4PmHoi .

AndreasBomholtz commented 7 years ago

@halkeye Can you try to test with my PR with the new CRC check?

halkeye commented 7 years ago

I'll have to keep poking at it over the next couple days. I forgot how i triggered it. Its certainly not happening anymore with my smartthings motion sensor gen 1, but i forgot how to tell my blinds to go into join mode.

I think its nicer now.