Some drivers take too long to associate (Was: network-manager 0.7 always asks for WPA passphrase)

Bug #292054 reported by Lorenzo on 2008-11-01
106
This bug affects 12 people
Affects Status Importance Assigned to Milestone
NetworkManager
In Progress
Medium
network-manager (Fedora)
New
Undecided
Unassigned
network-manager (Ubuntu)
High
Alexander Sack
Intrepid
High
Alexander Sack

Bug Description

Verify:
1. ensure that you are affected: NM connect times out after 25 seconds + wpasupplicant takes more than ~25 seconds to connect manually
2. test that new package either succeeds or takes 60 seconds before giving up.

Binary package hint: network-manager

Ububtu 8.10
network-manager 0.7~~svn20081018t105859-0ubuntu1

Every time, after a reboot NM ask for the WPA passphase, even if it was correctly stored.
The same occours after a disconnection.

Here below the daemon log after disabling/enabling wireless. Please note the two rows in the log:

>> "connection 'Auto LORENZO' has security, and secrets exist. No new secrets needed. "
and
>>> "<info> Activation (ath0/wireless): asking for new secrets "

At that point NM applet asks for a new passphase even if the old one is showed.
I just rewrite the passphrase, click "Connect" and the connection restarts correctly.

ov 1 11:15:14 ncc-1701e NetworkManager: <WARN> nm_device_wifi_set_enabled(): not in expected unavailable state!
Nov 1 11:15:14 ncc-1701e NetworkManager: <info> (ath0): bringing up device.
Nov 1 11:15:14 ncc-1701e NetworkManager: <info> (ath0): device state change: 2 -> 3
Nov 1 11:15:14 ncc-1701e NetworkManager: <info> (ath0): supplicant interface state change: 1 -> 2.
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Activation (ath0) starting connection 'Auto LORENZO'
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> (ath0): device state change: 3 -> 4
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) scheduled...
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) started...
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) scheduled...
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) complete.
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) starting...
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> (ath0): device state change: 4 -> 5
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Activation (ath0/wireless): access point 'Auto LORENZO' has security, but secrets are required.
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> (ath0): device state change: 5 -> 6
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) complete.
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) scheduled...
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) started...
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> (ath0): device state change: 6 -> 4
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) scheduled...
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) complete.
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) starting...
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> (ath0): device state change: 4 -> 5
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Activation (ath0/wireless): connection 'Auto LORENZO' has security, and secrets exist. No new secrets needed.
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Config: added 'ssid' value 'LORENZO'
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Config: added 'scan_ssid' value '1'
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Config: added 'key_mgmt' value 'WPA-PSK'
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Config: added 'psk' value '<omitted>'
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Config: added 'proto' value 'WPA RSN'
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Config: added 'pairwise' value 'TKIP CCMP'
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Config: added 'group' value 'WEP40 WEP104 TKIP CCMP'
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) complete.
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> Config: set interface ap_scan to 1
Nov 1 11:15:43 ncc-1701e NetworkManager: <info> (ath0): supplicant connection state change: 2 -> 0
Nov 1 11:15:44 ncc-1701e NetworkManager: <info> (ath0): supplicant connection state change: 0 -> 2
Nov 1 11:15:44 ncc-1701e NetworkManager: <info> (ath0): supplicant connection state change: 2 -> 3
Nov 1 11:15:54 ncc-1701e NetworkManager: <info> (ath0): supplicant connection state change: 3 -> 0
Nov 1 11:15:54 ncc-1701e NetworkManager: <info> (ath0): supplicant connection state change: 0 -> 2
Nov 1 11:15:54 ncc-1701e NetworkManager: <info> (ath0): supplicant connection state change: 2 -> 3
Nov 1 11:15:58 ncc-1701e NetworkManager: <info> ath0: link timed out.
Nov 1 11:16:04 ncc-1701e NetworkManager: <info> (ath0): supplicant connection state change: 3 -> 0
Nov 1 11:16:04 ncc-1701e NetworkManager: <info> (ath0): supplicant connection state change: 0 -> 3
Nov 1 11:16:08 ncc-1701e NetworkManager: <info> Activation (ath0/wireless): association took too long.
Nov 1 11:16:08 ncc-1701e NetworkManager: <info> (ath0): device state change: 5 -> 6
Nov 1 11:16:08 ncc-1701e NetworkManager: <info> Activation (ath0/wireless): asking for new secrets
Nov 1 11:16:08 ncc-1701e NetworkManager: <info> (ath0): supplicant connection state change: 3 -> 0
Nov 1 11:16:23 ncc-1701e NetworkManager: <info> ath0: link timed out.
Nov 1 11:16:44 ncc-1701e NetworkManager: <info> (ath0): supplicant connection state change: 0 -> 2
Nov 1 11:17:50 ncc-1701e NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) scheduled...
Nov 1 11:17:50 ncc-1701e NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) started...
Nov 1 11:17:50 ncc-1701e NetworkManager: <info> (ath0): device state change: 6 -> 4
Nov 1 11:17:50 ncc-1701e NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) scheduled...
Nov 1 11:17:50 ncc-1701e NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) complete.
Nov 1 11:17:50 ncc-1701e NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) starting...
Nov 1 11:17:50 ncc-1701e NetworkManager: <info> (ath0): device state change: 4 -> 5
Nov 1 11:17:50 ncc-1701e NetworkManager: <info> Activation (ath0/wireless): connection 'Auto LORENZO' has security, and secrets exist. No new secrets needed.
Nov 1 11:17:50 ncc-1701e NetworkManager: <info> Config: added 'ssid' value 'LORENZO'
Nov 1 11:17:50 ncc-1701e NetworkManager: <info> Config: added 'scan_ssid' value '1'
Nov 1 11:17:50 ncc-1701e NetworkManager: <info> Config: added 'key_mgmt' value 'WPA-PSK'
Nov 1 11:17:50 ncc-1701e NetworkManager: <info> Config: added 'psk' value '<omitted>'
Nov 1 11:17:50 ncc-1701e NetworkManager: <info> Config: added 'proto' value 'WPA RSN'
Nov 1 11:17:50 ncc-1701e NetworkManager: <info> Config: added 'pairwise' value 'TKIP CCMP'
Nov 1 11:17:50 ncc-1701e NetworkManager: <info> Config: added 'group' value 'WEP40 WEP104 TKIP CCMP'
Nov 1 11:17:50 ncc-1701e NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) complete.
Nov 1 11:17:50 ncc-1701e NetworkManager: <info> (ath0): supplicant connection state change: 2 -> 0
Nov 1 11:17:50 ncc-1701e NetworkManager: <info> Config: set interface ap_scan to 1
Nov 1 11:17:50 ncc-1701e NetworkManager: <info> (ath0): supplicant connection state change: 0 -> 2
Nov 1 11:18:00 ncc-1701e NetworkManager: <info> (ath0): supplicant connection state change: 2 -> 3
Nov 1 11:18:00 ncc-1701e NetworkManager: <info> (ath0): supplicant connection state change: 3 -> 4
Nov 1 11:18:00 ncc-1701e NetworkManager: <info> (ath0): supplicant connection state change: 4 -> 5
Nov 1 11:18:00 ncc-1701e NetworkManager: <info> (ath0): supplicant connection state change: 5 -> 6
Nov 1 11:18:00 ncc-1701e NetworkManager: <info> (ath0): supplicant connection state change: 6 -> 7
Nov 1 11:18:00 ncc-1701e NetworkManager: <info> Activation (ath0/wireless) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'LORENZO'.

