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

Looks like the DB already has an entry for the alarm_raw channel

In Paper UI or HABmin, you should see this channel, and you should be able to link it to an item.

Then you should be able to write a rule that triggers when that item’s state changes.

And if not, you probably need to delete and rediscover the Thing to pull in an updated definition.

I can always count on you to catch this. LOL

1 Like

I had a similar issue with my kwiset 910. What i noticed was happening in the logs was that the alarm raw command was getting set then reverting to zero for some reason. I just wrote a rule with a dummy item that has tracks the alarm raw state but ignores the zero state.

@chris, I was holding up until I got a response from you on this, but I saw @mhilbush updated the VRMX1. Are you still processing or did I sneak this one past you?

Thanks, I can see the new channel now and have started working on a rule.

@volfan6415 would you mind posting your rule? I expect I will run into the same zero state issue

This isn’t for ALARM V1, but should be adaptable. I think there are some other examples in the forum for V1 too.

Not knowing where this would land, I thought I would add the VRMX1 and RZP03 just to be safe. In my logs, I saw those two devices were sending APP STATUS messages.

I haven’t reverted this change as yet, but I think I will do so… Either way, I did see your comment :slight_smile:

1 Like

Here is my rule:

rule "front lock state"
	when
		Item Front_Door_Alarm_Actual received update
	
	then
if (Front_Door_Alarm_Actual.state == 0){
logDebug("Alarm.rules","The alarm code was zero so we are ignoring it")
}
else{
Front_Door_Alarm.postUpdate(Front_Door_Alarm_Actual.state)
}
	end

The latest version should revert this change.

This is of course also no problem…

1 Like

I’ve updated the binding today with this version:

235 │ Active   │  80 │ 2.4.0.201807231832     │ ZWave Binding

and now I am seeing this in the log:

NODE 37: Invalid item type defined (QuantityType). Assuming DecimalType

I don’t think there was such message before, what does it mean?
The device is Qubino ZMNHDA Flush dimmer.

Hi guys,

I had a fully working z-wave network using

  • raspberry pi 3 with openhabian
  • openhab 2.3.0-1
  • Aeon zstick s2
  • experimental zwave binding
  • roughly 30 devices
    I don’t know what went wrong. I noticed that I couldn’t add any new devices. I tried upgrading to the newest version of the experimental binding. That only made the problems worse. Now all battery powered devices stopped working. I get errors like this in my openhab.og:
2018-07-24 20:49:54.388 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyUSB0'
2018-07-24 20:49:54.536 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2018-07-24 20:49:54.591 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2018-07-24 20:49:54.594 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2018-07-24 20:49:57.969 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2018-07-24 20:49:57.974 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 3: Node found
2018-07-24 20:49:57.977 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 4: Node found
2018-07-24 20:49:57.981 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 5: Node found
2018-07-24 20:49:57.984 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 6: Node found
2018-07-24 20:49:57.987 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 7: Node found
2018-07-24 20:49:57.990 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 8: Node found
2018-07-24 20:49:57.993 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 9: Node found
2018-07-24 20:49:57.996 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 10: Node found
2018-07-24 20:49:58.004 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 12: Node found
2018-07-24 20:49:58.011 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 13: Node found
2018-07-24 20:49:58.014 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 14: Node found
2018-07-24 20:49:58.017 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 15: Node found
2018-07-24 20:49:58.020 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 16: Node found
2018-07-24 20:49:58.022 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 17: Node found
2018-07-24 20:49:58.025 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 18: Node found
2018-07-24 20:49:58.028 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 19: Node found
2018-07-24 20:49:58.031 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 20: Node found
2018-07-24 20:49:58.034 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 21: Node found
2018-07-24 20:49:58.036 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 22: Node found
2018-07-24 20:49:58.038 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 23: Node found
2018-07-24 20:49:58.042 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 24: Node found
2018-07-24 20:49:58.045 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 25: Node found
2018-07-24 20:49:58.047 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 26: Node found
2018-07-24 20:49:58.050 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 27: Node found
2018-07-24 20:49:58.054 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 28: Node found
2018-07-24 20:49:58.056 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 29: Node found
2018-07-24 20:49:58.059 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 30: Node found
2018-07-24 20:49:58.062 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 31: Node found
2018-07-24 20:49:58.065 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 32: Node found
2018-07-24 20:49:58.068 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 33: Node found
2018-07-24 20:49:58.070 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 34: Node found
2018-07-24 20:49:58.073 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 35: Node found
2018-07-24 20:49:58.075 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 36: Node found
2018-07-24 20:49:58.080 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2018-07-24 20:49:58.082 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2018-07-24 20:49:58.084 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2018-07-24 20:49:58.087 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 34
2018-07-24 20:49:58.088 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2018-07-24 20:49:59.463 [ERROR] [ve.internal.protocol.ZWaveController] - NODE 8: Restore from config: Error deserialising XML file. com.thoughtworks.xstream.converters.reflection.AbstractReflectionConverter$UnknownFieldException: No such field org.openhab.binding.zwave.internal.protocol.ZWaveAssociationGroup.maxNodes
---- Debugging information ----
field               : maxNodes
class               : org.openhab.binding.zwave.internal.protocol.ZWaveAssociationGroup
required-type       : org.openhab.binding.zwave.internal.protocol.ZWaveAssociationGroup
converter-type      : com.thoughtworks.xstream.converters.reflection.ReflectionConverter
path                : /node/associationGroups/entry/associationGroup/maxNodes
line number         : 34
class[1]            : java.util.HashMap
converter-type[1]   : com.thoughtworks.xstream.converters.collections.MapConverter
class[2]            : org.openhab.binding.zwave.internal.protocol.ZWaveNode
version             : 1.4.7
-------------------------------
2018-07-24 20:49:59.463 [ERROR] [ve.internal.protocol.ZWaveController] - NODE 34: Restore from config: Error deserialising XML file. com.thoughtworks.xstream.converters.reflection.AbstractReflectionConverter$UnknownFieldException: No such field org.openhab.binding.zwave.internal.protocol.ZWaveAssociationGroup.maxNodes
---- Debugging information ----
field               : maxNodes
class               : org.openhab.binding.zwave.internal.protocol.ZWaveAssociationGroup
required-type       : org.openhab.binding.zwave.internal.protocol.ZWaveAssociationGroup
converter-type      : com.thoughtworks.xstream.converters.reflection.ReflectionConverter
path                : /node/associationGroups/entry/associationGroup/maxNodes
line number         : 42
class[1]            : java.util.concurrent.ConcurrentHashMap
converter-type[1]   : com.thoughtworks.xstream.converters.collections.MapConverter
class[2]            : org.openhab.binding.zwave.internal.protocol.ZWaveNode
version             : 1.4.7
-------------------------------
2018-07-24 20:49:59.469 [ERROR] [ve.internal.protocol.ZWaveController] - NODE 10: Restore from config: Error deserialising XML file. com.thoughtworks.xstream.converters.reflection.AbstractReflectionConverter$UnknownFieldException: No such field org.openhab.binding.zwave.internal.protocol.ZWaveAssociationGroup.maxNodes
---- Debugging information ----
field               : maxNodes
class               : org.openhab.binding.zwave.internal.protocol.ZWaveAssociationGroup
required-type       : org.openhab.binding.zwave.internal.protocol.ZWaveAssociationGroup
converter-type      : com.thoughtworks.xstream.converters.reflection.ReflectionConverter
path                : /node/associationGroups/entry/associationGroup/maxNodes
line number         : 34
class[1]            : java.util.HashMap
converter-type[1]   : com.thoughtworks.xstream.converters.collections.MapConverter
class[2]            : org.openhab.binding.zwave.internal.protocol.ZWaveNode
version             : 1.4.7
-------------------------------

The controler only works with the nodes that are connected to the main power. The battery devices are all dead except one fibaro motion sensor. If I try to click the wake up button on the other battery devices, notthing happens in the logs.

I’m at a loss. Does anyone have any idea what could be wrong?

Thanks

This simply means that the XML file has changed format - don’t worry about this.

Have you woken up the devices, or left the system so that they have time to wake themselves up? This could take a day or so, depending on your system.

I don’t think this should be new, and nothing has changed in this area of the code in the version you have from yesterday. I’ve now changed this message so that I can more easily tell what version people are using. Please ensure that you are using the latest version.

Have you woken up the devices, or left the system so that they have time to wake themselves up? This could take a day or so, depending on your system.

Yes, I did both. I took some devices and kept waking them up repeatedly. Nothing happens. I also don’t see any zwave activity in the logs when I wake the devices up. I also left the system running voor 48 hours. That didn’t do any good either.

