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...

Mon Jul 23 14:28:41 UTC 2018

In message <CACNAnaGbE+86dVAD4X6n4Vn_N63FK6i0wK4w+GgmR0dZmMJ_Kw at mail.gma
il.com>
, Kyle Evans writes:
> On Mon, Jul 23, 2018 at 7:55 AM, Dave Cottlehuber <dch at skunkwerks.at> wrote:
> > 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 at 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 <danfe at freebsd.org> 
> wrote
> >> >> :
> >> >>>> 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 resta
> rt
> >> >>>>> wlan0 helps. After your message I reinstalled wpa_supplicant from ol
> d
> >> >>>>> 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 itse
> lf,
> > not iwm but maybe more expert eyes see something I don't? I've seen this on
> ce
> > downstairs where the family has an imac on wifi, and it also disconnected a
> t
> > the same time, and reconnected. I collected all this for the Ubiquiti forum
> s
> > 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, an
> d
> > also the last CURRENT update I did.
> >
> > Sometimes it's brutal (every 1-2 minutes) and other times it takes a while 
> (hours) to occur:
> >
> > 2018-07-18T19:03:10.843020+00:00 akai kernel: [9200] wlan0: [80:2a:a8:5a:bd
> :3f] 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
> :3f] 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 ak
> ai.skunkwerks.at wpa_supplicant 91696 - - wlan0: CTRL-EVENT-DISCONNECTED bssi
> d=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 ak
> ai.skunkwerks.at devd 17186 - - Processing event '!system=IFNET subsystem=wla
> n0 type=LINK_DOWN'
> > 2018-07-18T19:03:11.848846+00:00 akai 1 2018-07-18T19:03:11.848384+00:00 ak
> ai.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 ak
> ai.skunkwerks.at devd 17186 - - Popping table
> > 2018-07-18T19:03:11.892696+00:00 akai kernel: [9201] wlan0: [80:2a:a8:5a:bd
> :3f] station deauth via MLME (reason: 1 (unspecified))
> > 2018-07-18T19:03:11.892720+00:00 akai kernel: [9201] wlan0: ieee80211_swsca
> n_cancel_scan: called; F_SCAN=0, vap=match, signal=0
> > 2018-07-18T19:03:11.892733+00:00 akai kernel: [9201] wlan0: ieee80211_swsca
> n_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
> :3f] send station disassociate (reason: 8 (sending STA is leaving/has left BS
> S))
> > 2018-07-18T19:03:11.892740+00:00 akai kernel: [9201] [80:2a:a8:5a:bd:3f] se
> nd disassoc on channel 6
> > 2018-07-18T19:03:11.892743+00:00 akai kernel: [9201] wlan0: [00:28:f8:d0:91
> :52] amrr_node_init: non-11n node
> > 2018-07-18T19:03:11.892746+00:00 akai kernel: [9201] wlan0: link state chan
> ged to DOWN
> > 2018-07-18T19:03:11.892749+00:00 akai kernel: [9201] wlan0: [00:28:f8:d0:91
> :52] AMRR: nrates=0, initial rate 0
> > 2018-07-18T19:03:12.114718+00:00 akai kernel: [9201] wlan0: ieee80211_scanr
> eq: flags 0x20052 duration 0x7fffffff mindwell 0 maxdwell 0 nssid 1
> > 2018-07-18T19:03:12.114744+00:00 akai kernel: [9201] wlan0: ieee80211_scan_
> flush
> >
> > this time I got both the wlandebug output and also /var/log/messages & pcap
>  from
> > the AP. I'm not sure how much privileged info is in the AP pcap so its avai
> lable
> > 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
> :3f] 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
> :3f] 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
> :3f] 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 ak
> ai.skunkwerks.at wpa_supplicant 22034 - - wlan0: CTRL-EVENT-DISCONNECTED bssi
> d=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 ak
> ai.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 ak
> ai.skunkwerks.at devd 37330 - - Processing event '!system=IFNET subsystem=wla
> n0 type=LINK_DOWN'
> > 2018-07-23T12:20:25.699521+00:00 akai 1 2018-07-23T12:20:25.699377+00:00 ak
> ai.skunkwerks.at devd 37330 - - Pushing table
> > 2018-07-23T12:20:25.699569+00:00 akai 1 2018-07-23T12:20:25.699447+00:00 ak
> ai.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 ak
> ai.skunkwerks.at devd 37330 - - Popping table
> > 2018-07-23T12:20:25.864867+00:00 akai kernel: [1826] wlan0: [80:2a:a8:5a:bd
> :3f] station deauth via MLME (reason: 1 (unspecified))
> > 2018-07-23T12:20:25.864893+00:00 akai kernel: [1826] wlan0: ieee80211_swsca
> n_cancel_scan: called; F_SCAN=0, vap=match, signal=0
> > 2018-07-23T12:20:25.864896+00:00 akai kernel: [1826] wlan0: ieee80211_swsca
> n_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
> :3f] send station disassociate (reason: 8 (sending STA is leaving/has left BS
> S))
> > 2018-07-23T12:20:25.864903+00:00 akai kernel: [1826] [80:2a:a8:5a:bd:3f] se
> nd disassoc on channel 1
> > 2018-07-23T12:20:25.864926+00:00 akai kernel: [1826] wlan0: [00:28:f8:d0:91
> :52] amrr_node_init: non-11n node
> > 2018-07-23T12:20:25.864929+00:00 akai kernel: [1826] wlan0: link state chan
> ged to DOWN
> > 2018-07-23T12:20:25.864936+00:00 akai kernel: [1826] wlan0: [00:28:f8:d0:91
> :52] AMRR: nrates=0, initial rate 0
> > 2018-07-23T12:20:25.864943+00:00 akai kernel: [1826] wlan0: ieee80211_scanr
> eq: flags 0x20052 duration 0x7fffffff mindwell 0 maxdwell 0 nssid 1
> > 2018-07-23T12:20:26.084679+00:00 akai kernel: [1826] wlan0: ieee80211_scan_
> flush
> >
> > AP logs - looking very much like a large chunk of the AP stack restarted bu
> t not the AP itself:
> >
> > Jul 23 12:24:36 ap2terrace user.info syslog: ubnt_protocol.ubnt_usr1_handle
> r(): Get DHCP IP
> > Jul 23 12:24:36 ap2terrace user.info syslog: ubnt_protocol.ubnt_usr1_handle
> r(): my_ip is 172.16.2.10
> > Jul 23 12:24:36 ap2terrace user.err syslog: ubnt_protocol.ubnt_multicast_so
> cket_init(): already drop membership
> > Jul 23 12:24:36 ap2terrace user.notice syswrapper: hostapd update: conf=/et
> c/aaa2.cfg iterface=ath1 nas_ip=172.16.2.10 res=OK
> > Jul 23 12:24:36 ap2terrace user.notice syswrapper: hostapd update: conf=/et
> c/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 /
> var/run/dropbear_dss_host_key -r /var/run/dropbear_rsa_host_key -p br0:22' (p
> id 918) exited. Sc
> > Jul 23 12:24:37 ap2terrace daemon.info init: starting pid 1029, tty '/dev/n
> ull': '/bin/dropbear -F -d /var/run/dropbear_dss_host_key -r /var/run/dropbea
> r_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(): U
> nknown[11] (http://172.16.1.14:8080/inform)
> > Jul 23 12:25:06 ap2terrace user.err syslog: ace_reporter.reporter_fail(): i
> nitial 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
>  DRIVER: 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_eve
> nt_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
>  IEEE 802.11: associated
> > Jul 23 12:25:08 ap2terrace user.info syslog: wevent.ubnt_custom_event(): EV
> ENT_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
>  WPA: pairwise key handshake completed (RSN)
> > Jul 23 12:25:08 ap2terrace user.info syslog: wevent.ubnt_custom_event(): EV
> ENT_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: 
> [73760] RATE: ChainMask 3, phymode 1044489, ni_flags 0x02233006, vht_mcs_set 
> 0xfffa, ht_mcs_set 0xffff, legacy_rate_set 0x12027
> > Jul 23 12:25:09 ap2terrace kern.warn kernel: [   53.000000] [wifi1] FWLOG: 
> [73767] WAL_DBGID_SECURITY_ALLOW_DATA ( 0x435110 )
> > Jul 23 12:25:09 ap2terrace kern.warn kernel: [   53.000000] [wifi1] FWLOG: 
> [73792] RATE: ChainMask 3, phymode 1044490, ni_flags 0x02233006, vht_mcs_set 
> 0xfffa, 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
>  RADIUS: starting accounting session 5AAD0B98-00000000
> > Jul 23 12:25:20 ap2terrace daemon.info hostapd: ath0: STA 80:2a:a8:5a:bd:3f
>  DRIVER: 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(): EV
> ENT_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
>  IEEE 802.11: associated
> > Jul 23 12:25:20 ap2terrace daemon.info hostapd: ath0: STA 00:28:f8:d0:91:52
>  WPA: pairwise key handshake completed (RSN)
> > Jul 23 12:25:20 ap2terrace user.info syslog: wevent.ubnt_custom_event(): EV
> ENT_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
>  RADIUS: starting accounting session 5AAD0B98-00000000
> >
> > I'll roll back my boot environment and let you know if it behaves different
> ly.
> >
>
> Hi,
>
> Please also try updating wpa_supplicant from a revision >= r336529 --
> some other stuff has been straightened out since.

In addition 2.6 addressed a long standing issue I had with 2.5 at a 
popular wifi spot just down the hall from $JOB which disconnected me 
every 30 minutes when my DHCP lease expired.

-- 
Cheers,
Cy Schubert <Cy.Schubert at cschubert.com>
FreeBSD UNIX:  <cy at FreeBSD.org>   Web:  http://www.FreeBSD.org

	The need of the many outweighs the greed of the few.