Adding Aeotec Siren6

acee · August 2, 2019, 7:34pm

I’m trying to add a Z-Wave device, the Aeotec Siren6, however am getting a lot of inconsistent behaviour to the point now where when I run the inclusion, nothing shows up in the inbox in PaperUI anymore.

At first, when I tried including the device, it appeared in the inbox (as unknown, which is expected as I know the Siren6 is not in the database yet). However, it would always show as offline, communication error. I wasn’t sure how to use exclusion mode in openhab, so I ended up reseting the Siren6 completely and added it again (would show up as a new node in openhab). It was still offline, but eventually it showed as Online.

Wanting to clean-up the mess of duplicate nodes, I manually excluded the device outside of openhab (I am using the Aeotec Z-Stick). I also used Domoticz’s node management tool to remove the duplicate nodes from earlier.

Now, however, when I try to add it back in openhab, it doesn’t appear at all in the inbox anymore. However, I do see a number of log messages below that make it look like something is found:

15:19:17.691 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart
15:19:17.694 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 12: Transaction COMPLETED
15:19:17.704 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 140ms
15:19:17.714 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 12: Transaction completed
15:19:17.718 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:12 DONE
15:19:17.722 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
15:19:17.730 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
15:19:19.596 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - NODE 10: Device discovery completed
15:19:19.618 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - NODE 10: Device discovery resolved to thingType zwave:homeseer_hsds100_00_000
15:19:19.630 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - NODE 15: Device discovery completed
15:19:19.640 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - NODE 15: Device discovery resolved to thingType zwave:aeotec_zwa005_00_000
15:19:22.071 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 02 02 00 00 B2 
15:19:22.083 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=2, payload=02 02 00 00 
15:19:22.087 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=2, payload=02 02 00 00 
15:19:22.093 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
15:19:22.096 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
15:19:22.103 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: null
15:19:22.108 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=2, payload=02 02 00 00 
15:19:22.114 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Add Node: New node found.
15:19:22.118 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
15:19:22.121 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
15:19:22.345 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1B 00 4A 02 03 16 14 04 03 01 5E 86 70 72 59 85 73 8E 60 5A 55 98 9F 6C 7A 71 79 26 
15:19:22.354 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=3, callback=2, payload=02 03 16 14 04 03 01 5E 86 70 72 59 85 73 8E 60 5A 55 98 9F 6C 7A 71 79 
15:19:22.359 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=3, callback=2, payload=02 03 16 14 04 03 01 5E 86 70 72 59 85 73 8E 60 5A 55 98 9F 6C 7A 71 79 
15:19:22.363 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
15:19:22.368 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
15:19:22.379 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: null
15:19:22.388 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=3, callback=2, payload=02 03 16 14 04 03 01 5E 86 70 72 59 85 73 8E 60 5A 55 98 9F 6C 7A 71 79 
15:19:22.395 [DEBUG] [col.serialmessage.AddNodeMessageClass] - NODE 22: Adding slave.
15:19:22.398 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeStart, new event IncludeSlaveFound
15:19:22.402 [DEBUG] [nal.protocol.ZWaveInclusionController] - NODE 22: Including node.
15:19:22.405 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
15:19:22.407 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
15:19:22.711 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 02 05 16 00 A3 
15:19:22.721 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=5, callback=2, payload=02 05 16 00 
15:19:22.729 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=5, callback=2, payload=02 05 16 00 
15:19:22.732 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
15:19:22.736 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
15:19:22.742 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: null
15:19:22.746 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=5, callback=2, payload=02 05 16 00 
15:19:22.754 [DEBUG] [col.serialmessage.AddNodeMessageClass] - NODE 22: Add Node: Protocol done.
15:19:22.758 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSlaveFound, new event IncludeProtocolDone
15:19:22.766 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
15:19:22.774 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 13 to queue - size 1
15:19:22.780 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
15:19:22.791 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 03 B6 
15:19:22.797 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 03 B6 
15:19:22.802 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
15:19:22.803 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
15:19:22.816 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
15:19:22.821 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 13: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 3
15:19:22.834 [DEBUG] [nal.protocol.ZWaveInclusionController] - NODE 22: Inclusion protocol completed.
15:19:22.855 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 03 06 16 00 A1 
15:19:22.861 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=3, payload=03 06 16 00 
15:19:27.835 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 255: TID 13: Timeout at state WAIT_REQUEST. 3 retries remaining.
15:19:27.847 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - TID 13: Transaction is current transaction, so clearing!!!!!
15:19:27.850 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 13: Transaction CANCELLED
15:19:27.856 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:13 CANCELLED
15:19:27.862 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
15:19:35.493 [INFO ] [smarthome.event.ItemStateChangedEvent] - LocalComputer_Cpu_LoadAverage_5 changed from 1.6 to 1.4
15:19:35.512 [INFO ] [smarthome.event.ItemStateChangedEvent] - LocalComputer_Cpu_SystemUptime changed from 3.8 to 4.8
15:19:35.526 [INFO ] [smarthome.event.ItemStateChangedEvent] - LocalComputer_Cpu_LoadAverage_1 changed from 2.4 to 1.2
15:19:37.835 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion timer at IncludeProtocolDone
15:19:37.847 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
15:19:37.854 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 14 to queue - size 1
15:19:37.860 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
15:19:37.871 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 00 B5 
15:19:37.876 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 00 B5 
15:19:37.884 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
15:19:37.889 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
15:19:37.897 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 2<>126 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
15:19:37.897 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 14: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
15:19:37.913 [DEBUG] [nal.protocol.ZWaveInclusionController] - ZWave controller end exclusion
15:19:37.916 [DEBUG] [ave.internal.protocol.ZWaveController] - ZWaveController include done
15:19:42.905 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 255: TID 14: Timeout at state WAIT_REQUEST. 3 retries remaining.
15:19:42.915 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - TID 14: Transaction is current transaction, so clearing!!!!!
15:19:42.925 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 14: Transaction CANCELLED
15:19:42.935 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:14 CANCELLED
15:19:42.946 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
15:19:47.476 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:c448fb80
15:19:47.486 [DEBUG] [ave.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do

Can anyone help me understand what I need to do to get the device added into openhab correctly so that I could help with getting this device (Siren6) added into the Z-Wave database?

Thanks for your help!

Bruce_Osborne · August 2, 2019, 7:41pm

Any idea what Node ID the Siren is? There are several listed in the log. I would guess Node 22. If there is an xml file ENDING in node_22 it would be helpful in getting the device added.

acee · August 2, 2019, 7:46pm

I think in this case it would have been node 22. However I don’t get the node being added into Openhab anymore (I used to the first few times I added it), it doesn’t show up in the PaperUI inbox anymore, so I’m confused what I should try next?

The device itself seems to respond as if it was included properly (the LED that blinks indicating its ready to be included turns off).

Bruce_Osborne · August 2, 2019, 8:18pm

no xml file?

acee · August 2, 2019, 9:55pm

I restarted openhab and after leaving it for a while there is a XML file for node 22 now, but there doesn’t seem to be much in it. I’m going to try excluding and running the inclusion again, as it seemed like something wasn’t working right until I restarted openhab.

Bruce_Osborne · August 2, 2019, 10:08pm

If you post the xml file here is can help us if it needs to be added to the database.

acee · August 2, 2019, 10:13pm

This is what is in the XML file from node 22: node22.xml (1.8 KB)

I have included the device again (now showing as node 26), but there is no xml file yet. If/when that is generated I’ll post it too if it looks different than the node 22 one.

acee · August 2, 2019, 10:43pm

Ok, there is a lot of log activity going on right now for the new node 26 that came up after I re-ran the inclusion. The communication activity LED on the Aeotec Z-Stick is also flashing very rapidly, so it seems like it’s getting some data. Hopefully this will generate a more complete XML file when done - I’ll check again in a bit and post anything that results!

The log messages that are streaming by look like this:

2019-08-02 18:41:50.353 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1e07071.
2019-08-02 18:41:50.353 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1e07071.
2019-08-02 18:41:50.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: notifyTransactionResponse TID:6909 DONE
2019-08-02 18:41:50.354 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-08-02 18:41:50.357 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 26: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@e7ee2b
2019-08-02 18:41:50.357 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 26: Node Init transaction completed with response COMPLETE
2019-08-02 18:41:50.357 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 26: MultiInstance init first=false
2019-08-02 18:41:50.357 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 26: Initialising endpoints - version 2
2019-08-02 18:41:50.357 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 26: Creating new message for command MULTI_CHANNEL_CAPABILITY_GET endpoint 1
2019-08-02 18:41:50.358 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 26: Creating new message for command MULTI_CHANNEL_CAPABILITY_GET endpoint 2
2019-08-02 18:41:50.359 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 26: Creating new message for command MULTI_CHANNEL_CAPABILITY_GET endpoint 3
2019-08-02 18:41:50.359 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 26: Creating new message for command MULTI_CHANNEL_CAPABILITY_GET endpoint 4
2019-08-02 18:41:50.360 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 26: Creating new message for command MULTI_CHANNEL_CAPABILITY_GET endpoint 5
2019-08-02 18:41:50.360 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 26: Creating new message for command MULTI_CHANNEL_CAPABILITY_GET endpoint 6
2019-08-02 18:41:50.361 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 26: Creating new message for command MULTI_CHANNEL_CAPABILITY_GET endpoint 7
2019-08-02 18:41:50.361 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 26: Creating new message for command MULTI_CHANNEL_CAPABILITY_GET endpoint 8
2019-08-02 18:41:50.362 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 26: MultiInstance init returned 8
2019-08-02 18:41:50.362 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 26: ZWaveCommandClassTransactionPayload - send to node
2019-08-02 18:41:50.363 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
2019-08-02 18:41:50.363 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2019-08-02 18:41:50.363 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@a11976

Bruce_Osborne · August 2, 2019, 11:10pm

That looks like corrupted data to me.

  <manufacturer>0x7fffffff</manufacturer>
  <deviceId>0x7fffffff</deviceId>
  <deviceType>0x7fffffff</deviceType>

acee · August 2, 2019, 11:14pm

Thanks for taking a look. I was hoping there would be another XML file from the after re-adding the device, but the log messages are still streaming by and they look like they are a lot of the same thing and there is no new XML file yet.

I notice that there are some error-level messages there too:

2019-08-02 18:43:32.596 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Application Command Request (ALIVE:ENDPOINTS)
2019-08-02 18:43:32.597 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: Incoming command class COMMAND_CLASS_MULTI_CHANNEL, endpoint 0
2019-08-02 18:43:32.598 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
2019-08-02 18:43:32.599 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 26: Received COMMAND_CLASS_MULTI_CHANNEL V2 MULTI_CHANNEL_CAPABILITY_REPORT
2019-08-02 18:43:32.600 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 26: Process Multi-channel capability Report
2019-08-02 18:43:32.601 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 26: Endpoints are the same device class = true
2019-08-02 18:43:32.602 [ERROR] [class.ZWaveMultiInstanceCommandClass] - NODE 26: Endpoint 1 has invalid device class. generic = 0x3, specific = 0x1.
2019-08-02 18:43:32.603 [ERROR] [class.ZWaveMultiInstanceCommandClass] - NODE 26: Endpoint 2 has invalid device class. generic = 0x3, specific = 0x1.
2019-08-02 18:43:32.603 [ERROR] [class.ZWaveMultiInstanceCommandClass] - NODE 26: Endpoint 3 has invalid device class. generic = 0x3, specific = 0x1.
2019-08-02 18:43:32.604 [ERROR] [class.ZWaveMultiInstanceCommandClass] - NODE 26: Endpoint 4 has invalid device class. generic = 0x3, specific = 0x1.
2019-08-02 18:43:32.604 [ERROR] [class.ZWaveMultiInstanceCommandClass] - NODE 26: Endpoint 5 has invalid device class. generic = 0x3, specific = 0x1.
2019-08-02 18:43:32.605 [ERROR] [class.ZWaveMultiInstanceCommandClass] - NODE 26: Endpoint 6 has invalid device class. generic = 0x3, specific = 0x1.
2019-08-02 18:43:32.605 [ERROR] [class.ZWaveMultiInstanceCommandClass] - NODE 26: Endpoint 7 has invalid device class. generic = 0x3, specific = 0x1.
2019-08-02 18:43:32.605 [ERROR] [class.ZWaveMultiInstanceCommandClass] - NODE 26: Endpoint 8 has invalid device class. generic = 0x3, specific = 0x1.
2019-08-02 18:43:32.606 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Commands processed 1.
2019-08-02 18:43:32.606 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1b8d734.
2019-08-02 18:43:32.607 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1b8d734.
2019-08-02 18:43:32.607 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: notifyTransactionResponse TID:7920 DONE
2019-08-02 18:43:32.607 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

Those errors repeat every so often too, so I’m wondering if it’s trying and failing to do the same thing over and over again.

Does that seem like it would be something wrong with the device or communication? I have the device right next to the USB controller stick.

Is there anything else I should look for specifically in the log file that might hint at what is wrong?

Bruce_Osborne · August 2, 2019, 11:15pm

I am not an expert by any means. @chris , @sihui, and @5iver are the knowledge bases here.

sihui · August 3, 2019, 8:41am

Yes. I would try to factory reset the device and include it again.

acee · August 3, 2019, 6:40pm

I factory reset the device and added it again, and after some waiting the same thing started happening again.

I’m not 100% sure if the inclusion process is going as expected though. This is what I am observing:

Using PaperUI, I go to add a thing with the Z-Wave binding
I press the inclusion button on the Siren6
The Siren6’s LED sequence seems to indicate a successful pair (goes solid for 30 seconds then turns off).
No thing appears in the PaperUI inbox.
I restart openhab2 and in PaperUI, I go back to add a thing using the Z-Wave binding.
A new node appears in the inbox, which I add. It’s number matches the number of a node I saw in the debug logs during step 2-4 above.

The logs during this time look like (NODE 27 is the new one):

2019-08-03 14:16:19.071 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:c448fb80
2019-08-03 14:16:19.074 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
2019-08-03 14:16:19.086 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:c448fb80
2019-08-03 14:16:19.088 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
2019-08-03 14:16:19.099 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2019-08-03 14:16:19.102 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion
2019-08-03 14:16:19.110 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.
2019-08-03 14:16:19.116 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 16 to queue - size 1
2019-08-03 14:16:19.120 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-08-03 14:16:19.125 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 06 77 
2019-08-03 14:16:19.131 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 06 77 
2019-08-03 14:16:19.138 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-08-03 14:16:19.139 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-08-03 14:16:19.139 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-08-03 14:16:19.140 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-08-03 14:16:19.140 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-08-03 14:16:19.140 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-08-03 14:16:19.141 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 06 01 00 00 B5 
2019-08-03 14:16:19.142 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-08-03 14:16:19.144 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 16: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 6
2019-08-03 14:16:19.146 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=6, payload=06 01 00 00 
2019-08-03 14:16:19.149 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-08-03 14:16:19.150 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=6, payload=06 01 00 00 
2019-08-03 14:16:19.150 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 16: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 6
2019-08-03 14:16:19.150 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-08-03 14:16:19.151 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 16: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 6
2019-08-03 14:16:19.151 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 16: (Callback 6)
2019-08-03 14:16:19.151 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-08-03 14:16:19.151 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 16: callback 6
2019-08-03 14:16:19.152 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=6, payload=06 01 00 00 
2019-08-03 14:16:19.154 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
2019-08-03 14:16:19.174 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart
2019-08-03 14:16:19.179 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 16: Transaction COMPLETED
2019-08-03 14:16:19.183 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 39ms
2019-08-03 14:16:19.186 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 16: Transaction completed
2019-08-03 14:16:19.188 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:16 DONE
2019-08-03 14:16:19.196 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-08-03 14:16:19.197 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-08-03 14:16:21.161 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 10: Device discovery completed
2019-08-03 14:16:21.178 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 10: Device discovery resolved to thingType zwave:homeseer_hsds100_00_000
2019-08-03 14:16:21.194 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 15: Device discovery completed
2019-08-03 14:16:21.203 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 15: Device discovery resolved to thingType zwave:aeotec_zwa005_00_000
2019-08-03 14:16:25.444 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 06 02 00 00 B6 
2019-08-03 14:16:25.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=6, payload=06 02 00 00 
2019-08-03 14:16:25.449 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=6, payload=06 02 00 00 
2019-08-03 14:16:25.449 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-08-03 14:16:25.450 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2019-08-03 14:16:25.450 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2019-08-03 14:16:25.450 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=6, payload=06 02 00 00 
2019-08-03 14:16:25.451 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: New node found.
2019-08-03 14:16:25.451 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-08-03 14:16:25.452 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-08-03 14:16:25.684 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1B 00 4A 06 03 1B 14 04 03 01 5E 86 70 72 59 85 73 8E 60 5A 55 98 9F 6C 7A 71 79 2F 
2019-08-03 14:16:25.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=3, callback=6, payload=06 03 1B 14 04 03 01 5E 86 70 72 59 85 73 8E 60 5A 55 98 9F 6C 7A 71 79 
2019-08-03 14:16:25.692 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=3, callback=6, payload=06 03 1B 14 04 03 01 5E 86 70 72 59 85 73 8E 60 5A 55 98 9F 6C 7A 71 79 
2019-08-03 14:16:25.692 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-08-03 14:16:25.693 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2019-08-03 14:16:25.693 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2019-08-03 14:16:25.693 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=3, callback=6, payload=06 03 1B 14 04 03 01 5E 86 70 72 59 85 73 8E 60 5A 55 98 9F 6C 7A 71 79 
2019-08-03 14:16:25.694 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - NODE 27: Adding slave.
2019-08-03 14:16:25.694 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeStart, new event IncludeSlaveFound
2019-08-03 14:16:25.697 [DEBUG] [al.protocol.ZWaveInclusionController] - NODE 27: Including node.
2019-08-03 14:16:25.699 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-08-03 14:16:25.702 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-08-03 14:16:26.052 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 06 05 1B 00 AA 
2019-08-03 14:16:26.055 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=5, callback=6, payload=06 05 1B 00 
2019-08-03 14:16:26.056 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=5, callback=6, payload=06 05 1B 00 
2019-08-03 14:16:26.057 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-08-03 14:16:26.057 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2019-08-03 14:16:26.057 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2019-08-03 14:16:26.058 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=5, callback=6, payload=06 05 1B 00 
2019-08-03 14:16:26.058 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - NODE 27: Add Node: Protocol done.
2019-08-03 14:16:26.059 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSlaveFound, new event IncludeProtocolDone
2019-08-03 14:16:26.059 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2019-08-03 14:16:26.059 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 17 to queue - size 1
2019-08-03 14:16:26.060 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-08-03 14:16:26.068 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 07 B2 
2019-08-03 14:16:26.070 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 07 B2 
2019-08-03 14:16:26.072 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-08-03 14:16:26.074 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-08-03 14:16:26.074 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-08-03 14:16:26.075 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 17: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 7
2019-08-03 14:16:26.077 [DEBUG] [al.protocol.ZWaveInclusionController] - NODE 27: Inclusion protocol completed.
2019-08-03 14:16:26.125 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 07 06 1B 00 A8 
2019-08-03 14:16:26.128 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=7, payload=07 06 1B 00 
2019-08-03 14:16:31.076 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 17: Timeout at state WAIT_REQUEST. 3 retries remaining.
2019-08-03 14:16:31.079 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 17: Transaction is current transaction, so clearing!!!!!
2019-08-03 14:16:31.080 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 17: Transaction CANCELLED
2019-08-03 14:16:31.081 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:17 CANCELLED
2019-08-03 14:16:31.083 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-08-03 14:16:41.076 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion timer at IncludeProtocolDone
2019-08-03 14:16:41.080 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2019-08-03 14:16:41.084 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 18 to queue - size 1
2019-08-03 14:16:41.093 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-08-03 14:16:41.095 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 00 B5 
2019-08-03 14:16:41.096 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 00 B5 
2019-08-03 14:16:41.101 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-08-03 14:16:41.103 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 2<>126 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-08-03 14:16:41.103 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-08-03 14:16:41.105 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 18: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2019-08-03 14:16:41.106 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion
2019-08-03 14:16:41.107 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done
2019-08-03 14:16:46.106 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 18: Timeout at state WAIT_REQUEST. 3 retries remaining.
2019-08-03 14:16:46.107 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 18: Transaction is current transaction, so clearing!!!!!
2019-08-03 14:16:46.108 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 18: Transaction CANCELLED
2019-08-03 14:16:46.109 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:18 CANCELLED
2019-08-03 14:16:46.110 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-08-03 14:16:49.082 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:c448fb80
2019-08-03 14:16:49.085 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do

Aside from this, before the log goes crazy with the errors above, I also periodically see some messages related to node 27, sometimes with “Transaction not completed” messages.

For example

2019-08-03 14:42:11.207 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-08-03 14:42:11.207 [DEBUG] [andclass.impl.CommandClassSecurityV1] - Creating command message SECURITY_MESSAGE_ENCAPSULATION version 1
2019-08-03 14:42:11.209 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 27: SECURITY_TXD 98 02 
2019-08-03 14:42:11.213 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 1D 00 13 1B 16 98 81 D3 25 1E 64 9B C1 22 0F 6C 0D 5D 73 FB D1 2A EF E2 52 8E 44 25 0B EA 
2019-08-03 14:42:11.216 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 27: Sending REQUEST Message = 01 1D 00 13 1B 16 98 81 D3 25 1E 64 9B C1 22 0F 6C 0D 5D 73 FB D1 2A EF E2 52 8E 44 25 0B EA 
2019-08-03 14:42:11.218 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-08-03 14:42:11.219 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 22: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 11
2019-08-03 14:42:11.221 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-08-03 14:42:11.221 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-08-03 14:42:11.222 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-08-03 14:42:11.224 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 22: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 11
2019-08-03 14:42:11.225 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-08-03 14:42:11.227 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-08-03 14:42:11.228 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-08-03 14:42:11.228 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-08-03 14:42:11.229 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-08-03 14:42:11.230 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-08-03 14:42:11.230 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 22: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 11
2019-08-03 14:42:11.231 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-08-03 14:42:11.231 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 22: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 11
2019-08-03 14:42:11.231 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-08-03 14:42:11.232 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 27: sentData successfully placed on stack.
2019-08-03 14:42:11.232 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 22: Advanced to WAIT_REQUEST
2019-08-03 14:42:11.233 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 27: TID 22: Transaction not completed
2019-08-03 14:42:11.233 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-08-03 14:42:11.233 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-08-03 14:42:11.253 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 0B 00 00 03 E3 
2019-08-03 14:42:11.254 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=11, payload=0B 00 00 03 
2019-08-03 14:42:11.256 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=11, payload=0B 00 00 03 
2019-08-03 14:42:11.256 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 22: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 11
2019-08-03 14:42:11.257 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-08-03 14:42:11.258 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 22: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 11
2019-08-03 14:42:11.258 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 22: (Callback 11)
2019-08-03 14:42:11.259 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-08-03 14:42:11.260 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 22: callback 11
2019-08-03 14:42:11.262 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=11, payload=0B 00 00 03 
2019-08-03 14:42:11.263 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 27: SendData Request. CallBack ID = 11, Status = Transmission complete and ACK received(0)
2019-08-03 14:42:11.264 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 22: Advanced to WAIT_DATA
2019-08-03 14:42:11.265 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 27: TID 22: Transaction not completed
2019-08-03 14:42:11.265 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-08-03 14:42:11.266 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-08-03 14:42:16.265 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 27: TID 22: Timeout at state WAIT_DATA. 3 retries remaining.
2019-08-03 14:42:16.267 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 22: Transaction CANCELLED
2019-08-03 14:42:16.273 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 27: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-08-03 14:42:16.275 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 27: notifyTransactionResponse TID:22 CANCELLED
2019-08-03 14:42:16.276 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-08-03 14:42:16.277 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 22: Transaction event listener: DONE: CANCELLED -> 
2019-08-03 14:42:16.278 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 27: Node Init response (4) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@43ff14
2019-08-03 14:42:16.279 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 27: No data from device, but it was ACK'd. Possibly not supported? (Try 4)

Overall, it seems like something is not working right with my openhab2 instance given that I have to restart openhab before the node appears in the inbox.

Is the Z-Wave inclusion process really sensitive to CPU processing power on the controller by any chance? I am testing this on a very old CPU (1.6 GHz single core Pentium M 725). I may try to load up a VM and a fresh install of openhab2 on a more modern machine later to see if that makes any difference.

Bruce_Osborne · August 3, 2019, 7:13pm

It is generally recommended to use HABmin for including zwave devices but I have used PaperUI too.

acee · August 3, 2019, 7:25pm

Thanks, I’m still pretty new to openhab. I will try HABmin next.

I spun up an entirely new instance of openhab2 on a VM on a modern Core i7 laptop and the issue is the same - for some reason the node does not show up in the inbox until I restart openhab, and after restarting openhab those same invalid device class errors start appearing and repeating themselves.

About the log message:

NODE 28: Endpoint 1 has invalid device class. generic = 0x3, specific = 0x1.

I’m not an expert in Z-Wave, but I notice that in the spec document for the Siren6, the endpoint capabilities for multichannel are listed as (page 16):

Generic: GENERIC_TYPE_AV_CONTROL_POINT
Specific: SPECIFIC_TYPE_SOUND_SWITCH

And in this file I found on github: https://github.com/Z-WavePublic/libzwaveip/blob/master/config/ZWave_custom_cmd_classes.xml

GENERIC_TYPE_AV_CONTROL_POINT = 0x03
SPECIFIC_TYPE_SOUND_SWITCH = 0x01

This seems to correspond to the contents of the log message. Why is this being considered invalid if it appears to be part of the spec? Is it that the values are valid but just not expected at this time, or that the Siren6 is using something classes in the Z-Wave spec that are not the stable version of openhab yet? (I apologize in advance for any imprecision or inaccuracies in what I’m asking, as I really don’t know a whole lot about the details of Z-Wave beyond including and excluding devices).

Thanks again for everyone’s help so far.

Bruce_Osborne · August 3, 2019, 9:01pm

Here are Chris’s recommended steps. He wrote the binding.

https://www.cd-jackson.com/index.php/openhab/habmin/10-habmin-zwave-binding-initialisation

acee · August 3, 2019, 10:58pm

Thanks for the suggestion about HABmin, it’s a bit easier to access some of the Z-Wave binding features there.

Unfortunately, it seems the issue is the same when I try to use HABmin (even after factory resetting both the Z-Stick and the Siren6) - when I do the inclusion, the Siren6 LED sequence for successful inclusion happens but no new things appear in HABmin until I restart openhab. Then the new thing will appear and the error log messages start happening.

I was worried maybe my Z-Stick is not working properly, so I tried adding back a couple other Z-Wave devices that were working before, a Homeseer door/window sensor and an Aeotec motion/temperature/light sensor. Both those added back without any issue and appeared in as available new things in HABmin right away (no need to restart openhab).

Bruce_Osborne · August 3, 2019, 11:19pm

OK
Sorry, @chris has been away traveling on business.
Perhaps @sihui or @5iver have ideas.

5iver · August 4, 2019, 1:21am

Which OH version and zwave binding version, if different?

acee · August 4, 2019, 1:39pm

Both my openhab and Z-Wave binding versions are 2.4.0 (they are the latest stable version installed with the openhabian installer).