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.