Battery operated device slow

Add-ons Bindings
,
1

Hi there,

I’ve been trying to figure out why my wall scene controller, battery operated, takes such a long time to turn off or on a wall swatch.

I enabled debug log in karaf and there is a 2 second lag between the last log for node 45, the wall scene controller and node 25, the switch but I can’t for the life of me understand why it takes so long.
I have the suspicion that something’s not right with my zwave network as other battery-operated

wall controller: nodon CWS-3101
power switch: Aeotec ZW096
openhab2 running on RPi3
USB zwave stick aeotec Gen5

Any guidance towards where to look into would be great, I can’t make sense of what’s happening and why it takes so long.

The rule controlling the light from the wall controller is not complicated:

rule "Scenes_Lounge_White"
when
	Item Switch_Nodon_Wall_1 received update
then
	if (Switch_Nodon_Wall_1.state == 1.0 || Switch_Nodon_Wall_1.state == 1.1) {
...
	else if (Switch_Nodon_Wall_1.state == 2.0 || Switch_Nodon_Wall_1.state == 2.1) {
//		message = "Turning ON piano light"
//		logInfo("Controllers", message)
//		pushover(message)
		sendCommand(Switch_2_switch, ON)
	}
	else if (Switch_Nodon_Wall_1.state == 4.0 || Switch_Nodon_Wall_1.state == 4.1) {
//		message = "Turning OFF piano light"
//		logInfo("Controllers", message)
//		pushover(message)
		sendCommand(Switch_2_switch, OFF)
	}
end

I am sorry for their extent, but I added the quite verbose output log.

output for wall scene controller

==> /var/log/openhab2/openhab.log <==
2017-11-17 22:47:55.421 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 2D 05 5B 03 EA 00 04 6E
2017-11-17 22:47:55.426 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:55.429 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0B 00 04 00 2D 05 5B 03 EA 00 04 6E
2017-11-17 22:47:55.432 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0B 00 04 00 2D 05 5B 03 EA 00 04 6E
2017-11-17 22:47:55.435 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 2D 05 5B 03 EA 00 04
2017-11-17 22:47:55.436 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 45: Application Command Request (ALIVE:DONE)
2017-11-17 22:47:55.437 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 45: Starting initialisation from DONE
2017-11-17 22:47:55.439 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@14dc277 already registered
2017-11-17 22:47:55.440 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 45: Incoming command class CENTRAL_SCENE
2017-11-17 22:47:55.441 [DEBUG] [dclass.ZWaveCentralSceneCommandClass] - NODE 45: Received CENTRAL_SCENE command V2
2017-11-17 22:47:55.443 [DEBUG] [dclass.ZWaveCentralSceneCommandClass] - NODE 45: Received scene 4 at key 0 [Single Press]
2017-11-17 22:47:55.443 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 2D 02 84 07 5F
2017-11-17 22:47:55.444 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2017-11-17 22:47:55.445 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 45: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2017-11-17 22:47:55.446 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 45: Got a value event from Z-Wave network, endpoint = 0, command class = CENTRAL_SCENE, value = 4.0
2017-11-17 22:47:55.450 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 45: Updating channel state zwave:device:5ddcc1cc:node45:scene_number to 4.0 [DecimalType]
2017-11-17 22:47:55.459 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 20: Transaction not completed: node address inconsistent.  lastSent=20, incoming=255
2017-11-17 22:47:55.461 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:55.463 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 00 2D 02 84 07 5F
2017-11-17 22:47:55.465 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 00 2D 02 84 07 5F
2017-11-17 22:47:55.467 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 2D 02 84 07

==> /var/log/openhab2/events.log <==
2017-11-17 22:47:55.467 [ItemStateChangedEvent     ] - Switch_Nodon_Wall_1 changed from NULL to 4.0

==> /var/log/openhab2/openhab.log <==
2017-11-17 22:47:55.468 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 45: Application Command Request (ALIVE:DONE)
2017-11-17 22:47:55.469 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 45: Starting initialisation from DONE
2017-11-17 22:47:55.470 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@14dc277 already registered
2017-11-17 22:47:55.472 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 45: Incoming command class WAKE_UP
2017-11-17 22:47:55.473 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 45: Received Wake Up Request
2017-11-17 22:47:55.473 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 45: Received WAKE_UP_NOTIFICATION
2017-11-17 22:47:55.474 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 45: Is awake with 2 messages in the wake-up queue.
2017-11-17 22:47:55.476 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveWakeUpEvent
2017-11-17 22:47:55.477 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 45: Got an event from Z-Wave network: ZWaveWakeUpEvent
2017-11-17 22:47:55.480 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-11-17 22:47:55.480 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-11-17 22:47:55.482 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 20: Transaction not completed: node address inconsistent.  lastSent=20, incoming=255
2017-11-17 22:47:55.484 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 2D 02 84 08 25 62 01
2017-11-17 22:47:55.487 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 45: Sending REQUEST Message = 01 09 00 13 2D 02 84 08 25 62 01
2017-11-17 22:47:55.499 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-11-17 22:47:55.501 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:55.503 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-11-17 22:47:55.504 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-11-17 22:47:55.505 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-11-17 22:47:55.506 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 45: Sent Data successfully placed on stack.
2017-11-17 22:47:55.514 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 62 00 00 02 8B
2017-11-17 22:47:55.516 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:55.517 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 62 00 00 02 00 00 85
2017-11-17 22:47:55.518 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 62 00 00 02 00 00 85
2017-11-17 22:47:55.520 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=62 00 00 02
2017-11-17 22:47:55.520 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 45: SendData Request. CallBack ID = 98, Status = Transmission complete and ACK received(0)
2017-11-17 22:47:55.521 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 45: Starting initialisation from DONE
2017-11-17 22:47:55.522 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@14dc277 already registered
2017-11-17 22:47:55.523 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=45, callback=98, payload=2D 02 84 08
2017-11-17 22:47:55.525 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=62 00 00 02
2017-11-17 22:47:55.525 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=98, expected=SendData, cancelled=false        transaction complete!
2017-11-17 22:47:55.526 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-11-17 22:47:55.527 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 45: Went to sleep
2017-11-17 22:47:55.527 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 45: Is sleeping
2017-11-17 22:47:55.528 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 45: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-11-17 22:47:55.528 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 45: Response processed after 40ms/4526ms.

output for power switch

2017-11-17 22:47:57.981 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Command received zwave:device:5ddcc1cc:node25:switch_binary --> OFF
2017-11-17 22:47:57.982 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 25: Creating new message for application command SWITCH_BINARY_SET
2017-11-17 22:47:57.985 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-11-17 22:47:57.985 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 0. Queue={}
2017-11-17 22:47:57.986 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 19 03 25 01 00 25 63 9E

==> /var/log/openhab2/events.log <==
2017-11-17 22:47:57.987 [ItemCommandEvent          ] - Item 'Switch_2_switch' received command OFF

==> /var/log/openhab2/openhab.log <==
2017-11-17 22:47:57.988 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 25: Sending REQUEST Message = 01 0A 00 13 19 03 25 01 00 25 63 9E

==> /var/log/openhab2/events.log <==
2017-11-17 22:47:57.990 [ItemStateChangedEvent     ] - Switch_2_switch changed from ON to OFF

==> /var/log/openhab2/openhab.log <==
2017-11-17 22:47:58.001 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-11-17 22:47:58.003 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.004 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-11-17 22:47:58.005 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-11-17 22:47:58.006 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-11-17 22:47:58.006 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 25: Sent Data successfully placed on stack.
2017-11-17 22:47:58.017 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 63 00 00 02 8A
2017-11-17 22:47:58.020 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.022 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 63 00 00 02 00 00 84
2017-11-17 22:47:58.023 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 63 00 00 02 00 00 84
2017-11-17 22:47:58.024 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=63 00 00 02
2017-11-17 22:47:58.027 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 25: SendData Request. CallBack ID = 99, Status = Transmission complete and ACK received(0)
2017-11-17 22:47:58.028 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: Starting initialisation from DONE
2017-11-17 22:47:58.028 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@51c7c7 already registered
2017-11-17 22:47:58.030 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=25, callback=99, payload=19 03 25 01 00
2017-11-17 22:47:58.030 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 19 02 82 01 6B
2017-11-17 22:47:58.031 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=63 00 00 02
2017-11-17 22:47:58.032 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=99, expected=SendData, cancelled=false        transaction complete!
2017-11-17 22:47:58.032 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-11-17 22:47:58.033 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-11-17 22:47:58.034 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 25: Response processed after 43ms/4526ms.
2017-11-17 22:47:58.037 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.038 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 00 19 02 82 01 6B
2017-11-17 22:47:58.040 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 00 19 02 82 01 6B
2017-11-17 22:47:58.041 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 02 82 01
2017-11-17 22:47:58.042 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Application Command Request (ALIVE:DONE)
2017-11-17 22:47:58.043 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: Starting initialisation from DONE
2017-11-17 22:47:58.043 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@51c7c7 already registered
2017-11-17 22:47:58.044 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Incoming command class HAIL
2017-11-17 22:47:58.045 [DEBUG] [l.commandclass.ZWaveHailCommandClass] - NODE 25: Received Hail command (v0)
2017-11-17 22:47:58.046 [DEBUG] [l.commandclass.ZWaveHailCommandClass] - NODE 25: Request an update of the dynamic values
2017-11-17 22:47:58.047 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveDelayedPollEvent
2017-11-17 22:47:58.051 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveDelayedPollEvent
2017-11-17 22:47:58.052 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Polling intialised at 1800 seconds - start in 75 milliseconds.
2

the rest of the output for node25:

2017-11-17 22:47:58.054 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=25, callback=99, payload=19 03 25 01 00
2017-11-17 22:47:58.055 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 02 82 01
2017-11-17 22:47:58.056 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=99, expected=SendData, cancelled=false      MISMATCH
2017-11-17 22:47:58.082 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 19 02 82 01 6B
2017-11-17 22:47:58.084 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.085 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 00 19 02 82 01 6B
2017-11-17 22:47:58.087 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 00 19 02 82 01 6B
2017-11-17 22:47:58.088 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 02 82 01
2017-11-17 22:47:58.089 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Application Command Request (ALIVE:DONE)
2017-11-17 22:47:58.090 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: Starting initialisation from DONE
2017-11-17 22:47:58.091 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@51c7c7 already registered
2017-11-17 22:47:58.091 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Incoming command class HAIL
2017-11-17 22:47:58.092 [DEBUG] [l.commandclass.ZWaveHailCommandClass] - NODE 25: Received Hail command (v0)
2017-11-17 22:47:58.093 [DEBUG] [l.commandclass.ZWaveHailCommandClass] - NODE 25: Request an update of the dynamic values
2017-11-17 22:47:58.094 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveDelayedPollEvent
2017-11-17 22:47:58.095 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveDelayedPollEvent
2017-11-17 22:47:58.095 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Polling intialised at 1800 seconds - start in 75 milliseconds.
2017-11-17 22:47:58.097 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=25, callback=99, payload=19 03 25 01 00
2017-11-17 22:47:58.098 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 02 82 01
2017-11-17 22:47:58.099 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=99, expected=SendData, cancelled=false      MISMATCH
2017-11-17 22:47:58.104 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 19 02 82 01 6B
2017-11-17 22:47:58.106 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.107 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 00 19 02 82 01 6B
2017-11-17 22:47:58.109 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 00 19 02 82 01 6B
2017-11-17 22:47:58.110 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 02 82 01
2017-11-17 22:47:58.111 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Application Command Request (ALIVE:DONE)
2017-11-17 22:47:58.112 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: Starting initialisation from DONE
2017-11-17 22:47:58.113 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@51c7c7 already registered
2017-11-17 22:47:58.114 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Incoming command class HAIL
2017-11-17 22:47:58.115 [DEBUG] [l.commandclass.ZWaveHailCommandClass] - NODE 25: Received Hail command (v0)
2017-11-17 22:47:58.115 [DEBUG] [l.commandclass.ZWaveHailCommandClass] - NODE 25: Request an update of the dynamic values
2017-11-17 22:47:58.116 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveDelayedPollEvent
2017-11-17 22:47:58.117 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveDelayedPollEvent
2017-11-17 22:47:58.118 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Polling intialised at 1800 seconds - start in 75 milliseconds.
2017-11-17 22:47:58.119 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=25, callback=99, payload=19 03 25 01 00
2017-11-17 22:47:58.120 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 02 82 01
2017-11-17 22:47:58.121 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=99, expected=SendData, cancelled=false      MISMATCH
2017-11-17 22:47:58.130 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 19 03 25 01 00 CC
2017-11-17 22:47:58.132 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.133 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 19 03 25 01 00 CC
2017-11-17 22:47:58.134 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 19 03 25 01 00 CC
2017-11-17 22:47:58.135 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 03 25 01 00
2017-11-17 22:47:58.136 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Application Command Request (ALIVE:DONE)
2017-11-17 22:47:58.137 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: Starting initialisation from DONE
2017-11-17 22:47:58.137 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@51c7c7 already registered
2017-11-17 22:47:58.138 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Incoming command class SWITCH_BINARY
2017-11-17 22:47:58.139 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 25
2017-11-17 22:47:58.140 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 25: Switch Binary SET
2017-11-17 22:47:58.140 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 25: Switch Binary report, value = 0
2017-11-17 22:47:58.141 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2017-11-17 22:47:58.142 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2017-11-17 22:47:58.142 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 0
2017-11-17 22:47:58.145 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Updating channel state zwave:device:5ddcc1cc:node25:switch_binary to OFF [OnOffType]
2017-11-17 22:47:58.148 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=25, callback=99, payload=19 03 25 01 00
2017-11-17 22:47:58.149 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 03 25 01 00
2017-11-17 22:47:58.150 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=99, expected=SendData, cancelled=false      MISMATCH
2017-11-17 22:47:58.193 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Polling...
2017-11-17 22:47:58.194 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Polling zwave:device:5ddcc1cc:node25:switch_binary
2017-11-17 22:47:58.194 [DEBUG] [converter.ZWaveBinarySwitchConverter] - NODE 25: Generating poll message for SWITCH_BINARY, endpoint 0
2017-11-17 22:47:58.195 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 25: Creating new message for application command SWITCH_BINARY_GET
2017-11-17 22:47:58.196 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Polling zwave:device:5ddcc1cc:node25:meter_kwh
2017-11-17 22:47:58.196 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 25: Generating poll message for METER, endpoint 0
2017-11-17 22:47:58.197 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 25: Generating poll message for METER, endpoint 0
2017-11-17 22:47:58.197 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Creating new message for application command METER_GET
2017-11-17 22:47:58.198 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Polling zwave:device:5ddcc1cc:node25:meter_current
2017-11-17 22:47:58.199 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 25: Generating poll message for METER, endpoint 0
2017-11-17 22:47:58.200 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 25: Generating poll message for METER, endpoint 0
2017-11-17 22:47:58.202 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Creating new message for application command METER_GET
2017-11-17 22:47:58.203 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Polling zwave:device:5ddcc1cc:node25:meter_voltage
2017-11-17 22:47:58.210 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 25: Generating poll message for METER, endpoint 0
2017-11-17 22:47:58.211 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 25: Generating poll message for METER, endpoint 0
2017-11-17 22:47:58.213 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Creating new message for application command METER_GET
2017-11-17 22:47:58.214 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Polling zwave:device:5ddcc1cc:node25:meter_watts
2017-11-17 22:47:58.216 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 25: Generating poll message for METER, endpoint 0
2017-11-17 22:47:58.217 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 25: Generating poll message for METER, endpoint 0
2017-11-17 22:47:58.218 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Creating new message for application command METER_GET
2017-11-17 22:47:58.220 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Polling zwave:device:5ddcc1cc:node25:meter_reset
2017-11-17 22:47:58.221 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 25: Generating poll message for METER, endpoint 0
2017-11-17 22:47:58.222 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Polling zwave:device:5ddcc1cc:node25:color_color
2017-11-17 22:47:58.224 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 25: Generating poll message for SWITCH_MULTILEVEL, endpoint 0
2017-11-17 22:47:58.225 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 25: Creating new message for command SWITCH_MULTILEVEL_GET
2017-11-17 22:47:58.227 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Polling zwave:device:5ddcc1cc:node25:color_color
2017-11-17 22:47:58.228 [DEBUG] [ternal.converter.ZWaveColorConverter] - NODE 25: Generating poll message for COLOR, endpoint 0
2017-11-17 22:47:58.230 [DEBUG] [.commandclass.ZWaveColorCommandClass] - NODE Node 25. Manufacturer 0086, Type 0003, Id 0060: Color refresh is already in progress
2017-11-17 22:47:58.231 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Polling zwave:device:5ddcc1cc:node25:color_color
2017-11-17 22:47:58.233 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 25: Generating poll message for SWITCH_MULTILEVEL, endpoint 0
2017-11-17 22:47:58.234 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 25: Creating new message for command SWITCH_MULTILEVEL_GET
2017-11-17 22:47:58.236 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-11-17 22:47:58.236 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-11-17 22:47:58.237 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-11-17 22:47:58.238 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 19 02 25 02 25 64 98
2017-11-17 22:47:58.238 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
2017-11-17 22:47:58.239 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 25: Sending REQUEST Message = 01 09 00 13 19 02 25 02 25 64 98
2017-11-17 22:47:58.239 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 3. Queue={}
2017-11-17 22:47:58.241 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 4. Queue={}
2017-11-17 22:47:58.249 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 5. Queue={}
2017-11-17 22:47:58.249 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-11-17 22:47:58.250 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 6. Queue={}
2017-11-17 22:47:58.251 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.252 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-11-17 22:47:58.253 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-11-17 22:47:58.254 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-11-17 22:47:58.255 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 25: Sent Data successfully placed on stack.
2017-11-17 22:47:58.359 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 64 00 00 0C 83
2017-11-17 22:47:58.360 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.362 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 64 00 00 0C 00 00 8D
2017-11-17 22:47:58.363 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 64 00 00 0C 00 00 8D
2017-11-17 22:47:58.364 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=64 00 00 0C
2017-11-17 22:47:58.365 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 25: SendData Request. CallBack ID = 100, Status = Transmission complete and ACK received(0)
2017-11-17 22:47:58.366 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: Starting initialisation from DONE
2017-11-17 22:47:58.366 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@51c7c7 already registered
2017-11-17 22:47:58.368 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=25, callback=100, payload=19 02 25 02
2017-11-17 22:47:58.369 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=64 00 00 0C
2017-11-17 22:47:58.370 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=100, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
2017-11-17 22:47:58.371 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 19 03 25 03 00 CE
2017-11-17 22:47:58.374 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.375 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 19 03 25 03 00 CE
2017-11-17 22:47:58.377 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 19 03 25 03 00 CE
2017-11-17 22:47:58.378 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 03 25 03 00
2017-11-17 22:47:58.379 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Application Command Request (ALIVE:DONE)
2017-11-17 22:47:58.380 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: Starting initialisation from DONE
2017-11-17 22:47:58.380 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@51c7c7 already registered
2017-11-17 22:47:58.381 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Incoming command class SWITCH_BINARY
2017-11-17 22:47:58.382 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 25
2017-11-17 22:47:58.383 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 25: Switch Binary report, value = 0
2017-11-17 22:47:58.384 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2017-11-17 22:47:58.385 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2017-11-17 22:47:58.385 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 0
2017-11-17 22:47:58.387 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Updating channel state zwave:device:5ddcc1cc:node25:switch_binary to OFF [OnOffType]
2017-11-17 22:47:58.391 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=25, callback=100, payload=19 02 25 02
2017-11-17 22:47:58.392 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 03 25 03 00
2017-11-17 22:47:58.393 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=100, expected=ApplicationCommandHandler, cancelled=false        transaction complete!
2017-11-17 22:47:58.397 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-11-17 22:47:58.397 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-11-17 22:47:58.398 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 25: Response processed after 159ms/4526ms.
2017-11-17 22:47:58.399 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 5
2017-11-17 22:47:58.401 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 19 03 32 01 00 25 65 8F
2017-11-17 22:47:58.402 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 25: Sending REQUEST Message = 01 0A 00 13 19 03 32 01 00 25 65 8F
2017-11-17 22:47:58.413 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-11-17 22:47:58.415 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.416 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-11-17 22:47:58.417 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-11-17 22:47:58.418 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-11-17 22:47:58.418 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 25: Sent Data successfully placed on stack.
2017-11-17 22:47:58.567 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 65 00 00 10 9E
2017-11-17 22:47:58.569 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.570 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 65 00 00 10 00 00 90
2017-11-17 22:47:58.572 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 65 00 00 10 00 00 90
2017-11-17 22:47:58.573 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=65 00 00 10
2017-11-17 22:47:58.575 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 25: SendData Request. CallBack ID = 101, Status = Transmission complete and ACK received(0)
2017-11-17 22:47:58.576 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: Starting initialisation from DONE
2017-11-17 22:47:58.577 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@51c7c7 already registered
2017-11-17 22:47:58.578 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=25, callback=101, payload=19 03 32 01 00
2017-11-17 22:47:58.579 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=65 00 00 10
2017-11-17 22:47:58.580 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=101, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
2017-11-17 22:47:58.584 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 19 12 32 02 21 64 00 00 8A 16 02 BA 00 00 8A 16 00 00 00 00 25
2017-11-17 22:47:58.587 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.589 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 18 00 04 00 19 12 32 02 21 64 00 00 8A 16 02 BA 00 00 8A 16 00 00 00 00 25
2017-11-17 22:47:58.590 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 18 00 04 00 19 12 32 02 21 64 00 00 8A 16 02 BA 00 00 8A 16 00 00 00 00 25
2017-11-17 22:47:58.593 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 12 32 02 21 64 00 00 8A 16 02 BA 00 00 8A 16 00 00 00 00
2017-11-17 22:47:58.594 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Application Command Request (ALIVE:DONE)
2017-11-17 22:47:58.596 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: Starting initialisation from DONE
2017-11-17 22:47:58.598 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@51c7c7 already registered
2017-11-17 22:47:58.600 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Incoming command class METER
2017-11-17 22:47:58.601 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Received METER command V3
2017-11-17 22:47:58.604 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Meter: Type=Electric(1), Scale=kWh(0), Value=35.35
2017-11-17 22:47:58.605 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
2017-11-17 22:47:58.607 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveMeterValueEvent
2017-11-17 22:47:58.609 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 35.35
2017-11-17 22:47:58.612 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Updating channel state zwave:device:5ddcc1cc:node25:meter_kwh to 35.35 [DecimalType]
2017-11-17 22:47:58.616 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_A <> E_KWh
2017-11-17 22:47:58.618 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_V <> E_KWh
2017-11-17 22:47:58.619 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_W <> E_KWh
2017-11-17 22:47:58.621 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=25, callback=101, payload=19 03 32 01 00
2017-11-17 22:47:58.623 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 12 32 02 21 64 00 00 8A 16 02 BA 00 00 8A 16 00 00 00 00
2017-11-17 22:47:58.625 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=101, expected=ApplicationCommandHandler, cancelled=false        transaction complete!
2017-11-17 22:47:58.626 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-11-17 22:47:58.628 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
3

and the last bit…

2017-11-17 22:47:58.630 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 25: Response processed after 227ms/4526ms.
2017-11-17 22:47:58.631 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 4
2017-11-17 22:47:58.632 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 19 03 32 01 28 25 66 A4
2017-11-17 22:47:58.633 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 25: Sending REQUEST Message = 01 0A 00 13 19 03 32 01 28 25 66 A4
2017-11-17 22:47:58.644 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-11-17 22:47:58.646 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.647 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-11-17 22:47:58.650 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-11-17 22:47:58.651 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-11-17 22:47:58.653 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 25: Sent Data successfully placed on stack.
2017-11-17 22:47:58.697 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 66 00 00 05 88
2017-11-17 22:47:58.698 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.700 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 66 00 00 05 00 00 86
2017-11-17 22:47:58.702 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 66 00 00 05 00 00 86
2017-11-17 22:47:58.704 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=66 00 00 05
2017-11-17 22:47:58.705 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 25: SendData Request. CallBack ID = 102, Status = Transmission complete and ACK received(0)
2017-11-17 22:47:58.707 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: Starting initialisation from DONE
2017-11-17 22:47:58.708 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@51c7c7 already registered
2017-11-17 22:47:58.710 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=25, callback=102, payload=19 03 32 01 28
2017-11-17 22:47:58.711 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 19 12 32 02 A1 6C 00 00 00 3B 00 00 00 00 00 00 00 00 00 00 2E
2017-11-17 22:47:58.712 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=66 00 00 05
2017-11-17 22:47:58.714 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=102, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
2017-11-17 22:47:58.716 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.718 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 18 00 04 00 19 12 32 02 A1 6C 00 00 00 3B 00 00 00 00 00 00 00 00 00 00 2E
2017-11-17 22:47:58.720 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 18 00 04 00 19 12 32 02 A1 6C 00 00 00 3B 00 00 00 00 00 00 00 00 00 00 2E
2017-11-17 22:47:58.722 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 12 32 02 A1 6C 00 00 00 3B 00 00 00 00 00 00 00 00 00 00
2017-11-17 22:47:58.723 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Application Command Request (ALIVE:DONE)
2017-11-17 22:47:58.725 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: Starting initialisation from DONE
2017-11-17 22:47:58.726 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@51c7c7 already registered
2017-11-17 22:47:58.727 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Incoming command class METER
2017-11-17 22:47:58.729 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Received METER command V3
2017-11-17 22:47:58.731 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Meter: Type=Electric(1), Scale=A(5), Value=0.059
2017-11-17 22:47:58.733 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
2017-11-17 22:47:58.735 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveMeterValueEvent
2017-11-17 22:47:58.736 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 0.059
2017-11-17 22:47:58.739 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_KWh <> E_A
2017-11-17 22:47:58.741 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Updating channel state zwave:device:5ddcc1cc:node25:meter_current to 0.059 [DecimalType]
2017-11-17 22:47:58.744 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_V <> E_A
2017-11-17 22:47:58.746 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_W <> E_A
2017-11-17 22:47:58.748 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=25, callback=102, payload=19 03 32 01 28
2017-11-17 22:47:58.750 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 12 32 02 A1 6C 00 00 00 3B 00 00 00 00 00 00 00 00 00 00
2017-11-17 22:47:58.751 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=102, expected=ApplicationCommandHandler, cancelled=false        transaction complete!
2017-11-17 22:47:58.753 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-11-17 22:47:58.754 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-11-17 22:47:58.756 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 25: Response processed after 122ms/4526ms.
2017-11-17 22:47:58.757 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 3
2017-11-17 22:47:58.758 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 19 03 32 01 20 25 67 AD
2017-11-17 22:47:58.758 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 25: Sending REQUEST Message = 01 0A 00 13 19 03 32 01 20 25 67 AD
2017-11-17 22:47:58.770 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-11-17 22:47:58.773 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.775 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-11-17 22:47:58.776 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-11-17 22:47:58.778 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-11-17 22:47:58.780 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 25: Sent Data successfully placed on stack.
2017-11-17 22:47:58.799 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 19 12 32 02 A1 6C 00 00 00 3B 00 00 00 00 00 00 00 00 00 00 2E
2017-11-17 22:47:58.803 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.805 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 18 00 04 00 19 12 32 02 A1 6C 00 00 00 3B 00 00 00 00 00 00 00 00 00 00 2E
2017-11-17 22:47:58.808 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 18 00 04 00 19 12 32 02 A1 6C 00 00 00 3B 00 00 00 00 00 00 00 00 00 00 2E
2017-11-17 22:47:58.810 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 12 32 02 A1 6C 00 00 00 3B 00 00 00 00 00 00 00 00 00 00
2017-11-17 22:47:58.812 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Application Command Request (ALIVE:DONE)
2017-11-17 22:47:58.813 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: Starting initialisation from DONE
2017-11-17 22:47:58.814 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@51c7c7 already registered
2017-11-17 22:47:58.816 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Incoming command class METER
2017-11-17 22:47:58.817 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 67 00 00 05 89
2017-11-17 22:47:58.818 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Received METER command V3
2017-11-17 22:47:58.820 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Meter: Type=Electric(1), Scale=A(5), Value=0.059
2017-11-17 22:47:58.821 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
2017-11-17 22:47:58.823 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveMeterValueEvent
2017-11-17 22:47:58.825 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 0.059
2017-11-17 22:47:58.827 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_KWh <> E_A
2017-11-17 22:47:58.829 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Updating channel state zwave:device:5ddcc1cc:node25:meter_current to 0.059 [DecimalType]
2017-11-17 22:47:58.833 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_V <> E_A
2017-11-17 22:47:58.834 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_W <> E_A
2017-11-17 22:47:58.836 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=25, callback=103, payload=19 03 32 01 20
2017-11-17 22:47:58.838 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 12 32 02 A1 6C 00 00 00 3B 00 00 00 00 00 00 00 00 00 00
2017-11-17 22:47:58.840 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=103, expected=ApplicationCommandHandler, cancelled=false        transaction complete!
2017-11-17 22:47:58.841 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-11-17 22:47:58.843 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-11-17 22:47:58.844 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.844 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 25: Response processed after 85ms/4526ms.
2017-11-17 22:47:58.846 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 67 00 00 05 00 00 87
2017-11-17 22:47:58.848 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 67 00 00 05 00 00 87
2017-11-17 22:47:58.851 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=67 00 00 05
2017-11-17 22:47:58.852 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 25: SendData Request. CallBack ID = 103, Status = Transmission complete and ACK received(0)
2017-11-17 22:47:58.854 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: Starting initialisation from DONE
2017-11-17 22:47:58.855 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@51c7c7 already registered
2017-11-17 22:47:58.857 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=25, callback=103, payload=19 03 32 01 20
2017-11-17 22:47:58.859 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=67 00 00 05
2017-11-17 22:47:58.860 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=103, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
2017-11-17 22:47:58.861 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 2
2017-11-17 22:47:58.862 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 19 03 32 01 10 25 68 92
2017-11-17 22:47:58.862 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 19 12 32 02 A1 6C 00 00 00 3B 00 00 00 00 00 00 00 00 00 00 2E
2017-11-17 22:47:58.863 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 25: Sending REQUEST Message = 01 0A 00 13 19 03 32 01 10 25 68 92
2017-11-17 22:47:58.864 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.866 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 18 00 04 00 19 12 32 02 A1 6C 00 00 00 3B 00 00 00 00 00 00 00 00 00 00 2E
2017-11-17 22:47:58.868 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 18 00 04 00 19 12 32 02 A1 6C 00 00 00 3B 00 00 00 00 00 00 00 00 00 00 2E
2017-11-17 22:47:58.869 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (CAN), resending
2017-11-17 22:47:58.870 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 12 32 02 A1 6C 00 00 00 3B 00 00 00 00 00 00 00 00 00 00
2017-11-17 22:47:58.872 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Application Command Request (ALIVE:DONE)
2017-11-17 22:47:58.873 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: Starting initialisation from DONE
2017-11-17 22:47:58.874 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@51c7c7 already registered
2017-11-17 22:47:58.876 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Incoming command class METER
2017-11-17 22:47:58.877 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Received METER command V3
2017-11-17 22:47:58.878 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Meter: Type=Electric(1), Scale=A(5), Value=0.059
2017-11-17 22:47:58.879 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
2017-11-17 22:47:58.880 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveMeterValueEvent
2017-11-17 22:47:58.881 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 0.059
2017-11-17 22:47:58.883 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_KWh <> E_A
2017-11-17 22:47:58.884 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Updating channel state zwave:device:5ddcc1cc:node25:meter_current to 0.059 [DecimalType]
2017-11-17 22:47:58.887 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_V <> E_A
2017-11-17 22:47:58.887 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_W <> E_A
2017-11-17 22:47:58.888 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Message has Ack Pending: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=25, callback=104, payload=19 03 32 01 10
2017-11-17 22:47:58.909 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 19 12 32 02 A1 6C 00 00 00 3B 00 00 00 00 00 00 00 00 00 00 2E
2017-11-17 22:47:58.915 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.916 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 18 00 04 00 19 12 32 02 A1 6C 00 00 00 3B 00 00 00 00 00 00 00 00 00 00 2E
2017-11-17 22:47:58.918 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 18 00 04 00 19 12 32 02 A1 6C 00 00 00 3B 00 00 00 00 00 00 00 00 00 00 2E
2017-11-17 22:47:58.919 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 12 32 02 A1 6C 00 00 00 3B 00 00 00 00 00 00 00 00 00 00
2017-11-17 22:47:58.920 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Application Command Request (ALIVE:DONE)
2017-11-17 22:47:58.921 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: Starting initialisation from DONE
2017-11-17 22:47:58.922 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@51c7c7 already registered
2017-11-17 22:47:58.923 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Incoming command class METER
2017-11-17 22:47:58.924 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Received METER command V3
2017-11-17 22:47:58.925 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Meter: Type=Electric(1), Scale=A(5), Value=0.059
2017-11-17 22:47:58.926 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
2017-11-17 22:47:58.927 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveMeterValueEvent
2017-11-17 22:47:58.928 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 0.059
2017-11-17 22:47:58.930 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_KWh <> E_A
2017-11-17 22:47:58.931 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Updating channel state zwave:device:5ddcc1cc:node25:meter_current to 0.059 [DecimalType]
2017-11-17 22:47:58.934 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_V <> E_A
2017-11-17 22:47:58.935 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_W <> E_A
2017-11-17 22:47:58.936 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Message has Ack Pending: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=25, callback=104, payload=19 03 32 01 10
2017-11-17 22:47:58.946 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 19 12 32 02 A1 64 00 03 80 0C 00 00 00 00 00 00 00 00 00 00 92
2017-11-17 22:47:58.949 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:58.951 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 18 00 04 00 19 12 32 02 A1 64 00 03 80 0C 00 00 00 00 00 00 00 00 00 00 92
2017-11-17 22:47:58.952 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 18 00 04 00 19 12 32 02 A1 64 00 03 80 0C 00 00 00 00 00 00 00 00 00 00 92
2017-11-17 22:47:58.953 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 12 32 02 A1 64 00 03 80 0C 00 00 00 00 00 00 00 00 00 00
2017-11-17 22:47:58.954 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Application Command Request (ALIVE:DONE)
2017-11-17 22:47:58.955 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: Starting initialisation from DONE
2017-11-17 22:47:58.956 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@51c7c7 already registered
2017-11-17 22:47:58.957 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Incoming command class METER
2017-11-17 22:47:58.958 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Received METER command V3
2017-11-17 22:47:58.959 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Meter: Type=Electric(1), Scale=V(4), Value=229.388
2017-11-17 22:47:58.960 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
2017-11-17 22:47:58.961 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveMeterValueEvent
2017-11-17 22:47:58.962 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 229.388
2017-11-17 22:47:58.965 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_KWh <> E_V
2017-11-17 22:47:58.966 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_A <> E_V
2017-11-17 22:47:58.967 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Updating channel state zwave:device:5ddcc1cc:node25:meter_voltage to 229.388 [DecimalType]
2017-11-17 22:47:58.969 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_W <> E_V
2017-11-17 22:47:58.971 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Message has Ack Pending: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=25, callback=104, payload=19 03 32 01 10
2017-11-17 22:47:59.026 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 19 12 32 02 A1 64 00 03 80 0C 00 00 00 00 00 00 00 00 00 00 92
2017-11-17 22:47:59.031 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:59.033 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 18 00 04 00 19 12 32 02 A1 64 00 03 80 0C 00 00 00 00 00 00 00 00 00 00 92
2017-11-17 22:47:59.034 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 18 00 04 00 19 12 32 02 A1 64 00 03 80 0C 00 00 00 00 00 00 00 00 00 00 92
2017-11-17 22:47:59.035 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 12 32 02 A1 64 00 03 80 0C 00 00 00 00 00 00 00 00 00 00
2017-11-17 22:47:59.036 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Application Command Request (ALIVE:DONE)
2017-11-17 22:47:59.037 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: Starting initialisation from DONE
2017-11-17 22:47:59.038 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@51c7c7 already registered
2017-11-17 22:47:59.039 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Incoming command class METER
2017-11-17 22:47:59.040 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Received METER command V3
2017-11-17 22:47:59.041 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Meter: Type=Electric(1), Scale=V(4), Value=229.388
2017-11-17 22:47:59.042 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
2017-11-17 22:47:59.043 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveMeterValueEvent
2017-11-17 22:47:59.044 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 229.388
2017-11-17 22:47:59.047 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_KWh <> E_V
2017-11-17 22:47:59.048 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_A <> E_V
2017-11-17 22:47:59.048 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Updating channel state zwave:device:5ddcc1cc:node25:meter_voltage to 229.388 [DecimalType]
2017-11-17 22:47:59.051 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_W <> E_V
2017-11-17 22:47:59.056 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Message has Ack Pending: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=25, callback=104, payload=19 03 32 01 10
2017-11-17 22:47:59.071 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 19 12 32 02 A1 64 00 03 80 0C 00 00 00 00 00 00 00 00 00 00 92
2017-11-17 22:47:59.080 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-17 22:47:59.081 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 18 00 04 00 19 12 32 02 A1 64 00 03 80 0C 00 00 00 00 00 00 00 00 00 00 92
2017-11-17 22:47:59.082 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 18 00 04 00 19 12 32 02 A1 64 00 03 80 0C 00 00 00 00 00 00 00 00 00 00 92
2017-11-17 22:47:59.084 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 19 12 32 02 A1 64 00 03 80 0C 00 00 00 00 00 00 00 00 00 00
2017-11-17 22:47:59.085 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Application Command Request (ALIVE:DONE)
2017-11-17 22:47:59.085 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: Starting initialisation from DONE
2017-11-17 22:47:59.086 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@51c7c7 already registered
2017-11-17 22:47:59.087 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 25: Incoming command class METER
2017-11-17 22:47:59.088 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Received METER command V3
2017-11-17 22:47:59.090 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 25: Meter: Type=Electric(1), Scale=V(4), Value=229.388
2017-11-17 22:47:59.091 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
2017-11-17 22:47:59.092 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveMeterValueEvent
2017-11-17 22:47:59.093 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 229.388
2017-11-17 22:47:59.095 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_KWh <> E_V
2017-11-17 22:47:59.096 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_A <> E_V
2017-11-17 22:47:59.097 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Updating channel state zwave:device:5ddcc1cc:node25:meter_voltage to 229.388 [DecimalType]
2017-11-17 22:47:59.100 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_W <> E_V
2017-11-17 22:47:59.101 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Message has Ack Pending: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=25, callback=104, payload=19 03 32 01 10
4

I reckon that there’s something wrong with controlling the wall plug.

I composed a small script to trigger OFF/ON at an interval and I never get consistent response from the Aoetec wall plug, even with an interval of 5s:

#!/bin/bash

COUNTER=0
DELAY=$1
while [  $COUNTER -lt 10 ]; do
	echo The counter is $COUNTER
	let COUNTER=COUNTER+1
	sleep $DELAY
	curl -X POST --header "Content-Type: text/plain" --header "Accept:application/json" -d "ON" "http://IP:8080/rest/items/Switch_2_switch"
	sleep $DELAY
	curl -X POST --header "Content-Type: text/plain" --header "Accept:application/json" -d "OFF" "http://IP:8080/rest/items/Switch_2_switch"
done

I then tried the script on a hue lamp and another wall plug from Devolo and the devices responded to the 1s interval.

So I reckon that something is not right with the config of my Aoetec wall plug. the logs above sure show a lot of events for when the wall plug (node25) is triggered.

cheers,

Norberto

5

I didn’t know they even made Zwave battery powered actuators.

The way I understand it, battery powered devices periodically wake up and when they do the controller will send any commands queued up to the device at that time. It can’t sit there and listen constantly and immediately react because you battery would only last a day off that.

In short, I think you are seeing a limitation of using battery powered devices. There is unlikely to be anything you can do within OH too make it better. There might be a setting on the device you can change through Habmin to shorten the sleep period, but I don’t think they will ever be instant.

6

I think that the main issue lies within the ZW096 wall plug/switch, even using the rest api to control it, it behaves very badly in comparison with another wall plug from another brand.

I realized after using another battery operated switch, the nodon soft, that these battery operated devices have limitations. I just got miffed that the Hue ones, zigbee, also battery operated remotes were just so much quicker.

For the wall plug, I excluded and included it again, but it still does not respond very quickly - I should probably archive this issue and create one for the visibly real issue, the Aeotec ZW096 wall plug.

Bruh Automation on YouTube has a demo of the aeotec minimote, he’s using HomeAssistant and the remote is soooo quick (in his video).

7

OK, I sorted it out.

the reason why I had such a massive output in the log was due to the device setting 80: enable send to associated devices, that was set to Hail CC. The logs included the output:

NODE 47: Incoming command class HAIL
NODE 47: Received Hail command (v0)

When I excluded and included the wall switch, it obtained default values again, which is in this case the value Nothing, it now gives a very short output (verbose logging on)

2017-11-19 20:45:49.008 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 47: Command received zwave:device:5ddcc1cc:node47:switch_binary --> OFF
2017-11-19 20:45:49.010 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 47: Creating new message for application command SWITCH_BINARY_SET
2017-11-19 20:45:49.019 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 47: Sending REQUEST Message = 01 0A 00 13 2F 03 25 01 00 25 E0 2B
2017-11-19 20:45:49.037 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 47: Sent Data successfully placed on stack.
2017-11-19 20:45:49.058 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 47: SendData Request. CallBack ID = 224, Status = Transmission complete and ACK received(0)
2017-11-19 20:45:49.060 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Starting initialisation from DONE
2017-11-19 20:45:49.066 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 47: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-11-19 20:45:49.067 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 47: Response processed after 45ms/4921ms.

I reckon that in the previous setting, when it was responding very slowly, the value was Hail CC, and either the zwave network was loaded or openhab was doing something with the Hail CC which caused the very long delays.

The wall switch is now responding normally, for a battery powered wall controller that is.