Re: Cannot connect because association took too long
On Wednesday 27 of April 2011 22:36:32 Michal Sojka wrote: Hi and thanks for the reply. Here is the log. -Michal 1303936311.434616: EAP: EAP-Request Identity data - hexdump_ascii(len=44): 00 6e 65 74 77 6f 72 6b 69 64 3d 65 64 75 72 6f _networkid=eduro 61 6d 2c 6e 61 73 69 64 3d 61 73 62 2d 77 69 73 am,nasid=asb-wis 6d 35 2c 70 6f 72 74 69 64 3d 32 39 m5,portid=29 1303936311.434650: EAP: using real identity - hexdump_ascii(len=19): 73 6f 6a 6b 61 6d 31 40 66 65 6c 2e 63 76 75 74 sojk...@fel.cvut 2e 63 7a .cz 1303936311.434696: TX EAPOL - hexdump(len=28): 01 00 00 18 02 01 00 18 01 73 6f 6a 6b 61 6d 31 40 66 65 6c 2e 63 76 75 74 2e 63 7a Hmm, the delay of 30 seconds, here 1303936341.259024: RX EAPOL - hexdump(len=53): 02 00 00 31 01 02 00 31 01 00 6e 65 74 77 6f 72 6b 69 64 3d 65 64 75 72 6f 61 6d 2c 6e 61 73 69 64 3d 61 73 62 2d 77 69 73 6d 35 2c 70 6f 72 74 69 64 3d 32 39 1303936341.259142: EAP: EAP-Request Identity data - hexdump_ascii(len=44): 00 6e 65 74 77 6f 72 6b 69 64 3d 65 64 75 72 6f _networkid=eduro 61 6d 2c 6e 61 73 69 64 3d 61 73 62 2d 77 69 73 am,nasid=asb-wis 6d 35 2c 70 6f 72 74 69 64 3d 32 39 m5,portid=29 1303936341.259178: EAP: using real identity - hexdump_ascii(len=19): 73 6f 6a 6b 61 6d 31 40 66 65 6c 2e 63 76 75 74 sojk...@fel.cvut 2e 63 7a .cz 1303936341.259225: TX EAPOL - hexdump(len=28): 01 00 00 18 02 02 00 18 01 Could you capture the packet exchange by wireshark, so we can see if there is really the delay or it is just processing issue in wpa_supplicant? Jirka ___ networkmanager-list mailing list networkmanager-list@gnome.org http://mail.gnome.org/mailman/listinfo/networkmanager-list
Re: Cannot connect because association took too long
On Wed, 2011-06-15 at 16:10 +0200, Jirka Klimes wrote: On Wednesday 27 of April 2011 22:36:32 Michal Sojka wrote: Hi and thanks for the reply. Here is the log. -Michal 1303936311.434616: EAP: EAP-Request Identity data - hexdump_ascii(len=44): 00 6e 65 74 77 6f 72 6b 69 64 3d 65 64 75 72 6f _networkid=eduro 61 6d 2c 6e 61 73 69 64 3d 61 73 62 2d 77 69 73 am,nasid=asb-wis 6d 35 2c 70 6f 72 74 69 64 3d 32 39 m5,portid=29 1303936311.434650: EAP: using real identity - hexdump_ascii(len=19): 73 6f 6a 6b 61 6d 31 40 66 65 6c 2e 63 76 75 74 sojk...@fel.cvut 2e 63 7a .cz 1303936311.434696: TX EAPOL - hexdump(len=28): 01 00 00 18 02 01 00 18 01 73 6f 6a 6b 61 6d 31 40 66 65 6c 2e 63 76 75 74 2e 63 7a Hmm, the delay of 30 seconds, here 1303936341.259024: RX EAPOL - hexdump(len=53): 02 00 00 31 01 02 00 31 01 00 6e 65 74 77 6f 72 6b 69 64 3d 65 64 75 72 6f 61 6d 2c 6e 61 73 69 64 3d 61 73 62 2d 77 69 73 6d 35 2c 70 6f 72 74 69 64 3d 32 39 1303936341.259142: EAP: EAP-Request Identity data - hexdump_ascii(len=44): 00 6e 65 74 77 6f 72 6b 69 64 3d 65 64 75 72 6f _networkid=eduro 61 6d 2c 6e 61 73 69 64 3d 61 73 62 2d 77 69 73 am,nasid=asb-wis 6d 35 2c 70 6f 72 74 69 64 3d 32 39 m5,portid=29 1303936341.259178: EAP: using real identity - hexdump_ascii(len=19): 73 6f 6a 6b 61 6d 31 40 66 65 6c 2e 63 76 75 74 sojk...@fel.cvut 2e 63 7a .cz 1303936341.259225: TX EAPOL - hexdump(len=28): 01 00 00 18 02 02 00 18 01 Could you capture the packet exchange by wireshark, so we can see if there is really the delay or it is just processing issue in wpa_supplicant? Eduroam can sometimes be finicky; I think often the RADIUS servers are at different locations? Except that here after the 30 second delay things move very quickly which indicates that 30 second delay is quite unusual. Just to confirm, was the machine stationary during this log? Was the signal strength good? That would allow us to rule out packet retries at the driver level; and given that the exchange *after* the 30 second delay works very smoothly I would not expect the network to be heavily loaded either. Also if anyone could follow this up with Eduroam administrators and ask if they delay initial EAP authentication as a DoS prevention measure or anything like that? Or is the equipment just badly configured? Other than that, like Jirka suggests, we may have to break out wireshark and packet captures to figure out where the delay actually exists. Either the first EAP frame from the AP got lost, or the AP is just waiting for the RADIUS server to respond. Dan ___ networkmanager-list mailing list networkmanager-list@gnome.org http://mail.gnome.org/mailman/listinfo/networkmanager-list
Re: Cannot connect because association took too long
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:
Re: Cannot connect because association took too long
On Wed, 27 Apr 2011, Dan Williams wrote: 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 Hi and thanks for the reply. Here is the log. -Michal 1303936298.761407: WPS: UUID based on MAC address - hexdump(len=16): 02 71 ae d2 db 05 50 40 82 71 18 e6 f8 44 f8 eb 1303936301.319951: ca_cert - hexdump_ascii(len=31): 2f 65 74 63 2f 73 73 6c 2f 63 65 72 74 73 2f 63 /etc/ssl/certs/c 65 73 6e 65 74 2d 63 61 2e 63 7a 2e 70 65 6d esnet-ca.cz.pem 1303936301.320002: password - hexdump_ascii(len=8): [REMOVED] 1303936301.320015: phase2 - hexdump_ascii(len=13): 61 75 74 68 3d 4d 53 43 48 41 50 56 32auth=MSCHAPV2 1303936301.320033: eap methods - hexdump(len=16): 00 00 00 00 19 00 00 00 00 00 00 00 00 00 00 00 1303936301.320048: ssid - hexdump_ascii(len=7): 65 64 75 72 6f 61 6d eduroam 1303936301.320093: identity - hexdump_ascii(len=19): 73 6f 6a 6b 61 6d 31 40 66 65 6c 2e 63 76 75 74 sojk...@fel.cvut 2e 63 7a .cz 1303936308.859606: Scan SSID - hexdump_ascii(len=7): 65 64 75 72 6f 61 6d eduroam 1303936311.425345: WPA: set AP WPA IE - hexdump(len=26): dd 18 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 01 00 00 1303936311.425371: WPA: set AP RSN IE - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 01 28 00 1303936311.425400: WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 01 00 00 1303936311.432000: AssocResp IE wireless event - hexdump(len=65): 01 06 98 24 b0 48 60 6c dd 18 00 50 f2 02 01 01 80 00 03 a4 00 00 27 a4 00 00 42 43 5e 00 62 32 2f 00 dd 1d 00 40 96 0c 01 e4 27 f9 1d a9 98 2f 01 00 00 f7 0c 00 00 00 00 9a e7 8a 00 c4 39 53 be 1303936311.432069: resp_ies - hexdump(len=65): 01 06 98 24 b0 48 60 6c dd 18 00 50 f2 02 01 01 80 00 03 a4 00 00 27 a4 00 00 42 43 5e 00 62 32 2f 00 dd 1d 00 40 96 0c 01 e4 27 f9 1d a9 98 2f 01 00 00 f7 0c 00 00 00 00 9a e7 8a 00 c4 39 53 be 1303936311.434398: RX EAPOL - hexdump(len=53): 02 00 00 31 01 01 00 31 01 00 6e 65 74 77 6f 72 6b 69 64 3d 65 64 75 72 6f 61 6d 2c 6e 61 73 69 64 3d 61 73 62 2d 77 69 73 6d 35 2c 70 6f 72 74 69 64 3d 32 39 1303936311.434616: EAP: EAP-Request Identity data - hexdump_ascii(len=44): 00 6e 65 74 77 6f 72 6b 69 64 3d 65 64 75 72 6f _networkid=eduro 61 6d 2c 6e 61 73 69 64 3d 61 73 62 2d 77 69 73 am,nasid=asb-wis 6d 35 2c 70 6f 72 74 69 64 3d 32 39 m5,portid=29 1303936311.434650: EAP: using real identity - hexdump_ascii(len=19): 73 6f 6a 6b 61 6d 31 40 66 65 6c 2e 63 76 75 74 sojk...@fel.cvut 2e 63 7a .cz 1303936311.434696: TX EAPOL - hexdump(len=28): 01 00 00 18 02 01 00 18 01 73 6f 6a 6b 61 6d 31 40 66 65 6c 2e 63 76 75 74 2e 63 7a 1303936341.259024: RX EAPOL - hexdump(len=53): 02 00 00 31 01 02 00 31 01 00 6e 65 74 77 6f 72 6b 69 64 3d 65 64 75 72 6f 61 6d 2c 6e 61 73 69 64 3d 61 73 62 2d 77 69 73 6d 35 2c 70 6f 72 74 69 64 3d 32 39 1303936341.259142: EAP: EAP-Request Identity data - hexdump_ascii(len=44): 00 6e 65 74 77 6f 72 6b 69 64 3d 65 64 75 72 6f _networkid=eduro 61 6d 2c 6e 61 73 69 64 3d 61 73 62 2d 77 69 73 am,nasid=asb-wis 6d 35 2c 70 6f 72 74 69 64 3d 32 39 m5,portid=29 1303936341.259178: EAP: using real identity - hexdump_ascii(len=19): 73 6f 6a 6b 61 6d 31 40 66 65 6c 2e 63 76 75 74 sojk...@fel.cvut 2e 63 7a .cz 1303936341.259225: TX EAPOL - hexdump(len=28): 01 00 00 18 02 02 00 18 01 73 6f 6a 6b 61 6d 31 40 66 65 6c 2e 63 76 75 74 2e 63 7a 1303936341.320832: RX EAPOL - hexdump(len=10): 02 00 00 06 01 03 00 06 19 20
Cannot connect because association took too long
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 'sojk...@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
