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

chris · October 15, 2017, 5:58pm

From the database it looks like there is 1 channel defined at the moment (ie the lock itself). Do you mean that there are no channels showing up that you can link to? The version I compiled yesterday should have this channel and also the battery state.

Matt77 · October 15, 2017, 6:25pm

in HABmin it looks like the device would not be in the DB

chris · October 15, 2017, 6:57pm

And this is using todays binding version?

Matt77 · October 15, 2017, 7:27pm

i cross checked and it was an older version, must mixed up something with all changing between dev and snapshot version, sorry for the inconvenience.

looks ok now, will start to test the channels.

only my fibaro door/window sensor is not working (not a secure device) as mentioned earlier.
still getting :

2017-10-15 23:25:48.108 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Application Command Request (ALIVE:REQUEST_NIF)
2017-10-15 23:25:48.111 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2017-10-15 23:25:48.113 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: COMMAND_CLASS_MULTI_CHANNEL not found

stevenazari · October 15, 2017, 7:37pm

I guess this line in your log is not relevant?

2017-10-15 21:12:40.815 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Went to sleep COMPLETE
2017

Matt77 · October 15, 2017, 8:33pm

@stevenazari
i’m not sure what you want to tell me with that.
its a battery device which suppose to go into a sleep mode, or not?
if i wake it up i get the below in the log’s

your code goes here

and if i open the window this:

2017-10-16 00:10:23.040 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Application Command Request (ALIVE:DONE)
2017-10-16 00:10:23.043 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: resetResendCount initComplete=true isDead=false
2017-10-16 00:10:23.046 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2017-10-16 00:10:23.049 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: COMMAND_CLASS_MULTI_CHANNEL not found
2017-10-16 00:10:35.484 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Application Command Request (ALIVE:DONE)
2017-10-16 00:10:35.486 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: resetResendCount initComplete=true isDead=false
2017-10-16 00:10:35.488 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2017-10-16 00:10:35.490 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: COMMAND_CLASS_MULTI_CHANNEL not found

so what i try to understand is why do i get the second error regarding the COMMAND_CLASS_MULTI_CHANNEL not found, which i assume is the reason why i do not get an open/close status of the corresponding item. this is working with the binding from the latest OH2 snapshot

@chris any suggestions where i could start? all other nodes, battery none battery and even the Danalock v2 secure communication are working fine.

Matt77 · October 15, 2017, 8:34pm

