Initialization problem on Kernel version 4.1.15

[bht-patrick-schneider]

Hi there,
I don't know if this problem is limited to Kernel version 4.1.15, but before further investigating the issue - is this driver compatible with Kernel version 4.1.xx?
If so I seemed to have run into a initialization issue, because I cannot get the driver to load correctly. The problem seems to be the order of function calls involved. Please see the kernel output:

[ 33.279354] /soc/aips-bus@02100000/usdhc@02194000: voltage-ranges unspecified
[ 33.286928] sdhci-esdhc-imx 2194000.usdhc: could not get ultra high speed state, work on normal mode
[ 33.302508] sdhci-esdhc-imx 2194000.usdhc: No vmmc regulator found
[ 33.312793] sdhci-esdhc-imx 2194000.usdhc: No vqmmc regulator found
[ 33.376340] mmc1: SDHCI controller on 2194000.usdhc [2194000.usdhc] using ADMA
[ 33.416632] mmc1: queuing unknown CIS tuple 0x91 (2 bytes)
[ 33.422241] mmc1: new high speed SDIO card at address 0001
[ 33.434653] (unnamed net_device) (uninitialized): INFO [wilc_create_wiphy]Registering wifi device
[ 33.454727] (unnamed net_device) (uninitialized): INFO [wilc_wfi_cfg_alloc]Allocating wireless device
[ 33.467715] (unnamed net_device) (uninitialized): INFO [wilc_create_wiphy]Successful Registering
[ 33.494164] (unnamed net_device) (uninitialized): INFO [wilc_create_wiphy]Registering wifi device
[ 33.515595] (unnamed net_device) (uninitialized): INFO [wilc_wfi_cfg_alloc]Allocating wireless device
[ 33.537618] (unnamed net_device) (uninitialized): INFO [wilc_create_wiphy]Successful Registering
[ 33.585388] wilc_sdio mmc1:0001:1: WILC got 121 for gpio_reset
[ 33.591362] wilc_sdio mmc1:0001:1: WILC got 137 for gpio_chip_en
[ 33.601043] systemd-networkd[208]: wlan0: IP[ 33.608611] wilc_sdio mmc1:0001:1 wlan0: INFO [wilc_mac_open]MAC OPEN[9c7c6800] wlan0
v6 enabled for interface: Success
[ 33.623006] wilc_sdio mmc1:0001:1: WILC got 21 for gpio_irq
[ 33.632269] wilc_sdio mmc1:0001:1 wlan0: INFO [wilc_mac_open]WL[9c7c6000] (null)
[ 33.641936] wifi_pm : 0
[ 33.644535] wifi_pm : 1
[ 33.648424] Unable to handle kernel NULL pointer dereference at virtual address 00000000
[ 33.656686] pgd = 9c810000
[ 33.659417] [00000000] *pgd=00000000
[ 33.663031] Internal error: Oops: 805 [#1] PREEMPT SMP ARM
[ 33.668529] Modules linked in: wilc_sdio
[ 33.672508] CPU: 0 PID: 208 Comm: systemd-network Not tainted 4.1.15 #4
[ 33.679133] Hardware name: Freescale i.MX6 Ultralite (Device Tree)
[ 33.685326] task: 9c495300 ti: 9c824000 task.ti: 9c824000
[ 33.690753] PC is at __mutex_lock_slowpath+0x9c/0x19c
[ 33.695821] LR is at _raw_spin_lock+0x10/0x50
[ 33.700195] pc : [<8071d890>] lr : [<8071f210>] psr: a00f0013
[ 33.700195] sp : 9c825bc0 ip : 00000000 fp : 00000000
[ 33.711685] r10: 7f018428 r9 : 9c7c676c r8 : 00000002
[ 33.716926] r7 : 9c495300 r6 : ffffffff r5 : 9c7c6768 r4 : 9c7c6764
[ 33.723467] r3 : 00000000 r2 : 9c825bc4 r1 : 00000000 r0 : 00000001
[ 33.730009] Flags: NzCv IRQs on FIQs on Mode SVC_32 ISA ARM Segment user
[ 33.737158] Control: 10c53c7d Table: 9c81006a DAC: 00000015
[ 33.742917] Process systemd-network (pid: 208, stack limit = 0x9c824210)
[ 33.749630] Stack: (0x9c825bc0 to 0x9c826000)
[ 33.754012] 5bc0: 80923ca4 9c7c676c 00000000 9c7c6800 808b2e70 9c7c6764 7f0212bc 9c7c6cc0
[ 33.762208] 5be0: 9c7c6764 00000000 9c7c6000 8071d9dc 9c7c6000 7f015ca0 00000000 8058636c
[ 33.770404] 5c00: 9c7c6800 7f0212bc 9c7c6cc0 9c7c6830 9c7c6000 9c397b10 7f018428 7f007200
[ 33.778600] 5c20: 00000000 00000000 00000000 00000000 00000000 00000000 00000141 000012d0
[ 33.786798] 5c40: 00000000 00000100 9c825c48 9c825c48 80646090 fffffff4 fffffff1 9c825ca4
[ 33.794995] 5c60: 0000000d 00000000 80a304f8 9c397b10 7f018428 80045d44 9c7c6800 9c7c6800
[ 33.803191] 5c80: 00000001 7f018428 9c7c6830 9c8b2300 9c397b10 7f018428 00000000 8058a600
[ 33.811388] 5ca0: 00001003 9c7c6800 00000000 9c7c6800 00000001 00001003 00001002 8058a88c
[ 33.819584] 5cc0: 9c7c6800 00001002 00000000 9c7c6938 9c8b2300 8058a954 9c7c6800 9c7c6800
[ 33.827781] 5ce0: 9c825d5c 00000000 9c8b2300 80598e88 8078f84c 00000003 0000000a 00000000
[ 33.835977] 5d00: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 9c7c6800
[ 33.844174] 5d20: 9c8b2300 9c397b10 00000000 9c825e54 00000000 00000000 00000000 805993a0
[ 33.852371] 5d40: 9c825d4c 00000000 9ca54700 9c825e00 9a25c7c0 00383032 9ca54700 00000000
[ 33.860567] 5d60: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[ 33.868763] 5d80: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[ 33.876959] 5da0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[ 33.885155] 5dc0: 00000000 9c397b20 00000000 00000000 00000000 00000000 00000000 00000000
[ 33.893352] 5de0: 00000000 00000000 00000000 00000000 00000000 00000000 805992d0 9c397b00
[ 33.901549] 5e00: 9c8b2300 80598488 9fb96e88 9a2a7dd0 00000000 800f4ffc 9a2a7dd0 9a2a7e20
[ 33.909747] 5e20: 9c397b00 9c8b2300 805983bc 9c8b2300 9c825e54 805af6cc 9c8b2300 00000030
[ 33.917944] 5e40: 9c592c00 805983b4 9c0ab000 805af050 9c825ef4 7fffffff 9c825eec 9c825eec
[ 33.926141] 5e60: 00000030 9c592c00 00000008 9c8b2300 00000000 805af4ac 9c825e98 800ec984
[ 33.934338] 5e80: 54bdf3d8 00000008 809ee2a0 9c8097c0 00000000 000000d0 000003e4 000003e1
[ 33.942536] 5ea0: 9c9e2000 00000000 00000000 9a12a000 00000122 8000f484 9c824000 00000000
[ 33.950733] 5ec0: 76fd3ce8 80571300 00000000 80572404 9c825ef4 00000000 9c495300 00000000
[ 33.958930] 5ee0: 00000000 560075b0 00000030 9c825f18 00000010 00000001 00000000 00000000
[ 33.967127] 5f00: 9c825eec 00000000 00000000 00000000 00000000 8071f210 00000010 00000000
[ 33.975324] 5f20: 00000000 00000000 9fbd6e00 9ca498e8 9fbd6e00 9ca498e8 60010013 809f9500
[ 33.983522] 5f40: 00000000 8006e264 a444dffa ffffffff c1be51d0 00165a0b ffffffff 00000000
[ 33.991718] 5f60: 9c825f98 7eec796c 76fd3ce8 00000107 8000f484 7eec796c 76fd3ce8 00000107
[ 33.999916] 5f80: 8000f484 7eec796c 00000008 00000000 7eec796c 80076374 7eec796c 00000010
[ 34.008113] 5fa0: 76fd3ce8 8000f300 7eec796c 00000010 00000003 560075b0 00000030 00000000
[ 34.016311] 5fc0: 7eec796c 00000010 76fd3ce8 00000122 000000d0 54b61d60 55ffcb80 76fd3ce8
[ 34.024507] 5fe0: 00000000 7eec7950 00000000 76f35490 80010010 00000003 00000000 00000000
[ 34.032727] [<8071d890>] (__mutex_lock_slowpath) from [<8071d9dc>] (mutex_lock+0x4c/0x50)
[ 34.041062] [<8071d9dc>] (mutex_lock) from [<7f015ca0>] (wilc_bt_power_up+0x24/0x330 [wilc_sdio])
[ 34.050121] [<7f015ca0>] (wilc_bt_power_up [wilc_sdio]) from [<7f007200>] (wilc_mac_open+0x258/0xc18 [wilc_sdio])
[ 34.060487] [<7f007200>] (wilc_mac_open [wilc_sdio]) from [<8058a600>] (__dev_open+0xac/0x114)
[ 34.069128] [<8058a600>] (__dev_open) from [<8058a88c>] (__dev_change_flags+0x94/0x144)
[ 34.077153] [<8058a88c>] (__dev_change_flags) from [<8058a954>] (dev_change_flags+0x18/0x48)
[ 34.085616] [<8058a954>] (dev_change_flags) from [<80598e88>] (do_setlink+0x2bc/0x704)
[ 34.093554] [<80598e88>] (do_setlink) from [<805993a0>] (rtnl_setlink+0xd0/0x118)
[ 34.101057] [<805993a0>] (rtnl_setlink) from [<80598488>] (rtnetlink_rcv_msg+0xcc/0x1e4)
[ 34.109173] [<80598488>] (rtnetlink_rcv_msg) from [<805af6cc>] (netlink_rcv_skb+0xb4/0xd8)
[ 34.117461] [<805af6cc>] (netlink_rcv_skb) from [<805983b4>] (rtnetlink_rcv+0x24/0x2c)
[ 34.125400] [<805983b4>] (rtnetlink_rcv) from [<805af050>] (netlink_unicast+0x158/0x20c)
[ 34.133512] [<805af050>] (netlink_unicast) from [<805af4ac>] (netlink_sendmsg+0x2e0/0x348)
[ 34.141803] [<805af4ac>] (netlink_sendmsg) from [<80571300>] (sock_sendmsg+0x14/0x24)
[ 34.149655] [<80571300>] (sock_sendmsg) from [<80572404>] (SyS_sendto+0xb4/0xe8)
[ 34.157080] [<80572404>] (SyS_sendto) from [<8000f300>] (ret_fast_syscall+0x0/0x3c)
[ 34.164760] Code: e58d9004 e3e06000 e58d3008 e3a08002 (e5832000)
[ 34.171038] ---[ end trace cfd4bd76b0a941a2 ]---
[ 34.175736] note: systemd-network[208] exited with preempt_count 2
[ 34.194404] wilc_sdio mmc1:0001:1: Driver Initializing success

I tracked down the issue, which seems to be that the mutex is not initialized before it is used. To be more specific: the NULL pointer is the mutex used in wilc_bt.c line 211 called from the __dev_open function. This function seems to be called BEFORE the initial probe function (linux_sdio_probe) in wilc_sdio.c is completely finished (and the mutex is initialized at line 203).
Once in my testing it happened that this order was correct and the driver initialized completely but the system hangs after the "wilc_sdio mmc1:0001:1: Driver Initializing success" output and is not usable, so I assume there are more issues at play here.

As I said I am running at a linux-imx kernel version 4.1.15 on a i.MX6UL SOM.

Any help is appreciated,
Patrick

[AdhamAbozaeid]

Hi @bht-patrick-schneider

The problem you are having is that linux_sdio_probe() is called, and it's the registering the net device by calling wilc_netdev_init(), and it looks like your system is calling mac_open directly after the net device is regisetered, before mutex wilc->cs is initialized later in linux_sdio_probe().

As a quick workaround for now, you can try moving the mutex_init() calls for wilc's mutexes inside wilc_netdev_init() after wilc structure is allocated, and before the net_device is registered

Thanks,
Adham

[bht-patrick-schneider]

Hi @AdhamAbozaeid ,
thank you very much for your answer!
If I do as you suggest the driver fails with another error:

[ 440.367792] /soc/aips-bus@02100000/usdhc@02194000: voltage-ranges unspecified
[ 440.375360] sdhci-esdhc-imx 2194000.usdhc: could not get ultra high speed state, work on normal mode
[ 440.384950] sdhci-esdhc-imx 2194000.usdhc: No vmmc regulator found
[ 440.396439] sdhci-esdhc-imx 2194000.usdhc: No vqmmc regulator found
[ 440.465224] mmc1: SDHCI controller on 2194000.usdhc [2194000.usdhc] using ADMA
[ 440.510848] mmc1: queuing unknown CIS tuple 0x91 (2 bytes)
[ 440.516542] mmc1: new high speed SDIO card at address 0001
[ 440.528546] (unnamed net_device) (uninitialized): INFO [wilc_create_wiphy]Registering wifi device
[ 440.551803] (unnamed net_device) (uninitialized): INFO [wilc_wfi_cfg_alloc]Allocating wireless device
[ 440.563593] (unnamed net_device) (uninitialized): INFO [wilc_create_wiphy]Successful Registering
[ 440.590604] (unnamed net_device) (uninitialized): INFO [wilc_create_wiphy]Registering wifi device
[ 440.610190] (unnamed net_device) (uninitialized): INFO [wilc_wfi_cfg_alloc]Allocating wireless device
[ 440.637512] (unnamed net_device) (uninitialized): INFO [wilc_create_wiphy]Successful Registering
[ 440.673395] systemd-networkd[239]: wlan0: IPv6 enabled for interface: Success
[ 440.696084] wilc_sdio mmc1:0001:1: WILC got 121 for gpio_reset
[ 440.702058] wilc_sdio mmc1:0001:1: WILC got 137 for gpio_chip_en
[ 440.712875] wilc_sdio mmc1:0001:1 wlan0: INFO [wilc_mac_open]MAC OPEN[9ca5f000] wlan0
[ 440.737908] wilc_sdio mmc1:0001:1: WILC got 21 for gpio_irq
[ 440.743604] wifi_pm : 0
[ 440.750808] WILC POWER UP
[ 440.753491] wilc_sdio mmc1:0001:1 wlan0: INFO [wilc_init_host_int]Host[9ca5f000][9ca3fa80]
[ 440.765260] wifi_pm : 1
[ 440.780967] wilc_sdio mmc1:0001:1: Driver Initializing success
[ 440.787033] wilc_sdio mmc1:0001:1 wlan0: INFO [wilc_mac_open]*** re-init ***
[ 440.794117] wilc_sdio mmc1:0001:1 wlan0: INFO [wlan_init_locks]Initializing Locks ...
[ 440.819434] wilc_sdio mmc1:0001:1 wlan0: INFO [wilc_wlan_init]Initializing WILC_Wlan
[ 440.829566] wilc_sdio mmc1:0001:1: SDIO speed: 50000000
[ 440.839373] wilc_sdio mmc1:0001:1: wilc_sdio_cmd52..failed, err(-110)
[ 440.846699] wilc_sdio mmc1:0001:1: Fail cmd 52, enable csa...
[ 440.852935] wilc_sdio mmc1:0001:1 wlan0: ERR [wilc_wlan_initialize: 1157] Initializing WILC_Wlan FAILED
[ 440.868893] wilc_sdio mmc1:0001:1 wlan0: INFO [wlan_deinit_locks]De-Initializing Locks
[ 440.877817] wilc_sdio mmc1:0001:1 wlan0: ERR [wilc_wlan_initialize: 1244] WLAN initialization FAILED
[ 440.891316] wilc_sdio mmc1:0001:1 wlan0: ERR [wilc_mac_open: 1298] Failed to initialize wilc
[ 440.902965] wilc_sdio mmc1:0001:1 wlan0: ERR [wilc_send_config_pkt: 1929] Set Timed out
[ 440.915775] wilc_sdio mmc1:0001:1 wlan0: ERR [handle_set_wfi_drv_handler: 445] Failed to set driver handler
[ 440.926417] wilc_sdio mmc1:0001:1 wlan0: Host cmd 24 failed
[ 440.932524] wilc_sdio mmc1:0001:1 wlan0: ERR [host_if_work: 3000] [Host Interface] undefined
[ 440.964869] systemd-networkd[239]: wlan0: Could not bring up interface: Input/output error

even more often I will get:
wlan0: ERR [wilc_mac_open: 1274] device not ready

and I have to reset the module and retrigger a sdio-probe.

Again, should this driver work with my kernel version or is there an older driver version somewhere around?
Many thanks so far,
Patrick

[AdhamAbozaeid]

Hi @bht-patrick-schneider
The good news are that it looks like that the change fixed the problem you were having before, since I see the powerup step now succeeds.

Again, should this driver work with my kernel version or is there an older driver version somewhere around?

The driver should work with any kernel version. We use kernel version checks in the code to account for changes in the cfg80211 from one kernel version to another.
However, some kernel versions, WPA supplicant versions, and different configurations, causes the host to behave differently or do things in different sequences.
Since it's very difficult to cover all these cases while testing, we do testing against a reference setup (sama5d4 + kernel 4.9) which is available on this linux4wilc.
Issues arising from other hosts or SW combination will have are debugged as they arise.

The problem you are having now looks to be related to powersave which causes SDIO failures.
Can you try disabling powersave and see if that helped?

[bht-patrick-schneider]

Hi @AdhamAbozaeid
thanks again for the answer and the clarifications!
Unfortunately I am pinned to this kernel version because of the used controller.
Please forgive me as this may sound as a dumb question, but what do you mean with powersave? Regarding kernel or sdio or this driver? I couldn't find anything regarding options for disabling, could you give me a hint what you mean and how to disable it?

[AdhamAbozaeid]

Hi @bht-patrick-schneider
I don't believe you have to change your kernel. If there's a problem with this specific host configuration, it can still be fixed in the driver, which seems like worked with the fix I suggested earlier.

For the SDIO errors, what I mean by powersave is the wireless device powersave. the wpa supplicant on linux can configure the wireless device to enter into powersave mode. You can either make sure that the supplicant doesn't do that, or hack it in the driver by overriding power_mode in handle_power_management() to always be NO_POWERSAVE.

[bht-patrick-schneider]

Hi @AdhamAbozaeid
Thanks again for the explanation. I tried as you instructed (and a few other things), but unfortunately the output and behaviour stays exactly the same.
Over the course of the last weeks I tried several things and just to rule out any side effects that may or may not be possible here are some other informations that could have an impact on behaviour:

• to be able to test more frequently I am building the driver as a kernel module with yocto (without patching the kernel, just a raw module) and manually load it after boot

• that requires me to manually retrigger an sdio-probe and my script for fast testing looks like this:
  modprobe wilc_sdio -r
  echo 121 > /sys/class/gpio/export
  echo 137 > /sys/class/gpio/export
  echo out > /sys/class/gpio/gpio121/direction
  echo out > /sys/class/gpio/gpio137/direction
  echo 0 > /sys/class/gpio/gpio137/value
  echo 0 > /sys/class/gpio/gpio121/value
  sleep 1s
  echo 1 > /sys/class/gpio/gpio137/value
  sleep 1s
  echo 1 > /sys/class/gpio/gpio121/value
  echo 121 > /sys/class/gpio/unexport
  echo 137 > /sys/class/gpio/unexport
  sleep 3s
  cd /sys/devices/platform/soc/2100000.aips-bus/2194000.usdhc/driver/
  echo -n "2194000.usdhc" > unbind
  sleep 3s
  modprobe wilc_sdio
  sleep 3s
  echo -n "2194000.usdhc" > bind

• GPIO121 is Reset, GPIO137 is enable, so basically I am resetting the module, rebind the usdhc driver and trigger a new probe

• if I would just let it load at startup the boot procedure would crash (because of the errors) which is more difficult to test

• could that in any way alter the behaviour of the driver and cause additional problems?

• also, this is my device tree entry, are there any errors?
  &usdhc2 {
  pinctrl-names = "default";
  pinctrl-0 = <&pinctrl_usdhc2_wifi>;
  pinctrl-1 = <&pinctrl_usdhc2_wifi100mhz>;
  pinctrl-2 = <&pinctrl_usdhc2_wifi200mhz>;
  non-removable;
  status = "okay";

  #address-cells = <1>;
  #size-cells = <0>;

  wilc_sdio@0{
  compatible = "atmel,wilc_sdio";
  gpio_reset = <&gpio4 25 GPIO_ACTIVE_HIGH>;
  gpio_chip_en = <&gpio5 9 GPIO_ACTIVE_HIGH>;
  gpio_irq = <&gpio1 21 GPIO_ACTIVE_LOW>;
  interrupt-parent = <&gpio1>;
  interrupts = <21 IRQ_TYPE_EDGE_RISING>;
  status = "okay";
  reg = <0>;
  bus-width = <4>;
  };
  };

[AdhamAbozaeid]

Hi @bht-patrick-schneider
Please open a ticket on the sales force.
The team will try to replicate the problem and help more with that.