Date: Wed, 17 Jul 2019 07:38:26 +0200 From: Matthias Apitz <guru@unixarea.de> To: freebsd-wireless@freebsd.org Subject: debugging a Wifi association problem Message-ID: <20190717053826.GA3090@c720-r342378>
next in thread | raw e-mail | index | archive | help
Hello,
I have at home the problem that all my Wifi devices (four FreeBSD laptops,
one Ubuntu laptop and three Ubuntu mobile phones) can connect fine to my AP.
Only one can't anymore (it worked fine in the past but since some months can't
associate anymore). The association requests are always rejected with a package
CTRL-EVENT-ASSOC-REJECT with 'status_code=1'. The device in question can
connect to any other AP I know of in public or in my company, but not to
the two AVM FRITZ!Box WLAN 3170 and 7430 (I bought
the 7430 only to verify the problem, both AVM devices reject the
association).
Do we have any tool in FreeBSD to monitor/debug this problem between the
device in question and the AP? Any other ideas?
I have here a debug log of the wpa_supplicant collected in the device
itself, maybe some expert has an idea what the problem could be. Thanks.
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@unixarea.de, http://www.unixarea.de/ +49-176-38902045
Public GnuPG key: http://www.unixarea.de/key.pub
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20190717053826.GA3090>