Zwave with Razberry2 Unkown Device

Scotsman · July 14, 2018, 9:30am

Do you think there is something wrong with my installation?

Its the 2.4 snapshot from Thursday. The zwave binding was uninstall and reinstalled last night.

These are common devices that shouldn’t be giving problems.

Thanks for any help

Scotsman · July 14, 2018, 10:00am

Hi Chris,

This is the degug log for when I wake up a Neo Coolcam motion sensor;

2018-07-14 10:56:31.588 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 16 00 49 84 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84 6F 

2018-07-14 10:56:31.629 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0

2018-07-14 10:56:31.640 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 16 00 49 84 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84 6F 

2018-07-14 10:56:31.648 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 16 00 49 84 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84 6F 

2018-07-14 10:56:31.658 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, callback=0, payload=84 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84 

2018-07-14 10:56:31.662 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 2: Application update request. Node information received.

2018-07-14 10:56:31.665 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Is awake with 2 messages in the wake-up queue.

2018-07-14 10:56:31.669 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveWakeUpEvent

2018-07-14 10:56:31.672 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Wakeup during initialisation.

2018-07-14 10:56:31.676 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - PING: queue length(1), free to send(false)

2018-07-14 10:56:31.680 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 1

2018-07-14 10:56:31.683 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0

2018-07-14 10:56:31.689 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 0. Queue={}

2018-07-14 10:56:31.691 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 02 01 00 25 4D 8F 

2018-07-14 10:56:31.693 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}

2018-07-14 10:56:31.697 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 08 00 13 02 01 00 25 4D 8F 

2018-07-14 10:56:31.697 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=7, callback=76, payload=07 02 84 08 

2018-07-14 10:56:31.706 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, callback=0, payload=84 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84 

2018-07-14 10:56:31.709 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2018-07-14 10:56:31.709 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationUpdate, callback id=76, expected=SendData, cancelled=false      MISMATCH

2018-07-14 10:56:31.759 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0

2018-07-14 10:56:31.761 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 4D 00 00 02 A4 

2018-07-14 10:56:31.761 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 

2018-07-14 10:56:31.764 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 

2018-07-14 10:56:31.767 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 

2018-07-14 10:56:31.769 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.

2018-07-14 10:56:31.789 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0

2018-07-14 10:56:31.792 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 4D 00 00 02 00 00 AA 

2018-07-14 10:56:31.795 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 4D 00 00 02 00 00 AA 

2018-07-14 10:56:31.798 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=4D 00 00 02 

2018-07-14 10:56:31.801 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 77, Status = Transmission complete and ACK received(0)

2018-07-14 10:56:31.803 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Poll, dest=2, callback=77, payload=02 01 00 

2018-07-14 10:56:31.806 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=4D 00 00 02 

2018-07-14 10:56:31.808 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=77, expected=SendData, cancelled=false        transaction complete!

2018-07-14 10:56:31.810 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent

2018-07-14 10:56:31.812 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - PING: Transaction complete (SendData:Request) success(true)

2018-07-14 10:56:31.814 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 1.

2018-07-14 10:56:31.815 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - message removed from queue. Queue size 0.

2018-07-14 10:56:31.817 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - PING: queue length(0), free to send(true)

2018-07-14 10:56:31.819 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - PING try 2: stageAdvanced(false)

2018-07-14 10:56:31.821 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to DETAILS

2018-07-14 10:56:31.823 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent

2018-07-14 10:56:31.825 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - DETAILS try 0: stageAdvanced(true)

2018-07-14 10:56:31.827 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: received RequestNodeInfo

2018-07-14 10:56:31.830 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to INCLUSION_START

2018-07-14 10:56:31.832 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent

2018-07-14 10:56:31.834 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - INCLUSION_START try 0: stageAdvanced(true)

2018-07-14 10:56:31.836 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: Unknown node state INCLUSION_START encountered.

2018-07-14 10:56:31.838 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to IDENTIFY_NODE

2018-07-14 10:56:31.840 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent

2018-07-14 10:56:31.842 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - IDENTIFY_NODE try 0: stageAdvanced(true)

2018-07-14 10:56:31.844 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: PROTOINFO - send IdentifyNode

2018-07-14 10:56:31.847 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 1

2018-07-14 10:56:31.849 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}

2018-07-14 10:56:31.851 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 3. Queue={}

2018-07-14 10:56:31.854 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Response processed after 124ms/213ms.

2018-07-14 10:56:31.855 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 2

