NRF7002-DK and DNS resolver

[Vigen]

Hello,

I've been evaluating the NRF7002-DK with 2.3.0-rc1 SDK. Although there's almost no documentation on how to use Noridc's WiFi stack (at least I haven't found any), the samples in the SDK were great and I was able to get the scanning, connecting and DHCP working just fine.

Where I faced issues was with DNS host resolution using the getaddrinfo API - it just times out regardless the timeout value I put in configuration. I have a feeling this has to do with the configuration, but I wasn't able to figure this out. Attempting to debug the issue cause stack overflow as the library seem to be 'caught' in the middle of static initialization when VScode stops on 'main()' entry.

I would greatly appreciate any help to unblock the use of getaddrinfo() API. Thank you!

Here's what I have in the prj.conf

# WiFi stack.
CONFIG_WIFI=y
CONFIG_WIFI_NRF700X=y
CONFIG_NET_L2_WIFI_MGMT=y
# WPA Supplicant is required to establish WiFi connection.
CONFIG_WPA_SUPP=y

# Networking stack needed for WiFi to operate.
CONFIG_NET_L2_ETHERNET=y
CONFIG_NET_DHCPV4=y
CONFIG_NET_IPV4=y
CONFIG_NET_UDP=y
CONFIG_NET_TCP=y
CONFIG_NET_SOCKETS_POLL_MAX=10
CONFIG_NET_CONFIG_SETTINGS=y
CONFIG_NET_SOCKETS_POSIX_NAMES=y

CONFIG_DNS_RESOLVER=y
CONFIG_DNS_NUM_CONCUR_QUERIES=2
CONFIG_DNS_RESOLVER_LOG_LEVEL_DBG=y
CONFIG_NET_SOCKETS_DNS_TIMEOUT=30000

# SSL?
CONFIG_POSIX_CLOCK=y
CONFIG_ENTROPY_GENERATOR=y

# Buffers.
CONFIG_NET_PKT_RX_COUNT=8
CONFIG_NET_PKT_TX_COUNT=8

# Memories.
CONFIG_NET_TX_STACK_SIZE=4096
CONFIG_NET_RX_STACK_SIZE=4096
CONFIG_NET_MGMT_EVENT_STACK_SIZE=4096

[dejans]

Hi,

Which application or sample do you use? Could you provide more information about your application?

Could you provide log output from your application?

Best regards,
Dejan

[Vigen]

I based my code on sta and scan apps in nrf/samples/wifi. The application scans the available WiFi APs, selects the one that is configured and establishes a WiFi connection with that AP (this part works just fine). Later on the app tries to connect to Azure IoT Hub DPS, which uses getaddrinfo under the hood to resolve the DPS IP address for mqtt to connect to. The Azure connection works just great with NRF9160-DK over LTE, but with NRF7002-DK the DNS resolution fails.

Here's log the log snippet:

[00:00:00.274,902] <inf> wifi_nrf: QSPI freq = 24 MHz
[00:00:00.280,426] <inf> wifi_nrf: QSPI latency = 1
[00:00:00.293,487] <inf> wifi_nrf: wifi_nrf_fmac_fw_load: LMAC patches loaded
[00:00:00.312,042] <inf> wifi_nrf: wifi_nrf_fmac_fw_load: LMAC boot check passed
[00:00:00.322,753] <inf> wifi_nrf: wifi_nrf_fmac_fw_load: UMAC patches loaded
[00:00:00.341,278] <inf> wifi_nrf: wifi_nrf_fmac_fw_load: UMAC boot check passed
[00:00:00.381,652] <inf> wifi_nrf: RPU LPM type: HW
[00:00:00.599,060] <inf> wifi_nrf: wifi_nrf_if_carr_state_chg: Carrier state: 0
[00:00:00.696,716] <dbg> net_dns_resolve: dns_resolve_init_locked: (main): No DNS servers defined.
*** Booting Zephyr OS build v3.2.99-ncs2-rc1 ***
[00:00:00.710,632] <inf> net_config: Initializing network
[00:00:00.716,522] <inf> net_config: Waiting interface 1 (0x20001560) to be up...
[00:00:00.724,487] <inf> net_config: Running dhcpv4 client...
[00:00:00.739,990] <inf> work_queues: IO work queue started
[00:00:00.806,457] <inf> wpa_supp: z_wpas_start: 334 Starting wpa_supplicant thread with debug level: 3
[00:00:00.829,162] <inf> wpa_supp: Successfully initialized wpa_supplicant
[00:00:00.853,759] <inf> wifi: Scanning for WiFi networks
[00:00:00.869,110] <inf> wpa_supp: l2_packet_init: iface wlan0 ifindex 1
[00:00:05.189,361] <inf> wifi: Got WiFi result: ssid=****, security=OPEN, band=5GHz, channel=A1, mac=***
[00:00:05.201,049] <inf> wifi: Got WiFi result: ssid=****, security=OPEN, band=2.4GHz, channel=06, mac=***
[00:00:05.213,958] <inf> wifi: Got WiFi result: ssid=****, security=WPA2-PSK, band=5GHz, channel=95, mac=***
[00:00:05.225,891] <inf> wifi: Got WiFi result: ssid=****, security=WPA2-PSK, band=5GHz, channel=95, mac=***
[00:00:05.238,433] <inf> wifi: Got WiFi result: ssid=****, security=WPA2-PSK, band=2.4GHz, channel=06, mac=***
[00:00:05.250,640] <inf> wifi: Got WiFi result: ssid=****, security=WPA2-PSK, band=2.4GHz, channel=06, mac=***
[00:00:05.263,732] <inf> wifi: Got WiFi result: ssid=****, security=OPEN, band=2.4GHz, channel=01, mac=***
[00:00:05.276,245] <inf> wifi: Got WiFi result: ssid=****, security=WPA2-PSK, band=2.4GHz, channel=0B, mac=***
[00:00:05.288,543] <inf> wifi: Got WiFi result: ssid=****, security=WPA2-PSK, band=5GHz, channel=99, mac=***
[00:00:05.300,811] <inf> wifi: Connecting to ****...
[00:00:10.886,291] <inf> wpa_supp: wlan0: SME: Trying to authenticate with 08:9b:f1:93:36:71 (SSID='****' freq=5240 MHz)
[00:00:10.903,442] <inf> wifi_nrf: wifi_nrf_wpa_supp_authenticate:Authentication request sent successfully
[00:00:11.167,236] <inf> wpa_supp: wlan0: Trying to associate with 08:9b:f1:93:36:71 (SSID='****' freq=5240 MHz)
[00:00:11.188,903] <inf> wifi_nrf: wifi_nrf_wpa_supp_associate: Association request sent successfully
[00:00:11.211,059] <inf> wifi_nrf: wifi_nrf_if_carr_state_chg: Carrier state: 1
[00:00:11.223,602] <inf> wpa_supp: wpa_drv_zep_get_ssid: SSID size: 13
[00:00:11.230,834] <inf> wpa_supp: wlan0: Associated with 08:9b:f1:93:36:71
[00:00:11.238,311] <inf> wpa_supp: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
[00:00:11.248,657] <inf> wpa_supp: wpa_drv_zep_get_ssid: SSID size: 13
[00:00:11.280,426] <inf> wpa_supp: wlan0: WPA: Key negotiation completed with 08:9b:f1:93:36:71 [PTK=CCMP GTK=CCMP]
[00:00:11.291,564] <inf> wpa_supp: wlan0: CTRL-EVENT-CONNECTED - Connection to 08:9b:f1:93:36:71 completed [id=0 id_str=]
[00:00:11.309,356] <wrn> wifi: Unexpected event received: -536608759
[00:00:11.323,364] <inf> wifi: Connected to WiFi network, waiting for dhcp allocation...
[00:00:12.515,899] <inf> net_dhcpv4: Received: 192.168.12.20
[00:00:12.522,125] <inf> net_config: IPv4 address: 192.168.12.20
[00:00:12.528,503] <inf> net_config: Lease time: 14092 seconds
[00:00:12.534,759] <inf> net_config: Subnet: 255.255.255.0
[00:00:12.540,679] <inf> net_config: Router: 192.168.12.1
[00:00:12.549,072] <inf> wifi: DHCP IP address: 192.168.12.20
[00:00:12.556,304] <dbg> net_dns_resolve: dns_resolve_name: (): DNS id will be 20441
[00:00:12.564,575] <dbg> net_dns_resolve: dns_write: (): [0] submitting work to server idx 0 for id 20441 hash 59079
[00:00:14.564,666] <dbg> net_dns_resolve: query_timeout: (sysworkq): Query timeout DNS req 20441 type 1 hash 59079
[00:00:14.575,408] <dbg> net_dns_resolve: dns_resolve_cancel_with_hash: (sysworkq): Cancelling DNS req 20441 (name google.com type 1 hash 59079)
[00:00:14.588,867] <err> wifi: getaddrinfo failed -101
[00:00:14.594,726] <err> wifi: Failed to resolve www.google.com: -5
[00:00:14.601,684] <err> main: Failed to enable cloud
[00:00:14.607,421] <inf> wifi: Connected to wifi: addrs=192.168.12.1
[00:00:14.614,227] <inf> azure_iot: Initializing Azure IoT Hub...
[00:00:14.621,032] <inf> azure_iot: Azure provisioning not started
[00:00:14.627,868] <dbg> net_dns_resolve: dns_resolve_name: (): DNS id will be 19812
[00:00:14.636,108] <dbg> net_dns_resolve: dns_write: (): [0] submitting work to server idx 0 for id 19812 hash 36583
[00:00:14.729,003] <err> mqtt_helper: mqtt_connect, error: -23
[00:00:14.735,626] <err> azure_iot_hub_dps: mqtt_helper_connect failed, error: -23
[00:00:14.743,835] <err> azure_iot: Failed to start Azure device provisioning: err=-23
[00:00:14.752,441] <err> main: Failed to initialize cloud: err=-23

