Some lines of code not executed

#1

1) Give a description of the problem
This piston monitors the power used by the dishwasher, when the cycle is complete a number of actions are executed. However, sometimes not all lines of code seem to run.

2) What is the expected behaviour?
Lines 42 to 51 should be run once the cycle has completed

3) What is happening/not happening?
Often everything works fine, but on some occasions only line 42 runs - sending a notification to the phone app. But the speech to the sonos and the setting of the variables does not work. Checking the activity of the socket, there has been no change in power usage for 20 mins, so not sure why lines 42 - 52 seem to be interrupted/cancelled. I have the same piston for the washing machine (different power levels etc) and this always works fine.
Also, I’m not sure I heard one of the sono’s speak, but definitely not the other. Could an issue with big talker be stopping the piston?

**4)

image
image.png1178×1602 85.6 KB

5) Attach logs after turning logging level to Full

#2

Normally, after the WAIT on line 41 has completed, then line 34 will no longer be true, so lines 42-52 will not execute. Changing TCP to Never on the WITH on line 38 should force it to complete.

Also, if Outlet 4 turns off during the WAIT, the block mentioned above will also abort.

To be honest, with five triggers all running thru the code from top to bottom, you should turn your logs to FULL during testing.

#3

Could be. I would insert a few “Log to consoles” in your code (scattered about) to easily detect which sections of code were executed.

#4

Thanks for the suggestions.

I can’t use TCP - during a full cycle the power drops to 0.6w for up to 10 mins, so I need this to be cancelled if its a mid cycle dip to 0.6w.

The power does stay below 0.6w at the end of the cycle, so the condition should still be true, in any case, if it changed, why would one line execute but not the proceeding lines?

The only triggers usually ised are the power monitoring, The virtual switch is just used to indicate in the ST app that the cycle is running, and is not usually changed manually. The main power would/is only turned off to reset the piston. Neither of these were triggered during the failed run

#5

You have five events that triggers this piston:

  1. Outlet 4’s power
  2. Switch 2’s switch changing to on
  3. Switch 2’s switch changing to off
  4. Outlet 4’s switch changing to on
  5. Outlet 4’s switch changing to off

Any of those five events runs the piston all the way thru the code from top to bottom. Executing anything allowed by conditions, and cancelling anything after waits if it no longer applies.

Power often fluctuates all throughout the day. Logging to FULL will help with diagnose

Again, logging to full (and logs to console) will either pinpoint your speech issue, or your piston issue

  • Lines 30, 50, 61, 72 & 81 all flip Switch 2.
  • That switch is subscribed to in this same piston

Meaning, each time Switch 2 switch changes, your code starts the piston all over from the top again

#6

I’ve just watched another cycle end. I saw the 10 nin countdown go to 0. The condistion was still green. The count down then turned red and started counting up. At about 30 secs the following lines had not run, and the condition changed from green

29/06/2019, 21:38:14 +217ms
+10121ms ║Piston waited at a semaphore for 10019ms
29/06/2019, 21:38:14 +194ms
+10122ms ║Piston waited at a semaphore for 10022ms
29/06/2019, 21:12:16 +188ms
+10165ms ║Piston waited at a semaphore for 10058ms
29/06/2019, 20:49:37 +472ms
+10226ms ║Piston waited at a semaphore for 10112ms

#7

This is probably due to all your triggers flipping a switch that is also a trigger. (causing your piston to loop) There are way too many things happening at once… Hence, the 10 second semaphore delay

#8

I did wonder about the virtual switch coding. I just want to use it as an indicator in the ST app. The coding is just to return it to the correct status if it is accidentally changed. Ideally the piston should only respond to a physical change of the switch and not a programmatic change, but I’m not sure if this can be done.

Is there a better way to achieve this? Would moving this to a separate piston help?

Is this causing the original problem, as the VS is the last statement executed when the cycle finishes, so the proceeding lines which speak & set the variables should already have run?

I’ll put logging full on next time the piston runs and see if any useful logging info can be obtained.

#9

I would probably move lines 53-74 into it’s own piston. (triggered by Switch 2)

Likewise, I would probably move lines 75-89 into it’s own piston. (triggered by Outlet 4)

This keeps only one piston running at any one event, and prevents needless code from running at the wrong time. (great for streamlining)

This also lets you “beef” up the extra pistons in the future, without breaking this one.

Side Note:
If you go this route, you may need to use a global variable (or argument) to pass between pistons. (and globals aren’t usually written until after the piston completes, so code accordingly)

#10

This has just failed tonight. Power dropped to 0.6, but no notification, change of virtual switch etc. (see logs)

When the power drops to 0.6, the piston runs and at the wait 10 mins sets up a “wake up” for 10:08:31. However, the piston does not resume then, at which point it should complete the end of cycle actions. It starts again at 22:10:46?