Lorenzo (lorped) on 2008-11-01
description: updated
Alexander Sack (asac) wrote :

this smells like a timing issue and slow drivers. Please test the latest intrepid packages from the network-manager team test archive (PPA): http://launchpad.net/~network-manager/+archive.

Changed in network-manager:
status: New → Incomplete

Alexander,
I installed from the PPA repository the folowing packages

network-manager 0.7~~svn20081018t105859-0ubuntu2~nm4
libnm-glib0 0.7~~svn20081018t105859-0ubuntu2~nm4
libnm-util0 0.7~~svn20081018t105859-0ubuntu2~nm4
libmbca0 0.0.3~bzr42-0ubuntu3~nm1

And the problem disappeared at the first connection after the login and
also on subsequently disabling/enabling the wireless adapter.

Thanks for your support. :)

Alexander Sack (asac) wrote :

we should give them more time. like the ~network-manager PPA package currently proposes.

This issue is about atheros, but we also have bug 263963 which is about iwl drivers; and dont forget the WPA-Enterprise issues we solved with such a timeout patch.

Changed in network-manager:
importance: Undecided → High
status: Incomplete → Triaged
Alexander Sack (asac) wrote :

nominating for intrepid updates ... though that patch is already nominated to fix WPA Enterprise PEAP Use-Case (like bug 272185)

Changed in network-manager:
importance: Undecided → High
milestone: none → intrepid-updates
status: New → Triaged
David (david-kahn) wrote :

The NetworkManager is disabling my ethernet card and making it impossible to login to Intrepid, and I wonder if this is a related problem. The ethernet works fine in single user recovery mode, but it has been impossible to log into my machine for three days. I am desperate.

uname -a (in single user mode) returns:
  Linux CERTIBY-DEV1 2.6.27-7-generic #1 SMP Thu Oct 30 04:12:22 UTC 2008 x86_64 GNU/Linux

I upgraded from Hardy (which worked fine) using sudo do-release-upgrade

In /var/log/daemon.log I see:

   CERTIBY-DEV1 NetworkManager <info> (eth0) device state change: 1 -> 2
   CERTIBY-DEV1 NetworkManager <info> (eth0) preparing device.
   CERTIBY-DEV1 NetworkManager <info> (eth0) deactivating device.
   CERTIBY-DEV1 NetworkManager <WARN> check_one_route(): (eth0) error -34 returned from rtnl_route_del(): Sucess
   CERTIBY-DEV1 avahi-daemon [5382]: Withdrawing address record for 10.10.10.84 on eth0.
   CERTIBY-DEV1 avahi-daemon [5382]: Leaving mDNS multicast group on interface eth0.IPv4 with address 10.10.10.84.
   CERTIBY-DEV1 avahi-daemon [5382]: Interface eth0.IPv4 no longer relevant for mDNS.
   CERTIBY-DEV1 NetworkManager <info> Setting system hostname to 'localhost@localdomain' (no default device)
   CERTIBY-DEV1 NetworkManager <info> (eth0) device state change: 2 -> 3

