search

zigpy / zigpy-znp

TI CC2531, CC13x2, CC26x2 radio support for Zigpy and ZHA
GNU General Public License v3.0
145 stars 40 forks source link

ZNP issue after upgrading to fw CC2652RB_20210128 #63

Closed julnobugs closed 3 years ago

julnobugs commented 3 years ago

Hi,

I hope this is the right place for this. I did migrate recently to the CC2652RB from slae.sh. I was running on firmware version CC2652RB_20201026.

As lost recently connectivity with all zigbee devices, I tried the last recommended version of the koenkk's fw for CC2652R Upgrade was successful but after replugging, restarting home-assistant (core hosted on hassos), seems that HA is unable to communicate properly with the coordinator anymore: 2021-02-02 00:02:37 ERROR (MainThread) [zigpy.application] Couldn't start application 2021-02-02 00:02:37 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start ZNP = Texas Instruments Z-Stack ZNP protocol: CC253x, CC26x2, CC13x2 coordinator Traceback (most recent call last)

Detailed logs:

2021-02-02 00:02:19 DEBUG (MainThread) [zigpy_znp.uart] Connecting to /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_0A_BD-if00-port0 at 115200 baud
2021-02-02 00:02:19 DEBUG (MainThread) [zigpy_znp.uart] Opened /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_0A_BD-if00-port0 serial port
2021-02-02 00:02:19 DEBUG (MainThread) [zigpy_znp.uart] Toggling RTS/CTS to skip CC2652R bootloader
2021-02-02 00:02:19 DEBUG (MainThread) [zigpy_znp.uart] Received data: b'\x00'
2021-02-02 00:02:20 DEBUG (MainThread) [zigpy_znp.uart] Received data: b'\x00'
2021-02-02 00:02:20 DEBUG (MainThread) [zigpy_znp.uart] Connected to /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_0A_BD-if00-port0 at 115200 baud
2021-02-02 00:02:20 DEBUG (MainThread) [zigpy_znp.api] Waiting 1s before sending anything
2021-02-02 00:02:21 DEBUG (MainThread) [zigpy_znp.api] Sending bootloader skip byte
2021-02-02 00:02:21 DEBUG (MainThread) [zigpy_znp.uart] Sending data: b'\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF'
2021-02-02 00:02:21 DEBUG (MainThread) [zigpy_znp.api] Waiting 1s or until a reset indication is received
2021-02-02 00:02:21 DEBUG (MainThread) [zigpy_znp.api] Creating one-shot listener OneShotResponseListener(matching_commands=(SYS.ResetInd.Callback(Reason=None, TransportRev=None, ProductId=None, MajorRel=None, MinorRel=None, MaintRel=None),), future=<Future pending cb=[ZNP.wait_for_responses.<locals>.<lambda>() at /usr/local/lib/python3.8/site-packages/zigpy_znp/api.py:436, <TaskWakeupMethWrapper object at 0x69c4dc70>()]>)
2021-02-02 00:02:22 DEBUG (MainThread) [zigpy_znp.api] Removing listener OneShotResponseListener(matching_commands=(SYS.ResetInd.Callback(Reason=None, TransportRev=None, ProductId=None, MajorRel=None, MinorRel=None, MaintRel=None),), future=<Future cancelled>)
2021-02-02 00:02:22 DEBUG (MainThread) [zigpy_znp.api] Cleaning up empty listener list for header CommandHeader(id=0x80, subsystem=Subsystem.SYS, type=CommandType.AREQ)
2021-02-02 00:02:22 DEBUG (MainThread) [zigpy_znp.api] There are 0 callbacks and 0 one-shot listeners remaining
2021-02-02 00:02:22 DEBUG (MainThread) [zigpy_znp.api] Testing connection to /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_0A_BD-if00-port0
2021-02-02 00:02:22 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Version.Req()
2021-02-02 00:02:22 DEBUG (MainThread) [zigpy_znp.api] Creating one-shot listener OneShotResponseListener(matching_commands=(SYS.Version.Rsp(TransportRev=None, ProductId=None, MajorRel=None, MinorRel=None, MaintRel=None, CodeRevision=None, BootloaderBuildType=None, BootloaderRevision=None), RPCError.CommandNotRecognized.Rsp(ErrorCode=None, RequestHeader=CommandHeader(id=0x02, subsystem=Subsystem.SYS, type=CommandType.SREQ))), future=<Future pending cb=[ZNP.wait_for_responses.<locals>.<lambda>() at /usr/local/lib/python3.8/site-packages/zigpy_znp/api.py:436, <TaskWakeupMethWrapper object at 0x69c4d958>()]>)
2021-02-02 00:02:22 DEBUG (MainThread) [zigpy_znp.uart] Sending data: b'\xFE\x00\x21\x02\x23'
2021-02-02 00:02:29 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.processor_use, old_state=<state sensor.processor_use=3; unit_of_measurement=%, friendly_name=Processor use (percent), icon=mdi:cpu-32-bit @ 2021-02-02T00:01:59.547391-05:00>, new_state=<state sensor.processor_use=7; unit_of_measurement=%, friendly_name=Processor use (percent), icon=mdi:cpu-32-bit @ 2021-02-02T00:02:29.550944-05:00>>
2021-02-02 00:02:29 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.memory_use_percent, old_state=<state sensor.memory_use_percent=44.4; unit_of_measurement=%, friendly_name=Memory use (percent), icon=mdi:memory @ 2021-02-02T00:01:59.559425-05:00>, new_state=<state sensor.memory_use_percent=44.6; unit_of_measurement=%, friendly_name=Memory use (percent), icon=mdi:memory @ 2021-02-02T00:02:29.564764-05:00>>
2021-02-02 00:02:29 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.swap_free, old_state=<state sensor.swap_free=223.7; unit_of_measurement=MiB, friendly_name=Swap free, icon=mdi:harddisk @ 2021-02-01T23:58:29.552396-05:00>, new_state=<state sensor.swap_free=223.5; unit_of_measurement=MiB, friendly_name=Swap free, icon=mdi:harddisk @ 2021-02-02T00:02:29.578521-05:00>>
2021-02-02 00:02:37 DEBUG (MainThread) [zigpy_znp.api] Removing listener OneShotResponseListener(matching_commands=(SYS.Version.Rsp(TransportRev=None, ProductId=None, MajorRel=None, MinorRel=None, MaintRel=None, CodeRevision=None, BootloaderBuildType=None, BootloaderRevision=None), RPCError.CommandNotRecognized.Rsp(ErrorCode=None, RequestHeader=CommandHeader(id=0x02, subsystem=Subsystem.SYS, type=CommandType.SREQ))), future=<Future cancelled>)
2021-02-02 00:02:37 DEBUG (MainThread) [zigpy_znp.api] Cleaning up empty listener list for header CommandHeader(id=0x00, subsystem=Subsystem.RPCError, type=CommandType.SRSP)
2021-02-02 00:02:37 DEBUG (MainThread) [zigpy_znp.api] Cleaning up empty listener list for header CommandHeader(id=0x02, subsystem=Subsystem.SYS, type=CommandType.SRSP)
2021-02-02 00:02:37 DEBUG (MainThread) [zigpy_znp.api] There are 0 callbacks and 0 one-shot listeners remaining
2021-02-02 00:02:37 DEBUG (MainThread) [zigpy_znp.api] Connection to /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_0A_BD-if00-port0 failed, cleaning up
2021-02-02 00:02:37 ERROR (MainThread) [zigpy.application] Couldn't start application
2021-02-02 00:02:37 DEBUG (MainThread) [zigpy_znp.uart] Closing serial port
2021-02-02 00:02:37 DEBUG (MainThread) [zigpy_znp.api] We were disconnected from /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_0A_BD-if00-port0: None
2021-02-02 00:02:37 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start ZNP = Texas Instruments Z-Stack ZNP protocol: CC253x, CC26x2, CC13x2 coordinator
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/zigpy_znp/api.py", line 507, in request
    response = await response_future
