Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Hass crashes Aeotec Gen 5 zwave stick #5501

Closed
UltraSub opened this issue Jan 22, 2017 · 63 comments
Closed

Hass crashes Aeotec Gen 5 zwave stick #5501

UltraSub opened this issue Jan 22, 2017 · 63 comments

Comments

@UltraSub
Copy link

UltraSub commented Jan 22, 2017

Home Assistant release: 0.40.0
Python release: Python 3.5.2+
OpenZwave: 1.4.2253
Component/platform: zwave
OS: Ubuntu 16.10 running on ESX 6.0.0 U2, Intel NUC6I3SYH

Description of problem:
Restarting Home Assistant results in the Aeotec Gen 5 Z-wave stick needing a poweroff/poweron to start working again. It looks like being hung up at stop of Home Assistant, and reports 0 devices at startup.

Expected:
To be able to restart Home Assistant without the zwave stick hanging up.

Problem-relevant configuration.yaml entries and steps to reproduce:
Zwave logs report the following in the faulty situation:

January 22nd 2017, 10:39:31.266	contrlr	ERROR: Dropping command, expected response not received after 1 attempt(s)
January 22nd 2017, 10:39:31.266	contrlr	Removing current message
January 22nd 2017, 10:39:31.266	contrlr	Notification: Notification - TimeOut
January 22nd 2017, 10:39:30.266	contrlr	Removing current message
January 22nd 2017, 10:39:30.266	contrlr	Notification: Notification - TimeOut
January 22nd 2017, 10:39:30.266	contrlr	ERROR: Dropping command, expected response not received after 1 attempt(s)
January 22nd 2017, 10:39:30.266	contrlr	Sending (Command) message (Callback ID=0x00, Expected Reply=0x56) - FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
January 22nd 2017, 10:39:29.266	contrlr	Notification: Notification - TimeOut
January 22nd 2017, 10:39:29.266	contrlr	Sending (Command) message (Callback ID=0x00, Expected Reply=0x07) - FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
January 22nd 2017, 10:39:29.266	contrlr	Removing current message
January 22nd 2017, 10:39:29.266	contrlr	ERROR: Dropping command, expected response not received after 1 attempt(s)
January 22nd 2017, 10:39:28.266	contrlr	ERROR: Dropping command, expected response not received after 1 attempt(s)
January 22nd 2017, 10:39:28.266	contrlr	Removing current message
January 22nd 2017, 10:39:28.266	contrlr	Notification: Notification - TimeOut
January 22nd 2017, 10:39:28.266	contrlr	Sending (Command) message (Callback ID=0x00, Expected Reply=0x05) - FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
January 22nd 2017, 10:39:27.265	contrlr	ERROR: Dropping command, expected response not received after 1 attempt(s)
January 22nd 2017, 10:39:27.265	contrlr	Sending (Command) message (Callback ID=0x00, Expected Reply=0x20) - FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
January 22nd 2017, 10:39:27.265	contrlr	Notification: Notification - TimeOut
January 22nd 2017, 10:39:27.265	contrlr	Removing current message
January 22nd 2017, 10:39:26.264	contrlr	Sending (Command) message (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
January 22nd 2017, 10:39:26.264	contrlr	Queuing (Command) FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
January 22nd 2017, 10:39:26.264	contrlr	Queuing (Command) FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
January 22nd 2017, 10:39:26.264	contrlr	Queuing (Command) FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
January 22nd 2017, 10:39:26.264	contrlr	Queuing (Command) FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
January 22nd 2017, 10:39:26.264	contrlr	Queuing (Command) FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc

I cannot reproduce this using Domoticz or OZwcp. Restarted those countless times and not a single problem. Restart Home Assistant and the stick dies. No clue where to start troubleshooting.

Extra information;
I symlinked the xml:
/home/hass/.homeassistant/zwcfg_<homeid>.xml -> /srv/hass/src/open-zwave-control-panel/zwcfg_<homeid>.xml
Since Home Assistant wrecked the xml a few times, I figured it didn't need write access and just set read-only for the hass user. After remembering that, I figured that might be a problem, and tried with write access, same result.

As far as I can remember, it looks like this started when I added secure nodes to the network. Might have something to do with it.

Further details, hass is showing clean logs, as is OZW_Log.txt on a shutdown of the network. All looking good. Until trying to restart.

OZW_Log.txt at shutdown by Home Assistant:

2017-01-22 11:08:26.757 Info, mgr,     Manager::WriteConfig completed for driver with home ID of 0xca4e8fa0
2017-01-22 11:08:27.766 Info, mgr,     Driver for controller /dev/ttyUSB-ZStick-5G pending removal
2017-01-22 11:08:27.766 Detail, Notification: DriverRemoved
2017-01-22 11:08:27.766 Always, ***************************************************************************
2017-01-22 11:08:27.766 Always, *********************  Cumulative Network Statistics  *********************
2017-01-22 11:08:27.766 Always, *** General
2017-01-22 11:08:27.766 Always, Driver run time: . .  . 0 days, 0 hours, 22 minutes
2017-01-22 11:08:27.766 Always, Frames processed: . . . . . . . . . . . . . . . . . . . . 203
2017-01-22 11:08:27.766 Always, Total messages successfully received: . . . . . . . . . . 203
2017-01-22 11:08:27.766 Always, Total Messages successfully sent: . . . . . . . . . . . . 50
2017-01-22 11:08:27.767 Always, ACKs received from controller:  . . . . . . . . . . . . . 62
2017-01-22 11:08:27.767 Always, *** Errors
2017-01-22 11:08:27.767 Always, Unsolicited messages received while waiting for ACK:  . . 0
2017-01-22 11:08:27.767 Always, Reads aborted due to timeouts:  . . . . . . . . . . . . . 0
2017-01-22 11:08:27.767 Always, Bad checksum errors:  . . . . . . . . . . . . . . . . . . 0
2017-01-22 11:08:27.767 Always, CANs received from controller:  . . . . . . . . . . . . . 0
2017-01-22 11:08:27.767 Always, NAKs received from controller:  . . . . . . . . . . . . . 0
2017-01-22 11:08:27.767 Always, Out of frame data flow errors:  . . . . . . . . . . . . . 0
2017-01-22 11:08:27.767 Always, Messages retransmitted: . . . . . . . . . . . . . . . . . 0
2017-01-22 11:08:27.767 Always, Messages dropped and not delivered: . . . . . . . . . . . 2
2017-01-22 11:08:27.767 Always, ***************************************************************************
2017-01-22 11:08:29.773 Info, mgr,     Driver for controller /dev/ttyUSB-ZStick-5G removed
2017-01-22 11:08:30.773 Error, mgr,     Manager::GetDriver failed - Home ID 0xca4e8fa0 is unknown
2017-01-22 11:08:30.773 Warning, Exception: Manager.cpp:373 - 100 - Invalid HomeId passed to GetDriver
2017-01-22 11:08:30.773 Info, mgr,     GetSendQueueCount() failed - _homeId -900821088 not found

Shutdown by ozwcp:

2017-01-22 11:13:56.710 Info, mgr,     Driver for controller /dev/ttyUSB-ZStick-5G pending removal
2017-01-22 11:13:56.710 Detail, Notification: DriverRemoved
2017-01-22 11:13:56.710 Info, Notification: type 27 home ca4e8fa0 node 0 genre 0 class 0 instance 0 index 0 type 0
2017-01-22 11:13:56.710 Always, ***************************************************************************
2017-01-22 11:13:56.710 Always, *********************  Cumulative Network Statistics  *********************
2017-01-22 11:13:56.710 Always, *** General
2017-01-22 11:13:56.710 Always, Driver run time: . .  . 0 days, 0 hours, 2 minutes
2017-01-22 11:13:56.710 Always, Frames processed: . . . . . . . . . . . . . . . . . . . . 128
2017-01-22 11:13:56.710 Always, Total messages successfully received: . . . . . . . . . . 128
2017-01-22 11:13:56.710 Always, Total Messages successfully sent: . . . . . . . . . . . . 48
2017-01-22 11:13:56.710 Always, ACKs received from controller:  . . . . . . . . . . . . . 56
2017-01-22 11:13:56.711 Always, *** Errors
2017-01-22 11:13:56.711 Always, Unsolicited messages received while waiting for ACK:  . . 0
2017-01-22 11:13:56.711 Always, Reads aborted due to timeouts:  . . . . . . . . . . . . . 0
2017-01-22 11:13:56.711 Always, Bad checksum errors:  . . . . . . . . . . . . . . . . . . 0
2017-01-22 11:13:56.711 Always, CANs received from controller:  . . . . . . . . . . . . . 0
2017-01-22 11:13:56.711 Always, NAKs received from controller:  . . . . . . . . . . . . . 0
2017-01-22 11:13:56.711 Always, Out of frame data flow errors:  . . . . . . . . . . . . . 0
2017-01-22 11:13:56.711 Always, Messages retransmitted: . . . . . . . . . . . . . . . . . 0
2017-01-22 11:13:56.711 Always, Messages dropped and not delivered: . . . . . . . . . . . 2
2017-01-22 11:13:56.711 Always, ***************************************************************************
2017-01-22 11:13:58.724 Info, mgr,     Driver for controller /dev/ttyUSB-ZStick-5G removed

Additional info:
Just a side thought, why do we restart the zwave network every time we need to restart for a config change?

@turbokongen
Copy link
Contributor

Start by checking if stop and then start home assistant produces the same error. The log you provide looks good. All normal. What does the ozw_log.txt show after restart when the error is present?

@turbokongen
Copy link
Contributor

I mean, the complete logoutput for ozw_log

@UltraSub
Copy link
Author

UltraSub commented Jan 22, 2017

Restart and stop/start both produce the same error.
Couldn't reproduce the bug 4 times though when I tried to produce the log below. 5th time was the charm. Most of the time it is happening, and I'm lucky if it works. I'm already used to stop HA, unplug and plug the stick, and then start it again (that always works).

The full log for starting with a failing stick:

2017-01-22 16:50:45.966 Always, OpenZwave Version 1.4.2253 Starting Up
2017-01-22 16:50:46.360 Info, Setting Up Provided Network Key for Secure Communications
2017-01-22 16:50:46.360 Info, mgr,     Added driver for controller /dev/ttyUSB-ZStick-5G
2017-01-22 16:50:46.362 Info,   Opening controller /dev/ttyUSB-ZStick-5G
2017-01-22 16:50:46.362 Info, Trying to open serial port /dev/ttyUSB-ZStick-5G (attempt 1)
2017-01-22 16:50:46.379 Info, Serial port /dev/ttyUSB-ZStick-5G opened (attempt 1)
2017-01-22 16:50:46.379 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2017-01-22 16:50:46.379 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2017-01-22 16:50:46.380 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2017-01-22 16:50:46.380 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2017-01-22 16:50:46.380 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2017-01-22 16:50:46.380 Detail, 
2017-01-22 16:50:46.380 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2017-01-22 16:50:46.390 Detail, contrlr,   Received: 0x01, 0x10, 0x01, 0x15, 0x5a, 0x2d, 0x57, 0x61, 0x76, 0x65, 0x20, 0x33, 0x2e, 0x39, 0x35, 0x00, 0x01, 0x99
2017-01-22 16:50:46.390 Detail, 
2017-01-22 16:50:46.390 Info, contrlr, Received reply to FUNC_ID_ZW_GET_VERSION:
2017-01-22 16:50:46.390 Info, contrlr,     Static Controller library, version Z-Wave 3.95
2017-01-22 16:50:46.390 Detail, Node045,   Expected reply was received
2017-01-22 16:50:46.390 Detail, Node045,   Message transaction complete
2017-01-22 16:50:46.390 Detail, 
2017-01-22 16:50:46.390 Detail, contrlr, Removing current message
2017-01-22 16:50:46.390 Detail, 
2017-01-22 16:50:46.390 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x20) - FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2017-01-22 16:50:46.398 Detail, contrlr,   Received: 0x01, 0x08, 0x01, 0x20, 0xca, 0x4e, 0x8f, 0xa0, 0x01, 0x7c
2017-01-22 16:50:46.398 Detail, 
2017-01-22 16:50:46.398 Info, contrlr, Received reply to FUNC_ID_ZW_MEMORY_GET_ID. Home ID = 0xca4e8fa0.  Our node ID = 1
2017-01-22 16:50:46.398 Detail, Node078,   Expected reply was received
2017-01-22 16:50:46.398 Detail, Node078,   Message transaction complete
2017-01-22 16:50:46.398 Detail, 
2017-01-22 16:50:46.398 Detail, contrlr, Removing current message
2017-01-22 16:50:46.398 Detail, 
2017-01-22 16:50:46.398 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x05) - FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2017-01-22 16:50:46.411 Detail, contrlr,   Received: 0x01, 0x04, 0x01, 0x05, 0x08, 0xf7
2017-01-22 16:50:46.411 Detail, 
2017-01-22 16:50:46.412 Info, contrlr, Received reply to FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES:
2017-01-22 16:50:46.412 Info, contrlr,     There is no SUC ID Server (SIS) in this network.
2017-01-22 16:50:46.412 Info, contrlr,     The PC controller is a primary controller.
2017-01-22 16:50:46.412 Detail, Node247,   Expected reply was received
2017-01-22 16:50:46.412 Detail, Node247,   Message transaction complete
2017-01-22 16:50:46.412 Detail, 
2017-01-22 16:50:46.412 Detail, contrlr, Removing current message
2017-01-22 16:50:46.412 Detail, 
2017-01-22 16:50:46.412 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x07) - FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2017-01-22 16:50:47.412 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-01-22 16:50:47.412 Detail, contrlr, Removing current message
2017-01-22 16:50:47.412 Detail, contrlr, Notification: Notification - TimeOut
2017-01-22 16:50:47.413 Detail, 
2017-01-22 16:50:47.413 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x56) - FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2017-01-22 16:50:48.413 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-01-22 16:50:48.413 Detail, contrlr, Removing current message
2017-01-22 16:50:48.413 Detail, contrlr, Notification: Notification - TimeOut

