wpa_supplicant not perform 4way handshake while using wpa-psk security

[Vasanth Ragavendran]

Hi

I am using hostapd and wpa-supplicant ver 0.8.x for my ap and client
running linux 2.6.31 version with mips architecture. There is some issue
while trying to use WPA-PSK security method. With the hostapd running I
give the command to run wpa_supplicant. However, it says 'ASSOCIATED' when
run in debug mode. and after which it doesn't perform a 4-way handshake. it
immediately disconnects from the AP and tries to scan and associate again.
What could be the reason behind this. I've checked every possible detail
and everything seem to be correct. Here is the wpa_supplicant.conf file

ap_scan=1
network={
 ssid="wireless_vap_333"
 scan_ssid=1
    proto=WPA
        key_mgmt=WPA-PSK
        pairwise=CCMP
        psk="firmware123"
}

and the corresponding hostapd.conf file being

interface=ath0
bridge=br0
logger_syslog=-1
logger_syslog_level=2
logger_stdout=-1
logger_stdout_level=2
ctrl_interface=/var/run/hostapd
ctrl_interface_group=0
ssid=wireless_vap_333
dtim_period=2
max_num_sta=255
macaddr_acl=0
auth_algs=1
ignore_broadcast_ssid=0
wme_enabled=0
ieee8021x=0
eapol_version=2
eapol_key_index_workaround=0
eap_server=1
wpa=1
wpa_passphrase=firmware123
wpa_key_mgmt=WPA-PSK
wpa_pairwise=CCMP
wpa_strict_rekey=1

I've tried to my best to solve this issue. But I couldn't solve it. And the
command i use to run the hostapd and wpa_supplicant are
hostapd -B /tmp/hostapd.conf
wpa_supplicant -c/tmp/wpa_supplicant.conf -iath0 -bbr0 -dd

and kindly find attached the log of wpa_supplicant when it is trying to
associate. It's a little lengthy.

Having a closer look revealed that the state changes from ASSOCIATING ->
ASSOCIATED. However, after that ath0 interface gets disabled before
performing a 4way handshake and this whole process repeats infinitely. Why
this is happening? I don't think its due to some configuration setting. Or
am I wrong in assuming so?! Kindly help me out. I'm struck at this stage
and have been breaking my head over it for the past 2 days!

Thanks and Regards
R.Vasanth Ragavendran.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.shmoo.com/pipermail/hostap/attachments/20120131/fad41726/attachment.htm 
-------------- next part --------------
random: Trying to read entropy from /dev/random
Initializing interface 'ath0' conf '/tmp/supath0' driver 'default' ctrl_interface 'N/A' bridge 'br0'
Configuration file '/tmp/supath0' -> '/tmp/supath0'
Reading configuration file '/tmp/supath0'
ap_scan=1
Line: 2 - start of a new network block
ssid - hexdump_ascii(len=16):
     77 69 72 65 6c 65 73 73 5f 76 61 70 5f 33 33 33   wireless_vap_333
scan_ssid=1 (0x1)
proto: 0x1
key_mgmt: 0x2
pairwise: 0x10
PSK (ASCII passphrase) - hexdump_ascii(len=11): [REMOVED]
PSK (from passphieee80211_ioctl_getparam : parameter 0x284 not supported
rase) - hexdump(len=32): [REMOVED]
Priority group 0
   id=0 ssid='wireless_vap_333'
athr: Driver version 9.2.0_U8.834
call80211ioctl: 4 op=0x8be1 (GETPARAM) subop=0x284=644 value=0x0,0x0
call80211ioctl: op=0x8be1 (GETPARAM) subop=0x284=644 value=0x0,0x0 failed: 122 (Operation not supported)
athrosx: Failed to get interface P2P opmode
br0: port 2(ath0) entering forwarding state
SIOCGIWRANGE: WE(compiled)=22 WE(source)=13 enc_capa=0xf
  capabilities: key_mgmt 0xf enc 0xf flags 0x0
call80211ioctl: 4 op=0x8be1 (GETPARAM) subop=0x4f=79 value=0x0,0x0
athr: Country code changed 0 -> 702
ath0: Event 31 received on interface ath0
set80211param_ifname: ifname=ath0 subioctl=646 (SCAN_FLUSH) arg=0
set80211param_ifname: ifname=ath0 subioctl=12 (??) arg=2
ath0: Own MAC address: 00:06:c7:50:12:02
ath0: Receiving packets from bridge interface 'br0'
driver_atheros_del_key: keyidx=0
driver_atheros_del_key: keyidx=1
driver_atheros_del_key: keyidx=2
driver_atheros_del_key: keyidx=3
driver_atheros_set_countermeasures: enabled=0
set80211param_ifname: ifname=ath0 subioctl=14 (COUNTERMEASURES) arg=0
ath0: RSN: flushing PMKID list in the driver
ath0: Setting scan request: 0 sec 100000 usec
WPS: Set UUID for interface ath0
WPS: UUID based on MAC address - hexdump(len=16): b0 de 6a d3 1f 22 58 83 85 89 d5 cf 24 54 a1 31
EAPOL: SUPP_PAE entering state DISCONNECTED
EAPOL: Supplicant port status: Unauthorized
EAPOL: KEY_RX entering state NO_KEY_RECEIVE
EAPOL: SUPP_BE entering state INITIALIZE
EAP: EAP entering state DISABLED
EAPOL: Supplicant port status: Unauthorized
EAPOL: Supplicant port status: Unauthorized
ath0: Added interface ath0
br0: port 2(ath0) entering disabled state
ath0: State: DISCONNECTED -> SCANNING
Scan SSID - hexdump_ascii(len=16):
     77 69 72 65 6c 65 73 73 5f 76 61 70 5f 33 33 33   wireless_vap_333
