OH2 Z-Wave refactoring and testing... and SECURITY

5iver · October 6, 2017, 6:37pm

My minimote looks like this in Habmin:

But wakeups are not moving it along. Shouldn’t initialization complete after it is woken up? There are a couple of mains powered and frequently listening (lock) devices that I would expect to have initialized quickly after a restart, but are in this same state. Maybe it is related to the error above, or is this (-- To notify -- TIMEOUT_WAITING_FOR_DATA) because of the controller being too busy to process things? I have been replacing zigbee bulbs with zwave dimmers and restarted a few times recently, but I see this after every restart. It just seems like there is something hung up somewhere. It’ll take half a day for the zwave binding to calm down after a restart, and until then everything is very slow to respond.

2017-Oct-06 14:22:38.913 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2017-Oct-06 14:22:39.025 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2017-Oct-06 14:22:39.025 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2017-Oct-06 14:22:39.041 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2017-Oct-06 14:22:39.041 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2017-Oct-06 14:22:50.319 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:REQUEST_NIF)
2017-Oct-06 14:22:50.320 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_WAKE_UP, endpoint 0
2017-Oct-06 14:22:50.320 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported
2017-Oct-06 14:22:50.320 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_WAKE_UP V0 WAKE_UP_NOTIFICATION
2017-Oct-06 14:22:50.321 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: Is awake with 1 messages in the queue
2017-Oct-06 14:22:50.321 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: Creating WakeupTimerTask
2017-Oct-06 14:22:50.321 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: Creating WakeupTimerTask
2017-Oct-06 14:22:50.322 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2017-Oct-06 14:22:50.322 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - NODE 2: Node Status event - Node is AWAKE
2017-Oct-06 14:22:50.323 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
2017-Oct-06 14:22:50.323 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@71de1ce3.
2017-Oct-06 14:22:50.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Checking transaction 1836  null.
2017-Oct-06 14:22:50.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Checking transaction : state >> ABORTED
2017-Oct-06 14:22:50.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Checking transaction : node  >> 83
2017-Oct-06 14:22:50.325 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Checking transaction : class >> 132 == null.
2017-Oct-06 14:22:50.325 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Checking transaction : commd >> 7 == 0.
2017-Oct-06 14:22:50.325 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Ignoring transaction since not waiting for data.
2017-Oct-06 14:23:00.322 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == true
2017-Oct-06 14:23:00.322 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2017-Oct-06 14:23:08.533 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == true
2017-Oct-06 14:23:08.562 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: TID 1598: Transaction not completed
2017-Oct-06 14:23:10.322 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == true
2017-Oct-06 14:23:10.323 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2017-Oct-06 14:23:20.322 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == true
2017-Oct-06 14:23:20.322 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2017-Oct-06 14:23:30.322 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == true
2017-Oct-06 14:23:30.322 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2017-Oct-06 14:23:33.562 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 2: TID 1598: Timeout at state WAIT_DATA. 3 retries remaining.
2017-Oct-06 14:23:33.563 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-Oct-06 14:23:33.563 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:1598 CANCELLED
2017-Oct-06 14:23:33.565 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: -- To notify -- TIMEOUT_WAITING_FOR_DATA
2017-Oct-06 14:23:33.566 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Init response (4) TIMEOUT_WAITING_FOR_DATA
2017-Oct-06 14:23:33.566 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 2: No data from device, but it was ACK'd. Possibly not supported? (Try 4)
2017-Oct-06 14:23:40.322 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == true
2017-Oct-06 14:23:40.322 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: WakeupTimerTask 0 Messages waiting, state REQUEST_NIF
2017-Oct-06 14:23:40.322 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: WakeupTimerTask First iteration
2017-Oct-06 14:23:50.322 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == true
2017-Oct-06 14:23:50.323 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: WakeupTimerTask 0 Messages waiting, state REQUEST_NIF
2017-Oct-06 14:23:50.323 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: No more messages, go back to sleep
2017-Oct-06 14:23:50.323 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 2: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION
2017-Oct-06 14:23:50.323 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, endpoint 0
2017-Oct-06 14:23:50.323 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported
2017-Oct-06 14:23:50.323 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_WAKE_UP is NOT required to be secured
2017-Oct-06 14:23:50.323 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@1f1bffeb
2017-Oct-06 14:23:50.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue
2017-Oct-06 14:23:50.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Added to queue - size 17
2017-Oct-06 14:24:10.219 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == true
2017-Oct-06 14:24:10.220 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 09 00 13 02 02 84 08 25 50 1C
2017-Oct-06 14:24:10.230 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 2: sentData successfully placed on stack.
2017-Oct-06 14:24:10.231 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: TID 1843: Transaction not completed
2017-Oct-06 14:24:10.352 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 80, Status = Transmission complete, no ACK received(1)
2017-Oct-06 14:24:10.353 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 2: WAKE_UP_NO_MORE_INFORMATION. Treated as ACK.
2017-Oct-06 14:24:10.354 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Response processed after 131ms
2017-Oct-06 14:24:10.354 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: TID 1843: Transaction completed
2017-Oct-06 14:24:10.355 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:1843 DONE
2017-Oct-06 14:24:10.355 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-Oct-06 14:24:10.366 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: -- To notify -- COMPLETE
2017-Oct-06 14:24:10.367 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: Went to sleep COMPLETE
2017-Oct-06 14:24:15.043 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@7cf4186d
2017-Oct-06 14:24:15.044 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue
2017-Oct-06 14:24:15.044 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Added to queue - size 17
2017-Oct-06 14:24:16.385 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2017-Oct-06 14:24:16.385 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2017-Oct-06 14:25:15.600 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2017-Oct-06 14:25:15.600 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2017-Oct-06 14:25:20.616 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2017-Oct-06 14:25:20.616 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2017-Oct-06 14:25:20.638 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2017-Oct-06 14:25:20.638 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2017-Oct-06 14:25:20.658 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false

