Closed UltraSub closed 4 years ago
turbokongen
commented
7 years ago 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
commented
7 years ago I mean, the complete logoutput for ozw_log
UltraSub
commented
7 years ago 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 - TimeOutAnd then it just sits there.
UltraSub
commented
7 years ago 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 foundWhich 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
commented
7 years ago 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
commented
7 years ago 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
commented
7 years ago Ok, checked everything. All hass.nogroup for:
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
commented
7 years ago 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
commented
7 years ago 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
commented
7 years ago 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
commented
7 years ago Can you please confirm that:
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
commented
7 years ago Yeah, I'm using an Aeotec Gen5 and it crashes when stopping. However I'm unable to reproduce the same results this evening.
infamy
commented
7 years ago 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
commented
7 years ago 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
commented
7 years ago 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-5GDid 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
commented
7 years ago 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/configInteresting.. 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
commented
7 years ago 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
commented
7 years ago 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
commented
7 years ago 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
commented
7 years ago 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
commented
7 years ago 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 :+1:
nitrag
commented
7 years ago 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 foundOh wait, I just hit Start Network and the node is not appearing. Weird. Hope this helps.
UltraSub
commented
7 years ago 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
commented
7 years ago 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
commented
7 years ago 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.
haimgel
commented
7 years ago I've had similar issues with Aeotec Gen 5 zwave stick crashing in 6.5 ESXi guests, which I eventually traced to faulty USB driver in ESXi itself (it was ESXi 6.5 exclusive at that time, though). Just saying it might be worthwhile to try to test for it outside of ESXi environment, if possible.
UltraSub
commented
7 years ago Never had issues on a raspberry. Also no issues running through esx in centos 7 with Domoticz. Some issues with passing trough esx in ubuntu and Hass. My guess is it has to do something with the virtualization layer, but no clue why it only happens on vm's running hass. :-/
tbrasser
commented
6 years ago I've been running 0.55.2 via HASSIO (everything updated to the latest version) with a z-wave.me UZB1 stick. Never had any problems, however now it all crashed when I clicked ' check config'.
I vpn'ed into my home network (am remote now) and ssh'ed into hassio, rebooted the host, but still have the same problem. (no nodes found, incorrect home_id of only 0's).
My guess is that it'll work when I physically replug the zwave usb stick, but I have no access to that now.
It seems that my zwave xml file with the home id in the name is emptied out now, with only 1 node remaining (the controller), however it looks bad. I had previously given unique names to all my nodes and entities belonging to the nodes, which are saved in this file. It seems now everything is gone again.
Is there any way to recover from this except for physically removing the z-wave usb stick / cycling the power (the usb stick doesn't stop receiving power when rebooting, have had multiple /dev/tty* issues with that in the past, it seems that the power to the usb ports on raspberry pi's remains while rebooting)
EDIT/UPDATE: I don't know exactly what got it working again, but I did the following things:
After a host reboot, z-wave is showing up again, but I've lost all my names given to nodes and entities belonging to nodes. I get that the new naming convention makes it so that when z-wave functions correctly you can change nodes while keeping the names. However now I have to rename everything every time stuff like this happens. Anybody got a better/easier way of maintaining this except for making a spreadsheet with names corresponding to node id's?
fanaticDavid
commented
6 years ago Backing up the zwcfg_***.xml file seems like the easiest option to me.
tbrasser
commented
6 years ago Well, as far as I can tell the zwcfg_
I tried manually editing the names in the xml file, and that doesn't work. It works only when edited through the Home Assistant Z-Wave Configuration frontend.
gazoscalvertos
commented
6 years ago Suffered same issues in ESXi 6.5. @hageltech care to share your findings on the driver edit?
I'm now still using ESXi 6.5 with a vm however having to use a RPI3 with the device plugged into that sharing over usb.ip
I still see the Manager::GetDriver failed - Home ID XXX is unknown on shutdown however everything else seems to work to a degree. Occasionally the controller fails to pickup messages on the network occasionally so a motion sensor shows as active longer than it should. This could however be down to the usb.ip service
nitrag
commented
6 years ago @gazoscalvertos Can you explain how you got this usb.ip working? I couldn't find a package that worked on the Pi3. Thanks!
gazoscalvertos
commented
6 years ago @nitrag I followed this guide https://community.home-assistant.io/t/rpi-as-z-wave-zigbee-over-ip-server-for-hass/23006 which worked a treat
infamy
commented
6 years ago @gazoscalvertos I'm running mine on ESXi with no issues. If you continue to have that many issues with your stick, I would test the stick outside of that, on different hardware/os. It maybe a hardware failure on the stick side. Just a thought.
basschipper
commented
6 years ago I'm experiencing the same issue running HomeAssistant 0.63.3 on a Intel NUC (Docker Environment).
I already tried unpairing all devices, resetting the Aeotec and repairing all devices. But unfortunately this did not solve the problem. Also, I bought a new Aeotec, still no luck...
I don't know for sure yet but I have the feeling that the problem is increasing when adding the Fibaro Motion Sensors (FGMS-001). Maybe there is a cause with the battery operated devices?
Custos
commented
6 years ago @basschipper I'm on the NUC Docker Environment as well and using a HUSBZB-1 and have that error on restart. For whatever reason I have 5 motorized blinds with all but 1 as showing as dead.
mhump711
commented
6 years ago I just went through this. I am using ESXi 6.5 and Home Assistant on Lubuntu and Aeon Gen 5 Z-stick. I found my issue to be with the USB drivers that VMWare made for ESXi 6.5. Once I downgraded them and used legacy drivers the issue was gone. So may be an issue with drivers for some.
Method I used for ESXi 6.5:
esxcli system module set -m=vmkusb -e=FALSEesxcli system module list | grep usb
The Last column should say FalseFor those that are having the same issue but are not using VMs try updating the USB driver.
Hope this helps someone. Mike
bieniu
commented
6 years ago I have the same issue. RPi3 with Raspbian Stretch, HA 0.67 (virtualenv installation) and Aeon Gen 5 Z-stick. In my case, when RPi works for over a week without reboot, the Z-Wave error causes a problem with the restart of HA:
Apr 13 17:48:21 raspberry systemd[1]: Stopping Home Assistant...
Apr 13 17:48:21 raspberry hass[29665]: 2018-04-13 17:48:21 INFO (SyncWorker_13) [homeassistant.components.zwave] Stopping Z-Wave network
Apr 13 17:48:21 raspberry hass[29665]: 2018-04-13 17:48:21.345 Info, mgr, Manager::WriteConfig completed for driver with home ID of 0xd8bc2f21
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.354 Info, mgr, Driver for controller /dev/zwave pending removal
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.354 Detail, Notification: DriverRemoved
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.355 Always, ***************************************************************************
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.355 Always, ********************* Cumulative Network Statistics *********************
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.355 Always, *** General
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.355 Always, Driver run time: . . . 2 days, 23 hours, 49 minutes
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.355 Always, Frames processed: . . . . . . . . . . . . . . . . . . . . 33348
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.355 Always, Total messages successfully received: . . . . . . . . . . 33348
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.355 Always, Total Messages successfully sent: . . . . . . . . . . . . 5827
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.355 Always, ACKs received from controller: . . . . . . . . . . . . . 5826
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.355 Always, *** Errors
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.356 Always, Unsolicited messages received while waiting for ACK: . . 1
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.356 Always, Reads aborted due to timeouts: . . . . . . . . . . . . . 0
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.356 Always, Bad checksum errors: . . . . . . . . . . . . . . . . . . 0
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.356 Always, CANs received from controller: . . . . . . . . . . . . . 1
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.356 Always, NAKs received from controller: . . . . . . . . . . . . . 0
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.356 Always, Out of frame data flow errors: . . . . . . . . . . . . . 0
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.356 Always, Messages retransmitted: . . . . . . . . . . . . . . . . . 1
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.356 Always, Messages dropped and not delivered: . . . . . . . . . . . 3
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.356 Always, ***************************************************************************
Apr 13 17:48:22 raspberry hass[29665]: 2018-04-13 17:48:22.359 Detail, WriteMsg Wait Timeout m_currentMsg=00000000
Apr 13 17:48:24 raspberry hass[29665]: 2018-04-13 17:48:24.479 Info, mgr, Driver for controller /dev/zwave removed
Apr 13 17:48:25 raspberry hass[29665]: 2018-04-13 17:48:25.483 Error, mgr, Manager::GetDriver failed - Home ID 0xd8bc2f21 is unknown
Apr 13 17:48:25 raspberry hass[29665]: 2018-04-13 17:48:25.486 Warning, Exception: Manager.cpp:373 - 100 - Invalid HomeId passed to GetDriver
Apr 13 17:48:25 raspberry hass[29665]: 2018-04-13 17:48:25.486 Info, mgr, GetSendQueueCount() failed - _homeId -658755807 not found
Apr 13 17:49:51 raspberry systemd[1]: home-assistant.service: State 'stop-sigterm' timed out. Killing.
Apr 13 17:49:51 raspberry systemd[1]: home-assistant.service: Killing process 29665 (hass) with signal SIGKILL.
Apr 13 17:51:21 raspberry systemd[1]: home-assistant.service: Processes still around after SIGKILL. Ignoring.
rossdargan
commented
6 years ago Pretty sure I'm now suffering from this issue running Home assistant 0.71 on docker.
This is my log:
2018-06-21 08:10:43.103 Always, OpenZwave Version 1.4.2926 Starting Up
2018-06-21 08:11:14.278 Info, Setting Up Provided Network Key for Secure Communications
2018-06-21 08:11:14.294 Info, mgr, Added driver for controller /dev/ttyUSB0
2018-06-21 08:11:14.294 Info, Opening controller /dev/ttyUSB0
2018-06-21 08:11:14.294 Info, Trying to open serial port /dev/ttyUSB0 (attempt 1)
2018-06-21 08:11:14.298 Info, Serial port /dev/ttyUSB0 opened (attempt 1)
2018-06-21 08:11:14.298 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2018-06-21 08:11:14.298 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2018-06-21 08:11:14.298 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2018-06-21 08:11:14.298 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2018-06-21 08:11:14.298 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2018-06-21 08:11:14.298 Detail,
2018-06-21 08:11:14.298 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2018-06-21 08:11:15.299 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2018-06-21 08:11:15.299 Detail, contrlr, Removing current message
2018-06-21 08:11:15.299 Detail, contrlr, Notification: Notification - TimeOut
2018-06-21 08:11:15.300 Detail,
2018-06-21 08:11:15.300 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x20) - FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2018-06-21 08:11:16.300 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2018-06-21 08:11:16.300 Detail, contrlr, Removing current message
2018-06-21 08:11:16.300 Detail, contrlr, Notification: Notification - TimeOut
2018-06-21 08:11:16.305 Detail,
2018-06-21 08:11:16.305 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x05) - FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2018-06-21 08:11:17.306 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2018-06-21 08:11:17.306 Detail, contrlr, Removing current message
2018-06-21 08:11:17.306 Detail, contrlr, Notification: Notification - TimeOut
2018-06-21 08:11:17.306 Detail,
2018-06-21 08:11:17.306 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x07) - FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2018-06-21 08:11:18.306 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2018-06-21 08:11:18.306 Detail, contrlr, Removing current message
2018-06-21 08:11:18.306 Detail, contrlr, Notification: Notification - TimeOut
2018-06-21 08:11:18.306 Detail,
2018-06-21 08:11:18.306 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x56) - FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2018-06-21 08:11:19.307 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2018-06-21 08:11:19.307 Detail, contrlr, Removing current message
2018-06-21 08:11:19.307 Detail, contrlr, Notification: Notification - TimeOut
2018-06-23 08:35:56.525 Error, mgr, Manager::GetDriver failed - Home ID 0x00000000 is unknown
2018-06-23 08:35:56.531 Warning, Exception: Manager.cpp:373 - 100 - Invalid HomeId passed to GetDriver
2018-06-23 08:35:56.531 Info, mgr, Manager::WriteConfig failed - _homeId 0 not found
2018-06-23 08:35:57.619 Detail, Notification: DriverRemoved
2018-06-23 08:35:57.620 Always, ***************************************************************************
2018-06-23 08:35:57.620 Always, ********************* Cumulative Network Statistics *********************
2018-06-23 08:35:57.620 Always, *** General
2018-06-23 08:35:57.620 Always, Driver run time: . . . 2 days, 0 hours, 24 minutes
2018-06-23 08:35:57.620 Always, Frames processed: . . . . . . . . . . . . . . . . . . . . 0
2018-06-23 08:35:57.620 Always, Total messages successfully received: . . . . . . . . . . 0
2018-06-23 08:35:57.620 Always, Total Messages successfully sent: . . . . . . . . . . . . 5
2018-06-23 08:35:57.620 Always, ACKs received from controller: . . . . . . . . . . . . . 0
2018-06-23 08:35:57.620 Always, *** Errors
2018-06-23 08:35:57.620 Always, Unsolicited messages received while waiting for ACK: . . 0
2018-06-23 08:35:57.621 Always, Reads aborted due to timeouts: . . . . . . . . . . . . . 0
2018-06-23 08:35:57.621 Always, Bad checksum errors: . . . . . . . . . . . . . . . . . . 0
2018-06-23 08:35:57.621 Always, CANs received from controller: . . . . . . . . . . . . . 0
2018-06-23 08:35:57.621 Always, NAKs received from controller: . . . . . . . . . . . . . 0
2018-06-23 08:35:57.621 Always, Out of frame data flow errors: . . . . . . . . . . . . . 0
2018-06-23 08:35:57.621 Always, Messages retransmitted: . . . . . . . . . . . . . . . . . 0
2018-06-23 08:35:57.621 Always, Messages dropped and not delivered: . . . . . . . . . . . 5
2018-06-23 08:35:57.621 Always, ***************************************************************************
2018-06-23 08:35:57.621 Warning, WARNING: Tried to write driver config with no home ID set@rossdargan That is your stick that has failed. Home id is 0000000.
slomanl1
commented
6 years ago 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
commented
6 years ago 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
commented
5 years ago 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
commented
5 years ago 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
commented
5 years ago 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
commented
5 years ago 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 :+1:
alexmannuk
commented
5 years ago 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
commented
5 years ago 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.
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.yamlentries and steps to reproduce: Zwave logs report the following in the faulty situation: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>.xmlSince 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:
Shutdown by ozwcp:
Additional info: Just a side thought, why do we restart the zwave network every time we need to restart for a config change?