Date: Wed, 24 Aug 2016 11:55:13 -0700 From: Kevin Oberman <kob6558@gmail.com> To: Adrian Chadd <adrian.chadd@gmail.com>, FreeBSD Net <net@freebsd.org> Cc: =?UTF-8?Q?Vin=C3=ADcius_Zavam?= <egypcio@googlemail.com>, Andriy Voskoboinyk <avos@freebsd.org> Subject: Re: iwn(4) association issues in 11-Stable (and maybe RC) Message-ID: <CAN6yY1sjtqSWrsc8eHzP411J00utwJ8ajFPQcdWHPeAeV9PZpA@mail.gmail.com> In-Reply-To: <CAN6yY1vc7h8RDWXq0O7T6pKwNOjou4=uBax%2BA9XNwW-Mjh%2BG8g@mail.gmail.com> References: <CAN6yY1udTdC4PKE-%2BoOeFQWyV3TYAyCXqwRfT0fq-8fYJQc02A@mail.gmail.com> <CAJ-VmokAQYQGsdPhoDS%2Bty6toc_oXs_V5rND11_3Qc8Dc_4TdQ@mail.gmail.com> <CAN6yY1vTtFR_KzcxVtgLsenHaXMKwrysg5DUJzKsLWXiM-fJcw@mail.gmail.com> <CAJ-Vmom=GiJp_Jomtsi5MeJKz1==eWjMXOj8tDwE4-udRLBJiw@mail.gmail.com> <CA%2BKr6DP7e%2BpPPSSSOKnKiR%2BzT7dN3c_0a9iX3nj%2BvycBsnjUSw@mail.gmail.com> <CAN6yY1uUBVpaS_gYpZQW8_RkbW=NTWCNRinnn9287pguv_57UA@mail.gmail.com> <CAJ-VmomoXPHHZXpKwcjoTRsNMGEaVF%2BJ-iJexktmEkNHHTm97g@mail.gmail.com> <CAN6yY1vc7h8RDWXq0O7T6pKwNOjou4=uBax%2BA9XNwW-Mjh%2BG8g@mail.gmail.com>
next in thread | previous in thread | raw e-mail | index | archive | help
On Tue, Aug 23, 2016 at 10:40 PM, Kevin Oberman < <kob6558@gmail.com> kob6558@gmail.com> wrote: > On Tue, Aug 23, 2016 at 11:48 AM, Adrian Chadd < <kob6558@gmail.com> > adrian.chadd@gmail.com> wrote: > >> Hi, >> >> Compile in IWN_DEBUG and IEEE80211_DEBUG and then do: >> >> wlandebug +assoc +auth +state +rate >> sysctl debug.iwn.0.debug=0x1 >> >> that's TX debugging, and it hopefully will show it trying to do >> association and failing. My guess is that something changed when doing >> the 11n bits for -11 and it's failing to send out the 802.1x frame >> exchange. >> >> It may be something as simple as "adrian needs to fix the rate control >> again". >> >> >> >> -adrian >> > Not working right. I do see 802.11 messages but nothing from iwn. Rebuilt with: options IEEE80211_DEBUG options IWN_DEBUG > sysctl debug.iwn.0.debug=0x1 sysctl: unknown oid 'debug.iwn.0.debug' Exit 1 > sysctl -a | grep iwn device iwn net.wlan.0.%parent: iwn0 net.wlan.devices: iwn0 dev.iwn.0.debug: 0 dev.iwn.0.%parent: pci1 dev.iwn.0.%pnpinfo: vendor=0x8086 device=0x0085 subvendor=0x8086 subdevice=0x1311 class=0x028000 dev.iwn.0.%location: slot=0 function=0 dbsf=pci0:3:0:0 dev.iwn.0.%driver: iwn dev.iwn.0.%desc: Intel Centrino Advanced-N 6205 dev.iwn.%parent: > Here is what I did log. (In this case it did re-associate fairly quickly, unlike when I booted up and it took repeated tries to get an association.) Aug 24 09:54:57 rogue dhclient: New IP Address (wlan0): 192.168.1.5 Aug 24 09:54:57 rogue dhclient: New Subnet Mask (wlan0): 255.255.255.0 Aug 24 09:54:57 rogue dhclient: New Broadcast Address (wlan0): 192.168.1.255 Aug 24 09:54:57 rogue dhclient: New Routers (wlan0): 192.168.1.1 Aug 24 09:54:59 rogue dhclient: New Routers (wlan0): 192.168.1.1 Aug 24 09:56:28 rogue kernel: wlan0: [00:18:e7:dc:05:19] AMRR: current rate 15, txcnt=12, retrycnt=0 Aug 24 09:57:38 rogue kernel: wlan0: [00:18:e7:dc:05:19] AMRR: current rate 15, txcnt=11, retrycnt=0 Aug 24 09:58:43 rogue kernel: wlan0: [00:18:e7:dc:05:19] AMRR: current rate 15, txcnt=12, retrycnt=0 Aug 24 09:59:17 rogue wpa_supplicant[364]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:18:e7:dc:05:19 reason=3 locally_generated=1 Aug 24 09:59:17 rogue kernel: wlan0: [00:18:e7:dc:05:19] station deauth via MLME (reason: 3 (sending STA is leaving/has left IBSS or ESS)) Aug 24 09:59:17 rogue kernel: wlan0: ieee80211_new_state_locked: RUN -> INIT (nrunning 0 nscanning 0) Aug 24 09:59:17 rogue kernel: wlan0: ieee80211_newstate_cb: RUN -> INIT arg 3 Aug 24 09:59:17 rogue kernel: wlan0: sta_newstate: RUN -> INIT (3) Aug 24 09:59:17 rogue kernel: wlan0: [00:18:e7:dc:05:19] send station disassociate (reason: 8 (sending STA is leaving/has left BSS)) Aug 24 09:59:17 rogue kernel: wlan0: [a0:88:b4:c6:ad:28] amrr_node_init: non-11n node Aug 24 09:59:17 rogue kernel: wlan0: [a0:88:b4:c6:ad:28] AMRR: nrates=0, initial rate 0 Aug 24 09:59:17 rogue kernel: wlan0: link state changed to DOWN Aug 24 09:59:17 rogue kernel: wlan0: stop running, 1 vaps running Aug 24 09:59:17 rogue kernel: wlan0: ieee80211_new_state_locked: INIT -> INIT (nrunning 0 nscanning 0) Aug 24 09:59:17 rogue kernel: wlan0: down parent iwn0 Aug 24 09:59:17 rogue kernel: wlan0: ieee80211_newstate_cb: INIT -> INIT arg -1 Aug 24 09:59:17 rogue kernel: wlan0: sta_newstate: INIT -> INIT (-1) Aug 24 09:59:17 rogue wpa_supplicant[364]: wlan0: CTRL-EVENT-TERMINATING Aug 24 09:59:17 rogue dhclient[376]: connection closed Aug 24 09:59:17 rogue dhclient[376]: exiting. Aug 24 09:59:17 rogue kernel: wlan0: ieee80211_vap_detach: STA parent iwn0 Aug 24 09:59:17 rogue kernel: wlan0: stop running, 0 vaps running Aug 24 09:59:17 rogue kernel: wlan0: ieee80211_new_state_locked: INIT -> INIT (nrunning 0 nscanning 0) Aug 24 09:59:17 rogue kernel: wlan0: ieee80211_newstate_cb: INIT -> INIT arg -1 Aug 24 09:59:17 rogue kernel: wlan0: sta_newstate: INIT -> INIT (-1) Aug 24 09:59:17 rogue rtsold[817]: <rtsock_input_ifannounce> interface wlan0 removed Aug 24 09:59:17 rogue kernel: wlan0: Ethernet address: a0:88:b4:c6:ad:28 Aug 24 09:59:17 rogue wpa_supplicant[1638]: Successfully initialized wpa_supplicant Aug 24 09:59:18 rogue wpa_supplicant[1655]: Successfully initialized wpa_supplicant Aug 24 09:59:18 rogue root: /etc/rc.d/wpa_supplicant: WARNING: failed to start wpa_supplicant Aug 24 09:59:18 rogue wpa_supplicant[1656]: ioctl[SIOCS80211, op=103, val=0, arg_len=128]: Operation now in progress Aug 24 09:59:18 rogue kernel: iwn0: iwn_read_firmware: ucode rev=0x12a80601 Aug 24 09:59:18 rogue wpa_supplicant[1656]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1 Aug 24 09:59:19 rogue wpa_supplicant[1656]: ioctl[SIOCS80211, op=103, val=0, arg_len=128]: Operation now in progress Aug 24 09:59:19 rogue wpa_supplicant[1656]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1 Aug 24 09:59:19 rogue wpa_supplicant[1656]: wlan0: Trying to associate with 00:18:e7:dc:05:19 (SSID='babcom' freq=2462 MHz) Aug 24 09:59:29 rogue wpa_supplicant[1656]: wlan0: Authentication with 00:18:e7:dc:05:19 timed out. Aug 24 09:59:29 rogue wpa_supplicant[1656]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:18:e7:dc:05:19 reason=3 locally_generated=1 Aug 24 09:59:29 rogue oberman: /etc/rc.d/dhclient: WARNING: failed to start dhclient Aug 24 09:59:30 rogue wpa_supplicant[1656]: wlan0: Trying to associate with 00:18:e7:dc:05:19 (SSID='babcom' freq=2462 MHz) Aug 24 09:59:30 rogue wpa_supplicant[1656]: wlan0: Associated with 00:18:e7:dc:05:19 Aug 24 09:59:30 rogue kernel: wlan0: link state changed to UP Aug 24 09:59:30 rogue wpa_supplicant[1656]: wlan0: WPA: Key negotiation completed with 00:18:e7:dc:05:19 [PTK=CCMP GTK=TKIP] Aug 24 09:59:30 rogue wpa_supplicant[1656]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:18:e7:dc:05:19 completed [id=1 id_str=] Aug 24 09:59:31 rogue dhclient: New IP Address (wlan0): 192.168.1.5 Aug 24 09:59:31 rogue dhclient: New Subnet Mask (wlan0): 255.255.255.0 Aug 24 09:59:31 rogue dhclient: New Broadcast Address (wlan0): 192.168.1.255 Aug 24 09:59:31 rogue dhclient: New Routers (wlan0): 192.168.1.1 Any idea what is going on?
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?CAN6yY1sjtqSWrsc8eHzP411J00utwJ8ajFPQcdWHPeAeV9PZpA>