5iver · October 7, 2017, 2:39am

I think I may be experiencing what @stevenazari has reported. I am getting these when saving a device change in Habmin. This occurred when when trying to change the Association, because they had all come up like this (they were newly added). Previously added devices of the same type (VRMX1-1LZ) do not throw this error when modifying the Association. I also had to readd a BE469 today and it receives the error too.

2017-Oct-06 20:07:21.958 [ERROR] [marthome.io.rest.core.internal.thing.ThingResource] - Exception during HTTP PUT request for update config at 'things/zwave:device:07cb40a2:node8/config' for thing 'zwave:device:07cb40a2:node8': null
2017-Oct-06 20:07:35.097 [ERROR] [marthome.io.rest.core.internal.thing.ThingResource] - Exception during HTTP PUT request for update config at 'things/zwave:device:07cb40a2:node9/config' for thing 'zwave:device:07cb40a2:node9': null
2017-Oct-06 20:07:46.824 [ERROR] [marthome.io.rest.core.internal.thing.ThingResource] - Exception during HTTP PUT request for update config at 'things/zwave:device:07cb40a2:node11/config' for thing 'zwave:device:07cb40a2:node11': null
2017-Oct-06 20:08:00.760 [ERROR] [marthome.io.rest.core.internal.thing.ThingResource] - Exception during HTTP PUT request for update config at 'things/zwave:device:07cb40a2:node12/config' for thing 'zwave:device:07cb40a2:node12': null
2017-Oct-06 20:08:11.273 [ERROR] [marthome.io.rest.core.internal.thing.ThingResource] - Exception during HTTP PUT request for update config at 'things/zwave:device:07cb40a2:node13/config' for thing 'zwave:device:07cb40a2:node13': null
2017-Oct-06 20:08:22.534 [ERROR] [marthome.io.rest.core.internal.thing.ThingResource] - Exception during HTTP PUT request for update config at 'things/zwave:device:07cb40a2:node14/config' for thing 'zwave:device:07cb40a2:node14': null
2017-Oct-06 20:08:35.885 [ERROR] [marthome.io.rest.core.internal.thing.ThingResource] - Exception during HTTP PUT request for update config at 'things/zwave:device:07cb40a2:node16/config' for thing 'zwave:device:07cb40a2:node16': null

The log shows this, but nothing further and no errors:

2017-Oct-06 22:47:08.268 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Configuration update received
2017-Oct-06 22:47:08.269 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Configuration update group_1 to [node_1_0]

I am also seeing this when trying to heal a specific device type, the DZMX1-1LZ:

mstormi · October 7, 2017, 7:27am

Happily running this one so far.
Just one minor thing, the exception below happens when a device of mine sends a bad payload.
You had already removed that message in some older version of your binding, please adjust that again (or lower its priority) - thanks.

2017-10-07 09:20:19.431 [ERROR] [nal.protocol.ZWaveTransactionManager] - Exception processing frame:
java.lang.ArrayIndexOutOfBoundsException: 3
        at org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload.getPayloadByte(ZWaveCommandClassPayload.java:49) [11:org.openhab.binding.zwave:2.2.0.201710012213]
        at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiInstanceCommandClass.getSourceEndpoint(ZWaveMultiInstanceCommandClass.java:381) [11:org.openhab.binding.zwave:2.2.0.201710012213]
        at org.openhab.binding.zwave.internal.protocol.ZWaveNode.processCommand(ZWaveNode.java:1205) [11:org.openhab.binding.zwave:2.2.0.201710012213]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveReceiveThread.run(ZWaveTransactionManager.java:421) [11:org.openhab.binding.zwave:2.2.0.201710012213]

chris · October 7, 2017, 11:44am

This exception is a catch-all for any corrupted frames that are handled. So, I don’t change the logging here, but I want to try and fix the processing of the corrupted frame. Can you see if you can get a debug file showing the messages received just before this exception.

Thanks

chris · October 7, 2017, 11:47am

The hassle here is that (I think) the REST server is probably eating the exception, and just passing the 404 (or 500, or whatever) error to the REST response, so we don’t actually have any log of what is causing the underlying problem .

I’ll see if I can find a way to improve the ESH logging here so we can see what’s happening.

chris · October 7, 2017, 11:51am

I guess you filtered this log? The WAKEUP is being received, and it says there’s 1 message in the queue when it wakes up. I then see a timeout, so I’m guessing that this message gets sent but is filtered out of your log? The device doesn’t respond to this message, so it doesn’t progress.

This looks ‘ok’ - by which I mean what the binding is doing appears fine from this log. Maybe you can check that my assumption about the data being sent is correct?

5iver · October 7, 2017, 3:23pm

Yes… and I fell asleep with debug on, so it’s long gone. I’ll restart and investigate further. The minimote was an example. Every device, even powered devices, go through this. It can take 6+ hours for things to settle down and the network is responsive again. This seems much longer than in the past, but not necessarily new to this build. In my dreams, there’s a toggle to switch off the initialization at startup.

I had adjusted my logging, but couldn’t find anything that gave more details. In case this helps, the newly added devices that get the error have (explaining the first image in my previous post)

      "group_1": [
        "node_1"
      ],

in the Thing jsondb, where the older devices that do not get the error have

      "group_1": [
        "node_1_0"
      ],

chris · October 7, 2017, 4:00pm

That definitely shouldn’t happen - powered devices shouldn’t have anything to do with the wakeup request for starters . I certainly don’t see that here - the initialisation is normally pretty quick for powered devices and they don’t wait for a wakeup. I would like to see the logs for a powered device as well then please.

Nothing has changed in the initialisation for a long time. The changes I made to the associations recently are much later in init process than this. (I think this is probably the very first step that you’re seeing issues with).

stevenazari · October 7, 2017, 9:21pm

Hi Chris,
Not sure if it’s an expected action or not, but when saving configuration, openhab resets, I’m guessing this is so the configuration is updated? Does it need to reset the whole service? seems a bit odd to take down the whole application for 1 binding…? Is there no way to avoid this?

chris · October 7, 2017, 10:03pm

If you mean that the whole system restarts, then no, this shouldn’t happen.

stevenazari · October 7, 2017, 10:39pm

The plot thickens! I’ll Look at getting a more detailed bug report tomorrow

mstormi · October 8, 2017, 11:15am

Here’s one. I think you already analysed this once, IIRC it was announcing to have a different number of fields than it actually had.

