IWN hangs periodically on 10.0RC3

Sat Jan 11 05:51:42 UTC 2014

On Fri, Jan 10, 2014 at 9:37 AM, Adrian Chadd <adrian at freebsd.org> wrote:

> .. when you see it hang, does anything get logged in dmesg (eg a
> firmware panic) ?
>
> Try recompiling your kernel with:
>
> IEEE80211_DEBUG
> IWN_DEBUG
>
> That way it can be debugged :)
>
> The first thing I'd check is whether there's more fun races going on
> in the crypto code - try wlandebug +crypto .
>
>
> -a
>

I just sent a message about issues I am seeing with my IWN to wireless at .
Then I saw these responses. Sorry.

As far as logs go, I wee a number if cases of the following sequence:
Jan  1 18:00:12 rogue dbus[1451]: [system] Activating service
name='org.freedesktop.PackageKit' (using servicehelper)
Jan  1 18:00:12 rogue dbus[1451]: [system] Successfully activated service
'org.freedesktop.PackageKit'
Jan  1 18:28:56 rogue wpa_supplicant[620]: wlan0: CTRL-EVENT-DISCONNECTED
bssid=00:26:b8:67:c3:2d reason=0
Jan  1 18:28:56 rogue kernel: wlan0: link state changed to DOWN
Jan  1 18:28:59 rogue wpa_supplicant[620]: wlan0: Trying to associate with
00:26:b8:67:c3:2d (SSID='babcom' freq=2437 MHz)
Jan  1 18:28:59 rogue wpa_supplicant[620]: wlan0: Associated with
00:26:b8:67:c3:2d
Jan  1 18:28:59 rogue kernel: wlan0: link state changed to UP
Jan  1 18:28:59 rogue dhclient[652]: send_packet: No buffer space available
Jan  1 18:28:59 rogue devd: Executing '/etc/rc.d/dhclient quietstart wlan0'
Jan  1 18:28:59 rogue wpa_supplicant[620]: wlan0: WPA: Key negotiation
completed with 00:26:b8:67:c3:2d [PTK=CCMP GTK=CCMP]
Jan  1 18:28:59 rogue wpa_supplicant[620]: wlan0: CTRL-EVENT-CONNECTED -
Connection to 00:26:b8:67:c3:2d completed [id=1 id_str=]
Jan  1 18:29:02 rogue dhclient: New IP Address (wlan0): 192.168.1.5
Jan  1 18:29:02 rogue dhclient: New Subnet Mask (wlan0): 255.255.255.0
Jan  1 18:29:02 rogue dhclient: New Broadcast Address (wlan0): 192.168.1.255
Jan  1 18:29:02 rogue dhclient: New Routers (wlan0): 192.168.1.1

So it seems that the bounce is happening fairly often, but the system
usually recovers. It seems to be pretty consistently 2-3 time4s a day.
Note that the dbus messages about packagekit always immediately precede the
link going down.

Every tthe or four of these fail to recover:
Jan  3 14:09:05 rogue kernel: wlan0: link state changed to DOWN
Jan  3 14:09:56 rogue ntpd[1303]: sendto(198.129.254.218) (fd=25): Network
is down
Jan  3 14:10:15 rogue ntpd[1303]: sendto(208.79.18.86) (fd=25): Network is
down
Jan  3 14:10:29 rogue ntpd[1303]: sendto(198.124.252.90) (fd=25): Network
is down
Jan  3 14:10:49 rogue ntpd[1303]: sendto(198.55.111.5) (fd=25): Network is
down
Jan  3 14:11:00 rogue ntpd[1303]: sendto(192.95.38.104) (fd=25): Network is
down
Jan  3 14:14:02 rogue ntpd[1303]: sendto(198.129.252.38) (fd=25): Network
is down
Jan  3 14:14:12 rogue wpa_supplicant[620]: ioctl[SIOCS80211, op=26, val=0,
arg_len=0]: Operation not supported
Jan  3 14:14:12 rogue wpa_supplicant[620]: ioctl[SIOCS80211, op=26, val=0,
arg_len=0]: Operation not supported
Jan  3 14:14:12 rogue wpa_supplicant[620]: wlan0: CTRL-EVENT-TERMINATING
Jan  3 14:14:12 rogue dhclient[652]: connection closed
Jan  3 14:14:12 rogue dhclient[652]: exiting.
Jan  3 14:14:12 rogue wpa_supplicant[67153]: Successfully initialized
wpa_supplicant
Jan  3 14:14:16 rogue wpa_supplicant[67154]: wlan0: Trying to associate
with 00:26:b8:67:c3:2d (SSID='babcom' freq=2437 MHz)
Jan  3 14:14:16 rogue wpa_supplicant[67154]: wlan0: Associated with
00:26:b8:67:c3:2d
Jan  3 14:14:16 rogue kernel: wlan0: link state changed to UP
Jan  3 14:14:16 rogue devd: Executing '/etc/rc.d/dhclient quietstart wlan0'
Jan  3 14:14:16 rogue dhclient[67191]: send_packet: No buffer space
available
Jan  3 14:14:17 rogue wpa_supplicant[67154]: wlan0: WPA: Key negotiation
completed with 00:26:b8:67:c3:2d [PTK=CCMP GTK=CCMP]
Jan  3 14:14:17 rogue wpa_supplicant[67154]: wlan0: CTRL-EVENT-CONNECTED -
Connection to 00:26:b8:67:c3:2d completed [id=1 id_str=]
Jan  3 14:14:18 rogue dhclient: New IP Address (wlan0): 192.168.1.5
Jan  3 14:14:18 rogue dhclient: New Subnet Mask (wlan0): 255.255.255.0
Jan  3 14:14:18 rogue dhclient: New Broadcast Address (wlan0): 192.168.1.255
Jan  3 14:14:18 rogue dhclient: New Routers (wlan0): 192.168.1.1

The restart took place when I restarted the interface about 5 minutes after
it went down and, as you can see, it came up normally. I'll admit that I am
completely baffled by the dbus/packagekit tie-in as I can't see what
packagekit would do to touch the network.

I'll be building a new kernel with debug shortly.

In my other message (to wireless) I also mentioned the (possibly unrelated)
issue of poor performance and and periodic sub-second connectivity drops.
-- 
R. Kevin Oberman, Network Engineer, Retired
E-mail: rkoberman at gmail.com