Switch not turning off or maybe turning itself on randomly

Qwertypo · 2022-05-24 05:12:10 UTC

1) Give a description of the problem
Switch is coming on randomly

2) What is the expected behaviour?
Using a motion sensor to trigger on and off

3) What is happening/not happening?
It seems to work for the most part, some delay in on events and seemed to randomly not turn off, but looking at the logs it actually seems to turn itself on when no motion is happening

4) Post a Green Snapshot of the piston!

5) Attach logs after turning logging level to Full
5/23/2022, 9:54:50 PM +768ms
+1ms ╔Received event [Garage Lights].switch = off with a delay of 55ms
+149ms ║off
+153ms ╚Event processed successfully (153ms)
5/23/2022, 9:54:50 PM +768ms
+1ms ╔Received event [Garage Lights].switch = off with a delay of 55ms
+87ms ║off
+91ms ╚Event processed successfully (91ms)
5/23/2022, 9:02:15 PM +454ms
+1ms ╔Received event [Garage Lights].switch = on with a delay of 66ms
+95ms ║on
+99ms ╚Event processed successfully (99ms)
5/23/2022, 8:56:59 PM +50ms
+1ms ╔Received event [Ventura].time = 1653364620082 with a delay of -1032ms
+108ms ╚Event processed successfully (108ms)
5/23/2022, 8:54:59 PM +984ms
+1ms ╔Received event [Motion Garage].motion = inactive with a delay of 51ms
+103ms ║Setting up scheduled job for Mon, May 23 2022 @ 8:57:00 PM PDT (in 119s)
+136ms ╚Event processed successfully (136ms)
5/23/2022, 8:54:48 PM +91ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 56ms
+121ms ╚Event processed successfully (121ms)
5/23/2022, 7:47:11 PM +548ms
+1ms ╔Received event [Garage Lights].switch = off with a delay of 61ms
+10085ms ║Piston waited at a semaphore for 10017ms
+10105ms ╚Event processed successfully (10105ms)
5/23/2022, 7:47:11 PM +543ms
+1ms ╔Received event [Garage Lights].switch = off with a delay of 56ms
+84ms ║off
+89ms ╚Event processed successfully (88ms)
5/23/2022, 7:47:11 PM +50ms
+0ms ╔Received event [Ventura].time = 1653360432572 with a delay of -1523ms
+121ms ╚Event processed successfully (121ms)
5/23/2022, 7:45:12 PM +489ms
+1ms ╔Received event [Motion Garage].motion = inactive with a delay of 52ms
+88ms ║Setting up scheduled job for Mon, May 23 2022 @ 7:47:12 PM PDT (in 119s)
+95ms ╚Event processed successfully (95ms)
5/23/2022, 7:45:00 PM +550ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 58ms
+94ms ╚Event processed successfully (94ms)
5/23/2022, 7:44:52 PM +158ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 54ms
+86ms ╚Event processed successfully (86ms)
5/23/2022, 7:44:42 PM +747ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 54ms
+94ms ╚Event processed successfully (94ms)
5/23/2022, 7:44:32 PM +970ms
+2ms ╔Received event [Motion Garage].motion = active with a delay of 54ms
+109ms ╚Event processed successfully (109ms)
5/23/2022, 7:44:24 PM +831ms
+1ms ╔Received event [Motion Garage].motion = inactive with a delay of 54ms
+100ms ║Setting up scheduled job for Mon, May 23 2022 @ 7:46:24 PM PDT (in 119s)
+106ms ╚Event processed successfully (106ms)
5/23/2022, 7:44:13 PM +485ms
+1ms ╔Received event [Garage Lights].switch = on with a delay of 64ms
+10089ms ║Piston waited at a semaphore for 10017ms
+10109ms ╚Event processed successfully (10108ms)
5/23/2022, 7:44:13 PM +481ms
+1ms ╔Received event [Garage Lights].switch = on with a delay of 60ms
+95ms ║on
+99ms ╚Event processed successfully (99ms)
5/23/2022, 7:44:12 PM +925ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 51ms
+128ms ╚Event processed successfully (128ms)
5/23/2022, 7:33:16 PM +484ms
+1ms ╔Received event [Garage Lights].switch = off with a delay of 63ms
+10101ms ║Piston waited at a semaphore for 10019ms
+10119ms ╚Event processed successfully (10119ms)
5/23/2022, 7:33:16 PM +483ms
+1ms ╔Received event [Garage Lights].switch = off with a delay of 63ms
+103ms ║off
+108ms ╚Event processed successfully (108ms)
5/23/2022, 7:22:35 PM +58ms
+1ms ╔Received event [Ventura].time = 1653358956315 with a delay of -1257ms
+136ms ╚Event processed successfully (136ms)
5/23/2022, 7:20:36 PM +230ms
+1ms ╔Received event [Motion Garage].motion = inactive with a delay of 53ms
+90ms ║Setting up scheduled job for Mon, May 23 2022 @ 7:22:36 PM PDT (in 119s)
+97ms ╚Event processed successfully (97ms)
5/23/2022, 7:20:24 PM +304ms
+2ms ╔Received event [Motion Garage].motion = active with a delay of 49ms
+90ms ╚Event processed successfully (90ms)
5/23/2022, 7:20:11 PM +259ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 53ms
+111ms ╚Event processed successfully (110ms)
5/23/2022, 7:19:57 PM +602ms
+1ms ╔Received event [Motion Garage].motion = inactive with a delay of 47ms
+83ms ║Setting up scheduled job for Mon, May 23 2022 @ 7:21:57 PM PDT (in 119s)
+90ms ╚Event processed successfully (90ms)
5/23/2022, 7:19:45 PM +667ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 47ms
+86ms ╚Event processed successfully (86ms)
5/23/2022, 7:19:37 PM +806ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 52ms
+86ms ╚Event processed successfully (86ms)
5/23/2022, 7:19:23 PM +173ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 52ms
+100ms ╚Event processed successfully (100ms)
5/23/2022, 7:19:15 PM +337ms
+2ms ╔Received event [Motion Garage].motion = active with a delay of 57ms
+94ms ╚Event processed successfully (93ms)
5/23/2022, 7:19:07 PM +169ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 55ms
+191ms ╚Event processed successfully (191ms)
5/23/2022, 7:18:57 PM +448ms
+1ms ╔Received event [Motion Garage].motion = inactive with a delay of 55ms
+96ms ║Setting up scheduled job for Mon, May 23 2022 @ 7:20:57 PM PDT (in 119s)
+102ms ╚Event processed successfully (102ms)
5/23/2022, 7:18:45 PM +484ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 50ms
+86ms ╚Event processed successfully (85ms)
5/23/2022, 7:18:35 PM +833ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 55ms
+88ms ╚Event processed successfully (87ms)
5/23/2022, 7:18:27 PM +991ms
+2ms ╔Received event [Motion Garage].motion = active with a delay of 49ms
+96ms ╚Event processed successfully (96ms)
5/23/2022, 7:18:15 PM +189ms
+1ms ╔Received event [Garage Lights].switch = on with a delay of 67ms
+98ms ║on
+102ms ╚Event processed successfully (102ms)
5/23/2022, 7:18:14 PM +623ms
+0ms ╔Received event [Motion Garage].motion = active with a delay of 53ms
+118ms ╚Event processed successfully (118ms)
5/23/2022, 4:45:22 PM +632ms
+1ms ╔Received event [Garage Lights].switch = off with a delay of 67ms
+10106ms ║Piston waited at a semaphore for 10033ms
+10127ms ╚Event processed successfully (10127ms)
5/23/2022, 4:45:22 PM +623ms
+1ms ╔Received event [Garage Lights].switch = off with a delay of 58ms
+85ms ║off
+89ms ╚Event processed successfully (89ms)
5/23/2022, 4:45:22 PM +63ms
+0ms ╔Received event [Ventura].time = 1653349523539 with a delay of -1477ms
+123ms ╚Event processed successfully (124ms)
5/23/2022, 4:43:23 PM +459ms
+1ms ╔Received event [Motion Garage].motion = inactive with a delay of 47ms
+84ms ║Setting up scheduled job for Mon, May 23 2022 @ 4:45:23 PM PDT (in 119s)
+91ms ╚Event processed successfully (91ms)
5/23/2022, 4:43:11 PM +232ms
+1ms ╔Received event [Garage Lights].switch = on with a delay of 63ms
+91ms ║on
+96ms ╚Event processed successfully (95ms)
5/23/2022, 4:43:10 PM +668ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 53ms
+121ms ╚Event processed successfully (121ms)
5/23/2022, 4:35:47 PM +606ms
+1ms ╔Received event [Garage Lights].switch = off with a delay of 62ms
+10102ms ║Piston waited at a semaphore for 10021ms
+10121ms ╚Event processed successfully (10121ms)
5/23/2022, 4:35:47 PM +605ms
+1ms ╔Received event [Garage Lights].switch = off with a delay of 61ms
+94ms ║off
+99ms ╚Event processed successfully (99ms)
5/23/2022, 4:35:47 PM +51ms
+0ms ╔Received event [Ventura].time = 1653348948303 with a delay of -1253ms
+117ms ╚Event processed successfully (117ms)
5/23/2022, 4:33:48 PM +223ms
+1ms ╔Received event [Motion Garage].motion = inactive with a delay of 48ms
+84ms ║Setting up scheduled job for Mon, May 23 2022 @ 4:35:48 PM PDT (in 119s)
+92ms ╚Event processed successfully (92ms)
5/23/2022, 4:33:36 PM +8ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 53ms
+105ms ╚Event processed successfully (105ms)
5/23/2022, 4:33:27 PM +860ms
+1ms ╔Received event [Motion Garage].motion = inactive with a delay of 52ms
+98ms ║Setting up scheduled job for Mon, May 23 2022 @ 4:35:27 PM PDT (in 119s)
+105ms ╚Event processed successfully (105ms)
5/23/2022, 4:33:15 PM +615ms
+0ms ╔Received event [Motion Garage].motion = active with a delay of 46ms
+96ms ╚Event processed successfully (97ms)
5/23/2022, 4:33:07 PM +168ms
+1ms ╔Received event [Garage Lights].switch = on with a delay of 67ms
+110ms ║on
+116ms ╚Event processed successfully (116ms)
5/23/2022, 4:33:06 PM +585ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 53ms
+126ms ╚Event processed successfully (127ms)
5/23/2022, 4:26:59 PM +635ms
+1ms ╔Received event [Garage Lights].switch = off with a delay of 60ms
+91ms ║off
+95ms ╚Event processed successfully (94ms)
5/23/2022, 4:26:59 PM +49ms
+0ms ╔Received event [Ventura].time = 1653348420701 with a delay of -1653ms
+129ms ╚Event processed successfully (130ms)
5/23/2022, 4:25:00 PM +617ms
+1ms ╔Received event [Motion Garage].motion = inactive with a delay of 52ms
+89ms ║Setting up scheduled job for Mon, May 23 2022 @ 4:27:00 PM PDT (in 119s)
+96ms ╚Event processed successfully (96ms)
5/23/2022, 4:24:48 PM +674ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 48ms
+77ms ╚Event processed successfully (76ms)
5/23/2022, 4:24:40 PM +824ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 53ms
+132ms ╚Event processed successfully (133ms)
5/23/2022, 4:24:31 PM +33ms
+2ms ╔Received event [Motion Garage].motion = active with a delay of 49ms
+106ms ╚Event processed successfully (106ms)
5/23/2022, 4:24:23 PM +499ms
+1ms ╔Received event [Motion Garage].motion = inactive with a delay of 46ms
+95ms ║Setting up scheduled job for Mon, May 23 2022 @ 4:26:23 PM PDT (in 119s)
+101ms ╚Event processed successfully (101ms)
5/23/2022, 4:24:12 PM +774ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 48ms
+100ms ╚Event processed successfully (100ms)
5/23/2022, 3:59:29 PM +35ms
+1ms ╔Received event [Garage Lights].switch = on with a delay of 68ms
+10147ms ║Piston waited at a semaphore for 10069ms
+10166ms ╚Event processed successfully (10166ms)
5/23/2022, 3:59:29 PM +28ms
+1ms ╔Received event [Garage Lights].switch = on with a delay of 60ms
+89ms ║on
+93ms ╚Event processed successfully (93ms)
5/23/2022, 3:46:47 PM +48ms
+0ms ╔Received event [Ventura].time = 1653346008013 with a delay of -965ms
+99ms ╚Event processed successfully (99ms)
5/23/2022, 3:44:47 PM +920ms
+1ms ╔Received event [Motion Garage].motion = inactive with a delay of 62ms
+98ms ║Setting up scheduled job for Mon, May 23 2022 @ 3:46:48 PM PDT (in 119s)
+105ms ╚Event processed successfully (105ms)
5/23/2022, 3:44:38 PM +985ms
+2ms ╔Received event [Motion Garage].motion = active with a delay of 58ms
+90ms ╚Event processed successfully (90ms)
5/23/2022, 3:44:28 PM +87ms
+0ms ╔Received event [Motion Garage].motion = active with a delay of 43ms
+106ms ╚Event processed successfully (105ms)
5/23/2022, 3:44:27 PM +351ms
+1ms ╔Received event [Garage Lights].switch = off with a delay of 58ms
+88ms ║off
+97ms ╚Event processed successfully (96ms)
5/23/2022, 3:42:54 PM +157ms
+2ms ╔Received event [Motion Garage].motion = inactive with a delay of 49ms
+87ms ║Setting up scheduled job for Mon, May 23 2022 @ 3:44:54 PM PDT (in 119s)
+93ms ╚Event processed successfully (93ms)
5/23/2022, 3:42:42 PM +281ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 55ms
+98ms ╚Event processed successfully (98ms)
5/23/2022, 3:31:38 PM +55ms
+1ms ╔Received event [Ventura].time = 1653345099039 with a delay of -984ms
+125ms ╚Event processed successfully (125ms)
5/23/2022, 3:29:38 PM +952ms
+2ms ╔Received event [Motion Garage].motion = inactive with a delay of 52ms
+92ms ║Setting up scheduled job for Mon, May 23 2022 @ 3:31:39 PM PDT (in 119s)
+98ms ╚Event processed successfully (98ms)
5/23/2022, 3:29:25 PM +586ms
+1ms ╔Received event [Garage Lights].switch = on with a delay of 67ms
+10224ms ║Piston waited at a semaphore for 10152ms
+10243ms ╚Event processed successfully (10243ms)
5/23/2022, 3:29:25 PM +579ms
+1ms ╔Received event [Garage Lights].switch = on with a delay of 59ms
+83ms ║on
+87ms ╚Event processed successfully (87ms)
5/23/2022, 3:29:25 PM +2ms
+1ms ╔Received event [Motion Garage].motion = active with a delay of 51ms
+121ms ╚Event processed successfully (121ms)

