[pkg-wpa-devel] Bug#814517: wpasupplicant: Unstable connection after laptop suspend

Fri Feb 12 12:40:38 UTC 2016

Package: wpasupplicant
Version: 2.3-2.3
Severity: normal

After a fresh reboot, wpasupplicant can easily and reliably connect to
any of my networks - home, work, etc...

If I suspend the laptop and resume it again, either in the same place it
was suspended or by moving it to another, quite often wpasupplicant will
get stuck in an unstable loop, where it associates, obtains IP
addresses, only to choose to disconnect and start over. I say "quite
often" because it seems to be unstable; sometimes it doesn't do this.
Always one of three scenarios happens:

 1. It connects stably the first time and continues working

 2. It gets stuck in a permanent reconnection cycle, requiring manual
    intervention (sudo ifdown wlan0; sudo ifup wlan0) to recover

 3. It reconnects a few times, maybe order of 3 to 10, and then
    mysteriously succeeds and thereafter remains stable.

It is possible that cases 2 and 3 are really the same; usually after a
few minutes of waiting watching it continually reconnect I get bored of
waiting and forcibly restart it.

As an example, here's a chunk of /var/log/messages from just now when it
was stuck in a reconnection loop, before I manually restarted it:

  ...
  Feb 12 12:15:35 shy wpa_action: creating sendsigs omission pidfile: /run/sendsigs.omit.d/wpasupplicant.wpa_supplicant.wlan0.pid
  Feb 12 12:15:35 shy wpa_action: bssid=4a:d9:e7:47:bd:a6
  Feb 12 12:15:35 shy wpa_action: freq=0
  Feb 12 12:15:35 shy wpa_action: ssid=leoair
  Feb 12 12:15:35 shy wpa_action: id=0
  Feb 12 12:15:35 shy wpa_action: id_str=home
  Feb 12 12:15:35 shy wpa_action: mode=station
  Feb 12 12:15:35 shy wpa_action: pairwise_cipher=CCMP
  Feb 12 12:15:35 shy wpa_action: group_cipher=CCMP
  Feb 12 12:15:35 shy wpa_action: key_mgmt=WPA2-PSK
  Feb 12 12:15:35 shy wpa_action: wpa_state=COMPLETED
  Feb 12 12:15:35 shy wpa_action: ip_address=192.168.43.25
  Feb 12 12:15:35 shy wpa_action: address=8c:a9:82:c3:87:98
  Feb 12 12:15:35 shy wpa_action: uuid=78bcb1d2-42b3-571f-a058-ee941a51415e
  Feb 12 12:15:35 shy wpa_action: WPA_IFACE=wlan0 WPA_ACTION=DISCONNECTED
  Feb 12 12:15:35 shy wpa_action: WPA_ID=0 WPA_ID_STR=home WPA_CTRL_DIR=/var/run/wpa_supplicant
  Feb 12 12:15:35 shy wpa_action: ifdown wlan0
  Feb 12 12:15:36 shy kernel: [173556.420871] wlan0: deauthenticating from 4a:d9:e7:47:bd:a6 by local choice (Reason: 3=DEAUTH_LEAVING)
  Feb 12 12:15:46 shy wpa_action: removing sendsigs omission pidfile: /run/sendsigs.omit.d/wpasupplicant.wpa_supplicant.wlan0.pid
  Feb 12 12:15:46 shy kernel: [173566.483376] iwlwifi 0000:03:00.0: L1 Enabled - LTR Disabled
  Feb 12 12:15:46 shy kernel: [173566.490868] iwlwifi 0000:03:00.0: Radio type=0x0-0x0-0x3
  Feb 12 12:15:46 shy kernel: [173566.537968] iwlwifi 0000:03:00.0: L1 Enabled - LTR Disabled
  Feb 12 12:15:46 shy kernel: [173566.545392] iwlwifi 0000:03:00.0: Radio type=0x0-0x0-0x3
  Feb 12 12:15:46 shy kernel: [173566.578249] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
  Feb 12 12:15:46 shy wpa_action: WPA_IFACE=wlan0 WPA_ACTION=CONNECTED
  Feb 12 12:15:46 shy wpa_action: WPA_ID=0 WPA_ID_STR=home WPA_CTRL_DIR=/var/run/wpa_supplicant
  Feb 12 12:15:46 shy wpa_action: ifup wlan0=home
  Feb 12 12:15:46 shy kernel: [173567.044242] wlan0: authenticate with 4a:d9:e7:47:bd:a6
  Feb 12 12:15:46 shy kernel: [173567.048153] wlan0: send auth to 4a:d9:e7:47:bd:a6 (try 1/3)
  Feb 12 12:15:46 shy kernel: [173567.050642] wlan0: authenticated
  Feb 12 12:15:46 shy kernel: [173567.051134] wlan0: associate with 4a:d9:e7:47:bd:a6 (try 1/3)
  Feb 12 12:15:46 shy kernel: [173567.054908] wlan0: RX AssocResp from 4a:d9:e7:47:bd:a6 (capab=0x431 status=0 aid=2)
  Feb 12 12:15:46 shy kernel: [173567.069891] wlan0: associated
  Feb 12 12:15:46 shy kernel: [173567.069959] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
  Feb 12 12:15:51 shy wpa_action: creating sendsigs omission pidfile: /run/sendsigs.omit.d/wpasupplicant.wpa_supplicant.wlan0.pid
  Feb 12 12:15:51 shy wpa_action: bssid=4a:d9:e7:47:bd:a6
  Feb 12 12:15:51 shy wpa_action: freq=0
  ... as before
  Feb 12 12:15:51 shy wpa_action: WPA_ID=0 WPA_ID_STR=home WPA_CTRL_DIR=/var/run/wpa_supplicant
  Feb 12 12:15:51 shy wpa_action: ifdown wlan0
  Feb 12 12:15:52 shy kernel: [173572.482103] wlan0: deauthenticating from 4a:d9:e7:47:bd:a6 by local choice (Reason: 3=DEAUTH_LEAVING)
  Feb 12 12:16:02 shy wpa_action: removing sendsigs omission pidfile: /run/sendsigs.omit.d/wpasupplicant.wpa_supplicant.wlan0.pid
  Feb 12 12:16:02 shy kernel: [173582.545790] iwlwifi 0000:03:00.0: L1 Enabled - LTR Disabled
  Feb 12 12:16:02 shy kernel: [173582.553264] iwlwifi 0000:03:00.0: Radio type=0x0-0x0-0x3
  Feb 12 12:16:02 shy kernel: [173582.588903] iwlwifi 0000:03:00.0: L1 Enabled - LTR Disabled
  Feb 12 12:16:02 shy kernel: [173582.596332] iwlwifi 0000:03:00.0: Radio type=0x0-0x0-0x3
  Feb 12 12:16:02 shy kernel: [173582.630502] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
  Feb 12 12:16:02 shy wpa_action: WPA_IFACE=wlan0 WPA_ACTION=CONNECTED
  Feb 12 12:16:02 shy wpa_action: WPA_ID=0 WPA_ID_STR=home WPA_CTRL_DIR=/var/run/wpa_supplicant
  Feb 12 12:16:02 shy wpa_action: ifup wlan0=home
  ...

