Make a GET request is causing loop execution problems

[kpslc]

**1) Created a simple piston that executes every minute (for testing). Normally it runs every 60 minutes.
This piston switches on two devices
Waits 15 seconds
switches the two devices off

2) What is the expected behaviour?
It has been working properly for a few weeks.

3) What is happening/not happening?
I added two simple get requests to log the data to a google sheets file. I’ve done this many other times without an issue.

The problem is once the first get is encountered, the piston continues to run the the first with statement that turns on both devices and logs the data to google.

If I comment out the get request, the piston starts acting normally again. Why would the get request cause this behavior?

**4)

5. This is a copy of the output on google. It shows that the first get is executing every 15 seconds:
   

Here is a log file
5/31/2020, 10:39:51 PM +448ms
+50ms ╔Stopping piston…
+102ms ╚Piston successfully stopped (52ms)
5/31/2020, 10:39:42 PM +137ms
+0ms ╔Received event [Heber GH].time = 1590986383298 with a delay of -1161ms
+54ms ║RunTime Analysis CS > 17ms > PS > 5ms > PE > 31ms > CE
+56ms ║Runtime (40533 bytes) successfully initialized in 5ms (v0.3.110.20191009) (55ms)
+57ms ║╔Execution stage started
+66ms ║║Cancelling statement #2’s schedules…
+80ms ║║Skipped execution of physical command [Return pump].on([]) because it would make no change to the device. (8ms)
+81ms ║║Executed [Return pump].on (11ms)
+93ms ║║Skipped execution of physical command [Return UV light].on([]) because it would make no change to the device. (9ms)
+94ms ║║Executed [Return UV light].on (11ms)
+103ms ║║Pump On
+104ms ║║Executed virtual command [Return pump, Return UV light].log (2ms)
+108ms ║║Cancelling statement #18’s schedules…
+116ms ║║Calculating (string) https://script.google.com/macros/s/{ID removed}/exec?Return=on&Wait=4.75&Pump Status= + (string) ONLINE >> (string) https://script.google.com/macros/s/{ID removed}/exec?Return=on&Wait=4.75&Pump Status=ONLINE
+120ms ║║Calculating (string) https://script.google.com/macros/s/{ID removed}/exec?Return=on&Wait=4.75&Pump Status=ONLINE + (string) &UV Light Status= >> (string) https://script.google.com/macros/s/{ID removed}/exec?Return=on&Wait=4.75&Pump Status=ONLINE&UV Light Status=
+124ms ║║Calculating (string) https://script.google.com/macros/s/{ID removed}/exec?Return=on&Wait=4.75&Pump Status=ONLINE&UV Light Status= + (string) ONLINE >> (string) https://script.google.com/macros/s/{ID removed}/exec?Return=on&Wait=4.75&Pump Status=ONLINE&UV Light Status=ONLINE
+130ms ║║Sending external web request to: script.google.com/macros/s/{ID removed}/exec?Return=on&Wait=4.75&Pump%20Status=ONLINE&UV%20Light%20Status=ONLINE
+1659ms ║║Executed virtual command httpRequest (1529ms)
+1662ms ║║Cancelling statement #4’s schedules…
+1665ms ║║Executed virtual command wait (1ms)
+1666ms ║║Requesting a wake up for Sun, May 31 2020 @ 10:39:58 PM MDT (in 15.0s)
+1670ms ║╚Execution stage complete. (1613ms)
+1672ms ║Setting up scheduled job for Sun, May 31 2020 @ 10:39:58 PM MDT (in 14.996s), with 1 more job pending
+1706ms ╚Event processed successfully (1705ms)
5/31/2020, 10:39:26 PM +129ms
+1ms ╔Received event [Heber GH].time = 1590986366766 with a delay of -637ms
+49ms ║RunTime Analysis CS > 17ms > PS > 4ms > PE > 27ms > CE
+51ms ║Runtime (40532 bytes) successfully initialized in 4ms (v0.3.110.20191009) (50ms)
+52ms ║╔Execution stage started
+61ms ║║Cancelling statement #2’s schedules…
+139ms ║║Executed physical command [Return pump].on() (58ms)
+143ms ║║Executed [Return pump].on (75ms)
+160ms ║║Executed physical command [Return UV light].on() (14ms)
+161ms ║║Executed [Return UV light].on (16ms)
+175ms ║║Pump On
+176ms ║║Executed virtual command [Return pump, Return UV light].log (1ms)
+179ms ║║Cancelling statement #18’s schedules…
+192ms ║║Calculating (string) https://script.google.com/macros/s/{ID removed}/exec?Return=on&Wait=4.75&Pump Status= + (string) ONLINE >> (string) https://script.google.com/macros/s/{ID removed}/exec?Return=on&Wait=4.75&Pump Status=ONLINE
+197ms ║║Calculating (string) https://script.google.com/macros/s/{ID removed}/exec?Return=on&Wait=4.75&Pump Status=ONLINE + (string) &UV Light Status= >> (string) https://script.google.com/macros/s/{ID removed}/exec?Return=on&Wait=4.75&Pump Status=ONLINE&UV Light Status=
+201ms ║║Calculating (string) https://script.google.com/macros/s/{ID removed}/exec?Return=on&Wait=4.75&Pump Status=ONLINE&UV Light Status= + (string) ONLINE >> (string) https://script.google.com/macros/s/{ID removed}/exec?Return=on&Wait=4.75&Pump Status=ONLINE&UV Light Status=ONLINE
+214ms ║║Sending external web request to: script.google.com/macros/s/{ID removed}/exec?Return=on&Wait=4.75&Pump%20Status=ONLINE&UV%20Light%20Status=ONLINE
+2137ms ║║Executed virtual command httpRequest (1923ms)
+2140ms ║║Cancelling statement #4’s schedules…
+2145ms ║║Executed virtual command wait (1ms)
+2163ms ║║Requesting a wake up for Sun, May 31 2020 @ 10:39:43 PM MDT (in 15.0s)
+2172ms ║╚Execution stage complete. (2120ms)
+2174ms ║Setting up scheduled job for Sun, May 31 2020 @ 10:39:43 PM MDT (in 14.996s), with 1 more job pending
+2200ms ╚Event processed successfully (2200ms)
5/31/2020, 10:38:29 PM +3ms
+0ms ╔Received event [Heber GH].test = 1590986308999 with a delay of 3ms
+60ms ║RunTime Analysis CS > 20ms > PS > 6ms > PE > 35ms > CE
+63ms ║Runtime (40529 bytes) successfully initialized in 6ms (v0.3.110.20191009) (62ms)
+64ms ║╔Execution stage started
+110ms ║╚Execution stage complete. (45ms)
+112ms ║Setting up scheduled job for Sun, May 31 2020 @ 10:39:26 PM MDT (in 57.652s)
+132ms ╚Event processed successfully (132ms)
5/31/2020, 10:38:26 PM +465ms
+1ms ╔Starting piston… (v0.3.110.20191009)
+204ms ║╔Subscribing to devices…
+267ms ║║Subscribing to Return pump…
+268ms ║║Subscribing to Return UV light…
+269ms ║╚Finished subscribing (69ms)
+332ms ║Setting up scheduled job for Sun, May 31 2020 @ 10:39:26 PM MDT (in 59.97s)
+344ms ╚Piston successfully started (344ms)