2017-10-16 00:05:16.416 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Application Command Request (ALIVE:REQUEST_NIF)
2017-10-16 00:05:16.418 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Incoming command class COMMAND_CLASS_WAKE_UP, endpoint 0
2017-10-16 00:05:16.421 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: SECURITY NOT required on COMMAND_CLASS_WAKE_UP
2017-10-16 00:05:16.423 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 31: Received COMMAND_CLASS_WAKE_UP V2 WAKE_UP_NOTIFICATION
2017-10-16 00:05:16.426 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Creating wakeup timer
2017-10-16 00:05:16.429 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Is awake with 1 messages in the queue
2017-10-16 00:05:16.431 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Creating WakeupTimerTask
2017-10-16 00:05:16.434 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Creating WakeupTimerTask
2017-10-16 00:05:16.439 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2017-10-16 00:05:16.445 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 31: Node Status event - Node is AWAKE
2017-10-16 00:05:16.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Commands processed 1.
2017-10-16 00:05:16.450 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1a56f9.
2017-10-16 00:05:16.462 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: listening == false, frequentlyListening == false, awake == true
2017-10-16 00:05:16.553 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: TID 23: Transaction not completed
2017-10-16 00:05:16.575 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 31: Application update request. Node information received. Transaction TID 23: [WAIT_DATA] requiresResponse=true callback: 0
2017-10-16 00:05:16.589 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Response processed after 106ms
2017-10-16 00:05:16.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: TID 23: Transaction completed
2017-10-16 00:05:16.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: notifyTransactionResponse TID:23 DONE
2017-10-16 00:05:16.596 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: -- To notify -- COMPLETE
2017-10-16 00:05:16.597 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-10-16 00:05:16.600 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node Init response (0) COMPLETE
2017-10-16 00:05:16.602 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node Init transaction completed with response COMPLETE
2017-10-16 00:05:16.605 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: Restored from file - skipping static initialisation
2017-10-16 00:05:16.607 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer - advancing to STATIC_END
2017-10-16 00:05:16.613 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2017-10-16 00:05:16.615 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Updating node properties.
2017-10-16 00:05:16.618 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Updating node properties. MAN=271
2017-10-16 00:05:16.621 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Updating node properties. MAN=271. SET. Was 271
2017-10-16 00:05:16.625 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Properties synchronised
2017-10-16 00:05:16.653 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Update ASSOCIATION group_org.openhab.binding.zwave.internal.protocol.ZWaveAssociationGroup@106b5f9: Adding node_1_0
2017-10-16 00:05:16.656 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Setting ONLINE
2017-10-16 00:05:16.663 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Initialising Thing Node...
2017-10-16 00:05:16.666 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Initialising cmd channel zwave:device:15f1ee0619b:node31:scene_number for DecimalType
2017-10-16 00:05:16.667 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Initialising state channel zwave:device:15f1ee0619b:node31:scene_number for DecimalType
2017-10-16 00:05:16.669 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Initialising cmd channel zwave:device:15f1ee0619b:node31:sensor_binary for OnOffType
2017-10-16 00:05:16.671 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Initialising state channel zwave:device:15f1ee0619b:node31:sensor_binary for OnOffType
2017-10-16 00:05:16.673 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Initialising cmd channel zwave:device:15f1ee0619b:node31:sensor_temperature for DecimalType
2017-10-16 00:05:16.674 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Initialising state channel zwave:device:15f1ee0619b:node31:sensor_temperature for DecimalType
2017-10-16 00:05:16.676 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Initialising cmd channel zwave:device:15f1ee0619b:node31:sensor_door for OpenClosedType
2017-10-16 00:05:16.678 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Initialising state channel zwave:device:15f1ee0619b:node31:sensor_door for OpenClosedType
2017-10-16 00:05:16.680 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Initialising cmd channel zwave:device:15f1ee0619b:node31:alarm_tamper for OnOffType
2017-10-16 00:05:16.681 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Initialising state channel zwave:device:15f1ee0619b:node31:alarm_tamper for OnOffType
2017-10-16 00:05:16.683 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Initialising cmd channel zwave:device:15f1ee0619b:node31:battery-level for PercentType
2017-10-16 00:05:16.685 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Initialising state channel zwave:device:15f1ee0619b:node31:battery-level for PercentType
2017-10-16 00:05:16.687 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Initialising cmd channel zwave:device:15f1ee0619b:node31:alarm_general for OnOffType
2017-10-16 00:05:16.688 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Initialising state channel zwave:device:15f1ee0619b:node31:alarm_general for OnOffType
2017-10-16 00:05:16.690 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Polling intialised at 1800 seconds - start in 1800000 milliseconds.
2017-10-16 00:05:16.691 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 31: Serialise aborted as static stages not complete
2017-10-16 00:05:16.693 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer - advancing to DYNAMIC_VALUES
2017-10-16 00:05:16.696 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2017-10-16 00:05:16.697 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_BASIC
2017-10-16 00:05:16.698 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_SENSOR_ALARM
2017-10-16 00:05:16.700 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Found 1 instances of COMMAND_CLASS_SENSOR_ALARM for endpoint 0
2017-10-16 00:05:16.705 [DEBUG] [ndclass.ZWaveAlarmSensorCommandClass] - NODE 31: ====---- Checking alarm GENERAL - init false
2017-10-16 00:05:16.707 [DEBUG] [ndclass.ZWaveAlarmSensorCommandClass] - NODE 31: Creating new message for command SENSOR_ALARM_GET, type General
2017-10-16 00:05:16.710 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Encapsulating message, endpoint 0
2017-10-16 00:05:16.711 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: SECURITY NOT required on COMMAND_CLASS_SENSOR_ALARM
2017-10-16 00:05:16.713 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Command Class COMMAND_CLASS_SENSOR_ALARM is NOT required to be secured
2017-10-16 00:05:16.714 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: ZWaveCommandClassTransactionPayload - send to node
2017-10-16 00:05:16.716 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Encapsulating message, endpoint 0
2017-10-16 00:05:16.718 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: SECURITY NOT required on COMMAND_CLASS_SENSOR_ALARM
2017-10-16 00:05:16.719 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Command Class COMMAND_CLASS_SENSOR_ALARM is NOT required to be secured
2017-10-16 00:05:16.721 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@17d90c1
2017-10-16 00:05:16.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Adding to device queue
2017-10-16 00:05:16.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Added to queue - size 0
2017-10-16 00:05:16.727 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: listening == false, frequentlyListening == false, awake == true
2017-10-16 00:05:16.734 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 31: Sending REQUEST Message = 01 0A 00 13 1F 03 9C 01 00 25 9A D8 
2017-10-16 00:05:16.775 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 31: sentData successfully placed on stack.
2017-10-16 00:05:16.795 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: TID 286: Transaction not completed
2017-10-16 00:05:16.816 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 31: SendData Request. CallBack ID = 154, Status = Transmission complete and ACK received(0)
2017-10-16 00:05:16.835 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: TID 286: Transaction not completed
2017-10-16 00:05:16.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Application Command Request (ALIVE:DYNAMIC_VALUES)
2017-10-16 00:05:16.841 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Incoming command class COMMAND_CLASS_SENSOR_ALARM, endpoint 0
2017-10-16 00:05:16.843 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: SECURITY NOT required on COMMAND_CLASS_SENSOR_ALARM
2017-10-16 00:05:16.844 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 31: Received COMMAND_CLASS_SENSOR_ALARM V1 SENSOR_ALARM_REPORT
2017-10-16 00:05:16.847 [DEBUG] [ndclass.ZWaveAlarmSensorCommandClass] - NODE 31: Alarm Report: Source=31, Type=General(0), Value=255
2017-10-16 00:05:16.850 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveAlarmSensorValueEvent
2017-10-16 00:05:16.852 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SENSOR_ALARM, value = 255
2017-10-16 00:05:16.854 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Updating channel state zwave:device:15f1ee0619b:node31:alarm_general to ON [OnOffType]
2017-10-16 00:05:16.856 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Commands processed 1.
2017-10-16 00:05:16.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1096b7c.
2017-10-16 00:05:16.859 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction 286  ApplicationCommandHandler.
2017-10-16 00:05:16.860 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction : state >> WAIT_DATA
2017-10-16 00:05:16.862 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction : node  >> 31
2017-10-16 00:05:16.863 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction : class >> 156 == 156.
2017-10-16 00:05:16.865 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction : commd >> 2 == 2.
2017-10-16 00:05:16.866 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1096b7c.
2017-10-16 00:05:16.874 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: notifyTransactionResponse TID:286 DONE
2017-10-16 00:05:16.877 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-10-16 00:05:16.877 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: -- To notify -- COMPLETE
2017-10-16 00:05:16.880 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node Init response (0) COMPLETE
2017-10-16 00:05:16.881 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node Init transaction completed with response COMPLETE
2017-10-16 00:05:16.883 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_ZWAVEPLUS_INFO
2017-10-16 00:05:16.885 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_ALARM
2017-10-16 00:05:16.886 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Found 1 instances of COMMAND_CLASS_ALARM for endpoint 0
2017-10-16 00:05:16.887 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_NO_OPERATION
2017-10-16 00:05:16.889 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_BATTERY
2017-10-16 00:05:16.890 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Found 1 instances of COMMAND_CLASS_BATTERY for endpoint 0
2017-10-16 00:05:16.893 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Encapsulating message, endpoint 0
2017-10-16 00:05:16.895 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: SECURITY NOT required on COMMAND_CLASS_BATTERY
2017-10-16 00:05:16.896 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Command Class COMMAND_CLASS_BATTERY is NOT required to be secured
2017-10-16 00:05:16.897 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: ZWaveCommandClassTransactionPayload - send to node
2017-10-16 00:05:16.899 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Encapsulating message, endpoint 0
2017-10-16 00:05:16.900 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: SECURITY NOT required on COMMAND_CLASS_BATTERY
2017-10-16 00:05:16.902 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Command Class COMMAND_CLASS_BATTERY is NOT required to be secured
2017-10-16 00:05:16.903 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@63e90b
2017-10-16 00:05:16.905 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Adding to device queue
2017-10-16 00:05:16.906 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Added to queue - size 0
2017-10-16 00:05:16.909 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: listening == false, frequentlyListening == false, awake == true
2017-10-16 00:05:16.916 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 31: Sending REQUEST Message = 01 09 00 13 1F 02 80 02 25 9B C4 
2017-10-16 00:05:16.963 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 31: sentData successfully placed on stack.
2017-10-16 00:05:16.976 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: TID 287: Transaction not completed
2017-10-16 00:05:16.996 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 31: SendData Request. CallBack ID = 155, Status = Transmission complete and ACK received(0)
2017-10-16 00:05:17.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: TID 287: Transaction not completed
2017-10-16 00:05:17.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Application Command Request (ALIVE:DYNAMIC_VALUES)
2017-10-16 00:05:17.012 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Incoming command class COMMAND_CLASS_BATTERY, endpoint 0
2017-10-16 00:05:17.013 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: SECURITY NOT required on COMMAND_CLASS_BATTERY
2017-10-16 00:05:17.015 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 31: Received COMMAND_CLASS_BATTERY V1 BATTERY_REPORT
2017-10-16 00:05:17.016 [DEBUG] [ommandclass.ZWaveBatteryCommandClass] - NODE 31: Battery report value = 94
2017-10-16 00:05:17.019 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2017-10-16 00:05:17.021 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_BATTERY, value = 94
2017-10-16 00:05:17.023 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Updating channel state zwave:device:15f1ee0619b:node31:battery-level to 94 [DecimalType]
2017-10-16 00:05:17.027 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Commands processed 1.
2017-10-16 00:05:17.029 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@a7799a.
2017-10-16 00:05:17.031 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction 287  ApplicationCommandHandler.
2017-10-16 00:05:17.032 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction : state >> WAIT_DATA
2017-10-16 00:05:17.034 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction : node  >> 31
2017-10-16 00:05:17.036 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction : class >> 128 == 128.
2017-10-16 00:05:17.037 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction : commd >> 3 == 3.
2017-10-16 00:05:17.038 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@a7799a.
2017-10-16 00:05:17.046 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: notifyTransactionResponse TID:287 DONE
2017-10-16 00:05:17.049 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-10-16 00:05:17.052 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: -- To notify -- COMPLETE
2017-10-16 00:05:17.057 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node Init response (0) COMPLETE
2017-10-16 00:05:17.059 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node Init transaction completed with response COMPLETE
2017-10-16 00:05:17.060 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_ASSOCIATION
2017-10-16 00:05:17.062 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_APPLICATION_STATUS
2017-10-16 00:05:17.063 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_ASSOCIATION_GRP_INFO
2017-10-16 00:05:17.064 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_DEVICE_RESET_LOCALLY
2017-10-16 00:05:17.065 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_MANUFACTURER_SPECIFIC
2017-10-16 00:05:17.066 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_SCENE_ACTIVATION
2017-10-16 00:05:17.067 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_POWERLEVEL
2017-10-16 00:05:17.069 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Found 1 instances of COMMAND_CLASS_POWERLEVEL for endpoint 0
2017-10-16 00:05:17.073 [DEBUG] [andclass.ZWavePowerLevelCommandClass] - NODE 31: Creating new message for application command POWERLEVEL_GET
2017-10-16 00:05:17.077 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Encapsulating message, endpoint 0
2017-10-16 00:05:17.079 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: SECURITY NOT required on COMMAND_CLASS_POWERLEVEL
2017-10-16 00:05:17.081 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Command Class COMMAND_CLASS_POWERLEVEL is NOT required to be secured
2017-10-16 00:05:17.083 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: ZWaveCommandClassTransactionPayload - send to node
2017-10-16 00:05:17.085 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Encapsulating message, endpoint 0
2017-10-16 00:05:17.087 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: SECURITY NOT required on COMMAND_CLASS_POWERLEVEL
2017-10-16 00:05:17.089 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Command Class COMMAND_CLASS_POWERLEVEL is NOT required to be secured
2017-10-16 00:05:17.091 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@683f06
2017-10-16 00:05:17.094 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Adding to device queue
2017-10-16 00:05:17.095 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Added to queue - size 0
2017-10-16 00:05:17.098 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: listening == false, frequentlyListening == false, awake == true
2017-10-16 00:05:17.108 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 31: Sending REQUEST Message = 01 09 00 13 1F 02 73 02 25 9C 30 
2017-10-16 00:05:17.158 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 31: sentData successfully placed on stack.
2017-10-16 00:05:17.169 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: TID 288: Transaction not completed
2017-10-16 00:05:17.187 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 31: SendData Request. CallBack ID = 156, Status = Transmission complete and ACK received(0)
2017-10-16 00:05:17.202 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: TID 288: Transaction not completed
2017-10-16 00:05:17.208 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Application Command Request (ALIVE:DYNAMIC_VALUES)
2017-10-16 00:05:17.210 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Incoming command class COMMAND_CLASS_POWERLEVEL, endpoint 0
2017-10-16 00:05:17.211 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: SECURITY NOT required on COMMAND_CLASS_POWERLEVEL
2017-10-16 00:05:17.214 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 31: Received COMMAND_CLASS_POWERLEVEL V1 POWERLEVEL_REPORT
2017-10-16 00:05:17.216 [DEBUG] [andclass.ZWavePowerLevelCommandClass] - NODE 31: Received POWERLEVEL report -0dB with 0 second timeout
2017-10-16 00:05:17.221 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWavePowerLevelCommandClassChangeEvent
2017-10-16 00:05:17.223 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_POWERLEVEL, value = 0
2017-10-16 00:05:17.226 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Config updated
2017-10-16 00:05:17.253 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Commands processed 1.
2017-10-16 00:05:17.254 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@fef4fb.
2017-10-16 00:05:17.255 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction 288  ApplicationCommandHandler.
2017-10-16 00:05:17.256 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction : state >> WAIT_DATA
2017-10-16 00:05:17.257 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction : node  >> 31
2017-10-16 00:05:17.258 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction : class >> 115 == 115.
2017-10-16 00:05:17.259 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction : commd >> 3 == 3.
2017-10-16 00:05:17.260 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@fef4fb.
2017-10-16 00:05:17.269 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: notifyTransactionResponse TID:288 DONE
2017-10-16 00:05:17.273 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-10-16 00:05:17.276 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: -- To notify -- COMPLETE
2017-10-16 00:05:17.281 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node Init response (0) COMPLETE
2017-10-16 00:05:17.282 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node Init transaction completed with response COMPLETE
2017-10-16 00:05:17.284 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_FIRMWARE_UPDATE_MD
2017-10-16 00:05:17.285 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_SECURITY

