Zwave with Razberry2 Unkown Device

[Scotsman (Patrick Beard)]

I am coming from Domoticz.
My hardware is a Raspberry Pi3 with a Razberry2 Zwave controller. My zwave devices are Neo Coolcam Motion Sensors, Neo Coolcam Sirens, Fibaro Smoke Detectors, and Heiman Smoke and Co2 detectors and Heiman Door sensors.

When I set up OpenHab2.3 and configured my Razberry2 it found 19 nodes but listed them all as ‘Unknown Devices’.

I reset the Razberry2 and then Included a single Neo Coolcam Motion Sensor. It included it immediately but again listed it as a unknown device. I woke the sensor up a few times using its code button and have left it overnight but it is still listed as ‘Unknown Device’

Does anyone have any suggestions for getting my zwave devices working?

Thanks,
Patrick

[chris (Chris Jackson)]

All of the devices you have listed here are battery devices. They will of course take time to initialise as the binding will need to wait for the devices to wake up. You can speed this up by manually waking the devices.

[Scotsman (Patrick Beard)]

Thanks for the reply Chris.

I have been waking the device up but its remained UnKnown. I have just switched from Stable 2.3 to unstable to get the latest binding.

I know they are two different platforms but with Domoticz the device recognition was pretty much instant. Why do battery devices take so long with OpenHab?

One last thing - now I am on unstable what is the correct update proceedure - do I just keep using openhabian-config with the install or switch to latest unstable?

Thanks again,
Patrick

[chris (Chris Jackson)]

@Scotsman

I have been waking the device up but its remained UnKnown

What do the debug logs show?

@Scotsman

Why do battery devices take so long with OpenHab?

This is the way that ZWave works. The binding needs to download some information from the device before it knows what the device is. If the device is asleep, then it needs to wait for it to wake up. Most people have their wakeup set to 1 hour, but I know others set it to 1 day, or anything else they like.

When you first include the device, it is of course awake, so the data can be downloaded quickly (normally!). However, if you move the controller to a new system, or choose to reinitialise (etc), then the system needs to wait for the device to wake up before it can download the data. This is not an issue with openHAB - all systems will work the same way. The device needs to be awake one way or the other.

@Scotsman

One last thing - now I am on unstable what is the correct update proceedure - do I just keep using openhabian-config with the install or switch to latest unstable?

I’m not 100% familiar with openhabian, but you should just need to uninstall the binding, and reinstall it using PaperUI / HABmin. When you reinstall, it will pick up the latest snapshot.

[Scotsman (Patrick Beard)]

Hi Chris,

Thanks again - that all makes sense.

Can I ask 1 final question. When a device is listed as unknown should it be left in ‘Inbox’ until it is configured or can it be move to items whilst still reporting ‘UnKnown Device’

Thanks,
Patrick

[chris (Chris Jackson)]

@Scotsman

When a device is listed as unknown should it be left in ‘Inbox’ until it is configured or can it be move to items whilst still reporting ‘UnKnown Device’

It shouldn’t matter either way. If you create the thing, and it’s still unknown, then you will have no channels etc, but it won’t hurt.

[Scotsman (Patrick Beard)]

I still can’t get my devices recognized.

Both my Razberry2 and all my zwave devices have been factory reset. I have included 7 of them all battery devices but after a day all are still ‘unknown’
With Domoticz they were recognised and usable as soon as they were included.
I’m running the snapshot from yesterday.

The log says;
2018-07-13 23:46:22.291 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0

2018-07-13 23:46:22.333 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0

2018-07-13 23:46:22.370 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 4: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0

2018-07-13 23:46:22.400 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 5: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0

2018-07-13 23:46:22.426 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 6: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0

What am I doing wrong?

[Scotsman (Patrick Beard)]

Tried waking up a couple of devices and the following was logged;

2018-07-14 00:26:43.857 [WARN ] [l.serialmessage.SendDataMessageClass] - NODE 4: Already processed another send data request for this callback Id, ignoring.

2018-07-14 00:27:56.481 [WARN ] [l.serialmessage.SendDataMessageClass] - NODE 2: Already processed another send data request for this callback Id, ignoring.

Node 2 is a neo coolcam motion sensor and node 4 is a Heiman smoke detector

Any ideas?

[chris (Chris Jackson)]

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.

[Scotsman (Patrick Beard)]

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 (Patrick Beard)]

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 (Chris Jackson)]

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 (Patrick Beard)]

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 (Chris Jackson)]

@Scotsman

I don’t know how to code fence it and not sure how to use the </> button.

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

@Scotsman

I am seeing a lot of MISMATCH entries

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

[sihui]

@Scotsman

I don’t know how to code fence

How to use code fences

We all have to type this content over and over and over. Here is a posting we can all point to when the topic comes up. Why use code fences? Because rules, sitemap, logs, and configs are all but unreadable when code fences are not used. When to use code fences? Whenever one is posting any sort of code, config, log, and any text where line wrapping, indentation, and using an equal spaced font makes the text more legible. How to use code fences? Use 3 backticks (```)... Or use <code>... …

[Scotsman (Patrick Beard)]

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 (Patrick Beard)]

Thanks I’ll give that a read

[Scotsman (Patrick Beard)]

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 (Chris Jackson)]

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 (Patrick Beard)]

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.