httpRequest being called twice

poo1ooq · 2022-10-20 13:40:13 UTC

1) Give a description of the problem
I have a piston that posts an HTTP request to a local IP when motion is detected on my doorbell sensor. It has worked flawlessly for several years but suddenly started posting the HTTP request twice.

2) What is the expected behaviour?
Only post the http reqeust once

3) What is happening/not happening?
httpRequest being sent twice

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

5) Attach logs after turning logging level to Full

10/19/2022, 10:08:35 PM +217ms
+1ms ╔Received event [Front Door].motion = inactive with a delay of 78ms
+64ms ║RunTime Analysis CS > 21ms > PS > 4ms > PE > 40ms > CE
+67ms ║Runtime (38428 bytes) successfully initialized in 4ms (v0.3.111.20210130) (65ms)
+68ms ║╔Execution stage started
+76ms ║║Comparison (enum) inactive changes_to (string) active = false (1ms)
+77ms ║║Cancelling condition #4’s schedules…
+78ms ║║Condition #4 evaluated false (6ms)
+80ms ║║Cancelling condition #1’s schedules…
+80ms ║║Condition group #1 evaluated false (state changed) (8ms)
+87ms ║╚Execution stage complete. (20ms)
+93ms ╚Event processed successfully (93ms)

10/19/2022, 10:08:09 PM +916ms
+0ms ╔Received event [My Home].wc_async_reply = httpRequest with a delay of 0ms
+60ms ║RunTime Analysis CS > 16ms > PS > 6ms > PE > 39ms > CE
+62ms ║Runtime (38435 bytes) successfully initialized in 6ms (v0.3.111.20210130) (61ms)
+63ms ║╔Execution stage started
+64ms ║╚Execution stage complete. (1ms)
+66ms ║Setting up scheduled job for Wed, Oct 19 2022 @ 10:08:37 PM CDT (in 27s)
+75ms ╚Event processed successfully (76ms)

10/19/2022, 10:08:07 PM +56ms
+1ms ╔Received event [My Home].wc_async_reply = httpRequest with a delay of 1ms
+187ms ║RunTime Analysis CS > 132ms > PS > 10ms > PE > 44ms > CE
+190ms ║Runtime (38439 bytes) successfully initialized in 10ms (v0.3.111.20210130) (188ms)
+191ms ║╔Execution stage started
+226ms ║║Executed virtual command wait (1ms)
+229ms ║║Requesting a wake up for Wed, Oct 19 2022 @ 10:08:37 PM CDT (in 30.0s)
+255ms ║╚Execution stage complete. (63ms)
+260ms ║Setting up scheduled job for Wed, Oct 19 2022 @ 10:08:37 PM CDT (in 29s)
+270ms ╚Event processed successfully (270ms)

10/19/2022, 10:08:03 PM +981ms
+3ms ╔Received event [Front Door].motion = active with a delay of 87ms
+70ms ║RunTime Analysis CS > 19ms > PS > 5ms > PE > 46ms > CE
+73ms ║Runtime (38433 bytes) successfully initialized in 5ms (v0.3.111.20210130) (68ms)
+75ms ║╔Execution stage started
+83ms ║║Comparison (enum) active changes_to (string) active = true (1ms)
+85ms ║║Cancelling condition #4’s schedules…
+86ms ║║Condition #4 evaluated true (6ms)
+87ms ║║Cancelling condition #1’s schedules…
+88ms ║║Condition group #1 evaluated true (state changed) (9ms)
+91ms ║║Cancelling statement #12’s schedules…
+117ms ║║Sending internal web request to: 10.10.1.3:3000/assistant
+122ms ║║Executed virtual command httpRequest (24ms)
+124ms ║║Requesting a wake up for Wed, Oct 19 2022 @ 10:08:24 PM CDT (in 20.0s)
+132ms ║╚Execution stage complete. (58ms)
+133ms ║Setting up scheduled job for Wed, Oct 19 2022 @ 10:08:24 PM CDT (in 19s)
+161ms ╚Event processed successfully (161ms)

REMOVE BELOW AFTER READING

bthrock · 2022-10-20 16:27:46 UTC

I see only one httpRequest here at 10:08:03 PM +981ms:

Executed virtual command httpRequest (24ms)

However, the log suggests you may be receiving more than one response as you have two lines like this.

Received event [My Home].wc_async_reply = httpRequest with a delay of 1ms

If it were me, I would duplicate the request in Postman or something similar so you could observe the response(s) more clearly.

poo1ooq · 2022-10-20 19:07:35 UTC

Thanks for the reply. I have tested with postman and I get the expected result from the endpoint.

As an additional test, I spun up a docker container with mendhak/http-https-echo. I then copied the call I’m making and pointed it at this new endpoint. It received 2 calls from the “SmartThings” client when I only made 1 call to that endpoint.

{
“path”: “/”,
“headers”: {
“accept”: “/”,
“user-agent”: “Linux UPnP/1.0 SmartThings”,
“host”: “10.10.1.3:9999”,
“content-type”: “application/json”,
“content-length”: “83”
},
“method”: “POST”,
“body”: “{“command”:“broadcast Motion at Front Door”,“user”:“smart-things”,“broadcast”:true}”,
“fresh”: false,
“hostname”: “10.10.1.3”,
“ip”: “::ffff:172.17.0.1”,
“ips”: [],
“protocol”: “http”,
“query”: {},
“subdomains”: [],
“xhr”: false,
“os”: {
“hostname”: “8cbc050045e4”
},
“connection”: {},
“json”: {
“command”: “broadcast Motion at Front Door”,
“user”: “smart-things”,
“broadcast”: true
}
}
::ffff:172.17.0.1 - - [20/Oct/2022:18:57:35 +0000] “POST / HTTP/1.1” 200 676 “-” “Linux UPnP/1.0 SmartThings”

bthrock · 2022-10-20 21:47:33 UTC

The second piston you posted is anonymized, so it’s not clear if you made two requests to one endpoint or separate requests to two different endpoints.

The log for the original piston clearly shows only one request being made, so if the endpoint is receiving two, this is above my pay grade. Sorry.

poo1ooq · 2022-10-20 21:50:25 UTC

Thanks for looking. They are going to separate endpoints:

Paul1964 · 2022-10-21 12:33:04 UTC

Just a thought, if you’re still on smartthings, I thought groovy & hence webcore, were scheduled to stop working on 15th October. I have a few pistons still on there, that still seem to run, but wonder if the change you are seeing is due to some elements of the infrastructure being changed/removed.

orangebucket · 2022-10-22 18:26:33 UTC

I’ve only come across two requests being sent on SmartThings when there are two hubs.