Testing Z-Wave binding on openHAB-2

laohixdxm2016 · March 29, 2016, 6:40pm

Never mind.
I just guess from the code I mentioned above, either.

Here is my whole log.

laohixdxm2016 · March 29, 2016, 6:46pm

I will unite my messages as a single post. I thought short message with a main point is easy for readers previously. Sorry about that.

Do you mean that one single post is better than multiple posts, like 2,3 posts?

You know, sometimes a problem should have many aspects. And if I put all the information in one post including log within one post, that would be very long post. So in this case, do you still recommend single post?

Thank you.

chris · March 29, 2016, 6:47pm

Well, I don’t think there’s anything wrong with that code. It simply says that if the received message is equal to the one we’re looking for, and the transaction wasn’t already cancelled, that the transaction is complete… If you think it’s a bug, then please file an issue and we can discuss…

laohixdxm2016 · March 29, 2016, 6:53pm

You already confirm that in the previous message.

It is just a quick response for Please provide the log as I don’t know what transaction you are referring to….

laohixdxm2016 · March 29, 2016, 7:11pm

Problem:
initialization forever problem.
Below is copy from paper UI.
http://localhost:8080/ui/index.html#/configuration/things/view/zwave:aeon_dsc06_00_000:1

DSC06 Smart Energy Switch

Smart Energy Switch

Status: INITIALIZING
Channels
Electric meter (kWh)

zwave:aeon_dsc06_00_000:1:meter_kwh

Indicates the energy consumption (kWh)
Electric meter (watts)

zwave:aeon_dsc06_00_000:1:meter_watts

Indicates the instantaneous power consumption
Sensor (power)

zwave:aeon_dsc06_00_000:1:sensor_power

Indicates the energy consumption (kWh)
Switch

zwave:aeon_dsc06_00_000:1:switch_binary

Switch the light on and off

zwave debug log is below three posts,
zwave debug log part1

zwave debug log part2
https://community.openhab.org/t/testing-z-wave-binding-on-openhab-2/7522/891
zwave debug log part3
https://community.openhab.org/t/testing-z-wave-binding-on-openhab-2/7522/892

Here is my initialization problem and DEBUG log. Can you shed some light to help? Thank you very much.

laohixdxm2016 · March 29, 2016, 7:41pm

zwave debug log part1