And then it just sits there.

@UltraSub
Copy link
Author

Looking at the logs for shutting down, I notice that HA shutting down has a few extra lines:

2017-01-22 11:08:29.773 Info, mgr,     Driver for controller /dev/ttyUSB-ZStick-5G removed
2017-01-22 11:08:30.773 Error, mgr,     Manager::GetDriver failed - Home ID 0xca4e8fa0 is unknown
2017-01-22 11:08:30.773 Warning, Exception: Manager.cpp:373 - 100 - Invalid HomeId passed to GetDriver
2017-01-22 11:08:30.773 Info, mgr,     GetSendQueueCount() failed - _homeId -900821088 not found

Which shutting with Domoticz or ozwcp doesn't produce. Home ID 0xca4e8fa0 is ok, but the 900821088 part? I've never seen that anywhere. Is HA trying do something here?

@turbokongen
Copy link
Contributor

Ok, after looking at the code and logs I have found the following:

The log lines that are printed in HomeAssistant are printed because we use the python-openzwave wrapper, and the wrapper issues some extra commands at network stop to check that the network is really stopped. https://github.com/OpenZWave/python-openzwave/blob/master/src-api/openzwave/network.py#L390-L431
This is not used by OZWCP nor domoticz, because they access OZW directly.
So for some reason your stick does not shutdown properly, and is not releasing the connection after its closed.
Are there anybody else having this problem with the Aeon Gen 5 Z-stick?
I have a slight feeling that this might be a permission issue. All parts of OZW, python-openzwave and hass should be set with full privileges for the hass user.

