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

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?

Thanks for your attention.

-- Thierry Moreau

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

Thanks for your reply Larry. I had seen the interrupt latency fix (latest release candidate) but since my problem occurs earlier than any wifi protocol activity, I abstained from upgrading.

Anyway since you suggested it, I moved to 3.14.0-rc5 and the problem occurs exactly as reported earlier (the dmesg indeed reports a different module load and init sequence).

From your suggestions, I should try with tools other than iw and iwconfig. I thought the higher level wireless management tools would use the same kernel api.

Any other suggestion?

P.S. Yes, the "ip link set up wlan1" command was given. The EBUSY return applies equally before and after this command.

Regards,

-- Thierry Moreau

Please give me the exact set of commands you use to get this problem. If possible, capture the console output. As I am currently running long-term tests of the latest version of rtl8192ce using an RTL8188CE (10ec:8176), it will be a perfect time to test.

Larry

Here is the command script, and the console log
(....sh 2>&1 | tee ....log)

Is it possible that the Shuttle system be arranged with a digital output enabling/inhibiting the Realtek wifi interface active participation in wifi protocol?

I did ask Shuttle tech support, but in any event I don't want to induce you to troubleshoot a specific system.

Thanks,

-- Thierry Moreau

+ uname -a
Linux dodeca1er 3.14.0-rc5 #1 SMP Wed Mar 5 15:38:33 UTC 2014 x86_64 Intel(R) Atom(TM) CPU D2550 @ 1.86GHz GenuineIntel GNU/Linux
+ grep -i wifi -C 4 -n
+ dmesg

711-[    2.581616] gma500 0000:00:02.0: trying to get vblank count for disabled pipe 1
712-[    2.771178] usb 5-2: new low-speed USB device number 2 using uhci_hcd
713-[    2.832203] fbcon: psbdrmfb (fb0) is primary device
714-[    2.832262] rtl8192ce:_rtl92ce_read_chip_version():<0-0> Chip Version ID: B_CUT_88C
715:[    2.844335] rtl8192ce: Using firmware rtlwifi/rtl8192cfwU_B.bin
716-[    2.939453] usb 5-2: New USB device found, idVendor=045e, idProduct=0780
717-[    2.939458] usb 5-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
718-[    2.939462] usb 5-2: Product: Comfort Curve Keyboard 3000
719-[    2.939465] usb 5-2: Manufacturer: Microsoft
--
725-[    3.287718] gma500 0000:00:02.0: fb0: psbdrmfb frame buffer device
726-[    3.287723] gma500 0000:00:02.0: registered panic notifier
727-[    3.287820] [drm] Initialized gma500 1.0.0 2011-06-06 for 0000:00:02.0 on minor 0
728-[    3.396518] ieee80211 phy0: Selected rate control algorithm 'rtl_rc'
729:[    3.397145] rtlwifi: wireless switch is on
730-[    5.834746] Adding 16777212k swap on /dev/sda6.  Priority:42 extents:1 across:16777212k 
731-[    5.859658] Adding 16777212k swap on /dev/sda7.  Priority:52 extents:1 across:16777212k 
732-[    5.883344] Adding 16777212k swap on /dev/sda8.  Priority:62 extents:1 across:16777212k 
733-[    6.872268] gzip (166) used greatest stack depth: 3864 bytes left
+ lsmod
Module                  Size  Used by
rtl8192ce              71392  0 
gma500_gfx            139440  1 
rtl_pci                24810  1 rtl8192ce
rtlwifi                70066  2 rtl_pci,rtl8192ce
rtl8192c_common        53859  1 rtl8192ce
drm_kms_helper         28143  1 gma500_gfx

+ cat
+ 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 short limit:7 RTS thr=2347 B Fragment thr:off
Encryption key:off
Power Management:on

+ cat
+ iw dev wlan1 info
Interface wlan1

	ifindex 4
	wdev 0x1
	addr 64:5a:04:aa:f8:16
	type managed
	wiphy 0

