Periodic poller incorrectly resetting multilevel switches

[jadedeane]

Running version 2.2.3.

Opened a thread on the forums around GE light switches, namely the fact that the add-on-/3-way switches weren’t updating in Z-Way after a physical press. After some research, and education on my part I learned that while the main/line switch does send NIF on physical press (picked up by Niffler module/app) and updates great, the add-on/3-way switch doesn’t trigger a NIF. So, no update change, ever.

Once I worked around my admittedly basic knowledge of Z-Wave and learned more about NIFs, the patent nonsense, etc. I figured the solution to updates would be to just enable the periodic poller, set it to 1min for my switches, and that would be good enough. However, once I set up the poller I started to see some behavior I think is a bug, explained here: https://forum.z-wave.me/viewtopic.php?f=3419&t=23672&start=10

Basically when the poller fires off it turns the lights off (if they were turned on via the non-NIF sending switch), and turns the lights on (if they were turned off already by the non-NIF sending switch).

I hope I’ve explained this well enough, and thanks in advance for your help!

[jadedeane]

Noticed in the debug that when the poller fires off to snag updates (I see the SwitchMultilevel Get job, presume that's the update request?) there's also a "SwitchMultilevel Set" job. Seems odd anything but a "get" for an update would go out. I don't see sets for the binary switches, just multilevel.

[jadedeane]

Logs from a poller run:

[2016-08-20 10:21:00.309] [I] [core] --- ZWayVDev_zway_11-0-38 performCommand processing: {"0":"update"}
[2016-08-20 10:21:00.310] [I] [zway] Adding job: SwitchMultilevel Get
[2016-08-20 10:21:00.310] [I] [zway] Adding job: SwitchMultilevel Set
[2016-08-20 10:21:00.310] [D] [zway] Job 0x13 (SwitchMultilevel Get): removing duplicate
[2016-08-20 10:21:00.310] [I] [core] --- ZWayVDev_zway_12-0-37 performCommand processing: {"0":"update"}
[2016-08-20 10:21:00.311] [I] [zway] Adding job: SwitchBinary Get
[2016-08-20 10:21:00.311] [I] [core] --- ZWayVDev_zway_13-0-38 performCommand processing: {"0":"update"}
[2016-08-20 10:21:00.312] [I] [zway] Adding job: SwitchMultilevel Get
[2016-08-20 10:21:00.312] [D] [zway] SENDING (cb 0xa4): ( 01 0A 00 13 0B 03 26 01 00 25 A4 48 )
[2016-08-20 10:21:00.312] [I] [zway] Adding job: SwitchMultilevel Set
[2016-08-20 10:21:00.313] [D] [zway] Job 0x13 (SwitchMultilevel Get): removing duplicate
[2016-08-20 10:21:00.313] [I] [core] --- ZWayVDev_zway_14-0-37 performCommand processing: {"0":"update"}
[2016-08-20 10:21:00.313] [I] [zway] Adding job: SwitchBinary Get
[2016-08-20 10:21:00.314] [D] [zway] RECEIVED ACK
[2016-08-20 10:21:00.320] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2016-08-20 10:21:00.320] [D] [zway] SENT ACK
[2016-08-20 10:21:00.320] [D] [zway] Delivered to Z-Wave stack
[2016-08-20 10:21:00.413] [D] [zway] RECEIVED: ( 01 07 00 13 A4 00 00 09 46 )
[2016-08-20 10:21:00.414] [D] [zway] SENT ACK
[2016-08-20 10:21:00.414] [I] [zway] Job 0x13 (SwitchMultilevel Set): Delivered
[2016-08-20 10:21:00.414] [D] [zway] SETDATA devices.11.data.lastPacketInfo.delivered = True
[2016-08-20 10:21:00.414] [D] [zway] SETDATA devices.11.data.lastPacketInfo.packetLength = 6 (0x00000006)
[2016-08-20 10:21:00.414] [D] [zway] SETDATA devices.11.data.lastPacketInfo.deliveryTime = 93 (0x0000005d)
[2016-08-20 10:21:00.414] [D] [zway] SETDATA devices.11.data.lastPacketInfo = **********
[2016-08-20 10:21:00.414] [D] [zway] SendData Response with callback 0xa4 received: received by recipient
[2016-08-20 10:21:00.415] [D] [zway] SETDATA devices.11.data.lastSend = 23591427 (0x0167fa03)
[2016-08-20 10:21:00.415] [D] [zway] Job 0x13 (SwitchMultilevel Set): success
[2016-08-20 10:21:00.415] [I] [zway] Removing job: SwitchMultilevel Set
[2016-08-20 10:21:00.415] [D] [zway] SENDING (cb 0xa5): ( 01 09 00 13 0C 02 25 02 25 A5 4C )
[2016-08-20 10:21:00.423] [D] [zway] RECEIVED ACK
[2016-08-20 10:21:00.424] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2016-08-20 10:21:00.424] [D] [zway] SENT ACK
[2016-08-20 10:21:00.424] [D] [zway] Delivered to Z-Wave stack
[2016-08-20 10:21:00.453] [D] [zway] RECEIVED: ( 01 07 00 13 A5 00 00 03 4D )
[2016-08-20 10:21:00.453] [D] [zway] SENT ACK
[2016-08-20 10:21:00.453] [I] [zway] Job 0x13 (SwitchBinary Get): Delivered
[2016-08-20 10:21:00.454] [D] [zway] SETDATA devices.12.data.lastPacketInfo.delivered = True
[2016-08-20 10:21:00.454] [D] [zway] SETDATA devices.12.data.lastPacketInfo.packetLength = 5 (0x00000005)
[2016-08-20 10:21:00.454] [D] [zway] SETDATA devices.12.data.lastPacketInfo.deliveryTime = 29 (0x0000001d)
[2016-08-20 10:21:00.454] [D] [zway] SETDATA devices.12.data.lastPacketInfo = **********
[2016-08-20 10:21:00.454] [D] [zway] SendData Response with callback 0xa5 received: received by recipient
[2016-08-20 10:21:00.454] [D] [zway] SETDATA devices.12.data.lastSend = 23591431 (0x0167fa07)
[2016-08-20 10:21:00.454] [D] [zway] Job 0x13 (SwitchBinary Get): success
[2016-08-20 10:21:00.454] [I] [zway] Removing job: SwitchBinary Get
[2016-08-20 10:21:00.455] [D] [zway] SENDING (cb 0xa6): ( 01 0A 00 13 0D 03 26 01 00 25 A6 4C )
[2016-08-20 10:21:00.463] [D] [zway] RECEIVED ACK
[2016-08-20 10:21:00.470] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2016-08-20 10:21:00.470] [D] [zway] SENT ACK
[2016-08-20 10:21:00.470] [D] [zway] Delivered to Z-Wave stack
[2016-08-20 10:21:00.473] [D] [zway] RECEIVED: ( 01 09 00 04 00 0C 03 25 03 FF 24 )
[2016-08-20 10:21:00.473] [D] [zway] SENT ACK
[2016-08-20 10:21:00.473] [D] [zway] SETDATA devices.12.data.lastReceived = 0 (0x00000000)
[2016-08-20 10:21:00.474] [D] [zway] SETDATA devices.12.instances.0.commandClasses.37.data.level = True
[2016-08-20 10:21:00.527] [D] [zway] RECEIVED: ( 01 07 00 13 A6 00 00 06 4B )
[2016-08-20 10:21:00.527] [D] [zway] SENT ACK
[2016-08-20 10:21:00.528] [I] [zway] Job 0x13 (SwitchMultilevel Set): Delivered
[2016-08-20 10:21:00.528] [D] [zway] SETDATA devices.13.data.lastPacketInfo.delivered = True
[2016-08-20 10:21:00.528] [D] [zway] SETDATA devices.13.data.lastPacketInfo.packetLength = 6 (0x00000006)
[2016-08-20 10:21:00.528] [D] [zway] SETDATA devices.13.data.lastPacketInfo.deliveryTime = 57 (0x00000039)
[2016-08-20 10:21:00.528] [D] [zway] SETDATA devices.13.data.lastPacketInfo = **********
[2016-08-20 10:21:00.528] [D] [zway] SendData Response with callback 0xa6 received: received by recipient
[2016-08-20 10:21:00.528] [D] [zway] SETDATA devices.13.data.lastSend = 23591438 (0x0167fa0e)
[2016-08-20 10:21:00.528] [D] [zway] Job 0x13 (SwitchMultilevel Set): success
[2016-08-20 10:21:00.529] [I] [zway] Removing job: SwitchMultilevel Set
[2016-08-20 10:21:00.529] [D] [zway] SENDING (cb 0xa7): ( 01 09 00 13 0B 02 26 02 25 A7 4A )
[2016-08-20 10:21:00.534] [D] [zway] RECEIVED ACK
[2016-08-20 10:21:00.537] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2016-08-20 10:21:00.538] [D] [zway] SENT ACK
[2016-08-20 10:21:00.538] [D] [zway] Delivered to Z-Wave stack
[2016-08-20 10:21:00.622] [D] [zway] RECEIVED: ( 01 07 00 13 A7 00 00 09 45 )
[2016-08-20 10:21:00.623] [D] [zway] SENT ACK
[2016-08-20 10:21:00.623] [I] [zway] Job 0x13 (SwitchMultilevel Get): Delivered
[2016-08-20 10:21:00.623] [D] [zway] SETDATA devices.11.data.lastPacketInfo.delivered = True
[2016-08-20 10:21:00.623] [D] [zway] SETDATA devices.11.data.lastPacketInfo.packetLength = 5 (0x00000005)
[2016-08-20 10:21:00.623] [D] [zway] SETDATA devices.11.data.lastPacketInfo.deliveryTime = 85 (0x00000055)
[2016-08-20 10:21:00.623] [D] [zway] SETDATA devices.11.data.lastPacketInfo = **********
[2016-08-20 10:21:00.623] [D] [zway] SendData Response with callback 0xa7 received: received by recipient
[2016-08-20 10:21:00.624] [D] [zway] SETDATA devices.11.data.lastSend = 23591447 (0x0167fa17)
[2016-08-20 10:21:00.624] [D] [zway] Job 0x13 (SwitchMultilevel Get): success
[2016-08-20 10:21:00.624] [I] [zway] Removing job: SwitchMultilevel Get
[2016-08-20 10:21:00.624] [D] [zway] SENDING (cb 0xa8): ( 01 09 00 13 0D 02 26 02 25 A8 43 )
[2016-08-20 10:21:00.626] [D] [zway] RECEIVED ACK
[2016-08-20 10:21:00.633] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2016-08-20 10:21:00.633] [D] [zway] SENT ACK
[2016-08-20 10:21:00.633] [D] [zway] Delivered to Z-Wave stack
[2016-08-20 10:21:00.690] [D] [zway] RECEIVED: ( 01 07 00 13 A8 00 00 06 45 )
[2016-08-20 10:21:00.691] [D] [zway] SENT ACK
[2016-08-20 10:21:00.691] [I] [zway] Job 0x13 (SwitchMultilevel Get): Delivered
[2016-08-20 10:21:00.691] [D] [zway] SETDATA devices.13.data.lastPacketInfo.delivered = True
[2016-08-20 10:21:00.691] [D] [zway] SETDATA devices.13.data.lastPacketInfo.packetLength = 5 (0x00000005)
[2016-08-20 10:21:00.691] [D] [zway] SETDATA devices.13.data.lastPacketInfo.deliveryTime = 57 (0x00000039)
[2016-08-20 10:21:00.691] [D] [zway] SETDATA devices.13.data.lastPacketInfo = **********
[2016-08-20 10:21:00.691] [D] [zway] SendData Response with callback 0xa8 received: received by recipient
[2016-08-20 10:21:00.691] [D] [zway] SETDATA devices.13.data.lastSend = 23591454 (0x0167fa1e)
[2016-08-20 10:21:00.692] [D] [zway] Job 0x13 (SwitchMultilevel Get): success
[2016-08-20 10:21:00.692] [I] [zway] Removing job: SwitchMultilevel Get
[2016-08-20 10:21:00.692] [D] [zway] SENDING (cb 0xa9): ( 01 09 00 13 0E 02 25 02 25 A9 42 )
[2016-08-20 10:21:00.696] [D] [zway] RECEIVED ACK
[2016-08-20 10:21:00.701] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2016-08-20 10:21:00.701] [D] [zway] SENT ACK
[2016-08-20 10:21:00.701] [D] [zway] Delivered to Z-Wave stack
[2016-08-20 10:21:00.725] [D] [zway] RECEIVED: ( 01 07 00 13 A9 00 00 03 41 )
[2016-08-20 10:21:00.725] [D] [zway] SENT ACK
[2016-08-20 10:21:00.725] [I] [zway] Job 0x13 (SwitchBinary Get): Delivered
[2016-08-20 10:21:00.725] [D] [zway] SETDATA devices.14.data.lastPacketInfo.delivered = True
[2016-08-20 10:21:00.725] [D] [zway] SETDATA devices.14.data.lastPacketInfo.packetLength = 5 (0x00000005)
[2016-08-20 10:21:00.726] [D] [zway] SETDATA devices.14.data.lastPacketInfo.deliveryTime = 24 (0x00000018)
[2016-08-20 10:21:00.726] [D] [zway] SETDATA devices.14.data.lastPacketInfo = **********
[2016-08-20 10:21:00.726] [D] [zway] SendData Response with callback 0xa9 received: received by recipient
[2016-08-20 10:21:00.726] [D] [zway] SETDATA devices.14.data.lastSend = 23591457 (0x0167fa21)
[2016-08-20 10:21:00.726] [D] [zway] Job 0x13 (SwitchBinary Get): success
[2016-08-20 10:21:00.726] [I] [zway] Removing job: SwitchBinary Get
[2016-08-20 10:21:00.747] [D] [zway] RECEIVED: ( 01 09 00 04 00 0E 03 25 03 00 D9 )
[2016-08-20 10:21:00.747] [D] [zway] SENT ACK
[2016-08-20 10:21:00.747] [D] [zway] SETDATA devices.14.data.lastReceived = 0 (0x00000000)
[2016-08-20 10:21:00.747] [D] [zway] SETDATA devices.14.instances.0.commandClasses.37.data.level = False
[2016-08-20 10:21:00.848] [D] [zway] RECEIVED: ( 01 09 00 04 00 0D 03 26 03 00 D9 )
[2016-08-20 10:21:00.849] [D] [zway] SENT ACK
[2016-08-20 10:21:00.849] [D] [zway] SETDATA devices.13.data.lastReceived = 0 (0x00000000)
[2016-08-20 10:21:00.849] [D] [zway] SETDATA devices.13.instances.0.commandClasses.38.data.level = 0 (0x00000000)
[2016-08-20 10:21:00.951] [D] [zway] RECEIVED: ( 01 09 00 04 00 0B 03 26 03 00 DF )
[2016-08-20 10:21:00.951] [D] [zway] SENT ACK
[2016-08-20 10:21:00.951] [D] [zway] SETDATA devices.11.data.lastReceived = 0 (0x00000000)
[2016-08-20 10:21:00.951] [D] [zway] SETDATA devices.11.instances.0.commandClasses.38.data.level = 0 (0x00000000)
[2016-08-20 10:21:20.737] [D] [zway] Job 0x13: deleted from queue
[2016-08-20 10:21:20.747] [D] [zway] Job 0x13: deleted from queue
[2016-08-20 10:21:20.808] [D] [zway] Job 0x13: deleted from queue
[2016-08-20 10:21:20.890] [D] [zway] Job 0x13: deleted from queue
[2016-08-20 10:21:20.951] [D] [zway] Job 0x13: deleted from queue
[2016-08-20 10:21:20.971] [D] [zway] Job 0x13: deleted from queue

[PoltoS]

I see only device 11 is affected, while devices 12 and 13 are not (being also Switch Multilevel). For me it looks like you have some other rule that sends a Set on device value changes. Please doublecheck it.

[jadedeane]

@PoltoS thanks for the follow-up, really appreciate it.

Before going into detail I hope the following two bits of information are helpful:

1. Other than the "Niffler" module/app no other modules, apps, or "tweaks" have been implemented.
2. When the periodical poller is disabled the issue goes away.

Devices 11 and 13 in my setup are both dimmer switches, and both experience the same problem, while 12 is a binary. Please see Z-Wave.me forums thread (https://forum.z-wave.me/viewtopic.php?f=3419&t=23672&start=10). You'll note myself and someone else are seeing the same behavior with dimmer switches, while binary switches are fine.

If I disable the poller the issue goes away (nothing to/from the devices unless manually triggered). Additionally, per aforementioned forum post the other person is seeing exactly what I'm seeing, namely that pressing "update" in the standard UI sends a get+set, while pressing "update" in the expert UI sends only a "get".

[jadedeane]

I updated the forums post with a screenshot showing the job queue with a standard vs. expert ui "update" press.

[PoltoS]

ba97f5e

Got it, this was fix few days ago but not released yet. Please add three few lines to fix the problem meanwhile

[adingeldein]

@PoltoS Thank you, the fix works for me!

[jadedeane]

Working here as well. Thank you @PoltoS.

[PoltoS]

Welcome!