@UltraSub
Copy link
Author

Thanks! Will double check all permissions and test.
As I said before, I set the ozwcfg_xx.xml to read-only for hass since it messed it up quite badly once and I lost all my namings for devices. I did test this however with write access and it reproduced the same problem.

Will double check all settings and make sure hass hass write everywhere and report back. Thanks for looking into it!

@UltraSub
Copy link
Author

Ok, checked everything.
All hass.nogroup for:

  • /srv/hass/lib/python3.5/site-packages/openzwave-0.3.1-py3.5.egg
  • /srv/hass/src/python-openzwave
  • /home/hass/.homeassistant

As I said:
lrwxrwxrwx 1 hass nogroup 59 Nov 25 05:46 zwcfg_0xca4e8fa0.xml -> /srv/hass/src/open-zwave-control-panel/zwcfg_0xca4e8fa0.xml does not have full access:
-rw-r--r-- 1 root root 219894 Jan 22 11:13 /srv/hass/src/open-zwave-control-panel/zwcfg_0xca4e8fa0.xml but I tested with it having hass.nogroup as owner, and it produced the same erratic behaviour unfortunately. So I changed it back to read-only as HA messed up the xml quite badly a few times. That might be due to this issue, where HA updates the xml if stopped with what it thinks the values should be (0 devices returned so rewrite the xml to 0 devices).

@turbokongen
Copy link
Contributor

The thing is that this all happens outside HA. There is no Zwave managing code in HA, that is all done by OZW. And we tap in to the values of the network. Meaning if the network provides no devices, HA will not see any devices, and OZW will save the network config to be 0 at stop.
My guess is permissions, a faulty z-stick or a bug in OZW/python-openzwave. That is why I'm curious if anybody else has this problem. Most people seems to be using the Z-Stick or the UZB1.

@UltraSub
Copy link
Author

Ok, I see where you're coming from, and I agree.
What I don't get however is why this only happens using HA. The only difference, like you already said, is python-openzwave. Domoticz and OZwcp are not using that.
And if HA stops and writes all devices back to 0 after not seeing any devices, that is also python-openzwave. So I hope someone else can reproduce this, as I already checked all permissions and they seem to be ok.
Or a faulty stick.. hmm. You never know. I'll wait a bit to see if someone else can reproduce this and then might go for an RMA.

@getsmokes
Copy link

First time github user here, I've got the same error.

Started with a fresh install of raspbian with the AIOI, 90% of restarts end with a crash. Rebooting the pi fixes this and everything loads correctly.

@UltraSub
Copy link
Author

UltraSub commented Jan 23, 2017

Can you please confirm that:

  • you are also using a Aeotec Gen5 stick
  • the stick crashes on stop of hass