asyncio.exceptions.CancelledError
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 157, in async_initialize
    self.application_controller = await app_controller_cls.new(
  File "/usr/local/lib/python3.8/site-packages/zigpy/application.py", line 69, in new
    await app.startup(auto_form)
  File "/usr/local/lib/python3.8/site-packages/zigpy_znp/zigbee/application.py", line 206, in startup
    return await self._startup(auto_form=auto_form)
  File "/usr/local/lib/python3.8/site-packages/zigpy_znp/zigbee/application.py", line 215, in _startup
    await znp.connect()
  File "/usr/local/lib/python3.8/site-packages/zigpy_znp/api.py", line 234, in connect
    self._version = await self.request(c.SYS.Version.Req())
  File "/usr/local/lib/python3.8/site-packages/zigpy_znp/api.py", line 507, in request
    response = await response_future
  File "/usr/local/lib/python3.8/site-packages/async_timeout/__init__.py", line 55, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.8/site-packages/async_timeout/__init__.py", line 92, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError

Output of the first sucessfull flash with JelmerT python script:

cc2538-bsl.py -p COM3 -evw CC2652RB_20210128.hex
Opening port COM3, baud 500000
Reading data from CC2652RB_20210128.hex
Your firmware looks like an Intel Hex file
Connecting to target...
CC1350 PG2.0 (7x7mm): 352KB Flash, 20KB SRAM, CCFG.BL_CONFIG at 0x00057FD8
Primary IEEE Address: 00:12:4B:00:21:CC:0A:BD
    Performing mass erase
Erasing all main bank flash sectors
    Erase done
Writing 360448 bytes starting at address 0x00000000
Write 104 bytes at 0x00057F980
    Write done
Verifying by comparing CRC32 calculations.
    Verified (match: 0x4ae3081e)

Seeing the issue with HA, did then flash successfully with SmartRF Flash Programmer 2:

>Initiate access to target: COM3 using 2-pin cJTAG.
>Reading file: C:/Users/Julien/CloudSync/SOFTS/HA/CC2652RB_20210128.hex.
>Start flash erase ...
>Erase finished successfully.
>Start flash programming ...
>Programming finished successfully.
>Start flash verify ...
>Skip verification of unassigned page: 23.
>Skip verification of unassigned page: 24.
>Skip verification of unassigned page: 25.
>Skip verification of unassigned page: 26.
>Skip verification of unassigned page: 27.
>Skip verification of unassigned page: 28.
>Skip verification of unassigned page: 29.
>Skip verification of unassigned page: 30.
>Skip verification of unassigned page: 31.
>Skip verification of unassigned page: 32.
>Skip verification of unassigned page: 33.
>Skip verification of unassigned page: 34.
>Skip verification of unassigned page: 35.
>Skip verification of unassigned page: 36.
>Skip verification of unassigned page: 37.
>Skip verification of unassigned page: 38.
>Skip verification of unassigned page: 39.
>Skip verification of unassigned page: 40.
>Skip verification of unassigned page: 41.
>Skip verification of unassigned page: 42.
>Page: 0 verified OK.
>Page: 1 verified OK.
>Page: 2 verified OK.
>Page: 3 verified OK.
>Page: 4 verified OK.
>Page: 5 verified OK.
>Page: 6 verified OK.
>Page: 7 verified OK.
>Page: 8 verified OK.
>Page: 9 verified OK.
>Page: 10 verified OK.
>Page: 11 verified OK.
>Page: 12 verified OK.
>Page: 13 verified OK.
>Page: 14 verified OK.
>Page: 15 verified OK.
>Page: 16 verified OK.
>Page: 17 verified OK.
>Page: 18 verified OK.
>Page: 19 verified OK.
>Page: 20 verified OK.
>Page: 21 verified OK.
>Page: 22 verified OK.
>Page: 43 verified OK.
>Verification finished successfully.
>Reset target ...
>Reset of target successful.

HA details: core-2021.1.5 supervisor-2021.01.7 HassOS 4.17

Any help to troubleshoot this will be greatly appreciated =)

puddly commented 3 years ago

I've not seen a coordinator send null bytes like this before so this is a little strange:

2021-02-02 00:02:19 DEBUG (MainThread) [zigpy_znp.uart] Received data: b'\x00'
2021-02-02 00:02:20 DEBUG (MainThread) [zigpy_znp.uart] Received data: b'\x00'

To rule out a bad flash, does downgrading the firmware back to the version you were previously using work? Very little changes between Koenkk's Z-Stack builds so I would not expect this to break, especially when I'm running the same version myself on the LAUNCHXL-CC1352P-2 board.

julnobugs commented 3 years ago

Thanks a lot for your answer puddy. After downgrading, communication with the coordinator is restored but seems I did loose the pairing with all my zigbee devices (routers and end devices) unfortunately.

2021-02-02 01:09:18 DEBUG (MainThread) [zigpy_znp.uart] Connecting to /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_0A_BD-if00-port0 at 115200 baud
2021-02-02 01:09:18 DEBUG (MainThread) [zigpy_znp.uart] Opened /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_0A_BD-if00-port0 serial port
2021-02-02 01:09:18 DEBUG (MainThread) [zigpy_znp.uart] Toggling RTS/CTS to skip CC2652R bootloader
2021-02-02 01:09:18 DEBUG (MainThread) [zigpy_znp.uart] Received data: b'\x00'
2021-02-02 01:09:19 DEBUG (MainThread) [zigpy_znp.uart] Received data: b'\x00'
2021-02-02 01:09:19 DEBUG (MainThread) [zigpy_znp.uart] Connected to /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_0A_BD-if00-port0 at 115200 baud
2021-02-02 01:09:19 DEBUG (MainThread) [zigpy_znp.api] Waiting 1s before sending anything
2021-02-02 01:09:20 DEBUG (MainThread) [zigpy_znp.api] Sending bootloader skip byte
2021-02-02 01:09:20 DEBUG (MainThread) [zigpy_znp.uart] Sending data: b'\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF\xEF'
2021-02-02 01:09:20 DEBUG (MainThread) [zigpy_znp.api] Waiting 1s or until a reset indication is received
2021-02-02 01:09:20 DEBUG (MainThread) [zigpy_znp.api] Creating one-shot listener OneShotResponseListener(matching_commands=(SYS.ResetInd.Callback(Reason=None, TransportRev=None, ProductId=None, MajorRel=None, MinorRel=None, MaintRel=None),), future=<Future pending cb=[ZNP.wait_for_responses.<locals>.<lambda>() at /usr/local/lib/python3.8/site-packages/zigpy_znp/api.py:436, <TaskWakeupMethWrapper object at 0x69e50820>()]>)
2021-02-02 01:09:20 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event hacs/status[L]>
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.uart] Received data: b'\xFE\x06\x41\x80\x00\x02\x01\x02\x07\x01\xC0'
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.uart] Parsed frame: TransportFrame(payload=GeneralFrame(header=CommandHeader(id=0x80, subsystem=Subsystem.SYS, type=CommandType.AREQ), data=b'\x00\x02\x01\x02\x07\x01'))
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.ResetInd.Callback(Reason=<ResetReason.PowerUp: 0>, TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] SYS.ResetInd.Callback(Reason=<ResetReason.PowerUp: 0>, TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1) matches OneShotResponseListener(matching_commands=(SYS.ResetInd.Callback(Reason=None, TransportRev=None, ProductId=None, MajorRel=None, MinorRel=None, MaintRel=None),), future=<Future finished result=SYS.ResetInd....7, MaintRel=1)>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Removing listener OneShotResponseListener(matching_commands=(SYS.ResetInd.Callback(Reason=None, TransportRev=None, ProductId=None, MajorRel=None, MinorRel=None, MaintRel=None),), future=<Future finished result=SYS.ResetInd....7, MaintRel=1)>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Cleaning up empty listener list for header CommandHeader(id=0x80, subsystem=Subsystem.SYS, type=CommandType.AREQ)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] There are 0 callbacks and 0 one-shot listeners remaining
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Testing connection to /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_0A_BD-if00-port0
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Version.Req()
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Creating one-shot listener OneShotResponseListener(matching_commands=(SYS.Version.Rsp(TransportRev=None, ProductId=None, MajorRel=None, MinorRel=None, MaintRel=None, CodeRevision=None, BootloaderBuildType=None, BootloaderRevision=None), RPCError.CommandNotRecognized.Rsp(ErrorCode=None, RequestHeader=CommandHeader(id=0x02, subsystem=Subsystem.SYS, type=CommandType.SREQ))), future=<Future pending cb=[ZNP.wait_for_responses.<locals>.<lambda>() at /usr/local/lib/python3.8/site-packages/zigpy_znp/api.py:436, <TaskWakeupMethWrapper object at 0x69269dd8>()]>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.uart] Received data: b'\xFE\x0A\x61\x02\x02\x01\x02\x07\x01\x42\x3E\x34\x01\x00\x27'
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.uart] Parsed frame: TransportFrame(payload=GeneralFrame(header=CommandHeader(id=0x02, subsystem=Subsystem.SYS, type=CommandType.SRSP), data=b'\x02\x01\x02\x07\x01\x42\x3E\x34\x01\x00'))
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Version.Rsp(TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1, CodeRevision=20201026, BootloaderBuildType=<BootloaderBuildType.NON_BOOTLOADER_BUILD: 0>, BootloaderRevision=None)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] SYS.Version.Rsp(TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1, CodeRevision=20201026, BootloaderBuildType=<BootloaderBuildType.NON_BOOTLOADER_BUILD: 0>, BootloaderRevision=None) matches OneShotResponseListener(matching_commands=(SYS.Version.Rsp(TransportRev=None, ProductId=None, MajorRel=None, MinorRel=None, MaintRel=None, CodeRevision=None, BootloaderBuildType=None, BootloaderRevision=None), RPCError.CommandNotRecognized.Rsp(ErrorCode=None, RequestHeader=CommandHeader(id=0x02, subsystem=Subsystem.SYS, type=CommandType.SREQ))), future=<Future finished result=SYS.Version.R...Revision=None)>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Removing listener OneShotResponseListener(matching_commands=(SYS.Version.Rsp(TransportRev=None, ProductId=None, MajorRel=None, MinorRel=None, MaintRel=None, CodeRevision=None, BootloaderBuildType=None, BootloaderRevision=None), RPCError.CommandNotRecognized.Rsp(ErrorCode=None, RequestHeader=CommandHeader(id=0x02, subsystem=Subsystem.SYS, type=CommandType.SREQ))), future=<Future finished result=SYS.Version.R...Revision=None)>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Cleaning up empty listener list for header CommandHeader(id=0x00, subsystem=Subsystem.RPCError, type=CommandType.SRSP)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Cleaning up empty listener list for header CommandHeader(id=0x02, subsystem=Subsystem.SYS, type=CommandType.SRSP)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] There are 0 callbacks and 0 one-shot listeners remaining
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Creating one-shot listener OneShotResponseListener(matching_commands=(SYS.Ping.Rsp(Capabilities=None), RPCError.CommandNotRecognized.Rsp(ErrorCode=None, RequestHeader=CommandHeader(id=0x01, subsystem=Subsystem.SYS, type=CommandType.SREQ))), future=<Future finished result=SYS.Ping.Rsp(...AP_SYS: 1625>)>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.uart] Sending data: b'\xFE\x00\x21\x01\x20'
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.uart] Received data: b'\xFE\x02\x61\x01\x59\x06\x3D'
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.uart] Parsed frame: TransportFrame(payload=GeneralFrame(header=CommandHeader(id=0x01, subsystem=Subsystem.SYS, type=CommandType.SRSP), data=b'\x59\x06'))
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.CAP_APP_CNF|CAP_GP|CAP_UTIL|CAP_ZDO|CAP_AF|CAP_SYS: 1625>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] SYS.Ping.Rsp(Capabilities=<MTCapabilities.CAP_APP_CNF|CAP_GP|CAP_UTIL|CAP_ZDO|CAP_AF|CAP_SYS: 1625>) matches OneShotResponseListener(matching_commands=(SYS.Ping.Rsp(Capabilities=None), RPCError.CommandNotRecognized.Rsp(ErrorCode=None, RequestHeader=CommandHeader(id=0x01, subsystem=Subsystem.SYS, type=CommandType.SREQ))), future=<Future finished result=SYS.Ping.Rsp(...AP_SYS: 1625>)>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Removing listener OneShotResponseListener(matching_commands=(SYS.Ping.Rsp(Capabilities=None), RPCError.CommandNotRecognized.Rsp(ErrorCode=None, RequestHeader=CommandHeader(id=0x01, subsystem=Subsystem.SYS, type=CommandType.SREQ))), future=<Future finished result=SYS.Ping.Rsp(...AP_SYS: 1625>)>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Cleaning up empty listener list for header CommandHeader(id=0x00, subsystem=Subsystem.RPCError, type=CommandType.SRSP)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Cleaning up empty listener list for header CommandHeader(id=0x01, subsystem=Subsystem.SYS, type=CommandType.SRSP)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] There are 0 callbacks and 0 one-shot listeners remaining
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Connected to /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_0A_BD-if00-port0 at 115200 baud
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Creating callback CallbackResponseListener(matching_commands=(AF.IncomingMsg.Callback(GroupId=None, ClusterId=None, SrcAddr=None, SrcEndpoint=None, DstEndpoint=None, WasBroadcast=None, LQI=None, SecurityUse=None, TimeStamp=None, TSN=None, Data=None, MacSrcAddr=None, MsgResultRadius=None),), callback=<bound method ControllerApplication.on_af_message of <zigpy_znp.zigbee.application.ControllerApplication object at 0x7079d610>>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Creating callback CallbackResponseListener(matching_commands=(ZDO.EndDeviceAnnceInd.Callback(Src=None, NWK=None, IEEE=None, Capabilities=None),), callback=<bound method ControllerApplication.on_zdo_device_announce of <zigpy_znp.zigbee.application.ControllerApplication object at 0x7079d610>>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Creating callback CallbackResponseListener(matching_commands=(ZDO.TCDevInd.Callback(SrcNwk=None, SrcIEEE=None, ParentNwk=None),), callback=<bound method ControllerApplication.on_zdo_tc_device_join of <zigpy_znp.zigbee.application.ControllerApplication object at 0x7079d610>>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Creating callback CallbackResponseListener(matching_commands=(ZDO.LeaveInd.Callback(NWK=None, IEEE=None, Request=None, Remove=None, Rejoin=None),), callback=<bound method ControllerApplication.on_zdo_device_leave of <zigpy_znp.zigbee.application.ControllerApplication object at 0x7079d610>>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Creating callback CallbackResponseListener(matching_commands=(ZDO.SrcRtgInd.Callback(DstAddr=None, Relays=None),), callback=<bound method ControllerApplication.on_zdo_relays_message of <zigpy_znp.zigbee.application.ControllerApplication object at 0x7079d610>>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.HAS_CONFIGURED_ZSTACK3: 96>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Creating one-shot listener OneShotResponseListener(matching_commands=(SYS.OSALNVLength.Rsp(ItemLen=None), RPCError.CommandNotRecognized.Rsp(ErrorCode=None, RequestHeader=CommandHeader(id=0x13, subsystem=Subsystem.SYS, type=CommandType.SREQ))), future=<Future finished result=SYS.OSALNVLen...Rsp(ItemLen=1)>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.uart] Sending data: b'\xFE\x02\x21\x13\x60\x00\x50'
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.uart] Received data: b'\xFE\x02\x61\x13\x01\x00\x71'
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.uart] Parsed frame: TransportFrame(payload=GeneralFrame(header=CommandHeader(id=0x13, subsystem=Subsystem.SYS, type=CommandType.SRSP), data=b'\x01\x00'))
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] SYS.OSALNVLength.Rsp(ItemLen=1) matches OneShotResponseListener(matching_commands=(SYS.OSALNVLength.Rsp(ItemLen=None), RPCError.CommandNotRecognized.Rsp(ErrorCode=None, RequestHeader=CommandHeader(id=0x13, subsystem=Subsystem.SYS, type=CommandType.SREQ))), future=<Future finished result=SYS.OSALNVLen...Rsp(ItemLen=1)>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Removing listener OneShotResponseListener(matching_commands=(SYS.OSALNVLength.Rsp(ItemLen=None), RPCError.CommandNotRecognized.Rsp(ErrorCode=None, RequestHeader=CommandHeader(id=0x13, subsystem=Subsystem.SYS, type=CommandType.SREQ))), future=<Future finished result=SYS.OSALNVLen...Rsp(ItemLen=1)>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Cleaning up empty listener list for header CommandHeader(id=0x00, subsystem=Subsystem.RPCError, type=CommandType.SRSP)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Cleaning up empty listener list for header CommandHeader(id=0x13, subsystem=Subsystem.SYS, type=CommandType.SRSP)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] There are 5 callbacks and 0 one-shot listeners remaining
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.HAS_CONFIGURED_ZSTACK3: 96>, Offset=0)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Creating one-shot listener OneShotResponseListener(matching_commands=(SYS.OSALNVReadExt.Rsp(Status=None, Value=None), RPCError.CommandNotRecognized.Rsp(ErrorCode=None, RequestHeader=CommandHeader(id=0x1C, subsystem=Subsystem.SYS, type=CommandType.SREQ))), future=<Future finished result=SYS.OSALNVRea...Value=b'\x55')>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.uart] Sending data: b'\xFE\x04\x21\x1C\x60\x00\x00\x00\x59'
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.uart] Received data: b'\xFE\x03\x61\x1C\x00\x01\x55\x2A'
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.uart] Parsed frame: TransportFrame(payload=GeneralFrame(header=CommandHeader(id=0x1C, subsystem=Subsystem.SYS, type=CommandType.SRSP), data=b'\x00\x01\x55'))
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x55')
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x55') matches OneShotResponseListener(matching_commands=(SYS.OSALNVReadExt.Rsp(Status=None, Value=None), RPCError.CommandNotRecognized.Rsp(ErrorCode=None, RequestHeader=CommandHeader(id=0x1C, subsystem=Subsystem.SYS, type=CommandType.SREQ))), future=<Future finished result=SYS.OSALNVRea...Value=b'\x55')>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Removing listener OneShotResponseListener(matching_commands=(SYS.OSALNVReadExt.Rsp(Status=None, Value=None), RPCError.CommandNotRecognized.Rsp(ErrorCode=None, RequestHeader=CommandHeader(id=0x1C, subsystem=Subsystem.SYS, type=CommandType.SREQ))), future=<Future finished result=SYS.OSALNVRea...Value=b'\x55')>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Cleaning up empty listener list for header CommandHeader(id=0x00, subsystem=Subsystem.RPCError, type=CommandType.SRSP)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Cleaning up empty listener list for header CommandHeader(id=0x1C, subsystem=Subsystem.SYS, type=CommandType.SRSP)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] There are 5 callbacks and 0 one-shot listeners remaining
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Creating one-shot listener OneShotResponseListener(matching_commands=(SYS.ResetInd.Callback(Reason=None, TransportRev=None, ProductId=None, MajorRel=None, MinorRel=None, MaintRel=None),), future=<Future pending cb=[ZNP.wait_for_responses.<locals>.<lambda>() at /usr/local/lib/python3.8/site-packages/zigpy_znp/api.py:436, <TaskWakeupMethWrapper object at 0x6ef3e9b8>()]>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.ResetReq.Req(Type=<ResetType.Soft: 1>)
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.api] Request has no response, not waiting for one.
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.uart] Sending data: b'\xFE\x01\x41\x00\x01\x41'
2021-02-02 01:09:21 DEBUG (MainThread) [zigpy_znp.uart] Received data: b'\x00'
puddly commented 3 years ago

