Problem connecting to hostapd AP

Nikolay Martynov mar.kolya at gmail.com
Sat Jan 22 00:42:44 EST 2011


Hi.

  I have the following problem.
  Devices:
    - TEW-632 (ath9k) router with latest openwrt
    - Dell laptop with intel 5300 card and Ubuntu
    - Macbook pro.

  I experience disconnects from my AP several times a day and some
times (~once a day) clients cannot reconnect back. I mean all clients
cannot connect. Bellow I have logs from AP and Ubuntu client in a
situation when no client can connect to AP. Could you please have a
look and tell me whether this is hostapd problem or wireless driver
problem? Or may be some other problem. Thanks in advance!

  Hostapd logs on router:
  --------------------
Jan 22 00:23:16 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 IEEE 802.11: authentication OK (open system)
Jan 22 00:23:16 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 MLME:
MLME-AUTHENTICATE.indication(xx:xx:xx:xx:18:56, OPEN_SYSTEM)
Jan 22 00:23:16 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 MLME: MLME-DELETEKEYS.request(xx:xx:xx:xx:18:56)
Jan 22 00:23:16 router user.notice hostapd: wlan0: STA
xx:xx:xx:xx:18:56 IEEE 802.11: did not acknowledge authentication
response
Jan 22 00:23:16 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 IEEE 802.11: association OK (aid 2)
Jan 22 00:23:16 router user.info hostapd: wlan0: STA xx:xx:xx:xx:18:56
IEEE 802.11: associated (aid 2)
Jan 22 00:23:16 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 MLME: MLME-ASSOCIATE.indication(xx:xx:xx:xx:18:56)
Jan 22 00:23:16 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 MLME: MLME-DELETEKEYS.request(xx:xx:xx:xx:18:56)
Jan 22 00:23:16 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 WPA: event 1 notification
Jan 22 00:23:16 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 WPA: start authentication
Jan 22 00:23:16 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 IEEE 802.1X: unauthorizing port
Jan 22 00:23:16 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 WPA: sending 1/4 msg of 4-Way Handshake
Jan 22 00:23:16 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 WPA: EAPOL-Key timeout
Jan 22 00:23:16 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 WPA: sending 1/4 msg of 4-Way Handshake
Jan 22 00:23:17 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 WPA: EAPOL-Key timeout
Jan 22 00:23:17 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 WPA: sending 1/4 msg of 4-Way Handshake
Jan 22 00:23:18 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 WPA: received EAPOL-Key frame (2/4 Pairwise)
Jan 22 00:23:18 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 WPA: sending 3/4 msg of 4-Way Handshake
Jan 22 00:23:18 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 WPA: EAPOL-Key timeout
Jan 22 00:23:18 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 WPA: sending 3/4 msg of 4-Way Handshake
Jan 22 00:23:19 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 WPA: EAPOL-Key timeout
Jan 22 00:23:19 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 WPA: sending 3/4 msg of 4-Way Handshake
Jan 22 00:23:20 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 WPA: EAPOL-Key timeout
Jan 22 00:23:20 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 WPA: sending 3/4 msg of 4-Way Handshake
Jan 22 00:23:21 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 WPA: EAPOL-Key timeout
Jan 22 00:23:21 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 IEEE 802.1X: unauthorizing port
Jan 22 00:23:21 router user.info hostapd: wlan0: STA xx:xx:xx:xx:18:56
IEEE 802.11: deauthenticated due to local deauth request
Jan 22 00:23:38 router user.notice hostapd: wlan1: STA
xx:xx:xx:xx:18:56 IEEE 802.11: did not acknowledge authentication
response
Jan 22 00:23:38 router user.info hostapd: wlan1: STA xx:xx:xx:xx:18:56
IEEE 802.11: associated (aid 1)
Jan 22 00:23:41 router user.info hostapd: wlan1: STA xx:xx:xx:xx:18:56
IEEE 802.11: deauthenticated due to local deauth request
Jan 22 00:23:44 router user.notice hostapd: wlan1: STA
xx:xx:xx:xx:18:56 IEEE 802.11: did not acknowledge authentication
response
Jan 22 00:23:58 router user.notice hostapd: wlan1: STA
xx:xx:xx:xx:18:56 IEEE 802.11: did not acknowledge authentication
response
Jan 22 00:24:20 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 IEEE 802.11: authentication OK (open system)
Jan 22 00:24:20 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 MLME:
MLME-AUTHENTICATE.indication(xx:xx:xx:xx:18:56, OPEN_SYSTEM)
Jan 22 00:24:20 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 MLME: MLME-DELETEKEYS.request(xx:xx:xx:xx:18:56)
Jan 22 00:24:20 router user.info hostapd: wlan1: STA xx:xx:xx:xx:18:56
IEEE 802.11: deauthenticated due to local deauth request
Jan 22 00:24:20 router user.notice hostapd: wlan0: STA
xx:xx:xx:xx:18:56 IEEE 802.11: did not acknowledge authentication
response
Jan 22 00:24:21 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 IEEE 802.11: association OK (aid 2)
Jan 22 00:24:21 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 IEEE 802.11: did not acknowledge association
response
Jan 22 00:24:34 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 IEEE 802.11: authentication OK (open system)
Jan 22 00:24:34 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 WPA: event 0 notification
Jan 22 00:24:34 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 MLME:
MLME-AUTHENTICATE.indication(xx:xx:xx:xx:18:56, OPEN_SYSTEM)
Jan 22 00:24:34 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 MLME: MLME-DELETEKEYS.request(xx:xx:xx:xx:18:56)
Jan 22 00:24:34 router user.notice hostapd: wlan0: STA
xx:xx:xx:xx:18:56 IEEE 802.11: did not acknowledge authentication
response
Jan 22 00:24:35 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 IEEE 802.11: association OK (aid 2)
Jan 22 00:24:35 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 IEEE 802.11: did not acknowledge association
response
Jan 22 00:24:48 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 IEEE 802.11: authentication OK (open system)
Jan 22 00:24:48 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 WPA: event 0 notification
Jan 22 00:24:48 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 MLME:
MLME-AUTHENTICATE.indication(xx:xx:xx:xx:18:56, OPEN_SYSTEM)
Jan 22 00:24:48 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 MLME: MLME-DELETEKEYS.request(xx:xx:xx:xx:18:56)
Jan 22 00:24:48 router user.notice hostapd: wlan0: STA
xx:xx:xx:xx:18:56 IEEE 802.11: did not acknowledge authentication
response
Jan 22 00:25:09 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 IEEE 802.11: authentication OK (open system)
Jan 22 00:25:09 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 WPA: event 0 notification
Jan 22 00:25:09 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 MLME:
MLME-AUTHENTICATE.indication(xx:xx:xx:xx:18:56, OPEN_SYSTEM)
Jan 22 00:25:09 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 MLME: MLME-DELETEKEYS.request(xx:xx:xx:xx:18:56)
Jan 22 00:25:09 router user.notice hostapd: wlan0: STA
xx:xx:xx:xx:18:56 IEEE 802.11: did not acknowledge authentication
response
Jan 22 00:25:09 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 IEEE 802.11: association OK (aid 2)
Jan 22 00:25:09 router user.debug hostapd: wlan0: STA
xx:xx:xx:xx:18:56 IEEE 802.11: did not acknowledge association
response
  --------------------

  Wpa_supplican log on Ubuntu laptop:
  --------------------
