Forums - BMI errors while loading driver module

3 posts / 0 new
Last post
BMI errors while loading driver module
jiangjie
Join Date: 13 Sep 22
Posts: 2
Posted: Tue, 2022-09-13 08:37

Hi all,

I am trying to get an SDIO WIFI module, which has a QCA9377-3, working on my system.

The host system is based on Nvidia AGX Xavier. And the kernel is 5.10.

There are some  failures during the driver initialization, such as

"[   36.338188] +HTCWaitCtrlMessageRecv

[   41.626161] HTCWaitTarget - Exit (-1)
[   41.626199] -HWT

[   41.626274] R0: [insmod][13:03:47.819798]  wlan: [7888:F :VOS] vos_open: Failed to complete BMI phase

"

What does this failure mean?

From the driver source code (CORE/VOSS/src/vos_api.c),

function "HTCWaitTarget" is called after bmi_download_firmware(),

can we assume that the driver FW has been downloaded successfully?

If so, what  prevents the BMI phase to be completed?

Is this failure related to the SDIO communication?

 

Following are parts of dmesg logs while loading the driver module:

===============================================

[  196.010853] wlan: loading out-of-tree module taints kernel.

[  196.104312] wlan: loading driver v4.5.25.57
[  196.104343] AR6000: HIFInit registering
[  196.104561] AR6000: hifDeviceInserted, Function: 0x1, Vendor ID: 0x271, Device ID: 0x701, block size: 0x800/0x200
[  196.104765] hifDeviceInserted: Dumping clocks (50000000,208000000)
[  196.104901] AR6000: +hifEnableFunc
[  196.104986] AR6000: 4-bit ASYNC IRQ mode enabled
[  196.106426] AR6000: start tx_comple task
[  196.106451] AR6000: tx completion task
[  196.106497] AR6000: start async task
[  196.106502] AR6k: call deviceInsertedHandler
.....
[   36.335978] BMI Write Memory: Enter (device: 0xffffffc7760a4000, address: 0x4008c0, length: 4)
[   36.335980] AR6000: device 0xffffffc7760a4000 addr 0x850 buffer 0xffffff8001857178 len 4 req 0x259 context 0x0000000000000000
[   36.335982] AR6000: Execution mode: Synch
[   36.335982] AR6000: hifAllocateBusRequest: 0xffffffc7ca3e4880
[   36.335983] AR6000: queued sync req: 0xFFFFFFC7CA3E4880
[   36.335991] AR6000: async_task processing req: 0xFFFFFFC7CA3E4880
[   36.335999] __HIFReadWrite, addr:0X000850, len:00000004, Read , Sync 
[   36.336009] AR6000: Byte mode (BlockLen: 4)
[   36.336010] AR6000: Address mode: Incremental 0x850
[   36.336012] mmc1: starting CMD53 arg 1410a004 flags 000001b5
[   36.336013] mmc1:     blksz 4 blocks 1 flags 00000200 tsac 1000 ms nsac 0
[   36.336039] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000003
[   36.336057] mmc1: req done (CMD53): 0: 00009000 00000000 00000000 00000000
[   36.336060] mmc1:     4 bytes transferred: 0
[   36.336076] AR6000: readio ret=0 address: 0x850, len: 4, 0x2
[   36.336083] AR6000: async_task upping req: 0xFFFFFFC7CA3E4880
[   36.336091] AR6000: sync return freeing 0xFFFFFFC7CA3E4880: 0x0
[   36.336092] AR6000: freeing req: 0x259
[   36.336094] AR6000: device 0xffffffc7760a4000 addr 0x1000 buffer 0xffffffc7cdc27800 len 16 req 0x25A context 0x0000000000000000
[   36.336095] AR6000: Execution mode: Synch
[   36.336096] AR6000: hifAllocateBusRequest: 0xffffffc7ca3e4880
[   36.336097] AR6000: queued sync req: 0xFFFFFFC7CA3E4880
[   36.336104] AR6000: async_task processing req: 0xFFFFFFC7CA3E4880
[   36.336106] __HIFReadWrite, addr:0X001000, len:00000016, Write, Sync 
[   36.336106] AR6000: Byte mode (BlockLen: 16)
[   36.336107] address:00001000, Length:0x00000010, Dummy:0x0000, Final:0x000017F0
[   36.336108] AR6000: Address mode: Incremental 0x17F0
[   36.336110] mmc1: starting CMD53 arg 942fe010 flags 000001b5
[   36.336112] mmc1:     blksz 16 blocks 1 flags 00000100 tsac 1000 ms nsac 0
[   36.336138] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000003
[   36.336162] mmc1: req done (CMD53): 0: 00009000 00000000 00000000 00000000
[   36.336172] mmc1:     16 bytes transferred: 0
[   36.336191] AR6000: writeio ret=0 address: 0x17F0, len: 16, 0x3
[   36.336192] AR6000: async_task upping req: 0xFFFFFFC7CA3E4880
[   36.336200] AR6000: sync return freeing 0xFFFFFFC7CA3E4880: 0x0
[   36.336201] AR6000: freeing req: 0x25A
[   36.336201] BMI Write Memory: Exit
[   36.336204] +HTCCreate ..  HIF :ffffffc7760a4000 
[   36.336324] AR6000: start rx_comple task
[   36.336328] HIF Interrupt processing is SYNC ONLY
[   36.336331] AR6000: configuration opcode 7 is only used for RTOS systems, not Linux systems
[   36.336333] AR6000: configuration opcode 5 is not used for Linux SDIO stack 
[   36.336335] AR6000: device 0xffffffc7760a4000 addr 0x828 buffer 0xffffffc77602b55c len 4 req 0x25A context 0x0000000000000000
[   36.336336] AR6000: Execution mode: Synch
[   36.336338] AR6000: rx completion task
[   36.336343] AR6000: hifAllocateBusRequest: 0xffffffc7ca3e4880
[   36.336344] AR6000: queued sync req: 0xFFFFFFC7CA3E4880
[   36.336351] AR6000: async_task processing req: 0xFFFFFFC7CA3E4880
[   36.336353] __HIFReadWrite, addr:0X000828, len:00000004, Write, Sync 
[   36.336354] AR6000: Byte mode (BlockLen: 4)
[   36.336355] address:00000828, Length:0x00000004, Dummy:0x0000, Final:0x00000828
[   36.336356] AR6000: Address mode: Incremental 0x828
[   36.336358] mmc1: starting CMD53 arg 94105004 flags 000001b5
[   36.336359] mmc1:     blksz 4 blocks 1 flags 00000100 tsac 1000 ms nsac 0
[   36.336383] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000003
[   36.336411] mmc1: req done (CMD53): 0: 00009000 00000000 00000000 00000000
[   36.336430] mmc1:     4 bytes transferred: 0
[   36.336448] AR6000: writeio ret=0 address: 0x828, len: 4, 0x0
[   36.336450] AR6000: async_task upping req: 0xFFFFFFC7CA3E4880
[   36.336459] AR6000: sync return freeing 0xFFFFFFC7CA3E4880: 0x0
[   36.336460] AR6000: freeing req: 0x25A
[   36.336464] SDIO: Disabling IRQ for mmc1:0001:1...
[   36.336467] mmc1: starting CMD52 arg 00000800 flags 00000195
[   36.336482] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
[   36.336497] mmc1: req done (CMD52): 0: 00009000 00000000 00000000 00000000
[   36.336513] mmc1: starting CMD52 arg 80000800 flags 00000195
[   36.336534] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
[   36.336552] mmc1: req done (CMD52): 0: 00001000 00000000 00000000 00000000
[   36.336578] -HTCCreate (0xffffffc7cd466000) 
[   36.336580] BMI Done: Enter (device: 0xffffffc7760a4000)
[   36.336582] AR6000: device 0xffffffc7760a4000 addr 0x850 buffer 0xffffff8001857178 len 4 req 0x259 context 0x0000000000000000
[   36.336584] AR6000: Execution mode: Synch
[   36.336585] AR6000: hifAllocateBusRequest: 0xffffffc7ca3e4880
[   36.336586] AR6000: queued sync req: 0xFFFFFFC7CA3E4880
[   36.336593] AR6000: async_task processing req: 0xFFFFFFC7CA3E4880
[   36.336595] __HIFReadWrite, addr:0X000850, len:00000004, Read , Sync 
[   36.336597] AR6000: Byte mode (BlockLen: 4)
[   36.336598] AR6000: Address mode: Incremental 0x850
[   36.336599] mmc1: starting CMD53 arg 1410a004 flags 000001b5
[   36.336600] mmc1:     blksz 4 blocks 1 flags 00000200 tsac 1000 ms nsac 0
[   36.336622] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000003
[   36.336643] mmc1: req done (CMD53): 0: 00001000 00000000 00000000 00000000
[   36.336646] mmc1:     4 bytes transferred: 0
[   36.336659] AR6000: readio ret=0 address: 0x850, len: 4, 0x2
[   36.336668] AR6000: async_task upping req: 0xFFFFFFC7CA3E4880
[   36.336683] AR6000: sync return freeing 0xFFFFFFC7CA3E4880: 0x0
[   36.336684] AR6000: freeing req: 0x259
[   36.336686] AR6000: device 0xffffffc7760a4000 addr 0x1000 buffer 0xffffffc7cdc27800 len 4 req 0x25A context 0x0000000000000000
[   36.336688] AR6000: Execution mode: Synch
[   36.336689] AR6000: hifAllocateBusRequest: 0xffffffc7ca3e4880
[   36.336690] AR6000: queued sync req: 0xFFFFFFC7CA3E4880
[   36.336697] AR6000: async_task processing req: 0xFFFFFFC7CA3E4880
[   36.336699] __HIFReadWrite, addr:0X001000, len:00000004, Write, Sync 
[   36.336699] AR6000: Byte mode (BlockLen: 4)
[   36.336700] address:00001000, Length:0x00000004, Dummy:0x0000, Final:0x000017FC
[   36.336701] AR6000: Address mode: Incremental 0x17FC
[   36.336703] mmc1: starting CMD53 arg 942ff804 flags 000001b5
[   36.336704] mmc1:     blksz 4 blocks 1 flags 00000100 tsac 1000 ms nsac 0
[   36.336727] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000003
[   36.336747] mmc1: req done (CMD53): 0: 00001000 00000000 00000000 00000000
[   36.336750] mmc1:     4 bytes transferred: 0
[   36.336765] AR6000: writeio ret=0 address: 0x17FC, len: 4, 0x1
[   36.336766] AR6000: async_task upping req: 0xFFFFFFC7CA3E4880
[   36.336773] AR6000: sync return freeing 0xFFFFFFC7CA3E4880: 0x0
[   36.336774] AR6000: freeing req: 0x25A
[   36.336776] BMI Done: Exit
[   36.336814] R0: [insmod][13:03:42.594685]  wlan: [7888:F :WDA] WMA --> wmi_unified_attach - success
[   36.337260] R0: [insmod][13:03:42.595123]  wlan: [7888:E :SAP] dfs_init_radar_filters[217]: Unknown dfs domain 0 
[   36.337737] HTCWaitTarget - Enter (target:0xffffffc7cd466000) 
[   36.337739] +HWT
[   36.337744] AR6000: device 0xffffffc7760a4000 addr 0x828 buffer 0xffffffc77602b54c len 4 req 0x25A context 0x0000000000000000
[   36.337746] AR6000: Execution mode: Synch
[   36.337748] AR6000: hifAllocateBusRequest: 0xffffffc7ca3e4880
[   36.337749] AR6000: queued sync req: 0xFFFFFFC7CA3E4880
[   36.337766] AR6000: async_task processing req: 0xFFFFFFC7CA3E4880
[   36.337769] __HIFReadWrite, addr:0X000828, len:00000004, Write, Sync 
[   36.337770] AR6000: Byte mode (BlockLen: 4)
[   36.337772] address:00000828, Length:0x00000004, Dummy:0x0000, Final:0x00000828
[   36.337772] AR6000: Address mode: Incremental 0x828
[   36.337776] mmc1: starting CMD53 arg 94105004 flags 000001b5
[   36.337777] mmc1:     blksz 4 blocks 1 flags 00000100 tsac 1000 ms nsac 0
[   36.337810] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000003
[   36.337836] mmc1: req done (CMD53): 0: 00001000 00000000 00000000 00000000
[   36.337846] mmc1:     4 bytes transferred: 0
[   36.337868] AR6000: writeio ret=0 address: 0x828, len: 4, 0x0
[   36.337870] AR6000: async_task upping req: 0xFFFFFFC7CA3E4880
[   36.337881] AR6000: sync return freeing 0xFFFFFFC7CA3E4880: 0x0
[   36.337882] AR6000: freeing req: 0x25A
[   36.337885] SDIO: Disabling IRQ for mmc1:0001:1...
[   36.337887] mmc1: starting CMD52 arg 00000800 flags 00000195
[   36.337907] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
[   36.337930] mmc1: req done (CMD52): 0: 00001000 00000000 00000000 00000000
[   36.337944] mmc1: starting CMD52 arg 80000800 flags 00000195
[   36.337959] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
[   36.337971] mmc1: req done (CMD52): 0: 00001000 00000000 00000000 00000000
[   36.337985] SDIO: Enabling IRQ for mmc1:0001:1...
[   36.337987] mmc1: starting CMD52 arg 00000800 flags 00000195
[   36.338001] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
[   36.338015] mmc1: req done (CMD52): 0: 00001000 00000000 00000000 00000000
[   36.338024] mmc1: starting CMD52 arg 80000803 flags 00000195
[   36.338039] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
[   36.338051] mmc1: req done (CMD52): 0: 00001003 00000000 00000000 00000000
[   36.338067] AR6000: device 0xffffffc7760a4000 addr 0x828 buffer 0xffffffc77602b58c len 4 req 0x25A context 0x0000000000000000
[   36.338068] AR6000: Execution mode: Synch
[   36.338069] AR6000: hifAllocateBusRequest: 0xffffffc7ca3e4880
[   36.338070] AR6000: queued sync req: 0xFFFFFFC7CA3E4880
[   36.338082] AR6000: async_task processing req: 0xFFFFFFC7CA3E4880
[   36.338085] __HIFReadWrite, addr:0X000828, len:00000004, Write, Sync 
[   36.338085] AR6000: Byte mode (BlockLen: 4)
[   36.338087] address:00000828, Length:0x00000004, Dummy:0x0000, Final:0x00000828
[   36.338087] AR6000: Address mode: Incremental 0x828
[   36.338089] mmc1: starting CMD53 arg 94105004 flags 000001b5
[   36.338091] mmc1:     blksz 4 blocks 1 flags 00000100 tsac 1000 ms nsac 0
[   36.338123] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000003
[   36.338146] mmc1: req done (CMD53): 0: 00001000 00000000 00000000 00000000
[   36.338155] mmc1:     4 bytes transferred: 0
[   36.338171] AR6000: writeio ret=0 address: 0x828, len: 4, 0x10303D3
[   36.338172] AR6000: async_task upping req: 0xFFFFFFC7CA3E4880
[   36.338185] AR6000: sync return freeing 0xFFFFFFC7CA3E4880: 0x0
[   36.338186] AR6000: freeing req: 0x25A
[   36.338188] +HTCWaitCtrlMessageRecv
[   41.626161] HTCWaitTarget - Exit (-1)
[   41.626199] -HWT
[   41.626274] R0: [insmod][13:03:47.819798]  wlan: [7888:F :VOS] vos_open: Failed to complete BMI phase
[   41.628133] +HTCDestroy ..  Destroying :0xffffffc7cd466000 
[   41.628185] AR6000: device 0xffffffc7760a4000 addr 0x828 buffer 0