2018-07-14 10:56:31.858 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 02 01 00 25 4F 8D 

2018-07-14 10:56:31.861 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 08 00 13 02 01 00 25 4F 8D 

2018-07-14 10:56:31.870 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2018-07-14 10:56:31.919 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0

2018-07-14 10:56:31.921 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 4F 00 00 02 A6 

2018-07-14 10:56:31.921 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 

2018-07-14 10:56:31.924 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 

2018-07-14 10:56:31.926 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 

2018-07-14 10:56:31.928 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.

2018-07-14 10:56:31.949 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0

2018-07-14 10:56:31.951 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 4F 00 00 02 00 00 A8 

2018-07-14 10:56:31.954 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 4F 00 00 02 00 00 A8 

2018-07-14 10:56:31.956 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=4F 00 00 02 

2018-07-14 10:56:31.958 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 79, Status = Transmission complete and ACK received(0)

2018-07-14 10:56:31.961 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=2, callback=79, payload=02 01 00 

2018-07-14 10:56:31.963 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=4F 00 00 02 

2018-07-14 10:56:31.965 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=79, expected=SendData, cancelled=false        transaction complete!

2018-07-14 10:56:31.966 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent

2018-07-14 10:56:31.968 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - IDENTIFY_NODE: Transaction complete (SendData:Request) success(true)

2018-07-14 10:56:31.970 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 1.

2018-07-14 10:56:31.972 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Response processed after 83ms/213ms.

2018-07-14 10:56:31.973 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1

2018-07-14 10:56:31.976 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 02 02 84 08 25 4E 02 

2018-07-14 10:56:31.981 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 09 00 13 02 02 84 08 25 4E 02 

2018-07-14 10:56:31.990 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2018-07-14 10:56:32.039 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0

2018-07-14 10:56:32.040 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 4E 00 00 02 A7 

2018-07-14 10:56:32.041 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 

2018-07-14 10:56:32.043 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 

2018-07-14 10:56:32.046 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 

2018-07-14 10:56:32.048 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.

2018-07-14 10:56:32.069 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0

2018-07-14 10:56:32.072 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 4E 00 00 02 00 00 A9 

2018-07-14 10:56:32.074 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 4E 00 00 02 00 00 A9 

2018-07-14 10:56:32.077 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=4E 00 00 02 

2018-07-14 10:56:32.078 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 78, Status = Transmission complete and ACK received(0)

2018-07-14 10:56:32.081 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=2, callback=78, payload=02 02 84 08 

2018-07-14 10:56:32.083 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=4E 00 00 02 

2018-07-14 10:56:32.085 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=78, expected=SendData, cancelled=false        transaction complete!

2018-07-14 10:56:32.087 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent

2018-07-14 10:56:32.088 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - IDENTIFY_NODE: Transaction complete (SendData:Request) success(true)

2018-07-14 10:56:32.090 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 1.

2018-07-14 10:56:32.092 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Went to sleep

2018-07-14 10:56:32.094 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Is sleeping

2018-07-14 10:56:32.096 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Response processed after 87ms/213ms.

2018-07-14 10:56:32.097 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0

2018-07-14 10:56:32.100 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 02 B8 

2018-07-14 10:56:32.102 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 02 B8 

2018-07-14 10:56:32.106 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 53 9C 01 04 07 01 7A 

2018-07-14 10:56:32.159 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0

2018-07-14 10:56:32.161 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 01 41 53 9C 01 04 07 01 7A 

2018-07-14 10:56:32.164 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 01 41 53 9C 01 04 07 01 7A 

2018-07-14 10:56:32.166 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=IdentifyNode[0x41], type=Response[0x01], priority=High, dest=255, callback=0, payload=53 9C 01 04 07 01 

2018-07-14 10:56:32.168 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: ProtocolInfo

2018-07-14 10:56:32.170 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Listening = false

2018-07-14 10:56:32.172 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Routing = true

2018-07-14 10:56:32.173 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Beaming = true

2018-07-14 10:56:32.176 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Version = 4

2018-07-14 10:56:32.177 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: FLIRS = false

2018-07-14 10:56:32.179 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Security = false

2018-07-14 10:56:32.181 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Max Baud = 40000

2018-07-14 10:56:32.183 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Basic = Routing Slave

2018-07-14 10:56:32.185 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Generic = Sensor Notification

2018-07-14 10:56:32.188 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Specific = Notification Sensor

2018-07-14 10:56:32.190 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Creating new instance of command class NO_OPERATION