07/07/2019, 22:10:46 +842ms
+1ms ╔Received event [Home].execute = recovery with a delay of 63ms
+293ms ║RunTime Analysis CS > 16ms > PS > 223ms > PE > 54ms > CE
+296ms ║Runtime (45235 bytes) successfully initialized in 223ms (v0.3.10d.20190627) (294ms)
+297ms ║╔Execution stage started
+307ms ║║Condition #4 evaluated false (6ms)
+308ms ║║Condition group #1 evaluated false (state did not change) (7ms)
+316ms ║║Cancelling condition #9’s schedules…
+317ms ║║Condition #9 evaluated false (5ms)
+318ms ║║Cancelling condition #5’s schedules…
+318ms ║║Condition group #5 evaluated false (state changed) (8ms)
+326ms ║║Condition #28 evaluated false (5ms)
+327ms ║║Condition group #27 evaluated false (state did not change) (6ms)
+335ms ║║Condition #33 evaluated false (5ms)
+336ms ║║Condition group #32 evaluated false (state did not change) (6ms)
+343ms ║║Condition #72 evaluated false (5ms)
+344ms ║║Condition group #71 evaluated false (state did not change) (6ms)
+352ms ║╚Execution stage complete. (55ms)
+353ms ╚Event processed successfully (353ms)
07/07/2019, 21:58:31 +394ms
+1ms ╔Received event [Dishwasher].power = 0.6 with a delay of 86ms
+116ms ║RunTime Analysis CS > 21ms > PS > 37ms > PE > 57ms > CE
+118ms ║Runtime (45237 bytes) successfully initialized in 37ms (v0.3.10d.20190627) (116ms)
+119ms ║╔Execution stage started
+127ms ║║Comparison (decimal) 0.6 remains_above_or_equal_to (integer) 3 = false (0ms)
+128ms ║║Condition #4 evaluated false (5ms)
+129ms ║║Condition group #1 evaluated false (state did not change) (6ms)
+135ms ║║Comparison (decimal) 0.6 drops_to_or_below (decimal) 0.6 = true (0ms)
+136ms ║║Cancelling condition #9’s schedules…
+137ms ║║Condition #9 evaluated true (5ms)
+141ms ║║Comparison (boolean) true is (boolean) true = true (1ms)
+142ms ║║Condition #10 evaluated true (4ms)
+143ms ║║Cancelling condition #5’s schedules…
+144ms ║║Condition group #5 evaluated true (state changed) (13ms)
+147ms ║║Cancelling statement #6’s schedules…
+152ms ║║Executed virtual command [Kitchen, Lounge].wait (0ms)
+153ms ║║Requesting a wake up for Sun, Jul 7 2019 @ 10:08:31 PM BST (in 600.0s)
+157ms ║╚Execution stage complete. (38ms)
+158ms ║Setting up scheduled job for Sun, Jul 7 2019 @ 10:08:31 PM BST (in 599.996s)
+166ms ╚Event processed successfully (166ms)

#11

The log means nothing to us without also posting the piston that ran during that time

#12

Sorry, I should have said, its the same piston at the top of the post.

#13

Thanks! According to the first log at 21:58:31, everything went as expected. The conditions checked out, and webCoRE set a wakeup timer for 10 minutes in the future as expected.