Matt77 · October 15, 2017, 8:35pm

sorry wasn’t able to put the log in one post

2017-10-16 00:05:17.287 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_CONFIGURATION
2017-10-16 00:05:17.288 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_CRC_16_ENCAP
2017-10-16 00:05:17.291 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_WAKE_UP
2017-10-16 00:05:17.300 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_SENSOR_BINARY
2017-10-16 00:05:17.303 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Found 1 instances of COMMAND_CLASS_SENSOR_BINARY for endpoint 0
2017-10-16 00:05:17.306 [DEBUG] [dclass.ZWaveBinarySensorCommandClass] - NODE 31: Creating new message for application command SENSOR_BINARY_GET
2017-10-16 00:05:17.310 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Encapsulating message, endpoint 0
2017-10-16 00:05:17.312 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: SECURITY NOT required on COMMAND_CLASS_SENSOR_BINARY
2017-10-16 00:05:17.315 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Command Class COMMAND_CLASS_SENSOR_BINARY is NOT required to be secured
2017-10-16 00:05:17.317 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: ZWaveCommandClassTransactionPayload - send to node
2017-10-16 00:05:17.319 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Encapsulating message, endpoint 0
2017-10-16 00:05:17.321 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: SECURITY NOT required on COMMAND_CLASS_SENSOR_BINARY
2017-10-16 00:05:17.323 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Command Class COMMAND_CLASS_SENSOR_BINARY is NOT required to be secured
2017-10-16 00:05:17.325 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@15bb82b
2017-10-16 00:05:17.328 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Adding to device queue
2017-10-16 00:05:17.329 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Added to queue - size 0
2017-10-16 00:05:17.333 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: listening == false, frequentlyListening == false, awake == true
2017-10-16 00:05:17.342 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 31: Sending REQUEST Message = 01 09 00 13 1F 02 30 02 25 9D 72 
2017-10-16 00:05:17.391 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 31: sentData successfully placed on stack.
2017-10-16 00:05:17.403 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: TID 289: Transaction not completed
2017-10-16 00:05:17.420 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 31: SendData Request. CallBack ID = 157, Status = Transmission complete and ACK received(0)
2017-10-16 00:05:17.436 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: TID 289: Transaction not completed
2017-10-16 00:05:17.441 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Application Command Request (ALIVE:DYNAMIC_VALUES)
2017-10-16 00:05:17.444 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Incoming command class COMMAND_CLASS_SENSOR_BINARY, endpoint 0
2017-10-16 00:05:17.446 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: SECURITY NOT required on COMMAND_CLASS_SENSOR_BINARY
2017-10-16 00:05:17.448 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 31: Received COMMAND_CLASS_SENSOR_BINARY V1 SENSOR_BINARY_REPORT
2017-10-16 00:05:17.450 [DEBUG] [dclass.ZWaveBinarySensorCommandClass] - NODE 31: Sensor Binary report, type=Unknown, value=0
2017-10-16 00:05:17.455 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveBinarySensorValueEvent
2017-10-16 00:05:17.457 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SENSOR_BINARY, value = 0
2017-10-16 00:05:17.459 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Updating channel state zwave:device:15f1ee0619b:node31:sensor_binary to OFF [OnOffType]
2017-10-16 00:05:17.462 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Commands processed 1.
2017-10-16 00:05:17.464 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@142e93.
2017-10-16 00:05:17.466 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction 289  ApplicationCommandHandler.
2017-10-16 00:05:17.467 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction : state >> WAIT_DATA
2017-10-16 00:05:17.469 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction : node  >> 31
2017-10-16 00:05:17.471 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction : class >> 48 == 48.
2017-10-16 00:05:17.473 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Checking transaction : commd >> 3 == 3.
2017-10-16 00:05:17.474 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@142e93.
2017-10-16 00:05:17.483 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: notifyTransactionResponse TID:289 DONE
2017-10-16 00:05:17.487 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: -- To notify -- COMPLETE
2017-10-16 00:05:17.487 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-10-16 00:05:17.495 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node Init response (0) COMPLETE
2017-10-16 00:05:17.496 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node Init transaction completed with response COMPLETE
2017-10-16 00:05:17.497 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_VERSION
2017-10-16 00:05:17.498 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION
2017-10-16 00:05:17.502 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: Initialisation complete!
2017-10-16 00:05:17.504 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer - advancing to DYNAMIC_END
2017-10-16 00:05:17.506 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2017-10-16 00:05:17.508 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 31: Serializing to file /var/lib/openhab2/zwave/network_fa03649c__node_31.xml
2017-10-16 00:05:17.588 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer - advancing to HEAL_START
2017-10-16 00:05:17.591 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2017-10-16 00:05:17.637 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer - advancing to UPDATE_NEIGHBORS
2017-10-16 00:05:17.640 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2017-10-16 00:05:17.641 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: UPDATE_NEIGHBORS - updating neighbor list
2017-10-16 00:05:17.643 [DEBUG] [equestNodeNeighborUpdateMessageClass] - NODE 31: Request neighbor update
2017-10-16 00:05:17.645 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@174ec57
2017-10-16 00:05:17.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Adding to device queue
2017-10-16 00:05:17.648 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Added to queue - size 0
2017-10-16 00:05:17.651 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: listening == false, frequentlyListening == false, awake == true
2017-10-16 00:05:17.746 [DEBUG] [equestNodeNeighborUpdateMessageClass] - NODE 31: Got NodeNeighborUpdate request.
2017-10-16 00:05:17.749 [DEBUG] [equestNodeNeighborUpdateMessageClass] - NODE 31: NodeNeighborUpdate STARTED
2017-10-16 00:05:17.768 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Response processed after 95ms
2017-10-16 00:05:17.771 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: TID 290: Transaction completed
2017-10-16 00:05:17.774 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: notifyTransactionResponse TID:290 DONE
2017-10-16 00:05:17.779 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: -- To notify -- COMPLETE
2017-10-16 00:05:17.780 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-10-16 00:05:17.784 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node Init response (0) COMPLETE
2017-10-16 00:05:17.785 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node Init transaction completed with response COMPLETE
2017-10-16 00:05:17.786 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer - advancing to GET_NEIGHBORS
2017-10-16 00:05:17.789 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2017-10-16 00:05:17.790 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer: GET_NEIGHBORS - get RoutingInfo
2017-10-16 00:05:17.791 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 31: Request routing info
2017-10-16 00:05:17.841 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 31: Got NodeRoutingInfo request.
2017-10-16 00:05:17.843 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 31: Neighbor nodes: 1 13 20 22
2017-10-16 00:05:17.847 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveNetworkEvent
2017-10-16 00:05:17.868 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node Init response (0) COMPLETE
2017-10-16 00:05:17.869 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node Init transaction completed with response COMPLETE
2017-10-16 00:05:17.871 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer - advancing to DELETE_SUC_ROUTES
2017-10-16 00:05:17.873 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2017-10-16 00:05:17.874 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer - advancing to SUC_ROUTE
2017-10-16 00:05:17.877 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2017-10-16 00:05:17.879 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer - advancing to DELETE_ROUTES
2017-10-16 00:05:17.881 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2017-10-16 00:05:17.885 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Generate return routes list
2017-10-16 00:05:17.900 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer is deleting return routes.
2017-10-16 00:05:17.902 [DEBUG] [essage.DeleteReturnRouteMessageClass] - NODE 31: Deleting return routes
2017-10-16 00:05:17.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@102587d
2017-10-16 00:05:17.906 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Adding to device queue
2017-10-16 00:05:17.908 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Added to queue - size 0
2017-10-16 00:05:17.910 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: listening == false, frequentlyListening == false, awake == true
2017-10-16 00:05:17.945 [DEBUG] [essage.DeleteReturnRouteMessageClass] - NODE 31: Got DeleteReturnRoute response.
2017-10-16 00:05:17.946 [DEBUG] [essage.DeleteReturnRouteMessageClass] - NODE 31: DeleteReturnRoute command started.
2017-10-16 00:05:17.953 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: TID 292: Transaction not completed
2017-10-16 00:05:18.127 [DEBUG] [essage.DeleteReturnRouteMessageClass] - NODE 31: Got DeleteReturnRoute request.
2017-10-16 00:05:18.130 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveNetworkEvent
2017-10-16 00:05:18.137 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Response processed after 218ms
2017-10-16 00:05:18.138 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: TID 292: Transaction completed
2017-10-16 00:05:18.139 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: notifyTransactionResponse TID:292 DONE
2017-10-16 00:05:18.142 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-10-16 00:05:18.143 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: -- To notify -- COMPLETE
2017-10-16 00:05:18.147 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node Init response (0) COMPLETE
2017-10-16 00:05:18.148 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node Init transaction completed with response COMPLETE
2017-10-16 00:05:18.149 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer - advancing to RETURN_ROUTES
2017-10-16 00:05:18.152 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2017-10-16 00:05:18.154 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Generate return routes list
2017-10-16 00:05:18.155 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Adding return route to 1
2017-10-16 00:05:18.157 [DEBUG] [essage.AssignReturnRouteMessageClass] - NODE 31: Assigning return route to node 1
2017-10-16 00:05:18.159 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1258f5
2017-10-16 00:05:18.160 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Adding to device queue
2017-10-16 00:05:18.161 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Added to queue - size 0
2017-10-16 00:05:18.165 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: listening == false, frequentlyListening == false, awake == true
2017-10-16 00:05:18.214 [DEBUG] [essage.AssignReturnRouteMessageClass] - NODE 31: Got AssignReturnRoute response.
2017-10-16 00:05:18.215 [DEBUG] [essage.AssignReturnRouteMessageClass] - NODE 31: AssignReturnRoute command started.
2017-10-16 00:05:18.222 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: TID 293: Transaction not completed
2017-10-16 00:05:18.958 [DEBUG] [essage.AssignReturnRouteMessageClass] - NODE 31: Got AssignReturnRoute request.
2017-10-16 00:05:18.961 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveNetworkEvent
2017-10-16 00:05:18.973 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Response processed after 798ms
2017-10-16 00:05:18.975 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: TID 293: Transaction completed
2017-10-16 00:05:18.977 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: notifyTransactionResponse TID:293 DONE
2017-10-16 00:05:18.981 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-10-16 00:05:18.983 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: -- To notify -- COMPLETE
2017-10-16 00:05:18.987 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node Init response (0) COMPLETE
2017-10-16 00:05:18.989 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node Init transaction completed with response COMPLETE
2017-10-16 00:05:18.991 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer - advancing to HEAL_END
2017-10-16 00:05:18.995 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2017-10-16 00:05:19.002 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 31: Serializing to file /var/lib/openhab2/zwave/network_fa03649c__node_31.xml
2017-10-16 00:05:19.055 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 31: Node advancer - advancing to DONE
2017-10-16 00:05:19.057 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2017-10-16 00:05:19.059 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 31: Serializing to file /var/lib/openhab2/zwave/network_fa03649c__node_31.xml
2017-10-16 00:05:26.437 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: listening == false, frequentlyListening == false, awake == true
2017-10-16 00:05:26.441 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: WakeupTimerTask 0 Messages waiting, state DONE
2017-10-16 00:05:26.447 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: WakeupTimerTask First iteration
2017-10-16 00:05:36.438 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: listening == false, frequentlyListening == false, awake == true
2017-10-16 00:05:36.440 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: WakeupTimerTask 0 Messages waiting, state DONE
2017-10-16 00:05:36.443 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: No more messages, go back to sleep
2017-10-16 00:05:36.446 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 31: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION
2017-10-16 00:05:36.452 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Encapsulating message, endpoint 0
2017-10-16 00:05:36.455 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: SECURITY NOT required on COMMAND_CLASS_WAKE_UP
2017-10-16 00:05:36.458 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Command Class COMMAND_CLASS_WAKE_UP is NOT required to be secured
2017-10-16 00:05:36.462 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@19ef9bc
2017-10-16 00:05:36.465 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Adding to device queue
2017-10-16 00:05:36.469 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: Added to queue - size 0
2017-10-16 00:05:36.474 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: listening == false, frequentlyListening == false, awake == true
2017-10-16 00:05:36.487 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 31: Sending REQUEST Message = 01 09 00 13 1F 02 84 08 25 A1 F0 
2017-10-16 00:05:36.633 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 31: sentData successfully placed on stack.
2017-10-16 00:05:36.641 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: TID 295: Transaction not completed
2017-10-16 00:05:41.645 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 31: TID 295: Timeout at state WAIT_REQUEST. 3 retries remaining.
2017-10-16 00:05:43.453 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 31: SendData Request. CallBack ID = 161, Status = Transmission complete, no ACK received(1)
2017-10-16 00:05:43.454 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 31: WAKE_UP_NO_MORE_INFORMATION. Treated as ACK.
2017-10-16 00:05:43.461 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: TID 295: Transaction not completed
2017-10-16 00:05:53.657 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 31: TID 295: Timeout at state ABORTED. 3 retries remaining.
2017-10-16 00:05:53.665 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-10-16 00:05:53.667 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: notifyTransactionResponse TID:295 CANCELLED
2017-10-16 00:05:53.675 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 31: -- To notify -- COMPLETE
2017-10-16 00:05:53.680 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Went to sleep COMPLETE

