Connection/disconnection problems with wpa_supplicant and hostapd when using WPA2 encryption

[Adrien Decostre]

Dear Jouni,

Thanks a lot for this quick answer.
The ath9k driver is used on the access point with hostapd.
In attachment, there is a full log file from wpa_supplicant where the
client disconnects before the completion of the authentication
procedure (due to limited size of the attachment, I have cut the part
of the log showing successful authentication).
Up to now, I have seen this problem with different PCs among other one
with a rt2800usb driver

Is there a way to reduce the authentication timeout (now currently set
to 10sec.) such that in case of "authentication failure", the
authentication procedure is restarted sooner?


Thanks in advance for your answer.

On Mon, Jan 23, 2012 at 7:23 PM, Johannes Berg
<johannes at sipsolutions.net> wrote:
> On 2012-01-23 04:39, Adrien Decostre wrote:
>> Apparently, the client is 1st correctly associated (message “State:
>> ASSOCIATING -> ASSOCIATED” visible in the wpa_supplicant log) but the
>> client is soon after disconnected due to authentication problem with
>> the following error message:
>>
>> WPA: drop TX EAPOL in non-IEEE 802.1X mode (type=1 len=0)
>> Authentication with 00:0e:8e:3b:05:6d timed out.
>> BSSID 00:0e:8e:3b:05:6d blacklist count incremented to 2
>> wpa_driver_wext_disassociate
>> No keys have been configured - skip key clearing
>> State: ASSOCIATED -> DISCONNECTED.
>>
>>
>>
>> After this the client restarts the association/authentication
>> procedure and after a few tries the authentication succeed.
>
> Need logs from hostapd, but it could be that there are not enough
> random numbers.
>
> johannes
> _______________________________________________
> HostAP mailing list
> HostAP at lists.shmoo.com
> http://lists.shmoo.com/mailman/listinfo/hostap
-------------- next part --------------
# wpa_supplicant -c /config/wpa_supplicant.config -ddt -i wlan0
212.209018: Initializing interface 'wlan0' conf '/config/wpa_supplicant.config' driver 'default' ctrl_interface 'N/A' bridge 'N/A'
212.209612: Configuration file '/config/wpa_supplicant.config' -> '/config/wpa_supplicant.config'
212.209800: Reading configuration file '/config/wpa_supplicant.config'
212.210519: ctrl_interface='/var/run/wpa_supplicant'
212.210706: ctrl_interface_group='root'
212.210800: Line: 3 - start of a new network block
212.211050: ssid - hexdump_ascii(len=15):
     43 6c 69 63 6b 53 68 61 72 65 5f 41 44 45 43      Bidule_beta
