[rt2x00-users] [PATCH] rt2x00: Don't queue ieee80211 work after USB removal

Sat Oct 31 19:36:29 UTC 2009

On Oct 31, 2009, at Sat 31, 1:56 AM, Ivo van Doorn wrote:

> On Saturday 31 October 2009, Sean Cross wrote:
>>
>> Perhaps it does make more sense to test for DEVICE_STATE_PRESENT in
>> rt2x00link_start_tuner, just so rt2x00link_reset_tuner() isn't called
>> on a card that is no longer present.
>>
>> But the timing issue I'm seeing is something like this:
>>
>> 1) Card is removed
>> 2) ENODEV messages start getting received.
>> 3) Something decides to start the tuner.
>> 4) link->work gets queued to happen sometime in the future.
>> 5) The USB system finally decides to unload the driver.  I think
>> rt2x00usb_disconnect() gets called here.
>> 6) link->work gets run, but as the device has been unloaded, the
>> delayed_work is no longer valid, so a KP occurs.
>>
>> The root cause is that link->work is suddenly no longer valid, so the
>> flag can't get checked at the start of the thread.  Since I think
>> ENODEV will get returned before rt2x00link_start_tuner() is called, I
>> believe this is a valid method of catching the removal.
>
> The problem is more between 5 and 6 in this case, the mac80211 queue
> must be flushed so it must wait until all tasks have completed.  
> Nothing
> should have been deleted that must be used when the thread start.
> If the work structure is gone, that means rt2x00dev is gone, which  
> really
> shouldn't happen.
>
> Don't get me wrong, you patch is still be valid, it is just that I  
> believe it is
> not covering the entire bug. ;)

Ah, okay, I think I see part of the problem.

The queue is flushed when the card is removed, as  
rt2x00usb_disconnect() is called immediately.  The  
DEVICE_STATE_PRESENT flag should probably be cleared here.   
Additionally, a check might be placed at the top of  
rt2x00usb_vendor_request() to not even perform the request if the  
device is not present.

Something keeps making requests even after the card is removed.  I  
know this because if I place a printk(...) at the top of  
rt2x00usb_disconnect to know when it's called, I receive the following:

[  842.660000] usb 1-1.1: USB disconnect, address 9
[  842.830000] Called rt2x00usb_disconnect()
[  842.830000] phy6 -> rt2x00usb_vendor_request: Error - Vendor  
Request 0x07 failed for offset 0x1004 with error -19.
[  842.840000] phy6 -> rt2x00usb_vendor_request: Error - Vendor  
Request 0x06 failed for offset 0x1004 with error -19.
[  842.850000] phy6 -> rt2x00usb_vendor_request: Error - Vendor  
Request 0x07 failed for offset 0x0208 with error -19.
[  842.860000] phy6 -> rt2x00usb_vendor_request: Error - Vendor  
Request 0x06 failed for offset 0x0208 with error -19.
[  842.870000] phy6 -> rt2x00usb_vendor_request: Error - Vendor  
Request 0x06 failed for offset 0x1004 with error -19.
[  842.880000] phy6 -> rt2x00usb_vendor_request: Error - Vendor  
Request 0x06 failed for offset 0x1204 with error -19.
[  842.890000] phy6 -> rt2x00usb_vendor_request: Error - Vendor  
Request 0x06 failed for offset 0x1328 with error -19.
[  842.900000] phy6 -> rt2x00usb_vendor_request: Error - Vendor  
Request 0x07 failed for offset 0x0208 with error -19.
[  842.920000] phy6 -> rt2x00usb_vendor_request: Error - Vendor  
Request 0x0c failed for offset 0x0000 with error -19.
[  843.160000] phy6 -> rt2x00usb_regbusy_read: Error - Indirect  
register access failed: offset=0x00007010, value=0xc3bdbd70
(...additional lines omitted...)

There can be anywhere from, say, six of these errors, up to maybe 50  
or so.  My guess is that the ieee80211 device is getting removed  
(which happens when rt2x00usb_disconnect calls ieee80211_free_hw(hw)),  
but something is still requesting that data be sent.  Sometimes it's  
the LED unloading itself, sometimes it's an attempt to turn the radio  
off.

