search

zigpy / zigpy-cli

Command line interface for zigpy
GNU General Public License v3.0
44 stars 12 forks source link

Unable to backup HUSBZB-1 #10

Closed jesseas closed 2 years ago

jesseas commented 2 years ago

I am struggling to back up my HUSBZB-1 - with the goal of migrating to a Sonoff Zigbee USB dongle.

environment info:

(venv)  zigpy $ python --version
Python 3.8.12
(venv)  zigpy $ udevadm info -a -n /dev/ttyUSB1 | grep '{interface}' | head -n1
    ATTRS{interface}=="HubZ ZigBee Com Port"

I was trying to follow along with this ticket, so I used the braches there: https://github.com/zigpy/zigpy-cli/pull/2

pip install \
    git+https://github.com/puddly/zigpy.git@puddly/new-radio-settings-api \
    git+https://github.com/puddly/zigpy-cli.git@puddly/zigpy-radio-api \
    git+https://github.com/puddly/zigpy-znp.git@puddly/new-radio-settings-api \
    git+https://github.com/puddly/zigpy-deconz.git@puddly/new-radio-api \
    git+https://github.com/puddly/bellows.git@puddly/zigpy-radio-api

This is what I see when I try to run a backup. After the last line it just hangs for minutes until I send ^c. 

(venv)  zigpy $ zigpy -vv radio ezsp /dev/ttyUSB1 backup backup.json
2022-03-12 15:53:58.133 localhost.localdomain asyncio DEBUG Using selector: EpollSelector
2022-03-12 15:53:58.238 localhost.localdomain zigpy.appdb DEBUG SQLite version for <module 'sqlite3' from '/usr/lib64/python3.8/sqlite3/__init__.py'>: 3.37.2
2022-03-12 15:53:58.292 localhost.localdomain asyncio DEBUG Using selector: EpollSelector
2022-03-12 15:53:58.412 localhost.localdomain bellows.ezsp DEBUG Resetting EZSP
2022-03-12 15:53:58.413 localhost.localdomain bellows.uart DEBUG Resetting ASH
2022-03-12 15:53:58.413 localhost.localdomain bellows.uart DEBUG Sending: b'1ac038bc7e'
2022-03-12 15:53:59.712 localhost.localdomain bellows.uart DEBUG RSTACK Version: 2 Reason: RESET_POWER_ON frame: b'c102029b7b7e'
2022-03-12 15:53:59.712 localhost.localdomain bellows.ezsp ERROR NCP entered failed state. Requesting APP controller restart
2022-03-12 15:53:59.713 localhost.localdomain bellows.uart DEBUG Closed serial connection

^c results in this log:

2022-03-12 15:59:45.700 localhost.localdomain asyncio ERROR Task was destroyed but it is pending!
task: <Task pending name='Task-6' coro=<Gateway.reset() running at ~/dev/zigpy/venv/lib/python3.8/site-packages/bellows/uart.py:223> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f31031cdaf0>()]> cb=[_chain_future.<locals>._call_set_state() at /usr/lib64/python3.8/asyncio/futures.py:367]>

and have also tried the master branch:

(venv)  zigpy $ pip install  --force-reinstall   git+https://github.com/puddly/zigpy.git     git+https://github.com/puddly/zigpy-cli.git    git+https://github.com/puddly/zigpy-znp.git    git+https://github.com/puddly/zigpy-deconz.git     git+https://github.com/puddly/bellows.git