212.211425: proto: 0x2
212.211581: key_mgmt: 0x2
212.211675: pairwise: 0x10
212.211769: PSK - hexdump(len=32): [REMOVED]
212.211956: priority=20 (0x14)
212.212331: Priority group 20
212.212456:    id=0 ssid='Bidule_beta'
212.212581: Initializing interface (2) 'wlan0'
212.214269: Interface wlan0 set UP - waiting a second for the driver to complete initialization
213.215116: SIOCGIWRANGE: WE(compiled)=22 WE(source)=9 enc_capa=0x0
213.215334:   capabilities: key_mgmt 0x0 enc 0x3 flags 0x0
213.242587: RSI: Operstate: linkmode=1, operstate=5
213.243462: Own MAC address: 00:23:a7:39:d0:69
213.243649: wpa_driver_rsi_set_wpa
213.243868: wpa_driver_rsi_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
213.244368: wpa_driver_rsi_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
213.244712: wpa_driver_rsi_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
213.245056: wpa_driver_rsi_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
213.245368: wpa_driver_rsi_set_countermeasures
213.245587: wpa_driver_rsi_set_drop_unencrypted
213.245743: RSN: flushing PMKID list in the driver
213.246024: Setting scan request: 0 sec 100000 usec
213.246306: WPS: UUID based on MAC address - hexdump(len=16): 26 90 53 f7 14 45 51 92 b4 ff ae 14 90 c1 50 79
213.246618: WPS: Build Beacon and Probe Response IEs
213.246775: WPS:  * Version
213.246900: WPS:  * Wi-Fi Protected Setup State (0)
213.247056: WPS:  * Version
213.247118: WPS:  * Wi-Fi Protected Setup State (0)
213.247181: WPS:  * Response Type (2)
213.247275: WPS:  * UUID-E
213.247368: WPS:  * Manufacturer
213.247431: WPS:  * Model Name
213.247525: WPS:  * Model Number
213.247587: WPS:  * Serial Number
213.247650: WPS:  * Primary Device Type
213.247743: WPS:  * Device Name
213.247775: WPS:  * Config Methods (0)
213.247868: WPS:  * RF Bands (3)
213.248056: EAPOL: SUPP_PAE entering state DISCONNECTED
213.248181: EAPOL: KEY_RX entering state NO_KEY_RECEIVE
213.248306: EAPOL: SUPP_BE entering state INITIALIZE
213.248400: EAP: EAP entering state DISABLED
213.249244: ctrl_interface_group=0 (from group name 'root')
213.258963: Added interface wlan0
213.259463: RTM_NEWLINK: operstate=0 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
213.259619: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
213.259838: RTM_NEWLINK: operstate=0 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
213.260276: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
213.260401: Wireless event: cmd=0x8b06 len=8
213.260557: RTM_NEWLINK: operstate=0 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
213.260713: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
213.260838: Wireless event: cmd=0x8b1a len=40
213.260963: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
213.261088: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
213.346375: State: DISCONNECTED -> SCANNING
213.346594: Starting AP scan (broadcast SSID)
213.346687: Trying to get current scan results first without requesting a new scan to speed up initial association
213.348375: Received 890 bytes of scan results (8 BSSes)
213.348562: New scan results available
213.348750: WPS: attr type=0x104a len=1
213.348875: WPS: attr type=0x1044 len=1
213.348969: WPS: attr type=0x104a len=1
213.349062: WPS: attr type=0x1044 len=1
213.349156: WPS-AP-AVAILABLE
213.349250: Selecting BSS from priority group 20
213.349312: Try to find WPA-enabled AP
213.349406: 0: 00:0e:8e:3b:05:6d ssid='Bidule_beta' wpa_ie_len=0 rsn_ie_len=20 caps=0x11
213.349625:    selected based on RSN IE
213.349719:    selected WPA AP 00:0e:8e:3b:05:6d ssid='Bidule_beta'
213.349937: Trying to associate with 00:0e:8e:3b:05:6d (SSID='Bidule_beta' freq=2472 MHz)
213.362281: Cancelling scan request
213.362437: WPA: clearing own WPA/RSN IE
213.362781: Automatic auth_alg selection: 0x1
213.363125: RSN: using IEEE 802.11i/D9.0
213.363250: WPA: Selected cipher suites: group 16 pairwise 16 key_mgmt 2 proto 2
213.363375: WPA: clearing AP WPA IE
213.363468: WPA: set AP RSN IE - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
213.363750: WPA: using GTK CCMP
213.363843: WPA: using PTK CCMP
213.363937: WPA: using KEY_MGMT WPA-PSK
213.364031: WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
213.364312: No keys have been configured - skip key clearing
213.364406: wpa_driver_rsi_set_drop_unencrypted
213.364562: State: SCANNING -> ASSOCIATING
213.364656: wpa_driver_rsi_set_operstate: operstate 0->0 (DORMANT)
213.364781: RSI: Operstate: linkmode=-1, operstate=5
213.364968: wpa_driver_rsi_associate
213.365500: wpa_driver_rsi_set_psk
213.369562: Setting authentication timeout: 10 sec 0 usec
213.369750: EAPOL: External notification - EAP success=0
213.369843: EAPOL: External notification - EAP fail=0
213.369937: EAPOL: External notification - portControl=Auto
213.380343: RSN: Ignored PMKID candidate without preauth flag
213.380625: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
213.380812: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
213.380937: Wireless event: cmd=0x8b06 len=8
213.381062: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
213.381187: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
213.381281: Wireless event: cmd=0x8b04 len=12
213.381406: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
213.381562: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
213.381656: Wireless event: cmd=0x8b1a len=23
213.407656: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
213.407843: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
213.407999: Wireless event: cmd=0x8b15 len=20
213.408093: Wireless event: new AP: 00:0e:8e:3b:05:6d
213.408187: State: ASSOCIATING -> ASSOCIATED
213.408281: wpa_driver_rsi_set_operstate: operstate 0->0 (DORMANT)
213.408374: RSI: Operstate: linkmode=-1, operstate=5
213.408812: Associated to a new BSS: BSSID=00:0e:8e:3b:05:6d
213.408937: No keys have been configured - skip key clearing
213.409062: Associated with 00:0e:8e:3b:05:6d
213.409156: WPA: Association event - clear replay counter
213.409218: WPA: Clear old PTK
213.409312: EAPOL: External notification - portEnabled=0
213.409406: EAPOL: External notification - portValid=0
213.409499: EAPOL: External notification - EAP success=0
213.409562: EAPOL: External notification - portEnabled=1
213.409656: EAPOL: SUPP_PAE entering state CONNECTING
213.409718: EAPOL: SUPP_BE entering state IDLE
213.742656: Setting authentication timeout: 10 sec 0 usec
213.742812: Cancelling scan request
214.249156: EAPOL: startWhen --> 0
214.249343: EAPOL: disable timer tick
214.249437: EAPOL: SUPP_PAE entering state CONNECTING
214.249531: EAPOL: enable timer tick
214.249593: EAPOL: txStart
214.249687: WPA: drop TX EAPOL in non-IEEE 802.1X mode (type=1 len=0)
223.743495: Authentication with 00:0e:8e:3b:05:6d timed out.
223.743651: Added BSSID 00:0e:8e:3b:05:6d into blacklist
223.743807: wpa_driver_rsi_disassociate
223.744682: No keys have been configured - skip key clearing
223.744807: State: ASSOCIATED -> DISCONNECTED
223.744932: wpa_driver_rsi_set_operstate: operstate 0->0 (DORMANT)
223.745057: RSI: Operstate: linkmode=-1, operstate=5
223.749714: EAPOL: External notification - portEnabled=0
223.760434: EAPOL: SUPP_PAE entering state DISCONNECTED
223.760527: EAPOL: SUPP_BE entering state INITIALIZE
223.760621: EAPOL: External notification - portValid=0
223.760715: EAPOL: External notification - EAP success=0
223.760871: Setting scan request: 0 sec 0 usec
223.761059: State: DISCONNECTED -> SCANNING
223.761153: Starting AP scan (broadcast SSID)
223.765872: Scan requested (ret=0) - scan timeout 20 seconds
223.766153: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
223.766309: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
223.766434: Wireless event: cmd=0x8b1a len=40
223.766809: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
223.766966: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
223.767091: Wireless event: cmd=0x8b15 len=20
223.767216: Wireless event: new AP: 00:00:00:00:00:00
223.767341: Added BSSID 00:00:00:00:00:00 into blacklist
223.767466: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
223.767559: wpa_driver_rsi_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
223.767903: wpa_driver_rsi_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
223.768247: wpa_driver_rsi_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
223.768591: wpa_driver_rsi_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
223.768903: wpa_driver_rsi_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
223.769247: State: SCANNING -> DISCONNECTED
223.769372: wpa_driver_rsi_set_operstate: operstate 0->0 (DORMANT)
223.769466: RSI: Operstate: linkmode=-1, operstate=5
223.769653: EAPOL: External notification - portEnabled=0
223.769747: EAPOL: External notification - portValid=0
223.769841: EAPOL: External notification - EAP success=0
232.228156: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
232.228406: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
232.228531: Wireless event: cmd=0x8b19 len=8
232.244906: Received 946 bytes of scan results (8 BSSes)
232.245156: New scan results available
232.245312: WPS: attr type=0x104a len=1
232.245406: WPS: attr type=0x1044 len=1
232.245500: WPS: attr type=0x104a len=1
232.245562: WPS: attr type=0x1044 len=1
232.245656: WPS-AP-AVAILABLE
232.245781: Selecting BSS from priority group 20
232.245875: Try to find WPA-enabled AP
232.245937: 0: 00:0e:8e:3b:10:40 ssid='Bidule_alpha_1' wpa_ie_len=0 rsn_ie_len=20 caps=0x11
232.246093:    skip - SSID mismatch
232.246156: 1: 00:0e:8e:3b:05:6d ssid='Bidule_beta' wpa_ie_len=0 rsn_ie_len=20 caps=0x11
232.246312:    selected based on RSN IE
232.246406:    selected WPA AP 00:0e:8e:3b:05:6d ssid='Bidule_beta'
232.246593: Trying to associate with 00:0e:8e:3b:05:6d (SSID='Bidule_beta' freq=2472 MHz)
232.246687: Cancelling scan request
232.246781: WPA: clearing own WPA/RSN IE
232.247156: Automatic auth_alg selection: 0x1
232.247437: RSN: using IEEE 802.11i/D9.0
232.247562: WPA: Selected cipher suites: group 16 pairwise 16 key_mgmt 2 proto 2
232.247656: WPA: clearing AP WPA IE
232.247750: WPA: set AP RSN IE - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
232.248062: WPA: using GTK CCMP
232.248156: WPA: using PTK CCMP
232.248250: WPA: using KEY_MGMT WPA-PSK
232.248312: WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
232.248625: No keys have been configured - skip key clearing
232.248687: wpa_driver_rsi_set_drop_unencrypted
232.248843: State: DISCONNECTED -> ASSOCIATING
232.248968: wpa_driver_rsi_set_operstate: operstate 0->0 (DORMANT)
232.249062: RSI: Operstate: linkmode=-1, operstate=5
232.249281: wpa_driver_rsi_associate
232.249781: wpa_driver_rsi_set_psk
232.293531: Setting authentication timeout: 10 sec 0 usec
232.307312: EAPOL: External notification - EAP success=0
232.307437: EAPOL: External notification - EAP fail=0
232.307562: EAPOL: External notification - portControl=Auto
232.307750: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
232.307875: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
232.307968: Wireless event: cmd=0x8b06 len=8
232.308093: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
232.308281: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
232.308375: Wireless event: cmd=0x8b04 len=12
232.308500: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
232.308625: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
232.308718: Wireless event: cmd=0x8b1a len=23
232.332093: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
232.332281: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
232.332406: Wireless event: cmd=0x8b15 len=20
232.332531: Wireless event: new AP: 00:0e:8e:3b:05:6d
232.332656: State: ASSOCIATING -> ASSOCIATED
232.332718: wpa_driver_rsi_set_operstate: operstate 0->0 (DORMANT)
232.332812: RSI: Operstate: linkmode=-1, operstate=5
232.333281: Associated to a new BSS: BSSID=00:0e:8e:3b:05:6d
232.333375: No keys have been configured - skip key clearing
232.333531: Associated with 00:0e:8e:3b:05:6d
232.333625: WPA: Association event - clear replay counter
232.333687: WPA: Clear old PTK
232.333750: EAPOL: External notification - portEnabled=0
232.333843: EAPOL: External notification - portValid=0
232.333937: EAPOL: External notification - EAP success=0
232.334031: EAPOL: External notification - portEnabled=1
232.334125: EAPOL: SUPP_PAE entering state CONNECTING
232.334187: EAPOL: SUPP_BE entering state IDLE
232.334281: Setting authentication timeout: 10 sec 0 usec
232.334406: Cancelling scan request
232.341125: RX EAPOL from 00:0e:8e:3b:05:6d
232.341281: RX EAPOL - hexdump(len=99): 02 03 00 5f 02 00 8a 00 10 00 00 00 00 00 00 00 01 5b fd 5b d8 2f 7f 7e 09 89 1a 4e a6 e1 7d fa f6 46 f8 f4 f9 57 1d 60 dd 24 6c ff 72 b8 0b 1f 07 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
232.342343: Setting authentication timeout: 10 sec 0 usec
232.342500: IEEE 802.1X RX: version=2 type=3 length=95
232.342625:   EAPOL-Key type=2
232.342687:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
232.342843:   key_length=16 key_data_length=0
232.342968:   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 01
232.343125:   key_nonce - hexdump(len=32): 5b fd 5b d8 2f 7f 7e 09 89 1a 4e a6 e1 7d fa f6 46 f8 f4 f9 57 1d 60 dd 24 6c ff 72 b8 0b 1f 07
232.343468:   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
232.343750:   key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
232.343875:   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
232.344031:   key_mic - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
232.344281: WPA: RX EAPOL-Key - hexdump(len=99): 02 03 00 5f 02 00 8a 00 10 00 00 00 00 00 00 00 01 5b fd 5b d8 2f 7f 7e 09 89 1a 4e a6 e1 7d fa f6 46 f8 f4 f9 57 1d 60 dd 24 6c ff 72 b8 0b 1f 07 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
232.345562: State: ASSOCIATED -> 4WAY_HANDSHAKE