Piston seems to run through twice

guxdude · 2020-08-08 01:55:47 UTC

1) Give a description of the problem
I have a notification piston triggered by global variables. When it is triggered, I get two SMS notifications instead of one. Can anyone see what is going wrong? I don’t understand why it seems to run through twice.

2) What is the expected behaviour?
Run through once and send one SMS notification.

3) What is happening/not happening?
I get two SMS notifications at the same time.

**4) Post a Green Snapshot of the piston![image|45x37]

5) Attach logs after turning logging level to Full

8/7/2020, 6:29:59 PM +130ms
+1ms ╔Received event [Las Vegas].time = 1596850200000 with a delay of -870ms
+125ms ║RunTime Analysis CS &gt; 34ms &gt; PS &gt; 58ms &gt; PE &gt; 33ms &gt; CE
+128ms ║Runtime (42516 bytes) successfully initialized in 58ms (v0.3.110.20191009) (127ms)
+129ms ║╔Execution stage started
+133ms ║║Cancelling statement #392's schedules...
+140ms ║║Executed virtual command setVariable (4ms)
+144ms ║║Executed virtual command setVariable (2ms)
+149ms ║║Comparison (datetime) 1596850199277 happens_daily_at (datetime) 1596850200000 = true (1ms)
+150ms ║║Time restriction check passed
+151ms ║║Cancelling condition #378's schedules...
+152ms ║║Condition #378 evaluated true (5ms)
+153ms ║║Cancelling statement #378's schedules...
+156ms ║║Requesting time schedule wake up at Fri, Aug 7 2020 @ 6:30:00 PM PDT
+158ms ║║Cancelling condition #377's schedules...
+159ms ║║Condition group #377 evaluated true (state changed) (13ms)
+161ms ║║Cancelling statement #379's schedules...
+205ms ║║Executed physical command [Echo - LV Fire TV].setLevel([60]) (38ms)
+205ms ║║Executed [Echo - LV Fire TV].setLevel (40ms)
+247ms ║║Executed physical command [Echo - LV Living Room Dot].setLevel([60]) (38ms)
+248ms ║║Executed [Echo - LV Living Room Dot].setLevel (39ms)
+250ms ║║Executed virtual command [Echo - LV Fire TV, Echo - LV Living Room Dot].wait (0ms)
+251ms ║║Waiting for 2000ms
+2279ms ║║Executed physical command [Echo - LV Fire TV].speak(NASA Alert... Rocket 3.1 is launching in 30 minutes. (Friday @ 7:00 PM). Expect the Rocket 3.1 Flight 1, at Pacific Spaceport Complex - Alaska on pad LP-3B.
+2279ms ║║null
+2280ms ║║Executed [Echo - LV Fire TV].speak (25ms)
+2302ms ║║Executed physical command [Echo - LV Living Room Dot].speak(NASA Alert... Rocket 3.1 is launching in 30 minutes. (Friday @ 7:00 PM). Expect the Rocket 3.1 Flight 1, at Pacific Spaceport Complex - Alaska on pad LP-3B.
+2302ms ║║null
+2303ms ║║Executed [Echo - LV Living Room Dot].speak (23ms)
+2305ms ║║Cancelling statement #395's schedules...
+4598ms ║║Executed virtual command sendSMSNotification (2288ms)
+4605ms ║║NASA Alert... Rocket 3.1 is launching in 30 minutes. (Friday @ 7:00 PM). Expect the Rocket 3.1 Flight 1, at Pacific Spaceport Complex - Alaska on pad LP-3B.
+4605ms ║║null. https://rocketlaunch.live/launch/rocket-3-1; https://www.nasa.gov/nasalive
+4606ms ║║Executed virtual command log (2ms)
+4611ms ║║Executed virtual command setState (2ms)
+4617ms ║║Cancelling statement #392's schedules...
+4623ms ║║Executed virtual command setVariable (4ms)
+4628ms ║║Executed virtual command setVariable (3ms)
+4632ms ║║Comparison (datetime) 1596850203760 happens_daily_at (datetime) 1596850200000 = true (0ms)
+4633ms ║║Time restriction check passed
+4635ms ║║Condition #378 evaluated true (4ms)
+4636ms ║║Cancelling statement #378's schedules...
+4640ms ║║Condition group #377 evaluated true (state did not change) (9ms)
+4642ms ║║Cancelling statement #379's schedules...
+4670ms ║║Executed physical command [Echo - LV Fire TV].setLevel([60]) (24ms)
+4671ms ║║Executed [Echo - LV Fire TV].setLevel (26ms)
+4699ms ║║Executed physical command [Echo - LV Living Room Dot].setLevel([60]) (26ms)
+4699ms ║║Executed [Echo - LV Living Room Dot].setLevel (27ms)
+4703ms ║║Executed virtual command [Echo - LV Fire TV, Echo - LV Living Room Dot].wait (1ms)
+4704ms ║║Waiting for 2000ms
+6729ms ║║Executed physical command [Echo - LV Fire TV].speak(NASA Alert... Rocket 3.1 is launching in 30 minutes. (Friday @ 7:00 PM). Expect the Rocket 3.1 Flight 1, at Pacific Spaceport Complex - Alaska on pad LP-3B.
+6730ms ║║null
+6730ms ║║Executed [Echo - LV Fire TV].speak (24ms)
+6753ms ║║Executed physical command [Echo - LV Living Room Dot].speak(NASA Alert... Rocket 3.1 is launching in 30 minutes. (Friday @ 7:00 PM). Expect the Rocket 3.1 Flight 1, at Pacific Spaceport Complex - Alaska on pad LP-3B.
+6753ms ║║null
+6754ms ║║Executed [Echo - LV Living Room Dot].speak (23ms)
+6756ms ║║Cancelling statement #395's schedules...
+6769ms ║║Executed virtual command sendSMSNotification (7ms)
+6773ms ║║NASA Alert... Rocket 3.1 is launching in 30 minutes. (Friday @ 7:00 PM). Expect the Rocket 3.1 Flight 1, at Pacific Spaceport Complex - Alaska on pad LP-3B.
+6773ms ║║null. https://rocketlaunch.live/launch/rocket-3-1; https://www.nasa.gov/nasalive
+6774ms ║║Executed virtual command log (1ms)
+6777ms ║║Executed virtual command setState (1ms)
+6779ms ║╚Execution stage complete. (6651ms)
+6780ms ╚Event processed successfully (6780ms)

WCmore · 2020-08-08 02:03:35 UTC

I suspect, because your piston ran a second early
6:29:59 PM
… a moment later, we see this:
Requesting time schedule wake up @ 6:30:00 PM

It might be worth while to add a 1500ms WAIT as the very first command…
(just to make sure it is completely inside the new minute, before the time is evaluated)

Unrelated observation:

If your @global time changes, this piston will have no clue until after it runs at the previous time first. (which is no longer accurate) If that time happens to be in the past, then this piston will never automatically run again.

guxdude · 2020-08-08 02:14:13 UTC

That’s what i thought as well so I originally had a check looking for a change in one of the other global variable to trigger an update of the time. But the logs showed it always ran twice every time the variables updated. Turns out, when I change the time, it gets triggered. This is the last time it ran before the logs above:

8/7/2020, 12:15:45 AM +995ms
+0ms ╔Received event [Las Vegas].:aaa980d0f10c80523a928ba3ca55915a: = @globalLaunchTime with a delay of 66ms
+155ms ║RunTime Analysis CS &gt; 21ms &gt; PS &gt; 113ms &gt; PE &gt; 21ms &gt; CE
+158ms ║Runtime (42741 bytes) successfully initialized in 113ms (v0.3.110.20191009) (156ms)
+159ms ║╔Execution stage started
+163ms ║║Cancelling statement #392's schedules...
+167ms ║║Executed virtual command setVariable (2ms)
+172ms ║║Executed virtual command setVariable (2ms)
+176ms ║║Comparison (datetime) 1596784546169 happens_daily_at (datetime) 1596850200000 = false (0ms)
+178ms ║║Cancelling condition #378's schedules...
+179ms ║║Condition #378 evaluated false (5ms)
+180ms ║║Cancelling statement #378's schedules...
+183ms ║║Requesting time schedule wake up at Fri, Aug 7 2020 @ 6:30:00 PM PDT
+185ms ║║Cancelling condition #377's schedules...
+186ms ║║Condition group #377 evaluated false (state changed) (12ms)
+189ms ║║Cancelling statement #386's schedules...
+195ms ║║Calculating (string) Fri, Aug 7 2020 @ 12:15:46 AM PDT + (string) Alert changed: &gt;&gt; (string) Fri, Aug 7 2020 @ 12:15:46 AM PDT Alert changed:
+198ms ║║Fri, Aug 7 2020 @ 12:15:46 AM PDT Alert changed:
+199ms ║║Executed virtual command log (1ms)
+204ms ║║NASA Alert... Rocket 3.1 is launching in 30 minutes. (Fri @ 7:00 PM). Expect the Rocket 3.1 Flight 1, at Pacific Spaceport Complex - Alaska on pad LP-3B.
+204ms ║║null
+205ms ║║Executed virtual command log (1ms)
+210ms ║║Calculating (string) New Alert Information Received + (string) Fri, Aug 7 2020 @ 12:15:46 AM PDT &gt;&gt; (string) New Alert Information Received Fri, Aug 7 2020 @ 12:15:46 AM PDT
+213ms ║║Executed virtual command setState (1ms)
+215ms ║╚Execution stage complete. (57ms)
+217ms ║Setting up scheduled job for Fri, Aug 7 2020 @ 6:30:00 PM PDT (in 65653.789s)
+224ms ╚Event processed successfully (224ms)

I will try the added wait at the beginning. thanks.

WCmore · 2020-08-08 02:20:25 UTC

Interesting… Although, if the @global is acting as a trigger, I would be wary about using three @globals that all changed simultaneously… Who is to say that all three actually got updated in the time it took for this piston to begin execution…

It sounds like a race-game, where I would be very surprised to get reliable results.

(IE: If your house is running sluggish, you will probably not notice it… but if your house is running swiftly, I suspect that not all @global data will always be ready to use yet)

guxdude · 2020-08-08 02:30:34 UTC

Once the time is updated and then, when that time occurs, the first thing I do is grab the other two global variables to make sure they are the latest.

guxdude · 2020-08-08 02:33:16 UTC

This did the trick. I added a 1 sec wait and then edited the global variable (using another piston) and got the following logs:

8/7/2020, 7:29:59 PM +78ms
+1ms ╔Received event [Las Vegas].time = 1596853800000 with a delay of -922ms
+72ms ║RunTime Analysis CS &gt; 17ms &gt; PS &gt; 36ms &gt; PE &gt; 19ms &gt; CE
+75ms ║Runtime (42616 bytes) successfully initialized in 36ms (v0.3.110.20191009) (73ms)
+76ms ║╔Execution stage started
+81ms ║║Cancelling statement #392's schedules...
+86ms ║║Executed virtual command setVariable (3ms)
+91ms ║║Executed virtual command setVariable (3ms)
+94ms ║║Executed virtual command wait (1ms)
+95ms ║║Waiting for 1000ms
+1100ms ║║Comparison (datetime) 1596853800176 happens_daily_at (datetime) 1596853800000 = true (1ms)
+1101ms ║║Time restriction check passed
+1102ms ║║Cancelling condition #378's schedules...
+1103ms ║║Condition #378 evaluated true (5ms)
+1104ms ║║Cancelling statement #378's schedules...
+1107ms ║║Cancelling condition #377's schedules...
+1108ms ║║Condition group #377 evaluated true (state changed) (11ms)
+1110ms ║║Cancelling statement #379's schedules...
+1184ms ║║Executed physical command [Echo - LV Fire TV].setLevel([60]) (68ms)
+1185ms ║║Executed [Echo - LV Fire TV].setLevel (69ms)
+1215ms ║║Executed physical command [Echo - LV Living Room Dot].setLevel([60]) (27ms)
+1216ms ║║Executed [Echo - LV Living Room Dot].setLevel (28ms)
+1219ms ║║Executed virtual command [Echo - LV Fire TV, Echo - LV Living Room Dot].wait (1ms)
+1220ms ║║Waiting for 2000ms
+3350ms ║║Executed physical command [Echo - LV Fire TV].speak(NASA Alert... Rocket 3.1 is launching in 30 minutes. (Friday @ 7:00 PM). Expect the Demo Flight, at Pacific Spaceport Complex - Alaska on pad LP-3B.
+3350ms ║║null
+3351ms ║║Executed [Echo - LV Fire TV].speak (24ms)
+3370ms ║║Executed physical command [Echo - LV Living Room Dot].speak(NASA Alert... Rocket 3.1 is launching in 30 minutes. (Friday @ 7:00 PM). Expect the Demo Flight, at Pacific Spaceport Complex - Alaska on pad LP-3B.
+3370ms ║║null
+3371ms ║║Executed [Echo - LV Living Room Dot].speak (19ms)
+3373ms ║║Cancelling statement #395's schedules...
+3733ms ║║Executed virtual command sendSMSNotification (355ms)
+3738ms ║║NASA Alert... Rocket 3.1 is launching in 30 minutes. (Friday @ 7:00 PM). Expect the Demo Flight, at Pacific Spaceport Complex - Alaska on pad LP-3B.
+3738ms ║║null. https://rocketlaunch.live/launch/rocket-3-1; https://www.nasa.gov/nasalive
+3739ms ║║Executed virtual command log (1ms)
+3742ms ║║Executed virtual command setState (1ms)
+3744ms ║╚Execution stage complete. (3668ms)
+3745ms ╚Event processed successfully (3745ms)
8/7/2020, 7:27:55 PM +629ms
+0ms ╔Received event [Las Vegas].:aaa980d0f10c80523a928ba3ca55915a: = @globalLaunchTime with a delay of 201ms
+100ms ║RunTime Analysis CS &gt; 27ms &gt; PS &gt; 54ms &gt; PE &gt; 20ms &gt; CE
+103ms ║Runtime (42644 bytes) successfully initialized in 54ms (v0.3.110.20191009) (102ms)
+104ms ║╔Execution stage started
+107ms ║║Cancelling statement #392's schedules...
+113ms ║║Executed virtual command setVariable (2ms)
+117ms ║║Executed virtual command setVariable (2ms)
+120ms ║║Executed virtual command wait (1ms)
+121ms ║║Waiting for 1000ms
+1126ms ║║Comparison (datetime) 1596853676753 happens_daily_at (datetime) 1596853800000 = false (0ms)
+1127ms ║║Condition #378 evaluated false (3ms)
+1128ms ║║Cancelling statement #378's schedules...
+1131ms ║║Requesting time schedule wake up at Fri, Aug 7 2020 @ 7:30:00 PM PDT
+1134ms ║║Condition group #377 evaluated false (state did not change) (10ms)
+1136ms ║║Cancelling statement #386's schedules...
+1141ms ║║Calculating (string) Fri, Aug 7 2020 @ 7:27:56 PM PDT + (string) Alert changed: &gt;&gt; (string) Fri, Aug 7 2020 @ 7:27:56 PM PDT Alert changed:
+1145ms ║║Fri, Aug 7 2020 @ 7:27:56 PM PDT Alert changed:
+1145ms ║║Executed virtual command log (1ms)
+1150ms ║║NASA Alert... Rocket 3.1 is launching in 30 minutes. (Friday @ 7:00 PM). Expect the Demo Flight, at Pacific Spaceport Complex - Alaska on pad LP-3B.
+1150ms ║║null
+1151ms ║║Executed virtual command log (1ms)
+1156ms ║║Calculating (string) New Alert Information Received + (string) Fri, Aug 7 2020 @ 7:27:56 PM PDT &gt;&gt; (string) New Alert Information Received Fri, Aug 7 2020 @ 7:27:56 PM PDT
+1158ms ║║Executed virtual command setState (1ms)
+1160ms ║╚Execution stage complete. (1057ms)
+1161ms ║Setting up scheduled job for Fri, Aug 7 2020 @ 7:30:00 PM PDT (in 123.21s)
+1168ms ╚Event processed successfully (1168ms)

This also resulting in only one SMS message. Thank you!

WCmore · 2020-08-08 02:34:04 UTC

I don’t think you will get problems with the second execution. The @global would have plenty of time to update by then.

I was referring to the ELSE block which only runs when the @global updates. This block is the one that looks like potential trouble. (although, it’s only a log, and should fix itself hours later, so does it really matter? LOL)

WCmore · 2020-08-08 02:34:58 UTC

One sec will solve 99% of the issues.
1500ms should solve them all.

(occasionally, I have caught a piston 1200ms early… not often, but occasionally)

guxdude · 2020-08-08 02:36:26 UTC

Possibly but it is just logging and mostly there to do something when the time updates

guxdude · 2020-08-08 02:37:56 UTC

OK, I changed to 1500ms. I was just concerned what if it is not that early? Then could it overshoot?

WCmore · 2020-08-08 02:40:41 UTC

I have never seen it overshoot at 1500ms.

You have me curious now. What happens if you test overshooting by 4 seconds?
(I am choosing 4 for a specific reason)

guxdude · 2020-08-08 02:47:42 UTC

Sorry, I forgot I turned down the logging but it looks like it still ran. I got the single SMS. Can run again with full logging if you like but not until later.

8/7/2020, 7:44:59 PM +104ms
+1ms	╔Received event [Las Vegas].time = 1596854700000 with a delay of -896ms
+6615ms	║NASA Alert... Rocket 3.1 is launching in 30 minutes. (Friday @ 7:00 PM). Expect the Demo Flight, at Pacific Spaceport Complex - Alaska on pad LP-3B.
+6615ms	║null. https://rocketlaunch.live/launch/rocket-3-1; https://www.nasa.gov/nasalive
+6620ms	╚Event processed successfully (6619ms)
8/7/2020, 7:43:39 PM +679ms
+0ms	╔Received event [Las Vegas].:aaa980d0f10c80523a928ba3ca55915a: = @globalLaunchTime with a delay of 118ms
+4135ms	║Fri, Aug 7 2020 @ 7:43:43 PM PDT Alert changed:
+4140ms	║NASA Alert... Rocket 3.1 is launching in 30 minutes. (Friday @ 7:00 PM). Expect the Demo Flight, at Pacific Spaceport Complex - Alaska on pad LP-3B.
+4140ms	║null
+4148ms	║Setting up scheduled job for Fri, Aug 7 2020 @ 7:45:00 PM PDT (in 76.173s)
+4156ms	╚Event processed successfully (4156ms)

guxdude · 2020-08-08 03:24:18 UTC

Looks like overshoot is not a problem. I edited the time to an hour earlier and it just runs immediately. I guess, if the time has past, it counts as true. Perhaps because it is date & time, not just time?

WCmore · 2020-08-08 04:15:28 UTC

Truth be told, I am most pleasantly surprised that this single line:

acts like two independent triggers. (the time & the @global change)

I wonder why a @global change failed to trigger my tests in the past…
(unless it was specifically subscribed to, that is. Did you do that here?)

I think we’d have to test the future at least once more before we can reach that conclusion…
(if you wouldn’t mind)

Can you change the ‘dummy wait’ to 25 seconds, and then change the global to 5min in the future? (I am especially interested in the actions after the wait)

I’m beginning to think this project is worthy of a test piston…

guxdude · 2020-08-08 06:44:25 UTC

No, and I went back to verify:

I ran the test it this time the overshoot did not count as true but interesting when I saved after adding the 25 second wait, the log shows it subscribed to the @global variable. Both when I edit the trigger time and when the trigger time occurs, the wait is clear and in both cases it goes to the else portion.

8/7/2020, 11:32:23 PM +127ms
+1ms ╔Received event [Las Vegas].time = 1596868344465 with a delay of -1338ms
+103ms ║RunTime Analysis CS &gt; 24ms &gt; PS &gt; 59ms &gt; PE &gt; 20ms &gt; CE
+105ms ║Runtime (42547 bytes) successfully initialized in 59ms (v0.3.110.20191009) (104ms)
+106ms ║╔Execution stage started
+115ms ║║Comparison (datetime) 1596868343240 happens_daily_at (datetime) 1596868320000 = false (1ms)
+116ms ║║Condition #378 evaluated false (3ms)
+120ms ║║Cancelling statement #378's schedules...
+124ms ║║Condition group #377 evaluated false (state did not change) (10ms)
+126ms ║║Cancelling statement #386's schedules...
+134ms ║║Calculating (string) Fri, Aug 7 2020 @ 11:32:23 PM PDT + (string) Alert changed: &gt;&gt; (string) Fri, Aug 7 2020 @ 11:32:23 PM PDT Alert changed:
+137ms ║║Fri, Aug 7 2020 @ 11:32:23 PM PDT Alert changed:
+138ms ║║Executed virtual command log (1ms)
+143ms ║║NASA Alert... Ariane 5 is launching in 30 minutes. (Friday @ 4:00 PM). Expect the Galaxy 30, at Guiana Space Centre on pad ELA-3.
+143ms ║║null
+144ms ║║Executed virtual command log (2ms)
+149ms ║║Calculating (string) New Alert Information Received + (string) Fri, Aug 7 2020 @ 11:32:23 PM PDT &gt;&gt; (string) New Alert Information Received Fri, Aug 7 2020 @ 11:32:23 PM PDT
+152ms ║║Executed virtual command setState (0ms)
+154ms ║╚Execution stage complete. (48ms)
+155ms ╚Event processed successfully (155ms)
8/7/2020, 11:31:59 PM +333ms
+0ms ╔Received event [Las Vegas].time = 1596868320000 with a delay of -667ms
+111ms ║RunTime Analysis CS &gt; 32ms &gt; PS &gt; 60ms &gt; PE &gt; 19ms &gt; CE
+113ms ║Runtime (42546 bytes) successfully initialized in 60ms (v0.3.110.20191009) (112ms)
+114ms ║╔Execution stage started
+119ms ║║Cancelling statement #392's schedules...
+123ms ║║Executed virtual command setVariable (2ms)
+128ms ║║Executed virtual command setVariable (2ms)
+131ms ║║Executed virtual command wait (0ms)
+132ms ║║Requesting a wake up for Fri, Aug 7 2020 @ 11:32:24 PM PDT (in 25.0s)
+135ms ║╚Execution stage complete. (20ms)
+136ms ║Setting up scheduled job for Fri, Aug 7 2020 @ 11:32:24 PM PDT (in 24.997s)
+142ms ╚Event processed successfully (141ms)
8/7/2020, 11:28:16 PM +73ms
+1ms ╔Received event [Las Vegas].time = 1596868097515 with a delay of -1442ms
+75ms ║RunTime Analysis CS &gt; 17ms &gt; PS &gt; 40ms &gt; PE &gt; 18ms &gt; CE
+78ms ║Runtime (42546 bytes) successfully initialized in 40ms (v0.3.110.20191009) (76ms)
+79ms ║╔Execution stage started
+93ms ║║Comparison (datetime) 1596868096163 happens_daily_at (datetime) 1596868320000 = false (0ms)
+94ms ║║Condition #378 evaluated false (4ms)
+95ms ║║Cancelling statement #378's schedules...
+99ms ║║Requesting time schedule wake up at Fri, Aug 7 2020 @ 11:32:00 PM PDT
+101ms ║║Condition group #377 evaluated false (state did not change) (11ms)
+103ms ║║Cancelling statement #386's schedules...
+110ms ║║Calculating (string) Fri, Aug 7 2020 @ 11:28:16 PM PDT + (string) Alert changed: &gt;&gt; (string) Fri, Aug 7 2020 @ 11:28:16 PM PDT Alert changed:
+113ms ║║Fri, Aug 7 2020 @ 11:28:16 PM PDT Alert changed:
+114ms ║║Executed virtual command log (1ms)
+120ms ║║NASA Alert... Ariane 5 is launching in 30 minutes. (Friday @ 4:00 PM). Expect the Galaxy 30, at Guiana Space Centre on pad ELA-3.
+120ms ║║null
+121ms ║║Executed virtual command log (1ms)
+126ms ║║Calculating (string) New Alert Information Received + (string) Fri, Aug 7 2020 @ 11:28:16 PM PDT &gt;&gt; (string) New Alert Information Received Fri, Aug 7 2020 @ 11:28:16 PM PDT
+129ms ║║Executed virtual command setState (1ms)
+135ms ║╚Execution stage complete. (55ms)
+141ms ║Setting up scheduled job for Fri, Aug 7 2020 @ 11:32:00 PM PDT (in 223.787s)
+147ms ╚Event processed successfully (147ms)
8/7/2020, 11:27:52 PM +412ms
+0ms ╔Received event [Las Vegas].:aaa980d0f10c80523a928ba3ca55915a: = @globalLaunchTime with a delay of 59ms
+80ms ║RunTime Analysis CS &gt; 22ms &gt; PS &gt; 37ms &gt; PE &gt; 21ms &gt; CE
+82ms ║Runtime (42577 bytes) successfully initialized in 37ms (v0.3.110.20191009) (81ms)
+83ms ║╔Execution stage started
+88ms ║║Cancelling statement #392's schedules...
+93ms ║║Executed virtual command setVariable (3ms)
+98ms ║║Executed virtual command setVariable (2ms)
+101ms ║║Executed virtual command wait (1ms)
+102ms ║║Requesting a wake up for Fri, Aug 7 2020 @ 11:28:17 PM PDT (in 25.0s)
+107ms ║╚Execution stage complete. (23ms)
+108ms ║Setting up scheduled job for Fri, Aug 7 2020 @ 11:28:17 PM PDT (in 24.995s), with 1 more job pending
+119ms ╚Event processed successfully (119ms)
8/7/2020, 11:27:09 PM +321ms
+1ms ╔Starting piston... (v0.3.110.20191009)
+544ms ║╔Subscribing to devices...
+612ms ║║Subscribing to Las Vegas.:aaa980d0f10c80523a928ba3ca55915a:.@globalLaunchTime...
+795ms ║║Subscribing to Echo - LV Fire TV...
+796ms ║║Subscribing to Echo - LV Living Room Dot...
+797ms ║╚Finished subscribing (266ms)
+833ms ║Comparison (datetime) 1596868030151 happens_daily_at (datetime) 1597444200000 = false (1ms)
+844ms ║Cancelling statement #378's schedules...
+848ms ║Requesting time schedule wake up at Fri, Aug 14 2020 @ 3:30:00 PM PDT
+887ms ║Setting up scheduled job for Fri, Aug 14 2020 @ 3:30:00 PM PDT (in 576169.793s)
+908ms ╚Piston successfully started (907ms)

Probably useful. This is the second time the hourly update got in the way of my testing and I had to start over.

WCmore · 2020-08-08 17:06:14 UTC

I was going back thru my old pistons to try to see to see the previous hurdles…

Apparently, the code
IF Time & Date happens daily at @global
will auto-subscribe to the @global change…

The code
Every day at @global
will not subscribe (or ever see) the @global change.
(unless we create workarounds to get inside that block)

I am using “Every day” because I need that portion of code to run independently…
(with the side effect of a @global time that is tricky to update)

guxdude · 2020-08-08 17:17:48 UTC

I wondered if the time & date was the difference.

Won’t it run independently either way? It should always look for the time set and be an independent trigger.

Which is one reason I went to the separate piston fo9r the notification. It updates immediately and now I don’t get double SMS!

WCmore · 2020-08-08 17:33:31 UTC

For clarification:

My Every day at @global is the Type: “time”
My IF Time & Date happens daily at @global, is “datetime”.

(untested, but that might play a part)

My apologies. I do not understand what you are asking. Basically, a block “EVERY DAY AT X” stays inside that block during that time… and other triggers in the piston avoid that block during normal executions.

That is what I meant by running independently.
(it’s a great method to get two small independent pistons into one)

WCmore · 2020-08-08 17:37:22 UTC

More analysis:

I have done quite a bit of testing the “over-shoot” using this test piston:

When the @global changes…
IF the ‘dummy wait’ is 6 seconds or more, it always returns false, false
IF the ‘dummy wait’ is 4 seconds or less, it always returns false, TRUE

(the first false is because the @global just changed, so the time does not match)

I think my original advice of 1500ms is ideal, but now I understand the process much better.

Thanks for this experiment!

guxdude · 2020-08-08 20:06:04 UTC

Yes, my notification @global uses datetime also. For the calculations, I use a time variable. (Basically, what you started with)

I understand now. Yes, you need to use every to keep the calculations and notification separate. I put them in separate pistons so switching to ‘Time happens daily at’ for my calculation trigger worked OK.

Always fun to learn Thanks again for your help. This double SMS had been bugging me for a while.