OZW stuck on "Starting Z-Wave Network... This may take a while depending on the size of your network."

ltoolio · August 2, 2019, 5:04pm

In the process of doing a rebuilt of my Home Assistant config, and out of nowhere my Z-Wave Network Management page now renders the following message:

I was not doing anything with ZWave prior to this, and I did not pull down any HASS-related update. It started after a reboot.

My existing, successfully configured ZWave devices are functioning properly, meaning I can interact with them through the WebUI, but I cannot do any other ZWave activities such as adding a new device.

The last 2000 lines of my OZW log file can be found at the URL below. Any ideas?

https://pastebin.com/ks4GsU4j

firstof9 · August 2, 2019, 5:12pm

What version of HA are you using?
What type of HA install? (vevnv, docker, hass.io)
Post the first 5-10 lines of your OZW_Log.txt

ltoolio · August 2, 2019, 6:26pm

Screen shot of my environment is below…running a docker on Ubuntu 18.04. Version 0.96.5

2019-08-02 11:08:42.921 Always, OpenZwave Version 1.4.3440 Starting Up
2019-08-02 11:08:52.281 Info, Setting Up Provided Network Key for Secure Communications
2019-08-02 11:08:52.282 Info, mgr,     Added driver for controller /dev/ttyACM0
2019-08-02 11:08:52.282 Info,   Opening controller /dev/ttyACM0
2019-08-02 11:08:52.282 Info, Trying to open serial port /dev/ttyACM0 (attempt 1)
2019-08-02 11:08:52.282 Info, Serial port /dev/ttyACM0 opened (attempt 1)
2019-08-02 11:08:52.285 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2019-08-02 11:08:52.285 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2019-08-02 11:08:52.285 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2019-08-02 11:08:52.285 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2019-08-02 11:08:52.285 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2019-08-02 11:08:52.285 Detail, 
2019-08-02 11:08:52.285 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2019-08-02 11:08:52.287 Detail, contrlr,   Received: 0x01, 0x10, 0x01, 0x15, 0x5a, 0x2d, 0x57, 0x61, 0x76, 0x65, 0x20, 0x33, 0x2e, 0x39, 0x35, 0x00, 0x01, 0x99
2019-08-02 11:08:52.287 Detail, 
2019-08-02 11:08:52.287 Info, cont

firstof9 · August 2, 2019, 7:26pm

How many zwave devices do you have?

ltoolio · August 2, 2019, 7:42pm

Right now I have ~10. Primary ZWave Plus, and all hard wired (no battery).

Before my tear down and build up, I was probably pushing 25, with the delta being a few plugs and the rest battery. But, I haven’t attempted to pair any of those yet.

firstof9 · August 2, 2019, 8:40pm

Hard to say what’s going on, I don’t use the docker version of HA, but it’s almost like it’s unable to find the device configuration XML files for openzwave.

Does it ever finish starting the zwave network?

ltoolio · August 3, 2019, 4:39am

I’m so confused.

I left home for a while, and upon coming back to the WebUI I was presented with a “Network Stopped” message and an option to click “Start Network”. I did that.

A little while later, I came back and the status was blank. There was nothing in the top of the ZWave page. It was like a blank Lovelace card. Weird. Rebooted.

Went to the ZWave page. “Network Stopped” and " Start Network" again. I come back later, and all I have is the ZWave stick listed. OK…it started over for some weird reason. I start thinking about the reset process for the existing devices. I decide to reboot.

I log back in, and now everything is back, with a couple of dead nodes to boot.

No clue what’s going on and if what I’ve got going now is stable. Will play around and report back.

Emphyrio · August 3, 2019, 5:46am

Did you remove or disable the modem manager in your Ubuntu host OS? It is described in the docs for Z-wave. For me, this solved similar issues with z-wave between HA restarts.

M0E-lnx · September 18, 2019, 6:26pm

Has anyone been able to resolve this? I’m having this exact same issue, and it’s not going away even after removing ModemManager. Tried running homeassistant on docker and venv, same results.

Nodes usually do respond, but there is a lag to it. Also, since the network is not listed as ready or started, I can’t add or remove nodes, heal the network or do anything else.

I see the same symptoms as listed above. Huge OZW_Log ( about 2GB)

I have tried different boards, an odroid xu4, raspberry pi 3b and 4. All end up with the same issue.

Any ideas would be appreciated.

Thanks

M0E-lnx · September 19, 2019, 2:34pm

For anyone else having this issue, I have filed an issue with the HomeAssistant backend project where I documented a possible temporary workaround for this.

See https://github.com/home-assistant/home-assistant/issues/26727

Hopefully this gets resolved some other way soon.

Mr.Morten · October 28, 2019, 8:35am

Still no news on the issue

M0E-lnx · October 28, 2019, 8:57pm

Unfortunately nothing yet. I’m still having to drop to the container and poke around pyozw_shell until homeassistant detects z-wave is up and running. Seems that it’s a hit and miss now. Sometimes it comes up by just running pyozw_shell. Sometimes it takes forcing an error in that program.

