Arduino WiFi Rev 2 processes GET requests twice

I'm using the WiFi Rev 2 and have a program on a computer that sends it HTTP GET requests at about twice per second. I'm experiencing the following issue: each request appears to be processed twice. I attempt to prove it with the following image:

In that image, the first command (time: 637650988386069194) is processed at 171581. But, further down, it is processed again at 216215. I know that it is the same request because the tick time (637650988386069194), which comes from the sender, is the same on both. Here is the code:

void loop() {

AnalogWriteFrequency(8); // 1 (default) doesn't work, 4 almost works, 8/16/32/64 all work

// log encoder position values
readEncoders(false);

// listen for incoming clients
WiFiClient client = server.available();
String header;
if (client) {
    Serial.println(""); Serial.print("new client: "); Serial.println(millis()); Serial.println("==========");
    // an HTTP request ends with a blank line
    boolean currentLineIsBlank = true;
    while (client.connected()) {
        if (client.available()) {
            char c = client.read();
            Serial.write(c);
            header += c;
            // if you've gotten to the end of the line (received a newline
            // character) and the line is blank, the HTTP request has ended,
            // so you can send a reply
            if (c == '\n' && currentLineIsBlank) { //Serial.print("header: "); Serial.println(header);
                parseQueryStringAndPrintOutput(client, header);
                break;
            }
            if (c == '\n') {
                // you're starting a new line
                currentLineIsBlank = true;
                //Serial.write("currentLineIsBlank = true");
            }
            else if (c != '\r') {
                // you've gotten a character on the current line
                currentLineIsBlank = false;
                //Serial.write("currentLineIsBlank = false");
            }
        }
    }

    // give the web browser time to receive the data
    //delay(1);

    // Clear the header variable
    header = "";

    // close the connection:
    client.stop();
    Serial.println("Client disconnected.");

}

}

Each GET request header (the "header" variable in the code above) appears like this:

GET /?time=637650988386069194&username=&password=&motorleft=49&motorright=49 HTTP/1.1
Host: 192.168.1.81
Connection: Keep-Alive

Any idea why it would process each request twice?