.....

HTCDestroy 
[   41.742541] R0: [VosMCThread][13:03:47.935074]  wlan: [7895:E :VOS] VosMCThread: MC Thread exiting!!!!
[   41.743116] R0: [VosTlshimRxThre][13:03:47.935490]  wlan: [7896:E :VOS] VosTlshimRxThread: Shutting down tl shim Tlshim rx thread
[   41.743130] R0: [VosTlshimRxThre][13:03:47.935664]  wlan: [7896:E :VOS] VosTlshimRxThread: Exiting VOSS Tlshim rx thread
[   41.744569] R0: [insmod][13:03:47.937083]  wlan: [7888:F :HDD] hdd_wlan_startup: vos_open failed
[   41.747122] R0: wlan: [7888:F :HIF]  hdd_wlan_startup failed
[   41.747245] AR6k: Device rejected error:-5 
[   41.747350] tx_completion_task: tx completion task stopping
[   41.747444] __HIFReadWrite, addr:0X000868, len:00000004, Write, Sync 
[   41.747451] AR6000: Byte mode (BlockLen: 4)
[   41.747460] address:00000868, Length:0x00000004, Dummy:0x0000, Final:0x00000868
[   41.747462] AR6000: Address mode: Incremental 0x868
[   41.747485] mmc1: starting CMD53 arg 9410d004 flags 000001b5
[   41.747489] mmc1:     blksz 4 blocks 1 flags 00000100 tsac 1000 ms nsac 0
[   41.747740] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00108001
[   41.747781] mmc1: Data timeout error
[   41.747957] sdhci: =========== REGISTER DUMP (mmc1)===========
[   41.748100] sdhci: Sys addr: 0x00000000 | Version:  0x00000505
[   41.748229] sdhci: Blk size: 0x00007004 | Blk cnt:  0x00000001
[   41.748403] sdhci: Argument: 0x9410d004 | Trn mode: 0x00000003
[   41.748539] sdhci: Present:  0x01f30000 | Host ctl: 0x00000013
[   41.748666] sdhci: Power:    0x00000001 | Blk gap:  0x00000000
[   41.748795] sdhci: Wake-up:  0x00000000 | Clock:    0x00000007
[   41.748913] sdhci: Timeout:  0x0000000b | Int stat: 0x00000000
[   41.749034] sdhci: Int enab: 0x02ff000b | Sig enab: 0x02fc000b
[   41.749158] sdhci: AC12 err: 0x00000000 | Slot int: 0x00000000
[   41.749277] sdhci: Caps:     0x3f6cd08c | Caps_1:   0x18002f73
[   41.749395] sdhci: Cmd:      0x0000353a | Max curr: 0x00000000
[   41.749547] sdhci: Host ctl2: 0x00003008
[   41.749848] sdhci: ADMA Err: 0x00000000 | ADMA Ptr: 0x00000000ffefe410
[   41.750330] ======= mmc1: Tuning windows =======
[   41.750350] mmc1: tuning window[0]: 0x0
[   41.750359] mmc1: tuning window[1]: 0x0
[   41.750363] mmc1: tuning window[2]: 0x0
[   41.750367] mmc1: tuning window[3]: 0x0
[   41.750371] mmc1: tuning window[4]: 0x0
[   41.750375] mmc1: tuning window[5]: 0x0
[   41.750379] mmc1: tuning window[6]: 0x0
[   41.750453] mmc1: tuning window[7]: 0x0
[   41.750459] sdhci: Tap value: 9 | Trim value: 5
[   41.750461] ==================================
[   41.750464] Vendor clock ctrl: 0x509d025
[   41.750467] Vendor SysSW ctrl: 0x38607002
[   41.750470] Vendor Err interrupt status : 0x40000
[   41.750473] Vendor Cap overrides: 0x1107
[   41.750477] Vendor Misc ctrl: 0xffff0098
[   41.750480] Vendor Misc ctrl_1: 0x0
[   41.750482] Vendor Misc ctrl_2: 0x20600000
[   41.750485] Vendor IO trim ctrl: 0x11
[   41.750487] Vendor Tuning ctrl: 0x74024057
[   41.750490] SDMEM comp padctrl: 0x8607000
[   41.750493] Autocal config: 0x20010000
[   41.750495] Autocal status: 0x7060706
[   41.750560] Tuning Status1: 0x0
[   41.750562] sdhci: ===========================================
[   41.750901] mmc1: req done (CMD53): 0: 00001200 00000000 00000000 00000000
[   41.750910] mmc1:     0 bytes transferred: -110
[   41.751298] AR6000: writeio ret=-110 address: 0x868, len: 4, 0x0
[   41.751332] AR6000: SDIO bus operation failed! MMC stack returned : -110 
[   41.751347] __HIFReadWrite, addr:0X000868, len:00000004, Write, Sync 
[   41.751383] SDIO: Disabling device mmc1:0001:1...
[   41.751392] mmc1: starting CMD52 arg 00000400 flags 00000195
[   41.751450] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
[   41.751483] mmc1: req done (CMD52): 0: 00001000 00000000 00000000 00000000
[   41.751579] mmc1: starting CMD52 arg 80000400 flags 00000195
[   41.751645] sdhci [sdhci_irq()]: *** mmc1 got interrupt: 0x00000001
[   41.751664] mmc1: req done (CMD52): 0: 00001000 00000000 00000000 00000000
[   41.751703] SDIO: Disabled device mmc1:0001:1
[   41.751734] AR6000: -hifEnableFunc
[   41.751757] AR6000: delHifDevice; 0xffffffc7760a4000
[   41.751765] AR6000: Release busrequest queue
[   41.752028] ar6k_wlan: probe of mmc1:0001:1 failed with error -1
[   41.753988] HIFInit sdio_register_driver successful
[   41.754022] ath_hif_sdio: HIF (Atheros/multi-bss)
[   41.754070] R0: wlan: [7888:E :HDD] hdd_hif_register_driver: 18374: hdd_wlan_startup failed status:-11 jiffies_left:35000
[   41.754076] R0: wlan: [7888:F :HDD] hdd_driver_init: WLAN Driver Initialization failed
[   41.754081] AR6000: +HIFShutDownDevice
[   41.754084] AR6000: HIFShutDownDevice, resetting
[   41.754085] AR6000: Unregistering with the bus driver
[   41.754255] AR6000: Unregistered!
[   41.754268] AR6000: -HIFShutDownDevice
 
 
Best Regards,
Jay
 
 
 
  • Up0
  • Down0