rgerrans · October 15, 2017, 8:52pm

With the newest zwave binding I’m getting the following errors showing up again. If I move back to last weeks build everything starts fine:

2017-10-15 14:43:00.703 [WARN ] [org.apache.felix.fileinstall        ] - Error while starting bundle: file:/usr/share/openhab2/addons/org.openhab.binding.zwave-2.2.0-SNAPSHOT.jar
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.zwave [10]
  Unresolved requirement: Import-Package: com.google.common.collect

	at org.eclipse.osgi.container.Module.start(Module.java:444) [?:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:383) [?:?]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1253) [8:org.apache.felix.fileinstall:3.6.0]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1225) [8:org.apache.felix.fileinstall:3.6.0]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:512) [8:org.apache.felix.fileinstall:3.6.0]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:361) [8:org.apache.felix.fileinstall:3.6.0]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:312) [8:org.apache.felix.fileinstall:3.6.0]

stevenazari · October 15, 2017, 8:57pm

Hi Matt,
Sorry I’m not helping but my suggestion was that there was no wake up request after sleep… there was an alive log though… so I’m likely wrong (I’m an openhab noob).

I think further up the chain of this thread I read that battery operated items also need to be added securely… I will search now

That’s a missing dependancy error?

sihui · October 15, 2017, 9:06pm

