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.

[Håkon Alseth]

Hi,

 

This is the log that I am seeing:

*** Booting nRF Connect SDK v2.9.2-4ab7b98fc76f ***
*** Using Zephyr OS v3.7.99-aa34a5632971 ***
[00:00:00.688,720] <inf> net_config: Initializing network
[00:00:00.688,751] <inf> net_config: Waiting interface 1 (0x20001290) to be up...
[00:00:00.688,903] <inf> net_config: IPv4 address: 192.168.32.99
[00:00:00.688,964] <inf> net_config: Running dhcpv4 client...
[00:00:00.689,788] <inf> sta: Starting nrf7002dk with CPU frequency: 64 MHz
[00:00:00.691,467] <inf> wifi_supplicant: wpa_supplicant initialized
[00:00:01.689,971] <inf> sta: Static IP address (overridable): 192.168.32.99/255.255.255.0 -> 192.168.32.1
[00:00:03.239,898] <inf> wifi_mgmt_ext: Connection requested
[00:00:03.239,929] <inf> sta: Connection requested
[00:00:03.239,990] <inf> sta: ==================
[00:00:03.240,020] <inf> sta: State: SCANNING
[00:00:03.540,161] <inf> sta: ==================
[00:00:03.540,191] <inf> sta: State: SCANNING
[00:00:03.840,332] <inf> sta: ==================
[00:00:03.840,362] <inf> sta: State: SCANNING
[00:00:04.140,502] <inf> sta: ==================
[00:00:04.140,533] <inf> sta: State: SCANNING
[00:00:04.440,673] <inf> sta: ==================
[00:00:04.440,704] <inf> sta: State: SCANNING
[00:00:04.740,844] <inf> sta: ==================
[00:00:04.740,875] <inf> sta: State: SCANNING
[00:00:05.041,015] <inf> sta: ==================
[00:00:05.041,015] <inf> sta: State: SCANNING
[00:00:05.341,186] <inf> sta: ==================
[00:00:05.341,186] <inf> sta: State: SCANNING
[00:00:05.641,326] <inf> sta: ==================
[00:00:05.641,357] <inf> sta: State: SCANNING
[00:00:05.941,528] <inf> sta: ==================
[00:00:05.941,558] <inf> sta: State: SCANNING
[00:00:06.241,668] <inf> sta: ==================
[00:00:06.241,699] <inf> sta: State: SCANNING
[00:00:06.541,870] <inf> sta: ==================
[00:00:06.541,900] <inf> sta: State: SCANNING
[00:00:06.842,041] <inf> sta: ==================
[00:00:06.842,041] <inf> sta: State: SCANNING
[00:00:07.142,211] <inf> sta: ==================
[00:00:07.142,242] <inf> sta: State: SCANNING
[00:00:07.442,352] <inf> sta: ==================
[00:00:07.442,382] <inf> sta: State: SCANNING
[00:00:07.742,523] <inf> sta: ==================
[00:00:07.742,553] <inf> sta: State: SCANNING
[00:00:08.042,724] <inf> sta: ==================
[00:00:08.042,755] <inf> sta: State: AUTHENTICATING
[00:00:08.342,895] <inf> sta: ==================
[00:00:08.342,926] <inf> sta: State: AUTHENTICATING
[00:00:08.452,941] <inf> sta: Connected
[00:00:12.475,097] <inf> net_dhcpv4: Received: 192.168.32.198
[00:00:12.475,280] <inf> net_config: IPv4 address: 192.168.32.198
[00:00:12.475,280] <inf> net_config: Lease time: 36000 seconds
[00:00:12.475,341] <inf> net_config: Subnet: 255.255.255.0
[00:00:12.475,372] <inf> net_config: Router: 192.168.32.1
[00:00:12.475,463] <inf> sta: DHCP IP address: 192.168.32.198
[00:00:12.657,257] <inf> sta: ==================
[00:00:12.657,287] <inf> sta: State: COMPLETED
[00:00:12.657,318] <inf> sta: Interface Mode: STATION
[00:00:12.657,348] <inf> sta: Link Mode: WIFI 6 (802.11ax/HE)
[00:00:12.657,379] <inf> sta: SSID: OpenWrt
[00:00:12.657,409] <inf> sta: BSSID: FC:34:97:0B:F6:DC
[00:00:12.657,409] <inf> sta: Band: 5GHz
[00:00:12.657,440] <inf> sta: Channel: 44
[00:00:12.657,440] <inf> sta: Security: WPA2-PSK
[00:00:12.657,470] <inf> sta: MFP: Optional
[00:00:12.657,470] <inf> sta: RSSI: -60
[00:00:13.657,562] <inf> sta: Try to open as client
[00:00:13.740,417] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:13.740,417] <err> sta: No IPv4 connectivity
[00:00:13.740,905] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:13.740,905] <err> sta: No IPv4 connectivity
[00:00:13.741,363] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:13.741,363] <err> sta: No IPv4 connectivity
[00:00:13.741,821] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:13.741,851] <err> sta: No IPv4 connectivity
[00:00:13.742,309] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:13.742,309] <err> sta: No IPv4 connectivity
[00:00:13.742,767] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:13.742,797] <err> sta: No IPv4 connectivity
[00:00:13.743,255] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:13.743,255] <err> sta: No IPv4 connectivity
[00:00:13.743,713] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:13.743,713] <err> sta: No IPv4 connectivity
[00:00:13.744,201] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:13.744,201] <err> sta: No IPv4 connectivity
[00:00:13.744,659] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:13.744,659] <err> sta: No IPv4 connectivity
[00:00:13.766,021] <inf> sta: Interface down
[00:00:13.766,143] <inf> wifi_supplicant: Network interface 1 (0x20001290) down

On the server side, I am running a small py script just to setup a server on port 3001:

#! /usr/bin/python
# a simple tcp server
import socket,os
sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
sock.bind(('192.168.32.166', 3001))
sock.listen(5)
while True:
    connection,address = sock.accept()
    buf = connection.recv(1024)
    print(buf)
    connection.send(buf)     
    connection.close()

 

 

Which prints this each time I connect:

b'GET / HTTP/1.1\r\nHost: 192.168.32.166\r\nOrigin: http://foobar\r\nSec-WebSocket-Key: lm0W7zOrdWFToQCN8Kkcmg==\r\nUpgrade: websocket\r\nConnection: Upgrade\r\nSec-WebSocket-Version: 13\r\n\r\n'

  

Running the websocketd as described here:

https://docs.zephyrproject.org/latest/samples/net/sockets/websocket_client/README.html#running-websocket-server-in-linux-host

 

Shows similar issues as before, ie. that the log spits out:

[00:00:13.955,291] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:13.955,291] <err> sta: No IPv4 connectivity
[00:00:14.078,338] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:14.078,338] <err> sta: No IPv4 connectivity
[00:00:14.178,863] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:14.178,894] <err> sta: No IPv4 connectivity
[00:00:14.279,449] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:14.279,449] <err> sta: No IPv4 connectivity
[00:00:14.380,004] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:14.380,035] <err> sta: No IPv4 connectivity
[00:00:14.480,621] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:14.480,651] <err> sta: No IPv4 connectivity
[00:00:14.581,207] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:14.581,237] <err> sta: No IPv4 connectivity
[00:00:14.681,793] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:14.681,793] <err> sta: No IPv4 connectivity
[00:00:14.782,348] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:14.782,379] <err> sta: No IPv4 connectivity
[00:00:14.882,934] <err> sta: Cannot connect to 192.168.32.166:3001 (err -113)
[00:00:14.882,934] <err> sta: No IPv4 connectivity

 

However, if you only run the function send_data_to_server() once, it will show:

*** Booting nRF Connect SDK v2.9.2-4ab7b98fc76f ***
*** Using Zephyr OS v3.7.99-aa34a5632971 ***
[00:00:00.638,793] <inf> net_config: Initializing network
[00:00:00.638,793] <inf> net_config: Waiting interface 1 (0x20000d98) to be up...
[00:00:00.638,977] <inf> net_config: IPv4 address: 192.168.32.99
[00:00:00.639,007] <inf> net_config: Running dhcpv4 client...
[00:00:00.639,953] <inf> sta: Starting nrf7002dk with CPU frequency: 64 MHz
[00:00:00.641,845] <inf> wifi_supplicant: wpa_supplicant initialized
[00:00:01.640,136] <inf> sta: Static IP address (overridable): 192.168.32.99/255.255.255.0 -> 192.168.32.1
[00:00:03.560,089] <inf> wifi_mgmt_ext: Connection requested
[00:00:03.560,119] <inf> sta: Connection requested
[00:00:03.560,180] <inf> sta: ==================
[00:00:03.560,211] <inf> sta: State: SCANNING
[00:00:08.062,774] <inf> sta: ==================
[00:00:08.062,774] <inf> sta: State: SCANNING
[00:00:08.362,945] <inf> sta: ==================
[00:00:08.362,976] <inf> sta: State: AUTHENTICATING
[00:00:08.663,116] <inf> sta: ==================
[00:00:08.663,146] <inf> sta: State: AUTHENTICATING
[00:00:08.730,682] <inf> sta: Connected
[00:00:12.988,555] <inf> sta: ==================
[00:00:12.988,586] <inf> sta: State: COMPLETED
[00:00:12.988,616] <inf> sta: Interface Mode: STATION
[00:00:12.988,647] <inf> sta: Link Mode: WIFI 6 (802.11ax/HE)
[00:00:12.988,647] <inf> sta: SSID: OpenWrt
[00:00:12.988,677] <inf> sta: BSSID: FC:34:97:0B:F6:DC
[00:00:12.988,708] <inf> sta: Band: 5GHz
[00:00:12.988,708] <inf> sta: Channel: 44
[00:00:12.988,739] <inf> sta: Security: WPA2-PSK
[00:00:12.988,769] <inf> sta: MFP: Optional
[00:00:12.988,769] <inf> sta: RSSI: -55
[00:00:13.752,960] <inf> net_dhcpv4: Received: 192.168.32.198
[00:00:13.753,143] <inf> net_config: IPv4 address: 192.168.32.198
[00:00:13.753,173] <inf> net_config: Lease time: 36000 seconds
[00:00:13.753,204] <inf> net_config: Subnet: 255.255.255.0
[00:00:13.753,234] <inf> net_config: Router: 192.168.32.1
[00:00:13.753,356] <inf> sta: DHCP IP address: 192.168.32.198
[00:00:13.988,830] <inf> sta: Try to open as client
[00:00:14.059,570] <err> sta: 12
[00:00:14.069,183] <inf> sta: Websocket 13 for IPv4 connected.
[00:00:14.069,183] <inf> sta: Websocket IPv4 13

 

I added these configurations to maximize the amount of sockets / net contexts:

CONFIG_ZVFS_OPEN_MAX=20
CONFIG_NET_SOCKETS_POLL_MAX=20
CONFIG_NET_CONFIG_NEED_IPV6=n
CONFIG_NET_IPV6=n
CONFIG_NET_MAX_CONTEXTS=20

Could you try the same and see if it runs accordingly?

 

Kind regards,

Håkon

[esmart-engineering]

Apologies for the late response.

The constant "Cannot connect to 192.168.32.166:3001 (err -113)" is not the issue I am talking about. My issue is seeing "Cannot connect to IPv4 remote (-116)" which is coming from connect_to_server(). Please carefully re-examine the exact problem I am talking about. Also pay attention to the other details I've shared; for example, the problem occasionally (roughly 50% of the time) occurs.

Your Python server is set up to receive 1 message, which is not my intention. It should connect to the nRF, receive multiple messages, then require user to Ctrl+C and rerun the server whenever the nRF needs to be run again. I've attached my script and an example of what you should see.

Fullscreen server.py Download

import socket
import datetime
PORT = 3001

ip_addr = '0.0.0.0'

while True:
    with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as s:
        s.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
        s.bind((ip_addr, PORT))
        s.listen()
        print(f"Server listening on {ip_addr}:{PORT}")
        conn, addr = s.accept()
        with conn:
            print(f"{datetime.datetime.now()}: Connected by {addr}")
            while True:
                did_receive_data = False
                while not did_receive_data:
                    data = conn.recv(1024)  # Receive up to 1024 bytes
                    if not data:
                        continue
                    print(f"{datetime.datetime.now()}: Received from client: {data.decode('utf-8')}")
                    response = f"Server received: {data.decode('utf-8')}"
                    conn.sendall(response.encode('utf-8'))
                    did_receive_data = True
        conn.close()
        s.close()

Fullscreen server_log.txt Download

$ python3 forumnrfserver.py
Server listening on 0.0.0.0:3001
2025-09-02 14:39:09.733185: Connected by ('192.168.101.143', 44678)
2025-09-02 14:39:09.839348: Received from client: GET / HTTP/1.1
Host: 192.168.101.98
Origin: http://foobar
Sec-WebSocket-Key: YVsNcLpQVGiMRgm59KgalA==
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Version: 13


2025-09-02 14:39:09.901119: Received from client: GET / HTTP/1.1
Host: 192.168.101.98
Origin: http://foobar
Sec-WebSocket-Key: vRC8G5IrTdSyeUaeW0M4kg==
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Version: 13


2025-09-02 14:39:10.037705: Received from client: GET / HTTP/1.1
Host: 192.168.101.98
Origin: http://foobar
Sec-WebSocket-Key: naFmSNGwbziixWIvyMAsNw==
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Version: 13


2025-09-02 14:39:10.186991: Received from client: GET / HTTP/1.1
Host: 192.168.101.98
Origin: http://foobar
Sec-WebSocket-Key: 75Vs3+u38V5dawGasrhY5A==
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Version: 13


2025-09-02 14:39:10.341248: Received from client: GET / HTTP/1.1
Host: 192.168.101.98
Origin: http://foobar
Sec-WebSocket-Key: ArFh1S9qCOPwpyYI4nWryA==
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Version: 13


2025-09-02 14:39:10.490259: Received from client: GET / HTTP/1.1
Host: 192.168.101.98
Origin: http://foobar
Sec-WebSocket-Key: Po6cfaXMYfPUt2x5P7BnCw==
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Version: 13


2025-09-02 14:39:10.647954: Received from client: GET / HTTP/1.1
Host: 192.168.101.98
Origin: http://foobar
Sec-WebSocket-Key: TbSY5fwvPJZ77+lFFMI7jw==
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Version: 13


2025-09-02 14:39:10.788101: Received from client: GET / HTTP/1.1
Host: 192.168.101.98
Origin: http://foobar
Sec-WebSocket-Key: SjDrtG71Qf8uWQ+H9BfcVA==
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Version: 13


2025-09-02 14:39:10.936990: Received from client: GET / HTTP/1.1
Host: 192.168.101.98
Origin: http://foobar
Sec-WebSocket-Key: PM/H9HezqWeN8kO256YoRg==
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Version: 13


2025-09-02 14:39:11.090528: Received from client: GET / HTTP/1.1
Host: 192.168.101.98
Origin: http://foobar
Sec-WebSocket-Key: UcMtSGmGAuNlk5ohphb43A==
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Version: 13

I went ahead and tried your configurations anyway, but it did not help with my issue.

[Håkon Alseth]

Hi,

 

esmart-engineering said:

The constant "Cannot connect to 192.168.32.166:3001 (err -113)" is not the issue I am talking about

Your logs show both -113 and -116.

esmart-engineering said:

Please carefully re-examine the exact problem I am talking about. Also pay attention to the other details I've shared; for example, the problem occasionally (roughly 50% of the time) occurs.

According to the logs that you posted, you are still running in a for-loop. If you look into what the websocket library does, it will create a new socket for each try. This means that you will exhaust the amount of sockets available if you hammer on.

Håkon Alseth said:

However, if you only run the function send_data_to_server() once, it will show:

To debug an issue, please take in one step at the time, then adjust when you're seeing issues.

This includes trying different scripts, specifically those intended to work with the sample itself, ie. websocketd for instance.

 

Kind regards,

Håkon

[esmart-engineering]

Can we have someone w/ more knowledge about this to support us?  Obvioously, Hakon is trying to drag out this issue.

[esmart-engineering]

My lead had me look into the 2 suggestions you had:

• Connect once and send data once
  • I have attached an updated project zip, with these changes.
  • wifi_station_w_sockets_v1.zip
  • It is still sometimes unable to connect to the server. Whether it was using my server script, your server script, or websocketd, none of them affected this result.
• Use websocketd for testing
  • I followed the instructions on the website link:
    • I prepared a Linux host machine, with the 3001 port ready for use.
    • I downloaded websocketd using the following command

      • $ wget 'https://github.com/joewalnes/websocketd/releases/download/v0.3.0/websocketd-0.3.0-linux_amd64.zip'
        $ unzip websocketd-0.3.0-linux_amd64.zip

    • I ran the command to start the program

      • $ ./websocketd --port=3001 cat

  • I have attached an example of the output from websocketd. This shows multiple attempts of powering on the nRF’s and having it send just 1 message.
    • (will upload later; DevZone is reporting errors when I try uploading)
  • Note that the Linux host we used is an AWS server that we have been using for multiple other products, for many years. Other than whatever else websocketd sets up, the Linux host and its settings absolutely should not be an issue when it comes to hosting servers.

Both of these suggestions did not work. Not only that, but again they were for addressing other parts of the project that are not the main problem we’re facing – why is it sometimes taking too long to connect to the server? Please address this directly. We will no longer waste time addressing other suggestions like this that lead us down different paths.

[esmart-engineering]

To make it even more clear - here is the project source showing the main problem. I'm not even calling send_data_to_server() at all anymore, as it's not the main problem. The main problem is with connect_to_server().

wifi_station_w_sockets_v2.zip

[Håkon Alseth]

Hi,

 

This seems to be due to timing between the connected event vs. when the DHCP is bound. Could you try to wait for the DHCP to be bound?

Here's a proposed diff:

diff --git a/src/main.c b/src/main.c
index 7a6f4fe..c675d6c 100644
--- a/src/main.c
+++ b/src/main.c
@@ -37,6 +37,9 @@ LOG_MODULE_REGISTER(sta, CONFIG_LOG_DEFAULT_LEVEL);
 #include <zephyr/net/websocket.h>
 #define SERVER_PORT 3001
 #define SERVER_ADDR4  CONFIG_NET_CONFIG_PEER_IPV4_ADDR
+^M
+static K_SEM_DEFINE(dhcp_bound, 0, 1);^M
+^M
 static int setup_socket(sa_family_t family, const char *server, int port,
                        int *sock, struct sockaddr *addr, socklen_t addr_len)
 {
@@ -333,6 +336,7 @@ static void net_mgmt_event_handler(struct net_mgmt_event_callback *cb,
 {
        switch (mgmt_event) {
        case NET_EVENT_IPV4_DHCP_BOUND:
+               k_sem_give(&dhcp_bound);^M
                print_dhcp_ip(cb);
                break;
        default:
@@ -437,6 +441,8 @@ int start_app(void)
                }
 
                if (context.connected) {
+                       LOG_INF("Waiting for DHCP to be bound");^M
+                       k_sem_take(&dhcp_bound, K_FOREVER);^M
                        cmd_wifi_status();
 
                        int err = connect_to_server();

File:

Fullscreen 51427.main.c Download

/*
 * Copyright (c) 2022 Nordic Semiconductor ASA
 *
 * SPDX-License-Identifier: LicenseRef-Nordic-5-Clause
 */

/** @file
 * @brief WiFi station sample
 */

#include <zephyr/logging/log.h>
LOG_MODULE_REGISTER(sta, CONFIG_LOG_DEFAULT_LEVEL);

#include <zephyr/kernel.h>
#include <stdio.h>
#include <stdlib.h>
#include <zephyr/shell/shell.h>
#include <zephyr/sys/printk.h>
#include <zephyr/init.h>

#include <zephyr/net/net_if.h>
#include <zephyr/net/wifi_mgmt.h>
#include <zephyr/net/net_event.h>
#include <zephyr/drivers/gpio.h>

#include <net/wifi_mgmt_ext.h>
#include <net/wifi_ready.h>

#if defined(CONFIG_BOARD_NRF7002DK_NRF7001_NRF5340_CPUAPP) || \
	defined(CONFIG_BOARD_NRF7002DK_NRF5340_CPUAPP)
#include <zephyr/drivers/wifi/nrf_wifi/bus/qspi_if.h>
#endif

/* Websocket */
#include <zephyr/net/net_ip.h>
#include <zephyr/net/socket.h>
#include <zephyr/net/websocket.h>
#define SERVER_PORT 3001
#define SERVER_ADDR4  CONFIG_NET_CONFIG_PEER_IPV4_ADDR

static K_SEM_DEFINE(dhcp_bound, 0, 1);

static int setup_socket(sa_family_t family, const char *server, int port,
			int *sock, struct sockaddr *addr, socklen_t addr_len)
{
	const char *family_str = family == AF_INET ? "IPv4" : "IPv6";
	int ret = 0;

	memset(addr, 0, addr_len);

	if (family == AF_INET) {
		net_sin(addr)->sin_family = AF_INET;
		net_sin(addr)->sin_port = htons(port);
		inet_pton(family, server, &net_sin(addr)->sin_addr);
	} else {
		// TODO
	}

	if (IS_ENABLED(CONFIG_NET_SOCKETS_SOCKOPT_TLS)) {
		// TODO
	} else {
		*sock = socket(family, SOCK_STREAM, IPPROTO_TCP);
	}

	if (*sock < 0) {
		LOG_ERR("Failed to create %s HTTP socket (%d)", family_str,
			-errno);
	}

	return ret;

fail:
	if (*sock >= 0) {
		close(*sock);
		*sock = -1;
	}

	return ret;
}
static int connect_socket(sa_family_t family, const char *server, int port,
			  int *sock, struct sockaddr *addr, socklen_t addr_len)
{
	int ret;

	ret = setup_socket(family, server, port, sock, addr, addr_len);
	if (ret < 0 || *sock < 0) {
		return -1;
	}

	ret = connect(*sock, addr, addr_len);
	if (ret < 0) {
		LOG_ERR("Cannot connect to %s remote (%d)",
			family == AF_INET ? "IPv4" : "IPv6",
			-errno);
		ret = -errno;
	}

	return ret;
}
static int connect_cb(int sock, struct http_request *req, void *user_data)
{
	LOG_INF("Websocket %d for %s connected.", sock, (char *)user_data);

	return 0;
}
static ssize_t sendall_with_ws_api(int sock, const void *buf, size_t len)
{
	return websocket_send_msg(sock, buf, len, WEBSOCKET_OPCODE_DATA_TEXT,
				  true, true, SYS_FOREVER_MS);
}
static ssize_t sendall_with_bsd_api(int sock, const void *buf, size_t len)
{
	return send(sock, buf, len, 0);
}
static bool send_and_wait_msg(int sock, size_t amount, const char *proto,
			      uint8_t *buf, size_t buf_len)
{
	static int count;
	int ret;

	if (sock < 0) {
		return true;
	}

	/* Terminate the sent data with \n so that we can use the
	 *      websocketd --port=9001 cat
	 * command in server side.
	 */
	buf[0] = 'H'; buf[1] = 'i'; buf[2] = '\n';

	/* Send every 2nd message using dedicated websocket API and generic
	 * BSD socket API. Real applications would not work like this but here
	 * we want to test both APIs. We also need to send the \n so add it
	 * here to amount variable.
	 */
	if (count % 2) {
		ret = sendall_with_ws_api(sock, buf, amount + 1);
	} else {
		ret = sendall_with_bsd_api(sock, buf, amount + 1);
	}

	if (ret <= 0) {
		if (ret < 0) {
			LOG_ERR("%s failed to send data using %s (%d)", proto,
				(count % 2) ? "ws API" : "socket API", ret);
		} else {
			LOG_DBG("%s connection closed", proto);
		}

		return false;
	} else {
		LOG_DBG("%s sent %d bytes", proto, ret);
	}

	count++;

	return true;
}

#include "net_private.h"

#define WIFI_SHELL_MODULE "wifi"

#define WIFI_SHELL_MGMT_EVENTS (NET_EVENT_WIFI_CONNECT_RESULT |		\
				NET_EVENT_WIFI_DISCONNECT_RESULT)

#define MAX_SSID_LEN        32
#define STATUS_POLLING_MS   300

/* 1000 msec = 1 sec */
#define LED_SLEEP_TIME_MS   100

/* The devicetree node identifier for the "led0" alias. */
#define LED0_NODE DT_ALIAS(led0)
/*
 * A build error on this line means your board is unsupported.
 * See the sample documentation for information on how to fix this.
 */
static const struct gpio_dt_spec led = GPIO_DT_SPEC_GET(LED0_NODE, gpios);

static struct net_mgmt_event_callback wifi_shell_mgmt_cb;
static struct net_mgmt_event_callback net_shell_mgmt_cb;

#ifdef CONFIG_WIFI_READY_LIB
static K_SEM_DEFINE(wifi_ready_state_changed_sem, 0, 1);
static bool wifi_ready_status;
#endif /* CONFIG_WIFI_READY_LIB */

static struct {
	const struct shell *sh;
	union {
		struct {
			uint8_t connected	: 1;
			uint8_t connect_result	: 1;
			uint8_t disconnect_requested	: 1;
			uint8_t _unused		: 5;
		};
		uint8_t all;
	};
} context;

void toggle_led(void)
{
	int ret;

	if (!device_is_ready(led.port)) {
		LOG_ERR("LED device is not ready");
		return;
	}

	ret = gpio_pin_configure_dt(&led, GPIO_OUTPUT_ACTIVE);
	if (ret < 0) {
		LOG_ERR("Error %d: failed to configure LED pin", ret);
		return;
	}

	while (1) {
		if (context.connected) {
			gpio_pin_toggle_dt(&led);
			k_msleep(LED_SLEEP_TIME_MS);
		} else {
			gpio_pin_set_dt(&led, 0);
			k_msleep(LED_SLEEP_TIME_MS);
		}
	}
}

K_THREAD_DEFINE(led_thread_id, 1024, toggle_led, NULL, NULL, NULL,
		7, 0, 0);

static int cmd_wifi_status(void)
{
	struct net_if *iface = net_if_get_default();
	struct wifi_iface_status status = { 0 };

	if (net_mgmt(NET_REQUEST_WIFI_IFACE_STATUS, iface, &status,
				sizeof(struct wifi_iface_status))) {
		LOG_INF("Status request failed");

		return -ENOEXEC;
	}

	LOG_INF("==================");
	LOG_INF("State: %s", wifi_state_txt(status.state));

	if (status.state >= WIFI_STATE_ASSOCIATED) {
		uint8_t mac_string_buf[sizeof("xx:xx:xx:xx:xx:xx")];

		LOG_INF("Interface Mode: %s",
		       wifi_mode_txt(status.iface_mode));
		LOG_INF("Link Mode: %s",
		       wifi_link_mode_txt(status.link_mode));
		LOG_INF("SSID: %.32s", status.ssid);
		LOG_INF("BSSID: %s",
		       net_sprint_ll_addr_buf(
				status.bssid, WIFI_MAC_ADDR_LEN,
				mac_string_buf, sizeof(mac_string_buf)));
		LOG_INF("Band: %s", wifi_band_txt(status.band));
		LOG_INF("Channel: %d", status.channel);
		LOG_INF("Security: %s", wifi_security_txt(status.security));
		LOG_INF("MFP: %s", wifi_mfp_txt(status.mfp));
		LOG_INF("RSSI: %d", status.rssi);
	}
	return 0;
}

static void handle_wifi_connect_result(struct net_mgmt_event_callback *cb)
{
	const struct wifi_status *status =
		(const struct wifi_status *) cb->info;

	if (context.connected) {
		return;
	}

	if (status->status) {
		LOG_ERR("Connection failed (%d)", status->status);
	} else {
		LOG_INF("Connected");
		context.connected = true;
	}

	context.connect_result = true;
}

static void handle_wifi_disconnect_result(struct net_mgmt_event_callback *cb)
{
	const struct wifi_status *status =
		(const struct wifi_status *) cb->info;

	if (!context.connected) {
		return;
	}

	if (context.disconnect_requested) {
		LOG_INF("Disconnection request %s (%d)",
			 status->status ? "failed" : "done",
					status->status);
		context.disconnect_requested = false;
	} else {
		LOG_INF("Received Disconnected");
		context.connected = false;
	}

	cmd_wifi_status();
}

static void wifi_mgmt_event_handler(struct net_mgmt_event_callback *cb,
				     uint32_t mgmt_event, struct net_if *iface)
{
	switch (mgmt_event) {
	case NET_EVENT_WIFI_CONNECT_RESULT:
		handle_wifi_connect_result(cb);
		break;
	case NET_EVENT_WIFI_DISCONNECT_RESULT:
		handle_wifi_disconnect_result(cb);
		break;
	default:
		break;
	}
}

static void print_dhcp_ip(struct net_mgmt_event_callback *cb)
{
	/* Get DHCP info from struct net_if_dhcpv4 and print */
	const struct net_if_dhcpv4 *dhcpv4 = cb->info;
	const struct in_addr *addr = &dhcpv4->requested_ip;
	char dhcp_info[128];

	net_addr_ntop(AF_INET, addr, dhcp_info, sizeof(dhcp_info));

	LOG_INF("DHCP IP address: %s", dhcp_info);
}
static void net_mgmt_event_handler(struct net_mgmt_event_callback *cb,
				    uint32_t mgmt_event, struct net_if *iface)
{
	switch (mgmt_event) {
	case NET_EVENT_IPV4_DHCP_BOUND:
		k_sem_give(&dhcp_bound);
		print_dhcp_ip(cb);
		break;
	default:
		break;
	}
}

static int wifi_connect(void)
{
	struct net_if *iface = net_if_get_first_wifi();

	context.connected = false;
	context.connect_result = false;

	if (net_mgmt(NET_REQUEST_WIFI_CONNECT_STORED, iface, NULL, 0)) {
		LOG_ERR("Connection request failed");

		return -ENOEXEC;
	}

	LOG_INF("Connection requested");

	return 0;
}

int bytes_from_str(const char *str, uint8_t *bytes, size_t bytes_len)
{
	size_t i;
	char byte_str[3];

	if (strlen(str) != bytes_len * 2) {
		LOG_ERR("Invalid string length: %zu (expected: %d)\n",
			strlen(str), bytes_len * 2);
		return -EINVAL;
	}

	for (i = 0; i < bytes_len; i++) {
		memcpy(byte_str, str + i * 2, 2);
		byte_str[2] = '\0';
		bytes[i] = strtol(byte_str, NULL, 16);
	}

	return 0;
}

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;
}

static uint8_t temp_recv_buf_ipv4[30];
int sock4 = -1;
int connect_to_server(void)
{
	struct sockaddr_in addr4;
	size_t amount;
	int ret = -1;

	LOG_INF("Try to open as client");
	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));
		return ret;
	}
	LOG_INF("Connected");
	return 0;
}

int start_app(void)
{
	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) {
			LOG_INF("Waiting for DHCP to be bound");
			k_sem_take(&dhcp_bound, K_FOREVER);
			cmd_wifi_status();

			int err = connect_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));

			gpio_pin_set_dt(&led, 0);
			sys_poweroff();
		}
	}

	return 0;
}

#ifdef CONFIG_WIFI_READY_LIB
void start_wifi_thread(void);
#define THREAD_PRIORITY K_PRIO_COOP(CONFIG_NUM_COOP_PRIORITIES - 1)
K_THREAD_DEFINE(start_wifi_thread_id, CONFIG_STA_SAMPLE_START_WIFI_THREAD_STACK_SIZE,
		start_wifi_thread, NULL, NULL, NULL,
		THREAD_PRIORITY, 0, -1);

void start_wifi_thread(void)
{
	start_app();
}

void wifi_ready_cb(bool wifi_ready)
{
	LOG_DBG("Is Wi-Fi ready?: %s", wifi_ready ? "yes" : "no");
	wifi_ready_status = wifi_ready;
	k_sem_give(&wifi_ready_state_changed_sem);
}
#endif /* CONFIG_WIFI_READY_LIB */

void net_mgmt_callback_init(void)
{
	memset(&context, 0, sizeof(context));

	net_mgmt_init_event_callback(&wifi_shell_mgmt_cb,
				     wifi_mgmt_event_handler,
				     WIFI_SHELL_MGMT_EVENTS);

	net_mgmt_add_event_callback(&wifi_shell_mgmt_cb);

	net_mgmt_init_event_callback(&net_shell_mgmt_cb,
				     net_mgmt_event_handler,
				     NET_EVENT_IPV4_DHCP_BOUND);

	net_mgmt_add_event_callback(&net_shell_mgmt_cb);

	LOG_INF("Starting %s with CPU frequency: %d MHz", CONFIG_BOARD, SystemCoreClock/MHZ(1));
	k_sleep(K_SECONDS(1));
}

#ifdef CONFIG_WIFI_READY_LIB
static int register_wifi_ready(void)
{
	int ret = 0;
	wifi_ready_callback_t cb;
	struct net_if *iface = net_if_get_first_wifi();

	if (!iface) {
		LOG_ERR("Failed to get Wi-Fi interface");
		return -1;
	}

	cb.wifi_ready_cb = wifi_ready_cb;

	LOG_DBG("Registering Wi-Fi ready callbacks");
	ret = register_wifi_ready_callback(cb, iface);
	if (ret) {
		LOG_ERR("Failed to register Wi-Fi ready callbacks %s", strerror(ret));
		return ret;
	}

	return ret;
}
#endif /* CONFIG_WIFI_READY_LIB */

int main(void)
{
	int ret = 0;

	net_mgmt_callback_init();

#ifdef CONFIG_WIFI_READY_LIB
	ret = register_wifi_ready();
	if (ret) {
		return ret;
	}
	k_thread_start(start_wifi_thread_id);
#else
	start_app();
#endif /* CONFIG_WIFI_READY_LIB */
	return ret;
}

 

Log:

*** Booting nRF Connect SDK v2.9.1-60d0d6c8d42d ***
*** Using Zephyr OS v3.7.99-ca954a6216c9 ***
[00:00:00.637,329] <inf> net_config: Initializing network
[00:00:00.637,329] <inf> net_config: Waiting interface 1 (0x20000dc8) to be up...
[00:00:00.637,481] <inf> net_config: IPv4 address: 192.168.1.99
[00:00:00.637,542] <inf> net_config: Running dhcpv4 client...
[00:00:00.638,366] <inf> sta: Starting nrf7002dk with CPU frequency: 64 MHz
[00:00:00.640,014] <inf> wifi_supplicant: wpa_supplicant initialized
[00:00:01.638,549] <inf> sta: Static IP address (overridable): 192.168.1.99/255.255.255.0 -> 192.168.1.1
[00:00:03.185,943] <inf> wifi_mgmt_ext: Connection requested
[00:00:03.185,974] <inf> sta: Connection requested
[00:00:03.186,035] <inf> sta: ==================
[00:00:03.186,065] <inf> sta: State: SCANNING
[00:00:03.486,206] <inf> sta: ==================
[00:00:03.486,236] <inf> sta: State: SCANNING
[00:00:03.786,346] <inf> sta: ==================
[00:00:03.786,376] <inf> sta: State: SCANNING
[00:00:04.086,486] <inf> sta: ==================
[00:00:04.086,517] <inf> sta: State: SCANNING
[00:00:04.386,627] <inf> sta: ==================
[00:00:04.386,657] <inf> sta: State: SCANNING
[00:00:04.686,828] <inf> sta: ==================
[00:00:04.686,859] <inf> sta: State: SCANNING
[00:00:04.986,968] <inf> sta: ==================
[00:00:04.986,999] <inf> sta: State: SCANNING
[00:00:05.287,139] <inf> sta: ==================
[00:00:05.287,170] <inf> sta: State: SCANNING
[00:00:05.587,280] <inf> sta: ==================
[00:00:05.587,310] <inf> sta: State: SCANNING
[00:00:05.887,451] <inf> sta: ==================
[00:00:05.887,481] <inf> sta: State: SCANNING
[00:00:06.187,591] <inf> sta: ==================
[00:00:06.187,622] <inf> sta: State: SCANNING
[00:00:06.487,731] <inf> sta: ==================
[00:00:06.487,762] <inf> sta: State: SCANNING
[00:00:06.787,902] <inf> sta: ==================
[00:00:06.787,933] <inf> sta: State: SCANNING
[00:00:07.088,043] <inf> sta: ==================
[00:00:07.088,073] <inf> sta: State: SCANNING
[00:00:07.388,214] <inf> sta: ==================
[00:00:07.388,244] <inf> sta: State: SCANNING
[00:00:07.688,385] <inf> sta: ==================
[00:00:07.688,415] <inf> sta: State: SCANNING
[00:00:07.988,555] <inf> sta: ==================
[00:00:07.988,586] <inf> sta: State: AUTHENTICATING
[00:00:08.288,726] <inf> sta: ==================
[00:00:08.288,757] <inf> sta: State: AUTHENTICATING
[00:00:08.373,504] <inf> sta: Connected
[00:00:08.588,836] <inf> sta: Waiting for DHCP to be bound
[00:00:12.395,080] <inf> net_dhcpv4: Received: 192.168.32.198
[00:00:12.395,263] <inf> net_config: IPv4 address: 192.168.32.198
[00:00:12.395,294] <inf> net_config: Lease time: 36000 seconds
[00:00:12.395,324] <inf> net_config: Subnet: 255.255.255.0
[00:00:12.395,355] <inf> net_config: Router: 192.168.32.1
[00:00:12.395,477] <inf> sta: DHCP IP address: 192.168.32.198
[00:00:12.401,916] <inf> sta: ==================
[00:00:12.401,947] <inf> sta: State: COMPLETED
[00:00:12.401,947] <inf> sta: Interface Mode: STATION
[00:00:12.401,977] <inf> sta: Link Mode: WIFI 6 (802.11ax/HE)
[00:00:12.402,008] <inf> sta: SSID: OpenWrt
[00:00:12.402,038] <inf> sta: BSSID: FC:34:97:0B:F6:DC
[00:00:12.402,069] <inf> sta: Band: 5GHz
[00:00:12.402,069] <inf> sta: Channel: 44
[00:00:12.402,099] <inf> sta: Security: WPA2-PSK
[00:00:12.402,099] <inf> sta: MFP: Optional
[00:00:12.402,130] <inf> sta: RSSI: -61
[00:00:12.402,130] <inf> sta: Try to open as client
[00:00:12.474,487] <inf> sta: Connected
[00:00:12.488,708] <inf> sta: Interface down

 