The only annoyance I have with this right now is that pyozw_shell requires a terminal, so I can’t just automatically launch it and automate the workaround.

Hopefully somebody comes up with a solution.

M0E-lnx · November 11, 2019, 4:45pm

So, after months of testing, I am not convinced this is problem with homeassistant or openzw, although homeassistant-openzw could and probably should catch this and offer a way out of this loop.

In my case, it appears to be a bad node. It took a bit of time to figure it out but I think I found the culprit. I have an Eaton RF9501 that appears to be mad. As soon as I add that node to the network, it starts flooding OZW_Log.txt. Looks like at some point during the query stage it enters a loop of some kind and it continues to flood the network with traffic.

I noticed that as soon as I remove this node, the traffic slows down and the network functions as it should

Anyone having this problem should try removing their nodes and add them back up while monitoring OZW_Log.txt. You should only see a little bit out output there when you add a node. If you add one and you see lots and lots of output being logged, that node is probably your culprit.

Even though I dont think this is a homeassistant or openzw issue, I think either or both of these projects should do something to detect this issue and raise some kind of notification that says there may be a problem with node X

I would like to see a notification and maybe a suggestion to exclude a node that has gone mad.

I would also point out that this is the 2nd switch that has gone bad on me. I also had an Eaton RF9540 that starting flickering the lights, so it may just be that Eaton is producing bad z-wave products. I have had better luck with Leviton switches.

Hope this helps anyone else having this issue.

Fabio06320 · November 24, 2019, 1:27pm

Hi,

My Starting z-wave network loop since few days, but z-Wave network work perfectly.
However, I don’t add new module or manage network.

Do you have ideas for help me please?

Home Assistant 0.102.1

Version interface utilisateur : 20191119.5 - latest

Hass.io supervisor

Latest version 192
System Debian GNU/Linux 10 (buster)

Hardware

serial:
- /dev/serial/by-id/usb-RFXCOM_RFXtrx433_A1XZQ3CA-if00-port0
- /dev/ttyS1
- /dev/ttyACM0
- /dev/ttyS0
- /dev/ttyS3
- /dev/serial/by-id/usb-0658_0200-if00
- /dev/ttyUSB0
- /dev/ttyS2
input:
- AT Translated Set 2 keyboard
- PC Speaker
- VirtualPS/2 VMware VMMouse
- Power Button
- QEMU QEMU USB Tablet
disk:
gpio:
audio:

FYI: I have a same problem with “/dev/ttyACM0” and I change to “/dev/serial/by-id/usb-0658_0200-if00” to test

2019-11-24 14:20:35.071 Always, OpenZwave Version 1.4.3440 Starting Up
2019-11-24 14:20:52.308 Info, Setting Up Provided Network Key for Secure Communications
2019-11-24 14:20:52.308 Warning, Failed - Network Key Not Set
2019-11-24 14:20:52.308 Info, mgr,     Added driver for controller /dev/serial/by-id/usb-0658_0200-if00
2019-11-24 14:20:52.308 Info,   Opening controller /dev/serial/by-id/usb-0658_0200-if00
2019-11-24 14:20:52.308 Info, Trying to open serial port /dev/serial/by-id/usb-0658_0200-if00 (attempt 1)
2019-11-24 14:20:52.316 Info, Serial port /dev/serial/by-id/usb-0658_0200-if00 opened (attempt 1)
2019-11-24 14:20:52.316 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2019-11-24 14:20:52.316 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2019-11-24 14:20:52.316 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2019-11-24 14:20:52.316 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2019-11-24 14:20:52.316 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2019-11-24 14:20:52.316 Detail, 
2019-11-24 14:20:52.316 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2019-11-24 14:20:52.321 Detail, contrlr,   Received: 0x01, 0x10, 0x01, 0x15, 0x5a, 0x2d, 0x57, 0x61, 0x76, 0x65, 0x20, 0x34, 0x2e, 0x35, 0x34, 0x00, 0x01, 0x93

firstof9 · November 25, 2019, 1:30am

Is this where your OZW_Log.txt stops?

Fabio06320 · November 25, 2019, 6:57pm

No,

17227 lignes in OZW_Log.txt 1,5Mo (24 & 25/11)
FYI: Z-Wave network work fine …

Example today log:

2019-11-25 00:03:01.993 Detail, 
2019-11-25 00:03:01.993 Info, Node004, Received SensorMultiLevel report from node 4, instance 1, Power: value=2.0W
2019-11-25 00:03:01.993 Detail, Node004, Refreshed Value: old value=1.9, new value=2.0, type=decimal
2019-11-25 00:03:01.993 Detail, Node004, Changes to this value are not verified
2019-11-25 00:03:01.993 Detail, Node004, Notification: ValueChanged
2019-11-25 00:03:32.081 Detail, Node004,   Received: 0x01, 0x0c, 0x00, 0x04, 0x00, 0x04, 0x06, 0x31, 0x05, 0x04, 0x22, 0x00, 0x13, 0xf4
2019-11-25 00:03:32.081 Detail, 
2019-11-25 00:03:32.081 Info, Node004, Received SensorMultiLevel report from node 4, instance 1, Power: value=1.9W
2019-11-25 00:03:32.081 Detail, Node004, Refreshed Value: old value=2.0, new value=1.9, type=decimal
2019-11-25 00:03:32.081 Detail, Node004, Changes to this value are not verified
2019-11-25 00:03:32.081 Detail, Node004, Notification: ValueChanged
2019-11-25 00:07:29.995 Detail, Node026,   Received: 0x01, 0x0c, 0x00, 0x04, 0x00, 0x1a, 0x06, 0x31, 0x05, 0x04, 0x22, 0x00, 0x00, 0xf9
2019-11-25 00:07:29.995 Detail, 
2019-11-25 00:07:29.995 Info, Node026, Received SensorMultiLevel report from node 26, instance 1, Power: value=0.0W
2019-11-25 00:07:29.995 Detail, Node026, Refreshed Value: old value=0.0, new value=0.0, type=decimal
2019-11-25 00:07:29.995 Detail, Node026, Changes to this value are not verified
2019-11-25 00:07:29.995 Detail, Node026, Notification: ValueChanged
2019-11-25 00:07:35.420 Detail, Node025,   Received: 0x01, 0x0c, 0x00, 0x04, 0x00, 0x19, 0x06, 0x31, 0x05, 0x04, 0x22, 0x00, 0x00, 0xfa
2019-11-25 00:07:35.420 Detail, 
2019-11-25 00:07:35.420 Info, Node025, Received SensorMultiLevel report from node 25, instance 1, Power: value=0.0W
2019-11-25 00:07:35.420 Detail, Node025, Refreshed Value: old value=0.0, new value=0.0, type=decimal
2019-11-25 00:07:35.420 Detail, Node025, Changes to this value are not verified
2019-11-25 00:07:35.420 Detail, Node025, Notification: ValueChanged
2019-11-25 00:07:37.602 Detail, Node024,   Received: 0x01, 0x0c, 0x00, 0x04, 0x00, 0x18, 0x06, 0x31, 0x05, 0x04, 0x22, 0x00, 0x00, 0xfb
2019-11-25 00:07:37.602 Detail, 
2019-11-25 00:07:37.602 Info, Node024, Received SensorMultiLevel report from node 24, instance 1, Power: value=0.0W
2019-11-25 00:07:37.602 Detail, Node024, Refreshed Value: old value=0.0, new value=0.0, type=decimal
2019-11-25 00:07:37.602 Detail, Node024, Changes to this value are not verified
2019-11-25 00:07:37.602 Detail, Node024, Notification: ValueChanged
2019-11-25 00:13:29.355 Detail, Node038,   Received: 0x01, 0x14, 0x00, 0x04, 0x00, 0x26, 0x0e, 0x60, 0x0d, 0x01, 0x01, 0x32, 0x02, 0x21, 0x44, 0x00, 0x00, 0x00, 0x03, 0x00, 0x00, 0xfc
2019-11-25 00:13:29.355 Detail, 
2019-11-25 00:13:29.355 Info, Node038, Received a MultiChannelEncap from node 38, endpoint 1 for Command Class COMMAND_CLASS_METER
2019-11-25 00:13:29.355 Detail, Node038, Refreshed Value: old value=false, new value=false, type=bool
2019-11-25 00:13:29.355 Detail, Node038, Changes to this value are not verified
2019-11-25 00:13:29.355 Info, Node038, Received Meter report from node 38: Energy=0.03kWh
2019-11-25 00:13:29.355 Detail, Node038, Refreshed Value: old value=0.03, new value=0.03, type=decimal
2019-11-25 00:13:29.355 Detail, Node038, Changes to this value are not verified
2019-11-25 00:13:29.355 Detail, Node038, Notification: ValueChanged
2019-11-25 00:13:29.361 Detail, Node038, Notification: ValueChanged
2019-11-25 00:13:59.356 Detail, Node038,   Received: 0x01, 0x14, 0x00, 0x04, 0x00, 0x26, 0x0e, 0x60, 0x0d, 0x02, 0x01, 0x32, 0x02, 0x21, 0x44, 0x00, 0x00, 0x01, 0x82, 0x00, 0x00, 0x7f
2019-11-25 00:13:59.356 Detail, 
2019-11-25 00:13:59.356 Info, Node038, Received a MultiChannelEncap from node 38, endpoint 2 for Command Class COMMAND_CLASS_METER
2019-11-25 00:13:59.356 Detail, Node038, Refreshed Value: old value=false, new value=false, type=bool
2019-11-25 00:13:59.356 Detail, Node038, Changes to this value are not verified
2019-11-25 00:13:59.356 Info, Node038, Received Meter report from node 38: Energy=3.86kWh
2019-11-25 00:13:59.356 Detail, Node038, Refreshed Value: old value=3.84, new value=3.86, type=decimal
2019-11-25 00:13:59.356 Detail, Node038, Changes to this value are not verified
2019-11-25 00:13:59.356 Detail, Node038, Notification: ValueChanged
2019-11-25 00:13:59.362 Detail, Node038, Notification: ValueChanged
2019-11-25 00:18:36.412 Detail, Node025,   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x19, 0x0a, 0x32, 0x02, 0x21, 0x44, 0x00, 0x00, 0x01, 0x91, 0x00, 0x00, 0x3d
2019-11-25 00:18:36.412 Detail, 
2019-11-25 00:18:36.412 Detail, Node025, Refreshed Value: old value=false, new value=false, type=bool
2019-11-25 00:18:36.412 Detail, Node025, Changes to this value are not verified
2019-11-25 00:18:36.412 Info, Node025, Received Meter report from node 25: Energy=4.01kWh
2019-11-25 00:18:36.412 Detail, Node025, Refreshed Value: old value=4.01, new value=4.01, type=decimal
2019-11-25 00:18:36.412 Detail, Node025, Changes to this value are not verified
2019-11-25 00:18:36.412 Detail, Node025, Notification: ValueChanged
2019-11-25 00:18:36.419 Detail, Node025, Notification: ValueChanged
2019-11-25 00:18:43.601 Detail, Node024,   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x18, 0x0a, 0x32, 0x02, 0x21, 0x44, 0x00, 0x00, 0x00, 0x43, 0x00, 0x00, 0xef
2019-11-25 00:18:43.601 Detail, 
2019-11-25 00:18:43.601 Detail, Node024, Refreshed Value: old value=false, new value=false, type=bool
2019-11-25 00:18:43.601 Detail, Node024, Changes to this value are not verified
2019-11-25 00:18:43.601 Info, Node024, Received Meter report from node 24: Energy=0.67kWh
2019-11-25 00:18:43.601 Detail, Node024, Refreshed Value: old value=0.67, new value=0.67, type=decimal
2019-11-25 00:18:43.601 Detail, Node024, Changes to this value are not verified
2019-11-25 00:18:43.601 Detail, Node024, Notification: ValueChanged
2019-11-25 00:18:43.606 Detail, Node024, Notification: ValueChanged
2019-11-25 00:18:44.997 Detail, Node026,   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x1a, 0x0a, 0x32, 0x02, 0x21, 0x44, 0x00, 0x00, 0x00, 0x2b, 0x00, 0x00, 0x85
2019-11-25 00:18:44.997 Detail, 
2019-11-25 00:18:44.997 Detail, Node026, Refreshed Value: old value=false, new value=false, type=bool
2019-11-25 00:18:44.997 Detail, Node026, Changes to this value are not verified
2019-11-25 00:18:44.997 Info, Node026, Received Meter report from node 26: Energy=0.43kWh
2019-11-25 00:18:44.997 Detail, Node026, Refreshed Value: old value=0.43, new value=0.43, type=decimal
2019-11-25 00:18:44.997 Detail, Node026, Changes to this value are not verified
2019-11-25 00:18:44.997 Detail, Node026, Notification: ValueChanged
2019-11-25 00:18:45.001 Detail, Node026, Notification: ValueChanged
2019-11-25 00:18:45.401 Detail, Node027,   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x1b, 0x0a, 0x32, 0x02, 0x21, 0x44, 0x00, 0x00, 0x00, 0x6c, 0x00, 0x00, 0xc3
2019-11-25 00:18:45.401 Detail, 
2019-11-25 00:18:45.401 Detail, Node027, Refreshed Value: old value=false, new value=false, type=bool
2019-11-25 00:18:45.401 Detail, Node027, Changes to this value are not verified
2019-11-25 00:18:45.401 Info, Node027, Received Meter report from node 27: Energy=1.08kWh
2019-11-25 00:18:45.401 Detail, Node027, Refreshed Value: old value=1.08, new value=1.08, type=decimal
2019-11-25 00:18:45.401 Detail, Node027, Changes to this value are not verified
2019-11-25 00:18:45.401 Detail, Node027, Notification: ValueChanged
2019-11-25 00:18:45.405 Detail, Node027, Notification: ValueChanged
2019-11-25 00:31:26.394 Detail, Node027,   Received: 0x01, 0x0c, 0x00, 0x04, 0x00, 0x1b, 0x06, 0x31, 0x05, 0x04, 0x22, 0x00, 0x00, 0xf8
2019-11-25 00:31:26.394 Detail, 
2019-11-25 00:31:26.394 Info, Node027, Received SensorMultiLevel report from node 27, instance 1, Power: value=0.0W
2019-11-25 00:31:26.394 Detail, Node027, Refreshed Value: old value=0.0, new value=0.0, type=decimal
2019-11-25 00:31:26.394 Detail, Node027, Changes to this value are not verified
2019-11-25 00:31:26.394 Detail, Node027, Notification: ValueChanged
2019-11-25 00:32:49.462 Detail, Node023,   Received: 0x01, 0x08, 0x00, 0x04, 0x00, 0x17, 0x02, 0x84, 0x07, 0x65
2019-11-25 00:32:49.462 Detail, 
2019-11-25 00:32:49.462 Info, Node023, Received Wakeup Notification from node 23
2019-11-25 00:32:49.462 Info, Node023,   Node 23 has been marked as awake
2019-11-25 00:32:49.462 Detail, Node023, Queuing (WakeUp) WakeUpCmd_NoMoreInformation (Node=23): 0x01, 0x09, 0x00, 0x13, 0x17, 0x02, 0x84, 0x08, 0x25, 0xa3, 0xfa
2019-11-25 00:32:49.462 Detail, Node023, Notification: Notification - Node Awake
2019-11-25 00:32:49.465 Detail, 
2019-11-25 00:32:49.465 Info, Node023, Sending (WakeUp) message (Callback ID=0xa3, Expected Reply=0x13) - WakeUpCmd_NoMoreInformation (Node=23): 0x01, 0x09, 0x00, 0x13, 0x17, 0x02, 0x84, 0x08, 0x25, 0xa3, 0xfa
2019-11-25 00:32:49.475 Detail, Node023,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-11-25 00:32:49.475 Detail, Node023,   ZW_SEND_DATA delivered to Z-Wave stack
2019-11-25 00:32:49.527 Detail, Node023,   Received: 0x01, 0x08, 0x00, 0x04, 0x00, 0x17, 0x02, 0x84, 0x07, 0x65
2019-11-25 00:32:49.527 Detail, 
2019-11-25 00:32:49.527 Info, Node023, Received Wakeup Notification from node 23
2019-11-25 00:32:49.527 Detail, Node023, Queuing (WakeUp) WakeUpCmd_NoMoreInformation (Node=23): 0x01, 0x09, 0x00, 0x13, 0x17, 0x02, 0x84, 0x08, 0x25, 0xa4, 0xfd
2019-11-25 00:32:49.644 Detail, Node023,   Received: 0x01, 0x08, 0x00, 0x04, 0x00, 0x17, 0x02, 0x84, 0x07, 0x65
2019-11-25 00:32:49.644 Detail, 
2019-11-25 00:32:49.644 Info, Node023, Received Wakeup Notification from node 23
2019-11-25 00:32:49.644 Detail, Node023, Queuing (WakeUp) WakeUpCmd_NoMoreInformation (Node=23): 0x01, 0x09, 0x00, 0x13, 0x17, 0x02, 0x84, 0x08, 0x25, 0xa5, 0xfc
2019-11-25 00:32:49.784 Detail, Node023,   Received: 0x01, 0x07, 0x00, 0x13, 0xa3, 0x00, 0x00, 0x20, 0x68
2019-11-25 00:32:49.784 Detail, Node023,   ZW_SEND_DATA Request with callback ID 0xa3 received (expected 0xa3)
2019-11-25 00:32:49.784 Info, Node023, Request RTT 319 Average Request RTT 244
2019-11-25 00:32:49.784 Info, Node023,   Node 23 has been marked as asleep
2019-11-25 00:32:49.784 Detail,   Expected callbackId was received
2019-11-25 00:32:49.784 Detail,   Expected reply was received
2019-11-25 00:32:49.784 Detail,   Message transaction complete
2019-11-25 00:32:49.784 Detail, 
2019-11-25 00:32:49.784 Detail, Node023, Removing current message
2019-11-25 00:32:49.784 Detail, Node023, Notification: Notification - Node Asleep
2019-11-25 00:32:49.786 Detail, 
2019-11-25 00:32:49.786 Info, Node023, Sending (WakeUp) message (Callback ID=0xa4, Expected Reply=0x13) - WakeUpCmd_NoMoreInformation (Node=23): 0x01, 0x09, 0x00, 0x13, 0x17, 0x02, 0x84, 0x08, 0x25, 0xa4, 0xfd
2019-11-25 00:32:49.797 Detail, Node023,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-11-25 00:32:49.797 Detail, Node023,   ZW_SEND_DATA delivered to Z-Wave stack
2019-11-25 00:32:50.355 Detail, Node023,   Received: 0x01, 0x07, 0x00, 0x13, 0xa4, 0x00, 0x00, 0x38, 0x77
2019-11-25 00:32:50.355 Detail, Node023,   ZW_SEND_DATA Request with callback ID 0xa4 received (expected 0xa4)
2019-11-25 00:32:50.355 Info, Node023, Request RTT 569 Average Request RTT 406
2019-11-25 00:32:50.355 Detail,   Expected callbackId was received
2019-11-25 00:32:50.355 Detail,   Expected reply was received
2019-11-25 00:32:50.355 Detail,   Message transaction complete
2019-11-25 00:32:50.355 Detail, 
2019-11-25 00:32:50.355 Detail, Node023, Removing current message
2019-11-25 00:32:50.355 Detail, 
2019-11-25 00:32:50.355 Info, Node023, Sending (WakeUp) message (Callback ID=0xa5, Expected Reply=0x13) - WakeUpCmd_NoMoreInformation (Node=23): 0x01, 0x09, 0x00, 0x13, 0x17, 0x02, 0x84, 0x08, 0x25, 0xa5, 0xfc
2019-11-25 00:32:50.496 Detail, Node023,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-11-25 00:32:50.496 Detail, Node023,   ZW_SEND_DATA delivered to Z-Wave stack
2019-11-25 00:32:50.557 Detail, Node023,   Received: 0x01, 0x07, 0x00, 0x13, 0xa5, 0x00, 0x00, 0x14, 0x5a
2019-11-25 00:32:50.557 Detail, Node023,   ZW_SEND_DATA Request with callback ID 0xa5 received (expected 0xa5)
2019-11-25 00:32:50.557 Info, Node023, Request RTT 201 Average Request RTT 303
2019-11-25 00:32:50.557 Detail,   Expected callbackId was received
2019-11-25 00:32:50.557 Detail,   Expected reply was received
2019-11-25 00:32:50.557 Detail,   Message transaction complete
2019-11-25 00:32:50.557 Detail, 
2019-11-25 00:32:50.557 Detail, Node023, Removing current message
2019-11-25 00:40:37.634 Detail, Node036,   Received: 0x01, 0x08, 0x00, 0x04, 0x00, 0x24, 0x02, 0x84, 0x07, 0x56
2019-11-25 00:40:37.634 Detail, 
2019-11-25 00:40:37.634 Info, Node036, Received Wakeup Notification from node 36
2019-11-25 00:40:37.634 Info, Node036,   Node 36 has been marked as awake
2019-11-25 00:40:37.634 Detail, Node036, Queuing (WakeUp) WakeUpCmd_NoMoreInformation (Node=36): 0x01, 0x09, 0x00, 0x13, 0x24, 0x02, 0x84, 0x08, 0x25, 0xa6, 0xcc
2019-11-25 00:40:37.634 Detail, Node036, Notification: Notification - Node Awake
2019-11-25 00:40:37.637 Detail, 
2019-11-25 00:40:37.637 Info, Node036, Sending (WakeUp) message (Callback ID=0xa6, Expected Reply=0x13) - WakeUpCmd_NoMoreInformation (Node=36): 0x01, 0x09, 0x00, 0x13, 0x24, 0x02, 0x84, 0x08, 0x25, 0xa6, 0xcc
2019-11-25 00:40:37.647 Detail, Node036,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-11-25 00:40:37.648 Detail, Node036,   ZW_SEND_DATA delivered to Z-Wave stack
2019-11-25 00:40:37.664 Detail, Node036,   Received: 0x01, 0x07, 0x00, 0x13, 0xa6, 0x00, 0x00, 0x02, 0x4f
2019-11-25 00:40:37.664 Detail, Node036,   ZW_SEND_DATA Request with callback ID 0xa6 received (expected 0xa6)
2019-11-25 00:40:37.664 Info, Node036, Request RTT 26 Average Request RTT 26
2019-11-25 00:40:37.664 Info, Node036,   Node 36 has been marked as asleep

Oddly, Z-Wave Node Management dropdown list is complete with my nodes :

M0E-lnx · November 25, 2019, 7:08pm

Could you tail -f OZW_Log.txt and see if it’s at a standstill with occasional output showing up when you trigger some stuff or does it constantly show output scrolling through the screen?

Fabio06320 · November 25, 2019, 7:34pm

Here is the result of the order tail -f OZW_Log.txt, it seems right, do not you think?

root@homeassistant:/usr/share/hassio/homeassistant# tail -f OZW_Log.txt
2019-11-25 20:26:13.357 Detail, Node014, Notification: ValueChanged
2019-11-25 20:27:26.650 Detail, Node014,   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x0e, 0x0a, 0x32, 0x02, 0x21, 0x34, 0x00, 0x00, 0x01, 0xb3, 0x00, 0x00, 0x78
2019-11-25 20:27:26.650 Detail, 
2019-11-25 20:27:26.650 Detail, Node014, Refreshed Value: old value=false, new value=false, type=bool
2019-11-25 20:27:26.650 Detail, Node014, Changes to this value are not verified
2019-11-25 20:27:26.650 Info, Node014, Received Meter report from node 14: Power=43.5W
2019-11-25 20:27:26.650 Detail, Node014, Refreshed Value: old value=41.9, new value=43.5, type=decimal
2019-11-25 20:27:26.650 Detail, Node014, Changes to this value are not verified
2019-11-25 20:27:26.650 Detail, Node014, Notification: ValueChanged
2019-11-25 20:27:26.661 Detail, Node014, Notification: ValueChanged
2019-11-25 20:28:22.525 Info, Node003, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 1 - True
2019-11-25 20:28:22.525 Info, Node003, SwitchBinary::Set - Setting node 3 to On
2019-11-25 20:28:22.525 Detail, Node003, Queuing (Send) MultiChannel Encapsulated (instance=1): SwitchBinaryCmd_Set (Node=3): 0x01, 0x0e, 0x00, 0x13, 0x03, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0xff, 0x25, 0x6a, 0x1f
2019-11-25 20:28:22.525 Detail, Node003, Queuing (Send) MultiChannel Encapsulated (instance=1): SwitchBinaryCmd_Get (Node=3): 0x01, 0x0d, 0x00, 0x13, 0x03, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x6b, 0xe0
2019-11-25 20:28:22.525 Detail, 
2019-11-25 20:28:22.525 Info, Node003, Sending (Send) message (Callback ID=0x6a, Expected Reply=0x13) - MultiChannel Encapsulated (instance=1): SwitchBinaryCmd_Set (Node=3): 0x01, 0x0e, 0x00, 0x13, 0x03, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0xff, 0x25, 0x6a, 0x1f
2019-11-25 20:28:22.525 Info, Node003, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 2 - True
2019-11-25 20:28:22.525 Info, Node003, SwitchBinary::Set - Setting node 3 to On
2019-11-25 20:28:22.525 Detail, Node003, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=3): 0x01, 0x0e, 0x00, 0x13, 0x03, 0x07, 0x60, 0x0d, 0x01, 0x02, 0x25, 0x01, 0xff, 0x25, 0x6c, 0x1a
2019-11-25 20:28:22.526 Detail, Node003, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=3): 0x01, 0x0d, 0x00, 0x13, 0x03, 0x06, 0x60, 0x0d, 0x01, 0x02, 0x25, 0x02, 0x25, 0x6d, 0xe5
2019-11-25 20:28:22.665 Detail, Node003,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-11-25 20:28:22.665 Detail, Node003,   ZW_SEND_DATA delivered to Z-Wave stack
2019-11-25 20:28:24.600 Detail, Node003,   Received: 0x01, 0x07, 0x00, 0x13, 0x6a, 0x00, 0x00, 0xcf, 0x4e
2019-11-25 20:28:24.600 Detail, Node003,   ZW_SEND_DATA Request with callback ID 0x6a received (expected 0x6a)
2019-11-25 20:28:24.600 Info, Node003, Request RTT 2075 Average Request RTT 1118
2019-11-25 20:28:24.600 Detail,   Expected callbackId was received
2019-11-25 20:28:24.600 Detail,   Expected reply was received
2019-11-25 20:28:24.600 Detail,   Message transaction complete
2019-11-25 20:28:24.600 Detail, 
2019-11-25 20:28:24.600 Detail, Node003, Removing current message
2019-11-25 20:28:24.600 Detail, 
2019-11-25 20:28:24.600 Info, Node003, Sending (Send) message (Callback ID=0x6b, Expected Reply=0x04) - MultiChannel Encapsulated (instance=1): SwitchBinaryCmd_Get (Node=3): 0x01, 0x0d, 0x00, 0x13, 0x03, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x6b, 0xe0
2019-11-25 20:28:24.612 Detail, Node003,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-11-25 20:28:24.612 Detail, Node003,   ZW_SEND_DATA delivered to Z-Wave stack
2019-11-25 20:28:24.670 Detail, Node003,   Received: 0x01, 0x07, 0x00, 0x13, 0x6b, 0x00, 0x00, 0x06, 0x86
2019-11-25 20:28:24.670 Detail, Node003,   ZW_SEND_DATA Request with callback ID 0x6b received (expected 0x6b)
2019-11-25 20:28:24.670 Info, Node003, Request RTT 69 Average Request RTT 593
2019-11-25 20:28:24.670 Detail,   Expected callbackId was received
2019-11-25 20:28:24.743 Detail, Node003,   Received: 0x01, 0x0d, 0x00, 0x04, 0x00, 0x03, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x03, 0xff, 0x46
2019-11-25 20:28:24.743 Detail, 
2019-11-25 20:28:24.743 Info, Node003, Response RTT 142 Average Response RTT 204
2019-11-25 20:28:24.743 Info, Node003, Received a MultiChannelEncap from node 3, endpoint 1 for Command Class COMMAND_CLASS_SWITCH_BINARY
2019-11-25 20:28:24.743 Info, Node003, Received SwitchBinary report from node 3: level=On
2019-11-25 20:28:24.743 Detail, Node003, Refreshed Value: old value=false, new value=true, type=bool
2019-11-25 20:28:24.743 Detail, Node003, Changes to this value are not verified
2019-11-25 20:28:24.743 Detail, Node003,   Expected reply and command class was received
2019-11-25 20:28:24.743 Detail, Node003,   Message transaction complete
2019-11-25 20:28:24.743 Detail, 
2019-11-25 20:28:24.743 Detail, Node003, Removing current message
2019-11-25 20:28:24.743 Detail, Node003, Notification: ValueChanged
2019-11-25 20:28:24.755 Detail, 
2019-11-25 20:28:24.755 Info, Node003, Sending (Send) message (Callback ID=0x6c, Expected Reply=0x13) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=3): 0x01, 0x0e, 0x00, 0x13, 0x03, 0x07, 0x60, 0x0d, 0x01, 0x02, 0x25, 0x01, 0xff, 0x25, 0x6c, 0x1a
2019-11-25 20:28:24.766 Detail, Node003,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-11-25 20:28:24.766 Detail, Node003,   ZW_SEND_DATA delivered to Z-Wave stack
2019-11-25 20:28:24.871 Detail, Node003,   Received: 0x01, 0x07, 0x00, 0x13, 0x6c, 0x00, 0x00, 0x0b, 0x8c
2019-11-25 20:28:24.871 Detail, Node003,   ZW_SEND_DATA Request with callback ID 0x6c received (expected 0x6c)
2019-11-25 20:28:24.871 Info, Node003, Request RTT 116 Average Request RTT 354
2019-11-25 20:28:24.871 Detail,   Expected callbackId was received
2019-11-25 20:28:24.871 Detail,   Expected reply was received
2019-11-25 20:28:24.871 Detail,   Message transaction complete
2019-11-25 20:28:24.871 Detail, 
2019-11-25 20:28:24.871 Detail, Node003, Removing current message
2019-11-25 20:28:24.871 Detail, 
2019-11-25 20:28:24.871 Info, Node003, Sending (Send) message (Callback ID=0x6d, Expected Reply=0x04) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=3): 0x01, 0x0d, 0x00, 0x13, 0x03, 0x06, 0x60, 0x0d, 0x01, 0x02, 0x25, 0x02, 0x25, 0x6d, 0xe5
2019-11-25 20:28:24.882 Detail, Node003,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-11-25 20:28:24.882 Detail, Node003,   ZW_SEND_DATA delivered to Z-Wave stack
2019-11-25 20:28:24.940 Detail, Node003,   Received: 0x01, 0x07, 0x00, 0x13, 0x6d, 0x00, 0x00, 0x06, 0x80
2019-11-25 20:28:24.940 Detail, Node003,   ZW_SEND_DATA Request with callback ID 0x6d received (expected 0x6d)
2019-11-25 20:28:24.940 Info, Node003, Request RTT 68 Average Request RTT 211
2019-11-25 20:28:24.940 Detail,   Expected callbackId was received
2019-11-25 20:28:25.016 Detail, Node003,   Received: 0x01, 0x0d, 0x00, 0x04, 0x00, 0x03, 0x07, 0x60, 0x0d, 0x02, 0x01, 0x25, 0x03, 0xff, 0x45
2019-11-25 20:28:25.016 Detail, 
2019-11-25 20:28:25.016 Info, Node003, Response RTT 146 Average Response RTT 175
2019-11-25 20:28:25.016 Info, Node003, Received a MultiChannelEncap from node 3, endpoint 2 for Command Class COMMAND_CLASS_SWITCH_BINARY
2019-11-25 20:28:25.016 Info, Node003, Received SwitchBinary report from node 3: level=On
2019-11-25 20:28:25.016 Detail, Node003, Refreshed Value: old value=false, new value=true, type=bool
2019-11-25 20:28:25.016 Detail, Node003, Changes to this value are not verified
2019-11-25 20:28:25.016 Detail, Node003,   Expected reply and command class was received
2019-11-25 20:28:25.016 Detail, Node003,   Message transaction complete
2019-11-25 20:28:25.016 Detail, 
2019-11-25 20:28:25.016 Detail, Node003, Removing current message
2019-11-25 20:28:25.016 Detail, Node003, Notification: ValueChanged
2019-11-25 20:29:49.432 Detail, Node004,   Received: 0x01, 0x0c, 0x00, 0x04, 0x00, 0x04, 0x06, 0x35, 0x05, 0x04, 0x22, 0x00, 0x52, 0xb1
2019-11-25 20:29:49.432 Detail, 
2019-11-25 20:29:49.432 Info, Node004, ApplicationCommandHandler - Unhandled Command Class 0x35
2019-11-25 20:29:49.530 Detail, Node004,   Received: 0x01, 0x0c, 0x00, 0x04, 0x00, 0x04, 0x06, 0x31, 0x05, 0x04, 0x22, 0x00, 0x12, 0xf5
2019-11-25 20:29:49.530 Detail, 
2019-11-25 20:29:49.530 Info, Node004, Received SensorMultiLevel report from node 4, instance 1, Power: value=1.8W
2019-11-25 20:29:49.530 Detail, Node004, Refreshed Value: old value=1.9, new value=1.8, type=decimal
2019-11-25 20:29:49.530 Detail, Node004, Changes to this value are not verified
2019-11-25 20:29:49.530 Detail, Node004, Notification: ValueChanged
2019-11-25 20:30:19.856 Detail, Node004,   Received: 0x01, 0x0c, 0x00, 0x04, 0x00, 0x04, 0x06, 0x31, 0x05, 0x04, 0x22, 0x00, 0x13, 0xf4
2019-11-25 20:30:19.856 Detail, 
2019-11-25 20:30:19.856 Info, Node004, Received SensorMultiLevel report from node 4, instance 1, Power: value=1.9W
2019-11-25 20:30:19.856 Detail, Node004, Refreshed Value: old value=1.8, new value=1.9, type=decimal
2019-11-25 20:30:19.856 Detail, Node004, Changes to this value are not verified
2019-11-25 20:30:19.856 Detail, Node004, Notification: ValueChanged

M0E-lnx · November 25, 2019, 7:48pm

I was asking if it prints messages non-stop or do you only see output when you trigger devices?

Fabio06320 · November 25, 2019, 7:50pm

Ah OK, yes just only output devices and stop