Suddenly can't add nodes

SnapETom · April 24, 2020, 2:14am

I have about a dozen Jasco/GE light switches connected to a Aeotec USB Z-Stick on a Raspberry Pi 3b+. For a while, they were working great with Homeassistant. After several breaking changes, I just decided to completely reinstall HA and do things the “right way” using the ZWave option on the configuration menu.

I’ve ran into an issue where I can’t add more than 7 devices. Things that were well in range before now cannot be added.

When I click Add Node, journalctl reports:

Apr 24 01:55:29 pibox hass[1148]: 2020-04-24 01:55:29 INFO (SyncWorker_9) [homeassistant.components.zwave] Z-Wave add_node have been initialized
Apr 24 02:02:02 pibox hass[1148]: 2020-04-24 02:02:02 INFO (MainThread) [homeassistant.components.websocket_api.http.connection.1594965840] Connection closed by client
Apr 24 02:03:19 pibox hass[1148]: 2020-04-24 02:03:19 ERROR (MainThread) [homeassistant.core] Error doing job: SSL error in data received
Apr 24 02:03:19 pibox hass[1148]: Traceback (most recent call last):
Apr 24 02:03:19 pibox hass[1148]:   File "/usr/local/lib/python3.7/asyncio/sslproto.py", line 526, in data_received
Apr 24 02:03:19 pibox hass[1148]:     ssldata, appdata = self._sslpipe.feed_ssldata(data)
Apr 24 02:03:19 pibox hass[1148]:   File "/usr/local/lib/python3.7/asyncio/sslproto.py", line 207, in feed_ssldata
Apr 24 02:03:19 pibox hass[1148]:     self._sslobj.unwrap()
Apr 24 02:03:19 pibox hass[1148]:   File "/usr/local/lib/python3.7/ssl.py", line 767, in unwrap
Apr 24 02:03:19 pibox hass[1148]:     return self._sslobj.shutdown()
Apr 24 02:03:19 pibox hass[1148]: ssl.SSLError: [SSL: KRB5_S_INIT] application data after close notify (_ssl.c:2609)
Apr 24 02:03:19 pibox hass[1148]: 2020-04-24 02:03:19 INFO (MainThread) [homeassistant.components.websocket_api.http.connection.1594612784] Connection closed by client

And OZW_Log reports:

2020-04-24 01:55:29.021 Detail, Queuing (Controller) Add Device
2020-04-24 01:55:29.022 Info, Add Device
2020-04-24 01:55:29.022 Detail, contrlr, Queuing (Command) ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x3a, 0x4b
2020-04-24 01:55:29.022 Detail, Notification: ControllerCommand - Starting
2020-04-24 01:55:29.023 Detail,
2020-04-24 01:55:29.023 Info, contrlr, Sending (Command) message (Callback ID=0x3a, Expected Reply=0x4a) - ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x3a, 0x4b
2020-04-24 01:55:29.027 Detail, contrlr,   Received: 0x01, 0x07, 0x00, 0x4a, 0x3a, 0x01, 0x00, 0x00, 0x89
2020-04-24 01:55:29.027 Detail,
2020-04-24 01:55:29.027 Info, contrlr, FUNC_ID_ZW_ADD_NODE_TO_NETWORK:
2020-04-24 01:55:29.028 Info, contrlr, ADD_NODE_STATUS_LEARN_READY
2020-04-24 01:55:29.028 Detail, Node001,   Expected callbackId was received
2020-04-24 01:55:29.028 Detail, Node001,   Expected reply was received
2020-04-24 01:55:29.028 Detail, Node001,   Message transaction complete
2020-04-24 01:55:29.028 Detail,
2020-04-24 01:55:29.028 Detail, contrlr, Removing current message
2020-04-24 01:55:29.028 Detail, Notification: ControllerCommand - Waiting
2020-04-24 01:55:29.031 Info, WriteNextMsg Controller nothing to do

And nothing. This timeout actually puts either homeassistant or OpenZWave into this blocked state. If I try to turn things on and off, I can see OpenZWave keep sending out commands, but nothing actually happens to the lights.

2020-04-24 02:05:55.869 Info, Node007, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 1 - False
2020-04-24 02:05:55.869 Info, Node007, SwitchBinary::Set - Setting node 7 to Off
2020-04-24 02:05:55.869 Detail, Node007, Queuing (Send) SwitchBinaryCmd_Set (Node=7): 0x01, 0x0a, 0x00, 0x13, 0x07, 0x03, 0x25, 0x01, 0x00, 0x25, 0x3d, 0xde
2020-04-24 02:05:55.869 Detail, Node007, Queuing (Send) SwitchBinaryCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x25, 0x02, 0x25, 0x3e, 0xdc

Any idea what’s going on? This is quite frustrating because everything was working fine for years, so I doubt it’s a signal strength issue.

Raspbian Buster
Raspberry Pi 3b+
Python 3.7.3
HA running in a virtual environment

SnapETom · April 24, 2020, 10:29pm

TL;DR - The Jasco/GE/Honeywell Lightswitches remember if they’re paired. Reseting does not change this. You have to unpair them with any Z-Wave Controller first.

After mulling over it for a night, the issue had to be either the switches, Aeotec Stick, the Pi, or Open Z-Wave itself. I concentrated on the switches because that was the easiest.

Through trial and error, I found some interesting behavior about these switches. I had a second Aeotec Stick lying around because when I first encountered this problem, it was my first guess at a point of failure. I found that many of the light switches never actually paired with the USB stick. The stick never received or acknowledge the pairing. They all unpaired just fine. This was true even though I did the reset sequence on the switch.

So, the order to add all of this was:

Unpair each switch with any Z-Wave controller switch. Throughout all of this, I had the new Aeotec controller plugged into the Pi. I unpaired with the old controller.
90% of the time, that’s all you’ll need. Add Node will work. A couple of times, I also had to reset the switch (3 ups, 3 downs quickly).
Add Node in HA.

Apparently, the switches keeps a state on whether it’s paired with a controller and will behave accordingly. When it receives an unpair command, it does not care what controller told it to unpair. It just does this and will be receptive to a pairing command later. Also a reset does not forget the pairing!

This was interesting for me because I had one light put in that never connected to my network. Once I did this sequence, now it works. I wonder if it was a return or flashed incorrectly.