ddeepakk Moderator
Join Date: 27 Jun 17
Posts: 144
Posted: Wed, 2022-09-14 08:14

Hi Jiangjie,

 There is a timeout happening in HTCWaitRecvCtrlMessage function.

    adf_os_re_init_completion(target->CtrlResponseValid);
    /* Wait for BMI request/response transaction to complete */
    if(!adf_os_wait_for_completion_timeout(&target->CtrlResponseValid,
        adf_os_msecs_to_ticks(HTC_CONTROL_RX_TIMEOUT))) {
        if(hif_set_target_reset(target->hif_dev))
            VOS_BUG(0);
        return A_ERROR;
    }
 
It could be an SDIO bus related issue that caused BMI timeout. The BMI phase is the initial communication between the driver and the WLAN Hardware. Please check SDIO is working OK or not.
 
Thanks.
  • Up0
  • Down0
jiangjie
Join Date: 13 Sep 22
Posts: 2
Posted: Thu, 2022-09-15 06:24

Hi ddeepakk,

Thanks for your reply.

Now we managed to load the driver successfully with 1-bit SDIO mode,
but the 4-bit SDIO mode still fails with the aforementioned errors.

Any idea?

Thanks.

  • Up0
  • Down0
or Register

Opinions expressed in the content posted here are the personal opinions of the original authors, and do not necessarily reflect those of Qualcomm Incorporated or its subsidiaries (“Qualcomm”). The content is provided for informational purposes only and is not meant to be an endorsement or representation by Qualcomm or any other party. This site may also provide links or references to non-Qualcomm sites and resources. Qualcomm makes no representations, warranties, or other commitments whatsoever about any non-Qualcomm sites or third-party resources that may be referenced, accessible from, or linked to this site.