$currentEventAttribute does not report correctly when attribute is 'time'

guxdude · 2020-07-02 22:16:06 UTC

1) Give a description of the problem
I have a piston that uses a timer to run every hour. In the logic, I can also use the ‘test’ button and that is supposed to run everything but only under ‘test’

2) What is the expected behaviour?
Do GET request only twice a day unless I press ‘test’ or it is close to a launch

3) What is happening/not happening?
The $currentEventAttribute always seems to be ‘test’ so it keeps running the web request every time.

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

5) Attach logs after turning logging level to Full
7/2/2020, 2:23:59 PM +90ms
+1ms ╔Received event [Las Vegas].time = 1593725040000 with a delay of -910ms
+211ms ║1-Current event attribute is test <–should not be ‘test’ based on event received
+4288ms ║API pulled = A China Long March 4B rocket will launch the Gaofen mission on Friday, July 3, 2020 at 3:10 AM (UTC).

WCmore · 2020-07-02 22:33:13 UTC

All of those blocks are connected with “OR”… meaning, that log to console happens if:
$hour is equal to X
OR
{hrsToLaunch} is less than Y
OR
$cEA is test

guxdude · 2020-07-02 22:39:11 UTC

Understood. I should have explained hrsToLaunch (Y) was 6 at the time and hourToRequest (X) is 3. I tried full logging but one run fills up the log in one run because it is doing so much. Even if that wasn’t the case I am logging cEA as shown and it should not be test, should it?

WCmore · 2020-07-02 22:46:19 UTC

Hmmm. I believe you are saying that IF #1 was true (time), but IF #2 thru #5 were all false?

If I am correct, then yes, this is strange.
If you don’t have space for one complete log set to FULL, perhaps try it as MEDIUM?

Although, logic suggests that there is no need for a double: “IF @cES is test”.
I mean, if it gets past the first one, what is the point of the second?

NM, I see now

guxdude · 2020-07-02 22:50:52 UTC

The first gets it into the larger ‘if’. The second gets into the smaller Get request portion. If only on the first, it would run an update of the gauges but not pull new data.

In this case, time was true and ‘test’ was true for the first if but the hourToRequest and HrsToLaunch were both false so it should have only updated the gauges but instead it also pulled new data because ‘test’ was true.

WCmore · 2020-07-02 22:52:06 UTC

How is this possible? The trigger shows it was Time based in the log.
(IE: did you really press Test? because it is not shown here)

guxdude · 2020-07-02 22:53:34 UTC

No, I waited for the timer to run but for some reason, cEA was still reported as ‘test’.

WCmore · 2020-07-02 22:57:05 UTC

Oh, in that case, I would make a new piston for testing… Something like this:

This way, you can keep a FULL log, and see more details.

guxdude · 2020-07-02 23:01:45 UTC

Great minds think alike. I just created that with a 2 minute loop to see what happens.

guxdude · 2020-07-02 23:13:22 UTC

Here is my first test. I created the piston below. First I pressed test and then waited for two timer cycles.

