From owner-freebsd-wireless@freebsd.org Wed Jul 17 05:38:38 2019 Return-Path: Delivered-To: freebsd-wireless@mailman.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.nyi.freebsd.org (Postfix) with ESMTP id ADD52A3FBA for ; Wed, 17 Jul 2019 05:38:38 +0000 (UTC) (envelope-from guru@unixarea.de) Received: from ms-10.1blu.de (ms-10.1blu.de [178.254.4.101]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id E21438EF26 for ; Wed, 17 Jul 2019 05:38:37 +0000 (UTC) (envelope-from guru@unixarea.de) Received: from [188.174.58.231] (helo=localhost.unixarea.de) by ms-10.1blu.de with esmtpsa (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.86_2) (envelope-from ) id 1hnce5-0006jT-6l for freebsd-wireless@freebsd.org; Wed, 17 Jul 2019 07:38:29 +0200 Received: from localhost.my.domain (localhost [127.0.0.1]) by localhost.unixarea.de (8.15.2/8.14.9) with ESMTPS id x6H5cRoF003196 (version=TLSv1.3 cipher=TLS_AES_256_GCM_SHA384 bits=256 verify=NO) for ; Wed, 17 Jul 2019 07:38:27 +0200 (CEST) (envelope-from guru@unixarea.de) Received: (from guru@localhost) by localhost.my.domain (8.15.2/8.14.9/Submit) id x6H5cQeE003195 for freebsd-wireless@freebsd.org; Wed, 17 Jul 2019 07:38:26 +0200 (CEST) (envelope-from guru@unixarea.de) X-Authentication-Warning: localhost.my.domain: guru set sender to guru@unixarea.de using -f Date: Wed, 17 Jul 2019 07:38:26 +0200 From: Matthias Apitz To: freebsd-wireless@freebsd.org Subject: debugging a Wifi association problem Message-ID: <20190717053826.GA3090@c720-r342378> Reply-To: Matthias Apitz MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Disposition: inline Content-Transfer-Encoding: 8bit X-Operating-System: FreeBSD 13.0-CURRENT r342378 (amd64) X-message-flag: Mails containing HTML will not be read! Please send only plain text. User-Agent: Mutt/1.11.1 (2018-12-01) X-Con-Id: 51246 X-Con-U: 0-guru X-Originating-IP: 188.174.58.231 X-Rspamd-Queue-Id: E21438EF26 X-Spamd-Bar: ---- Authentication-Results: mx1.freebsd.org X-Spamd-Result: default: False [-4.10 / 15.00]; RCVD_VIA_SMTP_AUTH(0.00)[]; HAS_REPLYTO(0.00)[guru@unixarea.de]; HAS_XOIP(0.00)[]; IP_SCORE(-2.93)[ip: (-8.59), ipnet: 178.254.0.0/19(-3.46), asn: 42730(-2.60), country: DE(-0.01)]; HAS_XAW(0.00)[]; TO_DN_NONE(0.00)[]; RCVD_COUNT_THREE(0.00)[4]; MX_GOOD(-0.01)[mail.unixarea.de]; NEURAL_HAM_SHORT(-0.47)[-0.466,0]; RECEIVED_SPAMHAUS_PBL(0.00)[231.58.174.188.zen.spamhaus.org : 127.0.0.10]; FROM_EQ_ENVFROM(0.00)[]; R_DKIM_NA(0.00)[]; ASN(0.00)[asn:42730, ipnet:178.254.0.0/19, country:DE]; MIME_TRACE(0.00)[0:+]; RCVD_IN_DNSWL_LOW(-0.10)[101.4.254.178.list.dnswl.org : 127.0.5.1]; ARC_NA(0.00)[]; NEURAL_HAM_MEDIUM(-1.00)[-0.995,0]; REPLYTO_EQ_FROM(0.00)[]; FROM_HAS_DN(0.00)[]; TO_MATCH_ENVRCPT_ALL(0.00)[]; NEURAL_HAM_LONG(-1.00)[-1.000,0]; MIME_GOOD(-0.10)[text/plain]; PREVIOUSLY_DELIVERED(0.00)[freebsd-wireless@freebsd.org]; AUTH_NA(1.00)[]; RCPT_COUNT_ONE(0.00)[1]; DMARC_NA(0.00)[unixarea.de]; R_SPF_NA(0.00)[]; MID_RHS_NOT_FQDN(0.50)[]; RCVD_TLS_LAST(0.00)[] X-BeenThere: freebsd-wireless@freebsd.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: "Discussions of 802.11 stack, tools device driver development." List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 17 Jul 2019 05:38:38 -0000 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