ItemState not updated from manual operating on Z-Wave switch

[mythbai (cybermyth)]

I’m currently on OH2 nightly snapshot build: 2.1.0~20170313143628-1, and found an problem for almost all my zwave switches: If I manually turn on/off switches, the ItemStateChangedEvent fire up inconsistently.

1. GE Z-Wave wall switches: If I long press (1+ seconds) the paddle to turn switch ON/OFF, there is no state event fired (while the physical switch is turned on correctly). And the subsequent OFF/ON operation will be ignored in OH too.

2. Aeon Lab Energy smart outlet: Short press to switch ON/OFF even give me the same problem 60% of the time.

I’m not using slave/auxiliary switches, so ZWAVE signal should be fired by the primary switches in my cases. Is this a known binding issue or just my particular version? I’m still new to OH and in the processing transitioning from ST to OH2, so I can’t say much about if this problem exist for older version.

[chris (Chris Jackson)]

I would check that all your associations are correctly configured. If you’ve got two controllers in the system, you will likely have problems as many devices only allow a single node for reporting events to a master controller via a “lifeline” group. This is the usual reason that people report this sort of issue.

If everything looks like it is configured correctly then you should get a debug log to see what’s being received and we can then look at what’s not being processed correctly.

[mythbai (cybermyth)]

I only got one controller. Which is a Sigma USB ZWave stick on RPi 3.

Here is what I captured in logs. With NODE 13 (my ZW_Office_Light) initially off. I started with a long press to turn the light on, and a short press to off. It looks like Off event is captured, but not ON though. Please kindly take a look.

01:04:15.831 [INFO ] [marthome.event.ItemStateChangedEvent] - ZW_Office_Light changed from ON to OFF
01:04:20.378 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 49 84 0D 0A 04 10 01 25 27 73 70 86 72 77 B2
01:04:20.400 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:04:20.402 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 10 00 49 84 0D 0A 04 10 01 25 27 73 70 86 72 77 B2
01:04:20.403 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 10 00 49 84 0D 0A 04 10 01 25 27 73 70 86 72 77 B2
01:04:20.405 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, callback=0, payload=84 0D 0A 04 10 01 25 27 73 70 86 72 77
01:04:20.406 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 13: Application update request. Node information received.
01:04:20.407 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Starting initialisation from DONE
01:04:20.408 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@f1f9f8 already registered
01:04:20.409 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 13: Application update request. Requesting node state.
01:04:20.411 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveDelayedPollEvent
01:04:20.412 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Got an event from Z-Wave network: ZWaveDelayedPollEvent
01:04:20.413 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Polling intialised at 1800 seconds - start in 75 milliseconds.
01:04:20.415 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=13, callback=222, payload=0D 02 25 02
01:04:20.416 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, callback=0, payload=84 0D 0A 04 10 01 25 27 73 70 86 72 77
01:04:20.418 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationUpdate, callback id=222, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
01:04:20.488 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Polling...
01:04:20.489 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Polling zwave:device:92d3e080:node13:switch_binary
01:04:20.489 [DEBUG] [converter.ZWaveBinarySwitchConverter] - NODE 13: Generating poll message for SWITCH_BINARY, endpoint 0
01:04:20.490 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 13: Creating new message for application command SWITCH_BINARY_GET
01:04:20.491 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
01:04:20.491 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
01:04:20.495 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 0D 02 25 02 25 DF 37
01:04:20.496 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 13: Sending REQUEST Message = 01 09 00 13 0D 02 25 02 25 DF 37
01:04:20.509 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
01:04:20.512 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:04:20.513 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
01:04:20.514 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
01:04:20.515 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
01:04:20.516 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 13: Sent Data successfully placed on stack.
01:04:20.525 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 13 DF 00 36
01:04:20.527 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:04:20.528 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 13 DF 00 00 00 34
01:04:20.530 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 13 DF 00 00 00 34
01:04:20.531 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=DF 00
01:04:20.532 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 13: SendData Request. CallBack ID = 223, Status = Transmission complete and ACK received(0)
01:04:20.533 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Starting initialisation from DONE
01:04:20.535 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@f1f9f8 already registered
01:04:20.536 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=13, callback=223, payload=0D 02 25 02
01:04:20.537 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=DF 00
01:04:20.538 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 0D 03 25 03 00 DA
01:04:20.539 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=223, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
01:04:20.540 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
01:04:20.541 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 0D 03 25 03 00 DA
01:04:20.543 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 0D 03 25 03 00 DA
01:04:20.544 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 0D 03 25 03 00
01:04:20.545 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 13: Application Command Request (ALIVE:DONE)
01:04:20.546 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Starting initialisation from DONE
01:04:20.547 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@f1f9f8 already registered
01:04:20.548 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 13: Incoming command class SWITCH_BINARY
01:04:20.549 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 13
01:04:20.550 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 13: Switch Binary report, value = 0
01:04:20.551 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
01:04:20.552 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
01:04:20.553 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 0
01:04:20.555 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Updating channel state zwave:device:92d3e080:node13:switch_binary to OFF [OnOffType]
01:04:20.561 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=13, callback=223, payload=0D 02 25 02
01:04:20.562 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 0D 03 25 03 00
01:04:20.563 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=223, expected=ApplicationCommandHandler, cancelled=false        transaction complete!
01:04:20.564 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
01:04:20.565 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
01:04:20.567 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 13: Response processed after 69ms/4710ms.