7/2/2020, 4:10:26 PM +65ms
+1ms ╔Received event [Las Vegas].time = 1593731425666 with a delay of 399ms
+103ms ║RunTime Analysis CS &gt; 24ms &gt; PS &gt; 64ms &gt; PE &gt; 14ms &gt; CE
+105ms ║Runtime (40048 bytes) successfully initialized in 64ms (v0.3.110.20191009) (103ms)
+106ms ║╔Execution stage started
+118ms ║║Comparison (time) 58226177 happens_daily_at (datetime) 1593731546179 = true (1ms)
+121ms ║║Time restriction check passed
+123ms ║║Condition #2 evaluated true (11ms)
+127ms ║║Cancelling statement #2's schedules...
+135ms ║║Requesting time schedule wake up at Thu, Jul 2 2020 @ 4:12:26 PM PDT
+138ms ║║Condition group #1 evaluated true (state did not change) (26ms)
+140ms ║║Cancelling statement #4's schedules...
+146ms ║║Calculating (string) Current Event Attribute: + (string) test &gt;&gt; (string) Current Event Attribute: test
+150ms ║║Current Event Attribute: test
+151ms ║║Executed virtual command log (1ms)
+162ms ║╚Execution stage complete. (56ms)
+164ms ║Setting up scheduled job for Thu, Jul 2 2020 @ 4:12:26 PM PDT (in 119.967s)
+170ms ╚Event processed successfully (170ms)
7/2/2020, 4:08:25 PM +579ms
+1ms ╔Received event [Las Vegas].time = 1593731306700 with a delay of -1121ms
+67ms ║RunTime Analysis CS &gt; 19ms &gt; PS &gt; 39ms &gt; PE &gt; 9ms &gt; CE
+70ms ║Runtime (40049 bytes) successfully initialized in 39ms (v0.3.110.20191009) (67ms)
+71ms ║╔Execution stage started
+81ms ║║Comparison (time) 58105655 happens_daily_at (datetime) 1593731425657 = true (0ms)
+82ms ║║Time restriction check passed
+83ms ║║Cancelling condition #2's schedules...
+84ms ║║Condition #2 evaluated true (9ms)
+85ms ║║Cancelling statement #2's schedules...
+90ms ║║Requesting time schedule wake up at Thu, Jul 2 2020 @ 4:10:25 PM PDT
+93ms ║║Condition group #1 evaluated true (state did not change) (17ms)
+95ms ║║Cancelling statement #4's schedules...
+100ms ║║Calculating (string) Current Event Attribute: + (string) test &gt;&gt; (string) Current Event Attribute: test
+104ms ║║Current Event Attribute: test
+105ms ║║Executed virtual command log (2ms)
+107ms ║╚Execution stage complete. (37ms)
+109ms ║Setting up scheduled job for Thu, Jul 2 2020 @ 4:10:25 PM PDT (in 119.979s)
+117ms ╚Event processed successfully (117ms)
7/2/2020, 4:06:26 PM +605ms
+0ms ╔Received event [Las Vegas].test = 1593731186605 with a delay of 1ms
+67ms ║RunTime Analysis CS &gt; 20ms &gt; PS &gt; 38ms &gt; PE &gt; 8ms &gt; CE
+69ms ║Runtime (40045 bytes) successfully initialized in 38ms (v0.3.110.20191009) (68ms)
+70ms ║╔Execution stage started
+81ms ║║Comparison (time) 57986680 happens_daily_at (datetime) 1593731306682 = false (1ms)
+83ms ║║Cancelling condition #2's schedules...
+84ms ║║Condition #2 evaluated false (8ms)
+93ms ║║Cancelling statement #2's schedules...
+99ms ║║Requesting time schedule wake up at Thu, Jul 2 2020 @ 4:08:26 PM PDT
+105ms ║║Comparison (string) test is (string) test = true (1ms)
+106ms ║║Cancelling condition #3's schedules...
+107ms ║║Condition #3 evaluated true (6ms)
+108ms ║║Condition group #1 evaluated true (state did not change) (34ms)
+110ms ║║Cancelling statement #4's schedules...
+116ms ║║Calculating (string) Current Event Attribute: + (string) test &gt;&gt; (string) Current Event Attribute: test
+120ms ║║Current Event Attribute: test
+121ms ║║Executed virtual command log (1ms)
+134ms ║╚Execution stage complete. (64ms)
+136ms ║Setting up scheduled job for Thu, Jul 2 2020 @ 4:08:26 PM PDT (in 119.96s)
+146ms ╚Event processed successfully (145ms)

EDIT: Here is another test. I edited the piston but didn’t change anything. I saved and then waited for one timer cycle, hit test, and then waited for another timer cycle, You see this time, it showed attribute as time but after I hit test, it continues to show ‘test’

