What I thought was not well documented is incorrect evaluation of statements in the piston.
You are quite correct that avoiding nested triggers is covered. The subtlety that a condition “becomes” a trigger upon subscription over-rides is not explicitly called out. In fact, one of the posts attempting to provide a definition of the trigger ( Conditions and Triggers: The difference? ) implies to me that my first condition is not a trigger since it was in the “condition” set of choices in the drop-down list. If I read carefully an earlier post ( Conditions and Triggers: The difference? ) then I could conclude my condition is considered a trigger (and thus should not be nested).
Now after seeing this execution correctness problems, I can find mention by others of similar issues when trigger statements are “late” in the expression ( Piston not running when condition met )… it’s not clear this is the same case I have but invalid expression execution due to trigger ordering is apparently already known.
So back to my test case… that code & log is below. For this test, I toggled the sensor from open to closed, after the piston had fired. So when the timer expired, the contact was closed, which is confirmed in the trace spit out @+163ms – but that state was ignored by code in line 22 of the piston on that run. I’m guessing the behavior has something to do with the “trigger” nature of the first IF condition, and only the trigger that fires the piston is evaluated on that run.
For my original code issue, I have added a “redundant” condition-only IF test after the timeout condition statement in the inner IF statement, that seems to have solved the problem. I could post that final code but suspect its a point solution of little interest. The more interesting matter (perhaps) is pointing out the behavior I saw for others.
Thanks again for your help - I at least (kinda) understand root cause, and more importantly have a fix.
4/4/2019, 3:18:50 PM +62ms
+1ms ╔Received event [HayekHome].time = 1554416330903 with a delay of -842ms
+150ms ║*** INNER IF TIMEOUT EXPIRED, CURRENT CONTACT STATE IS:
+163ms ║closed
+167ms ╚Event processed successfully (167ms)
4/4/2019, 3:17:01 PM +401ms
+1ms ╔Received event [Virtual contact sensor TEST].contact = closed with a delay of 71ms
+188ms ║*** CONTACT ELSE CONDITION WAS SATISFIED, CURRENT CONTACT STATE IS:
+199ms ║closed
+204ms ║Setting up scheduled job for Thu, Apr 4 2019 @ 3:18:50 PM PDT (in 109.299s)
+217ms ╚Event processed successfully (217ms)
4/4/2019, 3:16:50 PM +702ms
+2ms ╔Received event [Virtual contact sensor TEST].contact = open with a delay of 76ms
+184ms ║*** CONTACT IF CONDITION WAS SATISFIED
+207ms ║Setting up scheduled job for Thu, Apr 4 2019 @ 3:18:50 PM PDT (in 119.995s)
+217ms ╚Event processed successfully (217ms)