For loop not starting first count as expected -- please educate me

[GeorgeH]

1) Give a description of the problem
I must not understand how the “for” loop works, since I get one extra iteration than expected. Hoping someone can explain to me how this is supposed to work, or maybe I’m just confused by the logs.

2) What is the expected behavior?
I expect the first iteration of the for loop to happen at 2:00am. On the 2nd iteration at 2:15am (approx), I expect the the loop count to have incremented already – which it does not.

3) What is happening/not happening?
The piston first runs at 2:00am, and I expect that the for loop first executes at that time. Looking at the log, it seems on at 2:00am the loop does not execute and then executes for the first time on the next iteration (after a 15min wait). I’m looking at the log line at 2:15am at +193msec below, which shows a count of 0 which tells me this is the FIRST iteration of the for loop rather than the 2nd.
Also, I don’t see any comparison/reference to the index comparison on that first execution at 2:00am in the log (behaviour I’d expect since its seen on later iterations, but maybe theres some initialization process on the first loop)

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

5) Attach any logs (From ST IDE and by turning logging level to Full)
(PASTE YOUR LOGS HERE BETWEEN THE MARKS THEN HIGHLIGHT ALL OF THE LOGS SND CLICK ON THE </> ICON TO FORMAT THEM)

9/30/2018, 2:14:58 AM +58ms
+1ms ╔Received event [HayekHome].time = 1538298899356 with a delay of -1298ms
+150ms ║RunTime Analysis CS > 19ms > PS > 115ms > PE > 15ms > CE
+152ms ║Runtime (39601 bytes) successfully initialized in 115ms (v0.3.108.20180906) (150ms)
+154ms ║╔Execution stage started

**+193ms ║║Comparison (decimal) 0.0 is_equal_to (integer) 10 = false (2ms)**
+195ms ║║Condition #12 evaluated false (8ms)
+197ms ║║Condition group #11 evaluated false (state did not change) (10ms)
+217ms ║║Comparison (decimal) 693.88 is_less_than_or_equal_to (integer) 150 = false (2ms)
+219ms ║║Condition #8 evaluated false (13ms)
+221ms ║║Condition group #7 evaluated false (state did not change) (15ms)
+225ms ║║Cancelling statement #9’s schedules…
+230ms ║║Executed virtual command wait (1ms)
+235ms ║║Requesting a wake up for Sun, Sep 30 2018 @ 2:29:58 AM PDT (in 900.0s)
+253ms ║╚Execution stage complete. (100ms)
+256ms ║Setting up scheduled job for Sun, Sep 30 2018 @ 2:29:58 AM PDT (in 899.98s), with 1 more job pending
+270ms ╚Event processed successfully (270ms)

9/30/2018, 1:59:59 AM +142ms
+1ms ╔Received event [HayekHome].time = 1538298000000 with a delay of -859ms
+143ms ║RunTime Analysis CS > 19ms > PS > 99ms > PE > 26ms > CE
+147ms ║Runtime (39589 bytes) successfully initialized in 99ms (v0.3.108.20180906) (145ms)
+148ms ║╔Execution stage started
+192ms ║║Comparison (decimal) 693.88 is_less_than_or_equal_to (integer) 150 = false (3ms)
+195ms ║║Condition #8 evaluated false (16ms)
+197ms ║║Condition group #7 evaluated false (state did not change) (19ms)
+202ms ║║Cancelling statement #9's schedules...
+210ms ║║Executed virtual command wait (1ms)
+213ms ║║Requesting a wake up for Sun, Sep 30 2018 @ 2:14:59 AM PDT (in 900.0s)
+222ms ║╚Execution stage complete. (74ms)
+225ms ║Setting up scheduled job for Sun, Sep 30 2018 @ 2:14:59 AM PDT (in 899.99s), with 1 more job pending
+232ms ╚Event processed successfully (233Logging levelm

REMOVE BELOW AFTER READING
If a solution is found for your question then please mark the post as the solution.s

[WCmore]

First off, I am nowhere near an expert on loops, but I imported your piston, and put in a few log commands to test your code.

When PowerMeter is greater than 150, (mimicked by my SimSwitch)
I get exactly 11 iterations in the log, perfectly spaced out:

(1 Begin, 11 Before, 11 After, and 1 Final)

This sounds correct to me…

---

Although, you should be aware that once PowerMeter becomes less than 150, that section of code runs off many times in the blink of an eye, as seen below:

It ran right on schedule, but all 10 loops (11 iterations) happened within a half second.

You can likely resolve the spam by moving the WAIT command outside both IF statements…
(to where the arrow is pointing)

[WCmore]

I added "(INDEX = '$index')" to the end of each log command.
Maybe this log file is easier to see the stages as they progress.
This is with PowerMeter above 150 all the way thru

[WCmore]

… and when PowerMeter drops below 150 part way thru:

[GeorgeH]

Thanks for the simpler log examples - from those I see that the looping behavior does look correct.
What confused me is in my original log, the statement:

+193ms ║║Comparison (decimal) 0.0 is_equal_to (integer) 10 = false (2ms)

that is in the 1st loop iteration (i.e. after the wait). It seems odd that this comparison test for the loop index was after the wait - so I assumed that implied an extra iteration. But I guess it doesn’t necessarily mean an extra iteration, only that the generated code does the loop index increment/test later (may at the end) of the loop rather than the beginning.

WRT your observation of the code behavior when PowerMEter becomes < 150 (i.e. the many times in the blink of the eye execution), that I did not expect. I thought that the “exit” command would cause the piston to immediately terminate. So I guess “exit” causes some form of lazy termination? Basically when the value becomes less than 150 I wanted to exit and do no further testing (until the next day).

Is there more to “exit” than the simple exit behavior I expected?

Thanks tons for the help!

[WCmore]

I thought that the “exit” command would cause the piston to immediately terminate.

You are correct. I forgot that I disabled that line when testing.