It doesn’t sounds like it’s related to changing binding, but did you delete all your things and re-add them when you changed to the dev version?

It seems a little strange that all battery devices suddenly stopped sending wakeup messages.

When you say nothing happens in the logs, have you enabled debug mode? The log you showed earlier didn’t appear to have debug information enabled.

I didn’t change from the normal binding to the dev binding, just switched versions of the dev binding. But anyway realy strange thing, I switched on debug and woke up a node, I will spare you the log, it grew to 3 MB in about a minute. Important thing is that the battery nodes seem to work again. I was successfully able to wake up three nodes and got them to send their configuration data to the binding. So I’d say it works as expected again. Really strange, the only thing I did differently was switch on debug and wake up a node. I must have woken up nodes hundreds of times over the last few days. I switched off debug again and was able to wake up another node and watched it send it’s configuration to the binding now in default logging. Just for amusement this is that log.


2018-07-25 00:05:31.525 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:a93e88d5:node27' has been updated.
2018-07-25 00:05:44.573 [vent.ItemStateChangedEvent] - MotionSensorHal_MotionAlarm changed from ON to OFF
2018-07-25 00:05:44.653 [vent.ItemStateChangedEvent] - MotionSensorDummyHal changed from ON to OFF
2018-07-25 00:05:44.680 [hingStatusInfoChangedEvent] - 'zwave:device:a93e88d5:node27' changed from ONLINE to ONLINE: Node initialising: SECURITY_REPORT
2018-07-25 00:05:44.696 [hingStatusInfoChangedEvent] - 'zwave:device:a93e88d5:node27' changed from ONLINE: Node initialising: SECURITY_REPORT to ONLINE: Node initialising: MANUFACTURER
2018-07-25 00:05:44.751 [hingStatusInfoChangedEvent] - 'zwave:device:a93e88d5:node27' changed from ONLINE: Node initialising: MANUFACTURER to ONLINE: Node initialising: APP_VERSION
2018-07-25 00:05:44.826 [hingStatusInfoChangedEvent] - 'zwave:device:a93e88d5:node27' changed from ONLINE: Node initialising: APP_VERSION to ONLINE: Node initialising: DISCOVERY_COMPLETE
2018-07-25 00:05:44.829 [hingStatusInfoChangedEvent] - 'zwave:device:a93e88d5:node27' changed from ONLINE: Node initialising: DISCOVERY_COMPLETE to ONLINE: Node initialising: VERSION
2018-07-25 00:05:45.745 [hingStatusInfoChangedEvent] - 'zwave:device:a93e88d5:node27' changed from ONLINE: Node initialising: VERSION to ONLINE: Node initialising: ENDPOINTS
2018-07-25 00:05:45.759 [hingStatusInfoChangedEvent] - 'zwave:device:a93e88d5:node27' changed from ONLINE: Node initialising: ENDPOINTS to ONLINE: Node initialising: UPDATE_DATABASE
2018-07-25 00:05:45.773 [hingStatusInfoChangedEvent] - 'zwave:device:a93e88d5:node27' changed from ONLINE: Node initialising: UPDATE_DATABASE to ONLINE: Node initialising: STATIC_VALUES
2018-07-25 00:05:45.824 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:a93e88d5:node27' has been updated.
2018-07-25 00:05:45.828 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2018-07-25 00:05:46.244 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:a93e88d5:node27' has been updated.
2018-07-25 00:05:46.246 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2018-07-25 00:05:46.249 [hingStatusInfoChangedEvent] - 'zwave:device:a93e88d5:node27' changed from ONLINE: Node initialising: STATIC_VALUES to ONLINE: Node initialising: ASSOCIATIONS
2018-07-25 00:05:46.418 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:a93e88d5:node27' has been updated.
2018-07-25 00:05:46.422 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2018-07-25 00:05:48.778 [vent.ItemStateChangedEvent] - MotionSensorWoonEetkamer_Woonkamer_MotionAlarm changed from ON to OFF
2018-07-25 00:05:48.823 [vent.ItemStateChangedEvent] - MotionSensorDummyWoonEetkamer_Woonkamer changed from ON to OFF
2018-07-25 00:05:49.689 [vent.ItemStateChangedEvent] - MotionSensorWoonEetkamer_Eetkamer_MotionAlarm changed from ON to OFF
2018-07-25 00:05:49.697 [GroupItemStateChangedEvent] - RealMotionSensor_All_Movement changed from ON to OFF through MotionSensorWoonEetkamer_Eetkamer_MotionAlarm
2018-07-25 00:05:49.741 [vent.ItemStateChangedEvent] - MotionSensorDummyWoonEetkamer_Eetkamer changed from ON to OFF
2018-07-25 00:05:49.749 [GroupItemStateChangedEvent] - MotionSensor_Beneden_Movement changed from ON to OFF through MotionSensorDummyWoonEetkamer_Eetkamer
2018-07-25 00:05:49.756 [GroupItemStateChangedEvent] - MotionSensor_All_Movement changed from ON to OFF through MotionSensorDummyWoonEetkamer_Eetkamer
2018-07-25 00:05:51.501 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:a93e88d5:node27' has been updated.
2018-07-25 00:05:51.507 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2018-07-25 00:05:51.720 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:a93e88d5:node27' has been updated.
2018-07-25 00:05:51.725 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2018-07-25 00:05:51.863 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:a93e88d5:node27' has been updated.
2018-07-25 00:05:51.866 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2018-07-25 00:05:52.661 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:a93e88d5:node27' has been updated.
2018-07-25 00:05:52.664 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2018-07-25 00:05:52.816 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:a93e88d5:node27' has been updated.
2018-07-25 00:05:52.818 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2018-07-25 00:05:52.962 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:a93e88d5:node27' has been updated.
2018-07-25 00:05:52.964 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2018-07-25 00:05:53.107 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:a93e88d5:node27' has been updated.
2018-07-25 00:05:53.111 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2018-07-25 00:05:53.300 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:a93e88d5:node27' has been updated.
2018-07-25 00:05:53.309 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2018-07-25 00:05:53.317 [hingStatusInfoChangedEvent] - 'zwave:device:a93e88d5:node27' changed from ONLINE: Node initialising: ASSOCIATIONS to ONLINE: Node initialising: SET_WAKEUP
2018-07-25 00:05:53.327 [hingStatusInfoChangedEvent] - 'zwave:device:a93e88d5:node27' changed from ONLINE: Node initialising: SET_WAKEUP to ONLINE: Node initialising: SET_ASSOCIATION
2018-07-25 00:05:53.499 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:a93e88d5:node27' has been updated.
2018-07-25 00:05:53.507 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2018-07-25 00:05:53.512 [hingStatusInfoChangedEvent] - 'zwave:device:a93e88d5:node27' changed from ONLINE: Node initialising: SET_ASSOCIATION to ONLINE: Node initialising: SET_LIFELINE
2018-07-25 00:05:53.521 [hingStatusInfoChangedEvent] - 'zwave:device:a93e88d5:node27' changed from ONLINE: Node initialising: SET_LIFELINE to ONLINE: Node initialising: GET_CONFIGURATION
2018-07-25 00:05:54.835 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:a93e88d5:node27' has been updated.
2018-07-25 00:05:54.859 [hingStatusInfoChangedEvent] - 'zwave:device:a93e88d5:node27' changed from ONLINE: Node initialising: GET_CONFIGURATION to ONLINE
2018-07-25 00:05:55.046 [vent.ItemStateChangedEvent] - MotionSensorBadkamer_SensorLuminance changed from 0 to 1
2018-07-25 00:05:55.183 [GroupItemStateChangedEvent] - TemperatureMotionSensors changed from 25.5 to 25.8 through MotionSensorBadkamer_SensorTemperature
2018-07-25 00:05:55.186 [vent.ItemStateChangedEvent] - MotionSensorBadkamer_SensorTemperature changed from 24.6 ℃ to 27.5 ℃
2018-07-25 00:05:55.425 [arthome.event.BindingEvent] - org.openhab.binding.zwave.event.BindingEvent@1bf7c18
2018-07-25 00:05:59.057 [arthome.event.BindingEvent] - org.openhab.binding.zwave.event.BindingEvent@efd67b
2018-07-25 00:05:59.092 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:a93e88d5:node27' has been updated.

