ubuntu-phone team mailing list archive
-
ubuntu-phone team
-
Mailing list archive
-
Message #24095
Wifi connection gets rejected with CTRL-EVENT-ASSOC-REJECT
Hello,
I have at home a Wifi AP (AVM FRITZ!Box WLAN 3170) and a bunch of Linux
and FreeBSD laptops and 4 phones BQ E4.5 connected to it. All do fine,
but since some month one of the E4.5 running the latest developer
channel can not connect anymore to my AP. It started (IIRC) somewhere in
December, first being unstable on connect and after some days it could
not connect at all anymore. The connection is always rejected from the
AP with a package CTRL-EVENT-ASSOC-REJECT (see debug log below). As this
E4.5 is only my test device and as this can connect without any problem
to *all* other AP, I mostly don't care. Really, I have not found any other AP, not
in public, not in my office, to which the device can't connect. That's
why I think the fault must be in the AP or in the radio environment in
my house (I tested all channels), but as this AP does not offer any
log for debugging, I can't debug this from this side.
I managed to monitor and raised the debug level with wpa-cli in the E4.5
via "adb shell" and have here the log of one connection attempt.
Is there any Wifi expert to see from the log why it gets rejected?
Is this problem somewhere known in UBports or UBphone (Canonical) land?
Thanks in advance for any hint how I could debug this further and nail it down.
matthias
PS: Please don't think in AP's blacklist (as this AP hasn't one) or in
invalid psk. I run Wifi for many years and know what I do :-)
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
--
Matthias Apitz, ✉ guru@xxxxxxxxxxx, http://www.unixarea.de/ +49-176-38902045
Public GnuPG key: http://www.unixarea.de/key.pub
May, 9: Спаси́бо освободители! Thank you very much, Russian liberators!