[Vigen]

I did several runs, and they were quite inconsistent. Most of the times DNS would work, but from now and then it would timeout, especially on the hosts that are not accessed often. That said, the consequent run on the same host would succeed. I tried to increase the timeout without no effect on resolution error rate, but then I added a retry logic... and now it works like a charm in my app.

Correctly if I am wrong, but with the config I have it the DNS resolution happens over UDP. Then the only explanation I can think of that would induce the above behavior is that sometimes the first packet is lost (radio issues or my wifi setup, can't say), but afterwards things start to work neetly. Here's the log with socket debug enabled:

[00:00:10.627,838] <inf> wifi: Connected to WiFi network, waiting for dhcp allocation...
[00:00:10.975,097] <inf> net_dhcpv4: Received: 192.168.6.57
[00:00:10.975,280] <inf> net_config: IPv4 address: 192.168.6.57
[00:00:10.975,280] <inf> net_config: Lease time: 11120 seconds
[00:00:10.975,341] <inf> net_config: Subnet: 255.255.252.0
[00:00:10.975,433] <inf> net_config: Router: 192.168.4.1
[00:00:10.976,623] <inf> wifi: DHCP IP address: 192.168.6.57
[00:00:12.979,064] <wrn> wifi: Failed to resolve www.google.com: err=-5
[00:00:13.514,526] <inf> wifi: Successfully resolved www.google.com
[00:00:13.531,677] <inf> wifi: Successfully resolved www.amazon.com
[00:00:13.550,781] <inf> wifi: Successfully resolved www.yahoo.com
[00:00:13.550,781] <inf> wifi: All test servers has been successfully resolved

[dejans]

Hi,

Previously, you got timeout when both 2.4 GHz and 5 GHz network bands were enabled. With the addition of your retry logic, do you get successful resolution when both network bands are enabled?

Best regards,
Dejan

[Vigen]

Yes, that's right. Previously I tried to introduce a yield timeout of 1-10 seconds before the DNS resolution happens thinking I am accessing the stack too early (though as I wait for DHCP assignment that shouldn't have mattered). But apparently, it's the retries that guarantee the DNS to work. With the first successful resolution, all consequent resolutions work fine.

[dejans]

Hi,

Could you show your retry logic?

Best regards,
Dejan

[Vigen]

Hi Dejan,

Sorry for the late response. Here's my retry logic:

static int verify_hostname_resolved(const char* hostname) {
  struct addrinfo* result;
  struct addrinfo hints = {.ai_family = AF_INET, .ai_socktype = SOCK_DGRAM};
  int err = getaddrinfo(hostname, NULL, &hints, &result);
  if (err != 0) {
    return -EIO;
  }

  if (result == NULL) {
    return -ENOENT;
  }

  /* IPv4 Address. */
  struct sockaddr_in server = {
      .sin_addr = {.s_addr =
                       ((struct sockaddr_in*)result->ai_addr)->sin_addr.s_addr},
      .sin_family = AF_INET,
      .sin_port = htons(80),
  };

  /* Free the address. */
  freeaddrinfo(result);

  char ipv4_addr[NET_IPV4_ADDR_LEN];
  if (inet_ntop(AF_INET, &server.sin_addr.s_addr, ipv4_addr,
                sizeof(ipv4_addr))) {
    LOG_INF("Successfully resolved IP address: hostname=%s, ip=%s", hostname,
            ipv4_addr);
    return 0;
  }

  return -EAGAIN;
}

static int verify_dns() {
  const char* dns_test_servers[] = {"www.google.com", "www.amazon.com",
                                    "www.yahoo.com"};

  size_t dns_test_retry_count = 10;
  while (dns_test_retry_count-- > 0) {
    bool resolved = true;
    for (size_t i = 0; i < ARRAY_SIZE(dns_test_servers); ++i) {
      int err = verify_hostname_resolved(dns_test_servers[i]);
      if (err) {
        resolved = false;
        LOG_WRN("Failed to resolve %s: err=%d", dns_test_servers[i], err);
        break;
      }
    }

    if (resolved) {
      LOG_INF("All test servers has been successfully resolved");
      return 0;
    }

    // Sleep for (random) 500ms before trying again.
    k_usleep(500000);
  }

  return -ENETDOWN;
}

[dejans]

Hi,

There is a pull request for this DNS resolution problem - checking existing DNS servers before reconfigure.

Best regards,
Dejan