Bug 9388

Summary: Unable to associate rt25xx USB key with a WPA AP
Product: Drivers Reporter: Christian Casteyde (casteyde.christian)
Component: network-wirelessAssignee: Ivo van Doorn (IvDoorn)
Status: CLOSED PATCH_ALREADY_AVAILABLE    
Severity: normal CC: linville, master
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 2.6.24-rc2 Subsystem:
Regression: --- Bisected commit-id:
Attachments: Fix MAC address initialization
kernel dump at device plug in

Description Christian Casteyde 2007-11-15 08:59:48 UTC
Most recent kernel where this bug did not occur: N/A (driver introduced in 2.6.24)
Distribution:Bluewhite 64 (64 bits Linux)
Hardware Environment: D-Link DWL-G122 Wifi 11b/g USB key
Software Environment: wpa_supplicant v0.5.7, kernel 2.6.24-rc2
Problem Description:
I'm not able to associate the wireless interface of a USB key with an AP that use WPA/TKIP CCMP encryption.
When I try to force reassociation in wpa_cli with the reass command, I get:
<2>Trying to associate with 00:07:cb:55:12:b0 (SSID='MonRezo' freq=2427 MHz)
<2>Authentication with 00:00:00:00:00:00 timed out.
<2>Trying to associate with 00:07:cb:55:12:b0 (SSID='MonRezo' freq=2427 MHz)
<2>Authentication with 00:00:00:00:00:00 timed out.
<2>Trying to associate with 00:07:cb:55:12:b0 (SSID='MonRezo' freq=2427 MHz)
<2>Authentication with 00:00:00:00:00:00 timed out.
<2>Trying to associate with 00:07:cb:55:12:b0 (SSID='MonRezo' freq=2427 MHz)
<2>Authentication with 00:00:00:00:00:00 timed out.

dmesg with debug logs shows that:
usb 1-1: new high speed USB device using ehci_hcd and address 5
usb 1-1: configuration #1 chosen from 1 choice
phy1 -> rt2500usb_validate_eeprom: EEPROM recovery - NIC: 0xfff0
phy1 -> rt2x00_set_chip: Info - Chipset detected - rt: 1201, rf: 0005, rev: 00000003.
phy1: Selected rate control algorithm 'simple'
phy1 -> rt2500usb_init_bbp: Debug - Start initialization from EEPROM...
phy1 -> rt2500usb_init_bbp: Debug - BBP: 0x11, value: 0x32.
phy1 -> rt2500usb_init_bbp: Debug - BBP: 0x15, value: 0x18.
phy1 -> rt2500usb_init_bbp: Debug - BBP: 0x16, value: 0x18.
phy1 -> rt2500usb_init_bbp: Debug - BBP: 0x3e, value: 0x00.
phy1 -> rt2500usb_init_bbp: Debug - ...End initialization from EEPROM.
phy1 -> rt2x00mac_conf_tx: Info - Configured TX ring 0 - CWmin: 4, CWmax: 10, Aifs: 2.
phy1 -> rt2x00mac_conf_tx: Info - Configured TX ring 1 - CWmin: 4, CWmax: 10, Aifs: 2.
phy1 -> rt2x00mac_conf_tx: Info - Configured TX ring 7 - CWmin: 5, CWmax: 10, Aifs: 2.
WARNING: at kernel/lockdep.c:700 look_up_lock_class()

Call Trace:
 [<ffffffff802584d6>] __lock_acquire+0xb16/0x1080
 [<ffffffff805ddb0b>] _spin_unlock_irq+0x2b/0x60
 [<ffffffff805ce8e0>] ieee80211_sta_work+0x0/0x1140
 [<ffffffff80258a97>] lock_acquire+0x57/0x80
 [<ffffffff80246423>] run_workqueue+0x103/0x230
 [<ffffffff8024644c>] run_workqueue+0x12c/0x230
 [<ffffffff8024703a>] worker_thread+0xca/0x130
 [<ffffffff8024af40>] autoremove_wake_function+0x0/0x40
 [<ffffffff80246f70>] worker_thread+0x0/0x130
 [<ffffffff8024ab7d>] kthread+0x4d/0x80
 [<ffffffff8020c608>] child_rip+0xa/0x12
 [<ffffffff8020c1c3>] restore_args+0x0/0x30
 [<ffffffff8024ac82>] kthreadd+0xd2/0x150
 [<ffffffff8024ab30>] kthread+0x0/0x80
 [<ffffffff8020c5fe>] child_rip+0x0/0x12

HW CONFIG: channel=1 freq=2412 phymode=2
HW CONFIG: channel=2 freq=2417 phymode=2
HW CONFIG: channel=3 freq=2422 phymode=2
HW CONFIG: channel=4 freq=2427 phymode=2
HW CONFIG: channel=5 freq=2432 phymode=2
HW CONFIG: channel=6 freq=2437 phymode=2
HW CONFIG: channel=7 freq=2442 phymode=2
HW CONFIG: channel=8 freq=2447 phymode=2
HW CONFIG: channel=9 freq=2452 phymode=2
HW CONFIG: channel=10 freq=2457 phymode=2
HW CONFIG: channel=11 freq=2462 phymode=2
HW CONFIG: channel=12 freq=2467 phymode=2
HW CONFIG: channel=13 freq=2472 phymode=2
HW CONFIG: channel=1 freq=2412 phymode=2
HW CONFIG: channel=1 freq=2412 phymode=2
phy1 -> rt2x00mac_conf_tx: Info - Configured TX ring 0 - CWmin: 4, CWmax: 10, Aifs: 2.
phy1 -> rt2x00mac_conf_tx: Info - Configured TX ring 1 - CWmin: 4, CWmax: 10, Aifs: 2.
phy1 -> rt2x00mac_conf_tx: Info - Configured TX ring 7 - CWmin: 5, CWmax: 10, Aifs: 2.
wlan1: Initial auth_alg=0
wlan1: authenticate with AP 00:14:a4:34:6c:0f
wlan1: authenticate with AP 00:14:a4:34:6c:0f
wlan1: authenticate with AP 00:14:a4:34:6c:0f
wlan1: authentication with AP 00:14:a4:34:6c:0f timed out

