[Pkg-utopia-maintainers] Bug#683407: Further info on "deauthenticating by local choice"

Tue Oct 21 14:51:30 UTC 2014

The biggest issue here in my mind is that the correct error is not being 
surfaced.  The second biggest is that it is impossible to configure some 
options necessary for connection to certain networks via network manager 
UI.  From what I can gather, the flow of events is this:

1. network manager starts a wifi connection.  via dbus, it tells the 
wpa_supplicant daemon to connect and passes it the necessary details.  
The connection associates successfully:

Oct 21 10:17:59 localhost kernel: [ 2315.628273] wlan0: authenticate 
with 40:f4:ec:1b:32:bf
Oct 21 10:17:59 localhost kernel: [ 2315.630571] wlan0: send auth to 
40:f4:ec:1b:32:bf (try 1/3)
Oct 21 10:17:59 localhost kernel: [ 2315.632531] wlan0: authenticated
Oct 21 10:17:59 localhost kernel: [ 2315.636175] wlan0: associate with 
40:f4:ec:1b:32:bf (try 1/3)
Oct 21 10:17:59 localhost kernel: [ 2315.639926] wlan0: RX AssocResp 
from 40:f4:ec:1b:32:bf (capab=0x11 status=0 aid=29)
Oct 21 10:17:59 localhost kernel: [ 2315.642209] wlan0: associated
Oct 21 10:17:59 localhost kernel: [ 2315.642297] cfg80211: Calling CRDA 
for country: US
Oct 21 10:17:59 localhost kernel: [ 2315.677160] cfg80211: Regulatory 
domain changed to country: US
Oct 21 10:17:59 localhost kernel: [ 2315.677163] cfg80211:  DFS Master 
region: FCC
Oct 21 10:17:59 localhost kernel: [ 2315.677165] cfg80211: (start_freq - 
end_freq @ bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time)
Oct 21 10:17:59 localhost kernel: [ 2315.677167] cfg80211: (2402000 KHz 
- 2472000 KHz @ 40000 KHz), (N/A, 3000 mBm), (N/A)
Oct 21 10:17:59 localhost kernel: [ 2315.677168] cfg80211: (5170000 KHz 
- 5250000 KHz @ 80000 KHz), (N/A, 1700 mBm), (N/A)
Oct 21 10:17:59 localhost kernel: [ 2315.677170] cfg80211: (5250000 KHz 
- 5330000 KHz @ 80000 KHz), (N/A, 2300 mBm), (0 s)
Oct 21 10:17:59 localhost kernel: [ 2315.677171] cfg80211: (5735000 KHz 
- 5835000 KHz @ 80000 KHz), (N/A, 3000 mBm), (N/A)
Oct 21 10:17:59 localhost kernel: [ 2315.677172] cfg80211: (57240000 KHz 
- 63720000 KHz @ 2160000 KHz), (N/A, 4000 mBm), (N/A)

2. If that connection involves complicated authentication, then it can 
go wrong.  The messages are logged by wpa_supplicant to /var/log/syslog

Oct 21 10:17:59 localhost wpa_supplicant[2406]: wlan0: 
CTRL-EVENT-SSID-REENABLED id=0 ssid="TechSpaceUnionSquareWireless"
Oct 21 10:17:59 localhost wpa_supplicant[2406]: wlan0: SME: Trying to 
authenticate with 40:f4:ec:1b:32:bf (SSID='TechSpaceUnionSquareWireless' 
freq=5180 MHz)
Oct 21 10:17:59 localhost wpa_supplicant[2406]: wlan0: Trying to 
associate with 40:f4:ec:1b:32:bf (SSID='TechSpaceUnionSquareWireless' 
freq=5180 MHz)
Oct 21 10:17:59 localhost wpa_supplicant[2406]: wlan0: Associated with 
40:f4:ec:1b:32:bf
Oct 21 10:17:59 localhost wpa_supplicant[2406]: wlan0: 
CTRL-EVENT-EAP-STARTED EAP authentication started
Oct 21 10:17:59 localhost wpa_supplicant[2406]: wlan0: 
CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=US
Oct 21 10:17:59 localhost wpa_supplicant[2406]: wlan0: 
CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25 -> NAK
Oct 21 10:17:59 localhost wpa_supplicant[2406]: wlan0: 
CTRL-EVENT-EAP-FAILURE EAP authentication failed

