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 '[email protected]' > 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 > [email protected] > http://mail.gnome.org/mailman/listinfo/networkmanager-list _______________________________________________ networkmanager-list mailing list [email protected] http://mail.gnome.org/mailman/listinfo/networkmanager-list
