У меня дома есть 6 ноутбуков с FreeBSD и 4 мобильных телефона на основе Ubuntu. Все они отлично соединяются с моим AVM FRITZ!Box Wifi AP уже много лет использует WPA-PSK.
Уже несколько месяцев один из мобильных телефонов не хочет общаться большую часть времени. Проблема началась где-то в ноябре. И имеет всегда одну и ту же картину. Например, вчера я пришел домой с работы, он подключился около 10 минут, и после этого больше не было никакой связи. Они получают все отклоненные от AP с:
1548368341.541719: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:1c:4a:06:17:f5 status_code=1
Мне удалось запустить демон wpa_supplicant в телефоне в режиме отладки (что не так просто, потому что /root монтируется только для чтения) и прикрепить полный журнал отладки ниже. Я понятия не имею о том, почему AP отклоняет клиента. AP (ФРИЦ!Box) имеет фильтры MAC, но они отключены.
Я даже купил новый FRITZ!Коробка, ушла из дома с мобильным телефоном и новым роутером (чтобы избежать, возможно, проблем с радио в моем доме) - та же проблема: CTRL-EVENT-ASSOC-REJECTs. Последнее позволяет мне думать, что проблема не в роутере, а в мобильном телефоне.
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