hostapd mixing EAP ids

[Jouni Malinen]

On Fri, Oct 21, 2005 at 03:40:06PM -0600, Ahmet Basagalar wrote:

> I had a very huge debug log, but it is hard to find the exact place where it 
> gets triggered. Following is an interesting entry in the debug log

Would it be possible for you to send bit more larger extract from the
debug log? Ideally, I would like to see what happens from the
association all the way to the point when the EAP id gets mixed up.

> IEEE 802.1X: station 00:02:6f:07:c4:dc - new auth session, clearing State
> IEEE 802.1X: Generated EAP Request-Identity for 00:02:6f:07:c4:dc 
> (identifier 33, timeout 30)
> IEEE 802.1X: 00:02:6f:07:c4:dc REAUTH_TIMER entering state INITIALIZE
> IEEE 802.1X: 00:02:6f:07:c4:dc AUTH_PAE entering state CONNECTING
> IEEE 802.1X: 00:02:6f:07:c4:dc REAUTH_TIMER entering state INITIALIZE
> IEEE 802.1X: 00:02:6f:07:c4:dc AUTH_PAE entering state DISCONNECTED
> IEEE 802.1X: 00:02:6f:07:c4:dc REAUTH_TIMER entering state INITIALIZE
> IEEE 802.1X: 00:02:6f:07:c4:dc AUTH_PAE entering state RESTART
> IEEE 802.1X: station 00:02:6f:07:c4:dc - new auth session, clearing State
> IEEE 802.1X: Generated EAP Request-Identity for 00:02:6f:07:c4:dc 
> (identifier 34, timeout 30)
> IEEE 802.1X: 00:02:6f:07:c4:dc REAUTH_TIMER entering state INITIALIZE
> IEEE 802.1X: 00:02:6f:07:c4:dc AUTH_PAE entering state CONNECTING
> IEEE 802.1X: 00:02:6f:07:c4:dc REAUTH_TIMER entering state INITIALIZE
> IEEE 802.1X: 00:02:6f:07:c4:dc AUTH_PAE entering state AUTHENTICATING
> IEEE 802.1X: 00:02:6f:07:c4:dc BE_AUTH entering state REQUEST
> IEEE 802.1X: Sending EAP Packet to 00:02:6f:07:c4:dc (identifier 34)
> IEEE 802.1X: 00:02:6f:07:c4:dc REAUTH_TIMER entering state INITIALIZE
> IEEE 802.1X: 00:02:6f:07:c4:dc BE_AUTH entering state RESPONSE
> Encapsulating EAP message into a RADIUS packet
> Sending RADIUS message to authentication server
> RADIUS message: code=1 (Access-Request) identifier=164 length=176
> 
> As you can see the auth session was restarted twice. I do not know if this 
> gives any clue.

Unfortunately, the debug log did not include lines showing what happened
before the first start of a new authentication session. In many cases,
this is because of an EAPOL-Start frame from the supplicant. However,
here AUTH_PAE state machine is moving from CONNECTING to DISCONNECTED
state which should only happen if reAuthCount > reAuthMax, i.e.,
re-authentication has been tried too many times without success.

> My only concern for adding that modification was the fact that it may 
> trigger something else somewhere like a memory leak, but from what you said 
> it seems like it should not. To recreate it, you may try setting reauth 
> period to a very low value like 10 secs and associate as much clients as 
> possible. That was how I was able to reproduce it.

I don't expect it to lead to a memory leak, but I'm not sure whether
this change would resolve all cases that could trigger this kind of
behavior.

hostapd 0.4.x versions have a race condition that can trigger similar
problem if the connections between authentication server, authenticator,
and supplicant are very fast (e.g., in my tests that use emulated
network connection by just passing frames locally within one host).
However, after resolving this, I have not been able to reproduce this
issue. In addition to the latest development version, I tested with
0.3.x branch using 100 stations and five second EAPOL reauthentication
interval. Just having lots of stations and reauthentications does not
seem to be enough in my test setup; there needs to be different latency
between events etc. to trigger this.

-- 
Jouni Malinen                                            PGP id EFC895FA