Jan 22 00:17:43 kolya-laptop kernel: [ 2500.028513] wlan1:
authenticate with xx:xx:xx:xx:50:2d (try 1)
Jan 22 00:17:43 kolya-laptop kernel: [ 2500.228052] wlan1:
authenticate with xx:xx:xx:xx:50:2d (try 2)
Jan 22 00:17:43 kolya-laptop kernel: [ 2500.232570] wlan1: authenticated
Jan 22 00:17:43 kolya-laptop kernel: [ 2500.232637] wlan1: associate
with xx:xx:xx:xx:50:2d (try 1)
Jan 22 00:17:43 kolya-laptop kernel: [ 2500.432052] wlan1: associate
with xx:xx:xx:xx:50:2d (try 2)
Jan 22 00:17:44 kolya-laptop kernel: [ 2500.632066] wlan1: associate
with xx:xx:xx:xx:50:2d (try 3)
Jan 22 00:17:44 kolya-laptop kernel: [ 2500.635797] wlan1: RX
AssocResp from xx:xx:xx:xx:50:2d (capab=0x411 status=0 aid=2)
Jan 22 00:17:44 kolya-laptop kernel: [ 2500.635804] wlan1: associated
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: RTM_NEWLINK:
operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: RTM_NEWLINK,
IFLA_IFNAME: Interface 'wlan1' added
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: RTM_NEWLINK:
operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: RTM_NEWLINK,
IFLA_IFNAME: Interface 'wlan1' added
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: Wireless event:
cmd=0x8c08 len=102
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: RTM_NEWLINK:
operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: RTM_NEWLINK,
IFLA_IFNAME: Interface 'wlan1' added
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: Wireless event:
cmd=0x8b15 len=20
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: Wireless event: new
AP: xx:xx:xx:xx:50:2d
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: Association info event
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: State: ASSOCIATING
-> ASSOCIATED
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]:
wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: WEXT: Operstate:
linkmode=-1, operstate=5
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: Associated to a new
BSS: BSSID=xx:xx:xx:xx:50:2d
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: No keys have been
configured - skip key clearing
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: WPA: Association
event - clear replay counter
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: WPA: Clear old PTK
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: EAPOL: External
notification - portEnabled=0
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: EAPOL: External
notification - portValid=0
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: EAPOL: External
notification - EAP success=0
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: EAPOL: External
notification - portEnabled=1
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: EAPOL: SUPP_PAE
entering state CONNECTING
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: EAPOL: SUPP_BE
entering state IDLE
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: Setting
authentication timeout: 10 sec 0 usec
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: Cancelling scan request
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: EAPOL: startWhen --> 0
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: EAPOL: disable timer tick
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: EAPOL: SUPP_PAE
entering state CONNECTING
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: EAPOL: enable timer tick
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: EAPOL: txStart
Jan 22 00:17:44 kolya-laptop wpa_supplicant[1024]: WPA: drop TX EAPOL
in non-IEEE 802.1X mode (type=1 len=0)
Jan 22 00:17:54 kolya-laptop wpa_supplicant[1024]: BSSID
xx:xx:xx:xx:50:2d blacklist count incremented to 2
Jan 22 00:17:54 kolya-laptop wpa_supplicant[1024]: wpa_driver_wext_disassociate
Jan 22 00:17:54 kolya-laptop kernel: [ 2510.656189] wlan1:
deauthenticating from xx:xx:xx:xx:50:2d by local choice (reason=3)
Jan 22 00:17:54 kolya-laptop wpa_supplicant[1024]: No keys have been
configured - skip key clearing
Jan 22 00:17:54 kolya-laptop wpa_supplicant[1024]: State: ASSOCIATED
-> DISCONNECTED
  --------------------


-- 
Truthfully yours,
Martynov Nikolay.
Email: mar.kolya at gmail.com
Phone: +16478220537


More information about the HostAP mailing list