At that point, dhcpd bails out, and deconfigure the interface. If I issue
ifconfig wlan1 up
to reactivate it, wpa_supplicant keeps trying to associate and I get:
phy1 -> rt2500usb_init_bbp: Debug - Start initialization from EEPROM...
phy1 -> rt2500usb_init_bbp: Debug - BBP: 0x11, value: 0x32.
phy1 -> rt2500usb_init_bbp: Debug - BBP: 0x15, value: 0x18.
phy1 -> rt2500usb_init_bbp: Debug - BBP: 0x16, value: 0x18.
phy1 -> rt2500usb_init_bbp: Debug - BBP: 0x3e, value: 0x00.
phy1 -> rt2500usb_init_bbp: Debug - ...End initialization from EEPROM.
HW CONFIG: channel=1 freq=2412 phymode=2
HW CONFIG: channel=2 freq=2417 phymode=2
HW CONFIG: channel=3 freq=2422 phymode=2
HW CONFIG: channel=4 freq=2427 phymode=2
HW CONFIG: channel=5 freq=2432 phymode=2
HW CONFIG: channel=6 freq=2437 phymode=2
HW CONFIG: channel=7 freq=2442 phymode=2
HW CONFIG: channel=8 freq=2447 phymode=2
HW CONFIG: channel=9 freq=2452 phymode=2
HW CONFIG: channel=10 freq=2457 phymode=2
HW CONFIG: channel=11 freq=2462 phymode=2
HW CONFIG: channel=12 freq=2467 phymode=2
HW CONFIG: channel=13 freq=2472 phymode=2
HW CONFIG: channel=1 freq=2412 phymode=2
HW CONFIG: channel=1 freq=2412 phymode=2
HW CONFIG: channel=4 freq=2427 phymode=2
wlan1: Initial auth_alg=0
wlan1: authenticate with AP 00:14:a4:34:6c:0f
phy1 -> rt2x00mac_conf_tx: Info - Configured TX ring 0 - CWmin: 4, CWmax: 10, Aifs: 2.
phy1 -> rt2x00mac_conf_tx: Info - Configured TX ring 1 - CWmin: 4, CWmax: 10, Aifs: 2.
phy1 -> rt2x00mac_conf_tx: Info - Configured TX ring 7 - CWmin: 5, CWmax: 10, Aifs: 2.
wlan1: Initial auth_alg=0
wlan1: authenticate with AP 00:14:a4:34:6c:0f
wlan1: Initial auth_alg=0
wlan1: authenticate with AP 00:07:cb:55:12:b0
wlan1: authenticate with AP 00:07:cb:55:12:b0
wlan1: authenticate with AP 00:07:cb:55:12:b0
wlan1: authentication with AP 00:07:cb:55:12:b0 timed out
HW CONFIG: channel=1 freq=2412 phymode=2
HW CONFIG: channel=2 freq=2417 phymode=2
HW CONFIG: channel=3 freq=2422 phymode=2
HW CONFIG: channel=4 freq=2427 phymode=2
HW CONFIG: channel=5 freq=2432 phymode=2
HW CONFIG: channel=6 freq=2437 phymode=2
HW CONFIG: channel=7 freq=2442 phymode=2
HW CONFIG: channel=8 freq=2447 phymode=2
HW CONFIG: channel=9 freq=2452 phymode=2
HW CONFIG: channel=10 freq=2457 phymode=2
HW CONFIG: channel=11 freq=2462 phymode=2
HW CONFIG: channel=12 freq=2467 phymode=2
HW CONFIG: channel=13 freq=2472 phymode=2
HW CONFIG: channel=4 freq=2427 phymode=2
HW CONFIG: channel=4 freq=2427 phymode=2
wlan1: Initial auth_alg=0
wlan1: authenticate with AP 00:07:cb:55:12:b0
phy1 -> rt2x00mac_conf_tx: Info - Configured TX ring 0 - CWmin: 4, CWmax: 10, Aifs: 2.
phy1 -> rt2x00mac_conf_tx: Info - Configured TX ring 1 - CWmin: 4, CWmax: 10, Aifs: 2.
phy1 -> rt2x00mac_conf_tx: Info - Configured TX ring 7 - CWmin: 5, CWmax: 10, Aifs: 2.
wlan1: Initial auth_alg=0
wlan1: authenticate with AP 00:07:cb:55:12:b0
wlan1: authenticate with AP 00:07:cb:55:12:b0
wlan1: authenticate with AP 00:07:cb:55:12:b0
wlan1: authentication with AP 00:07:cb:55:12:b0 timed out
HW CONFIG: channel=4 freq=2427 phymode=2
phy1 -> rt2x00mac_conf_tx: Info - Configured TX ring 0 - CWmin: 4, CWmax: 10, Aifs: 2.
phy1 -> rt2x00mac_conf_tx: Info - Configured TX ring 1 - CWmin: 4, CWmax: 10, Aifs: 2.
phy1 -> rt2x00mac_conf_tx: Info - Configured TX ring 7 - CWmin: 5, CWmax: 10, Aifs: 2.
phy1 -> rt2500usb_init_bbp: Debug - Start initialization from EEPROM...
phy1 -> rt2500usb_init_bbp: Debug - BBP: 0x11, value: 0x32.
phy1 -> rt2500usb_init_bbp: Debug - BBP: 0x15, value: 0x18.
phy1 -> rt2500usb_init_bbp: Debug - BBP: 0x16, value: 0x18.
phy1 -> rt2500usb_init_bbp: Debug - BBP: 0x3e, value: 0x00.
phy1 -> rt2500usb_init_bbp: Debug - ...End initialization from EEPROM.
wlan1: Initial auth_alg=0
wlan1: authenticate with AP 00:07:cb:55:12:b0
wlan1: authenticate with AP 00:07:cb:55:12:b0
wlan1: authenticate with AP 00:07:cb:55:12:b0
wlan1: authentication with AP 00:07:cb:55:12:b0 timed out
etc.

So it never associates, with a timeout for unknown reason.

The device answer correctly to iwlist scan (ie: it sees all AP in my neighborhood). Please also note that I can connect with another Wifi device (bcm43xx based card integrated in my laptop, with every drivers that supports it). Of course, I deactivate the bcm driver before testing the rt28xx USB key.