2016-03-29 12:16:53.971 [DEBUG] [g.zwave.internal.ZWaveNetworkMonitor] - NODE 1: Network initialised - starting network monitor.
2016-03-29 12:16:53.978 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer - EMPTYNODE: queue length(0), free to send(true)
2016-03-29 12:16:53.978 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Initialisation retry timer started 5000
2016-03-29 12:16:53.978 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
2016-03-29 12:16:53.981 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer: Initialisation starting
2016-03-29 12:16:53.984 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer - advancing to PROTOINFO
2016-03-29 12:16:53.985 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-03-29 12:16:53.985 [DEBUG] [g.zwave.internal.ZWaveNetworkMonitor] - NODE 1: Network initialised - starting network monitor.
2016-03-29 12:16:53.986 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
2016-03-29 12:16:53.986 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer: PROTOINFO - send IdentifyNode
2016-03-29 12:16:53.987 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer - queued packet. Queue length is 1
2016-03-29 12:16:53.987 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2016-03-29 12:16:53.987 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2016-03-29 12:16:53.987 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 1: Init node thread finished
2016-03-29 12:16:53.991 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 01 BB 
2016-03-29 12:16:53.992 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 01 BB 
2016-03-29 12:16:53.994 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 92 16 00 02 02 01 33 
2016-03-29 12:16:53.995 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-03-29 12:16:53.995 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 01 41 92 16 00 02 02 01 33 
2016-03-29 12:16:53.995 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 01 41 92 16 00 02 02 01 33 
2016-03-29 12:16:53.995 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=IdentifyNode[0x41], type=Response[0x01], priority=High, dest=255, payload=92 16 00 02 02 01 
2016-03-29 12:16:53.996 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: ProtocolInfo
2016-03-29 12:16:53.996 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Listening = true
2016-03-29 12:16:53.996 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Routing = false
2016-03-29 12:16:53.996 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Beaming = true
2016-03-29 12:16:53.996 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Version = 3
2016-03-29 12:16:53.996 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: FLIRS = false
2016-03-29 12:16:53.996 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Security = false
2016-03-29 12:16:53.997 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Max Baud = 40000
2016-03-29 12:16:53.997 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Basic = Static Controller
2016-03-29 12:16:53.997 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Generic = Static Controller
2016-03-29 12:16:53.997 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Specific = PC Controller
2016-03-29 12:16:53.997 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Creating new instance of command class NO_OPERATION
2016-03-29 12:16:53.998 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Command class NO_OPERATION, endpoint null created
2016-03-29 12:16:53.998 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Creating new instance of command class BASIC
2016-03-29 12:16:53.998 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Command class BASIC, endpoint null created
2016-03-29 12:16:53.998 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=IdentifyNode[0x41], type=Request[0x00], priority=High, dest=255, payload=01 
2016-03-29 12:16:53.998 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=IdentifyNode[0x41], type=Response[0x01], priority=High, dest=255, payload=92 16 00 02 02 01 
2016-03-29 12:16:53.999 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=IdentifyNode, callback id=0, expected=IdentifyNode, cancelled=false        transaction complete!
2016-03-29 12:16:53.999 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-03-29 12:16:54.003 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true)
2016-03-29 12:16:54.004 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer - checking initialisation queue. Queue size 1.
2016-03-29 12:16:54.004 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer - message removed from queue. Queue size 0.
2016-03-29 12:16:54.004 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer - PROTOINFO: queue length(0), free to send(true)
2016-03-29 12:16:54.005 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Initialisation retry timer started 5000
2016-03-29 12:16:54.005 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false)
2016-03-29 12:16:54.005 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer - advancing to NEIGHBORS
2016-03-29 12:16:54.005 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-03-29 12:16:54.005 [DEBUG] [g.zwave.internal.ZWaveNetworkMonitor] - NODE 1: Network initialised - starting network monitor.
2016-03-29 12:16:54.005 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer: loop - NEIGHBORS try 0: stageAdvanced(true)
2016-03-29 12:16:54.006 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer: NEIGHBORS - send RoutingInfo
2016-03-29 12:16:54.006 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 1: Request routing info
2016-03-29 12:16:54.006 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer - queued packet. Queue length is 1
2016-03-29 12:16:54.007 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2016-03-29 12:16:54.011 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 19ms/55ms.
2016-03-29 12:16:54.011 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2016-03-29 12:16:54.012 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 80 01 00 00 03 7A 
2016-03-29 12:16:54.012 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 07 00 80 01 00 00 03 7A 
2016-03-29 12:16:54.018 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 20 01 80 40 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 1E 
2016-03-29 12:16:54.019 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-03-29 12:16:54.020 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 20 01 80 40 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 1E 
2016-03-29 12:16:54.020 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 20 01 80 40 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 1E 
2016-03-29 12:16:54.022 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=GetRoutingInfo[0x80], type=Response[0x01], priority=High, dest=255, payload=40 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2016-03-29 12:16:54.023 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 1: Got NodeRoutingInfo request.
2016-03-29 12:16:54.024 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 1: Neighbor nodes: 7
2016-03-29 12:16:54.025 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNetworkEvent
2016-03-29 12:16:54.028 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=GetRoutingInfo[0x80], type=Request[0x00], priority=High, dest=255, payload=01 00 00 03 
2016-03-29 12:16:54.029 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=GetRoutingInfo[0x80], type=Response[0x01], priority=High, dest=255, payload=40 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2016-03-29 12:16:54.030 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=GetRoutingInfo, callback id=0, expected=GetRoutingInfo, cancelled=false        transaction complete!
2016-03-29 12:16:54.031 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-03-29 12:16:54.034 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer - NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true)
2016-03-29 12:16:54.035 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer - checking initialisation queue. Queue size 1.
2016-03-29 12:16:54.036 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer - message removed from queue. Queue size 0.
2016-03-29 12:16:54.037 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer - NEIGHBORS: queue length(0), free to send(true)
2016-03-29 12:16:54.038 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Initialisation retry timer started 5000
2016-03-29 12:16:54.038 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer: loop - NEIGHBORS try 1: stageAdvanced(false)
2016-03-29 12:16:54.038 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer - advancing to FAILED_CHECK
2016-03-29 12:16:54.039 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-03-29 12:16:54.039 [DEBUG] [g.zwave.internal.ZWaveNetworkMonitor] - NODE 1: Network initialised - starting network monitor.
2016-03-29 12:16:54.039 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true)
2016-03-29 12:16:54.039 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer: FAILED_CHECK - Controller - terminating initialisation
2016-03-29 12:16:54.040 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer: loop - DONE try 0: stageAdvanced(true)
2016-03-29 12:16:54.040 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 1: Serializing to file /home/xiaomin/Downloads/openhab-offline-2.0.0-SNAPSHOT/userdata/zwave/node1.xml
2016-03-29 12:16:54.060 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 7: Restore from config: Ok.
2016-03-29 12:16:54.061 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-03-29 12:16:54.061 [DEBUG] [g.zwave.internal.ZWaveNetworkMonitor] - NODE 7: Network initialised - starting network monitor.
2016-03-29 12:16:54.062 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - EMPTYNODE: queue length(0), free to send(true)
2016-03-29 12:16:54.062 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Initialisation retry timer started 5000
2016-03-29 12:16:54.062 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
2016-03-29 12:16:54.071 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer: Initialisation starting
2016-03-29 12:16:54.071 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - advancing to PROTOINFO
2016-03-29 12:16:54.073 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-03-29 12:16:54.074 [DEBUG] [g.zwave.internal.ZWaveNetworkMonitor] - NODE 7: Network initialised - starting network monitor.
2016-03-29 12:16:54.074 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
2016-03-29 12:16:54.074 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer: PROTOINFO - send IdentifyNode
2016-03-29 12:16:54.074 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - queued packet. Queue length is 1
2016-03-29 12:16:54.075 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2016-03-29 12:16:54.075 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 7: Init node thread finished
2016-03-29 12:16:54.094 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 1: Node advancer: Initialisation complete!
2016-03-29 12:16:54.103 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-03-29 12:16:54.104 [DEBUG] [g.zwave.internal.ZWaveNetworkMonitor] - NODE 1: Network initialised - starting network monitor.
2016-03-29 12:16:54.104 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 92ms/92ms.
2016-03-29 12:16:54.104 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2016-03-29 12:16:54.104 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 07 BD 
2016-03-29 12:16:54.104 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 07 BD 
2016-03-29 12:16:54.109 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 D2 9C 00 04 10 01 ED 
2016-03-29 12:16:54.109 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-03-29 12:16:54.110 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 01 41 D2 9C 00 04 10 01 ED 
2016-03-29 12:16:54.110 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 01 41 D2 9C 00 04 10 01 ED 
2016-03-29 12:16:54.110 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=IdentifyNode[0x41], type=Response[0x01], priority=High, dest=255, payload=D2 9C 00 04 10 01 
2016-03-29 12:16:54.111 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 7: ProtocolInfo
2016-03-29 12:16:54.111 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 7: Listening = true
2016-03-29 12:16:54.112 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 7: Routing = true
2016-03-29 12:16:54.112 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 7: Beaming = true
2016-03-29 12:16:54.112 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 7: Version = 3
2016-03-29 12:16:54.112 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 7: FLIRS = false
2016-03-29 12:16:54.113 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 7: Security = false
2016-03-29 12:16:54.113 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 7: Max Baud = 40000
2016-03-29 12:16:54.113 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 7: Basic = Routing Slave
2016-03-29 12:16:54.113 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 7: Generic = Binary Switch
2016-03-29 12:16:54.113 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 7: Specific = Binary Power Switch
2016-03-29 12:16:54.114 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 7: Creating new instance of command class NO_OPERATION
2016-03-29 12:16:54.114 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 7: Command class NO_OPERATION, endpoint null created
2016-03-29 12:16:54.114 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 7: Creating new instance of command class BASIC
2016-03-29 12:16:54.114 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 7: Command class BASIC, endpoint null created
2016-03-29 12:16:54.115 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 7: Creating new instance of command class SWITCH_BINARY
2016-03-29 12:16:54.115 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 7: Command class SWITCH_BINARY, endpoint null created
2016-03-29 12:16:54.115 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=IdentifyNode[0x41], type=Request[0x00], priority=High, dest=255, payload=07 
2016-03-29 12:16:54.116 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=IdentifyNode[0x41], type=Response[0x01], priority=High, dest=255, payload=D2 9C 00 04 10 01 
2016-03-29 12:16:54.116 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=IdentifyNode, callback id=0, expected=IdentifyNode, cancelled=false        transaction complete!
2016-03-29 12:16:54.116 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-03-29 12:16:54.116 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true)
2016-03-29 12:16:54.117 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - checking initialisation queue. Queue size 1.
2016-03-29 12:16:54.117 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - message removed from queue. Queue size 0.
2016-03-29 12:16:54.117 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - PROTOINFO: queue length(0), free to send(true)
2016-03-29 12:16:54.117 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Initialisation retry timer started 5000
2016-03-29 12:16:54.118 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false)
2016-03-29 12:16:54.118 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - advancing to NEIGHBORS
2016-03-29 12:16:54.118 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-03-29 12:16:54.119 [DEBUG] [g.zwave.internal.ZWaveNetworkMonitor] - NODE 7: Network initialised - starting network monitor.
2016-03-29 12:16:54.119 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer: loop - NEIGHBORS try 0: stageAdvanced(true)
2016-03-29 12:16:54.119 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer: NEIGHBORS - send RoutingInfo
2016-03-29 12:16:54.120 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 7: Request routing info
2016-03-29 12:16:54.120 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - queued packet. Queue length is 1
2016-03-29 12:16:54.120 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2016-03-29 12:16:54.121 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 15ms/92ms.
2016-03-29 12:16:54.121 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2016-03-29 12:16:54.121 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 80 07 00 00 03 7C 
2016-03-29 12:16:54.121 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 07 00 80 07 00 00 03 7C 
2016-03-29 12:16:54.127 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 20 01 80 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 5F 
2016-03-29 12:16:54.128 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-03-29 12:16:54.128 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 20 01 80 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 5F 
2016-03-29 12:16:54.128 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 20 01 80 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 5F 
2016-03-29 12:16:54.128 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=GetRoutingInfo[0x80], type=Response[0x01], priority=High, dest=255, payload=01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2016-03-29 12:16:54.128 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 7: Got NodeRoutingInfo request.
2016-03-29 12:16:54.128 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 7: Neighbor nodes: 1
2016-03-29 12:16:54.128 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNetworkEvent
2016-03-29 12:16:54.129 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=GetRoutingInfo[0x80], type=Request[0x00], priority=High, dest=255, payload=07 00 00 03 
2016-03-29 12:16:54.129 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=GetRoutingInfo[0x80], type=Response[0x01], priority=High, dest=255, payload=01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2016-03-29 12:16:54.129 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=GetRoutingInfo, callback id=0, expected=GetRoutingInfo, cancelled=false        transaction complete!
2016-03-29 12:16:54.129 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-03-29 12:16:54.129 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true)
2016-03-29 12:16:54.129 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - checking initialisation queue. Queue size 1.
2016-03-29 12:16:54.129 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - message removed from queue. Queue size 0.
2016-03-29 12:16:54.129 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - NEIGHBORS: queue length(0), free to send(true)
2016-03-29 12:16:54.129 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Initialisation retry timer started 5000
2016-03-29 12:16:54.129 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer: loop - NEIGHBORS try 1: stageAdvanced(false)
2016-03-29 12:16:54.130 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - advancing to FAILED_CHECK
2016-03-29 12:16:54.130 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-03-29 12:16:54.130 [DEBUG] [g.zwave.internal.ZWaveNetworkMonitor] - NODE 7: Network initialised - starting network monitor.
2016-03-29 12:16:54.130 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true)
2016-03-29 12:16:54.130 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 7: Requesting IsFailedNode status from controller.
2016-03-29 12:16:54.131 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - queued packet. Queue length is 1
2016-03-29 12:16:54.131 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2016-03-29 12:16:54.131 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 10ms/92ms.
2016-03-29 12:16:54.131 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2016-03-29 12:16:54.131 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 07 9E 
2016-03-29 12:16:54.132 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 07 9E 
2016-03-29 12:16:54.135 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 00 98 
2016-03-29 12:16:54.139 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-03-29 12:16:54.139 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 62 00 98 
2016-03-29 12:16:54.139 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 62 00 98 
2016-03-29 12:16:54.139 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=IsFailedNodeID[0x62], type=Response[0x01], priority=High, dest=255, payload=00 
2016-03-29 12:16:54.140 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 7: Is currently marked as healthy by the controller
2016-03-29 12:16:54.140 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=IsFailedNodeID[0x62], type=Request[0x00], priority=High, dest=255, payload=07 
2016-03-29 12:16:54.140 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=IsFailedNodeID[0x62], type=Response[0x01], priority=High, dest=255, payload=00 
2016-03-29 12:16:54.140 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=IsFailedNodeID, callback id=0, expected=IsFailedNodeID, cancelled=false        transaction complete!
2016-03-29 12:16:54.140 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-03-29 12:16:54.140 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - FAILED_CHECK: Transaction complete (IsFailedNodeID:Request) success(true)
2016-03-29 12:16:54.141 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - checking initialisation queue. Queue size 1.
2016-03-29 12:16:54.141 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - message removed from queue. Queue size 0.
2016-03-29 12:16:54.141 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - FAILED_CHECK: queue length(0), free to send(true)
2016-03-29 12:16:54.141 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Initialisation retry timer started 5000
2016-03-29 12:16:54.141 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer: loop - FAILED_CHECK try 1: stageAdvanced(false)
2016-03-29 12:16:54.141 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - advancing to WAIT
2016-03-29 12:16:54.141 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-03-29 12:16:54.142 [DEBUG] [g.zwave.internal.ZWaveNetworkMonitor] - NODE 7: Network initialised - starting network monitor.
2016-03-29 12:16:54.142 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer: loop - WAIT try 0: stageAdvanced(true)
2016-03-29 12:16:54.142 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer: WAIT - Listening=true, FrequentlyListening=false
2016-03-29 12:16:54.142 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer: WAIT - Advancing
2016-03-29 12:16:54.142 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - advancing to PING
2016-03-29 12:16:54.142 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-03-29 12:16:54.142 [DEBUG] [g.zwave.internal.ZWaveNetworkMonitor] - NODE 7: Network initialised - starting network monitor.
2016-03-29 12:16:54.142 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer: loop - PING try 0: stageAdvanced(true)
2016-03-29 12:16:54.143 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer: PING - send NoOperation
2016-03-29 12:16:54.143 [DEBUG] [ndclass.ZWaveNoOperationCommandClass] - NODE 7: Creating new message for command No Operation
2016-03-29 12:16:54.143 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 7: Node advancer - queued packet. Queue length is 1

