Problem connecting to hostapd AP

Mon Jan 24 22:36:07 PST 2011

Hi.

  Is there any chance somebody could look into this and at least give
me an idea how I can diagnose problem further? AP dies on me couple of
times a day and I've run out of ideas. I would greatly appreciate any
help.
  Thanks!

2011/1/22 Nikolay Martynov <mar.kolya at gmail.com>:
> 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