I was also monitoring the IP addresses using `ip mon addr` and observed
that for a few seconds on each reconnection attempt, the wireless link
was working correctly. It negotiated DHCP IPv4 and DHCPv6 IPv6 addresses
and for a few seconds each time, packets would flow just fine.

  3: wlan0    inet6 fe80::8ea9:82ff:fec3:8798/64 scope link 
	 valid_lft forever preferred_lft forever
  3: wlan0    inet6 2001:8b0:3f7:43:8ea9:82ff:fec3:8798/64 scope global mngtmpaddr dynamic 
	 valid_lft 86399sec preferred_lft 14399sec
  3: wlan0    inet 192.168.43.25/24 brd 192.168.43.255 scope global wlan0
	 valid_lft forever preferred_lft forever
  Deleted 3: wlan0    inet 192.168.43.25/24 brd 192.168.43.255 scope global wlan0
	 valid_lft forever preferred_lft forever
  Deleted 3: wlan0    inet6 2001:8b0:3f7:43:8ea9:82ff:fec3:8798/64 scope global mngtmpaddr dynamic 
	 valid_lft 86397sec preferred_lft 14397sec
  Deleted 3: wlan0    inet6 fe80::8ea9:82ff:fec3:8798/64 scope link 
	 valid_lft forever preferred_lft forever

Hardware-wise, the machine is a Lenovo Thinkpad X220, with

  03:00.0 Network controller: Intel Corporation Centrino Wireless-N 1000 [Condor Peak]

Though it feels to me like this isn't a hardware-related bug - simply
restarting wpasupplicant gets it out of the problem, and while it's in
the reconnect loop, for a few seconds each time, it is working fine. It
feels to me like wpasupplicant has got confused about testing link
status, and falsely believes it not to be working, so chooses to
disconnect and retry.

-- System Information:
Debian Release: stretch/sid
  APT prefers testing
  APT policy: (990, 'testing'), (500, 'unstable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 4.2.0-1-amd64 (SMP w/4 CPU cores)
Locale: LANG=en_GB.UTF-8, LC_CTYPE=en_GB.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: sysvinit (via /sbin/init)

Versions of packages wpasupplicant depends on:
ii  adduser           3.113+nmu3
ii  libc6             2.19-22
ii  libdbus-1-3       1.10.6-1
ii  libnl-3-200       3.2.26-1
ii  libnl-genl-3-200  3.2.26-1
ii  libpcsclite1      1.8.15-1
ii  libreadline6      6.3-8+b4
ii  libssl1.0.2       1.0.2e-1
ii  lsb-base          9.20150917

wpasupplicant recommends no packages.

Versions of packages wpasupplicant suggests:
pn  libengine-pkcs11-openssl  <none>
ii  wpagui                    2.3-2.3

-- no debconf information