You don’t HAVE TO to add those devices securely. Just the locks (which solely have the secure “channels”).
The development version of the zwave binding is able to deal with secure and unsecure devices.

stevenazari · October 15, 2017, 9:16pm

ah my bad, back to the drawing board then…

rgerrans · October 16, 2017, 12:47pm

Correct, but it only appears with the latest version and not the one from a few weeks ago. @shawnmix had the same issue a while back with a different build but I never saw a specific resolution. I also can’t find any specific bindings referenced anyplace which contain the dependencies. So was wanting to see if anyone else was seeing the same issue or if it was specific to my setup.

Thanks.

rgerrans · October 16, 2017, 12:49pm

Did you figure out a specific fix for the com.google.common.collect missing dependency?

dezito · October 16, 2017, 2:37pm

I have the same problem sometimes, do the following:
ssh openhab@localhost -p8101
password: habopen
bundle:list (locate the Z-Wave plugin mine was number 10)
bundle:uninstall 10
logout
goto the addon folder and remove the jar plugin file
download the plugin again to the folder and the plugin should launch correctly no need the restart of openhab

rgerrans · October 17, 2017, 2:22am

That solved it, thanks!!

Matt77 · October 20, 2017, 8:02pm

did anyone get the Fibaro Door/Window sensor (FGK101 Door Opening Sensor) to work?
I’m getting the battery level but that’s all. no open/close status.