If the above are true, can you confirm that removing the stick and plugging it in again also solves the problem? (Rebooting could solve other problems if there are any, which wouldn't necessarily isolate this issue)

@getsmokes
Copy link

Yeah, I'm using an Aeotec Gen5 and it crashes when stopping. However I'm unable to reproduce the same results this evening.

@infamy
Copy link
Contributor

infamy commented Jan 31, 2017

Have a very similar setup. ESXi on a mac mini, with a Aeotec Gen 5 usb stick. And i'm not running into this issue.

Do you have any secure zwave devices? (door locks etc?) I also noticed that if some of my nodes don't have great signal the shutdown process can take a lot longer.

@UltraSub
Copy link
Author

Yes, I'm running two secure devices. A Fibaro Wall Plug Gen 5 and a motion sensor Gen 5. And I have a strong feeling this started when those were added. I had to add the network key to a second file by the way, which might be interesting.

When I first added the network key I did it here:
/srv/hass/src/python-openzwave/openzwave/config/options.xml
Started ozwcp and I noticed the key being loaded and working, as the nonces passed in the logs.

After that I noticed HA not being able to switch this devices. After a lot of debugging I noticed there was a second options.xml, which HA was using:
/srv/hass/lib/python3.5/site-packages/libopenzwave-0.3.1-py3.5-linux-x86_64.egg/config/options.xml
Added the network key there also, and HA loaded the key and started working. I found it kinda odd that HA was using options.xml in this directory while everything else was being loaded from the first path. Maybe this info gets us a bit further?

Signal isn't an issue, the devices are close to the controller and working fine. It's only the shutdown by HA which locks the stick.

@UltraSub
Copy link
Author

UltraSub commented Jan 31, 2017

Hmm.. wait.. triggering myself. I changed openzwave configs for the two gen5 nodes to get them working. Those changes were done in /srv/hass/src/python-openzwave/openzwave/config/fibaro/. Need to check if HA is using the old non-working configs which might be located in /srv/hass/lib/python3.5/site-packages/libopenzwave-0.3.1-py3.5-linux-x86_64.egg/config/ as that might explain a bit.

/edit
See that I didn't specify the config path in the zwave section:

zwave:
  usb_path: /dev/ttyUSB-ZStick-5G

Did that before, must have removed it.

config_path (Optional): The path to the Python OpenZWave configuration files. Defaults to the folder config in your Python OpenZWave install directory.

This could be a problem, considering the changes to configs above. Will test later tonight.

@UltraSub
Copy link
Author

UltraSub commented Feb 1, 2017

Ok, checked, I did provide a config_path. I just didn't pushed it to my GitLab, that's why I missed it above.

zwave:
  usb_path: /dev/ttyUSB-ZStick-5G
  config_path: /srv/hass/src/python-openzwave/openzwave/config

@UltraSub
Copy link
Author

UltraSub commented Feb 8, 2017

Interesting.. Stop HA, stick "crashes", start HA, no zwave as logs above show. Stop HA, start again, stick works and reports devices. Was able to reproduce that multiple times yesterday. Running out of options to debug this problem. Checked everything I could think off. Pretty annoying problem.

@andrey-git
Copy link
Contributor

Did you add the secured devices via HA or via other means?
When I added mine via ozwcp I had the same problem. Removed and secure added via HA - works fine.

@UltraSub
Copy link
Author

UltraSub commented Feb 8, 2017

I added them via ozwcp just like all my devices. Now that's strange if that's the case. And it is not cool to test because of id changes. Ok, not that hard to do but still.
You had exactly the same you say? Well I might need to exclude the devices and include them again. This might have something to do with the different paths/config used by open zwave / python / venvs?

@andrey-git
Copy link
Contributor

I'm not sure it was exactly the same, but I had issues with secure device added via ozwcp probably because they looked at different options.xml

@UltraSub
Copy link
Author

Upgraded to 0.40.0, pulled python-openzwave for latest changes and recompiled it.
Checked which files are used by HA and what files by ozwcp. Using the same config dir and options.xml. Still the same issues. Don't know where to look anymore, tried everything I can think of.
This is so annoying that I'm even hesitant to add or change something in HA, since I can't restart without removing the stick. Tried the same stick in a Domoticz VM, on the same ESX host using the same usb port and I cannot reproduce it.

@balloobbot
Copy link

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.

Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍

@nitrag
Copy link

nitrag commented Jun 1, 2017

I am having this issue, I think. I'm a new user. Running Ubuntu 16.04 VM on top of ESXI with the Aeon Gen5 usb plugged in.

I'm able to add a node (light) in HA - it blinks to confirm it's been added - but I don't see a device anywhere in HA. I am also able to remove it.

As far as I know I'm not getting a crash, just this:
ERROR: Dropping command, expected response not received after 1 attempt(s)

Here is the logs, the last thing I did was Stop Network.

2017-05-30 23:39:20.825 Always, OpenZwave Version 1.4.2508 Starting Up
2017-05-30 23:39:26.674 Info, Setting Up Provided Network Key for Secure Communications
2017-05-30 23:39:26.674 Warning, Failed - Network Key Not Set
2017-05-30 23:39:26.674 Info, mgr,     Added driver for controller /dev/ttyACM0
2017-05-30 23:39:26.674 Info,   Opening controller /dev/ttyACM0
2017-05-30 23:39:26.675 Info, Trying to open serial port /dev/ttyACM0 (attempt 1)
2017-05-30 23:39:26.949 Info, Serial port /dev/ttyACM0 opened (attempt 1)
2017-05-30 23:39:26.949 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2017-05-30 23:39:26.949 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2017-05-30 23:39:26.949 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2017-05-30 23:39:26.949 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2017-05-30 23:39:26.949 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2017-05-30 23:39:26.950 Detail, 
2017-05-30 23:39:26.950 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2017-05-30 23:39:26.955 Detail, contrlr,   Received: 0x01, 0x10, 0x01, 0x15, 0x5a, 0x2d, 0x57, 0x61, 0x76, 0x65, 0x20, 0x33, 0x2e, 0x39, 0x35, 0x00, 0x01, 0x99
2017-05-30 23:39:26.955 Detail, 
2017-05-30 23:39:26.955 Info, contrlr, Received reply to FUNC_ID_ZW_GET_VERSION:
2017-05-30 23:39:26.955 Info, contrlr,     Static Controller library, version Z-Wave 3.95
2017-05-30 23:39:26.955 Detail, Node045,   Expected reply was received
2017-05-30 23:39:26.955 Detail, Node045,   Message transaction complete
2017-05-30 23:39:26.955 Detail, 
2017-05-30 23:39:26.955 Detail, contrlr, Removing current message
2017-05-30 23:39:26.955 Detail, 
2017-05-30 23:39:26.955 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x20) - FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2017-05-30 23:39:26.961 Detail, contrlr,   Received: 0x01, 0x08, 0x01, 0x20, 0xec, 0x47, 0xea, 0x6c, 0x01, 0xfa
2017-05-30 23:39:26.961 Detail, 
2017-05-30 23:39:26.961 Info, contrlr, Received reply to FUNC_ID_ZW_MEMORY_GET_ID. Home ID = 0xec47ea6c.  Our node ID = 1
2017-05-30 23:39:26.961 Detail, Node071,   Expected reply was received
2017-05-30 23:39:26.961 Detail, Node071,   Message transaction complete
2017-05-30 23:39:26.961 Detail, 
2017-05-30 23:39:26.961 Detail, contrlr, Removing current message
2017-05-30 23:39:26.961 Detail, 
2017-05-30 23:39:26.961 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x05) - FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2017-05-30 23:39:26.966 Detail, contrlr,   Received: 0x01, 0x04, 0x01, 0x05, 0x28, 0xd7
2017-05-30 23:39:26.966 Detail, 
2017-05-30 23:39:26.966 Info, contrlr, Received reply to FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES:
2017-05-30 23:39:26.966 Info, contrlr,     There is no SUC ID Server (SIS) in this network.
2017-05-30 23:39:26.966 Info, contrlr,     The PC controller is a primary controller.
2017-05-30 23:39:26.966 Detail, Node215,   Expected reply was received
2017-05-30 23:39:26.966 Detail, Node215,   Message transaction complete
2017-05-30 23:39:26.966 Detail, 
2017-05-30 23:39:26.966 Detail, contrlr, Removing current message
2017-05-30 23:39:26.966 Detail, 
2017-05-30 23:39:26.966 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x07) - FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2017-05-30 23:39:26.974 Detail, contrlr,   Received: 0x01, 0x2b, 0x01, 0x07, 0x01, 0x00, 0x00, 0x86, 0x01, 0x01, 0x00, 0x5a, 0xfe, 0x81, 0xff, 0x88, 0x4f, 0x1f, 0x00, 0x00, 0xfb, 0x9f, 0x7d, 0xa0, 0x67, 0x00, 0x00, 0x80, 0x00, 0x80, 0x86, 0x00, 0x00, 0x00, 0xe8, 0x73, 0x00, 0x00, 0x0e, 0x00, 0x00, 0x60, 0x00, 0x00, 0xfa
2017-05-30 23:39:26.974 Detail, 
2017-05-30 23:39:26.974 Info, contrlr,  Received reply to FUNC_ID_SERIAL_API_GET_CAPABILITIES
2017-05-30 23:39:26.974 Info, contrlr,     Serial API Version:   1.0
2017-05-30 23:39:26.974 Info, contrlr,     Manufacturer ID:      0x0086
2017-05-30 23:39:26.974 Info, contrlr,     Product Type:         0x0101
2017-05-30 23:39:26.974 Info, contrlr,     Product ID:           0x005a
2017-05-30 23:39:26.974 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_RANDOM: 0x01, 0x04, 0x00, 0x1c, 0x20, 0xc7
2017-05-30 23:39:26.974 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_INIT_DATA: 0x01, 0x03, 0x00, 0x02, 0xfe
2017-05-30 23:39:26.974 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_SET_TIMEOUTS: 0x01, 0x05, 0x00, 0x06, 0x64, 0x0f, 0x97
2017-05-30 23:39:26.975 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_APPL_NODE_INFORMATION: 0x01, 0x07, 0x00, 0x03, 0x01, 0x02, 0x01, 0x00, 0xf9
2017-05-30 23:39:26.975 Detail,   Expected reply was received
2017-05-30 23:39:26.975 Detail,   Message transaction complete
2017-05-30 23:39:26.975 Detail, 
2017-05-30 23:39:26.975 Detail, contrlr, Removing current message
2017-05-30 23:39:26.975 Detail, 
2017-05-30 23:39:26.975 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x56) - FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2017-05-30 23:39:26.981 Detail, contrlr,   Received: 0x01, 0x04, 0x01, 0x56, 0x00, 0xac
2017-05-30 23:39:26.981 Detail, 
2017-05-30 23:39:26.981 Info, contrlr, Received reply to GET_SUC_NODE_ID.  Node ID = 0
2017-05-30 23:39:26.981 Info, Controller Does not Support SUC - Cannot Setup Controller as SUC Node
2017-05-30 23:39:26.981 Detail, Node172,   Expected reply was received
2017-05-30 23:39:26.981 Detail, Node172,   Message transaction complete
2017-05-30 23:39:26.981 Detail, 
2017-05-30 23:39:26.981 Detail, contrlr, Removing current message
2017-05-30 23:39:26.981 Detail, 
2017-05-30 23:39:26.981 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x1c) - FUNC_ID_ZW_GET_RANDOM: 0x01, 0x04, 0x00, 0x1c, 0x20, 0xc7
2017-05-30 23:39:27.043 Detail, contrlr,   Received: 0x01, 0x25, 0x01, 0x1c, 0x01, 0x20, 0xee, 0x2c, 0x12, 0x23, 0x5a, 0x7d, 0x50, 0x21, 0x8a, 0x4b, 0x8a, 0xde, 0x4b, 0x1d, 0x0a, 0x74, 0x65, 0x3e, 0x83, 0xb6, 0x2a, 0x0f, 0x29, 0x9d, 0x63, 0x6e, 0x26, 0x31, 0x9e, 0xb4, 0x1f, 0xea, 0xc4
2017-05-30 23:39:27.043 Detail, 
2017-05-30 23:39:27.043 Info, contrlr, Received reply to FUNC_ID_ZW_GET_RANDOM: true
2017-05-30 23:39:27.043 Detail, Node032,   Expected reply was received
2017-05-30 23:39:27.043 Detail, Node032,   Message transaction complete
2017-05-30 23:39:27.043 Detail, 
2017-05-30 23:39:27.043 Detail, contrlr, Removing current message
2017-05-30 23:39:27.043 Detail, 
2017-05-30 23:39:27.043 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x02) - FUNC_ID_SERIAL_API_GET_INIT_DATA: 0x01, 0x03, 0x00, 0x02, 0xfe
2017-05-30 23:39:27.145 Detail, contrlr,   Received: 0x01, 0x25, 0x01, 0x02, 0x05, 0x00, 0x1d, 0x01, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x05, 0x00, 0xc5
2017-05-30 23:39:27.145 Detail, 
2017-05-30 23:39:27.145 Info, mgr,     Driver with Home ID of 0xec47ea6c is now ready.
2017-05-30 23:39:27.145 Info, 
2017-05-30 23:39:27.146 Info, contrlr, Received reply to FUNC_ID_SERIAL_API_GET_INIT_DATA:
2017-05-30 23:39:27.146 Info, contrlr,     Node 001 - Known
2017-05-30 23:39:27.146 Detail, Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=CacheLoad live=1
2017-05-30 23:39:27.146 Detail, Node001, QueryStage_CacheLoad
2017-05-30 23:39:27.146 Info, Node001, Node Identity Codes: 0086:0101:005a
2017-05-30 23:39:27.146 Detail, Node001, QueryStage_Associations
2017-05-30 23:39:27.146 Detail, Node001, QueryStage_Neighbors
2017-05-30 23:39:27.146 Detail, contrlr, Requesting routing info (neighbor list) for Node 1
2017-05-30 23:39:27.146 Detail, Node001, Queuing (Command) Get Routing Info (Node=1): 0x01, 0x07, 0x00, 0x80, 0x01, 0x00, 0x00, 0x03, 0x7a
2017-05-30 23:39:27.146 Detail, Node001, Queuing (Query) Query Stage Complete (Neighbors)
2017-05-30 23:39:27.146 Detail,   Expected reply was received
2017-05-30 23:39:27.146 Detail,   Message transaction complete
2017-05-30 23:39:27.146 Detail, 
2017-05-30 23:39:27.146 Detail, contrlr, Removing current message
2017-05-30 23:39:27.146 Detail, Node001, Notification: DriverReady
2017-05-30 23:39:27.146 Detail, Node001, Notification: NodeAdded
2017-05-30 23:39:27.149 Detail, Node001, Notification: NodeProtocolInfo
2017-05-30 23:39:27.150 Detail, Node001, Notification: EssentialNodeQueriesComplete
2017-05-30 23:39:27.150 Detail, Node001, Notification: ValueAdded
2017-05-30 23:39:27.150 Detail, Node001, Notification: NodeNaming
2017-05-30 23:39:27.150 Detail, 
2017-05-30 23:39:27.150 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x06) - FUNC_ID_SERIAL_API_SET_TIMEOUTS: 0x01, 0x05, 0x00, 0x06, 0x64, 0x0f, 0x97
2017-05-30 23:39:27.156 Detail, contrlr,   Received: 0x01, 0x05, 0x01, 0x06, 0x64, 0x0f, 0x96
2017-05-30 23:39:27.156 Detail, 
2017-05-30 23:39:27.156 Info, contrlr, Received reply to FUNC_ID_SERIAL_API_SET_TIMEOUTS
2017-05-30 23:39:27.156 Detail, Node015,   Expected reply was received
2017-05-30 23:39:27.156 Detail, Node015,   Message transaction complete
2017-05-30 23:39:27.156 Detail, 
2017-05-30 23:39:27.156 Detail, contrlr, Removing current message
2017-05-30 23:39:27.156 Detail, 
2017-05-30 23:39:27.156 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x00) - FUNC_ID_SERIAL_API_APPL_NODE_INFORMATION: 0x01, 0x07, 0x00, 0x03, 0x01, 0x02, 0x01, 0x00, 0xf9
2017-05-30 23:39:27.161 Detail, contrlr, Removing current message
2017-05-30 23:39:27.161 Detail, 
2017-05-30 23:39:27.161 Info, Node001, Sending (Command) message (Callback ID=0x00, Expected Reply=0x80) - Get Routing Info (Node=1): 0x01, 0x07, 0x00, 0x80, 0x01, 0x00, 0x00, 0x03, 0x7a
2017-05-30 23:39:27.171 Detail, Node001,   Received: 0x01, 0x20, 0x01, 0x80, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x5e
2017-05-30 23:39:27.171 Detail, 
2017-05-30 23:39:27.171 Info, Node001, Received reply to FUNC_ID_ZW_GET_ROUTING_INFO
2017-05-30 23:39:27.171 Info, Node001,     Neighbors of this node are:
2017-05-30 23:39:27.171 Info, Node001,  (none reported)
2017-05-30 23:39:27.171 Detail,   Expected reply was received
2017-05-30 23:39:27.171 Detail,   Message transaction complete
2017-05-30 23:39:27.171 Detail, 
2017-05-30 23:39:27.171 Detail, Node001, Removing current message
2017-05-30 23:39:27.171 Detail, Node001, Query Stage Complete (Neighbors)
2017-05-30 23:39:27.171 Detail, Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Session live=1
2017-05-30 23:39:27.171 Detail, Node001, QueryStage_Session
2017-05-30 23:39:27.171 Detail, Node001, QueryStage_Dynamic
2017-05-30 23:39:27.171 Detail, Node001, QueryStage_Configuration
2017-05-30 23:39:27.171 Detail, Node001, QueryStage_Complete
2017-05-30 23:39:27.172 Warning, CheckCompletedNodeQueries m_allNodesQueried=0 m_awakeNodesQueried=0
2017-05-30 23:39:27.172 Warning, CheckCompletedNodeQueries all=1, deadFound=0 sleepingOnly=1
2017-05-30 23:39:27.172 Info,          Node query processing complete.
2017-05-30 23:39:27.172 Detail, Node001, Notification: NodeQueriesComplete
2017-05-30 23:39:27.172 Detail, contrlr, Notification: AllNodesQueried
2017-05-31 01:00:00.677 Detail, Node001, Queuing (Controller) Request Node Neighbor Update
2017-05-31 01:00:00.677 Info, Requesting Neighbor Update for node 1
2017-05-31 01:00:00.677 Detail, Node001, Queuing (Command) ControllerCommand_RequestNodeNeighborUpdate (Node=1): 0x01, 0x05, 0x00, 0x48, 0x01, 0x0a, 0xb9
2017-05-31 01:00:00.677 Detail, Notification: ControllerCommand - Starting
2017-05-31 01:00:00.677 Detail, 
2017-05-31 01:00:00.677 Info, Node001, Sending (Command) message (Callback ID=0x0a, Expected Reply=0x48) - ControllerCommand_RequestNodeNeighborUpdate (Node=1): 0x01, 0x05, 0x00, 0x48, 0x01, 0x0a, 0xb9
2017-05-31 01:00:01.677 Error, Node001, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-05-31 01:00:01.677 Detail, Node001, Removing current message
2017-05-31 01:00:01.677 Detail, Node001, Notification: Notification - TimeOut
2017-05-31 01:00:01.678 Detail, Notification: ControllerCommand - Error - Failed
2017-06-01 01:00:00.377 Detail, Node001, Queuing (Controller) Request Node Neighbor Update
2017-06-01 01:00:00.377 Info, Requesting Neighbor Update for node 1
2017-06-01 01:00:00.377 Detail, Node001, Queuing (Command) ControllerCommand_RequestNodeNeighborUpdate (Node=1): 0x01, 0x05, 0x00, 0x48, 0x01, 0x0b, 0xb8
2017-06-01 01:00:00.377 Detail, Notification: ControllerCommand - Starting
2017-06-01 01:00:00.378 Detail, 
2017-06-01 01:00:00.378 Info, Node001, Sending (Command) message (Callback ID=0x0b, Expected Reply=0x48) - ControllerCommand_RequestNodeNeighborUpdate (Node=1): 0x01, 0x05, 0x00, 0x48, 0x01, 0x0b, 0xb8
2017-06-01 01:00:01.378 Error, Node001, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-06-01 01:00:01.378 Detail, Node001, Removing current message
2017-06-01 01:00:01.378 Detail, Node001, Notification: Notification - TimeOut
2017-06-01 01:00:01.378 Detail, Notification: ControllerCommand - Error - Failed
2017-06-01 15:09:38.252 Detail, Queuing (Controller) Add Device
2017-06-01 15:09:38.252 Info, Add Device
2017-06-01 15:09:38.252 Detail, contrlr, Queuing (Command) ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0c, 0x7d
2017-06-01 15:09:38.252 Detail, Notification: ControllerCommand - Starting
2017-06-01 15:09:38.252 Detail, 
2017-06-01 15:09:38.252 Info, contrlr, Sending (Command) message (Callback ID=0x0c, Expected Reply=0x4a) - ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0c, 0x7d
2017-06-01 15:09:39.252 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-06-01 15:09:39.252 Detail, contrlr, Removing current message
2017-06-01 15:09:39.252 Detail, contrlr, Notification: Notification - TimeOut
2017-06-01 15:09:39.253 Detail, Notification: ControllerCommand - Error - Failed
2017-06-01 15:12:10.714 Detail, Queuing (Controller) Add Device
2017-06-01 15:12:10.714 Info, Add Device
2017-06-01 15:12:10.714 Detail, contrlr, Queuing (Command) ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0d, 0x7c
2017-06-01 15:12:10.714 Detail, Notification: ControllerCommand - Starting
2017-06-01 15:12:10.715 Detail, 
2017-06-01 15:12:10.715 Info, contrlr, Sending (Command) message (Callback ID=0x0d, Expected Reply=0x4a) - ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0d, 0x7c
2017-06-01 15:12:11.715 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-06-01 15:12:11.715 Detail, contrlr, Removing current message
2017-06-01 15:12:11.715 Detail, contrlr, Notification: Notification - TimeOut
2017-06-01 15:12:11.715 Detail, Notification: ControllerCommand - Error - Failed
2017-06-01 15:13:53.842 Detail, Queuing (Controller) Remove Device
2017-06-01 15:13:53.842 Info, Remove Device
2017-06-01 15:13:53.842 Detail, contrlr, Queuing (Command) ControllerCommand_RemoveDevice: 0x01, 0x05, 0x00, 0x4b, 0x81, 0x0e, 0x3e
2017-06-01 15:13:53.842 Detail, Notification: ControllerCommand - Starting
2017-06-01 15:13:53.842 Detail, 
2017-06-01 15:13:53.842 Info, contrlr, Sending (Command) message (Callback ID=0x0e, Expected Reply=0x4b) - ControllerCommand_RemoveDevice: 0x01, 0x05, 0x00, 0x4b, 0x81, 0x0e, 0x3e
2017-06-01 15:13:54.842 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-06-01 15:13:54.842 Detail, contrlr, Removing current message
2017-06-01 15:13:54.842 Detail, contrlr, Notification: Notification - TimeOut
2017-06-01 15:13:54.842 Detail, Notification: ControllerCommand - Error - Failed
2017-06-01 15:14:12.390 Detail, Queuing (Controller) Remove Device
2017-06-01 15:14:12.390 Info, Remove Device
2017-06-01 15:14:12.390 Detail, contrlr, Queuing (Command) ControllerCommand_RemoveDevice: 0x01, 0x05, 0x00, 0x4b, 0x81, 0x0f, 0x3f
2017-06-01 15:14:12.390 Detail, Notification: ControllerCommand - Starting
2017-06-01 15:14:12.390 Detail, 
2017-06-01 15:14:12.390 Info, contrlr, Sending (Command) message (Callback ID=0x0f, Expected Reply=0x4b) - ControllerCommand_RemoveDevice: 0x01, 0x05, 0x00, 0x4b, 0x81, 0x0f, 0x3f
2017-06-01 15:14:13.390 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-06-01 15:14:13.390 Detail, contrlr, Removing current message
2017-06-01 15:14:13.390 Detail, contrlr, Notification: Notification - TimeOut
2017-06-01 15:14:13.391 Detail, Notification: ControllerCommand - Error - Failed
2017-06-01 15:14:36.108 Detail, Queuing (Controller) Add Device
2017-06-01 15:14:36.108 Info, Add Device
2017-06-01 15:14:36.108 Detail, contrlr, Queuing (Command) ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x10, 0x61
2017-06-01 15:14:36.108 Detail, Notification: ControllerCommand - Starting
2017-06-01 15:14:36.108 Detail, 
2017-06-01 15:14:36.108 Info, contrlr, Sending (Command) message (Callback ID=0x10, Expected Reply=0x4a) - ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x10, 0x61
2017-06-01 15:14:37.108 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-06-01 15:14:37.108 Detail, contrlr, Removing current message
2017-06-01 15:14:37.108 Detail, contrlr, Notification: Notification - TimeOut
2017-06-01 15:14:37.108 Detail, Notification: ControllerCommand - Error - Failed
2017-06-01 15:17:04.536 Detail, Queuing (Controller) Add Device
2017-06-01 15:17:04.537 Info, Add Device
2017-06-01 15:17:04.537 Detail, contrlr, Queuing (Command) ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x11, 0x60
2017-06-01 15:17:04.537 Detail, Notification: ControllerCommand - Starting
2017-06-01 15:17:04.537 Detail, 
2017-06-01 15:17:04.537 Info, contrlr, Sending (Command) message (Callback ID=0x11, Expected Reply=0x4a) - ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x11, 0x60
2017-06-01 15:17:05.537 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-06-01 15:17:05.537 Detail, contrlr, Removing current message
2017-06-01 15:17:05.537 Detail, contrlr, Notification: Notification - TimeOut
2017-06-01 15:17:05.537 Detail, Notification: ControllerCommand - Error - Failed
2017-06-01 15:23:04.632 Info, mgr,     Manager::WriteConfig completed for driver with home ID of 0xec47ea6c
2017-06-01 15:23:05.633 Info, mgr,     Driver for controller /dev/ttyACM0 pending removal
2017-06-01 15:23:05.633 Detail, Notification: DriverRemoved
2017-06-01 15:23:05.633 Always, ***************************************************************************
2017-06-01 15:23:05.633 Always, *********************  Cumulative Network Statistics  *********************
2017-06-01 15:23:05.633 Always, *** General
2017-06-01 15:23:05.633 Always, Driver run time: . .  . 1 days, 15 hours, 43 minutes
2017-06-01 15:23:05.633 Always, Frames processed: . . . . . . . . . . . . . . . . . . . . 9
2017-06-01 15:23:05.633 Always, Total messages successfully received: . . . . . . . . . . 9
2017-06-01 15:23:05.633 Always, Total Messages successfully sent: . . . . . . . . . . . . 18
2017-06-01 15:23:05.633 Always, ACKs received from controller:  . . . . . . . . . . . . . 10
2017-06-01 15:23:05.633 Always, *** Errors
2017-06-01 15:23:05.633 Always, Unsolicited messages received while waiting for ACK:  . . 0
2017-06-01 15:23:05.633 Always, Reads aborted due to timeouts:  . . . . . . . . . . . . . 0
2017-06-01 15:23:05.633 Always, Bad checksum errors:  . . . . . . . . . . . . . . . . . . 0
2017-06-01 15:23:05.633 Always, CANs received from controller:  . . . . . . . . . . . . . 0
2017-06-01 15:23:05.633 Always, NAKs received from controller:  . . . . . . . . . . . . . 0
2017-06-01 15:23:05.633 Always, Out of frame data flow errors:  . . . . . . . . . . . . . 0
2017-06-01 15:23:05.633 Always, Messages retransmitted: . . . . . . . . . . . . . . . . . 0
2017-06-01 15:23:05.633 Always, Messages dropped and not delivered: . . . . . . . . . . . 8
2017-06-01 15:23:05.633 Always, ***************************************************************************
2017-06-01 15:23:08.467 Info, mgr,     Driver for controller /dev/ttyACM0 removed
2017-06-01 15:23:09.467 Error, mgr,     Manager::GetDriver failed - Home ID 0xec47ea6c is unknown
2017-06-01 15:23:09.467 Warning, Exception: Manager.cpp:373 - 100 - Invalid HomeId passed to GetDriver
2017-06-01 15:23:09.467 Info, mgr,     GetSendQueueCount() failed - _homeId -330831252 not found