Really strange, but if it works, don’t mess it up. Thanks for your help and thanks for all your hard work on the binding!

1 Like

I just updated to the latest binding along with the latest Openhab snapshot and things are working great. Earlier I had issues with polling not working and I never got to help out with posting any logs because I ended up quickly reverting versions. The latest version is outstanding though and startup seems to work a whole lot quicker in my network of 50 or so devices. Great work @chris!

I just installed the latest binding yesterday (201807231832). Tonight Z-Wave things stopped updating due to a Java exception. A restart of the Z-Wave binding brought it back to life. Here is the Z-Wave Debug log (exception at 2018-07-25 02:13:53.724):

2018-07-25 02:13:53.720 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 148: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2018-07-25 02:13:53.720 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Encapsulating message, endpoint 0
2018-07-25 02:13:53.720 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 161: Creating new message for application command METER_GET
2018-07-25 02:13:53.721 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 148: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
2018-07-25 02:13:53.721 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: SECURITY not supported
2018-07-25 02:13:53.720 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 26: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2018-07-25 02:13:53.721 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build COMMAND_CLASS_METER
2018-07-25 02:13:53.720 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 02:13:53.721 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 148: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2018-07-25 02:13:53.721 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Command Class COMMAND_CLASS_METER is NOT required to be secured
2018-07-25 02:13:53.721 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 148: Polling zwave:device:ZWOG:node148:meter_watts1
2018-07-25 02:13:53.720 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Adding to device queue
2018-07-25 02:13:53.721 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 191: SECURITY not supported
2018-07-25 02:13:53.721 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 161: Encapsulating message, endpoint 1
2018-07-25 02:13:53.721 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 02:13:53.721 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 26: Creating new message for application command METER_GET
2018-07-25 02:13:53.720 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 177: SECURITY NOT required on COMMAND_CLASS_SENSOR_MULTILEVEL
2018-07-25 02:13:53.721 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Adding to device queue
2018-07-25 02:13:53.721 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 161: Encapsulating message, instance / endpoint 1
2018-07-25 02:13:53.721 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 191: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2018-07-25 02:13:53.721 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 02:13:53.721 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: Adding to device queue
2018-07-25 02:13:53.721 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 191: Polling zwave:device:ZWOG:node191:meter_kwh1
2018-07-25 02:13:53.721 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 161: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2018-07-25 02:13:53.721 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 148: Generating poll message for COMMAND_CLASS_METER, endpoint 1
2018-07-25 02:13:53.721 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build COMMAND_CLASS_METER
2018-07-25 02:13:53.721 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 148: Generating poll message for COMMAND_CLASS_METER, endpoint 1
2018-07-25 02:13:53.721 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: Encapsulating message, endpoint 0
2018-07-25 02:13:53.721 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 02:13:53.721 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 191: Generating poll message for COMMAND_CLASS_METER, endpoint 1
2018-07-25 02:13:53.721 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: SECURITY not supported
2018-07-25 02:13:53.721 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 148: Creating new message for application command METER_GET
2018-07-25 02:13:53.721 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 177: Received COMMAND_CLASS_SENSOR_MULTILEVEL V5 SENSOR_MULTILEVEL_REPORT
2018-07-25 02:13:53.721 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 161: SECURITY not supported
2018-07-25 02:13:53.721 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Adding to device queue
2018-07-25 02:13:53.721 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 177: Sensor Type = Power(4), Scale = 0
2018-07-25 02:13:53.721 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 191: Generating poll message for COMMAND_CLASS_METER, endpoint 1
2018-07-25 02:13:53.721 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 02:13:53.721 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 177: Sensor Value = 21.6
2018-07-25 02:13:53.721 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: Command Class COMMAND_CLASS_METER is NOT required to be secured
2018-07-25 02:13:53.721 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build COMMAND_CLASS_METER
2018-07-25 02:13:53.721 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Adding to device queue
2018-07-25 02:13:53.722 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Polling zwave:device:ZWOG:node26:meter_watts
2018-07-25 02:13:53.721 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 161: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2018-07-25 02:13:53.721 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 191: Creating new message for application command METER_GET
2018-07-25 02:13:53.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 02:13:53.722 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 177: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2018-07-25 02:13:53.722 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 26: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2018-07-25 02:13:53.722 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 148: Encapsulating message, endpoint 1
2018-07-25 02:13:53.722 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build COMMAND_CLASS_METER
2018-07-25 02:13:53.722 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 26: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2018-07-25 02:13:53.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 161: Adding to device queue
2018-07-25 02:13:53.722 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 191: Encapsulating message, endpoint 1
2018-07-25 02:13:53.722 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 177: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SENSOR_MULTILEVEL, value = 21.6
2018-07-25 02:13:53.722 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 26: Creating new message for application command METER_GET
2018-07-25 02:13:53.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 02:13:53.722 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build COMMAND_CLASS_METER
2018-07-25 02:13:53.722 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 148: Encapsulating message, instance / endpoint 1
2018-07-25 02:13:53.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Adding to device queue
2018-07-25 02:13:53.722 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 191: Encapsulating message, instance / endpoint 1
2018-07-25 02:13:53.722 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 148: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2018-07-25 02:13:53.722 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 177: Sensor conversion not performed for POWER.
2018-07-25 02:13:53.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 02:13:53.722 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 148: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
2018-07-25 02:13:53.722 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 177: Updating channel state zwave:device:ZWOG:node177:sensor_power to 21.6 [DecimalType]
2018-07-25 02:13:53.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Adding to device queue
2018-07-25 02:13:53.722 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 148: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2018-07-25 02:13:53.722 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: Encapsulating message, endpoint 0
2018-07-25 02:13:53.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 02:13:53.722 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 191: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2018-07-25 02:13:53.722 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: SECURITY not supported
2018-07-25 02:13:53.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 148: Adding to device queue
2018-07-25 02:13:53.722 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 191: SECURITY not supported
2018-07-25 02:13:53.722 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: Command Class COMMAND_CLASS_METER is NOT required to be secured
2018-07-25 02:13:53.722 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 191: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2018-07-25 02:13:53.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 161: Adding to device queue
2018-07-25 02:13:53.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 02:13:53.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 02:13:53.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 148: Adding to device queue
2018-07-25 02:13:53.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 02:13:53.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 161: Adding to device queue
2018-07-25 02:13:53.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 02:13:53.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Adding to device queue
2018-07-25 02:13:53.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 177: Commands processed 1.
2018-07-25 02:13:53.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 02:13:53.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 191: Adding to device queue
2018-07-25 02:13:53.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 177: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@6969186.
2018-07-25 02:13:53.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 02:13:53.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2018-07-25 02:13:53.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2018-07-25 02:13:53.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2018-07-25 02:13:53.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 10804: [WAIT_RESPONSE] requiresResponse=true callback: 214
2018-07-25 02:13:53.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started...
2018-07-25 02:13:53.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 148: Adding to device queue
2018-07-25 02:13:53.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff true.
2018-07-25 02:13:53.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer active - no send...
2018-07-25 02:13:53.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer finishing in 250ms
2018-07-25 02:13:53.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer finishing in 250ms
2018-07-25 02:13:53.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 10804: Resetting transaction
2018-07-25 02:13:53.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 28: notifyTransactionResponse TID:10804 WAIT_RESPONSE
2018-07-25 02:13:53.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer finishing in 250ms
2018-07-25 02:13:53.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 28: Adding to device queue
2018-07-25 02:13:53.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-07-25 02:13:53.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer active - no send...
2018-07-25 02:13:53.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Adding to device queue
2018-07-25 02:13:53.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer finishing in 250ms
2018-07-25 02:13:53.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-07-25 02:13:53.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-25 02:13:53.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer active - no send...
2018-07-25 02:13:53.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-07-25 02:13:53.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 191: Adding to device queue
2018-07-25 02:13:53.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer active - no send...
2018-07-25 02:13:53.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer finishing in 249ms
2018-07-25 02:13:53.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer finishing in 249ms
2018-07-25 02:13:53.724 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 148: Polling aborted due to exception
java.lang.IllegalStateException: Task already scheduled or cancelled
	at java.util.Timer.sched(Unknown Source) [?:?]
	at java.util.Timer.schedule(Unknown Source) [?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.startTransactionTimer(ZWaveTransactionManager.java:906) [244:org.openhab.binding.zwave:2.4.0.201807231832]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.addTransactionToQueue(ZWaveTransactionManager.java:335) [244:org.openhab.binding.zwave:2.4.0.201807231832]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.queueTransactionForSend(ZWaveTransactionManager.java:298) [244:org.openhab.binding.zwave:2.4.0.201807231832]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.enqueue(ZWaveController.java:493) [244:org.openhab.binding.zwave:2.4.0.201807231832]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.sendData(ZWaveController.java:864) [244:org.openhab.binding.zwave:2.4.0.201807231832]
	at org.openhab.binding.zwave.handler.ZWaveControllerHandler.sendData(ZWaveControllerHandler.java:685) [244:org.openhab.binding.zwave:2.4.0.201807231832]
	at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:405) [244:org.openhab.binding.zwave:2.4.0.201807231832]
	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) [?:?]
	at java.util.concurrent.FutureTask.runAndReset(Unknown Source) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(Unknown Source) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]
	at java.lang.Thread.run(Unknown Source) [?:?]
2018-07-25 02:13:53.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-07-25 02:13:53.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer active - no send...
2018-07-25 02:13:53.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer finishing in 249ms
2018-07-25 02:13:53.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Adding to device queue
2018-07-25 02:13:53.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-07-25 02:13:53.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 191: Adding to device queue
2018-07-25 02:13:53.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer active - no send...
2018-07-25 02:13:53.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-07-25 02:13:53.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer active - no send...
2018-07-25 02:13:53.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer finishing in 248ms
2018-07-25 02:13:53.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer finishing in 248ms
2018-07-25 02:13:53.726 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 191: Polling aborted due to exception
java.lang.IllegalStateException: Task already scheduled or cancelled
	at java.util.Timer.sched(Unknown Source) [?:?]
	at java.util.Timer.schedule(Unknown Source) [?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.startTransactionTimer(ZWaveTransactionManager.java:906) [244:org.openhab.binding.zwave:2.4.0.201807231832]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.addTransactionToQueue(ZWaveTransactionManager.java:335) [244:org.openhab.binding.zwave:2.4.0.201807231832]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.queueTransactionForSend(ZWaveTransactionManager.java:298) [244:org.openhab.binding.zwave:2.4.0.201807231832]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.enqueue(ZWaveController.java:493) [244:org.openhab.binding.zwave:2.4.0.201807231832]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.sendData(ZWaveController.java:864) [244:org.openhab.binding.zwave:2.4.0.201807231832]
	at org.openhab.binding.zwave.handler.ZWaveControllerHandler.sendData(ZWaveControllerHandler.java:685) [244:org.openhab.binding.zwave:2.4.0.201807231832]
	at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:405) [244:org.openhab.binding.zwave:2.4.0.201807231832]
	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) [?:?]
	at java.util.concurrent.FutureTask.runAndReset(Unknown Source) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(Unknown Source) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]
	at java.lang.Thread.run(Unknown Source) [?:?]
2018-07-25 02:13:53.964 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@73a0a989
2018-07-25 02:13:53.964 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Adding to device queue
2018-07-25 02:13:53.964 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-25 02:13:53.964 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 1D 86 
2018-07-25 02:13:53.964 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Port closed sending REQUEST Message = 01 04 00 60 1D 86 
2018-07-25 02:13:53.964 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 4048: Transaction Start type RequestNodeInfo 
2018-07-25 02:13:53.974 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Holdoff Timer triggered...
2018-07-25 02:13:53.974 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-25 02:13:53.974 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 1C 02 26 02 25 D6 2C 
2018-07-25 02:13:53.974 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 28: Sending REQUEST Message = 01 09 00 13 1C 02 26 02 25 D6 2C 
2018-07-25 02:13:53.977 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-07-25 02:13:53.977 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 10804: Transaction Start type SendData 
2018-07-25 02:13:53.978 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-07-25 02:13:53.978 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-25 02:13:53.978 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-25 02:13:53.987 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2018-07-25 02:13:53.990 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2018-07-25 02:13:53.990 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2018-07-25 02:13:54.137 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 D6 00 00 0F 32 
2018-07-25 02:13:54.140 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 2<>126 : Message: class=SendData[19], type=Request[0], dest=0, callback=214, payload=D6 00 00 0F 
2018-07-25 02:13:54.140 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Request[0], dest=0, callback=214, payload=D6 00 00 0F 
2018-07-25 02:13:54.215 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 0F 12 32 02 21 74 00 07 C3 85 00 00 00 00 00 00 00 00 00 00 DA 
2018-07-25 02:13:54.216 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 07 C3 85 00 00 00 00 00 00 00 00 00 00 
2018-07-25 02:13:54.216 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 07 C3 85 00 00 00 00 00 00 00 00 00 00 
2018-07-25 02:13:54.217 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 07 C3 85 00 00 00 00 00 00 00 00 00 00 
2018-07-25 02:13:54.217 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-25 02:13:54.217 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: Application Command Request (ALIVE:DONE)
2018-07-25 02:13:54.217 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 15: resetResendCount initComplete=true isDead=false
2018-07-25 02:13:54.217 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 15: Incoming command class COMMAND_CLASS_METER, endpoint 0