Receiving "off" commands when nothing happened

#1

1) Give a description of the problem
I am receiving a device off event when I’m confident that nothing turned off the light switch (GE Z-Wave Enhanced Dimmer wall switch). No piston activated any commands, no physical interaction, etc.

2) What is the expected behavior?
I’d like to only have my logic trigger when the light is turned off.

3) What is happening/not happening?
Here is the log:

Received event [Office Lights].switch = off with a delay of 140ms
+10042ms	║Piston waited at a semaphore for 9621ms
+10092ms	║Setting up scheduled job for Sat, Apr 14 2018 @ 10:04:08 AM EDT (in 19.922s)
+10114ms	╚Event processed successfully (10113ms)

Whenever this happens I usually (or even always) get then ote about a long semaphore wait.

#2

I’m confused…what exactly is your question? Does the piston you are posting the log from subscribe to the switch’s status? If so, then that’s why you’re seeing this. Do you have a smartapp or something “polling” or “refreshing” the status of the switch?

What DTH are you using and what model GE switch is this?

If you’re asking about a piston, can you upload a green screenshot of it?

#3

My question is: why is this event getting triggered when as far as I know nothing is turning the switch off (and in fact the switch was already off when this is getting triggered).

I can post my piston code, but it is big and complex and I don’t think relevant. It does subscribe to the switch’s status, and as you can see in the logs that is getting triggered, however I have no idea why it is getting triggered. I don’t have any smartapps connected to that switch other than webCoRE (this is the only piston referencing that switch) and Alexa (I definitely didn’t turn it off verbally).

I am using the following community-provided driver for the switch: nuttytree : GE/Jasco Z-Wave Plus Dimmer Switch

#4

Go to the device in the ST app and see what apps are using that device, you might have setup something that you forgot about.

#5

Where do you think it could possibly be coming from? The switch is obviously being affected by something. What is happening in LiveLogging for the device?

#6

Wow, I found the Live Logging and that might help out a lot. I’ll get back to you guys once I’ve done some more analysis.

(note I’m fairly new to SmartThings)

#7

OK, it looks like it might be my own code that is turning off the light and triggering the event, but if so it is doing it without logging it and setting a variable. But the logs say the device itself was the source of the off event (see end of post)

In the code below, I’m turning the light off on line 141, but lines 136 and 137 don’t seem to be executing when that happens, if indeed I did turn it off.

download
download.png1178×3231 405 KB

Here is a log showing that the “manual override” was triggered because my piston thinks it didn’t turn off the light in the last 10 seconds:

4/15/2018, 12:02:23 AM +828ms
+2ms	╔Received event [Office Lights].switch = off with a delay of 106ms
+9910ms	║Piston waited at a semaphore for 9686ms
+9968ms	║manual override enabled, next is last_on_off_action
+9976ms	║Sat, Apr 14 2018 @ 11:53:55 PM EDT
+9980ms	║Setting up scheduled job for Sun, Apr 15 2018 @ 12:02:54 AM EDT (in 20.513s)
+10032ms	╚Event processed successfully (10031ms)
4/15/2018, 12:02:23 AM +373ms
+0ms	╔Received event [Home].time = 1523764944320 with a delay of -948ms
+459ms	║Setting up scheduled job for Sun, Apr 15 2018 @ 12:02:54 AM EDT (in 30.489s)
+483ms	╚Event processed successfully (483ms)
4/15/2018, 12:01:53 AM +347ms
+1ms	╔Received event [Home].time = 1523764914320 with a delay of -973ms
+1489ms	║Setting up scheduled job for Sun, Apr 15 2018 @ 12:02:24 AM EDT (in 29.485s)
+1510ms	╚Event processed successfully (1510ms)

Here is the event log from the device. Note how it is decreasing by 10% increments and then it is turned off. But the dim events show they were from webCoRE while the device off doesn’t.

2018-04-15 12:02:23.732 AM EDT
moments ago	DEVICE		level	0		Office Lights level is 0%
2018-04-15 12:02:23.722 AM EDT
moments ago	DEVICE		switch	off		Office Lights switch is off
2018-04-15 12:02:23.710 AM EDT
moments ago	APP_COMMAND			setLevel		Motion-Controlled Lighting (BETA) sent setLevel command to Office Lights
2018-04-15 12:01:53.887 AM EDT
moments ago	DEVICE		level	10		Office Lights level is 10%
2018-04-15 12:01:53.711 AM EDT
moments ago	APP_COMMAND			setLevel		Motion-Controlled Lighting (BETA) sent setLevel command to Office Lights
2018-04-15 12:01:24.850 AM EDT
moments ago	DEVICE		level	20		Office Lights level is 20%
2018-04-15 12:01:24.832 AM EDT
moments ago	APP_COMMAND			setLevel		Motion-Controlled Lighting (BETA) sent setLevel command to Office Lights
2018-04-15 12:00:55.090 AM EDT
moments ago	DEVICE		level	30		Office Lights level is 30%
2018-04-15 12:00:54.945 AM EDT
moments ago	APP_COMMAND			setLevel		Motion-Controlled Lighting (BETA) sent setLevel command to Office Lights
2018-04-15 12:00:23.935 AM EDT
moments ago	DEVICE		level	40		Office Lights level is 40%

For the actual “device off” command at the top, it says the source was the device itself:

|archivable|true|
|---|---|
|date|2018-04-15 12:02:23.722 AM EDT (2018-04-15T04:02:23.722Z)|
|description|Office Lights switch is off|
|deviceId|8fc2bdc4-dc20-441c-9d47-766f6e4962c6|
|deviceTypeId|daf68621-7eb5-4b53-b623-8e9b928ad2e8|
|displayed|true|
|eventSource|DEVICE|
|groupId|0f320ae6-c7e5-47f8-9bcb-37c13d33f493|
|hubId|9bda3e82-2df2-4fd2-b9c9-cb07ce0b4c37|
|id|cd6c1ca0-4061-11e8-ae5e-0afffbc54be2|
|isStateChange|true|
|isVirtualHub|false|
|linkText|Office Lights|
|locationId|019ca1dc-4c6d-4893-acb8-9dbd940fa6f6|
|name|switch|
|rawDescription||
|translatable|false|
|unixTime|1523764943722|
|value|off|
|viewed|false|
#8

While it may not be the case in this scenario it is worth noting that you CAN get random off (and on) commands showing-up even when no code has triggered it. It’s pretty evident from the experience of many folks that some devices send random on-off messages (sometimes with the devices actually turning on and off and sometimes not). I can post lots of Live Logging as examples.

Sounds ridiculous but it happens.

#9

Yes… But they come from somewhere. LOL. It’s either software or hardware. And if it’s hardware, it doesn’t matter what his piston is, you’re still going to get the off event. We could look at his pistons till the end of time. We’re still never going to find the problem if it’s Hardware.

#10

Do you have any Fibaro modules in your setup?

#11

Yes, that was my point ;).

#12

No, no Fibaro modules.

#13

That’s why i asked for LiveLogging. :grin:

#14

So by Live Logging are you talking about the device event history that I pasted above? In that case it showed:

|eventSource|DEVICE|

Which makes me think the light switch itself reported that in?

#15

Yes…and you turned your device off and it turned off. What’s the problem? I don’t see the issue here.

#16

Ryan780,

No, I didn’t turn that device off. It was already off. I received that event in my piston logs when the device was already off. Nor did any piston set it to off.