2018-07-14 10:56:32.192 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class NO_OPERATION, endpoint null created

2018-07-14 10:56:32.195 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Version = 1, version set. Enabling extra functionality.

2018-07-14 10:56:32.196 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Creating new instance of command class BASIC

2018-07-14 10:56:32.198 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class BASIC, endpoint null created

2018-07-14 10:56:32.201 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=IdentifyNode[0x41], type=Request[0x00], priority=High, dest=255, callback=0, payload=02 

2018-07-14 10:56:32.204 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=IdentifyNode[0x41], type=Response[0x01], priority=High, dest=255, callback=0, payload=53 9C 01 04 07 01 

2018-07-14 10:56:32.206 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=IdentifyNode, callback id=0, expected=IdentifyNode, cancelled=false        transaction complete!

2018-07-14 10:56:32.207 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent

2018-07-14 10:56:32.209 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - IDENTIFY_NODE: Transaction complete (IdentifyNode:Request) success(true)

2018-07-14 10:56:32.211 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 1.

2018-07-14 10:56:32.213 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - message removed from queue. Queue size 0.

2018-07-14 10:56:32.215 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - IDENTIFY_NODE: queue length(0), free to send(true)

2018-07-14 10:56:32.217 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - IDENTIFY_NODE try 1: stageAdvanced(false)

2018-07-14 10:56:32.219 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to MANUFACTURER

2018-07-14 10:56:32.221 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent

2018-07-14 10:56:32.224 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - MANUFACTURER try 0: stageAdvanced(true)

2018-07-14 10:56:32.226 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: MANUFACTURER - send ManufacturerSpecific

2018-07-14 10:56:32.228 [DEBUG] [WaveManufacturerSpecificCommandClass] - NODE 2: Creating new message for command MANUFACTURER_SPECIFIC_GET

2018-07-14 10:56:32.230 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 1

2018-07-14 10:56:32.233 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Putting message SendData in wakeup queue.

2018-07-14 10:56:32.235 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Putting message SendData in wakeup queue.

2018-07-14 10:56:32.238 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 108ms/213ms.

chris · July 14, 2018, 11:11am

What happens if you wake up the device? It looks like the binding is waiting for it to wake so that it can retrieve the manufacturer information.

(ps. please use code fences, or format using the </> button so that the logs are nicely formatted .)

Scotsman · July 14, 2018, 11:54am

Hi Chris

Can you tell me how the format rhe log. I don’t know how to code fence it and not sure how to use the </> button.

I am seeing a lot of MISMATCH entries
2018-07-14 12:55:04.253 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 04 30 03 FF 0C

2018-07-14 12:55:04.255 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=71, expected=SendData, cancelled=false MISMATCH

chris · July 14, 2018, 12:12pm

Well, the </> button is super simple - just highlight the log, and click the </> button.

This is not an error of any sort - it’s only a debug message.

sihui · July 14, 2018, 1:45pm

Scotsman · July 14, 2018, 2:18pm

This is what is output when I click the wake up button;

==> /var/log/openhab2/openhab.log <==

2018-07-14 15:15:13.448 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0F 00 04 00 02 09 71 05 00 00 00 FF 07 08 00 7B 

2018-07-14 15:15:13.479 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0

2018-07-14 15:15:13.483 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 02 04 30 03 FF 0C 37 

2018-07-14 15:15:13.487 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0F 00 04 00 02 09 71 05 00 00 00 FF 07 08 00 7B 

2018-07-14 15:15:13.493 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0F 00 04 00 02 09 71 05 00 00 00 FF 07 08 00 7B 

2018-07-14 15:15:13.498 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 09 71 05 00 00 00 FF 07 08 00 

2018-07-14 15:15:13.501 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:DONE)

2018-07-14 15:15:13.505 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from DONE

2018-07-14 15:15:13.508 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@80180 already registered

2018-07-14 15:15:13.511 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class ALARM

2018-07-14 15:15:13.514 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 2: Received ALARM command V8

2018-07-14 15:15:13.517 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 2: Process NOTIFICATION_REPORT V8

2018-07-14 15:15:13.520 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 2: NOTIFICATION report - 0 = 0, event=8, status=255

2018-07-14 15:15:13.523 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 2: Alarm Type = BURGLAR (0)

2018-07-14 15:15:13.527 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveAlarmValueEvent

2018-07-14 15:15:13.530 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 7: Transaction not completed: node address inconsistent.  lastSent=7, incoming=255

2018-07-14 15:15:13.533 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0