In this case, the supplicant proposes a particular method of 
authentication, PEAP (25 - see 
http://www.networksorcery.com/enp/protocol/eap.htm ), but the router 
does not support that.  Presumably this one wants EAP-MSCHAP-V2 or 
something.  Here is problem #2: I can't con

3. wpa_supplicant returns a failure to network manager, which responds 
by closing the connection.  Hence the "disconnected by local choice" 
message that you see in dmesg

Oct 21 10:18:01 localhost wpa_supplicant[2406]: wlan0: Authentication 
with 40:f4:ec:1b:32:bf timed out.
Oct 21 10:18:01 localhost kernel: [ 2317.794239] wlan0: deauthenticating 
from 40:f4:ec:1b:32:bf by local choice (Reason: 3=DEAUTH_LEAVING)
Oct 21 10:18:01 localhost kernel: [ 2317.803176] cfg80211: Calling CRDA 
to update world regulatory domain
Oct 21 10:18:01 localhost kernel: [ 2317.809017] cfg80211: World 
regulatory domain updated:
Oct 21 10:18:01 localhost kernel: [ 2317.809023] cfg80211:  DFS Master 
region: unset

My partial solution, and I say partial because it involves manually 
configuring wpa_supplicant, was to set a couple of extra options;

root at frank:/var/log# cat /etc/wpa_supplicant.conf
network={
     ssid="TechSpaceUnionSquareWireless"
     scan_ssid=1
     key_mgmt=WPA-EAP
     eap=PEAP
     identity="USERNAME"
     password="PASSWORD"
     phase1="peaplabel=0"
     phase2="auth=MSCHAPV2"
}
root at frank:/var/log#

Then, with network manager not actively trying to do anything, kill 
wpa_supplicant, start my own and run dhclient manually:

root at frank:/home/samv# pkill wpa_supplicant; wpa_supplicant -iwlan0 
-c/etc/wpa_supplicant.conf -B -s
root at frank:/home/samv# dhclient wlan0

With this, I get the following logged to syslog:

Oct 21 10:43:11 localhost wpa_supplicant[3296]: wlan0: SME: Trying to 
authenticate with 40:f4:ec:1b:32:bf (SSID='TechSpaceUnionSquareWireless' 
freq=5180 MHz)
Oct 21 10:43:11 localhost wpa_supplicant[3296]: wlan0: Trying to 
associate with 40:f4:ec:1b:32:bf (SSID='TechSpaceUnionSquareWireless' 
freq=5180 MHz)
Oct 21 10:43:11 localhost wpa_supplicant[3296]: wlan0: Associated with 
40:f4:ec:1b:32:bf
Oct 21 10:43:11 localhost wpa_supplicant[3296]: wlan0: 
CTRL-EVENT-EAP-STARTED EAP authentication started
Oct 21 10:43:11 localhost wpa_supplicant[3296]: wlan0: 
CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=US
Oct 21 10:43:11 localhost wpa_supplicant[3296]: wlan0: 
CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25
Oct 21 10:43:11 localhost wpa_supplicant[3296]: wlan0: 
CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
Oct 21 10:43:11 localhost wpa_supplicant[3296]: wlan0: 
CTRL-EVENT-EAP-PEER-CERT depth=0 
subject='/O=Unknown/OU=Unknown/CN=acs1-av-campus'
Oct 21 10:43:11 localhost wpa_supplicant[3296]: wlan0: 
CTRL-EVENT-EAP-PEER-CERT depth=0 
subject='/O=Unknown/OU=Unknown/CN=acs1-av-campus'
Oct 21 10:43:12 localhost wpa_supplicant[3296]: EAP-MSCHAPV2: 
Authentication succeeded
Oct 21 10:43:12 localhost wpa_supplicant[3296]: wlan0: 
CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Oct 21 10:43:12 localhost wpa_supplicant[3296]: wlan0: WPA: Key 
negotiation completed with 40:f4:ec:1b:32:bf [PTK=CCMP GTK=CCMP]
Oct 21 10:43:12 localhost wpa_supplicant[3296]: wlan0: 
CTRL-EVENT-CONNECTED - Connection to 40:f4:ec:1b:32:bf completed [id=0 
id_str=]

I'm running a fresh (<1week) Debian testing install, currently with the 
legacy Gnome desktop.

HTH!
Sam