Race condition with concurrent async HTTP requests

🚧 Developers Coding Questions
1

I'm working on a driver for a Samsung sound bar and I'm trying to use asynchronous HTTP GET calls to pull data from the device. My refresh() method fires off calls to retrieve the current volume level and current input back-to-back:

def refresh() {
    sendCommand("getInput")
    sendCommand("getVolume")
}

The method that translates these calls into the async requests is as follows:

private sendCommand(type, value = null) {
    if (type == "setInput") {
        command = "UIC?cmd=%3Cname%3ESetFunc%3C/name%3E%3Cp%20type=%22str%22%20name=%22function%22%20val=%22${value}%22/%3E"
    } else if (type == "setVolume") {
        command = "UIC?cmd=%3Cname%3ESetVolume%3C/name%3E%3Cp%20type=%22dec%22%20name=%22volume%22%20val=%22${value}%22/%3E"
    } else if (type == "getVolume") {
        command = "UIC?cmd=%3Cname%3EGetVolume%3C/name%3E"
    } else if (type == "getInput") {
        command = "UIC?cmd=%3Cname%3EGetFunc%3C/name%3E"
    }

    def params = [
        uri: "http://${ipaddr}:56001/${command}",
    ]

    log.debug("${type} - sendCommand: ${params['uri']}")

    if (type == "getVolume") {
        asynchttpGet('processGetVolumeResponse', params, [requestType: type])
    } else if (type == "getInput") {
        asynchttpGet('processGetInputResponse', params, [requestType: type])
    } else {
        asynchttpGet('processCommandResponse', params, [requestType: type])
    }
}

And finally, the callback methods:

private processGetVolumeResponse(response, data) {
    def xml = response.getXml()
    log.debug(data['requestType'] + " - XML - " + xml)
    soundbarVolume = xml.response.volume
    hubitatVolume = device.currentValue("currentVolume")

    log.debug(data['requestType'] + " - " + "Bar: ${soundbarVolume}")
    log.debug(data['requestType'] + " - " + "Hub: ${hubitatVolume}")
    if (soundbarVolume != hubitatVolume) {
        log.debug(data['requestType'] + " - MISMATCH!")
    }
}


private processGetInputResponse(response, data) {
    def xml = response.getXml()
    log.debug(data['requestType'] + " - XML - " + xml)
    soundbarInput = xml.response.input
    hubitatInput = device.currentValue("currentInput")

    log.debug(data['requestType'] + " - " + "Bar: ${soundbarInput}")
    log.debug(data['requestType'] + " - " + "Hub: ${hubitatInput}")
    if (soundbarInput != hubitatInput) {
        log.debug(data['requestType'] + " - MISMATCH!")
    }
}

When the refresh() method is called, each time both callbacks seem to get the same XML data passed to them. Sometimes it's the volume data, other times it's the input data. Here are two runs of refresh() about 13 seconds apart.

16%20PM
Screen Shot 2020-01-16 at 5.02.16 PM.png1020×182 52.6 KB

24%20PM
Screen Shot 2020-01-16 at 5.02.24 PM.png1014×206 55.9 KB

The lines with "- XML -" in them show that for each call of refresh(), both callbacks are working with the same data. In the first screenshot they both get a copy of the input data. In the second, they're both given the volume data.

Is this a scoping issue on my part? Is there something else I need to be doing to separate these calls better?

Any insight would be much appreciated.

2

Have you confirmed that sending the HTTP GET to the device will actually result in what you expect? Navigate to the URL with your browser...what gets displayed? I would suspect that you're getting back more data than you originally asked for from the device.

3

Yes. For the volume command I get:

<?xml version="1.0" encoding="UTF-8"?><UIC><method>VolumeLevel</method><version>1.0</version><speakerip>10.13.13.49</speakerip><user_identifier></user_identifier><response result="ok"><volume>6</volume></response></UIC>

The input command returns:

<?xml version="1.0" encoding="UTF-8"?><UIC><method>CurrentFunc</method><version>1.0</version><speakerip>10.13.13.49</speakerip><user_identifier></user_identifier><response result="ok"><function>hdmi1</function><submode></submode><connection>on</connection></response></UIC>

4

I think you're going to have to use Synchronous calls here. Since you say it's not consistent, i wonder if it is not always replying in the order they were received. I've never tried to send 2 asynchronous requests to the same endpoint in the same method.

Alternatively, you could use one callback method for both and distinguish between the two by the content. That might be easier.

5

Already tried that. The problem is that both calls to response.getXml() return the same data. If the two asynchttpGet calls are being made with two different callback functions, I would have thought that the hub would be able to keep the data separate.

6

That I don't understand. Because you just showed that they don't. Have you tried logging what you are getting back before trying to parse it to confirm?

How can you tell which is parsing which from the logs? There's no way to identify which method is parsing the data.

Like i said, I don't know that you can send multiple requests to the same endpoint at the same time.

This would definitely work. You're just not parsing it correctly. If only one callback method is used, it wouldn't matter what the content is.

7

Yes. The lines that start with "getInput - XML" and "getVolume - XML" are just printing the raw output from the AsyncResponse object.

Each line that is prefixed with getVolume comes from the volume callback. Likewise, each line that starts with getInput is from the input callback method.

I'll refactor it later tonight back to a single method and update, but when I was doing it this way it had the same problem. Both runs of that single method saw the same data in response.getXml().

8

No.,...you are setting that by by Request type that is passed back to the method from the async call. Hard code that into the callback method if you really want to know.

9

Ok.

57%20PM
57%20PM2040×384 121 KB

EDIT: Ooops, missed a line. Here it is with them all hardcoded:

55%20PM
55%20PM2070×432 137 KB

10

Okay...so, where are you seeing both method getting both pieces of data? I only see input lines for input and volume lines for volume. I don't see a volume value on an input line.

And I recommended logging out the RAW xml before you parsed it. That way you could compare unequivocally, what the method is receiving. Without having anything else influence it.

11

They aren't. Each method only gets ONE piece of data. The problem is that on each run, they both get the SAME piece of data.

Look at the first screenshot in my immediately previous post. The two - XML - log lines show that both methods received the volume response. In the second screenshot, the two - XML - lines show both methods being given the input response.

How? I need the response object before I can access the XML, and my first call on that object is to the built-in .getXml() function. The call right after that is to spit the output into log.debug(). I'm not doing anything to it. That's what I'm being handed by the platform.

private processGetVolumeResponse(response, data) {
    def xml = response.getXml()
    log.debug("processGetVolumeResponse - XML - " + xml)
    ...
12

look at your last screenshot. Where do you see volume data on an input line? I'm not seeing it.

13

log.debug response

14

I don't. That's in the first screenshot. The second screenshot shows input data on a volume line.

Not that useful, but here you go. In this run of refresh() both callbacks got the volume data.

15%20PM
15%20PM2038×454 158 KB

15

Not sure I can distill this much further. The code is pretty simple now:

A packet capture confirms that the hub is sending two different requests (one for volume, one for input) and that the soundbar is replying with the correct response to each. But still, when I go to access the response object, I get the same value in both callbacks:

40%20PM
Screen Shot 2020-01-16 at 8.39.40 PM.png2004×256 89.4 KB

@chuck.schwer - Any of this make any sense to you?

16

Perhaps the soundbar can't handle two GET's so quickly. Something like a volume up-down button wouldn't send two messages in 3ms apart and a change source command could take a lot longer.

17

A packet capture shows the correct responses to each request coming back from the soundbar.

18

You still didn't put the log in for the raw response. Is there a reason you won't? The code you linked to uses the sent data in the log. I believe that is incorrect. How do you know what method the speaker will return first? You should be parsing the content returned based on the content, not by what you expect to receive first and what you except to receive second. But you don't seem to want to make any adjustments to what you are doing. So, I won't bother repeating myself again. Best of luck.

19

Yes. I don't know how to show you what you're asking for. Earlier you asked me to log.debug(response). The output of that command was in the next screenshot on the lines containing "- Response - ":

I don't. That's why I previously separated them into two separate callback functions. But that doesn't change anything.

I'd love to be able to do that, but when each run only gets one of the two sets of content, that's a problem.

20

It's also possible there is only one response buffer. Put a delay between your sends to see what happens. Maybe 100 ms for a start.

1 Like