Public bug reported:
Ever since I upgraded from vivid to wily on my laptop, I'm running into
problems when connecting to my home WPA2 enterprise network.
Typically the first connection immediately after the driver is loaded
works as expected, however any further reconnection and the occasional
roaming between APs cause wpasupplicant to freeze entirely requiring me
to kill it and most often also reload my wireless driver to get things
working again.
## A failed (hanging) association looks like:
Sep 30 23:31:06 castiana NetworkManager[25815]: <info> (wlan0): Activation:
(wifi) connection 'stgraber.net-secure' has security, and secrets exist. No
new secrets needed.
Sep 30 23:31:06 castiana NetworkManager[25815]: <info> Config: added 'ssid'
value 'stgraber.net-secure'
Sep 30 23:31:06 castiana NetworkManager[25815]: <info> Config: added
'scan_ssid' value '1'
Sep 30 23:31:06 castiana NetworkManager[25815]: <info> Config: added
'key_mgmt' value 'WPA-EAP'
Sep 30 23:31:06 castiana NetworkManager[25815]: <info> Config: added 'eap'
value 'TLS'
Sep 30 23:31:06 castiana NetworkManager[25815]: <info> Config: added
'fragment_size' value '1300'
Sep 30 23:31:06 castiana NetworkManager[25815]: <info> Config: added 'ca_cert'
value '/home/stgraber/data/certs/stgraber-radius/ca.crt'
Sep 30 23:31:06 castiana NetworkManager[25815]: <info> Config: added
'private_key' value '/home/stgraber/data/certs/stgraber-radius/castiana.p12'
Sep 30 23:31:06 castiana NetworkManager[25815]: <info> Config: added
'private_key_passwd' value '<omitted>'
Sep 30 23:31:06 castiana NetworkManager[25815]: <info> Config: added
'identity' value 'castiana'
Sep 30 23:31:06 castiana NetworkManager[25815]: <info> Config: added 'bgscan'
value 'simple:30:-65:300'
Sep 30 23:31:06 castiana NetworkManager[25815]: <info> Config: added
'proactive_key_caching' value '1'
Sep 30 23:31:06 castiana NetworkManager[25815]: <warn> Connection disconnected
(reason -3)
Sep 30 23:31:06 castiana NetworkManager[25815]: <info> (wlan0): supplicant
interface state: associated -> disconnected
Sep 30 23:31:06 castiana NetworkManager[25815]: <warn> Failed to
GDBus.Error:fi.w1.wpa_supplicant1.NotConnected: This interface is not
connected: disconnect.
Sep 30 23:31:06 castiana NetworkManager[25815]: <warn> Failed to
GDBus.Error:fi.w1.wpa_supplicant1.NotConnected: This interface is not
connected: disconnect.
Sep 30 23:31:06 castiana NetworkManager[25815]: <info> Config: set interface
ap_scan to 1
Sep 30 23:31:06 castiana NetworkManager[25815]: <info> (wlan0): supplicant
interface state: disconnected -> scanning
Sep 30 23:31:07 castiana wpa_supplicant[25653]: wlan0: SME: Trying to
authenticate with 24:a4:3c:c8:69:03 (SSID='stgraber.net-secure' freq=2412 MHz)
Sep 30 23:31:07 castiana kernel: [102903.079940] wlan0: authenticate with
24:a4:3c:c8:69:03
Sep 30 23:31:07 castiana kernel: [102903.085128] wlan0: send auth to
24:a4:3c:c8:69:03 (try 1/3)
Sep 30 23:31:07 castiana wpa_supplicant[25653]: wlan0: Trying to associate with
24:a4:3c:c8:69:03 (SSID='stgraber.net-secure' freq=2412 MHz)
Sep 30 23:31:07 castiana NetworkManager[25815]: <info> (wlan0): supplicant
interface state: scanning -> authenticating
Sep 30 23:31:07 castiana kernel: [102903.086942] wlan0: authenticated
Sep 30 23:31:07 castiana kernel: [102903.090103] wlan0: associate with
24:a4:3c:c8:69:03 (try 1/3)
Sep 30 23:31:07 castiana NetworkManager[25815]: <info> (wlan0): supplicant
interface state: authenticating -> associating
Sep 30 23:31:07 castiana kernel: [102903.101962] wlan0: RX AssocResp from
24:a4:3c:c8:69:03 (capab=0x411 status=0 aid=1)
Sep 30 23:31:07 castiana wpa_supplicant[25653]: wlan0: Associated with
24:a4:3c:c8:69:03
Sep 30 23:31:07 castiana kernel: [102903.103701] wlan0: associated
Sep 30 23:31:07 castiana NetworkManager[25815]: <info> (wlan0): supplicant
interface state: associating -> associated
Sep 30 23:31:07 castiana wpa_supplicant[25653]: wlan0: CTRL-EVENT-EAP-STARTED
EAP authentication started
Sep 30 23:31:07 castiana wpa_supplicant[25653]: wlan0:
CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=13
Sep 30 23:31:07 castiana wpa_supplicant[25653]: wlan0: CTRL-EVENT-EAP-METHOD
EAP vendor 0 method 13 (TLS) selected
Sep 30 23:31:07 castiana wpa_supplicant[25653]: wlan0: CTRL-EVENT-EAP-PEER-CERT
depth=2 subject='/C=CA/ST=Quebec/L=Montreal/O=stgraber.net/OU=Internal
Infrastructure/CN=stgraber.net Root CA/name=stgraber.net Infrastructure Root
CA/emailAddress=stgra...@stgraber.org'
hash=87b9750baadddac7f05164d7fde3a0eb3d3efe0c948b430a3ecd093c629956e9
Sep 30 23:31:07 castiana wpa_supplicant[25653]: wlan0: CTRL-EVENT-EAP-PEER-CERT
depth=1 subject='/C=CA/ST=Quebec/L=Montreal/O=stgraber.net/OU=Internal
Infrastructure/CN=radius/name=stgraber.net Infrastructure Root
CA/emailAddress=stgra...@stgraber.org'
hash=1fc5a4237c625f445a8eaf3794d4ee475d47dd7be31301a0215ee9701dee46e0
Sep 30 23:31:07 castiana wpa_supplicant[25653]: wlan0: CTRL-EVENT-EAP-PEER-CERT
depth=0 subject='/C=CA/ST=Quebec/L=Montreal/O=stgraber.net/OU=Internal
Infrastructure/CN=freeradius01/name=stgraber.net Internal Infrastructure Radius
CA/emailAddress=stgra...@stgraber.org'
hash=9fa224ec6e74510d80257cc4dd43e660e0015642959b2fdea8995cbc71c6abf8
Sep 30 23:31:07 castiana wpa_supplicant[25653]: l2_packet_send - sendto:
Message too long
Sep 30 23:31:28 castiana wpa_supplicant[25653]: message repeated 3 times: [
l2_packet_send - sendto: Message too long]
Sep 30 23:31:31 castiana NetworkManager[25815]: <warn> (wlan0): Activation:
(wifi) association took too long
Sep 30 23:31:31 castiana NetworkManager[25815]: <info> (wlan0): device state
change: config -> failed (reason 'no-secrets') [50 120 7]
Sep 30 23:31:31 castiana NetworkManager[25815]: <info> NetworkManager state is
now CONNECTED_LOCAL
Sep 30 23:31:31 castiana kernel: [102927.404913] wlan0: deauthenticating from
24:a4:3c:c8:69:03 by local choice (Reason: 3=DEAUTH_LEAVING)
Sep 30 23:31:31 castiana NetworkManager[25815]: <warn> (wlan0): Activation:
failed for connection 'stgraber.net-secure'
Sep 30 23:31:31 castiana NetworkManager[25815]: <info> (wlan0): device state
change: failed -> disconnected (reason 'none') [120 30 0]
Sep 30 23:31:31 castiana wpa_supplicant[25653]: wlan0: CTRL-EVENT-DISCONNECTED
bssid=24:a4:3c:c8:69:03 reason=3 locally_generated=1
Sep 30 23:31:31 castiana NetworkManager[25815]: <info> Device 'wlan0' has no
connection; scheduling activate_check in 0 seconds.
Sep 30 23:31:31 castiana NetworkManager[25815]: <warn> Connection disconnected
(reason -3)
Sep 30 23:31:31 castiana NetworkManager[25815]: <info> (wlan0): supplicant
interface state: associated -> disconnected
Sep 30 23:31:31 castiana kernel: [102927.422121] IPv6: ADDRCONF(NETDEV_UP):
wlan0: link is not ready
Sep 30 23:31:31 castiana NetworkManager[25815]: <warn> Failed to
GDBus.Error:fi.w1.wpa_supplicant1.NotConnected: This interface is not
connected: disconnect.
## A successful association (as seen after restart wpasupplicant) looks like:
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> (wlan0): Activation:
(wifi) connection 'stgraber.net-secure' has security, and secrets exist. No
new secrets needed.
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> Config: added 'ssid'
value 'stgraber.net-secure'
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> Config: added
'scan_ssid' value '1'
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> Config: added 'key_mgmt'
value 'WPA-EAP'
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> Config: added 'eap'
value 'TLS'
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> Config: added
'fragment_size' value '1300'
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> Config: added 'ca_cert'
value '/home/stgraber/data/certs/stgraber-radius/ca.crt'
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> Config: added
'private_key' value '/home/stgraber/data/certs/stgraber-radius/castiana.p12'
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> Config: added
'private_key_passwd' value '<omitted>'
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> Config: added 'identity'
value 'castiana'
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> Config: added 'bgscan'
value 'simple:30:-65:300'
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> Config: added
'proactive_key_caching' value '1'
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> Config: set interface
ap_scan to 1
Oct 1 00:21:49 castiana kernel: [105943.745716] wlan0: authenticate with
24:a4:3c:c8:69:13
Oct 1 00:21:49 castiana wpa_supplicant[9608]: wlan0: SME: Trying to
authenticate with 24:a4:3c:c8:69:13 (SSID='stgraber.net-secure' freq=5805 MHz)
Oct 1 00:21:49 castiana kernel: [105943.756236] wlan0: send auth to
24:a4:3c:c8:69:13 (try 1/3)
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> (wlan0): supplicant
interface state: inactive -> authenticating
Oct 1 00:21:49 castiana wpa_supplicant[9608]: wlan0: Trying to associate with
24:a4:3c:c8:69:13 (SSID='stgraber.net-secure' freq=5805 MHz)
Oct 1 00:21:49 castiana kernel: [105943.842803] wlan0: authenticated
Oct 1 00:21:49 castiana kernel: [105943.845837] wlan0: associate with
24:a4:3c:c8:69:13 (try 1/3)
Oct 1 00:21:49 castiana wpa_supplicant[9608]: wlan0: Associated with
24:a4:3c:c8:69:13
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> (wlan0): supplicant
interface state: authenticating -> associating
Oct 1 00:21:49 castiana wpa_supplicant[9608]: wlan0: CTRL-EVENT-EAP-STARTED
EAP authentication started
Oct 1 00:21:49 castiana kernel: [105943.846886] wlan0: RX AssocResp from
24:a4:3c:c8:69:13 (capab=0x11 status=0 aid=1)
Oct 1 00:21:49 castiana kernel: [105943.848105] wlan0: associated
Oct 1 00:21:49 castiana kernel: [105943.848134] IPv6: ADDRCONF(NETDEV_CHANGE):
wlan0: link becomes ready
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> (wlan0): supplicant
interface state: associating -> associated
Oct 1 00:21:49 castiana wpa_supplicant[9608]: wlan0:
CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=13
Oct 1 00:21:49 castiana wpa_supplicant[9608]: wlan0: CTRL-EVENT-EAP-METHOD EAP
vendor 0 method 13 (TLS) selected
Oct 1 00:21:49 castiana wpa_supplicant[9608]: wlan0: CTRL-EVENT-EAP-PEER-CERT
depth=2 subject='/C=CA/ST=Quebec/L=Montreal/O=stgraber.net/OU=Internal
Infrastructure/CN=stgraber.net Root CA/name=stgraber.net Infrastructure Root
CA/emailAddress=stgra...@stgraber.org'
hash=87b9750baadddac7f05164d7fde3a0eb3d3efe0c948b430a3ecd093c629956e9
Oct 1 00:21:49 castiana wpa_supplicant[9608]: wlan0: CTRL-EVENT-EAP-PEER-CERT
depth=1 subject='/C=CA/ST=Quebec/L=Montreal/O=stgraber.net/OU=Internal
Infrastructure/CN=radius/name=stgraber.net Infrastructure Root
CA/emailAddress=stgra...@stgraber.org'
hash=1fc5a4237c625f445a8eaf3794d4ee475d47dd7be31301a0215ee9701dee46e0
Oct 1 00:21:49 castiana wpa_supplicant[9608]: wlan0: CTRL-EVENT-EAP-PEER-CERT
depth=0 subject='/C=CA/ST=Quebec/L=Montreal/O=stgraber.net/OU=Internal
Infrastructure/CN=freeradius01/name=stgraber.net Internal Infrastructure Radius
CA/emailAddress=stgra...@stgraber.org'
hash=9fa224ec6e74510d80257cc4dd43e660e0015642959b2fdea8995cbc71c6abf8
Oct 1 00:21:49 castiana wpa_supplicant[9608]: wlan0: CTRL-EVENT-EAP-SUCCESS
EAP authentication completed successfully
Oct 1 00:21:49 castiana wpa_supplicant[9608]: nl80211: Unexpected encryption
algorithm 5
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> (wlan0): supplicant
interface state: associated -> 4-way handshake
Oct 1 00:21:49 castiana wpa_supplicant[9608]: wlan0: WPA: Key negotiation
completed with 24:a4:3c:c8:69:13 [PTK=CCMP GTK=CCMP]
Oct 1 00:21:49 castiana wpa_supplicant[9608]: wlan0: CTRL-EVENT-CONNECTED -
Connection to 24:a4:3c:c8:69:13 completed [id=0 id_str=]
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> (wlan0): supplicant
interface state: 4-way handshake -> completed
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> (wlan0): Activation:
(wifi) Stage 2 of 5 (Device Configure) successful. Connected to wireless
network 'stgraber.net-secure'.
Oct 1 00:21:49 castiana NetworkManager[9615]: <info> (wlan0): device state
change: config -> ip-config (reason 'none') [50 70 0]
Oct 1 00:21:49 castiana gnome-session[1907]: (deja-dup-monitor:5926):
GLib-CRITICAL **: Source ID 1789 was not found when attempting to remove it
Oct 1 00:21:49 castiana wpa_supplicant[9608]: wlan0: CTRL-EVENT-SIGNAL-CHANGE
above=1 signal=-63 noise=9999 txrate=9000
ProblemType: Bug
DistroRelease: Ubuntu 15.10
Package: wpasupplicant 2.4-0ubuntu2
ProcVersionSignature: Ubuntu 4.2.0-11.13-generic 4.2.1
Uname: Linux 4.2.0-11-generic x86_64
NonfreeKernelModules: zfs zunicode zcommon znvpair zavl
ApportVersion: 2.19-0ubuntu1
Architecture: amd64
CurrentDesktop: Unity
Date: Thu Oct 1 00:24:02 2015
InstallationDate: Installed on 2015-04-23 (160 days ago)
InstallationMedia: Ubuntu 15.04 "Vivid Vervet" - Release amd64 (20150422)
SourcePackage: wpa
UpgradeStatus: No upgrade log present (probably fresh install)
** Affects: wpa (Ubuntu)
Importance: Undecided
Status: New
** Tags: amd64 apport-bug wily
--
You received this bug notification because you are a member of Ubuntu
Bugs, which is subscribed to Ubuntu.
https://bugs.launchpad.net/bugs/1501588
Title:
Wily's wpasupplicant frequently fails on WPA enterprise networks
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/wpa/+bug/1501588/+subscriptions
--
ubuntu-bugs mailing list
ubuntu-bugs@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
