search

linux4wilc / driver

DEPRECATED: Updated Linux drivers for the ATWILC1000/ATWILC3000 products are located at https://github.com/linux4microchip/linux/tree/master/drivers/net/wireless/microchip/wilc1000. To simplify development, the legacy Linux4WILC was merged into the Linux4Microchip repo where driver development continues (Please refer latest ATWILC1000/ATWILC 3000 Wi-Fi Link Controller Linux User Guide) Driver code for Microchip ATWILC Wireless Devices (ATWILC1000 & ATWILC3000)
https://www.microchip.com/wwwproducts/en/ATWILC1000
32 stars 19 forks source link

Network crashes while sending large file over wifi #110

Open mmader87 opened 3 years ago

mmader87 commented 3 years ago

Using WILC1000 with WILC Firmware Ver = WILC_WIFI_FW_REL_15_3_1 Build: 11736 on custom built Yocto linux.

While attempting to send a 150MB from a PC to a device with the WILC1000, the transfer stops midway because the network device appears to crash. After the network crashes on the device, the device can no longer ping anything else on the network or access any other external address. However, wpa_supplicant and ifconfig are still showing that the device is connected but no network traffic appears to be getting through.

I am looking for help as to how to debug this issue. This issue is very repeatable on my setup. Below is a log of the WILC1000 driver output. Please let me know what additional information may be needed.

root:~# dmesg | grep WILC_SPI [ 3.653140] WILC_SPI spi1.0: spiModalias: wilc1000, spiMax-Speed: 24000000 [ 3.740909] WILC_SPI spi1.0: succesfully got gpio_reset [ 3.754432] WILC_SPI spi1.0: succesfully got gpio_chip_en [ 3.774286] WILC_SPI spi1.0: succesfully got gpio_reset [ 3.824573] WILC_SPI spi1.0: succesfully got gpio_chip_en [ 3.847149] WILC_SPI spi1.0: WILC SPI probe success [ 5.220185] WILC_SPI spi1.0 wlan0: INFO [wilc_mac_open]MAC OPEN[(ptrval)] wlan0 [ 5.239106] WILC_SPI spi1.0 wlan0: INFO [wilc_init_host_int]Host[(ptrval)][(ptrval)] [ 5.249810] WILC_SPI spi1.0 wlan0: INFO [wilc_mac_open] re-init [ 5.260421] WILC_SPI spi1.0 wlan0: INFO [wilc_wlan_init]Initializing WILC_Wlan [ 5.268264] WILC_SPI spi1.0 wlan0: INFO [wilc_wlan_initialize]WILC Initialization done [ 5.268271] WILC_SPI spi1.0 wlan0: INFO [wlan_initialize_threads]Initializing Threads ... [ 5.268274] WILC_SPI spi1.0 wlan0: INFO [wlan_initialize_threads]Creating kthread for transmission [ 5.297789] WILC_SPI spi1.0 wlan0: INFO [wlan_initialize_threads]Creating kthread for Debugging [ 5.300498] WILC_SPI spi1.0: got gpio_irq successfully [ 5.312597] WILC_SPI spi1.0 wlan0: INFO [init_irq]IRQ request succeeded IRQ-NUM= 176 [ 5.323312] WILC_SPI spi1.0 wlan0: INFO [wilc_wlan_get_firmware]Detect chip WILC1000 [ 5.336397] WILC_SPI spi1.0 wlan0: INFO [wilc_wlan_get_firmware]loading firmware mchp/wilc1000_wifi_firmware.bin [ 5.352430] WILC_SPI spi1.0 wlan0: INFO [wilc_wlan_get_firmware]WLAN firmware: mchp/wilc1000_wifi_firmware.bin [ 5.365694] WILC_SPI spi1.0 wlan0: INFO [wilc_firmware_download]Downloading Firmware ... [ 5.499365] WILC_SPI spi1.0 wlan0: INFO [wilc_firmware_download]Download Succeeded [ 5.512407] WILC_SPI spi1.0 wlan0: INFO [wilc_start_firmware]Starting Firmware ... [ 5.520675] WILC_SPI spi1.0 wlan0: INFO [wilc_start_firmware]Waiting for FW to get ready ... [ 5.614085] WILC_SPI spi1.0 wlan0: INFO [wilc_start_firmware]Firmware successfully started [ 5.636311] WILC_SPI spi1.0 wlan0: INFO [wilc_wlan_initialize]WILC Firmware Ver = WILC_WIFI_FW_REL_15_3_1 Build: 11736 [ 5.647023] WILC_SPI spi1.0 wlan0: INFO [wilc_init_fw_config]Start configuring Firmware [ 5.777681] WILC_SPI spi1.0 wlan0: INFO [wilc_mac_open]Mac address: f8:f0:05:76:c2:6c [ 5.785544] WILC_SPI spi1.0 wlan0: INFO [wilc_set_multicast_list]Setting mcast List with count = 1.

[ 5.808474] WILC_SPI spi1.0 wlan0: INFO [wilc_set_multicast_list]Setting mcast List with count = 2.

[ 5.840507] WILC_SPI spi1.0 wlan0: INFO [set_power_mgmt]dev [wlan0] [ 5.846838] WILC_SPI spi1.0 wlan0: INFO [set_power_mgmt] Power save Enabled= 1 , TimeOut = -1 [ 5.876543] WILC_SPI spi1.0 wlan0: INFO [wilc_set_multicast_list]Setting mcast List with count = 3.

[ 5.920386] WILC_SPI spi1.0 wlan0: INFO [wilc_set_multicast_list]Setting mcast List with count = 4.

[ 5.968454] WILC_SPI spi1.0 wlan0: INFO [wilc_set_multicast_list]Setting mcast List with count = 5.

[ 6.036470] WILC_SPI spi1.0 wlan0: INFO [wilc_set_multicast_list]Setting mcast List with count = 6.

[ 6.146008] WILC_SPI spi1.0 wlan0: INFO [wilc_set_multicast_list]Setting mcast List with count = 6.

[ 6.279650] WILC_SPI spi1.0 p2p0: INFO [get_tx_power]Got tx power 18 [ 6.306965] WILC_SPI spi1.0 p2p0: INFO [get_tx_power]Got tx power 18 [ 6.317231] WILC_SPI spi1.0 p2p0: INFO [wilc_mac_open]MAC OPEN[(ptrval)] p2p0 [ 6.325108] WILC_SPI spi1.0 p2p0: INFO [wilc_init_host_int]Host[(ptrval)][(ptrval)] [ 6.338163] WILC_SPI spi1.0 p2p0: INFO [wilc_mac_open] re-init [ 6.352369] WILC_SPI spi1.0 p2p0: WRN [wilc_wlan_initialize: 987]wilc already initialized [ 6.415204] WILC_SPI spi1.0 p2p0: INFO [wilc_mac_open]Mac address: fa:f0:05:76:c2:6c [ 6.422976] WILC_SPI spi1.0 p2p0: INFO [wilc_set_multicast_list]Setting mcast List with count = 1.

[ 6.463601] WILC_SPI spi1.0 p2p0: INFO [wilc_set_multicast_list]Setting mcast List with count = 2.

[ 6.496661] WILC_SPI spi1.0 p2p0: INFO [set_power_mgmt]dev [p2p0] [ 6.502803] WILC_SPI spi1.0 p2p0: INFO [set_power_mgmt] Power save Enabled= 1 , TimeOut = -1 [ 6.537387] WILC_SPI spi1.0 p2p0: INFO [wilc_set_multicast_list]Setting mcast List with count = 3.

[ 6.584394] WILC_SPI spi1.0 p2p0: INFO [wilc_set_multicast_list]Setting mcast List with count = 4.

[ 6.650822] WILC_SPI spi1.0 wlan0: INFO [get_tx_power]Got tx power 18 [ 6.660566] WILC_SPI spi1.0 p2p0: INFO [wilc_set_multicast_list]Setting mcast List with count = 5.

[ 6.735990] WILC_SPI spi1.0 wlan0: INFO [get_tx_power]Got tx power 18 [ 6.743363] WILC_SPI spi1.0 p2p0: INFO [wilc_set_multicast_list]Setting mcast List with count = 6.

[ 6.834969] WILC_SPI spi1.0 wlan0: INFO [get_tx_power]Got tx power 18 [ 6.858333] WILC_SPI spi1.0 wlan0: INFO [get_tx_power]Got tx power 18 [ 7.079011] WILC_SPI spi1.0 wlan0: INFO [wilc_set_multicast_list]Setting mcast List with count = 7.

[ 7.215756] WILC_SPI spi1.0 wlan0: INFO [get_tx_power]Got tx power 18 [ 7.222662] WILC_SPI spi1.0 wlan0: INFO [wilc_set_multicast_list]Setting mcast List with count = 6.

[ 7.308877] WILC_SPI spi1.0 wlan0: INFO [flush_pmksa]Flushing PMKID key values [ 7.336502] WILC_SPI spi1.0 p2p0: INFO [get_tx_power]Got tx power 18 [ 7.356196] WILC_SPI spi1.0 p2p0: INFO [get_tx_power]Got tx power 18 [ 7.373174] WILC_SPI spi1.0 p2p0: INFO [get_tx_power]Got tx power 18 [ 7.389893] WILC_SPI spi1.0 p2p0: INFO [get_tx_power]Got tx power 18 [ 7.659137] WILC_SPI spi1.0 p2p0: INFO [get_tx_power]Got tx power 18 [ 7.696705] WILC_SPI spi1.0 p2p0: INFO [flush_pmksa]Flushing PMKID key values [ 7.705570] WILC_SPI spi1.0 wlan0: INFO [scan]Requested num of channel 14 [ 7.716357] WILC_SPI spi1.0 wlan0: INFO [scan]Scan Request IE len = 135 [ 7.723105] WILC_SPI spi1.0 wlan0: INFO [scan]Number of SSIDs 1 [ 7.729067] WILC_SPI spi1.0 wlan0: INFO [scan]Trigger Scan Request [ 8.343517] WILC_SPI spi1.0 wlan0: INFO [wilc_scan_complete_received]Scan notification received [ 8.353159] WILC_SPI spi1.0 wlan0: INFO [cfg_scan_result]Scan Done[00000000b8d00869] [ 8.866934] WILC_SPI spi1.0 wlan0: INFO [connect]Connecting to SSID [MiddleEarth] on netdev [00000000b8d00869] host if [7bf61c00] [ 8.884361] WILC_SPI spi1.0 wlan0: INFO [connect]Adding key with cipher group fac04 [ 8.892045] WILC_SPI spi1.0 wlan0: INFO [connect]Authentication Type = 0 [ 8.898768] WILC_SPI spi1.0 wlan0: INFO [connect]In OPEN SYSTEM [ 8.904779] WILC_SPI spi1.0 wlan0: INFO [wilc_wlan_set_bssid]set bssid [98:de:d0:9a:dd:2b] [ 8.913079] WILC_SPI spi1.0 wlan0: INFO [wilc_send_connect_wid]send HOST_IF_WAITING_CONN_RESP [ 8.997078] WILC_SPI spi1.0 wlan0: INFO [wilc_send_connect_wid]set HOST_IF_WAITING_CONN_RESP [ 9.316842] WILC_SPI spi1.0 wlan0: INFO [handle_rcvd_gnrl_async_info]Current State = 3,Received state = 1 [ 9.334850] WILC_SPI spi1.0 wlan0: INFO [cfg_connect_result]Connection response received=1 connect_stat[0] [ 9.348347] WILC_SPI spi1.0 wlan0: INFO [cfg_connect_result]Connection Successful: BSSID: 98ded09add2b [ 9.357791] WILC_SPI spi1.0 wlan0: INFO [cfg_connect_result]Association request info elements length = 27 [ 9.372351] WILC_SPI spi1.0 wlan0: INFO [cfg_connect_result]Association response info elements length = 170 [ 9.404823] WILC_SPI spi1.0 wlan0: INFO [add_key]Adding key with cipher suite = fac04 [ 9.412764] WILC_SPI spi1.0 wlan0: INFO [add_key]7d152300 7aa38000 0 [ 9.424358] WILC_SPI spi1.0 wlan0: INFO [add_key]key b9 96 1d [ 9.484298] WILC_SPI spi1.0 wlan0: INFO [add_key]Adding key with cipher suite = fac04 [ 9.492152] WILC_SPI spi1.0 wlan0: INFO [add_key]7d152300 7aa38000 1 [ 9.504355] WILC_SPI spi1.0 wlan0: INFO [add_key]key 16 c3 e6 [ 9.545564] WILC_SPI spi1.0 wlan0: INFO [wilc_set_multicast_list]Setting mcast List with count = 7.

[ 9.661680] WILC_SPI spi1.0 wlan0: INFO [wilc_set_multicast_list]Setting mcast List with count = 8.

root:~# ifconfig lo Link encap:Local Loopback inet addr:127.0.0.1 Mask:255.0.0.0 inet6 addr: ::1/128 Scope:Host UP LOOPBACK RUNNING MTU:65536 Metric:1 RX packets:100 errors:0 dropped:0 overruns:0 frame:0 TX packets:100 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:1000 RX bytes:9158 (8.9 KiB) TX bytes:9158 (8.9 KiB)

p2p0 Link encap:Ethernet HWaddr fa:f0:05:76:c2:6c inet6 addr: fe80::f8f0:5ff:fe76:c26c/64 Scope:Link UP BROADCAST MULTICAST MTU:1500 Metric:1 RX packets:0 errors:0 dropped:0 overruns:0 frame:0 TX packets:17 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:1000 RX bytes:0 (0.0 B) TX bytes:1569 (1.5 KiB)

wlan0 Link encap:Ethernet HWaddr f8:f0:05:76:c2:6c inet addr:192.168.0.115 Bcast:192.168.0.255 Mask:255.255.255.0 inet6 addr: fe80::faf0:5ff:fe76:c26c/64 Scope:Link UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1 RX packets:34974 errors:0 dropped:0 overruns:0 frame:0 TX packets:17785 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:1000 RX bytes:51602732 (49.2 MiB) TX bytes:1049870 (1.0 MiB)

mmader87 commented 3 years ago

While debugging this issue farther, I received the following error while sending said large file:

[ 324.342911] spi_master spi1: I/O Error in DMA RX [ 324.347575] WILC_SPI spi1.0: SPI transfer failed: -110 [ 324.352782] spi_master spi1: failed to transfer one message from queue [ 324.359355] WILC_SPI spi1.0: SPI transaction failed [ 324.364261] WILC_SPI spi1.0: Failed block read, bus err [ 324.369520] WILC_SPI spi1.0: Failed cmd, read block (00000000)... [ 324.376817] WILC_SPI spi1.0: Reset and retry 10 0 10808 [ 324.391742] get_if_handler Invalid handle [ 324.395769] wilc_wlan_handle_rx_buff: wilc_netdev in wilc is NULL

After receiving these error outputs, the network crashed as described above.