Zwave with Razberry2 Unkown Device


(Chris Jackson) #9

It’s hard to say what is happening without seeing a debug log. The “could not resolve to a thing type” message means that the device hasn’t sent its manufacturer information, so it’s not possible to work out what type it is. The “Already processed” message should not be a warning - it’s quite normal and is removed in later versions.


(Patrick Beard) #10

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


(Patrick Beard) #11

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 Jackson) #12

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 :wink: .)


(Patrick Beard) #13

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 Jackson) #14

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) #15

(Patrick Beard) #16

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.

(Patrick Beard) #17

Thanks I’ll give that a read


(Patrick Beard) #18

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 Jackson) #19

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.


(Patrick Beard) #20

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 Jackson) #21

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 :wink: (eg dropbox, github etc). Then just provide the link here.


(Patrick Beard) #22

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 Jackson) #23

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.


(Patrick Beard) #24

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 Jackson) #25

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).


(Patrick Beard) #26

Thanks Chris I appreciate all your help.


(Patrick Beard) #27

Hi Chris,

I have emailed you the log file.

Many thanks

Patrick


(Chris Jackson) #28

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.