+ cat
+ iw dev wlan1 set channel 2
command failed: Device or resource busy (-16)
+ cat
+ iw dev wlan1 scan
command failed: Network is down (-100)
+ cat
+ ip link set up wlan1
+ cat
+ iw dev wlan1 scan
BSS d8:6c:e9:29:e5:75(on wlan1)
TSF: 1358921377410 usec (15d, 17:28:41)
freq: 2412
beacon interval: 100 TUs
capability: ESS Privacy ShortSlotTime APSD (0x0c11)
signal: -74.00 dBm
last seen: 929 ms ago
SSID: BELL417
Supported rates: 1.0* 2.0* 5.5* 11.0* 9.0 18.0 36.0 54.0 DS Parameter set: channel 1
ERP: Barker_Preamble_Mode
Extended supported rates: 6.0 12.0 24.0 48.0
HT capabilities:
Capabilities: 0x106e
HT20/HT40
SM Power Save disabled
RX HT20 SGI
RX HT40 SGI
No RX STBC
Max AMSDU length: 3839 bytes DSSS/CCK HT40
Maximum RX AMPDU length 32767 bytes (exponent: 0x002) Minimum RX AMPDU time spacing: 4 usec (0x05) HT RX MCS rate indexes supported: 0-23, 32 HT TX MCS rate indexes are undefined
HT operation:
* primary channel: 1
* secondary channel offset: above
* STA channel width: any
* RIFS: 0
* HT protection: nonmember
* non-GF present: 0
* OBSS non-GF present: 0
* dual beacon: 0
* dual CTS protection: 0
* STBC beacon: 0
* L-SIG TXOP Prot: 0
* PCO active: 0
* PCO phase: 0
Secondary Channel Offset: no secondary (0)
RSN: * Version: 1
* Group cipher: CCMP
* Pairwise ciphers: CCMP
* Authentication suites: PSK
* Capabilities: 1-PTKSA-RC 1-GTKSA-RC (0x0000)
WMM: * Parameter version 1
* u-APSD
* BE: CW 15-1023, AIFSN 3
* BK: CW 15-1023, AIFSN 7
* VI: CW 7-15, AIFSN 2, TXOP 3008 usec
* VO: CW 3-7, AIFSN 2, TXOP 1504 usec
BSS Load:
* station count: 0
* channel utilisation: 11/255
* available admission capacity: 31250 [*32us]
Overlapping BSS scan params:
* passive dwell: 20 TUs
* active dwell: 10 TUs
* channel width trigger scan interval: 300 s
* scan passive total per channel: 200 TUs
* scan active total per channel: 20 TUs
* BSS width channel transition delay factor: 5
* OBSS Scan Activity Threshold: 0.25 %
Extended capabilities: HT Information Exchange Supported
Country: CA Environment: Indoor/Outdoor
Channels [1 - 11] @ 16 dBm
WPS: * Version: 1.0
* Wi-Fi Protected Setup State: 2 (Configured)
* Response Type: 3 (AP)
* UUID: 28802880-2880-1880-a880-d86ce929e575
* Manufacturer: Ralink Technology, Corp.
* Model: Ralink Wireless Access Point
* Model Number: RT2860
* Serial Number: 12345678
* Primary Device Type: 6-0050f204-1
* Device name: RalinkAPS
* Config methods: Label, PBC
* RF Bands: 0x1
+ cat
+ iwlist wlan1 scanning
wlan1 Scan completed :

          Cell 01 - Address: D8:6C:E9:29:E5:75
                    Channel:1
                    Frequency:2.412 GHz (Channel 1)
                    Quality=30/70  Signal level=-80 dBm  
                    Encryption key:on
                    ESSID:"BELL417"
                    Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 11 Mb/s; 9 Mb/s
                              18 Mb/s; 36 Mb/s; 54 Mb/s
                    Bit Rates:6 Mb/s; 12 Mb/s; 24 Mb/s; 48 Mb/s
                    Mode:Master
                    Extra:tsf=0000013c6606a682
                    Extra: Last beacon: 987ms ago
                    IE: Unknown: 000742454C4C343137
                    IE: Unknown: 010882848B961224486C
                    IE: Unknown: 030101
                    IE: Unknown: 2A0104
                    IE: Unknown: 32040C183060
                    IE: Unknown: 2D1A6E1016FFFFFF0001000000000000000000000000030000000000
                    IE: Unknown: 3D1601050100000000000000000000000000000000000000
                    IE: Unknown: 3E0100
                    IE: IEEE 802.11i/WPA2 Version 1
                        Group Cipher : CCMP
                        Pairwise Ciphers (1) : CCMP
                        Authentication Suites (1) : PSK
                    IE: Unknown: DD180050F2020101800003A4000027A4000042435E0062322F00
                    IE: Unknown: 0B0500000B127A
                    IE: Unknown: 4A0E14000A002C01C800140005001900
                    IE: Unknown: 7F0101
                    IE: Unknown: DD07000C4300000000
                    IE: Unknown: 0706434120010B10
                    IE: Unknown: DD9D0050F204104A0001101044000102103B000103104700102880288028801880A880D86CE929E5751021001852616C696E6B20546563686E6F6C6F67792C20436F72702E1023001C52616C696E6B20576972656C6573732041636365737320506F696E74102400065254323836301042000831323334353637381054000800060050F20400011011000952616C696E6B415053100800020084103C000101

