ZHA failing to start (regression?)

zombielinux · July 18, 2019, 4:19am

HASS .95.4 running on archlinux virtual machine on top of proxmox 5.3-11.
HUSBZB-1 (brand new) passed through to VM as usb device.

configuration.yaml

zha:
  usb_path: /dev/ttyUSB1
  database_path: /media/hass/zigbee.db

output of “ls -lah /media/hass/”

[root@homeassistant hass]# ls -lah /media/hass/
total 80K
drwxr-xr-x 2 hass hass 4.0K Jul 17 23:51 .
drwxr-xr-x 3 root root 4.0K Jul 17 22:49 ..
-rw-r--r-- 1 hass hass  68K Jul 17 23:51 zigbee.db

The error I receive is the same as the error in this issue.

Jul 18 00:18:07 homeassistant hass[427]: 2019-07-18 00:18:07 INFO (MainThread) [homeassistant.setup] Setup of domain climate took 7.8 seconds.
Jul 18 00:18:07 homeassistant hass[427]: 2019-07-18 00:18:07 INFO (MainThread) [homeassistant.components.climate] Setting up climate.zwave
Jul 18 00:18:07 homeassistant hass[427]: 2019-07-18 00:18:07 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry /dev/ttyUSB1 for zha
Jul 18 00:18:07 homeassistant hass[427]: Traceback (most recent call last):
Jul 18 00:18:07 homeassistant hass[427]:   File "/usr/lib/python3.7/site-packages/homeassistant/config_entries.py", line 153, in async_setup
Jul 18 00:18:07 homeassistant hass[427]:     hass, self)
Jul 18 00:18:07 homeassistant hass[427]:   File "/usr/lib/python3.7/site-packages/homeassistant/components/zha/__init__.py", line 94, in async_setup_entry
Jul 18 00:18:07 homeassistant hass[427]:     await zha_gateway.async_initialize(config_entry)
Jul 18 00:18:07 homeassistant hass[427]:   File "/usr/lib/python3.7/site-packages/homeassistant/components/zha/core/gateway.py", line 89, in async_initialize
Jul 18 00:18:07 homeassistant hass[427]:     await self.application_controller.startup(auto_form=True)
Jul 18 00:18:07 homeassistant hass[427]:   File "/var/lib/hass/deps/lib/python3.7/site-packages/bellows/zigbee/application.py", line 113, in startup
Jul 18 00:18:07 homeassistant hass[427]:     await self.initialize()
Jul 18 00:18:07 homeassistant hass[427]:   File "/var/lib/hass/deps/lib/python3.7/site-packages/bellows/zigbee/application.py", line 62, in initialize
Jul 18 00:18:07 homeassistant hass[427]:     await e.reset()
Jul 18 00:18:07 homeassistant hass[427]:   File "/var/lib/hass/deps/lib/python3.7/site-packages/bellows/ezsp.py", line 55, in reset
Jul 18 00:18:07 homeassistant hass[427]:     await self._gw.reset()
Jul 18 00:18:07 homeassistant hass[427]:   File "/usr/lib/python3.7/asyncio/tasks.py", line 423, in wait_for
Jul 18 00:18:07 homeassistant hass[427]:     raise futures.TimeoutError()
Jul 18 00:18:07 homeassistant hass[427]: concurrent.futures._base.TimeoutError
Jul 18 00:18:07 homeassistant hass[427]: 2019-07-18 00:18:07 INFO (MainThread) [homeassistant.bootstrap] Home Assistant initialized in 14.95s
Jul 18 00:18:07 homeassistant hass[427]: 2019-07-18 00:18:07 INFO (MainThread) [homeassistant.core] Starting Home Assistant

zombielinux · July 18, 2019, 3:00pm

This issue persists in .96.0

tube0013 · July 18, 2019, 9:08pm

see the Troubleshooting section here: https://www.home-assistant.io/components/zha/

be sure modem manager is not running on the host or the vm.

zombielinux · July 19, 2019, 9:42am

Confirmed not running, nor even installed on either host or VM.

lsof -n /dev/ttyUSB*

Returns nothing on either host when home assistant is stopped and

lsof -n /dev/ttyUSB1

Returns nothing when home assistant is running.

rpress · July 21, 2019, 12:01am

I have that same USB device passed into a qemu/kvm vm (same as Proxmox I think) running for a while, currently on 0.96.1. Pretty sure I ran it on 0.95.4 too. I’m using Hass.io under Fedora 30 (docker is running on the vm).

Have you tried accessing it from the command line with Bellows?

zombielinux · July 21, 2019, 6:30pm

@rpress
I havn’t. Can you send a link to the documentation on that?

zombielinux · July 21, 2019, 6:43pm

@rpress

Just did some tinkering with bellows, seems to be the same bug as this one: https://www.bountysource.com/issues/58588775-setup-of-zha-is-taking-over-10-seconds-homeassistant

rpress · July 22, 2019, 3:44pm

Here is what mine looks like, maybe you can compare it with your output.

[root@hassio ~]# bellows -v DEBUG -d /dev/ttyUSB1 info
debug: Using selector: EpollSelector
debug: Connected. Resetting.
debug: Resetting EZSP
debug: Resetting ASH
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'0142a1a8522815d2e7ae7e'
debug: Sending: b'8160597e'
debug: Application frame 0 (version) received
debug: Switching to eszp version 6
debug: Send command version
debug: Sending: b'7d31432157542a7d3315a67e'
debug: Data frame: b'1243a157542a13b059f4b6467e'
debug: Sending: b'82503a7e'
debug: Application frame 0 (version) received
debug: Configuring...
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'554721575479144d593eca7e'
debug: Data frame: b'5647a157547915ce557e'
debug: Sending: b'8610be7e'
debug: Application frame 83 (setConfigurationValue) received
debug: Send command networkInit
debug: Sending: b'66442157543dfba67e'
debug: Data frame: b'6744a557543d15a9577e'
debug: Sending: b'87009f7e'
debug: Application frame 23 (networkInit) received
debug: Data frame: b'7744b157543385b3c67e'
debug: Sending: b'8070787e'
debug: Application frame 25 (stackStatusHandler) received
debug: Send command getEui64
debug: Sending: b'70452157540ce0e07e'
debug: Data frame: b'0045a157540c04d248944a868855436e7e'
debug: Sending: b'8160597e'
debug: Application frame 38 (getEui64) received
[00:22:a3:00:00:11:60:11]
debug: Send command getNodeId
debug: Sending: b'014a2157540d95047e'
debug: Data frame: b'114aa157540d15b235117e'
debug: Sending: b'82503a7e'
debug: Application frame 39 (getNodeId) received
[0]
debug: Send command networkState
debug: Sending: b'124b215754322c8d7e'
debug: Data frame: b'224ba15754321771657e'
debug: Sending: b'83401b7e'
debug: Application frame 24 (networkState) received
[<EmberNetworkStatus.JOINED_NETWORK: 2>]
debug: Send command getNetworkParameters
debug: Sending: b'2348215754029e207e'
debug: Data frame: b'3348a157540215b356a84e0150dd56f308022fb8edce678bfd3e9c8e5cb57e'
debug: Sending: b'8430fc7e'
debug: Application frame 40 (getNetworkParameters) received
[<EmberStatus.SUCCESS: 0>, <EmberNodeType.COORDINATOR: 1>, <EmberNetworkParameters extendedPanId=[15, 60, 4, 36, 250, 136, 196, 186] panId=19604 radioTxPower=8 radioChannel=19 joinMethod=EmberJoinMethod.USE_MAC_ASSOCIATION nwkManagerId=0 nwkUpdateId=0 channels=134215680>]
debug: Send command getCurrentSecurityState
debug: Sending: b'344921575443be517e'
debug: Data frame: b'4449a157544315c659852a34aa55316b9c967c7e'
debug: Sending: b'8520dd7e'
debug: Application frame 105 (getCurrentSecurityState) received
[<EmberStatus.SUCCESS: 0>, <EmberCurrentSecurityState bitmask=116 trustCenterLongAddress=00:22:a3:00:00:11:60:11>]
debug: Closed serial connection

zombielinux · July 22, 2019, 5:49pm

hmmmm, it looks like i’ve got the same stuff, except I don’t have

debug: Resetting EZSP
debug: Resetting ASH

rpress · July 22, 2019, 6:02pm

Have you tried to form a new network? You will need to pair your devices again if you do this…

Something like:

bellows -v DEBUG -d /dev/ttyUSB1 form

zombielinux · July 22, 2019, 6:07pm

[root@homeassistant ~]# bellows -v DEBUG -d /dev/ttyUSB1 form
debug: Using selector: EpollSelector
debug: Loading application state from /root/.config/bellows/app.db
debug: Sending: b'1ac038bc7e'

It hangs in the same spot. I’m wondering why I’m not getting the EZSP and ASH lines.

zombielinux · July 29, 2019, 4:28pm

I appear to have solved the issue.

Remove the USB device from the Proxmox Passthrough and execute:

qm set $VMID -serial0 /dev/ttyUSB0
qm set $VMID -serial1 /dev/ttyUSB1

Where $VMID is the number of the vm (in my case its 119) and ttyUSB0/1 are the serial ports created by the HUSBZB-1 stick. These will internally be mapped inside the vm to /dev/ttyS0 and /dev/ttyS1, respectively.

zombielinux · July 30, 2019, 3:05am

Followup: This does not work. I’m at a loss as to whats going on here. If anyone can chime in, I’d be really appreciative.

rpress · July 31, 2019, 3:20pm

Have you tried changing your qemu USB emulation to/from USB2 or USB3? Is there any Proxmox configuration you can share?

And I’m a bit confused, you mention regression but you say it’s a brand new HUSBZB-1. Did you ever have it working before?

I have noticed that it is a bit touchy - if I put a USB hub in-between my VM host and the HUSBZB-1 it eventually fails. I’d guess that there is some (probably unintentional) timing requirement in the software.

zombielinux · August 1, 2019, 12:57pm

I have tried changing it between the USB modes. No success.

Its brand new, but has never worked for me on any of my 3 hypervisors.

By regression, I mean, this same issue has been opened before, then closed, but it still persists. Its possible that the issue is a minor firmware change in the stick itself.

I suspect that you’re right as well, that there is some timing issue somewhere.