Bug 730012

Summary: rt2860sta - WPA PSK /w TKIP NetworkManager doesn't wait long enough
Product: [Fedora] Fedora Reporter: Paul Bransford <draeath>
Component: NetworkManagerAssignee: Kernel Maintainer List <kernel-maint>
Status: CLOSED WONTFIX QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 15CC: dcbw, gansalmon, itamar, jklimes, jonathan, kernel-maint, madhu.chinakonda, psimerda
Target Milestone: ---   
Target Release: ---   
Hardware: i686   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-08-07 16:44:27 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Paul Bransford 2011-08-11 14:19:30 UTC
The wireless cards using the rt2860sta module fails to authenticate using WPA PSK-TKIP, most of the time. Occasionally it does succeed in connecting. It appears that NetworkManager does not wait long enough for wpa_supplicant before giving up.

The NetworkManager logs during a connection attempt that fails are below. The process appears to be that it attempts to connect using the key entered earlier (before updating), this "takes too long" and it aborts, asking for a key. Upon cancellation, you can see it falls back on the connected eth0 interface.

(this is a known reliable network)

Hardware specifics:
01:00.0 Network controller: RaLink RT2860
	Subsystem: RaLink Device 2790
	Physical Slot: eeepc-wifi
	Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
	Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
	Latency: 0, Cache Line Size: 32 bytes
	Interrupt: pin A routed to IRQ 19
	Region 0: Memory at f8000000 (32-bit, non-prefetchable) [size=64K]
	Capabilities: <access denied>
	Kernel driver in use: rt2800pci
	Kernel modules: rt2800pci

Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Activation (wlan0) starting connection 'VFI Wireless'
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> (wlan0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Activation (wlan0/wireless): access point 'VFI Wireless' has security, but secrets are required.
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> (wlan0): device state change: config -> need-auth (reason 'none') [50 60 0]
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> (wlan0): device state change: need-auth -> prepare (reason 'none') [60 40 0]
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Activation (wlan0/wireless): connection 'VFI Wireless' has security, and secrets exist.  No new secrets needed.
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Config: added 'ssid' value 'VFI Wireless'
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Config: added 'scan_ssid' value '1'
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Config: added 'key_mgmt' value 'WPA-PSK'
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Config: added 'psk' value '<omitted>'
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Config: added 'proto' value 'WPA RSN'
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> Config: set interface ap_scan to 1
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> (wlan0): supplicant interface state: disconnected -> scanning
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> (wlan0): supplicant interface state: authenticating -> associating
Aug 11 09:57:56 wanderer NetworkManager[862]: <info> (wlan0): supplicant interface state: associating -> disconnected
Aug 11 09:58:20 wanderer NetworkManager[862]: <warn> Activation (wlan0/wireless): association took too long.
Aug 11 09:58:20 wanderer NetworkManager[862]: <info> (wlan0): device state change: config -> need-auth (reason 'none') [50 60 0]
Aug 11 09:58:20 wanderer NetworkManager[862]: <warn> Activation (wlan0/wireless): asking for new secrets
Aug 11 09:58:28 wanderer NetworkManager[862]: <warn> No agents were available for this request.
Aug 11 09:58:28 wanderer NetworkManager[862]: <info> (wlan0): device state change: need-auth -> failed (reason 'no-secrets') [60 120 7]
Aug 11 09:58:28 wanderer NetworkManager[862]: <warn> Activation (wlan0) failed for access point (VFI Wireless)
Aug 11 09:58:28 wanderer NetworkManager[862]: <info> Marking connection 'VFI Wireless' invalid.
Aug 11 09:58:28 wanderer NetworkManager[862]: <warn> Activation (wlan0) failed.
Aug 11 09:58:28 wanderer NetworkManager[862]: <info> (wlan0): device state change: failed -> disconnected (reason 'none') [120 30 0]
Aug 11 09:58:28 wanderer NetworkManager[862]: <info> (wlan0): deactivating device (reason: 0).
Aug 11 09:58:28 wanderer NetworkManager[862]: <info> Policy set 'Wired connection 1' (eth0) as default for IPv4 routing and DNS.
Aug 11 09:58:28 wanderer NetworkManager[862]: <info> Policy set 'Wired connection 1' (eth0) as default for IPv4 routing and DNS.

--------------------------------------

Should the connection succeed, this is seen:

Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Activation (wlan0) starting connection 'VFI Wireless'
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> (wlan0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> (wlan0): supplicant interface state: completed -> disconnected
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Activation (wlan0/wireless): access point 'VFI Wireless' has security, but secrets are required.
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> (wlan0): device state change: config -> need-auth (reason 'none') [50 60 0]
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> (wlan0): device state change: need-auth -> prepare (reason 'none') [60 40 0]
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Activation (wlan0/wireless): connection 'VFI Wireless' has security, and secrets exist.  No new secrets needed.
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Config: added 'ssid' value 'VFI Wireless'
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Config: added 'scan_ssid' value '1'
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Config: added 'key_mgmt' value 'WPA-PSK'
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Config: added 'psk' value '<omitted>'
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Config: added 'proto' value 'WPA RSN'
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> Config: set interface ap_scan to 1
Aug 11 10:12:22 wanderer NetworkManager[862]: <info> (wlan0): supplicant interface state: disconnected -> scanning
Aug 11 10:12:23 wanderer NetworkManager[862]: <info> (wlan0): supplicant interface state: scanning -> associating
Aug 11 10:12:23 wanderer NetworkManager[862]: <info> (wlan0): supplicant interface state: associating -> associated
Aug 11 10:12:24 wanderer NetworkManager[862]: <info> (wlan0): supplicant interface state: associated -> 4-way handshake
Aug 11 10:12:24 wanderer NetworkManager[862]: <info> (wlan0): supplicant interface state: 4-way handshake -> group handshake
Aug 11 10:12:24 wanderer NetworkManager[862]: <info> (wlan0): supplicant interface state: group handshake -> completed
Aug 11 10:12:24 wanderer NetworkManager[862]: <info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'VFI Wireless'.
Aug 11 10:12:24 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
Aug 11 10:12:24 wanderer NetworkManager[862]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
Aug 11 10:12:24 wanderer NetworkManager[862]: <info> (wlan0): device state change: config -> ip-config (reason 'none') [50 70 0]
Aug 11 10:12:24 wanderer NetworkManager[862]: <info> Activation (wlan0) Beginning DHCPv4 transaction (timeout in 45 seconds)

The system then goes on to perform the DHCP transaction and business continues as usual.

dmesg is fairly uneventful:[ 1228.599579] cfg80211: Calling CRDA for country: US
[ 1228.627705] cfg80211: Regulatory domain changed to country: US
[ 1228.627715] cfg80211:     (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[ 1228.627725] cfg80211:     (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
[ 1228.627734] cfg80211:     (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 1700 mBm)
[ 1228.627743] cfg80211:     (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 1228.627752] cfg80211:     (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 1228.627761] cfg80211:     (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 1228.627770] cfg80211:     (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm)
[ 1229.463489] wlan0: authenticate with 00:20:a6:50:ec:7d (try 1)
[ 1229.465161] wlan0: authenticated
[ 1229.465833] wlan0: associate with 00:20:a6:50:ec:7d (try 1)
[ 1229.467855] wlan0: RX ReassocResp from 00:20:a6:50:ec:7d (capab=0x431 status=0 aid=4)
[ 1229.467867] wlan0: associated
[ 1240.594056] wlan0: no IPv6 routers present

However, when it is taking a long time to authenticate this is what is seen (this is where NetworkManager "gives up")
[  261.962241] wlan0: authenticate with 00:20:a6:50:ec:7d (try 1)
[  261.963772] wlan0: authenticated
[  261.976318] wlan0: associate with 00:20:a6:50:ec:7d (try 1)
[  261.980265] wlan0: deauthenticated from 00:20:a6:50:ec:7d (Reason: 6)
[  293.547733] wlan0: authenticate with 00:20:a6:4f:28:0c (try 1)
[  293.551408] wlan0: authenticated
[  293.562458] wlan0: associate with 00:20:a6:4f:28:0c (try 1)
[  293.564821] wlan0: deauthenticated from 00:20:a6:4f:28:0c (Reason: 6)
[  323.738518] wlan0: authenticate with 00:20:a6:4f:28:0c (try 1)
[  323.741426] wlan0: authenticated
[  323.752491] wlan0: associate with 00:20:a6:4f:28:0c (try 1)
[  323.754375] wlan0: deauthenticated from 00:20:a6:4f:28:0c (Reason: 6)
[  363.024440] wlan0: authenticate with 00:20:a6:50:ec:7d (try 1)
[  363.026086] wlan0: authenticated
[  363.033329] wlan0: associate with 00:20:a6:50:ec:7d (try 1)
[  363.038518] wlan0: deauthenticated from 00:20:a6:50:ec:7d (Reason: 6)
[  846.319151] wlan0: authenticate with 00:20:a6:50:ec:7d (try 1)
[  846.328611] wlan0: authenticated
[  846.340163] wlan0: associate with 00:20:a6:50:ec:7d (try 1)
[  846.343466] wlan0: RX AssocResp from 00:20:a6:50:ec:7d (capab=0x431 status=0 aid=12)
[  846.343477] wlan0: associated
[  846.347693] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready

Comment 1 Paul Bransford 2011-08-11 14:20:32 UTC
I apoligize! When originally writing this I had thought it was a kernel problem. It became apparent that it was an issue with NetworkManager during the process, and I failed to update the component I was filing against!

Comment 2 Jirka Klimes 2012-03-26 12:03:01 UTC
Why do you think NM is at fault? Have you successfully connected without NM?
Do you still see the issue? If so, please report:

* dmesg
* nm-tool
* /var/log/messages
* /var/log/wpa_supplicant.log
  (best with debugging on
   see http://live.gnome.org/NetworkManager/Debugging/#wpa_supplicant07)
* rpm -q NetworkManager
* uname -r

Comment 3 Fedora End Of Life 2012-08-07 16:44:30 UTC
This message is a notice that Fedora 15 is now at end of life. Fedora
has stopped maintaining and issuing updates for Fedora 15. It is
Fedora's policy to close all bug reports from releases that are no
longer maintained. At this time, all open bugs with a Fedora 'version'
of '15' have been closed as WONTFIX.

(Please note: Our normal process is to give advanced warning of this
occurring, but we forgot to do that. A thousand apologies.)

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, feel free to reopen
this bug and simply change the 'version' to a later Fedora version.

Bug Reporter: Thank you for reporting this issue and we are sorry that
we were unable to fix it before Fedora 15 reached end of life. If you
would still like to see this bug fixed and are able to reproduce it
against a later version of Fedora, you are encouraged to click on
"Clone This Bug" (top right of this page) and open it against that
version of Fedora.

Although we aim to fix as many bugs as possible during every release's
lifetime, sometimes those efforts are overtaken by events. Often a
more recent Fedora release includes newer upstream software that fixes
bugs or makes them obsolete.

The process we are following is described here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping