Re: rtlwifi (rtl8192ce) consistently reports EBUSY error, but scanning works

[Larry Finger <Larry.Finger@lwfinger.net>]

On 03/05/2014 12:36 AM, Thierry Moreau wrote:
> Hi!
>
> I am using a kind-of "linux from scratch" (i.e. Crux 3.0, 64 bits Intel, kernel
> 3.10.32) and I am stuck with a EBUSY error return from the wireless driver I
> suspect it comes from the driver behavior since it is consistent either from the
> command
>
> iw dev wlan1 set channel 2
>
> or the comand
>
> iwconfig wlan1 set channel 2
>
> (it occurred also with "iw" with a kernel where the iwconfig support emulation
> is off -- CONFIG_CFG82011_WEXT). The EBUSY error return occurs as early as
> immediately after the initial module install, and consistently thereafter. The
> wireless scanning works (reporting a nearby beacon on channel 1).
>
> I understand this list is not for user/integrator support but since I control
> many variables in the troubleshooting exercise, some of you might be interested
> in finding more about a possible bug.
>
> Here is a sequence of commands immediately after system boot:
>
> + uname -a
> Linux a-host 3.10.32 #2 SMP Wed Mar 5 00:39:47 UTC 2014 x86_64 Intel(R) Atom(TM)
> CPU D2550 @ 1.86GHz GenuineIntel GNU/Linux
>
> + dmesg | grep -i wifi -C 4 -n
> 853-[    2.468354] gma500 0000:00:02.0: trying to get vblank count for disabled
> pipe 1
> 854-[    2.556398] usb 5-2: new low-speed USB device number 2 using uhci_hcd
> 855-[    2.685093] rtl8192ce:_rtl92ce_read_chip_version():<0-0> Chip Version ID:
> B_CUT_88C
> 856-[    2.693197] fbcon: psbdrmfb (fb0) is primary device
> 857:[    2.697204] rtl8192ce: Using firmware rtlwifi/rtl8192cfwU_B.bin
> 858-[    2.700363] modprobe (109) used greatest stack depth: 3928 bytes left
> 859-[    2.700499] usb 5-2: skipped 1 descriptor after interface
> 860-[    2.700506] usb 5-2: skipped 1 descriptor after interface
> 861-[    2.705486] usb 5-2: default language 0x0409
> --
> 889-[    3.149779] gma500 0000:00:02.0: fb0: psbdrmfb frame buffer device
> 890-[    3.149784] gma500 0000:00:02.0: registered panic notifier
> 891-[    3.149870] [drm] Initialized gma500 1.0.0 2011-06-06 for 0000:00:02.0 on
> minor 0
> 892-[    3.403646] ieee80211 phy0: Selected rate control algorithm 'rtl_rc'
> 893:[    3.404050] rtlwifi: wireless switch is on
> 894-[    5.579389] Adding 16777212k swap on /dev/sda6.  Priority:42 extents:1
> across:16777212k
> 895-[    5.595963] Adding 16777212k swap on /dev/sda7.  Priority:52 extents:1
> across:16777212k
> 896-[    5.611337] Adding 16777212k swap on /dev/sda8.  Priority:62 extents:1
> across:16777212k
> 897-[    5.699807] rm (146) used greatest stack depth: 3032 bytes left
>
> + lsmod
> Module                  Size  Used by
> rtl8192ce              72128  0
> gma500_gfx            147187  1
> rtlwifi               106604  1 rtl8192ce
> rtl8192c_common        54252  1 rtl8192ce
> drm_kms_helper         27871  1 gma500_gfx
>
> + iwconfig
> eth0      no wireless extensions.
>
> lo        no wireless extensions.
>
> sit0      no wireless extensions.
>
> wlan1     IEEE 802.11bgn  ESSID:off/any
>            Mode:Managed  Access Point: Not-Associated   Tx-Power=0 dBm
>            Retry  long limit:7   RTS thr=2347 B   Fragment thr:off
>            Encryption key:off
>            Power Management:on
>
>
> + iw dev wlan1 info
> Interface wlan1
>      ifindex 4
>      wdev 0x1
>      addr 64:5a:04:aa:f8:16
>      type managed
>      wiphy 0
>
> **** Here is the first occurrence of the blocking error condition:
>
> + iw dev wlan1 set channel 2
> command failed: Device or resource busy (-16)
>
> **** Next error is expected:
>
> + iw dev wlan1 scan
> command failed: Network is down (-100)
>
> + ip link set up wlan1
>
> + iw dev wlan1 scan
> BSS d8:6c:e9:29:e5:75(on wlan1)
>      TSF: 1305304974530 usec (15d, 02:35:04)
>      freq: 2412
> ... bla bla bla
>           * Device name: RalinkAPS
>           * Config methods: Label, PBC
>           * RF Bands: 0x1
>
> + iwlist wlan1 scanning
> wlan1     Scan completed :
>            Cell 01 - Address: D8:6C:E9:29:E5:75
>                      Channel:1
>                      Frequency:2.412 GHz (Channel 1)
>                      Quality=70/70  Signal level=-4 dBm
> ... bla bla bla
>                      IE: Unknown: 0706434120010B10
>
>
> **** Here is another instance of the blocking error condition (occurs with iw as
> well):
>
> + iwconfig wlan1 channel 2
> Error for wireless request "Set Frequency" (8B04) :
>      SET failed on device wlan1 ; Device or resource busy.
>
> **** Some user of a widespread distribution reported a similar problem and a
> work-around with the "iw ... interface add .." command, which I attempt here:
>
> + ip link set down wlan1
>
> + iw dev wlan1 interface add wlan2 type managed
>
> **** note that I don't care that the name wlan2 turns into rename5 because it
> did not occur without CONFIG_CFG82011_WEXT which is useless besides the present
> troubleshooting:
>
> + iwconfig
> eth0      no wireless extensions.
>
> lo        no wireless extensions.
>
> sit0      no wireless extensions.
>
> wlan1     IEEE 802.11bgn  ESSID:off/any
>            Mode:Managed  Frequency:2.417 GHz  Access Point: Not-Associated
>            Tx-Power=20 dBm
>            Retry  long limit:7   RTS thr=2347 B   Fragment thr:off
>            Encryption key:off
>            Power Management:off
>
> rename5   IEEE 802.11bgn  ESSID:off/any
>            Mode:Managed  Access Point: Not-Associated   Tx-Power=20 dBm
>            Retry  long limit:7   RTS thr=2347 B   Fragment thr:off
>            Encryption key:off
>            Power Management:on
>
> **** Too bad it occurs again:
>
> + iw dev rename5 set channel 2
> command failed: Device or resource busy (-16)
>
>
> ==============
>
> Final remarks:
>
> I went through the firmware load learning curve for a Linux user/integrator and
> I am confident that the following sha1sum'ed file has been loaded:
> c81ec289a236875ab7139c0e357fdcddcc21cc46 /lib/firmware/rtlwifi/rtl8192cfwU_B.bin
> (the fact that scanning works supports my confidence)
>
> I investigated the iw source code (version 3.11, but the above is with version
> 3.14) and I gave up once I traced the reported error condition to the call to
> nl_recvmsgs in the iw.c source file.
>
> I grep'ed EBUSY in the C source files in the drivers/net/rtlwifi sub-directories
> and find none. I suppose some other component in the driver detects the error
> condition.
>
> If I recall correctly, the command "iw ... interface add ..." followed by "iw
> ... del" for the source interface allowed me to set the channel without the
> EBUSY outcome once (and the sticky EBUSY came again vey soon) with the kernel
> devoid of CONFIG_CFG82011_WEXT. It makes seldom sense to me to pursue this
> elusive workaround, but this could be a sign that a fresh kernel "interface"
> data structure turns EBUSY-sick after some action occurring in the driver
> initialization logic.
>
> The system is a Shuttle XS36VL box
> (http://us.shuttle.com/barebone/Models/XS36VL.html). It does not have a physical
> wireless switch (a dmesg line above reports the switch position as "on").
>
> Any suggestion about a next step in troubleshooting? Maybe trying the latest
> kernel release candidate?

I use NetworkManager and I never see errors like this.

You definitely should use either a newer kernel or the backports sources. There 
is a recent change that fixes a problem in rtl8192ce that caused interrupts to 
be disabled for a long time. That fix is in the mainline 3.14-rc5 and in the 
wireless-testing repo. It is in the process of being applied to the various 
stable kernels, but it is probably not there yet.

If you just want to try that patch, it is available at 
https://lkml.org/lkml/2014/2/1/15.

Larry