7/2/2020, 4:17:52 PM +131ms
+1ms ╔Received event [Las Vegas].time = 1593731873923 with a delay of -1792ms
+152ms ║RunTime Analysis CS &gt; 47ms &gt; PS &gt; 92ms &gt; PE &gt; 13ms &gt; CE
+155ms ║Runtime (40051 bytes) successfully initialized in 92ms (v0.3.110.20191009) (153ms)
+156ms ║╔Execution stage started
+169ms ║║Comparison (time) 58672293 happens_daily_at (datetime) 1593731992295 = true (1ms)
+173ms ║║Time restriction check passed
+174ms ║║Cancelling condition #2's schedules...
+175ms ║║Condition #2 evaluated true (13ms)
+182ms ║║Cancelling statement #2's schedules...
+188ms ║║Requesting time schedule wake up at Thu, Jul 2 2020 @ 4:19:52 PM PDT
+190ms ║║Condition group #1 evaluated true (state did not change) (29ms)
+192ms ║║Cancelling statement #4's schedules...
+198ms ║║Calculating (string) Current Event Attribute: + (string) test &gt;&gt; (string) Current Event Attribute: test
+203ms ║║Current Event Attribute: test
+204ms ║║Executed virtual command log (2ms)
+207ms ║╚Execution stage complete. (50ms)
+208ms ║Setting up scheduled job for Thu, Jul 2 2020 @ 4:19:52 PM PDT (in 119.977s)
+215ms ╚Event processed successfully (215ms)
7/2/2020, 4:15:53 PM +788ms
+1ms ╔Received event [Las Vegas].test = 1593731753788 with a delay of 0ms
+105ms ║RunTime Analysis CS &gt; 26ms &gt; PS &gt; 61ms &gt; PE &gt; 17ms &gt; CE
+107ms ║Runtime (40047 bytes) successfully initialized in 61ms (v0.3.110.20191009) (105ms)
+109ms ║╔Execution stage started
+120ms ║║Comparison (time) 58553902 happens_daily_at (datetime) 1593731873904 = false (0ms)
+122ms ║║Cancelling condition #2's schedules...
+123ms ║║Condition #2 evaluated false (9ms)
+132ms ║║Cancelling statement #2's schedules...
+139ms ║║Requesting time schedule wake up at Thu, Jul 2 2020 @ 4:17:53 PM PDT
+147ms ║║Comparison (string) test is (string) test = true (2ms)
+149ms ║║Cancelling condition #3's schedules...
+150ms ║║Condition #3 evaluated true (6ms)
+151ms ║║Condition group #1 evaluated true (state did not change) (38ms)
+153ms ║║Cancelling statement #4's schedules...
+162ms ║║Calculating (string) Current Event Attribute: + (string) test &gt;&gt; (string) Current Event Attribute: test
+166ms ║║Current Event Attribute: test
+167ms ║║Executed virtual command log (2ms)
+203ms ║╚Execution stage complete. (95ms)
+207ms ║Setting up scheduled job for Thu, Jul 2 2020 @ 4:17:53 PM PDT (in 119.929s)
+218ms ╚Event processed successfully (217ms)
7/2/2020, 4:15:38 PM +214ms
+1ms ╔Received event [Las Vegas].time = 1593731739265 with a delay of -1051ms
+110ms ║RunTime Analysis CS &gt; 29ms &gt; PS &gt; 67ms &gt; PE &gt; 14ms &gt; CE
+113ms ║Runtime (40053 bytes) successfully initialized in 67ms (v0.3.110.20191009) (111ms)
+114ms ║╔Execution stage started
+125ms ║║Comparison (time) 58538333 happens_daily_at (datetime) 1593731858335 = true (1ms)
+126ms ║║Time restriction check passed
+127ms ║║Cancelling condition #2's schedules...
+128ms ║║Condition #2 evaluated true (9ms)
+129ms ║║Cancelling statement #2's schedules...
+136ms ║║Requesting time schedule wake up at Thu, Jul 2 2020 @ 4:17:38 PM PDT
+138ms ║║Cancelling condition #1's schedules...
+139ms ║║Condition group #1 evaluated true (state changed) (20ms)
+141ms ║║Cancelling statement #4's schedules...
+147ms ║║Calculating (string) Current Event Attribute: + (string) time &gt;&gt; (string) Current Event Attribute: time
+151ms ║║Current Event Attribute: time
+152ms ║║Executed virtual command log (2ms)
+154ms ║╚Execution stage complete. (40ms)
+156ms ║Setting up scheduled job for Thu, Jul 2 2020 @ 4:17:38 PM PDT (in 119.977s)
+165ms ╚Event processed successfully (165ms)

WCmore · 2020-07-02 23:44:46 UTC

Great logging… It definitely appears to be “sticky”…
(I always thought $currentEventAttribute was null 99% of the time, like $args)