2018-07-14 15:15:13.538 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 04 00 02 04 30 03 FF 0C 37 

2018-07-14 15:15:13.543 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0A 00 04 00 02 04 30 03 FF 0C 37 

2018-07-14 15:15:13.548 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 04 30 03 FF 0C 

2018-07-14 15:15:13.551 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:DONE)

2018-07-14 15:15:13.554 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from DONE

2018-07-14 15:15:13.557 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@80180 already registered

2018-07-14 15:15:13.560 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class SENSOR_BINARY

2018-07-14 15:15:13.562 [DEBUG] [dclass.ZWaveBinarySensorCommandClass] - NODE 2: Received SENSOR_BINARY command V2

2018-07-14 15:15:13.565 [DEBUG] [dclass.ZWaveBinarySensorCommandClass] - Processing Sensor Type 12

2018-07-14 15:15:13.568 [DEBUG] [dclass.ZWaveBinarySensorCommandClass] - Sensor Type is MOTION

2018-07-14 15:15:13.571 [DEBUG] [dclass.ZWaveBinarySensorCommandClass] - NODE 2: Sensor Binary report, type=Motion, value=255

2018-07-14 15:15:13.574 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveBinarySensorValueEvent

2018-07-14 15:15:13.577 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 7: Transaction not completed: node address inconsistent.  lastSent=7, incoming=255

2018-07-14 15:15:16.340 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 02 02 84 07 70 

2018-07-14 15:15:16.369 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0

2018-07-14 15:15:16.374 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 00 02 02 84 07 70 

2018-07-14 15:15:16.379 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 00 02 02 84 07 70 

2018-07-14 15:15:16.385 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 02 84 07 

2018-07-14 15:15:16.389 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:DONE)

2018-07-14 15:15:16.393 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from DONE

2018-07-14 15:15:16.397 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@80180 already registered

2018-07-14 15:15:16.402 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class WAKE_UP

2018-07-14 15:15:16.406 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Received Wake Up Request

2018-07-14 15:15:16.410 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Received WAKE_UP_NOTIFICATION

2018-07-14 15:15:16.415 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Is awake with 0 messages in the wake-up queue.

2018-07-14 15:15:16.419 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveWakeUpEvent

2018-07-14 15:15:16.422 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 7: Transaction not completed: node address inconsistent.  lastSent=7, incoming=255

2018-07-14 15:15:17.423 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: No more messages, go back to sleep

2018-07-14 15:15:17.426 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION

2018-07-14 15:15:17.431 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}

2018-07-14 15:15:17.431 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0

2018-07-14 15:15:17.437 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 02 02 84 08 25 5A 16 

2018-07-14 15:15:17.442 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 09 00 13 02 02 84 08 25 5A 16 

2018-07-14 15:15:17.453 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2018-07-14 15:15:17.499 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0

2018-07-14 15:15:17.503 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 5A 00 00 02 B3 

2018-07-14 15:15:17.504 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 

2018-07-14 15:15:17.507 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 

2018-07-14 15:15:17.512 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 

2018-07-14 15:15:17.516 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.

2018-07-14 15:15:17.529 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0

2018-07-14 15:15:17.534 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 5A 00 00 02 00 00 BD 

2018-07-14 15:15:17.538 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 5A 00 00 02 00 00 BD 

2018-07-14 15:15:17.542 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=5A 00 00 02 

2018-07-14 15:15:17.545 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 90, Status = Transmission complete and ACK received(0)

2018-07-14 15:15:17.548 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from DONE

2018-07-14 15:15:17.551 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@80180 already registered

2018-07-14 15:15:17.555 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=2, callback=90, payload=02 02 84 08 

2018-07-14 15:15:17.559 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=5A 00 00 02 

2018-07-14 15:15:17.562 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=90, expected=SendData, cancelled=false        transaction complete!

2018-07-14 15:15:17.565 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent

2018-07-14 15:15:17.568 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Went to sleep

2018-07-14 15:15:17.571 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Is sleeping

2018-07-14 15:15:17.574 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Response processed after 105ms/4210ms.

Scotsman · July 14, 2018, 2:19pm

Thanks I’ll give that a read

Scotsman · July 16, 2018, 5:05pm

Day 3 Still all devices are listed as unknown.

Here is what is logged when I wake up my Heiman smoke detector;

2018-07-16 18:03:29.602 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 04 03 80 03 58 2E 

2018-07-16 18:03:29.632 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0

2018-07-16 18:03:29.636 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 04 03 80 03 58 2E 

