OH2 Z-Wave refactoring and testing... and SECURITY

security
zwave
Tags: #<Tag:0x00007fd30ad7ea30> #<Tag:0x00007fd30ad7e8f0>

(Chris Jackson) #3216

I would not recommend changing this - it will not affect the polling - only (some) commanding. Since you aren’t ever commanding the device, it won’t impact anything anyway.


(Kris K) #3217

Having an issue installing the 2.4 binding…

07:03:41.208 [WARN ] [org.apache.felix.fileinstall ] - Error while starting bundle: file:/usr/share/openhab2/addons/org.openhab.binding.zwave_2.4.0.201807071112.jar
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.zwave [223]
Unresolved requirement: Import-Package: gnu.io

Any thoughts? my folder looks like this:

openhab-addons-2.3.0.kar org.openhab.binding.broadlink-2.2.0-BETA2.jar org.openhab.binding.yamahareceiver-2.3.1.jar org.openhab.binding.zwave_2.4.0.201807071112.jar README
kris@OpenHAB:/usr/share/openhab2/addons$

EDIT: Seems I needed this: feature:install openhab-transport-serial


(Chris Jackson) #3218

You need to install the serial driver -:


(Harald Resch) #3219

Hi again, i can change the polling to 2 Day, however OH does not save this. When i save the cahnges and open the Device Configuration again, the Polling is set to 1 Day…


(Chris Jackson) #3220

Well spotted - I’ll fix this. As above, I don’t think this will impact battery life, but I’ll fix it in a few days.


(Kris K) #3221

Hi Chris, think I see a bug with the binding. or perhaps its as a result of what we discussed before.

If I have a light dimmer, I switch it to 50%, it will only show a very low usage of power. Lets say its a 50 watt light, at 50% brightness, it should use say 25watts. What occurs, is it will show about 2 watts. HOWEVER, when I change the dimming function to say 75%, it will show the correct wattage for the previous change, ie NOW it shows 25watts :slight_smile:

This is reflected in the logs.

  1. I turn the light off.
14:12:39.478 [INFO ] [smarthome.event.ItemStateChangedEvent] - KitchenSw1 changed from ON to OFF
14:12:39.623 [INFO ] [smarthome.event.ItemStateChangedEvent] - KitchenDim1 changed from 47 to 0
14:12:41.136 [INFO ] [smarthome.event.ItemStateChangedEvent] - KitchenNum1 changed from 0.2 to 11.5

Odd, its still showing 11.5Watts being used despite being OFF.

I turn it ON/OFF

14:13:14.946 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'KitchenSw1' received command ON
14:13:14.949 [INFO ] [smarthome.event.ItemStateChangedEvent] - KitchenSw1 changed from OFF to ON
14:13:15.100 [INFO ] [smarthome.event.ItemStateChangedEvent] - KitchenDim1 changed from 0 to 47
14:13:15.679 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'KitchenSw1' received command OFF
14:13:15.682 [INFO ] [smarthome.event.ItemStateChangedEvent] - KitchenSw1 changed from ON to OFF
14:13:15.830 [INFO ] [smarthome.event.ItemStateChangedEvent] - KitchenDim1 changed from 47 to 0
14:13:17.339 [INFO ] [smarthome.event.ItemStateChangedEvent] - KitchenNum1 changed from 11.5 to 2.9

The light is still off, showing 2.9 watts.

I turn the light on to 100%, it should use approx 58Watts now

14:14:14.249 [INFO ] [smarthome.event.ItemStateChangedEvent] - KitchenDim1 changed from 0 to 100
14:14:14.501 [INFO ] [smarthome.event.ItemStateChangedEvent] - KitchenSw1 changed from OFF to ON
14:14:15.907 [INFO ] [smarthome.event.ItemStateChangedEvent] - KitchenNum1 changed from 2.9 to 32.6

Its showing 32.6. I bet if i turn the dimmer down to 50% (should show 25watts roughly) it will show 50 watts :slight_smile:

14:15:03.368 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'KitchenDim1' received command 50
14:15:03.373 [INFO ] [smarthome.event.ItemStateChangedEvent] - KitchenDim1 changed from 100 to 50
14:15:05.030 [INFO ] [smarthome.event.ItemStateChangedEvent] - KitchenNum1 changed from 32.6 to 40.5

Ok, it shows 40 but you can see my point (i think)

Any thoughts? a reboot of the system (whole server) changes KitchenNum1 to 0

14:48:56.749 [INFO ] [smarthome.event.ItemStateChangedEvent] - KitchenSw1 changed from ON to OFF
14:48:56.906 [INFO ] [smarthome.event.ItemStateChangedEvent] - KitchenDim1 changed from 51 to 0
14:48:58.402 [INFO ] [smarthome.event.ItemStateChangedEvent] - KitchenNum1 changed from 0.1 to 19.6

This by rights should be showing KitchenNum1 changes from 19.6 to 0

@5iver you may have an opinion on this. Am I seeing issues relating to this? https://github.com/eclipse/smarthome/issues/5674


(Scott Rushworth) #3222

I have an opinion, but everybody has one and all that… I have nothing to back it up, but I don’t think what you are seeing is related to that issue. You could confirm this by upgrading to a recent snapshot build. You didn’t mention which dimmer you are using. There may be some configuration for when it sends its reports. It may not be sending data until it changes by a certain percentage, or wattage, timing, etc. Do you see the same with more than one dimmer? I also would not be too surprised if the meter in a dimmer is not all that accurate.


(Kris K) #3223

haha! Yes, its a Fibaro Dimmer 2, latest generation D212

Yes, it will send a report if the change is 10% or more, of which it is. It does eventually update, ages after. I have the same issue on both dimmers yes.


(Scott Rushworth) #3224

Both versions of this device (1 and 2) have a lot of settings you can play with to adjust the reports, which may help.


(Chris Jackson) #3225

Please check the debug logs to see what is happening - not the event log. My guess is that there is no bug in the binding, but the device is not updating. The binding can only show the data that the device sends, so you need to find out if the device is sending the reports or not. At the moment, I can’t tell either way, but I would be very surprised if the binding is selectively not showing some updates it receives, but is showing others.


(Kris K) #3226

Everything is on default right now.

@chris OK, ill turn on zwave debug


(Kris K) #3227

@chris


17:26:00.110 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Command received zwave:device:d4900ba9:node2:switch_dimmer1 --> 50
17:26:00.113 [INFO ] [smarthome.event.ItemStateChangedEvent] - LivingRoomDim1 changed from 100 to 50
17:26:00.117 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 2: Creating new message for command SWITCH_MULTILEVEL_SET
17:26:00.117 [DEBUG] [CommandClassTransactionPayloadBuilder] - At build null
17:26:00.118 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, endpoint 1
17:26:00.119 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, instance / endpoint 1
17:26:00.119 [DEBUG] [dclass.ZWaveMultiInstanceCommandClass] - NODE 2: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
17:26:00.120 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
17:26:00.120 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
17:26:00.120 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue
17:26:00.121 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false
17:26:00.121 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 13 02 07 60 0D 01 01 26 01 32 25 46 FC
17:26:00.121 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0E 00 13 02 07 60 0D 01 01 26 01 32 25 46 FC
17:26:00.122 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
17:26:00.123 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
17:26:00.123 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
17:26:00.124 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
17:26:00.124 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
17:26:00.124 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
17:26:00.125 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
17:26:00.125 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:26:00.125 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false
17:26:00.125 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 88: Transaction Start type SendData
17:26:00.126 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling intialised at 86400 seconds - start in 86400 milliseconds.
17:26:00.129 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
17:26:00.130 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
17:26:00.130 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
17:26:00.130 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
17:26:00.131 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 88: [WAIT_RESPONSE] requiresResponse=true callback: 70
17:26:00.131 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
17:26:00.131 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 88: [WAIT_RESPONSE] requiresResponse=true callback: 70
17:26:00.131 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
17:26:00.131 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 2: sentData successfully placed on stack.
17:26:00.131 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 88: Advanced to WAIT_REQUEST
17:26:00.132 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: TID 88: Transaction not completed
17:26:00.132 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:26:00.132 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
17:26:00.146 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 46 00 00 02 AF
17:26:00.147 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=70, payload=46 00 00 02
17:26:00.148 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Request[0], dest=0, callback=70, payload=46 00 00 02
17:26:00.148 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=70, payload=46 00 00 02
17:26:00.148 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 88: [WAIT_REQUEST] requiresResponse=true callback: 70
17:26:00.149 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
17:26:00.149 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 88: [WAIT_REQUEST] requiresResponse=true callback: 70
17:26:00.149 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 88: (Callback 70)
17:26:00.149 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
17:26:00.150 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 88: callback 70
17:26:00.150 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=70, payload=46 00 00 02
17:26:00.150 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 70, Status = Transmission complete and ACK received(0)
17:26:00.150 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
17:26:00.150 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 88: Transaction COMPLETED
17:26:00.150 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Response processed after 25ms
17:26:00.151 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: TID 88: Transaction completed
17:26:00.151 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:88 DONE
17:26:00.157 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
17:26:00.157 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:26:00.159 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false


(Kris K) #3228

@chris


17:27:26.526 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling...
17:27:26.527 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:d4900ba9:node2:meter_reset
17:27:26.527 [DEBUG] [nternal.converter.ZWaveMeterConverter] - NODE 2: Generating poll message for COMMAND_CLASS_METER, endpoint 0
17:27:26.527 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:d4900ba9:node2:switch_dimmer1
17:27:26.527 [DEBUG] [verter.ZWaveMultiLevelSwitchConverter] - NODE 2: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 1
17:27:26.528 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 2: Creating new message for command SWITCH_MULTILEVEL_GET
17:27:26.528 [DEBUG] [CommandClassTransactionPayloadBuilder] - At build COMMAND_CLASS_SWITCH_MULTILEVEL
17:27:26.529 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, endpoint 1
17:27:26.529 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, instance / endpoint 1
17:27:26.530 [DEBUG] [dclass.ZWaveMultiInstanceCommandClass] - NODE 2: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
17:27:26.530 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
17:27:26.530 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
17:27:26.530 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling skipped for zwave:device:d4900ba9:node2:switch_dimmer1 on COMMAND_CLASS_BASIC
17:27:26.531 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:d4900ba9:node2:meter_kwh1
17:27:26.535 [DEBUG] [nternal.converter.ZWaveMeterConverter] - NODE 2: Generating poll message for COMMAND_CLASS_METER, endpoint 1
17:27:26.535 [DEBUG] [nternal.converter.ZWaveMeterConverter] - NODE 2: Generating poll message for COMMAND_CLASS_METER, endpoint 1
17:27:26.535 [DEBUG] [l.commandclass.ZWaveMeterCommandClass] - NODE 2: Creating new message for application command METER_GET
17:27:26.536 [DEBUG] [CommandClassTransactionPayloadBuilder] - At build COMMAND_CLASS_METER
17:27:26.536 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, endpoint 1
17:27:26.536 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, instance / endpoint 1
17:27:26.537 [DEBUG] [dclass.ZWaveMultiInstanceCommandClass] - NODE 2: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
17:27:26.539 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
17:27:26.539 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
17:27:26.540 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:d4900ba9:node2:meter_watts1
17:27:26.540 [DEBUG] [nternal.converter.ZWaveMeterConverter] - NODE 2: Generating poll message for COMMAND_CLASS_METER, endpoint 1
17:27:26.540 [DEBUG] [nternal.converter.ZWaveMeterConverter] - NODE 2: Generating poll message for COMMAND_CLASS_METER, endpoint 1
17:27:26.540 [DEBUG] [l.commandclass.ZWaveMeterCommandClass] - NODE 2: Creating new message for application command METER_GET
17:27:26.541 [DEBUG] [CommandClassTransactionPayloadBuilder] - At build COMMAND_CLASS_METER
17:27:26.544 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, endpoint 1
17:27:26.545 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, instance / endpoint 1
17:27:26.545 [DEBUG] [dclass.ZWaveMultiInstanceCommandClass] - NODE 2: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
17:27:26.545 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
17:27:26.546 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
17:27:26.551 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue
17:27:26.551 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false
17:27:26.551 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 02 06 60 0D 01 01 26 02 25 47 CE
17:27:26.552 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0D 00 13 02 06 60 0D 01 01 26 02 25 47 CE
17:27:26.553 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
17:27:26.553 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 89: Transaction Start type SendData
17:27:26.554 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
17:27:26.555 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
17:27:26.555 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
17:27:26.555 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
17:27:26.555 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
17:27:26.556 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
17:27:26.556 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:27:26.556 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false
17:27:26.560 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
17:27:26.561 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
17:27:26.561 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
17:27:26.562 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
17:27:26.562 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 89: [WAIT_RESPONSE] requiresResponse=true callback: 71
17:27:26.562 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
17:27:26.563 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 89: [WAIT_RESPONSE] requiresResponse=true callback: 71
17:27:26.563 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
17:27:26.563 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 2: sentData successfully placed on stack.
17:27:26.563 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 89: Advanced to WAIT_REQUEST
17:27:26.565 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: TID 89: Transaction not completed
17:27:26.565 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:27:26.566 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
17:27:26.566 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue
17:27:26.566 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
17:27:26.566 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue
17:27:26.567 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
17:27:26.576 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 47 00 00 02 AE
17:27:26.577 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=71, payload=47 00 00 02
17:27:26.578 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Request[0], dest=0, callback=71, payload=47 00 00 02
17:27:26.578 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=71, payload=47 00 00 02
17:27:26.579 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 89: [WAIT_REQUEST] requiresResponse=true callback: 71
17:27:26.579 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
17:27:26.579 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 89: [WAIT_REQUEST] requiresResponse=true callback: 71
17:27:26.579 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 89: (Callback 71)
17:27:26.579 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
17:27:26.580 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 89: callback 71
17:27:26.580 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=71, payload=47 00 00 02
17:27:26.580 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 71, Status = Transmission complete and ACK received(0)
17:27:26.581 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
17:27:26.581 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 89: Advanced to WAIT_DATA
17:27:26.582 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: TID 89: Transaction not completed
17:27:26.582 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:27:26.585 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
17:27:26.588 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 02 07 60 0D 01 01 26 03 32 89
17:27:26.589 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 07 60 0D 01 01 26 03 32
17:27:26.590 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 07 60 0D 01 01 26 03 32
17:27:26.591 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 07 60 0D 01 01 26 03 32
17:27:26.591 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
17:27:26.591 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
17:27:26.591 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
17:27:26.591 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
17:27:26.591 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 1
17:27:26.592 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
17:27:26.592 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT
17:27:26.592 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 2: Switch Multi Level report, value = 50
17:27:26.592 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
17:27:26.592 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_SWITCH_MULTILEVEL, value = 50
17:27:26.593 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:d4900ba9:node2:switch_dimmer1 to 50 [PercentType]
17:27:26.594 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
17:27:26.594 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@247525bc.
17:27:26.595 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@247525bc.
17:27:26.599 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:89 DONE
17:27:26.599 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
17:27:26.601 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
17:27:26.602 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
17:27:26.602 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:27:26.602 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false
17:27:26.602 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 13 02 07 60 0D 01 01 32 01 00 25 48 D4
17:27:26.602 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0E 00 13 02 07 60 0D 01 01 32 01 00 25 48 D4
17:27:26.603 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
17:27:26.604 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
17:27:26.604 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
17:27:26.604 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
17:27:26.605 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 90: Transaction Start type SendData
17:27:26.605 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
17:27:26.605 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 90: [WAIT_RESPONSE] requiresResponse=true callback: 72
17:27:26.605 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
17:27:26.608 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:27:26.609 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
17:27:26.610 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
17:27:26.611 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
17:27:26.611 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
17:27:26.611 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
17:27:26.612 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 90: [WAIT_RESPONSE] requiresResponse=true callback: 72
17:27:26.612 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
17:27:26.612 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 90: [WAIT_RESPONSE] requiresResponse=true callback: 72
17:27:26.612 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
17:27:26.612 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 2: sentData successfully placed on stack.
17:27:26.617 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 90: Advanced to WAIT_REQUEST
17:27:26.617 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: TID 90: Transaction not completed
17:27:26.620 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:27:26.620 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
17:27:26.627 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 48 00 00 02 A1
17:27:26.628 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=72, payload=48 00 00 02
17:27:26.628 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Request[0], dest=0, callback=72, payload=48 00 00 02
17:27:26.628 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=72, payload=48 00 00 02
17:27:26.628 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 90: [WAIT_REQUEST] requiresResponse=true callback: 72
17:27:26.629 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
17:27:26.629 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 90: [WAIT_REQUEST] requiresResponse=true callback: 72
17:27:26.629 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 90: (Callback 72)
17:27:26.629 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
17:27:26.629 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 90: callback 72
17:27:26.630 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=72, payload=48 00 00 02
17:27:26.630 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 72, Status = Transmission complete and ACK received(0)
17:27:26.630 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
17:27:26.630 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 90: Advanced to WAIT_DATA
17:27:26.631 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: TID 90: Transaction not completed
17:27:26.631 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:27:26.631 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
17:27:26.640 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 02 0E 60 0D 01 01 32 02 21 44 00 00 00 00 00 00 DB
17:27:26.641 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0E 60 0D 01 01 32 02 21 44 00 00 00 00 00 00
17:27:26.641 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0E 60 0D 01 01 32 02 21 44 00 00 00 00 00 00
17:27:26.641 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0E 60 0D 01 01 32 02 21 44 00 00 00 00 00 00
17:27:26.642 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
17:27:26.642 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
17:27:26.645 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
17:27:26.645 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
17:27:26.645 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_METER, endpoint 1
17:27:26.646 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY NOT required on COMMAND_CLASS_METER
17:27:26.646 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_METER V3 METER_REPORT
17:27:26.646 [DEBUG] [l.commandclass.ZWaveMeterCommandClass] - NODE 2: Meter: Type=Electric(1), Scale=kWh(0), Value=0E+1
17:27:26.647 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveMeterValueEvent
17:27:26.647 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_METER, value = 0E+1
17:27:26.647 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:d4900ba9:node2:meter_kwh1 to 0 [DecimalType]
17:27:26.651 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
17:27:26.652 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@497860c3.
17:27:26.652 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@497860c3.
17:27:26.652 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:90 DONE
17:27:26.657 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
17:27:26.657 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
17:27:26.658 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
17:27:26.658 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:27:26.658 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false
17:27:26.659 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 13 02 07 60 0D 01 01 32 01 10 25 49 C5
17:27:26.659 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0E 00 13 02 07 60 0D 01 01 32 01 10 25 49 C5
17:27:26.660 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
17:27:26.660 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 91: Transaction Start type SendData
17:27:26.661 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
17:27:26.661 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
17:27:26.661 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
17:27:26.661 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
17:27:26.662 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 91: [WAIT_RESPONSE] requiresResponse=true callback: 73
17:27:26.662 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
17:27:26.662 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:27:26.662 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
17:27:26.667 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
17:27:26.668 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
17:27:26.668 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
17:27:26.669 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
17:27:26.669 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 91: [WAIT_RESPONSE] requiresResponse=true callback: 73
17:27:26.669 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
17:27:26.669 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 91: [WAIT_RESPONSE] requiresResponse=true callback: 73
17:27:26.669 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
17:27:26.670 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 2: sentData successfully placed on stack.
17:27:26.671 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 91: Advanced to WAIT_REQUEST
17:27:26.671 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: TID 91: Transaction not completed
17:27:26.671 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:27:26.672 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
17:27:26.684 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 49 00 00 02 A0
17:27:26.684 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=73, payload=49 00 00 02
17:27:26.685 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Request[0], dest=0, callback=73, payload=49 00 00 02
17:27:26.685 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=73, payload=49 00 00 02
17:27:26.685 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 91: [WAIT_REQUEST] requiresResponse=true callback: 73
17:27:26.686 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
17:27:26.686 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 91: [WAIT_REQUEST] requiresResponse=true callback: 73
17:27:26.686 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 91: (Callback 73)
17:27:26.686 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
17:27:26.686 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 91: callback 73
17:27:26.686 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=73, payload=49 00 00 02
17:27:26.687 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 73, Status = Transmission complete and ACK received(0)
17:27:26.687 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
17:27:26.687 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 91: Advanced to WAIT_DATA
17:27:26.687 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: TID 91: Transaction not completed
17:27:26.687 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:27:26.687 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
17:27:26.697 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 12 00 04 00 02 0C 60 0D 01 01 32 02 21 32 00 96 00 00 3F
17:27:26.698 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0C 60 0D 01 01 32 02 21 32 00 96 00 00
17:27:26.698 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0C 60 0D 01 01 32 02 21 32 00 96 00 00
17:27:26.698 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0C 60 0D 01 01 32 02 21 32 00 96 00 00
17:27:26.699 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
17:27:26.699 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
17:27:26.699 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
17:27:26.700 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
17:27:26.700 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_METER, endpoint 1
17:27:26.700 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY NOT required on COMMAND_CLASS_METER
17:27:26.700 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_METER V3 METER_REPORT
17:27:26.701 [DEBUG] [l.commandclass.ZWaveMeterCommandClass] - NODE 2: Meter: Type=Electric(1), Scale=W(2), Value=15
17:27:26.702 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveMeterValueEvent
17:27:26.705 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_METER, value = 15
17:27:26.706 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:d4900ba9:node2:meter_watts1 to 15 [DecimalType]
17:27:26.710 [INFO ] [smarthome.event.ItemStateChangedEvent] - LivingRoomNum1 changed from 26.5 to 15
17:27:26.711 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
17:27:26.711 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@3261bb26.
17:27:26.711 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@3261bb26.
17:27:26.712 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:91 DONE
17:27:26.719 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
17:27:26.720 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
17:27:26.720 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
17:27:26.720 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:27:26.720 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false