@nitrag
Copy link

nitrag commented Jun 1, 2017

Oh wait, I just hit Start Network and the node is not appearing. Weird. Hope this helps.

@UltraSub
Copy link
Author

UltraSub commented Jun 1, 2017

This is in no way the same issue. Can't see your stick locking up in the logs :)

--

I followed most upgrades, and when I upgraded to 0.45.1 with the "bundled" zwave the problem seems not reproducible anymore. No clue, but it seems to be fixed. Will report back if it is reproduced.

@binbin2000
Copy link

I'm running Hass in Docker on a Synology together with an Aeon Z-stick and are experiencing similar problems. Whenever I restart Hass, the Z-stick no longer works.

Interesting.. Stop HA, stick "crashes", start HA, no zwave as logs above show. Stop HA, start again, stick works and reports devices. Was able to reproduce that multiple times yesterday. Running out of options to debug this problem. Checked everything I could think off. Pretty annoying problem.

I tested this procedure as well, and it actually seems to works. At least once.
By restarting Hass a second time, the Z-stick suddenly comes back to life again, without the need to unplug it from USB. Let me know if I can contribute with anything else to solve this issue.

@UltraSub
Copy link
Author

Just upgraded to 0.47 and at first restart of HA got the same problem again. As @binbin2000 says, same here, second restart and it works.