EDIT: I updated the log, to include my intial TURN OFF. So that you can see clearer. I think there is no DEBUG log spit out with turning ON the switch. But only with turning off. I’ll test more, and post the logs and my observation. (I have a lot other ZWAVE switches spitting a lot of debugs in the same time.)

[mythbai (cybermyth)]

Okay, after more testing, I can be pretty certain that long pressing my GE switch’s paddle doesn’t generating any debug log entry. It’s only when I short press it does.

I’m started to thinking maybe this is a problem with my Z-stick. cuz I haven’t experiencing this with my SmartThings controller before. This is the USB stick I’m using: Sigma Designs Inc. ACC-UZB2-U

[mythbai (cybermyth)]

I found where the problem is. After re-pair the switch to SmartThings hub, similar behavior presents, but instead of no state updates, but there is about 5-6 seconds delay of the updates after GE switches are physically long pressed. This is same as I press the add-on switches.

So the conclusion is that all my GE switches (haven’t tested other aeon lab outlets yet) will not emitting Z-Wave signal if I long press the paddle. Maybe some members in the forum can confirm this behavior of other Zwave switches.

Solution: I don’t know how SmartThings hub is handling this. But with OH2 on RPi 3, I can only think of changing the polling period of switches in the device configuration through HABMin. Currently the lowest number seems to be 15 seconds, and in reality it give me around 10 seconds delay (vs. SmartThings about 6 seconds)

Considering Smartthing is updating status through cloud, it’s still faster than my OH set up. I’m wondering is there another way to make this polling faster, without impacting too much on the overall system performance.

[chris (Chris Jackson)]

I could look to reduce the minimum polling - I set it to 15 seconds as a good compromise (in my opinion at least) - what we used to see on OH1 is people don’t understand they should use associations, so they set polling to a high rate on every device, and then complain when things don’t work so well…

The first question though is if there is ANY message sent when you do this long press - there are other means to detect changes. There’s a NIF received in your log so it might be possible to do something with that but it’s a bit of a change to the binding…

Let’s see what others say and we can maybe address this again…

Log for my future reference -:

[mythbai (cybermyth)]

Thanks a lot Chris!

The first question though is if there is ANY message sent when you do this long press

I only turned on the DEBUG log of zwave binding, and I cannot see any message at all if I keep long pressing these switches. (0.5 seconds+) I hope I can have some physical digital tester to verify this. It’s just so weird a manufacture would design product these way.

what we used to see on OH1 is people don’t understand they should use associations

I never used association before, but it looks like there is no such configuration in Habmin 2 binding any more? After I read some old openhab1 document, it sounds promising. Maybe I should install OH1 just for testing this?

[chris (Chris Jackson)]

I cannot see any message at all if I keep long pressing these switches.

Hmmm - ok, I thought that the log above was with a long press and there is a NIF reported. I’d assumed (maybe incorrectly?) that this was related.

I never used association before, but it looks like there is no such configuration in Habmin 2 binding any more?

Associations are a feature of the device, but OH2 of course allows you to configure them if the device supports it. It’s a very fundimental part of ZWave -:

[mythbai (cybermyth)]

I thought that the log above was with a long press

Sorry but I should mention that I pressed “normally” 5 seconds later, to flip light OFF. there is 5 seconds gap there, is me waited a couple seconds for long pressing to spit out messages.

Associations are a feature of the device

No wonder I couldn’t see it on my BINARY_SWITCH. So it’s not working in this case. I guess only option for me is to use 15 seconds. But I think it’s better if allow smaller number, so that ppl can decide what work best for them?

[mythbai (cybermyth)]

BTW, if anyone is interested, I just want to share how I came upon this problem.

I had a Disable_Kids_Light switch and rule that “disable” kids’ room light after 10:00PM. As I can’t really disable the switch, a rule is used to detect switch ON change event after 10PM and turn switch OFF immediately.

This played well before in SmartThings, and kids knew that and didn’t bother trying. Until they heard I had switched the platform, and last night I was surprised my elder son’s room’s light was ON while my rule was supposed to kick in. Then my son was very excited to show me he became a hacker and found a “way” to hack my system. There you go, long press is the key.

Not any more, after setting the polling period to 15, they now know the light will stay on for 10 seconds only. lol.