7002dk mqtt demo connect to router problem

[William.wei]

hi support team,

I was testing 7002dk with a Asus router，i found two questions:

1.5340tfm jump to application taks about 8 seconds, why it takes so much time?

2.7002dk could never connect to Asus router once it is disconnected.(pc and mobile phone don't have such problem)

i have input the debug log in attachment, please help to look at this problem.

7607.7002dk_connect_error_log.txt

3. i also see a hardfault problem:

[13:50:02.074] [00:00:21.921,813] [0m<inf> network: Network connectivity established[0m

[13:50:02.080]

[13:50:08.344] [00:00:28.187,286] [0m<inf> transport: Connected to MQTT broker[0m

[13:50:08.355] [00:00:28.196,258] [0m<inf> transport: Hostname: test.mosquitto.org[0m

[13:50:08.355] [00:00:28.202,789] [0m<inf> transport: Client ID: F4CE36000396[0m

[13:50:08.364] [00:00:28.208,740] [0m<inf> transport: Port: 1883[0m

[13:50:08.374] [00:00:28.213,592] [0m<inf> transport: TLS: No[0m

[13:50:08.374] [00:00:28.218,200] [0m<inf> transport: Subscribing to: F4CE36000396/my/subscribe/topic[0m

[13:50:08.378]

[13:50:09.395] [00:00:29.235,595] [0m<inf> transport: Subscribed to topic F4CE36000396/my/subscribe/topic[0m

[13:50:09.400]

[13:50:10.344] [00:00:30.188,079] [0m<dbg> wpa_supp: wpa_printf_impl: wlan0: Control interface command 'SIGNAL_POLL'[0m

[13:50:10.349] [00:00:30.211,395] [0m<inf> transport: TWT setup success![0m

[13:50:10.367]

[13:51:40.714] [00:02:00.559,295] [0m<inf> transport: Published message: "Hello MQTT! Current uptime is: 120558" on topic: "F4CE36000396/my/publish/topic"[0m

[13:51:40.725]

[13:53:00.704] [00:03:20.547,729] [0m<dbg> wpa_supp: wpa_printf_impl: wlan0: BSS: Remove id 1 BSSID 04:42:1a:a2:fc:70 SSID 'Nordic_ASUS' due to wpa_bss_flush_by_age[0m

[13:53:00.714] [00:03:20.561,828] [0m<dbg> wpa_supp: wpa_printf_impl: Received len: 42, msg_len:42 - CTRL-EVENT-BSS-REMOVED 1 04:42:1a:a2:fc:70->END[0m

[13:53:00.724]

[13:53:40.714] [00:04:00.559,539] [0m<inf> transport: Published message: "Hello MQTT! Current uptime is: 240558" on topic: "F4CE36000396/my/publish/topic"[0m

[13:53:40.723]

[13:55:40.714] [00:06:00.559,783] [0m<inf> transport: Published message: "Hello MQTT! Current uptime is: 360558" on topic: "F4CE36000396/my/publish/topic"[0m

[13:55:40.725]

[13:57:40.714] [00:08:00.560,058] [0m<inf> transport: Published message: "Hello MQTT! Current uptime is: 480559" on topic: "F4CE36000396/my/publish/topic"[0m

[13:57:40.722]

[13:59:40.714] [00:10:00.560,241] [0m<inf> transport: Published message: "Hello MQTT! Current uptime is: 600559" on topic: "F4CE36000396/my/publish/topic"[0m

[13:59:40.729]

[14:01:40.715] [00:12:00.560,791] [0m<inf> transport: Published message: "Hello MQTT! Current uptime is: 720559" on topic: "F4CE36000396/my/publish/topic"[0m

[14:01:40.728]

[14:03:40.714] [00:14:00.560,943] [0m<inf> transport: Published message: "Hello MQTT! Current uptime is: 840560" on topic: "F4CE36000396/my/publish/topic"[0m

[14:03:40.729]

[14:04:31.843] [00:14:51.686,370] [0m<inf> network: Network connectivity lost[0m

[14:04:31.843] [00:1[00:14:51.695,037] [0m<dbg> wpa_supp: wpa_printf_impl: wlan0: RX EAPOL from 04:42:1a:a2:fc:74[0m

[14:04:31.854] [00:14:51.705,718] [0m<dbg> wpa_supp: wpa_printf_impl: RX EAPOL - hexdump(len=163): 02 03 00 9f 02 13 82 00 00 00 00 00 00 00 00 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0[0m

[14:04:31.885] [00:14:51.733,306] [0m<dbg> wpa_supp: wpa_printf_impl: wlan0: IEEE 802.1X RX: version=2 type=3 length=159[0m

[14:04:31.894] [00:14:51.744,812] [0m<dbg> wpa_supp: wpa_printf_impl: WPA: RX EAPOL-Key - hexdump(len=163): 02 03 00 9f 02 13 82 00 00 00 00 00 00 00 00 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0[0m

[14:04:31.925] [00:14:51.772,338] [0m<dbg> wpa_supp: wpa_printf_impl: wlan0: EAPOL-Key type=2[0m

[14:04:31.936] [00:14:51.780,090] [0m<dbg> wpa_supp: wpa_printf_impl: wlan0: key_info 0x1382 (ver=2 keyidx=0 rsvd=0 Group Ack MIC Secure Encr)[0m

[14:04:31.944] [00:14:51.791,961] [0m<dbg> wpa_supp: wpa_printf_impl: wlan0: key_length=0 key_data_length=64[0m

[14:04:31.954] [00:14:51.800,933] [0m<dbg> wpa_supp: wpa_printf_impl: replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 04[0m

[14:04:31.964] [00:14:51.811,706] [0m<dbg> wpa_supp: wpa_printf_impl: key_nonce - hexdump(len=32): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00[0m

[14:04:31.984] [00:14:51.828,186] [0m<dbg> wpa_supp: wpa_printf_impl: key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00[0m

[14:04:31.995] [00:14:51.840,148] [0m<dbg> wpa_supp: wpa_printf_impl: key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00[0m

[14:04:32.005] [00:14:51.850,067] [0m<dbg> wpa_supp: wpa_printf_impl: key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00[0m

[14:04:32.014] [00:14:51.860,931] [0m<dbg> wpa_supp: wpa_printf_impl: key_mic - hexdump(len=16): fd 66 b0 e0 13 f4 b5 47 86 69 e8 cd 1b 99 10 0d[0m

[14:04:32.024] [00:14:51.872,894] [0m<dbg> wpa_supp: wpa_printf_impl: WPA: EAPOL-Key MIC using HMAC-SHA1[0m

[14:04:32.032] [00:14:51.883,270] [0m<dbg> wpa_supp: wpa_printf_impl: RSN: encrypted key data - hexdump(len=64): 2a 38 4d d4 3b 8a 76 78 7c 75 56 76 dc 16 1e be d7 8d 46 64 ba 83 b3 a1 e6 8e ae fa 9a 7a a3 72 ba 92 00 88 59 f4 75 2b f9 4f 61 d4 f3 89 65 fa de 92 ad d9 c5 3c 68 1a b6 76 e4 3c bc 95 cc 17[0m

[14:04:32.063] [00:14:51.908,935] [0m<dbg> wpa_supp: wpa_printf_impl: WPA: Decrypt Key Data using AES-UNWRAP (KEK length 16)[0m

[14:04:32.072] [00:14:51.919,891] [0m<dbg> wpa_supp: wpa_printf_impl: WPA: decrypted EAPOL-Key key data - hexdump(len=56): [REMOVED][0m

[14:04:32.085] [00:14:51.930,816] [0m<dbg> wpa_supp: wpa_printf_impl: wlan0: RSN: RX message 1 of Group Key Handshake from 04:42:1a:a2:fc:74 (ver=2)[0m

[14:04:32.094] [00:14:51.943,359] [0m<dbg> wpa_supp: wpa_printf_impl: RSN: msg 1/2 key data - hexdump(len=56): [REMOVED][0m

[14:04:32.104] [00:14:51.953,155] [0m<dbg> wpa_supp: wpa_printf_impl: WPA: GTK in EAPOL-Key - hexdump(len=24): [REMOVED][0m

[14:04:32.115] [00:14:51.962,860] [0m<dbg> wpa_supp: wpa_printf_impl: WPA: IGTK in EAPOL-Key - hexdump(len=30): [REMOVED][0m

[14:04:32.123] [00:14:51.972,747] [0m<dbg> wpa_supp: wpa_printf_impl: wlan0: State: COMPLETED -> GROUP_HANDSHAKE[0m

[14:04:32.136] [00:14:51.981,811] [0m<dbg> wpa_supp: wpa_printf_impl: RSN: received GTK in group key handshake - hexdump(len=18): [REMOVED][0m

[14:04:32.147] [00:14:51.993,286] [0m<dbg> wpa_supp: wpa_printf_impl: wlan0: WPA: IGTK keyid 5 pn 000000000000[0m

[14:04:32.154] [00:14:52.002,136] [0m<dbg> wpa_supp: wpa_printf_impl: WPA: IGTK - hexdump(len=16): [REMOVED][0m

[14:04:32.162] [00:14:52.010,925] [0m<dbg> wpa_supp: wpa_printf_impl: _wpa_drv_zep_set_key: priv:0x2000e7e0 alg 4 addr 0xb5be8 key_idx 5 set_tx 0 seq 0x2003cc1b seq_len 6 key 0x2003cc21 key_len 16 key_flag 14[0m

[14:04:32.185] 4:51.693,542] [0m<inf> transport: Disconnected from MQTT broker[00:14:52.040,618] [0m<dbg> wpa_supp: wpa_printf_impl: WPA: Group Key - hexdump(len=16): [REMOVED][0m

[14:04:32.204] [00:14:52.049,926] [0m<dbg> wpa_supp: wpa_printf_impl: wlan0: WPA: Installing GTK to the driver (keyidx=2 tx=0 len=16)[0m

[14:04:32.214] [00:14:52.060,882] [0m<dbg> wpa_supp: wpa_printf_impl: WPA: RSC - hexdump(len=6): 00 00 00 00 00 00[0m

[14:04:32.225] [00:14:52.070,190] [0m<dbg> wpa_supp: wpa_printf_impl: _wpa_drv_zep_set_key: priv:0x2000e7e0 alg 3 addr 0xb5be8 key_idx 2 set_tx 0 seq 0x2003cbd9 seq_len 6 key 0x20017860 key_len 16 key_flag 14[0m

[14:04:32.243] [0m

[14:04:32.243] [00:14:52.088,653] [1;31m<err> mqtt_helper: Failed to send[00:14:52.098,785] [0m<dbg> wpa_supp: wpa_printf_impl: wlan0: WPA: Sending EAPOL-Key 2/2[0m

[14:04:32.264] [00:14:52.107,238] [0m<dbg> wpa_supp: wpa_printf_impl: WPA: Send EAPOL-Key frame to 04:42:1a:a2:fc:74 ver=2 mic_len=16 key_mgmt=0x2[0m

[14:04:32.284] [00:14:52.119,171] [0m<dbg> wpa_supp: wpa_printf_impl: WPA: EAPOL-Key MIC using HMAC-SHA1[0m

[14:04:32.284] [00:14:52.128,753] [0m<dbg> wpa_supp: wpa_printf_impl: WPA: KCK - hexdump(len=16): [REMOVED][0m

[14:04:32.294] [00:14:52.137,542] [0m<dbg> wpa_supp: wpa_printf_impl: WPA: Derived Key MIC - hexdump(len=16): 03 12 85 7f 9e c4 e0 4d 4e 03 35 f7 bd 43 a2 f1[0m

[14:04:32.305] [00:14:52.151,580] [0m<dbg> wpa_supp: wpa_printf_impl: WPA: TX EAPOL-Key - hexdump(len=99): 01 03 00 5f 02 03 02 00 00 00 00 00 00 00 00 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00[0m

[14:04:32.335] [00:14:52.179,107] [1;31m<err> wpa_supp: l2_packet_send - sendto: Network interface is not configured[0m

[14:04:32.345] [00:14:52.189,178] [0m<dbg> wpa_supp: wpa_printf_impl: wlan0: Request t

[14:04:32.353] o deauthenticate - bssid=04:42:1a:a2:fc:74 pending_bssid=00:00:00:00:00:00 reason=1 (UNSPECIFIED) state=GROUP_HANDSHAKE[0m

[14:04:32.363] disconnection request, treating as disconnected[0m

[14:04:32.363] [00:14:52.217,010] [0m<dbg> wpa_supp: wpa_printf_impl: wlan0: Event DEAUTH (11) received[0m

[14:04:32.385] [00:14:52.225,433] [0m<dbg> wpa_supp: wpa_printf_impl: wlan0: Deauthentication notification[0m

[14:04:32.385] [00:14:52.234,039] [0m<dbg> wpa_supp: wpa_printf_impl: wlan0: * reason 1 (UNSPECIFIED) locally_generated=1[0m

[14:04:32.395] [00:14:52.243,957] [0m<dbg> wpa_supp: wpa_printf_impl: Deauthentication frame IE(s) - hexdump(len=0): [NULL][0m

[14:04:32.406] [00:14:52.254,119] [1;31m<err> os: ***** USAGE FAULT *****[0m

[14:04:32.414] [00:14:52.259,674] [1;31m<err> os: Stack overflow (context area not valid)[0m

[14:04:32.424] [00:14:52.266,876] [1;31m<err> os: r0/a1: 0x0dc6f285 r1/a2: 0x1cfe5ce8 r2/a3: 0x000246e8[0m

[14:04:32.435] [00:14:52.275,512] [1;31m<err> os: r3/a4: 0x01000000 r12/ip: 0x0000005b r14/lr: 0x5b08b850[0m

[14:04:32.444] [00:14:52.284,149] [1;31m<err> os: xpsr: 0x0007e600[0m

[14:04:32.444] [00:14:52.289,337] [1;31m<err> os: Faulting instruction address (r15/pc): 0x80000000[0m

[14:04:32.455] [00:14:52.297,210] [1;31m<err> os: >>> ZEPHYR FATAL ERROR 2: Stack overflow on CPU 0[0m

[14:04:32.463] [00:14:52.305,053] [1;31m<err> os: Current thread: 0x2000d760 (unknown)[0m

[14:04:32.463] [00:14:52.311,798] [1;31m<err> os: Halting system[0m

Regards,

thanks!

[Håkon Alseth]

Hi,

 

1.5340tfm jump to application taks about 8 seconds, why it takes so much time?

Looks like there's a secure side log on timestamp at 1 and 9, so why do you mean that this is tfm?

It is too little info for me to state anything on what happens in this scenario, unfortunately.

7002dk could never connect to Asus router once it is disconnected.(pc and mobile phone don't have such problem)

Do you see the same issue if you use wifi/shell for instance?

3. i also see a hardfault problem:

Likely because there's a disconnect/reconnect scenario, and the application re-uses already closed sockets. When the network goes down, so does the sockets/connection towards the server. You will have to re-establish such connection again before starting to send data.

 

Kind regards,

Håkon

[William.wei]

Thanks Hakon,

for problem 1, sorry for whatever i thought it was, it costs 8 to 9 seconds anyway.how can we reduce this time, it is not acceptable.

this is mqtt demo by defualt.

for problem 2, what should i do to collect more information if you need it?

for problem 3, it is clear.

Regards,

William.

[Håkon Alseth]

Hi,

 

William.wei said:

for problem 1, sorry for whatever i thought it was, it costs 8 to 9 seconds anyway.how can we reduce this time, it is not acceptable.

this is mqtt demo by defualt.

Which firmware are you specifically using? Can you please link it here?

William.wei said:

for problem 2, what should i do to collect more information if you need it?

Does the connection work if you run any other sample? Please share log output.

Which AP model is this?

 

Kind regards,

Håkon

[William.wei]

Thanks Hakon,

for problem 1:

it is ncs3.0.0.

i was testing mqtt with 7002ek,

      v3.0.0\nrf\samples\net\mqtt----problem.

however, there is no such problem in scan and shell.

      v3.0.0\nrf\samples\wifi\shell----ok

      v3.0.0\nrf\samples\wifi\scan----ok

i think you can reproduce this.100% percent you can reproduce this problem.

for problem 2:

i will try other routers.

Regards,

William.

[Håkon Alseth]

Hi,

 

I believe the issue you are seeing with the log is because the wifi thread is scanning and actively trying to connect, and thus blocking the log thread from running.

 

By adding CONFIG_LOG_MODE_IMMEDIATE=y to the prj.conf file, you can see that the application is effectively blocked due to this scan/connect procedure:

*** Booting nRF Connect SDK v3.0.2-89ba1294ac9b ***
*** Using Zephyr OS v4.0.99-f791c49f492c ***
[00:00:00.572,845] <inf> network: Bringing network interface up and connecting to the network
Connected
[00:00:15.063,323] <inf> network: Network connectivity established
[00:00:22.544,250] <inf> transport: Connected to MQTT broker
[00:00:22.553,375] <inf> transport: Hostname: test.mosquitto.org
[00:00:22.561,950] <inf> transport: Client ID: F4CE3600832D
[00:00:22.570,098] <inf> transport: Port: 1883
[00:00:22.577,117] <inf> transport: TLS: No

 

Kind regards,

Håkon

[William.wei]

hi Hakon，

i don't think it is related to this config: CONFIG_LOG_MODE_IMMEDIATE=y

1.

scan and connect wouldn't cost so much time, normally4-5 seconds, but you see it costs 15 seconds in your log.

"Network connectivity established" costs 15 seconds, is because there is 8 to 9 seconds we blocked somewhere, we can see the current is 15uA.

to prove my point of view, i change this config in boards/nrf7002dk_nrf5340_cpuapp_ns.conf

CONFIG_WIFI_NM_WPA_SUPPLICANT_LOG_LEVEL_DBG=y

# CONFIG_WIFI_NM_WPA_SUPPLICANT_LOG_LEVEL_ERR=y

and i can't see any log here

2. 

for another demo SHELL. connect to network costs 8 seconds.

here is the log from shell:

from "[11:05:56.514]wifi connect -s Nordic_ASUS -k 1 -p Nordic20201908"

to "11:06:04.785 Connected", it costs only 8 seconds.

11:05:53.355] [00:00:00.448,730] <inf> wifi_nrf: Configuring SLEEP CTRL GPIO control register
[11:05:53.355] 
[11:05:53.355] uart:~$ *** Booting nRF Connect SDK v3.0.0-3bfc46578e42 ***
[11:05:53.365] uart:~$ *** Using Zephyr OS v4.0.99-3e0ce7636fa6 ***
[11:05:53.375] uart:~$ Starting nrf7002dk with CPU frequency: 128 MHz
[11:05:53.375] uart:~$ [00:00:00.593,139] <inf> net_config: Initializing network
[11:05:53.385] uart:~$ [00:00:00.593,139] <inf> net_config: Waiting interface 1 (0x2000d2d0) to be up...
[11:05:53.396] uart:~$ [00:00:00.593,719] <inf> wifi_supplicant: wpa_supplicant initialized
[11:05:53.404] uart:~$ uart:~$ 
[11:05:56.514] wifi connect -s Nordic_ASUS -k 1 -p Nordic20201908

[11:05:56.520] wifi connect -s Nordic_ASUS -k 1 -p Nordic20201908
[11:05:56.520] 
[11:06:00.477] Connection requested
[11:06:00.477] uart:~$ 
[11:06:04.785] Connected
[11:06:04.785] uart:~$ [00:00:12.477,600] <inf> wpa_supp: wlan0: SME: Trying to authenticate with 04:42:1a:a2:fc:74 (SSID='Nordic_ASUS' freq=5745 MHz)
[11:06:04.814] uart:~$ [00:00:12.843,048] <inf> wpa_supp: wlan0: Trying to associate with 04:42:1a:a2:fc:74 (SSID='Nordic_ASUS' freq=5745 MHz)
[11:06:04.824] uart:~$ [00:00:12.855,102] <inf> net_config: Interface 1 (0x2000d2d0) coming up
[11:06:04.834] uart:~$ [00:00:12.858,978] <inf> net_config: IPv4 address: 192.168.50.98
[11:06:04.844] uart:~$ [00:00:12.859,008] <inf> net_config: Running dhcpv4 client...
[11:06:04.854] uart:~$ [00:00:12.861,572] <inf> wpa_supp: wlan0: Associated with 04:42:1a:a2:fc:74
[11:06:04.864] uart:~$ [00:00:12.862,274] <inf> wpa_supp: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
[11:06:04.874] uart:~$ [00:00:12.882,171] <inf> wpa_supp: wlan0: WPA: Key negotiation completed with 04:42:1a:a2:fc:74 [PTK=CCMP GTK=CCMP]
[11:06:04.885] uart:~$ [00:00:12.882,385] <inf> wpa_supp: wlan0: CTRL-EVENT-CONNECTED - Connection to 04:42:1a:a2:fc:74 completed [id=0 id_str=]
[11:06:04.894] uart:~$ [00:00:12.895,812] <inf> net_dhcpv4: Received: 192.168.50.29
[11:06:04.904] uart:~$ [00:00:12.895,904] <inf> net_config: IPv4 address: 192.168.50.29
[11:06:04.912] uart:~$ [00:00:12.895,904] <inf> net_config: Lease time: 86400 seconds
[11:06:04.924] uart:~$ [00:00:12.895,935] <inf> net_config: Subnet: 255.255.255.0
[11:06:04.935] uart:~$ [00:00:12.895,935] <inf> net_config: Router: 192.168.50.1
[11:06:04.942] uart:~$ uart:~$ uart:~$ 

3.for another demo scan:

scan costs only4.6 seconds, and there is no block before scan:

in other words, did find that mqtt demo is quite slow in wifi connection?

Regards,

William.

[William.wei]

hi hakon,

how can we prove this 8 to 9 seconds is scaning?

which config can we added to see the log? between this gap"

Regards,

William.