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 <email address hidden>' 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 <email address hidden>' 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 <email address hidden>' 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 <email address hidden>' 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 <email address hidden>' 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 <email address hidden>' 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)
Description of problem: After updating to wpa_supplicant 2.4-3 on July 1, was unable to connect to my corporate wifi access point. Subsequent downgrade to wpa_supplicant 2.3-3 fixed access problem, so I think this is a wpa_supplicant bug
Version-Release number of selected component (if applicable): wpa_supplicant 2.4-3
How reproducible: Upgrade to 2.4-3 try to access wpa/wpa2 wifi with TTLS authentication that has been working for well over a year now. Fails. Downgrade to 2.3-3 and it works again.
Steps to Reproduce: See above
1. Select network in NetworkManager
2. Does not connect
3. Keeps asking for password
Actual results:
From /etc/wpa_ supplicant. log after upgrade:
wlp12s0: SME: Trying to authenticate with e0:1c:41:34:19:e9 (SSID='CICS' freq=5220 MHz) REGDOM- CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US EAP-STARTED EAP authentication started EAP-PROPOSED- METHOD vendor=0 method=21 EAP-METHOD EAP vendor 0 method 21 (TTLS) selected EAP-PEER- CERT depth=2 subject= '/C=US/ O=The Go Daddy Group, Inc./OU=Go Daddy Class 2 Certification Authori 9e93ca64274c0ec 67c1ecc5e024ffc acd2d74019350e8 1fe546ae4 EAP-PEER- CERT depth=2 subject= '/C=US/ O=The Go Daddy Group, Inc./OU=Go Daddy Class 2 Certification Authori 9e93ca64274c0ec 67c1ecc5e024ffc acd2d74019350e8 1fe546ae4 EAP-PEER- CERT depth=1 subject= '/C=US/ ST=Arizona/ L=Scottsdale/ O=GoDaddy. com, Inc./OU=http:// certificates. g com/repository/ CN=Go Daddy Secure Certification Authority/ serialNumber= 07969287' hash=09ed6e991f c3273d8fea317d3 39c0204 1558f411f11211a a3 EAP-PEER- CERT depth=0 subject='/OU=Domain Control Validated/ CN=cicsnc. org' hash=598c9bcc63 d9e114262181d14 0eb762e701b689b 0e309f9b7 EAP-PEER- ALT depth=0 DNS:cicsnc.org EAP-PEER- ALT depth=0 DNS:www.cicsnc.org EAP-PEER- ALT depth=0 DNS:osx.cicsnc.org EAP-PEER- ALT depth=0 DNS:osx2.cicsnc.org fatal:handshake failure SSL3_CHECK_ CERT_AND_ ALGORITHM: dh key too small EAP-FAILURE EAP authentication failed DISCONNECTED bssid=e0: 1c:41:34: 19:e9 reason=3 locally_generated=1 SSID-TEMP- DISABLED id=0 ssid="CICS" auth_failures=1 duration=10 reason=AUTH_FAILED SSID-TEMP- DISABLED id=0 ssid="CICS" auth_failures=2 duration=35 reason=CONN_FAILED
wlp12s0: Trying to associate with e0:1c:41:34:19:e9 (SSID='CICS' freq=5220 MHz)
wlp12s0: Associated with e0:1c:41:34:19:e9
wlp12s0: CTRL-EVENT-
wlp12s0: CTRL-EVENT-
wlp12s0: CTRL-EVENT-
wlp12s0: CTRL-EVENT-
wlp12s0: CTRL-EVENT-
ty' hash=c3846bf24b
wlp12s0: CTRL-EVENT-
ty' hash=c3846bf24b
wlp12s0: CTRL-EVENT-
odaddy.
1861973549cfa6e
wlp12s0: CTRL-EVENT-
dfed5372381b7ae
wlp12s0: CTRL-EVENT-
wlp12s0: CTRL-EVENT-
wlp12s0: CTRL-EVENT-
wlp12s0: CTRL-EVENT-
SSL: SSL3 alert: write (local SSL3 detected an error):
OpenSSL: openssl_handshake - SSL_connect error:14082174:SSL routines:
wlp12s0: CTRL-EVENT-
wlp12s0: Authentication with e0:1c:41:34:19:e9 timed out.
wlp12s0: CTRL-EVENT-
wlp12s0: CTRL-EVENT-
wlp12s0: CTRL-EVENT-
After downgrade:
wlp12s0: Trying to associate with e0:1c:41:34:19:e9 (SSID='CICS' freq=5220 MHz) EAP-STARTED EAP authentication started REGDOM- CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US EAP-PROPOSED- METHOD vendor=0 method=21
wlp12s0: Associated with e0:1c:41:34:19:e9
wlp12s0: CTRL-EVENT-
wlp12s0: CTRL-EVENT-
wlp12s0: CTRL-EVENT-
wlp12s0: ...