Alexander Sack (asac) wrote :

David, ethernet card issues are clearnly not covered in this bug. open new bugs if you are unsure instead of adding stuff to whatever thing sounds related. Thanks.

Martin Pitt (pitti) on 2008-11-04
Changed in network-manager:
assignee: nobody → asac
assignee: nobody → asac

Alex not sure if this is where I should post this.
This are logs of trying to connect to a FON WPA2 network

FYI I have no trouble with other domestic WPA/WPA2 networks. Just yesterday NM connected just after GDM started.

I'm inclined to think that some of this time outs (here and on bug 272185) are related to remote authentication schemes.

MarkS (mark-marksyms) wrote :

 BUGabundo - I suspect you're onto something.

My problems relate to our corporate network where the authentication is backed by our active directory domain and it works fine on my home PSK network. Of course, we also have a load of APs in the office to ensure coverage of the entire building and that may also be a factor as the association tries to roam between three different APs when sitting in the same location. I suspect, although I don't know enough about WLAN to be sure, that roaming to a new AP whilst in the middle of authenticating is a bad thing.

Alexander Sack (asac) wrote :

if you see this on some APs (but not all), could you check whether your AP is in A, G or N mode?

Alexander Sack (asac) wrote :

MarkS, could you try to create a wireless connection in connection-editor and set a fixed BSSID (for any of those 3 APs) and see if it doesnt roam anymore? Maybe that helps?

@asac AFAICR they are all G networks.
At my universaty some APs also have A networks, but I cant really tell to what I'm connecting

Is there a way via driver or NM to select the protocol?

caspar_wrede (caspar-wrede) wrote :

I have a similar issue (WPA always/often asking for passphrase).

It also seems to result in WLAN access not working at all after a suspend. This is a regression bug from hardy.

I have a thinkpad X31 with an atheros card.

I couldn't get NetworkManager+knetworkmanager to connect at all to my wifi network (using thinkpad t42 with atheros card). It looked like wpa_supplicant was timing out. Upgrading to the PPA packages fixed the issue.

@BUGabundo: you can set mode using 'iwpriv ath0 mode x' where x is an integer specifying the protocol 1=a, 2=b, 3=g. You can check what you're currently using with 'iwconfig ath0'. Note that this is for an atheros card - substitute ath0 with your device - also your driver might not support iwpriv mode setting anyway, try 'iwpriv ath0' to get a list of your supported ioctl commands.

David M (david-mathy) wrote :

I'm getting the same problem @ work, when connecting to a WPA2-PSK PEAP.
Just for your information, I tried Fedora 9 Live (usb), and I've got the same problem.

Alexander Sack (asac) on 2008-11-28
description: updated
Alexander Sack (asac) on 2008-11-28
Changed in network-manager:
status: Triaged → Fix Committed
Alexander Sack (asac) wrote :

upload SRU: network-manager_0.7~~svn20081018t105859-0ubuntu1.8.10.1_source.changes to ubuntu/intrepid-proposed

Changed in network-manager:
status: Triaged → In Progress
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package network-manager - 0.7~~svn20081018t105859-0ubuntu2

---------------
network-manager (0.7~~svn20081018t105859-0ubuntu2) jaunty; urgency=low

  * fix LP: #292054 - Some drivers take too long to associate (Was:
    network-manager 0.7 always asks for WPA passphrase); we workaround
    this driver/wpasupplicant bug by giving association more time
    (e.g. 60sec instead of 25sec)
    - add debian/patches/lp292054_tune_supplicant_timeout_60s.patch
    - update debian/patches/series
  * fix LP: #256905 - dbus policy file (nm-avahi-autoipd.conf) not properly
    deployed in package; install nm-avahi-autoipd.conf
    - update debian/network-manager.install
  * fix LP: #282207 - [Sierra] NM 0.7 does not set APN for AT&T 3G connection;
    apply fix from Jerone Young
    - add debian/patches/lp282207_set_apn_at_syntax.patch
    - update debian/patches/series
  * fix LP: #268667 - not all required ppp options get set on command line
    which makes ppp use bad values from /etc/ppp/options; we backport upstream
    fix
    - add debian/patches/lp268667_more_ppp_default_options.patch
    - update debian/patches/series
  * fix LP: #291564 - ifupdown network manager does not blacklist/unmanage
    mapped devices in managed=false mode; thanks to Stephan Trebels for the
    patch
    - add debian/patches/lp291564_ifupdown_unmanage_mapping_and_iface.patch
    - update debian/patches/series
  * fix LP: #291902 - ifupdown plugin should not export any parsed connection
    configuration when running in managed=false mode; we fix this by exporting
    empty connection list in unmanaged mode
    - add debian/patches/lp291902_IFUPDOWN_dont_export_connection_in_unmanaged_mode.patch
    - update debian/patches/series
  * belt-and-braces fix LP: #290468 VPN fails, "/usr/bin/nm-ppp-starter
    missing"; we remove obsolete conffiles in -pptp .preinst; in case user
    modified them they will be renamed to .dpkg-bak; this patch takes care that
    NM doesn't consider files in /etc/NetworkManager/VPN that don't have a
    .name filename suffix.
    - add debian/patches/lp290468_only_consider_name_suffix_VPN_service_files.patch
    - update debian/patches/series
  * fix LP: #303142 - 3G [Option] some modems take a while time to register on
    network (CREG); we use g_timeout_add instead of _idle_add to give the
    modem some rest during registration phase.
    - add debian/patches/lp303142_more_time_for_automatic_registration.patch
    - update debian/patches/series

 -- Alexander Sack <email address hidden> Fri, 28 Nov 2008 13:47:07 +0100

