kernel NULL pointer at wilc_wlan_txq_remove_from_head+0x58/0xd4 #76
Description
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）