Wifi router rejects with association with CTRL-EVENT-ASSOC-REJECT
I have at home some 6 FreeBSD laptops and 4 Ubuntu based mobile phones.
They all connect fine with my AVM FRITZ!Box Wifi AP for years already using WPA-PSK.
Since some months, one of the mobiles is unwilling to associate most of the time.
The problem started somewhere in November. And has always the same picture.
For example yesterday I came home from
work, it connected for around 10 minutes and after this no association
anymore. They get all rejected from the AP with:
1548368341.541719: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:1c:4a:06:17:f5 status_code=1
I managed to start the wpa_supplicant daemon in the phone in debugging
mode (which is not that easy because the /root is mounted read-only) and
have a full debug log attached below. I have no clue about why the AP
rejects the client. The AP (a FRITZ!Box) has MAC filters, but they're disabled.
I even bought a new FRITZ!Box, went away from home with the mobile and
the new router (to avoid maybe radio problems in my home) -- same
problem: CTRL-EVENT-ASSOC-REJECTs. The latter let me think, that the
problem is not the router, but the mobile.
1548368340.906062: wlan0: Starting AP scan for wildcard SSID
1548368340.906260: wlan0: Determining shared radio frequencies (max len 1)
1548368340.906338: wlan0: Shared frequencies (len=0): completed iteration
1548368340.906410: wlan0: Add radio work 'scan'@0xb8a29310
1548368340.906475: wlan0: First radio work item in the queue - schedule start immediately
1548368340.906584: wlan0: Starting radio work 'scan'@0xb8a29310 after 0.000099 second wait
1548368340.906834: wlan0: nl80211: scan request
1548368340.906930: nl80211: Scan SSID - hexdump_ascii(len=0): [NULL]
1548368340.908515: Scan requested (ret=0) - scan timeout 30 seconds
1548368340.908740: nl80211: Event message available
1548368340.908840: nl80211: Drv Event 33 (NL80211_CMD_TRIGGER_SCAN) received for wlan0
1548368340.908912: wlan0: nl80211: Scan trigger
1548368340.908981: wlan0: Event SCAN_STARTED (47) received
1548368340.909053: wlan0: Own scan request started a scan in 0.000342 seconds
1548368340.911945: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1
1548368341.325323: RTM_NEWLINK: ifi_index=10 ifname=wlan0 wext ifi_family=0 ifi_flags=0x1003 ([UP])
1548368341.325791: RTM_NEWLINK: ifi_index=10 ifname=wlan0 wext ifi_family=0 ifi_flags=0x1003 ([UP])
1548368341.325972: nl80211: Event message available
1548368341.326090: nl80211: Drv Event 34 (NL80211_CMD_NEW_SCAN_RESULTS) received for wlan0
1548368341.326164: wlan0: nl80211: New scan results available
1548368341.326226: nl80211: Scan probed for SSID ''
1548368341.326302: nl80211: Scan included frequencies: 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462 2467 2472
1548368341.326366: wlan0: Event SCAN_RESULTS (3) received
1548368341.326436: wlan0: Scan completed in 0.417385 seconds
1548368341.327931: nl80211: Received scan results (6 BSSes)
1548368341.328181: wlan0: BSS: Start scan result update 17
1548368341.328675: BSS: last_scan_res_used=6/32
1548368341.328775: wlan0: New scan results available (own=1 ext=0)
1548368341.338042: WPS: AP[0] d4:21:22:e0:24:8b type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338203: WPS: AP[1] e0:28:6d:26:32:9d type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338272: WPS: AP[2] cc:ce:1e:b1:69:38 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338334: WPS: AP[3] 10:b1:f8:fb:fb:38 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338396: WPS: AP[4] 7c:ff:4d:7c:5c:29 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338529: WPS: AP[5] 24:69:a5:5d:cb:5e type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338762: WPS: AP[6] 30:d3:2d:74:86:41 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338873: wlan0: Radio work 'scan'@0xb8a29310 done in 0.432282 seconds
1548368341.338945: wlan0: Selecting BSS from priority group 0
1548368341.339039: wlan0: 0: 00:1c:4a:06:17:f5 ssid='tarara' wpa_ie_len=24 rsn_ie_len=20 caps=0x411 level=-42
1548368341.339112: wlan0: selected based on RSN IE
1548368341.339194: wlan0: selected BSS 00:1c:4a:06:17:f5 ssid='tarara'
1548368341.339303: wlan0: Considering connect request: reassociate: 0 selected: 00:1c:4a:06:17:f5 bssid: 00:00:00:00:00:00 pending: 00:00:00:00:00:00 wpa_state: SCANNING ssid=0xb8a28738 current_ssid=(nil)
1548368341.339377: wlan0: Request association with 00:1c:4a:06:17:f5
1548368341.339437: wlan0: Re-association to the same ESS
1548368341.339495: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=8): 00 06 74 61 72 61 72 61
1548368341.339565: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=3): 03 01 03
1548368341.339625: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=14): 05 0c 00 03 00 00 00 00 00 00 00 00 00 00
1548368341.339707: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=3): 2a 01 04
1548368341.339766: WPA: RSN IE in EAPOL-Key - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1548368341.339863: WPA: WPA IE in EAPOL-Key - hexdump(len=26): dd 18 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 00 00
1548368341.339981: wlan0: Add radio work 'connect'@0xb8a29310
1548368341.340044: wlan0: First radio work item in the queue - schedule start immediately
1548368341.340112: RSN: Ignored PMKID candidate without preauth flag
1548368341.340224: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1
1548368341.358253: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/7
1548368341.364150: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/19
1548368341.368290: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/20
1548368341.368562: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/1
1548368341.371943: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/2
1548368341.372207: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/6
1548368341.372566: wlan0: Starting radio work 'connect'@0xb8a29310 after 0.032518 second wait
1548368341.372608: wlan0: Trying to associate with SSID 'tarara'
1548368341.372638: wlan0: Cancelling scan request
1548368341.372667: wlan0: WPA: clearing own WPA/RSN IE
1548368341.372697: wlan0: Automatic auth_alg selection: 0x1
1548368341.372725: wlan0: Overriding auth_alg selection: 0x1
1548368341.372752: RSN: PMKSA cache search - network_ctx=0xb8a28738 try_opportunistic=0
1548368341.372778: RSN: Search for BSSID 00:1c:4a:06:17:f5
1548368341.372805: RSN: No PMKSA cache entry found
1548368341.372835: wlan0: RSN: using IEEE 802.11i/D9.0
1548368341.372868: wlan0: WPA: Selected cipher suites: group 8 pairwise 16 key_mgmt 2 proto 2
1548368341.372897: wlan0: WPA: Selected mgmt group cipher 32
1548368341.372923: WPA: set AP WPA IE - hexdump(len=26): dd 18 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 00 00
1548368341.372973: WPA: set AP RSN IE - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1548368341.373022: wlan0: WPA: using GTK TKIP
1548368341.373050: wlan0: WPA: using PTK CCMP
1548368341.373077: wlan0: WPA: using KEY_MGMT WPA-PSK
1548368341.373105: wlan0: WPA: not using MGMT group cipher
1548368341.373131: WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1548368341.373288: wlan0: State: SCANNING -> ASSOCIATING
1548368341.373319: nl80211: Set wlan0 operstate 0->0 (DORMANT)
1548368341.373347: netlink: Operstate: ifindex=10 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
1548368341.373507: wlan0: set_disable_max_amsdu: -1
1548368341.373546: wlan0: set_ampdu_factor: -1
1548368341.373575: wlan0: set_ampdu_density: -1
1548368341.373603: wlan0: set_disable_ht40: 0
1548368341.373630: wlan0: set_disable_sgi: 0
1548368341.373658: wlan0: set_disable_ldpc: 0
1548368341.373688: wlan0: Determining shared radio frequencies (max len 1)
1548368341.373718: wlan0: Shared frequencies (len=0): completed iteration
1548368341.373744: nl80211: Set mode ifindex 10 iftype 2 (STATION)
1548368341.373848: nl80211: Unsubscribe mgmt frames handle 0x3029e831 (mode change)
1548368341.388203: nl80211: Subscribe to mgmt frames with non-AP handle 0xb8a160b8
1548368341.388312: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=040a
1548368341.388510: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=040b
1548368341.388617: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=040c
1548368341.388704: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=040d
1548368341.388789: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=090a
1548368341.388872: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=090b
1548368341.388955: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=090c
1548368341.389037: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=090d
1548368341.389120: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0409506f9a09
1548368341.389204: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=7f506f9a09
1548368341.389285: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0801
1548368341.389367: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=06
1548368341.389450: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0a07
1548368341.389532: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0a11
1548368341.389614: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=1101
1548368341.389695: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=1102
1548368341.389776: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0505
1548368341.389868: nl80211: Key management set PSK
1548368341.389897: nl80211: Connect (ifindex=10)
1548368341.389929: * bssid_hint=00:1c:4a:06:17:f5
1548368341.389959: * freq_hint=2422
1548368341.389985: * SSID - hexdump_ascii(len=6):
74 61 72 61 72 61 tarara
1548368341.390044: * IEs - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1548368341.390090: * WPA Versions 0x2
1548368341.390115: * pairwise=0xfac04
1548368341.390139: * group=0xfac02
1548368341.390163: * akm=0xfac02
1548368341.390188: * htcaps - hexdump(len=26): 63 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
1548368341.390236: * htcaps_mask - hexdump(len=26): 63 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
1548368341.390286: * vhtcaps - hexdump(len=12): 00 00 00 00 00 00 00 00 00 00 00 00
1548368341.390321: * vhtcaps_mask - hexdump(len=12): 00 00 00 00 00 00 00 00 00 00 00 00
1548368341.390357: * Auth Type 0
1548368341.410056: nl80211: Connect request send successfully
1548368341.410178: wlan0: Setting authentication timeout: 10 sec 0 usec
1548368341.410219: EAPOL: External notification - EAP success=0
1548368341.410251: EAPOL: External notification - EAP fail=0
1548368341.410278: EAPOL: External notification - portControl=Auto
1548368341.410450: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1
1548368341.541040: nl80211: Event message available
1548368341.541434: nl80211: Drv Event 46 (NL80211_CMD_CONNECT) received for wlan0
1548368341.541556: nl80211: Connect event (status=1 ignore_next_local_disconnect=0)
1548368341.541637: wlan0: Event ASSOC_REJECT (13) received
1548368341.541719: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:1c:4a:06:17:f5 status_code=1
1548368341.541799: wlan0: Radio work 'connect'@0xb8a29310 done in 0.169226 seconds
1548368341.541860: Added BSSID 00:1c:4a:06:17:f5 into blacklist
1548368341.541925: Continuous association failures - consider temporary network disabling
1548368341.542001: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="tarara" auth_failures=2 duration=20 reason=CONN_FAILED
1548368341.542068: wlan0: Blacklist count 11 --> request scan in 10000 ms
1548368341.542134: wlan0: Setting scan request: 10.000000 sec
1548368341.542205: wlan0: State: ASSOCIATING -> DISCONNECTED
1548368341.542260: nl80211: Set wlan0 operstate 0->0 (DORMANT)
1548368341.542318: netlink: Operstate: ifindex=10 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
1548368341.543474: EAPOL: External notification - portEnabled=0
1548368341.543583: EAPOL: External notification - portValid=0
1548368341.543641: EAPOL: External notification - EAP success=0
1548368341.548586: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1
wireless-networking router wireless-access-point wpa-supplicant
add a comment |
I have at home some 6 FreeBSD laptops and 4 Ubuntu based mobile phones.
They all connect fine with my AVM FRITZ!Box Wifi AP for years already using WPA-PSK.
Since some months, one of the mobiles is unwilling to associate most of the time.
The problem started somewhere in November. And has always the same picture.
For example yesterday I came home from
work, it connected for around 10 minutes and after this no association
anymore. They get all rejected from the AP with:
1548368341.541719: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:1c:4a:06:17:f5 status_code=1
I managed to start the wpa_supplicant daemon in the phone in debugging
mode (which is not that easy because the /root is mounted read-only) and
have a full debug log attached below. I have no clue about why the AP
rejects the client. The AP (a FRITZ!Box) has MAC filters, but they're disabled.
I even bought a new FRITZ!Box, went away from home with the mobile and
the new router (to avoid maybe radio problems in my home) -- same
problem: CTRL-EVENT-ASSOC-REJECTs. The latter let me think, that the
problem is not the router, but the mobile.
1548368340.906062: wlan0: Starting AP scan for wildcard SSID
1548368340.906260: wlan0: Determining shared radio frequencies (max len 1)
1548368340.906338: wlan0: Shared frequencies (len=0): completed iteration
1548368340.906410: wlan0: Add radio work 'scan'@0xb8a29310
1548368340.906475: wlan0: First radio work item in the queue - schedule start immediately
1548368340.906584: wlan0: Starting radio work 'scan'@0xb8a29310 after 0.000099 second wait
1548368340.906834: wlan0: nl80211: scan request
1548368340.906930: nl80211: Scan SSID - hexdump_ascii(len=0): [NULL]
1548368340.908515: Scan requested (ret=0) - scan timeout 30 seconds
1548368340.908740: nl80211: Event message available
1548368340.908840: nl80211: Drv Event 33 (NL80211_CMD_TRIGGER_SCAN) received for wlan0
1548368340.908912: wlan0: nl80211: Scan trigger
1548368340.908981: wlan0: Event SCAN_STARTED (47) received
1548368340.909053: wlan0: Own scan request started a scan in 0.000342 seconds
1548368340.911945: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1
1548368341.325323: RTM_NEWLINK: ifi_index=10 ifname=wlan0 wext ifi_family=0 ifi_flags=0x1003 ([UP])
1548368341.325791: RTM_NEWLINK: ifi_index=10 ifname=wlan0 wext ifi_family=0 ifi_flags=0x1003 ([UP])
1548368341.325972: nl80211: Event message available
1548368341.326090: nl80211: Drv Event 34 (NL80211_CMD_NEW_SCAN_RESULTS) received for wlan0
1548368341.326164: wlan0: nl80211: New scan results available
1548368341.326226: nl80211: Scan probed for SSID ''
1548368341.326302: nl80211: Scan included frequencies: 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462 2467 2472
1548368341.326366: wlan0: Event SCAN_RESULTS (3) received
1548368341.326436: wlan0: Scan completed in 0.417385 seconds
1548368341.327931: nl80211: Received scan results (6 BSSes)
1548368341.328181: wlan0: BSS: Start scan result update 17
1548368341.328675: BSS: last_scan_res_used=6/32
1548368341.328775: wlan0: New scan results available (own=1 ext=0)
1548368341.338042: WPS: AP[0] d4:21:22:e0:24:8b type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338203: WPS: AP[1] e0:28:6d:26:32:9d type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338272: WPS: AP[2] cc:ce:1e:b1:69:38 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338334: WPS: AP[3] 10:b1:f8:fb:fb:38 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338396: WPS: AP[4] 7c:ff:4d:7c:5c:29 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338529: WPS: AP[5] 24:69:a5:5d:cb:5e type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338762: WPS: AP[6] 30:d3:2d:74:86:41 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338873: wlan0: Radio work 'scan'@0xb8a29310 done in 0.432282 seconds
1548368341.338945: wlan0: Selecting BSS from priority group 0
1548368341.339039: wlan0: 0: 00:1c:4a:06:17:f5 ssid='tarara' wpa_ie_len=24 rsn_ie_len=20 caps=0x411 level=-42
1548368341.339112: wlan0: selected based on RSN IE
1548368341.339194: wlan0: selected BSS 00:1c:4a:06:17:f5 ssid='tarara'
1548368341.339303: wlan0: Considering connect request: reassociate: 0 selected: 00:1c:4a:06:17:f5 bssid: 00:00:00:00:00:00 pending: 00:00:00:00:00:00 wpa_state: SCANNING ssid=0xb8a28738 current_ssid=(nil)
1548368341.339377: wlan0: Request association with 00:1c:4a:06:17:f5
1548368341.339437: wlan0: Re-association to the same ESS
1548368341.339495: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=8): 00 06 74 61 72 61 72 61
1548368341.339565: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=3): 03 01 03
1548368341.339625: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=14): 05 0c 00 03 00 00 00 00 00 00 00 00 00 00
1548368341.339707: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=3): 2a 01 04
1548368341.339766: WPA: RSN IE in EAPOL-Key - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1548368341.339863: WPA: WPA IE in EAPOL-Key - hexdump(len=26): dd 18 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 00 00
1548368341.339981: wlan0: Add radio work 'connect'@0xb8a29310
1548368341.340044: wlan0: First radio work item in the queue - schedule start immediately
1548368341.340112: RSN: Ignored PMKID candidate without preauth flag
1548368341.340224: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1
1548368341.358253: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/7
1548368341.364150: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/19
1548368341.368290: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/20
1548368341.368562: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/1
1548368341.371943: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/2
1548368341.372207: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/6
1548368341.372566: wlan0: Starting radio work 'connect'@0xb8a29310 after 0.032518 second wait
1548368341.372608: wlan0: Trying to associate with SSID 'tarara'
1548368341.372638: wlan0: Cancelling scan request
1548368341.372667: wlan0: WPA: clearing own WPA/RSN IE
1548368341.372697: wlan0: Automatic auth_alg selection: 0x1
1548368341.372725: wlan0: Overriding auth_alg selection: 0x1
1548368341.372752: RSN: PMKSA cache search - network_ctx=0xb8a28738 try_opportunistic=0
1548368341.372778: RSN: Search for BSSID 00:1c:4a:06:17:f5
1548368341.372805: RSN: No PMKSA cache entry found
1548368341.372835: wlan0: RSN: using IEEE 802.11i/D9.0
1548368341.372868: wlan0: WPA: Selected cipher suites: group 8 pairwise 16 key_mgmt 2 proto 2
1548368341.372897: wlan0: WPA: Selected mgmt group cipher 32
1548368341.372923: WPA: set AP WPA IE - hexdump(len=26): dd 18 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 00 00
1548368341.372973: WPA: set AP RSN IE - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1548368341.373022: wlan0: WPA: using GTK TKIP
1548368341.373050: wlan0: WPA: using PTK CCMP
1548368341.373077: wlan0: WPA: using KEY_MGMT WPA-PSK
1548368341.373105: wlan0: WPA: not using MGMT group cipher
1548368341.373131: WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1548368341.373288: wlan0: State: SCANNING -> ASSOCIATING
1548368341.373319: nl80211: Set wlan0 operstate 0->0 (DORMANT)
1548368341.373347: netlink: Operstate: ifindex=10 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
1548368341.373507: wlan0: set_disable_max_amsdu: -1
1548368341.373546: wlan0: set_ampdu_factor: -1
1548368341.373575: wlan0: set_ampdu_density: -1
1548368341.373603: wlan0: set_disable_ht40: 0
1548368341.373630: wlan0: set_disable_sgi: 0
1548368341.373658: wlan0: set_disable_ldpc: 0
1548368341.373688: wlan0: Determining shared radio frequencies (max len 1)
1548368341.373718: wlan0: Shared frequencies (len=0): completed iteration
1548368341.373744: nl80211: Set mode ifindex 10 iftype 2 (STATION)
1548368341.373848: nl80211: Unsubscribe mgmt frames handle 0x3029e831 (mode change)
1548368341.388203: nl80211: Subscribe to mgmt frames with non-AP handle 0xb8a160b8
1548368341.388312: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=040a
1548368341.388510: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=040b
1548368341.388617: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=040c
1548368341.388704: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=040d
1548368341.388789: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=090a
1548368341.388872: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=090b
1548368341.388955: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=090c
1548368341.389037: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=090d
1548368341.389120: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0409506f9a09
1548368341.389204: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=7f506f9a09
1548368341.389285: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0801
1548368341.389367: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=06
1548368341.389450: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0a07
1548368341.389532: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0a11
1548368341.389614: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=1101
1548368341.389695: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=1102
1548368341.389776: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0505
1548368341.389868: nl80211: Key management set PSK
1548368341.389897: nl80211: Connect (ifindex=10)
1548368341.389929: * bssid_hint=00:1c:4a:06:17:f5
1548368341.389959: * freq_hint=2422
1548368341.389985: * SSID - hexdump_ascii(len=6):
74 61 72 61 72 61 tarara
1548368341.390044: * IEs - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1548368341.390090: * WPA Versions 0x2
1548368341.390115: * pairwise=0xfac04
1548368341.390139: * group=0xfac02
1548368341.390163: * akm=0xfac02
1548368341.390188: * htcaps - hexdump(len=26): 63 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
1548368341.390236: * htcaps_mask - hexdump(len=26): 63 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
1548368341.390286: * vhtcaps - hexdump(len=12): 00 00 00 00 00 00 00 00 00 00 00 00
1548368341.390321: * vhtcaps_mask - hexdump(len=12): 00 00 00 00 00 00 00 00 00 00 00 00
1548368341.390357: * Auth Type 0
1548368341.410056: nl80211: Connect request send successfully
1548368341.410178: wlan0: Setting authentication timeout: 10 sec 0 usec
1548368341.410219: EAPOL: External notification - EAP success=0
1548368341.410251: EAPOL: External notification - EAP fail=0
1548368341.410278: EAPOL: External notification - portControl=Auto
1548368341.410450: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1
1548368341.541040: nl80211: Event message available
1548368341.541434: nl80211: Drv Event 46 (NL80211_CMD_CONNECT) received for wlan0
1548368341.541556: nl80211: Connect event (status=1 ignore_next_local_disconnect=0)
1548368341.541637: wlan0: Event ASSOC_REJECT (13) received
1548368341.541719: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:1c:4a:06:17:f5 status_code=1
1548368341.541799: wlan0: Radio work 'connect'@0xb8a29310 done in 0.169226 seconds
1548368341.541860: Added BSSID 00:1c:4a:06:17:f5 into blacklist
1548368341.541925: Continuous association failures - consider temporary network disabling
1548368341.542001: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="tarara" auth_failures=2 duration=20 reason=CONN_FAILED
1548368341.542068: wlan0: Blacklist count 11 --> request scan in 10000 ms
1548368341.542134: wlan0: Setting scan request: 10.000000 sec
1548368341.542205: wlan0: State: ASSOCIATING -> DISCONNECTED
1548368341.542260: nl80211: Set wlan0 operstate 0->0 (DORMANT)
1548368341.542318: netlink: Operstate: ifindex=10 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
1548368341.543474: EAPOL: External notification - portEnabled=0
1548368341.543583: EAPOL: External notification - portValid=0
1548368341.543641: EAPOL: External notification - EAP success=0
1548368341.548586: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1
wireless-networking router wireless-access-point wpa-supplicant
add a comment |
I have at home some 6 FreeBSD laptops and 4 Ubuntu based mobile phones.
They all connect fine with my AVM FRITZ!Box Wifi AP for years already using WPA-PSK.
Since some months, one of the mobiles is unwilling to associate most of the time.
The problem started somewhere in November. And has always the same picture.
For example yesterday I came home from
work, it connected for around 10 minutes and after this no association
anymore. They get all rejected from the AP with:
1548368341.541719: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:1c:4a:06:17:f5 status_code=1
I managed to start the wpa_supplicant daemon in the phone in debugging
mode (which is not that easy because the /root is mounted read-only) and
have a full debug log attached below. I have no clue about why the AP
rejects the client. The AP (a FRITZ!Box) has MAC filters, but they're disabled.
I even bought a new FRITZ!Box, went away from home with the mobile and
the new router (to avoid maybe radio problems in my home) -- same
problem: CTRL-EVENT-ASSOC-REJECTs. The latter let me think, that the
problem is not the router, but the mobile.
1548368340.906062: wlan0: Starting AP scan for wildcard SSID
1548368340.906260: wlan0: Determining shared radio frequencies (max len 1)
1548368340.906338: wlan0: Shared frequencies (len=0): completed iteration
1548368340.906410: wlan0: Add radio work 'scan'@0xb8a29310
1548368340.906475: wlan0: First radio work item in the queue - schedule start immediately
1548368340.906584: wlan0: Starting radio work 'scan'@0xb8a29310 after 0.000099 second wait
1548368340.906834: wlan0: nl80211: scan request
1548368340.906930: nl80211: Scan SSID - hexdump_ascii(len=0): [NULL]
1548368340.908515: Scan requested (ret=0) - scan timeout 30 seconds
1548368340.908740: nl80211: Event message available
1548368340.908840: nl80211: Drv Event 33 (NL80211_CMD_TRIGGER_SCAN) received for wlan0
1548368340.908912: wlan0: nl80211: Scan trigger
1548368340.908981: wlan0: Event SCAN_STARTED (47) received
1548368340.909053: wlan0: Own scan request started a scan in 0.000342 seconds
1548368340.911945: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1
1548368341.325323: RTM_NEWLINK: ifi_index=10 ifname=wlan0 wext ifi_family=0 ifi_flags=0x1003 ([UP])
1548368341.325791: RTM_NEWLINK: ifi_index=10 ifname=wlan0 wext ifi_family=0 ifi_flags=0x1003 ([UP])
1548368341.325972: nl80211: Event message available
1548368341.326090: nl80211: Drv Event 34 (NL80211_CMD_NEW_SCAN_RESULTS) received for wlan0
1548368341.326164: wlan0: nl80211: New scan results available
1548368341.326226: nl80211: Scan probed for SSID ''
1548368341.326302: nl80211: Scan included frequencies: 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462 2467 2472
1548368341.326366: wlan0: Event SCAN_RESULTS (3) received
1548368341.326436: wlan0: Scan completed in 0.417385 seconds
1548368341.327931: nl80211: Received scan results (6 BSSes)
1548368341.328181: wlan0: BSS: Start scan result update 17
1548368341.328675: BSS: last_scan_res_used=6/32
1548368341.328775: wlan0: New scan results available (own=1 ext=0)
1548368341.338042: WPS: AP[0] d4:21:22:e0:24:8b type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338203: WPS: AP[1] e0:28:6d:26:32:9d type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338272: WPS: AP[2] cc:ce:1e:b1:69:38 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338334: WPS: AP[3] 10:b1:f8:fb:fb:38 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338396: WPS: AP[4] 7c:ff:4d:7c:5c:29 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338529: WPS: AP[5] 24:69:a5:5d:cb:5e type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338762: WPS: AP[6] 30:d3:2d:74:86:41 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338873: wlan0: Radio work 'scan'@0xb8a29310 done in 0.432282 seconds
1548368341.338945: wlan0: Selecting BSS from priority group 0
1548368341.339039: wlan0: 0: 00:1c:4a:06:17:f5 ssid='tarara' wpa_ie_len=24 rsn_ie_len=20 caps=0x411 level=-42
1548368341.339112: wlan0: selected based on RSN IE
1548368341.339194: wlan0: selected BSS 00:1c:4a:06:17:f5 ssid='tarara'
1548368341.339303: wlan0: Considering connect request: reassociate: 0 selected: 00:1c:4a:06:17:f5 bssid: 00:00:00:00:00:00 pending: 00:00:00:00:00:00 wpa_state: SCANNING ssid=0xb8a28738 current_ssid=(nil)
1548368341.339377: wlan0: Request association with 00:1c:4a:06:17:f5
1548368341.339437: wlan0: Re-association to the same ESS
1548368341.339495: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=8): 00 06 74 61 72 61 72 61
1548368341.339565: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=3): 03 01 03
1548368341.339625: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=14): 05 0c 00 03 00 00 00 00 00 00 00 00 00 00
1548368341.339707: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=3): 2a 01 04
1548368341.339766: WPA: RSN IE in EAPOL-Key - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1548368341.339863: WPA: WPA IE in EAPOL-Key - hexdump(len=26): dd 18 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 00 00
1548368341.339981: wlan0: Add radio work 'connect'@0xb8a29310
1548368341.340044: wlan0: First radio work item in the queue - schedule start immediately
1548368341.340112: RSN: Ignored PMKID candidate without preauth flag
1548368341.340224: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1
1548368341.358253: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/7
1548368341.364150: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/19
1548368341.368290: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/20
1548368341.368562: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/1
1548368341.371943: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/2
1548368341.372207: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/6
1548368341.372566: wlan0: Starting radio work 'connect'@0xb8a29310 after 0.032518 second wait
1548368341.372608: wlan0: Trying to associate with SSID 'tarara'
1548368341.372638: wlan0: Cancelling scan request
1548368341.372667: wlan0: WPA: clearing own WPA/RSN IE
1548368341.372697: wlan0: Automatic auth_alg selection: 0x1
1548368341.372725: wlan0: Overriding auth_alg selection: 0x1
1548368341.372752: RSN: PMKSA cache search - network_ctx=0xb8a28738 try_opportunistic=0
1548368341.372778: RSN: Search for BSSID 00:1c:4a:06:17:f5
1548368341.372805: RSN: No PMKSA cache entry found
1548368341.372835: wlan0: RSN: using IEEE 802.11i/D9.0
1548368341.372868: wlan0: WPA: Selected cipher suites: group 8 pairwise 16 key_mgmt 2 proto 2
1548368341.372897: wlan0: WPA: Selected mgmt group cipher 32
1548368341.372923: WPA: set AP WPA IE - hexdump(len=26): dd 18 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 00 00
1548368341.372973: WPA: set AP RSN IE - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1548368341.373022: wlan0: WPA: using GTK TKIP
1548368341.373050: wlan0: WPA: using PTK CCMP
1548368341.373077: wlan0: WPA: using KEY_MGMT WPA-PSK
1548368341.373105: wlan0: WPA: not using MGMT group cipher
1548368341.373131: WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1548368341.373288: wlan0: State: SCANNING -> ASSOCIATING
1548368341.373319: nl80211: Set wlan0 operstate 0->0 (DORMANT)
1548368341.373347: netlink: Operstate: ifindex=10 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
1548368341.373507: wlan0: set_disable_max_amsdu: -1
1548368341.373546: wlan0: set_ampdu_factor: -1
1548368341.373575: wlan0: set_ampdu_density: -1
1548368341.373603: wlan0: set_disable_ht40: 0
1548368341.373630: wlan0: set_disable_sgi: 0
1548368341.373658: wlan0: set_disable_ldpc: 0
1548368341.373688: wlan0: Determining shared radio frequencies (max len 1)
1548368341.373718: wlan0: Shared frequencies (len=0): completed iteration
1548368341.373744: nl80211: Set mode ifindex 10 iftype 2 (STATION)
1548368341.373848: nl80211: Unsubscribe mgmt frames handle 0x3029e831 (mode change)
1548368341.388203: nl80211: Subscribe to mgmt frames with non-AP handle 0xb8a160b8
1548368341.388312: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=040a
1548368341.388510: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=040b
1548368341.388617: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=040c
1548368341.388704: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=040d
1548368341.388789: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=090a
1548368341.388872: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=090b
1548368341.388955: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=090c
1548368341.389037: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=090d
1548368341.389120: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0409506f9a09
1548368341.389204: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=7f506f9a09
1548368341.389285: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0801
1548368341.389367: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=06
1548368341.389450: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0a07
1548368341.389532: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0a11
1548368341.389614: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=1101
1548368341.389695: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=1102
1548368341.389776: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0505
1548368341.389868: nl80211: Key management set PSK
1548368341.389897: nl80211: Connect (ifindex=10)
1548368341.389929: * bssid_hint=00:1c:4a:06:17:f5
1548368341.389959: * freq_hint=2422
1548368341.389985: * SSID - hexdump_ascii(len=6):
74 61 72 61 72 61 tarara
1548368341.390044: * IEs - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1548368341.390090: * WPA Versions 0x2
1548368341.390115: * pairwise=0xfac04
1548368341.390139: * group=0xfac02
1548368341.390163: * akm=0xfac02
1548368341.390188: * htcaps - hexdump(len=26): 63 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
1548368341.390236: * htcaps_mask - hexdump(len=26): 63 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
1548368341.390286: * vhtcaps - hexdump(len=12): 00 00 00 00 00 00 00 00 00 00 00 00
1548368341.390321: * vhtcaps_mask - hexdump(len=12): 00 00 00 00 00 00 00 00 00 00 00 00
1548368341.390357: * Auth Type 0
1548368341.410056: nl80211: Connect request send successfully
1548368341.410178: wlan0: Setting authentication timeout: 10 sec 0 usec
1548368341.410219: EAPOL: External notification - EAP success=0
1548368341.410251: EAPOL: External notification - EAP fail=0
1548368341.410278: EAPOL: External notification - portControl=Auto
1548368341.410450: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1
1548368341.541040: nl80211: Event message available
1548368341.541434: nl80211: Drv Event 46 (NL80211_CMD_CONNECT) received for wlan0
1548368341.541556: nl80211: Connect event (status=1 ignore_next_local_disconnect=0)
1548368341.541637: wlan0: Event ASSOC_REJECT (13) received
1548368341.541719: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:1c:4a:06:17:f5 status_code=1
1548368341.541799: wlan0: Radio work 'connect'@0xb8a29310 done in 0.169226 seconds
1548368341.541860: Added BSSID 00:1c:4a:06:17:f5 into blacklist
1548368341.541925: Continuous association failures - consider temporary network disabling
1548368341.542001: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="tarara" auth_failures=2 duration=20 reason=CONN_FAILED
1548368341.542068: wlan0: Blacklist count 11 --> request scan in 10000 ms
1548368341.542134: wlan0: Setting scan request: 10.000000 sec
1548368341.542205: wlan0: State: ASSOCIATING -> DISCONNECTED
1548368341.542260: nl80211: Set wlan0 operstate 0->0 (DORMANT)
1548368341.542318: netlink: Operstate: ifindex=10 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
1548368341.543474: EAPOL: External notification - portEnabled=0
1548368341.543583: EAPOL: External notification - portValid=0
1548368341.543641: EAPOL: External notification - EAP success=0
1548368341.548586: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1
wireless-networking router wireless-access-point wpa-supplicant
I have at home some 6 FreeBSD laptops and 4 Ubuntu based mobile phones.
They all connect fine with my AVM FRITZ!Box Wifi AP for years already using WPA-PSK.
Since some months, one of the mobiles is unwilling to associate most of the time.
The problem started somewhere in November. And has always the same picture.
For example yesterday I came home from
work, it connected for around 10 minutes and after this no association
anymore. They get all rejected from the AP with:
1548368341.541719: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:1c:4a:06:17:f5 status_code=1
I managed to start the wpa_supplicant daemon in the phone in debugging
mode (which is not that easy because the /root is mounted read-only) and
have a full debug log attached below. I have no clue about why the AP
rejects the client. The AP (a FRITZ!Box) has MAC filters, but they're disabled.
I even bought a new FRITZ!Box, went away from home with the mobile and
the new router (to avoid maybe radio problems in my home) -- same
problem: CTRL-EVENT-ASSOC-REJECTs. The latter let me think, that the
problem is not the router, but the mobile.
1548368340.906062: wlan0: Starting AP scan for wildcard SSID
1548368340.906260: wlan0: Determining shared radio frequencies (max len 1)
1548368340.906338: wlan0: Shared frequencies (len=0): completed iteration
1548368340.906410: wlan0: Add radio work 'scan'@0xb8a29310
1548368340.906475: wlan0: First radio work item in the queue - schedule start immediately
1548368340.906584: wlan0: Starting radio work 'scan'@0xb8a29310 after 0.000099 second wait
1548368340.906834: wlan0: nl80211: scan request
1548368340.906930: nl80211: Scan SSID - hexdump_ascii(len=0): [NULL]
1548368340.908515: Scan requested (ret=0) - scan timeout 30 seconds
1548368340.908740: nl80211: Event message available
1548368340.908840: nl80211: Drv Event 33 (NL80211_CMD_TRIGGER_SCAN) received for wlan0
1548368340.908912: wlan0: nl80211: Scan trigger
1548368340.908981: wlan0: Event SCAN_STARTED (47) received
1548368340.909053: wlan0: Own scan request started a scan in 0.000342 seconds
1548368340.911945: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1
1548368341.325323: RTM_NEWLINK: ifi_index=10 ifname=wlan0 wext ifi_family=0 ifi_flags=0x1003 ([UP])
1548368341.325791: RTM_NEWLINK: ifi_index=10 ifname=wlan0 wext ifi_family=0 ifi_flags=0x1003 ([UP])
1548368341.325972: nl80211: Event message available
1548368341.326090: nl80211: Drv Event 34 (NL80211_CMD_NEW_SCAN_RESULTS) received for wlan0
1548368341.326164: wlan0: nl80211: New scan results available
1548368341.326226: nl80211: Scan probed for SSID ''
1548368341.326302: nl80211: Scan included frequencies: 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462 2467 2472
1548368341.326366: wlan0: Event SCAN_RESULTS (3) received
1548368341.326436: wlan0: Scan completed in 0.417385 seconds
1548368341.327931: nl80211: Received scan results (6 BSSes)
1548368341.328181: wlan0: BSS: Start scan result update 17
1548368341.328675: BSS: last_scan_res_used=6/32
1548368341.328775: wlan0: New scan results available (own=1 ext=0)
1548368341.338042: WPS: AP[0] d4:21:22:e0:24:8b type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338203: WPS: AP[1] e0:28:6d:26:32:9d type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338272: WPS: AP[2] cc:ce:1e:b1:69:38 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338334: WPS: AP[3] 10:b1:f8:fb:fb:38 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338396: WPS: AP[4] 7c:ff:4d:7c:5c:29 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338529: WPS: AP[5] 24:69:a5:5d:cb:5e type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338762: WPS: AP[6] 30:d3:2d:74:86:41 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
1548368341.338873: wlan0: Radio work 'scan'@0xb8a29310 done in 0.432282 seconds
1548368341.338945: wlan0: Selecting BSS from priority group 0
1548368341.339039: wlan0: 0: 00:1c:4a:06:17:f5 ssid='tarara' wpa_ie_len=24 rsn_ie_len=20 caps=0x411 level=-42
1548368341.339112: wlan0: selected based on RSN IE
1548368341.339194: wlan0: selected BSS 00:1c:4a:06:17:f5 ssid='tarara'
1548368341.339303: wlan0: Considering connect request: reassociate: 0 selected: 00:1c:4a:06:17:f5 bssid: 00:00:00:00:00:00 pending: 00:00:00:00:00:00 wpa_state: SCANNING ssid=0xb8a28738 current_ssid=(nil)
1548368341.339377: wlan0: Request association with 00:1c:4a:06:17:f5
1548368341.339437: wlan0: Re-association to the same ESS
1548368341.339495: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=8): 00 06 74 61 72 61 72 61
1548368341.339565: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=3): 03 01 03
1548368341.339625: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=14): 05 0c 00 03 00 00 00 00 00 00 00 00 00 00
1548368341.339707: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=3): 2a 01 04
1548368341.339766: WPA: RSN IE in EAPOL-Key - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1548368341.339863: WPA: WPA IE in EAPOL-Key - hexdump(len=26): dd 18 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 00 00
1548368341.339981: wlan0: Add radio work 'connect'@0xb8a29310
1548368341.340044: wlan0: First radio work item in the queue - schedule start immediately
1548368341.340112: RSN: Ignored PMKID candidate without preauth flag
1548368341.340224: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1
1548368341.358253: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/7
1548368341.364150: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/19
1548368341.368290: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/20
1548368341.368562: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/1
1548368341.371943: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/2
1548368341.372207: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/6
1548368341.372566: wlan0: Starting radio work 'connect'@0xb8a29310 after 0.032518 second wait
1548368341.372608: wlan0: Trying to associate with SSID 'tarara'
1548368341.372638: wlan0: Cancelling scan request
1548368341.372667: wlan0: WPA: clearing own WPA/RSN IE
1548368341.372697: wlan0: Automatic auth_alg selection: 0x1
1548368341.372725: wlan0: Overriding auth_alg selection: 0x1
1548368341.372752: RSN: PMKSA cache search - network_ctx=0xb8a28738 try_opportunistic=0
1548368341.372778: RSN: Search for BSSID 00:1c:4a:06:17:f5
1548368341.372805: RSN: No PMKSA cache entry found
1548368341.372835: wlan0: RSN: using IEEE 802.11i/D9.0
1548368341.372868: wlan0: WPA: Selected cipher suites: group 8 pairwise 16 key_mgmt 2 proto 2
1548368341.372897: wlan0: WPA: Selected mgmt group cipher 32
1548368341.372923: WPA: set AP WPA IE - hexdump(len=26): dd 18 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 00 00
1548368341.372973: WPA: set AP RSN IE - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1548368341.373022: wlan0: WPA: using GTK TKIP
1548368341.373050: wlan0: WPA: using PTK CCMP
1548368341.373077: wlan0: WPA: using KEY_MGMT WPA-PSK
1548368341.373105: wlan0: WPA: not using MGMT group cipher
1548368341.373131: WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1548368341.373288: wlan0: State: SCANNING -> ASSOCIATING
1548368341.373319: nl80211: Set wlan0 operstate 0->0 (DORMANT)
1548368341.373347: netlink: Operstate: ifindex=10 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
1548368341.373507: wlan0: set_disable_max_amsdu: -1
1548368341.373546: wlan0: set_ampdu_factor: -1
1548368341.373575: wlan0: set_ampdu_density: -1
1548368341.373603: wlan0: set_disable_ht40: 0
1548368341.373630: wlan0: set_disable_sgi: 0
1548368341.373658: wlan0: set_disable_ldpc: 0
1548368341.373688: wlan0: Determining shared radio frequencies (max len 1)
1548368341.373718: wlan0: Shared frequencies (len=0): completed iteration
1548368341.373744: nl80211: Set mode ifindex 10 iftype 2 (STATION)
1548368341.373848: nl80211: Unsubscribe mgmt frames handle 0x3029e831 (mode change)
1548368341.388203: nl80211: Subscribe to mgmt frames with non-AP handle 0xb8a160b8
1548368341.388312: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=040a
1548368341.388510: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=040b
1548368341.388617: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=040c
1548368341.388704: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=040d
1548368341.388789: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=090a
1548368341.388872: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=090b
1548368341.388955: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=090c
1548368341.389037: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=090d
1548368341.389120: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0409506f9a09
1548368341.389204: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=7f506f9a09
1548368341.389285: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0801
1548368341.389367: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=06
1548368341.389450: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0a07
1548368341.389532: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0a11
1548368341.389614: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=1101
1548368341.389695: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=1102
1548368341.389776: nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xb8a160b8 match=0505
1548368341.389868: nl80211: Key management set PSK
1548368341.389897: nl80211: Connect (ifindex=10)
1548368341.389929: * bssid_hint=00:1c:4a:06:17:f5
1548368341.389959: * freq_hint=2422
1548368341.389985: * SSID - hexdump_ascii(len=6):
74 61 72 61 72 61 tarara
1548368341.390044: * IEs - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1548368341.390090: * WPA Versions 0x2
1548368341.390115: * pairwise=0xfac04
1548368341.390139: * group=0xfac02
1548368341.390163: * akm=0xfac02
1548368341.390188: * htcaps - hexdump(len=26): 63 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
1548368341.390236: * htcaps_mask - hexdump(len=26): 63 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
1548368341.390286: * vhtcaps - hexdump(len=12): 00 00 00 00 00 00 00 00 00 00 00 00
1548368341.390321: * vhtcaps_mask - hexdump(len=12): 00 00 00 00 00 00 00 00 00 00 00 00
1548368341.390357: * Auth Type 0
1548368341.410056: nl80211: Connect request send successfully
1548368341.410178: wlan0: Setting authentication timeout: 10 sec 0 usec
1548368341.410219: EAPOL: External notification - EAP success=0
1548368341.410251: EAPOL: External notification - EAP fail=0
1548368341.410278: EAPOL: External notification - portControl=Auto
1548368341.410450: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1
1548368341.541040: nl80211: Event message available
1548368341.541434: nl80211: Drv Event 46 (NL80211_CMD_CONNECT) received for wlan0
1548368341.541556: nl80211: Connect event (status=1 ignore_next_local_disconnect=0)
1548368341.541637: wlan0: Event ASSOC_REJECT (13) received
1548368341.541719: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:1c:4a:06:17:f5 status_code=1
1548368341.541799: wlan0: Radio work 'connect'@0xb8a29310 done in 0.169226 seconds
1548368341.541860: Added BSSID 00:1c:4a:06:17:f5 into blacklist
1548368341.541925: Continuous association failures - consider temporary network disabling
1548368341.542001: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="tarara" auth_failures=2 duration=20 reason=CONN_FAILED
1548368341.542068: wlan0: Blacklist count 11 --> request scan in 10000 ms
1548368341.542134: wlan0: Setting scan request: 10.000000 sec
1548368341.542205: wlan0: State: ASSOCIATING -> DISCONNECTED
1548368341.542260: nl80211: Set wlan0 operstate 0->0 (DORMANT)
1548368341.542318: netlink: Operstate: ifindex=10 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
1548368341.543474: EAPOL: External notification - portEnabled=0
1548368341.543583: EAPOL: External notification - portValid=0
1548368341.543641: EAPOL: External notification - EAP success=0
1548368341.548586: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1
wireless-networking router wireless-access-point wpa-supplicant
wireless-networking router wireless-access-point wpa-supplicant
asked Jan 25 at 9:21
guruguru
11
11
add a comment |
add a comment |
0
active
oldest
votes
Your Answer
StackExchange.ready(function() {
var channelOptions = {
tags: "".split(" "),
id: "3"
};
initTagRenderer("".split(" "), "".split(" "), channelOptions);
StackExchange.using("externalEditor", function() {
// Have to fire editor after snippets, if snippets enabled
if (StackExchange.settings.snippets.snippetsEnabled) {
StackExchange.using("snippets", function() {
createEditor();
});
}
else {
createEditor();
}
});
function createEditor() {
StackExchange.prepareEditor({
heartbeatType: 'answer',
autoActivateHeartbeat: false,
convertImagesToLinks: true,
noModals: true,
showLowRepImageUploadWarning: true,
reputationToPostImages: 10,
bindNavPrevention: true,
postfix: "",
imageUploader: {
brandingHtml: "Powered by u003ca class="icon-imgur-white" href="https://imgur.com/"u003eu003c/au003e",
contentPolicyHtml: "User contributions licensed under u003ca href="https://creativecommons.org/licenses/by-sa/3.0/"u003ecc by-sa 3.0 with attribution requiredu003c/au003e u003ca href="https://stackoverflow.com/legal/content-policy"u003e(content policy)u003c/au003e",
allowUrls: true
},
onDemand: true,
discardSelector: ".discard-answer"
,immediatelyShowMarkdownHelp:true
});
}
});
Sign up or log in
StackExchange.ready(function () {
StackExchange.helpers.onClickDraftSave('#login-link');
});
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
StackExchange.ready(
function () {
StackExchange.openid.initPostLogin('.new-post-login', 'https%3a%2f%2fsuperuser.com%2fquestions%2f1398268%2fwifi-router-rejects-with-association-with-ctrl-event-assoc-reject%23new-answer', 'question_page');
}
);
Post as a guest
Required, but never shown
0
active
oldest
votes
0
active
oldest
votes
active
oldest
votes
active
oldest
votes
Thanks for contributing an answer to Super User!
- Please be sure to answer the question. Provide details and share your research!
But avoid …
- Asking for help, clarification, or responding to other answers.
- Making statements based on opinion; back them up with references or personal experience.
To learn more, see our tips on writing great answers.
Sign up or log in
StackExchange.ready(function () {
StackExchange.helpers.onClickDraftSave('#login-link');
});
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
StackExchange.ready(
function () {
StackExchange.openid.initPostLogin('.new-post-login', 'https%3a%2f%2fsuperuser.com%2fquestions%2f1398268%2fwifi-router-rejects-with-association-with-ctrl-event-assoc-reject%23new-answer', 'question_page');
}
);
Post as a guest
Required, but never shown
Sign up or log in
StackExchange.ready(function () {
StackExchange.helpers.onClickDraftSave('#login-link');
});
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
Sign up or log in
StackExchange.ready(function () {
StackExchange.helpers.onClickDraftSave('#login-link');
});
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
Sign up or log in
StackExchange.ready(function () {
StackExchange.helpers.onClickDraftSave('#login-link');
});
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown