Light group works intermittently

Setup, Configuration and Use Scripts & Rules
1

Hi
I’m on 2.4.0, Rpi 2.

I have my lights assigned to groups, max three layers - e.g.
gLightsAll
gLightsEast
gLightsEastSome

My problem is that when I turn lights off using gLightsAll at night, sometimes some lights stays on. All lights never turn off immediately. Some do, but some can take a while before they turn off. It’s always the same lights that are slow or not responding - it’s those in the bottom hierarchy - gLightsEastSome that don’t work reliably.

There’s no issue turning them off individually or through the sub group. Always working, always immediate response. I don’t know how to troubleshoot this or if there’s any other way to set this up. It’s a fairly simple setup I guess.

All my lights with issues are Z-wave devices (Fibaro plugs). I never had any issues with this until I installed MQTT and Node-red. I can’t see how this can be related, other than that maybe the Rpi is too slow to drive everything. Any ideas?

2

Do these lights have good signal strength? You may want to move them closer to your router and test if you get the same results.

3

Flooding your network with individual requests.

The quickest workaround is to implement a rule that steps through group membership issuing individual commands with a short delay between each.

1 Like
4

I was thinking more about the lights (always the same ones) that do not turn off. Could flooding the network cause the light to not turn off?

5

In reality, that should make no difference. The binding only sends one command at a time due to limitations with the ZWave protocol anyway.

6

Hi
Thans for the reply.
I don’t believe there’s a problem with range. I can operate all my devices individually or through sub group without issues. I don’t have any communication errors in the log either.

The only problem I have is that the devices in the “lowest” hierarchy groups works intermittently when turning them OFF (I’m not using ON command) using the top hiearchy group.

I have items tied to all group levels.

Sure, I could probably create a more advanced rule walking through all groups or items individually, but it feels like a workaround, not a solution.

7

I guess you’re stuck with the problem then.

1 Like
8

Much has changed since OH 2.4. Does the issue occur on OH 2.5?

9

Good question. I’ve missed that 2.5 is released. I’ll try that. Thanks.

10

If the problem persists, please provide a debug log as per the binding docs.

1 Like
11

Hi again,
I’ve tried updating to 2.5. No improvement. Maybe not related, but I feel the problem actually got worse after moving from 2.4 to 2.5.
Tried the latest snapshot (today). No improvement.
I tested turning one of the lights ON before to turning them OFF using the ALL group. In sitemap, all switches turns OFF when executing the ALL command. But, status in sitemap goes back to “ON” after a while and the light doesn’t switch OFF.
I was able to get the Zwave debug log, using the ALL group for turning OFF the lights when it didn’t work. But, the log is massive (3355 lines) and the file is almost half a Meg. Any recommendations on how to filter it or otherwise make it available for review?

Did a filter for that particular node. Hope it helps:

2020-05-27 11:38:13.945 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Command received zwave:device:36793424:node3:switch_binary --> OFF [OnOffType]
2020-05-27 11:38:13.948 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 3: Creating new message for application command SWITCH_BINARY_SET
2020-05-27 11:38:13.951 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
2020-05-27 11:38:13.956 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured
2020-05-27 11:38:13.960 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue
2020-05-27 11:38:13.963 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Added 503 to queue - size 4
2020-05-27 11:38:13.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling initialised at 86400 seconds - start in 1500 milliseconds.
2020-05-27 11:38:14.672 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Command received zwave:device:36793424:node3:switch_binary --> OFF [OnOffType]
2020-05-27 11:38:14.683 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 3: Creating new message for application command SWITCH_BINARY_SET
2020-05-27 11:38:14.690 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
2020-05-27 11:38:14.701 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured
2020-05-27 11:38:14.706 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue
2020-05-27 11:38:14.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Transaction already in queue - removed original
2020-05-27 11:38:14.721 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Added 513 to queue - size 9
2020-05-27 11:38:14.821 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling initialised at 86400 seconds - start in 1500 milliseconds.
2020-05-27 11:38:16.322 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling...
2020-05-27 11:38:16.324 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling zwave:device:36793424:node3:switch_binary
2020-05-27 11:38:16.325 [DEBUG] [converter.ZWaveBinarySwitchConverter] - NODE 3: Generating poll message for COMMAND_CLASS_SWITCH_BINARY, endpoint 0
2020-05-27 11:38:16.327 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 3: Creating new message for application command SWITCH_BINARY_GET
2020-05-27 11:38:16.328 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
2020-05-27 11:38:16.329 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured
2020-05-27 11:38:16.331 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling skipped for zwave:device:36793424:node3:switch_binary on COMMAND_CLASS_BASIC
2020-05-27 11:38:16.333 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling zwave:device:36793424:node3:sensor_power
2020-05-27 11:38:16.335 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 3: Generating poll message for COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2020-05-27 11:38:16.337 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 3: Creating new message for command SENSOR_MULTILEVEL_GET
2020-05-27 11:38:16.338 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
2020-05-27 11:38:16.340 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_SENSOR_MULTILEVEL is NOT required to be secured
2020-05-27 11:38:16.344 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue
2020-05-27 11:38:16.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Added 541 to queue - size 34
2020-05-27 11:38:16.357 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue
2020-05-27 11:38:16.358 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Added 543 to queue - size 36
2020-05-27 11:39:12.860 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 0A 00 13 03 03 25 01 00 25 B7 50 
2020-05-27 11:39:14.866 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 3: TID 513: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2020-05-27 11:39:26.872 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 3: TID 513: Timeout at state ABORTED. 3 retries remaining.
2020-05-27 11:39:26.877 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-05-27 11:39:26.878 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:513 CANCELLED
2020-05-27 11:39:57.425 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 09 00 13 03 02 25 02 25 CD 2B 
2020-05-27 11:39:57.453 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack.
2020-05-27 11:39:57.458 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 541: Transaction not completed
2020-05-27 11:39:57.479 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 205, Status = Transmission complete and ACK received(0)
2020-05-27 11:39:57.481 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
2020-05-27 11:39:57.485 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 541: Transaction not completed
2020-05-27 11:39:57.492 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DONE)
2020-05-27 11:39:57.493 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
2020-05-27 11:39:57.496 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_SWITCH_BINARY, endpoint 0
2020-05-27 11:39:57.497 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
2020-05-27 11:39:57.500 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_SWITCH_BINARY V1 SWITCH_BINARY_REPORT
2020-05-27 11:39:57.502 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 3: Switch Binary report, value = 255
2020-05-27 11:39:57.505 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2020-05-27 11:39:57.507 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_BINARY, value=255
2020-05-27 11:39:57.510 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:36793424:node3:switch_binary to ON [OnOffType]
2020-05-27 11:39:57.514 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
2020-05-27 11:39:57.516 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@b91c59.
2020-05-27 11:39:57.521 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@b91c59.
2020-05-27 11:39:57.523 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:541 DONE
2020-05-27 11:39:57.527 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-05-27 11:39:57.682 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 09 00 13 03 02 31 04 25 CF 3B 
2020-05-27 11:39:57.728 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack.
2020-05-27 11:39:57.733 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 543: Transaction not completed
2020-05-27 11:39:57.751 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 207, Status = Transmission complete and ACK received(0)
2020-05-27 11:39:57.753 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
2020-05-27 11:39:57.757 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 543: Transaction not completed
2020-05-27 11:39:57.763 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DONE)
2020-05-27 11:39:57.765 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
2020-05-27 11:39:57.767 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2020-05-27 11:39:57.768 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
2020-05-27 11:39:57.770 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_SENSOR_MULTILEVEL V2 SENSOR_MULTILEVEL_REPORT
2020-05-27 11:39:57.772 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 3: Sensor Type = Power(4), Scale = 0
2020-05-27 11:39:57.774 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 3: Sensor Value = 0.8
2020-05-27 11:39:57.775 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2020-05-27 11:39:57.777 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=0.8
2020-05-27 11:39:57.779 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 3: Sensor conversion not performed for POWER.
2020-05-27 11:39:57.781 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:36793424:node3:sensor_power to 0.8 [DecimalType]
2020-05-27 11:39:57.785 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
2020-05-27 11:39:57.787 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@7d4ccf.
2020-05-27 11:39:57.795 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@7d4ccf.
2020-05-27 11:39:57.797 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:543 DONE
2020-05-27 11:39:57.800 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

Thanks.

12

Chris needs unfiltered logs for troubleshooting.

If you want ideas, here is the zwave log viewer.
https://www.cd-jackson.com/index.php/openhab/zwave-log-viewer

13

OK, got it. Should I just upload the 0,5 Mb file here?
I checked the log using the link you sent, but unfortunately I can’t make much out of it and need help to proceed. One thing I’ve noticed is that if I turn on/off the node directly, the Fibaro plug responds immediately. If I turn it on/off using a group, there’s always a fairly long delay - maybe 5-10 seconds). If I use a group higher up in the hierarchy, mostly it doesn’t work. Maybe it’s related. There’s too much delay with nested groups?

14

If you are permitted or post a link from Dropbox, for instance.

Perhaps. I am no OH or Z-Wave expert.

15

debug.log (425.9 KB)

OK, here is the log. The light I’ve tested with is Node 3.
Node 12 gives an error, but that’s because it’s currently unplugged.

Any help would be appreciated. Thanks.

16

How long it takes openHAB to issue a command makes no difference to the binding. It gets a command, or it doesn’t.
The difference is likely to be what else is going on, presumably higher up in your hierarchy means more commands to many devices.

1 Like