If that is true, then perhaps Time is clearing itself properly, but Test is residual.

guxdude · 2020-07-03 00:30:32 UTC

Actually, I think ‘test’ is setting itself properly but ‘time’ is not. I believe cEA should be populated on each run based on the event. I created another piston:

As you can see, all this one does is call the first one. You can see the logs below but here is the summary:

After edit:
1st run on timer --> cEA is ‘time’
2nd run when I hit test on piston 2 --> cEA is ‘execute’
3rd run on timer --> cEA is ‘execute’
4th run when I hit test on piston 1 --> cEA is ‘test’
5th run on timer --> cEA is ‘test’
6th run when I hit test on piston 2 --> cEA is ‘execute’
7th run on timer --> cEA is ‘execute’

I believe this may be a bug. I am going to run a couple more tests to check a fixed value for the timer and using ‘every’.

7/2/2020, 5:23:21 PM +209ms
+0ms ╔Received event [Las Vegas].time = 1593735802658 with a delay of -1450ms
+105ms ║RunTime Analysis CS &gt; 25ms &gt; PS &gt; 62ms &gt; PE &gt; 19ms &gt; CE
+108ms ║Runtime (40061 bytes) successfully initialized in 62ms (v0.3.110.20191009) (106ms)
+109ms ║╔Execution stage started
+119ms ║║Comparison (time) 62601322 happens_daily_at (datetime) 1593735921324 = true (0ms)
+120ms ║║Time restriction check passed
+121ms ║║Cancelling condition #2's schedules...
+122ms ║║Condition #2 evaluated true (9ms)
+123ms ║║Cancelling statement #2's schedules...
+128ms ║║Requesting time schedule wake up at Thu, Jul 2 2020 @ 5:25:21 PM PDT
+131ms ║║Cancelling condition #1's schedules...
+131ms ║║Condition group #1 evaluated true (state changed) (18ms)
+134ms ║║Cancelling statement #4's schedules...
+139ms ║║Calculating (string) Current Event Attribute: + (string) execute &gt;&gt; (string) Current Event Attribute: execute
+142ms ║║Current Event Attribute: execute
+143ms ║║Executed virtual command log (1ms)
+145ms ║╚Execution stage complete. (37ms)
+147ms ║Setting up scheduled job for Thu, Jul 2 2020 @ 5:25:21 PM PDT (in 119.979s)
+154ms ╚Event processed successfully (155ms)
7/2/2020, 5:21:22 PM +481ms
+1ms ╔Received event [Las Vegas].execute = :f8a03f565ecfd06745d5f6b024948ebe: with a delay of 91ms
+160ms ║RunTime Analysis CS &gt; 86ms &gt; PS &gt; 57ms &gt; PE &gt; 17ms &gt; CE
+162ms ║Runtime (40073 bytes) successfully initialized in 57ms (v0.3.110.20191009) (160ms)
+163ms ║╔Execution stage started
+172ms ║║Comparison (time) 62482648 happens_daily_at (datetime) 1593735802650 = false (0ms)
+173ms ║║Cancelling condition #2's schedules...
+174ms ║║Condition #2 evaluated false (7ms)
+175ms ║║Cancelling statement #2's schedules...
+180ms ║║Requesting time schedule wake up at Thu, Jul 2 2020 @ 5:23:22 PM PDT
+185ms ║║Comparison (string) execute is (string) test = false (1ms)
+186ms ║║Cancelling condition #3's schedules...
+187ms ║║Condition #3 evaluated false (5ms)
+188ms ║║Cancelling condition #1's schedules...
+189ms ║║Condition group #1 evaluated false (state changed) (22ms)
+191ms ║║Cancelling statement #4's schedules...
+196ms ║║Calculating (string) Current Event Attribute: + (string) execute &gt;&gt; (string) Current Event Attribute: execute
+199ms ║║Current Event Attribute: execute
+200ms ║║Executed virtual command log (1ms)
+202ms ║╚Execution stage complete. (39ms)
+203ms ║Setting up scheduled job for Thu, Jul 2 2020 @ 5:23:22 PM PDT (in 119.974s)
+213ms ╚Event processed successfully (213ms)
7/2/2020, 5:20:54 PM +188ms
+0ms ╔Received event [Las Vegas].time = 1593735655564 with a delay of -1377ms
+95ms ║RunTime Analysis CS &gt; 21ms &gt; PS &gt; 59ms &gt; PE &gt; 16ms &gt; CE
+98ms ║Runtime (40052 bytes) successfully initialized in 59ms (v0.3.110.20191009) (96ms)
+99ms ║╔Execution stage started
+110ms ║║Comparison (time) 62454293 happens_daily_at (datetime) 1593735774295 = true (1ms)
+111ms ║║Time restriction check passed
+113ms ║║Cancelling condition #2's schedules...
+113ms ║║Condition #2 evaluated true (9ms)
+114ms ║║Cancelling statement #2's schedules...
+123ms ║║Requesting time schedule wake up at Thu, Jul 2 2020 @ 5:22:54 PM PDT
+127ms ║║Condition group #1 evaluated true (state did not change) (22ms)
+130ms ║║Cancelling statement #4's schedules...
+138ms ║║Calculating (string) Current Event Attribute: + (string) test &gt;&gt; (string) Current Event Attribute: test
+142ms ║║Current Event Attribute: test
+143ms ║║Executed virtual command log (1ms)
+145ms ║╚Execution stage complete. (46ms)
+146ms ║Setting up scheduled job for Thu, Jul 2 2020 @ 5:22:54 PM PDT (in 119.972s)
+153ms ╚Event processed successfully (153ms)
7/2/2020, 5:18:55 PM +474ms
+0ms ╔Received event [Las Vegas].test = 1593735535474 with a delay of 1ms
+69ms ║RunTime Analysis CS &gt; 20ms &gt; PS &gt; 36ms &gt; PE &gt; 12ms &gt; CE
+72ms ║Runtime (40051 bytes) successfully initialized in 36ms (v0.3.110.20191009) (70ms)
+73ms ║╔Execution stage started
+84ms ║║Comparison (time) 62335552 happens_daily_at (datetime) 1593735655554 = false (0ms)
+85ms ║║Cancelling condition #2's schedules...
+86ms ║║Condition #2 evaluated false (9ms)
+88ms ║║Cancelling statement #2's schedules...
+94ms ║║Requesting time schedule wake up at Thu, Jul 2 2020 @ 5:20:55 PM PDT
+99ms ║║Comparison (string) test is (string) test = true (1ms)
+101ms ║║Cancelling condition #3's schedules...
+102ms ║║Condition #3 evaluated true (6ms)
+103ms ║║Condition group #1 evaluated true (state did not change) (26ms)
+106ms ║║Cancelling statement #4's schedules...
+112ms ║║Calculating (string) Current Event Attribute: + (string) test &gt;&gt; (string) Current Event Attribute: test
+115ms ║║Current Event Attribute: test
+116ms ║║Executed virtual command log (1ms)
+119ms ║╚Execution stage complete. (47ms)
+120ms ║Setting up scheduled job for Thu, Jul 2 2020 @ 5:20:55 PM PDT (in 119.97s)
+131ms ╚Event processed successfully (131ms)
7/2/2020, 5:18:25 PM +121ms
+1ms ╔Received event [Las Vegas].time = 1593735506716 with a delay of -1595ms
+107ms ║RunTime Analysis CS &gt; 21ms &gt; PS &gt; 72ms &gt; PE &gt; 14ms &gt; CE
+110ms ║Runtime (40061 bytes) successfully initialized in 72ms (v0.3.110.20191009) (108ms)
+111ms ║╔Execution stage started
+121ms ║║Comparison (time) 62305237 happens_daily_at (datetime) 1593735625239 = true (1ms)
+122ms ║║Time restriction check passed
+124ms ║║Cancelling condition #2's schedules...
+124ms ║║Condition #2 evaluated true (8ms)
+125ms ║║Cancelling statement #2's schedules...
+131ms ║║Requesting time schedule wake up at Thu, Jul 2 2020 @ 5:20:25 PM PDT
+134ms ║║Cancelling condition #1's schedules...
+135ms ║║Condition group #1 evaluated true (state changed) (19ms)
+137ms ║║Cancelling statement #4's schedules...
+143ms ║║Calculating (string) Current Event Attribute: + (string) execute &gt;&gt; (string) Current Event Attribute: execute
+146ms ║║Current Event Attribute: execute
+147ms ║║Executed virtual command log (2ms)
+149ms ║╚Execution stage complete. (39ms)
+150ms ║Setting up scheduled job for Thu, Jul 2 2020 @ 5:20:25 PM PDT (in 119.978s)
+159ms ╚Event processed successfully (159ms)
7/2/2020, 5:16:26 PM +613ms
+0ms ╔Received event [Las Vegas].execute = :f8a03f565ecfd06745d5f6b024948ebe: with a delay of 72ms
+85ms ║RunTime Analysis CS &gt; 24ms &gt; PS &gt; 49ms &gt; PE &gt; 13ms &gt; CE
+87ms ║Runtime (40073 bytes) successfully initialized in 49ms (v0.3.110.20191009) (86ms)
+88ms ║╔Execution stage started
+98ms ║║Comparison (time) 62186706 happens_daily_at (datetime) 1593735506707 = false (0ms)
+99ms ║║Cancelling condition #2's schedules...
+100ms ║║Condition #2 evaluated false (8ms)
+101ms ║║Cancelling statement #2's schedules...
+106ms ║║Requesting time schedule wake up at Thu, Jul 2 2020 @ 5:18:26 PM PDT
+111ms ║║Comparison (string) execute is (string) test = false (1ms)
+113ms ║║Condition #3 evaluated false (4ms)
+114ms ║║Cancelling condition #1's schedules...
+114ms ║║Condition group #1 evaluated false (state changed) (22ms)
+117ms ║║Cancelling statement #4's schedules...
+122ms ║║Calculating (string) Current Event Attribute: + (string) execute &gt;&gt; (string) Current Event Attribute: execute
+125ms ║║Current Event Attribute: execute
+126ms ║║Executed virtual command log (1ms)
+128ms ║╚Execution stage complete. (40ms)
+129ms ║Setting up scheduled job for Thu, Jul 2 2020 @ 5:18:26 PM PDT (in 119.974s)
+139ms ╚Event processed successfully (139ms)
7/2/2020, 5:16:09 PM +156ms
+1ms ╔Received event [Las Vegas].time = 1593735370667 with a delay of -1511ms
+69ms ║RunTime Analysis CS &gt; 17ms &gt; PS &gt; 42ms &gt; PE &gt; 10ms &gt; CE
+72ms ║Runtime (40054 bytes) successfully initialized in 42ms (v0.3.110.20191009) (70ms)
+72ms ║╔Execution stage started
+82ms ║║Comparison (time) 62169233 happens_daily_at (datetime) 1593735489235 = true (0ms)
+83ms ║║Time restriction check passed
+85ms ║║Cancelling condition #2's schedules...
+85ms ║║Condition #2 evaluated true (8ms)
+86ms ║║Cancelling statement #2's schedules...
+92ms ║║Requesting time schedule wake up at Thu, Jul 2 2020 @ 5:18:09 PM PDT
+94ms ║║Cancelling condition #1's schedules...
+95ms ║║Condition group #1 evaluated true (state changed) (17ms)
+97ms ║║Cancelling statement #4's schedules...
+102ms ║║Calculating (string) Current Event Attribute: + (string) time &gt;&gt; (string) Current Event Attribute: time
+106ms ║║Current Event Attribute: time
+106ms ║║Executed virtual command log (1ms)
+108ms ║╚Execution stage complete. (36ms)
+110ms ║Setting up scheduled job for Thu, Jul 2 2020 @ 5:18:09 PM PDT (in 119.98s)
+119ms ╚Event processed successfully (119ms)

