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: Christian Rank <christian.rank@xxxxxxxxxxxxx>
Date: Mon, 07 Dec 2015 13:08:36 -0000
Reply-to: Bug 1501588 <1501588@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
The logs submitted by the bug reporter contain lines like
Sep 30 23:31:07 castiana wpa_supplicant[25653]: l2_packet_send - sendto: Message too long

I had exactly the same problem, so I checked the MTU of my wireless
interface and noticed that it was set to 1280.

After issuing
   ifconfig <wlan-interface> mtu 1500
the wpa connection works again.

But, after being connected some time, the MTU decreases again to 1280. The reason in my setup seems to be some strange behaviour of NetworkManager and IPv6:
Dec  7 13:46:31 rank-Latitude-E4310 NetworkManager[731]: <info>    address xxx.xxx.xxx.160
Dec  7 13:46:31 rank-Latitude-E4310 NetworkManager[731]: <info>    plen 23 (255.255.254.0)
Dec  7 13:46:31 rank-Latitude-E4310 NetworkManager[731]: <info>    gateway xxx.xxx.xxx.252
Dec  7 13:46:31 rank-Latitude-E4310 NetworkManager[731]: <info>    server identifier xxx.xxx.xxx.252
Dec  7 13:46:31 rank-Latitude-E4310 NetworkManager[731]: <info>    lease time 1200
Dec  7 13:46:31 rank-Latitude-E4310 NetworkManager[731]: <info>    nameserver 'xxx.xxx.xxx.253'
Dec  7 13:46:31 rank-Latitude-E4310 NetworkManager[731]: <info>    domain name 'xxx.de'
Dec  7 13:46:31 rank-Latitude-E4310 NetworkManager[731]: <info>  (wlp2s0): DHCPv4 state changed bound -> bound
Dec  7 13:46:31 rank-Latitude-E4310 NetworkManager[731]: <warn>  (wlp2s0): Lowering IPv6 MTU (1500) to match device MTU (0)
Dec  7 13:46:31 rank-Latitude-E4310 NetworkManager[731]: <warn>  (wlp2s0): IPv6 MTU (0) smaller than 1280, adjusting
Dec  7 13:46:31 rank-Latitude-E4310 NetworkManager[731]: <warn>  (wlp2s0): Raising device MTU (0) to match IPv6 MTU (1280)

Since we have no IPv6 in our WLAN, I disabled IPv6 for the connection in
NetworkManager. Unfortunately, this does not change anything - after the
first DHCP renewal, the MTU is set to 1280 again ...

This calls for further investigation ...

-- 
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 hostap:
  Unknown
Status in wpa package in Ubuntu:
  Confirmed

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/hostap/+bug/1501588/+subscriptions
References

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