(there is the other issue you may notice that the requests are out of order, but I think that is due to network latency and I haven't found a solution for that yet)

The picture you posted does not match with the prints in your code…

That's right, I eliminated some of the useless print-outs.

This code, Serial.print("new client: "); Serial.println(millis());, shows the time at which the request is processed (line 12 of the code above).

The line such as (time=637650988386069194&username=&password=&motorleft=49&motorright=49) is just a substring of the GET request to show the querystring with the time value of the sender (accomplished in the "parseQueryStringAndPrintOutput" function on line 24 of the code above).

It would be food to see the full request and when disconnect is called(client.stop(); )

Of course it would help to validate the sender too… what happen if you only send one request

client.stop(); is the fourth line from the bottom of the code above. Trying a single request is a good idea. Here is the output (since it is a short test, I provide all output):

new client: 581117

GET /?time=637651038644977897&username=&password=&motorleft=49&motorright=49 HTTP/1.1
Host: 192.168.1.81
Connection: Keep-Alive

querystring: time=637651038644977897&username=&password=&motorleft=49&motorright=49
Client disconnected.

new client: 586147

GET /?time=637651038644977897&username=&password=&motorleft=49&motorright=49 HTTP/1.1
Host: 192.168.1.81
Connection: Keep-Alive

querystring: time=637651038644977897&username=&password=&motorleft=49&motorright=49
Client disconnected.

Same result: the sender sent one request at 637651038644977897, and it was processed on the card at 581117 & 586147.

I also tried the following:

        if (c == '\n' && currentLineIsBlank) { //Serial.print("header: "); Serial.println(header);
            parseQueryStringAndPrintOutput(client, header);
            client.stop();
            break;
        }

Putting an additional client.stop() there didn't solve the double-processing.

Maybe it is because a response, of some particular content-type, must be sent back? (just guessing here)

how did you send the request?
can you print the full request as received (header and body)?

do you return anything back to the client? (like a 200 OK)

I investigated the response and interesting results. To explain, I will display here the .NET code (sending & receiving).

SENDING CODE:

Dim sentOnce As Boolean
Private Sub MicroControllerHttpWebRequest()

    'If sentOnce = True Then Exit Sub
    sentOnce = True

    Dim CommandString As String
    Dim wc As New WebClient
    AddHandler wc.DownloadStringCompleted, AddressOf MicroControllerHttpWebRequestCompleted
    Dim CancelTokenSource As New CancellationTokenSource
    Dim CancelToken As CancellationToken = CancelTokenSource.Token

    Try

        CommandString = "http://" & MicroControllerIPAddress & "/"
        CommandString &= "?time=" & DateTime.Now.Ticks.ToString
        CommandString &= "&username=" & MicroControllerUsername
        CommandString &= "&password=" & MicroControllerPassword
        CommandString &= "&motorleft=" & NewMotorSpeedL.ToString
        CommandString &= "&motorright=" & NewMotorSpeedR.ToString

        wc.DownloadStringAsync(New Uri(CommandString))

    Catch ex As HttpRequestException
        Console.WriteLine("Error (MicroControllerHttpWebRequest): " & ex.Message)

    Catch ex As TaskCanceledException
        Console.WriteLine("Error (MicroControllerHttpWebRequest, TaskCanceledException): " & ex.Message)

    Catch ex As Exception
        Console.WriteLine("Error (MicroControllerHttpWebRequest): " & ex.Message)

    Finally

    End Try

End Sub

And now the receiving code (in function MicroControllerHttpWebRequestCompleted):

Sub MicroControllerHttpWebRequestCompleted(ByVal sender As Object, ByVal e As DownloadStringCompletedEventArgs)

    'Console.Clear()
    Dim ResultString As String = String.Empty

    Try
        ResultString = CStr(e.Result)
        Console.WriteLine("ResultString: " & ResultString)

    Catch ex As Exception
        Console.WriteLine("Error (MicroControllerHttpWebRequestCompleted): " & ex.Message)
        Console.WriteLine("Error (InnerException.Message): " & ex.InnerException.Message)

    End Try

End Sub

When I let this execute once, it still processed the request twice, exactly as in the examples above. But, interestingly, in the .NET program, I now detected the following error in the response back:

Exception thrown: 'System.Reflection.TargetInvocationException' in System.dll
Error (MicroControllerHttpWebRequestCompleted): An exception occurred during the operation, making the result invalid. Check InnerException for exception details.
Error (InnerException.Message): The underlying connection was closed: The connection was closed unexpectedly.

So, just as an idea, I commented out the "client.stop();" line in Arduino and it processed the request only once! And no .NET error on reading response, too. Success, right...almost. So, then, to make a larger test, I commented out the "sentOnce" in .NET and let it process many requests. It processed the first two requests and, then, didn't process any further requests. So, like this:

new client: 209902

GET /?time=637651347799708327&username=&password=&motorleft=49&motorright=49 HTTP/1.1
Host: 192.168.1.81
Connection: Keep-Alive

querystring: time=637651347799708327&username=&password=&motorleft=49&motorright=49
Client disconnected.

new client: 223690

GET /?time=637651347801720565&username=&password=&motorleft=48&motorright=48 HTTP/1.1
Host: 192.168.1.81
Connection: Keep-Alive

querystring: time=637651347801720565&username=&password=&motorleft=48&motorright=48
Client disconnected.

... and it stopped processing requests after that.

The good thing about this is that it processed each request once (and in the right order) nicely. But, then, it stopped processing requests after that second request. I tried making the "client" variable a global variable (in case there is maximum number of clients limitation), but got the same result: processed the first two requests and stopped. But I am now sure that the "client.stop()" was causing the error in .NET and, then, caused the card to attempt re-processing the request.

I also tried the larger test again with putting the "client.stop()" back in and setting "client.setRetry(false)" in setup, to see if that would prevent it from trying to re-process requests, but that didn't work - the "client.stop()" always causes two processing's of each request. I also tried putting "client.clearWriteError();" where "client.stop()" was to see if maybe some error needs to be cleared, but no effect. Lastly, I also tried setting "delay(1000);" to see if more time was needed in processing multiple requests, but no effect.

I should also mention: in the Arduino code, I don't send any response back to .NET program, as it doesn't need any information returned.

May be it does expect an http status code… would be worth returning 200 (well HTTP/1.1 200 OK )

Thanks for the response suggestion - the double-processing is resolved. The root of the problem appears to have been that card was attempting to communicate back with the sender more than once and either a) the client was closed, or b) the response was incomplete. So, the I implemented the following things and it stopped the double-processing:

  • I'm using the "client.stop();" function - the "client" variable can be global or local.

  • I'm using the "delay();" function - changing the number, in conjunction with changing the timing of the sender, makes varying amounts of latency (more on that later).

  • The response must have certain elements to for the sender to receive it properly, or else the card will attempt to resend it. The bare minimum is as follows:

if (c == '\n' && currentLineIsBlank) {
  client.println("HTTP/1.1 200 OK"); // necessary
  // client.println("Content-Type: text/html"); // optional
  client.println("Connection: close"); // necessary
  client.println(); //blank line after any headers is necessary, even if no text follows
  // client.println("<!DOCTYPE HTML><html>Hello World</html>"); // optional
  break;
}

So, the three lines are necessary in the response: a) "HTTP/1.1 200 OK", b) "Connection: close (or keep-alive)", c) a blank line after those, or any other, headers. And that solved the double-processing, so I'll mark the prior remark regarding the response as the solution.

Should note: adjusting the "delay();" function, and adjusting the timing of the messages being sent from the sender, can be done to adjust the latency of the round-trip processing. But it's quite slow, actually. Some commands can take more than a second to make the full round-trip. I'll post an example below displaying this, but since it's more of a widely-distributed-system problem, I'll either post it as a general programming question in a different thread and I'll also need to investigate a "ramping" feature that my motor controller has and send ON/OFF commands, instead of rapidly changing velocities. Here's an example of the order that should have been processed:

http://192.168.1.81/?username=&password=&motorleft=49&motorright=49
http://192.168.1.81/?username=&password=&motorleft=48&motorright=48
http://192.168.1.81/?username=&password=&motorleft=46&motorright=46
http://192.168.1.81/?username=&password=&motorleft=44&motorright=44
http://192.168.1.81/?username=&password=&motorleft=40&motorright=40
http://192.168.1.81/?username=&password=&motorleft=35&motorright=35
http://192.168.1.81/?username=&password=&motorleft=26&motorright=26
http://192.168.1.81/?username=&password=&motorleft=14&motorright=14
http://192.168.1.81/?username=&password=&motorleft=0&motorright=0
http://192.168.1.81/?username=&password=&motorleft=14&motorright=14
http://192.168.1.81/?username=&password=&motorleft=27&motorright=27
http://192.168.1.81/?username=&password=&motorleft=36&motorright=36
http://192.168.1.81/?username=&password=&motorleft=42&motorright=42
http://192.168.1.81/?username=&password=&motorleft=46&motorright=46
http://192.168.1.81/?username=&password=&motorleft=48&motorright=48
http://192.168.1.81/?username=&password=&motorleft=50&motorright=50
http://192.168.1.81/?username=&password=&motorleft=127&motorright=127
http://192.168.1.81/?username=&password=&motorleft=127&motorright=127

And here's an example of the latency issue (observing the "timestamp" variables really points out the problem) - it shows, from the senders perspective, the sending URL, and the ResultString (response) back:

http://192.168.1.81/?timestamp=637651910424413170&username=&password=&motorleft=49&motorright=49
http://192.168.1.81/?timestamp=637651910429331136&username=&password=&motorleft=48&motorright=48
http://192.168.1.81/?timestamp=637651910431851386&username=&password=&motorleft=46&motorright=46
ResultString: {"command":"getEncoders","E1":0,"E2":0,"M1":49,"M2":49,"TS":637651910424413170}