2017-10-08 13:08:50.961 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-10-08 13:08:50.966 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=42, callback=0, payload=00 2A 07 56 01 30 03 00 CF 3B
2017-10-08 13:08:50.969 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=42, callback=0, payload=00 2A 07 56 01 30 03 00 CF 3B
2017-10-08 13:08:50.972 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=42, callback=0, payload=00 2A 07 56 01 30 03 00 CF 3B
2017-10-08 13:08:50.974 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2017-10-08 13:08:50.976 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Application Command Request (ALIVE:IDENTIFY_NODE)
2017-10-08 13:08:50.978 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Decapsulating COMMAND_CLASS_CRC_16_ENCAP
2017-10-08 13:08:50.979 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Incoming command class COMMAND_CLASS_SENSOR_BINARY, endpoint 0
2017-10-08 13:08:50.981 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: SECURITY not supported
2017-10-08 13:08:50.997 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Received COMMAND_CLASS_SENSOR_BINARY V1 SENSOR_BINARY_REPORT
2017-10-08 13:08:51.028 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 2A 03 60 0D 01 B7
2017-10-08 13:08:51.032 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-10-08 13:08:50.999 [DEBUG] [dclass.ZWaveBinarySensorCommandClass] - NODE 42: Sensor Binary report, type=Unknown, value=0
2017-10-08 13:08:51.036 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=42, callback=0, payload=00 2A 03 60 0D 01
2017-10-08 13:08:51.045 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveBinarySensorValueEvent
2017-10-08 13:08:51.046 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=42, callback=0, payload=00 2A 03 60 0D 01
2017-10-08 13:08:51.053 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Got an event from Z-Wave network: ZWaveBinarySensorValueEvent
2017-10-08 13:08:51.058 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SENSOR_BINARY, value = 0
2017-10-08 13:08:51.064 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Updating channel state zwave:device:ddd23e6c:node42:alarm_motion to OFF [OnOffType]
2017-10-08 13:08:51.072 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Commands processed 1.
2017-10-08 13:08:51.074 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@6296f9.
2017-10-08 13:08:51.076 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Checking transaction 497  ApplicationCommandHandler.
2017-10-08 13:08:51.078 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Checking transaction : state >> WAIT_DATA
2017-10-08 13:08:51.080 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Checking transaction : node  >> 2
2017-10-08 13:08:51.081 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Checking transaction : class >> 48 == 50.
2017-10-08 13:08:51.083 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Checking transaction : commd >> 3 == 2.
2017-10-08 13:08:51.085 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Command NOT verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@6296f9.
2017-10-08 13:08:51.086 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2017-10-08 13:08:51.088 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2017-10-08 13:08:51.090 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=42, callback=0, payload=00 2A 03 60 0D 01
2017-10-08 13:08:51.092 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2017-10-08 13:08:51.094 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Application Command Request (ALIVE:IDENTIFY_NODE)
2017-10-08 13:08:51.111 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2017-10-08 13:08:51.122 [ERROR] [nal.protocol.ZWaveTransactionManager] - Exception processing frame: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=42, callback=0, payload=00 2A 03 60 0D 01
2017-10-08 13:08:51.124 [ERROR] [nal.protocol.ZWaveTransactionManager] - Exception processing frame:
java.lang.ArrayIndexOutOfBoundsException: 3
        at org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload.getPayloadByte(ZWaveCommandClassPayload.java:49) [11:org.openhab.binding.zwave:2.2.0.201710012213]
        at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiInstanceCommandClass.getSourceEndpoint(ZWaveMultiInstanceCommandClass.java:381) [11:org.openhab.binding.zwave:2.2.0.201710012213]
        at org.openhab.binding.zwave.internal.protocol.ZWaveNode.processCommand(ZWaveNode.java:1205) [11:org.openhab.binding.zwave:2.2.0.201710012213]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveReceiveThread.run(ZWaveTransactionManager.java:421) [11:org.openhab.binding.zwave:2.2.0.201710012213]
2017-10-08 13:08:51.130 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

chris · October 8, 2017, 11:26am

This one here is a corrupted multi-channel frame - it has no data in it at all from the looks of it.

chris · October 8, 2017, 12:01pm

For reference -:

Baumstange · October 8, 2017, 3:50pm

Hi there,

today I switched my zwave binding to this one including security. Everything worked quite smoothly from excluding standard binding and acting the new one, deleting and adding wave device.

The only problem I encountered is that I can not define the association group “lifeline”. Overtime I try to do this across all my devices I get the following error and the selection is not stored

17:42:06.550 [ERROR] [ome.io.rest.core.thing.ThingResource] - Exception during HTTP PUT request for update config at 'things/zwave:device:15efc367451:node2/config' for thing 'zwave:device:15efc367451:node2': null

224 | Active   |  80 | 2.2.0.201710012213     | ZWave Binding

Any clue why I can not save the association group?
Thanks for support.

5iver · October 8, 2017, 4:06pm

This has been reported by a couple of us…

chris · October 8, 2017, 4:25pm

In theory, with the latest binding the lifeline should always be set automatically by the binding for ZWave+ devices (and given lifeline is a ZW+ concept, that should be all of them).

shorin · October 8, 2017, 9:23pm

OK, Chris, I’m needing some help too…

Currently using a couple Veras for my Zwave, and I’d like to move to a Z stick with just openHAB. I’ve been running this way for a couple years, but the Vera is getting flakey again and it appears that the openHAB zwave binding is mature enough now, so I figured I’d give it a try.

I put an Aeon Zstick into my openHAB box, and I can see the device as /dev/ttyACM0

[    0.000000] console [tty0] enabled
[    5.288057] tty tty7: hash matches
[   19.210283] cdc_acm 4-1:1.0: ttyACM0: USB ACM device

Downloaded the jar and put it into the addons folder, and started openHAB back up. I’m seeing this in the log:

