desktop-packages team mailing list archive

Thread
Date
[Bug 1501588] Re: Wily's wpasupplicant frequently fails on WPA enterprise networks

To: desktop-packages@xxxxxxxxxxxxxxxxxxx
From: Stéphane Graber <stgraber@xxxxxxxxxxxx>
Date: Thu, 01 Oct 2015 04:51:58 -0000
Reply-to: Bug 1501588 <1501588@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Same issue happened again after I downgraded to vivid's version...

Now rebooting my laptop on a vivid kernel to confirm it's a kernel bug
and not a wpasupplicant bug.

-- 
You received this bug notification because you are a member of Desktop
Packages, which is subscribed to wpa in Ubuntu.
https://bugs.launchpad.net/bugs/1501588

Title:
  Wily's wpasupplicant frequently fails on WPA enterprise networks

Status in wpa package in Ubuntu:
  New

Bug description:
  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=stgraber@xxxxxxxxxxxx' 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=stgraber@xxxxxxxxxxxx' 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=stgraber@xxxxxxxxxxxx' 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=stgraber@xxxxxxxxxxxx' 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=stgraber@xxxxxxxxxxxx' 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=stgraber@xxxxxxxxxxxx' 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)

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/wpa/+bug/1501588/+subscriptions
References

[Bug 1501588] [NEW] Wily's wpasupplicant frequently fails on WPA enterprise networks
From: Stéphane Graber, 2015-10-01