Websocket connection has timeout too frequently

[esmart-engineering]

I am evaluating the nRF7002's WiFi capabilities and starting off with the nRF52840DK + nRF7002EK and a project that connects to a socket and sends data. I've primarily used the Websocket Client example (NCS v2.9.1, zephyr/samples/net/sockets/websocket_client) though I mixed in some code from the WiFi station project to ensure I connect to my local WiFi first (NCS v2.9.1, nrf/samples/wifi/sta). The server socket is one I set up with a simple Python script that simply reports any data sent to it.

Functionally my code is working: able to connect to WiFi, connect to socket, and send some data. For sending data, I'm having it repeatedly call websocket_connect(); it will return with an error but my server still gets the data (which is acceptable at this time of evaluation).

However, once my code gets to the connect() call as part of connect_socket(), it will occasionally (roughly 50% of the time) timeout after the default 3sec. I modified it to repeatedly call connect() until it succeeds, and noticed it may take 2-3 tries to connect. But this means that it's taking almost 10sec at most just to simply connect to a socket.

Could you please help look into why this operation is taking so long? We've created custom boards with nRF for years, and recently also with nRF7002. While it was developed through Linux drivers and such rather than with NCS/VS-Code/etc., we determined it can connect to WiFi, connect to socket, and send a little data all comfortably in <10sec. So I'm expecting similar performance.

More info: I am using a Windows 11 machine, VS Code, & nRF Connect Extension. It was already mentioned earlier but we're also using NCS v2.9.1, nRF52840DK, and nRF7002EK.

--------------------------------------------------------

Note that I also tried one of Nordic's official networking samples - the HTTPS client one (NCS v2.9.1, nrf/samples/net/https_client). But I'm not able to proceed that far because it's unable to connect to my local WiFi.

• Made a build config
  • Board target: nrf52840dk/nrf52840
  • Config files: prj.conf, boards/native_sim.conf
    • Had to add native_sim.conf or else I would've had build errors
  • CMake arguments: -DSHIELD="nrf7002ek"
• Tried the build from above, but command line wouldn't respond to any user input, so I couldn't type in the "wifi_cred" command
• Then tried modifying prj.conf to have the static WiFi credentials, but it still wouldn't proceed past "Connecting to the network"

[Håkon Alseth]

Hi,

 

Functionally my code is working: able to connect to WiFi, connect to socket, and send some data. For sending data, I'm having it repeatedly call websocket_connect(); it will return with an error but my server still gets the data (which is acceptable at this time of evaluation).

However, once my code gets to the connect() call as part of connect_socket(), it will occasionally (roughly 50% of the time) timeout after the default 3sec. I modified it to repeatedly call connect() until it succeeds, and noticed it may take 2-3 tries to connect. But this means that it's taking almost 10sec at most just to simply connect to a socket.

Can you share logs and relevant code for this procedure?

Are you closing your sockets after use?

 

If you are already connected via a socket, you should not run connect() multiple times.

 

Note that I also tried one of Nordic's official networking samples - the HTTPS client one (NCS v2.9.1, nrf/samples/net/https_client).

This sample does not have support for the board combination that you're using:

https://docs.nordicsemi.com/bundle/ncs-latest/page/nrf/samples/net/https_client/README.html#requirements

 

Kind regards,

Håkon

[esmart-engineering]

I tested closing my socket after use but it did not help.

Here's the relevant code:

int sock4 = -1;

static int wifi_connect(void) { // same definition as WiFi station example }

static int wifi_shutdown(void)
{   // based off NCS v2.9.1 (nrf/samples/wifi/shutdown)
	int ret;
	struct net_if *iface = net_if_get_default();

	if (!net_if_is_admin_up(iface)) {
		return 0;
	}

	ret = net_if_down(iface);
	if (ret) {
		LOG_ERR("Cannot bring down iface (%d)", ret);
		return ret;
	}

	LOG_INF("Interface down");

	return 0;
}

int connect_to_server(void)
{   // based off Websocket client example
    
	struct sockaddr_in addr4;
	size_t amount;
	int ret = -1;

	LOG_INF("Try to open as client");
	while (ret < 0) {
		if (IS_ENABLED(CONFIG_NET_IPV4)) {
			ret = connect_socket(AF_INET, SERVER_ADDR4, SERVER_PORT,
						&sock4, (struct sockaddr *)&addr4,
						sizeof(addr4));
		}
		if (sock4 < 0 || ret < 0) {
			LOG_ERR("Cannot create HTTP connection.");
			k_sleep(K_SECONDS(1));
		}
	}
}

int send_data_to_server(void)
{   // based off Websocket client example

	/* Just an example how to set extra headers */
	const char *extra_headers[] = {
		"Origin: http://foobar\r\n",
		NULL
	};
	int websock4 = -1;
	int32_t timeout = 150;	// units [ms]

	if (sock4 >= 0 && IS_ENABLED(CONFIG_NET_IPV4)) {
		struct websocket_request req;

		memset(&req, 0, sizeof(req));

		req.host = SERVER_ADDR4;
		req.url = "/";
		req.optional_headers = extra_headers;
		req.cb = connect_cb;
		req.tmp_buf = temp_recv_buf_ipv4;
		req.tmp_buf_len = sizeof(temp_recv_buf_ipv4);

		websock4 = websocket_connect(sock4, &req, timeout, "IPv4");
		if (websock4 < 0) {
			LOG_ERR("Cannot connect to %s:%d (err %d)",
				SERVER_ADDR4, SERVER_PORT,
				websock4);
			// close(sock4);
		}
	}
	if (websock4 < 0) {
		LOG_ERR("No IPv4 connectivity");
		return -2;
	}
	LOG_INF("Websocket IPv4 %d", websock4);
}

int start_app(void)
{       // main() calls this; my main() has same definition as main() from WiFi station example
	LOG_INF("Static IP address (overridable): %s/%s -> %s",
		CONFIG_NET_CONFIG_MY_IPV4_ADDR,
		CONFIG_NET_CONFIG_MY_IPV4_NETMASK,
		CONFIG_NET_CONFIG_MY_IPV4_GW);
		
	while (1) {
	    wifi_connect();

		while (!context.connect_result) {
			cmd_wifi_status();
			k_sleep(K_MSEC(STATUS_POLLING_MS));
		}

		if (context.connected) {
			cmd_wifi_status();

			connect_to_server();
			
			// Send data multiple times
			for (uint8_t i = 0; i < 10; i ++) {
			    send_data_to_server();
			}
			
			// Close socket
			    // NOTE - didn't try with websock4, since I see "No IPv4 connectivity" log output
			if (sock4 >= 0) {
			    close(sock4);
			}

			wifi_shutdown();
			k_sleep(K_SECONDS(1));

			sys_poweroff();
		}
	}
}

Here's the log I get:

Fullscreen websocket_log.txt Download

[00:00:00.507,476] <inf> wifi_nrf_bus: SPIM spi@4002f000: freq = 8 MHz
[00:00:00.507,507] <inf> wifi_nrf_bus: SPIM spi@4002f000: latency = 0
[00:00:00.642,028] <inf> wifi_nrf: Management buffer offload enabled

*** Booting nRF Connect SDK v2.9.1-60d0d6c8d42d ***
*** Using Zephyr OS v3.7.99-ca954a6216c9 ***
[00:00:00.773,223] <inf> net_config: Initializing network
[00:00:00.773,223] <inf> net_config: Waiting interface 1 (0x200018c8) to be up...
[00:00:00.773,406] <inf> net_config: IPv4 address: 192.168.1.99
[00:00:00.773,468] <inf> net_config: Running dhcpv4 client...
[00:00:00.774,505] <inf> sta: Starting nrf52840dk with CPU frequency: 64 MHz
[00:00:00.777,252] <inf> wifi_supplicant: wpa_supplicant initialized
....[00:00:01.774,780] <inf> sta: Static IP address (overridable): 192.168.1.99/255.255.255.0 -> 192.168.1.1
[00:00:03.476,074] <inf> wifi_mgmt_ext: Connection requested
[00:00:03.476,104] <inf> sta: Connection requested
[00:00:03.476,165] <inf> sta: ==================
[00:00:03.476,196] <inf> sta: State: SCANNING
[00:00:03.776,336] <inf> sta: ==================
[00:00:03.776,367] <inf> sta: State: SCANNING
[00:00:04.076,507] <inf> sta: ==================
[00:00:04.076,538] <inf> sta: State: SCANNING
[00:00:04.376,678] <inf> sta: ==================
[00:00:04.376,708] <inf> sta: State: SCANNING
[00:00:04.676,849] <inf> sta: ==================
[00:00:04.676,879] <inf> sta: State: SCANNING
[00:00:04.977,020] <inf> sta: ==================
[00:00:04.977,050] <inf> sta: State: SCANNING
[00:00:05.277,191] <inf> sta: ==================
[00:00:05.277,221] <inf> sta: State: SCANNING
[00:00:05.577,362] <inf> sta: ==================
[00:00:05.577,392] <inf> sta: State: SCANNING
[00:00:05.877,532] <inf> sta: ==================
[00:00:05.877,563] <inf> sta: State: SCANNING
[00:00:06.177,703] <inf> sta: ==================
[00:00:06.177,734] <inf> sta: State: SCANNING
[00:00:06.477,874] <inf> sta: ==================
[00:00:06.477,905] <inf> sta: State: SCANNING
[00:00:06.778,045] <inf> sta: ==================
[00:00:06.778,076] <inf> sta: State: SCANNING
[00:00:07.078,216] <inf> sta: ==================
[00:00:07.078,247] <inf> sta: State: SCANNING
[00:00:07.378,967] <inf> sta: ==================
[00:00:07.378,997] <inf> sta: State: AUTHENTICATING
[00:00:07.679,168] <inf> sta: ==================
[00:00:07.679,199] <inf> sta: State: AUTHENTICATING
[00:00:07.829,711] <inf> sta: Connected
[00:00:07.994,964] <inf> sta: ==================
[00:00:07.994,995] <inf> sta: State: COMPLETED
[00:00:07.995,025] <inf> sta: Interface Mode: STATION
[00:00:07.995,056] <inf> sta: Link Mode: WIFI 4 (802.11n/HT)
[00:00:07.995,086] <inf> sta: SSID: ************
[00:00:07.995,117] <inf> sta: BSSID: ************
[00:00:07.995,147] <inf> sta: Band: 2.4GHz
[00:00:07.995,147] <inf> sta: Channel: 1
[00:00:07.995,178] <inf> sta: Security: WPA2-PSK
[00:00:07.995,208] <inf> sta: MFP: Optional
[00:00:07.995,208] <inf> sta: RSSI: -37
[00:00:07.995,208] <inf> sta: Try to open as client
[00:00:09.321,838] <wrn> net_tcp: net_pkt alloc failure
[00:00:09.626,037] <wrn> net_tcp: net_pkt alloc failure
[00:00:09.930,236] <wrn> net_tcp: net_pkt alloc failure
[00:00:10.951,232] <err> sta: Cannot connect to IPv4 remote (-116)
[00:00:10.951,232] <err> sta: Cannot create HTTP connection.
[00:00:12.052,185] <wrn> net_tcp: net_pkt alloc failure
[00:00:15.052,337] <err> sta: Cannot connect to IPv4 remote (-116)
[00:00:15.052,337] <err> sta: Cannot create HTTP connection.
[00:00:16.278,167] <err> sta: Cannot connect to 192.168.101.98:3001 (err -113)
[00:00:16.278,198] <err> sta: No IPv4 connectivity

Again, for context:

• I call connect() multiple times because there's a timeout in trying to connect; it's confirmed on my server too that no connection is established.
• I see the attempt to connect to socket will timeout if I see "Cannot connect to IPv4 remote (-116)"
• The data arrives on the server if I see " Cannot connect to 192.168.101.98:3001 (err -113)". The message is misleading but my server does receive data.

[esmart-engineering]

Socket is created and a connection is established in connect_to_server().

I will try those KConfig flags when I get in the office next. I previously increased CONFIG_NET_PKT_TX_COUNT from 8 to 16, and this removed those "alloc failure" messages. But the problem still persists.

[Håkon Alseth]

Hi,

 

You're connecting to a server on 192.168.101.x, have you enabled DHCPv4 on the nRF side?

If not, it will default to this IP and mask:

....[00:00:01.774,780] <inf> sta: Static IP address (overridable): 192.168.1.99/255.255.255.0 -> 192.168.1.1

 

Kind regards,

Håkon

[esmart-engineering]

I already have CONFIG_NET_DHCPV4=y. In addition, I had these which probably explain the IP's/masks in the log:

• CONFIG_NET_CONFIG_MY_IPV4_ADDR="192.168.1.99"
• CONFIG_NET_CONFIG_MY_IPV4_NETMASK="255.255.255.0"
• CONFIG_NET_CONFIG_MY_IPV4_GW="192.168.1.1"

[Håkon Alseth]

Hi,

 

Can you confirm that you're receiving an IP within 192.168.101.x range? Or with a netmask of 255.255.0.0 if in the 192.168.x.x range?

Could you please share the full log, and do not take out any of the lines? Feel free to redact the SSID for instance.

 

Kind regards,

Håkon

[esmart-engineering]

Server reports it connected to nRF with an IP 192.168.101.x

Log only had the following removed. Apologies. Initially it was to avoid confusion on when the nRF connected to the socket, but looking at it now it could be relevant:

...

[00:00:09.321,838] <wrn> net_tcp: net_pkt alloc failure
[00:00:09.626,037] <wrn> net_tcp: net_pkt alloc failure
[00:00:09.930,236] <wrn> net_tcp: net_pkt alloc failure
[00:00:10.864,440] <inf> net_dhcpv4: Received: 192.168.101.143
[00:00:10.864,654] <inf> net_config: IPv4 address: 192.168.101.143
[00:00:10.864,685] <inf> net_config: Lease time: 86400 seconds
[00:00:10.864,715] <inf> net_config: Subnet: 255.255.255.0
[00:00:10.864,776] <inf> net_config: Router: 192.168.101.1
[00:00:10.864,898] <inf> sta: DHCP IP address: 192.168.101.143
[00:00:10.951,232] <err> sta: Cannot connect to IPv4 remote (-116)
[00:00:10.951,232] <err> sta: Cannot create HTTP connection.
[00:00:12.052,185] <wrn> net_tcp: net_pkt alloc failure
[00:00:15.052,337] <err> sta: Cannot connect to IPv4 remote (-116)
[00:00:15.052,337] <err> sta: Cannot create HTTP connection.
...

Regardless, logs indicate 3sec in this particular case between attempting to connect to socket, and receiving the 192.168.101.x IP address. This seems too long.

[Håkon Alseth]

Hi,

 

You still have packet allocation issues, based on your latest log.

[00:00:09.321,838] <wrn> net_tcp: net_pkt alloc failure
[00:00:09.626,037] <wrn> net_tcp: net_pkt alloc failure
[00:00:09.930,236] <wrn> net_tcp: net_pkt alloc failure

 

What NET_PKT configuration did you end up using?

 

Kind regards,

Håkon

[esmart-engineering]

As I already mentioned, the issue was resolved with CONFIG_NET_PKT_TX_COUNT. My log is from before making the change, but the log does not differ much with or without the change. And again it does not resolve my primary issue.

I also tried CONFIG_NET_BUF_DATA_SIZE (to 256, 512, and 4096) and none of these fixed the packet allocation issues like CONFIG_NET_PKT_TX_COUNT did.

If by "NET_PKT configuration", you mean KConfig flags related to "NET_PKT", then I have CONFIG_NET_PKT_RX_COUNT=8 and CONFIG_NET_PKT_TX_COUNT=16 explicitly stated in my "prj.conf" file. The following is what I see in my build output ".config" file:

CONFIG_NET_PKT_RX_COUNT=8
CONFIG_NET_PKT_TX_COUNT=16
...
# CONFIG_NET_PKT_TXTIME is not set
# CONFIG_NET_PKT_TIMESTAMP is not set
...
# CONFIG_NET_CONTEXT_NET_PKT_POOL is not set
...
CONFIG_NET_PKT_BUF_RX_DATA_POOL_SIZE=4096
CONFIG_NET_PKT_BUF_TX_DATA_POOL_SIZE=4096
CONFIG_NET_PKT_BUF_USER_DATA_SIZE=4
...
# CONFIG_NET_PKT_RXTIME_STATS is not set
# CONFIG_NET_PKT_TXTIME_STATS is not set
...
# CONFIG_NET_PKT_LOG_LEVEL_OFF is not set
# CONFIG_NET_PKT_LOG_LEVEL_ERR is not set
# CONFIG_NET_PKT_LOG_LEVEL_WRN is not set
# CONFIG_NET_PKT_LOG_LEVEL_INF is not set
# CONFIG_NET_PKT_LOG_LEVEL_DBG is not set
CONFIG_NET_PKT_LOG_LEVEL_DEFAULT=y
CONFIG_NET_PKT_LOG_LEVEL=3
# CONFIG_NET_DEBUG_NET_PKT_ALLOC is not set
CONFIG_NET_DEBUG_NET_PKT_EXTERNALS=0
# CONFIG_NET_DEBUG_NET_PKT_NON_FRAGILE_ACCESS is not set
...
# CONFIG_NET_PKT_FILTER is not set

-------

EDIT #1 - Here's another log, with complete output and with the CONFIG_NET_PKT_TX_COUNT=16 fix.

Fullscreen websocket_log2.txt Download

[00:00:00.493,316] <inf> wifi_nrf_bus: SPIM spi@4002f000: freq = 8 MHz
[00:00:00.493,347] <inf> wifi_nrf_bus: SPIM spi@4002f000: latency = 0
[00:00:00.628,295] <inf> wifi_nrf: Management buffer offload enabled

*** Booting nRF Connect SDK v2.9.1-60d0d6c8d42d ***
*** Using Zephyr OS v3.7.99-ca954a6216c9 ***
[00:00:00.758,972] <inf> net_config: Initializing network
[00:00:00.759,002] <inf> net_config: Waiting interface 1 (0x200018c8) to be up...
[00:00:00.759,185] <inf> net_config: IPv4 address: 192.168.1.99
[00:00:00.759,246] <inf> net_config: Running dhcpv4 client...
[00:00:00.760,192] <inf> sta: Starting nrf52840dk with CPU frequency: 64 MHz
[00:00:00.762,237] <inf> wifi_supplicant: wpa_supplicant initialized
[00:00:01.760,375] <inf> sta: Static IP address (overridable): 192.168.1.99/255.255.255.0 -> 192.168.1.1
[00:00:03.447,082] <inf> wifi_mgmt_ext: Connection requested
[00:00:03.447,998] <inf> sta: Connection requested
[00:00:03.448,028] <inf> sta: ==================
[00:00:03.448,059] <inf> sta: State: SCANNING
[00:00:03.748,229] <inf> sta: ==================
[00:00:03.748,260] <inf> sta: State: SCANNING
[00:00:04.048,400] <inf> sta: ==================
[00:00:04.048,431] <inf> sta: State: SCANNING
[00:00:04.348,571] <inf> sta: ==================
[00:00:04.348,602] <inf> sta: State: SCANNING
[00:00:04.648,742] <inf> sta: ==================
[00:00:04.648,773] <inf> sta: State: SCANNING
[00:00:04.948,913] <inf> sta: ==================
[00:00:04.948,944] <inf> sta: State: SCANNING
[00:00:05.249,084] <inf> sta: ==================
[00:00:05.249,114] <inf> sta: State: SCANNING
[00:00:05.549,255] <inf> sta: ==================
[00:00:05.549,285] <inf> sta: State: SCANNING
[00:00:05.849,426] <inf> sta: ==================
[00:00:05.849,456] <inf> sta: State: SCANNING
[00:00:06.149,597] <inf> sta: ==================
[00:00:06.149,627] <inf> sta: State: SCANNING
[00:00:06.449,768] <inf> sta: ==================
[00:00:06.449,798] <inf> sta: State: SCANNING
[00:00:06.749,938] <inf> sta: ==================
[00:00:06.749,969] <inf> sta: State: SCANNING
[00:00:07.050,109] <inf> sta: ==================
[00:00:07.050,140] <inf> sta: State: SCANNING
[00:00:07.350,311] <inf> sta: ==================
[00:00:07.350,341] <inf> sta: State: AUTHENTICATING
[00:00:07.650,482] <inf> sta: ==================
[00:00:07.650,512] <inf> sta: State: AUTHENTICATING
[00:00:07.826,599] <inf> sta: Connected
[00:00:07.959,411] <inf> sta: ==================
[00:00:07.959,442] <inf> sta: State: COMPLETED
[00:00:07.959,472] <inf> sta: Interface Mode: STATION
[00:00:07.959,503] <inf> sta: Link Mode: WIFI 4 (802.11n/HT)
[00:00:07.959,533] <inf> sta: SSID: eSmartGuest
[00:00:07.959,594] <inf> sta: BSSID: ***********
[00:00:07.959,594] <inf> sta: Band: 2.4GHz
[00:00:07.959,625] <inf> sta: Channel: 1
[00:00:07.959,655] <inf> sta: Security: WPA2-PSK
[00:00:07.959,655] <inf> sta: MFP: Optional
[00:00:07.959,686] <inf> sta: RSSI: -45
[00:00:07.959,686] <inf> sta: Try to open as client
[00:00:08.768,493] <inf> net_dhcpv4: Received: 192.168.101.143
[00:00:08.768,737] <inf> net_config: IPv4 address: 192.168.101.143
[00:00:08.768,737] <inf> net_config: Lease time: 86400 seconds
[00:00:08.768,798] <inf> net_config: Subnet: 255.255.255.0
[00:00:08.768,829] <inf> net_config: Router: 192.168.101.1
[00:00:08.768,981] <inf> sta: DHCP IP address: 192.168.101.143
[00:00:10.592,864] <err> sta: Cannot connect to IPv4 remote (-116)
[00:00:10.592,864] <err> sta: Cannot create HTTP connection.
[00:00:14.266,448] <err> sta: Cannot connect to IPv4 remote (-116)
[00:00:14.266,448] <err> sta: Cannot create HTTP connection.
[00:00:17.570,404] <err> sta: Cannot connect to 192.168.101.98:3001 (err -113)
[00:00:17.570,434] <err> sta: No IPv4 connectivity
[00:00:17.593,536] <inf> wifi_suppli�

[esmart-engineering]

It has been a week since the posting and we've only gotten small suggestions that are not helping whatsoever. Please look into this more in depth and give us a solid concrete solution for us to try.

[Håkon Alseth]

Hi,

 

esmart-engineering said:

My log is from before making the change,

It is important that you disclose such information when posting, to avoid any confusion, such is the scenario right now.

esmart-engineering said:

It has been a week since the posting and we've only gotten small suggestions that are not helping whatsoever. Please look into this more in depth and give us a solid concrete solution for us to try.

I understand that this issue is blocking your evaluation and development, and I aim to help you with this. However, I am going to stress this as much as I can, please do not truncate any information that you share on devzone. Logs show warnings and errors, and leaving them out makes it hard to be able to help you.

 

Can you please share your configurations and settings, so I can recreate this in the STA sample?

You are combining the nRF52840 with the nRF7002, which is a tight fit wrt. RAM, meaning that it needs to be optimized quite heavily.

 

Kind regards,

Håkon

[esmart-engineering]

Could be a RAM issue, but I also tested on an nRF7002DK (using nRF53 which has 2x RAM as nRF52) and saw the same issue.

I've attached the whole project here you can use. Please build based off the build configuration presets I have for the nRF52+nRF70, as well as the nRF7002DK I just tried.

wifi_station_w_sockets.zip