Re: Cannot connect because "association took too long"

[Dan Williams <dcbw redhat com>]

On Tue, 2011-04-26 at 20:36 +0200, Michal Sojka wrote:
> Hi,
> 
> I cannot connect to a wireless network, because network manager says
> that association took too long. I can imagine, that this is not a fault
> of network manager, but you can at lest forward me to somebody else.
> 
> I'm using vanilla Linux 2.6.37.4 and I have the following WiFi NIC:
> 10:00.0 Network controller: Intel Corporation PRO/Wireless 3945ABG [Golan] Network Connection (rev 02)
> 
> I found some old bug reports, similar to my problem, and the problem
> there was caused by buggy drivers. I do not think this is my case,
> because I can connect to almost every wireless network expect a single
> one - Eduroam (http://www.eduroam.org/). The problem appears only when
> I'm abroad so I wonder whether the network manager's timeout (25
> seconds) elapses because the authentication between different countries
> takes long time due to a slower connection to authentication servers.

Wow, that's like a 30 second EAP exchange.  What would be interesting to
get here to figure out why this is happening is the wpa_supplicant debug
logs as described here:

http://live.gnome.org/NetworkManager/Debugging

so that we can find out why the supplicant is taking 30 seconds to
connect.  It looks like a timeout issue in the supplicant more than
anything right now, because a simple EAP exchange should never take mroe
more than 10 or so seconds even with retries.

Dan

> By applying the following patch, I'm able to connect:
> 
> diff --git a/src/nm-device-wifi.c b/src/nm-device-wifi.c
> index 9258f77..032113b 100644
> --- a/src/nm-device-wifi.c
> +++ b/src/nm-device-wifi.c
> @@ -2828,7 +2828,7 @@ start_supplicant_connection_timeout (NMDeviceWifi *self)
>         priv = NM_DEVICE_WIFI_GET_PRIVATE (self);
>  
>         /* Set up a timeout on the connection attempt to fail it after 25 seconds */
> -       id = g_timeout_add_seconds (25, supplicant_connection_timeout_cb, self);
> +       id = g_timeout_add_seconds (60, supplicant_connection_timeout_cb, self);
>         if (id == 0) {
>                 nm_log_err (LOGD_DEVICE | LOGD_WIFI,
>                             "Activation (%s/wireless): couldn't start supplicant "
> 
> Then, the log of successfull connection process is attached bellow and
> one can see which part takes how long. It seems that wpa_suplicant is
> the one to blame, but it might be that there is no way to achieve faster
> authentication because of poor network connectivity to the
> authentication server.
> 
> Can someone confirm, that this hypothesis is correct? And if it is, what
> should network manager users do when they do not want to patch and
> recompile network manager?
> 
> Thanks
> Michal
>                             
> Apr 26 20:00:06 steelpick NetworkManager[25803]: <info> WiFi now enabled by radio killswitch
> Apr 26 20:00:06 steelpick NetworkManager[25803]: <info> (wlan0): bringing up device.
> Apr 26 20:00:06 steelpick NetworkManager[25803]: <info> (wlan0): supplicant interface state:  starting -> ready
> Apr 26 20:00:06 steelpick NetworkManager[25803]: <info> (wlan0): device state change: 2 -> 3 (reason 42)
> Apr 26 20:00:06 steelpick wpa_supplicant[2503]: Failed to initiate AP scan.
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> Activation (wlan0) starting connection 'Auto eduroam'
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> (wlan0): device state change: 3 -> 4 (reason 0)
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> (wlan0): device state change: 4 -> 5 (reason 0)
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> Activation (wlan0/wireless): connection 'Auto eduroam' has security, and secrets exist.  No new secrets needed.
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> Config: added 'ssid' value 'eduroam'
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> Config: added 'scan_ssid' value '1'
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> Config: added 'key_mgmt' value 'WPA-EAP'
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> Config: added 'password' value '<omitted>'
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> Config: added 'eap' value 'PEAP'
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> Config: added 'fragment_size' value '1300'
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> Config: added 'phase2' value 'auth=MSCHAPV2'
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> Config: added 'ca_cert' value '/etc/ssl/certs/cesnet-ca.cz.pem'
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> Config: added 'identity' value 'sojkam1 fel cvut cz'
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
> Apr 26 20:00:09 steelpick NetworkManager[25803]: <info> Config: set interface ap_scan to 1
> Apr 26 20:00:16 steelpick NetworkManager[25803]: <info> (wlan0): supplicant connection state:  inactive -> scanning
> Apr 26 20:00:19 steelpick wpa_supplicant[2503]: Trying to associate with 08:17:35:82:f6:7d (SSID='eduroam' freq=5520 MHz)
> Apr 26 20:00:19 steelpick NetworkManager[25803]: <info> (wlan0): supplicant connection state:  scanning -> associating
> Apr 26 20:00:19 steelpick wpa_supplicant[2503]: Associated with 08:17:35:82:f6:7d
> Apr 26 20:00:19 steelpick wpa_supplicant[2503]: CTRL-EVENT-EAP-STARTED EAP authentication started
> Apr 26 20:00:19 steelpick NetworkManager[25803]: <info> (wlan0): supplicant connection state:  associating -> associated
> Apr 26 20:00:21 steelpick avahi-daemon[2242]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::21f:3cff:fedf:1e2a.
> Apr 26 20:00:21 steelpick avahi-daemon[2242]: New relevant interface wlan0.IPv6 for mDNS.
> Apr 26 20:00:21 steelpick avahi-daemon[2242]: Registering new address record for fe80::21f:3cff:fedf:1e2a on wlan0.*.
> Apr 26 20:00:49 steelpick wpa_supplicant[2503]: CTRL-EVENT-EAP-STARTED EAP authentication started
> Apr 26 20:00:49 steelpick wpa_supplicant[2503]: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
> Apr 26 20:00:49 steelpick wpa_supplicant[2503]: EAP-MSCHAPV2: Authentication succeeded
> Apr 26 20:00:49 steelpick wpa_supplicant[2503]: EAP-TLV: TLV Result - Success - EAP-TLV/Phase2 Completed
> Apr 26 20:00:49 steelpick wpa_supplicant[2503]: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
> Apr 26 20:00:49 steelpick NetworkManager[25803]: <info> (wlan0): supplicant connection state:  associated -> 4-way handshake
> Apr 26 20:00:49 steelpick wpa_supplicant[2503]: WPA: Key negotiation completed with 08:17:35:82:f6:7d [PTK=CCMP GTK=TKIP]
> Apr 26 20:00:49 steelpick wpa_supplicant[2503]: CTRL-EVENT-CONNECTED - Connection to 08:17:35:82:f6:7d completed (auth) [id=0 id_str=]
> Apr 26 20:00:49 steelpick NetworkManager[25803]: <info> (wlan0): supplicant connection state:  4-way handshake -> group handshake
> Apr 26 20:00:49 steelpick NetworkManager[25803]: <info> (wlan0): supplicant connection state:  group handshake -> completed
> Apr 26 20:00:49 steelpick NetworkManager[25803]: <info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'eduroam'.
> Apr 26 20:00:49 steelpick NetworkManager[25803]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
> Apr 26 20:00:49 steelpick NetworkManager[25803]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
> Apr 26 20:00:49 steelpick NetworkManager[25803]: <info> (wlan0): device state change: 5 -> 7 (reason 0)
> Apr 26 20:00:49 steelpick NetworkManager[25803]: <info> Activation (wlan0) Beginning DHCPv4 transaction (timeout in 45 seconds)
> Apr 26 20:00:49 steelpick NetworkManager[25803]: <info> dhclient started with pid 26280
> Apr 26 20:00:49 steelpick NetworkManager[25803]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
> Apr 26 20:00:49 steelpick dhclient: Internet Systems Consortium DHCP Client 4.1.1-P1
> Apr 26 20:00:49 steelpick dhclient: Copyright 2004-2010 Internet Systems Consortium.
> Apr 26 20:00:49 steelpick dhclient: All rights reserved.
> Apr 26 20:00:49 steelpick dhclient: For info, please visit https://www.isc.org/software/dhcp/
> Apr 26 20:00:49 steelpick dhclient: 
> Apr 26 20:00:49 steelpick NetworkManager[25803]: <info> (wlan0): DHCPv4 state changed nbi -> preinit
> Apr 26 20:00:49 steelpick dhclient: Listening on LPF/wlan0/00:1f:3c:df:1e:2a
> Apr 26 20:00:49 steelpick dhclient: Sending on   LPF/wlan0/00:1f:3c:df:1e:2a
> Apr 26 20:00:49 steelpick dhclient: Sending on   Socket/fallback
> Apr 26 20:00:51 steelpick dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
> Apr 26 20:00:58 steelpick dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
> Apr 26 20:00:58 steelpick dhclient: DHCPACK from 141.30.1.225
> Apr 26 20:00:58 steelpick dhclient: bound to 141.76.185.8 -- renewal in 236 seconds.
> Apr 26 20:00:58 steelpick NetworkManager[25803]: <info> (wlan0): DHCPv4 state changed preinit -> reboot
> Apr 26 20:00:58 steelpick NetworkManager[25803]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) scheduled...
> Apr 26 20:00:58 steelpick NetworkManager[25803]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) started...
> Apr 26 20:00:58 steelpick NetworkManager[25803]: <info>   address 141.76.185.8
> Apr 26 20:00:58 steelpick NetworkManager[25803]: <info>   prefix 22 (255.255.252.0)
> Apr 26 20:00:58 steelpick NetworkManager[25803]: <info>   gateway 141.76.184.1
> Apr 26 20:00:58 steelpick NetworkManager[25803]: <info>   nameserver '141.30.66.135'
> Apr 26 20:00:58 steelpick NetworkManager[25803]: <info>   nameserver '141.30.66.1'
> Apr 26 20:00:58 steelpick NetworkManager[25803]: <info>   domain name 'dip.tu-dresden.de'
> Apr 26 20:00:58 steelpick NetworkManager[25803]: <info> Scheduling stage 5
> Apr 26 20:00:58 steelpick NetworkManager[25803]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) scheduled...
> Apr 26 20:00:58 steelpick NetworkManager[25803]: <info> Done scheduling stage 5
> Apr 26 20:00:58 steelpick NetworkManager[25803]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) complete.
> Apr 26 20:00:58 steelpick NetworkManager[25803]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started...
> Apr 26 20:00:58 steelpick avahi-daemon[2242]: Joining mDNS multicast group on interface wlan0.IPv4 with address 141.76.185.8.
> Apr 26 20:00:58 steelpick avahi-daemon[2242]: New relevant interface wlan0.IPv4 for mDNS.
> Apr 26 20:00:58 steelpick avahi-daemon[2242]: Registering new address record for 141.76.185.8 on wlan0.IPv4.
> Apr 26 20:00:59 steelpick NetworkManager[25803]: <info> (wlan0): device state change: 7 -> 8 (reason 0)
> Apr 26 20:00:59 steelpick NetworkManager[25803]: <info> Policy set 'Auto eduroam' (wlan0) as default for IPv4 routing and DNS.
> Apr 26 20:00:59 steelpick NetworkManager[25803]: <info> Activation (wlan0) successful, device activated.
> Apr 26 20:00:59 steelpick NetworkManager[25803]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) complete.
> Apr 26 20:00:59 steelpick ntpdate[26321]: the NTP socket is in use, exiting
> _______________________________________________
> networkmanager-list mailing list
> networkmanager-list gnome org
> http://mail.gnome.org/mailman/listinfo/networkmanager-list