What normally happens after a WAIT is:
If the condition is no longer true, then the rest of the code aborts.
(notice at 22:10:46, Condition #9 (line 34) evaluated false after the WAIT)

What actually happened in your case took place 2m 15s late, and was not a proper wakeup. (notice the “recovery” at 22:10:46). That being said, the recovery would have actually worked (albeit slightly late) if a single change was made to your piston.

The WITH block on line 38 can have Task Cancellation Policy set to Never.

What this does is force the rest of the block to run after the WAIT.
(even if the conditions are no longer true)

#14

Apologies for the late update, I’ve been rather busy this week.

I’m curious about the “recovery” happens. Is this something webcore does occasionally or is there something wrong with the way I’m doing this?

I think I understand the task cancellation policy, in this case I can’t use it. The reason for the wait is that several times during the cycle the power drops to 0.6w for around 8 mins, so I would get several “finished” notifications during the cycle.

I’m going to rewrite the piston over the weekend taking your advice to simplify.

  • Use stays below for 10 mins, rather than use the wait

  • Have the piston just trigger on the power change. I’ll leave the original piston to do the other stuff(virtual switch changed manually & dishwasher power turned off) and remove the power monitoring/alerting

I’ll post the new piston when its written & tested.

#15

This is the new piston - totally untested - I need to wait for the dishwasher to be full!

image
image.png1178×932 51.6 KB

#16

I think this was happening frequently for you because of the reasons I have already mentioned…

  • Too many triggers in your original piston
  • Sending a command which is also a trigger, which executes the piston again

I agree, this method is much more efficient. (and also works great with motion sensors)

#17

I’ve just run a dishwasher cycle, and its worked. However, it still seems to do a recover around 4 mins later than expected. Is this a problem or am I just being over fussy?

I also changed line 20 of the original piston as it would cause the piston to run every 20 secs (I think) while the power was over 3w. I’m very conscious of wasting cloud resource running the piston.

image
image.png1178×932 50.9 KB

14/07/2019, 20:52:31 +971ms
+1ms ╔Received event [Home].execute = recovery with a delay of 50ms
+116ms ║RunTime Analysis CS > 19ms > PS > 32ms > PE > 65ms > CE
+120ms ║Runtime (40109 bytes) successfully initialized in 32ms (v0.3.10d.20190627) (117ms)
+121ms ║╔Execution stage started
+134ms ║║Condition #4 evaluated false (7ms)
+135ms ║║Condition group #1 evaluated false (state did not change) (9ms)
+146ms ║║Comparison (decimal) 0.6 stays_less_than_or_equal_to (decimal) 0.6 = true (1ms)
+149ms ║║Condition #9 evaluated false (11ms)
+151ms ║║Condition group #5 evaluated false (state did not change) (13ms)
+166ms ║║Cancelling condition #9’s schedules…
+167ms ║║Condition #9 evaluated true (1ms)
+171ms ║║Comparison (boolean) true is (boolean) true = true (1ms)
+173ms ║║Cancelling condition #10’s schedules…
+174ms ║║Condition #10 evaluated true (5ms)
+175ms ║║Cancelling condition #5’s schedules…
+176ms ║║Condition group #5 evaluated true (state changed) (10ms)
+178ms ║║Cancelling statement #6’s schedules…
+215ms ║║Executed virtual command [Kitchen, Lounge].sendPushNotification (31ms)
+1010ms ║║Executed physical command [Kitchen].playTextAndResume([Dishwasher Cycle Finished, 50]) (789ms)
+1011ms ║║Executed [Kitchen].playTextAndResume (791ms)
+1706ms ║║Executed physical command [Lounge].playTextAndResume([Dishwasher Cycle Finished, 50]) (692ms)
+1708ms ║║Executed [Lounge].playTextAndResume (694ms)
+1713ms ║║Executed virtual command [Kitchen, Lounge].setVariable (2ms)
+1716ms ║║Executed virtual command [Kitchen, Lounge].setVariable (1ms)
+1719ms ║║Cancelling statement #25’s schedules…
+1735ms ║║Executed physical command [Dishwasher Running].off() (13ms)
+1735ms ║║Executed [Dishwasher Running].off (14ms)
+1738ms ║╚Execution stage complete. (1616ms)
+1739ms ╚Event processed successfully (1738ms)
14/07/2019, 20:38:51 +963ms
+2ms ╔Received event [Dishwasher].power = 0.6 with a delay of 65ms
+101ms ║RunTime Analysis CS > 17ms > PS > 34ms > PE > 49ms > CE
+103ms ║Runtime (40108 bytes) successfully initialized in 34ms (v0.3.10d.20190627) (101ms)
+104ms ║╔Execution stage started
+111ms ║║Comparison (decimal) 0.6 remains_above_or_equal_to (integer) 3 = false (1ms)
+112ms ║║Condition #4 evaluated false (4ms)
+113ms ║║Condition group #1 evaluated false (state did not change) (5ms)
+120ms ║║Comparison (decimal) 0.6 stays_less_than_or_equal_to (decimal) 0.6 = true (1ms)
+122ms ║║Adding a timed trigger schedule for condition 9
+126ms ║║Condition #9 evaluated false (10ms)
+127ms ║║Condition group #5 evaluated false (state did not change) (12ms)
+129ms ║╚Execution stage complete. (25ms)
+130ms ║Setting up scheduled job for Sun, Jul 14 2019 @ 8:48:52 PM BST (in 599.993s)
+138ms ╚Event processed successfully (137ms)

#18

I think your latest code in this piston is solid. I suspect the “recovery” is due to some other piston that was hogging your hub’s bandwidth at the time

#19

Thanks for your help on this.
I’ll continue to see how this works over the next few dishwasher cycles.

I’m not aware anything would have been hogging the hub, is there any way to monitor? I’ve not noticed delays in other pistons e.g lights always turn on as soon as a motion sensor is activated.
I do think about code efficiency and minimising the amount of code/pistons executed, the move to cloud has brought back the old principal of coding for efficiency.

#20

The most likely culprits:

  • Pistons with multiple triggers
  • Pistons with Loops
  • Pistons with WHILE statements

All three of these can bombard your hub with extraneous commands

Edit:
Motion Sensors in high traffic area (or around pets) should also be included in the above list