chris · March 29, 2016, 7:56pm

It’s very difficult to look over such long logs that are pasted like this into a forum. I’d recommend pasting them somewhere and only linking it in the forum. So, I can’t really look over the log in any detail, however, I thought that the problem was the device didn’t initialise? In this log, which only lasts about 5 seconds, the device is completely initialised so I don’t understand what the problem is.

laohixdxm2016 · March 29, 2016, 8:48pm

Hi chris, thank you for your information and sugguestion.

Thank you for pointing out “Initialisation complete” message.
I even ignore such important log message.
The problem is initialization state forever in paperUI. More details below.

[FOLLOW UP]
As in paper UI, zwave:aeon_dsc06_00_000:1’s state stay initialization forever.
So it comes up with another problem, the log is,
No delegation command ‘OFF’ for item ‘Z_socket1’ to handle for channel
’zwave:aeon_dsc06_00_000:1:switch’, because thing is not initialized (must be in status ONLINE or OFFLINE)
When I switch the button on the web GUI, I got the log above.

Do you have some idea or suggestion about that? Thank you very much.

For your reference, here is the link for the log,
Here is zwave DEBUG log,
http://laohixdxm2016.weebly.com/zwave-debug.html

Here is zwave ERROR log,

chris · March 29, 2016, 9:02pm