@turbokongen
Copy link
Contributor

@rossdargan That is your stick that has failed. Home id is 0000000.

@slomanl1
Copy link

Now it is August 2018 and I am having the same problem. Running HASSIO on Rasp Pi3. Everytime I restart the drivers get unloaded and I have to reset the Aeotec USB stick and re-pair Zwave devices to recover. Has there been any progress made on this issue?

@uchagani
Copy link
Contributor

I have the same zwave stick and don't have this issue at all. Running HA 0.73.2 in a virtual environment with 7 zwave plus devices.

@rpitera
Copy link

rpitera commented Sep 21, 2018

I just experienced this today for the first time ever. Same error messages in both the HA and OZW logs. Hard takedown of my Pi and a few HA restarts finally resolved my panic though.

I moved a few months ago from one pi running an old AIO install at 0.65 to a new pi running hass.io. I've been upgrading to current versions and doing restarts both warm (HA only) and cold (Hassio Host) prior to this without any issues until today. I was running 0.78.1 but due to CC/Google TTS issues I downgraded to 0.77.3. That's when this happened.

Let me know if I can provide any further info to help.

@PlayedIn
Copy link

PlayedIn commented Nov 6, 2018

I'm having this on Hassio using HA on 0.81.6 on rpi3+. Been happening for months on older versions also. Just restarting HA using Configuration/General/Restart does NOT cause it. However if I go to HASS.IO/System/Reboot Host System or I cold boot the rpi by unplugging/replugging power supply happens EVERY time. Also happens to my zigbee2mqtt stick, but a simple press of the little button on the stick and a stop and start of the zigbee2mqtt addon gets it back online. However I have to fight this zwave stick for an hour or more to finally get it back online. Replugging the stick and restarting HA doesn't cut it for me. If HA hangs up and won't restart, I know I'm in for trouble because I will have to restart the host system.
tl/dr : I can recreate the problem 100% of the time by cold booting the raspberry pi