which gave me a syntax error (it looks like backup isn't a command there yet?)

I don't remember what firmware version I have on my HUSBZB-1, but I did update it within the last year to the latest.

Any help is appreciated. Let me know if there is more info I can provide.

puddly commented 2 years ago

Does it always produce the RESET_POWER_ON status code? Even if you run it multiple times in a row?

jesseas commented 2 years ago

Yes, it seems to. I am happy to rerun a test. If I go that route, let it hang 30 seconds (should I wait longer?) and then ^c and then repeat a few more times?

puddly commented 2 years ago

It takes about 10 seconds to run for me with my HUSBZB-1, you should either see immediate output or an error code.

What about if you install and run bellows from its main branch (in a new venv)?

$ pip install bellows
$ bellows -v DEBUG -d /dev/... backup

The backup format for the above command won't be compatible with the other tools but it should also fail with a similar status.

jesseas commented 2 years ago

ok, so on the first question, here are 3 runs in a row.

Here are three runs of zigpy, they all look the same to me, but maybe I am missing something.

(venv)  zigpy $ zigpy -vv radio ezsp /dev/ttyUSB1 backup backup.json
2022-03-12 19:26:59.150 localhost.localdomain asyncio DEBUG Using selector: EpollSelector
2022-03-12 19:26:59.259 localhost.localdomain zigpy.appdb DEBUG SQLite version for <module 'sqlite3' from '/usr/lib64/python3.8/sqlite3/__init__.py'>: 3.37.2
2022-03-12 19:26:59.313 localhost.localdomain asyncio DEBUG Using selector: EpollSelector
2022-03-12 19:26:59.437 localhost.localdomain bellows.ezsp DEBUG Resetting EZSP
2022-03-12 19:26:59.438 localhost.localdomain bellows.uart DEBUG Resetting ASH
2022-03-12 19:26:59.438 localhost.localdomain bellows.uart DEBUG Sending: b'1ac038bc7e'
2022-03-12 19:27:00.732 localhost.localdomain bellows.uart DEBUG RSTACK Version: 2 Reason: RESET_POWER_ON frame: b'c102029b7b7e'
2022-03-12 19:27:00.733 localhost.localdomain bellows.ezsp ERROR NCP entered failed state. Requesting APP controller restart
2022-03-12 19:27:00.734 localhost.localdomain bellows.uart DEBUG Closed serial connection
^C
Aborted!
2022-03-12 19:27:09.750 localhost.localdomain asyncio ERROR Task was destroyed but it is pending!
task: <Task pending name='Task-6' coro=<Gateway.reset() running at /home/jesse/dev/zigpy/venv/lib/python3.8/site-packages/bellows/uart.py:223> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f32e5a8daf0>()]> cb=[_chain_future.<locals>._call_set_state() at /usr/lib64/python3.8/asyncio/futures.py:367]>
(venv)  zigpy $ zigpy -vv radio ezsp /dev/ttyUSB1 backup backup.json
2022-03-12 19:27:11.312 localhost.localdomain asyncio DEBUG Using selector: EpollSelector
2022-03-12 19:27:11.413 localhost.localdomain zigpy.appdb DEBUG SQLite version for <module 'sqlite3' from '/usr/lib64/python3.8/sqlite3/__init__.py'>: 3.37.2
2022-03-12 19:27:11.464 localhost.localdomain asyncio DEBUG Using selector: EpollSelector
2022-03-12 19:27:11.581 localhost.localdomain bellows.ezsp DEBUG Resetting EZSP
2022-03-12 19:27:11.582 localhost.localdomain bellows.uart DEBUG Resetting ASH
2022-03-12 19:27:11.582 localhost.localdomain bellows.uart DEBUG Sending: b'1ac038bc7e'
2022-03-12 19:27:12.883 localhost.localdomain bellows.uart DEBUG RSTACK Version: 2 Reason: RESET_POWER_ON frame: b'c102029b7b7e'
2022-03-12 19:27:12.884 localhost.localdomain bellows.ezsp ERROR NCP entered failed state. Requesting APP controller restart
2022-03-12 19:27:12.885 localhost.localdomain bellows.uart DEBUG Closed serial connection
^C
Aborted!
2022-03-12 19:27:23.205 localhost.localdomain asyncio ERROR Task was destroyed but it is pending!
task: <Task pending name='Task-6' coro=<Gateway.reset() running at /home/jesse/dev/zigpy/venv/lib/python3.8/site-packages/bellows/uart.py:223> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f8f765728b0>()]> cb=[_chain_future.<locals>._call_set_state() at /usr/lib64/python3.8/asyncio/futures.py:367]>
(venv)  zigpy $ zigpy -vv radio ezsp /dev/ttyUSB1 backup backup.json
2022-03-12 19:27:26.124 localhost.localdomain asyncio DEBUG Using selector: EpollSelector
2022-03-12 19:27:26.225 localhost.localdomain zigpy.appdb DEBUG SQLite version for <module 'sqlite3' from '/usr/lib64/python3.8/sqlite3/__init__.py'>: 3.37.2
2022-03-12 19:27:26.279 localhost.localdomain asyncio DEBUG Using selector: EpollSelector
2022-03-12 19:27:26.400 localhost.localdomain bellows.ezsp DEBUG Resetting EZSP
2022-03-12 19:27:26.401 localhost.localdomain bellows.uart DEBUG Resetting ASH
2022-03-12 19:27:26.401 localhost.localdomain bellows.uart DEBUG Sending: b'1ac038bc7e'
2022-03-12 19:27:27.699 localhost.localdomain bellows.uart DEBUG RSTACK Version: 2 Reason: RESET_POWER_ON frame: b'c102029b7b7e'
2022-03-12 19:27:27.700 localhost.localdomain bellows.ezsp ERROR NCP entered failed state. Requesting APP controller restart
2022-03-12 19:27:27.701 localhost.localdomain bellows.uart DEBUG Closed serial connection
^C
Aborted!
2022-03-12 19:27:35.080 localhost.localdomain asyncio ERROR Task was destroyed but it is pending!
task: <Task pending name='Task-6' coro=<Gateway.reset() running at /home/jesse/dev/zigpy/venv/lib/python3.8/site-packages/bellows/uart.py:223> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff6f20cdfd0>()]> cb=[_chain_future.<locals>._call_set_state() at /usr/lib64/python3.8/asyncio/futures.py:367]>