I don't have Slaesh's stick to test with but it appears like Koenkk's Z-Stack build for your CC2652RB may be bad if you are able to downgrade successfully??

Regarding your network settings: unfortunately, firmware upgrades wipe NVRAM so unless you performed an NVRAM backup before upgrading (outlined in the main project README) and then restored it, your settings will have been completely erased and a brand new network was formed on startup. If you have old startup debug logs, they may contain enough info to rebuild your settings.

julnobugs commented 3 years ago

Agree, chances are high that the issue is in latest koenkk's build for CC2652RB. Will report there. Got it for the NVRAM backup. I guess it cannot be done from hassos or ha core, right ? It has to be a venv with python 3.8 hosted on a linux box ?

puddly commented 3 years ago

The subcommands to read/write NVRAM will run within any environment with the zigpy_znp Python package installed, including the Home Assistant virtual environment hosting HA Core or the managed OS's Docker container. You don't need anything separate to do this, though if you prefer an external setup, anything with Python 3.7 or above that can pip install zigpy-znp will work, regardless of platform.

julnobugs commented 3 years ago

Thanks a lot for your help. Maybe am doing sthg wrong but when I try, I get this error:

 |  | |                          /\           (_)   | |            | |
| |__| | ___  _ __ ___   ___     /  \   ___ ___ _ ___| |_ __ _ _ __ | |_
|  __  |/ _ \| '_ ` _ \ / _ \   / /\ \ / __/ __| / __| __/ _` | '_ \| __|
| |  | | (_) | | | | | |  __/  / ____ \\__ \__ \ \__ \ || (_| | | | | |_
|_|  |_|\___/|_| |_| |_|\___| /_/    \_\___/___/_|___/\__\__,_|_| |_|\__|

Welcome to the Home Assistant command line.

For more details use 'help' and 'exit' to close.
If you need access to host system use 'login'.

ha > login
# docker exec -it homeassistant /bin/bash
bash-5.0# python -m zigpy_znp.tools.nvram_read /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_0A_BD-if00-port0 -o cc2652rb-backup.json
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/zigpy_znp/api.py", line 507, in request
    response = await response_future
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/runpy.py", line 194, in _run_module_as_main
    return _run_code(code, main_globals, None,
  File "/usr/local/lib/python3.8/runpy.py", line 87, in _run_code
    exec(code, run_globals)
  File "/usr/local/lib/python3.8/site-packages/zigpy_znp/tools/nvram_read.py", line 95, in <module>
    asyncio.run(main(sys.argv[1:]))  # pragma: no cover
  File "/usr/local/lib/python3.8/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/usr/local/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "/usr/local/lib/python3.8/site-packages/zigpy_znp/tools/nvram_read.py", line 90, in main
    obj = await backup(args.serial)
  File "/usr/local/lib/python3.8/site-packages/zigpy_znp/tools/nvram_read.py", line 48, in backup
    value = await znp.nvram.osal_read(nwk_nvid)
  File "/usr/local/lib/python3.8/site-packages/zigpy_znp/nvram.py", line 111, in osal_read
    length = (await self.znp.request(c.SYS.OSALNVLength.Req(Id=nv_id))).ItemLen
  File "/usr/local/lib/python3.8/site-packages/zigpy_znp/api.py", line 507, in request
    response = await response_future
  File "/usr/local/lib/python3.8/site-packages/async_timeout/__init__.py", line 55, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.8/site-packages/async_timeout/__init__.py", line 92, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError
julnobugs commented 3 years ago

My bad, I did use the router image instead of the coordinator by mistake. I checked this morning again the last version for CC2652RB as a coordinator and it's CC2652RB_2021010 so I definitely did not download the correct fw. CC2652RB_20210128 is the router fw. This couldn't have work.

Am still interested though if there is a way to do a backup of NVRAM from HA core hosted on hassos.

puddly commented 3 years ago

Ah, that explains it.

Make sure home assistant is shut down when reading nvram. You can't have two connections attempting to control the same serial port.

julnobugs commented 3 years ago

If I understand well, zigpy-znp is only pre-installed in ha-core. But I need to stop home-assistant to free the control of the serial port.

Is there a way to ask home-assistant to disconnect this serial port or is there a way to stop home-assistant without having to stop the homeassistant container so I can perform this backup ?

Else. is there a way to install this package on hassos level or in any hassos containers ?

# docker ps --format '{{.Image}}'
ghcr.io/hassio-addons/node-red/armv7:8.0.1
homeassistant/armv7-addon-configurator:5.2.0
homeassistant/armv7-addon-duckdns:1.12.4
homeassistant/armv7-addon-ssh:8.10.0
homeassistant/armv7-addon-mosquitto:5.1
ghcr.io/hassio-addons/nut/armv7:0.4.0
homeassistant/armv7-hassio-multicast:3
homeassistant/armv7-hassio-cli:2020.11.1
homeassistant/armv7-hassio-audio:17
homeassistant/armv7-hassio-dns:2021.01.0
homeassistant/armv7-hassio-supervisor:latest
homeassistant/raspberrypi3-homeassistant:2021.1.5
homeassistant/armv7-hassio-observer:2020.10.1
julnobugs commented 3 years ago

Thanks again puddly for your help. For the one that would be interested to backup directly from ha core, you can temporarily free the serial port by killing the ha python process. HA is automatically restarting the process but if you have a good timing, you can perform successfully the backup.

Hedda commented 3 years ago

Am still interested though if there is a way to do a backup of NVRAM from HA core hosted on hassos.

FYI, there is some related discussion in https://github.com/zigpy/zigpy/issues and maybe you could mention it as a use-case there.