Every 5th TCP connection fails on Arduino Giga R1 if we don't fully read the HTTP content sent from the server each time

[schnoberts1]

Platform: Giga R1
Arduino Core Mbed 4.1.5
HttpClient: 0.6.1

Here's a sequence of events with a crudely instrumented MbedClient. We connect using ArduinoHttpClient every 1s. Every 5th connection fails with error -3005 from static_cast<TCPSocket *>(sock)->open(getNetwork()); in the MbedClient::connect() call. When it fails it takes 30s to return. This is in version 4.1.5. In version 4.1.1 it would never recover and continue to fail until device reboot. There would be no 30s delay. This issue occurs on any http server I've tried. I can continue to connect to the server in the code with python on my Mac with no problems. If I extend the delay so I connect to the server once every 5s the problem goes away. At 4s it reappears.

22:10:12.229 -> Fetching content length from httpforever.com:80
22:10:12.393 -> Return code from connect0
22:10:13.213 -> took=993ms length: 5124
22:10:15.229 -> Fetching content length from httpforever.com:80
22:10:15.394 -> Return code from connect0
22:10:16.216 -> took=979ms length: 5124
22:10:18.198 -> Fetching content length from httpforever.com:80
22:10:18.365 -> Return code from connect0
22:10:19.225 -> took=1008ms length: 5124
22:10:21.203 -> Fetching content length from httpforever.com:80
22:10:21.366 -> Return code from connect0
22:10:22.222 -> took=1004ms length: 5124
22:10:24.202 -> Fetching content length from httpforever.com:80
22:10:24.202 -> Return code from TCPSocket::open-3005
22:10:54.295 -> took=30099ms length: -1

code

#include <Arduino.h>
#include <WiFi.h>
#include <HttpClient.h>

void setup() {
  Serial.begin(115200);
  delay(1000);
  Serial.println("HI");
  // put your setup code here, to run once:
  auto wifi = WiFiInterface::get_default_instance();
  wifi->set_dhcp(true);
  wifi->set_credentials("ZZZZ", "ZZZZ", nsapi_security_t::NSAPI_SECURITY_WPA2);
  Serial.println(wifi->connect());
}

void loop() {
  // put your main code here, to run repeatedly:
  WiFiClient client;
 
   HttpClient httpClient(client, "httpforever.com", 80);
   Serial.println("Fetching content length from httpforever.com:80");
   auto then = millis();
   httpClient.beginRequest();
   httpClient.get("/");
   httpClient.endRequest();
   auto len = httpClient.contentLength(); // Doesn't read all content
   Serial.print("took="); Serial.print((millis() - then)); Serial.print("ms "); Serial.print("length: "); Serial.println(len);
   delay(5000);
}

[schnoberts1]

... at 4.5s delay it takes 8 calls before it fails, an interesting multiple of 4. Any hints? I tried moving WifiClient globally but that swaps -3005 errors for -3003 errors on the first re-use:

22:25:36.246 -> Fetching content length from httpforever.com:80
22:25:36.448 -> Return code from connect0
22:25:37.243 -> took=1001ms length: 5124
22:25:38.260 -> Fetching content length from httpforever.com:80
22:25:38.260 -> Return code from TCPSocket::open-3003
22:26:09.251 -> took=31000ms length: -1

31s timeout this time.

Since I've included the code this should replicate well.

[schnoberts1]

... I am also guessing this 30s timeout is in HttpClient since there's no delay on the return from the failed connect.

[schnoberts1]

Note: calling client.stop() does not resolve the issue

[stopandchatchfire]

The maximum number of TCP connections is 4.

As defined in the file: "mbed_config.h"

#define MBED_CONF_LWIP_TCP_SOCKET_MAX 4

I don't understand why it's so low. Need to recompile locally to have more connections available.

[schnoberts1]

I never have 4 tcp sockets open but I am confident this limit is at the core of the issue. Some clean up isn’t being executed. Increasing the socket count isn’t going to help though as it just puts the issue off.

[JAndrassy]

@schnoberts1 can you try these changes? https://github.com/arduino/ArduinoCore-mbed/pull/912/files

[schnoberts1]

Of course @JAndrassy. I've applied the patch and the issue still remains.

[pennam]

@schnoberts1 the 30s timeout comes from the Http library, you can get rid of it adding httpClient.setHttpResponseTimeout(1000); to your sketch.

I'm still investigating about the NSAPI_ERROR_NO_SOCKET return value but i agree it is related to the MBED_CONF_LWIP_TCP_SOCKET_MAX define and in the way lwip TCP connections are deleted https://github.com/arduino/mbed-os/blob/e0cad5c4277b3c5ee9cb01a9529df9333612bbeb/connectivity/lwipstack/lwip/src/api/lwip_api_lib.c#L233

It looks that before complete deletion they can be put in a waitstate and closed afterwards

https://github.com/arduino/mbed-os/blob/e0cad5c4277b3c5ee9cb01a9529df9333612bbeb/connectivity/lwipstack/lwip/src/api/lwip_api_msg.c#L913

[JAndrassy]

does the HttpClient send the "Connection: close" header?

[pennam]

@JAndrassy yes HttpClient sends the "Connection: close" header.

I think I've found the rootcause, and it is server side, in fact httpforever.com keeps sending TCP Keep-Alive messages, and thus connections are not closed. Using a different server like example.org connections are closed correctly and the NSAPI_ERROR_NO_SOCKET error is not generated..

[schnoberts1]

Good find! We close the socket though so I would have thought LWIP would have sent FIN and either got a FIN ACK and closed the underlying socket or timed out waiting for one. I wonder, is LWIP not sending FIN? On 1 Oct 2024, at 09:23, Mattia Pennasilico ***@***.***> wrote: @JAndrassy yes HttpClient sends the "Connection: close" header. I think I've found the rootcause, and it is server side, in fact httpforever.com keeps sending TCP Keep-Alive messages, and thus connections are not closed. Using a different server like example.org connections are closed correctly and the NSAPI_ERROR_NO_SOCKET error is not generated.. —Reply to this email directly, view it on GitHub, or unsubscribe.You are receiving this because you were mentioned.Message ID: ***@***.***>

[pennam]

Here is what i get with wireshark, I'm now thinking if the TCP Window Full messages are somehow involved
wireshark.zip

[pennam]

I get the same NSAPI_ERROR_NO_SOCKET using anothe http site sneaindia.com TCP Window Full
messages are also present.
snea.pcapng.zip

[schnoberts1]

Interesting. I can see on the exampleorg PCAP that the Giga sends a GET and then it gets the data and an HTTP 200 response followed immediately by a FIN. The Giga then sends an ACK for data up to sequential 537 and then an ack for data up to 1619 (which includes the FIN that got sent to the Giga). The Giga never sends a FIN in that packet capture. It should do that. I think the server is then in FIN_WAIT2 but since the HTTP server has closed the socket it’ll time it out. In the httpforever it gets interesting. The Giga sends the GET (split across two packets weirdly). Packet 24 has the GET and packet 25 has / HTTP/1.1 Host: httpforever.com The same happens again, the Giga sends User-Agent in one packet then : Arduino/2.2.0 \nConnection: close in the other. At this point it’s the same as the exampleorg capture really. A key difference is that the exampleorg payload is less than the advertised window (2144) so it never needs to write a packet with WindowFull set. The server sends the data with the Connection: close also in the header. Not all the data is in the packet so the next packet is more of the data but the TCP Window Full is set. This is because the advertised window from the Giga is 2144 and it’s sent exactly 2144 bytes across those two packets. It needs an ACK now. The Giga ACKs the two packets. The server sends a 536 byte packet so it can’t be finished, the content length was around 5k. The Giga acks it but now its window is down to 536 bytes. The server fills the window and tags the packet accordingly. The Giga announces a zero window (I don’t know why, it’s ACKed everything - but then I am not a TCP guru). The giga then RST’s the connection. At this point it should be closing the underlying socket since it’s an abort. It does not need to wait for anything from the server. However, it doesn’t abort. The server sends a TCP keep alive after the RST and the Giga responds to it! I don’t think that is right. You are right, it could be the WindowFull but the response from the Giga seems odd at this stage. I do not understand why it continues to process responses after sending a RST.

…

On 1 Oct 2024, at 11:05, Mattia Pennasilico ***@***.***> wrote: I get the same NSAPI_ERROR_NO_SOCKET using anothe http site sneaindia.com TCP Window Full messages are also present. snea.pcapng.zip <https://github.com/user-attachments/files/17203234/snea.pcapng.zip> — Reply to this email directly, view it on GitHub <#937 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ACMQSMWJFQ5RFGX6ID5LXKLZZJXX5AVCNFSM6AAAAABMS5OJFWVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDGOBVGM3DINRUHE>. You are receiving this because you were mentioned.