2018-07-16 18:03:29.639 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 04 03 80 03 58 2E 

2018-07-16 18:03:29.642 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 03 80 03 58 

2018-07-16 18:03:29.645 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 4: Application Command Request (ALIVE:DONE)

2018-07-16 18:03:29.648 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 4: Starting initialisation from DONE

2018-07-16 18:03:29.650 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@1013cd already registered

2018-07-16 18:03:29.653 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 4: Incoming command class BATTERY

2018-07-16 18:03:29.656 [DEBUG] [ommandclass.ZWaveBatteryCommandClass] - NODE 4: Received Battery Request

2018-07-16 18:03:29.658 [DEBUG] [ommandclass.ZWaveBatteryCommandClass] - NODE 4: Battery report value = 88

2018-07-16 18:03:29.660 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent

2018-07-16 18:03:29.664 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=4, callback=62, payload=04 02 84 08 

2018-07-16 18:03:29.668 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 03 80 03 58 

2018-07-16 18:03:29.671 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=62, expected=SendData, cancelled=false      MISMATCH

2018-07-16 18:03:32.615 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 04 03 80 03 50 26 

==> /var/log/openhab2/events.log <==

2018-07-16 18:03:32.624 [vent.ItemStateChangedEvent] - zwave_serial_zstick_657f1a0f_serial_sof changed from 437 to 438

==> /var/log/openhab2/openhab.log <==

2018-07-16 18:03:32.642 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0

2018-07-16 18:03:32.645 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 04 03 80 03 50 26 

2018-07-16 18:03:32.647 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 04 03 80 03 50 26 

2018-07-16 18:03:32.650 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 03 80 03 50 

2018-07-16 18:03:32.652 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 4: Application Command Request (ALIVE:DONE)

2018-07-16 18:03:32.654 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 4: Starting initialisation from DONE

2018-07-16 18:03:32.656 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@1013cd already registered

2018-07-16 18:03:32.658 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 4: Incoming command class BATTERY

2018-07-16 18:03:32.661 [DEBUG] [ommandclass.ZWaveBatteryCommandClass] - NODE 4: Received Battery Request

2018-07-16 18:03:32.663 [DEBUG] [ommandclass.ZWaveBatteryCommandClass] - NODE 4: Battery report value = 80

2018-07-16 18:03:32.665 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent

2018-07-16 18:03:32.668 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=4, callback=62, payload=04 02 84 08 

2018-07-16 18:03:32.672 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 03 80 03 50 

2018-07-16 18:03:32.674 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=62, expected=SendData, cancelled=false      MISMATCH

2018-07-16 18:03:35.631 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 04 02 84 07 76 

==> /var/log/openhab2/events.log <==

2018-07-16 18:03:35.637 [vent.ItemStateChangedEvent] - zwave_serial_zstick_657f1a0f_serial_sof changed from 438 to 439

==> /var/log/openhab2/openhab.log <==

2018-07-16 18:03:35.662 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0

2018-07-16 18:03:35.666 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 00 04 02 84 07 76 

2018-07-16 18:03:35.670 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 00 04 02 84 07 76 

2018-07-16 18:03:35.673 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 84 07 

2018-07-16 18:03:35.675 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 4: Application Command Request (ALIVE:DONE)

2018-07-16 18:03:35.678 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 4: Starting initialisation from DONE

2018-07-16 18:03:35.680 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@1013cd already registered

2018-07-16 18:03:35.683 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 4: Incoming command class WAKE_UP

2018-07-16 18:03:35.685 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 4: Received Wake Up Request

2018-07-16 18:03:35.687 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 4: Received WAKE_UP_NOTIFICATION

2018-07-16 18:03:35.690 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 4: Is awake with 0 messages in the wake-up queue.

2018-07-16 18:03:35.693 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveWakeUpEvent

2018-07-16 18:03:35.696 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=4, callback=62, payload=04 02 84 08 

2018-07-16 18:03:35.699 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 84 07 

2018-07-16 18:03:35.702 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=62, expected=SendData, cancelled=true      MISMATCH

2018-07-16 18:03:36.695 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 4: No more messages, go back to sleep

2018-07-16 18:03:36.698 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 4: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION

2018-07-16 18:03:36.700 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}

2018-07-16 18:03:36.700 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0

2018-07-16 18:03:36.704 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 04 02 84 08 25 3F 75 

2018-07-16 18:03:36.707 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 4: Sending REQUEST Message = 01 09 00 13 04 02 84 08 25 3F 75 

==> /var/log/openhab2/events.log <==