[guxdude]

When you comment out the get request do you still keep the wait? It seems the get request is somehow resetting the piston and it is starting again top to bottom. Let me make a suggestion: Put all of your tasks into one ‘with’ rather than breaking them up as you have. Set TCP to never on that with and try again.

[Pantheon]

I don’t know if this will help at all, but I have been having unusual behavior with some of my WAITS lately. Several in the ST community have also complained of the same. Just food for thought…

[kpslc]

When the GET request is commented out, the wait works properly. The wait is necessary to allow a pump to run for the wait time before turning off at the end of the loop.

Interesting other behavior. The second GET request doesn’t affect the operation of the loop. Whether it is active or commented out, the loop timing works properly.

I’ve also tried inserting additional with statements above the wait for the get request. In every test, having the get request above the wait command causes the loop to start over after the wait time expires. No additional statements in the loop are executed.

I will look for the “set TCP to never” and test again. Then if that fails, I’ll have to settle on this being a bug.

Thanks for the suggestion. I’ll reply after the test.

[WCmore]

The problem is once the first get is encountered, the piston continues to run the the first with statement that turns on both devices and logs the data to google.

Excuse me for jumping in…

Are you saying that, the 2 devices turn on after your first GET?!?
(it should turn on before the GET request)

Your current wording is:

• First, turn on 2 devices
• Then Log
• Then Make GET request
• Then WAIT

What order of operation are you looking for?

[guxdude]

I will look for the “set TCP to never” and test again.

When you select the ‘with’, click on the gear icon in the lower right corner and then look for ‘Task Cancellation Policy’ and set that to never. You need everything in a single ‘with’, though. Your piston should look like this:

Every minute
do
   with Return Pump and Return UV Light                 <-- TCP set to never
        turn on
        Log Pump on
        make GET request
        wait 15 seconds
        Log Wait
        turn off
        log pump off
   End with
end every

[WCmore]

@guxdude’s code looks good to me…

(just please remember to increase both times once you are happy with your testing)

[orangebucket]

I note this isn’t the first time we’ve encountered this issue:

Using Wait in a timer

1) Give a description of the problem I created a small piston that writes energy usage data to a thingspeak account. It works great and have been using it for a few weeks now. I decided to make a small update. I added a second data write for energy cost. This piston runs every hour at 30 past the hour. I have seen this same failure behavior in a another piston that runs at the same time every day. I basically tried to do the same thing. I moved to this piston since it runs more often so…

[WCmore]

If memory serves me right, I think this is because the GET request typically inserts a 20 second wakeup… (kind of a catch all in case the response is delayed). With your WAIT being less than 20, I would expect issues.

Increasing the WAIT to 25 seconds or more should give different results.
(and will be closer to real world action)