Changed in network-manager:
status: Fix Committed → Fix Released
Martin Pitt (pitti) wrote :

Accepted network-manager into intrepid-proposed, please test and give feedback here. Please see https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you in advance!

Changed in network-manager:
milestone: intrepid-updates → none
status: In Progress → Fix Committed

Please revert this.
network-manager (0.7~~svn20081018t105859-0ubuntu2) jaunty; urgency=low
just broke my wpa.
Now it wont connect and just times out

worksforme

On Fri, Nov 28, 2008 at 06:08:32PM -0000, BUGabundo wrote:
> Please revert this.
> network-manager (0.7~~svn20081018t105859-0ubuntu2) jaunty; urgency=low
> just broke my wpa.
> Now it wont connect and just times out

There is nothing in this upload that could make such issues appear for
your. I already asked you on irc that you can get rid of this issue by
downgrading your packages again. Please do that!

Thanks!

 - Alexander

Haldo (haldonebkp) wrote :

The workaround is not working for me.
I have to wait more time before being asked again for data, but I still receive the same message.
In attach my daemon.log

Thank you

Haldo

Alex today on wpa entreprise it seems to be working.
No idea why it wouldnt connect to wpa shared.

Sorry for the noise.

jasonwc (jwittlincohen) wrote :

I'm still having timeout problems with the new package. PEAPv0/MSCHAPv2 will occasionally connect whereas EAP-TLS consistently fails to connect. The bizarre part is that the majority of the time the RADIUS server doesn't even get a request for authentication, and when it does get a request, the user is authenticated properly, yet the connection still fails. I know there is no issue with the RADIUS server because with Juniper or Intel's supplicant, authentication takes 1-3 seconds, at most.

I have also noticed that after a successful connection, I can reconnect without re-authenticating with the RADIUS server despite the fact that my RADIUS server does not have pre-authentication or session resumption enabled. All three windows supplicants (Juniper Access Client, Intel ProSet Wireless Client, and XP's supplicant) re-authenticate upon a new connection attempt. However, there is absolutely no activity in the FreeRadius debug output when network-manager reconnects. In addition, 75% of connection attempts do not lead to an authentication attempt with the RADIUS server. Of those that do, authentication is always successful, but network-manager doesn't always connect properly. As I mentioned earlier, I have yet to connect once successfully with EAP-TLS.

Alexander Sack (asac) wrote :

jasonwc, can you please check that the timeout is now 60s?

Launchpad Janitor (janitor) wrote :

This bug was fixed in the package network-manager - 0.7~~svn20081018t105859-0ubuntu1.8.10.1

---------------
network-manager (0.7~~svn20081018t105859-0ubuntu1.8.10.1) intrepid-proposed; urgency=low

  * fix LP: #292054 - Some drivers take too long to associate (Was:
    network-manager 0.7 always asks for WPA passphrase); we workaround
    this driver/wpasupplicant bug by giving association more time
    (e.g. 60sec instead of 25sec)
    - add debian/patches/lp292054_tune_supplicant_timeout_60s.patch
    - update debian/patches/series
  * fix LP: #256905 - dbus policy file (nm-avahi-autoipd.conf) not properly
    deployed in package; install nm-avahi-autoipd.conf
    - update debian/network-manager.install
  * fix LP: #282207 - [Sierra] NM 0.7 does not set APN for AT&T 3G connection;
    apply fix from Jerone Young
    - add debian/patches/lp282207_set_apn_at_syntax.patch
    - update debian/patches/series
  * fix LP: #268667 - not all required ppp options get set on command line
    which makes ppp use bad values from /etc/ppp/options; we backport upstream
    fix
    - add debian/patches/lp268667_more_ppp_default_options.patch
    - update debian/patches/series
  * fix LP: #291564 - ifupdown network manager does not blacklist/unmanage
    mapped devices in managed=false mode; thanks to Stephan Trebels for the
    patch
    - add debian/patches/lp291564_ifupdown_unmanage_mapping_and_iface.patch
    - update debian/patches/series
  * fix LP: #291902 - ifupdown plugin should not export any parsed connection
    configuration when running in managed=false mode; we fix this by exporting
    empty connection list in unmanaged mode
    - add debian/patches/lp291902_IFUPDOWN_dont_export_connection_in_unmanaged_mode.patch
    - update debian/patches/series
  * belt-and-braces fix LP: #290468 VPN fails, "/usr/bin/nm-ppp-starter
    missing"; we remove obsolete conffiles in -pptp .preinst; in case user
    modified them they will be renamed to .dpkg-bak; this patch takes care that
    NM doesn't consider files in /etc/NetworkManager/VPN that don't have a
    .name filename suffix.
    - add debian/patches/lp290468_only_consider_name_suffix_VPN_service_files.patch
    - update debian/patches/series
  * fix LP: #303142 - 3G [Option] some modems take a while time to register on
    network (CREG); we use g_timeout_add instead of _idle_add to give the
    modem some rest during registration phase.
    - add debian/patches/lp303142_more_time_for_automatic_registration.patch
    - update debian/patches/series

 -- Alexander Sack <email address hidden> Fri, 28 Nov 2008 13:48:34 +0100

Changed in network-manager:
status: Fix Committed → Fix Released
jasonwc (jwittlincohen) wrote :

Alexander,

I can confirm that the 0.7~~svn20081018t105859-0ubuntu1.8.10.1 update waits 60 seconds before giving a timeout error. Through my testing I have discovered two separate bugs, the first of which is mitigated by this package.

1. Some drivers take too long to associate with the 2.6.27 kernel (tested WG511T and Intel 4965AGN chipsets). This delay is NOT present in the 2.6.24 kernel from Hardy.

2.EAP-TLS does not work under any configuration (tested with 2.6.24, 2.6.27, NM 0.6 and 0.7, wpasupplicant from hardy and intrepid, and every combination of kernel, network-manager, and wpasupplicant). With the latest patch, the server shows a successful authentication each time I try to connect, but the connection always fails with a timeout message on the client side.

I reported these issues in Bug # 35836 but I think #1 should be reported as a kernel problem, and #2 separated.

jasonwc (jwittlincohen) wrote :

PEAPv0/EAP-MSCHAPv2 and EAP-TTLS/MSCHAPv2 both connect every time under kernel 2.6.27. It just takes longer than 2.6.24. If you would like me to test any other configurations I have a FreeRADIUS at my disposal.

jasonwc (jwittlincohen) wrote :

That should read "FreeRADIUS server".

jasonwc (jwittlincohen) wrote :

I gave the wrong bug # earlier. The bug I reported was Bug #307622 (Ubuntu fails to reliably associate with WPA2-Enterprise networks using either the WG511T (AR5212) or Intel 4965AGN wireless chipsets with 2.6.27 kernel).

After some testing, I think this is a wpa_supplicant problem. If I configure /etc/network/interfaces and use "ifup" then the time from typing that command to actually having an IP address is around 15 seconds. If I use NetworkManager then the time is over 1 minute. It looks as though wpa_supplicant is doing some odd things, and it takes over 50 seconds to associate. I will attach a log of the very slow (>1 minute) network connection, and another fast (15 seconds or so) connection using "ifup" for comparison. Note that in testing this I used a global WEP password in NetworkManager, which didn't work until I used the patch in bug #288963.

It would be useful if someone else could confirm this by configuring /etc/network/interfaces and comparing the start time to NetworkManager. It seems to be a different issue to the kernel regression reported by jasonwc. Alternatively the following commands will do the same if you use WEP, the modprobe stuff just ensures that the kernel drivers are started from a fresh state - skip them if you don't use an Atheros card:

ifconfig ath0 down

modprobe -r ath_pci
modprobe -r ath_rate_sample
modprobe -r ath_hal
modprobe ath_hal
modprobe ath_rate_sample
modprobe ath_pci

iwconfig ath0 mode managed
iwconfig ath0 key 1111-2222-33
iwconfig ath0 essid mywifinet
ifconfig ath0 up
dhclient

Changed in network-manager:
status: Unknown → Confirmed

The bug seems to be in some interaction to do with NetworkManager or the DBUS interface. If I put a WEP config in /etc/wpa_supplicant/ and do:

/sbin/wpa_supplicant -d -t -iath0 -c/etc/wpa_supplicant/wpa_supplicant.conf

Then wpa_supplicant will associate in just over 10 seconds. Log attached. Comparing the State changes to operating via NetworkManager/DBUS: with lone wpa_supplicant we get states:

1229956617.602179: State: DISCONNECTED -> SCANNING
1229956617.608634: State: SCANNING -> ASSOCIATING
1229956626.819271: State: ASSOCIATING -> ASSOCIATED
1229956626.819527: State: ASSOCIATED -> COMPLETED

With NetworkManager/DBUS we get states:

1229894071.010839: State: DISCONNECTED -> SCANNING
1229894071.011231: State: SCANNING -> INACTIVE
1229894071.013447: State: INACTIVE -> SCANNING
1229894080.172201: State: SCANNING -> DISCONNECTED
1229894081.145672: State: DISCONNECTED -> SCANNING
1229894086.262912: State: SCANNING -> ASSOCIATING
1229894096.265724: State: ASSOCIATING -> DISCONNECTED
1229894096.266842: State: DISCONNECTED -> SCANNING
1229894101.378873: State: SCANNING -> ASSOCIATING
1229894111.381811: State: ASSOCIATING -> DISCONNECTED
1229894111.383023: State: DISCONNECTED -> SCANNING
1229894131.663788: State: SCANNING -> ASSOCIATING
1229894131.675183: State: ASSOCIATING -> ASSOCIATED
1229894131.676322: State: ASSOCIATED -> COMPLETED

