Zwave binding and security issues

meschmesch · August 20, 2017, 7:41pm

Hi, I am using zwave-2.1.0-SNAPSHOT together with Fibaro Switch 2 (FGS 213 and FGS 223).

In non-secure binding (in habmin) I can receive the input of the S1 switch via an item in openhab. This means I can read that voltage by e.g. turning on the light was applied to the S1 input of the Fibaro Switch. Applying the voltage to the S1 input also correctly directly triggers the switch itself. The switch can correctly be controlled by items and switches via openhab.
In secure binding (also in habmin), the S1 input is completely non-reporting to openhab. This means that any items relating to the S1 switch always remain on “null” (instead of being off or on). Still, even in secure binding the input of the S1 correctly triggers the switch itself. Nevertheless, the switch can correctly be controlled by items and switches via openhab (some features are not working like the change of the switch type to switch type “toggle switch” or “momentary switch”.

Thus, this seems to be a problem of the secure binding implementation in openhab.
How can I solve that issue?

Thanks!!
Meschmesch

sihui · August 20, 2017, 8:18pm

As far as I understand the manual this is not possible at all:

Associations in Z-Wave network security mode
This parameter defnes how commands are sent in specifed association groups: as secure or non-secure. Parameter is active only in
Z-Wave network security mode. This parameter does not apply to 1st
„lifeline” group.

meschmesch · August 20, 2017, 9:16pm

I don’t understand what this has to do with the sending of information itself? This only means that for the Lifeline group there is no choice in sending information secure our non secure. This does not seem to state that in secure mode no information at all is transmitted on the Lifeline…

meschmesch · August 22, 2017, 7:35am

Update: The problem additionally seems to me somewhere else. Does someone have a working configuration for the Fibaro FGS 223 Switch which permits to get status updates on the physical S2 switch?

I have an item like

Switch Light_Status	{channel="zwave:device:12db123f123:node36:switch_binary2"}

However, it allways reports “NULL”. The same with binary1.

meschmesch · August 22, 2017, 9:23pm

Next Update: I switched to non-secure binding to make it more easy. In Debug mode I can see that there is no reporting on status updates on any physical events on the physical S2 switch unless the association group “On/Off (S2)” is set to OpenHabController. However, it seems like the status updates are not reported as originating from the S2 switch?!

NODE 36: Application Command Request (ALIVE:DONE)
NODE 36: resetResendCount initComplete=true isDead=false
NODE 36: Incoming command class COMMAND_CLASS_BASIC, endpoint 0
NODE 36: SECURITY NOT required on COMMAND_CLASS_BASIC
NODE 36: Received COMMAND_CLASS_BASIC V1 BASIC_SET
NODE 36: Basic report, value = 0
Notifying event listeners: ZWaveCommandClassValueEvent
NODE 36: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
NODE 36: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_BASIC, value = 0
NODE 36: Updating channel state zwave:device:23ff142c123:node36:switch_binary to OFF [OnOffType]
NODE 36: Commands processed 1.
NODE 36: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@12ba63d.
Transaction completed - outstandingTransactions 0

This drives me crazy. Can anyone please help me I appreciate that…
Mesch.

sihui · August 23, 2017, 3:43pm

Actually I cannot follow what you want to achieve, sorry.

This is my FGS223 setup and event.log (zwave security binding 20170818, node not included with security):

Switch FibFGS223_1_Sw_1 "Living Wallplugs" (gRestore) { channel="zwave:device:15ca6a108b9:node30:switch_binary1" }
Switch FibFGS223_1_Sw_2 "Dining Wallplugs" (gRestore) { channel="zwave:device:15ca6a108b9:node30:switch_binary2" }
Number FibFGS223_1_Scenes "Scenes Wallplugs [%d]" { channel="zwave:device:15ca6a108b9:node30:scene_number" }

2017-08-22 20:23:20.361 [ItemStateChangedEvent     ] - FibFGS223_1_Sw_2 changed from OFF to ON
2017-08-22 20:23:20.822 [ItemStateChangedEvent     ] - FibFGS223_1_Sw_1 changed from OFF to ON
2017-08-22 20:23:20.883 [ItemStateChangedEvent     ] - FibFGS223_1_Scenes changed from 2.0 to 1.0
2017-08-22 23:27:09.113 [ItemStateChangedEvent     ] - FibFGS223_1_Sw_1 changed from ON to OFF
2017-08-22 23:27:09.985 [ItemStateChangedEvent     ] - FibFGS223_1_Sw_2 changed from ON to OFF
2017-08-22 23:27:10.043 [ItemStateChangedEvent     ] - FibFGS223_1_Scenes changed from 1.0 to 2.0

That is everything I need. So what does not work for you?

meschmesch · August 23, 2017, 9:02pm

Hi sihui,

I have the same items as you (see post #4) but for whatever reason I do not receive any events or status updates for binary1 and binary2. I receive NO status updates at all at openhab in case the S2 input is triggered by an external switch. I receive status updates only for node36:switch_binary in case the S1 input is triggered by an external switch - but still the node36:switch_binary1 is silent (always NULL). So it seems like node36:switch_binary1 and node36:switch_binary2 are not reported to openhab.

The same problem is with a FGS 213 which has only one input S1. node34:switch_binary is reporting correct values, node36:switch_binary1 is silent. In case of the FGS213 this does not matter, since binary and binary1 are identical. But in case of the FGS 223 this means that S2 is not accessable.

I know I appear pretty stupid here, but I would appreciate some guidance how to solve that problem, i.e. to also monitor status updates on node36:switch_binary1 and node36:switch_binary2.

Thank you sihui!

sihui · August 24, 2017, 3:36pm

If you switch between the development/security binding to the snapshot or stable binding, you have to delete all things and re-add them. Same thing applies vica versa.

Did you change any configuration parameters? For reference here are my config parameters (I’m using the development binding):

meschmesch · August 24, 2017, 8:13pm

Hi sihui,

wrong formulation from my side. I use the snapshot security binding with nodes included in mixture, with and without security. The FGS 213 and 223 we are currently talking about are inclued without security and in direct communication with the controller.

I use exact the same configuration parameters as you have, but binary1 and binary 2 remain silent.

So, same device, same parameters similar items, but no response.

I assume that it is possible to have some nodes included with security and some others without (not entry nodes but arbitrary nodes that were included while the controller was set to “always include with security”).

Thanks,
Michael

sihui · August 25, 2017, 6:30am

I’m pretty sure that is possible, although I did not test that, I’m using the refactored binding without any securely included nodes.
I guess the only chance to solve that problem is to provide a debug log (don’t edit it like in your above post, leave it the way it is) and then ping @chris so he can have a look at it.
Meanwhile you may run your debug log through the zwave log viewer, that’s a lot easier to read

chris · August 25, 2017, 7:03am

Yes - this is normally the case so there will be no problem with this situation.

meschmesch · August 25, 2017, 3:40pm

Hello @sihui and @chris ,

here is the debug log. It is about node 36 (FGS 223). Voltage was applied manually to input 2 at 17:31:39, and voltage was removed from input 2 at 17:31:45 (corresponding to turn on / turn off).

2017-08-25 17:31:39.883 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 24 05 5B 03 20 00 02 AB
2017-08-25 17:31:39.892 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-08-25 17:31:39.896 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=36, callback=0, payload=00 24 05 5B 03 20 00 02
2017-08-25 17:31:39.899 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=36, callback=0, payload=00 24 05 5B 03 20 00 02
2017-08-25 17:31:39.901 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=36, callback=0, payload=00 24 05 5B 03 20 00 02
2017-08-25 17:31:39.908 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2017-08-25 17:31:39.910 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Application Command Request (ALIVE:DONE)
2017-08-25 17:31:39.911 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: resetResendCount initComplete=true isDead=false
2017-08-25 17:31:39.912 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: Incoming command class COMMAND_CLASS_CENTRAL_SCENE, endpoint 0
2017-08-25 17:31:39.913 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: SECURITY NOT required on COMMAND_CLASS_CENTRAL_SCENE
2017-08-25 17:31:39.915 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 36: Received COMMAND_CLASS_CENTRAL_SCENE V2 CENTRAL_SCENE_NOTIFICATION
2017-08-25 17:31:39.917 [DEBUG] [dclass.ZWaveCentralSceneCommandClass] - NODE 36: Received scene 2 at key 0 [Single Press]
2017-08-25 17:31:39.918 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2017-08-25 17:31:39.920 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2017-08-25 17:31:39.922 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_CENTRAL_SCENE, value = 2.0
2017-08-25 17:31:39.924 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Updating channel state zwave:device:15db442c729:node36:scene_number to 2.0 [DecimalType]
2017-08-25 17:31:39.926 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Commands processed 1.
2017-08-25 17:31:39.927 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@116db75.
2017-08-25 17:31:39.928 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2017-08-25 17:31:39.929 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2017-08-25 17:31:39.931 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-08-25 17:31:39.932 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-08-25 17:31:39.933 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-08-25 17:31:39.933 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2017-08-25 17:31:43.902 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 30: Requesting IsFailedNode status from controller.
2017-08-25 17:31:43.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@169d986
2017-08-25 17:31:43.905 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2017-08-25 17:31:43.906 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
2017-08-25 17:31:43.907 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-08-25 17:31:43.908 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-08-25 17:31:43.909 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2017-08-25 17:31:43.912 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 1E 87
2017-08-25 17:31:43.914 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 1E 87
2017-08-25 17:31:43.915 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2017-08-25 17:31:43.916 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2307: Transaction Start type IsFailedNodeID
2017-08-25 17:31:43.918 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-08-25 17:31:43.918 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2307: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-08-25 17:31:43.919 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2017-08-25 17:31:43.920 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-08-25 17:31:43.920 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2017-08-25 17:31:43.921 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2017-08-25 17:31:43.921 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-08-25 17:31:43.924 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-08-25 17:31:43.925 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2017-08-25 17:31:43.926 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 01 99
2017-08-25 17:31:43.926 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2017-08-25 17:31:43.927 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-08-25 17:31:43.930 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Aug 25 17:31:45 CEST 2017 - 1999ms
2017-08-25 17:31:43.931 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-08-25 17:31:43.929 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-08-25 17:31:43.928 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 2: Requesting IsFailedNode status from controller.
2017-08-25 17:31:43.934 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1c51cfb
2017-08-25 17:31:43.931 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 2307: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-08-25 17:31:43.935 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-08-25 17:31:43.937 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Aug 25 17:31:45 CEST 2017 - 1986ms
2017-08-25 17:31:43.934 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01
2017-08-25 17:31:43.938 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2017-08-25 17:31:43.940 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
2017-08-25 17:31:43.940 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01
2017-08-25 17:31:43.941 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-08-25 17:31:43.941 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-08-25 17:31:43.942 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-08-25 17:31:43.944 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Aug 25 17:31:45 CEST 2017 - 1978ms
2017-08-25 17:31:43.945 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-08-25 17:31:43.946 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 28: Requesting IsFailedNode status from controller.
2017-08-25 17:31:43.946 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01
2017-08-25 17:31:43.948 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2307: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-08-25 17:31:43.948 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1a0717f
2017-08-25 17:31:43.951 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-08-25 17:31:43.953 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Aug 25 17:31:45 CEST 2017 - 1969ms
2017-08-25 17:31:43.955 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2017-08-25 17:31:43.956 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 2
2017-08-25 17:31:43.958 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2017-08-25 17:31:43.958 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-08-25 17:31:43.959 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2307: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-08-25 17:31:43.961 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-08-25 17:31:43.962 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01
2017-08-25 17:31:43.962 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-08-25 17:31:43.963 [WARN ] [rialmessage.IsFailedNodeMessageClass] - NODE 30: Is currently marked as failed by the controller!
2017-08-25 17:31:43.964 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Aug 25 17:31:45 CEST 2017 - 1959ms
2017-08-25 17:31:43.965 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2307: Transaction COMPLETED
2017-08-25 17:31:43.966 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2307: TransactionAdvance ST: DONE
2017-08-25 17:31:43.967 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2307: TransactionAdvance WT: null {}
2017-08-25 17:31:43.969 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2307: TransactionAdvance RX: Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01
2017-08-25 17:31:43.971 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2307: TransactionAdvance TO: DONE
2017-08-25 17:31:43.972 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 56ms
2017-08-25 17:31:43.973 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 2307: Transaction completed
2017-08-25 17:31:43.974 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2307 DONE
2017-08-25 17:31:43.976 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-08-25 17:31:43.976 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 2307: Transaction event listener: DONE: DONE ->
2017-08-25 17:31:43.977 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-08-25 17:31:43.978 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: -- To notify -- COMPLETE
2017-08-25 17:31:43.978 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-08-25 17:31:43.979 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-08-25 17:31:43.980 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete 2307 --
2017-08-25 17:31:43.981 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2017-08-25 17:31:43.981 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 30: Node Init response (0) COMPLETE
2017-08-25 17:31:43.987 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 30: Node Init transaction completed with response COMPLETE
2017-08-25 17:31:43.988 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 02 9B
2017-08-25 17:31:43.990 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 02 9B
2017-08-25 17:31:43.992 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2017-08-25 17:31:43.994 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2308: Transaction Start type IsFailedNodeID
2017-08-25 17:31:43.995 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2308: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-08-25 17:31:43.995 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-08-25 17:31:43.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2017-08-25 17:31:43.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2017-08-25 17:31:43.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-08-25 17:31:43.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2017-08-25 17:31:44.000 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-08-25 17:31:44.000 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-08-25 17:31:44.001 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Aug 25 17:31:46 CEST 2017 - 1999ms
2017-08-25 17:31:44.002 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 2308: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-08-25 17:31:44.003 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 01 99
2017-08-25 17:31:44.003 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-08-25 17:31:44.004 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Aug 25 17:31:46 CEST 2017 - 1996ms
2017-08-25 17:31:44.004 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-08-25 17:31:44.005 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-08-25 17:31:44.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01
2017-08-25 17:31:44.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2308: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-08-25 17:31:44.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01
2017-08-25 17:31:44.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2017-08-25 17:31:44.008 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01
2017-08-25 17:31:44.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2308: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-08-25 17:31:44.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2017-08-25 17:31:44.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2308: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-08-25 17:31:44.013 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01
2017-08-25 17:31:44.014 [WARN ] [rialmessage.IsFailedNodeMessageClass] - NODE 2: Is currently marked as failed by the controller!
2017-08-25 17:31:44.015 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2308: Transaction COMPLETED
2017-08-25 17:31:44.016 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2308: TransactionAdvance ST: DONE
2017-08-25 17:31:44.017 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2308: TransactionAdvance WT: null {}
2017-08-25 17:31:44.018 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2308: TransactionAdvance RX: Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01
2017-08-25 17:31:44.019 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2308: TransactionAdvance TO: DONE
2017-08-25 17:31:44.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 26ms
2017-08-25 17:31:44.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 2308: Transaction completed
2017-08-25 17:31:44.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2308 DONE
2017-08-25 17:31:44.024 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-08-25 17:31:44.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 2308: Transaction event listener: DONE: DONE ->
2017-08-25 17:31:44.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-08-25 17:31:44.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: -- To notify -- COMPLETE
2017-08-25 17:31:44.026 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-08-25 17:31:44.028 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete 2308 --
2017-08-25 17:31:44.028 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-08-25 17:31:44.029 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Init response (0) COMPLETE
2017-08-25 17:31:44.032 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Init transaction completed with response COMPLETE
2017-08-25 17:31:44.033 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2017-08-25 17:31:44.035 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 1C 85
2017-08-25 17:31:44.036 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 1C 85
2017-08-25 17:31:44.038 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2017-08-25 17:31:44.039 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2309: Transaction Start type IsFailedNodeID
2017-08-25 17:31:44.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2309: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-08-25 17:31:44.040 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-08-25 17:31:44.041 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2017-08-25 17:31:44.042 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-08-25 17:31:44.042 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2017-08-25 17:31:44.043 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2017-08-25 17:31:44.043 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-08-25 17:31:44.044 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-08-25 17:31:44.045 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Aug 25 17:31:46 CEST 2017 - 1999ms
2017-08-25 17:31:44.046 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 01 99
2017-08-25 17:31:44.046 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 2309: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-08-25 17:31:44.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-08-25 17:31:44.048 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-08-25 17:31:44.048 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Aug 25 17:31:46 CEST 2017 - 1996ms
2017-08-25 17:31:44.050 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-08-25 17:31:44.050 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01
2017-08-25 17:31:44.051 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2309: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-08-25 17:31:44.052 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01
2017-08-25 17:31:44.052 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2017-08-25 17:31:44.053 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01
2017-08-25 17:31:44.054 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2309: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-08-25 17:31:44.055 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2017-08-25 17:31:44.056 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2309: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-08-25 17:31:44.058 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01
2017-08-25 17:31:44.059 [WARN ] [rialmessage.IsFailedNodeMessageClass] - NODE 28: Is currently marked as failed by the controller!
2017-08-25 17:31:44.060 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2309: Transaction COMPLETED
2017-08-25 17:31:44.061 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2309: TransactionAdvance ST: DONE
2017-08-25 17:31:44.061 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2309: TransactionAdvance WT: null {}
2017-08-25 17:31:44.063 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2309: TransactionAdvance RX: Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01
2017-08-25 17:31:44.063 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2309: TransactionAdvance TO: DONE
2017-08-25 17:31:44.064 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 26ms
2017-08-25 17:31:44.065 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 2309: Transaction completed
2017-08-25 17:31:44.066 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2309 DONE
2017-08-25 17:31:44.067 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-08-25 17:31:44.067 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 2309: Transaction event listener: DONE: DONE ->
2017-08-25 17:31:44.068 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-08-25 17:31:44.068 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: -- To notify -- COMPLETE
2017-08-25 17:31:44.069 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-08-25 17:31:44.069 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-08-25 17:31:44.069 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete 2309 --
2017-08-25 17:31:44.072 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2017-08-25 17:31:44.072 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 28: Node Init response (0) COMPLETE
2017-08-25 17:31:44.073 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-08-25 17:31:44.073 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 28: Node Init transaction completed with response COMPLETE
2017-08-25 17:31:45.764 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 24 05 5B 03 21 00 02 AA
2017-08-25 17:31:45.770 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-08-25 17:31:45.774 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=36, callback=0, payload=00 24 05 5B 03 21 00 02
2017-08-25 17:31:45.777 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=36, callback=0, payload=00 24 05 5B 03 21 00 02
2017-08-25 17:31:45.779 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=36, callback=0, payload=00 24 05 5B 03 21 00 02
2017-08-25 17:31:45.781 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2017-08-25 17:31:45.782 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Application Command Request (ALIVE:DONE)
2017-08-25 17:31:45.783 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: resetResendCount initComplete=true isDead=false
2017-08-25 17:31:45.785 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: Incoming command class COMMAND_CLASS_CENTRAL_SCENE, endpoint 0
2017-08-25 17:31:45.786 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: SECURITY NOT required on COMMAND_CLASS_CENTRAL_SCENE
2017-08-25 17:31:45.788 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 36: Received COMMAND_CLASS_CENTRAL_SCENE V2 CENTRAL_SCENE_NOTIFICATION
2017-08-25 17:31:45.789 [DEBUG] [dclass.ZWaveCentralSceneCommandClass] - NODE 36: Received scene 2 at key 0 [Single Press]
2017-08-25 17:31:45.791 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2017-08-25 17:31:45.792 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2017-08-25 17:31:45.793 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_CENTRAL_SCENE, value = 2.0
2017-08-25 17:31:45.796 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Updating channel state zwave:device:15db442c729:node36:scene_number to 2.0 [DecimalType]
2017-08-25 17:31:45.797 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Commands processed 1.
2017-08-25 17:31:45.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@126bbd8.
2017-08-25 17:31:45.799 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2017-08-25 17:31:45.800 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2017-08-25 17:31:45.801 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-08-25 17:31:45.803 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-08-25 17:31:45.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-08-25 17:31:45.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing

Is that of any help?
Thank you! Michael

chris · August 25, 2017, 3:46pm

The device is using the CENTRAL_SCENE class (ie it’s being used as a scene controller) - and you’re expecting it to be used as a switch if I understand correctly? I guess there is a configuration parameter (or two) to change the way this works?

Maybe @sihui is more familiar with this device than me…

sihui · August 25, 2017, 4:49pm

That is the reason I posted my config above. From what I can see in my logs the switch is using multi channel encapsulation, so it should properly report on the switch_binaryX class.

This are the logs in comparison:

Michael’s log

My log:

The only config parameter I changed from the default settings are no. 28 and 29 so I can catch the scene numbers.

@meschmesch, please compare again the settings and make sure you only have set association group 1 to lifeline and no other association groups to any node.

Strange thing is I cannot properly filter the nodes on @meschmesch debug log …

chris · August 25, 2017, 4:51pm

Yes - I also noticed there’s something a bit strange there… I think there’s something not 100% right in the log filter routine…

sihui · August 25, 2017, 4:52pm

but it worked fine on my debug log …

chris · August 25, 2017, 4:53pm

Yes - it works fine most of the time, but I’ve seen issues where it’s not filtering properly in the past. I think that it’s seeing these as controller commands so they aren’t being filtered correctly. Normal commands to a device are ok.

chris · August 25, 2017, 5:16pm

It should be fixed now…

sihui · August 25, 2017, 5:20pm

Yepp, confirmed. That narrows down @meschmesch log to:

meschmesch · August 25, 2017, 6:00pm

Hi @chris & @sihui
I confirm that association groups are set identical to the ones provided by sihui.