driver kernel NULL pointer at wilc_wlan_txq_remove_from

kernel NULL pointer at wilc_wlan_txq_remove_from_head+0x58/0xd4， which cause hang while doing iper3.

I use WILC1000-SD wifi module insert to NK-NUC980 EVK Board SD1 slot(新唐) uesing this github driver.

Start WILC1000-SD wifi（STATION mode） log： ~ # sh /nvm/wifi.sh Successfully initialized wpa_supplicant [ 78.980599] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_mgmt_frame_register]Return since mac is closed [ 78.992274] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_mgmt_frame_register]Return since mac is closed [ 79.003549] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_mgmt_frame_register]Return since mac is closed [ 79.013166] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_mgmt_frame_register]Return since mac is closed [ 79.024233] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_mgmt_frame_register]Return since mac is closed [ 79.033816] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_mgmt_frame_register]Return since mac is closed [ 79.044883] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_mgmt_frame_register]Return since mac is closed rfkill: Cannot o[ 79.056658] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_mac_open]MAC OPEN[c399a000] wlan0 pen RFKILL control device [ 79.066908] WILC POWER UP [ 79.070474] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_init_host_int]Host[c399a000][c399b428] [ 79.078724] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_mac_open]*** re-init *** [ 79.087874] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_wlan_init]Initializing WILC_Wlan [ 79.095749] wilc_sdio mmc0:0001:1: SDIO speed: 20000000 [ 79.103074] wilc_sdio mmc0:0001:1: chipid 001003a0 [ 79.109108] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_wlan_initialize]WILC Initialization done [ 79.119141] wilc_sdio mmc0:0001:1 wlan0: INFO [wlan_initialize_threads]Initializing Threads ... [ 79.127974] wilc_sdio mmc0:0001:1 wlan0: INFO [wlan_initialize_threads]Creating kthread for transmission [ 79.139491] wilc_sdio mmc0:0001:1 wlan0: INFO [wlan_initialize_threads]Creating kthread for Debugging [ 79.149049] wilc_sdio mmc0:0001:1: failed to get IRQ GPIO, load default [ 79.157458] wilc_sdio mmc0:0001:1 wlan0: INFO [init_irq]IRQ request succeeded IRQ-NUM= 347 [ 79.166266] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_wlan_get_firmware]Detect chip WILC1000 [ 79.176366] wilc_handle_isr,>> UNKNOWN_INTERRUPT - 0x00000000 [ 79.182449] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_wlan_get_firmware]loading firmware mchp/wilc1000_wifi_firmware.bin [ 79.194758] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_wlan_get_firmware]WLAN firmware: mchp/wilc1000_wifi_firmware.bin [ 79.207416] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_firmware_download]Downloading Firmware ... [ 79.217708] wilc_wlan_firmware_downloadDownloading firmware size = 135060 [ 79.246708] wilc_wlan_firmware_download Offset = 119744 [ 79.254924] wilc_wlan_firmware_download Offset = 135060 [ 79.261724] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_firmware_download]Download Succeeded [ 79.270049] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_start_firmware]Starting Firmware ... [ 79.278949] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_start_firmware]Waiting for FW to get ready ... [ 79.363808] cfg_indicate_rx: Info message received [ 79.368799] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_start_firmware]Firmware successfully started [ 79.387866] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_wlan_initialize]WILC Firmware Ver = WILC_WIFI_FW_REL_15_2_1 Build: 11257 [ 79.400216] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_init_fw_config]Start configuring Firmware [ 79.503424] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_mac_open]Mac address: fa:f0:05:9a:88:b6 [ 79.524933] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_set_multicast_list]Setting mcast List with count = 0. [ 79.534616] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_set_multicast_list]Enable mcast filter retrive directed pkts only [ 79.548408] wilc_sdio mmc0:0001:1 wlan0: INFO [set_power_mgmt]dev [wlan0] [ 79.555333] wilc_sdio mmc0:0001:1 wlan0: INFO [set_power_mgmt] Power save Enabled= 0 , TimeOut = -1 [ 79.580524] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_set_multicast_list]Setting mcast List with count = 1. [ 79.590208] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_set_multicast_list]Entry[0]: 01:00:5e:00:00:01 [ 79.641583] wilc_sdio mmc0:0001:1 wlan0: INFO [flush_pmksa]Flushing PMKID key values [ 79.656558] random: wpa_supplicant: uninitialized urandom read (32 bytes read, 125 bits of entropy available) Selected interface 'wlan0' [ 81.994874] wilc_sdio mmc0:0001:1 wlan0: INFO [scan]Requested num of channel 14 OK [ 82.010749] wilc_sdio mmc0:0001:1 wlan0: INFO [scan]Scan Request IE len = 0 [ 82.017783] wilc_sdio mmc0:0001:1 wlan0: INFO [scan]Number of SSIDs 1 [ 82.039499] wilc_sdio mmc0:0001:1 wlan0: INFO [scan]Trigger Scan Request Selected interface 'wlan0' bssid / frequency / signal level / flags / ssid Selected interface 'wlan0' OK Selected interface 'wlan0' 0 Selected interface 'wlan0' OK Selected interface 'wlan0' OK [ 82.251866] random: nonblocking pool is initialized Selected interface 'wlan0' [ 82.652441] cfg_indicate_rx: Scan Notification Received [ 82.657674] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_scan_complete_received]Scan notification received [ 82.668158] wilc_sdio mmc0:0001:1 wlan0: INFO [cfg_scan_result]Scan Done[c399a000] OK wlan0: CTRL-EVENT-REGDOM-CHANGE init=BEACON_HINT type=UNKNOWN Selected interface 'wlan0' wlan0: Trying to associate with 34:fa:40:0c:53:48 (SSID='Robustel-308' freq=2437 MHz) OK [ 83.108533] wilc_sdio mmc0:0001:1 wlan0: INFO [connect]Connecting to SSID [Robustel-308] on netdev [c399a000] host if [c2544a00] [ 83.120308] wilc_sdio mmc0:0001:1 wlan0: INFO [connect]Adding key with cipher group fac02 [ 83.128449] wilc_sdio mmc0:0001:1 wlan0: INFO [connect]Authentication Type = 0 [ 83.137774] wilc_sdio mmc0:0001:1 wlan0: INFO [connect]In OPEN SYSTEM [ 83.144391] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_wlan_set_bssid]set bssid [34:fa:40:0c:53:48] [ 83.154783] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_send_connect_wid]send HOST_IF_WAITING_CONN_RESP [ 83.231099] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_send_connect_wid]set HOST_IF_WAITING_CONN_RESP [ 83.552708] cfg_indicate_rx: Info message received [ 83.557733] wilc_sdio mmc0:0001:1 wlan0: INFO [handle_rcvd_gnrl_async_info]Current State = 3,Received state = 1 [ 83.578724] wilc_sdio mmc0:0001:1 wlan0: INFO [cfg_connect_result]Connection response received=1 connect_stat[0] [ 83.589041] wilc_sdio mmc0:0001:1 wlan0: INFO [cfg_connect_result]Connection Successful: BSSID: 34fa40c5348 [ 83.600499] wilc_sdio mmc0:0001:1 wlan0: INFO [cfg_connect_result]Association request info elements length = 22 [ 83.610799] wilc_sdio mmc0:0001:1 wlan0: INFO [cfg_connect_result]Association response info elements length = 104 wlan0: Associated with 34:fa:40:0c:53:48 wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 [ 83.655274] NOHZ: local_softirq_pending 08 [ 83.664441] wilc_sdio mmc0:0001:1 wlan0: INFO [add_key]Adding key with cipher suite = fac04 [ 83.673024] wilc_sdio mmc0:0001:1 wlan0: INFO [add_key]c2479160 c399a000 0 [ 83.681824] wilc_sdio mmc0:0001:1 wlan0: INFO [add_key]key c0 87 f9 [ 83.732458] wilc_sdio mmc0:0001:1 wlan0: INFO [add_key]Adding key with cipher suite = fac02 [ 83.741049] wilc_sdio mmc0:0001:1 wlan0: INFO [add_key]c2479160 c399a000 2 [ 83.747899] wilc_sdio mmc0:0001:1 wlan0: INFO [add_key]key 1b 4f d3 wlan0: WPA: Key negotiation completed with 34:fa:40:0c:53:48 [PTK=CCMP GTK=TKIP] wlan0: CTRL-EVENT-CONNECTED - Connection to 34:fa:40:0c:53:48 completed [id=0 id_str=] [ 84.062641] NOHZ: local_softirq_pending 08 [ 84.226608] NOHZ: local_softirq_pending 08 udhcpc (v1.22.1) started Sending discover... [ 85.067883] NOHZ: local_softirq_pending 08 [ 85.866058] NOHZ: local_softirq_pending 08 [ 86.030041] NOHZ: local_softirq_pending 08 [ 87.177699] NOHZ: local_softirq_pending 08 [ 87.341633] NOHZ: local_softirq_pending 08 [ 87.837324] NOHZ: local_softirq_pending 08 [ 88.002783] NOHZ: local_softirq_pending 08 Sending discover... Sending select for 192.168.0.47... Lease of 192.168.0.47 obtained, lease time 7200 [ 88.228074] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_set_multicast_list]Setting mcast List with count = 1. [ 88.237758] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_set_multicast_list]Entry[0]: 01:00:5e:00:00:01 [ 88.250224] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_set_multicast_list]Setting mcast List with count = 1. [ 88.259908] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_set_multicast_list]Entry[0]: 01:00:5e:00:00:01 ~ #

Start iper3 test log： ~ # /nvm/iperf3 -c 192.168.0.100 -p 5201 Connecting to host 192.168.0.100, port 5201 [ 4] local 192.168.0.47 port 55910 connected to 192.168.0.100 port 5201 [ 990.260024] wilc_handle_isr,>> UNKNOWN_INTERRUPT - 0x00000053 [ 990.267833] wilc_handle_isr,>> UNKNOWN_INTERRUPT - 0x00000053 [ ID] Interval Transfer Bandwidth Retr Cwnd [ 4] 0.00-1.00 sec 80.6 KBytes 660 Kbits/sec 9 9.90 KBytes
[ 4] 1.00-2.00 sec 77.8 KBytes 637 Kbits/sec 2 9.90 KBytes
[ 992.511083] wilc_handle_isr,>> UNKNOWN_INTERRUPT - 0x00000036 [ 992.518699] wilc_handle_isr,>> UNKNOWN_INTERRUPT - 0x00000036 [ 4] 2.00-3.00 sec 106 KBytes 869 Kbits/sec 3 8.48 KBytes
[ 4] 3.00-4.00 sec 123 KBytes 1.01 Mbits/sec 4 12.7 KBytes
[ 994.523258] wilc_handle_isr,>> UNKNOWN_INTERRUPT - 0x00000051 [ 994.780949] Unable to handle kernel NULL pointer dereference at virtual address 00000004 [ 994.788999] pgd = c0004000 [ 994.791674] [00000004] *pgd=00000000 [ 994.795249] Internal error: Oops: 17 [#1] PREEMPT ARM [ 994.800258] Modules linked in: [ 994.803308] CPU: 0 PID: 2797 Comm: K_TXQ_TASK Not tainted 4.4.179 #23 [ 994.809708] Hardware name: Nuvoton NUC980 (Device Tree) [ 994.814908] task: c264c740 ti: c25ee000 task.ti: c25ee000 [ 994.820316] PC is at wilc_wlan_txq_remove_from_head+0x58/0xd4 [ 994.826016] LR is at wilc_wlan_handle_txq+0xbc4/0xe98 [ 994.831041] pc : [] lr : [] psr: 00000093 [ 994.831041] sp : c25efd38 ip : 80000013 fp : c25efd4c [ 994.842466] r10: 00000001 r9 : 0000060c r8 : c2479458 [ 994.847666] r7 : 00000004 r6 : 0000060c r5 : 00000100 r4 : 00000200 [ 994.854166] r3 : 00000000 r2 : c247ca00 r1 : c247c310 r0 : c24793a0 [ 994.860666] Flags: nzcv IRQs off FIQs on Mode SVC_32 ISA ARM Segment kernel [ 994.868033] Control: 0005317f Table: 0255c000 DAC: 00000057 [ 994.873758] Process K_TXQ_TASK (pid: 2797, stack limit = 0xc25ee190) [ 994.880083] Stack: (0xc25efd38 to 0xc25f0000) [ 994.884424] fd20: c04e96b8 000000fd [ 994.892583] fd40: c25eff1c c25efd50 c0312048 c030f98c c0c8b6a8 c0c8b6b8 00000000 c2479440 [ 994.900733] fd60: c26a0000 c25eff34 c2479a90 c24793a0 00000003 c2479b50 c399a4b4 c25efdb0 [ 994.908874] fd80: 00000037 c399a440 3f745dbe 02f5060c 00000002 06000606 01010101 00010000 [ 994.917024] fda0: 00000000 00000000 00000000 00000000 c25efd02 c25efdc0 c0042e5c c0042d60 [ 994.925174] fdc0: c0043390 c0c8a208 c264c740 c0c8a208 c0c8a208 c264c740 c25efe0c c25efde8 [ 994.933316] fde0: c003a694 c000b330 c0cc3468 00000002 00000183 00000000 00000000 00000002 [ 994.941466] fe00: c25efe34 c25efe10 c003a9f8 c0053400 00000000 00000000 c264c740 c0c84e58 [ 994.949616] fe20: c0c8a208 c25d8600 c25efe64 c25efe38 c0499390 c003e0ac 00000001 c25ee000 [ 994.957758] fe40: 00000000 00000000 00000000 c247947c c24793d0 c24793c8 c25efe7c c25efe68 [ 994.965908] fe60: c04996c8 c04991f0 7fffffff 00000002 c25efec4 c25efe80 c049c728 c0499680 [ 994.974049] fe80: c264c740 c264dd00 c0c8a208 c2661780 c25efecc c25efea0 c0499390 c003e0ac [ 994.982199] fea0: c25ee000 00000002 00000000 00000000 c247947c c24793d0 c25eff0c c25efec8 [ 994.990349] fec0: c049a338 c049c5bc c049976c c04991f0 ffffe000 00000001 c264c740 c003f79c [ 994.998491] fee0: 00000100 00000200 c25eff04 c24793a0 c25ee000 c24793a0 c25ee000 c2477f40 [ 995.006641] ff00: 00000000 c0cbcbd8 c24793d0 c24793c8 c25eff64 c25eff20 c0307950 c0311494 [ 995.014783] ff20: c2479488 c247947c c399a000 00000001 c03078b4 00000000 00000000 c2617b20 [ 995.022933] ff40: 00000000 c24793a0 c03078b4 00000000 00000000 00000000 c25effac c25eff68 [ 995.031074] ff60: c0039afc c03078c4 00000000 00000000 00000000 c24793a0 00000000 c25eff7c [ 995.039224] ff80: c25eff7c 00000000 c25eff88 c25eff88 c2617b20 c0039a38 00000000 00000000 [ 995.047374] ffa0: 00000000 c25effb0 c0010018 c0039a48 00000000 00000000 00000000 00000000 [ 995.055516] ffc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 [ 995.063658] ffe0: 00000000 00000000 00000000 00000000 00000013 00000000 00000000 00000000 [ 995.071774] Backtrace: [ 995.074258] [] (wilc_wlan_txq_remove_from_head) from [] (wilc_wlan_handle_txq+0xbc4/0xe98) [ 995.084191] r5:000000fd r4:c04e96b8 [ 995.087783] [] (wilc_wlan_handle_txq) from [] (wilc_txq_task+0x9c/0x250) [ 995.096149] r10:c24793c8 r9:c24793d0 r8:c0cbcbd8 r7:00000000 r6:c2477f40 r5:c25ee000 [ 995.103949] r4:c24793a0 [ 995.106491] [] (wilc_txq_task) from [] (kthread+0xc4/0xe4) [ 995.113658] r10:00000000 r9:00000000 r8:00000000 r7:c03078b4 r6:c24793a0 r5:00000000 [ 995.121449] r4:c2617b20 [ 995.124008] [] (kthread) from [] (ret_from_fork+0x14/0x3c) [ 995.131158] r7:00000000 r6:00000000 r5:c0039a38 r4:c2617b20 [ 995.136816] Code: e1530002 0a00001e e3a04c02 e3a05c01 (e5932004) [ 995.142891] ---[ end trace 009a64cf14a0d9c1 ]--- [ 995.147466] note: K_TXQ_TASK[2797] exited with preempt_count 1 [ 995.155749] cfg_indicate_rx: Receive unknown message 255-52-250-64-12-83-72-52 [ 995.163099] cfg_indicate_rx: Receive unknown message 255-255-255-52-250-64-12-83 [ 995.170549] wilc_wlan_handle_rx_buff: Data corrupted 0, 0 [ 995.176258] wilc_handle_isr,>> UNKNOWN_INTERRUPT - 0x0000003f [ 4] 4.00-5.11 sec 102 KBytes 752 Kbits/sec 5 1.41 KBytes
[ 4] 5.11-6.00 sec 0.00 Bytes 0.00 bits/sec 1 1.41 KBytes
[ 4] 6.00-7.00 sec 0.00 Bytes 0.00 bits/sec 0 1.41 KBytes
[ 4] 7.00-8.00 sec 0.00 Bytes 0.00 bits/sec 0 1.41 KBytes
[ 4] 8.00-9.00 sec 0.00 Bytes 0.00 bits/sec 0 1.41 KBytes
-----to here the iperf3 is hang，except "Ctrl+C"---------------

After "Ctrl+C" log out:

[ ID] Interval Transfer Bandwidth Retr [ 4] 0.00-107.39 sec 240 KBytes 18.3 Kbits/sec 6 sender [ 4] 0.00-107.39 sec 0.00 Bytes 0.00 bits/sec receiver iperf3: interrupt - the client has terminated

My Quentions are: 1、How to deal with kernel NULL pointer？ 2、Why the Bandwidth of iperf3 test is so small？（I have limited the SD_clk to 20MHz, becaue 25MHz ~50MHz is not work well）

Oct 29 '19 06:10 mgkiller7

Hi @mgkiller7 the UNKNOWN_INTERRUPT logs you are getting are very suspicious. I'm getting much better throughput with iperf 2, but I don't suspect that it will differ much if I used iperf 3.

Please report this issue on Microchip's SalesForce