Qwertypo · 2022-05-26 03:51:19 UTC

I excluded the device and re-paired it to see if just needed a clean install. Still see similar issues.

Mainly these echoed logs for on and off

5/25/2022, 8:02:09 PM +464ms
+1ms 	╔Received event [Garage Lights].switch = off with a delay of 56ms
+165ms 	║off
+170ms 	╚Event processed successfully (170ms)
5/25/2022, 8:02:09 PM +463ms
+1ms 	╔Received event [Garage Lights].switch = off with a delay of 55ms
+85ms 	║off
+89ms 	╚Event processed successfully (89ms)
5/25/2022, 8:02:05 PM +66ms
+0ms 	╔Received event [Ventura].time = 1653534126309 with a delay of -1244ms
+206ms 	╚Event processed successfully (206ms)

Any idea why that is happening? many times the second event is a semaphore delay.

eibyer · 2022-05-26 14:21:58 UTC

What happens if you remove the statement on line 38?

orangebucket · 2022-05-26 20:26:45 UTC

The semaphore delay is a consequence of the piston starting to process the second event while the first one is still being processed. I’ve no idea why you are getting two events sometimes.

Qwertypo · 2022-05-27 17:22:54 UTC

It does the same thing, I added that to try to diagnose, as it seemed the On event was sometimes coming late, after the light should have been turned off. After adding that line I did confirm that for some reason the light just turned itself back on 4 minutes after turning off due to motion. I was hoping the logging would show the difference between a physical press vs a cloud event, but it doesn’t seem to.

eibyer · 2022-05-27 18:32:59 UTC

I tried your piston with virtual motion/switch and it worked with no modification. Have you checked your live logging to see if you’re getting multiple events from the switch that may be causing the semaphore?