http://192.168.1.81/?timestamp=637651910434370234&username=&password=&motorleft=44&motorright=44
http://192.168.1.81/?timestamp=637651910436855235&username=&password=&motorleft=40&motorright=40
ResultString: {"command":"getEncoders","E1":0,"E2":0,"M1":46,"M2":46,"TS":637651910431851386}

http://192.168.1.81/?timestamp=637651910439387250&username=&password=&motorleft=35&motorright=35
http://192.168.1.81/?timestamp=637651910441908146&username=&password=&motorleft=26&motorright=26
http://192.168.1.81/?timestamp=637651910444409193&username=&password=&motorleft=14&motorright=14
ResultString: {"command":"getEncoders","E1":0,"E2":0,"M1":48,"M2":48,"TS":637651910429331136}

http://192.168.1.81/?timestamp=637651910446946765&username=&password=&motorleft=0&motorright=0
ResultString: {"command":"getEncoders","E1":0,"E2":0,"M1":40,"M2":40,"TS":637651910436855235}

ResultString: {"command":"getEncoders","E1":0,"E2":0,"M1":44,"M2":44,"TS":637651910434370234}

ResultString: {"command":"getEncoders","E1":0,"E2":0,"M1":35,"M2":35,"TS":637651910439387250}

ResultString: {"command":"getEncoders","E1":0,"E2":0,"M1":14,"M2":14,"TS":637651910444409193}

http://192.168.1.81/?timestamp=637651910469693027&username=&password=&motorleft=14&motorright=14
http://192.168.1.81/?timestamp=637651910472201069&username=&password=&motorleft=27&motorright=27
ResultString: {"command":"getEncoders","E1":0,"E2":0,"M1":26,"M2":26,"TS":637651910441908146}

http://192.168.1.81/?timestamp=637651910474708977&username=&password=&motorleft=36&motorright=36
http://192.168.1.81/?timestamp=637651910477213085&username=&password=&motorleft=42&motorright=42
ResultString: {"command":"getEncoders","E1":0,"E2":0,"M1":14,"M2":14,"TS":637651910469693027}

http://192.168.1.81/?timestamp=637651910479837835&username=&password=&motorleft=46&motorright=46
http://192.168.1.81/?timestamp=637651910482339554&username=&password=&motorleft=48&motorright=48
http://192.168.1.81/?timestamp=637651910484856299&username=&password=&motorleft=50&motorright=50
ResultString: {"command":"getEncoders","E1":0,"E2":0,"M1":27,"M2":27,"TS":637651910472201069}

http://192.168.1.81/?timestamp=637651910487355389&username=&password=&motorleft=127&motorright=127
http://192.168.1.81/?timestamp=637651910489851250&username=&password=&motorleft=127&motorright=127
ResultString: {"command":"getEncoders","E1":0,"E2":0,"M1":42,"M2":42,"TS":637651910477213085}

ResultString: {"command":"getEncoders","E1":0,"E2":0,"M1":0,"M2":0,"TS":637651910446946765}

ResultString: {"command":"getEncoders","E1":0,"E2":0,"M1":48,"M2":48,"TS":637651910482339554}

ResultString: {"command":"getEncoders","E1":0,"E2":0,"M1":127,"M2":127,"TS":637651910487355389}

ResultString: {"command":"getEncoders","E1":0,"E2":0,"M1":127,"M2":127,"TS":637651910489851250}

ResultString: {"command":"getEncoders","E1":0,"E2":0,"M1":36,"M2":36,"TS":637651910474708977}

ResultString: {"command":"getEncoders","E1":0,"E2":0,"M1":46,"M2":46,"TS":637651910479837835}

ResultString: {"command":"getEncoders","E1":0,"E2":0,"M1":50,"M2":50,"TS":637651910484856299}

You can see above that the URL's are sent in the correct order, but the processing takes place a bit random, as the timing is a bit too fast. So, again, I'll consider some other options before posting it as a separate option.

good work to solve this!

1 Like