Anyway, there's something subtle going wrong here.  If I add a WARN()  
in rt2x00link_start_tuner() to fire when it's called and the device  
has been removed, then I will occasionally (with the same frequency as  
when I'd get KPs before) get the following:

[   86.440000] ------------[ cut here ]------------
[   86.440000] WARNING: at /home/scross/Code/falconwing-build/compat- 
wireless-20090728/src/drivers/net/wireless/rt2x00/rt2x00link.c:365  
rt2x00link_start_tuner+0x5c/0x94 [rt2x00lib]()
[   86.460000] Can't call rt2x00link_start_tuner() on a device that's  
not present!
[   86.470000] Modules linked in: rt2800usb crc_ccitt snd_pcm_oss  
snd_mixer_oss stmp3xxx_rotdec stmp378x_devb_rotdec chumby_timer  
snd_soc_stmp3780_devb snd_soc_stmp3xxx_dai snd_soc_stmp378x_codec  
snd_soc_stmp3xxx snd_soc_core snd_pcm snd_timer snd soundcore  
snd_page_alloc i2c_dev rt2500usb arc4 rt73usb rt2x00usb rt2x00lib  
led_class mac80211 cfg80211 rfkill_backport ehci_hcd usbcore evdev  
joydev mousedev stmp3xxx_ts i2c_stmp378x i2c_core chumby_bend  
stmp3xxx_wdt
[   86.510000] [<c02faf20>] (dump_stack+0x0/0x14) from [<c003f49c>]  
(warn_slowpath+0x64/0x80)
[   86.520000] [<c003f438>] (warn_slowpath+0x0/0x80) from [<bf0d51d8>]  
(rt2x00link_start_tuner+0x5c/0x94 [rt2x00lib])
[   86.530000]  r3:0000642a r2:bf0d62a1
[   86.530000]  r6:00000060 r5:c3bac9a0 r4:c3bac9a0
[   86.540000] [<bf0d517c>] (rt2x00link_start_tuner+0x0/0x94  
[rt2x00lib]) from [<bf0d26b8>] (rt2x00lib_toggle_rx+0x48/0x4c  
[rt2x00lib])
[   86.550000]  r5:00000006 r4:c3bac9a0
[   86.550000] [<bf0d2670>] (rt2x00lib_toggle_rx+0x0/0x4c [rt2x00lib])  
from [<bf0d32ec>] (rt2x00mac_config+0x5c/0x64 [rt2x00lib])
[   86.570000]  r5:c3bac260 r4:c3bac9a0
[   86.570000] [<bf0d3290>] (rt2x00mac_config+0x0/0x64 [rt2x00lib])  
from [<bf09e0b0>] (ieee80211_hw_config+0xb0/0xbc [mac80211])
[   86.580000]  r7:c3bac838 r6:c3bac7e4 r5:c3bac260 r4:c24f446c
[   86.590000] [<bf09e000>] (ieee80211_hw_config+0x0/0xbc [mac80211])  
from [<bf0a19e4>] (ieee80211_scan_work+0x1b4/0x424 [mac80211])
[   86.600000]  r5:c3bac260 r4:c24f446c
[   86.600000] [<bf0a1830>] (ieee80211_scan_work+0x0/0x424 [mac80211])  
from [<c004f628>] (run_workqueue+0xb8/0x144)
[   86.610000] [<c004f570>] (run_workqueue+0x0/0x144) from  
[<c004fd54>] (worker_thread+0x104/0x118)
[   86.620000]  r7:c389f6a0 r6:c24f9520 r5:c24f9528 r4:c2524000
[   86.630000] [<c004fc50>] (worker_thread+0x0/0x118) from  
[<c0053120>] (kthread+0x54/0x80)
[   86.640000]  r7:00000000 r6:00000000 r5:c004fc50 r4:c24f9520
[   86.640000] [<c00530cc>] (kthread+0x0/0x80) from [<c00422b8>]  
(do_exit+0x0/0x6e4)
[   86.650000]  r5:00000000 r4:00000000
[   86.650000] ---[ end trace 299f1509891405a6 ]---

What do you think is going on here?

Sean