Re: associating -> disconnected

[Bill Moseley <moseley hank org>]

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.

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


-- 
Bill Moseley.
moseley hank org
Sent from my iMutt