Date: Sun, 12 Jan 2014 14:45:34 -0800 From: Kevin Oberman <rkoberman@gmail.com> To: Erich Dollansky <erichsfreebsdlist@alogt.com> Cc: FreeBSD Wireless <freebsd-wireless@freebsd.org> Subject: Re: IWN performance very bad with 10.0-RC5 Message-ID: <CAN6yY1sPwFz=KgzMzfc_Dgj-VDvRuyUvZNL2X8BNqN6HyVZLtw@mail.gmail.com> In-Reply-To: <20140112143614.3313f509@X220.alogt.com> References: <CAN6yY1skA-x=-JLf%2BWQ0GJdSmHugqmSX2Um2zWkKB_cULxwsSw@mail.gmail.com> <20140111132338.7a7fc14c@X220.alogt.com> <CAJ-VmokkmAuLCJo01yjMGT-is3ET-pigY6BHhk0pfROQ=UMJcg@mail.gmail.com> <20140111133610.313a4bca@X220.alogt.com> <CAJ-Vmomo=0=6Yc6hQ02uBYfuyYibnYdsCMVOKm91Kxya2LOKwQ@mail.gmail.com> <20140112143614.3313f509@X220.alogt.com>
next in thread | previous in thread | raw e-mail | index | archive | help
[-- Attachment #1 --] On Sat, Jan 11, 2014 at 10:36 PM, Erich Dollansky < erichsfreebsdlist@alogt.com> wrote: > Hi, > > On Fri, 10 Jan 2014 21:45:59 -0800 > Adrian Chadd <adrian@freebsd.org> wrote: > > > Please help dig up which change broke it. Even just test out the head > > iwn code from 6 months ago. > > I came to a very strange result. I have iwn in the kernel since June > 2012 using 10. I also have had run in the kernel of another machine > since February 2011. I could not even add runfw to the kernel those > days running some 8 stable. I kept it that way until now. > > run was always working. iwn gave problems starting between August and > November of last year on my access point but still worked on other > places. I used iwn to connect successfully to another wireless network > mid November 2013. > > After adding the firmware to the kernel for both iwn and run, I could > compile the kernel and iwn started to work. runfw did not break > compilation. > > I wonder now if the iwn or run could even work without firmware or if > the firmware was automatically loaded even when iwn or run where > compiled into the kernel. > > Erich > Some things look odd here. I had been running with crypto debug for about 15 hours when I captured the attached log. The things tha looks odd to me are two series of "AES-CCM replay detected" errors. Jan 12 00:54:03 rogue kernel: wlan0: [00:26:b8:67:c3:2d] AES-CCM replay detected tid 16 <rsc 1165, csc 1207, keyix 2 rxkeyix 65535> [rsc inc. by one 41 times until rsc = csc] Jan 12 00:54:03 rogue kernel: wlan0: [00:26:b8:67:c3:2d] AES-CCM replay detected tid 16 <rsc 1206, csc 1207, keyix 2 rxkeyix 65535> One VERY odd thing is the MAC address. It is one byte from being the address of my Verizon/ActionTec wireless router. It is the only device on my network that has an OID of 00:26:b8, but the last nibble is 28 while these errors claim a MAC ending in 2d. The setkey statements with a MAC of FF:FF:FF:FF:FF:FF also look odd to be, but I am pretty clueless about the meaning of most of the message, do it might be fine, but looks strange. During this time I have not had the network completely hang and require an interface restart. Does this provide anything useful? -- R. Kevin Oberman, Network Engineer, Retired E-mail: rkoberman@gmail.com [-- Attachment #2 --] Jan 11 20:33:29 rogue kernel: wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x6 keyix 1 Jan 11 20:33:29 rogue kernel: wlan0: ieee80211_crypto_newkey: no h/w support for cipher AES-CCM, falling back to s/w Jan 11 20:33:29 rogue kernel: wlan0: ieee80211_crypto_setkey: AES-CCM keyix 1 flags 0x136 mac ff:ff:ff:ff:ff:ff rsc 0 tsc 0 len 16 Jan 11 21:07:15 rogue wpa_supplicant[2669]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:26:b8:67:c3:2d reason=0 Jan 11 21:07:15 rogue kernel: wlan0: _ieee80211_crypto_delkey: AES-CCM keyix 0 flags 0x133 rsc 0 tsc 31619 len 16 Jan 11 21:07:15 rogue kernel: wlan0: link state changed to DOWN Jan 11 21:07:15 rogue kernel: wlan0: _ieee80211_crypto_delkey: NONE keyix 65535 flags 0x3 rsc 0 tsc 0 len 0 Jan 11 21:07:15 rogue kernel: wlan0: _ieee80211_crypto_delkey: AES-CCM keyix 1 flags 0x136 rsc 990 tsc 0 len 16 Jan 11 21:07:15 rogue kernel: wlan0: _ieee80211_crypto_delkey: AES-CCM keyix 2 flags 0x136 rsc 2337 tsc 0 len 16 Jan 11 21:07:15 rogue kernel: wlan0: _ieee80211_crypto_delkey: NONE keyix 65535 flags 0x3 rsc 0 tsc 0 len 0 Jan 11 21:07:20 rogue wpa_supplicant[2669]: wlan0: Trying to associate with 00:26:b8:67:c3:2d (SSID='babcom' freq=2437 MHz) Jan 11 21:07:20 rogue kernel: wlan0: [00:26:b8:67:c3:2d] key id 1 is not set (decap) Jan 11 21:07:31 rogue wpa_supplicant[2669]: wlan0: Authentication with 00:26:b8:67:c3:2d timed out. Jan 11 21:07:31 rogue wpa_supplicant[2669]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:26:b8:67:c3:2d reason=3 locally_generated=1 Jan 11 21:07:31 rogue kernel: wlan0: _ieee80211_crypto_delkey: NONE keyix 65535 flags 0x3 rsc 0 tsc 0 len 0 Jan 11 21:07:31 rogue last message repeated 3 times Jan 11 21:07:32 rogue wpa_supplicant[2669]: wlan0: Trying to associate with 00:26:b8:67:c3:2d (SSID='babcom' freq=2437 MHz) Jan 11 21:07:32 rogue wpa_supplicant[2669]: wlan0: Associated with 00:26:b8:67:c3:2d Jan 11 21:07:32 rogue kernel: wlan0: link state changed to UP Jan 11 21:07:32 rogue kernel: wlan0: [ff:ff:ff:ff:ff:ff] no default transmit key (ieee80211_encap) deftxkey 65535 Jan 11 21:07:32 rogue dhclient[2706]: send_packet: No buffer space available Jan 11 21:07:32 rogue devd: Executing '/etc/rc.d/dhclient quietstart wlan0' Jan 11 21:07:32 rogue wpa_supplicant[2669]: wlan0: WPA: Key negotiation completed with 00:26:b8:67:c3:2d [PTK=CCMP GTK=CCMP] Jan 11 21:07:32 rogue kernel: wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x3 keyix 65535 Jan 11 21:07:32 rogue kernel: wlan0: ieee80211_crypto_newkey: no h/w support for cipher AES-CCM, falling back to s/w Jan 11 21:07:32 rogue kernel: wlan0: ieee80211_crypto_setkey: AES-CCM keyix 0 flags 0x133 mac 00:26:b8:67:c3:2d rsc 0 tsc 0 len 16 Jan 11 21:07:32 rogue kernel: wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x6 keyix 1 Jan 11 21:07:32 rogue kernel: wlan0: ieee80211_crypto_newkey: no h/w support for cipher AES-CCM, falling back to s/w Jan 11 21:07:32 rogue kernel: wlan0: ieee80211_crypto_setkey: AES-CCM keyix 1 flags 0x136 mac ff:ff:ff:ff:ff:ff rsc 5 tsc 0 len 16 Jan 11 21:07:32 rogue wpa_supplicant[2669]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:26:b8:67:c3:2d completed [id=1 id_str=] Jan 11 21:07:37 rogue dhclient: New IP Address (wlan0): 192.168.1.5 Jan 11 21:07:37 rogue dhclient: New Subnet Mask (wlan0): 255.255.255.0 Jan 11 21:07:37 rogue dhclient: New Broadcast Address (wlan0): 192.168.1.255 Jan 11 21:07:37 rogue dhclient: New Routers (wlan0): 192.168.1.1 Jan 11 21:15:06 rogue dbus[1440]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper) Jan 11 21:15:06 rogue dbus[1440]: [system] Successfully activated service 'org.freedesktop.PackageKit' Jan 11 22:07:29 rogue kernel: wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x6 keyix 2 Jan 11 22:07:29 rogue kernel: wlan0: ieee80211_crypto_newkey: no h/w support for cipher AES-CCM, falling back to s/w Jan 11 22:07:29 rogue kernel: wlan0: ieee80211_crypto_setkey: AES-CCM keyix 2 flags 0x136 mac ff:ff:ff:ff:ff:ff rsc 0 tsc 0 len 16 Jan 11 22:15:06 rogue dbus[1440]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper) Jan 11 22:15:06 rogue dbus[1440]: [system] Successfully activated service 'org.freedesktop.PackageKit' Jan 11 22:48:38 rogue kernel: wlan0: _ieee80211_crypto_delkey: AES-CCM keyix 0 flags 0x133 rsc 0 tsc 6429 len 16 Jan 11 22:48:38 rogue kernel: wlan0: link state changed to DOWN Jan 11 22:48:38 rogue kernel: wlan0: _ieee80211_crypto_delkey: NONE keyix 65535 flags 0x3 rsc 0 tsc 0 len 0 Jan 11 22:48:38 rogue kernel: wlan0: _ieee80211_crypto_delkey: AES-CCM keyix 1 flags 0x136 rsc 2469 tsc 0 len 16 Jan 11 22:48:38 rogue wpa_supplicant[2669]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:26:b8:67:c3:2d reason=0 Jan 11 22:48:38 rogue kernel: wlan0: _ieee80211_crypto_delkey: AES-CCM keyix 2 flags 0x136 rsc 1180 tsc 0 len 16 Jan 11 22:48:38 rogue kernel: wlan0: _ieee80211_crypto_delkey: NONE keyix 65535 flags 0x3 rsc 0 tsc 0 len 0 Jan 11 22:52:52 rogue ntpd[1291]: sendto(xxx.xxx.252.38) (fd=25): Network is down Jan 11 22:53:14 rogue ntpd[1291]: sendto(xxx.xxx.254.218) (fd=25): Network is down Jan 11 22:53:20 rogue ntpd[1291]: sendto(xxx.xxx.100.18) (fd=25): Network is down Jan 11 22:53:24 rogue ntpd[1291]: sendto(xxx.xxx.252.90) (fd=25): Network is down Jan 11 22:53:58 rogue ntpd[1291]: sendto(xxx.xxx.48.12) (fd=25): Network is down Jan 11 22:54:19 rogue dbus[1440]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper) Jan 11 22:54:19 rogue dbus[1440]: [system] Successfully activated service 'org.freedesktop.PackageKit' Jan 11 22:54:29 rogue ntpd[1291]: sendto(xxx.xxx.177.206) (fd=25): Network is down Jan 11 23:15:06 rogue dbus[1440]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper) Jan 11 23:15:06 rogue dbus[1440]: [system] Successfully activated service 'org.freedesktop.PackageKit' Jan 11 23:18:14 rogue wpa_supplicant[2669]: wlan0: Trying to associate with 00:26:b8:67:c3:2d (SSID='babcom' freq=2437 MHz) Jan 11 23:18:14 rogue wpa_supplicant[2669]: wlan0: Associated with 00:26:b8:67:c3:2d Jan 11 23:18:14 rogue kernel: wlan0: link state changed to UP Jan 11 23:18:14 rogue kernel: wlan0: Jan 11 23:18:14 rogue kernel: [ff:ff:ff:ff:ff:ff] no default transmit key (ieee80211_encap) deftxkey 65535 Jan 11 23:18:14 rogue dhclient[2706]: send_packet: No buffer space available Jan 11 23:18:14 rogue devd: Executing '/etc/rc.d/dhclient quietstart wlan0' Jan 11 23:18:14 rogue wpa_supplicant[2669]: wlan0: WPA: Key negotiation completed with 00:26:b8:67:c3:2d [PTK=CCMP GTK=CCMP] Jan 11 23:18:14 rogue kernel: wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x3 keyix 65535 Jan 11 23:18:14 rogue kernel: wlan0: ieee80211_crypto_newkey: no h/w support for cipher AES-CCM, falling back to s/w Jan 11 23:18:14 rogue kernel: wlan0: ieee80211_crypto_setkey: AES-CCM keyix 0 flags 0x133 mac 00:26:b8:67:c3:2d rsc 0 tsc 0 len 16 Jan 11 23:18:14 rogue kernel: wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x6 keyix 1 Jan 11 23:18:14 rogue kernel: wlan0: ieee80211_crypto_newkey: no h/w support for cipher AES-CCM, falling back to s/w Jan 11 23:18:14 rogue kernel: wlan0: ieee80211_crypto_setkey: AES-CCM keyix 1 flags 0x136 mac ff:ff:ff:ff:ff:ff rsc 378 tsc 0 len 16 Jan 11 23:18:14 rogue wpa_supplicant[2669]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:26:b8:67:c3:2d completed [id=1 id_str=] Jan 11 23:18:20 rogue dhclient: New IP Address (wlan0): 192.168.1.5 Jan 11 23:18:20 rogue dhclient: New Subnet Mask (wlan0): 255.255.255.0 Jan 11 23:18:20 rogue dhclient: New Broadcast Address (wlan0): 192.168.1.255 Jan 11 23:18:20 rogue dhclient: New Routers (wlan0): 192.168.1.1 Jan 12 00:07:29 rogue kernel: wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x6 keyix 2 Jan 12 00:07:29 rogue kernel: wlan0: ieee80211_crypto_newkey: no h/w support for cipher AES-CCM, falling back to s/w Jan 12 00:07:29 rogue kernel: wlan0: ieee80211_crypto_setkey: AES-CCM keyix 2 flags 0x136 mac ff:ff:ff:ff:ff:ff rsc 0 tsc 0 len 16 Jan 12 00:15:06 rogue dbus[1440]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper) Jan 12 00:15:06 rogue dbus[1440]: [system] Successfully activated service 'org.freedesktop.PackageKit' Jan 12 00:54:03 rogue kernel: wlan0: [00:26:b8:67:c3:2d] AES-CCM replay detected tid 16 <rsc 1165, csc 1207, keyix 2 rxkeyix 65535> [rsc inc. by one 41 times until rsc = csc] Jan 12 00:54:03 rogue kernel: wlan0: [00:26:b8:67:c3:2d] AES-CCM replay detected tid 16 <rsc 1206, csc 1207, keyix 2 rxkeyix 65535> Jan 12 01:07:29 rogue kernel: wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x6 keyix 1 Jan 12 01:07:29 rogue kernel: wlan0: ieee80211_crypto_newkey: no h/w support for cipher AES-CCM, falling back to s/w Jan 12 01:07:29 rogue kernel: wlan0: ieee80211_crypto_setkey: AES-CCM keyix 1 flags 0x136 mac ff:ff:ff:ff:ff:ff rsc 0 tsc 0 len 16 Jan 12 01:15:06 rogue dbus[1440]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper) Jan 12 01:15:06 rogue dbus[1440]: [system] Successfully activated service 'org.freedesktop.PackageKit' Jan 12 02:07:29 rogue kernel: wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x6 keyix 2 Jan 12 02:07:29 rogue kernel: wlan0: ieee80211_crypto_newkey: no h/w support for cipher AES-CCM, falling back to s/w Jan 12 02:07:29 rogue kernel: wlan0: ieee80211_crypto_setkey: AES-CCM keyix 2 flags 0x136 mac ff:ff:ff:ff:ff:ff rsc 0 tsc 0 len 16 Jan 12 02:15:06 rogue dbus[1440]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper) Jan 12 02:15:06 rogue dbus[1440]: [system] Successfully activated service 'org.freedesktop.PackageKit' Jan 12 03:07:29 rogue kernel: wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x6 keyix 1 Jan 12 03:07:29 rogue kernel: wlan0: ieee80211_crypto_newkey: no h/w support for cipher AES-CCM, falling back to s/w Jan 12 03:07:29 rogue kernel: wlan0: ieee80211_crypto_setkey: AES-CCM keyix 1 flags 0x136 mac ff:ff:ff:ff:ff:ff rsc 0 tsc 0 len 16 Jan 12 03:15:06 rogue dbus[1440]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper) Jan 12 03:15:06 rogue dbus[1440]: [system] Successfully activated service 'org.freedesktop.PackageKit' Jan 12 04:07:29 rogue kernel: wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x6 keyix 2 Jan 12 04:07:29 rogue kernel: wlan0: ieee80211_crypto_newkey: no h/w support for cipher AES-CCM, falling back to s/w Jan 12 04:07:29 rogue kernel: wlan0: ieee80211_crypto_setkey: AES-CCM keyix 2 flags 0x136 mac ff:ff:ff:ff:ff:ff rsc 0 tsc 0 len 16 Jan 12 04:15:06 rogue dbus[1440]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper) Jan 12 04:15:06 rogue dbus[1440]: [system] Successfully activated service 'org.freedesktop.PackageKit' Jan 12 05:07:29 rogue kernel: wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x6 keyix 1 Jan 12 05:07:29 rogue kernel: wlan0: ieee80211_crypto_newkey: no h/w support for cipher AES-CCM, falling back to s/w Jan 12 05:07:29 rogue kernel: wlan0: ieee80211_crypto_setkey: AES-CCM keyix 1 flags 0x136 mac ff:ff:ff:ff:ff:ff rsc 0 tsc 0 len 16 Jan 12 05:15:06 rogue dbus[1440]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper) Jan 12 05:15:06 rogue dbus[1440]: [system] Successfully activated service 'org.freedesktop.PackageKit' Jan 12 06:07:28 rogue kernel: wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x6 keyix 2 Jan 12 06:07:28 rogue kernel: wlan0: ieee80211_crypto_newkey: no h/w support for cipher AES-CCM, falling back to s/w Jan 12 06:07:28 rogue kernel: wlan0: ieee80211_crypto_setkey: AES-CCM keyix 2 flags 0x136 mac ff:ff:ff:ff:ff:ff rsc 0 tsc 0 len 16 Jan 12 06:15:06 rogue dbus[1440]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper) Jan 12 06:15:06 rogue dbus[1440]: [system] Successfully activated service 'org.freedesktop.PackageKit' Jan 12 07:07:28 rogue kernel: wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x6 keyix 1 Jan 12 07:07:28 rogue kernel: wlan0: ieee80211_crypto_newkey: no h/w support for cipher AES-CCM, falling back to s/w Jan 12 07:07:28 rogue kernel: wlan0: ieee80211_crypto_setkey: AES-CCM keyix 1 flags 0x136 mac ff:ff:ff:ff:ff:ff rsc 0 tsc 0 len 16 Jan 12 07:15:06 rogue dbus[1440]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper) Jan 12 07:15:06 rogue dbus[1440]: [system] Successfully activated service 'org.freedesktop.PackageKit' Jan 12 07:17:04 rogue devd: Executing '/etc/rc.d/power_profile 0x00' Jan 12 07:17:05 rogue power_profile: changed to 'economy' Jan 12 08:00:05 rogue devd: Executing '/etc/rc.d/power_profile 0x01' Jan 12 08:00:05 rogue power_profile: changed to 'performance' Jan 12 08:05:05 rogue dbus[1440]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper) Jan 12 08:05:05 rogue dbus[1440]: [system] Successfully activated service 'org.freedesktop.PackageKit' Jan 12 08:07:28 rogue kernel: wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x6 keyix 2 Jan 12 08:07:28 rogue kernel: wlan0: ieee80211_crypto_newkey: no h/w support for cipher AES-CCM, falling back to s/w Jan 12 08:07:28 rogue kernel: wlan0: ieee80211_crypto_setkey: AES-CCM keyix 2 flags 0x136 mac ff:ff:ff:ff:ff:ff rsc 0 tsc 0 len 16 Jan 12 08:15:06 rogue dbus[1440]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper) Jan 12 08:15:06 rogue dbus[1440]: [system] Successfully activated service 'org.freedesktop.PackageKit' Jan 12 08:18:43 rogue kernel: wlan0: [00:26:b8:67:c3:2d] AES-CCM replay detected tid 16 <rsc 353, csc 417, keyix 2 rxkeyix 65535> [rsc increment by one 63 times until rsc = csc] Jan 12 08:18:43 rogue kernel: wlan0: [00:26:b8:67:c3:2d] AES-CCM replay detected tid 16 <rsc 416, csc 417, keyix 2 rxkeyix 65535> Jan 12 09:07:28 rogue kernel: wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x6 keyix 1 Jan 12 09:07:28 rogue kernel: wlan0: ieee80211_crypto_newkey: no h/w support for cipher AES-CCM, falling back to s/w Jan 12 09:07:28 rogue kernel: wlan0: ieee80211_crypto_setkey: AES-CCM keyix 1 flags 0x136 mac ff:ff:ff:ff:ff:ff rsc 0 tsc 0 len 16 Jan 12 09:15:06 rogue dbus[1440]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper) Jan 12 09:15:06 rogue dbus[1440]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?CAN6yY1sPwFz=KgzMzfc_Dgj-VDvRuyUvZNL2X8BNqN6HyVZLtw>