How are you initialising the device? Is this done through HABmin, or PaperUI, or text files. It looks to me like something isn’t configured correctly, which shouldn’t be possible if it was done through the system. If you’re using text files, then I suspect something is amiss there?

laohixdxm2016 · March 29, 2016, 10:04pm

Hi chris,

Mostly, I use text files.
Here is my text files setting.

I believe at that time, the initialization problem exists.

Paper UI, mostly I just use to check the status of thing/item/binding.

I did use Habmin2 about two days ago.
But the only thing I do is to create zstick_serial from zwave binding.
I only set port as /dev/ttyUSB0 for it.
After that, I do not see any difference for the initialization problem.

In addition, within Habmin2, the zwave:aeon_dsc006_00_000 is with gear instead of tick.
zstick_serial which shown online as status in paperUI is with tick in Habmin2.

Hopefully you have some idea for the problem by these information. Please let me know if you need more information. Thank you very much.

chris · March 29, 2016, 10:10pm

I am not really an expert in the configuration of the text files (I’ve never used it) but to me it looks like you don’t have the node set. This would be a major problem, and likely the cause of your issues. So, I suspect that if you used HABmin, this would work. We know that the protocol is working fine - we’re communicating with the device perfectly, but something is not configured in the thing.

I also see this in the log which I think confirms my theory -:

2016-03-29 12:14:00.207 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NodeID is not set in zwave:aeon_dsc06_00_000:1

laohixdxm2016 · March 29, 2016, 10:40pm

Great thanks, chris, for mentioning device discovery.
Previously, I totally have no idea there is such a entry in Habmin.

chris · March 29, 2016, 10:46pm

Surely you must agree that this is an error with your configuration - not the software? This is not a problem others have, so I really suggest that you look at the configuration, or use a UI (eg HABmin) to configure the system!

Well it’s clearly not a good idea to have to hard code all your node IDs into the binding. I really suggest that you look at the configuration.

Please use device discovery to include other devices. They will be added to the inbox and you can create the things from there. The UI is not designed to allow them to be added manually which is why only the controller is shown in the list.

laohixdxm2016 · March 29, 2016, 11:09pm

Great thanks, chris.
I didnt realize there Habmin can do device discovery.

So for now, I have discovered the device.
How can I send a binary switch command to the device?
I think there may be some Habmin operation to do that as in text files.

Can you give some suggestions for that? Thank you.

chris · March 29, 2016, 11:13pm

Once a device is included, then you can use it like any other device in OH. So, you will need to create an item, and then a sitemap. In the sitemap you need to create a switch that uses the item, and this will automatically send the appropriate commands to the zwave device.