@klaasnicolaas
Copy link
Member

klaasnicolaas commented Dec 28, 2018

Is there some progres with someone to solve this? I now experience the same problem on my Intel Nuc.

What strikes me most is that after a second restart of HA, I just get back my zwave nodes. And that the problem is probably in this line in the OZW_Log.txt: "Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt (s)".

The controller is temporarily unavailable for a moment, so HA is skipping and you will not see anything, at least I assume that I have to explain it so.

The only question now is how do you solve this?

@balloobbot
Copy link

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.

Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍

@alexmannuk
Copy link

Is this still an issue you are experiencing? Can you please try upgrading to the latest version of Home Assistant (0.90) and report back if this is still a problem? Thanks! This is similar to #21165

@KennethLavrsen
Copy link

I saw the issue once where with 0.90. I had to restart once to make the stick come alive. I reported #21165 which for the most is the same issue. I find it sad if this severe issue gets closed without a fix.

I am personally using z-wave for doors and window sensors and two sirens as a security system. And I have taken the consequence of the poor performance of z-wave in Home assistant to migrate away from z-wave. I have already replaced 4 of my 10 sensors with wifi based sensors and the remaining windows have now additional 433 MHz sensors. I simply cannot trust the z-wave network.

I think z-wave should be considered a key basic foundation feature in a home automation system and I wonder why a bug like this is allowed to stay open since 2017 and now being considered closed with no action. What is Lovelace and other cool bells and whistles worth if the foundation is not stable? Z-wave is so essential in the world of home automation.

@bieniu
Copy link
Member

bieniu commented Mar 22, 2019

Issue still exists. It happens when HA restarts. I have to wait about 2 minutes to system kills the HA service. Raspbian, Python 3.7.2, venv, HA 0.90

