Race condition with concurrent async HTTP requests

🚧 Developers Coding Questions
21

So here's my take on this...

First, your assertion of a race condition is not actually true.. It looks that way but if you look at the logs of the Response Decorators they have unique object ID's. So you are getting two unique callback responses.

Not completely ruling out a bug with the hub, but it's also equally possible that the soundbar is unable to handle the rapid-fire sequence http events that its receiving and is only returning data for the second request which is what your logs show.

Many devices only allow one concurrent request.. This could be true for the soundbar as well.

You mention packet captures.. I think those would be helpful for us to see as would the log dumps that Ryan has asked for.

In the absense of any data we can only speculate.

22

What additional log dumps would help? He asked for log.debug(response), which I posted in a screenshot in the next reply.

Here's the pcap.

23

Pretty sure it's the soundbar...

Been working on a new HubConnect framework tonight that uses asyncHTTP, and I staged a test making two concurrent async http calls to the same http server.. My callback returned exactly the data that it should have...

app:742020-01-17 12:00:31.460 am trace[{"id":578,"name":"HubConnect Hub","label":"Server Hub","displayName":"Server Hub"}]

app:742020-01-17 12:00:31.431 am tracehubitat.scheduling.AsyncResponse@c628d9e

app:742020-01-17 12:00:31.425 am trace[{"id":187,"name":"Generic Glass Break Detector","label":"Glass Break, Back Stairs","displayName":"Glass Break, Back Stairs"},{"id":190,"name":"Generic Glass Break Detector","label":"Glass Break, Front Foyer","displayName":"Glass Break, Front Foyer"},{"id":193,"name":"Generic Glass Break Detector","label":"Glass Break, Test","displayName":"Glass Break, Test"}]

app:742020-01-17 12:00:31.421 am tracehubitat.scheduling.AsyncResponse@6cd6d51b

def callbackF(response, data)
{
	log.trace response
	log.trace response.data
}

	asynchttpGetWithCallback("http://192.168.7.251/device/listJson?capability=capability.presenceSensor", callbackF)
	asynchttpGetWithCallback("http://192.168.7.251/device/listJson?capability=capability.shockSensor", callbackF)

I definately cannot reproduce this using the latest hub code... My money is on the soundbar.. I would suggest as others have said in adding a 100-200ms delay between commands.

24

The contents of the soundbar's responses as seen in the packet capture don't change if I add a delay, but the results at the hub do.

The greater the delay, the more likely it seems that the two response objects will contain different data.

Wouldn't that point more towards the hub than the soundbar?

25

Quite possibly, but not necessarily...

There is another clue in the capture.. Lines 15-18 show the hub requesting to close the socket, however the request to close the session on port 37950 (volume command) is never ACK'd by the speaker. It is definately missing a FIN ACK and ACK on the connction to port 37950. Which again is the volume request.

Since thats showing up on your wireshark captures, I am suspect that the hub is not receiving all packets. Perhaps it's neither the hub nor speaker, but a switch, router, etc in the middle..

But something is certanly up with the packets you captured.

26

@btk I am not able to reproduce this either. I don't have a soundbar to test against, but I used a couple NOAA xml endpoints.

I gotta ask, why are you doing this as an async request, why not use httpGet() instead?

1 Like