2017-10-08 15:28:31.430 [WARN ] [org.openhab.binding.zwave           ] - FrameworkEvent WARNING - org.openhab.binding.zwave
org.osgi.framework.ServiceException: org.apache.felix.scr.impl.manager.SingleComponentManager.getService() returned a null service object
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:232)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:496)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:619)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.apache.felix.scr.impl.manager.SingleRefPair.getServiceObject(SingleRefPair.java:72)
	at org.apache.felix.scr.impl.inject.BindMethod.getServiceObject(BindMethod.java:648)
	at org.apache.felix.scr.impl.manager.DependencyManager.getServiceObject(DependencyManager.java:2201)
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.prebind(DependencyManager.java:403)
	at org.apache.felix.scr.impl.manager.DependencyManager.prebind(DependencyManager.java:1520)
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.collectDependencies(AbstractComponentManager.java:1005)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:859)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:823)[32:org.apache.felix.scr:2.0.6]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at java.security.AccessController.doPrivileged(Native Method)[:1.8.0_101]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:496)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:619)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.smarthome.core.common.registry.AbstractRegistry$ProviderTracker.addingService(AbstractRegistry.java:105)[98:org.eclipse.smarthome.core:0.9.0.b4]
	at org.eclipse.smarthome.core.common.registry.AbstractRegistry$ProviderTracker.addingService(AbstractRegistry.java:1)[98:org.eclipse.smarthome.core:0.9.0.b4]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:901)[org.osgi.core-6.0.0.jar:]
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:914)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:886)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:873)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:132)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:940)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:740)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:674)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:429)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:657)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:341)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:403)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.Activator.access$200(Activator.java:54)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:278)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.utils.extender.AbstractExtender.createExtension(AbstractExtender.java:259)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.utils.extender.AbstractExtender.modifiedBundle(AbstractExtender.java:232)[32:org.apache.felix.scr:2.0.6]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444)[org.osgi.core-6.0.0.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.Module.publishEvent(Module.java:466)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.Module.start(Module.java:457)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1582)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1562)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1533)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1476)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]

In the console, here’s the version:

209 | Resolved |  80 | 2.1.0.201709182108    | ZWave Binding

In HABmin, the Z-wave thing just has a question mark, so something’s definitely not right…
So I stopped openHAB and removed the jar (and uninstalled the bundle through the console). Then, through PaperUI, I installed the 2.0 version of the binding.

210 | Active   |  80 | 2.0.0                 | ZWave Binding

Set up the Thing with the port address above (/dev/ACM0), and I’m getting a red X in HABmin on the thing, with the message at the bottom:

Serial Error: Port /dev/ttyACM0 does not exist

I’ve enabled debug logging for zwave and this is all I see in the logs now:

2017-10-08 15:56:15.813 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2017-10-08 15:56:15.813 [ERROR] [ing.zwave.handler.ZWaveSerialHandler] - ZWave port is not set.
2017-10-08 15:56:27.492 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update received
2017-10-08 15:56:27.504 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update port to /dev/ttyACM0
2017-10-08 15:56:27.511 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2017-10-08 15:56:27.512 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2017-10-08 15:56:27.512 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller.
2017-10-08 15:56:27.519 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'

Events:

2017-10-08 15:56:27.519 [ThingUpdatedEvent         ] - Thing 'zwave:serial_zstick:15efdc62998' has been updated.
2017-10-08 15:56:27.520 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:15efdc62998' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2017-10-08 15:56:27.555 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:15efdc62998' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to OFFLINE (COMMUNICATION_ERROR): Serial Error: Port /dev/ttyACM0 does not exist

I’m definitely not a Linux or openHAB expert, and am stuck. I don’t see what I’m doing wrong, or if there’s a bug somehow related to my system…

Thoughts?

Plan is to test the latest version if I can actually get something running…

Thanks,

Danny

5iver · October 8, 2017, 10:02pm

What version of OH are you running? Have you done this setup?

http://docs.openhab.org/installation/linux.html#privileges-for-common-peripherals

Look for your stick on another port… it may have changed ports. You could check for changes with a dmesg |grep tty, or just check to see what is in ls -la /dev |grep tty. If it’s moved, you may want to look into UDEV rules. There are several posts that can be found on the forum, but here is the info from the documentation::

http://docs.openhab.org/addons/bindings/serial1/readme.html#linux-users

stevenazari · October 8, 2017, 10:09pm

As this gent pointed out, check tty as it keeps switching for some reason!

Also ensure you only have 1 z wave bundle in list.

I had to use ttyACM1 But every now and then have to switch back to 0.

Also ensure openhab user has access to the port you are using… There’s a few hurdles to punch through for sure but we’ll get there