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