chris · October 20, 2017, 8:29pm

Well, it was working for me some time back. Maybe it’s broken now for some reason, but I would be surprised .

Seaside · October 20, 2017, 8:46pm

I have it working. Included two of them the other week. The channels have changed though from what they used to be 6 months back.

Regards s

Matt77 · October 21, 2017, 11:44am

HI, hmm wondering what im doing wrong then.
already excluded and re-included it.

but i have strange things in my log, including entries like “Node dead” or “Is currently marked as failed by the controller!”.
but with the non Security binding its working.
i also noticed that all my battery devices are showing as " node is not comunicating with controller" in habmin. haven’t hat that with the “non security” binding.

2017-10-21 15:38:21.029 [hingStatusInfoChangedEvent] - 'zwave:device:15f1ee0619b:node31' changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE
==> /var/log/openhab2/openhab.log <==
2017-10-21 15:38:21.035 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2017-10-21 15:38:21.039 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: COMMAND_CLASS_MULTI_CHANNEL not found
2017-10-21 15:38:21.043 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-10-21 15:38:21.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-10-21 15:38:21.049 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-10-21 15:38:21.051 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2017-10-21 15:38:49.387 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 26: Requesting IsFailedNode status from controller.
2017-10-21 15:38:49.393 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@179171e
2017-10-21 15:38:49.397 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2017-10-21 15:38:49.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
2017-10-21 15:38:49.402 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-10-21 15:38:49.405 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-10-21 15:38:49.408 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2017-10-21 15:38:49.415 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 1A 83 
2017-10-21 15:38:49.419 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 1A 83 
2017-10-21 15:38:49.423 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2017-10-21 15:38:49.425 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-10-21 15:38:49.427 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 16469: Transaction Start type IsFailedNodeID 
2017-10-21 15:38:49.430 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 16469: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.433 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2017-10-21 15:38:49.434 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-10-21 15:38:49.435 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2017-10-21 15:38:49.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2017-10-21 15:38:49.442 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Oct 21 15:38:51 GST 2017 - 2000ms
2017-10-21 15:38:49.445 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 16469: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.446 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-10-21 15:38:49.449 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-10-21 15:38:49.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-10-21 15:38:49.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 16469: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Oct 21 15:38:51 GST 2017 - 1988ms
2017-10-21 15:38:49.457 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2017-10-21 15:38:49.459 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 31: Requesting IsFailedNode status from controller.
2017-10-21 15:38:49.460 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-10-21 15:38:49.463 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@eae6b
2017-10-21 15:38:49.466 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-10-21 15:38:49.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2017-10-21 15:38:49.471 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
2017-10-21 15:38:49.473 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-10-21 15:38:49.473 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-10-21 15:38:49.475 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-10-21 15:38:49.477 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-10-21 15:38:49.480 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Oct 21 15:38:51 GST 2017 - 1961ms
2017-10-21 15:38:49.480 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 01 99 
2017-10-21 15:38:49.485 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-10-21 15:38:49.485 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-10-21 15:38:49.488 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-21 15:38:49.491 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-21 15:38:49.494 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Oct 21 15:38:51 GST 2017 - 1949ms
2017-10-21 15:38:49.497 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-21 15:38:49.498 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 16469: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.500 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2017-10-21 15:38:49.501 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 16469: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.503 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-21 15:38:49.505 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 26: Is currently marked as failed by the controller!
2017-10-21 15:38:49.506 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 16469: Transaction COMPLETED
2017-10-21 15:38:49.508 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 16469: TransactionAdvance ST: DONE
2017-10-21 15:38:49.509 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 16469: TransactionAdvance WT: null {}
2017-10-21 15:38:49.511 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 16469: TransactionAdvance RX: Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-21 15:38:49.512 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 16469: TransactionAdvance TO: DONE
2017-10-21 15:38:49.514 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 87ms
2017-10-21 15:38:49.516 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 16469: Transaction completed
2017-10-21 15:38:49.517 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:16469 DONE
2017-10-21 15:38:49.519 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-10-21 15:38:49.519 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 16469: Transaction event listener: DONE: DONE -> 
2017-10-21 15:38:49.520 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-10-21 15:38:49.522 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-10-21 15:38:49.523 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-10-21 15:38:49.524 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: -- To notify -- COMPLETE
2017-10-21 15:38:49.525 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2017-10-21 15:38:49.527 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 1F 86 
2017-10-21 15:38:49.527 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete 16469 -- 
2017-10-21 15:38:49.529 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 1F 86 
2017-10-21 15:38:49.529 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 26: Node Init response (0) COMPLETE
2017-10-21 15:38:49.531 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2017-10-21 15:38:49.531 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 26: Node Init transaction completed with response COMPLETE
2017-10-21 15:38:49.532 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 16470: Transaction Start type IsFailedNodeID 
2017-10-21 15:38:49.533 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-10-21 15:38:49.534 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 16470: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.534 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-10-21 15:38:49.535 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2017-10-21 15:38:49.536 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-10-21 15:38:49.536 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2017-10-21 15:38:49.537 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2017-10-21 15:38:49.538 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-10-21 15:38:49.538 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 01 99 
2017-10-21 15:38:49.540 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Oct 21 15:38:51 GST 2017 - 1998ms
2017-10-21 15:38:49.542 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 16470: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.543 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-10-21 15:38:49.545 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-10-21 15:38:49.545 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Oct 21 15:38:51 GST 2017 - 1993ms
2017-10-21 15:38:49.546 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-10-21 15:38:49.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 16470: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2017-10-21 15:38:49.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-21 15:38:49.550 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-10-21 15:38:49.552 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-10-21 15:38:49.552 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-21 15:38:49.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-10-21 15:38:49.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-10-21 15:38:49.558 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Oct 21 15:38:51 GST 2017 - 1980ms
2017-10-21 15:38:49.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-21 15:38:49.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 16470: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2017-10-21 15:38:49.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 16470: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.567 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-21 15:38:49.568 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 31: Is currently marked as failed by the controller!
2017-10-21 15:38:49.570 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNodeStatusEvent
2017-10-21 15:38:49.572 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2017-10-21 15:38:49.573 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Setting OFFLINE