The wpa_supplicant.conf file contains:
# See /usr/doc/wpa_supplicant-0.5.7/wpa_supplicant.conf.sample
# for many more options that you can use in this file.

# This line enables the use of wpa_cli which is used by rc.wireless
# if possible (to check for successful association)
ctrl_interface=/var/run/wpa_supplicant
# By default, only root (group 0) may use wpa_cli
ctrl_interface_group=0
eapol_version=1
ap_scan=1
fast_reauth=1

# WPA protected network, supply your own ESSID and WPAPSK here:
network={
#  scan_ssid=0
  ssid="MonRezo"
#  proto=WPA
  proto=RSN WPA
  key_mgmt=WPA-PSK
#  pairwise=CCMP TKIP
#  group=CCMP TKIP WEP104 WEP40
  psk="XXXXXXXXXXXX etc."
}


Steps to reproduce:
Totally reproduceable: connect the rt28xx based key on a 64 bits 2.6.24-rc2 kernel, start wpa_supplicant to join the AP network with WPA encryption.
Comment 1 Christian Casteyde 2007-11-17 06:27:53 UTC
I can also reproduce with a 32 bits slackware and with another AP (D-Link DSLG604T). The key fails to authenticate with timeout on "AP 00:00:00:...".
Comment 2 Christian Casteyde 2007-11-24 06:29:03 UTC
This is rt25xx usb and not rt28xx.
Comment 3 ceiphas 2007-12-09 05:06:37 UTC
exactly the same error here with a rt2500 miniPCI card running under kernel 2.6.24-rc4 
Comment 4 ceiphas 2007-12-18 06:23:24 UTC
I can reproduce it, too:

Kernel Data:
Linux ceiphas-desktop 2.6.24-rc4 #4 SMP Thu Dec 6 23:33:38 CET 2007 x86_64 Intel(R) Core(TM)2 CPU 6600 @ 2.40GHz GenuineIntel GNU/Linux

PCI Data:
04:05.0 Network controller [0280]: RaLink RT2500 802.11g Cardbus/mini-PCI [1814:0201] (rev 01)

WLAN Data (WEP Encryption):
          Cell 01 - Address: XX:XX:XX:XX:XX:XX
                    ESSID:"WLAN"
                    Protocol:IEEE 802.11g
                    Mode:Managed
                    Frequency:2.462 GHz (Channel 11)
                    Quality:90/100  Signal level:-47 dBm  Noise level:-96 dBm
                    Encryption key:on
                    Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 11 Mb/s; 6 Mb/s
                              9 Mb/s; 12 Mb/s; 18 Mb/s; 24 Mb/s; 36 Mb/s
                              48 Mb/s; 54 Mb/s
                    Extra:bcn_int=100
                    Extra:atim=0

I can scan, i can connect with ndiswrapper, but not with the builtin drivers

(also tested with a b43 card, same result)
Comment 5 Ivo van Doorn 2008-01-09 10:24:38 UTC
Created attachment 14384 [details]
Fix MAC address initialization

I have just send this patch upstream, this should fix the rt2500usb MAC initialization and most likely will fix this bug.
My kernel is currently recompiling to confirm, but since the bugfix in the patch is obvious, I have a good feeling about it. ;)
Comment 6 Christian Casteyde 2008-01-09 13:24:40 UTC
Association did succeeded (Essid found, AP cell OK, encryption key OK), but DHCP was still unable to get autoconfiguration. I didn't investigated further. Moreover, I got a kernel warning + dump (appended).
Comment 7 Christian Casteyde 2008-01-09 13:25:06 UTC
Created attachment 14387 [details]
kernel dump at device plug in
Comment 8 Ivo van Doorn 2008-01-09 13:32:14 UTC
It's not a panic, but a warning. I have recently submitted a patch to fix that.

According to the log, the association failed with an unspecified reason. (It did manage to authenticate).
But at least there seems to be some progress in rt2500usb now. :)
Comment 9 Christian Casteyde 2008-01-26 06:03:26 UTC
Seems to work with 2.6.24 kernel now.
Thanks a lot. The bitrate is really low (9Mb instead of 54 at 30cm from the AP), but it works.