guxdude · 2020-07-03 00:55:51 UTC

Test #3: I set the timer to every day last 5:40 PM. Same result. After pressing test, when the timer condition became true, the cEA was still ‘test’.

7/2/2020, 5:39:59 PM +91ms
+0ms ╔Received event [Las Vegas].time = 1593736800000 with a delay of -909ms
+87ms ║RunTime Analysis CS &gt; 19ms &gt; PS &gt; 53ms &gt; PE &gt; 14ms &gt; CE
+89ms ║Runtime (39874 bytes) successfully initialized in 53ms (v0.3.110.20191009) (88ms)
+90ms ║╔Execution stage started
+96ms ║║Comparison (time) 63599186 happens_daily_at (time) 63600000 = true (0ms)
+98ms ║║Time restriction check passed
+99ms ║║Cancelling condition #2's schedules...
+100ms ║║Condition #2 evaluated true (6ms)
+101ms ║║Cancelling statement #2's schedules...
+104ms ║║Requesting time schedule wake up at Fri, Jul 3 2020 @ 5:40:00 PM PDT
+106ms ║║Condition group #1 evaluated true (state did not change) (12ms)
+108ms ║║Cancelling statement #4's schedules...
+114ms ║║Calculating (string) Current Event Attribute: + (string) test &gt;&gt; (string) Current Event Attribute: test
+117ms ║║Current Event Attribute: test
+118ms ║║Executed virtual command log (2ms)
+120ms ║╚Execution stage complete. (31ms)
+121ms ║Setting up scheduled job for Fri, Jul 3 2020 @ 5:40:00 PM PDT (in 86400.788s)
+126ms ╚Event processed successfully (126ms)
7/2/2020, 5:37:13 PM +639ms
+1ms ╔Received event [Las Vegas].test = 1593736633639 with a delay of 0ms
+93ms ║RunTime Analysis CS &gt; 23ms &gt; PS &gt; 51ms &gt; PE &gt; 19ms &gt; CE
+96ms ║Runtime (39873 bytes) successfully initialized in 51ms (v0.3.110.20191009) (94ms)
+97ms ║╔Execution stage started
+104ms ║║Comparison (time) 63433741 happens_daily_at (time) 63600000 = false (1ms)
+106ms ║║Condition #2 evaluated false (5ms)
+109ms ║║Cancelling statement #2's schedules...
+113ms ║║Requesting time schedule wake up at Thu, Jul 2 2020 @ 5:40:00 PM PDT
+121ms ║║Comparison (string) test is (string) test = true (1ms)
+122ms ║║Cancelling condition #3's schedules...
+123ms ║║Condition #3 evaluated true (6ms)
+125ms ║║Cancelling condition #1's schedules...
+126ms ║║Condition group #1 evaluated true (state changed) (24ms)
+128ms ║║Cancelling statement #4's schedules...
+136ms ║║Calculating (string) Current Event Attribute: + (string) test &gt;&gt; (string) Current Event Attribute: test
+140ms ║║Current Event Attribute: test
+141ms ║║Executed virtual command log (1ms)
+173ms ║╚Execution stage complete. (76ms)
+176ms ║Setting up scheduled job for Thu, Jul 2 2020 @ 5:40:00 PM PDT (in 166.186s)
+185ms ╚Event processed successfully (185ms)