Best regards,

Håkon

[esmart-engineering]

I tested your code, along with the websocketd server, and was able to reproduce a similar log. However, the original problem is still there – the overall time to perform this operation is taking too long. It’s just that we have narrowed down the source of the delay to be when the nRF is waiting for DHCP (which your latest log also shows as well).

Why is this happening? As mentioned before, and as your sales rep is aware, we had previous projects using the nRF7002. We tested these with the same router and same Linux host as this current project, yet they did not experience this issue. These previous projects had the nRF code developed through Linux drivers, not through NCS/Zephyr. So perhaps this is something to do with the Zephyr drivers?

[Håkon Alseth]

Hi,

 

You're looking at the overall timing process, from boot until socket connected, correct?

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.

A linux device has more processing power for the WPA supplicant part than a nRF5-device has, and there will be a difference between the linux net based application implementation, as compared to the zephyr net implementation.

 

The crypto cpu processing part will take around 3-4 seconds for WPA2 as an example. You can see the difference by setting up test AP's with WPA2 / WPA3 and "open" security.

The below tests are from a complete cold boot (ie. power off, wait, power on), which is also why the logs are missing the first boot sequence logs (ie. "booting nRF connect SDK" etc)

WPA2 (nRF52840DK + nRF7002EK):

[00:00:01.631,896] <inf> sta: Static IP address (overridable): 192.168.1.99/255.255.255.0 -> 192.168.1.1
[00:00:03.296,081] <inf> wifi_mgmt_ext: Connection requested
[00:00:03.296,142] <inf> sta: Connection requested
[00:00:08.471,496] <inf> sta: Connected
[00:00:08.697,570] <inf> sta: Waiting for DHCP to be bound
[00:00:13.485,076] <inf> net_dhcpv4: Received: 192.168.32.163
[00:00:13.485,290] <inf> net_config: IPv4 address: 192.168.32.163
[00:00:13.485,321] <inf> net_config: Lease time: 36000 seconds
[00:00:13.485,351] <inf> net_config: Subnet: 255.255.255.0
[00:00:13.485,412] <inf> net_config: Router: 192.168.32.1
[00:00:13.485,809] <inf> sta: Try to open as client
[00:00:14.093,872] <inf> sta: Connected
[00:00:14.108,062] <inf> wifi_supplicant: Network interface 1 (0x20001140) down
[00:00:14.108,306] <inf> sta: Interface down

Open security:

[00:00:01.630,187] <inf> sta: Static IP address (overridable): 192.168.1.99/255.255.255.0 -> 192.168.1.1
[00:00:01.642,333] <inf> wifi_mgmt_ext: Connection requested
[00:00:01.642,364] <inf> sta: Connection requested
[00:00:06.731,109] <inf> sta: Connected
[00:00:06.743,713] <inf> sta: Waiting for DHCP to be bound
[00:00:06.748,962] <inf> net_dhcpv4: Received: 192.168.32.163
[00:00:06.749,145] <inf> net_config: IPv4 address: 192.168.32.163
[00:00:06.749,176] <inf> net_config: Lease time: 36000 seconds
[00:00:06.749,206] <inf> net_config: Subnet: 255.255.255.0
[00:00:06.749,267] <inf> net_config: Router: 192.168.32.1
[00:00:06.749,694] <inf> sta: Try to open as client
[00:00:07.369,934] <inf> sta: Connected
[00:00:07.383,911] <inf> wifi_supplicant: Network interface 1 (0x20001140) down
[00:00:07.384,155] <inf> sta: Interface down

 

Looking into the implementation, there will be a timing variation on both these testing vectors, as dhcp is udp based and the zephyr dhcp client has randomness on sending the request on the first boot. 

There is a random delay between 1 to 10 seconds in the initial dhcp client sequence, required as per RFC2131 4.4.1, which you can set with CONFIG_NET_DHCPV4_INITIAL_DELAY_MAX=2 (value of '2' is min at this time).

 

Here are the configurations that I added:

CONFIG_NRF_WIFI_PS_EXIT_EVERY_TIM=y
CONFIG_NET_SHELL=n
CONFIG_SHELL=n
CONFIG_NET_DHCPV4_INITIAL_DELAY_MAX=2

 

PS: If you want to test with no delay on initial dhcp request, you can set the "true -> false" in this function call:

https://github.com/nrfconnect/sdk-zephyr/blob/v3.7.99-ncs3/subsys/net/lib/dhcpv4/dhcpv4.c#L1816

RFC2131 ch 4.4.1 (https://www.rfc-editor.org/rfc/rfc2131.html#section-4.4) uses the wording "should" indicating that this initial delay is optional, which I will take up internally with our networking team.

  

Kind regards,

Håkon