Clearly something odd is going on with NetworkManager interaction that causes these disconnected states whilst trying to associate. I think bug #272185 might be related and some people reported the same issue in bug #264881.

I just found bug #259157 ... it has some similar reports to this one.

Alexander Sack (asac) wrote :

On Mon, Dec 22, 2008 at 03:00:39PM -0000, Chris Bainbridge wrote:
> The bug seems to be in some interaction to do with NetworkManager or the
> DBUS interface. If I put a WEP config in /etc/wpa_supplicant/ and do:
>
> /sbin/wpa_supplicant -d -t -iath0
> -c/etc/wpa_supplicant/wpa_supplicant.conf
>
> Then wpa_supplicant will associate in just over 10 seconds. Log
> attached. Comparing the State changes to operating via
> NetworkManager/DBUS: with lone wpa_supplicant we get states:
>
> 1229956617.602179: State: DISCONNECTED -> SCANNING
> 1229956617.608634: State: SCANNING -> ASSOCIATING
> 1229956626.819271: State: ASSOCIATING -> ASSOCIATED
> 1229956626.819527: State: ASSOCIATED -> COMPLETED
>
> With NetworkManager/DBUS we get states:
>
> 1229894071.010839: State: DISCONNECTED -> SCANNING
> 1229894071.011231: State: SCANNING -> INACTIVE
> 1229894071.013447: State: INACTIVE -> SCANNING
> 1229894080.172201: State: SCANNING -> DISCONNECTED

please try to put exactly the config paramaters you see in syslog by
NM in your wpa_supplicant.conf ... does that make the manual case
behave similar to NM?

 - Alexander

I tested again with a different AP, open AP so no WEP or WPA, borrowed this AP just for testing so no other users, AP next to test PC (64/70 signal). Using wpasupplicant-0.6.4-2 and network-manager-0.7-0ubuntu1~nm1~intrepid1. Config in /etc/NetworkManager so no front-end delay. Hopefully this will eliminate any potential issues.

Conclusions: associating with wpa_supplicant takes ~60 seconds. Total connect time with NetworkManager is ~70 seconds. Manual 'ifup' takes ~15 seconds. wpa_supplicant goes through the same numerous states as before. Again, this is with no authentication necessary.

> please try to put exactly the config paramaters you see in syslog by
> NM in your wpa_supplicant.conf ... does that make the manual case
> behave similar to NM?

The config is exactly the same - there is not much to configure - only ssid, scan_ssid=1, key_mgmt=NONE, priority=1.
The manual case associates in ~10 seconds.

Steps to reproduce:
In one terminal run: wpa_supplicant -u -d -t
In another terminal run: NetworkManager --no-daemon
You should see wpa_supplicant going through many states before associating.
Then terminate both processes and try: wpa_supplicant -iath0 -c/etc/wpa_supplicant/wpa_supplicant.conf -d -t

Alexander Sack (asac) wrote :

On Tue, Dec 30, 2008 at 01:43:37AM -0000, Chris Bainbridge wrote:
> I tested again with a different AP, open AP so no WEP or WPA, borrowed
> this AP just for testing so no other users, AP next to test PC (64/70
> signal). Using wpasupplicant-0.6.4-2 and network-
> manager-0.7-0ubuntu1~nm1~intrepid1. Config in /etc/NetworkManager so no
> front-end delay. Hopefully this will eliminate any potential issues.
>
> Conclusions: associating with wpa_supplicant takes ~60 seconds. Total
> connect time with NetworkManager is ~70 seconds. Manual 'ifup' takes ~15
> seconds. wpa_supplicant goes through the same numerous states as before.
> Again, this is with no authentication necessary.
>
> > please try to put exactly the config paramaters you see in syslog by
> > NM in your wpa_supplicant.conf ... does that make the manual case
> > behave similar to NM?
>
> The config is exactly the same - there is not much to configure - only ssid, scan_ssid=1, key_mgmt=NONE, priority=1.
> The manual case associates in ~10 seconds.
>
> Steps to reproduce:
> In one terminal run: wpa_supplicant -u -d -t
> In another terminal run: NetworkManager --no-daemon
> You should see wpa_supplicant going through many states before associating.
> Then terminate both processes and try: wpa_supplicant -iath0 -c/etc/wpa_supplicant/wpa_supplicant.conf -d -t
>

We should look into why wpasupplicant takes so much longer then.

Can you please enable debugging for wpasupplicant in both cases and
post the complete wpasupplicant snippet for both attempts (e.g. manual
+ through NM)?

For the NM wpasupplicant change the command in
/usr/share/dbus-1/system-services/fi.epitest.hostap.WPASupplicant.service
to output debug stuff and do a killall wpa_supplicant.