+ cat
+ iwconfig wlan1 channel 2
Error for wireless request "Set Frequency" (8B04) :
SET failed on device wlan1 ; Device or resource busy.
+ cat
+ ip link set down wlan1
+ cat
+ iw dev wlan1 interface add wlan2 type managed
+ cat
+ 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 short 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 short limit:7 RTS thr=2347 B Fragment thr:off
Encryption key:off
Power Management:on

+ cat
+ iw dev rename5 set channel 2
command failed: Device or resource busy (-16)
+ cat

Instead of cat, I used single-second sleeps as can be seen in the attached script. Our logs are roughly the same (I have replaced the last three bytes of the MAC address by XX for privacy). The rtlwifi module is patched[1], hence the out-of-tree marking.

What is the problem that you are experiencing? I am able to connect although it took half a minute for the first ICMP ping packets to pass (and then there is still a lot of packet loss). This pattern is observable on the past 2.5 weeks that I have been running ping tests (ping every second to the gateway).

I didn't understand the first part, are you referring to a possible mistake in attaching the antennas? When I opened up the case, I saw two antennas that were properly secured to the card.

Regards,
Peter

[1]: http://lkml.org/lkml/2014/2/14/430

Script started on Thu 06 Mar 2014 02:43:56 PM CET
+ iface=wlan0
+ uname -a
Linux work 3.14.0-rc2-custom-00267-g9398a10 #4 SMP PREEMPT Wed Feb 12 20:41:43 CET 2014 x86_64 GNU/Linux
+ dmesg
+ grep -i wifi -C 4 -n

1125-[   11.401304] [drm] No driver support for vblank timestamp query.
1126-[   11.514185] rtl8192ce:_rtl92ce_read_chip_version():<0-0> Chip Version ID: B_CUT_88C
1127-[   11.526221] rtl8192ce: rtl8192ce: Power Save off (module option)
1128-[   11.526222] rtl8192ce: rtl8192ce: FW Power Save off (module option)
1129:[   11.526242] rtl8192ce: Using firmware rtlwifi/rtl8192cfwU_B.bin
1130-[   11.604096] systemd[1]: Received SIGCHLD from PID 137 (systemd-vconsol).
1131-[   11.612617] systemd[1]: Got SIGCHLD for process 137 (systemd-vconsol)
1132-[   11.621165] systemd[1]: Child 137 died (code=exited, status=0/SUCCESS)
1133-[   11.629346] systemd[1]: Child 137 belongs to systemd-vconsole-setup.service
--
1148-[   11.839624] cfg80211:   (5170000 KHz - 5250000 KHz @ 80000 KHz), (N/A, 2000 mBm)
1149-[   11.855677] cfg80211:   (5735000 KHz - 5835000 KHz @ 80000 KHz), (N/A, 2000 mBm)
1150-[   11.871911] cfg80211:   (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 0 mBm)
1151-[   11.888513] ieee80211 phy0: Selected rate control algorithm 'rtl_rc'
1152:[   11.897674] rtlwifi: wireless switch is on
1153-[   11.908296] systemd[1]: sys-subsystem-net-devices-wlan0.device changed dead -> plugged
1154-[   11.911950] input: HDA Intel HDMI/DP,pcm=3 as /devices/pci0000:00/0000:00:1b.0/sound/card0/input10
1155-[   11.913175] input: HDA Intel Front Headphone as /devices/pci0000:00/0000:00:1b.0/sound/card0/input9
1156-[   11.915407] input: HDA Intel Mic as /devices/pci0000:00/0000:00:1b.0/sound/card0/input8
--
1577-[   16.885077] systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
1578-[   16.890932] ------------[ cut here ]------------
1579-[   16.890944] WARNING: CPU: 2 PID: 134 at /home/peter/linux/kernel/locking/mutex.c:516 __mutex_lock_slowpath+0x357/0x370()
1580-[   16.890947] DEBUG_LOCKS_WARN_ON(in_interrupt())
1581:[   16.891013] Modules linked in: xt_tcpudp nf_conntrack_ipv6 nf_conntrack_ipv4 nf_defrag_ipv4 nf_defrag_ipv6 xt_conntrack nf_conntrack iptable_filter ip6table_filter ip_tables ip6_tables x_tables snd_hda_codec_hdmi arc4 snd_hda_codec_idt snd_hda_codec_generic rtl8192ce(O) rtl_pci(O) gma500_gfx rtlwifi(O) mac80211 snd_hda_intel i2c_algo_bit drm_kms_helper snd_hda_codec snd_hwdep drm cfg80211 snd_pcm snd_timer snd evdev r8169 pcspkr iTCO_wdt i2c_i801 i2c_core iTCO_vendor_support video rfkill rtl8192c_common(O) coretemp microcode lpc_ich rtsx_pci_ms mii memstick soundcore fan processor thermal button ext4 crc16 mbcache jbd2 hid_logitech_dj usbhid hid sd_mod rtsx_pci_sdmmc mmc_core ahci libahci libata scsi_mod ehci_pci uhci_hcd ehci_hcd usbcore usb_common rtsx_pci mfd_core
1582-[   16.891018] CPU: 2 PID: 134 Comm: systemd-journal Tainted: G           O 3.14.0-rc2-custom-00267-g9398a10 #4
1583-[   16.891019] Hardware name: Shuttle Inc. XS36V/XS36V, BIOS 1.11 12/18/2012
1584-[   16.891026]  0000000000000009 ffff88012fd03bf0 ffffffff8146cca0 ffff88012fd03c38
1585-[   16.891030]  ffff88012fd03c28 ffffffff8104c45d ffff880037945818 ffff880037945818
+ lsmod
Module                  Size  Used by
xt_tcpudp               3111  1 
nf_conntrack_ipv6       7995  1 
nf_conntrack_ipv4       7754  1 
nf_defrag_ipv4          1403  1 nf_conntrack_ipv4
nf_defrag_ipv6         25934  1 nf_conntrack_ipv6
xt_conntrack            3265  2 
nf_conntrack           66712  3 xt_conntrack,nf_conntrack_ipv4,nf_conntrack_ipv6
iptable_filter          1488  1 
ip6table_filter         1428  1 
ip_tables              16451  1 iptable_filter
ip6_tables             16160  1 ip6table_filter
x_tables               17522  6 ip6table_filter,ip_tables,xt_tcpudp,xt_conntrack,iptable_filter,ip6_tables
snd_hda_codec_hdmi     36172  1 
arc4                    2000  2 
snd_hda_codec_idt      43450  1 
snd_hda_codec_generic    52827  1 snd_hda_codec_idt
rtl8192ce              73667  0 
rtl_pci                24976  1 rtl8192ce
gma500_gfx            174510  1 
rtlwifi                71601  2 rtl_pci,rtl8192ce
mac80211              490444  3 rtl_pci,rtlwifi,rtl8192ce
snd_hda_intel          34841  0 
i2c_algo_bit            5391  1 gma500_gfx
drm_kms_helper         35572  1 gma500_gfx
snd_hda_codec          98879  4 snd_hda_codec_hdmi,snd_hda_codec_idt,snd_hda_codec_generic,snd_hda_intel
snd_hwdep               5852  1 snd_hda_codec
drm                   237941  2 drm_kms_helper,gma500_gfx
cfg80211              430184  2 mac80211,rtlwifi
snd_pcm                80379  3 snd_hda_codec_hdmi,snd_hda_codec,snd_hda_intel
snd_timer              18709  1 snd_pcm
snd                    51167  8 snd_hwdep,snd_timer,snd_hda_codec_hdmi,snd_hda_codec_idt,snd_pcm,snd_hda_codec_generic,snd_hda_codec,snd_hda_intel
evdev                  10981  4 
r8169                  58223  0 
pcspkr                  1995  0 
iTCO_wdt                5407  0 
i2c_i801               11109  0 
i2c_core               23780  5 drm,i2c_i801,drm_kms_helper,i2c_algo_bit,gma500_gfx
iTCO_vendor_support     1929  1 iTCO_wdt
video                  11540  1 gma500_gfx
rfkill                 15683  1 cfg80211
rtl8192c_common        55112  1 rtl8192ce
coretemp                6390  0 
microcode              15090  0 
lpc_ich                13368  0 
rtsx_pci_ms             7418  0 
mii                     4027  1 r8169
memstick                7504  1 rtsx_pci_ms
soundcore                944  1 snd
fan                     2785  0 
processor              24170  0 
thermal                 8556  0 
button                  4477  0 
ext4                  481304  4 
crc16                   1359  1 ext4
mbcache                 6074  1 ext4
jbd2                   82736  1 ext4
hid_logitech_dj        10599  0 
usbhid                 40843  0 
hid                    89807  2 usbhid,hid_logitech_dj
sd_mod                 31817  5 
rtsx_pci_sdmmc         13924  0 
mmc_core               95817  1 rtsx_pci_sdmmc
ahci                   23403  4 
libahci                21484  1 ahci
libata                172031  2 ahci,libahci
scsi_mod              132830  2 libata,sd_mod
ehci_pci                3960  0 
uhci_hcd               33795  0 
ehci_hcd               63800  1 ehci_pci
usbcore               180840  4 uhci_hcd,ehci_hcd,ehci_pci,usbhid
usb_common              1648  1 usbcore
rtsx_pci               32831  2 rtsx_pci_ms,rtsx_pci_sdmmc
mfd_core                3249  2 lpc_ich,rtsx_pci