2019-03-22 08:25:56.855 Info, mgr,     Manager::WriteConfig completed for driver with home ID of 0xd8bc2f21
2019-03-22 08:25:57.866 Info, mgr,     Driver for controller /dev/zwave pending removal
2019-03-22 08:25:57.867 Detail, Notification: DriverRemoved
2019-03-22 08:25:57.867 Always, ***************************************************************************
2019-03-22 08:25:57.867 Always, *********************  Cumulative Network Statistics  *********************
2019-03-22 08:25:57.867 Always, *** General
2019-03-22 08:25:57.867 Always, Driver run time: . .  . 0 days, 19 hours, 6 minutes
2019-03-22 08:25:57.867 Always, Frames processed: . . . . . . . . . . . . . . . . . . . . 9003
2019-03-22 08:25:57.867 Always, Total messages successfully received: . . . . . . . . . . 9003
2019-03-22 08:25:57.867 Always, Total Messages successfully sent: . . . . . . . . . . . . 1598
2019-03-22 08:25:57.867 Always, ACKs received from controller:  . . . . . . . . . . . . . 1597
2019-03-22 08:25:57.867 Always, *** Errors
2019-03-22 08:25:57.867 Always, Unsolicited messages received while waiting for ACK:  . . 1
2019-03-22 08:25:57.868 Always, Reads aborted due to timeouts:  . . . . . . . . . . . . . 0
2019-03-22 08:25:57.868 Always, Bad checksum errors:  . . . . . . . . . . . . . . . . . . 0
2019-03-22 08:25:57.868 Always, CANs received from controller:  . . . . . . . . . . . . . 1
2019-03-22 08:25:57.868 Always, NAKs received from controller:  . . . . . . . . . . . . . 0
2019-03-22 08:25:57.868 Always, Out of frame data flow errors:  . . . . . . . . . . . . . 0
2019-03-22 08:25:57.868 Always, Messages retransmitted: . . . . . . . . . . . . . . . . . 1
2019-03-22 08:25:57.868 Always, Messages dropped and not delivered: . . . . . . . . . . . 3
2019-03-22 08:25:57.868 Always, ***************************************************************************
2019-03-22 08:25:57.875 Detail, WriteMsg Wait Timeout m_currentMsg=00000000
2019-03-22 08:25:59.955 Info, mgr,     Driver for controller /dev/zwave removed
2019-03-22 08:26:00.958 Error, mgr,     Manager::GetDriver failed - Home ID 0xd8bc2f21 is unknown
2019-03-22 08:26:00.959 Warning, Exception: Manager.cpp:373 - 100 - Invalid HomeId passed to GetDriver
2019-03-22 08:26:00.959 Info, mgr,     GetSendQueueCount() failed - _homeId -658755807 not found

@robbiet480
Copy link
Member

@bieniu thanks for reporting back on this one. I can entirely understand your frustrations with this specific bug as a Z-Wave user. Sadly, we are really at the mercy of the OpenZWave project for things like this. You may be interested to listen to the most recent episode of the Home Assistant Podcast in which Paulus gets into detail about our potential plans to build our own Z-Wave stack.

Don't worry, I'm not closing this. @ocatelle just asked for a status update because I asked him to.

@KennethLavrsen
Copy link

I just reproduced it again.
And same errors. I think that a possible work around would be if HA had a retry mechanism to start communication with the stick again after a minute or so if it fails. The easy way to reproduce the issue is to do several HA restarts with less than a minute between. There probability that the restart goes wrong is much higher when the Z-stick is still active with the starting up from earlier restart.

@robbiet480
Copy link
Member

@KennethLavrsen sorry, it's late here in California and I thought @bieniu had left both update comments, so thanks to you as well for reporting back.

I can try to help triage this a bit more for you in the morning. In the meantime, if you want to go above and beyond in helping me, can you take a look at the OpenZWave and python-openzwave issues to see if there's anything similar there? If you don't have time i'll take a look in about 8 hours when I wake up.

@bieniu
Copy link
Member

bieniu commented Mar 22, 2019

@robbiet480 I'm not complaining. I'm a patient user and full of admiration for the hard work of HA developers. I learned to live with this issue. The problem occurs when I don't restart the HA for a long time. Over a week of continuous work is needed. Sometimes after this error, the HA doesn't start without restarting the entire system (there is nothing special in the log). The start of the HA stops at "Starting Z-Wave network ...".

@robbiet480
Copy link
Member

@bieniu yeah sorry, as I just said, I got you and @KennethLavrsen confused :)

@bieniu
Copy link
Member

bieniu commented Mar 22, 2019

@robbiet480 We write too fast ;)

As @KennethLavrsen writes, you can quickly reproduce issue by restarting HA several times with less than a minute between (before the "Z-Wave network is complete" in log).

@KennethLavrsen
Copy link

I will gladly scan through some of the bugs of the upstream projects. I am in the EU time zone (Denmark) so I need to get off from work first but I am home alone Saturday so I also have some reading time available there.

@Fishwaldo
Copy link

Fishwaldo commented Apr 1, 2019

OZW author here. Just a few thoughts:

  1. the ZStick not responding on startup - I've seen this a few times, mostly on rPI boards. Its a Hardware/Kernel issue here, and not anything related to OZW. If you open up a serial console on the device, you will see it wont even get/send any information. Nothing OZW or HA can do about that.
  2. ZStick randomly dying after running for a while. Again, I've mostly seen this on rPI or SBC installs. As far as I can tell, seems to be power related. Users have reported using a externally powered hub with the ZStick makes this go away.
  3. Lots of Unsolicited Messages/CAN messages etc etc etc. This is usually a result of two programs accessing the serial port at the same time. Again, examples I've seen of this is where the programs are not shutdown properly between restarts, or in some cases, linux distributions trying to start up getty (for serial logins) on the serial port that the ZStick emulates.

regarding the messages at shutdown: 2019-03-22 08:26:00.958 Error, mgr, Manager::GetDriver failed - Home ID 0xd8bc2f21 is unknown 2019-03-22 08:26:00.959 Warning, Exception: Manager.cpp:373 - 100 - Invalid HomeId passed to GetDriver 2019-03-22 08:26:00.959 Info, mgr, GetSendQueueCount() failed - _homeId -658755807 not found

Thats something the python wrapper does and is harmless...

@stale
Copy link

stale bot commented Jul 7, 2019

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.
Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍
This issue now has been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

@stale stale bot added the stale label Jul 7, 2019
@KennethLavrsen
Copy link

We know that most people have a problem on machines that have Modem Manager installed and that the issue is that when a Docker is restarted it runs udev and initiates Modem Manager. Result is that both during boot and during restart the Modem Manager and HA tries to talk to the Aeotec stick.

The easy work around is to disable Modem Manager.

systemctl disable ModemManager.service

The documentation for HA has had this addressed now but the documentation suggests to purge the ModemManager from the system. This however can have negative effects on distros with Gnome desktops so best advice is to disable the service.

I still believe HA should be coded to take an approach that allows people that may need ModemManager or simply have not seen or understood the documentation. Modem Manager only runs for a few seconds so HA could simply retry maybe 30 seconds after a failed init and the user would be happily ignorant about the issue. There are so many other integrations that have mechanisms to reconnect when the link fails. That would be the best solution. But at least with the documentation update people can now use the stick.

@eavanvalkenburg
Copy link
Contributor

We know that most people have a problem on machines that have Modem Manager installed and that the issue is that when a Docker is restarted it runs udev and initiates Modem Manager. Result is that both during boot and during restart the Modem Manager and HA tries to talk to the Aeotec stick.

The easy work around is to disable Modem Manager.

systemctl disable ModemManager.service

The documentation for HA has had this addressed now but the documentation suggests to purge the ModemManager from the system. This however can have negative effects on distros with Gnome desktops so best advice is to disable the service.

I still believe HA should be coded to take an approach that allows people that may need ModemManager or simply have not seen or understood the documentation. Modem Manager only runs for a few seconds so HA could simply retry maybe 30 seconds after a failed init and the user would be happily ignorant about the issue. There are so many other integrations that have mechanisms to reconnect when the link fails. That would be the best solution. But at least with the documentation update people can now use the stick.

This did the trick for me when encountering this issue using the Zwave2MQTT container!

@stale
Copy link

stale bot commented Nov 25, 2019

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.
Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍
This issue now has been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

@stale stale bot added the stale label Nov 25, 2019
@stale stale bot closed this as completed Dec 2, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests