WILC1000 - "Failed to start firmware" on 4.1.15 kernel - SPI interface

[AndreyEroshenko]

Hello, I observed following problem on my iMX6 based system (linux kernel 4.1.15, latest firmware and driver for WILC1000 from dev-branch - as per yesterday 20-Feb-2020). OS is able to initialize wifi module (WILC1000) successfully first time always. But when I try to stop it and re-initialize again it fails quite often - not every time. See log below: .... WILC_SPI spi2.0 mlan0: INFO [wilc_firmware_download]Downloading Firmware ... wilc_wlan_firmware_downloadDownloading firmware size = 135832 wilc_wlan_firmware_download Offset = 120380 wilc_wlan_firmware_download Offset = 135832 WILC_SPI spi2.0 mlan0: INFO [wilc_firmware_download]Download Succeeded WILC_SPI spi2.0 mlan0: INFO [wilc_start_firmware]Starting Firmware ... WILC_SPI spi2.0 mlan0: INFO [wilc_start_firmware]Waiting for FW to get ready ... WILC_SPI spi2.0 mlan0: INFO [wilc_start_firmware]Firmware start timed out WILC_SPI spi2.0 mlan0: ERR [wilc_wlan_initialize:945] Failed to start firmware WILC_SPI spi2.0 mlan0: INFO [wlan_deinitialize_threads]Deinitializing Threads WILC_SPI spi2.0 mlan0: INFO [wlan_deinitialize_threads]Deinit debug Thread ...

Since this behavior is intermittent I updated "wilc_start_firmware()" (in wilc_netdev.c) to retry attempt to start firmware up to 5 times and now it seems that issue is not reproducible. In kernel log I can see that some times it takes up to 4 retries to start firmware successfully.

Please let me know if there is a better solution for this problem.

[AdhamAbozaeid]

Hi Andrey

Somethings you can try is to probe the IRQ line from the WILC board. When the FW starts, it sends an interrupt to the host. If you can see the IRQ line deasserted, but the driver is timing out, then the driver isn't handling it correctly, if IRQ line doesn't change, then the FW wasn't download/started correctly.

Otherwise you can open a salesforce ticket for this issue and the support team can help you. http://microchipsupport.force.com/

[AndreyEroshenko]

Thank you for your response Adham, Yes I confirmed that when driver times out and fails to start firmware - there is no interrupt on IRQ line.

Interesting fact - retry in wilc_start_firmware() does not reload firmware - it writes and reads some registers to just start it. It means that it seems there is some problem with firmware itself - sometime it can fail to start even if it was loaded correctly.

Another observation - with more extensive testing we reproduced another problem. Even if driver managed to start firmware - it can fail configuration: .... WILC_SPI spi2.0 mlan0: INFO [wilc_start_firmware]Waiting for FW to get ready ... cfg_indicate_rx: Info message received WILC_SPI spi2.0 mlan0: INFO [wilc_start_firmware]Firmware successfully started WILC_SPI spi2.0 mlan0: INFO [wilc_wlan_initialize]WILC Firmware Ver = WILC_WIFI_FW_REL_15_3_1 Build: 11736 WILC_SPI spi2.0 mlan0: INFO [wilc_init_fw_config]Start configuring Firmware cfg_set Timed Out WILC_SPI spi2.0 mlan0: ERR [wilc_wlan_initialize:974] Failed to configure firmware WILC_SPI spi2.0 mlan0: INFO [wlan_deinitialize_threads]Deinitializing Threads WILC_SPI spi2.0 mlan0: INFO [wlan_deinitialize_threads]Deinit debug Thread

Add more retries?

[AdhamAbozaeid]

Can you check if disabling powersave makes it more stable? You can do that by disabling it from the supplicant, and do wpa_cli save to make sure it won't start it again on the next init, or you can hack the driver at wilc_set_power_mgmt() to override enabled to be 0 all the time

[AndreyEroshenko]

Thank you! I disabled powersave and device started working much better - it seems that problem with startup is not reproducible anymore.

[xiebluelike]