+ sleep 1
+ iwconfig
eth0 no wireless extensions.

lo no wireless extensions.

wlan0 IEEE 802.11bgn ESSID:off/any
Mode:Managed Access Point: Not-Associated Tx-Power=0 dBm
Retry short limit:7 RTS thr=2347 B Fragment thr:off
Encryption key:off
Power Management:on

+ sleep 1
+ iw dev wlan0 info
Interface wlan0

	ifindex 3
	wdev 0x1
	addr e0:91:53:XX:XX:XX
	type managed
	wiphy 0

+ sleep 1
+ iw dev wlan0 set channel 2
command failed: Device or resource busy (-16)
+ sleep 1
+ iw dev wlan0 scan
command failed: Network is down (-100)
+ sleep 1
+ ip link set up wlan0
+ sleep 1
+ iw dev wlan0 scan
BSS 48:f9:25:00:01:13(on wlan0)

	TSF: 10820542146 usec (0d, 03:00:20)
	freq: 2472
	beacon interval: 100 TUs
	capability: ESS ShortPreamble ShortSlotTime (0x0421)
	signal: -54.00 dBm
	last seen: 26 ms ago
	Information elements from Probe Response frame:
	SSID: Hermes_Mobile_Hotspot
	Supported rates: 1.0* 2.0 5.5 11.0 
	DS Parameter set: channel 13
+ sleep 1
+ iwlist wlan0 scanning
wlan0     Scan completed :
          Cell 01 - Address: 48:F9:25:00:01:13
                    Channel:13
                    Frequency:2.472 GHz (Channel 13)
                    Quality=56/70  Signal level=-54 dBm  
                    Encryption key:off
                    ESSID:"Hermes_Mobile_Hotspot"
                    Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 11 Mb/s
                    Mode:Master
                    Extra:tsf=0000000284f45ec2
                    Extra: Last beacon: 1943ms ago
                    IE: Unknown: 00154865726D65735F4D6F62696C655F486F7473706F74
                    IE: Unknown: 010482040B16
                    IE: Unknown: 03010D
                    IE: Unknown: DD2A000C42000000011E001000000066160500004C563132333437000000000000000000000000000502A809

+ sleep 1
+ iwconfig wlan0 channel 2
Error for wireless request "Set Frequency" (8B04) :
SET failed on device wlan0 ; Device or resource busy.
+ sleep 1
+ ip link set down wlan0
+ sleep 1
+ iw dev wlan0 interface add wlan2 type managed
+ sleep 1
+ iwconfig
wlan2 IEEE 802.11bgn ESSID:off/any
Mode:Managed Access Point: Not-Associated Tx-Power=20 dBm
Retry short limit:7 RTS thr=2347 B Fragment thr:off
Encryption key:off
Power Management:on

eth0 no wireless extensions.

lo no wireless extensions.

wlan0 IEEE 802.11bgn ESSID:off/any
Mode:Managed Frequency:2.417 GHz Access Point: Not-Associated Tx-Power=20 dBm
Retry short limit:7 RTS thr=2347 B Fragment thr:off
Encryption key:off
Power Management:off

+ sleep 1
+ iw dev wlan2 set channel 2
command failed: Device or resource busy (-16)
+ sleep 1

real 0m15.794s
user 0m0.137s
sys 0m0.417s

Script done on Thu 06 Mar 2014 02:44:12 PM CET

Indeed a good question! Likely there is no problem. Likely a misunderstanding from my part of the wifi logic.

I was going step by step in my integration and I (wrongly?) assumed that the command to set a channel in the wifi configuration was a requirement for my next step: scanning done on an older wifi system detected signals from multiple channels but the newer system scanning saw only channel 1, hence I assumed that the newer scanning scheme needed channel changes by the user space logic.

Now a number of clues (including your log below -- thanks) point towards the inconsequential-ness of the EBUSY result in the specific command I was using as a milestone.

Other clues: a) suggestion by Larry to try other tools, and b) an EBUSY return code in net/wireless/chan.c .

Somewhere else I might learn how scanning on multiple channels can work, but I no longer care for my deployment priorities.

Please ignore this other hypothesis.

Thanks a lot to Larry and Peter. If you don't ear from me, please assume that I successfully installed hostapd and I am an happy rtlwifi user with the kernel 3.14.

-- Thierry Moreau

The problem is not specific to the Shuttle - I can reproduce it on my HP laptop. Furthermore, it affects other mac80211-based drivers. The EBUSY return comes out of mac80211/cfg80211/nl80211 code.

I have no idea why that particular set of commands fails to be able to set the channel. Both NetworkManager and the openSUSE ifup sequence work OK. Your system can set channels using the scan mechanism.

If you want to track it down, you will need to put printk statements at every place that the net/wireless code sets EBUSY to see which one triggers. Perhaps that will expose any bug there, or in your script.

Larry

I deleted the earlier bits of this thread after skimming it, but IIRC we're talking about scanning here right? If there's already a scan in-progress, then the stack can often return EBUSY.

For example, from both cfg80211_wext_siwscan() and nl80211_trigger_scan(), used by 'iwlist' and 'iw' respectively:

	if (rdev->scan_req) {
		err = -EBUSY;
		goto out;
	}

Scans do not get canceled just because another random scan request comes in. Whatever userspace there is needs to wait for a scan completion event and then request it's new scan. There are also stack internal scans that happen from time to time that may cause a user-requested scan to return EBUSY.

(NM hands this all off to wpa_supplicant, which itself handles the EBUSY by waiting a bit and then requesting another scan.)

Dan

It was not entirely clear for me, but have you enabled the interface before changing the channel? I.e.

ip link set wlan0 up
iw dev wlan0 set channel 2

I suggest to try 3.13 or even 3.14(-rcish). Earlier kernels (3.10 being the worst) had an issue[1] that impacted wireless stability.

The same box is operating in my neighbourhood (networking was not required for its purpose). Good luck with getting multi-head working. This box is running 3.14-rc2-something now with patches to get monitor mode to function properly.

Kind regards,
Peter

[1]: https://bugzilla.kernel.org/show_bug.cgi?id=60713