PMK Caching Issue

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Hello,

We have a station using openwrt with wpa_supplicant version 2.6. We are having issues when our station tries to connect using PMK caching with the AP. The station can connect when trying to reassociate with the AP using the wpa_cli command "wpa_cli reassociate"  and letting the command finished. However, when the reassociate command gets sent multiple times before the handshake finishes, the station is unable to connect. The reason this issue becomes a problem is that when we enable background scanning (bgscan=1) in the wpa_supplicant configuration file and the station tries to connect to two or more access points, the station will not be able to connect to either AP if it does not finish associating with one AP and tries to connect to another.

Has any one come across this issue or has any suggestions on what could be happening?

The logs for both the AP and the stations are below. Thanks in advance for your help!

Regards,

Phillip

AP Log:

May 21 20:34:39 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 WPA: EAPOL-Key timeout May 21 20:35:07 RuckusAP daemon.notice meshd[518]: scan_get, bssid:38:ff:36:b2:25:37, radioType=0x1, numStream=2, vht_flags=0 May 21 20:35:07 RuckusAP daemon.notice meshd[518]: scan_get, Meshie, bssid:38:ff:36:b2:25:37, radioType=0x15, numStream=2, vht_flags=0 May 21 20:35:07 RuckusAP daemon.notice meshd[518]: neighbor_update_ieState: n->reason=-, n->state=U, n->radioType=0x15, me.radioType=5 May 21 20:35:07 RuckusAP daemon.notice meshd[518]: uplink(wired=0)=38:ff:36:b2:25:37(49.0) best_wired=null(0.0) proposed=null( ,0.0,0.0) May 21 20:35:08 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 IEEE 802.1X: EAP timeout May 21 20:35:08 RuckusAP daemon.info hostapd: wlan34: STA 28:30:ac:00:0a:c9 IEEE 802.1X: EAP State Request: supplicant response eapTimeout May 21 20:35:08 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 IEEE 802.1X: aborting authentication May 21 20:35:13 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 DRIVER: NODE-AUTH May 21 20:35:13 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 IEEE 802.11: authentication OK (open system) May 21 20:35:13 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 WPA: event 0 notification May 21 20:35:13 RuckusAP daemon.info hostapd: wlan34: STA 28:30:ac:00:0a:c9 IEEE 802.11: add station:28:30:ac:00:0a:c9 to rudb May 21 20:35:13 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 IEEE 802.11: ***DEBUG*** Send out memcache get/set, type = 2, state = 0, dot11_state = 1, IP = 0, wispr_start_time=8, IPv6 = , msg-len=2704 May 21 20:35:13 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 WPA: ***DEBUG*** fired external DOT11 query May 21 20:35:13 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 DRIVER: REGISTERED May 21 20:35:13 RuckusAP daemon.info hostapd: wlan34: STA 28:30:ac:00:0a:c9 IEEE 802.11: associated May 21 20:35:13 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 WPA: Number of PMKID from station: 1 May 21 20:35:13 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 WPA: PMKID found from PMKSA cache May 21 20:35:13 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 WPA: event 1 notification May 21 20:35:13 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 IEEE 802.11: Receive assoc before query response May 21 20:35:13 RuckusAP daemon.info hostapd: wlan34: STA 28:30:ac:00:0a:c9 WPA: external DOT11 query timeout May 21 20:35:13 RuckusAP daemon.info hostapd: wlan34: STA 28:30:ac:00:0a:c9 IEEE 802.1X: PMK from PMKSA cache - skip IEEE 802.1X/EAP May 21 20:35:13 RuckusAP daemon.debug hostapd: IEEE 802.11: rks_clear_sta_rudb_state_acl wlan34 clear rudb state and acl for station ok:28:30:ac:00:0a:c9 May 21 20:35:13 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 IEEE 802.11: hostapd_cancel_sta_oauth_timer to cancel oauth timer May 21 20:35:13 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 IEEE 802.1X: set utp acl, filter id is 0 May 21 20:35:13 RuckusAP daemon.debug hostapd: IEEE 802.11: rks_set_sta_utp_acl wlan34 set utp acl(filter_id:0, conf->sta_utp_acl_list_id:1, acl id:0) for station ok:28:30:ac:00:0a:c9 May 21 20:35:13 RuckusAP daemon.debug hostapd: IEEE 802.11: rks_set_state wlan34 set rudb state(1) for station ok:28:30:ac:00:0a:c9 May 21 20:35:13 RuckusAP daemon.debug hostapd: IEEE 802.11: rks_set_state wlan34 set acl(lid:0) for station ok:28:30:ac:00:0a:c9 May 21 20:35:13 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 WPA: event 4 notification May 21 20:35:13 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 WPA: BEFORE FROM PMKSA vlan_id:528 May 21 20:35:13 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 Device Policy: Update attribute [VLAN ID] with value=528 from source [AAA] May 21 20:35:13 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 WPA: INITPMK FROM PMKSA dvlan:0, vp:0, vlan_id:528, default:528, access:528 May 21 20:35:13 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 WPA: sending 1/4 msg of 4-Way Handshake May 21 20:35:13 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 WPA: no existing external DOT11 query May 21 20:35:14 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 WPA: EAPOL-Key timeout May 21 20:35:14 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 WPA: sending 1/4 msg of 4-Way Handshake May 21 20:35:15 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 WPA: EAPOL-Key timeout May 21 20:35:15 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 WPA: sending 1/4 msg of 4-Way Handshake May 21 20:35:15 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 IEEE 802.1X: received EAPOL-Start from STA May 21 20:35:15 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 WPA: cached PMKSA available - ignore it since STA sent EAPOL-Start May 21 20:35:15 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 WPA: event 5 notification May 21 20:35:15 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 IEEE 802.1X: aborting authentication May 21 20:35:15 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 IEEE 802.1X: unauthorizing port May 21 20:35:16 RuckusAP daemon.debug hostapd: wlan34: STA 28:30:ac:00:0a:c9 WPA: EAPOL-Key timeout