(Chris Jackson) #3229

Can you comment on what are you trying to show in this log and why it shows that it there is a bug in the binding? There is no metering data coming from the device in this log - just a command to set the dimmer level.

If you think there’s a bug in the binding, then you need to show a log that shows incoming meter data, that does not get converted into a channel update.


(Kris K) #3230

Hi Chris, forgive me. I’ve got no idea what im doing , ill be frank. I’m trying , unsuccessfully to determine why updates to the Watt usage on this Dimmer is not happening when I make a change to the Dimmer brightness. It takes ages to do so - as I understand it, it should be instant. I know there are periodic updates and there are timers and changes in terms of % that triggers that but I believe these changes I make manually should be instant.

They clearly arent. I’ve no idea what the issue is.


(Chris Jackson) #3231

No problem. I suggest to get a long log and use the online log viewer to view it. Use the Filters tab to select the node you want to view, and then look through the list to see if there is meter data being received. I guess there will be, but probably not as often as you want.

There are 2 possible reasons I can think of. If you don’t receive any unsolicited meter data (ie data that is not gathered by the binding requesting it), then possibly this is related to associations not being configured. If you are receiving meter data, but just not as often as you want, then this is likely down to the settings in the device.

From what you’ve said so far, you are receiving meter data - you should check if this comes as a result of the binding sending a GET command immediately before (or not).