Hello， I had a similar problem；I try to start an ap scan by wpa_supplicant and wpa_cli；And stop it after get scan result， again and again； sometime I can see log like below（WILC Firmware Ver = WILC_WIFI_FW_REL_15_3_1 Build: 11736）: .... wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_mac_open]MAC OPEN[c38fa000] wlan0 power up request for already powered up source Wifi Device already up. request source is Wifi wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_init_host_int]Host[c38fa000][c38fb3a8] wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_mac_open]*** re-init *** wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_wlan_init]Initializing WILC_Wlan wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_wlan_initialize]WILC Initialization done wilc_sdio mmc0:0001:1 wlan0: INFO [wlan_initialize_threads]Initializing Threads ... wilc_sdio mmc0:0001:1 wlan0: INFO [wlan_initialize_threads]Creating kthread for transmission wilc_sdio mmc0:0001:1 wlan0: INFO [wlan_initialize_threads]Creating kthread for Debugging wilc_sdio mmc0:0001:1: failed to get IRQ GPIO, load default wilc_sdio mmc0:0001:1 wlan0: INFO [init_irq]IRQ request succeeded IRQ-NUM= 271 wilc_handle_isr,>> UNKNOWN_INTERRUPT - 0x0000000e wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_wlan_get_firmware]Detect chip WILC1000 wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_wlan_get_firmware]loading firmware mchp/wilc1000_wifi_firmware.bin wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_wlan_get_firmware]WLAN firmware: mchp/wilc1000_wifi_firmware.bin wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_firmware_download]Downloading Firmware ... wilc_wlan_firmware_downloadDownloading firmware size = 135832 wilc_wlan_firmware_download Offset = 120380 wilc_wlan_firmware_download Offset = 135832 wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_firmware_download]Download Succeeded wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_start_firmware]Starting Firmware ... wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_start_firmware]Waiting for FW to get ready ... wilc_sdio mmc0:0001:1 wlan0: INFO [wilc_start_firmware]Firmware start timed out wilc_sdio mmc0:0001:1 wlan0: ERR [wilc_wlan_initialize:945] Failed to start firmware wilc_sdio mmc0:0001:1: wilc_sdio_disable_interrupt wilc_sdio mmc0:0001:1 wlan0: INFO [wlan_deinitialize_threads]Deinitializing Threads wilc_sdio mmc0:0001:1 wlan0: INFO [wlan_deinitialize_threads]Deinit debug Thread Exit debug thread wilc_sdio mmc0:0001:1 wlan0: INFO [wlan_deinitialize_threads]Deinitializing Threads wilc_sdio mmc0:0001:1 wlan0: ERR [wilc_wlan_initialize:985] WLAN initialization FAILED wilc_sdio mmc0:0001:1 wlan0: ERR [wilc_mac_open:1029] Failed to initialize wilc wilc_sdio mmc0:0001:1 wlan0: ERR [wilc_send_config_pkt:1806] Set Timed out wilc_sdio mmc0:0001:1 wlan0: ERR [wilc_frame_register:2271] Failed to frame register wilc_sdio mmc0:0001:1 wlan0: ERR [wilc_send_config_pkt:1806] Set Timed out wilc_sdio mmc0:0001:1 wlan0: ERR [wilc_frame_register:2271] Failed to frame register wilc_sdio mmc0:0001:1 wlan0: ERR [wilc_send_config_pkt:1806] Set Timed out wilc_sdio mmc0:0001:1 wlan0: ERR [wilc_frame_register:2271] Failed to frame register wilc_sdio mmc0:0001:1 wlan0: ERR [wilc_send_config_pkt:1806] Set Timed out wilc_sdio mmc0:0001:1 wlan0: ERR [wilc_frame_register:2271] Failed to frame register wilc_sdio mmc0:0001:1 wlan0: ERR [wilc_send_config_pkt:1806] Set Timed out wilc_sdio mmc0:0001:1 wlan0: ERR [wilc_frame_register:2271] Failed to frame register wilc_sdio mmc0:0001:1 wlan0: ERR [wilc_send_config_pkt:1806] Set Timed out wilc_sdio mmc0:0001:1 wlan0: ERR [wilc_frame_register:2271] Failed to frame register wilc_sdio mmc0:0001:1 wlan0: ERR [wilc_send_config_pkt:1806] Set Timed out wilc_sdio mmc0:0001:1 wlan0: ERR [wilc_frame_register:2271] Failed to frame register

I also tried to disabled powersave，but the result was the same； Are there any other solutions?