Re: associating -> disconnected

[Dan Williams <dcbw redhat com>]

On Sun, 2009-06-14 at 12:43 -0700, Bill Moseley wrote:
> On Sun, Jun 14, 2009 at 07:37:49AM -0700, Bill Moseley wrote:
> > I recently upgraded from Ubuntu 8.10 to 9.04 a Thinkpad with an
> > Atheros AR5418 using the ath9k module.
> 
> Perhaps related -- another problem is I seem to have periodic
> disconnects now, where before upgrading the wireless was rock solid.
> I have a pretty new MacBook sitting next to me without any wireless
> issues at all -- so it's not something new or environmental with the
> AP, that I'm aware of.

If the periodic disconnects are around every 2 minutes like clockwork,
you'll want to get your distro provider to apply this commit to their
kernel:

commit a9a6ffffd05f97e6acbdeafc595e269855829751
Author: Kalle Valo <kalle valo nokia com>
Date:   Wed Mar 18 14:06:44 2009 +0200

    mac80211: don't drop nullfunc frames during software scan

That bug has existed since the beginning of the mac80211 stack and is
probably responsible for a number of the disconnect issues that users
are seeing, since the AP may be force-disconnecting the card after a few
seconds in this case.

Dan

> I apologize for my panic. I'm about to travel for work and will have
> to depend on the wireless.
> 
> I wish I had more experience debugging.  All I have is the syslog
> output.  Probably more than is needed, but it's what I have.
> 
> For some reason it's reporting first "deauthenticated" and then
> disconnects.  I was first suspecting that a dhcp lease renewal was
> triggering the disconnect, but that doesn't seem like it now.
> 
> Any ideas?  Please?
> 
> Thanks,
> 
> 
> Jun 14 11:55:52 tiger kernel: [ 2645.836518] wlan0: deauthenticated
> Jun 14 11:55:52 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> disconnected 
> Jun 14 11:55:52 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning 
> Jun 14 11:55:53 tiger kernel: [ 2646.836110] wlan0: direct probe to AP 00:09:5b:b3:c7:18 try 1
> Jun 14 11:55:53 tiger kernel: [ 2646.838886] wlan0 direct probe responded
> Jun 14 11:55:53 tiger kernel: [ 2646.838892] wlan0: authenticate with AP 00:09:5b:b3:c7:18
> Jun 14 11:55:53 tiger kernel: [ 2646.840802] wlan0: authenticated
> Jun 14 11:55:53 tiger kernel: [ 2646.840808] wlan0: associate with AP 00:09:5b:b3:c7:18
> Jun 14 11:55:53 tiger kernel: [ 2646.843030] wlan0: RX ReassocResp from 00:09:5b:b3:c7:18 (capab=0x431 status=0 aid=1)
> Jun 14 11:55:53 tiger kernel: [ 2646.843034] wlan0: associated
> Jun 14 11:55:53 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> 4-way handshake 
> Jun 14 11:55:53 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  4-way handshake -> associated 
> Jun 14 11:55:56 tiger kernel: [ 2649.931243] wlan0: deauthenticated
> Jun 14 11:55:56 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> disconnected 
> Jun 14 11:55:56 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning 
> Jun 14 11:55:57 tiger kernel: [ 2650.928060] wlan0: direct probe to AP 00:09:5b:b3:c7:18 try 1
> Jun 14 11:55:57 tiger kernel: [ 2650.930801] wlan0 direct probe responded
> Jun 14 11:55:57 tiger kernel: [ 2650.930807] wlan0: authenticate with AP 00:09:5b:b3:c7:18
> Jun 14 11:55:57 tiger kernel: [ 2650.932895] wlan0: authenticated
> Jun 14 11:55:57 tiger kernel: [ 2650.932901] wlan0: associate with AP 00:09:5b:b3:c7:18
> Jun 14 11:55:57 tiger kernel: [ 2650.934904] wlan0: RX ReassocResp from 00:09:5b:b3:c7:18 (capab=0x431 status=0 aid=1)
> Jun 14 11:55:57 tiger kernel: [ 2650.934908] wlan0: associated
> Jun 14 11:55:57 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> 4-way handshake 
> Jun 14 11:55:57 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  4-way handshake -> associated 
> Jun 14 11:55:59 tiger NetworkManager: <debug> [1245005759.000981] periodic_update(): Roamed from BSSID 00:09:5B:B3:C7:18 (hanklan2) to (none) ((none)) 
> Jun 14 11:56:00 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> disconnected 
> Jun 14 11:56:00 tiger kernel: [ 2654.134300] wlan0: deauthenticated
> Jun 14 11:56:00 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning 
> Jun 14 11:56:01 tiger kernel: [ 2655.132083] wlan0: direct probe to AP 00:09:5b:b3:c7:18 try 1
> Jun 14 11:56:01 tiger kernel: [ 2655.134876] wlan0 direct probe responded
> Jun 14 11:56:01 tiger kernel: [ 2655.134882] wlan0: authenticate with AP 00:09:5b:b3:c7:18
> Jun 14 11:56:01 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> 4-way handshake 
> Jun 14 11:56:01 tiger kernel: [ 2655.136869] wlan0: authenticated
> Jun 14 11:56:01 tiger kernel: [ 2655.136876] wlan0: associate with AP 00:09:5b:b3:c7:18
> Jun 14 11:56:01 tiger kernel: [ 2655.138897] wlan0: RX ReassocResp from 00:09:5b:b3:c7:18 (capab=0x431 status=0 aid=1)
> Jun 14 11:56:01 tiger kernel: [ 2655.138901] wlan0: associated
> Jun 14 11:56:01 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  4-way handshake -> associated 
> Jun 14 11:56:04 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> disconnected 
> Jun 14 11:56:04 tiger kernel: [ 2658.257131] wlan0: deauthenticated
> Jun 14 11:56:05 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning 
> Jun 14 11:56:05 tiger kernel: [ 2659.256080] wlan0: direct probe to AP 00:09:5b:b3:c7:18 try 1
> Jun 14 11:56:05 tiger kernel: [ 2659.258859] wlan0 direct probe responded
> Jun 14 11:56:05 tiger kernel: [ 2659.258865] wlan0: authenticate with AP 00:09:5b:b3:c7:18
> Jun 14 11:56:05 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> 4-way handshake 
> Jun 14 11:56:05 tiger kernel: [ 2659.260792] wlan0: authenticated
> Jun 14 11:56:05 tiger kernel: [ 2659.260798] wlan0: associate with AP 00:09:5b:b3:c7:18
> Jun 14 11:56:05 tiger kernel: [ 2659.263038] wlan0: RX ReassocResp from 00:09:5b:b3:c7:18 (capab=0x431 status=0 aid=1)
> Jun 14 11:56:05 tiger kernel: [ 2659.263042] wlan0: associated
> Jun 14 11:56:06 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  4-way handshake -> associated 
> Jun 14 11:56:08 tiger NetworkManager: <info>  (wlan0): device state change: 8 -> 3 
> Jun 14 11:56:08 tiger NetworkManager: <info>  (wlan0): deactivating device (reason: 11). 
> Jun 14 11:56:08 tiger NetworkManager: <info>  wlan0: canceled DHCP transaction, dhcp client pid 5970 
> Jun 14 11:56:08 tiger NetworkManager: <info>  Clearing nscd hosts cache. 
> Jun 14 11:56:08 tiger kernel: [ 2661.510150] wlan0: disassociating by local choice (reason=3)
> Jun 14 11:56:08 tiger NetworkManager: <WARN>  check_one_route(): (wlan0) error -34 returned from rtnl_route_del(): Sucess  
> Jun 14 11:56:08 tiger avahi-daemon[3146]: Withdrawing address record for 192.168.1.19 on wlan0.
> Jun 14 11:56:08 tiger avahi-daemon[3146]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.19.
> Jun 14 11:56:08 tiger avahi-daemon[3146]: Interface wlan0.IPv4 no longer relevant for mDNS.
> Jun 14 11:56:08 tiger NetworkManager: <info>  Activation (wlan0) starting connection 'Auto hanklan2' 
> Jun 14 11:56:08 tiger NetworkManager: <info>  (wlan0): device state change: 3 -> 4 
> Jun 14 11:56:08 tiger NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... 
> Jun 14 11:56:08 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> disconnected 
> Jun 14 11:56:08 tiger NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started... 
> Jun 14 11:56:08 tiger NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... 
> Jun 14 11:56:08 tiger NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. 
> Jun 14 11:56:08 tiger NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting... 
> Jun 14 11:56:08 tiger NetworkManager: <info>  (wlan0): device state change: 4 -> 5 
> Jun 14 11:56:08 tiger NetworkManager: <info>  Activation (wlan0/wireless): connection 'Auto hanklan2' has security, and secrets exist.  No new secrets needed. 
> Jun 14 11:56:08 tiger NetworkManager: <info>  Config: added 'ssid' value 'hanklan2' 
> Jun 14 11:56:08 tiger NetworkManager: <info>  Config: added 'scan_ssid' value '1' 
> Jun 14 11:56:08 tiger NetworkManager: <info>  Config: added 'key_mgmt' value 'WPA-PSK' 
> Jun 14 11:56:08 tiger NetworkManager: <info>  Config: added 'psk' value '<omitted>' 
> Jun 14 11:56:08 tiger NetworkManager: nm_setting_802_1x_get_pkcs11_engine_path: assertion `NM_IS_SETTING_802_1X (setting)' failed
> Jun 14 11:56:08 tiger NetworkManager: nm_setting_802_1x_get_pkcs11_module_path: assertion `NM_IS_SETTING_802_1X (setting)' failed
> Jun 14 11:56:08 tiger NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete. 
> Jun 14 11:56:08 tiger NetworkManager: <info>  Config: set interface ap_scan to 1 
> Jun 14 11:56:08 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning 
> Jun 14 11:56:08 tiger postfix/master[2829]: reload configuration /etc/postfix
> Jun 14 11:56:08 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> associating 
> Jun 14 11:56:11 tiger kernel: [ 2664.914981] wlan0: authenticate with AP 00:09:5b:b3:c7:18
> Jun 14 11:56:11 tiger kernel: [ 2664.916432] wlan0: authenticated
> Jun 14 11:56:11 tiger kernel: [ 2664.916439] wlan0: associate with AP 00:09:5b:b3:c7:18
> Jun 14 11:56:11 tiger kernel: [ 2664.918633] wlan0: RX AssocResp from 00:09:5b:b3:c7:18 (capab=0x431 status=0 aid=1)
> Jun 14 11:56:11 tiger kernel: [ 2664.918638] wlan0: associated
> Jun 14 11:56:11 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> associated 
> Jun 14 11:56:11 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> 4-way handshake 
> Jun 14 11:56:11 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  4-way handshake -> group handshake 
> Jun 14 11:56:11 tiger NetworkManager: <info>  (wlan0): supplicant connection state:  group handshake -> completed 
> Jun 14 11:56:11 tiger NetworkManager: <info>  Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'hanklan2'. 
> Jun 14 11:56:11 tiger NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled. 
> Jun 14 11:56:11 tiger NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) started... 
> Jun 14 11:56:11 tiger NetworkManager: <info>  (wlan0): device state change: 5 -> 7 
> Jun 14 11:56:11 tiger NetworkManager: <info>  Activation (wlan0) Beginning DHCP transaction. 
> Jun 14 11:56:11 tiger NetworkManager: <info>  dhclient started with pid 6094 
> Jun 14 11:56:11 tiger NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete. 
> Jun 14 11:56:11 tiger dhclient: Internet Systems Consortium DHCP Client V3.1.1
> Jun 14 11:56:11 tiger dhclient: Copyright 2004-2008 Internet Systems Consortium.
> Jun 14 11:56:11 tiger dhclient: All rights reserved.
> Jun 14 11:56:11 tiger dhclient: For info, please visit http://www.isc.org/sw/dhcp/
> Jun 14 11:56:11 tiger dhclient: 
> Jun 14 11:56:11 tiger dhclient: wmaster0: unknown hardware address type 801
> Jun 14 11:56:11 tiger NetworkManager: <info>  DHCP: device wlan0 state changed normal exit -> preinit 
> Jun 14 11:56:11 tiger dhclient: wmaster0: unknown hardware address type 801
> Jun 14 11:56:11 tiger dhclient: Listening on LPF/wlan0/00:19:7e:57:65:5d
> Jun 14 11:56:11 tiger dhclient: Sending on   LPF/wlan0/00:19:7e:57:65:5d
> Jun 14 11:56:11 tiger dhclient: Sending on   Socket/fallback
> Jun 14 11:56:11 tiger dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 5
> Jun 14 11:56:16 tiger dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 5
> Jun 14 11:56:16 tiger dhclient: DHCPOFFER of 192.168.1.19 from 192.168.1.1
> Jun 14 11:56:16 tiger dhclient: DHCPREQUEST of 192.168.1.19 on wlan0 to 255.255.255.255 port 67
> Jun 14 11:56:16 tiger dhclient: DHCPACK of 192.168.1.19 from 192.168.1.1
> Jun 14 11:56:16 tiger NetworkManager: <info>  DHCP: device wlan0 state changed preinit -> bound 
> Jun 14 11:56:16 tiger NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) scheduled... 
> Jun 14 11:56:16 tiger NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) started... 
> Jun 14 11:56:16 tiger NetworkManager: <info>    address 192.168.1.19 
> Jun 14 11:56:16 tiger NetworkManager: <info>    prefix 24 (255.255.255.0) 
> Jun 14 11:56:16 tiger NetworkManager: <info>    gateway 192.168.1.1 
> Jun 14 11:56:16 tiger NetworkManager: <info>    nameserver '192.168.1.1' 
> Jun 14 11:56:16 tiger NetworkManager: <info>    domain name 'hank.org' 
> Jun 14 11:56:16 tiger NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) scheduled... 
> Jun 14 11:56:16 tiger NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) complete. 
> Jun 14 11:56:16 tiger NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started... 
> Jun 14 11:56:16 tiger avahi-daemon[3146]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.19.
> Jun 14 11:56:16 tiger avahi-daemon[3146]: New relevant interface wlan0.IPv4 for mDNS.
> Jun 14 11:56:16 tiger avahi-daemon[3146]: Registering new address record for 192.168.1.19 on wlan0.IPv4.
> Jun 14 11:56:16 tiger dhclient: bound to 192.168.1.19 -- renewal in 556 seconds.
> Jun 14 11:56:17 tiger NetworkManager: <info>  Clearing nscd hosts cache. 
> Jun 14 11:56:17 tiger NetworkManager: <info>  (wlan0): device state change: 7 -> 8 
> Jun 14 11:56:17 tiger NetworkManager: <info>  Clearing nscd hosts cache. 
> Jun 14 11:56:17 tiger NetworkManager: <info>  Policy set 'Auto hanklan2' (wlan0) as default for routing and DNS. 
> Jun 14 11:56:17 tiger NetworkManager: <info>  Activation (wlan0) successful, device activated. 
> Jun 14 11:56:17 tiger NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) complete. 
> Jun 14 11:56:17 tiger postfix/master[2829]: reload configuration /etc/postfix
> Jun 14 11:56:17 tiger ntpdate[6156]: adjust time server 91.189.94.4 offset -0.000529 sec
> 
>