Slae.sh USB stick not working on v0.6.3

[davidbb]

After updating HA OS to 2021.12.0b2, ZHA fails to start up. Downgrading to 2021.11.5 allows ZHA to start up again. Enabling debug logging shows the logs below for 2021.12.0b2:

2021-12-07 10:08:07 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_45_F5-if00-port0 at 115200 baud
2021-12-07 10:08:07 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_45_F5-if00-port0 serial port
2021-12-07 10:08:07 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_45_F5-if00-port0 at 115200 baud
2021-12-07 10:08:07 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2021-12-07 10:08:10 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2021-12-07 10:08:10 DEBUG (MainThread) [zigpy_znp.api] Toggling RTS/DTR pins to skip bootloader or reset chip
2021-12-07 10:08:10 DEBUG (MainThread) [zigpy_znp.uart] Setting serial pin states: DTR=False, RTS=False
2021-12-07 10:08:10 DEBUG (MainThread) [zigpy_znp.uart] Setting serial pin states: DTR=False, RTS=True
2021-12-07 10:08:11 DEBUG (MainThread) [zigpy_znp.uart] Setting serial pin states: DTR=False, RTS=False
2021-12-07 10:08:11 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2021-12-07 10:08:12 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_45_F5-if00-port0 failed, cleaning up
2021-12-07 10:08:12 DEBUG (MainThread) [zigpy_znp.uart] Closing serial port
2021-12-07 10:08:12 ERROR (MainThread) [zigpy.application] Couldn't start application

And these are the equivalent logs for 2021.11.5:

2021-12-07 10:18:35 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_45_F5-if00-port0 at 115200 baud
2021-12-07 10:18:35 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_45_F5-if00-port0 serial port
2021-12-07 10:18:35 DEBUG (MainThread) [zigpy_znp.uart] Toggling RTS/CTS to skip CC2652R bootloader
2021-12-07 10:18:36 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_45_F5-if00-port0 at 115200 baud
2021-12-07 10:18:36 DEBUG (MainThread) [zigpy_znp.api] Waiting 1s before sending anything
2021-12-07 10:18:42 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-12-07 10:18:42 WARNING (MainThread) [zigpy_znp.api] Received an unhandled command: SYS.ResetInd.Callback(Reason=<ResetReason.PowerUp: 0>, TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1)
2021-12-07 10:18:43 DEBUG (MainThread) [zigpy_znp.api] Sending bootloader skip byte
2021-12-07 10:18:43 DEBUG (MainThread) [zigpy_znp.api] Waiting 1s or until a reset indication is received
2021-12-07 10:18:44 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_45_F5-if00-port0
2021-12-07 10:18:44 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2021-12-07 10:18:44 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2021-12-07 10:18:44 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NWKKEY: 130>)
2021-12-07 10:18:44 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=24)

It appears connection to the slaesh USB stick is failing. This seems related to the new connection logic introduced in PR #104. Happy to provide more info if necessary.

[puddly]

Interesting, it takes seven seconds for the stick to reset.

Could you try out this branch? You can use either the beta or the last stable. Instructions for setting up zigpy-znp with the custom deps deployment addon are here: https://github.com/zigpy/zigpy-znp#testing-dev-with-home-assistant-os

apk: []
pypi:
  - git+https://github.com/puddly/zigpy-znp.git@puddly/fix-slaesh-bootloader
  - zigpy==0.42.0

[davidbb]

Much better! Logs below on 2021.12.0b2 using zigpy 0.42.0 from your repo:

2021-12-07 13:59:48 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_45_F5-if00-port0 at 115200 baud
2021-12-07 13:59:48 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_45_F5-if00-port0 serial port
2021-12-07 13:59:48 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_45_F5-if00-port0 at 115200 baud
2021-12-07 13:59:48 DEBUG (MainThread) [zigpy_znp.api] Toggling RTS/DTR pins to skip bootloader or reset chip
2021-12-07 13:59:48 DEBUG (MainThread) [zigpy_znp.uart] Setting serial pin states: DTR=False, RTS=False
2021-12-07 13:59:48 DEBUG (MainThread) [zigpy_znp.uart] Setting serial pin states: DTR=False, RTS=True
2021-12-07 13:59:48 DEBUG (MainThread) [zigpy_znp.uart] Setting serial pin states: DTR=False, RTS=False
2021-12-07 13:59:49 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2021-12-07 13:59:51 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-12-07 13:59:51 DEBUG (MainThread) [zigpy_znp.api] Radio is alive: SYS.ResetInd.Callback(Reason=<ResetReason.PowerUp: 0>, TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1)
2021-12-07 13:59:51 DEBUG (MainThread) [zigpy_znp.api] Giving ping task 0.50s to finish
2021-12-07 13:59:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2021-12-07 13:59:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2021-12-07 13:59:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NWKKEY: 130>)
2021-12-07 13:59:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=24)
2021-12-07 13:59:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NWKKEY: 130>, Offset=0)
2021-12-07 13:59:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00\xFA\x6F\x91\x99\x94\x14\x8F\xC3\xE0\x22\x2F\xF5\x16\x8A\xED\x61\xEC\x01\x00\xCA\x86\x69\x00')
2021-12-07 13:59:51 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0082] = b'\x00\xFA\x6F\x91\x99\x94\x14\x8F\xC3\xE0\x22\x2F\xF5\x16\x8A\xED\x61\xEC\x01\x00\xCA\x86\x69\x00'
2021-12-07 13:59:51 DEBUG (MainThread) [zigpy_znp.nvram] Detected struct alignment: True

Seems to work OK thanks for the quick fix!