Thanks!

 - Alexander

Jeremy Nickurak (nickurak) wrote :

I see the symptoms of this bug, but usually only when I'm on an 802.1x network (or at least substantially more frequently). Running "sudo killall -9 wpa_supplicant" sometimes gets it behaving better, but I don't have anything concrete to back that up, and sooner or later the behavior crops up again, so it may just be my imagination.

Alexander Sack (asac) wrote :

On Wed, Jan 28, 2009 at 05:19:16PM -0000, Jeremy Nickurak wrote:
> I see the symptoms of this bug, but usually only when I'm on an 802.1x
> network (or at least substantially more frequently). Running "sudo
> killall -9 wpa_supplicant" sometimes gets it behaving better, but I
> don't have anything concrete to back that up, and sooner or later the
> behavior crops up again, so it may just be my imagination.
>

Yes, sounds driver issue-like. You think you could try a newer kernel
like the one from jaunty?

 - Alexander

This seems to be the crucial bit in the logs:

1230757793.729916: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1230757793.730072: RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
1230757793.730156: Wireless event: cmd=0x8b15 len=20
1230757793.730175: Wireless event: new AP: 00:0f:cb:ae:62:62

sometimes we don't get this and authentication times out, the AP is
blacklisted, and then about 60s passes before the AP is un-blacklisted and
authentication happens.

I don't know what causes this LOWER_UP / "new AP" event, or why it doesn't
occur sometimes.

I have tried the ath5k driver from linux-backports-modules package and still saw the bug.

I got a new wifi USB card with a different chipset to eliminate the driver as a source of error. Using zd1211rw chipset / driver this issue does not occur (associated 20 times without a single wpa_supplicant timeout). So the problem is probably with the madwifi driver. It would be useful if others that see this problem could mention whether their driver is madwifi or not.

Alex,

At your suggestion I tried linux-image-2.6.28-6-generic. I no longer see the very long delay that leads to wpa_supplicant timing out and blacklisting the AP leading to >60s association.

Jaunty ath5k is still slow though - comparing ath5k to zd1211rw over repeated runs I get a statistically significant mean time (from starting NetworkManager to binding an IP address) of 21 seconds versus 9 seconds respectively.

There also seems to be some new problem with Jaunty, I'm seeing the following error repeated every so often: NetworkManager: <debug> [1233236271.814432] periodic_update(): Roamed from BSSID 00:1D:68:0A:xx:yy (nameofwap) to (none) ((none))
Why would it try to roam to a non-existent AP? During the couple of seconds this happens it seems like packets are dropped.

I take back the statement about the roaming causing packet loss - even with the Zydas card NetworkManager reports a roam to "none" for about 6 seconds, but it doesn't seem to actually cause any problems.

However, the throughput of ath5k is very poor. I'm running ping whilst transferring a single 435MB file with scp to test both bandwidth and latency.

With Zydas card and zd1211rw driver: ping from 1ms to 35ms. Bandwidth 2.1MB/s.
With Atheros card and ath5k driver: ping from 1ms to 3500ms. Bandwidth 573KB/s.

Atheros card is internal on a Thinkpad T42p laptop, Zydas card is USB. Even accounting for hardware differences, the performance variance is extreme - changing wifi chipset/driver should not cause 4x bandwidth difference when everything else is identical.

The brand of Zydas card I'm testing with is "Safe Home" - www.safehome.com.tw - appears to be a Taiwanese manufacturer that ships direct on ebay, shipping to Europe took around 3 days. Manufacturer supports Linux and the card is cheap and working good so far. http://stores.ebay.co.uk/SAFE-HOME-Online-Shop - I have the one with internal antenna.

This testing was done with the Jaunty kernel.

I just realised that when I tested the jaunty kernel I didn't upgrade linux-restricted-modules, so I was only testing ath_pci. To clarify:

With 2.6.28-6 kernel and ath5k module, I see the slow bandwidth and high pings noted above. It might be something to do with this error in the logs "ath5k phy0: noise floor calibration timeout (2437MHz)"

With 2.6.28-6 kernel and ath_pci module from linux-restricted-modules-2.6.28-6, I still see the slow association (timeout/blacklist) bug noted above "ath0: link timed out."

Changed in network-manager:
status: Confirmed → In Progress

On Thu, Jan 29, 2009 at 01:59:26PM -0000, Chris Bainbridge wrote:
> There also seems to be some new problem with Jaunty, I'm seeing the following error repeated every so often: NetworkManager: <debug> [1233236271.814432] periodic_update(): Roamed from BSSID 00:1D:68:0A:xx:yy (nameofwap) to (none) ((none))
> Why would it try to roam to a non-existent AP? During the couple of seconds this happens it seems like packets are dropped.
>

For jaunty regressions please open new bugs so we can track them
individually. Remember to give us your bug id. BTW, NM usually dumps
the above into to the syslog if the driver shows a changed
BSSID. If there really is no such BSSID around please mention that in
bug.

Give us your bug id. Thanks!

 - Alexander

I have opened bug #337311 regarding the ath5k performance problems in Jaunty. I have re-tested today and it appears that some performance loss has already been fixed upstream in compat-wireless-2009-03-03. I do not know when this upstream version will appear in the Jaunty kernel.

"network-manager roams to (none) ((none))" has already been reported as bug #291760, however it appears to be a harmless message related to losing the connection to the AP (at least with the latest ath5k driver).

Kevint (ktreadwell) on 2009-08-16
Changed in network-manager (Ubuntu):
assignee: Alexander Sack (asac) → Kevint (ktreadwell)
Martin Pitt (pitti) on 2009-08-27
Changed in network-manager (Ubuntu):
assignee: Kevint (ktreadwell) → Alexander Sack (asac)
Download full text (3.9 KiB)

I have a similar but slightly different issue. wpa_supplicant associates fine, but network-manager times out waiting for dhclient to finish. If I run dhclient manually (from /etc/network/interfaces) then everything is fine.

NetworkManager: <info> Activation (wlan0) starting connection 'Auto HWAP0105'
NetworkManager: <info> (wlan0): device state change: 3 -> 4
NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager: <info> (wlan0): supplicant connection state change: 7 -> 0
NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
NetworkManager: <info> (wlan0): device state change: 4 -> 5
NetworkManager: <info> Activation (wlan0/wireless): connection 'Auto HWAP0105' has security, and secrets exist. No new secrets needed.
NetworkManager: <info> Config: added 'ssid' value 'HWAP0105'
NetworkManager: <info> Config: added 'scan_ssid' value '1'
NetworkManager: <info> Config: added 'key_mgmt' value 'WPA-PSK'
NetworkManager: <info> Config: added 'psk' value '<omitted>'
NetworkManager: <info> Config: added 'proto' value 'WPA RSN'
NetworkManager: <info> Config: added 'pairwise' value 'TKIP CCMP'
NetworkManager: <info> Config: added 'group' value 'WEP40 WEP104 TKIP CCMP'
NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
NetworkManager: <info> Config: set interface ap_scan to 1
NetworkManager: <info> (wlan0): supplicant connection state change: 0 -> 2
NetworkManager: <info> (wlan0): supplicant connection state change: 2 -> 3
NetworkManager: <info> (wlan0): supplicant connection state change: 3 -> 0
NetworkManager: <info> (wlan0): supplicant connection state change: 0 -> 4
NetworkManager: <info> (wlan0): supplicant connection state change: 4 -> 5
NetworkManager: <info> (wlan0): supplicant connection state change: 5 -> 6
NetworkManager: <info> (wlan0): supplicant connection state change: 6 -> 7
NetworkManager: <info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'HWAP0105'.
NetworkManager: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
NetworkManager: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
NetworkManager: <info> (wlan0): device state change: 5 -> 7
NetworkManager: <info> Activation (wlan0) Beginning DHCP transaction.
NetworkManager: <info> dhclient started with pid 3856
NetworkManager: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
NetworkManager: <info> DHCP: device wlan0 state changed normal exit -> preinit
dhclient: Listening on LPF/wlan0/00:19:d2:ce:c1:4f
dhclient: Sending on LPF/wlan0/00:19:d2:ce:c1:4f
dhclient: Sending on Socket/fallback
dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 8
dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 13
dhclient: DHCPDI...

Read more...

linusr (linusr) wrote :
Download full text (4.1 KiB)

Looks my Dell Vostro 1500 has smae issue connecting to WPA2 Enterprise network. Any workaround?

Apr 8 15:03:04 DeepBlue wpa_supplicant[1287]: Failed to initiate AP scan.
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Activation (wlan0) starting connection 'Auto Corporate_WiFi'
Apr 8 15:04:57 DeepBlue NetworkManager: <info> (wlan0): device state change: 3 -> 4 (reason 0)
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Apr 8 15:04:57 DeepBlue NetworkManager: <info> (wlan0): device state change: 4 -> 5 (reason 0)
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Activation (wlan0/wireless): access point 'Auto Corporate_WiFi' has security, but secrets are required.
Apr 8 15:04:57 DeepBlue NetworkManager: <info> (wlan0): device state change: 5 -> 6 (reason 0)
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Apr 8 15:04:57 DeepBlue NetworkManager: <info> (wlan0): device state change: 6 -> 4 (reason 0)
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Apr 8 15:04:57 DeepBlue NetworkManager: <info> (wlan0): device state change: 4 -> 5 (reason 0)
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Activation (wlan0/wireless): connection 'Auto Corporate_WiFi' has security, and secrets exist. No new secrets needed.
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Config: added 'ssid' value 'Corporate_WiFi'
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Config: added 'scan_ssid' value '1'
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Config: added 'key_mgmt' value 'WPA-EAP'
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Config: added 'password' value '<omitted>'
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Config: added 'eap' value 'PEAP'
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Config: added 'fragment_size' value '1300'
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Config: added 'phase2' value 'auth=MSCHAPV2'
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Config: added 'identity' value '*****'
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Config: added 'anonymous_identity' value '***'
Apr 8 15:04:57 DeepBlue NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (De...

Read more...

Changed in network-manager:
importance: Unknown → Medium
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Duplicates of this bug

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.