Station Logs:

Thu Apr 26 22:08:36 2018 daemon.debug wpa_supplicant[2862]: wlan0: State: SCANNING -> AUTHENTICATING Thu Apr 26 22:08:36 2018 daemon.debug wpa_supplicant[2862]: EAPOL: External notification - EAP success=0 Thu Apr 26 22:08:36 2018 daemon.debug wpa_supplicant[2862]: EAPOL: External notification - EAP fail=0 Thu Apr 26 22:08:36 2018 daemon.debug wpa_supplicant[2862]: EAPOL: External notification - portControl=Auto Thu Apr 26 22:08:36 2018 daemon.debug wpa_supplicant[2862]: nl80211: Authenticate (ifindex=16) Thu Apr 26 22:08:36 2018 daemon.debug wpa_supplicant[2862]:   * bssid=38:ff:36:9d:0c:1c
Thu Apr 26 22:08:36 2018 daemon.debug wpa_supplicant[2862]:   * freq=5785
Thu Apr 26 22:08:36 2018 daemon.debug wpa_supplicant[2862]:   * IEs - hexdump(len=0): [NULL]
Thu Apr 26 22:08:36 2018 daemon.debug wpa_supplicant[2862]:   * Auth Type 0
Thu Apr 26 22:08:36 2018 kern.info kernel: [  392.710000] wlan0: authenticate with 38:ff:36:9d:0c:1c Thu Apr 26 22:08:36 2018 daemon.debug wpa_supplicant[2862]: nl80211: Authentication request send successfully Thu Apr 26 22:08:36 2018 daemon.debug wpa_supplicant[2862]: nl80211: Drv Event 19 (NL80211_CMD_NEW_STATION) received for wlan0 Thu Apr 26 22:08:36 2018 daemon.debug wpa_supplicant[2862]: nl80211: New station 38:ff:36:9d:0c:1c Thu Apr 26 22:08:37 2018 kern.info kernel: [  392.720000] wlan0: send auth to 38:ff:36:9d:0c:1c (try 1/3) Thu Apr 26 22:08:37 2018 kern.info kernel: [  392.720000] wlan0: authenticated Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: nl80211: Drv Event 37 (NL80211_CMD_AUTHENTICATE) received for wlan0 Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: nl80211: Authenticate event Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: wlan0: Event AUTH (11) received Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: wlan0: SME: Authentication response: peer=38:ff:36:9d:0c:1c auth_type=0 auth_transaction=2 status_code=0 Thu Apr 26 22:08:37 2018 daemon.notice wpa_supplicant[2862]: wlan0: Trying to associate with 38:ff:36:9d:0c:1c (SSID='QA3_S_SSID' freq=5785 MHz) Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: wlan0: State: AUTHENTICATING -> ASSOCIATING Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: nl80211: Set wlan0 operstate 0->0 (DORMANT) Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: netlink: Operstate: ifindex=16 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT) Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: WPA: set own WPA/RSN IE - hexdump(len=40): 30 26 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 01 00 00 01 00 da 12 5d b7 9c b7 1a 07 90 6d 38 a4 c6 66 14 ad Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: nl80211: Associate (ifindex=16) Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]:   * bssid=38:ff:36:9d:0c:1c Thu Apr 26 22:08:37 2018 kern.info kernel: [  392.780000] wlan0: associate with 38:ff:36:9d:0c:1c (try 1/3) Thu Apr 26 22:08:37 2018 kern.info kernel: [  392.780000] wlan0: RX AssocResp from 38:ff:36:9d:0c:1c (capab=0x411 status=0 aid=1) Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: RTM_NEWLINK: ifi_index=16 ifname=wlan0 master=24 operstate=83886080 ifi_family=7 ifi_flags=0x11003 ([UP][LOWER_UP]) Thu Apr 26 22:08:37 2018 daemon.notice netifd: Network device 'wlan0' link is up Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: nl80211: Add ifindex 24 for bridge br-wan Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: nl80211: Add own interface ifindex 24 (ifidx_reason 16) Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: nl80211: ifindex 24 already in the list Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: RTM_NEWLINK: ifi_index=16 ifname=wlan0 operstate=83886080 linkmode=16777216 master=24 ifi_family=0 ifi_flags=0x11003 ([UP][LOWER_UP])
Thu Apr 26 22:08:37 2018 kern.info kernel: [  392.830000] wlan0: associated
Thu Apr 26 22:08:37 2018 kern.debug kernel: [  392.830000] wlan0: Limiting TX power to 36 (36 - 0) dBm as advertised by 38:ff:36:9d:0c:1c Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: RTM_NEWLINK: ifi_index=16 ifname=wlan0 wext ifi_family=0 ifi_flags=0x11003 ([UP][LOWER_UP]) Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: RTM_NEWLINK: ifi_index=16 ifname=wlan0 wext ifi_family=0 ifi_flags=0x11003 ([UP][LOWER_UP]) Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: RTM_NEWLINK: ifi_index=19 ifname=wlan0.199 operstate=83886080 linkmode=0 ifi_family=0 ifi_flags=0x31003 ([UP][LOWER_UP][DORMANT]) Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: RTM_NEWLINK: ifi_index=21 ifname=wlan0.520 master=12 operstate=83886080 ifi_family=7 ifi_flags=0x31003 ([UP][LOWER_UP][DORMANT]) Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: RTM_NEWLINK: ifi_index=21 ifname=wlan0.520 operstate=83886080 linkmode=0 master=12 ifi_family=0 ifi_flags=0x31003 ([UP][LOWER_UP][DORMANT]) Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: RTM_NEWLINK: ifi_index=20 ifname=wlan0.521 master=7 operstate=83886080 ifi_family=7 ifi_flags=0x31003 ([UP][LOWER_UP][DORMANT]) Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: RTM_NEWLINK: ifi_index=20 ifname=wlan0.521 operstate=83886080 linkmode=0 master=7 ifi_family=0 ifi_flags=0x31003 ([UP][LOWER_UP][DORMANT]) Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: nl80211: Drv Event 38 (NL80211_CMD_ASSOCIATE) received for wlan0 Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: nl80211: Associate event Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: wlan0: Event ASSOC (0) received Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: wlan0: Association info event Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: resp_ies - hexdump(len=148): 01 08 8c 12 98 24 b0 48 60 6c dd 18 00 50 f2 02 01 01 86 00 03 a4 00 00 27 a4 00 00 42 43 5e 00 62 32 2f 00 2d 1a ad 01 1b ff ff 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 04 06 46 e7 0d 00 3d 16 9d 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 30 26 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 01 00 00 01 00 da 12 5d b7 9c b7 1a 07 90 6d 38 a4 c6 66 14 ad dd 08 00 13 92 01 00 01 05 00 7f 08 00Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: wlan0: freq=5785 MHz Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: EAPOL: enable timer tick Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: EAPOL: SUPP_BE entering state IDLE Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: EAP: EAP entering state INITIALIZE Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: EAP: EAP entering state IDLE Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: wlan0: Setting authentication timeout: 10 sec 0 usec Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: wlan0: Cancelling scan request Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: WMM AC: AC mandatory: AC_BE=0 AC_BK=0 AC_VI=0 AC_VO=0 Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: WMM AC: U-APSD queues=0x0 Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: WMM AC: Valid WMM association, WMM AC is enabled Thu Apr 26 22:08:37 2018 daemon.notice wpa_supplicant[2862]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: nl80211: Drv Event 46 (NL80211_CMD_CONNECT) received for wlan0 Thu Apr 26 22:08:37 2018 daemon.debug wpa_supplicant[2862]: nl80211: Ignore connect event (cmd=46) when using userspace SME Thu Apr 26 22:08:39 2018 daemon.debug wpa_supplicant[2862]: EAPOL: startWhen --> 0 Thu Apr 26 22:08:39 2018 daemon.debug wpa_supplicant[2862]: EAPOL: SUPP_PAE entering state CONNECTING
Thu Apr 26 22:08:39 2018 daemon.debug wpa_supplicant[2862]: EAPOL: txStart
Thu Apr 26 22:08:39 2018 daemon.debug wpa_supplicant[2862]: RSN: Timeout on waiting for the AP to initiate 4-way handshake for PMKSA caching or EAP authentication - try to force it to start EAP authentication Thu Apr 26 22:08:39 2018 daemon.debug wpa_supplicant[2862]: TX EAPOL: dst=38:ff:36:9d:0c:1c Thu Apr 26 22:08:47 2018 daemon.notice wpa_supplicant[2862]: wlan0: Authentication with 38:ff:36:9d:0c:1c timed out. Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: Added BSSID 38:ff:36:9d:0c:1c into blacklist Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: WPA: Clear old PMK and PTK Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: Request to deauthenticate - bssid=38:ff:36:9d:0c:1c pending_bssid=00:00:00:00:00:00 reason=3 state=ASSOCIATED Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wpa_driver_nl80211_deauthenticate(addr=38:ff:36:9d:0c:1c reason_code=3) Thu Apr 26 22:08:47 2018 kern.info kernel: [  402.940000] wlan0: deauthenticating from 38:ff:36:9d:0c:1c by local choice (Reason: 3=DEAUTH_LEAVING) Thu Apr 26 22:08:47 2018 daemon.notice netifd: Network device 'wlan0' link is down Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: Event DEAUTH (12) received Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: Deauthentication notification Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0:  * reason 3 (locally generated) Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: Deauthentication frame IE(s) - hexdump(len=0): [NULL] Thu Apr 26 22:08:47 2018 daemon.notice wpa_supplicant[2862]: wlan0: CTRL-EVENT-DISCONNECTED bssid=38:ff:36:9d:0c:1c reason=3 locally_generated=1 Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: Auto connect enabled: try to reconnect (wps=0/0 wpa_state=6) Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: Setting scan request: 0.100000 sec Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: Radio work 'sme-connect'@0x4b95e8 done in 10.350717 seconds Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: radio_work_free('sme-connect'@0x4b95e8: num_active_works --> 0 Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: BSSID 38:ff:36:9d:0c:1c blacklist count incremented to 2 Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: Continuous association failures - consider temporary network disabling Thu Apr 26 22:08:47 2018 daemon.notice wpa_supplicant[2862]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="QA3_S_SSID" auth_failures=3 duration=46 reason=CONN_FAILED Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: Blacklist count 8 --> request scan in 10000 ms Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: Ignore new scan request for 10.000000 sec since an earlier request is scheduled to trigger sooner Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: WPA: Clear old PMK and PTK Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: Disconnect event - remove keys Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: State: ASSOCIATED -> DISCONNECTED Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: nl80211: Set wlan0 operstate 0->0 (DORMANT) Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: netlink: Operstate: ifindex=16 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT) Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: WMM AC: WMM AC is disabled Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: EAPOL: External notification - portEnabled=0 Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: EAPOL: SUPP_PAE entering state DISCONNECTED Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: EAPOL: Supplicant port status: Unauthorized Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: nl80211: Skip set_supp_port(unauthorized) while not associated Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: EAPOL: SUPP_BE entering state INITIALIZE Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: EAP: EAP entering state DISABLED Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: EAPOL: External notification - portValid=0 Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: State: DISCONNECTED -> DISCONNECTED Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: nl80211: Set wlan0 operstate 0->0 (DORMANT) Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: netlink: Operstate: ifindex=16 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT) Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: EAPOL: External notification - portEnabled=0 Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: EAPOL: External notification - portValid=0 Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: Ignore new scan request for 1.000000 sec since an earlier request is scheduled to trigger sooner Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: RTM_NEWLINK: ifi_index=16 ifname=wlan0 master=24 operstate=33554432 ifi_family=7 ifi_flags=0x1003 ([UP]) Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: nl80211: Add ifindex 24 for bridge br-wan Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: nl80211: Add own interface ifindex 24 (ifidx_reason 16) Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: nl80211: ifindex 24 already in the list Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: RTM_NEWLINK: ifi_index=16 ifname=wlan0 operstate=33554432 linkmode=16777216 master=24 ifi_family=0 ifi_flags=0x1003 ([UP]) Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: RTM_NEWLINK: ifi_index=16 ifname=wlan0 wext ifi_family=0 ifi_flags=0x1003 ([UP]) Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: RTM_NEWLINK: ifi_index=19 ifname=wlan0.199 operstate=50331648 linkmode=0 ifi_family=0 ifi_flags=0x1003 ([UP]) Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: RTM_NEWLINK: ifi_index=21 ifname=wlan0.520 master=12 operstate=50331648 ifi_family=7 ifi_flags=0x1003 ([UP]) Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: RTM_NEWLINK: ifi_index=21 ifname=wlan0.520 operstate=50331648 linkmode=0 master=12 ifi_family=0 ifi_flags=0x1003 ([UP]) Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: RTM_NEWLINK: ifi_index=20 ifname=wlan0.521 master=7 operstate=50331648 ifi_family=7 ifi_flags=0x1003 ([UP]) Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: RTM_NEWLINK: ifi_index=20 ifname=wlan0.521 operstate=50331648 linkmode=0 master=7 ifi_family=0 ifi_flags=0x1003 ([UP]) Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: nl80211: Drv Event 20 (NL80211_CMD_DEL_STATION) received for wlan0 Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: nl80211: Delete station 38:ff:36:9d:0c:1c Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: State: DISCONNECTED -> SCANNING Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: Starting AP scan for wildcard SSID Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: Add radio work 'scan'@0x4b8b20 Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: First radio work item in the queue - schedule start immediately Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: Starting radio work 'scan'@0x4b8b20 after 0.000190 second wait Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: nl80211: scan request Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: Scan requested (ret=0) - scan timeout 30 seconds Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: nl80211: Drv Event 33 (NL80211_CMD_TRIGGER_SCAN) received for wlan0 Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: nl80211: Scan trigger Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: Event SCAN_STARTED (47) received Thu Apr 26 22:08:47 2018 daemon.debug wpa_supplicant[2862]: wlan0: Own scan request started a scan in 0.000530 seconds Thu Apr 26 22:08:50 2018 daemon.debug wpa_supplicant[2862]: RTM_NEWLINK: ifi_index=16 ifname=wlan0 wext ifi_family=0 ifi_flags=0x1003 ([UP]) Thu Apr 26 22:08:50 2018 daemon.debug wpa_supplicant[2862]: nl80211: Drv Event 34 (NL80211_CMD_NEW_SCAN_RESULTS) received for wlan0 Thu Apr 26 22:08:50 2018 daemon.debug wpa_supplicant[2862]: wlan0: nl80211: New scan results available Thu Apr 26 22:08:50 2018 daemon.debug wpa_supplicant[2862]: nl80211: Scan probed for SSID 'QA3_S_SSID' Thu Apr 26 22:08:50 2018 daemon.debug wpa_supplicant[2862]: nl80211: Scan probed for SSID '' Thu Apr 26 22:08:50 2018 daemon.debug wpa_supplicant[2862]: nl80211: Scan included frequencies: 5180 5200 5220 5240 5260 5280 5300 5320 5500 5520 5540 5560 5580 5600 5620 5640 5660 5680 5700 5720 5745 5765 5785 5805 5825 5845 5865 Thu Apr 26 22:08:50 2018 daemon.debug wpa_supplicant[2862]: wlan0: Event SCAN_RESULTS (3) received Thu Apr 26 22:08:50 2018 daemon.debug wpa_supplicant[2862]: wlan0: Scan completed in 2.903115 seconds Thu Apr 26 22:08:50 2018 daemon.debug wpa_supplicant[2862]: nl80211: Received scan results (18 BSSes) Thu Apr 26 22:08:50 2018 daemon.debug wpa_supplicant[2862]: wlan0: BSS: Start scan result update 10 Thu Apr 26 22:08:50 2018 daemon.debug wpa_supplicant[2862]: wlan0: BSS: Remove id 18 BSSID 38:ff:36:b2:25:37 SSID '' due to no match in scan Thu Apr 26 22:08:50 2018 daemon.debug wpa_supplicant[2862]: wlan0: BSS: Remove id 35 BSSID 1e:51:a4:1d:ff:8a SSID '' due to no match in scan Thu Apr 26 22:08:50 2018 daemon.debug wpa_supplicant[2862]: BSS: last_scan_res_used=18/32 Thu Apr 26 22:08:50 2018 daemon.debug wpa_supplicant[2862]: wlan0: New scan results available (own=1 ext=0) Thu Apr 26 22:08:50 2018 daemon.debug wpa_supplicant[2862]: wlan0: Radio work 'scan'@0x4b8b20 done in 2.914762 seconds Thu Apr 26 22:08:50 2018 daemon.debug wpa_supplicant[2862]: wlan0: radio_work_free('scan'@0x4b8b20: num_active_works --> 0 Thu Apr 26 22:08:50 2018 daemon.debug wpa_supplicant[2862]: wlan0: Postpone network selection by 43 seconds since all networks are disabled Thu Apr 26 22:09:09 2018 daemon.debug wpa_supplicant[2862]: EAPOL: startWhen --> 0 Thu Apr 26 22:09:09 2018 daemon.debug wpa_supplicant[2862]: EAPOL: disable timer tick



_______________________________________________
Hostap mailing list
Hostap@xxxxxxxxxxxxxxxxxxx
http://lists.infradead.org/mailman/listinfo/hostap




[Index of Archives]     [Linux Wireless]     [Linux Kernel]     [ATH6KL]     [Linux Bluetooth]     [Linux Netdev]     [Kernel Newbies]     [IDE]     [Security]     [Git]     [Netfilter]     [Bugtraq]     [Yosemite News]     [MIPS Linux]     [ARM Linux]     [Linux Security]     [Linux RAID]     [Linux ATA RAID]     [Samba]     [Device Mapper]

  Powered by Linux