Test #4. Using timer every 2 minutes.

I used this piston:

Logs show:
1st run on timer --> cEA is ‘time’
2nd run pressing test --> cEA is ‘test’
3rd run on timer --> cEA is ‘time’

7/2/2020, 5:51:20 PM +218ms
+0ms ╔Received event [Las Vegas].time = 1593737481092 with a delay of -875ms
+164ms ║RunTime Analysis CS &gt; 40ms &gt; PS &gt; 110ms &gt; PE &gt; 14ms &gt; CE
+166ms ║Runtime (40918 bytes) successfully initialized in 110ms (v0.3.110.20191009) (165ms)
+167ms ║╔Execution stage started
+175ms ║║Cancelling statement #4's schedules...
+181ms ║║Calculating (string) Every: Current Event Attribute: + (string) time &gt;&gt; (string) Every: Current Event Attribute: time
+185ms ║║Every: Current Event Attribute: time
+186ms ║║Executed virtual command log (1ms)
+188ms ║╚Execution stage complete. (22ms)
+190ms ║Setting up scheduled job for Thu, Jul 2 2020 @ 5:53:21 PM PDT (in 120.685s)
+197ms ╚Event processed successfully (197ms)
7/2/2020, 5:49:34 PM +208ms
+1ms ╔Received event [Las Vegas].test = 1593737374208 with a delay of 0ms
+90ms ║RunTime Analysis CS &gt; 24ms &gt; PS &gt; 51ms &gt; PE &gt; 15ms &gt; CE
+93ms ║Runtime (40912 bytes) successfully initialized in 51ms (v0.3.110.20191009) (92ms)
+94ms ║╔Execution stage started
+127ms ║║Cancelling statement #7's schedules...
+133ms ║║Calculating (string) Current Event Attribute: + (string) test &gt;&gt; (string) Current Event Attribute: test
+137ms ║║Current Event Attribute: test
+138ms ║║Executed virtual command log (2ms)
+156ms ║╚Execution stage complete. (62ms)
+159ms ║Setting up scheduled job for Thu, Jul 2 2020 @ 5:51:21 PM PDT (in 106.726s)
+172ms ╚Event processed successfully (172ms)
7/2/2020, 5:49:20 PM +117ms
+1ms ╔Received event [Las Vegas].time = 1593737361092 with a delay of -975ms
+221ms ║RunTime Analysis CS &gt; 21ms &gt; PS &gt; 180ms &gt; PE &gt; 19ms &gt; CE
+223ms ║Runtime (40918 bytes) successfully initialized in 180ms (v0.3.110.20191009) (221ms)
+224ms ║╔Execution stage started
+234ms ║║Cancelling statement #4's schedules...
+240ms ║║Calculating (string) Every: Current Event Attribute: + (string) time &gt;&gt; (string) Every: Current Event Attribute: time
+245ms ║║Every: Current Event Attribute: time
+246ms ║║Executed virtual command log (2ms)
+249ms ║╚Execution stage complete. (25ms)
+250ms ║Setting up scheduled job for Thu, Jul 2 2020 @ 5:51:21 PM PDT (in 120.725s)
+258ms ╚Event processed successfully (258ms)