On the bellows test, I removed and reinserted the USB stick in order to make sure the blue light started on. I switched virtual envs and got this:

(venv)  dev $ bellows -v DEBUG -d /dev/ttyUSB1 backup
debug: Using selector: EpollSelector
debug: Using selector: EpollSelector
debug: Connected. Resetting.
debug: Resetting EZSP
debug: Resetting ASH
debug: Sending: b'1ac038bc7e'
debug: RSTACK Version: 2 Reason: RESET_POWER_ON frame: b'c102029b7b7e'
error: NCP entered failed state. Requesting APP controller restart
debug: _reset_controller_application callback: (<NcpResetCode.RESET_POWER_ON: 2>,)
debug: Closed serial connection
^C
Aborted!
error: Task was destroyed but it is pending!
error: task: <Task pending name='Task-5' coro=<Gateway.reset() done, defined at /home/jesse/dev/venv/lib/python3.8/site-packages/bellows/uart.py:202> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fcd4748a5b0>()]> cb=[_chain_future.<locals>._call_set_state() at /usr/lib64/python3.8/asyncio/futures.py:367]>
(venv)  dev $ bellows -v DEBUG -d /dev/ttyUSB1 backup
debug: Using selector: EpollSelector
debug: Using selector: EpollSelector
debug: Connected. Resetting.
debug: Resetting EZSP
debug: Resetting ASH
debug: Sending: b'1ac038bc7e'
debug: RSTACK Version: 2 Reason: RESET_POWER_ON frame: b'c102029b7b7e'
error: NCP entered failed state. Requesting APP controller restart
debug: _reset_controller_application callback: (<NcpResetCode.RESET_POWER_ON: 2>,)
debug: Closed serial connection
^C
Aborted!
error: Task was destroyed but it is pending!
error: task: <Task pending name='Task-5' coro=<Gateway.reset() done, defined at /home/jesse/dev/venv/lib/python3.8/site-packages/bellows/uart.py:202> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f5c7c38b550>()]> cb=[_chain_future.<locals>._call_set_state() at /usr/lib64/python3.8/asyncio/futures.py:367]>
(venv)  dev $ bellows -v DEBUG -d /dev/ttyUSB1 backup
debug: Using selector: EpollSelector
debug: Using selector: EpollSelector
debug: Connected. Resetting.
debug: Resetting EZSP
debug: Resetting ASH
debug: Sending: b'1ac038bc7e'
debug: RSTACK Version: 2 Reason: RESET_POWER_ON frame: b'c102029b7b7e'
error: NCP entered failed state. Requesting APP controller restart
debug: _reset_controller_application callback: (<NcpResetCode.RESET_POWER_ON: 2>,)
debug: Closed serial connection
^C
Aborted!
error: Task was destroyed but it is pending!
error: task: <Task pending name='Task-5' coro=<Gateway.reset() done, defined at /home/jesse/dev/venv/lib/python3.8/site-packages/bellows/uart.py:202> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f626da4b5b0>()]> cb=[_chain_future.<locals>._call_set_state() at /usr/lib64/python3.8/asyncio/futures.py:367]>

I gave that 10 seconds or so before killing it with ^c. I also have three outputs from that.

puddly commented 2 years ago

This looks like a problem either with the stick or with the host. Are you sure no other software is accessing the stick (i.e ZHA or Zigbee2MQTT)? Can you try a different type of USB port or a different computer?

jesseas commented 2 years ago

I initially tried this on my HA VM. When that didn't work (I don't remember what the error there was), I decided it was easier to move to my Linux laptop. My laptop doesn't have HA or anything else on it that should know or care about the zigbee dongle. I tried a different USB port (even moving from USB-A to Thunderbolt) and I don't see any change...

dmulcahey commented 2 years ago

If on a Linux laptop: make sure modemmanager is not running / there

jesseas commented 2 years ago

I removed ModemManager, although I don't think it was actually running. Zigpy and Bellows both give me the same error.

puddly commented 2 years ago

Bellows is the library ZHA and zigpy-cli use to communicate with the HUSBZB-1. If it can't connect, I'm not sure how you're able to use Home Assistant with it in the first place.

Some suggestions:

  1. Try yet another environment. If it 100% works within HA OS, you can disable ZHA and create the virtualenv in there to install the packages.
  2. Edit bellows to disable this specific check: https://github.com/zigpy/bellows/blob/dd00f42792efa200e40e1c806c5b84c5129b2d74/bellows/uart.py#L150
jesseas commented 2 years ago

Ok, yeah, this device was being used on HA (on a different machine), so I can try to move back to that environment and give it another go, or dig into that further. That will take a little longer to turn around. Thanks for your help so far.

jesseas commented 2 years ago

I was able to run this in the HA VM. not sure what caused the issue on my other machine. Thanks for the help.