2018-07-16 18:03:36.718 [vent.ItemStateChangedEvent] - zwave_serial_zstick_657f1a0f_serial_ack changed from 254 to 255

2018-07-16 18:03:36.727 [vent.ItemStateChangedEvent] - zwave_serial_zstick_657f1a0f_serial_sof changed from 439 to 440

==> /var/log/openhab2/openhab.log <==

2018-07-16 18:03:36.729 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2018-07-16 18:03:36.762 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0

2018-07-16 18:03:36.764 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 

2018-07-16 18:03:36.767 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 

2018-07-16 18:03:36.769 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 

2018-07-16 18:03:36.772 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: Sent Data successfully placed on stack.

==> /var/log/openhab2/events.log <==

2018-07-16 18:03:36.781 [vent.ItemStateChangedEvent] - zwave_serial_zstick_657f1a0f_serial_sof changed from 440 to 441

==> /var/log/openhab2/openhab.log <==

2018-07-16 18:03:36.784 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 3F 00 00 02 D6 

2018-07-16 18:03:36.812 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0

2018-07-16 18:03:36.816 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 3F 00 00 02 00 00 D8 

2018-07-16 18:03:36.819 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 3F 00 00 02 00 00 D8 

2018-07-16 18:03:36.823 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=3F 00 00 02 

2018-07-16 18:03:36.825 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: SendData Request. CallBack ID = 63, Status = Transmission complete and ACK received(0)

2018-07-16 18:03:36.828 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 4: Starting initialisation from DONE

2018-07-16 18:03:36.829 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@1013cd already registered

2018-07-16 18:03:36.832 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=4, callback=63, payload=04 02 84 08 

2018-07-16 18:03:36.834 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=3F 00 00 02 

2018-07-16 18:03:36.836 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=63, expected=SendData, cancelled=false        transaction complete!

2018-07-16 18:03:36.838 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent

2018-07-16 18:03:36.840 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 4: Went to sleep

2018-07-16 18:03:36.841 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 4: Is sleeping

2018-07-16 18:03:36.843 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 4: Response processed after 111ms/1438ms.

chris · July 16, 2018, 6:56pm

This section shows that initialisation is complete, but we don’t know what happened before hand.

Please provide the full debug log from startup - not just short sections. The event log is irrelevant, so please don’t confuse things by also providing this.

Scotsman · July 16, 2018, 7:32pm

Hi

Do you mean from openhab start up?

What’s best way to post. Some of the logging has been so long the forum has rejected it.

chris · July 16, 2018, 7:42pm

Yes - that would be fine. Restart, wait a few minutes for things to settle (maybe longer if you’re on a slow machine), then wake the device a few times - let’s say 4 times, waking it every 10 seconds. This ought to ensure that we get enough transactions through to see what is happening.

Choose your favourite web hosting system, and post there (eg dropbox, github etc). Then just provide the link here.

Scotsman · July 16, 2018, 7:58pm

If I grep the file and pipe the output to a new file is what would be the best pattern to ensure I get all the important details?

chris · July 16, 2018, 8:00pm

Please don’t filter the log - just provide it as it comes as you will likely miss some stuff. I use a log viewer to filter, and it does all the hard work.

Scotsman · July 16, 2018, 8:21pm

OK I try and get the log tonight. My TV is also my pc so need to wait until family in bed.

I also have bindings for my Netatmo account that includes a home cam. The logging won’t contain sensitive details will it?

chris · July 16, 2018, 8:32pm

It shouldn’t contain other sensitive data - if you only enable debug for zwave, then there should be next to nothing logged for other bindings.

If you like, you can email me the log so long as it’s less than 10MB or so… (chris -at- cd-jackson.com).

Scotsman · July 16, 2018, 8:39pm

Thanks Chris I appreciate all your help.

Scotsman · July 16, 2018, 9:41pm

Hi Chris,

I have emailed you the log file.

Many thanks

Patrick

chris · July 16, 2018, 9:49pm

Got it…

Node 4 that we discussed above looks like it is known -:

I guess you did the wakeups on node 2, and this node also appears to have completed initialisation and is known -:

So… Let’s take a step back to this statement -:

Can you describe exactly what you mean - maybe provide a screenshot or something so that I can understand better what you’re seeing.

Scotsman · July 16, 2018, 10:15pm

Hi Chris,

I’ve email a screen shot of my inbox.

Basically some Nodes have a description of the device in the name and some only say NODE 9 for example and all have ‘Unknown Device’ under each name