From owner-svn-src-head@freebsd.org Mon Jul 23 14:23:54 2018 Return-Path: Delivered-To: svn-src-head@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id CDAE3104C507; Mon, 23 Jul 2018 14:23:53 +0000 (UTC) (envelope-from cy.schubert@cschubert.com) Received: from smtp-out-so.shaw.ca (smtp-out-so.shaw.ca [64.59.136.139]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client CN "Client", Issuer "CA" (not verified)) by mx1.freebsd.org (Postfix) with ESMTPS id B50327E3C4; Mon, 23 Jul 2018 14:23:52 +0000 (UTC) (envelope-from cy.schubert@cschubert.com) Received: from spqr.komquats.com ([70.67.125.17]) by shaw.ca with ESMTPA id hbW4f0IUhwyxUhbW5fSWVS; Mon, 23 Jul 2018 08:08:51 -0600 X-Authority-Analysis: v=2.3 cv=NPJhBHyg c=1 sm=1 tr=0 a=VFtTW3WuZNDh6VkGe7fA3g==:117 a=VFtTW3WuZNDh6VkGe7fA3g==:17 a=kj9zAlcOel0A:10 a=R9QF1RCXAYgA:10 a=pwxSU7ffAAAA:8 a=6I5d2MoRAAAA:8 a=yzOrrXH3AAAA:8 a=2imQQCwUAAAA:8 a=fQfmUbWOAAAA:8 a=WuFjoxRHAAAA:8 a=YxBL1-UpAAAA:8 a=j7GXJ-y8OB5HAgjSyf8A:9 a=CjuIK1q_8ugA:10 a=vlsaR0gtvmEA:10 a=qiWi7Edwir4A:10 a=IPcZcscSuAkA:10 a=NWVoK91CQyQA:10 a=zOhIhOpZmA3SINFph3zL:22 a=fPZJm5J38vnTTye--D-X:22 a=IjZwj45LgO3ly-622nXo:22 a=wJ07XTJWiQ-_TuXd2b14:22 a=ssJKQMnrLbq1UR0lVSsA:22 a=LWTEZSnhwy1crucKGNEr:22 a=1wAt7nxaChJNlLLYrx5g:22 a=Ia-lj3WSrqcvXOmTRaiG:22 Received: from slippy.cwsent.com (slippy8 [10.2.2.6]) by spqr.komquats.com (Postfix) with ESMTPS id 073AE7CA; Mon, 23 Jul 2018 07:08:52 -0700 (PDT) Received: from slippy.cwsent.com (localhost [127.0.0.1]) by slippy.cwsent.com (8.15.2/8.15.2) with ESMTP id w6NE8W0E002393; Mon, 23 Jul 2018 07:08:32 -0700 (PDT) (envelope-from Cy.Schubert@cschubert.com) Received: from slippy (cy@localhost) by slippy.cwsent.com (8.15.2/8.15.2/Submit) with ESMTP id w6NE8T5D002390; Mon, 23 Jul 2018 07:08:31 -0700 (PDT) (envelope-from Cy.Schubert@cschubert.com) Message-Id: <201807231408.w6NE8T5D002390@slippy.cwsent.com> X-Authentication-Warning: slippy.cwsent.com: cy owned process doing -bs X-Mailer: exmh version 2.8.0 04/21/2012 with nmh-1.7.1 Reply-to: Cy Schubert From: Cy Schubert X-os: FreeBSD X-Sender: cy@cwsent.com X-URL: http://www.cschubert.com/ To: Dave Cottlehuber cc: Niclas Zeising , Cy Schubert , Alexey Dokuchaev , "src-committers" , Kyle Evans , svn-src-all@freebsd.org, "Andrey V. Elsukov" , Cy Schubert , svn-src-head@freebsd.org Subject: Re: svn commit: r336203 - in head: contrib/wpa contrib/wpa/hostapd contrib/wpa/hs20/client contrib/wpa/patches contrib/wpa/src/ap contrib/wpa/src/common contrib/wpa/src/crypto contrib/wpa/src/drivers c... In-Reply-To: Message from Dave Cottlehuber of "Mon, 23 Jul 2018 14:55:23 +0200." <1532350523.2338008.1449756200.7870027F@webmail.messagingengine.com> Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Date: Mon, 23 Jul 2018 07:08:29 -0700 X-CMAE-Envelope: MS4wfHgHxQITwYHRcGsJjrZNBwuI/3pv1kyBdCUeW1sZn1RAaVxMgp5SLG5dX3QBMlO6Ja7vb8MpT6XQiEvromF0khmTRompTxdQfsfELQzNAss2omAh2PqB ttZ5U6fpxGR8rYzJ9WruYpwTH4JK/iQA838y7L/ZpfJ+Jm5VccjzQA0VBiwM6RyGoMR7pwgbHpRyJKXBIDWDYqowCPKZgXW97n+kgCzQIFt+LS4ygisZsR7/ SedKJ7TTFKakibUiouYDwGPQ+svMlUatqbI7mdrzavX3egJ3ccGXMig8bZA1kXtr7ru/TH2C/nmJTJxetc/njM6GXeWSA5ILwJzstH75bt7ZwY6xMQ/+WhPC RRma7HW8gigGJL7tDghQMAs3HV+QlayYMFCcyPnjzNvJ3D7EzoE= X-Mailman-Approved-At: Mon, 23 Jul 2018 15:33:59 +0000 X-BeenThere: svn-src-head@freebsd.org X-Mailman-Version: 2.1.27 Precedence: list List-Id: SVN commit messages for the src tree for head/-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 23 Jul 2018 14:23:54 -0000 In message <1532350523.2338008.1449756200.7870027F@webmail.messagingengi ne.com> , Dave Cottlehuber writes: > On Thu, 19 Jul 2018, at 15:25, Niclas Zeising wrote: > > On 07/19/18 15:20, Cy Schubert wrote: > > > In message <2f0ab2c2-b7cc-3dae-2d65-ea3c4a9515cb@daemonic.se>, Niclas > > > Zeising w > > > rites: > > >> [ sending this again since I missed the list the first time, apologies > > >> if anyone receives a duplicate ] > > >> > > >> On 07/19/18 13:57, Kyle Evans wrote: > > >>> On Thu, Jul 19, 2018 at 4:51 AM, Alexey Dokuchaev w > rote > > >> : > > >>>> On Thu, Jul 19, 2018 at 11:48:03AM +0300, Andrey V. Elsukov wrote: > > >>>>> ... > > >>>>> Yesterday I updated my notebook (with iwm(4)) and also noticed that > > >>>>> wi-fi connection periodically breaks. /etc/rc.d/wpa_supplicant restar > t > > >>>>> wlan0 helps. After your message I reinstalled wpa_supplicant from old > > >>>>> source and now it works stable already about 2 hours. > > Reporting the same thing. At my end it looks like an issue with the AP itself > , > not iwm but maybe more expert eyes see something I don't? I've seen this once > downstairs where the family has an imac on wifi, and it also disconnected at > the same time, and reconnected. I collected all this for the Ubiquiti forums > but maybe it helps here. > > I'm using intel 8265, WPA-PSK, and unifi UAC Pro AP. I've been seeing this > for ~ 5 days, around the time my UAC firmware got bumped to 3.9.27.8537, and > also the last CURRENT update I did. > > Sometimes it's brutal (every 1-2 minutes) and other times it takes a while (h > ours) to occur: > > 2018-07-18T19:03:10.843020+00:00 akai kernel: [9200] wlan0: [80:2a:a8:5a:bd:3 > f] AMRR: current rate 2, txcnt=12, retrycnt=167 > 2018-07-18T19:03:11.684065+00:00 akai kernel: [9200] wlan0: [80:2a:a8:5a:bd:3 > f] AMRR: current rate 2, txcnt=11, retrycnt=94 > 2018-07-18T19:03:11.847485+00:00 akai 1 2018-07-18T19:03:11.847320+00:00 akai > .skunkwerks.at wpa_supplicant 91696 - - wlan0: CTRL-EVENT-DISCONNECTED bssid= > 80:2a:a8:5a:bd:3f reason=1 locally_generated=1 > 2018-07-18T19:03:11.848239+00:00 akai 1 2018-07-18T19:03:11.848123+00:00 akai > .skunkwerks.at devd 17186 - - Processing event '!system=IFNET subsystem=wlan0 > type=LINK_DOWN' > 2018-07-18T19:03:11.848846+00:00 akai 1 2018-07-18T19:03:11.848384+00:00 akai > .skunkwerks.at dhclient 57397 - - wlan0 link state up -> down > 2018-07-18T19:03:11.848899+00:00 akai 1 2018-07-18T19:03:11.848593+00:00 akai > .skunkwerks.at devd 17186 - - Popping table > 2018-07-18T19:03:11.892696+00:00 akai kernel: [9201] wlan0: [80:2a:a8:5a:bd:3 > f] station deauth via MLME (reason: 1 (unspecified)) > 2018-07-18T19:03:11.892720+00:00 akai kernel: [9201] wlan0: ieee80211_swscan_ > cancel_scan: called; F_SCAN=0, vap=match, signal=0 > 2018-07-18T19:03:11.892733+00:00 akai kernel: [9201] wlan0: ieee80211_swscan_ > cancel_scan: called; F_SCAN=0, vap=match, signal=0 > 2018-07-18T19:03:11.892736+00:00 akai kernel: [9201] wlan0: [80:2a:a8:5a:bd:3 > f] send station disassociate (reason: 8 (sending STA is leaving/has left BSS) > ) > 2018-07-18T19:03:11.892740+00:00 akai kernel: [9201] [80:2a:a8:5a:bd:3f] send > disassoc on channel 6 > 2018-07-18T19:03:11.892743+00:00 akai kernel: [9201] wlan0: [00:28:f8:d0:91:5 > 2] amrr_node_init: non-11n node > 2018-07-18T19:03:11.892746+00:00 akai kernel: [9201] wlan0: link state change > d to DOWN > 2018-07-18T19:03:11.892749+00:00 akai kernel: [9201] wlan0: [00:28:f8:d0:91:5 > 2] AMRR: nrates=0, initial rate 0 > 2018-07-18T19:03:12.114718+00:00 akai kernel: [9201] wlan0: ieee80211_scanreq > : flags 0x20052 duration 0x7fffffff mindwell 0 maxdwell 0 nssid 1 > 2018-07-18T19:03:12.114744+00:00 akai kernel: [9201] wlan0: ieee80211_scan_fl > ush > > this time I got both the wlandebug output and also /var/log/messages & pcap f > rom > the AP. I'm not sure how much privileged info is in the AP pcap so its availa > ble > privately on request if needed. > > laptop - looks like a normal exit of the AP to me: > > 2018-07-23T12:20:22.469857+00:00 akai kernel: [1823] wlan0: [80:2a:a8:5a:bd:3 > f] AMRR decreasing rate 11 (txcnt=46 retrycnt=16) > 2018-07-23T12:20:25.396670+00:00 akai kernel: [1825] wlan0: [80:2a:a8:5a:bd:3 > f] AMRR: current rate 11, txcnt=11, retrycnt=105 > 2018-07-23T12:20:25.396700+00:00 akai kernel: [1825] wlan0: [80:2a:a8:5a:bd:3 > f] AMRR decreasing rate 4 (txcnt=11 retrycnt=105) > 2018-07-23T12:20:25.698421+00:00 akai 1 2018-07-23T12:20:25.698238+00:00 akai > .skunkwerks.at wpa_supplicant 22034 - - wlan0: CTRL-EVENT-DISCONNECTED bssid= > 80:2a:a8:5a:bd:3f reason=1 locally_generated=1 > 2018-07-23T12:20:25.699374+00:00 akai 1 2018-07-23T12:20:25.699249+00:00 akai > .skunkwerks.at dhclient 23843 - - wlan0 link state up -> down > 2018-07-23T12:20:25.699465+00:00 akai 1 2018-07-23T12:20:25.699319+00:00 akai > .skunkwerks.at devd 37330 - - Processing event '!system=IFNET subsystem=wlan0 > type=LINK_DOWN' > 2018-07-23T12:20:25.699521+00:00 akai 1 2018-07-23T12:20:25.699377+00:00 akai > .skunkwerks.at devd 37330 - - Pushing table > 2018-07-23T12:20:25.699569+00:00 akai 1 2018-07-23T12:20:25.699447+00:00 akai > .skunkwerks.at devd 37330 - - Processing notify event > 2018-07-23T12:20:25.699778+00:00 akai 1 2018-07-23T12:20:25.699701+00:00 akai > .skunkwerks.at devd 37330 - - Popping table > 2018-07-23T12:20:25.864867+00:00 akai kernel: [1826] wlan0: [80:2a:a8:5a:bd:3 > f] station deauth via MLME (reason: 1 (unspecified)) > 2018-07-23T12:20:25.864893+00:00 akai kernel: [1826] wlan0: ieee80211_swscan_ > cancel_scan: called; F_SCAN=0, vap=match, signal=0 > 2018-07-23T12:20:25.864896+00:00 akai kernel: [1826] wlan0: ieee80211_swscan_ > cancel_scan: called; F_SCAN=0, vap=match, signal=0 > 2018-07-23T12:20:25.864898+00:00 akai kernel: [1826] wlan0: [80:2a:a8:5a:bd:3 > f] send station disassociate (reason: 8 (sending STA is leaving/has left BSS) > ) > 2018-07-23T12:20:25.864903+00:00 akai kernel: [1826] [80:2a:a8:5a:bd:3f] send > disassoc on channel 1 > 2018-07-23T12:20:25.864926+00:00 akai kernel: [1826] wlan0: [00:28:f8:d0:91:5 > 2] amrr_node_init: non-11n node > 2018-07-23T12:20:25.864929+00:00 akai kernel: [1826] wlan0: link state change > d to DOWN > 2018-07-23T12:20:25.864936+00:00 akai kernel: [1826] wlan0: [00:28:f8:d0:91:5 > 2] AMRR: nrates=0, initial rate 0 > 2018-07-23T12:20:25.864943+00:00 akai kernel: [1826] wlan0: ieee80211_scanreq > : flags 0x20052 duration 0x7fffffff mindwell 0 maxdwell 0 nssid 1 > 2018-07-23T12:20:26.084679+00:00 akai kernel: [1826] wlan0: ieee80211_scan_fl > ush > > AP logs - looking very much like a large chunk of the AP stack restarted but > not the AP itself: > > Jul 23 12:24:36 ap2terrace user.info syslog: ubnt_protocol.ubnt_usr1_handler( > ): Get DHCP IP > Jul 23 12:24:36 ap2terrace user.info syslog: ubnt_protocol.ubnt_usr1_handler( > ): my_ip is 172.16.2.10 > Jul 23 12:24:36 ap2terrace user.err syslog: ubnt_protocol.ubnt_multicast_sock > et_init(): already drop membership > Jul 23 12:24:36 ap2terrace user.notice syswrapper: hostapd update: conf=/etc/ > aaa2.cfg iterface=ath1 nas_ip=172.16.2.10 res=OK > Jul 23 12:24:36 ap2terrace user.notice syswrapper: hostapd update: conf=/etc/ > aaa1.cfg iterface=ath0 nas_ip=172.16.2.10 res=OK > Jul 23 12:24:37 ap2terrace daemon.info init: process '/bin/dropbear -F -d /va > r/run/dropbear_dss_host_key -r /var/run/dropbear_rsa_host_key -p br0:22' (pid > 918) exited. Sc > Jul 23 12:24:37 ap2terrace daemon.info init: starting pid 1029, tty '/dev/nul > l': '/bin/dropbear -F -d /var/run/dropbear_dss_host_key -r /var/run/dropbear_ > rsa_host_key -p > Jul 23 12:24:37 ap2terrace authpriv.info dropbear[1029]: Not backgrounding > Jul 23 12:25:06 ap2terrace user.err syslog: ace_reporter.reporter_fail(): Unk > nown[11] (http://172.16.1.14:8080/inform) > Jul 23 12:25:06 ap2terrace user.err syslog: ace_reporter.reporter_fail(): ini > tial contact failed #1, url=http://172.16.1.14:8080/inform, rc=11 > Jul 23 12:25:08 ap2terrace daemon.info hostapd: ath1: STA 80:2a:a8:5b:bd:3f D > RIVER: Sead AUTH addr=80:ed:2c:45:8e:f7 status_code=0 > Jul 23 12:25:08 ap2terrace kern.warn kernel: [ 52.510000] wmi_unified_event > _rx : no registered event handler : event id 0x901b > Jul 23 12:25:08 ap2terrace daemon.info hostapd: ath1: STA 80:ed:2c:45:8e:f7 I > EEE 802.11: associated > Jul 23 12:25:08 ap2terrace user.info syslog: wevent.ubnt_custom_event(): EVEN > T_STA_JOIN ath1: 80:ed:2c:45:8e:f7 / 1 > Jul 23 12:25:08 ap2terrace daemon.info hostapd: ath1: STA 80:ed:2c:45:8e:f7 W > PA: pairwise key handshake completed (RSN) > Jul 23 12:25:08 ap2terrace user.info syslog: wevent.ubnt_custom_event(): EVEN > T_STA_IP ath1: 80:ed:2c:45:8e:f7 / 172.16.2.14 > Jul 23 12:25:09 ap2terrace kern.warn kernel: [ 53.000000] [wifi1] FWLOG: [7 > 3760] RATE: ChainMask 3, phymode 1044489, ni_flags 0x02233006, vht_mcs_set 0x > fffa, ht_mcs_set 0xffff, legacy_rate_set 0x12027 > Jul 23 12:25:09 ap2terrace kern.warn kernel: [ 53.000000] [wifi1] FWLOG: [7 > 3767] WAL_DBGID_SECURITY_ALLOW_DATA ( 0x435110 ) > Jul 23 12:25:09 ap2terrace kern.warn kernel: [ 53.000000] [wifi1] FWLOG: [7 > 3792] RATE: ChainMask 3, phymode 1044490, ni_flags 0x02233006, vht_mcs_set 0x > fffa, ht_mcs_set 0xffff, legacy_rate_set 0x0401 > Jul 23 12:25:18 ap2terrace daemon.info hostapd: ath1: STA 80:ed:2c:45:8e:f7 R > ADIUS: starting accounting session 5AAD0B98-00000000 > Jul 23 12:25:20 ap2terrace daemon.info hostapd: ath0: STA 80:2a:a8:5a:bd:3f D > RIVER: Sead AUTH addr=00:28:f8:d0:91:52 status_code=0 > Jul 23 12:25:20 ap2terrace user.info syslog: wevent.ubnt_custom_event(): EVEN > T_STA_JOIN ath0: 00:28:f8:d0:91:52 / 1 > Jul 23 12:25:20 ap2terrace daemon.info hostapd: ath0: STA 00:28:f8:d0:91:52 I > EEE 802.11: associated > Jul 23 12:25:20 ap2terrace daemon.info hostapd: ath0: STA 00:28:f8:d0:91:52 W > PA: pairwise key handshake completed (RSN) > Jul 23 12:25:20 ap2terrace user.info syslog: wevent.ubnt_custom_event(): EVEN > T_STA_IP ath0: 00:28:f8:d0:91:52 / 172.16.2.92 > Jul 23 12:25:30 ap2terrace daemon.info hostapd: ath0: STA 00:28:f8:d0:91:52 R > ADIUS: starting accounting session 5AAD0B98-00000000 > > I'll roll back my boot environment and let you know if it behaves differently > . > > A+ > Dave Are you at least at r336531? -- Cheers, Cy Schubert FreeBSD UNIX: Web: http://www.FreeBSD.org The need of the many outweighs the greed of the few.