ath0: Starting AP scan for wildcard SSID
set80211param_ifname: ifname=ath0 subioctl=646 (SCAN_FLUSH) arg=0
set80211big: op=0x270=624 (SCAN_REQ) len=0xc8
call80211ioctl: 4 op=0x89fe (P2P_BIG_PARAM) subop=0x48fef0=4783856 value=0xc8,0x270
Scan requested (ret=0) - scan timeout 30 seconds
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
ath0: Event 5 received on interface ath0
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
ath0: Event 5 received on interface ath0
EAPOL: disable timer tick
EAPOL: Supplicant port status: Unauthorized
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
ath0: Event 5 received on interface ath0
Wireless event: cmd=0x8b19 len=8
driver_atheros_event_wireless: scan result event - SIOCGIWSCAN
call80211ioctl: 4 op=0x8be1 (GETPARAM) subop=0x4f=79 value=0x0,0x0
ath0: Event 3 received on interface ath0
driver_atheros_get_scan_results: 15456 bytes of scan available
<<<<a long list of values are displayed here. i've removed them here to increase readability>>>>>
Received 15456 bytes of scan results (65 BSSes)
set80211big: op=0x289=649 (P2P_FIND_BEST_CHANNEL) len=0xc
call80211ioctl: 4 op=0x89fe (P2P_BIG_PARAM) subop=0x7fc47830=2143582256 value=0xc,0x289
call80211ioctl: op=0x89fe (P2P_BIG_PARAM) subop=0x7fc47830=2143582256 value=0xc,0x289 failed: 22 (Invalid argument)
driver_atheros_get_best_channel set80211big returns -1
ath0: BSS: Start scan result update 1
ath0: BSS: Add new id 0 BSSID 00:03:7f:42:07:c9 SSID 'wireless_vap_333'
<<<<removed the rest of the scanned mac id's for readability except the one above which is ap to be connected to>>>>>
Add randomness: count=1 entropy=0
Add randomness: count=2 entropy=1
Add randomness: count=3 entropy=2
Add randomness: count=4 entropy=3
Add randomness: count=5 entropy=4
Add randomness: count=6 entropy=5
Add randomness: count=7 entropy=6
Add randomness: count=8 entropy=7
Add randomness: count=9 entropy=8
Add randomness: count=10 entropy=9
ath0: New scan results available
ath0: Selecting BSS from priority group 0
ath0: 0: 00:03:7f:42:07:c9 ssid='wireless_vap_333' wpa_ie_len=22 rsn_ie_len=0 caps=0x511 level=75
ath0:    selected based on WPA IE
ath0:    selected BSS 00:03:7f:42:07:c9 ssid='wireless_vap_333'
ath0: Request association: reassociate: 0  selected: 00:03:7f:42:07:c9  bssid: 00:00:00:00:00:00  pending: 00:00:00:00:00:00  wpa_state: SCANNING
ath0: Trying to associate with 00:03:7f:42:07:c9 (SSID='wireless_vap_333' freq=5745
 DES SSID SET=wireless_vap_333
 MHz)
ath0: Can
 DES SSID SET=wireless_vap_333
celling scan req ieee80211_ioctl_setmlme: os_opmode=1
uest
ath0: WPA:[ieee80211_ioctl_setmlme] set desired bssid 00:03:7f:42:07:c9
 clearing own WPA/RSN IE
ath0: Automatic auth_alg selection: 0x1
ath0: WPA: using IEEE 802.11i/D3.0
ath0: WPA: Selected cipher suites: group 16 pairwise 16 key_mgmt 2 proto 1
WPA: set AP WPA IE - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 04 01 00 00 50 f2 04 01 00 00 50 f2 02
ath0: WPA: clearing AP RSN IE
ath0: WPA: using GTK CCMP
ath0: WPA: using PTK CCMP
ath0: WPA: using KEY_MGMT WPA-PSK
WPA: Set own WPA IE default - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 04 01 00 00 50 f2 04 01 00 00 50 f2 02
ath0: No keys have been configured - skip key clearing
ath0: State: SCANNING -> ASSOCIATING
driver_atheros_set_operstate: operstate 0->0 (DORMANT)
netlink: Operstate: linkmode=-1, operstate=5
athr: Associate: mode=0 p2p=0 freq=5745
athr: Association IEs - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 04 01 00 00 50 f2 04 01 00 00 50 f2 02
set80211param_ifname: ifname=ath0 subioctl=15 (DROPUNENCRYPTED) arg=1
 *** KEY MGMT is 2
