Cannot connect because "association took too long"

[Michal Sojka <wsh 2x cz>]

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.

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