HABmin2, no zwave option and trouble connecting to the controller

I recently upgraded to the latest OH2 snapshot. I installed the zwave 2.0 binding from paper UI and the serial binding. I downloaded org.openhab.ui.habmin_2.0.0.SNAPSHOT-0.1.3.jar and placed it in the add-ons folder. habmin seems to have started up fine, but I see no options for dealing with the zwave network. How do I get it to allow me to configure my nodes?

I also seem to have some problem with getting it to recognise my nodes. The zwave binding connects to the controller without issue and starts checking the system. However, it seems that everything times out and no node configuration XML files are generated. This worked using an earlier OH2 snapshot and zwave binding, so I do not think the issue is with my hardware.

My zwave log contains a Lot of this:

NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
09:52:30.617 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.
09:52:35.614 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message.     Requeueing - 0 attempts left!
09:52:35.619 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to     error.
09:52:40.617 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Too many retries. Discarding     message: Message: class=RequestNodeInfo[0x60], type=Request[0x00], priority=High, dest=255, payload=24
09:52:40.626 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 6: Sent Data was not placed on stack     due to error 0.
09:52:45.625 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 6: Timeout while sending message.     Requeueing - 0 attempts left!
09:52:45.625 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 6: Got an error while sending data.     Resending message.
09:52:45.630 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 6: Sent Data was not placed on stack     due to error 0.
09:52:50.628 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 6: Too many retries. Discarding     message: Message: class=SendData[0x13], type=Request[0x00], priority=Poll, dest=6, payload=06 01 00
09:52:50.632 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 28: Sent Data was not placed on stack     due to error 0.
09:52:55.631 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 28: Too many retries. Discarding     message: Message: class=SendData[0x13], type=Request[0x00], priority=Poll, dest=28, payload=1C 01 00
09:52:55.635 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 21: Sent Data was not placed on stack     due to error 0.
09:53:00.634 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 21: Timeout while sending message.     Requeueing - 0 attempts left!
09:53:00.634 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 21: Got an error while sending data.     Resending message.
09:53:00.638 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 21: Sent Data was not placed on stack             due to error 0.

There also seems to be some problems with having multiple serial devices connected still, it tries to use the wrong lock file. However, this seems only to happen when the configurations is reloaded. Upon initial start it appears that it can connect to the controller, at least I get a list of nodes printed in the debug log. The following log illustrates the problem, but with the 1.9 version of the binding.

10:07:37.281 [INFO ] [ve.internal.protocol.ZWaveController] - Disconnected from serial port
10:07:37.281 [INFO ] [ve.internal.protocol.ZWaveController] - Stopped Z-Wave controller
10:07:37.281 [INFO ] [ve.internal.protocol.ZWaveController] - Starting Z-Wave controller
10:07:37.282 [INFO ] [ve.internal.protocol.ZWaveController] - Z-Wave timeout is set to 5000ms. Soft reset is false.
10:07:37.282 [INFO ] [ve.internal.protocol.ZWaveController] - Connecting to serial port /dev/ttyACM0
RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..mysensorsUSB: File exists. It is mine

 '�U testRead() Lock file failed
10:07:37.282 [ERROR] [ve.internal.protocol.ZWaveController] - Serial Error: Port /dev/ttyACM0 does not exist
10:07:37.283 [ERROR] [org.apache.felix.configadmin        ] - [org.osgi.service.event.EventHandler,     org.osgi.service.cm.ManagedService, id=305, bundle=176/mvn:org.openhab.binding/org.openhab.binding.zwave/1.9.0-    SNAPSHOT]: Updating property port of configuration org.openhab.zwave caused a problem: Port /dev/ttyACM0 does     not exist
org.osgi.service.cm.ConfigurationException: port : Port /dev/ttyACM0 does not exist

This is all done through the thing configuration.

This is a problem with the serial library - there’s nothing we can do about it until the library is updated.

I know we discussed this earlier, but who do I push/help to get this done? The issue because you linked to last time appeared not to be related according to the comments I got. I think the some updated versions of the library, but it has apparently not been included in the OH2 release, yet.

If you don’t think the open issues answer your problem, then you should open a new issue on the nrjavaserial repository.

I’ve not seen an update to the library, but if you think there’s already a fix for this, then it would be good to create a PR to get the updated serial library.

There might be something here: https://github.com/mnlipp/nrjavaserial/releases

I’m going to test it, at least, and see.

That didn’t seem to help me much. Anyway, I did a clean installation of the latest snapshot, only enabling the Zwave binding and setting the appropriate serial port in the setenv file. I still have the same problems as before. It seems to be able to connect to the controller, but all the nodes appear to time out. I still get a single node1.xml file, but nothing for the remaining nodes.

It is a bit difficult to tell the cosmonaut sure what is logged in the basic log tail when running with start_debug.sh. I tried to find the logback.xml that I remember from earlier versions of OH2 to move the zwave log to a separate file, but how this works appears to have changed.

