Re: Cannot connect because "association took too long"

[Dan Williams <dcbw redhat com>]

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   sojkam1 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   sojkam1 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