laohixdxm2016 · March 29, 2016, 11:13pm

polling Runnable only schedule once problem

** pollingJob = scheduler.scheduleAtFixedRate(pollingRunnable, initialPeriod, pollingPeriod * 1000,**
** TimeUnit.MILLISECONDS);**

For here, I notice polling Runnable should be scheduled periodically.

However, I notice in my log that, it only be schedule once.

I even could not see any DEBUG log I have put in. Yes, for debug purpose, I modify 1800s as 15s.

Here is my log,
./openhab.log:2016-03-28
19:18:22.071 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7:
Polling intialised at 15 seconds - start in 15000 milliseconds.
./openhab.log:2016-03-28 19:18:37.072 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling…
./openhab.log:2016-03-28 19:18:37.072 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling***

Is it a normal thing? Or something critical we need to take care of?
Thank you.

chris · March 29, 2016, 11:16pm

Well, polling I think is working fine in my environment (at least it was recently - I’ve not checked it tonight). You log doesn’t really show that it’s not working, and the code that you post is scheduling it up to run periodically, so there’s no reason that it should only run once.

chris · March 29, 2016, 11:20pm

I have confirmed polling is working fine!

23:17:12.435 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Configuration update received
23:17:12.486 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Configuration update binding_pollperiod to 15
23:17:12.487 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling intialised at 15 seconds - start in 15000 milliseconds.
23:17:27.487 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling...
23:17:27.487 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:1531045fdae:node2:switch_dimmer
23:17:42.487 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling...
23:17:42.487 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:1531045fdae:node2:switch_dimmer

laohixdxm2016 · March 29, 2016, 11:26pm

Thank you, chris.

For this part, do I need to do in paper UI or Habmin?
I can NOT manage to find entry for that in paper UI or Habmin.

Can you provide a little bit more operation details?
I am really a novice for the web operation.
As you see, I even could not find the Habmin entry for device discovery.

Thank you.

laohixdxm2016 · March 29, 2016, 11:33pm

Thank you for confirming.

It works for me now, also

> 2016-03-29 16:31:39.852 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling zwave:device:153bea5a84f:node7:meter_kwh
> 2016-03-29 16:31:39.853 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling zwave:device:153bea5a84f:node7:meter_watts
> 2016-03-29 16:31:39.853 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling zwave:device:153bea5a84f:node7:sensor_power
> 2016-03-29 16:31:39.854 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling zwave:device:153bea5a84f:node7:switch_binary
> 2016-03-29 16:31:41.217 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling...
> 2016-03-29 16:31:54.851 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling...
> 2016-03-29 16:31:54.852 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling zwave:device:153bea5a84f:node7:meter_kwh
> 2016-03-29 16:31:54.852 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling zwave:device:153bea5a84f:node7:meter_watts
> 2016-03-29 16:31:54.852 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling zwave:device:153bea5a84f:node7:sensor_power
> 2016-03-29 16:31:54.853 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling zwave:device:153bea5a84f:node7:switch_binary
> 2016-03-29 16:32:09.851 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling...
> 2016-03-29 16:32:09.851 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling zwave:device:153bea5a84f:node7:meter_kwh
> 2016-03-29 16:32:09.852 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling zwave:device:153bea5a84f:node7:meter_watts
> 2016-03-29 16:32:09.852 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling zwave:device:153bea5a84f:node7:sensor_power
> 2016-03-29 16:32:09.853 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling zwave:device:153bea5a84f:node7:switch_binary