I included my log file here: http://pastebin.com/QJnr0b9h

Without debug, it’s not too useful…

To enable debug, you need to log on to the Karaf console and type -:

log:set debug org.openhab.binding.zwave

Just figured that out, here is with debug:

http://pastebin.com/32Wexr2i

Let me know if you need me to run it with debug from the beginning.

What about inclusion, exclusion, node parameters et cetera? I see no options for this under “things” in the habmin configuration heading.

http://www.cd-jackson.com/index.php/openhab/habmin

I see. I have the devices in the inbox in habmin (and in paper ui), and I can add them. However they are all listed as unknown devices with a node ID. And I have no corresponding XML files in userdata/zwave, only for node1.xml.

What are the devices? Are they battery devices or mains?

They are a mix. I have around 18 mains devices and six battery operated wall controllers.

Hmmm - it’s strange that none of them are initialising. Do you have any idea what the problems is? Are they showing as being in the database?

They are definitely in the database. I tried the same procedure a few months ago when you initially released the 2.0 binding, and even added a device to the database which was not recognised. All my devices were then correctly recognised. I see no reason why it shouldn’t work since it is definitely working with an alpha version of OH2 with version 1.8 of your binding.

The binding seems to have calmed down a bit, but it still seems kind of busy. A random excerpt from the log:

22:42:06.969 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 10 04 02 84     07 66
22:42:06.971 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
22:42:06.971 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 10 04 02     84 07 66
22:42:06.971 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 10 04 02 84 07 66
22:42:06.971 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04],     type=Request[0x00], priority=High, dest=255, payload=10 04 02 84 07
22:42:06.971 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 4: Application Command Request     (ALIVE:PING)
22:42:06.971 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 4: Incoming command class     WAKE_UP
22:42:06.971 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 4: Received Wake Up Request
22:42:06.971 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 4: Received     WAKE_UP_NOTIFICATION
22:42:06.972 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 4: Is awake with 2 messages in the     wake-up queue.
22:42:06.972 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveWakeUpEvent
22:42:06.972 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 4: Wakeup during initialisation.
22:42:06.972 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 4: Node advancer - PING: queue length(1),     free to send(false)
22:42:06.972 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 4: Node advancer - queued packet. Queue     length is 1
22:42:06.972 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
22:42:06.972 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
22:42:06.972 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 255: Transaction not completed: node     address inconsistent.  lastSent=255, incoming=255
22:42:06.972 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue     length = 1
22:42:06.972 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 04 01 00     25 C6 02
22:42:06.972 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 4: Sending REQUEST Message = 01 08 00     13 04 01 00 25 C6 02
22:42:06.975 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 00 E9
22:42:06.976 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
22:42:06.976 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 00 E9
22:42:06.976 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 00 E9
22:42:06.976 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13],     type=Response[0x01], priority=High, dest=255, payload=00
22:42:06.976 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 4: Sent Data was not placed on stack     due to error 0.
22:42:07.144 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 10 04 02 84     07 66
22:42:07.145 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
22:42:07.145 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 10 04 02     84 07 66
22:42:07.145 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 10 04 02 84 07 66
22:42:07.145 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04],     type=Request[0x00], priority=High, dest=255, payload=10 04 02 84 07
22:42:07.145 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 4: Application Command Request     (ALIVE:PING)
22:42:07.145 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 4: Incoming command class     WAKE_UP
22:42:07.146 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 4: Received Wake Up Request
22:42:07.146 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 4: Received     WAKE_UP_NOTIFICATION
22:42:07.146 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 4: Is awake with 1 messages in the     wake-up queue.
22:42:07.146 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveWakeUpEvent
22:42:07.146 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 4: Wakeup during initialisation.
22:42:07.146 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 4: Node advancer - PING: queue length(1),     free to send(false)
22:42:07.146 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 4: Node advancer - queued packet. Queue     length is 1
22:42:07.146 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
22:42:07.146 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 3. Queue={}
22:42:11.973 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA
22:42:11.973 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 4: Sending ABORT Message = 01 03 00     16 EA
22:42:11.973 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA
22:42:11.974 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03     00 16 EA

What hardware are you using to run OH on?

Something looks strange with the formatting of the log, so maybe there’s something wierd going on with your system?

It is an Ubuntu installation running on an old server, i.e. a regular PC. What is weird with the formatting? If you’re referring to some weird spaces that is me adding four spaces at the beginning of each line to get the log formatted for the forum, and some of the log lines span multiple lines so we get spaces in the middle of the line.

Ok, I’m not sure what’s up then. Everything looks ok other than the error that the stick hasn’t accepted the command, but I don’t know why that is…

I do not understand what is happening, either. I plugged out and in the controller between shutting down my working version and beating up the latest version, and suddenly things seem to be happening. At least it has started generating XML files. I still get a lot of these in the log file, though.

 NODE 255: Timeout while sending message. Requeueing - 0 attempts left!

Do you know what this is? Is it some kind of broadcast address?