So it appears ‘time happens daily at’ does not work properly but ‘every’ does. I suppose I should post this to bugs.

WCmore · 2020-07-03 01:11:50 UTC

I might have written poorly above, but I believe your observations are based on the assumption that cEA keeps data (like normal variables do).

My observations are based on the assumption that cEA is null 99.9% of the time (like normal $args are)

This is hard to confirm either way without digging thru the groovy code.

IE: When a piston is running, “something” is in cEA…
but when a piston is NOT running, there should be no data there…

It looks to me like Test does not clear itself afterwards.

Possibly related:
Notice how both Test and Timer are both inconsistent in all of your testing.
(although the pattern is your Timer shows the previous Test, whatever that happened to be)

guxdude · 2020-07-03 01:40:25 UTC

Yes, I thought that was what you were saying when you said ‘test’ was ‘sticky’

Actually, I only think ‘time’ is not working. Definitely when editing, cEA is always null. No way to tell any other time between runs but, based on observations, there must be some sort of ‘memory’ or cache. As an experiment, I edited and ran again so it was reporting cEA as ‘time’ and then I pushed test on another piston. No effect as this one continued to report ‘time’ until I pressed test on this piston and then it was stuck on ‘test’ again. So values of cEA in other pistons do not seem to have an impact.

Not sure how it remembers but when the event is ‘time’ it reports whatever the previous event was (execute or test) but execute and test always are correct when run in that manner. Somehow it ‘remembers’ what the last event was (execute or test) and reports that whenever the event should be time. It is very strange but definitely repeatable.

guxdude · 2020-07-03 01:42:25 UTC

What is disconcerting here is that I use the cEA is ‘test’ as a check for initialization in many of my pistons. Now it seems maybe they are initializing multiple times? I will have to check back on those.

WCmore · 2020-07-03 01:46:29 UTC

This conflicts with your earlier statement:

guxdude · 2020-07-03 01:49:09 UTC

Sorry, I’m sure it was confusing. cEA is always as reported by piston 1. Piston 2 only makes piston 1 run with an ‘execute’ event.

WCmore · 2020-07-03 01:50:40 UTC

Oh, so all of your observations are from one piston, one log, but three different type of triggers.

Self time, self test, and other piston that executes this piston…

What kind of shenanigans do you have to do to get Time to actually appear?

guxdude · 2020-07-03 01:52:19 UTC

Correct.

I just press ‘edit’ and immediately press ‘save’. The next timer run reports ‘time’. If it runs any other way, though, it never seems to go back to ‘time’