Authentication / Association Problem with 2.6.31

[Michael Hirsch]

Hello all,

just to let you how this problem was finally solved:

After longs days of debugging, it turned out the described strange 
behavior was problem of the libertas based client.

A new libertas firmware (we changed to 9.70.3p36) solved this issue. 
Strange enaugh, this problem does also not appear if a iPhone is 
associated at the same time to hostap.

Best

Michael


Michael Hirsch wrote:
> Hello all,
> 
> can anybody help? Maybe not enough or wrong info?
> 
> Best
> 
> Michael
> 
> 
> Michael Hirsch wrote:
>> Hello all,
>>
>> I have a issue with hostapd running on my server:
>>
>> After a number of successful associations and authentications (let's say 
>> around 5) following associations do not work any more. I can't see a 
>> request in hostapd's output any more.
>>
>> Restarting the client does not help, also other linux based systems 
>> can't connect any more.
>>
>> The only solution is to restart hostapd.
>>
>> On both system Linux kernel 2.6.31 is used.
>> The client uses a libertas_sdio, the server ath5k
>>
>> here is the hostapd output:
>>
>> ---> Association works:
>>
>> 946693398.852547: wlan0: STA 00:19:88:11:dc:3c IEEE 802.11: associated 
>> (aid 1)
>> 946693398.852775: wlan0: STA 00:19:88:11:dc:3c MLME: 
>> MLME-ASSOCIATE.indication(00:19:88:11:dc:3c)
>> 946693398.852904: wlan0: STA 00:19:88:11:dc:3c MLME: 
>> MLME-DELETEKEYS.request(00:19:88:11:dc:3c)
>> 946693398.856344: wlan0: STA 00:19:88:11:dc:3c WPA: event 1 notification
>> 946693398.856600: wlan0: STA 00:19:88:11:dc:3c WPA: start authentication
>> 946693398.856648: WPA: 00:19:88:11:dc:3c WPA_PTK entering state INITIALIZE
>> 946693398.856917: wlan0: STA 00:19:88:11:dc:3c IEEE 802.1X: 
>> unauthorizing port
>> 946693398.856964: WPA: 00:19:88:11:dc:3c WPA_PTK_GROUP entering state IDLE
>> 946693398.857037: WPA: 00:19:88:11:dc:3c WPA_PTK entering state 
>> AUTHENTICATION
>> 946693398.857113: WPA: 00:19:88:11:dc:3c WPA_PTK entering state 
>> AUTHENTICATION2
>> 946693398.857186: WPA: 00:19:88:11:dc:3c WPA_PTK entering state INITPSK
>> 946693398.857261: WPA: 00:19:88:11:dc:3c WPA_PTK entering state PTKSTART
>> 946693398.857392: wlan0: STA 00:19:88:11:dc:3c WPA: sending 1/4 msg of 
>> 4-Way Handshake
>> 946693398.857436: WPA: Send EAPOL(version=1 secure=0 mic=0 ack=1 
>> install=0 pairwise=8 kde_len=0 keyidx=0 encr=0)
>> 946693398.859256: IEEE 802.1X: 00:19:88:11:dc:3c TX status - version=2 
>> type=3 length=95 - ack=1
>> 946693398.863783: IEEE 802.1X: 121 bytes from 00:19:88:11:dc:3c
>> 946693398.863862:    IEEE 802.1X: version=1 type=3 length=117
>> 946693398.863993: wlan0: STA 00:19:88:11:dc:3c WPA: received EAPOL-Key 
>> frame (2/4 Pairwise)
>> 946693398.864044: WPA: 00:19:88:11:dc:3c WPA_PTK entering state 
>> PTKCALCNEGOTIATING
>> 946693398.864257: WPA: PTK derivation - A1=00:0b:6b:2f:47:7d 
>> A2=00:19:88:11:dc:3c
>> 946693398.864360: WPA: PMK - hexdump(len=32): 5a 51 4e e7 08 36 b8 11 01 
>> 5a f5 bb cf 6c 2d fb e9 d5 92 cf fa 53 a2 d3 7b 89 0c 0d 4f 8b 9f 8f
>> 946693398.864655: WPA: PTK - hexdump(len=64): 92 fc 6b 64 d5 8c b4 e8 ad 
>> 55 f0 70 7d 27 15 1f 10 55 0f 17 48 79 4f e1 44 3d 3f 69 75 96 97 82 13 
>> ce ac 06 bb d7 6e 4f 3d b6 7d ec 1c 2e fe ef c5 c3 99 d1 22 eb e0 0b 82 
>> 38 b2 97 1f b0 dc 34
>> 946693398.865222: WPA: 00:19:88:11:dc:3c WPA_PTK entering state 
>> PTKCALCNEGOTIATING2
>> 946693398.865299: WPA: 00:19:88:11:dc:3c WPA_PTK entering state 
>> PTKINITNEGOTIATING
>> 946693398.865571: wlan0: STA 00:19:88:11:dc:3c WPA: sending 3/4 msg of 
>> 4-Way Handshake
>> 946693398.865624: WPA: Send EAPOL(version=1 secure=1 mic=1 ack=1 
>> install=1 pairwise=8 kde_len=86 keyidx=1 encr=1)
>> 946693398.865720: Plaintext EAPOL-Key Key Data - hexdump(len=86): 30 14 
>> 01 00 00 0f ac 02 01 00 00 0f ac 02 01 00 00 0f ac 02 0c 00 dd 16 00 50 
>> f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 dd 26 00 0f 
>> ac 01 01 00 a1 91 02 90 a8 af d6 7f e0 5a 5c 48 98 c2 b6 9b a3 82 a0 21 
>> 21 0d 6e 55 82 af b4 29 03 ba 7d 42
>> 946693398.869673: IEEE 802.1X: 00:19:88:11:dc:3c TX status - version=2 
>> type=3 length=181 - ack=1
>> 946693398.873990: IEEE 802.1X: 99 bytes from 00:19:88:11:dc:3c
>> 946693398.874071:    IEEE 802.1X: version=1 type=3 length=95
>> 946693398.874200: wlan0: STA 00:19:88:11:dc:3c WPA: received EAPOL-Key 
>> frame (4/4 Pairwise)
>> 946693398.874272: WPA: 00:19:88:11:dc:3c WPA_PTK entering state PTKINITDONE
>> 946693398.874615: wlan0: STA 00:19:88:11:dc:3c IEEE 802.1X: authorizing port
>> 946693398.874731: wlan0: STA 00:19:88:11:dc:3c RADIUS: starting 
>> accounting session 386D6441-0000000E
>> 946693398.875052: wlan0: STA 00:19:88:11:dc:3c WPA: pairwise key 
>> handshake completed (RSN)
>> 946693403.837124: unknown vendor specific information element ignored 
>> (vendor OUI 00:03:47 len=7)
>> 946693403.837941: unknown vendor specific information element ignored 
>> (vendor OUI 00:03:47 len=7)
>> 946693403.838111: STA 00:1b:77:a2:97:57 sent probe request for broadcast 
>> SSID
>> 946693403.839947: MGMT (TX callback) ACK
>> 946693403.840005: mgmt::proberesp cb
>> 946693403.853153: unknown vendor specific information element ignored 
>> (vendor OUI 00:03:47 len=7)
>> 946693403.853418: STA 00:1b:77:a2:97:57 sent probe request for broadcast 
>> SSID
>> 946693403.855250: MGMT (TX callback) ACK
>> 946693403.855298: mgmt::proberesp cb
>> 946693407.749200: MGMT
>> 946693407.749270: mgmt::deauth
>>
>> ------>I disconnect:
>> 946693407.749313: deauthentication: STA=00:19:88:11:dc:3c reason_code=3
>> 946693407.749473: wlan0: STA 00:19:88:11:dc:3c WPA: event 3 notification
>> 946693407.749662: WPA: 00:19:88:11:dc:3c WPA_PTK entering state DISCONNECTED
>> 946693407.749746: WPA: 00:19:88:11:dc:3c WPA_PTK entering state INITIALIZE
>>
>>
>> 946693407.750033: wlan0: STA 00:19:88:11:dc:3c IEEE 802.1X: 
>> unauthorizing port
>> 946693407.750137: wlan0: STA 00:19:88:11:dc:3c IEEE 802.11: deauthenticated
>> 946693407.750269: wlan0: STA 00:19:88:11:dc:3c MLME: 
>> MLME-DEAUTHENTICATE.indication(00:19:88:11:dc:3c, 3)
>> 946693407.750399: wlan0: STA 00:19:88:11:dc:3c MLME: 
>> MLME-DELETEKEYS.request(00:19:88:11:dc:3c)
>>
>> -> new requests seem to be ignored:
>>
>> 946693414.373969: STA 00:19:88:11:dc:3c sent probe request for broadcast 
>> SSID
>> 946693414.375804: MGMT (TX callback) ACK
>> 946693414.375855: mgmt::proberesp cb
>> 946693421.140081: STA 00:19:88:11:dc:3c sent probe request for broadcast 
>> SSID
>> 946693421.141917: MGMT (TX callback) ACK
>> 946693421.141968: mgmt::proberesp cb
>> 946693421.256939: STA 00:19:88:11:dc:3c sent probe request for broadcast 
>> SSID
>> 946693421.258780: MGMT (TX callback) ACK
>> 946693421.258836: mgmt::proberesp cb
>> 946693428.140399: STA 00:19:88:11:dc:3c sent probe request for broadcast 
>> SSID
>>
>>
>> sometimes it may happen, that in the moment of a authentification 
>> request from the client, I see in hostapds output:
>>
>> 946693476.290632: mgmt::proberesp cb
>> 946693478.986731: unknown vendor specific information element ignored 
>> (vendor OUI 00:10:18 len=9)
>> 946693478.993254: unknown vendor specific information element ignored 
>> (vendor OUI 00:10:18 len=9)
>> 946693479.002524: unknown vendor specific information element ignored 
>> (vendor OUI 00:10:18 len=9)
>> 946693479.009253: unknown vendor specific information element ignored 
>> (vendor OUI 00:10:18 len=9)
>> 946693479.025043: unknown vendor specific information element ignored 
>> (vendor OUI 00:10:18 len=9)
>>
>>
>>
>> Here is my host.conf:
>> ssid=->myssid...
>> wpa_psk=my key
>> channel=2
>> country_code=de
>> ieee80211d=1
>>
>> interface=wlan0
>> bridge=br0
>> driver=nl80211
>> hw_mode=g
>> wpa=3
>> wpa_pairwise=TKIP
>> wpa_key_mgmt=WPA-PSK
>> wme_enabled=1
>>
>>
>> Any idea where I can start searching?
>>
>>
>> Best regards and thanks for helping
>>
>> Michael
>>
>>
>>
>> _______________________________________________
>> HostAP mailing list
>> HostAP at lists.shmoo.com
>> http://lists.shmoo.com/mailman/listinfo/hostap
>>
> 
>