set80211param_ifname: ifname=ath0 subioctl=10 (WPA) arg=1
set80211param_ifname: ifname=ath0 subioctl=3 (AUTHMODE) arg=5
athr: Set cipher type=8 suite=3
athr: cipher=3
set80211param_ifname: ifname=ath0 subioctl=8 (UCASTCIPHER) arg=3
athr: Set cipher type=5 suite=3
athr: cipher=3
set80211param_ifname: ifname=ath0 subioctl=5 (MCASTCIPHER) arg=3
WPA IE: ifname:ath0 len=24
set80211param_ifname: ifname=ath0 subioctl=13 (PRIVACY) arg=1
set80211param_ifname: ifname=ath0 subioctl=632 (WPS_MODE) arg=0
set80211param_ifname: ifname=ath0 subioctl=12 (??) arg=2
Associating.. AP BSSID=00:03:7f:42:07:c9, ssid=wireless_vap_333, op=1
 driver_atheros_set_mlme: OP mode = 1
br0: port 2(ath0) entering learning state
ath0: Setting authentication timeout: 10 sec 0 usec
EAPOL: External notification - EAP success=0
EAPOL: Supplicant port status: Unauthorized
EAPOL: External notification - EAP fail=0
EAPOL: Supplicant port status: Unauthorized
EAPOL: External notification - portControl=Auto
EAPOL: Supplicant port status: Unauthorized
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
ath0: Event 5 received on interface ath0
Wireless event: cmd=0x8b15 len=20
Wireless event: new AP: 00:03:7f:42:07:c9
ath0: Event 4 received on interface ath0
ath0: Association info event
ath0: freq=5745 MHz
ath0: Event 0 received on interface ath0
ath0: State: ASSOCIATING -> ASSOCIATED
driver_atheros_set_operstate: operstate 0->0 (DORMANT)
netlink: Operstate: linkmode=-1, operstate=5
ath0: Associated to a new BSS: BSSID=00:03:7f:42:07:c9
Add randomness: count=11 entropy=10
ath0: No keys have been configured - skip key clearing
ath0: Associated with 00:03:7f:42:07:c9
ath0: WPA: Association event - clear replay counter
ath0: WPA: Clear old PTK
EAPOL: External notification - portEnabled=0
EAPOL: Supplicant port status: Unauthorized
EAPOL: External notification - portValid=0
EAPOL: Supplicant port status: Unauthorized
EAPOL: External notification - EAP success=0
EAPOL: Supplicant port status: Unauthorized
EAPOL: External notification - portEnabled=1
EAPOL: SUPP_PAE entering state CONNECTING
EAPOL: enable timer tick
EAPOL: SUPP_BE entering state IDLE
ath0: Setting authentication timeout: 10 sec 0 usec
ath0: Cancelling scan request
RTM_NEWLINK: operstate=0 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
ath0: Event 5 received on interface ath0
RTM_NEWLINK: operstate=0 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
ath0: Event 5 received on interface ath0
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
ath0: Event 5 received on interface ath0
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
ath0: Event 5 received on interface ath0
EAPOL: startWhen --> 0
EAPOL: disable timer tick
EAPOL: SUPP_PAE entering state CONNECTING
EAPOL: enable timer tick
EAPOL: txStart
WPA: drop TX EAPOL in non-IEEE 802.1X mode (type=1 len=0)
br0: port 2(ath0) entering disabled state
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
ath0: Event 5 received on interface ath0
Wireless event: cmd=0x8b15 len=20
Wireless event: new AP: 00:00:00:00:00:00
ath0: Event 1 received on interface ath0
ath0: Disassociation notification
ath0: WPA: Auto connect enabled: try to reconnect (wps=0)
ath0: Setting scan request: 0 sec 100000 usec
Added BSSID 00:03:7f:42:07:c9 into blacklist
ath0: Not rescheduling scan to ensure that specific SSID scans occur
ath0: CTRL-EVENT-DISCONNECTED bssid=00:03:7f:42:07:c9 reason=0
ath0: Disconnect event - remove keys
driver_atheros_del_key: keyidx=0
driver_atheros_del_key: keyidx=1
driver_atheros_del_key: keyidx=2
driver_atheros_del_key: keyidx=3
driver_atheros_del_key: keyidx=0
ath0: State: ASSOCIATED -> DISCONNECTED
driver_atheros_set_operstate: operstate 0->0 (DORMANT)
netlink: Operstate: linkmode=-1, operstate=5
EAPOL: External notification - portEnabled=0
EAPOL: SUPP_PAE entering state DISCONNECTED
EAPOL: Supplicant port status: Unauthorized
EAPOL: SUPP_BE entering state INITIALIZE
EAPOL: Supplicant port status: Unauthorized
EAPOL: External notification - portValid=0
EAPOL: Supplicant port status: Unauthorized
EAPOL: External notification - EAP success=0
EAPOL: Supplicant port status: Unauthorized
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
ath0: Event 5 received on interface ath0
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
ath0: Event 5 received on interface ath0
ath0: State: DISCONNECTED -> SCANNING