I hope this helps - I’m happy to look over logs if you have any questions… If you want to gather a long log (let’s say a couple of hours) then I’m also happy to look over it.


(Kris K) #3232

Thanks Chris.

Im definitely in the later, basically I don’t receive the data frequently enough.

Am i right in saying the normal behaviour is if you make a change to a dimmer it should reflect immediately?

I think the data is being received

21:25:28.229 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
21:25:28.229 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
21:25:28.229 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
21:25:28.230 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
21:25:28.230 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_METER, endpoint 1
21:25:28.230 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY NOT required on COMMAND_CLASS_METER
21:25:28.230 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_METER V3 METER_REPORT
21:25:28.230 [DEBUG] [l.commandclass.ZWaveMeterCommandClass] - NODE 2: Meter: Type=Electric(1), Scale=W(2), Value=13.8
21:25:28.231 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveMeterValueEvent
21:25:28.231 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_METER, value = 13.8
21:25:28.231 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:d4900ba9:node2:meter_watts1 to 13.8 [DecimalType]
21:25:28.232 [INFO ] [smarthome.event.ItemStateChangedEvent] - LivingRoomNum1 changed from 5.9 to 13.8
21:25:28.233 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
21:25:28.233 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@5a861754.
21:25:28.233 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@5a861754.
21:25:28.233 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:126 DONE
21:25:28.233 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
21:25:28.234 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
21:25:28.234 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
21:25:28.234 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
21:25:28.234 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false

(Chris Jackson) #3233

Yes - if you send a command to the dimmer, it should change immediately. Is that not happening? I thought that controlling the device was ok, but it’s just the meter readings you weren’t receiving?


(Kris K) #3234

Sorry Chris, yes controlling the device is faultless. Meter readings are problematic. They work, just slowly. I tried changing my settings to be aggressive for what relates to power reports, the issue remains.


(Chris Jackson) #3235

In the last log you show a meter report - can you provide 10 seconds of data from immediately before this log entry?